fio 3.36 hit out of memory when add 'verify' parameter

[ll123456]

Please acknowledge the following before creating a ticket

• [√ ] I have read the GitHub issues section of REPORTING-BUGS.

Description of the bug:
I encountered out of memory while running the fio command on 3.36, but it was normal in version 3.19

sudo fio -filename=/dev/nvme0n1 -size=100% -iodepth=256 -rw=randwrite -bssplit=512/10:1536/30:2048/20:3584/40 -numjobs=1 -name=fiotest -direct=1 -ioengine=libaio -group_reporting -do_verify=1 -verify=crc64 -verify_interval=4096 -random_generator=tausworthe64 -buffer_compress_chunk=4k -buffer_compress_percentage=7

error info:
fio-3.36
Starting 1 process
fio: pid=149019, got signal=9

fiotest: (groupid=0, jobs=1): err= 0: pid=149019: Tue Mar 26 15:41:51 2024
lat (usec) : 100=0.98%, 250=10.68%, 500=11.53%, 750=1.66%, 1000=6.82%
lat (msec) : 2=24.08%, 4=26.26%, 10=13.56%, 20=3.58%, 50=0.83%
lat (msec) : 100=0.01%, 250=0.01%, 500=0.01%
cpu : usr=0.00%, sys=0.00%, ctx=0, majf=0, minf=0
IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=0.1%, 32=0.1%, >=64=100.0%
submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
issued rwts: total=0,609812161,0,0 short=0,0,0,0 dropped=0,0,0,0
latency : target=0, window=0, percentile=100.00%, depth=256

Run status group 0 (all jobs):

Disk stats (read/write):
nvme0n1: ios=47/609812161, sectors=2128/2569856882, merge=0/0, ticks=3/1553222155, in_queue=1553222158, util=100.00%
free(): double free detected in tcache 2

Environment:
redhat9
[root@localhost ~]# uname -a
Linux localhost.localdomain 5.14.0-362.18.1.el9_3.x86_64 #1 SMP PREEMPT_DYNAMIC Wed Jan 3 15:54:45 EST 2024 x86_64 x86_64 x86_64 GNU/Linux

fio version:
[root@localhost ~]# fio --version
fio-3.36

Reproduction steps
sudo fio -filename=/dev/nvme0n1 -size=100% -iodepth=256 -rw=randwrite -bssplit=512/10:1536/30:2048/20:3584/40 -numjobs=1 -name=fiotest -direct=1 -ioengine=libaio -group_reporting -do_verify=1 -verify=crc64 -verify_interval=4096 -random_generator=tausworthe64 -buffer_compress_chunk=4k -buffer_compress_percentage=7

memory info
[root@localhost ~]# free -m
total used free shared buff/cache available
Mem: 63843 2712 61154 108 721 61131
Swap: 4095 441 3654

dmesg info:
[14650.887160] NetworkManager invoked oom-killer: gfp_mask=0x140cca(GFP_HIGHUSER_MOVABLE|__GFP_COMP), order=0, oom_score_adj=0
[14650.887165] CPU: 9 PID: 1084 Comm: NetworkManager Kdump: loaded Tainted: G OE ------- --- 5.14.0-362.18.1.el9_3.x86_64 #1
[14650.887167] Hardware name: ASUS System Product Name/PRIME Z790-P, BIOS 1402 09/08/2023
[14650.887168] Call Trace:
[14650.887169]
[14650.887171] dump_stack_lvl+0x34/0x48
[14650.887175] dump_header+0x4a/0x201
[14650.887177] oom_kill_process.cold+0xb/0x10
[14650.887178] out_of_memory+0xed/0x2e0
[14650.887181] __alloc_pages_slowpath.constprop.0+0x6e8/0x960
[14650.887185] __alloc_pages+0x21d/0x250
[14650.887186] folio_alloc+0x17/0x50
[14650.887188] __filemap_get_folio+0x1cd/0x330
[14650.887191] filemap_fault+0x40b/0x740
[14650.887193] __do_fault+0x33/0x140
[14650.887195] do_read_fault+0xf0/0x160
[14650.887196] do_fault+0xa9/0x390
[14650.887197] __handle_mm_fault+0x585/0x650
[14650.887200] handle_mm_fault+0xc5/0x2a0
[14650.887201] do_user_addr_fault+0x1b4/0x6a0
[14650.887204] exc_page_fault+0x62/0x150
[14650.887206] asm_exc_page_fault+0x22/0x30
[14650.887209] RIP: 0033:0x557e50d83dd0
[14650.887225] Code: Unable to access opcode bytes at RIP 0x557e50d83da6.
[14650.887225] RSP: 002b:00007ffd04560448 EFLAGS: 00010202
[14650.887227] RAX: 0000000000000000 RBX: 00007ffd04560478 RCX: 0000000000000018
[14650.887228] RDX: 000000000185df2a RSI: 000000000000393a RDI: 0000557e5171e400
[14650.887229] RBP: 0000557e516894f0 R08: 00007fe5b221b2fe R09: 0000000000000000
[14650.887230] R10: 00007ffd045df080 R11: 00007ffd045df090 R12: 0000557e5171e400
[14650.887230] R13: 0000557e50d83dd0 R14: 00007ffd04560490 R15: 00000d531de9546d
[14650.887232]
[14650.887233] Mem-Info:
[14650.887234] active_anon:167679 inactive_anon:15995659 isolated_anon:0
active_file:315 inactive_file:195 isolated_file:0
unevictable:2609 dirty:0 writeback:0
slab_reclaimable:12758 slab_unreclaimable:21233
mapped:16254 shmem:24036 pagetables:37045
sec_pagetables:0 bounce:0
kernel_misc_reclaimable:0
free:82432 free_pcp:0 free_cma:0
...
[14650.887273] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=1048576kB
[14650.887275] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB
[14650.887275] 42473 total pagecache pages
[14650.887276] 18117 pages in swap cache
[14650.887276] Free swap = 0kB
[14650.887277] Total swap = 4194300kB
[14650.887277] 16711020 pages RAM
[14650.887277] 0 pages HighMem/MovableOnly
[14650.887278] 366975 pages reserved
[14650.887278] 0 pages cma reserved
[14650.887278] 0 pages hwpoisoned
[14650.887279] Tasks state (memory values in pages):
[14650.887279] [ pid ] uid tgid total_vm rss pgtables_bytes swapents oom_score_adj name
[14650.887289] [ 761] 0 761 46543 28920 409600 239 -250 systemd-journal
[14650.887292] [ 776] 0 776 8683 564 94208 553 -1000 systemd-udevd
[14650.887294] [ 920] 32 920 3310 6 61440 203 0 rpcbind
[14650.887296] [ 923] 0 923 22975 81 69632 672 -1000 auditd
[14650.887298] [ 925] 0 925 1946 5 57344 87 0 sedispatch
[14650.887299] [ 946] 81 946 2755 44 61440 187 -900 dbus-broker-lau
[14650.887301] [ 947] 81 947 2223 203 61440 335 -900 dbus-broker
[14650.887302] [ 948] 70 948 3911 122 69632 189 0 avahi-daemon
[14650.887303] [ 951] 0 951 19816 43 57344 36 0 irqbalance
[14650.887304] [ 952] 993 952 676 1 40960 40 0 lsmd
[14650.887305] [ 955] 0 955 827 0 40960 39 0 mcelog
[14650.887307] [ 956] 997 956 746497 1929 270336 774 0 polkitd
[14650.887308] [ 957] 0 957 112995 110 114688 604 0 power-profiles-
[14650.887309] [ 958] 0 958 77313 13639 344064 2382 0 rsyslogd
[14650.887310] [ 959] 172 959 38528 0 61440 82 0 rtkit-daemon
[14650.887312] [ 960] 0 960 2938 38 61440 317 0 smartd
[14650.887313] [ 961] 0 961 112987 76 118784 1219 0 accounts-daemon
[14650.887314] [ 962] 0 962 112035 31 114688 612 0 switcheroo-cont
[14650.887315] [ 964] 0 964 12805 137 106496 199 0 systemd-logind
[14650.887316] [ 965] 0 965 98759 406 135168 823 0 udisksd
[14650.887317] [ 966] 0 966 112193 86 106496 1139 0 upowerd
[14650.887318] [ 968] 70 968 3811 14 65536 202 0 avahi-daemon
[14650.887320] [ 972] 975 972 21095 45 61440 124 0 chronyd
[14650.887321] [ 988] 0 988 1210 1 49152 89 0 alsactl
[14650.887323] [ 1020] 0 1020 60735 204 110592 266 0 ModemManager
[14650.887324] [ 1084] 0 1084 118509 425 151552 828 0 NetworkManager
[14650.887325] [ 1088] 0 1088 61839 138 114688 394 0 cupsd
[14650.887326] [ 1090] 0 1090 306384 517 163840 2637 0 probe
[14650.887327] [ 1093] 0 1093 4020 33 73728 375 -1000 sshd
[14650.887328] [ 1095] 0 1095 55670 1 57344 40 0 rhsmcertd
[14650.887329] [ 1099] 0 1099 67592 0 106496 732 0 gssproxy
[14650.887331] [ 1120] 0 1120 435895 2003 233472 1957 0 probe
[14650.887332] [ 1176] 0 1176 60529 580 118784 584 0 snmpd
[14650.887333] [ 1203] 0 1203 4836 66 77824 510 0 sshd
[14650.887334] [ 1283] 989 1283 4659 208 73728 263 0 pmcd
[14650.887336] [ 1287] 0 1287 4640 38 77824 234 0 pmdaroot
[14650.887337] [ 1290] 0 1290 4461 45 73728 231 0 pmdaxfs
[14650.887338] [ 1302] 0 1302 4475 33 73728 284 0 pmdakvm
[14650.887339] [ 1303] 0 1303 4602 33 73728 249 0 pmdadm
[14650.887340] [ 1879] 989 1879 4535 98 77824 231 0 pmie
[14650.887341] [ 1883] 989 1883 4418 0 73728 243 0 pmpause
[14650.887342] [ 7628] 0 7628 1167 14 49152 31 0 atd
[14650.887343] [ 7629] 0 7629 55979 34 77824 178 0 crond
[14650.887344] [ 7630] 0 7630 113269 1 114688 1293 0 gdm
[14650.887346] [ 7634] 0 7634 4984 95 73728 376 100 systemd
[14650.887347] [ 7654] 0 7654 5941 166 81920 986 100 (sd-pam)
[14650.887348] [ 7717] 42 7717 4985 107 73728 377 100 systemd
[14650.887349] [ 7723] 42 7723 5955 209 81920 946 100 (sd-pam)
[14650.887350] [ 7846] 42 7846 2633 0 61440 106 200 dbus-broker-lau
[14650.887351] [ 7847] 0 7847 4920 176 81920 453 0 sshd
[14650.887352] [ 7858] 0 7858 56089 2 69632 550 0 bash
[14650.887353] [ 7950] 42 7950 1215 7 57344 54 200 dbus-broker
[14650.887355] [ 8325] 0 8325 96702 1 122880 926 0 gdm-session-wor
[14650.887356] [ 8328] 42 8328 94427 0 102400 684 0 gdm-x-session
[14650.887357] [ 8330] 42 8330 448062 2545 548864 5065 0 Xorg
[14650.887358] [ 8419] 42 8419 1650 0 53248 61 0 dbus-run-sessio
[14650.887359] [ 8420] 42 8420 3904 1 69632 330 0 dbus-daemon
[14650.887360] [ 8421] 42 8421 165239 154 204800 1530 0 gnome-session-b
[14650.887362] [ 8445] 42 8445 77184 0 98304 239 0 at-spi-bus-laun
[14650.887363] [ 8450] 42 8450 3830 0 69632 237 0 dbus-daemon
[14650.887364] [ 8475] 42 8475 1324994 13703 1032192 6160 0 gnome-shell
[14650.887365] [ 8591] 42 8591 131655 1 131072 1661 0 ibus-daemon
[14650.887367] [ 8594] 42 8594 112274 0 110592 189 0 ibus-dconf
[14650.887368] [ 8597] 42 8597 109803 0 180224 1639 0 ibus-x11
[14650.887369] [ 8605] 42 8605 112256 1 110592 689 0 ibus-portal
[14650.887370] [ 8611] 42 8611 40444 0 81920 220 0 at-spi2-registr
[14650.887371] [ 8626] 42 8626 112022 0 106496 653 0 xdg-permission-
[14650.887372] [ 8739] 42 8739 64493 0 102400 841 200 pipewire
[14650.887374] [ 8741] 42 8741 136449 47 155648 1706 200 wireplumber
[14650.887375] [ 8742] 42 8742 59274 0 86016 345 200 pipewire-pulse
[14650.887376] [ 8960] 0 8960 3811 0 69632 218 0 wpa_supplicant
[14650.887377] [ 8987] 0 8987 121649 1133 184320 2345 0 packagekitd
[14650.887378] [ 9053] 42 9053 782023 1 278528 1386 0 gjs
[14650.887379] [ 9075] 42 9075 169422 157 147456 719 0 gsd-sharing
[14650.887380] [ 9078] 42 9078 146604 0 192512 1249 0 gsd-wacom
[14650.887381] [ 9080] 42 9080 165653 61 208896 1144 0 gsd-color
[14650.887382] [ 9084] 42 9084 146486 0 188416 1676 0 gsd-keyboard
[14650.887383] [ 9086] 42 9086 116703 50 147456 910 0 gsd-print-notif
[14650.887384] [ 9088] 42 9088 167405 0 135168 1226 0 gsd-rfkill
[14650.887385] [ 9090] 42 9090 150733 4 143360 861 0 gsd-smartcard
[14650.887387] [ 9092] 42 9092 148582 0 204800 1175 0 gsd-datetime
[14650.887388] [ 9094] 42 9094 201191 154 221184 1691 0 gsd-media-keys
[14650.887389] [ 9096] 42 9096 112010 0 102400 668 0 gsd-screensaver
[14650.887390] [ 9098] 42 9098 132669 0 131072 807 0 gsd-sound
[14650.887392] [ 9100] 42 9100 130533 0 114688 701 0 gsd-a11y-settin
[14650.887393] [ 9103] 42 9103 131124 31 114688 659 0 gsd-housekeepin
[14650.887394] [ 9104] 42 9104 165337 154 217088 1094 0 gsd-power
[14650.887395] [ 9207] 42 9207 93810 0 98304 685 0 ibus-engine-sim
[14650.887396] [ 9209] 996 9209 114170 0 126976 1075 0 colord
[14650.887397] [ 9212] 42 9212 800456 1 282624 1336 0 gjs
[14650.887398] [ 9301] 42 9301 149480 0 208896 1722 0 gsd-printer
[14650.887399] [ 11968] 0 11968 55855 33 73728 96 0 tmux: client
[14650.887400] [ 11970] 0 11970 57265 1183 69632 101 0 tmux: server
[14650.887402] [ 11971] 0 11971 56155 2 73728 607 0 bash
[14650.887403] [ 12058] 0 12058 56128 2 77824 597 0 bash
[14650.887404] [ 13119] 0 13119 59574 0 106496 384 0 sudo
[14650.887405] [ 13120] 0 13120 56295 975 77824 36 0 minicom
[14650.887406] [ 13370] 0 13370 4872 50 73728 514 0 sshd
[14650.887407] [ 13515] 1000 13515 4976 86 77824 385 100 systemd
[14650.887409] [ 13516] 1000 13516 42821 415 98304 751 100 (sd-pam)
[14650.887410] [ 13540] 1000 13540 5256 446 77824 559 0 sshd
[14650.887411] [ 15267] 1000 15267 5383509 27279 1048576 22318 0 java
[14650.887412] [ 18260] 0 18260 4872 505 73728 61 0 sshd
[14650.887413] [ 18261] 0 18261 4872 522 77824 44 0 sshd
[14650.887414] [ 18427] 1000 18427 5038 681 81920 97 0 sshd
[14650.887416] [ 18428] 1000 18428 4945 447 77824 249 0 sshd
[14650.887417] [ 19567] 1000 19567 5232979 18368 884736 17972 0 java
[14650.887418] [ 20769] 1000 20769 5248851 18389 884736 19517 0 java
[14650.887419] [ 112519] 989 112519 5744 1187 86016 383 0 pmlogger
[14650.887420] [ 112547] 989 112547 4418 0 77824 243 0 pmpause
[14650.887422] [ 138638] 0 138638 4858 354 77824 226 0 pmdaproc
[14650.887423] [ 138644] 0 138644 4684 427 73728 0 0 pmdalinux
[14650.887424] [ 145788] 0 145788 56095 1 77824 553 0 bash
[14650.887425] [ 145947] 0 145947 153835 2563 524288 19634 0 python3
[14650.887426] [ 147010] 0 147010 55662 45 69632 80 0 MemoryCheckEver
[14650.887427] [ 149004] 0 149004 59574 0 106496 384 0 sudo
[14650.887428] [ 149005] 0 149005 114455 135 131072 98 0 fio
[14650.887429] [ 149019] 0 149019 17005433 16020048 135610368 887541 0 fio
[14650.887431] [ 165475] 0 165475 55238 22 77824 0 0 sleep
[14650.887433] oom-kill:constraint=CONSTRAINT_NONE,nodemask=(null),cpuset=/,mems_allowed=0,global_oom,task_memcg=/user.slice/user-0.slice/session-1.scope,task=fio,pid=149019,uid=0
[14650.887441] Out of memory: Killed process 149019 (fio) total-vm:68021732kB, anon-rss:64080116kB, file-rss:0kB, shmem-rss:76kB, UID:0 pgtables:132432kB oom_score_adj:0

[vincentkfu]

I ran your job on a small (1000M) device and found no issues with fio 3.37 or 3.36:

root@localhost:~/fio-dev/fio-canonical# ./fio -filename=/dev/nvme0n1 -size=100% -iodepth=256 -rw=randwrite -bssplit=512/10:1536/30:2048/20:3584/40 -numjobs=1 -name=fiotest -direct=1 -ioengine=libaio -group_reporting -do_verify=1 -verify=crc64 -verify_interval=4096 -random_generator=tausworthe64 -buffer_compress_chunk=4k -buffer_compress_percentage=7
fiotest: (g=0): rw=randwrite, bs=(R) 512B-3584B, (W) 512B-3584B, (T) 512B-3584B, ioengine=libaio, iodepth=256
fio-3.37-1-g4eef
Starting 1 process
Jobs: 1 (f=1): [V(1)][100.0%][r=58.6MiB/s][r=42.5k IOPS][eta 00m:00s]
fiotest: (groupid=0, jobs=1): err= 0: pid=301823: Tue Apr  2 18:03:07 2024
  read: IOPS=37.1k, BW=63.7MiB/s (66.8MB/s)(1000MiB/15706msec)
    slat (nsec): min=1227, max=981299, avg=18487.16, stdev=19282.17
    clat (usec): min=55, max=14357, avg=6881.16, stdev=2017.12
     lat (usec): min=68, max=14387, avg=6899.64, stdev=2021.13
    clat percentiles (usec):
     |  1.00th=[ 4490],  5.00th=[ 4686], 10.00th=[ 5211], 20.00th=[ 5538],
     | 30.00th=[ 5735], 40.00th=[ 5866], 50.00th=[ 6063], 60.00th=[ 6390],
     | 70.00th=[ 6980], 80.00th=[ 8160], 90.00th=[10421], 95.00th=[11600],
     | 99.00th=[12780], 99.50th=[13042], 99.90th=[13435], 99.95th=[13829],
     | 99.99th=[14091]
  write: IOPS=35.1k, BW=60.3MiB/s (63.2MB/s)(1000MiB/16594msec); 0 zone resets
    slat (usec): min=3, max=5198, avg=25.98, stdev=22.14
    clat (usec): min=119, max=16345, avg=7268.64, stdev=2131.85
     lat (usec): min=123, max=16389, avg=7294.62, stdev=2138.22
    clat percentiles (usec):
     |  1.00th=[ 4686],  5.00th=[ 4883], 10.00th=[ 5473], 20.00th=[ 5735],
     | 30.00th=[ 5932], 40.00th=[ 6063], 50.00th=[ 6390], 60.00th=[ 6980],
     | 70.00th=[ 7767], 80.00th=[ 8717], 90.00th=[11076], 95.00th=[11994],
     | 99.00th=[13173], 99.50th=[13698], 99.90th=[14484], 99.95th=[14877],
     | 99.99th=[15795]
   bw (  KiB/s): min= 6415, max=87865, per=97.61%, avg=60235.26, stdev=13300.75, samples=34
   iops        : min= 4720, max=40662, avg=34234.47, stdev=5780.54, samples=34
  lat (usec)   : 100=0.01%, 250=0.01%, 500=0.01%, 750=0.01%, 1000=0.01%
  lat (msec)   : 2=0.01%, 4=0.02%, 10=87.07%, 20=12.90%
  cpu          : usr=32.33%, sys=67.65%, ctx=159, majf=0, minf=13842
  IO depths    : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=0.1%, 32=0.1%, >=64=100.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.1%
     issued rwts: total=581986,581986,0,0 short=0,0,0,0 dropped=0,0,0,0
     latency   : target=0, window=0, percentile=100.00%, depth=256

Run status group 0 (all jobs):
   READ: bw=63.7MiB/s (66.8MB/s), 63.7MiB/s-63.7MiB/s (66.8MB/s-66.8MB/s), io=1000MiB (1049MB), run=15706-15706msec
  WRITE: bw=60.3MiB/s (63.2MB/s), 60.3MiB/s-60.3MiB/s (63.2MB/s-63.2MB/s), io=1000MiB (1049MB), run=16594-16594msec

Disk stats (read/write):
  nvme0n1: ios=574972/581986, sectors=2032671/2048000, merge=0/0, ticks=75626/73500, in_queue=149127, util=99.85%

Observing the output of free -m during the run, fio seemed to use no more than 100M of RAM.

Consider trying to identify the first fio version where you encounter an OOM issue and then use git bisect to narrow it down to the exact commit responsible.

[ll123456]

@vincentkfu I can reproduce this issue on 3.2T/3.84T device with this job, and found no issues with fio 3.19.
I will verify fio versions between 3.20 and 3.36

[vincentkfu]

I started running this on a 3.84T device and saw fio's memory consumption steadily increase through 10+ GiB before I stopped it.

I believe what is happening is that fio is logging every write operation so that it can later read the blocks back for verification. I don't know what changed between fio 3.19 and 3.36.

One work-around is to run your job with --experimental_verify=1. With this option enabled fio no longer logs every write operation but instead resets the random number generators to the starting seed value when the read phase begins. The random number generators produce the same sequence of offsets and block sizes but this time fio issues read operations to verify the data that was written.

[ll123456]

@vincentkfu I can reproduce this issue on 3.2T/3.84T device with this job, and found no issues with fio 3.19. I will verify fio versions between 3.20 and 3.36

I have tried many versions of fio and found that I will encounter this problem all the time, this seems to have always existed.

[ll123456]

I started running this on a 3.84T device and saw fio's memory consumption steadily increase through 10+ GiB before I stopped it.

I believe what is happening is that fio is logging every write operation so that it can later read the blocks back for verification. I don't know what changed between fio 3.19 and 3.36.

One work-around is to run your job with --experimental_verify=1. With this option enabled fio no longer logs every write operation but instead resets the random number generators to the starting seed value when the read phase begins. The random number generators produce the same sequence of offsets and block sizes but this time fio issues read operations to verify the data that was written.

@vincentkfu , I haven't encountered this problem again after adding this parameter，thank you。