Rework error and closure tracing

pull/10833/head
ncteisen 8 years ago
parent a4bc791fd8
commit f0c46e360b
  1. 22
      src/core/lib/iomgr/closure.c
  2. 16
      src/core/lib/iomgr/closure.h
  3. 4
      src/core/lib/iomgr/combiner.c
  4. 42
      src/core/lib/iomgr/error.c
  5. 7
      src/core/lib/iomgr/error.h
  6. 15
      src/core/lib/iomgr/exec_ctx.c
  7. 2
      src/core/lib/iomgr/executor.c
  8. 2
      src/core/lib/surface/init.c

@ -24,7 +24,9 @@
#include "src/core/lib/profiling/timers.h" #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 *grpc_closure_init(const char *file, int line,
grpc_closure *closure, grpc_iomgr_cb_func cb, grpc_closure *closure, grpc_iomgr_cb_func cb,
void *cb_arg, 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 = cb;
closure->cb_arg = cb_arg; closure->cb_arg = cb_arg;
closure->scheduler = scheduler; closure->scheduler = scheduler;
#ifdef GRPC_CLOSURE_RICH_DEBUG #ifndef NDEBUG
closure->scheduled = false; closure->scheduled = false;
closure->file_initiated = NULL; closure->file_initiated = NULL;
closure->line_initiated = 0; 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); cb(exec_ctx, cb_arg, error);
} }
#ifdef GRPC_CLOSURE_RICH_DEBUG #ifndef NDEBUG
grpc_closure *grpc_closure_create(const char *file, int line, grpc_closure *grpc_closure_create(const char *file, int line,
grpc_iomgr_cb_func cb, void *cb_arg, grpc_iomgr_cb_func cb, void *cb_arg,
grpc_closure_scheduler *scheduler) { 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)); wrapped_closure *wc = gpr_malloc(sizeof(*wc));
wc->cb = cb; wc->cb = cb;
wc->cb_arg = cb_arg; wc->cb_arg = cb_arg;
#ifdef GRPC_CLOSURE_RICH_DEBUG #ifndef NDEBUG
grpc_closure_init(file, line, &wc->wrapper, closure_wrapper, wc, scheduler); grpc_closure_init(file, line, &wc->wrapper, closure_wrapper, wc, scheduler);
#else #else
grpc_closure_init(&wc->wrapper, closure_wrapper, wc, scheduler); 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; return &wc->wrapper;
} }
#ifdef GRPC_CLOSURE_RICH_DEBUG #ifndef NDEBUG
void grpc_closure_run(const char *file, int line, grpc_exec_ctx *exec_ctx, void grpc_closure_run(const char *file, int line, grpc_exec_ctx *exec_ctx,
grpc_closure *c, grpc_error *error) { grpc_closure *c, grpc_error *error) {
#else #else
@ -140,7 +142,7 @@ void grpc_closure_run(grpc_exec_ctx *exec_ctx, grpc_closure *c,
#endif #endif
GPR_TIMER_BEGIN("grpc_closure_run", 0); GPR_TIMER_BEGIN("grpc_closure_run", 0);
if (c != NULL) { if (c != NULL) {
#ifdef GRPC_CLOSURE_RICH_DEBUG #ifndef NDEBUG
c->file_initiated = file; c->file_initiated = file;
c->line_initiated = line; c->line_initiated = line;
c->run = true; 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); 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, void grpc_closure_sched(const char *file, int line, grpc_exec_ctx *exec_ctx,
grpc_closure *c, grpc_error *error) { grpc_closure *c, grpc_error *error) {
#else #else
@ -162,7 +164,7 @@ void grpc_closure_sched(grpc_exec_ctx *exec_ctx, grpc_closure *c,
#endif #endif
GPR_TIMER_BEGIN("grpc_closure_sched", 0); GPR_TIMER_BEGIN("grpc_closure_sched", 0);
if (c != NULL) { if (c != NULL) {
#ifdef GRPC_CLOSURE_RICH_DEBUG #ifndef NDEBUG
GPR_ASSERT(!c->scheduled); GPR_ASSERT(!c->scheduled);
c->scheduled = true; c->scheduled = true;
c->file_initiated = file; 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); GPR_TIMER_END("grpc_closure_sched", 0);
} }
#ifdef GRPC_CLOSURE_RICH_DEBUG #ifndef NDEBUG
void grpc_closure_list_sched(const char *file, int line, void grpc_closure_list_sched(const char *file, int line,
grpc_exec_ctx *exec_ctx, grpc_closure_list *list) { grpc_exec_ctx *exec_ctx, grpc_closure_list *list) {
#else #else
@ -186,7 +188,7 @@ void grpc_closure_list_sched(grpc_exec_ctx *exec_ctx, grpc_closure_list *list) {
grpc_closure *c = list->head; grpc_closure *c = list->head;
while (c != NULL) { while (c != NULL) {
grpc_closure *next = c->next_data.next; grpc_closure *next = c->next_data.next;
#ifdef GRPC_CLOSURE_RICH_DEBUG #ifndef NDEBUG
GPR_ASSERT(!c->scheduled); GPR_ASSERT(!c->scheduled);
c->scheduled = true; c->scheduled = true;
c->file_initiated = file; c->file_initiated = file;

@ -29,6 +29,8 @@
struct grpc_closure; struct grpc_closure;
typedef struct grpc_closure grpc_closure; typedef struct grpc_closure grpc_closure;
extern grpc_tracer_flag grpc_trace_closure;
typedef struct grpc_closure_list { typedef struct grpc_closure_list {
grpc_closure *head; grpc_closure *head;
grpc_closure *tail; grpc_closure *tail;
@ -59,8 +61,6 @@ struct grpc_closure_scheduler {
const grpc_closure_scheduler_vtable *vtable; const grpc_closure_scheduler_vtable *vtable;
}; };
// #define GRPC_CLOSURE_RICH_DEBUG
/** A closure over a grpc_iomgr_cb_func. */ /** A closure over a grpc_iomgr_cb_func. */
struct grpc_closure { struct grpc_closure {
/** Once queued, next indicates the next queued closure; before then, scratch /** 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 // extra tracing and debugging for grpc_closure. This incurs a decent amount of
// overhead per closure, so it must be enabled at compile time. // overhead per closure, so it must be enabled at compile time.
#ifdef GRPC_CLOSURE_RICH_DEBUG #ifndef NDEBUG
bool scheduled; bool scheduled;
bool run; // true = run, false = scheduled bool run; // true = run, false = scheduled
const char *file_created; const char *file_created;
@ -100,7 +100,7 @@ struct grpc_closure {
}; };
/** Initializes \a closure with \a cb and \a cb_arg. Returns \a 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 *grpc_closure_init(const char *file, int line,
grpc_closure *closure, grpc_iomgr_cb_func cb, grpc_closure *closure, grpc_iomgr_cb_func cb,
void *cb_arg, void *cb_arg,
@ -116,7 +116,7 @@ grpc_closure *grpc_closure_init(grpc_closure *closure, grpc_iomgr_cb_func cb,
#endif #endif
/* Create a heap allocated closure: try to avoid except for very rare events */ /* 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_closure *grpc_closure_create(const char *file, int line,
grpc_iomgr_cb_func cb, void *cb_arg, grpc_iomgr_cb_func cb, void *cb_arg,
grpc_closure_scheduler *scheduler); 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. /** 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 * Note that calling this at the end of a closure callback function itself is
* by definition safe. */ * by definition safe. */
#ifdef GRPC_CLOSURE_RICH_DEBUG #ifndef NDEBUG
void grpc_closure_run(const char *file, int line, grpc_exec_ctx *exec_ctx, void grpc_closure_run(const char *file, int line, grpc_exec_ctx *exec_ctx,
grpc_closure *closure, grpc_error *error); grpc_closure *closure, grpc_error *error);
#define GRPC_CLOSURE_RUN(exec_ctx, closure, 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 #endif
/** Schedule a closure to be run. Does not need to be run from a safe point. */ /** 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, void grpc_closure_sched(const char *file, int line, grpc_exec_ctx *exec_ctx,
grpc_closure *closure, grpc_error *error); grpc_closure *closure, grpc_error *error);
#define GRPC_CLOSURE_SCHED(exec_ctx, closure, 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 /** Schedule all closures in a list to be run. Does not need to be run from a
* safe point. */ * safe point. */
#ifdef GRPC_CLOSURE_RICH_DEBUG #ifndef NDEBUG
void grpc_closure_list_sched(const char *file, int line, void grpc_closure_list_sched(const char *file, int line,
grpc_exec_ctx *exec_ctx, grpc_exec_ctx *exec_ctx,
grpc_closure_list *closure_list); grpc_closure_list *closure_list);

@ -247,7 +247,7 @@ bool grpc_combiner_continue_exec_ctx(grpc_exec_ctx *exec_ctx) {
GPR_TIMER_BEGIN("combiner.exec1", 0); GPR_TIMER_BEGIN("combiner.exec1", 0);
grpc_closure *cl = (grpc_closure *)n; grpc_closure *cl = (grpc_closure *)n;
grpc_error *cl_err = cl->error_data.error; grpc_error *cl_err = cl->error_data.error;
#ifdef GRPC_CLOSURE_RICH_DEBUG #ifndef NDEBUG
cl->scheduled = false; cl->scheduled = false;
#endif #endif
cl->cb(exec_ctx, cl->cb_arg, cl_err); 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)); gpr_log(GPR_DEBUG, "C:%p execute_final[%d] c=%p", lock, loops, c));
grpc_closure *next = c->next_data.next; grpc_closure *next = c->next_data.next;
grpc_error *error = c->error_data.error; grpc_error *error = c->error_data.error;
#ifdef GRPC_CLOSURE_RICH_DEBUG #ifndef NDEBUG
c->scheduled = false; c->scheduled = false;
#endif #endif
c->cb(exec_ctx, c->cb_arg, error); c->cb(exec_ctx, c->cb_arg, error);

@ -34,6 +34,8 @@
#include "src/core/lib/profiling/timers.h" #include "src/core/lib/profiling/timers.h"
#include "src/core/lib/slice/slice_internal.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) { static const char *error_int_name(grpc_error_ints key) {
switch (key) { switch (key) {
case GRPC_ERROR_INT_ERRNO: case GRPC_ERROR_INT_ERRNO:
@ -119,14 +121,16 @@ bool grpc_error_is_special(grpc_error *err) {
err == GRPC_ERROR_CANCELLED; err == GRPC_ERROR_CANCELLED;
} }
#ifdef GRPC_ERROR_REFCOUNT_DEBUG #ifndef NDEBUG
grpc_error *grpc_error_ref(grpc_error *err, const char *file, int line, grpc_error *grpc_error_ref(grpc_error *err, const char *file, int line,
const char *func) { const char *func) {
if (grpc_error_is_special(err)) return err; 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),
gpr_atm_no_barrier_load(&err->atomics.refs.count) + 1, file, line, gpr_atm_no_barrier_load(&err->atomics.refs.count) + 1, file, line,
func); func);
}
gpr_ref(&err->atomics.refs); gpr_ref(&err->atomics.refs);
return err; return err;
} }
@ -172,14 +176,16 @@ static void error_destroy(grpc_error *err) {
gpr_free(err); gpr_free(err);
} }
#ifdef GRPC_ERROR_REFCOUNT_DEBUG #ifndef NDEBUG
void grpc_error_unref(grpc_error *err, const char *file, int line, void grpc_error_unref(grpc_error *err, const char *file, int line,
const char *func) { const char *func) {
if (grpc_error_is_special(err)) return; if (grpc_error_is_special(err)) return;
gpr_log(GPR_DEBUG, "%p: %" PRIdPTR " -> %" PRIdPTR " [%s:%d %s]", err, if (GRPC_TRACER_ON(grpc_trace_error_refcount)) {
gpr_atm_no_barrier_load(&err->atomics.refs.count), gpr_log(GPR_DEBUG, "%p: %" PRIdPTR " -> %" PRIdPTR " [%s:%d %s]", err,
gpr_atm_no_barrier_load(&err->atomics.refs.count) - 1, file, line, gpr_atm_no_barrier_load(&err->atomics.refs.count),
func); gpr_atm_no_barrier_load(&err->atomics.refs.count) - 1, file, line,
func);
}
if (gpr_unref(&err->atomics.refs)) { if (gpr_unref(&err->atomics.refs)) {
error_destroy(err); 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) { if ((*err)->arena_size + slots > (*err)->arena_capacity) {
return UINT8_MAX; return UINT8_MAX;
} }
#ifdef GRPC_ERROR_REFCOUNT_DEBUG #ifndef NDEBUG
grpc_error *orig = *err; grpc_error *orig = *err;
#endif #endif
*err = gpr_realloc( *err = gpr_realloc(
*err, sizeof(grpc_error) + (*err)->arena_capacity * sizeof(intptr_t)); *err, sizeof(grpc_error) + (*err)->arena_capacity * sizeof(intptr_t));
#ifdef GRPC_ERROR_REFCOUNT_DEBUG #ifndef NDEBUG
if (*err != orig) gpr_log(GPR_DEBUG, "realloc %p -> %p", orig, *err); if (GRPC_TRACER_ON(grpc_trace_error_refcount)) {
if (*err != orig) {
gpr_log(GPR_DEBUG, "realloc %p -> %p", orig, *err);
}
}
#endif #endif
} }
uint8_t placement = (*err)->arena_size; 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 if (err == NULL) { // TODO(ctiller): make gpr_malloc return NULL
return GRPC_ERROR_OOM; return GRPC_ERROR_OOM;
} }
#ifdef GRPC_ERROR_REFCOUNT_DEBUG #ifndef NDEBUG
gpr_log(GPR_DEBUG, "%p create [%s:%d]", err, file, line); if (GRPC_TRACER_ON(grpc_trace_error_refcount)) {
gpr_log(GPR_DEBUG, "%p create [%s:%d]", err, file, line);
}
#endif #endif
err->arena_size = 0; 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); new_arena_capacity = (uint8_t)(3 * new_arena_capacity / 2);
} }
out = gpr_malloc(sizeof(*in) + new_arena_capacity * sizeof(intptr_t)); out = gpr_malloc(sizeof(*in) + new_arena_capacity * sizeof(intptr_t));
#ifdef GRPC_ERROR_REFCOUNT_DEBUG #ifndef NDEBUG
gpr_log(GPR_DEBUG, "%p create copying %p", out, in); if (GRPC_TRACER_ON(grpc_trace_error_refcount)) {
gpr_log(GPR_DEBUG, "%p create copying %p", out, in);
}
#endif #endif
// bulk memcpy of the rest of the struct. // bulk memcpy of the rest of the struct.
size_t skip = sizeof(&out->atomics); size_t skip = sizeof(&out->atomics);

@ -26,6 +26,8 @@
#include <grpc/status.h> #include <grpc/status.h>
#include <grpc/support/time.h> #include <grpc/support/time.h>
#include "src/core/lib/debug/trace.h"
#ifdef __cplusplus #ifdef __cplusplus
extern "C" { extern "C" {
#endif #endif
@ -36,6 +38,8 @@ extern "C" {
typedef struct grpc_error grpc_error; typedef struct grpc_error grpc_error;
extern grpc_tracer_flag grpc_trace_error_refcount;
typedef enum { typedef enum {
/// 'errno' from the operating system /// 'errno' from the operating system
GRPC_ERROR_INT_ERRNO, 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), \ grpc_error_create(__FILE__, __LINE__, grpc_slice_from_copied_string(desc), \
errs, count) errs, count)
// #define GRPC_ERROR_REFCOUNT_DEBUG #ifndef NDEBUG
#ifdef GRPC_ERROR_REFCOUNT_DEBUG
grpc_error *grpc_error_ref(grpc_error *err, const char *file, int line, grpc_error *grpc_error_ref(grpc_error *err, const char *file, int line,
const char *func); const char *func);
void grpc_error_unref(grpc_error *err, const char *file, int line, void grpc_error_unref(grpc_error *err, const char *file, int line,

@ -62,7 +62,7 @@ bool grpc_exec_ctx_flush(grpc_exec_ctx *exec_ctx) {
grpc_closure *next = c->next_data.next; grpc_closure *next = c->next_data.next;
grpc_error *error = c->error_data.error; grpc_error *error = c->error_data.error;
did_something = true; did_something = true;
#ifdef GRPC_CLOSURE_RICH_DEBUG #ifndef NDEBUG
c->scheduled = false; c->scheduled = false;
#endif #endif
c->cb(exec_ctx, c->cb_arg, error); 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, static void exec_ctx_run(grpc_exec_ctx *exec_ctx, grpc_closure *closure,
grpc_error *error) { grpc_error *error) {
#ifdef GRPC_CLOSURE_RICH_DEBUG #ifndef NDEBUG
closure->scheduled = false; 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 #endif
closure->cb(exec_ctx, closure->cb_arg, error); 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); GRPC_ERROR_UNREF(error);
} }

@ -58,7 +58,7 @@ static size_t run_closures(grpc_exec_ctx *exec_ctx, grpc_closure_list list) {
while (c != NULL) { while (c != NULL) {
grpc_closure *next = c->next_data.next; grpc_closure *next = c->next_data.next;
grpc_error *error = c->error_data.error; grpc_error *error = c->error_data.error;
#ifdef GRPC_CLOSURE_RICH_DEBUG #ifndef NDEBUG
c->scheduled = false; c->scheduled = false;
#endif #endif
c->cb(exec_ctx, c->cb_arg, error); c->cb(exec_ctx, c->cb_arg, error);

@ -138,6 +138,8 @@ void grpc_init(void) {
grpc_register_tracer("call_error", &grpc_call_error_trace); grpc_register_tracer("call_error", &grpc_call_error_trace);
#ifndef NDEBUG #ifndef NDEBUG
grpc_register_tracer("pending_tags", &grpc_trace_pending_tags); 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 #endif
grpc_security_pre_init(); grpc_security_pre_init();
grpc_iomgr_init(&exec_ctx); grpc_iomgr_init(&exec_ctx);

Loading…
Cancel
Save