Get basic profiler working again

soochowtracy · Oct 8, 2015 · 504ed59 · 504ed59
1 parent 4d1fc55
commit 504ed59
Show file tree

Hide file tree

Showing 15 changed files with 138 additions and 252 deletions.
diff --git a/BUILD b/BUILD
@@ -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",
   ],

diff --git a/Makefile b/Makefile
@@ -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 \
 

diff --git a/build.yaml b/build.yaml
@@ -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

diff --git a/gRPC.podspec b/gRPC.podspec
@@ -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',

diff --git 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
@@ -53,49 +53,58 @@ 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,
                                 void *id, const char *file, int line) {
   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
@@ -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,

diff --git a/src/core/support/time_posix.c b/src/core/support/time_posix.c
@@ -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;

diff --git a/src/core/support/time_precise.c 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
@@ -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
@@ -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