Skip to content

Commit fdaac9e

Browse files
santigimenosantigimeno
committed
nsolid: use monotonic clock for timestamps
Replace scattered wall-clock timestamp calls (system_clock::now(), GetCurrentTimeInMicroseconds(), ms_since_epoch()) with a single current_timestamp_ns() utility that anchors 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.
1 parent fcab189 commit fdaac9e

7 files changed

Lines changed: 28 additions & 43 deletions

File tree

‎agents/grpc/src/grpc_agent.cc‎

Lines changed: 5 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -78,15 +78,10 @@ JSThreadMetrics::JSThreadMetrics(SharedEnvInst envinst):
7878
metrics_(ThreadMetrics::Create(envinst)) {
7979
}
8080

81-
std::pair<int64_t, int64_t>
82-
create_recorded(const time_point<system_clock>& ts) {
83-
using std::chrono::duration_cast;
84-
using std::chrono::seconds;
85-
using std::chrono::nanoseconds;
86-
87-
system_clock::duration dur = ts.time_since_epoch();
88-
return { duration_cast<seconds>(dur).count(),
89-
duration_cast<nanoseconds>(dur % seconds(1)).count() };
81+
std::pair<int64_t, int64_t> create_recorded() {
82+
uint64_t ns = node::nsolid::utils::current_timestamp_ns();
83+
return { static_cast<int64_t>(ns / 1000000000),
84+
static_cast<int64_t>(ns % 1000000000) };
9085
}
9186

9287
ErrorStor fill_error_stor(const ErrorType& type) {
@@ -124,7 +119,7 @@ void PopulateCommon(grpcagent::CommonResponse* common,
124119
const std::string& command,
125120
const char* req_id) {
126121
common->set_command(command);
127-
auto recorded = create_recorded(system_clock::now());
122+
auto recorded = create_recorded();
128123
grpcagent::Time* time = common->mutable_recorded();
129124
time->set_seconds(recorded.first);
130125
time->set_nanoseconds(recorded.second);

‎agents/zmq/src/zmq_agent.cc‎

Lines changed: 7 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -1077,7 +1077,7 @@ int ZmqAgent::send_command_message(const char* command,
10771077
const char* request_id,
10781078
const char* body) {
10791079
const char* real_body = body ? (strlen(body) ? body : "\"\"") : "null";
1080-
auto recorded = create_recorded(system_clock::now());
1080+
auto recorded = create_recorded();
10811081
int r;
10821082
if (request_id == nullptr) {
10831083
r = snprintf(msg_buf_,
@@ -1517,15 +1517,10 @@ void ZmqAgent::env_metrics_cb(SharedThreadMetrics metrics, ZmqAgent* agent) {
15171517
ASSERT_EQ(0, agent->metrics_msg_.send());
15181518
}
15191519

1520-
std::pair<int64_t, int64_t>
1521-
ZmqAgent::create_recorded(const time_point<system_clock>& ts) const {
1522-
using std::chrono::duration_cast;
1523-
using std::chrono::seconds;
1524-
using std::chrono::nanoseconds;
1525-
1526-
system_clock::duration dur = ts.time_since_epoch();
1527-
return { duration_cast<seconds>(dur).count(),
1528-
duration_cast<nanoseconds>(dur % seconds(1)).count() };
1520+
std::pair<int64_t, int64_t> ZmqAgent::create_recorded() const {
1521+
uint64_t ns = utils::current_timestamp_ns();
1522+
return { static_cast<int64_t>(ns / 1000000000),
1523+
static_cast<int64_t>(ns % 1000000000) };
15291524
}
15301525

15311526
ZmqAgent::ZmqCommandError ZmqAgent::create_command_error(
@@ -1573,7 +1568,7 @@ ZmqAgent::ZmqCommandError ZmqAgent::create_command_error(
15731568

15741569
void ZmqAgent::send_error_message(const std::string& msg,
15751570
uint32_t code) {
1576-
auto recorded = create_recorded(system_clock::now());
1571+
auto recorded = create_recorded();
15771572
int r = snprintf(msg_buf_,
15781573
msg_size_,
15791574
MSG_5,
@@ -1614,7 +1609,7 @@ void ZmqAgent::send_error_message(const std::string& msg,
16141609
int ZmqAgent::send_error_command_message(const std::string& req_id,
16151610
const std::string& command,
16161611
const ZmqCommandError& err) {
1617-
auto recorded = create_recorded(system_clock::now());
1612+
auto recorded = create_recorded();
16181613
int r = snprintf(msg_buf_,
16191614
msg_size_,
16201615
MSG_4,

‎agents/zmq/src/zmq_agent.h‎

Lines changed: 1 addition & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -534,8 +534,7 @@ class ZmqAgent {
534534

535535
void do_stop();
536536

537-
std::pair<int64_t, int64_t> create_recorded(
538-
const std::chrono::time_point<std::chrono::system_clock>&) const;
537+
std::pair<int64_t, int64_t> create_recorded() const;
539538

540539
ZmqCommandError create_command_error(const std::string& command,
541540
int err) const;

‎src/nsolid.cc‎

Lines changed: 1 addition & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -250,8 +250,7 @@ int ProcessMetrics::Update() {
250250
uv_mutex_lock(&stor_lock_);
251251
stor_.title = title;
252252
stor_.user = user;
253-
stor_.timestamp = duration_cast<milliseconds>(
254-
system_clock::now().time_since_epoch()).count();
253+
stor_.timestamp = utils::current_timestamp_ns() / 1000000;
255254
stor_.uptime =
256255
(uv_hrtime() - node::per_process::node_start_time) / NANOS_PER_SEC;
257256
stor_.system_uptime = static_cast<uint64_t>(system_uptime);

‎src/nsolid/nsolid_api.cc‎

Lines changed: 3 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -282,10 +282,7 @@ void EnvInst::GetThreadMetrics(ThreadMetrics::MetricsStor* stor) {
282282
CHECK_NE(env(), nullptr);
283283

284284
stor->current_hrtime_ = uv_hrtime();
285-
// TODO(trevnorris): Does this work instead of calling ms_since_epoch?
286-
// stor->timestamp = (stor->current_hrtime_ - env()->time_origin()) / 1e6 +
287-
// env()->time_origin_timestamp() / 1e3;
288-
stor->timestamp = utils::ms_since_epoch();
285+
stor->timestamp = utils::current_timestamp_ns() / 1e6;
289286
stor->thread_id = thread_id();
290287
stor->thread_name = GetThreadName();
291288
stor->active_handles = event_loop()->active_handles;
@@ -1434,8 +1431,7 @@ void EnvInst::send_datapoint(MetricsStream::Type type,
14341431
double value) {
14351432
double ts = 0;
14361433
if (has_metrics_stream_hooks_) {
1437-
ts = (PERFORMANCE_NOW() - env()->time_origin()) / 1e6 +
1438-
env()->time_origin_timestamp() / 1e3;
1434+
ts = utils::current_timestamp_ns() / 1e6;
14391435
}
14401436

14411437
EnvList::Inst()->datapoints_q_.Enqueue({ thread_id_, ts, type, value });
@@ -2233,13 +2229,11 @@ static void WriteLog(const FunctionCallbackInfo<Value>& args) {
22332229
DCHECK(args[1]->IsUint32());
22342230
String::Utf8Value s(args.GetIsolate(), args[0]);
22352231
std::string ss = *s;
2236-
uint64_t nanoseconds = std::chrono::duration_cast<std::chrono::nanoseconds>(
2237-
std::chrono::system_clock::now().time_since_epoch()).count();
22382232
// TODO(trevnorris): Allow tracing through this at some point?
22392233
EnvList::Inst()->WriteLogLine(GetLocalEnvInst(args.GetIsolate()),
22402234
{ ss,
22412235
args[1].As<v8::Uint32>()->Value(),
2242-
nanoseconds,
2236+
utils::current_timestamp_ns(),
22432237
"",
22442238
"",
22452239
0});

‎src/nsolid/nsolid_trace.cc‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -201,7 +201,7 @@ void TracerImpl::addSpanItem(const SpanItem& item) {
201201

202202
void TracerImpl::endPendingSpans() {
203203
int r = nsolid::QueueCallback(+[](TracerImpl* tracer) {
204-
double now = GetCurrentTimeInMicroseconds() / 1000;
204+
double now = utils::current_timestamp_ns() / 1e6;
205205
for (auto& item : tracer->pending_spans_) {
206206
auto& span = item.second;
207207
span.stor_.end_reason = Tracer::kSpanEndExit;
@@ -280,7 +280,7 @@ void TracerImpl::update_flags() {
280280

281281
void TracerImpl::expired_span_cb_(Span span, TracerImpl* tracer) {
282282
span.stor_.end_reason = Tracer::kSpanEndExpired;
283-
span.stor_.end = GetCurrentTimeInMicroseconds() / 1000;
283+
span.stor_.end = utils::current_timestamp_ns() / 1e6;
284284
span.stor_.attrs.pop_back();
285285
span.stor_.attrs += "}";
286286
tracer->trace_hook_list_.for_each([&](auto& stor) {

‎src/nsolid/nsolid_util.h‎

Lines changed: 9 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -16,6 +16,7 @@
1616

1717
#include "uv.h"
1818
#include "nlohmann/json.hpp"
19+
#include "node_perf_common.h"
1920

2021
using string_vector = std::vector<std::string>;
2122
using json = nlohmann::json;
@@ -128,12 +129,14 @@ inline const std::string generate_unique_id() {
128129
}
129130

130131

131-
inline uint64_t ms_since_epoch() {
132-
using std::chrono::duration_cast;
133-
using std::chrono::milliseconds;
134-
using std::chrono::system_clock;
135-
system_clock::duration dur = system_clock::now().time_since_epoch();
136-
return duration_cast<milliseconds>(dur).count();
132+
inline uint64_t current_timestamp_ns() {
133+
// Offset = epoch_ns_at_start - hrtime_at_start
134+
// So: epoch_ns_now = offset + hrtime_now
135+
static uint64_t offset =
136+
static_cast<uint64_t>(performance::performance_process_start_timestamp * 1000) -
137+
performance::performance_process_start;
138+
139+
return offset + uv_hrtime();
137140
}
138141

139142

0 commit comments

Comments
 (0)
⚡