Skip to content

Commit a84316b

Browse files
simaoseica-ddsimaoseica-dd
authored
Merge pull request #3006 from DataDog/simaoseica/RUM-16553/ttfd
RUM-16553: Attach TTFD to Profiling
2 parents 5dd0b59 + ed99b90 commit a84316b

7 files changed

Lines changed: 339 additions & 34 deletions

File tree

‎DatadogProfiling/Sources/AppLaunchProfiler.swift‎

Lines changed: 4 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -108,7 +108,10 @@ extension AppLaunchProfiler: FeatureMessageReceiver {
108108
self.write(profile: profile, rumVitals: Array(self.currentRUMVitals.values))
109109
return false
110110
} else if case let .payload(message as OperationMessage) = message {
111-
if message.operation.stepType == .start {
111+
// Capture vitals like TTFD that are not operation steps.
112+
if message.operation.stepType == nil {
113+
currentRUMVitals[message.operation.key] = message.operation
114+
} else if message.operation.stepType == .start {
112115
currentRUMVitals[message.operation.key] = message.operation
113116
} else if var startVital = currentRUMVitals[message.operation.key] {
114117
// Add duration to vital to help Profiling backend label correctly the samples of this vital

‎DatadogProfiling/Sources/DatadogProfiler.swift‎

Lines changed: 5 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -298,11 +298,13 @@ private extension DatadogProfiler {
298298
}
299299
attributes = message.attributes
300300

301-
switch message.operation.stepType {
302-
case .start:
301+
// Capture vitals like TTFD that are not operation steps.
302+
if message.operation.stepType == nil {
303+
currentRUMVitals[message.operation.key] = message.operation
304+
} else if message.operation.stepType == .start {
303305
currentRUMVitals[message.operation.key] = message.operation
304306
updateProfilerState(canProfile: shouldKeepProfilerRunning())
305-
case .end:
307+
} else if message.operation.stepType == .end {
306308
if var startVital = currentRUMVitals[message.operation.key] {
307309
// Add duration to vital to help Profiling backend label correctly the samples of this vital
308310
let duration = message.operation.date.timeIntervalSince(startVital.date)
@@ -316,7 +318,6 @@ private extension DatadogProfiler {
316318
fireTimer(after: fireInterval)
317319
}
318320
}
319-
default: break
320321
}
321322
}
322323
}

‎DatadogProfiling/Tests/AppLaunchProfilerTests.swift‎

Lines changed: 39 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -403,6 +403,45 @@ final class AppLaunchProfilerTests: XCTestCase {
403403
let vitalIDs = try eventIDs(ofType: "vital", from: metadata)
404404
XCTAssertEqual(vitalIDs.count, 2)
405405
XCTAssertTrue(vitalIDs.contains("start-id"))
406+
407+
let event = try XCTUnwrap(core.events.first as? ProfileEvent)
408+
let attributeVitalIDs = try XCTUnwrap(event.additionalAttributes?[RUMCoreContext.IDs.vitalID] as? [String])
409+
XCTAssertTrue(attributeVitalIDs.contains("start-id"))
410+
}
411+
412+
func testApplicationLaunchWithTTFDVital_includesTTIDAndTTFDInProfile() throws {
413+
// Given
414+
let core = PassthroughCoreMock()
415+
let profiler = appLaunchProfiler(core: core, isContinuousProfiling: false)
416+
let ttidVital = Vital.mockWith(
417+
id: "ttid-id",
418+
name: "time_to_initial_display",
419+
operationKey: nil,
420+
stepType: nil,
421+
duration: 1_000_000_000
422+
)
423+
let ttfdVital = Vital.mockWith(
424+
id: "ttfd-id",
425+
name: "time_to_full_display",
426+
operationKey: nil,
427+
stepType: nil,
428+
duration: 2_000_000_000
429+
)
430+
431+
XCTAssertEqual(dd_profiler_start(), 1)
432+
433+
// When
434+
_ = profiler.receive(message: .payload(OperationMessage(attributes: mockRandomAttributes(), operation: ttfdVital)), from: core)
435+
_ = profiler.receive(message: .payload(TTIDMessage(attributes: mockRandomAttributes(), ttid: ttidVital)), from: core)
436+
437+
// Then
438+
let metadata = try XCTUnwrap(core.metadata.first as? ProfileAttachments)
439+
let vitalIDs = try eventIDs(ofType: "vital", from: metadata)
440+
XCTAssertEqual(Set(vitalIDs), Set(["ttid-id", "ttfd-id"]))
441+
442+
let event = try XCTUnwrap(core.events.first as? ProfileEvent)
443+
let attributeVitalIDs = try XCTUnwrap(event.additionalAttributes?[RUMCoreContext.IDs.vitalID] as? [String])
444+
XCTAssertEqual(Set(attributeVitalIDs), Set(["ttid-id", "ttfd-id"]))
406445
}
407446

408447
func testApplicationLaunchWithOrphanedEndVital_excludesOrphanedFromProfile() throws {

‎DatadogProfiling/Tests/DatadogProfilerTests.swift‎

Lines changed: 61 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -75,6 +75,29 @@ final class DatadogProfilerTests: XCTestCase {
7575
XCTAssertFalse(result, "Continuous profiler and AppLaunch profiler consume app launch vitals")
7676
}
7777

78+
func testReceiveTTFDMessage_afterApplicationLaunchVital() {
79+
// Given
80+
let profiler = continuousProfiler()
81+
let launchVital: Vital = .mockWith(stepType: nil)
82+
83+
_ = profiler.receive(
84+
message: .payload(TTIDMessage(attributes: mockRandomAttributes(), ttid: launchVital)),
85+
from: core
86+
)
87+
88+
// When
89+
let result = profiler.receive(
90+
message: .payload(OperationMessage(
91+
attributes: mockRandomAttributes(),
92+
operation: .mockWith(stepType: nil, duration: 2_000_000_000)
93+
)),
94+
from: core
95+
)
96+
97+
// Then
98+
XCTAssertTrue(result, "Operation messages should be consumed by continuous profiler after app launch")
99+
}
100+
78101
func testReceiveLongTask() {
79102
// Given
80103
let profiler = continuousProfiler()
@@ -246,6 +269,44 @@ extension DatadogProfilerTests {
246269
withExtendedLifetime(profiler) {}
247270
}
248271

272+
func testApplicationDidEnterBackground_includesTTFDVitalFromOperationMessageInProfile() throws {
273+
// Given
274+
let dateProvider = DateProviderMock()
275+
let profiler = continuousProfiler(dateProvider: dateProvider)
276+
let ttfdVital = Vital.mockWith(
277+
id: "ttfd-id",
278+
name: "time_to_full_display",
279+
operationKey: nil,
280+
stepType: nil,
281+
date: dateProvider.now,
282+
duration: 2_000_000_000
283+
)
284+
285+
dd_profiler_start_testing(100, false, 5.seconds.dd.toInt64Nanoseconds, 0)
286+
_ = profiler.receive(message: .payload(OperationMessage(attributes: mockRandomAttributes(), operation: ttfdVital)), from: core)
287+
288+
// When
289+
core.context = .mockWith(applicationStateHistory: .mockWith(
290+
initialState: .active,
291+
date: dateProvider.now.addingTimeInterval(-1),
292+
transitions: [(state: .background, date: dateProvider.now)]
293+
))
294+
waitForProfileWrite {
295+
_ = profiler.receive(message: .context(core.context), from: core)
296+
}
297+
298+
// Then
299+
let metadata = try XCTUnwrap(core.metadata.first as? ProfileAttachments)
300+
let rumEvents = try typedRUMEvents(from: metadata)
301+
let vitalIDs = eventIDs(ofType: "vital", in: rumEvents)
302+
XCTAssertEqual(vitalIDs, ["ttfd-id"])
303+
304+
let event = try XCTUnwrap(core.events.first as? ProfileEvent)
305+
let attributeVitalIDs = try XCTUnwrap(event.additionalAttributes?[RUMCoreContext.IDs.vitalID] as? [String])
306+
XCTAssertEqual(attributeVitalIDs, ["ttfd-id"])
307+
withExtendedLifetime(profiler) {}
308+
}
309+
249310
func testApplicationDidEnterBackground_correctsAttachedVitalTimestampWithServerTimeOffset() throws {
250311
// Given
251312
let dateProvider = DateProviderMock()

‎DatadogRUM/Sources/RUMMonitor/Scopes/RUMAppLaunchManager.swift‎

Lines changed: 62 additions & 28 deletions
Original file line numberDiff line numberDiff line change
@@ -21,7 +21,11 @@ internal class RUMAppLaunchManager {
2121
private let telemetryController: AppLaunchMetricController
2222

2323
private var timeToInitialDisplay: Double?
24-
private var timeToFullDisplay: Double?
24+
private var timeToFullDisplay: (
25+
duration: TimeInterval,
26+
vitalId: String,
27+
attributes: [AttributeKey: AttributeValue]
28+
)?
2529
private var startupType: RUMVitalAppLaunchEvent.Vital.StartupType?
2630

2731
private lazy var startupTypeHandler = StartupTypeHandler(telemetryController: telemetryController)
@@ -63,18 +67,29 @@ private extension RUMAppLaunchManager {
6367

6468
self.timeToInitialDisplay = ttid
6569
let ttidVitalId = dependencies.rumUUIDGenerator.generateUnique().toRUMDataFormat
66-
6770
let profiling = context.additionalContext(ofType: ProfilingContext.self)?.ddProfiling
6871

72+
if let timeToFullDisplay {
73+
let ttfdVital = Vital(
74+
id: timeToFullDisplay.vitalId,
75+
name: RUMVitalAppLaunchEvent.Vital.AppLaunchMetric.ttfd.name,
76+
date: context.launchInfo.processLaunchDate,
77+
serverTimeOffset: context.serverTimeOffset,
78+
duration: max(ttid, timeToFullDisplay.duration).dd.toInt64Nanoseconds
79+
)
80+
81+
// TTID closes app-launch profiling, so only a TTFD reported earlier is sent here.
82+
sendTTFDMessageToProfiler(vital: ttfdVital)
83+
}
84+
6985
sendTTIDMessageToProfiler(
7086
vital: .init(
7187
id: ttidVitalId,
7288
name: RUMVitalAppLaunchEvent.Vital.AppLaunchMetric.ttid.name,
7389
date: context.launchInfo.processLaunchDate,
7490
serverTimeOffset: context.serverTimeOffset,
7591
duration: ttid.dd.toInt64Nanoseconds
76-
),
77-
activeView: activeView
92+
)
7893
)
7994

8095
dependencies.appStateManager.previousAppStateInfo { [weak self] previousAppStateInfo in
@@ -103,19 +118,20 @@ private extension RUMAppLaunchManager {
103118

104119
// The TTFD is always written after the TTID. If it exists already, means it was not written before.
105120
if let timeToFullDisplay {
106-
let ttfd = max(ttid, timeToFullDisplay)
121+
let ttfd = max(ttid, timeToFullDisplay.duration)
107122
self.writeVitalEvent(
108-
vitalId: dependencies.rumUUIDGenerator.generateUnique().toRUMDataFormat,
123+
vitalId: timeToFullDisplay.vitalId,
109124
duration: Double(ttfd.dd.toInt64Nanoseconds),
110125
appLaunchMetric: .ttfd,
111126
startupType: startupType,
112-
attributes: attributes,
127+
attributes: timeToFullDisplay.attributes,
113128
context: context,
114129
writer: writer,
115-
activeView: activeView
130+
activeView: activeView,
131+
profiling: profiling
116132
)
117133

118-
telemetryController.trackTTFD(duration: timeToFullDisplay.dd.toInt64Nanoseconds)
134+
telemetryController.trackTTFD(duration: ttfd.dd.toInt64Nanoseconds)
119135
}
120136

121137
telemetryController.sendMetric()
@@ -224,10 +240,8 @@ private extension RUMAppLaunchManager {
224240
telemetryController.track(ttidEvent: vitalEvent, context: context)
225241
}
226242

227-
func sendTTIDMessageToProfiler(vital: Vital, activeView: RUMViewScope?) {
228-
var contextAttributes: [String: Encodable] = parent.rumContextAttributes
229-
contextAttributes[RUMCoreContext.IDs.vitalID] = vital.id
230-
243+
func sendTTIDMessageToProfiler(vital: Vital) {
244+
let contextAttributes: [String: Encodable] = parent.rumContextAttributes
231245
dependencies.featureScope.send(message: .payload(TTIDMessage(attributes: contextAttributes, ttid: vital)))
232246
}
233247
}
@@ -239,23 +253,38 @@ private extension RUMAppLaunchManager {
239253
guard shouldProcess(command: command, context: context),
240254
let ttfd = time(from: command, context: context) else { return }
241255

242-
self.timeToFullDisplay = ttfd
243-
244-
if let timeToFullDisplay, let timeToInitialDisplay, let startupType {
245-
let attributes = command.globalAttributes
246-
.merging(command.attributes) { $1 }
247-
let ttfd = max(timeToInitialDisplay, timeToFullDisplay)
256+
let timeToFullDisplay = (
257+
duration: timeToInitialDisplay.map { max($0, ttfd) } ?? ttfd,
258+
vitalId: dependencies.rumUUIDGenerator.generateUnique().toRUMDataFormat,
259+
attributes: command.globalAttributes.merging(command.attributes) { $1 }
260+
)
261+
self.timeToFullDisplay = timeToFullDisplay
248262

249-
self.writeVitalEvent(
250-
vitalId: dependencies.rumUUIDGenerator.generateUnique().toRUMDataFormat,
251-
duration: Double(ttfd.dd.toInt64Nanoseconds),
252-
appLaunchMetric: .ttfd,
253-
startupType: startupType,
254-
attributes: attributes,
255-
context: context,
256-
writer: writer,
257-
activeView: activeView
263+
if timeToInitialDisplay != nil {
264+
let ttfdVital = Vital(
265+
id: timeToFullDisplay.vitalId,
266+
name: RUMVitalAppLaunchEvent.Vital.AppLaunchMetric.ttfd.name,
267+
date: context.launchInfo.processLaunchDate,
268+
serverTimeOffset: context.serverTimeOffset,
269+
duration: timeToFullDisplay.duration.dd.toInt64Nanoseconds
258270
)
271+
sendTTFDMessageToProfiler(vital: ttfdVital)
272+
273+
if let startupType {
274+
let profiling = context.additionalContext(ofType: ProfilingContext.self)?.ddProfiling
275+
276+
self.writeVitalEvent(
277+
vitalId: ttfdVital.id,
278+
duration: Double(timeToFullDisplay.duration.dd.toInt64Nanoseconds),
279+
appLaunchMetric: .ttfd,
280+
startupType: startupType,
281+
attributes: timeToFullDisplay.attributes,
282+
context: context,
283+
writer: writer,
284+
activeView: activeView,
285+
profiling: profiling
286+
)
287+
}
259288
}
260289
}
261290

@@ -274,6 +303,11 @@ private extension RUMAppLaunchManager {
274303

275304
return true
276305
}
306+
307+
func sendTTFDMessageToProfiler(vital: Vital) {
308+
let contextAttributes: [String: Encodable] = parent.rumContextAttributes
309+
dependencies.featureScope.send(message: .payload(OperationMessage(attributes: contextAttributes, operation: vital)))
310+
}
277311
}
278312

279313
private extension RUMVitalAppLaunchEvent.Vital.AppLaunchMetric {

0 commit comments

Comments
 (0)