Merge pull request #710 from molstar/console-stats-timing

add consoleStats, improve timer

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

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;
+(window as any).AlphaOrbitalsExample.setTimingMode = setTimingMode;
+(window as any).AlphaOrbitalsExample.consoleStats = consoleStats;

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';
@@ -442,7 +442,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;
@@ -629,6 +629,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) {
@@ -734,6 +736,8 @@ namespace Canvas3D {
             resized.next(+new Date());
         }
 
+        addConsoleStatsProvider(consoleStats);
+
         return {
             webgl,
 
@@ -912,6 +916,8 @@ namespace Canvas3D {
                 controls.dispose();
                 renderer.dispose();
                 interactionHelper.dispose();
+
+                removeConsoleStatsProvider(consoleStats);
             }
         };
 

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;
 

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,

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);

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 {

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();
+    }
+}