Skip to content

boot_serial: serial recovery wait lasts several times the configured timeout #2841

Description

@TheArkadiuszGrzelka

Summary

Under CONFIG_BOOT_SERIAL_WAIT_FOR_DFU, the wait lasts several times longer
than the configured timeout. Measured 5.5x on a Cortex-M0+ and 3.2x on a
Cortex-M23. The countdown is proportional, so it is not a hang, but a
BOOT_SERIAL_WAIT_FOR_DFU_TIMEOUT of 5000 is a 22 s window in practice.

Cause

boot_serial_read_console() in boot/boot_serial/src/boot_serial.c:

MCUBOOT_WATCHDOG_FEED();
uint32_t start = k_uptime_get_32();
rc = f->read(in_buf + off, sizeof(in_buf) - off, &full_line);
...
check_timeout:
elapsed_in_ms = (k_uptime_get_32() - start);
timeout_in_ms -= elapsed_in_ms;

start is sampled after the watchdog feed and after the previous iteration's
own measurement, so only f->read() is ever charged to the timeout. Everything
else in the iteration is free, including the two k_uptime_get_32() calls that
do the measuring.

On a core without hardware divide those calls are the bulk of the loop. Zephyr
converts ticks to milliseconds with a 64-bit division, so the sampling itself
costs more than the work being sampled. Sampling the PC over SWD through one
whole recovery window on an STM32C071 (Cortex-M0+), 166 samples inside the
bootloader:

share symbol
47.0% __udivmoddi4
10.8% __udivsi3
8.4% sys_clock_tick_get
4.8% console_read
4.8% __clzdi2
3.6% __aeabi_uldivmod

Over 72% in the 64-bit division helpers and the tick read, against 4.8% in the
console read that is the only part the timeout is charged for.

Measurements

STM32C071 (Cortex-M0+), MCUmgr over a 9600 baud serial line, timeout 30000 ms:
recovery ended 165 s after the last byte, with the bus fully silent and the
exit detected over SWD rather than on the wire. A 5000 ms
WAIT_FOR_DFU_TIMEOUT window on the same board measured 22.6 s.

PIC32CM5112GC00100 (Cortex-M23), same configuration: 3.2x.

The factor is stable enough to predict a run: a 30000 ms timeout followed by a
second boot paying a 5000 ms window again predicts 165 + 20 = 185 s, measured
184.8 s.

Suggested fix

Charge the whole iteration by carrying one timestamp across iterations instead
of re-sampling inside it:

uint32_t last = k_uptime_get_32();
while (...) {
    ...
    uint32_t now = k_uptime_get_32();
    timeout_in_ms -= (now - last);
    last = now;
}

That leaves one k_uptime_get_32() per iteration and accounts for the feed, the
loop overhead and the measurement itself. Happy to send a patch if the shape
looks right.

Found while measuring #2830, which is what made the figure worth trusting in the
first place. It is not caused by that PR and reproduces without it.

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions