Add docs on UNMANAGED_CODE_TIME and CPU_TIME #1613
Conversation
|
|
||
| The above code will generate CPU samples on EventPipe that look like `Main` or `Main->A->B->C->MyNativeFunction` but contain none of the native stack that happens after `MyNativeFunction`. | ||
|
|
||
| During a typical CPU usage investigation, you may want to ask about on-CPU vs off-CPU time to determine when your code is blocked waiting or actively doing work. Due to the limitation of only knowing about managed frames, CPU samples collected via EventPipe can't give exact on/off-CPU information. Instead, the TraceEvent library uses a heuristic to add pseudo-frames to the trave that indicate whether there are additional native frames on the stack or no. It uses relative time deltas between events and the state of the Garbage Collector at the time the sample was take to insert either `UNMANAGED_CODE_TIME` or `CPU_TIME` onto the stack in the "Thread Time" view or when exporting to SpeedScope or other formats. `UNMANAGED_CODE_TIME` represents stacks where there are one or more native frames after the last managed frame and that these frames may be blocked waiting _or_ actively on the CPU. `CPU_TIME` represents stacks where the last managed frame is the function currently on the CPU and doing work. |
There was a problem hiding this comment.
The last two sentences seem to contradict the 3rd from last.
UNMANAGED_CODE_TIMErepresents stacks where there are one or more native frames after the last managed frame and that these frames may be blocked waiting or actively on the CPU.CPU_TIMErepresents stacks where the last managed frame is the function currently on the CPU and doing work.
I read these sentences saying that what matters is whether there are native frames at the leaf of the stack.
It uses relative time deltas between events and the state of the Garbage Collector at the time the sample was take to insert either
UNMANAGED_CODE_TIMEorCPU_TIMEonto the stack in the "Thread Time" view or when exporting to SpeedScope or other formats
I read this sentence saying that what matters is the GC state and time deltas.
There was a problem hiding this comment.
The phrasing is definitely confusing. The GC state is what informs the computer whether there were native leaf frames, and the relative time deltas tell us how long that was the case.
For example, if I have a function that is 50% managed work and 50% P/Invoked work, I'd end up with two sets of thread time stacks. One that is MyFunction->CPU_TIME corresponding to the aggregate of samples where the GC was in COOP mode and another that is MyFunction->UNMANAGED_CODE_TIME for when the GC was in PRE mode.
The duration of the CPU_TIME and UNMANAGED_CODE_TIME frames come from the relative deltas and which frame gets used comes from the GC mode during the sample.
Let me try to reword this so it's more obvious that all these things are describing the same set of information.
There was a problem hiding this comment.
I'd suggest deleting the part about GC state and time deltas in that case. I think the critical information for the reader is to understand what callstack produces what descriptive term. The techniques we use to determine the callstack are implementation details that appear unnecessary as long as they are accomplishing the job reliably.
| @@ -936,3 +936,41 @@ Unfortunately when a provider registers with the operating system (the Win32 `Ev | |||
| ## On the fly filtering AND Logging using `ETWReloggerTraceEventSource` | |||
|
|
|||
| TODO | |||
|
|
|||
| ## `UNMANAGED_CODE_TIME` and `CPU_TIME` when analyzing CPU traces collected with EventPipe | |||
There was a problem hiding this comment.
This is useful for people targeting TraceEvent programmatically. For users using PerfView I'd expect them to look here instead: https://github.com/microsoft/perfview/blob/main/src/PerfView/SupportFiles/UsersGuide.htm. That page is the guide that is included in the PerfView tool where all the in-app help links resolve to.
There was a problem hiding this comment.
Yes, I think that's a better spot for this.
|
@josalem how many people look at this repo? In the meeting we were talking about how perfview is not the tool we really try to advertise. I think it is important to have this documented somewhere people can see it because UNMANAGED_CODE_TIME and CPU_TIME show up on any traces (not just when the traces are analyzed in perfview). |
@mikelle-rogers, this is a good question. I do think that this belongs in the |
These pseudo frames show up in 2 places and only if the trace is a nettrace file collected via EventPipe:
While We could link to this blurb in the user guide (after I move it there) from the For example: "dotnet-trace uses the TraceEvent library for converting nettrace files to other formats. For details on the conversion, see: ". |
That sounds great to me! |
Agreed, sounds great. |
fixes dotnet/diagnostics#1166