From c8db73c419f61668aac6908835125b1ad0880c76 Mon Sep 17 00:00:00 2001 From: Craig Tiller Date: Tue, 30 Aug 2016 14:00:48 -0700 Subject: [PATCH] expand debug --- .../chttp2/transport/chttp2_transport.c | 88 +++++++++---------- .../ext/transport/chttp2/transport/internal.h | 2 +- .../transport/chttp2/transport/stream_lists.c | 4 +- .../ext/transport/chttp2/transport/writing.c | 6 +- src/core/lib/surface/call.c | 8 ++ 5 files changed, 58 insertions(+), 50 deletions(-) diff --git a/src/core/ext/transport/chttp2/transport/chttp2_transport.c b/src/core/ext/transport/chttp2/transport/chttp2_transport.c index f375288577e..239c2f8f2e7 100644 --- a/src/core/ext/transport/chttp2/transport/chttp2_transport.c +++ b/src/core/ext/transport/chttp2/transport/chttp2_transport.c @@ -720,6 +720,9 @@ static void maybe_start_some_streams(grpc_exec_ctx *exec_ctx, #define CLOSURE_BARRIER_FIRST_REF_BIT (1 << 16) static grpc_closure *add_closure_barrier(grpc_closure *closure) { + gpr_log(GPR_DEBUG, "add_closure_barrier: %p | %" PRIdPTR " -> %" PRIdPTR, + closure, closure->next_data.scratch, + closure->next_data.scratch + CLOSURE_BARRIER_FIRST_REF_BIT); closure->next_data.scratch += CLOSURE_BARRIER_FIRST_REF_BIT; return closure; } @@ -734,6 +737,9 @@ void grpc_chttp2_complete_closure_step(grpc_exec_ctx *exec_ctx, GRPC_ERROR_UNREF(error); return; } + gpr_log(GPR_DEBUG, "complete_closure_step: %p | %" PRIdPTR " -> %" PRIdPTR, + closure, closure->next_data.scratch, + closure->next_data.scratch - CLOSURE_BARRIER_FIRST_REF_BIT); closure->next_data.scratch -= CLOSURE_BARRIER_FIRST_REF_BIT; if (error != GRPC_ERROR_NONE) { if (closure->error == GRPC_ERROR_NONE) { @@ -859,6 +865,11 @@ static void perform_stream_op_locked(grpc_exec_ctx *exec_ctx, void *stream_op, if (on_complete == NULL) { on_complete = grpc_closure_create(do_nothing, NULL); } + + if (grpc_http_trace) { + gpr_log(GPR_DEBUG, " on_complete = %p", on_complete); + } + /* use final_data as a barrier until enqueue time; the inital counter is dropped at the end of this function */ on_complete->next_data.scratch = CLOSURE_BARRIER_FIRST_REF_BIT; @@ -1039,6 +1050,13 @@ static void perform_stream_op(grpc_exec_ctx *exec_ctx, grpc_transport *gt, GPR_TIMER_BEGIN("perform_stream_op", 0); grpc_chttp2_transport *t = (grpc_chttp2_transport *)gt; grpc_chttp2_stream *s = (grpc_chttp2_stream *)gs; + + if (grpc_http_trace) { + char *str = grpc_transport_stream_op_string(op); + gpr_log(GPR_DEBUG, "perform_stream_op: %s", str); + gpr_free(str); + } + grpc_closure_init(&op->transport_private.closure, perform_stream_op_locked, op); op->transport_private.args[0] = gt; @@ -1961,40 +1979,30 @@ grpc_chttp2_incoming_byte_stream *grpc_chttp2_incoming_byte_stream_create( */ static char *format_flowctl_context_var(const char *context, const char *var, - int64_t val, uint32_t id, - char **scope) { - char *underscore_pos; - char *buf; - char *result; + int64_t val, uint32_t id) { + char *name; if (context == NULL) { - *scope = NULL; - gpr_asprintf(&buf, "%s(%" PRId64 ")", var, val); - result = gpr_leftpad(buf, ' ', 60); - gpr_free(buf); - return result; - } - underscore_pos = strchr(context, '_'); - *scope = gpr_strdup(context); - (*scope)[underscore_pos - context] = 0; - if (id != 0) { - char *tmp = *scope; - gpr_asprintf(scope, "%s[%d]", tmp, id); - gpr_free(tmp); - } - gpr_asprintf(&buf, "%s.%s(%" PRId64 ")", underscore_pos + 1, var, val); - result = gpr_leftpad(buf, ' ', 60); - gpr_free(buf); - return result; -} - -static int samestr(char *a, char *b) { - if (a == NULL) { - return b == NULL; - } - if (b == NULL) { - return 0; + name = gpr_strdup(var); + } else if (0 == strcmp(context, "t")) { + GPR_ASSERT(id == 0); + gpr_asprintf(&name, "TRANSPORT:%s", var); + } else if (0 == strcmp(context, "s")) { + GPR_ASSERT(id != 0); + gpr_asprintf(&name, "STREAM[%d]:%s", id, var); + } else { + gpr_asprintf(&name, "BAD_CONTEXT[%s][%d]:%s", context, id, var); } - return 0 == strcmp(a, b); + char *name_fld = gpr_leftpad(name, ' ', 64); + char *value; + gpr_asprintf(&value, "%" PRId64, val); + char *value_fld = gpr_leftpad(value, ' ', 8); + char *result; + gpr_asprintf(&result, "%s %s", name_fld, value_fld); + gpr_free(name); + gpr_free(name_fld); + gpr_free(value); + gpr_free(value_fld); + return result; } void grpc_chttp2_flowctl_trace(const char *file, int line, const char *phase, @@ -2002,26 +2010,18 @@ void grpc_chttp2_flowctl_trace(const char *file, int line, const char *phase, const char *var1, const char *context2, const char *var2, int is_client, uint32_t stream_id, int64_t val1, int64_t val2) { - char *scope1; - char *scope2; char *tmp_phase; - char *tmp_scope1; - char *label1 = - format_flowctl_context_var(context1, var1, val1, stream_id, &scope1); - char *label2 = - format_flowctl_context_var(context2, var2, val2, stream_id, &scope2); + char *label1 = format_flowctl_context_var(context1, var1, val1, stream_id); + char *label2 = format_flowctl_context_var(context2, var2, val2, stream_id); char *clisvr = is_client ? "client" : "server"; char *prefix; tmp_phase = gpr_leftpad(phase, ' ', 8); - tmp_scope1 = gpr_leftpad(scope1, ' ', 11); - gpr_asprintf(&prefix, "FLOW %s: %s %s ", tmp_phase, clisvr, scope1); + gpr_asprintf(&prefix, "FLOW %s: %s ", tmp_phase, clisvr); gpr_free(tmp_phase); - gpr_free(tmp_scope1); switch (op) { case GRPC_CHTTP2_FLOWCTL_MOVE: - GPR_ASSERT(samestr(scope1, scope2)); if (val2 != 0) { gpr_log(file, line, GPR_LOG_SEVERITY_DEBUG, "%sMOVE %s <- %s giving %" PRId64, prefix, label1, label2, @@ -2046,8 +2046,6 @@ void grpc_chttp2_flowctl_trace(const char *file, int line, const char *phase, break; } - gpr_free(scope1); - gpr_free(scope2); gpr_free(label1); gpr_free(label2); gpr_free(prefix); diff --git a/src/core/ext/transport/chttp2/transport/internal.h b/src/core/ext/transport/chttp2/transport/internal.h index c599c31162b..e684c424a2b 100644 --- a/src/core/ext/transport/chttp2/transport/internal.h +++ b/src/core/ext/transport/chttp2/transport/internal.h @@ -457,7 +457,7 @@ int grpc_chttp2_list_pop_writable_stream(grpc_chttp2_transport *t, bool grpc_chttp2_list_remove_writable_stream( grpc_chttp2_transport *t, grpc_chttp2_stream *s) GRPC_MUST_USE_RESULT; -void grpc_chttp2_list_add_writing_stream(grpc_chttp2_transport *t, +bool grpc_chttp2_list_add_writing_stream(grpc_chttp2_transport *t, grpc_chttp2_stream *s); int grpc_chttp2_list_have_writing_streams(grpc_chttp2_transport *t); int grpc_chttp2_list_pop_writing_stream(grpc_chttp2_transport *t, diff --git a/src/core/ext/transport/chttp2/transport/stream_lists.c b/src/core/ext/transport/chttp2/transport/stream_lists.c index a6b4a4e1d94..7a42c2a58a9 100644 --- a/src/core/ext/transport/chttp2/transport/stream_lists.c +++ b/src/core/ext/transport/chttp2/transport/stream_lists.c @@ -134,9 +134,9 @@ bool grpc_chttp2_list_remove_writable_stream(grpc_chttp2_transport *t, return stream_list_maybe_remove(t, s, GRPC_CHTTP2_LIST_WRITABLE); } -void grpc_chttp2_list_add_writing_stream(grpc_chttp2_transport *t, +bool grpc_chttp2_list_add_writing_stream(grpc_chttp2_transport *t, grpc_chttp2_stream *s) { - GPR_ASSERT(stream_list_add(t, s, GRPC_CHTTP2_LIST_WRITING)); + return stream_list_add(t, s, GRPC_CHTTP2_LIST_WRITING); } int grpc_chttp2_list_have_writing_streams(grpc_chttp2_transport *t) { diff --git a/src/core/ext/transport/chttp2/transport/writing.c b/src/core/ext/transport/chttp2/transport/writing.c index e4cd14d6d5c..84e5f634c31 100644 --- a/src/core/ext/transport/chttp2/transport/writing.c +++ b/src/core/ext/transport/chttp2/transport/writing.c @@ -109,6 +109,8 @@ bool grpc_chttp2_begin_write(grpc_exec_ctx *exec_ctx, bool sent_initial_metadata = s->sent_initial_metadata; bool now_writing = false; + gpr_log(GPR_DEBUG, "W:%d: sim=%d ann=%d fcb_len=%d (t,s)-win=%d,%d", (int)s->id,sent_initial_metadata, (int) s->announce_window, (int)s->flow_controlled_buffer.length, (int)t->outgoing_window,(int)s->outgoing_window); + /* send initial metadata if it's available */ if (!sent_initial_metadata && s->send_initial_metadata) { grpc_chttp2_encode_header(&t->hpack_compressor, s->id, @@ -120,7 +122,7 @@ bool grpc_chttp2_begin_write(grpc_exec_ctx *exec_ctx, now_writing = true; } /* send any window updates */ - if (s->announce_window > 0 && s->sent_initial_metadata) { + if (s->announce_window > 0 && sent_initial_metadata) { uint32_t announce = s->announce_window; gpr_slice_buffer_add(&t->outbuf, grpc_chttp2_window_update_create( @@ -159,7 +161,7 @@ bool grpc_chttp2_begin_write(grpc_exec_ctx *exec_ctx, now_writing = true; if (s->flow_controlled_buffer.length > 0) { GRPC_CHTTP2_STREAM_REF(s, "chttp2_writing"); - grpc_chttp2_list_add_writing_stream(t, s); + grpc_chttp2_list_add_writable_stream(t, s); } } else if (t->outgoing_window == 0) { grpc_chttp2_list_add_stalled_by_transport(t, s); diff --git a/src/core/lib/surface/call.c b/src/core/lib/surface/call.c index ae9424256c2..8ed33bee5f0 100644 --- a/src/core/lib/surface/call.c +++ b/src/core/lib/surface/call.c @@ -1197,6 +1197,10 @@ static void receiving_stream_ready(grpc_exec_ctx *exec_ctx, void *bctlp, batch_control *bctl = bctlp; grpc_call *call = bctl->call; + char *msg = grpc_transport_stream_op_string(&bctl->op); + gpr_log(GPR_DEBUG, "receiving_stream_ready: %s", msg); + gpr_free(msg); + gpr_mu_lock(&bctl->call->mu); if (bctl->call->has_initial_md_been_received || error != GRPC_ERROR_NONE || call->receiving_stream == NULL) { @@ -1307,6 +1311,10 @@ static void finish_batch(grpc_exec_ctx *exec_ctx, void *bctlp, grpc_call *child_call; grpc_call *next_child_call; + char *msg = grpc_transport_stream_op_string(&bctl->op); + gpr_log(GPR_DEBUG, "finish_batch: %s", msg); + gpr_free(msg); + GRPC_ERROR_REF(error); gpr_mu_lock(&call->mu);