Add trace_events Clock Sync Event for Date.now() and hrtime()

[AndreasMadsen]

• Version: >= 8.x
• Platform: all
• Subsystem: trace_events

trace_events has an internal clock, this makes it very difficult to correlate the data with other external data. I would suggest that we emit a Clock Sync Event on startup for synchronizing with Date.now() and process.hrtime().

/cc @nodejs/v8 - as we currently lack a trace_events specialist.

[bnoordhuis]

You mean adding a TRACE_EVENT_CLOCK_SYNC_ISSUER() in the right place? Seems fine to me, I'd say go for it.

[AndreasMadsen]

Oh, brilliant. I was looking to see if we had the macro but I couldn't find it. This makes it much easier.

[AndreasMadsen]

As suspected it is not implemented:

node/src/tracing/trace_event.h

Line 213 in 212b12c

UNIMPLEMENTED()

[bnoordhuis]

Curious, it exists in deps/v8/base:

node/deps/v8/base/trace_event/common/trace_event_common.h

Lines 922 to 926 in 4ca4db0

	#define TRACE_EVENT_CLOCK_SYNC_ISSUER(sync_id, issue_ts, issue_end_ts) \
	INTERNAL_TRACE_EVENT_ADD_WITH_TIMESTAMP( \
	TRACE_EVENT_PHASE_CLOCK_SYNC, "__metadata", "clock_sync", \
	issue_end_ts, TRACE_EVENT_FLAG_NONE, \
	"sync_id", sync_id, "issue_ts", issue_ts)

Time to sync up again, I suppose?

cc @matthewloring - do you still work on tracing?

[targos]

should I add something to update-v8 that syncs this file?

[AndreasMadsen]

@bnoordhuis It is INTERNAL_TRACE_EVENT_ADD_WITH_TIMESTAMP that isn't implemented.

[jasnell]

Definitely +1 on this. @bnoordhuis ... the trace events implementation in core was never completed and has quite a bit that has not been implemented yet. Specifically, none of the _WITH_TIMESTAMP macro variations have any implementation at all.

@matthewloring moved on to a different role within Google.
@ofrobots @JustinBeckwith ... has there been any progress in identifying who will be following up on the trace events impl in core?

[ofrobots]

Hi Folks! 👋 Sorry for the late reply @matthewloring was previously working on trace events, but since he is no longer working on the same team, @kjin and I are ramping up on the trace event implementation.

There have been some changes made upstream to make it easier for embedders to reuse the libplatform implementation of tracing controller rather than having to duplicate. See changes on this bug: https://bugs.chromium.org/p/v8/issues/detail?id=6511. @kjin and I are presently digesting this to understand how this could be utilized over in node.

[fmeawad]

For now, I would recommend to just sync the trace_event_common.h file as that macro does not require any changes on the back-end since it uses an existing internal macro.

Meanwhile, I will check with @ofrobots if we can reuse the existing file from V8 directly now since some parts have already been exposed.

[ofrobots]

Hi Folks. I have been doing some research, and here are my findings based on the Trace Event Clock Sync design document. As far as I understand the TRACE_EVENT_CLOCK_SYNC_ISSUER and *_RECEIVER macros are for the scenario where one has multiple individual trace event agents, each writing their logs separately. In the Node use-case, both Node and V8 write to the same agent, and the same IO sink (log file at present), so those macros wouldn't actually help.

@AndreasMadsen

trace_events has an internal clock, this makes it very difficult to correlate the data with other external data.

Can you elaborate a little bit more on where/how you saw the timestamps to differ? Trace events timestamps are based on the V8 TimeTicks class. Specifically we use the HighResolutionNow. At least on linux, I think the time source is the same as uv_hrtime, but other platforms I see this as possibly differing. Can you confirm which environment you saw the time domain differing?

There are a few ways I can think we can fix things:

1. Change the implementation of trace event in Node.js so that it uses a Platform provided hrtime function which we can back using uv_hrtime. This would require some API changes in the V8 platform to allow an embedder to provide a clock source. (/cc @hashseed)
2. Add a normal event (but not a .._CLOCK_SYNC_ISSUER) to allow trace log readers to correlate V8 TimerTicks timestamps to process.hrtime (and possibly Date.now) timestamps.

The latter would be something along the lines of:

  "traceEvents": [
    {
      "pid": 59661,
      "tid": 775,
      "ts": 220620843754,
      "tts": 5072,
      "ph": "X",
      "cat": "__metadata",
      "name": "clock sync",
      "dur": 16,
      "tdur": 8,
      "args": {
        "process.hrtime()": 220620843715826
      }
    }
  ]
}

Note that on my system the difference between process.hrtime and trace event internal timestamps is the units – nano seconds vs micro seconds.

I'm going to mull over these options and evaluate feasibility, but if anyone has opinions, or if I have understood something incorrectly, please do share your thoughts.

[ofrobots]

Another thing to consider here is that at least @jasnell has expressed a desire to be able to use the TRACE_EVENT_*_WITH_TIMESTAMP macros which suggests that we want to provide our own timestamps anyway. I think this suggests a preference for option 1.

@jasnell can you elaborate on your use-case for providing own timestamps while I am thinking this over?

[AndreasMadsen]

Hi Folks. I have been doing some research, and here are my findings based on the Trace Event Clock Sync design document. As far as I understand the TRACE_EVENT_CLOCK_SYNC_ISSUER and *_RECEIVER macros are for the scenario where one has multiple individual trace event agents, each writing their logs separately. In the Node use-case, both Node and V8 write to the same agent, and the same IO sink (log file at present), so those macros wouldn't actually help.

That is the primary use case. As I understand it, the reason why the CLOCK_SYNC is so complicated is to compensate for the small amount of time it takes to get the timestamp and call the macro. By making it a two way protocol, the delay can be messaured and compensated for later. In my opinion, this is over engineered.

Can you elaborate a little bit more on where/how you saw the timestamps to differ? Trace events timestamps are based on the V8 TimeTicks class. Specifically we use the HighResolutionNow. At least on linux, I think the time source is the same as uv_hrtime, but other platforms I see this as possibly differing. Can you confirm which environment you saw the time domain differing?

Oh, they do appear to match. I confirmed this on Mac. The big issues are then that it is not documented, nor gaurantteed to always align. I could be that they are the same, at least uv_hrtime on windows appears to use QueryPerformanceCounter too.

There are a few ways I can think we can fix things.

I'm fine with both options, with a slight preference for the first option.

[ofrobots]

With the preference for the first option, here's a proposed V8 change that allows embedders (i.e. Node) to provide the backing time source for the trace event timestamps: https://chromium-review.googlesource.com/c/v8/v8/+/847690. Once that is in place, it should be a fairly simple change in Node to start using uv_hrtime.

Assigning issue to self.