feat(core): introduce chrome profiling (nrwl#8215)

packages/workspace/src/tasks-runner/life-cycle.ts

@@ -2,6 +2,10 @@ import type { Task } from '@nrwl/devkit';
 import { TaskStatus } from './tasks-runner';
 import { TaskCacheStatus } from '../utilities/output';
 
+export interface TaskMetadata {
+  groupId: number;
+}
+
 export interface LifeCycle {
   startCommand?(): void;
 
@@ -23,10 +27,11 @@ export interface LifeCycle {
    */
   endTask?(task: Task, code: number): void;
 
-  startTasks?(task: Task[]): void;
+  startTasks?(task: Task[], metadata: TaskMetadata): void;
 
   endTasks?(
-    taskResults: Array<{ task: Task; status: TaskStatus; code: number }>
+    taskResults: Array<{ task: Task; status: TaskStatus; code: number }>,
+    metadata: TaskMetadata
   ): void;
 
   printTaskTerminalOutput?(
@@ -79,22 +84,23 @@ export class CompositeLifeCycle implements LifeCycle {
     }
   }
 
-  startTasks(tasks: Task[]): void {
+  startTasks(tasks: Task[], metadata: TaskMetadata): void {
     for (let l of this.lifeCycles) {
       if (l.startTasks) {
-        l.startTasks(tasks);
+        l.startTasks(tasks, metadata);
       } else if (l.startTask) {
         tasks.forEach((t) => l.startTask(t));
       }
     }
   }
 
   endTasks(
-    taskResults: Array<{ task: Task; status: TaskStatus; code: number }>
+    taskResults: Array<{ task: Task; status: TaskStatus; code: number }>,
+    metadata: TaskMetadata
   ): void {
     for (let l of this.lifeCycles) {
       if (l.endTasks) {
-        l.endTasks(taskResults);
+        l.endTasks(taskResults, metadata);
       } else if (l.endTask) {
         taskResults.forEach((t) => l.endTask(t.task, t.code));
       }

packages/workspace/src/tasks-runner/run-command.ts

@@ -100,7 +100,7 @@ export async function runCommand<T extends RunArgs>(
   ] as LifeCycle[];
 
   if (process.env.NX_PERF_LOGGING) {
-    lifeCycles.push(new TaskTimingsLifeCycle());
+    lifeCycles.push(new TaskTimingsLifeCycle(process.env.NX_PERF_LOGGING));
   }
   const lifeCycle = new CompositeLifeCycle(lifeCycles);
 

packages/workspace/src/tasks-runner/task-orchestrator.ts

@@ -15,6 +15,7 @@ import {
   removeTasksFromTaskGraph,
 } from './utils';
 import { Batch, TasksSchedule } from './tasks-schedule';
+import { TaskMetadata } from '@nrwl/workspace/src/tasks-runner/life-cycle';
 
 export class TaskOrchestrator {
   private cache = new Cache(this.options);
@@ -34,6 +35,7 @@ export class TaskOrchestrator {
   } = {};
   private waitingForTasks: Function[] = [];
 
+  private groups = [];
   // endregion internal state
 
   constructor(
@@ -80,14 +82,22 @@ export class TaskOrchestrator {
 
     const batch = this.tasksSchedule.nextBatch();
     if (batch) {
-      await this.applyFromCacheOrRunBatch(doNotSkipCache, batch);
+      const groupId = this.closeGroup();
+
+      await this.applyFromCacheOrRunBatch(doNotSkipCache, batch, groupId);
+
+      this.openGroup(groupId);
 
       return this.executeNextBatchOfTasksUsingTaskSchedule();
     }
 
     const task = this.tasksSchedule.nextTask();
     if (task) {
-      await this.applyFromCacheOrRunTask(doNotSkipCache, task);
+      const groupId = this.closeGroup();
+
+      await this.applyFromCacheOrRunTask(doNotSkipCache, task, groupId);
+
+      this.openGroup(groupId);
 
       return this.executeNextBatchOfTasksUsingTaskSchedule();
     }
@@ -140,12 +150,13 @@ export class TaskOrchestrator {
   // region Batch
   private async applyFromCacheOrRunBatch(
     doNotSkipCache: boolean,
-    batch: Batch
+    batch: Batch,
+    groupId: number
   ) {
     const taskEntries = Object.entries(batch.taskGraph.tasks);
     const tasks = taskEntries.map(([, task]) => task);
 
-    await this.preRunSteps(tasks);
+    await this.preRunSteps(tasks, { groupId });
 
     let results: {
       task: Task;
@@ -174,21 +185,25 @@ export class TaskOrchestrator {
       results.push(...batchResults);
     }
 
-    await this.postRunSteps(results);
+    await this.postRunSteps(results, { groupId });
 
     const tasksCompleted = taskEntries.filter(
       ([taskId]) => this.completedTasks[taskId]
     );
 
     // Batch is still not done, run it again
     if (tasksCompleted.length !== taskEntries.length) {
-      await this.applyFromCacheOrRunBatch(doNotSkipCache, {
-        executorName: batch.executorName,
-        taskGraph: removeTasksFromTaskGraph(
-          batch.taskGraph,
-          tasksCompleted.map(([taskId]) => taskId)
-        ),
-      });
+      await this.applyFromCacheOrRunBatch(
+        doNotSkipCache,
+        {
+          executorName: batch.executorName,
+          taskGraph: removeTasksFromTaskGraph(
+            batch.taskGraph,
+            tasksCompleted.map(([taskId]) => taskId)
+          ),
+        },
+        groupId
+      );
     }
   }
 
@@ -214,8 +229,12 @@ export class TaskOrchestrator {
   // endregion Batch
 
   // region Single Task
-  private async applyFromCacheOrRunTask(doNotSkipCache: boolean, task: Task) {
-    await this.preRunSteps([task]);
+  private async applyFromCacheOrRunTask(
+    doNotSkipCache: boolean,
+    task: Task,
+    groupId: number
+  ) {
+    await this.preRunSteps([task], { groupId });
 
     // hash the task here
     let results: {
@@ -238,7 +257,7 @@ export class TaskOrchestrator {
         terminalOutput,
       });
     }
-    await this.postRunSteps(results);
+    await this.postRunSteps(results, { groupId });
   }
 
   private async runTaskInForkedProcess(task: Task) {
@@ -279,16 +298,17 @@ export class TaskOrchestrator {
   // endregion Single Task
 
   // region Lifecycle
-  private async preRunSteps(tasks: Task[]) {
-    this.options.lifeCycle.startTasks(tasks);
+  private async preRunSteps(tasks: Task[], metadata: TaskMetadata) {
+    this.options.lifeCycle.startTasks(tasks, metadata);
   }
 
   private async postRunSteps(
     results: {
       task: Task;
       status: TaskStatus;
       terminalOutput?: string;
-    }[]
+    }[],
+    { groupId }: { groupId: number }
   ) {
     // cache the results
     await Promise.all(
@@ -316,7 +336,8 @@ export class TaskOrchestrator {
           status: result.status,
           code,
         };
-      })
+      }),
+      { groupId }
     );
 
     this.complete(
@@ -400,5 +421,17 @@ export class TaskOrchestrator {
     return !!task.overrides['watch'];
   }
 
+  private closeGroup() {
+    for (let i = 0; i < this.options.parallel; i++) {
+      if (!this.groups[i]) {
+        this.groups[i] = true;
+        return i;
+      }
+    }
+  }
+
+  private openGroup(id: number) {
+    this.groups[id] = false;
+  }
   // endregion utils
 }

packages/workspace/src/tasks-runner/task-timings-life-cycle.ts

@@ -1,25 +1,59 @@
-import { LifeCycle } from './life-cycle';
+import { LifeCycle, TaskMetadata } from './life-cycle';
 import { Task } from '@nrwl/devkit';
 import { TaskStatus } from './tasks-runner';
 
+import { writeFileSync } from 'fs';
+import { performance } from 'perf_hooks';
+import { join } from 'path';
+
 export class TaskTimingsLifeCycle implements LifeCycle {
-  private timings: { [target: string]: { start: number; end: number } } = {};
+  private timings: {
+    [target: string]: {
+      start: number;
+      end: number;
+      perfStart: number;
+      perfEnd?: number;
+    };
+  } = {};
+  private profile = [];
+  private readonly profileFile: string;
+  private registeredGroups = new Set();
+
+  constructor(private perfLoggingEnvValue: string) {
+    if (
+      typeof perfLoggingEnvValue === 'string' &&
+      perfLoggingEnvValue !== 'true'
+    ) {
+      this.profileFile = join(process.cwd(), perfLoggingEnvValue);
+    }
+  }
 
-  startTasks(tasks: Task[]): void {
+  startTasks(tasks: Task[], { groupId }: TaskMetadata): void {
+    if (this.profileFile && !this.registeredGroups.has(groupId)) {
+      this.registerGroup(groupId);
+    }
     for (let t of tasks) {
       this.timings[`${t.target.project}:${t.target.target}`] = {
         start: new Date().getTime(),
         end: undefined,
+        perfStart: performance.now(),
       };
     }
   }
 
   endTasks(
-    taskResults: Array<{ task: Task; status: TaskStatus; code: number }>
+    taskResults: Array<{ task: Task; status: TaskStatus; code: number }>,
+    metadata: TaskMetadata
   ): void {
     for (let tr of taskResults) {
       this.timings[`${tr.task.target.project}:${tr.task.target.target}`].end =
         new Date().getTime();
+      this.timings[
+        `${tr.task.target.project}:${tr.task.target.target}`
+      ].perfEnd = performance.now();
+    }
+    if (this.profileFile) {
+      this.recordTaskCompletions(taskResults, metadata);
     }
   }
 
@@ -31,5 +65,46 @@ export class TaskTimingsLifeCycle implements LifeCycle {
       timings[p] = t.end ? t.end - t.start : null;
     });
     console.log(JSON.stringify(timings, null, 2));
+    if (this.profileFile) {
+      writeFileSync('profile.json', JSON.stringify(this.profile));
+      console.log(`Performance Profile: ${this.profileFile}`);
+    }
+  }
+
+  private recordTaskCompletions(
+    tasks: Array<{ task: Task; status: TaskStatus }>,
+    { groupId }: TaskMetadata
+  ) {
+    for (const { task, status } of tasks) {
+      const { perfStart, perfEnd } =
+        this.timings[`${task.target.project}:${task.target.target}`];
+      this.profile.push({
+        name: task.id,
+        cat: Object.values(task.target).join(','),
+        ph: 'X',
+        ts: perfStart * 1000,
+        dur: (perfEnd - perfStart) * 1000,
+        pid: process.pid,
+        tid: groupId,
+        args: {
+          target: task.target,
+          status,
+        },
+      });
+    }
+  }
+
+  private registerGroup(groupId: number) {
+    this.profile.push({
+      name: 'thread_name',
+      ph: 'M',
+      pid: process.pid,
+      tid: groupId,
+      ts: 0,
+      args: {
+        name: 'Group #' + (groupId + 1),
+      },
+    });
+    this.registeredGroups.add(groupId);
   }
 }