dotnet / runtime

.NET is a cross-platform runtime for cloud, mobile, desktop, and IoT apps.
https://docs.microsoft.com/dotnet/core/
MIT License
14.54k stars 4.54k forks source link

R2RGetEntryPoint ETW / eventpipe event missing a size #103421

Open vvuk opened 2 weeks ago

vvuk commented 2 weeks ago

On Windows, when coreclr loads R2R-built jit assemblies are loaded, symbols from them can be resolved using PDB files and everything works fine. On macOS (and probably linux, since they share the same code), PreJIT symbols are emitted into jitdump files with PerfMapEnabled=1 (but not perfmap files, which is also odd).

Using eventpipe, MethodLoad[Verbose] events are not emitted for for R2R symbols. This is a little annoying, but it matches Windows behaviour. However, there are R2RGetEntryPoint events that are emitted with the compiler diagnostics keyword. These events have almost all the info I need... except the method native code size. As-is, the data in these events gives roughly the same info as a basic symbol map. For every R2RGetEntryPoint, I could look up what native library is mapped at that address and add it to my in-memory symbol map, and then on library unload/process end take all the symbols and infer sizes based on next symbol/end-of-mapping. This is kind of a pain.

I believe the size is available using the same approach that PerfMap::LogPreCompiledMethod uses:

    // Get information about the NGEN'd method code.
    EECodeInfo codeInfo(pCode);
    _ASSERTE(codeInfo.IsValid());

    IJitManager::MethodRegionInfo methodRegionInfo;
    codeInfo.GetMethodRegionInfo(&methodRegionInfo);

if this is true, are people open to a V1 of the R2RGetEntryPoint event that adds a code size? This would mean that the V0 event would no longer be emitted, so PerfView and others may be impacted, though I'm not sure if they're doing anything specific with this event.

R2RGetEntryPoint also doesn't include info about separate hot/cold precompiled code (there's only one method start address, so I assume only the hot address gets reported). Maybe a better approach would be adding a new event, R2RMethodLoad, that looks something like...

                        <data name="MethodID" inType="win:UInt64" outType="win:HexInt64" />
                        <data name="MethodNamespace" inType="win:UnicodeString" />
                        <data name="MethodName" inType="win:UnicodeString" />
                        <data name="MethodSignature" inType="win:UnicodeString" />
                        <data name="MethodStartAddress" inType="win:Pointer" />
                        <data name="MethodSize" inType="win:UInt32" />
                        <data name="MethodColdStartAddress" inType="win:Pointer" />
                        <data name="MethodColdSize" inType="win:UInt32" />
                        <data name="ClrInstanceID" inType="win:UInt16" />
vvuk commented 2 weeks ago

I could look up what native library is mapped at that address

An update.. I can't do this. I thought there was an actual native library but there isn't; it looks like the r2r compiled code is just in the original assembly? There's no event that provides any mapping/memory region info that I can find.

dotnet-policy-service[bot] commented 2 weeks ago

Tagging subscribers to this area: @tommcdon See info in area-owners.md if you want to be subscribed.

tommcdon commented 2 weeks ago

@noahfalk @davmason

davmason commented 2 weeks ago

Adding @brianrob

Hi @vvuk - on non-windows platforms we use alternative ways to get the symbol information for R2R code. You should not have to introduce a new event to the runtime.

The perfcollect tool uses crossgen /CreatePerfMap to generate perfmaps from R2R images, and following that example would be your best bet.

noahfalk commented 1 week ago

@vvuk - I believe a typical way that ETW/EventPipe based profilers would access this data is via rundown events (https://github.com/dotnet/runtime/blob/main/src/coreclr/vm/eventtrace.cpp#L5091-L5117). The terminology is still confusingly labeled as NGen methods, but it is actually enumerating R2R methods on CoreCLR. The rundown events aren't documented much but all the event manifest info is in ClrEtwAll.man. You could look for the MethodDCEnd and MethodDCEndVerbose events on the rundown provider using the NGenRundownKeyword.

The approach David suggested does also work but you might find rundown events easier to work with. There are no external dependencies and the events should work uniformly on any platform where ETW/EventPipe is supported.

brianrob commented 1 week ago

@vvuk, can you share a bit more about the scenario? Both @davmason and @noahfalk have mentioned options that could potentially work, but knowing a bit more about what you are trying to do would help me.

vvuk commented 1 week ago

You could look for the MethodDCEnd and MethodDCEndVerbose events on the rundown provider using the NGenRundownKeyword.

Ah ha! I was aware of the rundown provider (and am using it for some things) but I didn't consider pulling the method info from there. It looks like this should have what I need. I'll try this and will report/close if this is sufficient.

@vvuk, can you share a bit more about the scenario? Both @davmason and @noahfalk have mentioned options that could potentially work, but knowing a bit more about what you are trying to do would help me.

Yep, working on building/improving CoreCLR support into an open-source profiler that can handle both native + managed profile data. The core profiling works, but I'm working to add GC and other data on non-Windows and so am switching to eventpipe; I wanted to move everything to eventpipe instead of relying on jitdump/perfmap data so that I could support attach-to-process.

brianrob commented 1 week ago

You could look for the MethodDCEnd and MethodDCEndVerbose events on the rundown provider using the Yep, working on building/improving CoreCLR support into an open-source profiler that can handle both native + managed profile data. The core profiling works, but I'm working to add GC and other data on non-Windows and so am switching to eventpipe; I wanted to move everything to eventpipe instead of relying on jitdump/perfmap data so that I could support attach-to-process.

Gotcha, thanks. Hopefully those rundown events will do what you want. These are a historic artifact from before NGEN on .NET Framework could generate PDBs, and so they should act just like their JIT counterparts, assuming that they function properly for R2R code.

davmason commented 1 week ago

I thought we had issues with R2R not giving the right rundown events and that's why we had the crossgen tool emit perfmap files in perfcollect. Is that issue solved now?

vvuk commented 1 week ago

You could look for the MethodDCEnd and MethodDCEndVerbose events on the rundown provider using the NGenRundownKeyword

Interesting, testing this now and it seems to work. It's a bit awkward though -- these events don't get emitted until the end rundown, whereas profiling samples that contain addresses in the method regions would have happened before those events.

So in order to have the correct time range for when these method addresses are valid, I need to keep track of all module loads/unloads and their times, and then during the end rundown when I see a MethodDCEnd* event (... maybe only for methods with the R2R tier flag set?) add that method to my jit method map using the module load time. Doable, but if something happens and I don't get the end rundown (e.g. runtime crash) then all that data is lost.

There's already a NGEN keyword on the non-rundown provider; any reason to not generate MethodLoad events in the non-rundown provider for R2R methods if the NGEN keyword is enabled?

brianrob commented 1 week ago

I thought we had issues with R2R not giving the right rundown events and that's why we had the crossgen tool emit perfmap files in perfcollect. Is that issue solved now?

You could be right, but I don't remember this being an issue. The reason we don't usually use these events is because they are costly at trace time and we can capture the data from a PDB/equivalent cheaper after collection.

brianrob commented 1 week ago

You could look for the MethodDCEnd and MethodDCEndVerbose events on the rundown provider using the NGenRundownKeyword

Interesting, testing this now and it seems to work. It's a bit awkward though -- these events don't get emitted until the end rundown, whereas profiling samples that contain addresses in the method regions would have happened before those events.

So in order to have the correct time range for when these method addresses are valid, I need to keep track of all module loads/unloads and their times, and then during the end rundown when I see a MethodDCEnd* event (... maybe only for methods with the R2R tier flag set?) add that method to my jit method map using the module load time. Doable, but if something happens and I don't get the end rundown (e.g. runtime crash) then all that data is lost.

There's already a NGEN keyword on the non-rundown provider; any reason to not generate MethodLoad events in the non-rundown provider for R2R methods if the NGEN keyword is enabled?

You've got it. That's exactly how this is supposed to work. You can use the events from the public (non-rundown) provider, but they will only tell you what's occurring during the trace. This is fine if you start profiling before the process launches. If you start profiling after the process has started, you won't have complete state, and you'll need to do a rundown at the end to capture the full process state.

noahfalk commented 1 week ago

A couple alternatives if you find any of them more helpful @vvuk:

vvuk commented 1 week ago

You can always create a 2nd trace running concurrently and end it immediately to induce rundown to happen at that point in time

Ah interesting idea! Is there any reason that the rundown trace provider doesn't support a start rundown for all this vs. only end rundown? But this second trace approach would miss the case of a module being loaded during the trace that contains R2R code; still seems odd that that scenario is still only covered by an end rundown.

GetFunctionFromIP is definitely too heavyweight, yeah.

Thanks all for your help -- it sounds like my best option is to for now use the end rundown data. This can probably get closed unless there are any enhancements that people would like to see; I'd be happy to take a stab at anything that gets closer to "just see R2R methods as part of normal trace stream" :)

brianrob commented 1 week ago
  • @brianrob - does PerfView track module loads/unloads or does it just blindly assume that any IP in a callstack that matches an IP enumerated at rundown is a match? Certainly its theoretically possible for module unload/load to recycle an IP but maybe this just doesn't happen in practice often enough for profilers to care about it?

PerfView and TraceEvent will both capture module loads/unloads and code loads/unloads along with timestamps to ensure that we resolve the right symbol at the right time in the trace.

noahfalk commented 1 week ago

But this second trace approach would miss the case of a module being loaded during the trace that contains R2R code; still seems odd that that scenario is still only covered by an end rundown.

I suspect the lack of those events was because the original NGEN format was optimized such that once the image was loaded, calls from A() to B() within the image can be a direct call assembly instruction from A to B. Without some kind of per-method fixup or loading occuring there wasn't a good place to insert an event callback indicating B is about to run for the first time. Enumerating every method in the module at module load time would have been possible, but probably not done because of the overhead. Its also possible folks didn't pursue it because they found it easy enough to treat NGEN images like native images and resolve the IPs using PDBs.

I don't believe the new R2R format allows methods to run without first having a per-method loading step occur so now it presumably is possible to emit those events. If you felt motivated to look into further I'm certainly open to it, but I can't promise I'd have time to review anything or answer design questions until after .NET 9 feature complete deadline had already passed. Not trying to dissuade you, just wanted you to be fully warned :)

brianrob commented 1 week ago

But this second trace approach would miss the case of a module being loaded during the trace that contains R2R code; still seems odd that that scenario is still only covered by an end rundown.

I suspect the lack of those events was because the original NGEN format was optimized such that once the image was loaded, calls from A() to B() within the image can be a direct call assembly instruction from A to B. Without some kind of per-method fixup or loading occuring there wasn't a good place to insert an event callback indicating B is about to run for the first time. Enumerating every method in the module at module load time would have been possible, but probably not done because of the overhead. Its also possible folks didn't pursue it because they found it easy enough to treat NGEN images like native images and resolve the IPs using PDBs.

I don't believe the new R2R format allows methods to run without first having a per-method loading step occur so now it presumably is possible to emit those events. If you felt motivated to look into further I'm certainly open to it, but I can't promise I'd have time to review anything or answer design questions until after .NET 9 feature complete deadline had already passed. Not trying to dissuade you, just wanted you to be fully warned :)

Agree with @noahfalk here - this is likely an artifact of the original NGEN format. NGEN rundown was really only used prior to .NET Framework v4. .NET Framework v4 contained the ability to generate a PDB directly, and so we've just considered it to be native code since then.

It is possible to enumerate all of the R2R methods in a module and determine which have been called, so you then just dump the data for those. Those methods that were fixed up are said to have been "restored" and there is a method to check this.