Diagnostics: [dotnet-trace] Converting big size nettrace file to speedscope format crashes

[t-bzhan]

When using below command to collect traces:

dotnet-trace collect --process-id 1 --format speedscope

The command crashes with message:

No profile or providers specified, defaulting to trace profile 'cpu-sampling'

Provider Name Keywords Level Enabled By
Microsoft-DotNETCore-SampleProfiler 0x0000000000000000 Informational(4) --profile
Microsoft-Windows-DotNETRuntime 0x00000014C14FCCBD Informational(4) --profile

Process : /usr/share/dotnet/dotnet
Output File : /app/trace.nettrace

[00:00:09:17] Recording trace 51.6842 (MB)
Press or to exit... to minutes depending on the application being traced.

Trace completed.
Writing: /app/trace.speedscope.json
Killed

I've also tried to use below command to convert the nettrace file to seedscope format, but still with no good.

dotnet-trace convert trace.nettrace --format speedscope -o trace.speedscope

I can see it generate an eltx file with big size but the speedscope file is not written.

-rw-r--r-- 1 root root 66962210 Jun 10 13:13 trace.nettrace
-rw-r--r-- 1 root root 618481325 Jun 10 13:13 trace.nettrace.etlx
-rw-r--r-- 1 root root 0 Jun 10 13:14 trace.speedscope.json

Version: dotnet-trace 3.1.120604

[sywhang]

@t-bzhan Is this nettrace file something you can share with us?

[t-bzhan]

@t-bzhan Is this nettrace file something you can share with us?

@sywhang , I am afraid not. The trace is captured on our production machine. I can try whether I could repro it with my toy project.

[sywhang]

@t-bzhan That would be great. Thanks!

[t-bzhan]

@sywhang , it is a pity that I could not reproduce it with my toy project, but I found that “dotnet-trace convert trace.nettrace --format speedscope -o trace.speedscope” will succeed in the end, it just took a long time (more than 2 hours) which gives me the impression that it hangs. And it had consumed all my CPUs and hundreds of MB of memory, that might explain why the dotnet-trace process get killed by docker in my scenario.

The converted speedscope file's size is 26.6 GB for a 60+MB nettrace file, is it normal?

[t-bzhan]

From the SpeedScopeStackSourceWriter.WriteStackViewAsJson implementation defined in:https://github.com/microsoft/perfview/blob/ea844afac34a96c45b7aba5dc7c3813b7aeaaf34/src/TraceEvent/Stacks/SpeedScopeStackSourceWriter.cs#L26-L46 https://github.com/dotnet/diagnostics/blob/bf74bba4b90d3fc54973156dafe7c2e981f1fd88/src/Tools/dotnet-trace/TraceFileFormatConverter.cs#L85-L86

It looks like SpeedScopeStackSourceWriter.WriteStackViewAsJson has to do some sorting/aggregation before writing to the speedscope file. That explains why I did not see the file get written for a long time and why so many memory consumed.

I am not sure whether it is possible to do the file converting together with file writing, that would be more efficient and user friendly.

[josalem]

Is the generate speedscope file valid and capable of being viewed? That size increase is much larger than I would expect.

Speedscope represents stacks in a much different manner than nettrace, hence the aggregation. We wouldn't be able to write the trace in speedscope on the fly since it uses symbol information in the aggregation step which requires reading the entire trace file. I'd be curious where most of that time was spent. If possible, could you trace that conversion process (or a portion of it) and see if it generates any interesting patterns in the flame graph or other views of the data?

[adamsitnik]

It looks like SpeedScopeStackSourceWriter.WriteStackViewAsJson has to do some sorting/aggregation before writing to the speedscope file. That explains why I did not see the file get written for a long time and why so many memory consumed.

I've rewritten the exporter in microsoft/perfview#1212 and once #1313 gets merged this problem should be gone.

[josalem]

1313 was merged, so the next version of dotnet-trace shouldn't have this issue. Closing.