Merge pull request #19907 from soheilhy/call-cycle-clock

Use cycle clock instead of clock monotonic to measure call latency.

src/core/ext/filters/client_channel/client_channel.cc

@@ -720,7 +720,7 @@ class CallData {
   grpc_deadline_state deadline_state_;
 
   grpc_slice path_;  // Request path.
-  gpr_timespec call_start_time_;
+  gpr_cycle_counter call_start_time_;
   grpc_millis deadline_;
   Arena* arena_;
   grpc_call_stack* owning_call_;
@@ -3730,7 +3730,7 @@ void CallData::ApplyServiceConfigToCallLocked(grpc_call_element* elem) {
     // from the client API, reset the deadline timer.
     if (chand->deadline_checking_enabled() && method_params_->timeout() != 0) {
       const grpc_millis per_method_deadline =
-          grpc_timespec_to_millis_round_up(call_start_time_) +
+          grpc_cycle_counter_to_millis_round_up(call_start_time_) +
           method_params_->timeout();
       if (per_method_deadline < deadline_) {
         deadline_ = per_method_deadline;

src/core/ext/filters/client_channel/health/health_check_client.cc

@@ -304,8 +304,8 @@ void HealthCheckClient::CallState::StartCall() {
       health_check_client_->connected_subchannel_,
       &pollent_,
       GRPC_MDSTR_SLASH_GRPC_DOT_HEALTH_DOT_V1_DOT_HEALTH_SLASH_WATCH,
-      gpr_now(GPR_CLOCK_MONOTONIC),  // start_time
-      GRPC_MILLIS_INF_FUTURE,        // deadline
+      gpr_get_cycle_counter(),  // start_time
+      GRPC_MILLIS_INF_FUTURE,   // deadline
       arena_,
       context_,
       &call_combiner_,

src/core/ext/filters/client_channel/subchannel.h

@@ -26,6 +26,7 @@
 #include "src/core/ext/filters/client_channel/subchannel_pool_interface.h"
 #include "src/core/lib/backoff/backoff.h"
 #include "src/core/lib/channel/channel_stack.h"
+#include "src/core/lib/gpr/time_precise.h"
 #include "src/core/lib/gprpp/arena.h"
 #include "src/core/lib/gprpp/map.h"
 #include "src/core/lib/gprpp/ref_counted.h"
@@ -104,7 +105,7 @@ class SubchannelCall {
     RefCountedPtr<ConnectedSubchannel> connected_subchannel;
     grpc_polling_entity* pollent;
     grpc_slice path;
-    gpr_timespec start_time;
+    gpr_cycle_counter start_time;
     grpc_millis deadline;
     Arena* arena;
     grpc_call_context_element* context;

src/core/lib/channel/channel_stack.h

@@ -42,6 +42,7 @@
 #include <grpc/support/time.h>
 
 #include "src/core/lib/debug/trace.h"
+#include "src/core/lib/gpr/time_precise.h"
 #include "src/core/lib/gprpp/arena.h"
 #include "src/core/lib/iomgr/call_combiner.h"
 #include "src/core/lib/iomgr/polling_entity.h"
@@ -67,7 +68,7 @@ typedef struct {
   const void* server_transport_data;
   grpc_call_context_element* context;
   const grpc_slice& path;
-  gpr_timespec start_time;
+  gpr_cycle_counter start_time;
   grpc_millis deadline;
   grpc_core::Arena* arena;
   grpc_core::CallCombiner* call_combiner;

src/core/lib/gpr/time_precise.cc

@@ -113,7 +113,8 @@ void gpr_precise_clock_init(void) {
 }
 
 gpr_timespec gpr_cycle_counter_to_time(gpr_cycle_counter cycles) {
-  double secs = static_cast<double>(cycles - start_cycle) / cycles_per_second;
+  const double secs =
+      static_cast<double>(cycles - start_cycle) / cycles_per_second;
   gpr_timespec ts;
   ts.tv_sec = static_cast<int64_t>(secs);
   ts.tv_nsec = static_cast<int32_t>(GPR_NS_PER_SEC *
@@ -122,6 +123,16 @@ gpr_timespec gpr_cycle_counter_to_time(gpr_cycle_counter cycles) {
   return ts;
 }
 
+gpr_timespec gpr_cycle_counter_sub(gpr_cycle_counter a, gpr_cycle_counter b) {
+  const double secs = static_cast<double>(a - b) / cycles_per_second;
+  gpr_timespec ts;
+  ts.tv_sec = static_cast<int64_t>(secs);
+  ts.tv_nsec = static_cast<int32_t>(GPR_NS_PER_SEC *
+                                    (secs - static_cast<double>(ts.tv_sec)));
+  ts.clock_type = GPR_TIMESPAN;
+  return ts;
+}
+
 void gpr_precise_clock_now(gpr_timespec* clk) {
   int64_t counter = gpr_get_cycle_counter();
   *clk = gpr_cycle_counter_to_time(counter);
@@ -146,4 +157,9 @@ void gpr_precise_clock_now(gpr_timespec* clk) {
   *clk = gpr_now(GPR_CLOCK_REALTIME);
   clk->clock_type = GPR_CLOCK_PRECISE;
 }
+
+gpr_timespec gpr_cycle_counter_sub(gpr_cycle_counter a, gpr_cycle_counter b) {
+  return gpr_time_sub(gpr_cycle_counter_to_time(a),
+                      gpr_cycle_counter_to_time(b));
+}
 #endif /* GPR_CYCLE_COUNTER_FALLBACK */

src/core/lib/gpr/time_precise.h

@@ -61,5 +61,6 @@ gpr_cycle_counter gpr_get_cycle_counter();
 void gpr_precise_clock_init(void);
 void gpr_precise_clock_now(gpr_timespec* clk);
 gpr_timespec gpr_cycle_counter_to_time(gpr_cycle_counter cycles);
+gpr_timespec gpr_cycle_counter_sub(gpr_cycle_counter a, gpr_cycle_counter b);
 
 #endif /* GRPC_CORE_LIB_GPR_TIME_PRECISE_H */

src/core/lib/iomgr/exec_ctx.cc

@@ -52,9 +52,9 @@ static void exec_ctx_sched(grpc_closure* closure, grpc_error* error) {
 }
 
 static gpr_timespec g_start_time;
+static gpr_cycle_counter g_start_cycle;
 
-static grpc_millis timespec_to_millis_round_down(gpr_timespec ts) {
-  ts = gpr_time_sub(ts, g_start_time);
+static grpc_millis timespan_to_millis_round_down(gpr_timespec ts) {
   double x = GPR_MS_PER_SEC * static_cast<double>(ts.tv_sec) +
              static_cast<double>(ts.tv_nsec) / GPR_NS_PER_MS;
   if (x < 0) return 0;
@@ -62,8 +62,11 @@ static grpc_millis timespec_to_millis_round_down(gpr_timespec ts) {
   return static_cast<grpc_millis>(x);
 }
 
-static grpc_millis timespec_to_millis_round_up(gpr_timespec ts) {
-  ts = gpr_time_sub(ts, g_start_time);
+static grpc_millis timespec_to_millis_round_down(gpr_timespec ts) {
+  return timespan_to_millis_round_down(gpr_time_sub(ts, g_start_time));
+}
+
+static grpc_millis timespan_to_millis_round_up(gpr_timespec ts) {
   double x = GPR_MS_PER_SEC * static_cast<double>(ts.tv_sec) +
              static_cast<double>(ts.tv_nsec) / GPR_NS_PER_MS +
              static_cast<double>(GPR_NS_PER_SEC - 1) /
@@ -73,6 +76,10 @@ static grpc_millis timespec_to_millis_round_up(gpr_timespec ts) {
   return static_cast<grpc_millis>(x);
 }
 
+static grpc_millis timespec_to_millis_round_up(gpr_timespec ts) {
+  return timespan_to_millis_round_up(gpr_time_sub(ts, g_start_time));
+}
+
 gpr_timespec grpc_millis_to_timespec(grpc_millis millis,
                                      gpr_clock_type clock_type) {
   // special-case infinities as grpc_millis can be 32bit on some platforms
@@ -101,6 +108,16 @@ grpc_millis grpc_timespec_to_millis_round_up(gpr_timespec ts) {
       gpr_convert_clock_type(ts, g_start_time.clock_type));
 }
 
+grpc_millis grpc_cycle_counter_to_millis_round_down(gpr_cycle_counter cycles) {
+  return timespan_to_millis_round_down(
+      gpr_cycle_counter_sub(cycles, g_start_cycle));
+}
+
+grpc_millis grpc_cycle_counter_to_millis_round_up(gpr_cycle_counter cycles) {
+  return timespan_to_millis_round_up(
+      gpr_cycle_counter_sub(cycles, g_start_cycle));
+}
+
 static const grpc_closure_scheduler_vtable exec_ctx_scheduler_vtable = {
     exec_ctx_run, exec_ctx_sched, "exec_ctx"};
 static grpc_closure_scheduler exec_ctx_scheduler = {&exec_ctx_scheduler_vtable};
@@ -117,7 +134,13 @@ void ExecCtx::TestOnlyGlobalInit(gpr_timespec new_val) {
 }
 
 void ExecCtx::GlobalInit(void) {
+  // gpr_now(GPR_CLOCK_MONOTONIC) incurs a syscall. We don't actually know the
+  // exact cycle the time was captured, so we use the average of cycles before
+  // and after the syscall as the starting cycle.
+  const gpr_cycle_counter cycle_before = gpr_get_cycle_counter();
   g_start_time = gpr_now(GPR_CLOCK_MONOTONIC);
+  const gpr_cycle_counter cycle_after = gpr_get_cycle_counter();
+  g_start_cycle = (cycle_before + cycle_after) / 2;
   gpr_tls_init(&exec_ctx_);
 }
 

src/core/lib/iomgr/exec_ctx.h

@@ -26,6 +26,7 @@
 #include <grpc/support/cpu.h>
 #include <grpc/support/log.h>
 
+#include "src/core/lib/gpr/time_precise.h"
 #include "src/core/lib/gpr/tls.h"
 #include "src/core/lib/gprpp/fork.h"
 #include "src/core/lib/iomgr/closure.h"
@@ -58,6 +59,8 @@ extern grpc_closure_scheduler* grpc_schedule_on_exec_ctx;
 gpr_timespec grpc_millis_to_timespec(grpc_millis millis, gpr_clock_type clock);
 grpc_millis grpc_timespec_to_millis_round_down(gpr_timespec timespec);
 grpc_millis grpc_timespec_to_millis_round_up(gpr_timespec timespec);
+grpc_millis grpc_cycle_counter_to_millis_round_down(gpr_cycle_counter cycles);
+grpc_millis grpc_cycle_counter_to_millis_round_up(gpr_cycle_counter cycles);
 
 namespace grpc_core {
 /** Execution context.

src/core/lib/surface/call.cc

@@ -36,6 +36,7 @@
 #include "src/core/lib/debug/stats.h"
 #include "src/core/lib/gpr/alloc.h"
 #include "src/core/lib/gpr/string.h"
+#include "src/core/lib/gpr/time_precise.h"
 #include "src/core/lib/gpr/useful.h"
 #include "src/core/lib/gprpp/arena.h"
 #include "src/core/lib/gprpp/manual_constructor.h"
@@ -154,7 +155,7 @@ struct grpc_call {
   grpc_completion_queue* cq;
   grpc_polling_entity pollent;
   grpc_channel* channel;
-  gpr_timespec start_time = gpr_now(GPR_CLOCK_MONOTONIC);
+  gpr_cycle_counter start_time = gpr_get_cycle_counter();
   /* parent_call* */ gpr_atm parent_call_atm = 0;
   child_call* child = nullptr;
 
@@ -552,8 +553,7 @@ static void destroy_call(void* call, grpc_error* error) {
                         &(c->final_info.error_string));
   GRPC_ERROR_UNREF(status_error);
   c->final_info.stats.latency =
-      gpr_time_sub(gpr_now(GPR_CLOCK_MONOTONIC), c->start_time);
-
+      gpr_cycle_counter_sub(gpr_get_cycle_counter(), c->start_time);
   grpc_call_stack_destroy(CALL_STACK_FROM_CALL(c), &c->final_info,
                           GRPC_CLOSURE_INIT(&c->release_call, release_call, c,
                                             grpc_schedule_on_exec_ctx));

test/core/channel/channel_stack_test.cc

@@ -117,14 +117,14 @@ static void test_create_channel_stack(void) {
   call_stack =
       static_cast<grpc_call_stack*>(gpr_malloc(channel_stack->call_stack_size));
   const grpc_call_element_args args = {
-      call_stack,                   /* call_stack */
-      nullptr,                      /* server_transport_data */
-      nullptr,                      /* context */
-      path,                         /* path */
-      gpr_now(GPR_CLOCK_MONOTONIC), /* start_time */
-      GRPC_MILLIS_INF_FUTURE,       /* deadline */
-      nullptr,                      /* arena */
-      nullptr,                      /* call_combiner */
+      call_stack,              /* call_stack */
+      nullptr,                 /* server_transport_data */
+      nullptr,                 /* context */
+      path,                    /* path */
+      gpr_get_cycle_counter(), /* start_time */
+      GRPC_MILLIS_INF_FUTURE,  /* deadline */
+      nullptr,                 /* arena */
+      nullptr,                 /* call_combiner */
   };
   grpc_error* error =
       grpc_call_stack_init(channel_stack, 1, free_call, call_stack, &args);

test/core/end2end/tests/filter_latency.cc

@@ -122,7 +122,7 @@ static void test_request(grpc_end2end_test_config config) {
   g_client_latency = gpr_time_0(GPR_TIMESPAN);
   g_server_latency = gpr_time_0(GPR_TIMESPAN);
   gpr_mu_unlock(&g_mu);
-  const gpr_timespec start_time = gpr_now(GPR_CLOCK_MONOTONIC);
+  const gpr_timespec start_time = gpr_now(GPR_CLOCK_REALTIME);
 
   gpr_timespec deadline = five_seconds_from_now();
   c = grpc_channel_create_call(f.client, nullptr, GRPC_PROPAGATE_DEFAULTS, f.cq,
@@ -224,7 +224,7 @@ static void test_request(grpc_end2end_test_config config) {
   end_test(&f);
   config.tear_down_data(&f);
 
-  const gpr_timespec end_time = gpr_now(GPR_CLOCK_MONOTONIC);
+  const gpr_timespec end_time = gpr_now(GPR_CLOCK_REALTIME);
   const gpr_timespec max_latency = gpr_time_sub(end_time, start_time);
 
   // Perform checks after test tear-down

test/cpp/microbenchmarks/bm_call_create.cc

@@ -523,7 +523,7 @@ static void BM_IsolatedFilter(benchmark::State& state) {
   grpc_call_stack* call_stack =
       static_cast<grpc_call_stack*>(gpr_zalloc(channel_stack->call_stack_size));
   grpc_millis deadline = GRPC_MILLIS_INF_FUTURE;
-  gpr_timespec start_time = gpr_now(GPR_CLOCK_MONOTONIC);
+  gpr_cycle_counter start_time = gpr_get_cycle_counter();
   grpc_slice method = grpc_slice_from_static_string("/foo/bar");
   grpc_call_final_info final_info;
   TestOp test_op_data;