Speed up debug_active_drawing and improve drawing failure reporting

When a drawing fails to generate (e.g. an annotation with a runaway
coordinate that makes project_point_onto_camera return None), surface an
actionable error instead of a raw traceback, and make the search for the
offending element much faster.

drawing/operator.py:
- Wrap CreateDrawing.execute so any failure prints the full traceback
  (still consumed by debug_active_drawing) and reports a clear message
  pointing users at "Search Active Drawing For Failing Elements".
- Add should_generate_underlay/linework/annotation toggles so the
  generation stages can be run independently.

debug/operator.py:
- Detect which stage (underlay/linework/annotation) reproduces the
  failure and bisect with only that stage, skipping the expensive
  underlay render and OpenCASCADE linework on every iteration.
- Add a console spinner (background thread, writes to the real stdout)
  so long silent waits no longer look frozen.
- Include the GlobalId in element labels.

Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>
This commit is contained in:
Ryan Schultz
2026-06-30 21:46:43 -05:00
parent 647a1f44ee
commit c7c4cfa946
2 changed files with 109 additions and 8 deletions
+78 -3
View File
@@ -18,12 +18,14 @@
import contextlib import contextlib
import io import io
import itertools
import logging import logging
import os import os
import platform import platform
import random import random
import subprocess import subprocess
import sys import sys
import threading
import time import time
from collections import defaultdict from collections import defaultdict
from pathlib import Path from pathlib import Path
@@ -929,6 +931,49 @@ class PipInstall(bpy.types.Operator):
return {"FINISHED"} return {"FINISHED"}
class _ConsoleSpinner:
"""Animate a spinner on the real stdout while a blocking call runs on the main thread.
Writes to ``sys.__stdout__`` so it isn't swallowed by ``contextlib.redirect_stdout()``,
which the drawing search uses to silence ``create_drawing``'s own output. The animation
runs on a daemon thread that only touches stdout (never bpy data), so it's safe while a
synchronous ``bpy.ops`` call blocks the main thread.
"""
def __init__(self, message: str = "Working"):
self.message = message
self._stop = threading.Event()
self._thread: Union[threading.Thread, None] = None
self._start_time = 0.0
def __enter__(self) -> "_ConsoleSpinner":
self._start_time = time.time()
if sys.__stdout__ is not None:
self._thread = threading.Thread(target=self._spin, daemon=True)
self._thread.start()
return self
def _spin(self) -> None:
out = sys.__stdout__
assert out is not None
for frame in itertools.cycle("|/-\\"):
if self._stop.wait(0.1):
break
elapsed = time.time() - self._start_time
out.write(f"\r {frame} {self.message} ({elapsed:0.0f}s) ")
out.flush()
def __exit__(self, *args: object) -> None:
self._stop.set()
if self._thread is not None:
self._thread.join()
out = sys.__stdout__
if out is not None:
# Clear the spinner line so it doesn't linger before the next print.
out.write("\r" + " " * (len(self.message) + 24) + "\r")
out.flush()
class DebugActiveDrawing(bpy.types.Operator): class DebugActiveDrawing(bpy.types.Operator):
bl_idname = "bim.debug_active_drawing" bl_idname = "bim.debug_active_drawing"
bl_label = "Search Active Drawing For Failing Elements" bl_label = "Search Active Drawing For Failing Elements"
@@ -967,7 +1012,8 @@ class DebugActiveDrawing(bpy.types.Operator):
def elem_label(e: ifcopenshell.entity_instance) -> str: def elem_label(e: ifcopenshell.entity_instance) -> str:
name = getattr(e, "Name", None) or "?" name = getattr(e, "Name", None) or "?"
return f"#{e.id()} {e.is_a()} '{name}'" guid = getattr(e, "GlobalId", None) or "?"
return f"#{e.id()} {e.is_a()} '{name}' ({guid})"
# run create drawing with sync for once # run create drawing with sync for once
# to make sure everything is actually in sync # to make sure everything is actually in sync
@@ -985,6 +1031,33 @@ class DebugActiveDrawing(bpy.types.Operator):
pset = tool.Pset.get_element_pset(drawing, "EPset_Drawing") pset = tool.Pset.get_element_pset(drawing, "EPset_Drawing")
failing_elements: list[ifcopenshell.entity_instance] = [] failing_elements: list[ifcopenshell.entity_instance] = []
# Figure out which generation stage actually reproduces the failure so the
# bisection below can run ONLY that stage. The three stages (underlay, linework,
# annotation) produce independent SVGs, and re-running the expensive underlay/
# linework stages on every bisection step is what makes this operator slow --
# a single full create_drawing can take ~1 minute. Isolating the failing stage
# can cut each iteration (and thus the whole search) by more than half.
STAGES = ("underlay", "linework", "annotation")
def create_drawing_fails(**stage_toggles: bool) -> bool:
try:
with _ConsoleSpinner("Isolating failing stage"), contextlib.redirect_stdout(io.StringIO()):
bpy.ops.bim.create_drawing(sync=False, **stage_toggles)
return False
except Exception:
return True
# Default: run everything (used if we can't isolate a single failing stage).
active_stages = {f"should_generate_{s}": True for s in STAGES}
for stage in ("annotation", "linework", "underlay"):
only_stage = {f"should_generate_{s}": (s == stage) for s in STAGES}
if create_drawing_fails(**only_stage):
active_stages = only_stage
print(f"{CYAN}Failure reproduces in the '{stage}' stage -- bisecting with only that stage.{END}")
break
else:
print(f"{CYAN}Could not isolate a single failing stage -- bisecting with all stages (slower).{END}")
def drawing_fails_to_load(chunk_to_include: set[ifcopenshell.entity_instance]) -> bool: def drawing_fails_to_load(chunk_to_include: set[ifcopenshell.entity_instance]) -> bool:
current_elements = all_elements - chunk_to_include current_elements = all_elements - chunk_to_include
excluded_guids = ", ".join([e.GlobalId for e in current_elements if hasattr(e, "GlobalId")]) excluded_guids = ", ".join([e.GlobalId for e in current_elements if hasattr(e, "GlobalId")])
@@ -993,8 +1066,10 @@ class DebugActiveDrawing(bpy.types.Operator):
ifcopenshell.api.pset.edit_pset(ifc_file, pset=pset, properties={"Exclude": new_exclude}) ifcopenshell.api.pset.edit_pset(ifc_file, pset=pset, properties={"Exclude": new_exclude})
try: try:
with contextlib.redirect_stdout(io.StringIO()): with _ConsoleSpinner(f"Testing {len(chunk_to_include)} element(s)"), contextlib.redirect_stdout(
bpy.ops.bim.create_drawing(sync=False) io.StringIO()
):
bpy.ops.bim.create_drawing(sync=False, **active_stages)
failed = False failed = False
except Exception: except Exception:
failed = True failed = True
@@ -24,6 +24,7 @@ import os
import shutil import shutil
import subprocess import subprocess
import time import time
import traceback
from math import radians from math import radians
from pathlib import Path from pathlib import Path
from timeit import default_timer as timer from timeit import default_timer as timer
@@ -261,11 +262,19 @@ class CreateDrawing(bpy.types.Operator):
description="Could save some time if you're sure IFC and current Blender session are already in sync", description="Could save some time if you're sure IFC and current Blender session are already in sync",
default=True, default=True,
) )
# Stage toggles, mainly for bim.debug_active_drawing so it can reproduce a failure
# by running only the culprit stage instead of the full (slow) generation each time.
should_generate_underlay: bpy.props.BoolProperty(name="Generate Underlay", default=True, options={"SKIP_SAVE"})
should_generate_linework: bpy.props.BoolProperty(name="Generate Linework", default=True, options={"SKIP_SAVE"})
should_generate_annotation: bpy.props.BoolProperty(name="Generate Annotation", default=True, options={"SKIP_SAVE"})
if TYPE_CHECKING: if TYPE_CHECKING:
print_all: bool print_all: bool
open_viewer: bool open_viewer: bool
sync: bool sync: bool
should_generate_underlay: bool
should_generate_linework: bool
should_generate_annotation: bool
drawing_name: str drawing_name: str
is_manifold_cache: dict[str, bool] is_manifold_cache: dict[str, bool]
@@ -298,6 +307,23 @@ class CreateDrawing(bpy.types.Operator):
return self.execute(context) return self.execute(context)
def execute(self, context): def execute(self, context):
try:
return self._execute(context)
except Exception:
# Print the full traceback so developers (and `bim.debug_active_drawing`,
# which bisects the drawing to find the offending element) still get it.
traceback.print_exc()
drawing_name = getattr(self, "drawing_name", None) or "?"
self.report(
{"ERROR"},
f"Failed to create drawing '{drawing_name}'. This is usually caused by a corrupt or "
"out-of-bounds element in the drawing (e.g. an annotation with a runaway coordinate). "
"Run Debug > 'Search Active Drawing For Failing Elements' (bpy.ops.bim.debug_active_drawing) "
"to locate the offending element.",
)
return {"CANCELLED"}
def _execute(self, context):
self.props = tool.Drawing.get_document_props() self.props = tool.Drawing.get_document_props()
assert context.scene and context.scene.camera assert context.scene and context.scene.camera
@@ -356,7 +382,9 @@ class CreateDrawing(bpy.types.Operator):
annotation_svg = None annotation_svg = None
with profile("Generate underlay"): with profile("Generate underlay"):
if ifcopenshell.util.element.get_pset(self.drawing, "EPset_Drawing", "HasUnderlay"): if self.should_generate_underlay and ifcopenshell.util.element.get_pset(
self.drawing, "EPset_Drawing", "HasUnderlay"
):
drawing_style = self.cprops.get_active_drawing_style() drawing_style = self.cprops.get_active_drawing_style()
if not drawing_style: if not drawing_style:
self.report( self.report(
@@ -384,16 +412,14 @@ class CreateDrawing(bpy.types.Operator):
underlay_svg = self.generate_underlay(context) underlay_svg = self.generate_underlay(context)
with profile("Generate linework"): with profile("Generate linework"):
if tool.Drawing.is_camera_orthographic(): if self.should_generate_linework and tool.Drawing.is_camera_orthographic():
if self.cprops.linework_mode == "OPENCASCADE": if self.cprops.linework_mode == "OPENCASCADE":
linework_svg = self.generate_linework(context) linework_svg = self.generate_linework(context)
elif self.cprops.linework_mode == "FREESTYLE": elif self.cprops.linework_mode == "FREESTYLE":
linework_svg = self.generate_freestyle_linework(context) linework_svg = self.generate_freestyle_linework(context)
elif self.cprops.linework_mode == "FREESTYLE":
linework_svg = self.generate_freestyle_linework(context)
with profile("Generate annotation"): with profile("Generate annotation"):
if tool.Drawing.is_camera_orthographic(): if self.should_generate_annotation and tool.Drawing.is_camera_orthographic():
annotation_svg = self.generate_annotation(context) annotation_svg = self.generate_annotation(context)
with profile("Combine SVG layers"): with profile("Combine SVG layers"):