Add flow control tracing

Allow some insight into what the flow controller is doing

3 files changed, 24 insertions, 0 deletions

diff --git a/src/core/surface/init.c b/src/core/surface/init.c
index 5a119a47cc..a5d86d0071 100644
--- a/src/core/surface/init.c
+++ b/src/core/surface/init.c
@@ -59,6 +59,7 @@ void grpc_init(void) {
     grpc_register_tracer("channel", &grpc_trace_channel);
     grpc_register_tracer("surface", &grpc_surface_trace);
     grpc_register_tracer("http", &grpc_http_trace);
+    grpc_register_tracer("flowctl", &grpc_flowctl_trace);
     grpc_register_tracer("batch", &grpc_trace_batch);
     grpc_security_pre_init();
     grpc_iomgr_init();
diff --git a/src/core/transport/chttp2_transport.c b/src/core/transport/chttp2_transport.c
index 26c550c1f1..65161bd1af 100644
--- a/src/core/transport/chttp2_transport.c
+++ b/src/core/transport/chttp2_transport.c
@@ -64,6 +64,7 @@
 #define CLIENT_CONNECT_STRLEN 24
 
 int grpc_http_trace = 0;
+int grpc_flowctl_trace = 0;
 
 typedef struct transport transport;
 typedef struct stream stream;
@@ -74,6 +75,12 @@ typedef struct stream stream;
   else                    \
   stmt
 
+#define FLOWCTL_TRACE(t, obj, dir, id, delta) \
+  if (!grpc_flowctl_trace)                    \
+    ;                                         \
+  else                                        \
+  flowctl_trace(t, #dir, obj->dir##_window, id, delta)
+
 /* streams are kept in various linked lists depending on what things need to
    happen to them... this enum labels each list */
 typedef enum {
@@ -382,6 +389,12 @@ static void add_to_pollset_locked(transport *t, grpc_pollset *pollset);
 static void perform_op_locked(transport *t, stream *s, grpc_transport_op *op);
 static void add_metadata_batch(transport *t, stream *s);
 
+static void flowctl_trace(transport *t, const char *flow, gpr_int32 window,
+                          gpr_uint32 id, gpr_int32 delta) {
+  gpr_log(GPR_DEBUG, "HTTP:FLOW:%p:%d:%s: %d + %d = %d", t, id, flow, window,
+          delta, window + delta);
+}
+
 /*
  * CONSTRUCTION/DESTRUCTION/REFCOUNTING
  */
@@ -894,6 +907,8 @@ static int prepare_write(transport *t) {
     window_delta = grpc_chttp2_preencode(
         s->outgoing_sopb->ops, &s->outgoing_sopb->nops,
         GPR_MIN(t->outgoing_window, s->outgoing_window), &s->writing_sopb);
+    FLOWCTL_TRACE(t, t, outgoing, 0, -window_delta);
+    FLOWCTL_TRACE(t, s, outgoing, s->id, -window_delta);
     t->outgoing_window -= window_delta;
     s->outgoing_window -= window_delta;
 
@@ -922,6 +937,7 @@ static int prepare_write(transport *t) {
     if (!s->read_closed && window_delta) {
       gpr_slice_buffer_add(
           &t->outbuf, grpc_chttp2_window_update_create(s->id, window_delta));
+      FLOWCTL_TRACE(t, s, incoming, s->id, window_delta);
       s->incoming_window += window_delta;
     }
   }
@@ -931,6 +947,7 @@ static int prepare_write(transport *t) {
     window_delta = t->connection_window_target - t->incoming_window;
     gpr_slice_buffer_add(&t->outbuf,
                          grpc_chttp2_window_update_create(0, window_delta));
+    FLOWCTL_TRACE(t, t, incoming, 0, window_delta);
     t->incoming_window += window_delta;
   }
 
@@ -1253,6 +1270,8 @@ static grpc_chttp2_parse_error update_incoming_window(transport *t, stream *s) {
     return GRPC_CHTTP2_CONNECTION_ERROR;
   }
 
+  FLOWCTL_TRACE(t, t, incoming, 0, -t->incoming_frame_size);
+  FLOWCTL_TRACE(t, s, incoming, s->id, -t->incoming_frame_size);
   t->incoming_window -= t->incoming_frame_size;
   s->incoming_window -= t->incoming_frame_size;
 
@@ -1599,6 +1618,7 @@ static int parse_frame_slice(transport *t, gpr_slice slice, int is_last) {
         for (i = 0; i < t->stream_map.count; i++) {
           stream *s = (stream *)(t->stream_map.values[i]);
           int was_window_empty = s->outgoing_window <= 0;
+          FLOWCTL_TRACE(t, s, outgoing, s->id, st.initial_window_update);
           s->outgoing_window += st.initial_window_update;
           if (was_window_empty && s->outgoing_window > 0 && s->outgoing_sopb &&
               s->outgoing_sopb->nops > 0) {
@@ -1617,6 +1637,7 @@ static int parse_frame_slice(transport *t, gpr_slice slice, int is_last) {
                                       GRPC_CHTTP2_FLOW_CONTROL_ERROR),
                             GRPC_CHTTP2_FLOW_CONTROL_ERROR, NULL, 1);
             } else {
+              FLOWCTL_TRACE(t, s, outgoing, s->id, st.window_update);
               s->outgoing_window += st.window_update;
               /* if this window update makes outgoing ops writable again,
                  flag that */
@@ -1631,6 +1652,7 @@ static int parse_frame_slice(transport *t, gpr_slice slice, int is_last) {
           if (!is_window_update_legal(st.window_update, t->outgoing_window)) {
             drop_connection(t);
           } else {
+            FLOWCTL_TRACE(t, t, outgoing, 0, st.window_update);
             t->outgoing_window += st.window_update;
           }
         }
diff --git a/src/core/transport/chttp2_transport.h b/src/core/transport/chttp2_transport.h
index a7f1b9a864..fad714fabf 100644
--- a/src/core/transport/chttp2_transport.h
+++ b/src/core/transport/chttp2_transport.h
@@ -38,6 +38,7 @@
 #include "src/core/transport/transport.h"
 
 extern int grpc_http_trace;
+extern int grpc_flowctl_trace;
 
 void grpc_create_chttp2_transport(grpc_transport_setup_callback setup,
                                   void *arg,