Adding up the self time…
`; + } const apexLog = this.logStore?.log; - const slices = apexLog ? categorySelfTimes(apexLog) : []; + const windowed = this._window.stats; + const slices = windowed + ? toCategoryTimes(windowed.selfByCategory) + : apexLog + ? categorySelfTimes(apexLog) + : []; if (!slices.length) { - return html`No categorised time was recorded in this log.
`; + return html`+ ${ + this._window.window + ? 'No categorised time was recorded in this range.' + : 'No categorised time was recorded in this log.' + } +
`; } return html`Adding up the governor usage…
`; + } + const window = this.wholeLog ? null : this._window.counts; + const gauges = apexLog ? seriesGauges(apexLimitTimeSeries(apexLog), window ?? undefined) : []; if (!apexLog || !gauges.length) { return html`${NO_CUMULATIVE_LIMITS_TEXT}
`; } diff --git a/log-viewer/src/components/NamespaceTimeBar.ts b/log-viewer/src/components/NamespaceTimeBar.ts index 41f135f85..0b0c6df4c 100644 --- a/log-viewer/src/components/NamespaceTimeBar.ts +++ b/log-viewer/src/components/NamespaceTimeBar.ts @@ -7,6 +7,7 @@ import { LitElement, html, type PropertyValues } from 'lit'; import { customElement, property, state } from 'lit/decorators.js'; import { logContext } from '../core/log/logContext.js'; +import { WindowStatsController } from '../core/log/windowStats.js'; import type { LogStore } from '../core/log/LogStore.js'; import { globalStyles } from '../styles/global.styles.js'; import { inspectorSectionStyles } from '../styles/inspectorSection.styles.js'; @@ -16,6 +17,7 @@ import { logNamespacePalette } from './namespacePalette.js'; import { cachedNamespaceSelfTimes, scopedNamespaceSelfTimes, + toNamespaceTimes, type NamespaceTime, } from './namespaceTime.js'; @@ -35,7 +37,8 @@ interface Scope { * namespace. * * Whole log with no `eventIndex`, otherwise the selected frame and everything - * below it, so the same section answers "and inside this method?". + * below it, so the same section answers "and inside this method?". Narrowed + * again to the window the Timeline is showing, when it shows part of the log. * * One namespace still gets its bar: that a scope mixes no packages is an answer, * and the full bar with its figure says it. @@ -66,21 +69,26 @@ export class NamespaceTimeBar extends LitElement { /** The walk in flight; a new scope aborts it, and so does a disconnect. */ private _walk: AbortController | null = null; - /** The log's palette, so a namespace keeps its colour across scopes. Null until - * a scope resolves, which needs a log. */ - private _color: ((namespace: string) => string) | null = null; + private readonly _window = new WindowStatsController(this, () => this.logStore?.log ?? null); static styles = [globalStyles, inspectorSectionStyles]; render() { - const slices = this._slices; + let slices = this._slices; + if (this._windowScoped()) { + const windowed = this._window.stats; + slices = windowed ? toNamespaceTimes(windowed.selfByNamespace) : null; + } if (!slices) { return html`Adding up the self time…
`; } - const color = this._color; - if (!slices.length || !color) { + // The palette is the log's, so it stands whatever the scope is: the window + // answers without the scope walk that used to resolve it. + const log = this.logStore?.log; + if (!slices.length || !log) { return html`No time was recorded here.
`; } + const color = logNamespacePalette(log); const segments = segmentsWithTail(slices, (slice) => ({ label: slice.namespace, value: slice.selfTime, @@ -109,6 +117,11 @@ export class NamespaceTimeBar extends LitElement { } protected updated(changed: PropertyValues): void { + // The window answers on its own, so a whole-log walk now would be thrown + // away. It waits until the window clears or a selection takes over. + if (this._windowScoped()) { + return; + } // Resolving a scope maps every instance index, so only a changed selection — // or a scope we have yet to resolve — earns the walk. if (changed.has('eventIndex') || changed.has('instances') || this._scopeKey === UNRESOLVED) { @@ -130,7 +143,6 @@ export class NamespaceTimeBar extends LitElement { this._slices = []; return; } - this._color = logNamespacePalette(scope.log); // A scope walked before answers now, so a re-selection shows no placeholder. this._slices = cachedNamespaceSelfTimes(scope.key) ?? null; if (this._slices) { @@ -151,6 +163,17 @@ export class NamespaceTimeBar extends LitElement { } } + /** True where the section answers for a picked frame or aggregate. */ + private _selected(): boolean { + return this.eventIndex >= 0 || !!this.instances?.length; + } + + /** True where the window is the scope. A selection wins over it: a picked + * frame is answered as itself, wherever the timeline is looking. */ + private _windowScoped(): boolean { + return !this._selected() && this._window.window !== null; + } + private _scope(): Scope | null { const store = this.logStore; if (!store) { diff --git a/log-viewer/src/components/__tests__/NamespaceTimeBar.test.ts b/log-viewer/src/components/__tests__/NamespaceTimeBar.test.ts index ca4cde2af..3a358d99d 100644 --- a/log-viewer/src/components/__tests__/NamespaceTimeBar.test.ts +++ b/log-viewer/src/components/__tests__/NamespaceTimeBar.test.ts @@ -9,6 +9,7 @@ import type { ApexLog } from 'apex-log-parser'; let apexLog: ApexLog | null = null; import type { LogStore } from '../../core/log/LogStore.js'; +import { setRange } from '../../core/log/rangeScope.js'; import type { NamespaceTimeBar } from '../NamespaceTimeBar.js'; import { DEFAULT_MAX_SEGMENTS } from '../StackedTimeBar.js'; import '../NamespaceTimeBar.js'; @@ -49,6 +50,7 @@ describe('namespace-time-bar', () => { document.body.replaceChildren(); resetEvents(); apexLog = null; + setRange(null); }); it('splits the whole log by namespace, largest first', async () => { @@ -124,3 +126,45 @@ describe('namespace-time-bar', () => { expect(element.shadowRoot?.querySelector('.note')?.textContent).toContain('No time'); }); }); + +describe('namespace-time-bar with a timeline window', () => { + beforeEach(() => { + document.body.replaceChildren(); + resetEvents(); + apexLog = null; + setRange(null); + }); + + afterEach(() => { + setRange(null); + }); + + // A picked frame is answered as itself, wherever the timeline is looking: the + // window here holds a nanosecond, so its own figures could not be these. + it('answers for the picked frame, not the window', async () => { + logOf([ev('default', 100, [ev('pkg', 500)])], ['pkg']); + setRange({ start: 0, end: 1 }); + + // Children register first, so the outer `default` frame is index 1. + const element = await mount({ eventIndex: 1 }); + + expect(segments(element).map((segment) => segment.label)).toEqual(['pkg', 'default']); + expect(segments(element).map((segment) => segment.value)).toEqual([500, 100]); + }); + + // The bar took its palette from the whole-log walk, which a window skips, so + // mounting into a window left it with no colours and an empty note. + it('answers for a window it mounts into', async () => { + logOf([ev('default', 100, [ev('pkg', 500)])], ['pkg']); + // `default` owns 0 to 100, `pkg` 100 to 600. + setRange({ start: 0, end: 350 }); + + const element = await mount(); + const bars = segments(element); + + expect(bars.map((segment) => segment.label)).toEqual(['pkg', 'default']); + expect(bars[0]?.value).toBeCloseTo(250, 3); + expect(bars[1]?.value).toBeCloseTo(100, 3); + expect(bars[0]?.color).toBe(logNamespacePalette(apexLog!)('pkg')); + }); +}); diff --git a/log-viewer/src/components/__tests__/fixtures/logEvents.ts b/log-viewer/src/components/__tests__/fixtures/logEvents.ts index ff153548e..2a8a961e7 100644 --- a/log-viewer/src/components/__tests__/fixtures/logEvents.ts +++ b/log-viewer/src/components/__tests__/fixtures/logEvents.ts @@ -3,15 +3,31 @@ */ import type { ApexLog, LogEvent } from 'apex-log-parser'; -/** Only the fields the namespace walk reads. */ +interface Count { + self: number; + total: number; +} + +/** Only the fields the namespace walk and the window index read. */ export interface FakeEvent { eventIndex: number; namespace: string; + category: string; duration: { total: number; self: number }; + /** Laid out by {@link log}, which is what puts the tree in time. */ + timestamp: number; + exitStamp: number; + soqlCount: Count; + soqlRowCount: Count; + dmlCount: Count; + dmlRowCount: Count; + soslCount: Count; children: FakeEvent[]; parent?: FakeEvent; } +const count = (): Count => ({ self: 0, total: 0 }); + const registry: FakeEvent[] = []; /** @@ -22,10 +38,18 @@ export function ev(namespace: string, self: number, children: FakeEvent[] = []): const event: FakeEvent = { eventIndex: registry.length, namespace, + category: 'Apex', duration: { total: self + children.reduce((sum, child) => sum + child.duration.total, 0), self, }, + timestamp: 0, + exitStamp: 0, + soqlCount: count(), + soqlRowCount: count(), + dmlCount: count(), + dmlRowCount: count(), + soslCount: count(), children, }; for (const child of children) { @@ -46,5 +70,25 @@ export function eventByIndex(index: number): FakeEvent | null { export const roots = (events: FakeEvent[]) => events as unknown as LogEvent[]; -export const log = (children: FakeEvent[], namespaces: string[] = []) => - ({ children, namespaces }) as unknown as ApexLog; +/** + * Lays `event` out from `start` and returns where it ends: its own time first, + * then its children back to back. A windowed read needs real timestamps, and + * this keeps each event's own time exactly its `duration.self`. + */ +function layOut(event: FakeEvent, start: number): number { + event.timestamp = start; + let cursor = start + event.duration.self; + for (const child of event.children) { + cursor = layOut(child, cursor); + } + event.exitStamp = cursor; + return cursor; +} + +export const log = (children: FakeEvent[], namespaces: string[] = []) => { + let cursor = 0; + for (const child of children) { + cursor = layOut(child, cursor); + } + return { children, namespaces, timestamp: 0, exitStamp: cursor } as unknown as ApexLog; +}; diff --git a/log-viewer/src/components/__tests__/logOverviewMetrics.test.ts b/log-viewer/src/components/__tests__/logOverviewMetrics.test.ts index c288370ff..da74e74b2 100644 --- a/log-viewer/src/components/__tests__/logOverviewMetrics.test.ts +++ b/log-viewer/src/components/__tests__/logOverviewMetrics.test.ts @@ -3,6 +3,7 @@ */ import { describe, expect, it } from '@jest/globals'; +import type { WindowCounts } from '../../core/log/windowStats.js'; import { GOVERNOR_METRICS, limitTotals, seriesGauges } from '../logOverviewMetrics.js'; import { emptyLimits, seriesEvent, timeSeries } from './limitsTestUtils.js'; @@ -110,3 +111,79 @@ describe('seriesGauges', () => { expect(seriesGauges(timeSeries([]))).toEqual([]); }); }); + +describe('seriesGauges for a window', () => { + const none = { + soqlCount: 0, + soqlRowCount: 0, + dmlCount: 0, + dmlRowCount: 0, + soslCount: 0, + }; + + /** The log reports these statements one by one, so they are windowable. */ + const reported = { ...none, soqlCount: 9, dmlCount: 4 }; + const windowOf = (counts: WindowCounts, logCounts: WindowCounts = reported) => ({ + counts, + logCounts, + }); + + const series = () => + timeSeries([ + seriesEvent(1_000, { + cpuTime: { used: 15_163, limit: 10_000 }, + soqlQueries: { used: 9, limit: 100 }, + dmlStatements: { used: 4, limit: 150 }, + heapSize: { used: 219_591, limit: 6_000_000 }, + }), + ]); + + // Rows must not appear, vanish or reorder as the viewport moves. + it('shows the same metrics in the same order as the whole log', () => { + const whole = seriesGauges(series()).map((gauge) => gauge.label); + + expect(seriesGauges(series(), windowOf(none)).map((gauge) => gauge.label)).toEqual(whole); + }); + + it('reads a metric the window did not use as zero, not as missing', () => { + const gauges = seriesGauges(series(), windowOf(none)); + + expect(gauges.find((gauge) => gauge.label === 'SOQL')).toMatchObject({ + used: 0, + found: 0, + limit: 100, + }); + }); + + it('reads what the window ran', () => { + const gauges = seriesGauges(series(), windowOf({ ...none, soqlCount: 6, dmlCount: 2 })); + + expect(gauges.find((gauge) => gauge.label === 'SOQL')).toMatchObject({ used: 6, limit: 100 }); + expect(gauges.find((gauge) => gauge.label === 'DML')).toMatchObject({ used: 2, limit: 150 }); + }); + + // Both are cumulative readings the log reports only in total. + it('keeps CPU time and heap whole-log, and says so', () => { + const gauges = seriesGauges(series(), windowOf(none)); + + expect(gauges.find((gauge) => gauge.label === 'CPU Time')).toMatchObject({ + used: 15_163, + limit: 10_000, + wholeLog: true, + }); + expect(gauges.find((gauge) => gauge.label === 'Heap Size')).toMatchObject({ wholeLog: true }); + expect(gauges.find((gauge) => gauge.label === 'SOQL')?.wholeLog).toBeUndefined(); + }); + + // The whole-log figure then came from the cumulative block, which no window + // can cut. Reading 0 would say no statements ran. + it('keeps a counter the log never reported one by one whole-log', () => { + const gauges = seriesGauges(series(), windowOf(none, none)); + + expect(gauges.find((gauge) => gauge.label === 'SOQL')).toMatchObject({ + used: 9, + limit: 100, + wholeLog: true, + }); + }); +}); diff --git a/log-viewer/src/components/categoryTime.ts b/log-viewer/src/components/categoryTime.ts index 4b3442df6..9ff9f29f6 100644 --- a/log-viewer/src/components/categoryTime.ts +++ b/log-viewer/src/components/categoryTime.ts @@ -61,20 +61,27 @@ export function categorySelfTimes(root: ApexLog): CategoryTime[] { while (stack.length) { const event = stack.pop()!; // non-empty: the loop condition just checked - const category = categoryName(event.category); - totals.set(category, (totals.get(category) ?? 0) + event.duration.self); + totals.set(event.category, (totals.get(event.category) ?? 0) + event.duration.self); for (const child of event.children) { stack.push(child); } } - const slices = [...totals] - .filter(([, selfTime]) => selfTime > 0) - .map(([category, selfTime]) => ({ category, selfTime })) - .sort((a, b) => b.selfTime - a.selfTime); + const slices = toCategoryTimes(totals); selfTimesCache.set(root, slices); return slices; } +/** + * Self time per raw category, named and ranked for display: empty buckets go, + * an uncategorised event lands in {@link OTHER_CATEGORY}, largest first. + */ +export function toCategoryTimes(totals: ReadonlyMap