Repository navigation
worker: memory leak #997
Description
Issue to track the second memory leak the worker
We solved one some time ago, and set up some mitigation in GKE to kill workers frequently and stop memory rising.
But we are still seeing Lost runs as a result of the leak.
Tracking findings and solutions in this issue.
Metadata
Metadata
Assignees
Type
Projects
- Status
Activity
josephjclark commentedon Sep 15, 2025
Here's some long running output, posting one run every 30 seconds
I see this pattern consistently under different setups. Some observations:
josephjclark commentedon Sep 15, 2025
Just running claims doesn't seem to trigger the leak - memory rises slowly but does get reclaimed (I guess when gc runs, having a bit of trouble getting node diagnostics to run)
With capacity 1 and a single claim, memory does come right back down:
Also good with 2 claims - but note that, yet again, the second run is super slow
But with capacity 2 and 10 runs posted in rapid succession, memory doesn't get reclaimed. Not entirely anyway:
Same problem with capacity 1 actually
josephjclark commentedon Sep 15, 2025
This is quite telling
Inside the engine, the run duration is quite consistent, around 400ms. But the durations recorded by the worker are very different:
In this case, there's nearly 7 seconds of something extending that duration
josephjclark commentedon Sep 15, 2025
Slowing the claim rate down doesn't seem to help (maybe gc runs a bit better because everything is slower)
josephjclark commentedon Sep 15, 2025
I don't think it's GC itself - it seems to be running super fast. Here's the output of the 9th run, which is taking 20 seconds from start to complete (and 400ms to execute)
I suppose there are a lot of GC calls there, but when they're running so quickly I don't really think that's a problem?
josephjclark commentedon Sep 15, 2025
Running some tests against the engine. If we run something multiple times, do we see a slow down? This bypasses most of the runtime and worker stuff and just looks at the core engine and how quickly it can spin up worker threads.
Running a simple loop in nodejs shows a tiny variance over 500 iterations, less than 5ms between the fastests and slowest run.
The same code in the engine - spinning up a worker thread each time - shows a bit more variance, around 20ms. It#s hard to see a pattern over 500 runs bit I think it's consistently quicker at the start and consistently slower at the end.
Setting a timeout in the engine doesn't make much difference - the variance stays about the same.
So maybe the engine runs a bit more slowly under load, after many iterations. And maybe if you thicken the runtime environment, with module loaders and stuff, that scales manifests as a slowing down.
Maybe. Not actually sold on this.
josephjclark commentedon Sep 16, 2025
Profiler for the main thread suggests its mostly idle. Top functions appear to be event messaging - parsing strings and pushing events through the socket.
But yeah, looking at the trace, it's just waiting. What are we waiting for? Is this just debug stuff?
No insight here yet.
josephjclark commentedon Sep 16, 2025
Ok here's something:
The time it takes to join the run channel is increasing every time = from 3ms -> 600ms. Is every event slowing down that much?
Is this happening in prod?? Is it related to the memory leak? Am I just seeing contention on the websocket?
josephjclark commentedon Sep 16, 2025
Ok this is interesting: if I disable the
logevent - which is loud and spammy - the 10th run completes in half the time, and the memory seems to get reclaimed.So I could be looking at:
Updated phoenix js,restored logs and ran again. Still takes ages memory doesn't seem to recover.
josephjclark commentedon Sep 16, 2025
Dang, it's feeling like a phoenix issue. If I do everything apart from send the log event to phoenix, runs are significantly more quick and memory is reclaimed after. When I sent the event - even with a redacted payload - we get significant slowdown and memory is locked out.
Something about the socket performance under load?
josephjclark commentedon Sep 17, 2025
Well maybe not. I've got a simple phoenix server with a websocket and I'm calling it from a standalone
.mjs, sending in loads of data every 1ms. And the memory is absolutely fine - it spikes up and down but always settles.This is after 10k events
Options from here? Could be a setting on the socket. Could be the transport (I'm pretty sure its just a standard WebSocket). I could be chasing a dev artifact.
EDIT: I've matched the parameter and used the same
wstransport (and the same version). All fine.josephjclark commentedon Sep 19, 2025
Might be getting onto something new.
I've been bypassing the engine and trying to call the runtime directly from the worker. There's a lot of work involved in this because the events all need wiring up at least roughly to get a minimal run working.
But very quicky, without even the logs hooked up, I'm seeing a memory leak when running just two runs through the worker back-to-back. Very strangely, it's like it's the second run that does it, even if there's a long delay between them. Maybe each successive run is adding a bit of memory that doesn't get reclaimed.
Ah, this is just an artifact of using the runtime directly - I just wasn't running the cleanup code yet because some evens weren't wired up
EDIT: Hmm. I've introduced a new problem here because I think each time I call the runtime, it increases my memory usage a little. It's not really a fair test: in the engine we burn the thread each time so we know that any runtime memory is reclaimed.
In hmain thread, I think I'm seeing the memory creep up because of repeated runtime calls - but its irrelevant.
Not sure if this thread is worth continuing.
josephjclark commentedon Sep 22, 2025
I'm trying to use clinic.js to get better a visualisation of what's happening internally. I've created a standalone script, which is requires, but I'm getting burned right now by this open issue: clinicjs/node-clinic#444
EDIT: Got a workaround using the awkward env var
WORKER_DISABLE_EXIT_LISTENERSEDIT: First hit tells me that it's message parsing in the lightning mock chewing up the memory. Pretty dumb -I've taken that out of process in my script now.
Second hit tells me that most memory is being used in:
parseChannelMessages-> that's the main worker thread loading large json files from the runs. Fine. Doesn't tell me anything about deallocation (the problem isn't that a lot of memory is used reading events - the problem is I don't seem to get the memory back)The problem is that the heap profile tool is just telling me the biggest allocations (i'm still hazy on whether this is total or single shot). But my problem really is that the memory isn't freed up.
The most obviously suspicious thing I see here is the compiler. Let me try and cut that out of the loop.
josephjclark commentedon Sep 23, 2025
It's the bloody compiler!!!!
I've just switched the compiler off my test case and memory comes right back down.
So I need to work out why the compiler is leaking memory.
I've also been thinking for ages that I'd love to run the compiler in a dedicated child process. Compilation of large files is likely to take a lot of memory and it would be good to insulate CPU and memory from the main worker thread while compilation runs. That doesn't really help the memory leak though because it'll still cause kubernetes to kill the pod if it chews up memory
josephjclark commentedon Sep 23, 2025
Nope. Getting confused.
preloadAdaptorExports, which loads the typescript engine fromdescribe-adaptorsdescribe-adaptors, and in a long running processes that may well account for the memory leakkillall node -9, it does NOT seem to reclaim memory. What?!So currently my local test basically isn't feeling very reliable and I can't account for that. Sometimes it's ok, sometimes it's not.
Tempted just to go on and implement #1002 and just see what happens
josephjclark commentedon Sep 26, 2025
I'm gonna declare this irrelevant now: if there IS still a memory leak, it does not affect the worker or the CLI.