Get basic profiler working again
diff --git a/BUILD b/BUILD
index 3e2a45b..7c01d6b 100644
--- a/BUILD
+++ b/BUILD
@@ -88,6 +88,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",
],
@@ -995,6 +996,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/Makefile b/Makefile
index 8eb94f7..6d6dc71 100644
--- a/Makefile
+++ b/Makefile
@@ -3928,6 +3928,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/build.yaml b/build.yaml
index 98fb034..503d7a8 100644
--- a/build.yaml
+++ b/build.yaml
@@ -437,6 +437,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
secure: false
diff --git a/gRPC.podspec b/gRPC.podspec
index 717e700..5b93281 100644
--- a/gRPC.podspec
+++ b/gRPC.podspec
@@ -134,6 +134,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',
'src/core/security/auth_filters.h',
diff --git a/grpc.gyp b/grpc.gyp
index 2225ca4..b684cfd 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 2f6c88d..b761437 100644
--- a/src/core/profiling/basic_timers.c
+++ b/src/core/profiling/basic_timers.c
@@ -53,31 +53,42 @@
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 @@
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 a705204..c7cbf2b 100644
--- a/src/core/profiling/timers.h
+++ b/src/core/profiling/timers.h
@@ -65,7 +65,7 @@
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 78f2c2b..320a067 100644
--- a/src/core/support/time_posix.c
+++ b/src/core/support/time_posix.c
@@ -63,7 +63,7 @@
/** 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 0000000..b37517e
--- /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 <grpc/support/log.h>
+#include <grpc/support/time.h>
+#include <stdio.h>
+
+#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 cd201fa..80c5000 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 <grpc/support/sync.h>
#include <grpc/support/time.h>
-#include <stdio.h>
-#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 5658a10..98d56f2 100644
--- a/tools/doxygen/Doxyfile.core.internal
+++ b/tools/doxygen/Doxyfile.core.internal
@@ -1112,6 +1112,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/tools/profile_analyzer/profile_analyzer.py b/tools/profile_analyzer/profile_analyzer.py
index e5e9a28..074ceb8 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))
+ inf = json.loads(line)
+ thd = inf['thd']
+ del inf['thd']
+ data[thd].append(inf)
-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 data
- 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)
-
-
-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 1ceff15..f2237e0 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 479286f..4c3b36a 100644
--- a/vsprojects/vcxproj/gpr/gpr.vcxproj
+++ b/vsprojects/vcxproj/gpr/gpr.vcxproj
@@ -244,6 +244,8 @@
</ClCompile>
<ClCompile Include="..\..\..\src\core\support\time_posix.c">
</ClCompile>
+ <ClCompile Include="..\..\..\src\core\support\time_precise.c">
+ </ClCompile>
<ClCompile Include="..\..\..\src\core\support\time_win32.c">
</ClCompile>
<ClCompile Include="..\..\..\src\core\support\tls_pthread.c">
diff --git a/vsprojects/vcxproj/gpr/gpr.vcxproj.filters b/vsprojects/vcxproj/gpr/gpr.vcxproj.filters
index be5bb51..69391b4 100644
--- a/vsprojects/vcxproj/gpr/gpr.vcxproj.filters
+++ b/vsprojects/vcxproj/gpr/gpr.vcxproj.filters
@@ -106,6 +106,9 @@
<ClCompile Include="..\..\..\src\core\support\time_posix.c">
<Filter>src\core\support</Filter>
</ClCompile>
+ <ClCompile Include="..\..\..\src\core\support\time_precise.c">
+ <Filter>src\core\support</Filter>
+ </ClCompile>
<ClCompile Include="..\..\..\src\core\support\time_win32.c">
<Filter>src\core\support</Filter>
</ClCompile>