Deadlock warning on x86 machine while testing selftests: bpf: test_progs and running linux next 4.18.0-rc3-next-20180705 and still happening on 4.18.0-rc5-next-20180720.
Any one noticed this kernel warning about deadlock ?
selftests: bpf: test_progs libbpf: incorrect bpf_call opcode libbpf: incorrect bpf_call opcode test_pkt_access:FAIL:ipv4 err 0 errno 2 retval 0 duration 126 test_pkt_access:FAIL:ipv6 err 0 errno 2 retval 0 duration 115 test_xdp:FAIL:ipv4 err 0 errno 2 retval 3 size 74 test_xdp:FAIL:ipv6 err 0 errno 2 retval 3 size 114 test_xdp_adjust_tail:FAIL:ipv4 err 0 errno 2 retval 1 size 54 test_xdp_adjust_tail:FAIL:ipv6 err 0 errno 2 retval 3 siz[ 69.901655] [ 69.903862] ======================================================== [ 69.910213] WARNING: possible irq lock inversion dependency detected [ 69.916559] 4.18.0-rc3-next-20180705 #1 Not tainted [ 69.921428] -------------------------------------------------------- [ 69.927774] dd/2928 just changed the state of lock: [ 69.932643] 0000000022eeb38d (&head->lock){+...}, at: pcpu_freelist_push+0x28/0x50 [ 69.940208] but this lock was taken by another, HARDIRQ-safe lock in the past: [ 69.947420] (&rq->lock){-.-.} [ 69.947421] [ 69.947421] [ 69.947421] and interrupts could create inverse lock ordering between them. [ 69.947421] [ 69.961842] [ 69.961842] other info that might help us debug this: [ 69.968357] Possible interrupt unsafe locking scenario: [ 69.968357] [ 69.975136] CPU0 CPU1 [ 69.979659] ---- ---- [ 69.984184] lock(&head->lock); [ 69.987406] local_irq_disable(); [ 69.993319] lock(&rq->lock); [ 69.998882] lock(&head->lock); [ 70.004618] <Interrupt> [ 70.007235] lock(&rq->lock); [ 70.010461] [ 70.010461] *** DEADLOCK *** [ 70.010461] [ 70.016372] 1 lock held by dd/2928: [ 70.019856] #0: 00000000ab9293c8 (rcu_read_lock){....}, at: trace_call_bpf+0x37/0x1d0 [ 70.027768] [ 70.027768] the shortest dependencies between 2nd lock and 1st lock: [ 70.035586] -> (&rq->lock){-.-.} ops: 1401365 { [ 70.040204] IN-HARDIRQ-W at: [ 70.043428] lock_acquire+0xd5/0x1c0 [ 70.048820] _raw_spin_lock+0x2f/0x40 [ 70.054299] scheduler_tick+0x51/0xf0 [ 70.059781] update_process_times+0x47/0x60 [ 70.065779] tick_periodic+0x2b/0xc0 [ 70.071171] tick_handle_periodic+0x25/0x70 [ 70.077168] timer_interrupt+0x15/0x20 [ 70.082731] __handle_irq_event_percpu+0x48/0x320 [ 70.089250] handle_irq_event_percpu+0x32/0x80 [ 70.095505] handle_irq_event+0x39/0x60 [ 70.101157] handle_level_irq+0x7f/0x100 [ 70.106893] handle_irq+0x6f/0x110 [ 70.112112] do_IRQ+0x5c/0x110 [ 70.116982] ret_from_intr+0x0/0x1d [ 70.122286] _raw_spin_unlock_irqrestore+0x38/0x50 [ 70.128891] __setup_irq+0x45d/0x700 [ 70.134281] setup_irq+0x4c/0x90 [ 70.139324] hpet_time_init+0x25/0x37 [ 70.144803] x86_late_time_init+0xf/0x1c [ 70.150538] start_kernel+0x40c/0x4ca [ 70.156017] x86_64_start_reservations+0x24/0x26 [ 70.162445] x86_64_start_kernel+0x6f/0x72 [ 70.168357] secondary_startup_64+0xa4/0xb0 [ 70.174356] IN-SOFTIRQ-W at: [ 70.177578] lock_acquire+0xd5/0x1c0 [ 70.182970] _raw_spin_lock+0x2f/0x40 [ 70.188448] try_to_wake_up+0x31b/0x540 [ 70.194097] wake_up_process+0x15/0x20 [ 70.199661] swake_up_locked+0x24/0x40 [ 70.205226] swake_up_one+0x1f/0x30 [ 70.210530] rcu_gp_kthread_wake+0x3b/0x40 [ 70.216441] rcu_accelerate_cbs_unlocked+0x9c/0xe0 [ 70.223048] rcu_process_callbacks+0x111/0x10c0 [ 70.229396] __do_softirq+0xbf/0x493 [ 70.234788] irq_exit+0xc3/0xd0 [ 70.239743] smp_apic_timer_interrupt+0x93/0x2a0 [ 70.246176] apic_timer_interrupt+0xf/0x20 [ 70.252084] console_unlock+0x4e8/0x620 [ 70.257737] vprintk_emit+0x254/0x430 [ 70.263214] vprintk_default+0x1f/0x30 [ 70.268776] vprintk_func+0x27/0x60 [ 70.274082] printk+0x52/0x6e [ 70.278864] native_cpu_up+0x71b/0x7a0 [ 70.284431] bringup_cpu+0x2a/0xb0 [ 70.289648] cpuhp_invoke_callback+0xb2/0xb20 [ 70.295818] _cpu_up+0xae/0x160 [ 70.300776] do_cpu_up+0x8d/0xb0 [ 70.305818] cpu_up+0x13/0x20 [ 70.310602] smp_init+0x67/0xc4 [ 70.315559] kernel_init_freeable+0x134/0x259 [ 70.321731] kernel_init+0xe/0x110 [ 70.326947] ret_from_fork+0x3a/0x50 [ 70.332339] INITIAL USE at: [ 70.335477] lock_acquire+0xd5/0x1c0 [ 70.340780] _raw_spin_lock_irqsave+0x3a/0x50 [ 70.346864] rq_attach_root+0x1b/0xc0 [ 70.352255] sched_init+0x310/0x432 [ 70.357472] start_kernel+0x26e/0x4ca [ 70.362861] x86_64_start_reservations+0x24/0x26 [ 70.369207] x86_64_start_kernel+0x6f/0x72 [ 70.375048] secondary_startup_64+0xa4/0xb0 [ 70.380958] } [ 70.382710] ... key at: [<ffffffff8716faf8>] __key.69482+0x0/0x8 [ 70.389310] ... acquired at: [ 70.392364] _raw_spin_lock+0x2f/0x40 [ 70.396192] pcpu_freelist_pop+0x7a/0xd0 [ 70.400286] bpf_get_stackid+0x1ca/0x470 [ 70.404383] bpf_get_stackid_tp+0x11/0x20 [ 70.408559] ___bpf_prog_run+0x7f2/0x1090 [ 70.412739] __bpf_prog_run32+0x39/0x50 [ 70.416742] trace_call_bpf+0xc8/0x1d0 [ 70.420659] perf_trace_run_bpf_submit+0x42/0xb0 [ 70.425444] perf_trace_sched_switch+0x116/0x190 [ 70.430227] __schedule+0x6d8/0xa20 [ 70.433883] schedule+0x3d/0x90 [ 70.437194] worker_thread+0xd0/0x410 [ 70.441025] kthread+0x10d/0x140 [ 70.444424] ret_from_fork+0x3a/0x50 [ 70.448165] [ 70.449658] -> (&head->lock){+...} ops: 61660 { [ 70.454181] HARDIRQ-ON-W at: [ 70.457319] lock_acquire+0xd5/0x1c0 [ 70.462536] _raw_spin_lock+0x2f/0x40 [ 70.467841] pcpu_freelist_push+0x28/0x50 [ 70.473492] bpf_get_stackid+0x43a/0x470 [ 70.479054] bpf_get_stackid_tp+0x11/0x20 [ 70.484724] ___bpf_prog_run+0x7f2/0x1090 [ 70.490372] __bpf_prog_run32+0x39/0x50 [ 70.495852] trace_call_bpf+0xc8/0x1d0 [ 70.501243] perf_trace_run_bpf_submit+0x42/0xb0 [ 70.507500] perf_trace_urandom_read+0xbf/0x100 [ 70.513670] urandom_read+0x1ce/0x340 [ 70.518975] __vfs_read+0x37/0x160 [ 70.524027] vfs_read+0xa8/0x150 [ 70.528898] ksys_read+0x58/0xc0 [ 70.533766] __x64_sys_read+0x1a/0x20 [ 70.539092] do_syscall_64+0x4f/0x190 [ 70.544401] entry_SYSCALL_64_after_hwframe+0x49/0xbe [ 70.551092] INITIAL USE at: [ 70.554143] lock_acquire+0xd5/0x1c0 [ 70.559272] _raw_spin_lock+0x2f/0x40 [ 70.564491] pcpu_freelist_populate+0xb6/0x110 [ 70.570489] htab_map_alloc+0x3b6/0x4c0 [ 70.575878] map_create+0xf0/0x370 [ 70.580836] __x64_sys_bpf+0x10b/0x260 [ 70.586138] do_syscall_64+0x4f/0x190 [ 70.591356] entry_SYSCALL_64_after_hwframe+0x49/0xbe [ 70.597960] } [ 70.599624] ... key at: [<ffffffff87d4c5a0>] __key.11024+0x0/0x8 [ 70.606142] ... acquired at: [ 70.609104] mark_lock+0x392/0x570 [ 70.612676] __lock_acquire+0x5cd/0x13c0 [ 70.616767] lock_acquire+0xd5/0x1c0 [ 70.620511] _raw_spin_lock+0x2f/0x40 [ 70.624342] pcpu_freelist_push+0x28/0x50 [ 70.628519] bpf_get_stackid+0x43a/0x470 [ 70.632610] bpf_get_stackid_tp+0x11/0x20 [ 70.636785] ___bpf_prog_run+0x7f2/0x1090 [ 70.640965] __bpf_prog_run32+0x39/0x50 [ 70.644969] trace_call_bpf+0xc8/0x1d0 [ 70.648886] perf_trace_run_bpf_submit+0x42/0xb0 [ 70.653668] perf_trace_urandom_read+0xbf/0x100 [ 70.658366] urandom_read+0x1ce/0x340 [ 70.662199] __vfs_read+0x37/0x160 [ 70.665768] vfs_read+0xa8/0x150 [ 70.669166] ksys_read+0x58/0xc0 [ 70.672562] __x64_sys_read+0x1a/0x20 [ 70.676393] do_syscall_64+0x4f/0x190 [ 70.680223] entry_SYSCALL_64_after_hwframe+0x49/0xbe [ 70.685440] [ 70.686933] [ 70.686933] stack backtrace: [ 70.691283] CPU: 3 PID: 2928 Comm: dd Not tainted 4.18.0-rc3-next-20180705 #1 [ 70.698405] Hardware name: Supermicro SYS-5019S-ML/X11SSH-F, BIOS 2.0b 07/27/2017 [ 70.705875] Call Trace: [ 70.708321] dump_stack+0x68/0x95 [ 70.711631] print_irq_inversion_bug.part.41+0x1a5/0x1b1 [ 70.716935] check_usage_backwards+0x14b/0x160 [ 70.721374] mark_lock+0x392/0x570 [ 70.724771] ? mark_lock+0x392/0x570 [ 70.728340] ? print_shortest_lock_dependencies+0x1a0/0x1a0 [ 70.733904] __lock_acquire+0x5cd/0x13c0 [ 70.737823] ? find_get_entry+0x1a2/0x2f0 [ 70.741825] lock_acquire+0xd5/0x1c0 [ 70.745397] ? lock_acquire+0xd5/0x1c0 [ 70.749141] ? pcpu_freelist_push+0x28/0x50 [ 70.753317] _raw_spin_lock+0x2f/0x40 [ 70.756974] ? pcpu_freelist_push+0x28/0x50 [ 70.761153] pcpu_freelist_push+0x28/0x50 [ 70.765156] bpf_get_stackid+0x43a/0x470 [ 70.769073] bpf_get_stackid_tp+0x11/0x20 [ 70.773077] ___bpf_prog_run+0x7f2/0x1090 [ 70.777083] __bpf_prog_run32+0x39/0x50 [ 70.780912] ? lock_acquire+0xd5/0x1c0 [ 70.784656] trace_call_bpf+0xc8/0x1d0 [ 70.788399] perf_trace_run_bpf_submit+0x42/0xb0 [ 70.793013] perf_trace_urandom_read+0xbf/0x100 [ 70.797544] urandom_read+0x1ce/0x340 [ 70.801202] __vfs_read+0x37/0x160 [ 70.804598] ? security_file_permission+0x8d/0xb0 [ 70.809297] ? security_file_permission+0x8d/0xb0 [ 70.813993] vfs_read+0xa8/0x150 [ 70.817218] ksys_read+0x58/0xc0 [ 70.820442] __x64_sys_read+0x1a/0x20 [ 70.824106] do_syscall_64+0x4f/0x190 [ 70.827764] entry_SYSCALL_64_after_hwframe+0x49/0xbe [ 70.832807] RIP: 0033:0x7f302526f160 [ 70.836378] Code: b6 fe ff ff 48 8d 3d 97 b1 08 00 48 83 ec 08 e8 66 d3 01 00 66 0f 1f 44 00 00 83 3d e9 15 2c 00 00 75 10 b8 00 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 31 c3 48 83 ec 08 e8 7e 94 01 00 48 89 04 24 [ 70.855253] RSP: 002b:00007fff096fd4e8 EFLAGS: 00000246 ORIG_RAX: 0000000000000000 [ 70.862812] RAX: ffffffffffffffda RBX: 0000000000000001 RCX: 00007f302526f160 [ 70.869935] RDX: 0000000000000200 RSI: 000000000070f000 RDI: 0000000000000000 [ 70.877060] RBP: 0000000000000200 R08: 000000000070f000 R09: 0000000000711060 [ 70.884183] R10: 0000000000000871 R11: 0000000000000246 R12: 000000000070f000 [ 70.891306] R13: 0000000000000000 R14: 0000000000000200 R15: 0000000000000000 e 54 test_l4lb:FAIL:ipv4 err 0 errno 2 retval 7 size 54 magic 1234
Full kernel selftest test log, https://lkft.validation.linaro.org/scheduler/job/314724#L2142
Best regards Naresh Kamboju -- To unsubscribe from this list: send the line "unsubscribe linux-kselftest" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html