fix: normalize timestamps relative to transaction start (#2729)

Sentry.xcodeproj/project.pbxproj

@@ -610,6 +610,7 @@
 		7DC8310A2398283C0043DD9A /* SentryCrashIntegration.h in Headers */ = {isa = PBXBuildFile; fileRef = 7DC831082398283C0043DD9A /* SentryCrashIntegration.h */; };
 		7DC8310C2398283C0043DD9A /* SentryCrashIntegration.m in Sources */ = {isa = PBXBuildFile; fileRef = 7DC831092398283C0043DD9A /* SentryCrashIntegration.m */; };
 		8419C0C428C1889D001C8259 /* SentryProfilerSwiftTests.swift in Sources */ = {isa = PBXBuildFile; fileRef = 8419C0C328C1889D001C8259 /* SentryProfilerSwiftTests.swift */; };
+		8431EE5B29ADB8EA00D8DC56 /* SentryTimeTests.m in Sources */ = {isa = PBXBuildFile; fileRef = 8431EE5A29ADB8EA00D8DC56 /* SentryTimeTests.m */; };
 		844EDC6F294143B900C86F34 /* SentryNSProcessInfoWrapper.h in Headers */ = {isa = PBXBuildFile; fileRef = 844EDC6D294143B900C86F34 /* SentryNSProcessInfoWrapper.h */; };
 		844EDC70294143B900C86F34 /* SentryNSProcessInfoWrapper.mm in Sources */ = {isa = PBXBuildFile; fileRef = 844EDC6E294143B900C86F34 /* SentryNSProcessInfoWrapper.mm */; };
 		844EDC73294144B200C86F34 /* TestSentryNSProcessInfoWrapper.swift in Sources */ = {isa = PBXBuildFile; fileRef = 844EDC712941442200C86F34 /* TestSentryNSProcessInfoWrapper.swift */; };
@@ -1449,6 +1450,7 @@
 		7DC831082398283C0043DD9A /* SentryCrashIntegration.h */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.h; name = SentryCrashIntegration.h; path = include/SentryCrashIntegration.h; sourceTree = "<group>"; };
 		7DC831092398283C0043DD9A /* SentryCrashIntegration.m */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.objc; path = SentryCrashIntegration.m; sourceTree = "<group>"; };
 		8419C0C328C1889D001C8259 /* SentryProfilerSwiftTests.swift */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.swift; path = SentryProfilerSwiftTests.swift; sourceTree = "<group>"; };
+		8431EE5A29ADB8EA00D8DC56 /* SentryTimeTests.m */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.objc; path = SentryTimeTests.m; sourceTree = "<group>"; };
 		844A34C3282B278500C6D1DF /* .github */ = {isa = PBXFileReference; lastKnownFileType = folder; path = .github; sourceTree = "<group>"; };
 		844A3563282B3C9F00C6D1DF /* .sauce */ = {isa = PBXFileReference; lastKnownFileType = folder; path = .sauce; sourceTree = "<group>"; };
 		844DA7F6282435CD00E6B62E /* README.md */ = {isa = PBXFileReference; lastKnownFileType = net.daringfireball.markdown; path = README.md; sourceTree = "<group>"; };
@@ -2668,6 +2670,7 @@
 				849472802971C107002603DE /* SentrySystemWrapperTests.swift */,
 				849472822971C2CD002603DE /* SentryNSProcessInfoWrapperTests.swift */,
 				849472842971C41A002603DE /* SentryNSTimerWrapperTest.swift */,
+				8431EE5A29ADB8EA00D8DC56 /* SentryTimeTests.m */,
 			);
 			path = Helper;
 			sourceTree = "<group>";
@@ -3947,6 +3950,7 @@
 				7B18DE4428D9F8F6004845C6 /* TestNSNotificationCenterWrapper.swift in Sources */,
 				7B5B94352657AD21002E474B /* SentryFramesTrackingIntegrationTests.swift in Sources */,
 				7BAF3DC8243DB90E008A5414 /* TestTransport.swift in Sources */,
+				8431EE5B29ADB8EA00D8DC56 /* SentryTimeTests.m in Sources */,
 				7B0A54562523178700A71716 /* SentryScopeSwiftTests.swift in Sources */,
 				7B5B94332657A816002E474B /* SentryAppStartTrackingIntegrationTests.swift in Sources */,
 				0A5370A128A3EC2400B2DCDE /* SentryViewHierarchyTests.swift in Sources */,

Sources/Sentry/SentryMetricProfiler.mm

@@ -2,11 +2,24 @@
 
 #if SENTRY_TARGET_PROFILING_SUPPORTED
 
+#    import "SentryEvent+Private.h"
 #    import "SentryLog.h"
 #    import "SentryNSProcessInfoWrapper.h"
 #    import "SentryNSTimerWrapper.h"
 #    import "SentrySystemWrapper.h"
 #    import "SentryTime.h"
+#    import "SentryTransaction.h"
+
+/**
+ * A storage class for metric readings, with one property for the reading value itself, whether it
+ * be bytes of memory, % CPU etc, and another for the absolute system time it was recorded at.
+ */
+@interface SentryMetricReading : NSObject
+@property (strong, nonatomic) NSNumber *value;
+@property (assign, nonatomic) uint64_t absoluteTimestamp;
+@end
+@implementation SentryMetricReading
+@end
 
 /**
  * Currently set to 10 Hz as we don't anticipate much utility out of a higher resolution when
@@ -22,10 +35,39 @@
 NSString *const kSentryMetricProfilerSerializationUnitPercentage = @"percent";
 
 namespace {
-NSDictionary<NSString *, id> *
-serializedValues(NSArray<NSDictionary<NSString *, NSString *> *> *values, NSString *unit)
+/**
+ * @return a dictionary containing all the metric values recorded during the transaction, or @c nil
+ * if there were no metrics recorded during the transaction.
+ */
+SentrySerializedMetricEntry *_Nullable serializeValuesWithNormalizedTime(
+    NSArray<SentryMetricReading *> *absoluteTimestampValues, NSString *unit,
+    SentryTransaction *transaction)
 {
-    return @ { @"unit" : unit, @"values" : values };
+    const auto *timestampNormalizedValues = [NSMutableArray<SentrySerializedMetricReading *> array];
+    [absoluteTimestampValues enumerateObjectsUsingBlock:^(
+        SentryMetricReading *_Nonnull reading, NSUInteger idx, BOOL *_Nonnull stop) {
+        // if the metric reading wasn't recorded until the transaction ended, don't include it
+        if (orderedChronologically(transaction.endSystemTime, reading.absoluteTimestamp)) {
+            return;
+        }
+
+        // if the metric reading was taken before the transaction started, don't include it
+        if (!orderedChronologically(transaction.startSystemTime, reading.absoluteTimestamp)) {
+            return;
+        }
+
+        const auto relativeTimestamp
+            = getDurationNs(transaction.startSystemTime, reading.absoluteTimestamp);
+
+        [timestampNormalizedValues addObject:@{
+            @"elapsed_since_start_ns" : @(relativeTimestamp).stringValue,
+            @"value" : reading.value
+        }];
+    }];
+    if (timestampNormalizedValues.count == 0) {
+        return nil;
+    }
+    return @ { @"unit" : unit, @"values" : timestampNormalizedValues };
 }
 } // namespace
 
@@ -37,36 +79,30 @@ @implementation SentryMetricProfiler {
     SentryNSTimerWrapper *_timerWrapper;
 
     /// arrays of readings keyed on NSNumbers representing the core number for the set of readings
-    NSMutableDictionary<NSNumber *, NSMutableArray<NSDictionary<NSString *, NSString *> *> *>
-        *_cpuUsage;
+    NSMutableDictionary<NSNumber *, NSMutableArray<SentryMetricReading *> *> *_cpuUsage;
 
-    NSMutableArray<NSDictionary<NSString *, id> *> *_memoryFootprint;
-    uint64_t _profileStartTime;
+    NSMutableArray<SentryMetricReading *> *_memoryFootprint;
 }
 
-- (instancetype)initWithProfileStartTime:(uint64_t)profileStartTime
-                      processInfoWrapper:(SentryNSProcessInfoWrapper *)processInfoWrapper
-                           systemWrapper:(SentrySystemWrapper *)systemWrapper
-                            timerWrapper:(SentryNSTimerWrapper *)timerWrapper
+- (instancetype)initWithProcessInfoWrapper:(SentryNSProcessInfoWrapper *)processInfoWrapper
+                             systemWrapper:(SentrySystemWrapper *)systemWrapper
+                              timerWrapper:(SentryNSTimerWrapper *)timerWrapper
 {
     if (self = [super init]) {
-        _cpuUsage = [NSMutableDictionary<NSNumber *,
-            NSMutableArray<NSDictionary<NSString *, NSString *> *> *>
-            dictionary];
+        _cpuUsage =
+            [NSMutableDictionary<NSNumber *, NSMutableArray<SentryMetricReading *> *> dictionary];
         const auto processorCount = processInfoWrapper.processorCount;
         SENTRY_LOG_DEBUG(
             @"Preparing %lu arrays for CPU core usage readings", (long unsigned)processorCount);
         for (NSUInteger core = 0; core < processorCount; core++) {
-            _cpuUsage[@(core)] = [NSMutableArray<NSDictionary<NSString *, NSString *> *> array];
+            _cpuUsage[@(core)] = [NSMutableArray<SentryMetricReading *> array];
         }
 
         _systemWrapper = systemWrapper;
         _processInfoWrapper = processInfoWrapper;
         _timerWrapper = timerWrapper;
 
-        _memoryFootprint = [NSMutableArray<NSDictionary<NSString *, id> *> array];
-
-        _profileStartTime = profileStartTime;
+        _memoryFootprint = [NSMutableArray<SentryMetricReading *> array];
     }
     return self;
 }
@@ -88,7 +124,7 @@ - (void)stop
     [_timer invalidate];
 }
 
-- (NSMutableDictionary<NSString *, id> *)serialize
+- (NSMutableDictionary<NSString *, id> *)serializeForTransaction:(SentryTransaction *)transaction
 {
     NSMutableDictionary<NSString *, id> *dict;
     @synchronized(self) {
@@ -97,16 +133,17 @@ - (void)stop
 
     if (_memoryFootprint.count > 0) {
         dict[kSentryMetricProfilerSerializationKeyMemoryFootprint]
-            = serializedValues(_memoryFootprint, kSentryMetricProfilerSerializationUnitBytes);
+            = serializeValuesWithNormalizedTime(
+                _memoryFootprint, kSentryMetricProfilerSerializationUnitBytes, transaction);
     }
 
     [_cpuUsage enumerateKeysAndObjectsUsingBlock:^(NSNumber *_Nonnull core,
-        NSMutableArray<NSDictionary<NSString *, NSString *> *> *_Nonnull readings,
-        BOOL *_Nonnull stop) {
+        NSMutableArray<SentryMetricReading *> *_Nonnull readings, BOOL *_Nonnull stop) {
         if (readings.count > 0) {
             dict[[NSString stringWithFormat:kSentryMetricProfilerSerializationKeyCPUUsageFormat,
                            core.intValue]]
-                = serializedValues(readings, kSentryMetricProfilerSerializationUnitPercentage);
+                = serializeValuesWithNormalizedTime(
+                    readings, kSentryMetricProfilerSerializationUnitPercentage, transaction);
         }
     }];
 
@@ -137,7 +174,7 @@ - (void)recordMemoryFootprint
     }
 
     @synchronized(self) {
-        [_memoryFootprint addObject:[self metricEntryForValue:@(footprintBytes)]];
+        [_memoryFootprint addObject:[self metricReadingForValue:@(footprintBytes)]];
     }
 }
 
@@ -154,18 +191,17 @@ - (void)recordCPUPercentagePerCore
     @synchronized(self) {
         [result enumerateObjectsUsingBlock:^(
             NSNumber *_Nonnull usage, NSUInteger core, BOOL *_Nonnull stop) {
-            [_cpuUsage[@(core)] addObject:[self metricEntryForValue:usage]];
+            [_cpuUsage[@(core)] addObject:[self metricReadingForValue:usage]];
         }];
     }
 }
 
-- (NSDictionary<NSString *, id> *)metricEntryForValue:(NSNumber *)value
+- (SentryMetricReading *)metricReadingForValue:(NSNumber *)value
 {
-    return @{
-        @"value" : value,
-        @"elapsed_since_start_ns" :
-            [@(getDurationNs(_profileStartTime, getAbsoluteTime())) stringValue]
-    };
+    const auto reading = [[SentryMetricReading alloc] init];
+    reading.value = value;
+    reading.absoluteTimestamp = getAbsoluteTime();
+    return reading;
 }
 
 @end