From ca045622867d4b26ebcd72d85a113ad5d6edd670 Mon Sep 17 00:00:00 2001 From: Craig Tiller Date: Tue, 9 Aug 2016 08:38:03 -0700 Subject: [PATCH] Timing nuances --- src/core/lib/iomgr/combiner.c | 1 + src/core/lib/iomgr/exec_ctx.c | 3 +++ src/core/lib/iomgr/tcp_posix.c | 4 ++-- src/core/lib/profiling/basic_timers.c | 11 ++++++++++- src/core/lib/profiling/timers.h | 2 ++ src/core/lib/surface/completion_queue.c | 4 ++-- test/cpp/qps/driver.cc | 3 +++ 7 files changed, 23 insertions(+), 5 deletions(-) diff --git a/src/core/lib/iomgr/combiner.c b/src/core/lib/iomgr/combiner.c index 1042cd86593..946cfc65fce 100644 --- a/src/core/lib/iomgr/combiner.c +++ b/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); diff --git a/src/core/lib/iomgr/exec_ctx.c b/src/core/lib/iomgr/exec_ctx.c index 450cf3aa93b..12e51ac0922 100644 --- a/src/core/lib/iomgr/exec_ctx.c +++ b/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, diff --git a/src/core/lib/iomgr/tcp_posix.c b/src/core/lib/iomgr/tcp_posix.c index 92767721d5d..caaed23212d 100644 --- a/src/core/lib/iomgr/tcp_posix.c +++ b/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 diff --git a/src/core/lib/profiling/basic_timers.c b/src/core/lib/profiling/basic_timers.c index 51813d04617..bdf9af2339c 100644 --- a/src/core/lib/profiling/basic_timers.c +++ b/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 */ diff --git a/src/core/lib/profiling/timers.h b/src/core/lib/profiling/timers.h index c8567e81372..621cdbf6569 100644 --- a/src/core/lib/profiling/timers.h +++ b/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) \ diff --git a/src/core/lib/surface/completion_queue.c b/src/core/lib/surface/completion_queue.c index 47f53f7ad22..2412f78a064 100644 --- a/src/core/lib/surface/completion_queue.c +++ b/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, diff --git a/test/cpp/qps/driver.cc b/test/cpp/qps/driver.cc index 2aeaea51f25..7db99629d4c 100644 --- a/test/cpp/qps/driver.cc +++ b/test/cpp/qps/driver.cc @@ -45,6 +45,7 @@ #include #include +#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 RunScenario( start, gpr_time_from_seconds(warmup_seconds + benchmark_seconds, GPR_TIMESPAN))); + gpr_timer_set_enabled(0); + // Finish a run std::unique_ptr result(new ScenarioResult); Histogram merged_latencies;