From 504ed5997a09006a525af921f2969a096bfd3f44 Mon Sep 17 00:00:00 2001 From: Craig Tiller Date: Thu, 8 Oct 2015 07:38:43 -0700 Subject: [PATCH] Get basic profiler working again --- BUILD | 2 + Makefile | 1 + build.yaml | 1 + gRPC.podspec | 1 + grpc.gyp | 1 + src/core/profiling/basic_timers.c | 39 +++-- src/core/profiling/timers.h | 2 +- src/core/support/time_posix.c | 2 +- src/core/support/time_precise.c | 89 ++++++++++ src/core/support/time_precise.h | 55 +----- tools/doxygen/Doxyfile.core.internal | 1 + tools/profile_analyzer/profile_analyzer.py | 190 +-------------------- tools/run_tests/sources_and_headers.json | 1 + vsprojects/vcxproj/gpr/gpr.vcxproj | 2 + vsprojects/vcxproj/gpr/gpr.vcxproj.filters | 3 + 15 files changed, 138 insertions(+), 252 deletions(-) create mode 100644 src/core/support/time_precise.c diff --git a/BUILD b/BUILD index 3e2a45b8a0a..7c01d6b0bbc 100644 --- a/BUILD +++ b/BUILD @@ -88,6 +88,7 @@ cc_library( "src/core/support/thd_win32.c", "src/core/support/time.c", "src/core/support/time_posix.c", + "src/core/support/time_precise.c", "src/core/support/time_win32.c", "src/core/support/tls_pthread.c", ], @@ -995,6 +996,7 @@ objc_library( "src/core/support/thd_win32.c", "src/core/support/time.c", "src/core/support/time_posix.c", + "src/core/support/time_precise.c", "src/core/support/time_win32.c", "src/core/support/tls_pthread.c", ], diff --git a/Makefile b/Makefile index 8eb94f768a2..6d6dc71acce 100644 --- a/Makefile +++ b/Makefile @@ -3928,6 +3928,7 @@ LIBGPR_SRC = \ src/core/support/thd_win32.c \ src/core/support/time.c \ src/core/support/time_posix.c \ + src/core/support/time_precise.c \ src/core/support/time_win32.c \ src/core/support/tls_pthread.c \ diff --git a/build.yaml b/build.yaml index 98fb0348ca3..503d7a80c75 100644 --- a/build.yaml +++ b/build.yaml @@ -437,6 +437,7 @@ libs: - src/core/support/thd_win32.c - src/core/support/time.c - src/core/support/time_posix.c + - src/core/support/time_precise.c - src/core/support/time_win32.c - src/core/support/tls_pthread.c secure: false diff --git a/gRPC.podspec b/gRPC.podspec index 717e7005ee5..5b93281b417 100644 --- a/gRPC.podspec +++ b/gRPC.podspec @@ -134,6 +134,7 @@ Pod::Spec.new do |s| 'src/core/support/thd_win32.c', 'src/core/support/time.c', 'src/core/support/time_posix.c', + 'src/core/support/time_precise.c', 'src/core/support/time_win32.c', 'src/core/support/tls_pthread.c', 'src/core/security/auth_filters.h', diff --git a/grpc.gyp b/grpc.gyp index 2225ca4e045..b684cfd9d33 100644 --- a/grpc.gyp +++ b/grpc.gyp @@ -124,6 +124,7 @@ 'src/core/support/thd_win32.c', 'src/core/support/time.c', 'src/core/support/time_posix.c', + 'src/core/support/time_precise.c', 'src/core/support/time_win32.c', 'src/core/support/tls_pthread.c', ], diff --git a/src/core/profiling/basic_timers.c b/src/core/profiling/basic_timers.c index 2f6c88daacf..b7614375b3c 100644 --- a/src/core/profiling/basic_timers.c +++ b/src/core/profiling/basic_timers.c @@ -53,31 +53,42 @@ typedef enum { typedef struct grpc_timer_entry { gpr_timespec tm; - int tag; const char *tagstr; marker_type type; - void *id; const char *file; int line; } grpc_timer_entry; #define MAX_COUNT (1024 * 1024 / sizeof(grpc_timer_entry)) -static __thread grpc_timer_entry log[MAX_COUNT]; -static __thread int count; +static __thread grpc_timer_entry g_log[MAX_COUNT]; +static __thread int g_count; +static gpr_once g_once_init = GPR_ONCE_INIT; +static FILE *output_file; + +static void close_output() { fclose(output_file); } + +static void init_output() { + output_file = fopen("latency_trace.txt", "w"); + GPR_ASSERT(output_file); + atexit(close_output); +} static void log_report() { int i; - for (i = 0; i < count; i++) { - grpc_timer_entry *entry = &(log[i]); - printf("GRPC_LAT_PROF %ld.%09d %p %c %d(%s) %p %s %d\n", entry->tm.tv_sec, - entry->tm.tv_nsec, (void *)(gpr_intptr)gpr_thd_currentid(), - entry->type, entry->tag, entry->tagstr, entry->id, entry->file, - entry->line); + gpr_once_init(&g_once_init, init_output); + for (i = 0; i < g_count; i++) { + grpc_timer_entry *entry = &(g_log[i]); + fprintf(output_file, + "{\"t\": %ld.%09d, \"thd\": \"%p\", \"type\": \"%c\", \"tag\": " + "\"%s\", \"file\": \"%s\", \"line\": %d}\n", + entry->tm.tv_sec, entry->tm.tv_nsec, + (void *)(gpr_intptr)gpr_thd_currentid(), entry->type, entry->tagstr, + entry->file, entry->line); } /* Now clear out the log */ - count = 0; + g_count = 0; } static void grpc_timers_log_add(int tag, const char *tagstr, marker_type type, @@ -85,17 +96,15 @@ static void grpc_timers_log_add(int tag, const char *tagstr, marker_type type, grpc_timer_entry *entry; /* TODO (vpai) : Improve concurrency */ - if (count == MAX_COUNT) { + if (g_count == MAX_COUNT) { log_report(); } - entry = &log[count++]; + entry = &g_log[g_count++]; entry->tm = gpr_now(GPR_CLOCK_PRECISE); - entry->tag = tag; entry->tagstr = tagstr; entry->type = type; - entry->id = id; entry->file = file; entry->line = line; } diff --git a/src/core/profiling/timers.h b/src/core/profiling/timers.h index a70520408c3..c7cbf2bc2e4 100644 --- a/src/core/profiling/timers.h +++ b/src/core/profiling/timers.h @@ -65,7 +65,7 @@ enum grpc_profiling_tags { GRPC_PTAG_POLL_FINISHED = 203 + GRPC_PTAG_IGNORE_THRESHOLD, GRPC_PTAG_TCP_CB_WRITE = 204 + GRPC_PTAG_IGNORE_THRESHOLD, GRPC_PTAG_TCP_WRITE = 205 + GRPC_PTAG_IGNORE_THRESHOLD, - GRPC_PTAG_CALL_ON_DONE_RECV = 206 + GRPC_PTAG_IGNORE_THRESHOLD, + GRPC_PTAG_CALL_ON_DONE_RECV = 206, /* C++ */ GRPC_PTAG_CPP_CALL_CREATED = 300 + GRPC_PTAG_IGNORE_THRESHOLD, diff --git a/src/core/support/time_posix.c b/src/core/support/time_posix.c index 78f2c2bb77a..320a0678c2a 100644 --- a/src/core/support/time_posix.c +++ b/src/core/support/time_posix.c @@ -63,7 +63,7 @@ static gpr_timespec gpr_from_timespec(struct timespec ts, /** maps gpr_clock_type --> clockid_t for clock_gettime */ static clockid_t clockid_for_gpr_clock[] = {CLOCK_MONOTONIC, CLOCK_REALTIME}; -void gpr_time_init(void) {} +void gpr_time_init(void) { gpr_precise_clock_init(); } gpr_timespec gpr_now(gpr_clock_type clock_type) { struct timespec now; diff --git a/src/core/support/time_precise.c b/src/core/support/time_precise.c new file mode 100644 index 00000000000..b37517e639e --- /dev/null +++ b/src/core/support/time_precise.c @@ -0,0 +1,89 @@ +/* + * + * Copyright 2015, Google Inc. + * All rights reserved. + * + * Redistribution and use in source and binary forms, with or without + * modification, are permitted provided that the following conditions are + * met: + * + * * Redistributions of source code must retain the above copyright + * notice, this list of conditions and the following disclaimer. + * * Redistributions in binary form must reproduce the above + * copyright notice, this list of conditions and the following disclaimer + * in the documentation and/or other materials provided with the + * distribution. + * * Neither the name of Google Inc. nor the names of its + * contributors may be used to endorse or promote products derived from + * this software without specific prior written permission. + * + * THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS + * "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT + * LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR + * A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT + * OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL, + * SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT + * LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE, + * DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY + * THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT + * (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE + * OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE. + * + */ + +#include +#include +#include + +#ifdef GRPC_TIMERS_RDTSC +#if defined(__i386__) +static void gpr_get_cycle_counter(long long int *clk) { + long long int ret; + __asm__ volatile("rdtsc" : "=A"(ret)); + *clk = ret; +} + +// ---------------------------------------------------------------- +#elif defined(__x86_64__) || defined(__amd64__) +static void gpr_get_cycle_counter(long long int *clk) { + unsigned long long low, high; + __asm__ volatile("rdtsc" : "=a"(low), "=d"(high)); + *clk = (long long)(high << 32) | (long long)low; +} +#endif + +static double cycles_per_second = 0; +static long long int start_cycle; +void gpr_precise_clock_init(void) { + time_t start; + long long end_cycle; + gpr_log(GPR_DEBUG, "Calibrating timers"); + start = time(NULL); + while (time(NULL) == start) + ; + gpr_get_cycle_counter(&start_cycle); + while (time(NULL) <= start + 10) + ; + gpr_get_cycle_counter(&end_cycle); + cycles_per_second = (double)(end_cycle - start_cycle) / 10.0; + gpr_log(GPR_DEBUG, "... cycles_per_second = %f\n", cycles_per_second); +} + +void gpr_precise_clock_now(gpr_timespec *clk) { + long long int counter; + double secs; + gpr_get_cycle_counter(&counter); + secs = (double)(counter - start_cycle) / cycles_per_second; + clk->clock_type = GPR_CLOCK_PRECISE; + clk->tv_sec = (time_t)secs; + clk->tv_nsec = (int)(1e9 * (secs - (double)clk->tv_sec)); +} + +#else /* GRPC_TIMERS_RDTSC */ +void gpr_precise_clock_init(void) {} + +void gpr_precise_clock_now(gpr_timespec *clk) { + *clk = gpr_now(GPR_CLOCK_REALTIME); + clk->clock_type = GPR_CLOCK_PRECISE; +} +#endif /* GRPC_TIMERS_RDTSC */ diff --git a/src/core/support/time_precise.h b/src/core/support/time_precise.h index cd201faab95..80c5000123d 100644 --- a/src/core/support/time_precise.h +++ b/src/core/support/time_precise.h @@ -34,60 +34,9 @@ #ifndef GRPC_CORE_SUPPORT_TIME_PRECISE_H_ #define GRPC_CORE_SUPPORT_TIME_PRECISE_H_ -#include #include -#include -#ifdef GRPC_TIMERS_RDTSC -#if defined(__i386__) -static void gpr_get_cycle_counter(long long int *clk) { - long long int ret; - __asm__ volatile("rdtsc" : "=A"(ret)); - *clk = ret; -} - -// ---------------------------------------------------------------- -#elif defined(__x86_64__) || defined(__amd64__) -static void gpr_get_cycle_counter(long long int *clk) { - unsigned long long low, high; - __asm__ volatile("rdtsc" : "=a"(low), "=d"(high)); - *clk = (high << 32) | low; -} -#endif - -static gpr_once precise_clock_init = GPR_ONCE_INIT; -static long long cycles_per_second = 0; -static void gpr_precise_clock_init() { - time_t start = time(NULL); - gpr_precise_clock start_cycle; - gpr_precise_clock end_cycle; - while (time(NULL) == start) - ; - gpr_get_cycle_counter(&start_cycle); - while (time(NULL) == start + 1) - ; - gpr_get_cycle_counter(&end_cycle); - cycles_per_second = end_cycle - start_cycle; -} - -static double grpc_precise_clock_scaling_factor() { - gpr_once_init(&precise_clock_init, grpc_precise_clock_init); - return 1e6 / cycles_per_second; -} - -static void gpr_precise_clock_now(gpr_timespec *clk) { - long long int counter; - gpr_get_cycle_counter(&counter); - clk->clock = GPR_CLOCK_REALTIME; - clk->tv_sec = counter / cycles_per_second; - clk->tv_nsec = counter % cycles_per_second; -} - -#else /* GRPC_TIMERS_RDTSC */ -static void gpr_precise_clock_now(gpr_timespec *clk) { - *clk = gpr_now(GPR_CLOCK_REALTIME); - clk->clock_type = GPR_CLOCK_PRECISE; -} -#endif /* GRPC_TIMERS_RDTSC */ +void gpr_precise_clock_init(void); +void gpr_precise_clock_now(gpr_timespec *clk); #endif /* GRPC_CORE_SUPPORT_TIME_PRECISE_ */ diff --git a/tools/doxygen/Doxyfile.core.internal b/tools/doxygen/Doxyfile.core.internal index 5658a102d75..98d56f21eee 100644 --- a/tools/doxygen/Doxyfile.core.internal +++ b/tools/doxygen/Doxyfile.core.internal @@ -1112,6 +1112,7 @@ src/core/support/thd_posix.c \ src/core/support/thd_win32.c \ src/core/support/time.c \ src/core/support/time_posix.c \ +src/core/support/time_precise.c \ src/core/support/time_win32.c \ src/core/support/tls_pthread.c diff --git a/tools/profile_analyzer/profile_analyzer.py b/tools/profile_analyzer/profile_analyzer.py index e5e9a28a92d..074ceb8428d 100755 --- a/tools/profile_analyzer/profile_analyzer.py +++ b/tools/profile_analyzer/profile_analyzer.py @@ -1,188 +1,14 @@ #!/usr/bin/env python2.7 -# Copyright 2015, Google Inc. -# All rights reserved. -# -# Redistribution and use in source and binary forms, with or without -# modification, are permitted provided that the following conditions are -# met: -# -# * Redistributions of source code must retain the above copyright -# notice, this list of conditions and the following disclaimer. -# * Redistributions in binary form must reproduce the above -# copyright notice, this list of conditions and the following disclaimer -# in the documentation and/or other materials provided with the -# distribution. -# * Neither the name of Google Inc. nor the names of its -# contributors may be used to endorse or promote products derived from -# this software without specific prior written permission. -# -# THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS -# "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT -# LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR -# A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT -# OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL, -# SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT -# LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE, -# DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY -# THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT -# (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE -# OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE. - -""" -Read GRPC basic profiles, analyze the data. - -Usage: - bins/basicprof/qps_smoke_test > log - cat log | tools/profile_analyzer/profile_analyzer.py -""" - - +import json import collections -import itertools -import math -import re - -# Create a regex to parse output of the C core basic profiler, -# as defined in src/core/profiling/basic_timers.c. -_RE_LINE = re.compile(r'GRPC_LAT_PROF ' + - r'([0-9]+\.[0-9]+) 0x([0-9a-f]+) ([{}.!]) ([0-9]+) ' + - r'([^ ]+) ([^ ]+) ([0-9]+)') - -Entry = collections.namedtuple( - 'Entry', - ['time', 'thread', 'type', 'tag', 'id', 'file', 'line']) - - -class ImportantMark(object): - def __init__(self, entry, stack): - self._entry = entry - self._pre_stack = stack - self._post_stack = list() - self._n = len(stack) # we'll also compute times to that many closing }s - - @property - def entry(self): - return self._entry - - @property - def max_depth(self): - return self._n - def append_post_entry(self, post_entry): - if self._n > 0 and post_entry.thread == self._entry.thread: - self._post_stack.append(post_entry) - self._n -= 1 - - def get_deltas(self): - pre_and_post_stacks = itertools.chain(self._pre_stack, self._post_stack) - return collections.OrderedDict((stack_entry, - abs(self._entry.time - stack_entry.time)) - for stack_entry in pre_and_post_stacks) - - -def print_block_statistics(block_times): - print '{:<12s} {:>12s} {:>12s} {:>12s} {:>12s}'.format( - 'Block tag', '50th p.', '90th p.', '95th p.', '99th p.') - for tag, tag_times in sorted(block_times.iteritems()): - times = sorted(tag_times) - print '{:<12d}: {:>12.3f} {:>12.3f} {:>12.3f} {:>12.3f}'.format( - tag, percentile(times, 50), percentile(times, 90), - percentile(times, 95), percentile(times, 99)) - print - -def print_grouped_imark_statistics(group_key, imarks_group): - values = collections.OrderedDict() - for imark in imarks_group: - deltas = imark.get_deltas() - for relative_entry, time_delta_us in deltas.iteritems(): - key = '{tag} {type} ({file}:{line})'.format(**relative_entry._asdict()) - l = values.setdefault(key, list()) - l.append(time_delta_us) - - print group_key - print '{:<50s} {:>12s} {:>12s} {:>12s} {:>12s}'.format( - 'Relative mark', '50th p.', '90th p.', '95th p.', '99th p.') - for key, time_values in values.iteritems(): - time_values = sorted(time_values) - print '{:<50s}: {:>12.3f} {:>12.3f} {:>12.3f} {:>12.3f}'.format( - key, percentile(time_values, 50), percentile(time_values, 90), - percentile(time_values, 95), percentile(time_values, 99)) - print - -def percentile(vals, percent): - """ Calculates the interpolated percentile given a sorted sequence and a - percent (in the usual 0-100 range).""" - assert vals, "Empty input sequence." - percent /= 100.0 - k = (len(vals)-1) * percent - f = math.floor(k) - c = math.ceil(k) - if f == c: - return vals[int(k)] - # else, interpolate - d0 = vals[int(f)] * (c-k) - d1 = vals[int(c)] * (k-f) - return d0 + d1 - -def entries(f): +data = collections.defaultdict(list) +with open('latency_trace.txt') as f: for line in f: - m = _RE_LINE.match(line) - if not m: continue - yield Entry(time=float(m.group(1)), - thread=m.group(2), - type=m.group(3), - tag=int(m.group(4)), - id=m.group(5), - file=m.group(6), - line=m.group(7)) - -def main(f): - percentiles = (50, 90, 95, 99) - threads = collections.defaultdict(lambda: collections.defaultdict(list)) - times = collections.defaultdict(list) - important_marks = collections.defaultdict(list) - stack_depth = collections.defaultdict(int) - for entry in entries(f): - thread = threads[entry.thread] - if entry.type == '{': - thread[entry.tag].append(entry) - stack_depth[entry.thread] += 1 - if entry.type == '!': - # Save a snapshot of the current stack inside a new ImportantMark instance. - # Get all entries _for any tag in the thread_. - stack = [e for entries_for_tag in thread.itervalues() - for e in entries_for_tag] - imark_group_key = '{tag}/{thread}@{file}:{line}'.format(**entry._asdict()) - important_marks[imark_group_key].append(ImportantMark(entry, stack)) - elif entry.type == '}': - last = thread[entry.tag].pop() - times[entry.tag].append(entry.time - last.time) - # only access the last "depth" imarks for the tag. - depth = stack_depth[entry.thread] - for imarks_group in important_marks.itervalues(): - for imark in imarks_group[-depth:]: - # if at a '}' deeper than where the current "imark" was found, ignore. - if depth > imark.max_depth: continue - imark.append_post_entry(entry) - stack_depth[entry.thread] -= 1 - - print - print 'Block marks:' - print '============' - print_block_statistics(times) - - print - print 'Important marks:' - print '================' - for group_key, imarks_group in important_marks.iteritems(): - print_grouped_imark_statistics(group_key, imarks_group) + inf = json.loads(line) + thd = inf['thd'] + del inf['thd'] + data[thd].append(inf) +print data -if __name__ == '__main__': - # If invoked without arguments, read off sys.stdin. If one argument is given, - # take it as a file name and open it for reading. - import sys - f = sys.stdin - if len(sys.argv) == 2: - f = open(sys.argv[1], 'r') - main(f) diff --git a/tools/run_tests/sources_and_headers.json b/tools/run_tests/sources_and_headers.json index 1ceff15a3be..f2237e0fef7 100644 --- a/tools/run_tests/sources_and_headers.json +++ b/tools/run_tests/sources_and_headers.json @@ -12244,6 +12244,7 @@ "src/core/support/thd_win32.c", "src/core/support/time.c", "src/core/support/time_posix.c", + "src/core/support/time_precise.c", "src/core/support/time_precise.h", "src/core/support/time_win32.c", "src/core/support/tls_pthread.c" diff --git a/vsprojects/vcxproj/gpr/gpr.vcxproj b/vsprojects/vcxproj/gpr/gpr.vcxproj index 479286fe97c..4c3b36abdc8 100644 --- a/vsprojects/vcxproj/gpr/gpr.vcxproj +++ b/vsprojects/vcxproj/gpr/gpr.vcxproj @@ -244,6 +244,8 @@ + + diff --git a/vsprojects/vcxproj/gpr/gpr.vcxproj.filters b/vsprojects/vcxproj/gpr/gpr.vcxproj.filters index be5bb5162d3..69391b4f991 100644 --- a/vsprojects/vcxproj/gpr/gpr.vcxproj.filters +++ b/vsprojects/vcxproj/gpr/gpr.vcxproj.filters @@ -106,6 +106,9 @@ src\core\support + + src\core\support + src\core\support