diff --git a/docs/map.json b/docs/map.json index ca2291cb53..8f3fbbc5f9 100644 --- a/docs/map.json +++ b/docs/map.json @@ -1487,6 +1487,11 @@ "id": "monorepo-nx-enterprise", "file": "shared/monorepo-nx-enterprise" }, + { + "name": "Profiling Build Performance", + "id": "performance-profiling", + "file": "shared/guides/performance-profiling" + }, { "name": "Using ESLint in Nx Workspaces", "id": "eslint", diff --git a/docs/shared/guides/performance-profiling-devtools.png b/docs/shared/guides/performance-profiling-devtools.png new file mode 100644 index 0000000000..acc576969f Binary files /dev/null and b/docs/shared/guides/performance-profiling-devtools.png differ diff --git a/docs/shared/guides/performance-profiling.md b/docs/shared/guides/performance-profiling.md new file mode 100644 index 0000000000..7984ef79d7 --- /dev/null +++ b/docs/shared/guides/performance-profiling.md @@ -0,0 +1,29 @@ +# Profiling Performance + +When running an Nx command, many tasks are run at different times in different processes. +Visualizing where and when the tasks were executed can help optimize the entire run to be quicker. + +## How to Profile the Performance of Running Tasks + +1. Prepend `NX_PROFILE=profile.json` before running targets with Nx. For example, + +```bash +# This builds the "cart" application and creates a profile.json file +NX_PROFILE=profile.json nx build cart + +# This builds affected projects and creates a profile.json file +NX_PROFILE=profile.json nx affected --target build +``` + +2. Open the Performance Tab in Chrome Devtools + ![Performance Profiling with Chrome Devtools](./performance-profiling-devtools.png) +3. Click the upload button and open the `profile.json` that was created. (Or drag the file into the window) +4. Expand each group to see the names of the tasks which were run + +## Optimizing the Performance of Running Tasks + +Now that you have visualized how the tasks were run, you can try tweaking things to make the process faster. Generate profiles after each tweak and compare the results. + +1. Are there tasks that you did not expect to be necessary? Sometimes, more tasks are captured by a command than expected. Excluding them could free up workers for other tasks. +2. Try adding more workers. Did the new workers handle tasks while other workers were busy? This will likely result in faster runs. +3. Are a lot of the tasks waiting on a single task to be completed? Splitting that project into smaller projects may allow fewer projects and therefore tasks to depend on a single project/task. This will allow for more room to parallelize the tasks. diff --git a/nx-dev/nx-dev/public/documentation/map.json b/nx-dev/nx-dev/public/documentation/map.json index ca2291cb53..8f3fbbc5f9 100644 --- a/nx-dev/nx-dev/public/documentation/map.json +++ b/nx-dev/nx-dev/public/documentation/map.json @@ -1487,6 +1487,11 @@ "id": "monorepo-nx-enterprise", "file": "shared/monorepo-nx-enterprise" }, + { + "name": "Profiling Build Performance", + "id": "performance-profiling", + "file": "shared/guides/performance-profiling" + }, { "name": "Using ESLint in Nx Workspaces", "id": "eslint", diff --git a/nx-dev/nx-dev/public/documentation/shared/guides/performance-profiling-devtools.png b/nx-dev/nx-dev/public/documentation/shared/guides/performance-profiling-devtools.png new file mode 100644 index 0000000000..acc576969f Binary files /dev/null and b/nx-dev/nx-dev/public/documentation/shared/guides/performance-profiling-devtools.png differ diff --git a/nx-dev/nx-dev/public/documentation/shared/guides/performance-profiling.md b/nx-dev/nx-dev/public/documentation/shared/guides/performance-profiling.md new file mode 100644 index 0000000000..7984ef79d7 --- /dev/null +++ b/nx-dev/nx-dev/public/documentation/shared/guides/performance-profiling.md @@ -0,0 +1,29 @@ +# Profiling Performance + +When running an Nx command, many tasks are run at different times in different processes. +Visualizing where and when the tasks were executed can help optimize the entire run to be quicker. + +## How to Profile the Performance of Running Tasks + +1. Prepend `NX_PROFILE=profile.json` before running targets with Nx. For example, + +```bash +# This builds the "cart" application and creates a profile.json file +NX_PROFILE=profile.json nx build cart + +# This builds affected projects and creates a profile.json file +NX_PROFILE=profile.json nx affected --target build +``` + +2. Open the Performance Tab in Chrome Devtools + ![Performance Profiling with Chrome Devtools](./performance-profiling-devtools.png) +3. Click the upload button and open the `profile.json` that was created. (Or drag the file into the window) +4. Expand each group to see the names of the tasks which were run + +## Optimizing the Performance of Running Tasks + +Now that you have visualized how the tasks were run, you can try tweaking things to make the process faster. Generate profiles after each tweak and compare the results. + +1. Are there tasks that you did not expect to be necessary? Sometimes, more tasks are captured by a command than expected. Excluding them could free up workers for other tasks. +2. Try adding more workers. Did the new workers handle tasks while other workers were busy? This will likely result in faster runs. +3. Are a lot of the tasks waiting on a single task to be completed? Splitting that project into smaller projects may allow fewer projects and therefore tasks to depend on a single project/task. This will allow for more room to parallelize the tasks. diff --git a/packages/workspace/src/tasks-runner/run-command.ts b/packages/workspace/src/tasks-runner/run-command.ts index 05eed74a0e..dfa5812c79 100644 --- a/packages/workspace/src/tasks-runner/run-command.ts +++ b/packages/workspace/src/tasks-runner/run-command.ts @@ -25,6 +25,7 @@ import { EmptyTerminalOutputLifeCycle } from './empty-terminal-output-life-cycle import { RunOneTerminalOutputLifeCycle } from './run-one-terminal-output-life-cycle'; import { TaskTimingsLifeCycle } from './task-timings-life-cycle'; import { createOutputRenderer } from './neo-output/render'; +import { TaskProfilingLifeCycle } from '@nrwl/workspace/src/tasks-runner/task-profiling-life-cycle'; async function getTerminalOutputLifeCycle( initiatingProject: string, @@ -117,7 +118,11 @@ export async function runCommand( const lifeCycles = [lifeCycle] as LifeCycle[]; if (process.env.NX_PERF_LOGGING) { - lifeCycles.push(new TaskTimingsLifeCycle(process.env.NX_PERF_LOGGING)); + lifeCycles.push(new TaskTimingsLifeCycle()); + } + + if (process.env.NX_PROFILE) { + lifeCycles.push(new TaskProfilingLifeCycle(process.env.NX_PROFILE)); } const promiseOrObservable = tasksRunner( diff --git a/packages/workspace/src/tasks-runner/task-profiling-life-cycle.ts b/packages/workspace/src/tasks-runner/task-profiling-life-cycle.ts new file mode 100644 index 0000000000..d427166859 --- /dev/null +++ b/packages/workspace/src/tasks-runner/task-profiling-life-cycle.ts @@ -0,0 +1,87 @@ +import { LifeCycle, TaskMetadata } from './life-cycle'; +import { Task, writeJsonFile } from '@nrwl/devkit'; +import { TaskStatus } from './tasks-runner'; + +import { performance } from 'perf_hooks'; +import { join } from 'path'; + +export class TaskProfilingLifeCycle implements LifeCycle { + private timings: { + [target: string]: { + perfStart: number; + perfEnd?: number; + }; + } = {}; + private profile = []; + private readonly profileFile: string; + private registeredGroups = new Set(); + + constructor(_profileFile: string) { + this.profileFile = join(process.cwd(), _profileFile); + } + + 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}`] = { + perfStart: performance.now(), + }; + } + } + + endTasks( + 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}` + ].perfEnd = performance.now(); + } + this.recordTaskCompletions(taskResults, metadata); + } + + endCommand(): void { + writeJsonFile(this.profileFile, 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); + } +} 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 79d58753ec..45e42e895e 100644 --- a/packages/workspace/src/tasks-runner/task-timings-life-cycle.ts +++ b/packages/workspace/src/tasks-runner/task-timings-life-cycle.ts @@ -1,59 +1,30 @@ -import { LifeCycle, TaskMetadata } from './life-cycle'; +import { LifeCycle } 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; - 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[], { groupId }: TaskMetadata): void { - if (this.profileFile && !this.registeredGroups.has(groupId)) { - this.registerGroup(groupId); - } + startTasks(tasks: Task[]): void { 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 }>, - metadata: TaskMetadata + taskResults: Array<{ task: Task; status: TaskStatus; code: number }> ): 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); } } @@ -65,46 +36,5 @@ 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); } }