puzpuzpuz/cls-rtracer

cls-rtracer uses synchronous API

tsondergaard opened this issue · 1 comments

Running node with --trace-sync-io for an application that uses cls-rtracer outputs warnings such as this one:

(node:31771) WARNING: Detected use of sync API
    at randomBytes (internal/crypto/random.js:54:31)
    at nodeRNG ([...]/node_modules/cls-rtracer/node_modules/uuid/lib/rng.js:7:17)
    at v4 ([...]/node_modules/cls-rtracer/node_modules/uuid/v4.js:13:52)
    at [...]/node_modules/cls-rtracer/index.js:30:30
    at handle ([...]/node_modules/express/lib/router/layer.js:95:5)
    at trim_prefix ([...]/node_modules/express/lib/router/index.js:317:13)
    at [...]/node_modules/express/lib/router/index.js:284:7
    at process_params ([...]/node_modules/express/lib/router/index.js:335:12)
    at next ([...]/node_modules/express/lib/router/index.js:275:10)

Using a synchronous API is undesirable even if the randomBytes() function is normally very fast. If for no other reason, just for the fact that it makes --trace-sync-io much less useful when cls-rtracer creates a lot of noise.

I would expect that a UUID V1 should be plenty good enough for cls-rtracer. uuid.v1() is 5 times faster than uuid.v4() and does not trigger the "WARNING: Detected use of sync API" when run with --trace-sync-io as demonstrated by this little experiment:

$ cat experiment.js 
const uuid = require("uuid");
const { performance } = require("perf_hooks");

const iterations = 5000000;

let t_begin = performance.now();
for (let i = 0; i < iterations; ++i) {
    uuid.v1();
}
console.log(`${iterations} uuid.v1(): ${(performance.now() - t_begin).toFixed(0)} ms`);

t_begin = performance.now();
for (let i = 0; i < iterations; ++i) {
    uuid.v4();
}
console.log(`${iterations} uuid.v4(): ${(performance.now() - t_begin).toFixed(0)} ms`);

$ node experiment.js 
5000000 uuid.v1(): 2941 ms
5000000 uuid.v4(): 14589 ms

Many thanks for finding this issue @tsondergaard

I completely agree that there is not point in using UUID V4 for cls-rtracer, especially considering the sync call that happens in uuid/v4. Going to fix this defect and ship it in 1.4.0 today.