Slow/irregular output for Python runtime with simple statements

[wesm]

I was surprised by how "laggy" the Output window is for the Python Runtime is — see this screen recording:

https://github.com/posit-dev/positron/assets/329591/1ae91aee-8013-4eb9-9a3d-8db9126c2df3

From the console, it is clear that the result of the execution comes back right way, but it takes a while for the Output window to finish updating with this output. Perhaps this is by design but it suggests possibly something being wrong — Ark doesn't have this problem

[Python] *** MESSAGE TYPE:is_complete_request***
[Python] [PositronIPKernelApp]    Content: {'code': "print('hello world')"}
[Python]    --->
[Python]    
[Python] [PositronIPKernelApp] is_complete_request: {'header': {'msg_id': 'b5af0fb1-3b1c-4a07-bab3-58cbc368795c', 'msg_type': 'is_complete_request', 'version': '5.0', 'date': datetime.datetime(2024, 2, 22, 17, 39, 59, 174000, tzinfo=tzutc()), 'session': '8a2d97830a920ae2eac452269e9a2233', 'username': 'wesm'}, 'msg_id': 'b5af0fb1-3b1c-4a07-bab3-58cbc368795c', 'msg_type': 'is_complete_request', 'parent_header': {}, 'metadata': {}, 'content': {'code': "print('hello world')"}, 'buffers': []}
[Python] [PositronIPKernelApp] {'header': {'msg_id': '83f693de-e033fed825ecaa72112ccdc8_64959_112', 'msg_type': 'is_complete_reply', 'username': 'wesm', 'session': '83f693de-e033fed825ecaa72112ccdc8', 'date': datetime.datetime(2024, 2, 22, 17, 39, 59, 181232, tzinfo=datetime.timezone.utc), 'version': '5.3'}, 'msg_id': '83f693de-e033fed825ecaa72112ccdc8_64959_112', 'msg_type': 'is_complete_reply', 'parent_header': {'msg_id': 'b5af0fb1-3b1c-4a07-bab3-58cbc368795c', 'msg_type': 'is_complete_request', 'version': '5.0', 'date': datetime.datetime(2024, 2, 22, 17, 39, 59, 174000, tzinfo=tzutc()), 'session': '8a2d97830a920ae2eac452269e9a2233', 'username': 'wesm'}, 'content': {'status': 'complete'}, 'metadata': {}, 'tracker': <zmq.sugar.tracker.MessageTracker object at 0x1050bba10>}
[Python] [positron._vendor.pygls.protocol.json_rpc] Received b'Content-Length: 284\r\n\r\n{"jsonrpc":"2.0","method":"textDocument/didChange","params":{"textDocument":{"uri":"inmemory:/repl-python-e7f4720a-1b6e-43f7-b2b9-36247ffb58f2","version":56},"contentChanges":[{"range":{"start":{"line":0,"character":20},"end":{"line":0,"character":20}},"rangeLength":0,"text":"\\n"}]}}'
[Python] [positron._vendor.pygls.protocol.json_rpc] Notification message received.
[Python] [positron._vendor.pygls.protocol.json_rpc] Received b'Content-Length: 281\r\n\r\n{"jsonrpc":"2.0","method":"textDocument/didChange","params":{"textDocument":{"uri":"inmemory:/repl-python-e7f4720a-1b6e-43f7-b2b9-36247ffb58f2","version":57},"contentChanges":[{"range":{"start":{"line":0,"character":0},"end":{"line":1,"character":0}},"rangeLength":21,"text":""}]}}'
[Python] [positron._vendor.pygls.protocol.json_rpc] Notification message received.
[Python] [positron._vendor.pygls.protocol.json_rpc] Received b'Content-Length: 280\r\n\r\n{"jsonrpc":"2.0","method":"textDocument/didChange","params":{"textDocument":{"uri":"inmemory:/repl-python-e7f4720a-1b6e-43f7-b2b9-36247ffb58f2","version":58},"contentChanges":[{"range":{"start":{"line":0,"character":0},"end":{"line":0,"character":0}},"rangeLength":0,"text":""}]}}'
[Python] [positron._vendor.pygls.protocol.json_rpc] Notification message received.
[Python] [PositronIPKernelApp] 
[Python] *** MESSAGE TYPE:execute_request***
[Python] [PositronIPKernelApp]    Content: {'code': "print('hello world')", 'allow_stdin': True, 'silent': False, 'store_history': True, 'user_expressions': {}, 'stop_on_error': False}
[Python]    --->
[Python]    
[Python] [PositronIPKernelApp] execute_request: {'header': {'msg_id': 'fragment-3bd16f2a-3015-4e9f-b929-f0bec8f1658d', 'msg_type': 'execute_request', 'version': '5.0', 'date': datetime.datetime(2024, 2, 22, 17, 39, 59, 193000, tzinfo=tzutc()), 'session': '8a2d97830a920ae2eac452269e9a2233', 'username': 'wesm'}, 'msg_id': 'fragment-3bd16f2a-3015-4e9f-b929-f0bec8f1658d', 'msg_type': 'execute_request', 'parent_header': {}, 'metadata': {}, 'content': {'code': "print('hello world')", 'allow_stdin': True, 'silent': False, 'store_history': True, 'user_expressions': {}, 'stop_on_error': False}, 'buffers': []}
[Python] [PositronIPKernelApp] {'header': {'msg_id': '83f693de-e033fed825ecaa72112ccdc8_64959_117', 'msg_type': 'execute_reply', 'username': 'wesm', 'session': '83f693de-e033fed825ecaa72112ccdc8', 'date': datetime.datetime(2024, 2, 22, 17, 39, 59, 200371, tzinfo=datetime.timezone.utc), 'version': '5.3'}, 'msg_id': '83f693de-e033fed825ecaa72112ccdc8_64959_117', 'msg_type': 'execute_reply', 'parent_header': {'msg_id': 'fragment-3bd16f2a-3015-4e9f-b929-f0bec8f1658d', 'msg_type': 'execute_request', 'version': '5.0', 'date': datetime.datetime(2024, 2, 22, 17, 39, 59, 193000, tzinfo=tzutc()), 'session': '8a2d97830a920ae2eac452269e9a2233', 'username': 'wesm'}, 'content': {'status': 'ok', 'execution_count': 10, 'user_expressions': {}, 'payload': []}, 'metadata': {'started': datetime.datetime(2024, 2, 22, 17, 39, 59, 197898, tzinfo=datetime.timezone.utc), 'dependencies_met': True, 'engine': 'b5496a6b-7268-47a0-b518-09b8a12fa385', 'status': 'ok'}, 'tracker': <zmq.sugar.tracker.MessageTracker object at 0x1050bba10>}
[Python] [positron._vendor.pygls.protocol.json_rpc] Sending notification: 'textDocument/publishDiagnostics' PublishDiagnosticsParams(uri='inmemory:/repl-python-e7f4720a-1b6e-43f7-b2b9-36247ffb58f2', diagnostics=[], version=None)
[Python] [positron._vendor.pygls.protocol.json_rpc] Sending data: {"params": {"uri": "inmemory:/repl-python-e7f4720a-1b6e-43f7-b2b9-36247ffb58f2", "diagnostics": []}, "method": "textDocument/publishDiagnostics", "jsonrpc": "2.0"}

[seeM]

I reproduced this in R as well. I then tracked it down to the NodeJS fs.watchFile function which defaults the polling interval to 5001 ms (docs).

There is also the fs.watch function which the NodeJS docs recommend:

Using fs.watch() is more efficient than fs.watchFile and fs.unwatchFile. fs.watch should be used instead of fs.watchFile and fs.unwatchFile when possible.

But the same docs also warn that fs.watch is OS-dependent and therefore less reliable 🤷.

Here's the relevant configuration:

https://github.com/posit-dev/positron/blob/e7c19f238643b3cbc0916cd243b56ec895c1d935/extensions/jupyter-adapter/src/JupyterKernel.ts#L1441

What do folks think about switching to fs.watch? Alternatively, we could lower the interval – although I'm not sure what a better value is for this use-case.