[v2] adds the --profile flag support (#324)

* adding commander to replace yargs

* logging and verbosity

* make sure the error case exits with an exit code of 1

* fixed README.md

* pass the internalCacheFolder into the config

* Change files

* fixing formating

* updates the snapshots

* most e2e passed, except for transitiveDepsTests

* fixed up the transitive task deps - by adding back the default behavior of v1.x --include-dependencies

* formatting

* move e2e tests to a new package

* fixing up mocking after moving e2e tests

* Change files

* having a go at chrome trace event reporter

* profiler reporter

* adding a profiler

* added tests

* removed change files

* Change files

* filling out the correct "ts" time start for ChromeTraceEvents

* fix formatting

* don't show paths

.gitignore

@@ -7,4 +7,5 @@ lib
 *.pdf
 coverage
 .idea/
-**/.docusaurus/
+**/.docusaurus/
+profile*.json

change/@lage-run-cli-980d9c45-2508-40fe-927b-f20faf43ea98.json

@@ -0,0 +1,7 @@
+{
+  "type": "patch",
+  "comment": "Adds the --profile flag",
+  "packageName": "@lage-run/cli",
+  "email": "kchau@microsoft.com",
+  "dependentChangeType": "patch"
+}

change/@lage-run-reporters-669bcc9b-4f47-4758-9555-ae941b884187.json

@@ -0,0 +1,7 @@
+{
+  "type": "patch",
+  "comment": "Adds the ChromeTraceEventReporters that is used in --profile",
+  "packageName": "@lage-run/reporters",
+  "email": "kchau@microsoft.com",
+  "dependentChangeType": "patch"
+}

change/@lage-run-scheduler-88417326-6ecc-43e0-93e6-b4c71a564270.json

@@ -0,0 +1,7 @@
+{
+  "type": "patch",
+  "comment": "removed the rename of TargetRun",
+  "packageName": "@lage-run/scheduler",
+  "email": "kchau@microsoft.com",
+  "dependentChangeType": "patch"
+}

packages/cli/src/commands/run/createProfileReporter.ts

@@ -0,0 +1,9 @@
+import { ChromeTraceEventsReporter } from "@lage-run/reporters";
+
+export function createProfileReporter(options: { concurrency: number; profile: string | boolean | undefined }) {
+  const { concurrency, profile } = options;
+  return new ChromeTraceEventsReporter({
+    concurrency: concurrency,
+    outputFile: typeof profile === "string" ? profile : undefined,
+  });
+}

packages/cli/src/commands/run/index.ts

@@ -34,7 +34,10 @@ runCommand
   .option("--skip-local-cache", "skips caching locally")
 
   .option("--profile [profile]", "writes a run profile into a file that can be processed by Chromium devtool")
-  .option("--nodearg <nodeArg...>", "arguments to be passed to node (e.g. --nodearg=--max_old_space_size=1234 --nodearg=--heap-prof")
+  .option(
+    "--nodearg <nodeArg>",
+    'arguments to be passed to node (e.g. --nodearg="--max_old_space_size=1234 --heap-prof" - set via "NODE_OPTIONS" environment variable'
+  )
   .option("--continue", "continues the run even on error")
 
   .allowUnknownOption(true)

packages/cli/src/commands/run/runAction.ts

@@ -1,10 +1,11 @@
 import { BackfillCacheProvider, RemoteFallbackCacheProvider, TargetHasher } from "@lage-run/cache";
 import { Command } from "commander";
+import { createProfileReporter } from "./createProfileReporter";
+import { createReporter } from "../../createReporter";
 import { findNpmClient } from "../../workspace/findNpmClient";
 import { getConfig } from "../../config/getConfig";
 import { getFilteredPackages } from "../../filter/getFilteredPackages";
 import { getPackageInfos, getWorkspaceRoot } from "workspace-tools";
-import { createReporter } from "../../createReporter";
 import { NpmScriptRunner, SimpleScheduler } from "@lage-run/scheduler";
 import { TargetGraphBuilder } from "@lage-run/target-graph";
 import createLogger, { LogLevel, Reporter } from "@lage-run/logger";
@@ -17,7 +18,25 @@ function filterArgsForTasks(args: string[]) {
   };
 }
 
-export async function runAction(options: Record<string, any>, command: Command) {
+interface RunOptions {
+  reporter: string[];
+  concurrency: number;
+  profile: string | boolean | undefined;
+  verbose: boolean;
+  logLevel: keyof typeof LogLevel;
+  grouped: boolean;
+  dependencies: boolean;
+  dependents: boolean;
+  since: string;
+  scope: string[];
+  skipLocalCache: boolean;
+  continue: boolean;
+  cache: boolean;
+  resetCache: boolean;
+  nodeargs: string;
+}
+
+export async function runAction(options: RunOptions, command: Command) {
   const cwd = process.cwd();
   const config = getConfig(cwd);
   const reporterInstances: Reporter[] = [];
@@ -38,6 +57,12 @@ export async function runAction(options: Record<string, any>, command: Command)
     logger.addReporter(reporterInstance);
   }
 
+  if (options.profile !== undefined) {
+    const reporter = createProfileReporter(options);
+    reporterInstances.push(reporter);
+    logger.addReporter(reporter);
+  }
+
   // Build Target Graph
   const root = getWorkspaceRoot(process.cwd())!;
   const packageInfos = getPackageInfos(root);
@@ -83,7 +108,7 @@ export async function runAction(options: Record<string, any>, command: Command)
             root,
             cacheOptions: {
               outputGlob: config.cacheOptions.outputGlob,
-              internalCacheFolder: config.cacheOptions.internalCacheFolder,
+              ...(config.cacheOptions.internalCacheFolder && { internalCacheFolder: config.cacheOptions.internalCacheFolder }),
             },
           }),
     remoteCacheProvider: config.cacheOptions?.cacheStorageConfig

packages/reporters/src/ChromeTraceEventsReporter.ts

@@ -0,0 +1,123 @@
+import { getStartTargetId } from "@lage-run/target-graph";
+import { isTargetStatusLogEntry } from "./isTargetStatusLogEntry";
+import chalk from "chalk";
+import fs from "fs";
+import path from "path";
+import type { LogEntry, Reporter } from "@lage-run/logger";
+import type { SchedulerRunSummary, TargetRun } from "@lage-run/scheduler";
+import type { TargetMessageEntry, TargetStatusEntry } from "./types/TargetLogEntry";
+import { Writable } from "stream";
+
+interface TraceEventsObject {
+  traceEvents: CompleteEvent[];
+  displayTimeUnit: "ms" | "ns";
+}
+
+interface CompleteEvent {
+  name: string;
+  cat: string;
+  ph: "X";
+  ts: number; // in microseconds
+  pid: number;
+  tid: number;
+  dur: number;
+  args?: Record<string, any>;
+}
+
+export interface ChromeTraceEventsReporterOptions {
+  outputFile?: string;
+  concurrency: number;
+  categorize?: (targetRun?: TargetRun) => string;
+}
+
+function range(len: number) {
+  return Array(len)
+    .fill(0)
+    .map((_, idx) => idx + 1);
+}
+
+function hrTimeToMicroseconds(hr: [number, number]) {
+  return hr[0] * 1e6 + hr[1] * 1e-3;
+}
+
+function getTimeBasedFilename(prefix: string) {
+  const now = new Date(); // 2011-10-05T14:48:00.000Z
+  const datetime = now.toISOString().split(".")[0]; // 2011-10-05T14:48:00
+  const datetimeNormalized = datetime.replace(/-|:/g, ""); // 20111005T144800
+  return `${prefix ? prefix + "-" : ""}${datetimeNormalized}.json`;
+}
+
+export class ChromeTraceEventsReporter implements Reporter {
+  logStream: Writable;
+  consoleLogStream: Writable = process.stdout;
+
+  private threads: number[];
+  private targetIdThreadMap: Map<string, number> = new Map();
+  private events: TraceEventsObject = {
+    traceEvents: [],
+    displayTimeUnit: "ms",
+  };
+  private outputFile: string;
+
+  constructor(private options: ChromeTraceEventsReporterOptions) {
+    this.outputFile = options.outputFile ?? getTimeBasedFilename("profile");
+    this.threads = range(options.concurrency);
+
+    if (!fs.existsSync(path.dirname(this.outputFile))) {
+      fs.mkdirSync(path.dirname(this.outputFile), { recursive: true });
+    }
+
+    this.logStream = fs.createWriteStream(this.outputFile, { flags: "w" });
+  }
+
+  log(entry: LogEntry<TargetStatusEntry | TargetMessageEntry>) {
+    const data = entry.data;
+    if (isTargetStatusLogEntry(data) && data.status !== "pending" && data.target.id !== getStartTargetId()) {
+      if (data.status === "running") {
+        const threadId = this.threads.shift() ?? 0;
+        this.targetIdThreadMap.set(data.target.id, threadId);
+      } else {
+        const threadId = this.targetIdThreadMap.get(data.target.id)!;
+
+        this.events.traceEvents.push({
+          name: data.target.id,
+          cat: "", // to be filled in later in the "summary" step
+          ph: "X",
+          ts: 0, // to be filled in later in the "summary" step
+          dur: hrTimeToMicroseconds(data.duration ?? [0, 1000]), // in microseconds
+          pid: 1,
+          tid: threadId ?? 0,
+        });
+
+        this.threads.unshift(threadId);
+        this.threads.sort((a, b) => a - b);
+      }
+    }
+  }
+
+  summarize(schedulerRunSummary: SchedulerRunSummary) {
+    const { targetRuns, startTime } = schedulerRunSummary;
+
+    // categorize events
+    const { categorize } = this.options;
+
+    for (const event of this.events.traceEvents) {
+      const targetRun = targetRuns.get(event.name);
+
+      event.ts = hrTimeToMicroseconds(targetRun?.startTime!) - hrTimeToMicroseconds(startTime!);
+      event.cat = targetRun?.status ?? "";
+      if (categorize) {
+        event.cat += `,${categorize(targetRun)}`;
+      }
+    }
+
+    // write events to stream
+    this.logStream.write(JSON.stringify(this.events, null, 2));
+
+    this.consoleLogStream.write(
+      chalk.blueBright(
+        `\nProfiler output written to ${chalk.underline(this.outputFile)}, open it with chrome://tracing or edge://tracing\n`
+      )
+    );
+  }
+}

packages/reporters/src/index.ts

@@ -1,5 +1,6 @@
 export { AdoReporter } from "./AdoReporter";
 export { JsonReporter } from "./JsonReporter";
 export { NpmLogReporter } from "./NpmLogReporter";
+export { ChromeTraceEventsReporter } from "./ChromeTraceEventsReporter";
 
 export type { TargetStatusEntry, TargetMessageEntry } from "./types/TargetLogEntry";

packages/reporters/tests/ChromeTraceEventsReporter.test.ts

@@ -0,0 +1,119 @@
+// For this test, we need have a force color set before any imports
+process.env.FORCE_COLOR = "0";
+
+import { LogLevel } from "@lage-run/logger";
+import { ChromeTraceEventsReporter } from "../src/ChromeTraceEventsReporter";
+import streams from "memory-streams";
+import type { TargetMessageEntry, TargetStatusEntry } from "../src/types/TargetLogEntry";
+
+function createTarget(packageName: string, task: string) {
+  return {
+    id: `${packageName}#${task}`,
+    cwd: `/repo/root/packages/${packageName}`,
+    dependencies: [],
+    packageName,
+    task,
+    label: `${packageName} - ${task}`,
+  };
+}
+
+describe("ChromeTraceEventsReporter", () => {
+  it("can group verbose messages, displaying summary", () => {
+    const writer = new streams.WritableStream();
+    const consoleWriter = new streams.WritableStream();
+
+    const reporter = new ChromeTraceEventsReporter({ concurrency: 4, outputFile: "profile.json" });
+    reporter.logStream = writer;
+    reporter.consoleLogStream = consoleWriter;
+
+    const aBuildTarget = createTarget("a", "build");
+    const aTestTarget = createTarget("a", "test");
+    const bBuildTarget = createTarget("b", "build");
+
+    const logs = [
+      [{ target: aBuildTarget, status: "running", duration: [0, 0], startTime: [0, 0] }],
+      [{ target: aTestTarget, status: "running", duration: [0, 0], startTime: [1, 0] }],
+      [{ target: bBuildTarget, status: "running", duration: [0, 0], startTime: [2, 0] }],
+      [{ target: aBuildTarget, pid: 1 }, "test message for a#build"],
+      [{ target: aTestTarget, pid: 1 }, "test message for a#test"],
+      [{ target: aBuildTarget, pid: 1 }, "test message for a#build again, but look there is an error!"],
+      [{ target: bBuildTarget, pid: 1 }, "test message for b#build"],
+      [{ target: aTestTarget, pid: 1 }, "test message for a#test again"],
+      [{ target: bBuildTarget, pid: 1 }, "test message for b#build again"],
+      [{ target: aTestTarget, status: "success", duration: [10, 0], startTime: [0, 0] }],
+      [{ target: bBuildTarget, status: "success", duration: [30, 0], startTime: [2, 0] }],
+      [{ target: aBuildTarget, status: "failed", duration: [60, 0], startTime: [1, 0] }],
+    ] as [TargetStatusEntry | TargetMessageEntry, string?][];
+
+    for (const log of logs) {
+      reporter.log({
+        data: log[0],
+        level: "status" in log[0] ? LogLevel.info : LogLevel.verbose,
+        msg: log[1] ?? "",
+        timestamp: 0,
+      });
+    }
+
+    reporter.summarize({
+      duration: [100, 0],
+      startTime: [0, 0],
+      results: "failed",
+      targetRunByStatus: {
+        success: [aTestTarget.id, bBuildTarget.id],
+        failed: [aBuildTarget.id],
+        pending: [],
+        running: [],
+        aborted: [],
+        skipped: [],
+      },
+      targetRuns: new Map([
+        [aBuildTarget.id, { target: aBuildTarget, status: "failed", duration: [60, 0], startTime: [0, 0] }],
+        [aTestTarget.id, { target: aTestTarget, status: "success", duration: [10, 0], startTime: [1, 0] }],
+        [bBuildTarget.id, { target: bBuildTarget, status: "success", duration: [30, 0], startTime: [2, 0] }],
+      ]),
+    });
+
+    writer.end();
+    consoleWriter.end();
+
+    expect(writer.toString()).toMatchInlineSnapshot(`
+      "{
+        \\"traceEvents\\": [
+          {
+            \\"name\\": \\"a#test\\",
+            \\"cat\\": \\"success\\",
+            \\"ph\\": \\"X\\",
+            \\"ts\\": 1000000,
+            \\"dur\\": 10000000,
+            \\"pid\\": 1,
+            \\"tid\\": 2
+          },
+          {
+            \\"name\\": \\"b#build\\",
+            \\"cat\\": \\"success\\",
+            \\"ph\\": \\"X\\",
+            \\"ts\\": 2000000,
+            \\"dur\\": 30000000,
+            \\"pid\\": 1,
+            \\"tid\\": 3
+          },
+          {
+            \\"name\\": \\"a#build\\",
+            \\"cat\\": \\"failed\\",
+            \\"ph\\": \\"X\\",
+            \\"ts\\": 0,
+            \\"dur\\": 60000000,
+            \\"pid\\": 1,
+            \\"tid\\": 1
+          }
+        ],
+        \\"displayTimeUnit\\": \\"ms\\"
+      }"
+    `);
+    expect(consoleWriter.toString()).toMatchInlineSnapshot(`
+      "
+      Profiler output written to profile.json, open it with chrome://tracing or edge://tracing
+      "
+    `);
+  });
+});

packages/scheduler/src/index.ts

@@ -2,7 +2,7 @@ export { SimpleScheduler } from "./SimpleScheduler";
 export { NpmScriptRunner } from "./runners/NpmScriptRunner";
 
 export type { TargetStatus } from "./types/TargetStatus";
-export type { TargetRun as TargetRunContext } from "./types/TargetRun";
+export type { TargetRun } from "./types/TargetRun";
 export type { TargetRunner } from "./types/TargetRunner";
 export type { TargetScheduler } from "./types/TargetScheduler";
 export type { SchedulerRunSummary, SchedulerRunResults } from "./types/SchedulerRunSummary";