From a50cd305195dbfa05a9dbb60e8d8edad6889d94a Mon Sep 17 00:00:00 2001 From: Yury Semikhatsky Date: Thu, 9 May 2024 15:31:23 -0700 Subject: [PATCH] chore: use monotonic time for sorting (#30735) * Use only monotonicTime for sorting, do not use wallTime for that * Since test runner and the library can be running on different machines, those machines may have clocks which are not synchronized. To avoid problems in such cases we compute delta between test runner and and library contexts based on a start time of action that exists in both contexts. --- packages/trace-viewer/src/ui/modelUtil.ts | 75 +++++++++++++++-------- tests/library/trace-viewer.spec.ts | 4 +- 2 files changed, 51 insertions(+), 28 deletions(-) diff --git a/packages/trace-viewer/src/ui/modelUtil.ts b/packages/trace-viewer/src/ui/modelUtil.ts index 7c9e6e1237ff6..19fff2784a7b0 100644 --- a/packages/trace-viewer/src/ui/modelUtil.ts +++ b/packages/trace-viewer/src/ui/modelUtil.ts @@ -189,7 +189,7 @@ function mergeActionsAndUpdateTiming(contexts: ContextEntry[]) { return -1; if (a1.parentId === a2.callId) return 1; - return a1.wallTime - a2.wallTime || a1.startTime - a2.startTime; + return a1.startTime - a2.startTime; }); for (let i = 1; i < result.length; ++i) @@ -212,38 +212,28 @@ function makeCallIdsUniqueAcrossTraceFiles(contexts: ContextEntry[], traceFileId function mergeActionsAndUpdateTimingSameTrace(contexts: ContextEntry[]) { const map = new Map(); - // Protocol call aka isPrimary contexts have startTime/endTime as server-side times. - // Step aka non-isPrimary contexts have startTime/endTime are client-side times. - // Adjust expect startTime/endTime on non-primary contexts to put them on a single timeline. - let offset = 0; const primaryContexts = contexts.filter(context => context.isPrimary); const nonPrimaryContexts = contexts.filter(context => !context.isPrimary); for (const context of primaryContexts) { for (const action of context.actions) map.set(`${action.apiName}@${action.wallTime}`, { ...action, context }); - if (!offset && context.actions.length) - offset = context.actions[0].startTime - context.actions[0].wallTime; } + // Protocol call aka isPrimary contexts have startTime/endTime as server-side times. + // Step aka non-isPrimary contexts have startTime/endTime are client-side times. + // Adjust startTime/endTime on the primary contexts to align them with the test + // runner steps. + const delta = monotonicTimeDeltaBetweenLibraryAndRunner(nonPrimaryContexts, map); + if (delta) + adjustMonotonicTime(primaryContexts, delta); + const nonPrimaryIdToPrimaryId = new Map(); - const nonPrimaryTimeDelta = new Map(); for (const context of nonPrimaryContexts) { for (const action of context.actions) { - if (offset) { - const duration = action.endTime - action.startTime; - if (action.startTime) { - const newStartTime = action.wallTime + offset; - nonPrimaryTimeDelta.set(context, newStartTime - action.startTime); - action.startTime = newStartTime; - } - if (action.endTime) - action.endTime = action.startTime + duration; - } - const key = `${action.apiName}@${action.wallTime}`; const existing = map.get(key); - if (existing && existing.apiName === action.apiName) { + if (existing) { nonPrimaryIdToPrimaryId.set(action.callId, existing.callId); if (action.error) existing.error = action.error; @@ -251,6 +241,10 @@ function mergeActionsAndUpdateTimingSameTrace(contexts: ContextEntry[]) { existing.attachments = action.attachments; if (action.parentId) existing.parentId = nonPrimaryIdToPrimaryId.get(action.parentId) ?? action.parentId; + // For the events that are present in the test runner context, always take + // their time from the test runner context to preserve client side order. + existing.startTime = action.startTime; + existing.endTime = action.endTime; continue; } if (action.parentId) @@ -258,18 +252,47 @@ function mergeActionsAndUpdateTimingSameTrace(contexts: ContextEntry[]) { map.set(key, { ...action, context }); } } + return map; +} - for (const [context, timeDelta] of nonPrimaryTimeDelta) { - context.startTime += timeDelta; - context.endTime += timeDelta; +function adjustMonotonicTime(contexts: ContextEntry[], monotonicTimeDelta: number) { + for (const context of contexts) { + context.startTime += monotonicTimeDelta; + context.endTime += monotonicTimeDelta; + for (const action of context.actions) { + if (action.startTime) + action.startTime += monotonicTimeDelta; + if (action.endTime) + action.endTime += monotonicTimeDelta; + } for (const event of context.events) - event.time += timeDelta; + event.time += monotonicTimeDelta; + for (const event of context.stdio) + event.timestamp += monotonicTimeDelta; for (const page of context.pages) { for (const frame of page.screencastFrames) - frame.timestamp += timeDelta; + frame.timestamp += monotonicTimeDelta; } } - return map; +} + +function monotonicTimeDeltaBetweenLibraryAndRunner(nonPrimaryContexts: ContextEntry[], libraryActions: Map) { + // We cannot rely on wall time or monotonic time to be the in sync + // between library and test runner contexts. So we find first action + // that is present in both runner and library contexts and use it + // to calculate the time delta, assuming the two events happened at the + // same instant. + for (const context of nonPrimaryContexts) { + for (const action of context.actions) { + if (!action.startTime) + continue; + const key = `${action.apiName}@${action.wallTime}`; + const libraryAction = libraryActions.get(key); + if (libraryAction) + return action.startTime - libraryAction.startTime; + } + } + return 0; } export function buildActionTree(actions: ActionTraceEventInContext[]): { rootItem: ActionTreeItem, itemMap: Map } { diff --git a/tests/library/trace-viewer.spec.ts b/tests/library/trace-viewer.spec.ts index 7bba694177d8c..4a6acb5e85dc5 100644 --- a/tests/library/trace-viewer.spec.ts +++ b/tests/library/trace-viewer.spec.ts @@ -809,11 +809,11 @@ test('should open two trace files of the same test', async ({ context, page, req // Same actions from different test runs should not be merged. await expect(traceViewer.actionTitles).toHaveText([ 'Before Hooks', + 'Before Hooks', + 'page.gotohttps://playwright.dev/', 'page.gotohttps://playwright.dev/', 'expect.toBe', 'After Hooks', - 'Before Hooks', - 'page.gotohttps://playwright.dev/', 'expect.toBe', 'After Hooks', ]);