Extend NIOEventLoopTickInfo with end-time and loop sleep time

Motivation:

NIO’s event loop can emit metrics. Currently, this includes the start time (i.e. when the loop started working) and the number of tasks which were executed in that tick.

It would be useful to collect the time the loop tick ended and the length of time the loop was asleep before starting the tick.

Modifications:

The event loop has a new property to track the time between runs. The tick info collects two new values:
* The time since the last run.
* The time the loop finished.

Result:

The new metrics are available for collection.

Author: josephnoir

Sources/NIOPosix/SelectableEventLoop.swift

@@ -53,13 +53,25 @@ public struct NIOEventLoopTickInfo: Sendable, Hashable {
     public var eventLoopID: ObjectIdentifier
     /// The number of tasks which were executed in this tick
     public var numberOfTasks: Int
+    /// The time the event loop slept since the last tick
+    public var sleepTime: TimeAmount
     /// The time at which the tick began
     public var startTime: NIODeadline
+    /// The time at which the tick finished
+    public var endTime: NIODeadline
 
-    internal init(eventLoopID: ObjectIdentifier, numberOfTasks: Int, startTime: NIODeadline) {
+    internal init(
+        eventLoopID: ObjectIdentifier,
+        numberOfTasks: Int,
+        sleepTime: TimeAmount,
+        startTime: NIODeadline,
+        endTime: NIODeadline
+    ) {
         self.eventLoopID = eventLoopID
         self.numberOfTasks = numberOfTasks
+        self.sleepTime = sleepTime
         self.startTime = startTime
+        self.endTime = endTime
     }
 }
 
@@ -169,6 +181,8 @@ internal final class SelectableEventLoop: EventLoop, @unchecked Sendable {
 
     private let metricsDelegate: (any NIOEventLoopMetricsDelegate)?
 
+    private var lastTickEndTime: NIODeadline
+
     @usableFromInline
     internal func _promiseCreated(futureIdentifier: _NIOEventLoopFutureIdentifier, file: StaticString, line: UInt) {
         precondition(_isDebugAssertConfiguration())
@@ -246,6 +260,7 @@ internal final class SelectableEventLoop: EventLoop, @unchecked Sendable {
         self.msgBufferPool = Pool<PooledMsgBuffer>(maxSize: 16)
         self.tasksCopy.reserveCapacity(Self.tasksCopyBatchSize)
         self.canBeShutdownIndividually = canBeShutdownIndividually
+        self.lastTickEndTime = .now()
         // note: We are creating a reference cycle here that we'll break when shutting the SelectableEventLoop down.
         // note: We have to create the promise and complete it because otherwise we'll hit a loop in `makeSucceededFuture`. This is
         //       fairly dumb, but it's the only option we have.
@@ -722,14 +737,19 @@ internal final class SelectableEventLoop: EventLoop, @unchecked Sendable {
 
     private func runLoop(selfIdentifier: ObjectIdentifier) -> NIODeadline? {
         let tickStartTime: NIODeadline = .now()
+        let sleepTime: TimeAmount = tickStartTime - self.lastTickEndTime
         var tasksProcessedInTick = 0
         defer {
+            let tickEndTime: NIODeadline = .now()
             let tickInfo = NIOEventLoopTickInfo(
                 eventLoopID: selfIdentifier,
                 numberOfTasks: tasksProcessedInTick,
-                startTime: tickStartTime
+                sleepTime: sleepTime,
+                startTime: tickStartTime,
+                endTime: tickEndTime
             )
             self.metricsDelegate?.processedTick(info: tickInfo)
+            self.lastTickEndTime = tickEndTime
         }
         while true {
             let nextReadyDeadline = self._tasksLock.withLock { () -> NIODeadline? in

Tests/NIOPosixTests/EventLoopMetricsDelegateTests.swift

@@ -49,22 +49,36 @@ final class EventLoopMetricsDelegateTests: XCTestCase {
         XCTAssertEqual(delegate.infos.count, 0)
 
         let promise = el.makePromise(of: Void.self)
+        el.scheduleTask(in: .milliseconds(100)) {
+            // Nop. Ensures that we collect multiple tick infos.
+        }
         el.scheduleTask(in: .seconds(1)) {
             promise.succeed()
         }
+
         promise.futureResult.whenSuccess {
-            // There are 3 tasks (scheduleTask, whenSuccess, wait) which can trigger a total of 1...3 ticks
-            XCTAssertTrue((1...3).contains(delegate.infos.count), "Expected 1...3 ticks, got \(delegate.infos.count)")
-            // the total number of tasks across these ticks should be either 2 or 3
+            // There are 4 tasks (scheduleTask, scheduleTask, whenSuccess, wait) which can trigger a total of 2...4 ticks
+            XCTAssertTrue((2...4).contains(delegate.infos.count), "Expected 2...4 ticks, got \(delegate.infos.count)")
+            // The total number of tasks across these ticks should be either 2 or 3
             let totalTasks = delegate.infos.map { $0.numberOfTasks }.reduce(0, { $0 + $1 })
-            XCTAssertTrue((2...3).contains(totalTasks), "Expected 2...3 tasks, got \(totalTasks)")
+            XCTAssertTrue((3...4).contains(totalTasks), "Expected 3...4 tasks, got \(totalTasks)")
+            // All tasks were run by the same event loop. The measurements are monotonically increasing.
+            var lastEndTime: NIODeadline?
             for info in delegate.infos {
                 XCTAssertEqual(info.eventLoopID, ObjectIdentifier(el))
+                XCTAssertTrue(info.startTime < info.endTime)
+                // If this is not the first tick, verify the sleep time.
+                if let lastEndTime {
+                    XCTAssertTrue(lastEndTime < info.startTime)
+                    XCTAssertEqual(lastEndTime + info.sleepTime, info.startTime)
+                }
+                // Keep track of the last event time to verify the sleep interval.
+                lastEndTime = info.endTime
             }
             if let lastTickStartTime = delegate.infos.last?.startTime {
                 let timeSinceStart = lastTickStartTime - testStartTime
-                // This should be near instant, limiting to 100ms
-                XCTAssertLessThan(timeSinceStart.nanoseconds, 100_000_000)
+                // This should be near instantly after the delay of the first run.
+                XCTAssertLessThan(timeSinceStart.nanoseconds, 200_000_000)
                 XCTAssertGreaterThan(timeSinceStart.nanoseconds, 0)
             }
         }