Skip to content

Commit

Permalink
delete wallTime from trace
Browse files Browse the repository at this point in the history
  • Loading branch information
yury-s committed May 11, 2024
1 parent 0af856e commit 391a3e6
Show file tree
Hide file tree
Showing 21 changed files with 29 additions and 43 deletions.
10 changes: 4 additions & 6 deletions packages/playwright-core/src/client/channelOwner.ts
Original file line number Diff line number Diff line change
Expand Up @@ -143,15 +143,15 @@ export abstract class ChannelOwner<T extends channels.Channel = channels.Channel
if (validator) {
return async (params: any) => {
return await this._wrapApiCall(async apiZone => {
const { apiName, frames, csi, callCookie, wallTime, stepId } = apiZone.reported ? { apiName: undefined, csi: undefined, callCookie: undefined, frames: [], wallTime: undefined, stepId: undefined } : apiZone;
const { apiName, frames, csi, callCookie, stepId } = apiZone.reported ? { apiName: undefined, csi: undefined, callCookie: undefined, frames: [], stepId: undefined } : apiZone;
apiZone.reported = true;
let currentStepId = stepId;
if (csi && apiName) {
const out: { stepId?: string } = {};
csi.onApiCallBegin(apiName, params, frames, wallTime, callCookie, out);
csi.onApiCallBegin(apiName, params, frames, callCookie, out);
currentStepId = out.stepId;
}
return await this._connection.sendMessageToServer(this, prop, validator(params, '', { tChannelImpl: tChannelImplToWire, binary: this._connection.rawBuffers() ? 'buffer' : 'toBase64' }), apiName, frames, wallTime, currentStepId);
return await this._connection.sendMessageToServer(this, prop, validator(params, '', { tChannelImpl: tChannelImplToWire, binary: this._connection.rawBuffers() ? 'buffer' : 'toBase64' }), apiName, frames, currentStepId);
});
};
}
Expand Down Expand Up @@ -179,7 +179,6 @@ export abstract class ChannelOwner<T extends channels.Channel = channels.Channel

// Enclosing zone could have provided the apiName and wallTime.
const expectZone = zones.zoneData<ExpectZone>('expectZone');
const wallTime = expectZone ? expectZone.wallTime : Date.now();
const stepId = expectZone?.stepId;
if (!isInternal && expectZone)
apiName = expectZone.title;
Expand All @@ -191,7 +190,7 @@ export abstract class ChannelOwner<T extends channels.Channel = channels.Channel

try {
logApiCall(logger, `=> ${apiName} started`, isInternal);
const apiZone: ApiZone = { apiName, frames, isInternal, reported: false, csi, callCookie, wallTime, stepId };
const apiZone: ApiZone = { apiName, frames, isInternal, reported: false, csi, callCookie, stepId };
const result = await zones.run('apiZone', apiZone, async () => await func(apiZone));
csi?.onApiCallEnd(callCookie);
logApiCall(logger, `<= ${apiName} succeeded`, isInternal);
Expand Down Expand Up @@ -248,6 +247,5 @@ type ApiZone = {
reported: boolean;
csi: ClientInstrumentation | undefined;
callCookie: any;
wallTime: number;
stepId?: string;
};
4 changes: 2 additions & 2 deletions packages/playwright-core/src/client/clientInstrumentation.ts
Original file line number Diff line number Diff line change
Expand Up @@ -22,7 +22,7 @@ export interface ClientInstrumentation {
addListener(listener: ClientInstrumentationListener): void;
removeListener(listener: ClientInstrumentationListener): void;
removeAllListeners(): void;
onApiCallBegin(apiCall: string, params: Record<string, any>, frames: StackFrame[], wallTime: number, userData: any, out: { stepId?: string }): void;
onApiCallBegin(apiCall: string, params: Record<string, any>, frames: StackFrame[], userData: any, out: { stepId?: string }): void;
onApiCallEnd(userData: any, error?: Error): void;
onDidCreateBrowserContext(context: BrowserContext): Promise<void>;
onDidCreateRequestContext(context: APIRequestContext): Promise<void>;
Expand All @@ -32,7 +32,7 @@ export interface ClientInstrumentation {
}

export interface ClientInstrumentationListener {
onApiCallBegin?(apiName: string, params: Record<string, any>, frames: StackFrame[], wallTime: number, userData: any, out: { stepId?: string }): void;
onApiCallBegin?(apiName: string, params: Record<string, any>, frames: StackFrame[], userData: any, out: { stepId?: string }): void;
onApiCallEnd?(userData: any, error?: Error): void;
onDidCreateBrowserContext?(context: BrowserContext): Promise<void>;
onDidCreateRequestContext?(context: APIRequestContext): Promise<void>;
Expand Down
4 changes: 2 additions & 2 deletions packages/playwright-core/src/client/connection.ts
Original file line number Diff line number Diff line change
Expand Up @@ -118,7 +118,7 @@ export class Connection extends EventEmitter {
this._tracingCount--;
}

async sendMessageToServer(object: ChannelOwner, method: string, params: any, apiName: string | undefined, frames: channels.StackFrame[], wallTime: number | undefined, stepId?: string): Promise<any> {
async sendMessageToServer(object: ChannelOwner, method: string, params: any, apiName: string | undefined, frames: channels.StackFrame[], stepId?: string): Promise<any> {
if (this._closedError)
throw this._closedError;
if (object._wasCollected)
Expand All @@ -133,7 +133,7 @@ export class Connection extends EventEmitter {
debugLogger.log('channel', 'SEND> ' + JSON.stringify(message));
}
const location = frames[0] ? { file: frames[0].file, line: frames[0].line, column: frames[0].column } : undefined;
const metadata: channels.Metadata = { wallTime, apiName, location, internal: !apiName, stepId };
const metadata: channels.Metadata = { apiName, location, internal: !apiName, stepId };
if (this._tracingCount && frames && type !== 'LocalUtils')
this._localUtils?._channel.addStackToTracingNoReply({ callData: { stack: frames, id } }).catch(() => {});
// We need to exit zones before calling into the server, otherwise
Expand Down
1 change: 0 additions & 1 deletion packages/playwright-core/src/protocol/validator.ts
Original file line number Diff line number Diff line change
Expand Up @@ -34,7 +34,6 @@ scheme.Metadata = tObject({
})),
apiName: tOptional(tString),
internal: tOptional(tBoolean),
wallTime: tOptional(tNumber),
stepId: tOptional(tString),
});
scheme.ClientSideCallMetadata = tObject({
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -286,7 +286,6 @@ export class DispatcherConnection {
const sdkObject = dispatcher._object instanceof SdkObject ? dispatcher._object : undefined;
const callMetadata: CallMetadata = {
id: `call@${id}`,
wallTime: validMetadata.wallTime || Date.now(),
location: validMetadata.location,
apiName: validMetadata.apiName,
internal: validMetadata.internal,
Expand Down
1 change: 0 additions & 1 deletion packages/playwright-core/src/server/instrumentation.ts
Original file line number Diff line number Diff line change
Expand Up @@ -106,7 +106,6 @@ export function serverSideCallMetadata(): CallMetadata {
id: '',
startTime: 0,
endTime: 0,
wallTime: Date.now(),
type: 'Internal',
method: '',
params: {},
Expand Down
1 change: 0 additions & 1 deletion packages/playwright-core/src/server/recorder.ts
Original file line number Diff line number Diff line change
Expand Up @@ -605,7 +605,6 @@ class ContextRecorder extends EventEmitter {
frameId: frame.guid,
startTime: monotonicTime(),
endTime: 0,
wallTime: Date.now(),
type: 'Frame',
method: action,
params,
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -535,7 +535,6 @@ function createBeforeActionTraceEvent(metadata: CallMetadata): trace.BeforeActio
class: metadata.type,
method: metadata.method,
params: metadata.params,
wallTime: metadata.wallTime,
stepId: metadata.stepId,
pageId: metadata.pageId,
};
Expand Down
1 change: 0 additions & 1 deletion packages/playwright-core/src/utils/stackTrace.ts
Original file line number Diff line number Diff line change
Expand Up @@ -140,6 +140,5 @@ Call log:

export type ExpectZone = {
title: string;
wallTime: number;
stepId: string;
};
2 changes: 1 addition & 1 deletion packages/playwright/src/common/testType.ts
Original file line number Diff line number Diff line change
Expand Up @@ -263,7 +263,7 @@ export class TestTypeImpl {
const testInfo = currentTestInfo();
if (!testInfo)
throw new Error(`test.step() can only be called from a test`);
const step = testInfo._addStep({ wallTime: Date.now(), category: 'test.step', title, box: options.box });
const step = testInfo._addStep({ category: 'test.step', title, box: options.box });
return await zones.run('stepZone', step, async () => {
try {
const result = await body();
Expand Down
3 changes: 1 addition & 2 deletions packages/playwright/src/index.ts
Original file line number Diff line number Diff line change
Expand Up @@ -247,7 +247,7 @@ const playwrightFixtures: Fixtures<TestFixtures, WorkerFixtures> = ({
const artifactsRecorder = new ArtifactsRecorder(playwright, tracing().artifactsDir(), screenshot);
await artifactsRecorder.willStartTest(testInfo as TestInfoImpl);
const csiListener: ClientInstrumentationListener = {
onApiCallBegin: (apiName: string, params: Record<string, any>, frames: StackFrame[], wallTime: number, userData: any, out: { stepId?: string }) => {
onApiCallBegin: (apiName: string, params: Record<string, any>, frames: StackFrame[], userData: any, out: { stepId?: string }) => {
const testInfo = currentTestInfo();
if (!testInfo || apiName.includes('setTestIdAttribute'))
return { userObject: null };
Expand All @@ -257,7 +257,6 @@ const playwrightFixtures: Fixtures<TestFixtures, WorkerFixtures> = ({
title: renderApiCall(apiName, params),
apiName,
params,
wallTime,
});
userData.userObject = step;
out.stepId = step.stepId;
Expand Down
4 changes: 1 addition & 3 deletions packages/playwright/src/matchers/expect.ts
Original file line number Diff line number Diff line change
Expand Up @@ -259,7 +259,6 @@ class ExpectMetaInfoProxyHandler implements ProxyHandler<any> {

const defaultTitle = `expect${this._info.isPoll ? '.poll' : ''}${this._info.isSoft ? '.soft' : ''}${this._info.isNot ? '.not' : ''}.${matcherName}${argsSuffix}`;
const title = customMessage || defaultTitle;
const wallTime = Date.now();

// This looks like it is unnecessary, but it isn't - we need to filter
// out all the frames that belong to the test runner from caught runtime errors.
Expand All @@ -270,7 +269,6 @@ class ExpectMetaInfoProxyHandler implements ProxyHandler<any> {
category: 'expect',
title: trimLongString(title, 1024),
params: args[0] ? { expected: args[0] } : undefined,
wallTime,
infectParentStepsWithError: this._info.isSoft,
};

Expand All @@ -295,7 +293,7 @@ class ExpectMetaInfoProxyHandler implements ProxyHandler<any> {
// so they behave like a retriable step.
const result = (matcherName === 'toPass' || this._info.isPoll) ?
zones.run('stepZone', step, callback) :
zones.run<ExpectZone, any>('expectZone', { title, wallTime, stepId: step.stepId }, callback);
zones.run<ExpectZone, any>('expectZone', { title, stepId: step.stepId }, callback);
if (result instanceof Promise)
return result.then(finalizer).catch(reportStepError);
finalizer();
Expand Down
8 changes: 3 additions & 5 deletions packages/playwright/src/worker/testInfo.ts
Original file line number Diff line number Diff line change
Expand Up @@ -34,7 +34,6 @@ export interface TestStepInternal {
stepId: string;
title: string;
category: 'hook' | 'fixture' | 'test.step' | 'expect' | string;
wallTime: number;
location?: Location;
boxedStack?: StackFrame[];
steps: TestStepInternal[];
Expand Down Expand Up @@ -322,11 +321,11 @@ export class TestInfoImpl implements TestInfo {
parentStepId: parentStep ? parentStep.stepId : undefined,
title: data.title,
category: data.category,
wallTime: data.wallTime,
wallTime: Date.now(),
location: data.location,
};
this._onStepBegin(payload);
this._tracing.appendBeforeActionForStep(stepId, parentStep?.stepId, data.apiName || data.title, data.params, data.wallTime, data.location ? [data.location] : []);
this._tracing.appendBeforeActionForStep(stepId, parentStep?.stepId, data.apiName || data.title, data.params, data.location ? [data.location] : []);
return step;
}

Expand Down Expand Up @@ -355,7 +354,7 @@ export class TestInfoImpl implements TestInfo {
const location = stage.runnable?.location ? ` at "${formatLocation(stage.runnable.location)}"` : ``;
debugTest(`started stage "${stage.title}"${location}`);
}
stage.step = stage.stepInfo ? this._addStep({ ...stage.stepInfo, title: stage.title, wallTime: Date.now(), isStage: true }) : undefined;
stage.step = stage.stepInfo ? this._addStep({ ...stage.stepInfo, title: stage.title, isStage: true }) : undefined;
this._stages.push(stage);

try {
Expand Down Expand Up @@ -420,7 +419,6 @@ export class TestInfoImpl implements TestInfo {
const step = this._addStep({
title: `attach "${name}"`,
category: 'attach',
wallTime: Date.now(),
});
this._attachmentsPush(attachment);
this._onAttach({
Expand Down
3 changes: 1 addition & 2 deletions packages/playwright/src/worker/testTracing.ts
Original file line number Diff line number Diff line change
Expand Up @@ -220,12 +220,11 @@ export class TestTracing {
});
}

appendBeforeActionForStep(callId: string, parentId: string | undefined, apiName: string, params: Record<string, any> | undefined, wallTime: number, stack: StackFrame[]) {
appendBeforeActionForStep(callId: string, parentId: string | undefined, apiName: string, params: Record<string, any> | undefined, stack: StackFrame[]) {
this._appendTraceEvent({
type: 'before',
callId,
parentId,
wallTime,
startTime: monotonicTime(),
class: 'Test',
method: 'step',
Expand Down
2 changes: 0 additions & 2 deletions packages/protocol/src/callMetadata.ts
Original file line number Diff line number Diff line change
Expand Up @@ -32,8 +32,6 @@ export type CallMetadata = {
// Service-side is making a call to itself, this metadata does not go
// through the dispatcher, so is always excluded from inspector / tracing.
isServerSide?: boolean;
// Client wall time.
wallTime: number;
// Test runner step id.
stepId?: string;
location?: { file: string, line?: number, column?: number };
Expand Down
1 change: 0 additions & 1 deletion packages/protocol/src/channels.ts
Original file line number Diff line number Diff line change
Expand Up @@ -149,7 +149,6 @@ export type Metadata = {
},
apiName?: string,
internal?: boolean,
wallTime?: number,
stepId?: string,
};

Expand Down
2 changes: 0 additions & 2 deletions packages/protocol/src/protocol.yml
Original file line number Diff line number Diff line change
Expand Up @@ -33,8 +33,6 @@ Metadata:
column: number?
apiName: string?
internal: boolean?
# The number of milliseconds elapsed since midnight, January 1, 1970 UTC.
wallTime: number?
# Test runner step id.
stepId: string?

Expand Down
9 changes: 7 additions & 2 deletions packages/trace-viewer/src/ui/callTab.tsx
Original file line number Diff line number Diff line change
Expand Up @@ -23,9 +23,10 @@ import { CopyToClipboard } from './copyToClipboard';
import { asLocator } from '@isomorphic/locatorGenerators';
import type { Language } from '@isomorphic/locatorGenerators';
import { PlaceholderPanel } from './placeholderPanel';
import type { ActionTraceEventInContext } from './modelUtil';

export const CallTab: React.FunctionComponent<{
action: ActionTraceEvent | undefined,
action: ActionTraceEventInContext | undefined,
sdkLanguage: Language | undefined,
}> = ({ action, sdkLanguage }) => {
if (!action)
Expand All @@ -34,7 +35,11 @@ export const CallTab: React.FunctionComponent<{
// Strip down the waitForEventInfo data, we never need it.
delete params.info;
const paramKeys = Object.keys(params);
const wallTime = action.wallTime ? new Date(action.wallTime).toLocaleString() : null;
let wallTime = null;
if (action.context.wallTime) {
const timeMillis = action.startTime + (action.context.wallTime - action.context.startTime);
wallTime = new Date(timeMillis).toLocaleString();
}
const duration = action.endTime ? msToString(action.endTime - action.startTime) : 'Timed Out';

return <div className='call-tab'>
Expand Down
3 changes: 2 additions & 1 deletion packages/trace-viewer/src/ui/logTab.tsx
Original file line number Diff line number Diff line change
Expand Up @@ -31,7 +31,8 @@ export const LogTab: React.FunctionComponent<{
if (!action || !action.log.length)
return [];
const log = action.log;
const wallTimeOffset = action.wallTime - action.startTime;
// TODO: store context metadata for test runner context.
const wallTimeOffset = (action.context.wallTime || action.context.startTime) - action.context.startTime;
const entries: { message: string, time: string }[] = [];
for (let i = 0; i < log.length; ++i) {
let time = '';
Expand Down
10 changes: 5 additions & 5 deletions packages/trace-viewer/src/ui/modelUtil.ts
Original file line number Diff line number Diff line change
Expand Up @@ -225,7 +225,7 @@ function mergeActionsAndUpdateTimingSameTrace(contexts: ContextEntry[]) {

for (const context of libraryContexts) {
for (const action of context.actions) {
const key = matchByStepId ? action.stepId! : `${action.apiName}@${action.wallTime}`;
const key = matchByStepId ? action.stepId! : `${action.apiName}@${(action as any).wallTime}`;
map.set(key, { ...action, context });
}
}
Expand All @@ -234,14 +234,14 @@ function mergeActionsAndUpdateTimingSameTrace(contexts: ContextEntry[]) {
// Step aka test runner contexts have startTime/endTime as client-side times.
// Adjust startTime/endTime on the library contexts to align them with the test
// runner steps.
const delta = monotonicTimeDeltaBetweenLibraryAndRunner(testRunnerContexts, map);
const delta = monotonicTimeDeltaBetweenLibraryAndRunner(testRunnerContexts, map, matchByStepId);
if (delta)
adjustMonotonicTime(libraryContexts, delta);

const nonPrimaryIdToPrimaryId = new Map<string, string>();
for (const context of testRunnerContexts) {
for (const action of context.actions) {
const key = matchByStepId ? action.callId : `${action.apiName}@${action.wallTime}`;
const key = matchByStepId ? action.callId : `${action.apiName}@${(action as any).wallTime}`;
const existing = map.get(key);
if (existing) {
nonPrimaryIdToPrimaryId.set(action.callId, existing.callId);
Expand Down Expand Up @@ -286,7 +286,7 @@ function adjustMonotonicTime(contexts: ContextEntry[], monotonicTimeDelta: numbe
}
}

function monotonicTimeDeltaBetweenLibraryAndRunner(nonPrimaryContexts: ContextEntry[], libraryActions: Map<string, ActionTraceEventInContext>) {
function monotonicTimeDeltaBetweenLibraryAndRunner(nonPrimaryContexts: ContextEntry[], libraryActions: Map<string, ActionTraceEventInContext>, matchByStepId: boolean) {
// 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
Expand All @@ -296,7 +296,7 @@ function monotonicTimeDeltaBetweenLibraryAndRunner(nonPrimaryContexts: ContextEn
for (const action of context.actions) {
if (!action.startTime)
continue;
const key = `${action.apiName}@${action.wallTime}`;
const key = matchByStepId ? action.stepId! : `${action.apiName}@${(action as any).wallTime}`;
const libraryAction = libraryActions.get(key);
if (libraryAction)
return action.startTime - libraryAction.startTime;
Expand Down
1 change: 0 additions & 1 deletion packages/trace/src/trace.ts
Original file line number Diff line number Diff line change
Expand Up @@ -60,7 +60,6 @@ export type BeforeActionTraceEvent = {
class: string;
method: string;
params: Record<string, any>;
wallTime: number;
stepId?: string;
beforeSnapshot?: string;
stack?: StackFrame[];
Expand Down

0 comments on commit 391a3e6

Please sign in to comment.