Skip to content

Fix --pipeline >1 panic and pipelined byte/label accounting - #114

Merged
fcostaoliveira merged 2 commits into
masterfrom
fix/pipeline-byte-accounting-113
Jul 13, 2026
Merged

Fix --pipeline >1 panic and pipelined byte/label accounting#114
fcostaoliveira merged 2 commits into
masterfrom
fix/pipeline-byte-accounting-113

Conversation

@fcostaoliveira

Copy link
Copy Markdown
Contributor

Closes #113.

Problem

On the --pipeline N (N>1) path, sendFlatCmd/sendIfRequired/connectionProcessor threaded parallel scalar values through the flush, which caused several defects (the default pipeline=1 path was already correct):

  1. Panic — pipeline mode was unusable. connectionProcessor reassigned cmds/times from sendFlatCmd (so they accumulated to pipeline) but replies was never grown, so the flush loop indexed replies[pos] out of range → index out of range [1] with length 1, crashing the worker goroutine.
  2. Per-command TxBytes fabricated. The flush recorded a single scalar txBytesCount for every command in the batch, so TxBytes became Σ(pipeline × flushing-row bytes) instead of the sum of each command's bytes.
  3. Per-command labels wrong. cmdType/cmdQueryId were per-flush scalars, so a mixed pipeline filed every command under the flushing command's label (wrong histogram grouping).
  4. RxBytes always 0. sendFlatCmd passed a nil interface{} receiver to radix.Cmd, so replies were discarded and getRxLen always saw nil. (Its string/[]string branches were dead.)
  5. READ_CURSOR label mismatch. The histogram switch matched case "CURSOR_READ" while the code emits READ_CURSOR, so cursor reads were dropped from readCursorHistogram.

Fix

Buffer each pipelined command as a pendingCmd that carries its own send time, sent-byte count, reply receiver, and labels. The flush then records one correct stat per command. Specifically:

  • One []pendingCmd buffer per slot in connectionProcessor (no separate replies slice to fall out of sync).
  • sendFlatCmd passes a *interface{} receiver so replies are captured; getRxLen sizes string/[]byte/[]interface{} (recursive)/int64, dereferencing *interface{}.
  • Each stat is recorded with its own txBytes, latency, cmdType, and cmdQueryId.
  • benchmark_runner histogram switch corrected to case "READ_CURSOR".

Validation (E2E against redis)

--pipeline 4 master this branch
exit 2 — panic (index out of range) 0
keys ingested 8 (crashed) 2000
TxBytes 135780 (per-command)
RxBytes 2000 (was structurally 0)

At pipeline=1, TotalOps and TxBytes are byte-identical to master (2000 / 135780); RxBytes goes from 0 → 2000 (replies now counted).

Tests

Notes / out of scope

  • Reply capture cost: the *interface{} receiver allocates per command (radix previously discarded replies). This restores the evidently-intended behavior (getRxLen predates this PR) and makes RxBytes meaningful. Negligible for the dominant ingest path (integer/OK replies); for large query replies it is more — can be gated behind a flag in a follow-up if it perturbs latency measurement.
  • TotalOps 1-off at pipeline>1: pipelined commands share one completion time, so the last has ~0µs measured latency, which the HDR histogram (min=1) rejects — a pre-existing pipeline latency-accounting semantics issue, not introduced here (master crashed before it was observable).

…ipeline >1 panic

Buffer each pipelined command as a pendingCmd carrying its own send time, sent-byte
count, reply receiver, and labels, instead of threading parallel scalar slices
through the flush. This fixes several defects on the --pipeline N>1 path (default
pipeline=1 was already correct):

- Panic: the old code kept a single `replies` slice that connectionProcessor
  never grew, while cmds/times accumulated to `pipeline`; the flush indexed
  `replies[pos]` out of range -> "index out of range [1] with length 1", crashing
  the worker. --pipeline >1 was unusable. Now each command owns its receiver.
- Per-command TxBytes: the flush recorded one scalar txBytesCount for every
  command; now each records its own sent bytes.
- Per-command labels: cmdType/cmdQueryId are now per-command, so a mixed pipeline
  no longer files every command under the flushing command's label.
- Reply capture: sendFlatCmd now passes a *interface{} receiver (was a nil
  interface, so replies were discarded and RxBytes was always 0). getRxLen sizes
  the captured reply (string/[]byte/[]interface{}/int64, deref *interface{}).
- Fix READ_CURSOR label: the histogram switch matched "CURSOR_READ" but the code
  emits "READ_CURSOR", so cursor reads were dropped from readCursorHistogram.

Validated E2E against redis: master crashes at --pipeline 4 (index out of range,
8/2000 keys); this branch completes (2000/2000 keys) with TxBytes=135780 and
RxBytes=2000. At pipeline=1 the Tx/ops numbers are byte-identical to master.

Closes #113
The refactor collapsed the timeout log message to a bare count, dropping the
command and key. That broke integration tests (TestFTSBWithTimeout,
TestFTSBWithLogFileAndTimeout) which assert the log contains 'Timeout occurred'
+ the command ('DEBUG') + key ('SLEEP') on one line. Restore the per-command
detail using the representative pending command.
@sonarqubecloud

Copy link
Copy Markdown

@fcostaoliveira
fcostaoliveira merged commit a7cebb9 into master Jul 13, 2026
3 checks passed
@fcostaoliveira
fcostaoliveira deleted the fix/pipeline-byte-accounting-113 branch July 13, 2026 12:31
fcostaoliveira added a commit that referenced this pull request Jul 13, 2026
…ne latency

Supersedes the earlier latency-only change on this branch. The 7-way adversarial
review showed the original premise was wrong: hdrhistogram-go v1.0.1 does NOT
drop RecordValue(0) (it is counted), so the latency clamp never prevented any
TotalOps undercount. The real op-drops were elsewhere. This commit fixes them:

A. Flush the trailing partial pipeline window. connectionProcessor buffered up to
   `pipeline` commands per slot but never flushed the leftover (< pipeline) at end
   of input, so the last `rows % pipeline` commands per batch were NEVER sent to
   Redis or counted -- silent data loss whenever pipeline did not divide the row
   count (e.g. pipeline=3 over 100 rows -> 99 sent). sendIfRequired is split into
   a guard + reusable flushPending; connectionProcessor now flushes every
   non-empty slot before finishing.

B. Make TotalOps/overallOpsRate exact via an atomic counter (one increment per
   recorded command) instead of the HDR histograms' TotalCount(), which drops any
   latency above the trackable cap (--max-latency-seconds, ~1.05s default -- a
   cold query or any i/o timeout) and loses increments under concurrent unlocked
   RecordValue. The histograms remain the source for percentiles only.

C. Keep the send-time uniform pipeline latency (one batch round-trip attributed
   to each command; matches redis-benchmark) but reframe the 1us floor honestly:
   a network round-trip is never 0us, so a 0 only reflects timer resolution -- it
   is NOT a TotalOps fix. Also capture sendT after building the pipeline action so
   client-side slice bookkeeping is not charged as latency.

Validated E2E: TotalOps == dbsize == input count at pipeline 1/3/4/8/16/100
(was 99/1980/1920 before). Adds: atomic-counter decoupling unit test, a
pipeline=3 integration test asserting exact TotalOps, and reframed latency test.

Follow-ups filed separately: histogram RecordValue data race under workers>1;
#114 reply-capture unmarshal inflating FT.SEARCH latency.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

ftsb_redisearch: --pipeline >1 panics; pipelined TX/RX byte accounting is wrong

1 participant