Add execution timings to cell metadata

[saulshanabrook]

Partially addresses #3320 by allowing users to record cell execution timing information.

• Adds Toggle Recording Cell Timing command that sets the recording_timing notebook metadata key to true/false.
• If the record_timing metadata key is true timing information is saved to the cell metadata when a cell is executed.

We record multiple timing events that could be interpreted as "starting" and "ending" execution.

• Starting:
  • timing.iopub.status.busy: header.date of iopub status busy message
  • timing.iopub.execute_input: header.date of iopub execute_input message
  • timing.shell.execute_reply.started: metadata.started of shell execute_reply message
• Ending
  • timing.shell.execute_reply: header.date of shell execute_repl
  • timing.iopub.status.idle: header.date of iopub status busy message

Now third party extensions can use this information to display elapsed time of cell execution. Subsequent work includes:

• Adding semantics of "duration" and "start time" to cell abstraction so that different UXs can display these times (i.e. do we have users choose which key to use as start time and which as end time? With defaults? Or does it make sense to have different durations that correspond to different parts of the execution?)
• Display elapsed time in status bar (depends on merging in status bar first Add status bar to core #5352)
• Figure out UX design for how to enable showing timing on all cells simultaneously.

[saulshanabrook]

@rgbkrk What do you think of this approach to storing event times instead of generic start/end time? xref nteract/papermill#133 nteract/nteract#2660

[ellisonbg]

I think this starts to make sense if there are more than 2 time markers (and thus more than 1 delta to compute). I see that in this PR there are only 2 time markers, what others do you plan to add (if any)?

[saulshanabrook]

I agree. In the next steps section of the issue description I list some other timings, especially a variety of them coming from iopub messages. EDIT: I started adding iopub timings, but ended up having to add something like the [ForeignHandler](https://github.com/saulshanabrook/jupyterlab/blob/203a83acc2f22529621419d43bb9bc3ecdaf26cb/packages/console/src/foreign.ts#L34) iopub message tracking to the notebook, so that new messages that come in can be associated with the proper cell. I would like to merge in some work before starting on that, so that UIs can start to display this and so that we have smaller PRs that are easier to review/merge in.

…

On Tue, Jul 31, 2018, 12:20 AM Brian E. Granger ***@***.***> wrote: I think this starts to make sense if there are more than 2 time markers (and thus more than 1 delta to compute). I see that in this PR there are only 2 time markers, what others do you plan to add (if any)? — You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub <#5009 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/ABIZTDJTGatFiItoJXBGNfsS9-EEcIUjks5uL4aTgaJpZM4VnLX6> .

[ellisonbg]

@saulshanabrook looks like this needs a rebase...

[saulshanabrook]

@ellisonbg Thanks, rebased.

[saulshanabrook]

I have to update the tests on this.

[saulshanabrook]

I am looking into including more timings, maybe available from #5033

[saulshanabrook]

I have rebased this branch and am working on adding the other timings.

[saulshanabrook]

I have done some more experimental investigation of the different websocket messages sent and received when you execute a cell to see what information in them would be useful to save for timings.

I ran "Restart and Run All" on a notebook with time.Sleep(10) in two different cells:

Here is a copy of some relevent info the websocket calls:

# to server
time = 13:07:51.128
    channel = shell
    header.msg_type = execute_request
    header.msg_id = 8032505a-a992-438d-8a23-f0eb45bb3ffd
    content = {"silent":false,"store_history":true,"user_expressions":{},"allow_stdin":true,"stop_on_error":true,"code":"import time"}
time = 13:07:51.129
    channel = shell
    header.msg_type = execute_request
    header.msg_id = cf26f494-8862-4a24-bdb4-680343ca828b
    content = {"silent":false,"store_history":true,"user_expressions":{},"allow_stdin":true,"stop_on_error":true,"code":"time.sleep(10)"}
time = 13:07:51.130
    channel = shell
    header.msg_type = execute_request
    header.msg_id = 163e9eec-7956-46e6-a4fe-85dbafe6b180
    content = {"silent":false,"store_history":true,"user_expressions":{},"allow_stdin":true,"stop_on_error":true,"code":"time.sleep(10)"}

# from server

# these relate to first import command
time = 13:07:51.137
    channel = iopub
    header.msg_type = status
    header.msg_id = 3aae4375-d6965ac8cc77396eb7d2e2f6
    content = {"execution_state":"busy"}
    parent_header.msg_id = 8032505a-a992-438d-8a23-f0eb45bb3ffd
time = 13:07:51.141
    channel = iopub
    header.msg_type = execute_input
    header.msg_id = 6824de00-cc2f5de747326bbd659702f5
    content = {"code":"import time","execution_count":1}
    parent_header.msg_id = 8032505a-a992-438d-8a23-f0eb45bb3ffd
time = 13:07:51.143
    channel = shell
    header.msg_type = execute_reply
    header.msg_id = 4c2029bb-859d1fa39e70bfddbd89f894
    content = {"status":"ok","execution_count":1,"user_expressions":{},"payload":[]}
    parent_header.msg_id = 8032505a-a992-438d-8a23-f0eb45bb3ffd
    metadata.started = 2018-10-04T17:07:51.132017Z
time = 13:07:51.146
    channel = iopub
    header.msg_type = status
    header.msg_id = 7cb7fa63-1f275bcc67fad437b90ddb93
    content = {"execution_state":"idle"}
    parent_header.msg_id = 8032505a-a992-438d-8a23-f0eb45bb3ffd

# first time.sleep(10)
time = 13:07:51.149
    channel = iopub
    header.msg_type = status
    header.msg_id = a152697d-7449744faa574ab12186666b
    content = {"execution_state":"busy"}
    parent_header.msg_id = cf26f494-8862-4a24-bdb4-680343ca828b
time = 13:07:51.151
    channel = iopub
    header.msg_type = execute_input
    header.msg_id = 73820125-edaa1d9373101a1e84689202
    content = {"code":"time.sleep(10)","execution_count":2}
    parent_header.msg_id = cf26f494-8862-4a24-bdb4-680343ca828b
time = 13:08:01.152
    channel = shell
    header.msg_type = execute_reply
    header.msg_id = f2a4ce76-65dafe62b172d977b3f246c3
    content = {"status":"ok","execution_count":2,"user_expressions":{},"payload":[]}
    parent_header.msg_id = cf26f494-8862-4a24-bdb4-680343ca828b
    metadata.started = 2018-10-04T17:07:51.142290Z
time = 13:08:01.154
    channel = iopub
    header.msg_type = status
    header.msg_id = 3165b3cb-4a47e53a4363237da5ee2ec6
    content = {"execution_state":"idle"}
    parent_header.msg_id = cf26f494-8862-4a24-bdb4-680343ca828b

# second time.sleep(10)
time = 13:08:01.155
    channel = iopub
    header.msg_type = status
    header.msg_id = 8142e53c-e4ca4ad3c2c2fe9673e95a07
    content = {"execution_state":"busy"}
    parent_header.msg_id = 163e9eec-7956-46e6-a4fe-85dbafe6b180
time = 13:08:01.158
    channel = iopub
    header.msg_type = execute_input
    header.msg_id = a96d8afb-cd34528790e8f402d8b08bef
    content = {"code":"time.sleep(10)","execution_count":3}
    parent_header.msg_id = 163e9eec-7956-46e6-a4fe-85dbafe6b180
time = 13:08:11.160
    channel = iopub
    header.msg_type = status
    header.msg_id = 517e804b-60af31fbe6fad37a367c6f9e
    content = {"execution_state":"idle"}
    parent_header.msg_id = 163e9eec-7956-46e6-a4fe-85dbafe6b180
time = 13:08:11.162
    channel = shell
    header.msg_type = execute_reply
    header.msg_id = 33749235-172c6bb865726be9da244279
    content = {"status":"ok","execution_count":3,"user_expressions":{},"payload":[]}
    parent_header.msg_id = 163e9eec-7956-46e6-a4fe-85dbafe6b180
    metadata.started = 2018-10-04T17:08:01.152019Z

I produced the body of each call calling this script on the JSON websocket blob, which I accessed by right clicking on it in the chrome debugger and saying store as global variable:

function l(a) {
    console.log(`channel = ${a.channel}
header.msg_type = ${a.header.msg_type}
header.msg_id = ${a.header.msg_id}
${a.content ? `content = ${JSON.stringify(a.content)}
` : ''}${a.parent_header.msg_id ? `parent_header.msg_id = ${a.parent_header.msg_id}
` : ''}${a.metadata.started ? `metadata.started = ${a.metadata.started}
` : ''}
`);
}

[saulshanabrook]

I have added the other timings for the iopub messages.

Here are the metadata keys added that correspond to start times of execution:

• timing.iopub.status.busy: header.date of iopub status busy message
• timing.iopub.execute_input: header.date of iopub execute_input message
• timing.shell.execute_reply.started: metadata.started of shell execute_reply message

And these correspond to end times:

• timing.shell.execute_reply: header.date of shell execute_repl
• timing.iopub.status.idle: header.date of iopub status busy message

[saulshanabrook]

I have to fix some tests and add a way to toggle this on and off.

[saulshanabrook]

OK I added the ability to toggle this on and off with a command. It is saved in the notebook metadata under the record_timing key and defaults to false if that key is not provided.

[rgbkrk]

I think you can both continue on with this PR and on nbformat. This likely does still belong in metadata, though should still be specced in nbformat's json schema. We can still type it as a strong field in the metadata.

If we made it an official field outside the metadata, it would cause a major version bump because there are no allowed additional properties in the cell. Generally people don't want a major version bump of the format without good cause, as it forces breakages to lots of clients and leads to inevitable user support.

[ellisonbg]

+1

…

On Fri, Nov 30, 2018 at 2:06 PM Kyle Kelley ***@***.***> wrote: I think you can both continue on with this PR and on nbformat. This likely does still belong in metadata, though should still be specced in nbformat's json schema <https://github.com/jupyter/nbformat/blob/master/nbformat/v4/nbformat.v4.schema.json>. We can still type it as a strong field in the metadata. If we made it an official field outside the metadata, it would cause a major version bump because there are no allowed additional properties in the cell. Generally people don't want a major version bump of the format without good cause, as it forces breakages to lots of clients and inevitable user support. — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#5009 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AABr0Bn3TH26jsJvcFDJSZaukJNwSCCYks5u0avfgaJpZM4VnLX6> .

-- Brian E. Granger Associate Professor of Physics and Data Science Cal Poly State University, San Luis Obispo @ellisonbg on Twitter and GitHub bgranger@calpoly.edu and ellisonbg@gmail.com

[saulshanabrook]

The next steps on this PR are:

• Put timings in sub dict: Add execution timings to cell metadata #5009 (comment)
• Add timings to metadata spec: Add execution timings to cell metadata #5009 (comment)

If anyone else is wants to get started with this, I am happy to answer any questions for them about how to proceed, working off this branch.

I won't get to this for a bit!

[concretevitamin]

A daily active user here -- this should be P0. Thanks @saulshanabrook for the great work! The org should prioritize this.

[riemannzetagambit]

@saulshanabrook I would be happy to poke around and help out (as this was one of the best add-ons for jupyter notebook), but I can only do so if the changes to make are simple as

1. I am not a js coder
2. I have not contributed to this project yet and don't know how testing and deployment and what not works.

If you think there is something a noob can do (I can write subdicts well enough), please point me in the right direction!

[saulshanabrook]

@riemannzetagambit This would require diving into some typescript coding :) If you are interested in trying it out, we have some notes on how to get started locally. I would recommend using VS Code for an editor as well, because it has great Typescript integration.

[Madhu94]

@saulshanabrook Do you know if anyone is working on this ?

cc @riemannzetagambit

[saulshanabrook]

@Madhu94 I don't believe so.

[saulshanabrook]

@Madhu94 If you or anyone else would like to, I would be happy to provide support.

[Madhu94]

Thanks @saulshanabrook Started on this.

[Madhu94]

I think we should put these into a nested timing sub-dict in the metadata.

Minor clarification - Does the above comment imply a nested subdict? {"timing": {"iopub": {"status": "busy"}, "shell": {...}} vs {"timing": {"iopub.status": "busy", "shell.execute_reply.start": ...}}.

[saulshanabrook]

Closing this in favor of @Madhu94's work in #6864 (thanks!)

[vidartf]

Ok to clean up branch, or should we wait until #6864 is merged?

[saulshanabrook]

Yep! I'll delete it

[williamstein]

We do something similar in cocalc and will try to change our to be compatible with this. See sagemathinc/cocalc#3983.

Note that we always record (and display in a hover) which kernel was used in evaluating the cell. Is there something in the spec (or envisioned for it) that records this? People can change the kernel at any time while going through and evaluating cells...

[rgbkrk]

Wow very true @williamstein, I hadn't thought about taking note of that until now.