From 766bd705986f80e29914c631383717c3f75e9e98 Mon Sep 17 00:00:00 2001 From: Dan Field Date: Thu, 13 Feb 2020 14:04:02 -0800 Subject: [PATCH] Image tracing (#50648) --- dev/bots/test.dart | 5 + .../release_smoke_test/pubspec.yaml | 4 +- dev/tracing_tests/README.md | 7 + dev/tracing_tests/pubspec.yaml | 42 +++++ .../test/image_cache_tracing_test.dart | 160 ++++++++++++++++++ .../flutter/lib/src/painting/image_cache.dart | 117 ++++++++++++- 6 files changed, 328 insertions(+), 7 deletions(-) create mode 100644 dev/tracing_tests/README.md create mode 100644 dev/tracing_tests/pubspec.yaml create mode 100644 dev/tracing_tests/test/image_cache_tracing_test.dart diff --git a/dev/bots/test.dart b/dev/bots/test.dart index 8759ba2163..64cf3dc8f5 100644 --- a/dev/bots/test.dart +++ b/dev/bots/test.dart @@ -457,6 +457,11 @@ Future _runFrameworkTests() async { await _runFlutterTest(path.join(flutterRoot, 'packages', 'flutter_localizations'), tableData: bigqueryApi?.tabledata); await _runFlutterTest(path.join(flutterRoot, 'packages', 'flutter_test'), tableData: bigqueryApi?.tabledata); await _runFlutterTest(path.join(flutterRoot, 'packages', 'fuchsia_remote_debug_protocol'), tableData: bigqueryApi?.tabledata); + await _runFlutterTest( + path.join(flutterRoot, 'dev', 'tracing_tests'), + options: ['--enable-vmservice'], + tableData: bigqueryApi?.tabledata, + ); await _runFlutterTest( path.join(flutterRoot, 'dev', 'integration_tests', 'codegen'), tableData: bigqueryApi?.tabledata, diff --git a/dev/integration_tests/release_smoke_test/pubspec.yaml b/dev/integration_tests/release_smoke_test/pubspec.yaml index 68e1045036..df94efc6d9 100644 --- a/dev/integration_tests/release_smoke_test/pubspec.yaml +++ b/dev/integration_tests/release_smoke_test/pubspec.yaml @@ -17,7 +17,7 @@ dev_dependencies: flutter_test: sdk: flutter - e2e: 0.2.3+1 + e2e: 0.2.4+1 archive: 2.0.11 # THIS LINE IS AUTOGENERATED - TO UPDATE USE "flutter update-packages --force-upgrade" args: 1.5.2 # THIS LINE IS AUTOGENERATED - TO UPDATE USE "flutter update-packages --force-upgrade" @@ -40,4 +40,4 @@ dev_dependencies: test_api: 0.2.11 # THIS LINE IS AUTOGENERATED - TO UPDATE USE "flutter update-packages --force-upgrade" xml: 3.5.0 # THIS LINE IS AUTOGENERATED - TO UPDATE USE "flutter update-packages --force-upgrade" -# PUBSPEC CHECKSUM: bb2f +# PUBSPEC CHECKSUM: bc30 diff --git a/dev/tracing_tests/README.md b/dev/tracing_tests/README.md new file mode 100644 index 0000000000..73d37f569f --- /dev/null +++ b/dev/tracing_tests/README.md @@ -0,0 +1,7 @@ +# Tracing tests + +The tests in this folder must be run with `flutter test --enable-vmservice`, +since they test that trace data is written to the timeline by connecting to +the observatory. + +These tests will fail if run without this flag. \ No newline at end of file diff --git a/dev/tracing_tests/pubspec.yaml b/dev/tracing_tests/pubspec.yaml new file mode 100644 index 0000000000..abd7057876 --- /dev/null +++ b/dev/tracing_tests/pubspec.yaml @@ -0,0 +1,42 @@ +name: tracing_tests +description: Various tests for tracing in flutter/flutter + +environment: + # The pub client defaults to an <2.0.0 sdk constraint which we need to explicitly overwrite. + sdk: ">=2.2.2 <3.0.0" + +dependencies: + flutter: + sdk: flutter + + collection: 1.14.11 # THIS LINE IS AUTOGENERATED - TO UPDATE USE "flutter update-packages --force-upgrade" + meta: 1.1.8 # THIS LINE IS AUTOGENERATED - TO UPDATE USE "flutter update-packages --force-upgrade" + typed_data: 1.1.6 # THIS LINE IS AUTOGENERATED - TO UPDATE USE "flutter update-packages --force-upgrade" + vector_math: 2.0.8 # THIS LINE IS AUTOGENERATED - TO UPDATE USE "flutter update-packages --force-upgrade" + +dev_dependencies: + flutter_test: + sdk: flutter + + archive: 2.0.11 # THIS LINE IS AUTOGENERATED - TO UPDATE USE "flutter update-packages --force-upgrade" + args: 1.5.2 # THIS LINE IS AUTOGENERATED - TO UPDATE USE "flutter update-packages --force-upgrade" + async: 2.4.0 # THIS LINE IS AUTOGENERATED - TO UPDATE USE "flutter update-packages --force-upgrade" + boolean_selector: 1.0.5 # THIS LINE IS AUTOGENERATED - TO UPDATE USE "flutter update-packages --force-upgrade" + charcode: 1.1.2 # THIS LINE IS AUTOGENERATED - TO UPDATE USE "flutter update-packages --force-upgrade" + convert: 2.1.1 # THIS LINE IS AUTOGENERATED - TO UPDATE USE "flutter update-packages --force-upgrade" + crypto: 2.1.3 # THIS LINE IS AUTOGENERATED - TO UPDATE USE "flutter update-packages --force-upgrade" + image: 2.1.4 # THIS LINE IS AUTOGENERATED - TO UPDATE USE "flutter update-packages --force-upgrade" + matcher: 0.12.6 # THIS LINE IS AUTOGENERATED - TO UPDATE USE "flutter update-packages --force-upgrade" + path: 1.6.4 # THIS LINE IS AUTOGENERATED - TO UPDATE USE "flutter update-packages --force-upgrade" + pedantic: 1.8.0+1 # THIS LINE IS AUTOGENERATED - TO UPDATE USE "flutter update-packages --force-upgrade" + petitparser: 2.4.0 # THIS LINE IS AUTOGENERATED - TO UPDATE USE "flutter update-packages --force-upgrade" + quiver: 2.0.5 # THIS LINE IS AUTOGENERATED - TO UPDATE USE "flutter update-packages --force-upgrade" + source_span: 1.5.5 # THIS LINE IS AUTOGENERATED - TO UPDATE USE "flutter update-packages --force-upgrade" + stack_trace: 1.9.3 # THIS LINE IS AUTOGENERATED - TO UPDATE USE "flutter update-packages --force-upgrade" + stream_channel: 2.0.0 # THIS LINE IS AUTOGENERATED - TO UPDATE USE "flutter update-packages --force-upgrade" + string_scanner: 1.0.5 # THIS LINE IS AUTOGENERATED - TO UPDATE USE "flutter update-packages --force-upgrade" + term_glyph: 1.1.0 # THIS LINE IS AUTOGENERATED - TO UPDATE USE "flutter update-packages --force-upgrade" + test_api: 0.2.11 # THIS LINE IS AUTOGENERATED - TO UPDATE USE "flutter update-packages --force-upgrade" + xml: 3.5.0 # THIS LINE IS AUTOGENERATED - TO UPDATE USE "flutter update-packages --force-upgrade" + +# PUBSPEC CHECKSUM: f789 diff --git a/dev/tracing_tests/test/image_cache_tracing_test.dart b/dev/tracing_tests/test/image_cache_tracing_test.dart new file mode 100644 index 0000000000..c96e4b2e9f --- /dev/null +++ b/dev/tracing_tests/test/image_cache_tracing_test.dart @@ -0,0 +1,160 @@ +// Copyright 2014 The Flutter Authors. All rights reserved. +// Use of this source code is governed by a BSD-style license that can be +// found in the LICENSE file. + +import 'dart:async'; +import 'dart:convert'; +import 'dart:developer' as developer; +import 'dart:io'; +import 'dart:isolate' as isolate; + +import 'package:flutter/painting.dart'; +import 'package:flutter_test/flutter_test.dart'; + +void main() { + String isolateId; + final TimelineObtainer timelineObtainer = TimelineObtainer(); + + setUpAll(() async { + isolateId = developer.Service.getIsolateID(isolate.Isolate.current); + final developer.ServiceProtocolInfo info = await developer.Service.getInfo(); + + if (info.serverUri == null) { + throw TestFailure('This test _must_ be run with --enable-vmservice.'); + } + await timelineObtainer.connect(info.serverUri); + await timelineObtainer.setDartFlags(); + + // Initialize the image cache. + TestWidgetsFlutterBinding.ensureInitialized(); + }); + + tearDownAll(() async { + await timelineObtainer?.close(); + }); + + test('Image cache tracing', () async { + final TestImageStreamCompleter completer1 = TestImageStreamCompleter(); + PaintingBinding.instance.imageCache.putIfAbsent( + 'Test', + () => completer1, + ); + PaintingBinding.instance.imageCache.clear(); + + final List> timelineEvents = await timelineObtainer.getTimelineData(); + + _expectTimelineEvents( + timelineEvents, + >[ + { + 'name': 'ImageCache.putIfAbsent', + 'args': {'key': 'Test', 'isolateId': isolateId} + }, + { + 'name': 'listener', + 'args': {'parentId': '1', 'isolateId': isolateId} + }, + { + 'name': 'ImageCache.clear', + 'args': { + 'pendingImages': 1, + 'cachedImages': 0, + 'currentSizeInBytes': 0, + 'isolateId': isolateId, + } + }, + ], + ); + }, skip: isBrowser); // uses dart:isolate and io +} + +void _expectTimelineEvents( + List> events, + List> expected, +) { + for (final Map event in events) { + + for (int index = 0; index < expected.length; index += 1) { + if (expected[index]['name'] == event['name']) { + final Map expectedArgs = expected[index]['args'] as Map; + final Map args = event['args'] as Map; + if (_mapsEqual(expectedArgs, args)) { + expected.removeAt(index); + } + } + } + } + if (expected.isNotEmpty) { + final String encodedEvents = jsonEncode(events); + fail('Timeline did not contain expected events: $expected\nactual: $encodedEvents'); + } +} + +bool _mapsEqual(Map expectedArgs, Map args) { + if (expectedArgs.length != args.length) { + return false; + } + for (final String key in expectedArgs.keys) { + if (expectedArgs[key] != args[key]) { + return false; + } + } + return true; +} + +// TODO(dnfield): we can drop this in favor of vm_service when https://github.com/dart-lang/webdev/issues/899 is resolved. +class TimelineObtainer { + WebSocket _observatorySocket; + int _lastCallId = 0; + + final Map> _completers = >{}; + + + Future connect(Uri uri) async { + _observatorySocket = await WebSocket.connect('ws://localhost:${uri.port}${uri.path}ws'); + _observatorySocket.listen((dynamic data) => _processResponse(data as String)); + } + + void _processResponse(String data) { + final Map json = jsonDecode(data) as Map; + final int id = json['id'] as int; + _completers.remove(id).complete(json['result']); + } + + Future setDartFlags() async { + _lastCallId += 1; + final Completer> completer = Completer>(); + _completers[_lastCallId] = completer; + _observatorySocket.add(jsonEncode({ + 'id': _lastCallId, + 'method': 'setVMTimelineFlags', + 'params': { + 'recordedStreams': ['Dart'], + }, + })); + + final Map result = await completer.future; + return result['type'] == 'Success'; + } + + Future>> getTimelineData() async { + _lastCallId += 1; + final Completer> completer = Completer>(); + _completers[_lastCallId] = completer; + _observatorySocket.add(jsonEncode({ + 'id': _lastCallId, + 'method': 'getVMTimeline', + })); + + final Map result = await completer.future; + final List list = result['traceEvents'] as List; + return list.cast>(); + } + + Future close() async { + expect(_completers, isEmpty); + await _observatorySocket.close(); + } +} + +class TestImageStreamCompleter extends ImageStreamCompleter {} diff --git a/packages/flutter/lib/src/painting/image_cache.dart b/packages/flutter/lib/src/painting/image_cache.dart index 86a02cf98c..63034dbba5 100644 --- a/packages/flutter/lib/src/painting/image_cache.dart +++ b/packages/flutter/lib/src/painting/image_cache.dart @@ -2,6 +2,10 @@ // Use of this source code is governed by a BSD-style license that can be // found in the LICENSE file. +import 'dart:developer'; + +import 'package:flutter/foundation.dart'; + import 'image_stream.dart'; const int _kDefaultSize = 1000; @@ -85,11 +89,21 @@ class ImageCache { assert(value >= 0); if (value == maximumSize) return; + TimelineTask timelineTask; + if (!kReleaseMode) { + timelineTask = TimelineTask()..start( + 'ImageCache.setMaximumSize', + arguments: {'value': value}, + ); + } _maximumSize = value; if (maximumSize == 0) { clear(); } else { - _checkCacheSize(); + _checkCacheSize(timelineTask); + } + if (!kReleaseMode) { + timelineTask.finish(); } } @@ -114,11 +128,21 @@ class ImageCache { assert(value >= 0); if (value == _maximumSizeBytes) return; + TimelineTask timelineTask; + if (!kReleaseMode) { + timelineTask = TimelineTask()..start( + 'ImageCache.setMaximumSizeBytes', + arguments: {'value': value}, + ); + } _maximumSizeBytes = value; if (_maximumSizeBytes == 0) { clear(); } else { - _checkCacheSize(); + _checkCacheSize(timelineTask); + } + if (!kReleaseMode) { + timelineTask.finish(); } } @@ -134,6 +158,16 @@ class ImageCache { /// Images which have not finished loading yet will not be removed from the /// cache, and when they complete they will be inserted as normal. void clear() { + if (!kReleaseMode) { + Timeline.instantSync( + 'ImageCache.clear', + arguments: { + 'pendingImages': _pendingImages.length, + 'cachedImages': _cache.length, + 'currentSizeInBytes': _currentSizeBytes, + }, + ); + } _cache.clear(); _pendingImages.clear(); _currentSizeBytes = 0; @@ -158,14 +192,30 @@ class ImageCache { bool evict(Object key) { final _PendingImage pendingImage = _pendingImages.remove(key); if (pendingImage != null) { + if (!kReleaseMode) { + Timeline.instantSync('ImageCache.evict', arguments: { + 'type': 'pending' + }); + } pendingImage.removeListener(); return true; } final _CachedImage image = _cache.remove(key); if (image != null) { + if (!kReleaseMode) { + Timeline.instantSync('ImageCache.evict', arguments: { + 'type': 'completed', + 'sizeiInBytes': image.sizeBytes, + }); + } _currentSizeBytes -= image.sizeBytes; return true; } + if (!kReleaseMode) { + Timeline.instantSync('ImageCache.evict', arguments: { + 'type': 'miss', + }); + } return false; } @@ -182,20 +232,45 @@ class ImageCache { ImageStreamCompleter putIfAbsent(Object key, ImageStreamCompleter loader(), { ImageErrorListener onError }) { assert(key != null); assert(loader != null); + TimelineTask timelineTask; + TimelineTask listenerTask; + if (!kReleaseMode) { + timelineTask = TimelineTask()..start( + 'ImageCache.putIfAbsent', + arguments: { + 'key': key.toString(), + }, + ); + } ImageStreamCompleter result = _pendingImages[key]?.completer; // Nothing needs to be done because the image hasn't loaded yet. - if (result != null) + if (result != null) { + if (!kReleaseMode) { + timelineTask.finish(arguments: {'result': 'pending'}); + } return result; + } // Remove the provider from the list so that we can move it to the // recently used position below. final _CachedImage image = _cache.remove(key); if (image != null) { + if (!kReleaseMode) { + timelineTask.finish(arguments: {'result': 'completed'}); + } _cache[key] = image; return image.completer; } + try { result = loader(); } catch (error, stackTrace) { + if (!kReleaseMode) { + timelineTask.finish(arguments: { + 'result': 'error', + 'error': error.toString(), + 'stackTrace': stackTrace.toString(), + }); + } if (onError != null) { onError(error, stackTrace); return null; @@ -203,6 +278,11 @@ class ImageCache { rethrow; } } + + if (!kReleaseMode) { + listenerTask = TimelineTask(parent: timelineTask)..start('listener'); + } + bool listenedOnce = false; void listener(ImageInfo info, bool syncCall) { // Images that fail to load don't contribute to cache size. final int imageSize = info?.image == null ? 0 : info.image.height * info.image.width * 4; @@ -215,8 +295,19 @@ class ImageCache { if (imageSize <= maximumSizeBytes) { _currentSizeBytes += imageSize; _cache[key] = image; - _checkCacheSize(); + _checkCacheSize(listenerTask); } + if (!kReleaseMode && !listenedOnce) { + listenerTask.finish(arguments: { + 'syncCall': syncCall, + 'sizeInBytes': imageSize, + }); + timelineTask.finish(arguments: { + 'currentSizeBytes': currentSizeBytes, + 'currentSize': currentSize, + }); + } + listenedOnce = true; } if (maximumSize > 0 && maximumSizeBytes > 0) { final ImageStreamListener streamListener = ImageStreamListener(listener); @@ -234,12 +325,28 @@ class ImageCache { // Remove images from the cache until both the length and bytes are below // maximum, or the cache is empty. - void _checkCacheSize() { + void _checkCacheSize(TimelineTask timelineTask) { + final Map finishArgs = {}; + TimelineTask checkCacheTask; + if (!kReleaseMode) { + checkCacheTask = TimelineTask(parent: timelineTask)..start('checkCacheSize'); + finishArgs['evictedKeys'] = []; + finishArgs['currentSize'] = currentSize; + finishArgs['currentSizeBytes'] = currentSizeBytes; + } while (_currentSizeBytes > _maximumSizeBytes || _cache.length > _maximumSize) { final Object key = _cache.keys.first; final _CachedImage image = _cache[key]; _currentSizeBytes -= image.sizeBytes; _cache.remove(key); + if (!kReleaseMode) { + finishArgs['evictedKeys'].add(key.toString()); + } + } + if (!kReleaseMode) { + finishArgs['endSize'] = currentSize; + finishArgs['endSizeBytes'] = currentSizeBytes; + checkCacheTask.finish(arguments: finishArgs); } assert(_currentSizeBytes >= 0); assert(_cache.length <= maximumSize);