[BUG] Illegal instruction executed #2570
Description
Describe the bug
valkey-server (64 bit) crashes when running tests on a server with an Intel(R) Xeon(R) E5-2430 CPU, which supports AVX, but not AVX2.
To reproduce
make distclean; make test
Expected behavior
I expect it to not crash.
Additional information
The issue was introduced in #1741:
commit 79d504742d24762d82f7ce48a685579ee5056ade
Author: chzhoo <[email protected]>
Date: Wed Feb 26 18:55:04 2025 +0800
Optimize bitcount command by SIMD (#1741)
End of make distclean; make test output:
...
[ok]: Quicklist: SORT BY hash field (19 ms)
[ok]: BITFIELD overflow detection fuzzing (794 ms)
[ok]: Check if maxclients works refusing connections (914 ms)
[ok]: SHUTDOWN SIGTERM will abort if there's an initial AOFRW - default (98 ms)
Logged crash report (pid 364990):
=== VALKEY BUG REPORT START: Cut & paste starting from here ===
364990:M 02 Sep 2025 10:28:22.512 # valkey 255.255.255 crashed by signal: 4, si_code: 2
364990:M 02 Sep 2025 10:28:22.512 # Crashed running the instruction at: 0x515a82
------ STACK TRACE ------
EIP:
src/valkey-server 127.0.0.1:23612(popcountAVX2+0x42) [0x515a82]
365001 bio_rdb_save
/lib64/libc.so.6(+0x7a462) [0x7f327aa89462]
/lib64/libc.so.6(+0x6e75c) [0x7f327aa7d75c]
/lib64/libc.so.6(+0x6edcc) [0x7f327aa7ddcc]
/lib64/libc.so.6(pthread_cond_wait+0x14e) [0x7f327aa8049e]
src/valkey-server 127.0.0.1:23612(bioProcessBackgroundJobs+0x1ce) [0x512a2e]
/lib64/libc.so.6(+0x71f54) [0x7f327aa80f54]
/lib64/libc.so.6(+0xf532c) [0x7f327ab0432c]
364990 valkey-server *
/lib64/libc.so.6(+0x1a070) [0x7f327aa29070]
src/valkey-server 127.0.0.1:23612(invalidFunctionWasCalled+0x0) [0x4d9e00]
[0x7fff64af1be0]
364998 bio_close_file
/lib64/libc.so.6(+0x7a462) [0x7f327aa89462]
/lib64/libc.so.6(+0x6e75c) [0x7f327aa7d75c]
/lib64/libc.so.6(+0x6edcc) [0x7f327aa7ddcc]
/lib64/libc.so.6(pthread_cond_wait+0x14e) [0x7f327aa8049e]
src/valkey-server 127.0.0.1:23612(bioProcessBackgroundJobs+0x1ce) [0x512a2e]
/lib64/libc.so.6(+0x71f54) [0x7f327aa80f54]
/lib64/libc.so.6(+0xf532c) [0x7f327ab0432c]
364999 bio_aof
/lib64/libc.so.6(+0x7a462) [0x7f327aa89462]
/lib64/libc.so.6(+0x6e75c) [0x7f327aa7d75c]
/lib64/libc.so.6(+0x6edcc) [0x7f327aa7ddcc]
/lib64/libc.so.6(pthread_cond_wait+0x14e) [0x7f327aa8049e]
src/valkey-server 127.0.0.1:23612(bioProcessBackgroundJobs+0x1ce) [0x512a2e]
/lib64/libc.so.6(+0x71f54) [0x7f327aa80f54]
/lib64/libc.so.6(+0xf532c) [0x7f327ab0432c]
365000 bio_lazy_free
/lib64/libc.so.6(+0x7a462) [0x7f327aa89462]
/lib64/libc.so.6(+0x6e75c) [0x7f327aa7d75c]
/lib64/libc.so.6(+0x6edcc) [0x7f327aa7ddcc]
/lib64/libc.so.6(pthread_cond_wait+0x14e) [0x7f327aa8049e]
src/valkey-server 127.0.0.1:23612(bioProcessBackgroundJobs+0x1ce) [0x512a2e]
/lib64/libc.so.6(+0x71f54) [0x7f327aa80f54]
/lib64/libc.so.6(+0xf532c) [0x7f327ab0432c]
5/5 expected stacktraces.
------ STACK TRACE DONE ------
------ REGISTERS ------
364990:M 02 Sep 2025 10:28:22.519 #
RAX:00007f327a578005 RBX:00007f327a53d280
RCX:00000000000008a4 RDX:00000000000009a4
RDI:00007f327a578005 RSI:00000000000009a4
RBP:00007fff64af1b60 RSP:00007fff64af1b60
R8 :0000000000000800 R9 :000000000f0f0f0f
R10:00007f327a578005 R11:1b439f57b32948e3
R12:0000000000000001 R13:00063dcd456b478a
R14:00007f327a578005 R15:0000000000000000
RIP:0000000000515a82 EFL:0000000000010246
CSGSFS:002b000000000033
364990:M 02 Sep 2025 10:28:22.519 # (00007fff64af1b6f) -> 00007f327a53d280
364990:M 02 Sep 2025 10:28:22.519 # (00007fff64af1b6e) -> 00000000007a2400
364990:M 02 Sep 2025 10:28:22.519 # (00007fff64af1b6d) -> 000000000045dac3
364990:M 02 Sep 2025 10:28:22.519 # (00007fff64af1b6c) -> 00007fff64af1be0
364990:M 02 Sep 2025 10:28:22.519 # (00007fff64af1b6b) -> 00007f327a53d280
364990:M 02 Sep 2025 10:28:22.519 # (00007fff64af1b6a) -> 00000000007a2400
364990:M 02 Sep 2025 10:28:22.519 # (00007fff64af1b69) -> 0000000000000026
364990:M 02 Sep 2025 10:28:22.519 # (00007fff64af1b68) -> 0000000000000000
364990:M 02 Sep 2025 10:28:22.519 # (00007fff64af1b67) -> 00000000000009a4
364990:M 02 Sep 2025 10:28:22.519 # (00007fff64af1b66) -> 00007fff64af1c10
364990:M 02 Sep 2025 10:28:22.519 # (00007fff64af1b65) -> 0000000000000000
364990:M 02 Sep 2025 10:28:22.519 # (00007fff64af1b64) -> 0000000000000000
364990:M 02 Sep 2025 10:28:22.519 # (00007fff64af1b63) -> 00000000000009a3
364990:M 02 Sep 2025 10:28:22.519 # (00007fff64af1b62) -> 00007fff64af1be0
364990:M 02 Sep 2025 10:28:22.519 # (00007fff64af1b61) -> 0000000000518b73
364990:M 02 Sep 2025 10:28:22.519 # (00007fff64af1b60) -> 00007fff64af1be0
------ INFO OUTPUT ------
# Server
redis_version:7.2.4
server_name:valkey
valkey_version:255.255.255
valkey_release_stage:dev
redis_git_sha1:eebed884
redis_git_dirty:0
redis_build_id:20c587f7d2ed812e
server_mode:standalone
os:Linux 6.16.3-200.fc42.x86_64 x86_64
arch_bits:64
monotonic_clock:POSIX clock_gettime
multiplexing_api:epoll
gcc_version:15.2.1
process_id:364990
process_supervised:no
run_id:8df4312cdfc7768cc0487af19e4e0bc6d4cfa933
tcp_port:23612
server_time_usec:1756801702512522
uptime_in_seconds:0
uptime_in_days:0
hz:10
configured_hz:10
clients_hz:10
lru_clock:11971238
executable:/home/ted/git/redis_stuff/valkey/src/valkey-server
config_file:/home/ted/git/redis_stuff/valkey/./tests/tmp/valkey.conf.364657.4
io_threads_active:0
availability_zone:
listener0:name=tcp,bind=127.0.0.1,port=23612
listener1:name=unix,bind=/home/ted/git/redis_stuff/valkey/tests/tmp/server.364657.3/socket
# Clients
connected_clients:1
cluster_connections:0
maxclients:10000
client_recent_max_input_buffer:0
client_recent_max_output_buffer:0
blocked_clients:0
tracking_clients:0
pubsub_clients:0
watching_clients:0
clients_in_timeout_table:0
total_watched_keys:0
total_blocking_keys:0
total_blocking_keys_on_nokey:0
paused_reason:none
paused_actions:none
paused_timeout_milliseconds:0
# Memory
used_memory:1049192
used_memory_human:1.00M
used_memory_rss:7995392
used_memory_rss_human:7.62M
used_memory_peak:1049192
used_memory_peak_human:1.00M
used_memory_peak_perc:100.21%
used_memory_overhead:878248
used_memory_startup:877600
used_memory_dataset:170944
used_memory_dataset_perc:99.62%
allocator_allocated:1260416
allocator_active:1372160
allocator_resident:5570560
allocator_muzzy:0
total_system_memory:16389935104
total_system_memory_human:15.26G
used_memory_lua:32768
used_memory_vm_eval:32768
used_memory_lua_human:32.00K
used_memory_scripts_eval:0
number_of_cached_scripts:0
number_of_functions:0
number_of_libraries:0
used_memory_vm_functions:33792
used_memory_vm_total:66560
used_memory_vm_total_human:65.00K
used_memory_functions:240
used_memory_scripts:240
used_memory_scripts_human:240B
maxmemory:0
maxmemory_human:0B
maxmemory_policy:noeviction
allocator_frag_ratio:1.09
allocator_frag_bytes:111744
allocator_rss_ratio:4.06
allocator_rss_bytes:4198400
rss_overhead_ratio:1.44
rss_overhead_bytes:2424832
mem_fragmentation_ratio:9.11
mem_fragmentation_bytes:7117648
mem_not_counted_for_evict:0
mem_replication_backlog:0
mem_total_replication_buffers:0
mem_clients_slaves:0
mem_clients_normal:0
mem_cluster_links:0
mem_cluster_slot_import:0
mem_cluster_slot_export:0
mem_aof_buffer:0
mem_allocator:jemalloc-5.3.0
mem_overhead_db_hashtable_rehashing:0
active_defrag_running:0
lazyfree_pending_objects:0
lazyfreed_objects:0
# Persistence
loading:0
async_loading:0
current_cow_peak:0
current_cow_size:0
current_cow_size_age:0
current_fork_perc:0.00
current_save_keys_processed:0
current_save_keys_total:0
rdb_changes_since_last_save:12
rdb_bgsave_in_progress:0
rdb_last_save_time:1756801702
rdb_last_bgsave_status:ok
rdb_last_bgsave_time_sec:-1
rdb_current_bgsave_time_sec:-1
rdb_saves:0
rdb_last_cow_size:0
rdb_last_load_keys_expired:0
rdb_last_load_keys_loaded:0
aof_enabled:0
aof_rewrite_in_progress:0
aof_rewrite_scheduled:0
aof_last_rewrite_time_sec:-1
aof_current_rewrite_time_sec:-1
aof_last_bgrewrite_status:ok
aof_rewrites:0
aof_rewrites_consecutive_failures:0
aof_last_write_status:ok
aof_last_cow_size:0
module_fork_in_progress:0
module_fork_last_cow_size:0
# Stats
total_connections_received:2
total_commands_processed:36
instantaneous_ops_per_sec:0
total_net_input_bytes:3833
total_net_output_bytes:416
total_net_repl_input_bytes:0
total_net_repl_output_bytes:0
total_net_cluster_slot_import_bytes:0
total_net_cluster_slot_export_bytes:0
instantaneous_input_kbps:0.00
instantaneous_output_kbps:0.00
instantaneous_input_repl_kbps:0.00
instantaneous_output_repl_kbps:0.00
rejected_connections:0
sync_full:0
sync_partial_ok:0
sync_partial_err:0
expired_keys:0
expired_fields:0
expired_stale_perc:0.00
expired_keys_with_volatile_items_stale_perc:0.00
expired_time_cap_reached_count:0
expire_cycle_cpu_milliseconds:0
evicted_keys:0
evicted_clients:0
evicted_scripts:0
total_eviction_exceeded_time:0
current_eviction_exceeded_time:0
keyspace_hits:19
keyspace_misses:4
pubsub_channels:0
pubsub_patterns:0
pubsubshard_channels:0
latest_fork_usec:0
total_forks:0
migrate_cached_sockets:0
slave_expires_tracked_keys:0
active_defrag_hits:0
active_defrag_misses:0
active_defrag_key_hits:0
active_defrag_key_misses:0
total_active_defrag_time:0
current_active_defrag_time:0
tracking_total_keys:0
tracking_total_items:0
tracking_total_prefixes:0
unexpected_error_replies:0
total_error_replies:4
dump_payload_sanitizations:0
total_reads_processed:38
total_writes_processed:36
io_threaded_reads_processed:0
io_threaded_writes_processed:0
io_threaded_freed_objects:0
io_threaded_accept_processed:0
io_threaded_poll_processed:0
io_threaded_total_prefetch_batches:0
io_threaded_total_prefetch_entries:0
client_query_buffer_limit_disconnections:0
client_output_buffer_limit_disconnections:0
reply_buffer_shrinks:0
reply_buffer_expands:0
eventloop_cycles:41
eventloop_duration_sum:7016
eventloop_duration_cmd_sum:139
instantaneous_eventloop_cycles_per_sec:0
instantaneous_eventloop_duration_usec:0
acl_access_denied_auth:0
acl_access_denied_cmd:0
acl_access_denied_key:0
acl_access_denied_channel:0
acl_access_denied_tls_cert:0
# Replication
role:master
connected_slaves:0
replicas_waiting_psync:0
master_failover_state:no-failover
master_replid:f151e29528d590953f321656e2aa00026dd95e79
master_replid2:0000000000000000000000000000000000000000
master_repl_offset:0
second_repl_offset:-1
repl_backlog_active:0
repl_backlog_size:10485760
repl_backlog_first_byte_offset:0
repl_backlog_histlen:0
# CPU
used_cpu_sys:0.010157
used_cpu_user:0.008560
used_cpu_sys_children:0.000000
used_cpu_user_children:0.000000
used_cpu_sys_main_thread:0.009544
used_cpu_user_main_thread:0.008676
# Modules
# Commandstats
cmdstat_select:calls=1,usec=4,usec_per_call=4.00,rejected_calls=0,failed_calls=0
cmdstat_lpush:calls=1,usec=11,usec_per_call=11.00,rejected_calls=0,failed_calls=0
cmdstat_del:calls=3,usec=10,usec_per_call=3.33,rejected_calls=0,failed_calls=0
cmdstat_bitcount:calls=22,usec=48,usec_per_call=2.18,rejected_calls=0,failed_calls=4
cmdstat_set:calls=8,usec=65,usec_per_call=8.12,rejected_calls=0,failed_calls=0
cmdstat_ping:calls=1,usec=1,usec_per_call=1.00,rejected_calls=0,failed_calls=0
# Errorstats
errorstat_WRONGTYPE:count=4
# Latencystats
latency_percentiles_usec_select:p50=4.015,p99=4.015,p99.9=4.015
latency_percentiles_usec_lpush:p50=11.007,p99=11.007,p99.9=11.007
latency_percentiles_usec_del:p50=2.007,p99=7.007,p99.9=7.007
latency_percentiles_usec_bitcount:p50=2.007,p99=3.007,p99.9=3.007
latency_percentiles_usec_set:p50=7.007,p99=16.063,p99.9=16.063
latency_percentiles_usec_ping:p50=1.003,p99=1.003,p99.9=1.003
# Cluster
cluster_enabled:0
# Keyspace
db9:keys=2,expires=0,avg_ttl=0,keys_with_volatile_items=0
------ CLIENT LIST OUTPUT ------
id=3 addr=127.0.0.1:38767 laddr=127.0.0.1:23612 fd=10 name= age=0 idle=0 flags=N capa= db=9 sub=0 psub=0 ssub=0 multi=-1 watch=0 qbuf=0 qbuf-free=0 argv-mem=11 multi-mem=0 rbs=16384 rbp=16384 obl=0 oll=0 omem=0 tot-mem=17051 events=r cmd=bitcount user=default redir=-1 resp=2 lib-name= lib-ver= tot-net-in=3826 tot-net-out=409 tot-cmds=35
------ CURRENT CLIENT INFO ------
id=3 addr=127.0.0.1:38767 laddr=127.0.0.1:23612 fd=10 name= age=0 idle=0 flags=N capa= db=9 sub=0 psub=0 ssub=0 multi=-1 watch=0 qbuf=0 qbuf-free=0 argv-mem=11 multi-mem=0 rbs=16384 rbp=16384 obl=0 oll=0 omem=0 tot-mem=17051 events=r cmd=bitcount user=default redir=-1 resp=2 lib-name= lib-ver= tot-net-in=3826 tot-net-out=409 tot-cmds=35
argc: 2
argv[0]: "bitcount"
argv[1]: "str"
364990:M 02 Sep 2025 10:28:22.520 # key 'str' found in DB containing the following object:
364990:M 02 Sep 2025 10:28:22.520 # Object type: 0
364990:M 02 Sep 2025 10:28:22.520 # Object encoding: 0
364990:M 02 Sep 2025 10:28:22.520 # Object refcount: 1
------ EXECUTING CLIENT INFO ------
id=3 addr=127.0.0.1:38767 laddr=127.0.0.1:23612 fd=10 name= age=0 idle=0 flags=N capa= db=9 sub=0 psub=0 ssub=0 multi=-1 watch=0 qbuf=0 qbuf-free=0 argv-mem=11 multi-mem=0 rbs=16384 rbp=16384 obl=0 oll=0 omem=0 tot-mem=17051 events=r cmd=bitcount user=default redir=-1 resp=2 lib-name= lib-ver= tot-net-in=3826 tot-net-out=409 tot-cmds=35
argc: 2
argv[0]: "bitcount"
argv[1]: "str"
364990:M 02 Sep 2025 10:28:22.520 # key 'str' found in DB containing the following object:
364990:M 02 Sep 2025 10:28:22.520 # Object type: 0
364990:M 02 Sep 2025 10:28:22.520 # Object encoding: 0
364990:M 02 Sep 2025 10:28:22.520 # Object refcount: 1
------ MODULES INFO OUTPUT ------
------ CONFIG DEBUG OUTPUT ------
io-threads 1
replica-read-only yes
lazyfree-lazy-user-flush yes
lazyfree-lazy-user-del yes
repl-diskless-sync yes
client-query-buffer-limit 1gb
slave-read-only yes
debug-context ""
import-mode no
sanitize-dump-payload no
proto-max-bulk-len 512mb
lazyfree-lazy-server-del yes
lazyfree-lazy-expire yes
lazyfree-lazy-eviction yes
dual-channel-replication-enabled no
activedefrag no
list-compress-depth 0
repl-diskless-load disabled
------ FAST MEMORY TEST ------
364990:M 02 Sep 2025 10:28:22.520 # Bio worker thread #0 terminated
364990:M 02 Sep 2025 10:28:22.520 # Bio worker thread #1 terminated
364990:M 02 Sep 2025 10:28:22.520 # Bio worker thread #2 terminated
364990:M 02 Sep 2025 10:28:22.520 # Bio worker thread #3 terminated
*** Preparing to test memory region 7b8000 (2355200 bytes)
*** Preparing to test memory region 210ef000 (135168 bytes)
*** Preparing to test memory region 7f3264000000 (135168 bytes)
*** Preparing to test memory region 7f32697fc000 (8388608 bytes)
*** Preparing to test memory region 7f3269ffd000 (8388608 bytes)
*** Preparing to test memory region 7f326a7fe000 (8388608 bytes)
*** Preparing to test memory region 7f326afff000 (8388608 bytes)
*** Preparing to test memory region 7f326b800000 (8388608 bytes)
*** Preparing to test memory region 7f327a000000 (8388608 bytes)
*** Preparing to test memory region 7f327a9d2000 (12288 bytes)
*** Preparing to test memory region 7f327aa00000 (12288 bytes)
*** Preparing to test memory region 7f327abf9000 (32768 bytes)
*** Preparing to test memory region 7f327ad21000 (4096 bytes)
*** Preparing to test memory region 7f327ae48000 (8192 bytes)
*** Preparing to test memory region 7f327ae89000 (4096 bytes)
.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O
Fast memory test PASSED, however your memory can still be broken. Please run a memory test for several hours if possible.
------ DUMPING CODE AROUND EIP ------
Symbol: popcountAVX2 (base: 0x515a40)
Module: src/valkey-server 127.0.0.1:23612 (base 0x400000)
$ xxd -r -p /tmp/dump.hex /tmp/dump.bin
$ objdump --adjust-vma=0x515a40 -D -b binary -m i386:x86-64 /tmp/dump.bin
------
364990:M 02 Sep 2025 10:28:22.835 # dump of function (hexdump of 194 bytes):
554889e54883e4e04881feff0000000f8ebb030000488d8e00ffffffc5c1efff4889f841b90f0f0f0f4989c8c4c1796ed9c5fd6f2587c31900c5fd7f7c24e04530c0c4e27d58db4a8d94070001000090c5fe6f6860c57e6f5020480500010000c5fe6f7880c57e6f8040ffffffc58571d504c5d5dbebc57e6f48a0c5fe6f8800ffffffc4e25d00f5c5d571d704c505dbfbc5d5dbebc4c17d71d204c52ddbd3c5fd7f7424c0c4c16d71d004c4e25d00edc5fddbc3c5fe6f70e0c59d71d104c5fd7f6c
=== VALKEY BUG REPORT END. Make sure to include from START to END. ===
Please report the crash by opening an issue on github:
https://github.com/valkey-io/valkey/issues
If a module was involved, please open in the module's repo instead.
Suspect RAM error? Use valkey-server --test-memory to verify it.
Some other issues could be detected by valkey-server --check-system
[exception]: Executing test client: I/O error reading reply.
I/O error reading reply
while executing
"[srv $level "client"] {*}$args"
(procedure "r" line 7)
invoked from within
"r bitcount str"
invoked from within
"expr {[r bitcount str] == $count}"
("uplevel" body line 1)
invoked from within
"uplevel 1 [list expr $condition]"
(procedure "assert" line 2)
invoked from within
"assert {[r bitcount str] == $count}"
("uplevel" body line 6)
invoked from within
"uplevel 1 $code"
(procedure "test" line 62)
invoked from within
"test {BITCOUNT fuzzing without start/end} {
for {set j 0} {$j < 100} {incr j} {
set str [randstring 0 3000]
r set str ..."
("uplevel" body line 47)
invoked from within
"uplevel 1 $code "
(procedure "start_server" line 2)
invoked from within
"start_server {tags {"bitops"}} {
test {BITCOUNT against wrong type} {
r del mylist
r lpush mylist a b c
assert_error "*WRO..."
(file "tests/unit/bitops.tcl" line 47)
invoked from within
"source $path"
(procedure "execute_test_file" line 4)
invoked from within
"execute_test_file $data"
(procedure "test_client_main" line 10)
invoked from within
"test_client_main $::test_server_port "
Killing still running Valkey server 364672
Killing still running Valkey server 364690
Killing still running Valkey server 364691
Killing still running Valkey server 364695
Killing still running Valkey server 364705
Killing still running Valkey server 364714
Killing still running Valkey server 364725
Killing still running Valkey server 364733
Killing still running Valkey server 364800
Killing still running Valkey server 364799
Killing still running Valkey server 365037
Killing still running Valkey server 365131
Killing still running Valkey server 365140
Killing still running Valkey server 365173
Killing still running Valkey server 365212
Killing still running Valkey server 365256
Killing still running Valkey server 365312
make[1]: *** [Makefile:591: test] Error 1
make[1]: Leaving directory '/home/ted/git/redis_stuff/valkey/src'
make: *** [Makefile:6: test] Error 2