feat(core): add more perf logging to make troubleshooting perf issue …

…easier

packages/nx/bin/init-local.ts

@@ -1,8 +1,7 @@
-import { getPackageManagerCommand } from '../src/utils/package-manager';
-
 import { performance } from 'perf_hooks';
 import { execSync } from 'child_process';
 
+import { getPackageManagerCommand } from '../src/utils/package-manager';
 import { commandsObject } from '../src/command-line/nx-commands';
 import { WorkspaceTypeAndRoot } from '../src/utils/find-workspace-root';
 import { stripIndents } from '../src/utils/strip-indents';

packages/nx/src/command-line/affected/affected.ts

@@ -32,7 +32,8 @@ export async function affected(
     (TargetDependencyConfig | string)[]
   > = {}
 ): Promise<void> {
-  performance.mark('command-execution-begins');
+  performance.mark('code-loading:end');
+  performance.measure('code-loading', 'init-local', 'code-loading:end');
   workspaceConfigurationCheck();
 
   const nxJson = readNxJson();

packages/nx/src/command-line/run-many/run-many.ts

@@ -30,7 +30,8 @@ export async function runMany(
     loadDotEnvFiles: boolean;
   }
 ) {
-  performance.mark('command-execution-begins');
+  performance.mark('code-loading:end');
+  performance.measure('code-loading', 'init-local', 'code-loading:end');
   workspaceConfigurationCheck();
   const nxJson = readNxJson();
   const { nxArgs, overrides } = splitArgsIntoNxArgsAndOverrides(

packages/nx/src/command-line/run/run-one.ts

@@ -34,8 +34,8 @@ export async function runOne(
     loadDotEnvFiles: boolean;
   }
 ): Promise<void> {
-  performance.mark('command-execution-begins');
-  performance.measure('code-loading', 'init-local', 'command-execution-begins');
+  performance.mark('code-loading:end');
+  performance.measure('code-loading', 'init-local', 'code-loading:end');
   workspaceConfigurationCheck();
 
   const nxJson = readNxJson();

packages/nx/src/daemon/server/file-watching/file-watcher-sockets.ts

@@ -90,13 +90,15 @@ export function notifyFileWatcherSockets(
         }
 
         if (changedProjects.length > 0 || changedFiles.length > 0) {
-          return handleResult(socket, {
-            description: 'File watch changed',
-            response: JSON.stringify({
-              changedProjects,
-              changedFiles,
-            }),
-          });
+          return handleResult(socket, 'FILE-WATCH-CHANGED', () =>
+            Promise.resolve({
+              description: 'File watch changed',
+              response: JSON.stringify({
+                changedProjects,
+                changedFiles,
+              }),
+            })
+          );
         }
       })
     );

packages/nx/src/daemon/server/server.ts

@@ -134,26 +134,34 @@ async function handleMessage(socket, data: string) {
   }
 
   if (payload.type === 'PING') {
-    await handleResult(socket, {
-      response: JSON.stringify(true),
-      description: 'ping',
-    });
+    await handleResult(socket, 'PING', () =>
+      Promise.resolve({ response: JSON.stringify(true), description: 'ping' })
+    );
   } else if (payload.type === 'REQUEST_PROJECT_GRAPH') {
-    await handleResult(socket, await handleRequestProjectGraph());
+    await handleResult(socket, 'REQUEST_PROJECT_GRAPH', () =>
+      handleRequestProjectGraph()
+    );
   } else if (payload.type === 'HASH_TASKS') {
-    await handleResult(socket, await handleHashTasks(payload));
+    await handleResult(socket, 'HASH_TASKS', () => handleHashTasks(payload));
   } else if (payload.type === 'REQUEST_FILE_DATA') {
-    await handleResult(socket, await handleRequestFileData());
+    await handleResult(socket, 'REQUEST_FILE_DATA', () =>
+      handleRequestFileData()
+    );
   } else if (payload.type === 'PROCESS_IN_BACKGROUND') {
-    await handleResult(socket, await handleProcessInBackground(payload));
+    await handleResult(socket, 'PROCESS_IN_BACKGROUND', () =>
+      handleProcessInBackground(payload)
+    );
   } else if (payload.type === 'RECORD_OUTPUTS_HASH') {
-    await handleResult(socket, await handleRecordOutputsHash(payload));
+    await handleResult(socket, 'RECORD_OUTPUTS_HASH', () =>
+      handleRecordOutputsHash(payload)
+    );
   } else if (payload.type === 'OUTPUTS_HASHES_MATCH') {
-    await handleResult(socket, await handleOutputsHashesMatch(payload));
+    await handleResult(socket, 'OUTPUTS_HASHES_MATCH', () =>
+      handleOutputsHashesMatch(payload)
+    );
   } else if (payload.type === 'REQUEST_SHUTDOWN') {
-    await handleResult(
-      socket,
-      await handleRequestShutdown(server, numberOfOpenConnections)
+    await handleResult(socket, 'REQUEST_SHUTDOWN', () =>
+      handleRequestShutdown(server, numberOfOpenConnections)
     );
   } else if (payload.type === 'REGISTER_FILE_WATCHER') {
     registeredFileWatcherSockets.push({ socket, config: payload.config });
@@ -166,12 +174,25 @@ async function handleMessage(socket, data: string) {
   }
 }
 
-export async function handleResult(socket: Socket, hr: HandlerResult) {
+export async function handleResult(
+  socket: Socket,
+  type: string,
+  hrFn: () => Promise<HandlerResult>
+) {
+  const startMark = new Date();
+  const hr = await hrFn();
+  const doneHandlingMark = new Date();
   if (hr.error) {
     await respondWithErrorAndExit(socket, hr.description, hr.error);
   } else {
     await respondToClient(socket, hr.response, hr.description);
   }
+  const endMark = new Date();
+  serverLogger.log(
+    `Handled ${type}. Handling time: ${
+      doneHandlingMark.getTime() - startMark.getTime()
+    }. Response time: ${endMark.getTime() - doneHandlingMark.getTime()}.`
+  );
 }
 
 function handleInactivityTimeout() {
@@ -234,6 +255,7 @@ function nxVersionChanged(): boolean {
 }
 
 const nxPackageJsonPath = require.resolve('nx/package.json');
+
 function getInstalledNxVersion() {
   try {
     const { version } = readJsonFile<PackageJson>(nxPackageJsonPath);

packages/nx/src/project-graph/project-graph.ts

@@ -17,6 +17,7 @@ import { fileExists } from '../utils/fileutils';
 import { workspaceRoot } from '../utils/workspace-root';
 import { Workspaces } from '../config/workspaces';
 import { createProjectFileMap } from './file-map-utils';
+import { performance } from 'perf_hooks';
 
 /**
  * Synchronously reads the latest cached copy of the workspace's ProjectGraph.
@@ -135,9 +136,18 @@ export async function createProjectGraphAsync(
     resetDaemonClient: false,
   }
 ): Promise<ProjectGraph> {
+  performance.mark('create-project-graph-async:start');
+
   if (!daemonClient.enabled()) {
     try {
-      return await buildProjectGraphWithoutDaemon();
+      const res = await buildProjectGraphWithoutDaemon();
+      performance.mark('create-project-graph-async:end');
+      performance.measure(
+        'create-project-graph-async',
+        'create-project-graph-async:start',
+        'create-project-graph-async:end'
+      );
+      return res;
     } catch (e) {
       handleProjectGraphError(opts, e);
     }
@@ -147,6 +157,12 @@ export async function createProjectGraphAsync(
       if (opts.resetDaemonClient) {
         daemonClient.reset();
       }
+      performance.mark('create-project-graph-async:end');
+      performance.measure(
+        'create-project-graph-async',
+        'create-project-graph-async:start',
+        'create-project-graph-async:end'
+      );
       return projectGraph;
     } catch (e) {
       if (e.message.indexOf('inotify_add_watch') > -1) {

packages/nx/src/tasks-runner/default-tasks-runner.ts

@@ -77,16 +77,6 @@ async function runAllTasks(
     daemon: DaemonClient;
   }
 ): Promise<{ [id: string]: TaskStatus }> {
-  // TODO: vsavkin: remove this after Nx 16
-  performance.mark('task-graph-created');
-
-  performance.measure('nx-prep-work', 'init-local', 'task-graph-created');
-  performance.measure(
-    'graph-creation',
-    'command-execution-begins',
-    'task-graph-created'
-  );
-
   const orchestrator = new TaskOrchestrator(
     context.hasher,
     context.initiatingProject,

packages/nx/src/tasks-runner/init-tasks-runner.ts

@@ -20,7 +20,7 @@ export async function initTasksRunner(nxArgs: NxArgs) {
       tasks: Task[];
       parallel: number;
     }): Promise<{ status: number; taskGraph: TaskGraph }> => {
-      performance.mark('command-execution-begins');
+      performance.mark('code-loading:end');
       const lifeCycle = new InvokeRunnerTerminalOutputLifeCycle(opts.tasks);
 
       const taskGraph = {

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

@@ -34,6 +34,7 @@ import { daemonClient } from '../daemon/client/client';
 import { StoreRunInformationLifeCycle } from './life-cycles/store-run-information-life-cycle';
 import { fileHasher } from '../hasher/impl';
 import { getProjectFileMap } from '../project-graph/build-project-graph';
+import { performance } from 'perf_hooks';
 
 async function getTerminalOutputLifeCycle(
   initiatingProject: string,
@@ -250,12 +251,15 @@ export async function invokeTasksRunner({
   // this is used for two reasons: to fetch all remote cache hits AND
   // to submit everything that is known in advance to Nx Cloud to run in
   // a distributed fashion
+  performance.mark('hashing:start');
   await hashTasksThatDoNotDependOnOtherTasks(
     new Workspaces(workspaceRoot),
     hasher,
     projectGraph,
     taskGraph
   );
+  performance.mark('hashing:end');
+  performance.measure('hashing', 'hashing:start', 'hashing:end');
 
   const promiseOrObservable = tasksRunner(
     tasks,

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

@@ -62,7 +62,7 @@ export class TaskOrchestrator {
   async run() {
     // initial scheduling
     await this.tasksSchedule.scheduleNextTasks();
-    performance.mark('task-execution-begins');
+    performance.mark('task-execution:start');
 
     const threads = [];
 
@@ -75,11 +75,11 @@ export class TaskOrchestrator {
     }
     await Promise.all(threads);
 
-    performance.mark('task-execution-ends');
+    performance.mark('task-execution:end');
     performance.measure(
-      'command-execution',
-      'task-execution-begins',
-      'task-execution-ends'
+      'task-execution',
+      'task-execution:start',
+      'task-execution:end'
     );
     this.cache.removeOldCacheRecords();
 

packages/nx/src/tasks-runner/tasks-schedule.ts

@@ -134,7 +134,6 @@ export class TasksSchedule {
       const rootTask = this.notScheduledTaskGraph.tasks[root];
       const executorName = await getExecutorNameForTask(
         rootTask,
-        this.nxJson,
         this.projectGraph
       );
       await this.processTaskForBatches(batchMap, rootTask, executorName, true);
@@ -166,11 +165,7 @@ export class TasksSchedule {
       this.projectGraph,
       this.nxJson
     );
-    const executorName = await getExecutorNameForTask(
-      task,
-      this.nxJson,
-      this.projectGraph
-    );
+    const executorName = await getExecutorNameForTask(task, this.projectGraph);
     if (rootExecutorName !== executorName) {
       return;
     }

packages/nx/src/tasks-runner/utils.ts

@@ -235,21 +235,9 @@ export function interpolate(template: string, data: any): string {
 
 export async function getExecutorNameForTask(
   task: Task,
-  nxJson: NxJsonConfiguration,
   projectGraph: ProjectGraph
 ) {
   const project = projectGraph.nodes[task.target.project].data;
-
-  const projectRoot = join(workspaceRoot, project.root);
-  if (existsSync(join(projectRoot, 'package.json'))) {
-    project.targets = mergeNpmScriptsWithTargets(projectRoot, project.targets);
-  }
-  project.targets = mergePluginTargetsWithNxTargets(
-    project.root,
-    project.targets,
-    await loadNxPlugins(nxJson.plugins)
-  );
-
   return project.targets[task.target.target].executor;
 }
 
@@ -259,7 +247,7 @@ export async function getExecutorForTask(
   projectGraph: ProjectGraph,
   nxJson: NxJsonConfiguration
 ) {
-  const executor = await getExecutorNameForTask(task, nxJson, projectGraph);
+  const executor = await getExecutorNameForTask(task, projectGraph);
   const [nodeModule, executorName] = executor.split(':');
 
   return workspace.readExecutor(nodeModule, executorName);