Timing nuances

src/core/lib/iomgr/combiner.c

@@ -181,6 +181,7 @@ static bool maybe_finish_one(grpc_exec_ctx *exec_ctx, grpc_combiner *lock) {
                       lock);
     grpc_workqueue_enqueue(exec_ctx, lock->optional_workqueue,
                            &lock->continue_finishing, GRPC_ERROR_NONE);
+    GPR_TIMER_END("combiner.maybe_finish_one", 0);
     return false;
   }
   gpr_mpscq_node *n = gpr_mpscq_pop(&lock->queue);

src/core/lib/iomgr/exec_ctx.c

@@ -95,6 +95,7 @@ bool grpc_exec_ctx_flush(grpc_exec_ctx *exec_ctx) {
       GRPC_ERROR_UNREF(error);
       GPR_TIMER_END("grpc_exec_ctx_flush.stolen_cb", 0);
       grpc_exec_ctx_flush(exec_ctx);
+      GPR_TIMER_END("grpc_exec_ctx_flush", 0);
       return true;
     }
   }
@@ -110,6 +111,7 @@ void grpc_exec_ctx_finish(grpc_exec_ctx *exec_ctx) {
 void grpc_exec_ctx_sched(grpc_exec_ctx *exec_ctx, grpc_closure *closure,
                          grpc_error *error,
                          grpc_workqueue *offload_target_or_null) {
+  GPR_TIMER_BEGIN("grpc_exec_ctx_sched", 0);
   if (offload_target_or_null == NULL) {
     grpc_closure_list_append(&exec_ctx->closure_list, closure, error);
   } else if (exec_ctx->stealing_from_workqueue == NULL) {
@@ -127,6 +129,7 @@ void grpc_exec_ctx_sched(grpc_exec_ctx *exec_ctx, grpc_closure *closure,
     exec_ctx->stolen_closure = closure;
     GRPC_WORKQUEUE_UNREF(exec_ctx, offload_target_or_null, "exec_ctx_sched");
   }
+  GPR_TIMER_END("grpc_exec_ctx_sched", 0);
 }
 
 void grpc_exec_ctx_enqueue_list(grpc_exec_ctx *exec_ctx,

src/core/lib/iomgr/tcp_posix.c

@@ -209,11 +209,11 @@ static void tcp_continue_read(grpc_exec_ctx *exec_ctx, grpc_tcp *tcp) {
   msg.msg_controllen = 0;
   msg.msg_flags = 0;
 
-  GPR_TIMER_BEGIN("recvmsg", 1);
+  GPR_TIMER_BEGIN("recvmsg", 0);
   do {
     read_bytes = recvmsg(tcp->fd, &msg, 0);
   } while (read_bytes < 0 && errno == EINTR);
-  GPR_TIMER_END("recvmsg", 0);
+  GPR_TIMER_END("recvmsg", read_bytes >= 0);
 
   if (read_bytes < 0) {
     /* NB: After calling call_read_cb a parallel call of the read handler may

src/core/lib/profiling/basic_timers.c

@@ -83,6 +83,7 @@ static int g_shutdown;
 static gpr_thd_id g_writing_thread;
 static __thread int g_thread_id;
 static int g_next_thread_id;
+static int g_writing_enabled = 1;
 
 static int timer_log_push_back(gpr_timer_log_list *list, gpr_timer_log *log) {
   if (list->head == NULL) {
@@ -177,7 +178,7 @@ static void flush_logs(gpr_timer_log_list *list) {
   }
 }
 
-static void finish_writing() {
+static void finish_writing(void) {
   pthread_mutex_lock(&g_mu);
   g_shutdown = 1;
   pthread_cond_signal(&g_cv);
@@ -230,6 +231,10 @@ static void gpr_timers_log_add(const char *tagstr, marker_type type,
                                int important, const char *file, int line) {
   gpr_timer_entry *entry;
 
+  if (!g_writing_enabled) {
+    return;
+  }
+
   if (g_thread_log == NULL || g_thread_log->num_entries == MAX_COUNT) {
     rotate_log();
   }
@@ -261,6 +266,8 @@ void gpr_timer_end(const char *tagstr, int important, const char *file,
   gpr_timers_log_add(tagstr, END, important, file, line);
 }
 
+void gpr_timer_set_enabled(int enabled) { g_writing_enabled = enabled; }
+
 /* Basic profiler specific API functions. */
 void gpr_timers_global_init(void) {}
 
@@ -272,4 +279,6 @@ void gpr_timers_global_init(void) {}
 void gpr_timers_global_destroy(void) {}
 
 void gpr_timers_set_log_filename(const char *filename) {}
+
+void gpr_timer_set_enabled(int enabled) {}
 #endif /* GRPC_BASIC_PROFILER */

src/core/lib/profiling/timers.h

@@ -50,6 +50,8 @@ void gpr_timer_end(const char *tagstr, int important, const char *file,
 
 void gpr_timers_set_log_filename(const char *filename);
 
+void gpr_timer_set_enabled(int enabled);
+
 #if !(defined(GRPC_STAP_PROFILER) + defined(GRPC_BASIC_PROFILER))
 /* No profiling. No-op all the things. */
 #define GPR_TIMER_MARK(tag, important) \

src/core/lib/surface/completion_queue.c

@@ -335,7 +335,7 @@ static bool cq_is_next_finished(grpc_exec_ctx *exec_ctx, void *arg) {
     return true;
   }
   gpr_mu_unlock(cq->mu);
-  return gpr_time_cmp(a->deadline, gpr_now(a->deadline.clock_type)) > 0;
+  return gpr_time_cmp(a->deadline, gpr_now(a->deadline.clock_type)) < 0;
 }
 
 grpc_event grpc_completion_queue_next(grpc_completion_queue *cc,
@@ -484,7 +484,7 @@ static bool cq_is_pluck_finished(grpc_exec_ctx *exec_ctx, void *arg) {
     prev = c;
   }
   gpr_mu_unlock(cq->mu);
-  return gpr_time_cmp(a->deadline, gpr_now(a->deadline.clock_type)) > 0;
+  return gpr_time_cmp(a->deadline, gpr_now(a->deadline.clock_type)) < 0;
 }
 
 grpc_event grpc_completion_queue_pluck(grpc_completion_queue *cc, void *tag,

test/cpp/qps/driver.cc

@@ -45,6 +45,7 @@
 #include <grpc/support/host_port.h>
 #include <grpc/support/log.h>
 
+#include "src/core/lib/profiling/timers.h"
 #include "src/core/lib/support/env.h"
 #include "src/proto/grpc/testing/services.grpc.pb.h"
 #include "test/core/util/port.h"
@@ -405,6 +406,8 @@ std::unique_ptr<ScenarioResult> RunScenario(
       start,
       gpr_time_from_seconds(warmup_seconds + benchmark_seconds, GPR_TIMESPAN)));
 
+  gpr_timer_set_enabled(0);
+
   // Finish a run
   std::unique_ptr<ScenarioResult> result(new ScenarioResult);
   Histogram merged_latencies;