diff --git a/src/dispatchers/dispatcher.ts b/src/dispatchers/dispatcher.ts index c3e1a56c8bf72..5087554045052 100644 --- a/src/dispatchers/dispatcher.ts +++ b/src/dispatchers/dispatcher.ts @@ -219,6 +219,7 @@ export class DispatcherConnection { rewriteErrorMessage(e, e.message + formatLogRecording(callMetadata.log) + kLoggingNote); this.onmessage({ id, error: serializeError(e) }); } finally { + callMetadata.endTime = monotonicTime(); if (sdkObject) await sdkObject.instrumentation.onAfterCall(sdkObject, callMetadata); } diff --git a/src/server/instrumentation.ts b/src/server/instrumentation.ts index 5544d779dfc17..bb4165cd59b74 100644 --- a/src/server/instrumentation.ts +++ b/src/server/instrumentation.ts @@ -34,6 +34,8 @@ export type CallMetadata = { id: number; startTime: number; endTime: number; + pauseStartTime?: number; + pauseEndTime?: number; type: string; method: string; params: any; diff --git a/src/server/progress.ts b/src/server/progress.ts index 47a8a00155f90..238f36441da95 100644 --- a/src/server/progress.ts +++ b/src/server/progress.ts @@ -109,7 +109,6 @@ export class ProgressController { throw e; } finally { clearTimeout(timer); - this.metadata.endTime = monotonicTime(); } } diff --git a/src/server/supplements/inspectorController.ts b/src/server/supplements/inspectorController.ts index ae0869548202c..4ecbc76545f58 100644 --- a/src/server/supplements/inspectorController.ts +++ b/src/server/supplements/inspectorController.ts @@ -72,12 +72,15 @@ export class InspectorController implements InstrumentationListener { const info = metadata.params.info; switch (info.phase) { case 'before': + metadata.endTime = 0; // Fall through. case 'log': return; case 'after': - metadata = this._waitOperations.get(info.waitId)!; + const originalMetadata = this._waitOperations.get(info.waitId)!; + originalMetadata.endTime = metadata.endTime; this._waitOperations.delete(info.waitId); + metadata = originalMetadata; break; } } diff --git a/src/server/supplements/recorder/recorderTypes.ts b/src/server/supplements/recorder/recorderTypes.ts index 48f91c5a105de..9d010e5b7d583 100644 --- a/src/server/supplements/recorder/recorderTypes.ts +++ b/src/server/supplements/recorder/recorderTypes.ts @@ -36,6 +36,11 @@ export type CallLog = { status: 'in-progress' | 'done' | 'error' | 'paused'; error?: string; reveal?: boolean; + duration?: number; + params: { + url?: string, + selector?: string, + }; }; export type SourceHighlight = { diff --git a/src/server/supplements/recorderSupplement.ts b/src/server/supplements/recorderSupplement.ts index 250d1f16a95ea..b669df2ad6359 100644 --- a/src/server/supplements/recorderSupplement.ts +++ b/src/server/supplements/recorderSupplement.ts @@ -31,7 +31,7 @@ import { RecorderApp } from './recorder/recorderApp'; import { CallMetadata, internalCallMetadata, SdkObject } from '../instrumentation'; import { Point } from '../../common/types'; import { CallLog, EventData, Mode, Source, UIState } from './recorder/recorderTypes'; -import { isUnderTest } from '../../utils/utils'; +import { isUnderTest, monotonicTime } from '../../utils/utils'; type BindingSource = { frame: Frame, page: Page }; @@ -210,6 +210,7 @@ export class RecorderSupplement { this._pausedCallsMetadata.set(metadata, f); }); this._recorderApp!.setPaused(true); + metadata.pauseStartTime = monotonicTime(); this._updateUserSources(); this.updateCallLog([metadata]); return result; @@ -219,8 +220,11 @@ export class RecorderSupplement { this._pauseOnNextStatement = step; this._recorderApp?.setPaused(false); - for (const callback of this._pausedCallsMetadata.values()) + const endTime = monotonicTime(); + for (const [metadata, callback] of this._pausedCallsMetadata) { + metadata.pauseEndTime = endTime; callback(); + } this._pausedCallsMetadata.clear(); this._updateUserSources(); @@ -418,7 +422,21 @@ export class RecorderSupplement { status = 'paused'; if (metadata.error) status = 'error'; - logs.push({ id: metadata.id, messages: metadata.log, title, status, error: metadata.error }); + const params = { + url: metadata.params?.url, + selector: metadata.params?.selector, + }; + let duration = metadata.endTime ? metadata.endTime - metadata.startTime : undefined; + if (duration && metadata.pauseStartTime && metadata.pauseEndTime) + duration -= (metadata.pauseEndTime - metadata.pauseStartTime); + logs.push({ + id: metadata.id, + messages: metadata.log, + title, status, + error: metadata.error, + params, + duration + }); } this._recorderApp?.updateCallLogs(logs); } diff --git a/src/web/recorder/callLog.css b/src/web/recorder/callLog.css index 7a90ca65c0b8d..de2693cdd1253 100644 --- a/src/web/recorder/callLog.css +++ b/src/web/recorder/callLog.css @@ -76,3 +76,16 @@ .call-log .codicon-error { color: red; } + +.call-log-url { + color: var(--blue); +} + +.call-log-selector { + color: var(--orange); +} + +.call-log-time { + margin-left: 4px; + color: var(--gray); +} diff --git a/src/web/recorder/callLog.example.ts b/src/web/recorder/callLog.example.ts index 65845956836fb..ec9c00d23f953 100644 --- a/src/web/recorder/callLog.example.ts +++ b/src/web/recorder/callLog.example.ts @@ -22,7 +22,9 @@ export function exampleCallLog(): CallLog[] { 'id': 3, 'messages': [], 'title': 'newPage', - 'status': 'done' + 'status': 'done', + 'duration': 100, + 'params': {} }, { 'id': 4, @@ -30,7 +32,11 @@ export function exampleCallLog(): CallLog[] { 'navigating to "https://github.com/microsoft", waiting until "load"', ], 'title': 'goto', - 'status': 'done' + 'status': 'done', + 'params': { + 'url': 'https://github.com/microsoft' + }, + 'duration': 1100, }, { 'id': 5, @@ -47,7 +53,10 @@ export function exampleCallLog(): CallLog[] { ' performing click action' ], 'title': 'click', - 'status': 'paused' + 'status': 'paused', + 'params': { + 'selector': 'input[aria-label="Find a repository…"]' + }, }, { 'id': 6, @@ -56,7 +65,9 @@ export function exampleCallLog(): CallLog[] { ], 'error': 'Error occured', 'title': 'error', - 'status': 'error' + 'status': 'error', + 'params': { + }, }, ]; } diff --git a/src/web/recorder/callLog.tsx b/src/web/recorder/callLog.tsx index 031be1f300555..be98680dd1f8a 100644 --- a/src/web/recorder/callLog.tsx +++ b/src/web/recorder/callLog.tsx @@ -17,6 +17,7 @@ import './callLog.css'; import * as React from 'react'; import type { CallLog } from '../../server/supplements/recorder/recorderTypes'; +import { msToString } from '../uiUtils'; export interface CallLogProps { log: CallLog[] @@ -46,7 +47,10 @@ export const CallLogView: React.FC = ({ setExpandOverrides(newOverrides); }}> { callLog.title } + { callLog.params.url ? ({callLog.params.url}) : undefined } + { callLog.params.selector ? ({callLog.params.selector}) : undefined } + { typeof callLog.duration === 'number' ? — {msToString(callLog.duration)} : undefined} { (isExpanded ? callLog.messages : []).map((message, i) => { return
diff --git a/src/web/traceViewer/ui/helpers.tsx b/src/web/traceViewer/ui/helpers.tsx index 0891083a0c718..d152c0d411aea 100644 --- a/src/web/traceViewer/ui/helpers.tsx +++ b/src/web/traceViewer/ui/helpers.tsx @@ -72,29 +72,3 @@ export const Expandable: React.FunctionComponent<{ { expanded &&
{body}
}
; }; - -export function msToString(ms: number): string { - if (!isFinite(ms)) - return '-'; - - if (ms === 0) - return '0'; - - if (ms < 1000) - return ms.toFixed(0) + 'ms'; - - const seconds = ms / 1000; - if (seconds < 60) - return seconds.toFixed(1) + 's'; - - const minutes = seconds / 60; - if (minutes < 60) - return minutes.toFixed(1) + 'm'; - - const hours = minutes / 60; - if (hours < 24) - return hours.toFixed(1) + 'h'; - - const days = hours / 24; - return days.toFixed(1) + 'd'; -} diff --git a/src/web/traceViewer/ui/snapshotTab.tsx b/src/web/traceViewer/ui/snapshotTab.tsx index 55adb6efab5eb..ad83dd4ab2f55 100644 --- a/src/web/traceViewer/ui/snapshotTab.tsx +++ b/src/web/traceViewer/ui/snapshotTab.tsx @@ -18,7 +18,8 @@ import { ActionEntry } from '../../../cli/traceViewer/traceModel'; import { Boundaries, Size } from '../geometry'; import './snapshotTab.css'; import * as React from 'react'; -import { msToString, useMeasure } from './helpers'; +import { useMeasure } from './helpers'; +import { msToString } from '../../uiUtils'; export const SnapshotTab: React.FunctionComponent<{ actionEntry: ActionEntry | undefined, diff --git a/src/web/traceViewer/ui/timeline.tsx b/src/web/traceViewer/ui/timeline.tsx index d52e765ccee21..d3919c96a3a70 100644 --- a/src/web/traceViewer/ui/timeline.tsx +++ b/src/web/traceViewer/ui/timeline.tsx @@ -19,7 +19,8 @@ import { ContextEntry, InterestingPageEvent, ActionEntry, trace } from '../../.. import './timeline.css'; import { Boundaries } from '../geometry'; import * as React from 'react'; -import { msToString, useMeasure } from './helpers'; +import { useMeasure } from './helpers'; +import { msToString } from '../../uiUtils'; type TimelineBar = { entry?: ActionEntry; diff --git a/src/web/uiUtils.ts b/src/web/uiUtils.ts new file mode 100644 index 0000000000000..34ad57731ff59 --- /dev/null +++ b/src/web/uiUtils.ts @@ -0,0 +1,41 @@ +/* + Copyright (c) Microsoft Corporation. + + Licensed under the Apache License, Version 2.0 (the "License"); + you may not use this file except in compliance with the License. + You may obtain a copy of the License at + + http://www.apache.org/licenses/LICENSE-2.0 + + Unless required by applicable law or agreed to in writing, software + distributed under the License is distributed on an "AS IS" BASIS, + WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + See the License for the specific language governing permissions and + limitations under the License. +*/ + +export function msToString(ms: number): string { + if (!isFinite(ms)) + return '-'; + + if (ms === 0) + return '0'; + + if (ms < 1000) + return ms.toFixed(0) + 'ms'; + + const seconds = ms / 1000; + if (seconds < 60) + return seconds.toFixed(1) + 's'; + + const minutes = seconds / 60; + if (minutes < 60) + return minutes.toFixed(1) + 'm'; + + const hours = minutes / 60; + if (hours < 24) + return hours.toFixed(1) + 'h'; + + const days = hours / 24; + return days.toFixed(1) + 'd'; +} diff --git a/test/pause.spec.ts b/test/pause.spec.ts index 44aca2bf1707f..9506355c19f35 100644 --- a/test/pause.spec.ts +++ b/test/pause.spec.ts @@ -146,8 +146,8 @@ describe('pause', (suite, { mode }) => { await recorderPage.click('[title="Resume"]'); await recorderPage.waitForSelector('.source-line-paused:has-text("page.pause(); // 2")'); expect(await sanitizeLog(recorderPage)).toEqual([ - 'pause', - 'click', + 'pause- XXms', + 'click(button)- XXms', 'pause', ]); await recorderPage.click('[title="Resume"]'); @@ -168,9 +168,9 @@ describe('pause', (suite, { mode }) => { await recorderPage.click('[title="Resume"]'); await recorderPage.waitForSelector('.source-line-paused:has-text("page.pause(); // 2")'); expect(await sanitizeLog(recorderPage)).toEqual([ - 'pause', - 'waitForEvent()', - 'click', + 'pause- XXms', + 'waitForEvent(console)- XXms', + 'click(button)- XXms', 'pause', ]); await recorderPage.click('[title="Resume"]'); @@ -187,10 +187,10 @@ describe('pause', (suite, { mode }) => { await recorderPage.click('[title="Resume"]'); await recorderPage.waitForSelector('.source-line-error'); expect(await sanitizeLog(recorderPage)).toEqual([ - 'pause', - 'isChecked', + 'pause- XXms', + 'isChecked(button)- XXms', 'checking \"checked\" state of \"button\"', - 'selector resolved to ', + 'selector resolved to ', 'Not a checkbox or radio button', ]); const error = await scriptPromise; @@ -199,10 +199,15 @@ describe('pause', (suite, { mode }) => { }); async function sanitizeLog(recorderPage: Page): Promise { - const text = await recorderPage.innerText('.call-log'); - return text.split('\n').filter(l => { - return l !== 'element is not stable - waiting...'; - }).map(l => { - return l.replace(/\(.*\)/, '()'); - }); + const results = []; + for (const entry of await recorderPage.$$('.call-log-call')) { + const header = await (await (await entry.$('.call-log-call-header')).textContent()).replace(/— \d+(ms|s)/, '- XXms'); + results.push(header); + results.push(...await entry.$$eval('.call-log-message', ee => ee.map(e => e.textContent))); + const errorElement = await entry.$('.call-log-error'); + const error = errorElement ? await errorElement.textContent() : undefined; + if (error) + results.push(error); + } + return results; }