Annotate more things

src/core/ext/census/grpc_filter.c

@@ -45,6 +45,7 @@
 #include "src/core/ext/census/census_interface.h"
 #include "src/core/ext/census/census_rpc_stats.h"
 #include "src/core/lib/channel/channel_stack.h"
+#include "src/core/lib/profiling/timers.h"
 #include "src/core/lib/transport/static_metadata.h"
 
 typedef struct call_data {
@@ -92,6 +93,7 @@ static void client_start_transport_op(grpc_exec_ctx *exec_ctx,
 
 static void server_on_done_recv(grpc_exec_ctx *exec_ctx, void *ptr,
                                 grpc_error *error) {
+  GPR_TIMER_BEGIN("census-server:server_on_done_recv", 0);
   grpc_call_element *elem = ptr;
   call_data *calld = elem->call_data;
   channel_data *chand = elem->channel_data;
@@ -99,6 +101,7 @@ static void server_on_done_recv(grpc_exec_ctx *exec_ctx, void *ptr,
     extract_and_annotate_method_tag(calld->recv_initial_metadata, calld, chand);
   }
   calld->on_done_recv->cb(exec_ctx, calld->on_done_recv->cb_arg, error);
+  GPR_TIMER_END("census-server:server_on_done_recv", 0);
 }
 
 static void server_mutate_op(grpc_call_element *elem,

src/core/ext/client_config/client_channel.c

@@ -367,6 +367,8 @@ static int cc_pick_subchannel(grpc_exec_ctx *exec_ctx, void *elemp,
                               uint32_t initial_metadata_flags,
                               grpc_connected_subchannel **connected_subchannel,
                               grpc_closure *on_ready) {
+  GPR_TIMER_BEGIN("cc_pick_subchannel", 0);
+
   grpc_call_element *elem = elemp;
   channel_data *chand = elem->channel_data;
   call_data *calld = elem->call_data;
@@ -391,6 +393,7 @@ static int cc_pick_subchannel(grpc_exec_ctx *exec_ctx, void *elemp,
       }
     }
     gpr_mu_unlock(&chand->mu_config);
+    GPR_TIMER_END("cc_pick_subchannel", 0);
     return 1;
   }
   if (chand->lb_policy != NULL) {
@@ -402,6 +405,7 @@ static int cc_pick_subchannel(grpc_exec_ctx *exec_ctx, void *elemp,
                             initial_metadata, initial_metadata_flags,
                             connected_subchannel, on_ready);
     GRPC_LB_POLICY_UNREF(exec_ctx, lb_policy, "cc_pick_subchannel");
+    GPR_TIMER_END("cc_pick_subchannel", 0);
     return r;
   }
   if (chand->resolver != NULL && !chand->started_resolving) {
@@ -426,6 +430,8 @@ static int cc_pick_subchannel(grpc_exec_ctx *exec_ctx, void *elemp,
                         NULL);
   }
   gpr_mu_unlock(&chand->mu_config);
+
+  GPR_TIMER_END("cc_pick_subchannel", 0);
   return 0;
 }
 

src/core/ext/client_config/subchannel.c

@@ -690,9 +690,11 @@ char *grpc_subchannel_call_get_peer(grpc_exec_ctx *exec_ctx,
 void grpc_subchannel_call_process_op(grpc_exec_ctx *exec_ctx,
                                      grpc_subchannel_call *call,
                                      grpc_transport_stream_op *op) {
+  GPR_TIMER_BEGIN("grpc_subchannel_call_process_op", 0);
   grpc_call_stack *call_stack = SUBCHANNEL_CALL_TO_CALL_STACK(call);
   grpc_call_element *top_elem = grpc_call_stack_element(call_stack, 0);
   top_elem->filter->start_transport_stream_op(exec_ctx, top_elem, op);
+  GPR_TIMER_END("grpc_subchannel_call_process_op", 0);
 }
 
 grpc_connected_subchannel *grpc_subchannel_get_connected_subchannel(

src/core/ext/transport/chttp2/transport/chttp2_transport.c

@@ -642,6 +642,8 @@ static void finish_global_actions(grpc_exec_ctx *exec_ctx,
   grpc_chttp2_executor_action_header *hdr;
   grpc_chttp2_executor_action_header *next;
 
+  GPR_TIMER_BEGIN("finish_global_actions", 0);
+
   for (;;) {
     if (!t->executor.writing_active && !t->closed &&
         grpc_chttp2_unlocking_check_writes(exec_ctx, &t->global, &t->writing)) {
@@ -659,7 +661,9 @@ static void finish_global_actions(grpc_exec_ctx *exec_ctx,
           NULL;
       gpr_mu_unlock(&t->executor.mu);
       while (hdr != NULL) {
+        GPR_TIMER_BEGIN("chttp2:locked_action", 0);
         hdr->action(exec_ctx, t, hdr->stream, hdr->arg);
+        GPR_TIMER_END("chttp2:locked_action", 0);
         next = hdr->next;
         gpr_free(hdr);
         UNREF_TRANSPORT(exec_ctx, t, "pending_action");
@@ -672,6 +676,8 @@ static void finish_global_actions(grpc_exec_ctx *exec_ctx,
     gpr_mu_unlock(&t->executor.mu);
     break;
   }
+
+  GPR_TIMER_END("finish_global_actions", 0);
 }
 
 void grpc_chttp2_run_with_global_lock(grpc_exec_ctx *exec_ctx,
@@ -681,6 +687,8 @@ void grpc_chttp2_run_with_global_lock(grpc_exec_ctx *exec_ctx,
                                       void *arg, size_t sizeof_arg) {
   grpc_chttp2_executor_action_header *hdr;
 
+  GPR_TIMER_BEGIN("grpc_chttp2_run_with_global_lock", 0);
+
   REF_TRANSPORT(t, "run_global");
   gpr_mu_lock(&t->executor.mu);
 
@@ -689,7 +697,9 @@ void grpc_chttp2_run_with_global_lock(grpc_exec_ctx *exec_ctx,
       t->executor.global_active = 1;
       gpr_mu_unlock(&t->executor.mu);
 
+      GPR_TIMER_BEGIN("chttp2:locked_action", 0);
       action(exec_ctx, t, optional_stream, arg);
+      GPR_TIMER_END("chttp2:locked_action", 0);
 
       finish_global_actions(exec_ctx, t);
     } else {
@@ -726,6 +736,8 @@ void grpc_chttp2_run_with_global_lock(grpc_exec_ctx *exec_ctx,
   }
 
   UNREF_TRANSPORT(exec_ctx, t, "run_global");
+
+  GPR_TIMER_END("grpc_chttp2_run_with_global_lock", 0);
 }
 
 /*******************************************************************************