From edc2a6b988c8019b2e5debaaa8d4716c62fbe3d9 Mon Sep 17 00:00:00 2001 From: Yash Tibrewal Date: Fri, 10 Apr 2020 12:16:37 -0700 Subject: [PATCH 1/3] Add option for logging keepalive pings --- doc/environment_variables.md | 1 + .../transport/chttp2/transport/chttp2_transport.cc | 8 ++++++-- .../transport/chttp2/transport/chttp2_transport.h | 1 + src/core/ext/transport/chttp2/transport/writing.cc | 13 +++++++++---- 4 files changed, 17 insertions(+), 6 deletions(-) diff --git a/doc/environment_variables.md b/doc/environment_variables.md index ab45f937bff..fe3a81657eb 100644 --- a/doc/environment_variables.md +++ b/doc/environment_variables.md @@ -66,6 +66,7 @@ some configuration as environment variables that can be set. - http2_stream_state - traces all http2 stream state mutations. - http1 - traces HTTP/1.x operations performed by gRPC - inproc - traces the in-process transport + - keepalive - traces keepalive pings - flowctl - traces http2 flow control - lrs_lb - traces lrs LB policy - op_failure - traces error information when failure is pushed onto a diff --git a/src/core/ext/transport/chttp2/transport/chttp2_transport.cc b/src/core/ext/transport/chttp2/transport/chttp2_transport.cc index 3f27466611f..790a66c1260 100644 --- a/src/core/ext/transport/chttp2/transport/chttp2_transport.cc +++ b/src/core/ext/transport/chttp2/transport/chttp2_transport.cc @@ -99,6 +99,7 @@ static int g_default_max_ping_strikes = DEFAULT_MAX_PING_STRIKES; #define MAX_CLIENT_STREAM_ID 0x7fffffffu grpc_core::TraceFlag grpc_http_trace(false, "http"); +grpc_core::TraceFlag grpc_keepalive_trace(false, "keepalive"); grpc_core::DebugOnlyTraceFlag grpc_trace_chttp2_refcount(false, "chttp2_refcount"); @@ -2771,6 +2772,7 @@ static void init_keepalive_ping(void* arg, grpc_error* error) { static void init_keepalive_ping_locked(void* arg, grpc_error* error) { grpc_chttp2_transport* t = static_cast(arg); + GPR_ASSERT(t->keepalive_state == GRPC_CHTTP2_KEEPALIVE_STATE_WAITING); if (t->destroying || t->closed_with_error != GRPC_ERROR_NONE) { t->keepalive_state = GRPC_CHTTP2_KEEPALIVE_STATE_DYING; @@ -2817,7 +2819,8 @@ static void start_keepalive_ping_locked(void* arg, grpc_error* error) { if (t->channelz_socket != nullptr) { t->channelz_socket->RecordKeepaliveSent(); } - if (GRPC_TRACE_FLAG_ENABLED(grpc_http_trace)) { + if (GRPC_TRACE_FLAG_ENABLED(grpc_http_trace) || + GRPC_TRACE_FLAG_ENABLED(grpc_keepalive_trace)) { gpr_log(GPR_INFO, "%s: Start keepalive ping", t->peer_string); } GRPC_CHTTP2_REF_TRANSPORT(t, "keepalive watchdog"); @@ -2840,7 +2843,8 @@ static void finish_keepalive_ping_locked(void* arg, grpc_error* error) { grpc_chttp2_transport* t = static_cast(arg); if (t->keepalive_state == GRPC_CHTTP2_KEEPALIVE_STATE_PINGING) { if (error == GRPC_ERROR_NONE) { - if (GRPC_TRACE_FLAG_ENABLED(grpc_http_trace)) { + if (GRPC_TRACE_FLAG_ENABLED(grpc_http_trace) || + GRPC_TRACE_FLAG_ENABLED(grpc_keepalive_trace)) { gpr_log(GPR_INFO, "%s: Finish keepalive ping", t->peer_string); } if (!t->keepalive_ping_started) { diff --git a/src/core/ext/transport/chttp2/transport/chttp2_transport.h b/src/core/ext/transport/chttp2/transport/chttp2_transport.h index 39574f93ec7..b04630bbe2b 100644 --- a/src/core/ext/transport/chttp2/transport/chttp2_transport.h +++ b/src/core/ext/transport/chttp2/transport/chttp2_transport.h @@ -27,6 +27,7 @@ #include "src/core/lib/transport/transport.h" extern grpc_core::TraceFlag grpc_http_trace; +extern grpc_core::TraceFlag grpc_keepalive_trace; extern grpc_core::TraceFlag grpc_trace_http2_stream_state; extern grpc_core::DebugOnlyTraceFlag grpc_trace_chttp2_refcount; extern grpc_core::DebugOnlyTraceFlag grpc_trace_chttp2_hpack_parser; diff --git a/src/core/ext/transport/chttp2/transport/writing.cc b/src/core/ext/transport/chttp2/transport/writing.cc index c7613afcf6f..98d7f9f3edc 100644 --- a/src/core/ext/transport/chttp2/transport/writing.cc +++ b/src/core/ext/transport/chttp2/transport/writing.cc @@ -18,6 +18,7 @@ #include +#include "src/core/ext/transport/chttp2/transport/chttp2_transport.h" #include "src/core/ext/transport/chttp2/transport/context_list.h" #include "src/core/ext/transport/chttp2/transport/internal.h" @@ -54,7 +55,8 @@ static void maybe_initiate_ping(grpc_chttp2_transport* t) { if (!grpc_closure_list_empty(pq->lists[GRPC_CHTTP2_PCL_INFLIGHT])) { /* ping already in-flight: wait */ if (GRPC_TRACE_FLAG_ENABLED(grpc_http_trace) || - GRPC_TRACE_FLAG_ENABLED(grpc_bdp_estimator_trace)) { + GRPC_TRACE_FLAG_ENABLED(grpc_bdp_estimator_trace) || + GRPC_TRACE_FLAG_ENABLED(grpc_keepalive_trace)) { gpr_log(GPR_INFO, "%s: Ping delayed [%p]: already pinging", t->is_client ? "CLIENT" : "SERVER", t->peer_string); } @@ -64,7 +66,8 @@ static void maybe_initiate_ping(grpc_chttp2_transport* t) { t->ping_policy.max_pings_without_data != 0) { /* need to receive something of substance before sending a ping again */ if (GRPC_TRACE_FLAG_ENABLED(grpc_http_trace) || - GRPC_TRACE_FLAG_ENABLED(grpc_bdp_estimator_trace)) { + GRPC_TRACE_FLAG_ENABLED(grpc_bdp_estimator_trace) || + GRPC_TRACE_FLAG_ENABLED(grpc_keepalive_trace)) { gpr_log(GPR_INFO, "%s: Ping delayed [%p]: too many recent pings: %d/%d", t->is_client ? "CLIENT" : "SERVER", t->peer_string, t->ping_state.pings_before_data_required, @@ -85,7 +88,8 @@ static void maybe_initiate_ping(grpc_chttp2_transport* t) { if (next_allowed_ping > now) { /* not enough elapsed time between successive pings */ if (GRPC_TRACE_FLAG_ENABLED(grpc_http_trace) || - GRPC_TRACE_FLAG_ENABLED(grpc_bdp_estimator_trace)) { + GRPC_TRACE_FLAG_ENABLED(grpc_bdp_estimator_trace) || + GRPC_TRACE_FLAG_ENABLED(grpc_keepalive_trace)) { gpr_log(GPR_INFO, "%s: Ping delayed [%p]: not enough time elapsed since last ping. " " Last ping %f: Next ping %f: Now %f", @@ -116,7 +120,8 @@ static void maybe_initiate_ping(grpc_chttp2_transport* t) { GRPC_STATS_INC_HTTP2_PINGS_SENT(); t->ping_state.last_ping_sent_time = now; if (GRPC_TRACE_FLAG_ENABLED(grpc_http_trace) || - GRPC_TRACE_FLAG_ENABLED(grpc_bdp_estimator_trace)) { + GRPC_TRACE_FLAG_ENABLED(grpc_bdp_estimator_trace) || + GRPC_TRACE_FLAG_ENABLED(grpc_keepalive_trace)) { gpr_log(GPR_INFO, "%s: Ping sent [%s]: %d/%d", t->is_client ? "CLIENT" : "SERVER", t->peer_string, t->ping_state.pings_before_data_required, From c90dc0e0987cbce29db4b9ac39ecec75ec78dd23 Mon Sep 17 00:00:00 2001 From: Yash Tibrewal Date: Fri, 10 Apr 2020 12:18:39 -0700 Subject: [PATCH 2/3] Remove blank line --- src/core/ext/transport/chttp2/transport/chttp2_transport.cc | 1 - 1 file changed, 1 deletion(-) diff --git a/src/core/ext/transport/chttp2/transport/chttp2_transport.cc b/src/core/ext/transport/chttp2/transport/chttp2_transport.cc index 790a66c1260..f1724764da3 100644 --- a/src/core/ext/transport/chttp2/transport/chttp2_transport.cc +++ b/src/core/ext/transport/chttp2/transport/chttp2_transport.cc @@ -2772,7 +2772,6 @@ static void init_keepalive_ping(void* arg, grpc_error* error) { static void init_keepalive_ping_locked(void* arg, grpc_error* error) { grpc_chttp2_transport* t = static_cast(arg); - GPR_ASSERT(t->keepalive_state == GRPC_CHTTP2_KEEPALIVE_STATE_WAITING); if (t->destroying || t->closed_with_error != GRPC_ERROR_NONE) { t->keepalive_state = GRPC_CHTTP2_KEEPALIVE_STATE_DYING; From 2d0ed47223e252a8ecf2d1fca9a0fdee8ac5711b Mon Sep 17 00:00:00 2001 From: Yash Tibrewal Date: Fri, 10 Apr 2020 12:28:25 -0700 Subject: [PATCH 3/3] Reviewer comments --- doc/environment_variables.md | 2 +- src/core/ext/transport/chttp2/transport/chttp2_transport.cc | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/doc/environment_variables.md b/doc/environment_variables.md index fe3a81657eb..ec1b4f86717 100644 --- a/doc/environment_variables.md +++ b/doc/environment_variables.md @@ -66,7 +66,7 @@ some configuration as environment variables that can be set. - http2_stream_state - traces all http2 stream state mutations. - http1 - traces HTTP/1.x operations performed by gRPC - inproc - traces the in-process transport - - keepalive - traces keepalive pings + - http_keepalive - traces gRPC keepalive pings - flowctl - traces http2 flow control - lrs_lb - traces lrs LB policy - op_failure - traces error information when failure is pushed onto a diff --git a/src/core/ext/transport/chttp2/transport/chttp2_transport.cc b/src/core/ext/transport/chttp2/transport/chttp2_transport.cc index f1724764da3..cc03a406903 100644 --- a/src/core/ext/transport/chttp2/transport/chttp2_transport.cc +++ b/src/core/ext/transport/chttp2/transport/chttp2_transport.cc @@ -99,7 +99,7 @@ static int g_default_max_ping_strikes = DEFAULT_MAX_PING_STRIKES; #define MAX_CLIENT_STREAM_ID 0x7fffffffu grpc_core::TraceFlag grpc_http_trace(false, "http"); -grpc_core::TraceFlag grpc_keepalive_trace(false, "keepalive"); +grpc_core::TraceFlag grpc_keepalive_trace(false, "http_keepalive"); grpc_core::DebugOnlyTraceFlag grpc_trace_chttp2_refcount(false, "chttp2_refcount");