Added more analytics

dwds/CHANGELOG.md

@@ -6,7 +6,11 @@
 - Use default constant port for debug service.
   - If we fail binding to the port, fall back to previous strategy
     of finding unbound ports.
-- Add metrics measuring DevTools Initial Page Load time.
+- Add metrics measuring
+  - DevTools Initial Page Load time
+  - Various VM API
+  - Hot restart
+  - Http request handling exceptions
 - Add `ext.dwds.sendEvent` service extension to dwds so other tools
   can send events to the debugger.
   Event format:

dwds/lib/dwds.dart

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

dwds/lib/src/dwds_vm_client.dart

@@ -80,71 +80,19 @@ class DwdsVmClient {
         }
       };
     });
-    await client.registerService('_flutter.listViews', 'DWDS listViews');
-
-    client.registerServiceCallback('hotRestart', (request) async {
-      _logger.info('Attempting a hot restart');
-
-      chromeProxyService.terminatingIsolates = true;
-      await _disableBreakpointsAndResume(client, chromeProxyService);
-      int context;
-      try {
-        _logger.info('Attempting to get execution context ID.');
-        context = await chromeProxyService.executionContext.id;
-        _logger.info('Got execution context ID.');
-      } on StateError catch (e) {
-        // We couldn't find the execution context. `hotRestart` may have been
-        // triggered in the middle of a full reload.
-        return {
-          'error': {
-            'code': RPCError.kInternalError,
-            'message': e.message,
-          }
-        };
-      }
-      // Start listening for isolate create events before issuing a hot
-      // restart. Only return success after the isolate has fully started.
-      var stream = chromeProxyService.onEvent('Isolate');
-      try {
-        _logger.info('Issuing \$dartHotRestart request.');
-        await chromeProxyService.remoteDebugger
-            .sendCommand('Runtime.evaluate', params: {
-          'expression': r'$dartHotRestart();',
-          'awaitPromise': true,
-          'contextId': context,
-        });
-        _logger.info('\$dartHotRestart request complete.');
-      } on WipError catch (exception) {
-        var code = exception.error['code'];
-        // This corresponds to `Execution context was destroyed` which can
-        // occur during a hot restart that must fall back to a full reload.
-        if (code != RPCError.kServerError) {
-          return {
-            'error': {
-              'code': exception.error['code'],
-              'message': exception.error['message'],
-              'data': exception,
-            }
-          };
-        }
-      }
+    await client.registerService('_flutter.listViews', 'DWDS');
 
-      _logger.info('Waiting for Isolate Start event.');
-      await stream.firstWhere((event) => event.kind == EventKind.kIsolateStart);
-      chromeProxyService.terminatingIsolates = false;
-
-      _logger.info('Successful hot restart');
-      return {'result': Success().toJson()};
-    });
-    await client.registerService('hotRestart', 'DWDS fullReload');
+    client.registerServiceCallback(
+        'hotRestart',
+        (request) => captureElapsedTime(
+            () => _hotRestart(chromeProxyService, client),
+            (_) => DwdsEvent.hotRestart()));
+    await client.registerService('hotRestart', 'DWDS');
 
-    client.registerServiceCallback('fullReload', (_) async {
-      _logger.info('Attempting a full reload');
-      await chromeProxyService.remoteDebugger.enablePage();
-      await chromeProxyService.remoteDebugger.pageReload();
-      _logger.info('Successful full reload');
-      return {'result': Success().toJson()};
-    });
+    client.registerServiceCallback(
+        'fullReload',
+        (request) => captureElapsedTime(() => _fullReload(chromeProxyService),
+            (_) => DwdsEvent.fullReload()));
     await client.registerService('fullReload', 'DWDS');
 
     client.registerServiceCallback('ext.dwds.screenshot', (_) async {
@@ -205,6 +153,9 @@ void _processSendEvent(Map<String, dynamic> event,
         var action = payload == null ? null : payload['action'];
         if (screen == 'debugger' && action == 'pageReady') {
           if (dwdsStats.isFirstDebuggerReady()) {
+            emitEvent(DwdsEvent.devToolsLoad(DateTime.now()
+                .difference(dwdsStats.devToolsStart)
+                .inMilliseconds));
             emitEvent(DwdsEvent.debuggerReady(DateTime.now()
                 .difference(dwdsStats.debuggerStart)
                 .inMilliseconds));
@@ -218,6 +169,71 @@ void _processSendEvent(Map<String, dynamic> event,
   }
 }
 
+Future<Map<String, dynamic>> _hotRestart(
+    ChromeProxyService chromeProxyService, VmService client) async {
+  _logger.info('Attempting a hot restart');
+
+  chromeProxyService.terminatingIsolates = true;
+  await _disableBreakpointsAndResume(client, chromeProxyService);
+  int context;
+  try {
+    _logger.info('Attempting to get execution context ID.');
+    context = await chromeProxyService.executionContext.id;
+    _logger.info('Got execution context ID.');
+  } on StateError catch (e) {
+    // We couldn't find the execution context. `hotRestart` may have been
+    // triggered in the middle of a full reload.
+    return {
+      'error': {
+        'code': RPCError.kInternalError,
+        'message': e.message,
+      }
+    };
+  }
+  // Start listening for isolate create events before issuing a hot
+  // restart. Only return success after the isolate has fully started.
+  var stream = chromeProxyService.onEvent('Isolate');
+  try {
+    _logger.info('Issuing \$dartHotRestart request.');
+    await chromeProxyService.remoteDebugger
+        .sendCommand('Runtime.evaluate', params: {
+      'expression': r'$dartHotRestart();',
+      'awaitPromise': true,
+      'contextId': context,
+    });
+    _logger.info('\$dartHotRestart request complete.');
+  } on WipError catch (exception) {
+    var code = exception.error['code'];
+    // This corresponds to `Execution context was destroyed` which can
+    // occur during a hot restart that must fall back to a full reload.
+    if (code != RPCError.kServerError) {
+      return {
+        'error': {
+          'code': exception.error['code'],
+          'message': exception.error['message'],
+          'data': exception,
+        }
+      };
+    }
+  }
+
+  _logger.info('Waiting for Isolate Start event.');
+  await stream.firstWhere((event) => event.kind == EventKind.kIsolateStart);
+  chromeProxyService.terminatingIsolates = false;
+
+  _logger.info('Successful hot restart');
+  return {'result': Success().toJson()};
+}
+
+Future<Map<String, dynamic>> _fullReload(
+    ChromeProxyService chromeProxyService) async {
+  _logger.info('Attempting a full reload');
+  await chromeProxyService.remoteDebugger.enablePage();
+  await chromeProxyService.remoteDebugger.pageReload();
+  _logger.info('Successful full reload');
+  return {'result': Success().toJson()};
+}
+
 Future<void> _disableBreakpointsAndResume(
     VmService client, ChromeProxyService chromeProxyService) async {
   _logger.info('Attempting to disable breakpoints and resume the isolate');

dwds/lib/src/events.dart

@@ -12,6 +12,9 @@ class DwdsStats {
   /// The time when the user starts the debugger.
   final DateTime debuggerStart;
 
+  /// The time when dwds launches DevTools.
+  DateTime devToolsStart;
+
   var _isDebuggerReady = false;
 
   /// Records and returns whether the debugger became ready.
@@ -28,13 +31,17 @@ class DwdsEventKind {
   static const String compilerUpdateDependencies =
       'COMPILER_UPDATE_DEPENDENCIES';
   static const String devtoolsLaunch = 'DEVTOOLS_LAUNCH';
+  static const String devToolsLoad = 'DEVTOOLS_LOAD';
+  static const String debuggerReady = 'DEBUGGER_READY';
   static const String evaluate = 'EVALUATE';
   static const String evaluateInFrame = 'EVALUATE_IN_FRAME';
+  static const String fullReload = 'FULL_RELOAD';
   static const String getIsolate = 'GET_ISOLATE';
   static const String getScripts = 'GET_SCRIPTS';
   static const String getSourceReport = 'GET_SOURCE_REPORT';
-  static const String debuggerReady = 'DEBUGGER_READY';
   static const String getVM = 'GET_VM';
+  static const String hotRestart = 'HOT_RESTART';
+  static const String httpRequestException = 'HTTP_REQUEST_EXCEPTION';
   static const String resume = 'RESUME';
 
   DwdsEventKind._();
@@ -77,11 +84,26 @@ class DwdsEvent {
 
   DwdsEvent.getSourceReport() : this(DwdsEventKind.getSourceReport, {});
 
+  DwdsEvent.hotRestart() : this(DwdsEventKind.hotRestart, {});
+
+  DwdsEvent.fullReload() : this(DwdsEventKind.fullReload, {});
+
   DwdsEvent.debuggerReady(int elapsedMilliseconds)
       : this(DwdsEventKind.debuggerReady, {
           'elapsedMilliseconds': elapsedMilliseconds,
         });
 
+  DwdsEvent.devToolsLoad(int elapsedMilliseconds)
+      : this(DwdsEventKind.devToolsLoad, {
+          'elapsedMilliseconds': elapsedMilliseconds,
+        });
+
+  DwdsEvent.httpRequestException(String server, String exception)
+      : this(DwdsEventKind.httpRequestException, {
+          'server': server,
+          'exception': exception,
+        });
+
   void addException(dynamic exception) {
     payload['exception'] = exception;
   }
@@ -103,3 +125,24 @@ void emitEvent(DwdsEvent event) => _eventController.sink.add(event);
 
 /// A global stream of [DwdsEvent]s.
 Stream<DwdsEvent> get eventStream => _eventController.stream;
+
+/// Call [function] and record its execution time.
+///
+/// Calls [event] to create the event to be recorded,
+/// and appends time and exception details to it if
+/// available.
+Future<T> captureElapsedTime<T>(
+    Future<T> Function() function, DwdsEvent Function(T result) event) async {
+  var stopwatch = Stopwatch()..start();
+  T result;
+  try {
+    return result = await function();
+  } catch (e) {
+    emitEvent(event(result)
+      ..addException(e)
+      ..addElapsedTime(stopwatch.elapsedMilliseconds));
+    rethrow;
+  } finally {
+    emitEvent(event(result)..addElapsedTime(stopwatch.elapsedMilliseconds));
+  }
+}

dwds/lib/src/handlers/dev_handler.dart

@@ -221,8 +221,8 @@ class DevHandler {
     );
   }
 
-  Future<AppDebugServices> loadAppServices(AppConnection appConnection) async {
-    var dwdsStats = DwdsStats(DateTime.now());
+  Future<AppDebugServices> loadAppServices(
+      AppConnection appConnection, DwdsStats dwdsStats) async {
     var appId = appConnection.request.appId;
     if (_servicesByAppId[appId] == null) {
       var debugService = await _startLocalDebugService(
@@ -321,9 +321,10 @@ class DevHandler {
       return;
     }
 
+    var dwdsStats = DwdsStats(DateTime.now());
     AppDebugServices appServices;
     try {
-      appServices = await loadAppServices(appConnection);
+      appServices = await loadAppServices(appConnection, dwdsStats);
     } catch (_) {
       var error = 'Unable to connect debug services to your '
           'application. Most likely this means you are trying to '
@@ -364,6 +365,7 @@ class DevHandler {
           ..promptExtension = false))));
 
     appServices.connectedInstanceId = appConnection.request.instanceId;
+    dwdsStats.devToolsStart = DateTime.now();
     await _launchDevTools(appServices.chromeProxyService.remoteDebugger,
         appServices.debugService.uri);
   }
@@ -511,6 +513,7 @@ class DevHandler {
         extensionDebugConnections.add(DebugConnection(appServices));
         _servicesByAppId[appId] = appServices;
       }
+      dwdsStats.devToolsStart = DateTime.now();
       await _launchDevTools(extensionDebugger,
           await _servicesByAppId[appId].debugService.encodedUri);
     });

dwds/lib/src/servers/extension_backend.dart

@@ -8,20 +8,20 @@ import 'dart:async';
 import 'dart:io';
 
 import 'package:async/async.dart';
-
 import 'package:http_multi_server/http_multi_server.dart';
 import 'package:logging/logging.dart';
 import 'package:shelf/shelf.dart';
 
 import '../../data/extension_request.dart';
+import '../events.dart';
 import '../handlers/socket_connections.dart';
 import '../utilities/shared.dart';
 import 'extension_debugger.dart';
 
 const authenticationResponse = 'Dart Debug Authentication Success!\n\n'
     'You can close this tab and launch the Dart Debug Extension again.';
 
-Logger _logger = Logger('ExtensiobBackend');
+Logger _logger = Logger('ExtensionBackend');
 
 /// A backend for the Dart Debug Extension.
 ///
@@ -56,7 +56,8 @@ class ExtensionBackend {
     }).add(_socketHandler.handler);
     var server = await HttpMultiServer.bind(hostname, 0);
     serveHttpRequests(server, cascade.handler, (e, s) {
-      _logger.warning('Error serving requests', e, s);
+      _logger.warning('Error serving requests', e);
+      emitEvent(DwdsEvent.httpRequestException('ExtensionBackend', '$e:$s'));
     });
     return ExtensionBackend._(
         _socketHandler, server.address.host, server.port, server);