Get basic profiler working again

pull/3767/head
Craig Tiller 9 years ago
parent 4d1fc55261
commit 504ed5997a
  1. 2
      BUILD
  2. 1
      Makefile
  3. 1
      build.yaml
  4. 1
      gRPC.podspec
  5. 1
      grpc.gyp
  6. 39
      src/core/profiling/basic_timers.c
  7. 2
      src/core/profiling/timers.h
  8. 2
      src/core/support/time_posix.c
  9. 89
      src/core/support/time_precise.c
  10. 55
      src/core/support/time_precise.h
  11. 1
      tools/doxygen/Doxyfile.core.internal
  12. 190
      tools/profile_analyzer/profile_analyzer.py
  13. 1
      tools/run_tests/sources_and_headers.json
  14. 2
      vsprojects/vcxproj/gpr/gpr.vcxproj
  15. 3
      vsprojects/vcxproj/gpr/gpr.vcxproj.filters

@ -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",
],

@ -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 \

@ -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

@ -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',

@ -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',
],

@ -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;
}

@ -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,

@ -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;

@ -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 */

@ -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_ */

@ -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

@ -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)

@ -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"

@ -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">

@ -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>

Loading…
Cancel
Save