Profiling x64 processes can’t resolve R2R symbols

[hoyosjs]

[ghost]

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

Issue Details

---

Author:	hoyosjs
Assignees:	-
Labels:	area-Diagnostics-coreclr
Milestone:	-

[AndyAyersMS]

Note this is not just x64. I see similar issues on arm64.

[davmason]

@AndyAyersMS I am having trouble reproducing this, can you share what you were doing when you saw the failures?

[AndyAyersMS]

Looking at the profile from System.Collections.Sort<Int32>.Array - one of the runtime micro benchmarks from dotnet/performance -- collected with --corerun and -p ETW

See #71214 (comment)

[hoyosjs]

I ran that same benchmark and can see events from r2r and non-r2r bodies. Oddly, I don't see the [Optimized...] and such annotations.

[AndyAyersMS]

Let me see if I can still repro.

I ran that same benchmark and can see events from r2r and non-r2r bodies. Oddly, I don't see the [Optimized...] and such annotations.

There is a tiering-annotated profile under the advanced group in perfview.

[AndyAyersMS]

This still repros for me, eg using the latest nightly build (on windows arm64) and the sort benchmark from #71214:

There is no way this benchmark is spending 86% of its time in PoolingAsyncValueTaskMethodBuilder.

Similar thing shows up in the normal profile view.

[hoyosjs]

Hmm I still see the r2r frames in that view for that benchmark:

Probably if you could share the log we could see if it found SPC's ni.pdb?

[hoyosjs]

And yes, in my profile I see:

[AndyAyersMS]

Sent it to you via email.

[AndyAyersMS]

If I'm parsing this right the PDB it finds seems awfully small

FindSymbolFilePath: Waiting for initial connection to \\redmond/symfiles\VSOSYMPRXY16\cache\8F\1D\FA0B71E98A2A2DFEBD2441816A4658952F3B12930736721726CAC37693EB00\system.private.corelib.ni.pdb.
CopyStreamToFile: Copying \\redmond\symfiles\VSOSYMPRXY16\cache\8F\1D\FA0B71E98A2A2DFEBD2441816A4658952F3B12930736721726CAC37693EB00\system.private.corelib.ni.pdb to C:\Users\andya\AppData\Local\Temp\SymbolCache\System.Private.CoreLib.ni.pdb\D571163A5E469B27E5E464F1C8D65FA31\System.Private.CoreLib.ni.pdb.new
.................................................................................................... 1.0 Meg
.................................................................................................... 2.0 Meg
.................................................................................................... 3.0 Meg
................................
CopyStreamToFile: Copy Done, moving to C:\Users\andya\AppData\Local\Temp\SymbolCache\System.Private.CoreLib.ni.pdb\D571163A5E469B27E5E464F1C8D65FA31\System.Private.CoreLib.ni.pdb

[hoyosjs]

A local build on a native x64 machine and the ni pdb's for 6.0.7 are all ~3mb. They don't contain much info - just symbol to native offset, but no line info. EDIT: meant to say this is expected - cvdump shows the functions with offsets and are roughtly the same size.

[davmason]

@mangod9 could you have someone look in to what Andy is reporting above? He is investigating a trace where the symbols for System.Private.CoreLib (which is R2R) are loaded, but methods are resolving incorrectly.

[mangod9]

Adding @AntonLapounov since he had investigated a similar issue earlier in 7.

[mangod9]

Do we know if this is a regression or we had similar behavior in 6 ?

[AndyAyersMS]

I'll try the same thing on 6.0

[AntonLapounov]

@AndyAyersMS Could you please share the exact repro steps?

[AndyAyersMS]

6.0 profile looks similar. It could be a broken benchmark perhaps.

@AndyAyersMS Could you please share the exact repro steps?

See #71214 (comment)

[AntonLapounov]

If it affects only few benchmarks and not a regression, we should remove the 'blocking-release' label.

[tommcdon]

If it affects only few benchmarks and not a regression, we should remove the 'blocking-release' label.

Agreed and removed

[AndyAyersMS]

Not sure how many benchmarks are affected. This one is perhaps unusual in that R2R code figures prominently during the "actual" intervals (which is not typical, we usually try and measure Tier1 code).

[AntonLapounov]

@AndyAyersMS Could you please share the exact repro steps?

See #71214 (comment)

That was not helpful. I can run benchmarks_ci.py -f net6.0 --filter "System.Collections.Sort<Int32>*", but it doesn't accept -p ETW.

[AndyAyersMS]

Sorry, here's something more specific:

• windows x64 or arm64
• install 6.0, 7.0 product
• clone dotnet/performance repo
• start admin shell
• cd to src/benchmarks/micro in the repo
• dotnet run -c Release -f net7.0 -- --filter "System.Collections.Sort<Int32>.Array" --runtimes net6.0 net7.0 -p ETW

The above will create two ETL files. Look at those with perfview.

• select cpu stacks (or cpu stacks with optmization tiers) view
• dotnet process.
• Ungroup.
• Search for "engineactual" and include BenchmarkDotNet.Engines.EngineActualStage.RunAuto.
• Sort by inclusive or exclusive.

[AntonLapounov]

Thank you, I have reproduced the issue with SDK 6.0.303. I see the same behavior in Windows Performance Analyzer, so the issue is not specific to PerfView. Both apps show [ReadyToRun]System.Array::Fill(System.Int32[], System.Int32) calling [ReadyToRun]System.Runtime.CompilerServices.PoolingAsyncValueTaskMethodBuilder`1+SyncSuccessSentinelStateMachineBox[System.Int32]::.ctor(), which is displayed calling itself recursively (and that is obviously incorrect). In reality, Array::Fill is a very short ReadyToRun function that delegates the work to System.SpanHelpers::Fill, which has no ReadyToRun version. Is there a way to dump raw stack offsets from the .etl file?

[AndyAyersMS]

Possibly? The data is there but you might need a custom parser and I think there is possibly some cleverness in how it's encoded. @brianrob would likely know but I think he's OOF (or soon to be)

You might try peeking at the perfview log, sometimes they spew interesting stuff there.

[AntonLapounov]

I think I identified the issue. Below is a snippet from cvdump output for System.Private.CoreLib.ni.pdb (SDK 6.0.303) sorted by the function offset. Note the large gap in the middle (42D060..42EF00):

S_PUB32: [0001:0042D040], Flags: 00000002, System.Int16 System.Runtime.CompilerServices.PoolingAsyncValueTaskMethodBuilder`1+StateMachineBox[System.Int32]::get_Version()$##600508A
S_PUB32: [0001:0042D050], Flags: 00000002, System.Runtime.CompilerServices.PoolingAsyncValueTaskMethodBuilder`1+StateMachineBox[System.Int32]::.ctor()$##600508D
S_PUB32: [0001:0042D060], Flags: 00000002, System.Runtime.CompilerServices.PoolingAsyncValueTaskMethodBuilder`1+SyncSuccessSentinelStateMachineBox[System.Int32]::.ctor()$##600508E
S_PUB32: [0001:0042EF00], Flags: 00000002, System.Int32 System.Collections.Generic.NullableEqualityComparer`1[System.Int32]::IndexOf(System.Nullable`1[System.Int32][], System.Nullable`1[System.Int32], System.Int32, System.Int32)$##6006C84
S_PUB32: [0001:0042F030], Flags: 00000002, System.Int32 System.Collections.Generic.NullableEqualityComparer`1[System.Int32]::LastIndexOf(System.Nullable`1[System.Int32][], System.Nullable`1[System.Int32], System.Int32, System.Int32)$##6006C85
S_PUB32: [0001:0042F0C0], Flags: 00000002, System.Boolean System.Collections.Generic.NullableEqualityComparer`1[System.Int32]::Equals(System.Nullable`1[System.Int32], System.Nullable`1[System.Int32])$##6006C86

According to R2RDump, that gap actually contains GenericArraySortHelper`1<int> ReadyToRun methods, which are missing from the System.Private.CoreLib.ni.pdb file. That is why those methods are incorrectly displayed with the name of the last method before the gap in PerfView and WPA. Similary, the gap after Array::Fill

S_PUB32: [0001:004EF6E0], Flags: 00000002, System.Array::Fill(System.Int32[], System.Int32)$##60001B6
S_PUB32: [0001:004EF990], Flags: 00000002, System.Array::Sort(System.Int32[], System.Comparison`1[System.Int32])$##60001E2

contains one of Array::Sort overloads, which is incorrectly displayed as Array::Fill.

There are 28,822 ReadyToRun methods in System.Private.CoreLib.dll, but only 21,978 S_PUB32 entries in the corresponding .ni.pdb file (~76%). We could have a sanity check verifying that these numbers are either equal or close enough.

[AndyAyersMS]

Thanks @AntonLapounov -- sounds like real progress. Hopefully not too hard to fix.