From e21772b53a57c2043ab82aa0d3f52715ea4fbbbd Mon Sep 17 00:00:00 2001 From: David Brochart Date: Fri, 28 Feb 2020 14:22:45 +0100 Subject: [PATCH 1/3] Add execution timing in code cell metadata for v4 spec --- nbclient/client.py | 18 ++++++++++++++++-- 1 file changed, 16 insertions(+), 2 deletions(-) diff --git a/nbclient/client.py b/nbclient/client.py index 56236492..8fb70464 100644 --- a/nbclient/client.py +++ b/nbclient/client.py @@ -1,3 +1,4 @@ +import datetime import base64 from textwrap import dedent @@ -17,6 +18,9 @@ from .exceptions import CellTimeoutError, DeadKernelError, CellExecutionComplete, CellExecutionError +def timestamp(): + return datetime.datetime.utcnow().isoformat() + 'Z' + class NotebookClient(LoggingConfigurable): """ Encompasses a Client for executing cells in a notebook @@ -436,6 +440,8 @@ async def _poll_for_reply(self, msg_id, cell, timeout, task_poll_output_msg): try: msg = await self.kc.shell_channel.get_msg(timeout=timeout) if msg['parent_header'].get('msg_id') == msg_id: + if msg['msg_type'] == 'execute_reply': + cell['metadata']['execution']['shell.execute_reply'] = timestamp() try: await asyncio.wait_for(task_poll_output_msg, self.iopub_timeout) except (asyncio.TimeoutError, Empty): @@ -608,6 +614,9 @@ async def async_execute_cell(self, cell, cell_index, execution_count=None, store self.log.debug("Skipping non-executing cell %s", cell_index) return cell + if 'execution' not in cell['metadata']: + cell['metadata']['execution'] = {} + self.log.debug("Executing cell:\n%s", cell.source) parent_msg_id = self.kc.execute( cell.source, store_history=store_history, stop_on_error=not self.allow_errors @@ -674,14 +683,19 @@ def process_message(self, msg, cell, cell_index): if msg_type == 'status': if content['execution_state'] == 'idle': + cell['metadata']['execution']['iopub.status.idle'] = timestamp() raise CellExecutionComplete() + elif content['execution_state'] == 'busy': + cell['metadata']['execution']['iopub.status.busy'] = timestamp() elif msg_type == 'clear_output': self.clear_output(cell.outputs, msg, cell_index) elif msg_type.startswith('comm'): self.handle_comm_msg(cell.outputs, msg, cell_index) + elif msg_type == 'execute_input': + cell['metadata']['execution']['iopub.execute_input'] = timestamp() # Check for remaining messages we don't process - elif msg_type not in ['execute_input', 'update_display_data']: - # Assign output as our processed "result" + elif msg_type != 'update_display_data': + # Assign output as ocell['metadata']['execution']ur processed "result" return self.output(cell.outputs, msg, display_id, cell_index) def output(self, outs, msg, display_id, cell_index): From 232dcfbfe6e880c8b0f4e4154bd5e29916931575 Mon Sep 17 00:00:00 2001 From: David Brochart Date: Fri, 28 Feb 2020 14:56:46 +0100 Subject: [PATCH 2/3] Add record_timing trait --- nbclient/client.py | 33 ++++++++++++++++++++++++--------- 1 file changed, 24 insertions(+), 9 deletions(-) diff --git a/nbclient/client.py b/nbclient/client.py index 8fb70464..724fd4fa 100644 --- a/nbclient/client.py +++ b/nbclient/client.py @@ -21,6 +21,7 @@ def timestamp(): return datetime.datetime.utcnow().isoformat() + 'Z' + class NotebookClient(LoggingConfigurable): """ Encompasses a Client for executing cells in a notebook @@ -148,6 +149,16 @@ class NotebookClient(LoggingConfigurable): ), ).tag(config=True) + record_timing = Bool( + True, + help=dedent( + """ + If `True` (default), then the execution timings of each cell will + be stored in the metadata of the notebook. + """ + ), + ).tag(config=True) + iopub_timeout = Integer( 4, allow_none=False, @@ -440,7 +451,7 @@ async def _poll_for_reply(self, msg_id, cell, timeout, task_poll_output_msg): try: msg = await self.kc.shell_channel.get_msg(timeout=timeout) if msg['parent_header'].get('msg_id') == msg_id: - if msg['msg_type'] == 'execute_reply': + if self.record_timing: cell['metadata']['execution']['shell.execute_reply'] = timestamp() try: await asyncio.wait_for(task_poll_output_msg, self.iopub_timeout) @@ -614,7 +625,7 @@ async def async_execute_cell(self, cell, cell_index, execution_count=None, store self.log.debug("Skipping non-executing cell %s", cell_index) return cell - if 'execution' not in cell['metadata']: + if self.record_timing and 'execution' not in cell['metadata']: cell['metadata']['execution'] = {} self.log.debug("Executing cell:\n%s", cell.source) @@ -681,21 +692,25 @@ def process_message(self, msg, cell, cell_index): if 'execution_count' in content: cell['execution_count'] = content['execution_count'] + if self.record_timing: + if msg_type == 'status': + if content['execution_state'] == 'idle': + cell['metadata']['execution']['iopub.status.idle'] = timestamp() + elif content['execution_state'] == 'busy': + cell['metadata']['execution']['iopub.status.busy'] = timestamp() + elif msg_type == 'execute_input': + cell['metadata']['execution']['iopub.execute_input'] = timestamp() + if msg_type == 'status': if content['execution_state'] == 'idle': - cell['metadata']['execution']['iopub.status.idle'] = timestamp() raise CellExecutionComplete() - elif content['execution_state'] == 'busy': - cell['metadata']['execution']['iopub.status.busy'] = timestamp() elif msg_type == 'clear_output': self.clear_output(cell.outputs, msg, cell_index) elif msg_type.startswith('comm'): self.handle_comm_msg(cell.outputs, msg, cell_index) - elif msg_type == 'execute_input': - cell['metadata']['execution']['iopub.execute_input'] = timestamp() # Check for remaining messages we don't process - elif msg_type != 'update_display_data': - # Assign output as ocell['metadata']['execution']ur processed "result" + elif msg_type not in ['execute_input', 'update_display_data']: + # Assign output as our processed "result" return self.output(cell.outputs, msg, display_id, cell_index) def output(self, outs, msg, display_id, cell_index): From 8f85581604c60920ef4544947c656bfbcaa441d5 Mon Sep 17 00:00:00 2001 From: David Brochart Date: Sat, 29 Feb 2020 17:46:41 +0100 Subject: [PATCH 3/3] Add test --- nbclient/tests/files/Sleep1s.ipynb | 65 ++++++++++++++++++++++++++++++ nbclient/tests/test_client.py | 31 ++++++++++++++ 2 files changed, 96 insertions(+) create mode 100644 nbclient/tests/files/Sleep1s.ipynb diff --git a/nbclient/tests/files/Sleep1s.ipynb b/nbclient/tests/files/Sleep1s.ipynb new file mode 100644 index 00000000..5fcebd97 --- /dev/null +++ b/nbclient/tests/files/Sleep1s.ipynb @@ -0,0 +1,65 @@ +{ + "cells": [ + { + "cell_type": "code", + "execution_count": null, + "metadata": {}, + "outputs": [], + "source": [ + "import time\n", + "import datetime" + ] + }, + { + "cell_type": "code", + "execution_count": null, + "metadata": {}, + "outputs": [], + "source": [ + "t0 = datetime.datetime.utcnow()\n", + "time.sleep(1)\n", + "t1 = datetime.datetime.utcnow()" + ] + }, + { + "cell_type": "code", + "execution_count": null, + "metadata": {}, + "outputs": [], + "source": [ + "time_format = '%Y-%m-%dT%H:%M:%S.%fZ'\n", + "print(t0.strftime(time_format), end='')" + ] + }, + { + "cell_type": "code", + "execution_count": null, + "metadata": {}, + "outputs": [], + "source": [ + "print(t1.strftime(time_format), end='')" + ] + } + ], + "metadata": { + "kernelspec": { + "display_name": "Python 3", + "language": "python", + "name": "python3" + }, + "language_info": { + "codemirror_mode": { + "name": "ipython", + "version": 3 + }, + "file_extension": ".py", + "mimetype": "text/x-python", + "name": "python", + "nbconvert_exporter": "python", + "pygments_lexer": "ipython3", + "version": "3.8.1" + } + }, + "nbformat": 4, + "nbformat_minor": 2 +} diff --git a/nbclient/tests/test_client.py b/nbclient/tests/test_client.py index 75af8a9b..988f8539 100644 --- a/nbclient/tests/test_client.py +++ b/nbclient/tests/test_client.py @@ -5,6 +5,7 @@ import re import threading import asyncio +import datetime import nbformat import sys @@ -354,6 +355,36 @@ def test_many_async_parallel_notebooks(capfd): assert captured.err == "" +def test_execution_timing(): + """Compare the execution timing information stored in the cell with the + actual time it took to run the cell. Also check for the cell timing string + format.""" + opts = dict(kernel_name="python") + input_name = "Sleep1s.ipynb" + input_file = os.path.join(current_dir, "files", input_name) + res = notebook_resources() + input_nb, output_nb = run_notebook(input_file, opts, res) + + def get_time_from_str(s): + time_format = '%Y-%m-%dT%H:%M:%S.%fZ' + return datetime.datetime.strptime(s, time_format) + + execution_timing = output_nb['cells'][1]['metadata']['execution'] + status_busy = get_time_from_str(execution_timing['iopub.status.busy']) + execute_input = get_time_from_str(execution_timing['iopub.execute_input']) + execute_reply = get_time_from_str(execution_timing['shell.execute_reply']) + status_idle = get_time_from_str(execution_timing['iopub.status.idle']) + + cell_start = get_time_from_str(output_nb['cells'][2]['outputs'][0]['text']) + cell_end = get_time_from_str(output_nb['cells'][3]['outputs'][0]['text']) + + delta = datetime.timedelta(milliseconds=100) + assert status_busy - cell_start < delta + assert execute_input - cell_start < delta + assert execute_reply - cell_end < delta + assert status_idle - cell_end < delta + + class TestExecute(NBClientTestsBase): """Contains test functions for execute.py"""