Skip to content

Commit

Permalink
ref: slice profiles per transaction (#2545)
Browse files Browse the repository at this point in the history
Send profiling data up attached to transaction envelopes. This is required for dynamic sampling to work for profiling. To do so, track tracer instances to determine when to start and stop profiler, and track the tracer's system start time, passing it to transactions, and track transaction end system time, so profiling/metric data can be sliced per transaction.

* ref: extract methods for separate tasks involved in serializing/transmitting profile envelopes
* ref: rename captureEnvelopeItem... to createEnvelopeItem...
* ref: remove @synchronized scope for profiler start method which is now called in the context of a lock_guard scope

Some changes specific to how profiler starts and stops:
* don't stop current profiler and start a new one if started concurrently, just bail and let the current one keep going; this was an assumption from the nonconcurrent profiling days, and in any case, this shouldn't even happen here because we do the same check in the class method that calls through to this
* don't nil out profiler until after serialization for abortive stops

* fix: measurements must be sibling, not child, of profile in the JSON structure
* fix: use system timestamps for GPU frame render info instead of the CADisplayLink's timestamp, which is actually a duration, not a point in time

* test: only pop clang diagnostic if it was added for TSAN runs
* test: change how profiler timeout interval is set in tests, and reset at end to avoid subsequent tests using it and failing
* test: reenable some disabled profiling tests
* test: fix conditional compilation and profiling assertions for frames tracker, add test point for frame rate tracking
* test: repeat concurrent span test logic a second time to ensure no state leakage from profile to profile and that it starts and stops and starts again OK
  • Loading branch information
armcknight committed Feb 24, 2023
1 parent eaa1002 commit efb2222
Show file tree
Hide file tree
Showing 19 changed files with 863 additions and 491 deletions.
8 changes: 8 additions & 0 deletions Sentry.xcodeproj/project.pbxproj
Original file line number Diff line number Diff line change
Expand Up @@ -630,6 +630,8 @@
84A8891C28DBD28900C51DFD /* SentryDevice.h in Headers */ = {isa = PBXBuildFile; fileRef = 84A8891A28DBD28900C51DFD /* SentryDevice.h */; };
84A8891D28DBD28900C51DFD /* SentryDevice.mm in Sources */ = {isa = PBXBuildFile; fileRef = 84A8891B28DBD28900C51DFD /* SentryDevice.mm */; };
84A8892128DBD8D600C51DFD /* SentryDeviceTests.mm in Sources */ = {isa = PBXBuildFile; fileRef = 84A8892028DBD8D600C51DFD /* SentryDeviceTests.mm */; };
84AF45A629A7FFA500FBB177 /* SentryTracerConcurrency.h in Headers */ = {isa = PBXBuildFile; fileRef = 84AF45A429A7FFA500FBB177 /* SentryTracerConcurrency.h */; };
84AF45A729A7FFA500FBB177 /* SentryTracerConcurrency.mm in Sources */ = {isa = PBXBuildFile; fileRef = 84AF45A529A7FFA500FBB177 /* SentryTracerConcurrency.mm */; };
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 */; };
Expand Down Expand Up @@ -1492,6 +1494,8 @@
84A8891A28DBD28900C51DFD /* SentryDevice.h */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.h; name = SentryDevice.h; path = include/SentryDevice.h; sourceTree = "<group>"; };
84A8891B28DBD28900C51DFD /* SentryDevice.mm */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.cpp.objcpp; path = SentryDevice.mm; sourceTree = "<group>"; };
84A8892028DBD8D600C51DFD /* SentryDeviceTests.mm */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.cpp.objcpp; path = SentryDeviceTests.mm; sourceTree = "<group>"; };
84AF45A429A7FFA500FBB177 /* SentryTracerConcurrency.h */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.h; name = SentryTracerConcurrency.h; path = include/SentryTracerConcurrency.h; sourceTree = "<group>"; };
84AF45A529A7FFA500FBB177 /* SentryTracerConcurrency.mm */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.cpp.objcpp; path = SentryTracerConcurrency.mm; sourceTree = "<group>"; };
84E4F5692914F020004C7358 /* Brewfile */ = {isa = PBXFileReference; indentWidth = 2; lastKnownFileType = text; path = Brewfile; sourceTree = "<group>"; tabWidth = 2; };
861265F72404EC1500C4AFDE /* NSArray+SentrySanitize.h */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.h; name = "NSArray+SentrySanitize.h"; path = "include/NSArray+SentrySanitize.h"; sourceTree = "<group>"; };
861265F82404EC1500C4AFDE /* NSArray+SentrySanitize.m */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.objc; path = "NSArray+SentrySanitize.m"; sourceTree = "<group>"; };
Expand Down Expand Up @@ -3049,6 +3053,8 @@
8E133FA025E72DEF00ABD0BF /* SentrySamplingContext.m */,
8E4E7C7B25DAB287006AB9E2 /* SentryTracer.h */,
8E4E7C8125DAB2A5006AB9E2 /* SentryTracer.m */,
84AF45A429A7FFA500FBB177 /* SentryTracerConcurrency.h */,
84AF45A529A7FFA500FBB177 /* SentryTracerConcurrency.mm */,
8E8C57A525EEFC42001CEEFA /* SentryTracesSampler.h */,
8E8C57A025EEFC07001CEEFA /* SentryTracesSampler.m */,
8E4A037725F6F52100000D77 /* SentrySampleDecision.h */,
Expand Down Expand Up @@ -3280,6 +3286,7 @@
03F84D1E27DD414C008FE43F /* SentryBacktrace.hpp in Headers */,
63AA76991EB9C1C200D153DE /* SentryDefines.h in Headers */,
D86B6835294348A400B8B1FC /* SentryAttachment+Private.h in Headers */,
84AF45A629A7FFA500FBB177 /* SentryTracerConcurrency.h in Headers */,
0A4EDEA928D3461B00FA67CB /* SentryPerformanceTracker+Private.h in Headers */,
7B2A70DB27D607CF008B0D15 /* SentryThreadWrapper.h in Headers */,
8EAE980B261E9F530073B6B3 /* SentryPerformanceTracker.h in Headers */,
Expand Down Expand Up @@ -3806,6 +3813,7 @@
63FE70AD20DA4C1000CDBAE8 /* SentryCrashCString.m in Sources */,
6304360B1EC0595B00C4D3FA /* NSData+SentryCompression.m in Sources */,
639889B81EDECFA800EA7442 /* SentryBreadcrumbTracker.m in Sources */,
84AF45A729A7FFA500FBB177 /* SentryTracerConcurrency.mm in Sources */,
7DC8310C2398283C0043DD9A /* SentryCrashIntegration.m in Sources */,
03F84D3227DD4191008FE43F /* SentryProfiler.mm in Sources */,
635B3F391EBC6E2500A6176D /* SentryAsynchronousOperation.m in Sources */,
Expand Down
9 changes: 0 additions & 9 deletions Sentry.xcodeproj/xcshareddata/xcschemes/Sentry.xcscheme
Original file line number Diff line number Diff line change
Expand Up @@ -73,15 +73,6 @@
<Test
Identifier = "SentryNetworkTrackerIntegrationTests/testGetRequest_SpanCreatedAndBaggageHeaderAdded()">
</Test>
<Test
Identifier = "SentryProfilerSwiftTests/testConcurrentSpansWithTimeout()">
</Test>
<Test
Identifier = "SentryProfilerSwiftTests/testMetricProfiler()">
</Test>
<Test
Identifier = "SentryProfilerSwiftTests/testProfileTimeoutTimer()">
</Test>
<Test
Identifier = "SentrySDKIntegrationTestsBase">
</Test>
Expand Down
17 changes: 1 addition & 16 deletions Sources/Sentry/SentryEvent.m
Original file line number Diff line number Diff line change
@@ -1,10 +1,10 @@
#import "SentryEvent.h"
#import "NSDate+SentryExtras.h"
#import "NSDictionary+SentrySanitize.h"
#import "SentryBreadcrumb.h"
#import "SentryClient.h"
#import "SentryCurrentDate.h"
#import "SentryDebugMeta.h"
#import "SentryEvent+Private.h"
#import "SentryException.h"
#import "SentryId.h"
#import "SentryLevelMapper.h"
Expand All @@ -17,21 +17,6 @@

NS_ASSUME_NONNULL_BEGIN

@interface
SentryEvent ()

@property (nonatomic) BOOL isCrashEvent;

// We're storing serialized breadcrumbs to disk in JSON, and when we're reading them back (in
// the case of OOM), we end up with the serialized breadcrumbs again. Instead of turning those
// dictionaries into proper SentryBreadcrumb instances which then need to be serialized again in
// SentryEvent, we use this serializedBreadcrumbs property to set the pre-serialized
// breadcrumbs. It saves a LOT of work - especially turning an NSDictionary into a SentryBreadcrumb
// is silly when we're just going to do the opposite right after.
@property (nonatomic, strong) NSArray *serializedBreadcrumbs;

@end

@implementation SentryEvent

- (instancetype)init
Expand Down
15 changes: 10 additions & 5 deletions Sources/Sentry/SentryFramesTracker.m
Original file line number Diff line number Diff line change
Expand Up @@ -3,6 +3,7 @@
#import "SentryDisplayLinkWrapper.h"
#import "SentryProfiler.h"
#import "SentryProfilingConditionals.h"
#import "SentryTime.h"
#import "SentryTracer.h"
#import <SentryScreenFrames.h>
#include <stdatomic.h>
Expand All @@ -29,6 +30,7 @@

@property (nonatomic, strong, readonly) SentryDisplayLinkWrapper *displayLinkWrapper;
@property (nonatomic, assign) CFTimeInterval previousFrameTimestamp;
@property (nonatomic) uint64_t previousFrameSystemTimestamp;
# if SENTRY_TARGET_PROFILING_SUPPORTED
@property (nonatomic, readwrite) SentryMutableFrameInfoTimeSeries *frozenFrameTimestamps;
@property (nonatomic, readwrite) SentryMutableFrameInfoTimeSeries *slowFrameTimestamps;
Expand Down Expand Up @@ -107,9 +109,11 @@ - (void)start
- (void)displayLinkCallback
{
CFTimeInterval thisFrameTimestamp = self.displayLinkWrapper.timestamp;
uint64_t thisFrameSystemTimestamp = getAbsoluteTime();

if (self.previousFrameTimestamp == SentryPreviousFrameInitialValue) {
self.previousFrameTimestamp = thisFrameTimestamp;
self.previousFrameSystemTimestamp = thisFrameSystemTimestamp;
return;
}

Expand Down Expand Up @@ -144,7 +148,7 @@ - (void)displayLinkCallback
= shouldRecordFrameRates && (hasNoFrameRatesYet || frameRateSignificantlyChanged);
if (shouldRecordNewFrameRate) {
[self.frameRateTimestamps addObject:@{
@"timestamp" : @(self.displayLinkWrapper.timestamp),
@"timestamp" : @(thisFrameSystemTimestamp),
@"frame_rate" : @(actualFramesPerSecond),
}];
}
Expand All @@ -159,21 +163,22 @@ - (void)displayLinkCallback
if (frameDuration > slowFrameThreshold && frameDuration <= SentryFrozenFrameThreshold) {
atomic_fetch_add_explicit(&_slowFrames, 1, SentryFramesMemoryOrder);
# if SENTRY_TARGET_PROFILING_SUPPORTED
[self recordTimestampStart:@(self.previousFrameTimestamp)
end:@(thisFrameTimestamp)
[self recordTimestampStart:@(self.previousFrameSystemTimestamp)
end:@(thisFrameSystemTimestamp)
array:self.slowFrameTimestamps];
# endif // SENTRY_TARGET_PROFILING_SUPPORTED
} else if (frameDuration > SentryFrozenFrameThreshold) {
atomic_fetch_add_explicit(&_frozenFrames, 1, SentryFramesMemoryOrder);
# if SENTRY_TARGET_PROFILING_SUPPORTED
[self recordTimestampStart:@(self.previousFrameTimestamp)
end:@(thisFrameTimestamp)
[self recordTimestampStart:@(self.previousFrameSystemTimestamp)
end:@(thisFrameSystemTimestamp)
array:self.frozenFrameTimestamps];
# endif // SENTRY_TARGET_PROFILING_SUPPORTED
}

atomic_fetch_add_explicit(&_totalFrames, 1, SentryFramesMemoryOrder);
self.previousFrameTimestamp = thisFrameTimestamp;
self.previousFrameSystemTimestamp = thisFrameSystemTimestamp;
}

# if SENTRY_TARGET_PROFILING_SUPPORTED
Expand Down
7 changes: 6 additions & 1 deletion Sources/Sentry/SentryLog.m
Original file line number Diff line number Diff line change
Expand Up @@ -25,12 +25,17 @@ + (void)logWithMessage:(NSString *)message andLevel:(SentryLevel)level
logOutput = [[SentryLogOutput alloc] init];
}

if (isDebug && level != kSentryLevelNone && level >= diagnosticLevel) {
if ([self willLogAtLevel:level]) {
[logOutput log:[NSString stringWithFormat:@"[Sentry] [%@] %@", nameForSentryLevel(level),
message]];
}
}

+ (BOOL)willLogAtLevel:(SentryLevel)level
{
return isDebug && level != kSentryLevelNone && level >= diagnosticLevel;
}

// Internal and only needed for testing.
+ (void)setLogOutput:(SentryLogOutput *)output
{
Expand Down

0 comments on commit efb2222

Please sign in to comment.