Use exit package rather than process.exit

[amcasey]

It sounds like process.exit might truncate in-flight I/O, so use process.exitCode in non-error scenarios.

(I'm tentatively assuming that a tiny message sent to stdout/stderr immediately before exit will make it to the console.)

Fixes #33

[amcasey]

@dylang Can you please give this a shot before I merge it?

[dylang]

I don't think this change is what we want, or there's more bugs to find.

It runs for few minutes with no output and then this happens.

--- Last few GCs --->

[76369:0x7fc138008000]   314662 ms: Mark-sweep (reduce) 4094.9 (4099.7) -> 4094.8 (4097.7) MB, 4.5 / 0.0 ms  (+ 2.2 ms in 16 steps since start of marking, biggest step 0.3 ms, walltime since start of marking 9 ms) (average mu = 0.851, current mu = 0.805) [76369:0x7fc138008000]   314686 ms: Mark-sweep 4095.8 (4097.7) -> 4095.7 (4101.7) MB, 13.2 / 0.0 ms  (average mu = 0.729, current mu = 0.461) allocation failure scavenge might not succeed

<--- JS stacktrace --->

FATAL ERROR: Reached heap limit Allocation failed - JavaScript heap out of memory
 1: 0x10824dbf5 node::Abort() (.cold.1) [/Users/dgreene/.nvm/versions/node/v16.15.0/bin/node]
 2: 0x106f41349 node::Abort() [/Users/dgreene/.nvm/versions/node/v16.15.0/bin/node]
 3: 0x106f414bf node::OnFatalError(char const*, char const*) [/Users/dgreene/.nvm/versions/node/v16.15.0/bin/node]
 4: 0x1070c3987 v8::Utils::ReportOOMFailure(v8::internal::Isolate*, char const*, bool) [/Users/dgreene/.nvm/versions/node/v16.15.0/bin/node]
 5: 0x1070c3923 v8::internal::V8::FatalProcessOutOfMemory(v8::internal::Isolate*, char const*, bool) [/Users/dgreene/.nvm/versions/node/v16.15.0/bin/node]
 6: 0x107265005 v8::internal::Heap::FatalProcessOutOfMemory(char const*) [/Users/dgreene/.nvm/versions/node/v16.15.0/bin/node]
 7: 0x10726398c v8::internal::Heap::CollectGarbage(v8::internal::AllocationSpace, v8::internal::GarbageCollectionReason, v8::GCCallbackFlags) [/Users/dgreene/.nvm/versions/node/v16.15.0/bin/node]
 8: 0x107270230 v8::internal::Heap::AllocateRawWithLightRetrySlowPath(int, v8::internal::AllocationType, v8::internal::AllocationOrigin, v8::internal::AllocationAlignment) [/Users/dgreene/.nvm/versions/node/v16.15.0/bin/node]
 9: 0x1072702b1 v8::internal::Heap::AllocateRawWithRetryOrFailSlowPath(int, v8::internal::AllocationType, v8::internal::AllocationOrigin, v8::internal::AllocationAlignment) [/Users/dgreene/.nvm/versions/node/v16.15.0/bin/node]
10: 0x10723735e v8::internal::FactoryBase<v8::internal::Factory>::NewRawTwoByteString(int, v8::internal::AllocationType) [/Users/dgreene/.nvm/versions/node/v16.15.0/bin/node]
11: 0x10723ef51 v8::internal::Factory::NewStringFromUtf8(v8::base::Vector<char const> const&, v8::internal::AllocationType) [/Users/dgreene/.nvm/versions/node/v16.15.0/bin/node]
12: 0x1070e56bf v8::String::NewFromUtf8(v8::Isolate*, char const*, v8::NewStringType, int) [/Users/dgreene/.nvm/versions/node/v16.15.0/bin/node]
13: 0x10700940c node::StringBytes::Encode(v8::Isolate*, char const*, unsigned long, node::encoding, v8::Local<v8::Value>*) [/Users/dgreene/.nvm/versions/node/v16.15.0/bin/node]
14: 0x106f21a00 void node::Buffer::(anonymous namespace)::StringSlice<(node::encoding)1>(v8::FunctionCallbackInfo<v8::Value> const&) [/Users/dgreene/.nvm/versions/node/v16.15.0/bin/node]
15: 0x1079335ec Builtins_CallApiCallback [/Users/dgreene/.nvm/versions/node/v16.15.0/bin/node]
16: 0x10bf73d3d
fish: Job 1, 'analyze-trace .cache/ts-trace/' terminated by signal SIGABRT (Abort)

[dylang]

Would this be a more optimal solutions? https://nodejs.org/dist/latest-v16.x/docs/api/worker_threads.html

[dylang]

This hacky workaround is working for me. OMG so much output! I thought we were just showing one hot spot per project, we have so many for each!

.then(found => {
    // bad hack to hope the console buffer has flushed by this point.
    setTimeout(() => {
        process.exit(found ? 0 : 1);
    }, 1000);
})

[dylang]

How are we limiting the number of forks to stay below the number of cores?

The repo I am using this on has over 200 projects (yarn workspaces) in our monorepo. My laptop, sadly, does not have that many cores.

[amcasey]

How are we limiting the number of forks to stay below the number of cores?

The repo I am using this on has over 200 projects (yarn workspaces) in our monorepo. My laptop, sadly, does not have that many cores.

p-limit

FWIW, I've run the tool without issue on monorepos with > 1000 projects, so I don't think that's the issue.

[amcasey]

I don't think this change is what we want, or there's more bugs to find.

It runs for few minutes with no output and then this happens.

--- Last few GCs --->

[76369:0x7fc138008000]   314662 ms: Mark-sweep (reduce) 4094.9 (4099.7) -> 4094.8 (4097.7) MB, 4.5 / 0.0 ms  (+ 2.2 ms in 16 steps since start of marking, biggest step 0.3 ms, walltime since start of marking 9 ms) (average mu = 0.851, current mu = 0.805) [76369:0x7fc138008000]   314686 ms: Mark-sweep 4095.8 (4097.7) -> 4095.7 (4101.7) MB, 13.2 / 0.0 ms  (average mu = 0.729, current mu = 0.461) allocation failure scavenge might not succeed

<--- JS stacktrace --->

FATAL ERROR: Reached heap limit Allocation failed - JavaScript heap out of memory
 1: 0x10824dbf5 node::Abort() (.cold.1) [/Users/dgreene/.nvm/versions/node/v16.15.0/bin/node]
 2: 0x106f41349 node::Abort() [/Users/dgreene/.nvm/versions/node/v16.15.0/bin/node]
 3: 0x106f414bf node::OnFatalError(char const*, char const*) [/Users/dgreene/.nvm/versions/node/v16.15.0/bin/node]
 4: 0x1070c3987 v8::Utils::ReportOOMFailure(v8::internal::Isolate*, char const*, bool) [/Users/dgreene/.nvm/versions/node/v16.15.0/bin/node]
 5: 0x1070c3923 v8::internal::V8::FatalProcessOutOfMemory(v8::internal::Isolate*, char const*, bool) [/Users/dgreene/.nvm/versions/node/v16.15.0/bin/node]
 6: 0x107265005 v8::internal::Heap::FatalProcessOutOfMemory(char const*) [/Users/dgreene/.nvm/versions/node/v16.15.0/bin/node]
 7: 0x10726398c v8::internal::Heap::CollectGarbage(v8::internal::AllocationSpace, v8::internal::GarbageCollectionReason, v8::GCCallbackFlags) [/Users/dgreene/.nvm/versions/node/v16.15.0/bin/node]
 8: 0x107270230 v8::internal::Heap::AllocateRawWithLightRetrySlowPath(int, v8::internal::AllocationType, v8::internal::AllocationOrigin, v8::internal::AllocationAlignment) [/Users/dgreene/.nvm/versions/node/v16.15.0/bin/node]
 9: 0x1072702b1 v8::internal::Heap::AllocateRawWithRetryOrFailSlowPath(int, v8::internal::AllocationType, v8::internal::AllocationOrigin, v8::internal::AllocationAlignment) [/Users/dgreene/.nvm/versions/node/v16.15.0/bin/node]
10: 0x10723735e v8::internal::FactoryBase<v8::internal::Factory>::NewRawTwoByteString(int, v8::internal::AllocationType) [/Users/dgreene/.nvm/versions/node/v16.15.0/bin/node]
11: 0x10723ef51 v8::internal::Factory::NewStringFromUtf8(v8::base::Vector<char const> const&, v8::internal::AllocationType) [/Users/dgreene/.nvm/versions/node/v16.15.0/bin/node]
12: 0x1070e56bf v8::String::NewFromUtf8(v8::Isolate*, char const*, v8::NewStringType, int) [/Users/dgreene/.nvm/versions/node/v16.15.0/bin/node]
13: 0x10700940c node::StringBytes::Encode(v8::Isolate*, char const*, unsigned long, node::encoding, v8::Local<v8::Value>*) [/Users/dgreene/.nvm/versions/node/v16.15.0/bin/node]
14: 0x106f21a00 void node::Buffer::(anonymous namespace)::StringSlice<(node::encoding)1>(v8::FunctionCallbackInfo<v8::Value> const&) [/Users/dgreene/.nvm/versions/node/v16.15.0/bin/node]
15: 0x1079335ec Builtins_CallApiCallback [/Users/dgreene/.nvm/versions/node/v16.15.0/bin/node]
16: 0x10bf73d3d
fish: Job 1, 'analyze-trace .cache/ts-trace/' terminated by signal SIGABRT (Abort)

My initial guess would be that you're getting so much output that you're overflowing the string collecting it. Maybe try a run without type expansion to get a rough idea of where to look or what timing parameters to use?

[amcasey]

Would this be a more optimal solutions? https://nodejs.org/dist/latest-v16.x/docs/api/worker_threads.html

I'm not sure I understand what advantage that would have. I suppose a thread is a bit cheaper than a process, but the interaction model is basically the same, isn't it? And I'm pretty sure process overhead is not what's hurting you.

[amcasey]

This hacky workaround is working for me. OMG so much output! I thought we were just showing one hot spot per project, we have so many for each!

.then(found => {
    // bad hack to hope the console buffer has flushed by this point.
    setTimeout(() => {
        process.exit(found ? 0 : 1);
    }, 1000);
})

Is that in analyze-dir or analyze-file?

[dylang]

p-limit

Excellent, I use p-limit for this purpose as well.

const limit = plimit(os.cpus().length);

Totally unrelated to this, to be kind to our developers other needs, we should probably avoid maxing all cores. Something like Math.round(os.cpus().length * 0.75) gives some headroom. 😄

you're overflowing the string collecting it

I thought the same, but it doesn't run out of memory with the setTimeout hack. Is it possible the thread isn't exiting, like an async task is still running?

Is that in analyze-dir or analyze-file?

anaylyze-trace-file - here's what the code looks like.

reportHighlights(tracePath, argv.expandTypes ? typesPath : undefined, thresholdDuration, minDuration, minPercentage, importExpressionThreshold)
.then(found => {
    setTimeout(() => {
        process.exit(found ? 0 : 1);
    }, 1000);
})
.catch(err => {
    console.error(`Internal Error: ${err.message}\n${err.stack}`);
    process.exit(2);
});

[amcasey]

@dylang How about now?

[amcasey]

@dylang updated package should be pushed shortly. Thanks for your help!

[dylang]

Thanks for doing this @amcasey! And I just realized exit is from @cowboy, not Sindre Sorhus, whoops! I was thinking of https://github.com/sindresorhus/exit-hook.