From 1803656c3e67327c5e6575e351d51b5ef5475034 Mon Sep 17 00:00:00 2001 From: Andrew McKnight Date: Fri, 8 Sep 2023 14:11:40 -0400 Subject: [PATCH 1/4] fix: gather metric samples at profile start/end --- Sources/Sentry/SentryDispatchSourceWrapper.m | 3 +-- Sources/Sentry/SentryMetricProfiler.mm | 17 ++++++++++++----- .../SentryProfilerSwiftTests.swift | 7 ++++++- 3 files changed, 19 insertions(+), 8 deletions(-) diff --git a/Sources/Sentry/SentryDispatchSourceWrapper.m b/Sources/Sentry/SentryDispatchSourceWrapper.m index cae6298700c..980911917da 100644 --- a/Sources/Sentry/SentryDispatchSourceWrapper.m +++ b/Sources/Sentry/SentryDispatchSourceWrapper.m @@ -15,8 +15,7 @@ - (instancetype)initTimerWithInterval:(uint64_t)interval _queueWrapper = queueWrapper; _source = dispatch_source_create(DISPATCH_SOURCE_TYPE_TIMER, 0, 0, queueWrapper.queue); dispatch_source_set_event_handler(_source, eventHandler); - dispatch_source_set_timer( - _source, dispatch_time(DISPATCH_TIME_NOW, interval), interval, leeway); + dispatch_source_set_timer(_source, dispatch_time(DISPATCH_TIME_NOW, 0), interval, leeway); dispatch_resume(_source); } return self; diff --git a/Sources/Sentry/SentryMetricProfiler.mm b/Sources/Sentry/SentryMetricProfiler.mm index fb34e3f8e0c..04742e9c535 100644 --- a/Sources/Sentry/SentryMetricProfiler.mm +++ b/Sources/Sentry/SentryMetricProfiler.mm @@ -111,6 +111,9 @@ - (void)start - (void)stop { [_dispatchSource cancel]; + + // make sure we have a measurement at the end of the profile + [self recordMetrics]; } - (NSMutableDictionary *)serializeBetween:(uint64_t)startSystemTime @@ -159,11 +162,15 @@ - (void)registerSampler queueName:"io.sentry.metric-profiler" attributes:dispatch_queue_attr_make_with_qos_class( DISPATCH_QUEUE_CONCURRENT, QOS_CLASS_UTILITY, 0) - eventHandler:^{ - [weakSelf recordCPUsage]; - [weakSelf recordMemoryFootprint]; - [weakSelf recordEnergyUsageEstimate]; - }]; + eventHandler:^{ [weakSelf recordMetrics]; }]; +} + +- (void)recordMetrics +{ + SENTRY_LOG_DEBUG(@"Recording profiling metrics sample"); + [self recordCPUsage]; + [self recordMemoryFootprint]; + [self recordEnergyUsageEstimate]; } - (void)recordMemoryFootprint diff --git a/Tests/SentryProfilerTests/SentryProfilerSwiftTests.swift b/Tests/SentryProfilerTests/SentryProfilerSwiftTests.swift index 7982907de19..e3eddb651ac 100644 --- a/Tests/SentryProfilerTests/SentryProfilerSwiftTests.swift +++ b/Tests/SentryProfilerTests/SentryProfilerSwiftTests.swift @@ -205,6 +205,11 @@ class SentryProfilerSwiftTests: XCTestCase { systemWrapper.overrides.memoryFootprintError = NSError(domain: "test-error", code: 1) systemWrapper.overrides.cpuEnergyUsageError = NSError(domain: "test-error", code: 2) metricTimerFactory?.fire() + + // clear out errors for the profile end sample collection + systemWrapper.overrides.cpuUsageError = nil + systemWrapper.overrides.memoryFootprintError = nil + systemWrapper.overrides.cpuEnergyUsageError = nil } // app start simulation @@ -658,7 +663,7 @@ private extension SentryProfilerSwiftTests { func assertMetricValue(measurements: [String: Any], key: String, numberOfReadings: Int, expectedValue: T? = nil, transaction: Transaction, expectedUnits: String) throws { let metricContainer = try XCTUnwrap(measurements[key] as? [String: Any]) let values = try XCTUnwrap(metricContainer["values"] as? [[String: Any]]) - XCTAssertEqual(values.count, numberOfReadings, "Wrong number of values under \(key)") + XCTAssertEqual(values.count, numberOfReadings + 1, "Wrong number of values under \(key). Need the expected number of samples, plus a profile end reading") if let expectedValue = expectedValue { let actualValue = try XCTUnwrap(values[0]["value"] as? T) From d454f3142c2728cd4e0b5fe54aff6bc312dad47d Mon Sep 17 00:00:00 2001 From: Andrew McKnight Date: Fri, 8 Sep 2023 14:15:19 -0400 Subject: [PATCH 2/4] changelog --- CHANGELOG.md | 1 + 1 file changed, 1 insertion(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index 33d06940e79..8555e8d1882 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -5,6 +5,7 @@ ### Fixes - Remove warning about non-portable path to file "SentryDsn.h" (#3270) +- Gather metric readings fully covering the duration of a profile (#3272) ### Features From c8d388c0764255b01a5883fed8a2481fa62aa435 Mon Sep 17 00:00:00 2001 From: Andrew McKnight Date: Fri, 8 Sep 2023 17:37:55 -0400 Subject: [PATCH 3/4] wip fixing tests; also make sure all concurrent spans have samples at start and end --- Sources/Sentry/SentryDispatchSourceWrapper.m | 3 ++- Sources/Sentry/SentryMetricProfiler.mm | 19 +++++++---------- Sources/Sentry/SentryProfiler.mm | 4 ++++ Sources/Sentry/include/SentryMetricProfiler.h | 2 ++ .../SentryProfilerSwiftTests.swift | 21 +++++++++++-------- 5 files changed, 28 insertions(+), 21 deletions(-) diff --git a/Sources/Sentry/SentryDispatchSourceWrapper.m b/Sources/Sentry/SentryDispatchSourceWrapper.m index 980911917da..cae6298700c 100644 --- a/Sources/Sentry/SentryDispatchSourceWrapper.m +++ b/Sources/Sentry/SentryDispatchSourceWrapper.m @@ -15,7 +15,8 @@ - (instancetype)initTimerWithInterval:(uint64_t)interval _queueWrapper = queueWrapper; _source = dispatch_source_create(DISPATCH_SOURCE_TYPE_TIMER, 0, 0, queueWrapper.queue); dispatch_source_set_event_handler(_source, eventHandler); - dispatch_source_set_timer(_source, dispatch_time(DISPATCH_TIME_NOW, 0), interval, leeway); + dispatch_source_set_timer( + _source, dispatch_time(DISPATCH_TIME_NOW, interval), interval, leeway); dispatch_resume(_source); } return self; diff --git a/Sources/Sentry/SentryMetricProfiler.mm b/Sources/Sentry/SentryMetricProfiler.mm index 04742e9c535..3804249758a 100644 --- a/Sources/Sentry/SentryMetricProfiler.mm +++ b/Sources/Sentry/SentryMetricProfiler.mm @@ -108,12 +108,17 @@ - (void)start [self registerSampler]; } +- (void)recordMetrics +{ + SENTRY_LOG_DEBUG(@"Recording profiling metrics sample"); + [self recordCPUsage]; + [self recordMemoryFootprint]; + [self recordEnergyUsageEstimate]; +} + - (void)stop { [_dispatchSource cancel]; - - // make sure we have a measurement at the end of the profile - [self recordMetrics]; } - (NSMutableDictionary *)serializeBetween:(uint64_t)startSystemTime @@ -165,14 +170,6 @@ - (void)registerSampler eventHandler:^{ [weakSelf recordMetrics]; }]; } -- (void)recordMetrics -{ - SENTRY_LOG_DEBUG(@"Recording profiling metrics sample"); - [self recordCPUsage]; - [self recordMemoryFootprint]; - [self recordEnergyUsageEstimate]; -} - - (void)recordMemoryFootprint { NSError *error; diff --git a/Sources/Sentry/SentryProfiler.mm b/Sources/Sentry/SentryProfiler.mm index 8a8bc2ec444..00902c96136 100644 --- a/Sources/Sentry/SentryProfiler.mm +++ b/Sources/Sentry/SentryProfiler.mm @@ -320,6 +320,7 @@ + (void)startWithTracer:(SentryId *)traceId if (_gCurrentProfiler && [_gCurrentProfiler isRunning]) { SENTRY_LOG_DEBUG(@"A profiler is already running."); trackProfilerForTracer(_gCurrentProfiler, traceId); + [_gCurrentProfiler->_metricProfiler recordMetrics]; return; } @@ -414,6 +415,9 @@ + (void)updateProfilePayload:(NSMutableDictionary *)payload and:(uint64_t)endSystemTime onHub:(SentryHub *)hub; { + if (self.isRunning) { + [_metricProfiler recordMetrics]; + } return serializedProfileData([self._state copyProfilingData], startSystemTime, endSystemTime, self.profileId, profilerTruncationReasonName(_truncationReason), [_metricProfiler serializeBetween:startSystemTime and:endSystemTime], diff --git a/Sources/Sentry/include/SentryMetricProfiler.h b/Sources/Sentry/include/SentryMetricProfiler.h index 747d36deab5..5af35db5288 100644 --- a/Sources/Sentry/include/SentryMetricProfiler.h +++ b/Sources/Sentry/include/SentryMetricProfiler.h @@ -42,6 +42,8 @@ typedef NSDictionary(measurements: [String: Any], key: String, numberOfReadings: Int, expectedValue: T? = nil, transaction: Transaction, expectedUnits: String) throws { let metricContainer = try XCTUnwrap(measurements[key] as? [String: Any]) let values = try XCTUnwrap(metricContainer["values"] as? [[String: Any]]) - XCTAssertEqual(values.count, numberOfReadings + 1, "Wrong number of values under \(key). Need the expected number of samples, plus a profile end reading") + XCTAssertEqual(values.count, numberOfReadings, "Wrong number of values under \(key)") if let expectedValue = expectedValue { - let actualValue = try XCTUnwrap(values[0]["value"] as? T) + let actualValue = try XCTUnwrap(values[1]["value"] as? T) XCTAssertEqual(actualValue, expectedValue, "Wrong value for \(key)") let timestamp = try XCTUnwrap(values[0]["elapsed_since_start_ns"] as? NSString) From 359e03a9ed0bf09c40c6c8fc3961cf5bca516b89 Mon Sep 17 00:00:00 2001 From: Andrew McKnight Date: Fri, 8 Sep 2023 23:14:22 -0400 Subject: [PATCH 4/4] fix tests and location of stop readings --- SentryTestUtils/TestDispatchSourceWrapper.swift | 1 + Sources/Sentry/SentryDispatchSourceWrapper.m | 3 +-- Sources/Sentry/SentryProfiler.mm | 13 ++++++++++--- Sources/Sentry/SentryTracer.m | 3 +++ Sources/Sentry/include/SentryProfiler.h | 6 ++++++ .../SentryProfilerSwiftTests.swift | 13 ++++++++++--- 6 files changed, 31 insertions(+), 8 deletions(-) diff --git a/SentryTestUtils/TestDispatchSourceWrapper.swift b/SentryTestUtils/TestDispatchSourceWrapper.swift index 447b5414050..553ce7a53d2 100644 --- a/SentryTestUtils/TestDispatchSourceWrapper.swift +++ b/SentryTestUtils/TestDispatchSourceWrapper.swift @@ -10,6 +10,7 @@ public class TestDispatchSourceWrapper: SentryDispatchSourceWrapper { public init(eventHandler: @escaping () -> Void) { self.overrides.eventHandler = eventHandler super.init() + eventHandler() // SentryDispatchSourceWrapper constructs a timer so that it fires with no initial delay } public override func cancel() { diff --git a/Sources/Sentry/SentryDispatchSourceWrapper.m b/Sources/Sentry/SentryDispatchSourceWrapper.m index cae6298700c..980911917da 100644 --- a/Sources/Sentry/SentryDispatchSourceWrapper.m +++ b/Sources/Sentry/SentryDispatchSourceWrapper.m @@ -15,8 +15,7 @@ - (instancetype)initTimerWithInterval:(uint64_t)interval _queueWrapper = queueWrapper; _source = dispatch_source_create(DISPATCH_SOURCE_TYPE_TIMER, 0, 0, queueWrapper.queue); dispatch_source_set_event_handler(_source, eventHandler); - dispatch_source_set_timer( - _source, dispatch_time(DISPATCH_TIME_NOW, interval), interval, leeway); + dispatch_source_set_timer(_source, dispatch_time(DISPATCH_TIME_NOW, 0), interval, leeway); dispatch_resume(_source); } return self; diff --git a/Sources/Sentry/SentryProfiler.mm b/Sources/Sentry/SentryProfiler.mm index 00902c96136..8294ec8b868 100644 --- a/Sources/Sentry/SentryProfiler.mm +++ b/Sources/Sentry/SentryProfiler.mm @@ -320,6 +320,7 @@ + (void)startWithTracer:(SentryId *)traceId if (_gCurrentProfiler && [_gCurrentProfiler isRunning]) { SENTRY_LOG_DEBUG(@"A profiler is already running."); trackProfilerForTracer(_gCurrentProfiler, traceId); + // record a new metric sample for every concurrent span start [_gCurrentProfiler->_metricProfiler recordMetrics]; return; } @@ -339,6 +340,15 @@ + (BOOL)isCurrentlyProfiling return [_gCurrentProfiler isRunning]; } ++ (void)recordMetrics +{ + std::lock_guard l(_gProfilerLock); + if (_gCurrentProfiler == nil) { + return; + } + [_gCurrentProfiler->_metricProfiler recordMetrics]; +} + + (nullable SentryEnvelopeItem *)createProfilingEnvelopeItemForTransaction: (SentryTransaction *)transaction { @@ -415,9 +425,6 @@ + (void)updateProfilePayload:(NSMutableDictionary *)payload and:(uint64_t)endSystemTime onHub:(SentryHub *)hub; { - if (self.isRunning) { - [_metricProfiler recordMetrics]; - } return serializedProfileData([self._state copyProfilingData], startSystemTime, endSystemTime, self.profileId, profilerTruncationReasonName(_truncationReason), [_metricProfiler serializeBetween:startSystemTime and:endSystemTime], diff --git a/Sources/Sentry/SentryTracer.m b/Sources/Sentry/SentryTracer.m index 20a2e091e52..8f327550109 100644 --- a/Sources/Sentry/SentryTracer.m +++ b/Sources/Sentry/SentryTracer.m @@ -599,6 +599,9 @@ - (SentryTransaction *)toTransaction transaction.transaction = self.transactionContext.name; #if SENTRY_TARGET_PROFILING_SUPPORTED transaction.startSystemTime = self.startSystemTime; + if (self.isProfiling) { + [SentryProfiler recordMetrics]; + } transaction.endSystemTime = SentryDependencyContainer.sharedInstance.dateProvider.systemTime; #endif // SENTRY_TARGET_PROFILING_SUPPORTED diff --git a/Sources/Sentry/include/SentryProfiler.h b/Sources/Sentry/include/SentryProfiler.h index 95f3cdbae93..76ba45bf0d5 100644 --- a/Sources/Sentry/include/SentryProfiler.h +++ b/Sources/Sentry/include/SentryProfiler.h @@ -64,6 +64,12 @@ SENTRY_EXTERN_C_END */ + (BOOL)isCurrentlyProfiling; +/** + * Immediately record a sample of profiling metrics. Helps get full coverage of concurrent spans + * when they're ended. + */ ++ (void)recordMetrics; + /** * Given a transaction, return an envelope item containing any corresponding profile data to be * attached to the transaction envelope. diff --git a/Tests/SentryProfilerTests/SentryProfilerSwiftTests.swift b/Tests/SentryProfilerTests/SentryProfilerSwiftTests.swift index 99b4e753ddf..b114a0142c1 100644 --- a/Tests/SentryProfilerTests/SentryProfilerSwiftTests.swift +++ b/Tests/SentryProfilerTests/SentryProfilerSwiftTests.swift @@ -260,7 +260,7 @@ class SentryProfilerSwiftTests: XCTestCase { try fixture.gatherMockedMetrics(span: span) self.fixture.currentDateProvider.advanceBy(nanoseconds: 1.toNanoSeconds()) span.finish() - try self.assertMetricsPayload(expectedUsageReadings: fixture.mockUsageReadingsPerBatch + 1) + try self.assertMetricsPayload(expectedUsageReadings: fixture.mockUsageReadingsPerBatch + 2) // including one sample at the start and the end } func testConcurrentProfilingTransactions() throws { @@ -272,6 +272,7 @@ class SentryProfilerSwiftTests: XCTestCase { XCTAssertEqual(SentryProfiler.currentProfiledTracers(), UInt(0)) for i in 0 ..< numberOfTransactions { + print("creating new concurrent transaction for test") let span = try fixture.newTransaction() // because energy readings are computed as the difference between sequential cumulative readings, we must increment the mock value by the expected result each iteration @@ -289,10 +290,16 @@ class SentryProfilerSwiftTests: XCTestCase { try fixture.gatherMockedMetrics(span: span) XCTAssertTrue(SentryProfiler.isCurrentlyProfiling()) span.finish() - XCTAssertEqual(SentryProfiler.currentProfiledTracers(), UInt(numberOfTransactions - i - 1)) + XCTAssertEqual(SentryProfiler.currentProfiledTracers(), UInt(numberOfTransactions - (i + 1))) try self.assertValidProfileData() - try self.assertMetricsPayload(expectedUsageReadings: fixture.mockUsageReadingsPerBatch * (i + 1) + numberOfTransactions + i) + + // this is a complicated number to come up with, see the explanation for each part... + let expectedUsageReadings = fixture.mockUsageReadingsPerBatch * (i + 1) // since we fire mock metrics readings for each concurrent span, + // we need to accumulate across the number of spans each iteration + + numberOfTransactions // and then, add the number of spans that were created to account for the start reading for each span + + 1 // and the end reading for this span + try self.assertMetricsPayload(expectedUsageReadings: expectedUsageReadings, oneLessEnergyReading: i == 0) } XCTAssertFalse(SentryProfiler.isCurrentlyProfiling())