Timeout while executing StartEventPipeSession

[AT-WH]

Description

In my code I follow the instructions from the docs and create a session using this snippet:

    var providers = new List<EventPipeProvider>()
    {
        new EventPipeProvider(
            "System.Runtime",
            EventLevel.Verbose,
            (long)ClrTraceEventParser.Keywords.None,
            new Dictionary<string, string>() {
                { "EventCounterIntervalSec", "1" }
            }
        )
    };
    var client = new DiagnosticsClient(processId);
    using(var session = client.StartEventPipeSession(providers))
    {
      // ... more code
    }

In most of the cases this works, but sometimes it fails to connect to a process running on my machine (note: I verified that processId is always correct). The error message is:

EXCEPTION: System.TimeoutException: The operation has timed out.
   at System.IO.Pipes.NamedPipeClientStream.ConnectInternal(Int32 timeout, CancellationToken cancellationToken, Int32 startTime)
   at Microsoft.Diagnostics.NETCore.Client.IpcEndpointHelper.Connect(IpcEndpointConfig config, TimeSpan timeout)
   at Microsoft.Diagnostics.NETCore.Client.PidIpcEndpoint.Connect(TimeSpan timeout)
   at Microsoft.Diagnostics.NETCore.Client.IpcClient.SendMessageGetContinuation(IpcEndpoint endpoint, IpcMessage message)
   at Microsoft.Diagnostics.NETCore.Client.EventPipeSession.Start(IpcEndpoint endpoint, EventPipeSessionConfiguration config)
   at Microsoft.Diagnostics.NETCore.Client.DiagnosticsClient.StartEventPipeSession(IEnumerable`1 providers, Boolean requestRundown, Int32 circularBufferMB)

This seems to be a random issue, so I can't provide a code to reliably reproduce it. I noticed that it occurs while my CPU is heavily loaded. In my environment I try spawning ~20 .NET processes that bring CPU utilization to 90-99%.

Then sometimes I see that a call to StartEventPipeSession freezes and times out after a while.

I've also tried calling the function once again after the timeout, but the result is the same.

It looks like as if the process I want to connect to failed to initialize the Event Counters for whatever reason. Is it possible?

Configuration

> dotnet --info

.NET SDK:
 Version:           8.0.101
 Commit:            6eceda187b
 Workload version:  8.0.100-manifests.9297b15b

Runtime Environment:
 OS Name:     Windows
 OS Version:  10.0.19045
 OS Platform: Windows
 RID:         win-x64
 Base Path:   C:\Program Files\dotnet\sdk\8.0.101\

.NET workloads installed:
 Workload version: 8.0.100-manifests.9297b15b
There are no installed workloads to display.

Host:
  Version:      8.0.1
  Architecture: x64
  Commit:       bf5e279d92

.NET SDKs installed:
  6.0.201 [C:\Program Files\dotnet\sdk]
  7.0.101 [C:\Program Files\dotnet\sdk]
  7.0.404 [C:\Program Files\dotnet\sdk]
  8.0.100 [C:\Program Files\dotnet\sdk]
  8.0.101 [C:\Program Files\dotnet\sdk]

.NET runtimes installed:
  Microsoft.AspNetCore.App 5.0.17 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 6.0.3 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 6.0.26 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 7.0.1 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 7.0.14 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 7.0.15 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 8.0.0 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 8.0.1 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.NETCore.App 5.0.17 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 6.0.3 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 6.0.26 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 7.0.1 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 7.0.14 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 7.0.15 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 8.0.0 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 8.0.1 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.WindowsDesktop.App 5.0.17 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App]
  Microsoft.WindowsDesktop.App 6.0.3 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App]
  Microsoft.WindowsDesktop.App 6.0.26 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App]
  Microsoft.WindowsDesktop.App 7.0.1 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App]
  Microsoft.WindowsDesktop.App 7.0.14 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App]
  Microsoft.WindowsDesktop.App 7.0.15 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App]
  Microsoft.WindowsDesktop.App 8.0.0 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App]
  Microsoft.WindowsDesktop.App 8.0.1 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App]

Other architectures found:
  x86   [C:\Program Files (x86)\dotnet]
    registered at [HKLM\SOFTWARE\dotnet\Setup\InstalledVersions\x86\InstallLocation]

Environment variables:
  Not set

global.json file:
  Not found

Learn more:
  https://aka.ms/dotnet/info

Download .NET:
  https://aka.ms/dotnet/download

Regression?

I saw the issue from time to time in the past, but now it became more problematic, as my IT system grew and I want to keep an eye on more processes.

Other information

My processes are launched using an .exe file that has the same name for all of the processes (i.e. each process uses a separate copy of the same binaries). Previously I used Performance Counters to track the stats of my processes and I remember that using the same name messes up with Performance Counters. Is it possible that it's causing problems here as well?

[tommcdon]

@AT-WH thanks for reporting this issue. I believe there are two possible explanations for the issue:

1. The target process is either hung or stopped (e.g. a debugger is attached in break state), causing the Named Pipe to be non-responsive.
2. The machine has significant load and so the server does not start start the IPC server in time before the diagnostics client times out.

Do the target processes have the DOTNET_DiagnosticPorts environment variable set? If yes please share the config string.

Also collecting a dump of the target process at the point where we are timing out might shed light on why the diagnostics ipc thread is not responding. This would tell us if something is preventing the diagnostics IPC server from processing messages:
https://github.com/dotnet/runtime/blob/c659c6e511da37385fd0e56941fd84c34ac5171d/src/native/eventpipe/ds-server.c#L115-L116

One possible workaround might be to try modifying the default connect timeout (currently 30 seconds) though I am not confident that the problem could be eliminated using this solution (just the frequency reduced):

diagnostics/src/Microsoft.Diagnostics.NETCore.Client/DiagnosticsIpc/IpcClient.cs

Lines 15 to 16 in 5ae2a15

	internal static readonly TimeSpan ConnectTimeout = TimeSpan.FromSeconds(30);

[AT-WH]

Hi @tommcdon
Thanks for responding.

I confirm that I don't use DOTNET_DiagnosticPorts.
My machine is under very serious load and it's not uncommon that CPU utilization shows 100%, or something very close to this value.

I wonder if this is possible for a .NET process to 'decide' to skip initialization of the Event Counters in a situation of a very heavy load?

For now I switched to StartEventPipeSessionAsync and use a CancellationToken, which expires after 5 seconds. This won't solve the problem, but at least my system works in a normal way and the only drawback is that it fails to collect stats from the process.

[AT-WH]

Regarding this part

Also collecting a dump of the target process at the point where we are timing out might shed light on why the diagnostics ipc thread is not responding. This would tell us if something is preventing the diagnostics IPC server from processing messages.

Do you have a quick tutorial on how to do this? Typically I deal with 'a bit' higher level programming than this ;).

[noahfalk]

Sorry I see this issue hasn't been updated in a long time! I don't know whether this is still relevant for you but also updating in case other people encounter the same issue in the future.

I wonder if this is possible for a .NET process to 'decide' to skip initialization of the Event Counters in a situation of a very heavy load?

Although the runtime wouldn't monitor system load and decide this directly, there are various places the OS might fail or starve a thread of CPU if resource usage is high enough (which you suggested may be a factor). In particular in order for the counters to work a few things need to happen:

1. A thread servicing the diagnostic server inside the runtime needs to accept the connection request: https://github.com/dotnet/runtime/blob/main/src/native/eventpipe/ds-ipc-pal-namedpipe.c#L471
2. Processing that request will start the EventPipe session which calls into various EventSources to notify them tracing has started
3. The EventSource will invoke the EventCommandExecuted event which runs the CounterGroup.OnEventSourceCommand callback function.
4. Inside that callback a timer is enabled that in many cases tries to create a new thread.
5. That new thread is responsible for sending metric data at periodic intervals.

If you got a connection timeout then its likely step (1) never completed - perhaps because the thread that was supposed to do the work is being starved of CPU time or the OS was too resource constrained to create the thread at all.

Do you have a quick tutorial on how to do this? Typically I deal with 'a bit' higher level programming than this ;).

You can capture a dump using the createdump tool which is located in the same directory as the other runtime binaries such as libcoreclr.so. https://stackoverflow.com/questions/58213127/how-to-generate-a-reasonably-sized-memory-dump-file-of-a-net-core-process-on-li

Normally I'd point people at dotnet-dump which is better documented but that tool also sends messages to the runtime using DiagnosticClient so it will likely have the same timeout error you see with your counters.

So that you don't get your hopes up, even if you do capture a dump I'm skeptical it will quickly lead to a better solution for you. It might tell us a little more how resource starvation caused the diagnostic server to fail.

If you wanted a higher reliability reporting mechanism when the machine is under high load a couple possibilities:

1. You could use some monitoring agent that runs as a separate process (simple things like top or fancy things like paid APM products) and if needed boost its scheduling priority or set dedicated CPU quotas. You won't necessarily get all the same metrics you can get from the EventCounters, but you can get some things.
2. You could set CPU quotas for various processes on the machine (or use containers with quotas) to ensure that processes that need to do self-reporting won't get completely starved.
3. You could try creating a dedicated managed thread that will report metrics and boost its scheduling priority relative to other threads. You would need to write the code that determines how this thread calculates metrics and how it writes them. A very simple version might look like:

while(true)
{
    Thread.Sleep(10_000); // wake up every 10 seconds and report metrics
    Console.WriteLine(DateTime.Now + ": " + Process.GetCurrentProcess().UserProcessorTime);
}

Thats probably overly simplistic and a better one gets more complicated to write but its possible if you decide its worth the effort.

Hope that helps!

[dotnet-policy-service]

Hi @@AT-WH. We have added the "Needs: Author Feedback" label to this issue, which indicates that we have an open question for you before we can take further action. This issue will be closed automatically in 7 days if we do not hear back from you by then - please feel free to re-open it if you come back to this issue after that time.

[dotnet-policy-service]

This issue has been automatically marked as stale because it has been marked as requiring author feedback but has not had any activity for 4 days. It will be closed if no further activity occurs within 3 days of this comment. If it is closed, feel free to comment when you are able to provide the additional information and we will re-investigate.

[dotnet-policy-service]

Hi @@AT-WH. We are closing this issue due to inactivity. If you comment within 30 days it will automatically reopen. If you are not the author of this issue and you're facing the same problem, feel free to open a new issue referencing this one.