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

VS 2022 Preview - Startup time for CoreClr compiler slower than desktop #11907

Closed
TIHan opened this issue Aug 2, 2021 · 13 comments
Closed

VS 2022 Preview - Startup time for CoreClr compiler slower than desktop #11907

TIHan opened this issue Aug 2, 2021 · 13 comments
Labels
Impact-High (Internal MS Team use only) Describes an issue with extreme impact on existing code. Regression Resolution-External Theme-Performance

Comments

@TIHan
Copy link
Contributor

TIHan commented Aug 2, 2021

We recently switched to using the CoreClr compiler for builds in VS instead of the desktop compiler. Doing so, we regressed compile-time performance.
TFM: net5

// Learn more about F# at http://docs.microsoft.com/dotnet/fsharp

open System

// Define a function to construct a message to print
let from whom =
    sprintf "from %s" whom

[<EntryPoint>]
let main argv =
    let message = from "F#" // Call the function
    printfn "Hello world %s" message
    0 // return an integer exit code

CoreClr compiler: 1326 ms Fsc 1 calls
Desktop compiler: 586 ms Fsc 1 calls

It's over double the cost.

This is basically the startup time; I imagine the compiler doesn't actually perform worse on the CoreClr. However, this can be surprising for users as the additional 740ms build-cost per project will add up.

@TIHan TIHan added Regression Area-Compiler Impact-High (Internal MS Team use only) Describes an issue with extreme impact on existing code. labels Aug 2, 2021
@TIHan
Copy link
Contributor Author

TIHan commented Aug 2, 2021

// cc @KevinRansom @jonsequitur

@vzarytovskii
Copy link
Member

vzarytovskii commented Aug 2, 2021

We recently switched to using the CoreClr compiler for builds in VS instead of the desktop compiler. Doing so, we regressed compile-time performance.

TFM: net5

// Learn more about F# at http://docs.microsoft.com/dotnet/fsharp



open System



// Define a function to construct a message to print

let from whom =

    sprintf "from %s" whom



[<EntryPoint>]

let main argv =

    let message = from "F#" // Call the function

    printfn "Hello world %s" message

    0 // return an integer exit code

CoreClr compiler: 1326 ms Fsc 1 calls

Desktop compiler: 586 ms Fsc 1 calls

It's over double the cost.

This is basically the startup time; I imagine the compiler doesn't actually perform worse on the CoreClr. However, this can be surprising for users as the additional 740ms build-cost per project will add up.

Hm, that's interesting. Did you manage to see which part is taking more time? Do we know if it's actually fsc, or something before?

Edit: I mean, can it be msbuild or something? CoreCLR also uses crossgen, right?

@TIHan
Copy link
Contributor Author

TIHan commented Aug 3, 2021

It's not msbuild. It's simply that the JIT is taking longer on the CoreClr.

CoreClr
coreclr

Desktop
desktop

For FSharp.Compiler.Private.dll, the desktop JIT took 0.5ms, where as the CoreClr JIT took 439ms.
FSharp.Core.dll takes longer as well. The runtime libraries take longer on the CoreClr but not nearly the same magnitude as the F# compiler.

@TIHan
Copy link
Contributor Author

TIHan commented Aug 3, 2021

I think we may not have cross-gen enabled in the SDK; we may have to do this -> https://docs.microsoft.com/en-us/dotnet/core/deploying/ready-to-run

// cc @brettfo

@KevinRansom
Copy link
Member

Yes ... there is a steep performance degrade between desktop and coreclr:

The following shows --times for exactly the same inputs between desktop and coreclr for dotnet 6 and 5.05

C:\Users\codec\source\repos\ConsoleApp11\ConsoleApp11>"C:\Program Files (x86)\Microsoft Visual Studio\2019\Community\Common7\IDE\CommonExtensions\Microsoft\FSharp\Tools\fsc.exe" --times @ConsoleApp11.rsp
Microsoft (R) F# Compiler version 11.4.2.0 for F# 5.0
Copyright (c) Microsoft Corporation. All Rights Reserved.

warning FS0075: The command-line option 'times' is for test purposes only
TIME:  0.2 Delta:  0.1 Mem:  80 G0:   0 G1:  0 G2:  0 [Import mscorlib and FSharp.Core.dll]
TIME:  0.3 Delta:  0.1 Mem:  86 G0:   0 G1:  0 G2:  0 [Parse inputs]
TIME:  0.3 Delta:  0.0 Mem:  86 G0:   0 G1:  0 G2:  0 [Import non-system references]
TIME:  0.3 Delta:  0.1 Mem: 106 G0:   0 G1:  0 G2:  0 [Typecheck]
TIME:  0.3 Delta:  0.0 Mem: 106 G0:   0 G1:  0 G2:  0 [Typechecked]
TIME:  0.3 Delta:  0.0 Mem: 106 G0:   0 G1:  0 G2:  0 [Write Interface File]
TIME:  0.3 Delta:  0.0 Mem: 107 G0:   0 G1:  0 G2:  0 [Write XML document signatures]
TIME:  0.3 Delta:  0.0 Mem: 107 G0:   0 G1:  0 G2:  0 [Write XML docs]
TIME:  0.4 Delta:  0.0 Mem: 116 G0:   0 G1:  0 G2:  0 [Encode Interface Data]
TIME:  0.4 Delta:  0.0 Mem: 116 G0:   0 G1:  0 G2:  0 [Optimizations]
TIME:  0.4 Delta:  0.0 Mem: 116 G0:   0 G1:  0 G2:  0 [Ending Optimizations]
TIME:  0.4 Delta:  0.0 Mem: 117 G0:   0 G1:  0 G2:  0 [Encoding OptData]
TIME:  0.4 Delta:  0.0 Mem: 120 G0:   0 G1:  0 G2:  0 [TAST -> IL]
ilwrite: TIME      0.000 (total)        0.391 (delta) - Write Started
ilwrite: TIME      0.000 (total)        0.000 (delta) - Module Generation Preparation
ilwrite: TIME      0.000 (total)        0.000 (delta) - Module Generation Pass 1
ilwrite: TIME      0.000 (total)        0.000 (delta) - Module Generation Pass 2
ilwrite: TIME      0.000 (total)        0.000 (delta) - Module Generation Pass 3
ilwrite: TIME      0.000 (total)        0.000 (delta) - Module Generation Pass 4
ilwrite: TIME      0.000 (total)        0.000 (delta) - Finalize Module Generation Results
ilwrite: TIME      0.000 (total)        0.000 (delta) - Generated Tables and Code
ilwrite: TIME      0.000 (total)        0.000 (delta) - Layout Header of Tables
ilwrite: TIME      0.000 (total)        0.000 (delta) - Build String/Blob Address Tables
ilwrite: TIME      0.000 (total)        0.000 (delta) - Sort Tables
ilwrite: TIME      0.000 (total)        0.000 (delta) - Write Header of tablebuf
ilwrite: TIME      0.000 (total)        0.000 (delta) - Write Tables to tablebuf
ilwrite: TIME      0.000 (total)        0.000 (delta) - Layout Metadata
ilwrite: TIME      0.000 (total)        0.000 (delta) - Write Metadata Header
ilwrite: TIME      0.000 (total)        0.000 (delta) - Write Metadata Tables
ilwrite: TIME      0.000 (total)        0.000 (delta) - Write Metadata Strings
ilwrite: TIME      0.000 (total)        0.000 (delta) - Write Metadata User Strings
ilwrite: TIME      0.000 (total)        0.000 (delta) - Write Blob Stream
ilwrite: TIME      0.000 (total)        0.000 (delta) - Fixup Metadata
ilwrite: TIME      0.000 (total)        0.000 (delta) - Generated IL and metadata
ilwrite: TIME      0.000 (total)        0.000 (delta) - PDB: Defined 1 documents
ilwrite: TIME      0.000 (total)        0.000 (delta) - PDB: Sorted 1 methods
ilwrite: TIME      0.000 (total)        0.000 (delta) - PDB: Created
ilwrite: TIME      0.000 (total)        0.000 (delta) - Layout image
ilwrite: TIME      0.016 (total)        0.016 (delta) - Writing Image
ilwrite: TIME      0.016 (total)        0.000 (delta) - PDB: Closed
ilwrite: TIME      0.016 (total)        0.000 (delta) - Generate PDB Info
ilwrite: TIME      0.016 (total)        0.000 (delta) - Finalize PDB
ilwrite: TIME      0.016 (total)        0.000 (delta) - Signing Image
TIME:  0.4 Delta:  0.0 Mem: 123 G0:   0 G1:  0 G2:  0 [Write .NET Binary]
STATS: #ByteArrayFile = 151, #MemoryMappedFileOpen = 1, #MemoryMappedFileClosed = 0, #RawMemoryFile = 1, #WeakByteArrayFile = 0

C:\Users\codec\source\repos\ConsoleApp11\ConsoleApp11>dotnet.exe "C:\Program Files\dotnet\sdk\6.0.100-preview.6.21355.2\FSharp\fsc.dll" --times @ConsoleApp11.rsp
Microsoft (R) F# Compiler version 12.0.0.0 for F# 5.0
Copyright (c) Microsoft Corporation. All Rights Reserved.

warning FS0075: The command-line option 'times' is for test purposes only
TIME:  0.4 Delta:  0.2 Mem: 112 G0:   8 G1:  4 G2:  2 [Import mscorlib and FSharp.Core.dll]
TIME:  0.5 Delta:  0.1 Mem: 118 G0:   0 G1:  0 G2:  0 [Parse inputs]
TIME:  0.5 Delta:  0.0 Mem: 118 G0:   0 G1:  0 G2:  0 [Import non-system references]
TIME:  0.9 Delta:  0.4 Mem: 136 G0:   3 G1:  1 G2:  1 [Typecheck]
TIME:  0.9 Delta:  0.0 Mem: 136 G0:   0 G1:  0 G2:  0 [Typechecked]
TIME:  0.9 Delta:  0.0 Mem: 136 G0:   0 G1:  0 G2:  0 [Write Interface File]
TIME:  0.9 Delta:  0.0 Mem: 136 G0:   0 G1:  0 G2:  0 [Write XML document signatures]
TIME:  0.9 Delta:  0.0 Mem: 136 G0:   0 G1:  0 G2:  0 [Write XML docs]
TIME:  1.0 Delta:  0.1 Mem: 136 G0:   1 G1:  0 G2:  0 [Encode Interface Data]
TIME:  1.0 Delta:  0.0 Mem: 137 G0:   0 G1:  0 G2:  0 [Optimizations]
TIME:  1.0 Delta:  0.0 Mem: 137 G0:   0 G1:  0 G2:  0 [Ending Optimizations]
TIME:  1.0 Delta:  0.0 Mem: 137 G0:   0 G1:  0 G2:  0 [Encoding OptData]
TIME:  1.1 Delta:  0.1 Mem: 140 G0:   1 G1:  0 G2:  0 [TAST -> IL]
ilwrite: TIME      0.000 (total)        1.094 (delta) - Write Started
ilwrite: TIME      0.016 (total)        0.016 (delta) - Module Generation Preparation
ilwrite: TIME      0.016 (total)        0.000 (delta) - Module Generation Pass 1
ilwrite: TIME      0.016 (total)        0.000 (delta) - Module Generation Pass 2
ilwrite: TIME      0.047 (total)        0.031 (delta) - Module Generation Pass 3
ilwrite: TIME      0.047 (total)        0.000 (delta) - Module Generation Pass 4
ilwrite: TIME      0.047 (total)        0.000 (delta) - Finalize Module Generation Results
ilwrite: TIME      0.047 (total)        0.000 (delta) - Generated Tables and Code
ilwrite: TIME      0.047 (total)        0.000 (delta) - Layout Header of Tables
ilwrite: TIME      0.047 (total)        0.000 (delta) - Build String/Blob Address Tables
ilwrite: TIME      0.047 (total)        0.000 (delta) - Sort Tables
ilwrite: TIME      0.047 (total)        0.000 (delta) - Write Header of tablebuf
ilwrite: TIME      0.047 (total)        0.000 (delta) - Write Tables to tablebuf
ilwrite: TIME      0.047 (total)        0.000 (delta) - Layout Metadata
ilwrite: TIME      0.047 (total)        0.000 (delta) - Write Metadata Header
ilwrite: TIME      0.047 (total)        0.000 (delta) - Write Metadata Tables
ilwrite: TIME      0.047 (total)        0.000 (delta) - Write Metadata Strings
ilwrite: TIME      0.047 (total)        0.000 (delta) - Write Metadata User Strings
ilwrite: TIME      0.047 (total)        0.000 (delta) - Write Blob Stream
ilwrite: TIME      0.047 (total)        0.000 (delta) - Fixup Metadata
ilwrite: TIME      0.047 (total)        0.000 (delta) - Generated IL and metadata
ilwrite: TIME      0.047 (total)        0.000 (delta) - PDB: Defined 1 documents
ilwrite: TIME      0.047 (total)        0.000 (delta) - PDB: Sorted 1 methods
ilwrite: TIME      0.062 (total)        0.016 (delta) - PDB: Created
ilwrite: TIME      0.078 (total)        0.016 (delta) - Layout image
ilwrite: TIME      0.078 (total)        0.000 (delta) - Writing Image
ilwrite: TIME      0.078 (total)        0.000 (delta) - PDB: Closed
ilwrite: TIME      0.078 (total)        0.000 (delta) - Generate PDB Info
ilwrite: TIME      0.078 (total)        0.000 (delta) - Finalize PDB
ilwrite: TIME      0.078 (total)        0.000 (delta) - Signing Image
TIME:  1.2 Delta:  0.1 Mem: 143 G0:   0 G1:  0 G2:  0 [Write .NET Binary]

C:\Users\codec\source\repos\ConsoleApp11\ConsoleApp11>dotnet.exe "C:\Program Files\dotnet\sdk\5.0.302\FSharp\fsc.dll" --times @ConsoleApp11.rsp
Microsoft (R) F# Compiler version 11.4.2.0 for F# 5.0
Copyright (c) Microsoft Corporation. All Rights Reserved.

warning FS0075: The command-line option 'times' is for test purposes only
TIME:  0.4 Delta:  0.3 Mem: 110 G0:   9 G1:  4 G2:  2 [Import mscorlib and FSharp.Core.dll]
TIME:  0.5 Delta:  0.1 Mem: 115 G0:   0 G1:  0 G2:  0 [Parse inputs]
TIME:  0.5 Delta:  0.0 Mem: 115 G0:   0 G1:  0 G2:  0 [Import non-system references]
TIME:  0.9 Delta:  0.4 Mem: 139 G0:   2 G1:  1 G2:  0 [Typecheck]
TIME:  0.9 Delta:  0.0 Mem: 139 G0:   0 G1:  0 G2:  0 [Typechecked]
TIME:  0.9 Delta:  0.0 Mem: 139 G0:   0 G1:  0 G2:  0 [Write Interface File]
TIME:  0.9 Delta:  0.0 Mem: 139 G0:   0 G1:  0 G2:  0 [Write XML document signatures]
TIME:  0.9 Delta:  0.0 Mem: 139 G0:   0 G1:  0 G2:  0 [Write XML docs]
TIME:  1.0 Delta:  0.1 Mem: 138 G0:   2 G1:  1 G2:  1 [Encode Interface Data]
TIME:  1.0 Delta:  0.0 Mem: 139 G0:   0 G1:  0 G2:  0 [Optimizations]
TIME:  1.0 Delta:  0.0 Mem: 139 G0:   0 G1:  0 G2:  0 [Ending Optimizations]
TIME:  1.0 Delta:  0.0 Mem: 139 G0:   0 G1:  0 G2:  0 [Encoding OptData]
TIME:  1.1 Delta:  0.1 Mem: 140 G0:   0 G1:  0 G2:  0 [TAST -> IL]
ilwrite: TIME      0.000 (total)        1.109 (delta) - Write Started
ilwrite: TIME      0.016 (total)        0.016 (delta) - Module Generation Preparation
ilwrite: TIME      0.016 (total)        0.000 (delta) - Module Generation Pass 1
ilwrite: TIME      0.016 (total)        0.000 (delta) - Module Generation Pass 2
ilwrite: TIME      0.031 (total)        0.016 (delta) - Module Generation Pass 3
ilwrite: TIME      0.031 (total)        0.000 (delta) - Module Generation Pass 4
ilwrite: TIME      0.031 (total)        0.000 (delta) - Finalize Module Generation Results
ilwrite: TIME      0.031 (total)        0.000 (delta) - Generated Tables and Code
ilwrite: TIME      0.031 (total)        0.000 (delta) - Layout Header of Tables
ilwrite: TIME      0.031 (total)        0.000 (delta) - Build String/Blob Address Tables
ilwrite: TIME      0.031 (total)        0.000 (delta) - Sort Tables
ilwrite: TIME      0.031 (total)        0.000 (delta) - Write Header of tablebuf
ilwrite: TIME      0.031 (total)        0.000 (delta) - Write Tables to tablebuf
ilwrite: TIME      0.031 (total)        0.000 (delta) - Layout Metadata
ilwrite: TIME      0.031 (total)        0.000 (delta) - Write Metadata Header
ilwrite: TIME      0.031 (total)        0.000 (delta) - Write Metadata Tables
ilwrite: TIME      0.031 (total)        0.000 (delta) - Write Metadata Strings
ilwrite: TIME      0.031 (total)        0.000 (delta) - Write Metadata User Strings
ilwrite: TIME      0.031 (total)        0.000 (delta) - Write Blob Stream
ilwrite: TIME      0.031 (total)        0.000 (delta) - Fixup Metadata
ilwrite: TIME      0.031 (total)        0.000 (delta) - Generated IL and metadata
ilwrite: TIME      0.031 (total)        0.000 (delta) - PDB: Defined 1 documents
ilwrite: TIME      0.031 (total)        0.000 (delta) - PDB: Sorted 1 methods
ilwrite: TIME      0.062 (total)        0.031 (delta) - PDB: Created
ilwrite: TIME      0.078 (total)        0.016 (delta) - Layout image
ilwrite: TIME      0.078 (total)        0.000 (delta) - Writing Image
ilwrite: TIME      0.078 (total)        0.000 (delta) - PDB: Closed
ilwrite: TIME      0.078 (total)        0.000 (delta) - Generate PDB Info
ilwrite: TIME      0.078 (total)        0.000 (delta) - Finalize PDB
ilwrite: TIME      0.078 (total)        0.000 (delta) - Signing Image
TIME:  1.2 Delta:  0.1 Mem: 143 G0:   0 G1:  0 G2:  0 [Write .NET Binary]

C:\Users\codec\source\repos\ConsoleApp11\ConsoleApp11>

@KevinRansom
Copy link
Member

The shipped binary has been compiled with cross-gen:

We build IL only, note the flag: IL Only

C:\Users\codec\source\repos\ConsoleApp11\ConsoleApp11>dumpbin /CLRHEADER C:\kevinransom\fsharp\artifacts\bin\fsc\Release\net5.0\FSharp.Compiler.Service.dll
Microsoft (R) COFF/PE Dumper Version 14.29.30040.0
Copyright (C) Microsoft Corporation.  All rights reserved.


Dump of file C:\kevinransom\fsharp\artifacts\bin\fsc\Release\net5.0\FSharp.Compiler.Service.dll

File Type: DLL

  clr Header:

              48 cb
            2.05 runtime version
          3B13AC [  81E918] RVA [size] of MetaData Directory
               1 flags
                   IL Only
               0 entry point token
          BCFD44 [  2929E4] RVA [size] of Resources Directory
          BCFCC4 [      80] RVA [size] of StrongNameSignature Directory
               0 [       0] RVA [size] of CodeManagerTable Directory
               0 [       0] RVA [size] of VTableFixups Directory
               0 [       0] RVA [size] of ExportAddressTableJumps Directory
               0 [       0] RVA [size] of ManagedNativeHeader Directory


  Summary

        2000 .reloc
        2000 .rsrc
     1038000 .text

C:\Users\codec\source\repos\ConsoleApp11\ConsoleApp11>

When shipped it has been transformed by crossgen to IL Library:

Microsoft (R) COFF/PE Dumper Version 14.29.30040.0
Copyright (C) Microsoft Corporation.  All rights reserved.


Dump of file C:\Program Files\dotnet\sdk\5.0.302\FSharp\FSharp.Compiler.Service.dll

File Type: DLL

  clr Header:

              48 cb
            2.05 runtime version
          60F3A0 [  86413C] RVA [size] of MetaData Directory
               4 flags
                   IL Library
               0 entry point token
          E734E0 [  287598] RVA [size] of Resources Directory
               0 [       0] RVA [size] of StrongNameSignature Directory
               0 [       0] RVA [size] of CodeManagerTable Directory
               0 [       0] RVA [size] of VTableFixups Directory
               0 [       0] RVA [size] of ExportAddressTableJumps Directory
           A8478 [      88] RVA [size] of ManagedNativeHeader Directory


  Summary

       A7000 .data
       1C000 .reloc
     1D35000 .text

@KevinRansom
Copy link
Member

@jkotas ,
Hey mate, it looks as if cross-gen'd F# assemblies are spending an awfully large amount of time in the Jit. Who should we work with, or how can analyse what is going on here?

Thanks

Kevin

@KevinRansom
Copy link
Member

I have done a sanity check back to 2.1 and the behavior seems similar, so at least it's not a regression.

@jkotas
Copy link
Member

jkotas commented Aug 4, 2021

@mangod9 Could your team please take a look?

@mangod9
Copy link
Member

mangod9 commented Aug 4, 2021

cc @dotnet/crossgen-contrib. @TIHan @KevinRansom is there a standalone repro you can share ? Also would be good to know what tooling you are using to crossgen the assemblies.

@jakobbotsch
Copy link
Member

jakobbotsch commented Aug 4, 2021

Do you know how many functions you have with tail. prefixes in them? Currently any such function will be skipped during crossgen. I'd be curious to see if dotnet/runtime#56669 has an effect on x64 Windows (it should allow a significant fraction of these functions to be crossgenned).

@TIHan
Copy link
Contributor Author

TIHan commented Sep 15, 2021

@jakobbotsch - We emit 'tail' prefix pretty frequently; basically any function call that could be tail recursive we emit the prefix. That's not entirely true for every single function, but it's mostly true.

@KevinRansom
Copy link
Member

This has been identified as being an issue with crossgen, the coreclr team have done some stellar work and improved the amount of .tailcalls that get crossgened.

Their PR is here: dotnet/runtime#56669

We will close this issue. And add a tracking issue to identify further issues once 56669 is available

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Impact-High (Internal MS Team use only) Describes an issue with extreme impact on existing code. Regression Resolution-External Theme-Performance
Projects
None yet
Development

No branches or pull requests

7 participants