Add logging to the incremental resolver.

pkg/analyzer/lib/src/generated/incremental_resolver.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 engine.incremental_resolver;
 
 import 'dart:collection';
+import 'dart:io';

[Brian Wilkerson, 2014/12/03 15:05:17]

Won't this pull in a dependency on dart:io that some clients can't have?

 import 'dart:math' as math;
 
-import 'package:analyzer/src/generated/error_verifier.dart';
-import 'package:analyzer/src/generated/utilities_dart.dart';
-
 import 'ast.dart';
 import 'element.dart';
 import 'engine.dart';
 import 'error.dart';
+import 'error_verifier.dart';
 import 'java_engine.dart';
 import 'parser.dart';
 import 'resolver.dart';
 import 'scanner.dart';
 import 'source.dart';
+import 'utilities_dart.dart';
+
+
+_Logger _logger = new _NullLogger();

[Brian Wilkerson, 2014/12/03 15:05:17]

The logger should be moved to a separate library (or multiple libraries because
of io) so that it can be re-used in other places.

[scheglov, 2014/12/03 15:58:09]

Done.

+String _loggerSpec = null;
+
+
+void _initLogger(String spec) {
+  // check if the same logging specification
+  if (spec == _loggerSpec) {
+    return;
+  }
+  _loggerSpec = spec;
+  // check for null
+  _logger = new _NullLogger();
+  if (spec == null) {
+    return;
+  }
+  // create logger
+  if (spec == 'console') {
+    _logger = new _StringSinkLogger(console.log);
+  }
+  if (spec.startsWith('file:')) {
+    String fileName = spec.substring('file:'.length);
+    File file = new File(fileName);
+    IOSink sink = file.openWrite();
+    _logger = new _StringSinkLogger(sink);
+  }
+}
 
 
 /**
  * Instances of the class [DeclarationMatcher] determine whether the element
  * model defined by a given AST structure matches an existing element model.
  */
 class DeclarationMatcher extends RecursiveAstVisitor {
   /**
    * The libary containing the AST nodes being visited.
    */
@@ skipping 873 matching lines @@
   int _updateEndOld;
   int _updateEndNew;
 
   List<AnalysisError> _newScanErrors = <AnalysisError>[];
   List<AnalysisError> _newParseErrors = <AnalysisError>[];
   List<AnalysisError> _newResolveErrors = <AnalysisError>[];
   List<AnalysisError> _newVerifyErrors = <AnalysisError>[];
   List<AnalysisError> _newHints = <AnalysisError>[];
 
   PoorMansIncrementalResolver(this._typeProvider, this._unitSource,
-      this._librarySource, this._entry);
+      this._librarySource, this._entry, String logSpec) {
+    _initLogger(logSpec);
+  }
 
   /**
    * Attempts to update [oldUnit] to the state corresponding to [newCode].
    * Returns `true` if success, or `false` otherwise.
    * The [oldUnit] might be damaged.
    */
   bool resolve(CompilationUnit oldUnit, String newCode) {
+    _logger.enter('resolve $_unitSource');
+    _logger.log(oldUnit != null ? 'has oldUnit' : 'oldUnit is null');
     try {
       CompilationUnit newUnit = _parseUnit(newCode);
       _TokenPair firstPair =
           _findFirstDifferentToken(oldUnit.beginToken, newUnit.beginToken);
       _TokenPair lastPair =
           _findLastDifferentToken(oldUnit.endToken, newUnit.endToken);
       if (firstPair != null && lastPair != null) {
         int firstOffsetOld = firstPair.oldToken.offset;
         int firstOffsetNew = firstPair.newToken.offset;
         int lastOffsetOld = lastPair.oldToken.end;
         int lastOffsetNew = lastPair.newToken.end;
         int beginOffsetOld = math.min(firstOffsetOld, lastOffsetOld);
         int endOffsetOld = math.max(firstOffsetOld, lastOffsetOld);
         int beginOffsetNew = math.min(firstOffsetNew, lastOffsetNew);
         int endOffsetNew = math.max(firstOffsetNew, lastOffsetNew);
         // check for a whitespace only change
         if (identical(lastPair.oldToken, firstPair.oldToken) &&
             identical(lastPair.newToken, firstPair.newToken)) {
           _updateOffset = beginOffsetOld - 1;
           _updateEndOld = endOffsetOld;
           _updateDelta = newUnit.length - oldUnit.length;
           if (firstPair.atComment && lastPair.atComment) {
+            _logger.log('Comment change.');
             _resolveComment(oldUnit, newUnit, firstPair);
           } else {
+            _logger.log('Whitespace change.');
             _shiftTokens(firstPair.oldToken);
             IncrementalResolver._updateElementNameOffsets(
                 oldUnit.element,
                 _updateOffset,
                 _updateDelta);
             _updateEntry();
           }
+          _logger.log('Success.');
           return true;
         }
         // Find nodes covering the "old" and "new" token ranges.
         AstNode oldNode =
             _findNodeCovering(oldUnit, beginOffsetOld, endOffsetOld);
         AstNode newNode =
             _findNodeCovering(newUnit, beginOffsetNew, endOffsetNew);
-//        print('oldNode: $oldNode');
-//        print('newNode: $newNode');
+        _logger.log('oldNode: $oldNode');
+        _logger.log('newNode: $newNode');
         // Try to find the smallest common node, a FunctionBody currently.
         {
           List<AstNode> oldParents = _getParents(oldNode);
           List<AstNode> newParents = _getParents(newNode);
           int length = math.min(oldParents.length, newParents.length);
           bool found = false;
           for (int i = 0; i < length; i++) {
             AstNode oldParent = oldParents[i];
             AstNode newParent = newParents[i];
             if (oldParent is FunctionDeclaration &&
                 newParent is FunctionDeclaration ||
                 oldParent is MethodDeclaration && newParent is MethodDeclaration ||
                 oldParent is ConstructorDeclaration && newParent is ConstructorDeclaration) {
               oldNode = oldParent;
               newNode = newParent;
               found = true;
             }
             if (oldParent is FunctionBody && newParent is FunctionBody) {
               oldNode = oldParent;
               newNode = newParent;
               found = true;
               break;
             }
           }
           if (!found) {
+            _logger.log('Failure: no enclosing function body or executable.');
             return false;
           }
         }
-//        print('oldNode: $oldNode');
-//        print('newNode: $newNode');
+        _logger.log('oldNode: $oldNode');
+        _logger.log('newNode: $newNode');
         // prepare update range
         _updateOffset = oldNode.offset;
         _updateEndOld = oldNode.end;
         _updateEndNew = newNode.end;
         _updateDelta = _updateEndNew - _updateEndOld;
         // replace node
         NodeReplacer.replace(oldNode, newNode);
         // update token references
         {
           Token oldBeginToken = _getBeginTokenNotComment(oldNode);
@@ skipping 12 matching lines @@
             _typeProvider,
             oldUnitElement,
             _updateOffset,
             oldNode.length,
             newNode.length);
         incrementalResolver.resolve(newNode);
         _newResolveErrors = incrementalResolver._resolveErrors;
         _newVerifyErrors = incrementalResolver._verifyErrors;
         _newHints = incrementalResolver._hints;
         _updateEntry();
-//        print('Successfully incrementally resolved.');
+        _logger.log('Success.');
         return true;
       }
-    } catch (e) {
-      // TODO(scheglov) find a way to log these exceptions
-//      print(e);
-//      print(st);
+    } catch (e, st) {
+      _logger.log(e);
+      _logger.log(st);
+      _logger.log('Failure: exception.');
+    } finally {
+      _logger.exit();
     }
     return false;
   }
 
   CompilationUnit _parseUnit(String code) {
     Token token = _scan(code);
     RecordingErrorListener errorListener = new RecordingErrorListener();
     Parser parser = new Parser(_unitSource, errorListener);
     CompilationUnit unit = parser.parseCompilationUnit(token);
     _newParseErrors = errorListener.errors;
     return unit;
   }
 
   void _resolveComment(CompilationUnit oldUnit, CompilationUnit newUnit,
       _TokenPair firstPair) {
     Token oldToken = firstPair.oldToken;
-    int offset = oldToken.precedingComments.offset;
+    CommentToken precedingComments = oldToken.precedingComments;
+    int offset = precedingComments.offset;
+    _logger.log('offset: $offset');
     Comment oldComment = _findNodeCovering(oldUnit, offset, offset);
     Comment newComment = _findNodeCovering(newUnit, offset, offset);
+    _logger.log('oldComment.beginToken: ${oldComment.beginToken}');
+    _logger.log('newComment.beginToken: ${newComment.beginToken}');
     _updateOffset = oldToken.offset - 1;
     // update token references
     _shiftTokens(firstPair.oldToken);
     _setPrecedingComments(oldToken, newComment.tokens.first);
     // replace node
     NodeReplacer.replace(oldComment, newComment);
     // update elements
     IncrementalResolver._updateElementNameOffsets(
         oldUnit.element,
         _updateOffset,
@@ skipping 479 matching lines @@
     super.visitFunctionExpression(node);
   }
 
   @override
   visitSimpleIdentifier(SimpleIdentifier node) {
     _elements[node] = node.staticElement;
   }
 }
 
 
+/**
+ * A simple hierarchical logger.
+ */
+abstract class _Logger {
+  /**
+   * Mark an enter to a new section with the given [name].
+   */
+  void enter(String name);
+
+  /**
+   * Mark an exit from the current sections, logs the duration.
+   */
+  void exit();
+
+  /**
+   * Logs the given [message].
+   */
+  void log(Object obj);
+}
+
+
+class _LoggerSection {
+  final DateTime start = new DateTime.now();
+  final String indent;
+  final String name;
+  _LoggerSection(this.indent, this.name);
+}
+
+
+/**
+ * A [_Logger] that does nothing.
+ */
+class _NullLogger implements _Logger {
+  @override
+  void enter(String name) {
+  }
+
+  @override
+  void exit() {
+  }
+
+  @override
+  void log(Object obj) {
+  }
+}
+
+
+/**
+ * A [_Logger] that writes to a [StringSink].
+ */
+class _StringSinkLogger implements _Logger {
+  static const int MAX_LINE_LENGTH = 512;
+  final StringSink sink;
+  final List<_LoggerSection> sectionStack = <_LoggerSection>[];
+  _LoggerSection section = new _LoggerSection('', 'ROOT');
+
+  _StringSinkLogger(this.sink);
+
+  @override
+  void enter(String name) {
+    log('+++ $name');
+    sectionStack.add(section);
+    section = new _LoggerSection(section.indent + '\t', name);
+  }
+
+  @override
+  void exit() {
+    DateTime now = new DateTime.now();
+    Duration duration = now.difference(section.start);
+    String message = '--- ${section.name} in ${duration.inMilliseconds} ms';
+    section = sectionStack.removeLast();
+    log(message);
+  }
+
+  @override
+  void log(Object obj) {
+    DateTime now = new DateTime.now();
+    String indent = section.indent;
+    String objStr = _getObjectString(obj);
+    String line = '[$now] $indent$objStr';
+    sink.writeln(line);
+  }
+
+  String _getObjectString(Object obj) {
+    if (obj == null) {
+      return 'null';
+    }
+    String str = obj.toString();
+    if (str.length < MAX_LINE_LENGTH) {
+      return str;
+    }
+    return str.split('\n').map((String line) {
+      if (line.length > MAX_LINE_LENGTH) {
+        line = line.substring(0, MAX_LINE_LENGTH) + '...';
+      }
+      return line;
+    }).join('\n');
+  }
+}
+
+
 class _TokenPair {
   final Token oldToken;
   final Token newToken;
   final bool atComment;
   _TokenPair(this.oldToken, this.newToken, [this.atComment = false]);
 }