mi_stats_print_out() prints weird numbers with mimalloc 3.3.1

[rockdrilla]

I've confused by counter "arenas -> committed -> current" having negative value (-2.6 GiB).

Current output with mimalloc 3.3.1:

Apr 23 00:51:05 vm app[13828]: --- mimalloc stats begin ---
Apr 23 00:51:05 vm app[13828]: subproc 0
Apr 23 00:51:05 vm app[13828]:  pages           peak       total     current       block      total#
Apr 23 00:51:05 vm app[13828]:   touched   :     0           0           0                                ok
Apr 23 00:51:05 vm app[13828]:   pages     :     4.5 K      35.7 K       2.0 K
Apr 23 00:51:05 vm app[13828]:   abandoned :     4.4 K      18.9 K       1.0 K
Apr 23 00:51:05 vm app[13828]:   reclaima  :   238
Apr 23 00:51:05 vm app[13828]:   reclaimf  :    10.3 K
Apr 23 00:51:05 vm app[13828]:   reabandon :     5.2 K
Apr 23 00:51:05 vm app[13828]:   waits     :     0
Apr 23 00:51:05 vm app[13828]:   extended  :     0
Apr 23 00:51:05 vm app[13828]:   retire    :     0
Apr 23 00:51:05 vm app[13828]:   searches  :     2.7 avg
Apr 23 00:51:05 vm app[13828]: 
Apr 23 00:51:05 vm app[13828]:  arenas          peak       total     current       block      total#
Apr 23 00:51:05 vm app[13828]:   reserved  :     1.0 GiB     1.0 GiB     1.0 GiB
Apr 23 00:51:05 vm app[13828]:   committed :   505.1 MiB   771.1 MiB    -2.6 GiB
Apr 23 00:51:05 vm app[13828]:   reset     :     0
Apr 23 00:51:05 vm app[13828]:   purged    :     3.3 GiB
Apr 23 00:51:05 vm app[13828]:   arenas    :     1
Apr 23 00:51:05 vm app[13828]:   rollback  :     0
Apr 23 00:51:05 vm app[13828]:   mmaps     :     4
Apr 23 00:51:05 vm app[13828]:   commits   :     0
Apr 23 00:51:05 vm app[13828]:   resets    :     0
Apr 23 00:51:05 vm app[13828]:   purges    :     3.1 K
Apr 23 00:51:05 vm app[13828]:   guarded   :     0
Apr 23 00:51:05 vm app[13828]:   theaps    :     2           2           2
Apr 23 00:51:05 vm app[13828]:   heaps     :     1           1           1
Apr 23 00:51:05 vm app[13828]:   heap waits:     0
Apr 23 00:51:05 vm app[13828]: 
Apr 23 00:51:05 vm app[13828]:  process         peak       total     current       block      total#
Apr 23 00:51:05 vm app[13828]:   threads   :     3           3           3
Apr 23 00:51:05 vm app[13828]:   numa nodes:     1
Apr 23 00:51:05 vm app[13828]:   elapsed   :  9022.745 s
Apr 23 00:51:05 vm app[13828]:   process   : user: 95.221 s, system: 2.800 s, faults: 0, peak rss: 883.6 MiB, peak commit: 505.1 MiB
Apr 23 00:51:05 vm app[13828]: 
Apr 23 00:51:05 vm app[13828]: --- mimalloc stats end -----

Previous output with mimalloc 3.2.8:

Apr 13 11:57:45 vm app[421]: subproc 0
Apr 13 11:57:45 vm app[421]:  pages           peak       total     current       block      total#
Apr 13 11:57:45 vm app[421]:   touched   :     0           0           0                                ok
Apr 13 11:57:45 vm app[421]:   pages     :     4.2 Ki    189.7 Ki      3.0 Ki                           not all freed
Apr 13 11:57:45 vm app[421]:   abandoned :     4.1 Ki    170.1 Ki      1.4 Ki                           not all freed
Apr 13 11:57:45 vm app[421]:   reclaima  :    12.8 Ki
Apr 13 11:57:45 vm app[421]:   reclaimf  :    43.9 Ki
Apr 13 11:57:45 vm app[421]:   reabandon :    96.4 Ki
Apr 13 11:57:45 vm app[421]:   waits     :     1
Apr 13 11:57:45 vm app[421]:   extended  :     0
Apr 13 11:57:45 vm app[421]:   retire    :     0
Apr 13 11:57:45 vm app[421]:   searches  :     2.8 avg
Apr 13 11:57:45 vm app[421]: 
Apr 13 11:57:45 vm app[421]:  arenas          peak       total     current       block      total#
Apr 13 11:57:45 vm app[421]:   reserved  :     1.0 GiB     1.0 GiB     1.0 GiB
Apr 13 11:57:45 vm app[421]:   committed :   772.1 MiB   774.3 MiB   772.1 MiB
Apr 13 11:57:45 vm app[421]:   reset     :     0
Apr 13 11:57:45 vm app[421]:   purged    :     2.0 Mi
Apr 13 11:57:45 vm app[421]:   arenas    :     1
Apr 13 11:57:45 vm app[421]:   rollback  :     0
Apr 13 11:57:45 vm app[421]:   mmaps     :     4
Apr 13 11:57:45 vm app[421]:   commits   :     0
Apr 13 11:57:45 vm app[421]:   resets    :     0
Apr 13 11:57:45 vm app[421]:   purges    :     2
Apr 13 11:57:45 vm app[421]:   guarded   :     0
Apr 13 11:57:45 vm app[421]:   heaps     :     1           1           1
Apr 13 11:57:45 vm app[421]: 
Apr 13 11:57:45 vm app[421]:  process         peak       total     current       block      total#
Apr 13 11:57:45 vm app[421]:   threads   :     3           3           3
Apr 13 11:57:45 vm app[421]:   numa nodes:     1
Apr 13 11:57:45 vm app[421]:   elapsed   : 133223.524 s
Apr 13 11:57:45 vm app[421]:   process   : user: 952.276 s, system: 23.078 s, faults: 261, peak rss: 1.0 GiB, peak commit: 772.1 MiB

[bazineta]

Seeing the same thing (OSX Tahoe).

If I hack mi_subproc_stats_get() to aggregate each heap via mi_heap_get_stats(heap) instead of using raw heap->stats, then at least the arenas -> committed -> current value becomes a plausible positive instead of an insanely huge negative number, but my subproc 0 -> pages and abandoned current are insane negative values.

So far as I can see, the aggregation fields are initialized properly, but the aggregation itself seems broken for the current values.

[rockdrilla]

@daanx I've seen somewhere in issues that "MIMALLOC_ALLOW_THP=0" may help. I'm going to test my long-running service with that environment variable set and report what happens.

Upd: nope, still present:

Apr 25 23:11:50 vm app[35769]: subproc 0
Apr 25 23:11:50 vm app[35769]:  pages           peak       total     current       block      total#
Apr 25 23:11:50 vm app[35769]:   touched   :     0           0           0                                ok
Apr 25 23:11:50 vm app[35769]:   pages     :     4.2 K      15.2 K       1.9 K
Apr 25 23:11:50 vm app[35769]:   abandoned :     4.1 K      13.2 K       1.2 K
Apr 25 23:11:50 vm app[35769]:   reclaima  :   551
Apr 25 23:11:50 vm app[35769]:   reclaimf  :     7.5 K
Apr 25 23:11:50 vm app[35769]:   reabandon :     3.0 K
Apr 25 23:11:50 vm app[35769]:   waits     :     0
Apr 25 23:11:50 vm app[35769]:   extended  :     0
Apr 25 23:11:50 vm app[35769]:   retire    :     0
Apr 25 23:11:50 vm app[35769]:   searches  :     2.7 avg
Apr 25 23:11:50 vm app[35769]: 
Apr 25 23:11:50 vm app[35769]:  arenas          peak       total     current       block      total#
Apr 25 23:11:50 vm app[35769]:   reserved  :     1.0 GiB     1.0 GiB     1.0 GiB
Apr 25 23:11:50 vm app[35769]:   committed :   284.9 MiB   707.6 MiB    -1.3 GiB
Apr 25 23:11:50 vm app[35769]:   reset     :     0
Apr 25 23:11:50 vm app[35769]:   purged    :     2.0 GiB
Apr 25 23:11:50 vm app[35769]:   arenas    :     1
Apr 25 23:11:50 vm app[35769]:   rollback  :     0
Apr 25 23:11:50 vm app[35769]:   mmaps     :     4
Apr 25 23:11:50 vm app[35769]:   commits   :     0
Apr 25 23:11:50 vm app[35769]:   resets    :     0
Apr 25 23:11:50 vm app[35769]:   purges    :     3.2 K
Apr 25 23:11:50 vm app[35769]:   guarded   :     0
Apr 25 23:11:50 vm app[35769]:   theaps    :     2           2           2
Apr 25 23:11:50 vm app[35769]:   heaps     :     1           1           1
Apr 25 23:11:50 vm app[35769]:   heap waits:     0
Apr 25 23:11:50 vm app[35769]: 
Apr 25 23:11:50 vm app[35769]:  process         peak       total     current       block      total#
Apr 25 23:11:50 vm app[35769]:   threads   :     3           3           3
Apr 25 23:11:50 vm app[35769]:   numa nodes:     1
Apr 25 23:11:50 vm app[35769]:   elapsed   :  1821.927 s
Apr 25 23:11:50 vm app[35769]:   process   : user: 49.114 s, system: 2.263 s, faults: 0, peak rss: 714.9 MiB, peak commit: 284.9 MiB

[daanx]

This is strange as there are not many changes from v3.2.8. Maybe the latest dev3 improves matters as it adds @bazineta's suggestion to not use the raw heap address (so the thread's theap stats are taken into account). I cannot repro this locally -- do you have a smallish repro that I can test with?

[rockdrilla]

Ok, I'll apply git diff v3.3.1..7a79a0c88ddf (current HEAD of dev3 branch) on top of mimalloc source, build package and see what happens.

Upd: whoops! All statistics are gone away!

Reproducer command:

$ LD_PRELOAD=/usr/lib/x86_64-linux-gnu/libmimalloc.so.3 MIMALLOC_SHOW_STATS=1 bash -ic 'sleep 1 ; exit 0'

Current dev3 branch:

exit

Pristine 3.3.1 version:

exit
subproc 0
 arenas          peak       total     current       block      total#   
  reserved  :     1.0 GiB     1.0 GiB     1.0 GiB                          
  committed :     4.6 MiB     4.6 MiB     4.6 MiB                          
  reset     :     0      
  purged    :     0      
  arenas    :     1      
  rollback  :     0      
  mmaps     :     3      
  commits   :     0      
  resets    :     0      
  purges    :     0      
  guarded   :     0      
  theaps    :     0           0           0      
  heaps     :     1           1           1      
  heap waits:     0      

 process         peak       total     current       block      total#   
  threads   :     1           1           1      
  numa nodes:     1
  elapsed   :     1.006 s
  process   : user: 0.006 s, system: 0.000 s, faults: 0, peak rss: 21.6 MiB, peak commit: 4.6 MiB