Merge pull request #1449 from ctiller/profile

Add rdtsc profiling support, implement begin/end and tag hiding

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
 

src/core/profiling/basic_timers.c

@@ -45,10 +45,17 @@
 #include <grpc/support/thd.h>
 #include <stdio.h>
 
+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_begin(int tag, void* id, const char *file, int 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, 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) {

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 <grpc/support/sync.h>
 #include <grpc/support/time.h>
 #include <stdio.h>
 
-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;
 };

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