Skip to content

Commit 4ba5666

Browse files
lawmichalawmicha
authored
fix(DataStore): log metrics for ReconcileAndLocalSaveOperation (#1215)
* fix(DataStore): log metrics for ReconcileAndLocalSaveOperation * fix(DataStore): setting nil values in defer
1 parent 754359f commit 4ba5666

File tree

5 files changed

+155
-8
lines changed

5 files changed

+155
-8
lines changed

‎AmplifyPlugins/DataStore/AWSDataStoreCategoryPlugin/Sync/SubscriptionSync/ReconcileAndLocalSave/ReconcileAndLocalSaveOperation.swift‎

Lines changed: 23 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -34,6 +34,7 @@ class ReconcileAndLocalSaveOperation: AsynchronousOperation {
3434
private let stateMachine: StateMachine<State, Action>
3535
private let remoteModel: RemoteModel
3636
private let modelSchema: ModelSchema
37+
private let stopwatch: Stopwatch
3738
private var stateMachineSink: AnyCancellable?
3839

3940
private let mutationEventPublisher: PassthroughSubject<ReconcileAndLocalSaveOperationEvent, DataStoreError>
@@ -48,6 +49,7 @@ class ReconcileAndLocalSaveOperation: AsynchronousOperation {
4849
self.modelSchema = modelSchema
4950
self.remoteModel = remoteModel
5051
self.storageAdapter = storageAdapter
52+
self.stopwatch = Stopwatch()
5153
self.stateMachine = stateMachine ?? StateMachine(initialState: .waiting,
5254
resolver: Resolver.resolve(currentState:action:))
5355
self.mutationEventPublisher = PassthroughSubject<ReconcileAndLocalSaveOperationEvent, DataStoreError>()
@@ -74,6 +76,7 @@ class ReconcileAndLocalSaveOperation: AsynchronousOperation {
7476
return
7577
}
7678

79+
stopwatch.start()
7780
stateMachine.notify(action: .started(remoteModel))
7881
}
7982

@@ -109,6 +112,9 @@ class ReconcileAndLocalSaveOperation: AsynchronousOperation {
109112
case .finished:
110113
// Maybe we have to notify the Hub?
111114
notifyFinished()
115+
if log.logLevel == .debug {
116+
log.debug("total time: \(stopwatch.stop())s")
117+
}
112118
finish()
113119
}
114120

@@ -140,6 +146,11 @@ class ReconcileAndLocalSaveOperation: AsynchronousOperation {
140146
}
141147

142148
let queriedAction = Action.queried(remoteModel, localMetadata)
149+
150+
if log.logLevel == .debug {
151+
log.debug("query local metadata: \(stopwatch.lap())s")
152+
}
153+
143154
stateMachine.notify(action: queriedAction)
144155
}
145156

@@ -162,7 +173,9 @@ class ReconcileAndLocalSaveOperation: AsynchronousOperation {
162173
case .success(let mutationEvents):
163174
pendingMutations = mutationEvents
164175
}
165-
176+
if log.logLevel == .debug {
177+
log.debug("query pending mutations: \(stopwatch.lap())s")
178+
}
166179
let disposition = RemoteSyncReconciler.reconcile(remoteModel: remoteModel,
167180
to: localMetadata,
168181
pendingMutations: pendingMutations)
@@ -192,8 +205,6 @@ class ReconcileAndLocalSaveOperation: AsynchronousOperation {
192205
private func apply(remoteModel: RemoteModel) {
193206
if log.logLevel == .verbose {
194207
log.verbose("\(#function): remoteModel")
195-
} else if log.logLevel == .debug {
196-
log.debug(#function)
197208
}
198209

199210
guard !isCancelled else {
@@ -228,6 +239,9 @@ class ReconcileAndLocalSaveOperation: AsynchronousOperation {
228239
modelSchema: modelSchema,
229240
withId: remoteModel.model.id,
230241
predicate: nil) { response in
242+
if log.logLevel == .debug {
243+
log.debug("delete model: \(stopwatch.lap())s")
244+
}
231245
switch response {
232246
case .failure(let dataStoreError):
233247
let errorAction = Action.errored(dataStoreError)
@@ -241,6 +255,9 @@ class ReconcileAndLocalSaveOperation: AsynchronousOperation {
241255
private func saveCreateOrUpdateMutation(storageAdapter: StorageEngineAdapter, remoteModel: RemoteModel) {
242256
log.verbose(#function)
243257
storageAdapter.save(untypedModel: remoteModel.model.instance) { response in
258+
if self.log.logLevel == .debug {
259+
self.log.debug("save model: \(self.stopwatch.lap())s")
260+
}
244261
switch response {
245262
case .failure(let dataStoreError):
246263
let errorAction = Action.errored(dataStoreError)
@@ -274,6 +291,9 @@ class ReconcileAndLocalSaveOperation: AsynchronousOperation {
274291
return
275292
}
276293
storageAdapter.save(remoteModel.syncMetadata, condition: nil) { result in
294+
if self.log.logLevel == .debug {
295+
self.log.debug("save metadata: \(self.stopwatch.lap())s")
296+
}
277297
switch result {
278298
case .failure(let dataStoreError):
279299
let errorAction = Action.errored(dataStoreError)
@@ -358,7 +378,6 @@ class ReconcileAndLocalSaveOperation: AsynchronousOperation {
358378

359379
return pendingMutationResult
360380
}
361-
362381
}
363382

364383
@available(iOS 13.0, *)

‎AmplifyPlugins/DataStore/AWSDataStoreCategoryPlugin/Sync/Support/Stopwatch.swift‎

Lines changed: 65 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,65 @@
1+
//
2+
// Copyright Amazon.com Inc. or its affiliates.
3+
// All Rights Reserved.
4+
//
5+
// SPDX-License-Identifier: Apache-2.0
6+
//
7+
8+
import Foundation
9+
10+
/// A simple implementation of a stopwatch used for gathering metrics of elapsed time.
11+
class Stopwatch {
12+
let lock = NSLock()
13+
var startTime: DispatchTime?
14+
var lapStart: DispatchTime?
15+
16+
/// Marks the beginning of the stopwatch.
17+
/// If called multiple times, the latest call will overwrite the previous start values.
18+
func start() {
19+
lock.lock()
20+
defer {
21+
lock.unlock()
22+
}
23+
startTime = DispatchTime.now()
24+
lapStart = startTime
25+
}
26+
27+
/// Returns the elapsed time since `start()` or the last `lap()` was called.
28+
///
29+
/// - Returns: the elapsed time in seconds
30+
func lap() -> Double {
31+
lock.lock()
32+
defer {
33+
lock.unlock()
34+
}
35+
guard let lapStart = lapStart else {
36+
return 0
37+
}
38+
39+
let lapEnd = DispatchTime.now()
40+
let lapTime = Double(lapEnd.uptimeNanoseconds - lapStart.uptimeNanoseconds) / 1_000_000_000.0
41+
self.lapStart = lapEnd
42+
return lapTime
43+
}
44+
45+
/// Returns the total time from the initial `start()` call and resets the stopwatch.
46+
///
47+
/// - Returns: the total time in seconds that the stop watch has been running, or 0
48+
func stop() -> Double {
49+
lock.lock()
50+
defer {
51+
lapStart = nil
52+
startTime = nil
53+
lock.unlock()
54+
}
55+
guard let startTime = startTime else {
56+
lapStart = nil
57+
return 0
58+
}
59+
let endTime = DispatchTime.now()
60+
let total = Double(endTime.uptimeNanoseconds - startTime.uptimeNanoseconds) / 1_000_000_000.0
61+
self.startTime = nil
62+
lapStart = nil
63+
return total
64+
}
65+
}

‎AmplifyPlugins/DataStore/AWSDataStoreCategoryPluginTests/Sync/Support/StopwatchTests.swift‎

Lines changed: 47 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,47 @@
1+
//
2+
// Copyright Amazon.com Inc. or its affiliates.
3+
// All Rights Reserved.
4+
//
5+
// SPDX-License-Identifier: Apache-2.0
6+
//
7+
8+
import XCTest
9+
@testable import AWSDataStoreCategoryPlugin
10+
11+
class StopwatchTests: XCTestCase {
12+
13+
func testStartLapStop() throws {
14+
let stopwatch = Stopwatch()
15+
XCTAssertNil(stopwatch.startTime)
16+
XCTAssertNil(stopwatch.lapStart)
17+
18+
stopwatch.start()
19+
XCTAssertNotNil(stopwatch.startTime)
20+
XCTAssertNotNil(stopwatch.lapStart)
21+
22+
let lap1 = stopwatch.lap()
23+
XCTAssertTrue(lap1 > 0)
24+
25+
let lap2 = stopwatch.lap()
26+
XCTAssertTrue(lap2 > 0)
27+
28+
let total = stopwatch.stop()
29+
XCTAssertTrue(total > 0)
30+
let totalLap = lap1 + lap2
31+
XCTAssertTrue(total > totalLap)
32+
33+
XCTAssertNil(stopwatch.startTime)
34+
XCTAssertNil(stopwatch.lapStart)
35+
}
36+
37+
func testConcurrentLap() {
38+
let stopwatch = Stopwatch()
39+
stopwatch.start()
40+
DispatchQueue.concurrentPerform(iterations: 1_000) { _ in
41+
let lap1 = stopwatch.lap()
42+
XCTAssertTrue(lap1 > 0)
43+
let lap2 = stopwatch.lap()
44+
XCTAssertTrue(lap2 > 0)
45+
}
46+
}
47+
}

‎AmplifyPlugins/DataStore/DataStoreCategoryPlugin.xcodeproj/project.pbxproj‎

Lines changed: 19 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -57,6 +57,8 @@
5757
2149E61423886C7F00873955 /* LaunchScreen.storyboard in Resources */ = {isa = PBXBuildFile; fileRef = 2149E61223886C7F00873955 /* LaunchScreen.storyboard */; };
5858
2149E62223886CEE00873955 /* AWSDataStoreCategoryPlugin.framework in Frameworks */ = {isa = PBXBuildFile; fileRef = 2149E59B238867E100873955 /* AWSDataStoreCategoryPlugin.framework */; };
5959
2149E62D23886D3900873955 /* SyncMetadataTests.swift in Sources */ = {isa = PBXBuildFile; fileRef = 2149E62B23886D3900873955 /* SyncMetadataTests.swift */; };
60+
214B6B65264B0D6700A9311D /* Stopwatch.swift in Sources */ = {isa = PBXBuildFile; fileRef = 214B6B64264B0D6700A9311D /* Stopwatch.swift */; };
61+
214B6B68264B157500A9311D /* StopwatchTests.swift in Sources */ = {isa = PBXBuildFile; fileRef = 214B6B67264B157500A9311D /* StopwatchTests.swift */; };
6062
217D61752578AF85009F0639 /* DataStoreConnectionScenario2Tests.swift in Sources */ = {isa = PBXBuildFile; fileRef = 217D61742578AF85009F0639 /* DataStoreConnectionScenario2Tests.swift */; };
6163
217D622225798ED3009F0639 /* DataStoreConnectionScenario1Tests.swift in Sources */ = {isa = PBXBuildFile; fileRef = 217D622125798ED3009F0639 /* DataStoreConnectionScenario1Tests.swift */; };
6264
217D622B2579E15F009F0639 /* DataStoreConnectionScenario5Tests.swift in Sources */ = {isa = PBXBuildFile; fileRef = 217D62282579E15F009F0639 /* DataStoreConnectionScenario5Tests.swift */; };
@@ -311,6 +313,8 @@
311313
2149E61D23886CEE00873955 /* AWSDataStoreCategoryPluginIntegrationTests.xctest */ = {isa = PBXFileReference; explicitFileType = wrapper.cfbundle; includeInIndex = 0; path = AWSDataStoreCategoryPluginIntegrationTests.xctest; sourceTree = BUILT_PRODUCTS_DIR; };
312314
2149E62123886CEE00873955 /* Info.plist */ = {isa = PBXFileReference; lastKnownFileType = text.plist.xml; path = Info.plist; sourceTree = "<group>"; };
313315
2149E62B23886D3900873955 /* SyncMetadataTests.swift */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.swift; path = SyncMetadataTests.swift; sourceTree = "<group>"; };
316+
214B6B64264B0D6700A9311D /* Stopwatch.swift */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.swift; path = Stopwatch.swift; sourceTree = "<group>"; };
317+
214B6B67264B157500A9311D /* StopwatchTests.swift */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.swift; path = StopwatchTests.swift; sourceTree = "<group>"; };
314318
217D61742578AF85009F0639 /* DataStoreConnectionScenario2Tests.swift */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.swift; path = DataStoreConnectionScenario2Tests.swift; sourceTree = "<group>"; };
315319
217D622125798ED3009F0639 /* DataStoreConnectionScenario1Tests.swift */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.swift; path = DataStoreConnectionScenario1Tests.swift; sourceTree = "<group>"; };
316320
217D62282579E15F009F0639 /* DataStoreConnectionScenario5Tests.swift */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.swift; path = DataStoreConnectionScenario5Tests.swift; sourceTree = "<group>"; };
@@ -706,6 +710,14 @@
706710
path = AWSDataStoreCategoryPluginIntegrationTests;
707711
sourceTree = "<group>";
708712
};
713+
214B6B66264B156200A9311D /* Support */ = {
714+
isa = PBXGroup;
715+
children = (
716+
214B6B67264B157500A9311D /* StopwatchTests.swift */,
717+
);
718+
path = Support;
719+
sourceTree = "<group>";
720+
};
709721
217D61552578AEB0009F0639 /* Connection */ = {
710722
isa = PBXGroup;
711723
children = (
@@ -850,6 +862,7 @@
850862
FA8F4D1D2395AF7600861D91 /* DataStoreError+Plugin.swift */,
851863
FA8F4D212395B11700861D91 /* MutationEvent+Query.swift */,
852864
FA3841E823889D440070AD5B /* StateMachine.swift */,
865+
214B6B64264B0D6700A9311D /* Stopwatch.swift */,
853866
);
854867
path = Support;
855868
sourceTree = "<group>";
@@ -881,14 +894,15 @@
881894
children = (
882895
2149E5F1238869CF00873955 /* APICategoryDependencyTests.swift */,
883896
FA0427CF2396CDD800D25AB0 /* DataStoreHubTests.swift */,
897+
FAE01F9923997BD900B468DA /* InitialSync */,
884898
2149E5F3238869CF00873955 /* LocalSubscriptionTests.swift */,
885899
B4D59DDC2554BBE7009B9235 /* LocalSubscriptionWithJSONModelTests.swift */,
886-
6BDC223F23E21A4E007C8410 /* RemoteSyncEngineTests.swift */,
887-
6BC4FDA723A899180027D20C /* RequestRetryablePolicyTests.swift */,
888-
FAE01F9923997BD900B468DA /* InitialSync */,
889900
FAE01F9823997B7600B468DA /* MutationQueue */,
890901
FAE01F9A23997C0600B468DA /* RemoteSync */,
902+
6BDC223F23E21A4E007C8410 /* RemoteSyncEngineTests.swift */,
903+
6BC4FDA723A899180027D20C /* RequestRetryablePolicyTests.swift */,
891904
FAE01F9B23997C3700B468DA /* SubscriptionSync */,
905+
214B6B66264B156200A9311D /* Support */,
892906
);
893907
path = Sync;
894908
sourceTree = "<group>";
@@ -1608,6 +1622,7 @@
16081622
FACD624A2397415C004AF037 /* ModelReconciliationQueue.swift in Sources */,
16091623
FA3B3EFF238F13B2002EFDB3 /* MutationEventIngester.swift in Sources */,
16101624
D8D1DED4252E2CB400681DA8 /* ReadyEventEmitter.swift in Sources */,
1625+
214B6B65264B0D6700A9311D /* Stopwatch.swift in Sources */,
16111626
FAC010EE23956DDE00FCE7BB /* RemoteSyncReconciler.swift in Sources */,
16121627
FA3841E523889D280070AD5B /* IncomingEventReconciliationQueue.swift in Sources */,
16131628
213481D4242ABA86001966DE /* ProcessMutationErrorFromCloudOperation.swift in Sources */,
@@ -1747,6 +1762,7 @@
17471762
B9FAA142238C6082009414B4 /* BaseDataStoreTests.swift in Sources */,
17481763
6B7743E7259071C8001469F5 /* StorageEngineTestsHasMany.swift in Sources */,
17491764
6BE9D6F125A6643100AB5C9A /* StorageEngineTestsHasOne.swift in Sources */,
1765+
214B6B68264B157500A9311D /* StopwatchTests.swift in Sources */,
17501766
6B52DC9624478E75007F5AD3 /* MockModelReconciliationQueue.swift in Sources */,
17511767
FA4A955B239AD3F4008E876E /* Foundation+TestExtensions.swift in Sources */,
17521768
21A4EE77259D510400E1047D /* DataStoreListProviderFunctionalTests.swift in Sources */,

‎AmplifyPlugins/DataStore/Podfile.lock‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -118,4 +118,4 @@ SPEC CHECKSUMS:
118118

119119
PODFILE CHECKSUM: fb973c73bd5a639b441e0a01717635b41533ab26
120120

121-
COCOAPODS: 1.9.3
121+
COCOAPODS: 1.10.1

0 commit comments

Comments
 (0)