more markers

src/core/channel/client_channel.c

@@ -36,16 +36,18 @@
 #include <stdio.h>
 #include <string.h>
 
+#include <grpc/support/alloc.h>
+#include <grpc/support/log.h>
+#include <grpc/support/sync.h>
+#include <grpc/support/useful.h>
+
 #include "src/core/channel/channel_args.h"
 #include "src/core/channel/connected_channel.h"
-#include "src/core/surface/channel.h"
 #include "src/core/iomgr/iomgr.h"
+#include "src/core/profiling/timers.h"
 #include "src/core/support/string.h"
+#include "src/core/surface/channel.h"
 #include "src/core/transport/connectivity_state.h"
-#include <grpc/support/alloc.h>
-#include <grpc/support/log.h>
-#include <grpc/support/sync.h>
-#include <grpc/support/useful.h>
 
 /* Client channel implementation */
 
@@ -235,6 +237,8 @@ static void picked_target(grpc_exec_ctx *exec_ctx, void *arg,
   call_data *calld = arg;
   grpc_pollset *pollset;
 
+  GRPC_TIMER_BEGIN(GRPC_PTAG_CHANNEL_PICKED_TARGET, 0);
+
   if (calld->picked_channel == NULL) {
     /* treat this like a cancellation */
     calld->waiting_op.cancel_with_status = GRPC_STATUS_UNAVAILABLE;
@@ -255,6 +259,8 @@ static void picked_target(grpc_exec_ctx *exec_ctx, void *arg,
                                   &calld->async_setup_task);
     }
   }
+
+  GRPC_TIMER_END(GRPC_PTAG_CHANNEL_PICKED_TARGET, 0);
 }
 
 static grpc_closure *merge_into_waiting_op(grpc_call_element *elem,

src/core/iomgr/exec_ctx.c

@@ -45,8 +45,10 @@ int grpc_exec_ctx_flush(grpc_exec_ctx *exec_ctx) {
     exec_ctx->closure_list.head = exec_ctx->closure_list.tail = NULL;
     while (c != NULL) {
       grpc_closure *next = c->next;
-      did_something = 1;
+      did_something++;
+      GRPC_TIMER_BEGIN(GRPC_PTAG_EXEC_CTX_STEP, 0);
       c->cb(exec_ctx, c->cb_arg, c->success);
+      GRPC_TIMER_END(GRPC_PTAG_EXEC_CTX_STEP, 0);
       c = next;
     }
   }

src/core/profiling/timers.h

@@ -65,6 +65,12 @@ enum grpc_profiling_tags {
   GRPC_PTAG_TCP_WRITE = 205 + GRPC_PTAG_IGNORE_THRESHOLD,
   GRPC_PTAG_BECOME_READABLE = 207,
 
+  GRPC_PTAG_MUTEX_LOCK = 250,
+  GRPC_PTAG_MUTEX_UNLOCK = 254,
+  GRPC_PTAG_MALLOC = 251,
+  GRPC_PTAG_REALLOC = 252,
+  GRPC_PTAG_FREE = 253,
+
   /* C++ */
   GRPC_PTAG_CPP_CALL_CREATED = 300 + GRPC_PTAG_IGNORE_THRESHOLD,
   GRPC_PTAG_CPP_PERFORM_OPS = 301 + GRPC_PTAG_IGNORE_THRESHOLD,
@@ -74,19 +80,25 @@ enum grpc_profiling_tags {
 
   /* Transports */
   GRPC_PTAG_HTTP2_RECV_DATA = 400,
-  GRPC_PTAG_HTTP2_UNLOCK = 401 + GRPC_PTAG_IGNORE_THRESHOLD,
-  GRPC_PTAG_HTTP2_UNLOCK_CLEANUP = 402 + GRPC_PTAG_IGNORE_THRESHOLD,
+  GRPC_PTAG_HTTP2_UNLOCK = 401,
+  GRPC_PTAG_HTTP2_WRITING_ACTION = 402,
+  GRPC_PTAG_HTTP2_TERMINATE_WRITING = 403,
 
   /* Completion queue */
   GRPC_PTAG_CQ_NEXT = 501,
   GRPC_PTAG_CQ_PLUCK = 502,
   GRPC_PTAG_POLLSET_WORK = 503,
   GRPC_PTAG_EXEC_CTX_FLUSH = 504,
+  GRPC_PTAG_EXEC_CTX_STEP = 505,
 
   /* Surface */
   GRPC_PTAG_CALL_START_BATCH = 600,
   GRPC_PTAG_CALL_ON_DONE_RECV = 601,
   GRPC_PTAG_CALL_UNLOCK = 602,
+  GRPC_PTAG_CALL_ON_DONE_SEND = 602,
+
+  /* Channel */
+  GRPC_PTAG_CHANNEL_PICKED_TARGET = 700,
 
   /* > 1024 Unassigned reserved. For any miscellaneous use.
    * Use addition to generate tags from this base or take advantage of the 10

src/core/support/alloc.c

@@ -35,22 +35,32 @@
 
 #include <stdlib.h>
 #include <grpc/support/port_platform.h>
+#include "src/core/profiling/timers.h"
 
 void *gpr_malloc(size_t size) {
-  void *p = malloc(size);
+  void *p;
+  GRPC_TIMER_BEGIN(GRPC_PTAG_MALLOC, 0);
+  p = malloc(size);
   if (!p) {
     abort();
   }
+  GRPC_TIMER_END(GRPC_PTAG_MALLOC, 0);
   return p;
 }
 
-void gpr_free(void *p) { free(p); }
+void gpr_free(void *p) { 
+  GRPC_TIMER_BEGIN(GRPC_PTAG_FREE, 0);
+  free(p); 
+  GRPC_TIMER_END(GRPC_PTAG_FREE, 0);
+}
 
 void *gpr_realloc(void *p, size_t size) {
+  GRPC_TIMER_BEGIN(GRPC_PTAG_REALLOC, 0);
   p = realloc(p, size);
   if (!p) {
     abort();
   }
+  GRPC_TIMER_END(GRPC_PTAG_REALLOC, 0);
   return p;
 }
 

src/core/support/sync_posix.c

@@ -40,14 +40,23 @@
 #include <grpc/support/log.h>
 #include <grpc/support/sync.h>
 #include <grpc/support/time.h>
+#include "src/core/profiling/timers.h"
 
 void gpr_mu_init(gpr_mu* mu) { GPR_ASSERT(pthread_mutex_init(mu, NULL) == 0); }
 
 void gpr_mu_destroy(gpr_mu* mu) { GPR_ASSERT(pthread_mutex_destroy(mu) == 0); }
 
-void gpr_mu_lock(gpr_mu* mu) { GPR_ASSERT(pthread_mutex_lock(mu) == 0); }
+void gpr_mu_lock(gpr_mu* mu) { 
+  GRPC_TIMER_BEGIN(GRPC_PTAG_MUTEX_LOCK, 0);
+  GPR_ASSERT(pthread_mutex_lock(mu) == 0); 
+  GRPC_TIMER_END(GRPC_PTAG_MUTEX_LOCK, 0);
+}
 
-void gpr_mu_unlock(gpr_mu* mu) { GPR_ASSERT(pthread_mutex_unlock(mu) == 0); }
+void gpr_mu_unlock(gpr_mu* mu) { 
+  GRPC_TIMER_BEGIN(GRPC_PTAG_MUTEX_UNLOCK, 0);
+  GPR_ASSERT(pthread_mutex_unlock(mu) == 0); 
+  GRPC_TIMER_END(GRPC_PTAG_MUTEX_UNLOCK, 0);
+}
 
 int gpr_mu_trylock(gpr_mu* mu) {
   int err = pthread_mutex_trylock(mu);

src/core/surface/call.c

@@ -836,6 +836,7 @@ static void early_out_write_ops(grpc_call *call) {
 
 static void call_on_done_send(grpc_exec_ctx *exec_ctx, void *pc, int success) {
   grpc_call *call = pc;
+  GRPC_TIMER_BEGIN(GRPC_PTAG_CALL_ON_DONE_SEND, 0);
   lock(call);
   if (call->last_send_contains & (1 << GRPC_IOREQ_SEND_INITIAL_METADATA)) {
     finish_ioreq_op(call, GRPC_IOREQ_SEND_INITIAL_METADATA, success);
@@ -859,6 +860,7 @@ static void call_on_done_send(grpc_exec_ctx *exec_ctx, void *pc, int success) {
   call->sending = 0;
   unlock(exec_ctx, call);
   GRPC_CALL_INTERNAL_UNREF(exec_ctx, call, "sending");
+  GRPC_TIMER_END(GRPC_PTAG_CALL_ON_DONE_SEND, 0);
 }
 
 static void finish_message(grpc_call *call) {

src/core/transport/chttp2_transport.c

@@ -546,6 +546,8 @@ void grpc_chttp2_terminate_writing(grpc_exec_ctx *exec_ctx,
   grpc_chttp2_transport_writing *transport_writing = transport_writing_ptr;
   grpc_chttp2_transport *t = TRANSPORT_FROM_WRITING(transport_writing);
 
+  GRPC_TIMER_BEGIN(GRPC_PTAG_HTTP2_TERMINATE_WRITING, 0);
+
   lock(t);
 
   allow_endpoint_shutdown_locked(exec_ctx, t);
@@ -567,12 +569,16 @@ void grpc_chttp2_terminate_writing(grpc_exec_ctx *exec_ctx,
   unlock(exec_ctx, t);
 
   UNREF_TRANSPORT(exec_ctx, t, "writing");
+  
+  GRPC_TIMER_END(GRPC_PTAG_HTTP2_TERMINATE_WRITING, 0);
 }
 
 static void writing_action(grpc_exec_ctx *exec_ctx, void *gt,
                            int iomgr_success_ignored) {
   grpc_chttp2_transport *t = gt;
+  GRPC_TIMER_BEGIN(GRPC_PTAG_HTTP2_WRITING_ACTION, 0);
   grpc_chttp2_perform_writes(exec_ctx, &t->writing, t->ep);
+  GRPC_TIMER_END(GRPC_PTAG_HTTP2_WRITING_ACTION, 0);
 }
 
 void grpc_chttp2_add_incoming_goaway(