fix(tracing): speed up trace recording (#30946)

This includes two major changes:
- reuse `SerializedFS` for live test runner tracing;
- merge scheduled `appendFile` operations into a single `fs` call.

In some cases, this improves performance of UI mode by 61% and
performance of `trace: on` mode by 38%. Note that performance
improvement on the average test will not be as noticeable.

References #30875, #30635.

packages/playwright-core/src/server/trace/recorder/tracing.ts

@@ -14,18 +14,13 @@
  * limitations under the License.
  */
 
-import type { EventEmitter } from 'events';
 import fs from 'fs';
 import os from 'os';
 import path from 'path';
 import type { NameValue } from '../../../common/types';
 import type { TracingTracingStopChunkParams } from '@protocol/channels';
 import { commandsWithTracingSnapshots } from '../../../protocol/debug';
-import { ManualPromise } from '../../../utils/manualPromise';
-import type { RegisteredListener } from '../../../utils/eventsHelper';
-import { eventsHelper } from '../../../utils/eventsHelper';
-import { assert, createGuid, monotonicTime } from '../../../utils';
-import { removeFolders } from '../../../utils/fileUtils';
+import { assert, createGuid, monotonicTime, SerializedFS, removeFolders, eventsHelper, type RegisteredListener } from '../../../utils';
 import { Artifact } from '../../artifact';
 import { BrowserContext } from '../../browserContext';
 import type { ElementHandle } from '../../dom';
@@ -40,7 +35,6 @@ import type { FrameSnapshot } from '@trace/snapshot';
 import type * as trace from '@trace/trace';
 import type { SnapshotterBlob, SnapshotterDelegate } from './snapshotter';
 import { Snapshotter } from './snapshotter';
-import { yazl } from '../../../zipBundle';
 import type { ConsoleMessage } from '../../console';
 import { Dispatcher } from '../../dispatchers/dispatcher';
 import { serializeError } from '../../errors';
@@ -580,92 +574,3 @@ function createAfterActionTraceEvent(metadata: CallMetadata): trace.AfterActionT
     point: metadata.point,
   };
 }
-
-class SerializedFS {
-  private _writeChain = Promise.resolve();
-  private _buffers = new Map<string, string[]>(); // Should never be accessed from within appendOperation.
-  private _error: Error | undefined;
-
-  mkdir(dir: string) {
-    this._appendOperation(() => fs.promises.mkdir(dir, { recursive: true }));
-  }
-
-  writeFile(file: string, content: string | Buffer, skipIfExists?: boolean) {
-    this._buffers.delete(file); // No need to flush the buffer since we'll overwrite anyway.
-
-    // Note: 'wx' flag only writes when the file does not exist.
-    // See https://nodejs.org/api/fs.html#file-system-flags.
-    // This way tracing never have to write the same resource twice.
-    this._appendOperation(async () => {
-      if (skipIfExists)
-        await fs.promises.writeFile(file, content, { flag: 'wx' }).catch(() => {});
-      else
-        await fs.promises.writeFile(file, content);
-    });
-  }
-
-  appendFile(file: string, text: string, flush?: boolean) {
-    if (!this._buffers.has(file))
-      this._buffers.set(file, []);
-    this._buffers.get(file)!.push(text);
-    if (flush)
-      this._flushFile(file);
-  }
-
-  private _flushFile(file: string) {
-    const buffer = this._buffers.get(file);
-    if (buffer === undefined)
-      return;
-    const text = buffer.join('');
-    this._buffers.delete(file);
-    this._appendOperation(() => fs.promises.appendFile(file, text));
-  }
-
-  copyFile(from: string, to: string) {
-    this._flushFile(from);
-    this._buffers.delete(to); // No need to flush the buffer since we'll overwrite anyway.
-    this._appendOperation(() => fs.promises.copyFile(from, to));
-  }
-
-  async syncAndGetError() {
-    for (const file of this._buffers.keys())
-      this._flushFile(file);
-    await this._writeChain;
-    return this._error;
-  }
-
-  zip(entries: NameValue[], zipFileName: string) {
-    for (const file of this._buffers.keys())
-      this._flushFile(file);
-
-    // Chain the export operation against write operations,
-    // so that files do not change during the export.
-    this._appendOperation(async () => {
-      const zipFile = new yazl.ZipFile();
-      const result = new ManualPromise<void>();
-      (zipFile as any as EventEmitter).on('error', error => result.reject(error));
-      for (const entry of entries)
-        zipFile.addFile(entry.value, entry.name);
-      zipFile.end();
-      zipFile.outputStream
-          .pipe(fs.createWriteStream(zipFileName))
-          .on('close', () => result.resolve())
-          .on('error', error => result.reject(error));
-      await result;
-    });
-  }
-
-  private _appendOperation(cb: () => Promise<unknown>): void {
-    // This method serializes all writes to the trace.
-    this._writeChain = this._writeChain.then(async () => {
-      // Ignore all operations after the first error.
-      if (this._error)
-        return;
-      try {
-        await cb();
-      } catch (e) {
-        this._error = e;
-      }
-    });
-  }
-}

packages/playwright-core/src/utils/fileUtils.ts

@@ -16,6 +16,9 @@
 
 import fs from 'fs';
 import path from 'path';
+import { ManualPromise } from './manualPromise';
+import type { EventEmitter } from 'events';
+import { yazl } from '../zipBundle';
 
 export const fileUploadSizeLimit = 50 * 1024 * 1024;
 
@@ -56,3 +59,147 @@ export function sanitizeForFilePath(s: string) {
 export function toPosixPath(aPath: string): string {
   return aPath.split(path.sep).join(path.posix.sep);
 }
+
+type NameValue = { name: string, value: string };
+type SerializedFSOperation = {
+  op: 'mkdir', dir: string,
+} | {
+  op: 'writeFile', file: string, content: string | Buffer, skipIfExists?: boolean,
+} | {
+  op: 'appendFile', file: string, content: string,
+} | {
+  op: 'copyFile', from: string, to: string,
+} | {
+  op: 'zip', entries: NameValue[], zipFileName: string,
+};
+
+export class SerializedFS {
+  private _buffers = new Map<string, string[]>(); // Should never be accessed from within appendOperation.
+  private _error: Error | undefined;
+  private _operations: SerializedFSOperation[] = [];
+  private _operationsDone: ManualPromise<void>;
+
+  constructor() {
+    this._operationsDone = new ManualPromise();
+    this._operationsDone.resolve();  // No operations scheduled yet.
+  }
+
+  mkdir(dir: string) {
+    this._appendOperation({ op: 'mkdir', dir });
+  }
+
+  writeFile(file: string, content: string | Buffer, skipIfExists?: boolean) {
+    this._buffers.delete(file); // No need to flush the buffer since we'll overwrite anyway.
+    this._appendOperation({ op: 'writeFile', file, content, skipIfExists });
+  }
+
+  appendFile(file: string, text: string, flush?: boolean) {
+    if (!this._buffers.has(file))
+      this._buffers.set(file, []);
+    this._buffers.get(file)!.push(text);
+    if (flush)
+      this._flushFile(file);
+  }
+
+  private _flushFile(file: string) {
+    const buffer = this._buffers.get(file);
+    if (buffer === undefined)
+      return;
+    const content = buffer.join('');
+    this._buffers.delete(file);
+    this._appendOperation({ op: 'appendFile', file, content });
+  }
+
+  copyFile(from: string, to: string) {
+    this._flushFile(from);
+    this._buffers.delete(to); // No need to flush the buffer since we'll overwrite anyway.
+    this._appendOperation({ op: 'copyFile', from, to });
+  }
+
+  async syncAndGetError() {
+    for (const file of this._buffers.keys())
+      this._flushFile(file);
+    await this._operationsDone;
+    return this._error;
+  }
+
+  zip(entries: NameValue[], zipFileName: string) {
+    for (const file of this._buffers.keys())
+      this._flushFile(file);
+
+    // Chain the export operation against write operations,
+    // so that files do not change during the export.
+    this._appendOperation({ op: 'zip', entries, zipFileName });
+  }
+
+  // This method serializes all writes to the trace.
+  private _appendOperation(op: SerializedFSOperation): void {
+    const last = this._operations[this._operations.length - 1];
+    if (last?.op === 'appendFile' && op.op === 'appendFile' && last.file === op.file) {
+      // Merge pending appendFile operations for performance.
+      last.content += op.content;
+      return;
+    }
+
+    this._operations.push(op);
+    if (this._operationsDone.isDone())
+      this._performOperations();
+  }
+
+  private async _performOperations() {
+    this._operationsDone = new ManualPromise();
+    while (this._operations.length) {
+      const op = this._operations.shift()!;
+      // Ignore all operations after the first error.
+      if (this._error)
+        continue;
+      try {
+        await this._performOperation(op);
+      } catch (e) {
+        this._error = e;
+      }
+    }
+    this._operationsDone.resolve();
+  }
+
+  private async _performOperation(op: SerializedFSOperation) {
+    switch (op.op) {
+      case 'mkdir': {
+        await fs.promises.mkdir(op.dir, { recursive: true });
+        return;
+      }
+      case 'writeFile': {
+        // Note: 'wx' flag only writes when the file does not exist.
+        // See https://nodejs.org/api/fs.html#file-system-flags.
+        // This way tracing never have to write the same resource twice.
+        if (op.skipIfExists)
+          await fs.promises.writeFile(op.file, op.content, { flag: 'wx' }).catch(() => {});
+        else
+          await fs.promises.writeFile(op.file, op.content);
+        return;
+      }
+      case 'copyFile': {
+        await fs.promises.copyFile(op.from, op.to);
+        return;
+      }
+      case 'appendFile': {
+        await fs.promises.appendFile(op.file, op.content);
+        return;
+      }
+      case 'zip': {
+        const zipFile = new yazl.ZipFile();
+        const result = new ManualPromise<void>();
+        (zipFile as any as EventEmitter).on('error', error => result.reject(error));
+        for (const entry of op.entries)
+          zipFile.addFile(entry.value, entry.name);
+        zipFile.end();
+        zipFile.outputStream
+            .pipe(fs.createWriteStream(op.zipFileName))
+            .on('close', () => result.resolve())
+            .on('error', error => result.reject(error));
+        await result;
+        return;
+      }
+    }
+  }
+}

packages/playwright/src/worker/testTracing.ts

@@ -19,7 +19,7 @@ import type * as trace from '@trace/trace';
 import type EventEmitter from 'events';
 import fs from 'fs';
 import path from 'path';
-import { ManualPromise, calculateSha1, monotonicTime, createGuid } from 'playwright-core/lib/utils';
+import { ManualPromise, calculateSha1, monotonicTime, createGuid, SerializedFS } from 'playwright-core/lib/utils';
 import { yauzl, yazl } from 'playwright-core/lib/zipBundle';
 import type { TestInfo, TestInfoError } from '../../types/test';
 import { filteredStackTrace } from '../util';
@@ -37,7 +37,7 @@ type TraceOptions = { screenshots: boolean, snapshots: boolean, sources: boolean
 export class TestTracing {
   private _testInfo: TestInfoImpl;
   private _options: TraceOptions | undefined;
-  private _liveTraceFile: string | undefined;
+  private _liveTraceFile: { file: string, fs: SerializedFS } | undefined;
   private _traceEvents: trace.TraceEvent[] = [];
   private _temporaryTraceFiles: string[] = [];
   private _artifactsDir: string;
@@ -103,10 +103,10 @@ export class TestTracing {
 
     if (!this._liveTraceFile && this._options._live) {
       // Note that trace name must start with testId for live tracing to work.
-      this._liveTraceFile = path.join(this._tracesDir, `${this._testInfo.testId}-test.trace`);
-      await fs.promises.mkdir(path.dirname(this._liveTraceFile), { recursive: true });
+      this._liveTraceFile = { file: path.join(this._tracesDir, `${this._testInfo.testId}-test.trace`), fs: new SerializedFS() };
+      this._liveTraceFile.fs.mkdir(path.dirname(this._liveTraceFile.file));
       const data = this._traceEvents.map(e => JSON.stringify(e)).join('\n') + '\n';
-      await fs.promises.writeFile(this._liveTraceFile, data);
+      this._liveTraceFile.fs.writeFile(this._liveTraceFile.file, data);
     }
   }
 
@@ -144,6 +144,10 @@ export class TestTracing {
     if (!this._options)
       return;
 
+    const error = await this._liveTraceFile?.fs.syncAndGetError();
+    if (error)
+      throw error;
+
     const testFailed = this._testInfo.status !== this._testInfo.expectedStatus;
     const shouldAbandonTrace = !testFailed && (this._options.mode === 'retain-on-failure' || this._options.mode === 'retain-on-first-failure');
 
@@ -261,7 +265,7 @@ export class TestTracing {
   private _appendTraceEvent(event: trace.TraceEvent) {
     this._traceEvents.push(event);
     if (this._liveTraceFile)
-      fs.appendFileSync(this._liveTraceFile, JSON.stringify(event) + '\n');
+      this._liveTraceFile.fs.appendFile(this._liveTraceFile.file, JSON.stringify(event) + '\n', true);
   }
 }
 

tests/playwright-test/playwright-test-fixtures.ts

@@ -19,7 +19,6 @@ import * as fs from 'fs';
 import * as os from 'os';
 import * as path from 'path';
 import { PNG } from 'playwright-core/lib/utilsBundle';
-import { removeFolders } from '../../packages/playwright-core/src/utils/fileUtils';
 import type { CommonFixtures, CommonWorkerFixtures, TestChildProcess } from '../config/commonFixtures';
 import { commonFixtures } from '../config/commonFixtures';
 import type { ServerFixtures, ServerWorkerOptions } from '../config/serverFixtures';
@@ -457,3 +456,9 @@ export default defineConfig({
   projects: [{name: 'default'}],
 });
 `;
+
+export async function removeFolders(dirs: string[]): Promise<Error[]> {
+  return await Promise.all(dirs.map((dir: string) =>
+    fs.promises.rm(dir, { recursive: true, force: true, maxRetries: 10 }).catch(e => e)
+  ));
+}

tests/playwright-test/ui-mode-fixtures.ts

@@ -18,11 +18,10 @@ import * as fs from 'fs';
 import * as os from 'os';
 import * as path from 'path';
 import type { TestChildProcess } from '../config/commonFixtures';
-import { cleanEnv, cliEntrypoint, test as base, writeFiles } from './playwright-test-fixtures';
+import { cleanEnv, cliEntrypoint, test as base, writeFiles, removeFolders } from './playwright-test-fixtures';
 import type { Files, RunOptions } from './playwright-test-fixtures';
 import type { Browser, BrowserType, Page, TestInfo } from './stable-test-runner';
 import { createGuid } from '../../packages/playwright-core/src/utils/crypto';
-import { removeFolders } from '../../packages/playwright-core/src/utils/fileUtils';
 
 type Latch = {
   blockingCode: string;