From c7507689b43bf0913f634d49bdda81e29211bc0c Mon Sep 17 00:00:00 2001 From: Andrew McKnight Date: Thu, 15 Sep 2022 20:50:30 -0800 Subject: [PATCH] fix new test for timed out profiler with concurrent traces completing --- .../xcshareddata/xcschemes/Sentry.xcscheme | 3 -- Sources/Sentry/SentryProfiler.mm | 9 ++--- .../Profiling/SentryProfilerSwiftTests.swift | 35 +++++++++++++------ 3 files changed, 30 insertions(+), 17 deletions(-) diff --git a/Sentry.xcodeproj/xcshareddata/xcschemes/Sentry.xcscheme b/Sentry.xcodeproj/xcshareddata/xcschemes/Sentry.xcscheme index 2e348764d09..9629e068f43 100644 --- a/Sentry.xcodeproj/xcshareddata/xcschemes/Sentry.xcscheme +++ b/Sentry.xcodeproj/xcshareddata/xcschemes/Sentry.xcscheme @@ -55,9 +55,6 @@ ReferencedContainer = "container:Sentry.xcodeproj"> - - diff --git a/Sources/Sentry/SentryProfiler.mm b/Sources/Sentry/SentryProfiler.mm index 56a01ee1384..d4b88096e41 100644 --- 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( @@ -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 index af36f4a07eb..bdb341d0dc1 100644 --- 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() {