RPi3 B 1.2: 'flip_done timed out' when turning monitor off and on again

[z0rti]

I got this error with my RPi3 using 'dtoverlay=vc4-kms-v3d' (on bullseye)
I'm using 'hdmi_mode=4' in config.txt
It boots up fine (HDMI monitor is on)
but when i turn the monitor off and on again i don't get a picture anymore, until i do a hard reset (pull power off)

Mar 26 20:08:28 pi3 kernel: [ 2500.612845] ------------[ cut here ]------------
Mar 26 20:08:28 pi3 kernel: [ 2500.612857] Timeout waiting for VC4_HDMI_SCHEDULER_CONTROL_HDMI_ACTIVE
Mar 26 20:08:28 pi3 kernel: [ 2500.612978] WARNING: CPU: 2 PID: 6289 at drivers/gpu/drm/vc4/vc4_hdmi.c:1336 vc4_hdmi_encoder_post_crtc_enable+0x1064/0x11a8 [vc
4]
Mar 26 20:08:28 pi3 kernel: [ 2500.612983] Modules linked in: ccm rfcomm algif_hash algif_skcipher af_alg bnep hci_uart btbcm bluetooth ecdh_generic ecc 8021q
garp stp llc snd_soc_hdmi_codec rt2800usb rt2800lib rt2x00usb rt2x00lib joydev brcmfmac mac80211 brcmutil crc_ccitt vc4 libarc4 cec cfg80211 drm_kms_helper rfk
ill snd_soc_core snd_compress snd_pcm_dmaengine syscopyarea sysfillrect sysimgblt fb_sys_fops raspberrypi_hwmon i2c_bcm2835 bcm2835_codec(C) bcm2835_v4l2(C) bc
m2835_isp(C) bcm2835_mmal_vchiq(C) v4l2_mem2mem videobuf2_vmalloc videobuf2_dma_contig videobuf2_memops videobuf2_v4l2 snd_bcm2835(C) videobuf2_common snd_pcm
snd_timer snd vc_sm_cma(C) videodev mc uio_pdrv_genirq uio i2c_dev aes_neon_bs aes_neon_blk crypto_simd cryptd drm drm_panel_orientation_quirks backlight fuse
ip_tables x_tables ipv6
Mar 26 20:08:28 pi3 kernel: [ 2500.613222] CPU: 2 PID: 6289 Comm: kworker/2:2 Tainted: G         C        5.10.92-v8+ raspberrypi/firmware#1514
Mar 26 20:08:28 pi3 kernel: [ 2500.613226] Hardware name: Raspberry Pi 3 Model B Rev 1.2 (DT)
Mar 26 20:08:28 pi3 kernel: [ 2500.613294] Workqueue: events output_poll_execute [drm_kms_helper]
Mar 26 20:08:28 pi3 kernel: [ 2500.613304] pstate: 80000005 (Nzcv daif -PAN -UAO -TCO BTYPE=--)
Mar 26 20:08:28 pi3 kernel: [ 2500.613331] pc : vc4_hdmi_encoder_post_crtc_enable+0x1064/0x11a8 [vc4]
Mar 26 20:08:28 pi3 kernel: [ 2500.613357] lr : vc4_hdmi_encoder_post_crtc_enable+0x1064/0x11a8 [vc4]
Mar 26 20:08:28 pi3 kernel: [ 2500.613361] sp : ffffffc0132538a0
Mar 26 20:08:28 pi3 kernel: [ 2500.613365] x29: ffffffc0132538a0 x28: 0000000000000001
Mar 26 20:08:28 pi3 kernel: [ 2500.613375] x27: ffffffc0090e43e8 x26: 0000000000000500
Mar 26 20:08:28 pi3 kernel: [ 2500.613385] x25: ffffff80076d3c50 x24: ffffff80076d3c30
Mar 26 20:08:28 pi3 kernel: [ 2500.613395] x23: ffffffc010e1d178 x22: ffffff80076d3c28
Mar 26 20:08:28 pi3 kernel: [ 2500.613405] x21: 0000024637dffa7e x20: ffffff80076d34b8
Mar 26 20:08:28 pi3 kernel: [ 2500.613415] x19: ffffff80076d3080 x18: 0000000000000000
Mar 26 20:08:28 pi3 kernel: [ 2500.613425] x17: 0000000000000000 x16: 0000000000000000
Mar 26 20:08:28 pi3 kernel: [ 2500.613434] x15: 0000007f8adf46a8 x14: 0000000000000000
Mar 26 20:08:28 pi3 kernel: [ 2500.613444] x13: 0000000000000000 x12: ffffffc0113154f8
Mar 26 20:08:28 pi3 kernel: [ 2500.613453] x11: 0000000000000003 x10: ffffffc0112fd4b8
Mar 26 20:08:28 pi3 kernel: [ 2500.613463] x9 : ffffffc0100e6558 x8 : 0000000000017fe8
Mar 26 20:08:28 pi3 kernel: [ 2500.613473] x7 : c0000000ffffefff x6 : ffffffc013253500
Mar 26 20:08:28 pi3 kernel: [ 2500.613483] x5 : 0000000000000001 x4 : 0000000000000000
Mar 26 20:08:28 pi3 kernel: [ 2500.613492] x3 : 0000000000000001 x2 : 0000000000000000
Mar 26 20:08:28 pi3 kernel: [ 2500.613502] x1 : bcd5c0829e029300 x0 : 0000000000000000
Mar 26 20:08:28 pi3 kernel: [ 2500.613511] Call trace:
Mar 26 20:08:28 pi3 kernel: [ 2500.613539]  vc4_hdmi_encoder_post_crtc_enable+0x1064/0x11a8 [vc4]
Mar 26 20:08:28 pi3 kernel: [ 2500.613565]  vc4_crtc_atomic_enable+0x3d0/0x4a8 [vc4]
Mar 26 20:08:28 pi3 kernel: [ 2500.613609]  drm_atomic_helper_commit_modeset_enables+0x210/0x258 [drm_kms_helper]
Mar 26 20:08:28 pi3 kernel: [ 2500.613635]  vc4_atomic_complete_commit+0x1dc/0x6a8 [vc4]
Mar 26 20:08:28 pi3 kernel: [ 2500.613660]  vc4_atomic_commit+0x1b0/0x200 [vc4]
Mar 26 20:08:28 pi3 kernel: [ 2500.613785]  drm_atomic_commit+0x54/0x68 [drm]
Mar 26 20:08:28 pi3 kernel: [ 2500.613877]  drm_client_modeset_commit_atomic.isra.16+0x1ec/0x290 [drm]
Mar 26 20:08:28 pi3 kernel: [ 2500.613963]  drm_client_modeset_commit_locked+0x68/0x1a8 [drm]
Mar 26 20:08:28 pi3 kernel: [ 2500.614050]  drm_client_modeset_commit+0x38/0x60 [drm]
Mar 26 20:08:28 pi3 kernel: [ 2500.614094]  __drm_fb_helper_restore_fbdev_mode_unlocked+0xd4/0x118 [drm_kms_helper]
Mar 26 20:08:28 pi3 kernel: [ 2500.614139]  drm_fb_helper_set_par+0x44/0x80 [drm_kms_helper]
Mar 26 20:08:28 pi3 kernel: [ 2500.614184]  drm_fb_helper_hotplug_event.part.24+0xb4/0xe8 [drm_kms_helper]
Mar 26 20:08:28 pi3 kernel: [ 2500.614228]  drm_fbdev_client_hotplug+0x44/0x1b8 [drm_kms_helper]
Mar 26 20:08:28 pi3 kernel: [ 2500.614314]  drm_client_dev_hotplug+0x80/0xc8 [drm]
Mar 26 20:08:28 pi3 kernel: [ 2500.614357]  drm_kms_helper_hotplug_event+0x3c/0x50 [drm_kms_helper]
Mar 26 20:08:28 pi3 kernel: [ 2500.614401]  output_poll_execute+0x1e0/0x230 [drm_kms_helper]
Mar 26 20:08:28 pi3 kernel: [ 2500.614413]  process_one_work+0x1f4/0x4d8
Mar 26 20:08:28 pi3 kernel: [ 2500.614419]  worker_thread+0x50/0x480
Mar 26 20:08:28 pi3 kernel: [ 2500.614427]  kthread+0x148/0x158
Mar 26 20:08:28 pi3 kernel: [ 2500.614435]  ret_from_fork+0x10/0x30
Mar 26 20:08:28 pi3 kernel: [ 2500.614440] ---[ end trace cca87e7ca102e151 ]---
Mar 26 20:08:28 pi3 kernel: [ 2500.614515] ------------[ cut here ]------------
[...]
Mar 26 20:08:39 pi3 kernel: [ 2510.824308] [drm:drm_atomic_helper_wait_for_flip_done [drm_kms_helper]] *ERROR* [CRTC:76:crtc-3] flip_done timed out

$ lsb_release -d
Description:    Debian GNU/Linux 11 (bullseye)
$ uname -a
Linux pi3 5.10.92-v8+ raspberrypi/firmware#1514 SMP PREEMPT Mon Jan 17 17:39:38 GMT 2022 aarch64 GNU/Linux

So i'm currently using 'dtoverlay=vc4-fkms-v3d' where this doesn't happen.

[popcornmix]

Can you try running rpi-update to switch to the 5.15 kernel branch? Is the issue still there?
This is intended to become the stable kernel in apt in the very near future.

[simnalamburt]

@popcornmix I could reproduce this issue with 5.15.30-v8+.

[popcornmix]

That's good. That should be default kernel pretty soon.

[pelwell]

It doesn't sound good if @simnalamburt can reproduce the issue with 5.15.30.

[popcornmix]

Sorry - I misread his post. I'll see if I can reproduce.

[popcornmix]

I didn't see this on my monitor when switching into/out of standby.
I didn't see when switching AV indput on monitor.
I didn't see when unplugging/replugging hdmi cable.
I did see it when unplugging monitor from mains / plugging back in (specifically on plugging back in).

(note: what happens to hotplug signal and ability to read edid in each of these cases tends to be monitor specific).

[popcornmix]

Transferred to linux kernel issues and added KMS label.

[popcornmix]

I have a look, but not seen anything obvious. Increasing the timeout to 10s doesn't help.
HDMI_SCHEDULER_CONTROL=0xcb029 so we've requested hdmi mode but it's not reported as being active.

aside: we are setting VC4_HDMI_SCHEDULER_CONTROL_VERT_ALWAYS_KEEPOUT when I don't think we should - that is only needed with HDCP which we will never support. But I don't believe that is related.

I have seen the failure when replugging hdmi cable, but it's not happening every time.
I haven't seen it on my monitor when switching to standby (as monitor doesn't deassert hotplug).

@mripard @timg236 any thoughts?
I'm guessing we are in the wrong state to do this (e.g. missing clock, or shutdown or reset of something), but I don't know much about the hdmi block.

10 hdmi unplug/replug cycles on Pi4 hasn't triggered it.

[popcornmix]

@z0rti adding video=HDMI-A-1:D to end of /boot/cmdline.txt might provide a workaround for this issue (while we continue to look into it).

[popcornmix]

@mripard before the failure (from /sys/kernel/debug/clk/clk_summary):
fw-clk-pixel 1 1 0 148500000 0 0 50000 Y

$ vcgencmd measure_clock pixel
frequency(29)=148500000

and after:
fw-clk-pixel 0 0 0 148500000 0 0 50000 Y

$ vcgencmd measure_clock pixel
frequency(29)=0

So I guess fw-clk-pixel is not running in the failure mode, and you can't switch hdmi mode (through HDMI_SCHEDULER_CONTROL) without the pixel clock running.

[mripard]

I had a look this morning, but couldn't reproduce it here

I didn't see this on my monitor when switching into/out of standby.
I didn't see when switching AV indput on monitor.
I didn't see when unplugging/replugging hdmi cable.
I did see it when unplugging monitor from mains / plugging back in (specifically on plugging back in).

I'm not sure I understand the difference between the last two. Did you unplug the HDMI cable on the first, and the power plug on the last?

I'll look at the code to see if there's anything obvious

[mripard]

The only case where this could happen is if one of the functions in vc4_hdmi_encoder_pre_crtc_configure that can error (clk_set_rate, clk_set_min_rate, clk_prepare_enable or pm_runtime_resume_and_get) does return an error. Can you print the rest of the logs before that warning? All these functions should have an error message logged if they fail.

[mripard]

Another thing I just remembered, we don't use the hotplug interrupts on the 3B and the polling interval is 10s so plugging/unplugging the monitor fairly fast might be ignored and lead to inconsistent behaviours.

[popcornmix]

There are no logged error messages before the WARN. e.g. http://sprunge.us/HmP3nh

I just tried unplugging. Waiting a few minutes. Replugging and it failed in the same way: http://sprunge.us/TOxFuc

[popcornmix]

With all drm debug enabled: http://sprunge.us/TpeHh4

[mripard]

I'm a bit puzzled by this bug. I did more testing today and neither my 3B or 3B+ shows it on any of the three monitors I tested it with.

Which kind of display did you test it with?

[popcornmix]

@mripard did you try unplugging hdmi cable? (and replugging ten seconds later).
That reliably caused it. Not every time, but more often than not.
My monitor didn't provoke it on standby (as it doesn't deassert hotplug then).

[mripard]

I've done that for about 45 minutes now on a 3B, with and without X running, and making sure the kernel would detect the monitor status properly. I'm still not seeing the issue.

Could you share your config.txt file and the mode it's happening in?

Is it with X running?

[popcornmix]

Just tried at work (so different pi/sdcard and monitor), Failed on second replug.
I'm booting to console (no X).
config.txt
cmdline.txt

pi@b3plus:~ $ uname -a
Linux b3plus 5.15.32-v7+ #1539 SMP Fri Apr 1 11:38:09 BST 2022 armv7l GNU/Linux
pi@b3plus:~ $ vcgencmd version
Mar 24 2022 13:20:54 
Copyright (c) 2012 Broadcom
version e5a963efa66a1974127860b42e913d2374139ff5 (clean) (release) (start)
pi@b3plus:~ $ kmsprint 
Connector 0 (32) HDMI-A-1 (connected)
  Encoder 0 (31) TMDS
    Crtc 3 (89) [email protected] 154.000 1920/48/32/80/+ 1200/3/6/26/+ 60 (59.95) 0x5 0x48
      Plane 3 (79) fb-id: 291 (crtcs: 3) 0,0 1920x1200 -> 0,0 1920x1200 (XR24 AR24 AB24 XB24 RG16 BG16 AR15 XR15 RG24 BG24 YU16 YV16 YU12 YV12 NV12 NV21 NV16 NV61)
        FB 291 1920x1200
pi@b3plus:~ $ base64 /sys/devices/platform/soc/soc:gpu/drm/card0/card0-HDMI-A-1/edid
AP///////wAQrLygU002MR0bAQOANCB46gSVqVVNnSYQUFSlSwBxT4GAqUDRwNEAAQEBAQEBKDyA
oHCwI0AwIDYABkQhAAAeAAAA/wA3TVQwMTc3TDE2TVMKAAAA/ABERUxMIFUyNDE1CiAgAAAA/QAx
PR5TEQAKICAgICAgAZ8CAyLxT5AFBAMCBxYBFB8SEyAhIiMJBwdlAwwAIACDAQAAAjqAGHE4LUBY
LEUABkQhAAAeAR2AGHEcFiBYLCUABkQhAACeAR0AclHQHiBuKFUABkQhAAAejArQiiDgLRAQPpYA
BkQhAAAYAAAAAAAAAAAAAAAAAAAAAAAAAAAAcg==

I'm on a 3B+.

[gorky]

I am seeing this with 5.15.32-v8+ using a KVM switch.

[popcornmix]

I've tested an upstream kernel (5.18-rc6) and couldn't reproduce this. The comparable downstream kernel did have this issue, so I may be able to bisect it.

[gorky]

Also with:
Linux rothman 5.15.32-v7+ #1538 SMP Thu Mar 31 19:38:48 BST 2022 armv7l GNU/Linux
using same model KVM Switches.

[EdiDD]

I have got the same issue when TV is switched to another source or disabled for a longer time (day or so).
Raspberry Pi OS Lite 64 bit with kernel: 5.15.32-v8+
Did you find any temporary workaround for this bugs ?

[popcornmix]

Did you find any temporary workaround for this bugs ?

Can you try adding video=HDMI-A-1:D to end of /boot/cmdline.txt (on same line).
I think that will avoid the issue.

[EdiDD]

Can you try adding video=HDMI-A-1:D to end of /boot/cmdline.txt (on same line).

Sounds like it will completely disable HDMI port ? . If yes it is not a solution for me.

[pelwell]

Do you think @popcornmix would have suggested it if that's what it does?

From https://wiki.archlinux.org/title/kernel_mode_setting:

video=:x[M][R][-][@][i][m][eDd]
...
d: output forced to off
D: digital output forced to on (e.g. DVI-I connector)

[EdiDD]

Ah... forgive me. You are right, I forgot that capital letter has different action. It looks like overscan from /boot/config.txt stop working after adding video parameter but that's ok as temporary solution.

[tonymartino]

New install. RPI can't turn screen back on after it puts it to sleep.

pi@officedisplay:~ $ uname -a
Linux officedisplay 5.15.32-v7+ #1538 SMP Thu Mar 31 19:38:48 BST 2022 armv7l GNU/Linux
pi@officedisplay:~ $ 

Relevant logs:

Jul 22 15:27:37 officedisplay kernel: [drm:drm_crtc_commit_wait [drm]] *ERROR* flip_done timed out
Jul 22 15:27:37 officedisplay kernel: [drm:drm_atomic_helper_wait_for_dependencies [drm_kms_helper]] *ERROR* [CRTC:89:crtc-3] commit wait timed out
Jul 22 15:27:47 officedisplay kernel: [drm:drm_crtc_commit_wait [drm]] *ERROR* flip_done timed out
Jul 22 15:27:47 officedisplay kernel: [drm:drm_atomic_helper_wait_for_dependencies [drm_kms_helper]] *ERROR* [CONNECTOR:32:HDMI-A-1] commit wait timed out
Jul 22 15:27:58 officedisplay kernel: [drm:drm_crtc_commit_wait [drm]] *ERROR* flip_done timed out
Jul 22 15:27:58 officedisplay kernel: vc4-drm soc:gpu: [drm] *ERROR* Timed out waiting for commit
Jul 22 15:28:08 officedisplay kernel: [drm:drm_atomic_helper_wait_for_flip_done [drm_kms_helper]] *ERROR* [CRTC:89:crtc-3] flip_done timed out

I see this has been open since March. Any updates? What other information can I provide that might be helpful?

[popcornmix]

I can reproduce (although @mripard cannot).

I've narrowed it down to the disable/enable of the HDMI domain (removing the mailbox call avoids the issue).
The critical part of that is the writes to PM_HDMI register (again, commenting those out avoids the issue).

I suspect the reset of PM_HDMI requires some HDMI registers to be re-set up, although visibly the registers exposed through debug sysfs are unchanged after the operation.

In the fkms world, the same power down/up code is run and doesn't have the issue (but the code for shutting down and restarting the various display related parts of chip is quite different there).

Until the issue is fully resolved I believe this is a workaround.

[tonymartino]

Thanks or the tip but that didn't work. I'm seeing the same errors.

[weslord]

I think I've run into this issue too. If left alone long enough, Pi would deactivate the display, but would not reactivate on keypresses or mouse movement.

Running a fairly fresh copy of Raspberry Pi OS 64-bit (Bullseye) on a Raspberry Pi 3 Model B Rev 1.2. I think the only modifications to the default config have been re-enabling Glamor so I can work with cameras.

$ uname -a
Linux raspberrypi 5.15.32-v8+ #1538 SMP PREEMPT Thu Mar 31 19:40:39 BST 2022 aarch64 GNU/Linux

After a bunch of experimenting, the smallest number of steps to quickly and reliably reproduce (aside from waiting for the screensaver to timeout) is this:

1. $ xset dpms force off
2. Physically turn off the screen for a few seconds.
3. Physically turn the screen back on.
4. $ xset dpms force on (or jostle the mouse)

The display does not reactivate. xset dpms force on takes a while to finish executing. Weirdly enough, there's also no error message in /var/log/messages when I do it this way. Sometimes an error is logged when I triggered it another way (replace force off with force standby?), but my messages file doesn't include the words flip_done timed out anywhere.

When the error does show, here's a typical example (Timeout waiting for VC4_HDMI_SCHEDULER_CONTROL_HDMI_ACTIVE is included only about half the time, otherwise identical):

Jul 27 10:55:49 raspberrypi kernel: [  456.198863] ------------[ cut here ]------------
Jul 27 10:55:49 raspberrypi kernel: [  456.198897] Timeout waiting for VC4_HDMI_SCHEDULER_CONTROL_HDMI_ACTIVE
Jul 27 10:55:49 raspberrypi kernel: [  456.199012] WARNING: CPU: 0 PID: 574 at drivers/gpu/drm/vc4/vc4_hdmi.c:1531 vc4_hdmi_encoder_post_crtc_enable+0x105c/0x11c8 [vc4]
Jul 27 10:55:49 raspberrypi kernel: [  456.199147] Modules linked in: rfcomm cmac algif_hash aes_arm64 algif_skcipher af_alg bnep hci_uart btbcm bluetooth ecdh_generic ecc 8021q garp ov5647 stp llc snd_soc_hdmi_codec brcmfmac brcmutil vc4 cec cfg80211 rfkill drm_kms_helper snd_soc_core i2c_mux_pinctrl i2c_mux snd_compress raspberrypi_hwmon snd_pcm_dmaengine syscopyarea sysfillrect sysimgblt fb_sys_fops bcm2835_unicam v4l2_dv_timings v4l2_fwnode v4l2_async snd_bcm2835(C) bcm2835_isp(C) bcm2835_v4l2(C) bcm2835_codec(C) snd_pcm videobuf2_vmalloc bcm2835_mmal_vchiq(C) v4l2_mem2mem videobuf2_dma_contig i2c_bcm2835 videobuf2_memops videobuf2_v4l2 videobuf2_common snd_timer snd vc_sm_cma(C) videodev mc uio_pdrv_genirq uio i2c_dev drm drm_panel_orientation_quirks backlight fuse ip_tables x_tables ipv6
Jul 27 10:55:49 raspberrypi kernel: [  456.199591] CPU: 0 PID: 574 Comm: Xorg Tainted: G         C        5.15.32-v8+ #1538
Jul 27 10:55:49 raspberrypi kernel: [  456.199609] Hardware name: Raspberry Pi 3 Model B Rev 1.2 (DT)
Jul 27 10:55:49 raspberrypi kernel: [  456.199619] pstate: 80000005 (Nzcv daif -PAN -UAO -TCO -DIT -SSBS BTYPE=--)
Jul 27 10:55:49 raspberrypi kernel: [  456.199636] pc : vc4_hdmi_encoder_post_crtc_enable+0x105c/0x11c8 [vc4]
Jul 27 10:55:49 raspberrypi kernel: [  456.199734] lr : vc4_hdmi_encoder_post_crtc_enable+0x105c/0x11c8 [vc4]
Jul 27 10:55:49 raspberrypi kernel: [  456.199831] sp : ffffffc00a35b8b0
Jul 27 10:55:49 raspberrypi kernel: [  456.199839] x29: ffffffc00a35b8b0 x28: 0000000000000001 x27: ffffffc001141f50
Jul 27 10:55:49 raspberrypi kernel: [  456.199868] x26: 0000000000000500 x25: ffffff800629cbc0 x24: ffffff800629cba0
Jul 27 10:55:49 raspberrypi kernel: [  456.199896] x23: ffffffc008e8a9c8 x22: ffffff800629cb98 x21: 0000006a3754ce27
Jul 27 10:55:49 raspberrypi kernel: [  456.199924] x20: ffffff800629c4d8 x19: ffffff800629c080 x18: 0000000000000000
Jul 27 10:55:49 raspberrypi kernel: [  456.199952] x17: 0000000000000000 x16: 0000000000000000 x15: 00000055769fece0
Jul 27 10:55:49 raspberrypi kernel: [  456.199979] x14: 0000000000000000 x13: 4556495443415f49 x12: ffffffc0093a6670
Jul 27 10:55:49 raspberrypi kernel: [  456.200006] x11: 0000000000000003 x10: ffffffc00938e630 x9 : ffffffc0080ec768
Jul 27 10:55:49 raspberrypi kernel: [  456.200034] x8 : 0000000000017fe8 x7 : c0000000ffffefff x6 : 0000000000000001
Jul 27 10:55:49 raspberrypi kernel: [  456.200060] x5 : ffffffc032139000 x4 : 0000000000000000 x3 : 0000000000000001
Jul 27 10:55:49 raspberrypi kernel: [  456.200086] x2 : 0000000000000000 x1 : eed24f03d394c000 x0 : 0000000000000000
Jul 27 10:55:49 raspberrypi kernel: [  456.200113] Call trace:
Jul 27 10:55:49 raspberrypi kernel: [  456.200122]  vc4_hdmi_encoder_post_crtc_enable+0x105c/0x11c8 [vc4]
Jul 27 10:55:49 raspberrypi kernel: [  456.200220]  vc4_crtc_atomic_enable+0x3d8/0x4b0 [vc4]
Jul 27 10:55:49 raspberrypi kernel: [  456.200315]  drm_atomic_helper_commit_modeset_enables+0x210/0x258 [drm_kms_helper]
Jul 27 10:55:49 raspberrypi kernel: [  456.200535]  vc4_atomic_commit_tail+0x3c4/0x730 [vc4]
Jul 27 10:55:49 raspberrypi kernel: [  456.200631]  commit_tail+0xac/0x1a8 [drm_kms_helper]
Jul 27 10:55:49 raspberrypi kernel: [  456.200822]  drm_atomic_helper_commit+0x168/0x378 [drm_kms_helper]
Jul 27 10:55:49 raspberrypi kernel: [  456.201015]  drm_atomic_commit+0x54/0x68 [drm]
Jul 27 10:55:49 raspberrypi kernel: [  456.201408]  drm_atomic_connector_commit_dpms+0xf4/0x120 [drm]
Jul 27 10:55:49 raspberrypi kernel: [  456.201751]  drm_mode_obj_set_property_ioctl+0x1d8/0x460 [drm]
Jul 27 10:55:49 raspberrypi kernel: [  456.202093]  drm_connector_property_set_ioctl+0x48/0x70 [drm]
Jul 27 10:55:49 raspberrypi kernel: [  456.202434]  drm_ioctl_kernel+0xc8/0x118 [drm]
Jul 27 10:55:49 raspberrypi kernel: [  456.202778]  drm_ioctl+0x21c/0x450 [drm]
Jul 27 10:55:49 raspberrypi kernel: [  456.203118]  __arm64_sys_ioctl+0xb0/0xf0
Jul 27 10:55:49 raspberrypi kernel: [  456.203139]  invoke_syscall+0x4c/0x110
Jul 27 10:55:49 raspberrypi kernel: [  456.203158]  el0_svc_common.constprop.3+0xfc/0x120
Jul 27 10:55:49 raspberrypi kernel: [  456.203177]  do_el0_svc+0x2c/0x90
Jul 27 10:55:49 raspberrypi kernel: [  456.203194]  el0_svc+0x24/0x60
Jul 27 10:55:49 raspberrypi kernel: [  456.203212]  el0t_64_sync_handler+0x90/0xb8
Jul 27 10:55:49 raspberrypi kernel: [  456.203229]  el0t_64_sync+0x1a0/0x1a4
Jul 27 10:55:49 raspberrypi kernel: [  456.203245] ---[ end trace 284a8f64bc320b60 ]---

The good news is that adding video=HDMI-A-1:D to /boot/cmdline.txt does seem to resolve this for me.

Hope this is helpful.

[21a1ss3]

Hi to everyone.

Setup info:
RPi3 B+, HDMI connected to a DVI monitor through adapter.

# uname -a
Linux raspberrypi 5.15.32-v7+ #1538 SMP Thu Mar 31 19:38:48 BST 2022 armv7l GNU/Linux

# vcgencmd version
Mar 24 2022 13:20:54
Copyright (c) 2012 Broadcom
version e5a963efa66a1974127860b42e913d2374139ff5 (clean) (release) (start)

# kmsprint
Connector 0 (32) HDMI-A-1 (connected)
  Encoder 0 (31) TMDS
    Crtc 3 (89) [email protected] 148.500 1920/88/44/148/+ 1080/4/5/36/+ 60 (60.00) 0x5 0x0
      Plane 3 (79) fb-id: 294 (crtcs: 3) 0,0 1920x1080 -> 0,0 1920x1080 (XR24 AR24 AB24 XB24 RG16 BG16 AR15 XR15 RG24 BG24 YU16 YV16 YU12 YV12 NV12 NV21 NV16 NV61)
        FB 294 1920x1080
      Plane 23 (280) fb-id: 296 (crtcs: 3) 0,0 64x64 -> 68,4294967291 64x64 (XR24 AR24 AB24 XB24 RG16 BG16 AR15 XR15 RG24 BG24 YU16 YV16 YU12 YV12 NV12 NV21 NV16 NV61)
        FB 296 64x6

Description:
I have same issue on RPi3 B+, but whith screensaver (as it turns out). Proposed workaround with disable_fw_kms_setup=1 and video=HDMI-A-1:D won't help. The symptoms are same as earlier discussed - over some time clock rate went to 0 and then happend same log messages as where present above.

# vcgencmd measure_clock pixel
frequency(29)=0

Aug  4 15:59:37 raspberrypi kernel: [ 5450.747783] [drm:drm_atomic_helper_wait_for_flip_done [drm_kms_helper]] *ERROR* [CRTC:89:crtc-3] flip_done timed out
Aug  4 15:59:47 raspberrypi kernel: [ 5460.987841] [drm:drm_crtc_commit_wait [drm]] *ERROR* flip_done timed out
Aug  4 15:59:47 raspberrypi kernel: [ 5460.988483] [drm:drm_atomic_helper_wait_for_dependencies [drm_kms_helper]] *ERROR* [CRTC:89:crtc-3] commit wait timed out
Aug  4 15:59:57 raspberrypi kernel: [ 5471.227917] [drm:drm_crtc_commit_wait [drm]] *ERROR* flip_done timed out
Aug  4 15:59:57 raspberrypi kernel: [ 5471.228559] [drm:drm_atomic_helper_wait_for_dependencies [drm_kms_helper]] *ERROR* [CONNECTOR:32:HDMI-A-1] commit wait timed out

Also I did noticed that flip_done timed out messages are actully turns out much later then clock rate went to 0. In my case main trigger for those events were a mouse movement or keyboard actions, before that there is no messages. Also I did repeat experiments on true HDMI monitor which always was on on the time of experiments and the screensavings there working well, clock rate not going down to 0 when monitor in wait mode (monitor on, screen off, led indicator is yellow).

My workaround resolution:
I ended up with solution when I do have disable_fw_kms_setup=1 and video=HDMI-A-1:D options in a config plus I did changed display-setup-script in lightdm and put there those few lines:

xset s 0 0
xset s off
xset -dpms
xset s noblank

The crucial for me was xset s 0 0 since it totally disabled screen saving and screen now not going blank or being turned off, but that is still be workaround.

In result clock never goes down, even if monitor is not turned on (RPi even rebooted with turned off monitor due to power outage).

Hope this will be helpful as a temporary solution

[popcornmix]

rpi-update has a potential firmware fix for this. Please update and report if it's fixed.

[tonymartino]

So far, so good... The screen woke up after sleep. I'll try it a few more times.

Edit: Two successful wake ups now. I'm happy.

Thank you!

[21a1ss3]

I'll be able to check on next week

[mripard]

@popcornmix what was causing the issue?

[popcornmix]

The request kernel request RPI_FIRMWARE_SET_DOMAIN_STATE to disable RPI_POWER_DOMAIN_HDMI has the side effect of stopping the VEC and PIXEL (only used on pi0-3) clocks.
Re-enabling the domain leaves those clocks still disabled.

It wasn't clear what the best solution for this is. We have chosen to restore those clocks to the frequency they were when HDMI domain was disabled, when we get the enable call (that could cause a surprise if clocks are changed whilst disabled).

An alternative would be for the kernel to restore these clocks itself when enabling the domain which may be safer, but the mix of VEC and HDMI may be ugly.

It appears from a comment in the firmware code that PLLH is in the HDMI power domain, and PLLH provides both the VEC and pixel clock (one or the other), so they should be stopped as part of powering down.

[mripard]

The request kernel request RPI_FIRMWARE_SET_DOMAIN_STATE to disable RPI_POWER_DOMAIN_HDMI has the side effect of stopping the VEC and PIXEL (only used on pi0-3) clocks.

But there's is a dedicated VEC power domain, right?

Re-enabling the domain leaves those clocks still disabled.

It wasn't clear what the best solution for this is. We have chosen to restore those clocks to the frequency they were when HDMI domain was disabled, when we get the enable call (that could cause a surprise if clocks are changed whilst disabled).

The rate itself isn't really important, we can choose to set it to whatever we'd like in Linux (and we should pretty close to doing that already?). But yeah, Linux clock API comes with the expectation that it won't be shutdown while it's enabled (in the clock framework).

An alternative would be for the kernel to restore these clocks itself when enabling the domain which may be safer, but the mix of VEC and HDMI may be ugly.

It appears from a comment in the firmware code that PLLH is in the HDMI power domain, and PLLH provides both the VEC and pixel clock (one or the other), so they should be stopped as part of powering down.

So we effectively have a dependency of the VEC power domain on the HDMI one?

[21a1ss3]

I can confirm that issue has been fixed for me as well. Now if X goes to screensaver and turns off monitor clocks went down to 0 and afterwards, on wake up, successully restores backward to previous value.

[popcornmix]

@mripard

But there's is a dedicated VEC power domain, right?

No, I don't believe so (in a hardware sense). Software treats HDMI and VEC domains identically:

   case SYSMAN_BLOCK_HDMI:         return POWER_DOMAIN_IMAGE | POWER_DOMAIN_IMAGE_PERI | POWER_DOMAIN_HDMI_LDO;
   case SYSMAN_BLOCK_VEC:          return POWER_DOMAIN_IMAGE | POWER_DOMAIN_IMAGE_PERI | POWER_DOMAIN_HDMI_LDO; // pllh is inside hdmi phy

SYSMAN_BLOCK_HDMI / SYSMAN_BLOCK_VEC is what kernel passes in through RPI_FIRMWARE_SET_DOMAIN_STATE. But they both behave the same.
It is reference counted so you can request HDMI and VEC then release VEC and HDMI and the power domains will only be disabled when both releases are in. But it would behave no differently from you using HDMI in both cases.

[popcornmix]

So we effectively have a dependency of the VEC power domain on the HDMI one?

More specifically they are really the same domain as they share the same hardware resource (PLLH).

[mripard]

So, if it is reference counted, I'm not sure what the original issue that got addressed by the new firmware was? Was the power domain itself reference counted, but not the clock side?

[popcornmix]

Yes, clock are set to zero when all users of POWER_DOMAIN_HDMI_LDO are gone (and that occurs on hotplug deassert). They were not being set back by firmware or kernel when POWER_DOMAIN_HDMI_LDO was enabled again.
The lack of clocks (and PLLH) caused register accessed to HDMI to fail after hotplug assert.

Someone needs to start clocks again. With the recent firmware update that is done by firmware (restoring VEC and PIXEL clocks to values they had when domain went down).

[mripard]

Ok, thanks for the explanation :)

[popcornmix]

Closing as believed to be fixed.

[aaronriekenberg]

Just for understanding: is there a way to know from firmware version and/or linux kernel version if running with the fix for this?

Thank you!

[popcornmix]

The fix was in firmware here:
raspberrypi/firmware@ecc243c

If vcgencmd version reports Aug 26 2022 or later you should be fine.

[aaronriekenberg]

Looks like this has made it into current Raspberry Pi OS even without running rpi-update

$ vcgencmd version
Aug 26 2022 14:04:36
Copyright (c) 2012 Broadcom
version 102f1e848393c2112206fadffaaf86db04e98326 (clean) (release) (start)

Thanks again @popcornmix !

[fritol]

Closing as believed to be fixed
note really

it started for me after firmware update
pi 4
64bit rasp

fine before

[popcornmix]

it started for me after firmware update
pi 4
64bit rasp

This issue only affected pi0-3 and is fixed.
If you have an issue with Pi4 then create a new issue giving full details of how it occurs.