Fix fluctuation of execute time when re-executing a cell (#112)

.github/workflows/build.yml

@@ -108,7 +108,7 @@ jobs:
     - name: Install the extension
       run: |
         set -eux
-        python -m pip install "jupyterlab>=4.0.0,<5" jupyterlab_execute_time*.whl
+        python -m pip install "jupyterlab>=4.1.0rc1,<5" jupyterlab_execute_time*.whl
 
     - name: Install dependencies
       working-directory: ui-tests

.github/workflows/update-integration-tests.yml

@@ -34,7 +34,7 @@ jobs:
         uses: jupyterlab/maintainer-tools/.github/actions/base-setup@v1
 
       - name: Install dependencies
-        run: python -m pip install -U "jupyterlab>=4.0.0,<5"
+        run: python -m pip install -U "jupyterlab>=4.1.0rc1,<5"
 
       - name: Install extension
         run: |

CHANGELOG.md

@@ -1,3 +1,9 @@
+## [3.1.2](https://github.com/deshaw/jupyterlab-execute-time/compare/v3.1.0...v3.1.2) (unreleased)
+
+### Fixed
+
+- Fix fluctuation of execute time when re-executing a cell [#112](https://github.com/deshaw/jupyterlab-execute-time/pull/112)
+
 ## [3.1.1](https://github.com/deshaw/jupyterlab-execute-time/compare/v3.1.0...v3.1.1) (2024-01-29)
 
 ### Fixed

src/ExecuteTimeWidget.ts

@@ -343,7 +343,8 @@ export default class ExecuteTimeWidget extends Widget {
             const executionMetadata = cell.model.getMetadata(
               'execution'
             ) as JSONObject;
-            if (executionMetadata['execution_failed']) {
+            if (!executionMetadata || executionMetadata['execution_failed']) {
+              // (if cell got re-scheduled the metadata will be empty too)
               clearInterval(workingTimer);
               return this._updateCodeCell(cell, disableHighlight);
             }

ui-tests/package.json

@@ -9,7 +9,7 @@
     "test:update": "jlpm playwright test --update-snapshots"
   },
   "devDependencies": {
-    "@jupyterlab/galata": "^5.0.5",
-    "@playwright/test": "^1.37.0"
+    "@jupyterlab/galata": "^5.1.0-rc.1",
+    "@playwright/test": "^1.32.2"
   }
 }

ui-tests/playwright.config.js

@@ -11,5 +11,5 @@ module.exports = {
     timeout: 120 * 1000,
     reuseExistingServer: !process.env.CI,
   },
-  retries: process.env.CI ? 1 : 0
+  retries: process.env.CI ? 1 : 0,
 };

ui-tests/tests/cell_operations.spec.ts

@@ -1,5 +1,5 @@
 import { expect, galata, test } from '@jupyterlab/galata';
-import { openNotebook, cleanup } from './utils';
+import { openNotebook, cleanup, watchTimeIncrease } from './utils';
 
 const NOTEBOOK_ID = '@jupyterlab/notebook-extension:tracker';
 
@@ -30,4 +30,41 @@ test.describe('Cell operations', () => {
     // Four cells should now have the widget
     expect(await page.locator('.execute-time').count()).toBe(4);
   });
+
+  test('Re-run a cell that is already running', async ({ page }) => {
+    // Run `from time import sleep`
+    await page.notebook.runCell(0, true);
+
+    // Define locators
+    const cellLocator = page.locator('.jp-Cell[data-windowed-list-index="1"]');
+    const widgetLocator = cellLocator.locator('.execute-time');
+
+    // Increase the sleep interval to eight seconds to catch it in flight
+    await page.notebook.setCell(1, 'code', 'sleep(8)');
+
+    // Execute the cell, but do not wait for it to finish
+    const firstRunPromise = page.notebook.runCell(1, true);
+
+    // Wait for the widget to show up
+    await widgetLocator.waitFor();
+
+    // Execute the cell again
+    const secondRunPromise = page.notebook.runCell(1, true);
+
+    // Expect the widget to be gone
+    await expect(widgetLocator).toBeHidden();
+
+    // Wait for the widget to show up again (after the first cell finishes)
+    await widgetLocator.waitFor();
+
+    // Expect at least 50 updates, and every subsequent update to be monotonically increasing
+    const wasMonotonicallyIncreasing = await watchTimeIncrease(cellLocator, {
+      minimumTicks: 50,
+      timeout: 10 * 1000,
+    });
+    expect(wasMonotonicallyIncreasing).toBe(true);
+
+    // Wait for the execution to finish before closing the test for clean teardown.
+    await Promise.all([firstRunPromise, secondRunPromise]);
+  });
 });

ui-tests/tests/timing_outcomes.spec.ts

@@ -42,7 +42,7 @@ test.describe('Timing outcomes', () => {
   });
 
   // Skipped for now as this requires JupyterLab 4.1.
-  test.skip('"Failed" state', async ({ page }) => {
+  test('"Failed" state', async ({ page }) => {
     const cell = await page.notebook.getCell(6);
 
     // Execute cell manually without waiting for it to complete

ui-tests/tests/utils.ts

@@ -1,4 +1,4 @@
-import { Page, ElementHandle } from 'playwright';
+import { Page, ElementHandle, Locator } from 'playwright';
 import * as path from 'path';
 
 /**
@@ -63,3 +63,91 @@ export async function maskedScreenshot(
   });
   return blob;
 }
+
+interface ITimeWatchingOptions {
+  minimumTicks: number;
+  timeout: number;
+}
+
+/**
+ * Watch updates to the execute time widget of a cell, recording if the updates
+ * are monotonically increasing (the return value). The promise will reject if
+ * the `timeout` is exceeded, or less than `minimumTicks` updates are seen.
+ */
+export async function watchTimeIncrease(
+  cell: Locator,
+  options: ITimeWatchingOptions
+): Promise<boolean> {
+  return cell.evaluate<Promise<boolean>, ITimeWatchingOptions, HTMLElement>(
+    async (cellNode: HTMLElement, options: ITimeWatchingOptions) => {
+      let updatesCount = 1;
+
+      const matchTime = (node: HTMLElement, regex: RegExp): number => {
+        const result = node.innerText.match(regex);
+        if (result === null) {
+          return NaN;
+        }
+        return parseFloat(result[0]);
+      };
+
+      const completedPromise = new Promise<boolean>((resolve, reject) => {
+        let lastTimeMs = 0;
+        const observer = new MutationObserver(() => {
+          const node = cellNode.querySelector('.execute-time') as HTMLElement;
+          // Stop condition
+          if (node.innerText.includes('Last executed')) {
+            if (updatesCount >= options.minimumTicks) {
+              observer.disconnect();
+              return resolve(true);
+            } else {
+              observer.disconnect();
+              return reject(
+                `Only ${updatesCount} updates seen, expected at least ${options.minimumTicks}`
+              );
+            }
+          } else {
+            // Parse the time
+            let milliseconds = matchTime(node, /(\d+)ms ?/);
+            const seconds = matchTime(node, /(\d\.\d+)s ?/);
+            if (isNaN(milliseconds) && !isNaN(seconds)) {
+              milliseconds = seconds * 1000;
+            }
+            if (isNaN(milliseconds)) {
+              observer.disconnect();
+              return reject(
+                `Could not parse seconds nor milliseconds from ${node.innerText}`
+              );
+            }
+            if (lastTimeMs > milliseconds) {
+              observer.disconnect();
+              return reject(
+                `Non-increasing time delta seen, from ${lastTimeMs}ms to ${milliseconds}ms in ${updatesCount} update`
+              );
+            }
+            lastTimeMs = milliseconds;
+          }
+          // Only update at the end to ensure we do not increase the counter if the above code errors out
+          updatesCount += 1;
+        });
+        observer.observe(cellNode, {
+          childList: true,
+          subtree: true,
+          characterData: true,
+        });
+      });
+      const timeoutPromise = new Promise<boolean>((_resolve, reject) =>
+        setTimeout(
+          () =>
+            reject(
+              `Timeout of ${options.timeout}ms exceeded with ${
+                updatesCount - 1
+              } updates processed`
+            ),
+          options.timeout
+        )
+      );
+      return Promise.race([completedPromise, timeoutPromise]);
+    },
+    options
+  );
+}

ui-tests/tests/windowed_notebook.spec.ts

@@ -28,7 +28,7 @@ test.describe('Windowed notebook', () => {
     expect(await widgetLocator.isHidden()).toBeTruthy();
     // Scroll to the 100th cell
     await page.notebook.getCell(100);
-    // The widget should not be shown
+    // The widget should be shown
     expect(await widgetLocator.isHidden()).toBeFalsy();
     // The widget should be in "executed" state
     expect(await widgetLocator.textContent()).toContain('Last executed at');