More work on logging - new classes and timers.

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:math' as math;
 
 import 'ast.dart';
 import 'element.dart';
 import 'engine.dart';
 import 'error.dart';
 import 'error_verifier.dart';
-import 'incremental_logger.dart' show logger;
+import 'incremental_logger.dart' show logger, LoggerTimer;
 import 'java_engine.dart';
 import 'parser.dart';
 import 'resolver.dart';
 import 'scanner.dart';
 import 'source.dart';
 import 'utilities_dart.dart';
 
 
 /**
  * Instances of the class [DeclarationMatcher] determine whether the element
@@ skipping 52 matching lines @@
   /**
    * Return `true` if the declarations within the given AST structure define an element model
    * that is equivalent to the corresponding elements rooted at the given element.
    *
    * @param node the AST structure being compared to the element model
    * @param element the root of the element model being compared to the AST structure
    * @return `true` if the AST structure defines the same elements as those in the given
    *         element model
    */
   bool matches(AstNode node, Element element) {
-    _captureEnclosingElements(element);
-    _gatherElements(element);
+    logger.enter('match $element @ ${element.nameOffset}');
     try {
+      _captureEnclosingElements(element);
+      _gatherElements(element);
       node.accept(this);
     } on _DeclarationMismatchException catch (exception) {
       return false;
+    } finally {
+      logger.exit();
     }
     return _unmatchedElements.isEmpty;
   }
 
   @override
   visitBlockFunctionBody(BlockFunctionBody node) {
     // ignore bodies
   }
 
   @override
@@ skipping 559 matching lines @@
     _definingLibrary = _definingUnit.library;
     _source = _definingUnit.source;
   }
 
   /**
    * Resolve [node], reporting any errors or warnings to the given listener.
    *
    * [node] - the root of the AST structure to be resolved.
    */
   void resolve(AstNode node) {
-    AstNode rootNode = _findResolutionRoot(node);
-    // update elements
-    _updateElementNameOffsets(
-        _definingUnit,
-        _updateOffset,
-        _updateNewLength - _updateOldLength);
-    if (_elementModelChanged(rootNode)) {
-      throw new AnalysisException("Cannot resolve node: element model changed");
+    logger.enter('resolve: $_definingUnit');
+    try {
+      logger.log(() => 'node: $node');
+      AstNode rootNode = _findResolutionRoot(node);
+      logger.log(() => 'rootNode: $rootNode');
+      // update elements
+      _updateElementNameOffsets(
+          _definingUnit,
+          _updateOffset,
+          _updateNewLength - _updateOldLength);
+      if (_elementModelChanged(rootNode)) {
+        throw new AnalysisException(
+            "Cannot resolve node: element model changed");
+      }
+      _updateElements(rootNode);
+      // resolve
+      _resolveReferences(rootNode);
+      // verify
+      _verify(rootNode);
+      _generateHints(rootNode);
+    } finally {
+      logger.exit();
     }
-    _updateElements(rootNode);
-    // resolve
-    _resolveReferences(rootNode);
-    // verify
-    _verify(rootNode);
-    _generateHints(rootNode);
   }
 
   /**
    * Return `true` if the given node can be resolved independently of any other
    * nodes.
    *
    * *Note*: This method needs to be kept in sync with
    * [ScopeBuilder.ContextBuilder].
    *
    * [node] - the node being tested.
@@ skipping 46 matching lines @@
     while (node != null) {
       if (_canBeResolved(node)) {
         return node;
       }
       node = node.parent;
     }
     throw new AnalysisException("Cannot resolve node: no resolvable node");
   }
 
   void _generateHints(AstNode node) {
+    LoggerTimer timer = logger.startTimer();

[Brian Wilkerson, 2014/12/03 19:31:12]

Should we use try/finally to ensure that the timing information is printed?

[scheglov, 2014/12/03 19:46:35]

Acknowledged.

     RecordingErrorListener errorListener = new RecordingErrorListener();
     CompilationUnit unit = node.getAncestor((n) => n is CompilationUnit);
     AnalysisContext analysisContext = _definingLibrary.context;
     HintGenerator hintGenerator =
         new HintGenerator(<CompilationUnit>[unit], analysisContext, errorListener);
     hintGenerator.generateForLibrary();
     _hints = errorListener.getErrorsForSource(_source);
+    timer.stop('generate hints');
   }
 
   /**
    * Return the element defined by [node], or `null` if the node does not
    * define an element.
    */
   Element _getElement(AstNode node) {
     if (node is Declaration) {
       return node.element;
     } else if (node is CompilationUnit) {
       return node.element;
     }
     return null;
   }
 
   _resolveReferences(AstNode node) {
+    LoggerTimer timer = logger.startTimer();
     RecordingErrorListener errorListener = new RecordingErrorListener();
     // prepare context
     _resolutionContext =
         ResolutionContextBuilder.contextFor(node, errorListener);
     Scope scope = _resolutionContext.scope;
     // resolve types
     {
       TypeResolverVisitor visitor = new TypeResolverVisitor.con3(
           _definingLibrary,
           _source,
@@ skipping 26 matching lines @@
       }
       if (node is Comment) {
         visitor.resolveOnlyCommentInFunctionBody = true;
         node = node.parent;
       }
       visitor.initForIncrementalResolution();
       node.accept(visitor);
     }
     // remember errors
     _resolveErrors = errorListener.getErrorsForSource(_source);
+    timer.stop('resolve references');
   }
 
   void _updateElements(AstNode node) {
+    LoggerTimer timer = logger.startTimer();
     // build elements in node
     ElementHolder holder;
     _ElementsRestorer elementsRestorer = new _ElementsRestorer(node);
     try {
       holder = new ElementHolder();
       ElementBuilder builder = new ElementBuilder(holder);
       node.accept(builder);
     } finally {
       elementsRestorer.restore();
     }
@@ skipping 27 matching lines @@
           newElement = holderMethods[0];
         } else if (holderAccessors.isNotEmpty) {
           newElement = holderAccessors[0];
         }
       }
       // update the old Element
       oldElement.functions = newElement.functions;
       oldElement.labels = newElement.labels;
       oldElement.localVariables = newElement.localVariables;
     }
+    timer.stop('update elements');
   }
 
   void _verify(AstNode node) {
+    LoggerTimer timer = logger.startTimer();
     RecordingErrorListener errorListener = new RecordingErrorListener();
     ErrorReporter errorReporter = new ErrorReporter(errorListener, _source);
     ErrorVerifier errorVerifier = new ErrorVerifier(
         errorReporter,
         _definingLibrary,
         _typeProvider,
         new InheritanceManager(_definingLibrary));
     if (_resolutionContext.enclosingClassDeclaration != null) {
       errorVerifier.visitClassDeclarationIncrementally(
           _resolutionContext.enclosingClassDeclaration);
     }
     node.accept(errorVerifier);
     _verifyErrors = errorListener.getErrorsForSource(_source);
+    timer.stop('verify');
   }
 
   static void _updateElementNameOffsets(Element root, int offset, int delta) {
+    LoggerTimer timer = logger.startTimer();
     root.accept(new _ElementNameOffsetUpdater(offset, delta));
+    timer.stop('update element offsets');
   }
 }
 
 
 class PoorMansIncrementalResolver {
   final TypeProvider _typeProvider;
   final Source _unitSource;
   final Source _librarySource;
   final DartEntry _entry;
 
@@ skipping 10 matching lines @@
 
   PoorMansIncrementalResolver(this._typeProvider, this._unitSource,
       this._librarySource, this._entry);
 
   /**
    * 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.enter('diff/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;
@@ skipping 22 matching lines @@
             _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);
-        logger.log('oldNode: $oldNode');
-        logger.log('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;
           }
         }
-        logger.log('oldNode: $oldNode');
-        logger.log('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 26 matching lines @@
       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;
+    LoggerTimer timer = logger.startTimer();
+    try {
+      Token token = _scan(code);
+      RecordingErrorListener errorListener = new RecordingErrorListener();
+      Parser parser = new Parser(_unitSource, errorListener);
+      CompilationUnit unit = parser.parseCompilationUnit(token);
+      _newParseErrors = errorListener.errors;
+      return unit;
+    } finally {
+      timer.stop('parse');
+    }
   }
 
   void _resolveComment(CompilationUnit oldUnit, CompilationUnit newUnit,
       _TokenPair firstPair) {
     Token oldToken = firstPair.oldToken;
     CommentToken precedingComments = oldToken.precedingComments;
     int offset = precedingComments.offset;
     logger.log('offset: $offset');
     Comment oldComment = _findNodeCovering(oldUnit, offset, offset);
     Comment newComment = _findNodeCovering(newUnit, offset, offset);
@@ skipping 497 matching lines @@
   }
 }
 
 
 class _TokenPair {
   final Token oldToken;
   final Token newToken;
   final bool atComment;
   _TokenPair(this.oldToken, this.newToken, [this.atComment = false]);
 }