Bug: Timestamps in streaming output are incorrect, showing the same second for all messages

[dustinblack]

Description

When running a benchmark with streaming JSON or CSV output enabled, the timestamp_ns field for all MessageLatencyRecord entries is incorrect. The timestamps are all generated at the very end of the test run, causing them to have nearly identical values. This makes it impossible to analyze the test's progress over time, as the difference between the first and last timestamp in the file is a fraction of a second, even for tests that run for several minutes.

Steps to Reproduce

1. Run a benchmark with streaming output enabled. For example:

   cargo run --release -- -m pmq -s 128 -i 100000 --streaming-output-json /tmp/pmq_test.json

2. Examine the output file /tmp/pmq_test.json.
3. Observe the timestamp_ns values in the data array.

Expected Behavior

The timestamp_ns for each message record should reflect the approximate time that the message was sent. The difference between the first and last timestamp in the file should be close to the total duration of the benchmark run.

Actual Behavior

All timestamp_ns values have the same seconds component, making it appear as though the entire test completed in under a second.

• Example first timestamp: 1765229013390343
• Example last timestamp: 1765229013780759
• Difference: 390,416 ns (approx. 0.0004 seconds)

Analysis of Root Cause

The issue lies in how and when the timestamps for the streaming records are generated.

1. The benchmark loops in src/benchmark.rs (e.g., run_single_threaded_one_way) correctly create Message objects, which have a timestamp generated at the moment of creation.
2. However, during the test loop, only the latency Duration is collected into a Vec. The original message's timestamp is discarded.
3. After the benchmark loop completes, the code iterates over the collected Vec<Duration> and creates a MessageLatencyRecord for each one.
4. The MessageLatencyRecord::new() function in src/results.rs generates a new timestamp using SystemTime::now() at the moment it is called.

Because this happens in a tight loop after the test is finished, all records get a timestamp from that final moment, not from when the original message was sent.

Proposed Solution

The Message struct already contains the correct timestamp. This timestamp needs to be preserved and passed through to the MessageLatencyRecord.

1. Modify src/results.rs:

   • Update the MessageLatencyRecord::new and new_combined functions to accept a timestamp_ns: u64 parameter instead of generating a new one internally.

2. Modify src/benchmark.rs:

   • In the benchmark loops (e.g., run_single_threaded_one_way), the client logic should collect a tuple of (u64, Duration) representing (message_timestamp, latency) instead of just the Duration.
   • When creating the MessageLatencyRecord after the loop, pass the captured timestamp from the tuple into the updated MessageLatencyRecord::new function.

This will ensure that the timestamps in the streaming output accurately reflect the time each message was sent during the benchmark.

[acalhounRH]

Retested using main latest and not observing this particular issue with timestamps. seperately i am observing an issue with early timeout during SHM besides this issue the quality of timestamps for timeseries data is intact.

please retest using main latest.