chore(core): add perf logging

leosvelperez · leosvelperez · commit 08ab57ad8ce2 · 2025-12-15T15:27:55.000+01:00
diff --git a/packages/nx/src/hasher/task-details-recorder.ts b/packages/nx/src/hasher/task-details-recorder.ts
@@ -1,3 +1,4 @@
+import { performance } from 'perf_hooks';
 import type { HashedTask } from '../native';
 import { IS_WASM, TaskDetails } from '../native';
 import { getDbConnection } from '../utils/db-connection';
@@ -17,6 +18,8 @@ class TaskDetailsRecorder {
   async recordTaskDetails(tasks: HashedTask[]): Promise<void> {
     if (tasks.length === 0) return;
 
+    performance.mark('db:taskDetails.record:start');
+
     if (
       isOnDaemon() ||
       !daemonClient.enabled() ||
@@ -26,6 +29,13 @@ class TaskDetailsRecorder {
     } else {
       await daemonClient.recordTaskDetails(tasks);
     }
+
+    performance.mark('db:taskDetails.record:end');
+    performance.measure(
+      'db:taskDetails.record',
+      'db:taskDetails.record:start',
+      'db:taskDetails.record:end'
+    );
   }
 }
 
diff --git a/packages/nx/src/tasks-runner/cache.ts b/packages/nx/src/tasks-runner/cache.ts
@@ -119,6 +119,8 @@ export class DbCache {
   }
 
   async get(task: Task): Promise<CachedResult | null> {
+    performance.mark('db:cache.get:start');
+
     let res: NativeCacheResult | null;
 
     if (this.shouldDelegateToDaemon()) {
@@ -127,6 +129,13 @@ export class DbCache {
       res = this.cache.get(task.hash);
     }
 
+    performance.mark('db:cache.get:end');
+    performance.measure(
+      'db:cache.get',
+      'db:cache.get:start',
+      'db:cache.get:end'
+    );
+
     if (res) {
       return {
         ...res,
@@ -156,10 +165,28 @@ export class DbCache {
   }
 
   getUsedCacheSpace(): number | Promise<number> {
+    performance.mark('db:cache.getUsedCacheSpace:start');
+
     if (this.shouldDelegateToDaemon()) {
-      return daemonClient.cacheGetSize();
+      return daemonClient.cacheGetSize().then((size) => {
+        performance.mark('db:cache.getUsedCacheSpace:end');
+        performance.measure(
+          'db:cache.getUsedCacheSpace',
+          'db:cache.getUsedCacheSpace:start',
+          'db:cache.getUsedCacheSpace:end'
+        );
+        return size;
+      });
     }
-    return this.cache.getCacheSize();
+
+    const result = this.cache.getCacheSize();
+    performance.mark('db:cache.getUsedCacheSpace:end');
+    performance.measure(
+      'db:cache.getUsedCacheSpace',
+      'db:cache.getUsedCacheSpace:start',
+      'db:cache.getUsedCacheSpace:end'
+    );
+    return result;
   }
 
   private applyRemoteCacheResults(
@@ -180,12 +207,21 @@ export class DbCache {
     code: number
   ) {
     return tryAndRetry(async () => {
+      performance.mark('db:cache.put:start');
+
       if (this.shouldDelegateToDaemon()) {
         await daemonClient.cachePut(task.hash, terminalOutput, outputs, code);
       } else {
         this.cache.put(task.hash, terminalOutput, outputs, code);
       }
 
+      performance.mark('db:cache.put:end');
+      performance.measure(
+        'db:cache.put',
+        'db:cache.put:start',
+        'db:cache.put:end'
+      );
+
       if (this.remoteCache) {
         await this.remoteCache.store(task.hash, cacheDir, terminalOutput, code);
       }
@@ -199,10 +235,28 @@ export class DbCache {
   }
 
   removeOldCacheRecords(): void | Promise<void> {
+    performance.mark('db:cache.removeOldRecords:start');
+
     if (this.shouldDelegateToDaemon()) {
-      return daemonClient.cacheRemoveOldRecords();
+      return daemonClient.cacheRemoveOldRecords().then((result) => {
+        performance.mark('db:cache.removeOldRecords:end');
+        performance.measure(
+          'db:cache.removeOldRecords',
+          'db:cache.removeOldRecords:start',
+          'db:cache.removeOldRecords:end'
+        );
+        return result;
+      });
     }
-    return this.cache.removeOldCacheRecords();
+
+    const result = this.cache.removeOldCacheRecords();
+    performance.mark('db:cache.removeOldRecords:end');
+    performance.measure(
+      'db:cache.removeOldRecords',
+      'db:cache.removeOldRecords:start',
+      'db:cache.removeOldRecords:end'
+    );
+    return result;
   }
 
   temporaryOutputPath(task: Task): string {
diff --git a/packages/nx/src/utils/perf-logging.ts b/packages/nx/src/utils/perf-logging.ts
@@ -1,14 +1,43 @@
 import { PerformanceObserver } from 'perf_hooks';
 
 let initialized = false;
+const measurements: Map<string, number[]> = new Map();
 
 if (process.env.NX_PERF_LOGGING === 'true' && !initialized) {
   initialized = true;
 
   const obs = new PerformanceObserver((list) => {
     for (const entry of list.getEntries()) {
       console.log(`Time for '${entry.name}'`, entry.duration);
+
+      // Only aggregate DB operations for summary
+      if (entry.name.startsWith('db:')) {
+        if (!measurements.has(entry.name)) {
+          measurements.set(entry.name, []);
+        }
+        measurements.get(entry.name)!.push(entry.duration);
+      }
     }
   });
   obs.observe({ entryTypes: ['measure'] });
+
+  process.on('exit', () => {
+    if (!global.NX_PLUGIN_WORKER && measurements.size > 0) {
+      console.log('\n=== DB Operations Performance Summary ===');
+      let totalTime = 0;
+
+      for (const [name, durations] of measurements) {
+        const total = durations.reduce((a, b) => a + b, 0);
+        totalTime += total;
+        console.log(
+          `${name}: count=${durations.length}, total=${total.toFixed(
+            2
+          )}ms, avg=${(total / durations.length).toFixed(2)}ms`
+        );
+      }
+
+      console.log(`\nTotal DB time: ${totalTime.toFixed(2)}ms`);
+      console.log('==========================================\n');
+    }
+  });
 }
diff --git a/packages/nx/src/utils/running-tasks.ts b/packages/nx/src/utils/running-tasks.ts
@@ -1,3 +1,4 @@
+import { performance } from 'perf_hooks';
 import {
   IS_WASM,
   RunningTasksService as NxRunningTasksService,
@@ -17,36 +18,90 @@ export class RunningTasksService {
   }
 
   getRunningTasks(ids: string[]): string[] | Promise<string[]> {
+    performance.mark('db:runningTasks.get:start');
+
     if (
       isOnDaemon() ||
       !daemonClient.enabled() ||
       !shouldDelegateDbToDaemon()
     ) {
-      return this.service.getRunningTasks(ids);
+      const result = this.service.getRunningTasks(ids);
+      performance.mark('db:runningTasks.get:end');
+      performance.measure(
+        'db:runningTasks.get',
+        'db:runningTasks.get:start',
+        'db:runningTasks.get:end'
+      );
+      return result;
     }
-    return daemonClient.getRunningTasks(ids);
+
+    return daemonClient.getRunningTasks(ids).then((result) => {
+      performance.mark('db:runningTasks.get:end');
+      performance.measure(
+        'db:runningTasks.get',
+        'db:runningTasks.get:start',
+        'db:runningTasks.get:end'
+      );
+      return result;
+    });
   }
 
   addRunningTask(taskId: string): void | Promise<void> {
+    performance.mark('db:runningTasks.add:start');
+
     if (
       isOnDaemon() ||
       !daemonClient.enabled() ||
       !shouldDelegateDbToDaemon()
     ) {
-      return this.service.addRunningTask(taskId);
+      const result = this.service.addRunningTask(taskId);
+      performance.mark('db:runningTasks.add:end');
+      performance.measure(
+        'db:runningTasks.add',
+        'db:runningTasks.add:start',
+        'db:runningTasks.add:end'
+      );
+      return result;
     }
-    return daemonClient.addRunningTask(taskId);
+
+    return daemonClient.addRunningTask(taskId).then((result) => {
+      performance.mark('db:runningTasks.add:end');
+      performance.measure(
+        'db:runningTasks.add',
+        'db:runningTasks.add:start',
+        'db:runningTasks.add:end'
+      );
+      return result;
+    });
   }
 
   removeRunningTask(taskId: string): void | Promise<void> {
+    performance.mark('db:runningTasks.remove:start');
+
     if (
       isOnDaemon() ||
       !daemonClient.enabled() ||
       !shouldDelegateDbToDaemon()
     ) {
-      return this.service.removeRunningTask(taskId);
+      const result = this.service.removeRunningTask(taskId);
+      performance.mark('db:runningTasks.remove:end');
+      performance.measure(
+        'db:runningTasks.remove',
+        'db:runningTasks.remove:start',
+        'db:runningTasks.remove:end'
+      );
+      return result;
     }
-    return daemonClient.removeRunningTask(taskId);
+
+    return daemonClient.removeRunningTask(taskId).then((result) => {
+      performance.mark('db:runningTasks.remove:end');
+      performance.measure(
+        'db:runningTasks.remove',
+        'db:runningTasks.remove:start',
+        'db:runningTasks.remove:end'
+      );
+      return result;
+    });
   }
 }
 
diff --git a/packages/nx/src/utils/task-history.ts b/packages/nx/src/utils/task-history.ts
@@ -1,3 +1,4 @@
+import { performance } from 'perf_hooks';
 import { daemonClient } from '../daemon/client/client';
 import { isOnDaemon } from '../daemon/is-on-daemon';
 import { IS_WASM, NxTaskHistory, TaskRun, TaskTarget } from '../native';
@@ -21,24 +22,60 @@ export class TaskHistory {
   async getEstimatedTaskTimings(
     targets: TaskTarget[]
   ): Promise<Record<string, number>> {
+    performance.mark('db:taskHistory.getEstimatedTimings:start');
+
+    let result: Record<string, number>;
     if (isOnDaemon() || !daemonClient.enabled()) {
-      return this.taskHistory.getEstimatedTaskTimings(targets);
+      result = this.taskHistory.getEstimatedTaskTimings(targets);
+    } else {
+      result = await daemonClient.getEstimatedTaskTimings(targets);
     }
-    return daemonClient.getEstimatedTaskTimings(targets);
+
+    performance.mark('db:taskHistory.getEstimatedTimings:end');
+    performance.measure(
+      'db:taskHistory.getEstimatedTimings',
+      'db:taskHistory.getEstimatedTimings:start',
+      'db:taskHistory.getEstimatedTimings:end'
+    );
+
+    return result;
   }
 
   async getFlakyTasks(hashes: string[]) {
+    performance.mark('db:taskHistory.getFlakyTasks:start');
+
+    let result: string[];
     if (isOnDaemon() || !daemonClient.enabled()) {
-      return this.taskHistory.getFlakyTasks(hashes);
+      result = this.taskHistory.getFlakyTasks(hashes);
+    } else {
+      result = await daemonClient.getFlakyTasks(hashes);
     }
-    return daemonClient.getFlakyTasks(hashes);
+
+    performance.mark('db:taskHistory.getFlakyTasks:end');
+    performance.measure(
+      'db:taskHistory.getFlakyTasks',
+      'db:taskHistory.getFlakyTasks:start',
+      'db:taskHistory.getFlakyTasks:end'
+    );
+
+    return result;
   }
 
   async recordTaskRuns(taskRuns: TaskRun[]) {
+    performance.mark('db:taskHistory.recordTaskRuns:start');
+
     if (isOnDaemon() || !daemonClient.enabled()) {
-      return this.taskHistory.recordTaskRuns(taskRuns);
+      this.taskHistory.recordTaskRuns(taskRuns);
+    } else {
+      await daemonClient.recordTaskRuns(taskRuns);
     }
-    return daemonClient.recordTaskRuns(taskRuns);
+
+    performance.mark('db:taskHistory.recordTaskRuns:end');
+    performance.measure(
+      'db:taskHistory.recordTaskRuns',
+      'db:taskHistory.recordTaskRuns:start',
+      'db:taskHistory.recordTaskRuns:end'
+    );
   }
 }
 
