Skip to content

tp: rate-limit Ruckig plan-failure logging to once per segment - #4420

Merged
grandixximo merged 1 commit into
LinuxCNC:masterfrom
greatEndian:fix/ruckig-log-flood
Sep 7, 2026
Merged

tp: rate-limit Ruckig plan-failure logging to once per segment#4420
grandixximo merged 1 commit into
LinuxCNC:masterfrom
greatEndian:fix/ruckig-log-flood

Conversation

@greatEndian

@greatEndian greatEndian commented Aug 19, 2026

Copy link
Copy Markdown
Contributor

Problem

When Ruckig cannot plan a segment, tpCalculateSCurveAccel() logs the failure
and falls back to trapezoidal motion for that cycle. The caller then calls
straight back in on the next servo cycle, and — because ruckig_planned only
flips to 1 on success — the planning branch is re-entered and fails again. A
segment Ruckig can never solve therefore logs every servo cycle, i.e. at
1 kHz on a typical machine, for as long as that segment is being executed.

The fallback itself is graceful; the logging is not. On a long run this
produces a log measured in gigabytes and buries anything else in it.

Note that the S-curve path is the default (mode = 1 unless the move is an
abort), so this is reachable on a stock machine with jerk limits configured.

Fix

Add per-segment "already logged" flags to TC_STRUCT, cleared in tcInit(),
and guard each of the five failure sites in tpCalculateSCurveAccel(): the
pool-acquire failure, both velocity-control failures, and both position-control
failures. Each distinct segment still reports its first failure — and the
messages now carry tc->id, so you can tell which segment — but a segment
that keeps failing reports once instead of once per cycle.

One flag per site, not one shared flag: a segment that hits more than one
failure mode (say a pool-acquire failure, then a plan failure once a planner
frees up) still logs each mode once. A single shared flag would report only
whichever fired first.

The first-attempt position-control ERR dump also carries plan_result again
(it had been left only on the replan branch), so the give-up path shows which
limit Ruckig objected to; the velocity-control first-attempt warning carries
it too.

Nothing about the motion changes: the trapezoidal fallback, the return codes
and the retry behaviour are all untouched. This is a logging change only.

Precedent: master's own tpCalculateSCurveAccel() already carries a
scurve_jerk_warned guard for the adjacent "max jerk < 1" warning, with the
same rationale in its comment ("warn ONCE instead of storming the log at servo
rate"). This applies that treatment to the Ruckig failure paths, per-segment
rather than per-process, so each new bad segment is still surfaced.

Testing

Build clean (RIP, --with-realtime=uspace), no warnings. cppcheck clean on
all three changed files. tests/motion + tests/motion-logger +
tests/interp: 91/91 pass, 1 skipped (tests/interp/compile, disabled
upstream).

Measured with fault injection — forcing the first-attempt position-planning
failure (plan_result = -1 right after ruckig_plan_position()) and running a
five-move G-code program on configs/sim/axis/axis_mm_scurve.ini (which the
arc blender expands to nine queued segments):

build Ruckig planning failed (first attempt) lines total stderr lines
master tp.c, same injection 9427 65996
this branch 9 80

The nine remaining lines on the branch are one per queued segment that hits the
site (five moves plus four arc-blend segments, each its own TC_STRUCT), each
tagged reported once and naming its tc->id. With the injection removed the
branch logs zero Ruckig-failure lines on the same program, so nothing that
should be reported is being suppressed.

@grandixximo

Copy link
Copy Markdown
Contributor

Two things on the logging itself.

The RTAPI_MSG_INFO line carrying plan_result was printed before the if (tc->ruckig_planned) split, so it covered both branches. It has moved inside the ruckig_planned branch, which leaves the first-attempt failure, the one that actually gives up and returns TP_SCURVE_ACCEL_ERROR, with no plan_result at all. The ERR dump carries the feed override, the velocities and the limits but not the return code that says which of them Ruckig objected to. Adding plan_result to that format string keeps it.

ruckig_fail_logged guards all five sites, so whichever fires first silences the other four for that segment. A segment that fails to acquire a planner and later fails to plan reports only the acquire. Per segment the first failure still surfaces, as you say; per failure mode it does not. One bit per site instead of one flag keeps what you are after without that.

Neither changes my view that the rate limit is the right call.

@greatEndian

Copy link
Copy Markdown
Contributor Author

Both points addressed and force-pushed (ed8c87a):

  • plan_result is back in the first-attempt ERR dump (as a plan_result: %d line), so the give-up path shows the return code again. Added it to the velocity-control first-attempt warning too, for symmetry.
  • The shared ruckig_fail_logged is now five independent flags, one per failure site (pool acquire, velocity replan / first attempt, position replan / first attempt), all reset in tcInit(). A segment that hits more than one failure mode now logs each mode once instead of only the first.

Re-measured with the same fault injection (first-attempt position-plan failure forced, five-move program on configs/sim/axis/axis_mm_scurve.ini): 9 Ruckig-failure lines on this branch — one per queued segment that hits the site — vs 9427 on master over the same run. Injection removed: zero Ruckig-failure lines, so nothing that should surface is suppressed. PR description table updated.

@grandixximo
grandixximo merged commit a1d46db into LinuxCNC:master Sep 7, 2026
17 checks passed
A segment whose inputs Ruckig can never solve keeps ruckig_planned=0,
so tpCalculateSCurveAccel re-enters its failure branch every servo
cycle and logs at the full servo rate (e.g. 1kHz). Motion is
unaffected (it falls back to trapezoidal), but over a long run this
floods the kernel log / journald with GBs of identical records.

Add per-segment "already logged" flags to TC_STRUCT (reset by tcInit
on every new segment) and log each failure once, tagged with the
segment id. Not re-armed on a later success within the same segment,
so an oscillating fail/succeed segment also cannot flood. No change to
motion behaviour. master's own tpCalculateSCurveAccel already carries a
scurve_jerk_warned once-only guard for the adjacent warning.

tpCalculateSCurveAccel has five distinct Ruckig failure sites, each
retried every servo cycle:

- pool acquire: ruckig_planner stays NULL and is re-acquired next cycle
  for as long as the preallocated pool is exhausted;
- velocity control, replan failed: keeps the previous trajectory and
  falls straight back in on the next cycle;
- velocity control, first attempt failed: returns
  TP_SCURVE_ACCEL_ERROR, which only makes the caller use trapezoidal
  for that one cycle before calling back in;
- position control, replan failed / first attempt failed: the same two
  cases on the position-control path.

Each site gets its own flag rather than one shared flag, so a segment
that hits more than one failure mode (e.g. pool-acquire, then a plan
failure once a planner frees up) still logs each mode once. A single
shared flag would report only whichever fired first.

The first-attempt position-control ERR dump also regains plan_result,
which was previously only on the replan branch, so the give-up path
again shows which limit Ruckig objected to. The velocity-control
first-attempt warning carries it too, for symmetry.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants