From 356cf008ced9551de625910ab227fe61d8df2f55 Mon Sep 17 00:00:00 2001
From: Alexander Rose <alexander.rose@weirdbyte.de>
Date: Sat, 4 Feb 2023 19:25:08 -0800
Subject: [PATCH] add consoleStats, improve timer
---
src/apps/viewer/app.ts | 4 +-
src/examples/alpha-orbitals/index.ts | 5 +-
src/mol-canvas3d/canvas3d.ts | 12 ++-
src/mol-canvas3d/passes/pick.ts | 2 +-
src/mol-gl/webgl/context.ts | 10 +-
src/mol-gl/webgl/render-item.ts | 8 +-
src/mol-gl/webgl/timer.ts | 148 ++++++++++++++++++++++++---
src/mol-util/debug.ts | 22 +++-
8 files changed, 184 insertions(+), 27 deletions(-)
diff --git a/src/apps/viewer/app.ts b/src/apps/viewer/app.ts
index c6a531763..47656082c 100644
--- a/src/apps/viewer/app.ts
+++ b/src/apps/viewer/app.ts
@@ -1,5 +1,5 @@
/**
- * Copyright (c) 2018-2022 mol* contributors, licensed under MIT, See LICENSE file for more info.
+ * Copyright (c) 2018-2023 mol* contributors, licensed under MIT, See LICENSE file for more info.
*
* @author David Sehnal <david.sehnal@gmail.com>
* @author Alexander Rose <alexander.rose@weirdbyte.de>
@@ -50,7 +50,7 @@ import { SaccharideCompIdMapType } from '../../mol-model/structure/structure/car
import { Backgrounds } from '../../extensions/backgrounds';
export { PLUGIN_VERSION as version } from '../../mol-plugin/version';
-export { setDebugMode, setProductionMode, setTimingMode } from '../../mol-util/debug';
+export { setDebugMode, setProductionMode, setTimingMode, consoleStats } from '../../mol-util/debug';
const CustomFormats = [
['g3d', G3dProvider] as const
diff --git a/src/examples/alpha-orbitals/index.ts b/src/examples/alpha-orbitals/index.ts
index cf463bfee..05c52c4eb 100644
--- a/src/examples/alpha-orbitals/index.ts
+++ b/src/examples/alpha-orbitals/index.ts
@@ -25,7 +25,7 @@ import { DemoMoleculeSDF, DemoOrbitals } from './example-data';
import './index.html';
require('mol-plugin-ui/skin/light.scss');
-import { setDebugMode, setTimingMode } from '../../mol-util/debug';
+import { setDebugMode, setTimingMode, consoleStats } from '../../mol-util/debug';
interface DemoInput {
moleculeSdf: string,
@@ -222,4 +222,5 @@ export class AlphaOrbitalsExample {
(window as any).AlphaOrbitalsExample = new AlphaOrbitalsExample();
(window as any).AlphaOrbitalsExample.setDebugMode = setDebugMode;
-(window as any).AlphaOrbitalsExample.setTimingMode = setTimingMode;
\ No newline at end of file
+(window as any).AlphaOrbitalsExample.setTimingMode = setTimingMode;
+(window as any).AlphaOrbitalsExample.consoleStats = consoleStats;
\ No newline at end of file
diff --git a/src/mol-canvas3d/canvas3d.ts b/src/mol-canvas3d/canvas3d.ts
index b65f42eb7..969831e70 100644
--- a/src/mol-canvas3d/canvas3d.ts
+++ b/src/mol-canvas3d/canvas3d.ts
@@ -1,5 +1,5 @@
/**
- * Copyright (c) 2018-2022 mol* contributors, licensed under MIT, See LICENSE file for more info.
+ * Copyright (c) 2018-2023 mol* contributors, licensed under MIT, See LICENSE file for more info.
*
* @author Alexander Rose <alexander.rose@weirdbyte.de>
* @author David Sehnal <david.sehnal@gmail.com>
@@ -31,7 +31,7 @@ import { PickData } from './passes/pick';
import { PickHelper } from './passes/pick';
import { ImagePass, ImageProps } from './passes/image';
import { Sphere3D } from '../mol-math/geometry';
-import { isDebugMode, isTimingMode } from '../mol-util/debug';
+import { addConsoleStatsProvider, isDebugMode, isTimingMode, removeConsoleStatsProvider } from '../mol-util/debug';
import { CameraHelperParams } from './helper/camera-helper';
import { produce } from 'immer';
import { HandleHelperParams } from './helper/handle-helper';
@@ -440,7 +440,7 @@ namespace Canvas3D {
cam = stereoCamera;
}
- if (isTimingMode) webgl.timer.mark('Canvas3D.render');
+ if (isTimingMode) webgl.timer.mark('Canvas3D.render', true);
const ctx = { renderer, camera: cam, scene, helper };
if (MultiSamplePass.isEnabled(p.multiSample)) {
const forceOn = !cameraChanged && markingUpdated && !controls.isAnimating;
@@ -623,6 +623,8 @@ namespace Canvas3D {
attribute: `${(attribute / 1024 / 1024).toFixed(3)} MiB`,
elements: `${(elements / 1024 / 1024).toFixed(3)} MiB`,
});
+
+ console.log(webgl.timer.formatedStats());
}
function add(repr: Representation.Any) {
@@ -728,6 +730,8 @@ namespace Canvas3D {
resized.next(+new Date());
}
+ addConsoleStatsProvider(consoleStats);
+
return {
webgl,
@@ -905,6 +909,8 @@ namespace Canvas3D {
controls.dispose();
renderer.dispose();
interactionHelper.dispose();
+
+ removeConsoleStatsProvider(consoleStats);
}
};
diff --git a/src/mol-canvas3d/passes/pick.ts b/src/mol-canvas3d/passes/pick.ts
index 83199e143..8df182f66 100644
--- a/src/mol-canvas3d/passes/pick.ts
+++ b/src/mol-canvas3d/passes/pick.ts
@@ -291,7 +291,7 @@ export class PickHelper {
}
private render(camera: Camera | StereoCamera) {
- if (isTimingMode) this.webgl.timer.mark('PickHelper.render');
+ if (isTimingMode) this.webgl.timer.mark('PickHelper.render', true);
const { pickX, pickY, pickWidth, pickHeight, halfPickWidth } = this;
const { renderer, scene, helper } = this;
diff --git a/src/mol-gl/webgl/context.ts b/src/mol-gl/webgl/context.ts
index c638f03fb..83d78ff21 100644
--- a/src/mol-gl/webgl/context.ts
+++ b/src/mol-gl/webgl/context.ts
@@ -155,7 +155,7 @@ function getDrawingBufferPixelData(gl: GLRenderingContext, state: WebGLState) {
//
function createStats() {
- return {
+ const stats = {
resourceCounts: {
attribute: 0,
elements: 0,
@@ -171,7 +171,13 @@ function createStats() {
drawCount: 0,
instanceCount: 0,
instancedDrawCount: 0,
+
+ calls: {
+ drawInstanced: 0,
+ counts: 0,
+ },
};
+ return stats;
}
export type WebGLStats = ReturnType<typeof createStats>
@@ -224,7 +230,7 @@ export function createContext(gl: GLRenderingContext, props: Partial<{ pixelScal
const state = createState(gl);
const stats = createStats();
const resources = createResources(gl, state, stats, extensions);
- const timer = createTimer(gl, extensions);
+ const timer = createTimer(gl, extensions, stats);
const parameters = {
maxTextureSize: gl.getParameter(gl.MAX_TEXTURE_SIZE) as number,
diff --git a/src/mol-gl/webgl/render-item.ts b/src/mol-gl/webgl/render-item.ts
index 47d62df93..b3d74edc8 100644
--- a/src/mol-gl/webgl/render-item.ts
+++ b/src/mol-gl/webgl/render-item.ts
@@ -1,5 +1,5 @@
/**
- * Copyright (c) 2018-2022 mol* contributors, licensed under MIT, See LICENSE file for more info.
+ * Copyright (c) 2018-2023 mol* contributors, licensed under MIT, See LICENSE file for more info.
*
* @author Alexander Rose <alexander.rose@weirdbyte.de>
* @author Gianluca Tomasello <giagitom@gmail.com>
@@ -15,7 +15,7 @@ import { idFactory } from '../../mol-util/id-factory';
import { ValueCell } from '../../mol-util';
import { TextureImage, TextureVolume } from '../../mol-gl/renderable/util';
import { checkFramebufferStatus } from './framebuffer';
-import { isDebugMode } from '../../mol-util/debug';
+import { isDebugMode, isTimingMode } from '../../mol-util/debug';
import { VertexArray } from './vertex-array';
import { fillSerial } from '../../mol-util/array';
import { deepClone } from '../../mol-util/object';
@@ -212,6 +212,10 @@ export function createRenderItem<T extends string>(ctx: WebGLContext, drawMode:
} else {
instancedArrays.drawArraysInstanced(glDrawMode, 0, drawCount, instanceCount);
}
+ if (isTimingMode) {
+ stats.calls.drawInstanced += 1;
+ stats.calls.counts += instanceCount;
+ }
if (isDebugMode) {
try {
checkError(ctx.gl);
diff --git a/src/mol-gl/webgl/timer.ts b/src/mol-gl/webgl/timer.ts
index 2479455bf..9678ddf07 100644
--- a/src/mol-gl/webgl/timer.ts
+++ b/src/mol-gl/webgl/timer.ts
@@ -1,16 +1,54 @@
/**
- * Copyright (c) 2022 mol* contributors, licensed under MIT, See LICENSE file for more info.
+ * Copyright (c) 2022-2023 mol* contributors, licensed under MIT, See LICENSE file for more info.
*
* @author Alexander Rose <alexander.rose@weirdbyte.de>
*/
+import { now } from '../../mol-util/now';
import { GLRenderingContext } from './compat';
+import { WebGLStats } from './context';
import { WebGLExtensions } from './extensions';
+function movingAverage(avg: number, sample: number, count: number) {
+ avg -= avg / count;
+ avg += sample / count;
+ return avg;
+}
+
+class MovingAverage {
+ private readonly avgs = new Map<string, number>();
+
+ add(label: string, sample: number) {
+ let avg = this.avgs.get(label) || sample;
+ avg = movingAverage(avg, sample, this.count);
+ this.avgs.set(label, avg);
+ return avg;
+ }
+
+ get(label: string) {
+ return this.avgs.get(label);
+ }
+
+ stats() {
+ return Object.fromEntries(this.avgs.entries());
+ }
+
+ constructor(private count: number) { }
+}
+
+function clearStatsCalls(stats: WebGLStats) {
+ stats.calls.drawInstanced = 0;
+ stats.calls.counts = 0;
+}
+
export type TimerResult = {
readonly label: string
- readonly timeElapsed: number
+ readonly gpuElapsed: number
+ readonly gpuAvg: number
+ readonly cpuElapsed: number
+ readonly cpuAvg: number
readonly children: TimerResult[]
+ readonly calls?: Calls
}
function getQuery(extensions: WebGLExtensions) {
@@ -20,24 +58,45 @@ function getQuery(extensions: WebGLExtensions) {
export type WebGLTimer = {
/** Check with GPU for finished timers. */
resolve: () => TimerResult[]
- mark: (label: string) => void
+ mark: (label: string, captureCalls?: boolean) => void
markEnd: (label: string) => void
+ stats: () => { gpu: Record<string, number>, cpu: Record<string, number> }
+ formatedStats: () => Record<string, string>
clear: () => void
destroy: () => void
}
-type Measure = { label: string, queries: WebGLQuery[], children: Measure[], root: boolean, timeElapsed?: number };
+type Calls = {
+ drawInstanced: number,
+ counts: number,
+}
+
+type Measure = {
+ label: string,
+ queries: WebGLQuery[],
+ children: Measure[],
+ root: boolean,
+ cpu: { start: number, end: number },
+ captureCalls: boolean,
+ timeElapsed?: number,
+ calls?: Calls,
+};
+
type QueryResult = { timeElapsed?: number, refCount: number };
-export function createTimer(gl: GLRenderingContext, extensions: WebGLExtensions): WebGLTimer {
+export function createTimer(gl: GLRenderingContext, extensions: WebGLExtensions, stats: WebGLStats, options?: { avgCount: number }): WebGLTimer {
const dtq = extensions.disjointTimerQuery;
+ const avgCount = options?.avgCount ?? 30;
const queries = new Map<WebGLQuery, QueryResult>();
const pending = new Map<string, Measure>();
const stack: Measure[] = [];
+ const gpuAvgs = new MovingAverage(avgCount);
+ const cpuAvgs = new MovingAverage(avgCount);
let measures: Measure[] = [];
let current: WebGLQuery | null = null;
+ let capturingCalls = false;
const clear = () => {
if (!dtq) return;
@@ -100,17 +159,32 @@ export function createTimer(gl: GLRenderingContext, extensions: WebGLExtensions)
const children: TimerResult[] = [];
const add = (measures: Measure[], children: TimerResult[]) => {
for (const measure of measures) {
+ const timeElapsed = measure.timeElapsed!;
+ const cpuElapsed = measure.cpu.end - measure.cpu.start;
const result: TimerResult = {
label: measure.label,
- timeElapsed: measure.timeElapsed!,
- children: []
+ gpuElapsed: timeElapsed,
+ gpuAvg: gpuAvgs.add(measure.label, timeElapsed),
+ cpuElapsed,
+ cpuAvg: cpuAvgs.add(measure.label, cpuElapsed),
+ children: [],
+ calls: measure.calls,
};
children.push(result);
add(measure.children, result.children);
}
};
add(measure.children, children);
- results.push({ label: measure.label, timeElapsed, children });
+ const cpuElapsed = measure.cpu.end - measure.cpu.start;
+ results.push({
+ label: measure.label,
+ gpuElapsed: timeElapsed,
+ gpuAvg: gpuAvgs.add(measure.label, timeElapsed),
+ cpuElapsed,
+ cpuAvg: cpuAvgs.add(measure.label, cpuElapsed),
+ children,
+ calls: measure.calls,
+ });
}
} else {
unresolved.push(measure);
@@ -126,7 +200,7 @@ export function createTimer(gl: GLRenderingContext, extensions: WebGLExtensions)
return results;
},
- mark: (label: string) => {
+ mark: (label: string, captureCalls = false) => {
if (!dtq) return;
if (pending.has(label)) {
@@ -136,7 +210,14 @@ export function createTimer(gl: GLRenderingContext, extensions: WebGLExtensions)
if (current !== null) {
dtq.endQuery(dtq.TIME_ELAPSED);
}
- const measure: Measure = { label, queries: [], children: [], root: current === null };
+ const measure: Measure = {
+ label,
+ queries: [],
+ children: [],
+ root: current === null,
+ cpu: { start: now(), end: -1 },
+ captureCalls,
+ };
pending.set(label, measure);
if (stack.length) {
@@ -144,6 +225,14 @@ export function createTimer(gl: GLRenderingContext, extensions: WebGLExtensions)
}
stack.push(measure);
+ if (captureCalls) {
+ if (capturingCalls) {
+ throw new Error('Already capturing calls');
+ }
+ clearStatsCalls(stats);
+ capturingCalls = true;
+ }
+
add();
},
markEnd: (label: string) => {
@@ -160,6 +249,16 @@ export function createTimer(gl: GLRenderingContext, extensions: WebGLExtensions)
dtq.endQuery(dtq.TIME_ELAPSED);
pending.delete(label);
+
+ measure.cpu.end = now();
+ if (measure.captureCalls) {
+ measure.calls = {
+ drawInstanced: stats.calls.drawInstanced,
+ counts: stats.calls.counts,
+ };
+ capturingCalls = false;
+ }
+
measures.push(measure);
if (pending.size > 0) {
@@ -168,6 +267,23 @@ export function createTimer(gl: GLRenderingContext, extensions: WebGLExtensions)
current = null;
}
},
+ stats: () => {
+ return {
+ gpu: gpuAvgs.stats(),
+ cpu: cpuAvgs.stats(),
+ };
+ },
+ formatedStats: () => {
+ const stats: Record<string, string> = {};
+ const gpu = gpuAvgs.stats();
+ const cpu = cpuAvgs.stats();
+ for (const l of Object.keys(gpu)) {
+ const g = `${(gpu[l] / 1000 / 1000).toFixed(2)}`;
+ const c = `${cpu[l].toFixed(2)}`;
+ stats[l] = `${g} ms | CPU: ${c} ms`;
+ }
+ return stats;
+ },
clear,
destroy: () => {
clear();
@@ -176,15 +292,19 @@ export function createTimer(gl: GLRenderingContext, extensions: WebGLExtensions)
}
function formatTimerResult(result: TimerResult) {
- const timeElapsed = result.timeElapsed / 1000 / 1000;
- return `${result.label} ${timeElapsed.toFixed(2)}ms`;
+ const gpu = `${(result.gpuElapsed / 1000 / 1000).toFixed(2)}`;
+ const gpuAvg = `${(result.gpuAvg / 1000 / 1000).toFixed(2)}`;
+ const cpu = `${result.cpuElapsed.toFixed(2)}`;
+ const cpuAvg = `${result.cpuAvg.toFixed(2)}`;
+ return `${result.label} ${gpu} ms (avg. ${gpuAvg} ms) | CPU: ${cpu} ms (avg. ${cpuAvg} ms)`;
}
export function printTimerResults(results: TimerResult[]) {
- return results.map(r => {
+ results.map(r => {
const f = formatTimerResult(r);
- if (r.children.length) {
+ if (r.children.length || r.calls) {
console.groupCollapsed(f);
+ if (r.calls) console.log(r.calls);
printTimerResults(r.children);
console.groupEnd();
} else {
diff --git a/src/mol-util/debug.ts b/src/mol-util/debug.ts
index eb688aec3..c9d2cbffd 100644
--- a/src/mol-util/debug.ts
+++ b/src/mol-util/debug.ts
@@ -1,5 +1,5 @@
/**
- * Copyright (c) 2019-2020 mol* contributors, licensed under MIT, See LICENSE file for more info.
+ * Copyright (c) 2019-2023 mol* contributors, licensed under MIT, See LICENSE file for more info.
*
* @author Alexander Rose <alexander.rose@weirdbyte.de>
*/
@@ -48,3 +48,23 @@ export function setDebugMode(value?: boolean) {
export function setTimingMode(value?: boolean) {
if (typeof value !== 'undefined') isTimingMode = value;
}
+
+//
+
+type ConsoleStatsProvider = () => void
+const consoleStatsProviders: ConsoleStatsProvider[] = [];
+
+export function addConsoleStatsProvider(p: ConsoleStatsProvider) {
+ if (!consoleStatsProviders.includes(p)) consoleStatsProviders.push(p);
+}
+
+export function removeConsoleStatsProvider(p: ConsoleStatsProvider) {
+ const idx = consoleStatsProviders.indexOf(p);
+ if (idx !== -1) consoleStatsProviders.splice(idx, 1);
+}
+
+export function consoleStats() {
+ for (const p of consoleStatsProviders) {
+ p();
+ }
+}
--
GitLab