From d20b38e76020cb86620c15171a0552dc8495787a Mon Sep 17 00:00:00 2001 From: forbes-0023 Date: Sat, 21 Feb 2026 10:07:47 -0600 Subject: [PATCH] feat(solver): add diagnostic logging throughout solver pipeline - solver.py: log solve entry (parts/constraints counts), system build stats, convergence result with timing, decomposition decisions, Newton/BFGS fallback events, and per-constraint diagnostics on failure - solver.py: log drag lifecycle (pre_drag parts, drag_step timing/status, post_drag step count summary) - decompose.py: log cluster count, per-cluster body/constraint/residual stats, and per-cluster convergence failures - Init.py: add _FreeCADLogHandler routing Python logging.* calls to FreeCAD.Console (PrintLog/PrintWarning/PrintError) with kindred_solver logger at DEBUG level --- Init.py | 29 +++++++++ kindred_solver/decompose.py | 21 +++++- kindred_solver/solver.py | 125 ++++++++++++++++++++++++++++++++++-- 3 files changed, 168 insertions(+), 7 deletions(-) diff --git a/Init.py b/Init.py index d604339..4ec73cd 100644 --- a/Init.py +++ b/Init.py @@ -1,11 +1,40 @@ """Register the Kindred solver with the KCSolve solver registry.""" +import logging + import FreeCAD + +class _FreeCADLogHandler(logging.Handler): + """Route Python logging to FreeCAD's Console.""" + + def emit(self, record): + msg = self.format(record) + "\n" + if record.levelno >= logging.ERROR: + FreeCAD.Console.PrintError(msg) + elif record.levelno >= logging.WARNING: + FreeCAD.Console.PrintWarning(msg) + elif record.levelno >= logging.INFO: + FreeCAD.Console.PrintLog(msg) + else: + FreeCAD.Console.PrintLog(msg) + + +def _setup_logging(): + """Attach FreeCAD log handler to the kindred_solver logger.""" + logger = logging.getLogger("kindred_solver") + if not logger.handlers: + handler = _FreeCADLogHandler() + handler.setFormatter(logging.Formatter("%(name)s: %(message)s")) + logger.addHandler(handler) + logger.setLevel(logging.DEBUG) + + try: import kcsolve from kindred_solver import KindredSolver + _setup_logging() kcsolve.register_solver("kindred", KindredSolver) FreeCAD.Console.PrintLog("kindred-solver registered\n") except Exception as exc: diff --git a/kindred_solver/decompose.py b/kindred_solver/decompose.py index 6b5e581..97f3385 100644 --- a/kindred_solver/decompose.py +++ b/kindred_solver/decompose.py @@ -382,6 +382,13 @@ def solve_decomposed( Returns True if all clusters converged. """ + log.info( + "solve_decomposed: %d clusters, %d bodies, %d constraints", + len(clusters), + len(bodies), + len(constraint_objs), + ) + # Build reverse map: constraint_index → position in constraint_objs list idx_to_obj: dict[int, "ConstraintBase"] = {} for pos, ci in enumerate(constraint_indices_map): @@ -390,7 +397,7 @@ def solve_decomposed( solved_bodies: set[str] = set() all_converged = True - for cluster in clusters: + for cluster_idx, cluster in enumerate(clusters): # 1. Fix boundary bodies that were already solved fixed_boundary_params: list[str] = [] for body_id in cluster.boundary_bodies: @@ -424,6 +431,14 @@ def solve_decomposed( # 5. Newton solve (+ BFGS fallback) if cluster_residuals: + log.debug( + " cluster[%d]: %d bodies (%d boundary), %d constraints, %d residuals", + cluster_idx, + len(cluster.bodies), + len(cluster.boundary_bodies), + len(cluster.constraint_indices), + len(cluster_residuals), + ) converged = newton_solve( cluster_residuals, params, @@ -432,6 +447,9 @@ def solve_decomposed( tol=1e-10, ) if not converged: + log.info( + " cluster[%d]: Newton-Raphson failed, trying BFGS", cluster_idx + ) converged = bfgs_solve( cluster_residuals, params, @@ -440,6 +458,7 @@ def solve_decomposed( tol=1e-10, ) if not converged: + log.warning(" cluster[%d]: failed to converge", cluster_idx) all_converged = False # 6. Mark this cluster's bodies as solved diff --git a/kindred_solver/solver.py b/kindred_solver/solver.py index 43012ca..a1d3297 100644 --- a/kindred_solver/solver.py +++ b/kindred_solver/solver.py @@ -3,8 +3,13 @@ expression-based Newton-Raphson solver.""" from __future__ import annotations +import logging +import time + import kcsolve +log = logging.getLogger(__name__) + from .bfgs import bfgs_solve from .constraints import ( AngleConstraint, @@ -97,15 +102,33 @@ class KindredSolver(kcsolve.IKCSolver): # ── Static solve ──────────────────────────────────────────────── def solve(self, ctx): + t0 = time.perf_counter() + n_parts = len(ctx.parts) + n_constraints = len(ctx.constraints) + n_grounded = sum(1 for p in ctx.parts if p.grounded) + log.info( + "solve: %d parts (%d grounded), %d constraints", + n_parts, + n_grounded, + n_constraints, + ) + system = _build_system(ctx) + n_free_bodies = sum(1 for b in system.bodies.values() if not b.grounded) + n_residuals = len(system.all_residuals) + n_free_params = len(system.params.free_names()) + log.info( + "solve: system built — %d free bodies, %d residuals, %d free params", + n_free_bodies, + n_residuals, + n_free_params, + ) # Warn once per solver instance if any constraints have limits if not self._limits_warned: for c in ctx.constraints: if c.limits: - import logging - - logging.getLogger(__name__).warning( + log.warning( "Joint limits on '%s' ignored " "(not yet supported by Kindred solver)", c.id, @@ -131,10 +154,15 @@ class KindredSolver(kcsolve.IKCSolver): residuals = single_equation_pass(residuals, system.params) # Solve (decomposed for large assemblies, monolithic for small) - n_free_bodies = sum(1 for b in system.bodies.values() if not b.grounded) if n_free_bodies >= _DECOMPOSE_THRESHOLD: grounded_ids = {pid for pid, b in system.bodies.items() if b.grounded} clusters = decompose(ctx.constraints, grounded_ids) + log.info( + "solve: decomposed into %d cluster(s) (%d free bodies >= threshold %d)", + len(clusters), + n_free_bodies, + _DECOMPOSE_THRESHOLD, + ) if len(clusters) > 1: converged = solve_decomposed( clusters, @@ -152,6 +180,11 @@ class KindredSolver(kcsolve.IKCSolver): weight_vector=weight_vec, ) else: + log.debug( + "solve: monolithic path (%d free bodies < threshold %d)", + n_free_bodies, + _DECOMPOSE_THRESHOLD, + ) converged = _monolithic_solve( residuals, system.params, @@ -180,6 +213,21 @@ class KindredSolver(kcsolve.IKCSolver): ) result.placements = _extract_placements(system.params, system.bodies) + + elapsed = (time.perf_counter() - t0) * 1000 + log.info( + "solve: %s in %.1f ms — dof=%d, %d placements", + "converged" if converged else "FAILED", + elapsed, + dof, + len(result.placements), + ) + if not converged and result.diagnostics: + for d in result.diagnostics: + log.warning( + " diagnostic: [%s] %s — %s", d.kind, d.constraint_id, d.detail + ) + return result # ── Incremental update ────────────────────────────────────────── @@ -190,24 +238,49 @@ class KindredSolver(kcsolve.IKCSolver): # ── Interactive drag ──────────────────────────────────────────── def pre_drag(self, ctx, drag_parts): + log.info("pre_drag: drag_parts=%s", drag_parts) self._drag_ctx = ctx self._drag_parts = set(drag_parts) - return self.solve(ctx) + self._drag_step_count = 0 + result = self.solve(ctx) + log.info("pre_drag: initial solve status=%s", result.status) + return result def drag_step(self, drag_placements): ctx = self._drag_ctx if ctx is None: + log.warning("drag_step: no drag context (pre_drag not called?)") return kcsolve.SolveResult() + self._drag_step_count = getattr(self, "_drag_step_count", 0) + 1 for pr in drag_placements: for part in ctx.parts: if part.id == pr.id: part.placement = pr.placement break - return self.solve(ctx) + t0 = time.perf_counter() + result = self.solve(ctx) + elapsed = (time.perf_counter() - t0) * 1000 + if result.status != kcsolve.SolveStatus.Success: + log.warning( + "drag_step #%d: solve %s in %.1f ms", + self._drag_step_count, + result.status, + elapsed, + ) + else: + log.debug( + "drag_step #%d: ok in %.1f ms", + self._drag_step_count, + elapsed, + ) + return result def post_drag(self): + steps = getattr(self, "_drag_step_count", 0) + log.info("post_drag: completed after %d drag steps", steps) self._drag_ctx = None self._drag_parts = None + self._drag_step_count = 0 # ── Diagnostics ───────────────────────────────────────────────── @@ -266,13 +339,25 @@ def _build_system(ctx): all_residuals = [] constraint_objs = [] constraint_indices = [] # parallel to constraint_objs: index in ctx.constraints + skipped_inactive = 0 + skipped_missing_body = 0 + skipped_unsupported = 0 for idx, c in enumerate(ctx.constraints): if not c.activated: + skipped_inactive += 1 continue body_i = bodies.get(c.part_i) body_j = bodies.get(c.part_j) if body_i is None or body_j is None: + skipped_missing_body += 1 + log.debug( + "_build_system: constraint[%d] %s skipped — missing body (%s or %s)", + idx, + c.id, + c.part_i, + c.part_j, + ) continue marker_i_pos = tuple(c.marker_i.position) @@ -289,11 +374,26 @@ def _build_system(ctx): c.params, ) if obj is None: + skipped_unsupported += 1 + log.debug( + "_build_system: constraint[%d] %s type=%s — unsupported, skipped", + idx, + c.id, + c.type, + ) continue constraint_objs.append(obj) constraint_indices.append(idx) all_residuals.extend(obj.residuals()) + if skipped_inactive or skipped_missing_body or skipped_unsupported: + log.debug( + "_build_system: skipped constraints — %d inactive, %d missing body, %d unsupported", + skipped_inactive, + skipped_missing_body, + skipped_unsupported, + ) + # 3. Build residual-to-constraint mapping residual_ranges = [] # (start_row, end_row, constraint_idx) row = 0 @@ -359,6 +459,7 @@ def _monolithic_solve( all_residuals, params, quat_groups, post_step=None, weight_vector=None ): """Newton-Raphson solve with BFGS fallback on the full system.""" + t0 = time.perf_counter() converged = newton_solve( all_residuals, params, @@ -368,7 +469,12 @@ def _monolithic_solve( post_step=post_step, weight_vector=weight_vector, ) + nr_ms = (time.perf_counter() - t0) * 1000 if not converged: + log.info( + "_monolithic_solve: Newton-Raphson failed (%.1f ms), trying BFGS", nr_ms + ) + t1 = time.perf_counter() converged = bfgs_solve( all_residuals, params, @@ -377,6 +483,13 @@ def _monolithic_solve( tol=1e-10, weight_vector=weight_vector, ) + bfgs_ms = (time.perf_counter() - t1) * 1000 + if converged: + log.info("_monolithic_solve: BFGS converged (%.1f ms)", bfgs_ms) + else: + log.warning("_monolithic_solve: BFGS also failed (%.1f ms)", bfgs_ms) + else: + log.debug("_monolithic_solve: Newton-Raphson converged (%.1f ms)", nr_ms) return converged