Log figure render count and start/end

[droumis]

This branch, created by @ianthomas23 (and now rebased onto branch-3.4), addresses the need for a console log render count to measure the latency of display and interaction updates. It includes the figure id, count, and state (start, end).

As this is likely not ideal to have printed for every user, the next step is to limit the conditions under which it is emitted. I could use feedback/guidance on achieving this, maybe with an environment variable like 'BOKEH_RENDER_COUNT'.

• issues: fixes [FEATURE] Assist in measuring display and interaction latency #13502
• [ ] tests added / passed N/A
• [ ] release document entry (if new feature or API change) N/A

UPDATE: I've put the console messages behind Bokeh log level "trace" as suggested.

[bryevdv]

This should use logger from core/logging and probably at level "trace" e.g. like

bokeh/bokehjs/src/lib/models/canvas/canvas.ts

Line 52 in d620157

logger.trace("WebGL is supported, but not the required extensions")

then BOKEH_LOG_LEVEL=trace can be used to enable.

Edit: I guess the risk here is that trace may already spit out voluminous output and maybe that's hard to deal with or even distorts performance all on its own. But let's start with this approach and see how it goes.

[codecov]

Codecov Report

All modified and coverable lines are covered by tests ✅

Comparison is base (a8fb295) 92.54% compared to head (8886ac7) 92.54%.
Report is 10 commits behind head on branch-3.4.

Additional details and impacted files

@@              Coverage Diff               @@
##           branch-3.4   #13503      +/-   ##
==============================================
- Coverage       92.54%   92.54%   -0.01%     
==============================================
  Files             323      323              
  Lines           20493    20493              
==============================================
- Hits            18966    18965       -1     
- Misses           1527     1528       +1     

[mattpap]

To note, a lot of information can be extracted from browsers' devtools, e.g.:

Such profile can be saved as JSON and later processed and evaluated. They can also be collected when running bokehjs' tests, because we use devtools' API there, which exposes all of the features available in the UI. We already use this API to collect general metrics regarding memory usage, DOM node and event listener count, etc., which can be then visualized similarly to test reports (http://localhost:5777/integration/metrics).

[bryevdv]

Such profile can be saved as JSON and later processed and evaluated.

Is the format stable across browser versions? Or even browsers? Resolving this with docs updates and some possibly some helper scripts under scripts sounds ideal, but I'm also not sure what the actual requirements are or whether the devtools logs would be sufficient for them. cc @droumis @philippjfr

[droumis]

Thanks for the patience. To provide more context about what we are trying to achieve:

Summary

We are developing several workflows (HoloViz and Bokeh code), each demonstrating how to build a certain type of visualization relevant to biomedical research (e.g. Bokeh's subcoordinates_zoom EEG example is inspired by one of the workflows)

For each type of workflow, we need to benchmark the latency of the initial display, as well as the latency of the updated display following an interaction event (e.g. zoom), as a function of dataset size and backend (canvas, WebGL).

• e.g. from here.

Importantly, we need to be able to compare the latency measurements for the same workflow, given different versions of the workflow code (comparing script version A vs B) or changes to the underlying libraries (comparing branch A vs B).

• e.g.

Less importantly, but in the longer term, we would like to have the workflow benchmarks used as an automated test for candidate library releases (ASV style).

---

What has been done so far?

Ian created this PR's log_render_count branch to emit figure id, count, and state (start, end) to the browser console. He also set up a system with ASV and Playwright to run repeated and parameterized (data size and backend) displays and interactions from simple HoloViz/Bokeh code snippets and use the messages from the console to measure latency.

PRs:

• initial benchmarking framework using Bokeh snippet
• adding benchmarking for zoom using Bokeh snippet
• adding a Panel and HoloViews (Bokeh backend) snippet

[droumis]

Aside from the unrelated CI issue (which is failing on all PRs right now), this should be ready for review @mattpap or @bryevdv. thanks!

[bryevdv]

I don't necessarily have any problem with adding this behind trace if it is blocking downstream work, but I thought the plan was to first investigate whether the necessary information could be obtained with built-in browser dev tools. Was there any result or conclusion reached regarding that that I missed?

[droumis]

Hi @bryevdv, since the approach we've constructed utilizes ASV and Playwright to listen for these console messages on the fly and execute parameterized runs with different backends and data amounts interleaved, it would indeed unblock our progress if this PR could be merged and included in the upcoming release, as long as there's no harm in the implementation. We don't have the availability to dive into the devtools approach anytime soon and evaluate its sufficiency, but maybe in the future it might be reasonable thing to do it as a cross-validation of measurements. I think this is a pretty unique case - wanting to get the timing of the paint - so I don't anticipate that this would lead to many more trace-based measurement PRs.

[mattpap]

I don't mind merging this. console.trace() doesn't affect performance when trace-level logging isn't enabled, so this only affects bundle size. I meant to add support for stripping debug code (like recently infamous assert_debug()) from bundles for a long while, so eventually this also won't be an issue as well.

[bryevdv]

LGTM with @mattpap's one suggested change

[droumis]

Thanks! The suggested change is pushed

[droumis]

this can be merged now

[github-actions]

This pull request has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.