record and display request latency

pkg/analysis_server/lib/src/analysis_server.dart

 // Copyright (c) 2014, 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.
 
 library analysis.server;
 
 import 'dart:async';
 import 'dart:collection';
+import 'dart:math' show max;
 
 import 'package:analysis_server/src/analysis_logger.dart';
 import 'package:analysis_server/src/channel/channel.dart';
 import 'package:analysis_server/src/context_manager.dart';
 import 'package:analysis_server/src/operation/operation.dart';
 import 'package:analysis_server/src/operation/operation_analysis.dart';
 import 'package:analysis_server/src/operation/operation_queue.dart';
 import 'package:analysis_server/src/protocol.dart' hide Element;
 import 'package:analysis_server/src/services/correction/namespace.dart';
 import 'package:analysis_server/src/services/index/index.dart';
@@ skipping 141 matching lines @@
       new HashMap<AnalysisService, Set<String>>();
 
   /**
    * A table mapping [AnalysisContext]s to the completers that should be
    * completed when analysis of this context is finished.
    */
   Map<AnalysisContext, Completer<AnalysisDoneReason>> contextAnalysisDoneCompleters =
       new HashMap<AnalysisContext, Completer<AnalysisDoneReason>>();
 
   /**
+   * Performance information before initial analysis is complete.
+   */
+  ServerPerformance performanceDuringStartup = new ServerPerformance();
+
+  /**
+   * Performance information after initial analysis is complete
+   * or `null` if the initial analysis is not yet complete
+   */
+  ServerPerformance performanceAfterStartup;
+
+  /**
+   * The class into which performance information is currently being recorded.
+   * During startup, this will be the same as [performanceDuringStartup]
+   * and after startup is complete, this switches to [performanceAfterStartup].
+   */
+  ServerPerformance _performance;
+
+  /**
    * The option possibly set from the server initialization which disables error notifications.
    */
   bool _noErrorNotification;
 
   /**
    * The [Completer] that completes when analysis is complete.
    */
   Completer _onAnalysisCompleteCompleter;
 
   /**
@@ skipping 38 matching lines @@
    *
    * If [rethrowExceptions] is true, then any exceptions thrown by analysis are
    * propagated up the call stack.  The default is true to allow analysis
    * exceptions to show up in unit tests, but it should be set to false when
    * running a full analysis server.
    */
   AnalysisServer(this.channel, this.resourceProvider,
       PackageMapProvider packageMapProvider, this.index,
       AnalysisServerOptions analysisServerOptions, this.defaultSdk,
       this.instrumentationService, {this.rethrowExceptions: true}) {
+    _performance = performanceDuringStartup;
     searchEngine = createSearchEngine(index);
     operationQueue = new ServerOperationQueue();
     contextDirectoryManager =
         new ServerContextManager(this, resourceProvider, packageMapProvider);
     contextDirectoryManager.defaultOptions.incremental = true;
     contextDirectoryManager.defaultOptions.incrementalApi =
         analysisServerOptions.enableIncrementalResolutionApi;
     contextDirectoryManager.defaultOptions.incrementalValidation =
         analysisServerOptions.enableIncrementalResolutionValidation;
     _noErrorNotification = analysisServerOptions.noErrorNotification;
     AnalysisEngine.instance.logger = new AnalysisLogger();
     _onAnalysisStartedController = new StreamController.broadcast();
     _onFileAnalyzedController = new StreamController.broadcast();
     _onPriorityChangeController =
         new StreamController<PriorityChangeEvent>.broadcast();
     running = true;
+    onAnalysisStarted.first.then((_) {
+      onAnalysisComplete.then((_) {
+        performanceAfterStartup = new ServerPerformance();
+        _performance = performanceAfterStartup;
+      });
+    });
     Notification notification = new ServerConnectedParams().toNotification();
     channel.sendNotification(notification);
     channel.listen(handleRequest, onDone: done, onError: error);
   }
 
   /**
    * The [Future] that completes when analysis is complete.
    */
   Future get onAnalysisComplete {
     if (isAnalysisComplete()) {
@@ skipping 268 matching lines @@
     }
     // file-based source
     File file = resourceProvider.getResource(path);
     return file.createSource();
   }
 
   /**
    * Handle a [request] that was read from the communication channel.
    */
   void handleRequest(Request request) {
+    _performance.logRequest(request);
     runZoned(() {
       int count = handlers.length;
       for (int i = 0; i < count; i++) {
         try {
           Response response = handlers[i].handleRequest(request);
           if (response == Response.DELAYED_RESPONSE) {
             return;
           }
           if (response != null) {
             channel.sendResponse(response);
@@ skipping 602 matching lines @@
    * [packageUriResolver].
    */
   SourceFactory _createSourceFactory(UriResolver packageUriResolver) {
     List<UriResolver> resolvers = <UriResolver>[
         new DartUriResolver(analysisServer.defaultSdk),
         new ResourceUriResolver(resourceProvider),
         packageUriResolver];
     return new SourceFactory(resolvers);
   }
 }
+
+
+/**
+ * A class used by [AnalysisServer] to record performance information
+ * such as request latency.
+ */
+class ServerPerformance {
+
+  /**
+   * The creation time and the time when performance information
+   * started to be recorded here.
+   */
+  int startTime = new DateTime.now().millisecondsSinceEpoch;
+
+  /**
+   * The number of requests.
+   */
+  int requestCount = 0;
+
+  /**
+   * The total latency (milliseconds) for all recorded requests.
+   */
+  int requestLatency = 0;
+
+  /**
+   * The maximum latency (milliseconds) for all recorded requests.
+   */
+  int maxLatency = 0;
+
+  /**
+   * The number of requests with latency > 150 milliseconds.
+   */
+  int slowRequestCount = 0;
+
+  /**
+   * Log performation information about the given request.
+   */
+  void logRequest(Request request) {
+    ++requestCount;
+    if (request.clientRequestTime != null) {
+      int latency =
+          new DateTime.now().millisecondsSinceEpoch -
+          request.clientRequestTime;
+      requestLatency += latency;
+      maxLatency = max(maxLatency, latency);
+      if (latency > 150) {
+        ++slowRequestCount;
+      }
+    }
+  }
+}