performance logging

core/nodeslicer/nodes/system.py

@@ -172,6 +172,7 @@ class SLICENODE_Executor(ExecSliceNode, SliceNodeJoiner):
     socket_type = "SLICESOCK_ExecutionLink"
 
     auto_refresh: bool = NfBoolProperty(name="Auto-refresh", default=False)
+    log: bool = NfBoolProperty(name="Monitor Performance", default=False, description="Monitor performance statistics to open text editor")
 
     def init(self, context):
         self._init_exec()
@@ -180,13 +181,20 @@ class SLICENODE_Executor(ExecSliceNode, SliceNodeJoiner):
     def draw_buttons(self, context, layout):
         super().draw_buttons(context, layout)
         layout.prop(self, "auto_refresh")
+        layout.prop(self, "log")
 
     def evaluate(self, operator=None):
         from ....infra.blender.blender_slice_nodes_generic import (
             execution_cache,
+            profiler_context,
+            profile_node_execution,
+            show_in_text_editor,
             resolve_input
         )
 
+        profiling_enabled = getattr(self, "log", False)
+
+        def _run_jobs():
             for i, job in enumerate(self.inputs):
                 # Resolve the input to get the connected node(s)
                 res = resolve_input(job)
@@ -205,6 +213,7 @@ class SLICENODE_Executor(ExecSliceNode, SliceNodeJoiner):
                     
                     try:
                         with execution_cache():
+                            with profile_node_execution(upstream_node):
                                 exec_res = upstream_node.evaluate(operator=operator)
                                 if exec_res != 'ok' and exec_res is not None:
                                      if operator: operator.report({'WARNING'}, f"Node {upstream_node.bl_label} returned {exec_res}")
@@ -214,6 +223,15 @@ class SLICENODE_Executor(ExecSliceNode, SliceNodeJoiner):
 
             return 'ok'
 
+        if profiling_enabled:
+            with profiler_context() as profiler:
+                result = _run_jobs()
+                table_str = profiler.format_table()
+                show_in_text_editor("Performance", table_str)
+                return result
+        else:
+            return _run_jobs()
+
 @register_class
 class SLICENODE_JoinSettings(SliceNodeJoiner):
     bl_label = "Join Settings"

doc/NODES.md

@@ -189,4 +189,6 @@ All nodes are found in the **Add (Shift+A)** menu under the **SliceNodes** categ
     - **Gcode Field**: The name of the attachment field in Airtable.
 - **Gcode to Preview Mesh**: Decodes G-code and creates a Blender mesh ("Debug" object) for visualization. 
 - **Executor**: Executes sub-tree node chains.
+    - **Auto-refresh**: Automatically re-evaluates the connected subtrees whenever scene objects or node tree dependencies change.
+    - **Log**: Calculates and profiles execution performance across all evaluated nodes, outputting a summary table (`node_type`, `execution_count`, `avg_execution_time`, `tot_execution_time`) into the "Performance" text block in an open text editor.
 - **Test**: Triggers evaluation for debugging purposes.

infra/blender/blender_slice_nodes_generic.py

@@ -1,5 +1,6 @@
 from __future__ import annotations
 from dataclasses import field
+import time
 import typing
 from typing import Any, cast
 import bpy
@@ -226,6 +227,153 @@ class SliceNode(Node, AutoBlIdName):
 
 _current_execution_cache: _EvalCache | None = None
 
+def get_node_type(node: Any) -> str:
+    if hasattr(node, "bl_label") and node.bl_label:
+        return str(node.bl_label)
+    if hasattr(node, "bl_idname") and node.bl_idname:
+        return str(node.bl_idname)
+    return type(node).__name__
+
+class NodeProfiler:
+    def __init__(self) -> None:
+        # Maps node_type -> [execution_count, total_self_time_seconds]
+        self.stats: dict[str, list[float]] = {}
+        self._stack: list[dict[str, Any]] = []
+
+    @contextmanager
+    def profile_node(self, node: Any):
+        node_type = get_node_type(node)
+        now = time.perf_counter()
+
+        # Pause parent node's self-timer
+        if self._stack:
+            parent = self._stack[-1]
+            parent["self_time"] += (now - parent["start_time"])
+
+        frame = {
+            "node_type": node_type,
+            "start_time": now,
+            "self_time": 0.0,
+        }
+        self._stack.append(frame)
+        try:
+            yield
+        finally:
+            end_time = time.perf_counter()
+            popped = self._stack.pop()
+            total_node_self_time = popped["self_time"] + (end_time - popped["start_time"])
+
+            if node_type not in self.stats:
+                self.stats[node_type] = [0.0, 0.0]
+            self.stats[node_type][0] += 1.0
+            self.stats[node_type][1] += total_node_self_time
+
+            # Resume parent node's timer
+            if self._stack:
+                self._stack[-1]["start_time"] = time.perf_counter()
+
+    def format_table(self) -> str:
+        headers = ["node_type", "execution_count", "avg_execution_time", "tot_execution_time"]
+
+        if not self.stats:
+            col_widths = [20, 15, 18, 18]
+            header_line = " | ".join(headers[i].ljust(col_widths[i]) for i in range(4))
+            separator_line = "-+-".join("-" * col_widths[i] for i in range(4))
+            return f"{header_line}\n{separator_line}\n(No nodes executed)"
+
+        sorted_stats = sorted(self.stats.items(), key=lambda item: item[1][1], reverse=True)
+
+        rows: list[list[str]] = []
+        tot_count = 0
+        tot_time_all = 0.0
+
+        for node_type, (count, tot_time) in sorted_stats:
+            icount = int(count)
+            tot_count += icount
+            tot_time_all += tot_time
+            avg_time = tot_time / icount if icount > 0 else 0.0
+            rows.append([
+                node_type,
+                str(icount),
+                f"{avg_time:.6f}s",
+                f"{tot_time:.6f}s",
+            ])
+
+        col_widths = [
+            max(len(headers[i]), max(len(row[i]) for row in rows))
+            for i in range(4)
+        ]
+        col_widths[0] = max(col_widths[0], len("Total"))
+        col_widths[1] = max(col_widths[1], len(str(tot_count)))
+        col_widths[3] = max(col_widths[3], len(f"{tot_time_all:.6f}s"))
+
+        lines: list[str] = []
+        header_line = " | ".join(headers[i].ljust(col_widths[i]) for i in range(4))
+        separator_line = "-+-".join("-" * col_widths[i] for i in range(4))
+
+        lines.append(header_line)
+        lines.append(separator_line)
+        for row in rows:
+            lines.append(" | ".join([
+                row[0].ljust(col_widths[0]),
+                row[1].rjust(col_widths[1]),
+                row[2].rjust(col_widths[2]),
+                row[3].rjust(col_widths[3]),
+            ]))
+        lines.append(separator_line)
+        total_row = [
+            "Total".ljust(col_widths[0]),
+            str(tot_count).rjust(col_widths[1]),
+            "-".rjust(col_widths[2]),
+            f"{tot_time_all:.6f}s".rjust(col_widths[3]),
+        ]
+        lines.append(" | ".join(total_row))
+
+        return "\n".join(lines)
+
+
+_current_profiler: NodeProfiler | None = None
+
+@contextmanager
+def profiler_context():
+    global _current_profiler
+    old = _current_profiler
+    profiler = NodeProfiler()
+    _current_profiler = profiler
+    try:
+        yield profiler
+    finally:
+        _current_profiler = old
+
+@contextmanager
+def profile_node_execution(node: Any):
+    if _current_profiler is None:
+        yield
+        return
+    with _current_profiler.profile_node(node):
+        yield
+
+def show_in_text_editor(name: str, content: str) -> Any:
+    try:
+        text_block = bpy.data.texts.get(name)
+        if text_block is None:
+            text_block = bpy.data.texts.new(name=name)
+        text_block.from_string(content)
+
+        wm = getattr(bpy.context, "window_manager", None)
+        if wm and hasattr(wm, "windows"):
+            for window in wm.windows:
+                if hasattr(window, "screen") and window.screen and hasattr(window.screen, "areas"):
+                    for area in window.screen.areas:
+                        if getattr(area, "type", "") == 'TEXT_EDITOR':
+                            for space in getattr(area, "spaces", []):
+                                if getattr(space, "type", "") == 'TEXT_EDITOR':
+                                    space.text = text_block
+        return text_block
+    except Exception as e:
+        print(f"Error displaying in text editor: {e}")
+        return None
+
 @contextmanager
 def execution_cache():
     global _current_execution_cache
@@ -499,6 +647,7 @@ def _resolve_output(
     visited.add(node_key)
     try:
         with execution_cache():
+            with profile_node_execution(socket.node):
                 if not isinstance(socket.node, SliceNode):
                     is_group = isinstance(socket.node, SLICENODE_Group) or (
                         isinstance(getattr(bpy.types, "NodeGroup", None), type) and isinstance(socket.node, bpy.types.NodeGroup)

tests/test_performance.py

@@ -0,0 +1,223 @@
+import unittest
+from unittest.mock import MagicMock, patch
+import time
+from pathlib import Path
+import sys
+
+PROJECT_ROOT = Path(__file__).resolve().parent.parent
+sys.path.append(str(PROJECT_ROOT.parent))
+
+class DummyNodeSocket:
+    def __init__(self, name=""):
+        self.name = name
+        self.identifier = name
+        self.is_linked = False
+        self.links = []
+        self.default = None
+        self.node = None
+
+class DummyNode:
+    def __init__(self, name: str = "Node", label: str = "", idname: str = ""):
+        self.name = name
+        if label:
+            self.bl_label = label
+        if idname:
+            self.bl_idname = idname
+        self.inputs = []
+        self.outputs = []
+
+    def as_pointer(self):
+        return id(self)
+
+mock_types = MagicMock()
+mock_types.NodeSocket = DummyNodeSocket
+mock_types.Node = DummyNode
+mock_types.NodeCustomGroup = DummyNode
+
+mock_bpy = MagicMock()
+mock_bpy.types = mock_types
+
+sys.modules['bpy'] = mock_bpy
+sys.modules['bpy.types'] = mock_types
+sys.modules['bpy.props'] = MagicMock()
+sys.modules['bpy.utils'] = MagicMock()
+sys.modules['bpy.utils.previews'] = MagicMock()
+sys.modules['bpy.app'] = MagicMock()
+sys.modules['bpy.app.handlers'] = MagicMock()
+
+from NodeSlicer.infra.blender.blender_slice_nodes_generic import (
+    NodeProfiler,
+    get_node_type,
+    profiler_context,
+    profile_node_execution,
+    show_in_text_editor,
+)
+from NodeSlicer.core.nodeslicer.nodes.system import SLICENODE_Executor
+
+
+class TestNodeProfiler(unittest.TestCase):
+    def test_get_node_type(self):
+        n1 = DummyNode(label="Slice Shells", idname="SLICENODE_Slice")
+        self.assertEqual(get_node_type(n1), "Slice Shells")
+
+        n2 = DummyNode(idname="SLICENODE_Offset")
+        self.assertEqual(get_node_type(n2), "SLICENODE_Offset")
+
+        class GenericObject:
+            pass
+
+        self.assertEqual(get_node_type(GenericObject()), "GenericObject")
+
+    def test_profile_single_node(self):
+        profiler = NodeProfiler()
+        node = DummyNode(label="TestNode")
+
+        with profiler.profile_node(node):
+            time.sleep(0.01)
+
+        self.assertIn("TestNode", profiler.stats)
+        count, tot_time = profiler.stats["TestNode"]
+        self.assertEqual(count, 1)
+        self.assertGreaterEqual(tot_time, 0.008)
+
+    def test_profile_nested_nodes_self_time(self):
+        profiler = NodeProfiler()
+        parent = DummyNode(label="ParentNode")
+        child = DummyNode(label="ChildNode")
+
+        with profiler.profile_node(parent):
+            time.sleep(0.01)
+            with profiler.profile_node(child):
+                time.sleep(0.02)
+            time.sleep(0.01)
+
+        self.assertIn("ParentNode", profiler.stats)
+        self.assertIn("ChildNode", profiler.stats)
+
+        parent_count, parent_tot_time = profiler.stats["ParentNode"]
+        child_count, child_tot_time = profiler.stats["ChildNode"]
+
+        self.assertEqual(parent_count, 1)
+        self.assertEqual(child_count, 1)
+        # Child should have ~0.02s
+        self.assertGreaterEqual(child_tot_time, 0.018)
+        # Parent self-time should be ~0.02s (0.01s before + 0.01s after), NOT 0.04s
+        self.assertGreaterEqual(parent_tot_time, 0.018)
+        self.assertLess(parent_tot_time, 0.035)
+
+    def test_profile_multiple_executions(self):
+        profiler = NodeProfiler()
+        node1 = DummyNode(label="Offset")
+        node2 = DummyNode(label="Offset")
+
+        with profiler.profile_node(node1):
+            time.sleep(0.005)
+        with profiler.profile_node(node2):
+            time.sleep(0.005)
+
+        self.assertIn("Offset", profiler.stats)
+        count, tot_time = profiler.stats["Offset"]
+        self.assertEqual(count, 2)
+        self.assertGreaterEqual(tot_time, 0.008)
+
+    def test_format_table(self):
+        profiler = NodeProfiler()
+        profiler.stats["Slice Shells"] = [1.0, 0.045]
+        profiler.stats["Buffer Shells"] = [2.0, 0.024]
+
+        table = profiler.format_table()
+        self.assertIn("node_type", table)
+        self.assertIn("execution_count", table)
+        self.assertIn("avg_execution_time", table)
+        self.assertIn("tot_execution_time", table)
+        self.assertIn("Slice Shells", table)
+        self.assertIn("Buffer Shells", table)
+        self.assertIn("Total", table)
+
+    def test_format_empty_table(self):
+        profiler = NodeProfiler()
+        table = profiler.format_table()
+        self.assertIn("node_type", table)
+        self.assertIn("(No nodes executed)", table)
+
+    def test_profiler_context_and_profile_node_execution(self):
+        node = DummyNode(label="Slice")
+        with profiler_context() as profiler:
+            with profile_node_execution(node):
+                time.sleep(0.005)
+            self.assertIn("Slice", profiler.stats)
+
+        # Outside context, profile_node_execution should be a no-op
+        with profile_node_execution(node):
+            pass
+
+
+class TestShowInTextEditor(unittest.TestCase):
+    def test_show_in_text_editor(self):
+        with patch("NodeSlicer.infra.blender.blender_slice_nodes_generic.bpy") as mock_bpy_module:
+            mock_text_block = MagicMock()
+            mock_bpy_module.data.texts.get.return_value = None
+            mock_bpy_module.data.texts.new.return_value = mock_text_block
+
+            mock_space = MagicMock()
+            mock_space.type = 'TEXT_EDITOR'
+            mock_area = MagicMock()
+            mock_area.type = 'TEXT_EDITOR'
+            mock_area.spaces = [mock_space]
+            mock_window = MagicMock()
+            mock_window.screen.areas = [mock_area]
+            mock_bpy_module.context.window_manager.windows = [mock_window]
+
+            result = show_in_text_editor("Performance", "Table content")
+            self.assertEqual(result, mock_text_block)
+            mock_bpy_module.data.texts.new.assert_called_with(name="Performance")
+            mock_text_block.from_string.assert_called_with("Table content")
+            self.assertEqual(mock_space.text, mock_text_block)
+
+
+class TestExecutorPerformance(unittest.TestCase):
+    @patch("NodeSlicer.infra.blender.blender_slice_nodes_generic.show_in_text_editor")
+    @patch("NodeSlicer.infra.blender.blender_slice_nodes_generic.resolve_input")
+    def test_executor_with_log_enabled(self, mock_resolve_input, mock_show):
+        executor = SLICENODE_Executor()
+        executor.log = True
+
+        upstream = MagicMock()
+        upstream.bl_label = "Export Gcode"
+        upstream.evaluate.return_value = 'ok'
+        mock_resolve_input.return_value = [upstream]
+
+        dummy_socket = MagicMock()
+        executor.inputs = [dummy_socket]
+
+        res = executor.evaluate()
+        self.assertEqual(res, 'ok')
+        upstream.evaluate.assert_called_once()
+        mock_show.assert_called_once()
+        args, _ = mock_show.call_args
+        self.assertEqual(args[0], "Performance")
+        self.assertIn("Export Gcode", args[1])
+        self.assertIn("node_type", args[1])
+
+    @patch("NodeSlicer.infra.blender.blender_slice_nodes_generic.show_in_text_editor")
+    @patch("NodeSlicer.infra.blender.blender_slice_nodes_generic.resolve_input")
+    def test_executor_with_log_disabled(self, mock_resolve_input, mock_show):
+        executor = SLICENODE_Executor()
+        executor.log = False
+
+        upstream = MagicMock()
+        upstream.bl_label = "Export Gcode"
+        upstream.evaluate.return_value = 'ok'
+        mock_resolve_input.return_value = [upstream]
+
+        dummy_socket = MagicMock()
+        executor.inputs = [dummy_socket]
+
+        res = executor.evaluate()
+        self.assertEqual(res, 'ok')
+        upstream.evaluate.assert_called_once()
+        mock_show.assert_not_called()
+
+
+if __name__ == "__main__":
+    unittest.main()