fix new test for timed out profiler with concurrent traces completing

getsentry · Sep 16, 2022 · c750768 · c750768
1 parent bdddfbe
commit c750768
Show file tree

Hide file tree

Showing 3 changed files with 30 additions and 17 deletions.
diff --git a/Sentry.xcodeproj/xcshareddata/xcschemes/Sentry.xcscheme b/Sentry.xcodeproj/xcshareddata/xcschemes/Sentry.xcscheme
@@ -55,9 +55,6 @@
                ReferencedContainer = "container:Sentry.xcodeproj">
             </BuildableReference>
             <SkippedTests>
-               <Test
-                  Identifier = "SentryProfilerSwiftTests/testConcurrentSpansWithTimeout()">
-               </Test>
                <Test
                   Identifier = "SentrySDKIntegrationTestsBase">
                </Test>

diff --git a/Sources/Sentry/SentryProfiler.mm b/Sources/Sentry/SentryProfiler.mm
@@ -160,7 +160,7 @@ + (void)startForSpanID:(SentrySpanId *)spanID
         [SentryFramesTracker.sharedInstance resetProfilingTimestamps];
         [_gCurrentProfiler start];
         _gCurrentProfiler->_timeoutTimer = [NSTimer scheduledTimerWithTimeInterval:30 repeats:NO block:^(NSTimer * _Nonnull timer) {
-            SENTRY_LOG_DEBUG(@"Profiler timed out.");
+            SENTRY_LOG_DEBUG(@"Profiler %@ timed out.", _gCurrentProfiler);
             [[self class] maybeStopProfilerForSpanID:spanID reason:SentryProfilerTruncationReasonTimeout];
         }];
     }
@@ -199,13 +199,14 @@ + (void)captureProfilingEnvelopeIfFinishedAfterTransaction:(SentryTransaction *)
 
     SentryProfiler *profiler = _gCurrentProfiler;
     if (profiler == nil) {
-        SENTRY_LOG_DEBUG(@"No current profiler, checking for any that timed out while waiting for this transaction.");
+        SENTRY_LOG_DEBUG(@"No current profiler, checking for any that timed out while waiting for span with ID %@.", transaction.trace.context.spanId.sentrySpanIdString);
         const auto spanID = transaction.trace.context.spanId;
         profiler = _gTimedOutProfilers[spanID];
         if (profiler == nil) {
             SENTRY_LOG_DEBUG(@"No profilers waiting for this transaction.");
             return;
         }
+        SENTRY_LOG_DEBUG(@"Found profiler waiting for span with ID %@: %@", transaction.trace.context.spanId.sentrySpanIdString, profiler);
         [profiler addTransaction:transaction];
         if (profiler->_spansInFlight.count > 0) {
             SENTRY_LOG_DEBUG(@"Profiler %@ is timed out and waiting on more spans to finish.", profiler);
@@ -263,7 +264,7 @@ - (void)start
         _startTimestamp = getAbsoluteTime();
         _startDate = [NSDate date];
 
-        [SentryLog logWithMessage:[NSString stringWithFormat:@"Starting profiler at system time %llu.", _startTimestamp] andLevel:kSentryLevelDebug];
+        SENTRY_LOG_DEBUG(@"Starting profiler %@ at system time %llu.", self, _startTimestamp);
 
         __weak const auto weakSelf = self;
         _profiler = std::make_shared<SamplingProfiler>(
@@ -352,7 +353,7 @@ - (void)stop
         _profiler->stopSampling();
         _endTimestamp = getAbsoluteTime();
         _endDate = [NSDate date];
-        [SentryLog logWithMessage:[NSString stringWithFormat:@"Stopped profiler at system time: %llu.", _endTimestamp] andLevel:kSentryLevelDebug];
+        SENTRY_LOG_DEBUG(@"Stopped profiler %@ at system time: %llu.", self, _endTimestamp);
     }
 }
 

diff --git a/Tests/SentryTests/Profiling/SentryProfilerSwiftTests.swift b/Tests/SentryTests/Profiling/SentryProfilerSwiftTests.swift
@@ -99,6 +99,14 @@ class SentryProfilerSwiftTests: XCTestCase {
 
         let expA = expectation(description: "Span A finishes")
         let spanA = fixture.hub.startTransaction(name: fixture.transactionName, operation: fixture.transactionOperation)
+
+        // Some busy work to try and get it to show up in the profile.
+        let str = "a"
+        var concatStr = ""
+        for _ in 0..<100_000 {
+            concatStr = concatStr.appending(str)
+        }
+
         DispatchQueue.main.asyncAfter(deadline: .now() + 45) {
             spanA.finish()
             expA.fulfill()
@@ -107,6 +115,14 @@ class SentryProfilerSwiftTests: XCTestCase {
         let expB = expectation(description: "Span B finishes")
         DispatchQueue.main.asyncAfter(deadline: .now() + 35) {
             let spanB = self.fixture.hub.startTransaction(name: self.fixture.transactionName, operation: self.fixture.transactionOperation)
+
+            // Some busy work to try and get it to show up in the profile.
+            let str = "a"
+            var concatStr = ""
+            for _ in 0..<100_000 {
+                concatStr = concatStr.appending(str)
+            }
+
             DispatchQueue.main.asyncAfter(deadline: .now() + 5) {
                 spanB.finish()
                 expB.fulfill()
@@ -115,17 +131,16 @@ class SentryProfilerSwiftTests: XCTestCase {
 
         waitForExpectations(timeout: 50)
 
-        guard let envelope = self.fixture.client.captureEnvelopeInvocations.first else {
-            XCTFail("Expected to capture at least 1 event")
-            return
-        }
-        XCTAssertEqual(1, envelope.items.count)
-        guard let profileItem = envelope.items.first else {
-            XCTFail("Expected at least 1 additional envelope item")
-            return
+        XCTAssertEqual(self.fixture.client.captureEnvelopeInvocations.count, 2)
+        for envelope in self.fixture.client.captureEnvelopeInvocations.invocations {
+            XCTAssertEqual(1, envelope.items.count)
+            guard let profileItem = envelope.items.first else {
+                XCTFail("Expected at least 1 additional envelope item")
+                return
+            }
+            XCTAssertEqual("profile", profileItem.header.type)
+            self.assertValidProfileData(data: profileItem.data)
         }
-        XCTAssertEqual("profile", profileItem.header.type)
-        self.assertValidProfileData(data: profileItem.data)
     }
 
     func testProfileTimeout() {