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
This commit is contained in:
29
Init.py
29
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:
|
||||
|
||||
@@ -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
|
||||
|
||||
@@ -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
|
||||
|
||||
|
||||
|
||||
Reference in New Issue
Block a user