Additional diagnostics for .NET 6

[davidfowl]

The goal is to help customers better understand how their applications are running by adding events and counters that can give more insights and will help them debug potential performance issues. It'll also help us debug customer applications and write tools that would be able to glean insights from traces.

Runtime

• What is the thread pool configuration? Many of our customers set a high number of minimum thread pool threads to “fix” starvation. Knowing what this is relative to machine setting (working set and core count) would be useful. (tracked in Capture the thread pool min/max threads config in an event #57247)
• What app context switches are used, and what are they set to? This will tell customers what quirks are enabled (binary formatter etc.) This can be a huge aid when debugging applications. (tracked in [Feature Request]: Diagnostics for App Context switches #56142)
• What are the GC settings? Today it's sometimes difficult to tell how the GC was configured without a dump. The goal is to have an event that emits the current GC settings so customers can see what was applied. (part of PR instrumentation changes #55888)
• What was the value of Environment.ProcessorCount should be emitted in an event. I'm not sure which event is most appropriate for this (if we have an existing one) but we need a way to get the runtime settings. (tracked in [Feature Request]: Diagnostics for processor count #56143)

Networking

• How much time is spent in DNS resolution? This is a blocking operation, and we added a mitigation for this in .NET 6. We would like customers to be able to determine the time spent here using something high level like a counter or an event (Do we already have an event for this?)
  • dns-lookups-duration counter + we have the events
• How many unique DNS addresses are resolved in an application’s lifetime? In .NET 6 we added some special logic to queue DNS requests to a single host name (to avoid thread pool starvation). We assume there is a handful of these in the process. Can we add a counters so customers can get a sense of what total and unique DNS resolutions look like in their applications? (tracked in Add Dns event counters #48885)

Threading

• How many timers are one-shot, vs periodic? The Timer implementation optimizes for timers firing rarely, customers can figure out how their timer queue is behaving. Today we only collect the number of timers, but not the types of timers.
• We added a thread pool starvation mitigation feature in .NET 6 and have added events that kick in when this mechanism is being used. We should make sure we have the appropriate events here so that customers can observe how this is behaving in their systems.

ArrayPool

• How many arrays are discarded when returning to the pool? This is a measure of pooling efficiency that we’d like to help customers understand better. We have an event but we need to make sure it's efficient enough to turn on in a production environment.

Dependency Injection

• We would like to help customers better understand some statistics about registered services:
• How many singleton services?
• How many scoped services?
• How many transient services?
• How many container instances are in the processes?
• (tracked in Additional Diagnostics in Dependency Injection #56313)

similar issue in aspnetcore repo: dotnet/aspnetcore#34578

cc @danmoseley @jeffschwMSFT @jkotas @geoffkizer @stephentoub @eerhardt @kouvel @mangod9 @Maoni0

I couldn't figure out the best area label to add to this issue. If you have write-permissions please help me learn by adding exactly one area label.

[danmoseley]

@ericstj @karelz @jeffhandley

[stephentoub]

How much time is spent in DNS resolution? This is a blocking operation, and we added a mitigation for this in .NET 6. We would like customers to be able to determine the time spent here using something high level like a counter or an event (Do we already have an event for this?)

The existing dns-lookups-duration counter provides this.

How many unique DNS addresses are resolved in an application’s lifetime?

What is a developer going to do with this information? Doing this "perfectly" would be a leak, as it would require the application to maintain a set of every address it saw; that's not viable (it'd be like Kestrel having a counter for how many unique client addresses connected to it over the process' lifetime). Events are already emitted for that information, so a dev can post-process that information from traces if needed. #48885 proposes one for the number of unique addresses currently being resolved; from my perspective, that's more reasonable, though I'm not sure how actionable it actually is, either.

How many arrays are discarded when returning to the pool? This is a measure of pooling efficiency that we’d like to help customers understand better. We have an event but we need to make sure it's efficient enough to turn on in a production environment.

What is "efficient enough"? Just adding one (uncontended) interlocked operation increases the cost of renting/returning by 10%:

private long _counter;

[Benchmark(Baseline = true)]
public void RentReturn()
{
    ArrayPool<byte>.Shared.Return(ArrayPool<byte>.Shared.Rent(16));
}

[Benchmark]
public void RentReturnInterlocked()
{
    ArrayPool<byte>.Shared.Return(ArrayPool<byte>.Shared.Rent(16));
    Interlocked.Increment(ref _counter);
}

Method	Mean	Error	StdDev	Ratio
RentReturn	16.54 ns	0.051 ns	0.047 ns	1.00
RentReturnInterlocked	18.40 ns	0.132 ns	0.117 ns	1.11

and if it's contended, the difference skyrockets:

private long _counter;

[Benchmark(Baseline = true)]
public void RentReturn()
{
    Parallel.For(0, 1_000_000, i =>
    {
        ArrayPool<byte>.Shared.Return(ArrayPool<byte>.Shared.Rent(16));
    });
}

[Benchmark]
public void RentReturnInterlocked()
{
    Parallel.For(0, 1_000_000, i =>
    {
        ArrayPool<byte>.Shared.Return(ArrayPool<byte>.Shared.Rent(16));
        Interlocked.Increment(ref _counter);
    });
}

Method	Mean	Error	StdDev	Ratio
RentReturn	3.437 ms	0.0373 ms	0.0349 ms	1.00
RentReturnInterlocked	19.153 ms	0.0407 ms	0.0381 ms	5.57

Even for the uncontended case, the difference is more pronounced if you just look at such an interlocked in comparison to an allocation (since for dropped arrays, that's basically what we're talking about):

private long _counter;

[Benchmark(Baseline = true)]
public void Allocate()
{
    _ = new byte[16];
}

[Benchmark]
public void AllocateInterlocked()
{
    _ = new byte[16];
    Interlocked.Increment(ref _counter);
}

Method	Mean	Error	StdDev	Ratio
Allocate	2.697 ns	0.0289 ns	0.0270 ns	1.00
AllocateInterlocked	6.811 ns	0.0745 ns	0.0696 ns	2.53

Even a [ThreadStatic] adds measurable overhead in comparison:

[ThreadStatic]
private static long _counter;

[Benchmark(Baseline = true)]
public void Allocate()
{
    _ = new byte[16];
}

[Benchmark]
public void AllocateTS()
{
    _ = new byte[16];
    _counter++;
}

Method	Mean	Error	StdDev	Ratio
Allocate	2.658 ns	0.0399 ns	0.0373 ns	1.00
AllocateTS	6.032 ns	0.0625 ns	0.0585 ns	2.27

I added the event for dropped arrays in .NET 6 with the idea that someone can either measure it in development, or they can temporarily turn on the event for a minute in production to get a sampling of what their app is doing.

How many timers are one-shot, vs periodic? The Timer implementation optimizes for timers firing rarely, customers can figure out how their timer queue is behaving. Today we only collect the number of timers, but not the types of timers.

(It's more that it optimizes for adds/removes happening much more frequently than firings.)

What is someone going to do with information about periodic vs non-periodic?

[karelz]

@davidfowl

How many unique DNS addresses are resolved in an application’s lifetime?

I agree with @stephentoub here. Let's move the final discussion into #48885 and let's decide there if we want current vs. all-lifetime, how useful it is and if it needs to land in 6.0 vs. Future.

BTW: I updated the first Networking item with answer inline in the top post for easier tracking.

[jeffschwMSFT]

@mangod9

[jeffschwMSFT]

What app context switches are used, and what are they set to? This will tell customers what quirks are enabled (binary formatter etc.) This can be a huge aid when debugging applications.

There are more than just app context switches and should consider most configuration of NetCoreApp which also include environment and runtimeconfig.json. My hypothesis is that these are rare.

What are the GC settings? Today it's sometimes difficult to tell how the GC was configured without a dump. The goal is to have an event that emits the current GC settings so customers can see what was applied.

I presume this is referring to the various dynamically tuned configuration within the gc - budget, etc. As traces already capture the gc configuration - svr vs wks. Capturing the current set of configuration we would gather the remaining configuration details.

Runtime

I believe that all these would need to be rundown events as they are configuration and would likely fire at startup.

How many timers are one-shot, vs periodic? The Timer implementation optimizes for timers firing rarely, customers can figure out how their timer queue is behaving. Today we only collect the number of timers, but not the types of timers.

This feels like a perf counter/metric. Do we have something analogous already?

[stephentoub]

This feels like a perf counter/metric. Do we have something analogous already?

We have active-timer-count, which polls Timer.ActiveCount. That's inclusive of all timers, both periodic and non-periodic. David is suggesting splitting that to know how many are periodic and how many are non-periodic. I'd like to understand how such knowledge would be used :)

[stephentoub]

Runtime

I believe that all these would need to be rundown events as they are configuration and would likely fire at startup.

If the goal is simply to report configuration so that it's in a trace log, could we have one event / rundown component that's just a text string that includes every bit of configuration information we can muster?

[davidfowl]

There are more than just app context switches and should consider most configuration of NetCoreApp which also include environment and runtimeconfig.json. My hypothesis is that these are rare.

I'm not sure I want to group environment variables as part of the other runtime payload since it might contain PII and secrets and you may not want that to be it the same events as the other configuration.

[jeffschwMSFT]

There are more than just app context switches and should consider most configuration of NetCoreApp which also include environment and runtimeconfig.json. My hypothesis is that these are rare.

I'm not sure I want to group environment variables as part of the other runtime payload since it might contain PII and secrets and you may not want that to be it the same events as the other configuration.

Certainly not recommending the peb, but rather we have configuration that is unique to complus_/dotnet_ env variables. There are a few config systems that we could query for configuration information. App context is only 1.

[davidfowl]

Certainly not recommending the peb, but rather we have configuration that is unique to complus_/dotnet_ env variables. There are a few config systems that we could query for configuration information. App context is only 1.

I agree, lets add that to the list.