Surprising performance hit in mi_page_free_list_extend when allowing THP

[timo]

TL;DR: This may just be the expected result of working with THP, that you pay for the management and receive benefits over the long run, but I was still rather surprised.

All of this is with v3.4.4 of mimalloc

Benchmark 1: env MVM_SPESH_BLOCKING=0 MIMALLOC_ALLOW_THP=0 rakudo -ne 'BEGIN my %h; if /\s+(\d+)/ { %h{$0}++; }; last if $++ > 1000; END say +%h.keys' gen/moar/CORE.*setting
  Time (mean ± σ):     230.1 ms ±   3.8 ms    [User: 164.3 ms, System: 62.3 ms]
  Range (min … max):   223.8 ms … 237.1 ms    20 runs
 
Benchmark 2: env MVM_SPESH_BLOCKING=0 MIMALLOC_ALLOW_THP=1 rakudo -ne 'BEGIN my %h; if /\s+(\d+)/ { %h{$0}++; }; last if $++ > 1000; END say +%h.keys' gen/moar/CORE.*setting
  Time (mean ± σ):     439.5 ms ±  35.2 ms    [User: 164.9 ms, System: 270.2 ms]
  Range (min … max):   360.0 ms … 490.9 ms    20 runs
 
Summary
  env MVM_SPESH_BLOCKING=0 MIMALLOC_ALLOW_THP=0 rakudo -ne 'BEGIN my %h; if /\s+(\d+)/ { %h{$0}++; }; last if $++ > 1000; END say +%h.keys' gen/moar/CORE.*setting ran
    1.91 ± 0.16 times faster than env MVM_SPESH_BLOCKING=0 MIMALLOC_ALLOW_THP=1 rakudo -ne 'BEGIN my %h; if /\s+(\d+)/ { %h{$0}++; }; last if $++ > 1000; END say +%h.keys' gen/moar/CORE.*setting

You can see the disparity in system time is about 190 milliseconds and the range of wall-clock time is 14ms wide with THP turned off, and 130ms wide with THP turned on.

I made a perf recording of my program once with THP allowed and once with THP disallowed with this command:

env MVM_SPESH_BLOCKING=0 MIMALLOC_ALLOW_THP=1 perf record --user-callchains -g --call-graph fp -F 20000 rakudo -ne 'BEGIN my %h; if /\s+(\d+)/ { %h{$0}++; }; last if $++ > 1000; END say +%h.keys' gen/moar/CORE.*setting

The results in the report are rather large, so I collapsed them. Takeaway is that with THP on it recorded 9k samples for the same workload that recorded 4k samples without THP.

Results of a perf recording with THP disallowed and one with THP allowed:

command for the reports: perf report --stdio --parent "mi_page_queue_find_free_ex" --exclude-other --sort=parent

# Total Lost Samples: 0
#
# Samples: 4K of event 'cpu/cycles/P'
# Event count (approx.): 1047552711
#
# Children      Self  Parent symbol                         
# ........  ........  ......................................
#
     7.54%     7.54%  mi_page_queue_find_free_ex.constprop.0
            |          
            |--5.73%--0x6d2e366c7265702f
            |          main
            |          |          
            |          |--5.08%--MVM_interp_run
            |          |          |          
            |          |          |--1.29%--MVM_6model_get_how
            |          |          |          MVM_6model_get_how
            |          |          |          MVM_gc_write_barrier (inlined)
            |          |          |          MVM_serialization_demand_object
            |          |          |          work_loop
            |          |          |          deserialize_object (inlined)
            |          |          |          |          
            |          |          |           --1.20%--deserialize
            |          |          |                     |          
            |          |          |                      --0.76%--MVM_gc_write_barrier (inlined)
            |          |          |                                |          
            |          |          |                                 --0.67%--MVM_serialization_read_ref
            |          |          |                                           MVM_gc_allocate_object
            |          |          |                                           MVM_gc_gen2_allocate_zeroed
            |          |          |                                           MVM_gc_gen2_allocate
            |          |          |                                           add_page (inlined)
            |          |          |                                           MVM_malloc (inlined)
            |          |          |                                           _mi_malloc_generic
            |          |          |                                           mi_page_queue_find_free_ex (inlined)
            |          |          |                                           |          
            |          |          |                                            --0.53%--mi_page_free_list_extend
            |          |          |                                                      |          
            |          |          |                                                       --0.51%--mi_block_set_next (inlined)
            |          |          |                                                                 mi_block_set_nextx (inlined)
            |          |          |          
            |          |           --1.00%--MVM_serialization_deserialize
            |          |                     |          
            |          |                      --0.87%--repossess
            |          |                                |          
            |          |                                 --0.80%--MVM_serialization_demand_stable
            |          |                                           MVM_gc_root_temp_pop (inlined)
            |          |                                           read_param_intern
            |          |                                           |          
            |          |                                            --0.70%--MVM_gc_allocate_gen2_default_set (inlined)
            |          |                                                      MVM_serialization_demand_object
            |          |                                                      work_loop
            |          |                                                      |          
            |          |                                                       --0.51%--deserialize_object (inlined)
[...]

and here the same setup but with THP allowed

# Total Lost Samples: 0
#
# Samples: 9K of event 'cpu/cycles/P'
# Event count (approx.): 2347591455
#
# Children      Self  Parent symbol                         
# ........  ........  ......................................
#
    47.52%    47.52%  mi_page_queue_find_free_ex.constprop.0
            |          
            |--45.05%--0x6d2e366c7265702f
            |          main
            |          |          
            |          |--43.79%--MVM_interp_run
            |          |          |          
            |          |          |--31.71%--MVM_load_bytecode
            |          |          |          MVM_cu_map_from_file
            |          |          |          MVM_cu_from_bytes
            |          |          |          MVM_bytecode_unpack
            |          |          |          |          
            |          |          |          |--30.13%--deserialize_frames (inlined)
            |          |          |          |          |          
            |          |          |          |          |--29.49%--MVM_repr_alloc_init
            |          |          |          |          |          MVM_gc_allocate_object
            |          |          |          |          |          MVM_gc_gen2_allocate_zeroed
            |          |          |          |          |          MVM_gc_gen2_allocate
            |          |          |          |          |          add_page (inlined)
            |          |          |          |          |          MVM_malloc (inlined)
            |          |          |          |          |          _mi_malloc_generic
            |          |          |          |          |          mi_page_queue_find_free_ex (inlined)
            |          |          |          |          |          |          
            |          |          |          |          |           --29.45%--mi_page_fresh_alloc
            |          |          |          |          |                     mi_arenas_page_regular_alloc
            |          |          |          |          |                     mi_arenas_page_regular_alloc
            |          |          |          |          |                     mi_page_free_list_extend
            |          |          |          |          |                     mi_block_set_next (inlined)
            |          |          |          |          |                     mi_block_set_nextx (inlined)
            |          |          |          |          |          
            |          |          |          |           --0.60%--MVM_malloc (inlined)
            |          |          |          |                     _mi_malloc_generic
            |          |          |          |                     mi_page_queue_find_free_ex (inlined)
            |          |          |          |                     mi_page_fresh_alloc
            |          |          |          |                     mi_arenas_page_regular_alloc
            |          |          |          |                     mi_arenas_page_regular_alloc
            |          |          |          |                     mi_page_free_list_extend
            |          |          |          |                     mi_block_set_next (inlined)
            |          |          |          |                     mi_block_set_nextx (inlined)
[...]

I only noticed this because there was a suspiciously long period on the bytecode specializer thread in MoarVM when it did its first batch of work, and for that period, basically 90% of samples were under mi_theap_realloc_zero going all the way into mi_block_set_nextx which had all of the self samples; mi_block_set_nextx is highlighted in darker yellow in the following two pictures:

and there were similar measurements the next time it worked:

these were recorded with the bytecode specializer thread in "blocking" mode, so that the thread that submitted the work waits for it to complete. that's why the main thread doesn't wake up at all during that time.

The main thread also has a few samples with mi_block_set_nextx but very noticeably less.

It makes sense for the workload in question where the main thread really only works with small arrays and hashes that die young, so memory usage wouldn't grow, whereas the specializer thread would be doing different-sized amounts of work for each bytecode frame it encounters, including potentially quite large temporary arrays.

running the workload with MIMALLOC_VERBOSE=1 MIMALLOC_SHOW_STATS=1 and THP allowed and disallowed. the output looks almost the same, but one has 1 fault to the other's 0, and of course the time taken for the THP allowed one is a bit longer by roughly 200ms system time

allowed:

mimalloc: process init: 0x7FCA03254000
v3.4.4 (built on Aug 24 2026, 14:57:01)
option 'show_errors': 0 
option 'show_stats': 1 
option 'verbose': 1 
option 'deprecated_eager_commit': 1 
option 'arena_eager_commit': 2 
option 'purge_decommits': 1 
option 'allow_large_os_pages': 0 
option 'reserve_huge_os_pages': 0 
option 'reserve_huge_os_pages_at': -1 
option 'reserve_os_memory': 0 KiB
option 'deprecated_segment_cache': 0 
option 'deprecated_page_reset': 0 
option 'deprecated_abandoned_page_purge': 0 
option 'deprecated_segment_reset': 0 
option 'deprecated_eager_commit_delay': 1 
option 'purge_delay': 1000 
option 'use_numa_nodes': 0 
option 'disallow_os_alloc': 0 
option 'os_tag': 100 
option 'max_errors': 32 
option 'max_warnings': 32 
option 'deprecated_max_segment_reclaim': 10 
option 'destroy_on_exit': 0 
option 'arena_reserve': 1048576 KiB
option 'arena_purge_mult': 1 
option 'deprecated_purge_extend_delay': 1 
option 'disallow_arena_alloc': 0 
option 'retry_on_oom': 400 
option 'deprecated_visit_abandoned': 1 
option 'guarded_min': 0 
option 'guarded_max': 1073741824 
option 'guarded_precise': 0 
option 'guarded_sample_rate': 0 
option 'guarded_sample_seed': 0 
option 'generic_collect': 10000 
option 'page_reclaim_on_free': 0 
option 'page_full_retain': 2 
option 'page_max_candidates': 4 
option 'max_vabits': 0 
option 'pagemap_commit': 0 
option 'page_commit_on_demand': 0 
option 'page_max_reclaim': -1 
option 'page_cross_thread_max_reclaim': 32 
option 'allow_thp': 1 
option 'minimal_purge_size': 0 KiB
option 'arena_max_object_size': 2097152 KiB
option 'arena_is_numa_local': 0 
debug level : 0
secure level: 0
mem tracking: none
mimalloc: reserved 1048576 KiB memory
mimalloc: using 5 numa regions
4
subproc 0
 pages           peak       total     current       block      total#   
  touched   :     0           0           0                                ok
  pages     :   717           1.2 K     700      
  abandoned :   550         837         271      
  reclaima  :     0      
  reclaimf  :   560      
  reabandon :     0      
  waits     :     0      
  extended  :     0      
  retire    :     0      
  searches  :     2.4 avg

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

 process         peak       total     current       block      total#   
  threads   :     2           2           2      
  numa nodes:     5
  elapsed   :     0.527 s
  process   : user: 0.185 s, system: 0.256 s, faults: 55, peak rss: 193.7 MiB, peak commit: 191.4 MiB

mimalloc: process done: 0x7FCA03254000

disallowed:

mimalloc: process init: 0x7FD95A8E2000
v3.4.4 (built on Aug 24 2026, 14:57:01)
option 'show_errors': 0 
option 'show_stats': 1 
option 'verbose': 1 
option 'deprecated_eager_commit': 1 
option 'arena_eager_commit': 2 
option 'purge_decommits': 1 
option 'allow_large_os_pages': 0 
option 'reserve_huge_os_pages': 0 
option 'reserve_huge_os_pages_at': -1 
option 'reserve_os_memory': 0 KiB
option 'deprecated_segment_cache': 0 
option 'deprecated_page_reset': 0 
option 'deprecated_abandoned_page_purge': 0 
option 'deprecated_segment_reset': 0 
option 'deprecated_eager_commit_delay': 1 
option 'purge_delay': 1000 
option 'use_numa_nodes': 0 
option 'disallow_os_alloc': 0 
option 'os_tag': 100 
option 'max_errors': 32 
option 'max_warnings': 32 
option 'deprecated_max_segment_reclaim': 10 
option 'destroy_on_exit': 0 
option 'arena_reserve': 1048576 KiB
option 'arena_purge_mult': 1 
option 'deprecated_purge_extend_delay': 1 
option 'disallow_arena_alloc': 0 
option 'retry_on_oom': 400 
option 'deprecated_visit_abandoned': 1 
option 'guarded_min': 0 
option 'guarded_max': 1073741824 
option 'guarded_precise': 0 
option 'guarded_sample_rate': 0 
option 'guarded_sample_seed': 0 
option 'generic_collect': 10000 
option 'page_reclaim_on_free': 0 
option 'page_full_retain': 2 
option 'page_max_candidates': 4 
option 'max_vabits': 0 
option 'pagemap_commit': 0 
option 'page_commit_on_demand': 0 
option 'page_max_reclaim': -1 
option 'page_cross_thread_max_reclaim': 32 
option 'allow_thp': 0 
option 'minimal_purge_size': 0 KiB
option 'arena_max_object_size': 2097152 KiB
option 'arena_is_numa_local': 0 
debug level : 0
secure level: 0
mem tracking: none
mimalloc: reserved 1048576 KiB memory
mimalloc: using 5 numa regions
4
subproc 0
 pages           peak       total     current       block      total#   
  touched   :     0           0           0                                ok
  pages     :   717           1.2 K     702      
  abandoned :   550         839         275      
  reclaima  :     0      
  reclaimf  :   558      
  reabandon :     0      
  waits     :     0      
  extended  :     0      
  retire    :     0      
  searches  :     2.4 avg

 arenas          peak       total     current       block      total#   
  reserved  :     1.0 GiB     1.0 GiB     1.0 GiB                          
  committed :   191.5 MiB   191.5 MiB   191.5 MiB                          
  reset     :     0      
  purged    :     2.6 MiB
  arenas    :     1      
  rollback  :     0      
  mmaps     :     4      
  commits   :     0      
  resets    :     0      
  purges    :    37      
  guarded   :     0      
  theaps    :     1           1           1      
  heaps     :     1           1           1      
  heap waits:     0      

 process         peak       total     current       block      total#   
  threads   :     2           2           2      
  numa nodes:     5
  elapsed   :     0.214 s
  process   : user: 0.158 s, system: 0.055 s, faults: 0, peak rss: 186.9 MiB, peak commit: 191.5 MiB

mimalloc: process done: 0x7FD95A8E2000

Again, maybe this is completely normal and expected, and users should turn MIMALLOC_ALLOW_THP off for short-lived processes, or turn THP in their system off if they don't want to deal with this kind of overhead.

Maybe mimalloc can submit some kind of madvise or something when it sets up a freelist of pages since that's what looks to be the cause of a lot of work on linux's MM?

here's the kernel portion of one of the perf recordings btw:

Thanks in advance for any advice!

[timo]

first_thirty_k_events_page_free_list_extend_and_return_and_malloc_generic.txt

here I've got traces for probes --add "_mi_malloc_generic size", --add='mi_page_free_list_extend bsize extend', and --add='mi_page_free_list_extend%return', just the first 30k out of 66k, and without stack traces, though I did record stacks. LMK if I can provide anything else helpful

[timo]

quick and dirty counting of amount of time between call and return to how often:

0.000001 => 107
0.000002 => 920
0.000003 => 3499
0.000004 => 1326
0.000005 => 151
0.000006 => 78
0.000007 => 16
0.000008 => 10
0.000009 => 5
0.00001 => 2
0.000011 => 7
0.000012 => 3
0.000013 => 3
0.000017 => 1
0.000021 => 1
0.000022 => 1
0.000024 => 2
0.000025 => 1
0.000029 => 1
0.00003 => 1
0.000031 => 1
0.000032 => 1
0.000033 => 4
0.000034 => 1
0.000035 => 5
0.000037 => 2
0.000038 => 1
0.00004 => 2
0.000041 => 1
0.000043 => 1
0.000044 => 2
0.000045 => 2
0.000049 => 1
0.000052 => 1
0.000055 => 1
0.000056 => 1
0.000058 => 2
0.000059 => 1
0.000062 => 1
0.000064 => 2
0.000065 => 1
0.000072 => 1
0.000075 => 2
0.000076 => 1
0.000077 => 1
0.000084 => 1
0.00009 => 1
0.000096 => 1
0.000108 => 1
0.000846 => 1
0.001336 => 1
0.0015 => 1
0.001662 => 1
0.001769 => 1
0.009973 => 1
0.010127 => 1
0.075421 => 1
:calls(6186)
:returns(6186)
:totaltime(0.124459)

broken down by the extend parameter to the page_free_list_extend function

calls to free_list_extend with extend parameter = 0x1
0.000001 => 44
0.000002 => 417
0.000003 => 1589
0.000004 => 792
0.000005 => 49
0.000006 => 44
0.000007 => 4
0.000008 => 3
0.000009 => 2
0.00001 => 1
0.000011 => 6
0.000012 => 2
0.000013 => 1
0.000017 => 1
0.000024 => 1
0.000029 => 1
0.00003 => 1
0.000031 => 1
0.000032 => 1
0.000033 => 3
0.000034 => 1
0.000035 => 4
0.000037 => 1
0.000038 => 1
0.00004 => 1
0.000041 => 1
0.000044 => 1
0.000045 => 2
0.000049 => 1
0.000052 => 1
0.000058 => 1
0.000059 => 1
0.000062 => 1
0.000064 => 2
0.000065 => 1
0.000072 => 1
0.000075 => 2
0.000077 => 1
0.000084 => 1
0.00009 => 1
0.000096 => 1
0.000846 => 1
0.0015 => 1
0.001769 => 1
0.009973 => 1
0.010127 => 1
0.075421 => 1
calls to free_list_extend with extend parameter = 0x2
0.000001 => 7
0.000002 => 41
0.000003 => 83
0.000004 => 30
0.000005 => 5
0.000006 => 3
0.000008 => 1
calls to free_list_extend with extend parameter = 0x3
0.000001 => 6
0.000002 => 9
0.000003 => 13
0.000004 => 13
0.000005 => 1
0.000006 => 2
calls to free_list_extend with extend parameter = 0x4
0.000001 => 2
0.000002 => 16
0.000003 => 108
0.000004 => 40
0.000005 => 3
0.000006 => 2
0.000035 => 1
0.001662 => 1
calls to free_list_extend with extend parameter = 0x5
0.000001 => 7
0.000002 => 19
0.000003 => 26
0.000004 => 10
0.000005 => 2
0.000013 => 1
calls to free_list_extend with extend parameter = 0x6
0.000002 => 3
0.000003 => 20
0.000004 => 8
0.000005 => 2
0.000033 => 1
calls to free_list_extend with extend parameter = 0x7
0.000001 => 1
0.000002 => 7
0.000003 => 2
calls to free_list_extend with extend parameter = 0x8
0.000001 => 1
0.000002 => 27
0.000003 => 90
0.000004 => 41
0.000005 => 6
0.000006 => 4
0.000007 => 1
0.000022 => 1
0.00004 => 1
0.001336 => 1
calls to free_list_extend with extend parameter = 0x9
0.000002 => 7
0.000003 => 27
0.000004 => 5
0.000005 => 1
0.000006 => 1
calls to free_list_extend with extend parameter = 0xa
0.000001 => 19
0.000002 => 65
0.000003 => 65
0.000004 => 1
0.000005 => 3
calls to free_list_extend with extend parameter = 0xc
0.000001 => 2
0.000002 => 15
0.000003 => 21
0.000004 => 15
calls to free_list_extend with extend parameter = 0xf
0.000002 => 11
calls to free_list_extend with extend parameter = 0x10
0.000001 => 6
0.000002 => 28
0.000003 => 94
0.000004 => 32
0.000005 => 6
0.000006 => 4
0.000007 => 2
0.000009 => 1
0.00001 => 1
0.000044 => 1
calls to free_list_extend with extend parameter = 0x12
0.000003 => 12
0.000004 => 2
calls to free_list_extend with extend parameter = 0x15
0.000002 => 4
0.000003 => 46
0.000004 => 8
0.000005 => 2
0.000006 => 1
0.000007 => 1
0.000009 => 1
calls to free_list_extend with extend parameter = 0x19
0.000002 => 8
0.000003 => 42
0.000004 => 8
calls to free_list_extend with extend parameter = 0x1f
0.000002 => 8
0.000003 => 1
calls to free_list_extend with extend parameter = 0x20
0.000001 => 2
0.000002 => 41
0.000003 => 75
0.000004 => 24
0.000005 => 6
0.000006 => 1
0.000007 => 2
0.000008 => 1
0.000055 => 1
0.000108 => 1
calls to free_list_extend with extend parameter = 0x24
0.000002 => 1
0.000003 => 64
0.000004 => 11
0.000005 => 1
0.000006 => 1
0.000008 => 1
calls to free_list_extend with extend parameter = 0x2a
0.000003 => 31
0.000004 => 13
0.000021 => 1
calls to free_list_extend with extend parameter = 0x33
0.000002 => 15
0.000003 => 128
0.000004 => 22
0.000005 => 4
0.000006 => 3
calls to free_list_extend with extend parameter = 0x3f
0.000001 => 2
0.000002 => 10
calls to free_list_extend with extend parameter = 0x40
0.000001 => 2
0.000002 => 38
0.000003 => 124
0.000004 => 42
0.000005 => 9
0.000007 => 1
0.000076 => 1
calls to free_list_extend with extend parameter = 0x55
0.000001 => 1
0.000002 => 40
0.000003 => 203
0.000004 => 37
0.000005 => 5
0.000006 => 3
0.000008 => 1
0.000011 => 1
calls to free_list_extend with extend parameter = 0x7f
0.000001 => 4
0.000002 => 35
0.000003 => 5
calls to free_list_extend with extend parameter = 0x80
0.000002 => 30
0.000003 => 467
0.000004 => 112
0.000005 => 35
0.000006 => 8
0.000007 => 4
0.000008 => 2
0.000009 => 1
0.000024 => 1
0.000025 => 1
0.000043 => 1
0.000056 => 1
0.000058 => 1
calls to free_list_extend with extend parameter = 0xff
0.000001 => 1
0.000002 => 7
0.000003 => 3
calls to free_list_extend with extend parameter = 0x100
0.000002 => 18
0.000003 => 105
0.000004 => 34
0.000005 => 8
0.000006 => 1
0.000007 => 1
0.000012 => 1
0.000013 => 1
0.000037 => 1
calls to free_list_extend with extend parameter = 0x1ff
0.000003 => 3
0.000004 => 2
calls to free_list_extend with extend parameter = 0x200
0.000003 => 52
0.000004 => 24
0.000005 => 3
0.000008 => 1
:calls(6186)
:returns(6186)
:totaltime(0.124459)

The same for MIMALLOC_ALLOW_THP=0 is a whole lot shorter:

0.000001 => 86
0.000002 => 853
0.000003 => 2707
0.000004 => 2032
0.000005 => 243
0.000006 => 140
0.000007 => 44
0.000008 => 26
0.000009 => 10
0.00001 => 3
0.000011 => 5
0.000012 => 1
0.000013 => 1
0.000014 => 6
0.000015 => 2
0.000016 => 2
0.000017 => 3
0.000019 => 1
0.00002 => 1
0.000022 => 1
0.000023 => 1
0.000029 => 1
0.00003 => 2
0.000031 => 1
0.000033 => 3
0.000048 => 1
0.000051 => 1
0.000056 => 1
0.000057 => 1
0.000059 => 1
0.00012 => 1
0.000167 => 1
:calls(6182)
:returns(6182)
:totaltime(0.02187)

broken down by the extend parameter to the page_free_list_extend function

calls to free_list_extend with extend parameter = 0x1
0.000001 => 44
0.000002 => 417
0.000003 => 1589
0.000004 => 792
0.000005 => 49
0.000006 => 44
0.000007 => 4
0.000008 => 3
0.000009 => 2
0.00001 => 1
0.000011 => 6
0.000012 => 2
0.000013 => 1
0.000017 => 1
0.000024 => 1
0.000029 => 1
0.00003 => 1
0.000031 => 1
0.000032 => 1
0.000033 => 3
0.000034 => 1
0.000035 => 4
0.000037 => 1
0.000038 => 1
0.00004 => 1
0.000041 => 1
0.000044 => 1
0.000045 => 2
0.000049 => 1
0.000052 => 1
0.000058 => 1
0.000059 => 1
0.000062 => 1
0.000064 => 2
0.000065 => 1
0.000072 => 1
0.000075 => 2
0.000077 => 1
0.000084 => 1
0.00009 => 1
0.000096 => 1
0.000846 => 1
0.0015 => 1
0.001769 => 1
0.009973 => 1
0.010127 => 1
0.075421 => 1
calls to free_list_extend with extend parameter = 0x2
0.000001 => 7
0.000002 => 41
0.000003 => 83
0.000004 => 30
0.000005 => 5
0.000006 => 3
0.000008 => 1
calls to free_list_extend with extend parameter = 0x3
0.000001 => 6
0.000002 => 9
0.000003 => 13
0.000004 => 13
0.000005 => 1
0.000006 => 2
calls to free_list_extend with extend parameter = 0x4
0.000001 => 2
0.000002 => 16
0.000003 => 108
0.000004 => 40
0.000005 => 3
0.000006 => 2
0.000035 => 1
0.001662 => 1
calls to free_list_extend with extend parameter = 0x5
0.000001 => 7
0.000002 => 19
0.000003 => 26
0.000004 => 10
0.000005 => 2
0.000013 => 1
calls to free_list_extend with extend parameter = 0x6
0.000002 => 3
0.000003 => 20
0.000004 => 8
0.000005 => 2
0.000033 => 1
calls to free_list_extend with extend parameter = 0x7
0.000001 => 1
0.000002 => 7
0.000003 => 2
calls to free_list_extend with extend parameter = 0x8
0.000001 => 1
0.000002 => 27
0.000003 => 90
0.000004 => 41
0.000005 => 6
0.000006 => 4
0.000007 => 1
0.000022 => 1
0.00004 => 1
0.001336 => 1
calls to free_list_extend with extend parameter = 0x9
0.000002 => 7
0.000003 => 27
0.000004 => 5
0.000005 => 1
0.000006 => 1
calls to free_list_extend with extend parameter = 0xa
0.000001 => 19
0.000002 => 65
0.000003 => 65
0.000004 => 1
0.000005 => 3
calls to free_list_extend with extend parameter = 0xc
0.000001 => 2
0.000002 => 15
0.000003 => 21
0.000004 => 15
calls to free_list_extend with extend parameter = 0xf
0.000002 => 11
calls to free_list_extend with extend parameter = 0x10
0.000001 => 6
0.000002 => 28
0.000003 => 94
0.000004 => 32
0.000005 => 6
0.000006 => 4
0.000007 => 2
0.000009 => 1
0.00001 => 1
0.000044 => 1
calls to free_list_extend with extend parameter = 0x12
0.000003 => 12
0.000004 => 2
calls to free_list_extend with extend parameter = 0x15
0.000002 => 4
0.000003 => 46
0.000004 => 8
0.000005 => 2
0.000006 => 1
0.000007 => 1
0.000009 => 1
calls to free_list_extend with extend parameter = 0x19
0.000002 => 8
0.000003 => 42
0.000004 => 8
calls to free_list_extend with extend parameter = 0x1f
0.000002 => 8
0.000003 => 1
calls to free_list_extend with extend parameter = 0x20
0.000001 => 2
0.000002 => 41
0.000003 => 75
0.000004 => 24
0.000005 => 6
0.000006 => 1
0.000007 => 2
0.000008 => 1
0.000055 => 1
0.000108 => 1
calls to free_list_extend with extend parameter = 0x24
0.000002 => 1
0.000003 => 64
0.000004 => 11
0.000005 => 1
0.000006 => 1
0.000008 => 1
calls to free_list_extend with extend parameter = 0x2a
0.000003 => 31
0.000004 => 13
0.000021 => 1
calls to free_list_extend with extend parameter = 0x33
0.000002 => 15
0.000003 => 128
0.000004 => 22
0.000005 => 4
0.000006 => 3
calls to free_list_extend with extend parameter = 0x3f
0.000001 => 2
0.000002 => 10
calls to free_list_extend with extend parameter = 0x40
0.000001 => 2
0.000002 => 38
0.000003 => 124
0.000004 => 42
0.000005 => 9
0.000007 => 1
0.000076 => 1
calls to free_list_extend with extend parameter = 0x55
0.000001 => 1
0.000002 => 40
0.000003 => 203
0.000004 => 37
0.000005 => 5
0.000006 => 3
0.000008 => 1
0.000011 => 1
calls to free_list_extend with extend parameter = 0x7f
0.000001 => 4
0.000002 => 35
0.000003 => 5
calls to free_list_extend with extend parameter = 0x80
0.000002 => 30
0.000003 => 467
0.000004 => 112
0.000005 => 35
0.000006 => 8
0.000007 => 4
0.000008 => 2
0.000009 => 1
0.000024 => 1
0.000025 => 1
0.000043 => 1
0.000056 => 1
0.000058 => 1
calls to free_list_extend with extend parameter = 0xff
0.000001 => 1
0.000002 => 7
0.000003 => 3
calls to free_list_extend with extend parameter = 0x100
0.000002 => 18
0.000003 => 105
0.000004 => 34
0.000005 => 8
0.000006 => 1
0.000007 => 1
0.000012 => 1
0.000013 => 1
0.000037 => 1
calls to free_list_extend with extend parameter = 0x1ff
0.000003 => 3
0.000004 => 2
calls to free_list_extend with extend parameter = 0x200
0.000003 => 52
0.000004 => 24
0.000005 => 3
0.000008 => 1
:calls(6186)
:returns(6186)
:totaltime(0.124459)

[daanx]

Wow, very interesting timo -- the "extend free" is the first time the memory is touched so only at that point the Linux MM gets to work. Usually though THP makes programs faster... I wonder if what you see is partly a fragmented memory system where the OS needs to move physical 4k pages to make space for a single huge page? Not sure what we can do about this .. I agree that for short lived programs it is probably better to disable THP but sometimes I have seen significant performance gains as well so difficult to say what is best.

Also, you many want to try v3.5 (or the latest dev3) for MoarVM as it has a slightly faster mi_free(_small) that may benefit in particular small allocations. YMMV.

[timo]

Wow, you were not kidding!

turned off a VM that used roughly 18 gigs of ram:

and now the performance numbers have turned around:

  env MVM_SPESH_BLOCKING=0 MIMALLOC_ALLOW_THP=1 rakudo -ne 'BEGIN my %h; if /\s+(\d+)/ { %h{$0}++; }; last if $++ > 1000; END say +%h.keys' rakudo/gen/moar/CORE.*setting ran
    1.28 ± 0.07 times faster than env MVM_SPESH_BLOCKING=0 MIMALLOC_ALLOW_THP=0 rakudo -ne 'BEGIN my %h; if /\s+(\d+)/ { %h{$0}++; }; last if $++ > 1000; END say +%h.keys' rakudo/gen/moar/CORE.*setting

That's fascinating! I was at roughly as much "Free" memory as this workload reached at its peak, but had somewhere around 6 gigabytes of "Available" memory, and I would guess it's just like you assumed: the kernel was moving physical pages around for some pages to be brought together and become a huge page. The big surprise, to me at least, is that it blocked the process while doing that? Or maybe I was measuring only a small part of the work and the kernel was doing more work in a background thread (presumably what kcompactd0 and khugepaged do).

All of this means that if you have transparent huge pages turned on, and some programs allow THP, then the "actually unused memory" that is usually fine to have hover around 0 can be a cause for performance degradation?

I guess this means that mimalloc isn't at fault here at all, and this was just a false alarm. Fascinating hunt for the cause, though.

If you agree, you can close this issue, or use it as a task to figure out if something can be done against the potential performance degradation.

It would probably be too expensive to measure the time it takes to extend a free list and if a slow queue extend operation is encountered, turn the madvise that allows THP back off, maybe just for a while and try again later?

Thanks for lending me your ear in any case!

[daanx]

Nice investigation timo. I think the unpredicatable performance of THP is why it is configurable at the OS level (always,madvise,or never) instead of always being on. Currently, by default mimalloc respects the user OS setting and uses madvise for huge pages when the OS setting is not never (and the huge pages usually work well with the large arena areas).
Btw. windows has the same issue when requesting 1 GiB pages which can take a long time when the memory is physically fragmented , which is why mimalloc even has a mechanism to time out on huge page reservations.