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

Pali Rohár
2021-10-26T12:41:02Z

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.

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.

Or if you have other USB-UART cables, try another. I have good
experience with pl2303-based.

> > > 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.

> > 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.

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...

> Thanks,
> Stefan