Grpc census: v0 trace_printf() implementation in C.

Change on 2015/01/09 by hongyu <hongyu@google.com>
-------------
Created by MOE: http://code.google.com/p/moe-java
MOE_MIGRATED_REVID=83626942

src/core/statistics/census_tracing.c

@@ -47,8 +47,8 @@
 
 /* Struct for a trace annotation. */
 typedef struct annotation {
-  gpr_uint64 ts;                          /* timestamp of the annotation */
-  char txt[CENSUS_MAX_ANNOTATION_LENGTH]; /* actual txt annotation */
+  gpr_timespec ts;                            /* timestamp of the annotation */
+  char txt[CENSUS_MAX_ANNOTATION_LENGTH + 1]; /* actual txt annotation */
   struct annotation* next;
 } annotation;
 
@@ -107,8 +107,8 @@ census_op_id census_tracing_start_op() {
     ret->rpc_stats.cnt = 1;
     ret->ts = gpr_now();
     census_ht_insert(g_trace_store, op_id_as_key(&ret->id), (void*)ret);
+    gpr_log(GPR_DEBUG, "Start tracing for id %lu", g_id);
     gpr_mu_unlock(&g_mu);
-    gpr_log(GPR_DEBUG, "Start tracing for id %lu\n", g_id);
     return ret->id;
   }
 }
@@ -127,7 +127,27 @@ int census_add_method_tag(census_op_id op_id, const char* method) {
   return ret;
 }
 
-void census_tracing_print(census_op_id op_id, const char* annotation) {}
+void census_tracing_print(census_op_id op_id, const char* anno_txt) {
+  trace_obj* trace = NULL;
+  gpr_mu_lock(&g_mu);
+  trace = census_ht_find(g_trace_store, op_id_as_key(&op_id));
+  if (trace != NULL) {
+    annotation* anno = gpr_malloc(sizeof(annotation));
+    anno->ts = gpr_now();
+    {
+      char* d = anno->txt;
+      const char* s = anno_txt;
+      int n = 0;
+      for (; n < CENSUS_MAX_ANNOTATION_LENGTH && *s != '\0'; ++n) {
+        *d++ = *s++;
+      }
+      *d = '\0';
+    }
+    anno->next = trace->annotations;
+    trace->annotations = anno;
+  }
+  gpr_mu_unlock(&g_mu);
+}
 
 void census_tracing_end_op(census_op_id op_id) {
   trace_obj* trace = NULL;
@@ -136,7 +156,7 @@ void census_tracing_end_op(census_op_id op_id) {
   if (trace != NULL) {
     trace->rpc_stats.elapsed_time_ms =
         gpr_timespec_to_micros(gpr_time_sub(gpr_now(), trace->ts));
-    gpr_log(GPR_DEBUG, "End tracing for id %lu, method %s, latency %f us\n",
+    gpr_log(GPR_DEBUG, "End tracing for id %lu, method %s, latency %f us",
             op_id_2_uint64(&op_id), trace->method,
             trace->rpc_stats.elapsed_time_ms);
     census_ht_erase(g_trace_store, op_id_as_key(&op_id));

test/core/statistics/trace_test.c

@@ -41,6 +41,7 @@
 #include <grpc/support/sync.h>
 #include <grpc/support/thd.h>
 #include <grpc/support/time.h>
+#include <grpc/support/useful.h>
 #include "test/core/util/test_config.h"
 
 /* Ensure all possible state transitions are called without causing problem */
@@ -130,10 +131,12 @@ static void test_concurrency() {
   for (i = 0; i < NUM_THREADS; ++i) {
     gpr_thd_new(tid + i, mimic_trace_op_sequences, &arg, NULL);
   }
+  gpr_mu_lock(&arg.mu);
   while (arg.num_done < NUM_THREADS) {
     gpr_log(GPR_INFO, "num done %d", arg.num_done);
     gpr_cv_wait(&arg.done, &arg.mu, gpr_inf_future);
   }
+  gpr_mu_unlock(&arg.mu);
   census_tracing_shutdown();
 #undef NUM_THREADS
 }
@@ -147,6 +150,28 @@ static void test_add_method_tag_to_unknown_op_id() {
   census_tracing_shutdown();
 }
 
+static void test_trace_print() {
+  census_op_id id;
+  int i;
+  const char* annotation_txt[4] = {"abc", "", "$%^ *()_"};
+  char long_txt[CENSUS_MAX_ANNOTATION_LENGTH + 10];
+
+  memset(long_txt, 'a', GPR_ARRAY_SIZE(long_txt));
+  long_txt[CENSUS_MAX_ANNOTATION_LENGTH + 9] = '\0';
+  annotation_txt[3] = long_txt;
+
+  census_tracing_init();
+  id = census_tracing_start_op();
+  /* Adds large number of annotations to each trace */
+  for (i = 0; i < 1000; i++) {
+    census_tracing_print(id,
+                         annotation_txt[i % GPR_ARRAY_SIZE(annotation_txt)]);
+  }
+  census_tracing_end_op(id);
+
+  census_tracing_shutdown();
+}
+
 int main(int argc, char** argv) {
   grpc_test_init(argc, argv);
   test_init_shutdown();
@@ -154,5 +179,6 @@ int main(int argc, char** argv) {
   test_get_trace_method_name();
   test_concurrency();
   test_add_method_tag_to_unknown_op_id();
+  test_trace_print();
   return 0;
 }