Skip to content

Commit 273e06e

Browse files
authored
Fix CPU profiler tab time estimates (#8941)
Fixes #8870. This fixes all views on the cpu profiler tab to take into account time where no code was executing (no samples taken). The approach taken is to use the sampleCount * medianObservedSamplePeriod to get the total duration, which is then used in all the other calculations, instead of the total duration of the profile. This isn't necessarily perfect but should be much better than what we had before, and I don't know that we can do any better. We use the median observed sample period because it is more accurate and reliable than the reported sample period. For the reproduction case in the issue you now get this: <img width="1247" alt="Screenshot 2025-02-26 at 2 21 13 PM" src="https://github.com/user-attachments/assets/aca32479-b6d0-4298-9bdb-7f25b4990a22" /> Instead of this: <img width="1273" alt="Screenshot 2025-02-24 at 11 36 12 AM" src="https://github.com/user-attachments/assets/b106296c-07c4-4542-b85d-02a8105dba72" />
1 parent a33575c commit 273e06e

8 files changed

Lines changed: 162 additions & 19 deletions

File tree

packages/devtools_app/lib/src/screens/profiler/cpu_profile_model.dart

Lines changed: 74 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -5,6 +5,7 @@
55
import 'package:devtools_shared/devtools_shared.dart';
66
import 'package:flutter/foundation.dart';
77
import 'package:logging/logging.dart';
8+
import 'package:meta/meta.dart';
89
import 'package:vm_service/vm_service.dart' as vm_service;
910

1011
import '../../shared/charts/flame_chart.dart';
@@ -170,9 +171,24 @@ class CpuProfileData with Serializable {
170171

171172
factory CpuProfileData.fromJson(Map<String, Object?> json_) {
172173
final json = _CpuProfileDataJson(json_);
174+
175+
// All CPU samples.
176+
final samples = json.traceEvents ?? <CpuSampleEvent>[];
177+
178+
// Sort the samples so we can compute the observed time difference between
179+
// each sample.
180+
samples.sort((a, b) => a.timestampMicros!.compareTo(b.timestampMicros!));
181+
182+
// Prefer the approximate observed median time between samples over the
183+
// reported sample period.
184+
//
185+
// See https://github.com/flutter/devtools/pull/8941 for more information.
186+
final samplePeriod =
187+
observedSamplePeriod(samples) ?? json.samplePeriod ?? 0;
188+
173189
final profileMetaData = CpuProfileMetaData(
174190
sampleCount: json.sampleCount ?? 0,
175-
samplePeriod: json.samplePeriod ?? 0,
191+
samplePeriod: samplePeriod,
176192
stackDepth: json.stackDepth ?? 0,
177193
time:
178194
(json.timeOriginMicros != null && json.timeExtentMicros != null)
@@ -211,9 +227,6 @@ class CpuProfileData with Serializable {
211227
stackFrames[stackFrame.id] = stackFrame;
212228
}
213229

214-
// Initialize all CPU samples.
215-
final samples = json.traceEvents ?? [];
216-
217230
return CpuProfileData._(
218231
stackFrames: stackFrames,
219232
cpuSamples: samples,
@@ -379,9 +392,7 @@ class CpuProfileData with Serializable {
379392
.toList();
380393
assert(samplesWithTag.isNotEmpty);
381394

382-
final originalTime = originalData.profileMetaData.time!.duration;
383-
final microsPerSample =
384-
originalTime.inMicroseconds / originalData.profileMetaData.sampleCount;
395+
final microsPerSample = originalData.profileMetaData.samplePeriod;
385396
final newSampleCount = samplesWithTag.length;
386397
final metaData = originalData.profileMetaData.copyWith(
387398
sampleCount: newSampleCount,
@@ -486,7 +497,7 @@ class CpuProfileData with Serializable {
486497
return null;
487498
}
488499

489-
final originalTime = originalData.profileMetaData.time!.duration;
500+
final originalTime = originalData.profileMetaData.measuredDuration;
490501
final microsPerSample =
491502
originalTime.inMicroseconds / originalData.profileMetaData.sampleCount;
492503
final updatedMetaData = originalData.profileMetaData.copyWith(
@@ -791,13 +802,11 @@ extension type _CpuProfileDataJson(Map<String, Object?> json) {
791802
class CpuProfileMetaData extends ProfileMetaData {
792803
CpuProfileMetaData({
793804
required super.sampleCount,
794-
required this.samplePeriod,
805+
required super.samplePeriod,
795806
required this.stackDepth,
796807
required super.time,
797808
});
798809

799-
final int samplePeriod;
800-
801810
final int stackDepth;
802811

803812
CpuProfileMetaData copyWith({
@@ -1386,3 +1395,57 @@ extension on vm_service.CpuSamples {
13861395
return traceObject;
13871396
}
13881397
}
1398+
1399+
/// Efficiently approximates the observed sample period of [samples], by
1400+
/// calculating the approximate median time difference between each sample.
1401+
///
1402+
/// The [samples] must be sorted by timestampMicros before calling this
1403+
/// function.
1404+
///
1405+
/// If there are fewer than 100 samples, returns `null`, because there isn't
1406+
/// enough data to be confident about the observed sample period.
1407+
///
1408+
/// This does not return the exact median, but instead the median of medians
1409+
/// of groups of 5 elements, which makes the algorithm much more efficient.
1410+
@visibleForTesting
1411+
int? observedSamplePeriod(List<CpuSampleEvent> samples) {
1412+
if (samples.length < 100) return null;
1413+
1414+
// To compute the median efficiently, we compute the median of groups of 5
1415+
// elements, and then grab the median of those medians by sorting, which
1416+
// brings us a linear time complexity while retaining high accuracy.
1417+
final mediansOfGroupsOf5 = <int>[];
1418+
for (var i = 1; i + 5 < samples.length; i += 5) {
1419+
// The time diff between the sample at index and the previous sample.
1420+
int diff(int index) {
1421+
final result =
1422+
samples[index].timestampMicros! - samples[index - 1].timestampMicros!;
1423+
assert(result >= 0);
1424+
return result;
1425+
}
1426+
1427+
mediansOfGroupsOf5.add(
1428+
_median5(diff(i), diff(i + 1), diff(i + 2), diff(i + 3), diff(i + 4)),
1429+
);
1430+
}
1431+
mediansOfGroupsOf5.sort();
1432+
return mediansOfGroupsOf5[(mediansOfGroupsOf5.length / 2).floor()];
1433+
}
1434+
1435+
/// Computes the median of 5 numbers without allocating a list
1436+
/// or actually sorting all the numbers.
1437+
int _median5(int a, int b, int c, int d, int e) {
1438+
while (true) {
1439+
if (c < a) {
1440+
(a, c) = (c, a);
1441+
} else if (c < b) {
1442+
(b, c) = (c, b);
1443+
} else if (c > d) {
1444+
(c, d) = (d, c);
1445+
} else if (c > e) {
1446+
(c, e) = (e, c);
1447+
} else {
1448+
return c;
1449+
}
1450+
}
1451+
}

packages/devtools_app/lib/src/screens/profiler/panes/method_table/method_table_model.dart

Lines changed: 3 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -68,15 +68,16 @@ class MethodTableGraphNode extends GraphNode with SearchableDataMixin {
6868

6969
Duration get selfTime => Duration(
7070
microseconds:
71-
(selfTimeRatio * profileMetaData.time!.duration.inMicroseconds).round(),
71+
(selfTimeRatio * profileMetaData.measuredDuration.inMicroseconds)
72+
.round(),
7273
);
7374

7475
double get totalTimeRatio =>
7576
safeDivide(totalCount, profileMetaData.sampleCount);
7677

7778
Duration get totalTime => Duration(
7879
microseconds:
79-
(totalTimeRatio * profileMetaData.time!.duration.inMicroseconds)
80+
(totalTimeRatio * profileMetaData.measuredDuration.inMicroseconds)
8081
.round(),
8182
);
8283

packages/devtools_app/lib/src/shared/config_specific/framework_initialize/_framework_initialize_web.dart

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -98,11 +98,11 @@ void _sendKeyPressToParent(KeyboardEvent event) {
9898
class BrowserStorage implements Storage {
9999
@override
100100
Future<String?> getValue(String key) async {
101-
return window.localStorage[key];
101+
return window.localStorage.getItem(key);
102102
}
103103

104104
@override
105105
Future<void> setValue(String key, String value) async {
106-
window.localStorage[key] = value;
106+
window.localStorage.setItem(key, value);
107107
}
108108
}

packages/devtools_app/lib/src/shared/utils/profiler_utils.dart

Lines changed: 24 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -42,7 +42,7 @@ mixin ProfilableDataMixin<T extends TreeNode<T>> on TreeNode<T> {
4242

4343
late Duration totalTime = Duration(
4444
microseconds:
45-
(totalTimeRatio * profileMetaData.time!.duration.inMicroseconds)
45+
(totalTimeRatio * profileMetaData.measuredDuration.inMicroseconds)
4646
.round(),
4747
);
4848

@@ -53,7 +53,8 @@ mixin ProfilableDataMixin<T extends TreeNode<T>> on TreeNode<T> {
5353

5454
late Duration selfTime = Duration(
5555
microseconds:
56-
(selfTimeRatio * profileMetaData.time!.duration.inMicroseconds).round(),
56+
(selfTimeRatio * profileMetaData.measuredDuration.inMicroseconds)
57+
.round(),
5758
);
5859

5960
double get inclusiveSampleRatio =>
@@ -97,11 +98,31 @@ mixin ProfilableDataMixin<T extends TreeNode<T>> on TreeNode<T> {
9798
}
9899

99100
class ProfileMetaData {
100-
const ProfileMetaData({required this.sampleCount, required this.time});
101+
const ProfileMetaData({
102+
required this.sampleCount,
103+
required this.samplePeriod,
104+
required this.time,
105+
});
101106

107+
/// The total number of samples in this profile.
102108
final int sampleCount;
103109

110+
/// The sample period for this profile in microseconds.
111+
final int samplePeriod;
112+
113+
/// The time range of the entire profile.
114+
///
115+
/// Note that there may be periods of time with no samples, so the duration
116+
/// of this time should not be used in any calculations for how long a given
117+
/// sample took, instead use [measuredDuration].
104118
final TimeRange? time;
119+
120+
/// The amount of time measured by all the samples taken in this profile.
121+
///
122+
/// This is different from [time] which is just the start to end time of the
123+
/// entire profile which includes time where no samples were taken.
124+
Duration get measuredDuration =>
125+
Duration(microseconds: sampleCount * samplePeriod);
105126
}
106127

107128
/// Process for converting a [ProfilableDataMixin] into a bottom-up

packages/devtools_app/release_notes/NEXT_RELEASE_NOTES.md

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -40,6 +40,8 @@ TODO: Remove this section if there are not any general updates.
4040
* [#8892](https://github.com/flutter/devtools/pull/8892)
4141
* [#8878](https://github.com/flutter/devtools/pull/8878)
4242
* [#8839](https://github.com/flutter/devtools/pull/8839)
43+
* Fixed incorrect duration calculations when there is time during which no
44+
samples were taken - [#8941](https://github.com/flutter/devtools/pull/8941).
4345

4446
## Memory updates
4547

packages/devtools_app/test/screens/cpu_profiler/cpu_profile_model_test.dart

Lines changed: 50 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -4,6 +4,7 @@
44

55
import 'package:devtools_app/src/screens/profiler/cpu_profile_model.dart';
66
import 'package:devtools_app/src/service/service_manager.dart';
7+
import 'package:devtools_app/src/shared/primitives/trace_event.dart';
78
import 'package:devtools_app/src/shared/primitives/utils.dart';
89
import 'package:devtools_app_shared/utils.dart';
910
import 'package:devtools_test/devtools_test.dart';
@@ -438,4 +439,53 @@ void main() {
438439
expect(stackFrameC.matches(stackFrameG), isFalse);
439440
expect(stackFrameC.matches(stackFrameC4), isFalse);
440441
});
442+
443+
group('observedSamplePeriod', () {
444+
CpuSampleEvent sampleEventWithTimestamp(int timestampMicros) {
445+
return CpuSampleEvent.fromJson({
446+
CpuProfileData.stackFrameIdKey: '0',
447+
ChromeTraceEvent.timestampKey: timestampMicros,
448+
});
449+
}
450+
451+
test('returns null if less than 100 samples', () {
452+
expect(observedSamplePeriod([]), isNull);
453+
expect(
454+
observedSamplePeriod(List.filled(99, sampleEventWithTimestamp(1))),
455+
isNull,
456+
);
457+
expect(
458+
observedSamplePeriod(
459+
List.generate(100, (i) => sampleEventWithTimestamp(i)),
460+
),
461+
1,
462+
);
463+
});
464+
465+
test('asserts that samples are sorted', () {
466+
expect(
467+
() => observedSamplePeriod([
468+
sampleEventWithTimestamp(10),
469+
sampleEventWithTimestamp(5),
470+
// Need at least 100 elements for anything to happen.
471+
...List.filled(100, sampleEventWithTimestamp(1)),
472+
]),
473+
throwsA(isA<AssertionError>()),
474+
);
475+
});
476+
477+
test('computes an approximate time difference median', () {
478+
final samples = List.generate(
479+
100,
480+
(i) => sampleEventWithTimestamp(i * i),
481+
);
482+
// Better to hard code this than rely on computing the median correctly.
483+
const actualMedianSamplePeriod = 50 * 50 - 49 * 49;
484+
expect(
485+
observedSamplePeriod(samples),
486+
// Ensure we are within 5%, this is not a perfect median.
487+
closeTo(actualMedianSamplePeriod, actualMedianSamplePeriod * 0.05),
488+
);
489+
});
490+
});
441491
}

packages/devtools_app/test/screens/cpu_profiler/method_table/method_table_model_test.dart

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -17,6 +17,7 @@ void main() {
1717
selfCount: 1,
1818
profileMetaData: ProfileMetaData(
1919
sampleCount: 10,
20+
samplePeriod: 250,
2021
time:
2122
TimeRange()
2223
..start = Duration.zero
@@ -32,6 +33,7 @@ void main() {
3233
selfCount: 4,
3334
profileMetaData: ProfileMetaData(
3435
sampleCount: 10,
36+
samplePeriod: 250,
3537
time:
3638
TimeRange()
3739
..start = Duration.zero
@@ -47,6 +49,7 @@ void main() {
4749
selfCount: 2,
4850
profileMetaData: ProfileMetaData(
4951
sampleCount: 10,
52+
samplePeriod: 250,
5053
time:
5154
TimeRange()
5255
..start = Duration.zero
@@ -62,6 +65,7 @@ void main() {
6265
selfCount: 3,
6366
profileMetaData: ProfileMetaData(
6467
sampleCount: 10,
68+
samplePeriod: 250,
6569
time:
6670
TimeRange()
6771
..start = Duration.zero

packages/devtools_app/test/test_infra/test_data/cpu_profiler/cpu_profile.dart

Lines changed: 3 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1211,7 +1211,9 @@ final profileMetaData = CpuProfileMetaData(
12111211
time:
12121212
TimeRange()
12131213
..start = const Duration()
1214-
..end = const Duration(microseconds: 10000),
1214+
// Note this intentionally adds 10000 microseconds more than what
1215+
// was measured, regression test for Issue #8870.
1216+
..end = const Duration(microseconds: 20000),
12151217
);
12161218

12171219
final tagFrameA = CpuStackFrame(

0 commit comments

Comments
 (0)