Something is fishy in RTS's "max pause" GC statistic
While looking into a GC issue, I found a peculiar inconsistency between the +RTS -s
output and that from the eventlog.
The -s
output is,
13,756,939,024 bytes allocated in the heap
6,085,406,120 bytes copied during GC
182,001,080 bytes maximum residency (22 sample(s))
753,160 bytes maximum slop
508 MB total memory in use (0 MB lost due to fragmentation)
Tot time (elapsed) Avg pause Max pause
Gen 0 28674 colls, 28674 par 5.268s 2.949s 0.0001s 0.1016s
Gen 1 22 colls, 21 par 0.004s 0.002s 0.0001s 0.0005s
Parallel GC work balance: 79.36% (serial 0%, perfect 100%)
TASKS: 9 (1 bound, 8 peak workers (8 total), using -N2)
SPARKS: 0 (0 converted, 0 overflowed, 0 dud, 0 GC'd, 0 fizzled)
INIT time 0.007s ( 0.017s elapsed)
MUT time 4.353s ( 2.556s elapsed)
GC time 5.272s ( 2.951s elapsed)
EXIT time 0.004s ( 0.072s elapsed)
Total time 9.635s ( 5.596s elapsed)
Alloc rate 3,160,479,659 bytes per MUT second
Productivity 45.2% of total user, 47.0% of total elapsed
Note the "Max pause" statistic: gen0 apparently pauses for four orders of magnitude more than gen1. This seems rather hard to believe.
Moreover, if I open the eventlog from the same run in threadscope, I find,
Generation | Collections | Par collections | Elapsed time | Avg pause | Max pause |
---|---|---|---|---|---|
GC Total | 27215 | 25518 | 2.83s | 0.0001s | 0.1016s |
Gen 0 | 25504 | 25504 | 1.55s | 0.0001s | 0.0012s |
Gen 1 | 15 | 14 | 0.99s | 0.0657s | 0.1016s |
Hmmmmmmmmm...
Trac metadata
Trac field | Value |
---|---|
Version | 8.2.1 |
Type | Bug |
TypeOfFailure | OtherFailure |
Priority | normal |
Resolution | Unresolved |
Component | Runtime System |
Test case | |
Differential revisions | |
BlockedBy | |
Related | |
Blocking | |
CC | |
Operating system | |
Architecture |