Update benchmark test (#357)

* tweaking params

* better io handling

* reverting debug param change

* updating updating git ignore

* turn tests in blocking tests

* removing `finished` console output

.gitignore

@@ -334,5 +334,5 @@ test-results.xml
 tsconfig.tsbuildinfo
 *.tgz
 
-# Files created by `npm run resourceTest'.
-src/test/resourceTest/benchmarkResources/logs/*.perf
+# Files created by `npm run test:benchmark'.
+src/test/resourceTest/benchmark/logs/*

src/powerquery-parser/common/trace.ts

@@ -52,6 +52,8 @@ export const enum TraceConstant {
 }
 
 export class Trace {
+    public readonly timeCreated: number = performanceNow();
+
     constructor(
         protected readonly emitter: (trace: Trace, message: string, details?: object) => void,
         public readonly phase: string,
@@ -126,9 +128,15 @@ export abstract class TraceManager {
         const detailsJson: string = details !== undefined ? this.safeJsonStringify(details) : TraceConstant.Empty;
 
         return (
-            [trace.phase, trace.task, trace.id, trace.correlationId, performanceNow(), message, detailsJson].join(
-                this.valueDelimiter,
-            ) + this.newline
+            [
+                trace.phase,
+                trace.task,
+                trace.id,
+                trace.correlationId,
+                performanceNow() - trace.timeCreated,
+                message,
+                detailsJson,
+            ].join(this.valueDelimiter) + this.newline
         );
     }
 

src/test/resourceTest/benchmark/createBenchmarks.ts

@@ -1,50 +1,84 @@
 // Copyright (c) Microsoft Corporation.
 // Licensed under the MIT license.
 
+// tslint:disable-next-line: no-require-imports
+import performanceNow = require("performance-now");
+
 import * as fs from "fs";
 import * as path from "path";
 
 import { DefaultSettings, Settings } from "../../..";
 import { BenchmarkTraceManager } from "../../../powerquery-parser/common/trace";
 import { TestFileUtils } from "../../testUtils";
 
-const NumberOfRunsPerFile: number = 10;
+const NumberOfRunsPerFile: number = 25;
 const ResourceDirectory: string = path.dirname(__filename);
 const SourceFilesDirectory: string = path.join(ResourceDirectory, "sourceFiles");
 const OutputDirectory: string = path.join(ResourceDirectory, "logs");
 
-function createOutputStream(filePath: string, iteration: number): fs.WriteStream {
-    const iterationFilePath: string = path.join(
-        OutputDirectory,
-        `${path.parse(filePath).name}_example_${iteration}.log`,
-    );
+function createOutputStream(filename: string): fs.WriteStream {
+    const filePath: string = path.join(OutputDirectory, filename);
+    createOutputDirectoryIfNeeded();
+
+    return fs.createWriteStream(filePath, { flags: "w" });
+}
 
+function createIterationOutputStream(filePath: string, iteration: number): fs.WriteStream {
+    return createOutputStream(`${path.parse(filePath).name}_example_${iteration}.log`);
+}
+
+function createOutputDirectoryIfNeeded(): void {
     // tslint:disable-next-line: non-literal-fs-path
     if (!fs.existsSync(OutputDirectory)) {
         // tslint:disable-next-line: non-literal-fs-path
         fs.mkdirSync(OutputDirectory, { recursive: true });
     }
+}
+
+async function runTest(filePath: string, iteration: number): Promise<string> {
+    console.log(`Starting iteration ${iteration + 1} out of ${NumberOfRunsPerFile} for ${path.basename(filePath)}`);
 
-    return fs.createWriteStream(iterationFilePath, { flags: "w" });
+    let contents: string = "";
+
+    const benchmarkSettings: Settings = {
+        ...DefaultSettings,
+        traceManager: new BenchmarkTraceManager((message: string) => (contents = contents + message)),
+    };
+
+    await TestFileUtils.tryLexParse(benchmarkSettings, filePath);
+
+    return contents;
 }
 
-for (const filePath of TestFileUtils.getPowerQueryFilesRecursively(SourceFilesDirectory)) {
-    for (let iteration: number = 0; iteration < NumberOfRunsPerFile; iteration += 1) {
-        const stream: fs.WriteStream = createOutputStream(filePath, iteration);
+async function main(): Promise<void> {
+    for (const filePath of TestFileUtils.getPowerQueryFilesRecursively(SourceFilesDirectory)) {
+        const fileStart: number = performanceNow();
+
+        for (let iteration: number = 0; iteration < NumberOfRunsPerFile; iteration += 1) {
+            // eslint-disable-next-line no-await-in-loop
+            const contents: string = await runTest(filePath, iteration);
 
-        stream.on("open", async () => {
-            if (iteration % 10 === 0 || iteration === NumberOfRunsPerFile - 1) {
-                console.log(
-                    `Running iteration ${iteration + 1} out of ${NumberOfRunsPerFile} for ${path.basename(filePath)}`,
-                );
-            }
+            const iterationStream: fs.WriteStream = createIterationOutputStream(filePath, iteration);
 
-            const benchmarkSettings: Settings = {
-                ...DefaultSettings,
-                traceManager: new BenchmarkTraceManager((message: string) => stream.write(message)),
-            };
+            iterationStream.on("open", () => {
+                iterationStream.write(contents);
+            });
+        }
 
-            await TestFileUtils.tryLexParse(benchmarkSettings, filePath);
+        const fileEnd: number = performanceNow();
+        const fileDuration: number = fileEnd - fileStart;
+        const fileAverage: number = fileDuration / NumberOfRunsPerFile;
+
+        const summaryStream: fs.WriteStream = createOutputStream(`${path.basename(filePath)}.summary`);
+
+        summaryStream.on("open", () => {
+            summaryStream.write(`Total time: ${fileDuration}ms\nAverage time: ${fileAverage}ms\n`);
+            summaryStream.close();
         });
     }
 }
+
+// eslint-disable-next-line @typescript-eslint/no-floating-promises
+(async (): Promise<void> => {
+    void (await main());
+})();