Ubuntu 20.10 Desktop on Pi4B - random Xorg freezes

[Juliane]

My system:
Linux myRaspi 5.8.0-1010-raspi #13-Ubuntu SMP PREEMPT Wed Dec 9 17:14:07 UTC 2020 aarch64 aarch64 aarch64 GNU/Linux

I'm using
- Raspberry Pi4B 8GB
- Logitech MK120 Keyboard and Mouse (wired)

I'm using Ubuntu 20.10 Desktop and get random crashes in both of my desktops, ubuntu and lxqt. After 1 or 2 hours (often during CPU/GPU-heavy work like using Firefox), the system freezes, which means:
- Screen freezes (just shows the same picture. mouse-cursor not moving, keyboard not working)
- Keyboard not responding (e.g. Num-LED not changing when pressing Num)
- Changing to another tty via e.g. Ctrl+Alt+F3 is not working anymore
- BUT: System in the background still works. I can still hear audio (of a movie for example). Other tasks like ffmpeg-downloads are still working.

During a freeze, Alt+SysRq+k isn't changing much. I can hear the audio stopping. But the system is "too frozen" to be able to kill Xorg. I also tried killing it via ssh - no chance. Alt+SysRq+reisub works to do a Pi-restart.
These freezes occur during typing, during clicking, but also when doing nothing with mouse and keyboard (like watching a video).

A journalctl-log of the freeze (occurred at 00:08:something when typing with my keyboard) during ubuntu-desktop session is given here (I tried Alt+SysRq+k at 00:10:something without success):

[...]
Dez 26 00:07:31 myRaspi gnome-shell[166054]: JS ERROR: TypeError: windowActor is null
                                                     _addWindowEffect@resource:///org/gnome/shell/ui/closeDialog.js:90:28
                                                     vfunc_show@resource:///org/gnome/shell/ui/closeDialog.js:162:14
Dez 26 00:07:36 myRaspi gnome-shell[166054]: JS ERROR: TypeError: windowActor is null
                                                     _addWindowEffect@resource:///org/gnome/shell/ui/closeDialog.js:90:28
                                                     vfunc_show@resource:///org/gnome/shell/ui/closeDialog.js:162:14
Dez 26 00:07:41 myRaspi gnome-shell[166054]: JS ERROR: TypeError: windowActor is null
                                                     _addWindowEffect@resource:///org/gnome/shell/ui/closeDialog.js:90:28
                                                     vfunc_show@resource:///org/gnome/shell/ui/closeDialog.js:162:14
Dez 26 00:07:46 myRaspi gnome-shell[166054]: JS ERROR: TypeError: windowActor is null
                                                     _addWindowEffect@resource:///org/gnome/shell/ui/closeDialog.js:90:28
                                                     vfunc_show@resource:///org/gnome/shell/ui/closeDialog.js:162:14
Dez 26 00:07:48 myRaspi dbus-daemon[4131]: [session uid=1000 pid=4131] Activating via systemd: service name='org.freedesktop.Tracker1' unit='tracker-store.service' requested by ':1.2' (uid=1000 pid=4128 comm="/usr/libexec/tracker-miner-fs " label="unconfined")
Dez 26 00:07:48 myRaspi systemd[4119]: Starting Tracker metadata database store and lookup manager...
Dez 26 00:07:48 myRaspi dbus-daemon[4131]: [session uid=1000 pid=4131] Successfully activated service 'org.freedesktop.Tracker1'
Dez 26 00:07:48 myRaspi systemd[4119]: Started Tracker metadata database store and lookup manager.
Dez 26 00:07:49 myRaspi dbus-daemon[4131]: [session uid=1000 pid=4131] Activating via systemd: service name='org.freedesktop.Tracker1.Miner.Extract' unit='tracker-extract.service' requested by ':1.2' (uid=1000 pid=4128 comm="/usr/libexec/tracker-miner-fs " label="unconfined")
Dez 26 00:07:49 myRaspi systemd[4119]: Starting Tracker metadata extractor...
Dez 26 00:07:49 myRaspi tracker-extract[179165]: Set scheduler policy to SCHED_IDLE
Dez 26 00:07:49 myRaspi tracker-extract[179165]: Setting priority nice level to 19
Dez 26 00:07:49 myRaspi dbus-daemon[4131]: [session uid=1000 pid=4131] Successfully activated service 'org.freedesktop.Tracker1.Miner.Extract'
Dez 26 00:07:49 myRaspi systemd[4119]: Started Tracker metadata extractor.
Dez 26 00:07:51 myRaspi gnome-shell[166054]: JS ERROR: TypeError: windowActor is null
                                                     _addWindowEffect@resource:///org/gnome/shell/ui/closeDialog.js:90:28
                                                     vfunc_show@resource:///org/gnome/shell/ui/closeDialog.js:162:14
Dez 26 00:08:00 myRaspi systemd[4119]: tracker-extract.service: Succeeded.
Dez 26 00:08:01 myRaspi gnome-shell[166054]: JS ERROR: TypeError: windowActor is null
                                                     _addWindowEffect@resource:///org/gnome/shell/ui/closeDialog.js:90:28
                                                     vfunc_show@resource:///org/gnome/shell/ui/closeDialog.js:162:14
Dez 26 00:08:06 myRaspi gnome-shell[166054]: JS ERROR: TypeError: windowActor is null
                                                     _addWindowEffect@resource:///org/gnome/shell/ui/closeDialog.js:90:28
                                                     vfunc_show@resource:///org/gnome/shell/ui/closeDialog.js:162:14
Dez 26 00:08:11 myRaspi gnome-shell[166054]: JS ERROR: TypeError: windowActor is null
                                                     _addWindowEffect@resource:///org/gnome/shell/ui/closeDialog.js:90:28
                                                     vfunc_show@resource:///org/gnome/shell/ui/closeDialog.js:162:14
Dez 26 00:08:16 myRaspi gnome-shell[166054]: JS ERROR: TypeError: windowActor is null
                                                     _addWindowEffect@resource:///org/gnome/shell/ui/closeDialog.js:90:28
                                                     vfunc_show@resource:///org/gnome/shell/ui/closeDialog.js:162:14
Dez 26 00:08:20 myRaspi tracker-store[179156]: OK
Dez 26 00:08:20 myRaspi systemd[4119]: tracker-store.service: Succeeded.
Dez 26 00:08:21 myRaspi gnome-shell[166054]: JS ERROR: TypeError: windowActor is null
                                                     _addWindowEffect@resource:///org/gnome/shell/ui/closeDialog.js:90:28
                                                     vfunc_show@resource:///org/gnome/shell/ui/closeDialog.js:162:14
Dez 26 00:08:22 myRaspi /usr/libexec/gdm-x-session[165062]: (EE) event1 - Logitech USB Keyboard: client bug: event processing lagging behind by 13ms, your system is too slow
Dez 26 00:08:23 myRaspi /usr/libexec/gdm-x-session[165062]: (EE) event1 - Logitech USB Keyboard: client bug: event processing lagging behind by 22ms, your system is too slow
Dez 26 00:10:02 myRaspi rsyslogd[823]: [origin software="rsyslogd" swVersion="8.2006.0" x-pid="823" x-info="https://www.rsyslog.com"] rsyslogd was HUPed
Dez 26 00:10:35 myRaspi kernel: INFO: task Xorg:165062 blocked for more than 120 seconds.
Dez 26 00:10:35 myRaspi kernel: Tainted: G C E 5.8.0-1010-raspi #13-Ubuntu
Dez 26 00:10:35 myRaspi kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Dez 26 00:10:35 myRaspi kernel: Xorg D 0 165062 165060 0x00000001
Dez 26 00:10:35 myRaspi kernel: Call trace:
Dez 26 00:10:35 myRaspi kernel: __switch_to+0xfc/0x12c
Dez 26 00:10:35 myRaspi kernel: __schedule+0x2a8/0x72c
Dez 26 00:10:35 myRaspi kernel: schedule+0x84/0x120
Dez 26 00:10:35 myRaspi kernel: schedule_timeout+0xc8/0x100
Dez 26 00:10:35 myRaspi kernel: wait_for_completion+0x8c/0x12c
Dez 26 00:10:35 myRaspi kernel: __flush_work.isra.0+0x80/0xa0
Dez 26 00:10:35 myRaspi kernel: __cancel_work_timer+0xcc/0x1e0
Dez 26 00:10:35 myRaspi kernel: cancel_delayed_work_sync+0x20/0x30
Dez 26 00:10:35 myRaspi kernel: v3d_clock_up_get+0x58/0xa0 [v3d]
Dez 26 00:10:35 myRaspi kernel: v3d_job_init+0xc4/0xe0 [v3d]
Dez 26 00:10:35 myRaspi kernel: v3d_submit_cl_ioctl+0xac/0x740 [v3d]
Dez 26 00:10:35 myRaspi kernel: drm_ioctl_kernel+0xd0/0x120 [drm]
Dez 26 00:10:35 myRaspi kernel: drm_ioctl+0x1e8/0x460 [drm]
Dez 26 00:10:35 myRaspi kernel: ksys_ioctl+0xb4/0xf4
Dez 26 00:10:35 myRaspi kernel: __arm64_sys_ioctl+0x2c/0xbc
Dez 26 00:10:35 myRaspi kernel: el0_svc_common.constprop.0+0x84/0x200
Dez 26 00:10:35 myRaspi kernel: do_el0_svc+0x30/0xa0
Dez 26 00:10:35 myRaspi kernel: el0_svc+0x18/0x50
Dez 26 00:10:35 myRaspi kernel: el0_sync_handler+0x98/0x354
Dez 26 00:10:35 myRaspi kernel: el0_sync+0x17c/0x180
Dez 26 00:10:35 myRaspi kernel: INFO: task kworker/1:1:171257 blocked for more than 120 seconds.
Dez 26 00:10:35 myRaspi kernel: Tainted: G C E 5.8.0-1010-raspi #13-Ubuntu
Dez 26 00:10:35 myRaspi kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Dez 26 00:10:35 myRaspi kernel: kworker/1:1 D 0 171257 2 0x00000028
Dez 26 00:10:35 myRaspi kernel: Workqueue: events dbs_work_handler
Dez 26 00:10:35 myRaspi kernel: Call trace:
Dez 26 00:10:35 myRaspi kernel: __switch_to+0xfc/0x12c
Dez 26 00:10:35 myRaspi kernel: __schedule+0x2a8/0x72c
Dez 26 00:10:35 myRaspi kernel: schedule+0x84/0x120
Dez 26 00:10:35 myRaspi kernel: schedule_timeout+0x88/0x100
Dez 26 00:10:35 myRaspi kernel: wait_for_completion_timeout+0x8c/0x110
Dez 26 00:10:35 myRaspi kernel: mbox_send_message+0xac/0x130
Dez 26 00:10:35 myRaspi kernel: rpi_firmware_transaction+0x6c/0x110
Dez 26 00:10:35 myRaspi kernel: rpi_firmware_property_list+0xc4/0x184
Dez 26 00:10:35 myRaspi kernel: rpi_firmware_property+0x7c/0x120
Dez 26 00:10:35 myRaspi kernel: raspberrypi_fw_get_rate+0x50/0x8c
Dez 26 00:10:35 myRaspi kernel: clk_recalc+0x40/0xac
Dez 26 00:10:35 myRaspi kernel: clk_change_rate+0xf0/0x520
Dez 26 00:10:35 myRaspi kernel: clk_core_set_rate_nolock.part.0+0xe0/0xf0
Dez 26 00:10:35 myRaspi kernel: clk_core_set_rate_nolock+0xa0/0x200
Dez 26 00:10:35 myRaspi kernel: clk_set_rate+0x44/0x18c
Dez 26 00:10:35 myRaspi kernel: dev_pm_opp_set_rate+0x4b0/0x620
Dez 26 00:10:35 myRaspi kernel: set_target+0x4c/0x94
Dez 26 00:10:35 myRaspi kernel: __target_index+0xd0/0x1e4
Dez 26 00:10:35 myRaspi kernel: __cpufreq_driver_target+0x108/0x13c
Dez 26 00:10:35 myRaspi kernel: od_update+0xe8/0x130
Dez 26 00:10:35 myRaspi kernel: od_dbs_update+0x54/0xb4
Dez 26 00:10:35 myRaspi kernel: dbs_work_handler+0x4c/0x8c
Dez 26 00:10:35 myRaspi kernel: process_one_work+0x1d8/0x4a0
Dez 26 00:10:35 myRaspi kernel: worker_thread+0x74/0x3c0
Dez 26 00:10:35 myRaspi kernel: kthread+0x138/0x14c
Dez 26 00:10:35 myRaspi kernel: ret_from_fork+0x10/0x34
Dez 26 00:10:35 myRaspi kernel: INFO: task kworker/0:1:178168 blocked for more than 120 seconds.
Dez 26 00:10:35 myRaspi kernel: Tainted: G C E 5.8.0-1010-raspi #13-Ubuntu
Dez 26 00:10:35 myRaspi kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Dez 26 00:10:35 myRaspi kernel: kworker/0:1 D 0 178168 2 0x00000028
Dez 26 00:10:35 myRaspi kernel: Workqueue: events v3d_clock_down_work [v3d]
[...]

[Juliane (juliane11)]

A fresh Xorg.0.log.old after such a crash is given as attachment. I changed some stuff like mac-address, but all relevant details are kept original.

It is full of "Logitech USB Optical Mouse/Keyboard: client bug: event processing lagging behind" messages.

[Juliane (juliane11)]

See attachment for Xorg backtrace. My steps:
- connecting to raspberry pi via ssh
- pgrep Xorg returned 4193
- sudo gdb /usr/bin/Xorg 2>&1 | tee gdb-Xorg-backtrace.txt
- (gdb) attach 4193
- (gdb) cont
After the freeze occurred:
- (gdb) thread apply all bt full

[Juerg Haefliger (juergh)]

Are there specific things you run to trigger this? Is this still an issue with an update groovy system and the latest kernel 5.8.0-1019.22? Also, do you see similar issues with hirsute http://cdimage.ubuntu.com/daily-preinstalled/current/?

[Juliane (juliane11)]

I don't want to jinx it, but I couldn't trigger it anymore using the latest kernel.

And regarding your first question: No, there were no specific things to trigger the freeze.

[Juerg Haefliger (juergh)]

Thanks for reporting back. I'll close the ticker as 'Fix Released'. Please open a new one if you encounter the issue again.