rhildinger
Posts: 39
Joined: Thu Jun 09, 2016 6:07 pm

4k60p display issue (DRM VC4 driver crash / backtrace)

Tue Sep 08, 2020 3:01 pm

I'm running into an issue trying to get 4K60p output from my RPi4 to my Acer Nitro XV273K monitor. I thought this might have been the typical EDID issue that many people have run into trying to get 4K60p to work, but this appears to be more of a corner case that involves a bug in the DRM VC4 driver causing it to get stuck in a loop and eventually crash an/or restart.

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
This goes on for several minutes until the VC4 DRM driver apparently crashes or restarts just past the 7 minute mark. The following backtrace is dumped at this point:

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.
Immediately after this backtrace is dumped, the VC4 DRM driver seems to correct itself and the successfully brings up the desktop at 4k60p

I've reached the limit of my ability to debug this issue, so I need some guidance from the RPi experts...

Thanks!
-Robert Hildinger

ejolson
Posts: 6039
Joined: Tue Mar 18, 2014 11:47 am

Re: 4k60p display issue (DRM VC4 driver crash / backtrace)

Tue Sep 08, 2020 3:14 pm

rhildinger wrote:
Tue Sep 08, 2020 3:01 pm
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
Could it be a marginal cable? Is it possible to increase the HDMI drive strength to make up for it?

rhildinger
Posts: 39
Joined: Thu Jun 09, 2016 6:07 pm

Re: 4k60p display issue (DRM VC4 driver crash / backtrace)

Tue Sep 08, 2020 3:17 pm

ejolson wrote:
Tue Sep 08, 2020 3:14 pm
Could it be a marginal cable? Is it possible to increase the HDMI drive strength to make up for it?
Thanks for your reply! I tried multiple cables, all with the same result. Also, you cannot increase HDMI drive strength on RPi 4...

jamesh
Raspberry Pi Engineer & Forum Moderator
Raspberry Pi Engineer & Forum Moderator
Posts: 27451
Joined: Sat Jul 30, 2011 7:41 pm

Re: 4k60p display issue (DRM VC4 driver crash / backtrace)

Tue Sep 08, 2020 4:48 pm

Could you post an issue with the above contents on our Linux github repo? Easier to flag up to the right engineer from there. Once done, please add a link to it on this thread.
Principal Software Engineer at Raspberry Pi (Trading) Ltd.
Contrary to popular belief, humorous signatures are allowed.
I've been saying "Mucho" to my Spanish friend a lot more lately. It means a lot to him.

rhildinger
Posts: 39
Joined: Thu Jun 09, 2016 6:07 pm

Re: 4k60p display issue (DRM VC4 driver crash / backtrace)

Tue Sep 08, 2020 5:43 pm

Done.

Issue #3842 created in raspberrypi/linux:

https://github.com/raspberrypi/linux/issues/3842

Thanks!
-Robert

Return to “Troubleshooting”