How incremental can incremental marking be?

[John Edwards]

Hi all! Just want to lead with a quick thanks to everyone who makes v8 happen! It's been a super useful piece of technology for me for many years. That said, it can still be quite mysterious, and, most recently, I've been trying to understand a bit more about the incremental marking part of the garbage collector.

I'm working on the server for a competitive online game using node.js (primarily version 8.11.1 with v8 version 6.2.414.50). The server updates the game state around 100 times a second, and normally takes less than 1ms per update. Occasionally, though, we were seeing 16-50ms pauses between frames, which temporarily degraded the player experience. The first suspect was the garbage collector, but on my initial (incorrect) read, I didn't see anything taking over a few milliseconds. This log of a mark-sweep pass appeared to me to only take 2.1ms, for instance:

[2944:0x356a660] 76591 ms: Mark-sweep 20.2 (40.9) -> 12.5 (40.9) MB, 2.1 / 0.0 ms (+ 26.1 ms in 18 steps since start of marking, biggest step 2.3 ms, walltime since start of marking 29 ms) finalize incremental marking via task GC in old space requested

After much confusion, I eventually stumbled on the --trace_incremental_marking flag, which gave the following output:

[2944:0x356a660] 76562 ms: [IncrementalMarking] Start (idle task): old generation 19MB, limit 27MB, slack 8MB
[2944:0x356a660] 76562 ms: [IncrementalMarking] Start marking
[2944:0x356a660] 76562 ms: [IncrementalMarking] Running
[2944:0x356a660] 76564 ms: [IncrementalMarking] Step in task 827176 bytes (827100) in 1.9
[2944:0x356a660] 76566 ms: [IncrementalMarking] Step in task 827136 bytes (827100) in 1.9
[2944:0x356a660] 76567 ms: [IncrementalMarking] Step in task 827216 bytes (827100) in 1.1
[2944:0x356a660] 76569 ms: [IncrementalMarking] Step in task 878480 bytes (827100) in 1.5
[2944:0x356a660] 76570 ms: [IncrementalMarking] Step in task 827168 bytes (827100) in 1.1
[2944:0x356a660] 76571 ms: [IncrementalMarking] Step in task 827184 bytes (827100) in 1.0
[2944:0x356a660] 76573 ms: [IncrementalMarking] Step in task 849536 bytes (827100) in 1.7
[2944:0x356a660] 76575 ms: [IncrementalMarking] Step in task 827104 bytes (827100) in 2.2
[2944:0x356a660] 76576 ms: [IncrementalMarking] Step in task 857840 bytes (827100) in 1.1
[2944:0x356a660] 76577 ms: [IncrementalMarking] Step in task 1038576 bytes (827100) in 0.8
[2944:0x356a660] 76578 ms: [IncrementalMarking] Step in task 827160 bytes (827100) in 0.7
[2944:0x356a660] 76580 ms: [IncrementalMarking] Step in task 827128 bytes (827100) in 2.0
[2944:0x356a660] 76582 ms: [IncrementalMarking] Step in task 827112 bytes (827100) in 2.2
[2944:0x356a660] 76585 ms: [IncrementalMarking] Step in task 827104 bytes (827100) in 2.2
[2944:0x356a660] 76586 ms: [IncrementalMarking] Step in task 829880 bytes (827100) in 1.0
[2944:0x356a660] 76587 ms: [IncrementalMarking] Step in task 971384 bytes (827100) in 1.3
[2944:0x356a660] 76588 ms: [IncrementalMarking] requesting finalization of incremental marking.
[2944:0x356a660] 76588 ms: [IncrementalMarking] Step in task 199296 bytes (827100) in 0.6
[2944:0x356a660] 76588 ms: [IncrementalMarking] (finalize incremental marking via task).
[2944:0x356a660] 76588 ms: [IncrementalMarking] Finalize incrementally round 0, spent 0 ms, marking progress 13.
[2944:0x356a660] 76588 ms: [IncrementalMarking] Black allocation started
[2944:0x356a660] 76589 ms: [IncrementalMarking] Complete (normal).
[2944:0x356a660] 76589 ms: [IncrementalMarking] Step in task 41240 bytes (827100) in 0.8
[2944:0x356a660] 76589 ms: [IncrementalMarking] Stopping: old generation 19MB, limit 27MB, overshoot 0MB
[2944:0x356a660] 76589 ms: [IncrementalMarking] Black allocation finished

... revealing that incremental marking steps occur consecutively (and, in this case, blocked execution for 29ms). Since I'd read that incremental marking was designed to reduce jank when scrolling web pages, I'd assumed the marking steps would be spaced over time. After quite a lot of profiling, however, I've never seen control get returned to the program between the start of incremental marking and completion.

We were eventually able to work around this by avoiding triggering any mark-sweeps during rounds of gameplay, but I am curious if this is expected behavior? Am I missing some sort of flag to tune the priority of the incremental marker? Game developers are used to working around blocking garbage collectors like this, so it's not too big an issue, but it would be a nice bonus if you didn't have to worry about it, and it feels like v8 is pretty close to getting there!

Also, apologies if this is more of a node issue. If so, I can take my question over there.

[hpa...@chromium.org]

Thanks John for your detailed report.

You are right, incremental marking steps should ideally be spread out over the whole program execution. It seems like the incremental marking task is the only task running in the observed trace. Do you have any JavaScript work pending? JavaScript should take turns with incremental marking work. Is your workload somehow reproducible for us?

We have some good news for you: V8 6.4 introduces concurrent marking which moves most of the marking work on a concurrent thread. I would be interested in seeing how your workload performance changes with a more recent V8 version.

[Hannes Payer]

+Ulan Degenbaev 

--
--
v8-users mailing list
v8-u...@googlegroups.com
http://groups.google.com/group/v8-users
---
You received this message because you are subscribed to the Google Groups "v8-users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to v8-users+u...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Ulan Degenbaev]

Thank you, John.

This looks like an unfortunate interaction of V8 incremental marker with NodeJS's implementation of v8::Platform.

The incremental marker posts a 1ms task that does a marking step and reposts itself (using  v8::Platform::CallOnForegroundThread).

This works well in Chrome, but in NodeJS this results in effectively non-incremental marking because v8::Platform implementation in NodeJS drains the foreground queue all at once until the queue becomes empty:

while (std::unique_ptr<Task> task = foreground_tasks_.Pop()) {

   did_work = true;

   RunForegroundTask(std::move(task));

}

Running the incremental marking tasks results in adding a new task to foreground_tasks_:

void PerIsolatePlatformData::PostTask(std::unique_ptr<Task> task) {

  foreground_tasks_.Push(std::move(task));

  uv_async_send(flush_tasks_);

}

I see two possible fixes:

1) Limit the task draining loop to only run tasks that were in the queue at the beginning of the loop.

2) Add time based heuristics to incremental marker to stop rescheduling tasks or to alternate delayed tasks with normal tasks.

I'll check with NodeJS team if option 1 is possible because option 2 seems a bit hacky.

Cheers,

Ulan.

+Ulan Degenbaev 

To unsubscribe from this group and stop receiving emails from it, send an email to v8-users+unsubscribe@googlegroups.com.

[Ulan Degenbaev]

I filed https://github.com/nodejs/node/issues/19937

[John Edwards]

Thanks for the quick responses. Glad to see it's being taken care of in node!