[hooks_runner] Add TimelineEvents (#2327)

This PR adds timeline events to the `hooks_runner` package:

* All `FileSystem` calls. (With a `TracingFileSystem`.)
* All `Process` runs.
* The main methods.

This enables looking at the performance:

<img width="990" alt="image" src="https://github.com/user-attachments/assets/6a5c78be-46b7-4a0a-bc9a-ada325a30193" />

(First build compiles the hook and runs the hook. Second build doesn't compile the hook and doesn't run the hook. Side note: Compiling Dart takes longer than running the hook (compiling C)!)

Some quirks:

* The current approach only works for non-concurrent events. (The stdout and stderr file logging is concurrent to the process calls and therefore has to be excluded.) If we ever start doing things concurrently, we'll need to refactor this.
* There are a lot of possibilities to improve things when we have more than one hook in the system. Optimizing this only makes sense once we have more real world projects using hooks.
* Tracking issues for improving the performance: #1288 #1578

The one improvement made in this PR is that we stop hashing the kernel file contents. Saving a hook invocation if the kernel file didn't change (~300ms) if the hook sources only had a whitespace change seems less valuable than saving the hashing of the hook kernel file on every invocation (~50ms). After this change, cached hook invocations take ~30ms per hook on the local test cases.

Closes: #2236

Author: dcharkes

pkgs/hooks_runner/CHANGELOG.md

@@ -1,3 +1,8 @@
+## 0.20.2
+
+* Add `dart:developer` `TimelineEvent`s to enable performance tracing for
+  hook invocations.
+
 ## 0.20.1
 
 * Bump the SDK constraint to at least the one from `package:hooks` to fix

pkgs/hooks_runner/lib/src/build_runner/build_planner.dart

@@ -3,6 +3,7 @@
 // BSD-style license that can be found in the LICENSE file.
 
 import 'dart:convert';
+import 'dart:developer';
 
 import 'package:file/file.dart';
 import 'package:graphs/graphs.dart' as graphs;
@@ -19,13 +20,16 @@ typedef BuildPlan = List<Package>;
 
 @internal
 class NativeAssetsBuildPlanner {
+  final TimelineTask task;
+
   final PackageGraph packageGraph;
   final Uri dartExecutable;
   final Logger logger;
   final PackageLayout packageLayout;
   final FileSystem fileSystem;
 
   NativeAssetsBuildPlanner._({
+    required this.task,
     required this.packageGraph,
     required this.dartExecutable,
     required this.logger,
@@ -39,11 +43,12 @@ class NativeAssetsBuildPlanner {
     required Logger logger,
     required PackageLayout packageLayout,
     required FileSystem fileSystem,
+    TimelineTask? task,
   }) async {
     final packageGraphJsonFile = fileSystem.file(
       packageConfigUri.resolve('package_graph.json'),
     );
-    assert(packageGraphJsonFile.existsSync());
+    assert(await packageGraphJsonFile.exists());
     final packageGraphJson = await packageGraphJsonFile.readAsString();
     final packageGraph = PackageGraph.fromPackageGraphJsonString(
       packageGraphJson,
@@ -57,17 +62,22 @@ class NativeAssetsBuildPlanner {
       logger: logger,
       packageLayout: packageLayout,
       fileSystem: fileSystem,
+      task: task ?? TimelineTask(),
     );
   }
 
   /// All packages in [PackageLayout.packageConfig] with native assets.
   ///
   /// Whether a package has native assets is defined by whether it contains
   /// a `hook/build.dart` or `hook/link.dart`.
-  Future<List<Package>> packagesWithHook(Hook hook) async => switch (hook) {
-    Hook.build => _packagesWithBuildHook ??= await _runPackagesWithHook(hook),
-    Hook.link => _packagesWithLinkHook ??= await _runPackagesWithHook(hook),
-  };
+  Future<List<Package>> packagesWithHook(Hook hook) async => _timeAsync(
+    'BuildPlanner.packagesWithHook',
+    arguments: {'hook': hook.toString()},
+    () async => switch (hook) {
+      Hook.build => _packagesWithBuildHook ??= await _runPackagesWithHook(hook),
+      Hook.link => _packagesWithLinkHook ??= await _runPackagesWithHook(hook),
+    },
+  );
 
   List<Package>? _packagesWithBuildHook;
   List<Package>? _packagesWithLinkHook;
@@ -113,38 +123,53 @@ class NativeAssetsBuildPlanner {
   /// a cyclic dependency is detected among packages with native asset build
   /// hooks, the [Result] is a [Failure] containing a
   /// [HooksRunnerFailure.projectConfig].
-  Future<Result<BuildPlan, HooksRunnerFailure>> makeBuildHookPlan() async {
-    if (_buildHookPlan != null) return Success(_buildHookPlan!);
-    final packagesWithNativeAssets = await packagesWithHook(Hook.build);
-    if (packagesWithNativeAssets.isEmpty) {
-      // Avoid calculating the package graph if there are no hooks.
-      return const Success([]);
-    }
-    final packageMap = {
-      for (final package in packagesWithNativeAssets) package.name: package,
-    };
-    final packagesToBuild = packageMap.keys.toSet();
-    final stronglyConnectedComponents = packageGraph.computeStrongComponents();
-    final result = <Package>[];
-    for (final stronglyConnectedComponent in stronglyConnectedComponents) {
-      final stronglyConnectedComponentWithNativeAssets = [
-        for (final packageName in stronglyConnectedComponent)
-          if (packagesToBuild.contains(packageName)) packageName,
-      ];
-      if (stronglyConnectedComponentWithNativeAssets.length > 1) {
-        logger.severe(
-          'Cyclic dependency for native asset builds in the following '
-          'packages: $stronglyConnectedComponentWithNativeAssets.',
-        );
-        return const Failure(HooksRunnerFailure.projectConfig);
-      } else if (stronglyConnectedComponentWithNativeAssets.length == 1) {
-        result.add(
-          packageMap[stronglyConnectedComponentWithNativeAssets.single]!,
-        );
-      }
+  Future<Result<BuildPlan, HooksRunnerFailure>> makeBuildHookPlan() async =>
+      _timeAsync('BuildPlanner.makeBuildHookPlan', () async {
+        if (_buildHookPlan != null) return Success(_buildHookPlan!);
+        final packagesWithNativeAssets = await packagesWithHook(Hook.build);
+        if (packagesWithNativeAssets.isEmpty) {
+          // Avoid calculating the package graph if there are no hooks.
+          return const Success([]);
+        }
+        final packageMap = {
+          for (final package in packagesWithNativeAssets) package.name: package,
+        };
+        final packagesToBuild = packageMap.keys.toSet();
+        final stronglyConnectedComponents = packageGraph
+            .computeStrongComponents();
+        final result = <Package>[];
+        for (final stronglyConnectedComponent in stronglyConnectedComponents) {
+          final stronglyConnectedComponentWithNativeAssets = [
+            for (final packageName in stronglyConnectedComponent)
+              if (packagesToBuild.contains(packageName)) packageName,
+          ];
+          if (stronglyConnectedComponentWithNativeAssets.length > 1) {
+            logger.severe(
+              'Cyclic dependency for native asset builds in the following '
+              'packages: $stronglyConnectedComponentWithNativeAssets.',
+            );
+            return const Failure(HooksRunnerFailure.projectConfig);
+          } else if (stronglyConnectedComponentWithNativeAssets.length == 1) {
+            result.add(
+              packageMap[stronglyConnectedComponentWithNativeAssets.single]!,
+            );
+          }
+        }
+        _buildHookPlan = result;
+        return Success(result);
+      });
+
+  Future<T> _timeAsync<T>(
+    String name,
+    Future<T> Function() function, {
+    Map<String, Object>? arguments,
+  }) async {
+    task.start(name, arguments: arguments);
+    try {
+      return await function();
+    } finally {
+      task.finish();
     }
-    _buildHookPlan = result;
-    return Success(result);
   }
 }