diff --git a/src/core/ext/filters/client_channel/client_channel.cc b/src/core/ext/filters/client_channel/client_channel.cc
index 40ac1f22059..0a9b5ac43fb 100644
--- a/src/core/ext/filters/client_channel/client_channel.cc
+++ b/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;
diff --git a/src/core/ext/filters/client_channel/health/health_check_client.cc b/src/core/ext/filters/client_channel/health/health_check_client.cc
index 026831645c0..2662d8466b6 100644
--- a/src/core/ext/filters/client_channel/health/health_check_client.cc
+++ b/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_,
diff --git a/src/core/ext/filters/client_channel/subchannel.h b/src/core/ext/filters/client_channel/subchannel.h
index d745bc8ddc2..c178401ca8a 100644
--- a/src/core/ext/filters/client_channel/subchannel.h
+++ b/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;
diff --git a/src/core/lib/channel/channel_stack.h b/src/core/lib/channel/channel_stack.h
index a7c28d059f3..f7be806b695 100644
--- a/src/core/lib/channel/channel_stack.h
+++ b/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;
diff --git a/src/core/lib/gpr/time_precise.cc b/src/core/lib/gpr/time_precise.cc
index 9d11c66831c..3223a84c7ad 100644
--- a/src/core/lib/gpr/time_precise.cc
+++ b/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 */
diff --git a/src/core/lib/gpr/time_precise.h b/src/core/lib/gpr/time_precise.h
index ce16bafab2d..55eceb6c8ba 100644
--- a/src/core/lib/gpr/time_precise.h
+++ b/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 */
diff --git a/src/core/lib/iomgr/exec_ctx.cc b/src/core/lib/iomgr/exec_ctx.cc
index a847b4dcefc..730237a250d 100644
--- a/src/core/lib/iomgr/exec_ctx.cc
+++ b/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_);
}
diff --git a/src/core/lib/iomgr/exec_ctx.h b/src/core/lib/iomgr/exec_ctx.h
index daf019c41ee..0ccf2a878bf 100644
--- a/src/core/lib/iomgr/exec_ctx.h
+++ b/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.
diff --git a/src/core/lib/surface/call.cc b/src/core/lib/surface/call.cc
index 689281a9393..3720fad8e94 100644
--- a/src/core/lib/surface/call.cc
+++ b/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));
diff --git a/test/core/channel/channel_stack_test.cc b/test/core/channel/channel_stack_test.cc
index 14726336f92..3f15a0010bd 100644
--- a/test/core/channel/channel_stack_test.cc
+++ b/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);
diff --git a/test/core/end2end/tests/filter_latency.cc b/test/core/end2end/tests/filter_latency.cc
index a89db7b094b..85de58a3d20 100644
--- a/test/core/end2end/tests/filter_latency.cc
+++ b/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
diff --git a/test/cpp/microbenchmarks/bm_call_create.cc b/test/cpp/microbenchmarks/bm_call_create.cc
index 99ea1e053e9..e3c853d4430 100644
--- a/test/cpp/microbenchmarks/bm_call_create.cc
+++ b/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;