Moleculer: Trace spans have inconsistent timing

Created on 26 Mar 2021 · 4Comments · Source: moleculerjs/moleculer

Prerequisites

Please answer the following questions for yourself before submitting an issue.

[x] I am running the latest version
[x] I checked the documentation and found no answer
[x] I checked to make sure that this issue has not already been filed
[x] I'm reporting the issue to the correct repository

Current Behavior

Trace spans from moleculer don't line up with spans from third-party modules or moleculer spans from remote services (different processes/brokers). For example, the red span in the image below should fully contain the green and purple spans under it.

span offset

Expected Behavior

Span times should be as consistent as possible across all modules.

Screen Shot 2021-03-26 at 4 50 01 PM

Failure Information

This is caused by clock drift in moleculer's tracing/now.js implementation, which is used to set the startTime of spans. The following code and charts test this behavior and show how much a span could drift compared to Date.now().

Reproduce code snippet

const now = require("./src/tracing/now");

// Output CSV for analysis
console.log(`"Time elapsed (ms)","Drift (ms)"`);

const startTime = Date.now();
console.log(`0,${now() - startTime}`);

setInterval(() => {
    const time = Date.now();
    console.log(`${time - startTime},${now() - time}`);
}, 5e3);

Here are charts from two sample runs:

20 minutes, 25 ms drift
span time drift