From 9e68c63b7195d3df17f52a946460e5eb69529ad7 Mon Sep 17 00:00:00 2001 From: David Garcia Quintas Date: Wed, 13 May 2015 11:38:54 -0700 Subject: [PATCH] Added the tag enun name to the profiling marks. For example, whereas previously we'd have GRPC_LAT_PROF 1986206380734.095703 0x7f0b4bff7700 { 200 (nil) src/core/iomgr/tcp_posix.c 337 now we have: GRPC_LAT_PROF 1986206380734.095703 0x7f0b4bff7700 { 200(GRPC_PTAG_HANDLE_READ) (nil) src/core/iomgr/tcp_posix.c 337 Note the literal enum name in parenthesis following the tag int value. --- src/core/profiling/basic_timers.c | 32 ++++++++++++++---------- src/core/profiling/stap_timers.c | 13 ++++++---- src/core/profiling/timers.h | 41 +++++++++++++++++-------------- 3 files changed, 50 insertions(+), 36 deletions(-) diff --git a/src/core/profiling/basic_timers.c b/src/core/profiling/basic_timers.c index 124a8d6621a..ae37f584ebb 100644 --- a/src/core/profiling/basic_timers.c +++ b/src/core/profiling/basic_timers.c @@ -55,6 +55,7 @@ typedef enum { typedef struct grpc_timer_entry { grpc_precise_clock tm; int tag; + const char* tagstr; marker_type type; void* id; const char* file; @@ -70,18 +71,19 @@ static void log_report() { int i; for (i = 0; i < count; i++) { grpc_timer_entry* entry = &(log[i]); - printf("GRPC_LAT_PROF " GRPC_PRECISE_CLOCK_FORMAT " %p %c %d %p %s %d\n", + printf("GRPC_LAT_PROF " GRPC_PRECISE_CLOCK_FORMAT + " %p %c %d(%s) %p %s %d\n", GRPC_PRECISE_CLOCK_PRINTF_ARGS(&entry->tm), (void*)(gpr_intptr)gpr_thd_currentid(), entry->type, entry->tag, - entry->id, entry->file, entry->line); + entry->tagstr, entry->id, entry->file, entry->line); } /* Now clear out the log */ count = 0; } -static void grpc_timers_log_add(int tag, marker_type type, void* id, - const char* file, int line) { +static void grpc_timers_log_add(int tag, const char* tagstr, marker_type type, + void* id, const char* file, int line) { grpc_timer_entry* entry; /* TODO (vpai) : Improve concurrency */ @@ -93,6 +95,7 @@ static void grpc_timers_log_add(int tag, marker_type type, void* id, grpc_precise_clock_now(&entry->tm); entry->tag = tag; + entry->tagstr = tagstr; entry->type = type; entry->id = id; entry->file = file; @@ -100,28 +103,31 @@ static void grpc_timers_log_add(int tag, marker_type type, void* id, } /* Latency profiler API implementation. */ -void grpc_timer_add_mark(int tag, void* id, const char* file, int line) { +void grpc_timer_add_mark(int tag, const char* tagstr, void* id, + const char* file, int line) { if (tag < GRPC_PTAG_IGNORE_THRESHOLD) { - grpc_timers_log_add(tag, MARK, id, file, line); + grpc_timers_log_add(tag, tagstr, MARK, id, file, line); } } -void grpc_timer_add_important_mark(int tag, void* id, const char* file, - int line) { +void grpc_timer_add_important_mark(int tag, const char* tagstr, void* id, + const char* file, int line) { if (tag < GRPC_PTAG_IGNORE_THRESHOLD) { - grpc_timers_log_add(tag, IMPORTANT, id, file, line); + grpc_timers_log_add(tag, tagstr, IMPORTANT, id, file, line); } } -void grpc_timer_begin(int tag, void* id, const char* file, int line) { +void grpc_timer_begin(int tag, const char* tagstr, void* id, const char* file, + int line) { if (tag < GRPC_PTAG_IGNORE_THRESHOLD) { - grpc_timers_log_add(tag, BEGIN, id, file, line); + grpc_timers_log_add(tag, tagstr, BEGIN, id, file, line); } } -void grpc_timer_end(int tag, void* id, const char* file, int line) { +void grpc_timer_end(int tag, const char* tagstr, void* id, const char* file, + int line) { if (tag < GRPC_PTAG_IGNORE_THRESHOLD) { - grpc_timers_log_add(tag, END, id, file, line); + grpc_timers_log_add(tag, tagstr, END, id, file, line); } } diff --git a/src/core/profiling/stap_timers.c b/src/core/profiling/stap_timers.c index 064c86e794e..99975163f93 100644 --- a/src/core/profiling/stap_timers.c +++ b/src/core/profiling/stap_timers.c @@ -42,20 +42,23 @@ #include "src/core/profiling/stap_probes.h" /* Latency profiler API implementation. */ -void grpc_timer_add_mark(int tag, void* id, const char* file, int line) { +void grpc_timer_add_mark(int tag, const char* tagstr, void* id, + const char* file, int line) { _STAP_ADD_MARK(tag); } -void grpc_timer_add_important_mark(int tag, void* id, const char* file, - int line) { +void grpc_timer_add_important_mark(int tag, const char* tagstr, void* id, + const char* file, int line) { _STAP_ADD_IMPORTANT_MARK(tag); } -void grpc_timer_begin(int tag, void* id, const char* file, int line) { +void grpc_timer_begin(int tag, const char* tagstr, void* id, const char* file, + int line) { _STAP_TIMING_NS_BEGIN(tag); } -void grpc_timer_end(int tag, void* id, const char* file, int line) { +void grpc_timer_end(int tag, const char* tagstr, void* id, const char* file, + int line) { _STAP_TIMING_NS_END(tag); } diff --git a/src/core/profiling/timers.h b/src/core/profiling/timers.h index 4fb465c2371..036d02f187d 100644 --- a/src/core/profiling/timers.h +++ b/src/core/profiling/timers.h @@ -41,11 +41,14 @@ extern "C" { void grpc_timers_global_init(void); void grpc_timers_global_destroy(void); -void grpc_timer_add_mark(int tag, void *id, const char *file, int line); -void grpc_timer_add_important_mark(int tag, void *id, const char *file, - int 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_add_mark(int tag, const char *tagstr, void *id, + const char *file, int line); +void grpc_timer_add_important_mark(int tag, const char *tagstr, void *id, + const char *file, int line); +void grpc_timer_begin(int tag, const char *tagstr, void *id, const char *file, + int line); +void grpc_timer_end(int tag, const char *tagstr, void *id, const char *file, + int line); enum grpc_profiling_tags { /* Any GRPC_PTAG_* >= than the threshold won't generate any profiling mark. */ @@ -103,25 +106,27 @@ enum grpc_profiling_tags { #endif /* Generic profiling interface. */ -#define GRPC_TIMER_MARK(tag, id) \ - if (tag < GRPC_PTAG_IGNORE_THRESHOLD) { \ - grpc_timer_add_mark(tag, ((void *)(gpr_intptr)(id)), __FILE__, __LINE__); \ +#define GRPC_TIMER_MARK(tag, id) \ + if (tag < GRPC_PTAG_IGNORE_THRESHOLD) { \ + grpc_timer_add_mark(tag, #tag, ((void *)(gpr_intptr)(id)), __FILE__, \ + __LINE__); \ } -#define GRPC_TIMER_IMPORTANT_MARK(tag, id) \ - if (tag < GRPC_PTAG_IGNORE_THRESHOLD) { \ - grpc_timer_add_important_mark(tag, ((void *)(gpr_intptr)(id)), __FILE__, \ - __LINE__); \ +#define GRPC_TIMER_IMPORTANT_MARK(tag, id) \ + if (tag < GRPC_PTAG_IGNORE_THRESHOLD) { \ + grpc_timer_add_important_mark(tag, #tag, ((void *)(gpr_intptr)(id)), \ + __FILE__, __LINE__); \ } -#define GRPC_TIMER_BEGIN(tag, id) \ - if (tag < GRPC_PTAG_IGNORE_THRESHOLD) { \ - grpc_timer_begin(tag, ((void *)(gpr_intptr)(id)), __FILE__, __LINE__); \ +#define GRPC_TIMER_BEGIN(tag, id) \ + if (tag < GRPC_PTAG_IGNORE_THRESHOLD) { \ + grpc_timer_begin(tag, #tag, ((void *)(gpr_intptr)(id)), __FILE__, \ + __LINE__); \ } -#define GRPC_TIMER_END(tag, id) \ - if (tag < GRPC_PTAG_IGNORE_THRESHOLD) { \ - grpc_timer_end(tag, ((void *)(gpr_intptr)(id)), __FILE__, __LINE__); \ +#define GRPC_TIMER_END(tag, id) \ + if (tag < GRPC_PTAG_IGNORE_THRESHOLD) { \ + grpc_timer_end(tag, #tag, ((void *)(gpr_intptr)(id)), __FILE__, __LINE__); \ } #ifdef GRPC_STAP_PROFILER