Strange events from System.Runtime EventCounters under Linux #56695
Comments
dotnet-issue-labeler
bot
added
the
untriaged
|
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. |
|
Tagging subscribers to this area: @tarekgh, @tommcdon, @pjanotti Issue DetailsHi. I wrote a small program to demonstrate this behavior: using System;
using System.Collections.Generic;
using System.Diagnostics.Tracing;
namespace EventCountersProblem
{
class Program
{
static void Main(string[] args)
{
var eventListener = new CpuTimeEventListener();
Console.WriteLine("Press enter for exit");
Console.ReadLine();
GC.KeepAlive(eventListener);
}
}
public class CpuTimeEventListener : EventListener
{
private readonly EventLevel _level = EventLevel.Verbose;
protected override void OnEventSourceCreated(EventSource source)
{
if (source.Name.Equals("System.Runtime"))
{
var refreshInterval = new Dictionary<string, string>();
refreshInterval.Add("EventCounterIntervalSec", "5");
EnableEvents(source, _level, (EventKeywords)(-1), refreshInterval);
}
}
protected override void OnEventWritten(EventWrittenEventArgs eventData)
{
if (eventData.EventName.Equals("EventCounters"))
{
for (int i = 0; i < eventData.Payload.Count; i++)
{
IDictionary<string, object> eventPayload = eventData.Payload[i] as IDictionary<string, object>;
if (eventPayload != null)
{
if (eventPayload["Name"] == "cpu-usage")
{
Console.WriteLine($"{DateTime.Now}:");
foreach (var ep in eventPayload)
{
Console.WriteLine($"{ep.Key}: {ep.Value}");
}
Console.WriteLine("=========");
}
}
}
}
}
}
}<Project Sdk="Microsoft.NET.Sdk">
<PropertyGroup>
<OutputType>Exe</OutputType>
<TargetFramework>net5.0</TargetFramework>
</PropertyGroup>
</Project>
This project is published as a self-contained application: dotnet publish -f net5.0 -r linux-x64 -c ReleaseBelow is the output of the program when working under Windows: Everything is correct here, one event every 5 seconds with the correct value. Below is the output of the program when running under Linux Centos (CentOS Linux release 7.4.1708 (Core)): Here we see that two events are generated in a 5 second interval. In the first event, the correct value. In the second event, the value is incorrect (24% and 35% of cpu-usage). Please tell me what could be the reason for this behavior? Is this a bug? Is this related to #53836? Thanks in advance for your reply. p.s.
|
I think your intuition is probably correct, though I'm not sure why that change would cause that behavior. On a quick glance, the new logic should be doing exactly what the old logic did and can't increment the timestamp by anything other than a multiple of the interval (due to the |
|
@josalem I also tested the work of the application built in SDK 5.0.301. No problems observed. My test program output: The problem has been observed since SDK version 5.0.302. If necessary, I can provide more technical information about the environment or carry out the necessary checks on other SDKs. |
|
I think I've worked out what happened. The new logic: TimeSpan delta = now - _nextPollingTimeStamp;
if (delta > TimeSpan.Zero && _pollingIntervalInMilliseconds > 0)
_nextPollingTimeStamp += TimeSpan.FromMilliseconds(_pollingIntervalInMilliseconds * Math.Ceiling(delta.TotalMilliseconds / _pollingIntervalInMilliseconds));can have wonky behavior if the sleep in
A fix would be to switch to the following: private const TimeSpan MinimumPollingInterval = TimeSpan.FromSeconds(1);
// ...
TimeSpan delta = now - _nextPollingTimeStamp;
delta = MinimumPollingInterval > delta ? MinimumPollingInterval : delta;
if (_pollingIntervalInMilliseconds > 0)
_nextPollingTimeStamp += TimeSpan.FromMilliseconds(_pollingIntervalInMilliseconds * Math.Ceiling(delta.TotalMilliseconds / _pollingIntervalInMilliseconds));The I need to do some more testing to be sure, but I believe this is the case. If this is true, we'll need to backport the fix to 5.0 and 3.1 since this snippet was backported all the way back. CC @dotnet/dotnet-diag |
* prevent a negative delta value
ghost
added
the
in-pr
* Fix #56695 * prevent a negative delta value * PR feedback + bug fix * bug fix is preexisting: if a user other than the one who is listening sets the interval to 0 while the counter is enabled, it makes the counter continuously submit values. Changed this so that an interval value of <= 0 results in the counter being disabled * Add assert after offline conversation
ghost
removed
the
in-pr
|
Reopening for servicing ports. |
|
The original issue was for .net5. It has been fixed in .net6 already. We should consider back porting it to .net5 at least. |
* Fix dotnet#56695 * prevent a negative delta value * PR feedback + bug fix * bug fix is preexisting: if a user other than the one who is listening sets the interval to 0 while the counter is enabled, it makes the counter continuously submit values. Changed this so that an interval value of <= 0 results in the counter being disabled * Add assert after offline conversation
|
With support for .net5 ending in May, I'm not sure it is worth the effort to backport this change. I can be convinced otherwise, though. For now, I'll close this. |
ghost
locked as resolved and limited conversation to collaborators
* Fix dotnet#56695 * prevent a negative delta value * PR feedback + bug fix * bug fix is preexisting: if a user other than the one who is listening sets the interval to 0 while the counter is enabled, it makes the counter continuously submit values. Changed this so that an interval value of <= 0 results in the counter being disabled * Add assert after offline conversation
Hi.
After migrating from .net 5 sdk 5.0.101 to net 5 sdk 5.0.302, I noticed strange behavior in System.Runtime EventCounters under Linux. It's about the "cpu-usage" counter. I began to receive two events in the required time interval. Moreover, in the second event, the value is clearly incorrect.
I wrote a small program to demonstrate this behavior:
This project is published as a self-contained application:
Below is the output of the program when working under Windows:
Everything is correct here, one event every 5 seconds with the correct value.
Below is the output of the program when running under Linux Centos (CentOS Linux release 7.4.1708 (Core)):
(When run in wsl2 (ubuntu or centos), the behavior is the same)
Here we see that two events are generated in a 5 second interval. In the first event, the correct value. In the second event, the value is incorrect (24% and 35% of cpu-usage).
The second event has a similarly strange meaning in IntervalSec field.
Please tell me what could be the reason for this behavior? Is this a bug? Is this related to #53836?
Thanks in advance for your reply.
p.s.
My dotnet --info output below:
The text was updated successfully, but these errors were encountered: