Image tracing (#50648)

dev/bots/test.dart

@@ -457,6 +457,11 @@ Future<void> _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: <String>['--enable-vmservice'],
+      tableData: bigqueryApi?.tabledata,
+    );
     await _runFlutterTest(
       path.join(flutterRoot, 'dev', 'integration_tests', 'codegen'),
       tableData: bigqueryApi?.tabledata,

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

dev/tracing_tests/README.md

+# 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

dev/tracing_tests/pubspec.yaml

+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

dev/tracing_tests/test/image_cache_tracing_test.dart

+// 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<Map<String, dynamic>> timelineEvents = await timelineObtainer.getTimelineData();
+
+    _expectTimelineEvents(
+      timelineEvents,
+      <Map<String, dynamic>>[
+        <String, dynamic>{
+          'name': 'ImageCache.putIfAbsent',
+          'args': <String, dynamic>{'key': 'Test', 'isolateId': isolateId}
+        },
+        <String, dynamic>{
+          'name': 'listener',
+          'args': <String, dynamic>{'parentId': '1', 'isolateId': isolateId}
+        },
+        <String, dynamic>{
+          'name': 'ImageCache.clear',
+          'args': <String, dynamic>{
+            'pendingImages': 1,
+            'cachedImages': 0,
+            'currentSizeInBytes': 0,
+            'isolateId': isolateId,
+          }
+        },
+      ],
+    );
+  }, skip: isBrowser); // uses dart:isolate and io
+}
+
+void _expectTimelineEvents(
+  List<Map<String, dynamic>> events,
+  List<Map<String, dynamic>> expected,
+) {
+  for (final Map<String, dynamic> event in events) {
+
+    for (int index = 0; index < expected.length; index += 1) {
+      if (expected[index]['name'] == event['name']) {
+        final Map<String, dynamic> expectedArgs = expected[index]['args'] as Map<String, dynamic>;
+        final Map<String, dynamic> args = event['args'] as Map<String, dynamic>;
+        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<String, dynamic> expectedArgs, Map<String, dynamic> 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<int, Completer<dynamic>> _completers = <int, Completer<dynamic>>{};
+
+
+  Future<void> 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<String, dynamic> json = jsonDecode(data) as Map<String, dynamic>;
+    final int id = json['id'] as int;
+    _completers.remove(id).complete(json['result']);
+  }
+
+  Future<bool> setDartFlags() async {
+    _lastCallId += 1;
+    final Completer<Map<String, dynamic>> completer = Completer<Map<String, dynamic>>();
+    _completers[_lastCallId] = completer;
+    _observatorySocket.add(jsonEncode(<String, dynamic>{
+      'id': _lastCallId,
+      'method': 'setVMTimelineFlags',
+      'params': <String, dynamic>{
+        'recordedStreams': <String>['Dart'],
+      },
+    }));
+
+    final Map<String, dynamic> result = await completer.future;
+    return result['type'] == 'Success';
+  }
+
+  Future<List<Map<String, dynamic>>> getTimelineData() async {
+    _lastCallId += 1;
+    final Completer<Map<String, dynamic>> completer = Completer<Map<String, dynamic>>();
+    _completers[_lastCallId] = completer;
+    _observatorySocket.add(jsonEncode(<String, dynamic>{
+      'id': _lastCallId,
+      'method': 'getVMTimeline',
+    }));
+
+    final Map<String, dynamic> result = await completer.future;
+    final List<dynamic> list = result['traceEvents'] as List<dynamic>;
+    return list.cast<Map<String, dynamic>>();
+  }
+
+  Future<void> close() async {
+    expect(_completers, isEmpty);
+    await _observatorySocket.close();
+  }
+}
+
+class TestImageStreamCompleter extends ImageStreamCompleter {}

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: <String, dynamic>{'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: <String, dynamic>{'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: <String, dynamic>{
+          '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: <String, dynamic>{
+          'type': 'pending'
+        });
+      }
       pendingImage.removeListener();
       return true;
     }
     final _CachedImage image = _cache.remove(key);
     if (image != null) {
+      if (!kReleaseMode) {
+        Timeline.instantSync('ImageCache.evict', arguments: <String, dynamic>{
+          'type': 'completed',
+          'sizeiInBytes': image.sizeBytes,
+        });
+      }
       _currentSizeBytes -= image.sizeBytes;
       return true;
     }
+    if (!kReleaseMode) {
+      Timeline.instantSync('ImageCache.evict', arguments: <String, dynamic>{
+        '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: <String, dynamic>{
+          '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: <String, dynamic>{'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: <String, dynamic>{'result': 'completed'});
+      }
       _cache[key] = image;
       return image.completer;
     }
+
     try {
       result = loader();
     } catch (error, stackTrace) {
+      if (!kReleaseMode) {
+        timelineTask.finish(arguments: <String, dynamic>{
+          '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: <String, dynamic>{
+          'syncCall': syncCall,
+          'sizeInBytes': imageSize,
+        });
+        timelineTask.finish(arguments: <String, dynamic>{
+          '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<String, dynamic> finishArgs = <String, dynamic>{};
+    TimelineTask checkCacheTask;
+    if (!kReleaseMode) {
+      checkCacheTask = TimelineTask(parent: timelineTask)..start('checkCacheSize');
+      finishArgs['evictedKeys'] = <String>[];
+      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);