From: Menglong Dong <[email protected]>
While the system is running in KVM, pci config writing for virtio devices
may cost long time (about 1-2ms), as it causes VM-exit. During
__pci_bus_assign_resources(), pci_setup_bridge(), which can write pci
config up to 10 times, can be called many times without any
cond_resched(). So __pci_bus_assign_resources() can cause 25+ms
scheduling latency with !CONFIG_PREEMPT.
To solve this problem, call cond_resched() after pci config writing.
Signed-off-by: Menglong Dong <[email protected]>
---
v2:
- use cond_resched() instead of _cond_resched()
---
drivers/pci/access.c | 1 +
1 file changed, 1 insertion(+)
diff --git a/drivers/pci/access.c b/drivers/pci/access.c
index 46935695cfb9..4c52a50f2c46 100644
--- a/drivers/pci/access.c
+++ b/drivers/pci/access.c
@@ -57,6 +57,7 @@ int noinline pci_bus_write_config_##size \
pci_lock_config(flags); \
res = bus->ops->write(bus, devfn, pos, len, value); \
pci_unlock_config(flags); \
+ cond_resched(); \
return res; \
}
--
2.27.0
On Fri, Oct 15, 2021 at 10:40:25AM +0800, [email protected] wrote:
> From: Menglong Dong <[email protected]>
>
> While the system is running in KVM, pci config writing for virtio devices
> may cost long time (about 1-2ms), as it causes VM-exit. During
> __pci_bus_assign_resources(), pci_setup_bridge(), which can write pci
> config up to 10 times, can be called many times without any
> cond_resched(). So __pci_bus_assign_resources() can cause 25+ms
> scheduling latency with !CONFIG_PREEMPT.
>
> To solve this problem, call cond_resched() after pci config writing.
See https://lore.kernel.org/r/20211013190014.GA1909934@bhelgaas
for comments about subject line, s/pci/PCI/, line length, etc.
> Signed-off-by: Menglong Dong <[email protected]>
> ---
> v2:
> - use cond_resched() instead of _cond_resched()
> ---
> drivers/pci/access.c | 1 +
> 1 file changed, 1 insertion(+)
>
> diff --git a/drivers/pci/access.c b/drivers/pci/access.c
> index 46935695cfb9..4c52a50f2c46 100644
> --- a/drivers/pci/access.c
> +++ b/drivers/pci/access.c
> @@ -57,6 +57,7 @@ int noinline pci_bus_write_config_##size \
> pci_lock_config(flags); \
> res = bus->ops->write(bus, devfn, pos, len, value); \
> pci_unlock_config(flags); \
> + cond_resched(); \
> return res; \
> }
>
> --
> 2.27.0
>
Greeting,
FYI, we noticed the following commit (built with gcc-9):
commit: 6239f32478b26c16e2a98f99519f971013f85a32 ("[PATCH v2] pci: call cond_resched() after pci bus config writing")
url: https://github.com/0day-ci/linux/commits/menglong8-dong-gmail-com/pci-call-cond_resched-after-pci-bus-config-writing/20211015-104121
base: https://git.kernel.org/cgit/linux/kernel/git/helgaas/pci.git next
in testcase: boot
on test machine: qemu-system-x86_64 -enable-kvm -cpu SandyBridge -smp 2 -m 16G
caused below changes (please refer to attached dmesg/kmsg for entire log/backtrace):
+---------------------------------------------------------------------------+------------+------------+
| | d53c18bef9 | 6239f32478 |
+---------------------------------------------------------------------------+------------+------------+
| boot_successes | 6 | 0 |
| boot_failures | 0 | 7 |
| BUG:sleeping_function_called_from_invalid_context_at_drivers/pci/access.c | 0 | 7 |
+---------------------------------------------------------------------------+------------+------------+
If you fix the issue, kindly add following tag
Reported-by: kernel test robot <[email protected]>
[ 17.382175][ T258] BUG: sleeping function called from invalid context at drivers/pci/access.c:68
[ 17.383077][ T258] in_atomic(): 1, irqs_disabled(): 1, non_block: 0, pid: 258, name: scsi_eh_0
[ 17.383901][ T258] 2 locks held by scsi_eh_0/258:
[ 17.384375][ T258] #0: ffff88813e18a0e0 (&host->eh_mutex){+.+.}-{3:3}, at: ata_eh_acquire+0x16/0x50
[ 17.385253][ T258] #1: ffffffff842f5b18 (piix_lock){....}-{2:2}, at: piix_set_timings+0x8c/0x2d0
[ 17.385450][ T258] irq event stamp: 74
[ 17.385450][ T258] hardirqs last enabled at (73): [<ffffffff827b8802>] _raw_spin_unlock_irqrestore+0x42/0x50
[ 17.385450][ T258] hardirqs last disabled at (74): [<ffffffff827b860b>] _raw_spin_lock_irqsave+0x4b/0x50
[ 17.385450][ T258] softirqs last enabled at (50): [<ffffffff82a002f9>] __do_softirq+0x2f9/0x48a
[ 17.385450][ T258] softirqs last disabled at (31): [<ffffffff81169b2e>] irq_exit_rcu+0x8e/0xb0
[ 17.385450][ T258] CPU: 1 PID: 258 Comm: scsi_eh_0 Not tainted 5.15.0-rc2-00083-g6239f32478b2 #1
[ 17.385450][ T258] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.12.0-1 04/01/2014
[ 17.385450][ T258] Call Trace:
[ 17.385450][ T258] dump_stack_lvl+0x57/0x7d
[ 17.385450][ T258] ___might_sleep.cold+0xa6/0xb8
[ 17.385450][ T258] pci_bus_write_config_word+0x3c/0x50
[ 17.385450][ T258] piix_set_timings+0x105/0x2d0
[ 17.385450][ T258] ? lockdep_hardirqs_on_prepare+0xd4/0x180
[ 17.385450][ T258] ata_eh_reset+0x14d/0xd10
[ 17.385450][ T258] ? piix_set_piomode+0x20/0x20
[ 17.385450][ T258] ? ata_sff_dev_classify+0x100/0x100
[ 17.385450][ T258] ? sata_sff_hardreset+0x70/0x70
[ 17.385450][ T258] ? ata_eh_schedule_probe+0x10e/0x1e0
[ 17.385450][ T258] ? ata_sff_dev_classify+0x100/0x100
[ 17.385450][ T258] ? sata_sff_hardreset+0x70/0x70
[ 17.385450][ T258] ata_eh_recover+0x48e/0x1290
[ 17.385450][ T258] ? piix_set_piomode+0x20/0x20
[ 17.385450][ T258] ? ata_sff_dev_classify+0x100/0x100
[ 17.385450][ T258] ? sata_sff_hardreset+0x70/0x70
[ 17.385450][ T258] ? ata_sff_softreset+0x180/0x180
[ 17.385450][ T258] ? sata_sff_hardreset+0x70/0x70
[ 17.385450][ T258] ? piix_set_piomode+0x20/0x20
[ 17.385450][ T258] ? ata_sff_dev_classify+0x100/0x100
[ 17.385450][ T258] ata_do_eh+0x3b/0xa0
[ 17.385450][ T258] ata_scsi_port_error_handler+0x36c/0x7d0
[ 17.385450][ T258] ? lockdep_hardirqs_on_prepare+0xd4/0x180
[ 17.385450][ T258] ? _raw_spin_unlock_irqrestore+0x42/0x50
[ 17.385450][ T258] ? scsi_error_handler+0x35/0x540
[ 17.385450][ T258] ata_scsi_error+0x8e/0xb0
[ 17.385450][ T258] scsi_error_handler+0xc6/0x540
[ 17.385450][ T258] ? lockdep_hardirqs_on_prepare+0xd4/0x180
[ 17.385450][ T258] ? _raw_spin_unlock_irqrestore+0x42/0x50
[ 17.385450][ T258] ? scsi_eh_get_sense+0x240/0x240
[ 17.385450][ T258] kthread+0x12e/0x150
[ 17.385450][ T258] ? set_kthread_struct+0x40/0x40
[ 17.385450][ T258] ret_from_fork+0x22/0x30
To reproduce:
# build kernel
cd linux
cp config-5.15.0-rc2-00083-g6239f32478b2 .config
make HOSTCC=gcc-9 CC=gcc-9 ARCH=x86_64 olddefconfig prepare modules_prepare bzImage
git clone https://github.com/intel/lkp-tests.git
cd lkp-tests
bin/lkp qemu -k <bzImage> job-script # job-script is attached in this email
# if come across any failure that blocks the test,
# please remove ~/.lkp and /lkp dir to run from a clean state.
---
0DAY/LKP+ Test Infrastructure Open Source Technology Center
https://lists.01.org/hyperkitty/list/[email protected] Intel Corporation
Thanks,
Oliver Sang