From 113d169f8f03957c495ef938712f6456ab49099f Mon Sep 17 00:00:00 2001 From: Craig Tiller Date: Fri, 1 May 2015 15:26:15 -0700 Subject: [PATCH] Add rdtsc profiling support, implement begin/end and tag hiding --- Makefile | 2 +- src/core/profiling/basic_timers.c | 29 ++++++++++++++--- src/core/profiling/timers_preciseclock.h | 40 ++++++++++++++++++++++-- templates/Makefile.template | 2 +- 4 files changed, 63 insertions(+), 10 deletions(-) diff --git a/Makefile b/Makefile index e3c81f470b0..0bd653eff8d 100644 --- a/Makefile +++ b/Makefile @@ -92,7 +92,7 @@ CC_basicprof = $(DEFAULT_CC) CXX_basicprof = $(DEFAULT_CXX) LD_basicprof = $(DEFAULT_CC) LDXX_basicprof = $(DEFAULT_CXX) -CPPFLAGS_basicprof = -O2 -DGRPC_BASIC_PROFILER +CPPFLAGS_basicprof = -O2 -DGRPC_BASIC_PROFILER -DGRPC_TIMERS_RDTSC LDFLAGS_basicprof = DEFINES_basicprof = NDEBUG diff --git a/src/core/profiling/basic_timers.c b/src/core/profiling/basic_timers.c index d89bba7b878..0145ce208ee 100644 --- a/src/core/profiling/basic_timers.c +++ b/src/core/profiling/basic_timers.c @@ -45,10 +45,17 @@ #include #include +typedef enum { + BEGIN = '{', + END = '}', + MARK = '.' +} marker_type; + typedef struct grpc_timer_entry { grpc_precise_clock tm; gpr_thd_id thd; int tag; + marker_type type; void* id; const char* file; int line; @@ -89,7 +96,7 @@ static void log_report_locked(grpc_timers_log* log) { grpc_timer_entry* entry = &(log->log[i]); fprintf(fp, "GRPC_LAT_PROF "); grpc_precise_clock_print(&entry->tm, fp); - fprintf(fp, " %p %d %p %s %d\n", (void*)(gpr_intptr)entry->thd, entry->tag, + fprintf(fp, " %p %c %d %p %s %d\n", (void*)(gpr_intptr)entry->thd, entry->type, entry->tag, entry->id, entry->file, entry->line); } @@ -108,7 +115,7 @@ static void grpc_timers_log_destroy(grpc_timers_log* log) { gpr_free(log); } -static void grpc_timers_log_add(grpc_timers_log* log, int tag, void* id, +static void grpc_timers_log_add(grpc_timers_log* log, int tag, marker_type type, void* id, const char* file, int line) { grpc_timer_entry* entry; @@ -122,6 +129,7 @@ static void grpc_timers_log_add(grpc_timers_log* log, int tag, void* id, grpc_precise_clock_now(&entry->tm); entry->tag = tag; + entry->type = type; entry->id = id; entry->file = file; entry->line = line; @@ -132,11 +140,22 @@ static void grpc_timers_log_add(grpc_timers_log* log, int tag, void* id, /* Latency profiler API implementation. */ void grpc_timer_add_mark(int tag, void* id, const char* file, int line) { - grpc_timers_log_add(grpc_timers_log_global, tag, id, file, line); + if (tag < GRPC_PTAG_IGNORE_THRESHOLD) { + grpc_timers_log_add(grpc_timers_log_global, tag, MARK, id, file, line); + } } -void grpc_timer_begin(int tag, void* id, const char *file, int line) {} -void grpc_timer_end(int tag, void* id, const char *file, int line) {} +void grpc_timer_begin(int tag, void* id, const char *file, int line) { + if (tag < GRPC_PTAG_IGNORE_THRESHOLD) { + grpc_timers_log_add(grpc_timers_log_global, tag, BEGIN, id, file, line); + } +} + +void grpc_timer_end(int tag, void* id, const char *file, int line) { + if (tag < GRPC_PTAG_IGNORE_THRESHOLD) { + grpc_timers_log_add(grpc_timers_log_global, tag, END, id, file, line); + } +} /* Basic profiler specific API functions. */ void grpc_timers_global_init(void) { diff --git a/src/core/profiling/timers_preciseclock.h b/src/core/profiling/timers_preciseclock.h index bf4a0eab8a4..625db906e1b 100644 --- a/src/core/profiling/timers_preciseclock.h +++ b/src/core/profiling/timers_preciseclock.h @@ -34,14 +34,48 @@ #ifndef GRPC_CORE_PROFILING_TIMERS_PRECISECLOCK_H #define GRPC_CORE_PROFILING_TIMERS_PRECISECLOCK_H +#include #include #include -typedef struct grpc_precise_clock grpc_precise_clock; - #ifdef GRPC_TIMERS_RDTSC -#error RDTSC timers not currently supported +typedef long long int grpc_precise_clock; +#if defined(__i386__) +static void grpc_precise_clock_now(grpc_precise_clock *clk) { + grpc_precise_clock ret; + __asm__ volatile("rdtsc" : "=A" (ret) ); + *clk = ret; +} + +// ---------------------------------------------------------------- +#elif defined(__x86_64__) || defined(__amd64__) +static void grpc_precise_clock_now(grpc_precise_clock *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 double cycles_per_second = 0.0; +static void grpc_precise_clock_init() { + time_t start = time(NULL); + grpc_precise_clock start_time; + grpc_precise_clock end_time; + while (time(NULL) == start); + grpc_precise_clock_now(&start_time); + while (time(NULL) == start+1); + grpc_precise_clock_now(&end_time); + cycles_per_second = end_time - start_time; +} +static double grpc_precise_clock_scaling_factor() { + gpr_once_init(&precise_clock_init, grpc_precise_clock_init); + return 1e6 / cycles_per_second; +} +static void grpc_precise_clock_print(const grpc_precise_clock* clk, FILE* fp) { + fprintf(fp, "%f", *clk * grpc_precise_clock_scaling_factor()); +} #else +typedef struct grpc_precise_clock grpc_precise_clock; struct grpc_precise_clock { gpr_timespec clock; }; diff --git a/templates/Makefile.template b/templates/Makefile.template index 1e7a2a49bdd..839a0c290bd 100644 --- a/templates/Makefile.template +++ b/templates/Makefile.template @@ -106,7 +106,7 @@ CC_basicprof = $(DEFAULT_CC) CXX_basicprof = $(DEFAULT_CXX) LD_basicprof = $(DEFAULT_CC) LDXX_basicprof = $(DEFAULT_CXX) -CPPFLAGS_basicprof = -O2 -DGRPC_BASIC_PROFILER +CPPFLAGS_basicprof = -O2 -DGRPC_BASIC_PROFILER -DGRPC_TIMERS_RDTSC LDFLAGS_basicprof = DEFINES_basicprof = NDEBUG