Skip to content

Commit 5d0e8af

Browse files
wesleywisermichaelwoerister
authored andcommitted
Add more comments about how self-time works
1 parent 1952df5 commit 5d0e8af

File tree

1 file changed

+58
-1
lines changed

1 file changed

+58
-1
lines changed

summarize/src/analysis.rs

Lines changed: 58 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -52,6 +52,62 @@ pub fn perform_analysis(data: ProfilingData) -> Results {
5252
}
5353
};
5454

55+
/*
56+
The basic idea is to iterate over all of the events in the profile data file, with some
57+
special handling for Start and Stop events.
58+
59+
When calculating timing data, the core thing we're interested in is self-time.
60+
In order to calculate that correctly, we need to track when an event is running and when
61+
it has been interrupted by another event.
62+
63+
Let's look at a simple example with two events:
64+
65+
Event 1:
66+
- Started at 0ms
67+
- Ended at 10ms
68+
69+
Event 2:
70+
- Started at 4ms
71+
- Ended at 6ms
72+
73+
0 1 2 3 4 5 6 7 8 9 10
74+
================================
75+
1 |------------------------------|
76+
2 |-----|
77+
78+
When processing this, we see the events like this:
79+
80+
- Start Event 1
81+
- Start Event 2
82+
- End Event 2
83+
- End Event 1
84+
85+
Now, I'll add some annotation to these events to show what's happening in the code:
86+
87+
- Start Event 1
88+
- Since there is no other event is running, there is no additional bookkeeping to do
89+
- We push Event 1 onto the thread stack.
90+
- Start Event 2
91+
- Since there is another event on the stack running, record the time from that event's
92+
start time to this event's start time. (In this case, that's the time from 0ms - 4ms)
93+
- We push Event 2 onto the thread stack.
94+
- End Event 2
95+
- We pop Event 2's start event from the thread stack and record the time from its start
96+
time to the current time (In this case, that's 4ms - 6ms)
97+
- Since there's another event on the stack, we mutate its start time to be the current
98+
time. This effectively "restarts" that event's timer.
99+
- End Event 1
100+
- We pop Event 1's start event from the thread stack and record the time from its start
101+
time to the current time (In this case, that's 6ms - 10ms because we mutated the start
102+
time when we processed End Event 2)
103+
- Since there's no other events on the stack, there is no additional bookkeeping to do
104+
105+
As a result:
106+
Event 1's self-time is `(4-0)ms + (10-6)ms = 8ms`
107+
108+
Event 2's self-time is `(6-2)ms = 2ms`
109+
*/
110+
55111
for event in data.iter() {
56112
match event.timestamp_kind {
57113
TimestampKind::Start => {
@@ -109,7 +165,8 @@ pub fn perform_analysis(data: ProfilingData) -> Results {
109165
data.invocation_count += 1;
110166
});
111167

112-
//now adjust the previous event's start time so that it "started" right now
168+
//this is the critical bit to correctly calculating self-time:
169+
//adjust the previous event's start time so that it "started" right now
113170
if let Some(previous_event) = thread_stack.last_mut() {
114171
assert_eq!(TimestampKind::Start, previous_event.timestamp_kind);
115172
previous_event.timestamp = event.timestamp;

0 commit comments

Comments
 (0)