fixes #1637

Author: jph00

nbdev/__init__.py

@@ -4,7 +4,7 @@
 
 - `nbdev.extract_attachments`: A preprocessor that extracts all of the attachments from the notebook file. The extracted attachments are returned in the 'resources' dictionary.
 - `nbdev.moddocs`: # Module docs: creating them from existing notebooks
-- `nbdev.skill`: Author clear, executable nbdev notebooks where code, prose, examples, outputs, and tests form one coherent narrative."""
+- `nbdev.skill`: Author clear, executable nbdev notebooks where code, prose, examples, outputs, and tests form one coherent narrative. Trigger: ALWAYS read this before ANY notebook edit."""
 
 __version__ = "3.3.13"
 

nbdev/test.py

@@ -65,7 +65,8 @@ def test_nb(
     verbose=False,  # stream stdout/stderr from cells to console?
     save=False,  # write outputs back to notebook on success?
     profile:bool=None, # load the IPython profile, as `ipykernel` does? (default: `exec_profile` config key)
-    cell_timeout:int=600  # seconds before each cell times out (None: no limit)
+    cell_timeout:int=600, # seconds before each cell times out (None: no limit)
+    cell_timing_min:float=None # print cells slower than this many seconds (None: no timing output)
 ):
     "Execute tests in notebook in `fn` except those with `skip_flags`"
     if not IN_NOTEBOOK and threading.current_thread() is threading.main_thread(): signal.signal(signal.SIGINT, _int_handler)
@@ -86,14 +87,18 @@ def _no_eval(cell):
             if not does_cell_eval(cell, dflt): return True
             return flags & (getattr(cell, 'directives_', {}) or {}).keys()
 
+        def _postproc(cell):
+            elapsed = cell.metadata['execution']['total']
+            if cell_timing_min is not None and elapsed > cell_timing_min: print(f'{fn.name}:{cell.id}: {elapsed:.3f}s')
+
         start = time.time()
         if profile is None: profile = bool(get_config(fn.parent).exec_profile)
         k = CaptureShell(fn, profile=profile)
         _cur_shell[0] = k
         if do_print: print(f'Starting {fn}')
         try:
             with working_directory(fn.parent):
-                k.run_all(nb, exc_stop=True, preproc=_no_eval, verbose=verbose, cell_timeout=cell_timeout)
+                k.run_all(nb, exc_stop=True, preproc=_no_eval, postproc=_postproc, verbose=verbose, cell_timeout=cell_timeout)
                 if save: write_nb(nb, fn)
                 res = True
         except: 
@@ -131,6 +136,7 @@ def nbdev_test(
     verbose:bool=False, # Print stdout/stderr from notebook cells?
     save:bool=False, # Write outputs back to notebooks on success?
     cell_timeout:int=600, # Seconds before each cell times out (0: no limit)
+    cell_timing_min:float=None, # Print cells slower than this many seconds (None: no timing output)
     **kwargs
 ):
     "Test in parallel notebooks matching `path`, passing along `flags`"
@@ -150,7 +156,7 @@ def nbdev_test(
         try:
             results = parallel(test_nb, files, skip_flags=skip_flags, force_flags=force_flags, n_workers=n_workers,
                                basepath=cfg.config_path, pause=pause, do_print=do_print, verbose=verbose, save=save,
-                               cell_timeout=cell_timeout or None, **kw)
+                               cell_timeout=cell_timeout or None, cell_timing_min=cell_timing_min, **kw)
         except KeyboardInterrupt:
             sys.stderr.write('\nnbdev-test interrupted; in-flight notebook stacks shown above\n')
             sys.exit(130)

nbs/api/12_test.ipynb

@@ -109,7 +109,8 @@
     "    verbose=False,  # stream stdout/stderr from cells to console?\n",
     "    save=False,  # write outputs back to notebook on success?\n",
     "    profile:bool=None, # load the IPython profile, as `ipykernel` does? (default: `exec_profile` config key)\n",
-    "    cell_timeout:int=600  # seconds before each cell times out (None: no limit)\n",
+    "    cell_timeout:int=600, # seconds before each cell times out (None: no limit)\n",
+    "    cell_timing_min:float=None # print cells slower than this many seconds (None: no timing output)\n",
     "):\n",
     "    \"Execute tests in notebook in `fn` except those with `skip_flags`\"\n",
     "    if not IN_NOTEBOOK and threading.current_thread() is threading.main_thread(): signal.signal(signal.SIGINT, _int_handler)\n",
@@ -130,14 +131,18 @@
     "            if not does_cell_eval(cell, dflt): return True\n",
     "            return flags & (getattr(cell, 'directives_', {}) or {}).keys()\n",
     "\n",
+    "        def _postproc(cell):\n",
+    "            elapsed = cell.metadata['execution']['total']\n",
+    "            if cell_timing_min is not None and elapsed > cell_timing_min: print(f'{fn.name}:{cell.id}: {elapsed:.3f}s')\n",
+    "\n",
     "        start = time.time()\n",
     "        if profile is None: profile = bool(get_config(fn.parent).exec_profile)\n",
     "        k = CaptureShell(fn, profile=profile)\n",
     "        _cur_shell[0] = k\n",
     "        if do_print: print(f'Starting {fn}')\n",
     "        try:\n",
     "            with working_directory(fn.parent):\n",
-    "                k.run_all(nb, exc_stop=True, preproc=_no_eval, verbose=verbose, cell_timeout=cell_timeout)\n",
+    "                k.run_all(nb, exc_stop=True, preproc=_no_eval, postproc=_postproc, verbose=verbose, cell_timeout=cell_timeout)\n",
     "                if save: write_nb(nb, fn)\n",
     "                res = True\n",
     "        except: \n",
@@ -211,6 +216,14 @@
     "from fastcore.xtras import modified_env"
    ]
   },
+  {
+   "cell_type": "markdown",
+   "id": "bae187da",
+   "metadata": {},
+   "source": [
+    "Pass `cell_timing_min` to identify slow cells without flooding ordinary test output. Each cell over the threshold prints its notebook name, stable cell id, and elapsed seconds; `--cell-timing-min=0.1` is a useful first pass."
+   ]
+  },
   {
    "cell_type": "markdown",
    "id": "e3e69d17",
@@ -283,6 +296,7 @@
     "    verbose:bool=False, # Print stdout/stderr from notebook cells?\n",
     "    save:bool=False, # Write outputs back to notebooks on success?\n",
     "    cell_timeout:int=600, # Seconds before each cell times out (0: no limit)\n",
+    "    cell_timing_min:float=None, # Print cells slower than this many seconds (None: no timing output)\n",
     "    **kwargs\n",
     "):\n",
     "    \"Test in parallel notebooks matching `path`, passing along `flags`\"\n",
@@ -302,7 +316,7 @@
     "        try:\n",
     "            results = parallel(test_nb, files, skip_flags=skip_flags, force_flags=force_flags, n_workers=n_workers,\n",
     "                               basepath=cfg.config_path, pause=pause, do_print=do_print, verbose=verbose, save=save,\n",
-    "                               cell_timeout=cell_timeout or None, **kw)\n",
+    "                               cell_timeout=cell_timeout or None, cell_timing_min=cell_timing_min, **kw)\n",
     "        except KeyboardInterrupt:\n",
     "            sys.stderr.write('\\nnbdev-test interrupted; in-flight notebook stacks shown above\\n')\n",
     "            sys.exit(130)\n",

pyproject.toml

@@ -19,7 +19,7 @@ classifiers = [
     "License :: OSI Approved :: Apache Software License",
 ]
 dynamic = ["version"]
-dependencies = [ "fastcore>=2.2.7", "execnb>=0.3.2", "astunparse", "ghapi>=2.0.2", "watchdog", "asttokens",
+dependencies = [ "fastcore>=2.2.7", "execnb>=0.3.3", "astunparse", "ghapi>=2.0.2", "watchdog", "asttokens",
     "setuptools", "build", "fastgit>=0.0.7", "pyyaml", "tomli; python_version < '3.11'", ]
 
 [project.optional-dependencies]