Skip to content

Commit

Permalink
chore: use monotonic time for sorting (#30735)
Browse files Browse the repository at this point in the history
* 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.
  • Loading branch information
yury-s committed May 9, 2024
1 parent 0d004c9 commit a50cd30
Show file tree
Hide file tree
Showing 2 changed files with 51 additions and 28 deletions.
75 changes: 49 additions & 26 deletions packages/trace-viewer/src/ui/modelUtil.ts
Expand Up @@ -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)
Expand All @@ -212,64 +212,87 @@ function makeCallIdsUniqueAcrossTraceFiles(contexts: ContextEntry[], traceFileId
function mergeActionsAndUpdateTimingSameTrace(contexts: ContextEntry[]) {
const map = new Map<string, ActionTraceEventInContext>();

// 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<string, string>();
const nonPrimaryTimeDelta = new Map<ContextEntry, number>();
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;
if (action.attachments)
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)
action.parentId = nonPrimaryIdToPrimaryId.get(action.parentId) ?? action.parentId;
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<string, ActionTraceEventInContext>) {
// 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<string, ActionTreeItem> } {
Expand Down
4 changes: 2 additions & 2 deletions tests/library/trace-viewer.spec.ts
Expand Up @@ -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',
]);
Expand Down

0 comments on commit a50cd30

Please sign in to comment.