Rework error and closure tracing

8 files changed, 71 insertions, 39 deletions

diff --git a/src/core/lib/iomgr/closure.c b/src/core/lib/iomgr/closure.c
index 719e2e8cee..c1535fbabe 100644
--- a/src/core/lib/iomgr/closure.c
+++ b/src/core/lib/iomgr/closure.c
@@ -24,7 +24,9 @@
 
 #include "src/core/lib/profiling/timers.h"
 
-#ifdef GRPC_CLOSURE_RICH_DEBUG
+grpc_tracer_flag grpc_trace_closure = GRPC_TRACER_INITIALIZER(false);
+
+#ifndef NDEBUG
 grpc_closure *grpc_closure_init(const char *file, int line,
                                 grpc_closure *closure, grpc_iomgr_cb_func cb,
                                 void *cb_arg,
@@ -37,7 +39,7 @@ grpc_closure *grpc_closure_init(grpc_closure *closure, grpc_iomgr_cb_func cb,
   closure->cb = cb;
   closure->cb_arg = cb_arg;
   closure->scheduler = scheduler;
-#ifdef GRPC_CLOSURE_RICH_DEBUG
+#ifndef NDEBUG
   closure->scheduled = false;
   closure->file_initiated = NULL;
   closure->line_initiated = 0;
@@ -112,7 +114,7 @@ static void closure_wrapper(grpc_exec_ctx *exec_ctx, void *arg,
   cb(exec_ctx, cb_arg, error);
 }
 
-#ifdef GRPC_CLOSURE_RICH_DEBUG
+#ifndef NDEBUG
 grpc_closure *grpc_closure_create(const char *file, int line,
                                   grpc_iomgr_cb_func cb, void *cb_arg,
                                   grpc_closure_scheduler *scheduler) {
@@ -123,7 +125,7 @@ grpc_closure *grpc_closure_create(grpc_iomgr_cb_func cb, void *cb_arg,
   wrapped_closure *wc = gpr_malloc(sizeof(*wc));
   wc->cb = cb;
   wc->cb_arg = cb_arg;
-#ifdef GRPC_CLOSURE_RICH_DEBUG
+#ifndef NDEBUG
   grpc_closure_init(file, line, &wc->wrapper, closure_wrapper, wc, scheduler);
 #else
   grpc_closure_init(&wc->wrapper, closure_wrapper, wc, scheduler);
@@ -131,7 +133,7 @@ grpc_closure *grpc_closure_create(grpc_iomgr_cb_func cb, void *cb_arg,
   return &wc->wrapper;
 }
 
-#ifdef GRPC_CLOSURE_RICH_DEBUG
+#ifndef NDEBUG
 void grpc_closure_run(const char *file, int line, grpc_exec_ctx *exec_ctx,
                       grpc_closure *c, grpc_error *error) {
 #else
@@ -140,7 +142,7 @@ void grpc_closure_run(grpc_exec_ctx *exec_ctx, grpc_closure *c,
 #endif
   GPR_TIMER_BEGIN("grpc_closure_run", 0);
   if (c != NULL) {
-#ifdef GRPC_CLOSURE_RICH_DEBUG
+#ifndef NDEBUG
     c->file_initiated = file;
     c->line_initiated = line;
     c->run = true;
@@ -153,7 +155,7 @@ void grpc_closure_run(grpc_exec_ctx *exec_ctx, grpc_closure *c,
   GPR_TIMER_END("grpc_closure_run", 0);
 }
 
-#ifdef GRPC_CLOSURE_RICH_DEBUG
+#ifndef NDEBUG
 void grpc_closure_sched(const char *file, int line, grpc_exec_ctx *exec_ctx,
                         grpc_closure *c, grpc_error *error) {
 #else
@@ -162,7 +164,7 @@ void grpc_closure_sched(grpc_exec_ctx *exec_ctx, grpc_closure *c,
 #endif
   GPR_TIMER_BEGIN("grpc_closure_sched", 0);
   if (c != NULL) {
-#ifdef GRPC_CLOSURE_RICH_DEBUG
+#ifndef NDEBUG
     GPR_ASSERT(!c->scheduled);
     c->scheduled = true;
     c->file_initiated = file;
@@ -177,7 +179,7 @@ void grpc_closure_sched(grpc_exec_ctx *exec_ctx, grpc_closure *c,
   GPR_TIMER_END("grpc_closure_sched", 0);
 }
 
-#ifdef GRPC_CLOSURE_RICH_DEBUG
+#ifndef NDEBUG
 void grpc_closure_list_sched(const char *file, int line,
                              grpc_exec_ctx *exec_ctx, grpc_closure_list *list) {
 #else
@@ -186,7 +188,7 @@ void grpc_closure_list_sched(grpc_exec_ctx *exec_ctx, grpc_closure_list *list) {
   grpc_closure *c = list->head;
   while (c != NULL) {
     grpc_closure *next = c->next_data.next;
-#ifdef GRPC_CLOSURE_RICH_DEBUG
+#ifndef NDEBUG
     GPR_ASSERT(!c->scheduled);
     c->scheduled = true;
     c->file_initiated = file;
diff --git a/src/core/lib/iomgr/closure.h b/src/core/lib/iomgr/closure.h
index 3ecf9e947b..874d08d29e 100644
--- a/src/core/lib/iomgr/closure.h
+++ b/src/core/lib/iomgr/closure.h
@@ -29,6 +29,8 @@
 struct grpc_closure;
 typedef struct grpc_closure grpc_closure;
 
+extern grpc_tracer_flag grpc_trace_closure;
+
 typedef struct grpc_closure_list {
   grpc_closure *head;
   grpc_closure *tail;
@@ -59,8 +61,6 @@ struct grpc_closure_scheduler {
   const grpc_closure_scheduler_vtable *vtable;
 };
 
-// #define GRPC_CLOSURE_RICH_DEBUG
-
 /** A closure over a grpc_iomgr_cb_func. */
 struct grpc_closure {
   /** Once queued, next indicates the next queued closure; before then, scratch
@@ -89,7 +89,7 @@ struct grpc_closure {
 
 // extra tracing and debugging for grpc_closure. This incurs a decent amount of
 // overhead per closure, so it must be enabled at compile time.
-#ifdef GRPC_CLOSURE_RICH_DEBUG
+#ifndef NDEBUG
   bool scheduled;
   bool run;  // true = run, false = scheduled
   const char *file_created;
@@ -100,7 +100,7 @@ struct grpc_closure {
 };
 
 /** Initializes \a closure with \a cb and \a cb_arg. Returns \a closure. */
-#ifdef GRPC_CLOSURE_RICH_DEBUG
+#ifndef NDEBUG
 grpc_closure *grpc_closure_init(const char *file, int line,
                                 grpc_closure *closure, grpc_iomgr_cb_func cb,
                                 void *cb_arg,
@@ -116,7 +116,7 @@ grpc_closure *grpc_closure_init(grpc_closure *closure, grpc_iomgr_cb_func cb,
 #endif
 
 /* Create a heap allocated closure: try to avoid except for very rare events */
-#ifdef GRPC_CLOSURE_RICH_DEBUG
+#ifndef NDEBUG
 grpc_closure *grpc_closure_create(const char *file, int line,
                                   grpc_iomgr_cb_func cb, void *cb_arg,
                                   grpc_closure_scheduler *scheduler);
@@ -153,7 +153,7 @@ bool grpc_closure_list_empty(grpc_closure_list list);
 /** Run a closure directly. Caller ensures that no locks are being held above.
  *  Note that calling this at the end of a closure callback function itself is
  *  by definition safe. */
-#ifdef GRPC_CLOSURE_RICH_DEBUG
+#ifndef NDEBUG
 void grpc_closure_run(const char *file, int line, grpc_exec_ctx *exec_ctx,
                       grpc_closure *closure, grpc_error *error);
 #define GRPC_CLOSURE_RUN(exec_ctx, closure, error) \
@@ -166,7 +166,7 @@ void grpc_closure_run(grpc_exec_ctx *exec_ctx, grpc_closure *closure,
 #endif
 
 /** Schedule a closure to be run. Does not need to be run from a safe point. */
-#ifdef GRPC_CLOSURE_RICH_DEBUG
+#ifndef NDEBUG
 void grpc_closure_sched(const char *file, int line, grpc_exec_ctx *exec_ctx,
                         grpc_closure *closure, grpc_error *error);
 #define GRPC_CLOSURE_SCHED(exec_ctx, closure, error) \
@@ -180,7 +180,7 @@ void grpc_closure_sched(grpc_exec_ctx *exec_ctx, grpc_closure *closure,
 
 /** Schedule all closures in a list to be run. Does not need to be run from a
  * safe point. */
-#ifdef GRPC_CLOSURE_RICH_DEBUG
+#ifndef NDEBUG
 void grpc_closure_list_sched(const char *file, int line,
                              grpc_exec_ctx *exec_ctx,
                              grpc_closure_list *closure_list);
diff --git a/src/core/lib/iomgr/combiner.c b/src/core/lib/iomgr/combiner.c
index 750ff102ff..d1377a942a 100644
--- a/src/core/lib/iomgr/combiner.c
+++ b/src/core/lib/iomgr/combiner.c
@@ -247,7 +247,7 @@ bool grpc_combiner_continue_exec_ctx(grpc_exec_ctx *exec_ctx) {
     GPR_TIMER_BEGIN("combiner.exec1", 0);
     grpc_closure *cl = (grpc_closure *)n;
     grpc_error *cl_err = cl->error_data.error;
-#ifdef GRPC_CLOSURE_RICH_DEBUG
+#ifndef NDEBUG
     cl->scheduled = false;
 #endif
     cl->cb(exec_ctx, cl->cb_arg, cl_err);
@@ -264,7 +264,7 @@ bool grpc_combiner_continue_exec_ctx(grpc_exec_ctx *exec_ctx) {
           gpr_log(GPR_DEBUG, "C:%p execute_final[%d] c=%p", lock, loops, c));
       grpc_closure *next = c->next_data.next;
       grpc_error *error = c->error_data.error;
-#ifdef GRPC_CLOSURE_RICH_DEBUG
+#ifndef NDEBUG
       c->scheduled = false;
 #endif
       c->cb(exec_ctx, c->cb_arg, error);
diff --git a/src/core/lib/iomgr/error.c b/src/core/lib/iomgr/error.c
index 68884226b5..30a6a0fd2c 100644
--- a/src/core/lib/iomgr/error.c
+++ b/src/core/lib/iomgr/error.c
@@ -34,6 +34,8 @@
 #include "src/core/lib/profiling/timers.h"
 #include "src/core/lib/slice/slice_internal.h"
 
+grpc_tracer_flag grpc_trace_error_refcount = GRPC_TRACER_INITIALIZER(false);
+
 static const char *error_int_name(grpc_error_ints key) {
   switch (key) {
     case GRPC_ERROR_INT_ERRNO:
@@ -119,14 +121,16 @@ bool grpc_error_is_special(grpc_error *err) {
          err == GRPC_ERROR_CANCELLED;
 }
 
-#ifdef GRPC_ERROR_REFCOUNT_DEBUG
+#ifndef NDEBUG
 grpc_error *grpc_error_ref(grpc_error *err, const char *file, int line,
                            const char *func) {
   if (grpc_error_is_special(err)) return err;
-  gpr_log(GPR_DEBUG, "%p: %" PRIdPTR " -> %" PRIdPTR " [%s:%d %s]", err,
+  if (GRPC_TRACER_ON(grpc_trace_error_refcount)) {
+   gpr_log(GPR_DEBUG, "%p: %" PRIdPTR " -> %" PRIdPTR " [%s:%d %s]", err,
           gpr_atm_no_barrier_load(&err->atomics.refs.count),
           gpr_atm_no_barrier_load(&err->atomics.refs.count) + 1, file, line,
           func);
+  }
   gpr_ref(&err->atomics.refs);
   return err;
 }
@@ -172,14 +176,16 @@ static void error_destroy(grpc_error *err) {
   gpr_free(err);
 }
 
-#ifdef GRPC_ERROR_REFCOUNT_DEBUG
+#ifndef NDEBUG
 void grpc_error_unref(grpc_error *err, const char *file, int line,
                       const char *func) {
   if (grpc_error_is_special(err)) return;
-  gpr_log(GPR_DEBUG, "%p: %" PRIdPTR " -> %" PRIdPTR " [%s:%d %s]", err,
-          gpr_atm_no_barrier_load(&err->atomics.refs.count),
-          gpr_atm_no_barrier_load(&err->atomics.refs.count) - 1, file, line,
-          func);
+  if (GRPC_TRACER_ON(grpc_trace_error_refcount)) {
+    gpr_log(GPR_DEBUG, "%p: %" PRIdPTR " -> %" PRIdPTR " [%s:%d %s]", err,
+            gpr_atm_no_barrier_load(&err->atomics.refs.count),
+            gpr_atm_no_barrier_load(&err->atomics.refs.count) - 1, file, line,
+            func);
+  }
   if (gpr_unref(&err->atomics.refs)) {
     error_destroy(err);
   }
@@ -202,13 +208,17 @@ static uint8_t get_placement(grpc_error **err, size_t size) {
     if ((*err)->arena_size + slots > (*err)->arena_capacity) {
       return UINT8_MAX;
     }
-#ifdef GRPC_ERROR_REFCOUNT_DEBUG
+#ifndef NDEBUG
     grpc_error *orig = *err;
 #endif
     *err = gpr_realloc(
         *err, sizeof(grpc_error) + (*err)->arena_capacity * sizeof(intptr_t));
-#ifdef GRPC_ERROR_REFCOUNT_DEBUG
-    if (*err != orig) gpr_log(GPR_DEBUG, "realloc %p -> %p", orig, *err);
+#ifndef NDEBUG
+    if (GRPC_TRACER_ON(grpc_trace_error_refcount)) {
+      if (*err != orig) {
+        gpr_log(GPR_DEBUG, "realloc %p -> %p", orig, *err);
+      }
+    }
 #endif
   }
   uint8_t placement = (*err)->arena_size;
@@ -316,8 +326,10 @@ grpc_error *grpc_error_create(const char *file, int line, grpc_slice desc,
   if (err == NULL) {  // TODO(ctiller): make gpr_malloc return NULL
     return GRPC_ERROR_OOM;
   }
-#ifdef GRPC_ERROR_REFCOUNT_DEBUG
-  gpr_log(GPR_DEBUG, "%p create [%s:%d]", err, file, line);
+#ifndef NDEBUG
+  if (GRPC_TRACER_ON(grpc_trace_error_refcount)) {
+    gpr_log(GPR_DEBUG, "%p create [%s:%d]", err, file, line);
+  }
 #endif
 
   err->arena_size = 0;
@@ -395,8 +407,10 @@ static grpc_error *copy_error_and_unref(grpc_error *in) {
       new_arena_capacity = (uint8_t)(3 * new_arena_capacity / 2);
     }
     out = gpr_malloc(sizeof(*in) + new_arena_capacity * sizeof(intptr_t));
-#ifdef GRPC_ERROR_REFCOUNT_DEBUG
-    gpr_log(GPR_DEBUG, "%p create copying %p", out, in);
+#ifndef NDEBUG
+    if (GRPC_TRACER_ON(grpc_trace_error_refcount)) {
+      gpr_log(GPR_DEBUG, "%p create copying %p", out, in);
+    }
 #endif
     // bulk memcpy of the rest of the struct.
     size_t skip = sizeof(&out->atomics);
diff --git a/src/core/lib/iomgr/error.h b/src/core/lib/iomgr/error.h
index 1ce916f2ec..729f4eb70c 100644
--- a/src/core/lib/iomgr/error.h
+++ b/src/core/lib/iomgr/error.h
@@ -26,6 +26,8 @@
 #include <grpc/status.h>
 #include <grpc/support/time.h>
 
+#include "src/core/lib/debug/trace.h"
+
 #ifdef __cplusplus
 extern "C" {
 #endif
@@ -36,6 +38,8 @@ extern "C" {
 
 typedef struct grpc_error grpc_error;
 
+extern grpc_tracer_flag grpc_trace_error_refcount;
+
 typedef enum {
   /// 'errno' from the operating system
   GRPC_ERROR_INT_ERRNO,
@@ -149,8 +153,7 @@ grpc_error *grpc_error_create(const char *file, int line, grpc_slice desc,
   grpc_error_create(__FILE__, __LINE__, grpc_slice_from_copied_string(desc), \
                     errs, count)
 
-// #define GRPC_ERROR_REFCOUNT_DEBUG
-#ifdef GRPC_ERROR_REFCOUNT_DEBUG
+#ifndef NDEBUG
 grpc_error *grpc_error_ref(grpc_error *err, const char *file, int line,
                            const char *func);
 void grpc_error_unref(grpc_error *err, const char *file, int line,
diff --git a/src/core/lib/iomgr/exec_ctx.c b/src/core/lib/iomgr/exec_ctx.c
index 51c36216c5..322944eb98 100644
--- a/src/core/lib/iomgr/exec_ctx.c
+++ b/src/core/lib/iomgr/exec_ctx.c
@@ -62,7 +62,7 @@ bool grpc_exec_ctx_flush(grpc_exec_ctx *exec_ctx) {
         grpc_closure *next = c->next_data.next;
         grpc_error *error = c->error_data.error;
         did_something = true;
-#ifdef GRPC_CLOSURE_RICH_DEBUG
+#ifndef NDEBUG
         c->scheduled = false;
 #endif
         c->cb(exec_ctx, c->cb_arg, error);
@@ -85,10 +85,21 @@ void grpc_exec_ctx_finish(grpc_exec_ctx *exec_ctx) {
 
 static void exec_ctx_run(grpc_exec_ctx *exec_ctx, grpc_closure *closure,
                          grpc_error *error) {
-#ifdef GRPC_CLOSURE_RICH_DEBUG
+#ifndef NDEBUG
   closure->scheduled = false;
+  if (GRPC_TRACER_ON(grpc_trace_closure)) {
+    gpr_log(GPR_DEBUG, "running closure %p: created [%s:%d]: %s [%s:%d]", 
+            closure, closure->file_created, closure->line_created,
+            closure->run ? "run" : "scheduled", closure->file_initiated,
+            closure->line_initiated);
+  }
 #endif
   closure->cb(exec_ctx, closure->cb_arg, error);
+#ifndef NDEBUG
+  if (GRPC_TRACER_ON(grpc_trace_closure)) {
+    gpr_log(GPR_DEBUG, "closure %p finished", closure);
+  }
+#endif
   GRPC_ERROR_UNREF(error);
 }
 
diff --git a/src/core/lib/iomgr/executor.c b/src/core/lib/iomgr/executor.c
index fda274e797..7621a7fe75 100644
--- a/src/core/lib/iomgr/executor.c
+++ b/src/core/lib/iomgr/executor.c
@@ -58,7 +58,7 @@ static size_t run_closures(grpc_exec_ctx *exec_ctx, grpc_closure_list list) {
   while (c != NULL) {
     grpc_closure *next = c->next_data.next;
     grpc_error *error = c->error_data.error;
-#ifdef GRPC_CLOSURE_RICH_DEBUG
+#ifndef NDEBUG
     c->scheduled = false;
 #endif
     c->cb(exec_ctx, c->cb_arg, error);
diff --git a/src/core/lib/surface/init.c b/src/core/lib/surface/init.c
index 01a1f33db2..9b8077bc6c 100644
--- a/src/core/lib/surface/init.c
+++ b/src/core/lib/surface/init.c
@@ -138,6 +138,8 @@ void grpc_init(void) {
     grpc_register_tracer("call_error", &grpc_call_error_trace);
 #ifndef NDEBUG
     grpc_register_tracer("pending_tags", &grpc_trace_pending_tags);
+    grpc_register_tracer("closure", &grpc_trace_closure);
+    grpc_register_tracer("error_refcount", &grpc_trace_error_refcount);
 #endif
     grpc_security_pre_init();
     grpc_iomgr_init(&exec_ctx);