Restore WebGL reveal timing diagnostics

This commit is contained in:
2026-06-10 08:09:02 +02:00
parent 10bf23b10b
commit 5a84923884
4 changed files with 157 additions and 20 deletions
+99 -14
View File
@@ -17,6 +17,7 @@ class BookPlaybackTimelineModule extends BaseModule {
this.activeSegment = null;
this.preparedSegments = new Map();
this.timelineDiagnostics = [];
this.benchmarkEntries = [];
this.ownsPageFlipCommit = true;
this.bindMethods([
@@ -29,6 +30,7 @@ class BookPlaybackTimelineModule extends BaseModule {
'createRevealDetail',
'requiresSpreadTransition',
'requiresRightPageFlipAfterReveal',
'getBlockRevealSides',
'waitForVisualCompletion',
'waitForRevealCommit',
'requestPageFlip',
@@ -37,6 +39,8 @@ class BookPlaybackTimelineModule extends BaseModule {
'getPageMetaForIndex',
'getVisibleSpreadIndex',
'isChoiceAwaitingPlayer',
'markBenchmark',
'timeStage',
'recordDiagnostic',
'getRuntimeState'
]);
@@ -48,13 +52,33 @@ class BookPlaybackTimelineModule extends BaseModule {
this.pageCache = this.getModule('webgl-page-cache');
this.playbackCoordinator = this.getModule('playback-coordinator');
this.sentenceQueue = this.getModule('sentence-queue');
this.addEventListener(document, 'webgl-book:page-reveal-start', (event) => {
this.markBenchmark('reveal-start', {
blockId: event.detail?.blockId ?? null
});
});
this.addEventListener(document, 'webgl-book:reveal-committed', (event) => {
this.markBenchmark('reveal-committed', {
blockId: event.detail?.blockIds?.[0] ?? null,
side: event.detail?.side || null,
pageFlipAfterReveal: event.detail?.pageFlipAfterReveal === true
});
});
this.addEventListener(document, 'webgl-book:page-flip-started', (event) => {
this.markBenchmark('flip-started', event.detail || {});
});
this.addEventListener(document, 'webgl-book:page-flip-finished', (event) => {
this.markBenchmark('flip-finished', event.detail || {});
});
window.BookPlaybackTimeline = this;
this.reportProgress(100, 'Book playback timeline ready');
return true;
}
async playSentence(sentence = {}) {
const segment = await this.prepareSentence(sentence, { immediate: true });
const segment = await this.timeStage('prepare-current', { blockId: sentence.blockId ?? null }, () => {
return this.prepareSentence(sentence, { immediate: true });
});
if (!segment) {
return this.playbackCoordinator?.play?.(sentence);
}
@@ -63,11 +87,11 @@ class BookPlaybackTimelineModule extends BaseModule {
this.recordDiagnostic('segment-play:start', segment);
if (this.requiresSpreadTransition(segment)) {
const flipped = await this.requestPageFlip(1, {
const flipped = await this.timeStage('preplay-flip', segment, () => this.requestPageFlip(1, {
reason: 'timeline-preplay-spread-transition',
targetSpread: segment.targetSpreadIndex,
force: true
});
}));
if (!flipped) {
this.pageCache?.recordProblem?.({
type: 'timeline-preplay-flip-failed',
@@ -77,10 +101,12 @@ class BookPlaybackTimelineModule extends BaseModule {
}
}
await this.activatePreparedSegment(segment, sentence);
await this.timeStage('activate', segment, () => this.activatePreparedSegment(segment, sentence));
const visualPromise = this.waitForVisualCompletion(segment);
const playbackPromise = this.playbackCoordinator?.play?.(sentence) || Promise.resolve();
const playbackPromise = this.timeStage('playback', segment, () => {
return this.playbackCoordinator?.play?.(sentence) || Promise.resolve();
});
await Promise.all([playbackPromise, visualPromise]);
this.recordDiagnostic('segment-play:end', segment);
@@ -94,7 +120,10 @@ class BookPlaybackTimelineModule extends BaseModule {
const existing = sentence.webglBookPresentation?.timelineSegment || this.preparedSegments.get(key);
if (existing && options.force !== true) return existing;
this.ensureAnimationTimings(sentence);
const segment = await this.createPreparedSegment(sentence, options);
const segment = await this.timeStage(options.immediate === true ? 'segment-prepare-immediate' : 'segment-prepare-lookahead', {
blockId: sentence.blockId,
id: sentence.id
}, () => this.createPreparedSegment(sentence, options));
if (!segment) return null;
this.preparedSegments.set(segment.key, segment);
sentence.webglBookPresentation = {
@@ -121,6 +150,7 @@ class BookPlaybackTimelineModule extends BaseModule {
const targetSpreadIndex = Math.max(0, Number(previewSpread.index || 0));
const currentSpreadIndex = this.getVisibleSpreadIndex();
const revealSides = this.getBlockRevealSides(previewSpread, sentence.blockId);
const segment = {
key: `${sentence.gameId || sentence.metadata?.gameId || 'game'}:${sentence.blockId}`,
id: sentence.id,
@@ -129,13 +159,14 @@ class BookPlaybackTimelineModule extends BaseModule {
previewSpread,
targetSpreadIndex,
currentSpreadIndex,
revealSides,
requiresPreFlip: targetSpreadIndex > currentSpreadIndex,
requiresRightFlip: this.requiresRightPageFlipAfterReveal(previewSpread),
requiresRightFlip: revealSides.includes('right') && this.requiresRightPageFlipAfterReveal(previewSpread),
preparedAt: performance.now(),
status: 'prepared'
};
await this.prewarmSegmentTextures(segment);
await this.timeStage('texture-prewarm', segment, () => this.prewarmSegmentTextures(segment));
if (options.immediate !== true) {
await new Promise(resolve => setTimeout(resolve, 0));
}
@@ -149,7 +180,9 @@ class BookPlaybackTimelineModule extends BaseModule {
});
segment.activeSpread = activeSpread || segment.previewSpread;
segment.targetSpreadIndex = Math.max(0, Number(segment.activeSpread?.index ?? segment.targetSpreadIndex ?? 0));
segment.requiresRightFlip = this.requiresRightPageFlipAfterReveal(segment.activeSpread || segment.previewSpread);
segment.revealSides = this.getBlockRevealSides(segment.activeSpread || segment.previewSpread, sentence.blockId);
segment.requiresRightFlip = segment.revealSides.includes('right')
&& this.requiresRightPageFlipAfterReveal(segment.activeSpread || segment.previewSpread);
const revealDetail = this.createRevealDetail(sentence, segment.activeSpread || segment.previewSpread, 'activate');
this.textureRenderer.prepareRevealBlock(revealDetail);
@@ -192,15 +225,27 @@ class BookPlaybackTimelineModule extends BaseModule {
return maxLine >= Math.max(1, Number(meta.linesPerPage || 25));
}
getBlockRevealSides(spread = {}, blockId = null) {
const id = String(blockId ?? '');
if (!id) return [];
return ['left', 'right'].filter((side) => {
const lines = Array.isArray(spread?.[side]) ? spread[side] : [];
return lines.some(line => String(line?.blockId ?? '') === id);
});
}
async waitForVisualCompletion(segment = {}) {
if (!segment.requiresRightFlip) return;
const committed = await this.waitForRevealCommit(segment);
if (!segment.requiresRightFlip || !Array.isArray(segment.revealSides) || !segment.revealSides.includes('right')) {
this.recordDiagnostic('visual-completion:no-right-flip-wait', segment);
return;
}
const committed = await this.timeStage('wait-right-reveal-commit', segment, () => this.waitForRevealCommit(segment));
if (!committed || this.isChoiceAwaitingPlayer()) return;
await this.requestPageFlip(1, {
await this.timeStage('right-page-flip', segment, () => this.requestPageFlip(1, {
reason: 'timeline-right-page-filled',
targetSpread: Math.max(0, Number(segment.targetSpreadIndex || this.getVisibleSpreadIndex()) + 1),
force: true
});
}));
}
waitForRevealCommit(segment = {}) {
@@ -350,18 +395,58 @@ class BookPlaybackTimelineModule extends BaseModule {
blockId: segment.blockId ?? null,
spreadIndex: segment.targetSpreadIndex ?? null,
status: segment.status || null,
revealSides: Array.isArray(segment.revealSides) ? segment.revealSides : [],
at: Math.round(performance.now())
});
while (this.timelineDiagnostics.length > 200) this.timelineDiagnostics.shift();
document.documentElement.dataset.webglBookTimeline = type;
}
markBenchmark(stage, detail = {}, startedAt = null) {
const now = performance.now();
const entry = {
stage,
blockId: detail.blockId ?? null,
spreadIndex: detail.targetSpreadIndex ?? detail.spreadIndex ?? detail.targetSpread ?? null,
durationMs: Number.isFinite(Number(startedAt)) ? Math.round((now - Number(startedAt)) * 100) / 100 : null,
at: Math.round(now),
detail: {
status: detail.status || null,
revealSides: Array.isArray(detail.revealSides) ? detail.revealSides : undefined,
reason: detail.reason || null,
side: detail.side || null,
pageFlipAfterReveal: detail.pageFlipAfterReveal === true
}
};
this.benchmarkEntries.push(entry);
while (this.benchmarkEntries.length > 240) this.benchmarkEntries.shift();
document.documentElement.dataset.webglBookBenchmark = JSON.stringify(this.benchmarkEntries.slice(-40));
return entry;
}
async timeStage(stage, detail = {}, callback = null) {
const startedAt = performance.now();
this.markBenchmark(`${stage}:start`, detail);
try {
const result = await callback?.();
this.markBenchmark(`${stage}:end`, detail, startedAt);
return result;
} catch (error) {
this.markBenchmark(`${stage}:error`, {
...detail,
reason: error?.message || String(error)
}, startedAt);
throw error;
}
}
getRuntimeState() {
return {
activeBlockId: this.activeSegment?.blockId ?? null,
preparedSegmentCount: this.preparedSegments.size,
ownsPageFlipCommit: this.ownsPageFlipCommit,
diagnostics: this.timelineDiagnostics.slice(-20)
diagnostics: this.timelineDiagnostics.slice(-20),
benchmark: this.benchmarkEntries.slice(-40)
};
}
}
+1 -1
View File
@@ -24,7 +24,7 @@ const ModuleState = {
ERROR: 'ERROR'
};
const MODULE_CACHE_BUSTER = '20260610-book-timeline-a';
const MODULE_CACHE_BUSTER = '20260610-book-timeline-b';
window.MODULE_CACHE_BUSTER = MODULE_CACHE_BUSTER;
/**
+51 -2
View File
@@ -4,7 +4,7 @@ import { RenderPass } from 'https://esm.sh/three@0.165.0/examples/jsm/postproces
import { SSAOPass } from 'https://esm.sh/three@0.165.0/examples/jsm/postprocessing/SSAOPass.js';
import { SMAAPass } from 'https://esm.sh/three@0.165.0/examples/jsm/postprocessing/SMAAPass.js';
import { OutputPass } from 'https://esm.sh/three@0.165.0/examples/jsm/postprocessing/OutputPass.js';
import { PROCEDURAL_BOOK, createProceduralBookModel, snapProceduralPageCount } from './procedural-book-model.js?v=20260610-book-timeline-a';
import { PROCEDURAL_BOOK, createProceduralBookModel, snapProceduralPageCount } from './procedural-book-model.js?v=20260610-book-timeline-b';
const canvas = document.getElementById('scene');
canvas.style.cursor = 'grab';
@@ -163,6 +163,7 @@ let fpsDisplay = null;
let fpsWindowStartedAt = performance.now();
let fpsWindowFrames = 0;
const lastFrameTiming = {};
const slowFrameLog = [];
const loaderTimings = {};
const pageTextureTimings = [];
@@ -610,6 +611,14 @@ window.BookLabDebug = {
lastFlipTexturePreflight
};
},
getBenchmarkState() {
return {
frameTiming: { ...lastFrameTiming },
slowFrames: slowFrameLog.slice(-20),
pageTextureTimings: pageTextureTimings.slice(-40),
timeline: window.BookPlaybackTimeline?.getRuntimeState?.()?.benchmark || []
};
},
projectPointerToPage(clientX, clientY) {
return projectPointerToPage(clientX, clientY);
},
@@ -2424,6 +2433,13 @@ function beginPageReveal(side, sourceCanvas, revealDetail = {}) {
shaderReady: Boolean(shader?.uniforms),
started: pageRevealState[side].startedAt != null
});
markPageTextureTiming('revealState:created', {
side,
blockIds: pageRevealState[side].blockIds,
started: pageRevealState[side].startedAt != null,
durationMs: pageRevealState[side].durationMs,
regionCount: Array.isArray(revealDetail.lineRects) ? revealDetail.lineRects.length : 0
});
markPageTextureTiming('revealUpload:end', { side });
}
@@ -2540,6 +2556,7 @@ function startPageRevealForBlock(blockId) {
const id = String(blockId ?? '');
if (!id) return;
if (!activeRevealBlockStarts.has(id)) activeRevealBlockStarts.set(id, performance.now());
let matchedSides = 0;
if (activeFlips.length > 0) {
pendingRevealStartBlockIds.add(id);
markPageTextureTiming('revealStart:deferred-for-flip', {
@@ -2552,11 +2569,18 @@ function startPageRevealForBlock(blockId) {
const state = pageRevealState[side];
if (!state || state.startedAt != null) return;
if (!state.blockIds.map(value => String(value)).includes(id)) return;
matchedSides += 1;
state.pendingStart = true;
state.startedAt = activeRevealBlockStarts.get(id) || performance.now();
const shader = getPageRevealShader(side);
if (shader?.uniforms?.bookRevealElapsedMs) shader.uniforms.bookRevealElapsedMs.value = 0;
});
markPageTextureTiming('revealStart:applied', {
blockId: id,
matchedSides,
hasLeftState: Boolean(pageRevealState.left),
hasRightState: Boolean(pageRevealState.right)
});
}
function fastForwardPageReveals(blockIds = []) {
@@ -4353,6 +4377,7 @@ function animate(now = performance.now()) {
const delta = Math.min(0.1, frameElapsedMs / 1000);
clock.getDelta();
const t = clock.elapsedTime;
const updateStartedAt = performance.now();
updateCameraRig(delta);
scene.traverse((object) => {
if (!object.userData?.light) return;
@@ -4382,10 +4407,15 @@ function animate(now = performance.now()) {
}
});
const hadActiveFlips = activeFlips.length > 0;
const flipStartedAt = performance.now();
updateActiveFlips(performance.now());
lastFrameTiming.flips = performance.now() - flipStartedAt;
if (hadActiveFlips) markStaticSceneBuffersDirty();
const revealStartedAt = performance.now();
updatePageRevealAnimations(now);
lastFrameTiming.reveal = performance.now() - revealStartedAt;
updateCandleShadowUniforms();
lastFrameTiming.update = performance.now() - updateStartedAt;
renderedFrameCount += 1;
const shadowStartedAt = performance.now();
updateBookShadowMaps();
@@ -4405,7 +4435,26 @@ function animate(now = performance.now()) {
renderer.render(scene, camera);
}
lastFrameTiming.render = performance.now() - renderStartedAt;
lastFrameTiming.total = lastFrameTiming.shadows + lastFrameTiming.reflection + lastFrameTiming.render;
lastFrameTiming.total = lastFrameTiming.update + lastFrameTiming.shadows + lastFrameTiming.reflection + lastFrameTiming.render;
if (frameElapsedMs > targetFrameDurationMs * 1.75 || lastFrameTiming.total > targetFrameDurationMs * 1.25) {
slowFrameLog.push({
at: Math.round(now),
frameElapsedMs: Math.round(frameElapsedMs * 100) / 100,
activeFlips: activeFlips.length,
revealActive: Boolean(pageRevealState.left || pageRevealState.right),
timings: {
update: Math.round(lastFrameTiming.update * 100) / 100,
flips: Math.round(lastFrameTiming.flips * 100) / 100,
reveal: Math.round(lastFrameTiming.reveal * 100) / 100,
shadows: Math.round(lastFrameTiming.shadows * 100) / 100,
reflection: Math.round(lastFrameTiming.reflection * 100) / 100,
render: Math.round(lastFrameTiming.render * 100) / 100,
total: Math.round(lastFrameTiming.total * 100) / 100
}
});
while (slowFrameLog.length > 80) slowFrameLog.shift();
document.documentElement.dataset.webglSlowFrames = JSON.stringify(slowFrameLog.slice(-20));
}
if (refreshStaticSceneBuffers && activeFlips.length === 0) {
staticSceneBuffersDirty = false;
}