New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

High (probably unnecessary) CPU load due to is_valid calls. #7977

Closed
thomasetter opened this Issue Jun 8, 2018 · 12 comments

Comments

Projects
None yet
3 participants
@thomasetter
Copy link

thomasetter commented Jun 8, 2018

python 3.6 on linux 4.16, tested with the latest (as of 2018-06-07) bokeh dev version and with 0.12.16

This example exhibits bokeh slowness and high CPU usage:

from bokeh.plotting import figure
from bokeh.layouts import layout
from bokeh.models import Div, CustomJS
from bokeh.io import curdoc
import os

# prepare some data
x = range(0,100)
y = range(0,100)
os.environ['BOKEH_VALIDATE_DOC'] = "0" # This does nothing for this example

def create_plot():
    # create a new plot with a title and axis labels
    p = figure(title="simple line example", x_axis_label='x', y_axis_label='y')

    # add a line renderer with legend and line thickness
    p.line(x, y, legend="Temp.", line_width=2)
    return p

plots = []

for i in range(0,50):
    plots.append(create_plot())

l = layout(plots)

curdoc().add_root(l)

The high CPU usage is partially in the browser, but that only lasts a few seconds, however in the server, it uses 100% CPU for up to 20 seconds (on an 8-th gen Intel CPU) even after the page seems fully rendered in the browser.

bokeh serve --show example.py

Flamechart

Most of the time seems to be spent doing validations with self.validate() which throws an expensive (there is a lot of string concatenating/formatting) error the message of which is then ignored in is_valid.

I am not sure whether is_valid should not be called here or if it should be cheaper to call.

Setting BOKEH_VALIDATE_DOC to false does not seem to help as it hits no code path which checks that variable. It is checked here:

$ git grep 'perform_document_validation'
bokeh/application/application.py:        if settings.perform_document_validation():
bokeh/embed/notebook.py:    if settings.perform_document_validation():
bokeh/embed/standalone.py:    if settings.perform_document_validation():
bokeh/settings.py:    def perform_document_validation(self, default=True):

The flamechart has been created using pyflame:
sudo pyflame -s 20 -p {PID} -o prof.txt

and FlameGraph:
flamegraph.pl prof.txt > _bokeh_flame.html

@bryevdv

This comment has been minimized.

Copy link
Member

bryevdv commented Jun 8, 2018

The exception is not ignored, it is converted into a Boolean value that signals whether validation succeeded or not. If there is some validator that is doing too much work we just need to figure out what it is.

In passing, I will also say that 50 plots on a page is not a good use scenario for Bokeh, given the its tradeoff choices, and if that is what you need you may want to look at other tools.

@bryevdv

This comment has been minimized.

Copy link
Member

bryevdv commented Jun 8, 2018

Putting a print there does show lots of exceptions being raised. The fact that they are not escaping leads me to believe that they are probably due to checking potential values against Either properties -- if the first type fails to validate, then Bokeh moves on to try the next type. But that's not an error, unless all the types fail, so normally the exceptions do not escape. If what is taking a long time is the string creation, and I am right in the supposition above, then what me might be able to do is have a flag to suppress the detailed error string generation that Either could use to avoid the cost when validation is happening 'internally'

cc @mattpap

@mattpap

This comment has been minimized.

Copy link
Contributor

mattpap commented Jun 8, 2018

The current approach is indeed inefficient. Though the numbers are a little different for me: validations takes 3 seconds and rendering 13 seconds. Still, 3 seconds for validation way too much.

@bryevdv

This comment has been minimized.

Copy link
Member

bryevdv commented Jun 8, 2018

I'm testing out the approach I desired above right now

@bryevdv

This comment has been minimized.

Copy link
Member

bryevdv commented Jun 8, 2018

@thomasetter can you try things out with #7980 and report back? Things seem qualitatively better to me but you have immediate experience with some useful quantitative tools that are not available on OSX, and that would be valuable.

@bryevdv

This comment has been minimized.

Copy link
Member

bryevdv commented Jun 8, 2018

I've also just realized BOKEH_VALIDATE_DOC controls something else and entirely unrelated (whole document integrity checks, vs fine grained type checks like these)

@thomasetter

This comment has been minimized.

Copy link
Author

thomasetter commented Jun 9, 2018

Thanks for the quick fix!
I have tried it with #7980 and seems to roughly half the time spent in is_valid, therfore saving 10% CPU time 👍

Looking at the flamegraph for other opportunities, I also found that bokeh/core/property/bases.py:prepare_value:282 uses another 10% importing a module in a function.
When I moved it to the top of the file, it disappeared from the graph (I am not sure whether that would break anything though).

Also this in-function import consumes >.5% CPU time.

I am not really familiar with the trade-offs of having imports at the top of the file vs in functions, so it would help me to have some comment outlining why the in-function import is better.
I found this stack overflow thread, where the consensus is that imports should generally be put at the top of the file according to PEP 8.

@bryevdv

This comment has been minimized.

Copy link
Member

bryevdv commented Jun 9, 2018

@thomasetter thanks for the quick feedback and detailed report, we will definitely get this merged before the next release. Nearly all of Bokeh's imports are at the top level, but sometimes there is a technical reason why this is not possible (i.e a circular import dependency maybe) I will take a look at the prepare_value case more closely though.

@bryevdv

This comment has been minimized.

Copy link
Member

bryevdv commented Jun 9, 2018

Actually I think in the past this probably was a circular dependency. Properties can form object graphs with HasProps objects that have properties that themselves refer to other HasProps objects. That a situation that can lead to circular module imports without care. But there was a large cleanup and refactor of the properties system maybe a year ago, and I think that it's no longer the case, has_props.py only depends on the property descriptors module which is very ight, and not on properties themselves. I will move import up to the top now, and get a dev build out.

@bryevdv

This comment has been minimized.

Copy link
Member

bryevdv commented Jun 9, 2018

@thomasetter I have mode those changes and also moved a few more function imports I found elsewhere. I also changed is_valid to just always suppress details. After closer inspection I realized this function is precisely and only used for internal type checking, and no exception escapes it, so to this should be cleaner at the call sites.

Can you test one more time with the updated PR? Then we will get this merged

@bryevdv bryevdv added type: task and removed type: discussion labels Jun 9, 2018

@thomasetter

This comment has been minimized.

Copy link
Author

thomasetter commented Jun 10, 2018

Thanks, tested #7980 again and it looks good, the is_valid CPU time is now ~10% vs ~20% before and the expensive imports do not appear anymore.

Updated Flamegraph

Another improvement is also that the Flame graph is much nicer to read now which will make future optimizations easier.

@bryevdv

This comment has been minimized.

Copy link
Member

bryevdv commented Jun 10, 2018

@thomasetter brilliant, I've added some more extensive tests to maintain that we do not compute these expensive messages when they are not necessary. I will merge the PR when green. I'd just like to thank you for your detailed report and eager engagement, I wish all issues/PRs went like this.

@bryevdv bryevdv added this to the 0.13.0 milestone Jun 10, 2018

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment