Merge pull request #10833 from ncteisen/tracing-overhaul

Tracing Overhaul

12 files changed, 86 insertions, 53 deletions

diff --git a/src/core/ext/filters/client_channel/client_channel_plugin.c b/src/core/ext/filters/client_channel/client_channel_plugin.c
index 2c6af1d78e..60e77d6268 100644
--- a/src/core/ext/filters/client_channel/client_channel_plugin.c
+++ b/src/core/ext/filters/client_channel/client_channel_plugin.c
@@ -78,6 +78,9 @@ void grpc_client_channel_init(void) {
       GRPC_CLIENT_CHANNEL, GRPC_CHANNEL_INIT_BUILTIN_PRIORITY, append_filter,
       (void *)&grpc_client_channel_filter);
   grpc_http_connect_register_handshaker_factory();
+#ifndef NDEBUG
+  grpc_register_tracer("resolver_refcount", &grpc_trace_resolver_refcount);
+#endif
 }
 
 void grpc_client_channel_shutdown(void) {
diff --git a/src/core/ext/filters/client_channel/lb_policy.c b/src/core/ext/filters/client_channel/lb_policy.c
index 50f8faef8e..8d69ba6af5 100644
--- a/src/core/ext/filters/client_channel/lb_policy.c
+++ b/src/core/ext/filters/client_channel/lb_policy.c
@@ -21,6 +21,10 @@
 
 #define WEAK_REF_BITS 16
 
+#ifndef NDEBUG
+grpc_tracer_flag grpc_trace_lb_policy_refcount = GRPC_TRACER_INITIALIZER(false);
+#endif
+
 void grpc_lb_policy_init(grpc_lb_policy *policy,
                          const grpc_lb_policy_vtable *vtable,
                          grpc_combiner *combiner) {
@@ -30,7 +34,7 @@ void grpc_lb_policy_init(grpc_lb_policy *policy,
   policy->combiner = GRPC_COMBINER_REF(combiner, "lb_policy");
 }
 
-#ifdef GRPC_LB_POLICY_REFCOUNT_DEBUG
+#ifndef NDEBUG
 #define REF_FUNC_EXTRA_ARGS , const char *file, int line, const char *reason
 #define REF_MUTATE_EXTRA_ARGS REF_FUNC_EXTRA_ARGS, const char *purpose
 #define REF_FUNC_PASS_ARGS(new_reason) , file, line, new_reason
@@ -46,11 +50,12 @@ static gpr_atm ref_mutate(grpc_lb_policy *c, gpr_atm delta,
                           int barrier REF_MUTATE_EXTRA_ARGS) {
   gpr_atm old_val = barrier ? gpr_atm_full_fetch_add(&c->ref_pair, delta)
                             : gpr_atm_no_barrier_fetch_add(&c->ref_pair, delta);
-#ifdef GRPC_LB_POLICY_REFCOUNT_DEBUG
-  gpr_log(file, line, GPR_LOG_SEVERITY_DEBUG,
-          "LB_POLICY: 0x%" PRIxPTR " %12s 0x%" PRIxPTR " -> 0x%" PRIxPTR
-          " [%s]",
-          (intptr_t)c, purpose, old_val, old_val + delta, reason);
+#ifndef NDEBUG
+  if (GRPC_TRACER_ON(grpc_trace_lb_policy_refcount)) {
+    gpr_log(file, line, GPR_LOG_SEVERITY_DEBUG,
+            "LB_POLICY: 0x%p %12s 0x%" PRIxPTR " -> 0x%" PRIxPTR " [%s]", c,
+            purpose, old_val, old_val + delta, reason);
+  }
 #endif
   return old_val;
 }
diff --git a/src/core/ext/filters/client_channel/lb_policy.h b/src/core/ext/filters/client_channel/lb_policy.h
index 42503c37ca..645d51e138 100644
--- a/src/core/ext/filters/client_channel/lb_policy.h
+++ b/src/core/ext/filters/client_channel/lb_policy.h
@@ -29,6 +29,10 @@ typedef struct grpc_lb_policy grpc_lb_policy;
 typedef struct grpc_lb_policy_vtable grpc_lb_policy_vtable;
 typedef struct grpc_lb_policy_args grpc_lb_policy_args;
 
+#ifndef NDEBUG
+extern grpc_tracer_flag grpc_trace_lb_policy_refcount;
+#endif
+
 struct grpc_lb_policy {
   const grpc_lb_policy_vtable *vtable;
   gpr_atm ref_pair;
@@ -96,8 +100,7 @@ struct grpc_lb_policy_vtable {
                         const grpc_lb_policy_args *args);
 };
 
-//#define GRPC_LB_POLICY_REFCOUNT_DEBUG
-#ifdef GRPC_LB_POLICY_REFCOUNT_DEBUG
+#ifndef NDEBUG
 
 /* Strong references: the policy will shutdown when they reach zero */
 #define GRPC_LB_POLICY_REF(p, r) \
diff --git a/src/core/ext/filters/client_channel/lb_policy/grpclb/grpclb.c b/src/core/ext/filters/client_channel/lb_policy/grpclb/grpclb.c
index e80b1dcd80..5a5ff2902d 100644
--- a/src/core/ext/filters/client_channel/lb_policy/grpclb/grpclb.c
+++ b/src/core/ext/filters/client_channel/lb_policy/grpclb/grpclb.c
@@ -1880,6 +1880,9 @@ static bool maybe_add_client_load_reporting_filter(
 void grpc_lb_policy_grpclb_init() {
   grpc_register_lb_policy(grpc_glb_lb_factory_create());
   grpc_register_tracer("glb", &grpc_lb_glb_trace);
+#ifndef NDEBUG
+  grpc_register_tracer("lb_policy_refcount", &grpc_trace_lb_policy_refcount);
+#endif
   grpc_channel_init_register_stage(GRPC_CLIENT_SUBCHANNEL,
                                    GRPC_CHANNEL_INIT_BUILTIN_PRIORITY,
                                    maybe_add_client_load_reporting_filter,
diff --git a/src/core/ext/filters/client_channel/resolver.c b/src/core/ext/filters/client_channel/resolver.c
index 69b1c31e59..de9a8ce41b 100644
--- a/src/core/ext/filters/client_channel/resolver.c
+++ b/src/core/ext/filters/client_channel/resolver.c
@@ -19,6 +19,10 @@
 #include "src/core/ext/filters/client_channel/resolver.h"
 #include "src/core/lib/iomgr/combiner.h"
 
+#ifndef NDEBUG
+grpc_tracer_flag grpc_trace_resolver_refcount = GRPC_TRACER_INITIALIZER(false);
+#endif
+
 void grpc_resolver_init(grpc_resolver *resolver,
                         const grpc_resolver_vtable *vtable,
                         grpc_combiner *combiner) {
@@ -27,25 +31,30 @@ void grpc_resolver_init(grpc_resolver *resolver,
   gpr_ref_init(&resolver->refs, 1);
 }
 
-#ifdef GRPC_RESOLVER_REFCOUNT_DEBUG
-void grpc_resolver_ref(grpc_resolver *resolver, grpc_closure_list *closure_list,
-                       const char *file, int line, const char *reason) {
-  gpr_log(file, line, GPR_LOG_SEVERITY_DEBUG, "RESOLVER:%p   ref %d -> %d %s",
-          resolver, (int)resolver->refs.count, (int)resolver->refs.count + 1,
-          reason);
+#ifndef NDEBUG
+void grpc_resolver_ref(grpc_resolver *resolver, const char *file, int line,
+                       const char *reason) {
+  if (GRPC_TRACER_ON(grpc_trace_resolver_refcount)) {
+    gpr_atm old_refs = gpr_atm_no_barrier_load(&resolver->refs.count);
+    gpr_log(file, line, GPR_LOG_SEVERITY_DEBUG,
+            "RESOLVER:%p   ref %" PRIdPTR " -> %" PRIdPTR " %s", resolver,
+            old_refs, old_refs + 1, reason);
+  }
 #else
 void grpc_resolver_ref(grpc_resolver *resolver) {
 #endif
   gpr_ref(&resolver->refs);
 }
 
-#ifdef GRPC_RESOLVER_REFCOUNT_DEBUG
-void grpc_resolver_unref(grpc_resolver *resolver,
-                         grpc_closure_list *closure_list, const char *file,
-                         int line, const char *reason) {
-  gpr_log(file, line, GPR_LOG_SEVERITY_DEBUG, "RESOLVER:%p unref %d -> %d %s",
-          resolver, (int)resolver->refs.count, (int)resolver->refs.count - 1,
-          reason);
+#ifndef NDEBUG
+void grpc_resolver_unref(grpc_exec_ctx *exec_ctx, grpc_resolver *resolver,
+                         const char *file, int line, const char *reason) {
+  if (GRPC_TRACER_ON(grpc_trace_resolver_refcount)) {
+    gpr_atm old_refs = gpr_atm_no_barrier_load(&resolver->refs.count);
+    gpr_log(file, line, GPR_LOG_SEVERITY_DEBUG,
+            "RESOLVER:%p unref %" PRIdPTR " -> %" PRIdPTR " %s", resolver,
+            old_refs, old_refs - 1, reason);
+  }
 #else
 void grpc_resolver_unref(grpc_exec_ctx *exec_ctx, grpc_resolver *resolver) {
 #endif
diff --git a/src/core/ext/filters/client_channel/resolver.h b/src/core/ext/filters/client_channel/resolver.h
index c78bb316cb..ae9c8f66fe 100644
--- a/src/core/ext/filters/client_channel/resolver.h
+++ b/src/core/ext/filters/client_channel/resolver.h
@@ -25,6 +25,10 @@
 typedef struct grpc_resolver grpc_resolver;
 typedef struct grpc_resolver_vtable grpc_resolver_vtable;
 
+#ifndef NDEBUG
+extern grpc_tracer_flag grpc_trace_resolver_refcount;
+#endif
+
 /** \a grpc_resolver provides \a grpc_channel_args objects to its caller */
 struct grpc_resolver {
   const grpc_resolver_vtable *vtable;
@@ -41,17 +45,17 @@ struct grpc_resolver_vtable {
                       grpc_channel_args **result, grpc_closure *on_complete);
 };
 
-#ifdef GRPC_RESOLVER_REFCOUNT_DEBUG
+#ifndef NDEBUG
 #define GRPC_RESOLVER_REF(p, r) grpc_resolver_ref((p), __FILE__, __LINE__, (r))
-#define GRPC_RESOLVER_UNREF(cl, p, r) \
-  grpc_resolver_unref((cl), (p), __FILE__, __LINE__, (r))
+#define GRPC_RESOLVER_UNREF(e, p, r) \
+  grpc_resolver_unref((e), (p), __FILE__, __LINE__, (r))
 void grpc_resolver_ref(grpc_resolver *policy, const char *file, int line,
                        const char *reason);
-void grpc_resolver_unref(grpc_resolver *policy, grpc_closure_list *closure_list,
+void grpc_resolver_unref(grpc_exec_ctx *exec_ctx, grpc_resolver *policy,
                          const char *file, int line, const char *reason);
 #else
 #define GRPC_RESOLVER_REF(p, r) grpc_resolver_ref((p))
-#define GRPC_RESOLVER_UNREF(cl, p, r) grpc_resolver_unref((cl), (p))
+#define GRPC_RESOLVER_UNREF(e, p, r) grpc_resolver_unref((e), (p))
 void grpc_resolver_ref(grpc_resolver *policy);
 void grpc_resolver_unref(grpc_exec_ctx *exec_ctx, grpc_resolver *policy);
 #endif
diff --git a/src/core/ext/filters/client_channel/subchannel.c b/src/core/ext/filters/client_channel/subchannel.c
index 0877ef4e67..88157ed738 100644
--- a/src/core/ext/filters/client_channel/subchannel.c
+++ b/src/core/ext/filters/client_channel/subchannel.c
@@ -140,25 +140,13 @@ struct grpc_subchannel_call {
 static void subchannel_connected(grpc_exec_ctx *exec_ctx, void *subchannel,
                                  grpc_error *error);
 
-#ifdef GRPC_STREAM_REFCOUNT_DEBUG
+#ifndef NDEBUG
 #define REF_REASON reason
-#define REF_LOG(name, p)                                                  \
-  gpr_log(file, line, GPR_LOG_SEVERITY_DEBUG, "%s: %p   ref %d -> %d %s", \
-          (name), (p), (p)->refs.count, (p)->refs.count + 1, reason)
-#define UNREF_LOG(name, p)                                                \
-  gpr_log(file, line, GPR_LOG_SEVERITY_DEBUG, "%s: %p unref %d -> %d %s", \
-          (name), (p), (p)->refs.count, (p)->refs.count - 1, reason)
 #define REF_MUTATE_EXTRA_ARGS \
   GRPC_SUBCHANNEL_REF_EXTRA_ARGS, const char *purpose
 #define REF_MUTATE_PURPOSE(x) , file, line, reason, x
 #else
 #define REF_REASON ""
-#define REF_LOG(name, p) \
-  do {                   \
-  } while (0)
-#define UNREF_LOG(name, p) \
-  do {                     \
-  } while (0)
 #define REF_MUTATE_EXTRA_ARGS
 #define REF_MUTATE_PURPOSE(x)
 #endif
@@ -207,10 +195,12 @@ static gpr_atm ref_mutate(grpc_subchannel *c, gpr_atm delta,
                           int barrier REF_MUTATE_EXTRA_ARGS) {
   gpr_atm old_val = barrier ? gpr_atm_full_fetch_add(&c->ref_pair, delta)
                             : gpr_atm_no_barrier_fetch_add(&c->ref_pair, delta);
-#ifdef GRPC_STREAM_REFCOUNT_DEBUG
-  gpr_log(file, line, GPR_LOG_SEVERITY_DEBUG,
-          "SUBCHANNEL: %p %s 0x%08" PRIxPTR " -> 0x%08" PRIxPTR " [%s]", c,
-          purpose, old_val, old_val + delta, reason);
+#ifndef NDEBUG
+  if (GRPC_TRACER_ON(grpc_trace_stream_refcount)) {
+    gpr_log(file, line, GPR_LOG_SEVERITY_DEBUG,
+            "SUBCHANNEL: %p %12s 0x%" PRIxPTR " -> 0x%" PRIxPTR " [%s]", c,
+            purpose, old_val, old_val + delta, reason);
+  }
 #endif
   return old_val;
 }
diff --git a/src/core/ext/filters/client_channel/subchannel.h b/src/core/ext/filters/client_channel/subchannel.h
index f38bf42803..6d2abb04df 100644
--- a/src/core/ext/filters/client_channel/subchannel.h
+++ b/src/core/ext/filters/client_channel/subchannel.h
@@ -37,7 +37,7 @@ typedef struct grpc_subchannel_call grpc_subchannel_call;
 typedef struct grpc_subchannel_args grpc_subchannel_args;
 typedef struct grpc_subchannel_key grpc_subchannel_key;
 
-#ifdef GRPC_STREAM_REFCOUNT_DEBUG
+#ifndef NDEBUG
 #define GRPC_SUBCHANNEL_REF(p, r) \
   grpc_subchannel_ref((p), __FILE__, __LINE__, (r))
 #define GRPC_SUBCHANNEL_REF_FROM_WEAK_REF(p, r) \
diff --git a/src/core/ext/transport/chttp2/transport/chttp2_plugin.c b/src/core/ext/transport/chttp2/transport/chttp2_plugin.c
index b0ffdc0cf9..6a8c81445a 100644
--- a/src/core/ext/transport/chttp2/transport/chttp2_plugin.c
+++ b/src/core/ext/transport/chttp2/transport/chttp2_plugin.c
@@ -23,6 +23,9 @@
 void grpc_chttp2_plugin_init(void) {
   grpc_register_tracer("http", &grpc_http_trace);
   grpc_register_tracer("flowctl", &grpc_flowctl_trace);
+#ifndef NDEBUG
+  grpc_register_tracer("chttp2_refcount", &grpc_trace_chttp2_refcount);
+#endif
 }
 
 void grpc_chttp2_plugin_shutdown(void) {}
diff --git a/src/core/ext/transport/chttp2/transport/chttp2_transport.c b/src/core/ext/transport/chttp2/transport/chttp2_transport.c
index cd2c6cc492..1f4abbc792 100644
--- a/src/core/ext/transport/chttp2/transport/chttp2_transport.c
+++ b/src/core/ext/transport/chttp2/transport/chttp2_transport.c
@@ -76,6 +76,10 @@ static bool g_default_keepalive_permit_without_calls =
 grpc_tracer_flag grpc_http_trace = GRPC_TRACER_INITIALIZER(false);
 grpc_tracer_flag grpc_flowctl_trace = GRPC_TRACER_INITIALIZER(false);
 
+#ifndef NDEBUG
+grpc_tracer_flag grpc_trace_chttp2_refcount = GRPC_TRACER_INITIALIZER(false);
+#endif
+
 static const grpc_transport_vtable vtable;
 
 /* forward declarations of various callbacks that we'll build closures around */
@@ -213,20 +217,26 @@ static void destruct_transport(grpc_exec_ctx *exec_ctx,
   gpr_free(t);
 }
 
-#ifdef GRPC_CHTTP2_REFCOUNTING_DEBUG
+#ifndef NDEBUG
 void grpc_chttp2_unref_transport(grpc_exec_ctx *exec_ctx,
                                  grpc_chttp2_transport *t, const char *reason,
                                  const char *file, int line) {
-  gpr_log(GPR_DEBUG, "chttp2:unref:%p %" PRIdPTR "->%" PRIdPTR " %s [%s:%d]", t,
-          t->refs.count, t->refs.count - 1, reason, file, line);
+  if (GRPC_TRACER_ON(grpc_trace_chttp2_refcount)) {
+    gpr_atm val = gpr_atm_no_barrier_load(&t->refs.count);
+    gpr_log(GPR_DEBUG, "chttp2:unref:%p %" PRIdPTR "->%" PRIdPTR " %s [%s:%d]",
+            t, val, val - 1, reason, file, line);
+  }
   if (!gpr_unref(&t->refs)) return;
   destruct_transport(exec_ctx, t);
 }
 
 void grpc_chttp2_ref_transport(grpc_chttp2_transport *t, const char *reason,
                                const char *file, int line) {
-  gpr_log(GPR_DEBUG, "chttp2:  ref:%p %" PRIdPTR "->%" PRIdPTR " %s [%s:%d]", t,
-          t->refs.count, t->refs.count + 1, reason, file, line);
+  if (GRPC_TRACER_ON(grpc_trace_chttp2_refcount)) {
+    gpr_atm val = gpr_atm_no_barrier_load(&t->refs.count);
+    gpr_log(GPR_DEBUG, "chttp2:  ref:%p %" PRIdPTR "->%" PRIdPTR " %s [%s:%d]",
+            t, val, val + 1, reason, file, line);
+  }
   gpr_ref(&t->refs);
 }
 #else
@@ -622,7 +632,7 @@ static void close_transport_locked(grpc_exec_ctx *exec_ctx,
   GRPC_ERROR_UNREF(error);
 }
 
-#ifdef GRPC_STREAM_REFCOUNT_DEBUG
+#ifndef NDEBUG
 void grpc_chttp2_stream_ref(grpc_chttp2_stream *s, const char *reason) {
   grpc_stream_ref(s->refcount, reason);
 }
diff --git a/src/core/ext/transport/chttp2/transport/chttp2_transport.h b/src/core/ext/transport/chttp2/transport/chttp2_transport.h
index 0a1fb4d772..0c4e2a91c0 100644
--- a/src/core/ext/transport/chttp2/transport/chttp2_transport.h
+++ b/src/core/ext/transport/chttp2/transport/chttp2_transport.h
@@ -26,6 +26,10 @@
 extern grpc_tracer_flag grpc_http_trace;
 extern grpc_tracer_flag grpc_flowctl_trace;
 
+#ifndef NDEBUG
+extern grpc_tracer_flag grpc_trace_chttp2_refcount;
+#endif
+
 grpc_transport *grpc_create_chttp2_transport(
     grpc_exec_ctx *exec_ctx, const grpc_channel_args *channel_args,
     grpc_endpoint *ep, int is_client);
diff --git a/src/core/ext/transport/chttp2/transport/internal.h b/src/core/ext/transport/chttp2/transport/internal.h
index 4041b29fec..b7ac744795 100644
--- a/src/core/ext/transport/chttp2/transport/internal.h
+++ b/src/core/ext/transport/chttp2/transport/internal.h
@@ -748,7 +748,7 @@ void grpc_chttp2_mark_stream_closed(grpc_exec_ctx *exec_ctx,
 void grpc_chttp2_start_writing(grpc_exec_ctx *exec_ctx,
                                grpc_chttp2_transport *t);
 
-#ifdef GRPC_STREAM_REFCOUNT_DEBUG
+#ifndef NDEBUG
 #define GRPC_CHTTP2_STREAM_REF(stream, reason) \
   grpc_chttp2_stream_ref(stream, reason)
 #define GRPC_CHTTP2_STREAM_UNREF(exec_ctx, stream, reason) \
@@ -764,8 +764,7 @@ void grpc_chttp2_stream_ref(grpc_chttp2_stream *s);
 void grpc_chttp2_stream_unref(grpc_exec_ctx *exec_ctx, grpc_chttp2_stream *s);
 #endif
 
-//#define GRPC_CHTTP2_REFCOUNTING_DEBUG 1
-#ifdef GRPC_CHTTP2_REFCOUNTING_DEBUG
+#ifndef NDEBUG
 #define GRPC_CHTTP2_REF_TRANSPORT(t, r) \
   grpc_chttp2_ref_transport(t, r, __FILE__, __LINE__)
 #define GRPC_CHTTP2_UNREF_TRANSPORT(cl, t, r) \