Negative productivity in Haskell's runtime statistics

Question

I'm using a program coded in Haskell to which I passed +RTS -N3 -M9G -s -RTS in order to obtain runtime statistics at the end of the execution. I've occasionally had a result where the productivity is negative. Also, the program ran its task successfully but MUT is zero.

1. How come productivity is negative?
2. How is it possible for MUT to be zero if the program is completed successfully?

---

3,904,320,026,552 bytes allocated in the heap
4,110,237,505,912 bytes copied during GC
   6,874,676,192 bytes maximum residency (706 sample(s))
      16,352,288 bytes maximum slop
            9369 MiB total memory in use (0 MB lost due to fragmentation)

                                     Tot time (elapsed)  Avg pause  Max pause
  Gen  0     2402028 colls, 987034 par   39844.808s  1005.947s     0.0004s    0.0150s
  Gen  1       706 colls,   583 par   1165.131s  1730.422s     2.4510s    17.6798s

  Parallel GC work balance: 70.86% (serial 0%, perfect 100%)

  TASKS: 8 (1 bound, 7 peak workers (7 total), using -N3)

  SPARKS: 36096 (16594 converted, 0 overflowed, 0 dud, 5857 GC'd, 13645 fizzled)

  INIT    time    0.003s  (  0.002s elapsed)
  MUT     time    0.000s  (789.778s elapsed)
  GC      time  41009.939s  (2736.369s elapsed)
  EXIT    time    2.253s  (  0.001s elapsed)
  Total   time  5072.554s  (3526.151s elapsed)

  Alloc rate    0 bytes per MUT second

  Productivity -708.5% of total user, 22.4% of total elapsed


real   58m46,534s
user   80m23,692s
sys     4m9,296s

---

¹ The time in the end is because I'm invoking with $ time <program> +RTS -N3 -M9G -s -RTS <args-for-program>

OS: Ubuntu 18.04.6 LTS

Answer 1

There appears to be something very wrong with the calculated GC CPU time. It's 41010 secs compared to 2737 sec elapsed, which doesn't make sense if you're only running on three capabilities.

This miscalculation means that the calculated MUT CPU time, which is just total CPU time minus INIT, GC, and EXIT time, is actually a large negative number (5073-41010-2 = -35939). This gives a productivity of -35939/5073=-708%. When the MUT seconds are displayed, negative numbers are truncated at zero, to avoid reporting small negative numbers when MUT is very low and there's a clock precision error, which is why the displayed MUT time is 0 instead of -35939.

I don't know why the GC time is so badly miscalculated. My best guess is this. If you're running on Windows, there are known issues with CPU time clock precision, and it's possible that certain unusual patterns of garbage collection timing might result in precision errors occuring in only one direction, slightly overestimating the actual GC time more often than it underestimates it. Over 2.4 million collections (see your GC stats), this difference could accumulate to a huge positive error.

I looked through GitLab issues, and except for the report on general Windows CPU time imprecision and a couple of probably unrelated negative MUT reports here and here, I didn't see anything helpful.