From 552be0dd14d999f40da0cead629b2e86535bada9 Mon Sep 17 00:00:00 2001 From: Jason Jean Date: Tue, 21 Dec 2021 15:00:41 -0500 Subject: [PATCH] feat(core): introduce chrome profiling (#8215) --- .../workspace/src/tasks-runner/life-cycle.ts | 18 ++-- .../workspace/src/tasks-runner/run-command.ts | 2 +- .../src/tasks-runner/task-orchestrator.ts | 71 +++++++++++----- .../tasks-runner/task-timings-life-cycle.ts | 83 ++++++++++++++++++- 4 files changed, 144 insertions(+), 30 deletions(-) diff --git a/packages/workspace/src/tasks-runner/life-cycle.ts b/packages/workspace/src/tasks-runner/life-cycle.ts index 59c31cf2eae50..80dbd2109e1c9 100644 --- a/packages/workspace/src/tasks-runner/life-cycle.ts +++ b/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,10 +84,10 @@ 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)); } @@ -90,11 +95,12 @@ export class CompositeLifeCycle implements LifeCycle { } 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)); } diff --git a/packages/workspace/src/tasks-runner/run-command.ts b/packages/workspace/src/tasks-runner/run-command.ts index e0b553196b7d1..92659fa5017da 100644 --- a/packages/workspace/src/tasks-runner/run-command.ts +++ b/packages/workspace/src/tasks-runner/run-command.ts @@ -100,7 +100,7 @@ export async function runCommand( ] 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); diff --git a/packages/workspace/src/tasks-runner/task-orchestrator.ts b/packages/workspace/src/tasks-runner/task-orchestrator.ts index 1b9c1882812c8..c11c0d246e5b4 100644 --- a/packages/workspace/src/tasks-runner/task-orchestrator.ts +++ b/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,7 +185,7 @@ export class TaskOrchestrator { results.push(...batchResults); } - await this.postRunSteps(results); + await this.postRunSteps(results, { groupId }); const tasksCompleted = taskEntries.filter( ([taskId]) => this.completedTasks[taskId] @@ -182,13 +193,17 @@ export class TaskOrchestrator { // 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,8 +298,8 @@ 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( @@ -288,7 +307,8 @@ export class TaskOrchestrator { 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 } diff --git a/packages/workspace/src/tasks-runner/task-timings-life-cycle.ts b/packages/workspace/src/tasks-runner/task-timings-life-cycle.ts index 73b9dbffe1314..79d58753ec29f 100644 --- a/packages/workspace/src/tasks-runner/task-timings-life-cycle.ts +++ b/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); } }