Description
Phosphor TraceEvents record a timestamp from the steady_clock. When we export the traces, we only export that recorded timestamp. The steady_clock is monotonic, and as such, is ideal for situations such as recording events in a multithreaded system and to avoid skew due to system clock changes.
However, those timetamps cannot be easily mapped to the system clock, which memcached.log uses.
{"name":"ConnManager","cat":"ep-engine\/task","ph":"X","dur":2.202,"ts":1938517239.497,"pid":4906,"tid":4936,"args":{}}, |
Adding a system time field to every single TraceEvent object might be unnecessary. Instead, we could use the current delta between steady_clock and system_clock to map "ts" to a "time" in JSONExport, to get a similar result as in our slow ops traces, where we have "ts" and "args.time":
{"cat": "SASL_AUTH", "ph": "X", "pid": "77C96C3800000009/000000005B720230", "name": "request", "ts": 1408995962.384, "dur": 764755, "args": {"opaque": 2216230912, "fd": "231", "peer": {"ip": "67.212.150.204", "port": 9375}, "key": "<ud>PLAIN</ud>", "bucket": "", "vbucket": 0, "time": "2024-01-09T02:33:42.187831+00:00", "worker_tid": 140605116069440}} |
Mapping steady_clock -> system_clock after the fact can result in skew, especially if the system clock changed. However, I think we can live with that tradeoff (we have the same issues with slow ops traces).
Alternatively, we could simple output a mapping between steady clock and system clock in the root JSON object returned from the JSONExporter. We could then use a script to post-process the collected trace and add a system clock time in each TraceEvent.
Attachments
Gerrit Reviews
For Gerrit Dashboard: MB-60499 | ||||||
---|---|---|---|---|---|---|
# | Subject | Branch | Project | Status | CR | V |
204410,4 | MB-60499: Add clock information to phosphor dump | master | kv_engine | Status: NEW | -1 | -1 |