[PATCH u-boot-marvell 00/13] Yet another kwboot improvements
Stefan Roese
sr at denx.de
Tue Oct 26 17:13:05 CEST 2021
On 26.10.21 16:48, Pali Rohár wrote:
> 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 at 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 at 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 at 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?
No. AFAICT, it's always the same time. Like ~1.5 minutes for the overall
U-Boot image.
>> 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 at 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 at 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 at 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 at 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.
I've disabled the watchdog now. So it will not interfere with these
tests and confuse us any more.
I've not seen the reset any more now. So it's most likely only related
to the watchdog. Here the latest log with all your suggested changes:
[stefan at 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 - 17:02:40 +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 (548868 bytes)...
0 %
[......................................................................]
1 %
[......................................................................]
3 %
[......................................................................]
4 %
[......................................................................]
6 %
[......................................................................]
8 %
[......................................................................]
9 %
[......................................................................]
11 %
[......................................................................]
13 %
[......................................................................]
14 %
[......................................................................]
16 %
[......................................................................]
17 %
[......................................................................]
19 %
[......................................................................]
21 %
[......................................................................]
22 %
[......................................................................]
24 %
[......................................................................]
26 %
[......................................................................]
27 %
[......................................................................]
29 %
[......................................................................]
31 %
[......................................................................]
32 %
[......................................................................]
34 %
[......................................................................]
35 %
[......................................................................]
37 %
[......................................................................]
39 %
[......................................................................]
40 %
[......................................................................]
42 %
[......................................................................]
44 %
[......................................................................]
45 %
[......................................................................]
47 %
[......................................................................]
48 %
[......................................................................]
50 %
[......................................................................]
52 %
[......................................................................]
53 %
[......................................................................]
55 %
[......................................................................]
57 %
[......................................................................]
58 %
[......................................................................]
60 %
[......................................................................]
62 %
[......................................................................]
63 %
[......................................................................]
65 %
[......................................................................]
66 %
[......................................................................]
68 %
[......................................................................]
70 %
[......................................................................]
71 %
[......................................................................]
73 %
[......................................................................]
75 %
[......................................................................]
76 %
[......................................................................]
78 %
[......................................................................]
80 %
[......................................................................]
81 %
[......................................................................]
83 %
[......................................................................]
84 %
[......................................................................]
86 %
[......................................................................]
88 %
[......................................................................]
89 %
[......................................................................]
91 %
[......................................................................]
93 %
[......................................................................]
94 %
[......................................................................]
96 %
[......................................................................]
97 %
[......................................................................]
99 % [...................
]
Done
Finishing transfer
Waiting 1s for baudrate change magic
Changing baudrate back to 115200 Bd
[Type Ctrl-\ + c to quit]
Here is now just hangs forever. No output from main U-Boot proper at
all. This happed every time, when the baudrate is changed, meaning a
non 115200 -B is passed to kwboot. I checked with 115201 and here no
U-Boot proper output is printed as well.
> 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.
I changed the timeout to 10s without any change. It did not help.
Thanks,
Stefan
More information about the U-Boot
mailing list