Runtime: System.Diagnostics.StackTrace slow on .NET Core

[martinmine]

Consider the following program:

using System;
using System.Diagnostics;

static void Main()
{
    var start = DateTime.Now;

    for (var i = 0; i < 5000; i++)
    {
        new StackTrace(0, true);
    }

    var timeSpent = DateTime.Now - start;
    Console.WriteLine($"Spent time: {timeSpent.TotalMilliseconds} ms");
    Console.ReadKey();
}

This takes 4133.3539 ms in .NET Core 2.0, while targeting .NET 4.7.1 this takes 108.1025 ms to execute. Making a full dump on this with procdump, I can see the following stack trace typically being called:

System.Private.CoreLib.dll!00007ffee4a6bfb9()   Unknown
[Managed to Native Transition]  
System.Private.CoreLib.dll!System.IO.FileStream.SeekCore(long offset, System.IO.SeekOrigin origin) Line 608 C#
System.Private.CoreLib.dll!System.IO.FileStream.Seek(long offset, System.IO.SeekOrigin origin) Line 542 C#
System.Reflection.Metadata.dll!System.Reflection.PortableExecutable.PEHeaders.PEHeaders(System.IO.Stream peStream, int size, bool isLoadedImage)    Unknown
System.Reflection.Metadata.dll!System.Reflection.PortableExecutable.PEReader.InitializePEHeaders()  Unknown
System.Reflection.Metadata.dll!System.Reflection.PortableExecutable.PEReader.ReadDebugDirectory()   Unknown
System.Reflection.Metadata.dll!System.Reflection.PortableExecutable.PEReader.TryOpenAssociatedPortablePdb(string peImagePath, System.Func<string, System.IO.Stream> pdbFileStreamProvider, out System.Reflection.Metadata.MetadataReaderProvider pdbReaderProvider, out string pdbPath) Unknown
System.Diagnostics.StackTrace.dll!System.Diagnostics.StackTraceSymbols.TryOpenReaderFromAssemblyFile(string assemblyPath, System.IntPtr loadedPeAddress, int loadedPeSize) Line 198 C#
System.Diagnostics.StackTrace.dll!System.Diagnostics.StackTraceSymbols.TryGetReader(string assemblyPath, System.IntPtr loadedPeAddress, int loadedPeSize, System.IntPtr inMemoryPdbAddress, int inMemoryPdbSize) Line 129   C#
System.Diagnostics.StackTrace.dll!System.Diagnostics.StackTraceSymbols.GetSourceLineInfo(string assemblyPath, System.IntPtr loadedPeAddress, int loadedPeSize, System.IntPtr inMemoryPdbAddress, int inMemoryPdbSize, int methodToken, int ilOffset, out string sourceFile, out int sourceLine, out int sourceColumn) Line 59   C#
System.Private.CoreLib.dll!System.Diagnostics.StackFrameHelper.InitializeSourceInfo(int iSkip, bool fNeedFileInfo, System.Exception exception) Line 140 C#
System.Private.CoreLib.dll!System.Diagnostics.StackTrace.CaptureStackTrace(int iSkip, bool fNeedFileInfo, System.Threading.Thread targetThread, System.Exception e) Line 426    C#
System.Private.CoreLib.dll!System.Diagnostics.StackTrace.StackTrace(int skipFrames, bool fNeedFileInfo) Line 307    C#

[RussKeldorph]

@dotnet/dotnet-diag @tommcdon

[0xd4d]

StackTrace.CaptureStackTrace() creates and disposes of StackFrameHelper which holds a reference to StackTraceSymbols in getSourceLineInfo.Target. StackTraceSymbols has a PDB cache that gets cleared when it gets disposed.

All of these classes get disposed when StackTrace.CaptureStackTrace() returns. The PDB files are read and then thrown away every single time the method gets called.

StackTraceSymbols.TryGetReader is also inefficient, it should not try to reopen the EXE/DLL again if it already tried and failed to find a PDB file.

[martinmine]

@0xd4d Not sure how this is handled in the .NET framework but I assume that they cache this somehow.

[0xd4d]

I haven't checked since it was so fast, so I assume .NET Framework uses a cache.

[noahfalk]

Strong suspicion you are seeing this issue https://github.com/Microsoft/dotnet/issues/529. A fix was made for desktop and it needs to be brought to CoreCLR.

[stephentoub]

Should this be considered for 2.1? Seems like a significant regression.

[noahfalk]

The performance now is the same behavior we shipped in CoreCLR RTM 2.0 (based on my memory of when the changes happened and @martinmine's report of the performance above). The regression is relative to desktop, and maybe relative to .Net Core 1.0. I do think it would be worth considering this for 2.1.

[mikem8361]

Fixed in PR https://github.com/dotnet/corefx/pull/29359 and PR https://github.com/dotnet/coreclr/pull/17804

[martinmine]

@noahfalk @mikem8361 In which version(s) of .NET Core will we be seeing this get patched in?

[mikem8361]

Currently version 2.2. @Petermarcu @leecow @tommcdon Does this meet the 2.1 bug bar?

[Petermarcu]

Worth having a discussion about risk/reward. Clearly writing down the E2E scenarios that are impacted by this so everyone understands the value in taking the fix late in 2.1 will help make or break the case for it.

[mikem8361]

The main E2E scenarios is the use of System.Diagnostics.StackTrace or System.Exception.StackTrace to log source/line number info is certain frameworks like SharpDX, GrandTheftAuto mod (520727), IKVM library used in Belgium, etc. on the desktop. More details in issue #529. These changes have been in 4.7.2 or 4.7.3 since the holidays. This is backporting the changes to .NET Core so we don’t run into similar problems.