diff --git a/core/nodeslicer/nodes/system.py b/core/nodeslicer/nodes/system.py index 97904a2..c117c7b 100644 --- a/core/nodeslicer/nodes/system.py +++ b/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,39 +181,56 @@ 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 ) - for i, job in enumerate(self.inputs): - # Resolve the input to get the connected node(s) - res = resolve_input(job) - if res is None: - continue + profiling_enabled = getattr(self, "log", False) - # Ensure we have a list of jobs to process (JoinExecution returns a list) - jobs_to_run = res if isinstance(res, list) else [res] - - for upstream_node in jobs_to_run: - if not hasattr(upstream_node, "evaluate"): + def _run_jobs(): + for i, job in enumerate(self.inputs): + # Resolve the input to get the connected node(s) + res = resolve_input(job) + if res is None: continue - if operator: - operator.report({'INFO'}, f"Executing: {upstream_node.bl_label}") - - try: - with execution_cache(): - 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}") - except Exception as e: - if operator: operator.report({'ERROR'}, f"Failed executing {upstream_node.bl_label}: {str(e)}") - return 'error' + # Ensure we have a list of jobs to process (JoinExecution returns a list) + jobs_to_run = res if isinstance(res, list) else [res] - return 'ok' + for upstream_node in jobs_to_run: + if not hasattr(upstream_node, "evaluate"): + continue + + if operator: + operator.report({'INFO'}, f"Executing: {upstream_node.bl_label}") + + 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}") + except Exception as e: + if operator: operator.report({'ERROR'}, f"Failed executing {upstream_node.bl_label}: {str(e)}") + return 'error' + + 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): diff --git a/doc/NODES.md b/doc/NODES.md index dbb7e70..1204408 100644 --- a/doc/NODES.md +++ b/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. diff --git a/infra/blender/blender_slice_nodes_generic.py b/infra/blender/blender_slice_nodes_generic.py index 7819824..011281c 100644 --- a/infra/blender/blender_slice_nodes_generic.py +++ b/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,52 +647,53 @@ def _resolve_output( visited.add(node_key) try: with execution_cache(): - 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) - ) or getattr(socket.node, "bl_idname", "") in ("NodeGroup", "GeometryNodeGroup") - if is_group: - return _resolve_group_output(socket, cache=cache, visited=visited) - - is_group_input = ( - isinstance(getattr(bpy.types, "NodeGroupInput", None), type) and isinstance(socket.node, bpy.types.NodeGroupInput) - ) or getattr(socket.node, "bl_idname", "") == "NodeGroupInput" - if is_group_input: - return _resolve_group_input(socket, cache=cache, visited=visited) - return default - - # Set these temporarily so self.resolve() can find them - socket.node._current_cache = cache # type: ignore - socket.node._current_visited = visited # type: ignore - - try: - if getattr(socket.node, "mute", False): - # Attempt bypass: find a matching input socket by name or type - input_to_bypass = socket.node.inputs.get(socket.name) - if not input_to_bypass: - for inp in socket.node.inputs: - if inp.bl_idname == socket.bl_idname: - input_to_bypass = inp - break + 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) + ) or getattr(socket.node, "bl_idname", "") in ("NodeGroup", "GeometryNodeGroup") + if is_group: + return _resolve_group_output(socket, cache=cache, visited=visited) - if input_to_bypass: - value = resolve_input(typing.cast(Any, input_to_bypass), cache=cache, visited=visited) - cache[key] = value - return value + is_group_input = ( + isinstance(getattr(bpy.types, "NodeGroupInput", None), type) and isinstance(socket.node, bpy.types.NodeGroupInput) + ) or getattr(socket.node, "bl_idname", "") == "NodeGroupInput" + if is_group_input: + return _resolve_group_input(socket, cache=cache, visited=visited) return default - assert socket.node.evaluate_output - value = socket.node.evaluate_output( - socket.name, - identifier=socket.identifier, - socket=socket, - cache=cache, - visited=visited - ) - cache[key] = value - return value - finally: - socket.node._current_cache = None # type: ignore - socket.node._current_visited = None # type: ignore + # Set these temporarily so self.resolve() can find them + socket.node._current_cache = cache # type: ignore + socket.node._current_visited = visited # type: ignore + + try: + if getattr(socket.node, "mute", False): + # Attempt bypass: find a matching input socket by name or type + input_to_bypass = socket.node.inputs.get(socket.name) + if not input_to_bypass: + for inp in socket.node.inputs: + if inp.bl_idname == socket.bl_idname: + input_to_bypass = inp + break + + if input_to_bypass: + value = resolve_input(typing.cast(Any, input_to_bypass), cache=cache, visited=visited) + cache[key] = value + return value + return default + + assert socket.node.evaluate_output + value = socket.node.evaluate_output( + socket.name, + identifier=socket.identifier, + socket=socket, + cache=cache, + visited=visited + ) + cache[key] = value + return value + finally: + socket.node._current_cache = None # type: ignore + socket.node._current_visited = None # type: ignore finally: visited.remove(node_key) diff --git a/tests/test_performance.py b/tests/test_performance.py new file mode 100644 index 0000000..19e0972 --- /dev/null +++ b/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()