feat(scope): add scope digest stat collection

Closes #609

Author: mhevery

demo/bouncing_balls/web/bouncy_balls.dart

@@ -66,14 +66,14 @@ class BounceController {
       balls.removeAt(0);
       count++;
     }
-    tick();
+    //tick();
   }
 
   void timeDigest() {
     var start = window.performance.now();
     digestTime = currentDigestTime;
     scope.rootScope.domRead(() {
-      currentDigestTime = (window.performance.now() - start).round();
+      currentDigestTime = window.performance.now() - start;
     });
   }
 
@@ -100,7 +100,7 @@ class BounceController {
 @NgDirective(
   selector: '[ball-position]',
   map: const {
-    "ballPosition": '=>position'})
+    "ball-position": '=>position'})
 class BallPositionDirective {
   final Element element;
   final Scope scope;
@@ -118,6 +118,17 @@ class MyModule extends Module {
   MyModule() {
     type(BounceController);
     type(BallPositionDirective);
+    value(GetterCache, new GetterCache({
+      'x': (o) => o.x,
+      'y': (o) => o.y,
+      'bounce': (o) => o.bounce,
+      'fps': (o) => o.fps,
+      'balls': (o) => o.balls,
+      'length': (o) => o.length,
+      'digestTime': (o) => o.digestTime,
+      'ballClassName': (o) => o.ballClassName
+    }));
+    value(ScopeStats, new ScopeStats(report: true));
   }
 }
 

demo/bouncing_balls/web/index.html

@@ -50,7 +50,7 @@
         </div>
     </div>
 
-    {{bounce.fps}} fps. ({{bounce.balls.length}} balls) [{{(1000/bounce.fps).round()}} ms] <br>
+    {{bounce.fps}} fps. ({{bounce.balls.length}} balls) [{{1000/bounce.fps}} ms] <br>
     Digest: {{bounce.digestTime}} ms<br>
     <a href ng-click="bounce.changeCount(1)">+1</a>
     <a href ng-click="bounce.changeCount(10)">+10</a>

lib/change_detection/change_detection.dart

@@ -54,7 +54,8 @@ abstract class ChangeDetector<H> extends ChangeDetectorGroup<H> {
    * linked list of [ChangeRecord]s. The [ChangeRecord]s are returned in the
    * same order as they were registered.
    */
-  ChangeRecord<H> collectChanges([EvalExceptionHandler exceptionHandler]);
+  ChangeRecord<H> collectChanges({ EvalExceptionHandler exceptionHandler,
+                                   AvgStopwatch stopwatch });
 }
 
 abstract class Record<H> {
@@ -238,3 +239,20 @@ abstract class MovedItem<V> extends CollectionChangeItem<V> {
 abstract class RemovedItem<V> extends CollectionChangeItem<V> {
   RemovedItem<V> get nextRemovedItem;
 }
+
+class AvgStopwatch extends Stopwatch {
+  int _count = 0;
+
+  int get count => _count;
+
+  void reset() {
+    _count = 0;
+    super.reset();
+  }
+
+  int increment(int count) => _count += count;
+
+  double get ratePerMs => elapsedMicroseconds == 0
+      ? 0.0
+      : _count / elapsedMicroseconds * 1000;
+}

lib/change_detection/dirty_checking_change_detector.dart

@@ -281,11 +281,14 @@ class DirtyCheckingChangeDetector<H> extends DirtyCheckingChangeDetectorGroup<H>
     return true;
   }
 
-  DirtyCheckingRecord<H> collectChanges([EvalExceptionHandler exceptionHandler]) {
+  DirtyCheckingRecord<H> collectChanges({ EvalExceptionHandler exceptionHandler,
+                                          AvgStopwatch stopwatch}) {
+    if (stopwatch != null) stopwatch.start();
     DirtyCheckingRecord changeHead = null;
     DirtyCheckingRecord changeTail = null;
     DirtyCheckingRecord current = _recordHead; // current index
 
+    int count = 0;
     while (current != null) {
       try {
         if (current.check() != null) {
@@ -295,6 +298,7 @@ class DirtyCheckingChangeDetector<H> extends DirtyCheckingChangeDetectorGroup<H>
             changeTail = changeTail.nextChange = current;
           }
         }
+        if (stopwatch != null) count++;
       } catch (e, s) {
         if (exceptionHandler == null) {
           rethrow;
@@ -305,6 +309,7 @@ class DirtyCheckingChangeDetector<H> extends DirtyCheckingChangeDetectorGroup<H>
       current = current._nextRecord;
     }
     if (changeTail != null) changeTail.nextChange = null;
+    if (stopwatch != null) stopwatch..stop()..increment(count);
     return changeHead;
   }
 

lib/change_detection/watch_group.dart

@@ -358,25 +358,33 @@ class RootWatchGroup extends WatchGroup {
    * Each step is called in sequence. ([ReactionFn]s are not called until all
    * previous steps are completed).
    */
-  int detectChanges({EvalExceptionHandler exceptionHandler,
-                    ChangeLog changeLog}) {
+  int detectChanges({ EvalExceptionHandler exceptionHandler,
+                      ChangeLog changeLog, 
+                      AvgStopwatch fieldStopwatch,
+                      AvgStopwatch evalStopwatch,
+                      AvgStopwatch processStopwatch}) {
     // Process the ChangeRecords from the change detector
     ChangeRecord<_Handler> changeRecord =
-        (_changeDetector as ChangeDetector<_Handler>)
-            .collectChanges(exceptionHandler);
+        (_changeDetector as ChangeDetector<_Handler>).collectChanges(
+            exceptionHandler:exceptionHandler, 
+            stopwatch: fieldStopwatch);
+    if (processStopwatch != null) processStopwatch.start();
     while (changeRecord != null) {
       if (changeLog != null) changeLog(changeRecord.handler.expression,
                                        changeRecord.currentValue,
                                        changeRecord.previousValue);
       changeRecord.handler.onChange(changeRecord);
       changeRecord = changeRecord.nextChange;
     }
+    if (processStopwatch != null) processStopwatch.stop();
 
-    int count = 0;
+    if (evalStopwatch != null) evalStopwatch.start();
     // Process our own function evaluations
     _EvalWatchRecord evalRecord = _evalWatchHead;
+    int evalCount = 0;
     while (evalRecord != null) {
       try {
+        if (evalStopwatch != null) evalCount++;
         var change = evalRecord.check();
         if (change != null && changeLog != null) {
           changeLog(evalRecord.handler.expression,
@@ -388,10 +396,13 @@ class RootWatchGroup extends WatchGroup {
       }
       evalRecord = evalRecord._nextEvalWatch;
     }
+    if (evalStopwatch != null) evalStopwatch..stop()..increment(evalCount);
 
     // Because the handler can forward changes between each other synchronously
     // We need to call reaction functions asynchronously. This processes the
     // asynchronous reaction function queue.
+    int count = 0;
+    if (processStopwatch != null) processStopwatch.stop();
     Watch dirtyWatch = _dirtyWatchHead;
     RootWatchGroup root = _rootGroup;
     root._removeCount = 0;
@@ -407,6 +418,7 @@ class RootWatchGroup extends WatchGroup {
       dirtyWatch = dirtyWatch._nextDirtyWatch;
     }
     _dirtyWatchHead = _dirtyWatchTail = null;
+    if (processStopwatch != null) processStopwatch..stop()..increment(count);
     return count;
   }
 

lib/core/module.dart

@@ -3,6 +3,7 @@ library angular.core;
 import 'dart:async' as async;
 import 'dart:collection';
 import 'dart:mirrors';
+import 'package:intl/intl.dart';
 
 import 'package:di/di.dart';
 
@@ -40,15 +41,10 @@ class NgCoreModule extends Module {
     type(FilterMap);
     type(Interpolate);
     type(RootScope);
+    factory(Scope, (injector) => injector.get(RootScope));
+    value(ScopeStats, new ScopeStats());
     value(GetterCache, new GetterCache({}));
     value(Object, {}); // RootScope context
-    factory(Scope, (injector) {
-//      try { throw null; }
-//      catch (e, s) {
-//        print('DEPRECATED reference to Scope:\n$s');
-//      }
-      return injector.get(RootScope);
-    });
     type(AstParser);
     type(NgZone);
 

lib/core/scope.dart

@@ -344,6 +344,59 @@ class Scope {
 _mapEqual(Map a, Map b) => a.length == b.length &&
     a.keys.every((k) => b.containsKey(k) && a[k] == b[k]);
 
+class ScopeStats {
+  bool report = true;
+  final nf = new NumberFormat.decimalPattern();
+
+  final digestFieldStopwatch = new AvgStopwatch();
+  final digestEvalStopwatch = new AvgStopwatch();
+  final digestProcessStopwatch = new AvgStopwatch();
+  int _digestLoopNo = 0;
+
+  final flushFieldStopwatch = new AvgStopwatch();
+  final flushEvalStopwatch = new AvgStopwatch();
+  final flushProcessStopwatch = new AvgStopwatch();
+
+  ScopeStats({this.report: false}) {
+    nf.maximumFractionDigits = 0;
+  }
+
+  void digestStart() {
+    _digestStopwatchReset();
+    _digestLoopNo = 0;
+  }
+
+  _digestStopwatchReset() {
+    digestFieldStopwatch.reset();
+    digestEvalStopwatch.reset();
+    digestProcessStopwatch.reset();
+  }
+
+  void digestLoop(int changeCount) {
+    _digestLoopNo++;
+    if (report) {
+      print(this);
+    }
+    _digestStopwatchReset();
+  }
+
+  String _stat(AvgStopwatch s) {
+    return '${nf.format(s.count)}'
+           ' / ${nf.format(s.elapsedMicroseconds)} us'
+           ' = ${nf.format(s.ratePerMs)} #/ms';
+  }
+
+  void digestEnd() {
+  }
+
+  toString() =>
+    'digest #$_digestLoopNo:'
+    'Field: ${_stat(digestFieldStopwatch)} '
+    'Eval: ${_stat(digestEvalStopwatch)} '
+    'Process: ${_stat(digestProcessStopwatch)}';
+}
+
+
 class RootScope extends Scope {
   static final STATE_APPLY = 'apply';
   static final STATE_DIGEST = 'digest';
@@ -360,11 +413,14 @@ class RootScope extends Scope {
   _FunctionChain _domWriteHead, _domWriteTail;
   _FunctionChain _domReadHead, _domReadTail;
 
+  final ScopeStats _scopeStats;
+
   String _state;
 
   RootScope(Object context, this._astParser, this._parser,
             GetterCache cacheGetter, FilterMap filterMap,
-            this._exceptionHandler, this._ttl, this._zone)
+            this._exceptionHandler, this._ttl, this._zone, 
+            this._scopeStats)
       : super(context, null, null,
             new RootWatchGroup(new DirtyCheckingChangeDetector(cacheGetter), context),
             new RootWatchGroup(new DirtyCheckingChangeDetector(cacheGetter), context))
@@ -387,6 +443,7 @@ class RootScope extends Scope {
       List digestLog;
       var count;
       ChangeLog changeLog;
+      _scopeStats.digestStart();
       do {
         while(_runAsyncHead != null) {
           try {
@@ -399,7 +456,11 @@ class RootScope extends Scope {
 
         digestTTL--;
         count = rootWatchGroup.detectChanges(
-            exceptionHandler: _exceptionHandler, changeLog: changeLog);
+            exceptionHandler: _exceptionHandler,
+            changeLog: changeLog,
+            fieldStopwatch: _scopeStats.digestFieldStopwatch,
+            evalStopwatch: _scopeStats.digestEvalStopwatch,
+            processStopwatch: _scopeStats.digestProcessStopwatch);
 
         if (digestTTL <= LOG_COUNT) {
           if (changeLog == null) {
@@ -415,8 +476,10 @@ class RootScope extends Scope {
           throw 'Model did not stabilize in ${_ttl.ttl} digests. '
                 'Last $LOG_COUNT iterations:\n${log.join('\n')}';
         }
+        _scopeStats.digestLoop(count);
       } while (count > 0);
     } finally {
+      _scopeStats.digestEnd();
       _transitionState(STATE_DIGEST, null);
     }
   }