Merge pull request #3754 from ctiller/latent-see

Latency profiling support

27 files changed, 382 insertions, 231 deletions

diff --git a/src/core/channel/client_channel.c b/src/core/channel/client_channel.c
index ce8af96054..9f85557ea1 100644
--- a/src/core/channel/client_channel.c
+++ b/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 */
 
@@ -242,6 +244,8 @@ static void picked_target(grpc_exec_ctx *exec_ctx, void *arg,
   grpc_pollset *pollset;
   grpc_subchannel_call_create_status call_creation_status;
 
+  GPR_TIMER_BEGIN("picked_target", 0);
+
   if (calld->picked_channel == NULL) {
     /* treat this like a cancellation */
     calld->waiting_op.cancel_with_status = GRPC_STATUS_UNAVAILABLE;
@@ -266,6 +270,8 @@ static void picked_target(grpc_exec_ctx *exec_ctx, void *arg,
       }
     }
   }
+
+  GPR_TIMER_END("picked_target", 0);
 }
 
 static grpc_closure *merge_into_waiting_op(grpc_call_element *elem,
@@ -326,6 +332,7 @@ static void perform_transport_stream_op(grpc_exec_ctx *exec_ctx,
   grpc_subchannel_call *subchannel_call;
   grpc_lb_policy *lb_policy;
   grpc_transport_stream_op op2;
+  GPR_TIMER_BEGIN("perform_transport_stream_op", 0);
   GPR_ASSERT(elem->filter == &grpc_client_channel_filter);
   GRPC_CALL_LOG_OP(GPR_INFO, elem, op);
 
@@ -437,6 +444,8 @@ static void perform_transport_stream_op(grpc_exec_ctx *exec_ctx,
       }
       break;
   }
+
+  GPR_TIMER_END("perform_transport_stream_op", 0);
 }
 
 static void cc_start_transport_stream_op(grpc_exec_ctx *exec_ctx,
diff --git a/src/core/channel/compress_filter.c b/src/core/channel/compress_filter.c
index c32f150715..20b5084044 100644
--- a/src/core/channel/compress_filter.c
+++ b/src/core/channel/compress_filter.c
@@ -41,6 +41,7 @@
 
 #include "src/core/channel/compress_filter.h"
 #include "src/core/channel/channel_args.h"
+#include "src/core/profiling/timers.h"
 #include "src/core/compression/message_compress.h"
 #include "src/core/support/string.h"
 
@@ -271,10 +272,14 @@ static void process_send_ops(grpc_call_element *elem,
 static void compress_start_transport_stream_op(grpc_exec_ctx *exec_ctx,
                                                grpc_call_element *elem,
                                                grpc_transport_stream_op *op) {
+  GPR_TIMER_BEGIN("compress_start_transport_stream_op", 0);
+
   if (op->send_ops && op->send_ops->nops > 0) {
     process_send_ops(elem, op->send_ops);
   }
 
+  GPR_TIMER_END("compress_start_transport_stream_op", 0);
+
   /* pass control down the stack */
   grpc_call_next_op(exec_ctx, elem, op);
 }
diff --git a/src/core/channel/connected_channel.c b/src/core/channel/connected_channel.c
index f9fc280259..6d4d7be632 100644
--- a/src/core/channel/connected_channel.c
+++ b/src/core/channel/connected_channel.c
@@ -39,6 +39,7 @@
 
 #include "src/core/support/string.h"
 #include "src/core/transport/transport.h"
+#include "src/core/profiling/timers.h"
 #include <grpc/byte_buffer.h>
 #include <grpc/support/alloc.h>
 #include <grpc/support/log.h>
diff --git a/src/core/channel/http_client_filter.c b/src/core/channel/http_client_filter.c
index d67dc37ad2..f78a5cc315 100644
--- a/src/core/channel/http_client_filter.c
+++ b/src/core/channel/http_client_filter.c
@@ -36,6 +36,7 @@
 #include <grpc/support/log.h>
 #include <grpc/support/string_util.h>
 #include "src/core/support/string.h"
+#include "src/core/profiling/timers.h"
 
 typedef struct call_data {
   grpc_linked_mdelem method;
@@ -162,8 +163,10 @@ static void hc_mutate_op(grpc_call_element *elem,
 static void hc_start_transport_op(grpc_exec_ctx *exec_ctx,
                                   grpc_call_element *elem,
                                   grpc_transport_stream_op *op) {
+  GPR_TIMER_BEGIN("hc_start_transport_op", 0);
   GRPC_CALL_LOG_OP(GPR_INFO, elem, op);
   hc_mutate_op(elem, op);
+  GPR_TIMER_END("hc_start_transport_op", 0);
   grpc_call_next_op(exec_ctx, elem, op);
 }
 
diff --git a/src/core/channel/http_server_filter.c b/src/core/channel/http_server_filter.c
index 5e6d684a52..99e5066a4e 100644
--- a/src/core/channel/http_server_filter.c
+++ b/src/core/channel/http_server_filter.c
@@ -36,6 +36,7 @@
 #include <string.h>
 #include <grpc/support/alloc.h>
 #include <grpc/support/log.h>
+#include "src/core/profiling/timers.h"
 
 typedef struct call_data {
   gpr_uint8 got_initial_metadata;
@@ -230,8 +231,10 @@ static void hs_start_transport_op(grpc_exec_ctx *exec_ctx,
                                   grpc_call_element *elem,
                                   grpc_transport_stream_op *op) {
   GRPC_CALL_LOG_OP(GPR_INFO, elem, op);
+  GPR_TIMER_BEGIN("hs_start_transport_op", 0);
   hs_mutate_op(elem, op);
   grpc_call_next_op(exec_ctx, elem, op);
+  GPR_TIMER_END("hs_start_transport_op", 0);
 }
 
 /* Constructor for call_data */
diff --git a/src/core/client_config/lb_policies/pick_first.c b/src/core/client_config/lb_policies/pick_first.c
index 4b3aaab09c..e5bf0680ff 100644
--- a/src/core/client_config/lb_policies/pick_first.c
+++ b/src/core/client_config/lb_policies/pick_first.c
@@ -175,7 +175,7 @@ void pf_pick(grpc_exec_ctx *exec_ctx, grpc_lb_policy *pol,
   }
 }
 
-static void destroy_subchannels(grpc_exec_ctx *exec_ctx, void *arg, 
+static void destroy_subchannels(grpc_exec_ctx *exec_ctx, void *arg,
                                 int iomgr_success) {
   pick_first_lb_policy *p = arg;
   size_t i;
@@ -235,7 +235,8 @@ static void pf_connectivity_changed(grpc_exec_ctx *exec_ctx, void *arg,
         GRPC_SUBCHANNEL_REF(p->selected, "picked_first");
         /* drop the pick list: we are connected now */
         GRPC_LB_POLICY_REF(&p->base, "destroy_subchannels");
-        grpc_exec_ctx_enqueue(exec_ctx, grpc_closure_create(destroy_subchannels, p), 1);
+        grpc_exec_ctx_enqueue(exec_ctx,
+                              grpc_closure_create(destroy_subchannels, p), 1);
         /* update any calls that were waiting for a pick */
         while ((pp = p->pending_picks)) {
           p->pending_picks = pp->next;
diff --git a/src/core/iomgr/exec_ctx.c b/src/core/iomgr/exec_ctx.c
index f2914d376e..410b34c521 100644
--- a/src/core/iomgr/exec_ctx.c
+++ b/src/core/iomgr/exec_ctx.c
@@ -35,18 +35,24 @@
 
 #include <grpc/support/log.h>
 
+#include "src/core/profiling/timers.h"
+
 int grpc_exec_ctx_flush(grpc_exec_ctx *exec_ctx) {
   int did_something = 0;
+  GPR_TIMER_BEGIN("grpc_exec_ctx_flush", 0);
   while (!grpc_closure_list_empty(exec_ctx->closure_list)) {
     grpc_closure *c = exec_ctx->closure_list.head;
     exec_ctx->closure_list.head = exec_ctx->closure_list.tail = NULL;
     while (c != NULL) {
       grpc_closure *next = c->next;
-      did_something = 1;
+      did_something++;
+      GPR_TIMER_BEGIN("grpc_exec_ctx_flush.cb", 0);
       c->cb(exec_ctx, c->cb_arg, c->success);
+      GPR_TIMER_END("grpc_exec_ctx_flush.cb", 0);
       c = next;
     }
   }
+  GPR_TIMER_END("grpc_exec_ctx_flush", 0);
   return did_something;
 }
 
diff --git a/src/core/iomgr/pollset_multipoller_with_epoll.c b/src/core/iomgr/pollset_multipoller_with_epoll.c
index ba9ba73f9d..2aafd21dfb 100644
--- a/src/core/iomgr/pollset_multipoller_with_epoll.c
+++ b/src/core/iomgr/pollset_multipoller_with_epoll.c
@@ -41,10 +41,11 @@
 #include <sys/epoll.h>
 #include <unistd.h>
 
-#include "src/core/iomgr/fd_posix.h"
-#include "src/core/support/block_annotate.h"
 #include <grpc/support/alloc.h>
 #include <grpc/support/log.h>
+#include "src/core/iomgr/fd_posix.h"
+#include "src/core/support/block_annotate.h"
+#include "src/core/profiling/timers.h"
 
 typedef struct wakeup_fd_hdl {
   grpc_wakeup_fd wakeup_fd;
@@ -182,9 +183,11 @@ static void multipoll_with_epoll_pollset_maybe_work_and_unlock(
 
   /* TODO(vpai): Consider first doing a 0 timeout poll here to avoid
      even going into the blocking annotation if possible */
+  GPR_TIMER_BEGIN("poll", 0);
   GRPC_SCHEDULING_START_BLOCKING_REGION;
   poll_rv = grpc_poll_function(pfds, 2, timeout_ms);
   GRPC_SCHEDULING_END_BLOCKING_REGION;
+  GPR_TIMER_END("poll", 0);
 
   if (poll_rv < 0) {
     if (errno != EINTR) {
diff --git a/src/core/iomgr/pollset_posix.c b/src/core/iomgr/pollset_posix.c
index d056866d13..4d8bc5374f 100644
--- a/src/core/iomgr/pollset_posix.c
+++ b/src/core/iomgr/pollset_posix.c
@@ -101,9 +101,12 @@ static void push_front_worker(grpc_pollset *p, grpc_pollset_worker *worker) {
 void grpc_pollset_kick_ext(grpc_pollset *p,
                            grpc_pollset_worker *specific_worker,
                            gpr_uint32 flags) {
+  GPR_TIMER_BEGIN("grpc_pollset_kick_ext", 0);
+
   /* pollset->mu already held */
   if (specific_worker != NULL) {
     if (specific_worker == GRPC_POLLSET_KICK_BROADCAST) {
+      GPR_TIMER_BEGIN("grpc_pollset_kick_ext.broadcast", 0);
       GPR_ASSERT((flags & GRPC_POLLSET_REEVALUATE_POLLING_ON_WAKEUP) == 0);
       for (specific_worker = p->root_worker.next;
            specific_worker != &p->root_worker;
@@ -111,44 +114,50 @@ void grpc_pollset_kick_ext(grpc_pollset *p,
         grpc_wakeup_fd_wakeup(&specific_worker->wakeup_fd);
       }
       p->kicked_without_pollers = 1;
-      return;
+      GPR_TIMER_END("grpc_pollset_kick_ext.broadcast", 0);
     } else if (gpr_tls_get(&g_current_thread_worker) !=
                (gpr_intptr)specific_worker) {
+      GPR_TIMER_MARK("different_thread_worker", 0);
       if ((flags & GRPC_POLLSET_REEVALUATE_POLLING_ON_WAKEUP) != 0) {
         specific_worker->reevaluate_polling_on_wakeup = 1;
       }
       grpc_wakeup_fd_wakeup(&specific_worker->wakeup_fd);
-      return;
     } else if ((flags & GRPC_POLLSET_CAN_KICK_SELF) != 0) {
+      GPR_TIMER_MARK("kick_yoself", 0);
       if ((flags & GRPC_POLLSET_REEVALUATE_POLLING_ON_WAKEUP) != 0) {
         specific_worker->reevaluate_polling_on_wakeup = 1;
       }
       grpc_wakeup_fd_wakeup(&specific_worker->wakeup_fd);
-      return;
     }
   } else if (gpr_tls_get(&g_current_thread_poller) != (gpr_intptr)p) {
     GPR_ASSERT((flags & GRPC_POLLSET_REEVALUATE_POLLING_ON_WAKEUP) == 0);
+    GPR_TIMER_MARK("kick_anonymous", 0);
     specific_worker = pop_front_worker(p);
     if (specific_worker != NULL) {
       if (gpr_tls_get(&g_current_thread_worker) ==
           (gpr_intptr)specific_worker) {
+        GPR_TIMER_MARK("kick_anonymous_not_self", 0);
         push_back_worker(p, specific_worker);
         specific_worker = pop_front_worker(p);
         if ((flags & GRPC_POLLSET_CAN_KICK_SELF) == 0 &&
             gpr_tls_get(&g_current_thread_worker) ==
                 (gpr_intptr)specific_worker) {
           push_back_worker(p, specific_worker);
-          return;
+          specific_worker = NULL;
         }
       }
-      push_back_worker(p, specific_worker);
-      grpc_wakeup_fd_wakeup(&specific_worker->wakeup_fd);
-      return;
+      if (specific_worker != NULL) {
+        GPR_TIMER_MARK("finally_kick", 0);
+        push_back_worker(p, specific_worker);
+        grpc_wakeup_fd_wakeup(&specific_worker->wakeup_fd);
+      }
     } else {
+      GPR_TIMER_MARK("kicked_no_pollers", 0);
       p->kicked_without_pollers = 1;
-      return;
     }
   }
+
+  GPR_TIMER_END("grpc_pollset_kick_ext", 0);
 }
 
 void grpc_pollset_kick(grpc_pollset *p, grpc_pollset_worker *specific_worker) {
@@ -229,6 +238,7 @@ void grpc_pollset_work(grpc_exec_ctx *exec_ctx, grpc_pollset *pollset,
   int locked = 1;
   int queued_work = 0;
   int keep_polling = 0;
+  GPR_TIMER_BEGIN("grpc_pollset_work", 0);
   /* this must happen before we (potentially) drop pollset->mu */
   worker->next = worker->prev = NULL;
   worker->reevaluate_polling_on_wakeup = 0;
@@ -273,8 +283,10 @@ void grpc_pollset_work(grpc_exec_ctx *exec_ctx, grpc_pollset *pollset,
       }
       gpr_tls_set(&g_current_thread_poller, (gpr_intptr)pollset);
       gpr_tls_set(&g_current_thread_worker, (gpr_intptr)worker);
+      GPR_TIMER_BEGIN("maybe_work_and_unlock", 0);
       pollset->vtable->maybe_work_and_unlock(exec_ctx, pollset, worker,
                                              deadline, now);
+      GPR_TIMER_END("maybe_work_and_unlock", 0);
       locked = 0;
       gpr_tls_set(&g_current_thread_poller, 0);
       gpr_tls_set(&g_current_thread_worker, 0);
@@ -329,6 +341,7 @@ void grpc_pollset_work(grpc_exec_ctx *exec_ctx, grpc_pollset *pollset,
       gpr_mu_lock(&pollset->mu);
     }
   }
+  GPR_TIMER_END("grpc_pollset_work", 0);
 }
 
 void grpc_pollset_shutdown(grpc_exec_ctx *exec_ctx, grpc_pollset *pollset,
@@ -563,10 +576,11 @@ static void basic_pollset_maybe_work_and_unlock(grpc_exec_ctx *exec_ctx,
      even going into the blocking annotation if possible */
   /* poll fd count (argument 2) is shortened by one if we have no events
      to poll on - such that it only includes the kicker */
+  GPR_TIMER_BEGIN("poll", 0);
   GRPC_SCHEDULING_START_BLOCKING_REGION;
   r = grpc_poll_function(pfd, nfds, timeout);
   GRPC_SCHEDULING_END_BLOCKING_REGION;
-  GRPC_TIMER_MARK(GRPC_PTAG_POLL_FINISHED, r);
+  GPR_TIMER_END("poll", 0);
 
   if (r < 0) {
     gpr_log(GPR_ERROR, "poll() failed: %s", strerror(errno));
diff --git a/src/core/iomgr/tcp_posix.c b/src/core/iomgr/tcp_posix.c
index 4a57037a72..915553d509 100644
--- a/src/core/iomgr/tcp_posix.c
+++ b/src/core/iomgr/tcp_posix.c
@@ -180,7 +180,7 @@ static void tcp_continue_read(grpc_exec_ctx *exec_ctx, grpc_tcp *tcp) {
   GPR_ASSERT(!tcp->finished_edge);
   GPR_ASSERT(tcp->iov_size <= MAX_READ_IOVEC);
   GPR_ASSERT(tcp->incoming_buffer->count <= MAX_READ_IOVEC);
-  GRPC_TIMER_BEGIN(GRPC_PTAG_HANDLE_READ, 0);
+  GPR_TIMER_BEGIN("tcp_continue_read", 0);
 
   while (tcp->incoming_buffer->count < (size_t)tcp->iov_size) {
     gpr_slice_buffer_add_indexed(tcp->incoming_buffer,
@@ -199,11 +199,11 @@ static void tcp_continue_read(grpc_exec_ctx *exec_ctx, grpc_tcp *tcp) {
   msg.msg_controllen = 0;
   msg.msg_flags = 0;
 
-  GRPC_TIMER_BEGIN(GRPC_PTAG_RECVMSG, 0);
+  GPR_TIMER_BEGIN("recvmsg", 1);
   do {
     read_bytes = recvmsg(tcp->fd, &msg, 0);
   } while (read_bytes < 0 && errno == EINTR);
-  GRPC_TIMER_END(GRPC_PTAG_RECVMSG, 0);
+  GPR_TIMER_END("recvmsg", 0);
 
   if (read_bytes < 0) {
     /* NB: After calling call_read_cb a parallel call of the read handler may
@@ -240,7 +240,7 @@ static void tcp_continue_read(grpc_exec_ctx *exec_ctx, grpc_tcp *tcp) {
     TCP_UNREF(exec_ctx, tcp, "read");
   }
 
-  GRPC_TIMER_END(GRPC_PTAG_HANDLE_READ, 0);
+  GPR_TIMER_END("tcp_continue_read", 0);
 }
 
 static void tcp_handle_read(grpc_exec_ctx *exec_ctx, void *arg /* grpc_tcp */,
@@ -316,12 +316,12 @@ static flush_result tcp_flush(grpc_tcp *tcp) {
     msg.msg_controllen = 0;
     msg.msg_flags = 0;
 
-    GRPC_TIMER_BEGIN(GRPC_PTAG_SENDMSG, 0);
+    GPR_TIMER_BEGIN("sendmsg", 1);
     do {
       /* TODO(klempner): Cork if this is a partial write */
       sent_length = sendmsg(tcp->fd, &msg, SENDMSG_FLAGS);
     } while (sent_length < 0 && errno == EINTR);
-    GRPC_TIMER_END(GRPC_PTAG_SENDMSG, 0);
+    GPR_TIMER_END("sendmsg", 0);
 
     if (sent_length < 0) {
       if (errno == EAGAIN) {
@@ -370,17 +370,17 @@ static void tcp_handle_write(grpc_exec_ctx *exec_ctx, void *arg /* grpc_tcp */,
     return;
   }
 
-  GRPC_TIMER_BEGIN(GRPC_PTAG_TCP_CB_WRITE, 0);
   status = tcp_flush(tcp);
   if (status == FLUSH_PENDING) {
     grpc_fd_notify_on_write(exec_ctx, tcp->em_fd, &tcp->write_closure);
   } else {
     cb = tcp->write_cb;
     tcp->write_cb = NULL;
+    GPR_TIMER_BEGIN("tcp_handle_write.cb", 0);
     cb->cb(exec_ctx, cb->cb_arg, status == FLUSH_DONE);
+    GPR_TIMER_END("tcp_handle_write.cb", 0);
     TCP_UNREF(exec_ctx, tcp, "write");
   }
-  GRPC_TIMER_END(GRPC_PTAG_TCP_CB_WRITE, 0);
 }
 
 static void tcp_write(grpc_exec_ctx *exec_ctx, grpc_endpoint *ep,
@@ -399,11 +399,11 @@ static void tcp_write(grpc_exec_ctx *exec_ctx, grpc_endpoint *ep,
     }
   }
 
-  GRPC_TIMER_BEGIN(GRPC_PTAG_TCP_WRITE, 0);
+  GPR_TIMER_BEGIN("tcp_write", 0);
   GPR_ASSERT(tcp->write_cb == NULL);
 
   if (buf->length == 0) {
-    GRPC_TIMER_END(GRPC_PTAG_TCP_WRITE, 0);
+    GPR_TIMER_END("tcp_write", 0);
     grpc_exec_ctx_enqueue(exec_ctx, cb, 1);
     return;
   }
@@ -420,7 +420,7 @@ static void tcp_write(grpc_exec_ctx *exec_ctx, grpc_endpoint *ep,
     grpc_exec_ctx_enqueue(exec_ctx, cb, status == FLUSH_DONE);
   }
 
-  GRPC_TIMER_END(GRPC_PTAG_TCP_WRITE, 0);
+  GPR_TIMER_END("tcp_write", 0);
 }
 
 static void tcp_add_to_pollset(grpc_exec_ctx *exec_ctx, grpc_endpoint *ep,
diff --git a/src/core/iomgr/wakeup_fd_eventfd.c b/src/core/iomgr/wakeup_fd_eventfd.c
index 48eb1afb3d..f67379e4fc 100644
--- a/src/core/iomgr/wakeup_fd_eventfd.c
+++ b/src/core/iomgr/wakeup_fd_eventfd.c
@@ -39,9 +39,11 @@
 #include <sys/eventfd.h>
 #include <unistd.h>
 
-#include "src/core/iomgr/wakeup_fd_posix.h"
 #include <grpc/support/log.h>
 
+#include "src/core/iomgr/wakeup_fd_posix.h"
+#include "src/core/profiling/timers.h"
+
 static void eventfd_create(grpc_wakeup_fd* fd_info) {
   int efd = eventfd(0, EFD_NONBLOCK | EFD_CLOEXEC);
   /* TODO(klempner): Handle failure more gracefully */
@@ -60,9 +62,11 @@ static void eventfd_consume(grpc_wakeup_fd* fd_info) {
 
 static void eventfd_wakeup(grpc_wakeup_fd* fd_info) {
   int err;
+  GPR_TIMER_BEGIN("eventfd_wakeup", 0);
   do {
     err = eventfd_write(fd_info->read_fd, 1);
   } while (err < 0 && errno == EINTR);
+  GPR_TIMER_END("eventfd_wakeup", 0);
 }
 
 static void eventfd_destroy(grpc_wakeup_fd* fd_info) {
diff --git a/src/core/profiling/basic_timers.c b/src/core/profiling/basic_timers.c
index 2f6c88daac..b49cdd07b3 100644
--- a/src/core/profiling/basic_timers.c
+++ b/src/core/profiling/basic_timers.c
@@ -44,98 +44,91 @@
 #include <grpc/support/thd.h>
 #include <stdio.h>
 
-typedef enum {
-  BEGIN = '{',
-  END = '}',
-  MARK = '.',
-  IMPORTANT = '!'
-} marker_type;
-
-typedef struct grpc_timer_entry {
+typedef enum { BEGIN = '{', END = '}', MARK = '.' } marker_type;
+
+typedef struct gpr_timer_entry {
   gpr_timespec tm;
-  int tag;
   const char *tagstr;
-  marker_type type;
-  void *id;
   const char *file;
   int line;
-} grpc_timer_entry;
+  char type;
+  gpr_uint8 important;
+} gpr_timer_entry;
+
+#define MAX_COUNT (1024 * 1024 / sizeof(gpr_timer_entry))
 
-#define MAX_COUNT (1024 * 1024 / sizeof(grpc_timer_entry))
+static __thread gpr_timer_entry g_log[MAX_COUNT];
+static __thread int g_count;
+static gpr_once g_once_init = GPR_ONCE_INIT;
+static FILE *output_file;
 
-static __thread grpc_timer_entry log[MAX_COUNT];
-static __thread int count;
+static void close_output() { fclose(output_file); }
+
+static void init_output() {
+  output_file = fopen("latency_trace.txt", "w");
+  GPR_ASSERT(output_file);
+  atexit(close_output);
+}
 
 static void log_report() {
   int i;
-  for (i = 0; i < count; i++) {
-    grpc_timer_entry *entry = &(log[i]);
-    printf("GRPC_LAT_PROF %ld.%09d  %p %c %d(%s) %p %s %d\n", entry->tm.tv_sec,
-           entry->tm.tv_nsec, (void *)(gpr_intptr)gpr_thd_currentid(),
-           entry->type, entry->tag, entry->tagstr, entry->id, entry->file,
-           entry->line);
+  gpr_once_init(&g_once_init, init_output);
+  for (i = 0; i < g_count; i++) {
+    gpr_timer_entry *entry = &(g_log[i]);
+    fprintf(output_file,
+            "{\"t\": %ld.%09d, \"thd\": \"%p\", \"type\": \"%c\", \"tag\": "
+            "\"%s\", \"file\": \"%s\", \"line\": %d, \"imp\": %d}\n",
+            entry->tm.tv_sec, entry->tm.tv_nsec,
+            (void *)(gpr_intptr)gpr_thd_currentid(), entry->type, entry->tagstr,
+            entry->file, entry->line, entry->important);
   }
 
   /* Now clear out the log */
-  count = 0;
+  g_count = 0;
 }
 
-static void grpc_timers_log_add(int tag, const char *tagstr, marker_type type,
-                                void *id, const char *file, int line) {
-  grpc_timer_entry *entry;
+static void gpr_timers_log_add(const char *tagstr, marker_type type,
+                               int important, const char *file, int line) {
+  gpr_timer_entry *entry;
 
   /* TODO (vpai) : Improve concurrency */
-  if (count == MAX_COUNT) {
+  if (g_count == MAX_COUNT) {
     log_report();
   }
 
-  entry = &log[count++];
+  entry = &g_log[g_count++];
 
   entry->tm = gpr_now(GPR_CLOCK_PRECISE);
-  entry->tag = tag;
   entry->tagstr = tagstr;
   entry->type = type;
-  entry->id = id;
   entry->file = file;
   entry->line = line;
+  entry->important = important != 0;
 }
 
 /* Latency profiler API implementation. */
-void grpc_timer_add_mark(int tag, const char *tagstr, void *id,
-                         const char *file, int line) {
-  if (tag < GRPC_PTAG_IGNORE_THRESHOLD) {
-    grpc_timers_log_add(tag, tagstr, MARK, id, file, line);
-  }
+void gpr_timer_add_mark(const char *tagstr, int important, const char *file,
+                        int line) {
+  gpr_timers_log_add(tagstr, MARK, important, file, line);
 }
 
-void grpc_timer_add_important_mark(int tag, const char *tagstr, void *id,
-                                   const char *file, int line) {
-  if (tag < GRPC_PTAG_IGNORE_THRESHOLD) {
-    grpc_timers_log_add(tag, tagstr, IMPORTANT, id, file, line);
-  }
+void gpr_timer_begin(const char *tagstr, int important, const char *file,
+                     int line) {
+  gpr_timers_log_add(tagstr, BEGIN, important, file, line);
 }
 
-void grpc_timer_begin(int tag, const char *tagstr, void *id, const char *file,
-                      int line) {
-  if (tag < GRPC_PTAG_IGNORE_THRESHOLD) {
-    grpc_timers_log_add(tag, tagstr, BEGIN, id, file, line);
-  }
-}
-
-void grpc_timer_end(int tag, const char *tagstr, void *id, const char *file,
-                    int line) {
-  if (tag < GRPC_PTAG_IGNORE_THRESHOLD) {
-    grpc_timers_log_add(tag, tagstr, END, id, file, line);
-  }
+void gpr_timer_end(const char *tagstr, int important, const char *file,
+                   int line) {
+  gpr_timers_log_add(tagstr, END, important, file, line);
 }
 
 /* Basic profiler specific API functions. */
-void grpc_timers_global_init(void) {}
+void gpr_timers_global_init(void) {}
 
-void grpc_timers_global_destroy(void) {}
+void gpr_timers_global_destroy(void) {}
 
 #else  /* !GRPC_BASIC_PROFILER */
-void grpc_timers_global_init(void) {}
+void gpr_timers_global_init(void) {}
 
-void grpc_timers_global_destroy(void) {}
+void gpr_timers_global_destroy(void) {}
 #endif /* GRPC_BASIC_PROFILER */
diff --git a/src/core/profiling/stap_timers.c b/src/core/profiling/stap_timers.c
index 6868a674a9..efcd1af4a1 100644
--- a/src/core/profiling/stap_timers.c
+++ b/src/core/profiling/stap_timers.c
@@ -42,23 +42,23 @@
 #include "src/core/profiling/stap_probes.h"
 
 /* Latency profiler API implementation. */
-void grpc_timer_add_mark(int tag, const char *tagstr, void *id,
-                         const char *file, int line) {
+void gpr_timer_add_mark(int tag, const char *tagstr, void *id, const char *file,
+                        int line) {
   _STAP_ADD_MARK(tag);
 }
 
-void grpc_timer_add_important_mark(int tag, const char *tagstr, void *id,
-                                   const char *file, int line) {
+void gpr_timer_add_important_mark(int tag, const char *tagstr, void *id,
+                                  const char *file, int line) {
   _STAP_ADD_IMPORTANT_MARK(tag);
 }
 
-void grpc_timer_begin(int tag, const char *tagstr, void *id, const char *file,
-                      int line) {
+void gpr_timer_begin(int tag, const char *tagstr, void *id, const char *file,
+                     int line) {
   _STAP_TIMING_NS_BEGIN(tag);
 }
 
-void grpc_timer_end(int tag, const char *tagstr, void *id, const char *file,
-                    int line) {
+void gpr_timer_end(int tag, const char *tagstr, void *id, const char *file,
+                   int line) {
   _STAP_TIMING_NS_END(tag);
 }
 
diff --git a/src/core/profiling/timers.h b/src/core/profiling/timers.h
index a70520408c..0d112e7248 100644
--- a/src/core/profiling/timers.h
+++ b/src/core/profiling/timers.h
@@ -38,65 +38,28 @@
 extern "C" {
 #endif
 
-void grpc_timers_global_init(void);
-void grpc_timers_global_destroy(void);
-
-void grpc_timer_add_mark(int tag, const char *tagstr, void *id,
-                         const char *file, int line);
-void grpc_timer_add_important_mark(int tag, const char *tagstr, void *id,
-                                   const char *file, int line);
-void grpc_timer_begin(int tag, const char *tagstr, void *id, const char *file,
-                      int line);
-void grpc_timer_end(int tag, const char *tagstr, void *id, const char *file,
-                    int line);
-
-enum grpc_profiling_tags {
-  /* Any GRPC_PTAG_* >= than the threshold won't generate any profiling mark. */
-  GRPC_PTAG_IGNORE_THRESHOLD = 1000000,
-
-  /* Re. Protos. */
-  GRPC_PTAG_PROTO_SERIALIZE = 100 + GRPC_PTAG_IGNORE_THRESHOLD,
-  GRPC_PTAG_PROTO_DESERIALIZE = 101 + GRPC_PTAG_IGNORE_THRESHOLD,
-
-  /* Re. sockets. */
-  GRPC_PTAG_HANDLE_READ = 200 + GRPC_PTAG_IGNORE_THRESHOLD,
-  GRPC_PTAG_SENDMSG = 201 + GRPC_PTAG_IGNORE_THRESHOLD,
-  GRPC_PTAG_RECVMSG = 202 + GRPC_PTAG_IGNORE_THRESHOLD,
-  GRPC_PTAG_POLL_FINISHED = 203 + GRPC_PTAG_IGNORE_THRESHOLD,
-  GRPC_PTAG_TCP_CB_WRITE = 204 + GRPC_PTAG_IGNORE_THRESHOLD,
-  GRPC_PTAG_TCP_WRITE = 205 + GRPC_PTAG_IGNORE_THRESHOLD,
-  GRPC_PTAG_CALL_ON_DONE_RECV = 206 + GRPC_PTAG_IGNORE_THRESHOLD,
-
-  /* C++ */
-  GRPC_PTAG_CPP_CALL_CREATED = 300 + GRPC_PTAG_IGNORE_THRESHOLD,
-  GRPC_PTAG_CPP_PERFORM_OPS = 301 + GRPC_PTAG_IGNORE_THRESHOLD,
-
-  /* Transports */
-  GRPC_PTAG_HTTP2_UNLOCK = 401 + GRPC_PTAG_IGNORE_THRESHOLD,
-  GRPC_PTAG_HTTP2_UNLOCK_CLEANUP = 402 + GRPC_PTAG_IGNORE_THRESHOLD,
-
-  /* > 1024 Unassigned reserved. For any miscellaneous use.
-   * Use addition to generate tags from this base or take advantage of the 10
-   * zero'd bits for OR-ing. */
-  GRPC_PTAG_OTHER_BASE = 1024
-};
+void gpr_timers_global_init(void);
+void gpr_timers_global_destroy(void);
+
+void gpr_timer_add_mark(const char *tagstr, int important, const char *file,
+                        int line);
+void gpr_timer_begin(const char *tagstr, int important, const char *file,
+                     int line);
+void gpr_timer_end(const char *tagstr, int important, const char *file,
+                   int line);
 
 #if !(defined(GRPC_STAP_PROFILER) + defined(GRPC_BASIC_PROFILER))
 /* No profiling. No-op all the things. */
-#define GRPC_TIMER_MARK(tag, id) \
-  do {                           \
-  } while (0)
-
-#define GRPC_TIMER_IMPORTANT_MARK(tag, id) \
-  do {                                     \
+#define GPR_TIMER_MARK(tag, important) \
+  do {                                 \
   } while (0)
 
-#define GRPC_TIMER_BEGIN(tag, id) \
-  do {                            \
+#define GPR_TIMER_BEGIN(tag, important) \
+  do {                                  \
   } while (0)
 
-#define GRPC_TIMER_END(tag, id) \
-  do {                          \
+#define GPR_TIMER_END(tag, important) \
+  do {                                \
   } while (0)
 
 #else /* at least one profiler requested... */
@@ -106,28 +69,14 @@ enum grpc_profiling_tags {
 #endif
 
 /* Generic profiling interface. */
-#define GRPC_TIMER_MARK(tag, id)                                         \
-  if (tag < GRPC_PTAG_IGNORE_THRESHOLD) {                                \
-    grpc_timer_add_mark(tag, #tag, ((void *)(gpr_intptr)(id)), __FILE__, \
-                        __LINE__);                                       \
-  }
-
-#define GRPC_TIMER_IMPORTANT_MARK(tag, id)                               \
-  if (tag < GRPC_PTAG_IGNORE_THRESHOLD) {                                \
-    grpc_timer_add_important_mark(tag, #tag, ((void *)(gpr_intptr)(id)), \
-                                  __FILE__, __LINE__);                   \
-  }
+#define GPR_TIMER_MARK(tag, important) \
+  gpr_timer_add_mark(tag, important, __FILE__, __LINE__);
 
-#define GRPC_TIMER_BEGIN(tag, id)                                     \
-  if (tag < GRPC_PTAG_IGNORE_THRESHOLD) {                             \
-    grpc_timer_begin(tag, #tag, ((void *)(gpr_intptr)(id)), __FILE__, \
-                     __LINE__);                                       \
-  }
+#define GPR_TIMER_BEGIN(tag, important) \
+  gpr_timer_begin(tag, important, __FILE__, __LINE__);
 
-#define GRPC_TIMER_END(tag, id)                                                \
-  if (tag < GRPC_PTAG_IGNORE_THRESHOLD) {                                      \
-    grpc_timer_end(tag, #tag, ((void *)(gpr_intptr)(id)), __FILE__, __LINE__); \
-  }
+#define GPR_TIMER_END(tag, important) \
+  gpr_timer_end(tag, important, __FILE__, __LINE__);
 
 #ifdef GRPC_STAP_PROFILER
 /* Empty placeholder for now. */
@@ -141,6 +90,28 @@ enum grpc_profiling_tags {
 
 #ifdef __cplusplus
 }
+
+#if (defined(GRPC_STAP_PROFILER) + defined(GRPC_BASIC_PROFILER))
+namespace grpc {
+class ProfileScope {
+ public:
+  ProfileScope(const char *desc, bool important) : desc_(desc) {
+    GPR_TIMER_BEGIN(desc_, important ? 1 : 0);
+  }
+  ~ProfileScope() { GPR_TIMER_END(desc_, 0); }
+
+ private:
+  const char *const desc_;
+};
+}
+
+#define GPR_TIMER_SCOPE(tag, important) \
+  ::grpc::ProfileScope _profile_scope_##__LINE__((tag), (important))
+#else
+#define GPR_TIMER_SCOPE(tag, important) \
+  do {                                  \
+  } while (false)
+#endif
 #endif
 
 #endif /* GRPC_CORE_PROFILING_TIMERS_H */
diff --git a/src/core/support/alloc.c b/src/core/support/alloc.c
index d2ed82e771..bfcb77956b 100644
--- a/src/core/support/alloc.c
+++ b/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;
+  GPR_TIMER_BEGIN("gpr_malloc", 0);
+  p = malloc(size);
   if (!p) {
     abort();
   }
+  GPR_TIMER_END("gpr_malloc", 0);
   return p;
 }
 
-void gpr_free(void *p) { free(p); }
+void gpr_free(void *p) {
+  GPR_TIMER_BEGIN("gpr_free", 0);
+  free(p);
+  GPR_TIMER_END("gpr_free", 0);
+}
 
 void *gpr_realloc(void *p, size_t size) {
+  GPR_TIMER_BEGIN("gpr_realloc", 0);
   p = realloc(p, size);
   if (!p) {
     abort();
   }
+  GPR_TIMER_END("gpr_realloc", 0);
   return p;
 }
 
diff --git a/src/core/support/sync_posix.c b/src/core/support/sync_posix.c
index 91c30989ce..39c96feb13 100644
--- a/src/core/support/sync_posix.c
+++ b/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) {
+  GPR_TIMER_BEGIN("gpr_mu_lock", 0);
+  GPR_ASSERT(pthread_mutex_lock(mu) == 0);
+  GPR_TIMER_END("gpr_mu_lock", 0);
+}
 
-void gpr_mu_unlock(gpr_mu* mu) { GPR_ASSERT(pthread_mutex_unlock(mu) == 0); }
+void gpr_mu_unlock(gpr_mu* mu) {
+  GPR_TIMER_BEGIN("gpr_mu_unlock", 0);
+  GPR_ASSERT(pthread_mutex_unlock(mu) == 0);
+  GPR_TIMER_END("gpr_mu_unlock", 0);
+}
 
 int gpr_mu_trylock(gpr_mu* mu) {
   int err = pthread_mutex_trylock(mu);
diff --git a/src/core/support/time_posix.c b/src/core/support/time_posix.c
index 78f2c2bb77..02cfca8555 100644
--- a/src/core/support/time_posix.c
+++ b/src/core/support/time_posix.c
@@ -63,7 +63,7 @@ static gpr_timespec gpr_from_timespec(struct timespec ts,
 /** maps gpr_clock_type --> clockid_t for clock_gettime */
 static clockid_t clockid_for_gpr_clock[] = {CLOCK_MONOTONIC, CLOCK_REALTIME};
 
-void gpr_time_init(void) {}
+void gpr_time_init(void) { gpr_precise_clock_init(); }
 
 gpr_timespec gpr_now(gpr_clock_type clock_type) {
   struct timespec now;
@@ -89,6 +89,7 @@ static uint64_t g_time_start;
 
 void gpr_time_init(void) {
   mach_timebase_info_data_t tb = {0, 1};
+  gpr_precise_clock_init();
   mach_timebase_info(&tb);
   g_time_scale = tb.numer;
   g_time_scale /= tb.denom;
diff --git a/src/core/support/time_precise.c b/src/core/support/time_precise.c
new file mode 100644
index 0000000000..b37517e639
--- /dev/null
+++ b/src/core/support/time_precise.c
@@ -0,0 +1,89 @@
+/*
+ *
+ * Copyright 2015, Google Inc.
+ * All rights reserved.
+ *
+ * Redistribution and use in source and binary forms, with or without
+ * modification, are permitted provided that the following conditions are
+ * met:
+ *
+ *     * Redistributions of source code must retain the above copyright
+ * notice, this list of conditions and the following disclaimer.
+ *     * Redistributions in binary form must reproduce the above
+ * copyright notice, this list of conditions and the following disclaimer
+ * in the documentation and/or other materials provided with the
+ * distribution.
+ *     * Neither the name of Google Inc. nor the names of its
+ * contributors may be used to endorse or promote products derived from
+ * this software without specific prior written permission.
+ *
+ * THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS
+ * "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT
+ * LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR
+ * A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT
+ * OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL,
+ * SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT
+ * LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE,
+ * DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY
+ * THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT
+ * (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE
+ * OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
+ *
+ */
+
+#include <grpc/support/log.h>
+#include <grpc/support/time.h>
+#include <stdio.h>
+
+#ifdef GRPC_TIMERS_RDTSC
+#if defined(__i386__)
+static void gpr_get_cycle_counter(long long int *clk) {
+  long long int ret;
+  __asm__ volatile("rdtsc" : "=A"(ret));
+  *clk = ret;
+}
+
+// ----------------------------------------------------------------
+#elif defined(__x86_64__) || defined(__amd64__)
+static void gpr_get_cycle_counter(long long int *clk) {
+  unsigned long long low, high;
+  __asm__ volatile("rdtsc" : "=a"(low), "=d"(high));
+  *clk = (long long)(high << 32) | (long long)low;
+}
+#endif
+
+static double cycles_per_second = 0;
+static long long int start_cycle;
+void gpr_precise_clock_init(void) {
+  time_t start;
+  long long end_cycle;
+  gpr_log(GPR_DEBUG, "Calibrating timers");
+  start = time(NULL);
+  while (time(NULL) == start)
+    ;
+  gpr_get_cycle_counter(&start_cycle);
+  while (time(NULL) <= start + 10)
+    ;
+  gpr_get_cycle_counter(&end_cycle);
+  cycles_per_second = (double)(end_cycle - start_cycle) / 10.0;
+  gpr_log(GPR_DEBUG, "... cycles_per_second = %f\n", cycles_per_second);
+}
+
+void gpr_precise_clock_now(gpr_timespec *clk) {
+  long long int counter;
+  double secs;
+  gpr_get_cycle_counter(&counter);
+  secs = (double)(counter - start_cycle) / cycles_per_second;
+  clk->clock_type = GPR_CLOCK_PRECISE;
+  clk->tv_sec = (time_t)secs;
+  clk->tv_nsec = (int)(1e9 * (secs - (double)clk->tv_sec));
+}
+
+#else  /* GRPC_TIMERS_RDTSC */
+void gpr_precise_clock_init(void) {}
+
+void gpr_precise_clock_now(gpr_timespec *clk) {
+  *clk = gpr_now(GPR_CLOCK_REALTIME);
+  clk->clock_type = GPR_CLOCK_PRECISE;
+}
+#endif /* GRPC_TIMERS_RDTSC */
diff --git a/src/core/support/time_precise.h b/src/core/support/time_precise.h
index cd201faab9..80c5000123 100644
--- a/src/core/support/time_precise.h
+++ b/src/core/support/time_precise.h
@@ -34,60 +34,9 @@
 #ifndef GRPC_CORE_SUPPORT_TIME_PRECISE_H_
 #define GRPC_CORE_SUPPORT_TIME_PRECISE_H_
 
-#include <grpc/support/sync.h>
 #include <grpc/support/time.h>
-#include <stdio.h>
 
-#ifdef GRPC_TIMERS_RDTSC
-#if defined(__i386__)
-static void gpr_get_cycle_counter(long long int *clk) {
-  long long int ret;
-  __asm__ volatile("rdtsc" : "=A"(ret));
-  *clk = ret;
-}
-
-// ----------------------------------------------------------------
-#elif defined(__x86_64__) || defined(__amd64__)
-static void gpr_get_cycle_counter(long long int *clk) {
-  unsigned long long low, high;
-  __asm__ volatile("rdtsc" : "=a"(low), "=d"(high));
-  *clk = (high << 32) | low;
-}
-#endif
-
-static gpr_once precise_clock_init = GPR_ONCE_INIT;
-static long long cycles_per_second = 0;
-static void gpr_precise_clock_init() {
-  time_t start = time(NULL);
-  gpr_precise_clock start_cycle;
-  gpr_precise_clock end_cycle;
-  while (time(NULL) == start)
-    ;
-  gpr_get_cycle_counter(&start_cycle);
-  while (time(NULL) == start + 1)
-    ;
-  gpr_get_cycle_counter(&end_cycle);
-  cycles_per_second = end_cycle - start_cycle;
-}
-
-static double grpc_precise_clock_scaling_factor() {
-  gpr_once_init(&precise_clock_init, grpc_precise_clock_init);
-  return 1e6 / cycles_per_second;
-}
-
-static void gpr_precise_clock_now(gpr_timespec *clk) {
-  long long int counter;
-  gpr_get_cycle_counter(&counter);
-  clk->clock = GPR_CLOCK_REALTIME;
-  clk->tv_sec = counter / cycles_per_second;
-  clk->tv_nsec = counter % cycles_per_second;
-}
-
-#else  /* GRPC_TIMERS_RDTSC */
-static void gpr_precise_clock_now(gpr_timespec *clk) {
-  *clk = gpr_now(GPR_CLOCK_REALTIME);
-  clk->clock_type = GPR_CLOCK_PRECISE;
-}
-#endif /* GRPC_TIMERS_RDTSC */
+void gpr_precise_clock_init(void);
+void gpr_precise_clock_now(gpr_timespec *clk);
 
 #endif /* GRPC_CORE_SUPPORT_TIME_PRECISE_ */
diff --git a/src/core/surface/call.c b/src/core/surface/call.c
index 386a4a6b29..b40e74d61b 100644
--- a/src/core/surface/call.c
+++ b/src/core/surface/call.c
@@ -306,8 +306,9 @@ grpc_call *grpc_call_create(grpc_channel *channel, grpc_call *parent_call,
   grpc_transport_stream_op *initial_op_ptr = NULL;
   grpc_channel_stack *channel_stack = grpc_channel_get_channel_stack(channel);
   grpc_exec_ctx exec_ctx = GRPC_EXEC_CTX_INIT;
-  grpc_call *call =
-      gpr_malloc(sizeof(grpc_call) + channel_stack->call_stack_size);
+  grpc_call *call;
+  GPR_TIMER_BEGIN("grpc_call_create", 0);
+  call = gpr_malloc(sizeof(grpc_call) + channel_stack->call_stack_size);
   memset(call, 0, sizeof(grpc_call));
   gpr_mu_init(&call->mu);
   gpr_mu_init(&call->completion_mu);
@@ -401,6 +402,7 @@ grpc_call *grpc_call_create(grpc_channel *channel, grpc_call *parent_call,
     set_deadline_alarm(&exec_ctx, call, send_deadline);
   }
   grpc_exec_ctx_finish(&exec_ctx);
+  GPR_TIMER_END("grpc_call_create", 0);
   return call;
 }
 
@@ -461,6 +463,7 @@ void grpc_call_internal_ref(grpc_call *c) {
 static void destroy_call(grpc_exec_ctx *exec_ctx, grpc_call *call) {
   size_t i;
   grpc_call *c = call;
+  GPR_TIMER_BEGIN("destroy_call", 0);
   grpc_call_stack_destroy(exec_ctx, CALL_STACK_FROM_CALL(c));
   GRPC_CHANNEL_INTERNAL_UNREF(exec_ctx, c->channel, "call");
   gpr_mu_destroy(&c->mu);
@@ -493,6 +496,7 @@ static void destroy_call(grpc_exec_ctx *exec_ctx, grpc_call *call) {
     GRPC_CQ_INTERNAL_UNREF(c->cq, "bind");
   }
   gpr_free(c);
+  GPR_TIMER_END("destroy_call", 0);
 }
 
 #ifdef GRPC_CALL_REF_COUNT_DEBUG
@@ -624,6 +628,8 @@ static void unlock(grpc_exec_ctx *exec_ctx, grpc_call *call) {
   const size_t MAX_RECV_PEEK_AHEAD = 65536;
   size_t buffered_bytes;
 
+  GPR_TIMER_BEGIN("unlock", 0);
+
   memset(&op, 0, sizeof(op));
 
   op.cancel_with_status = call->cancel_with_status;
@@ -694,6 +700,8 @@ static void unlock(grpc_exec_ctx *exec_ctx, grpc_call *call) {
     unlock(exec_ctx, call);
     GRPC_CALL_INTERNAL_UNREF(exec_ctx, call, "completing");
   }
+
+  GPR_TIMER_END("unlock", 0);
 }
 
 static void get_final_status(grpc_call *call, grpc_ioreq_data out) {
@@ -843,6 +851,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;
+  GPR_TIMER_BEGIN("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);
@@ -866,9 +875,11 @@ 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");
+  GPR_TIMER_END("call_on_done_send", 0);
 }
 
 static void finish_message(grpc_call *call) {
+  GPR_TIMER_BEGIN("finish_message", 0);
   if (call->error_status_set == 0) {
     /* TODO(ctiller): this could be a lot faster if coded directly */
     grpc_byte_buffer *byte_buffer;
@@ -888,6 +899,7 @@ static void finish_message(grpc_call *call) {
   gpr_slice_buffer_reset_and_unref(&call->incoming_message);
   GPR_ASSERT(call->incoming_message.count == 0);
   call->reading_message = 0;
+  GPR_TIMER_END("finish_message", 0);
 }
 
 static int begin_message(grpc_call *call, grpc_begin_message msg) {
@@ -977,7 +989,7 @@ static void call_on_done_recv(grpc_exec_ctx *exec_ctx, void *pc, int success) {
   grpc_call *child_call;
   grpc_call *next_child_call;
   size_t i;
-  GRPC_TIMER_BEGIN(GRPC_PTAG_CALL_ON_DONE_RECV, 0);
+  GPR_TIMER_BEGIN("call_on_done_recv", 0);
   lock(call);
   call->receiving = 0;
   if (success) {
@@ -987,13 +999,19 @@ static void call_on_done_recv(grpc_exec_ctx *exec_ctx, void *pc, int success) {
         case GRPC_NO_OP:
           break;
         case GRPC_OP_METADATA:
+          GPR_TIMER_BEGIN("recv_metadata", 0);
           recv_metadata(exec_ctx, call, &op->data.metadata);
+          GPR_TIMER_END("recv_metadata", 0);
           break;
         case GRPC_OP_BEGIN_MESSAGE:
+          GPR_TIMER_BEGIN("begin_message", 0);
           success = begin_message(call, op->data.begin_message);
+          GPR_TIMER_END("begin_message", 0);
           break;
         case GRPC_OP_SLICE:
+          GPR_TIMER_BEGIN("add_slice_to_message", 0);
           success = add_slice_to_message(call, op->data.slice);
+          GPR_TIMER_END("add_slice_to_message", 0);
           break;
       }
     }
@@ -1039,7 +1057,7 @@ static void call_on_done_recv(grpc_exec_ctx *exec_ctx, void *pc, int success) {
   unlock(exec_ctx, call);
 
   GRPC_CALL_INTERNAL_UNREF(exec_ctx, call, "receiving");
-  GRPC_TIMER_END(GRPC_PTAG_CALL_ON_DONE_RECV, 0);
+  GPR_TIMER_END("call_on_done_recv", 0);
 }
 
 static int prepare_application_metadata(grpc_call *call, size_t count,
@@ -1517,16 +1535,25 @@ static void recv_metadata(grpc_exec_ctx *exec_ctx, grpc_call *call,
     grpc_mdelem *mdel = l->md;
     grpc_mdstr *key = mdel->key;
     if (key == grpc_channel_get_status_string(call->channel)) {
+      GPR_TIMER_BEGIN("status", 0);
       set_status_code(call, STATUS_FROM_WIRE, decode_status(mdel));
+      GPR_TIMER_END("status", 0);
     } else if (key == grpc_channel_get_message_string(call->channel)) {
+      GPR_TIMER_BEGIN("status-details", 0);
       set_status_details(call, STATUS_FROM_WIRE, GRPC_MDSTR_REF(mdel->value));
+      GPR_TIMER_END("status-details", 0);
     } else if (key ==
                grpc_channel_get_compression_algorithm_string(call->channel)) {
+      GPR_TIMER_BEGIN("compression_algorithm", 0);
       set_compression_algorithm(call, decode_compression(mdel));
+      GPR_TIMER_END("compression_algorithm", 0);
     } else if (key == grpc_channel_get_encodings_accepted_by_peer_string(
                           call->channel)) {
+      GPR_TIMER_BEGIN("encodings_accepted_by_peer", 0);
       set_encodings_accepted_by_peer(call, mdel->value->slice);
+      GPR_TIMER_END("encodings_accepted_by_peer", 0);
     } else {
+      GPR_TIMER_BEGIN("report_up", 0);
       dest = &call->buffered_metadata[is_trailing];
       if (dest->count == dest->capacity) {
         dest->capacity = GPR_MAX(dest->capacity + 8, dest->capacity * 2);
@@ -1547,12 +1574,15 @@ static void recv_metadata(grpc_exec_ctx *exec_ctx, grpc_call *call,
       }
       call->owned_metadata[call->owned_metadata_count++] = mdel;
       l->md = NULL;
+      GPR_TIMER_END("report_up", 0);
     }
   }
   if (gpr_time_cmp(md->deadline, gpr_inf_future(md->deadline.clock_type)) !=
           0 &&
       !call->is_client) {
+    GPR_TIMER_BEGIN("set_deadline_alarm", 0);
     set_deadline_alarm(exec_ctx, call, md->deadline);
+    GPR_TIMER_END("set_deadline_alarm", 0);
   }
   if (!is_trailing) {
     call->read_state = READ_STATE_GOT_INITIAL_METADATA;
@@ -1615,6 +1645,8 @@ grpc_call_error grpc_call_start_batch(grpc_call *call, const grpc_op *ops,
   grpc_call_error error;
   grpc_exec_ctx exec_ctx = GRPC_EXEC_CTX_INIT;
 
+  GPR_TIMER_BEGIN("grpc_call_start_batch", 0);
+
   GRPC_API_TRACE(
       "grpc_call_start_batch(call=%p, ops=%p, nops=%lu, tag=%p, reserved=%p)",
       5, (call, ops, (unsigned long)nops, tag, reserved));
@@ -1852,6 +1884,7 @@ grpc_call_error grpc_call_start_batch(grpc_call *call, const grpc_op *ops,
                                               finish_func, tag);
 done:
   grpc_exec_ctx_finish(&exec_ctx);
+  GPR_TIMER_END("grpc_call_start_batch", 0);
   return error;
 }
 
diff --git a/src/core/surface/completion_queue.c b/src/core/surface/completion_queue.c
index 9e552c2cdf..bcdb363873 100644
--- a/src/core/surface/completion_queue.c
+++ b/src/core/surface/completion_queue.c
@@ -42,6 +42,7 @@
 #include "src/core/surface/call.h"
 #include "src/core/surface/event_string.h"
 #include "src/core/surface/surface_trace.h"
+#include "src/core/profiling/timers.h"
 #include <grpc/support/alloc.h>
 #include <grpc/support/atm.h>
 #include <grpc/support/log.h>
@@ -143,6 +144,8 @@ void grpc_cq_end_op(grpc_exec_ctx *exec_ctx, grpc_completion_queue *cc,
   int i;
   grpc_pollset_worker *pluck_worker;
 
+  GPR_TIMER_BEGIN("grpc_cq_end_op", 0);
+
   storage->tag = tag;
   storage->done = done;
   storage->done_arg = done_arg;
@@ -174,6 +177,8 @@ void grpc_cq_end_op(grpc_exec_ctx *exec_ctx, grpc_completion_queue *cc,
     gpr_mu_unlock(GRPC_POLLSET_MU(&cc->pollset));
     grpc_pollset_shutdown(exec_ctx, &cc->pollset, &cc->pollset_destroy_done);
   }
+
+  GPR_TIMER_END("grpc_cq_end_op", 0);
 }
 
 grpc_event grpc_completion_queue_next(grpc_completion_queue *cc,
@@ -184,6 +189,8 @@ grpc_event grpc_completion_queue_next(grpc_completion_queue *cc,
   gpr_timespec now;
   grpc_exec_ctx exec_ctx = GRPC_EXEC_CTX_INIT;
 
+  GPR_TIMER_BEGIN("grpc_completion_queue_next", 0);
+
   GRPC_API_TRACE(
       "grpc_completion_queue_next("
       "cc=%p, "
@@ -230,6 +237,9 @@ grpc_event grpc_completion_queue_next(grpc_completion_queue *cc,
   GRPC_SURFACE_TRACE_RETURNED_EVENT(cc, &ret);
   GRPC_CQ_INTERNAL_UNREF(cc, "next");
   grpc_exec_ctx_finish(&exec_ctx);
+
+  GPR_TIMER_END("grpc_completion_queue_next", 0);
+
   return ret;
 }
 
@@ -267,6 +277,8 @@ grpc_event grpc_completion_queue_pluck(grpc_completion_queue *cc, void *tag,
   int first_loop = 1;
   grpc_exec_ctx exec_ctx = GRPC_EXEC_CTX_INIT;
 
+  GPR_TIMER_BEGIN("grpc_completion_queue_pluck", 0);
+
   GRPC_API_TRACE(
       "grpc_completion_queue_pluck("
       "cc=%p, tag=%p, "
@@ -332,6 +344,9 @@ done:
   GRPC_SURFACE_TRACE_RETURNED_EVENT(cc, &ret);
   GRPC_CQ_INTERNAL_UNREF(cc, "pluck");
   grpc_exec_ctx_finish(&exec_ctx);
+
+  GPR_TIMER_END("grpc_completion_queue_pluck", 0);
+
   return ret;
 }
 
diff --git a/src/core/surface/init.c b/src/core/surface/init.c
index 95011cab17..715c90a5e1 100644
--- a/src/core/surface/init.c
+++ b/src/core/surface/init.c
@@ -115,7 +115,7 @@ void grpc_init(void) {
         gpr_log(GPR_ERROR, "Could not initialize census.");
       }
     }
-    grpc_timers_global_init();
+    gpr_timers_global_init();
     for (i = 0; i < g_number_of_plugins; i++) {
       if (g_all_of_the_plugins[i].init != NULL) {
         g_all_of_the_plugins[i].init();
@@ -133,7 +133,7 @@ void grpc_shutdown(void) {
   if (--g_initializations == 0) {
     grpc_iomgr_shutdown();
     census_shutdown();
-    grpc_timers_global_destroy();
+    gpr_timers_global_destroy();
     grpc_tracer_shutdown();
     grpc_resolver_registry_shutdown();
     for (i = 0; i < g_number_of_plugins; i++) {
diff --git a/src/core/transport/chttp2/parsing.c b/src/core/transport/chttp2/parsing.c
index a0977ccaf6..5d4d8e70c4 100644
--- a/src/core/transport/chttp2/parsing.c
+++ b/src/core/transport/chttp2/parsing.c
@@ -35,6 +35,7 @@
 
 #include <string.h>
 
+#include "src/core/profiling/timers.h"
 #include "src/core/transport/chttp2/http2_errors.h"
 #include "src/core/transport/chttp2/status_conversion.h"
 #include "src/core/transport/chttp2/timeout_encoding.h"
@@ -68,6 +69,8 @@ void grpc_chttp2_prepare_to_read(
   grpc_chttp2_stream_global *stream_global;
   grpc_chttp2_stream_parsing *stream_parsing;
 
+  GPR_TIMER_BEGIN("grpc_chttp2_prepare_to_read", 0);
+
   transport_parsing->next_stream_id = transport_global->next_stream_id;
 
   /* update the parsing view of incoming window */
@@ -89,6 +92,8 @@ void grpc_chttp2_prepare_to_read(
       stream_parsing->incoming_window = stream_global->incoming_window;
     }
   }
+
+  GPR_TIMER_END("grpc_chttp2_prepare_to_read", 0);
 }
 
 void grpc_chttp2_publish_reads(
diff --git a/src/core/transport/chttp2/writing.c b/src/core/transport/chttp2/writing.c
index d1c9da6df0..69ad8854ba 100644
--- a/src/core/transport/chttp2/writing.c
+++ b/src/core/transport/chttp2/writing.c
@@ -37,6 +37,7 @@
 
 #include <grpc/support/log.h>
 
+#include "src/core/profiling/timers.h"
 #include "src/core/transport/chttp2/http2_errors.h"
 
 static void finalize_outbuf(grpc_chttp2_transport_writing *transport_writing);
@@ -180,6 +181,8 @@ void grpc_chttp2_perform_writes(
 static void finalize_outbuf(grpc_chttp2_transport_writing *transport_writing) {
   grpc_chttp2_stream_writing *stream_writing;
 
+  GPR_TIMER_BEGIN("finalize_outbuf", 0);
+
   while (
       grpc_chttp2_list_pop_writing_stream(transport_writing, &stream_writing)) {
     if (stream_writing->sopb.nops > 0 ||
@@ -208,6 +211,8 @@ static void finalize_outbuf(grpc_chttp2_transport_writing *transport_writing) {
     }
     grpc_chttp2_list_add_written_stream(transport_writing, stream_writing);
   }
+
+  GPR_TIMER_END("finalize_outbuf", 0);
 }
 
 void grpc_chttp2_cleanup_writing(
diff --git a/src/core/transport/chttp2_transport.c b/src/core/transport/chttp2_transport.c
index de74379546..effc3c4b3b 100644
--- a/src/core/transport/chttp2_transport.c
+++ b/src/core/transport/chttp2_transport.c
@@ -510,6 +510,7 @@ grpc_chttp2_stream_parsing *grpc_chttp2_parsing_accept_stream(
 static void lock(grpc_chttp2_transport *t) { gpr_mu_lock(&t->mu); }
 
 static void unlock(grpc_exec_ctx *exec_ctx, grpc_chttp2_transport *t) {
+  GPR_TIMER_BEGIN("unlock", 0);
   unlock_check_read_write_state(exec_ctx, t);
   if (!t->writing_active && !t->closed &&
       grpc_chttp2_unlocking_check_writes(&t->global, &t->writing)) {
@@ -520,6 +521,7 @@ static void unlock(grpc_exec_ctx *exec_ctx, grpc_chttp2_transport *t) {
   }
 
   gpr_mu_unlock(&t->mu);
+  GPR_TIMER_END("unlock", 0);
 }
 
 /*
@@ -546,6 +548,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);
 
+  GPR_TIMER_BEGIN("grpc_chttp2_terminate_writing", 0);
+
   lock(t);
 
   allow_endpoint_shutdown_locked(exec_ctx, t);
@@ -567,12 +571,16 @@ void grpc_chttp2_terminate_writing(grpc_exec_ctx *exec_ctx,
   unlock(exec_ctx, t);
 
   UNREF_TRANSPORT(exec_ctx, t, "writing");
+
+  GPR_TIMER_END("grpc_chttp2_terminate_writing", 0);
 }
 
 static void writing_action(grpc_exec_ctx *exec_ctx, void *gt,
                            int iomgr_success_ignored) {
   grpc_chttp2_transport *t = gt;
+  GPR_TIMER_BEGIN("writing_action", 0);
   grpc_chttp2_perform_writes(exec_ctx, &t->writing, t->ep);
+  GPR_TIMER_END("writing_action", 0);
 }
 
 void grpc_chttp2_add_incoming_goaway(
@@ -642,6 +650,7 @@ static void maybe_start_some_streams(
 static void perform_stream_op_locked(
     grpc_exec_ctx *exec_ctx, grpc_chttp2_transport_global *transport_global,
     grpc_chttp2_stream_global *stream_global, grpc_transport_stream_op *op) {
+  GPR_TIMER_BEGIN("perform_stream_op_locked", 0);
   if (op->cancel_with_status != GRPC_STATUS_OK) {
     cancel_from_api(transport_global, stream_global, op->cancel_with_status);
   }
@@ -713,6 +722,7 @@ static void perform_stream_op_locked(
   }
 
   grpc_exec_ctx_enqueue(exec_ctx, op->on_consumed, 1);
+  GPR_TIMER_END("perform_stream_op_locked", 0);
 }
 
 static void perform_stream_op(grpc_exec_ctx *exec_ctx, grpc_transport *gt,
@@ -1103,6 +1113,8 @@ static void recv_data(grpc_exec_ctx *exec_ctx, void *tp, int success) {
   int keep_reading = 0;
   grpc_chttp2_transport *t = tp;
 
+  GPR_TIMER_BEGIN("recv_data", 0);
+
   lock(t);
   i = 0;
   GPR_ASSERT(!t->parsing_active);
@@ -1113,11 +1125,13 @@ static void recv_data(grpc_exec_ctx *exec_ctx, void *tp, int success) {
                                      &t->parsing_stream_map);
     grpc_chttp2_prepare_to_read(&t->global, &t->parsing);
     gpr_mu_unlock(&t->mu);
+    GPR_TIMER_BEGIN("recv_data.parse", 0);
     for (; i < t->read_buffer.count &&
                grpc_chttp2_perform_read(exec_ctx, &t->parsing,
                                         t->read_buffer.slices[i]);
          i++)
       ;
+    GPR_TIMER_END("recv_data.parse", 0);
     gpr_mu_lock(&t->mu);
     if (i != t->read_buffer.count) {
       drop_connection(exec_ctx, t);
@@ -1154,6 +1168,8 @@ static void recv_data(grpc_exec_ctx *exec_ctx, void *tp, int success) {
   } else {
     UNREF_TRANSPORT(exec_ctx, t, "recv_data");
   }
+
+  GPR_TIMER_END("recv_data", 0);
 }
 
 /*
diff --git a/src/core/transport/stream_op.c b/src/core/transport/stream_op.c
index 1cb2bd7c59..6493e77bc5 100644
--- a/src/core/transport/stream_op.c
+++ b/src/core/transport/stream_op.c
@@ -38,6 +38,8 @@
 #include <grpc/support/alloc.h>
 #include <grpc/support/log.h>
 
+#include "src/core/profiling/timers.h"
+
 /* Exponential growth function: Given x, return a larger x.
    Currently we grow by 1.5 times upon reallocation. */
 #define GROW(x) (3 * (x) / 2)
@@ -300,6 +302,8 @@ void grpc_metadata_batch_filter(grpc_metadata_batch *batch,
   grpc_linked_mdelem *l;
   grpc_linked_mdelem *next;
 
+  GPR_TIMER_BEGIN("grpc_metadata_batch_filter", 0);
+
   assert_valid_list(&batch->list);
   assert_valid_list(&batch->garbage);
   for (l = batch->list.head; l; l = next) {
@@ -328,4 +332,6 @@ void grpc_metadata_batch_filter(grpc_metadata_batch *batch,
   }
   assert_valid_list(&batch->list);
   assert_valid_list(&batch->garbage);
+
+  GPR_TIMER_END("grpc_metadata_batch_filter", 0);
 }
diff --git a/src/core/tsi/fake_transport_security.c b/src/core/tsi/fake_transport_security.c
index a40268a7f0..99e28ab63b 100644
--- a/src/core/tsi/fake_transport_security.c
+++ b/src/core/tsi/fake_transport_security.c
@@ -121,7 +121,7 @@ static void store32_little_endian(gpr_uint32 value, unsigned char *buf) {
   buf[3] = (unsigned char)((value >> 24) & 0xFF);
   buf[2] = (unsigned char)((value >> 16) & 0xFF);
   buf[1] = (unsigned char)((value >> 8) & 0xFF);
-  buf[0] = (unsigned char)((value) & 0xFF);
+  buf[0] = (unsigned char)((value)&0xFF);
 }
 
 static void tsi_fake_frame_reset(tsi_fake_frame *frame, int needs_draining) {