From c3df7b4924227d60589e5b1fc3d1f809815e88c2 Mon Sep 17 00:00:00 2001
From: Craig Tiller <ctiller@google.com>
Date: Mon, 18 Jul 2016 15:51:26 -0700
Subject: [PATCH] Get traces around everything
---
src/core/lib/iomgr/combiner.c | 53 ++++++++++++++++++++--------------
src/core/lib/iomgr/combiner.h | 2 ++
src/core/lib/iomgr/error.c | 2 +-
src/core/lib/iomgr/tcp_posix.c | 24 ++++++++++-----
src/core/lib/surface/init.c | 2 ++
5 files changed, 52 insertions(+), 31 deletions(-)
diff --git a/src/core/lib/iomgr/combiner.c b/src/core/lib/iomgr/combiner.c
index c3c32cb8a3..eb476c0572 100644
--- a/src/core/lib/iomgr/combiner.c
+++ b/src/core/lib/iomgr/combiner.c
@@ -43,10 +43,12 @@
int grpc_combiner_trace = 0;
-#define COMBINER_TRACE(fn) \
- if (grpc_combiner_trace) { \
- fn \
- }
+#define GRPC_COMBINER_TRACE(fn) \
+ do { \
+ if (grpc_combiner_trace) { \
+ fn; \
+ } \
+ } while (0)
struct grpc_combiner {
grpc_workqueue *optional_workqueue;
@@ -67,12 +69,12 @@ grpc_combiner *grpc_combiner_create(grpc_workqueue *optional_workqueue) {
gpr_mpscq_init(&lock->queue);
lock->take_async_break_before_final_list = false;
grpc_closure_list_init(&lock->final_list);
- gpr_log(GPR_DEBUG, "C:%p create", lock);
+ GRPC_COMBINER_TRACE(gpr_log(GPR_DEBUG, "C:%p create", lock));
return lock;
}
static void really_destroy(grpc_exec_ctx *exec_ctx, grpc_combiner *lock) {
- gpr_log(GPR_DEBUG, "C:%p really_destroy", lock);
+ GRPC_COMBINER_TRACE(gpr_log(GPR_DEBUG, "C:%p really_destroy", lock));
GPR_ASSERT(gpr_atm_no_barrier_load(&lock->state) == 0);
gpr_mpscq_destroy(&lock->queue);
GRPC_WORKQUEUE_UNREF(exec_ctx, lock->optional_workqueue, "combiner");
@@ -81,8 +83,8 @@ static void really_destroy(grpc_exec_ctx *exec_ctx, grpc_combiner *lock) {
void grpc_combiner_destroy(grpc_exec_ctx *exec_ctx, grpc_combiner *lock) {
gpr_atm old_state = gpr_atm_full_fetch_add(&lock->state, -1);
- gpr_log(GPR_DEBUG, "C:%p really_destroy old_state=%" PRIdPTR, lock,
- old_state);
+ GRPC_COMBINER_TRACE(gpr_log(
+ GPR_DEBUG, "C:%p really_destroy old_state=%" PRIdPTR, lock, old_state));
if (old_state == 1) {
really_destroy(exec_ctx, lock);
}
@@ -95,7 +97,8 @@ static void continue_finishing_mainline(grpc_exec_ctx *exec_ctx, void *arg,
grpc_error *error) {
GPR_TIMER_BEGIN("combiner.continue_executing_mainline", 0);
grpc_combiner *lock = arg;
- gpr_log(GPR_DEBUG, "C:%p continue_finishing_mainline", lock);
+ GRPC_COMBINER_TRACE(
+ gpr_log(GPR_DEBUG, "C:%p continue_finishing_mainline", lock));
GPR_ASSERT(exec_ctx->active_combiner == NULL);
exec_ctx->active_combiner = lock;
if (maybe_finish_one(exec_ctx, lock)) finish(exec_ctx, lock);
@@ -112,7 +115,8 @@ static void execute_final(grpc_exec_ctx *exec_ctx, grpc_combiner *lock) {
lock->take_async_break_before_final_list = false;
int loops = 0;
while (c != NULL) {
- gpr_log(GPR_DEBUG, "C:%p execute_final[%d] c=%p", lock, loops, c);
+ GRPC_COMBINER_TRACE(
+ 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;
c->cb(exec_ctx, c->cb_arg, error);
@@ -127,7 +131,8 @@ static void continue_executing_final(grpc_exec_ctx *exec_ctx, void *arg,
grpc_error *error) {
GPR_TIMER_BEGIN("combiner.continue_executing_final", 0);
grpc_combiner *lock = arg;
- gpr_log(GPR_DEBUG, "C:%p continue_executing_final", lock);
+ GRPC_COMBINER_TRACE(
+ gpr_log(GPR_DEBUG, "C:%p continue_executing_final", lock));
GPR_ASSERT(exec_ctx->active_combiner == NULL);
exec_ctx->active_combiner = lock;
// quick peek to see if new things have turned up on the queue: if so, go back
@@ -146,9 +151,10 @@ static void continue_executing_final(grpc_exec_ctx *exec_ctx, void *arg,
static bool start_execute_final(grpc_exec_ctx *exec_ctx, grpc_combiner *lock) {
GPR_TIMER_BEGIN("combiner.start_execute_final", 0);
GPR_ASSERT(exec_ctx->active_combiner == lock);
- gpr_log(GPR_DEBUG,
- "C:%p start_execute_final take_async_break_before_final_list=%d",
- lock, lock->take_async_break_before_final_list);
+ GRPC_COMBINER_TRACE(
+ gpr_log(GPR_DEBUG,
+ "C:%p start_execute_final take_async_break_before_final_list=%d",
+ lock, lock->take_async_break_before_final_list));
if (lock->take_async_break_before_final_list) {
grpc_closure_init(&lock->continue_finishing, continue_executing_final,
lock);
@@ -166,7 +172,8 @@ static bool start_execute_final(grpc_exec_ctx *exec_ctx, grpc_combiner *lock) {
static bool maybe_finish_one(grpc_exec_ctx *exec_ctx, grpc_combiner *lock) {
GPR_TIMER_BEGIN("combiner.maybe_finish_one", 0);
gpr_mpscq_node *n = gpr_mpscq_pop(&lock->queue);
- gpr_log(GPR_DEBUG, "C:%p maybe_finish_one n=%p", lock, n);
+ GRPC_COMBINER_TRACE(
+ gpr_log(GPR_DEBUG, "C:%p maybe_finish_one n=%p", lock, n));
GPR_ASSERT(exec_ctx->active_combiner == lock);
if (n == NULL) {
// queue is in an inconsistant state: use this as a cue that we should
@@ -193,9 +200,9 @@ static void finish(grpc_exec_ctx *exec_ctx, grpc_combiner *lock) {
do {
executor = maybe_finish_one;
gpr_atm old_state = gpr_atm_full_fetch_add(&lock->state, -2);
- gpr_log(GPR_DEBUG, "C:%p finish[%d] old_state=%" PRIdPTR " cl=[%p,%p]",
- lock, loops, old_state, lock->final_list.head,
- lock->final_list.tail);
+ GRPC_COMBINER_TRACE(gpr_log(
+ GPR_DEBUG, "C:%p finish[%d] old_state=%" PRIdPTR " cl=[%p,%p]", lock,
+ loops, old_state, lock->final_list.head, lock->final_list.tail));
switch (old_state) {
case 5: // we're down to one queued item: if it's the final list we
case 4: // should do that
@@ -223,7 +230,8 @@ static void finish(grpc_exec_ctx *exec_ctx, grpc_combiner *lock) {
void grpc_combiner_execute(grpc_exec_ctx *exec_ctx, grpc_combiner *lock,
grpc_closure *cl, grpc_error *error) {
- gpr_log(GPR_DEBUG, "C:%p grpc_combiner_execute c=%p", lock, cl);
+ GRPC_COMBINER_TRACE(
+ gpr_log(GPR_DEBUG, "C:%p grpc_combiner_execute c=%p", lock, cl));
GPR_TIMER_BEGIN("combiner.execute", 0);
gpr_atm last = gpr_atm_full_fetch_add(&lock->state, 2);
GPR_ASSERT(last & 1); // ensure lock has not been destroyed
@@ -252,9 +260,10 @@ static void enqueue_finally(grpc_exec_ctx *exec_ctx, void *closure,
void grpc_combiner_execute_finally(grpc_exec_ctx *exec_ctx, grpc_combiner *lock,
grpc_closure *closure, grpc_error *error,
bool force_async_break) {
- gpr_log(GPR_DEBUG,
- "C:%p grpc_combiner_execute_finally c=%p force_async_break=%d; ac=%p",
- lock, closure, force_async_break, exec_ctx->active_combiner);
+ GRPC_COMBINER_TRACE(gpr_log(
+ GPR_DEBUG,
+ "C:%p grpc_combiner_execute_finally c=%p force_async_break=%d; ac=%p",
+ lock, closure, force_async_break, exec_ctx->active_combiner));
GPR_TIMER_BEGIN("combiner.execute_finally", 0);
if (exec_ctx->active_combiner != lock) {
GPR_TIMER_MARK("slowpath", 0);
diff --git a/src/core/lib/iomgr/combiner.h b/src/core/lib/iomgr/combiner.h
index 5b94d5bd99..3eb9f34638 100644
--- a/src/core/lib/iomgr/combiner.h
+++ b/src/core/lib/iomgr/combiner.h
@@ -64,4 +64,6 @@ void grpc_combiner_execute_finally(grpc_exec_ctx *exec_ctx, grpc_combiner *lock,
bool hint_async_break);
void grpc_combiner_force_async_finally(grpc_combiner *lock);
+extern int grpc_combiner_trace;
+
#endif /* GRPC_CORE_LIB_IOMGR_COMBINER_H */
diff --git a/src/core/lib/iomgr/error.c b/src/core/lib/iomgr/error.c
index 149c55663c..e366961936 100644
--- a/src/core/lib/iomgr/error.c
+++ b/src/core/lib/iomgr/error.c
@@ -332,7 +332,7 @@ grpc_error *grpc_error_add_child(grpc_error *src, grpc_error *child) {
return new;
}
-static const char *no_error_string = "null";
+static const char *no_error_string = "\"No Error\"";
static const char *oom_error_string = "\"Out of memory\"";
static const char *cancelled_error_string = "\"Cancelled\"";
diff --git a/src/core/lib/iomgr/tcp_posix.c b/src/core/lib/iomgr/tcp_posix.c
index bf6e9b16b3..fa4b72acbb 100644
--- a/src/core/lib/iomgr/tcp_posix.c
+++ b/src/core/lib/iomgr/tcp_posix.c
@@ -379,14 +379,18 @@ static void tcp_handle_write(grpc_exec_ctx *exec_ctx, void *arg /* grpc_tcp */,
}
if (!tcp_flush(tcp, &error)) {
- gpr_log(GPR_DEBUG, "write: delayed");
+ if (grpc_tcp_trace) {
+ gpr_log(GPR_DEBUG, "write: delayed");
+ }
grpc_fd_notify_on_write(exec_ctx, tcp->em_fd, &tcp->write_closure);
} else {
cb = tcp->write_cb;
tcp->write_cb = NULL;
- const char *str = grpc_error_string(error);
- gpr_log(GPR_DEBUG, "write: %s", str);
- grpc_error_free_string(str);
+ if (grpc_tcp_trace) {
+ const char *str = grpc_error_string(error);
+ gpr_log(GPR_DEBUG, "write: %s", str);
+ grpc_error_free_string(str);
+ }
GPR_TIMER_BEGIN("tcp_handle_write.cb", 0);
cb->cb(exec_ctx, cb->cb_arg, error);
@@ -430,12 +434,16 @@ static void tcp_write(grpc_exec_ctx *exec_ctx, grpc_endpoint *ep,
if (!tcp_flush(tcp, &error)) {
TCP_REF(tcp, "write");
tcp->write_cb = cb;
- gpr_log(GPR_DEBUG, "write: delayed");
+ if (grpc_tcp_trace) {
+ gpr_log(GPR_DEBUG, "write: delayed");
+ }
grpc_fd_notify_on_write(exec_ctx, tcp->em_fd, &tcp->write_closure);
} else {
- const char *str = grpc_error_string(error);
- gpr_log(GPR_DEBUG, "write: %s", str);
- grpc_error_free_string(str);
+ if (grpc_tcp_trace) {
+ const char *str = grpc_error_string(error);
+ gpr_log(GPR_DEBUG, "write: %s", str);
+ grpc_error_free_string(str);
+ }
grpc_exec_ctx_sched(exec_ctx, cb, error, NULL);
}
diff --git a/src/core/lib/surface/init.c b/src/core/lib/surface/init.c
index 5397913a21..edda0c85fa 100644
--- a/src/core/lib/surface/init.c
+++ b/src/core/lib/surface/init.c
@@ -47,6 +47,7 @@
#include "src/core/lib/channel/http_server_filter.h"
#include "src/core/lib/debug/trace.h"
#include "src/core/lib/http/parser.h"
+#include "src/core/lib/iomgr/combiner.h"
#include "src/core/lib/iomgr/executor.h"
#include "src/core/lib/iomgr/iomgr.h"
#include "src/core/lib/profiling/timers.h"
@@ -165,6 +166,7 @@ void grpc_init(void) {
grpc_register_tracer("http1", &grpc_http1_trace);
grpc_register_tracer("compression", &grpc_compression_trace);
grpc_register_tracer("queue_pluck", &grpc_cq_pluck_trace);
+ grpc_register_tracer("combiner", &grpc_combiner_trace);
// Default pluck trace to 1
grpc_cq_pluck_trace = 1;
grpc_register_tracer("queue_timeout", &grpc_cq_event_timeout_trace);
--
GitLab