From 1904f2ae30d0f555a309f1c70d15af4fb554613b Mon Sep 17 00:00:00 2001 From: Santiago Gimeno Date: Wed, 26 Nov 2025 15:10:34 +0100 Subject: [PATCH] src: use monotonic clock for timestamps Replace scattered wall-clock timestamp calls (system_clock::now(), GetCurrentTimeInMicroseconds(), ms_since_epoch()) with a couple of current_timestamp_ns(), current_timestamp_ms() utilities that anchor to epoch time at process start and uses uv_hrtime() for elapsed time. Benefits: - Monotonicity: timestamps never jump backward due to NTP adjustments, VM migrations, or manual clock changes - Consistency: all metrics, traces, and agent protocol messages use the same time source - Precision: nanosecond resolution from uv_hrtime() - Performance: uv_hrtime() uses vDSO-accelerated clock_gettime() on Linux, avoiding syscall overhead on each timestamp The approach trusts the system clock once at startup, then relies on the monotonic high-resolution timer. This is preferable for observability data where ordering and rate calculations matter more than tracking real-time clock drift. Refactored current_timestamp_ns() to cache the offset between epoch and hrtime at startup, reducing per-call overhead to a single addition. --- agents/grpc/src/grpc_agent.cc | 28 ++++++++-------------------- agents/zmq/src/zmq_agent.cc | 21 +++++++-------------- agents/zmq/src/zmq_agent.h | 5 +---- src/nsolid.cc | 3 +-- src/nsolid/nsolid_api.cc | 12 +++--------- src/nsolid/nsolid_trace.cc | 4 ++-- src/nsolid/nsolid_util.h | 18 ++++++++++++------ 7 files changed, 34 insertions(+), 57 deletions(-) diff --git a/agents/grpc/src/grpc_agent.cc b/agents/grpc/src/grpc_agent.cc index be0593b9fde..54f598147ca 100644 --- a/agents/grpc/src/grpc_agent.cc +++ b/agents/grpc/src/grpc_agent.cc @@ -22,8 +22,6 @@ #include "opentelemetry/exporters/otlp/otlp_grpc_metric_exporter_factory.h" #include "opentelemetry/exporters/otlp/otlp_metric_utils.h" -using std::chrono::system_clock; -using std::chrono::time_point; using google::protobuf::Arena; using google::protobuf::ArenaOptions; using json = nlohmann::json; @@ -78,15 +76,10 @@ JSThreadMetrics::JSThreadMetrics(SharedEnvInst envinst): metrics_(ThreadMetrics::Create(envinst)) { } -std::pair -create_recorded(const time_point& ts) { - using std::chrono::duration_cast; - using std::chrono::seconds; - using std::chrono::nanoseconds; - - system_clock::duration dur = ts.time_since_epoch(); - return { duration_cast(dur).count(), - duration_cast(dur % seconds(1)).count() }; +std::pair create_recorded() { + uint64_t ns = utils::current_timestamp_ns(); + return { static_cast(ns / 1000000000), + static_cast(ns % 1000000000) }; } ErrorStor fill_error_stor(const ErrorType& type) { @@ -124,7 +117,7 @@ void PopulateCommon(grpcagent::CommonResponse* common, const std::string& command, const char* req_id) { common->set_command(command); - auto recorded = create_recorded(system_clock::now()); + auto recorded = create_recorded(); grpcagent::Time* time = common->mutable_recorded(); time->set_seconds(recorded.first); time->set_nanoseconds(recorded.second); @@ -1494,8 +1487,6 @@ void GrpcAgent::got_profile(const ProfileCollector::ProfileQStor& stor) { void GrpcAgent::got_continuous_profile( const ProfileCollector::ProfileQStor& stor) { - static double performance_process_start_timestamp = - performance::performance_process_start_timestamp / 1e3; google::protobuf::Struct metadata; uint64_t thread_id; uint64_t start_timestamp; @@ -1541,12 +1532,9 @@ void GrpcAgent::got_continuous_profile( // Check if the profile is complete bool profileStreamComplete = stor.profile.length() == 0; if (profileStreamComplete) { - uint64_t now = uv_hrtime() - performance::performance_process_start; - uint64_t start = start_timestamp - performance::performance_process_start; - double start_ts = - performance_process_start_timestamp + start / 1e6; - double end_ts = performance_process_start_timestamp + now / 1e6; - uint64_t duration = (now - start) / 1e6; + double end_ts = utils::current_timestamp_ms(); + uint64_t duration = (uv_hrtime() - start_timestamp) / 1000000; + double start_ts = end_ts - duration; // Create complete profile grpcagent::Asset asset; PopulateCommon(asset.mutable_common(), diff --git a/agents/zmq/src/zmq_agent.cc b/agents/zmq/src/zmq_agent.cc index 09287b9843b..7b4526f8bf4 100644 --- a/agents/zmq/src/zmq_agent.cc +++ b/agents/zmq/src/zmq_agent.cc @@ -15,8 +15,6 @@ namespace node { namespace nsolid { -using std::chrono::system_clock; -using std::chrono::time_point; using nlohmann::json; using string_vector = std::vector; using ZmqCommandHandleRes = std::pair; @@ -1077,7 +1075,7 @@ int ZmqAgent::send_command_message(const char* command, const char* request_id, const char* body) { const char* real_body = body ? (strlen(body) ? body : "\"\"") : "null"; - auto recorded = create_recorded(system_clock::now()); + auto recorded = create_recorded(); int r; if (request_id == nullptr) { r = snprintf(msg_buf_, @@ -1517,15 +1515,10 @@ void ZmqAgent::env_metrics_cb(SharedThreadMetrics metrics, ZmqAgent* agent) { ASSERT_EQ(0, agent->metrics_msg_.send()); } -std::pair -ZmqAgent::create_recorded(const time_point& ts) const { - using std::chrono::duration_cast; - using std::chrono::seconds; - using std::chrono::nanoseconds; - - system_clock::duration dur = ts.time_since_epoch(); - return { duration_cast(dur).count(), - duration_cast(dur % seconds(1)).count() }; +std::pair ZmqAgent::create_recorded() const { + uint64_t ns = utils::current_timestamp_ns(); + return { static_cast(ns / 1000000000), + static_cast(ns % 1000000000) }; } ZmqAgent::ZmqCommandError ZmqAgent::create_command_error( @@ -1573,7 +1566,7 @@ ZmqAgent::ZmqCommandError ZmqAgent::create_command_error( void ZmqAgent::send_error_message(const std::string& msg, uint32_t code) { - auto recorded = create_recorded(system_clock::now()); + auto recorded = create_recorded(); int r = snprintf(msg_buf_, msg_size_, MSG_5, @@ -1614,7 +1607,7 @@ void ZmqAgent::send_error_message(const std::string& msg, int ZmqAgent::send_error_command_message(const std::string& req_id, const std::string& command, const ZmqCommandError& err) { - auto recorded = create_recorded(system_clock::now()); + auto recorded = create_recorded(); int r = snprintf(msg_buf_, msg_size_, MSG_4, diff --git a/agents/zmq/src/zmq_agent.h b/agents/zmq/src/zmq_agent.h index efadca4033b..cdc5b8b9f22 100644 --- a/agents/zmq/src/zmq_agent.h +++ b/agents/zmq/src/zmq_agent.h @@ -4,8 +4,6 @@ #include #include #include -// NOLINTNEXTLINE(build/c++11) -#include #include #include #include @@ -534,8 +532,7 @@ class ZmqAgent { void do_stop(); - std::pair create_recorded( - const std::chrono::time_point&) const; + std::pair create_recorded() const; ZmqCommandError create_command_error(const std::string& command, int err) const; diff --git a/src/nsolid.cc b/src/nsolid.cc index 282d35a0f8c..fd0a126feb9 100644 --- a/src/nsolid.cc +++ b/src/nsolid.cc @@ -250,8 +250,7 @@ int ProcessMetrics::Update() { uv_mutex_lock(&stor_lock_); stor_.title = title; stor_.user = user; - stor_.timestamp = duration_cast( - system_clock::now().time_since_epoch()).count(); + stor_.timestamp = utils::current_timestamp_ms(); stor_.uptime = (uv_hrtime() - node::per_process::node_start_time) / NANOS_PER_SEC; stor_.system_uptime = static_cast(system_uptime); diff --git a/src/nsolid/nsolid_api.cc b/src/nsolid/nsolid_api.cc index 484d0420b2e..0c0703ed246 100644 --- a/src/nsolid/nsolid_api.cc +++ b/src/nsolid/nsolid_api.cc @@ -282,10 +282,7 @@ void EnvInst::GetThreadMetrics(ThreadMetrics::MetricsStor* stor) { CHECK_NE(env(), nullptr); stor->current_hrtime_ = uv_hrtime(); - // TODO(trevnorris): Does this work instead of calling ms_since_epoch? - // stor->timestamp = (stor->current_hrtime_ - env()->time_origin()) / 1e6 + - // env()->time_origin_timestamp() / 1e3; - stor->timestamp = utils::ms_since_epoch(); + stor->timestamp = utils::current_timestamp_ms(); stor->thread_id = thread_id(); stor->thread_name = GetThreadName(); stor->active_handles = event_loop()->active_handles; @@ -1434,8 +1431,7 @@ void EnvInst::send_datapoint(MetricsStream::Type type, double value) { double ts = 0; if (has_metrics_stream_hooks_) { - ts = (PERFORMANCE_NOW() - env()->time_origin()) / 1e6 + - env()->time_origin_timestamp() / 1e3; + ts = utils::current_timestamp_ms(); } EnvList::Inst()->datapoints_q_.Enqueue({ thread_id_, ts, type, value }); @@ -2233,13 +2229,11 @@ static void WriteLog(const FunctionCallbackInfo& args) { DCHECK(args[1]->IsUint32()); String::Utf8Value s(args.GetIsolate(), args[0]); std::string ss = *s; - uint64_t nanoseconds = std::chrono::duration_cast( - std::chrono::system_clock::now().time_since_epoch()).count(); // TODO(trevnorris): Allow tracing through this at some point? EnvList::Inst()->WriteLogLine(GetLocalEnvInst(args.GetIsolate()), { ss, args[1].As()->Value(), - nanoseconds, + utils::current_timestamp_ns(), "", "", 0}); diff --git a/src/nsolid/nsolid_trace.cc b/src/nsolid/nsolid_trace.cc index dc36657628d..366b2fd3c73 100644 --- a/src/nsolid/nsolid_trace.cc +++ b/src/nsolid/nsolid_trace.cc @@ -201,7 +201,7 @@ void TracerImpl::addSpanItem(const SpanItem& item) { void TracerImpl::endPendingSpans() { int r = nsolid::QueueCallback(+[](TracerImpl* tracer) { - double now = GetCurrentTimeInMicroseconds() / 1000; + double now = utils::current_timestamp_ms(); for (auto& item : tracer->pending_spans_) { auto& span = item.second; span.stor_.end_reason = Tracer::kSpanEndExit; @@ -280,7 +280,7 @@ void TracerImpl::update_flags() { void TracerImpl::expired_span_cb_(Span span, TracerImpl* tracer) { span.stor_.end_reason = Tracer::kSpanEndExpired; - span.stor_.end = GetCurrentTimeInMicroseconds() / 1000; + span.stor_.end = utils::current_timestamp_ms(); span.stor_.attrs.pop_back(); span.stor_.attrs += "}"; tracer->trace_hook_list_.for_each([&](auto& stor) { diff --git a/src/nsolid/nsolid_util.h b/src/nsolid/nsolid_util.h index 460a762aa6a..01dfcb03cd1 100644 --- a/src/nsolid/nsolid_util.h +++ b/src/nsolid/nsolid_util.h @@ -16,6 +16,7 @@ #include "uv.h" #include "nlohmann/json.hpp" +#include "node_perf_common.h" using string_vector = std::vector; using json = nlohmann::json; @@ -128,12 +129,17 @@ inline const std::string generate_unique_id() { } -inline uint64_t ms_since_epoch() { - using std::chrono::duration_cast; - using std::chrono::milliseconds; - using std::chrono::system_clock; - system_clock::duration dur = system_clock::now().time_since_epoch(); - return duration_cast(dur).count(); +inline uint64_t current_timestamp_ns() { + // Offset = epoch_ns_at_start - hrtime_at_start + // So: epoch_ns_now = offset + hrtime_now + static uint64_t offset = + static_cast(performance::performance_process_start_timestamp * + 1000) - performance::performance_process_start; + return offset + uv_hrtime(); +} + +inline double current_timestamp_ms() { + return static_cast(current_timestamp_ns()) / 1000000; }