Diagnostics: Dotnet-trace collect command does not respect "--duration" parameter

[iliamosko]

Configuration

.NET Version: 3.1.403
dotnet-trace version: 3.1.141901+3f460984c62efa118b6bd87fa4c5f07b11074b34
OS: Linux
Dockerized? The app is running in a docker container and the trace is taken within the container.
Machine Load: High. Traces are taken during high load scenarios.

Description

Commands used:
1: ./dotnet-trace collect --process-id 1 --duration 00:00:00:30 --buffersize 1024 -o /home/application/app-trace/TRACE.nettrace
Size of trace: 101MB.

2: ./dotnet-trace collect --process-id 1 --providers Microsoft-DotNETCore-SampleProfiler --clrevents GC+GCHeapSurvivalAndMovement+Stack+Loader+GCHandle+Type+GCHeapDump+GCHeapCollect+GCHeapAndTypeNames+Exception --clreventlevel 5 --duration 00:00:00:10 --buffersize 1024 -o /home/application/app-trace/TRACE.nettrace
Size of trace: 7GB

While running these commands, the duration parameter was not honored, and the collect command kept on running until CTRL+C was pressed to cancel the operation. There were some instances where the first command would finish as it should, but there would be no information in the trace log.

This seems like a problem when collecting a trace when the machine is under high load. Also, when trying to open the large trace file(7GB), it would take substantially long for PerfView to parse the trace. This could also be a factor of collecting a trace with a high machine load. I have tested these commands under normal machine load and it is working fine. However, I did notice that whenever you click on the CMD/Terminal window while the collect command is running, the window seems to "Freeze" and the collect command will always go over the duration that is specified.

[hoyosjs]

However, I did notice that whenever you click on the CMD/Terminal window while the collect command is running, the window seems to "Freeze" and the collect command will always go over the duration that is specified.

This is expected an behavior of conhost if you are talking about Windows.

[hoyosjs]

@sywhang @josalem Isn't it possible that this is just a very lengthy case of rundown? Or is it more likely that there's so much load that it took a while for the timer in the cancellation token to fire and then rundown just lags because of the CPU constraints?

[sywhang]

Could be either but I'm guessing it's the rundown that's taking the majority of the time. Stopping the trace on dotnet-trace sends a rundown command to the target app which can take a while - we've seen it take minutes on certain apps with a lot of type definitions to resolve. If the app is under CPU pressure I wouldn't be surprised if it takes tens of minutes.

Also, when trying to open the large trace file(7GB), it would take substantially long for PerfView to parse the trace.

This is normal too, although I'm not sure what order of magnitude of time we're talking by "substantially long". Parsing a trace file as big as 7GB is not something I'd expect PerfView to take in the order of seconds - my guess is it'd at least take several minutes to do this. It needs to first write out the ETLX format file, then parse that again to form TraceLog object to be able to display it fully.

[iliamosko]

@hoyosjs

This is expected an behavior of conhost if you are talking about Windows.

This issue also happens when running dotnet-trace under WSL2. Not sure if that is also the expected behavior or not.

@sywhang
The problem so far is that when collecting a trace, with a specified duration and with the machine being under high load, the duration of the trace always goes over the specified duration. When seeing that the duration of the trace is taking longer than it should, CTRL+C is pressed and the trace "zips" within a reasonable amount of time(~30-60 secs), as expected.

When the trace duration surpasses the specified duration, there is no indication that the trace is being stopped and is taking the time to compile the logs. The timer and the size of the trace increases until CTRL+C is pressed then afterwards the message pops up, and the trace is completed.

[hoyosjs]

@hoyosjs This issue also happens when running dotnet-trace under WSL2. Not sure if that is also the expected behavior or not.

It's not really about the shell you are using (WSL2, Bash, Powershell, CMD), but rather the console that's hosting it. The default console host on Windows has that behavior.

[baal2000]

@iliamosko > CTRL+C is pressed and the trace "zips" within a reasonable amount of time(~30-60 secs), as expected.

@hoyosjs @sywhang
Is CTRL+C combination a correct way to stop the trace? The application checks for ConsoleKey.Enter

The below file was produced when collecting .NET with 10 seconds duration parameter from inside a Docker container containing the .NET Core process under Linux.

It could not be opened in PerfView on Windows

The error log:

Started with command line: "C:\Program Files\PerfView.exe" "C:\Users\...\Downloads\example.nettrace"
PerfView Version: 2.0.46  BuildDate: Thu, 24 Oct 2019 10:54:49 GMT
PerfView Start Time 11/11/2020 3:15:46 PM
Started: View
Warning: PdbScope not found at C:\Program Files\PerfViewExtensions\PdbScope.exe
Disabling the Image Size Menu Item.
Warning: ILSize not found at C:\Program Files\PerfViewExtensions\ILSize.dll
Disabling the IL Size Menu Item.
Completed: View   (Elapsed Time: 0.114 sec)
Started: Opening example.nettrace
Creating ETLX file C:\Users\sergepavlov\AppData\Local\Temp\PerfView\example_9c22195.etlx from C:\Users\sergepavlov\Downloads\example.nettrace
Collecting a maximum of 20,000,000 events.
[Opening a log file of size 0 MB.]
[ERROR: processing events ****]
***** Consider using /ContinueOnError to ignore the bad part of the trace.  *****
Error: Exception EventPipe conversion: System.NotSupportedException: Streams larger than 4 GB.  You need to use /MaxEventCount to limit the size.
   at FastSerialization.IOStreamStreamWriter.GetLabel()
   at Microsoft.Diagnostics.Tracing.Etlx.TraceLog.<>c__DisplayClass83_0.<CopyRawEvents>b__1(TraceEvent data)
   at Microsoft.Diagnostics.Tracing.TraceEventDispatcher.DoDispatch(TraceEvent anEvent)
   at Microsoft.Diagnostics.Tracing.TraceEventDispatcher.Dispatch(TraceEvent anEvent)
   at Microsoft.Diagnostics.Tracing.EventPipeEventSource.DispatchEventRecord(EVENT_RECORD* eventRecord)
   at Microsoft.Diagnostics.Tracing.EventPipeEventSource.EventCache_OnEvent(EventPipeEventHeader& header)
   at Microsoft.Diagnostics.Tracing.EventPipe.EventCache.SortAndDispatch(Int64 stopTimestamp)
   at Microsoft.Diagnostics.Tracing.EventPipe.EventCache.ProcessSequencePointBlock(Byte[] sequencePointBytes)
   at Microsoft.Diagnostics.Tracing.EventPipeSequencePointBlock.ReadBlockContents(PinnedStreamReader reader)
   at Microsoft.Diagnostics.Tracing.EventPipeBlock.FromStream(Deserializer deserializer)
   at FastSerialization.Deserializer.ReadObjectDefinition(Tags tag, StreamLabel objectLabel)
   at FastSerialization.Deserializer.ReadObject()
   at Microsoft.Diagnostics.Tracing.EventPipeEventSource.Process()
   at Microsoft.Diagnostics.Tracing.Etlx.TraceLog.CopyRawEvents(TraceEventDispatcher rawEvents, IStreamWriter writer)
   at Microsoft.Diagnostics.Tracing.Etlx.TraceLog.<>c__DisplayClass118_0.<FastSerialization.IFastSerializable.ToStream>b__0()
   at FastSerialization.DeferedRegion.Write(Serializer serializer, Action toStream)
   at Microsoft.Diagnostics.Tracing.Etlx.TraceLog.FastSerialization.IFastSerializable.ToStream(Serializer serializer)
   at FastSerialization.Serializer.WriteObjectData(IFastSerializable obj, Tags beginTag)
   at FastSerialization.Serializer.WriteObjectRef(IFastSerializable obj, Boolean defered)
   at FastSerialization.Serializer..ctor(IStreamWriter writer, IFastSerializable entryObject)
   at Microsoft.Diagnostics.Tracing.Etlx.TraceLog.CreateFromEventPipeEventSources(TraceEventDispatcher source, String etlxFilePath, TraceLogOptions options)
   at Microsoft.Diagnostics.Tracing.Etlx.TraceLog.CreateFromEventPipeDataFile(String filePath, String etlxFilePath, TraceLogOptions options)
   at PerfView.EventPipePerfViewData.GetTraceLog(TextWriter log)
[Error: exception while opening EventPipe data.]
Completed: Opening example.nettrace   (Elapsed Time: 62.843 sec)

Could this behavior be related to the runtime environment?

[josalem]

dotnet-trace will stop tracing on the following condition

https://github.com/dotnet/diagnostics/blob/fb65a2c90acf744a7ea5051f313875f3425fba2e/src/Tools/dotnet-trace/CommandLine/Commands/CollectCommand.cs#L228

ctrl-c sets the cancellation token which has been registered to set the shouldExit ManualResetEvent:
https://github.com/dotnet/diagnostics/blob/fb65a2c90acf744a7ea5051f313875f3425fba2e/src/Tools/dotnet-trace/CommandLine/Commands/CollectCommand.cs#L160

That same MRE is being set by the duration timer if a timeout is specified at the command line:
https://github.com/dotnet/diagnostics/blob/fb65a2c90acf744a7ea5051f313875f3425fba2e/src/Tools/dotnet-trace/CommandLine/Commands/CollectCommand.cs#L184-L189

The console output says you can stop with either Enter or ctrl-c (more specifically a SIGINT):
https://github.com/dotnet/diagnostics/blob/fb65a2c90acf744a7ea5051f313875f3425fba2e/src/Tools/dotnet-trace/CommandLine/Commands/CollectCommand.cs#L221

Note that "stopping" the trace just sends the StopTracing command to the runtime. In order to have symbol information, a rundown of data is then sent. We display a message when this has started:
https://github.com/dotnet/diagnostics/blob/fb65a2c90acf744a7ea5051f313875f3425fba2e/src/Tools/dotnet-trace/CommandLine/Commands/CollectCommand.cs#L224-L225

For sufficiently large applications (many, many type/method definitions), this can take a non-trivial amount of time.

The below file was produced when collecting .NET with 10 seconds duration parameter from inside a Docker container containing the .NET Core process under Linux.

How long did the trace collect for to grow to ~10 GiB? I'm assuming this was longer than 10 seconds.

When the timer goes past the requested duration runs out, does the text output show the message above about "stopping the trace"?

The exception you're seeing in the PerfView log is due to the file being so large, not due to the runtime environment.

[baal2000]

@josalem
Thanks for explaining how stopping is performed. We will get back after collecting the necessary screenshots and also trying running the tool with different argument sets.

One question: is there a parameter (could be unpublished) that, like CPUSampleMSec in PervView, limits the amount of collected CPU data points?

Update:
Could --clreventlevel argument control that? There is not much information about that parameter. What is the recommended value for it?

Update 1
Here is how --clreventlevel is processed: private static EventLevel GetEventLevel(string token)

where EventLevel is defined as https://docs.microsoft.com/en-us/dotnet/api/system.diagnostics.tracing.eventlevel

Level "5" would be "Verbose". We should try "4" ("Informational") and see what happens.

[josalem]

One question: is there a parameter (could be unpublished) that, like CPUSampleMSec in PervView, limits the amount of collected CPU data points?

The frequency of CPU sampling isn't variable currently.

Level "5" would be "Verbose". We should try "4" ("Informational") and see what happens.

That adjusts the event level for a provider which doesn't affect CPU sample frequency.

---

When the specified duration in your scenario runs out, do you see the "stopping the trace" text in the output?

[iliamosko]

@josalem
When the timer goes past the specified duration, there is no sign of "stopping the trace" text. Usually the session window will not update or allow any interaction until the trace is finished after pressing "CTRL+C" or "ENTER".

[josalem]

Usually the session window will not update

Do the trace size and timer in the stdout output increase over time? If those aren't increasing either, it sounds like you might somehow be pausing execution of dotnet-trace like @hoyosjs suggested above (by clicking in the console window in a conhost powered terminal on Windows).

@sywhang and I tried to reproduce the issue and couldn't.

[baal2000]

The unresponsive trace app could be a victim of being overwhelmed by the sheer volume of the memory allocation-related data (--clreventlevel 5) and no known support for "sampled" collection of the memory events (likes of DotNetAllocSampled in perfview). Also mentioned in https://github.com/dotnet/diagnostics/issues/1744.

Once the memory - based providers are turned off or clreventlevel lowered to 4 then everything is back to normal. The file size becomes reasonably small, the application honours the timer setting. With the level 4 (information) though some of the useful memory allocation data is missing from the trace, that is unacceptable to our purpose.

@josalem and @sywhang To reproduce you should stress test by running the trace for a very large heap, high-allocation rate .NET Core application with clreventlevel 5 and large enough buffersize that ensures that no events are being skipped due to the buffer being overflown. And please take a look at https://github.com/dotnet/diagnostics/issues/1744.

Thank you.