Incorrect span duration

[Gareth]

Hi. I've noticed that the .NET agent is not able to measure span durations less than 16ms on my server. It either reports 0us or 16ms, nothing in between. The exception are spans for SQL calls which go to us precision.

I’ve experimented and setting the timer resolution to 1ms using timeBeginPeriod makes a difference but it still won’t record things to us precision. Also, setting this affects everything on the server which I don’t want to do.

I’ve had a look at the source for the .NET client and I think the sql client is using Stopwatch to measure the span duration but everything else is using DateTime.UtcNow() however I may be looking on the wrong place.

Am I correct or have I misconfigured something?

Cheers

Gareth

[GregKalapos]

Hi @Gareth

but everything else is using DateTime.UtcNow() however I may be looking on the wrong place.

That is correct - by default the agent uses DateTime.UtcNow() to measure duration. The exception is when a library (or the user) passes the duration to the agent.

The resolution you are able to achieve will be dependent on the machine where you run the agent - I'm very surprised by the 16ms - it's either some super strange setup or a super old machine.

Here is a test from a 4 year old macbook that I type this massage on:

Sample code:

Console.WriteLine(TimeSpan.FromTicks(1));
// Just 1 transaction as warmup (make sure everything JITted, etc)
Agent.Tracer.CaptureTransaction("Warmup", "bar", t =>
{
	t.CaptureSpan("span1", "sample", () => { Thread.Sleep(TimeSpan.FromMilliseconds(1)); });
});
Agent.Tracer.CaptureTransaction("foo", "bar", t =>
{
	t.CaptureSpan("span1", "sample", () => { Thread.Sleep(TimeSpan.FromMilliseconds(10)); });
	t.CaptureSpan("span2", "sample", () => { Thread.Sleep(TimeSpan.FromMilliseconds(5)); });
	t.CaptureSpan("span2", "sample", () => { Thread.Sleep(TimeSpan.FromMilliseconds(1)); });
	t.CaptureSpan("span2", "sample", () => { Thread.Sleep(TimeSpan.FromTicks(1)); });
});
Console.ReadKey();

(Update: I realize I call the last 3 spans "Span2" - doesn't matter - the point is we go from 10ms down to 1 tick and as you can see below, there isn't a resolution issue).

Output (TimeSpan.FromTicks(1)):

00:00:00.0000001

And here is how the trace looks:

As you can see the resolution here is well below 1ms.

So usually the timer resolution is not an issue.

[Gareth]

Hi Greg,

Thanks for coming back to me.

We're running on Windows Server 2019 servers. There's very little else on there so it's running at the default resolution.

Everything I've read online indicates that the default timer resolution for Windows is 15.625ms - a timer interrupt 64 times a second. It only changes if something on the server calls the timeBeginPeriod function.

The use of timeBeginPeriod is not recommended as it affects other systems on the server.

The SQL Agent that uses Stopwatch.GetTimestamp() gives much better resolution and using Stopwatch.GetTimestamp() doesn't have any performance issues. Is there any reason not to use that throughout.

Cheers

Gareth

[GregKalapos]

@Gareth this is a good point and it's worth a GitHub issue - I opened one: Move to Stopwatch.GetTimestamp for measuring duration · Issue #1654 · elastic/apm-agent-dotnet · GitHub

This issue is not yet scheduled and it's not a final decision, but yeah, it seems it'd be beneficial to make this change.

Thanks for bringing this up!