The specific symptom in this case is that when I set "hdmi_enable_4kp60=1" in config.txt and reboot, the display will show the initial boot screen with the 4 raspberry pi logos and boot logs, but as soon as the VC4 driver takes over, the display goes blank and stays blank. I did eventually discover that If I wait for 8 or 9 minutes, the display does in fact come back on and show the RPi OS desktop at 4k60p. This behavior is consistent and repeatable.
Hardware list:
- RPi 4 8GB
- Official PSU
- Official microHDMI to HDMI
- Acer Nitro XV273K Monitor (supports HDMI 2.0 input with support for 4K60p full RGB)
OS:
- Fresh install of August 2020 Raspberry Pi OS (32-bit)
Steps:
- Install clean image of August 2020 RPi OS to SD card
- boot SD card, desktop comes up normally at 4K30p
- Use raspi-config to enable 4K60p, reboot
- Initial boot screen comes up in 4k60p, then display goes blank
- After 8-9 minutes, desktop finally appears in 4K60p
Analysis:
I spent most of the day yesterday trying to debug this issue. My initial thought was that this was an EDID parsing / matching issue, but after some investigation I determined that wasn't the case and that the VC4 DRM driver is selecting the appropriate modeline. After enabling the DRM debug logs in the kernel via the "drm.debug=0x14" kernel command line flag, I could see that the DRM driver is getting stuck in a loop with the following error logs popping out 30 seconds or so:
Code: Select all
[ 247.534702] [drm:drm_atomic_helper_wait_for_dependencies [drm_kms_helper]] *ERROR* [CRTC:52:crtc-0] flip_done timed out
[ 257.774879] [drm:drm_atomic_helper_wait_for_dependencies [drm_kms_helper]] *ERROR* [CONNECTOR:54:HDMI-A-1] flip_done timed out
[ 257.774970] [drm:vc4_crtc_atomic_flush [vc4]] [CRTC:52] crtc_atomic_flush.
[ 268.015082] [drm:drm_atomic_helper_wait_for_flip_done [drm_kms_helper]] *ERROR* [CRTC:52:crtc-0] flip_done timed out
Code: Select all
[ 432.577342] [drm:vc4_crtc_atomic_check [vc4]] [CRTC:52] crtc_atomic_check.
[ 432.577529] [drm:drm_atomic_commit [drm]] committing f6ee61ec
[ 442.738703] [drm:drm_atomic_helper_wait_for_dependencies [drm_kms_helper]] *ERROR* [CRTC:52:crtc-0] flip_done timed out
[ 452.978880] [drm:drm_atomic_helper_wait_for_dependencies [drm_kms_helper]] *ERROR* [CONNECTOR:54:HDMI-A-1] flip_done timed out
[ 463.219017] [drm:drm_atomic_helper_wait_for_dependencies [drm_kms_helper]] *ERROR* [PLANE:31:plane-0] flip_done timed out
[ 463.219109] [drm:drm_atomic_helper_commit_modeset_disables [drm_kms_helper]] disabling [ENCODER:53:TMDS-53]
[ 463.219231] [drm:vc4_fkms_encoder_disable [vc4]] Encoder_disable
[ 463.219321] [drm:drm_atomic_helper_commit_modeset_disables [drm_kms_helper]] disabling [CRTC:52:crtc-0]
[ 463.219401] [drm:vc4_crtc_disable [vc4]] [CRTC:52] vblanks off.
[ 463.219483] [drm:vc4_fkms_disable_vblank [vc4]] [CRTC:52] disable_vblank.
[ 463.219560] [drm:vc4_plane_atomic_disable [vc4]] [PLANE:31:plane-0] plane disable 3840x2160@44 +0,0
[ 463.219636] [drm:vc4_plane_set_blank [vc4]] [PLANE:31:plane-0] primary plane blank
[ 463.219765] [drm:drm_atomic_helper_commit_modeset_disables [drm_kms_helper]] modeset on [CRTC:52:crtc-0]
[ 463.219875] [drm:vc4_crtc_mode_set_nofb [vc4]] Setting mode for display num 2 mode name , clk 594000, h(disp 3840, start 4016, end 4104, total 4400, skew 0) v(disp 2160, start 2168, end 2178, total 2250, scan 0), vrefresh 60, par 0, flags 0x0005
[ 464.258959] ------------[ cut here ]------------
[ 464.258990] WARNING: CPU: 0 PID: 511 at drivers/firmware/raspberrypi.c:63 rpi_firmware_transaction+0x108/0x128
[ 464.259002] Firmware transaction timeout
[ 464.259006] Modules linked in: cmac rfcomm bnep hci_uart btbcm bluetooth ecdh_generic ecc 8021q garp stp llc evdev hid_apple brcmfmac brcmutil sha256_generic libsha256 cfg80211 rfkill vc4 cec v3d gpu_sched raspberrypi_hwmon drm_kms_helper drm bcm2835_codec(C) bcm2835_v4l2(C) v4l2_mem2mem bcm2835_isp(C) bcm2835_mmal_vchiq(C) videobuf2_dma_contig drm_panel_orientation_quirks videobuf2_vmalloc videobuf2_memops vc_sm_cma(C) videobuf2_v4l2 snd_bcm2835(C) videobuf2_common snd_soc_core videodev snd_compress mc snd_pcm_dmaengine snd_pcm snd_timer snd rpivid_mem syscopyarea sysfillrect sysimgblt fb_sys_fops uio_pdrv_genirq uio i2c_dev ip_tables x_tables ipv6 nf_defrag_ipv6
[ 464.259253] CPU: 0 PID: 511 Comm: Xorg Tainted: G C 5.4.51-v7l+ #1333
[ 464.259261] Hardware name: BCM2711
[ 464.259268] Backtrace:
[ 464.259289] [<c020d46c>] (dump_backtrace) from [<c020d768>] (show_stack+0x20/0x24)
[ 464.259302] r6:d30d0000 r5:00000000 r4:c129c8f8 r3:0e24d4f2
[ 464.259321] [<c020d748>] (show_stack) from [<c0a39a44>] (dump_stack+0xe0/0x124)
[ 464.259338] [<c0a39964>] (dump_stack) from [<c0221c70>] (__warn+0xec/0x104)
[ 464.259351] r8:0000003f r7:00000009 r6:c0e2a724 r5:00000000 r4:d30d1a64 r3:0e24d4f2
[ 464.259367] [<c0221b84>] (__warn) from [<c0221d0c>] (warn_slowpath_fmt+0x84/0xc0)
[ 464.259379] r9:c0e2a724 r8:0000003f r7:c08a2dec r6:00000009 r5:c0e2a744 r4:c1204f88
[ 464.259394] [<c0221c8c>] (warn_slowpath_fmt) from [<c08a2dec>] (rpi_firmware_transaction+0x108/0x128)
[ 464.259406] r9:ef96b340 r8:00000000 r7:00000000 r6:ffffff92 r5:ef96b340 r4:c1204f88
[ 464.259421] [<c08a2ce4>] (rpi_firmware_transaction) from [<c08a2ec8>] (rpi_firmware_property_list+0xbc/0x174)
[ 464.259431] r7:c1204f88 r6:dec04000 r5:00001000 r4:4000000e
[ 464.259513] [<c08a2e0c>] (rpi_firmware_property_list) from [<bf25e008>] (vc4_crtc_mode_set_nofb+0x2d4/0x35c [vc4])
[ 464.259526] r10:d4270a00 r9:d3dedc40 r8:ef323614 r7:c1204f88 r6:d3ded440 r5:00000000
[ 464.259534] r4:ef323600
[ 464.259685] [<bf25dd34>] (vc4_crtc_mode_set_nofb [vc4]) from [<bf3435c8>] (drm_atomic_helper_commit_modeset_disables+0x294/0x4b8 [drm_kms_helper])
[ 464.259697] r10:ef322600 r9:d3ded440 r8:bf27ad80 r7:d3ded800 r6:d3ded440 r5:00000001
[ 464.259705] r4:d3c28580
[ 464.259855] [<bf343334>] (drm_atomic_helper_commit_modeset_disables [drm_kms_helper]) from [<bf25fffc>] (vc4_atomic_complete_commit+0xc4/0x5d4 [vc4])
[ 464.259867] r10:d30d1e24 r9:d3c28300 r8:d3dedda8 r7:00000000 r6:d3dedc40 r5:d3c28580
[ 464.259875] r4:d3ded800
[ 464.260008] [<bf25ff38>] (vc4_atomic_complete_commit [vc4]) from [<bf2605ec>] (vc4_atomic_commit+0xe0/0x194 [vc4])
[ 464.260021] r10:d30d1e24 r9:d3c28300 r8:d3dedda8 r7:00000000 r6:d3ded800 r5:00000000
[ 464.260028] r4:d3c28580
[ 464.260278] [<bf26050c>] (vc4_atomic_commit [vc4]) from [<bf2db2dc>] (drm_atomic_commit+0x5c/0x60 [drm])
[ 464.260290] r8:00000001 r7:d3ded800 r6:d3ded800 r5:d3c28580 r4:00000000 r3:bf26050c
[ 464.260548] [<bf2db280>] (drm_atomic_commit [drm]) from [<bf3442f8>] (drm_atomic_helper_set_config+0x7c/0xa8 [drm_kms_helper])
[ 464.260559] r6:d30d1d54 r5:d3c28580 r4:00000000 r3:0e24d4f2
[ 464.260818] [<bf34427c>] (drm_atomic_helper_set_config [drm_kms_helper]) from [<bf2cee90>] (drm_mode_setcrtc+0x354/0x5ac [drm])
[ 464.260829] r6:d408a0c0 r5:d30d0000 r4:d3c28300 r3:bf34427c
[ 464.261182] [<bf2ceb3c>] (drm_mode_setcrtc [drm]) from [<bf2c9aa8>] (drm_ioctl_kernel+0xb4/0xf8 [drm])
[ 464.261194] r10:c06864a2 r9:d3e37400 r8:00000002 r7:d30d1e24 r6:bf2ceb3c r5:d3ded800
[ 464.261202] r4:c1204f88
[ 464.261553] [<bf2c99f4>] (drm_ioctl_kernel [drm]) from [<bf2c9f74>] (drm_ioctl+0x234/0x3c8 [drm])
[ 464.261565] r9:d3e37400 r8:00000068 r7:d30d1e24 r6:00000068 r5:bf2fa894 r4:c1204f88
[ 464.261749] [<bf2c9d40>] (drm_ioctl [drm]) from [<c0410860>] (do_vfs_ioctl+0xbc/0x804)
[ 464.261762] r10:00000036 r9:d30d0000 r8:0000000c r7:d42ada80 r6:d3ea7af0 r5:bef43568
[ 464.261770] r4:c1204f88
[ 464.261785] [<c04107a4>] (do_vfs_ioctl) from [<c0410fec>] (ksys_ioctl+0x44/0x6c)
[ 464.261797] r10:00000036 r9:d30d0000 r8:0000000c r7:c06864a2 r6:d42ada80 r5:bef43568
[ 464.261804] r4:d42ada81
[ 464.261819] [<c0410fa8>] (ksys_ioctl) from [<c041102c>] (sys_ioctl+0x18/0x1c)
[ 464.261831] r8:c02011c4 r7:00000036 r6:c06864a2 r5:bef43568 r4:b6fbd968 r3:00000001
[ 464.261846] [<c0411014>] (sys_ioctl) from [<c0201000>] (ret_fast_syscall+0x0/0x28)
[ 464.261855] Exception stack(0xd30d1fa8 to 0xd30d1ff0)
[ 464.261867] 1fa0: b6fbd968 bef43568 0000000c c06864a2 bef43568 00000001
[ 464.261879] 1fc0: b6fbd968 bef43568 c06864a2 00000036 01026cb8 0000003c 00000034 00000000
[ 464.261889] 1fe0: b6d6a08c bef4354c b6d5088c b69dc51c
[ 464.261900] ---[ end trace 2904cc9e799aa989 ]---
[ 464.261998] [drm:drm_atomic_helper_commit_modeset_disables [drm_kms_helper]] modeset on [ENCODER:53:TMDS-53]
[ 464.262080] [drm:vc4_plane_set_blank [vc4]] [PLANE:31:plane-0] primary plane unblank
[ 464.504905] raspberrypi-firmware soc:firmware: Request 0x00048015 returned status 0x80000001
[ 464.504923] ------------[ cut here ]------------
[ 464.505011] WARNING: CPU: 0 PID: 511 at drivers/gpu/drm/vc4/vc4_firmware_kms.c:419 vc4_plane_set_blank+0x164/0x170 [vc4]
[ 464.505023] vc4_plane_set_blank: firmware call failed. Please update your firmware
[ 464.505028] Modules linked in: cmac rfcomm bnep hci_uart btbcm bluetooth ecdh_generic ecc 8021q garp stp llc evdev hid_apple brcmfmac brcmutil sha256_generic libsha256 cfg80211 rfkill vc4 cec v3d gpu_sched raspberrypi_hwmon drm_kms_helper drm bcm2835_codec(C) bcm2835_v4l2(C) v4l2_mem2mem bcm2835_isp(C) bcm2835_mmal_vchiq(C) videobuf2_dma_contig drm_panel_orientation_quirks videobuf2_vmalloc videobuf2_memops vc_sm_cma(C) videobuf2_v4l2 snd_bcm2835(C) videobuf2_common snd_soc_core videodev snd_compress mc snd_pcm_dmaengine snd_pcm snd_timer snd rpivid_mem syscopyarea sysfillrect sysimgblt fb_sys_fops uio_pdrv_genirq uio i2c_dev ip_tables x_tables ipv6 nf_defrag_ipv6
[ 464.505261] CPU: 0 PID: 511 Comm: Xorg Tainted: G WC 5.4.51-v7l+ #1333
[ 464.505269] Hardware name: BCM2711
[ 464.505276] Backtrace:
[ 464.505298] [<c020d46c>] (dump_backtrace) from [<c020d768>] (show_stack+0x20/0x24)
[ 464.505309] r6:d30d0000 r5:00000000 r4:c129c8f8 r3:0e24d4f2
[ 464.505326] [<c020d748>] (show_stack) from [<c0a39a44>] (dump_stack+0xe0/0x124)
[ 464.505344] [<c0a39964>] (dump_stack) from [<c0221c70>] (__warn+0xec/0x104)
[ 464.505356] r8:000001a3 r7:00000009 r6:bf27f344 r5:00000000 r4:d30d1b6c r3:0e24d4f2
[ 464.505371] [<c0221b84>] (__warn) from [<c0221d0c>] (warn_slowpath_fmt+0x84/0xc0)
[ 464.505382] r9:bf27f344 r8:000001a3 r7:bf25d8bc r6:00000009 r5:bf27f36c r4:c1204f88
[ 464.505458] [<c0221c8c>] (warn_slowpath_fmt) from [<bf25d8bc>] (vc4_plane_set_blank+0x164/0x170 [vc4])
[ 464.505470] r9:00000000 r8:00000000 r7:00000000 r6:d3dedc40 r5:c1204f88 r4:ffffffea
[ 464.505605] [<bf25d758>] (vc4_plane_set_blank [vc4]) from [<bf25da50>] (vc4_plane_atomic_update+0x34/0x38 [vc4])
[ 464.505616] r7:ef323400 r6:d3f1e840 r5:d3c28580 r4:00000001
[ 464.505764] [<bf25da1c>] (vc4_plane_atomic_update [vc4]) from [<bf34520c>] (drm_atomic_helper_commit_planes+0x134/0x2a0 [drm_kms_helper])
[ 464.505911] [<bf3450d8>] (drm_atomic_helper_commit_planes [drm_kms_helper]) from [<bf260018>] (vc4_atomic_complete_commit+0xe0/0x5d4 [vc4])
[ 464.505924] r10:d30d1e24 r9:d3c28300 r8:d3dedda8 r7:00000000 r6:d3dedc40 r5:d3c28580
[ 464.505932] r4:d3ded800
[ 464.506063] [<bf25ff38>] (vc4_atomic_complete_commit [vc4]) from [<bf2605ec>] (vc4_atomic_commit+0xe0/0x194 [vc4])
[ 464.506075] r10:d30d1e24 r9:d3c28300 r8:d3dedda8 r7:00000000 r6:d3ded800 r5:00000000
[ 464.506083] r4:d3c28580
[ 464.506329] [<bf26050c>] (vc4_atomic_commit [vc4]) from [<bf2db2dc>] (drm_atomic_commit+0x5c/0x60 [drm])
[ 464.506342] r8:00000001 r7:d3ded800 r6:d3ded800 r5:d3c28580 r4:00000000 r3:bf26050c
[ 464.506598] [<bf2db280>] (drm_atomic_commit [drm]) from [<bf3442f8>] (drm_atomic_helper_set_config+0x7c/0xa8 [drm_kms_helper])
[ 464.506610] r6:d30d1d54 r5:d3c28580 r4:00000000 r3:0e24d4f2
[ 464.506866] [<bf34427c>] (drm_atomic_helper_set_config [drm_kms_helper]) from [<bf2cee90>] (drm_mode_setcrtc+0x354/0x5ac [drm])
[ 464.506877] r6:d408a0c0 r5:d30d0000 r4:d3c28300 r3:bf34427c
[ 464.507227] [<bf2ceb3c>] (drm_mode_setcrtc [drm]) from [<bf2c9aa8>] (drm_ioctl_kernel+0xb4/0xf8 [drm])
[ 464.507240] r10:c06864a2 r9:d3e37400 r8:00000002 r7:d30d1e24 r6:bf2ceb3c r5:d3ded800
[ 464.507248] r4:c1204f88
[ 464.507597] [<bf2c99f4>] (drm_ioctl_kernel [drm]) from [<bf2c9f74>] (drm_ioctl+0x234/0x3c8 [drm])
[ 464.507610] r9:d3e37400 r8:00000068 r7:d30d1e24 r6:00000068 r5:bf2fa894 r4:c1204f88
[ 464.507794] [<bf2c9d40>] (drm_ioctl [drm]) from [<c0410860>] (do_vfs_ioctl+0xbc/0x804)
[ 464.507807] r10:00000036 r9:d30d0000 r8:0000000c r7:d42ada80 r6:d3ea7af0 r5:bef43568
[ 464.507815] r4:c1204f88
[ 464.507830] [<c04107a4>] (do_vfs_ioctl) from [<c0410fec>] (ksys_ioctl+0x44/0x6c)
[ 464.507841] r10:00000036 r9:d30d0000 r8:0000000c r7:c06864a2 r6:d42ada80 r5:bef43568
[ 464.507849] r4:d42ada81
[ 464.507864] [<c0410fa8>] (ksys_ioctl) from [<c041102c>] (sys_ioctl+0x18/0x1c)
[ 464.507876] r8:c02011c4 r7:00000036 r6:c06864a2 r5:bef43568 r4:b6fbd968 r3:00000001
[ 464.507891] [<c0411014>] (sys_ioctl) from [<c0201000>] (ret_fast_syscall+0x0/0x28)
[ 464.507900] Exception stack(0xd30d1fa8 to 0xd30d1ff0)
[ 464.507912] 1fa0: b6fbd968 bef43568 0000000c c06864a2 bef43568 00000001
[ 464.507924] 1fc0: b6fbd968 bef43568 c06864a2 00000036 01026cb8 0000003c 00000034 00000000
[ 464.507934] 1fe0: b6d6a08c bef4354c b6d5088c b69dc51c
[ 464.507944] ---[ end trace 2904cc9e799aa98a ]---
[ 464.508026] [drm:vc4_crtc_atomic_flush [vc4]] [CRTC:52] crtc_atomic_flush.
[ 464.508117] [drm:drm_atomic_helper_commit_modeset_enables [drm_kms_helper]] enabling [CRTC:52:crtc-0]
[ 464.508202] [drm:vc4_crtc_enable [vc4]] [CRTC:52] vblanks on.
I've reached the limit of my ability to debug this issue, so I need some guidance from the RPi experts...
Thanks!
-Robert Hildinger
