dotnet / fsharp

The F# compiler, F# core library, F# language service, and F# tooling integration for Visual Studio
https://dotnet.microsoft.com/languages/fsharp
MIT License
3.88k stars 783 forks source link

Compilation timings produced by `reportTime` are incorrect. #16598

Open safesparrow opened 8 months ago

safesparrow commented 8 months ago

reportTime is used for recording timings of individual phases of compilation.

When the --times:file.csv is used, it produces a csv file with the following header:

Name,StartTime,EndTime,Duration(s),Id,ParentId,RootId,fileName,project,qualifiedNameOfFile,userOpName,length,cache,cpuDelta(s),realDelta(s),gc0,gc1,gc2,outputDllFile,buildPhase

Every reportTime call starts an activity. The StartTime of that activity is the time of the reportTime call. The EndTime of the activity is the time of the next reportTime call.

This means that code like this: https://github.com/dotnet/fsharp/blob/615475b87bacc6728cb6a80acfd185983bf3ce8b/src/Compiler/AbstractIL/ilwritepdb.fs#L323-L324

produces incorrect EndTime and Duration value:

PDB: Sorted 84715 methods,21-34-19.7634,21-34-20.3083,000.5449,00-9c3f77575c3b7a5ca12bf645a553cada-2400157aee4f53f6-00,00-9c3f77575c3b7a5ca12bf645a553cada-d46ddb4fcab9901d-00,9c3f77575c3b7a5ca12bf645a553cada,,,,,,,,,,,,,

This made me spend quite a while thinking that there is ome low-hanging fruit in how those method objects are being sorted - sadly (thankfully?) there is none, and it's just an artefact of the report.

It would be nice to improve the reporting here.

CC @T-Gro

T-Gro commented 8 months ago

Thanks @safesparrow , that is indeed an incorrect usage of the reportTime call. An entry should be done when the activity starts, and the coverage of the blocks/phases should be without holes.

This is a set of legacy entries which I decided to keep in and just hook into the otel calls because it was easy to do so, a more granular control is better achieved with the Activity module and properly controlling the end of the block via Activity disposal.

I will check semantics of other preexisting usages and move+rename the calls.