Re: [PATCH u-boot-marvell 00/13] Yet another kwboot improvements

Pali Rohár
2021-10-26T14:48:18Z

On Tuesday 26 October 2021 16:21:02 Stefan Roese wrote:
> On 26.10.21 14:40, Pali Rohár wrote:
> > On Tuesday 26 October 2021 13:09:42 Stefan Roese wrote:
> > > On 26.10.21 11:06, Pali Rohár wrote:
> > >
> > > <snip>
> > >
> > > > Now I found logical error in kwboot code which handles retransmission of
> > > > the last header packet. State of "baudrate change" is cleared on every
> > > > retransmission. Please apply following diff, so state variables are
> > > > initialized only once.
> > > >
> > > > diff --git a/tools/kwboot.c b/tools/kwboot.c
> > > > index d38ee0065177..835ccc8c113a 100644
> > > > --- a/tools/kwboot.c
> > > > +++ b/tools/kwboot.c
> > > > @@ -859,11 +859,6 @@ kwboot_xm_recv_reply(int fd, char *c, int nak_on_non_xm,
> > > > uint64_t recv_until = _now() + timeout;
> > > > int rc;
> > > > - if (non_xm_print)
> > > > - *non_xm_print = 0;
> > > > - if (baud_changed)
> > > > - *baud_changed = 0;
> > > > -
> > > > while (1) {
> > > > rc = kwboot_tty_recv(fd, c, 1, timeout);
> > > > if (rc) {
> > > > @@ -929,6 +924,8 @@ kwboot_xm_sendblock(int fd, struct kwboot_block *block, int allow_non_xm,
> > > > char c;
> > > > *done_print = 0;
> > > > + non_xm_print = 0;
> > > > + baud_changed = 0;
> > > > retries = 0;
> > > > do {
> > >
> > > This definitely helps (a bit). Now I get this:
> >
> > Perfect! So this fixes issue with retransmission of the last header
> > packet.
> >
> > But there is still issue with starting main U-Boot binary.
> >
> > > [stefan@ryzen u-boot-marvell (kwboot-test1)]$ ./tools/kwboot -B 230400 -b
> > > u-boot-spl.kwb -t
> > > /dev/serial/by-id/usb-FTDI_FT232R_USB_UART_A1019EGY-if00-port0
> > > Patching image boot signature to UART
> > > Injecting binary header code for changing baudrate to 230400 Bd
> > > Injecting code for changing baudrate back
> > > Sending boot message. Please reboot the target...|
> > > Waiting 2s and flushing tty
> > > Sending boot image header (90112 bytes)...
> > > 0 %
> > > [......................................................................]
> > > 10 %
> > > [......................................................................]
> > > 20 %
> > > [......................................................................]
> > > 29 %
> > > [......................................................................]
> > > 39 %
> > > [......................................................................]
> > > 49 %
> > > [......................................................................]
> > > 59 %
> > > [......................................................................]
> > > 69 %
> > > [......................................................................]
> > > 79 %
> > > [......................................................................]
> > > 89 %
> > > [......................................................................]
> > > 99 % [.... ]
> > > Done
> > >
> > > U-Boot SPL 2021.10-00908-gc129aa2f173a-dirty (Oct 26 2021 - 12:48:11 +0200)
> > > High speed PHY - Version: 2.1.5 (COM-PHY-V20)
> > > High speed PHY - Ended Successfully
> > > DDR3 Training Sequence - Ver 5.7.4
> > > DDR3 Training Sequence - Ended Successfully
> > > Trying to boot from BOOTROM
> > > Returning to BootROM (return address 0xffff0aa0)...
> > >
> > > Changing baudrate to 230400 Bd
> > >
> > > Sending boot image data (549892 bytes)...
> > > 0 %
> > > [......................................................................]
> > >
> > > ...
> > >
> > > 99 % [........................... ]
> > > Done
> > > Finishing transfer
> > > Waiting 1s for baudrate change magic
> > > xmodem: Connection timed out
> > >
> > >
> > > BTW: The baudrate change does not seem to work or have any effect on
> > > the image download speed. Comparing 230400 and 921600 baud speeds, I can
> > > spot no real time difference here:
> > >
> > > 230400 baud:
> > > [stefan@ryzen u-boot-marvell (kwboot-test1)]$ time ./tools/kwboot -B 230400
> > > -b u-boot-spl.kwb -t
> > > /dev/serial/by-id/usb-FTDI_FT232R_USB_UART_A1019EGY-if00-port0
> > > Patching image boot signature to UART
> > > Injecting binary header code for changing baudrate to 230400 Bd
> > >
> > > ...
> > >
> > > 99 % [........................... ]
> > > Done
> > > Finishing transfer
> > > Waiting 1s for baudrate change magic
> > > xmodem: Connection timed out
> > > [2]+ Done emacs tools/kwboot.c
> > >
> > > real 1m27,279s
> > > user 0m2,313s
> > > sys 0m0,337s
> > >
> > > 921600 baud:
> > > [stefan@ryzen u-boot-marvell (kwboot-test1)]$ time ./tools/kwboot -B 921600
> > > -b u-boot-spl.kwb -t
> > > /dev/serial/by-id/usb-FTDI_FT232R_USB_UART_A1019EGY-if00-port0
> > > Patching image boot signature to UART
> > > Injecting binary header code for changing baudrate to 921600 Bd
> > >
> > > ...
> > >
> > > 99 % [........................... ]
> > > Done
> > > Finishing transfer
> > > Waiting 1s for baudrate change magic
> > > xmodem: Connection timed out
> > >
> > > real 1m27,839s
> > > user 0m0,224s
> > > sys 0m0,194s
> > >
> > > Any idea why this is the case?
> >
> > UARTs at both sides must be configured to 921600 speed, otherwise they
> > would not be able to communicate.
>
> I'm also surpised here.
>
> > What is happening here? I do not know. But as Marek told me that
> > observed same issue and replacing USB-UART cable by another decreased
> > transfer time. So I think that issue is somewhere in USB-UART
> > transmitter. My guess is that USB-UART transmitter send at 921600 speed:
> > start bit, 8 bits of data, stop bit and then loooong idle pause (logical
> > one). After that sends another 10 bits.
> >
> > Maybe kernel is not filling next byte into USB-UART hw queue? Or USB-UART
> > cannot send more bytes faster and inserts those long idle pauses?
> >
> > Could you try following diff which disables calling tcdrain() for xmodem
> > packets, to remove any waits between individual bytes?
> >
> > diff --git a/tools/kwboot.c b/tools/kwboot.c
> > index 835ccc8c113a..5f4ff673972e 100644
> > --- a/tools/kwboot.c
> > +++ b/tools/kwboot.c
> > @@ -404,7 +404,7 @@ out:
> > }
> > static int
> > -kwboot_tty_send(int fd, const void *buf, size_t len)
> > +kwboot_tty_send(int fd, const void *buf, size_t len, int nodrain)
> > {
> > if (!buf)
> > return 0;
> > @@ -412,13 +412,16 @@ kwboot_tty_send(int fd, const void *buf, size_t len)
> > if (kwboot_write(fd, buf, len) < 0)
> > return -1;
> > + if (nodrain)
> > + return 0;
> > +
> > return tcdrain(fd);
> > }
> > static int
> > kwboot_tty_send_char(int fd, unsigned char c)
> > {
> > - return kwboot_tty_send(fd, &c, 1);
> > + return kwboot_tty_send(fd, &c, 1, 0);
> > }
> > static speed_t
> > @@ -705,7 +708,7 @@ kwboot_bootmsg(int tty, void *msg)
> > break;
> > for (count = 0; count < 128; count++) {
> > - rc = kwboot_tty_send(tty, msg, 8);
> > + rc = kwboot_tty_send(tty, msg, 8, 0);
> > if (rc) {
> > usleep(msg_req_delay * 1000);
> > continue;
> > @@ -737,7 +740,7 @@ kwboot_debugmsg(int tty, void *msg)
> > if (rc)
> > break;
> > - rc = kwboot_tty_send(tty, msg, 8);
> > + rc = kwboot_tty_send(tty, msg, 8, 0);
> > if (rc) {
> > usleep(msg_req_delay * 1000);
> > continue;
> > @@ -929,7 +932,7 @@ kwboot_xm_sendblock(int fd, struct kwboot_block *block, int allow_non_xm,
> > retries = 0;
> > do {
> > - rc = kwboot_tty_send(fd, block, sizeof(*block));
> > + rc = kwboot_tty_send(fd, block, sizeof(*block), 1);
> > if (rc)
> > return rc;
> >
> > If it is kernel who does not fill next bytes into hw UART queue as it
> > waits for tcdrain then above patch should fix it.
>
> Still no ciguar. Here the end of the log with "-B 921600":

So no change in total transfer time with above patch?

> 97 %
> [......................................................................]
> 99 % [........................... ]
> Done
> Finishing transfer
> Waiting 1s for baudrate change magic
> xmodem: Connection timed out
>
>
> > Or if you have other USB-UART cables, try another. I have good
> > experience with pl2303-based.
>
> I have tons of USB-UART adapters / cables. But as mentioned in the
> other mail, I can't connect them, as the FTDI chip is soldered on the
> target.

Understood.

> Still it should work at least with 115201 baud, even if baudrate
> changing does not work. Right? So we have at least one other problem
> here AFAICT.

Baudrate change must work. Using 115201 baud could just show output from
board/bootrom if CPU prematurely resets (which resets baudrate to
default 115200).

> > > > > Ok. This seems to work at least partly (SPL):
> > > > >
> > > > > [stefan@ryzen u-boot-marvell (kwboot-test1)]$ ./tools/kwboot -B 115201 -b
> > > > > u-boot-spl.kwb -t
> > > > > /dev/serial/by-id/usb-FTDI_FT232R_USB_UART_A1019EGY-if00-port0
> > > > > Patching image boot signature to UART
> > > > > Injecting binary header code for changing baudrate to 115201 Bd
> > > > > Injecting code for changing baudrate back
> > > > > Sending boot message. Please reboot the target...|
> > > > > Waiting 2s and flushing tty
> > > > > Sending boot image header (90112 bytes)...
> > > > > 0 %
> > > > > [......................................................................]
> > > > > 10 %
> > > > > [......................................................................]
> > > > > 20 %
> > > > > [......................................................................]
> > > > > 29 %
> > > > > [......................................................................]
> > > > > 39 %
> > > > > [......................................................................]
> > > > > 49 %
> > > > > [......................................................................]
> > > > > 59 %
> > > > > [......................................................................]
> > > > > 69 %
> > > > > [......................................................................]
> > > > > 79 %
> > > > > [......................................................................]
> > > > > 89 %
> > > > > [......................................................................]
> > > > > 99 % [.... ]
> > > > > Done
> > > > >
> > > > > U-Boot SPL 2021.10-00908-gc129aa2f173a (Oct 26 2021 - 10:39:55 +0200)
> > > > > High speed PHY - Version: 2.1.5 (COM-PHY-V20)
> > > > > High speed PHY - Ended Successfully
> > > > > DDR3 Training Sequence - Ver 5.7.4
> > > > > DDR3 Training Sequence - Ended Successfully
> > > > > Trying to boot from BOOTROM
> > > > > Returning to BootROM (return address 0xffff0aa0)...
> > > > >
> > > > > Changing baudrate to 115201 Bd
> > > > >
> > > > > Sending boot image data (549892 bytes)...
> > > > > 0 %
> > > > > [......................................................................]
> > > > > 1 %
> > > > > [......................................................................]
> > > > > ...
> > > > > 97 %
> > > > > [......................................................................]
> > > > > 99 % [........................... ]
> > > > > Done
> > > > > Finishing transfer
> > > > > Waiting 1s for baudrate change magic
> > > > >
> > > > > Changing baudrate back to 115200 Bd
> > > > >
> > > > > [Type Ctrl-\ + c to quit]
> > > > >
> > > > > BootROM 1.20
> > > > > Booting from SPI flash
> > > > >
> > > > >
> > > > > So the CPU has run through a reset here.
> > > >
> > > > What kind of CPU core has your AXP board? Maybe there is some arm
> > > > instruction in kwboot_baud_code[] array which is not supported by that
> > > > core (and so reset occurs)?
> > >
> > > AXP stands for Armada XP, which is ARM v7 AFAIK.
> >
> > I remember that older Marvell Armada SoCs used custom designed ARM
> > cores, so there could be some differences what is supported by licensed
> > ARM core and custom ARM core.
> >
> > Anyway, as changing baudrate after execution of SPL is working fine, it
> > should mean that there is no undefined/unsupported instruction.
> >
> > My another guess there could be a problem is usage of stack. Maybe it is
> > possible that register with stack pointer is not initialized after the
> > full transfer when going to execute main image. Same arm baudrate change
> > code is used after the SPL and before main U-Boot, and the first
> > instruction is "push". Maybe modifying the arm code to not use stack
> > when switching the baudrate back to 115200 could also help. I will look
> > at it.
>
> Thanks.
>
> > > > And could you send me commands which you are using for compiling U-Boot
> > > > for that your AXP board? I would like to examine resulted binary.
> > >
> > > I'm currently using a kernel.org toolchain:
> > >
> > > [stefan@ryzen u-boot-marvell (kwboot-test1)]$ set | grep CROSS
> > > CROSS_COMPILE=/opt/kernel.org/gcc-11.1.0-nolibc/arm-linux-gnueabi/bin/arm-linux-gnueabi-
> > > [stefan@ryzen u-boot-marvell (kwboot-test1)]$
> > > /opt/kernel.org/gcc-11.1.0-nolibc/arm-linux-gnueabi/bin/arm-linux-gnueabi-gcc
> > > --version
> > > arm-linux-gnueabi-gcc (GCC) 11.1.0
> > > Copyright (C) 2021 Free Software Foundation, Inc.
> > > This is free software; see the source for copying conditions. There is NO
> > > warranty; not even for MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.
> > >
> > > Here my commands to generate the U-Boot binary:
> > >
> > > make mrproper
> > > make theadorable_debug_defconfig
> > > make -s -j20
> >
> > Ok.
> >
> > > > > > And what is the output of following command immediately after kwboot?
> > > > > >
> > > > > > stty -F /dev/serial/by-id/usb-FTDI_FT232R_USB_UART_A1019EGY-if00-port0
> > > > >
> > > > > Changing baudrate to 230400 Bd
> > > > > Baudrate was not changed
> > > > >
> > > > >
> > > > > xmodem: Protocol error
> > > > > [stefan@ryzen u-boot-marvell (kwboot-test1)]$ stty -F
> > > > > /dev/serial/by-id/usb-FTDI_FT232R_USB_UART_A1019EGY-if00-port0
> > > > > speed 230400 baud; line = 0;
> > > >
> > > > ... but baudrate _was_ changed.
> > > >
> > > > So it looks like a bug in kwboot code. Try to apply above diff, it is
> > > > really possible that you hit that logical error. (Interesting that
> > > > neither Marek nor me saw it)
> > > >
> > > > > intr = <undef>; quit = <undef>; erase = <undef>; kill = <undef>; eof =
> > > > > <undef>; start = <undef>; stop = <undef>; susp = <undef>; rprnt = <undef>;
> > > > > werase = <undef>; lnext = <undef>; discard = <undef>; min = 1; time = 0;
> > > > > -brkint -icrnl -imaxbel
> > > > > -opost -onlcr
> > > > > -isig -icanon -iexten -echo -echoe -echok -echoctl -echoke
> > > > >
> > > > > > Also, could try to catch whole strace log and send it to me?
> > > > >
> > > > > I'll try to do this later today.
> > > >
> > > > 'strace kwboot ... 1>log 2>&1' should do it...
> > >
> > > Okay, will follow in the next privatze mail.
> >
> > Received. I have looked at it. And there are two interesting parts:
> >
> > 1) Both parts of transfer (header at default speed 115200 and main at
> > high speed 921600) were transferred without any error, except for the
> > error indication of the last header packet. Error indication was sent
> > after the execution of header itself (SPL and baudrate change), it means
> > that there was no error and bootrom did not sent any error indication.
> > kwboot did retransmission of this one packet and it succeeded (thanks to
> > that fixup which I have sent).
> >
> > So this error must have been just fluctuation on UART and probably
> > caused by changing UART speed. I guess that your USB-UART chip needs
> > more time to stabilize new speed and so USB-UART receiver lost/damaged
> > reply byte sent by bootrom.
> >
> > Maybe you could increase delay in arm baudrate change code, so CPU waits
> > longer time before it returns to bootrom?
> >
> > Replacing code in kwboot_baud_code[] array:
> >
> > /* ; Sleep 1ms ~~ 600000 cycles at 1200 MHz */
> > /* ; r1 = 600000 */
> > 0x9f, 0x1d, 0xa0, 0xe3, /* mov r1, #0x27c0 */
> > 0x09, 0x10, 0x40, 0xe3, /* movt r1, #0x0009 */
> >
> > by:
> >
> > /* ; Sleep 10ms ~~ 6M cycles at 1200 MHz */
> > /* ; r1 = 6000000 */
> > 0x80, 0x1d, 0x08, 0xe3, /* mov r1, #0x8d80 */
> > 0x5b, 0x10, 0x40, 0xe3, /* movt r1, #0x005b */
> >
> > should do it.
>
> Still no change. Also not in the download speed AFAICT.
>
> ...
> 97 %
> [......................................................................]
> 99 % [........................... ]
> Done
> Finishing transfer
> Waiting 1s for baudrate change magic
>
> Changing baudrate back to 115200 Bd
>
> [Type Ctrl-\ + c to quit]
>
> BootROM 1.20
>
> BTW: There is a external watchdog on the target, which might be the root
> cause for the reset I'm seeing here. It kicks in at around 2-3 minutes
> after power-up AFAIR.

But there is no more "xmodem: Connection timed out" error.

When that "BootROM 1.20" message was printed? Immediately after the
"Changing baudrate back to 115200 Bd"? Or it was e.g. minute later? I
would like to know if board reset relates to watchdog or if it relates
to baudrate change code.

If there are timeout errors related to "Waiting 1s for baudrate change
magic" then increasing 1s (1000 ms value) to e.g. 10s could help.

> > 2) Transfer was successful (EOT was ACKed) but there is absolutely no
> > output on UART after the transfer. Which should indicate that bootrom
> > should have started execution of the main image, but something crashed
> > and board reset... Maybe it is really due to usage of stack...
>
> Yep.
>
> Thanks,
> Stefan