add lifecycle metrics

motivation: startup/shutdown metrics are important for real-life services, for example spike in start metrics indicates a crash-loop

changes:
* add start and shutdown counters to ComponentLifecycle
* add start and shutdown timers to report duration of startup and shutdown operations

Author: tomerd

Sources/Lifecycle/Lifecycle.swift

@@ -18,9 +18,9 @@ import Darwin
 import Glibc
 #endif
 import Backtrace
+import CoreMetrics
 import Dispatch
 import Logging
-import Metrics
 
 // MARK: - LifecycleTask
 
@@ -469,6 +469,8 @@ public class ComponentLifecycle: LifecycleTask {
     // MARK: - private
 
     private func _start(on queue: DispatchQueue, tasks: [LifecycleTask], callback: @escaping (Error?) -> Void) {
+        Counter(label: "\(self.label).lifecycle.start").increment()
+
         self.stateLock.withLock {
             guard case .idle = self.state else {
                 preconditionFailure("invalid state, \(self.state)")
@@ -517,7 +519,9 @@ public class ComponentLifecycle: LifecycleTask {
             return callback(index, nil)
         }
         self.log("starting tasks [\(tasks[index].label)]")
+        let startTime = DispatchTime.now()
         start { error in
+            Timer(label: "\(self.label).\(tasks[index].label).lifecycle.start").recordNanoseconds(DispatchTime.now().uptimeNanoseconds - startTime.uptimeNanoseconds)
             if let error = error {
                 self.log(level: .error, "failed to start [\(tasks[index].label)]: \(error)")
                 return callback(index, error)
@@ -531,6 +535,8 @@ public class ComponentLifecycle: LifecycleTask {
     }
 
     private func _shutdown(on queue: DispatchQueue, tasks: [LifecycleTask], callback: @escaping () -> Void) {
+        Counter(label: "\(self.label).lifecycle.shutdown").increment()
+
         self.stateLock.withLock {
             log("shutting down")
             self.state = .shuttingDown(queue)
@@ -555,8 +561,11 @@ public class ComponentLifecycle: LifecycleTask {
         if index >= tasks.count {
             return callback(errors)
         }
+
         self.log("stopping tasks [\(tasks[index].label)]")
+        let startTime = DispatchTime.now()
         shutdown { error in
+            Timer(label: "\(self.label).\(tasks[index].label).lifecycle.shutdown").recordNanoseconds(DispatchTime.now().uptimeNanoseconds - startTime.uptimeNanoseconds)
             var errors = errors
             if let error = error {
                 if errors == nil {

Tests/LifecycleTests/ComponentLifecycleTests+XCTest.swift

@@ -66,6 +66,7 @@ extension ComponentLifecycleTests {
             ("testStatefulNIO", testStatefulNIO),
             ("testStatefulNIOStartFailure", testStatefulNIOStartFailure),
             ("testStatefulNIOShutdownFailure", testStatefulNIOShutdownFailure),
+            ("testMetrics", testMetrics),
         ]
     }
 }

Tests/LifecycleTests/ComponentLifecycleTests.swift

@@ -14,6 +14,7 @@
 
 @testable import Lifecycle
 import LifecycleNIOCompat
+import Metrics
 import NIO
 import XCTest
 
@@ -1247,4 +1248,89 @@ final class ComponentLifecycleTests: XCTestCase {
 
         XCTAssertFalse(item.shutdown, "expected item to be shutdown")
     }
+
+    func testMetrics() {
+        let metrics = TestMetrics()
+        MetricsSystem.bootstrap(metrics)
+
+        let items = (0 ..< 3).map { _ in GoodItem(id: UUID().uuidString, startDelay: 0.1, shutdownDelay: 0.1) }
+        let lifecycle = ComponentLifecycle(label: "test")
+        lifecycle.register(items)
+        lifecycle.start { startError in
+            XCTAssertNil(startError, "not expecting error")
+            lifecycle.shutdown { shutdownErrors in
+                XCTAssertNil(shutdownErrors, "not expecting error")
+            }
+        }
+        lifecycle.wait()
+        XCTAssertEqual(metrics.counters["\(lifecycle.label).lifecycle.start"]?.value, 1, "expected start counter to be 1")
+        XCTAssertEqual(metrics.counters["\(lifecycle.label).lifecycle.shutdown"]?.value, 1, "expected shutdown counter to be 1")
+        items.forEach { XCTAssertGreaterThan(metrics.timers["\(lifecycle.label).\($0.label).lifecycle.shutdown"]?.value ?? 0, 0, "expected start timer to be non-zero") }
+        items.forEach { XCTAssertGreaterThan(metrics.timers["\(lifecycle.label).\($0.label).lifecycle.shutdown"]?.value ?? 0, 0, "expected shutdown timer to be non-zero") }
+    }
+}
+
+// this is not thread-safe but okay for our purposes
+class TestMetrics: MetricsFactory, RecorderHandler {
+    var counters = [String: TestCounter]()
+    var timers = [String: TestTimer]()
+
+    public init() {}
+
+    public func makeCounter(label: String, dimensions: [(String, String)]) -> CounterHandler {
+        let counter = TestCounter(label: label)
+        self.counters[label] = counter
+        return counter
+    }
+
+    public func makeRecorder(label: String, dimensions: [(String, String)], aggregate: Bool) -> RecorderHandler {
+        return self
+    }
+
+    public func makeTimer(label: String, dimensions: [(String, String)]) -> TimerHandler {
+        let timer = TestTimer(label: label)
+        self.timers[label] = timer
+        return timer
+    }
+
+    public func destroyCounter(_: CounterHandler) {}
+    public func destroyRecorder(_: RecorderHandler) {}
+    public func destroyTimer(_: TimerHandler) {}
+
+    public func record(_: Int64) {}
+    public func record(_: Double) {}
+
+    // this is not thread-safe but okay for our purposes
+    class TestCounter: CounterHandler {
+        let label: String
+        var value: Int64
+
+        init(label: String) {
+            self.label = label
+            self.value = 0
+        }
+
+        public func increment(by: Int64) {
+            self.value += by
+        }
+
+        public func reset() {
+            self.value = 0
+        }
+    }
+
+    // this is not thread-safe but okay for our purposes
+    class TestTimer: TimerHandler {
+        let label: String
+        var value: Int64
+
+        init(label: String) {
+            self.label = label
+            self.value = 0
+        }
+
+        public func recordNanoseconds(_ value: Int64) {
+            self.value = value
+        }
+    }
 }