[daily-ci] FLAKY-TEST: nested prefetch io-threads tests stall out the valgrind integration-type shard (missing valgrind:skip)

[madolson]

Every Daily valgrind integration-type shard since 2026-09-10 dies on Zset nested prefetch - ZSCORE correctness with pipelined commands hitting the 2400s per-test timeout. The test starts a server with io-threads 4 io-threads-always-active yes (tests/unit/type/zset.tcl:3290), and in that mode idle IO threads busy-spin on pthread_mutex_lock/unlock at src/io_threads.c:423-425 with no syscall and no yield. Valgrind serializes all threads onto one core, so three spinning workers starve the main thread: that server takes 214s just to reach "ok" versus about 3s for every other server in the same run, and 200 sequential ZADDs then made no progress for 41 minutes.

Fix is the valgrind:skip tag, which the io-threads suite already uses for exactly this reason (tests/unit/io-threads.tcl:61 and :142). The three nested-prefetch blocks added by #3940 missed it. Not a production defect: no deployment runs under memcheck.

Details

Jobs

All seven Daily runs 2026-09-10 through 2026-09-16 list test-valgrind-test (integration-type) as failure. Logs read for four:

• https://github.com/valkey-io/valkey/actions/runs/34792420918/job/103819010995
• https://github.com/valkey-io/valkey/actions/runs/34727724387/job/103644755540
• https://github.com/valkey-io/valkey/actions/runs/34661154146/job/103463756126
• https://github.com/valkey-io/valkey/actions/runs/34420651673/job/102695099607

The twin job test-valgrind-no-malloc-usable-size-test (integration-type) (.github/workflows/daily.yml:945) fails on the identical test in the same runs, verified in 34661154146, 34727724387 and 34792420918. One test currently costs two full valgrind shards per Daily run and masks every tests/unit/type test that would have run after it.

Failing output

Same in all four. Run 34792420918:

=== (zset external:skip) Starting server on 127.0.0.1:21431 ok
[TIMEOUT]: clients state report follows.
sock55850c238830 => (IN PROGRESS) Zset nested prefetch - ZSCORE correctness with pipelined commands

Test Summary: 1200 passed, 1 failed

!!! WARNING The following tests failed:

*** [TIMEOUT]: Zset nested prefetch - ZSCORE correctness with pipelined commands in tests/unit/type/zset.tcl
##[error]Process completed with exit code 1.

No [err], no ==pid== block, no ERROR SUMMARY, no crash anywhere in the four logs. This is not a valgrind report, which is why the automated fingerprinter found no signature. ##[error]Process completed with exit code 1 is runtest exiting non-zero after the timeout.

Failing step is the test step at .github/workflows/daily.yml:884, which runs --single tests/integration --single tests/unit/type with --timeout 2400 (.github/workflows/daily.yml:878-884). timeout-minutes: 1440 at .github/workflows/daily.yml:840 is not the limit; the jobs finished in about 50 minutes.

The test

tests/unit/type/zset.tcl:3290:

start_server {config "minimal.conf" tags {"zset" "external:skip"} overrides {io-threads 4 io-threads-always-active yes zset-max-listpack-entries 0}} {
    test "Zset nested prefetch - ZSCORE correctness with pipelined commands" {
        for {set i 0} {$i < 200} {incr i} {
            r zadd myzset $i "member:$i"
        }

200 sequential ZADDs then 50 pipelined ZSCOREs. Sub-second work natively.

Why it stalls

IOThreadsAfterSleep unlocks every IO thread mutex as soon as an event arrives, in the io_threads_always_active branch at src/io_threads.c:490. Each idle IO thread then spins in IOThreadMain, src/io_threads.c:423-425:

/* If it is locked. We should block until main thread unlocks it. */
pthread_mutex_lock(&io_threads_mutex[id]);
pthread_mutex_unlock(&io_threads_mutex[id]);

With the mutex unlocked both calls return immediately, so the loop at src/io_threads.c:364 spins with no syscall and no yield. waitForClientIO at src/io_threads.c:122-137 spins the same way on the main thread with only atomic_thread_fence between iterations.

Under valgrind all threads are serialized onto one core and preempted on a basic-block quota, so the main thread gets a small slice and every spin iteration costs orders of magnitude more than native. Starvation, not deadlock, but indistinguishable from a hang at this magnitude.

Quantified from run 34792420918's own log. Ordinary servers in that run:

01:38:36.038 === (external:skip) Starting server on 127.0.0.1:21428 ok
01:38:39.374 === (stream needs:debug) Starting server on 127.0.0.1:21429 ok
01:38:42.032 === (zset) Starting server on 127.0.0.1:21430 ok

About 3 seconds each. The io-threads 4 server logs Ready to accept connections tcp at 01:40:18 and the framework does not print ok until 01:43:51: 214 seconds, roughly 70x, before the test body runs at all. The body then logged nothing from 01:48:00 until the framework gave up at 02:29:19.

Introduced by

2d44c74, "Nested prefetching for hash and zset inner hashtables" (#3940), merged 2026-09-09. It added three identical io-threads 4 io-threads-always-active yes start_server blocks with no valgrind:skip:

• tests/unit/type/hash.tcl:965
• tests/unit/type/set.tcl:1257
• tests/unit/type/zset.tcl:3290

The first Daily run after that merge, 34420651673 on 2026-09-10, is the first failure.

Fix

Add "valgrind:skip" to the tags of all three blocks. start_server honours it at tests/support/server.tcl:299. All three need it in one change: only zset is observed failing today because the timeout aborts the run before hash and set are reached, so skipping zset alone just moves the stall.

Ruled out

• Not a valgrind report. No ==pid==, ERROR SUMMARY or Valgrind error in any log. src/valgrind.sup is irrelevant.
• Not a build failure. make valgrind SERVER_CFLAGS='-Werror' completed in all four.
• Not a job-level timeout.
• Not infra, network or toolchain. Same valgrind 3.22.0-0ubuntu3 on ubuntu-latest, deterministic across seven consecutive runs and two independent job definitions.
• Not a production defect. The busy-spin is intentional for io-threads-always-active and is only pathological under valgrind's serialized scheduler.

This was generated by AI but verified, with love, by a human.

[madolson]

Confirmed on test-valgrind-no-malloc-usable-size-test (integration-type), verdict FLAKY-TEST, agreeing with everything above. Adding run 34545972977, which was not in the list.

Details

New occurrence: https://github.com/valkey-io/valkey/actions/runs/34545972977/job/103098549730 (twin test-valgrind-test: https://github.com/valkey-io/valkey/actions/runs/34545972977/job/103098549799).

=== (zset external:skip) Starting server on 127.0.0.1:21426 ok
[TIMEOUT]: clients state report follows.
sock5591747a2d30 => (IN PROGRESS) Zset nested prefetch - ZSCORE correctness with pipelined commands

Test Summary: 1174 passed, 1 failed

!!! WARNING The following tests failed:

*** [TIMEOUT]: Zset nested prefetch - ZSCORE correctness with pipelined commands in tests/unit/type/zset.tcl

Failing step for this job is .github/workflows/daily.yml:997, same --timeout 2400, enforced at tests/test_helper.tcl:399. Nothing NO_MALLOC_USABLE_SIZE-specific.

Per-command numbers from the dumped server logs, if useful for the starvation claim. Run 34545972977 pid 103626: ready 01:51:58, first client 01:53:09, deferring client 01:57:55, so 286s for the 200 ZADDs, about 1.4s each. Run 34727724387 pid 108795: ready 02:09:24, first client 02:10:41, deferring client 02:23:36, so 775s, about 3.9s each. In the same run ZRANDMEMBER with <count> - btree finishes in 1563 ms with far more commands, so this is not generic valgrind slowdown.

One correction to the count: of the seven Daily runs, only four reach zset.tcl. 34912708159 and 35039408935 die earlier in tests/integration/throttle-repl.tcl, and 34420651673 fails before the suite. It timed out four out of four times it was reached, so deterministic rather than borderline.

This was generated by AI but verified, with love, by a human.

[madolson]

Reproduced locally and confirmed as a test bug. The forcing knob is --timeout: the stall is starvation, not a hang, so on a fast box the default 2400s budget eventually completes (109632 ms for the zset test here), but squeezing the per-test budget to 60s turns it into the exact CI [TIMEOUT] failure, 15/15 across the three files over --loops 5. A scratch suite running the identical body in two servers under the same valgrind, pinned to one core, gives 206 ms without io-threads and 20531 ms with io-threads 4 io-threads-always-active yes, so the config is the only variable.

The report's diagnosis holds: idle IO threads busy-spin on an already-unlocked mutex at src/io_threads.c:422-425 and waitForClientIO spins the same way on the main thread at src/io_threads.c:122-137, both with no syscall and no yield, and valgrind's serialized scheduler turns that into main-thread starvation. Nothing to fix in src/. Fix is valgrind:skip on all three blocks, matching tests/unit/io-threads.tcl:61 and :142. PR: #64.

No upstream test-failure issue exists for these test names. I searched all 159 by name fragment (nested prefetch, prefetch, ZSCORE, pipelined, and by file); the only zset.tcl hit is valkey-io/valkey#4558, a closed and unrelated ZREMRANGEBYLEX fuzzer failure. So this issue is the record.

Details

Setup

git -C ~/git/valkey worktree add /tmp/wt-48 -b ai/issue-48 upstream/unstable   # d6415e766
cd /tmp/wt-48 && make valgrind -j8

valgrind 3.19.0-1ubuntu1, 32 cores. Branched from upstream/unstable rather than agents/unstable, which is 66 commits behind and does not contain #3940, so the lines in question do not exist there.

Before: 15/15 timeouts

$ ./runtest --single unit/type/zset --single unit/type/hash --single unit/type/set \
    --valgrind --only "/nested prefetch" --timeout 60 --loops 5
[TIMEOUT]: clients state report follows.
Test Summary: 0 passed, 15 failed

!!! WARNING The following tests failed:

*** [TIMEOUT]: Zset nested prefetch - ZSCORE correctness with pipelined commands in tests/unit/type/zset.tcl
*** [TIMEOUT]: Hash nested prefetch - HGET correctness with pipelined commands in tests/unit/type/hash.tcl
*** [TIMEOUT]: Set nested prefetch - SISMEMBER correctness with pipelined commands in tests/unit/type/set.tcl
*** [TIMEOUT]: Zset nested prefetch - ZSCORE correctness with pipelined commands in tests/unit/type/zset.tcl
*** [TIMEOUT]: Hash nested prefetch - HGET correctness with pipelined commands in tests/unit/type/hash.tcl
*** [TIMEOUT]: Set nested prefetch - SISMEMBER correctness with pipelined commands in tests/unit/type/set.tcl
*** [TIMEOUT]: Zset nested prefetch - ZSCORE correctness with pipelined commands in tests/unit/type/zset.tcl
*** [TIMEOUT]: Hash nested prefetch - HGET correctness with pipelined commands in tests/unit/type/hash.tcl
*** [TIMEOUT]: Set nested prefetch - SISMEMBER correctness with pipelined commands in tests/unit/type/set.tcl
*** [TIMEOUT]: Zset nested prefetch - ZSCORE correctness with pipelined commands in tests/unit/type/zset.tcl
*** [TIMEOUT]: Hash nested prefetch - HGET correctness with pipelined commands in tests/unit/type/hash.tcl
*** [TIMEOUT]: Set nested prefetch - SISMEMBER correctness with pipelined commands in tests/unit/type/set.tcl
*** [TIMEOUT]: Zset nested prefetch - ZSCORE correctness with pipelined commands in tests/unit/type/zset.tcl
*** [TIMEOUT]: Hash nested prefetch - HGET correctness with pipelined commands in tests/unit/type/hash.tcl
*** [TIMEOUT]: Set nested prefetch - SISMEMBER correctness with pipelined commands in tests/unit/type/set.tcl

--only matches exactly or by /regex (tests/support/test.tcl:182-196), so the leading slash is required; a glob silently selects nothing.

Note only the first test of each block appears: the timeout kills the client mid-block, so Zset nested prefetch - short members are looked up safely and the four other hash tests never run. That is the same masking effect the report describes for the CI shard.

At the default budget the test passes but pays the full cost:

$ ./runtest --single unit/type/zset --valgrind \
    --only "Zset nested prefetch - ZSCORE correctness with pipelined commands" --timeout 300
[ok]: Zset nested prefetch - ZSCORE correctness with pipelined commands (109632 ms)

After: skipped under valgrind, unchanged natively

With "valgrind:skip" added to the tags of tests/unit/type/zset.tcl:3290, tests/unit/type/hash.tcl:965 and tests/unit/type/set.tcl:1257, start_server drops the block at tests/support/server.tcl:299 and the run finishes in 5s instead of timing out:

$ ./runtest --single unit/type/zset --single unit/type/hash --single unit/type/set \
    --valgrind --only "/nested prefetch" --timeout 60 --loops 5
Test Summary: 0 passed, 0 failed

\o/ All tests passed without errors!

Native coverage is untouched, 8 tests x 5 loops:

$ ./runtest --single unit/type/zset --single unit/type/hash --single unit/type/set \
    --only "/nested prefetch" --loops 5
      5 [ok]: Hash nested prefetch - correctness with a forced multi-key batch
      5 [ok]: Hash nested prefetch - HDEL correctness with pipelined commands
      5 [ok]: Hash nested prefetch - HGET correctness with pipelined commands
      5 [ok]: Hash nested prefetch - HMGET multi-field correctness
      5 [ok]: Hash nested prefetch - large non-embedded values exercise value phase
      5 [ok]: Set nested prefetch - SISMEMBER correctness with pipelined commands
      5 [ok]: Zset nested prefetch - short members are looked up safely
      5 [ok]: Zset nested prefetch - ZSCORE correctness with pipelined commands
Test Summary: 40 passed, 0 failed

Isolating the config from the body

Scratch suite, since removed, ran the identical body in two servers, the second with the exact overrides from tests/unit/type/zset.tcl:3290:

proc repro_body {} {
    uplevel 1 {
        r del myzset
        for {set i 0} {$i < 200} {incr i} { r zadd myzset $i "member:$i" }
        set rd [valkey_deferring_client]
        for {set i 0} {$i < 50} {incr i} { $rd zscore myzset "member:$i" }
        $rd flush
        for {set i 0} {$i < 50} {incr i} { assert_equal $i [$rd read] }
        $rd close
    }
}

start_server {config "minimal.conf" tags {"zset" "external:skip"} overrides {zset-max-listpack-entries 0}} {
    test "REPRO control - no io-threads" { repro_body }
}
start_server {config "minimal.conf" tags {"zset" "external:skip"} overrides {io-threads 4 io-threads-always-active yes zset-max-listpack-entries 0}} {
    test "REPRO io-threads 4 always-active" { repro_body }
}

$ taskset -c 5 ./runtest --single unit/type/zsetreprotmp --valgrind --timeout 600
[ok]: REPRO control - no io-threads (206 ms)
[ok]: REPRO io-threads 4 always-active (20531 ms)

100x, same body, same valgrind, one core. The 60s budget used above is still ~290x the control.

Mechanism, confirmed at these lines

src/io_threads.c:422-425, reached whenever an IO thread has no work and no pending responses:

            } else {
                /* If it is locked. We should block until main thread unlocks it. */
                pthread_mutex_lock(&io_threads_mutex[id]);
                pthread_mutex_unlock(&io_threads_mutex[id]);
            }

IOThreadsAfterSleep unlocks all of them on any event in the always-active branch, src/io_threads.c:175-183:

    if (server.io_threads_always_active) {
        if (numevents > 0 && server.active_io_threads_num < server.io_threads_num) {
            for (int i = server.active_io_threads_num; i < server.io_threads_num; i++) {
                pthread_mutex_unlock(&io_threads_mutex[i]);
            }
            server.active_io_threads_num = server.io_threads_num;
        }
        return;
    }

so both calls return immediately and the while (1) at src/io_threads.c:364 spins with no syscall and no yield. waitForClientIO spins the same way on the main thread, src/io_threads.c:122-137.

Line numbers differ slightly from the report, which cited 423-425 and 490; the code is the same, at 422-425 and 175-183 on d6415e766.

Unexpected: more cores is worse

Pinning to one core is 5x faster than letting the scheduler roam, which is the opposite of the usual direction:

run	per-test time
--valgrind, unpinned, 32 cores	109632 ms
--valgrind, taskset -c 0	20240 ms

Consistent with contention on valgrind's serializing lock: more runnable spinners means more handoffs, not more throughput. It also means a repro on a many-core dev box overstates the cost relative to a 2-core CI runner, and the CI failure is still worse than both, so the 2400s budget is being blown by more than this local measurement alone would predict.

Ruled out

• Not a valgrind report. No ==pid== block and no ERROR SUMMARY locally or in the CI logs. src/valgrind.sup is irrelevant.
• Not the test body. 206 ms without io-threads, above.
• Not a deadlock. The test completes at 109632 ms given enough budget.
• Not a product defect. The busy-spin is deliberate for io-threads-always-active and only pathological under valgrind's serialized scheduler. No deployment runs under memcheck.

This was generated by AI but verified, with love, by a human.