mirror of https://github.com/grpc/grpc.git
[cleanup] Remove profiling timers (#30779)
* [cleanup] Remove profiling timers - nobody has used this system in years - if we needed it, we'd probably rewrite it at this point to be something more modern - let's remove it until that need arises * fix * fixespull/30611/head
Craig Tiller
3 years ago
committed by
GitHub
parent
0c46726229
commit
004788af3d
58 changed files with 1 additions and 988 deletions
@ -1,295 +0,0 @@ |
||||
/*
|
||||
* |
||||
* Copyright 2015 gRPC authors. |
||||
* |
||||
* Licensed under the Apache License, Version 2.0 (the "License"); |
||||
* you may not use this file except in compliance with the License. |
||||
* You may obtain a copy of the License at |
||||
* |
||||
* http://www.apache.org/licenses/LICENSE-2.0
|
||||
* |
||||
* Unless required by applicable law or agreed to in writing, software |
||||
* distributed under the License is distributed on an "AS IS" BASIS, |
||||
* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. |
||||
* See the License for the specific language governing permissions and |
||||
* limitations under the License. |
||||
* |
||||
*/ |
||||
|
||||
#include <grpc/support/port_platform.h> |
||||
|
||||
#include "src/core/lib/profiling/timers.h" |
||||
|
||||
#ifdef GRPC_BASIC_PROFILER |
||||
|
||||
#include <inttypes.h> |
||||
#include <pthread.h> |
||||
#include <stdio.h> |
||||
#include <string.h> |
||||
|
||||
#include <grpc/support/alloc.h> |
||||
#include <grpc/support/log.h> |
||||
#include <grpc/support/sync.h> |
||||
#include <grpc/support/time.h> |
||||
|
||||
#include "src/core/lib/gpr/tls.h" |
||||
#include "src/core/lib/gprpp/global_config.h" |
||||
#include "src/core/lib/profiling/timers.h" |
||||
|
||||
typedef enum { BEGIN = '{', END = '}', MARK = '.' } marker_type; |
||||
|
||||
typedef struct gpr_timer_entry { |
||||
gpr_timespec tm; |
||||
const char* tagstr; |
||||
const char* file; |
||||
short line; |
||||
char type; |
||||
uint8_t important; |
||||
int thd; |
||||
} gpr_timer_entry; |
||||
|
||||
#define MAX_COUNT 1000000 |
||||
|
||||
typedef struct gpr_timer_log { |
||||
size_t num_entries; |
||||
struct gpr_timer_log* next; |
||||
struct gpr_timer_log* prev; |
||||
gpr_timer_entry log[MAX_COUNT]; |
||||
} gpr_timer_log; |
||||
|
||||
typedef struct gpr_timer_log_list { |
||||
gpr_timer_log* head; |
||||
/* valid iff head!=NULL */ |
||||
gpr_timer_log* tail; |
||||
} gpr_timer_log_list; |
||||
|
||||
static GPR_THREAD_LOCAL(gpr_timer_log*) g_thread_log; |
||||
static gpr_once g_once_init = GPR_ONCE_INIT; |
||||
static FILE* output_file; |
||||
static const char* output_filename_or_null = NULL; |
||||
static pthread_mutex_t g_mu; |
||||
static pthread_cond_t g_cv; |
||||
static gpr_timer_log_list g_in_progress_logs; |
||||
static gpr_timer_log_list g_done_logs; |
||||
static int g_shutdown; |
||||
static pthread_t g_writing_thread; |
||||
static GPR_THREAD_LOCAL(int) g_thread_id; |
||||
static int g_next_thread_id; |
||||
static int g_writing_enabled = 1; |
||||
|
||||
GPR_GLOBAL_CONFIG_DEFINE_STRING(grpc_latency_trace, "latency_trace.txt", |
||||
"Output file name for latency trace") |
||||
|
||||
static const char* output_filename() { |
||||
if (output_filename_or_null == NULL) { |
||||
grpc_core::UniquePtr<char> value = |
||||
GPR_GLOBAL_CONFIG_GET(grpc_latency_trace); |
||||
if (strlen(value.get()) > 0) { |
||||
output_filename_or_null = value.release(); |
||||
} else { |
||||
output_filename_or_null = "latency_trace.txt"; |
||||
} |
||||
} |
||||
return output_filename_or_null; |
||||
} |
||||
|
||||
static int timer_log_push_back(gpr_timer_log_list* list, gpr_timer_log* log) { |
||||
if (list->head == NULL) { |
||||
list->head = list->tail = log; |
||||
log->next = log->prev = NULL; |
||||
return 1; |
||||
} else { |
||||
log->prev = list->tail; |
||||
log->next = NULL; |
||||
list->tail->next = log; |
||||
list->tail = log; |
||||
return 0; |
||||
} |
||||
} |
||||
|
||||
static gpr_timer_log* timer_log_pop_front(gpr_timer_log_list* list) { |
||||
gpr_timer_log* out = list->head; |
||||
if (out != NULL) { |
||||
list->head = out->next; |
||||
if (list->head != NULL) { |
||||
list->head->prev = NULL; |
||||
} else { |
||||
list->tail = NULL; |
||||
} |
||||
} |
||||
return out; |
||||
} |
||||
|
||||
static void timer_log_remove(gpr_timer_log_list* list, gpr_timer_log* log) { |
||||
if (log->prev == NULL) { |
||||
list->head = log->next; |
||||
if (list->head != NULL) { |
||||
list->head->prev = NULL; |
||||
} |
||||
} else { |
||||
log->prev->next = log->next; |
||||
} |
||||
if (log->next == NULL) { |
||||
list->tail = log->prev; |
||||
if (list->tail != NULL) { |
||||
list->tail->next = NULL; |
||||
} |
||||
} else { |
||||
log->next->prev = log->prev; |
||||
} |
||||
} |
||||
|
||||
static void write_log(gpr_timer_log* log) { |
||||
size_t i; |
||||
if (output_file == NULL) { |
||||
output_file = fopen(output_filename(), "w"); |
||||
} |
||||
for (i = 0; i < log->num_entries; i++) { |
||||
gpr_timer_entry* entry = &(log->log[i]); |
||||
if (gpr_time_cmp(entry->tm, gpr_time_0(entry->tm.clock_type)) < 0) { |
||||
entry->tm = gpr_time_0(entry->tm.clock_type); |
||||
} |
||||
fprintf(output_file, |
||||
"{\"t\": %" PRId64 |
||||
".%09d, \"thd\": \"%d\", \"type\": \"%c\", \"tag\": " |
||||
"\"%s\", \"file\": \"%s\", \"line\": %d, \"imp\": %d}\n", |
||||
entry->tm.tv_sec, entry->tm.tv_nsec, entry->thd, entry->type, |
||||
entry->tagstr, entry->file, entry->line, entry->important); |
||||
} |
||||
} |
||||
|
||||
static void* writing_thread(void* unused) { |
||||
gpr_timer_log* log; |
||||
pthread_mutex_lock(&g_mu); |
||||
for (;;) { |
||||
while ((log = timer_log_pop_front(&g_done_logs)) == NULL && !g_shutdown) { |
||||
pthread_cond_wait(&g_cv, &g_mu); |
||||
} |
||||
if (log != NULL) { |
||||
pthread_mutex_unlock(&g_mu); |
||||
write_log(log); |
||||
free(log); |
||||
pthread_mutex_lock(&g_mu); |
||||
} |
||||
if (g_shutdown) { |
||||
pthread_mutex_unlock(&g_mu); |
||||
return NULL; |
||||
} |
||||
} |
||||
} |
||||
|
||||
static void flush_logs(gpr_timer_log_list* list) { |
||||
gpr_timer_log* log; |
||||
while ((log = timer_log_pop_front(list)) != NULL) { |
||||
write_log(log); |
||||
free(log); |
||||
} |
||||
} |
||||
|
||||
static void finish_writing(void) { |
||||
pthread_mutex_lock(&g_mu); |
||||
g_shutdown = 1; |
||||
pthread_cond_signal(&g_cv); |
||||
pthread_mutex_unlock(&g_mu); |
||||
pthread_join(g_writing_thread, NULL); |
||||
|
||||
gpr_log(GPR_INFO, "flushing logs"); |
||||
|
||||
pthread_mutex_lock(&g_mu); |
||||
flush_logs(&g_done_logs); |
||||
flush_logs(&g_in_progress_logs); |
||||
pthread_mutex_unlock(&g_mu); |
||||
|
||||
if (output_file) { |
||||
fclose(output_file); |
||||
} |
||||
} |
||||
|
||||
void gpr_timers_set_log_filename(const char* filename) { |
||||
output_filename_or_null = filename; |
||||
} |
||||
|
||||
static void init_output() { |
||||
pthread_attr_t attr; |
||||
pthread_attr_init(&attr); |
||||
pthread_attr_setdetachstate(&attr, PTHREAD_CREATE_JOINABLE); |
||||
pthread_create(&g_writing_thread, &attr, &writing_thread, NULL); |
||||
pthread_attr_destroy(&attr); |
||||
|
||||
atexit(finish_writing); |
||||
} |
||||
|
||||
static void rotate_log() { |
||||
/* Using malloc here, as this code could end up being called by gpr_malloc */ |
||||
gpr_timer_log* log = static_cast<gpr_timer_log*>(malloc(sizeof(*log))); |
||||
gpr_once_init(&g_once_init, init_output); |
||||
log->num_entries = 0; |
||||
pthread_mutex_lock(&g_mu); |
||||
if (g_thread_log != NULL) { |
||||
timer_log_remove(&g_in_progress_logs, g_thread_log); |
||||
if (timer_log_push_back(&g_done_logs, g_thread_log)) { |
||||
pthread_cond_signal(&g_cv); |
||||
} |
||||
} else { |
||||
g_thread_id = g_next_thread_id++; |
||||
} |
||||
timer_log_push_back(&g_in_progress_logs, log); |
||||
pthread_mutex_unlock(&g_mu); |
||||
g_thread_log = log; |
||||
} |
||||
|
||||
static void gpr_timers_log_add(const char* tagstr, marker_type type, |
||||
int important, const char* file, int line) { |
||||
gpr_timer_entry* entry; |
||||
|
||||
if (!g_writing_enabled) { |
||||
return; |
||||
} |
||||
|
||||
if (g_thread_log == NULL || g_thread_log->num_entries == MAX_COUNT) { |
||||
rotate_log(); |
||||
} |
||||
|
||||
entry = &g_thread_log->log[g_thread_log->num_entries++]; |
||||
|
||||
entry->tm = gpr_now(GPR_CLOCK_PRECISE); |
||||
entry->tagstr = tagstr; |
||||
entry->type = type; |
||||
entry->file = file; |
||||
entry->line = (short)line; |
||||
entry->important = important != 0; |
||||
entry->thd = g_thread_id; |
||||
} |
||||
|
||||
/* Latency profiler API implementation. */ |
||||
void gpr_timer_add_mark(const char* tagstr, int important, const char* file, |
||||
int line) { |
||||
gpr_timers_log_add(tagstr, MARK, important, file, line); |
||||
} |
||||
|
||||
void gpr_timer_begin(const char* tagstr, int important, const char* file, |
||||
int line) { |
||||
gpr_timers_log_add(tagstr, BEGIN, important, file, line); |
||||
} |
||||
|
||||
void gpr_timer_end(const char* tagstr, int important, const char* file, |
||||
int line) { |
||||
gpr_timers_log_add(tagstr, END, important, file, line); |
||||
} |
||||
|
||||
void gpr_timer_set_enabled(int enabled) { g_writing_enabled = enabled; } |
||||
|
||||
/* Basic profiler specific API functions. */ |
||||
void gpr_timers_global_init(void) {} |
||||
|
||||
void gpr_timers_global_destroy(void) {} |
||||
|
||||
#else /* !GRPC_BASIC_PROFILER */ |
||||
void gpr_timers_global_init(void) {} |
||||
|
||||
void gpr_timers_global_destroy(void) {} |
||||
|
||||
void gpr_timers_set_log_filename(const char* /*filename*/) {} |
||||
|
||||
void gpr_timer_set_enabled(int /*enabled*/) {} |
||||
#endif /* GRPC_BASIC_PROFILER */ |
||||
@ -1,7 +0,0 @@ |
||||
provider _stap { |
||||
probe add_mark(int tag); |
||||
probe add_important_mark(int tag); |
||||
probe timing_ns_begin(int tag); |
||||
probe timing_ns_end(int tag); |
||||
}; |
||||
|
||||
@ -1,50 +0,0 @@ |
||||
/*
|
||||
* |
||||
* Copyright 2015 gRPC authors. |
||||
* |
||||
* Licensed under the Apache License, Version 2.0 (the "License"); |
||||
* you may not use this file except in compliance with the License. |
||||
* You may obtain a copy of the License at |
||||
* |
||||
* http://www.apache.org/licenses/LICENSE-2.0
|
||||
* |
||||
* Unless required by applicable law or agreed to in writing, software |
||||
* distributed under the License is distributed on an "AS IS" BASIS, |
||||
* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. |
||||
* See the License for the specific language governing permissions and |
||||
* limitations under the License. |
||||
* |
||||
*/ |
||||
|
||||
#include <grpc/support/port_platform.h> |
||||
|
||||
#ifdef GRPC_STAP_PROFILER |
||||
|
||||
#include <sys/sdt.h> |
||||
|
||||
#include "src/core/lib/profiling/timers.h" |
||||
/* Generated from src/core/profiling/stap_probes.d */ |
||||
#include "src/core/lib/profiling/stap_probes.h" |
||||
|
||||
/* Latency profiler API implementation. */ |
||||
void gpr_timer_add_mark(int tag, const char* tagstr, void* id, const char* file, |
||||
int line) { |
||||
_STAP_ADD_MARK(tag); |
||||
} |
||||
|
||||
void gpr_timer_add_important_mark(int tag, const char* tagstr, void* id, |
||||
const char* file, int line) { |
||||
_STAP_ADD_IMPORTANT_MARK(tag); |
||||
} |
||||
|
||||
void gpr_timer_begin(int tag, const char* tagstr, void* id, const char* file, |
||||
int line) { |
||||
_STAP_TIMING_NS_BEGIN(tag); |
||||
} |
||||
|
||||
void gpr_timer_end(int tag, const char* tagstr, void* id, const char* file, |
||||
int line) { |
||||
_STAP_TIMING_NS_END(tag); |
||||
} |
||||
|
||||
#endif /* GRPC_STAP_PROFILER */ |
||||
@ -1,94 +0,0 @@ |
||||
/*
|
||||
* |
||||
* Copyright 2015 gRPC authors. |
||||
* |
||||
* Licensed under the Apache License, Version 2.0 (the "License"); |
||||
* you may not use this file except in compliance with the License. |
||||
* You may obtain a copy of the License at |
||||
* |
||||
* http://www.apache.org/licenses/LICENSE-2.0
|
||||
* |
||||
* Unless required by applicable law or agreed to in writing, software |
||||
* distributed under the License is distributed on an "AS IS" BASIS, |
||||
* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. |
||||
* See the License for the specific language governing permissions and |
||||
* limitations under the License. |
||||
* |
||||
*/ |
||||
|
||||
#ifndef GRPC_CORE_LIB_PROFILING_TIMERS_H |
||||
#define GRPC_CORE_LIB_PROFILING_TIMERS_H |
||||
|
||||
void gpr_timers_global_init(void); |
||||
void gpr_timers_global_destroy(void); |
||||
|
||||
void gpr_timer_add_mark(const char* tagstr, int important, const char* file, |
||||
int line); |
||||
void gpr_timer_begin(const char* tagstr, int important, const char* file, |
||||
int line); |
||||
void gpr_timer_end(const char* tagstr, int important, const char* file, |
||||
int line); |
||||
|
||||
void gpr_timers_set_log_filename(const char* filename); |
||||
|
||||
void gpr_timer_set_enabled(int enabled); |
||||
|
||||
#if !(defined(GRPC_STAP_PROFILER) + defined(GRPC_BASIC_PROFILER) + \ |
||||
defined(GRPC_CUSTOM_PROFILER)) |
||||
/* No profiling. No-op all the things. */ |
||||
#define GPR_TIMER_MARK(tag, important) \ |
||||
do { \
|
||||
} while (0) |
||||
|
||||
#define GPR_TIMER_SCOPE(tag, important) \ |
||||
do { \
|
||||
} while (0) |
||||
|
||||
#else /* at least one profiler requested... */ |
||||
/* ... hopefully only one. */ |
||||
#if defined(GRPC_STAP_PROFILER) && defined(GRPC_BASIC_PROFILER) |
||||
#error "GRPC_STAP_PROFILER and GRPC_BASIC_PROFILER are mutually exclusive." |
||||
#endif |
||||
#if defined(GRPC_STAP_PROFILER) && defined(GRPC_CUSTOM_PROFILER) |
||||
#error "GRPC_STAP_PROFILER and GRPC_CUSTOM_PROFILER are mutually exclusive." |
||||
#endif |
||||
#if defined(GRPC_CUSTOM_PROFILER) && defined(GRPC_BASIC_PROFILER) |
||||
#error "GRPC_CUSTOM_PROFILER and GRPC_BASIC_PROFILER are mutually exclusive." |
||||
#endif |
||||
|
||||
/* Generic profiling interface. */ |
||||
#define GPR_TIMER_MARK(tag, important) \ |
||||
gpr_timer_add_mark(tag, important, __FILE__, __LINE__); |
||||
|
||||
#ifdef GRPC_STAP_PROFILER |
||||
/* Empty placeholder for now. */ |
||||
#endif /* GRPC_STAP_PROFILER */ |
||||
|
||||
#ifdef GRPC_BASIC_PROFILER |
||||
/* Empty placeholder for now. */ |
||||
#endif /* GRPC_BASIC_PROFILER */ |
||||
|
||||
namespace grpc { |
||||
class ProfileScope { |
||||
public: |
||||
ProfileScope(const char* desc, bool important, const char* file, int line) |
||||
: desc_(desc) { |
||||
gpr_timer_begin(desc_, important ? 1 : 0, file, line); |
||||
} |
||||
~ProfileScope() { gpr_timer_end(desc_, 0, "n/a", 0); } |
||||
|
||||
private: |
||||
const char* const desc_; |
||||
}; |
||||
} // namespace grpc
|
||||
|
||||
#define GPR_TIMER_SCOPE_NAME_INTERNAL(prefix, line) prefix##line |
||||
#define GPR_TIMER_SCOPE_NAME(prefix, line) \ |
||||
GPR_TIMER_SCOPE_NAME_INTERNAL(prefix, line) |
||||
#define GPR_TIMER_SCOPE(tag, important) \ |
||||
::grpc::ProfileScope GPR_TIMER_SCOPE_NAME(_profile_scope_, __LINE__)( \
|
||||
(tag), (important), __FILE__, __LINE__) |
||||
|
||||
#endif /* at least one profiler requested. */ |
||||
|
||||
#endif /* GRPC_CORE_LIB_PROFILING_TIMERS_H */ |
||||
@ -1,276 +0,0 @@ |
||||
#!/usr/bin/env python3 |
||||
# Copyright 2015 gRPC authors. |
||||
# |
||||
# Licensed under the Apache License, Version 2.0 (the "License"); |
||||
# you may not use this file except in compliance with the License. |
||||
# You may obtain a copy of the License at |
||||
# |
||||
# http://www.apache.org/licenses/LICENSE-2.0 |
||||
# |
||||
# Unless required by applicable law or agreed to in writing, software |
||||
# distributed under the License is distributed on an "AS IS" BASIS, |
||||
# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. |
||||
# See the License for the specific language governing permissions and |
||||
# limitations under the License. |
||||
|
||||
import argparse |
||||
import collections |
||||
import hashlib |
||||
import json |
||||
import math |
||||
import sys |
||||
import time |
||||
|
||||
from six.moves import zip |
||||
import tabulate |
||||
|
||||
SELF_TIME = object() |
||||
TIME_FROM_SCOPE_START = object() |
||||
TIME_TO_SCOPE_END = object() |
||||
TIME_FROM_STACK_START = object() |
||||
TIME_TO_STACK_END = object() |
||||
TIME_FROM_LAST_IMPORTANT = object() |
||||
|
||||
argp = argparse.ArgumentParser( |
||||
description='Process output of basic_prof builds') |
||||
argp.add_argument('--source', default='latency_trace.txt', type=str) |
||||
argp.add_argument('--fmt', choices=tabulate.tabulate_formats, default='simple') |
||||
argp.add_argument('--out', default='-', type=str) |
||||
args = argp.parse_args() |
||||
|
||||
|
||||
class LineItem(object): |
||||
|
||||
def __init__(self, line, indent): |
||||
self.tag = line['tag'] |
||||
self.indent = indent |
||||
self.start_time = line['t'] |
||||
self.end_time = None |
||||
self.important = line['imp'] |
||||
self.filename = line['file'] |
||||
self.fileline = line['line'] |
||||
self.times = {} |
||||
|
||||
|
||||
class ScopeBuilder(object): |
||||
|
||||
def __init__(self, call_stack_builder, line): |
||||
self.call_stack_builder = call_stack_builder |
||||
self.indent = len(call_stack_builder.stk) |
||||
self.top_line = LineItem(line, self.indent) |
||||
call_stack_builder.lines.append(self.top_line) |
||||
self.first_child_pos = len(call_stack_builder.lines) |
||||
|
||||
def mark(self, line): |
||||
line_item = LineItem(line, self.indent + 1) |
||||
line_item.end_time = line_item.start_time |
||||
self.call_stack_builder.lines.append(line_item) |
||||
|
||||
def finish(self, line): |
||||
assert line['tag'] == self.top_line.tag, ( |
||||
'expected %s, got %s; thread=%s; t0=%f t1=%f' % |
||||
(self.top_line.tag, line['tag'], line['thd'], |
||||
self.top_line.start_time, line['t'])) |
||||
final_time_stamp = line['t'] |
||||
assert self.top_line.end_time is None |
||||
self.top_line.end_time = final_time_stamp |
||||
self.top_line.important = self.top_line.important or line['imp'] |
||||
assert SELF_TIME not in self.top_line.times |
||||
self.top_line.times[ |
||||
SELF_TIME] = final_time_stamp - self.top_line.start_time |
||||
for line in self.call_stack_builder.lines[self.first_child_pos:]: |
||||
if TIME_FROM_SCOPE_START not in line.times: |
||||
line.times[ |
||||
TIME_FROM_SCOPE_START] = line.start_time - self.top_line.start_time |
||||
line.times[TIME_TO_SCOPE_END] = final_time_stamp - line.end_time |
||||
|
||||
|
||||
class CallStackBuilder(object): |
||||
|
||||
def __init__(self): |
||||
self.stk = [] |
||||
self.signature = hashlib.md5() |
||||
self.lines = [] |
||||
|
||||
def finish(self): |
||||
start_time = self.lines[0].start_time |
||||
end_time = self.lines[0].end_time |
||||
self.signature = self.signature.hexdigest() |
||||
last_important = start_time |
||||
for line in self.lines: |
||||
line.times[TIME_FROM_STACK_START] = line.start_time - start_time |
||||
line.times[TIME_TO_STACK_END] = end_time - line.end_time |
||||
line.times[ |
||||
TIME_FROM_LAST_IMPORTANT] = line.start_time - last_important |
||||
if line.important: |
||||
last_important = line.end_time |
||||
last_important = end_time |
||||
|
||||
def add(self, line): |
||||
line_type = line['type'] |
||||
self.signature.update(line_type.encode('UTF-8')) |
||||
self.signature.update(line['tag'].encode('UTF-8')) |
||||
if line_type == '{': |
||||
self.stk.append(ScopeBuilder(self, line)) |
||||
return False |
||||
elif line_type == '}': |
||||
assert self.stk, ( |
||||
'expected non-empty stack for closing %s; thread=%s; t=%f' % |
||||
(line['tag'], line['thd'], line['t'])) |
||||
self.stk.pop().finish(line) |
||||
if not self.stk: |
||||
self.finish() |
||||
return True |
||||
return False |
||||
elif line_type == '.' or line_type == '!': |
||||
if self.stk: |
||||
self.stk[-1].mark(line) |
||||
return False |
||||
else: |
||||
raise Exception('Unknown line type: \'%s\'' % line_type) |
||||
|
||||
|
||||
class CallStack(object): |
||||
|
||||
def __init__(self, initial_call_stack_builder): |
||||
self.count = 1 |
||||
self.signature = initial_call_stack_builder.signature |
||||
self.lines = initial_call_stack_builder.lines |
||||
for line in self.lines: |
||||
for key, val in list(line.times.items()): |
||||
line.times[key] = [val] |
||||
|
||||
def add(self, call_stack_builder): |
||||
assert self.signature == call_stack_builder.signature |
||||
self.count += 1 |
||||
assert len(self.lines) == len(call_stack_builder.lines) |
||||
for lsum, line in zip(self.lines, call_stack_builder.lines): |
||||
assert lsum.tag == line.tag |
||||
assert list(lsum.times.keys()) == list(line.times.keys()) |
||||
for k, lst in list(lsum.times.items()): |
||||
lst.append(line.times[k]) |
||||
|
||||
def finish(self): |
||||
for line in self.lines: |
||||
for lst in list(line.times.values()): |
||||
lst.sort() |
||||
|
||||
|
||||
builder = collections.defaultdict(CallStackBuilder) |
||||
call_stacks = collections.defaultdict(CallStack) |
||||
|
||||
lines = 0 |
||||
start = time.time() |
||||
with open(args.source) as f: |
||||
for line in f: |
||||
lines += 1 |
||||
inf = json.loads(line) |
||||
thd = inf['thd'] |
||||
cs = builder[thd] |
||||
if cs.add(inf): |
||||
if cs.signature in call_stacks: |
||||
call_stacks[cs.signature].add(cs) |
||||
else: |
||||
call_stacks[cs.signature] = CallStack(cs) |
||||
del builder[thd] |
||||
time_taken = time.time() - start |
||||
|
||||
call_stacks = sorted(list(call_stacks.values()), |
||||
key=lambda cs: cs.count, |
||||
reverse=True) |
||||
total_stacks = 0 |
||||
for cs in call_stacks: |
||||
total_stacks += cs.count |
||||
cs.finish() |
||||
|
||||
|
||||
def percentile(N, percent, key=lambda x: x): |
||||
""" |
||||
Find the percentile of an already sorted list of values. |
||||
|
||||
@parameter N - is a list of values. MUST be already sorted. |
||||
@parameter percent - a float value from [0.0,1.0]. |
||||
@parameter key - optional key function to compute value from each element of N. |
||||
|
||||
@return - the percentile of the values |
||||
""" |
||||
if not N: |
||||
return None |
||||
float_idx = (len(N) - 1) * percent |
||||
idx = int(float_idx) |
||||
result = key(N[idx]) |
||||
if idx < len(N) - 1: |
||||
# interpolate with the next element's value |
||||
result += (float_idx - idx) * (key(N[idx + 1]) - key(N[idx])) |
||||
return result |
||||
|
||||
|
||||
def tidy_tag(tag): |
||||
if tag[0:10] == 'GRPC_PTAG_': |
||||
return tag[10:] |
||||
return tag |
||||
|
||||
|
||||
def time_string(values): |
||||
num_values = len(values) |
||||
return '%.1f/%.1f/%.1f' % (1e6 * percentile(values, 0.5), 1e6 * percentile( |
||||
values, 0.9), 1e6 * percentile(values, 0.99)) |
||||
|
||||
|
||||
def time_format(idx): |
||||
|
||||
def ent(line, idx=idx): |
||||
if idx in line.times: |
||||
return time_string(line.times[idx]) |
||||
return '' |
||||
|
||||
return ent |
||||
|
||||
|
||||
BANNER = {'simple': 'Count: %(count)d', 'html': '<h1>Count: %(count)d</h1>'} |
||||
|
||||
FORMAT = [ |
||||
('TAG', lambda line: '..' * line.indent + tidy_tag(line.tag)), |
||||
('LOC', lambda line: '%s:%d' % |
||||
(line.filename[line.filename.rfind('/') + 1:], line.fileline)), |
||||
('IMP', lambda line: '*' if line.important else ''), |
||||
('FROM_IMP', time_format(TIME_FROM_LAST_IMPORTANT)), |
||||
('FROM_STACK_START', time_format(TIME_FROM_STACK_START)), |
||||
('SELF', time_format(SELF_TIME)), |
||||
('TO_STACK_END', time_format(TIME_TO_STACK_END)), |
||||
('FROM_SCOPE_START', time_format(TIME_FROM_SCOPE_START)), |
||||
('SELF', time_format(SELF_TIME)), |
||||
('TO_SCOPE_END', time_format(TIME_TO_SCOPE_END)), |
||||
] |
||||
|
||||
out = sys.stdout |
||||
if args.out != '-': |
||||
out = open(args.out, 'w') |
||||
|
||||
if args.fmt == 'html': |
||||
out.write('<html>') |
||||
out.write('<head>') |
||||
out.write('<title>Profile Report</title>') |
||||
out.write('</head>') |
||||
|
||||
accounted_for = 0 |
||||
for cs in call_stacks: |
||||
out.write('\n') |
||||
if args.fmt in BANNER: |
||||
out.write(BANNER[args.fmt] % { |
||||
'count': cs.count, |
||||
}) |
||||
header, _ = list(zip(*FORMAT)) |
||||
table = [] |
||||
for line in cs.lines: |
||||
fields = [] |
||||
for _, fn in FORMAT: |
||||
fields.append(fn(line)) |
||||
table.append(fields) |
||||
out.write(tabulate.tabulate(table, header, tablefmt=args.fmt)) |
||||
accounted_for += cs.count |
||||
if accounted_for > .99 * total_stacks: |
||||
break |
||||
|
||||
if args.fmt == 'html': |
||||
print('</html>') |
||||
Loading…
Reference in new issue