v3.2.6: assertion failures on Debian i386

[pitrou]

I've been testing the v3.2.6 release candidate on the Apache Arrow CI jobs, and we get assertion failures on Debian i386 (32-bit) on all our unit tests.

Here are the full logs:
https://productionresultssa8.blob.core.windows.net/actions-results/b9e69351-eb38-4866-afb7-37eeacd9a404/workflow-job-run-ce200fd7-7937-5c45-b048-66dd2b022568/logs/job/job-logs.txt?rsct=text%2Fplain&se=2026-01-12T10%3A10%3A04Z&sig=iRvbbY6wJbu4TPUqcYyoIfZlLJ3IQuZ%2BMBLFXFbgSg4%3D&ske=2026-01-12T18%3A52%3A42Z&skoid=ca7593d4-ee42-46cd-af88-8b886a2f84eb&sks=b&skt=2026-01-12T06%3A52%3A42Z&sktid=398a6654-997b-47e9-b12b-9515b896b4de&skv=2025-11-05&sp=r&spr=https&sr=b&st=2026-01-12T09%3A59%3A59Z&sv=2025-11-05

Here is an example crash log for clarity. It seems to happen at process shutdown:

2026-01-12T09:35:15.7210769Z Running arrow-extension-type-test, redirecting output into /build/cpp/build/test-logs/arrow-extension-type-test.txt (attempt 1/1)
2026-01-12T09:35:15.7214676Z /arrow/cpp/build-support/run-test.sh: line 88: 16282 Aborted                 (core dumped) $TEST_EXECUTABLE "$@" > $LOGFILE.raw 2>&1
2026-01-12T09:35:15.7216769Z Running main() from gmock_main.cc
2026-01-12T09:35:15.7217541Z [==========] Running 6 tests from 1 test suite.
2026-01-12T09:35:15.7218108Z [----------] Global test environment set-up.
2026-01-12T09:35:15.7218642Z [----------] 6 tests from TestExtensionType
2026-01-12T09:35:15.7219192Z [ RUN      ] TestExtensionType.ExtensionTypeTest
2026-01-12T09:35:15.7219796Z [       OK ] TestExtensionType.ExtensionTypeTest (0 ms)
2026-01-12T09:35:15.7220418Z [ RUN      ] TestExtensionType.IpcRoundtrip
2026-01-12T09:35:15.7220982Z [       OK ] TestExtensionType.IpcRoundtrip (5 ms)
2026-01-12T09:35:15.7221577Z [ RUN      ] TestExtensionType.UnrecognizedExtension
2026-01-12T09:35:15.7222227Z [       OK ] TestExtensionType.UnrecognizedExtension (0 ms)
2026-01-12T09:35:15.7222857Z [ RUN      ] TestExtensionType.ParametricTypes
2026-01-12T09:35:15.7223435Z [       OK ] TestExtensionType.ParametricTypes (1 ms)
2026-01-12T09:35:15.7224016Z [ RUN      ] TestExtensionType.ParametricEquals
2026-01-12T09:35:15.7224625Z [       OK ] TestExtensionType.ParametricEquals (0 ms)
2026-01-12T09:35:15.7225223Z [ RUN      ] TestExtensionType.ValidateExtensionArray
2026-01-12T09:35:15.7226158Z [       OK ] TestExtensionType.ValidateExtensionArray (1 ms)
2026-01-12T09:35:15.7226791Z [----------] 6 tests from TestExtensionType (9 ms total)
2026-01-12T09:35:15.7227172Z 
2026-01-12T09:35:15.7227351Z [----------] Global test environment tear-down
2026-01-12T09:35:15.7228210Z [==========] 6 tests from 1 test suite ran. (9 ms total)
2026-01-12T09:35:15.7228923Z [  PASSED  ] 6 tests.
2026-01-12T09:35:15.7229855Z mimalloc: assertion failed: at "/build/cpp/mimalloc_ep-prefix/src/mimalloc_ep/src/bitmap.c":1453, _mi_bitmap_forall_setc_rangesn
2026-01-12T09:35:15.7230890Z   assertion: "rngslices <= MI_BFIELD_BITS"
2026-01-12T09:35:15.7231424Z !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
2026-01-12T09:35:15.7232517Z Running '/build/cpp/debug/arrow-extension-type-test' produced core dump at '/tmp/core.arrow-extension.16282', printing backtrace:
2026-01-12T09:35:15.7233514Z [New LWP 16282]
2026-01-12T09:35:15.7233825Z [New LWP 16288]
2026-01-12T09:35:15.7234191Z [Thread debugging using libthread_db enabled]
2026-01-12T09:35:15.7234859Z Using host libthread_db library "/lib/i386-linux-gnu/libthread_db.so.1".
2026-01-12T09:35:15.7235669Z Core was generated by `/build/cpp/debug/arrow-extension-type-test'.
2026-01-12T09:35:15.7236510Z Program terminated with signal SIGABRT, Aborted.
2026-01-12T09:35:15.7237040Z #0  0xf262a579 in __kernel_vsyscall ()
2026-01-12T09:35:15.7237565Z [Current thread is 1 (Thread 0xecf5e200 (LWP 16282))]
2026-01-12T09:35:15.7237958Z 
2026-01-12T09:35:15.7238123Z Thread 2 (Thread 0xecbffb40 (LWP 16288)):
2026-01-12T09:35:15.7238590Z #0  0xf262a579 in __kernel_vsyscall ()
2026-01-12T09:35:15.7239124Z #1  0xee6dfdc2 in ?? () from /lib/i386-linux-gnu/libc.so.6
2026-01-12T09:35:15.7239741Z #2  0xee64e6d5 in ?? () from /lib/i386-linux-gnu/libc.so.6
2026-01-12T09:35:15.7240441Z #3  0xee65192e in pthread_cond_wait () from /lib/i386-linux-gnu/libc.so.6
2026-01-12T09:35:15.7241659Z #4  0xf117429f in background_thread_sleep (tsdn=0xecbff2b0, info=0xecc09b80, interval=18446744073709551615) at src/background_thread.c:137
2026-01-12T09:35:15.7243165Z #5  0xf117474c in background_work_sleep_once (tsdn=0xecbff2b0, info=0xecc09b80, ind=0) at src/background_thread.c:229
2026-01-12T09:35:15.7244334Z #6  0xf1174c69 in background_thread0_work (tsd=0xecbff2b0) at src/background_thread.c:374
2026-01-12T09:35:15.7245336Z #7  0xf1174eeb in background_work (tsd=0xecbff2b0, ind=0) at src/background_thread.c:412
2026-01-12T09:35:15.7276580Z #8  0xf1175074 in background_thread_entry (ind_arg=0x0) at src/background_thread.c:444
2026-01-12T09:35:15.7277426Z #9  0xee65248c in ?? () from /lib/i386-linux-gnu/libc.so.6
2026-01-12T09:35:15.7278078Z #10 0xee6eb616 in clone () from /lib/i386-linux-gnu/libc.so.6
2026-01-12T09:35:15.7278509Z 
2026-01-12T09:35:15.7278678Z Thread 1 (Thread 0xecf5e200 (LWP 16282)):
2026-01-12T09:35:15.7279154Z #0  0xf262a579 in __kernel_vsyscall ()
2026-01-12T09:35:15.7279676Z #1  0xee654457 in ?? () from /lib/i386-linux-gnu/libc.so.6
2026-01-12T09:35:15.7280324Z #2  0xee603121 in raise () from /lib/i386-linux-gnu/libc.so.6
2026-01-12T09:35:15.7280992Z #3  0xee5ec26a in abort () from /lib/i386-linux-gnu/libc.so.6
2026-01-12T09:35:15.7281912Z #4  0xf123e113 in _mi_assert_fail () at /build/cpp/mimalloc_ep-prefix/src/mimalloc_ep/src/options.c:561
2026-01-12T09:35:15.7283202Z #5  0xf1238c77 in _mi_bitmap_forall_setc_rangesn () at /build/cpp/mimalloc_ep-prefix/src/mimalloc_ep/src/bitmap.c:1453
2026-01-12T09:35:15.7284492Z #6  0xf123372a in mi_arena_try_purge () at /build/cpp/mimalloc_ep-prefix/src/mimalloc_ep/src/arena.c:1965
2026-01-12T09:35:15.7285668Z #7  0xf1233910 in mi_arenas_try_purge () at /build/cpp/mimalloc_ep-prefix/src/mimalloc_ep/src/arena.c:2000
2026-01-12T09:35:15.7287027Z #8  0xf123138b in _mi_arenas_collect () at /build/cpp/mimalloc_ep-prefix/src/mimalloc_ep/src/arena.c:1206
2026-01-12T09:35:15.7288216Z #9  0xf124a9c3 in mi_theap_collect_ex () at /build/cpp/mimalloc_ep-prefix/src/mimalloc_ep/src/theap.c:134
2026-01-12T09:35:15.7289377Z #10 0xf124aa28 in mi_theap_collect () at /build/cpp/mimalloc_ep-prefix/src/mimalloc_ep/src/theap.c:145
2026-01-12T09:35:15.7290517Z #11 0xf123c397 in mi_process_done () at /build/cpp/mimalloc_ep-prefix/src/mimalloc_ep/src/init.c:929
2026-01-12T09:35:15.7291668Z #12 0xf123c473 in _mi_auto_process_done () at /build/cpp/mimalloc_ep-prefix/src/mimalloc_ep/src/init.c:956
2026-01-12T09:35:15.7293258Z #13 0xf124d124 in mi_process_detach () at /build/cpp/mimalloc_ep-prefix/src/mimalloc_ep/src/prim/prim.c:45
2026-01-12T09:35:15.7294169Z #14 0xf262d12a in ?? () from /lib/ld-linux.so.2
2026-01-12T09:35:15.7294688Z #15 0xf2630991 in ?? () from /lib/ld-linux.so.2
2026-01-12T09:35:15.7295250Z #16 0xee605b66 in ?? () from /lib/i386-linux-gnu/libc.so.6
2026-01-12T09:35:15.7296044Z #17 0xee605d81 in exit () from /lib/i386-linux-gnu/libc.so.6
2026-01-12T09:35:15.7296684Z #18 0xee5ed2e1 in ?? () from /lib/i386-linux-gnu/libc.so.6
2026-01-12T09:35:15.7297366Z #19 0xee5ed398 in __libc_start_main () from /lib/i386-linux-gnu/libc.so.6
2026-01-12T09:35:15.7297989Z #20 0x61726e27 in _start ()
2026-01-12T09:35:15.7298417Z !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!

[pitrou]

@daanx

[pitrou]

I was unable to reproduce locally with the same Docker setup as on that CI, so I assume there's something specific on GitHub Actions that triggers this.

[pitrou]

That said, this snippet looks fishy :)

mimalloc/src/bitmap.c

Lines 1453 to 1454 in 4dbc66f

	mi_assert_internal(rngslices <= MI_BFIELD_BITS);
	if (rngslices > MI_BFIELD_BITS) { rngslices = MI_BFIELD_BITS; }

[daanx]

Thanks so much -- it is not a bug perse and I removed the assertion for now. The rngslices parameter is used to avoid breaking up Linux huge OS pages (2 MiB usually) -- this is set in the mi_option_minimal_purge_size parameter at initialization. However, on 32-bit there are only 32 bits in the bfields of 32 KiB pages = 1 MiB so the rngslices is more that that routine supports and it caps it at 32. That is not ideal (as we may now sometimes still break up THP pages), but not wrong either. (a potential fix is on 32-bit Linux to default to 64 KiB small pages instead )

[pitrou]

Thanks for doing this, however I'm now hitting an infinite loop at process shutdown on Debian i386.

Here is a gdb backtrace:

^C
Thread 1 "arrow-array-tes" received signal SIGINT, Interrupt.
_mi_bitmap_forall_setc_rangesn (bitmap=0xe9ff88e0, rngslices=32, visit=0xf55a2681 <mi_arena_try_purge_visitor>, arena=0xe9ff8000, arg=0xffd93fe4)
    at /build/cpp/mimalloc_ep-prefix/src/mimalloc_ep/src/bitmap.c:1486
1486	          rngmask <<= rngslices;

(gdb) bt
#0  _mi_bitmap_forall_setc_rangesn (bitmap=0xe9ff88e0, rngslices=32, visit=0xf55a2681 <mi_arena_try_purge_visitor>, arena=0xe9ff8000, arg=0xffd93fe4)
    at /build/cpp/mimalloc_ep-prefix/src/mimalloc_ep/src/bitmap.c:1486
#1  0xf55a2886 in mi_arena_try_purge (arena=0xe9ff8000, now=3238771, force=true) at /build/cpp/mimalloc_ep-prefix/src/mimalloc_ep/src/arena.c:1980
#2  0xf55a2a6c in mi_arenas_try_purge (force=true, visit_all=true, subproc=0xf5dc3400 <subproc_main>, tseq=0) at /build/cpp/mimalloc_ep-prefix/src/mimalloc_ep/src/arena.c:2015
#3  0xf55a04e7 in _mi_arenas_collect (force_purge=true, visit_all=true, tld=0xf5db6340 <tld_main>) at /build/cpp/mimalloc_ep-prefix/src/mimalloc_ep/src/arena.c:1221
#4  0xf55b99a5 in mi_theap_collect_ex (theap=0xf5db6380 <theap_main>, collect=MI_FORCE) at /build/cpp/mimalloc_ep-prefix/src/mimalloc_ep/src/theap.c:134
#5  0xf55b9a0a in mi_theap_collect (theap=0xf5db6380 <theap_main>, force=true) at /build/cpp/mimalloc_ep-prefix/src/mimalloc_ep/src/theap.c:145
#6  0xf55ab41d in mi_process_done () at /build/cpp/mimalloc_ep-prefix/src/mimalloc_ep/src/init.c:954
#7  0xf55ab4f9 in _mi_auto_process_done () at /build/cpp/mimalloc_ep-prefix/src/mimalloc_ep/src/init.c:980
#8  0xf55bc106 in mi_process_detach () at /build/cpp/mimalloc_ep-prefix/src/mimalloc_ep/src/prim/prim.c:45
#9  0xf62ff12a in ?? () from /lib/ld-linux.so.2
#10 0xf6302991 in ?? () from /lib/ld-linux.so.2
#11 0xf2f40b66 in ?? () from /lib/i386-linux-gnu/libc.so.6
#12 0xf2f40d81 in exit () from /lib/i386-linux-gnu/libc.so.6
#13 0xf2f282e1 in ?? () from /lib/i386-linux-gnu/libc.so.6
#14 0xf2f28398 in __libc_start_main () from /lib/i386-linux-gnu/libc.so.6
#15 0x63c1d5e7 in _start ()

(gdb) info locals
base_idx = 0
b = 4294967292
skipped = 4294967292
rngmask = 4294967295
j = 0
chunk_idx = 0
chunk = 0xe9ff8920
cmap_entry = 2
cmap_idx = 0
i = 0
chunkmap_max = 1

Note that rngslices is 32 and rngmask is 32 bits too, so rngmask <<= rngslices is technically undefined behavior.

Do you want me to open a new issue for this @daanx ?

[pitrou]

Disassembly shows a SHL instruction, which masks the bit count based on operand size, so a shift by 32 is equivalent to a shift by 0:

1486	          rngmask <<= rngslices;
=> 0xf55a7ebe <+382>:	mov    0xc(%ebp),%eax
   0xf55a7ec1 <+385>:	mov    %eax,%ecx
   0xf55a7ec3 <+387>:	shll   %cl,-0x18(%ebp)

1487	        } while (rngmask != 0);
   0xf55a7ec6 <+390>:	cmpl   $0x0,-0x18(%ebp)
   0xf55a7eca <+394>:	jne    0xf55a7e57 <_mi_bitmap_forall_setc_rangesn+279>

[daanx]

Thanks! Darn, that one new routine causing so much issues :-( I pushed a fix which resolves this now.

[pitrou]

Great, I've verified that our i386 CI job is fixed now.

[daanx]

Thanks again for all the testing -- glad this is fixed!

[pitrou]

Also, with this latest fix, I'm happy to report that there seem to be no further regression on the Arrow CI, over more than one hundred build configurations.