This thread has been locked.

If you have a related question, please click the "Ask a related question" button in the top right corner. The newly created question will be automatically linked to this question.

AM3352: Linux reboot command hangs for 10 minutes (while booting down), then succeeds

Part Number: AM3352
Other Parts Discussed in Thread: AM3359,

Hello,

We are facing a strange problem with AM3352BZCZD60-based custom design PCB. System seems to be working otherwise fine, but when I run reboot the system hangs:


Arago Project http://arago-project.org am335x-evm ttyS3

Arago 2019.11 am335x-evm ttyS3

am335x-evm login: root
root@am335x-evm:~# reboot
root@am335x-evm:~#          Unmounting /run/media/mmcblk1p4...
         Unmounting /run/media/mmcblk1p2...
         Stopping Session c1 of user root.
         Stopping User Manager for UID 0...
         Unmounting /run/media/mmcblk1p1...
         Stopping NFS status monitor for NFSv2/3 locking....
[  OK  ] Closed Load/Save RF Kill Switch Status /dev/rfkill Watch.
[  OK  ] Stopped target Timers.
[  OK  ] Stopped Daily rotation of log files.
[  OK  ] Stopped Daily Cleanup of Temporary Directories.
[  OK  ] Stopped Serial Getty on ttyS3.

...

[  OK  ] Stopped Create Static Device Nodes in /dev.
[  OK  ] Reached target Shutdown.
[  OK  ] Reached target Final Step.
         Starting Reboot...
[  327.458349] watchdog: watchdog0: watchdog did not stop!
[  327.475070] systemd-shutdow: 29 output lines suppressed due to ratelimiting
[  327.520955] systemd-shutdown[1]: Syncing filesystems and block devices.
[  327.540341] systemd-shutdown[1]: Sending SIGTERM to remaining processes...
[  327.570333] systemd-journald[77]: Received SIGTERM from PID 1 (systemd-shutdow).
[  327.603411] systemd-shutdown[1]: Sending SIGKILL to remaining processes...
[  327.626189] systemd-shutdown[1]: Hardware watchdog 'OMAP Watchdog', version 0
[  327.640817] systemd-shutdown[1]: Unmounting file systems.
[  327.658243] [881]: Remounting '/' read-only in with options '(null)'.
[  327.696609] EXT4-fs (mmcblk1p3): re-mounted. Opts: (null)
[  327.719348] systemd-shutdown[1]: All filesystems unmounted.
[  327.725546] systemd-shutdown[1]: Deactivating swaps.
[  327.731221] systemd-shutdown[1]: All swaps deactivated.
[  327.737208] systemd-shutdown[1]: Detaching loop devices.
[  327.757021] systemd-shutdown[1]: All loop devices detached.

<STAYS HERE FOR 10 MINUTES 8 SECONDS>

<WAKES UP, BOOTS UP TO U-BOOT AND SYSTEM JUST FINE: >

U-Boot 2019.01 (Mar 01 2022 - 03:11:13 +0200)

CPU  : AM335X-GP rev 2.1
Model: TI AM3359 ICE-V2
DRAM:  256 MiB
ETH0, PRU
NAND:  0 MiB
MMC:   OMAP SD/MMC: 0, OMAP SD/MMC: 1
Loading Environment from FAT... <ethaddr> not set. Validating first E-fuse MAC
Net:   eth0: ethernet@4a100000
Hit any key to stop autoboot:  0
Trying to load uEnv.txt from mmc 1:1 (internal)
1304 bytes read in 1 ms (1.2 MiB/s)
Trying to load uEnv.txt from mmc 0:1 (external)
26 bytes read in 1 ms (25.4 KiB/s)
Loading correct boot bank info from FW_bank_uEnv.txt
** Unable to read file /flags/1ST_FULL_BOOT **
** Unable to read file /flags/1ST_UBOOT **
switch to partitions #0, OK
mmc1(part 0) is current device
SD/MMC found on device 1
4280832 bytes read in 360 ms (11.3 MiB/s)
36957 bytes read in 4 ms (8.8 MiB/s)
## Flattened Device Tree blob at 88000000
   Booting using the fdt blob at 0x88000000
   Loading Device Tree to 8df2d000, end 8df3905c ... OK

Starting kernel ...

[    0.000000] Booting Linux on physical CPU 0x0
[    0.000000] Linux version 4.19.94-gbe5389fd85 (oe-user@oe-host) (gcc version 8.3.0 (GNU Toolchain for the A-profile Architecture 8.3-2019.03 (arm-rel-8.36))) #1 PREEMPT Sun Feb 20 15:14:05 UTC 2022
[    0.000000] CPU: ARMv7 Processor [413fc082] revision 2 (ARMv7), cr=10c5387d
[    0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache
[    0.000000] OF: fdt: Machine model: TI AM3352 PROPRIETARY AP1 - i2c eeprom added
[    0.000000] Memory policy: Data cache writeback
[    0.000000] efi: Getting EFI parameters from FDT:
[    0.000000] efi: UEFI not found.
[    0.000000] cma: Reserved 48 MiB at 0x8a800000
[    0.000000] CPU: All CPU(s) started in SVC mode.
[    0.000000] AM335X ES2.1 (neon)

<BOOTS JUST FINE FROM THIS POINT>

...

Where does the reboot wait 10 minutes and why?

  • Some random info:

    root@am335x-evm:~# uname -a

    Linux am335x-evm 4.19.94-gbe5389fd85 #1 PREEMPT Sun Feb 20 15:14:05 UTC 2022 armv7l GNU/Linux

    I think we are using TI Processor SDK 06.03.00.106 in yocto.

    As can be seen, we are booting from internal eMMC.

    Reset in u-boot works always just fine!

    We are using TPS65910A3A1RSLR PMIC.

  • Interestingly, while the long reboot is ongoing, ping still works, so kernel is still alive?!?

    <WAITING ON THE LONG REBOOT>

    64 bytes from 172.16.9.13: icmp_seq=1 ttl=128 time=6.16 ms
    64 bytes from 172.16.9.13: icmp_seq=2 ttl=128 time=8.41 ms
    64 bytes from 172.16.9.13: icmp_seq=4 ttl=128 time=7.20 ms
    64 bytes from 172.16.9.13: icmp_seq=5 ttl=128 time=37.1 ms
    64 bytes from 172.16.9.13: icmp_seq=6 ttl=128 time=8.29 ms
    64 bytes from 172.16.9.13: icmp_seq=7 ttl=128 time=8.91 ms
    64 bytes from 172.16.9.13: icmp_seq=8 ttl=128 time=13.9 ms
    64 bytes from 172.16.9.13: icmp_seq=9 ttl=128 time=7.04 ms
    64 bytes from 172.16.9.13: icmp_seq=10 ttl=128 time=6.83 ms

    <MAIN POWER OFF VIA EXTERNAL PSU>

    From 172.16.9.31 icmp_seq=31 Destination Host Unreachable
    From 172.16.9.31 icmp_seq=34 Destination Host Unreachable
    From 172.16.9.31 icmp_seq=37 Destination Host Unreachable

  • I compared Evaluation board AM3359 to our AM3352, running "strace reboot -f -f" :

    ...

    openat(AT_FDCWD, "/proc/self/stat", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = 3
    fstat64(3, {st_mode=S_IFREG|0444, st_size=0, ...}) = 0
    read(3, "810 (reboot) R 807 807 740 1091 "..., 1024) = 229
    close(3)                                = 0

    <EVALUATION BOARD AM3359 WOULD REBOOT FINE HERE>

    <BUT OUR CUSTOM DESIGN AM3352 SUDDENLY RECEIVES SIGBUS HERE:>

    rt_sigaction(SIGBUS, {sa_handler=0xb6ddb9fd, sa_mask=[], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0xb6c122c0}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
    ioctl(1, TCGETS, {B115200 opost isig icanon echo ...}) = 0
    openat(AT_FDCWD, "/sys/kernel/kexec_loaded", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = 3
    fstat64(3, {st_mode=S_IFREG|0444, st_size=4096, ...}) = 0

    ...

    faccessat(AT_FDCWD, "/run/systemd/system/", F_OK) = 0
    sync()                                  = 0
    reboot(LINUX_REBOOT_MAGIC1, LINUX_REBOOT_MAGIC2, LINUX_REBOOT_CMD_CAD_ON) = 0
    access("/proc/vz", F_OK)                = -1 ENOENT (No such file or directory)

    ...

    openat(AT_FDCWD, "/run/systemd/reboot-param", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = -1 ENOENT (No such file or directory)
    writev(2, [{iov_base="Rebooting.", iov_len=10}, {iov_base="\n", iov_len=1}], 2Rebooting.
    ) = 11
    reboot(LINUX_REBOOT_MAGIC1, LINUX_REBOOT_MAGIC2, LINUX_REBOOT_CMD_RESTART

    <OUR CUSTOM DESIGN AM3352 DOES NOT RECOVER FROM THIS. BUT IT RECOVERED FROM THE REGULAR "reboot" COMMAND>

  • Hi Janne,

    Does the strace log on your board show at which point the long delay happens?

  • Hi Bin. This is a good point. In u-boot I did the following:

    setenv optargs debug printk.devkmsg=on printk_devkmsg=on

    then I booted. I get tons and tons of messages on reboot and finally this:

    [  251.471517] systemd-journald[67]: Received SIGTERM from PID 1 (systemd-shutdow).
    [  251.479037] systemd-journald[67]: systemd-journald stopped as pid 67
    [  251.486040] systemd-journald[67]: Journal effective settings seal=no compress=yes compress_threshold_bytes=512B
    [  251.496546] systemd-journald[67]: Journal effective settings seal=no compress=yes compress_threshold_bytes=512B
    [  251.518476] systemd-shutdown[1]: Sending SIGKILL to remaining processes...
    [  251.541870] systemd-shutdown[1]: Hardware watchdog 'OMAP Watchdog', version 0
    [  251.556360] systemd-shutdown[1]: Unmounting file systems.
    [  251.568043] systemd-shutdown[1]: Successfully forked off '(sd-remount)' as PID 835.
    [  251.581274] [835]: Remounting '/' read-only in with options '(null)'.
    [  251.624985] EXT4-fs (mmcblk1p3): re-mounted. Opts: (null)
    [  251.643958] systemd-shutdown[1]: All filesystems unmounted.
    [  251.649645] systemd-shutdown[1]: Deactivating swaps.
    [  251.655732] systemd-shutdown[1]: All swaps deactivated.
    [  251.661456] systemd-shutdown[1]: Detaching loop devices.
    [  251.667023] systemd-shutdown[1]: device-enumerator: scan all dirs
    [  251.673733] systemd-shutdown[1]:   device-enumerator: scanning /sys/bus
    [  251.680981] systemd-shutdown[1]:   device-enumerator: scanning /sys/class
    [  251.701229] systemd-shutdown[1]: All loop devices detached.
    [  251.706901] systemd-shutdown[1]: Detaching DM devices.
    [  251.712353] systemd-shutdown[1]: device-enumerator: scan all dirs
    [  251.718673] systemd-shutdown[1]:   device-enumerator: scanning /sys/bus
    [  251.726131] systemd-shutdown[1]:   device-enumerator: scanning /sys/class
    [  251.733888] systemd-shutdown[1]: All DM devices detached.
    [  251.739372] systemd-shutdown[1]: All filesystems, swaps, loop devices and DM devices detached.
    [  251.749400] systemd-shutdown[1]: Successfully forked off '(sd-executor)' as PID 836.
    [  251.769956] systemd-shutdown[1]: (sd-executor) succeeded.
    [  251.776720] systemd-shutdown[1]: Successfully forked off '(sd-sync)' as PID 837.
    [  251.790433] systemd-shutdown[1]: Syncing filesystems and block devices.
    [  251.797671] systemd-shutdown[1]: Rebooting.

    I was thinking I will get systemd source, recompile it with custom debug info and see what is wrong. Like what they did here: https://github.com/systemd/systemd/issues/11821#issuecomment-475987668 . Unfortunately I caught flu and I'm currently bed-ridden. I will test this when I get back to my lab.

  • To recap: There are 2 problems:

    1. Huge delay in systemd-reboot

    2. reboot -f -f not working at all (it hangs forever)

    I just need the systemd-reboot to work.

  • Hi Janne,

    [ 251.471517] systemd-journald[67]: Received SIGTERM from PID 1 (systemd-shutdow). ... [ 251.797671] systemd-shutdown[1]: Rebooting.

    Does the long delay happen before or after seeing these log messages?

  • Thank you for your interest. It happens so that I see:

    [  251.797671] systemd-shutdown[1]: Rebooting.

    Then it delays for 10 minutes and reboots.

  • Hi Janne,

    Here is a quick test, does running command 'devmem2 0x44e00f00 w 1' on the console immediately reboot the board?

  • Thank you Bin, I will try this when I get back to my lab without fewer.

  • I got the systemd-239 source. I think I know how to code path goes:

    shutdown.c:399 log_info("All filesystems, swaps, loop devices and DM devices detached.");

    shutdown.c:470 sync_with_progress();

    shutdown.c:225 log_info("Syncing filesystems and block devices.");

    shutdown.c:506 (void) reboot_with_parameter(REBOOT_LOG);

    reboot-util.c:75 log_full(flags & REBOOT_LOG ? LOG_INFO : LOG_DEBUG, "Rebooting.");

    reboot-util.c:80 (void) reboot(RB_AUTOBOOT);

    reboot(RB_AUTOBOOT) is probably a system call to the kernel, so it looks like something gets stuck inside the kernel?

  • Janne,

    Following is the note I created some time back showing the am335x kernel callflow for reboot. You might use it as a reference to debug the kernel for this issue.

    kernel_restart()                                        in kernel/reboot.c
      machine_restart()                                     in arch/arm/kernel/reboot.c
        arm_pm_restart()                                    in arch/arm/kernel/setup.c
          DT_MACHINE_START(AM33XX_DT...)                    in arch/arm/mach-omap2/board-generic.c
            am33xx-restart()                                in arch/arm/mach-omap2/am33xx-restart.c
              omap_prm_reset_system()                       in arch/arm/mach-omap2/prm_common.c
                prm_ll_daata->reset_system()
                  am33xx_prm_ll_data                        in arch/arm/mach-omap2/prm33xx.c
                    am33xx_prm_global_warm_sw_reset()       in arch/arm/mach-omap2/prm33xx.c
    
                      which does global warm reset, as:
                      # devmem2 0x44e00f00 w 1
    

  • Thank you Bin! This will be also extremely helpful!

  • I took a look at source https://elixir.bootlin.com/linux/v4.19.94/source/kernel/reboot.c#L241 :

    void kernel_restart(char *cmd)
    {
    	kernel_restart_prepare(cmd);
    	migrate_to_reboot_cpu();
    	syscore_shutdown();
    	if (!cmd)
    		pr_emerg("Restarting system\n");
    	else
    		pr_emerg("Restarting system with command '%s'\n", cmd);
    	kmsg_dump(KMSG_DUMP_RESTART);
    	machine_restart(cmd);
    }

    I think I should be seeing the "Restarting system" directly from kernel. Like this chap: https://e2e.ti.com/support/processors-group/processors/f/processors-forum/989184/am6548-command-reboot-hang-with-sd-boot :

    [ 40.211461] systemd-shutdown[1]: Rebooting.
    [ 40.241162] reboot: Restarting system

    But I only see the systemd saying Rebooting. So I think problem is possibly in one of these sub-calls:

    kernel_restart_prepare()
    migrate_to_reboot_cpu()
    syscore_shutdown()

    I'll just put more prints there and see what it can process and what not, haha.

  • I was able to put these custom prints to my kernel as a proof of concept:

    void kernel_restart(char *cmd)
    {
      pr_emerg("Entered kernel_restart\n");
      kmsg_dump(KMSG_DUMP_RESTART);
      kernel_restart_prepare(cmd);
      pr_emerg("Entering migrate_to_reboot_cpu\n");
      kmsg_dump(KMSG_DUMP_RESTART);
      migrate_to_reboot_cpu();
      pr_emerg("Entering syscore_shutdown\n");
      kmsg_dump(KMSG_DUMP_RESTART);
      syscore_shutdown();
      if (!cmd)
        pr_emerg("Restarting system\n");
      else
        pr_emerg("Restarting system with command '%s'\n", cmd);
      kmsg_dump(KMSG_DUMP_RESTART);
      pr_emerg("Entering machine_restart\n");
      kmsg_dump(KMSG_DUMP_RESTART);
            machine_restart(cmd);
    }
    

    Aand, they show up while rebooting! See:

    [  641.369925] systemd-shutdown[1]: All swaps deactivated.
    [  641.375239] systemd-shutdown[1]: Detaching loop devices.
    [  641.394983] systemd-shutdown[1]: All loop devices detached.
    [  641.446854] reboot: Entered kernel_restart

    So, no it is a matter of putting the prints everywhere and recompiling until the bug is found.

  • Hi again, Bin,

    While another kernel is compiling, I tried the devmem2 thing:

    root@am335x-evm:~# sync
    root@am335x-evm:~# devmem2 0x44e00f00 w 1
    /dev

    U-Boot 2019.01 (Mar 01 2022 - 03:11:13 +0200)

    CPU  : AM335X-GP rev 2.1
    Model: TI AM3359 ICE-V2
    DRAM:  256 MiB
    ETH0, PRU
    NAND:  0 MiB
    MMC:   OMAP SD/MMC: 0, OMAP SD/MMC: 1
    Loading Environment from FAT... *** Warning - bad CRC, using default environment

    <ethaddr> not set. Validating first E-fuse MAC
    Net:   eth0: ethernet@4a100000
    Hit any key to stop autoboot:  0

    So, it works! I believed it would, because u-boot also works.

    Now I believe 100% that problem is not in u-boot, not in systemd, not in hardware but inside a kernel branch. Getting there...

  • [   91.766944] reboot: Entered kernel_restart
    [   91.771551] reboot: kernel_restart_prepare calling blocking_notifier_call_chain
    [   91.778994] reboot: kernel_restart_prepare SYSTEM_RESTART
    [   91.784822] reboot: kernel_restart_prepare calling usermodehelper_disable
    [   91.791788] reboot: kernel_restart_prepare calling device_shutdown

    I need to continue tomorrow. But kernel_restart_prepare() is calling device_shutdown() but not returning on time. So next dive is inside device_shutdown(). Too bad each iteration takes 35 minutes, but I am making progress.

    EDIT: Further prints:

    [  322.368635] device_shutdown(): entered
    [  322.372419] device_shutdown(): calling wait_for_device_probe()

    So, nerver returning from wait_for_device_probe().

    EDIT:

    [  155.207329] wait_for_device_probe(): entered
    [  155.211627] wait_for_device_probe(): calling flush_work()
    [  155.217129] wait_for_device_probe(): calling wait_event()

  • Janne,

    Now I believe 100% that problem is not in u-boot, not in systemd, not in hardware but inside a kernel branch.

    I agreed.

    Too bad each iteration takes 35 minutes

    Why does it take this long?

    It would take some time to add printk(), but 'make Image' should take no more than one minute, then copy Image to the sdcard, boot the board and do reboot command. I thought each iteration should take no longer than a few minutes, the most time would be on reviewing the source code to figure out where to put the printk()...

    In my daily work while debugging kernel, I use tftp+NFS boot (when cpsw still works...), so the sdcard only holds uboot binaries, then I can rebuild kernel and boot the board within a minute...

  • oh, I guess you don't use SD card boot...

  • I use actually both SD and eMMC. I use Yocto. And I have not set it up myself and my knowledge is limited, so I'm just sticking to what is available here. Of course I could find a way to shortcut things, but with Yocto it at least "works" every time (otherwise than the reboot thing).

  • I'm not sure but I got a feeling that I am hitting this: https://bugs.launchpad.net/ubuntu/+source/linux/+bug/1886827

    See also: https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/?id=b292b50b0efcc7095d8bf15505fba6909bb35dce

    I decided I will just try newer Yocto build with more recent kernel, possibly already having the fix.

  • Unlocking per Janne's request 

  • Hello,

    I have debugged the situation a bit forward. I have not had time to try the new kernel yet, there is soooo much going on. But I found a way to work around this.

    Basically I created this patch which comments out kernel_restart_prepare:

    diff --git a/kernel/reboot.c b/kernel/reboot.c
    index 8fb44dec9ad7..38932c1cb404 100644
    --- a/kernel/reboot.c
    +++ b/kernel/reboot.c
    @@ -240,7 +240,7 @@ void migrate_to_reboot_cpu(void)
      */
     void kernel_restart(char *cmd)
     {
    -       kernel_restart_prepare(cmd);
    +        //kernel_restart_prepare(cmd);
            migrate_to_reboot_cpu();
            syscore_shutdown();
            if (!cmd)

    Now reboot works. I figure that because systemd has already unmounted everything and remounted / read-only, I'm probably on safe waters. At least opposed to earlier approach, which was using devmem2 directly from running system. I'd like to hear arguments if omitting kernel_restart_prepare() is dangerous in this context.

    I have narrowed down the actual problem also a bit:

    void kernel_restart(char *cmd)
    -void kernel_restart_prepare(char *cmd)
    --void device_shutdown(void)
    ---void wait_for_device_probe(void)
    ----#define wait_event(wq_head, condition)
    -----#define __wait_event(wq_head, condition)
    ------asmlinkage __visible void __sched schedule(void) < HANGS HERE

    I will keep digging. This is not work anymore. This is personal.

  • And we have some major developments.

    I realized we have AM3352. But in our dts-included .dtsi (for dtb) we had this:

    &pruss_soc_bus {
            status = "okay";

        pruss: pruss@4a300000 {
                    status = "okay";
            };
    };

    So I took it out in our dts:

    // Deleting pruss because our PCB AM3352 does not have it
    /delete-node/ &pruss_soc_bus;

    Lo and behold on reboot:

    [  150.936697] systemd-shutdown[1]: Deactivating swaps.
    [  150.942497] systemd-shutdown[1]: All swaps deactivated.
    [  150.947808] systemd-shutdown[1]: Detaching loop devices.
    [  150.963229] systemd-shutdown[1]: All loop devices detached.
    [  151.224165] mmc1: cache flush error -110
    [  151.228202] mmc1: error -110 during shutdown
    [  151.254675] reboot: Restarting system


    U-Boot 2019.01 (Mar 01 2022 - 03:11:13 +0200)

    CPU  : AM335X-GP rev 2.1
    Model: TI AM3359 ICE-V2
    DRAM:  256 MiB
    ETH0, PRU

    Still some kind of problem, but looks much more "reasonable" than earlier skipping of kernel functions based on a hunch.

    Thank you everyone for helping. I consider my original problem solved.

  • I recompiled everything without traces of my "skip" patch. I have been rebooting a system running from eMMC. The hang problems are gone. And no -110 errors either.

  • Janne, thanks for closing the loop here and keeping us posted. Glad to hear the issue is resolved.