Add speedscope export timestamp fallback#899
Conversation
2118cc9 to
1daa4a2
Compare
|
See an example scope for the sqlite example by using › https://github.com/user-attachments/files/26490542/memray-speedscope-example.py.201148.speedscope.json in https://www.speedscope.app |
1daa4a2 to
31e477b
Compare
Codecov Report❌ Patch coverage is
Additional details and impacted files@@ Coverage Diff @@
## main #899 +/- ##
==========================================
+ Coverage 92.22% 92.29% +0.06%
==========================================
Files 99 99
Lines 12556 12705 +149
Branches 432 442 +10
==========================================
+ Hits 11580 11726 +146
- Misses 976 979 +3
Flags with carried forward coverage won't be shown. Click here to find out more. ☔ View full report in Codecov by Harness. 🚀 New features to boost your workflow:
|
godlygeek
left a comment
There was a problem hiding this comment.
I'm still looking through this one. I've reviewed the changes to add the allocation timestamp to every allocation record, I haven't yet really reviewed the new report. I've got a few comments on the code from the first commit.
But mostly, I'm a bit confused by why we need the per-allocation timestamp. What is it that this gives us beyond what we can already get from our temporal format? Is it just to get finer granularity rather than sticking us with the default 10ms granularity?
| const bool d_allocation_timestamps; | ||
| linker::SymbolPatcher d_patcher; | ||
| std::unique_ptr<BackgroundThread> d_background_thread; | ||
| const std::chrono::steady_clock::time_point d_monotonic_start{std::chrono::steady_clock::now()}; |
There was a problem hiding this comment.
Is there any way that we can synchronize this to refer to the exact same moment in time as the start_time in the metadata? I think the answer is "no", but if we could it would be very nice. As it is, we can sort of say what wall clock time an event happened at, but not exactly - even setting aside clock adjustments due to NTP or whatever, or DST transitions, we'll always be off by some fixed number of microseconds due to the delta between when we get the wall clock timestamp and when we get the monotonic clock timestamp.
Like I said, I don't think there's anything we can do about that, but if there was it'd be cool...
|
Hm. An interesting observation, with my current favorite stress test: memray run --trace-python-allocators --allocation-timestamps --no-compress -fo output.bin -m test test_set82.50% of all records have a delta of 0 microseconds from the previous The uncompressed capture file is 184,012,800 bytes and contains 42,419,372 allocation records, and deltas of 0 or 1 are varint encoded as a single byte per allocation record, so 19% of the space in the uncompressed capture file (~35 megabytes) is spent encoding "the time hasn't changed since the last record", and an additional 4% of the capture file (~7 megabytes) is spent encoding "the time changed by 1us since the last record". That seems very inefficient, and makes me think we want a different encoding for timestamps. I'm thinking about creating a new |
0fe392c to
8e9452e
Compare
|
@pablogsal I'm still not understanding why we need to add the fine grained timestamps for the speedscope report. It seems like the only thing they're used for is to tell when the first time we saw an allocation with a given stack was, and then the superposition of stacks in the speedscope flamegraph winds up ordered left to right by the first time we saw an allocation at each of those stacks. Right? But... we don't need timestamps for that! The capture file is written in allocation order, so we know whether we saw an allocation with stack X before an allocation with stack Y without needing to know exactly when those allocations occurred. We could get the exact same behavior just replacing the timestamp with a sequence number. I feel like either I'm badly misreading something or you implemented a really overengineered way to explicitly record a piece of information that we already had implicitly. Starting with your original commit 31e477b (just to make sure I haven't screwed anything up while working on it), I applied this patch: diff --git a/src/memray/_memray/tracking_api.cpp b/src/memray/_memray/tracking_api.cpp
index 3dc1692..9b581bf 100644
--- a/src/memray/_memray/tracking_api.cpp
+++ b/src/memray/_memray/tracking_api.cpp
@@ -1495,6 +1495,7 @@ Tracker::getTracker()
uint64_t
Tracker::currentTimestampUs() const
{
+ std::this_thread::sleep_for(std::chrono::microseconds(1));
return std::chrono::duration_cast<std::chrono::microseconds>(
std::chrono::steady_clock::now() - d_monotonic_start)
.count();That makes it so that we still record the fine grained timestamps, but also guarantees that every allocation will have a unique timestamp, so that the order is deterministic (we never have two allocations rounded to the same timestamp because of our quantum). Then, I ran: memray run -fo output.bin --allocation-timestamps --trace-python-allocators -m test test_setto generate a report with tons of data, and with allocation timestamps in the report. I generated a speedscope report with: memray transform speedscope -f -o memray-speedscope-output.speedscope.json.uniq_micros output.binThen I applied this patch, which completely ignores the timestamps encoded in the capture file in favor of just using a sequence number: diff --git a/src/memray/_memray/record_reader.cpp b/src/memray/_memray/record_reader.cpp
index 64eecd4..b29aa2a 100644
--- a/src/memray/_memray/record_reader.cpp
+++ b/src/memray/_memray/record_reader.cpp
@@ -356,7 +356,7 @@ RecordReader::processAllocationRecord(const AllocationRecord& record)
d_latest_allocation.native_segment_generation = 0;
}
d_latest_allocation.n_allocations = 1;
- d_latest_allocation.timestamp_us = record.timestamp_us;
+ d_latest_allocation.timestamp_us++;
return true;
}and then I regenerated that report again: memray transform speedscope -f -o memray-speedscope-output.speedscope.json.uniq_seqnum output.binand... the two files are byte-for-byte identical. The only difference the timestamp makes over a sequence number is screwing up the order, by making it arbitrary which order two allocations seen in the same microsecond show up in! Am I missing something? |
Teach the transform reporter to emit sampled speedscope profiles for bytes and allocation counts, preserving root-to-leaf stack order and aggregating identical stacks. Preserve the capture order with sequence numbers assigned while building snapshots. This keeps the export deterministic without changing the capture format or recording allocation timestamps. Signed-off-by: Pablo Galindo Salgado <pablogsal@gmail.com>
8e9452e to
d3692c5
Compare
|
Yep, you’re totally right 😅 My fault. I’m used to profiling formats that rely on timestamps, so I went straight down that path. I’ve removed all the timestamp machinery and the temporal fallback. Snapshot aggregation now keeps a local sequence number and uses it to preserve ordering. I also rebased everything into one clean commit. Thanks for catching it! |
Build the speedscope export around sampled stacks and make the ordering
source explicit instead of relying on the reader's iteration order.
When a capture has exact allocation timestamps, record them in the
non-aggregated file format, expose them through the reader metadata, and
sort each aggregated speedscope sample by the earliest allocation time
that contributed to it. This keeps the sampled profile aligned with the
real execution order without changing the existing high-water-mark and
leak aggregation logic.
When exact timestamps are not available, switch the speedscope path to
temporal allocation records and recover a stable approximation from the
memory snapshots we already store. Leak exports keep only intervals that
survive to the end of the run and order them by the first snapshot where
they appear. High-water-mark exports evaluate intervals at the peak
snapshot and order them by the first snapshot that contributes to that
peak.
Keep this behavior speedscope-specific and reject
--aggregatewith--allocation-timestamps, because aggregated captures discard the eventordering that the export depends on. The patch also bumps the file
format/header metadata and adds command, reader/writer, and reporter
tests for both the exact-timestamp and fallback paths.
Issue number of the reported bug or feature request: #
Describe your changes
A clear and concise description of the changes you have made.
Testing performed
Describe the testing you have performed to ensure that the bug has been addressed, or that the new feature works as planned.
Additional context
Add any other context about your contribution here.