fix: additional profiling data races #3035

indragiek · 2023-05-16T06:08:32Z

📜 Description

While debugging the memory leaks reported in #2980 I found additional data race issues on top of the ones fixed in #3018. This is a larger refactor that fixes those issues but also simplifies the way that synchronization works.

In #3018, there was a change to add locking where processBacktrace mutated data structures that could be accessed concurrently. It attempted to separate the code that did not access the shared data structures, and moved all mutating code to a section at the end of the function. However, it missed a few reads from those data structures that also needed to be synchronized (e.g. frames.count and stacks.count). Generally, separating the critical section from the rest of the logic in that function is not worth the pain because the taking the lock for the entire duration of the function is not expensive.

This refactor adds a new type, SentryProfilingState, that centralizes all logic for reading/writing the shared data structures. This has the additional benefit that you no longer need a processBacktrace function that takes many parameters where the lifetime of those parameters is unclear (this will be helpful for fixing the memory leaks in a subsequent PR).

All notable changes have been commented on inline.

💚 How did you test it?

Ran all existing tests, they pass.

📝 Checklist

You have to check all boxes before merging:

I reviewed the submitted code.
I added tests to verify the changes.
No new PII added or SDK only sends newly added PII if sendDefaultPII is enabled.
I updated the docs if needed.
Review from the native team if needed.
No breaking change or entry added to the changelog.
No breaking change for hybrid SDKs or communicated to hybrid SDKs.

🔮 Next steps

indragiek · 2023-05-16T06:08:48Z

Sources/Sentry/SentryProfiler.mm

@@ -49,7 +50,6 @@
 #    endif

 const int kSentryProfilerFrequencyHz = 101;
-NSString *const kTestStringConst = @"test";


This constant was unused so I removed it

indragiek · 2023-05-16T06:11:19Z

Sources/Sentry/SentryProfiler.mm

+
+- (void)appendBacktrace:(const Backtrace &)backtrace {
+    [self mutate:^(SentryProfilingMutableState *state) {
+        const auto threadID = sentry_stringForUInt64(backtrace.threadMetadata.threadID);


The logic inside mutate is essentially unchanged from the original logic of processBacktrace prior to the changes in #3018. The original code is here:

sentry-cocoa/Sources/Sentry/SentryProfiler.mm

Lines 91 to 160 in b7bd719

const auto threadID = sentry_stringForUInt64(backtrace.threadMetadata.threadID);

NSString *queueAddress = nil;

if (backtrace.queueMetadata.address != 0) {

queueAddress = sentry_formatHexAddressUInt64(backtrace.queueMetadata.address);

}

NSMutableDictionary<NSString *, id> *metadata = threadMetadata[threadID];

if (metadata == nil) {

metadata = [NSMutableDictionary<NSString *, id> 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<void *const *>(backtrace.addresses.data()),

static_cast<int>(backtrace.addresses.size()));

# endif

const auto stack = [NSMutableArray<NSNumber *> array];

for (std::vector<uintptr_t>::size_type backtraceAddressIdx = 0;

backtraceAddressIdx < backtrace.addresses.size(); backtraceAddressIdx++) {

const auto instructionAddress

= sentry_formatHexAddressUInt64(backtrace.addresses[backtraceAddressIdx]);

const auto frameIndex = frameIndexLookup[instructionAddress];

if (frameIndex == nil) {

const auto frame = [NSMutableDictionary<NSString *, id> dictionary];

frame[@"instruction_addr"] = instructionAddress;

# if defined(DEBUG)

frame[@"function"] = parseBacktraceSymbolsFunctionName(symbols[backtraceAddressIdx]);

# endif

[stack addObject:@(frames.count)];

frameIndexLookup[instructionAddress] = @(frames.count);

[frames addObject:frame];

} else {

[stack addObject:frameIndex];

}

}

const auto sample = [[SentrySample alloc] init];

sample.absoluteTimestamp = backtrace.absoluteTimestamp;

sample.threadID = backtrace.threadMetadata.threadID;

if (queueAddress != nil) {

sample.queueAddress = queueAddress;

}

const auto stackKey = [stack componentsJoinedByString:@"|"];

const auto stackIndex = stackIndexLookup[stackKey];

if (stackIndex) {

sample.stackIndex = stackIndex;

} else {

const auto nextStackIndex = @(stacks.count);

sample.stackIndex = nextStackIndex;

stackIndexLookup[stackKey] = nextStackIndex;

[stacks addObject:stack];

}

{

std::lock_guard<std::mutex> l(_gSamplesArrayLock);

[samples addObject:sample];

}

We now take a single lock to make the entire mutation which simplifies the code, there is no fine grained locking.

indragiek · 2023-05-16T06:12:07Z

Sources/Sentry/SentryProfiler.mm

+    NSMutableArray<SentrySample *> *const samples = [_mutableState.samples copy];
+    NSMutableArray<NSArray<NSNumber *> *> *const stacks = [_mutableState.stacks copy];
+    NSMutableArray<NSDictionary<NSString *, id> *> *const frames = [_mutableState.frames copy];
+    NSMutableDictionary<NSString *, NSDictionary *> *const queueMetadata = [_mutableState.queueMetadata 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
+    const auto threadMetadata = [NSMutableDictionary<NSString *, NSDictionary *> dictionary];
+    [_mutableState.threadMetadata
+        enumerateKeysAndObjectsUsingBlock:^(NSString *_Nonnull key, NSDictionary *_Nonnull obj,
+            BOOL *_Nonnull stop) { threadMetadata[key] = [obj copy]; }];
+
+    return @{
+        @"profile": @{
+            @"samples": samples,
+            @"stacks": stacks,
+            @"frames": frames,
+            @"thread_metadata": threadMetadata,
+            @"queue_metadata": queueMetadata
+        }
+    };


This logic is preserved from the changes in #3018

indragiek · 2023-05-16T06:12:17Z

Sources/Sentry/SentryProfiler.mm

    std::shared_ptr<SamplingProfiler> _profiler;
    SentryMetricProfiler *_metricProfiler;
    SentryDebugImageProvider *_debugImageProvider;
-    thread::TIDType _mainThreadID;


This was unused

indragiek · 2023-05-16T06:13:25Z

Tests/SentryProfilerTests/SentryProfilerTests.mm

-    const auto frameIndexLookup = [NSMutableDictionary<NSString *, NSNumber *> dictionary];
-    const auto stackIndexLookup = [NSMutableDictionary<NSString *, NSNumber *> dictionary];
-
+    SentryProfilingState *state = [[SentryProfilingState alloc] init];


SentryProfilingState simplifies these tests

codecov · 2023-05-16T06:15:22Z

Codecov Report

Merging #3035 (9479742) into main (aeec206) will increase coverage by 0.033%.
The diff coverage is 99.324%.

❗ Current head 9479742 differs from pull request most recent head 81abade. Consider uploading reports for the commit 81abade to get more accurate results

Additional details and impacted files

@@              Coverage Diff              @@
##              main     #3035       +/-   ##
=============================================
+ Coverage   88.835%   88.868%   +0.033%     
=============================================
  Files          492       492               
  Lines        53063     53005       -58     
  Branches     19000     18991        -9     
=============================================
- Hits         47139     47105       -34     
+ Misses        4964      4942       -22     
+ Partials       960       958        -2

Impacted Files	Coverage Δ
Sources/Sentry/SentryProfiler.mm	`85.534% <99.145%> (+0.660%)`	⬆️
Tests/SentryProfilerTests/SentryProfilerTests.mm	`98.728% <100.000%> (-0.152%)`	⬇️

... and 14 files with indirect coverage changes

Continue to review full report in Codecov by Sentry.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update aeec206...81abade. Read the comment docs.

indragiek · 2023-05-16T06:22:10Z

Sources/Sentry/SentryProfiler.mm

-            [stack addObject:@(frames.count)];
-            frameIndexLookup[instructionAddress] = @(frames.count);


In the old implementation the logic was changed to use the framesToAdd array as a temporary container before applying the append all at once in the critical section, but that means that frames.count will now be incorrect here.

github-actions · 2023-05-16T06:23:00Z

Performance metrics 🚀

	Plain	With Sentry	Diff
Startup time	1231.16 ms	1233.04 ms	1.88 ms
Size	20.76 KiB	435.26 KiB	414.50 KiB

Baseline results on branch: main

Startup times

Revision	Plain	With Sentry	Diff
`28333b6`	1247.29 ms	1262.51 ms	15.22 ms
`eaa1002`	1205.50 ms	1235.08 ms	29.58 ms
`1e065bc`	1239.69 ms	1258.18 ms	18.49 ms
`47b41ed`	1252.31 ms	1253.96 ms	1.64 ms
`15b8c61`	1223.16 ms	1244.83 ms	21.67 ms
`9e96fd6`	1207.20 ms	1229.40 ms	22.20 ms
`1bbcb9c`	1192.51 ms	1231.96 ms	39.45 ms
`dc0fe58`	1198.56 ms	1220.98 ms	22.42 ms
`371db89`	1226.40 ms	1251.54 ms	25.14 ms
`78d5983`	1229.98 ms	1245.60 ms	15.62 ms

App size

Revision	Plain	With Sentry	Diff
`28333b6`	20.76 KiB	424.69 KiB	403.93 KiB
`eaa1002`	20.76 KiB	423.19 KiB	402.43 KiB
`1e065bc`	20.76 KiB	425.78 KiB	405.01 KiB
`47b41ed`	20.76 KiB	436.66 KiB	415.90 KiB
`15b8c61`	20.76 KiB	419.67 KiB	398.91 KiB
`9e96fd6`	20.76 KiB	425.80 KiB	405.04 KiB
`1bbcb9c`	20.76 KiB	426.10 KiB	405.34 KiB
`dc0fe58`	20.76 KiB	436.50 KiB	415.74 KiB
`371db89`	20.76 KiB	427.31 KiB	406.55 KiB
`78d5983`	20.76 KiB	427.80 KiB	407.04 KiB

Previous results on branch: indragiek/fix-profiling-concurrency

Startup times

Revision	Plain	With Sentry	Diff
`6826b48`	1229.86 ms	1236.84 ms	6.98 ms
`6a989e4`	1248.90 ms	1273.30 ms	24.40 ms

App size

Revision	Plain	With Sentry	Diff
`6826b48`	20.76 KiB	435.10 KiB	414.34 KiB
`6a989e4`	20.76 KiB	435.04 KiB	414.28 KiB

brustolin

LGTM

github-actions · 2023-05-16T15:19:54Z

	Fails
🚫	Please consider adding a changelog entry for the next release.

Instructions and example for changelog

Please add an entry to CHANGELOG.md to the "Unreleased" section. Make sure the entry includes this PR's number.

Example:

## Unreleased

- additional profiling data races ([#3035](https://github.com/getsentry/sentry-cocoa/pull/3035))

If none of the above apply, you can opt out of this check by adding #skip-changelog to the PR description.

Generated by 🚫 dangerJS against 1ce7da9

philipphofmann

Thanks for the refactoring. I reviewed this while you merged it. Still LGTM 👍

armcknight · 2023-07-07T00:03:27Z

Tests/SentryProfilerTests/SentryProfilerTests.mm

-        processBacktrace(backtrace, resolvedThreadMetadata, resolvedQueueMetadata, resolvedSamples,
-            resolvedStacks, resolvedFrames, frameIndexLookup, stackIndexLookup);
-        [mutateExpectation fulfill];
+        [state mutate:^(
+            __unused SentryProfilingMutableState *mutableState) { [mutateExpectation fulfill]; }];


@indragiek I just noticed this change when going to write some new tests. Is the last backtrace created above (here) no longer appended to the profile data?

indragiek added 2 commits May 15, 2023 22:47

fix: additional profiling data races

2bfe5bb

Remove unused kTestStringConst

23129ea

indragiek requested review from philipphofmann, brustolin and armcknight as code owners May 16, 2023 06:08

getsentry-bot and others added 2 commits May 16, 2023 06:09

Format code

0f26457

Remove @autoreleasepool

69d8f8a

indragiek commented May 16, 2023

View reviewed changes

indragiek and others added 2 commits May 15, 2023 23:13

Update CHANGELOG.md

9479742

Format code

81abade

indragiek commented May 16, 2023

View reviewed changes

brustolin approved these changes May 16, 2023

View reviewed changes

indragiek added 2 commits May 16, 2023 08:18

Merge branch 'main' into indragiek/fix-profiling-concurrency

09d0377

Update CHANGELOG.md

1ce7da9

indragiek merged commit cd39d58 into main May 16, 2023

indragiek deleted the indragiek/fix-profiling-concurrency branch May 16, 2023 15:19

philipphofmann reviewed May 16, 2023

View reviewed changes

armcknight reviewed Jul 7, 2023

View reviewed changes

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

fix: additional profiling data races #3035

fix: additional profiling data races #3035

indragiek commented May 16, 2023

indragiek May 16, 2023

indragiek May 16, 2023

indragiek May 16, 2023

indragiek May 16, 2023

indragiek May 16, 2023

codecov bot commented May 16, 2023 •

edited

Loading

indragiek May 16, 2023

github-actions bot commented May 16, 2023 •

edited

Loading

Baseline results on branch: main

Startup times

App size

Previous results on branch: indragiek/fix-profiling-concurrency

Startup times

App size

brustolin left a comment

github-actions bot commented May 16, 2023

philipphofmann left a comment

armcknight Jul 7, 2023

	const auto threadID = sentry_stringForUInt64(backtrace.threadMetadata.threadID);

	NSString *queueAddress = nil;
	if (backtrace.queueMetadata.address != 0) {
	queueAddress = sentry_formatHexAddressUInt64(backtrace.queueMetadata.address);
	}
	NSMutableDictionary<NSString , id> metadata = threadMetadata[threadID];
	if (metadata == nil) {
	metadata = [NSMutableDictionary<NSString *, id> 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<void const >(backtrace.addresses.data()),
	static_cast<int>(backtrace.addresses.size()));
	# endif

	const auto stack = [NSMutableArray<NSNumber *> array];
	for (std::vector<uintptr_t>::size_type backtraceAddressIdx = 0;
	backtraceAddressIdx < backtrace.addresses.size(); backtraceAddressIdx++) {
	const auto instructionAddress
	= sentry_formatHexAddressUInt64(backtrace.addresses[backtraceAddressIdx]);

	const auto frameIndex = frameIndexLookup[instructionAddress];
	if (frameIndex == nil) {
	const auto frame = [NSMutableDictionary<NSString *, id> dictionary];
	frame[@"instruction_addr"] = instructionAddress;
	# if defined(DEBUG)
	frame[@"function"] = parseBacktraceSymbolsFunctionName(symbols[backtraceAddressIdx]);
	# endif
	[stack addObject:@(frames.count)];
	frameIndexLookup[instructionAddress] = @(frames.count);
	[frames addObject:frame];
	} else {
	[stack addObject:frameIndex];
	}
	}

	const auto sample = [[SentrySample alloc] init];
	sample.absoluteTimestamp = backtrace.absoluteTimestamp;
	sample.threadID = backtrace.threadMetadata.threadID;
	if (queueAddress != nil) {
	sample.queueAddress = queueAddress;
	}
	const auto stackKey = [stack componentsJoinedByString:@"\|"];
	const auto stackIndex = stackIndexLookup[stackKey];
	if (stackIndex) {
	sample.stackIndex = stackIndex;
	} else {
	const auto nextStackIndex = @(stacks.count);
	sample.stackIndex = nextStackIndex;
	stackIndexLookup[stackKey] = nextStackIndex;
	[stacks addObject:stack];
	}

	{
	std::lock_guard<std::mutex> l(_gSamplesArrayLock);
	[samples addObject:sample];
	}

fix: additional profiling data races #3035

fix: additional profiling data races #3035

Conversation

indragiek commented May 16, 2023

📜 Description

💚 How did you test it?

📝 Checklist

🔮 Next steps

indragiek May 16, 2023

Choose a reason for hiding this comment

indragiek May 16, 2023

Choose a reason for hiding this comment

indragiek May 16, 2023

Choose a reason for hiding this comment

indragiek May 16, 2023

Choose a reason for hiding this comment

indragiek May 16, 2023

Choose a reason for hiding this comment

codecov bot commented May 16, 2023 • edited Loading

Codecov Report

indragiek May 16, 2023

Choose a reason for hiding this comment

github-actions bot commented May 16, 2023 • edited Loading

Performance metrics 🚀

Baseline results on branch: main

Startup times

App size

Previous results on branch: indragiek/fix-profiling-concurrency

Startup times

App size

brustolin left a comment

Choose a reason for hiding this comment

github-actions bot commented May 16, 2023

Instructions and example for changelog

philipphofmann left a comment

Choose a reason for hiding this comment

armcknight Jul 7, 2023

Choose a reason for hiding this comment

codecov bot commented May 16, 2023 •

edited

Loading

github-actions bot commented May 16, 2023 •

edited

Loading