Skip to content

Commit 462046d

Browse files
VysotskiVadimgithub-actions[bot]
VysotskiVadim
authored and
github-actions[bot]
committed
track synchronous sections in a synchronous way (#9586)
GitOrigin-RevId: c395981d55a9ffbbcc987781f264ead3ef8c3a9e
1 parent 55bb158 commit 462046d

File tree

13 files changed

+215
-75
lines changed

13 files changed

+215
-75
lines changed

‎base/src/main/java/com/mapbox/navigation/base/internal/performance/LogcatPerformanceLogging.kt‎

Lines changed: 4 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -8,11 +8,11 @@ import kotlin.time.Duration
88
private const val TAG = "PERFORMANCE"
99

1010
internal class LogcatPerformanceLogging : PerformanceObserver {
11-
override fun sectionStarted(name: String, id: Int) {
12-
logI(TAG) { "$name($id) section started" }
11+
override fun syncSectionStarted(name: String) {
12+
logI(TAG) { "$name section started" }
1313
}
1414

15-
override fun sectionCompleted(name: String, id: Int, duration: Duration?) {
16-
logI(TAG) { "$name($id) section completed in $duration" }
15+
override fun syncSectionCompleted(name: String, duration: Duration?) {
16+
logI(TAG) { "$name section completed in $duration" }
1717
}
1818
}

‎base/src/main/java/com/mapbox/navigation/base/internal/performance/PerformanceTracker.kt‎

Lines changed: 23 additions & 14 deletions
Original file line numberDiff line numberDiff line change
@@ -2,16 +2,13 @@ package com.mapbox.navigation.base.internal.performance
22

33
import androidx.annotation.RestrictTo
44
import java.util.concurrent.CopyOnWriteArraySet
5-
import java.util.concurrent.atomic.AtomicInteger
65
import kotlin.time.Duration
76
import kotlin.time.ExperimentalTime
87
import kotlin.time.measureTime
98

109
@RestrictTo(RestrictTo.Scope.LIBRARY_GROUP_PREFIX)
1110
object PerformanceTracker {
1211

13-
private val sectionNumberCounter = AtomicInteger(0)
14-
1512
internal fun addObserver(observer: PerformanceObserver) {
1613
performanceObservers.add(observer)
1714
}
@@ -24,41 +21,53 @@ object PerformanceTracker {
2421

2522
val trackingIsActive get() = performanceObservers.isNotEmpty()
2623

27-
fun sectionStarted(name: String): Int {
28-
val id = sectionNumberCounter.incrementAndGet()
24+
fun syncSectionStarted(name: String) {
2925
performanceObservers.forEach {
30-
it.sectionStarted(name, id)
26+
it.syncSectionStarted(name)
3127
}
32-
return id
3328
}
3429

35-
fun sectionCompleted(name: String, id: Int, duration: Duration?) {
30+
fun syncSectionCompleted(name: String, duration: Duration?) {
3631
performanceObservers.forEach {
37-
it.sectionCompleted(name, id, duration)
32+
it.syncSectionCompleted(name, duration)
3833
}
3934
}
4035

36+
/**
37+
* Tracks performance of a synchronous block of code.
38+
* @param block should be a synchronous function. Suspend function might break internal logic.
39+
*/
4140
@OptIn(ExperimentalTime::class)
42-
inline fun <R> trackPerformance(name: String, block: () -> R): R {
41+
inline fun <R> trackPerformanceSync(name: String, block: () -> R): R {
4342
if (!trackingIsActive) {
4443
return block()
4544
}
46-
val id = sectionStarted(name)
45+
syncSectionStarted(name)
4746
val result: R
4847
var executionTime: Duration? = null
4948
try {
5049
executionTime = measureTime {
5150
result = block()
5251
}
5352
} finally {
54-
sectionCompleted(name, id, executionTime)
53+
syncSectionCompleted(name, executionTime)
5554
}
5655
return result
5756
}
5857
}
5958

6059
@RestrictTo(RestrictTo.Scope.LIBRARY_GROUP_PREFIX)
6160
internal interface PerformanceObserver {
62-
fun sectionStarted(name: String, id: Int)
63-
fun sectionCompleted(name: String, id: Int, duration: Duration?)
61+
/**
62+
* Notifies about new synchronous section start.
63+
* @see [syncSectionCompleted]
64+
*/
65+
fun syncSectionStarted(name: String)
66+
67+
/**
68+
* Notifies about synchronous section end.
69+
* @param name always matches last started synchronous section
70+
* @see [syncSectionStarted]
71+
*/
72+
fun syncSectionCompleted(name: String, duration: Duration?)
6473
}

‎base/src/main/java/com/mapbox/navigation/base/internal/performance/TraceSectionsPerformanceObserver.kt‎

Lines changed: 6 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,6 @@
11
package com.mapbox.navigation.base.internal.performance
22

3+
import android.annotation.SuppressLint
34
import android.os.Build
45
import android.os.Trace
56
import androidx.annotation.RequiresApi
@@ -10,12 +11,13 @@ private const val MAPBOX_TRACE_ID = "mbx"
1011
@RequiresApi(Build.VERSION_CODES.Q)
1112
internal class TraceSectionsPerformanceObserver : PerformanceObserver {
1213

13-
override fun sectionStarted(name: String, id: Int) {
14-
Trace.beginAsyncSection(wrapSectionName(name), id)
14+
@SuppressLint("UnclosedTrace")
15+
override fun syncSectionStarted(name: String) {
16+
Trace.beginSection(wrapSectionName(name))
1517
}
1618

17-
override fun sectionCompleted(name: String, id: Int, duration: Duration?) {
18-
Trace.endAsyncSection(wrapSectionName(name), id)
19+
override fun syncSectionCompleted(name: String, duration: Duration?) {
20+
Trace.endSection()
1921
}
2022

2123
private fun wrapSectionName(name: String) = "$MAPBOX_TRACE_ID: $name"

‎base/src/test/java/com/mapbox/navigation/base/internal/performance/PerformanceTrackerTest.kt‎

Lines changed: 125 additions & 13 deletions
Original file line numberDiff line numberDiff line change
@@ -1,44 +1,156 @@
11
package com.mapbox.navigation.base.internal.performance
22

3-
import io.mockk.mockk
4-
import io.mockk.slot
5-
import io.mockk.verify
63
import org.junit.Assert.assertEquals
74
import org.junit.Test
85

96
class PerformanceTrackerTest {
107

118
@Test
129
fun `tracking section performance`() {
13-
val testObserver = mockk<PerformanceObserver>(relaxed = true)
10+
val testObserver = FakePerformanceObserver()
1411
PerformanceTracker.addObserver(testObserver)
15-
val sectionId = slot<Int>()
1612

17-
val result = PerformanceTracker.trackPerformance("test-section") {
18-
verify { testObserver.sectionStarted("test-section", capture(sectionId)) }
13+
val result = PerformanceTracker.trackPerformanceSync("test-section") {
1914
"test-result"
2015
}
2116

22-
verify { testObserver.sectionCompleted("test-section", sectionId.captured, any()) }
17+
assertEquals(
18+
listOf(
19+
ObserverInvocation.SyncSectionStarted("test-section"),
20+
ObserverInvocation.SyncSectionCompleted("test-section"),
21+
),
22+
testObserver.recordedCalls,
23+
)
2324
assertEquals("test-result", result)
2425
}
2526

2627
@Test
2728
fun `exception during tracking`() {
28-
val testObserver = mockk<PerformanceObserver>(relaxed = true)
29+
val testObserver = FakePerformanceObserver()
2930
PerformanceTracker.addObserver(testObserver)
3031

3132
val result: Throwable = try {
32-
PerformanceTracker.trackPerformance("test-section") {
33+
PerformanceTracker.trackPerformanceSync("test-section") {
3334
throw Throwable("test error")
3435
}
3536
} catch (t: Throwable) {
3637
t
3738
}
3839

39-
val sectionId = slot<Int>()
40-
verify { testObserver.sectionStarted("test-section", capture(sectionId)) }
41-
verify { testObserver.sectionCompleted("test-section", capture(sectionId), null) }
40+
assertEquals(
41+
listOf(
42+
ObserverInvocation.SyncSectionStarted("test-section"),
43+
ObserverInvocation.SyncSectionCompleted(
44+
"test-section",
45+
isDurationAvailable = false,
46+
),
47+
),
48+
testObserver.recordedCalls,
49+
)
4250
assertEquals("test error", result.message)
4351
}
52+
53+
@Test
54+
fun `nested tracking sections`() {
55+
val testObserver = FakePerformanceObserver()
56+
PerformanceTracker.addObserver(testObserver)
57+
58+
val result = PerformanceTracker.trackPerformanceSync("outer-section") {
59+
val inner1Result = PerformanceTracker.trackPerformanceSync("inner-section-1") {
60+
"inner1-value"
61+
}
62+
val inner2Result = PerformanceTracker.trackPerformanceSync("inner-section-2") {
63+
"inner2-value"
64+
}
65+
inner1Result + "+" + inner2Result + "-modified"
66+
}
67+
68+
assertEquals(
69+
listOf(
70+
ObserverInvocation.SyncSectionStarted("outer-section"),
71+
ObserverInvocation.SyncSectionStarted("inner-section-1"),
72+
ObserverInvocation.SyncSectionCompleted("inner-section-1"),
73+
ObserverInvocation.SyncSectionStarted("inner-section-2"),
74+
ObserverInvocation.SyncSectionCompleted("inner-section-2"),
75+
ObserverInvocation.SyncSectionCompleted("outer-section"),
76+
),
77+
testObserver.recordedCalls,
78+
)
79+
assertEquals("inner1-value+inner2-value-modified", result)
80+
}
81+
82+
@Test
83+
fun `exception during nested tracking`() {
84+
val testObserver = FakePerformanceObserver()
85+
PerformanceTracker.addObserver(testObserver)
86+
87+
val exception = try {
88+
PerformanceTracker.trackPerformanceSync("outer-section") {
89+
val inner1Result = PerformanceTracker.trackPerformanceSync("inner-section-1") {
90+
"inner1-value"
91+
}
92+
val inner2Result = PerformanceTracker.trackPerformanceSync("inner-section-2") {
93+
throw Throwable("inner section error")
94+
}
95+
inner1Result + "+" + inner2Result + "-modified"
96+
}
97+
null
98+
} catch (t: Throwable) {
99+
t
100+
}
101+
102+
assertEquals(
103+
listOf(
104+
ObserverInvocation.SyncSectionStarted("outer-section"),
105+
ObserverInvocation.SyncSectionStarted("inner-section-1"),
106+
ObserverInvocation.SyncSectionCompleted("inner-section-1"),
107+
ObserverInvocation.SyncSectionStarted("inner-section-2"),
108+
ObserverInvocation.SyncSectionCompleted(
109+
"inner-section-2",
110+
isDurationAvailable = false,
111+
),
112+
ObserverInvocation.SyncSectionCompleted(
113+
"outer-section",
114+
isDurationAvailable = false,
115+
),
116+
),
117+
testObserver.recordedCalls,
118+
)
119+
assertEquals("inner section error", exception?.message)
120+
}
121+
}
122+
123+
private sealed class ObserverInvocation {
124+
data class SyncSectionStarted(val sectionName: String) : ObserverInvocation()
125+
data class SyncSectionCompleted(
126+
val sectionName: String,
127+
val isDurationAvailable: Boolean = true,
128+
) : ObserverInvocation()
129+
}
130+
131+
/**
132+
* Fake observer implementation used for testing instead of mockk.
133+
* * Mockk's order verification (verifyOrder/verifySequence) was unreliable for this test case
134+
* due to issues with value classes (Duration) and nested call sequences. The fake observer
135+
* provides a more reliable and readable approach to verify the exact sequence of
136+
* performance tracking invocations.
137+
*/
138+
private class FakePerformanceObserver : PerformanceObserver {
139+
val recordedCalls = mutableListOf<ObserverInvocation>()
140+
141+
override fun syncSectionStarted(name: String) {
142+
recordedCalls.add(ObserverInvocation.SyncSectionStarted(name))
143+
}
144+
145+
override fun syncSectionCompleted(
146+
name: String,
147+
duration: kotlin.time.Duration?,
148+
) {
149+
recordedCalls.add(
150+
ObserverInvocation.SyncSectionCompleted(
151+
name,
152+
isDurationAvailable = duration != null,
153+
),
154+
)
155+
}
44156
}

‎base/src/test/java/com/mapbox/navigation/base/utils/NavigationPerformanceTest.kt‎

Lines changed: 3 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -20,11 +20,11 @@ class NavigationPerformanceTest {
2020

2121
@Test
2222
fun `tracking performance in different logging states`() {
23-
PerformanceTracker.trackPerformance("test-section1") { }
23+
PerformanceTracker.trackPerformanceSync("test-section1") { }
2424
NavigationPerformance.performanceInfoLoggingEnabled(true)
25-
PerformanceTracker.trackPerformance("test-section2") { }
25+
PerformanceTracker.trackPerformanceSync("test-section2") { }
2626
NavigationPerformance.performanceInfoLoggingEnabled(false)
27-
PerformanceTracker.trackPerformance("test-section3") { }
27+
PerformanceTracker.trackPerformanceSync("test-section3") { }
2828

2929
verify(exactly = 0) { mockLogger.logI(match { it.contains("test-section1") }, any()) }
3030
verify(exactly = 2) { mockLogger.logI(match { it.contains("test-section2") }, any()) }

‎navigation/src/main/java/com/mapbox/navigation/core/MapboxNavigation.kt‎

Lines changed: 15 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -469,7 +469,10 @@ class MapboxNavigation @VisibleForTesting internal constructor(
469469
internal val skuIdProvider: SkuIdProvider
470470

471471
init {
472-
PerformanceTracker.trackPerformance("MapboxNavigationSDKInitializerImpl") {
472+
val initSectionName = "MapboxNavigation#init-"
473+
PerformanceTracker.trackPerformanceSync(
474+
"${initSectionName}MapboxNavigationSDKInitializerImpl",
475+
) {
473476
BaseMapboxInitializer.init(MapboxNavigationSDKInitializerImpl::class.java)
474477
}
475478
if (hasInstance) {
@@ -503,7 +506,7 @@ class MapboxNavigation @VisibleForTesting internal constructor(
503506
tilesConfig,
504507
config,
505508
historyRecorderHandles.composite,
506-
PerformanceTracker.trackPerformance("createOfflineCacheHandle") {
509+
PerformanceTracker.trackPerformanceSync("${initSectionName}createOfflineCacheHandle") {
507510
createOfflineCacheHandle(config)
508511
},
509512
NavigationComponentProvider.createEventsMetadataInterface(
@@ -515,7 +518,9 @@ class MapboxNavigation @VisibleForTesting internal constructor(
515518

516519
val routeParsingManager = createRouteParsingManager()
517520
routeParsingManager.setPrepareForParsingAction(this::prepareNavigationForRoutesParsing)
518-
routerWrapper = PerformanceTracker.trackPerformance("RouterWrapper") {
521+
routerWrapper = PerformanceTracker.trackPerformanceSync(
522+
"${initSectionName}RouterWrapper",
523+
) {
519524
RouterWrapper(
520525
navigator.getRouter(),
521526
threadController,
@@ -524,7 +529,7 @@ class MapboxNavigation @VisibleForTesting internal constructor(
524529
)
525530
}
526531

527-
etcGateAPI = PerformanceTracker.trackPerformance("etcGateAPI") {
532+
etcGateAPI = PerformanceTracker.trackPerformanceSync("${initSectionName}etcGateAPI") {
528533
EtcGateApi(navigator.experimental)
529534
}
530535

@@ -539,7 +544,9 @@ class MapboxNavigation @VisibleForTesting internal constructor(
539544
historyRecordingStateHandler,
540545
)
541546

542-
val notification: TripNotification = PerformanceTracker.trackPerformance("notification") {
547+
val notification: TripNotification = PerformanceTracker.trackPerformanceSync(
548+
"${initSectionName}notification",
549+
) {
543550
MapboxModuleProvider
544551
.createModule(
545552
MapboxModuleType.NavigationTripNotification,
@@ -688,8 +695,8 @@ class MapboxNavigation @VisibleForTesting internal constructor(
688695

689696
roadObjectsStore = RoadObjectsStore(navigator)
690697
graphAccessor = GraphAccessor(navigator)
691-
tilesetDescriptorFactory = PerformanceTracker.trackPerformance(
692-
"MapboxNavigation#init-tilesetDescriptorFactory",
698+
tilesetDescriptorFactory = PerformanceTracker.trackPerformanceSync(
699+
"${initSectionName}tilesetDescriptorFactory",
693700
) {
694701
TilesetDescriptorFactory(
695702
navigationOptions.routingTilesOptions,
@@ -2138,7 +2145,7 @@ class MapboxNavigation @VisibleForTesting internal constructor(
21382145

21392146
private fun createHistoryRecorderHandles(
21402147
config: ConfigHandle,
2141-
) = PerformanceTracker.trackPerformance("createHistoryRecorderHandles") {
2148+
) = PerformanceTracker.trackPerformanceSync("createHistoryRecorderHandles") {
21422149
NavigatorLoader.createHistoryRecorderHandles(
21432150
config,
21442151
historyRecorder.fileDirectory(),

0 commit comments

Comments
 (0)