[BUG] valkey-benchmark hangs forever in showReport() percentile iteration when --warmup is used with --threads

[arcivanov]

Describe the bug

valkey-benchmark can hang forever at 100% CPU after a test has finished measuring, spinning inside the latency report. The measured run completes normally, the final progress line is written, and then the process never returns and prints nothing further. In one campaign a cell that should have taken 25 s sat spinning for 26 minutes before I killed it.

Stack at the hang (eu-stack, binary built with -g):

#0  0x0000000000451230 percentile_iter_next
#1  0x000000000043762f showReport
#2  0x000000000043c4b6 benchmarkSequence
#3  0x000000000040ecf5 main

Symptoms: one thread left, R state, 100 % of one core, output file frozen at the last ... 19.8 seconds progress line and not growing, client connections still open on the server.

Root cause

hdr_reset() is not atomic (deps/hdr_histogram/hdr_histogram.c):

void hdr_reset(struct hdr_histogram *h)
{
     h->total_count=0;
     h->min_value = INT64_MAX;
     h->max_value = 0;
     memset(h->counts, 0, (sizeof(int64_t) * h->counts_len));
}

It is called at the end of the warmup period from showThroughput() (src/valkey-benchmark.c:2164) against the single shared config.latency_histogram. In multi-threaded mode showThroughput() is registered on a per-thread timer (src/valkey-benchmark.c:1367), and every other thread is concurrently writing that same histogram through hdr_record_value_atomic() (src/valkey-benchmark.c:804).

Worse, the warmup transition is a non-atomic check-then-act, so it is not limited to one thread (src/valkey-benchmark.c:2154):

int warmup_duration = atomic_load_explicit(&config.current_warmup_duration, memory_order_relaxed);
if (warmup_duration > 0) {
    if ((current_tick - config.start) >= (warmup_duration * 1000LL)) {
        atomic_store_explicit(&config.current_warmup_duration, 0, memory_order_relaxed);
        config.start = current_tick;
        ...
        hdr_reset(config.latency_histogram);
    }
}

The load, the test and the store are separate, so every thread whose timer fires before any of them stores 0 runs the whole body, including hdr_reset() and the config.start / counter resets.

If a hdr_record_value_atomic() lands between the h->total_count = 0 store and the memset(), the increment to total_count survives while the bucket it incremented is zeroed. The histogram is then left with total_count > sum(counts).

That state is terminal for the percentile iterator, because has_next() compares the running cumulative count against a snapshot of total_count taken at iterator init (deps/hdr_histogram/hdr_histogram.c:807):

static bool has_next(struct hdr_iter* iter)
{
    return iter->cumulative_count < iter->total_count;
}

percentile_iter_next() walks every bucket looking for a non-zero count, finds none, falls out of its do { } while (basic_iter_next(iter)) loop and returns true unconditionally. has_next() stays true forever because cumulative_count can never reach the inflated total_count. So the reporting loop at src/valkey-benchmark.c:1236 spins forever while emitting nothing.

Deterministic reproducer

This reproduces the post-race histogram state directly and runs showReport()'s loop verbatim, so it does not depend on winning the race:

#include <stdio.h>
#include <string.h>
#include <stdint.h>
#include "hdr_histogram.h"

int main(void) {
    struct hdr_histogram *h;
    hdr_init(10L, 3000000L, 3, &h);
    hdr_record_value(h, 500);
    hdr_record_value(h, 1200);

    /* torn hdr_reset(): total_count zeroed, a concurrent record bumps
       counts+total_count, then the memset wipes counts only. */
    memset(h->counts, 0, sizeof(int64_t) * h->counts_len);
    h->total_count = 2;              /* survives; sum(counts) == 0 */

    struct hdr_iter iter;
    long long previous_cumulative_count = -1;
    const long long total_count = h->total_count;
    hdr_iter_percentile_init(&iter, h, 1);
    long long spins = 0;
    while (hdr_iter_next(&iter)) {
        const long long cumulative_count = iter.cumulative_count;
        previous_cumulative_count = cumulative_count;
        (void)previous_cumulative_count;
        if (++spins >= 20000000) {
            printf("HANG CONFIRMED: %lld iterations, loop never terminates\n", spins);
            return 1;
        }
    }
    printf("terminated after %lld iterations\n", spins);
    return 0;
}

Output:

state: total_count=2 sum(counts)=0  (invariant violated)
HANG CONFIRMED: 20000000 iterations, 1 lines printed, loop never terminates

Reproducing through the benchmark

It is a race, so it is intermittent. It needs --warmup together with --threads; I hit it twice in roughly 40 cells with:

valkey-benchmark -t get -r 3000000 --duration 20 -c 600 --threads 16 --warmup 5

--csv and -q are not affected, because both percentile loops sit inside if (!config.quiet && !config.csv) and those two paths derive avg/min/p50/p95/p99/max from hdr_value_at_percentile() rather than from the iterator. Using --csv is a viable workaround.

Suggested fix

There are two separable problems.

1. The warmup transition should run exactly once rather than once per thread. An atomic compare-exchange on config.current_warmup_duration (rather than load, test, then store) would confine the reset, the config.start assignment and the counter resets to a single thread.
2. Even with that, resetting a histogram that other threads are actively recording into is unsound, since hdr_reset() is a plain store plus memset. Either pause recording across the transition, or swap in a fresh histogram and free the old one, or have the reporting side tolerate an inconsistent histogram (for instance by calling hdr_reset_internal_counters() to recompute total_count from the buckets before iterating, and bounding the reporting loop).

The second point matters independently of the first: a bounded reporting loop turns a permanent hang into a cosmetically wrong report, which is a much better failure mode for a benchmarking tool.

Additional information

The same race also corrupts throughput accounting, since config.start and the requests_issued / requests_finished counters are reset by every thread that enters the block rather than once.

Version: unstable at 7be7d564f, built with a plain make (-O3, jemalloc), Linux x86-64, 2 x Xeon E5-2699A v4.