Capture the request time for performance data and support forced shutdown

pkg/analysis_server/lib/src/plugin/plugin_manager.dart

 // Copyright (c) 2017, the Dart project authors.  Please see the AUTHORS file
 // for details. 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:collection';
 import 'dart:io' show Platform;
 
 import 'package:analysis_server/src/plugin/notification_manager.dart';
 import 'package:analyzer/context/context_root.dart' as analyzer;
@@ skipping 217 matching lines @@
       currentSession.sendRequest(params);
     }
   }
 }
 
 /**
  * An object used to manage the currently running plugins.
  */
 class PluginManager {
   /**
+   * A table, keyed by both a plugin and a request method, to a list of the
+   * times that it took the plugin to return a response to requests with the
+   * method.
+   */
+  static Map<PluginInfo, Map<String, List<int>>> pluginResponseTimes =
+      <PluginInfo, Map<String, List<int>>>{};
+
+  /**
    * The resource provider used to access the file system.
    */
   final ResourceProvider resourceProvider;
 
   /**
    * The absolute path of the directory containing the on-disk byte store, or
    * `null` if there is no on-disk store.
    */
   final String byteStorePath;
 
@@ skipping 312 matching lines @@
     return computePaths(executionFolder, runPub: true);
   }
 
   /**
    * Return a hex-encoded MD5 signature of the given file [path].
    */
   String _uniqueDirectoryName(String path) {
     List<int> bytes = md5.convert(path.codeUnits).bytes;
     return hex.encode(bytes);
   }
+
+  /**
+   * Record the fact that the given [plugin] responded to a request with the
+   * given [method] in the given [time].
+   */
+  static void recordResponseTime(PluginInfo plugin, String method, int time) {
+    pluginResponseTimes
+        .putIfAbsent(plugin, () => <String, List<int>>{})
+        .putIfAbsent(method, () => <int>[])
+        .add(time);
+  }
 }
 
 /**
  * Information about the execution a single plugin.
  */
 @visibleForTesting
 class PluginSession {
   /**
+   * The maximum number of milliseconds that server should wait for a response
+   * from a plugin before deciding that the plugin is hung.
+   */
+  static const Duration MAXIMUM_RESPONSE_TIME = const Duration(minutes: 2);
+
+  /**
+   * The length of time to wait after sending a 'plugin.shutdown' request before
+   * a failure to terminate will cause the isolate to be killed.
+   */
+  static const Duration WAIT_FOR_SHUTDOWN_DURATION =
+      const Duration(seconds: 10);
+
+  /**
    * The information about the plugin being executed.
    */
   final PluginInfo info;
 
   /**
    * The completer used to signal when the plugin has stopped.
    */
   Completer<Null> pluginStoppedCompleter = new Completer<Null>();
 
   /**
    * The channel used to communicate with the plugin.
    */
   ServerCommunicationChannel channel;
 
   /**
    * The index of the next request to be sent to the plugin.
    */
   int requestId = 0;
 
   /**
    * A table mapping the id's of requests to the functions used to handle the
    * response to those requests.
    */
-  Map<String, Completer<Response>> pendingRequests =
-      <String, Completer<Response>>{};
+  Map<String, _PendingRequest> pendingRequests = <String, _PendingRequest>{};
 
   /**
    * A boolean indicating whether the plugin is compatible with the version of
    * the plugin API being used by this server.
    */
   bool isCompatible = true;
 
   /**
    * The contact information to include when reporting problems related to the
    * plugin.
@@ skipping 69 matching lines @@
 //    print('  $message');
 //    print('  ${new StackTrace.fromString(stackTrace)}');
 //    pluginStoppedCompleter.completeError(message, new StackTrace.fromString(stackTrace));
   }
 
   /**
    * Handle a [response] from the plugin by completing the future that was
    * created when the request was sent.
    */
   void handleResponse(Response response) {
-    Completer<Response> completer = pendingRequests.remove(response.id);
+    _PendingRequest requestData = pendingRequests.remove(response.id);
+    int responseTime = new DateTime.now().millisecondsSinceEpoch;
+    int duration = responseTime - requestData.requestTime;
+    PluginManager.recordResponseTime(info, requestData.method, duration);
+    Completer<Response> completer = requestData.completer;
     if (completer != null) {
       completer.complete(response);
     }
   }
 
   /**
+   * Return `true` if there are any requests that have not been responded to
+   * within the maximum allowed amount of time.
+   */
+  bool isNonResponsive() {
+    // TODO(brianwilkerson) Figure out when to invoke this method in order to
+    // identify non-responsive plugins and kill them.
+    int cutOffTime = new DateTime.now().millisecondsSinceEpoch -
+        MAXIMUM_RESPONSE_TIME.inMilliseconds;
+    for (var requestData in pendingRequests.values) {
+      if (requestData.requestTime < cutOffTime) {
+        return true;
+      }
+    }
+    return false;
+  }
+
+  /**
    * Send a request, based on the given [parameters]. Return a future that will
    * complete when a response is received.
    */
   Future<Response> sendRequest(RequestParams parameters) {
     if (channel == null) {
       throw new StateError(
           'Cannot send a request to a plugin that has stopped.');
     }
     String id = nextRequestId;
     Completer<Response> completer = new Completer();
-    pendingRequests[id] = completer;
-    channel.sendRequest(parameters.toRequest(id));
+    int requestTime = new DateTime.now().millisecondsSinceEpoch;
+    Request request = parameters.toRequest(id);
+    pendingRequests[id] =
+        new _PendingRequest(request.method, requestTime, completer);
+    channel.sendRequest(request);
     return completer.future;
   }
 
   /**
    * Start a new isolate that is running this plugin. The plugin will be sent
    * the given [byteStorePath]. Return `true` if the plugin is compatible and
    * running.
    */
   Future<bool> start(String byteStorePath, String sdkPath) async {
     if (channel != null) {
@@ skipping 29 matching lines @@
     return true;
   }
 
   /**
    * Request that the plugin shutdown.
    */
   Future<Null> stop() {
     if (channel == null) {
       throw new StateError('Cannot stop a plugin that is not running.');
     }
-    // TODO(brianwilkerson) Ensure that the isolate is killed if it does not
-    // terminate normally.
     sendRequest(new PluginShutdownParams());
+    new Future.delayed(WAIT_FOR_SHUTDOWN_DURATION, () {
+      if (channel != null) {
+        channel.kill();
+        channel = null;
+      }
+    });
     return pluginStoppedCompleter.future;
   }
 }
+
+/**
+ * Information about a request that has been sent but for which a response has
+ * not yet been received.
+ */
+class _PendingRequest {
+  /**
+   * The method of the request.
+   */
+  final String method;
+
+  /**
+   * The time at which the request was sent to the plugin.
+   */
+  final int requestTime;

[scheglov, 2017/05/18 21:36:16]

Or you could use new Stopwatch()..start() instead.

[Brian Wilkerson, 2017/05/18 21:51:39]

I hadn't considered that, but now that I think about it, I have concerns
(possibly unwarranted) about the memory management issues of creating more
objects and holding on to them just until the plugin has responded. If they
never graduate from new space it shouldn't be a problem, but...

Unless there's a compelling reason to change it, I think I'll leave it as is.

[scheglov, 2017/05/18 21:55:55]

It's fine with my any way, just thought about other way, which could be simpler.

+
+  /**
+   * The completer that will be used to complete the future when the response is
+   * received from the plugin.
+   */
+  final Completer<Response> completer;
+
+  /**
+   * Initialize a pending request.
+   */
+  _PendingRequest(this.method, this.requestTime, this.completer);
+}