Fix issues in DevTools load time reporting (#1518)

* Fix issues in DevTools load time reporting

- Store dwdsStats on appServices for an app to make sure we are
  updating an reporting the same stats for an app. Previously,
  if the app services already existed, we would use incorrect
  object to report the stats, causing incorrect times and missing
  reports.
- Set the times on dwdsStats when debug request arrives to make
  sure times are recorded only from the time when the user starts
  debugging.
- Process `pageReady` events from any DevTools page, as DevTools
  does not always show the debugger page first.
- Enabled previously skipped tests.

Closes:#1517

* Format

Author: Anna Gringauze

dwds/CHANGELOG.md

@@ -1,15 +1,17 @@
 ## 13.0.0-dev
 - Change wording of paused overlay from "Paused in Dart DevTools" to "Paused"
-- Allow sending back the Dart DevTools URL from DWDS instead of launching 
+- Allow sending back the Dart DevTools URL from DWDS instead of launching
   Dart DevTools, to support embedding Dart DevTools in Chrome DevTools.
 - Temporarily disable the paused in debugger overlay.
 - Add `SdkConfiguration` and `SdkConfigurationProvider` classes to allow
   for lazily created SDK configurations.
+- Fix an issue in reporting DevTools stats where the DevTools load time was
+  not always recorded.
 - Add an `ide` query parameter to the Dart DevTools URL for analytics.
 
 **Breaking changes:**
-- `Dwds.start` and `ExpressionCompilerService` now take 
-  `sdkConfigurationProvider` argument instead of separate SDK-related file 
+- `Dwds.start` and `ExpressionCompilerService` now take
+  `sdkConfigurationProvider` argument instead of separate SDK-related file
   paths.
 
 ## 12.1.0

dwds/lib/dwds.dart

@@ -89,9 +89,7 @@ class Dwds {
 
   Future<DebugConnection> debugConnection(AppConnection appConnection) async {
     if (!_enableDebugging) throw StateError('Debugging is not enabled.');
-    final dwdsStats = DwdsStats(DateTime.now());
-    var appDebugServices =
-        await _devHandler.loadAppServices(appConnection, dwdsStats);
+    var appDebugServices = await _devHandler.loadAppServices(appConnection);
     await appDebugServices.chromeProxyService.isInitialized;
     return DebugConnection(appDebugServices);
   }

dwds/lib/src/dwds_vm_client.dart

@@ -150,10 +150,9 @@ void _processSendEvent(Map<String, dynamic> event,
   switch (type) {
     case 'DevtoolsEvent':
       {
-        var screen = payload == null ? null : payload['screen'];
         var action = payload == null ? null : payload['action'];
-        if (screen == 'debugger' && action == 'pageReady') {
-          if (dwdsStats.isFirstDebuggerReady()) {
+        if (action == 'pageReady') {
+          if (dwdsStats.isFirstDebuggerReady) {
             if (dwdsStats.devToolsStart != null) {
               emitEvent(DwdsEvent.devToolsLoad(DateTime.now()
                   .difference(dwdsStats.devToolsStart)
@@ -165,6 +164,7 @@ void _processSendEvent(Map<String, dynamic> event,
                   .inMilliseconds));
             }
           } else {
+            print('Ignoring already received event: $event');
             _logger.warning('Ignoring already received event: $event');
           }
         } else {

dwds/lib/src/events.dart

@@ -10,21 +10,27 @@ import 'package:vm_service/vm_service.dart';
 
 class DwdsStats {
   /// The time when the user starts the debugger.
-  final DateTime debuggerStart;
+  DateTime _debuggerStart;
+  DateTime get debuggerStart => _debuggerStart;
 
   /// The time when dwds launches DevTools.
-  DateTime devToolsStart;
-
-  var _isDebuggerReady = false;
+  DateTime _devToolsStart;
+  DateTime get devToolsStart => _devToolsStart;
+
+  /// Records and returns weither the debugger is ready.
+  bool _isFirstDebuggerReady = true;
+  bool get isFirstDebuggerReady {
+    var wasReady = _isFirstDebuggerReady;
+    _isFirstDebuggerReady = false;
+    return wasReady;
+  }
 
-  /// Records and returns whether the debugger became ready.
-  bool isFirstDebuggerReady() {
-    final wasReady = _isDebuggerReady;
-    _isDebuggerReady = true;
-    return !wasReady;
+  void updateLoadTime({DateTime debuggerStart, DateTime devToolsStart}) {
+    _debuggerStart = debuggerStart;
+    _devToolsStart = devToolsStart;
   }
 
-  DwdsStats(this.debuggerStart);
+  DwdsStats();
 }
 
 class DwdsEventKind {

dwds/lib/src/handlers/dev_handler.dart

@@ -226,14 +226,13 @@ class DevHandler {
     );
   }
 
-  Future<AppDebugServices> loadAppServices(
-      AppConnection appConnection, DwdsStats dwdsStats) async {
+  Future<AppDebugServices> loadAppServices(AppConnection appConnection) async {
     var appId = appConnection.request.appId;
     if (_servicesByAppId[appId] == null) {
       var debugService = await _startLocalDebugService(
           await _chromeConnection(), appConnection);
       var appServices = await _createAppDebugServices(
-          appConnection.request.appId, debugService, dwdsStats);
+          appConnection.request.appId, debugService);
       unawaited(appServices.chromeProxyService.remoteDebugger.onClose.first
           .whenComplete(() async {
         await appServices.close();
@@ -329,11 +328,10 @@ class DevHandler {
                 'Otherwise check the docs for the tool you are using.'))));
       return;
     }
-
-    var dwdsStats = DwdsStats(DateTime.now());
+    var debuggerStart = DateTime.now();
     AppDebugServices appServices;
     try {
-      appServices = await loadAppServices(appConnection, dwdsStats);
+      appServices = await loadAppServices(appConnection);
     } catch (_) {
       var error = 'Unable to connect debug services to your '
           'application. Most likely this means you are trying to '
@@ -374,7 +372,10 @@ class DevHandler {
           ..promptExtension = false))));
 
     appServices.connectedInstanceId = appConnection.request.instanceId;
-    dwdsStats.devToolsStart = DateTime.now();
+    appServices.dwdsStats.updateLoadTime(
+      debuggerStart: debuggerStart,
+      devToolsStart: DateTime.now(),
+    );
     await _launchDevTools(
         appServices.chromeProxyService.remoteDebugger,
         _constructDevToolsUri(appServices.debugService.uri,
@@ -448,12 +449,14 @@ class DevHandler {
   }
 
   Future<AppDebugServices> _createAppDebugServices(
-      String appId, DebugService debugService, DwdsStats dwdsStats) async {
+      String appId, DebugService debugService) async {
+    var dwdsStats = DwdsStats();
     var webdevClient = await DwdsVmClient.create(debugService, dwdsStats);
     if (_spawnDds) {
       await debugService.startDartDevelopmentService();
     }
-    var appDebugService = AppDebugServices(debugService, webdevClient);
+    var appDebugService =
+        AppDebugServices(debugService, webdevClient, dwdsStats);
     var encodedUri = await debugService.encodedUri;
     _logger.info('Debug service listening on $encodedUri\n');
     await appDebugService.chromeProxyService.remoteDebugger
@@ -477,7 +480,6 @@ class DevHandler {
     // Waits for a `DevToolsRequest` to be sent from the extension background
     // when the extension is clicked.
     extensionDebugger.devToolsRequestStream.listen((devToolsRequest) async {
-      var dwdsStats = DwdsStats(DateTime.now());
       var connection = _appConnectionByAppId[devToolsRequest.appId];
       if (connection == null) {
         // TODO(grouma) - Ideally we surface this warning to the extension so
@@ -486,6 +488,7 @@ class DevHandler {
             'Not connected to an app with id: ${devToolsRequest.appId}');
         return;
       }
+      var debuggerStart = DateTime.now();
       var appId = devToolsRequest.appId;
       if (_servicesByAppId[appId] == null) {
         var debugService = await DebugService.start(
@@ -510,7 +513,6 @@ class DevHandler {
         var appServices = await _createAppDebugServices(
           devToolsRequest.appId,
           debugService,
-          dwdsStats,
         );
         var encodedUri = await debugService.encodedUri;
         extensionDebugger.sendEvent('dwds.encodedUri', encodedUri);
@@ -525,8 +527,8 @@ class DevHandler {
         extensionDebugConnections.add(DebugConnection(appServices));
         _servicesByAppId[appId] = appServices;
       }
-      final encodedUri = await _servicesByAppId[appId].debugService.encodedUri;
-      dwdsStats.devToolsStart = DateTime.now();
+      final appServices = _servicesByAppId[appId];
+      final encodedUri = await appServices.debugService.encodedUri;
 
       // If we only want the URI, this means we are embedding Dart DevTools in
       // Chrome DevTools. Therefore return early.
@@ -538,11 +540,12 @@ class DevHandler {
         extensionDebugger.sendEvent('dwds.devtoolsUri', devToolsUri);
         return;
       }
-
       final devToolsUri = _constructDevToolsUri(
         encodedUri,
         ideQueryParam: 'DebugExtension',
       );
+      appServices.dwdsStats.updateLoadTime(
+          debuggerStart: debuggerStart, devToolsStart: DateTime.now());
       await _launchDevTools(extensionDebugger, devToolsUri);
     });
   }

dwds/lib/src/services/app_debug_services.dart

@@ -7,13 +7,15 @@
 import 'dart:async';
 
 import '../dwds_vm_client.dart';
+import '../events.dart';
 import 'chrome_proxy_service.dart' show ChromeProxyService;
 import 'debug_service.dart';
 
 /// A container for all the services required for debugging an application.
 class AppDebugServices {
   final DebugService debugService;
   final DwdsVmClient dwdsVmClient;
+  final DwdsStats dwdsStats;
 
   ChromeProxyService get chromeProxyService =>
       debugService.chromeProxyService as ChromeProxyService;
@@ -28,7 +30,7 @@ class AppDebugServices {
   /// We only allow a given app to be debugged in a single tab at a time.
   String connectedInstanceId;
 
-  AppDebugServices(this.debugService, this.dwdsVmClient);
+  AppDebugServices(this.debugService, this.dwdsVmClient, this.dwdsStats);
 
   Future<void> close() =>
       _closed ??= Future.wait([debugService.close(), dwdsVmClient.close()]);

dwds/test/events_test.dart

@@ -96,6 +96,20 @@ void main() {
       return result;
     }
 
+    /// Runs [action] and waits for an event matching [eventMatcher].
+    Future<T> expectEventsDuring<T>(
+        List<Matcher> eventMatchers, Future<T> Function() action,
+        {Timeout timeout}) async {
+      // The events stream is a broadcast stream so start listening
+      // before the action.
+      final events = eventMatchers.map((matcher) => expectLater(
+          pipe(context.testServer.dwds.events, timeout: timeout),
+          emitsThrough(matcher)));
+      final result = await action();
+      await Future.wait(events);
+      return result;
+    }
+
     setUpAll(() async {
       setCurrentLogWriter();
       initialEvents = expectLater(
@@ -117,34 +131,26 @@ void main() {
       await context.tearDown();
     });
 
-    test('emits DEVTOOLS_LAUNCH event', () async {
-      await expectEventDuring(
-        matchesEvent(DwdsEventKind.devtoolsLaunch, {}),
+    test('emits DEBUGGER_READY and DEVTOOLS_LOAD events', () async {
+      await expectEventsDuring(
+        [
+          matchesEvent(DwdsEventKind.debuggerReady, {
+            'elapsedMilliseconds': isNotNull,
+          }),
+          matchesEvent(DwdsEventKind.devToolsLoad, {
+            'elapsedMilliseconds': isNotNull,
+          }),
+        ],
         () => keyboard.sendChord([Keyboard.alt, 'd']),
       );
     });
 
-    test('emits DEBUGGER_READY event', () async {
-      await expectEventDuring(
-        matchesEvent(DwdsEventKind.debuggerReady, {
-          'elapsedMilliseconds': isNotNull,
-        }),
-        () => keyboard.sendChord([Keyboard.alt, 'd']),
-      );
-    },
-        skip: 'Enable after publishing of '
-            'https://github.com/flutter/devtools/pull/3346');
-
-    test('emits DEVTOOLS_LOAD events', () async {
+    test('emits DEVTOOLS_LAUNCH event', () async {
       await expectEventDuring(
-        matchesEvent(DwdsEventKind.devToolsLoad, {
-          'elapsedMilliseconds': isNotNull,
-        }),
+        matchesEvent(DwdsEventKind.devtoolsLaunch, {}),
         () => keyboard.sendChord([Keyboard.alt, 'd']),
       );
-    },
-        skip: 'Enable after publishing of '
-            'https://github.com/flutter/devtools/pull/3346');
+    });
 
     test('events can be listened to multiple times', () async {
       events.listen((_) {});