Fix/streaming timestamps

[mcurrier2]

Description

Brief description of changes

Type of Change

• [ x] Bug fix
• New feature
• Breaking change
• Documentation update

Testing

• [ x] Tests pass locally
• [ x] Added tests for new functionality
• [ x] Updated documentation

Checklist

• [ x] Code follows style guidelines
• [ x] Self-review completed
• Comments added for complex code
• [ x] Documentation updated
• No breaking changes (or marked as breaking)

PR: Fix Streaming Output Timestamps Across All Code Paths

Summary

Streaming output timestamps (timestamp_ns in JSON/CSV per-message
records) were inaccurate across multiple code paths. Instead of
recording when each message was actually sent, timestamps were captured
at record-creation time — either post-test during batch iteration or
at file-read time. This caused all timestamps within a test run to
cluster into the same second, making time-series analysis of streaming
data meaningless.

Because this tool's primary purpose is precision measurement, incorrect
timestamps in the streaming output undermine the validity of per-message
latency records for any downstream analysis or visualization.

Branch: fix/streaming-timestamps
Base: main
Files changed: 11 (496 insertions, 60 deletions)

---

Root Cause

Commit e0ff7fa (Oct 8, 2025, PR #82) refactored the benchmark runner
to collect latencies inside spawned async futures, then batch-create
MessageLatencyRecord objects after the futures completed. This moved
the SystemTime::now() call from inside the hot loop (where it
reflected each message's send time) to the post-test iteration (where
it reflected the moment the record was created — all within the same
second).

The initial fix on this branch (68afe07) changed the
MessageLatencyRecord API to accept send_timestamp_ns as a
parameter, but only the blocking round-trip path was actually capturing
timestamps at send time. Three other code path families remained broken.

---

Problems and Fixes

1. Async round-trip timestamps captured post-test

Problem: The client future returned Vec<Duration>. After the
future completed, the post-test loop called current_timestamp_ns()
at record-creation time. All records received the same timestamp.

Fix: Changed the future to capture current_timestamp_ns() before
each send() and return Vec<(Duration, u64)>. The post-test loop
uses the captured timestamp.

// Inside the client future, before each send:
let wall_ts = MessageLatencyRecord::current_timestamp_ns();
let send_time = Instant::now();
client_transport.send(&message).await?;
// ...
latencies.push((send_time.elapsed(), wall_ts));

// Post-test loop:
for (i, (latency, wall_ts)) in latencies.iter().enumerate() {
    let record = MessageLatencyRecord::new(
        i as u64, mechanism, msg_size,
        LatencyType::RoundTrip, *latency, *wall_ts,
    );
}

Applies to: Both duration-based and count-based async round-trip
loops in src/benchmark.rs.

2. Async combined timestamps captured post-test

Problem: Same pattern as round-trip — the combined test (one-way +
round-trip in a single run) collected latency durations inside the
spawned future and created records post-test with stale timestamps.

Fix: Changed one_way_latencies to Vec<(Duration, u64)> to
carry the wall-clock timestamp alongside each measurement. The
timestamp is captured before each send() inside the future.

Applies to: Both duration-based and count-based async combined
loops in src/benchmark.rs.

3. One-way timestamps from file-read time instead of send time

Problem: One-way tests use a server process that measures receive
latency and writes results to a temporary file. The original format
was one latency_ns value per line. The client read this file
post-test and called current_timestamp_ns() at file-read time —
all records received the same timestamp.

Fix (server side): Both async and blocking server loops now write
wall_send_ns,latency_ns per line. The wall-clock send time is
computed as SystemTime::now() - latency_ns, approximating when the
message entered the IPC channel.

// Server, after measuring latency:
let wall_now_ns = SystemTime::now()
    .duration_since(UNIX_EPOCH)
    .unwrap_or_default()
    .as_nanos() as u64;
let wall_send_ns = wall_now_ns.saturating_sub(latency_ns);
writeln!(file, "{},{}", wall_send_ns, latency_ns).ok();

Fix (client side): A new parse_latency_file_line() function
parses the two-field format. Both async and blocking file readers
use the parsed wall_send_ns as send_timestamp_ns.

Applies to: src/main.rs (both server loops), src/benchmark.rs
(async reader), src/benchmark_blocking.rs (blocking reader).

---

Known Limitations

Wall-clock / monotonic clock mixing in one-way path

For one-way tests, the server computes the send timestamp by
subtracting the measured monotonic latency from its current wall-clock
time. This mixes two clock domains:

• latency_ns = monotonic_receive - monotonic_send
  (from message timestamp)
• wall_send_ns = SystemTime::now() - latency_ns

If NTP adjusts the system clock between message send and receive, the
computed wall_send_ns will be slightly off. This is the best
approximation available without clock synchronization between the
client and server processes. The error is bounded by the magnitude
of any NTP adjustment during the test (typically microseconds).

Timestamp capture ordering

In the round-trip and combined futures, current_timestamp_ns() is
captured one instruction before Instant::now(). The wall-clock
timestamp therefore slightly predates the monotonic measurement start.
The gap is single-digit nanoseconds — orders of magnitude below the
IPC latencies being measured.

---

Tests Added

Unit tests for parse_latency_file_line (7 tests)

Test	Coverage
test_parse_latency_file_line_valid	Happy path: "170...,42000"
test_parse_latency_file_line_zeros	Edge case: "0,0"
test_parse_latency_file_line_missing_comma	Error: single value
test_parse_latency_file_line_empty	Error: empty string
test_parse_latency_file_line_non_numeric_first	Error: "abc,789"
test_parse_latency_file_line_non_numeric_second	Error: "123,xyz"
test_parse_latency_file_line_extra_commas	Error: "1,2,3"

Enhanced end-to-end streaming tests (2 tests)

Both test_one_way_streaming_captures_send_timestamp and
test_round_trip_streaming_captures_send_timestamp now validate:

1. All timestamp_ns values fall within the test execution window
   (before_ns <= ts <= after_ns)
2. Timestamps are not all identical (which was the original bug)

Pre-existing timestamp API tests (3 tests in results.rs)

• test_new_uses_provided_send_timestamp
• test_new_combined_uses_provided_send_timestamp
• test_current_timestamp_ns_returns_recent_value

---

Documentation Added

README.md: Streaming Output Columns

Added a new "Streaming Output Columns" section documenting all six
per-message streaming columns with types, descriptions, and nullable
semantics:

Column	Type	Description
timestamp_ns	u64	Wall-clock time message was sent
message_id	u64	Zero-based message identifier
mechanism	string	IPC mechanism name
message_size	u64	Payload size in bytes
one_way_latency_ns	u64/null	One-way latency
round_trip_latency_ns	u64/null	Round-trip latency

Includes a note on timestamp_ns accuracy for one-way tests
(wall-clock / monotonic clock mixing).

---

Validation

Unit and Integration Tests

$ cargo test
test result: ok. 265 passed; 0 failed; 1 ignored
(+ 42 doc tests, 27 integration tests — 334 total)

$ cargo clippy --all-targets -- -D warnings
# zero warnings

$ cargo fmt --check
# clean

$ scripts/msrv-check.sh
[MSRV] Rust 1.70 build/tests passed.

Functional Verification

3-second duration benchmarks across all mechanisms with streaming
output enabled. Timestamps validated to span the full test window:

Mechanism	Mode	First Timestamp	Last Timestamp	Delta (s)	Messages
UDS	Round-Trip	13:13:48.101628	13:13:51.101572	3.000	213,424
TCP	Round-Trip	13:13:55.154037	13:13:58.153894	3.000	132,423
SHM	One-Way	13:17:32.079542	13:17:35.079503	3.000	1,317,468
PMQ	Round-Trip	13:14:15.407160	13:14:18.362355	2.955	42,687

All mechanisms show timestamps distributed across the full test
duration. PMQ delta is 45ms short due to backpressure from shallow
system queue depth (typically 10 messages).

Before/After: Timestamp Distribution

Before fix (main branch): All timestamp_ns values in streaming
output were within the same second, regardless of test duration. A
3-second test with 200,000+ messages would show all timestamps
clustering around a single epoch second.

After fix: Timestamps span the full test duration. Each message's
timestamp_ns reflects the approximate wall-clock time it was sent,
enabling meaningful time-series analysis of per-message latency data.

---

Files Changed

File	Change
src/benchmark.rs	Capture wall_ts inside async round-trip and combined futures before each send(); update one-way file reader to parse new wall_send_ns,latency_ns format; add parse_latency_file_line() with 7 unit tests; enhance 2 end-to-end streaming tests with timestamp validation
src/benchmark_blocking.rs	Update blocking one-way file reader to parse new format using parse_latency_file_line()
src/main.rs	Both async and blocking server loops write wall_send_ns,latency_ns per line (was latency_ns only)
README.md	Add "Streaming Output Columns" section with column definitions and accuracy note
src/results.rs	MessageLatencyRecord::new() and new_combined() accept send_timestamp_ns parameter; add current_timestamp_ns() helper; 3 API tests
src/ipc/tcp_socket.rs	Refactor is_some()/unwrap() to if let (clippy fix)
src/ipc/unix_domain_socket.rs	Same clippy fix
Cargo.toml	Pin uuid to <1.21 for MSRV compatibility
.cargo/audit.toml	Ignore known MSRV-pinned dependency advisories
CONFIG.md	Document sequential test execution
utils/dashboard/README.md	Note sequential test execution

---

Risk Assessment

• Low risk. The core latency measurement logic (monotonic clock,
  get_monotonic_time_ns()) is untouched. Only the wall-clock
  metadata timestamp in streaming records is changed.
• Backward compatible. No CLI changes. Streaming output JSON/CSV
  schema is unchanged (same columns, same types). The internal
  server-to-client latency file format changed from latency_ns to
  wall_send_ns,latency_ns, but this file is ephemeral (created and
  deleted within a single benchmark run) and never exposed to users.
• All 334 tests pass with zero clippy warnings.
• MSRV 1.70 verified via containerized pre-commit check.

[dustinblack]

I closed #92 because fresh testing showed the problem was no longer reproducible. Issue #106 was then created the following day as the basis for this PR, but it contains no evidence of an actual problem — no reproduction steps, no sample output showing incorrect timestamps, and no before/after data.

I'd suggest closing this PR and #106 unless concrete evidence can be provided in #106 demonstrating that the specific code paths being fixed here actually produce incorrect timestamps on the current main branch — similar to what I provided in #92.

[mcurrier2]

These are valid issues/problems. I added to issue #106 showing the problems and before/after scenarios.

[dustinblack]

Thanks for adding the evidence to #106 — the before/after data clearly demonstrates the problem across round-trip, combined, and one-way code paths. The bugs are real and the fixes are technically sound. Withdrawing my earlier suggestion to close.

Technical assessment of the changes:

The fixes are correct. Moving SystemTime::now() capture from record-creation time to send time (via the send_timestamp_ns parameter on new()/new_combined()) is the right approach. The one-way server-side approximation (wall_now - latency) mixes clock domains but is clearly documented and is the best available without clock sync. The parse_latency_file_line() parser is clean, and the test coverage is thorough.

Before this can be approved, it needs:

1. Rebase on main. This branch is based on e826b20, missing PRs #103 and #104. The clippy refactors and .cargo/audit.toml are already on main and will drop out. CI failures should resolve.

2. Coordinate file format with PR #109. This PR changes the server latency file from latency_ns to wall_send_ns,latency_ns. PR #109's write_latency_buffer() writes the old single-field format. Whichever merges second needs to match. Since #109 is closer to approval, consider whether this PR should rebase on top of #109 or vice versa.

3. Remove documentation that overlaps with PR #108. The "Streaming Output Columns" and "Test Execution Order" README sections appear in both PRs. Whichever PR owns those sections, the other should drop them to avoid merge conflicts. Since those sections are most relevant here, I'd suggest keeping them in this PR and removing them from #108.