Skip to content
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

[BUG] dcc.interval missed triggering callback on time #2186

Open
viper7882 opened this issue Aug 9, 2022 · 7 comments
Open

[BUG] dcc.interval missed triggering callback on time #2186

viper7882 opened this issue Aug 9, 2022 · 7 comments

Comments

@viper7882
Copy link

viper7882 commented Aug 9, 2022

Hi Dash Admin,

Environment

Package                   Version
------------------------- -------
dash                      2.6.1
dash-bootstrap-components 0.13.1
dash-core-components      2.0.0
dash-daq                  0.5.0
dash-html-components      2.0.0
dash-table                5.0.0

Frontend (P/S: You don't need browser to reproduce the issue below):

- OS: Windows 11
- Browser: Chrome
- Version: 103.0.5060.134 (64-bit)

Describe the bug
Using the simple Python script below, the intention is to confirm the time for dcc.interval component to trigger callback as specified by the interval parameter. The screenshot below captured what had happened after the script ran for about 30 seconds. The callback was fired neither according to the 1 second interval nor consistent with 1 second interval. In fact, it was fired twice within the gap of 100ms to 300ms. You may find the additional notes within the screenshot dump itself.

Expected behavior
dcc.interval should fire callback precisely at interval of 1 second and consistently doing so. It should NOT fire the callback twice (with gap of 100ms and 300ms), making it clearly it is a defect. I suspect this issue is not newly introduced in Dash 2.x.x as I've seen similar behavior in Dash 1.x.x as well.

I would appreciate if someone from your team will look into this issue as this should be a fundamental functionality of dcc.interval component and it has been missed out by your test coverage since long ago.

Thank you in advance for your attention.

Codes

import dash
import datetime
import inspect

from dash.dependencies import Input, Output
from dash import html
from dash import dcc

app = dash.Dash(__name__)

app.layout = html.Div([
    dcc.Interval(id='my_interval', disabled=False, n_intervals=0, interval=1000 * 1),
    html.Div("Counter: ", style={"display": "inline-block"}),
    html.Div(children=None, id="cnt_val", style={"display": "inline-block", "margin-left": "15px"}),
])

@app.callback(
    Output('cnt_val', 'children'),
    [Input('my_interval', 'n_intervals')]
)
def update(n_intervals):
    timer_label__children = ""
    print("{} Line: {}: {}".format(
        inspect.getframeinfo(inspect.currentframe()).function,
        inspect.getframeinfo(inspect.currentframe()).lineno,
        datetime.datetime.now().isoformat().replace("T", " "),
    ))
    return timer_label__children


app.run_server(debug=True)

Screenshots

python.exe dcc_interval_missed_triggering_callback.py 
Dash is running on http://127.0.0.1:8050/

 * Serving Flask app 'dcc_interval_missed_triggering_callback' (lazy loading)
 * Environment: production
   WARNING: This is a development server. Do not use it in a production deployment.
   Use a production WSGI server instead.
 * Debug mode: on
update Line: 25: 2022-08-09 17:55:13.380438
update Line: 25: 2022-08-09 17:55:13.410408 (~+100ms)
update Line: 25: 2022-08-09 17:55:14.663830 (~+1.2s)
update Line: 25: 2022-08-09 17:55:14.690467 (~+300ms)
update Line: 25: 2022-08-09 17:55:16.666802 (~+2s)
update Line: 25: 2022-08-09 17:55:16.694578 (~+300ms)
update Line: 25: 2022-08-09 17:55:18.674646 (~+2s)
update Line: 25: 2022-08-09 17:55:18.709329 (~+300ms)
update Line: 25: 2022-08-09 17:55:20.668811
update Line: 25: 2022-08-09 17:55:20.684814
update Line: 25: 2022-08-09 17:55:22.670781
update Line: 25: 2022-08-09 17:55:22.683749
update Line: 25: 2022-08-09 17:55:24.698829
update Line: 25: 2022-08-09 17:55:24.722054
update Line: 25: 2022-08-09 17:55:26.672720
update Line: 25: 2022-08-09 17:55:26.706718
update Line: 25: 2022-08-09 17:55:28.667662
update Line: 25: 2022-08-09 17:55:28.694618
update Line: 25: 2022-08-09 17:55:30.697895
update Line: 25: 2022-08-09 17:55:30.716306
update Line: 25: 2022-08-09 17:55:32.676514
update Line: 25: 2022-08-09 17:55:32.700857
update Line: 25: 2022-08-09 17:55:34.688452
update Line: 25: 2022-08-09 17:55:34.703525
update Line: 25: 2022-08-09 17:55:36.672344
update Line: 25: 2022-08-09 17:55:36.691374
update Line: 25: 2022-08-09 17:55:38.670202
update Line: 25: 2022-08-09 17:55:38.695352
update Line: 25: 2022-08-09 17:55:40.679620
update Line: 25: 2022-08-09 17:55:40.708878
update Line: 25: 2022-08-09 17:55:42.674115
update Line: 25: 2022-08-09 17:55:42.703361
update Line: 25: 2022-08-09 17:55:44.679233
update Line: 25: 2022-08-09 17:55:44.717429
@viper7882
Copy link
Author

Found a better place to file this issue @ https://github.com/plotly/dash-core-components, closing this issue for now.

@T4rk1n T4rk1n reopened this Aug 9, 2022
@T4rk1n
Copy link
Contributor

T4rk1n commented Aug 9, 2022

The interval components fires the callback on the js side at the specified interval, but if your callbacks themselves takes longer than the interval time, the time will not be synced with the front end.

Here you have inspect calls which are very slow and ends up taking more than 1s to run on the backend. So the next callback fire before the last one completed, resulting in missing callbacks results. If you put the interval even lower, you'll get an infinite loop.

I suggest using the interval component with an interval more than the execution time of your callbacks.

@viper7882
Copy link
Author

Hi @T4rk1n,

Good explanation and I'm aware the Dash is employing JS for the timer. In case you are not aware, I'm specializing in building time sensitive python program and I doubt the behavior described above is working as intended.

Firstly, I've tried removing the inspect, the result is similar to the earlier. The question I have in mind is that did you even try to eliminate the issue by removing inspect as that seems to be quick one before you posted your comment above?

Next I've tried with the following to prove your hypothesis where inspect is taking more than 1 second:

import dash
import datetime
import inspect

from dash.dependencies import Input, Output
from dash import html
from dash import dcc
from time import time as timer

app = dash.Dash(__name__)

app.layout = html.Div([
    dcc.Interval(id='my_interval', disabled=False, n_intervals=0, interval=1000 * 1),
    html.Div("Counter: ", style={"display": "inline-block"}),
    html.Div(children=None, id="cnt_val", style={"display": "inline-block", "margin-left": "15px"}),
])


def get_time_diff(start):
    prog_time_diff = timer() - start
    hours, rem = divmod(prog_time_diff, 3600)
    minutes, seconds = divmod(rem, 60)
    minutes = int(minutes)
    return hours, minutes, seconds


def get_ms_time_diff(start):
    _, minutes, seconds = get_time_diff(start)
    fraction_of_seconds = seconds - int(seconds)
    seconds = int(seconds)
    milliseconds = fraction_of_seconds * 1000
    milliseconds = int(milliseconds)
    return minutes, seconds, milliseconds


def print_timestamp_checkpoint(comment="Checkpoint timestamp", start=None):
    timestamp_str = datetime.datetime.now().isoformat().replace("T", " ")
    if start:
        minutes, seconds, milliseconds = get_ms_time_diff(start)
        print("{}, {}, Delta: {}m:{}s.{}ms".format(
            comment, timestamp_str, minutes, seconds, milliseconds,
        ))
    else:
        print("{}, {}".format(
            comment, timestamp_str,
        ))

@app.callback(
    Output('cnt_val', 'children'),
    [Input('my_interval', 'n_intervals')]
)
def update(n_intervals):
    start = timer()
    timer_label__children = ""
    print("{} Line: {}: {}".format(
        inspect.getframeinfo(inspect.currentframe()).function,
        inspect.getframeinfo(inspect.currentframe()).lineno,
        datetime.datetime.now().isoformat().replace("T", " "),
    ))
    print_timestamp_checkpoint(comment="Checkpoint", start=start)
    return timer_label__children


app.run_server(debug=True)

and below is the screenshot:

update Line: 57: 2022-08-10 19:46:57.355868
Checkpoint, 2022-08-10 19:46:57.355868, Delta: 0m:0s.234ms
update Line: 57: 2022-08-10 19:46:58.217521
Checkpoint, 2022-08-10 19:46:58.217521, Delta: 0m:0s.2ms
update Line: 57: 2022-08-10 19:47:00.145453
Checkpoint, 2022-08-10 19:47:00.145453, Delta: 0m:0s.1ms
update Line: 57: 2022-08-10 19:47:01.165044
Checkpoint, 2022-08-10 19:47:01.165044, Delta: 0m:0s.2ms
update Line: 57: 2022-08-10 19:47:02.127178
Checkpoint, 2022-08-10 19:47:02.127178, Delta: 0m:0s.1ms
update Line: 57: 2022-08-10 19:47:06.117606
Checkpoint, 2022-08-10 19:47:06.117606, Delta: 0m:0s.1ms
update Line: 57: 2022-08-10 19:47:08.116323
Checkpoint, 2022-08-10 19:47:08.116323, Delta: 0m:0s.2ms
update Line: 57: 2022-08-10 19:47:10.112785
Checkpoint, 2022-08-10 19:47:10.112785, Delta: 0m:0s.2ms
update Line: 57: 2022-08-10 19:47:12.105746
Checkpoint, 2022-08-10 19:47:12.105746, Delta: 0m:0s.2ms
update Line: 57: 2022-08-10 19:47:14.109291
Checkpoint, 2022-08-10 19:47:14.109291, Delta: 0m:0s.1ms
update Line: 57: 2022-08-10 19:47:14.148619
Checkpoint, 2022-08-10 19:47:14.148619, Delta: 0m:0s.0ms
update Line: 57: 2022-08-10 19:47:17.108614
Checkpoint, 2022-08-10 19:47:17.108614, Delta: 0m:0s.0ms
update Line: 57: 2022-08-10 19:47:19.107905
Checkpoint, 2022-08-10 19:47:19.107905, Delta: 0m:0s.0ms

It clearly indicated where the callback itself including inspect does not consume more than 300ms and that's only limited for the first callback. All subsequent callback consumes negligible time below millisecond range.

I totally understand Dash has been architected in a way where JS script is driving the callback to support Python, R, Julia, and F# (experimental) on top and it has my full support on this move. However, when user of any of these programming languages encounters functionality issue such as the one described above, you can't just blame the architecture itself and then declare it as problem of others. Even if JS fires the callback precisely at 1 second but for some reason the callback is not getting the firing, that defeat the whole purpose of dcc.interval as the fundamental functionality declared in the user guide documentation do not match with the actual code behavior. That's why I'm filing this case as an issue to be addressed. Btw, I'm surprised to learn that no user from Dash Enterprise actually discover this behavior and/or file this case earlier.

Please don't get me wrong, I'm not here to debate with you about Dash's architecture or limitation as this is one of the gating issue for my current support and I would like to get issue to be fixed. Unless you intend to fix at your end, I would like to explore how to fix this issue with you using workaround since official fix from Dash is going to be time consuming and I would prefer it to be addressed before that.

Let's explore ideas for workaround. From Python point of view, can user somehow replaces dcc.interval with a time.sleep() function? I'm 100% certain this workaround will work flawlessly. Is there any way user could swap dcc.interval with time.sleep() or other custom function?

@T4rk1n
Copy link
Contributor

T4rk1n commented Aug 10, 2022

This behavior is known, it's the reason why I refactored the long_callback to background_callback with a native request loop. Any interval inferior to a couple seconds will end up with this kind of race condition, in production server you'll have to add network latency to the mix.

You could use a background_callback and update props via the progress side update on a sleep loop.

@viper7882
Copy link
Author

Thanks. Perhaps you could please share a more practical example so that I don't have to perform my own R&D?

@T4rk1n
Copy link
Contributor

T4rk1n commented Aug 10, 2022

Using the progress output of background callbacks to update on a loop from the backend:

import time

from dash import Dash, html, DiskcacheManager, callback, Input, Output

app = Dash(__name__, background_callback_manager=DiskcacheManager())
app.layout = html.Div([
    html.Div(id='output'),
    html.Div(id='side'),
    html.Button('start', id='start'),
])


@callback(
    Output('output', 'children'),
    Input('start', 'n_clicks'),
    background=True,
    progress=Output('side', 'children')
)
def on_click(set_progress, n_clicks):
    i = 1
    while i < 30:
        set_progress(f'Progress {i}')
        time.sleep(1)
        i += 1

    return 'Finished'


if __name__ == '__main__':
    app.run(debug=True)

@viper7882
Copy link
Author

Thank you @T4rk1n but no quite what I'm looking for.

As dcc.interval running on JS is forever loop, I've modified your codes above to be running in forever loop instead of for loop. It is working for the codes above but "Finished" is never been returned and called. Also, if add in more callback functions, this forever loop will not exit and subsequently causing starvation to other callback functions.

It seems like I'll have to stick with dcc.interval for the meantime.

I have no more issue, you may go ahead and close this case if you wanted to.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants