[imx8mp] cannot wake up from suspend if message sent to serial too early

[martinetd]

Hello,

Sometimes our imx8mp board does not wake up from suspend in regression testing.

It looks like when a message is sent to tty too early, the driver falls in a bad state and wake up from tty no longer works (wake up from another external source like gpio still works in this state, so suspend succeeded, only the wake up by tty stopped working)

This can be reproduced as follow, I've confirmed I can reproduce it on imx8mp-evk with multiple kernels from 5.10.72-2.2.2 to 6.6.3-1.0.0 so this doesn't look fixed.

root@imx8mpevk:~# echo enabled > /sys/class/tty/ttymxc1/power/wakeup
root@imx8mpevk:~# while true; do echo mem > /sys/power/state; done
(at this point, keep a key pressed -- this does not reproduce 100% of the time but after a dozen of suspend/resume the system will stop waking up; usually takes less than 30s. Logs below with the 'f' key pressed)
[...]

f[   39.292333] imx-dwmac 30bf0000.ethernet eth1: No Safety Features support found
[   39.299579] imx-dwmac 30bf0000.ethernet eth1: IEEE 1588-2008 Advanced Timestamp supported
[   39.307965] imx-dwmac 30bf0000.ethernet eth1: FPE workqueue start
f[   39.314271] xhci-hcd xhci-hcd.1.auto: xHC error in resume, USBSTS 0x401, Reinit
[   39.314504] caam 30900000.crypto: registering rng-caam
[   39.321582] usb usb1: root hub lost power or was reset
[   39.321586] usb usb2: root hub lost power or was reset
ff[   39.429609] PM: resume devices took 0.360 seconds
[   39.434367] OOM killer enabled.
f[   39.437515] Restarting tasks ... done.
[   39.442550] random: crng reseeded on system resumption
[   39.447806] PM: suspend exit
[   39.450892] PM: suspend entry (deep)
ff[   39.523722] Filesystems sync: 0.069 seconds
[   39.528483] Freezing user space processes
[   39.532967] Freezing user space processes completed (elapsed 0.004 seconds)
[   39.539965] OOM killer disabled.
[   39.543210] Freezing remaining freezable tasks
ff[   39.604257] Freezing remaining freezable tasks completed (elapsed 0.056 seconds)
ff[   39.681364] imx-dwmac 30bf0000.ethernet eth1: FPE workqueue stop
[   39.694694] PM: suspend devices took 0.084 seconds
[   39.702612] Disabling non-boot CPUs ...
[   39.708044] psci: CPU1 killed (polled 0 ms)
[   39.713999] psci: CPU2 killed (polled 0 ms)
[   39.718424] Wakeup pending. Abort CPU freeze
[   39.722733] Non-boot CPUs are not disabled
[   39.726841] Enabling non-boot CPUs ...
[   39.730964] Detected VIPT I-cache on CPU1
[   39.730991] GICv3: CPU1: found redistributor 1 region 0:0x00000000388a0000
[   39.731020] CPU1: Booted secondary processor 0x0000000001 [0x410fd034]
[   39.731491] CPU1 is up
[   39.751641] Detected VIPT I-cache on CPU2
[   39.751662] GICv3: CPU2: found redistributor 2 region 0:0x00000000388c0000
[   39.751683] CPU2: Booted secondary processor 0x0000000002 [0x410fd034]
[   39.752156] CPU2 is up
ffffff[   39.952174] imx-dwmac 30bf0000.ethernet eth1: configuring for phy/rgmii-id link mode
f[   39.995983] imx-dwmac 30bf0000.ethernet eth1: No Safety Features support found
f[   40.003231] imx-dwmac 30bf0000.ethernet eth1: IEEE 1588-2008 Advanced Timestamp supported
[   40.012256] imx-dwmac 30bf0000.ethernet eth1: FPE workqueue start
[   40.018553] xhci-hcd xhci-hcd.1.auto: xHC error in resume, USBSTS 0x401, Reinit
[   40.018705] caam 30900000.crypto: registering rng-caam
[   40.025864] usb usb1: root hub lost power or was reset
[   40.025867] usb usb2: root hub lost power or was reset
fff[   40.132990] PM: resume devices took 0.360 seconds
[   40.137748] OOM killer enabled.
[   40.140896] Restarting tasks ... done.
[   40.145896] random: crng reseeded on system resumption
[   40.151162] PM: suspend exit
-sh: echo: write error: Device or[   40.154279] PM: suspend entry (deep)
 resource busy
ff[   40.225654] Filesystems sync: 0.064 seconds
[   40.230469] Freezing user space processes
[   40.235950] Freezing user space processes completed (elapsed 0.001 seconds)
f[   40.242979] OOM killer disabled.
[   40.246544] Freezing remaining freezable tasks
f[   40.295917] Freezing remaining freezable tasks completed (elapsed 0.044 seconds)
fff[   40.422151] imx-dwmac 30bf0000.ethernet eth1: FPE workqueue stop
[   40.435887] PM: suspend devices took 0.136 seconds
[   40.443055] Disabling non-boot CPUs ...
[   40.447724] psci: CPU1 killed (polled 4 ms)
[   40.453729] psci: CPU2 killed (polled 0 ms)
[   40.459617] psci: CPU3 killed (polled 0 ms)
(hung here, no more feedback from tty)

The "keep key pressed" example is quite silly, but it's possible that the system decided to sleep after a timeout and at that precise timing an external wakeup event comes and gets stuck (this is what happens in our test), so it'd be great to fix this.

It's likely that a key event comes between enabling wakeup in drivers/tty/serial/imx.c's imx_uart_suspend() and the actual suspend and the state machine gets somehow incorrectly stuck; perhaps not disabling irq and catching these (calling pm_system_wakeup() from the irq if one came after suspend started) would work better?

Thanks.

[Bio_TICFSL]

Hello,

Something is bad with the current driver, I will report immediately thanks for the catch. could you telll me what pins are you using?

Regards

[martinetd]

Hi @Bio_TICFSL

Have you heard back from the developers?
Would be happy to test a workaround or anything you could provide.

(The linux-imx lf-6.6.23-2.0.0 tag was pushed last week and I've quickly checked the content but there doesn't seem to have been a fix this fast -- I'm not in a very big hurry here, but our platform test failed again on this problem earlier today so I got curious and checked)

Thanks,
Dominique

[Bio_TICFSL]

Hello,

The issue is not reproducible with latest kernel, please provide a test code to check it.

Regards

[martinetd]

Thank you for the quick reply, sorry I hadn't noticed it.

I've just updated to last week's release and can still reproduce on imx8mp-evk / BSP v6.6.23-2.0.0

input is stuck at the end of the block below:

U-Boot SPL 2024.04+g674440bc73e+p0 (Jun 06 2024 - 10:05:34 +0000)
...
U-Boot 2024.04+g674440bc73e+p0 (Jun 06 2024 - 10:05:34 +0000)
...
NXP i.MX Release Distro 6.6-scarthgap imx8mpevk ttymxc1

imx8mpevk login: root
root@imx8mpevk:~# dmesg -n 7
root@imx8mpevk:~# echo enabled > /sys/class/tty/ttymxc1/power/wakeup
root@imx8mpevk:~# uname -r
6.6.23-lts-next-06236-gb586a521770e
root@imx8mpevk:~# while true; do echo mem > /sys/power/state; done
[   33.389011] PM: suspend entry (deep)
[   33.408535] Filesystems sync: 0.015 seconds
[   33.415560] Freezing user space processes
[   33.420826] Freezing user space processes completed (elapsed 0.001 seconds)
[   33.427853] OOM killer disabled.
[   33.431151] Freezing remaining freezable tasks
[   33.436796] Freezing remaining freezable tasks completed (elapsed 0.001 seconds)
[   33.444209] printk: Suspending console(s) (use no_console_suspend to debug)
[   33.485502] imx-dwmac 30bf0000.ethernet eth1: FPE workqueue stop
[   33.485555] fec 30be0000.ethernet eth0: Link is Down
[   33.495972] PM: suspend devices took 0.040 seconds
[   33.498648] Disabling non-boot CPUs ...
[   33.500239] psci: CPU1 killed (polled 0 ms)
[   33.502369] psci: CPU2 killed (polled 0 ms)
[   33.504336] psci: CPU3 killed (polled 0 ms)
[   33.505234] Enabling non-boot CPUs ...
[   33.505643] Detected VIPT I-cache on CPU1
[   33.505672] GICv3: CPU1: found redistributor 1 region 0:0x00000000388a0000
[   33.505703] CPU1: Booted secondary processor 0x0000000001 [0x410fd034]
[   33.506196] CPU1 is up
[   33.506534] Detected VIPT I-cache on CPU2
[   33.506551] GICv3: CPU2: found redistributor 2 region 0:0x00000000388c0000
[   33.506567] CPU2: Booted secondary processor 0x0000000002 [0x410fd034]
[   33.506930] CPU2 is up
[   33.507264] Detected VIPT I-cache on CPU3
[   33.507281] GICv3: CPU3: found redistributor 3 region 0:0x00000000388e0000
[   33.507297] CPU3: Booted secondary processor 0x0000000003 [0x410fd034]
[   33.507688] CPU3 is up
[   33.688982] imx-dwmac 30bf0000.ethernet eth1: configuring for phy/rgmii-id link mode
[   33.724728] imx-dwmac 30bf0000.ethernet eth1: No Safety Features support found
[   33.724747] imx-dwmac 30bf0000.ethernet eth1: IEEE 1588-2008 Advanced Timestamp supported
[   33.725025] imx-dwmac 30bf0000.ethernet eth1: FPE workqueue start
[   33.725334] xhci-hcd xhci-hcd.1.auto: xHC error in resume, USBSTS 0x401, Reinit
[   33.725342] usb usb1: root hub lost power or was reset
[   33.725346] usb usb2: root hub lost power or was reset
[   33.726676] caam 30900000.crypto: registering rng-caam
[   33.834089] PM: resume devices took 0.324 seconds
[   33.986160] OOM killer enabled.
[   33.989313] Restarting tasks ... done.
[   33.994648] random: crng reseeded on system resumption
[   33.999924] PM: suspend exit
[   34.000157] PM: suspend entry (deep)
[   34.064351] Filesystems sync: 0.064 seconds
[   34.072114] Freezing user space processes
[   34.084217] Freezing user space processes completed (elapsed 0.007 seconds)
[   34.091298] OOM killer disabled.
[   34.094577] Freezing remaining freezable tasks
[   34.144794] Freezing remaining freezable tasks completed (elapsed 0.045 seconds)
[   34.152224] printk: Suspending console(s) (use no_console_suspend to debug)
fffffffffff[   34.219468] imx-dwmac 30bf0000.ethernet eth1: FPE workqueue stop
[   34.226669] PM: suspend devices took 0.068 seconds
[   34.229121] Disabling non-boot CPUs ...
[   34.230674] psci: CPU1 killed (polled 0 ms)
[   34.231070] Wakeup pending. Abort CPU freeze
[   34.231073] Non-boot CPUs are not disabled
[   34.231075] Enabling non-boot CPUs ...
[   34.231464] Detected VIPT I-cache on CPU1
[   34.231492] GICv3: CPU1: found redistributor 1 region 0:0x00000000388a0000
[   34.231523] CPU1: Booted secondary processor 0x0000000001 [0x410fd034]
[   34.231998] CPU1 is up
[   34.412892] imx-dwmac 30bf0000.ethernet eth1: configuring for phy/rgmii-id link mode
[   34.448727] imx-dwmac 30bf0000.ethernet eth1: No Safety Features support found
[   34.448748] imx-dwmac 30bf0000.ethernet eth1: IEEE 1588-2008 Advanced Timestamp supported
f[   34.449127] imx-dwmac 30bf0000.ethernet eth1: FPE workqueue start
[   34.449591] xhci-hcd xhci-hcd.1.auto: xHC error in resume, USBSTS 0x401, Reinit
[   34.449599] usb usb1: root hub lost power or was reset
[   34.449603] usb usb2: root hub lost power or was reset
[   34.449905] caam 30900000.crypto: registering rng-caam
[   34.557809] PM: resume devices took 0.324 seconds
[   34.665393] OOM killer enabled.
f[   34.668533] Restarting tasks ... done.
[   34.675562] random: crng reseeded on system resumption
[   34.680886] PM: suspend exit
f-sh: echo: write error: Device o[   34.684001] PM: suspend entry (deep)
r resource busy
f[   34.741395] Filesystems sync: 0.051 seconds
[   34.747450] Freezing user space processes
f[   34.759490] Freezing user space processes completed (elapsed 0.007 seconds)
[   34.766504] OOM killer disabled.
[   34.769874] Freezing remaining freezable tasks
f[   34.820788] Freezing remaining freezable tasks completed (elapsed 0.046 seconds)
[   34.828222] printk: Suspending console(s) (use no_console_suspend to debug)
ffffffffffff[   34.968653] imx-dwmac 30bf0000.ethernet eth1: FPE workqueue stop
[   34.980005] PM: suspend devices took 0.140 seconds
[   34.982978] Disabling non-boot CPUs ...
[   34.984537] psci: CPU1 killed (polled 0 ms)
[   34.986558] psci: CPU2 killed (polled 0 ms)
[   34.987457] psci: CPU3 killed (polled 0 ms)
[   34.987935] Enabling non-boot CPUs ...
f[   34.988363] Detected VIPT I-cache on CPU1
[   34.988392] GICv3: CPU1: found redistributor 1 region 0:0x00000000388a0000
[   34.988422] CPU1: Booted secondary processor 0x0000000001 [0x410fd034]
[   34.988941] CPU1 is up
[   34.989285] Detected VIPT I-cache on CPU2
[   34.989303] GICv3: CPU2: found redistributor 2 region 0:0x00000000388c0000
[   34.989321] CPU2: Booted secondary processor 0x0000000002 [0x410fd034]
[   34.989690] CPU2 is up
[   34.990046] Detected VIPT I-cache on CPU3
[   34.990062] GICv3: CPU3: found redistributor 3 region 0:0x00000000388e0000
f[   34.990080] CPU3: Booted secondary processor 0x0000000003 [0x410fd034]
[   34.990481] CPU3 is up
[   35.168832] imx-dwmac 30bf0000.ethernet eth1: configuring for phy/rgmii-id link mode
[   35.204698] imx-dwmac 30bf0000.ethernet eth1: No Safety Features support found
[   35.204719] imx-dwmac 30bf0000.ethernet eth1: IEEE 1588-2008 Advanced Timestamp supported
[   35.205038] imx-dwmac 30bf0000.ethernet eth1: FPE workqueue start
[   35.205243] xhci-hcd xhci-hcd.1.auto: xHC error in resume, USBSTS 0x401, Reinit
[   35.205252] usb usb1: root hub lost power or was reset
f[   35.205256] usb usb2: root hub lost power or was reset
[   35.205457] caam 30900000.crypto: registering rng-caam
[   35.313965] PM: resume devices took 0.320 seconds
f[   35.461344] OOM killer enabled.
[   35.464538] Restarting tasks ... done.
[   35.471310] random: crng reseeded on system resumption
[   35.476626] PM: suspend exit
[   35.479753] PM: suspend entry (deep)
ff[   35.540757] Filesystems sync: 0.057 seconds
[   35.545848] Freezing user space processes
[   35.551839] Freezing user space processes completed (elapsed 0.001 seconds)
[   35.558856] OOM killer disabled.
[   35.562097] Freezing remaining freezable tasks
f[   35.604758] Freezing remaining freezable tasks completed (elapsed 0.038 seconds)
[   35.612198] printk: Suspending console(s) (use no_console_suspend to debug)
fffffffffff[   35.707187] imx-dwmac 30bf0000.ethernet eth1: FPE workqueue stop
[   35.714344] PM: suspend devices took 0.096 seconds
[   35.716809] Disabling non-boot CPUs ...
[   35.717358] psci: CPU1 killed (polled 0 ms)
[   35.719239] psci: CPU2 killed (polled 0 ms)
[   35.720684] psci: CPU3 killed (polled 4 ms)
[   35.721127] Enabling non-boot CPUs ...
f[   35.721554] Detected VIPT I-cache on CPU1
[   35.721583] GICv3: CPU1: found redistributor 1 region 0:0x00000000388a0000
[   35.721615] CPU1: Booted secondary processor 0x0000000001 [0x410fd034]
[   35.722120] CPU1 is up
[   35.722474] Detected VIPT I-cache on CPU2
[   35.722490] GICv3: CPU2: found redistributor 2 region 0:0x00000000388c0000
f[   35.722506] CPU2: Booted secondary processor 0x0000000002 [0x410fd034]
[   35.722865] CPU2 is up
[   35.723205] Detected VIPT I-cache on CPU3
[   35.723220] GICv3: CPU3: found redistributor 3 region 0:0x00000000388e0000
[   35.723238] CPU3: Booted secondary processor 0x0000000003 [0x410fd034]
[   35.723632] CPU3 is up
[   35.904827] imx-dwmac 30bf0000.ethernet eth1: configuring for phy/rgmii-id link mode
[   35.940669] imx-dwmac 30bf0000.ethernet eth1: No Safety Features support found
[   35.940690] imx-dwmac 30bf0000.ethernet eth1: IEEE 1588-2008 Advanced Timestamp supported
[   35.941160] imx-dwmac 30bf0000.ethernet eth1: FPE workqueue start
[   35.941364] xhci-hcd xhci-hcd.1.auto: xHC error in resume, USBSTS 0x401, Reinit
f[   35.941373] usb usb1: root hub lost power or was reset
[   35.941377] usb usb2: root hub lost power or was reset
[   35.941604] caam 30900000.crypto: registering rng-caam
[   36.049760] PM: resume devices took 0.324 seconds
f[   36.197192] OOM killer enabled.
[   36.200394] Restarting tasks ... done.
[   36.204967] random: crng reseeded on system resumption
[   36.210226] PM: suspend exit
[   36.213328] PM: suspend entry (deep)
ff[   36.283453] Filesystems sync: 0.066 seconds
[   36.288510] Freezing user space processes
[   36.304724] Freezing user space processes completed (elapsed 0.012 seconds)
[   36.311713] OOM killer disabled.
[   36.314952] Freezing remaining freezable tasks
f[   36.340740] Freezing remaining freezable tasks completed (elapsed 0.021 seconds)
[   36.348163] printk: Suspending console(s) (use no_console_suspend to debug)
ffffffffffff[   36.440530] imx-dwmac 30bf0000.ethernet eth1: FPE workqueue stop
[   36.463960] PM: suspend devices took 0.108 seconds
[   36.466432] Disabling non-boot CPUs ...
[   36.467998] psci: CPU1 killed (polled 0 ms)
[   36.469843] psci: CPU2 killed (polled 0 ms)
[   36.470161] Wakeup pending. Abort CPU freeze
[   36.470164] Non-boot CPUs are not disabled
[   36.470166] Enabling non-boot CPUs ...
[   36.470535] Detected VIPT I-cache on CPU1
[   36.470563] GICv3: CPU1: found redistributor 1 region 0:0x00000000388a0000
[   36.470593] CPU1: Booted secondary processor 0x0000000001 [0x410fd034]
[   36.471039] CPU1 is up
[   36.471401] Detected VIPT I-cache on CPU2
[   36.471421] GICv3: CPU2: found redistributor 2 region 0:0x00000000388c0000
[   36.471438] CPU2: Booted secondary processor 0x0000000002 [0x410fd034]
f[   36.471823] CPU2 is up
[   36.652896] imx-dwmac 30bf0000.ethernet eth1: configuring for phy/rgmii-id link mode
[   36.685193] imx-dwmac 30bf0000.ethernet eth1: No Safety Features support found
[   36.685213] imx-dwmac 30bf0000.ethernet eth1: IEEE 1588-2008 Advanced Timestamp supported
[   36.685396] imx-dwmac 30bf0000.ethernet eth1: FPE workqueue start
[   36.685735] xhci-hcd xhci-hcd.1.auto: xHC error in resume, USBSTS 0x401, Reinit
[   36.685744] usb usb1: root hub lost power or was reset
[   36.685748] usb usb2: root hub lost power or was reset
f[   36.686248] caam 30900000.crypto: registering rng-caam
[   36.793724] PM: resume devices took 0.320 seconds
[   36.925378] OOM killer enabled.
f[   36.928517] Restarting tasks ... done.
[   36.933894] random: crng reseeded on system resumption
[   36.939202] PM: suspend exit
-sh: echo: write error: Device or[   36.942345] PM: suspend entry (deep)
 resource busy
ff[   37.011463] Filesystems sync: 0.062 seconds
[   37.016608] Freezing user space processes
[   37.022472] Freezing user space processes completed (elapsed 0.001 seconds)
[   37.029534] OOM killer disabled.
f[   37.032806] Freezing remaining freezable tasks
f[   37.084740] Freezing remaining freezable tasks completed (elapsed 0.047 seconds)
[   37.092164] printk: Suspending console(s) (use no_console_suspend to debug)
ff

This does not reproduce every time, in the above snippet you can see "suspend exit" 4 times so wake up worked 4 times but the 5th time it got stuck.

"test code" is really all there is to this quote: enable wake up from tty with `echo enabled > /sys/class/tty/ttymxc1/power/wakeup` then repeat entering sleep in a loop with `while true; do echo mem > /sys/power/state; done`, at which point holding a key down over serial should wake it up in a loop but the system gets stuck in sleep state shortly. (I also enabled more messages to console with `dmesg -n 7` to get feedback, but that is not required)

Using another wake up method (e.g. rtc or gpio input) does get out of sleep in this case, so it must be an issue in the ttymxc driver.

I'm not sure why you would not be able to reproduce with this procedure, perhaps some hardware difference on the exact revision I'm using? This is on an evk we got a long time ago, but I've flashed exactly the image off the NXP site, and can also reproduce on our board with the same tty pins.

Thanks

[martinetd]

Thanks for the quick reply!

We're using the same pins as the imx8mp-evk, MX8MP_IOMUXC_UART2_RXD__UART2_DCE_RX / MX8MP_IOMUXC_UART2_TXD__UART2_DCE_TX

Thanks,
Dominique