New u-boot-aspeed-sdk runs slow and cause wdt2 timeout on ast2500

New u-boot-aspeed-sdk runs slow and cause wdt2 timeout on ast2500

[Lei Yu]

On the latest master with u-boot-aspeed v00.04.09 SDK, an issue occurs
on g220a that it runs slower than before and gets wdt2 timeout.
We reverted the u-boot to a version before v00.04.09 SDK (b0fe8fd9d)
and the issue is gone.

Below are some details:
* Before v00.04.09: u-boot works OK, and it takes about 9~10 seconds
to load and start the kernel including the 2 seconds timeout for
autoboot, the kernel starts OK and it kicks the watchdog as long as
the driver is loaded.
* With v00.04.09: u-boot runs slower than before, and it takes about
**16 seconds** to load and start the kernel (including 2s timeout for
autoboot), then the kernel does not have enough time to run and loads
the watchdog driver, and the wdt2 times out on about 22s.

Be noted that the issue is observed on g220a that is based on AST2500,
and could not be reproduced in QEMU. I think it could be reproduced on
other systems with AST2500.

-- 
BRs,
Lei YU

RE: New u-boot-aspeed-sdk runs slow and cause wdt2 timeout on ast2500

[ChiaWei Wang]

> Lei Yu
> Sent: Wednesday, February 23, 2022 10:15 AM
> 
> On the latest master with u-boot-aspeed v00.04.09 SDK, an issue occurs on
> g220a that it runs slower than before and gets wdt2 timeout.
> We reverted the u-boot to a version before v00.04.09 SDK (b0fe8fd9d) and the
> issue is gone.
> 
> Below are some details:
> * Before v00.04.09: u-boot works OK, and it takes about 9~10 seconds to load
> and start the kernel including the 2 seconds timeout for autoboot, the kernel
> starts OK and it kicks the watchdog as long as the driver is loaded.
> * With v00.04.09: u-boot runs slower than before, and it takes about
> **16 seconds** to load and start the kernel (including 2s timeout for
> autoboot), then the kernel does not have enough time to run and loads the
> watchdog driver, and the wdt2 times out on about 22s.

Could you share us the boot log with timestamps?
It would be nice to know the time elapsed at each stage.

Regards,
Chiawei

> 
> Be noted that the issue is observed on g220a that is based on AST2500, and
> could not be reproduced in QEMU. I think it could be reproduced on other
> systems with AST2500.

RE: New u-boot-aspeed-sdk runs slow and cause wdt2 timeout on ast2500

[Lei Yu]

On Wed, Feb 23, 2022 at 10:38 AM ChiaWei Wang
<chiawei_wang@aspeedtech.com> wrote:
>
> > Lei Yu
> > Sent: Wednesday, February 23, 2022 10:15 AM
> >
> > On the latest master with u-boot-aspeed v00.04.09 SDK, an issue occurs on
> > g220a that it runs slower than before and gets wdt2 timeout.
> > We reverted the u-boot to a version before v00.04.09 SDK (b0fe8fd9d) and the
> > issue is gone.
> >
> > Below are some details:
> > * Before v00.04.09: u-boot works OK, and it takes about 9~10 seconds to load
> > and start the kernel including the 2 seconds timeout for autoboot, the kernel
> > starts OK and it kicks the watchdog as long as the driver is loaded.
> > * With v00.04.09: u-boot runs slower than before, and it takes about
> > **16 seconds** to load and start the kernel (including 2s timeout for
> > autoboot), then the kernel does not have enough time to run and loads the
> > watchdog driver, and the wdt2 times out on about 22s.
>
> Could you share us the boot log with timestamps?
> It would be nice to know the time elapsed at each stage.

Pasted to https://pastebin.com/emseqW6c
It contains two logs, the first one is good, and the second has the issue.

Re: New u-boot-aspeed-sdk runs slow and cause wdt2 timeout on ast2500

[Thang Nguyen OS]

On 23/02/2022 09:15, Lei Yu wrote:
> On the latest master with u-boot-aspeed v00.04.09 SDK, an issue occurs
> on g220a that it runs slower than before and gets wdt2 timeout.
> We reverted the u-boot to a version before v00.04.09 SDK (b0fe8fd9d)
> and the issue is gone.
>
> Below are some details:
> * Before v00.04.09: u-boot works OK, and it takes about 9~10 seconds
> to load and start the kernel including the 2 seconds timeout for
> autoboot, the kernel starts OK and it kicks the watchdog as long as
> the driver is loaded.
> * With v00.04.09: u-boot runs slower than before, and it takes about
> **16 seconds** to load and start the kernel (including 2s timeout for
> autoboot), then the kernel does not have enough time to run and loads
> the watchdog driver, and the wdt2 times out on about 22s.
>
> Be noted that the issue is observed on g220a that is based on AST2500,
> and could not be reproduced in QEMU. I think it could be reproduced on
> other systems with AST2500.
>
I checked and saw the same issue with Ampere Mt.Jade. If I stop and 
u-boot prompt and disable watchdog via "mw 0x1e78502c 0", the command 
does not happen.

RE: New u-boot-aspeed-sdk runs slow and cause wdt2 timeout on ast2500

[ChiaWei Wang]

> From: Lei Yu <yulei.sh@bytedance.com>
> Sent: Wednesday, February 23, 2022 11:02 AM
> 
> On Wed, Feb 23, 2022 at 10:38 AM ChiaWei Wang
> <chiawei_wang@aspeedtech.com> wrote:
> >
> > > Lei Yu
> > > Sent: Wednesday, February 23, 2022 10:15 AM
> > >
> > > On the latest master with u-boot-aspeed v00.04.09 SDK, an issue
> > > occurs on g220a that it runs slower than before and gets wdt2 timeout.
> > > We reverted the u-boot to a version before v00.04.09 SDK (b0fe8fd9d)
> > > and the issue is gone.
> > >
> > > Below are some details:
> > > * Before v00.04.09: u-boot works OK, and it takes about 9~10 seconds
> > > to load and start the kernel including the 2 seconds timeout for
> > > autoboot, the kernel starts OK and it kicks the watchdog as long as the
> driver is loaded.
> > > * With v00.04.09: u-boot runs slower than before, and it takes about
> > > **16 seconds** to load and start the kernel (including 2s timeout
> > > for autoboot), then the kernel does not have enough time to run and
> > > loads the watchdog driver, and the wdt2 times out on about 22s.
> >
> > Could you share us the boot log with timestamps?
> > It would be nice to know the time elapsed at each stage.
> 
> Pasted to https://pastebin.com/emseqW6c
> It contains two logs, the first one is good, and the second has the issue.

Thanks for the information provided.
It appears that the Hash operation and DRAM initialization takes more time in newer U-Boot.
Could you help to provide the commit hash of the two U-Boot used in the experiment?
We will try to identity the root cause among the patch diffs.

Thanks,
Chiawei

Re: New u-boot-aspeed-sdk runs slow and cause wdt2 timeout on ast2500

[Joel Stanley]

On Wed, 23 Feb 2022 at 04:38, ChiaWei Wang <chiawei_wang@aspeedtech.com> wrote:
>
> > From: Lei Yu <yulei.sh@bytedance.com>
> > Sent: Wednesday, February 23, 2022 11:02 AM
> >
> > On Wed, Feb 23, 2022 at 10:38 AM ChiaWei Wang
> > <chiawei_wang@aspeedtech.com> wrote:
> > >
> > > > Lei Yu
> > > > Sent: Wednesday, February 23, 2022 10:15 AM
> > > >
> > > > On the latest master with u-boot-aspeed v00.04.09 SDK, an issue
> > > > occurs on g220a that it runs slower than before and gets wdt2 timeout.
> > > > We reverted the u-boot to a version before v00.04.09 SDK (b0fe8fd9d)
> > > > and the issue is gone.
> > > >
> > > > Below are some details:
> > > > * Before v00.04.09: u-boot works OK, and it takes about 9~10 seconds
> > > > to load and start the kernel including the 2 seconds timeout for
> > > > autoboot, the kernel starts OK and it kicks the watchdog as long as the
> > driver is loaded.
> > > > * With v00.04.09: u-boot runs slower than before, and it takes about
> > > > **16 seconds** to load and start the kernel (including 2s timeout
> > > > for autoboot), then the kernel does not have enough time to run and
> > > > loads the watchdog driver, and the wdt2 times out on about 22s.
> > >
> > > Could you share us the boot log with timestamps?
> > > It would be nice to know the time elapsed at each stage.
> >
> > Pasted to https://pastebin.com/emseqW6c
> > It contains two logs, the first one is good, and the second has the issue.

Working:
[2022-02-23 02:47:03] U-Boot 2019.04 (Jan 24 2022 - 10:18:18 +0000)
[2022-02-23 02:47:06] ## Loading kernel from FIT Image at 20100000 ...
[2022-02-23 02:47:12] Starting kernel ...

3 + 6 seconds.

broken:
[2022-02-23 02:58:07] U-Boot 2019.04 (Feb 15 2022 - 07:22:14 +0000)
[2022-02-23 02:58:12] ## Loading kernel from FIT Image at 20100000 ...
[2022-02-23 02:58:22] Starting kernel ...

5 + 10 seconds.

Interesting that the pre-hashing part is also slower.

The old branch was based on v00.04.03. The new branch is based on v00.04.09.

I wonder if this is the cause:

$ git diff  v00.04.03..v00.04.09 -- configs/evb-ast2500_defconfig
diff --git a/configs/evb-ast2500_defconfig b/configs/evb-ast2500_defconfig
index 9fcf55b05ebb..000ed3f90bdd 100644
--- a/configs/evb-ast2500_defconfig
+++ b/configs/evb-ast2500_defconfig
@@ -1,4 +1,5 @@
 CONFIG_ARM=y
+CONFIG_SYS_DCACHE_OFF=y
 CONFIG_ARCH_ASPEED=y
 CONFIG_SYS_TEXT_BASE=0x0
 CONFIG_SYS_MALLOC_F_LEN=0x2000

Lei, can you re-test with CONFIG_SYS_DCACHE_OFF=n ?

>
> Thanks for the information provided.
> It appears that the Hash operation and DRAM initialization takes more time in newer U-Boot.
> Could you help to provide the commit hash of the two U-Boot used in the experiment?
> We will try to identity the root cause among the patch diffs.

Regardless of the dcache issue, we should be patting the watchdog as
we do the hashing. It seems this is not happening.

You can see the sha library code does the hashing with the
WATCHDOG_RESET() macro:

$ git grep WATCHDOG lib/sha*
lib/sha1.c:#if defined(CONFIG_HW_WATCHDOG) || defined(CONFIG_WATCHDOG)
lib/sha1.c:#if defined(CONFIG_HW_WATCHDOG) || defined(CONFIG_WATCHDOG)
lib/sha1.c:             WATCHDOG_RESET ();
lib/sha256.c:#if defined(CONFIG_HW_WATCHDOG) || defined(CONFIG_WATCHDOG)
lib/sha256.c:#if defined(CONFIG_HW_WATCHDOG) || defined(CONFIG_WATCHDOG)
lib/sha256.c:           WATCHDOG_RESET();
lib/sha512.c:#if defined(CONFIG_HW_WATCHDOG) || defined(CONFIG_WATCHDOG)
lib/sha512.c:#if defined(CONFIG_HW_WATCHDOG) || defined(CONFIG_WATCHDOG)
lib/sha512.c:           WATCHDOG_RESET();
lib/sha512.c:#if defined(CONFIG_HW_WATCHDOG) || defined(CONFIG_WATCHDOG)
lib/sha512.c:#if defined(CONFIG_HW_WATCHDOG) || defined(CONFIG_WATCHDOG)
lib/sha512.c:           WATCHDOG_RESET();

This relies on CONFIG_WATCHDOG (or CONFIG_HW_WATCHDOG) being enabled:

$ grep CONFIG_WATCHDOG ast2500-obj/.config
# CONFIG_WATCHDOG is not set

which it is not.

In the old branch, we had this:

#if defined(CONFIG_HW_WATCHDOG)
void hw_watchdog_reset(void)
{
        /* Restart WD2 timer */
        writel(0x4755, AST_WDT2_BASE + 0x08);
}
#endif /* CONFIG_WATCHDOG */

We could add that back, or we could backport something like this from upstream:

https://github.com/u-boot/u-boot/commit/06985289d452ad2423145cfed8cece61a7f8cec6

That commit adds support for patting the first registered wdt class
driver. More recently they added
492ee6b8d0e780a2ded5d9df7efc916eb4913734, which supports patting all
of the registered watchdogs. This would be useful for AST2600 systems
to pat both the normal watchdog and the ABR watchdog.

If anyone wants to handle the backporting and testing, I would be
happy to review patches.

Cheers,

Joel

Re: New u-boot-aspeed-sdk runs slow and cause wdt2 timeout on ast2500

[Lei Yu]

> > > > Could you share us the boot log with timestamps?
> > > > It would be nice to know the time elapsed at each stage.
> > >
> > > Pasted to https://pastebin.com/emseqW6c
> > > It contains two logs, the first one is good, and the second has the issue.
>
> Working:
> [2022-02-23 02:47:03] U-Boot 2019.04 (Jan 24 2022 - 10:18:18 +0000)
> [2022-02-23 02:47:06] ## Loading kernel from FIT Image at 20100000 ...
> [2022-02-23 02:47:12] Starting kernel ...
>
> 3 + 6 seconds.
>
> broken:
> [2022-02-23 02:58:07] U-Boot 2019.04 (Feb 15 2022 - 07:22:14 +0000)
> [2022-02-23 02:58:12] ## Loading kernel from FIT Image at 20100000 ...
> [2022-02-23 02:58:22] Starting kernel ...
>
> 5 + 10 seconds.
>
> Interesting that the pre-hashing part is also slower.
>
> The old branch was based on v00.04.03. The new branch is based on v00.04.09.
>
> I wonder if this is the cause:
>
> $ git diff  v00.04.03..v00.04.09 -- configs/evb-ast2500_defconfig
> diff --git a/configs/evb-ast2500_defconfig b/configs/evb-ast2500_defconfig
> index 9fcf55b05ebb..000ed3f90bdd 100644
> --- a/configs/evb-ast2500_defconfig
> +++ b/configs/evb-ast2500_defconfig
> @@ -1,4 +1,5 @@
>  CONFIG_ARM=y
> +CONFIG_SYS_DCACHE_OFF=y
>  CONFIG_ARCH_ASPEED=y
>  CONFIG_SYS_TEXT_BASE=0x0
>  CONFIG_SYS_MALLOC_F_LEN=0x2000
>
> Lei, can you re-test with CONFIG_SYS_DCACHE_OFF=n ?
>

Yiwei helped to test with CONFIG_SYS_DCACHE_OFF=n, and it works fine now.
So it seems we get the root cause!

Re: New u-boot-aspeed-sdk runs slow and cause wdt2 timeout on ast2500

[Joel Stanley]

On Wed, 23 Feb 2022 at 10:02, Lei Yu <yulei.sh@bytedance.com> wrote:
>
> > > > > Could you share us the boot log with timestamps?
> > > > > It would be nice to know the time elapsed at each stage.
> > > >
> > > > Pasted to https://pastebin.com/emseqW6c
> > > > It contains two logs, the first one is good, and the second has the issue.
> >
> > Working:
> > [2022-02-23 02:47:03] U-Boot 2019.04 (Jan 24 2022 - 10:18:18 +0000)
> > [2022-02-23 02:47:06] ## Loading kernel from FIT Image at 20100000 ...
> > [2022-02-23 02:47:12] Starting kernel ...
> >
> > 3 + 6 seconds.
> >
> > broken:
> > [2022-02-23 02:58:07] U-Boot 2019.04 (Feb 15 2022 - 07:22:14 +0000)
> > [2022-02-23 02:58:12] ## Loading kernel from FIT Image at 20100000 ...
> > [2022-02-23 02:58:22] Starting kernel ...
> >
> > 5 + 10 seconds.
> >
> > Interesting that the pre-hashing part is also slower.
> >
> > The old branch was based on v00.04.03. The new branch is based on v00.04.09.
> >
> > I wonder if this is the cause:
> >
> > $ git diff  v00.04.03..v00.04.09 -- configs/evb-ast2500_defconfig
> > diff --git a/configs/evb-ast2500_defconfig b/configs/evb-ast2500_defconfig
> > index 9fcf55b05ebb..000ed3f90bdd 100644
> > --- a/configs/evb-ast2500_defconfig
> > +++ b/configs/evb-ast2500_defconfig
> > @@ -1,4 +1,5 @@
> >  CONFIG_ARM=y
> > +CONFIG_SYS_DCACHE_OFF=y
> >  CONFIG_ARCH_ASPEED=y
> >  CONFIG_SYS_TEXT_BASE=0x0
> >  CONFIG_SYS_MALLOC_F_LEN=0x2000
> >
> > Lei, can you re-test with CONFIG_SYS_DCACHE_OFF=n ?
> >
>
> Yiwei helped to test with CONFIG_SYS_DCACHE_OFF=n, and it works fine now.
> So it seems we get the root cause!

I'm glad this worked. The bill is in the mail :)

I would suggest this is not the root cause. This is a workaround that
speeds up booting enough that you make it to linux, but if your kernel
image got a bit larger (for example), it would take longer and the
issue would show up again.

To properly fix the issue, we need to ensure the watchdog is serviced,
as I mentioned in my previous email.

Cheers,

Joel