Mark activation for read, write, and time spent in system calls

1 files changed, 11 insertions, 0 deletions

diff --git a/src/core/iomgr/tcp_posix.c b/src/core/iomgr/tcp_posix.c
index 597a2a62d3..20df6d1b01 100644
--- a/src/core/iomgr/tcp_posix.c
+++ b/src/core/iomgr/tcp_posix.c
@@ -46,6 +46,7 @@
 
 #include "src/core/support/string.h"
 #include "src/core/debug/trace.h"
+#include "src/core/profiling/timers.h"
 #include <grpc/support/alloc.h>
 #include <grpc/support/log.h>
 #include <grpc/support/slice.h>
@@ -326,6 +327,7 @@ static void grpc_tcp_handle_read(void *arg /* grpc_tcp */, int success) {
   gpr_slice *final_slices;
   size_t final_nslices;
 
+  GRPC_TIMER_MARK(HANDLE_READ_BEGIN, 0);
   slice_state_init(&read_state, static_read_slices, INLINE_SLICE_BUFFER_SIZE,
                    0);
 
@@ -348,9 +350,11 @@ static void grpc_tcp_handle_read(void *arg /* grpc_tcp */, int success) {
     msg.msg_controllen = 0;
     msg.msg_flags = 0;
 
+    GRPC_TIMER_MARK(RECVMSG_BEGIN, 0);
     do {
       read_bytes = recvmsg(tcp->fd, &msg, 0);
     } while (read_bytes < 0 && errno == EINTR);
+    GRPC_TIMER_MARK(RECVMSG_END, 0);
 
     if (read_bytes < allocated_bytes) {
       /* TODO(klempner): Consider a second read first, in hopes of getting a
@@ -402,6 +406,7 @@ static void grpc_tcp_handle_read(void *arg /* grpc_tcp */, int success) {
       ++iov_size;
     }
   }
+  GRPC_TIMER_MARK(HANDLE_READ_BEGIN, 0);
 }
 
 static void grpc_tcp_notify_on_read(grpc_endpoint *ep, grpc_endpoint_read_cb cb,
@@ -433,10 +438,12 @@ static grpc_endpoint_write_status grpc_tcp_flush(grpc_tcp *tcp) {
     msg.msg_controllen = 0;
     msg.msg_flags = 0;
 
+    GRPC_TIMER_MARK(SENDMSG_BEGIN, 0);
     do {
       /* TODO(klempner): Cork if this is a partial write */
       sent_length = sendmsg(tcp->fd, &msg, 0);
     } while (sent_length < 0 && errno == EINTR);
+    GRPC_TIMER_MARK(SENDMSG_END, 0);
 
     if (sent_length < 0) {
       if (errno == EAGAIN) {
@@ -472,6 +479,7 @@ static void grpc_tcp_handle_write(void *arg /* grpc_tcp */, int success) {
     return;
   }
 
+  GRPC_TIMER_MARK(CB_WRITE_BEGIN, 0);
   write_status = grpc_tcp_flush(tcp);
   if (write_status == GRPC_ENDPOINT_WRITE_PENDING) {
     grpc_fd_notify_on_write(tcp->em_fd, &tcp->write_closure);
@@ -487,6 +495,7 @@ static void grpc_tcp_handle_write(void *arg /* grpc_tcp */, int success) {
     cb(tcp->write_user_data, cb_status);
     grpc_tcp_unref(tcp);
   }
+  GRPC_TIMER_MARK(CB_WRITE_END, 0);
 }
 
 static grpc_endpoint_write_status grpc_tcp_write(grpc_endpoint *ep,
@@ -509,6 +518,7 @@ static grpc_endpoint_write_status grpc_tcp_write(grpc_endpoint *ep,
     }
   }
 
+  GRPC_TIMER_MARK(WRITE_BEGIN, 0);
   GPR_ASSERT(tcp->write_cb == NULL);
   slice_state_init(&tcp->write_state, slices, nslices, nslices);
 
@@ -522,6 +532,7 @@ static grpc_endpoint_write_status grpc_tcp_write(grpc_endpoint *ep,
     grpc_fd_notify_on_write(tcp->em_fd, &tcp->write_closure);
   }
 
+  GRPC_TIMER_MARK(WRITE_END, 0);
   return status;
 }