Skip to content

Fix pipeline command accounting: flush trailing window + exact TotalOps - #115

Merged
fcostaoliveira merged 6 commits into
masterfrom
fix/pipeline-latency-accounting
Jul 13, 2026
Merged

Fix pipeline command accounting: flush trailing window + exact TotalOps#115
fcostaoliveira merged 6 commits into
masterfrom
fix/pipeline-latency-accounting

Conversation

@fcostaoliveira

@fcostaoliveira fcostaoliveira commented Jul 13, 2026

Copy link
Copy Markdown
Contributor

Makes ftsb_redisearch report the correct command count and latency in pipeline mode. Follow-up to #114 (which made --pipeline >1 usable).

Note: an earlier revision of this branch claimed the fix was about the HDR histogram dropping RecordValue(0). A 7-way adversarial review disproved that — hdrhistogram-go v1.0.1 counts RecordValue(0), it does not drop it. The real op-drops were elsewhere; this PR fixes them and the description below is corrected.

Problems (all on the --pipeline N>1 path; pipeline=1 was already correct)

  1. Trailing window never flushed → silent data loss. 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. E.g. --pipeline 3 over a 100-row input → only 99 executed and counted. Verified: dbsize dropped too.
  2. TotalOps/overallOpsRate were histogram-derived and lossy. They came from hdrhistogram.TotalCount(), which (a) rejects any latency above the trackable cap (--max-latency-seconds, ~1.05s default — a cold FT.SEARCH, GC pause, or any i/o timeout), and (b) loses increments under concurrent unlocked RecordValue. Either silently undercounts ops.
  3. Pipeline latency was measured from each command's buffer time, folding client-side queueing into the first command's latency.

Fix

  • A — Split sendIfRequired into a guard + reusable flushPending, and flush every non-empty slot in connectionProcessor before finishing. No command is left unsent.
  • B — Add an atomic totalOps counter (one increment per recorded command) and use it for TotalOps/overallOpsRate. The histograms now own percentiles only, where cap-clamping the tail is standard.
  • C — Keep the send-time uniform pipeline latency (one batch round-trip per command — matches redis-benchmark), capture sendT after building the pipeline action, and reframe the 1µs floor honestly (a network round-trip is never 0µs; it is not a TotalOps fix).

Validation (E2E against redis)

TotalOps == dbsize == input count at every pipeline depth, was lossy before:

--pipeline before after
1 2000 2000
3 1980 2000
8 1920 2000
16 1920 2000
100 (lossy) 2000

Tests

  • TestTotalOpsIsAtomicNotHistogramDerived — records an above-cap latency (rejected by the histogram) and asserts TotalOps still counts it (via the atomic counter).
  • TestFTSBPipelineTailIsFlushedAndCountedintegration test: --pipeline 3 over the 100-row minimal.csv asserts TotalOps == 100 (pre-fix: 99). Runs in CI's Docker integration step.
  • TestPipelineRecordsPerCommandTxAndDoesNotPanic — per-command Tx + equal/floored batch latency.
  • Full cmd/... + benchmark_runner suites pass with -race.

Out of scope — filed as follow-ups

…m TotalOps

Latency was computed as endT - pc.start, where pc.start is when a command was
buffered into the pipeline window. In a pipeline the last-buffered command is
flushed immediately, so its took rounded to 0us; the HDR histograms are
New(1, cap, 3) (min 1us), so RecordValue(0) is rejected and that command
silently vanishes from TotalOps and the latency histograms (observed:
TotalOps=1999 for 2000 commands at --pipeline 4). It also skewed per-command
latency: the first-buffered command's latency wrongly included the client-side
wait for the window to fill.

Measure latency from the batch send time instead (captured just before
client.Do) and attribute that single round-trip to every command in the flush,
clamped to >=1us. A pipeline is one client round-trip, so this is the correct
client-observed latency and it can't be sub-microsecond over TCP.

- No continuity impact: --pipeline >1 crashed before #114 (no historical data),
  and at pipeline=1 sendT equals the command's buffer time, so latency is
  unchanged.
- Validated E2E: TotalOps == 2000 at --pipeline 1, 4, and 10 (was 1999 at 4).
- Test asserts pipelined commands share one clamped, non-zero latency.
…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.
@fcostaoliveira fcostaoliveira changed the title Fix pipeline latency accounting: don't silently drop ops from TotalOps Fix pipeline command accounting: flush trailing window + exact TotalOps Jul 13, 2026
@fcostaoliveira

Copy link
Copy Markdown
Contributor Author

Follow-ups filed: #116 (histogram RecordValue race under -workers>1) and #117 (#114 reply-capture unmarshal inflating FT.SEARCH latency).

…ity gate

- Extract the pipeline-flush error/timeout logging into logFlushError, dropping
  flushPending's cognitive complexity below the threshold (behavior unchanged;
  timeout integration tests still pass).
- Extract the duplicated docker-redis setup in the integration tests into a
  shared startRedisContainer(t) helper (removes the new-code duplication the
  Sonar gate flagged; all 7 call sites now share one copy).
…cation

Collapse the duplicated 'run binary + read json result' boilerplate in the
JSON-asserting integration tests into a shared runFTSBReadJSON helper (drops the
vestigial REDIS_URL env, which ftsb never reads). Pushes new-code duplication
below the Sonar gate threshold.
- Collapse two more docker-setup blocks (blank-line variant missed earlier) into
  startRedisContainer.
- Extract BenchmarkRunner.overallCounts() so GetOverallRatesMap and summary share
  the per-label count + atomic-totalOps gathering instead of duplicating it.
Behavior unchanged; TotalOps/overallOpsRate verified E2E.
…rd, live-total reconcile

Fixes from the pre-merge adversarial review (no change to the A/B/C behavior):

- logFlushError: restore the historical "Fatal error with" prefix on the
  -continue-on-error=false path (the refactor had softened it to "Received an
  error with"). Control flow/exit unchanged; log text now matches master.
- GetMeasuredRatiosMap: guard totalOps==0 so empty input yields 0 ratios instead
  of NaN (NaN is unmarshalable -> json.Marshal aborted the run with no result
  file). Adds a unit test. Also documents that ratios (histogram numerators over
  the exact atomic total) may sum to <1.0 on tail-heavy runs -- intended.
- Live periodic reporter: derive its total ops from the atomic counter so the
  progress line reconciles with the final TotalOps/overallOpsRate.
- Extract flooredMicros() with a deterministic unit test (the fake-client clamp
  assertion was timing-dependent).
- GetTotalsMap: read TxBytes/RxBytes via atomic.LoadUint64 for consistency.
- Move the flushPending doc comment back onto flushPending (the logFlushError
  extraction had detached it).
- Integration test: assert TxBytes>0 and RxBytes>0 (reply capture) on the
  pipeline-tail run.

Validated: empty input no longer crashes (exit 0, JSON written, ratios 0);
pipeline-tail + timeout integration tests pass; full suite -race clean.
@sonarqubecloud

Copy link
Copy Markdown

@fcostaoliveira

Copy link
Copy Markdown
Contributor Author

16-way adversarial review (Opus 4.8) done on the current HEAD — verdict: merge. Note for consumers: overallOpsRate/TotalOps become more correct (they now count tail/timeout/pipeline-tail ops the histogram previously dropped), so the value steps up at this merge for tail-heavy or pipelined runs — that's honest counting, not a throughput change. Follow-ups filed: #116 (histogram + timeseries races), #117 (reply-capture latency), and the new pipelined-error-count inflation issue.

@fcostaoliveira
fcostaoliveira merged commit 01dce89 into master Jul 13, 2026
3 checks passed
@fcostaoliveira
fcostaoliveira deleted the fix/pipeline-latency-accounting branch July 13, 2026 14:29
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.

1 participant