PubSub - WriterGroup publishing time is drifting

[nilsv-abb]

Type of issue

• Bug
• Enhancement
• Compliance
• Question
• Help wanted

Current Behavior

We have implemented a simple publisher using the PubSub NuGet package. A WriterGroup is configured with a Publishing Interval of 1000ms, but the actual (runtime) interval will be slightly larger so the publishing time will start to drift.

This log, with entries from Opc.Ua.PubSub.UaPublisher_PublishMessages(), shows that the millisecond part of the publishing time has drifted from 531ms to 737ms (13:36:05.531 vs 13:36:25.737) after 20s:

[2024-08-29 13:36:05.531 INF] UaPublisher - PublishNetworkMessage, WriterGroupId:1; success = True [Opc.Ua]
[2024-08-29 13:36:06.543 INF] UaPublisher - PublishNetworkMessage, WriterGroupId:1; success = True [Opc.Ua]
[2024-08-29 13:36:07.557 INF] UaPublisher - PublishNetworkMessage, WriterGroupId:1; success = True [Opc.Ua]
[2024-08-29 13:36:08.557 INF] UaPublisher - PublishNetworkMessage, WriterGroupId:1; success = True [Opc.Ua]
[2024-08-29 13:36:09.585 INF] UaPublisher - PublishNetworkMessage, WriterGroupId:1; success = True [Opc.Ua]
[2024-08-29 13:36:10.589 INF] UaPublisher - PublishNetworkMessage, WriterGroupId:1; success = True [Opc.Ua]
[2024-08-29 13:36:11.602 INF] UaPublisher - PublishNetworkMessage, WriterGroupId:1; success = True [Opc.Ua]
[2024-08-29 13:36:12.602 INF] UaPublisher - PublishNetworkMessage, WriterGroupId:1; success = True [Opc.Ua]
[2024-08-29 13:36:13.614 INF] UaPublisher - PublishNetworkMessage, WriterGroupId:1; success = True [Opc.Ua]
[2024-08-29 13:36:14.626 INF] UaPublisher - PublishNetworkMessage, WriterGroupId:1; success = True [Opc.Ua]
[2024-08-29 13:36:15.640 INF] UaPublisher - PublishNetworkMessage, WriterGroupId:1; success = True [Opc.Ua]
[2024-08-29 13:36:16.654 INF] UaPublisher - PublishNetworkMessage, WriterGroupId:1; success = True [Opc.Ua]
[2024-08-29 13:36:17.669 INF] UaPublisher - PublishNetworkMessage, WriterGroupId:1; success = True [Opc.Ua]
[2024-08-29 13:36:18.679 INF] UaPublisher - PublishNetworkMessage, WriterGroupId:1; success = True [Opc.Ua]
[2024-08-29 13:36:19.681 INF] UaPublisher - PublishNetworkMessage, WriterGroupId:1; success = True [Opc.Ua]
[2024-08-29 13:36:20.694 INF] UaPublisher - PublishNetworkMessage, WriterGroupId:1; success = True [Opc.Ua]
[2024-08-29 13:36:21.715 INF] UaPublisher - PublishNetworkMessage, WriterGroupId:1; success = True [Opc.Ua]
[2024-08-29 13:36:22.727 INF] UaPublisher - PublishNetworkMessage, WriterGroupId:1; success = True [Opc.Ua]
[2024-08-29 13:36:23.733 INF] UaPublisher - PublishNetworkMessage, WriterGroupId:1; success = True [Opc.Ua]
[2024-08-29 13:36:24.734 INF] UaPublisher - PublishNetworkMessage, WriterGroupId:1; success = True [Opc.Ua]
[2024-08-29 13:36:25.737 INF] UaPublisher - PublishNetworkMessage, WriterGroupId:1; success = True [Opc.Ua]

Expected Behavior

The millisecond part of each publishing time should not be drifting, keeping the interval between publishing times constant.

Steps To Reproduce

No response

Environment

- OS: Windows 11
- Environment: Visual Studio 2022
- Runtime: .NET 8.0
- Nuget Version: 1.5.373.121-beta
- Component: Opc.Ua.PubSub
- Server:
- Client:

Anything else?

Changing how m_nextPublishTime is calculated fixes the problem, see "Old code" and "New code" comments below :

IntervalRunner.cs

    private async Task ProcessAsync()
    {
        do
        {
            int sleepCycle = 0;
            DateTime now = DateTime.UtcNow;
            DateTime nextPublishTime = DateTime.MinValue;

            lock (m_lock)
            {
                sleepCycle = Convert.ToInt32(m_interval);

                nextPublishTime = m_nextPublishTime;
            }

            if (nextPublishTime > now)
            {
                sleepCycle = (int)Math.Min((nextPublishTime - now).TotalMilliseconds, sleepCycle);
                sleepCycle = (int)Math.Max(kMinInterval, sleepCycle);
                await Task.Delay(TimeSpan.FromMilliseconds(sleepCycle), m_cancellationToken.Token).ConfigureAwait(false);
            }

            lock (m_lock)
            {
                var nextCycle = Convert.ToInt32(m_interval);

                // Old code
                // m_nextPublishTime = DateTime.UtcNow.AddMilliseconds(nextCycle);

                // New code
                m_nextPublishTime = m_nextPublishTime == DateTime.MinValue
                    ? DateTime.UtcNow.AddMilliseconds(nextCycle)
                    : m_nextPublishTime.AddMilliseconds(nextCycle);

                if (IntervalAction != null && CanExecuteFunc != null && CanExecuteFunc())
                {
                    // call on a new thread
                    Task.Run(() => {
                        IntervalAction();
                    });
                }
            }
        }
        while (true);
    }

[mrsuciu]

@nilsv-abb Good catch. The issue you describe stems from the usage of the System clock in time calculations.
Such code is always prone to time drifts. A better solution would be not to use DateTime.UtcNow at all.

[mregen]

@mrsuciu could you use a PeriodicTimer instead?