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

[Takashi Iwai <tiwai@suse.de>]

On Tue, 30 Apr 2024 12:54:36 +0200,
Mikhail Gavrilov wrote:
> 
> 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"

Where and how...?  That important piece is missing in you info...
And, it's likely a false-positive detection by lockdep.

When you disable lockdep, does it still show any performance down?


Takashi

> 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.
> 
>