Например, открываем в chromium https://www.youtube.com/watch?v=aqz-KE-bpKQ, и когда начнётся воспроизведение, активно шевелим мышкой над окном браузера. Видео останавливается, мышиный курсор движется с заметным запаздыванием.
Created attachment 10669 [details] общесистемный профайл на "плохом" ядре (5.15.33)
Created attachment 10670 [details] общесистемный профайл на "хорошем" ядре
На "плохом" ядре процесс Xorg тратит гораздо больше процессорного времени в функции ProcessPointerEvent. Кроме того, функция xf86_crtc_load_cursor_argb с "хорошим" ядром тратит практически всё время на вызов drmmode_set_cursor, а с "плохим" - примерно 2/3 (процессорного) времени что-то делает в userspace.
С "плохим" ядром в логе Xorg появляются такие сообщения: [ 52.025] (EE) event1 - Logitech Wireless Mouse: client bug: event processing lagging behind by 55ms, your system is too slow [ 52.808] (EE) event1 - Logitech Wireless Mouse: client bug: event processing lagging behind by 22ms, your system is too slow [ 55.491] (EE) event1 - Logitech Wireless Mouse: client bug: event processing lagging behind by 81ms, your system is too slow [ 56.491] (EE) event1 - Logitech Wireless Mouse: client bug: event processing lagging behind by 89ms, your system is too slow [ 56.492] (EE) event1 - Logitech Wireless Mouse: WARNING: log rate limit exceeded (5 msgs per 60min). Discarding future messages.
Общесистемный профайл получаю так: 1. Запускаю (в графическом интерфейсе) терминал и файловый менеджер, располагаю окна рядом 2. В UART консоли запускаю (от root) cd /tmp && perf record -g --call-graph=dwarf,16384 -a -F 997 -- sleep 20 Одновременно с этим в графическом интерфейсе вожу туда-сюда мышкой с терминала на файловый менеджер (и обратно) в течение 20 секунд (столько будет собирать информацию perf record) 3. Полученный perf.data обрабатываю командой: perf script --header | gzip -9 > xorg-cursor-`uname -r`.stacks.gz 4. Копирую файл xorg-cursor-`uname -r`.stacks.gz на свой компьютер, и делаю flamegraph в формате svg: zcat xorg-cursor-5.15.33-rpi-def-alt1.stacks.gz | stackcollapse-perf.pl | flamegraph.pl --title='5.15.33-rpi-def' > xorg-cursor-5.15.33-rpi-def-alt1.svg Заметил, что за одно и то же время (20 секунд) и при одной и той же частоте (997 Гц) сэмплирования на "плохом" ядре получаю на порядок меньше событий: # perf record -g --call-graph=dwarf,16384 -a -F 997 -- sleep 20 [ perf record: Woken up 41 times to write data ] [ perf record: Captured and wrote 12,079 MB perf.data (907 samples) ] # uname -r 5.15.33-rpi-def-alt1 а на "хорошем" ядре # perf record -g --call-graph=dwarf,16384 -a -F 997 -- sleep 20 [ perf record: Woken up 505 times to write data ] [ perf record: Captured and wrote 130,536 MB perf.data (9289 samples) ] # uname -r 5.15.25-rpi-def-alt1 Отсюда вывод: это какая-то взаимная блокировка, т.к. на "плохом" ядре все процессы/потоки тупо ждут чего-то
На ядре 5.15.28-rpi-un-alt1 проблема НЕ воспроизводится. Видно и невооружённым глазом, и в профайлере.
(Ответ для Alexey Sheplyakov на комментарий #5) > Общесистемный профайл получаю так: > > 1. Запускаю (в графическом интерфейсе) терминал и файловый менеджер, > располагаю окна рядом > 2. В UART консоли запускаю (от root) > > cd /tmp && perf record -g --call-graph=dwarf,16384 -a -F 997 -- sleep 20 > > Одновременно с этим в графическом интерфейсе вожу туда-сюда мышкой с > терминала на файловый менеджер (и обратно) в течение 20 секунд (столько > будет собирать информацию perf record) > > 3. Полученный perf.data обрабатываю командой: > > perf script --header | gzip -9 > xorg-cursor-`uname -r`.stacks.gz > > 4. Копирую файл xorg-cursor-`uname -r`.stacks.gz на свой компьютер, и делаю > flamegraph в формате svg: > > zcat xorg-cursor-5.15.33-rpi-def-alt1.stacks.gz | stackcollapse-perf.pl | > flamegraph.pl --title='5.15.33-rpi-def' > > xorg-cursor-5.15.33-rpi-def-alt1.svg > > Заметил, что за одно и то же время (20 секунд) и при одной и той же частоте > (997 Гц) сэмплирования на "плохом" ядре получаю на порядок меньше событий: > > # perf record -g --call-graph=dwarf,16384 -a -F 997 -- sleep 20 > [ perf record: Woken up 41 times to write data ] > [ perf record: Captured and wrote 12,079 MB perf.data (907 samples) ] > # uname -r > 5.15.33-rpi-def-alt1 > > а на "хорошем" ядре > > # perf record -g --call-graph=dwarf,16384 -a -F 997 -- sleep 20 > [ perf record: Woken up 505 times to write data ] > [ perf record: Captured and wrote 130,536 MB perf.data (9289 samples) ] > # uname -r > 5.15.25-rpi-def-alt1 > > Отсюда вывод: это какая-то взаимная блокировка, т.к. на "плохом" ядре все > процессы/потоки тупо ждут чего-то xf86ScreenSetCursor xf86SetCursor ... ProcessPointerEvent ... ProcessInputEvents Dispatch dix_main xf86ScreenSetCursor вызывает xf86DriverLoadCursorARGB и xf86_set_cursor_position. Обе эти функции в итоге вызывают drm_mode_cursor_universal (в ядре). Поскольку есть подозрение на взаимоблокировку, то измеряю распределение (точнее гистограмму) времени (физического, а не процессорного), потраченного на эту функцию. При взаимоблокировке ожидаю увидеть в распределении длинный "хвост". # /usr/share/bcc/tools/funclatency -p `pgrep X` -F 'drm_mode_cursor*' Tracing 4 functions for "drm_mode_cursor*"... Hit Ctrl-C to end. Function = b'drm_mode_cursor_universal' nsecs : count distribution 0 -> 1 : 0 | | 2 -> 3 : 0 | | 4 -> 7 : 0 | | 8 -> 15 : 0 | | 16 -> 31 : 0 | | 32 -> 63 : 0 | | 64 -> 127 : 0 | | 128 -> 255 : 0 | | 256 -> 511 : 0 | | 512 -> 1023 : 0 | | 1024 -> 2047 : 0 | | 2048 -> 4095 : 0 | | 4096 -> 8191 : 0 | | 8192 -> 16383 : 0 | | 16384 -> 32767 : 0 | | 32768 -> 65535 : 0 | | 65536 -> 131071 : 0 | | 131072 -> 262143 : 0 | | 262144 -> 524287 : 0 | | 524288 -> 1048575 : 0 | | 1048576 -> 2097151 : 0 | | 2097152 -> 4194303 : 0 | | 4194304 -> 8388607 : 0 | | 8388608 -> 16777215 : 1278 |****************************************| 16777216 -> 33554431 : 4 | | avg = 16577968 nsecs, total: 21518202826 nsecs, count: 1298 Никаких "длинных хвостов", всё детерминистично. Притом уж слишком детерминистично. Странно. Повторяю измерения на "хорошем" ядре, вижу /usr/share/bcc/tools/funclatency -p `pgrep X` -F 'drm_mode_cursor*' Tracing 4 functions for "drm_mode_cursor*"... Hit Ctrl-C to end. Function = b'drm_mode_cursor_universal' nsecs : count distribution 0 -> 1 : 0 | | 2 -> 3 : 0 | | 4 -> 7 : 0 | | 8 -> 15 : 0 | | 16 -> 31 : 0 | | 32 -> 63 : 0 | | 64 -> 127 : 0 | | 128 -> 255 : 0 | | 256 -> 511 : 0 | | 512 -> 1023 : 0 | | 1024 -> 2047 : 0 | | 2048 -> 4095 : 0 | | 4096 -> 8191 : 0 | | 8192 -> 16383 : 0 | | 16384 -> 32767 : 0 | | 32768 -> 65535 : 6 | | 65536 -> 131071 : 284 |*************** | 131072 -> 262143 : 745 |****************************************| 262144 -> 524287 : 24 |* | 524288 -> 1048575 : 5 | | 1048576 -> 2097151 : 7 | | avg = 170006 nsecs, total: 184457024 nsecs, count: 1085 Тут есть разброс, и среднее время (на один вызов) почти в 100 раз меньше. Это не похоже на взаимоблокировку. Это похоже на сериализацию. То есть, вместо того, чтобы забить на 2 слишком близких по времени события перемещения/отрисовки курсора, drm честно отрабатывает каждое событие одно за другим. С этой вводной легко находится подозреваемый: commit 575197eedf2aae854cb1ce14882e0b910a382737 Author: Daniel Vetter <daniel.vetter@ffwll.ch> Date: Fri Oct 23 14:39:23 2020 +0200 drm/atomic-helpers: remove legacy_cursor_update hacks The stuff never really worked, and leads to lots of fun because it out-of-order frees atomic states. Which upsets KASAN, among other things. For async updates we now have a more solid solution with the ->atomic_async_check and ->atomic_async_commit hooks. Support for that for msm and vc4 landed. nouveau and i915 have their own commit routines, doing something similar. For everyone else it's probably better to remove the use-after-free bug, and encourage folks to use the async support instead. The affected drivers which register a legacy cursor plane and don't either use the new async stuff or their own commit routine are: amdgpu, atmel, mediatek, qxl, rockchip, sti, sun4i, tegra, virtio, and vmwgfx. Inspired by an amdgpu bug report. v2: Drop RFC, I think with amdgpu converted over to use atomic_async_check/commit done in commit 674e78acae0dfb4beb56132e41cbae5b60f7d662 Author: Nicholas Kazlauskas <nicholas.kazlauskas@amd.com> Date: Wed Dec 5 14:59:07 2018 -0500 drm/amd/display: Add fast path for cursor plane updates we don't have any driver anymore where we have userspace expecting solid legacy cursor support _and_ they are using the atomic helpers in their fully glory. So we can retire this. v3: Paper over msm and i915 regression. The complete_all is the only thing missing afaict. v4: Rebased on recent kernel, added extra link for vc4 bug. Link: https://bugzilla.kernel.org/show_bug.cgi?id=199425 Link: https://lore.kernel.org/all/20220221134155.125447-9-maxime@cerno.tech/ Cc: mikita.lipski@amd.com Cc: Michel Dänzer <michel@daenzer.net> Cc: harry.wentland@amd.com Cc: Rob Clark <robdclark@gmail.com> Cc: "Kazlauskas, Nicholas" <nicholas.kazlauskas@amd.com> Tested-by: Maxime Ripard <maxime@cerno.tech> Signed-off-by: Daniel Vetter <daniel.vetter@intel.com> Signed-off-by: Maxime Ripard <maxime@cerno.tech> И действительно, отмена (revert) этого замечательного патча "оживляет" Xorg. P.S. Верующим в стабильные ядра - пламенный пролетарский привет!
(Ответ для Alexey Sheplyakov на комментарий #7) > (Ответ для Alexey Sheplyakov на комментарий #5) > > Общесистемный профайл получаю так: > > > > 1. Запускаю (в графическом интерфейсе) терминал и файловый менеджер, > > располагаю окна рядом > > 2. В UART консоли запускаю (от root) > > > > cd /tmp && perf record -g --call-graph=dwarf,16384 -a -F 997 -- sleep 20 > > > > Одновременно с этим в графическом интерфейсе вожу туда-сюда мышкой с > > терминала на файловый менеджер (и обратно) в течение 20 секунд (столько > > будет собирать информацию perf record) > > > > 3. Полученный perf.data обрабатываю командой: > > > > perf script --header | gzip -9 > xorg-cursor-`uname -r`.stacks.gz > > > > 4. Копирую файл xorg-cursor-`uname -r`.stacks.gz на свой компьютер, и делаю > > flamegraph в формате svg: > > > > zcat xorg-cursor-5.15.33-rpi-def-alt1.stacks.gz | stackcollapse-perf.pl | > > flamegraph.pl --title='5.15.33-rpi-def' > > > xorg-cursor-5.15.33-rpi-def-alt1.svg > > > > Заметил, что за одно и то же время (20 секунд) и при одной и той же частоте > > (997 Гц) сэмплирования на "плохом" ядре получаю на порядок меньше событий: > > > > # perf record -g --call-graph=dwarf,16384 -a -F 997 -- sleep 20 > > [ perf record: Woken up 41 times to write data ] > > [ perf record: Captured and wrote 12,079 MB perf.data (907 samples) ] > > # uname -r > > 5.15.33-rpi-def-alt1 > > > > а на "хорошем" ядре > > > > # perf record -g --call-graph=dwarf,16384 -a -F 997 -- sleep 20 > > [ perf record: Woken up 505 times to write data ] > > [ perf record: Captured and wrote 130,536 MB perf.data (9289 samples) ] > > # uname -r > > 5.15.25-rpi-def-alt1 > > > > Отсюда вывод: это какая-то взаимная блокировка, т.к. на "плохом" ядре все > > процессы/потоки тупо ждут чего-то > > xf86ScreenSetCursor > xf86SetCursor > ... > ProcessPointerEvent > ... > ProcessInputEvents > Dispatch > dix_main > > xf86ScreenSetCursor вызывает xf86DriverLoadCursorARGB и > xf86_set_cursor_position. Обе эти функции в итоге вызывают > drm_mode_cursor_universal (в ядре). > > Поскольку есть подозрение на взаимоблокировку, то измеряю распределение > (точнее гистограмму) времени (физического, а не процессорного), потраченного > на эту функцию. При взаимоблокировке ожидаю увидеть в распределении длинный > "хвост". > > # /usr/share/bcc/tools/funclatency -p `pgrep X` -F 'drm_mode_cursor*' > Tracing 4 functions for "drm_mode_cursor*"... Hit Ctrl-C to end. > > > Function = b'drm_mode_cursor_universal' > nsecs : count distribution > 0 -> 1 : 0 | | > 2 -> 3 : 0 | | > 4 -> 7 : 0 | | > 8 -> 15 : 0 | | > 16 -> 31 : 0 | | > 32 -> 63 : 0 | | > 64 -> 127 : 0 | | > 128 -> 255 : 0 | | > 256 -> 511 : 0 | | > 512 -> 1023 : 0 | | > 1024 -> 2047 : 0 | | > 2048 -> 4095 : 0 | | > 4096 -> 8191 : 0 | | > 8192 -> 16383 : 0 | | > 16384 -> 32767 : 0 | | > 32768 -> 65535 : 0 | | > 65536 -> 131071 : 0 | | > 131072 -> 262143 : 0 | | > 262144 -> 524287 : 0 | | > 524288 -> 1048575 : 0 | | > 1048576 -> 2097151 : 0 | | > 2097152 -> 4194303 : 0 | | > 4194304 -> 8388607 : 0 | | > 8388608 -> 16777215 : 1278 |****************************************| > 16777216 -> 33554431 : 4 | | > > avg = 16577968 nsecs, total: 21518202826 nsecs, count: 1298 > > Никаких "длинных хвостов", всё детерминистично. Притом уж слишком > детерминистично. Странно. А ничего странного: 1/16577968 нс = 60,32 Гц (с точностью до двух знаков после запятой). Что с хорошей точностью совпадает с частотой вертикальной развёртки (что бы это ни значило для ЖК мониторов). Всё как Ленин^W atomic update завещал. > Повторяю измерения на "хорошем" ядре, вижу > > > /usr/share/bcc/tools/funclatency -p `pgrep X` -F 'drm_mode_cursor*' > Tracing 4 functions for "drm_mode_cursor*"... Hit Ctrl-C to end. > > > Function = b'drm_mode_cursor_universal' > nsecs : count distribution > 0 -> 1 : 0 | | > 2 -> 3 : 0 | | > 4 -> 7 : 0 | | > 8 -> 15 : 0 | | > 16 -> 31 : 0 | | > 32 -> 63 : 0 | | > 64 -> 127 : 0 | | > 128 -> 255 : 0 | | > 256 -> 511 : 0 | | > 512 -> 1023 : 0 | | > 1024 -> 2047 : 0 | | > 2048 -> 4095 : 0 | | > 4096 -> 8191 : 0 | | > 8192 -> 16383 : 0 | | > 16384 -> 32767 : 0 | | > 32768 -> 65535 : 6 | | > 65536 -> 131071 : 284 |*************** | > 131072 -> 262143 : 745 |****************************************| > 262144 -> 524287 : 24 |* | > 524288 -> 1048575 : 5 | | > 1048576 -> 2097151 : 7 | | > > > avg = 170006 nsecs, total: 184457024 nsecs, count: 1085 > > Тут есть разброс, и среднее время (на один вызов) почти в 100 раз меньше. Да, потому что никто не пытается синхронизироваться по vsync. > Это не похоже на взаимоблокировку. Это похоже на сериализацию. Это и есть сериализация. Только ещё с ограничением скорости обработки. Так что ещё легче заподозрить: > С этой вводной легко находится подозреваемый: > > commit 575197eedf2aae854cb1ce14882e0b910a382737 > Author: Daniel Vetter <daniel.vetter@ffwll.ch> > Date: Fri Oct 23 14:39:23 2020 +0200 > > drm/atomic-helpers: remove legacy_cursor_update hacks > > The stuff never really worked, and leads to lots of fun because it > out-of-order frees atomic states. Which upsets KASAN, among other > things. > > For async updates we now have a more solid solution with the > ->atomic_async_check and ->atomic_async_commit hooks. Support for that > for msm and vc4 landed. nouveau and i915 have their own commit > routines, doing something similar. > > For everyone else it's probably better to remove the use-after-free > bug, and encourage folks to use the async support instead. The > affected drivers which register a legacy cursor plane and don't either > use the new async stuff or their own commit routine are: amdgpu, > atmel, mediatek, qxl, rockchip, sti, sun4i, tegra, virtio, and vmwgfx. > > Inspired by an amdgpu bug report. > > v2: Drop RFC, I think with amdgpu converted over to use > atomic_async_check/commit done in > > commit 674e78acae0dfb4beb56132e41cbae5b60f7d662 > Author: Nicholas Kazlauskas <nicholas.kazlauskas@amd.com> > Date: Wed Dec 5 14:59:07 2018 -0500 > > drm/amd/display: Add fast path for cursor plane updates > > we don't have any driver anymore where we have userspace expecting > solid legacy cursor support _and_ they are using the atomic helpers in > their fully glory. So we can retire this. > > v3: Paper over msm and i915 regression. The complete_all is the only > thing missing afaict. > > v4: Rebased on recent kernel, added extra link for vc4 bug. > > Link: https://bugzilla.kernel.org/show_bug.cgi?id=199425 > Link: > https://lore.kernel.org/all/20220221134155.125447-9-maxime@cerno.tech/ > Cc: mikita.lipski@amd.com > Cc: Michel Dänzer <michel@daenzer.net> > Cc: harry.wentland@amd.com > Cc: Rob Clark <robdclark@gmail.com> > Cc: "Kazlauskas, Nicholas" <nicholas.kazlauskas@amd.com> > Tested-by: Maxime Ripard <maxime@cerno.tech> > Signed-off-by: Daniel Vetter <daniel.vetter@intel.com> > Signed-off-by: Maxime Ripard <maxime@cerno.tech> > > > И действительно, отмена (revert) этого замечательного патча "оживляет" Xorg. > > P.S. Верующим в стабильные ядра - пламенный пролетарский привет!
Невооружённым глазом видны тормоза при быстром перемещении курсора или перетаскивании абсолютно любого окна. Тоже сразу заподозрил vsync. >И действительно, отмена (revert) этого замечательного патча "оживляет" Xorg. Ну два года с ним всё было хорошо, и вдруг всё сломалось? Мне кажется это странным. На std-def 5.15.37 и un-def 5.17.5 всё отлично, кстати. Ну и на rpi-un 5.17.1 тоже всё хорошо.
(In reply to Антон Мидюков from comment #9) > Невооружённым глазом видны тормоза при быстром перемещении курсора Нет, не видны. Да, это субъективное ощущение, поэтому нужно измерять (что и было сделано). > >И действительно, отмена (revert) этого замечательного патча "оживляет" Xorg. > > Ну два года с ним всё было хорошо, и вдруг всё сломалось? Откуда взялись "два года"? Это какой-то неизвестный мне мем? > Мне кажется это странным. Берёте ядро rpi-def-5.15.33-alt1, делаете git revert 575197eedf2aae854cb1ce14882e0b910a382737, пересобираете, загружаетесь, шевелите мышкой, измеряете. Если лениво пересобирать - можно взять уже собранное из задачи #299308 (для p10) > На std-def 5.15.37 и un-def 5.17.5 всё отлично, кстати. Нет там коммита "drm/atomic-helpers: remove legacy_cursor_update hacks", нет и проблемы. > Ну и на rpi-un 5.17.1 тоже всё хорошо. И тут его тоже нет. P.S. Говорят, когда кажется, надо перекреститься. Я пробовал - помогает.
(Ответ для Alexey Sheplyakov на комментарий #10) > (In reply to Антон Мидюков from comment #9) > > Невооружённым глазом видны тормоза при быстром перемещении курсора > > Нет, не видны. Да, это субъективное ощущение, поэтому нужно измерять (что и > было сделано). > > > > >И действительно, отмена (revert) этого замечательного патча "оживляет" Xorg. > > > > Ну два года с ним всё было хорошо, и вдруг всё сломалось? > > Откуда взялись "два года"? Это какой-то неизвестный мне мем? > Извиняюсь, смутила дата: > commit 575197eedf2aae854cb1ce14882e0b910a382737 > Author: Daniel Vetter <daniel.vetter@ffwll.ch> > Date: Fri Oct 23 14:39:23 2020 +0200
(In reply to Антон Мидюков from comment #11) > Извиняюсь, смутила дата: > > > commit 575197eedf2aae854cb1ce14882e0b910a382737 > > Author: Daniel Vetter <daniel.vetter@ffwll.ch> > > Date: Fri Oct 23 14:39:23 2020 +0200 Да, как я понял, Daniel отправлял его ещё 2 года назад, но в dri-devel@ его поругали. А в начале этого, 2022 года этот патч зачем-то забрали себе разработчки ядра rpi в свою 5.15.y При этом ни у Линуса, ни в одном из stable я этого патча не видел. Хотя возможно я смотреть не умею.
kernel-image-rpi-def-1:5.15.36-alt1 -> sisyphus: Thu May 05 2022 Alexey Sheplyakov <asheplyakov@altlinux> 1:5.15.36-alt1 - Updated to 5.15.36 - https://github.com/raspberrypi/linux.git rpi-5.15.y commit 9bc1ec59bd8db07e41067717aeea2749314ec801 - Restored legacy_cursor_update for Xorg (closes: #42604) Note: "legacy_cursor_update hack" has been removed by rpi-5.15.y commit 575197eedf2aae854cb1ce14882e0b910a382737
