Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

X64 - Too many methods JITted on startup for blank console application #85791

Open
2 of 6 tasks
TIHan opened this issue May 4, 2023 · 29 comments
Open
2 of 6 tasks

X64 - Too many methods JITted on startup for blank console application #85791

TIHan opened this issue May 4, 2023 · 29 comments

Comments

@TIHan
Copy link
Contributor

TIHan commented May 4, 2023

Using this example:

namespace HelloWorldStartup
{
    internal class Program
    {
        static void Main(string[] args)
        {
        }
    }
}

The CPU I used was an AMD 7950X.
X64 - With DOTNET_JitDisasmSummary=1 it shows this number of methods (this is with R2R):

   1: JIT compiled System.Runtime.CompilerServices.CastHelpers:StelemRef(System.Array,long,System.Object) [Tier1, IL size=88, code size=93]
   2: JIT compiled System.Runtime.CompilerServices.CastHelpers:LdelemaRef(System.Array,long,ulong) [Tier1, IL size=44, code size=44]
   3: JIT compiled System.SpanHelpers:IndexOfNullCharacter(ulong) [Tier1, IL size=805, code size=391]
   4: JIT compiled System.Guid:TryFormatCore[ushort](System.Span`1[ushort],byref,int) [Tier0, IL size=894, code size=892]
   5: JIT compiled System.Number:UInt32ToDecChars[ushort](ulong,uint) [Tier0, IL size=114, code size=253]
   6: JIT compiled System.ArgumentOutOfRangeException:ThrowIfNegative[int](int,System.String) [Tier0, IL size=22, code size=50]
   7: JIT compiled System.Text.Unicode.Utf16Utility:GetPointerToFirstInvalidChar(ulong,int,byref,byref) [Tier0, IL size=994, code size=1101]
   8: JIT compiled System.Text.Ascii:NarrowUtf16ToAscii(ulong,ulong,ulong) [Tier0, IL size=491, code size=594]
   9: JIT compiled System.SpanHelpers:IndexOfNullByte(ulong) [Tier1, IL size=844, code size=459]
  10: JIT compiled System.PackedSpanHelpers:IndexOf[System.SpanHelpers+DontNegate`1[short]](byref,short,int) [Tier0, IL size=698, code size=1631]
  11: JIT compiled System.PackedSpanHelpers:PackSources(System.Runtime.Intrinsics.Vector256`1[short],System.Runtime.Intrinsics.Vector256`1[short]) [Tier0, IL size=13, code size=52]
  12: JIT compiled System.PackedSpanHelpers:ComputeFirstIndexOverlapped(byref,byref,byref,System.Runtime.Intrinsics.Vector256`1[ubyte]) [Tier0, IL size=52, code size=124]
  13: JIT compiled System.PackedSpanHelpers:FixUpPackedVector256Result(System.Runtime.Intrinsics.Vector256`1[ubyte]) [Tier0, IL size=22, code size=42]
  14: JIT compiled System.SpanHelpers:LastIndexOfValueType[short,System.SpanHelpers+DontNegate`1[short]](byref,short,int) [Tier1, IL size=963, code size=419]
  15: JIT compiled System.Text.Ascii:WidenAsciiToUtf16(ulong,ulong,ulong) [Tier0, IL size=604, code size=1425]
  16: JIT compiled (dynamicClass):InvokeStub_EventAttribute.set_Level(System.Object,System.Object,ulong) [FullOpts, IL size=25, code size=27]
  17: JIT compiled (dynamicClass):InvokeStub_EventAttribute.set_Message(System.Object,System.Object,ulong) [FullOpts, IL size=25, code size=28]
  18: JIT compiled (dynamicClass):InvokeStub_EventAttribute.set_Task(System.Object,System.Object,ulong) [FullOpts, IL size=25, code size=27]
  19: JIT compiled (dynamicClass):InvokeStub_EventAttribute.set_Opcode(System.Object,System.Object,ulong) [FullOpts, IL size=25, code size=27]
  20: JIT compiled (dynamicClass):InvokeStub_EventAttribute.set_Version(System.Object,System.Object,ulong) [FullOpts, IL size=25, code size=28]
  21: JIT compiled (dynamicClass):InvokeStub_EventAttribute.set_Keywords(System.Object,System.Object,ulong) [FullOpts, IL size=25, code size=28]
  22: JIT compiled System.Number:Int64ToHexChars[ushort](ulong,ulong,int,int) [Tier0, IL size=67, code size=252]
  23: JIT compiled System.SpanHelpers:IndexOfAnyInRangeUnsignedNumber[ushort,System.SpanHelpers+DontNegate`1[ushort]](byref,ushort,ushort,int) [Tier0, IL size=142, code size=190]
  24: JIT compiled System.PackedSpanHelpers:IndexOfAnyInRange[System.SpanHelpers+DontNegate`1[short]](byref,short,short,int) [Tier0, IL size=659, code size=1600]
  25: JIT compiled System.SpanHelpers:SequenceCompareTo(byref,int,byref,int) [Tier1, IL size=568, code size=329]
  26: JIT compiled HelloWorldStartup.Program:Main(System.String[]) [Tier0, IL size=1, code size=10]

ARM64:

   1: JIT compiled System.Runtime.CompilerServices.CastHelpers:StelemRef(System.Array,long,System.Object) [Tier1, IL size=88, code size=144]
   2: JIT compiled System.Runtime.CompilerServices.CastHelpers:LdelemaRef(System.Array,long,ulong) [Tier1, IL size=44, code size=88]
   3: JIT compiled System.SpanHelpers:IndexOfNullCharacter(ulong) [Tier1, IL size=492, code size=392]
   4: JIT compiled HelloWorldStartup.Program:Main(System.String[]) [Tier0, IL size=1, code size=20]

Problems identified:

@TIHan TIHan added the runtime-coreclr specific to the CoreCLR runtime label May 4, 2023
@dotnet-issue-labeler dotnet-issue-labeler bot added the area-CodeGen-coreclr CLR JIT compiler in src/coreclr/src/jit and related components such as SuperPMI label May 4, 2023
@ghost ghost added the untriaged New issue has not been triaged by the area owner label May 4, 2023
@ghost
Copy link

ghost commented May 4, 2023

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

Issue Details

Using this example:

namespace HelloWorldStartup
{
    internal class Program
    {
        static void Main(string[] args)
        {
        }
    }
}

X64 - With DOTNET_JitDisasmSummary=1 it shows this number of methods (this is with R2R):

   1: JIT compiled System.Runtime.CompilerServices.CastHelpers:StelemRef(System.Array,long,System.Object) [Tier1, IL size=88, code size=93]
   2: JIT compiled System.Runtime.CompilerServices.CastHelpers:LdelemaRef(System.Array,long,ulong) [Tier1, IL size=44, code size=44]
   3: JIT compiled System.SpanHelpers:IndexOfNullCharacter(ulong) [Tier1, IL size=805, code size=391]
   4: JIT compiled System.Guid:TryFormatCore[ushort](System.Span`1[ushort],byref,int) [Tier0, IL size=894, code size=892]
   5: JIT compiled System.Number:UInt32ToDecChars[ushort](ulong,uint) [Tier0, IL size=114, code size=253]
   6: JIT compiled System.ArgumentOutOfRangeException:ThrowIfNegative[int](int,System.String) [Tier0, IL size=22, code size=50]
   7: JIT compiled System.Text.Unicode.Utf16Utility:GetPointerToFirstInvalidChar(ulong,int,byref,byref) [Tier0, IL size=994, code size=1101]
   8: JIT compiled System.Text.Ascii:NarrowUtf16ToAscii(ulong,ulong,ulong) [Tier0, IL size=491, code size=594]
   9: JIT compiled System.SpanHelpers:IndexOfNullByte(ulong) [Tier1, IL size=844, code size=459]
  10: JIT compiled System.PackedSpanHelpers:IndexOf[System.SpanHelpers+DontNegate`1[short]](byref,short,int) [Tier0, IL size=698, code size=1631]
  11: JIT compiled System.PackedSpanHelpers:PackSources(System.Runtime.Intrinsics.Vector256`1[short],System.Runtime.Intrinsics.Vector256`1[short]) [Tier0, IL size=13, code size=52]
  12: JIT compiled System.PackedSpanHelpers:ComputeFirstIndexOverlapped(byref,byref,byref,System.Runtime.Intrinsics.Vector256`1[ubyte]) [Tier0, IL size=52, code size=124]
  13: JIT compiled System.PackedSpanHelpers:FixUpPackedVector256Result(System.Runtime.Intrinsics.Vector256`1[ubyte]) [Tier0, IL size=22, code size=42]
  14: JIT compiled System.SpanHelpers:LastIndexOfValueType[short,System.SpanHelpers+DontNegate`1[short]](byref,short,int) [Tier1, IL size=963, code size=419]
  15: JIT compiled System.Text.Ascii:WidenAsciiToUtf16(ulong,ulong,ulong) [Tier0, IL size=604, code size=1425]
  16: JIT compiled (dynamicClass):InvokeStub_EventAttribute.set_Level(System.Object,System.Object,ulong) [FullOpts, IL size=25, code size=27]
  17: JIT compiled (dynamicClass):InvokeStub_EventAttribute.set_Message(System.Object,System.Object,ulong) [FullOpts, IL size=25, code size=28]
  18: JIT compiled (dynamicClass):InvokeStub_EventAttribute.set_Task(System.Object,System.Object,ulong) [FullOpts, IL size=25, code size=27]
  19: JIT compiled (dynamicClass):InvokeStub_EventAttribute.set_Opcode(System.Object,System.Object,ulong) [FullOpts, IL size=25, code size=27]
  20: JIT compiled (dynamicClass):InvokeStub_EventAttribute.set_Version(System.Object,System.Object,ulong) [FullOpts, IL size=25, code size=28]
  21: JIT compiled (dynamicClass):InvokeStub_EventAttribute.set_Keywords(System.Object,System.Object,ulong) [FullOpts, IL size=25, code size=28]
  22: JIT compiled System.Number:Int64ToHexChars[ushort](ulong,ulong,int,int) [Tier0, IL size=67, code size=252]
  23: JIT compiled System.SpanHelpers:IndexOfAnyInRangeUnsignedNumber[ushort,System.SpanHelpers+DontNegate`1[ushort]](byref,ushort,ushort,int) [Tier0, IL size=142, code size=190]
  24: JIT compiled System.PackedSpanHelpers:IndexOfAnyInRange[System.SpanHelpers+DontNegate`1[short]](byref,short,short,int) [Tier0, IL size=659, code size=1600]
  25: JIT compiled System.SpanHelpers:SequenceCompareTo(byref,int,byref,int) [Tier1, IL size=568, code size=329]
  26: JIT compiled HelloWorldStartup.Program:Main(System.String[]) [Tier0, IL size=1, code size=10]

ARM64:

   1: JIT compiled System.Runtime.CompilerServices.CastHelpers:StelemRef(System.Array,long,System.Object) [Tier1, IL size=88, code size=144]
   2: JIT compiled System.Runtime.CompilerServices.CastHelpers:LdelemaRef(System.Array,long,ulong) [Tier1, IL size=44, code size=88]
   3: JIT compiled System.SpanHelpers:IndexOfNullCharacter(ulong) [Tier1, IL size=492, code size=392]
   4: JIT compiled HelloWorldStartup.Program:Main(System.String[]) [Tier0, IL size=1, code size=20]
Author: TIHan
Assignees: -
Labels:

area-CodeGen-coreclr, runtime-coreclr

Milestone: -

@TIHan TIHan changed the title [JIT] X64 - Too many methods JITted on startup for blank console application [Runtime] X64 - Too many methods JITted on startup for blank console application May 4, 2023
@TIHan TIHan added area-System.Runtime and removed area-CodeGen-coreclr CLR JIT compiler in src/coreclr/src/jit and related components such as SuperPMI runtime-coreclr specific to the CoreCLR runtime labels May 4, 2023
@ghost
Copy link

ghost commented May 4, 2023

Tagging subscribers to this area: @dotnet/area-system-runtime
See info in area-owners.md if you want to be subscribed.

Issue Details

Using this example:

namespace HelloWorldStartup
{
    internal class Program
    {
        static void Main(string[] args)
        {
        }
    }
}

X64 - With DOTNET_JitDisasmSummary=1 it shows this number of methods (this is with R2R):

   1: JIT compiled System.Runtime.CompilerServices.CastHelpers:StelemRef(System.Array,long,System.Object) [Tier1, IL size=88, code size=93]
   2: JIT compiled System.Runtime.CompilerServices.CastHelpers:LdelemaRef(System.Array,long,ulong) [Tier1, IL size=44, code size=44]
   3: JIT compiled System.SpanHelpers:IndexOfNullCharacter(ulong) [Tier1, IL size=805, code size=391]
   4: JIT compiled System.Guid:TryFormatCore[ushort](System.Span`1[ushort],byref,int) [Tier0, IL size=894, code size=892]
   5: JIT compiled System.Number:UInt32ToDecChars[ushort](ulong,uint) [Tier0, IL size=114, code size=253]
   6: JIT compiled System.ArgumentOutOfRangeException:ThrowIfNegative[int](int,System.String) [Tier0, IL size=22, code size=50]
   7: JIT compiled System.Text.Unicode.Utf16Utility:GetPointerToFirstInvalidChar(ulong,int,byref,byref) [Tier0, IL size=994, code size=1101]
   8: JIT compiled System.Text.Ascii:NarrowUtf16ToAscii(ulong,ulong,ulong) [Tier0, IL size=491, code size=594]
   9: JIT compiled System.SpanHelpers:IndexOfNullByte(ulong) [Tier1, IL size=844, code size=459]
  10: JIT compiled System.PackedSpanHelpers:IndexOf[System.SpanHelpers+DontNegate`1[short]](byref,short,int) [Tier0, IL size=698, code size=1631]
  11: JIT compiled System.PackedSpanHelpers:PackSources(System.Runtime.Intrinsics.Vector256`1[short],System.Runtime.Intrinsics.Vector256`1[short]) [Tier0, IL size=13, code size=52]
  12: JIT compiled System.PackedSpanHelpers:ComputeFirstIndexOverlapped(byref,byref,byref,System.Runtime.Intrinsics.Vector256`1[ubyte]) [Tier0, IL size=52, code size=124]
  13: JIT compiled System.PackedSpanHelpers:FixUpPackedVector256Result(System.Runtime.Intrinsics.Vector256`1[ubyte]) [Tier0, IL size=22, code size=42]
  14: JIT compiled System.SpanHelpers:LastIndexOfValueType[short,System.SpanHelpers+DontNegate`1[short]](byref,short,int) [Tier1, IL size=963, code size=419]
  15: JIT compiled System.Text.Ascii:WidenAsciiToUtf16(ulong,ulong,ulong) [Tier0, IL size=604, code size=1425]
  16: JIT compiled (dynamicClass):InvokeStub_EventAttribute.set_Level(System.Object,System.Object,ulong) [FullOpts, IL size=25, code size=27]
  17: JIT compiled (dynamicClass):InvokeStub_EventAttribute.set_Message(System.Object,System.Object,ulong) [FullOpts, IL size=25, code size=28]
  18: JIT compiled (dynamicClass):InvokeStub_EventAttribute.set_Task(System.Object,System.Object,ulong) [FullOpts, IL size=25, code size=27]
  19: JIT compiled (dynamicClass):InvokeStub_EventAttribute.set_Opcode(System.Object,System.Object,ulong) [FullOpts, IL size=25, code size=27]
  20: JIT compiled (dynamicClass):InvokeStub_EventAttribute.set_Version(System.Object,System.Object,ulong) [FullOpts, IL size=25, code size=28]
  21: JIT compiled (dynamicClass):InvokeStub_EventAttribute.set_Keywords(System.Object,System.Object,ulong) [FullOpts, IL size=25, code size=28]
  22: JIT compiled System.Number:Int64ToHexChars[ushort](ulong,ulong,int,int) [Tier0, IL size=67, code size=252]
  23: JIT compiled System.SpanHelpers:IndexOfAnyInRangeUnsignedNumber[ushort,System.SpanHelpers+DontNegate`1[ushort]](byref,ushort,ushort,int) [Tier0, IL size=142, code size=190]
  24: JIT compiled System.PackedSpanHelpers:IndexOfAnyInRange[System.SpanHelpers+DontNegate`1[short]](byref,short,short,int) [Tier0, IL size=659, code size=1600]
  25: JIT compiled System.SpanHelpers:SequenceCompareTo(byref,int,byref,int) [Tier1, IL size=568, code size=329]
  26: JIT compiled HelloWorldStartup.Program:Main(System.String[]) [Tier0, IL size=1, code size=10]

ARM64:

   1: JIT compiled System.Runtime.CompilerServices.CastHelpers:StelemRef(System.Array,long,System.Object) [Tier1, IL size=88, code size=144]
   2: JIT compiled System.Runtime.CompilerServices.CastHelpers:LdelemaRef(System.Array,long,ulong) [Tier1, IL size=44, code size=88]
   3: JIT compiled System.SpanHelpers:IndexOfNullCharacter(ulong) [Tier1, IL size=492, code size=392]
   4: JIT compiled HelloWorldStartup.Program:Main(System.String[]) [Tier0, IL size=1, code size=20]
Author: TIHan
Assignees: -
Labels:

area-System.Runtime, untriaged, runtime-coreclr

Milestone: -

@TIHan TIHan changed the title [Runtime] X64 - Too many methods JITted on startup for blank console application X64 - Too many methods JITted on startup for blank console application May 4, 2023
@EgorBo
Copy link
Member

EgorBo commented May 4, 2023

@MihaZupan can it be caused by SearchValue preinitializations + AVX2?

@TIHan
Copy link
Contributor Author

TIHan commented May 4, 2023

// cc @stephentoub @tannergooding

@stephentoub
Copy link
Member

Seems like R2R gives up on methods parameterized with static abstract interfaces? Methods like UInt32ToDecChars, ThrowIfNegative, and Int64ToHexChars aren't doing anything with AVX2.

@stephentoub
Copy link
Member

I'm curious what's triggering these:

  16: JIT compiled (dynamicClass):InvokeStub_EventAttribute.set_Level(System.Object,System.Object,ulong) [FullOpts, IL size=25, code size=27]
  17: JIT compiled (dynamicClass):InvokeStub_EventAttribute.set_Message(System.Object,System.Object,ulong) [FullOpts, IL size=25, code size=28]
  18: JIT compiled (dynamicClass):InvokeStub_EventAttribute.set_Task(System.Object,System.Object,ulong) [FullOpts, IL size=25, code size=27]
  19: JIT compiled (dynamicClass):InvokeStub_EventAttribute.set_Opcode(System.Object,System.Object,ulong) [FullOpts, IL size=25, code size=27]
  20: JIT compiled (dynamicClass):InvokeStub_EventAttribute.set_Version(System.Object,System.Object,ulong) [FullOpts, IL size=25, code size=28]
  21: JIT compiled (dynamicClass):InvokeStub_EventAttribute.set_Keywords(System.Object,System.Object,ulong) [FullOpts, IL size=25, code size=28]

?

@jkotas
Copy link
Member

jkotas commented May 5, 2023

I'm curious what's triggering these:

Extensive use of reflection in EventSource

@stephentoub
Copy link
Member

stephentoub commented May 5, 2023

I'm curious what's triggering these:

Extensive use of reflection in EventSource

But nothing is registering with EventSource here. Is this all part of manifest generation that happens regardless of whether there are any listeners and that would go away if we finished the source generator?

Also, why would those not show up on ARM64... was that also on a different OS and that's impacting what EventSource is doing?

@jkotas
Copy link
Member

jkotas commented May 5, 2023

There is always some random ETW session active on my dev machine that turns .NET event tracing on. My guess is that the ARM64 machine that this was measured on was plain vanilla machine without Office, VS, InTune, ... that all tend to create global event tracing sessions in the background. Event tracing is often turned on in the cloud workloads as well. Running with event tracing on may be a lot more common in real world than one would expect.

These should go away if we were to build the source generator for EventSource.

@stephentoub
Copy link
Member

Running with event tracing on may be a lot more common in real world than one would expect.

That's concerning, both in terms of startup and in terms of what overheads we might be paying throughout executiion.

@EgorBo
Copy link
Member

EgorBo commented May 5, 2023

Please note that this is an empty app. Add Console.WriteLine("Hello world"); and the number of jitted methods grows to 121 on my machines

@EgorBo
Copy link
Member

EgorBo commented May 5, 2023

JIT compiled System.Guid:TryFormatCore[ushort]

Interesting, I see

System.Guid.TryFormatCore<byte>
System.Guid.TryFormatCore<char>

in R2R but no ushort 🤔

@stephentoub
Copy link
Member

but no ushort

It's never used with ushort, only byte and char.

@EgorBo
Copy link
Member

EgorBo commented May 5, 2023

Info: Method `[S.P.CoreLib]System.Number.UInt32ToDecChars<uint16>(uint16*,uint32)` 
was not compiled because `SVM` requires runtime JIT

(related issue: #84421)

@EgorBo
Copy link
Member

EgorBo commented May 5, 2023

but no ushort

It's never used with ushort, only byte and char.

🤷 trying to find out who is instanciating that

@EgorBo
Copy link
Member

EgorBo commented May 5, 2023

#85819 removed a couple of methods and now I see 19 for empty app:

   1: JIT compiled System.Runtime.CompilerServices.CastHelpers:StelemRef(System.Array,long,System.Object) [Tier1, IL size=88, code size=93]
   2: JIT compiled System.Runtime.CompilerServices.CastHelpers:LdelemaRef(System.Array,long,ulong) [Tier1, IL size=44, code size=44]
   3: JIT compiled System.Guid:TryFormatCore[ushort](System.Span`1[ushort],byref,int) [Tier0, IL size=894, code size=892]
   4: JIT compiled System.Number:UInt32ToDecChars[ushort](ulong,uint) [Tier0, IL size=114, code size=253]
   5: JIT compiled System.ArgumentOutOfRangeException:ThrowIfNegative[int](int,System.String) [Tier0, IL size=22, code size=50]
   6: JIT compiled System.PackedSpanHelpers:IndexOf[System.SpanHelpers+DontNegate`1[short]](byref,short,int) [Tier0, IL size=698, code size=1631]
   7: JIT compiled System.PackedSpanHelpers:PackSources(System.Runtime.Intrinsics.Vector256`1[short],System.Runtime.Intrinsics.Vector256`1[short]) [Tier0, IL size=13, code size=52]
   8: JIT compiled System.PackedSpanHelpers:ComputeFirstIndexOverlapped(byref,byref,byref,System.Runtime.Intrinsics.Vector256`1[ubyte]) [Tier0, IL size=52, code size=124]
   9: JIT compiled System.PackedSpanHelpers:FixUpPackedVector256Result(System.Runtime.Intrinsics.Vector256`1[ubyte]) [Tier0, IL size=22, code size=42]
  10: JIT compiled System.SpanHelpers:LastIndexOfValueType[short,System.SpanHelpers+DontNegate`1[short]](byref,short,int) [Tier1, IL size=963, code size=419]
  11: JIT compiled (dynamicClass):InvokeStub_EventAttribute.set_Level(System.Object,System.Object,ulong) [FullOpts, IL size=25, code size=27]
  12: JIT compiled (dynamicClass):InvokeStub_EventAttribute.set_Message(System.Object,System.Object,ulong) [FullOpts, IL size=25, code size=28]
  13: JIT compiled (dynamicClass):InvokeStub_EventAttribute.set_Task(System.Object,System.Object,ulong) [FullOpts, IL size=25, code size=27]
  14: JIT compiled (dynamicClass):InvokeStub_EventAttribute.set_Opcode(System.Object,System.Object,ulong) [FullOpts, IL size=25, code size=27]
  15: JIT compiled (dynamicClass):InvokeStub_EventAttribute.set_Version(System.Object,System.Object,ulong) [FullOpts, IL size=25, code size=28]
  16: JIT compiled (dynamicClass):InvokeStub_EventAttribute.set_Keywords(System.Object,System.Object,ulong) [FullOpts, IL size=25, code size=28]
  17: JIT compiled System.Number:Int64ToHexChars[ushort](ulong,ulong,int,int) [Tier0, IL size=67, code size=252]
  18: JIT compiled System.SpanHelpers:IndexOfAnyInRangeUnsignedNumber[ushort,System.SpanHelpers+DontNegate`1[ushort]](byref,ushort,ushort,int) [Tier0, IL size=142, code size=190]
  19: JIT compiled System.PackedSpanHelpers:IndexOfAnyInRange[System.SpanHelpers+DontNegate`1[short]](byref,short,short,int) [Tier0, IL size=659, code size=1600]

Found more cases with SVM (crossgen being not able to prejit static virtual methods) cc @trylek

@jkotas
Copy link
Member

jkotas commented May 5, 2023

Add Console.WriteLine("Hello world"); and the number of jitted methods grows to 121 on my machines

Do you have System.Console R2R compiled? It only goes up to 30 on my machine and the delta seems to be caused by the bogus SIMD prereqs that should be fixed by #85370 .

@EgorBo
Copy link
Member

EgorBo commented May 5, 2023

Add Console.WriteLine("Hello world"); and the number of jitted methods grows to 121 on my machines

Do you have System.Console R2R compiled? It only goes up to 30 on my machine and the delta seems to be caused by the bogus SIMD prereqs that should be fixed by #85370 .

I can confirm 30 methods, but if I do

..\dotnet8p5\dotnet.exe publish -c Release -r win-x64 /p:PublishTrimmed=true /p:PublishReadyToRun=true
$env:DOTNET_JitDisasmSummary=1
bin\Release\net8.0\win-x64\publish\sizedemo.exe

then it prints 140. Wonder if that because we re-jit corelib (due to IL trimming) but this time without MIBC (that usually helps crossgen to figure out what's needed to be prejitted aside of default)

         C:\Users\EgorBo\.nuget\packages\microsoft.netcore.app.crossgen2.win-x64\8.0.0-preview.5.23252.13\tools\crossgen2.exe --targetos:windows
         --targetarch:x64
         -O
         -r:"obj\Release\net8.0\win-x64\linked\sizedemo.dll"
         -r:"obj\Release\net8.0\win-x64\linked\System.Collections.Immutable.dll"
         -r:"obj\Release\net8.0\win-x64\linked\System.Console.dll"
         -r:"obj\Release\net8.0\win-x64\linked\System.Diagnostics.StackTrace.dll"
         -r:"obj\Release\net8.0\win-x64\linked\System.IO.Compression.dll"
         -r:"obj\Release\net8.0\win-x64\linked\System.IO.MemoryMappedFiles.dll"
         -r:"obj\Release\net8.0\win-x64\linked\System.Private.CoreLib.dll"
         -r:"obj\Release\net8.0\win-x64\linked\System.Reflection.Metadata.dll"
         --out:"obj\Release\net8.0\win-x64\R2R\System.Private.CoreLib.dll"
         obj\Release\net8.0\win-x64\linked\System.Private.CoreLib.dll

mibc is not used

@EgorBo
Copy link
Member

EgorBo commented May 5, 2023

Yes, confirmed that MIBC caused that. Ideally, dotnet/sdk should always use our default MIBC for all prejit operations.

@trylek
Copy link
Member

trylek commented May 5, 2023

I hit the same thing in my Crossgen2 startup perf measurements in the winter. I think we should fix the SDK to pass the MIBC file when /p:PublishReadyToRunComposite is specified.

@trylek trylek mentioned this issue May 5, 2023
46 tasks
@stephentoub
Copy link
Member

but no ushort

It's never used with ushort, only byte and char.

🤷 trying to find out who is instanciating that

Did you figure this part out?

@EgorBo
Copy link
Member

EgorBo commented May 8, 2023

Did you figure this part out?

Looks like we have two methods:

System.Guid.TryFormatCore[System.Char](System.Span`1<Char>, Int32 ByRef, System.ReadOnlySpan`1<Char>)
System.Guid.TryFormatCore[System.Char](System.Span`1<Char>, Int32 ByRef, Int32)

the latter fails to pick up R2R version, digging further

@EgorBo
Copy link
Member

EgorBo commented May 8, 2023

Ah, SVM again:

Info: Method `[S.P.CoreLib]System.Guid.TryFormatCore<char>(Span`1<char>,int32&,int32)` 
was not compiled because `SVM` requires runtime JIT

@stephentoub
Copy link
Member

Ah, SVM again

Not following... how does that explain why it compiled a ushort version?

@EgorBo
Copy link
Member

EgorBo commented May 8, 2023

Ah, SVM again

Not following... how does that explain why it compiled a ushort version?

I assume it's just the way it's displayed in the log (char -> ushort) or maybe R2R is smart enough to share a single version for both char and ushort, but the actual reason we see TryFormatCore in JitDisasmSummary is SVM

@stephentoub
Copy link
Member

it's just the way it's displayed in the log

Ok :)

@TIHan
Copy link
Contributor Author

TIHan commented May 8, 2023

Also, why would those not show up on ARM64... was that also on a different OS and that's impacting what EventSource is doing?

They will show-up while running a PerfView trace:

C:\Users\lolti\OneDrive\Desktop\runtime>dotnet HelloWorldStartup.dll
   1: JIT compiled System.Runtime.CompilerServices.CastHelpers:StelemRef(System.Array,long,System.Object) [Tier1, IL size=88, code size=144]
   2: JIT compiled System.Runtime.CompilerServices.CastHelpers:LdelemaRef(System.Array,long,ulong) [Tier1, IL size=44, code size=88]
   3: JIT compiled System.SpanHelpers:IndexOfNullCharacter(ulong) [Tier1, IL size=492, code size=392]
   4: JIT compiled System.ArgumentOutOfRangeException:ThrowIfNegative[int](int,System.String) [Tier0, IL size=22, code size=80]
   5: JIT compiled System.SpanHelpers:IndexOfNullByte(ulong) [Tier1, IL size=581, code size=504]
   6: JIT compiled System.SpanHelpers:NonPackedIndexOfValueType[short,System.SpanHelpers+DontNegate`1[short]](byref,short,int) [Tier1, IL size=843, code size=404]
   7: JIT compiled System.SpanHelpers:LastIndexOfValueType[short,System.SpanHelpers+DontNegate`1[short]](byref,short,int) [Tier1, IL size=819, code size=384]
   8: JIT compiled (dynamicClass):InvokeStub_EventAttribute.set_Level(System.Object,System.Object,ulong) [FullOpts, IL size=25, code size=56]
   9: JIT compiled (dynamicClass):InvokeStub_EventAttribute.set_Message(System.Object,System.Object,ulong) [FullOpts, IL size=25, code size=56]
  10: JIT compiled (dynamicClass):InvokeStub_EventAttribute.set_Task(System.Object,System.Object,ulong) [FullOpts, IL size=25, code size=56]
  11: JIT compiled (dynamicClass):InvokeStub_EventAttribute.set_Opcode(System.Object,System.Object,ulong) [FullOpts, IL size=25, code size=56]
  12: JIT compiled (dynamicClass):InvokeStub_EventAttribute.set_Version(System.Object,System.Object,ulong) [FullOpts, IL size=25, code size=56]
  13: JIT compiled (dynamicClass):InvokeStub_EventAttribute.set_Keywords(System.Object,System.Object,ulong) [FullOpts, IL size=25, code size=56]
  14: JIT compiled System.SpanHelpers:NonPackedIndexOfAnyInRangeUnsignedNumber[ushort,System.SpanHelpers+DontNegate`1[ushort]](byref,ushort,ushort,int) [Tier0, IL size=294, code size=708]
  15: JIT compiled System.SpanHelpers+DontNegate`1[ushort]:NegateIfNeeded(bool) [Tier0, IL size=2, code size=28]
  16: JIT compiled System.SpanHelpers:SequenceCompareTo(byref,int,byref,int) [Tier1, IL size=287, code size=248]
  17: JIT compiled HelloWorldStartup.Program:Main(System.String[]) [Tier0, IL size=1, code size=20]

C:\Users\lolti\OneDrive\Desktop\runtime>dotnet HelloWorldStartup.dll
   1: JIT compiled System.Runtime.CompilerServices.CastHelpers:StelemRef(System.Array,long,System.Object) [Tier1, IL size=88, code size=144]
   2: JIT compiled System.Runtime.CompilerServices.CastHelpers:LdelemaRef(System.Array,long,ulong) [Tier1, IL size=44, code size=88]
   3: JIT compiled System.SpanHelpers:IndexOfNullCharacter(ulong) [Tier1, IL size=492, code size=392]
   4: JIT compiled HelloWorldStartup.Program:Main(System.String[]) [Tier0, IL size=1, code size=20]

The second run is when I didn't do a perf-view trace.

On my X64 box, even when not running perf-view, the EventSource still gets created, likely from some other program.

@JulieLeeMSFT JulieLeeMSFT added this to the Future milestone May 18, 2023
@ghost ghost removed the untriaged New issue has not been triaged by the area owner label May 18, 2023
@stephentoub
Copy link
Member

stephentoub commented Aug 11, 2023

For the EventSource ones, anyone know why dotnet app.dll wouldn't show those entries but corerun app.dll would?

My dotnet is from a few weeks ago and my corerun is from a local build, but with an empty Main app, with dotnet app.dll I see:

   1: JIT compiled System.Runtime.CompilerServices.CastHelpers:StelemRef(System.Array,long,System.Object) [Tier1, IL size=88, code size=93]
   2: JIT compiled System.Runtime.CompilerServices.CastHelpers:LdelemaRef(System.Array,long,ulong) [Tier1, IL size=44, code size=44]
   3: JIT compiled System.Guid:TryFormatCore[ushort](System.Span`1[ushort],byref,int) [Tier0, IL size=894, code size=892]
   4: JIT compiled System.Guid:FormatGuidVector128Utf8(System.Guid,bool) [Tier0, IL size=322, code size=584]
   5: JIT compiled System.HexConverter:AsciiToHexVector128(System.Runtime.Intrinsics.Vector128`1[ubyte],System.Runtime.Intrinsics.Vector128`1[ubyte]) [Tier0, IL size=78, code size=359]
   6: JIT compiled System.Runtime.Intrinsics.Vector128:ShuffleUnsafe(System.Runtime.Intrinsics.Vector128`1[ubyte],System.Runtime.Intrinsics.Vector128`1[ubyte]) [Tier0, IL size=41, code size=50]
   7: JIT compiled System.Number:UInt32ToDecChars[ushort](ulong,uint) [Instrumented Tier0, IL size=114, code size=315]
   8: JIT compiled System.ArgumentOutOfRangeException:ThrowIfNegative[int](int,System.String) [Tier0, IL size=22, code size=50]
   9: JIT compiled System.Text.Unicode.Utf16Utility:GetPointerToFirstInvalidChar(ulong,int,byref,byref) [Instrumented Tier0, IL size=994, code size=1296]
  10: JIT compiled System.Text.Ascii:NarrowUtf16ToAscii(ulong,ulong,ulong) [Instrumented Tier0, IL size=558, code size=1384]
  11: JIT compiled System.RuntimeType+RuntimeTypeCache+MemberInfoCache`1[System.__Canon]:AddMethod(System.RuntimeType,long,int) [Instrumented Tier0, IL size=354, code size=1672]
  12: JIT compiled System.SpanHelpers:LastIndexOfValueType[short,System.SpanHelpers+DontNegate`1[short]](byref,short,int) [Instrumented Tier0, IL size=1128, code size=2125]
  13: JIT compiled System.Text.Ascii:WidenAsciiToUtf16(ulong,ulong,ulong) [Instrumented Tier0, IL size=738, code size=1814]
  14: JIT compiled System.PackedSpanHelpers:IndexOf[System.SpanHelpers+DontNegate`1[short]](byref,short,int) [Instrumented Tier0, IL size=977, code size=1912]
  15: JIT compiled System.Number:Int64ToHexChars[ushort](ulong,ulong,int,int) [Instrumented Tier0, IL size=67, code size=313]
  16: JIT compiled System.SpanHelpers:IndexOfAnyInRangeUnsignedNumber[ushort,System.SpanHelpers+DontNegate`1[ushort]](byref,ushort,ushort,int) [Tier0, IL size=142, code size=190]
  17: JIT compiled System.PackedSpanHelpers:IndexOfAnyInRange[System.SpanHelpers+DontNegate`1[short]](byref,short,short,int) [Instrumented Tier0, IL size=972, code size=1810]
  18: JIT compiled Test:Main() [Tier0, IL size=1, code size=6]

and with corerun app.dll I see:

   1: JIT compiled System.Runtime.CompilerServices.CastHelpers:StelemRef(System.Array,long,System.Object) [Tier1, IL size=88, code size=93]
   2: JIT compiled System.Runtime.CompilerServices.CastHelpers:LdelemaRef(System.Array,long,ulong) [Tier1, IL size=44, code size=44]
   3: JIT compiled System.Guid:FormatGuidVector128Utf8(System.Guid,bool) [Tier0, IL size=322, code size=584]
   4: JIT compiled System.HexConverter:AsciiToHexVector128(System.Runtime.Intrinsics.Vector128`1[ubyte],System.Runtime.Intrinsics.Vector128`1[ubyte]) [Tier0, IL size=78, code size=359]
   5: JIT compiled System.Runtime.Intrinsics.Vector128:ShuffleUnsafe(System.Runtime.Intrinsics.Vector128`1[ubyte],System.Runtime.Intrinsics.Vector128`1[ubyte]) [Tier0, IL size=41, code size=50]
   6: JIT compiled System.Text.Unicode.Utf16Utility:GetPointerToFirstInvalidChar(ulong,int,byref,byref) [Instrumented Tier0, IL size=994, code size=1292]
   7: JIT compiled System.RuntimeType+RuntimeTypeCache+MemberInfoCache`1[System.__Canon]:AddMethod(System.RuntimeType,long,int) [Instrumented Tier0, IL size=354, code size=1672]
   8: JIT compiled (dynamicClass):InvokeStub_EventAttribute.set_Level(System.Object,System.Object,ulong) [FullOpts, IL size=25, code size=27]
   9: JIT compiled (dynamicClass):InvokeStub_EventAttribute.set_Message(System.Object,System.Object,ulong) [FullOpts, IL size=25, code size=28]
  10: JIT compiled (dynamicClass):InvokeStub_EventAttribute.set_Task(System.Object,System.Object,ulong) [FullOpts, IL size=25, code size=27]
  11: JIT compiled (dynamicClass):InvokeStub_EventAttribute.set_Opcode(System.Object,System.Object,ulong) [FullOpts, IL size=25, code size=27]
  12: JIT compiled (dynamicClass):InvokeStub_EventAttribute.set_Version(System.Object,System.Object,ulong) [FullOpts, IL size=25, code size=28]
  13: JIT compiled (dynamicClass):InvokeStub_EventAttribute.set_Keywords(System.Object,System.Object,ulong) [FullOpts, IL size=25, code size=28]
  14: JIT compiled (dynamicClass):InvokeStub_EventAttribute.set_Level(System.Object,System.Span`1[System.Object]) [FullOpts, IL size=36, code size=40]
  15: JIT compiled (dynamicClass):InvokeStub_EventAttribute.set_Message(System.Object,System.Span`1[System.Object]) [FullOpts, IL size=26, code size=37]
  16: JIT compiled (dynamicClass):InvokeStub_EventAttribute.set_Task(System.Object,System.Span`1[System.Object]) [FullOpts, IL size=36, code size=40]
  17: JIT compiled (dynamicClass):InvokeStub_EventAttribute.set_Opcode(System.Object,System.Span`1[System.Object]) [FullOpts, IL size=36, code size=40]
  18: JIT compiled (dynamicClass):InvokeStub_EventAttribute.set_Version(System.Object,System.Span`1[System.Object]) [FullOpts, IL size=36, code size=41]
  19: JIT compiled (dynamicClass):InvokeStub_EventAttribute.set_Keywords(System.Object,System.Span`1[System.Object]) [FullOpts, IL size=36, code size=41]
  20: JIT compiled Test:Main() [Tier0, IL size=1, code size=6]

Many of the extraneous entries have been removed due to improvements in corelib, but corerun is showing all of these dynamicClass entries that dotnet isn't. Is it possible this is a regression? Or is there something different between the hosts that would trigger this?

@jkotas
Copy link
Member

jkotas commented Aug 11, 2023

My dotnet is from a few weeks ago

What is your exact dotnet version? I have tried this on .NET 8 P7 bits and I do not see this difference. (I see the event source in both cases.)

I think it is most likely difference in timing or difference in what kind of event providers get enabled on the machine. The managed providers run asynchronously and the process can be exiting before they get a chance to run in one case, but not in the other case. Also, the Windows monitoring software running in the background can be turning the event providers on - for examble, it can say that corerun.exe is unsigned binary so better to monitor to it in detail.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

6 participants