Heartbeat delay #17

mladjan-gadzic · 2025-05-26T10:00:02Z

collection for ended activities is removed
OnStart adds activity to active and heartbeat delayed activities
OnEnd removes activity from active activities
heartbeat is redesigned
- when processor starts separate thread is started
- job of the thread runs every z ms
- when it runs it processes activities
  - with delayed heartbeat are moved to ready heartbeat
  - with ready heartbeat are removed from the queue, logs are pushed and put back at the beginning
added tests to cover new functionality
bumped up version
modified Example.cs to include new changes
minor syntax fixes recommended by ide
batching is to be added later

jgiannuzzi

As discussed offline, I would suggest the following change, given x as the hearbeat interval, and y as the initial delay:

use 2 queues:
- one for just started spans (OnStart)
- one for spans that sent their initial heartbeat
OnStart adds the span to the back of the "started spans" queue with an initial heartbeat time of "now + y"
have one loop that runs every z ("batch interval"? there's probably a better name for it) and starts 2 tasks:
- one looking at the queue of started spans, popping all the spans that have started y ago, sending their initial heartbeat, and adding them to the back of the heartbeat queue with their next heartbeat time (now + x)
- one looking a the queue of heartbeat spans, popping all the spans that have sent their last heartbeat x ago, sending their new heartbeat, and adding them to the back of the heartbeat queue with their new heartbeat time (now + x)
you'd probably also need to have an efficient way to remove spans from these queues by having some kind of index by span ID, so that you can remove them when they finish (OnEnd)

G-Research.OpenTelemetry.Processor.Partial/Example.cs

G-Research.OpenTelemetry.Processor.Partial/PartialActivityProcessor.cs

jgiannuzzi · 2025-05-29T14:12:45Z

G-Research.OpenTelemetry.Processor.Partial/PartialActivityProcessor.cs

+        using (_logger.Value.BeginScope(GetHeartbeatLogRecordAttributes()))
+        {
+            _logger.Value.LogInformation(
+                SpecHelper.Json(new TracesData(data, TracesData.Signal.Heartbeat)));
+        }


the whole point of this change is to not send the event before the delay!

i think we discussed that heartbeat should not be sent before the delay. i am considering "on start" event, which just coincidentally has all attributes as a heartbeat, a different event.

based on your comment below, I think you know the answer, but just to be 100% clear: the goal of the delay is to postpone sending the initial heartbeat event, so that short-lived spans do not result in any partial span log events

jgiannuzzi · 2025-05-29T14:14:05Z

G-Research.OpenTelemetry.Processor.Partial/PartialActivityProcessor.cs

+            _logger.Value.LogInformation(
+                SpecHelper.Json(new TracesData(data, TracesData.Signal.Stop)));


we should also send a stop event if we had sent an initial heartbeat - again the whole point of this change is to minimize traffic and server-side processing of short-lived spans!

same to this, i was considering "on end" separate event than heartbeat. would you like me not to send this for on start and on end?

based on your comment below, I think you know the answer, but just to be 100% clear: yes, I would like to avoid sending a stop event when no initial heartbeat event was sent - the goal is to avoid having many short-lived spans sending 3 things: a "heartbeat" log event, a "stop" log event, and a regular span/trace.

mladjan-gadzic · 2025-05-29T14:39:16Z

@jgiannuzzi thanks for correcting me. discussed this version of implementation with the team in a standup and basically what we want to achieve is that no events are emitted if span ended before first (delayed) heartbeat.

G-Research.OpenTelemetry.Processor.Partial/PartialActivityProcessor.cs

jgiannuzzi · 2025-05-30T07:26:51Z

G-Research.OpenTelemetry.Processor.Partial/PartialActivityProcessor.cs

+        var isDelayedHeartbeatPending =
+            _delayedHeartbeatActivities.Any(span => span.SpanId == data.SpanId);


this is O(n) - we should instead have a way to immediately check whether a span is delayed or not (e.g. by using 2 dictionaries: one for delayed activities and one for ready activites)

why don't we use one dictionary instead of two? we should be able to check if span is delayed with one. if span is ready we should send log because log was already sent after delay expired.

sure thing - this was just a suggestion!

swythan · 2025-05-30T15:21:03Z

G-Research.OpenTelemetry.Processor.Partial/PartialActivityProcessor.cs

+        int heartbeatIntervalMilliseconds = DefaultHeartbeatIntervalMilliseconds,
+        int initialHeartbeatDelayMilliseconds = DefaultInitialHeartbeatDelayMilliseconds,
+        int processIntervalMilliseconds = DefaultProcessIntervalMilliseconds


Would it make more sense for these to be TimeSpans? I guess you'd have to use null or TimeSpan.Zero (or similar) as the default value.

Suggested change

int heartbeatIntervalMilliseconds = DefaultHeartbeatIntervalMilliseconds,

int initialHeartbeatDelayMilliseconds = DefaultInitialHeartbeatDelayMilliseconds,

int processIntervalMilliseconds = DefaultProcessIntervalMilliseconds

TimeSpan? heartbeatInterval = null,

TimeSpan? initialHeartbeatDelay = null,

TimeSpan? processInterval = null

i'd rather keep it as int since it aligns with other processors implementations (e.g https://github.com/open-telemetry/opentelemetry-dotnet/blob/main/src/OpenTelemetry/BatchExportProcessor.cs#L23)

swythan · 2025-05-30T15:36:38Z

G-Research.OpenTelemetry.Processor.Partial/PartialActivityProcessor.cs

-                Heartbeat();
-            }
-            catch (ObjectDisposedException)
+            while (_delayedHeartbeatActivities.TryPeek(out var activity) &&


This will only remove it from _delayedHeartbeatActivities if it's at the front of the queue, right? That doesn't seem like what we'd want.

Either we could just not remove it and look for it in _delayedHeartbeatActivitiesLookup when it comes to send the initial heartbeat, or we have to search the whole queue.

I think the first choice is probably easier/faster, as _delayedHeartbeatActivitiesLookup should (I think) be smaller than _delayedHeartbeatActivities and obviously it has the index.

from docs about TryPeek

Tries to return an object from the beginning of the ConcurrentQueue without removing it.

That's what I mean. It will only look at the item at the head of the queue.

If it matches activity.SpanId then we will remove it, and the next item obviously won't match and we'll exit the loop.

If the first item doesn't match then we'll immediately exit the loop.

There's no scenario where we'll ever check anything beyond the first two items (if I'm right).

it will try to peek item at the head of the queue and check whether it's time for a heartbeat. if it is not, that's it. if it is it will check whether that item is active and if it is it will do heartbeat and add it to the ready queue. we're not breaking the loop, but continuing to the next item. what am i missing?

That's the other loop. This is OnEnd and I think it's supposed to be removing the activity from both the lookup and the _delayedHeartbeatActivities queue (if it's there), but it looks to me like it will only remove it if it is at the head of the queue.

oh, i see, i am not iterating through it with TryPeek, but just getting the first one all the time. i'll see what i can do

swythan · 2025-06-02T12:03:06Z

G-Research.OpenTelemetry.Processor.Partial/PartialActivityProcessor.cs

+        while (_delayedHeartbeatActivities.TryPeek(out var span) &&
+               span.InitialHeartbeatTime <= DateTime.UtcNow)
+        {
+            _delayedHeartbeatActivitiesLookup.TryRemove(span.SpanId, out _);
+            _delayedHeartbeatActivities.TryDequeue(out span);


Might there be a race condition here if the span from TryPeek(out var span) has been removed from the queue before the TryDequeue(out span)?

The first thing to do would be swap the order so that at least the TryRemove(span.SpanId, out _) removes the right span from the lookup. I think it might still be possible that this might send something before its InitialHeartbeatTime though.

this might be the issue because removal from _delayedHeartbeatActivities within OnEnd method can happen after peek within ProcessDelayedHeartbeatActivities method. what i can think of is to synchronize these with locks. what do you think?

something like this 22f3568?

Seeing as we have two collections in play (the lookup and the queue) we probably have to go with locks. In that case I'd suggest using them everywhere and just use normal collections rather than the concurrent ones.

When performing an operation on both lists, put the lock around both operations.

mladjan-gadzic added 2 commits May 26, 2025 11:49

add heartbeat delay

090bf3e

bump up version

dbca579

mladjan-gadzic linked an issue May 26, 2025 that may be closed by this pull request

Add a delay before the initial heartbeat for a span is sent #12

Closed

mladjan-gadzic requested review from swythan and jgiannuzzi May 26, 2025 10:00

jgiannuzzi reviewed May 28, 2025

View reviewed changes

G-Research.OpenTelemetry.Processor.Partial/Example.cs Outdated Show resolved Hide resolved

mladjan-gadzic added 11 commits May 29, 2025 09:23

use parameter name for consistency

7da664c

modify example

084c900

reimplement delay

e129cc0

fix tests

dabfd98

use more intuitive naming and fix lint warnings

c5453a8

fix test flakiness

310165e

fix naming

33e585e

fix error messages

3703e58

fix ci tests flakiness

b171859

fix naming

7958687

fix flakiness

f5021ba

jgiannuzzi reviewed May 29, 2025

View reviewed changes

G-Research.OpenTelemetry.Processor.Partial/PartialActivityProcessor.cs Outdated Show resolved Hide resolved

mladjan-gadzic added 2 commits May 29, 2025 13:19

push log before enqueuing to ready heartbeat activities

f0c4e5a

fix build errors on windows

f7ca468

jgiannuzzi reviewed May 29, 2025

View reviewed changes

mladjan-gadzic added 2 commits May 29, 2025 23:24

do not send any log before initial heartbeat is sent after delay

2b08048

fix flakiness

d10ccd5

jgiannuzzi reviewed May 30, 2025

View reviewed changes

mladjan-gadzic added 3 commits May 30, 2025 10:15

use inverted if statement for better readability

8916443

use dictionary for quick lookup of activities with delayed heartbeat

9c6421a

remove activity from active activities on end as a first step

ec2a14d

jgiannuzzi approved these changes May 30, 2025

View reviewed changes

mladjan-gadzic merged commit 1a44326 into main Jun 2, 2025
18 checks passed

mladjan-gadzic deleted the opd-12 branch June 2, 2025 10:26

swythan reviewed Jun 2, 2025

View reviewed changes

mladjan-gadzic mentioned this pull request Jun 3, 2025

Fix synchronize access to delayed heartbeat activities #18

Merged

		_logger.Value.LogInformation(
		SpecHelper.Json(new TracesData(data, TracesData.Signal.Stop)));

		var isDelayedHeartbeatPending =
		_delayedHeartbeatActivities.Any(span => span.SpanId == data.SpanId);

Heartbeat delay #17

Heartbeat delay #17

Uh oh!

Conversation

mladjan-gadzic commented May 26, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

jgiannuzzi left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

mladjan-gadzic commented May 29, 2025

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

mladjan-gadzic Jun 2, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

mladjan-gadzic commented May 26, 2025 •

edited

Loading

mladjan-gadzic Jun 2, 2025 •

edited

Loading