Many widgets fail to render

[maartenbreddels]

cc @aschlaep
Eg.

import ipywidgets as widgets
widgets.Widget.close_all()
def recursive(n):
    if n == 0:
        return widgets.Button(description='Hi')
    else:
        cls = (widgets.VBox if n % 2 else widgets.HBox)
        return cls([recursive(n-1), recursive(n-1)])
display(recursive(9))
display(len(widgets.Widget.widgets))

Will often fail to render in voila. I think it's likely to be a timing/order issue in the manager (message received before an event handler is attached), or packets being dropped (iorate limit?)

[maartenbreddels]

I think this is a good opportunity to refactor this voila manager, to allow progressive rendering of widget (create widgets as they come in, and even try to render them as they come in). Also, we can think of connecting the websocket/kernel as early as possible, not wait till the execution is done.
I assume we can reuse quite a bit from the lab manager, I believe @vidartf and @jasongrout put quite some effort into that.

[jasongrout]

@maartenbreddels - do you want to do a video call to discuss this? It sounds like a tricky issue.

[maartenbreddels]

Notebook 6.0.2 seems to have the same issue, it worked once with n=9, but usually does not, Jupyter Lab 1.2.4 also does not render with n=8. So I don't think this is a voila issue.

Voila sees the 2558 comms/widgets, requests all their info, but gets ~2300 replies.

@maartenbreddels - do you want to do a video call to discuss this? It sounds like a tricky issue.

I'm on whereby!

[jasongrout]

I wonder if the problem is overwhelming the websocket buffer. All of these requests are made simultaneously. I don't know what the websocket buffer size is, but perhaps it is overflowing and dropping things closing the connection?

From https://developer.mozilla.org/en-US/docs/Web/API/WebSocket/send

The WebSocket.send() method enqueues the specified data to be transmitted to the server over the WebSocket connection, increasing the value of bufferedAmount by the number of bytes needed to contain the data. If the data can't be sent (for example, because it needs to be buffered but the buffer is full), the socket is closed automatically.

Can you check what the websocket bufferedAmount is? See also https://developer.mozilla.org/en-US/docs/Web/API/WebSocket/bufferedAmount

[jasongrout]

@maartenbreddels and I talked about this more, and it seems that problem is here:

voila/js/src/manager.js

Lines 117 to 140 in 8557d9d

	async _build_models() {
	const comm_ids = await this._get_comm_info();
	const models = {};
	const widgets_info = await Promise.all(Object.keys(comm_ids).map(async (comm_id) => {
	const comm = await this._create_comm(this.comm_target_name, comm_id);
	return this._update_comm(comm);
	}));
	await Promise.all(widgets_info.map(async (widget_info) => {
	const state = widget_info.msg.content.data.state;
	const modelPromise = this.new_model({
	model_name: state._model_name,
	model_module: state._model_module,
	model_module_version: state._model_module_version,
	comm: widget_info.comm,
	},
	state
	);
	const model = await modelPromise;
	models[model.model_id] = model;
	return modelPromise;
	}));
	return models;
	}

In particular, for his reproduction example, this gets back 2558 comm ids:

voila/js/src/manager.js

Line 118 in 8557d9d

const comm_ids = await this._get_comm_info();

But this Promise.all only succeeds for 2300 or so widget state updates, and then just hangs waiting for the rest of the widget state updates:

voila/js/src/manager.js

Lines 120 to 123 in 8557d9d

	const widgets_info = await Promise.all(Object.keys(comm_ids).map(async (comm_id) => {
	const comm = await this._create_comm(this.comm_target_name, comm_id);
	return this._update_comm(comm);
	}));

He can reproduce this sort of issue in classic notebook and jlab by creating all these widgets, then refreshing the page (which triggers the same sort of logic to request all widget state from the kernel to populate the client widget manager)

[jasongrout]

I think the key is to first narrow down if the problem is in getting the update requests to the kernel, in the kernel, or getting the updates from the kernel. @maartenbreddels decided to instrument the kernel to track these state requests, to see if the kernel is getting all the requests, and if it thinks it sent all the updates. That should narrow down the problem.

One other quick fix might be to just break up Object.keys in this Promise.all so that it actually just iterates over, say, 500 widgets at a time:

voila/js/src/manager.js

Line 120 in 8557d9d

const widgets_info = await Promise.all(Object.keys(comm_ids).map(async (comm_id) => {

[jasongrout]

Voila sees the 2558 comms/widgets, requests all their info, but gets ~2300 replies.

Since @maartenbreddels asked - here is where 2558 comes from...

• 2**9 Buttons
• 2**8 + 2**7 + 2**6 + ... + 2**0 = 2**9-1 HBoxes and VBoxes
• 2**9 Style widgets, one for each button
• 2**9+2**9-1 Layout widgets, one for each hbox, vbox, and button

(2**9 + 2**9 - 1)*2 + 2**9 = 2558 :)

[martinRenou]

The comms are limited to 1000 msgs/sec by default in the Notebook. This might be the reason for this issue.

IOPub message rate exceeded.
The notebook server will temporarily stop sending output
to the client in order to avoid crashing it.
To change this limit, set the config variable
`--NotebookApp.iopub_msg_rate_limit`.

Current values:
NotebookApp.iopub_msg_rate_limit=1000.0 (msgs/sec)
NotebookApp.rate_limit_window=3.0 (secs)

[maartenbreddels]

Since @maartenbreddels asked - here is where 2558 comes from...

Thanks, that helped sleeping :)

Ok, I've narrowed down the issue a bit, by patching jupyter_server like this:

$ git diff jupyter_server/services/kernels/handlers.py                                                                                                                               base
diff --git a/jupyter_server/services/kernels/handlers.py b/jupyter_server/services/kernels/handlers.py
index 23d763a84..97fb88f43 100644
--- a/jupyter_server/services/kernels/handlers.py
+++ b/jupyter_server/services/kernels/handlers.py
@@ -211,6 +211,9 @@ class ZMQChannelsHandler(AuthenticatedZMQStreamHandler):
         # Allows you to specify that the byte count should be lowered
         # by a delta amount at some point in the future.
         self._iopub_window_byte_queue = []
+        import collections
+        self.counters = collections.Counter()
+        self.request_order = {}

     @gen.coroutine
     def pre_get(self):
@@ -301,6 +304,11 @@ class ZMQChannelsHandler(AuthenticatedZMQStreamHandler):
         else:
             msg = json.loads(msg)
         channel = msg.pop('channel', None)
+        content = msg.get('content', {})
+        if channel == 'shell' and content.get('data', {}).get('method') == 'request_state':
+            self.request_order[content['comm_id']] = self.counters['request_state']
+            self.counters['request_state'] += 1
+            print(self.counters)
         if channel is None:
             self.log.warning("No channel specified, assuming shell: %s", msg)
             channel = 'shell'
@@ -329,6 +337,13 @@ class ZMQChannelsHandler(AuthenticatedZMQStreamHandler):
             self.write_message(json.dumps(msg, default=date_default))
         channel = getattr(stream, 'channel', None)
         msg_type = msg['header']['msg_type']
+        content = msg.get('content', {})
+        if channel == 'iopub' and content.get('data', {}).get('method') == 'update':
+            self.counters['update'] += 1
+            print(self.counters)
+            del self.request_order[content['comm_id']]
+            if self.counters['update'] > 1800:
+                print("missing", self.request_order)

         if channel == 'iopub' and msg_type == 'status' and msg['content'].get('execution_state') == 'idle':
             # reset rate limit counter on status=idle,

I can conclude the following

• we get 2558 request_state messages, so we get all websocket sends from the browser.
• we get < 2558 update messages, so either the kernels does not receive them (not the case, see below), or the server does not receive them (either the kernel does not send a reply, or the reply does not get through).

I've analyzed the request_order dict, and in 1 run, the first 1165 request_state calls got answered, the next 130 got dropped, the next 500 (or 501) got answered, then 459 dropped, and the last 305 dropped.

from the kernel

I monkey patch ipykernel and the Comm class to see what we do at the kernel side:

Counter({'update': 2558, 'request_state': 2558})

So we get all requests , and we send all the updates, but they don't arrive at the server.

[maartenbreddels]

The comms are limited to 1000 msgs/sec by default in the Notebook. This might be the reason for this issue.

Good idea, but I don't see any warning (could always end up in /dev/null thought). But the tracking of the reply happens before the rate limiting (i.e. the limiting is between the frontend and server, and I already lost the message between the kernel and the server)

[jasongrout]

The iopub rate limiting is at the server on messages going from the kernel to the browser. That seems to be where you are dropping messages? Can you up the rate limits to see if it solves the issue, just in case?

[jasongrout]

To up the limit to 10x its default: jupyter lab --LabApp.iopub_msg_rate_limit=10000

[maartenbreddels]

I see

• 2558 request_state msg'es going from browser->server
• 2558 request_state msg'es arriving at the kernel
• 2558 update calls from the kernel
• < 2558 update messages received at the server.

I intercept the messages at the server at:
https://github.com/jupyter/jupyter_server/blob/7a6cd8e5dece1a8084f6cf065188c6a004f0a38a/jupyter_server/services/kernels/handlers.py#L317

So I think this is before any rate-limiting is applied.

So I think either the zmq layer does not send the packets, or the server does not receive them.

[maartenbreddels]

kernel = get_ipython().kernel
kernel.iopub_socket.io_thread.socket.get_hwm()

Gives us 1000, meaning it will buffer 1000 messages, before dropping messages, as explained at: http://api.zeromq.org/2-1:zmq-setsockopt (ZMQ_HWM: Set high water mark).

Patching ipykernel, and removing that limit self.iopub_socket.set_hwm(0) will make voila get all the messages 🎉. But, this call needs to happen before binding the socket, so I don't think a notebook user can do it.

[jasongrout]

ah, nice!

By the way, here is a nice small program for spying on a specific kernel directly, in case you want to do something like count the iopub messages coming directly from the kernel zmq socket. Use it like python ./client.py <kernel-id>

from collections import Counter
from jupyter_client import BlockingKernelClient
from jupyter_core import paths
import os.path as path
import sys

connection_file = path.join(paths.jupyter_runtime_dir(), 'kernel-{}.json'.format(sys.argv[1]))
print(connection_file)

client = BlockingKernelClient()
client.load_connection_file(connection_file)
client.start_channels()
counter = Counter()

while True:
  msg = client.get_iopub_msg(timeout=100)
  counter[msg['msg_type']] += 1
  print(counter)