diff --git a/CHANGELOG.md b/CHANGELOG.md index bb4df5ca07d..6f5a26849ae 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -6,6 +6,9 @@ - Add flush (#2140) - Add more device context (#2190) +- Profile concurrent transactions (#2105) + +## 7.25.1 ### Fixes diff --git a/Sentry.xcodeproj/project.pbxproj b/Sentry.xcodeproj/project.pbxproj index 9911056416b..a2cb585965c 100644 --- a/Sentry.xcodeproj/project.pbxproj +++ b/Sentry.xcodeproj/project.pbxproj @@ -581,8 +581,10 @@ 7DC83100239826280043DD9A /* SentryIntegrationProtocol.h in Headers */ = {isa = PBXBuildFile; fileRef = 7DC830FF239826280043DD9A /* SentryIntegrationProtocol.h */; settings = {ATTRIBUTES = (Public, ); }; }; 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 */; }; 8453421228BE855D00C22EEC /* SentrySampleDecision.m in Sources */ = {isa = PBXBuildFile; fileRef = 8453421128BE855D00C22EEC /* SentrySampleDecision.m */; }; 8453421628BE8A9500C22EEC /* SentrySpanStatus.m in Sources */ = {isa = PBXBuildFile; fileRef = 8453421528BE8A9500C22EEC /* SentrySpanStatus.m */; }; + 84A888FD28D9B11700C51DFD /* SentryProfiler+Test.h in Headers */ = {isa = PBXBuildFile; fileRef = 84A888FC28D9B11700C51DFD /* SentryProfiler+Test.h */; }; 861265F92404EC1500C4AFDE /* NSArray+SentrySanitize.h in Headers */ = {isa = PBXBuildFile; fileRef = 861265F72404EC1500C4AFDE /* NSArray+SentrySanitize.h */; }; 861265FA2404EC1500C4AFDE /* NSArray+SentrySanitize.m in Sources */ = {isa = PBXBuildFile; fileRef = 861265F82404EC1500C4AFDE /* NSArray+SentrySanitize.m */; }; 8E0551E026A7A63C00400526 /* TestProtocolClient.swift in Sources */ = {isa = PBXBuildFile; fileRef = 8E0551DF26A7A63C00400526 /* TestProtocolClient.swift */; }; @@ -1323,6 +1325,7 @@ 7DC830FF239826280043DD9A /* SentryIntegrationProtocol.h */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.h; name = SentryIntegrationProtocol.h; path = Public/SentryIntegrationProtocol.h; sourceTree = ""; }; 7DC831082398283C0043DD9A /* SentryCrashIntegration.h */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.h; name = SentryCrashIntegration.h; path = include/SentryCrashIntegration.h; sourceTree = ""; }; 7DC831092398283C0043DD9A /* SentryCrashIntegration.m */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.objc; path = SentryCrashIntegration.m; sourceTree = ""; }; + 8419C0C328C1889D001C8259 /* SentryProfilerSwiftTests.swift */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.swift; path = SentryProfilerSwiftTests.swift; sourceTree = ""; }; 844A34C3282B278500C6D1DF /* .github */ = {isa = PBXFileReference; lastKnownFileType = folder; path = .github; sourceTree = ""; }; 844A3563282B3C9F00C6D1DF /* .sauce */ = {isa = PBXFileReference; lastKnownFileType = folder; path = .sauce; sourceTree = ""; }; 844DA7F6282435CD00E6B62E /* README.md */ = {isa = PBXFileReference; lastKnownFileType = net.daringfireball.markdown; path = README.md; sourceTree = ""; }; @@ -1348,6 +1351,7 @@ 844DA81F28246DE300E6B62E /* scripts */ = {isa = PBXFileReference; lastKnownFileType = folder; path = scripts; sourceTree = ""; }; 8453421128BE855D00C22EEC /* SentrySampleDecision.m */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.objc; path = SentrySampleDecision.m; sourceTree = ""; }; 8453421528BE8A9500C22EEC /* SentrySpanStatus.m */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.objc; path = SentrySpanStatus.m; sourceTree = ""; }; + 84A888FC28D9B11700C51DFD /* SentryProfiler+Test.h */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.c.h; name = "SentryProfiler+Test.h"; path = "Sources/Sentry/include/SentryProfiler+Test.h"; sourceTree = SOURCE_ROOT; }; 861265F72404EC1500C4AFDE /* NSArray+SentrySanitize.h */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.h; name = "NSArray+SentrySanitize.h"; path = "include/NSArray+SentrySanitize.h"; sourceTree = ""; }; 861265F82404EC1500C4AFDE /* NSArray+SentrySanitize.m */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.objc; path = "NSArray+SentrySanitize.m"; sourceTree = ""; }; 8E0551DF26A7A63C00400526 /* TestProtocolClient.swift */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.swift; path = TestProtocolClient.swift; sourceTree = ""; }; @@ -1497,6 +1501,7 @@ 035E73CB27D575B3005EEB11 /* SentrySamplingProfilerTests.mm */, 035E73CD27D5790A005EEB11 /* SentryThreadMetadataCacheTests.mm */, 03F9D37B2819A65C00602916 /* SentryProfilerTests.mm */, + 8419C0C328C1889D001C8259 /* SentryProfilerSwiftTests.swift */, ); path = Profiling; sourceTree = ""; @@ -2678,6 +2683,7 @@ 03F84D1B27DD414C008FE43F /* SentryMachLogging.hpp */, 03F84D2C27DD4191008FE43F /* SentryMachLogging.cpp */, 03F84D1127DD414C008FE43F /* SentryProfiler.h */, + 84A888FC28D9B11700C51DFD /* SentryProfiler+Test.h */, 03F84D2B27DD4191008FE43F /* SentryProfiler.mm */, 03BCC38D27E2A377003232C7 /* SentryProfilingConditionals.h */, 03F84D2927DD416B008FE43F /* SentryProfilingLogging.hpp */, @@ -2923,6 +2929,7 @@ 8EE3251C261FE33B00DC3FF2 /* SentryUIViewControllerSanitizer.h in Headers */, 7BAF3DD92440AEC8008A5414 /* SentryRequestManager.h in Headers */, 7BE3C77B2446111500A38442 /* SentryRateLimitParser.h in Headers */, + 84A888FD28D9B11700C51DFD /* SentryProfiler+Test.h in Headers */, 7D0637032382B34300B30749 /* SentryScope.h in Headers */, 03F84D2727DD414C008FE43F /* SentryMachLogging.hpp in Headers */, 0356A570288B4612008BF593 /* SentryProfilesSampler.h in Headers */, @@ -3505,6 +3512,7 @@ 63FE720520DA66EC00CDBAE8 /* FileBasedTestCase.m in Sources */, 0A6EEADD28A657970076B469 /* UIViewRecursiveDescriptionTests.swift in Sources */, 63EED6C32237989300E02400 /* SentryOptionsTest.m in Sources */, + 8419C0C428C1889D001C8259 /* SentryProfilerSwiftTests.swift in Sources */, 7BBD18B22451804C00427C76 /* SentryRetryAfterHeaderParserTests.swift in Sources */, 7BD337E424A356180050DB6E /* SentryCrashIntegrationTests.swift in Sources */, 7BD4E8E827FD95900086C410 /* SentryMigrateSessionInitTests.m in Sources */, diff --git a/Sources/Sentry/SentryFramesTracker.m b/Sources/Sentry/SentryFramesTracker.m index b7fbebce0f5..a141c100d1c 100644 --- a/Sources/Sentry/SentryFramesTracker.m +++ b/Sources/Sentry/SentryFramesTracker.m @@ -1,5 +1,6 @@ #import "SentryFramesTracker.h" #import "SentryDisplayLinkWrapper.h" +#import "SentryProfiler.h" #import "SentryProfilingConditionals.h" #import "SentryTracer.h" #import @@ -123,7 +124,7 @@ - (void)displayLinkCallback } # if SENTRY_TARGET_PROFILING_SUPPORTED - if (self.currentTracer.isProfiling + if ([SentryProfiler isRunning] && (self.frameRateTimestamps.count == 0 || self.frameRateTimestamps.lastObject[@"frame_rate"].doubleValue != actualFramesPerSecond)) { @@ -161,7 +162,7 @@ - (void)displayLinkCallback # if SENTRY_TARGET_PROFILING_SUPPORTED - (void)recordTimestampStart:(NSNumber *)start end:(NSNumber *)end { - if (self.currentTracer.isProfiling) { + if ([SentryProfiler isRunning]) { [self.frameTimestamps addObject:@{ @"start_timestamp" : start, @"end_timestamp" : end }]; } } diff --git a/Sources/Sentry/SentryProfiler.mm b/Sources/Sentry/SentryProfiler.mm index de58a0802f6..613d5d68a9f 100644 --- a/Sources/Sentry/SentryProfiler.mm +++ b/Sources/Sentry/SentryProfiler.mm @@ -1,7 +1,6 @@ #import "SentryProfiler.h" #if SENTRY_TARGET_PROFILING_SUPPORTED - # import "SentryBacktrace.hpp" # import "SentryClient+Private.h" # import "SentryDebugImageProvider.h" @@ -12,14 +11,16 @@ # import "SentryEnvelopeItemType.h" # import "SentryFramesTracker.h" # import "SentryHexAddressFormatter.h" -# import "SentryHub.h" +# import "SentryHub+Private.h" # import "SentryId.h" # import "SentryLog.h" +# import "SentryProfilesSampler.h" # import "SentryProfilingLogging.hpp" # import "SentrySamplingProfiler.hpp" # import "SentryScope+Private.h" # import "SentryScreenFrames.h" # import "SentrySerialization.h" +# import "SentrySpanId.h" # import "SentryTime.h" # import "SentryTransaction.h" # import "SentryTransactionContext.h" @@ -30,6 +31,7 @@ # import # import +# import # import # import @@ -37,6 +39,9 @@ # import # endif +const int kSentryProfilerFrequencyHz = 101; +NSString *const kTestStringConst = @"test"; + using namespace sentry::profiling; NSString * @@ -60,6 +65,19 @@ return [symbolNSStr substringWithRange:[match rangeAtIndex:1]]; } +NSString * +profilerTruncationReasonName(SentryProfilerTruncationReason reason) +{ + switch (reason) { + case SentryProfilerTruncationReasonNormal: + return @"normal"; + case SentryProfilerTruncationReasonAppMovedToBackground: + return @"backgrounded"; + case SentryProfilerTruncationReasonTimeout: + return @"timeout"; + } +} + namespace { NSString * getDeviceModel() @@ -92,28 +110,204 @@ return false; # endif } + +std::mutex _gProfilerLock; +NSMutableDictionary *_gProfilersPerSpanID; +SentryProfiler *_Nullable _gCurrentProfiler; } // namespace @implementation SentryProfiler { NSMutableDictionary *_profile; uint64_t _startTimestamp; + NSDate *_startDate; + uint64_t _endTimestamp; + NSDate *_endDate; std::shared_ptr _profiler; SentryDebugImageProvider *_debugImageProvider; thread::TIDType _mainThreadID; + + NSMutableArray *_spansInFlight; + NSMutableArray *_transactions; + SentryProfilerTruncationReason _truncationReason; + SentryScreenFrames *_frameInfo; + NSTimer *_timeoutTimer; + SentryHub *__weak _hub; +} + ++ (void)initialize +{ +# if SENTRY_TARGET_PROFILING_SUPPORTED + if (self == [SentryProfiler class]) { + _gProfilersPerSpanID = [NSMutableDictionary dictionary]; + } +# endif // SENTRY_TARGET_PROFILING_SUPPORTED } +# if SENTRY_TARGET_PROFILING_SUPPORTED - (instancetype)init { if (![NSThread isMainThread]) { SENTRY_LOG_ERROR(@"SentryProfiler must be initialized on the main thread"); return nil; } - if (self = [super init]) { - _debugImageProvider = [SentryDependencyContainer sharedInstance].debugImageProvider; - _mainThreadID = ThreadHandle::current()->tid(); + + if (!(self = [super init])) { + return nil; } + + SENTRY_LOG_DEBUG(@"Initialized new SentryProfiler %@", self); + _debugImageProvider = [SentryDependencyContainer sharedInstance].debugImageProvider; + _mainThreadID = ThreadHandle::current()->tid(); + _spansInFlight = [NSMutableArray array]; + _transactions = [NSMutableArray array]; return self; } +# endif + +# pragma mark - Public + ++ (void)startForSpanID:(SentrySpanId *)spanID hub:(SentryHub *)hub +{ +# if SENTRY_TARGET_PROFILING_SUPPORTED + NSTimeInterval timeoutInterval = 30; +# if defined(TEST) || defined(TESTCI) + timeoutInterval = 1; +# endif + [self startForSpanID:spanID hub:hub timeoutInterval:timeoutInterval]; +# endif +} + ++ (void)startForSpanID:(SentrySpanId *)spanID + hub:(SentryHub *)hub + timeoutInterval:(NSTimeInterval)timeoutInterval +{ +# if SENTRY_TARGET_PROFILING_SUPPORTED + std::lock_guard l(_gProfilerLock); + + if (_gCurrentProfiler == nil) { + _gCurrentProfiler = [[SentryProfiler alloc] init]; +# if SENTRY_HAS_UIKIT + [SentryFramesTracker.sharedInstance resetProfilingTimestamps]; +# endif // SENTRY_HAS_UIKIT + [_gCurrentProfiler start]; + _gCurrentProfiler->_timeoutTimer = + [NSTimer scheduledTimerWithTimeInterval:timeoutInterval + target:self + selector:@selector(timeoutAbort) + userInfo:nil + repeats:NO]; + _gCurrentProfiler->_hub = hub; + } + + SENTRY_LOG_DEBUG( + @"Tracking span with ID %@ with profiler %@", spanID.sentrySpanIdString, _gCurrentProfiler); + [_gCurrentProfiler->_spansInFlight addObject:spanID]; + _gProfilersPerSpanID[spanID] = _gCurrentProfiler; +# endif // SENTRY_TARGET_PROFILING_SUPPORTED +} + ++ (void)stopProfilingSpan:(id)span +{ +# if SENTRY_TARGET_PROFILING_SUPPORTED + std::lock_guard l(_gProfilerLock); + + if (_gCurrentProfiler == nil) { + SENTRY_LOG_DEBUG( + @"No profiler tracking span with id %@", span.context.spanId.sentrySpanIdString); + return; + } + + [_gCurrentProfiler->_spansInFlight removeObject:span.context.spanId]; + if (_gCurrentProfiler->_spansInFlight.count == 0) { + SENTRY_LOG_DEBUG(@"Stopping profiler %@ because span with id %@ was last being profiled.", + _gCurrentProfiler, span.context.spanId.sentrySpanIdString); + [self stopProfilerForReason:SentryProfilerTruncationReasonNormal]; + } +# endif // SENTRY_TARGET_PROFILING_SUPPORTED +} + ++ (void)dropTransaction:(SentryTransaction *)transaction +{ +# if SENTRY_TARGET_PROFILING_SUPPORTED + std::lock_guard l(_gProfilerLock); + + const auto spanID = transaction.trace.context.spanId; + const auto profiler = _gProfilersPerSpanID[spanID]; + if (profiler == nil) { + SENTRY_LOG_DEBUG(@"No profiler tracking span with id %@", spanID.sentrySpanIdString); + return; + } + + [self captureEnvelopeIfFinished:profiler spanID:spanID]; +# endif // SENTRY_TARGET_PROFILING_SUPPORTED +} + ++ (void)linkTransaction:(SentryTransaction *)transaction +{ +# if SENTRY_TARGET_PROFILING_SUPPORTED + std::lock_guard l(_gProfilerLock); + + const auto spanID = transaction.trace.context.spanId; + SentryProfiler *profiler = _gProfilersPerSpanID[spanID]; + if (profiler == nil) { + SENTRY_LOG_DEBUG(@"No profiler tracking span with id %@", spanID.sentrySpanIdString); + return; + } + + SENTRY_LOG_DEBUG(@"Found profiler waiting for span with ID %@: %@", + transaction.trace.context.spanId.sentrySpanIdString, profiler); + [profiler addTransaction:transaction]; + + [self captureEnvelopeIfFinished:profiler spanID:spanID]; +# endif // SENTRY_TARGET_PROFILING_SUPPORTED +} + ++ (BOOL)isRunning +{ +# if SENTRY_TARGET_PROFILING_SUPPORTED + std::lock_guard l(_gProfilerLock); + return [_gCurrentProfiler isRunning]; +# endif // SENTRY_TARGET_PROFILING_SUPPORTED +} + +# pragma mark - Private + ++ (void)captureEnvelopeIfFinished:(SentryProfiler *)profiler spanID:(SentrySpanId *)spanID +{ + [_gProfilersPerSpanID removeObjectForKey:spanID]; + [profiler->_spansInFlight removeObject:spanID]; + if (profiler->_spansInFlight.count == 0) { + [profiler captureEnvelope]; + [profiler->_transactions removeAllObjects]; + } else { + SENTRY_LOG_DEBUG(@"Profiler %@ is waiting for more spans to complete.", profiler); + } +} + ++ (void)timeoutAbort +{ + std::lock_guard l(_gProfilerLock); + + if (_gCurrentProfiler == nil) { + SENTRY_LOG_DEBUG(@"No current profiler to stop."); + return; + } + + SENTRY_LOG_DEBUG(@"Stopping profiler %@ due to timeout.", _gCurrentProfiler); + [self stopProfilerForReason:SentryProfilerTruncationReasonTimeout]; +} + ++ (void)stopProfilerForReason:(SentryProfilerTruncationReason)reason +{ + [_gCurrentProfiler->_timeoutTimer invalidate]; + [_gCurrentProfiler stop]; + _gCurrentProfiler->_truncationReason = reason; +# if SENTRY_HAS_UIKIT + _gCurrentProfiler->_frameInfo = SentryFramesTracker.sharedInstance.currentFrames; + [SentryFramesTracker.sharedInstance resetProfilingTimestamps]; +# endif // SENTRY_HAS_UIKIT + _gCurrentProfiler = nil; +} - (void)start { @@ -144,6 +338,9 @@ - (void)start sampledProfile[@"queue_metadata"] = queueMetadata; _profile[@"sampled_profile"] = sampledProfile; _startTimestamp = getAbsoluteTime(); + _startDate = [NSDate date]; + + SENTRY_LOG_DEBUG(@"Starting profiler %@ at system time %llu.", self, _startTimestamp); __weak const auto weakSelf = self; _profiler = std::make_shared( @@ -206,23 +403,42 @@ - (void)start } [samples addObject:sample]; }, - 101 /** Sample 101 times per second */); + kSentryProfilerFrequencyHz); _profiler->startSampling(); } } +- (void)addTransaction:(nonnull SentryTransaction *)transaction +{ + NSParameterAssert(transaction); + if (transaction == nil) { + SENTRY_LOG_WARN(@"Received nil transaction!"); + return; + } + + SENTRY_LOG_DEBUG(@"Adding transaction %@ to list of profiled transactions for profiler %@.", + transaction, self); + if (_transactions == nil) { + _transactions = [NSMutableArray array]; + } + [_transactions addObject:transaction]; +} + - (void)stop { @synchronized(self) { - if (_profiler != nullptr) { - _profiler->stopSampling(); + if (_profiler == nullptr || !_profiler->isSampling()) { + return; } + + _profiler->stopSampling(); + _endTimestamp = getAbsoluteTime(); + _endDate = [NSDate date]; + SENTRY_LOG_DEBUG(@"Stopped profiler %@ at system time: %llu.", self, _endTimestamp); } } -- (SentryEnvelopeItem *)buildEnvelopeItemForTransaction:(SentryTransaction *)transaction - hub:(SentryHub *)hub - frameInfo:(SentryScreenFrames *)frameInfo +- (void)captureEnvelope { NSMutableDictionary *profile = nil; @synchronized(self) { @@ -256,13 +472,11 @@ - (SentryEnvelopeItem *)buildEnvelopeItemForTransaction:(SentryTransaction *)tra profile[@"device_is_emulator"] = @(isSimulatorBuild()); profile[@"device_physical_memory_bytes"] = [@(NSProcessInfo.processInfo.physicalMemory) stringValue]; - profile[@"environment"] = hub.scope.environmentString ?: hub.getClient.options.environment ?: kSentryDefaultEnvironment; - profile[@"platform"] = transaction.platform; - profile[@"transaction_id"] = transaction.eventId.sentryIdString; - profile[@"trace_id"] = transaction.trace.context.traceId.sentryIdString; - profile[@"profile_id"] = [[SentryId alloc] init].sentryIdString; - profile[@"transaction_name"] = transaction.transaction; - profile[@"duration_ns"] = [@(getDurationNs(_startTimestamp, getAbsoluteTime())) stringValue]; + const auto profileID = [[SentryId alloc] init]; + profile[@"profile_id"] = profileID.sentryIdString; + const auto profileDuration = getDurationNs(_startTimestamp, _endTimestamp); + profile[@"duration_ns"] = [@(profileDuration) stringValue]; + profile[@"truncation_reason"] = profilerTruncationReasonName(_truncationReason); const auto bundle = NSBundle.mainBundle; profile[@"version_code"] = [bundle objectForInfoDictionaryKey:(NSString *)kCFBundleVersionKey]; @@ -270,22 +484,28 @@ - (SentryEnvelopeItem *)buildEnvelopeItemForTransaction:(SentryTransaction *)tra # if SENTRY_HAS_UIKIT auto relativeFrameTimestampsNs = [NSMutableArray array]; - [frameInfo.frameTimestamps enumerateObjectsUsingBlock:^( + [_frameInfo.frameTimestamps enumerateObjectsUsingBlock:^( NSDictionary *_Nonnull obj, NSUInteger idx, BOOL *_Nonnull stop) { const auto begin = (uint64_t)(obj[@"start_timestamp"].doubleValue * 1e9); if (begin < _startTimestamp) { return; } const auto end = (uint64_t)(obj[@"end_timestamp"].doubleValue * 1e9); + const auto relativeEnd = getDurationNs(_startTimestamp, end); + if (relativeEnd > profileDuration) { + SENTRY_LOG_DEBUG(@"The last slow/frozen frame extended past the end of the profile, " + @"will not report it."); + return; + } [relativeFrameTimestampsNs addObject:@{ @"start_timestamp_relative_ns" : @(getDurationNs(_startTimestamp, begin)), - @"end_timestamp_relative_ns" : @(getDurationNs(_startTimestamp, end)), + @"end_timestamp_relative_ns" : @(relativeEnd), }]; }]; profile[@"adverse_frame_render_timestamps"] = relativeFrameTimestampsNs; relativeFrameTimestampsNs = [NSMutableArray array]; - [frameInfo.frameRateTimestamps enumerateObjectsUsingBlock:^( + [_frameInfo.frameRateTimestamps enumerateObjectsUsingBlock:^( NSDictionary *_Nonnull obj, NSUInteger idx, BOOL *_Nonnull stop) { const auto timestamp = (uint64_t)(obj[@"timestamp"].doubleValue * 1e9); const auto refreshRate = obj[@"frame_rate"]; @@ -301,6 +521,33 @@ - (SentryEnvelopeItem *)buildEnvelopeItemForTransaction:(SentryTransaction *)tra profile[@"screen_frame_rates"] = relativeFrameTimestampsNs; # endif // SENTRY_HAS_UIKIT + // populate info from all transactions that occurred while profiler was running + profile[@"platform"] = _transactions.firstObject.platform; + auto transactionsInfo = [NSMutableArray array]; + for (SentryTransaction *transaction in _transactions) { + 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)]; + [transactionsInfo addObject:@{ + @"environment" : _hub.scope.environmentString ?: _hub.getClient.options.environment ?: kSentryDefaultEnvironment, + @"id" : transaction.eventId.sentryIdString, + @"trace_id" : transaction.trace.context.traceId.sentryIdString, + @"name" : transaction.transaction, + @"relative_start_ns" : relativeStart, + @"relative_end_ns" : relativeEnd + }]; + } + profile[@"transactions"] = transactionsInfo; + NSError *error = nil; const auto JSONData = [SentrySerialization dataWithJSONObject:profile error:&error]; if (JSONData == nil) { @@ -308,12 +555,15 @@ - (SentryEnvelopeItem *)buildEnvelopeItemForTransaction:(SentryTransaction *)tra logWithMessage:[NSString stringWithFormat:@"Failed to encode profile to JSON: %@", error] andLevel:kSentryLevelError]; - return nil; + return; } const auto header = [[SentryEnvelopeItemHeader alloc] initWithType:SentryEnvelopeItemTypeProfile length:JSONData.length]; - return [[SentryEnvelopeItem alloc] initWithHeader:header data:JSONData]; + 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]; + [_hub captureEnvelope:envelope]; } - (BOOL)isRunning diff --git a/Sources/Sentry/SentrySpan.m b/Sources/Sentry/SentrySpan.m index 2238dd66259..919b67d67ba 100644 --- a/Sources/Sentry/SentrySpan.m +++ b/Sources/Sentry/SentrySpan.m @@ -2,7 +2,10 @@ #import "NSDate+SentryExtras.h" #import "NSDictionary+SentrySanitize.h" #import "SentryCurrentDate.h" +#import "SentryLog.h" #import "SentryNoOpSpan.h" +#import "SentrySpanId.h" +#import "SentryTime.h" #import "SentryTraceHeader.h" #import "SentryTracer.h" @@ -21,6 +24,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); _tracer = tracer; _context = context; self.startTimestamp = [SentryCurrentDate date]; @@ -40,6 +45,7 @@ - (instancetype)initWithTracer:(SentryTracer *)tracer context:(SentrySpanContext description:(nullable NSString *)description { if (self.tracer == nil) { + SENTRY_LOG_DEBUG(@"No tracer, returning no-op span"); return [SentryNoOpSpan shared]; } diff --git a/Sources/Sentry/SentryTracer.m b/Sources/Sentry/SentryTracer.m index 534ff7a925b..fe7848d9c35 100644 --- a/Sources/Sentry/SentryTracer.m +++ b/Sources/Sentry/SentryTracer.m @@ -15,6 +15,7 @@ #import "SentrySpan.h" #import "SentrySpanContext.h" #import "SentrySpanId.h" +#import "SentryTime.h" #import "SentryTraceContext.h" #import "SentryTransaction+Private.h" #import "SentryTransaction.h" @@ -44,14 +45,12 @@ @property (nonatomic) BOOL isWaitingForChildren; @property (nonatomic) NSTimeInterval idleTimeout; @property (nonatomic, nullable, strong) SentryDispatchQueueWrapper *dispatchQueueWrapper; -@property (nonatomic, assign, readwrite) BOOL isProfiling; @end @implementation SentryTracer { BOOL _waitForChildren; SentryTraceContext *_traceContext; - SentryProfilesSamplerDecision *_profilesSamplerDecision; NSMutableDictionary *_tags; NSMutableDictionary *_data; dispatch_block_t _idleTimeoutBlock; @@ -69,19 +68,11 @@ @implementation SentryTracer { static NSObject *appStartMeasurementLock; static BOOL appStartMeasurementRead; -#if SENTRY_TARGET_PROFILING_SUPPORTED -static SentryProfiler *_Nullable profiler; -static NSLock *profilerLock; -#endif - + (void)initialize { if (self == [SentryTracer class]) { appStartMeasurementLock = [[NSObject alloc] init]; appStartMeasurementRead = NO; -#if SENTRY_TARGET_PROFILING_SUPPORTED - profilerLock = [[NSLock alloc] init]; -#endif } } @@ -149,7 +140,6 @@ - (instancetype)initWithTransactionContext:(SentryTransactionContext *)transacti _children = [[NSMutableArray alloc] init]; self.hub = hub; self.isWaitingForChildren = NO; - _profilesSamplerDecision = profilesSamplerDecision; _waitForChildren = waitForChildren; _tags = [[NSMutableDictionary alloc] init]; _data = [[NSMutableDictionary alloc] init]; @@ -174,19 +164,10 @@ - (instancetype)initWithTransactionContext:(SentryTransactionContext *)transacti initFrozenFrames = currentFrames.frozen; } #endif // SENTRY_HAS_UIKIT + #if SENTRY_TARGET_PROFILING_SUPPORTED - if (_profilesSamplerDecision.decision == kSentrySampleDecisionYes) { - [profilerLock lock]; - if (profiler == nil) { - profiler = [[SentryProfiler alloc] init]; - SENTRY_LOG_DEBUG(@"Starting profiler."); -# if SENTRY_HAS_UIKIT - framesTracker.currentTracer = self; - [framesTracker resetProfilingTimestamps]; -# endif // SENTRY_HAS_UIKIT - [profiler start]; - } - [profilerLock unlock]; + if (profilesSamplerDecision.decision == kSentrySampleDecisionYes) { + [SentryProfiler startForSpanID:transactionContext.spanId hub:hub]; } #endif // SENTRY_TARGET_PROFILING_SUPPORTED } @@ -264,6 +245,7 @@ - (void)cancelIdleTimeout sampled:_rootSpan.context.sampled]; context.spanDescription = description; + SENTRY_LOG_DEBUG(@"Starting child span under %@", parentId.sentrySpanIdString); SentrySpan *child = [[SentrySpan alloc] initWithTracer:self context:context]; @synchronized(_children) { [_children addObject:child]; @@ -447,23 +429,9 @@ - (void)finishInternal self.finishCallback = nil; } - if (_hub == nil) + if (_hub == nil) { return; - -#if SENTRY_TARGET_PROFILING_SUPPORTED - SentryScreenFrames *frameInfo; - if (_profilesSamplerDecision.decision == kSentrySampleDecisionYes) { - SENTRY_LOG_DEBUG(@"Stopping profiler."); - [profilerLock lock]; - [profiler stop]; -# if SENTRY_HAS_UIKIT - frameInfo = SentryFramesTracker.sharedInstance.currentFrames; - [SentryFramesTracker.sharedInstance resetProfilingTimestamps]; - SentryFramesTracker.sharedInstance.currentTracer = nil; -# endif // SENTRY_HAS_UIKIT - [profilerLock unlock]; } -#endif // SENTRY_TARGET_PROFILING_SUPPORTED [_hub.scope useSpan:^(id _Nullable span) { if (span == self) { @@ -491,6 +459,10 @@ - (void)finishInternal } } +#if SENTRY_TARGET_PROFILING_SUPPORTED + [SentryProfiler stopProfilingSpan:self.rootSpan]; +#endif // SENTRY_TARGET_PROFILING_SUPPORTED + SentryTransaction *transaction = [self toTransaction]; // Prewarming can execute code up to viewDidLoad of a UIViewController, and keep the app in the @@ -502,30 +474,16 @@ - (void)finishInternal SENTRY_LOG_INFO(@"Auto generated transaction exceeded the max duration of %f seconds. Not " @"capturing transaction.", SENTRY_AUTO_TRANSACTION_MAX_DURATION); +#if SENTRY_TARGET_PROFILING_SUPPORTED + [SentryProfiler dropTransaction:transaction]; +#endif // SENTRY_TARGET_PROFILING_SUPPORTED return; } - - NSMutableArray *additionalEnvelopeItems = [NSMutableArray array]; + [_hub captureTransaction:transaction withScope:_hub.scope]; #if SENTRY_TARGET_PROFILING_SUPPORTED - if (_profilesSamplerDecision.decision == kSentrySampleDecisionYes) { - [profilerLock lock]; - if (profiler != nil) { - SentryEnvelopeItem *profile = [profiler buildEnvelopeItemForTransaction:transaction - hub:_hub - frameInfo:frameInfo]; - if (profile != nil) { - [additionalEnvelopeItems addObject:profile]; - } - profiler = nil; - } - [profilerLock unlock]; - } -#endif - - [_hub captureTransaction:transaction - withScope:_hub.scope - additionalEnvelopeItems:additionalEnvelopeItems]; + [SentryProfiler linkTransaction:transaction]; +#endif // SENTRY_TARGET_PROFILING_SUPPORTED } - (void)trimEndTimestamp @@ -788,16 +746,6 @@ + (nullable SentryTracer *)getTracer:(id)span return nil; } -#if SENTRY_TARGET_PROFILING_SUPPORTED -- (BOOL)isProfiling -{ - [profilerLock lock]; - BOOL isRunning = profiler.isRunning; - [profilerLock unlock]; - return isRunning; -} -#endif // SENTRY_TARGET_PROFILING_SUPPORTED - @end NS_ASSUME_NONNULL_END diff --git a/Sources/Sentry/include/SentryFramesTracker.h b/Sources/Sentry/include/SentryFramesTracker.h index c75d0b5ea0b..c8278040b88 100644 --- a/Sources/Sentry/include/SentryFramesTracker.h +++ b/Sources/Sentry/include/SentryFramesTracker.h @@ -21,12 +21,6 @@ SENTRY_NO_INIT @property (nonatomic, assign, readonly) BOOL isRunning; # if SENTRY_TARGET_PROFILING_SUPPORTED -/** - * The tracer that is currently using this frame tracker. Provided so that the frame tracker can - * query for whether a profiler is currently running. - */ -@property (nullable, nonatomic, weak) SentryTracer *currentTracer; - /** Remove previously recorded timestamps in preparation for a later profiled transaction. */ - (void)resetProfilingTimestamps; # endif // SENTRY_TARGET_PROFILING_SUPPORTED diff --git a/Sources/Sentry/include/SentryProfiler+Test.h b/Sources/Sentry/include/SentryProfiler+Test.h new file mode 100644 index 00000000000..076d243a84a --- /dev/null +++ b/Sources/Sentry/include/SentryProfiler+Test.h @@ -0,0 +1,11 @@ +#import "SentryProfiler.h" +#import "SentryProfilingConditionals.h" + +#if SENTRY_TARGET_PROFILING_SUPPORTED +@interface +SentryProfiler (SentryTest) + ++ (void)timeoutAbort; + +@end +#endif // SENTRY_TARGET_PROFILING_SUPPORTED diff --git a/Sources/Sentry/include/SentryProfiler.h b/Sources/Sentry/include/SentryProfiler.h index 9c68c9e65cb..52316906529 100644 --- a/Sources/Sentry/include/SentryProfiler.h +++ b/Sources/Sentry/include/SentryProfiler.h @@ -1,15 +1,31 @@ +#import "SentryCompiler.h" #import "SentryProfilingConditionals.h" +#import "SentrySpan.h" #import -#if SENTRY_TARGET_PROFILING_SUPPORTED - -# import "SentryCompiler.h" - +#if SENTRY_HAS_UIKIT +@class SentryFramesTracker; +#endif // SENTRY_HAS_UIKIT @class SentryHub; +@class SentryProfilesSamplerDecision; @class SentryScreenFrames; +@class SentryEnvelope; +@class SentrySpanId; +@class SentryTransaction; + +#if SENTRY_TARGET_PROFILING_SUPPORTED + +typedef NS_ENUM(NSUInteger, SentryProfilerTruncationReason) { + SentryProfilerTruncationReasonNormal, + SentryProfilerTruncationReasonTimeout, + SentryProfilerTruncationReasonAppMovedToBackground, +}; NS_ASSUME_NONNULL_BEGIN +FOUNDATION_EXPORT const int kSentryProfilerFrequencyHz; +FOUNDATION_EXPORT NSString *const kTestStringConst; + SENTRY_EXTERN_C_BEGIN /* @@ -24,31 +40,43 @@ SENTRY_EXTERN_C_BEGIN */ NSString *parseBacktraceSymbolsFunctionName(const char *symbol); -SENTRY_EXTERN_C_END +NSString *profilerTruncationReasonName(SentryProfilerTruncationReason reason); -@class SentryEnvelopeItem, SentryTransaction; +SENTRY_EXTERN_C_END @interface SentryProfiler : NSObject -/** Clears all accumulated profiling data and starts profiling. */ -- (void)start; +/** + * Start the profiler, if it isn't already running, for the span with the provided ID. If it's + * already running, it will track the new span as well. + */ ++ (void)startForSpanID:(SentrySpanId *)spanID hub:(SentryHub *)hub; -/** Stops profiling. */ -- (void)stop; +/** + * Report that a span ended to the profiler so it can update bookkeeping and if it was the last + * concurrent span being profiled, stops the profiler. + */ ++ (void)stopProfilingSpan:(id)span; -/** Whether or not the sampling profiler is currently running. */ -- (BOOL)isRunning; +/** + * Certain transactions may be dropped by the SDK at the time they are ended, when we've already + * been tracking them for profiling. This allows them to be removed from bookkeeping and finish + * profile if necessary. + */ ++ (void)dropTransaction:(SentryTransaction *)transaction; +; /** - * Builds an envelope item using the currently accumulated profile data. + * After the SDK creates a transaction for a span, link it to this profile. If it was the last + * concurrent span being profiled, capture an envelope with the profile data and clean up the + * profiler. */ -- (nullable SentryEnvelopeItem *)buildEnvelopeItemForTransaction:(SentryTransaction *)transaction - hub:(SentryHub *)hub - frameInfo: - (nullable SentryScreenFrames *)frameInfo; ++ (void)linkTransaction:(SentryTransaction *)transaction; + ++ (BOOL)isRunning; @end NS_ASSUME_NONNULL_END -#endif +#endif // SENTRY_TARGET_PROFILING_SUPPORTED diff --git a/Sources/Sentry/include/SentryTracer.h b/Sources/Sentry/include/SentryTracer.h index 2881ace6d50..37f18fafc1d 100644 --- a/Sources/Sentry/include/SentryTracer.h +++ b/Sources/Sentry/include/SentryTracer.h @@ -42,11 +42,6 @@ static NSTimeInterval const SentryTracerDefaultTimeout = 3.0; */ @property (readonly) BOOL isFinished; -#if SENTRY_TARGET_PROFILING_SUPPORTED -/** Whether the profiler is currently running. */ -@property (assign, readonly) BOOL isProfiling; -#endif // SENTRY_TARGET_PROFILING_SUPPORTED - @property (nullable, nonatomic, copy) void (^finishCallback)(SentryTracer *); /** diff --git a/Tests/SentryTests/Performance/SentryTracerTests.swift b/Tests/SentryTests/Performance/SentryTracerTests.swift index 62d1e4b7d66..c0ab052ec96 100644 --- a/Tests/SentryTests/Performance/SentryTracerTests.swift +++ b/Tests/SentryTests/Performance/SentryTracerTests.swift @@ -728,42 +728,6 @@ class SentryTracerTests: XCTestCase { XCTAssertEqual(dict, [fixture.testKey: fixture.testValue]) } -#if os(iOS) || os(macOS) || targetEnvironment(macCatalyst) - func testCapturesProfile_whenProfilingEnabled() { - let scope = Scope() - let options = Options() - options.profilesSampleRate = 1.0 - options.tracesSampleRate = 1.0 - let client = TestClient(options: options)! - let hub = TestHub(client: client, andScope: scope) - - let tracer = hub.startTransaction(transactionContext: fixture.transactionContext) as! SentryTracer - tracer.finish() - hub.group.wait() - - XCTAssertEqual("profile", hub.capturedEventsWithScopes.first?.additionalEnvelopeItems.first?.header.type) - } - - func testDoesNotCapturesProfile_whenProfilingDisabled() { - let scope = Scope() - let options = Options() - options.profilesSampleRate = 0.0 - options.tracesSampleRate = 1.0 - let client = TestClient(options: options)! - let hub = TestHub(client: client, andScope: scope) - - let tracer = hub.startTransaction(transactionContext: fixture.transactionContext) as! SentryTracer - tracer.finish() - hub.group.wait() - - if let items = hub.capturedEventsWithScopes.first?.additionalEnvelopeItems { - for item in items { - XCTAssertNotEqual("profile", item.header.type) - } - } - } -#endif - private func advanceTime(bySeconds: TimeInterval) { fixture.currentDateProvider.setDate(date: fixture.currentDateProvider.date().addingTimeInterval(bySeconds)) diff --git a/Tests/SentryTests/Profiling/SentryProfilerSwiftTests.swift b/Tests/SentryTests/Profiling/SentryProfilerSwiftTests.swift new file mode 100644 index 00000000000..6530b5e1d41 --- /dev/null +++ b/Tests/SentryTests/Profiling/SentryProfilerSwiftTests.swift @@ -0,0 +1,357 @@ +import Sentry +import XCTest + +#if os(iOS) || os(macOS) || targetEnvironment(macCatalyst) +class SentryProfilerSwiftTests: XCTestCase { + private static let dsnAsString = TestConstants.dsnAsString(username: "SentryProfilerSwiftTests") + + private class Fixture { + lazy var options: Options = { + let options = Options() + options.dsn = SentryProfilerSwiftTests.dsnAsString + return options + }() + lazy var client: TestClient! = TestClient(options: options) + lazy var hub: SentryHub = { + let hub = SentryHub(client: client, andScope: scope) + hub.bindClient(client) + Dynamic(hub).tracesSampler.random = TestRandom(value: 1.0) + Dynamic(hub).profilesSampler.random = TestRandom(value: 0.5) + return hub + }() + let scope = Scope() + let message = "some message" + let transactionName = "Some Transaction" + let transactionOperation = "Some Operation" + } + + private var fixture: Fixture! + + override func setUp() { + super.setUp() + fixture = Fixture() + SentryTracer.resetAppStartMeasurementRead() + } + + override func tearDown() { + super.tearDown() + clearTestState() + SentryTracer.resetAppStartMeasurementRead() +#if os(iOS) || os(tvOS) || targetEnvironment(macCatalyst) + SentryFramesTracker.sharedInstance().resetFrames() + SentryFramesTracker.sharedInstance().stop() +#endif + } + + func testConcurrentProfilingTransactions() { + let options = fixture.options + options.profilesSampleRate = 1.0 + options.tracesSampleRate = 1.0 + + let numberOfTransactions = 10 + var spans = [Span]() + for _ in 0 ..< numberOfTransactions { + spans.append(fixture.hub.startTransaction(name: fixture.transactionName, operation: fixture.transactionOperation)) + } + + forceProfilerSample() + + spans.forEach { $0.finish() } + + guard let envelope = self.fixture.client.captureEnvelopeInvocations.first else { + XCTFail("Expected to capture 1 event") + return + } + XCTAssertEqual(1, envelope.items.count) + guard let profileItem = envelope.items.first else { + XCTFail("Expected an envelope item") + return + } + XCTAssertEqual("profile", profileItem.header.type) + self.assertValidProfileData(data: profileItem.data, numberOfTransactions: numberOfTransactions) + } + + /// Test a situation where a long-running span starts the profiler, which winds up timing out, and then another span starts that begins a new profile, then finishes, and then the long-running span finishes; both profiles should be separately captured in envelopes. + /// ``` + /// time 0s 1s 2s 2.5s 3s (these times are adjusted to the 1s profile timeout for testing only) + /// transaction A |---------------------------------------------------| + /// profiler A |---------------------------x <- timeout + /// transaction B |-------| + /// profiler B |-------| <- normal finish + /// ``` + func testConcurrentSpansWithTimeout() { + let options = fixture.options + options.profilesSampleRate = 1.0 + options.tracesSampleRate = 1.0 + + let spanA = fixture.hub.startTransaction(name: fixture.transactionName, operation: fixture.transactionOperation) + + forceProfilerSample() + + // cause spanA profiler to time out + let exp = expectation(description: "spanA times out") + DispatchQueue.main.asyncAfter(deadline: .now() + 2) { + exp.fulfill() + } + waitForExpectations(timeout: 3) + + let spanB = self.fixture.hub.startTransaction(name: self.fixture.transactionName, operation: self.fixture.transactionOperation) + + forceProfilerSample() + + spanB.finish() + spanA.finish() + + XCTAssertEqual(self.fixture.client.captureEnvelopeInvocations.count, 2) + var currentEnvelope = 0 + for envelope in self.fixture.client.captureEnvelopeInvocations.invocations { + XCTAssertEqual(1, envelope.items.count) + guard let profileItem = envelope.items.first else { + XCTFail("Expected an envelope item") + return + } + XCTAssertEqual("profile", profileItem.header.type) + self.assertValidProfileData(data: profileItem.data, shouldTimeout: currentEnvelope == 1) + currentEnvelope += 1 + } + } + + func testProfileTimeoutTimer() { + fixture.options.profilesSampleRate = 1.0 + fixture.options.tracesSampleRate = 1.0 + performTest(shouldTimeOut: true) + } + + func testStartTransaction_ProfilingDataIsValid() { + fixture.options.profilesSampleRate = 1.0 + fixture.options.tracesSampleRate = 1.0 + performTest() + } + + func testProfilingDataContainsEnvironmentSetFromOptions() { + fixture.options.profilesSampleRate = 1.0 + fixture.options.tracesSampleRate = 1.0 + let expectedEnvironment = "test-environment" + fixture.options.environment = expectedEnvironment + performTest(transactionEnvironment: expectedEnvironment) + } + + func testProfilingDataContainsEnvironmentSetFromConfigureScope() { + fixture.options.profilesSampleRate = 1.0 + fixture.options.tracesSampleRate = 1.0 + let expectedEnvironment = "test-environment" + fixture.hub.configureScope { scope in + scope.setEnvironment(expectedEnvironment) + } + performTest(transactionEnvironment: expectedEnvironment) + } + + func testStartTransaction_NotSamplingProfileUsingEnableProfiling() { + assertProfilesSampler(expectedDecision: .no) { options in + options.enableProfiling_DEPRECATED_TEST_ONLY = false + } + } + + func testStartTransaction_SamplingProfileUsingEnableProfiling() { + assertProfilesSampler(expectedDecision: .yes) { options in + options.enableProfiling_DEPRECATED_TEST_ONLY = true + } + } + + func testStartTransaction_NotSamplingProfileUsingSampleRate() { + assertProfilesSampler(expectedDecision: .no) { options in + options.profilesSampleRate = 0.49 + } + } + + func testStartTransaction_SamplingProfileUsingSampleRate() { + assertProfilesSampler(expectedDecision: .yes) { options in + options.profilesSampleRate = 0.5 + } + } + + func testStartTransaction_SamplingProfileUsingProfilesSampler() { + assertProfilesSampler(expectedDecision: .yes) { options in + options.profilesSampler = { _ in return 0.51 } + } + } + + func testStartTransaction_WhenProfilesSampleRateAndProfilesSamplerNil() { + assertProfilesSampler(expectedDecision: .no) { options in + options.profilesSampleRate = nil + options.profilesSampler = { _ in return nil } + } + } + + func testStartTransaction_WhenProfilesSamplerOutOfRange_TooBig() { + assertProfilesSampler(expectedDecision: .no) { options in + options.profilesSampler = { _ in return 1.01 } + } + } + + func testStartTransaction_WhenProfilesSamplersOutOfRange_TooSmall() { + assertProfilesSampler(expectedDecision: .no) { options in + options.profilesSampler = { _ in return -0.01 } + } + } +} + +private extension SentryProfilerSwiftTests { + /// Keep a thread busy over a long enough period of time (long enough for 3 samples) for the sampler to pick it up. + func forceProfilerSample() { + let str = "a" + var concatStr = "" + for _ in 0..<100_000 { + concatStr = concatStr.appending(str) + } + } + + func performTest(transactionEnvironment: String = kSentryDefaultEnvironment, numberOfTransactions: Int = 1, shouldTimeOut: Bool = false) { + let span = fixture.hub.startTransaction(name: fixture.transactionName, operation: fixture.transactionOperation) + + forceProfilerSample() + + let exp = expectation(description: "profiler should finish") + if shouldTimeOut { + DispatchQueue.main.asyncAfter(deadline: .now() + 2) { + span.finish() + exp.fulfill() + } + } else { + span.finish() + exp.fulfill() + } + + waitForExpectations(timeout: 10) + + 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 an envelope item") + return + } + XCTAssertEqual("profile", profileItem.header.type) + self.assertValidProfileData(data: profileItem.data, transactionEnvironment: transactionEnvironment, numberOfTransactions: numberOfTransactions, shouldTimeout: shouldTimeOut) + + } + + func assertValidProfileData(data: Data, transactionEnvironment: String = kSentryDefaultEnvironment, numberOfTransactions: Int = 1, shouldTimeout: Bool = false) { + let profile = try! JSONSerialization.jsonObject(with: data) as! [String: Any] + XCTAssertEqual("Apple", profile["device_manufacturer"] as! String) + XCTAssertEqual("cocoa", profile["platform"] as! String) + XCTAssertNotNil(profile["transactions"]) + if let transactions = profile["transactions"] as? [[String: String]] { + XCTAssertEqual(transactions.count, numberOfTransactions) + for transaction in transactions { + XCTAssertEqual(fixture.transactionName, transaction["name"]) + XCTAssertNotNil(transaction["id"]) + if let idString = transaction["id"] { + XCTAssertNotEqual(SentryId.empty, SentryId(uuidString: idString)) + } + XCTAssertNotNil(transaction["trace_id"]) + if let traceIDString = transaction["trace_id"] { + XCTAssertNotEqual(SentryId.empty, SentryId(uuidString: traceIDString)) + } + XCTAssertEqual(transactionEnvironment, transaction["environment"]) + XCTAssertNotNil(transaction["trace_id"]) + XCTAssertNotNil(transaction["relative_start_ns"]) + XCTAssertNotNil(transaction["relative_end_ns"]) + } + } else { + XCTFail("Transaction information in profile payload not of expected type.") + } +#if targetEnvironment(macCatalyst) + XCTAssertEqual("iPadOS", profile["device_os_name"] as! String) + XCTAssertFalse((profile["device_os_version"] as! String).isEmpty) +#elseif os(iOS) + XCTAssertEqual("iOS", profile["device_os_name"] as! String) + XCTAssertFalse((profile["device_os_version"] as! String).isEmpty) +#endif + XCTAssertFalse((profile["device_os_build_number"] as! String).isEmpty) + XCTAssertFalse((profile["device_locale"] as! String).isEmpty) + XCTAssertFalse((profile["device_model"] as! String).isEmpty) +#if os(iOS) && !targetEnvironment(macCatalyst) + XCTAssertTrue(profile["device_is_emulator"] as! Bool) +#else + XCTAssertFalse(profile["device_is_emulator"] as! Bool) +#endif + XCTAssertFalse((profile["device_physical_memory_bytes"] as! String).isEmpty) + XCTAssertFalse((profile["version_code"] as! String).isEmpty) + XCTAssertNotEqual(SentryId.empty, SentryId(uuidString: profile["profile_id"] as! String)) + + let images = (profile["debug_meta"] as! [String: Any])["images"] as! [[String: Any]] + XCTAssertFalse(images.isEmpty) + let firstImage = images[0] + XCTAssertFalse((firstImage["code_file"] as! String).isEmpty) + XCTAssertFalse((firstImage["debug_id"] as! String).isEmpty) + XCTAssertFalse((firstImage["image_addr"] as! String).isEmpty) + XCTAssertGreaterThan((firstImage["image_size"] as! Int), 0) + XCTAssertEqual(firstImage["type"] as! String, "macho") + + let sampledProfile = profile["sampled_profile"] as! [String: Any] + let threadMetadata = sampledProfile["thread_metadata"] as! [String: [String: Any]] + let queueMetadata = sampledProfile["queue_metadata"] as! [String: Any] + + XCTAssertFalse(threadMetadata.isEmpty) + XCTAssertFalse(threadMetadata.values.compactMap { $0["priority"] }.filter { ($0 as! Int) > 0 }.isEmpty) + XCTAssertFalse(threadMetadata.values.filter { $0["is_main_thread"] as? Bool == true }.isEmpty) + XCTAssertFalse(queueMetadata.isEmpty) + XCTAssertFalse(((queueMetadata.first?.value as! [String: Any])["label"] as! String).isEmpty) + + let samples = sampledProfile["samples"] as! [[String: Any]] + XCTAssertFalse(samples.isEmpty) + let frames = samples[0]["frames"] as! [[String: Any]] + XCTAssertFalse(frames.isEmpty) + XCTAssertFalse((frames[0]["instruction_addr"] as! String).isEmpty) + XCTAssertFalse((frames[0]["function"] as! String).isEmpty) + if shouldTimeout { + XCTAssertEqual(profile["truncation_reason"] as! String, profilerTruncationReasonName(.timeout)) + } + } + + func assertProfilesSampler(expectedDecision: SentrySampleDecision, options: (Options) -> Void) { + let fixtureOptions = fixture.options + fixtureOptions.tracesSampleRate = 1.0 + fixtureOptions.profilesSampler = { _ in + switch expectedDecision { + case .undecided, .no: + return NSNumber(value: 0) + case .yes: + return NSNumber(value: 1) + @unknown default: + fatalError("Unexpected value for sample decision") + } + } + options(fixtureOptions) + + let hub = fixture.hub + Dynamic(hub).tracesSampler.random = TestRandom(value: 1.0) + + let span = hub.startTransaction(name: fixture.transactionName, operation: fixture.transactionOperation) + let exp = expectation(description: "Span finishes") + DispatchQueue.global().asyncAfter(deadline: .now() + 2.0) { + span.finish() + + switch expectedDecision { + case .undecided, .no: + XCTAssertEqual(0, self.fixture.client.captureEnvelopeInvocations.count) + case .yes: + guard let envelope = self.fixture.client.captureEnvelopeInvocations.first else { + XCTFail("Expected to capture at least 1 event") + return + } + XCTAssertEqual(1, envelope.items.count) + @unknown default: + fatalError("Unexpected value for sample decision") + } + + exp.fulfill() + } + + waitForExpectations(timeout: 3) + } +} +#endif // os(iOS) || os(macOS) || targetEnvironment(macCatalyst) diff --git a/Tests/SentryTests/SentryHubTests.swift b/Tests/SentryTests/SentryHubTests.swift index 549becaadf1..c06bde20805 100644 --- a/Tests/SentryTests/SentryHubTests.swift +++ b/Tests/SentryTests/SentryHubTests.swift @@ -1,8 +1,6 @@ import Sentry import XCTest -// swiftlint:disable file_length - class SentryHubTests: XCTestCase { private static let dsnAsString = TestConstants.dsnAsString(username: "SentryHubTests") @@ -768,271 +766,3 @@ class SentryHubTests: XCTestCase { XCTAssertEqual(expected, span.context.sampled) } } - -#if os(iOS) || os(macOS) || targetEnvironment(macCatalyst) -extension SentryHubTests { - func assertProfilesSampler(expectedDecision: SentrySampleDecision, options: (Options) -> Void) { - let fixtureOptions = fixture.options - fixtureOptions.tracesSampleRate = 1.0 - options(fixtureOptions) - - let hub = fixture.getSut() - Dynamic(hub).tracesSampler.random = TestRandom(value: 1.0) - Dynamic(hub).profilesSampler.random = TestRandom(value: 0.5) - - let span = hub.startTransaction(name: fixture.transactionName, operation: fixture.transactionOperation) - span.finish() - - guard let additionalEnvelopeItems = fixture.client.captureEventWithScopeInvocations.first?.additionalEnvelopeItems else { - XCTFail("Expected to capture at least 1 event") - return - } - switch expectedDecision { - case .undecided, .no: - XCTAssertEqual(0, additionalEnvelopeItems.count) - case .yes: - XCTAssertEqual(1, additionalEnvelopeItems.count) - @unknown default: - fatalError("Unexpected value for sample decision") - } - } - - func testStartTransaction_ProfilingDataIsValid() { - let options = fixture.options - options.profilesSampleRate = 1.0 - options.tracesSampler = {(_: SamplingContext) -> NSNumber in - return 1 - } - let hub = fixture.getSut(options) - let profileExpectation = expectation(description: "collects profiling data") - let span = hub.startTransaction(name: fixture.transactionName, operation: fixture.transactionOperation) - // Give it time to collect a profile, otherwise there will be no samples. - DispatchQueue.global().asyncAfter(deadline: .now() + 2.0) { - span.finish() - - guard let additionalEnvelopeItems = self.fixture.client.captureEventWithScopeInvocations.first?.additionalEnvelopeItems else { - XCTFail("Expected to capture at least 1 event") - return - } - XCTAssertEqual(1, additionalEnvelopeItems.count) - guard let profileItem = additionalEnvelopeItems.first else { - XCTFail("Expected at least 1 additional envelope item") - return - } - XCTAssertEqual("profile", profileItem.header.type) - self.assertValidProfileData(data: profileItem.data, customFields: ["environment": kSentryDefaultEnvironment]) - profileExpectation.fulfill() - } - - // 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) - } - - waitForExpectations(timeout: 5.0) { - if let error = $0 { - print(error) - } - } - } - - func testProfilingDataContainsEnvironmentSetFromOptions() { - let options = fixture.options - options.profilesSampleRate = 1.0 - options.tracesSampler = {(_: SamplingContext) -> NSNumber in - return 1 - } - let expectedEnvironment = "test-environment" - options.environment = expectedEnvironment - let hub = fixture.getSut(options) - let profileExpectation = expectation(description: "collects profiling data") - let span = hub.startTransaction(name: fixture.transactionName, operation: fixture.transactionOperation) - // Give it time to collect a profile, otherwise there will be no samples. - DispatchQueue.global().asyncAfter(deadline: .now() + 2.0) { - span.finish() - - guard let additionalEnvelopeItems = self.fixture.client.captureEventWithScopeInvocations.first?.additionalEnvelopeItems else { - XCTFail("Expected to capture at least 1 event") - return - } - XCTAssertEqual(1, additionalEnvelopeItems.count) - guard let profileItem = additionalEnvelopeItems.first else { - XCTFail("Expected at least 1 additional envelope item") - return - } - XCTAssertEqual("profile", profileItem.header.type) - self.assertValidProfileData(data: profileItem.data, customFields: ["environment": expectedEnvironment]) - profileExpectation.fulfill() - } - - // 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) - } - - waitForExpectations(timeout: 5.0) { - if let error = $0 { - print(error) - } - } - } - - func testProfilingDataContainsEnvironmentSetFromConfigureScope() { - let options = fixture.options - options.profilesSampleRate = 1.0 - options.tracesSampler = {(_: SamplingContext) -> NSNumber in - return 1 - } - let expectedEnvironment = "test-environment" - let hub = fixture.getSut(options) - hub.configureScope { scope in - scope.setEnvironment(expectedEnvironment) - } - let profileExpectation = expectation(description: "collects profiling data") - let span = hub.startTransaction(name: fixture.transactionName, operation: fixture.transactionOperation) - // Give it time to collect a profile, otherwise there will be no samples. - DispatchQueue.global().asyncAfter(deadline: .now() + 2.0) { - span.finish() - - guard let additionalEnvelopeItems = self.fixture.client.captureEventWithScopeInvocations.first?.additionalEnvelopeItems else { - XCTFail("Expected to capture at least 1 event") - return - } - XCTAssertEqual(1, additionalEnvelopeItems.count) - guard let profileItem = additionalEnvelopeItems.first else { - XCTFail("Expected at least 1 additional envelope item") - return - } - XCTAssertEqual("profile", profileItem.header.type) - self.assertValidProfileData(data: profileItem.data, customFields: ["environment": expectedEnvironment]) - profileExpectation.fulfill() - } - - // 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) - } - - waitForExpectations(timeout: 5.0) { - if let error = $0 { - print(error) - } - } - } - - func testStartTransaction_NotSamplingProfileUsingEnableProfiling() { - assertProfilesSampler(expectedDecision: .no) { options in - options.enableProfiling_DEPRECATED_TEST_ONLY = false - } - } - - func testStartTransaction_SamplingProfileUsingEnableProfiling() { - assertProfilesSampler(expectedDecision: .yes) { options in - options.enableProfiling_DEPRECATED_TEST_ONLY = true - } - } - - func testStartTransaction_NotSamplingProfileUsingSampleRate() { - assertProfilesSampler(expectedDecision: .no) { options in - options.profilesSampleRate = 0.49 - } - } - - func testStartTransaction_SamplingProfileUsingSampleRate() { - assertProfilesSampler(expectedDecision: .yes) { options in - options.profilesSampleRate = 0.5 - } - } - - func testStartTransaction_SamplingProfileUsingProfilesSampler() { - assertProfilesSampler(expectedDecision: .yes) { options in - options.profilesSampler = { _ in return 0.51 } - } - } - - func testStartTransaction_WhenProfilesSampleRateAndProfilesSamplerNil() { - assertProfilesSampler(expectedDecision: .no) { options in - options.profilesSampleRate = nil - options.profilesSampler = { _ in return nil } - } - } - - func testStartTransaction_WhenProfilesSamplerOutOfRange_TooBig() { - assertProfilesSampler(expectedDecision: .no) { options in - options.profilesSampler = { _ in return 1.01 } - } - } - - func testStartTransaction_WhenProfilesSamplersOutOfRange_TooSmall() { - assertProfilesSampler(expectedDecision: .no) { options in - options.profilesSampler = { _ in return -0.01 } - } - } - - private func assertValidProfileData(data: Data, customFields: [String: String]) { - let profile = try! JSONSerialization.jsonObject(with: data) as! [String: Any] - XCTAssertEqual("Apple", profile["device_manufacturer"] as! String) - XCTAssertEqual("cocoa", profile["platform"] as! String) - XCTAssertEqual(fixture.transactionName, profile["transaction_name"] as! String) -#if os(iOS) && !targetEnvironment(macCatalyst) - XCTAssertEqual("iOS", profile["device_os_name"] as! String) - XCTAssertFalse((profile["device_os_version"] as! String).isEmpty) -#endif - XCTAssertFalse((profile["device_os_build_number"] as! String).isEmpty) - XCTAssertFalse((profile["device_locale"] as! String).isEmpty) - XCTAssertFalse((profile["device_model"] as! String).isEmpty) -#if os(iOS) && !targetEnvironment(macCatalyst) - XCTAssertTrue(profile["device_is_emulator"] as! Bool) -#else - XCTAssertFalse(profile["device_is_emulator"] as! Bool) -#endif - XCTAssertFalse((profile["device_physical_memory_bytes"] as! String).isEmpty) - XCTAssertFalse((profile["version_code"] as! String).isEmpty) - - XCTAssertNotEqual(SentryId.empty, SentryId(uuidString: profile["transaction_id"] as! String)) - XCTAssertNotEqual(SentryId.empty, SentryId(uuidString: profile["profile_id"] as! String)) - XCTAssertNotEqual(SentryId.empty, SentryId(uuidString: profile["trace_id"] as! String)) - - let images = (profile["debug_meta"] as! [String: Any])["images"] as! [[String: Any]] - XCTAssertFalse(images.isEmpty) - let firstImage = images[0] - XCTAssertFalse((firstImage["code_file"] as! String).isEmpty) - XCTAssertFalse((firstImage["debug_id"] as! String).isEmpty) - XCTAssertFalse((firstImage["image_addr"] as! String).isEmpty) - XCTAssertGreaterThan((firstImage["image_size"] as! Int), 0) - XCTAssertEqual(firstImage["type"] as! String, "macho") - - let sampledProfile = profile["sampled_profile"] as! [String: Any] - let threadMetadata = sampledProfile["thread_metadata"] as! [String: [String: Any]] - let queueMetadata = sampledProfile["queue_metadata"] as! [String: Any] - - XCTAssertFalse(threadMetadata.isEmpty) - XCTAssertFalse(threadMetadata.values.compactMap { $0["priority"] }.filter { ($0 as! Int) > 0 }.isEmpty) - XCTAssertFalse(threadMetadata.values.filter { $0["is_main_thread"] as? Bool == true }.isEmpty) - XCTAssertFalse(queueMetadata.isEmpty) - XCTAssertFalse(((queueMetadata.first?.value as! [String: Any])["label"] as! String).isEmpty) - - let samples = sampledProfile["samples"] as! [[String: Any]] - XCTAssertFalse(samples.isEmpty) - let frames = samples[0]["frames"] as! [[String: Any]] - XCTAssertFalse(frames.isEmpty) - XCTAssertFalse((frames[0]["instruction_addr"] as! String).isEmpty) - XCTAssertFalse((frames[0]["function"] as! String).isEmpty) - for (key, expectedValue) in customFields { - guard let actualValue = profile[key] as? String else { - XCTFail("Expected value not present in profile") - continue - } - XCTAssertEqual(expectedValue, actualValue) - } - } -} -#endif // os(iOS) || os(macOS) || targetEnvironment(macCatalyst) - -// swiftlint:enable file_length diff --git a/Tests/SentryTests/SentryTests-Bridging-Header.h b/Tests/SentryTests/SentryTests-Bridging-Header.h index 1dba179c9e6..51862be092a 100644 --- a/Tests/SentryTests/SentryTests-Bridging-Header.h +++ b/Tests/SentryTests/SentryTests-Bridging-Header.h @@ -114,6 +114,7 @@ #import "SentryPerformanceTracker.h" #import "SentryPerformanceTrackingIntegration.h" #import "SentryPredicateDescriptor.h" +#import "SentryProfiler+Test.h" #import "SentryQueueableRequestManager.h" #import "SentryRandom.h" #import "SentryRateLimitParser.h"