From 2a894d51fb421fc00c10b772395c816e4678ca8a Mon Sep 17 00:00:00 2001 From: Andrew McKnight Date: Fri, 1 Dec 2023 11:30:43 -0900 Subject: [PATCH 01/31] meta: mention experimental nature of UIKitless feature (#3470) --- CHANGELOG.md | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index d28ad4e457a..7424c90ea68 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -86,7 +86,8 @@ The XCFramework attached to GitHub releases is now built with Xcode 15. ### Features -- Sentry can now be used without linking UIKit; this is helpful for using the SDK in certain app extension contexts (#3175) +- Sentry can now be used without linking UIKit; this is helpful for using the SDK in certain app extension contexts (#3175) +**Note:** this is an experimental feature not yet available for with SPM. **Warning:** this breaks some SPM integrations. Use 8.14.1 if you integrate using SPM. - GA of MetricKit integration (#3340) From e998fd0e5f91a6b4182e618d4dc5b3ee6ee1b2be Mon Sep 17 00:00:00 2001 From: Ivan Dlugos <6349682+vaind@users.noreply.github.com> Date: Sat, 2 Dec 2023 09:04:10 +0100 Subject: [PATCH 02/31] feat(internal): change collectProfilerForTrace result to mutable (#3473) --- Sources/Sentry/PrivateSentrySDKOnly.mm | 6 +++--- Sources/Sentry/include/HybridPublic/PrivateSentrySDKOnly.h | 6 +++--- 2 files changed, 6 insertions(+), 6 deletions(-) diff --git a/Sources/Sentry/PrivateSentrySDKOnly.mm b/Sources/Sentry/PrivateSentrySDKOnly.mm index 6b5ab722986..bff864d12b3 100644 --- a/Sources/Sentry/PrivateSentrySDKOnly.mm +++ b/Sources/Sentry/PrivateSentrySDKOnly.mm @@ -129,9 +129,9 @@ + (uint64_t)startProfilerForTrace:(SentryId *)traceId; return SentryDependencyContainer.sharedInstance.dateProvider.systemTime; } -+ (nullable NSDictionary *)collectProfileBetween:(uint64_t)startSystemTime - and:(uint64_t)endSystemTime - forTrace:(SentryId *)traceId; ++ (nullable NSMutableDictionary *)collectProfileBetween:(uint64_t)startSystemTime + and:(uint64_t)endSystemTime + forTrace:(SentryId *)traceId; { NSMutableDictionary *payload = [SentryProfiler collectProfileBetween:startSystemTime diff --git a/Sources/Sentry/include/HybridPublic/PrivateSentrySDKOnly.h b/Sources/Sentry/include/HybridPublic/PrivateSentrySDKOnly.h index ac3c4bc3add..6685388a32c 100644 --- a/Sources/Sentry/include/HybridPublic/PrivateSentrySDKOnly.h +++ b/Sources/Sentry/include/HybridPublic/PrivateSentrySDKOnly.h @@ -91,9 +91,9 @@ typedef void (^SentryOnAppStartMeasurementAvailable)( * Collect a profiler session data associated with the given @c SentryId. * This also discards the profiler. */ -+ (nullable NSDictionary *)collectProfileBetween:(uint64_t)startSystemTime - and:(uint64_t)endSystemTime - forTrace:(SentryId *)traceId; ++ (nullable NSMutableDictionary *)collectProfileBetween:(uint64_t)startSystemTime + and:(uint64_t)endSystemTime + forTrace:(SentryId *)traceId; /** * Discard profiler session data associated with the given @c SentryId. From b9a9dcab37e2e5ebe18ca868743047c4d385e5ae Mon Sep 17 00:00:00 2001 From: Andrew McKnight Date: Mon, 4 Dec 2023 12:21:58 -0900 Subject: [PATCH 03/31] meta: update develop-docs (#3474) --- develop-docs/README.md | 52 +++---------------- develop-docs/auto-ui-performance-tracking.svg | 42 --------------- develop-docs/auto-ui-performance-tracking.wsd | 20 ------- develop-docs/performance-api.svg | 44 ---------------- develop-docs/performance-api.wsd | 22 -------- 5 files changed, 7 insertions(+), 173 deletions(-) delete mode 100644 develop-docs/auto-ui-performance-tracking.svg delete mode 100644 develop-docs/auto-ui-performance-tracking.wsd delete mode 100644 develop-docs/performance-api.svg delete mode 100644 develop-docs/performance-api.wsd diff --git a/develop-docs/README.md b/develop-docs/README.md index 0903e329407..b0548c42412 100644 --- a/develop-docs/README.md +++ b/develop-docs/README.md @@ -42,6 +42,7 @@ CI runs the unit tests for one job with thread sanitizer enabled to detect race The Test scheme of Sentry uses `TSAN_OPTIONS` to specify the [suppression file](../Tests/ThreadSanitizer.sup) to ignore false positives or known issues. It's worth noting that you can use the `$(PROJECT_DIR)` to specify the path to the suppression file. To run the unit tests with the thread sanitizer enabled in Xcode click on edit scheme, go to tests, then open diagnostics, and enable Thread Sanitizer. +The profiler doesn't work with TSAN attached, so tests that run the profiler will be skipped. ### Further Reading @@ -91,55 +92,10 @@ Ensure to not commit the patch file after running this script, which then contai ./scripts/upload-dsyms-with-xcode-build-phase.sh YOUR_AUTH_TOKEN ``` -## Auto UI Performance Class Overview - -![Auto UI Performance Class Overview](./auto-ui-performance-tracking.svg) - -## Performance API Overview - -![Performance API Overview](./performance-api.svg) - ## Generating classes You can use the `generate-classes.sh` to generate ViewControllers and other classes to emulate a large project. This is useful, for example, to test the performance of swizzling in a large project without having to check in thousands of lines of code. -## Generating Diagrams - -The diagrams are created with [PlantUml](http://plantuml.com). The advantage of PlantUml -over other diagram tools is that you describe the diagrams with text, and you don't have -to worry about UML and layout, which can be time-consuming for changes. Furthermore, the -diagrams can be stored in git. - -With [Visual Studio Code](https://code.visualstudio.com/) and the -[PlantUml Plugin](https://marketplace.visualstudio.com/items?itemName=jebbs.plantuml#user-content-use-plantuml-server-as-render) -you can create diagrams, view them and export them. If you don't want to use Visual Studio Code, -there are many [alternatives](http://plantuml.com/running). - -For learning the syntax and quickly playing around you can check out [Plant Text](https://www.planttext.com/). - -### Visual Studio Code Setup - -Visual Studio Code needs a rendering engine for PlantUml. We recommend using the following Docker image: - -```sh -docker run -d -p 8080:8080 plantuml/plantuml-server:jetty -``` - -To ensure the rendering server is running properly, visit with `localhost:8080`. - -Finally, you have to configure the rendering server in Visual Studio Code. For this, open the settings of Visual Studio Code. Choose `Extensions > PlantUML configuration`. Click on `Edit in settings.json`. Then paste the following into the config: - -```json -{ - "plantuml.server": "http://localhost:8080", - "plantuml.render": "PlantUMLServer" -} -``` - -Save the settings and you should be able to render a diagram. - -You can find the official guide here: [configure a rendering server](https://marketplace.visualstudio.com/items?itemName=jebbs.plantuml#user-content-use-plantuml-server-as-render). - ## UIKit Some customers would like to not link UIKit for various reasons. Either they simply may not want to use our UIKit functionality, or they actually cannot link to it in certain circumstances, like a File Provider app extension. @@ -149,3 +105,9 @@ There are two build configurations they can use for this: `Debug_without_UIKit` - `GCC_PREPROCESSOR_DEFINITIONS` has an additional setting `SENTRY_NO_UIKIT=1`. This is now part of the definition of `SENTRY_HAS_UIKIT` in `SentryDefines.h` that is used to conditionally compile out any code that would otherwise use UIKit API and cause UIKit to be automatically linked as described above. There is another macro `SENTRY_UIKIT_AVAILABLE` defined as `SENTRY_HAS_UIKIT` used to be, meaning simply that compilation is targeting a platform where UIKit is available to be used. This is used in headers we deliver in the framework bundle to compile out declarations that rely on UIKit, and their corresponding implementations are switched over `SENTRY_HAS_UIKIT` to either provide the logic for configurations that link UIKit, or to provide a stub delivering a default value (`nil`, `0.0`, `NO` etc) and a warning log for publicly facing things like SentryOptions, or debug log for internal things like SentryDependencyContainer. There are two jobs in `.github/workflows/build.yml` that will build each of the new configs and use `otool -L` to ensure that UIKit does not appear as a load command in the build products. + +This feature is experimental and is currently not compatible with SPM. + +## Logging + +We have a set of macros for debugging at various levels defined in SentryLog.h. These are not async-safe; to log from special places like crash handlers, see SentryCrashLogger.h; see the headerdocs in that header for how to work with those logging macros. There are also separate macros in SentryProfilingLogging.hpp specifically for the profiler; these are completely compiled out of release builds due to https://github.com/getsentry/sentry-cocoa/issues/3336. diff --git a/develop-docs/auto-ui-performance-tracking.svg b/develop-docs/auto-ui-performance-tracking.svg deleted file mode 100644 index 2683c7d48e1..00000000000 --- a/develop-docs/auto-ui-performance-tracking.svg +++ /dev/null @@ -1,42 +0,0 @@ -SpanProtocolUIViewControllerPerformanceTrackerPerformanceTrackerSpantimestampTracer1many1manyobservers \ No newline at end of file diff --git a/develop-docs/auto-ui-performance-tracking.wsd b/develop-docs/auto-ui-performance-tracking.wsd deleted file mode 100644 index 282f2094bcf..00000000000 --- a/develop-docs/auto-ui-performance-tracking.wsd +++ /dev/null @@ -1,20 +0,0 @@ -@startuml - -interface SpanProtocol - -class UIViewControllerPerformanceTracker -class PerformanceTracker -class Span { - timestamp -} -class Tracer - -Span --|> SpanProtocol -Tracer --|> SpanProtocol - -UIViewControllerPerformanceTracker *-- PerformanceTracker -PerformanceTracker "1" *-- "many" SpanProtocol -Tracer "1" *-- "many" SpanProtocol -Tracer "observers" -- Span::timestamp - -@enduml diff --git a/develop-docs/performance-api.svg b/develop-docs/performance-api.svg deleted file mode 100644 index 1ef4858c3a0..00000000000 --- a/develop-docs/performance-api.svg +++ /dev/null @@ -1,44 +0,0 @@ -SpanProtocolSpantimestampTracerSpanContextTransactionContextTransaction1many \ No newline at end of file diff --git a/develop-docs/performance-api.wsd b/develop-docs/performance-api.wsd deleted file mode 100644 index 5b42b85f93c..00000000000 --- a/develop-docs/performance-api.wsd +++ /dev/null @@ -1,22 +0,0 @@ -@startuml - -interface SpanProtocol - -class Span { - timestamp -} -class Tracer -class SpanContext -class TransactionContext -class Transaction - -Span --up|> SpanProtocol -Tracer --up|> SpanProtocol -Tracer *-- TransactionContext -Span *-- SpanContext -Transaction *-- Tracer - -Tracer "1" *-- "many" SpanProtocol - - -@enduml From ef5821b64a14bacd9020dc033b7c6d7f1304ca52 Mon Sep 17 00:00:00 2001 From: Philipp Hofmann Date: Tue, 5 Dec 2023 09:06:41 +0100 Subject: [PATCH 04/31] feat: Add slow and frozen frames to spans (#3450) Add total, slow, and frozen frame numbers to span data. Fixes GH-3448 Co-authored-by: Andrew McKnight --- CHANGELOG.md | 6 + SentryTestUtils/TestDisplayLinkWrapper.swift | 2 +- Sources/Sentry/SentryBuildAppStartSpans.m | 2 +- Sources/Sentry/SentryFramesTracker.m | 10 ++ Sources/Sentry/SentrySpan.m | 56 +++++++- Sources/Sentry/SentryTracer.m | 19 ++- Sources/Sentry/include/SentryFramesTracker.h | 3 + Sources/Sentry/include/SentrySpan.h | 17 ++- .../PrivateSentrySDKOnlyTests.swift | 2 +- Tests/SentryTests/SentryClientTests.swift | 2 +- .../Transaction/SentrySpanTests.swift | 130 ++++++++++++++++-- .../Transaction/SentryTracerTests.swift | 6 +- 12 files changed, 230 insertions(+), 25 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 7424c90ea68..01a86d47979 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,5 +1,11 @@ # Changelog +## Unreleased + +## Features + +- Add slow and frozen frames to spans (#3450) + ## 8.17.1 ### Fixes diff --git a/SentryTestUtils/TestDisplayLinkWrapper.swift b/SentryTestUtils/TestDisplayLinkWrapper.swift index d3ef04e408a..9db29f7dbcd 100644 --- a/SentryTestUtils/TestDisplayLinkWrapper.swift +++ b/SentryTestUtils/TestDisplayLinkWrapper.swift @@ -99,7 +99,7 @@ public class TestDisplayLinkWrapper: SentryDisplayLinkWrapper { call() } - public func givenFrames(_ slow: Int, _ frozen: Int, _ normal: Int) { + public func renderFrames(_ slow: Int, _ frozen: Int, _ normal: Int) { self.call() for _ in 0.. * diff --git a/Sources/Sentry/SentryFramesTracker.m b/Sources/Sentry/SentryFramesTracker.m index d261c976cb7..76da05f6b35 100644 --- a/Sources/Sentry/SentryFramesTracker.m +++ b/Sources/Sentry/SentryFramesTracker.m @@ -242,4 +242,14 @@ - (void)dealloc @end +BOOL +sentryShouldAddSlowFrozenFramesData( + NSInteger totalFrames, NSInteger slowFrames, NSInteger frozenFrames) +{ + BOOL allBiggerThanOrEqualToZero = totalFrames >= 0 && slowFrames >= 0 && frozenFrames >= 0; + BOOL oneBiggerThanZero = totalFrames > 0 || slowFrames > 0 || frozenFrames > 0; + + return allBiggerThanOrEqualToZero && oneBiggerThanZero; +} + #endif // SENTRY_HAS_UIKIT diff --git a/Sources/Sentry/SentrySpan.m b/Sources/Sentry/SentrySpan.m index 95bbbcf5183..3caa32accaa 100644 --- a/Sources/Sentry/SentrySpan.m +++ b/Sources/Sentry/SentrySpan.m @@ -19,6 +19,11 @@ #import "SentryTraceHeader.h" #import "SentryTracer.h" +#if SENTRY_HAS_UIKIT +# import +# import +#endif // SENTRY_HAS_UIKIT + NS_ASSUME_NONNULL_BEGIN @interface @@ -30,9 +35,18 @@ @implementation SentrySpan { NSMutableDictionary *_tags; NSObject *_stateLock; BOOL _isFinished; +#if SENTRY_HAS_UIKIT + NSUInteger initTotalFrames; + NSUInteger initSlowFrames; + NSUInteger initFrozenFrames; + SentryFramesTracker *_framesTracker; +#endif // SENTRY_HAS_UIKIT } - (instancetype)initWithContext:(SentrySpanContext *)context +#if SENTRY_HAS_UIKIT + framesTracker:(nullable SentryFramesTracker *)framesTracker; +#endif // SENTRY_HAS_UIKIT { if (self = [super init]) { self.startTimestamp = [SentryDependencyContainer.sharedInstance.dateProvider date]; @@ -43,6 +57,17 @@ - (instancetype)initWithContext:(SentrySpanContext *)context if ([NSThread isMainThread]) { _data[SPAN_DATA_THREAD_NAME] = @"main"; + +#if SENTRY_HAS_UIKIT + // Only track frames if running on main thread. + _framesTracker = framesTracker; + if (_framesTracker.isRunning) { + SentryScreenFrames *currentFrames = _framesTracker.currentFrames; + initTotalFrames = currentFrames.total; + initSlowFrames = currentFrames.slow; + initFrozenFrames = currentFrames.frozen; + } +#endif // SENTRY_HAS_UIKIT } else { _data[SPAN_DATA_THREAD_NAME] = [SentryDependencyContainer.sharedInstance.threadInspector getThreadName:currentThread]; @@ -64,9 +89,17 @@ - (instancetype)initWithContext:(SentrySpanContext *)context return self; } -- (instancetype)initWithTracer:(SentryTracer *)tracer context:(SentrySpanContext *)context +- (instancetype)initWithTracer:(SentryTracer *)tracer + context:(SentrySpanContext *)context +#if SENTRY_HAS_UIKIT + framesTracker:(nullable SentryFramesTracker *)framesTracker +{ + if (self = [self initWithContext:context framesTracker:framesTracker]) { +#else { if (self = [self initWithContext:context]) { +#endif // SENTRY_HAS_UIKIT + _tracer = tracer; } return self; @@ -171,6 +204,27 @@ - (void)finishWithStatus:(SentrySpanStatus)status SENTRY_LOG_DEBUG(@"Setting span timestamp: %@ at system time %llu", self.timestamp, (unsigned long long)SentryDependencyContainer.sharedInstance.dateProvider.systemTime); } + +#if SENTRY_HAS_UIKIT + if (_framesTracker.isRunning) { + + SentryScreenFrames *currentFrames = _framesTracker.currentFrames; + NSInteger totalFrames = currentFrames.total - initTotalFrames; + NSInteger slowFrames = currentFrames.slow - initSlowFrames; + NSInteger frozenFrames = currentFrames.frozen - initFrozenFrames; + + if (sentryShouldAddSlowFrozenFramesData(totalFrames, slowFrames, frozenFrames)) { + [self setDataValue:@(totalFrames) forKey:@"frames.total"]; + [self setDataValue:@(slowFrames) forKey:@"frames.slow"]; + [self setDataValue:@(frozenFrames) forKey:@"frames.frozen"]; + + SENTRY_LOG_DEBUG(@"Frames for span \"%@\" Total:%ld Slow:%ld Frozen:%ld", + self.operation, (long)totalFrames, (long)slowFrames, (long)frozenFrames); + } + } + +#endif // SENTRY_HAS_UIKIT + if (self.tracer == nil) { SENTRY_LOG_DEBUG( @"No tracer associated with span with id %@", self.spanId.sentrySpanIdString); diff --git a/Sources/Sentry/SentryTracer.m b/Sources/Sentry/SentryTracer.m index 04f21900122..39284809123 100644 --- a/Sources/Sentry/SentryTracer.m +++ b/Sources/Sentry/SentryTracer.m @@ -123,7 +123,11 @@ - (instancetype)initWithTransactionContext:(SentryTransactionContext *)transacti hub:(nullable SentryHub *)hub configuration:(SentryTracerConfiguration *)configuration; { - if (!(self = [super initWithContext:transactionContext])) { + if (!(self = [super initWithContext:transactionContext +#if SENTRY_HAS_UIKIT + framesTracker:SentryDependencyContainer.sharedInstance.framesTracker +#endif // SENTRY_HAS_UIKIT + ])) { return nil; } @@ -351,7 +355,13 @@ - (void)cancelDeadlineTimer spanDescription:description sampled:self.sampled]; - SentrySpan *child = [[SentrySpan alloc] initWithTracer:self context:context]; + SentrySpan *child = + [[SentrySpan alloc] initWithTracer:self + context:context +#if SENTRY_HAS_UIKIT + framesTracker:SentryDependencyContainer.sharedInstance.framesTracker +#endif // SENTRY_HAS_UIKIT + ]; child.startTimestamp = [SentryDependencyContainer.sharedInstance.dateProvider date]; SENTRY_LOG_DEBUG(@"Started child span %@ under %@", child.spanId.sentrySpanIdString, parentId.sentrySpanIdString); @@ -741,10 +751,7 @@ - (void)addMeasurements:(SentryTransaction *)transaction NSInteger slowFrames = currentFrames.slow - initSlowFrames; NSInteger frozenFrames = currentFrames.frozen - initFrozenFrames; - BOOL allBiggerThanZero = totalFrames >= 0 && slowFrames >= 0 && frozenFrames >= 0; - BOOL oneBiggerThanZero = totalFrames > 0 || slowFrames > 0 || frozenFrames > 0; - - if (allBiggerThanZero && oneBiggerThanZero) { + if (sentryShouldAddSlowFrozenFramesData(totalFrames, slowFrames, frozenFrames)) { [self setMeasurement:@"frames_total" value:@(totalFrames)]; [self setMeasurement:@"frames_slow" value:@(slowFrames)]; [self setMeasurement:@"frames_frozen" value:@(frozenFrames)]; diff --git a/Sources/Sentry/include/SentryFramesTracker.h b/Sources/Sentry/include/SentryFramesTracker.h index 6724c3562c6..22e5c86e3b5 100644 --- a/Sources/Sentry/include/SentryFramesTracker.h +++ b/Sources/Sentry/include/SentryFramesTracker.h @@ -40,6 +40,9 @@ NS_ASSUME_NONNULL_BEGIN @end +BOOL sentryShouldAddSlowFrozenFramesData( + NSInteger totalFrames, NSInteger slowFrames, NSInteger frozenFrames); + NS_ASSUME_NONNULL_END #endif // SENTRY_HAS_UIKIT diff --git a/Sources/Sentry/include/SentrySpan.h b/Sources/Sentry/include/SentrySpan.h index 72ddce92044..70678b7d67e 100644 --- a/Sources/Sentry/include/SentrySpan.h +++ b/Sources/Sentry/include/SentrySpan.h @@ -6,6 +6,10 @@ NS_ASSUME_NONNULL_BEGIN @class SentryTracer, SentryId, SentrySpanId, SentryFrame, SentrySpanContext; @protocol SentrySerializable; +#if SENTRY_HAS_UIKIT +@class SentryFramesTracker; +#endif // SENTRY_HAS_UIKIT + @interface SentrySpan : NSObject SENTRY_NO_INIT @@ -85,13 +89,22 @@ SENTRY_NO_INIT * @param transaction The @c SentryTracer managing the transaction this span is associated with. * @param context This span context information. */ -- (instancetype)initWithTracer:(SentryTracer *)transaction context:(SentrySpanContext *)context; +- (instancetype)initWithTracer:(SentryTracer *)transaction + context:(SentrySpanContext *)context +#if SENTRY_HAS_UIKIT + framesTracker:(nullable SentryFramesTracker *)framesTracker; +#endif // SENTRY_HAS_UIKIT +; /** * Init a @c SentrySpan with given context. * @param context This span context information. */ -- (instancetype)initWithContext:(SentrySpanContext *)context; +- (instancetype)initWithContext:(SentrySpanContext *)context +#if SENTRY_HAS_UIKIT + framesTracker:(nullable SentryFramesTracker *)framesTracker; +#endif // SENTRY_HAS_UIKIT +; - (void)setExtraValue:(nullable id)value forKey:(NSString *)key DEPRECATED_ATTRIBUTE; @end diff --git a/Tests/SentryTests/PrivateSentrySDKOnlyTests.swift b/Tests/SentryTests/PrivateSentrySDKOnlyTests.swift index 8c01ab16bf9..388e6ede39e 100644 --- a/Tests/SentryTests/PrivateSentrySDKOnlyTests.swift +++ b/Tests/SentryTests/PrivateSentrySDKOnlyTests.swift @@ -195,7 +195,7 @@ class PrivateSentrySDKOnlyTests: XCTestCase { let slow = 2 let frozen = 1 let normal = 100 - displayLink.givenFrames(slow, frozen, normal) + displayLink.renderFrames(slow, frozen, normal) let currentFrames = PrivateSentrySDKOnly.currentScreenFrames XCTAssertEqual(UInt(slow + frozen + normal), currentFrames.total) diff --git a/Tests/SentryTests/SentryClientTests.swift b/Tests/SentryTests/SentryClientTests.swift index 43e06071e02..a1648cbaa05 100644 --- a/Tests/SentryTests/SentryClientTests.swift +++ b/Tests/SentryTests/SentryClientTests.swift @@ -348,7 +348,7 @@ class SentryClientTest: XCTestCase { func testCaptureTransactionWithoutScreen() { SentryDependencyContainer.sharedInstance().application = TestSentryUIApplication() - let event = Transaction(trace: SentryTracer(context: SpanContext(operation: "test")), children: []) + let event = Transaction(trace: SentryTracer(context: SpanContext(operation: "test"), framesTracker: nil), children: []) fixture.getSut().capture(event: event, scope: fixture.scope) try? assertLastSentEventWithAttachment { event in diff --git a/Tests/SentryTests/Transaction/SentrySpanTests.swift b/Tests/SentryTests/Transaction/SentrySpanTests.swift index 4001f82890a..99c7981342d 100644 --- a/Tests/SentryTests/Transaction/SentrySpanTests.swift +++ b/Tests/SentryTests/Transaction/SentrySpanTests.swift @@ -1,3 +1,4 @@ +import Nimble import Sentry import SentryTestUtils import XCTest @@ -14,7 +15,11 @@ class SentrySpanTests: XCTestCase { let extraValue = "extra_value" let options: Options let currentDateProvider = TestCurrentDateProvider() +#if os(iOS) || os(tvOS) || targetEnvironment(macCatalyst) + let tracer = SentryTracer(context: SpanContext(operation: "TEST"), framesTracker: nil) +#else let tracer = SentryTracer(context: SpanContext(operation: "TEST")) +#endif init() { options = Options() @@ -33,6 +38,13 @@ class SentrySpanTests: XCTestCase { return hub.startTransaction(name: someTransaction, operation: someOperation) } + func getSutWithTracer() -> SentrySpan { +#if os(iOS) || os(tvOS) || targetEnvironment(macCatalyst) + return SentrySpan(tracer: tracer, context: SpanContext(operation: someOperation, sampled: .undecided), framesTracker: nil) +#else + return SentrySpan(tracer: tracer, context: SpanContext(operation: someOperation, sampled: .undecided)) +#endif + } } override func setUp() { @@ -142,7 +154,7 @@ class SentrySpanTests: XCTestCase { } func testFinishSpanWithDefaultTimestamp() { - let span = SentrySpan(tracer: fixture.tracer, context: SpanContext(operation: fixture.someOperation, sampled: .undecided)) + let span = fixture.getSutWithTracer() span.finish() XCTAssertEqual(span.startTimestamp, TestData.timestamp) @@ -152,7 +164,7 @@ class SentrySpanTests: XCTestCase { } func testFinishSpanWithCustomTimestamp() { - let span = SentrySpan(tracer: fixture.tracer, context: SpanContext(operation: fixture.someOperation, sampled: .undecided)) + let span = fixture.getSutWithTracer() span.timestamp = Date(timeIntervalSince1970: 123) span.finish() @@ -292,15 +304,15 @@ class SentrySpanTests: XCTestCase { XCTAssertEqual("manual", serialization["origin"] as? String) } - func testSerialization_NoFrames() { - let span = SentrySpan(tracer: fixture.tracer, context: SpanContext(operation: "test")) + func testSerialization_NoStacktraceFrames() { + let span = fixture.getSutWithTracer() let serialization = span.serialize() XCTAssertEqual(2, (serialization["data"] as? [String: Any])?.count, "Only expected thread.name and thread.id in data.") } - func testSerialization_withFrames() { - let span = SentrySpan(tracer: fixture.tracer, context: SpanContext(operation: "test")) + func testSerialization_withStacktraceFrames() { + let span = fixture.getSutWithTracer() span.frames = [TestData.mainFrame, TestData.testFrame] let serialization = span.serialize() @@ -324,7 +336,7 @@ class SentrySpanTests: XCTestCase { } func testSanitizeDataSpan() { - let span = SentrySpan(tracer: fixture.tracer, context: SpanContext(operation: fixture.someOperation, sampled: .undecided)) + let span = fixture.getSutWithTracer() span.setData(value: Date(timeIntervalSince1970: 10), key: "date") span.finish() @@ -365,7 +377,7 @@ class SentrySpanTests: XCTestCase { } func testTraceHeaderUndecided() { - let span = SentrySpan(tracer: fixture.tracer, context: SpanContext(operation: fixture.someOperation, sampled: .undecided)) + let span = fixture.getSutWithTracer() let header = span.toTraceHeader() XCTAssertEqual(header.traceId, span.traceId) @@ -376,7 +388,7 @@ class SentrySpanTests: XCTestCase { @available(*, deprecated) func testSetExtra_ForwardsToSetData() { - let sut = SentrySpan(tracer: fixture.tracer, context: SpanContext(operation: "test")) + let sut = fixture.getSutWithTracer() sut.setExtra(value: 0, key: "key") let data = sut.data as [String: Any] @@ -387,8 +399,13 @@ class SentrySpanTests: XCTestCase { // Span has a weak reference to tracer. If we don't keep a reference // to the tracer ARC will deallocate the tracer. let sutGenerator: () -> Span = { +#if os(iOS) || os(tvOS) || targetEnvironment(macCatalyst) + let tracer = SentryTracer(context: SpanContext(operation: "TEST"), framesTracker: nil) + return SentrySpan(tracer: tracer, context: SpanContext(operation: ""), framesTracker: nil) +#else let tracer = SentryTracer(context: SpanContext(operation: "TEST")) return SentrySpan(tracer: tracer, context: SpanContext(operation: "")) +#endif } let sut = sutGenerator() @@ -451,4 +468,99 @@ class SentrySpanTests: XCTestCase { XCTAssertEqual(nameForSentrySpanStatus(.outOfRange), kSentrySpanStatusNameOutOfRange) XCTAssertEqual(nameForSentrySpanStatus(.dataLoss), kSentrySpanStatusNameDataLoss) } + +#if os(iOS) || os(tvOS) || targetEnvironment(macCatalyst) + func testAddSlowFrozenFramesToData() { + let (displayLinkWrapper, framesTracker) = givenFramesTracker() + + let sut = SentrySpan(context: SpanContext(operation: "TEST"), framesTracker: framesTracker) + + let slow = 2 + let frozen = 1 + let normal = 100 + displayLinkWrapper.renderFrames(slow, frozen, normal) + + sut.finish() + + expect(sut.data["frames.total"] as? NSNumber) == NSNumber(value: slow + frozen + normal) + expect(sut.data["frames.slow"] as? NSNumber) == NSNumber(value: slow) + expect(sut.data["frames.frozen"] as? NSNumber) == NSNumber(value: frozen) + } + + func testDontAddAllZeroSlowFrozenFramesToData() { + let (_, framesTracker) = givenFramesTracker() + + let sut = SentrySpan(context: SpanContext(operation: "TEST"), framesTracker: framesTracker) + + sut.finish() + + expect(sut.data["frames.total"]) == nil + expect(sut.data["frames.slow"]) == nil + expect(sut.data["frames.frozen"]) == nil + } + + func testDontAddZeroSlowFrozenFrames_WhenSpanStartedBackgroundThread() { + let (displayLinkWrapper, framesTracker) = givenFramesTracker() + + let expectation = expectation(description: "SpanStarted on a background thread") + DispatchQueue.global().async { + let sut = SentrySpan(context: SpanContext(operation: "TEST"), framesTracker: framesTracker) + + let slow = 2 + let frozen = 1 + let normal = 100 + displayLinkWrapper.renderFrames(slow, frozen, normal) + + sut.finish() + + expect(sut.data["frames.total"]) == nil + expect(sut.data["frames.slow"]) == nil + expect(sut.data["frames.frozen"]) == nil + + expectation.fulfill() + } + + wait(for: [expectation], timeout: 1.0) + } + + func testAddSlowFrozenFramesToData_WithPreexistingCounts() { + let (displayLinkWrapper, framesTracker) = givenFramesTracker() + let preexistingSlow = 1 + let preexistingFrozen = 2 + let preexistingNormal = 3 + displayLinkWrapper.renderFrames(preexistingSlow, preexistingFrozen, preexistingNormal) + + let sut = SentrySpan(context: SpanContext(operation: "TEST"), framesTracker: framesTracker) + + let slow = 7 + let frozen = 8 + let normal = 9 + displayLinkWrapper.renderFrames(slow, frozen, normal) + + sut.finish() + + expect(sut.data["frames.total"] as? NSNumber) == NSNumber(value: slow + frozen + normal) + expect(sut.data["frames.slow"] as? NSNumber) == NSNumber(value: slow) + expect(sut.data["frames.frozen"] as? NSNumber) == NSNumber(value: frozen) + } + + func testNoFramesTracker_NoFramesAddedToData() { + let sut = SentrySpan(context: SpanContext(operation: "TEST"), framesTracker: nil) + + sut.finish() + + expect(sut.data["frames.total"]) == nil + expect(sut.data["frames.slow"]) == nil + expect(sut.data["frames.frozen"]) == nil + } + + private func givenFramesTracker() -> (TestDisplayLinkWrapper, SentryFramesTracker) { + let displayLinkWrapper = TestDisplayLinkWrapper() + let framesTracker = SentryFramesTracker(displayLinkWrapper: displayLinkWrapper) + framesTracker.start() + displayLinkWrapper.call() + + return (displayLinkWrapper, framesTracker) + } +#endif } diff --git a/Tests/SentryTests/Transaction/SentryTracerTests.swift b/Tests/SentryTests/Transaction/SentryTracerTests.swift index e63ca895a87..93efca9723f 100644 --- a/Tests/SentryTests/Transaction/SentryTracerTests.swift +++ b/Tests/SentryTests/Transaction/SentryTracerTests.swift @@ -1061,7 +1061,7 @@ class SentryTracerTests: XCTestCase { func testChangeStartTimeStamp_RemovesFramesMeasurement() throws { let sut = fixture.getSut() - fixture.displayLinkWrapper.givenFrames(1, 1, 1) + fixture.displayLinkWrapper.renderFrames(1, 1, 1) sut.updateStartTime(try XCTUnwrap(sut.startTimestamp).addingTimeInterval(-1)) sut.finish() @@ -1076,7 +1076,7 @@ class SentryTracerTests: XCTestCase { let frozenFrames = 1 let normalFrames = 100 let totalFrames = slowFrames + frozenFrames + normalFrames - fixture.displayLinkWrapper.givenFrames(slowFrames, frozenFrames, normalFrames) + fixture.displayLinkWrapper.renderFrames(slowFrames, frozenFrames, normalFrames) sut.finish() @@ -1093,7 +1093,7 @@ class SentryTracerTests: XCTestCase { } func testNegativeFramesAmount_NoMeasurementAdded() { - fixture.displayLinkWrapper.givenFrames(10, 10, 10) + fixture.displayLinkWrapper.renderFrames(10, 10, 10) let sut = fixture.getSut() From 7d7bc749b9f844ab98e342480bb8ca80b2ad8c7e Mon Sep 17 00:00:00 2001 From: Philipp Hofmann Date: Tue, 5 Dec 2023 13:20:28 +0100 Subject: [PATCH 05/31] test: Increase timeout for SpanTests (#3479) The SentrySpanTests sometimes fail because the expectations sometimes time out. To fix this, we increase the value so the tests don't fail when CI is busy. --- Tests/SentryTests/Transaction/SentrySpanTests.swift | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/Tests/SentryTests/Transaction/SentrySpanTests.swift b/Tests/SentryTests/Transaction/SentrySpanTests.swift index 99c7981342d..46e55c59dda 100644 --- a/Tests/SentryTests/Transaction/SentrySpanTests.swift +++ b/Tests/SentryTests/Transaction/SentrySpanTests.swift @@ -93,7 +93,7 @@ class SentrySpanTests: XCTestCase { expect.fulfill() } - wait(for: [expect], timeout: 0.1) + wait(for: [expect], timeout: 1.0) } func testInit_SetsThreadInfoAsSpanData_FromBackgroundThreadWithNoName() { @@ -110,7 +110,7 @@ class SentrySpanTests: XCTestCase { expect.fulfill() } - wait(for: [expect], timeout: 0.1) + wait(for: [expect], timeout: 1.0) } func testFinish() { From 50bbebba38666fd2e317e7d3c769bc732261af15 Mon Sep 17 00:00:00 2001 From: Philipp Hofmann Date: Tue, 5 Dec 2023 13:59:47 +0100 Subject: [PATCH 06/31] ref: Add comment for CrashExceptionApplication (#3480) Add a comment to explain why we need SentryCrashExceptionApplication. --- Sources/Sentry/Public/SentryCrashExceptionApplication.h | 2 ++ 1 file changed, 2 insertions(+) diff --git a/Sources/Sentry/Public/SentryCrashExceptionApplication.h b/Sources/Sentry/Public/SentryCrashExceptionApplication.h index c70ecaf87c6..44531561bc4 100644 --- a/Sources/Sentry/Public/SentryCrashExceptionApplication.h +++ b/Sources/Sentry/Public/SentryCrashExceptionApplication.h @@ -4,6 +4,8 @@ // this the SDK breaks for MacOS. #import +// Required for capturing uncaught exceptions in macOS. For more info see +// https://docs.sentry.io/platforms/apple/guides/macos/usage/#capturing-uncaught-exceptions-in-macos #if TARGET_OS_OSX # import @interface SentryCrashExceptionApplication : NSApplication From 20f4f5d53b566c947e9199aa23ee83dea27baafc Mon Sep 17 00:00:00 2001 From: Philipp Hofmann Date: Tue, 5 Dec 2023 23:31:49 +0100 Subject: [PATCH 07/31] ref: Send frames for all spans (#3478) Initially, we wanted to send frame data only for spans started on the main thread, but we decided that the frame data makes sense for all spans. This PR fixes that. --- CHANGELOG.md | 2 +- Sources/Sentry/SentrySpan.m | 21 +++++++++---------- .../Transaction/SentrySpanTests.swift | 9 ++++---- 3 files changed, 15 insertions(+), 17 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 01a86d47979..5398bf41268 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -4,7 +4,7 @@ ## Features -- Add slow and frozen frames to spans (#3450) +- Add slow and frozen frames to spans (#3450, #3478) ## 8.17.1 diff --git a/Sources/Sentry/SentrySpan.m b/Sources/Sentry/SentrySpan.m index 3caa32accaa..8ea1cac2b50 100644 --- a/Sources/Sentry/SentrySpan.m +++ b/Sources/Sentry/SentrySpan.m @@ -57,22 +57,21 @@ - (instancetype)initWithContext:(SentrySpanContext *)context if ([NSThread isMainThread]) { _data[SPAN_DATA_THREAD_NAME] = @"main"; - -#if SENTRY_HAS_UIKIT - // Only track frames if running on main thread. - _framesTracker = framesTracker; - if (_framesTracker.isRunning) { - SentryScreenFrames *currentFrames = _framesTracker.currentFrames; - initTotalFrames = currentFrames.total; - initSlowFrames = currentFrames.slow; - initFrozenFrames = currentFrames.frozen; - } -#endif // SENTRY_HAS_UIKIT } else { _data[SPAN_DATA_THREAD_NAME] = [SentryDependencyContainer.sharedInstance.threadInspector getThreadName:currentThread]; } +#if SENTRY_HAS_UIKIT + _framesTracker = framesTracker; + if (_framesTracker.isRunning) { + SentryScreenFrames *currentFrames = _framesTracker.currentFrames; + initTotalFrames = currentFrames.total; + initSlowFrames = currentFrames.slow; + initFrozenFrames = currentFrames.frozen; + } +#endif // SENTRY_HAS_UIKIT + _tags = [[NSMutableDictionary alloc] init]; _stateLock = [[NSObject alloc] init]; _isFinished = NO; diff --git a/Tests/SentryTests/Transaction/SentrySpanTests.swift b/Tests/SentryTests/Transaction/SentrySpanTests.swift index 46e55c59dda..23a49998353 100644 --- a/Tests/SentryTests/Transaction/SentrySpanTests.swift +++ b/Tests/SentryTests/Transaction/SentrySpanTests.swift @@ -499,7 +499,7 @@ class SentrySpanTests: XCTestCase { expect(sut.data["frames.frozen"]) == nil } - func testDontAddZeroSlowFrozenFrames_WhenSpanStartedBackgroundThread() { + func testAddZeroSlowFrozenFrames_WhenSpanStartedBackgroundThread() { let (displayLinkWrapper, framesTracker) = givenFramesTracker() let expectation = expectation(description: "SpanStarted on a background thread") @@ -513,10 +513,9 @@ class SentrySpanTests: XCTestCase { sut.finish() - expect(sut.data["frames.total"]) == nil - expect(sut.data["frames.slow"]) == nil - expect(sut.data["frames.frozen"]) == nil - + expect(sut.data["frames.total"] as? NSNumber) == NSNumber(value: slow + frozen + normal) + expect(sut.data["frames.slow"] as? NSNumber) == NSNumber(value: slow) + expect(sut.data["frames.frozen"] as? NSNumber) == NSNumber(value: frozen) expectation.fulfill() } From 29d558ecf1bb0e444198c4b154787948ff8eabbd Mon Sep 17 00:00:00 2001 From: Philipp Hofmann Date: Wed, 6 Dec 2023 12:45:48 +0100 Subject: [PATCH 08/31] ref: Add nanosecondsToTimeInterval (#3483) SentryTime has timeIntervalToNanoseconds but not nanosecondsToTimeInterval. This PR adds nanosecondsToTimeInterval. Co-authored-by: Andrew McKnight --- Sentry.xcodeproj/project.pbxproj | 4 ++++ Sources/Sentry/SentryTime.mm | 10 +++++++-- Sources/Sentry/include/SentryTime.h | 3 +++ .../Helper/SentryTimeSwiftTests.swift | 21 +++++++++++++++++++ 4 files changed, 36 insertions(+), 2 deletions(-) create mode 100644 Tests/SentryTests/Helper/SentryTimeSwiftTests.swift diff --git a/Sentry.xcodeproj/project.pbxproj b/Sentry.xcodeproj/project.pbxproj index 66d56df9c5d..3aba2bee9f8 100644 --- a/Sentry.xcodeproj/project.pbxproj +++ b/Sentry.xcodeproj/project.pbxproj @@ -90,6 +90,7 @@ 62A456E52B0370E0003F19A1 /* SentryUIEventTrackerTransactionMode.m in Sources */ = {isa = PBXBuildFile; fileRef = 62A456E42B0370E0003F19A1 /* SentryUIEventTrackerTransactionMode.m */; }; 62B86CFC29F052BB008F3947 /* SentryTestLogConfig.m in Sources */ = {isa = PBXBuildFile; fileRef = 62B86CFB29F052BB008F3947 /* SentryTestLogConfig.m */; }; 62C25C862B075F4900C68CBD /* TestOptions.swift in Sources */ = {isa = PBXBuildFile; fileRef = 62C25C852B075F4900C68CBD /* TestOptions.swift */; }; + 62C3168B2B1F865A000D7031 /* SentryTimeSwiftTests.swift in Sources */ = {isa = PBXBuildFile; fileRef = 62C3168A2B1F865A000D7031 /* SentryTimeSwiftTests.swift */; }; 62E081A929ED4260000F69FC /* SentryBreadcrumbDelegate.h in Headers */ = {isa = PBXBuildFile; fileRef = 62E081A829ED4260000F69FC /* SentryBreadcrumbDelegate.h */; }; 62E081AB29ED4322000F69FC /* SentryBreadcrumbTestDelegate.swift in Sources */ = {isa = PBXBuildFile; fileRef = 62E081AA29ED4322000F69FC /* SentryBreadcrumbTestDelegate.swift */; }; 62F226B729A37C120038080D /* SentryBooleanSerialization.m in Sources */ = {isa = PBXBuildFile; fileRef = 62F226B629A37C120038080D /* SentryBooleanSerialization.m */; }; @@ -1002,6 +1003,7 @@ 62A456E42B0370E0003F19A1 /* SentryUIEventTrackerTransactionMode.m */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.objc; path = SentryUIEventTrackerTransactionMode.m; sourceTree = ""; }; 62B86CFB29F052BB008F3947 /* SentryTestLogConfig.m */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.objc; path = SentryTestLogConfig.m; sourceTree = ""; }; 62C25C852B075F4900C68CBD /* TestOptions.swift */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.swift; path = TestOptions.swift; sourceTree = ""; }; + 62C3168A2B1F865A000D7031 /* SentryTimeSwiftTests.swift */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.swift; path = SentryTimeSwiftTests.swift; sourceTree = ""; }; 62E081A829ED4260000F69FC /* SentryBreadcrumbDelegate.h */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.h; name = SentryBreadcrumbDelegate.h; path = include/SentryBreadcrumbDelegate.h; sourceTree = ""; }; 62E081AA29ED4322000F69FC /* SentryBreadcrumbTestDelegate.swift */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.swift; path = SentryBreadcrumbTestDelegate.swift; sourceTree = ""; }; 62F226B629A37C120038080D /* SentryBooleanSerialization.m */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.objc; path = SentryBooleanSerialization.m; sourceTree = ""; }; @@ -2854,6 +2856,7 @@ 84A8892028DBD8D600C51DFD /* SentryDeviceTests.mm */, D85790282976A69F00C6AC1F /* TestDebugImageProvider.swift */, 8431EE5A29ADB8EA00D8DC56 /* SentryTimeTests.m */, + 62C3168A2B1F865A000D7031 /* SentryTimeSwiftTests.swift */, 33042A1629DC2C4300C60085 /* SentryExtraContextProviderTests.swift */, ); path = Helper; @@ -4403,6 +4406,7 @@ 63EED6C32237989300E02400 /* SentryOptionsTest.m in Sources */, 7BBD18B22451804C00427C76 /* SentryRetryAfterHeaderParserTests.swift in Sources */, 7BD337E424A356180050DB6E /* SentryCrashIntegrationTests.swift in Sources */, + 62C3168B2B1F865A000D7031 /* SentryTimeSwiftTests.swift in Sources */, 7BD4E8E827FD95900086C410 /* SentryMigrateSessionInitTests.m in Sources */, 7B6CC50224EE5A42001816D7 /* SentryHubTests.swift in Sources */, 7BF9EF882722D13000B5BBEF /* SentryTestObjCRuntimeWrapper.m in Sources */, diff --git a/Sources/Sentry/SentryTime.mm b/Sources/Sentry/SentryTime.mm index 91da1b3e71b..d003e68c422 100644 --- a/Sources/Sentry/SentryTime.mm +++ b/Sources/Sentry/SentryTime.mm @@ -10,9 +10,15 @@ timeIntervalToNanoseconds(double seconds) { NSCAssert(seconds >= 0, @"Seconds must be a positive value"); - NSCAssert(seconds <= UINT64_MAX / 1e9, + NSCAssert(seconds <= (double)UINT64_MAX / (double)NSEC_PER_SEC, @"Value of seconds is too great; will overflow if casted to a uint64_t"); - return (uint64_t)(seconds * 1e9); + return (uint64_t)(seconds * NSEC_PER_SEC); +} + +double +nanosecondsToTimeInterval(uint64_t nanoseconds) +{ + return (double)nanoseconds / NSEC_PER_SEC; } uint64_t diff --git a/Sources/Sentry/include/SentryTime.h b/Sources/Sentry/include/SentryTime.h index 3985b60d12a..50ab2098e60 100644 --- a/Sources/Sentry/include/SentryTime.h +++ b/Sources/Sentry/include/SentryTime.h @@ -11,6 +11,9 @@ SENTRY_EXTERN_C_BEGIN */ uint64_t timeIntervalToNanoseconds(double seconds); +/** Converts integer nanoseconds to a @c NSTimeInterval. */ +double nanosecondsToTimeInterval(uint64_t nanoseconds); + /** * Returns the absolute timestamp, which has no defined reference point or unit * as it is platform dependent. diff --git a/Tests/SentryTests/Helper/SentryTimeSwiftTests.swift b/Tests/SentryTests/Helper/SentryTimeSwiftTests.swift new file mode 100644 index 00000000000..e5313bdcff0 --- /dev/null +++ b/Tests/SentryTests/Helper/SentryTimeSwiftTests.swift @@ -0,0 +1,21 @@ +import Nimble +import XCTest + +final class SentryTimeSwiftTests: XCTestCase { + + func testTimeIntervalToNanoseconds() { + expect(timeIntervalToNanoseconds(0.0)) == UInt64(0) + expect(timeIntervalToNanoseconds(0.5)) == UInt64(500_000_000) + expect(timeIntervalToNanoseconds(1.0)) == UInt64(1_000_000_000) + expect(timeIntervalToNanoseconds(1.123456789)) == UInt64(1_123_456_789) + expect(timeIntervalToNanoseconds(123_456_789.123456)) == UInt64(123_456_789_123_456_000) + } + + func testNanosecondsToTimeInterval() { + expect(nanosecondsToTimeInterval(0)).to(beCloseTo(0.0, within: 1e-9)) + expect(nanosecondsToTimeInterval(500_000_000)).to(beCloseTo(0.5, within: 1e-9)) + expect(nanosecondsToTimeInterval(1_000_000_000)).to(beCloseTo(1.0, within: 1e-9)) + expect(nanosecondsToTimeInterval(1_123_456_789)).to(beCloseTo(1.123456789, within: 1e-9)) + expect(nanosecondsToTimeInterval(123_456_789_123_456_000)).to(beCloseTo(123_456_789.123456, within: 1e-9)) + } +} From 0288d6cede4d53c0785bc759981c8915c466c2a0 Mon Sep 17 00:00:00 2001 From: Philipp Hofmann Date: Thu, 7 Dec 2023 09:11:06 +0100 Subject: [PATCH 09/31] test: Fix checkTotalFrames (#3485) Don't base min and max expected frames on the current frame rate as it could change while rendering frames. --- .../iOS-SwiftUITests/LaunchUITests.swift | 17 +++++++---------- 1 file changed, 7 insertions(+), 10 deletions(-) diff --git a/Samples/iOS-Swift/iOS-SwiftUITests/LaunchUITests.swift b/Samples/iOS-Swift/iOS-SwiftUITests/LaunchUITests.swift index 0ae008e0112..d810d203a1e 100644 --- a/Samples/iOS-Swift/iOS-SwiftUITests/LaunchUITests.swift +++ b/Samples/iOS-Swift/iOS-SwiftUITests/LaunchUITests.swift @@ -109,19 +109,16 @@ class LaunchUITests: BaseUITest { let endDate = Date() let secondsBetween = endDate.timeIntervalSince(startDate) - - // Retrieving the number of frames from the text label is inaccurate. - // Therefore, we add a one-second tolerance for the expected amount of frames. - // We only want to validate if the number of total frames is entirely off. - let maximumFramesPerSecond = Double(UIScreen.main.maximumFramesPerSecond) - - let expectedMinimumTotalFrames = (secondsBetween - 1.0) * maximumFramesPerSecond - let expectedMaximumTotalFrames = (secondsBetween + 1.0) * maximumFramesPerSecond + + // We don't calculate the min and max values based on the frame rate, as it could have changed while waiting for them to render. + // Instead, we pick the minimum value based on 60fps and the maximum value based on 120fps. + let expectedMinimumTotalFrames = (secondsBetween - 1.0) * 60 + let expectedMaximumTotalFrames = (secondsBetween + 1.0) * 120 let actualTotalFrames = Double(endTotalFrames - startTotalFrames) - XCTAssertGreaterThanOrEqual(actualTotalFrames, expectedMinimumTotalFrames, "Actual frames:\(actualTotalFrames) should be greater than \(expectedMinimumTotalFrames) with frame rate of \(maximumFramesPerSecond)") - XCTAssertLessThanOrEqual(actualTotalFrames, expectedMaximumTotalFrames, "Actual frames:\(actualTotalFrames) should be less than \(expectedMaximumTotalFrames) with frame rate of \(maximumFramesPerSecond)") + XCTAssertGreaterThanOrEqual(actualTotalFrames, expectedMinimumTotalFrames, "Actual frames:\(actualTotalFrames) should be greater than \(expectedMinimumTotalFrames)") + XCTAssertLessThanOrEqual(actualTotalFrames, expectedMaximumTotalFrames, "Actual frames:\(actualTotalFrames) should be less than \(expectedMaximumTotalFrames)") } /** From ddb47781bffd76406f31ab43e66760362585fcd7 Mon Sep 17 00:00:00 2001 From: Philipp Hofmann Date: Thu, 7 Dec 2023 09:11:33 +0100 Subject: [PATCH 10/31] test: Fix TestDisplayLink rounding issues (#3482) Calling the TestDisplayLinkWrapper with multiple slowestSlowFrames or fastestFrozenFrames in tests leads to wrong results. This is fixed now by adding and subtracting the timeEpsilon for these. --- SentryTestUtils/TestDisplayLinkWrapper.swift | 19 +++++++++---- .../SentryFramesTrackerTests.swift | 28 +++++++++++++++++++ 2 files changed, 41 insertions(+), 6 deletions(-) diff --git a/SentryTestUtils/TestDisplayLinkWrapper.swift b/SentryTestUtils/TestDisplayLinkWrapper.swift index 9db29f7dbcd..4110f52e1a5 100644 --- a/SentryTestUtils/TestDisplayLinkWrapper.swift +++ b/SentryTestUtils/TestDisplayLinkWrapper.swift @@ -23,11 +23,19 @@ public class TestDisplayLinkWrapper: SentryDisplayLinkWrapper { public var target: AnyObject! public var selector: Selector! public var currentFrameRate: FrameRate = .low - let frozenFrameThreshold = 0.7 + + private let frozenFrameThreshold = 0.7 + private let slowestSlowFrameDuration: Double + private let fastestFrozenFrameDuration: Double + public var dateProvider: TestCurrentDateProvider public init(dateProvider: TestCurrentDateProvider = TestCurrentDateProvider()) { self.dateProvider = dateProvider + // The test date provider converts the duration from UInt64 to a double back and forth. + // Therefore we have rounding issues, and subtract or add the timeEpsilon. + slowestSlowFrameDuration = frozenFrameThreshold - timeEpsilon + fastestFrozenFrameDuration = frozenFrameThreshold + timeEpsilon } public var linkInvocations = Invocations() @@ -80,16 +88,15 @@ public class TestDisplayLinkWrapper: SentryDisplayLinkWrapper { } public func slowestSlowFrame() -> CFTimeInterval { - dateProvider.advance(by: frozenFrameThreshold) + dateProvider.advance(by: slowestSlowFrameDuration) call() - return frozenFrameThreshold + return slowestSlowFrameDuration } public func fastestFrozenFrame() -> CFTimeInterval { - let duration: Double = frozenFrameThreshold + timeEpsilon - dateProvider.advance(by: duration) + dateProvider.advance(by: fastestFrozenFrameDuration) call() - return duration + return fastestFrozenFrameDuration } /// There's no upper bound for a frozen frame, except maybe for the watchdog time limit. diff --git a/Tests/SentryTests/Integrations/Performance/FramesTracking/SentryFramesTrackerTests.swift b/Tests/SentryTests/Integrations/Performance/FramesTracking/SentryFramesTrackerTests.swift index 16bd53155af..6e8d6824fb6 100644 --- a/Tests/SentryTests/Integrations/Performance/FramesTracking/SentryFramesTrackerTests.swift +++ b/Tests/SentryTests/Integrations/Performance/FramesTracking/SentryFramesTrackerTests.swift @@ -84,6 +84,20 @@ class SentryFramesTrackerTests: XCTestCase { try assert(slow: 2, frozen: 0, total: 3) } + + func testMultipleSlowestSlowFrames() throws { + let sut = fixture.sut + sut.start() + + fixture.displayLinkWrapper.call() + + let slowFramesCount: UInt = 20 + for _ in 0.. Date: Mon, 11 Dec 2023 15:10:47 -0800 Subject: [PATCH 11/31] ref: rename ViewController->TransactionsViewController (#3489) --- .../iOS-Swift/iOS-Swift.xcodeproj/project.pbxproj | 12 ++++++------ .../iOS-Swift/iOS-Swift/Base.lproj/Main.storyboard | 6 +++--- ...roller.swift => TransactionsViewController.swift} | 2 +- 3 files changed, 10 insertions(+), 10 deletions(-) rename Samples/iOS-Swift/iOS-Swift/{ViewController.swift => TransactionsViewController.swift} (99%) diff --git a/Samples/iOS-Swift/iOS-Swift.xcodeproj/project.pbxproj b/Samples/iOS-Swift/iOS-Swift.xcodeproj/project.pbxproj index 7d36ea6a636..2d22820527c 100644 --- a/Samples/iOS-Swift/iOS-Swift.xcodeproj/project.pbxproj +++ b/Samples/iOS-Swift/iOS-Swift.xcodeproj/project.pbxproj @@ -14,7 +14,7 @@ 62C07D5C2AF3E3F500894688 /* BaseUITest.swift in Sources */ = {isa = PBXBuildFile; fileRef = 62C07D5B2AF3E3F500894688 /* BaseUITest.swift */; }; 630853532440C60F00DDE4CE /* Sentry.framework in Frameworks */ = {isa = PBXBuildFile; fileRef = 630853322440C44F00DDE4CE /* Sentry.framework */; }; 637AFDAA243B02760034958B /* AppDelegate.swift in Sources */ = {isa = PBXBuildFile; fileRef = 637AFDA9243B02760034958B /* AppDelegate.swift */; }; - 637AFDAE243B02760034958B /* ViewController.swift in Sources */ = {isa = PBXBuildFile; fileRef = 637AFDAD243B02760034958B /* ViewController.swift */; }; + 637AFDAE243B02760034958B /* TransactionsViewController.swift in Sources */ = {isa = PBXBuildFile; fileRef = 637AFDAD243B02760034958B /* TransactionsViewController.swift */; }; 637AFDB1243B02760034958B /* Main.storyboard in Resources */ = {isa = PBXBuildFile; fileRef = 637AFDAF243B02760034958B /* Main.storyboard */; }; 637AFDB3243B02770034958B /* Assets.xcassets in Resources */ = {isa = PBXBuildFile; fileRef = 637AFDB2243B02770034958B /* Assets.xcassets */; }; 637AFDB6243B02770034958B /* LaunchScreen.storyboard in Resources */ = {isa = PBXBuildFile; fileRef = 637AFDB4243B02770034958B /* LaunchScreen.storyboard */; }; @@ -60,7 +60,7 @@ D8269A55274C0F9A00BD5BD5 /* TraceTestViewController.swift in Sources */ = {isa = PBXBuildFile; fileRef = 8E8C57AE25EF16E6001CEEFA /* TraceTestViewController.swift */; }; D8269A56274C0F9E00BD5BD5 /* NibViewController.xib in Resources */ = {isa = PBXBuildFile; fileRef = D890CD3B26CEE2FA001246CF /* NibViewController.xib */; }; D8269A57274C0FA100BD5BD5 /* NibViewController.swift in Sources */ = {isa = PBXBuildFile; fileRef = D890CD3E26CEE31B001246CF /* NibViewController.swift */; }; - D8269A58274C0FC700BD5BD5 /* ViewController.swift in Sources */ = {isa = PBXBuildFile; fileRef = 637AFDAD243B02760034958B /* ViewController.swift */; }; + D8269A58274C0FC700BD5BD5 /* TransactionsViewController.swift in Sources */ = {isa = PBXBuildFile; fileRef = 637AFDAD243B02760034958B /* TransactionsViewController.swift */; }; D8269A59274C100300BD5BD5 /* Sentry.framework in Frameworks */ = {isa = PBXBuildFile; fileRef = 630853322440C44F00DDE4CE /* Sentry.framework */; }; D8269A5A274C100300BD5BD5 /* Sentry.framework in Embed Frameworks */ = {isa = PBXBuildFile; fileRef = 630853322440C44F00DDE4CE /* Sentry.framework */; settings = {ATTRIBUTES = (CodeSignOnCopy, RemoveHeadersOnCopy, ); }; }; D83A30C8279EFD6E00372D0A /* ClearTestState.swift in Sources */ = {isa = PBXBuildFile; fileRef = D83A30C7279EFD6E00372D0A /* ClearTestState.swift */; }; @@ -290,7 +290,7 @@ 6308532C2440C44F00DDE4CE /* Sentry.xcodeproj */ = {isa = PBXFileReference; lastKnownFileType = "wrapper.pb-project"; name = Sentry.xcodeproj; path = ../../Sentry.xcodeproj; sourceTree = ""; }; 637AFDA6243B02760034958B /* iOS-Swift.app */ = {isa = PBXFileReference; explicitFileType = wrapper.application; includeInIndex = 0; path = "iOS-Swift.app"; sourceTree = BUILT_PRODUCTS_DIR; }; 637AFDA9243B02760034958B /* AppDelegate.swift */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.swift; path = AppDelegate.swift; sourceTree = ""; }; - 637AFDAD243B02760034958B /* ViewController.swift */ = {isa = PBXFileReference; indentWidth = 4; lastKnownFileType = sourcecode.swift; path = ViewController.swift; sourceTree = ""; tabWidth = 4; }; + 637AFDAD243B02760034958B /* TransactionsViewController.swift */ = {isa = PBXFileReference; indentWidth = 4; lastKnownFileType = sourcecode.swift; path = TransactionsViewController.swift; sourceTree = ""; tabWidth = 4; }; 637AFDB0243B02760034958B /* Base */ = {isa = PBXFileReference; lastKnownFileType = file.storyboard; name = Base; path = Base.lproj/Main.storyboard; sourceTree = ""; }; 637AFDB2243B02770034958B /* Assets.xcassets */ = {isa = PBXFileReference; lastKnownFileType = folder.assetcatalog; path = Assets.xcassets; sourceTree = ""; }; 637AFDB5243B02770034958B /* Base */ = {isa = PBXFileReference; lastKnownFileType = file.storyboard; name = Base; path = Base.lproj/LaunchScreen.storyboard; sourceTree = ""; }; @@ -481,7 +481,7 @@ D8DBDA73274D4DF900007380 /* ViewControllers */, 63F93AA9245AC91600A500DB /* iOS-Swift.entitlements */, 637AFDA9243B02760034958B /* AppDelegate.swift */, - 637AFDAD243B02760034958B /* ViewController.swift */, + 637AFDAD243B02760034958B /* TransactionsViewController.swift */, 84AB90782A50031B0054C99A /* Profiling */, D80D021229EE93630084393D /* ErrorsViewController.swift */, D80D021929EE936F0084393D /* ExtraViewController.swift */, @@ -938,7 +938,7 @@ D890CD3F26CEE31B001246CF /* NibViewController.swift in Sources */, D845F35B27BAD4CC00A4D7A2 /* SentryData.xcdatamodeld in Sources */, D8444E4C275E38090042F4DE /* UIViewControllerExtension.swift in Sources */, - 637AFDAE243B02760034958B /* ViewController.swift in Sources */, + 637AFDAE243B02760034958B /* TransactionsViewController.swift in Sources */, D8832B132AF4F7FE00C522B0 /* TopViewControllerInspector.swift in Sources */, 0AABE2EA28855FF80057ED69 /* PermissionsViewController.swift in Sources */, 7B5525B32938B5B5006A2932 /* DiskWriteException.swift in Sources */, @@ -1006,7 +1006,7 @@ D8444E57275F795D0042F4DE /* UIViewControllerExtension.swift in Sources */, D8F3D058274E57D600B56F8C /* TableViewController.swift in Sources */, 7B5525B62938B644006A2932 /* DiskWriteException.swift in Sources */, - D8269A58274C0FC700BD5BD5 /* ViewController.swift in Sources */, + D8269A58274C0FC700BD5BD5 /* TransactionsViewController.swift in Sources */, 844DA821282584C300E6B62E /* CoreDataViewController.swift in Sources */, D8444E55275F79570042F4DE /* SpanExtension.swift in Sources */, D8832B1F2AF535B200C522B0 /* PageViewController.swift in Sources */, diff --git a/Samples/iOS-Swift/iOS-Swift/Base.lproj/Main.storyboard b/Samples/iOS-Swift/iOS-Swift/Base.lproj/Main.storyboard index 372d6b033fc..094218d85bd 100644 --- a/Samples/iOS-Swift/iOS-Swift/Base.lproj/Main.storyboard +++ b/Samples/iOS-Swift/iOS-Swift/Base.lproj/Main.storyboard @@ -1,9 +1,9 @@ - + - + @@ -13,7 +13,7 @@ - + diff --git a/Samples/iOS-Swift/iOS-Swift/ViewController.swift b/Samples/iOS-Swift/iOS-Swift/TransactionsViewController.swift similarity index 99% rename from Samples/iOS-Swift/iOS-Swift/ViewController.swift rename to Samples/iOS-Swift/iOS-Swift/TransactionsViewController.swift index b28bea1e452..65d9404966d 100644 --- a/Samples/iOS-Swift/iOS-Swift/ViewController.swift +++ b/Samples/iOS-Swift/iOS-Swift/TransactionsViewController.swift @@ -1,7 +1,7 @@ import Sentry import UIKit -class ViewController: UIViewController { +class TransactionsViewController: UIViewController { @IBOutlet weak var anrFillingRunLoopButton: UIButton! From de033daa1cfa7690b0644ba9292b69259d386266 Mon Sep 17 00:00:00 2001 From: Philipp Hofmann Date: Thu, 14 Dec 2023 14:08:59 +0100 Subject: [PATCH 12/31] feat: Add frames delay to transactions (#3487) Add frames delay as span data to transactions. --- CHANGELOG.md | 1 + Sentry.xcodeproj/project.pbxproj | 16 + SentryTestUtils/TestDisplayLinkWrapper.swift | 8 +- Sources/Sentry/SentryDelayedFrame.m | 25 ++ Sources/Sentry/SentryDelayedFramesTracker.m | 196 +++++++++ Sources/Sentry/SentryDependencyContainer.m | 5 +- Sources/Sentry/SentryFramesTracker.m | 54 ++- Sources/Sentry/SentryTracer.m | 49 ++- Sources/Sentry/include/SentryDelayedFrame.h | 22 + .../include/SentryDelayedFramesTracker.h | 65 +++ Sources/Sentry/include/SentryFramesTracker.h | 12 +- Sources/Sentry/include/SentryTracer.h | 2 + .../SentryProfilerSwiftTests.swift | 2 +- .../SentryFramesTrackerTests.swift | 385 +++++++++++++++++- .../SentryTimeToDisplayTrackerTest.swift | 2 +- .../Transaction/SentrySpanTests.swift | 2 +- .../Transaction/SentryTracerTests.swift | 62 ++- 17 files changed, 847 insertions(+), 61 deletions(-) create mode 100644 Sources/Sentry/SentryDelayedFrame.m create mode 100644 Sources/Sentry/SentryDelayedFramesTracker.m create mode 100644 Sources/Sentry/include/SentryDelayedFrame.h create mode 100644 Sources/Sentry/include/SentryDelayedFramesTracker.h diff --git a/CHANGELOG.md b/CHANGELOG.md index 5398bf41268..72cb1233a1b 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -4,6 +4,7 @@ ## Features +- Add frames delay to transactions (#3487) - Add slow and frozen frames to spans (#3450, #3478) ## 8.17.1 diff --git a/Sentry.xcodeproj/project.pbxproj b/Sentry.xcodeproj/project.pbxproj index 3aba2bee9f8..e36918fc974 100644 --- a/Sentry.xcodeproj/project.pbxproj +++ b/Sentry.xcodeproj/project.pbxproj @@ -81,6 +81,8 @@ 622C08DB29E554B9002571D4 /* SentrySpanContext+Private.h in Headers */ = {isa = PBXBuildFile; fileRef = 622C08D929E554B9002571D4 /* SentrySpanContext+Private.h */; }; 623C45B02A651D8200D9E88B /* SentryCoreDataTracker+Test.m in Sources */ = {isa = PBXBuildFile; fileRef = 623C45AF2A651D8200D9E88B /* SentryCoreDataTracker+Test.m */; }; 627E7589299F6FE40085504D /* SentryInternalDefines.h in Headers */ = {isa = PBXBuildFile; fileRef = 627E7588299F6FE40085504D /* SentryInternalDefines.h */; }; + 62862B1C2B1DDBC8009B16E3 /* SentryDelayedFrame.h in Headers */ = {isa = PBXBuildFile; fileRef = 62862B1B2B1DDBC8009B16E3 /* SentryDelayedFrame.h */; }; + 62862B1E2B1DDC35009B16E3 /* SentryDelayedFrame.m in Sources */ = {isa = PBXBuildFile; fileRef = 62862B1D2B1DDC35009B16E3 /* SentryDelayedFrame.m */; }; 62885DA729E946B100554F38 /* TestConncurrentModifications.swift in Sources */ = {isa = PBXBuildFile; fileRef = 62885DA629E946B100554F38 /* TestConncurrentModifications.swift */; }; 62950F1029E7FE0100A42624 /* SentryTransactionContextTests.swift in Sources */ = {isa = PBXBuildFile; fileRef = 62950F0F29E7FE0100A42624 /* SentryTransactionContextTests.swift */; }; 629690532AD3E060000185FA /* SentryReachabilitySwiftTests.swift in Sources */ = {isa = PBXBuildFile; fileRef = 629690522AD3E060000185FA /* SentryReachabilitySwiftTests.swift */; }; @@ -91,6 +93,8 @@ 62B86CFC29F052BB008F3947 /* SentryTestLogConfig.m in Sources */ = {isa = PBXBuildFile; fileRef = 62B86CFB29F052BB008F3947 /* SentryTestLogConfig.m */; }; 62C25C862B075F4900C68CBD /* TestOptions.swift in Sources */ = {isa = PBXBuildFile; fileRef = 62C25C852B075F4900C68CBD /* TestOptions.swift */; }; 62C3168B2B1F865A000D7031 /* SentryTimeSwiftTests.swift in Sources */ = {isa = PBXBuildFile; fileRef = 62C3168A2B1F865A000D7031 /* SentryTimeSwiftTests.swift */; }; + 62C316812B1F2E93000D7031 /* SentryDelayedFramesTracker.h in Headers */ = {isa = PBXBuildFile; fileRef = 62C316802B1F2E93000D7031 /* SentryDelayedFramesTracker.h */; }; + 62C316832B1F2EA1000D7031 /* SentryDelayedFramesTracker.m in Sources */ = {isa = PBXBuildFile; fileRef = 62C316822B1F2EA1000D7031 /* SentryDelayedFramesTracker.m */; }; 62E081A929ED4260000F69FC /* SentryBreadcrumbDelegate.h in Headers */ = {isa = PBXBuildFile; fileRef = 62E081A829ED4260000F69FC /* SentryBreadcrumbDelegate.h */; }; 62E081AB29ED4322000F69FC /* SentryBreadcrumbTestDelegate.swift in Sources */ = {isa = PBXBuildFile; fileRef = 62E081AA29ED4322000F69FC /* SentryBreadcrumbTestDelegate.swift */; }; 62F226B729A37C120038080D /* SentryBooleanSerialization.m in Sources */ = {isa = PBXBuildFile; fileRef = 62F226B629A37C120038080D /* SentryBooleanSerialization.m */; }; @@ -995,6 +999,8 @@ 623C45AE2A651C4500D9E88B /* SentryCoreDataTracker+Test.h */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.h; path = "SentryCoreDataTracker+Test.h"; sourceTree = ""; }; 623C45AF2A651D8200D9E88B /* SentryCoreDataTracker+Test.m */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.objc; path = "SentryCoreDataTracker+Test.m"; sourceTree = ""; }; 627E7588299F6FE40085504D /* SentryInternalDefines.h */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.h; name = SentryInternalDefines.h; path = include/SentryInternalDefines.h; sourceTree = ""; }; + 62862B1B2B1DDBC8009B16E3 /* SentryDelayedFrame.h */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.h; name = SentryDelayedFrame.h; path = include/SentryDelayedFrame.h; sourceTree = ""; }; + 62862B1D2B1DDC35009B16E3 /* SentryDelayedFrame.m */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.objc; path = SentryDelayedFrame.m; sourceTree = ""; }; 62885DA629E946B100554F38 /* TestConncurrentModifications.swift */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.swift; path = TestConncurrentModifications.swift; sourceTree = ""; }; 62950F0F29E7FE0100A42624 /* SentryTransactionContextTests.swift */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.swift; path = SentryTransactionContextTests.swift; sourceTree = ""; }; 629690522AD3E060000185FA /* SentryReachabilitySwiftTests.swift */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.swift; path = SentryReachabilitySwiftTests.swift; sourceTree = ""; }; @@ -1004,6 +1010,8 @@ 62B86CFB29F052BB008F3947 /* SentryTestLogConfig.m */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.objc; path = SentryTestLogConfig.m; sourceTree = ""; }; 62C25C852B075F4900C68CBD /* TestOptions.swift */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.swift; path = TestOptions.swift; sourceTree = ""; }; 62C3168A2B1F865A000D7031 /* SentryTimeSwiftTests.swift */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.swift; path = SentryTimeSwiftTests.swift; sourceTree = ""; }; + 62C316802B1F2E93000D7031 /* SentryDelayedFramesTracker.h */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.h; name = SentryDelayedFramesTracker.h; path = include/SentryDelayedFramesTracker.h; sourceTree = ""; }; + 62C316822B1F2EA1000D7031 /* SentryDelayedFramesTracker.m */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.objc; path = SentryDelayedFramesTracker.m; sourceTree = ""; }; 62E081A829ED4260000F69FC /* SentryBreadcrumbDelegate.h */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.h; name = SentryBreadcrumbDelegate.h; path = include/SentryBreadcrumbDelegate.h; sourceTree = ""; }; 62E081AA29ED4322000F69FC /* SentryBreadcrumbTestDelegate.swift */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.swift; path = SentryBreadcrumbTestDelegate.swift; sourceTree = ""; }; 62F226B629A37C120038080D /* SentryBooleanSerialization.m */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.objc; path = SentryBooleanSerialization.m; sourceTree = ""; }; @@ -2943,6 +2951,10 @@ 7B6C5EDD264E8DF00010D138 /* SentryFramesTracker.m */, 7B7A599426B692540060A676 /* SentryScreenFrames.h */, 7B7A599626B692F00060A676 /* SentryScreenFrames.m */, + 62862B1B2B1DDBC8009B16E3 /* SentryDelayedFrame.h */, + 62862B1D2B1DDC35009B16E3 /* SentryDelayedFrame.m */, + 62C316802B1F2E93000D7031 /* SentryDelayedFramesTracker.h */, + 62C316822B1F2EA1000D7031 /* SentryDelayedFramesTracker.m */, ); name = FramesTracking; sourceTree = ""; @@ -3573,6 +3585,7 @@ 63B818F91EC34639002FDF4C /* SentryDebugMeta.h in Headers */, 6360850D1ED2AFE100E8599E /* SentryBreadcrumb.h in Headers */, 7BAF3DD92440AEC8008A5414 /* SentryRequestManager.h in Headers */, + 62862B1C2B1DDBC8009B16E3 /* SentryDelayedFrame.h in Headers */, 627E7589299F6FE40085504D /* SentryInternalDefines.h in Headers */, 7BE3C77B2446111500A38442 /* SentryRateLimitParser.h in Headers */, 84A888FD28D9B11700C51DFD /* SentryProfiler+Private.h in Headers */, @@ -3628,6 +3641,7 @@ 63FE718720DA4C1100CDBAE8 /* SentryCrashReportVersion.h in Headers */, 0A56DA5F28ABA01B00C400D5 /* SentryTransactionContext+Private.h in Headers */, 8E7C98312693E1CC00E6336C /* SentryTraceHeader.h in Headers */, + 62C316812B1F2E93000D7031 /* SentryDelayedFramesTracker.h in Headers */, 7BBD18912449BE9000427C76 /* SentryDefaultRateLimits.h in Headers */, 7B8713AE26415ADF006D6004 /* SentryAppStartTrackingIntegration.h in Headers */, 7B7D873224864BB900D2ECFF /* SentryCrashMachineContextWrapper.h in Headers */, @@ -4136,6 +4150,7 @@ 63FE712920DA4C1000CDBAE8 /* SentryCrashCPU_arm.c in Sources */, 03F84D3427DD4191008FE43F /* SentryThreadMetadataCache.cpp in Sources */, 7B88F30024BC5A7D00ADF90A /* SentrySdkInfo.m in Sources */, + 62862B1E2B1DDC35009B16E3 /* SentryDelayedFrame.m in Sources */, 84AC61D729F75A98009EEF61 /* SentryDispatchFactory.m in Sources */, 15360CD62432832400112302 /* SentryAutoSessionTrackingIntegration.m in Sources */, 7B63459F280EBA7200CFA05A /* SentryUIEventTracker.m in Sources */, @@ -4229,6 +4244,7 @@ 03F84D3827DD4191008FE43F /* SentryBacktrace.cpp in Sources */, 63FE712720DA4C1000CDBAE8 /* SentryCrashThread.c in Sources */, 7B127B0F27CF6F4700A71ED2 /* SentryANRTrackingIntegration.m in Sources */, + 62C316832B1F2EA1000D7031 /* SentryDelayedFramesTracker.m in Sources */, D8BFE37329A3782F002E73F3 /* SentryTimeToDisplayTracker.m in Sources */, 15360CCF2432777500112302 /* SentrySessionTracker.m in Sources */, 6334314320AD9AE40077E581 /* SentryMechanism.m in Sources */, diff --git a/SentryTestUtils/TestDisplayLinkWrapper.swift b/SentryTestUtils/TestDisplayLinkWrapper.swift index 4110f52e1a5..5f1016990e0 100644 --- a/SentryTestUtils/TestDisplayLinkWrapper.swift +++ b/SentryTestUtils/TestDisplayLinkWrapper.swift @@ -1,8 +1,6 @@ import Foundation #if os(iOS) || os(tvOS) || targetEnvironment(macCatalyst) -/// The smallest magnitude of time that is significant to how frames are classified as normal/slow/frozen. -let timeEpsilon = 0.001 public enum GPUFrame { case normal @@ -25,10 +23,12 @@ public class TestDisplayLinkWrapper: SentryDisplayLinkWrapper { public var currentFrameRate: FrameRate = .low private let frozenFrameThreshold = 0.7 - private let slowestSlowFrameDuration: Double - private let fastestFrozenFrameDuration: Double + public let slowestSlowFrameDuration: Double + public let fastestFrozenFrameDuration: Double public var dateProvider: TestCurrentDateProvider + /// The smallest magnitude of time that is significant to how frames are classified as normal/slow/frozen. + public let timeEpsilon = 0.001 public init(dateProvider: TestCurrentDateProvider = TestCurrentDateProvider()) { self.dateProvider = dateProvider diff --git a/Sources/Sentry/SentryDelayedFrame.m b/Sources/Sentry/SentryDelayedFrame.m new file mode 100644 index 00000000000..9d0290c7319 --- /dev/null +++ b/Sources/Sentry/SentryDelayedFrame.m @@ -0,0 +1,25 @@ +#import "SentryDelayedFrame.h" + +#if SENTRY_HAS_UIKIT + +NS_ASSUME_NONNULL_BEGIN + +@implementation SentryDelayedFrame + +- (instancetype)initWithStartTimestamp:(uint64_t)startSystemTimestamp + expectedDuration:(CFTimeInterval)expectedDuration + actualDuration:(CFTimeInterval)actualDuration +{ + if (self = [super init]) { + _startSystemTimestamp = startSystemTimestamp; + _expectedDuration = expectedDuration; + _actualDuration = actualDuration; + } + return self; +} + +@end + +NS_ASSUME_NONNULL_END + +#endif // SENTRY_HAS_UIKIT diff --git a/Sources/Sentry/SentryDelayedFramesTracker.m b/Sources/Sentry/SentryDelayedFramesTracker.m new file mode 100644 index 00000000000..0ef44cb59e8 --- /dev/null +++ b/Sources/Sentry/SentryDelayedFramesTracker.m @@ -0,0 +1,196 @@ +#import "SentryDelayedFramesTracker.h" + +#if SENTRY_HAS_UIKIT + +# import "SentryCurrentDateProvider.h" +# import "SentryDelayedFrame.h" +# import "SentryLog.h" +# import "SentryTime.h" + +NS_ASSUME_NONNULL_BEGIN + +@interface +SentryDelayedFramesTracker () + +@property (nonatomic, assign) CFTimeInterval keepDelayedFramesDuration; +@property (nonatomic, strong, readonly) SentryCurrentDateProvider *dateProvider; +@property (nonatomic, strong) NSMutableArray *delayedFrames; + +@end + +@implementation SentryDelayedFramesTracker + +- (instancetype)initWithKeepDelayedFramesDuration:(CFTimeInterval)keepDelayedFramesDuration + dateProvider:(SentryCurrentDateProvider *)dateProvider +{ + if (self = [super init]) { + _keepDelayedFramesDuration = keepDelayedFramesDuration; + _dateProvider = dateProvider; + [self resetDelayedFramesTimeStamps]; + } + return self; +} + +- (void)resetDelayedFramesTimeStamps +{ + _delayedFrames = [NSMutableArray array]; + SentryDelayedFrame *initialFrame = + [[SentryDelayedFrame alloc] initWithStartTimestamp:[self.dateProvider systemTime] + expectedDuration:0 + actualDuration:0]; + [_delayedFrames addObject:initialFrame]; +} + +- (void)recordDelayedFrame:(uint64_t)startSystemTimestamp + expectedDuration:(CFTimeInterval)expectedDuration + actualDuration:(CFTimeInterval)actualDuration +{ + @synchronized(self.delayedFrames) { + [self removeOldDelayedFrames]; + + SentryDelayedFrame *delayedFrame = + [[SentryDelayedFrame alloc] initWithStartTimestamp:startSystemTimestamp + expectedDuration:expectedDuration + actualDuration:actualDuration]; + [self.delayedFrames addObject:delayedFrame]; + } +} + +/** + * Removes delayed frame that are older than current time minus `keepDelayedFramesDuration`. + * @note Make sure to call this in a @synchronized block. + */ +- (void)removeOldDelayedFrames +{ + u_int64_t transactionMaxDurationNS = timeIntervalToNanoseconds(_keepDelayedFramesDuration); + + uint64_t removeFramesBeforeSystemTimeStamp + = _dateProvider.systemTime - transactionMaxDurationNS; + if (_dateProvider.systemTime < transactionMaxDurationNS) { + removeFramesBeforeSystemTimeStamp = 0; + } + + NSUInteger left = 0; + NSUInteger right = self.delayedFrames.count; + + while (left < right) { + NSUInteger mid = (left + right) / 2; + SentryDelayedFrame *midFrame = self.delayedFrames[mid]; + + uint64_t frameEndSystemTimeStamp + = midFrame.startSystemTimestamp + timeIntervalToNanoseconds(midFrame.actualDuration); + if (frameEndSystemTimeStamp >= removeFramesBeforeSystemTimeStamp) { + right = mid; + } else { + left = mid + 1; + } + } + + [self.delayedFrames removeObjectsInRange:NSMakeRange(0, left)]; +} + +- (CFTimeInterval)getFramesDelay:(uint64_t)startSystemTimestamp + endSystemTimestamp:(uint64_t)endSystemTimestamp + isRunning:(BOOL)isRunning + thisFrameTimestamp:(CFTimeInterval)thisFrameTimestamp + previousFrameTimestamp:(CFTimeInterval)previousFrameTimestamp + slowFrameThreshold:(CFTimeInterval)slowFrameThreshold +{ + CFTimeInterval cantCalculateFrameDelayReturnValue = -1.0; + + if (isRunning == NO) { + SENTRY_LOG_DEBUG(@"Not calculating frames delay because frames tracker isn't running."); + return cantCalculateFrameDelayReturnValue; + } + + if (startSystemTimestamp >= endSystemTimestamp) { + SENTRY_LOG_DEBUG(@"Not calculating frames delay because startSystemTimestamp is before " + @"endSystemTimestamp"); + return cantCalculateFrameDelayReturnValue; + } + + if (endSystemTimestamp > self.dateProvider.systemTime) { + SENTRY_LOG_DEBUG( + @"Not calculating frames delay because endSystemTimestamp is in the future."); + return cantCalculateFrameDelayReturnValue; + } + + if (previousFrameTimestamp < 0) { + SENTRY_LOG_DEBUG(@"Not calculating frames delay because no frames yet recorded."); + return cantCalculateFrameDelayReturnValue; + } + + NSArray *frames; + @synchronized(self.delayedFrames) { + uint64_t oldestDelayedFrameStartTimestamp = UINT64_MAX; + SentryDelayedFrame *oldestDelayedFrame = self.delayedFrames.firstObject; + if (oldestDelayedFrame != nil) { + oldestDelayedFrameStartTimestamp = oldestDelayedFrame.startSystemTimestamp; + } + + if (oldestDelayedFrameStartTimestamp > startSystemTimestamp) { + SENTRY_LOG_DEBUG(@"Not calculating frames delay because the record of delayed frames " + @"doesn't go back enough in time."); + return cantCalculateFrameDelayReturnValue; + } + + // Copy as late as possible to avoid allocating unnecessary memory. + frames = self.delayedFrames.copy; + } + + // Check if there is an delayed frame going on but not recorded yet. + CFTimeInterval frameDuration = thisFrameTimestamp - previousFrameTimestamp; + CFTimeInterval ongoingDelayedFrame = 0.0; + if (frameDuration > slowFrameThreshold) { + ongoingDelayedFrame = frameDuration - slowFrameThreshold; + } + + CFTimeInterval delay = ongoingDelayedFrame; + + // We need to calculate the intersections of the queried TimestampInterval + // (startSystemTimestamp - endSystemTimestamp) with the recorded frame delays. Doing that + // with NSDateInterval makes things easier. Therefore, we convert the system timestamps to + // NSDate objects, although they don't represent the correct dates. We only need to know how + // long the intersections are to calculate the frame delay and not precisely when. + + NSDate *startDate = [NSDate + dateWithTimeIntervalSinceReferenceDate:nanosecondsToTimeInterval(startSystemTimestamp)]; + NSDate *endDate = [NSDate + dateWithTimeIntervalSinceReferenceDate:nanosecondsToTimeInterval(endSystemTimestamp)]; + NSDateInterval *queryDateInterval = [[NSDateInterval alloc] initWithStartDate:startDate + endDate:endDate]; + + // Iterate in reverse order, as younger frame delays are more likely to match the queried + // period. + for (SentryDelayedFrame *frame in frames.reverseObjectEnumerator) { + + uint64_t frameEndSystemTimeStamp + = frame.startSystemTimestamp + timeIntervalToNanoseconds(frame.actualDuration); + if (frameEndSystemTimeStamp < startSystemTimestamp) { + break; + } + + CFTimeInterval delayStartTime + = nanosecondsToTimeInterval(frame.startSystemTimestamp) + frame.expectedDuration; + NSDate *frameDelayStartDate = + [NSDate dateWithTimeIntervalSinceReferenceDate:delayStartTime]; + + NSDateInterval *frameDelayDateInterval = [[NSDateInterval alloc] + initWithStartDate:frameDelayStartDate + duration:(frame.actualDuration - frame.expectedDuration)]; + + if ([queryDateInterval intersectsDateInterval:frameDelayDateInterval]) { + NSDateInterval *intersection = + [queryDateInterval intersectionWithDateInterval:frameDelayDateInterval]; + delay = delay + intersection.duration; + } + } + + return delay; +} + +@end + +NS_ASSUME_NONNULL_END + +#endif // SENTRY_HAS_UIKIT diff --git a/Sources/Sentry/SentryDependencyContainer.m b/Sources/Sentry/SentryDependencyContainer.m index dd04aaa1ff6..ab4b3dfc0d8 100644 --- a/Sources/Sentry/SentryDependencyContainer.m +++ b/Sources/Sentry/SentryDependencyContainer.m @@ -26,6 +26,7 @@ #import #import #import +#import #if SENTRY_HAS_UIKIT # import "SentryFramesTracker.h" @@ -268,7 +269,9 @@ - (SentryFramesTracker *)framesTracker @synchronized(sentryDependencyContainerLock) { if (_framesTracker == nil) { _framesTracker = [[SentryFramesTracker alloc] - initWithDisplayLinkWrapper:[[SentryDisplayLinkWrapper alloc] init]]; + initWithDisplayLinkWrapper:[[SentryDisplayLinkWrapper alloc] init] + dateProvider:self.dateProvider + keepDelayedFramesDuration:SENTRY_AUTO_TRANSACTION_MAX_DURATION]; } } } diff --git a/Sources/Sentry/SentryFramesTracker.m b/Sources/Sentry/SentryFramesTracker.m index 76da05f6b35..06237d902af 100644 --- a/Sources/Sentry/SentryFramesTracker.m +++ b/Sources/Sentry/SentryFramesTracker.m @@ -4,7 +4,8 @@ # import "SentryCompiler.h" # import "SentryCurrentDateProvider.h" -# import "SentryDependencyContainer.h" +# import "SentryDelayedFrame.h" +# import "SentryDelayedFramesTracker.h" # import "SentryDisplayLinkWrapper.h" # import "SentryLog.h" # import "SentryProfiler.h" @@ -26,8 +27,10 @@ SentryFramesTracker () @property (nonatomic, strong, readonly) SentryDisplayLinkWrapper *displayLinkWrapper; +@property (nonatomic, strong, readonly) SentryCurrentDateProvider *dateProvider; @property (nonatomic, assign) CFTimeInterval previousFrameTimestamp; @property (nonatomic) uint64_t previousFrameSystemTimestamp; +@property (nonatomic) uint64_t currentFrameRate; @property (nonatomic, strong) NSHashTable> *listeners; # if SENTRY_TARGET_PROFILING_SUPPORTED @property (nonatomic, readwrite) SentryMutableFrameInfoTimeSeries *frozenFrameTimestamps; @@ -35,6 +38,8 @@ @property (nonatomic, readwrite) SentryMutableFrameInfoTimeSeries *frameRateTimestamps; # endif // SENTRY_TARGET_PROFILING_SUPPORTED +@property (nonatomic, strong) SentryDelayedFramesTracker *delayedFramesTracker; + @end CFTimeInterval @@ -52,11 +57,20 @@ @implementation SentryFramesTracker { } - (instancetype)initWithDisplayLinkWrapper:(SentryDisplayLinkWrapper *)displayLinkWrapper + dateProvider:(SentryCurrentDateProvider *)dateProvider + keepDelayedFramesDuration:(CFTimeInterval)keepDelayedFramesDuration { if (self = [super init]) { _isRunning = NO; _displayLinkWrapper = displayLinkWrapper; + _dateProvider = dateProvider; + _delayedFramesTracker = [[SentryDelayedFramesTracker alloc] + initWithKeepDelayedFramesDuration:keepDelayedFramesDuration + dateProvider:dateProvider]; + _listeners = [NSHashTable weakObjectsHashTable]; + + _currentFrameRate = 60; [self resetFrames]; SENTRY_LOG_DEBUG(@"Initialized frame tracker %@", self); } @@ -80,6 +94,8 @@ - (void)resetFrames # if SENTRY_TARGET_PROFILING_SUPPORTED [self resetProfilingTimestamps]; # endif // SENTRY_TARGET_PROFILING_SUPPORTED + + [self.delayedFramesTracker resetDelayedFramesTimeStamps]; } # if SENTRY_TARGET_PROFILING_SUPPORTED @@ -105,8 +121,7 @@ - (void)start - (void)displayLinkCallback { CFTimeInterval thisFrameTimestamp = self.displayLinkWrapper.timestamp; - uint64_t thisFrameSystemTimestamp - = SentryDependencyContainer.sharedInstance.dateProvider.systemTime; + uint64_t thisFrameSystemTimestamp = self.dateProvider.systemTime; if (self.previousFrameTimestamp == SentryPreviousFrameInitialValue) { self.previousFrameTimestamp = thisFrameTimestamp; @@ -122,11 +137,9 @@ - (void)displayLinkCallback // need to check the frame rate for every callback. // targetTimestamp is only available on iOS 10.0 and tvOS 10.0 and above. We use a fallback of // 60 fps. - uint64_t currentFrameRate = 60; - if (UNLIKELY((self.displayLinkWrapper.targetTimestamp == self.displayLinkWrapper.timestamp))) { - currentFrameRate = 60; - } else { - currentFrameRate = (uint64_t)round( + _currentFrameRate = 60; + if (self.displayLinkWrapper.targetTimestamp != self.displayLinkWrapper.timestamp) { + _currentFrameRate = (uint64_t)round( (1 / (self.displayLinkWrapper.targetTimestamp - self.displayLinkWrapper.timestamp))); } @@ -135,12 +148,12 @@ - (void)displayLinkCallback BOOL hasNoFrameRatesYet = self.frameRateTimestamps.count == 0; uint64_t previousFrameRate = self.frameRateTimestamps.lastObject[@"value"].unsignedLongLongValue; - BOOL frameRateChanged = previousFrameRate != currentFrameRate; + BOOL frameRateChanged = previousFrameRate != _currentFrameRate; BOOL shouldRecordNewFrameRate = hasNoFrameRatesYet || frameRateChanged; if (shouldRecordNewFrameRate) { SENTRY_LOG_DEBUG(@"Recording new frame rate at %llu.", thisFrameSystemTimestamp); [self recordTimestamp:thisFrameSystemTimestamp - value:@(currentFrameRate) + value:@(_currentFrameRate) array:self.frameRateTimestamps]; } } @@ -148,7 +161,7 @@ - (void)displayLinkCallback CFTimeInterval frameDuration = thisFrameTimestamp - self.previousFrameTimestamp; - if (frameDuration > slowFrameThreshold(currentFrameRate) + if (frameDuration > slowFrameThreshold(_currentFrameRate) && frameDuration <= SentryFrozenFrameThreshold) { _slowFrames++; # if SENTRY_TARGET_PROFILING_SUPPORTED @@ -167,6 +180,13 @@ - (void)displayLinkCallback array:self.frozenFrameTimestamps]; # endif // SENTRY_TARGET_PROFILING_SUPPORTED } + + if (frameDuration > slowFrameThreshold(_currentFrameRate)) { + [self.delayedFramesTracker recordDelayedFrame:self.previousFrameSystemTimestamp + expectedDuration:slowFrameThreshold(_currentFrameRate) + actualDuration:frameDuration]; + } + _totalFrames++; self.previousFrameTimestamp = thisFrameTimestamp; self.previousFrameSystemTimestamp = thisFrameSystemTimestamp; @@ -214,6 +234,17 @@ - (SentryScreenFrames *)currentFrames # endif // SENTRY_TARGET_PROFILING_SUPPORTED } +- (CFTimeInterval)getFramesDelay:(uint64_t)startSystemTimestamp + endSystemTimestamp:(uint64_t)endSystemTimestamp +{ + return [self.delayedFramesTracker getFramesDelay:startSystemTimestamp + endSystemTimestamp:endSystemTimestamp + isRunning:_isRunning + thisFrameTimestamp:self.displayLinkWrapper.timestamp + previousFrameTimestamp:self.previousFrameTimestamp + slowFrameThreshold:slowFrameThreshold(_currentFrameRate)]; +} + - (void)addListener:(id)listener { @@ -233,6 +264,7 @@ - (void)stop { _isRunning = NO; [self.displayLinkWrapper invalidate]; + [self.delayedFramesTracker resetDelayedFramesTimeStamps]; } - (void)dealloc diff --git a/Sources/Sentry/SentryTracer.m b/Sources/Sentry/SentryTracer.m index 39284809123..78031ac82b8 100644 --- a/Sources/Sentry/SentryTracer.m +++ b/Sources/Sentry/SentryTracer.m @@ -56,12 +56,12 @@ static const NSTimeInterval SENTRY_APP_START_MEASUREMENT_DIFFERENCE = 5.0; #endif // SENTRY_HAS_UIKIT -static const NSTimeInterval SENTRY_AUTO_TRANSACTION_MAX_DURATION = 500.0; static const NSTimeInterval SENTRY_AUTO_TRANSACTION_DEADLINE = 30.0; @interface SentryTracer () +@property (nonatomic) uint64_t startSystemTime; @property (nonatomic) SentrySpanStatus finishStatus; /** This property is different from @c isFinished. While @c isFinished states if the tracer is * actually finished, this property tells you if finish was called on the tracer. Calling @@ -73,7 +73,6 @@ #if SENTRY_TARGET_PROFILING_SUPPORTED @property (nonatomic) BOOL isProfiling; -@property (nonatomic) uint64_t startSystemTime; #endif // SENTRY_TARGET_PROFILING_SUPPORTED @end @@ -131,6 +130,7 @@ - (instancetype)initWithTransactionContext:(SentryTransactionContext *)transacti return nil; } + _startSystemTime = SentryDependencyContainer.sharedInstance.dateProvider.systemTime; _configuration = configuration; self.transactionContext = transactionContext; @@ -172,7 +172,6 @@ - (instancetype)initWithTransactionContext:(SentryTransactionContext *)transacti #if SENTRY_TARGET_PROFILING_SUPPORTED if (_configuration.profilesSamplerDecision.decision == kSentrySampleDecisionYes) { - _startSystemTime = SentryDependencyContainer.sharedInstance.dateProvider.systemTime; _internalID = [[SentryId alloc] init]; _isProfiling = [SentryProfiler startWithTracer:_internalID]; } @@ -608,8 +607,11 @@ - (void)updateStartTime:(NSDate *)startTime - (SentryTransaction *)toTransaction { + NSUInteger capacity; #if SENTRY_HAS_UIKIT + [self addFrameStatistics]; + NSArray> *appStartSpans = sentryBuildAppStartSpans(self, appStartMeasurement); capacity = _children.count + appStartSpans.count; #else @@ -655,7 +657,7 @@ - (SentryTransaction *)toTransaction } #if SENTRY_HAS_UIKIT - [self addMeasurements:transaction]; + [self addAppStartMeasurements:transaction]; if ([viewNames count] > 0) { transaction.viewNames = viewNames; @@ -715,7 +717,7 @@ - (nullable SentryAppStartMeasurement *)getAppStartMeasurement return measurement; } -- (void)addMeasurements:(SentryTransaction *)transaction +- (void)addAppStartMeasurements:(SentryTransaction *)transaction { if (appStartMeasurement != nil && appStartMeasurement.type != SentryAppStartTypeUnknown) { NSString *type = nil; @@ -741,23 +743,36 @@ - (void)addMeasurements:(SentryTransaction *)transaction [transaction setContext:context]; } } +} - // Frames +- (void)addFrameStatistics +{ SentryFramesTracker *framesTracker = SentryDependencyContainer.sharedInstance.framesTracker; - if (framesTracker.isRunning && !_startTimeChanged) { + if (framesTracker.isRunning) { + CFTimeInterval framesDelay = [framesTracker + getFramesDelay:self.startSystemTime + endSystemTimestamp:SentryDependencyContainer.sharedInstance.dateProvider.systemTime]; - SentryScreenFrames *currentFrames = framesTracker.currentFrames; - NSInteger totalFrames = currentFrames.total - initTotalFrames; - NSInteger slowFrames = currentFrames.slow - initSlowFrames; - NSInteger frozenFrames = currentFrames.frozen - initFrozenFrames; + if (framesDelay >= 0) { + [self setDataValue:@(framesDelay) forKey:@"frames.delay"]; + SENTRY_LOG_DEBUG(@"Frames Delay:%f ms", framesDelay * 1000); + } - if (sentryShouldAddSlowFrozenFramesData(totalFrames, slowFrames, frozenFrames)) { - [self setMeasurement:@"frames_total" value:@(totalFrames)]; - [self setMeasurement:@"frames_slow" value:@(slowFrames)]; - [self setMeasurement:@"frames_frozen" value:@(frozenFrames)]; + if (!_startTimeChanged) { + SentryScreenFrames *currentFrames = framesTracker.currentFrames; + NSInteger totalFrames = currentFrames.total - initTotalFrames; + NSInteger slowFrames = currentFrames.slow - initSlowFrames; + NSInteger frozenFrames = currentFrames.frozen - initFrozenFrames; - SENTRY_LOG_DEBUG(@"Frames for transaction \"%@\" Total:%ld Slow:%ld Frozen:%ld", - self.operation, (long)totalFrames, (long)slowFrames, (long)frozenFrames); + if (sentryShouldAddSlowFrozenFramesData(totalFrames, slowFrames, frozenFrames)) { + [self setMeasurement:@"frames_total" value:@(totalFrames)]; + [self setMeasurement:@"frames_slow" value:@(slowFrames)]; + [self setMeasurement:@"frames_frozen" value:@(frozenFrames)]; + + SENTRY_LOG_DEBUG(@"Frames for transaction \"%@\" Total:%ld Slow:%ld " + @"Frozen:%ld", + self.operation, (long)totalFrames, (long)slowFrames, (long)frozenFrames); + } } } } diff --git a/Sources/Sentry/include/SentryDelayedFrame.h b/Sources/Sentry/include/SentryDelayedFrame.h new file mode 100644 index 00000000000..9fe97fc067f --- /dev/null +++ b/Sources/Sentry/include/SentryDelayedFrame.h @@ -0,0 +1,22 @@ +#import "SentryDefines.h" + +#if SENTRY_HAS_UIKIT + +NS_ASSUME_NONNULL_BEGIN + +@interface SentryDelayedFrame : NSObject +SENTRY_NO_INIT + +- (instancetype)initWithStartTimestamp:(uint64_t)startSystemTimestamp + expectedDuration:(CFTimeInterval)expectedDuration + actualDuration:(CFTimeInterval)actualDuration; + +@property (nonatomic, readonly) uint64_t startSystemTimestamp; +@property (nonatomic, readonly) CFTimeInterval expectedDuration; +@property (nonatomic, readonly) CFTimeInterval actualDuration; + +@end + +NS_ASSUME_NONNULL_END + +#endif // SENTRY_HAS_UIKIT diff --git a/Sources/Sentry/include/SentryDelayedFramesTracker.h b/Sources/Sentry/include/SentryDelayedFramesTracker.h new file mode 100644 index 00000000000..7606e4bce23 --- /dev/null +++ b/Sources/Sentry/include/SentryDelayedFramesTracker.h @@ -0,0 +1,65 @@ +#import "SentryDefines.h" + +#if SENTRY_HAS_UIKIT + +@class SentryDisplayLinkWrapper; +@class SentryCurrentDateProvider; + +NS_ASSUME_NONNULL_BEGIN + +@interface SentryDelayedFramesTracker : NSObject +SENTRY_NO_INIT + +/** + * Initializes a @c SentryDelayedFramesTracker. This class keeps track of information on delayed + * frames. Whenever a new delayed frame is recorded, it removes recorded delayed frames older than + * the current time minus the @c keepDelayedFramesDuration. + * + * @param keepDelayedFramesDuration The maximum duration to keep delayed frames records in memory. + * @param dateProvider The instance of a date provider. + */ +- (instancetype)initWithKeepDelayedFramesDuration:(CFTimeInterval)keepDelayedFramesDuration + dateProvider:(SentryCurrentDateProvider *)dateProvider; + +- (void)resetDelayedFramesTimeStamps; + +- (void)recordDelayedFrame:(uint64_t)startSystemTimestamp + expectedDuration:(CFTimeInterval)expectedDuration + actualDuration:(CFTimeInterval)actualDuration; + +/** + * This method returns the duration of all delayed frames between startSystemTimestamp and + * endSystemTimestamp. + * + * @discussion The frames delay for one recorded delayed frame is the intersection of the delayed + * part with the queried time interval of startSystemTimestamp and endSystemTimestamp. For example, + * the expected frame duration is 16.67 ms, and the frame took 20 ms to render. The frame delay is + * 20 ms - 16.67 ms = 3.33 ms. Parts of the delay may occur before the queried time interval. For + * example, of the 3.33 ms of a recorded frames delay only 2 ms intersect with the queried time + * interval. In that case, the frames delay is only 2 ms. This method also considers when there is + * no recorded frame information for the queried time interval, but there should be, meaning it + * includes ongoing, not yet recorded frames as frames delay. + * + * + * @param startSystemTimestamp The start system time stamp for the time interval to query frames + * delay. + * @param endSystemTimestamp The end system time stamp for the time interval to query frames delay. + * @param isRunning Wether the frames tracker is running or not. + * @param thisFrameTimestamp The timestamp of the current frame. + * @param previousFrameTimestamp The timestamp of the previous frame. + * @param slowFrameThreshold The threshold for a slow frame. For 60 fps this is roughly 16.67 ms. + * + * @return the frames delay duration or -1 if it can't calculate the frames delay. + */ +- (CFTimeInterval)getFramesDelay:(uint64_t)startSystemTimestamp + endSystemTimestamp:(uint64_t)endSystemTimestamp + isRunning:(BOOL)isRunning + thisFrameTimestamp:(CFTimeInterval)thisFrameTimestamp + previousFrameTimestamp:(CFTimeInterval)previousFrameTimestamp + slowFrameThreshold:(CFTimeInterval)slowFrameThreshold; + +@end + +NS_ASSUME_NONNULL_END + +#endif // SENTRY_HAS_UIKIT diff --git a/Sources/Sentry/include/SentryFramesTracker.h b/Sources/Sentry/include/SentryFramesTracker.h index 22e5c86e3b5..1e13b2ae63f 100644 --- a/Sources/Sentry/include/SentryFramesTracker.h +++ b/Sources/Sentry/include/SentryFramesTracker.h @@ -5,6 +5,7 @@ # import "SentryProfilingConditionals.h" @class SentryOptions, SentryDisplayLinkWrapper, SentryScreenFrames; +@class SentryCurrentDateProvider; NS_ASSUME_NONNULL_BEGIN @@ -21,7 +22,9 @@ NS_ASSUME_NONNULL_BEGIN */ @interface SentryFramesTracker : NSObject -- (instancetype)initWithDisplayLinkWrapper:(SentryDisplayLinkWrapper *)displayLinkWrapper; +- (instancetype)initWithDisplayLinkWrapper:(SentryDisplayLinkWrapper *)displayLinkWrapper + dateProvider:(SentryCurrentDateProvider *)dateProvider + keepDelayedFramesDuration:(CFTimeInterval)keepDelayedFramesDuration; @property (nonatomic, assign, readonly) SentryScreenFrames *currentFrames; @property (nonatomic, assign, readonly) BOOL isRunning; @@ -34,6 +37,13 @@ NS_ASSUME_NONNULL_BEGIN - (void)start; - (void)stop; +/* + * Returns the frames delay for the passed time period. If the method can't calculate the frames + * delay, it returns -1. + */ +- (CFTimeInterval)getFramesDelay:(uint64_t)startSystemTimestamp + endSystemTimestamp:(uint64_t)endSystemTimestamp; + - (void)addListener:(id)listener; - (void)removeListener:(id)listener; diff --git a/Sources/Sentry/include/SentryTracer.h b/Sources/Sentry/include/SentryTracer.h index 8dcc38bd4ee..4eb4aeb82bb 100644 --- a/Sources/Sentry/include/SentryTracer.h +++ b/Sources/Sentry/include/SentryTracer.h @@ -11,6 +11,8 @@ NS_ASSUME_NONNULL_BEGIN static NSTimeInterval const SentryTracerDefaultTimeout = 3.0; +static const NSTimeInterval SENTRY_AUTO_TRANSACTION_MAX_DURATION = 500.0; + @protocol SentryTracerDelegate /** diff --git a/Tests/SentryProfilerTests/SentryProfilerSwiftTests.swift b/Tests/SentryProfilerTests/SentryProfilerSwiftTests.swift index a11007012ee..8aa8b5e7d3c 100644 --- a/Tests/SentryProfilerTests/SentryProfilerSwiftTests.swift +++ b/Tests/SentryProfilerTests/SentryProfilerSwiftTests.swift @@ -36,7 +36,7 @@ class SentryProfilerSwiftTests: XCTestCase { #if !os(macOS) lazy var displayLinkWrapper = TestDisplayLinkWrapper(dateProvider: currentDateProvider) - lazy var framesTracker = SentryFramesTracker(displayLinkWrapper: displayLinkWrapper) + lazy var framesTracker = SentryFramesTracker(displayLinkWrapper: displayLinkWrapper, dateProvider: currentDateProvider, keepDelayedFramesDuration: 0) #endif init() { diff --git a/Tests/SentryTests/Integrations/Performance/FramesTracking/SentryFramesTrackerTests.swift b/Tests/SentryTests/Integrations/Performance/FramesTracking/SentryFramesTrackerTests.swift index 6e8d6824fb6..042a33e2ed0 100644 --- a/Tests/SentryTests/Integrations/Performance/FramesTracking/SentryFramesTrackerTests.swift +++ b/Tests/SentryTests/Integrations/Performance/FramesTracking/SentryFramesTrackerTests.swift @@ -9,15 +9,21 @@ class SentryFramesTrackerTests: XCTestCase { var displayLinkWrapper: TestDisplayLinkWrapper var queue: DispatchQueue + var dateProvider = TestCurrentDateProvider() + let keepDelayedFramesDuration = 10.0 lazy var hub = TestHub(client: nil, andScope: nil) lazy var tracer = SentryTracer(transactionContext: TransactionContext(name: "test transaction", operation: "test operation"), hub: hub) + + let slowestSlowFrameDelay: Double init() { - displayLinkWrapper = TestDisplayLinkWrapper() + displayLinkWrapper = TestDisplayLinkWrapper(dateProvider: dateProvider) queue = DispatchQueue(label: "SentryFramesTrackerTests", qos: .background, attributes: [.concurrent]) + + slowestSlowFrameDelay = (displayLinkWrapper.slowestSlowFrameDuration - slowFrameThreshold(displayLinkWrapper.currentFrameRate.rawValue)) } - lazy var sut: SentryFramesTracker = SentryFramesTracker(displayLinkWrapper: displayLinkWrapper) + lazy var sut: SentryFramesTracker = SentryFramesTracker(displayLinkWrapper: displayLinkWrapper, dateProvider: dateProvider, keepDelayedFramesDuration: keepDelayedFramesDuration) } private var fixture: Fixture! @@ -76,12 +82,13 @@ class SentryFramesTrackerTests: XCTestCase { func testSlowFrame() throws { let sut = fixture.sut sut.start() - - fixture.displayLinkWrapper.call() - _ = fixture.displayLinkWrapper.fastestSlowFrame() - fixture.displayLinkWrapper.normalFrame() - _ = fixture.displayLinkWrapper.slowestSlowFrame() - + + let displayLink = fixture.displayLinkWrapper + displayLink.call() + _ = displayLink.fastestSlowFrame() + displayLink.normalFrame() + _ = displayLink.slowestSlowFrame() + try assert(slow: 2, frozen: 0, total: 3) } @@ -149,6 +156,342 @@ class SentryFramesTrackerTests: XCTestCase { try assert(slow: 0, frozen: 0) } + + /** + * The following test validates one slow and one frozen frame in the time interval. The slow frame starts at + * the beginning of the time interval and the frozen frame stops at the end of the time interval. + * + * [nf][- sf - ][nf][ ---- ff ---- ] | nf = normal frame, sf = slow frame, ff = frozen frame + * [--------- time interval -------] + */ + func testFrameDelay_SlowAndFrozenFrameWithinTimeInterval() { + let sut = fixture.sut + sut.start() + + let startSystemTime = fixture.dateProvider.systemTime() + + let displayLink = fixture.displayLinkWrapper + displayLink.call() + displayLink.normalFrame() + _ = displayLink.fastestSlowFrame() + displayLink.normalFrame() + _ = displayLink.slowestSlowFrame() + + let endSystemTime = fixture.dateProvider.systemTime() + + let expectedDelay = displayLink.timeEpsilon + displayLink.slowestSlowFrameDuration - slowFrameThreshold(displayLink.currentFrameRate.rawValue) + + let actualFrameDelay = sut.getFramesDelay(startSystemTime, endSystemTimestamp: endSystemTime) + expect(actualFrameDelay).to(beCloseTo(expectedDelay, within: 0.0001)) + } + + /** + * When there is no frame information around yet, because the frame about to be drawn is still delayed, + * the delay should be returned as such. + * + * [nf][ ------- ?? ------ ] | nf = normal frame, ?? = No frame information + * [---- time interval ----] + */ + func testFrameDelay_NoFrameRenderedButShouldHave_DelayReturned() { + let sut = fixture.sut + sut.start() + + let startSystemTime = fixture.dateProvider.systemTime() + + let displayLink = fixture.displayLinkWrapper + displayLink.call() + displayLink.normalFrame() + + let delayWithoutFrameRecord = 1.0 + fixture.dateProvider.advance(by: delayWithoutFrameRecord) + let endSystemTime = fixture.dateProvider.systemTime() + + let expectedDelay = delayWithoutFrameRecord - slowFrameThreshold(displayLink.currentFrameRate.rawValue) + + let actualFrameDelay = sut.getFramesDelay(startSystemTime, endSystemTimestamp: endSystemTime) + expect(actualFrameDelay).to(beCloseTo(expectedDelay, within: 0.0001)) + } + + /** + * The following test validates one delayed frame starting before time interval and ending with the time interval. + * + * [---- delayed frame ---- ] + * [- time interval -- ] + */ + func testDelayedFrameStartsBeforeTimeInterval() { + let timeIntervalAfterFrameStart = 0.5 + + // The slow frame threshold is not included because the delayed frame started before the startDate and the rendering on time happened before the startDate. + let expectedDelay = fixture.displayLinkWrapper.slowestSlowFrameDuration - timeIntervalAfterFrameStart + + testFrameDelay(timeIntervalAfterFrameStart: timeIntervalAfterFrameStart, expectedDelay: expectedDelay) + } + + /** + * The following test validates one delayed frame starting shortly before time interval and ending with the time interval. + * Parts of the expected frame duration overlap with the beginning of the time interval, and are therefore not added to + * the frame delay. + * + * [| e | delayed frame ---- ] e = the expected frame duration + * [---- time interval ---- ] + */ + func testDelayedFrameStartsShortlyBeforeTimeInterval_OnlyDelayedPartAdded() { + let timeIntervalAfterFrameStart = 0.0001 + + // The timeIntervalAfterFrameStart is not subtracted from the delay, because that's when the frame was expected to be rendered on time. + let expectedDelay = fixture.displayLinkWrapper.slowestSlowFrameDuration - slowFrameThreshold(fixture.displayLinkWrapper.currentFrameRate.rawValue) + + testFrameDelay(timeIntervalAfterFrameStart: timeIntervalAfterFrameStart, expectedDelay: expectedDelay) + } + + /** + * The following test validates one delayed frame starting shortly before time interval and ending after the time interval. + * Parts of the expected frame duration overlap with the beginning of the time interval, and are therefore not added to + * the frame delay. + * + * [| e | delayed frame ------ ] e = the expected frame duration + * [---- time interval ---- ] + */ + func testDelayedFrameStartsAndEndsBeforeTimeInterval_OnlyDelayedPartAdded() { + let displayLink = fixture.displayLinkWrapper + + let timeIntervalAfterFrameStart = 0.1 + let timeIntervalBeforeFrameEnd = 0.01 + + // The slow frame threshold is not included because the startDate is after the frame rendered on time. + let expectedDelay = displayLink.slowestSlowFrameDuration - timeIntervalAfterFrameStart - timeIntervalBeforeFrameEnd + + testFrameDelay(timeIntervalAfterFrameStart: timeIntervalAfterFrameStart, timeIntervalBeforeFrameEnd: timeIntervalBeforeFrameEnd, expectedDelay: expectedDelay) + } + + func testDelayedFrames_NoRecordedFrames_MinusOne() { + fixture.dateProvider.advance(by: 2.0) + + let sut = fixture.sut + sut.start() + + let startSystemTime = fixture.dateProvider.systemTime() + + fixture.dateProvider.advance(by: 0.001) + + let endSystemTime = fixture.dateProvider.systemTime() + + let actualFrameDelay = sut.getFramesDelay(startSystemTime, endSystemTimestamp: endSystemTime) + expect(actualFrameDelay) == -1 + } + + func testDelayedFrames_NoRecordedDelayedFrames_ReturnsZero() { + fixture.dateProvider.advance(by: 2.0) + + let sut = fixture.sut + sut.start() + + let displayLink = fixture.displayLinkWrapper + displayLink.call() + + let startSystemTime = fixture.dateProvider.systemTime() + + fixture.dateProvider.advance(by: 0.001) + + let endSystemTime = fixture.dateProvider.systemTime() + + let actualFrameDelay = sut.getFramesDelay(startSystemTime, endSystemTimestamp: endSystemTime) + expect(actualFrameDelay).to(beCloseTo(0.0, within: 0.0001)) + } + + func testDelayedFrames_NoRecordedDelayedFrames_ButFrameIsDelayed_ReturnsDelay() { + fixture.dateProvider.advance(by: 2.0) + + let sut = fixture.sut + sut.start() + + let displayLink = fixture.displayLinkWrapper + displayLink.call() + + let startSystemTime = fixture.dateProvider.systemTime() + + let delay = 0.5 + fixture.dateProvider.advance(by: delay) + + let endSystemTime = fixture.dateProvider.systemTime() + + let expectedDelay = delay - slowFrameThreshold(fixture.displayLinkWrapper.currentFrameRate.rawValue) + + let actualFrameDelay = sut.getFramesDelay(startSystemTime, endSystemTimestamp: endSystemTime) + expect(actualFrameDelay).to(beCloseTo(expectedDelay, within: 0.0001)) + } + + private func testFrameDelay(timeIntervalAfterFrameStart: TimeInterval = 0.0, timeIntervalBeforeFrameEnd: TimeInterval = 0.0, expectedDelay: TimeInterval) { + let sut = fixture.sut + sut.start() + + let slowFrameStartSystemTime = fixture.dateProvider.systemTime() + + let displayLink = fixture.displayLinkWrapper + displayLink.call() + _ = displayLink.slowestSlowFrame() + + let endSystemTime = fixture.dateProvider.systemTime() - timeIntervalToNanoseconds(timeIntervalBeforeFrameEnd) + + let startSystemTime = slowFrameStartSystemTime + timeIntervalToNanoseconds(timeIntervalAfterFrameStart) + + let actualFrameDelay = sut.getFramesDelay(startSystemTime, endSystemTimestamp: endSystemTime) + expect(actualFrameDelay).to(beCloseTo(expectedDelay, within: 0.0001)) + } + + /** + * The following test validates two delayed frames. The delay of the first one is fully added to the frame delay. + * No delay of the second frame is added because only the expected frame duration overlaps with the time interval. + * + * [| e | delayed frame ] [| e | delayed frame - ] e = the expected frame duration + * [------ time interval ----- ] + */ + func testOneDelayedFrameStartsShortlyEndsBeforeTimeInterval() { + let sut = fixture.sut + sut.start() + + let startSystemTime = fixture.dateProvider.systemTime() + + let displayLink = fixture.displayLinkWrapper + displayLink.call() + _ = displayLink.slowestSlowFrame() + displayLink.normalFrame() + _ = displayLink.fastestSlowFrame() + + let timeIntervalBeforeFrameEnd = slowFrameThreshold(displayLink.currentFrameRate.rawValue) - 0.005 + let endSystemTime = fixture.dateProvider.systemTime() - timeIntervalToNanoseconds(timeIntervalBeforeFrameEnd) + + let expectedDelay = displayLink.slowestSlowFrameDuration - slowFrameThreshold(displayLink.currentFrameRate.rawValue) + + let actualFrameDelay = sut.getFramesDelay(startSystemTime, endSystemTimestamp: endSystemTime) + expect(actualFrameDelay).to(beCloseTo(expectedDelay, within: 0.0001)) + } + + func testFrameDelay_WithStartBeforeEnd_ReturnsMinusOne() { + let sut = fixture.sut + sut.start() + + let displayLink = fixture.displayLinkWrapper + displayLink.call() + _ = displayLink.slowestSlowFrame() + + let actualFrameDelay = sut.getFramesDelay(1, endSystemTimestamp: 0) + expect(actualFrameDelay) == -1.0 + } + + func testFrameDelay_LongestTimeStamp_ReturnsMinusOne() { + let sut = fixture.sut + sut.start() + + let displayLink = fixture.displayLinkWrapper + displayLink.call() + _ = displayLink.slowestSlowFrame() + + let actualFrameDelay = sut.getFramesDelay(0, endSystemTimestamp: UInt64.max) + expect(actualFrameDelay) == -1.0 + } + + func testFrameDelay_KeepAddingSlowFrames_OnlyTheMaxDurationFramesReturned() { + let sut = fixture.sut + sut.start() + + let (startSystemTime, _, expectedDelay) = givenMoreDelayedFramesThanTransactionMaxDuration(sut) + + let endSystemTime = fixture.dateProvider.systemTime() + + let actualFrameDelay = sut.getFramesDelay(startSystemTime, endSystemTimestamp: endSystemTime) + expect(actualFrameDelay).to(beCloseTo(expectedDelay, within: 0.0001)) + } + + func testFrameDelay_MoreThanMaxDuration_FrameInformationMissing_DelayReturned() { + let sut = fixture.sut + let displayLink = fixture.displayLinkWrapper + sut.start() + + let (startSystemTime, _, slowFramesDelay) = givenMoreDelayedFramesThanTransactionMaxDuration(sut) + + let delayWithoutFrameRecord = 2.0 + fixture.dateProvider.advance(by: delayWithoutFrameRecord) + let endSystemTime = fixture.dateProvider.systemTime() + + let delayNotRecorded = delayWithoutFrameRecord - slowFrameThreshold(displayLink.currentFrameRate.rawValue) + let expectedDelay = slowFramesDelay + delayNotRecorded + + let actualFrameDelay = sut.getFramesDelay(startSystemTime, endSystemTimestamp: endSystemTime) + expect(actualFrameDelay).to(beCloseTo(expectedDelay, within: 0.0001)) + } + + func testFrameDelay_MoreThanMaxDuration_StartTimeTooEarly_ReturnsMinusOne() { + let sut = fixture.sut + sut.start() + + let (startSystemTime, _, _) = givenMoreDelayedFramesThanTransactionMaxDuration(sut) + + let endSystemTime = fixture.dateProvider.systemTime() + + let actualFrameDelay = sut.getFramesDelay(startSystemTime - 1, endSystemTimestamp: endSystemTime) + expect(actualFrameDelay).to(beCloseTo(-1, within: 0.0001), description: "startSystemTimeStamp starts one nanosecond before the oldest slow frame. Therefore the frame delay can't be calculated and should me 0.") + } + + func testFrameDelay_FramesTrackerNotRunning_ReturnsMinusOne() { + let sut = fixture.sut + sut.start() + + let startSystemTime = fixture.dateProvider.systemTime() + + let displayLink = fixture.displayLinkWrapper + displayLink.call() + _ = displayLink.slowestSlowFrame() + + let endSystemTime = fixture.dateProvider.systemTime() + + sut.stop() + + let actualFrameDelay = sut.getFramesDelay(startSystemTime, endSystemTimestamp: endSystemTime) + expect(actualFrameDelay) == -1.0 + } + + func testFrameDelay_RestartTracker_ReturnsMinusOne() { + let sut = fixture.sut + sut.start() + + let (startSystemTime, _, _) = givenMoreDelayedFramesThanTransactionMaxDuration(sut) + + sut.stop() + sut.start() + + let endSystemTime = fixture.dateProvider.systemTime() + + let actualFrameDelay = sut.getFramesDelay(startSystemTime, endSystemTimestamp: endSystemTime) + expect(actualFrameDelay) == -1.0 + } + + func testFrameDelay_GetInfoFromBackgroundThreadWhileAdding() { + let sut = fixture.sut + sut.start() + + let (startSystemTime, _, _) = givenMoreDelayedFramesThanTransactionMaxDuration(sut) + let endSystemTime = fixture.dateProvider.systemTime() + + let loopSize = 1_000 + let expectation = expectation(description: "Get Frames Delays") + expectation.expectedFulfillmentCount = loopSize + + for _ in 0..= -1 + + expectation.fulfill() + } + } + + _ = givenMoreDelayedFramesThanTransactionMaxDuration(sut) + + wait(for: [expectation], timeout: 3.0) + } func testAddListener() { let sut = fixture.sut @@ -193,14 +536,36 @@ class SentryFramesTrackerTests: XCTestCase { } func testDealloc_CallsStop() { - func sutIsDeallocatedAfterCallingMe() { - _ = SentryFramesTracker(displayLinkWrapper: fixture.displayLinkWrapper) + _ = SentryFramesTracker(displayLinkWrapper: fixture.displayLinkWrapper, dateProvider: fixture.dateProvider, keepDelayedFramesDuration: 0) } sutIsDeallocatedAfterCallingMe() XCTAssertEqual(1, fixture.displayLinkWrapper.invalidateInvocations.count) } + + private func givenMoreDelayedFramesThanTransactionMaxDuration(_ framesTracker: SentryFramesTracker) -> (UInt64, UInt, Double) { + let displayLink = fixture.displayLinkWrapper + displayLink.call() + + let slowFramesCountBeforeAddingFrames = framesTracker.currentFrames.slow + + // We have to add the delay of the slowest frame because we remove frames + // based on the endTimeStamp not the start time stamp. + let keepAddingFramesSystemTime = fixture.dateProvider.systemTime() + timeIntervalToNanoseconds(fixture.keepDelayedFramesDuration + fixture.slowestSlowFrameDelay) + + while fixture.dateProvider.systemTime() < keepAddingFramesSystemTime { + _ = displayLink.slowestSlowFrame() + } + + // We have to remove 1 slow frame cause one will be older than transactionMaxDurationNS + let slowFramesCount = framesTracker.currentFrames.slow - slowFramesCountBeforeAddingFrames - 1 + + let slowFramesDelay = fixture.slowestSlowFrameDelay * Double(slowFramesCount) + + // Where the second frame starts + return (timeIntervalToNanoseconds(displayLink.slowestSlowFrameDuration), slowFramesCount, slowFramesDelay) + } } private class FrameTrackerListener: NSObject, SentryFramesTrackerListener { diff --git a/Tests/SentryTests/Integrations/Performance/UIViewController/SentryTimeToDisplayTrackerTest.swift b/Tests/SentryTests/Integrations/Performance/UIViewController/SentryTimeToDisplayTrackerTest.swift index 15523f0493d..f0bb2434c3f 100644 --- a/Tests/SentryTests/Integrations/Performance/UIViewController/SentryTimeToDisplayTrackerTest.swift +++ b/Tests/SentryTests/Integrations/Performance/UIViewController/SentryTimeToDisplayTrackerTest.swift @@ -15,7 +15,7 @@ class SentryTimeToDisplayTrackerTest: XCTestCase { var framesTracker: SentryFramesTracker init() { - framesTracker = SentryFramesTracker(displayLinkWrapper: displayLinkWrapper) + framesTracker = SentryFramesTracker(displayLinkWrapper: displayLinkWrapper, dateProvider: dateProvider, keepDelayedFramesDuration: 0) SentryDependencyContainer.sharedInstance().framesTracker = framesTracker framesTracker.start() } diff --git a/Tests/SentryTests/Transaction/SentrySpanTests.swift b/Tests/SentryTests/Transaction/SentrySpanTests.swift index 23a49998353..b6e71b1d328 100644 --- a/Tests/SentryTests/Transaction/SentrySpanTests.swift +++ b/Tests/SentryTests/Transaction/SentrySpanTests.swift @@ -555,7 +555,7 @@ class SentrySpanTests: XCTestCase { private func givenFramesTracker() -> (TestDisplayLinkWrapper, SentryFramesTracker) { let displayLinkWrapper = TestDisplayLinkWrapper() - let framesTracker = SentryFramesTracker(displayLinkWrapper: displayLinkWrapper) + let framesTracker = SentryFramesTracker(displayLinkWrapper: displayLinkWrapper, dateProvider: TestCurrentDateProvider(), keepDelayedFramesDuration: 0) framesTracker.start() displayLinkWrapper.call() diff --git a/Tests/SentryTests/Transaction/SentryTracerTests.swift b/Tests/SentryTests/Transaction/SentryTracerTests.swift index 93efca9723f..122d04d3bf4 100644 --- a/Tests/SentryTests/Transaction/SentryTracerTests.swift +++ b/Tests/SentryTests/Transaction/SentryTracerTests.swift @@ -1,3 +1,4 @@ +import Nimble import SentryTestUtils import XCTest @@ -62,7 +63,7 @@ class SentryTracerTests: XCTestCase { hub = TestHub(client: client, andScope: scope) #if os(iOS) || os(tvOS) || targetEnvironment(macCatalyst) - displayLinkWrapper = TestDisplayLinkWrapper() + displayLinkWrapper = TestDisplayLinkWrapper(dateProvider: currentDateProvider) SentryDependencyContainer.sharedInstance().framesTracker.setDisplayLinkWrapper(displayLinkWrapper) SentryDependencyContainer.sharedInstance().framesTracker.start() @@ -1059,37 +1060,70 @@ class SentryTracerTests: XCTestCase { #if os(iOS) || os(tvOS) || targetEnvironment(macCatalyst) - func testChangeStartTimeStamp_RemovesFramesMeasurement() throws { + func testChangeStartTimeStamp_OnlyFramesDelayAdded() throws { let sut = fixture.getSut() - fixture.displayLinkWrapper.renderFrames(1, 1, 1) + fixture.displayLinkWrapper.renderFrames(0, 0, 100) sut.updateStartTime(try XCTUnwrap(sut.startTimestamp).addingTimeInterval(-1)) sut.finish() - assertNoMeasurementsAdded() + expect(self.fixture.hub.capturedEventsWithScopes.count) == 1 + let serializedTransaction = fixture.hub.capturedEventsWithScopes.first!.event.serialize() + + let extra = serializedTransaction["extra"] as? [String: Any] + + let framesDelay = extra?["frames.delay"] as? NSNumber + expect(framesDelay).to(beCloseTo(0.0, within: 0.0001)) } func testAddFramesMeasurement() { let sut = fixture.getSut() - let slowFrames = 4 + let displayLink = fixture.displayLinkWrapper + + let slowFrames = 1 let frozenFrames = 1 let normalFrames = 100 let totalFrames = slowFrames + frozenFrames + normalFrames - fixture.displayLinkWrapper.renderFrames(slowFrames, frozenFrames, normalFrames) + _ = displayLink.slowestSlowFrame() + _ = displayLink.fastestFrozenFrame() + displayLink.renderFrames(0, 0, normalFrames) sut.finish() - XCTAssertEqual(1, fixture.hub.capturedEventsWithScopes.count) + expect(self.fixture.hub.capturedEventsWithScopes.count) == 1 let serializedTransaction = fixture.hub.capturedEventsWithScopes.first!.event.serialize() - let measurements = serializedTransaction["measurements"] as? [String: [String: Int]] + let measurements = serializedTransaction["measurements"] as? [String: [String: Any]] + + expect(measurements?["frames_total"] as? [String: Int]) == ["value": totalFrames] + expect(measurements?["frames_slow"] as? [String: Int]) == ["value": slowFrames] + expect(measurements?["frames_frozen"] as? [String: Int]) == ["value": frozenFrames] + + let extra = serializedTransaction["extra"] as? [String: Any] + let framesDelay = extra?["frames.delay"] as? NSNumber + + let expectedFrameDuration = slowFrameThreshold(displayLink.currentFrameRate.rawValue) + let expectedDelay = displayLink.slowestSlowFrameDuration + displayLink.fastestFrozenFrameDuration - expectedFrameDuration * 2 as NSNumber - XCTAssertEqual([ - "frames_total": ["value": totalFrames], - "frames_slow": ["value": slowFrames], - "frames_frozen": ["value": frozenFrames] - ], measurements) - XCTAssertNil(SentrySDK.getAppStartMeasurement()) + expect(framesDelay).to(beCloseTo(expectedDelay, within: 0.0001)) + expect(SentrySDK.getAppStartMeasurement()) == nil + } + + func testFramesDelay_WhenBeingZero() { + let sut = fixture.getSut() + + let displayLink = fixture.displayLinkWrapper + let normalFrames = 100 + displayLink.renderFrames(0, 0, normalFrames) + + sut.finish() + + expect(self.fixture.hub.capturedEventsWithScopes.count) == 1 + + let serializedTransaction = fixture.hub.capturedEventsWithScopes.first!.event.serialize() + let extra = serializedTransaction["extra"] as? [String: Any] + let framesDelay = extra?["frames.delay"] as? NSNumber + expect(framesDelay).to(beCloseTo(0.0, within: 0.0001)) } func testNegativeFramesAmount_NoMeasurementAdded() { From e02158b007e2c4bca924ca25c5b75d8860a22c43 Mon Sep 17 00:00:00 2001 From: Andrew McKnight Date: Fri, 15 Dec 2023 00:59:34 -0800 Subject: [PATCH 13/31] ref: move fcd to where its actually used (#3499) --- Sources/Sentry/Public/SentryScope.h | 2 +- Sources/Sentry/include/SentryScope+Private.h | 1 + 2 files changed, 2 insertions(+), 1 deletion(-) diff --git a/Sources/Sentry/Public/SentryScope.h b/Sources/Sentry/Public/SentryScope.h index 85df60ff1f1..a9feae6f8ad 100644 --- a/Sources/Sentry/Public/SentryScope.h +++ b/Sources/Sentry/Public/SentryScope.h @@ -2,7 +2,7 @@ #import "SentrySerializable.h" #import "SentrySpanProtocol.h" -@class SentryUser, SentrySession, SentryOptions, SentryBreadcrumb, SentryAttachment; +@class SentryUser, SentryOptions, SentryBreadcrumb, SentryAttachment; NS_ASSUME_NONNULL_BEGIN diff --git a/Sources/Sentry/include/SentryScope+Private.h b/Sources/Sentry/include/SentryScope+Private.h index de662b856f2..ac581eb63a3 100644 --- a/Sources/Sentry/include/SentryScope+Private.h +++ b/Sources/Sentry/include/SentryScope+Private.h @@ -5,6 +5,7 @@ @class SentryAttachment; @class SentryPropagationContext; +@class SentrySession; NS_ASSUME_NONNULL_BEGIN From aea59877317b2d37269e169717c17311683d98d7 Mon Sep 17 00:00:00 2001 From: Philipp Hofmann Date: Fri, 15 Dec 2023 14:28:23 +0100 Subject: [PATCH 14/31] fix: Marking manual sessions as crashed (#3501) Fix marking manual sessions as crashed when capturing crash events. Fixes GH-3498 --- CHANGELOG.md | 6 ++++- Sources/Sentry/SentryHub.m | 31 ++++++++++------------ Tests/SentryTests/SentryHubTests.swift | 36 +++++++++++++++++--------- 3 files changed, 43 insertions(+), 30 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 72cb1233a1b..4a1aacc4b66 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -2,11 +2,15 @@ ## Unreleased -## Features +### Features - Add frames delay to transactions (#3487) - Add slow and frozen frames to spans (#3450, #3478) +### Fixes + +- **Fix marking manual sessions as crashed (#3501)**: When turning off autoSessionTracking and manually starting and ending sessions, the SDK didn't mark sessions as crashed when sending a crash event to Sentry. This is fixed now. + ## 8.17.1 ### Fixes diff --git a/Sources/Sentry/SentryHub.m b/Sources/Sentry/SentryHub.m index 2571a59c64b..7172a17a6c9 100644 --- a/Sources/Sentry/SentryHub.m +++ b/Sources/Sentry/SentryHub.m @@ -238,10 +238,10 @@ - (void)captureCrashEvent:(SentryEvent *)event } /** - * If autoSessionTracking is enabled we want to send the crash and the event together to get proper - * numbers for release health statistics. If there are multiple crash events to be sent on the start - * of the SDK there is currently no way to know which one belongs to the crashed session so we just - * send the session with the first crashed event we receive. + * We must send the crash and the event together to get proper numbers for release health + * statistics. If multiple crash events are to be dispatched at the start of the SDK, there is + * currently no way to know which one belongs to the crashed session, so we send the session with + * the first crash event we receive. */ - (void)captureCrashEvent:(SentryEvent *)event withScope:(SentryScope *)scope { @@ -252,21 +252,18 @@ - (void)captureCrashEvent:(SentryEvent *)event withScope:(SentryScope *)scope return; } - // Check this condition first to avoid unnecessary I/O - if (client.options.enableAutoSessionTracking) { - SentryFileManager *fileManager = [client fileManager]; - SentrySession *crashedSession = [fileManager readCrashedSession]; + SentryFileManager *fileManager = [client fileManager]; + SentrySession *crashedSession = [fileManager readCrashedSession]; - // It can be that there is no session yet, because autoSessionTracking was just enabled and - // there is a previous crash on disk. In this case we just send the crash event. - if (crashedSession != nil) { - [client captureCrashEvent:event withSession:crashedSession withScope:scope]; - [fileManager deleteCrashedSession]; - return; - } + // It can occur that there is no session yet because autoSessionTracking was just enabled or + // users didn't start a manual session yet, and there is a previous crash on disk. In this case, + // we just send the crash event. + if (crashedSession != nil) { + [client captureCrashEvent:event withSession:crashedSession withScope:scope]; + [fileManager deleteCrashedSession]; + } else { + [client captureCrashEvent:event withScope:scope]; } - - [client captureCrashEvent:event withScope:scope]; } - (SentryId *)captureTransaction:(SentryTransaction *)transaction withScope:(SentryScope *)scope diff --git a/Tests/SentryTests/SentryHubTests.swift b/Tests/SentryTests/SentryHubTests.swift index 159970f8a92..f5bfcf2821e 100644 --- a/Tests/SentryTests/SentryHubTests.swift +++ b/Tests/SentryTests/SentryHubTests.swift @@ -1,3 +1,4 @@ +import Nimble import Sentry import SentryTestUtils import XCTest @@ -606,9 +607,28 @@ class SentryHubTests: XCTestCase { assertNoCrashedSessionSent() + let environment = "test" + sut.configureScope { $0.setEnvironment(environment) } sut.captureCrash(fixture.event) + assertEventSentWithSession(scopeEnvironment: environment) - assertEventSentWithSession() + // Make sure further crash events are sent + sut.captureCrash(fixture.event) + assertCrashEventSent() + } + + func testCaptureCrashEvent_ManualSessionTracking_CrashedSessionExists() { + givenAutoSessionTrackingDisabled() + + givenCrashedSession() + + assertNoCrashedSessionSent() + + let environment = "test" + sut.configureScope { $0.setEnvironment(environment) } + sut.captureCrash(fixture.event) + + assertEventSentWithSession(scopeEnvironment: environment) // Make sure further crash events are sent sut.captureCrash(fixture.event) @@ -640,15 +660,6 @@ class SentryHubTests: XCTestCase { assertCrashEventSent() } - func testCaptureCrashEvent_SessionExistsButAutoSessionTrackingDisabled() { - givenAutoSessionTrackingDisabled() - givenCrashedSession() - - sut.captureCrash(fixture.event) - - assertCrashEventSent() - } - func testCaptureCrashEvent_ClientIsNil() { sut = fixture.getSut() sut.bindClient(nil) @@ -989,7 +1000,7 @@ class SentryHubTests: XCTestCase { XCTAssertTrue(arguments.first?.event.isCrashEvent ?? false) } - private func assertEventSentWithSession() { + private func assertEventSentWithSession(scopeEnvironment: String) { let arguments = fixture.client.captureCrashEventWithSessionInvocations XCTAssertEqual(1, arguments.count) @@ -1001,7 +1012,8 @@ class SentryHubTests: XCTestCase { XCTAssertEqual(SentrySessionStatus.crashed, session?.status) XCTAssertEqual(fixture.options.environment, session?.environment) - XCTAssertEqual(fixture.scope, argument?.scope) + let event = argument?.scope.applyTo(event: fixture.event, maxBreadcrumbs: 10) + expect(event?.environment) == scopeEnvironment } private func assertSessionWithIncrementedErrorCountedAdded() { From f0ce81c3105c33add6dada975cec8a32e604b9e5 Mon Sep 17 00:00:00 2001 From: Philipp Hofmann Date: Mon, 18 Dec 2023 12:59:46 +0100 Subject: [PATCH 15/31] feat: Add frames delay to span data (#3496) Also, fix a couple of edge cases when calculating the frames delay when An ongoing delayed frame has not yet been recorded. --- CHANGELOG.md | 2 +- Sources/Sentry/SentryDelayedFramesTracker.m | 62 +++++++++++-------- Sources/Sentry/SentryFramesTracker.m | 3 +- Sources/Sentry/SentrySpan.m | 10 +++ .../include/SentryDelayedFramesTracker.h | 6 +- .../SentryFramesTrackerTests.swift | 27 +++++++- .../Transaction/SentrySpanTests.swift | 52 ++++++---------- 7 files changed, 96 insertions(+), 66 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 7d813359883..864902a14bf 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -4,7 +4,7 @@ ### Features -- Add frames delay to transactions (#3487) +- Add frames delay to transactions and spans (#3487, #3496) - Add slow and frozen frames to spans (#3450, #3478) ## 8.17.2 diff --git a/Sources/Sentry/SentryDelayedFramesTracker.m b/Sources/Sentry/SentryDelayedFramesTracker.m index 0ef44cb59e8..d1b6cda83b3 100644 --- a/Sources/Sentry/SentryDelayedFramesTracker.m +++ b/Sources/Sentry/SentryDelayedFramesTracker.m @@ -92,8 +92,7 @@ - (void)removeOldDelayedFrames - (CFTimeInterval)getFramesDelay:(uint64_t)startSystemTimestamp endSystemTimestamp:(uint64_t)endSystemTimestamp isRunning:(BOOL)isRunning - thisFrameTimestamp:(CFTimeInterval)thisFrameTimestamp - previousFrameTimestamp:(CFTimeInterval)previousFrameTimestamp + previousFrameSystemTimestamp:(uint64_t)previousFrameSystemTimestamp slowFrameThreshold:(CFTimeInterval)slowFrameThreshold { CFTimeInterval cantCalculateFrameDelayReturnValue = -1.0; @@ -115,12 +114,12 @@ - (CFTimeInterval)getFramesDelay:(uint64_t)startSystemTimestamp return cantCalculateFrameDelayReturnValue; } - if (previousFrameTimestamp < 0) { + if (previousFrameSystemTimestamp == 0) { SENTRY_LOG_DEBUG(@"Not calculating frames delay because no frames yet recorded."); return cantCalculateFrameDelayReturnValue; } - NSArray *frames; + NSMutableArray *frames; @synchronized(self.delayedFrames) { uint64_t oldestDelayedFrameStartTimestamp = UINT64_MAX; SentryDelayedFrame *oldestDelayedFrame = self.delayedFrames.firstObject; @@ -135,17 +134,17 @@ - (CFTimeInterval)getFramesDelay:(uint64_t)startSystemTimestamp } // Copy as late as possible to avoid allocating unnecessary memory. - frames = self.delayedFrames.copy; + frames = self.delayedFrames.mutableCopy; } - // Check if there is an delayed frame going on but not recorded yet. - CFTimeInterval frameDuration = thisFrameTimestamp - previousFrameTimestamp; - CFTimeInterval ongoingDelayedFrame = 0.0; - if (frameDuration > slowFrameThreshold) { - ongoingDelayedFrame = frameDuration - slowFrameThreshold; - } + // Add a delayed frame for a potentially ongoing but not recorded delayed frame + SentryDelayedFrame *currentFrameDelay = [[SentryDelayedFrame alloc] + initWithStartTimestamp:previousFrameSystemTimestamp + expectedDuration:slowFrameThreshold + actualDuration:nanosecondsToTimeInterval( + endSystemTimestamp - previousFrameSystemTimestamp)]; - CFTimeInterval delay = ongoingDelayedFrame; + [frames addObject:currentFrameDelay]; // We need to calculate the intersections of the queried TimestampInterval // (startSystemTimestamp - endSystemTimestamp) with the recorded frame delays. Doing that @@ -160,6 +159,8 @@ - (CFTimeInterval)getFramesDelay:(uint64_t)startSystemTimestamp NSDateInterval *queryDateInterval = [[NSDateInterval alloc] initWithStartDate:startDate endDate:endDate]; + CFTimeInterval delay = 0.0; + // Iterate in reverse order, as younger frame delays are more likely to match the queried // period. for (SentryDelayedFrame *frame in frames.reverseObjectEnumerator) { @@ -170,23 +171,34 @@ - (CFTimeInterval)getFramesDelay:(uint64_t)startSystemTimestamp break; } - CFTimeInterval delayStartTime - = nanosecondsToTimeInterval(frame.startSystemTimestamp) + frame.expectedDuration; - NSDate *frameDelayStartDate = - [NSDate dateWithTimeIntervalSinceReferenceDate:delayStartTime]; + delay = delay + [self calculateDelay:frame queryDateInterval:queryDateInterval]; + } - NSDateInterval *frameDelayDateInterval = [[NSDateInterval alloc] - initWithStartDate:frameDelayStartDate - duration:(frame.actualDuration - frame.expectedDuration)]; + return delay; +} - if ([queryDateInterval intersectsDateInterval:frameDelayDateInterval]) { - NSDateInterval *intersection = - [queryDateInterval intersectionWithDateInterval:frameDelayDateInterval]; - delay = delay + intersection.duration; - } +- (CFTimeInterval)calculateDelay:(SentryDelayedFrame *)delayedFrame + queryDateInterval:(NSDateInterval *)queryDateInterval +{ + CFTimeInterval delayStartTime = nanosecondsToTimeInterval(delayedFrame.startSystemTimestamp) + + delayedFrame.expectedDuration; + NSDate *frameDelayStartDate = [NSDate dateWithTimeIntervalSinceReferenceDate:delayStartTime]; + + NSTimeInterval duration = delayedFrame.actualDuration - delayedFrame.expectedDuration; + if (duration < 0) { + return 0.0; } - return delay; + NSDateInterval *frameDelayDateInterval = + [[NSDateInterval alloc] initWithStartDate:frameDelayStartDate duration:duration]; + + if ([queryDateInterval intersectsDateInterval:frameDelayDateInterval]) { + NSDateInterval *intersection = + [queryDateInterval intersectionWithDateInterval:frameDelayDateInterval]; + return intersection.duration; + } else { + return 0.0; + } } @end diff --git a/Sources/Sentry/SentryFramesTracker.m b/Sources/Sentry/SentryFramesTracker.m index 06237d902af..dda690fd8ff 100644 --- a/Sources/Sentry/SentryFramesTracker.m +++ b/Sources/Sentry/SentryFramesTracker.m @@ -240,8 +240,7 @@ - (CFTimeInterval)getFramesDelay:(uint64_t)startSystemTimestamp return [self.delayedFramesTracker getFramesDelay:startSystemTimestamp endSystemTimestamp:endSystemTimestamp isRunning:_isRunning - thisFrameTimestamp:self.displayLinkWrapper.timestamp - previousFrameTimestamp:self.previousFrameTimestamp + previousFrameSystemTimestamp:self.previousFrameSystemTimestamp slowFrameThreshold:slowFrameThreshold(_currentFrameRate)]; } diff --git a/Sources/Sentry/SentrySpan.m b/Sources/Sentry/SentrySpan.m index 8ea1cac2b50..7fd4b4971f5 100644 --- a/Sources/Sentry/SentrySpan.m +++ b/Sources/Sentry/SentrySpan.m @@ -35,6 +35,7 @@ @implementation SentrySpan { NSMutableDictionary *_tags; NSObject *_stateLock; BOOL _isFinished; + uint64_t _startSystemTime; #if SENTRY_HAS_UIKIT NSUInteger initTotalFrames; NSUInteger initSlowFrames; @@ -49,6 +50,7 @@ - (instancetype)initWithContext:(SentrySpanContext *)context #endif // SENTRY_HAS_UIKIT { if (self = [super init]) { + _startSystemTime = SentryDependencyContainer.sharedInstance.dateProvider.systemTime; self.startTimestamp = [SentryDependencyContainer.sharedInstance.dateProvider date]; _data = [[NSMutableDictionary alloc] init]; @@ -207,6 +209,14 @@ - (void)finishWithStatus:(SentrySpanStatus)status #if SENTRY_HAS_UIKIT if (_framesTracker.isRunning) { + CFTimeInterval framesDelay = [_framesTracker + getFramesDelay:_startSystemTime + endSystemTimestamp:SentryDependencyContainer.sharedInstance.dateProvider.systemTime]; + + if (framesDelay >= 0) { + [self setDataValue:@(framesDelay) forKey:@"frames.delay"]; + } + SentryScreenFrames *currentFrames = _framesTracker.currentFrames; NSInteger totalFrames = currentFrames.total - initTotalFrames; NSInteger slowFrames = currentFrames.slow - initSlowFrames; diff --git a/Sources/Sentry/include/SentryDelayedFramesTracker.h b/Sources/Sentry/include/SentryDelayedFramesTracker.h index 7606e4bce23..f2c3527caeb 100644 --- a/Sources/Sentry/include/SentryDelayedFramesTracker.h +++ b/Sources/Sentry/include/SentryDelayedFramesTracker.h @@ -45,8 +45,7 @@ SENTRY_NO_INIT * delay. * @param endSystemTimestamp The end system time stamp for the time interval to query frames delay. * @param isRunning Wether the frames tracker is running or not. - * @param thisFrameTimestamp The timestamp of the current frame. - * @param previousFrameTimestamp The timestamp of the previous frame. + * @param previousFrameSystemTimestamp The system timestamp of the previous frame. * @param slowFrameThreshold The threshold for a slow frame. For 60 fps this is roughly 16.67 ms. * * @return the frames delay duration or -1 if it can't calculate the frames delay. @@ -54,8 +53,7 @@ SENTRY_NO_INIT - (CFTimeInterval)getFramesDelay:(uint64_t)startSystemTimestamp endSystemTimestamp:(uint64_t)endSystemTimestamp isRunning:(BOOL)isRunning - thisFrameTimestamp:(CFTimeInterval)thisFrameTimestamp - previousFrameTimestamp:(CFTimeInterval)previousFrameTimestamp + previousFrameSystemTimestamp:(uint64_t)previousFrameSystemTimestamp slowFrameThreshold:(CFTimeInterval)slowFrameThreshold; @end diff --git a/Tests/SentryTests/Integrations/Performance/FramesTracking/SentryFramesTrackerTests.swift b/Tests/SentryTests/Integrations/Performance/FramesTracking/SentryFramesTrackerTests.swift index 042a33e2ed0..34acd569783 100644 --- a/Tests/SentryTests/Integrations/Performance/FramesTracking/SentryFramesTrackerTests.swift +++ b/Tests/SentryTests/Integrations/Performance/FramesTracking/SentryFramesTrackerTests.swift @@ -310,7 +310,7 @@ class SentryFramesTrackerTests: XCTestCase { let startSystemTime = fixture.dateProvider.systemTime() - let delay = 0.5 + let delay = 0.02 fixture.dateProvider.advance(by: delay) let endSystemTime = fixture.dateProvider.systemTime() @@ -321,6 +321,31 @@ class SentryFramesTrackerTests: XCTestCase { expect(actualFrameDelay).to(beCloseTo(expectedDelay, within: 0.0001)) } + func testDelayedFrames_FrameIsDelayedSmallerThanSlowFrameThreshold_ReturnsDelay() { + fixture.dateProvider.advance(by: 2.0) + + let sut = fixture.sut + sut.start() + + let displayLink = fixture.displayLinkWrapper + displayLink.call() + displayLink.normalFrame() + + fixture.dateProvider.advance(by: slowFrameThreshold(fixture.displayLinkWrapper.currentFrameRate.rawValue)) + + let startSystemTime = fixture.dateProvider.systemTime() + + let delay = 0.0001 + fixture.dateProvider.advance(by: delay) + + let endSystemTime = fixture.dateProvider.systemTime() + + let expectedDelay = delay + + let actualFrameDelay = sut.getFramesDelay(startSystemTime, endSystemTimestamp: endSystemTime) + expect(actualFrameDelay).to(beCloseTo(expectedDelay, within: 0.0001)) + } + private func testFrameDelay(timeIntervalAfterFrameStart: TimeInterval = 0.0, timeIntervalBeforeFrameEnd: TimeInterval = 0.0, expectedDelay: TimeInterval) { let sut = fixture.sut sut.start() diff --git a/Tests/SentryTests/Transaction/SentrySpanTests.swift b/Tests/SentryTests/Transaction/SentrySpanTests.swift index b6e71b1d328..15b9ae320dd 100644 --- a/Tests/SentryTests/Transaction/SentrySpanTests.swift +++ b/Tests/SentryTests/Transaction/SentrySpanTests.swift @@ -499,30 +499,7 @@ class SentrySpanTests: XCTestCase { expect(sut.data["frames.frozen"]) == nil } - func testAddZeroSlowFrozenFrames_WhenSpanStartedBackgroundThread() { - let (displayLinkWrapper, framesTracker) = givenFramesTracker() - - let expectation = expectation(description: "SpanStarted on a background thread") - DispatchQueue.global().async { - let sut = SentrySpan(context: SpanContext(operation: "TEST"), framesTracker: framesTracker) - - let slow = 2 - let frozen = 1 - let normal = 100 - displayLinkWrapper.renderFrames(slow, frozen, normal) - - sut.finish() - - expect(sut.data["frames.total"] as? NSNumber) == NSNumber(value: slow + frozen + normal) - expect(sut.data["frames.slow"] as? NSNumber) == NSNumber(value: slow) - expect(sut.data["frames.frozen"] as? NSNumber) == NSNumber(value: frozen) - expectation.fulfill() - } - - wait(for: [expectation], timeout: 1.0) - } - - func testAddSlowFrozenFramesToData_WithPreexistingCounts() { + func testAddFrameStatisticsToData_WithPreexistingCounts() { let (displayLinkWrapper, framesTracker) = givenFramesTracker() let preexistingSlow = 1 let preexistingFrozen = 2 @@ -531,16 +508,24 @@ class SentrySpanTests: XCTestCase { let sut = SentrySpan(context: SpanContext(operation: "TEST"), framesTracker: framesTracker) - let slow = 7 - let frozen = 8 - let normal = 9 - displayLinkWrapper.renderFrames(slow, frozen, normal) + let slowFrames = 1 + let frozenFrames = 1 + let normalFrames = 100 + let totalFrames = slowFrames + frozenFrames + normalFrames + _ = displayLinkWrapper.slowestSlowFrame() + _ = displayLinkWrapper.fastestFrozenFrame() + displayLinkWrapper.renderFrames(0, 0, normalFrames) sut.finish() - expect(sut.data["frames.total"] as? NSNumber) == NSNumber(value: slow + frozen + normal) - expect(sut.data["frames.slow"] as? NSNumber) == NSNumber(value: slow) - expect(sut.data["frames.frozen"] as? NSNumber) == NSNumber(value: frozen) + expect(sut.data["frames.total"] as? NSNumber) == NSNumber(value: totalFrames) + expect(sut.data["frames.slow"] as? NSNumber) == NSNumber(value: slowFrames) + expect(sut.data["frames.frozen"] as? NSNumber) == NSNumber(value: frozenFrames) + + let expectedFrameDuration = slowFrameThreshold(displayLinkWrapper.currentFrameRate.rawValue) + let expectedDelay = displayLinkWrapper.slowestSlowFrameDuration + displayLinkWrapper.fastestFrozenFrameDuration - expectedFrameDuration * 2 as NSNumber + + expect(sut.data["frames.delay"] as? NSNumber).to(beCloseTo(expectedDelay, within: 0.0001)) } func testNoFramesTracker_NoFramesAddedToData() { @@ -551,11 +536,12 @@ class SentrySpanTests: XCTestCase { expect(sut.data["frames.total"]) == nil expect(sut.data["frames.slow"]) == nil expect(sut.data["frames.frozen"]) == nil + expect(sut.data["frames.delay"]) == nil } private func givenFramesTracker() -> (TestDisplayLinkWrapper, SentryFramesTracker) { - let displayLinkWrapper = TestDisplayLinkWrapper() - let framesTracker = SentryFramesTracker(displayLinkWrapper: displayLinkWrapper, dateProvider: TestCurrentDateProvider(), keepDelayedFramesDuration: 0) + let displayLinkWrapper = TestDisplayLinkWrapper(dateProvider: self.fixture.currentDateProvider) + let framesTracker = SentryFramesTracker(displayLinkWrapper: displayLinkWrapper, dateProvider: self.fixture.currentDateProvider, keepDelayedFramesDuration: 10) framesTracker.start() displayLinkWrapper.call() From fac579e10b1b00e6ff6c8c1db22645329d083ff5 Mon Sep 17 00:00:00 2001 From: Philipp Hofmann Date: Tue, 19 Dec 2023 11:28:44 +0100 Subject: [PATCH 16/31] fix: TTFD waits for next drawn frame (#3505) The SDK waits for the next drawn frame after users call reportFullyDisplayed to reflect when UI changes are visible to the user correctly. --- CHANGELOG.md | 5 + .../LoremIpsumViewController.swift | 5 +- Sources/Sentry/SentryTimeToDisplayTracker.m | 63 ++-- ...SentryUIViewControllerPerformanceTracker.m | 2 +- .../include/SentryTimeToDisplayTracker.h | 2 +- ...yPerformanceTrackingIntegrationTests.swift | 1 + .../SentryTimeToDisplayTrackerTest.swift | 287 +++++++++--------- ...iewControllerPerformanceTrackerTests.swift | 17 +- 8 files changed, 205 insertions(+), 177 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 864902a14bf..dfffc1bee6e 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -6,6 +6,11 @@ - Add frames delay to transactions and spans (#3487, #3496) - Add slow and frozen frames to spans (#3450, #3478) + +### Fixes + +- TTFD waits for next drawn frame (#3505) + ## 8.17.2 ### Fixes diff --git a/Samples/iOS-Swift/iOS-Swift/ViewControllers/LoremIpsumViewController.swift b/Samples/iOS-Swift/iOS-Swift/ViewControllers/LoremIpsumViewController.swift index b3a113e37ff..d74750bd347 100644 --- a/Samples/iOS-Swift/iOS-Swift/ViewControllers/LoremIpsumViewController.swift +++ b/Samples/iOS-Swift/iOS-Swift/ViewControllers/LoremIpsumViewController.swift @@ -14,7 +14,10 @@ class LoremIpsumViewController: UIViewController { if let contents = FileManager.default.contents(atPath: path) { DispatchQueue.main.async { self.textView.text = String(data: contents, encoding: .utf8) - SentrySDK.reportFullyDisplayed() + + dispatchQueue.asyncAfter(deadline: .now() + 0.1) { + SentrySDK.reportFullyDisplayed() + } } } } diff --git a/Sources/Sentry/SentryTimeToDisplayTracker.m b/Sources/Sentry/SentryTimeToDisplayTracker.m index 99492abe4a1..1bf922378e6 100644 --- a/Sources/Sentry/SentryTimeToDisplayTracker.m +++ b/Sources/Sentry/SentryTimeToDisplayTracker.m @@ -26,7 +26,7 @@ @implementation SentryTimeToDisplayTracker { BOOL _waitForFullDisplay; - BOOL _isReadyToDisplay; + BOOL _initialDisplayReported; BOOL _fullyDisplayedReported; NSString *_controllerName; } @@ -37,8 +37,7 @@ - (instancetype)initForController:(UIViewController *)controller if (self = [super init]) { _controllerName = [SwiftDescriptor getObjectClassName:controller]; _waitForFullDisplay = waitForFullDisplay; - - _isReadyToDisplay = NO; + _initialDisplayReported = NO; _fullyDisplayedReported = NO; } return self; @@ -66,33 +65,26 @@ - (void)startForTracer:(SentryTracer *)tracer self.initialDisplaySpan.startTimestamp = tracer.startTimestamp; [SentryDependencyContainer.sharedInstance.framesTracker addListener:self]; - [tracer setFinishCallback:^( - SentryTracer *_tracer) { [self trimTTFDIdNecessaryForTracer:_tracer]; }]; + [tracer setFinishCallback:^(SentryTracer *_tracer) { + if (self.fullDisplaySpan.status != kSentrySpanStatusDeadlineExceeded) { + return; + } + + self.fullDisplaySpan.timestamp = self.initialDisplaySpan.timestamp; + self.fullDisplaySpan.spanDescription = [NSString + stringWithFormat:@"%@ - Deadline Exceeded", self.fullDisplaySpan.spanDescription]; + [self addTimeToDisplayMeasurement:self.fullDisplaySpan name:@"time_to_full_display"]; + }]; } -- (void)reportReadyToDisplay +- (void)reportInitialDisplay { - _isReadyToDisplay = YES; + _initialDisplayReported = YES; } - (void)reportFullyDisplayed { _fullyDisplayedReported = YES; - if (self.waitForFullDisplay && _isReadyToDisplay) { - // We need the timestamp to be able to calculate the duration - // but we can't finish first and add measure later because - // finishing the span may trigger the tracer finishInternal. - self.fullDisplaySpan.timestamp = - [SentryDependencyContainer.sharedInstance.dateProvider date]; - [self addTimeToDisplayMeasurement:self.fullDisplaySpan name:@"time_to_full_display"]; - [self.fullDisplaySpan finish]; - } -} - -- (void)addTimeToDisplayMeasurement:(SentrySpan *)span name:(NSString *)name -{ - NSTimeInterval duration = [span.timestamp timeIntervalSinceDate:span.startTimestamp] * 1000; - [span setMeasurement:name value:@(duration) unit:SentryMeasurementUnitDuration.millisecond]; } - (void)framesTrackerHasNewFrame @@ -102,32 +94,35 @@ - (void)framesTrackerHasNewFrame // The purpose of TTID and TTFD is to measure how long // takes to the content of the screen to change. // Thats why we need to wait for the next frame to be drawn. - if (_isReadyToDisplay && self.initialDisplaySpan.isFinished == NO) { + if (_initialDisplayReported && self.initialDisplaySpan.isFinished == NO) { self.initialDisplaySpan.timestamp = finishTime; [self addTimeToDisplayMeasurement:self.initialDisplaySpan name:@"time_to_initial_display"]; [self.initialDisplaySpan finish]; - [SentryDependencyContainer.sharedInstance.framesTracker removeListener:self]; + + if (!_waitForFullDisplay) { + [SentryDependencyContainer.sharedInstance.framesTracker removeListener:self]; + } } - if (_waitForFullDisplay && _fullyDisplayedReported && self.fullDisplaySpan.isFinished == NO) { + if (_waitForFullDisplay && _fullyDisplayedReported && self.fullDisplaySpan.isFinished == NO + && self.initialDisplaySpan.isFinished == YES) { self.fullDisplaySpan.timestamp = finishTime; - [self addTimeToDisplayMeasurement:self.initialDisplaySpan name:@"time_to_full_display"]; + [self addTimeToDisplayMeasurement:self.fullDisplaySpan name:@"time_to_full_display"]; [self.fullDisplaySpan finish]; } -} -- (void)trimTTFDIdNecessaryForTracer:(SentryTracer *)tracer -{ - if (self.fullDisplaySpan.status != kSentrySpanStatusDeadlineExceeded) { - return; + if (self.initialDisplaySpan.isFinished == YES && self.fullDisplaySpan.isFinished == YES) { + [SentryDependencyContainer.sharedInstance.framesTracker removeListener:self]; } +} - self.fullDisplaySpan.timestamp = self.initialDisplaySpan.timestamp; - self.fullDisplaySpan.spanDescription = - [NSString stringWithFormat:@"%@ - Deadline Exceeded", self.fullDisplaySpan.spanDescription]; +- (void)addTimeToDisplayMeasurement:(SentrySpan *)span name:(NSString *)name +{ + NSTimeInterval duration = [span.timestamp timeIntervalSinceDate:span.startTimestamp] * 1000; + [span setMeasurement:name value:@(duration) unit:SentryMeasurementUnitDuration.millisecond]; } @end diff --git a/Sources/Sentry/SentryUIViewControllerPerformanceTracker.m b/Sources/Sentry/SentryUIViewControllerPerformanceTracker.m index 922fdf4ac1c..4d3dd4c983e 100644 --- a/Sources/Sentry/SentryUIViewControllerPerformanceTracker.m +++ b/Sources/Sentry/SentryUIViewControllerPerformanceTracker.m @@ -182,7 +182,7 @@ - (void)viewControllerViewWillAppear:(UIViewController *)controller SentryTimeToDisplayTracker *ttdTracker = objc_getAssociatedObject(controller, &SENTRY_UI_PERFORMANCE_TRACKER_TTD_TRACKER); - [ttdTracker reportReadyToDisplay]; + [ttdTracker reportInitialDisplay]; }; [self limitOverride:@"viewWillAppear" diff --git a/Sources/Sentry/include/SentryTimeToDisplayTracker.h b/Sources/Sentry/include/SentryTimeToDisplayTracker.h index 1b239aa8f94..755179af4ec 100644 --- a/Sources/Sentry/include/SentryTimeToDisplayTracker.h +++ b/Sources/Sentry/include/SentryTimeToDisplayTracker.h @@ -29,7 +29,7 @@ SENTRY_NO_INIT - (void)startForTracer:(SentryTracer *)tracer; -- (void)reportReadyToDisplay; +- (void)reportInitialDisplay; - (void)reportFullyDisplayed; diff --git a/Tests/SentryTests/Integrations/Performance/SentryPerformanceTrackingIntegrationTests.swift b/Tests/SentryTests/Integrations/Performance/SentryPerformanceTrackingIntegrationTests.swift index 37376eabe95..de7f143d26b 100644 --- a/Tests/SentryTests/Integrations/Performance/SentryPerformanceTrackingIntegrationTests.swift +++ b/Tests/SentryTests/Integrations/Performance/SentryPerformanceTrackingIntegrationTests.swift @@ -1,3 +1,4 @@ +import Nimble import SentryTestUtils import XCTest diff --git a/Tests/SentryTests/Integrations/Performance/UIViewController/SentryTimeToDisplayTrackerTest.swift b/Tests/SentryTests/Integrations/Performance/UIViewController/SentryTimeToDisplayTrackerTest.swift index f0bb2434c3f..c1e48bc0f7c 100644 --- a/Tests/SentryTests/Integrations/Performance/UIViewController/SentryTimeToDisplayTrackerTest.swift +++ b/Tests/SentryTests/Integrations/Performance/UIViewController/SentryTimeToDisplayTrackerTest.swift @@ -1,4 +1,5 @@ import Foundation +import Nimble import Sentry import SentryTestUtils import XCTest @@ -9,7 +10,7 @@ class SentryTimeToDisplayTrackerTest: XCTestCase { private class Fixture { let dateProvider: TestCurrentDateProvider = TestCurrentDateProvider() - var tracer: SentryTracer { SentryTracer(transactionContext: TransactionContext(operation: "Test Operation"), hub: nil) } + let timerFactory = TestSentryNSTimerFactory() var displayLinkWrapper = TestDisplayLinkWrapper() var framesTracker: SentryFramesTracker @@ -23,6 +24,16 @@ class SentryTimeToDisplayTrackerTest: XCTestCase { func getSut(for controller: UIViewController, waitForFullDisplay: Bool) -> SentryTimeToDisplayTracker { return SentryTimeToDisplayTracker(for: controller, waitForFullDisplay: waitForFullDisplay) } + + func getTracer() throws -> SentryTracer { + let options = Options() + let hub = TestHub(client: SentryClient(options: options, fileManager: try TestFileManager(options: options), deleteOldEnvelopeItems: false), andScope: nil) + return SentryTracer(transactionContext: TransactionContext(operation: "Test Operation"), hub: hub, configuration: SentryTracerConfiguration(block: { + $0.waitForChildren = true + $0.timerFactory = self.timerFactory + $0.dispatchQueueWrapper = TestSentryDispatchQueueWrapper() + })) + } } private lazy var fixture = Fixture() @@ -37,242 +48,246 @@ class SentryTimeToDisplayTrackerTest: XCTestCase { clearTestState() } - func testReportInitialDisplay_notWaitingFullDisplay() throws { + func testReportInitialDisplay_notWaitingForFullDisplay() throws { let sut = fixture.getSut(for: UIViewController(), waitForFullDisplay: false) fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 7)) - let tracer = fixture.tracer + let tracer = try fixture.getTracer() sut.start(for: tracer) - XCTAssertEqual(tracer.children.count, 1) - XCTAssertEqual(Dynamic(fixture.framesTracker).listeners.count, 1) + expect(tracer.children.count) == 1 + expect(Dynamic(self.fixture.framesTracker).listeners.count) == 1 let ttidSpan = try XCTUnwrap(tracer.children.first, "Expected a TTID span") - XCTAssertEqual(ttidSpan.startTimestamp, fixture.dateProvider.date()) + expect(ttidSpan.startTimestamp) == fixture.dateProvider.date() fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 9)) - sut.reportReadyToDisplay() + sut.reportInitialDisplay() + expect(ttidSpan.timestamp) == nil + expect(ttidSpan.isFinished) == false + fixture.displayLinkWrapper.normalFrame() - XCTAssertEqual(ttidSpan.timestamp, fixture.dateProvider.date()) - XCTAssertTrue(ttidSpan.isFinished) - XCTAssertEqual(ttidSpan.spanDescription, "UIViewController initial display") - XCTAssertEqual(ttidSpan.operation, SentrySpanOperationUILoadInitialDisplay) - XCTAssertEqual(ttidSpan.origin, "auto.ui.time_to_display") + expect(ttidSpan.timestamp) == fixture.dateProvider.date() + expect(ttidSpan.isFinished) == true + expect(ttidSpan.spanDescription) == "UIViewController initial display" + expect(ttidSpan.operation) == SentrySpanOperationUILoadInitialDisplay + expect(ttidSpan.origin) == "auto.ui.time_to_display" assertMeasurement(tracer: tracer, name: "time_to_initial_display", duration: 2_000) - XCTAssertEqual(Dynamic(fixture.framesTracker).listeners.count, 0) - } - - func testReportNewFrame_notReadyToDisplay() throws { - let sut = fixture.getSut(for: UIViewController(), waitForFullDisplay: false) - - fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 7)) - - let tracer = fixture.tracer - - sut.start(for: tracer) - XCTAssertEqual(tracer.children.count, 1) - - let ttidSpan = try XCTUnwrap(tracer.children.first, "Expected a TTID span") - XCTAssertEqual(ttidSpan.startTimestamp, fixture.dateProvider.date()) - - fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 9)) - fixture.displayLinkWrapper.normalFrame() - - XCTAssertNil(ttidSpan.timestamp) - XCTAssertFalse(ttidSpan.isFinished) - - fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 12)) - sut.reportReadyToDisplay() - fixture.displayLinkWrapper.normalFrame() - - XCTAssertEqual(ttidSpan.timestamp, fixture.dateProvider.date()) - XCTAssertTrue(ttidSpan.isFinished) + expect(Dynamic(self.fixture.framesTracker).listeners.count) == 0 } - func testreportInitialDisplay_waitForFullDisplay() { + func testReportInitialDisplay_waitForFullDisplay() throws { fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 7)) let sut = fixture.getSut(for: UIViewController(), waitForFullDisplay: true) - let tracer = fixture.tracer + let tracer = try fixture.getTracer() sut.start(for: tracer) - XCTAssertEqual(tracer.children.count, 2) + expect(tracer.children.count) == 2 - let ttidSpan = tracer.children.first - XCTAssertEqual(ttidSpan?.startTimestamp, fixture.dateProvider.date()) + let ttidSpan = sut.initialDisplaySpan + expect(ttidSpan?.startTimestamp) == fixture.dateProvider.date() fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 9)) - sut.reportReadyToDisplay() + sut.reportInitialDisplay() fixture.displayLinkWrapper.normalFrame() - XCTAssertEqual(ttidSpan?.timestamp, fixture.dateProvider.date()) - XCTAssertTrue(ttidSpan?.isFinished ?? false) + expect(ttidSpan?.isFinished) == true + expect(ttidSpan?.timestamp) == Date(timeIntervalSince1970: 9) + + assertMeasurement(tracer: tracer, name: "time_to_initial_display", duration: 2_000) fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 11)) sut.reportFullyDisplayed() - - assertMeasurement(tracer: tracer, name: "time_to_initial_display", duration: 2_000) - assertMeasurement(tracer: tracer, name: "time_to_full_display", duration: 4_000) - - XCTAssertEqual(ttidSpan?.timestamp, Date(timeIntervalSince1970: 9)) - XCTAssertTrue(ttidSpan?.isFinished ?? false) - XCTAssertEqual(tracer.children.count, 2) + + // TTFD not reported yet cause we wait for the next frame + expect(sut.fullDisplaySpan?.startTimestamp) == ttidSpan?.startTimestamp + expect(sut.fullDisplaySpan?.timestamp) == nil + expect(tracer.measurements["time_to_full_display"]) == nil + + expect(Dynamic(self.fixture.framesTracker).listeners.count) == 1 } - func testreportFullDisplay_notWaitingForFullDisplay() { + func testReportFullDisplay_notWaitingForFullDisplay() throws { let sut = fixture.getSut(for: UIViewController(), waitForFullDisplay: false) - let tracer = fixture.tracer + let tracer = try fixture.getTracer() sut.start(for: tracer) - sut.reportReadyToDisplay() + sut.reportInitialDisplay() fixture.displayLinkWrapper.normalFrame() sut.reportFullyDisplayed() - XCTAssertNil(sut.fullDisplaySpan) - XCTAssertEqual(tracer.children.count, 1) + expect(sut.fullDisplaySpan) == nil + expect(tracer.children.count) == 1 + expect(tracer.measurements["time_to_full_display"]) == nil + + expect(Dynamic(self.fixture.framesTracker).listeners.count) == 0 } - - func testreportFullDisplay_waitingForFullDisplay() { + + func testReportFullDisplay_waitingForFullDisplay() throws { fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 9)) let sut = fixture.getSut(for: UIViewController(), waitForFullDisplay: true) - let tracer = fixture.tracer + let tracer = try fixture.getTracer() sut.start(for: tracer) fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 10)) - sut.reportReadyToDisplay() + sut.reportInitialDisplay() fixture.displayLinkWrapper.normalFrame() fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 11)) sut.reportFullyDisplayed() fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 12)) + fixture.displayLinkWrapper.normalFrame() + + fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 13)) tracer.finish() - XCTAssertNotNil(sut.fullDisplaySpan) - XCTAssertEqual(sut.fullDisplaySpan?.startTimestamp, Date(timeIntervalSince1970: 9)) - XCTAssertEqual(sut.fullDisplaySpan?.timestamp, Date(timeIntervalSince1970: 11)) - XCTAssertEqual(sut.fullDisplaySpan?.status, .ok) - - XCTAssertEqual(sut.fullDisplaySpan?.spanDescription, "UIViewController full display") - XCTAssertEqual(sut.fullDisplaySpan?.operation, SentrySpanOperationUILoadFullDisplay) - XCTAssertEqual(sut.fullDisplaySpan?.origin, "manual.ui.time_to_display") + expect(sut.fullDisplaySpan) != nil + expect(sut.fullDisplaySpan?.startTimestamp) == Date(timeIntervalSince1970: 9) + expect(sut.fullDisplaySpan?.timestamp) == Date(timeIntervalSince1970: 12) + expect(sut.fullDisplaySpan?.status) == .ok + + expect(sut.fullDisplaySpan?.spanDescription) == "UIViewController full display" + expect(sut.fullDisplaySpan?.operation) == SentrySpanOperationUILoadFullDisplay + expect(sut.fullDisplaySpan?.origin) == "manual.ui.time_to_display" + + assertMeasurement(tracer: tracer, name: "time_to_full_display", duration: 3_000) + + expect(Dynamic(self.fixture.framesTracker).listeners.count) == 0 } - - func testReportFullDisplay_waitingForFullDisplay_notReadyToDisplay() { + + func testWaitingForFullDisplay_ReportFullDisplayBeforeInitialDisplay() throws { + fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 9)) let sut = fixture.getSut(for: UIViewController(), waitForFullDisplay: true) - let tracer = fixture.tracer + let tracer = try fixture.getTracer() sut.start(for: tracer) fixture.displayLinkWrapper.normalFrame() fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 11)) sut.reportFullyDisplayed() - - XCTAssertFalse(sut.fullDisplaySpan?.isFinished ?? true) - } - - func testReportFullDisplay_expires() { - fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 9)) - - let sut = fixture.getSut(for: UIViewController(), waitForFullDisplay: true) - let tracer = fixture.tracer - - sut.start(for: tracer) - - fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 10)) - sut.reportReadyToDisplay() + fixture.displayLinkWrapper.normalFrame() - fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 11)) - sut.fullDisplaySpan?.finish(status: .deadlineExceeded) - - fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 13)) - tracer.finish() - - XCTAssertEqual(sut.fullDisplaySpan?.startTimestamp, Date(timeIntervalSince1970: 9)) - XCTAssertEqual(sut.fullDisplaySpan?.timestamp, Date(timeIntervalSince1970: 10)) - XCTAssertEqual(sut.fullDisplaySpan?.spanDescription, "UIViewController full display - Deadline Exceeded") + expect(sut.fullDisplaySpan?.isFinished) == false + expect(sut.initialDisplaySpan?.isFinished) == false + + sut.reportInitialDisplay() + + expect(sut.fullDisplaySpan?.isFinished) == false + expect(sut.initialDisplaySpan?.isFinished) == false + + fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 12)) + fixture.displayLinkWrapper.normalFrame() + + expect(sut.initialDisplaySpan?.isFinished) == true + expect(sut.initialDisplaySpan?.timestamp) == Date(timeIntervalSince1970: 12) + expect(sut.initialDisplaySpan?.status) == .ok + assertMeasurement(tracer: tracer, name: "time_to_initial_display", duration: 3_000) + + expect(sut.fullDisplaySpan?.isFinished) == true + expect(sut.fullDisplaySpan?.timestamp) == Date(timeIntervalSince1970: 12) + expect(sut.fullDisplaySpan?.status) == .ok + assertMeasurement(tracer: tracer, name: "time_to_full_display", duration: 3_000) + + expect(Dynamic(self.fixture.framesTracker).listeners.count) == 0 } - func testCheckInitialTime() { + func testCheckInitialTime() throws { fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 9)) fixture.dateProvider.driftTimeForEveryRead = true let sut = fixture.getSut(for: UIViewController(), waitForFullDisplay: true) - let tracer = fixture.tracer + let tracer = try fixture.getTracer() sut.start(for: tracer) - XCTAssertNotNil(sut.fullDisplaySpan) - XCTAssertEqual(sut.fullDisplaySpan?.startTimestamp, tracer.startTimestamp) - XCTAssertEqual(sut.initialDisplaySpan?.startTimestamp, tracer.startTimestamp) + expect(sut.fullDisplaySpan) != nil + expect(sut.fullDisplaySpan?.startTimestamp) == tracer.startTimestamp + expect(sut.initialDisplaySpan?.startTimestamp) == tracer.startTimestamp } + + func testReportFullyDisplayed_AfterTracerTimesOut() throws { + fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 9)) - func testFullDisplay_reportedBefore_initialDisplay() { - fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 7)) - + let tracer = try fixture.getTracer() + let sut = fixture.getSut(for: UIViewController(), waitForFullDisplay: true) - let tracer = fixture.tracer + sut.start(for: tracer) - fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 9)) - sut.reportFullyDisplayed() + fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 10)) + sut.reportInitialDisplay() + fixture.displayLinkWrapper.normalFrame() fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 11)) - sut.reportReadyToDisplay() - fixture.displayLinkWrapper.normalFrame() - assertMeasurement(tracer: tracer, name: "time_to_initial_display", duration: 4_000) - assertMeasurement(tracer: tracer, name: "time_to_full_display", duration: 4_000) + // Timeout for tracer times out + fixture.timerFactory.fire() - XCTAssertEqual(sut.initialDisplaySpan?.timestamp, fixture.dateProvider.date()) - XCTAssertEqual(sut.fullDisplaySpan?.timestamp, sut.initialDisplaySpan?.timestamp) + fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 12)) + sut.reportFullyDisplayed() + + let ttidSpan = sut.initialDisplaySpan + expect(ttidSpan?.startTimestamp) == Date(timeIntervalSince1970: 9) + expect(ttidSpan?.timestamp) == Date(timeIntervalSince1970: 10) + expect(ttidSpan?.status) == .ok + assertMeasurement(tracer: tracer, name: "time_to_initial_display", duration: 1_000) + + let ttfdSpan = sut.fullDisplaySpan + expect(ttfdSpan?.startTimestamp) == ttidSpan?.startTimestamp + expect(ttfdSpan?.timestamp) == ttidSpan?.timestamp + expect(ttfdSpan?.status) == .deadlineExceeded + expect(ttfdSpan?.spanDescription) == "UIViewController full display - Deadline Exceeded" + expect(ttfdSpan?.operation) == SentrySpanOperationUILoadFullDisplay + expect(ttfdSpan?.origin) == "manual.ui.time_to_display" + + assertMeasurement(tracer: tracer, name: "time_to_full_display", duration: 1_000) } - - func testReportFullyDisplayed_afterFinishingTracer_withWaitForChildren() throws { + + func testNotWaitingForFullyDisplayed_AfterTracerTimesOut() throws { fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 9)) - let options = Options() - let hub = TestHub(client: SentryClient(options: options, fileManager: try TestFileManager(options: options), deleteOldEnvelopeItems: false), andScope: nil) - let tracer = SentryTracer(transactionContext: TransactionContext(operation: "Test Operation"), hub: hub, configuration: SentryTracerConfiguration(block: { config in - config.waitForChildren = true - })) - let sut = fixture.getSut(for: UIViewController(), waitForFullDisplay: true) + let tracer = try fixture.getTracer() + + let sut = fixture.getSut(for: UIViewController(), waitForFullDisplay: false) sut.start(for: tracer) fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 10)) - sut.reportReadyToDisplay() + sut.reportInitialDisplay() fixture.displayLinkWrapper.normalFrame() fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 11)) - tracer.finish() + // Timeout for tracer times out + fixture.timerFactory.fire() fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 12)) sut.reportFullyDisplayed() - - let transaction = hub.capturedTransactionsWithScope.first?.transaction - let measurements = transaction?["measurements"] as? [String: Any] - let ttid = measurements?["time_to_initial_display"] as? [String: Any] - let ttfd = measurements?["time_to_full_display"] as? [String: Any] - - XCTAssertEqual(ttid?["value"] as? Int, 1_000) - XCTAssertEqual(ttfd?["value"] as? Int, 3_000) + + assertMeasurement(tracer: tracer, name: "time_to_initial_display", duration: 1_000) + let ttidSpan = sut.initialDisplaySpan + expect(ttidSpan?.startTimestamp) == Date(timeIntervalSince1970: 9) + expect(ttidSpan?.timestamp) == Date(timeIntervalSince1970: 10) + expect(ttidSpan?.status) == .ok + + expect(sut.fullDisplaySpan) == nil + expect(tracer.measurements["time_to_full_display"]) == nil } func assertMeasurement(tracer: SentryTracer, name: String, duration: TimeInterval) { - XCTAssertEqual(tracer.measurements[name]?.value, NSNumber(value: duration)) - XCTAssertEqual(tracer.measurements[name]?.unit?.unit, "millisecond") - + expect(tracer.measurements[name]?.value) == NSNumber(value: duration) + expect(tracer.measurements[name]?.unit?.unit) == "millisecond" } } diff --git a/Tests/SentryTests/Integrations/Performance/UIViewController/SentryUIViewControllerPerformanceTrackerTests.swift b/Tests/SentryTests/Integrations/Performance/UIViewController/SentryUIViewControllerPerformanceTrackerTests.swift index c9921cb8f35..6262eb35479 100644 --- a/Tests/SentryTests/Integrations/Performance/UIViewController/SentryUIViewControllerPerformanceTrackerTests.swift +++ b/Tests/SentryTests/Integrations/Performance/UIViewController/SentryUIViewControllerPerformanceTrackerTests.swift @@ -1,5 +1,6 @@ #if os(iOS) || os(tvOS) || targetEnvironment(macCatalyst) +import Nimble import ObjectiveC import SentryTestUtils import XCTest @@ -21,6 +22,7 @@ class SentryUIViewControllerPerformanceTrackerTests: XCTestCase { let spanName = "spanName" let spanOperation = "spanOperation" let origin = "auto.ui.view_controller" + let frameDuration = 0.0016 private class Fixture { @@ -251,11 +253,11 @@ class SentryUIViewControllerPerformanceTrackerTests: XCTestCase { callbackExpectation.fulfill() } try assertSpanDuration(span: lastSpan, expectedDuration: 5) - try assertSpanDuration(span: transactionSpan, expectedDuration: 22) + try assertSpanDuration(span: transactionSpan, expectedDuration: 22 + frameDuration) wait(for: [callbackExpectation], timeout: 0) } - + func testReportFullyDisplayed() { let sut = fixture.getSut() sut.enableWaitForFullDisplay = true @@ -267,11 +269,17 @@ class SentryUIViewControllerPerformanceTrackerTests: XCTestCase { let spans = self.getStack(tracker) tracer = spans.first as? SentryTracer } + sut.viewControllerViewWillAppear(viewController) { + self.advanceTime(bySeconds: 0.1) + } sut.reportFullyDisplayed() reportFrame() + let expectedTTFDTimestamp = fixture.dateProvider.date() - XCTAssertTrue(tracer?.children[1].isFinished ?? false) + let ttfdSpan = tracer?.children[1] + expect(ttfdSpan?.isFinished) == true + expect(ttfdSpan?.timestamp) == expectedTTFDTimestamp } func testSecondViewController() { @@ -598,7 +606,7 @@ class SentryUIViewControllerPerformanceTrackerTests: XCTestCase { let timestamp = try XCTUnwrap(span.timestamp) let startTimestamp = try XCTUnwrap(span.startTimestamp) let duration = timestamp.timeIntervalSince(startTimestamp) - XCTAssertEqual(duration, expectedDuration) + expect(duration).to(beCloseTo(expectedDuration, within: 0.001)) } private func assertTrackerIsEmpty(_ tracker: SentryPerformanceTracker) { @@ -621,6 +629,7 @@ class SentryUIViewControllerPerformanceTrackerTests: XCTestCase { } private func reportFrame() { + advanceTime(bySeconds: self.frameDuration) Dynamic(SentryDependencyContainer.sharedInstance().framesTracker).displayLinkCallback() } } From add9550ef7dbb74d409806e99c31b85be9dafb1b Mon Sep 17 00:00:00 2001 From: Philipp Hofmann Date: Tue, 19 Dec 2023 15:35:55 +0100 Subject: [PATCH 17/31] ref: Improve FileManager delete logs (#3514) Delete file log messages show whether a file was successfully deleted, it doesn't exist, or an error occurred. Co-authored-by: Karl Heinz Struggl Co-authored-by: Sentry Github Bot --- Sources/Sentry/SentryFileManager.m | 12 +++++++----- 1 file changed, 7 insertions(+), 5 deletions(-) diff --git a/Sources/Sentry/SentryFileManager.m b/Sources/Sentry/SentryFileManager.m index 19c5b1f249e..387de2c5c9f 100644 --- a/Sources/Sentry/SentryFileManager.m +++ b/Sources/Sentry/SentryFileManager.m @@ -239,13 +239,15 @@ - (void)removeFileAtPath:(NSString *)path NSFileManager *fileManager = [NSFileManager defaultManager]; NSError *error = nil; @synchronized(self) { - SENTRY_LOG_DEBUG(@"Deleting %@", path); - if (![fileManager removeItemAtPath:path error:&error]) { - // We don't want to log an error if the file doesn't exist. - if (error.code != NSFileNoSuchFileError) { - SENTRY_LOG_ERROR(@"Couldn't delete file %@: %@", path, error); + if (error.code == NSFileNoSuchFileError) { + SENTRY_LOG_DEBUG(@"No file to delete at %@", path); + } else { + SENTRY_LOG_ERROR( + @"Error occurred while deleting file at %@ because of %@", path, error); } + } else { + SENTRY_LOG_DEBUG(@"Successfully deleted file at %@", path); } } } From 3297d6e29cd37151f68e9c605aea8b44e5e432cb Mon Sep 17 00:00:00 2001 From: Philipp Hofmann Date: Wed, 20 Dec 2023 10:45:13 +0100 Subject: [PATCH 18/31] fix: TTID/TTFD for app start transactions (#3512) The TTFD/TTID spans and measurements for app start transactions were wrong, as they didn't include the app start duration. This is fixed now. Fixes GH-3471 --- CHANGELOG.md | 1 + Sources/Sentry/SentryTimeToDisplayTracker.m | 16 +++- Sources/Sentry/SentryTracer.m | 12 +-- .../SentryTimeToDisplayTrackerTest.swift | 75 ++++++++++++++++++- 4 files changed, 91 insertions(+), 13 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index dfffc1bee6e..110234facbe 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -10,6 +10,7 @@ ### Fixes - TTFD waits for next drawn frame (#3505) +- Fix TTID/TTFD for app start transactions (#3512): TTID/TTFD spans and measurements for app start transaction now include the app start duration. ## 8.17.2 diff --git a/Sources/Sentry/SentryTimeToDisplayTracker.m b/Sources/Sentry/SentryTimeToDisplayTracker.m index 1bf922378e6..4b9b21569f1 100644 --- a/Sources/Sentry/SentryTimeToDisplayTracker.m +++ b/Sources/Sentry/SentryTimeToDisplayTracker.m @@ -66,6 +66,18 @@ - (void)startForTracer:(SentryTracer *)tracer [SentryDependencyContainer.sharedInstance.framesTracker addListener:self]; [tracer setFinishCallback:^(SentryTracer *_tracer) { + // If the start time of the tracer changes, which is the case for app start transactions, we + // also need to adapt the start time of our spans. + self.initialDisplaySpan.startTimestamp = _tracer.startTimestamp; + [self addTimeToDisplayMeasurement:self.initialDisplaySpan name:@"time_to_initial_display"]; + + if (self.fullDisplaySpan == nil) { + return; + } + + self.fullDisplaySpan.startTimestamp = _tracer.startTimestamp; + [self addTimeToDisplayMeasurement:self.fullDisplaySpan name:@"time_to_full_display"]; + if (self.fullDisplaySpan.status != kSentrySpanStatusDeadlineExceeded) { return; } @@ -97,8 +109,6 @@ - (void)framesTrackerHasNewFrame if (_initialDisplayReported && self.initialDisplaySpan.isFinished == NO) { self.initialDisplaySpan.timestamp = finishTime; - [self addTimeToDisplayMeasurement:self.initialDisplaySpan name:@"time_to_initial_display"]; - [self.initialDisplaySpan finish]; if (!_waitForFullDisplay) { @@ -109,8 +119,6 @@ - (void)framesTrackerHasNewFrame && self.initialDisplaySpan.isFinished == YES) { self.fullDisplaySpan.timestamp = finishTime; - [self addTimeToDisplayMeasurement:self.fullDisplaySpan name:@"time_to_full_display"]; - [self.fullDisplaySpan finish]; } diff --git a/Sources/Sentry/SentryTracer.m b/Sources/Sentry/SentryTracer.m index 78031ac82b8..3f8860963ce 100644 --- a/Sources/Sentry/SentryTracer.m +++ b/Sources/Sentry/SentryTracer.m @@ -491,6 +491,12 @@ - (void)finishInternal } [super finishWithStatus:_finishStatus]; } +#if SENTRY_HAS_UIKIT + if (appStartMeasurement != nil) { + [self updateStartTime:appStartMeasurement.appStartTimestamp]; + } +#endif // SENTRY_HAS_UIKIT + [self.delegate tracerDidFinish:self]; if (self.finishCallback) { @@ -501,12 +507,6 @@ - (void)finishInternal self.finishCallback = nil; } -#if SENTRY_HAS_UIKIT - if (appStartMeasurement != nil) { - [self updateStartTime:appStartMeasurement.appStartTimestamp]; - } -#endif // SENTRY_HAS_UIKIT - // Prewarming can execute code up to viewDidLoad of a UIViewController, and keep the app in the // background. This can lead to auto-generated transactions lasting for minutes or even hours. // Therefore, we drop transactions lasting longer than SENTRY_AUTO_TRANSACTION_MAX_DURATION. diff --git a/Tests/SentryTests/Integrations/Performance/UIViewController/SentryTimeToDisplayTrackerTest.swift b/Tests/SentryTests/Integrations/Performance/UIViewController/SentryTimeToDisplayTrackerTest.swift index c1e48bc0f7c..adc04dbc21d 100644 --- a/Tests/SentryTests/Integrations/Performance/UIViewController/SentryTimeToDisplayTrackerTest.swift +++ b/Tests/SentryTests/Integrations/Performance/UIViewController/SentryTimeToDisplayTrackerTest.swift @@ -28,7 +28,7 @@ class SentryTimeToDisplayTrackerTest: XCTestCase { func getTracer() throws -> SentryTracer { let options = Options() let hub = TestHub(client: SentryClient(options: options, fileManager: try TestFileManager(options: options), deleteOldEnvelopeItems: false), andScope: nil) - return SentryTracer(transactionContext: TransactionContext(operation: "Test Operation"), hub: hub, configuration: SentryTracerConfiguration(block: { + return SentryTracer(transactionContext: TransactionContext(operation: "ui.load"), hub: hub, configuration: SentryTracerConfiguration(block: { $0.waitForChildren = true $0.timerFactory = self.timerFactory $0.dispatchQueueWrapper = TestSentryDispatchQueueWrapper() @@ -67,6 +67,7 @@ class SentryTimeToDisplayTrackerTest: XCTestCase { expect(ttidSpan.isFinished) == false fixture.displayLinkWrapper.normalFrame() + tracer.finish() expect(ttidSpan.timestamp) == fixture.dateProvider.date() expect(ttidSpan.isFinished) == true @@ -97,8 +98,7 @@ class SentryTimeToDisplayTrackerTest: XCTestCase { expect(ttidSpan?.isFinished) == true expect(ttidSpan?.timestamp) == Date(timeIntervalSince1970: 9) - - assertMeasurement(tracer: tracer, name: "time_to_initial_display", duration: 2_000) + expect(tracer.measurements["time_to_initial_display"]) == nil fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 11)) sut.reportFullyDisplayed() @@ -188,6 +188,7 @@ class SentryTimeToDisplayTrackerTest: XCTestCase { fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 12)) fixture.displayLinkWrapper.normalFrame() + tracer.finish() expect(sut.initialDisplaySpan?.isFinished) == true expect(sut.initialDisplaySpan?.timestamp) == Date(timeIntervalSince1970: 12) @@ -284,6 +285,74 @@ class SentryTimeToDisplayTrackerTest: XCTestCase { expect(sut.fullDisplaySpan) == nil expect(tracer.measurements["time_to_full_display"]) == nil } + + func testTracerWithAppStartData_notWaitingForFullDisplay() throws { + let appStartMeasurement = TestData.getAppStartMeasurement(type: .cold, appStartTimestamp: Date(timeIntervalSince1970: 6)) + SentrySDK.setAppStartMeasurement(appStartMeasurement) + + fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 7)) + + let sut = fixture.getSut(for: UIViewController(), waitForFullDisplay: false) + let tracer = try fixture.getTracer() + + sut.start(for: tracer) + + fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 8)) + sut.reportInitialDisplay() + fixture.displayLinkWrapper.normalFrame() + + fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 9)) + sut.reportFullyDisplayed() + fixture.displayLinkWrapper.normalFrame() + + tracer.finish() + + let ttidSpan = sut.initialDisplaySpan + expect(ttidSpan?.isFinished) == true + expect(ttidSpan?.startTimestamp) == tracer.startTimestamp + expect(ttidSpan?.timestamp) == Date(timeIntervalSince1970: 8) + assertMeasurement(tracer: tracer, name: "time_to_initial_display", duration: 2_000) + + expect(sut.fullDisplaySpan) == nil + expect(tracer.measurements["time_to_full_display"]) == nil + + expect(Dynamic(self.fixture.framesTracker).listeners.count) == 0 + } + + func testTracerWithAppStartData_waitingForFullDisplay() throws { + let appStartMeasurement = TestData.getAppStartMeasurement(type: .cold, appStartTimestamp: Date(timeIntervalSince1970: 6)) + SentrySDK.setAppStartMeasurement(appStartMeasurement) + + fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 7)) + + let sut = fixture.getSut(for: UIViewController(), waitForFullDisplay: true) + let tracer = try fixture.getTracer() + + sut.start(for: tracer) + + fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 8)) + sut.reportInitialDisplay() + fixture.displayLinkWrapper.normalFrame() + + fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 9)) + sut.reportFullyDisplayed() + fixture.displayLinkWrapper.normalFrame() + + tracer.finish() + + let ttidSpan = sut.initialDisplaySpan + + expect(ttidSpan?.isFinished) == true + expect(ttidSpan?.startTimestamp) == tracer.startTimestamp + expect(ttidSpan?.timestamp) == Date(timeIntervalSince1970: 8) + assertMeasurement(tracer: tracer, name: "time_to_initial_display", duration: 2_000) + + expect(sut.fullDisplaySpan?.startTimestamp) == ttidSpan?.startTimestamp + expect(sut.fullDisplaySpan?.timestamp) == Date(timeIntervalSince1970: 9) + assertMeasurement(tracer: tracer, name: "time_to_full_display", duration: 3_000) + + expect(Dynamic(self.fixture.framesTracker).listeners.count) == 0 + } func assertMeasurement(tracer: SentryTracer, name: String, duration: TimeInterval) { expect(tracer.measurements[name]?.value) == NSNumber(value: duration) From 48e8c2e10e5b5e103fd28ed34b54ca7a9a7645ca Mon Sep 17 00:00:00 2001 From: Dhiogo Brustolin Date: Thu, 28 Dec 2023 10:34:40 +0100 Subject: [PATCH 19/31] chore: Script to create a hot fix (#3502) * Hot fix * Hot fix * Update hot-fix.sh * Update hot-fix.sh * Update hot-fix.sh * Update hot-fix.sh * rename script * Update create-cherry-pick-branch.sh --- scripts/create-cherry-pick-branch.sh | 28 ++++++++++++++++++++++++++++ 1 file changed, 28 insertions(+) create mode 100755 scripts/create-cherry-pick-branch.sh diff --git a/scripts/create-cherry-pick-branch.sh b/scripts/create-cherry-pick-branch.sh new file mode 100755 index 00000000000..f0b3231ee50 --- /dev/null +++ b/scripts/create-cherry-pick-branch.sh @@ -0,0 +1,28 @@ +#!/bin/bash + +#Creates a new branch from given tag and cherry pick commit. +#This helps to make a hotfix release by updating given version +#with the merge commit of a specific PR. + +#run this from sentry-cocoa root directory + +if [ "$#" -ne 3 ]; then + echo "Usage: $0 " + exit 1 +fi + +# Assign command-line arguments to variables +tag="$1" +version="$2" +commit_hash="$3" + +# Define the hotfix branch name +hotfix_branch="hotfix/$version" + +git checkout "tags/$tag" +git checkout -b "$hotfix_branch" +git cherry-pick "$commit_hash" +git push origin "$hotfix_branch" + +echo "Hotfix branch $hotfix_branch created and pushed successfully." + From 80da9d18512a22b76ecec0a3db415dc8702eaf84 Mon Sep 17 00:00:00 2001 From: Philipp Hofmann Date: Tue, 2 Jan 2024 10:48:27 +0100 Subject: [PATCH 20/31] ref: Ignore getFramesDelay for ThreadSanitizer (#3516) The ThreadSanitizer now ignores SentryFramesTracker:getFramesDelay. We accept the data race of the two properties _currentFrameRate and previousFrameSystemTimestamp, that are updated on the main thread in the displayLinkCallback. This method only reads these properties. In most scenarios, this method will be called on the main thread, for which no synchronization is needed. When calling this function from a background thread, the frames delay statistics don't need to be that accurate because background spans contribute less to delayed frames. We prefer having not 100% correct frames delay numbers for background spans instead of adding the overhead of synchronization. --- Sources/Sentry/SentryFramesTracker.m | 11 +++++++++++ Tests/ThreadSanitizer.sup | 3 +++ 2 files changed, 14 insertions(+) diff --git a/Sources/Sentry/SentryFramesTracker.m b/Sources/Sentry/SentryFramesTracker.m index dda690fd8ff..0381bc0ca82 100644 --- a/Sources/Sentry/SentryFramesTracker.m +++ b/Sources/Sentry/SentryFramesTracker.m @@ -234,6 +234,17 @@ - (SentryScreenFrames *)currentFrames # endif // SENTRY_TARGET_PROFILING_SUPPORTED } +/** + * The ThreadSanitizer ignores this method; see ThreadSanitizer.sup. + * + * We accept the data race of the two properties _currentFrameRate and previousFrameSystemTimestamp, + * that are updated on the main thread in the displayLinkCallback. This method only reads these + * properties. In most scenarios, this method will be called on the main thread, for which no + * synchronization is needed. When calling this function from a background thread, the frames delay + * statistics don't need to be that accurate because background spans contribute less to delayed + * frames. We prefer having not 100% correct frames delay numbers for background spans instead of + * adding the overhead of synchronization. + */ - (CFTimeInterval)getFramesDelay:(uint64_t)startSystemTimestamp endSystemTimestamp:(uint64_t)endSystemTimestamp { diff --git a/Tests/ThreadSanitizer.sup b/Tests/ThreadSanitizer.sup index 4595c26bd6c..a2f631f3118 100644 --- a/Tests/ThreadSanitizer.sup +++ b/Tests/ThreadSanitizer.sup @@ -23,3 +23,6 @@ race:disable race:URLSessionDataTaskMock race:getOriginalImplementation race:SentrySpanContext + +# Ignore SentryFramesTracer:getFramesDelay. Visit the method for the explanation. +race:getFramesDelay From 3d3a411a5668140abdfd76df5c94cf90989b4fb8 Mon Sep 17 00:00:00 2001 From: Philipp Hofmann Date: Tue, 2 Jan 2024 13:56:46 +0100 Subject: [PATCH 21/31] fix: Race condition in SentryTracer (#3523) Fix a race condition of the wasFinishCalled property in SentryTracer by using two extra synchronized blocks. --- CHANGELOG.md | 1 + Sources/Sentry/SentryTracer.m | 29 +++++++++++++++++------------ Tests/ThreadSanitizer.sup | 12 ++++++++++-- 3 files changed, 28 insertions(+), 14 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 110234facbe..ea220b54eae 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -11,6 +11,7 @@ - TTFD waits for next drawn frame (#3505) - Fix TTID/TTFD for app start transactions (#3512): TTID/TTFD spans and measurements for app start transaction now include the app start duration. +- Fix a race condition in SentryTracer (#3523) ## 8.17.2 diff --git a/Sources/Sentry/SentryTracer.m b/Sources/Sentry/SentryTracer.m index 3f8860963ce..6ae6ee7e959 100644 --- a/Sources/Sentry/SentryTracer.m +++ b/Sources/Sentry/SentryTracer.m @@ -425,7 +425,9 @@ - (void)finishWithStatus:(SentrySpanStatus)status { SENTRY_LOG_DEBUG(@"Finished trace with traceID: %@ and status: %@", self.traceId.sentryIdString, nameForSentrySpanStatus(status)); - self.wasFinishCalled = YES; + @synchronized(self) { + self.wasFinishCalled = YES; + } _finishStatus = status; [self canBeFinished]; } @@ -441,18 +443,21 @@ - (void)canBeFinished } BOOL hasUnfinishedChildSpansToWaitFor = [self hasUnfinishedChildSpansToWaitFor]; - if (!self.wasFinishCalled && !hasUnfinishedChildSpansToWaitFor && [self hasIdleTimeout]) { - SENTRY_LOG_DEBUG( - @"Span with id %@ isn't waiting on children and needs idle timeout dispatched.", - self.spanId.sentrySpanIdString); - [self dispatchIdleTimeout]; - return; - } - if (!self.wasFinishCalled || hasUnfinishedChildSpansToWaitFor) { - SENTRY_LOG_DEBUG(@"Span with id %@ has children but isn't waiting for them right now.", - self.spanId.sentrySpanIdString); - return; + @synchronized(self) { + if (!self.wasFinishCalled && !hasUnfinishedChildSpansToWaitFor && [self hasIdleTimeout]) { + SENTRY_LOG_DEBUG( + @"Span with id %@ isn't waiting on children and needs idle timeout dispatched.", + self.spanId.sentrySpanIdString); + [self dispatchIdleTimeout]; + return; + } + + if (!self.wasFinishCalled || hasUnfinishedChildSpansToWaitFor) { + SENTRY_LOG_DEBUG(@"Span with id %@ has children but isn't waiting for them right now.", + self.spanId.sentrySpanIdString); + return; + } } [self finishInternal]; diff --git a/Tests/ThreadSanitizer.sup b/Tests/ThreadSanitizer.sup index a2f631f3118..da403fd0161 100644 --- a/Tests/ThreadSanitizer.sup +++ b/Tests/ThreadSanitizer.sup @@ -10,10 +10,18 @@ race:monitorCachedData race:TestThread.m race:uninstallExceptionHandler -# These methods use Double-Checked Locking and ThreadSanitizers produces -# false alarms for them. +# ------------------ Double Checked Locks ------------------ # +# ThreadSanitizers produces false alarms for double-checked +# locks. + race:getAppStartMeasurement +# SentryDependencyContainer +race:application +race:threadInspector + +# ------------------ End: Double Checked Locks -------------- # + # Races to fix race:returnResponse race:dispatchAsync From ea2a263b23b9ef8317741b5b71b6c51305569cdc Mon Sep 17 00:00:00 2001 From: Philipp Hofmann Date: Tue, 2 Jan 2024 14:34:43 +0100 Subject: [PATCH 22/31] ci: Bump actions artifacts from 3 to 4 (#3515) Bumps actions/download-artifact from 3 to 4 and actions/upload-artifact from 3 to 4. --- .github/workflows/benchmarking.yml | 4 ++-- .github/workflows/build.yml | 6 +++--- .github/workflows/saucelabs-UI-tests.yml | 4 ++-- .github/workflows/test.yml | 22 +++++++++++----------- .github/workflows/testflight.yml | 2 +- 5 files changed, 19 insertions(+), 19 deletions(-) diff --git a/.github/workflows/benchmarking.yml b/.github/workflows/benchmarking.yml index 5c8f5595993..4d521f24608 100644 --- a/.github/workflows/benchmarking.yml +++ b/.github/workflows/benchmarking.yml @@ -70,7 +70,7 @@ jobs: run: | sentry-cli --auth-token ${{ secrets.SENTRY_AUTH_TOKEN }} upload-dif --org sentry-sdks --project sentry-cocoa DerivedData/Build/Products/Debug-iphoneos/iOS-Swift.app.dSYM - name: Archiving DerivedData - uses: actions/upload-artifact@v3 + uses: actions/upload-artifact@v4 with: name: DerivedData-Xcode path: | @@ -87,7 +87,7 @@ jobs: suite: ['High-end device', 'Mid-range device', 'Low-end device'] steps: - uses: actions/checkout@v4 - - uses: actions/download-artifact@v3 + - uses: actions/download-artifact@v4 with: name: DerivedData-Xcode - run: npm install -g saucectl@0.107.2 diff --git a/.github/workflows/build.yml b/.github/workflows/build.yml index 9d28f886f3f..0d078f9caee 100644 --- a/.github/workflows/build.yml +++ b/.github/workflows/build.yml @@ -94,7 +94,7 @@ jobs: shell: sh - name: Archiving XCFramework.zip - uses: actions/upload-artifact@v3 + uses: actions/upload-artifact@v4 with: name: ${{ github.sha }} if-no-files-found: error @@ -102,7 +102,7 @@ jobs: ${{ github.workspace }}/*.zip - name: Archive build log if failed - uses: actions/upload-artifact@v3 + uses: actions/upload-artifact@v4 if: ${{ failure() || cancelled() }} with: name: raw-build-output-build-xcframework @@ -115,7 +115,7 @@ jobs: needs: build-xcframework steps: - uses: actions/checkout@v4 - - uses: actions/download-artifact@v3 + - uses: actions/download-artifact@v4 with: name: ${{ github.sha }} - run: ./scripts/ci-select-xcode.sh 15.0.1 diff --git a/.github/workflows/saucelabs-UI-tests.yml b/.github/workflows/saucelabs-UI-tests.yml index 206e20574f0..11c1d8681bf 100644 --- a/.github/workflows/saucelabs-UI-tests.yml +++ b/.github/workflows/saucelabs-UI-tests.yml @@ -78,7 +78,7 @@ jobs: run: | sentry-cli --auth-token ${{ secrets.SENTRY_AUTH_TOKEN }} upload-dif --org sentry-sdks --project sentry-cocoa DerivedData/Build/Products/Test-iphoneos/iOS-Swift.app.dSYM - name: Archiving DerivedData - uses: actions/upload-artifact@v3 + uses: actions/upload-artifact@v4 with: name: DerivedData-Xcode-${{matrix.xcode}} path: | @@ -115,7 +115,7 @@ jobs: steps: - uses: actions/checkout@v4 - - uses: actions/download-artifact@v3 + - uses: actions/download-artifact@v4 with: name: DerivedData-Xcode-${{ matrix.xcode }} diff --git a/.github/workflows/test.yml b/.github/workflows/test.yml index c412ec8ec60..186fe020892 100644 --- a/.github/workflows/test.yml +++ b/.github/workflows/test.yml @@ -55,14 +55,14 @@ jobs: run: cp $(swift build --show-bin-path -c release)/Run test-server-exec - name: Archiving DerivedData - uses: actions/upload-artifact@v3 + uses: actions/upload-artifact@v4 with: name: test-server path: | ./test-server/test-server-exec - name: Archiving Raw Test Logs - uses: actions/upload-artifact@v3 + uses: actions/upload-artifact@v4 if: ${{ failure() || cancelled() }} with: name: test-server-build-log-${{matrix.platform}}-xcode-${{matrix.xcode}}-os-${{matrix.test-destination-os}} @@ -148,7 +148,7 @@ jobs: steps: - uses: actions/checkout@v4 - - uses: actions/download-artifact@v3 + - uses: actions/download-artifact@v4 with: name: test-server @@ -200,7 +200,7 @@ jobs: run: ./scripts/xcode-slowest-tests.sh - name: Archiving DerivedData Logs - uses: actions/upload-artifact@v3 + uses: actions/upload-artifact@v4 if: steps.build_tests.outcome == 'failure' with: name: derived-data-${{matrix.platform}}-xcode-${{matrix.xcode}}-os-${{matrix.test-destination-os}} @@ -208,7 +208,7 @@ jobs: /Users/runner/Library/Developer/Xcode/DerivedData/**/Logs/** - name: Archiving Raw Test Logs - uses: actions/upload-artifact@v3 + uses: actions/upload-artifact@v4 if: ${{ failure() || cancelled() }} with: name: raw-test-output-${{matrix.platform}}-xcode-${{matrix.xcode}}-os-${{matrix.test-destination-os}} @@ -216,7 +216,7 @@ jobs: raw-test-output.log - name: Archiving Crash Logs - uses: actions/upload-artifact@v3 + uses: actions/upload-artifact@v4 if: ${{ failure() || cancelled() }} with: name: crash-logs-${{matrix.platform}}-xcode-${{matrix.xcode}}-os-${{matrix.test-destination-os}} @@ -263,7 +263,7 @@ jobs: steps: - uses: actions/checkout@v4 - - uses: actions/download-artifact@v3 + - uses: actions/download-artifact@v4 with: name: test-server @@ -278,7 +278,7 @@ jobs: run: ./scripts/tests-with-thread-sanitizer.sh - name: Archiving Test Logs - uses: actions/upload-artifact@v3 + uses: actions/upload-artifact@v4 if: ${{ failure() || cancelled() }} with: name: thread-sanitizer @@ -301,7 +301,7 @@ jobs: shell: sh - name: Archiving Raw Test Logs - uses: actions/upload-artifact@v3 + uses: actions/upload-artifact@v4 if: ${{ failure() || cancelled() }} with: name: raw-uitest-output-${{matrix.target}} @@ -335,7 +335,7 @@ jobs: shell: sh - name: Archiving Raw Test Logs - uses: actions/upload-artifact@v3 + uses: actions/upload-artifact@v4 if: ${{ failure() || cancelled() }} with: name: raw-swiftui-test-output-${{matrix.platform}}-xcode-${{matrix.xcode}}-os-${{matrix.test-destination-os}} @@ -357,7 +357,7 @@ jobs: shell: sh - name: Archiving Raw Test Logs - uses: actions/upload-artifact@v3 + uses: actions/upload-artifact@v4 if: ${{ failure() || cancelled() }} with: name: raw-uitest-output-asan diff --git a/.github/workflows/testflight.yml b/.github/workflows/testflight.yml index 852fa4b2f7a..372d8d486de 100644 --- a/.github/workflows/testflight.yml +++ b/.github/workflows/testflight.yml @@ -52,7 +52,7 @@ jobs: bundle exec fastlane ios_swift_to_testflight - name: Archiving - uses: actions/upload-artifact@v3 + uses: actions/upload-artifact@v4 with: name: dSYMs path: | From b9a9ffd9ab91b555e7b798a60311876a15b87b01 Mon Sep 17 00:00:00 2001 From: Andrew McKnight Date: Tue, 2 Jan 2024 12:32:43 -0900 Subject: [PATCH 23/31] fix: simplify dispatch queue wrapper access (#3477) --- CHANGELOG.md | 1 + Sources/Sentry/SentryTracer.m | 22 ++++--- .../SentryUIEventTrackerTransactionMode.m | 6 +- .../Sentry/SentryUIEventTrackingIntegration.m | 7 +-- .../include/SentryTracerConfiguration.h | 5 -- .../SentryUIEventTrackerTransactionMode.h | 5 +- .../SentryProfilerSwiftTests.swift | 2 +- .../SentryTimeToDisplayTrackerTest.swift | 2 +- .../UIEvents/SentryUIEventTrackerTests.swift | 3 +- .../Transaction/SentryTracerTests.swift | 61 ++++++++----------- 10 files changed, 48 insertions(+), 66 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index ea220b54eae..fde42b354e2 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -12,6 +12,7 @@ - TTFD waits for next drawn frame (#3505) - Fix TTID/TTFD for app start transactions (#3512): TTID/TTFD spans and measurements for app start transaction now include the app start duration. - Fix a race condition in SentryTracer (#3523) +- Missing transactions when not calling `reportFullyDisplayed` (#3477) ## 8.17.2 diff --git a/Sources/Sentry/SentryTracer.m b/Sources/Sentry/SentryTracer.m index 6ae6ee7e959..5a33a615d4b 100644 --- a/Sources/Sentry/SentryTracer.m +++ b/Sources/Sentry/SentryTracer.m @@ -70,6 +70,7 @@ @property (nonatomic) BOOL wasFinishCalled; @property (nonatomic, nullable, strong) NSTimer *deadlineTimer; @property (nonnull, strong) SentryTracerConfiguration *configuration; +@property (nonatomic, strong) SentryDispatchQueueWrapper *dispatchQueue; #if SENTRY_TARGET_PROFILING_SUPPORTED @property (nonatomic) BOOL isProfiling; @@ -132,6 +133,7 @@ - (instancetype)initWithTransactionContext:(SentryTransactionContext *)transacti _startSystemTime = SentryDependencyContainer.sharedInstance.dateProvider.systemTime; _configuration = configuration; + _dispatchQueue = SentryDependencyContainer.sharedInstance.dispatchQueueWrapper; self.transactionContext = transactionContext; _children = [[NSMutableArray alloc] init]; @@ -198,10 +200,10 @@ - (void)dispatchIdleTimeout { @synchronized(_idleTimeoutLock) { if (_idleTimeoutBlock != NULL) { - [_configuration.dispatchQueueWrapper dispatchCancel:_idleTimeoutBlock]; + [_dispatchQueue dispatchCancel:_idleTimeoutBlock]; } __weak SentryTracer *weakSelf = self; - _idleTimeoutBlock = [_configuration.dispatchQueueWrapper createDispatchBlock:^{ + _idleTimeoutBlock = [_dispatchQueue createDispatchBlock:^{ if (weakSelf == nil) { SENTRY_LOG_DEBUG(@"WeakSelf is nil. Not doing anything."); return; @@ -215,15 +217,14 @@ - (void)dispatchIdleTimeout // If the transaction has no children, the SDK will discard it. [self finishInternal]; } else { - [_configuration.dispatchQueueWrapper dispatchAfter:_configuration.idleTimeout - block:_idleTimeoutBlock]; + [_dispatchQueue dispatchAfter:_configuration.idleTimeout block:_idleTimeoutBlock]; } } } - (BOOL)hasIdleTimeout { - return _configuration.idleTimeout > 0 && _configuration.dispatchQueueWrapper != nil; + return _configuration.idleTimeout > 0; } - (BOOL)isAutoGeneratedTransaction @@ -235,7 +236,8 @@ - (void)cancelIdleTimeout { @synchronized(_idleTimeoutLock) { if ([self hasIdleTimeout]) { - [_configuration.dispatchQueueWrapper dispatchCancel:_idleTimeoutBlock]; + [SentryDependencyContainer.sharedInstance.dispatchQueueWrapper + dispatchCancel:_idleTimeoutBlock]; } } } @@ -243,7 +245,7 @@ - (void)cancelIdleTimeout - (void)startDeadlineTimer { __weak SentryTracer *weakSelf = self; - [_configuration.dispatchQueueWrapper dispatchOnMainQueue:^{ + [_dispatchQueue dispatchOnMainQueue:^{ weakSelf.deadlineTimer = [weakSelf.configuration.timerFactory scheduledTimerWithTimeInterval:SENTRY_AUTO_TRANSACTION_DEADLINE repeats:NO @@ -285,7 +287,7 @@ - (void)cancelDeadlineTimer // The timer must be invalidated from the thread on which the timer was installed, see // https://developer.apple.com/documentation/foundation/nstimer/1415405-invalidate#1770468 - [_configuration.dispatchQueueWrapper dispatchOnMainQueue:^{ + [_dispatchQueue dispatchOnMainQueue:^{ if (weakSelf == nil) { SENTRY_LOG_DEBUG(@"WeakSelf is nil. Not invalidating deadlineTimer."); return; @@ -454,7 +456,9 @@ - (void)canBeFinished } if (!self.wasFinishCalled || hasUnfinishedChildSpansToWaitFor) { - SENTRY_LOG_DEBUG(@"Span with id %@ has children but isn't waiting for them right now.", + SENTRY_LOG_DEBUG( + @"Span with id %@ has children but hasn't finished yet so isn't waiting " + @"for them right now.", self.spanId.sentrySpanIdString); return; } diff --git a/Sources/Sentry/SentryUIEventTrackerTransactionMode.m b/Sources/Sentry/SentryUIEventTrackerTransactionMode.m index 781fc808598..095040c1a49 100644 --- a/Sources/Sentry/SentryUIEventTrackerTransactionMode.m +++ b/Sources/Sentry/SentryUIEventTrackerTransactionMode.m @@ -19,7 +19,6 @@ @interface SentryUIEventTrackerTransactionMode () -@property (nonatomic, strong) SentryDispatchQueueWrapper *dispatchQueueWrapper; @property (nonatomic, assign) NSTimeInterval idleTimeout; @property (nullable, nonatomic, strong) NSMutableArray *activeTransactions; @@ -27,11 +26,9 @@ @implementation SentryUIEventTrackerTransactionMode -- (instancetype)initWithDispatchQueueWrapper:(SentryDispatchQueueWrapper *)dispatchQueueWrapper - idleTimeout:(NSTimeInterval)idleTimeout +- (instancetype)initWithIdleTimeout:(NSTimeInterval)idleTimeout { if (self = [super init]) { - self.dispatchQueueWrapper = dispatchQueueWrapper; self.idleTimeout = idleTimeout; self.activeTransactions = [NSMutableArray new]; } @@ -91,7 +88,6 @@ - (void)handleUIEvent:(NSString *)action SentryTracerConfiguration *config) { config.idleTimeout = self.idleTimeout; config.waitForChildren = YES; - config.dispatchQueueWrapper = self.dispatchQueueWrapper; }]]; SENTRY_LOG_DEBUG(@"Automatically started a new transaction with name: " diff --git a/Sources/Sentry/SentryUIEventTrackingIntegration.m b/Sources/Sentry/SentryUIEventTrackingIntegration.m index 130b3792b3a..e35db492bb5 100644 --- a/Sources/Sentry/SentryUIEventTrackingIntegration.m +++ b/Sources/Sentry/SentryUIEventTrackingIntegration.m @@ -2,7 +2,6 @@ #if SENTRY_HAS_UIKIT -# import # import # import # import @@ -25,10 +24,8 @@ - (BOOL)installWithOptions:(SentryOptions *)options return NO; } - SentryDependencyContainer *dependencies = [SentryDependencyContainer sharedInstance]; - SentryUIEventTrackerTransactionMode *mode = [[SentryUIEventTrackerTransactionMode alloc] - initWithDispatchQueueWrapper:dependencies.dispatchQueueWrapper - idleTimeout:options.idleTimeout]; + SentryUIEventTrackerTransactionMode *mode = + [[SentryUIEventTrackerTransactionMode alloc] initWithIdleTimeout:options.idleTimeout]; self.uiEventTracker = [[SentryUIEventTracker alloc] initWithMode:mode]; diff --git a/Sources/Sentry/include/SentryTracerConfiguration.h b/Sources/Sentry/include/SentryTracerConfiguration.h index cb38c47745f..5b81a0ffbb4 100644 --- a/Sources/Sentry/include/SentryTracerConfiguration.h +++ b/Sources/Sentry/include/SentryTracerConfiguration.h @@ -26,11 +26,6 @@ NS_ASSUME_NONNULL_BEGIN */ @property (nonatomic) BOOL waitForChildren; -/** - * A dispatch queue wrapper to intermediate between the tracer and dispatch calls. - */ -@property (nonatomic, strong, nullable) SentryDispatchQueueWrapper *dispatchQueueWrapper; - #if SENTRY_TARGET_PROFILING_SUPPORTED /** * Whether to sample a profile corresponding to this transaction diff --git a/Sources/Sentry/include/SentryUIEventTrackerTransactionMode.h b/Sources/Sentry/include/SentryUIEventTrackerTransactionMode.h index 4df6f1ea968..43b24d65d30 100644 --- a/Sources/Sentry/include/SentryUIEventTrackerTransactionMode.h +++ b/Sources/Sentry/include/SentryUIEventTrackerTransactionMode.h @@ -2,15 +2,12 @@ #if SENTRY_HAS_UIKIT -@class SentryDispatchQueueWrapper; - NS_ASSUME_NONNULL_BEGIN @interface SentryUIEventTrackerTransactionMode : NSObject SENTRY_NO_INIT -- (instancetype)initWithDispatchQueueWrapper:(SentryDispatchQueueWrapper *)dispatchQueueWrapper - idleTimeout:(NSTimeInterval)idleTimeout; +- (instancetype)initWithIdleTimeout:(NSTimeInterval)idleTimeout; @end diff --git a/Tests/SentryProfilerTests/SentryProfilerSwiftTests.swift b/Tests/SentryProfilerTests/SentryProfilerSwiftTests.swift index 8aa8b5e7d3c..8ed4b6c5a20 100644 --- a/Tests/SentryProfilerTests/SentryProfilerSwiftTests.swift +++ b/Tests/SentryProfilerTests/SentryProfilerSwiftTests.swift @@ -51,6 +51,7 @@ class SentryProfilerSwiftTests: XCTestCase { } SentryDependencyContainer.sharedInstance().dispatchFactory = dispatchFactory SentryDependencyContainer.sharedInstance().timerFactory = timeoutTimerFactory + SentryDependencyContainer.sharedInstance().dispatchQueueWrapper = dispatchQueueWrapper systemWrapper.overrides.cpuUsage = NSNumber(value: mockCPUUsage) systemWrapper.overrides.memoryFootprintBytes = mockMemoryFootprint @@ -76,7 +77,6 @@ class SentryProfilerSwiftTests: XCTestCase { if let idleTimeout = idleTimeout { $0.idleTimeout = idleTimeout } - $0.dispatchQueueWrapper = self.dispatchQueueWrapper $0.waitForChildren = true $0.timerFactory = self.timeoutTimerFactory })) diff --git a/Tests/SentryTests/Integrations/Performance/UIViewController/SentryTimeToDisplayTrackerTest.swift b/Tests/SentryTests/Integrations/Performance/UIViewController/SentryTimeToDisplayTrackerTest.swift index adc04dbc21d..70c77257c45 100644 --- a/Tests/SentryTests/Integrations/Performance/UIViewController/SentryTimeToDisplayTrackerTest.swift +++ b/Tests/SentryTests/Integrations/Performance/UIViewController/SentryTimeToDisplayTrackerTest.swift @@ -31,7 +31,6 @@ class SentryTimeToDisplayTrackerTest: XCTestCase { return SentryTracer(transactionContext: TransactionContext(operation: "ui.load"), hub: hub, configuration: SentryTracerConfiguration(block: { $0.waitForChildren = true $0.timerFactory = self.timerFactory - $0.dispatchQueueWrapper = TestSentryDispatchQueueWrapper() })) } } @@ -41,6 +40,7 @@ class SentryTimeToDisplayTrackerTest: XCTestCase { override func setUp() { super.setUp() SentryDependencyContainer.sharedInstance().dateProvider = fixture.dateProvider + SentryDependencyContainer.sharedInstance().dispatchQueueWrapper = TestSentryDispatchQueueWrapper() } override func tearDown() { diff --git a/Tests/SentryTests/Integrations/UIEvents/SentryUIEventTrackerTests.swift b/Tests/SentryTests/Integrations/UIEvents/SentryUIEventTrackerTests.swift index 57cfcde65d0..24cb5b2f156 100644 --- a/Tests/SentryTests/Integrations/UIEvents/SentryUIEventTrackerTests.swift +++ b/Tests/SentryTests/Integrations/UIEvents/SentryUIEventTrackerTests.swift @@ -16,7 +16,8 @@ class SentryUIEventTrackerTests: XCTestCase { init () { dispatchQueue.blockBeforeMainBlock = { false } SentryDependencyContainer.sharedInstance().swizzleWrapper = swizzleWrapper - uiEventTrackerMode = SentryUIEventTrackerTransactionMode(dispatchQueueWrapper: dispatchQueue, idleTimeout: 3.0) + SentryDependencyContainer.sharedInstance().dispatchQueueWrapper = dispatchQueue + uiEventTrackerMode = SentryUIEventTrackerTransactionMode(idleTimeout: 3.0) } func getSut() -> SentryUIEventTracker { diff --git a/Tests/SentryTests/Transaction/SentryTracerTests.swift b/Tests/SentryTests/Transaction/SentryTracerTests.swift index 122d04d3bf4..9d78a6fa0ef 100644 --- a/Tests/SentryTests/Transaction/SentryTracerTests.swift +++ b/Tests/SentryTests/Transaction/SentryTracerTests.swift @@ -52,6 +52,7 @@ class SentryTracerTests: XCTestCase { dispatchQueue.blockBeforeMainBlock = { false } SentryDependencyContainer.sharedInstance().dateProvider = currentDateProvider + SentryDependencyContainer.sharedInstance().dispatchQueueWrapper = dispatchQueue appStart = currentDateProvider.date() appStartEnd = appStart.addingTimeInterval(appStartDuration) @@ -87,30 +88,16 @@ class SentryTracerTests: XCTestCase { } #endif // os(iOS) || os(tvOS) || targetEnvironment(macCatalyst) - func getSut(waitForChildren: Bool = true) -> SentryTracer { + func getSut(waitForChildren: Bool = true, idleTimeout: TimeInterval = 0.0) -> SentryTracer { let tracer = hub.startTransaction( with: transactionContext, bindToScope: false, customSamplingContext: [:], configuration: SentryTracerConfiguration(block: { $0.waitForChildren = waitForChildren - $0.dispatchQueueWrapper = self.dispatchQueue $0.timerFactory = self.timerFactory - })) - return tracer - } - - func getSut(idleTimeout: TimeInterval = 0.0, dispatchQueueWrapper: SentryDispatchQueueWrapper) -> SentryTracer { - let tracer = hub.startTransaction( - with: transactionContext, - bindToScope: false, - customSamplingContext: [:], - configuration: SentryTracerConfiguration(block: { $0.idleTimeout = idleTimeout - $0.dispatchQueueWrapper = dispatchQueueWrapper - $0.waitForChildren = true - }) - ) + })) return tracer } } @@ -283,7 +270,7 @@ class SentryTracerTests: XCTestCase { } func testDeadlineTimer_OnlyForAutoTransactions() { - let sut = fixture.getSut(idleTimeout: fixture.idleTimeout, dispatchQueueWrapper: fixture.dispatchQueue) + let sut = fixture.getSut(idleTimeout: fixture.idleTimeout) let child1 = sut.startChild(operation: fixture.transactionOperation) let child2 = sut.startChild(operation: fixture.transactionOperation) let child3 = sut.startChild(operation: fixture.transactionOperation) @@ -306,12 +293,14 @@ class SentryTracerTests: XCTestCase { } func testDeadlineTimer_MultipleSpansFinishedInParallel() { - let sut = fixture.getSut(idleTimeout: 0.01, dispatchQueueWrapper: SentryDispatchQueueWrapper()) + SentryDependencyContainer.sharedInstance().dispatchQueueWrapper = SentryDispatchQueueWrapper() + let sut = fixture.getSut(idleTimeout: 0.01) testConcurrentModifications(writeWork: { _ in let child = sut.startChild(operation: self.fixture.transactionOperation) child.finish() }) + SentryDependencyContainer.sharedInstance().dispatchQueueWrapper = fixture.dispatchQueue } func testFinish_CheckDefaultStatus() { @@ -323,7 +312,7 @@ class SentryTracerTests: XCTestCase { func testIdleTransactionWithStatus_KeepsStatusWhenAutoFinishing() { let status = SentrySpanStatus.aborted - let sut = fixture.getSut(idleTimeout: fixture.idleTimeout, dispatchQueueWrapper: fixture.dispatchQueue) + let sut = fixture.getSut(idleTimeout: fixture.idleTimeout) sut.status = status let child = sut.startChild(operation: fixture.transactionOperation) @@ -339,13 +328,13 @@ class SentryTracerTests: XCTestCase { func testIdleTransaction_CreatingDispatchBlockFails_NoTransactionCaptured() { fixture.dispatchQueue.createDispatchBlockReturnsNULL = true - let sut = fixture.getSut(idleTimeout: fixture.idleTimeout, dispatchQueueWrapper: fixture.dispatchQueue) + let sut = fixture.getSut(idleTimeout: fixture.idleTimeout) assertTransactionNotCaptured(sut) } func testIdleTransaction_CreatingDispatchBlockFailsForFirstChild_FinishesTransaction() { - let sut = fixture.getSut(idleTimeout: fixture.idleTimeout, dispatchQueueWrapper: fixture.dispatchQueue) + let sut = fixture.getSut(idleTimeout: fixture.idleTimeout) fixture.dispatchQueue.createDispatchBlockReturnsNULL = true @@ -426,7 +415,7 @@ class SentryTracerTests: XCTestCase { #endif // os(iOS) || os(tvOS) || targetEnvironment(macCatalyst) func testFinish_IdleTimeout_ExceedsMaxDuration_NoTransactionCaptured() { - let sut = fixture.getSut(idleTimeout: fixture.idleTimeout, dispatchQueueWrapper: fixture.dispatchQueue) + let sut = fixture.getSut(idleTimeout: fixture.idleTimeout) advanceTime(bySeconds: 500) @@ -436,7 +425,7 @@ class SentryTracerTests: XCTestCase { } func testIdleTimeout_NoChildren_TransactionNotCaptured() { - _ = fixture.getSut(idleTimeout: fixture.idleTimeout, dispatchQueueWrapper: fixture.dispatchQueue) + _ = fixture.getSut(idleTimeout: fixture.idleTimeout) fixture.dispatchQueue.invokeLastDispatchAfter() @@ -444,7 +433,7 @@ class SentryTracerTests: XCTestCase { } func testIdleTimeout_NoChildren_SpanOnScopeUnset() { - let sut = fixture.getSut(idleTimeout: fixture.idleTimeout, dispatchQueueWrapper: fixture.dispatchQueue) + let sut = fixture.getSut(idleTimeout: fixture.idleTimeout) fixture.hub.scope.span = sut @@ -454,7 +443,7 @@ class SentryTracerTests: XCTestCase { } func testIdleTimeout_InvokesDispatchAfterWithCorrectWhen() { - _ = fixture.getSut(idleTimeout: fixture.idleTimeout, dispatchQueueWrapper: fixture.dispatchQueue) + _ = fixture.getSut(idleTimeout: fixture.idleTimeout) fixture.dispatchQueue.invokeLastDispatchAfter() @@ -462,7 +451,7 @@ class SentryTracerTests: XCTestCase { } func testIdleTimeout_SpanAdded_IdleTimeoutCancelled() { - let sut = fixture.getSut(idleTimeout: fixture.idleTimeout, dispatchQueueWrapper: fixture.dispatchQueue) + let sut = fixture.getSut(idleTimeout: fixture.idleTimeout) sut.startChild(operation: fixture.transactionOperation) @@ -471,7 +460,8 @@ class SentryTracerTests: XCTestCase { } func testIdleTimeoutWithRealDispatchQueue_SpanAdded_IdleTimeoutCancelled() { - let sut = fixture.getSut(idleTimeout: 0.1, dispatchQueueWrapper: SentryDispatchQueueWrapper()) + SentryDependencyContainer.sharedInstance().dispatchQueueWrapper = SentryDispatchQueueWrapper() + let sut = fixture.getSut(idleTimeout: 0.1) let child = sut.startChild(operation: fixture.transactionOperation) let grandChild = child.startChild(operation: fixture.transactionOperation) @@ -481,10 +471,11 @@ class SentryTracerTests: XCTestCase { delayNonBlocking(timeout: 0.5) assertOneTransactionCaptured(sut) + SentryDependencyContainer.sharedInstance().dispatchQueueWrapper = fixture.dispatchQueue } func testIdleTimeout_TwoChildren_FirstFinishes_WaitsForTheOther() { - let sut = fixture.getSut(idleTimeout: fixture.idleTimeout, dispatchQueueWrapper: fixture.dispatchQueue) + let sut = fixture.getSut(idleTimeout: fixture.idleTimeout) let child1 = sut.startChild(operation: fixture.transactionOperation) let child2 = sut.startChild(operation: fixture.transactionOperation) @@ -502,7 +493,7 @@ class SentryTracerTests: XCTestCase { } func testIdleTimeout_ChildSpanFinished_IdleStarted() { - let sut = fixture.getSut(idleTimeout: fixture.idleTimeout, dispatchQueueWrapper: fixture.dispatchQueue) + let sut = fixture.getSut(idleTimeout: fixture.idleTimeout) XCTAssertEqual(1, fixture.dispatchQueue.dispatchAfterInvocations.count) let child = sut.startChild(operation: fixture.transactionOperation) @@ -525,7 +516,7 @@ class SentryTracerTests: XCTestCase { } func testIdleTimeout_TimesOut_TrimsEndTimestamp() { - let sut = fixture.getSut(idleTimeout: fixture.idleTimeout, dispatchQueueWrapper: fixture.dispatchQueue) + let sut = fixture.getSut(idleTimeout: fixture.idleTimeout) let child1 = sut.startChild(operation: fixture.transactionOperation) advanceTime(bySeconds: 1.0) @@ -544,7 +535,7 @@ class SentryTracerTests: XCTestCase { } func testIdleTimeout_CallFinish_TrimsEndTimestamp() { - let sut = fixture.getSut(idleTimeout: fixture.idleTimeout, dispatchQueueWrapper: fixture.dispatchQueue) + let sut = fixture.getSut(idleTimeout: fixture.idleTimeout) let child = sut.startChild(operation: fixture.transactionOperation) advanceTime(bySeconds: 1.0) @@ -567,7 +558,7 @@ class SentryTracerTests: XCTestCase { // Interact with sut in extra function so ARC deallocates it func getSut() { - let sut = fixture.getSut(idleTimeout: fixture.idleTimeout, dispatchQueueWrapper: fixture.dispatchQueue) + let sut = fixture.getSut(idleTimeout: fixture.idleTimeout) _ = sut.startChild(operation: fixture.transactionOperation) } @@ -598,7 +589,7 @@ class SentryTracerTests: XCTestCase { } func testIdleTimeoutWithUnfinishedChildren_TimesOut_TrimsEndTimestamp() { - let sut = fixture.getSut(idleTimeout: fixture.idleTimeout, dispatchQueueWrapper: fixture.dispatchQueue) + let sut = fixture.getSut(idleTimeout: fixture.idleTimeout) let child1 = sut.startChild(operation: fixture.transactionOperation) advanceTime(bySeconds: 1.0) @@ -616,7 +607,7 @@ class SentryTracerTests: XCTestCase { } func testIdleTimeout_CallFinish_WaitsForChildren_DoesntStartTimeout() { - let sut = fixture.getSut(idleTimeout: fixture.idleTimeout, dispatchQueueWrapper: fixture.dispatchQueue) + let sut = fixture.getSut(idleTimeout: fixture.idleTimeout) let child = sut.startChild(operation: fixture.transactionOperation) XCTAssertEqual(1, fixture.dispatchQueue.dispatchAfterInvocations.count) @@ -914,7 +905,7 @@ class SentryTracerTests: XCTestCase { func testFinishCallback_CalledWhenTracerFinishes() { let callbackExpectation = expectation(description: "FinishCallback called") - let sut = fixture.getSut(idleTimeout: fixture.idleTimeout, dispatchQueueWrapper: fixture.dispatchQueue) + let sut = fixture.getSut(idleTimeout: fixture.idleTimeout) let block: (SentryTracer) -> Void = { tracer in XCTAssertEqual(sut, tracer) From 1d10917d832b3b158dd4be63b7e89517eb9bda85 Mon Sep 17 00:00:00 2001 From: Philipp Hofmann Date: Wed, 3 Jan 2024 14:18:48 +0100 Subject: [PATCH 24/31] fix: Crash when adding a crumb for a timezone change (#3524) Fix a crash when adding a time crumb for a timezone change and the previously stored timezone offset is nil. Fixes GH-3513 --- CHANGELOG.md | 1 + Sources/Sentry/SentrySystemEventBreadcrumbs.m | 14 +++++++++----- .../SentrySystemEventBreadcrumbsTest.swift | 15 +++++++++++++++ 3 files changed, 25 insertions(+), 5 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index fde42b354e2..e9afc5b1e68 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -11,6 +11,7 @@ - TTFD waits for next drawn frame (#3505) - Fix TTID/TTFD for app start transactions (#3512): TTID/TTFD spans and measurements for app start transaction now include the app start duration. +- Crash when adding a crumb for a timezone change (#3524) - Fix a race condition in SentryTracer (#3523) - Missing transactions when not calling `reportFullyDisplayed` (#3477) diff --git a/Sources/Sentry/SentrySystemEventBreadcrumbs.m b/Sources/Sentry/SentrySystemEventBreadcrumbs.m index f482b9d725c..dcdb672e562 100644 --- a/Sources/Sentry/SentrySystemEventBreadcrumbs.m +++ b/Sources/Sentry/SentrySystemEventBreadcrumbs.m @@ -240,11 +240,15 @@ - (void)timezoneEventTriggered:(NSNumber *)storedTimezoneOffset NSInteger offset = SentryDependencyContainer.sharedInstance.dateProvider.timezoneOffset; crumb.type = @"system"; - crumb.data = @{ - @"action" : @"TIMEZONE_CHANGE", - @"previous_seconds_from_gmt" : storedTimezoneOffset, - @"current_seconds_from_gmt" : @(offset) - }; + + NSMutableDictionary *dataDict = + [@{ @"action" : @"TIMEZONE_CHANGE", @"current_seconds_from_gmt" : @(offset) } mutableCopy]; + + if (storedTimezoneOffset != nil) { + dataDict[@"previous_seconds_from_gmt"] = storedTimezoneOffset; + } + + crumb.data = dataDict; [_delegate addBreadcrumb:crumb]; [self updateStoredTimezone]; diff --git a/Tests/SentryTests/Integrations/Breadcrumbs/SentrySystemEventBreadcrumbsTest.swift b/Tests/SentryTests/Integrations/Breadcrumbs/SentrySystemEventBreadcrumbsTest.swift index 71a18216e1c..ffc8ee4cdee 100644 --- a/Tests/SentryTests/Integrations/Breadcrumbs/SentrySystemEventBreadcrumbsTest.swift +++ b/Tests/SentryTests/Integrations/Breadcrumbs/SentrySystemEventBreadcrumbsTest.swift @@ -1,3 +1,4 @@ +import Nimble @testable import Sentry import SentryTestUtils import XCTest @@ -251,6 +252,20 @@ class SentrySystemEventBreadcrumbsTest: XCTestCase { XCTAssertEqual(data["current_seconds_from_gmt"] as? Int64, 7_200) } } + + func testTimezoneChangeNotificationBreadcrumb_NoStoredTimezoneOffset() { + sut = fixture.getSut(currentDevice: nil) + + fixture.currentDateProvider.timezoneOffsetValue = 7_200 + fixture.fileManager.deleteTimezoneOffset() + + sut.timezoneEventTriggered() + + assertBreadcrumbAction(action: "TIMEZONE_CHANGE") { data in + expect(data["previous_seconds_from_gmt"]) == nil + expect(data["current_seconds_from_gmt"] as? Int64) == 7_200 + } + } func testStopCallsSpecificRemoveObserverMethods() { sut = fixture.getSut(currentDevice: nil) From 1a4da1b80c362d90fcba0e7c5bc6a80d2289d391 Mon Sep 17 00:00:00 2001 From: Philipp Hofmann Date: Wed, 3 Jan 2024 14:19:13 +0100 Subject: [PATCH 25/31] ref: Remove internal init of AppStartMeasurement (#3525) SentryAppStartMeasurement is only plublic for hybrid SDKs since https://github.com/getsentry/sentry-cocoa/pull/2458. Therefore, we can remove the deprecated init method. --- Sources/Sentry/SentryAppStartMeasurement.m | 21 ------------------- .../HybridPublic/SentryAppStartMeasurement.h | 12 ----------- 2 files changed, 33 deletions(-) diff --git a/Sources/Sentry/SentryAppStartMeasurement.m b/Sources/Sentry/SentryAppStartMeasurement.m index cf6a57515ce..6649a250604 100644 --- a/Sources/Sentry/SentryAppStartMeasurement.m +++ b/Sources/Sentry/SentryAppStartMeasurement.m @@ -19,27 +19,6 @@ @implementation SentryAppStartMeasurement } # endif // SENTRY_HAS_UIKIT -- (instancetype)initWithType:(SentryAppStartType)type - appStartTimestamp:(NSDate *)appStartTimestamp - duration:(NSTimeInterval)duration - runtimeInitTimestamp:(NSDate *)runtimeInitTimestamp - didFinishLaunchingTimestamp:(NSDate *)didFinishLaunchingTimestamp -{ -# if SENTRY_HAS_UIKIT - return [self initWithType:type - isPreWarmed:NO - appStartTimestamp:appStartTimestamp - duration:duration - runtimeInitTimestamp:runtimeInitTimestamp - moduleInitializationTimestamp:[NSDate dateWithTimeIntervalSince1970:0] - didFinishLaunchingTimestamp:didFinishLaunchingTimestamp]; -# else - SENTRY_LOG_DEBUG(@"SentryAppStartMeasurement only works with UIKit enabled. Ensure you're " - @"using the right configuration of Sentry that links UIKit."); - return nil; -# endif // SENTRY_HAS_UIKIT -} - - (instancetype)initWithType:(SentryAppStartType)type isPreWarmed:(BOOL)isPreWarmed appStartTimestamp:(NSDate *)appStartTimestamp diff --git a/Sources/Sentry/include/HybridPublic/SentryAppStartMeasurement.h b/Sources/Sentry/include/HybridPublic/SentryAppStartMeasurement.h index 4b4f1725500..68f653b1f68 100644 --- a/Sources/Sentry/include/HybridPublic/SentryAppStartMeasurement.h +++ b/Sources/Sentry/include/HybridPublic/SentryAppStartMeasurement.h @@ -17,18 +17,6 @@ typedef NS_ENUM(NSUInteger, SentryAppStartType) { @interface SentryAppStartMeasurement : NSObject SENTRY_NO_INIT -/** - * Initializes SentryAppStartMeasurement with the given parameters. - */ -- (instancetype)initWithType:(SentryAppStartType)type - appStartTimestamp:(NSDate *)appStartTimestamp - duration:(NSTimeInterval)duration - runtimeInitTimestamp:(NSDate *)runtimeInitTimestamp - didFinishLaunchingTimestamp:(NSDate *)didFinishLaunchingTimestamp - DEPRECATED_MSG_ATTRIBUTE("Use " - "initWithType:appStartTimestamp:duration:mainTimestamp:" - "runtimeInitTimestamp:didFinishLaunchingTimestamp instead."); - /** * Initializes SentryAppStartMeasurement with the given parameters. */ From ce54c6a44f6c432d60721b985c6ddead0917a6ec Mon Sep 17 00:00:00 2001 From: Philipp Hofmann Date: Wed, 3 Jan 2024 16:37:57 +0100 Subject: [PATCH 26/31] fix: App start ends when first frame is drawn (#3530) When performanceV2 is enabled, the app start ends when the app draws the first frame instead of when it receives the UIWindowDidBecomeVisibleNotification. --- CHANGELOG.md | 1 + Samples/iOS-Swift/iOS-Swift/AppDelegate.swift | 1 + Sources/Sentry/Public/SentryOptions.h | 11 ++++++ Sources/Sentry/SentryAppStartTracker.m | 29 +++++++++++++-- .../SentryAppStartTrackingIntegration.m | 4 ++- Sources/Sentry/SentryOptions.m | 4 +++ Sources/Sentry/SentryTracer.m | 3 +- .../HybridPublic/SentryAppStartMeasurement.h | 3 +- .../Sentry/include/SentryAppStartTracker.h | 5 ++- .../SentryAppStartTrackerTests.swift | 36 +++++++++++++++++-- ...ntryAppStartTrackingIntegrationTests.swift | 13 +++++++ Tests/SentryTests/SentryOptionsTest.m | 5 +++ .../Transaction/SentryTracerTests.swift | 29 +++++++++++---- 13 files changed, 130 insertions(+), 14 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index e9afc5b1e68..17dbd896f7a 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -13,6 +13,7 @@ - Fix TTID/TTFD for app start transactions (#3512): TTID/TTFD spans and measurements for app start transaction now include the app start duration. - Crash when adding a crumb for a timezone change (#3524) - Fix a race condition in SentryTracer (#3523) +- App start ends when first frame is drawn when performanceV2 is enabled (#3530) - Missing transactions when not calling `reportFullyDisplayed` (#3477) ## 8.17.2 diff --git a/Samples/iOS-Swift/iOS-Swift/AppDelegate.swift b/Samples/iOS-Swift/iOS-Swift/AppDelegate.swift index cc03cd4b789..9e530c19463 100644 --- a/Samples/iOS-Swift/iOS-Swift/AppDelegate.swift +++ b/Samples/iOS-Swift/iOS-Swift/AppDelegate.swift @@ -31,6 +31,7 @@ class AppDelegate: UIResponder, UIApplicationDelegate { options.attachViewHierarchy = true options.environment = "test-app" options.enableTimeToFullDisplayTracing = true + options.enablePerformanceV2 = true options.add(inAppInclude: "iOS_External") diff --git a/Sources/Sentry/Public/SentryOptions.h b/Sources/Sentry/Public/SentryOptions.h index cff7cab25a0..cc41bbe850d 100644 --- a/Sources/Sentry/Public/SentryOptions.h +++ b/Sources/Sentry/Public/SentryOptions.h @@ -191,6 +191,17 @@ NS_SWIFT_NAME(Options) */ @property (nonatomic, assign) BOOL enableAutoPerformanceTracing; +/** + * @warning This is an experimental feature and may still have bugs. + * + * Sentry works on reworking the whole performance offering with the code Mobile Starfish, which + * aims to provide better insights into the performance of mobile apps and highlight clear actions + * to improve app performance to developers. This feature flag enables experimental features that + * impact the v1 performance offering and would require a major version update. Sentry aims to + * include most features in the next major by default. + */ +@property (nonatomic, assign) BOOL enablePerformanceV2; + /** * A block that configures the initial scope when starting the SDK. * @discussion The block receives a suggested default scope. You can either diff --git a/Sources/Sentry/SentryAppStartTracker.m b/Sources/Sentry/SentryAppStartTracker.m index aa0e6ea06e8..68123690f5c 100644 --- a/Sources/Sentry/SentryAppStartTracker.m +++ b/Sources/Sentry/SentryAppStartTracker.m @@ -5,6 +5,7 @@ # import "SentryAppStartMeasurement.h" # import "SentryAppStateManager.h" # import "SentryDefines.h" +# import "SentryFramesTracker.h" # import "SentryLog.h" # import "SentrySysctl.h" # import @@ -28,14 +29,16 @@ static const NSTimeInterval SENTRY_APP_START_MAX_DURATION = 180.0; @interface -SentryAppStartTracker () +SentryAppStartTracker () @property (nonatomic, strong) SentryAppState *previousAppState; @property (nonatomic, strong) SentryDispatchQueueWrapper *dispatchQueue; @property (nonatomic, strong) SentryAppStateManager *appStateManager; +@property (nonatomic, strong) SentryFramesTracker *framesTracker; @property (nonatomic, assign) BOOL wasInBackground; @property (nonatomic, strong) NSDate *didFinishLaunchingTimestamp; @property (nonatomic, assign) BOOL enablePreWarmedAppStartTracing; +@property (nonatomic, assign) BOOL enablePerformanceV2; @end @@ -55,11 +58,19 @@ + (void)load - (instancetype)initWithDispatchQueueWrapper:(SentryDispatchQueueWrapper *)dispatchQueueWrapper appStateManager:(SentryAppStateManager *)appStateManager + framesTracker:(SentryFramesTracker *)framesTracker enablePreWarmedAppStartTracing:(BOOL)enablePreWarmedAppStartTracing + enablePerformanceV2:(BOOL)enablePerformanceV2 { if (self = [super init]) { self.dispatchQueue = dispatchQueueWrapper; self.appStateManager = appStateManager; + _enablePerformanceV2 = enablePerformanceV2; + if (_enablePerformanceV2) { + self.framesTracker = framesTracker; + [framesTracker addListener:self]; + } + self.previousAppState = [self.appStateManager loadPreviousAppState]; self.wasInBackground = NO; self.didFinishLaunchingTimestamp = @@ -222,9 +233,21 @@ - (void)buildAppStartMeasurement } /** - * This is when the first frame is drawn. + * This is when the window becomes visible, which is not when the first frame of the app is drawn. + * When this is posted, the app screen is usually white. The correct time when the first frame is + * drawn is called in framesTrackerHasNewFrame only when `enablePerformanceV2` is enabled. */ - (void)didBecomeVisible +{ + if (!_enablePerformanceV2) { + [self buildAppStartMeasurement]; + } +} + +/** + * This is when the first frame is drawn. + */ +- (void)framesTrackerHasNewFrame { [self buildAppStartMeasurement]; } @@ -288,6 +311,8 @@ - (void)stop name:UIApplicationDidEnterBackgroundNotification object:nil]; + [self.framesTracker removeListener:self]; + # if TEST self.isRunning = NO; # endif diff --git a/Sources/Sentry/SentryAppStartTrackingIntegration.m b/Sources/Sentry/SentryAppStartTrackingIntegration.m index 4daec01180a..bb974f8158c 100644 --- a/Sources/Sentry/SentryAppStartTrackingIntegration.m +++ b/Sources/Sentry/SentryAppStartTrackingIntegration.m @@ -33,7 +33,9 @@ - (BOOL)installWithOptions:(SentryOptions *)options self.tracker = [[SentryAppStartTracker alloc] initWithDispatchQueueWrapper:[[SentryDispatchQueueWrapper alloc] init] appStateManager:appStateManager - enablePreWarmedAppStartTracing:options.enablePreWarmedAppStartTracing]; + framesTracker:SentryDependencyContainer.sharedInstance.framesTracker + enablePreWarmedAppStartTracing:options.enablePreWarmedAppStartTracing + enablePerformanceV2:options.enablePerformanceV2]; [self.tracker start]; return YES; diff --git a/Sources/Sentry/SentryOptions.m b/Sources/Sentry/SentryOptions.m index cfb4d840442..5e82d64566b 100644 --- a/Sources/Sentry/SentryOptions.m +++ b/Sources/Sentry/SentryOptions.m @@ -105,6 +105,7 @@ - (instancetype)init self.maxAttachmentSize = 20 * 1024 * 1024; self.sendDefaultPii = NO; self.enableAutoPerformanceTracing = YES; + self.enablePerformanceV2 = NO; self.enableCaptureFailedRequests = YES; self.environment = kSentryDefaultEnvironment; self.enableTimeToFullDisplayTracing = NO; @@ -375,6 +376,9 @@ - (BOOL)validateOptions:(NSDictionary *)options [self setBool:options[@"enableAutoPerformanceTracing"] block:^(BOOL value) { self->_enableAutoPerformanceTracing = value; }]; + [self setBool:options[@"enablePerformanceV2"] + block:^(BOOL value) { self->_enablePerformanceV2 = value; }]; + [self setBool:options[@"enableCaptureFailedRequests"] block:^(BOOL value) { self->_enableCaptureFailedRequests = value; }]; diff --git a/Sources/Sentry/SentryTracer.m b/Sources/Sentry/SentryTracer.m index 5a33a615d4b..aea8a1d8a53 100644 --- a/Sources/Sentry/SentryTracer.m +++ b/Sources/Sentry/SentryTracer.m @@ -147,7 +147,6 @@ - (instancetype)initWithTransactionContext:(SentryTransactionContext *)transacti } #if SENTRY_HAS_UIKIT - appStartMeasurement = [self getAppStartMeasurement]; viewNames = [SentryDependencyContainer.sharedInstance.application relevantViewControllersNames]; #endif // SENTRY_HAS_UIKIT @@ -501,6 +500,8 @@ - (void)finishInternal [super finishWithStatus:_finishStatus]; } #if SENTRY_HAS_UIKIT + appStartMeasurement = [self getAppStartMeasurement]; + if (appStartMeasurement != nil) { [self updateStartTime:appStartMeasurement.appStartTimestamp]; } diff --git a/Sources/Sentry/include/HybridPublic/SentryAppStartMeasurement.h b/Sources/Sentry/include/HybridPublic/SentryAppStartMeasurement.h index 68f653b1f68..f48cdd5f370 100644 --- a/Sources/Sentry/include/HybridPublic/SentryAppStartMeasurement.h +++ b/Sources/Sentry/include/HybridPublic/SentryAppStartMeasurement.h @@ -37,7 +37,8 @@ SENTRY_NO_INIT /** * How long the app start took. From appStartTimestamp to when the SDK creates the - * AppStartMeasurement, which is done when the OS posts UIWindowDidBecomeVisibleNotification. + * AppStartMeasurement, which is done when the OS posts UIWindowDidBecomeVisibleNotification and + * when `enablePerformanceV2` is enabled when the app draws it's first frame. */ @property (readonly, nonatomic, assign) NSTimeInterval duration; diff --git a/Sources/Sentry/include/SentryAppStartTracker.h b/Sources/Sentry/include/SentryAppStartTracker.h index b853873167c..f981c2733a7 100644 --- a/Sources/Sentry/include/SentryAppStartTracker.h +++ b/Sources/Sentry/include/SentryAppStartTracker.h @@ -6,6 +6,7 @@ @class SentryDispatchQueueWrapper; @class SentryAppStateManager; +@class SentryFramesTracker; NS_ASSUME_NONNULL_BEGIN @@ -22,7 +23,9 @@ SENTRY_NO_INIT - (instancetype)initWithDispatchQueueWrapper:(SentryDispatchQueueWrapper *)dispatchQueueWrapper appStateManager:(SentryAppStateManager *)appStateManager - enablePreWarmedAppStartTracing:(BOOL)enablePreWarmedAppStartTracing; + framesTracker:(SentryFramesTracker *)framesTracker + enablePreWarmedAppStartTracing:(BOOL)enablePreWarmedAppStartTracing + enablePerformanceV2:(BOOL)enablePerformanceV2; - (void)start; - (void)stop; diff --git a/Tests/SentryTests/Integrations/Performance/AppStartTracking/SentryAppStartTrackerTests.swift b/Tests/SentryTests/Integrations/Performance/AppStartTracking/SentryAppStartTrackerTests.swift index b3f78aa6711..d50556001db 100644 --- a/Tests/SentryTests/Integrations/Performance/AppStartTracking/SentryAppStartTrackerTests.swift +++ b/Tests/SentryTests/Integrations/Performance/AppStartTracking/SentryAppStartTrackerTests.swift @@ -1,3 +1,4 @@ +import Nimble import SentryTestUtils import XCTest @@ -14,8 +15,11 @@ class SentryAppStartTrackerTests: NotificationCenterTestCase { let fileManager: SentryFileManager let crashWrapper = TestSentryCrashWrapper.sharedInstance() let appStateManager: SentryAppStateManager + var displayLinkWrapper = TestDisplayLinkWrapper() + var framesTracker: SentryFramesTracker let dispatchQueue = TestSentryDispatchQueueWrapper() var enablePreWarmedAppStartTracing = true + var enablePerformanceV2 = false let appStartDuration: TimeInterval = 0.4 var runtimeInitTimestamp: Date @@ -41,6 +45,10 @@ class SentryAppStartTrackerTests: NotificationCenterTestCase { notificationCenterWrapper: SentryNSNotificationCenterWrapper() ) + framesTracker = SentryFramesTracker(displayLinkWrapper: displayLinkWrapper, dateProvider: currentDate, keepDelayedFramesDuration: 0) + SentryDependencyContainer.sharedInstance().framesTracker = framesTracker + framesTracker.start() + runtimeInitTimestamp = SentryDependencyContainer.sharedInstance().dateProvider.date().addingTimeInterval(0.2) moduleInitializationTimestamp = SentryDependencyContainer.sharedInstance().dateProvider.date().addingTimeInterval(0.1) didFinishLaunchingTimestamp = SentryDependencyContainer.sharedInstance().dateProvider.date().addingTimeInterval(0.3) @@ -50,7 +58,9 @@ class SentryAppStartTrackerTests: NotificationCenterTestCase { let sut = SentryAppStartTracker( dispatchQueueWrapper: TestSentryDispatchQueueWrapper(), appStateManager: appStateManager, - enablePreWarmedAppStartTracing: enablePreWarmedAppStartTracing + framesTracker: framesTracker, + enablePreWarmedAppStartTracing: enablePreWarmedAppStartTracing, + enablePerformanceV2: enablePerformanceV2 ) return sut } @@ -80,6 +90,25 @@ class SentryAppStartTrackerTests: NotificationCenterTestCase { assertValidStart(type: .cold) } + func testPerformanceV2_UsesRenderedFrameAsEndTimeStamp() { + fixture.enablePerformanceV2 = true + + startApp() + + assertValidStart(type: .cold, expectedDuration: 0.45) + } + + func testPerformanceV2_RemovesFramesTrackerListener() { + fixture.enablePerformanceV2 = true + + startApp() + + advanceTime(bySeconds: 0.05) + fixture.displayLinkWrapper.normalFrame() + + assertValidStart(type: .cold, expectedDuration: 0.45) + } + func testSecondStart_AfterSystemReboot_IsColdStart() { let previousBootTime = SentryDependencyContainer.sharedInstance().dateProvider.date().addingTimeInterval(-1) let appState = SentryAppState(releaseName: TestData.appState.releaseName, osVersion: UIDevice.current.systemVersion, vendorId: TestData.someUUID, isDebugging: false, systemBootTimestamp: previousBootTime) @@ -345,6 +374,9 @@ class SentryAppStartTrackerTests: NotificationCenterTestCase { advanceTime(bySeconds: 0.1) uiWindowDidBecomeVisible() didBecomeActive() + + advanceTime(bySeconds: 0.05) + fixture.displayLinkWrapper.normalFrame() } private func hybridAppStart() { @@ -397,7 +429,7 @@ class SentryAppStartTrackerTests: NotificationCenterTestCase { let expectedAppStartDuration = expectedDuration ?? fixture.appStartDuration let actualAppStartDuration = appStartMeasurement.duration - XCTAssertEqual(expectedAppStartDuration, actualAppStartDuration, accuracy: 0.0001) + expect(actualAppStartDuration).to(beCloseTo(expectedAppStartDuration, within: 0.0001)) if preWarmed { XCTAssertEqual(fixture.moduleInitializationTimestamp, appStartMeasurement.appStartTimestamp) diff --git a/Tests/SentryTests/Integrations/Performance/AppStartTracking/SentryAppStartTrackingIntegrationTests.swift b/Tests/SentryTests/Integrations/Performance/AppStartTracking/SentryAppStartTrackingIntegrationTests.swift index 70ba3054495..355062281e8 100644 --- a/Tests/SentryTests/Integrations/Performance/AppStartTracking/SentryAppStartTrackingIntegrationTests.swift +++ b/Tests/SentryTests/Integrations/Performance/AppStartTracking/SentryAppStartTrackingIntegrationTests.swift @@ -1,3 +1,4 @@ +import Nimble import SentryTestUtils import XCTest @@ -108,9 +109,21 @@ class SentryAppStartTrackingIntegrationTests: NotificationCenterTestCase { XCTAssertFalse(result) } + + func test_PerformanceV2Enabled() { + let options = fixture.options + options.enablePerformanceV2 = true + + expect(self.sut.install(with: options)) == true + + let tracker = Dynamic(sut).tracker.asAnyObject as? SentryAppStartTracker + expect(Dynamic(tracker).enablePerformanceV2.asBool) == true + } func assertTrackerSetupAndRunning(_ tracker: SentryAppStartTracker) throws { _ = try XCTUnwrap(Dynamic(tracker).dispatchQueue.asAnyObject as? SentryDispatchQueueWrapper, "Tracker does not have a dispatch queue.") + + expect(Dynamic(tracker).enablePerformanceV2.asBool) == false let appStateManager = Dynamic(tracker).appStateManager.asObject as? SentryAppStateManager diff --git a/Tests/SentryTests/SentryOptionsTest.m b/Tests/SentryTests/SentryOptionsTest.m index 6d90438e6b8..28503dddf6f 100644 --- a/Tests/SentryTests/SentryOptionsTest.m +++ b/Tests/SentryTests/SentryOptionsTest.m @@ -726,6 +726,11 @@ - (void)testEnableAutoPerformanceTracing [self testBooleanField:@"enableAutoPerformanceTracing"]; } +- (void)testEnablePerformanceV2 +{ + [self testBooleanField:@"enablePerformanceV2" defaultValue:NO]; +} + #if SENTRY_HAS_UIKIT - (void)testEnableUIViewControllerTracing { diff --git a/Tests/SentryTests/Transaction/SentryTracerTests.swift b/Tests/SentryTests/Transaction/SentryTracerTests.swift index 9d78a6fa0ef..2ab9f8b2e98 100644 --- a/Tests/SentryTests/Transaction/SentryTracerTests.swift +++ b/Tests/SentryTests/Transaction/SentryTracerTests.swift @@ -714,8 +714,23 @@ class SentryTracerTests: XCTestCase { assertAppStartMeasurementOn(transaction: fixture.hub.capturedEventsWithScopes.first!.event as! Transaction, appStartMeasurement: appStartMeasurement) } + + func testAddAppStartMeasurementWhileTransactionRunning_PutOnNextAutoUITransaction() { + let appStartMeasurement = fixture.getAppStartMeasurement(type: .warm) + + advanceTime(bySeconds: -(fixture.appStartDuration + 4)) + + let sut = fixture.getSut() + advanceTime(bySeconds: 1) + SentrySDK.setAppStartMeasurement(appStartMeasurement) + sut.finish() + + expect(self.fixture.hub.capturedEventsWithScopes.count) == 1 - func testAddColdStartMeasurement_PutOnFirstStartedTransaction() { + assertAppStartMeasurementOn(transaction: fixture.hub.capturedEventsWithScopes.first!.event as! Transaction, appStartMeasurement: appStartMeasurement) + } + + func testAddAppStartMeasurement_PutOnFirstFinishedAutoUITransaction() { let appStartMeasurement = fixture.getAppStartMeasurement(type: .warm) SentrySDK.setAppStartMeasurement(appStartMeasurement) @@ -728,14 +743,16 @@ class SentryTracerTests: XCTestCase { advanceTime(bySeconds: 0.5) secondTransaction.finish() - XCTAssertEqual(1, fixture.hub.capturedEventsWithScopes.count) - let serializedSecondTransaction = fixture.hub.capturedEventsWithScopes.first!.event.serialize() - XCTAssertNil(serializedSecondTransaction["measurements"]) + expect(self.fixture.hub.capturedEventsWithScopes.count) == 1 firstTransaction.finish() - XCTAssertEqual(2, fixture.hub.capturedEventsWithScopes.count) - assertAppStartMeasurementOn(transaction: fixture.hub.capturedEventsWithScopes.invocations[1].event as! Transaction, appStartMeasurement: appStartMeasurement) + expect(self.fixture.hub.capturedEventsWithScopes.count) == 2 + + let serializedFirstTransaction = fixture.hub.capturedEventsWithScopes.invocations[1].event.serialize() + expect(serializedFirstTransaction["measurements"]) == nil + + assertAppStartMeasurementOn(transaction: fixture.hub.capturedEventsWithScopes.invocations[0].event as! Transaction, appStartMeasurement: appStartMeasurement) } func testAddUnknownAppStartMeasurement_NotPutOnNextTransaction() { From f74904fa87218947c77c10540d685d25a43a1dd1 Mon Sep 17 00:00:00 2001 From: Philipp Hofmann Date: Thu, 4 Jan 2024 09:29:05 +0100 Subject: [PATCH 27/31] fix: Use correct rendered frames timestamp (#3531) Use the timestamp of the DisplayLink wrapper when a new frame is reported for TTID/TTFD and the app start. --- CHANGELOG.md | 2 ++ SentryTestUtils/TestCurrentDateProvider.swift | 3 +- Sources/Sentry/SentryAppStartTracker.m | 19 ++++++------ Sources/Sentry/SentryFramesTracker.m | 4 ++- Sources/Sentry/SentryTimeToDisplayTracker.m | 9 ++---- Sources/Sentry/include/SentryFramesTracker.h | 2 +- .../SentryAppStartTrackerTests.swift | 17 ++++++----- .../SentryFramesTrackerTests.swift | 29 +++++++++++++------ 8 files changed, 51 insertions(+), 34 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 17dbd896f7a..37fe9b0bd9b 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -14,6 +14,8 @@ - Crash when adding a crumb for a timezone change (#3524) - Fix a race condition in SentryTracer (#3523) - App start ends when first frame is drawn when performanceV2 is enabled (#3530) +- Use correct rendered frames timestamp for TTID/TTFD and app start (#3531) + - Missing transactions when not calling `reportFullyDisplayed` (#3477) ## 8.17.2 diff --git a/SentryTestUtils/TestCurrentDateProvider.swift b/SentryTestUtils/TestCurrentDateProvider.swift index 599f5a0f599..a8c193dbf2f 100644 --- a/SentryTestUtils/TestCurrentDateProvider.swift +++ b/SentryTestUtils/TestCurrentDateProvider.swift @@ -6,12 +6,13 @@ public class TestCurrentDateProvider: CurrentDateProvider { private var internalDate = defaultStartingDate private var internalSystemTime: UInt64 = 0 public var driftTimeForEveryRead = false + public var driftTimeInterval = 0.1 public override func date() -> Date { defer { if driftTimeForEveryRead { - internalDate = internalDate.addingTimeInterval(0.1) + internalDate = internalDate.addingTimeInterval(driftTimeInterval) } } diff --git a/Sources/Sentry/SentryAppStartTracker.m b/Sources/Sentry/SentryAppStartTracker.m index 68123690f5c..2786ad66b14 100644 --- a/Sources/Sentry/SentryAppStartTracker.m +++ b/Sources/Sentry/SentryAppStartTracker.m @@ -120,7 +120,8 @@ - (void)start object:nil]; if (PrivateSentrySDKOnly.appStartMeasurementHybridSDKMode) { - [self buildAppStartMeasurement]; + [self + buildAppStartMeasurement:[SentryDependencyContainer.sharedInstance.dateProvider date]]; } # if SENTRY_HAS_UIKIT @@ -130,7 +131,7 @@ - (void)start self.isRunning = YES; } -- (void)buildAppStartMeasurement +- (void)buildAppStartMeasurement:(NSDate *)appStartEnd { void (^block)(void) = ^(void) { [self stop]; @@ -181,12 +182,11 @@ - (void)buildAppStartMeasurement NSDate *appStartTimestamp; SentrySysctl *sysctl = SentryDependencyContainer.sharedInstance.sysctlWrapper; if (isPreWarmed) { - appStartDuration = [[SentryDependencyContainer.sharedInstance.dateProvider date] - timeIntervalSinceDate:sysctl.moduleInitializationTimestamp]; + appStartDuration = + [appStartEnd timeIntervalSinceDate:sysctl.moduleInitializationTimestamp]; appStartTimestamp = sysctl.moduleInitializationTimestamp; } else { - appStartDuration = [[SentryDependencyContainer.sharedInstance.dateProvider date] - timeIntervalSinceDate:sysctl.processStartTimestamp]; + appStartDuration = [appStartEnd timeIntervalSinceDate:sysctl.processStartTimestamp]; appStartTimestamp = sysctl.processStartTimestamp; } @@ -240,16 +240,17 @@ - (void)buildAppStartMeasurement - (void)didBecomeVisible { if (!_enablePerformanceV2) { - [self buildAppStartMeasurement]; + [self + buildAppStartMeasurement:[SentryDependencyContainer.sharedInstance.dateProvider date]]; } } /** * This is when the first frame is drawn. */ -- (void)framesTrackerHasNewFrame +- (void)framesTrackerHasNewFrame:(NSDate *)newFrameDate { - [self buildAppStartMeasurement]; + [self buildAppStartMeasurement:newFrameDate]; } - (SentryAppStartType)getStartType diff --git a/Sources/Sentry/SentryFramesTracker.m b/Sources/Sentry/SentryFramesTracker.m index 0381bc0ca82..43cf20b1238 100644 --- a/Sources/Sentry/SentryFramesTracker.m +++ b/Sources/Sentry/SentryFramesTracker.m @@ -200,8 +200,10 @@ - (void)reportNewFrame localListeners = [self.listeners allObjects]; } + NSDate *newFrameDate = [self.dateProvider date]; + for (id listener in localListeners) { - [listener framesTrackerHasNewFrame]; + [listener framesTrackerHasNewFrame:newFrameDate]; } } diff --git a/Sources/Sentry/SentryTimeToDisplayTracker.m b/Sources/Sentry/SentryTimeToDisplayTracker.m index 4b9b21569f1..89a6be2b44c 100644 --- a/Sources/Sentry/SentryTimeToDisplayTracker.m +++ b/Sources/Sentry/SentryTimeToDisplayTracker.m @@ -2,7 +2,6 @@ #if SENTRY_HAS_UIKIT -# import "SentryCurrentDateProvider.h" # import "SentryDependencyContainer.h" # import "SentryFramesTracker.h" # import "SentryMeasurementValue.h" @@ -99,15 +98,13 @@ - (void)reportFullyDisplayed _fullyDisplayedReported = YES; } -- (void)framesTrackerHasNewFrame +- (void)framesTrackerHasNewFrame:(NSDate *)newFrameDate { - NSDate *finishTime = [SentryDependencyContainer.sharedInstance.dateProvider date]; - // The purpose of TTID and TTFD is to measure how long // takes to the content of the screen to change. // Thats why we need to wait for the next frame to be drawn. if (_initialDisplayReported && self.initialDisplaySpan.isFinished == NO) { - self.initialDisplaySpan.timestamp = finishTime; + self.initialDisplaySpan.timestamp = newFrameDate; [self.initialDisplaySpan finish]; @@ -117,7 +114,7 @@ - (void)framesTrackerHasNewFrame } if (_waitForFullDisplay && _fullyDisplayedReported && self.fullDisplaySpan.isFinished == NO && self.initialDisplaySpan.isFinished == YES) { - self.fullDisplaySpan.timestamp = finishTime; + self.fullDisplaySpan.timestamp = newFrameDate; [self.fullDisplaySpan finish]; } diff --git a/Sources/Sentry/include/SentryFramesTracker.h b/Sources/Sentry/include/SentryFramesTracker.h index 1e13b2ae63f..56f139d55b3 100644 --- a/Sources/Sentry/include/SentryFramesTracker.h +++ b/Sources/Sentry/include/SentryFramesTracker.h @@ -13,7 +13,7 @@ NS_ASSUME_NONNULL_BEGIN @protocol SentryFramesTrackerListener -- (void)framesTrackerHasNewFrame; +- (void)framesTrackerHasNewFrame:(NSDate *)newFrameDate; @end diff --git a/Tests/SentryTests/Integrations/Performance/AppStartTracking/SentryAppStartTrackerTests.swift b/Tests/SentryTests/Integrations/Performance/AppStartTracking/SentryAppStartTrackerTests.swift index d50556001db..8e4bd5d73e9 100644 --- a/Tests/SentryTests/Integrations/Performance/AppStartTracking/SentryAppStartTrackerTests.swift +++ b/Tests/SentryTests/Integrations/Performance/AppStartTracking/SentryAppStartTrackerTests.swift @@ -16,7 +16,7 @@ class SentryAppStartTrackerTests: NotificationCenterTestCase { let crashWrapper = TestSentryCrashWrapper.sharedInstance() let appStateManager: SentryAppStateManager var displayLinkWrapper = TestDisplayLinkWrapper() - var framesTracker: SentryFramesTracker + private let framesTracker: SentryFramesTracker let dispatchQueue = TestSentryDispatchQueueWrapper() var enablePreWarmedAppStartTracing = true var enablePerformanceV2 = false @@ -46,7 +46,6 @@ class SentryAppStartTrackerTests: NotificationCenterTestCase { ) framesTracker = SentryFramesTracker(displayLinkWrapper: displayLinkWrapper, dateProvider: currentDate, keepDelayedFramesDuration: 0) - SentryDependencyContainer.sharedInstance().framesTracker = framesTracker framesTracker.start() runtimeInitTimestamp = SentryDependencyContainer.sharedInstance().dateProvider.date().addingTimeInterval(0.2) @@ -93,7 +92,7 @@ class SentryAppStartTrackerTests: NotificationCenterTestCase { func testPerformanceV2_UsesRenderedFrameAsEndTimeStamp() { fixture.enablePerformanceV2 = true - startApp() + startApp(callDisplayLink: true) assertValidStart(type: .cold, expectedDuration: 0.45) } @@ -101,7 +100,7 @@ class SentryAppStartTrackerTests: NotificationCenterTestCase { func testPerformanceV2_RemovesFramesTrackerListener() { fixture.enablePerformanceV2 = true - startApp() + startApp(callDisplayLink: true) advanceTime(bySeconds: 0.05) fixture.displayLinkWrapper.normalFrame() @@ -358,7 +357,7 @@ class SentryAppStartTrackerTests: NotificationCenterTestCase { advanceTime(bySeconds: 0.3) } - private func startApp(processStartTimeStamp: Date? = nil, runtimeInitTimestamp: Date? = nil, moduleInitializationTimestamp: Date? = nil) { + private func startApp(processStartTimeStamp: Date? = nil, runtimeInitTimestamp: Date? = nil, moduleInitializationTimestamp: Date? = nil, callDisplayLink: Bool = false) { givenProcessStartTimestamp(processStartTimestamp: processStartTimeStamp) sut = fixture.sut @@ -375,8 +374,12 @@ class SentryAppStartTrackerTests: NotificationCenterTestCase { uiWindowDidBecomeVisible() didBecomeActive() - advanceTime(bySeconds: 0.05) - fixture.displayLinkWrapper.normalFrame() + if callDisplayLink { + advanceTime(bySeconds: 0.05) + fixture.currentDate.driftTimeForEveryRead = true + fixture.displayLinkWrapper.normalFrame() + fixture.currentDate.driftTimeForEveryRead = false + } } private func hybridAppStart() { diff --git a/Tests/SentryTests/Integrations/Performance/FramesTracking/SentryFramesTrackerTests.swift b/Tests/SentryTests/Integrations/Performance/FramesTracking/SentryFramesTrackerTests.swift index 34acd569783..499e0ad2cec 100644 --- a/Tests/SentryTests/Integrations/Performance/FramesTracking/SentryFramesTrackerTests.swift +++ b/Tests/SentryTests/Integrations/Performance/FramesTracking/SentryFramesTrackerTests.swift @@ -517,16 +517,26 @@ class SentryFramesTrackerTests: XCTestCase { wait(for: [expectation], timeout: 3.0) } - - func testAddListener() { + + func testAddMultipleListeners_AllCalledWithSameDate() { let sut = fixture.sut - let listener = FrameTrackerListener() + let listener1 = FrameTrackerListener() + let listener2 = FrameTrackerListener() sut.start() - sut.add(listener) + sut.add(listener1) + sut.add(listener2) + + fixture.dateProvider.driftTimeForEveryRead = true fixture.displayLinkWrapper.normalFrame() + var expectedFrameDate = fixture.dateProvider.date() + expectedFrameDate.addTimeInterval(-fixture.dateProvider.driftTimeInterval) - XCTAssertTrue(listener.newFrameReported) + expect(listener1.newFrameInvocations.count) == 1 + expect(listener1.newFrameInvocations.first?.timeIntervalSince1970) == expectedFrameDate.timeIntervalSince1970 + + expect(listener2.newFrameInvocations.count) == 1 + expect(listener2.newFrameInvocations.first?.timeIntervalSince1970) == expectedFrameDate.timeIntervalSince1970 } func testRemoveListener() { @@ -538,7 +548,7 @@ class SentryFramesTrackerTests: XCTestCase { fixture.displayLinkWrapper.normalFrame() - XCTAssertFalse(listener.newFrameReported) + expect(listener.newFrameInvocations.count) == 0 } func testReleasedListener() { @@ -594,10 +604,11 @@ class SentryFramesTrackerTests: XCTestCase { } private class FrameTrackerListener: NSObject, SentryFramesTrackerListener { - var newFrameReported = false + + var newFrameInvocations = Invocations() var callback: (() -> Void)? - func framesTrackerHasNewFrame() { - newFrameReported = true + func framesTrackerHasNewFrame(_ newFrameDate: Date) { + newFrameInvocations.record(newFrameDate) callback?() } } From fa38a2bcd9bdcf8c26bc0ec7b9539e1969f3e711 Mon Sep 17 00:00:00 2001 From: Philipp Hofmann Date: Thu, 4 Jan 2024 14:03:42 +0100 Subject: [PATCH 28/31] feat: Prewarmed App Start Tracing is stable (#3536) Make the option enablePreWarmedAppStartTracing stable. --- CHANGELOG.md | 1 + Sources/Sentry/Public/SentryOptions.h | 5 +++-- 2 files changed, 4 insertions(+), 2 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 37fe9b0bd9b..c2bff563910 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -6,6 +6,7 @@ - Add frames delay to transactions and spans (#3487, #3496) - Add slow and frozen frames to spans (#3450, #3478) +- Prewarmed App Start Tracing is stable (#3536) ### Fixes diff --git a/Sources/Sentry/Public/SentryOptions.h b/Sources/Sentry/Public/SentryOptions.h index cc41bbe850d..c7714a631ae 100644 --- a/Sources/Sentry/Public/SentryOptions.h +++ b/Sources/Sentry/Public/SentryOptions.h @@ -254,11 +254,12 @@ NS_SWIFT_NAME(Options) * @note The default is 3 seconds. */ @property (nonatomic, assign) NSTimeInterval idleTimeout; + /** - * @warning This is an experimental feature and may still have bugs. - * @brief Report pre-warmed app starts by dropping the first app start spans if pre-warming paused + * Report pre-warmed app starts by dropping the first app start spans if pre-warming paused * during these steps. This approach will shorten the app start duration, but it represents the * duration a user has to wait after clicking the app icon until the app is responsive. + * * @note You can filter for different app start types in Discover with * @c app_start_type:cold.prewarmed , * @c app_start_type:warm.prewarmed , @c app_start_type:cold , and @c app_start_type:warm . From 4603c54a5b6130015fda309d0098634eb36b7881 Mon Sep 17 00:00:00 2001 From: Philipp Hofmann Date: Thu, 4 Jan 2024 14:04:09 +0100 Subject: [PATCH 29/31] ci: Cancel in progress workflows for PRs (#3537) Cancel in progress workflow runs when pushing new commits to a PR to save CI computing time. Fixes GH-3213 --- .github/workflows/benchmarking.yml | 5 +++++ .github/workflows/build.yml | 5 +++++ .github/workflows/codeql-analysis.yml | 5 +++++ .github/workflows/lint.yml | 5 +++++ .github/workflows/saucelabs-UI-tests.yml | 5 +++++ .github/workflows/test.yml | 5 +++++ 6 files changed, 30 insertions(+) diff --git a/.github/workflows/benchmarking.yml b/.github/workflows/benchmarking.yml index 4d521f24608..fbd5f187e8b 100644 --- a/.github/workflows/benchmarking.yml +++ b/.github/workflows/benchmarking.yml @@ -20,6 +20,11 @@ on: - 'scripts/ci-select-xcode.sh' - 'scripts/set-device-tests-environment.patch' +# https://docs.github.com/en/actions/using-jobs/using-concurrency#example-using-a-fallback-value +concurrency: + group: ${{ github.workflow }}-${{ github.head_ref || github.run_id }} + cancel-in-progress: true + jobs: build-benchmark-test-target: name: Build app and test runner diff --git a/.github/workflows/build.yml b/.github/workflows/build.yml index 0d078f9caee..e95a91e2734 100644 --- a/.github/workflows/build.yml +++ b/.github/workflows/build.yml @@ -18,6 +18,11 @@ on: - Gemfile.lock - 'Package.swift' +# https://docs.github.com/en/actions/using-jobs/using-concurrency#example-using-a-fallback-value +concurrency: + group: ${{ github.workflow }}-${{ github.head_ref || github.run_id }} + cancel-in-progress: true + jobs: # We had issues that the release build was broken on main. # With this we catch potential issues already in the PR. diff --git a/.github/workflows/codeql-analysis.yml b/.github/workflows/codeql-analysis.yml index 0c962d348a0..c7a436b3b31 100644 --- a/.github/workflows/codeql-analysis.yml +++ b/.github/workflows/codeql-analysis.yml @@ -9,6 +9,11 @@ on: schedule: - cron: '40 4 * * 6' +# https://docs.github.com/en/actions/using-jobs/using-concurrency#example-using-a-fallback-value +concurrency: + group: ${{ github.workflow }}-${{ github.head_ref || github.run_id }} + cancel-in-progress: true + jobs: analyze: name: Analyze diff --git a/.github/workflows/lint.yml b/.github/workflows/lint.yml index 75cb1490985..9ec0e534916 100644 --- a/.github/workflows/lint.yml +++ b/.github/workflows/lint.yml @@ -24,6 +24,11 @@ on: - 'Sentry.xcodeproj/**' - '*.podspec' +# https://docs.github.com/en/actions/using-jobs/using-concurrency#example-using-a-fallback-value +concurrency: + group: ${{ github.workflow }}-${{ github.head_ref || github.run_id }} + cancel-in-progress: true + jobs: swift-lint: name: Swift Lint diff --git a/.github/workflows/saucelabs-UI-tests.yml b/.github/workflows/saucelabs-UI-tests.yml index 11c1d8681bf..956304b866a 100644 --- a/.github/workflows/saucelabs-UI-tests.yml +++ b/.github/workflows/saucelabs-UI-tests.yml @@ -18,6 +18,11 @@ on: - 'Samples/iOS-Swift/iOS-Swift.xcodeproj/xcshareddata/xcschemes/iOS-SwiftUITests.xcscheme' - 'Samples/iOS-Swift/iOS-Swift.xcodeproj/xcshareddata/xcschemes/iOS-Swift.xcscheme' +# https://docs.github.com/en/actions/using-jobs/using-concurrency#example-using-a-fallback-value +concurrency: + group: ${{ github.workflow }}-${{ github.head_ref || github.run_id }} + cancel-in-progress: true + jobs: build-ui-tests: name: Build UITests diff --git a/.github/workflows/test.yml b/.github/workflows/test.yml index 186fe020892..75b0d58cca1 100644 --- a/.github/workflows/test.yml +++ b/.github/workflows/test.yml @@ -28,6 +28,11 @@ on: - "Samples/macOS-Swift/macOS-Swift.xcodeproj/xcshareddata/xcschemes/macOS-Swift.xcscheme" - "Samples/iOS-ObjectiveC/iOS-ObjectiveC.xcodeproj/xcshareddata/xcschemes/iOS-ObjectiveC.xcscheme" +# https://docs.github.com/en/actions/using-jobs/using-concurrency#example-using-a-fallback-value +concurrency: + group: ${{ github.workflow }}-${{ github.head_ref || github.run_id }} + cancel-in-progress: true + jobs: build-test-server: name: Build test server From 2f9c5f9dbd28d6d171efd250c25c2aeca9b16f45 Mon Sep 17 00:00:00 2001 From: Philipp Hofmann Date: Thu, 4 Jan 2024 14:10:15 +0100 Subject: [PATCH 30/31] feat: Split up UIKit and App Init App Start Spans (#3534) Split the UIKit and Application Init span into one span for UIKit Init and another for Application Init. The UIKit Init span ends when the users start the SentrySDK. We recommend that the SentrySDK is the first to call in the UIApplication.didFinishLaunching method because otherwise, users won't receive any potential crash reports for code running before our SDK. Therefore, we pick the start time of our SDK as when the UIApplicationDelegate.didFinishLaunching is called. Fixes GH-3345 --- CHANGELOG.md | 1 + Sources/Sentry/SentryAppStartMeasurement.m | 3 +++ Sources/Sentry/SentryAppStartTracker.m | 1 + Sources/Sentry/SentryBuildAppStartSpans.m | 12 ++++++++--- Sources/Sentry/SentrySDK.m | 21 +++++++++++++++++++ .../HybridPublic/SentryAppStartMeasurement.h | 6 ++++++ Sources/Sentry/include/SentrySDK+Private.h | 1 + .../SentryProfilerSwiftTests.swift | 3 ++- .../SentryAppStartTrackerTests.swift | 16 +++++++++----- Tests/SentryTests/Protocol/TestData.swift | 5 +++-- Tests/SentryTests/SentrySDKTests.swift | 18 ++++++++++++++++ .../Transaction/SentryTracerTests.swift | 16 ++++++++------ 12 files changed, 86 insertions(+), 17 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index c2bff563910..52e588eed3f 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -6,6 +6,7 @@ - Add frames delay to transactions and spans (#3487, #3496) - Add slow and frozen frames to spans (#3450, #3478) +- Split up UIKit and App Init App Start Span (#3534) - Prewarmed App Start Tracing is stable (#3536) ### Fixes diff --git a/Sources/Sentry/SentryAppStartMeasurement.m b/Sources/Sentry/SentryAppStartMeasurement.m index 6649a250604..8c87356a6d4 100644 --- a/Sources/Sentry/SentryAppStartMeasurement.m +++ b/Sources/Sentry/SentryAppStartMeasurement.m @@ -15,6 +15,7 @@ @implementation SentryAppStartMeasurement NSDate *_appStartTimestamp; NSDate *_runtimeInitTimestamp; NSDate *_moduleInitializationTimestamp; + NSDate *_sdkStartTimestamp; NSDate *_didFinishLaunchingTimestamp; } # endif // SENTRY_HAS_UIKIT @@ -25,6 +26,7 @@ - (instancetype)initWithType:(SentryAppStartType)type duration:(NSTimeInterval)duration runtimeInitTimestamp:(NSDate *)runtimeInitTimestamp moduleInitializationTimestamp:(NSDate *)moduleInitializationTimestamp + sdkStartTimestamp:(NSDate *)sdkStartTimestamp didFinishLaunchingTimestamp:(NSDate *)didFinishLaunchingTimestamp { # if SENTRY_HAS_UIKIT @@ -35,6 +37,7 @@ - (instancetype)initWithType:(SentryAppStartType)type _duration = duration; _runtimeInitTimestamp = runtimeInitTimestamp; _moduleInitializationTimestamp = moduleInitializationTimestamp; + _sdkStartTimestamp = sdkStartTimestamp; _didFinishLaunchingTimestamp = didFinishLaunchingTimestamp; } diff --git a/Sources/Sentry/SentryAppStartTracker.m b/Sources/Sentry/SentryAppStartTracker.m index 2786ad66b14..38da3d0f286 100644 --- a/Sources/Sentry/SentryAppStartTracker.m +++ b/Sources/Sentry/SentryAppStartTracker.m @@ -216,6 +216,7 @@ - (void)buildAppStartMeasurement:(NSDate *)appStartEnd duration:appStartDuration runtimeInitTimestamp:runtimeInit moduleInitializationTimestamp:sysctl.moduleInitializationTimestamp + sdkStartTimestamp:SentrySDK.startTimestamp didFinishLaunchingTimestamp:self.didFinishLaunchingTimestamp]; SentrySDK.appStartMeasurement = appStartMeasurement; diff --git a/Sources/Sentry/SentryBuildAppStartSpans.m b/Sources/Sentry/SentryBuildAppStartSpans.m index bfa40a5280f..2d344bef1b1 100644 --- a/Sources/Sentry/SentryBuildAppStartSpans.m +++ b/Sources/Sentry/SentryBuildAppStartSpans.m @@ -74,12 +74,18 @@ [appStartSpans addObject:runtimeInitSpan]; } - SentrySpan *appInitSpan = sentryBuildAppStartSpan( - tracer, appStartSpan.spanId, operation, @"UIKit and Application Init"); + SentrySpan *appInitSpan + = sentryBuildAppStartSpan(tracer, appStartSpan.spanId, operation, @"UIKit Init"); [appInitSpan setStartTimestamp:appStartMeasurement.moduleInitializationTimestamp]; - [appInitSpan setTimestamp:appStartMeasurement.didFinishLaunchingTimestamp]; + [appInitSpan setTimestamp:appStartMeasurement.sdkStartTimestamp]; [appStartSpans addObject:appInitSpan]; + SentrySpan *didFinishLaunching + = sentryBuildAppStartSpan(tracer, appStartSpan.spanId, operation, @"Application Init"); + [didFinishLaunching setStartTimestamp:appStartMeasurement.sdkStartTimestamp]; + [didFinishLaunching setTimestamp:appStartMeasurement.didFinishLaunchingTimestamp]; + [appStartSpans addObject:didFinishLaunching]; + SentrySpan *frameRenderSpan = sentryBuildAppStartSpan(tracer, appStartSpan.spanId, operation, @"Initial Frame Render"); [frameRenderSpan setStartTimestamp:appStartMeasurement.didFinishLaunchingTimestamp]; diff --git a/Sources/Sentry/SentrySDK.m b/Sources/Sentry/SentrySDK.m index 2840b439a1b..4135697d259 100644 --- a/Sources/Sentry/SentrySDK.m +++ b/Sources/Sentry/SentrySDK.m @@ -7,6 +7,7 @@ #import "SentryClient+Private.h" #import "SentryCrash.h" #import "SentryCrashWrapper.h" +#import "SentryCurrentDateProvider.h" #import "SentryDependencyContainer.h" #import "SentryDispatchQueueWrapper.h" #import "SentryFileManager.h" @@ -42,6 +43,7 @@ @implementation SentrySDK * reenable the integrations. */ static NSUInteger startInvocations; +static NSDate *_Nullable startTimestamp = nil; + (void)initialize { @@ -135,6 +137,22 @@ + (void)setStartInvocations:(NSUInteger)value startInvocations = value; } +/** + * Not public, only for internal use. + */ ++ (nullable NSDate *)startTimestamp +{ + return startTimestamp; +} + +/** + * Only needed for testing. + */ ++ (void)setStartTimestamp:(NSDate *)value +{ + startTimestamp = value; +} + + (void)startWithOptions:(SentryOptions *)options { [SentryLog configure:options.debug diagnosticLevel:options.diagnosticLevel]; @@ -145,6 +163,7 @@ + (void)startWithOptions:(SentryOptions *)options SENTRY_LOG_DEBUG(@"Starting SDK..."); startInvocations++; + startTimestamp = [SentryDependencyContainer.sharedInstance.dateProvider date]; SentryClient *newClient = [[SentryClient alloc] initWithOptions:options]; [newClient.fileManager moveAppStateToPreviousAppState]; @@ -402,6 +421,8 @@ + (void)close { SENTRY_LOG_DEBUG(@"Starting to close SDK."); + startTimestamp = nil; + SentryHub *hub = SentrySDK.currentHub; [hub removeAllIntegrations]; diff --git a/Sources/Sentry/include/HybridPublic/SentryAppStartMeasurement.h b/Sources/Sentry/include/HybridPublic/SentryAppStartMeasurement.h index f48cdd5f370..edd879dca9a 100644 --- a/Sources/Sentry/include/HybridPublic/SentryAppStartMeasurement.h +++ b/Sources/Sentry/include/HybridPublic/SentryAppStartMeasurement.h @@ -26,6 +26,7 @@ SENTRY_NO_INIT duration:(NSTimeInterval)duration runtimeInitTimestamp:(NSDate *)runtimeInitTimestamp moduleInitializationTimestamp:(NSDate *)moduleInitializationTimestamp + sdkStartTimestamp:(NSDate *)sdkStartTimestamp didFinishLaunchingTimestamp:(NSDate *)didFinishLaunchingTimestamp; /** @@ -58,6 +59,11 @@ SENTRY_NO_INIT */ @property (readonly, nonatomic, strong) NSDate *moduleInitializationTimestamp; +/** + * When the SentrySDK start method is called. + */ +@property (readonly, nonatomic, strong) NSDate *sdkStartTimestamp; + /** * When OS posts UIApplicationDidFinishLaunchingNotification. */ diff --git a/Sources/Sentry/include/SentrySDK+Private.h b/Sources/Sentry/include/SentrySDK+Private.h index de0f263286f..9d0f728acca 100644 --- a/Sources/Sentry/include/SentrySDK+Private.h +++ b/Sources/Sentry/include/SentrySDK+Private.h @@ -21,6 +21,7 @@ SentrySDK () + (nullable SentryAppStartMeasurement *)getAppStartMeasurement; @property (nonatomic, class) NSUInteger startInvocations; +@property (nullable, nonatomic, class) NSDate *startTimestamp; + (SentryHub *)currentHub; diff --git a/Tests/SentryProfilerTests/SentryProfilerSwiftTests.swift b/Tests/SentryProfilerTests/SentryProfilerSwiftTests.swift index 8ed4b6c5a20..f7c8d938ed8 100644 --- a/Tests/SentryProfilerTests/SentryProfilerSwiftTests.swift +++ b/Tests/SentryProfilerTests/SentryProfilerSwiftTests.swift @@ -228,7 +228,8 @@ class SentryProfilerSwiftTests: XCTestCase { appStart = preWarmed ? main : appStart appStartDuration = preWarmed ? appStartDuration - runtimeInitDuration - mainDuration : appStartDuration appStartEnd = appStart.addingTimeInterval(appStartDuration) - return SentryAppStartMeasurement(type: type, isPreWarmed: preWarmed, appStartTimestamp: appStart, duration: appStartDuration, runtimeInitTimestamp: runtimeInit, moduleInitializationTimestamp: main, didFinishLaunchingTimestamp: didFinishLaunching) + return SentryAppStartMeasurement(type: type, isPreWarmed: preWarmed, appStartTimestamp: appStart, duration: appStartDuration, runtimeInitTimestamp: runtimeInit, moduleInitializationTimestamp: main, + sdkStartTimestamp: appStart, didFinishLaunchingTimestamp: didFinishLaunching) } #endif // os(iOS) || os(tvOS) || targetEnvironment(macCatalyst) } diff --git a/Tests/SentryTests/Integrations/Performance/AppStartTracking/SentryAppStartTrackerTests.swift b/Tests/SentryTests/Integrations/Performance/AppStartTracking/SentryAppStartTrackerTests.swift index 8e4bd5d73e9..18106d87d0d 100644 --- a/Tests/SentryTests/Integrations/Performance/AppStartTracking/SentryAppStartTrackerTests.swift +++ b/Tests/SentryTests/Integrations/Performance/AppStartTracking/SentryAppStartTrackerTests.swift @@ -24,6 +24,7 @@ class SentryAppStartTrackerTests: NotificationCenterTestCase { let appStartDuration: TimeInterval = 0.4 var runtimeInitTimestamp: Date var moduleInitializationTimestamp: Date + var sdkStartTimestamp: Date var didFinishLaunchingTimestamp: Date init() { @@ -50,7 +51,10 @@ class SentryAppStartTrackerTests: NotificationCenterTestCase { runtimeInitTimestamp = SentryDependencyContainer.sharedInstance().dateProvider.date().addingTimeInterval(0.2) moduleInitializationTimestamp = SentryDependencyContainer.sharedInstance().dateProvider.date().addingTimeInterval(0.1) - didFinishLaunchingTimestamp = SentryDependencyContainer.sharedInstance().dateProvider.date().addingTimeInterval(0.3) + sdkStartTimestamp = SentryDependencyContainer.sharedInstance().dateProvider.date().addingTimeInterval(0.1) + SentrySDK.startTimestamp = sdkStartTimestamp + + didFinishLaunchingTimestamp = SentryDependencyContainer.sharedInstance().dateProvider.date().addingTimeInterval(0.2) } var sut: SentryAppStartTracker { @@ -440,10 +444,12 @@ class SentryAppStartTrackerTests: NotificationCenterTestCase { XCTAssertEqual(fixture.sysctl.processStartTimestamp, appStartMeasurement.appStartTimestamp) } - XCTAssertEqual(fixture.sysctl.moduleInitializationTimestamp, appStartMeasurement.moduleInitializationTimestamp) - XCTAssertEqual(fixture.runtimeInitTimestamp, appStartMeasurement.runtimeInitTimestamp) - XCTAssertEqual(fixture.didFinishLaunchingTimestamp, appStartMeasurement.didFinishLaunchingTimestamp) - XCTAssertEqual(preWarmed, appStartMeasurement.isPreWarmed) + expect(appStartMeasurement.moduleInitializationTimestamp) == fixture.sysctl.moduleInitializationTimestamp + expect(appStartMeasurement.runtimeInitTimestamp) == fixture.runtimeInitTimestamp + + expect(appStartMeasurement.sdkStartTimestamp) == fixture.sdkStartTimestamp + expect(appStartMeasurement.didFinishLaunchingTimestamp) == fixture.didFinishLaunchingTimestamp + expect(appStartMeasurement.isPreWarmed) == preWarmed } private func assertValidHybridStart(type: SentryAppStartType) { diff --git a/Tests/SentryTests/Protocol/TestData.swift b/Tests/SentryTests/Protocol/TestData.swift index bd7641355df..f200769ebcf 100644 --- a/Tests/SentryTests/Protocol/TestData.swift +++ b/Tests/SentryTests/Protocol/TestData.swift @@ -328,9 +328,10 @@ class TestData { let appStartDuration = 0.5 let main = appStartTimestamp.addingTimeInterval(0.15) let runtimeInit = appStartTimestamp.addingTimeInterval(0.05) - let didFinishLaunching = appStartTimestamp.addingTimeInterval(0.3) + let sdkStart = appStartTimestamp.addingTimeInterval(0.1) + let didFinishLaunching = appStartTimestamp.addingTimeInterval(0.2) - return SentryAppStartMeasurement(type: type, isPreWarmed: false, appStartTimestamp: appStartTimestamp, duration: appStartDuration, runtimeInitTimestamp: runtimeInit, moduleInitializationTimestamp: main, didFinishLaunchingTimestamp: didFinishLaunching) + return SentryAppStartMeasurement(type: type, isPreWarmed: false, appStartTimestamp: appStartTimestamp, duration: appStartDuration, runtimeInitTimestamp: runtimeInit, moduleInitializationTimestamp: main, sdkStartTimestamp: sdkStart, didFinishLaunchingTimestamp: didFinishLaunching) } #endif // os(iOS) || os(tvOS) || targetEnvironment(macCatalyst) diff --git a/Tests/SentryTests/SentrySDKTests.swift b/Tests/SentryTests/SentrySDKTests.swift index 37b63addf27..ed7fb639975 100644 --- a/Tests/SentryTests/SentrySDKTests.swift +++ b/Tests/SentryTests/SentrySDKTests.swift @@ -1,3 +1,4 @@ +import Nimble @testable import Sentry import SentryTestUtils import XCTest @@ -504,6 +505,23 @@ class SentrySDKTests: XCTestCase { XCTAssertEqual(1, SentrySDK.startInvocations) } + func testSDKStartTimestamp() { + let currentDateProvider = TestCurrentDateProvider() + SentryDependencyContainer.sharedInstance().dateProvider = currentDateProvider + + expect(SentrySDK.startTimestamp) == nil + + SentrySDK.start { options in + options.dsn = SentrySDKTests.dsnAsString + options.removeAllIntegrations() + } + + expect(SentrySDK.startTimestamp) == currentDateProvider.date() + + SentrySDK.close() + expect(SentrySDK.startTimestamp) == nil + } + func testIsEnabled() { XCTAssertFalse(SentrySDK.isEnabled) diff --git a/Tests/SentryTests/Transaction/SentryTracerTests.swift b/Tests/SentryTests/Transaction/SentryTracerTests.swift index 2ab9f8b2e98..b9d2dbfd456 100644 --- a/Tests/SentryTests/Transaction/SentryTracerTests.swift +++ b/Tests/SentryTests/Transaction/SentryTracerTests.swift @@ -78,13 +78,14 @@ class SentryTracerTests: XCTestCase { let runtimeInit = appStart.addingTimeInterval(runtimeInitDuration) let mainDuration = 0.15 let main = appStart.addingTimeInterval(mainDuration) - let didFinishLaunching = appStart.addingTimeInterval(0.3) + let sdkStart = appStart.addingTimeInterval(0.1) + let didFinishLaunching = appStart.addingTimeInterval(0.2) appStart = preWarmed ? main : appStart appStartDuration = preWarmed ? appStartDuration - runtimeInitDuration - mainDuration : appStartDuration appStartEnd = appStart.addingTimeInterval(appStartDuration) - return SentryAppStartMeasurement(type: type, isPreWarmed: preWarmed, appStartTimestamp: appStart, duration: appStartDuration, runtimeInitTimestamp: runtimeInit, moduleInitializationTimestamp: main, didFinishLaunchingTimestamp: didFinishLaunching) + return SentryAppStartMeasurement(type: type, isPreWarmed: preWarmed, appStartTimestamp: appStart, duration: appStartDuration, runtimeInitTimestamp: runtimeInit, moduleInitializationTimestamp: main, sdkStartTimestamp: sdkStart, didFinishLaunchingTimestamp: didFinishLaunching) } #endif // os(iOS) || os(tvOS) || targetEnvironment(macCatalyst) @@ -763,6 +764,7 @@ class SentryTracerTests: XCTestCase { duration: 0.5, runtimeInitTimestamp: fixture.currentDateProvider.date(), moduleInitializationTimestamp: fixture.currentDateProvider.date(), + sdkStartTimestamp: fixture.currentDateProvider.date(), didFinishLaunchingTimestamp: fixture.currentDateProvider.date() )) @@ -1188,7 +1190,7 @@ class SentryTracerTests: XCTestCase { #if os(iOS) || os(tvOS) || targetEnvironment(macCatalyst) private func assertAppStartsSpanAdded(transaction: Transaction, startType: String, operation: String, appStartMeasurement: SentryAppStartMeasurement) { let spans: [SentrySpan]? = Dynamic(transaction).spans - XCTAssertEqual(5, spans?.count) + expect(spans?.count) == 6 let appLaunchSpan = spans?.first { span in span.spanDescription == startType @@ -1214,7 +1216,8 @@ class SentryTracerTests: XCTestCase { assertSpan("Pre Runtime Init", appStartMeasurement.appStartTimestamp, appStartMeasurement.runtimeInitTimestamp) assertSpan("Runtime Init to Pre Main Initializers", appStartMeasurement.runtimeInitTimestamp, appStartMeasurement.moduleInitializationTimestamp) - assertSpan("UIKit and Application Init", appStartMeasurement.moduleInitializationTimestamp, appStartMeasurement.didFinishLaunchingTimestamp) + assertSpan("UIKit Init", appStartMeasurement.moduleInitializationTimestamp, appStartMeasurement.sdkStartTimestamp) + assertSpan("Application Init", appStartMeasurement.sdkStartTimestamp, appStartMeasurement.didFinishLaunchingTimestamp) assertSpan("Initial Frame Render", appStartMeasurement.didFinishLaunchingTimestamp, fixture.appStartEnd) } @@ -1230,7 +1233,7 @@ class SentryTracerTests: XCTestCase { private func assertPreWarmedAppStartsSpanAdded(transaction: Transaction, startType: String, operation: String, appStartMeasurement: SentryAppStartMeasurement) { let spans: [SentrySpan]? = Dynamic(transaction).spans - XCTAssertEqual(3, spans?.count) + expect(spans?.count) == 4 let appLaunchSpan = spans?.first { span in span.spanDescription == startType @@ -1252,7 +1255,8 @@ class SentryTracerTests: XCTestCase { XCTAssertEqual(timestamp, span?.timestamp) } - assertSpan("UIKit and Application Init", appStartMeasurement.moduleInitializationTimestamp, appStartMeasurement.didFinishLaunchingTimestamp) + assertSpan("UIKit Init", appStartMeasurement.moduleInitializationTimestamp, appStartMeasurement.sdkStartTimestamp) + assertSpan("Application Init", appStartMeasurement.sdkStartTimestamp, appStartMeasurement.didFinishLaunchingTimestamp) assertSpan("Initial Frame Render", appStartMeasurement.didFinishLaunchingTimestamp, fixture.appStartEnd) } From 3b9a8e69ca296bd8cd0e317ad7a448e5daf4a342 Mon Sep 17 00:00:00 2001 From: getsentry-bot Date: Thu, 4 Jan 2024 15:40:39 +0000 Subject: [PATCH 31/31] release: 8.18.0 --- CHANGELOG.md | 2 +- Samples/iOS-Swift/iOS-Swift.xcodeproj/project.pbxproj | 8 ++++---- Sentry.podspec | 4 ++-- SentryPrivate.podspec | 2 +- SentrySwiftUI.podspec | 4 ++-- Sources/Configuration/Sentry.xcconfig | 2 +- Sources/Configuration/SentryPrivate.xcconfig | 2 +- Sources/Sentry/SentryMeta.m | 2 +- Tests/HybridSDKTest/HybridPod.podspec | 2 +- 9 files changed, 14 insertions(+), 14 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 52e588eed3f..ec56be7126d 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,6 +1,6 @@ # Changelog -## Unreleased +## 8.18.0 ### Features diff --git a/Samples/iOS-Swift/iOS-Swift.xcodeproj/project.pbxproj b/Samples/iOS-Swift/iOS-Swift.xcodeproj/project.pbxproj index 66091050345..46f0cf5d319 100644 --- a/Samples/iOS-Swift/iOS-Swift.xcodeproj/project.pbxproj +++ b/Samples/iOS-Swift/iOS-Swift.xcodeproj/project.pbxproj @@ -1262,7 +1262,7 @@ "$(inherited)", "@executable_path/Frameworks", ); - MARKETING_VERSION = 8.17.2; + MARKETING_VERSION = 8.18.0; PRODUCT_BUNDLE_IDENTIFIER = "io.sentry.sample.iOS-Swift"; PRODUCT_NAME = "$(TARGET_NAME)"; PROVISIONING_PROFILE_SPECIFIER = "match Development io.sentry.sample.iOS-Swift"; @@ -1291,7 +1291,7 @@ "$(inherited)", "@executable_path/Frameworks", ); - MARKETING_VERSION = 8.17.2; + MARKETING_VERSION = 8.18.0; PRODUCT_BUNDLE_IDENTIFIER = "io.sentry.sample.iOS-Swift"; PRODUCT_NAME = "$(TARGET_NAME)"; PROVISIONING_PROFILE_SPECIFIER = "match AppStore io.sentry.sample.iOS-Swift"; @@ -1938,7 +1938,7 @@ "$(inherited)", "@executable_path/Frameworks", ); - MARKETING_VERSION = 8.17.2; + MARKETING_VERSION = 8.18.0; PRODUCT_BUNDLE_IDENTIFIER = "io.sentry.sample.iOS-Swift.Clip"; PRODUCT_NAME = "$(TARGET_NAME)"; PROVISIONING_PROFILE_SPECIFIER = "match Development io.sentry.sample.iOS-Swift.Clip"; @@ -1973,7 +1973,7 @@ "$(inherited)", "@executable_path/Frameworks", ); - MARKETING_VERSION = 8.17.2; + MARKETING_VERSION = 8.18.0; PRODUCT_BUNDLE_IDENTIFIER = "io.sentry.sample.iOS-Swift.Clip"; PRODUCT_NAME = "$(TARGET_NAME)"; PROVISIONING_PROFILE_SPECIFIER = "match AppStore io.sentry.sample.iOS-Swift.Clip"; diff --git a/Sentry.podspec b/Sentry.podspec index c8b80c81b59..88c31b8add1 100644 --- a/Sentry.podspec +++ b/Sentry.podspec @@ -1,6 +1,6 @@ Pod::Spec.new do |s| s.name = "Sentry" - s.version = "8.17.2" + s.version = "8.18.0" s.summary = "Sentry client for cocoa" s.homepage = "https://github.com/getsentry/sentry-cocoa" s.license = "mit" @@ -27,7 +27,7 @@ Pod::Spec.new do |s| } s.default_subspecs = ['Core'] - s.dependency "SentryPrivate", "8.17.2" + s.dependency "SentryPrivate", "8.18.0" s.subspec 'Core' do |sp| sp.source_files = "Sources/Sentry/**/*.{h,hpp,m,mm,c,cpp}", diff --git a/SentryPrivate.podspec b/SentryPrivate.podspec index 828f36ca04a..30db5fe5050 100644 --- a/SentryPrivate.podspec +++ b/SentryPrivate.podspec @@ -1,6 +1,6 @@ Pod::Spec.new do |s| s.name = "SentryPrivate" - s.version = "8.17.2" + s.version = "8.18.0" s.summary = "Sentry Private Library." s.homepage = "https://github.com/getsentry/sentry-cocoa" s.license = "mit" diff --git a/SentrySwiftUI.podspec b/SentrySwiftUI.podspec index 0982b6773f3..1adc1df3e4f 100644 --- a/SentrySwiftUI.podspec +++ b/SentrySwiftUI.podspec @@ -1,6 +1,6 @@ Pod::Spec.new do |s| s.name = "SentrySwiftUI" - s.version = "8.17.2" + s.version = "8.18.0" s.summary = "Sentry client for SwiftUI" s.homepage = "https://github.com/getsentry/sentry-cocoa" s.license = "mit" @@ -19,5 +19,5 @@ Pod::Spec.new do |s| s.watchos.framework = 'WatchKit' s.source_files = "Sources/SentrySwiftUI/**/*.{swift,h,m}" - s.dependency 'Sentry', "8.17.2" + s.dependency 'Sentry', "8.18.0" end diff --git a/Sources/Configuration/Sentry.xcconfig b/Sources/Configuration/Sentry.xcconfig index e72a4a614a3..67148865499 100644 --- a/Sources/Configuration/Sentry.xcconfig +++ b/Sources/Configuration/Sentry.xcconfig @@ -2,6 +2,6 @@ PRODUCT_NAME = Sentry INFOPLIST_FILE = Sources/Resources/Info.plist PRODUCT_BUNDLE_IDENTIFIER = io.sentry.Sentry -CURRENT_PROJECT_VERSION = 8.17.2 +CURRENT_PROJECT_VERSION = 8.18.0 MODULEMAP_FILE = $(SRCROOT)/Sources/Resources/Sentry.modulemap diff --git a/Sources/Configuration/SentryPrivate.xcconfig b/Sources/Configuration/SentryPrivate.xcconfig index c79cfd74d38..d2960235997 100644 --- a/Sources/Configuration/SentryPrivate.xcconfig +++ b/Sources/Configuration/SentryPrivate.xcconfig @@ -1,3 +1,3 @@ PRODUCT_NAME = SentryPrivate MACH_O_TYPE = staticlib -CURRENT_PROJECT_VERSION = 8.17.2 +CURRENT_PROJECT_VERSION = 8.18.0 diff --git a/Sources/Sentry/SentryMeta.m b/Sources/Sentry/SentryMeta.m index e62548ef113..63a3ea8c8a6 100644 --- a/Sources/Sentry/SentryMeta.m +++ b/Sources/Sentry/SentryMeta.m @@ -5,7 +5,7 @@ @implementation SentryMeta // Don't remove the static keyword. If you do the compiler adds the constant name to the global // symbol table and it might clash with other constants. When keeping the static keyword the // compiler replaces all occurrences with the value. -static NSString *versionString = @"8.17.2"; +static NSString *versionString = @"8.18.0"; static NSString *sdkName = @"sentry.cocoa"; + (NSString *)versionString diff --git a/Tests/HybridSDKTest/HybridPod.podspec b/Tests/HybridSDKTest/HybridPod.podspec index 6be5dd4a38e..dff8a52ebe1 100644 --- a/Tests/HybridSDKTest/HybridPod.podspec +++ b/Tests/HybridSDKTest/HybridPod.podspec @@ -13,6 +13,6 @@ Pod::Spec.new do |s| s.requires_arc = true s.frameworks = 'Foundation' s.swift_versions = "5.5" - s.dependency "Sentry/HybridSDK", "8.17.2" + s.dependency "Sentry/HybridSDK", "8.18.0" s.source_files = "HybridTest.swift" end