analysis server performance measurement - work in progress

pkg/analysis_server/test/performance/input_converter.dart

+// Copyright (c) 2015, 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 input.transformer;
 
 import 'dart:convert';
+import 'dart:io';
+
+import 'package:analysis_server/src/protocol.dart';
+import 'package:logging/logging.dart';
 
 import 'instrumentation_input_converter.dart';
+import 'log_file_input_converter.dart';
 import 'operation.dart';
 
-final int NINE = '9'.codeUnitAt(0);
-final int ZERO = '0'.codeUnitAt(0);
+/**
+ * Common input converter superclass for sharing implementation.
+ */
+abstract class CommonInputConverter extends Converter<String, Operation> {
+  static final ERROR_PREFIX = 'Server responded with an error: ';
+  final Logger logger = new Logger('InstrumentationInputConverter');
+  final Set<String> eventsSeen = new Set<String>();
+
+  /**
+   * A mapping from request/response id to expected error message.
+   */
+  final Map<String, dynamic> expectedErrors = new Map<String, dynamic>();
+
+  /**
+   * A mapping of source path prefixes
+   * from location where instrumentation or log file was generated
+   * to the target location of the source using during performance measurement.
+   */
+  final Map<String, String> srcPathMap;
+
+  /**
+   * A mapping of current overlay content
+   * parallel to what is in the analysis server
+   * so that we can update the file system.
+   */
+  final Map<String, String> overlays = new Map<String, String>();
+
+  CommonInputConverter(this.srcPathMap);
+
+  /**
+   * Examine recorded responses and record any expected errors.
+   */
+  void recordResponse(Map<String, dynamic> json) {
+    var error = json['error'];
+    if (error != null) {
+      String id = json['id'];
+      print('expected error for $id is $error');
+    }
+  }
+
+  /**
+   * Return an operation for the notification or `null` if none.
+   */
+  Operation convertNotification(Map<String, dynamic> json) {
+    String event = json['event'];
+    if (event == 'server.status') {
+      // {"event":"server.status","params":{"analysis":{"isAnalyzing":false}}}
+      Map<String, dynamic> params = json['params'];
+      if (params != null) {
+        Map<String, dynamic> analysis = params['analysis'];
+        if (analysis != null && analysis['isAnalyzing'] == false) {
+          return new WaitForAnalysisCompleteOperation();
+        }
+      }
+    }
+    if (event == 'server.connected') {
+      // {"event":"server.connected","params":{"version":"1.7.0"}}
+      return new StartServerOperation();
+    }
+    if (eventsSeen.add(event)) {
+      logger.log(Level.INFO, 'Ignored notification: $event\n  $json');
+    }
+    return null;
+  }
+
+  /**
+   * Return an operation for the request or `null` if none.
+   */
+  Operation convertRequest(Map<String, dynamic> origJson) {
+    Map<String, dynamic> json = translateSrcPaths(origJson);
+    String method = json['method'];
+    if (method == 'analysis.getHover' ||

[Brian Wilkerson, 2015/06/15 17:37:47]

This is going to get us in trouble. We should minimally add a TODO comment to
clean this up so that we don't need a list that is easy to get out of sync with
the actual implementation (and that can deal with contributed handlers).

[danrubel, 2015/06/17 15:35:31]

Agreed. I implemented it this way for now so that I could review each new api
being called and think about its implications. In the future, I can just apply a
transform to every request and send it to the server.

+        method == 'analysis.setAnalysisRoots' ||
+        method == 'analysis.setPriorityFiles' ||
+        method == 'analysis.setSubscriptions' ||
+        method == 'analysis.updateOptions' ||
+        method == 'completion.getSuggestions' ||
+        method == 'edit.getAssists' ||
+        method == 'edit.getAvailableRefactorings' ||
+        method == 'edit.getFixes' ||
+        method == 'edit.getRefactoring' ||
+        method == 'edit.sortMembers' ||
+        method == 'execution.createContext' ||
+        method == 'execution.deleteContext' ||
+        method == 'execution.mapUri' ||
+        method == 'execution.setSubscriptions' ||
+        method == 'server.getVersion' ||
+        method == 'server.setSubscriptions') {
+      return new RequestOperation(this, json);
+    }
+    // Sanity check operations that modify source
+    // to ensure that the operation is on source in temp space
+    if (method == 'analysis.updateContent') {
+      try {
+        validateSrcPaths(json);
+      } catch (e) {
+        throw '$e\n  in $json';

[Brian Wilkerson, 2015/06/15 17:37:47]

Personally, I dislike throwing anything other than an exception. Even though
it's something of an abuse, you might consider throwing an AnalysisException
because it knows how to display the wrapped exception's stack trace, which will
probably make debugging easier.

  throw new AnalysisException("error in $json", new CaughtException(e, s));

[danrubel, 2015/06/17 15:35:31]

Good suggestion. Done.

+      }
+      // Track overlays in parallel with the analysis server
+      // so that when an overlay is removed, the file can be updated on disk
+      Request request = new Request.fromJson(json);
+      var params = new AnalysisUpdateContentParams.fromRequest(request);
+      params.files.forEach((String path, change) {
+        if (change is AddContentOverlay) {
+          String content = change.content;
+          if (content == null) {
+            throw 'expected new overlay content\n$json';
+          }
+          overlays[path] = content;
+        } else if (change is ChangeContentOverlay) {
+          String content = overlays[path];
+          if (content == null) {
+            throw 'expected cached overlay content\n$json';
+          }
+          overlays[path] = SourceEdit.applySequence(content, change.edits);
+        } else if (change is RemoveContentOverlay) {
+          String content = overlays.remove(path);
+          if (content == null) {
+            throw 'expected cached overlay content\n$json';
+          }
+          validateSrcPath(path);
+          new File(path).writeAsStringSync(content);
+        } else {
+          throw 'unknown overlay change $change\n$json';
+        }
+      });
+      return new RequestOperation(this, json);
+    }
+    throw 'unknown request: $method\n  $json';
+  }
+
+  /**
+   * Determine if the given request is expected to fail
+   * and log an exception if not.
+   */
+  void recordErrorResponse(Map<String, dynamic> jsonRequest, exception) {
+    var actualErr;
+    if (exception is UnimplementedError) {
+      if (exception.message.startsWith(ERROR_PREFIX)) {
+        Map<String, dynamic> jsonResponse =
+            JSON.decode(exception.message.substring(ERROR_PREFIX.length));
+        actualErr = jsonResponse['error'];
+      }
+    }
+    String id = jsonRequest['id'];
+    if (id != null && actualErr != null) {
+      var expectedErr = expectedErrors[id];
+      if (expectedErr != null && actualErr == expectedErr) {
+        return;
+      }
+//      if (jsonRequest['method'] == 'edit.sortMembers') {
+//        var params = jsonRequest['params'];
+//        if (params is Map) {
+//          var filePath = params['file'];
+//          if (filePath is String) {
+//            var content = overlays[filePath];
+//            if (content is String) {
+//              logger.log(Level.WARNING, 'sort failed: $filePath\n$content');
+//            }
+//          }
+//        }
+//      }
+    }
+    logger.log(
+        Level.SEVERE, 'Send request failed for $id\n$exception\n$jsonRequest');
+  }
+
+  /**
+   * Return text where any references to
+   * the original source when the instrumentation or log file was generated
+   * are replace with the temporary source used during performance measurement.
+   */
+  String translateSrcPath(String text) {
+    if (text != null) {
+      srcPathMap.forEach((String oldPrefix, String newPrefix) {
+        if (text.startsWith(oldPrefix)) {
+          text = '$newPrefix${text.substring(oldPrefix.length)}';
+        }
+      });
+    }
+    return text;
+  }
+
+  /**
+   * Recursively translate source paths in the specified JSON to reference
+   * the temporary source used during performance measurement rather than
+   * the original source when the instrumentation or log file was generated.
+   */
+  Map<String, dynamic> translateSrcPaths(Map<String, dynamic> origJson) {

[Brian Wilkerson, 2015/06/15 17:37:47]

Consider "translateSrcPaths" --> "translateSrcPathsInMap" for consistency.

[danrubel, 2015/06/17 15:35:31]

Done.

+    Map<String, dynamic> result = new Map<String, dynamic>();
+    origJson.forEach((String origKey, value) {
+      String newKey = translateSrcPath(origKey);
+      if (value is String) {
+        value = translateSrcPath(value);
+      } else if (value is List) {
+        value = translateSrcPathsInList(value);
+      } else if (value is Map) {
+        value = translateSrcPaths(value);
+      }
+      result[newKey] = value;
+    });
+    return result;
+  }
+
+  /**
+   * Recursively translate source paths in the specified list to reference
+   * the temporary source used during performance measurement rather than
+   * the original source when the instrumentation or log file was generated.
+   */
+  List translateSrcPathsInList(List list) {
+    List result = [];
+    for (int i = 0; i < list.length; ++i) {
+      var value = list[i];
+      if (value is String) {

[Brian Wilkerson, 2015/06/15 17:37:47]

This logic is repeated at least 4 times. It should be moved to a utility method.

[danrubel, 2015/06/17 15:35:31]

Good point. Reworked this group of methods to remove the duplicate code.

+        value = translateSrcPath(value);
+      } else if (value is List) {
+        value = translateSrcPathsInList(value);
+      } else if (value is Map) {
+        value = translateSrcPaths(value);
+      }
+      result.add(value);
+    }
+    return result;
+  }
+
+  /**
+   * Verify that the source path
+   * only reference the temporary source used during performance measurement.
+   */
+  void validateSrcPath(String value) {
+    if (value != null &&
+        value.startsWith('/Users/') &&
+        !srcPathMap.values.any((String prefix) => value.startsWith(prefix))) {
+      throw 'found path referencing source outside temp space\n  $value';
+    }
+  }
+
+  /**
+   * Recursively verify that the source paths in the specified [json]
+   * only reference the temporary source used during performance measurement.
+   */
+  void validateSrcPaths(Map<String, dynamic> json) {
+    json.forEach((String key, value) {
+      validateSrcPath(key);
+      if (value is String) {
+        validateSrcPath(value);
+      } else if (value is List) {
+        validateSrcPathsInList(value);
+      } else if (value is Map) {
+        validateSrcPaths(value);
+      }
+    });
+  }
+
+  /**
+   * Recursively verify that the source paths in the specified [list]
+   * only reference the temporary source used during performance measurement.
+   */
+  void validateSrcPathsInList(List list) {
+    for (int i = list.length - 1; i >= 0; --i) {
+      var value = list[i];
+      if (value is String) {
+        validateSrcPath(value);
+      } else if (value is List) {
+        validateSrcPathsInList(value);
+      } else if (value is Map) {
+        validateSrcPaths(value);
+      }
+    }
+  }
+}
 
 /**
  * [InputConverter] converts an input stream
  * into a series of operations to be sent to the analysis server.
  * The input stream can be either an instrumenation or log file.
  */
 class InputConverter extends Converter<String, Operation> {
+  final Logger logger = new Logger('InputConverter');
+
+  /**
+   * A mapping of source path prefixes
+   * from location where instrumentation or log file was generated
+   * to the target location of the source using during performance measurement.
+   */
+  final Map<String, String> srcPathMap;
 
   /**
    * The number of lines read before the underlying converter was determined
    * or the end of file was reached.
    */
   int headerLineCount = 0;
 
   /**
    * The underlying converter used to translate lines into operations
    * or `null` if it has not yet been determined.
    */
   Converter<String, Operation> converter;
 
+  /**
+   * [active] is `true` if converting lines to operations
+   * or `false` if an exception has occurred.
+   */
+  bool active = true;
+
+  InputConverter(this.srcPathMap);
+
   @override
   Operation convert(String line) {
+    if (!active) {
+      return null;
+    }
     if (converter != null) {
-      return converter.convert(line);
+      try {
+        return converter.convert(line);
+      } catch (e) {
+        active = false;
+        rethrow;
+      }
     }
     if (headerLineCount == 20) {
       throw 'Failed to determine input file format';
     }
     if (InstrumentationInputConverter.isFormat(line)) {
-      converter = new InstrumentationInputConverter();
+      converter = new InstrumentationInputConverter(srcPathMap);
     } else if (LogFileInputConverter.isFormat(line)) {
-      converter = new LogFileInputConverter();
+      converter = new LogFileInputConverter(srcPathMap);
     }
     if (converter != null) {
       return converter.convert(line);
     }
-    print(line);
+    logger.log(Level.INFO, 'skipped input line: $line');
     return null;
   }
 
   @override
   _InputSink startChunkedConversion(outSink) {
     return new _InputSink(this, outSink);
   }
 }
 
-/**
- * [LogFileInputConverter] converts a log file stream
- * into a series of operations to be sent to the analysis server.
- */
-class LogFileInputConverter extends Converter<String, Operation> {
-  @override
-  Operation convert(String line) {
-    throw 'not implemented yet';
-  }
-
-  /**
-   * Determine if the given line is from an instrumentation file.
-   * For example:
-   * `1428347977499 <= {"event":"server.connected","params":{"version":"1.6.0"}}`
-   */
-  static bool isFormat(String line) {
-    String timeStampString = _parseTimeStamp(line);
-    int start = timeStampString.length;
-    int end = start + 5;
-    return start > 10 &&
-        line.length > end &&
-        line.substring(start, end) == ' <= {"event":"server.connected"';
-  }
-
-  /**
-   * Parse the given line and return the millisecond timestamp or `null`
-   * if it cannot be determined.
-   */
-  static String _parseTimeStamp(String line) {
-    int index = 0;
-    while (index < line.length) {
-      int code = line.codeUnitAt(index);
-      if (code < ZERO || NINE < code) {
-        return line.substring(0, index);
-      }
-      ++index;
-    }
-    return line;
-  }
-}
-
 class _InputSink extends ChunkedConversionSink<String> {
   final Converter<String, Operation> converter;
   final outSink;
 
   _InputSink(this.converter, this.outSink);
 
   @override
   void add(String line) {
     Operation op = converter.convert(line);
     if (op != null) {
       outSink.add(op);
     }
   }
 
   @override
   void close() {
     outSink.close();
   }
 }