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. On Wednesday, April 11, 2018 at 10:17:01 AM UTC+2, John Edwards wrote: > > 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. > -- -- v8-users mailing list v8-users@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+unsubscr...@googlegroups.com. For more options, visit https://groups.google.com/d/optout.
