fix: gather metric samples at profile start/end

CHANGELOG.md

@@ -8,6 +8,7 @@
 - Privacy manifest collection purposes type (#3276)
 - Fix how profiles were identified in the backend for grouping and issue correlation purposes (#3282)
 - Ensure GPU frame data is always sent with profiles even if `enableAutoPerformanceTracing` is `NO` (#3273)
+- Gather metric readings fully covering the duration of a profile (#3272)
 
 ### Features
 

SentryTestUtils/TestDispatchSourceWrapper.swift

@@ -10,6 +10,7 @@ public class TestDispatchSourceWrapper: SentryDispatchSourceWrapper {
     public init(eventHandler: @escaping () -> Void) {
         self.overrides.eventHandler = eventHandler
         super.init()
+        eventHandler() // SentryDispatchSourceWrapper constructs a timer so that it fires with no initial delay
     }
 
     public override func cancel() {

Sources/Sentry/SentryDispatchSourceWrapper.m

@@ -15,8 +15,7 @@ - (instancetype)initTimerWithInterval:(uint64_t)interval
         _queueWrapper = queueWrapper;
         _source = dispatch_source_create(DISPATCH_SOURCE_TYPE_TIMER, 0, 0, queueWrapper.queue);
         dispatch_source_set_event_handler(_source, eventHandler);
-        dispatch_source_set_timer(
-            _source, dispatch_time(DISPATCH_TIME_NOW, interval), interval, leeway);
+        dispatch_source_set_timer(_source, dispatch_time(DISPATCH_TIME_NOW, 0), interval, leeway);
         dispatch_resume(_source);
     }
     return self;

Sources/Sentry/SentryMetricProfiler.mm

@@ -108,6 +108,14 @@ - (void)start
     [self registerSampler];
 }
 
+- (void)recordMetrics
+{
+    SENTRY_LOG_DEBUG(@"Recording profiling metrics sample");
+    [self recordCPUsage];
+    [self recordMemoryFootprint];
+    [self recordEnergyUsageEstimate];
+}
+
 - (void)stop
 {
     [_dispatchSource cancel];
@@ -159,11 +167,7 @@ - (void)registerSampler
                  queueName:"io.sentry.metric-profiler"
                 attributes:dispatch_queue_attr_make_with_qos_class(
                                DISPATCH_QUEUE_CONCURRENT, QOS_CLASS_UTILITY, 0)
-              eventHandler:^{
-                  [weakSelf recordCPUsage];
-                  [weakSelf recordMemoryFootprint];
-                  [weakSelf recordEnergyUsageEstimate];
-              }];
+              eventHandler:^{ [weakSelf recordMetrics]; }];
 }
 
 - (void)recordMemoryFootprint

Sources/Sentry/SentryProfiler.mm

@@ -328,6 +328,8 @@ + (void)startWithTracer:(SentryId *)traceId
     if (_gCurrentProfiler && [_gCurrentProfiler isRunning]) {
         SENTRY_LOG_DEBUG(@"A profiler is already running.");
         trackProfilerForTracer(_gCurrentProfiler, traceId);
+        // record a new metric sample for every concurrent span start
+        [_gCurrentProfiler->_metricProfiler recordMetrics];
         return;
     }
 
@@ -346,6 +348,15 @@ + (BOOL)isCurrentlyProfiling
     return [_gCurrentProfiler isRunning];
 }
 
++ (void)recordMetrics
+{
+    std::lock_guard<std::mutex> l(_gProfilerLock);
+    if (_gCurrentProfiler == nil) {
+        return;
+    }
+    [_gCurrentProfiler->_metricProfiler recordMetrics];
+}
+
 + (nullable SentryEnvelopeItem *)createProfilingEnvelopeItemForTransaction:
     (SentryTransaction *)transaction
 {

Sources/Sentry/SentryTracer.m

@@ -599,6 +599,9 @@ - (SentryTransaction *)toTransaction
     transaction.transaction = self.transactionContext.name;
 #if SENTRY_TARGET_PROFILING_SUPPORTED
     transaction.startSystemTime = self.startSystemTime;
+    if (self.isProfiling) {
+        [SentryProfiler recordMetrics];
+    }
     transaction.endSystemTime = SentryDependencyContainer.sharedInstance.dateProvider.systemTime;
 #endif // SENTRY_TARGET_PROFILING_SUPPORTED
 

Sources/Sentry/include/SentryMetricProfiler.h

@@ -42,6 +42,8 @@ typedef NSDictionary<NSString *, id /* <NSString, NSArray<SentrySerializedMetric
 @interface SentryMetricProfiler : NSObject
 
 - (void)start;
+/** Record a metrics sample. Helps ensure full metric coverage for concurrent spans. */
+- (void)recordMetrics;
 - (void)stop;
 
 /**

Sources/Sentry/include/SentryProfiler.h

@@ -64,6 +64,12 @@ SENTRY_EXTERN_C_END
  */
 + (BOOL)isCurrentlyProfiling;
 
+/**
+ * Immediately record a sample of profiling metrics. Helps get full coverage of concurrent spans
+ * when they're ended.
+ */
++ (void)recordMetrics;
+
 /**
  * Given a transaction, return an envelope item containing any corresponding profile data to be
  * attached to the transaction envelope.

Tests/SentryProfilerTests/SentryProfilerSwiftTests.swift

@@ -205,6 +205,11 @@ class SentryProfilerSwiftTests: XCTestCase {
             systemWrapper.overrides.memoryFootprintError = NSError(domain: "test-error", code: 1)
             systemWrapper.overrides.cpuEnergyUsageError = NSError(domain: "test-error", code: 2)
             metricTimerFactory?.fire()
+
+            // clear out errors for the profile end sample collection
+            systemWrapper.overrides.cpuUsageError = nil
+            systemWrapper.overrides.memoryFootprintError = nil
+            systemWrapper.overrides.cpuEnergyUsageError = nil
         }
 
         // app start simulation
@@ -255,7 +260,7 @@ class SentryProfilerSwiftTests: XCTestCase {
         try fixture.gatherMockedMetrics(span: span)
         self.fixture.currentDateProvider.advanceBy(nanoseconds: 1.toNanoSeconds())
         span.finish()
-        try self.assertMetricsPayload()
+        try self.assertMetricsPayload(expectedUsageReadings: fixture.mockUsageReadingsPerBatch + 2) // including one sample at the start and the end
     }
 
     func testConcurrentProfilingTransactions() throws {
@@ -267,7 +272,12 @@ class SentryProfilerSwiftTests: XCTestCase {
             XCTAssertEqual(SentryProfiler.currentProfiledTracers(), UInt(0))
 
             for i in 0 ..< numberOfTransactions {
+                print("creating new concurrent transaction for test")
                 let span = try fixture.newTransaction()
+
+                // because energy readings are computed as the difference between sequential cumulative readings, we must increment the mock value by the expected result each iteration
+                fixture.systemWrapper.overrides.cpuEnergyUsage = NSNumber(value: fixture.systemWrapper.overrides.cpuEnergyUsage!.intValue + fixture.mockEnergyUsage.intValue)
+
                 XCTAssertTrue(SentryProfiler.isCurrentlyProfiling())
                 XCTAssertEqual(SentryProfiler.currentProfiledTracers(), UInt(i + 1))
                 spans.append(span)
@@ -280,10 +290,16 @@ class SentryProfilerSwiftTests: XCTestCase {
                 try fixture.gatherMockedMetrics(span: span)
                 XCTAssertTrue(SentryProfiler.isCurrentlyProfiling())
                 span.finish()
-                XCTAssertEqual(SentryProfiler.currentProfiledTracers(), UInt(numberOfTransactions - i - 1))
+                XCTAssertEqual(SentryProfiler.currentProfiledTracers(), UInt(numberOfTransactions - (i + 1)))
 
                 try self.assertValidProfileData()
-                try self.assertMetricsPayload(metricsBatches: i + 1)
+
+                // this is a complicated number to come up with, see the explanation for each part...
+                let expectedUsageReadings = fixture.mockUsageReadingsPerBatch * (i + 1) // since we fire mock metrics readings for each concurrent span,
+                                                                                        // we need to accumulate across the number of spans each iteration
+                    + numberOfTransactions // and then, add the number of spans that were created to account for the start reading for each span
+                    + 1 // and the end reading for this span
+                try self.assertMetricsPayload(expectedUsageReadings: expectedUsageReadings, oneLessEnergyReading: i == 0)
             }
 
             XCTAssertFalse(SentryProfiler.isCurrentlyProfiling())
@@ -594,20 +610,19 @@ private extension SentryProfilerSwiftTests {
         try self.assertValidProfileData(transactionEnvironment: transactionEnvironment, shouldTimeout: shouldTimeOut)
     }
 
-    func assertMetricsPayload(metricsBatches: Int = 1) throws {
+    func assertMetricsPayload(expectedUsageReadings: Int, oneLessEnergyReading: Bool = true) throws {
         let profileData = try self.getLatestProfileData()
         let transaction = try getLatestTransaction()
         let profile = try XCTUnwrap(JSONSerialization.jsonObject(with: profileData) as? [String: Any])
         let measurements = try XCTUnwrap(profile["measurements"] as? [String: Any])
 
-        let expectedUsageReadings = fixture.mockUsageReadingsPerBatch * metricsBatches
-
         try assertMetricValue(measurements: measurements, key: kSentryMetricProfilerSerializationKeyCPUUsage, numberOfReadings: expectedUsageReadings, expectedValue: fixture.mockCPUUsage, transaction: transaction, expectedUnits: kSentryMetricProfilerSerializationUnitPercentage)
 
         try assertMetricValue(measurements: measurements, key: kSentryMetricProfilerSerializationKeyMemoryFootprint, numberOfReadings: expectedUsageReadings, expectedValue: fixture.mockMemoryFootprint, transaction: transaction, expectedUnits: kSentryMetricProfilerSerializationUnitBytes)
 
-        // we wind up with one less energy reading. since we must use the difference between readings to get actual values, the first one is only the baseline reading.
-        try assertMetricValue(measurements: measurements, key: kSentryMetricProfilerSerializationKeyCPUEnergyUsage, numberOfReadings: expectedUsageReadings - 1, expectedValue: fixture.mockEnergyUsage, transaction: transaction, expectedUnits: kSentryMetricProfilerSerializationUnitNanoJoules)
+        // we wind up with one less energy reading for the first concurrent span's metric sample. since we must use the difference between readings to get actual values, the first one is only the baseline reading.
+        let expectedEnergyReadings = oneLessEnergyReading ? expectedUsageReadings - 1 : expectedUsageReadings
+        try assertMetricValue(measurements: measurements, key: kSentryMetricProfilerSerializationKeyCPUEnergyUsage, numberOfReadings: expectedEnergyReadings, expectedValue: fixture.mockEnergyUsage, transaction: transaction, expectedUnits: kSentryMetricProfilerSerializationUnitNanoJoules)
 
 #if !os(macOS)
         try assertMetricEntries(measurements: measurements, key: kSentryProfilerSerializationKeySlowFrameRenders, expectedEntries: fixture.expectedSlowFrames, transaction: transaction)
@@ -660,7 +675,7 @@ private extension SentryProfilerSwiftTests {
         XCTAssertEqual(values.count, numberOfReadings, "Wrong number of values under \(key)")
 
         if let expectedValue = expectedValue {
-            let actualValue = try XCTUnwrap(values[0]["value"] as? T)
+            let actualValue = try XCTUnwrap(values[1]["value"] as? T)
             XCTAssertEqual(actualValue, expectedValue, "Wrong value for \(key)")
 
             let timestamp = try XCTUnwrap(values[0]["elapsed_since_start_ns"] as? NSString)