AM6442: Boot time increased in SDK 08.00.00.21

Hi Koichiro-san,
I'll look into it, and get back to you early next week.
Best,
-Hong

Hi Koichiro-san,
I tested the SDK 8.2, and uploaded the SD boot time log in attachment.
www.ti.com/.../08.02.00.14
Can we check the SDK 8.2 on your side?
Best,
-Hong

sitara@sitara-Latitude-E6410:~/test/SDK_debug/grabserial$ grabserial -d /dev/ttyUSB0 -t -m "U-Boot SPL" -e 30
[0.000001 0.000001] 
[0.000332 0.000331] U-Boot SPL 2021.01-g44a87e3ab8 (Mar 30 2022 - 16:29:38 +0000)
[0.031618 0.031618] SYSFW ABI: 3.1 (firmware rev 0x0016 '22.1.1--v2022.01 (Terrific Llam')
[0.079510 0.047892] SPL initial stack usage: 13392 bytes
[0.095564 0.016054] Trying to boot from MMC2
[0.303653 0.208089] Starting ATF on ARM64 core...
[0.304561 0.000908] 
[0.304609 0.000048] NOTICE:  BL31: v2.5(release):08.01.00.006-dirty
[0.306290 0.001681] NOTICE:  BL31: Built : 16:24:35, Mar 30 2022
[0.447660 0.141370] 
[0.447759 0.000099] U-Boot SPL 2021.01-g44a87e3ab8 (Mar 30 2022 - 16:28:20 +0000)
[0.002094 0.002094] SYSFW ABI: 3.1 (firmware rev 0x0016 '22.1.1--v2022.01 (Terrific Llam')
[0.079975 0.077881] Trying to boot from MMC2
[0.815820 0.735845] 
[0.815915 0.000095] 
[0.815974 0.000059] U-Boot 2021.01-g44a87e3ab8 (Mar 30 2022 - 16:28:20 +0000)
[0.818169 0.002195] 
[0.818222 0.000053] SoC:   AM64X SR1.0
[0.818833 0.000611] Model: Texas Instruments AM642 EVM
[0.832392 0.013559] Board: AM64-GPEVM rev E2
[0.833412 0.001020] DRAM:  2 GiB
[0.863792 0.030380] NAND:  0 MiB
[0.864151 0.000359] MMC:   mmc@fa10000: 0, mmc@fa00000: 1
[0.880716 0.016565] In:    serial@2800000
[0.881816 0.001100] Out:   serial@2800000
[0.895946 0.014130] Err:   serial@2800000
[0.943746 0.047800] Net:   eth0: ethernet@8000000port@1
[0.960563 0.016817] Hit any key to stop autoboot:  2 

Hi Hong,

Thanks for your reply. Customer confirmed the boot time is decreased in SDK8.2.
But it is not clear why SDK 8.0 was longer. Customer does not have a plan to migrate SDK 8.2 soon, so they wants to know how to fix it in SDK8.0.

Customer did some debug and found memcopy in u-boot takes longer time in SDK8.0.
SDK 07.03.01.006: memcopy takes 0.006s.

[2022-04-19 10:47:58.432] External data: dst=80800000, offset=360, size=d54d8
[2022-04-19 10:47:58.436] memcpy(dest = 0x80800000, src = 0x80800020, n = 0xd54d8
[2022-04-19 10:47:58.442] memcpy() done.
[2022-04-19 10:47:58.444] Image OS is U-Boot

[2022-04-19 10:43:18.877] External data: dst=80800000, offset=514, size=e80f8
[2022-04-19 10:43:18.881] memcpy(dest = 0x80800000, src = 0x80800014, n = 0xe80f8
[2022-04-19 10:43:19.578] memcpy() done.
[2022-04-19 10:43:19.580] Image OS is U-Boot

diff --git a/common/spl/spl_fit.c b/common/spl/spl_fit.c
index 55511a90d0..74dd182a1d 100644
--- a/common/spl/spl_fit.c
+++ b/common/spl/spl_fit.c
@@ -16,6 +16,9 @@
#include <asm/cache.h>
#include <linux/libfdt.h>

+// Enable Debug
+#define _DEBUG 1
+
DECLARE_GLOBAL_DATA_PTR;

 #ifndef CONFIG_SPL_LOAD_FIT_APPLY_OVERLAY_BUF_SZ
@@ -329,8 +332,41 @@ static int spl_load_fit_image(struct spl_load_info *info, ulong sector,
                           }
                           length = size;
             } else {
+                         printf("memcpy(dest = 0x%lx, src = 0x%p, n = 0x%x\n", load_addr, src, (unsigned int) length);
                           memcpy((void *)load_addr, src, length);
+                         printf("memcpy() done.\n");
+           }
+
              }

             if (image_info) {

Hi Andreas,

Thanks for your answer. I asked customer to check it.

Thanks and regards,
Koichiro Tashiro

Tashiro-san,

thanks. Please close the loop once you hear back, so we can drive an official fix as needed.

Regards, Andreas

Hi Andreas,

Customer is trying to check the proposed solution.
Meanwhile, could you answer below customer's question?

Q) The reason why boot time is slower in SDK8.x is understood.
But why the same problem was not observed in SDK7.x?
What causes the boot time differences between SDK7.x and 8.x?

Thanks and regards,
Koichiro Tashiro

Hi Tashiro-san,

Koichiro Tashiro said:

But why the same problem was not observed in SDK7.x?
What causes the boot time differences between SDK7.x and 8.x?

I suspect this is caused by differences in how the DTB blobs are generated in SDKv7.x vs SDKv8.x. The later SDK may include additional items (bytes) into one of the headers (possibly due to changes to tools/fit_image.c between "old" and "new" U-Boot), thus shifting the alignment of the DTB-included data section(s) away from a 8-byte (64-bit) alignment boundary. You could reverse-compile the U-Boot FIT image and see if there are any differences in number of entries and entry length between the "old" and "new" U-Boot to check this theory. Something like this...

$ dtc -I dtb .out_a53/u-boot.img

Regards, Andreas

Hi Andreas,

The customer understood the reason why boot time is slower with SDK8.x than SDK7.x.
He has another question.
We understood memcopy with unaligned data gets slower because unaligned data are handled byte-wise.
But the customer observed unaligned memcopy was not so slow in SDK7.x.
Is there any reason why unaligned memcopy is faster in SDK7.x than SDK8.x?

SDK7.3

[2022-12-27 11:29:03.968] Benchmark memcpy()
[2022-12-27 11:29:03.969] memcpy(dest = 0x80900000, src = 80800000, n = 0x100000
[2022-12-27 11:29:03.969] memcpy() done.
[2022-12-27 11:29:03.969] memcpy(dest = 0x80900000, src = 80800014, n = 0x100000
[2022-12-27 11:29:03.985] memcpy() done.
[2022-12-27 11:29:03.985] memcpy(dest = 0x80900000, src = 80800020, n = 0x100000
[2022-12-27 11:29:03.985] memcpy() done.
[2022-12-27 11:29:03.985] memcpy(dest = 0x80900000, src = 80800024, n = 0x100000
[2022-12-27 11:29:04.002] memcpy() done.

[2022-12-27 11:20:04.961] Benchmark memcpy()
[2022-12-27 11:20:04.961] memcpy(dest = 0x80900000, src = 0x80800000, n = 0x100000
[2022-12-27 11:20:05.030] memcpy() done.
[2022-12-27 11:20:05.030] memcpy(dest = 0x80900000, src = 0x80800014, n = 0x100000
[2022-12-27 11:20:06.000] memcpy() done.
[2022-12-27 11:20:06.000] memcpy(dest = 0x80900000, src = 0x80800020, n = 0x100000
[2022-12-27 11:20:06.064] memcpy() done.
[2022-12-27 11:20:06.064] memcpy(dest = 0x80900000, src = 0x80800024, n = 0x100000
[2022-12-27 11:20:07.036] memcpy() done.

Hi Tashiro-san,

can you please double-check the concern is now between SDK v7.3 and SDK v8.2? We have had discussed different versions/SDKs before, so I want to make sure I look at the right thing.

I had another look at the U-Boot source code between v7.3 and v8.2 (via `git diff 07.03.00.005 08.02.00.006`) but nothing really spiked out. I also looked at the disassembler code of both memcpy() routines, and they look identical. I suspect it'll be down to a difference in clock system setup (by way of SYSFW built-in defaults, which may be different?), and/or DDR settings. But I need to run some tests on hardware to dig a bit deeper and see if I can confirm the customer findings. But first I want to make sure I'm using the correct SDKs.

Regards, Andreas

Hi Andreas,

The SDK versions the customer compared memcopy() are SDK7.3, SDK8.2 and SDK8.4.
I attached SDK7.3 and SDK8.2 in the last post as example.
SDK8.4 showed similar behavior as SDK8.2, i.e. unaligned memcopy() takes long time.

SDK8.4

[2022-12-27 11:10:46.048] Benchmark memcpy()
[2022-12-27 11:10:46.048] memcpy(dest = 0x80900000, src = 0x80800000, n = 0x100000
[2022-12-27 11:10:46.079] memcpy() done.
[2022-12-27 11:10:46.079] memcpy(dest = 0x80900000, src = 0x80800014, n = 0x100000
[2022-12-27 11:10:46.533] memcpy() done.
[2022-12-27 11:10:46.533] memcpy(dest = 0x80900000, src = 0x80800020, n = 0x100000
[2022-12-27 11:10:46.565] memcpy() done.
[2022-12-27 11:10:46.565] memcpy(dest = 0x80900000, src = 0x80800024, n = 0x100000
[2022-12-27 11:10:47.035] memcpy() done.

Hi Tashiro-san,

ok, thanks. I'll focus my investigation on 7.3 vs 8.2 then. It'll take a couple of hours to run some tests to see if I can find an additional root cause for the still-existing difference in the memcpy() behavior itself (independent of DTB alignment issues discussed earlier) so I need to work this in, hopefully this week.

Regards, Andreas

Hi Tashiro-san,

as per offline discussion, un-locking this thread so we can continue the investigation. I was able to clear my plate some and allocate time to work this issue this week. Will get back in a day or two with an update.

Regards, Andreas