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

Fixing #659 (output cutoff and iopub timeout) #994

Merged
merged 16 commits into from May 17, 2019
Merged
Changes from 9 commits
Commits
File filter...
Filter file types
Jump to…
Jump to file or symbol
Failed to load files and symbols.

Always

Just for now

@@ -6,6 +6,10 @@
import base64
from textwrap import dedent
from contextlib import contextmanager
try:
from time import monotonic
except ImportError:
from time import time as monotonic

try:
from queue import Empty # Py 3
@@ -448,6 +452,37 @@ def _update_display_id(self, display_id, msg):
outputs[output_idx]['data'] = out['data']
outputs[output_idx]['metadata'] = out['metadata']

def _poll_for_reply(self, msg_id, cell=None, timeout=None):
try:
# check with timeout if kernel is still alive
msg = self.kc.shell_channel.get_msg(timeout=timeout)
if msg['parent_header'].get('msg_id') == msg_id:
return msg
except Empty:
# received no message, check if kernel is still alive
self._check_alive()
# kernel still alive, wait for a message

def _get_timeout(self, cell):
if self.timeout_func is not None and cell is not None:
timeout = self.timeout_func(cell)
else:
timeout = self.timeout

if not timeout or timeout < 0:
timeout = None

return timeout

def _handle_timeout(self):
This conversation was marked as resolved by djherbis

This comment has been minimized.

Copy link
@MSeal

MSeal Apr 23, 2019

Collaborator

Good to poll this into its own function :)

self.log.error(
"Timeout waiting for execute reply (%is)." % self.timeout)
if self.interrupt_on_timeout:
self.log.error("Interrupting kernel")
self.km.interrupt_kernel()
return
This conversation was marked as resolved by djherbis

This comment has been minimized.

Copy link
@MSeal

MSeal May 2, 2019

Collaborator

Don't need this return

else:
raise TimeoutError("Cell execution timed out")

def _check_alive(self):
if not self.kc.is_alive():
@@ -457,13 +492,7 @@ def _check_alive(self):

def _wait_for_reply(self, msg_id, cell=None):
# wait for finish, with timeout
if self.timeout_func is not None and cell is not None:
timeout = self.timeout_func(cell)
else:
timeout = self.timeout

if not timeout or timeout < 0:
timeout = None
timeout = self._get_timeout(cell)
cummulative_time = 0
timeout_interval = 5
while True:
@@ -473,40 +502,68 @@ def _wait_for_reply(self, msg_id, cell=None):
self._check_alive()
cummulative_time += timeout_interval
if timeout and cummulative_time > timeout:
self.log.error(
"Timeout waiting for execute reply (%is)." % self.timeout)
if self.interrupt_on_timeout:
self.log.error("Interrupting kernel")
self.km.interrupt_kernel()
break
else:
raise TimeoutError("Cell execution timed out")
self._handle_timeout()
break
else:
if msg['parent_header'].get('msg_id') == msg_id:
return msg

def _timeout_with_deadline(self, timeout, deadline):
if deadline is not None and deadline - monotonic() < timeout:
timeout = deadline - monotonic()

if timeout < 0:
timeout = 0

return timeout

def _passed_deadline(self, deadline):
if deadline is not None and deadline - monotonic() <= 0:
self._handle_timeout()
return True
return False

def run_cell(self, cell, cell_index=0):
parent_msg_id = self.kc.execute(cell.source)
self.log.debug("Executing cell:\n%s", cell.source)
exec_reply = self._wait_for_reply(parent_msg_id, cell)
exec_timeout = self._get_timeout(cell)
if exec_timeout is not None:
deadline = monotonic() + exec_timeout

cell.outputs = []
self.clear_before_next_output = False

while True:
try:
# We've already waited for execute_reply, so all output
# should already be waiting. However, on slow networks, like
# in certain CI systems, waiting < 1 second might miss messages.
# So long as the kernel sends a status:idle message when it
# finishes, we won't actually have to wait this long, anyway.
msg = self.kc.iopub_channel.get_msg(timeout=self.iopub_timeout)
except Empty:
self.log.warning("Timeout waiting for IOPub output")
if self.raise_on_iopub_timeout:
raise RuntimeError("Timeout waiting for IOPub output")
else:
break
more_output = True
polling_exec_reply = True

while more_output or polling_exec_reply:

This comment has been minimized.

Copy link
@mpacer

mpacer May 15, 2019

Member

more_output being used as a signaling mechanism feels like a pretty significant piece of internal logic. Could you add a comment explaining why we're taking this approach?

I would think a description about the intention of the separate roles of more_output and polling_exec_reply would be enough to address the curious individual.

This comment has been minimized.

Copy link
@djherbis

djherbis May 17, 2019

Author Contributor

Great point, I added some detailed comments around this section to explain why it's written this way. Let me know if it's still not clear for future readers.


if polling_exec_reply:
if self._passed_deadline(deadline):
polling_exec_reply = False
continue

timeout = self._timeout_with_deadline(1, deadline)
exec_reply = self._poll_for_reply(parent_msg_id, cell, timeout)
if exec_reply is not None:
polling_exec_reply = False

if more_output:
try:
timeout = self.iopub_timeout

This comment has been minimized.

Copy link
@MSeal

MSeal May 5, 2019

Collaborator

So now with all the functionality in place, we likely need to address the fact that iopub_timeout no longer acts as it used to. In particular, since we aren't waiting for exec reply to fully complete we'll expect to timeout here often. Which means that raise_on_iopub_timeout will fire when users wouldn't expect.

@mpacer I think we should perhaps remove raise_on_iopub_timeout and iopub_timeout with this change and use timeout = self._timeout_with_deadline(1, deadline) for both conditional branches. Those other configurations just don't make any sense any more and are problematic if defined as they were in earlier versions. What's your thoughts? Even if we do a less severe change we'd need to address the change in timeout behavior somehow with this PR merging.

This comment has been minimized.

Copy link
@djherbis

djherbis May 5, 2019

Author Contributor

Actually I tried to preserve that behavior, it won't hit the raise_on_iopub_timeout unless polling_exec_reply is false, and it's only false if we've passed the deadline or if exec_reply is not None (completed).

If we've passed the deadline we hit handle_timeout, which will either interrupt or throw. If it throws it won't reach this section, if it interrupts I suspect we would get an idle message?

Let me know if I got anything wrong here.

This comment has been minimized.

Copy link
@MSeal

MSeal May 5, 2019

Collaborator

Ahh yes you're correct, my end-of-conference brain power failed to read properly. Then maybe we should deprecate those fields in the next release (5.5.1) so they can be removed in 6.0? That would help cleanup this code and make it simpler to control in the future imo.

We should add a test for this case if it's not covered yet to ensure we won't timeout unexpectantly. That might be tricky to write with Mocks, so I can probably make that test if it's not clear how to set that up. After that I think I'm good to merge once @mpacer approves / has any further concerns resolved.

This comment has been minimized.

Copy link
@djherbis

djherbis May 11, 2019

Author Contributor

Hey sorry, I was also gone for a week long work even this week.
Looks like I've got more merge conflicts to fix, I'll take a look Monday.

This comment has been minimized.

Copy link
@MSeal

MSeal May 12, 2019

Collaborator

Sorry there's been so many merge conflicts. I've been more careful to review / get more opinions on this PR before merging. Shouldn't be too many more conflicts. I asked @mpacer in person to take a look again when she's available so we don't keep this PR open for much longer.

This comment has been minimized.

Copy link
@djherbis

djherbis May 13, 2019

Author Contributor

Yeah I understand, I think I managed to merge it in correctly now.

This comment has been minimized.

Copy link
@mpacer

mpacer May 15, 2019

Member

I am not quite following the reasoning behind why the fields need to be deprecated. Could you lay out the situation where these fields cease to make sense?

This comment has been minimized.

Copy link
@djherbis

djherbis May 17, 2019

Author Contributor

@MSeal probably has a better answer than me, my interpretation was that iopub_timeout exists to give a small window after receiving exec_reply (so we know all output should be produced by then) for the output to reach the iopub_channel (in case of network latency etc.). I think @MSeal might feel that since we are polling for this output more regularly (and not just after exec_reply) that the purpose of this flag has changed somewhat. Perhaps I shouldn't be using iopub_timeout at all unless exec_reply has finished, and use a constant timeout / deadline similar to _poll_for_reply. I could be misinterpreting @MSeal though so please correct me!

Even with all of that, I still think iopub_timeout is relevant post exec_reply being received, since you may still need to wait for output produced near the end of execution to be received.

This comment has been minimized.

Copy link
@MSeal

MSeal May 17, 2019

Collaborator

That's pretty much on point. It's odd the to have a post exec_reply response specific timeout in addition to an overall timeout when the two channels are being consumed in parallel.

I'll start a separate PR / Issue on the field independent of this PR to avoid leaving this open longer.

This comment has been minimized.

Copy link
@djherbis

djherbis May 17, 2019

Author Contributor

@MSeal Thanks, what do you think about using a constant (like 1s) insead of the iopub_timeout in this PR for the poll to iopub_channel while polling_exec_reply=True, and then switching to iopub_timeout once exec_reply is received?

This comment has been minimized.

Copy link
@MSeal

MSeal May 17, 2019

Collaborator

Possibly that would be a way to approach it. In general I'm saying I think making it simpler and having 1 timeout would reduce confusion and be less nuanced.

if polling_exec_reply:
timeout = self._timeout_with_deadline(timeout, deadline)
msg = self.kc.iopub_channel.get_msg(timeout=timeout)
except Empty:
if polling_exec_reply:
continue

if self.raise_on_iopub_timeout:
raise RuntimeError("Timeout waiting for IOPub output")
else:
self.log.warning("Timeout waiting for IOPub output")
more_output = False
continue
if msg['parent_header'].get('msg_id') != parent_msg_id:
# not an output from our execution
continue
ProTip! Use n and p to navigate between commits in a pull request.
You can’t perform that action at this time.