feat(core): add perf logging

Author: vsavkin

Diff for: packages/cli/lib/init-local.ts

@@ -10,6 +10,7 @@ import { parseRunOneOptions } from './parse-run-one-options';
  */
 process.env.NX_CLI_SET = 'true';
 export function initLocal(workspace: Workspace) {
+  require('@nrwl/workspace/' + 'src/utils/perf-logging');
   const supportedNxCommands = require('@nrwl/workspace/' +
     'src/command-line/supported-nx-commands').supportedNxCommands;
   const runOpts = runOneOptions(workspace);

Diff for: packages/workspace/src/core/file-utils.ts

@@ -11,6 +11,7 @@ import { jsonDiff } from '../utils/json-diff';
 import { ProjectGraphNode } from './project-graph';
 import { Environment, NxJson } from './shared-interfaces';
 import { defaultFileHasher } from './hasher/file-hasher';
+import { performance } from 'perf_hooks';
 
 const ignore = require('ignore');
 
@@ -206,11 +207,19 @@ export function rootWorkspaceFileData(): FileData[] {
 
 export function readWorkspaceFiles(): FileData[] {
   const workspaceJson = readWorkspaceJson();
+  performance.mark('read workspace files:start');
 
   if (defaultFileHasher.usesGitForHashing) {
-    return defaultFileHasher
+    const r = defaultFileHasher
       .allFiles()
       .map((f) => getFileData(`${appRootPath}/${f}`));
+    performance.mark('read workspace files:end');
+    performance.measure(
+      'read workspace files',
+      'read workspace files:start',
+      'read workspace files:end'
+    );
+    return r;
   } else {
     const files = [];
     files.push(...rootWorkspaceFileData());
@@ -224,7 +233,12 @@ export function readWorkspaceFiles(): FileData[] {
       const project = workspaceJson.projects[projectName];
       files.push(...allFilesInDir(`${appRootPath}/${project.root}`));
     });
-
+    performance.mark('read workspace files:end');
+    performance.measure(
+      'read workspace files',
+      'read workspace files:start',
+      'read workspace files:end'
+    );
     return files;
   }
 }

Diff for: packages/workspace/src/core/hasher/file-hasher.ts

@@ -2,6 +2,7 @@ import { getFileHashes } from './git-hasher';
 import { readFileSync } from 'fs';
 import { defaultHashing, HashingImp } from './hashing-impl';
 import { appRootPath } from '../../utils/app-root';
+import { performance } from 'perf_hooks';
 
 type PathAndTransformer = {
   path: string;
@@ -26,9 +27,16 @@ export class FileHasher {
   }
 
   init() {
+    performance.mark('init hashing:start');
     this.fileHashes = {};
     this.getHashesFromGit();
     this.usesGitForHashing = Object.keys(this.fileHashes).length > 0;
+    performance.mark('init hashing:end');
+    performance.measure(
+      'init hashing',
+      'init hashing:start',
+      'init hashing:end'
+    );
   }
 
   hashFile(path: string, transformer: (x: string) => string | null = null) {

Diff for: packages/workspace/src/core/nx-deps/nx-deps-cache.ts

@@ -15,6 +15,7 @@ import {
   writeJsonFile,
 } from '../../utils/fileutils';
 import { FileMap } from '@nrwl/workspace/src/core/file-graph';
+import { performance } from 'perf_hooks';
 
 export interface ProjectGraphCache {
   version: string;
@@ -26,6 +27,7 @@ export interface ProjectGraphCache {
 const nxDepsDir = join(appRootPath, 'node_modules', '.cache', 'nx');
 const nxDepsPath = join(nxDepsDir, 'nxdeps.json');
 export function readCache(): false | ProjectGraphCache {
+  performance.mark('read cache:start');
   try {
     if (!existsSync(nxDepsDir)) {
       fsExtra.ensureDirSync(nxDepsDir);
@@ -47,19 +49,25 @@ export function readCache(): false | ProjectGraphCache {
   }
 
   const data = fileExists(nxDepsPath) ? readJsonFile(nxDepsPath) : null;
+
+  performance.mark('read cache:end');
+  performance.measure('read cache', 'read cache:start', 'read cache:end');
   return data ? data : false;
 }
 
 export function writeCache(
   rootFiles: FileData[],
   projectGraph: ProjectGraph
 ): void {
+  performance.mark('write cache:start');
   writeJsonFile(nxDepsPath, {
     version: '2.0',
     rootFiles,
     nodes: projectGraph.nodes,
     dependencies: projectGraph.dependencies,
   });
+  performance.mark('write cache:end');
+  performance.measure('write cache', 'write cache:start', 'write cache:end');
 }
 
 export function differentFromCache(

Diff for: packages/workspace/src/core/project-graph/project-graph.ts

@@ -29,6 +29,7 @@ import {
   writeCache,
 } from '../nx-deps/nx-deps-cache';
 import { NxJson } from '../shared-interfaces';
+import { performance } from 'perf_hooks';
 
 export function createProjectGraph(
   workspaceJson = readWorkspaceJson(),
@@ -83,6 +84,7 @@ function buildProjectGraph(
   fileRead: (s: string) => string,
   projectGraph: ProjectGraph
 ) {
+  performance.mark('build project graph:start');
   const builder = new ProjectGraphBuilder(projectGraph);
   const buildNodesFns: BuildNodes[] = [
     buildWorkspaceProjectNodes,
@@ -97,5 +99,12 @@ function buildProjectGraph(
   buildDependenciesFns.forEach((f) =>
     f(ctx, builder.nodes, builder.addDependency.bind(builder), fileRead)
   );
-  return builder.build();
+  const r = builder.build();
+  performance.mark('build project graph:end');
+  performance.measure(
+    'build project graph',
+    'build project graph:start',
+    'build project graph:end'
+  );
+  return r;
 }

Diff for: packages/workspace/src/utils/perf-logging.ts

@@ -0,0 +1,9 @@
+import { PerformanceObserver } from 'perf_hooks';
+
+if (process.env.NX_PERF_LOGGING) {
+  const obs = new PerformanceObserver((list) => {
+    const entry = list.getEntries()[0];
+    console.log(`Time for '${entry.name}'`, entry.duration);
+  });
+  obs.observe({ entryTypes: ['measure'], buffered: false });
+}