Make Line numbers work for crossgened DLLs when profiling with EventPipe

[vancem]

Useing the 2.1 version of .NET Core, you profile a simple app .NET Core App o (e.g. a spin loop like)

            var start = DateTime.Now;
            while ((DateTime.Now - start).TotalSeconds < 5)
                {}

Using EventPipe (e.g. set COMPlus_EnableEventPipe=1 and run the app) and then open the resulting *.netperf file, you will find that PerfView's 'Goto Source' feature works in the main program, attributing the cost to the correct source line.

However if you open up frames that are inside the framework (e.g. System.TimeZoneInfo.GetLocalTimeZoneFromTzFile) you will find that while PerfView can open the source code (it can correctly find the PDBS for System.Private.Corelib.pdb and the source files on Github), but it will attribute all the cost the the first line in the method.

This is because PerfView lacks the Native->IL mapping needed to map to a particular IL instruction (which in turn can be mapped to a particular line). These normally given to perfView by the ILToNativeMap events in the runtime. (Normally PerfView hides these events when you look at a trace but if you pass PerfView the /keepAllEvents when the trace is converted you can see them).

What you will find is that the mappings exist for all JIT compiled methods (at the time of JIT as well as during rundown), but there are no ILToNativeMap rundown events for DLLs that have been precompiled with Crossgen (which is most of the framework).

We do force the rundown of all methods (DCStopVerbose), that are precompiled (that is how we know the method), but we do currently do this for the ILToNativeMap.

Thus the most straightforward solution is to simply log the ILToNativeMap during this rundown as well.

This will be alot of data, and it may not be needed for simple investigations, but I think it is best to do the simple thing (always include it), and we can talk about having options for turning it off for advanced scenarios that care about file size.

@brianrob

[brianrob]

I've done some investigation on what it will take to add the ILToNativeMap for pre-compiled methods. Overall, it does not look difficult, but I have a couple of questions. @noahfalk can you help me answer these, or point me to the right person?

1. SendMethodILToNativeMapEvent uses the debugger interface to get the map via https://github.com/dotnet/coreclr/blob/master/src/vm/eventtrace.cpp#L6757. Will g_pDebugInterface->GetILToNativeMappingIntoArrays handle the hot and cold sections of a pre-compiled method? I know in the ETW case it doesn't need to, but I'm not sure if the debugger does need this.
2. Does the rejitID matter? For rundown events we specify 0 for the rejitID, but just want to make sure.
3. Does tiering affect the validity of this data for pre-compiled methods?
4. [Slightly less related] Is tiering already covered for the JIT case?

[noahfalk]

1. Yeah, that should work, but you probably want to make sure the right behavior is happening end to end. As I recall the offsets given in the map are encoded as if the hot and cold sections were contiguous in memory. This means the trace reader might need to compute:

offset = ip_somewhere_in_cold_code - cold_code_start + hot_code_size

before it can use the data in the map that corresponds to the cold offsets.

2. Yes we should make ReJITID be correct, but for precompiled code 0 is the correct value. Just curious, if the precompiled code isn't eligible to be used (lets says someone specified COMPlus_ReadyToRun=0) are the events going to skipped entirely?

3. Nope.

4. Yes it is. All jitting, whether or not for tiering, is funneled through JitCompileCode
   https://github.com/dotnet/coreclr/blob/master/src/vm/prestub.cpp#L555

From there, assuming ETW events are enabled it will reach the callstack:

ETW::MethodLog::SendMethodILToNativeMapEvent
ETW::MethodLog::MethodJitted
MethodDesc::JitCompileCodeLockedEventWrapper
MethodDesc::JitCompileCode

[brianrob]

Thanks @noahfalk.

We can certainly disable these events if ReadyToRun is disabled. I'm not sure at what level we have this knowledge, but at a minimum, we can check the environment variable. I need to look further into this to see how we know that we're dealing with pre-compiled code to know for sure.

One follow-up question as well - I dug more into the current implementation of SendMethodILToNativeMapEvent and how it gets the ILToNativeMap. It does look like it will provide information for both hot and cold sections, though as you point out, we'll need to make sure that we validate end-to-end that we do the math correctly. One thing that I noticed is that when we emit the event today, we do the following:

        FireEtwMethodILToNativeMap(
            ullMethodIdentifier, 
            rejitID,
            0,          // Extent:  This event is only sent for JITted (not NGENd) methods, and
            //          currently there is only one extent (hot) for JITted methods.
            cMap,
            rguiILOffset,
            rguiNativeOffset,
            GetClrInstanceId());

Does g_pDebugInterface->GetILToNativeMappingIntoArrays provide a way to get at the data individually for the hot and cold sections? I haven't found one yet. I'm wondering if that's the right way to go here, or if the extent number matters, and we can just emit the whole map with extent == 0.

[noahfalk]

Does g_pDebugInterface->GetILToNativeMappingIntoArrays provide a way to get at the data individually for the hot and cold sections?

I don't think there is anything directly inside the arrays you get back. You could seperately use CodeRegionInfo to determine the extents and then split the array based on the native offset.

Does g_pDebugInterface->GetILToNativeMappingIntoArrays provide a way to get at the data individually for the hot and cold sections?

Have ETW parsers have already taken a dependency on some contract for that extent? (You and Vance probably know better than I on that) If we don't have a conflicting implementation already in place then it seems reasonable to define that the event will always have extent = 0 and include offsets for all code regions.

[tommcdon]

@noahfalk any objections if we move this to future?

[pharring]

@brianrob, @noahfalk This still appears to be the case in .NET 6.
I can't seem to "Goto Source (Def)" in PerfView for AOT-compiled framework assemblies. In the log below, I tried to "Goto Source (Def)" on system.private.corelib!System.Threading.Tasks.Task::ExecuteWithThreadLocal(System.Threading.Tasks.Task&, System.Threading.Thread) on a trace from a .NET 6 app.

Opened Pdb file C:\REDACTED\SymbolCache\System.Private.CoreLib.ni.pdb\30C6BACB883EDCDD65584917F360153E1\System.Private.CoreLib.ni.pdb
SourceLocationForRva: looking up RVA 27387e 
SourceLocationForRva: did not find line info Looking for mangled symbol name (for NGEN pdbs)
SourceLocationForRva: RVA lives in method with 4.6.1 mangled name System.Threading.Tasks.Task::ExecuteWithThreadLocal(System.Threading.Tasks.Task&, System.Threading.Thread)$##60032B5
SourceLocationForRva: Looking up IL Offset by RVA 0x27387e
SourceLocationForRva: Ran out of IL mappings, guessing 0x0
SourceLocationForRva: Found native to IL mappings, IL offset 0x0
GetSourceLine:  Found mapping from Native to IL assembly System.Private.CoreLib Token 0x60032b5 offset 0x0
GetSourceLine: Could not find managed module for NGEN image c:\program files (x86)\dotnet\shared\microsoft.netcore.app\6.0.3\system.private.corelib.dll
GetSourceLine: Warning could not find line information in C:\REDACTED\SymbolCache\System.Private.CoreLib.ni.pdb\30C6BACB883EDCDD65584917F360153E1\System.Private.CoreLib.ni.pdb
GetSourceLine: Maybe because the NGEN pdb was generated without being able to reach the IL PDB
GetSourceLine: If you are on the machine where the data was collected, deleting the file may help

Metric as a function of code address
      Address    :   Line     Metric
        71cd387e :      0       14.0
Source could not find a source location for the given Frame.

[noahfalk]

I think that is expected because the work to emit Native2IL mappings for R2R images at rundown didn't make any more progress after the discussion above back in 2018. @brianrob does that sound right?

@pharring are you looking to do a profiling scenario where this is going to matter? I assume this is largely a priorities issue and thus far nothing pushed the priority to be high.

[pharring]

Yes, @noahfalk, this is about lighting up "go to source" from ETW traces.

[brianrob]

Yes, @noahfalk I think that is right. I don't believe that R2R PDBs have Native2IL mappings at this point.