Trace spans have inconsistent timing

[ngraef]

Prerequisites

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

• I am running the latest version
• I checked the documentation and found no answer
• I checked to make sure that this issue has not already been filed
• 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.

Expected Behavior

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

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

60 minutes, 42 ms max drift

Context

• Moleculer version: master
• NodeJS version: 12.21.0
• Operating System: macOS 10.15.7

[intech]

@icebob maybe we should go to perf_hook?

[intech]

@ngraef fast PR, thanks!

[ngraef]

@intech I made the fix while the second test was running 😁

[intech]

I also think that it is necessary to fix a similar problem in other places of the project, such as rate limiter and metrics. 🤔