Re: [PATCH 5/5] genirq: Use the maple tree for IRQ descriptors management

From: kernel test robot
Date: Wed Feb 01 2023 - 01:12:24 EST



Greeting,

FYI, we noticed WARNING:at_kernel/locking/lockdep.c:#lockdep_hardirqs_on_prepare due to commit (built with gcc-11):

commit: 02fb8013ee5f9b7d7bc35d54bf8bc5fe1179970c ("[PATCH 5/5] genirq: Use the maple tree for IRQ descriptors management")
url: https://github.com/intel-lab-lkp/linux/commits/Shanker-Donthineni/genirq-Use-hlist-for-managing-resend-handlers/20230130-085956
base: https://git.kernel.org/cgit/linux/kernel/git/tip/tip.git 188a569658584e93930ab60334c5a1079c0330d8
patch link: https://lore.kernel.org/all/20230130005725.3517597-6-sdonthineni@xxxxxxxxxx/
patch subject: [PATCH 5/5] genirq: Use the maple tree for IRQ descriptors management

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):


If you fix the issue, kindly add following tag
| Reported-by: kernel test robot <oliver.sang@xxxxxxxxx>
| Link: https://lore.kernel.org/oe-lkp/202302011308.f53123d2-oliver.sang@xxxxxxxxx


[ 2.214554][ T0] ------------[ cut here ]------------
[ 2.215401][ T0] DEBUG_LOCKS_WARN_ON(early_boot_irqs_disabled)
[ 2.215446][ T0] WARNING: CPU: 0 PID: 0 at kernel/locking/lockdep.c:4308 lockdep_hardirqs_on_prepare+0x2d4/0x350
[ 2.217975][ T0] Modules linked in:
[ 2.218526][ T0] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 6.2.0-rc3-00015-g02fb8013ee5f #1
[ 2.219803][ T0] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.16.0-debian-1.16.0-5 04/01/2014
[ 2.221228][ T0] RIP: 0010:lockdep_hardirqs_on_prepare+0x2d4/0x350
[ 2.222207][ T0] Code: 11 38 d0 7c 04 84 d2 75 5e 8b 0d bf 8b f7 03 85 c9 0f 85 c9 fe ff ff 48 c7 c6 40 7d a9 83 48 c7 c7 60 4e a9 83 e8 60 7c 35 02 <0f> 0b e9 af fe ff ff e8 50 8d 62 00 e9 0c fe ff ff e8 e6 8d 62 00
[ 2.224923][ T0] RSP: 0000:ffffffff844075a0 EFLAGS: 00010082
[ 2.225792][ T0] RAX: 0000000000000000 RBX: 0000000000000003 RCX: 0000000000000000
[ 2.226889][ T0] RDX: 0000000000000000 RSI: 0000000000000000 RDI: fffffbfff0880ea6
[ 2.227955][ T0] RBP: ffff8883af23fac0 R08: 0000000000000000 R09: ffffffff844072df
[ 2.229068][ T0] R10: fffffbfff0880e5b R11: 0000000000000001 R12: 0000000000000002
[ 2.230147][ T0] R13: 0000000000000002 R14: ffff88810022b018 R15: ffff88810022b010
[ 2.231269][ T0] FS: 0000000000000000(0000) GS:ffff8883af200000(0000) knlGS:0000000000000000
[ 2.232522][ T0] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 2.233395][ T0] CR2: ffff88843ffff000 CR3: 000000000442a000 CR4: 00000000000406b0
[ 2.234504][ T0] Call Trace:
[ 2.234941][ T0] <TASK>
[ 2.235345][ T0] trace_hardirqs_on+0x40/0x140
[ 2.236029][ T0] __kmem_cache_alloc_bulk+0x22e/0x490
[ 2.236795][ T0] ? kasan_set_track+0x25/0x30
[ 2.237470][ T0] kmem_cache_alloc_bulk+0x159/0x2e0
[ 2.238225][ T0] mas_alloc_nodes+0x253/0x690
[ 2.238886][ T0] mas_split+0x30d/0x1580
[ 2.239561][ T0] ? mas_push_data+0x1a40/0x1a40
[ 2.240219][ T0] ? memset+0x24/0x50
[ 2.240782][ T0] ? blake2s_final+0x110/0x140
[ 2.241426][ T0] ? blake2s+0x115/0x150
[ 2.242143][ T0] ? wait_for_random_bytes+0xd0/0xd0
[ 2.242859][ T0] ? mas_mab_cp+0x2f6/0x890
[ 2.243527][ T0] ? memset+0x24/0x50
[ 2.244122][ T0] ? find_held_lock+0x2c/0x110
[ 2.244803][ T0] ? mas_store_b_node+0x54c/0x1180
[ 2.245510][ T0] ? rcu_read_lock_sched_held+0x16/0x80
[ 2.246282][ T0] mas_wr_bnode+0x14f/0x1d0
[ 2.246902][ T0] ? mas_commit_b_node+0x600/0x600
[ 2.247677][ T0] ? secondary_startup_64_no_verify+0xe0/0xeb
[ 2.248567][ T0] ? ___slab_alloc+0x70b/0xe00
[ 2.249251][ T0] ? mas_wr_store_entry+0x2e9/0xe30
[ 2.250088][ T0] ? rcu_read_lock_sched_held+0x16/0x80
[ 2.250864][ T0] mas_store_gfp+0xc2/0x190
[ 2.251516][ T0] ? mtree_erase+0x100/0x100
[ 2.252190][ T0] ? lockdep_init_map_type+0x2c7/0x780
[ 2.252924][ T0] irq_insert_desc+0xac/0xf0
[ 2.253562][ T0] ? irq_kobj_release+0x100/0x100
[ 2.254243][ T0] early_irq_init+0x81/0x8c
[ 2.254866][ T0] start_kernel+0x1c7/0x3a4
[ 2.255479][ T0] secondary_startup_64_no_verify+0xe0/0xeb
[ 2.256408][ T0] </TASK>
[ 2.256802][ T0] irq event stamp: 0
[ 2.257268][ T0] hardirqs last enabled at (0): [<0000000000000000>] 0x0
[ 2.258177][ T0] hardirqs last disabled at (0): [<0000000000000000>] 0x0
[ 2.259116][ T0] softirqs last enabled at (0): [<0000000000000000>] 0x0
[ 2.260044][ T0] softirqs last disabled at (0): [<0000000000000000>] 0x0
[ 2.260979][ T0] ---[ end trace 0000000000000000 ]---
[ 2.262190][ T0] rcu: srcu_init: Setting srcu_struct sizes based on contention.
[ 2.263441][ T0] ------------[ cut here ]------------
[ 2.264180][ T0] Interrupts were enabled early
[ 2.264809][ T0] WARNING: CPU: 0 PID: 0 at init/main.c:1065 start_kernel+0x239/0x3a4
[ 2.265872][ T0] Modules linked in:
[ 2.266391][ T0] CPU: 0 PID: 0 Comm: swapper/0 Tainted: G W 6.2.0-rc3-00015-g02fb8013ee5f #1
[ 2.267721][ T0] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.16.0-debian-1.16.0-5 04/01/2014
[ 2.270166][ T0] RIP: 0010:start_kernel+0x239/0x3a4
[ 2.270938][ T0] Code: 48 89 05 f6 11 58 7a e8 b9 04 06 00 e8 f4 d2 d1 fd e8 40 75 05 00 9c 58 0f ba e0 09 73 0e 48 c7 c7 60 0e a0 83 e8 af bf bf
fd <0f> 0b c6 05 2a 12 81 ff 00 e8 ad 96 ad fb fb e8 58 07 07 00 e8 49
[ 2.273782][ T0] RSP: 0000:ffffffff84407f38 EFLAGS: 00010286
[ 2.274637][ T0] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000000
[ 2.275771][ T0] RDX: 0000000000000000 RSI: 0000000000000000 RDI: fffffbfff0880fd9
[ 2.276858][ T0] RBP: 0000000000000000 R08: 0000000000000000 R09: ffffffff84407c77
[ 2.277994][ T0] R10: fffffbfff0880f8e R11: 0000000000000001 R12: 0000000000000000
[ 2.279079][ T0] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000
[ 2.280185][ T0] FS: 0000000000000000(0000) GS:ffff8883af200000(0000) knlGS:0000000000000000
[ 2.281474][ T0] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 2.282441][ T0] CR2: ffff88843ffff000 CR3: 000000000442a000 CR4: 00000000000406b0
[ 2.283519][ T0] Call Trace:
[ 2.283930][ T0] <TASK>
[ 2.284328][ T0] secondary_startup_64_no_verify+0xe0/0xeb
[ 2.285143][ T0] </TASK>
[ 2.285517][ T0] irq event stamp: 0
[ 2.286011][ T0] hardirqs last enabled at (0): [<0000000000000000>] 0x0
[ 2.286946][ T0] hardirqs last disabled at (0): [<0000000000000000>] 0x0
[ 2.287873][ T0] softirqs last enabled at (0): [<0000000000000000>] 0x0
[ 2.288797][ T0] softirqs last disabled at (0): [<0000000000000000>] 0x0
[ 2.289618][ T0] ---[ end trace 0000000000000000 ]---


To reproduce:



git clone https://github.com/intel/lkp-tests.git
cd lkp-tests
bin/lkp qemu -k <bzImage> -m modules.cgz 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.



--
0-DAY CI Kernel Test Service
https://github.com/intel/lkp-tests


#!/bin/sh

export_top_env()
{
export suite='boot'
export testcase='boot'
export category='functional'
export timeout='10m'
export job_origin='boot.yaml'
export queue_cmdline_keys='branch
commit
kbuild_queue_analysis'
export queue='validate'
export testbox='vm-snb'
export tbox_group='vm-snb'
export branch='linux-review/Shanker-Donthineni/genirq-Use-hlist-for-managing-resend-handlers/20230130-085956'
export commit='02fb8013ee5f9b7d7bc35d54bf8bc5fe1179970c'
export kconfig='x86_64-rhel-8.3-kselftests'
export repeat_to=6
export nr_vm=300
export submit_id='63d9bd1880dd2ecb4e91ed89'
export job_file='/lkp/jobs/scheduled/vm-meta-29/boot-1-yocto-x86_64-minimal-20190520.cgz-02fb8013ee5f9b7d7bc35d54bf8bc5fe1179970c-20230201-52046-1foxqlm-4.yaml'
export id='44d34cde8a1698b43937f2dbf1af484adf8126ad'
export queuer_version='/zday/lkp'
export model='qemu-system-x86_64 -enable-kvm -cpu SandyBridge'
export nr_cpu=2
export memory='16G'
export need_kconfig=\{\"KVM_GUEST\"\=\>\"y\"\}
export ssh_base_port=23032
export kernel_cmdline='vmalloc=256M initramfs_async=0 page_owner=on'
export rootfs='yocto-x86_64-minimal-20190520.cgz'
export compiler='gcc-11'
export enqueue_time='2023-02-01 09:15:04 +0800'
export _id='63d9bd2f80dd2ecb4e91ed8a'
export _rt='/result/boot/1/vm-snb/yocto-x86_64-minimal-20190520.cgz/x86_64-rhel-8.3-kselftests/gcc-11/02fb8013ee5f9b7d7bc35d54bf8bc5fe1179970c'
export user='lkp'
export LKP_SERVER='internal-lkp-server'
export result_root='/result/boot/1/vm-snb/yocto-x86_64-minimal-20190520.cgz/x86_64-rhel-8.3-kselftests/gcc-11/02fb8013ee5f9b7d7bc35d54bf8bc5fe1179970c/3'
export scheduler_version='/lkp/lkp/.src-20230120-005037'
export arch='x86_64'
export max_uptime=600
export initrd='/osimage/yocto/yocto-x86_64-minimal-20190520.cgz'
export bootloader_append='root=/dev/ram0
RESULT_ROOT=/result/boot/1/vm-snb/yocto-x86_64-minimal-20190520.cgz/x86_64-rhel-8.3-kselftests/gcc-11/02fb8013ee5f9b7d7bc35d54bf8bc5fe1179970c/3
BOOT_IMAGE=/pkg/linux/x86_64-rhel-8.3-kselftests/gcc-11/02fb8013ee5f9b7d7bc35d54bf8bc5fe1179970c/vmlinuz-6.2.0-rc3-00015-g02fb8013ee5f
branch=linux-review/Shanker-Donthineni/genirq-Use-hlist-for-managing-resend-handlers/20230130-085956
job=/lkp/jobs/scheduled/vm-meta-29/boot-1-yocto-x86_64-minimal-20190520.cgz-02fb8013ee5f9b7d7bc35d54bf8bc5fe1179970c-20230201-52046-1foxqlm-4.yaml
user=lkp
ARCH=x86_64
kconfig=x86_64-rhel-8.3-kselftests
commit=02fb8013ee5f9b7d7bc35d54bf8bc5fe1179970c
vmalloc=256M initramfs_async=0 page_owner=on
initcall_debug
nmi_watchdog=0
max_uptime=600
LKP_SERVER=internal-lkp-server
selinux=0
debug
apic=debug
sysrq_always_enabled
rcupdate.rcu_cpu_stall_timeout=100
net.ifnames=0
printk.devkmsg=on
panic=-1
softlockup_panic=1
nmi_watchdog=panic
oops=panic
load_ramdisk=2
prompt_ramdisk=0
drbd.minor_count=8
systemd.log_level=err
ignore_loglevel
console=tty0
earlyprintk=ttyS0,115200
console=ttyS0,115200
vga=normal
rw'
export modules_initrd='/pkg/linux/x86_64-rhel-8.3-kselftests/gcc-11/02fb8013ee5f9b7d7bc35d54bf8bc5fe1179970c/modules.cgz'
export lkp_initrd='/osimage/user/lkp/lkp-x86_64.cgz'
export site='lkp-wsx01'
export LKP_CGI_PORT=80
export LKP_CIFS_PORT=139
export schedule_notify_address=
export stop_repeat_if_found='dmesg.WARNING:at_kernel/locking/lockdep.c:#lockdep_hardirqs_on_prepare'
export kbuild_queue_analysis=1
export meta_host='vm-meta-29'
export kernel='/pkg/linux/x86_64-rhel-8.3-kselftests/gcc-11/02fb8013ee5f9b7d7bc35d54bf8bc5fe1179970c/vmlinuz-6.2.0-rc3-00015-g02fb8013ee5f'
export dequeue_time='2023-02-01 09:15:39 +0800'
export job_initrd='/lkp/jobs/scheduled/vm-meta-29/boot-1-yocto-x86_64-minimal-20190520.cgz-02fb8013ee5f9b7d7bc35d54bf8bc5fe1179970c-20230201-52046-1foxqlm-4.cgz'

[ -n "$LKP_SRC" ] ||
export LKP_SRC=/lkp/${user:-lkp}/src
}

run_job()
{
echo $$ > $TMP/run-job.pid

. $LKP_SRC/lib/http.sh
. $LKP_SRC/lib/job.sh
. $LKP_SRC/lib/env.sh

export_top_env

run_monitor $LKP_SRC/monitors/one-shot/wrapper boot-slabinfo
run_monitor $LKP_SRC/monitors/one-shot/wrapper boot-meminfo
run_monitor $LKP_SRC/monitors/one-shot/wrapper memmap
run_monitor $LKP_SRC/monitors/no-stdout/wrapper boot-time
run_monitor $LKP_SRC/monitors/wrapper kmsg
run_monitor $LKP_SRC/monitors/wrapper heartbeat
run_monitor $LKP_SRC/monitors/wrapper meminfo
run_monitor $LKP_SRC/monitors/wrapper oom-killer
run_monitor $LKP_SRC/monitors/plain/watchdog

run_test $LKP_SRC/tests/wrapper sleep 1
}

extract_stats()
{
export stats_part_begin=
export stats_part_end=

$LKP_SRC/stats/wrapper boot-slabinfo
$LKP_SRC/stats/wrapper boot-meminfo
$LKP_SRC/stats/wrapper memmap
$LKP_SRC/stats/wrapper boot-memory
$LKP_SRC/stats/wrapper boot-time
$LKP_SRC/stats/wrapper kernel-size
$LKP_SRC/stats/wrapper kmsg
$LKP_SRC/stats/wrapper sleep
$LKP_SRC/stats/wrapper meminfo

$LKP_SRC/stats/wrapper time sleep.time
$LKP_SRC/stats/wrapper dmesg
$LKP_SRC/stats/wrapper kmsg
$LKP_SRC/stats/wrapper last_state
$LKP_SRC/stats/wrapper stderr
$LKP_SRC/stats/wrapper time
}

"$@"

Attachment: dmesg.xz
Description: application/xz