✨ Capture filter processing times (#1240)

This commit adds capturing of origin location and runtimes of each call to `process_filters`.

For `needs_debug_measurement=True` it also outputs this data to `<outdir>/debug_filters.json`, and
prints the 10 longest running filters to stdout

docs/conf.py

@@ -288,7 +288,7 @@
 
 # -- Options for Needs extension ---------------------------------------
 
-needs_debug_measurement = False
+needs_debug_measurement = "READTHEDOCS" in os.environ  # run on CI
 
 needs_types = [
     # Architecture types

pyproject.toml

@@ -201,6 +201,7 @@ extras =
 passenv =
     BUILDER
     CLEAN
+    READTHEDOCS
     TERM
 setenv =
     alabaster: DOCS_THEME=alabaster

sphinx_needs/data.py

@@ -28,10 +28,15 @@ class NeedsFilterType(TypedDict):
     status: list[str]
     tags: list[str]
     types: list[str]
-    result: list[str]
     amount: int
     export_id: str
     """If set, the filter is exported with this ID in the needs.json file."""
+    origin: str
+    """Origin of the request (e.g. needlist, needtable, needflow)."""
+    location: str
+    """Location of the request (e.g. "docname:lineno")"""
+    runtime: float
+    """Time take to run filter (seconds)."""
 
 
 class NeedsPartType(TypedDict):
@@ -792,13 +797,19 @@ def merge_data(
 
     Needs to update env manually for all data Sphinx-Needs collect during read phase
     """
+    this_data = SphinxNeedsData(env)
+    other_data = SphinxNeedsData(other)
 
-    if SphinxNeedsData(other).has_export_filters:
-        SphinxNeedsData(env).has_export_filters = True
+    # update filters
+    if other_data.has_export_filters:
+        this_data.has_export_filters = True
+    # merge these just to be safe,
+    # although actually all should be added in the write phase
+    this_data.get_or_create_filters().update(other_data.get_or_create_filters())
 
     # Update needs
-    needs = SphinxNeedsData(env).get_or_create_needs()
-    other_needs = SphinxNeedsData(other).get_or_create_needs()
+    needs = this_data.get_or_create_needs()
+    other_needs = other_data.get_or_create_needs()
     for other_id, other_need in other_needs.items():
         if other_id in needs:
             # we only want to warn if the need comes from one of the docs parsed in this worker

sphinx_needs/debug.py

@@ -17,6 +17,8 @@
 from jinja2 import Environment, PackageLoader, select_autoescape
 from sphinx.application import Sphinx
 
+from sphinx_needs.data import SphinxNeedsData
+
 TIME_MEASUREMENTS: dict[str, Any] = {}  # Stores the timing results
 EXECUTE_TIME_MEASUREMENTS = (
     False  # Will be used to de/activate measurements. Set during a Sphinx Event
@@ -146,7 +148,7 @@ def measure_time_func(
     return measure_time(category, source, name)(func)
 
 
-def print_timing_results() -> None:
+def _print_timing_results(app: Sphinx) -> None:
     for value in TIME_MEASUREMENTS.values():
         print(value["name"])
         print(f' amount:  {value["amount"]}')
@@ -155,9 +157,21 @@ def print_timing_results() -> None:
         print(f' max:     {value["max"]:2f}')
         print(f' min:     {value["min"]:2f} \n')
 
+    # print 10 slowest filters
+    filters = sorted(
+        SphinxNeedsData(app.env).get_or_create_filters().values(),
+        key=lambda x: x["runtime"],
+        reverse=True,
+    )
+    if filters:
+        print("Slowest need filters:")
+        for filter in filters[:10]:
+            print(f'{filter["location"]}: {filter["runtime"]:2f}s ({filter["origin"]})')
+        print("")
+
 
-def store_timing_results_json(outdir: str, build_data: dict[str, Any]) -> None:
-    json_result_path = os.path.join(outdir, "debug_measurement.json")
+def _store_timing_results_json(app: Sphinx, build_data: dict[str, Any]) -> None:
+    json_result_path = os.path.join(str(app.outdir), "debug_measurement.json")
 
     data = {"build": build_data, "measurements": TIME_MEASUREMENTS}
 
@@ -166,12 +180,22 @@ def store_timing_results_json(outdir: str, build_data: dict[str, Any]) -> None:
     print(f"Timing measurement results (JSON) stored under {json_result_path}")
 
 
-def store_timing_results_html(outdir: str, build_data: dict[str, Any]) -> None:
+def _store_filter_results_json(app: Sphinx) -> None:
+    json_result_path = os.path.join(str(app.outdir), "debug_filters.json")
+
+    data = SphinxNeedsData(app.env).get_or_create_filters()
+
+    with open(json_result_path, "w", encoding="utf-8") as f:
+        json.dump(data, f, indent=4)
+    print(f"Filter results (JSON) stored under {json_result_path}")
+
+
+def _store_timing_results_html(app: Sphinx, build_data: dict[str, Any]) -> None:
     jinja_env = Environment(
         loader=PackageLoader("sphinx_needs"), autoescape=select_autoescape()
     )
     template = jinja_env.get_template("time_measurements.html")
-    out_file = Path(outdir) / "debug_measurement.html"
+    out_file = Path(str(app.outdir)) / "debug_measurement.html"
     with open(out_file, "w", encoding="utf-8") as f:
         f.write(template.render(data=TIME_MEASUREMENTS, build_data=build_data))
     print(f"Timing measurement report (HTML) stored under {out_file}")
@@ -187,6 +211,7 @@ def process_timing(app: Sphinx, _exception: Exception | None) -> None:
             "timestamp": datetime.now().isoformat(),
         }
 
-        print_timing_results()
-        store_timing_results_json(app.outdir, build_data)
-        store_timing_results_html(app.outdir, build_data)
+        _print_timing_results(app)
+        _store_timing_results_json(app, build_data)
+        _store_filter_results_json(app)
+        _store_timing_results_html(app, build_data)

sphinx_needs/directives/needextract.py

@@ -106,7 +106,13 @@ def process_needextract(
                 )
             current_needextract["filter"] = need_filter_arg
 
-        found_needs = process_filters(app, all_needs.values(), current_needextract)
+        found_needs = process_filters(
+            app,
+            all_needs.values(),
+            current_needextract,
+            origin="needextract",
+            location=f"{node.source}:{node.line}",
+        )
 
         for need_info in found_needs:
             # filter out need_part from found_needs, in order to generate

sphinx_needs/directives/needfilter.py

@@ -158,7 +158,13 @@ def process_needfilters(
             tgroup += tbody
             content += tgroup
 
-        found_needs = process_filters(app, all_needs.values(), current_needfilter)
+        found_needs = process_filters(
+            app,
+            all_needs.values(),
+            current_needfilter,
+            origin="needfilter",
+            location=f"{node.source}:{node.line}",
+        )
 
         line_block = nodes.line_block()
         for need_info in found_needs:

sphinx_needs/directives/needflow/_graphviz.py

@@ -120,7 +120,13 @@ def process_needflow_graphviz(
             if (root_id := attributes["root_id"])
             else all_needs.values()
         )
-        filtered_needs = process_filters(app, init_filtered_needs, node.attributes)
+        filtered_needs = process_filters(
+            app,
+            init_filtered_needs,
+            node.attributes,
+            origin="needflow",
+            location=f"{node.source}:{node.line}",
+        )
 
         if not filtered_needs:
             node.replace_self(

sphinx_needs/directives/needflow/_plantuml.py

@@ -275,7 +275,13 @@ def process_needflow_plantuml(
             else all_needs.values()
         )
 
-        found_needs = process_filters(app, need_values, current_needflow)
+        found_needs = process_filters(
+            app,
+            need_values,
+            current_needflow,
+            origin="needflow",
+            location=f"{node.source}:{node.line}",
+        )
 
         if found_needs:
             plantuml_block_text = ".. plantuml::\n" "\n" "   @startuml" "   @enduml"

sphinx_needs/directives/needgantt.py

@@ -195,7 +195,13 @@ def process_needgantt(
         puml_node["uml"] += add_config(config)
 
         all_needs = list(all_needs_dict.values())
-        found_needs = process_filters(app, all_needs, current_needgantt)
+        found_needs = process_filters(
+            app,
+            all_needs,
+            current_needgantt,
+            origin="needgantt",
+            location=f"{node.source}:{node.line}",
+        )
 
         # Scale/timeline handling
         if current_needgantt["timeline"]:

sphinx_needs/directives/needlist.py

@@ -86,7 +86,13 @@ def process_needlist(
         current_needfilter: NeedsListType = node.attributes
         content: list[nodes.Node] = []
         all_needs = list(SphinxNeedsData(env).get_or_create_needs().values())
-        found_needs = process_filters(app, all_needs, current_needfilter)
+        found_needs = process_filters(
+            app,
+            all_needs,
+            current_needfilter,
+            origin="needlist",
+            location=f"{node.source}:{node.line}",
+        )
 
         if len(found_needs) > 0:
             line_block = nodes.line_block()

sphinx_needs/directives/needtable.py

@@ -210,12 +210,13 @@ def process_needtables(
         table_node.line = current_needtable["lineno"]
 
         # Perform filtering of needs
-        try:
-            filtered_needs = process_filters(
-                app, list(all_needs.values()), current_needtable
-            )
-        except Exception as e:
-            raise e
+        filtered_needs = process_filters(
+            app,
+            list(all_needs.values()),
+            current_needtable,
+            origin="needtable",
+            location=f"{node.source}:{node.line}",
+        )
 
         def get_sorter(key: str) -> Callable[[NeedsInfoType], Any]:
             """

sphinx_needs/filter_common.py

@@ -6,6 +6,7 @@
 from __future__ import annotations
 
 import re
+from timeit import default_timer as timer
 from types import CodeType
 from typing import Any, Iterable, TypedDict, TypeVar
 
@@ -101,6 +102,8 @@ def process_filters(
     app: Sphinx,
     all_needs: Iterable[NeedsInfoType],
     filter_data: NeedsFilteredBaseType,
+    origin: str,
+    location: str,
     include_external: bool = True,
 ) -> list[NeedsInfoType]:
     """
@@ -110,10 +113,13 @@ def process_filters(
     :param app: Sphinx application object
     :param filter_data: Filter configuration
     :param all_needs: List of all needs inside document
+    :param origin: Origin of the request (e.g. needlist, needtable, needflow)
+    :param location: Location of the request (e.g. "docname:lineno")
     :param include_external: Boolean, which decides to include external needs or not
 
     :return: list of needs, which passed the filters
     """
+    start = timer()
     needs_config = NeedsSphinxConfig(app.config)
     found_needs: list[NeedsInfoType]
     sort_key = filter_data["sort_by"]
@@ -242,16 +248,17 @@ def process_filters(
     # Store basic filter configuration and result global list.
     # Needed mainly for exporting the result to needs.json (if builder "needs" is used).
     filter_list = SphinxNeedsData(app.env).get_or_create_filters()
-    found_needs_ids = [need["id_complete"] for need in found_needs]
 
     filter_list[filter_data["target_id"]] = {
+        "origin": origin,
+        "location": location,
         "filter": filter_data["filter"] or "",
         "status": filter_data["status"],
         "tags": filter_data["tags"],
         "types": filter_data["types"],
         "export_id": filter_data["export_id"].upper(),
-        "result": found_needs_ids,
-        "amount": len(found_needs_ids),
+        "amount": len(found_needs),
+        "runtime": timer() - start,
     }
 
     return found_needs

tests/__snapshots__/test_export_id.ambr

@@ -8,18 +8,7 @@
             'amount': 10,
             'export_id': 'FLOW_1',
             'filter': '',
-            'result': list([
-              'REQ_001',
-              'REQ_002',
-              'REQ_003',
-              'REQ_004',
-              'REQ_005',
-              'TEST_001',
-              'TEST_002',
-              'TEST_003',
-              'REQ_005.1',
-              'REQ_005.cool',
-            ]),
+            'origin': 'needflow',
             'status': list([
             ]),
             'tags': list([
@@ -31,13 +20,7 @@
             'amount': 5,
             'export_id': 'FLOW_2',
             'filter': 'is_need is False or type != "story"',
-            'result': list([
-              'TEST_001',
-              'TEST_002',
-              'TEST_003',
-              'REQ_005.1',
-              'REQ_005.cool',
-            ]),
+            'origin': 'needflow',
             'status': list([
             ]),
             'tags': list([
@@ -49,18 +32,7 @@
             'amount': 10,
             'export_id': 'LIST_1',
             'filter': '',
-            'result': list([
-              'REQ_001',
-              'REQ_002',
-              'REQ_003',
-              'REQ_004',
-              'REQ_005',
-              'TEST_001',
-              'TEST_002',
-              'TEST_003',
-              'REQ_005.1',
-              'REQ_005.cool',
-            ]),
+            'origin': 'needlist',
             'status': list([
             ]),
             'tags': list([
@@ -72,18 +44,7 @@
             'amount': 10,
             'export_id': 'TABLE_1',
             'filter': '',
-            'result': list([
-              'REQ_001',
-              'REQ_002',
-              'REQ_003',
-              'REQ_004',
-              'REQ_005',
-              'TEST_001',
-              'TEST_002',
-              'TEST_003',
-              'REQ_005.1',
-              'REQ_005.cool',
-            ]),
+            'origin': 'needtable',
             'status': list([
             ]),
             'tags': list([
@@ -95,11 +56,7 @@
             'amount': 3,
             'export_id': 'TABLE_2',
             'filter': '"test" in type',
-            'result': list([
-              'TEST_001',
-              'TEST_002',
-              'TEST_003',
-            ]),
+            'origin': 'needtable',
             'status': list([
             ]),
             'tags': list([

tests/test_export_id.py

@@ -15,7 +15,9 @@ def test_export_id(test_app, snapshot):
     app = test_app
     app.build()
     needs_data = json.loads(Path(app.outdir, "needs.json").read_text())
-    assert needs_data == snapshot(exclude=props("created", "project"))
+    assert needs_data == snapshot(
+        exclude=props("created", "project", "location", "runtime")
+    )
 
 
 @pytest.mark.parametrize(