From eed6a10f3f07c5fe598c948001147193ac515667 Mon Sep 17 00:00:00 2001 From: Dmitry Gozman Date: Wed, 22 May 2024 15:19:32 -0700 Subject: [PATCH] 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. --- .../src/server/trace/recorder/tracing.ts | 97 +----------- .../playwright-core/src/utils/fileUtils.ts | 147 ++++++++++++++++++ packages/playwright/src/worker/testTracing.ts | 16 +- .../playwright-test-fixtures.ts | 7 +- tests/playwright-test/ui-mode-fixtures.ts | 3 +- 5 files changed, 165 insertions(+), 105 deletions(-) diff --git a/packages/playwright-core/src/server/trace/recorder/tracing.ts b/packages/playwright-core/src/server/trace/recorder/tracing.ts index 85c783118d..1dec4f536a 100644 --- a/packages/playwright-core/src/server/trace/recorder/tracing.ts +++ b/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(); // 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(); - (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): 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; - } - }); - } -} diff --git a/packages/playwright-core/src/utils/fileUtils.ts b/packages/playwright-core/src/utils/fileUtils.ts index 0b2f28143b..b7f441aa37 100644 --- a/packages/playwright-core/src/utils/fileUtils.ts +++ b/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(); // Should never be accessed from within appendOperation. + private _error: Error | undefined; + private _operations: SerializedFSOperation[] = []; + private _operationsDone: ManualPromise; + + 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(); + (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; + } + } + } +} diff --git a/packages/playwright/src/worker/testTracing.ts b/packages/playwright/src/worker/testTracing.ts index 87eeca3ebb..97c70d4e19 100644 --- a/packages/playwright/src/worker/testTracing.ts +++ b/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); } } diff --git a/tests/playwright-test/playwright-test-fixtures.ts b/tests/playwright-test/playwright-test-fixtures.ts index f8619dd6fe..62e20d6945 100644 --- a/tests/playwright-test/playwright-test-fixtures.ts +++ b/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 { + return await Promise.all(dirs.map((dir: string) => + fs.promises.rm(dir, { recursive: true, force: true, maxRetries: 10 }).catch(e => e) + )); +} diff --git a/tests/playwright-test/ui-mode-fixtures.ts b/tests/playwright-test/ui-mode-fixtures.ts index fa1ee5c023..2952761d60 100644 --- a/tests/playwright-test/ui-mode-fixtures.ts +++ b/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;