Re: regression/bisected/6.9 commit 587d67fd929ad89801bcc429675bda90d53f6592 decrease 30% of gaming performance

[Mikhail Gavrilov <mikhail.v.gavrilov@gmail.com>]

[-- Attachment #1: Type: text/plain, Size: 3350 bytes --]

On Tue, Apr 30, 2024 at 10:50 AM Takashi Iwai <tiwai@suse.de> wrote:
>
> It implies that it's not about the revert that influences on the
> result.  It might be rather the fact that you built the kernel by
> yourself.  Try to build the kernel again with a debug print but
> without the revert of the spinlock.

It was built without reverting the spinlock.
With revert in the kernel log appears "WARNING: possible irq lock
inversion dependency detected"
I suppose commit 587d67fd929a fixes just this.
About calls of snd_timer_close_locked, I again see only 3 invokes when
the system booted:
[Tue Apr 30 15:09:40 2024] igc 0000:0a:00.0 eno1: NIC Link is Up 1000
Mbps Full Duplex, Flow Control: RX/TX
[Tue Apr 30 15:09:42 2024] input: Denon PerL Pro 772 (AVRCP) as
/devices/virtual/input/input18
[Tue Apr 30 15:09:45 2024] rfkill: input handler disabled
[Tue Apr 30 15:09:49 2024] Bluetooth: RFCOMM TTY layer initialized
[Tue Apr 30 15:09:49 2024] Bluetooth: RFCOMM socket layer initialized
[Tue Apr 30 15:09:49 2024] Bluetooth: RFCOMM ver 1.11
[Tue Apr 30 15:09:49 2024] DEBUG: Passed snd_timer_close_locked 410
[Tue Apr 30 15:09:51 2024] systemd-journald[947]:
/var/log/journal/1b6a399fb0874de8b095a739fe2ff323/user-1000.journal:
Journal file uses a different sequence number ID, rotating.
[Tue Apr 30 15:09:52 2024] rfkill: input handler enabled
[Tue Apr 30 15:09:55 2024] DEBUG: Passed snd_timer_close_locked 410
[Tue Apr 30 15:09:55 2024] rfkill: input handler disabled
[Tue Apr 30 15:09:55 2024] input: Denon PerL Pro 772 (AVRCP) as
/devices/virtual/input/input19
[Tue Apr 30 15:09:57 2024] input: solaar-keyboard as
/devices/virtual/input/input20
[Tue Apr 30 15:10:08 2024] DEBUG: Passed snd_timer_close_locked 410
[Tue Apr 30 15:10:23 2024] show_signal_msg: 8 callbacks suppressed
[Tue Apr 30 15:10:23 2024] gldriverquery[4423]: segfault at 0 ip
0000000000000000 sp 00007fff2ee18c38 error 14 in
gldriverquery[55c135c00000+14000] likely on CPU 11 (core 11, socket 0)
[Tue Apr 30 15:10:23 2024] Code: Unable to access opcode bytes at
0xffffffffffffffd6.
[Tue Apr 30 15:10:40 2024] workqueue: gc_worker [nf_conntrack] hogged
CPU for >10000us 7 times, consider switching to WQ_UNBOUND
[Tue Apr 30 15:10:40 2024] workqueue: gc_worker [nf_conntrack] hogged
CPU for >10000us 11 times, consider switching to WQ_UNBOUND

And no invokes during benchmark.
root@primary-ws ~# cat /sys/kernel/tracing/trace
# tracer: function
#
# entries-in-buffer/entries-written: 0/0   #P:32
#
#                                _-----=> irqs-off/BH-disabled
#                               / _----=> need-resched
#                              | / _---=> hardirq/softirq
#                              || / _--=> preempt-depth
#                              ||| / _-=> migrate-disable
#                              |||| /     delay
#           TASK-PID     CPU#  |||||  TIMESTAMP  FUNCTION
#              | |         |   |||||     |         |

I attached here two kernel logs both with printk debug. One is clean
6.9.0-rc6 the other 6.9.0-rc6 with revert 587d67fd929a.
I didn't see any difference between kernel logs.
I only see that without 587d67fd929a at some point a possible irq lock
inversion dependency is detected and the benchmark improves results up
to 30%.

-- 
Best Regards,
Mike Gavrilov.

[-- Attachment #2: dmesg-test-build.zip --]
[-- Type: application/zip, Size: 50305 bytes --]

[-- Attachment #3: dmesg-test-build-revert-587d67fd929a.zip --]
[-- Type: application/zip, Size: 53154 bytes --]