[CFE] Add more benchmarking points; change how subdivides are handled

This CL adds more benchmarking points, specifically giving more insight
into where body_buildBodies time goes.

It furthermore changes how overlapping subdivides are handled.
Previously only the first subdivide was actually recorded, meaning that
if a subdivide `a` contained a subdivide `b` only subdivide `a` would
have any time recorded for it. Now instead subdivide `b` will get data
recorded for the time it runs; this time will then _not_ be added to
`a`s total. For instance if subdivide `a` spends one second, then
(while still being in subdivide `a`) we enter subdivide `b` and spend
one second there, exit it, and spend yet another second before we exit
subdivide `a` before we would just have recorded 3 seconds for subdivide
`a`, now we will instead record 2 seconds for subdivide `a` and 1 second
for subdivide `b`.

Additionally a "system subdivide" is automatically added summarizing
any unaccounted for subdivide time, and an extra entry describing the
estimated subdivide recording overhead figues too.

As an additional note, enabling benchmarking seems to add ~6-7% runtime,
and because we specifically add additional parsing phases to measure
that separately the token stream can change before doing the actual
parsing, meaning that when enabling benchmarking some errors might be
swallowed.

Change-Id: I07ef42657c385031e8bb8680738442cf04fe2263
Reviewed-on: https://dart-review.googlesource.com/c/sdk/+/295540
Reviewed-by: Johnni Winther <johnniwinther@google.com>
Commit-Queue: Jens Johansen <jensj@google.com>

pkg/front_end/lib/src/fasta/kernel/benchmarker.dart

@@ -14,8 +14,9 @@ class Benchmarker {
   final Stopwatch _subdivideStopwatch = new Stopwatch()..start();
 
   BenchmarkPhases _currentPhase = BenchmarkPhases.implicitInitialization;
-  BenchmarkSubdivides? _subdivide;
-  int _subdivideLayer = 0;
+  List<BenchmarkSubdivides> _subdivides = [
+    BenchmarkSubdivides.subdividesUnaccountedFor
+  ];
 
   void reset() {
     _totalStopwatch.start();
@@ -28,45 +29,58 @@ class Benchmarker {
       assert(BenchmarkPhases.values[i].index == i);
       _phaseTimings[i] = new PhaseTiming(BenchmarkPhases.values[i]);
     }
+    _subdivides = [BenchmarkSubdivides.subdividesUnaccountedFor];
     _currentPhase = BenchmarkPhases.implicitInitialization;
-    _subdivide = null;
-    _subdivideLayer = 0;
   }
 
   void beginSubdivide(final BenchmarkSubdivides phase) {
-    _subdivideLayer++;
-    if (_subdivideLayer != 1) return;
-    BenchmarkSubdivides? subdivide = _subdivide;
-    assert(subdivide == null);
+    _pauseLatestSubdivide(addAsCount: false);
     _subdivideStopwatch.reset();
-    _subdivide = phase;
+    _subdivides.add(phase);
+  }
+
+  void _pauseLatestSubdivide({required bool addAsCount}) {
+    if (_subdivides.isEmpty) return;
+    BenchmarkSubdivides subdivide = _subdivides.last;
+    _phaseTimings[_currentPhase.index].subdivides[subdivide.index].addRuntime(
+        _subdivideStopwatch.elapsedMicroseconds,
+        addAsCount: addAsCount);
   }
 
   void endSubdivide() {
-    _subdivideLayer--;
-    assert(_subdivideLayer >= 0);
-    if (_subdivideLayer != 0) return;
-    BenchmarkSubdivides? subdivide = _subdivide;
-    if (subdivide == null) throw "Can't end a nonexistent subdivide";
-    _phaseTimings[_currentPhase.index]
-        .subdivides[subdivide.index]
-        .addRuntime(_subdivideStopwatch.elapsedMicroseconds);
-    _subdivide = null;
+    if (_subdivides.isEmpty) throw "Can't end a nonexistent subdivide";
+    _pauseLatestSubdivide(addAsCount: true);
+    _subdivides.removeLast();
+    _subdivideStopwatch.reset();
   }
 
   void enterPhase(BenchmarkPhases phase) {
     if (_currentPhase == phase) return;
-    if (_subdivide != null) throw "Can't enter a phase while in a subdivide";
+    if (_subdivides.isEmpty) {
+      throw "System subdivide removed.";
+    }
+    endSubdivide();
+    if (_subdivides.isNotEmpty) {
+      throw "Can't enter a phase while in a subdivide";
+    }
 
     _phaseTimings[_currentPhase.index]
         .addRuntime(_phaseStopwatch.elapsedMicroseconds);
     _phaseStopwatch.reset();
     _currentPhase = phase;
+    beginSubdivide(BenchmarkSubdivides.subdividesUnaccountedFor);
   }
 
   void stop() {
     enterPhase(BenchmarkPhases.end);
     _totalStopwatch.stop();
+    if (_subdivides.isEmpty) {
+      throw "System subdivide removed.";
+    }
+    endSubdivide();
+    if (_subdivides.isNotEmpty) {
+      throw "Can't stop while in a subdivide";
+    }
   }
 
   Map<String, Object?> toJson() {
@@ -94,12 +108,19 @@ class PhaseTiming {
   }
 
   Map<String, Object?> toJson() {
-    List<SubdivideTiming> enteredSubdivides =
-        subdivides.where((element) => element._count > 0).toList();
+    List<SubdivideTiming> enteredSubdivides = [];
+    int subdivideRuntime = 0;
+    for (SubdivideTiming subdivide in subdivides) {
+      if (subdivide._count > 0) {
+        enteredSubdivides.add(subdivide);
+        subdivideRuntime += subdivide._runtime;
+      }
+    }
     return <String, Object?>{
       "phase": phase.name,
       "runtime": _runtime,
-      if (enteredSubdivides.isNotEmpty) "subdivides": enteredSubdivides,
+      "subdivides": enteredSubdivides,
+      "estimatedSubdividesOverhead": _runtime - subdivideRuntime,
     };
   }
 }
@@ -111,9 +132,11 @@ class SubdivideTiming {
 
   SubdivideTiming(this.phase);
 
-  void addRuntime(int runtime) {
+  void addRuntime(int runtime, {required bool addAsCount}) {
     _runtime += runtime;
-    _count++;
+    if (addAsCount) {
+      _count++;
+    }
   }
 
   Map<String, Object?> toJson() {
@@ -230,11 +253,19 @@ enum BenchmarkPhases {
 }
 
 enum BenchmarkSubdivides {
+  subdividesUnaccountedFor,
+
   tokenize,
 
   body_buildBody_benchmark_specific_diet_parser,
   body_buildBody_benchmark_specific_parser,
 
+  diet_listener_createListener,
+  diet_listener_buildFields,
+  diet_listener_buildFunctionBody,
+  diet_listener_buildFunctionBody_parseFunctionBody,
+  diet_listener_buildRedirectingFactoryMethod,
+
   inferImplicitFieldType,
   inferFieldInitializer,
   inferFunctionBody,

pkg/front_end/lib/src/fasta/source/diet_listener.dart

@@ -17,6 +17,8 @@ import 'package:_fe_analyzer_shared/src/parser/stack_listener.dart'
     show FixedNullableList, NullValues, ParserRecovery;
 import 'package:_fe_analyzer_shared/src/scanner/token.dart' show Token;
 import 'package:_fe_analyzer_shared/src/util/value_kind.dart';
+import 'package:front_end/src/fasta/kernel/benchmarker.dart'
+    show BenchmarkSubdivides, Benchmarker;
 import 'package:kernel/ast.dart';
 import 'package:kernel/class_hierarchy.dart' show ClassHierarchy;
 import 'package:kernel/core_types.dart' show CoreTypes;
@@ -90,6 +92,8 @@ class DietListener extends StackListenerImpl {
   @override
   Uri uri;
 
+  final Benchmarker? _benchmarker;
+
   DietListener(SourceLibraryBuilder library, this.hierarchy, this.coreTypes,
       this.typeInferenceEngine)
       : libraryBuilder = library,
@@ -98,7 +102,8 @@ class DietListener extends StackListenerImpl {
         enableNative =
             library.loader.target.backendTarget.enableNative(library.importUri),
         stringExpectedAfterNative =
-            library.loader.target.backendTarget.nativeExtensionExpectsString;
+            library.loader.target.backendTarget.nativeExtensionExpectsString,
+        _benchmarker = library.loader.target.benchmarker;
 
   DeclarationBuilder? get currentDeclaration => _currentDeclaration;
 
@@ -768,6 +773,8 @@ class DietListener extends StackListenerImpl {
       List<TypeParameter>? thisTypeParameters,
       Scope? formalParameterScope,
       InferenceDataForTesting? inferenceDataForTesting}) {
+    _benchmarker
+        ?.beginSubdivide(BenchmarkSubdivides.diet_listener_createListener);
     // Note: we set thisType regardless of whether we are building a static
     // member, since that provides better error recovery.
     // TODO(johnniwinther): Provide a dummy this on static extension methods
@@ -779,7 +786,7 @@ class DietListener extends StackListenerImpl {
     ConstantContext constantContext = builder.isConstructor && builder.isConst
         ? ConstantContext.required
         : ConstantContext.none;
-    return createListenerInternal(
+    BodyBuilder result = createListenerInternal(
         builder,
         memberScope,
         formalParameterScope,
@@ -788,6 +795,8 @@ class DietListener extends StackListenerImpl {
         thisTypeParameters,
         typeInferrer,
         constantContext);
+    _benchmarker?.endSubdivide();
+    return result;
   }
 
   BodyBuilder createListenerInternal(
@@ -834,6 +843,8 @@ class DietListener extends StackListenerImpl {
 
   void buildRedirectingFactoryMethod(Token token,
       SourceFunctionBuilderImpl builder, MemberKind kind, Token? metadata) {
+    _benchmarker?.beginSubdivide(
+        BenchmarkSubdivides.diet_listener_buildRedirectingFactoryMethod);
     final BodyBuilder listener = createFunctionListener(builder);
     try {
       Parser parser = new Parser(listener,
@@ -854,9 +865,11 @@ class DietListener extends StackListenerImpl {
     } catch (e, s) {
       throw new Crash(uri, token.charOffset, e, s);
     }
+    _benchmarker?.endSubdivide();
   }
 
   void buildFields(int count, Token token, bool isTopLevel) {
+    _benchmarker?.beginSubdivide(BenchmarkSubdivides.diet_listener_buildFields);
     List<String?>? names = const FixedNullableList<String>().pop(stack, count);
     Token? metadata = pop() as Token?;
     checkEmpty(token.charOffset);
@@ -875,6 +888,7 @@ class DietListener extends StackListenerImpl {
         metadata,
         isTopLevel);
     checkEmpty(token.charOffset);
+    _benchmarker?.endSubdivide();
   }
 
   @override
@@ -1092,6 +1106,8 @@ class DietListener extends StackListenerImpl {
 
   void buildFunctionBody(BodyBuilder bodyBuilder, Token startToken,
       Token? metadata, MemberKind kind) {
+    _benchmarker
+        ?.beginSubdivide(BenchmarkSubdivides.diet_listener_buildFunctionBody);
     Token token = startToken;
     try {
       Parser parser = new Parser(bodyBuilder,
@@ -1116,10 +1132,15 @@ class DietListener extends StackListenerImpl {
       }
       bool isExpression = false;
       bool allowAbstract = asyncModifier == AsyncMarker.Sync;
+
+      _benchmarker?.beginSubdivide(BenchmarkSubdivides
+          .diet_listener_buildFunctionBody_parseFunctionBody);
       parser.parseFunctionBody(token, isExpression, allowAbstract);
       Statement? body = bodyBuilder.pop() as Statement?;
+      _benchmarker?.endSubdivide();
       bodyBuilder.checkEmpty(token.charOffset);
       bodyBuilder.finishFunction(formals, asyncModifier, body);
+      _benchmarker?.endSubdivide();
     } on DebugAbort {
       rethrow;
     } catch (e, s) {

pkg/front_end/lib/src/fasta/source/source_loader.dart

@@ -1243,6 +1243,10 @@ severity: $severity
       // When benchmarking we do extra parsing on it's own to get a timing of
       // how much time is spent on the actual parsing (as opposed to the
       // building of what's parsed).
+      // NOTE: This runs the parser over the token stream meaning that any
+      // parser recovery rewriting the token stream will have happened once
+      // the "real" parsing is done. This in turn means that some errors
+      // (e.g. missing semi-colon) will not be issued when benchmarking.
       {
         target.benchmarker?.beginSubdivide(
             BenchmarkSubdivides.body_buildBody_benchmark_specific_diet_parser);

pkg/front_end/test/spell_checking_list_code.txt

@@ -1055,6 +1055,7 @@ pattern's
 patterned
 patterns
 paulberry
+pause
 pay
 payload
 payloads
@@ -1617,6 +1618,7 @@ ui
 uint
 umbrella
 un
+unaccounted
 unaffected
 unaligned
 unaltered