Skip to content

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

Open
greatEndian wants to merge 1 commit into
LinuxCNC:masterfrom
greatEndian:fix/ruckig-log-flood
Open

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

Conversation

@greatEndian

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 a per-segment ruckig_fail_logged flag to TC_STRUCT, cleared in
tcInit(), and guard each of the five failure sites in
tpCalculateSCurveAccel() with it: 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.

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.

Measured with fault injection — forcing the first-attempt position-planning
failure (plan_result = -1 right after ruckig_plan_position()) and running a
five-segment program on configs/sim/axis/axis_mm_scurve.ini, a 6.5 s run of
655 servo cycles:

build Ruckig planning failed (first attempt) lines total log lines
master, same injection 4222 29573
this branch 2 60

The two remaining lines name their segment (segment 2, segment 6) and are
tagged reported once. With the injection removed, this branch logs zero
Ruckig failures on the same program, so nothing that should be reported is
being suppressed.

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 a per-segment tc->ruckig_fail_logged flag (reset by tcInit on
every new segment) and log each failure once, 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.

All five failure sites in tpCalculateSCurveAccel share the flag, since
every one of them is retried each 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, both branches: the original case above.

Signed-off-by: Ladislav Chabron <chabron94@gmail.com>
@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.

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