fix: profiling transaction timestamps

CHANGELOG.md

@@ -4,7 +4,7 @@
 
 ### Fixes
 
-- Fix issue with invalid profiles uploading (#2358)
+- Fix issue with invalid profiles uploading (#2358 and #2359)
 
 ## 7.30.0
 

Sources/Sentry/SentryProfiler.mm

@@ -574,19 +574,38 @@ - (void)captureEnvelope
 
     // populate info from all transactions that occurred while profiler was running
     auto transactionsInfo = [NSMutableArray array];
+    SENTRY_LOG_DEBUG(@"Profile start timestamp: %@ absolute time: %llu", _startDate,
+        (unsigned long long)_startTimestamp);
+    SENTRY_LOG_DEBUG(@"Profile end timestamp: %@ absolute time: %llu", _endDate,
+        (unsigned long long)_endTimestamp);
     for (SentryTransaction *transaction in _transactions) {
+        SENTRY_LOG_DEBUG(@"Transaction %@ start timestamp: %@", transaction.trace.context.traceId,
+            transaction.startTimestamp);
+        SENTRY_LOG_DEBUG(@"Transaction %@ end timestamp: %@", transaction.trace.context.traceId,
+            transaction.timestamp);
         const auto relativeStart =
             [NSString stringWithFormat:@"%llu",
                       [transaction.startTimestamp compare:_startDate] == NSOrderedAscending
                           ? 0
                           : (unsigned long long)(
                               [transaction.startTimestamp timeIntervalSinceDate:_startDate] * 1e9)];
-        const auto relativeEnd =
-            [NSString stringWithFormat:@"%llu",
-                      [transaction.timestamp compare:_endDate] == NSOrderedDescending
-                          ? profileDuration
-                          : (unsigned long long)(
-                              [transaction.timestamp timeIntervalSinceDate:_startDate] * 1e9)];
+
+        NSString *relativeEnd;
+        if ([transaction.timestamp compare:_endDate] == NSOrderedDescending) {
+            relativeEnd = [NSString stringWithFormat:@"%llu", profileDuration];
+        } else {
+            const auto profileStartToTransactionEnd_ns =
+                [transaction.timestamp timeIntervalSinceDate:_startDate] * 1e9;
+            if (profileStartToTransactionEnd_ns < 0) {
+                SENTRY_LOG_DEBUG(@"Transaction %@ ended before the profiler started, won't "
+                                 @"associate it with this profile.",
+                    transaction.trace.context.traceId.sentryIdString);
+                continue;
+            } else {
+                relativeEnd = [NSString
+                    stringWithFormat:@"%llu", (unsigned long long)profileStartToTransactionEnd_ns];
+            }
+        }
         [transactionsInfo addObject:@{
             @"id" : transaction.eventId.sentryIdString,
             @"trace_id" : transaction.trace.context.traceId.sentryIdString,
@@ -596,6 +615,11 @@ - (void)captureEnvelope
             @"active_thread_id" : [transaction.trace.transactionContext sentry_threadInfo].threadId
         }];
     }
+
+    if (transactionsInfo.count == 0) {
+        SENTRY_LOG_DEBUG(@"No transactions to associate with this profile, will not upload.");
+        return;
+    }
     profile[@"transactions"] = transactionsInfo;
 
     NSError *error = nil;
@@ -610,6 +634,8 @@ - (void)captureEnvelope
     const auto item = [[SentryEnvelopeItem alloc] initWithHeader:header data:JSONData];
     const auto envelopeHeader = [[SentryEnvelopeHeader alloc] initWithId:profileID];
     const auto envelope = [[SentryEnvelope alloc] initWithHeader:envelopeHeader singleItem:item];
+
+    SENTRY_LOG_DEBUG(@"Capturing profile envelope.");
     [_hub captureEnvelope:envelope];
 }
 

Sources/Sentry/SentrySpan.m

@@ -25,8 +25,8 @@ @implementation SentrySpan {
 - (instancetype)initWithTracer:(SentryTracer *)tracer context:(SentrySpanContext *)context
 {
     if (self = [super init]) {
-        SENTRY_LOG_DEBUG(
-            @"Starting span %@ with tracer %@", context.spanId.sentrySpanIdString, tracer);
+        SENTRY_LOG_DEBUG(@"Created span %@ for trace ID %@", context.spanId.sentrySpanIdString,
+            tracer.context.traceId);
         _tracer = tracer;
         _context = context;
         self.startTimestamp = [SentryCurrentDate date];
@@ -128,6 +128,8 @@ - (void)finishWithStatus:(SentrySpanStatus)status
     _isFinished = YES;
     if (self.timestamp == nil) {
         self.timestamp = [SentryCurrentDate date];
+        SENTRY_LOG_DEBUG(@"Setting span timestamp: %@ at system time %llu", self.timestamp,
+            (unsigned long long)getAbsoluteTime());
     }
     if (self.tracer != nil) {
         [self.tracer spanFinished:self];

Sources/Sentry/SentryTracer.m

@@ -143,6 +143,8 @@ - (instancetype)initWithTransactionContext:(SentryTransactionContext *)transacti
           dispatchQueueWrapper:(nullable SentryDispatchQueueWrapper *)dispatchQueueWrapper
 {
     if (self = [super init]) {
+        SENTRY_LOG_DEBUG(
+            @"Starting transaction at system time %llu", (unsigned long long)getAbsoluteTime());
         self.rootSpan = [[SentrySpan alloc] initWithTracer:self context:transactionContext];
         self.transactionContext = transactionContext;
         _children = [[NSMutableArray alloc] init];
@@ -399,6 +401,8 @@ - (SentryTraceHeader *)toTraceHeader
 
 - (void)finish
 {
+    SENTRY_LOG_DEBUG(
+        @"-[SentryTracer finish] for trace ID %@", _traceContext.traceId.sentryIdString);
     [self finishWithStatus:kSentrySpanStatusOk];
 }
 

Tests/SentryTests/Profiling/SentryProfilerSwiftTests.swift

@@ -327,7 +327,7 @@ private extension SentryProfilerSwiftTests {
             }
             XCTAssertNotNil(transaction["trace_id"])
             XCTAssertNotNil(transaction["relative_start_ns"])
-            XCTAssertNotNil(transaction["relative_end_ns"])
+            XCTAssertFalse((transaction["relative_end_ns"] as! NSString).isEqual(to: "0"))
             XCTAssertNotNil(transaction["active_thread_id"])
         }