In a typical detailed zgc log, what's the meaning of these numbers in this mmu line?
[gc,mmu ] GC(18939) MMU: 2ms/0.0%, 5ms/0.0%, 10ms/0.0%, 20ms/0.0%, 50ms/36.2%, 100ms/68.0%
I've searched and read several pages but still got no expression on that line, so I'm seeking answers here.
A sample of full output of a zgc cycle: (jdk version: 17)
[2022-12-26T20:09:49.485+0800][824756][gc,start ] GC(18939) Garbage Collection (Allocation Rate)
[2022-12-26T20:09:49.485+0800][824756][gc,task ] GC(18939) Using 8 workers
[2022-12-26T20:09:49.486+0800][824899][gc,phases ] GC(18939) Pause Mark Start 0.048ms
[2022-12-26T20:09:51.200+0800][824756][gc,phases ] GC(18939) Concurrent Mark 1713.889ms
[2022-12-26T20:09:51.200+0800][824899][gc,phases ] GC(18939) Pause Mark End 0.064ms
[2022-12-26T20:09:51.200+0800][824756][gc,phases ] GC(18939) Concurrent Mark Free 0.002ms
[2022-12-26T20:09:51.220+0800][824756][gc,phases ] GC(18939) Concurrent Process Non-Strong References 20.398ms
[2022-12-26T20:09:51.221+0800][824756][gc,phases ] GC(18939) Concurrent Reset Relocation Set 0.297ms
[2022-12-26T20:09:51.237+0800][824756][gc,phases ] GC(18939) Concurrent Select Relocation Set 16.689ms
[2022-12-26T20:09:51.238+0800][824899][gc,phases ] GC(18939) Pause Relocate Start 0.012ms
[2022-12-26T20:09:51.248+0800][824756][gc,phases ] GC(18939) Concurrent Relocate 9.731ms
[2022-12-26T20:09:51.248+0800][824756][gc,load ] GC(18939) Load: 17.62/16.95/16.43
[2022-12-26T20:09:51.248+0800][824756][gc,mmu ] GC(18939) MMU: 2ms/0.0%, 5ms/0.0%, 10ms/0.0%, 20ms/0.0%, 50ms/36.2%, 100ms/68.0%
[2022-12-26T20:09:51.248+0800][824756][gc,marking ] GC(18939) Mark: 8 stripe(s), 2 proactive flush(es), 1 terminate flush(es), 0 completion(s), 0 continuation(s)
[2022-12-26T20:09:51.248+0800][824756][gc,marking ] GC(18939) Mark Stack Usage: 32M
[2022-12-26T20:09:51.248+0800][824756][gc,nmethod ] GC(18939) NMethods: 33902 registered, 10715 unregistered
[2022-12-26T20:09:51.248+0800][824756][gc,metaspace] GC(18939) Metaspace: 189M used, 191M committed, 1200M reserved
[2022-12-26T20:09:51.248+0800][824756][gc,ref ] GC(18939) Soft: 2612 encountered, 78 discovered, 0 enqueued
[2022-12-26T20:09:51.248+0800][824756][gc,ref ] GC(18939) Weak: 59639 encountered, 21677 discovered, 142 enqueued
[2022-12-26T20:09:51.248+0800][824756][gc,ref ] GC(18939) Final: 11628 encountered, 1203 discovered, 2 enqueued
[2022-12-26T20:09:51.248+0800][824756][gc,ref ] GC(18939) Phantom: 2517 encountered, 1758 discovered, 1 enqueued
[2022-12-26T20:09:51.248+0800][824756][gc,reloc ] GC(18939) Small Pages: 16920 / 33840M, Empty: 23428M, Relocated: 13M, In-Place: 0
[2022-12-26T20:09:51.248+0800][824756][gc,reloc ] GC(18939) Medium Pages: 9 / 288M, Empty: 192M, Relocated: 0M, In-Place: 0
[2022-12-26T20:09:51.248+0800][824756][gc,reloc ] GC(18939) Large Pages: 13 / 146M, Empty: 0M, Relocated: 0M, In-Place: 0
[2022-12-26T20:09:51.248+0800][824756][gc,reloc ] GC(18939) Forwarding Usage: 5M
[2022-12-26T20:09:51.248+0800][824756][gc,heap ] GC(18939) Min Capacity: 45056M(100%)
[2022-12-26T20:09:51.248+0800][824756][gc,heap ] GC(18939) Max Capacity: 45056M(100%)
[2022-12-26T20:09:51.248+0800][824756][gc,heap ] GC(18939) Soft Max Capacity: 45056M(100%)
[2022-12-26T20:09:51.248+0800][824756][gc,heap ] GC(18939) Mark Start Mark End Relocate Start Relocate End High Low
[2022-12-26T20:09:51.248+0800][824756][gc,heap ] GC(18939) Capacity: 45056M (100%) 45056M (100%) 45056M (100%) 45056M (100%) 45056M (100%) 45056M (100%)
[2022-12-26T20:09:51.248+0800][824756][gc,heap ] GC(18939) Free: 10782M (24%) 5440M (12%) 28954M (64%) 36920M (82%) 36922M (82%) 5376M (12%)
[2022-12-26T20:09:51.248+0800][824756][gc,heap ] GC(18939) Used: 34274M (76%) 39616M (88%) 16102M (36%) 8136M (18%) 39680M (88%) 8134M (18%)
[2022-12-26T20:09:51.248+0800][824756][gc,heap ] GC(18939) Live: - 2504M (6%) 2504M (6%) 2504M (6%) - -
[2022-12-26T20:09:51.248+0800][824756][gc,heap ] GC(18939) Allocated: - 5342M (12%) 5448M (12%) 5487M (12%) - -
[2022-12-26T20:09:51.248+0800][824756][gc,heap ] GC(18939) Garbage: - 31769M (71%) 8149M (18%) 143M (0%) - -
[2022-12-26T20:09:51.248+0800][824756][gc,heap ] GC(18939) Reclaimed: - - 23620M (52%) 31625M (70%) - -
[2022-12-26T20:09:51.248+0800][824756][gc ] GC(18939) Garbage Collection (Allocation Rate) 34274M(76%)->8136M(18%)
The term MMU (Minimum Mutator Utilization) was introduced in the paper "A Parallel, Real-Time Garbage Collector" by Perry Cheng and Guy E. Blelloch.
The MMU allows one to see not just the maximum pause time, but the fraction of time that the processor is available to the mutator (application) for any time window of a specified size (worst case across the full execution). This is a much more useful measure of real-time capabilities than just the maximum pause time.
More formally, in HotSpot JVM
MMU(t) = (t - time_paused) / t
where time_paused is the total time when the application threads were paused during the last time slice of t milliseconds ending with the last GC pause.
E.g. MMU 100ms/68.0% means that during the last 100 milliseconds, application threads were running for the total duration of 68 milliseconds.