Received-SPF: pass (google.com: domain of linux-kernel+bounces-163902-linux.lists.archive=gmail.com@vger.kernel.org designates 147.75.80.249 as permitted sender) client-ip=147.75.80.249;
Date: Tue, 30 Apr 2024 14:12:23 +0200
Message-ID: <87r0enm4m0.wl-tiwai@suse.de>
From: Takashi Iwai <tiwai@suse.de>
To: Mikhail Gavrilov <mikhail.v.gavrilov@gmail.com>
Cc: Takashi Iwai <tiwai@suse.de>,
	Linux List Kernel Mailing <linux-kernel@vger.kernel.org>,
	linux-sound@vger.kernel.org
Subject: Re: regression/bisected/6.9 commit 587d67fd929ad89801bcc429675bda90d53f6592 decrease 30% of gaming performance
In-Reply-To: <CABXGCsMPLWm8xVZ3mk-e8FJht4FjdxEREov0DFKMooMD0BvRyw@mail.gmail.com>
References: <CABXGCsNmEtrN9DK-XmESaPm_1xpXm8A+juE+44Jf6AK5JE0+TQ@mail.gmail.com>
	<874jcl7e83.wl-tiwai@suse.de>
	<CABXGCsMmRFW3EYJ3UvNd-LO7ZTOyoNqjc_3OAmaCDSL=LuxJqg@mail.gmail.com>
	<87v851e2di.wl-tiwai@suse.de>
	<CABXGCsNMBRUaY-V8mhUQKdq+CQW5+eGUWL_YCJWXo0cgh9bGJQ@mail.gmail.com>
	<87h6glt9zc.wl-tiwai@suse.de>
	<CABXGCsMcazRvmiN4XtiHQCE9=dB=M=VsRqB=v+RPmtuhBL29DA@mail.gmail.com>
	<a6f4e20ea2a68f56a7d2c4d76280bca44d6bf421.camel@gmail.com>
	<CABXGCsPdqfXeZUw1ocx8O3NdOEb+h4yQ77+zdNpcwP_4JrYXuQ@mail.gmail.com>
	<CABXGCsMTbmU4CP8CHUqRVXWkGiErFtEVG4COy6RSRWsAuK_-CQ@mail.gmail.com>
	<87pluedgx5.wl-tiwai@suse.de>
	<87jzkmdghh.wl-tiwai@suse.de>
	<CABXGCsP-e5CjqCFztiym=zjQ=Z00uxYcQPFACEbTwjV=BHEdJQ@mail.gmail.com>
	<87jzkfo0ty.wl-tiwai@suse.de>
	<CABXGCsMPLWm8xVZ3mk-e8FJht4FjdxEREov0DFKMooMD0BvRyw@mail.gmail.com>
User-Agent: Wanderlust/2.15.9 (Almost Unreal) Emacs/27.2 Mule/6.0
Precedence: bulk
MIME-Version: 1.0 (generated by SEMI-EPG 1.14.7 - "Harue")
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 8bit

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