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