Issues when updating plots from threads (possible race condition?)

Hi,

I use an embedded bokeh server to show plots, and use threads to asynchronously fetch data from remote database, and as data becomes available, update the plots shown to the user. I encountered weird issues that some plot updates seem never trigger, or sometime the glyph renders and then disappears.

Below is an example script reproduces the problem, the example draw a 2d grid of histograms, each initially has some data populated with xaxis.x_range set to [-1, 1], and when the remote data fetch completes (simulated with time.sleep), it updates the plot with new data and set new range. There are a few things that I noticed



1) Despite the order of draw_init => draw_update is guaranteed on the bokeh server side, the update to the plot seems to be out of order sometimes, so eventually the the plot was left with initial data or initial range.
  1. If some work is done and add_next_tick_callback is called before WS connection is established, then when those callbacks are executed, it is executed out of order, and after the WS connection is established, callbacks are executed in the order that was added.
  1. I tried to place locks on add_next_tick_callback, so threadpool synchronize on this call, but add_next_tick_callback seems to be very slow, and didn’t seem to help.
  1. If I added delay of say 5 seconds (change time.sleep(sleep_ts) to time.sleep(sleep_ts + 5)) to the “work”, then the plots usually render correctly. So is there requirement on certain events have to be fired after WS connection was established?
5) N = 2 usually works fine for me (a handleful of plots), but N = 6 consistently has issues. But probably it is because with a large number of random, it is more likely some "work" is done very fast.


Any help is much appreciated!

Thanks
Jack

import random
import time

from bokeh.io import curdoc
from bokeh.layouts import row, layout
from bokeh.models import Range1d, Label, ColumnDataSource, logging
from bokeh.plotting import figure
from concurrent.futures import ThreadPoolExecutor

logger = logging.getLogger(name)

class TestHistogram():

def __init__(self, doc, plot, plot_id):
    self._histogram = None
    self._doc = doc
    self._plot = plot
    self._plot_id = plot_id

def draw_init(self):
    self._caption_renderer = Label(
        text="Waiting",
        text_font_size="7pt",
        x=0,
        y=0,
        x_units='screen',
        y_units='screen',
        name="caption")

    self._plot.add_layout(self._caption_renderer, 'above')
    self._plot.x_range.start = -1
    self._plot.x_range.end = 1

    self._histogram = self._plot.quad(
        top="top",
        bottom="bottom",
        left="left",
        right="right",
        source=ColumnDataSource({
            "top": [1, 2, 3, 2, 1],
            "bottom": [0, 0, 0, 0, 0],
            "left": [0.2, 0.4, 0.6, 0.8, 1.0],
            "right": [0.3, 0.5, 0.7, 0.9, 1.1]
        }),
        name="histogram")

def do_work(self):
    logger.info("Start do_work: %s", self._plot_id)
    # blocking work, some slow, some fast
    sleep_ts = random.random() * 10

    # # Uncomment to simulate fast work that was done before WS connection
    # # was established
    # if sleep_ts < 1:
    #     sleep_ts /= 10
    time.sleep(sleep_ts)
    logger.info("Add callback: %s", self._plot_id)
    self._doc.add_next_tick_callback(self.draw_update)
    logger.info("End do_work: %s", self._plot_id)

def draw_update(self):
    logger.info("draw_update: %s", self._plot_id)
    # Update xaxis range of plot
    self._plot.x_range.start = -5
    self._plot.x_range.end = 5
    # Update histogram data
    self._histogram.data_source.data = {
        "top": [3, 2, 1, 2, 3],
        "bottom": [0, 0, 0, 0, 0],
        "left": [0.2, 0.4, 0.6, 0.8, 1.0],
        "right": [0.3, 0.5, 0.7, 0.9, 1.1]
    }
    self._caption_renderer.text = "DONE"

doc = curdoc()

N = 6

executor = ThreadPoolExecutor(max_workers=min(N * N, 50))

works =
plot_grid =
for i in range(N):
plots =
for j in range(N):
plot = figure(
title=“plot_” + str(i) + “" + str(j),
x_range=Range1d(),
plot_height=300,
plot_width=300)
hist = TestHistogram(doc, plot, str(i) + "
” + str(j))
hist.draw_init()
works.append(hist.do_work)

    plots.append(plot)
plot_grid.append(plots)

doc.add_root(row(layout(plot_grid), width=300 * N, height=300 * N))

for work in works:
executor.submit(work)


I think I have run into similar issues in the past.
Please be aware that Bokeh server application has its own (tornado) thread that may interfere your threads.

And I think that using time.sleep() on the main Bokeh thread can make it even worse.
The best practice is to do all plot updates in the update() function like this:

def update():
new_data = get_data_from_data_bucket()

do_update_plots(new_data)

curdoc().add_periodic_callback(update, 500)

``

You can have a second thread filling the “data bucket” that is being accessed in the main Bokeh thread => the update() function but don’t have one thread calling asynchronous functions on another thread unless you really know what you are doing.

···

On Wednesday, February 13, 2019 at 8:00:55 PM UTC+1, Jack Guo wrote:

Hi,


I use an embedded bokeh server to show plots, and use threads to asynchronously fetch data from remote database, and as data becomes available, update the plots shown to the user. I encountered weird issues that some plot updates seem never trigger, or sometime the glyph renders and then disappears.


Below is an example script reproduces the problem, the example draw a 2d grid of histograms, each initially has some data populated with xaxis.x_range set to [-1, 1], and when the remote data fetch completes (simulated with time.sleep), it updates the plot with new data and set new range. There are a few things that I noticed






1) Despite the order of draw_init => draw_update is guaranteed on the bokeh server side, the update to the plot seems to be out of order sometimes, so eventually the the plot was left with initial data or initial range.
  1. If some work is done and add_next_tick_callback is called before WS connection is established, then when those callbacks are executed, it is executed out of order, and after the WS connection is established, callbacks are executed in the order that was added.
  1. I tried to place locks on add_next_tick_callback, so threadpool synchronize on this call, but add_next_tick_callback seems to be very slow, and didn’t seem to help.
  1. If I added delay of say 5 seconds (change time.sleep(sleep_ts) to time.sleep(sleep_ts + 5)) to the “work”, then the plots usually render correctly. So is there requirement on certain events have to be fired after WS connection was established?
5) N = 2 usually works fine for me (a handleful of plots), but N = 6 consistently has issues. But probably it is because with a large number of random, it is more likely some "work" is done very fast.




Any help is much appreciated!


Thanks
Jack


import random
import time

from bokeh.io import curdoc
from bokeh.layouts import row, layout
from bokeh.models import Range1d, Label, ColumnDataSource, logging
from bokeh.plotting import figure
from concurrent.futures import ThreadPoolExecutor

logger = logging.getLogger(name)

class TestHistogram():

def __init__(self, doc, plot, plot_id):
    self._histogram = None
    self._doc = doc
    self._plot = plot
    self._plot_id = plot_id

def draw_init(self):
    self._caption_renderer = Label(
        text="Waiting",
        text_font_size="7pt",
        x=0,
        y=0,
        x_units='screen',
        y_units='screen',
        name="caption")

    self._plot.add_layout(self._caption_renderer, 'above')
    self._plot.x_range.start = -1
    self._plot.x_range.end = 1

    self._histogram = self._plot.quad(
        top="top",
        bottom="bottom",
        left="left",
        right="right",
        source=ColumnDataSource({
            "top": [1, 2, 3, 2, 1],
            "bottom": [0, 0, 0, 0, 0],
            "left": [0.2, 0.4, 0.6, 0.8, 1.0],
            "right": [0.3, 0.5, 0.7, 0.9, 1.1]
        }),
        name="histogram")

def do_work(self):
    logger.info("Start do_work: %s", self._plot_id)
    # blocking work, some slow, some fast
    sleep_ts = random.random() * 10

    # # Uncomment to simulate fast work that was done before WS connection
    # # was established
    # if sleep_ts < 1:
    #     sleep_ts /= 10
    time.sleep(sleep_ts)
    logger.info("Add callback: %s", self._plot_id)
    self._doc.add_next_tick_callback(self.draw_update)
    logger.info("End do_work: %s", self._plot_id)

def draw_update(self):
    logger.info("draw_update: %s", self._plot_id)
    # Update xaxis range of plot
    self._plot.x_range.start = -5
    self._plot.x_range.end = 5
    # Update histogram data
    self._histogram.data_source.data = {
        "top": [3, 2, 1, 2, 3],
        "bottom": [0, 0, 0, 0, 0],
        "left": [0.2, 0.4, 0.6, 0.8, 1.0],
        "right": [0.3, 0.5, 0.7, 0.9, 1.1]
    }
    self._caption_renderer.text = "DONE"

doc = curdoc()

N = 6

executor = ThreadPoolExecutor(max_workers=min(N * N, 50))

works =
plot_grid =
for i in range(N):
plots =
for j in range(N):
plot = figure(
title=“plot_” + str(i) + “" + str(j),
x_range=Range1d(),
plot_height=300,
plot_width=300)
hist = TestHistogram(doc, plot, str(i) + "
” + str(j))
hist.draw_init()
works.append(hist.do_work)

    plots.append(plot)
plot_grid.append(plots)

doc.add_root(row(layout(plot_grid), width=300 * N, height=300 * N))

for work in works:
executor.submit(work)







do_work function is executing on separate thread pool, so time.sleep is not on the main Bokeh thread I guess? Actually I am not really familiar with bokeh threading model, my understanding is it has a event loop thread from tornado, and user can create their own thread to update plots asynchronously as shown in the example (https://bokeh.pydata.org/en/latest/docs/user_guide/server.html#updating-from-threads).

My use case is a one off callback, can add_timeout_callback ever execute on a thread pool? I thought was it executes on event loop which doesn’t work for my case where I need multiple do_work to be done at the same time.

Jack

···

On Wednesday, February 13, 2019 at 4:07:01 PM UTC-8, tony halik wrote:

I think I have run into similar issues in the past.
Please be aware that Bokeh server application has its own (tornado) thread that may interfere your threads.

And I think that using time.sleep() on the main Bokeh thread can make it even worse.
The best practice is to do all plot updates in the update() function like this:

def update():
new_data = get_data_from_data_bucket()

do_update_plots(new_data)

curdoc().add_periodic_callback(update, 500)

``

You can have a second thread filling the “data bucket” that is being accessed in the main Bokeh thread => the update() function but don’t have one thread calling asynchronous functions on another thread unless you really know what you are doing.

On Wednesday, February 13, 2019 at 8:00:55 PM UTC+1, Jack Guo wrote:

Hi,


I use an embedded bokeh server to show plots, and use threads to asynchronously fetch data from remote database, and as data becomes available, update the plots shown to the user. I encountered weird issues that some plot updates seem never trigger, or sometime the glyph renders and then disappears.


Below is an example script reproduces the problem, the example draw a 2d grid of histograms, each initially has some data populated with xaxis.x_range set to [-1, 1], and when the remote data fetch completes (simulated with time.sleep), it updates the plot with new data and set new range. There are a few things that I noticed






1) Despite the order of draw_init => draw_update is guaranteed on the bokeh server side, the update to the plot seems to be out of order sometimes, so eventually the the plot was left with initial data or initial range.
  1. If some work is done and add_next_tick_callback is called before WS connection is established, then when those callbacks are executed, it is executed out of order, and after the WS connection is established, callbacks are executed in the order that was added.
  1. I tried to place locks on add_next_tick_callback, so threadpool synchronize on this call, but add_next_tick_callback seems to be very slow, and didn’t seem to help.
  1. If I added delay of say 5 seconds (change time.sleep(sleep_ts) to time.sleep(sleep_ts + 5)) to the “work”, then the plots usually render correctly. So is there requirement on certain events have to be fired after WS connection was established?
5) N = 2 usually works fine for me (a handleful of plots), but N = 6 consistently has issues. But probably it is because with a large number of random, it is more likely some "work" is done very fast.




Any help is much appreciated!


Thanks
Jack


import random
import time

from bokeh.io import curdoc
from bokeh.layouts import row, layout
from bokeh.models import Range1d, Label, ColumnDataSource, logging
from bokeh.plotting import figure
from concurrent.futures import ThreadPoolExecutor

logger = logging.getLogger(name)

class TestHistogram():

def __init__(self, doc, plot, plot_id):
    self._histogram = None
    self._doc = doc
    self._plot = plot
    self._plot_id = plot_id

def draw_init(self):
    self._caption_renderer = Label(
        text="Waiting",
        text_font_size="7pt",
        x=0,
        y=0,
        x_units='screen',
        y_units='screen',
        name="caption")

    self._plot.add_layout(self._caption_renderer, 'above')
    self._plot.x_range.start = -1
    self._plot.x_range.end = 1

    self._histogram = self._plot.quad(
        top="top",
        bottom="bottom",
        left="left",
        right="right",
        source=ColumnDataSource({
            "top": [1, 2, 3, 2, 1],
            "bottom": [0, 0, 0, 0, 0],
            "left": [0.2, 0.4, 0.6, 0.8, 1.0],
            "right": [0.3, 0.5, 0.7, 0.9, 1.1]
        }),
        name="histogram")

def do_work(self):
    logger.info("Start do_work: %s", self._plot_id)
    # blocking work, some slow, some fast
    sleep_ts = random.random() * 10

    # # Uncomment to simulate fast work that was done before WS connection
    # # was established
    # if sleep_ts < 1:
    #     sleep_ts /= 10
    time.sleep(sleep_ts)
    logger.info("Add callback: %s", self._plot_id)
    self._doc.add_next_tick_callback(self.draw_update)
    logger.info("End do_work: %s", self._plot_id)

def draw_update(self):
    logger.info("draw_update: %s", self._plot_id)
    # Update xaxis range of plot
    self._plot.x_range.start = -5
    self._plot.x_range.end = 5
    # Update histogram data
    self._histogram.data_source.data = {
        "top": [3, 2, 1, 2, 3],
        "bottom": [0, 0, 0, 0, 0],
        "left": [0.2, 0.4, 0.6, 0.8, 1.0],
        "right": [0.3, 0.5, 0.7, 0.9, 1.1]
    }
    self._caption_renderer.text = "DONE"

doc = curdoc()

N = 6

executor = ThreadPoolExecutor(max_workers=min(N * N, 50))

works =
plot_grid =
for i in range(N):
plots =
for j in range(N):
plot = figure(
title=“plot_” + str(i) + “" + str(j),
x_range=Range1d(),
plot_height=300,
plot_width=300)
hist = TestHistogram(doc, plot, str(i) + "
” + str(j))
hist.draw_init()
works.append(hist.do_work)

    plots.append(plot)
plot_grid.append(plots)

doc.add_root(row(layout(plot_grid), width=300 * N, height=300 * N))

for work in works:
executor.submit(work)







Bump up the thread. Any help appreciated!

···

On Wednesday, February 13, 2019 at 11:00:55 AM UTC-8, Jack Guo wrote:

Hi,


I use an embedded bokeh server to show plots, and use threads to asynchronously fetch data from remote database, and as data becomes available, update the plots shown to the user. I encountered weird issues that some plot updates seem never trigger, or sometime the glyph renders and then disappears.


Below is an example script reproduces the problem, the example draw a 2d grid of histograms, each initially has some data populated with xaxis.x_range set to [-1, 1], and when the remote data fetch completes (simulated with time.sleep), it updates the plot with new data and set new range. There are a few things that I noticed






1) Despite the order of draw_init => draw_update is guaranteed on the bokeh server side, the update to the plot seems to be out of order sometimes, so eventually the the plot was left with initial data or initial range.
  1. If some work is done and add_next_tick_callback is called before WS connection is established, then when those callbacks are executed, it is executed out of order, and after the WS connection is established, callbacks are executed in the order that was added.
  1. I tried to place locks on add_next_tick_callback, so threadpool synchronize on this call, but add_next_tick_callback seems to be very slow, and didn’t seem to help.
  1. If I added delay of say 5 seconds (change time.sleep(sleep_ts) to time.sleep(sleep_ts + 5)) to the “work”, then the plots usually render correctly. So is there requirement on certain events have to be fired after WS connection was established?
5) N = 2 usually works fine for me (a handleful of plots), but N = 6 consistently has issues. But probably it is because with a large number of random, it is more likely some "work" is done very fast.




Any help is much appreciated!


Thanks
Jack


import random
import time

from bokeh.io import curdoc
from bokeh.layouts import row, layout
from bokeh.models import Range1d, Label, ColumnDataSource, logging
from bokeh.plotting import figure
from concurrent.futures import ThreadPoolExecutor

logger = logging.getLogger(name)

class TestHistogram():

def __init__(self, doc, plot, plot_id):
    self._histogram = None
    self._doc = doc
    self._plot = plot
    self._plot_id = plot_id

def draw_init(self):
    self._caption_renderer = Label(
        text="Waiting",
        text_font_size="7pt",
        x=0,
        y=0,
        x_units='screen',
        y_units='screen',
        name="caption")

    self._plot.add_layout(self._caption_renderer, 'above')
    self._plot.x_range.start = -1
    self._plot.x_range.end = 1

    self._histogram = self._plot.quad(
        top="top",
        bottom="bottom",
        left="left",
        right="right",
        source=ColumnDataSource({
            "top": [1, 2, 3, 2, 1],
            "bottom": [0, 0, 0, 0, 0],
            "left": [0.2, 0.4, 0.6, 0.8, 1.0],
            "right": [0.3, 0.5, 0.7, 0.9, 1.1]
        }),
        name="histogram")

def do_work(self):
    logger.info("Start do_work: %s", self._plot_id)
    # blocking work, some slow, some fast
    sleep_ts = random.random() * 10

    # # Uncomment to simulate fast work that was done before WS connection
    # # was established
    # if sleep_ts < 1:
    #     sleep_ts /= 10
    time.sleep(sleep_ts)
    logger.info("Add callback: %s", self._plot_id)
    self._doc.add_next_tick_callback(self.draw_update)
    logger.info("End do_work: %s", self._plot_id)

def draw_update(self):
    logger.info("draw_update: %s", self._plot_id)
    # Update xaxis range of plot
    self._plot.x_range.start = -5
    self._plot.x_range.end = 5
    # Update histogram data
    self._histogram.data_source.data = {
        "top": [3, 2, 1, 2, 3],
        "bottom": [0, 0, 0, 0, 0],
        "left": [0.2, 0.4, 0.6, 0.8, 1.0],
        "right": [0.3, 0.5, 0.7, 0.9, 1.1]
    }
    self._caption_renderer.text = "DONE"

doc = curdoc()

N = 6

executor = ThreadPoolExecutor(max_workers=min(N * N, 50))

works =
plot_grid =
for i in range(N):
plots =
for j in range(N):
plot = figure(
title=“plot_” + str(i) + “" + str(j),
x_range=Range1d(),
plot_height=300,
plot_width=300)
hist = TestHistogram(doc, plot, str(i) + "
” + str(j))
hist.draw_init()
works.append(hist.do_work)

    plots.append(plot)
plot_grid.append(plots)

doc.add_root(row(layout(plot_grid), width=300 * N, height=300 * N))

for work in works:
executor.submit(work)







Hi,

I'm not really sure why you mean by "out of order". By submitting multiple tasks to a thread pool I would explicitly no longer have any expectations on the order the work is done.

I'm also not sure what "eventually the the plot was left with initial data or initial range" means. When I run with Bokeh 1.1 then all the plots eventually update when I run your code. So if you are not using 1.1 my first suggestion is to try using that version. It was a huge update to layout performance.

Otherwise I agree just staring the thread unconditionally and immediately is probably not good. There is not currently a lifecycle hook that would allow this to start only after the document is initialized. There is an open issue regarding events for doc init but it has not been implemented yet.

Thanks,

Bryan

···

On Apr 23, 2019, at 2:06 PM, Jack Guo <[email protected]> wrote:

Bump up the thread. Any help appreciated!

On Wednesday, February 13, 2019 at 11:00:55 AM UTC-8, Jack Guo wrote:
Hi,

I use an embedded bokeh server to show plots, and use threads to asynchronously fetch data from remote database, and as data becomes available, update the plots shown to the user. I encountered weird issues that some plot updates seem never trigger, or sometime the glyph renders and then disappears.

Below is an example script reproduces the problem, the example draw a 2d grid of histograms, each initially has some data populated with xaxis.x_range set to [-1, 1], and when the remote data fetch completes (simulated with time.sleep), it updates the plot with new data and set new range. There are a few things that I noticed

1) Despite the order of draw_init => draw_update is guaranteed on the bokeh server side, the update to the plot seems to be out of order sometimes, so eventually the the plot was left with initial data or initial range.
2) If some work is done and add_next_tick_callback is called before WS connection is established, then when those callbacks are executed, it is executed out of order, and after the WS connection is established, callbacks are executed in the order that was added.
3) I tried to place locks on add_next_tick_callback, so threadpool synchronize on this call, but add_next_tick_callback seems to be very slow, and didn't seem to help.
4) If I added delay of say 5 seconds (change time.sleep(sleep_ts) to time.sleep(sleep_ts + 5)) to the "work", then the plots usually render correctly. So is there requirement on certain events have to be fired after WS connection was established?
5) N = 2 usually works fine for me (a handleful of plots), but N = 6 consistently has issues. But probably it is because with a large number of random, it is more likely some "work" is done very fast.

Any help is much appreciated!

Thanks
Jack

import random
import time

from bokeh.io import curdoc
from bokeh.layouts import row, layout
from bokeh.models import Range1d, Label, ColumnDataSource, logging
from bokeh.plotting import figure
from concurrent.futures import ThreadPoolExecutor

logger = logging.getLogger(__name__)

class TestHistogram():

    def __init__(self, doc, plot, plot_id):
        self._histogram = None
        self._doc = doc
        self._plot = plot
        self._plot_id = plot_id

    def draw_init(self):
        self._caption_renderer = Label(
            text="Waiting",
            text_font_size="7pt",
            x=0,
            y=0,
            x_units='screen',
            y_units='screen',
            name="caption")

        self._plot.add_layout(self._caption_renderer, 'above')
        self._plot.x_range.start = -1
        self._plot.x_range.end = 1

        self._histogram = self._plot.quad(
            top="top",
            bottom="bottom",
            left="left",
            right="right",
            source=ColumnDataSource({
                "top": [1, 2, 3, 2, 1],
                "bottom": [0, 0, 0, 0, 0],
                "left": [0.2, 0.4, 0.6, 0.8, 1.0],
                "right": [0.3, 0.5, 0.7, 0.9, 1.1]
            }),
            name="histogram")

    def do_work(self):
        logger.info("Start do_work: %s", self._plot_id)
        # blocking work, some slow, some fast
        sleep_ts = random.random() * 10

        # # Uncomment to simulate fast work that was done before WS connection
        # # was established
        # if sleep_ts < 1:
        # sleep_ts /= 10
        time.sleep(sleep_ts)
        logger.info("Add callback: %s", self._plot_id)
        self._doc.add_next_tick_callback(self.draw_update)
        logger.info("End do_work: %s", self._plot_id)

    def draw_update(self):
        logger.info("draw_update: %s", self._plot_id)
        # Update xaxis range of plot
        self._plot.x_range.start = -5
        self._plot.x_range.end = 5
        # Update histogram data
        self._histogram.data_source.data = {
            "top": [3, 2, 1, 2, 3],
            "bottom": [0, 0, 0, 0, 0],
            "left": [0.2, 0.4, 0.6, 0.8, 1.0],
            "right": [0.3, 0.5, 0.7, 0.9, 1.1]
        }
        self._caption_renderer.text = "DONE"

doc = curdoc()

N = 6

executor = ThreadPoolExecutor(max_workers=min(N * N, 50))

works =
plot_grid =
for i in range(N):
    plots =
    for j in range(N):
        plot = figure(
            title="plot_" + str(i) + "_" + str(j),
            x_range=Range1d(),
            plot_height=300,
            plot_width=300)
        hist = TestHistogram(doc, plot, str(i) + "_" + str(j))
        hist.draw_init()
        works.append(hist.do_work)

        plots.append(plot)
    plot_grid.append(plots)

doc.add_root(row(layout(plot_grid), width=300 * N, height=300 * N))

for work in works:
    executor.submit(work)

--
You received this message because you are subscribed to the Google Groups "Bokeh Discussion - Public" group.
To unsubscribe from this group and stop receiving emails from it, send an email to [email protected].
To post to this group, send email to [email protected].
To view this discussion on the web visit https://groups.google.com/a/continuum.io/d/msgid/bokeh/bc97407a-98b9-4761-b29b-ccbe75b0b85a%40continuum.io.
For more options, visit https://groups.google.com/a/continuum.io/d/optout.