From f938d24c96581fdda0c99af1bff59087d4b69f5c Mon Sep 17 00:00:00 2001 From: Andrew McKnight Date: Mon, 15 May 2023 22:43:09 +0200 Subject: [PATCH] fix: synchronize and copy global profiling data structures (#3018) --- CHANGELOG.md | 6 + Sources/Sentry/SentryProfileTimeseries.mm | 40 +- Sources/Sentry/SentryProfiler.mm | 381 ++++++++++-------- Sources/Sentry/SentryTransactionContext.mm | 9 - .../Sentry/include/SentryProfileTimeseries.h | 7 - Sources/Sentry/include/SentryProfiler+Test.h | 10 +- .../SentryTransactionContext+Private.h | 6 +- .../SentryProfilerTests.mm | 163 +++++++- 8 files changed, 406 insertions(+), 216 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index ad8e1cb7304..35771ff681e 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,5 +1,11 @@ # Changelog +## Unreleased + +### Fixed + +- Fix crashes in profiling serialization race condition (#3018) + ## 8.7.1 ### Features diff --git a/Sources/Sentry/SentryProfileTimeseries.mm b/Sources/Sentry/SentryProfileTimeseries.mm index df4e6327c18..bd1d01c83bc 100644 --- a/Sources/Sentry/SentryProfileTimeseries.mm +++ b/Sources/Sentry/SentryProfileTimeseries.mm @@ -7,8 +7,6 @@ # import "SentryLog.h" # import "SentryTransaction.h" -std::mutex _gSamplesArrayLock; - /** * Print a debug log to help diagnose slicing errors. * @param start @c YES if this is an attempt to find the start of the sliced data based on the @@ -44,27 +42,21 @@ NSArray *_Nullable slicedProfileSamples( NSArray *samples, SentryTransaction *transaction) { - NSArray *samplesCopy; - { - std::lock_guard l(_gSamplesArrayLock); - samplesCopy = [samples copy]; - } - - if (samplesCopy.count == 0) { + if (samples.count == 0) { return nil; } const auto transactionStart = transaction.startSystemTime; const auto firstIndex = - [samplesCopy indexOfObjectWithOptions:NSEnumerationConcurrent - passingTest:^BOOL(SentrySample *_Nonnull sample, NSUInteger idx, - BOOL *_Nonnull stop) { - *stop = sample.absoluteTimestamp >= transactionStart; - return *stop; - }]; + [samples indexOfObjectWithOptions:NSEnumerationConcurrent + passingTest:^BOOL(SentrySample *_Nonnull sample, NSUInteger idx, + BOOL *_Nonnull stop) { + *stop = sample.absoluteTimestamp >= transactionStart; + return *stop; + }]; if (firstIndex == NSNotFound) { - logSlicingFailureWithArray(samplesCopy, transaction, /*start*/ YES); + logSlicingFailureWithArray(samples, transaction, /*start*/ YES); return nil; } else { SENTRY_LOG_DEBUG(@"Found first slice sample at index %lu", firstIndex); @@ -72,15 +64,15 @@ const auto transactionEnd = transaction.endSystemTime; const auto lastIndex = - [samplesCopy indexOfObjectWithOptions:NSEnumerationConcurrent | NSEnumerationReverse - passingTest:^BOOL(SentrySample *_Nonnull sample, NSUInteger idx, - BOOL *_Nonnull stop) { - *stop = sample.absoluteTimestamp <= transactionEnd; - return *stop; - }]; + [samples indexOfObjectWithOptions:NSEnumerationConcurrent | NSEnumerationReverse + passingTest:^BOOL(SentrySample *_Nonnull sample, NSUInteger idx, + BOOL *_Nonnull stop) { + *stop = sample.absoluteTimestamp <= transactionEnd; + return *stop; + }]; if (lastIndex == NSNotFound) { - logSlicingFailureWithArray(samplesCopy, transaction, /*start*/ NO); + logSlicingFailureWithArray(samples, transaction, /*start*/ NO); return nil; } else { SENTRY_LOG_DEBUG(@"Found last slice sample at index %lu", lastIndex); @@ -88,7 +80,7 @@ const auto range = NSMakeRange(firstIndex, (lastIndex - firstIndex) + 1); const auto indices = [NSIndexSet indexSetWithIndexesInRange:range]; - return [samplesCopy objectsAtIndexes:indices]; + return [samples objectsAtIndexes:indices]; } @implementation SentrySample diff --git a/Sources/Sentry/SentryProfiler.mm b/Sources/Sentry/SentryProfiler.mm index 21e011d8a95..5d001a2ac3e 100644 --- a/Sources/Sentry/SentryProfiler.mm +++ b/Sources/Sentry/SentryProfiler.mm @@ -79,44 +79,19 @@ return [symbolNSStr substringWithRange:[match rangeAtIndex:1]]; } +std::mutex _gDataStructureLock; + void processBacktrace(const Backtrace &backtrace, NSMutableDictionary *threadMetadata, NSMutableDictionary *queueMetadata, - NSMutableArray *samples, NSMutableArray *> *stacks, + NSMutableArray *samples, NSMutableArray *> *stacks, NSMutableArray *> *frames, NSMutableDictionary *frameIndexLookup, NSMutableDictionary *stackIndexLookup) { - const auto threadID = sentry_stringForUInt64(backtrace.threadMetadata.threadID); - - NSString *queueAddress = nil; - if (backtrace.queueMetadata.address != 0) { - queueAddress = sentry_formatHexAddressUInt64(backtrace.queueMetadata.address); - } - NSMutableDictionary *metadata = threadMetadata[threadID]; - if (metadata == nil) { - metadata = [NSMutableDictionary dictionary]; - threadMetadata[threadID] = metadata; - } - if (!backtrace.threadMetadata.name.empty() && metadata[@"name"] == nil) { - metadata[@"name"] = [NSString stringWithUTF8String:backtrace.threadMetadata.name.c_str()]; - } - if (backtrace.threadMetadata.priority != -1 && metadata[@"priority"] == nil) { - metadata[@"priority"] = @(backtrace.threadMetadata.priority); - } - if (queueAddress != nil && queueMetadata[queueAddress] == nil - && backtrace.queueMetadata.label != nullptr) { - queueMetadata[queueAddress] = - @ { @"label" : [NSString stringWithUTF8String:backtrace.queueMetadata.label->c_str()] }; - } -# if defined(DEBUG) - const auto symbols - = backtrace_symbols(reinterpret_cast(backtrace.addresses.data()), - static_cast(backtrace.addresses.size())); -# endif - const auto stack = [NSMutableArray array]; + const auto framesToAdd = [NSMutableArray *> array]; for (std::vector::size_type backtraceAddressIdx = 0; backtraceAddressIdx < backtrace.addresses.size(); backtraceAddressIdx++) { const auto instructionAddress @@ -127,11 +102,14 @@ const auto frame = [NSMutableDictionary dictionary]; frame[@"instruction_addr"] = instructionAddress; # if defined(DEBUG) + const auto symbols + = backtrace_symbols(reinterpret_cast(backtrace.addresses.data()), + static_cast(backtrace.addresses.size())); frame[@"function"] = parseBacktraceSymbolsFunctionName(symbols[backtraceAddressIdx]); # endif [stack addObject:@(frames.count)]; frameIndexLookup[instructionAddress] = @(frames.count); - [frames addObject:frame]; + [framesToAdd addObject:frame]; } else { [stack addObject:frameIndex]; } @@ -140,9 +118,15 @@ const auto sample = [[SentrySample alloc] init]; sample.absoluteTimestamp = backtrace.absoluteTimestamp; sample.threadID = backtrace.threadMetadata.threadID; + + NSString *queueAddress = nil; + if (backtrace.queueMetadata.address != 0) { + queueAddress = sentry_formatHexAddressUInt64(backtrace.queueMetadata.address); + } if (queueAddress != nil) { sample.queueAddress = queueAddress; } + const auto stackKey = [stack componentsJoinedByString:@"|"]; const auto stackIndex = stackIndexLookup[stackKey]; if (stackIndex) { @@ -151,12 +135,49 @@ const auto nextStackIndex = @(stacks.count); sample.stackIndex = nextStackIndex; stackIndexLookup[stackKey] = nextStackIndex; - [stacks addObject:stack]; } { - std::lock_guard l(_gSamplesArrayLock); + // critical section: here is where all mutable data structures are updated, which must be + // copied later during serialization, so we need enforce exclusive access + std::lock_guard l(_gDataStructureLock); + + // update queue metadata if we have any and it isn't already recorded from a previous sample + if (queueAddress != nil && queueMetadata[queueAddress] == nil + && backtrace.queueMetadata.label != nullptr) { + queueMetadata[queueAddress] = @ { + @"label" : [NSString stringWithUTF8String:backtrace.queueMetadata.label->c_str()] + }; + } + + // The following can overwrite thread metadata that was previously recorded for a thread, + // when between samples if we find that the metadata is not present on one sample but is + // present for a subsequent sample on the same thread. This occasionally happens when we + // can't read the metadata for a thread (unclear why this happens but it tends to happen + // sometimes for a newly created thread). + const auto threadID = sentry_stringForUInt64(backtrace.threadMetadata.threadID); + NSMutableDictionary *metadata = threadMetadata[threadID]; + if (metadata == nil) { + metadata = [NSMutableDictionary dictionary]; + threadMetadata[threadID] = metadata; + } + if (!backtrace.threadMetadata.name.empty() && metadata[@"name"] == nil) { + metadata[@"name"] = + [NSString stringWithUTF8String:backtrace.threadMetadata.name.c_str()]; + } + if (backtrace.threadMetadata.priority != -1 && metadata[@"priority"] == nil) { + metadata[@"priority"] = @(backtrace.threadMetadata.priority); + } + + // add the new sample to the data structure [samples addObject:sample]; + + // add the stack if it isn't already cached in the lookup index + if (stackIndex == nil) { + [stacks addObject:stack]; + } + + [frames addObjectsFromArray:framesToAdd]; } } @@ -264,6 +285,142 @@ return result; } +NSDictionary * +serializedProfileData(NSDictionary *profileData, SentryTransaction *transaction, + SentryId *profileID, NSString *truncationReason, NSString *environment, NSString *release, + NSDictionary *serializedMetrics, NSArray *debugMeta) +{ + NSArray *samplesCopy; + NSArray *> *stacksCopy; + NSArray *> *framesCopy; + NSMutableDictionary *threadMetadataCopy; + NSDictionary *queueMetadataCopy; + { + std::lock_guard d(_gDataStructureLock); + samplesCopy = [profileData[@"profile"][@"samples"] copy]; + stacksCopy = [profileData[@"profile"][@"stacks"] copy]; + framesCopy = [profileData[@"profile"][@"frames"] copy]; + queueMetadataCopy = [profileData[@"profile"][@"queue_metadata"] copy]; + + // thread metadata contains a mutable substructure, so it's not enough to perform a copy of + // the top-level dictionary, we need to go deeper to copy the mutable subdictionaries + threadMetadataCopy = [NSMutableDictionary dictionary]; + [((NSDictionary *)profileData[@"profile"][@"thread_metadata"]) + enumerateKeysAndObjectsUsingBlock:^(NSString *_Nonnull key, NSDictionary *_Nonnull obj, + BOOL *_Nonnull stop) { threadMetadataCopy[key] = [obj copy]; }]; + } + + // We need at least two samples to be able to draw a stack frame for any given function: one + // sample for the start of the frame and another for the end. Otherwise we would only have a + // stack frame with 0 duration, which wouldn't make sense. + if ([samplesCopy count] < 2) { + SENTRY_LOG_DEBUG(@"Not enough samples in profile"); + return nil; + } + + // slice the profile data to only include the samples/metrics within the transaction + const auto slicedSamples = slicedProfileSamples(samplesCopy, transaction); + if (slicedSamples.count < 2) { + SENTRY_LOG_DEBUG(@"Not enough samples in profile during the transaction"); + return nil; + } + + const auto payload = [NSMutableDictionary dictionary]; + + payload[@"version"] = @"1"; + const auto debugImages = [NSMutableArray *> new]; + for (SentryDebugMeta *debugImage in debugMeta) { + [debugImages addObject:[debugImage serialize]]; + } + if (debugImages.count > 0) { + payload[@"debug_meta"] = @ { @"images" : debugImages }; + } + + payload[@"os"] = @ { + @"name" : sentry_getOSName(), + @"version" : sentry_getOSVersion(), + @"build_number" : sentry_getOSBuildNumber() + }; + + const auto isEmulated = sentry_isSimulatorBuild(); + payload[@"device"] = @{ + @"architecture" : sentry_getCPUArchitecture(), + @"is_emulator" : @(isEmulated), + @"locale" : NSLocale.currentLocale.localeIdentifier, + @"manufacturer" : @"Apple", + @"model" : isEmulated ? sentry_getSimulatorDeviceModel() : sentry_getDeviceModel() + }; + + payload[@"profile_id"] = profileID.sentryIdString; + payload[@"truncation_reason"] = truncationReason; + payload[@"platform"] = transaction.platform; + payload[@"environment"] = environment; + + const auto timestamp = transaction.trace.originalStartTimestamp; + if (UNLIKELY(timestamp == nil)) { + SENTRY_LOG_WARN(@"There was no start timestamp on the provided transaction. Falling back " + @"to old behavior of using the current time."); + payload[@"timestamp"] = [[SentryCurrentDate date] sentry_toIso8601String]; + } else { + payload[@"timestamp"] = [timestamp sentry_toIso8601String]; + } + + payload[@"release"] = release; + + payload[@"profile"] = @ { + @"samples" : serializedSamplesWithRelativeTimestamps(slicedSamples, transaction), + @"stacks" : stacksCopy, + @"frames" : framesCopy, + @"thread_metadata" : threadMetadataCopy, + @"queue_metadata" : queueMetadataCopy, + }; + + payload[@"transaction"] = @ { + @"id" : transaction.eventId.sentryIdString, + @"trace_id" : transaction.trace.traceId.sentryIdString, + @"name" : transaction.transaction, + @"active_thread_id" : [transaction.trace.transactionContext sentry_threadInfo].threadId + }; + + // add the gathered metrics + auto metrics = serializedMetrics; + +# if SENTRY_HAS_UIKIT + const auto mutableMetrics = + [NSMutableDictionary dictionaryWithDictionary:metrics]; + const auto slowFrames = sliceGPUData(_gCurrentFramesTracker.currentFrames.slowFrameTimestamps, + transaction, /*useMostRecentRecording */ NO); + if (slowFrames.count > 0) { + mutableMetrics[@"slow_frame_renders"] = + @ { @"unit" : @"nanosecond", @"values" : slowFrames }; + } + + const auto frozenFrames + = sliceGPUData(_gCurrentFramesTracker.currentFrames.frozenFrameTimestamps, transaction, + /*useMostRecentRecording */ NO); + if (frozenFrames.count > 0) { + mutableMetrics[@"frozen_frame_renders"] = + @ { @"unit" : @"nanosecond", @"values" : frozenFrames }; + } + + if (slowFrames.count > 0 || frozenFrames.count > 0) { + const auto frameRates + = sliceGPUData(_gCurrentFramesTracker.currentFrames.frameRateTimestamps, transaction, + /*useMostRecentRecording */ YES); + if (frameRates.count > 0) { + mutableMetrics[@"screen_frame_rates"] = @ { @"unit" : @"hz", @"values" : frameRates }; + } + } + metrics = mutableMetrics; +# endif // SENTRY_HAS_UIKIT + + if (metrics.count > 0) { + payload[@"measurements"] = metrics; + } + + return payload; +} + @implementation SentryProfiler { NSMutableDictionary *_profileData; std::shared_ptr _profiler; @@ -353,78 +510,8 @@ + (BOOL)isRunning + (SentryEnvelopeItem *)createProfilingEnvelopeItemForTransaction:(SentryTransaction *)transaction { - std::lock_guard l(_gProfilerLock); - - if (_gCurrentProfiler == nil) { - SENTRY_LOG_DEBUG(@"No profiler from which to receive data."); - return nil; - } - - const auto payload = [NSMutableDictionary dictionary]; - - NSArray *samples = _gCurrentProfiler->_profileData[@"profile"][@"samples"]; - - // We need at least two samples to be able to draw a stack frame for any given function: one - // sample for the start of the frame and another for the end. Otherwise we would only have a - // stack frame with 0 duration, which wouldn't make sense. - if ([samples count] < 2) { - SENTRY_LOG_DEBUG(@"Not enough samples in profile"); - return nil; - } - - // slice the profile data to only include the samples/metrics within the transaction - const auto slicedSamples = slicedProfileSamples(samples, transaction); - if (slicedSamples.count < 2) { - SENTRY_LOG_DEBUG(@"Not enough samples in profile during the transaction"); - return nil; - } - - payload[@"profile"] = @{ - @"samples" : serializedSamplesWithRelativeTimestamps(slicedSamples, transaction), - @"stacks" : _gCurrentProfiler->_profileData[@"profile"][@"stacks"], - @"frames" : _gCurrentProfiler->_profileData[@"profile"][@"frames"], - @"thread_metadata" : _gCurrentProfiler->_profileData[@"profile"][@"thread_metadata"], - @"queue_metadata" : _gCurrentProfiler->_profileData[@"profile"][@"queue_metadata"], - }; - - // add the serialized info for the associated transaction - const auto transactionInfo = [self serializeInfoForTransaction:transaction]; - if (!transactionInfo) { - SENTRY_LOG_WARN(@"Could not find any associated transaction for the profile."); - return nil; - } - payload[@"transaction"] = transactionInfo; - - // add the gathered metrics - const auto metrics = [_gCurrentProfiler->_metricProfiler serializeForTransaction:transaction]; - -# if SENTRY_HAS_UIKIT - const auto slowFrames = sliceGPUData(_gCurrentFramesTracker.currentFrames.slowFrameTimestamps, - transaction, /*useMostRecentRecording */ NO); - if (slowFrames.count > 0) { - metrics[@"slow_frame_renders"] = @{ @"unit" : @"nanosecond", @"values" : slowFrames }; - } - - const auto frozenFrames - = sliceGPUData(_gCurrentFramesTracker.currentFrames.frozenFrameTimestamps, transaction, - /*useMostRecentRecording */ NO); - if (frozenFrames.count > 0) { - metrics[@"frozen_frame_renders"] = @{ @"unit" : @"nanosecond", @"values" : frozenFrames }; - } - - if (slowFrames.count > 0 || frozenFrames.count > 0) { - const auto frameRates - = sliceGPUData(_gCurrentFramesTracker.currentFrames.frameRateTimestamps, transaction, - /*useMostRecentRecording */ YES); - if (frameRates.count > 0) { - metrics[@"screen_frame_rates"] = @{ @"unit" : @"hz", @"values" : frameRates }; - } - } -# endif // SENTRY_HAS_UIKIT - - if (metrics.count > 0) { - payload[@"measurements"] = metrics; - } + const auto profileID = [[SentryId alloc] init]; + const auto payload = [self serializeForTransaction:transaction profileID:profileID]; # if defined(TEST) || defined(TESTCI) [NSNotificationCenter.defaultCenter postNotificationName:@"SentryProfileCompleteNotification" @@ -432,10 +519,6 @@ + (SentryEnvelopeItem *)createProfilingEnvelopeItemForTransaction:(SentryTransac userInfo:payload]; # endif // defined(TEST) || defined(TESTCI) - // add the remaining basic metadata for the profile - const auto profileID = [[SentryId alloc] init]; - [self serializeBasicProfileInfo:payload profileID:profileID transaction:transaction]; - return [self envelopeItemForProfileData:payload profileID:profileID]; } @@ -475,6 +558,25 @@ + (void)useFramesTracker:(SentryFramesTracker *)framesTracker # pragma mark - Private ++ (NSDictionary *)serializeForTransaction:(SentryTransaction *)transaction + profileID:(SentryId *)profileID +{ + std::lock_guard l(_gProfilerLock); + + if (_gCurrentProfiler == nil) { + SENTRY_LOG_DEBUG(@"No profiler from which to receive data."); + return nil; + } + + return serializedProfileData(_gCurrentProfiler->_profileData, transaction, profileID, + profilerTruncationReasonName(_gCurrentProfiler->_truncationReason), + _gCurrentProfiler->_hub.scope.environmentString + ?: _gCurrentProfiler->_hub.getClient.options.environment, + _gCurrentProfiler->_hub.getClient.options.releaseName, + [_gCurrentProfiler->_metricProfiler serializeForTransaction:transaction], + [_gCurrentProfiler->_debugImageProvider getDebugImages]); +} + + (void)timeoutAbort { std::lock_guard l(_gProfilerLock); @@ -614,7 +716,7 @@ - (void)start * ] */ const auto samples = [NSMutableArray array]; - const auto stacks = [NSMutableArray *> array]; + const auto stacks = [NSMutableArray *> array]; const auto frames = [NSMutableArray *> array]; const auto frameIndexLookup = [NSMutableDictionary dictionary]; const auto stackIndexLookup = [NSMutableDictionary dictionary]; @@ -674,66 +776,7 @@ - (void)stop SENTRY_LOG_DEBUG(@"Stopped profiler %@.", self); } -+ (void)serializeBasicProfileInfo:(NSMutableDictionary *)profile - profileID:(SentryId *const &)profileID - transaction:(SentryTransaction *)transaction -{ - profile[@"version"] = @"1"; - const auto debugImages = [NSMutableArray *> new]; - const auto debugMeta = [_gCurrentProfiler->_debugImageProvider getDebugImages]; - for (SentryDebugMeta *debugImage in debugMeta) { - [debugImages addObject:[debugImage serialize]]; - } - if (debugImages.count > 0) { - profile[@"debug_meta"] = @{ @"images" : debugImages }; - } - - profile[@"os"] = @{ - @"name" : sentry_getOSName(), - @"version" : sentry_getOSVersion(), - @"build_number" : sentry_getOSBuildNumber() - }; - - const auto isEmulated = sentry_isSimulatorBuild(); - profile[@"device"] = @{ - @"architecture" : sentry_getCPUArchitecture(), - @"is_emulator" : @(isEmulated), - @"locale" : NSLocale.currentLocale.localeIdentifier, - @"manufacturer" : @"Apple", - @"model" : isEmulated ? sentry_getSimulatorDeviceModel() : sentry_getDeviceModel() - }; - - profile[@"profile_id"] = profileID.sentryIdString; - profile[@"truncation_reason"] - = profilerTruncationReasonName(_gCurrentProfiler->_truncationReason); - profile[@"platform"] = transaction.platform; - profile[@"environment"] = _gCurrentProfiler->_hub.scope.environmentString - ?: _gCurrentProfiler->_hub.getClient.options.environment; - - const auto timestamp = transaction.trace.originalStartTimestamp; - if (UNLIKELY(timestamp == nil)) { - SENTRY_LOG_WARN(@"There was no start timestamp on the provided transaction. Falling back " - @"to old behavior of using the current time."); - profile[@"timestamp"] = [[SentryCurrentDate date] sentry_toIso8601String]; - } else { - profile[@"timestamp"] = [timestamp sentry_toIso8601String]; - } - - profile[@"release"] = _gCurrentProfiler->_hub.getClient.options.releaseName; -} - -/** @return serialize info corresponding to the specified transaction. */ -+ (NSDictionary *)serializeInfoForTransaction:(SentryTransaction *)transaction -{ - return @{ - @"id" : transaction.eventId.sentryIdString, - @"trace_id" : transaction.trace.traceId.sentryIdString, - @"name" : transaction.transaction, - @"active_thread_id" : [transaction.trace.transactionContext sentry_threadInfo].threadId - }; -} - -+ (SentryEnvelopeItem *)envelopeItemForProfileData:(NSMutableDictionary *)profile ++ (SentryEnvelopeItem *)envelopeItemForProfileData:(NSDictionary *)profile profileID:(SentryId *)profileID { const auto JSONData = [SentrySerialization dataWithJSONObject:profile]; diff --git a/Sources/Sentry/SentryTransactionContext.mm b/Sources/Sentry/SentryTransactionContext.mm index 73bec3d3589..d0b94b9fe66 100644 --- a/Sources/Sentry/SentryTransactionContext.mm +++ b/Sources/Sentry/SentryTransactionContext.mm @@ -11,15 +11,6 @@ static const auto kSentryDefaultSamplingDecision = kSentrySampleDecisionUndecided; -@interface -SentryTransactionContext () - -#if SENTRY_TARGET_PROFILING_SUPPORTED -@property (nonatomic, strong) SentryThread *threadInfo; -#endif - -@end - @implementation SentryTransactionContext #pragma mark - Public diff --git a/Sources/Sentry/include/SentryProfileTimeseries.h b/Sources/Sentry/include/SentryProfileTimeseries.h index cac370d2324..a8d2203df5f 100644 --- a/Sources/Sentry/include/SentryProfileTimeseries.h +++ b/Sources/Sentry/include/SentryProfileTimeseries.h @@ -8,13 +8,6 @@ @class SentryTransaction; -/** - * Synchronizes reads and writes to the samples array; otherwise there will be a data race between - * when the sampling profiler tries to insert a new sample, and when we iterate over the sample - * array with fast enumeration to extract only those samples needed for a given transaction. - */ -SENTRY_EXTERN std::mutex _gSamplesArrayLock; - NS_ASSUME_NONNULL_BEGIN /** A storage class to hold the data associated with a single profiler sample. */ diff --git a/Sources/Sentry/include/SentryProfiler+Test.h b/Sources/Sentry/include/SentryProfiler+Test.h index 958c10a5008..d8bb5f233ed 100644 --- a/Sources/Sentry/include/SentryProfiler+Test.h +++ b/Sources/Sentry/include/SentryProfiler+Test.h @@ -4,18 +4,26 @@ #if SENTRY_TARGET_PROFILING_SUPPORTED +@class SentryDebugMeta; +@class SentryId; @class SentrySample; +@class SentryTransaction; NS_ASSUME_NONNULL_BEGIN void processBacktrace(const sentry::profiling::Backtrace &backtrace, NSMutableDictionary *threadMetadata, NSMutableDictionary *queueMetadata, - NSMutableArray *samples, NSMutableArray *> *stacks, + NSMutableArray *samples, NSMutableArray *> *stacks, NSMutableArray *> *frames, NSMutableDictionary *frameIndexLookup, NSMutableDictionary *stackIndexLookup); +NSDictionary *serializedProfileData(NSDictionary *profileData, + SentryTransaction *transaction, SentryId *profileID, NSString *truncationReason, + NSString *environment, NSString *release, NSDictionary *serializedMetrics, + NSArray *debugMeta); + NS_ASSUME_NONNULL_END #endif diff --git a/Sources/Sentry/include/SentryTransactionContext+Private.h b/Sources/Sentry/include/SentryTransactionContext+Private.h index 14f3061e771..92a572c5dfb 100644 --- a/Sources/Sentry/include/SentryTransactionContext+Private.h +++ b/Sources/Sentry/include/SentryTransactionContext+Private.h @@ -4,7 +4,7 @@ NS_ASSUME_NONNULL_BEGIN @interface -SentryTransactionContext (Private) +SentryTransactionContext () - (instancetype)initWithName:(NSString *)name nameSource:(SentryTransactionNameSource)source @@ -37,6 +37,10 @@ SentryTransactionContext (Private) parentSampled:(SentrySampleDecision)parentSampled; #if SENTRY_TARGET_PROFILING_SUPPORTED +// This is currently only exposed for testing purposes, see -[SentryProfilerTests +// testProfilerMutationDuringSerialization] +@property (nonatomic, strong) SentryThread *threadInfo; + - (SentryThread *)sentry_threadInfo; #endif diff --git a/Tests/SentryProfilerTests/SentryProfilerTests.mm b/Tests/SentryProfilerTests/SentryProfilerTests.mm index b947c6bedb1..052bfa1665c 100644 --- a/Tests/SentryProfilerTests/SentryProfilerTests.mm +++ b/Tests/SentryProfilerTests/SentryProfilerTests.mm @@ -1,8 +1,11 @@ #import "SentryEvent+Private.h" +#import "SentryId.h" #import "SentryProfileTimeseries.h" #import "SentryProfiler+Test.h" #import "SentryProfilingConditionals.h" +#import "SentryThread.h" #import "SentryTransaction.h" +#import "SentryTransactionContext+Private.h" #if SENTRY_TARGET_PROFILING_SUPPORTED @@ -60,7 +63,7 @@ - (void)testProfilerMutationDuringSlicing const auto resolvedThreadMetadata = [NSMutableDictionary dictionary]; const auto resolvedQueueMetadata = [NSMutableDictionary dictionary]; - const auto resolvedStacks = [NSMutableArray *> array]; + const auto resolvedStacks = [NSMutableArray *> array]; const auto resolvedSamples = [NSMutableArray array]; const auto resolvedFrames = [NSMutableArray *> array]; const auto frameIndexLookup = [NSMutableDictionary dictionary]; @@ -168,12 +171,153 @@ - (void)testProfilerMutationDuringSlicing [self waitForExpectationsWithTimeout:1 handler:nil]; } +/** + * We received reports of crashes happening during serialization, which turned out to be caused by a + * data race in the collections we use to store profiler information, which are block-enumerated by + * NSJSONSerialization, which is not a thread-safe operation. So when the backtrace profiler + * modified the same collection from another thread while the block enumeration was in progress, a + * crash occurred. The solution is twofold: + * 1. copy the data structures so that serialization works with a new instance that will never be + * modified by the backtrace sampler thread + * 2. force exclusive access to the data structures so that they are never modified during any + * other operation, even the copy + */ +- (void)testProfilerMutationDuringSerialization +{ + const auto resolvedThreadMetadata = + [NSMutableDictionary dictionary]; + const auto resolvedQueueMetadata = [NSMutableDictionary dictionary]; + const auto resolvedStacks = [NSMutableArray *> array]; + const auto resolvedSamples = [NSMutableArray array]; + const auto resolvedFrames = [NSMutableArray *> array]; + const auto frameIndexLookup = [NSMutableDictionary dictionary]; + const auto stackIndexLookup = [NSMutableDictionary dictionary]; + + // initialize the data structures with some simulated data + { + ThreadMetadata threadMetadata; + // leave thread name as nil so it can be overwritten later + threadMetadata.threadID = 1; + threadMetadata.priority = 2; + + QueueMetadata queueMetadata; + queueMetadata.address = 3; + queueMetadata.label = std::make_shared("testQueue-1"); + + Backtrace backtrace; + backtrace.threadMetadata = threadMetadata; + backtrace.queueMetadata = queueMetadata; + backtrace.addresses = std::vector({ 0x4, 0x5, 0x6 }); + + backtrace.absoluteTimestamp = 1; + processBacktrace(backtrace, resolvedThreadMetadata, resolvedQueueMetadata, resolvedSamples, + resolvedStacks, resolvedFrames, frameIndexLookup, stackIndexLookup); + + backtrace.absoluteTimestamp = 2; + processBacktrace(backtrace, resolvedThreadMetadata, resolvedQueueMetadata, resolvedSamples, + resolvedStacks, resolvedFrames, frameIndexLookup, stackIndexLookup); + } + + // serialize the data as if it were captured in a transaction envelope + const auto sampledProfile = [NSMutableDictionary dictionary]; + sampledProfile[@"samples"] = resolvedSamples; + sampledProfile[@"stacks"] = resolvedStacks; + sampledProfile[@"frames"] = resolvedFrames; + sampledProfile[@"thread_metadata"] = resolvedThreadMetadata; + sampledProfile[@"queue_metadata"] = resolvedQueueMetadata; + const auto profileData = @{ @"profile" : sampledProfile }; + + const auto context = [[SentrySpanContext alloc] initWithOperation:@"test trace"]; + const auto trace = [[SentryTracer alloc] initWithContext:context]; + const auto transaction = [[SentryTransaction alloc] initWithTrace:trace children:@[]]; + transaction.transaction = @"someTransaction"; + transaction.trace.transactionContext = + [[SentryTransactionContext alloc] initWithName:@"someTransaction" + operation:@"someOperation"]; + transaction.trace.transactionContext.threadInfo = [[SentryThread alloc] initWithThreadId:@1]; + transaction.startSystemTime = 1; + transaction.endSystemTime = 2; + + const auto profileID = [[SentryId alloc] init]; + const auto serialization = serializedProfileData(profileData, transaction, profileID, + profilerTruncationReasonName(SentryProfilerTruncationReasonNormal), @"test", @"someRelease", + @{}, @[]); + + // cause the data structures to be modified again: add new addresses + { + ThreadMetadata threadMetadata; + threadMetadata.name = "newThread-2"; + threadMetadata.threadID = 12345568910; + threadMetadata.priority = 666; + + QueueMetadata queueMetadata; + queueMetadata.address = 9876543210; + queueMetadata.label = std::make_shared("newQueue-2"); + + Backtrace backtrace; + backtrace.threadMetadata = threadMetadata; + backtrace.queueMetadata = queueMetadata; + backtrace.absoluteTimestamp = 5; + backtrace.addresses = std::vector({ 0x777, 0x888, 0x999 }); + + processBacktrace(backtrace, resolvedThreadMetadata, resolvedQueueMetadata, resolvedSamples, + resolvedStacks, resolvedFrames, frameIndexLookup, stackIndexLookup); + } + + // cause the data structures to be modified again: overwrite previous thread metadata + // subdictionary contents + { + ThreadMetadata threadMetadata; + threadMetadata.name = "testThread-1"; + threadMetadata.threadID = 1; + threadMetadata.priority = 2; + + QueueMetadata queueMetadata; + queueMetadata.address = 3; + queueMetadata.label = std::make_shared("testQueue-1"); + + Backtrace backtrace; + backtrace.threadMetadata = threadMetadata; + backtrace.queueMetadata = queueMetadata; + backtrace.absoluteTimestamp = 6; + backtrace.addresses = std::vector({ 0x4, 0x5, 0x6 }); + + processBacktrace(backtrace, resolvedThreadMetadata, resolvedQueueMetadata, resolvedSamples, + resolvedStacks, resolvedFrames, frameIndexLookup, stackIndexLookup); + } + + // ensure the serialization's copied data structures don't contain the new addresses + NSArray *> *frames = serialization[@"profile"][@"frames"]; + XCTAssertEqual(frames.count, 3UL, + @"New frames appeared in the data structure that should have been copied for serialization " + @"and should no longer be modifiable from the backtrace sampler thread."); + + const auto index = + [frames indexOfObjectPassingTest:^BOOL(NSDictionary *_Nonnull obj, + __unused NSUInteger idx, __unused BOOL *_Nonnull stop) { + NSString *address = obj[@"instruction_addr"]; + const auto unexpected = + @[ @"0x0000000000000777", @"0x0000000000000888", @"0x0000000000000999" ]; + return [unexpected containsObject:address]; + }]; + XCTAssertEqual(index, NSNotFound, + @"The data structures copied for serialization should not be modified with subsequent " + @"calls from the backtrace sampler. The new backtrace addresses should not appear in the " + @"copies of the profiling data structures after calling the serialization function."); + + // ensure the serialization's copied data structures don't get the updated thread info + XCTAssertNil(serialization[@"profile"][@"thread_metadata"][@"1"][@"name"], + @"Thread metadata had a nil thread name at time of serialization, but modification " + @"overwrote it later and that change propagated to the serialization copy of the profiling " + @"data structure."); +} + - (void)testProfilerPayload { const auto resolvedThreadMetadata = [NSMutableDictionary dictionary]; const auto resolvedQueueMetadata = [NSMutableDictionary dictionary]; - const auto resolvedStacks = [NSMutableArray *> array]; + const auto resolvedStacks = [NSMutableArray *> array]; const auto resolvedSamples = [NSMutableArray array]; const auto resolvedFrames = [NSMutableArray *> array]; const auto frameIndexLookup = [NSMutableDictionary dictionary]; @@ -190,7 +334,7 @@ - (void)testProfilerPayload queueMetadata1.address = 9876543210; queueMetadata1.label = std::make_shared("testQueue"); - const auto addresses1 = std::vector({ 123, 456, 789 }); + const auto addresses1 = std::vector({ 0x123, 0x456, 0x789 }); Backtrace backtrace1; backtrace1.threadMetadata = threadMetadata1; @@ -212,7 +356,7 @@ - (void)testProfilerPayload queueMetadata2.address = 9876543210; queueMetadata2.label = std::make_shared("testQueue"); - const auto addresses2 = std::vector({ 777, 888, 789 }); + const auto addresses2 = std::vector({ 0x777, 0x888, 0x789 }); Backtrace backtrace2; backtrace2.threadMetadata = threadMetadata2; @@ -223,12 +367,21 @@ - (void)testProfilerPayload processBacktrace(backtrace2, resolvedThreadMetadata, resolvedQueueMetadata, resolvedSamples, resolvedStacks, resolvedFrames, frameIndexLookup, stackIndexLookup); - // record a third backtrace that's identical to the second to test stack deduplication + // record a third backtrace that's identical to the second to test stack/frame deduplication processBacktrace(backtrace2, resolvedThreadMetadata, resolvedQueueMetadata, resolvedSamples, resolvedStacks, resolvedFrames, frameIndexLookup, stackIndexLookup); XCTAssertEqual(resolvedFrames.count, 5UL); + const auto expectedOrdered = @[ + @"0x0000000000000123", @"0x0000000000000456", @"0x0000000000000789", @"0x0000000000000777", + @"0x0000000000000888" + ]; + [resolvedFrames enumerateObjectsUsingBlock:^(NSDictionary *_Nonnull actualFrame, + NSUInteger idx, __unused BOOL *_Nonnull stop) { + XCTAssert([actualFrame[@"instruction_addr"] isEqualToString:expectedOrdered[idx]]); + }]; + XCTAssertEqual(resolvedStacks.count, 2UL); XCTAssertEqual(resolvedSamples.count, 3UL); }