From f0c46e360b3e740aea254b5adc0c9dfeae31243a Mon Sep 17 00:00:00 2001
From: ncteisen <ncteisen@gmail.com>
Date: Thu, 8 Jun 2017 15:57:09 -0700
Subject: [PATCH] Rework error and closure tracing
---
src/core/lib/iomgr/closure.c | 22 +++++++++---------
src/core/lib/iomgr/closure.h | 16 ++++++-------
src/core/lib/iomgr/combiner.c | 4 ++--
src/core/lib/iomgr/error.c | 42 +++++++++++++++++++++++------------
src/core/lib/iomgr/error.h | 7 ++++--
src/core/lib/iomgr/exec_ctx.c | 15 +++++++++++--
src/core/lib/iomgr/executor.c | 2 +-
src/core/lib/surface/init.c | 2 ++
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);
--
GitLab