Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

fix: clean up profilers for discarded transactions #3154

Merged
Merged
Show file tree
Hide file tree
Changes from 14 commits
Commits
Show all changes
20 commits
Select commit Hold shift + click to select a range
cd6d521
rename SentryTracerConcurrency -> SentryProfiledTracerConcurrency
armcknight Jul 14, 2023
352df6a
clean up profilers for discarded transactions
armcknight Jul 14, 2023
0f5d163
also stop a running profiler
armcknight Jul 15, 2023
1467d20
only store the count of tracers in bookkeeping, not a set of references
armcknight Jul 17, 2023
b04c3ae
Merge remote-tracking branch 'origin/main' into armcknight/fix/profil…
armcknight Jul 18, 2023
e63cddf
Merge remote-tracking branch 'origin/main' into armcknight/fix/profil…
armcknight Jul 18, 2023
ea7a894
just call discard profiler from SentryTracer.dealloc
armcknight Jul 18, 2023
d53dce1
stub tests to write
armcknight Jul 18, 2023
45eed31
fixup! stub tests to write
armcknight Jul 18, 2023
2e02b79
Merge branch 'main' into armcknight/fix/profiling-transaction-bookkee…
armcknight Jul 18, 2023
b070216
Merge branch 'main' into armcknight/fix/profiling-transaction-bookkee…
armcknight Jul 18, 2023
a36628e
fixup! Merge branch 'main' into armcknight/fix/profiling-transaction-…
armcknight Jul 18, 2023
5c2add3
fixup! fixup! Merge branch 'main' into armcknight/fix/profiling-trans…
armcknight Jul 19, 2023
e5092c0
stronger checks
armcknight Jul 19, 2023
e452f98
add more tests
armcknight Jul 20, 2023
8c2ade9
fix tvos build
armcknight Jul 20, 2023
097e834
dont assert presence of profiler in discard; it may have already been…
armcknight Jul 21, 2023
95dcedb
changelog
armcknight Jul 21, 2023
99ea0bf
Merge branch 'main' into armcknight/fix/profiling-transaction-bookkee…
armcknight Jul 21, 2023
0529a52
fix changelog and test failure
armcknight Jul 21, 2023
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
8 changes: 0 additions & 8 deletions Sentry.xcodeproj/project.pbxproj
Original file line number Diff line number Diff line change
Expand Up @@ -1827,13 +1827,6 @@
/* End PBXFrameworksBuildPhase section */

/* Begin PBXGroup section */
035E73C627D5661A005EEB11 /* Profiling */ = {
isa = PBXGroup;
children = (
);
path = Profiling;
sourceTree = "<group>";
};
0A9BF4E028A114690068D266 /* ViewHierarchy */ = {
isa = PBXGroup;
children = (
Expand Down Expand Up @@ -2255,7 +2248,6 @@
7BD7299B24654CD500EA3610 /* Helper */,
7B944FA924697E9700A10721 /* Integrations */,
7BBD18AF24517E5D00427C76 /* Networking */,
035E73C627D5661A005EEB11 /* Profiling */,
7B3D0474249A3D5800E106B6 /* Protocol */,
63FE71D220DA66C500CDBAE8 /* SentryCrash */,
7B944FAC2469B41600A10721 /* State */,
Expand Down
2 changes: 1 addition & 1 deletion SentryTestUtils/ClearTestState.swift
Original file line number Diff line number Diff line change
Expand Up @@ -40,7 +40,7 @@ class TestCleanup: NSObject {

#if os(iOS) || os(macOS) || targetEnvironment(macCatalyst)
SentryProfiler.getCurrent().stop(for: .normal)
SentryTracer.resetConcurrencyTracking()
SentryProfiler.resetConcurrencyTracking()
#endif // os(iOS) || os(macOS) || targetEnvironment(macCatalyst)

#if os(iOS) || os(tvOS) || targetEnvironment(macCatalyst)
Expand Down
91 changes: 65 additions & 26 deletions Sources/Sentry/Profiling/SentryProfiledTracerConcurrency.mm
Original file line number Diff line number Diff line change
Expand Up @@ -16,19 +16,42 @@
# endif // SENTRY_HAS_UIKIT

/**
* a mapping of profilers to the tracers that started them that are still in-flight and will need to
* query them for their profiling data when they finish. this helps resolve the incongruity between
* the different timeout durations between tracers (500s) and profilers (30s), where a transaction
* may start a profiler that then times out, and then a new transaction starts a new profiler, and
* we must keep the aborted one around until its associated transaction finishes.
* a mapping of profilers to the number of tracers that started them that are still in-flight and
* will need to query them for their profiling data when they finish. this helps resolve the
* incongruity between the different timeout durations between tracers (500s) and profilers (30s),
* where a transaction may start a profiler that then times out, and then a new transaction starts a
* new profiler, and we must keep the aborted one around until its associated transaction finishes.
*/
static NSMutableDictionary</* SentryProfiler.profileId */ NSString *,
NSMutableSet<SentryTracer *> *> *_gProfilersToTracers;
/* number of in-flight tracers */ NSNumber *> *_gProfilersToTracers;

/** provided for fast access to a profiler given a tracer */
static NSMutableDictionary</* SentryTracer.tracerId */ NSString *, SentryProfiler *>
*_gTracersToProfilers;

namespace {

/**
* Remove a profiler from tracking given the id of the tracer it's associated with.
* @warning Must be called from a synchronized context.
*/
void
_unsafe_cleanUpProfiler(SentryProfiler *profiler, NSString *tracerKey)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

m: The prefix unsafe raises a few questions for me at the first glance. I thought this function is somewhat dangerous 😄 . Actually it's just not thread safe. What about renaming it to cleanUpProfiler_non_thread_safe?

Suggested change
_unsafe_cleanUpProfiler(SentryProfiler *profiler, NSString *tracerKey)
_cleanUpProfiler_non_thread_safe(SentryProfiler *profiler, NSString *tracerKey)

{
const auto profilerKey = profiler.profileId.sentryIdString;

[_gTracersToProfilers removeObjectForKey:tracerKey];
_gProfilersToTracers[profilerKey] = @(_gProfilersToTracers[profilerKey].unsignedIntValue - 1);
if ([_gProfilersToTracers[profilerKey] unsignedIntValue] == 0) {
[_gProfilersToTracers removeObjectForKey:profilerKey];
if ([profiler isRunning]) {
[profiler stopForReason:SentryProfilerTruncationReasonNormal];
}
}
}

} // namespace

std::mutex _gStateLock;

void
Expand All @@ -48,22 +71,40 @@

if (_gProfilersToTracers == nil) {
_gProfilersToTracers = [NSMutableDictionary</* SentryProfiler.profileId */ NSString *,
NSMutableSet<SentryTracer *> *> dictionaryWithObject:[NSMutableSet setWithObject:tracer]
forKey:profilerKey];
/* number of in-flight tracers */ NSNumber *>
dictionary];
_gTracersToProfilers =
[NSMutableDictionary</* SentryTracer.tracerId */ NSString *, SentryProfiler *>
dictionaryWithObject:profiler
forKey:tracerKey];
return;
dictionary];
}

if (_gProfilersToTracers[profilerKey] == nil) {
_gProfilersToTracers[profilerKey] = [NSMutableSet setWithObject:tracer];
} else {
[_gProfilersToTracers[profilerKey] addObject:tracer];
_gProfilersToTracers[profilerKey] = @(_gProfilersToTracers[profilerKey].unsignedIntValue + 1);
armcknight marked this conversation as resolved.
Show resolved Hide resolved
_gTracersToProfilers[tracerKey] = profiler;
armcknight marked this conversation as resolved.
Show resolved Hide resolved
}

void
discardProfilerForTracer(SentryTracer *tracer)
{
std::lock_guard<std::mutex> l(_gStateLock);

SENTRY_CASSERT(_gTracersToProfilers != nil && _gProfilersToTracers != nil,
@"Structures should have already been initialized by the time they are being queried");

const auto tracerKey = tracer.traceId.sentryIdString;
const auto profiler = _gTracersToProfilers[tracerKey];

if (!SENTRY_CASSERT_RETURN(profiler != nil,
@"Expected a profiler to be associated with tracer id %@.", tracerKey)) {
philipphofmann marked this conversation as resolved.
Show resolved Hide resolved
return;

Check warning on line 98 in Sources/Sentry/Profiling/SentryProfiledTracerConcurrency.mm

View check run for this annotation

Codecov / codecov/patch

Sources/Sentry/Profiling/SentryProfiledTracerConcurrency.mm#L98

Added line #L98 was not covered by tests
}

_gTracersToProfilers[tracerKey] = profiler;
_unsafe_cleanUpProfiler(profiler, tracerKey);

# if SENTRY_HAS_UIKIT
if (_gProfilersToTracers.count == 0) {
[SentryDependencyContainer.sharedInstance.framesTracker resetProfilingTimestamps];
}
# endif // SENTRY_HAS_UIKIT
}

SentryProfiler *_Nullable profilerForFinishedTracer(SentryTracer *tracer)
Expand All @@ -81,16 +122,7 @@
return nil;
}

const auto profilerKey = profiler.profileId.sentryIdString;

[_gTracersToProfilers removeObjectForKey:tracerKey];
[_gProfilersToTracers[profilerKey] removeObject:tracer];
if ([_gProfilersToTracers[profilerKey] count] == 0) {
[_gProfilersToTracers removeObjectForKey:profilerKey];
if ([profiler isRunning]) {
[profiler stopForReason:SentryProfilerTruncationReasonNormal];
}
}
_unsafe_cleanUpProfiler(profiler, tracerKey);

# if SENTRY_HAS_UIKIT
profiler._screenFrameData =
Expand All @@ -111,6 +143,13 @@
[_gTracersToProfilers removeAllObjects];
[_gProfilersToTracers removeAllObjects];
}

NSUInteger
currentProfiledTracers()
{
std::lock_guard<std::mutex> l(_gStateLock);
return [_gTracersToProfilers count];
}
# endif // defined(TEST) || defined(TESTCI)

#endif // SENTRY_TARGET_PROFILING_SUPPORTED
13 changes: 13 additions & 0 deletions Sources/Sentry/SentryProfiler.mm
Original file line number Diff line number Diff line change
Expand Up @@ -515,6 +515,19 @@ + (SentryProfiler *)getCurrentProfiler
{
return _gCurrentProfiler;
}

// this just calls through to SentryProfiledTracerConcurrency.resetConcurrencyTracking(). we have to
armcknight marked this conversation as resolved.
Show resolved Hide resolved
// do this through SentryTracer because SentryProfiledTracerConcurrency cannot be included in test
// targets via ObjC bridging headers because it contains C++.
+ (void)resetConcurrencyTracking
{
resetConcurrencyTracking();
}

+ (NSUInteger)currentProfiledTracers
{
return currentProfiledTracers();
}
# endif // defined(TEST) || defined(TESTCI)

@end
Expand Down
19 changes: 9 additions & 10 deletions Sources/Sentry/SentryTracer.m
Original file line number Diff line number Diff line change
Expand Up @@ -172,6 +172,15 @@ - (instancetype)initWithTransactionContext:(SentryTransactionContext *)transacti
return self;
}

- (void)dealloc
{
#if SENTRY_TARGET_PROFILING_SUPPORTED
if (self.isProfiling) {
discardProfilerForTracer(self);
}
#endif // SENTRY_TARGET_PROFILING_SUPPORTED
}

- (nullable SentryTracer *)tracer
{
return self;
Expand Down Expand Up @@ -831,16 +840,6 @@ - (NSDate *)originalStartTimestamp
return _startTimeChanged ? _originalStartTimestamp : self.startTimestamp;
}

#if SENTRY_TARGET_PROFILING_SUPPORTED && (defined(TEST) || defined(TESTCI))
// this just calls through to SentryProfiledTracerConcurrency.resetConcurrencyTracking(). we have to
// do this through SentryTracer because SentryProfiledTracerConcurrency cannot be included in test
// targets via ObjC bridging headers because it contains C++.
+ (void)resetConcurrencyTracking
{
resetConcurrencyTracking();
}
#endif // SENTRY_TARGET_PROFILING_SUPPORTED && (defined(TEST) || defined(TESTCI))

@end

NS_ASSUME_NONNULL_END
7 changes: 7 additions & 0 deletions Sources/Sentry/include/SentryProfiledTracerConcurrency.h
Original file line number Diff line number Diff line change
Expand Up @@ -17,6 +17,12 @@ SENTRY_EXTERN_C_BEGIN
*/
void trackProfilerForTracer(SentryProfiler *profiler, SentryTracer *tracer);

/**
* For transactions that will be discarded, clean up the bookkeeping state associated with them to
* reclaim the memory they're using.
*/
void discardProfilerForTracer(SentryTracer *tracer);
armcknight marked this conversation as resolved.
Show resolved Hide resolved

/**
* Return the profiler instance associated with the tracer. If it was the last tracer for the
* associated profiler, stop that profiler. Copy any recorded @c SentryScreenFrames data into the
Expand All @@ -27,6 +33,7 @@ SentryProfiler *_Nullable profilerForFinishedTracer(SentryTracer *tracer);

# if defined(TEST) || defined(TESTCI)
void resetConcurrencyTracking(void);
NSUInteger currentProfiledTracers(void);
# endif // defined(TEST) || defined(TESTCI)

SENTRY_EXTERN_C_END
Expand Down
113 changes: 109 additions & 4 deletions Tests/SentryProfilerTests/SentryProfilerSwiftTests.swift
Original file line number Diff line number Diff line change
Expand Up @@ -30,6 +30,7 @@ class SentryProfilerSwiftTests: XCTestCase {
lazy var dispatchFactory = TestDispatchFactory()
var metricTimerFactory: TestDispatchSourceWrapper?
lazy var timeoutTimerFactory = TestSentryNSTimerFactory()
let dispatchQueueWrapper = TestSentryDispatchQueueWrapper()

let currentDateProvider = TestCurrentDateProvider()

Expand Down Expand Up @@ -63,11 +64,25 @@ class SentryProfilerSwiftTests: XCTestCase {
}

/// Advance the mock date provider, start a new transaction and return its handle.
func newTransaction(testingAppLaunchSpans: Bool = false) throws -> SentryTracer {
if testingAppLaunchSpans {
return try XCTUnwrap(hub.startTransaction(name: transactionName, operation: SentrySpanOperationUILoad) as? SentryTracer)
func newTransaction(testingAppLaunchSpans: Bool = false, automaticTransaction: Bool = false, idleTimeout: TimeInterval? = nil) throws -> SentryTracer {
let operation = testingAppLaunchSpans ? SentrySpanOperationUILoad : transactionOperation

if automaticTransaction {
return hub.startTransaction(
with: TransactionContext(name: transactionName, operation: operation),
bindToScope: false,
customSamplingContext: [:],
configuration: SentryTracerConfiguration(block: {
if let idleTimeout = idleTimeout {
$0.idleTimeout = idleTimeout
}
$0.dispatchQueueWrapper = self.dispatchQueueWrapper
$0.waitForChildren = true
$0.timerFactory = self.timeoutTimerFactory
}))
}
return try XCTUnwrap(hub.startTransaction(name: transactionName, operation: transactionOperation) as? SentryTracer)

return try XCTUnwrap(hub.startTransaction(name: transactionName, operation: operation) as? SentryTracer)
}

// mocking
Expand Down Expand Up @@ -401,6 +416,96 @@ class SentryProfilerSwiftTests: XCTestCase {
options.profilesSampler = { _ in return -0.01 }
}
}

/// based on ``SentryTracerTests.testFinish_WithoutHub_DoesntCaptureTransaction``
func testProfilerCleanedUpAfterTransactionDiscarded_NoHub() throws {
armcknight marked this conversation as resolved.
Show resolved Hide resolved
XCTAssertEqual(SentryProfiler.currentProfiledTracers(), UInt(0))
func performTransaction() {
let sut = SentryTracer(transactionContext: TransactionContext(name: fixture.transactionName, operation: fixture.transactionOperation), hub: nil)
XCTAssertEqual(SentryProfiler.currentProfiledTracers(), UInt(0))
sut.finish()
}
performTransaction()
XCTAssertEqual(SentryProfiler.currentProfiledTracers(), UInt(0))
XCTAssertEqual(self.fixture.client?.captureEventWithScopeInvocations.count, 0)
}

/// based on ``SentryTracerTests.testFinish_WaitForAllChildren_ExceedsMaxDuration_NoTransactionCaptured``
func testProfilerCleanedUpAfterTransactionDiscarded_ExceedsMaxDuration() throws {
XCTAssertEqual(SentryProfiler.currentProfiledTracers(), UInt(0))
func performTransaction() throws {
let sut = try fixture.newTransaction(automaticTransaction: true)
XCTAssertEqual(SentryProfiler.currentProfiledTracers(), UInt(1))
fixture.currentDateProvider.advance(by: 500)
sut.finish()
}
try performTransaction()
XCTAssertEqual(SentryProfiler.currentProfiledTracers(), UInt(0))
XCTAssertEqual(self.fixture.client?.captureEventWithScopeInvocations.count, 0)
}

/// based on ``SentryTracerTests.testFinish_IdleTimeout_ExceedsMaxDuration_NoTransactionCaptured``
func testProfilerCleanedUpAfterTransactionDiscarded_IdleTimeout_ExceedsMaxDuration() throws {
XCTAssertEqual(SentryProfiler.currentProfiledTracers(), UInt(0))
func performTransaction() throws {
let sut = try fixture.newTransaction(automaticTransaction: true, idleTimeout: 1)
XCTAssertEqual(SentryProfiler.currentProfiledTracers(), UInt(1))
fixture.currentDateProvider.advance(by: 500)
sut.finish()
}
try performTransaction()
XCTAssertEqual(SentryProfiler.currentProfiledTracers(), UInt(0))
XCTAssertEqual(self.fixture.client?.captureEventWithScopeInvocations.count, 0)
}

/// based on ``SentryTracerTests.testIdleTimeout_NoChildren_TransactionNotCaptured``
func testProfilerCleanedUpAfterTransactionDiscarded_IdleTimeout_NoChildren() throws {
XCTAssertEqual(SentryProfiler.currentProfiledTracers(), UInt(0))
func performTransaction() throws {
let span = try fixture.newTransaction(automaticTransaction: true, idleTimeout: 1)
XCTAssertEqual(SentryProfiler.currentProfiledTracers(), UInt(1))
fixture.currentDateProvider.advance(by: 500)
fixture.dispatchQueueWrapper.invokeLastDispatchAfter()
XCTAssert(span.isFinished)
}
try performTransaction()
XCTAssertEqual(SentryProfiler.currentProfiledTracers(), UInt(0))
XCTAssertEqual(self.fixture.client?.captureEventWithScopeInvocations.count, 0)
}

/// based on ``SentryTracerTests.testIdleTransaction_CreatingDispatchBlockFails_NoTransactionCaptured``
func testProfilerCleanedUpAfterTransactionDiscarded_IdleTransaction_CreatingDispatchBlockFails() throws {
fixture.dispatchQueueWrapper.createDispatchBlockReturnsNULL = true
XCTAssertEqual(SentryProfiler.currentProfiledTracers(), UInt(0))
func performTransaction() throws {
let span = try fixture.newTransaction(automaticTransaction: true, idleTimeout: 1)
XCTAssertEqual(SentryProfiler.currentProfiledTracers(), UInt(1))
fixture.currentDateProvider.advance(by: 500)
span.finish()
}
try performTransaction()
XCTAssertEqual(SentryProfiler.currentProfiledTracers(), UInt(0))
XCTAssertEqual(self.fixture.client?.captureEventWithScopeInvocations.count, 0)
}

#if os(iOS) || os(tvOS) || targetEnvironment(macCatalyst)
/// based on ``SentryTracerTests.testFinish_WaitForAllChildren_StartTimeModified_NoTransactionCaptured``
func testProfilerCleanedUpAfterTransactionDiscarded_WaitForAllChildren_StartTimeModified() throws {
XCTAssertEqual(SentryProfiler.currentProfiledTracers(), UInt(0))
let appStartMeasurement = fixture.getAppStartMeasurement(type: .cold)
SentrySDK.setAppStartMeasurement(appStartMeasurement)
fixture.currentDateProvider.advance(by: 1)
func performTransaction() throws {
let sut = try fixture.newTransaction(testingAppLaunchSpans: true, automaticTransaction: true)
XCTAssertEqual(SentryProfiler.currentProfiledTracers(), UInt(1))
fixture.currentDateProvider.advance(by: 499)
sut.finish()
}
try performTransaction()
XCTAssertEqual(SentryProfiler.currentProfiledTracers(), UInt(0))
XCTAssertEqual(self.fixture.client?.captureEventWithScopeInvocations.count, 0)
}
#endif // os(iOS) || os(tvOS) || targetEnvironment(macCatalyst)
}

private extension SentryProfilerSwiftTests {
Expand Down
4 changes: 4 additions & 0 deletions Tests/SentryTests/SentryProfiler+Test.h
Original file line number Diff line number Diff line change
Expand Up @@ -10,6 +10,10 @@ SentryProfiler ()

+ (SentryProfiler *)getCurrentProfiler;

+ (void)resetConcurrencyTracking;

+ (NSUInteger)currentProfiledTracers;

@end

NS_ASSUME_NONNULL_END
Expand Down
Loading
Loading