[Bug runtime/21901] New: on rawhide, we're getting an "inconsistent lock state" kernel WARNING

["dsmith at redhat dot com" <sourceware-bugzilla at sourceware dot org>]

https://sourceware.org/bugzilla/show_bug.cgi?id=21901

            Bug ID: 21901
           Summary: on rawhide, we're getting an "inconsistent lock state"
                    kernel WARNING
           Product: systemtap
           Version: unspecified
            Status: NEW
          Severity: normal
          Priority: P2
         Component: runtime
          Assignee: systemtap at sourceware dot org
          Reporter: dsmith at redhat dot com
  Target Milestone: ---

When running the testsuite on rawhide (4.13.0-0.rc2.git3.1.fc27.x86_64), I get
the following WARNING:

====
Jul 27 17:51:24 bkr-hv03-guest26 kernel: ================================
Jul 27 17:51:24 bkr-hv03-guest26 kernel: WARNING: inconsistent lock state
Jul 27 17:51:24 bkr-hv03-guest26 kernel: 4.13.0-0.rc1.git4.1.fc27.x86_64 #1
Tainted: G        W  OE
Jul 27 17:51:24 bkr-hv03-guest26 kernel: --------------------------------
Jul 27 17:51:24 bkr-hv03-guest26 kernel: inconsistent {HARDIRQ-ON-W} ->
{IN-HARDIRQ-W} usage.
Jul 27 17:51:24 bkr-hv03-guest26 kernel: systemd/1 [HC1[1]:SC0[0]:HE0:SE1]
takes:
Jul 27 17:51:24 bkr-hv03-guest26 kernel:  (&(lock)->rlock){?.+...}, at:
[<ffffffffc07bf702>] _stp_mempool_alloc+0x22/0x80
[stap_4117b34ed19454671e35f4d369a98ef_13067]
Jul 27 17:51:24 bkr-hv03-guest26 kernel: {HARDIRQ-ON-W} state was registered
at:
Jul 27 17:51:24 bkr-hv03-guest26 kernel:   __lock_acquire+0x614/0x13b0
Jul 27 17:51:24 bkr-hv03-guest26 kernel:   lock_acquire+0xa3/0x1f0
Jul 27 17:51:24 bkr-hv03-guest26 kernel:   _raw_spin_lock+0x34/0x70
Jul 27 17:51:24 bkr-hv03-guest26 kernel:   utrace_attach_task+0xf9/0x2e0
[stap_4117b34ed19454671e35f4d369a98ef_13067]
Jul 27 17:51:24 bkr-hv03-guest26 kernel:   __stp_utrace_attach+0x56/0x1c0
[stap_4117b34ed19454671e35f4d369a98ef_13067]
Jul 27 17:51:24 bkr-hv03-guest26 kernel:   _stp_ctl_write_cmd+0x1288/0x19f0
[stap_4117b34ed19454671e35f4d369a98ef_13067]
Jul 27 17:51:24 bkr-hv03-guest26 kernel:   full_proxy_write+0x78/0xb0
Jul 27 17:51:24 bkr-hv03-guest26 kernel:   __vfs_write+0x37/0x170
Jul 27 17:51:24 bkr-hv03-guest26 kernel:   vfs_write+0xc6/0x1c0
Jul 27 17:51:24 bkr-hv03-guest26 kernel:   SyS_write+0x58/0xc0
Jul 27 17:51:24 bkr-hv03-guest26 kernel:   entry_SYSCALL_64_fastpath+0x1f/0xbe
Jul 27 17:51:24 bkr-hv03-guest26 kernel: irq event stamp: 4130470
Jul 27 17:51:24 bkr-hv03-guest26 kernel: hardirqs last  enabled at (4130469):
[<ffffffff8b2ecfec>] prepend_path+0x1cc/0x590
Jul 27 17:51:24 bkr-hv03-guest26 kernel: hardirqs last disabled at (4130470):
[<ffffffff8b9aa938>] apic_timer_interrupt+0x98/0xb0
Jul 27 17:51:24 bkr-hv03-guest26 kernel: softirqs last  enabled at (4129808):
[<ffffffff8b906ea6>] unix_sock_destructor+0x66/0xf0
Jul 27 17:51:24 bkr-hv03-guest26 kernel: softirqs last disabled at (4129806):
[<ffffffff8b906ea6>] unix_sock_destructor+0x66/0xf0
Jul 27 17:51:24 bkr-hv03-guest26 kernel:
                                                                     other info
that might help us debug this:
Jul 27 17:51:24 bkr-hv03-guest26 kernel:  Possible unsafe locking scenario:
Jul 27 17:51:24 bkr-hv03-guest26 kernel:        CPU0
Jul 27 17:51:24 bkr-hv03-guest26 kernel:        ----
Jul 27 17:51:24 bkr-hv03-guest26 kernel:   lock(&(lock)->rlock);
Jul 27 17:51:24 bkr-hv03-guest26 kernel:   <Interrupt>
Jul 27 17:51:24 bkr-hv03-guest26 kernel:     lock(&(lock)->rlock);
Jul 27 17:51:24 bkr-hv03-guest26 kernel:
                                                                      ***
DEADLOCK ***
Jul 27 17:51:24 bkr-hv03-guest26 kernel: 3 locks held by systemd/1:
Jul 27 17:51:24 bkr-hv03-guest26 kernel:  #0:  (rcu_read_lock){......}, at:
[<ffffffff8b2ed434>] d_path+0x84/0x2a0
Jul 27 17:51:24 bkr-hv03-guest26 kernel:  #1: 
(global_lock(s___global_profile)){......}, at: [<ffffffffc07bcfe1>]
stp_lock_probe+0x81/0xb0 [stap_4117b34ed19454671e35f4d369a98ef_13067]
Jul 27 17:51:24 bkr-hv03-guest26 kernel:  #2: 
(global_lock(s___global_pcount)){......}, at: [<ffffffffc07bcfe1>]
stp_lock_probe+0x81/0xb0 [stap_4117b34ed19454671e35f4d369a98ef_13067]
Jul 27 17:51:24 bkr-hv03-guest26 kernel:
                                                                     stack
backtrace:
Jul 27 17:51:24 bkr-hv03-guest26 kernel: CPU: 0 PID: 1 Comm: systemd Tainted: G
       W  OE   4.13.0-0.rc1.git4.1.fc27.x86_64 #1
Jul 27 17:51:24 bkr-hv03-guest26 kernel: Hardware name: Red Hat KVM, BIOS 0.5.1
01/01/2011
Jul 27 17:51:24 bkr-hv03-guest26 kernel: Call Trace:
Jul 27 17:51:24 bkr-hv03-guest26 kernel:  <IRQ>
Jul 27 17:51:24 bkr-hv03-guest26 kernel:  dump_stack+0x8e/0xd6
Jul 27 17:51:24 bkr-hv03-guest26 kernel:  print_usage_bug+0x1d0/0x1e0
Jul 27 17:51:24 bkr-hv03-guest26 kernel:  mark_lock+0x433/0x4f0
Jul 27 17:51:24 bkr-hv03-guest26 kernel:  ? kvm_sched_clock_read+0x25/0x40
Jul 27 17:51:24 bkr-hv03-guest26 kernel:  ? check_usage_backwards+0x140/0x140
Jul 27 17:51:24 bkr-hv03-guest26 kernel:  __lock_acquire+0x976/0x13b0
Jul 27 17:51:24 bkr-hv03-guest26 kernel:  ? kvm_sched_clock_read+0x25/0x40
Jul 27 17:51:24 bkr-hv03-guest26 kernel:  lock_acquire+0xa3/0x1f0
Jul 27 17:51:24 bkr-hv03-guest26 kernel:  ? lock_acquire+0xa3/0x1f0
Jul 27 17:51:24 bkr-hv03-guest26 kernel:  ? _stp_mempool_alloc+0x22/0x80
[stap_4117b34ed19454671e35f4d369a98ef_13067]
Jul 27 17:51:24 bkr-hv03-guest26 kernel:  _raw_spin_lock_irqsave+0x4d/0x90
Jul 27 17:51:24 bkr-hv03-guest26 kernel:  ? _stp_mempool_alloc+0x22/0x80
[stap_4117b34ed19454671e35f4d369a98ef_13067]
Jul 27 17:51:24 bkr-hv03-guest26 kernel:  _stp_mempool_alloc+0x22/0x80
[stap_4117b34ed19454671e35f4d369a98ef_13067]
Jul 27 17:51:24 bkr-hv03-guest26 kernel:  _stp_ctl_send+0x61/0x460
[stap_4117b34ed19454671e35f4d369a98ef_13067]
Jul 27 17:51:24 bkr-hv03-guest26 kernel:  _stp_vlog.constprop.152+0xd9/0x270
[stap_4117b34ed19454671e35f4d369a98ef_13067]
Jul 27 17:51:24 bkr-hv03-guest26 kernel:  _stp_warn+0x5e/0x80
[stap_4117b34ed19454671e35f4d369a98ef_13067]
Jul 27 17:51:24 bkr-hv03-guest26 kernel:  unwind+0x158/0x190
[stap_4117b34ed19454671e35f4d369a98ef_13067]
Jul 27 17:51:24 bkr-hv03-guest26 kernel:  _stp_stack_unwind_one_user+0x53/0x160
[stap_4117b34ed19454671e35f4d369a98ef_13067]
Jul 27 17:51:24 bkr-hv03-guest26 kernel:  probe_3651+0x3bb/0xc10
[stap_4117b34ed19454671e35f4d369a98ef_13067]
Jul 27 17:51:24 bkr-hv03-guest26 kernel:  enter_perf_probe_0+0x146/0x360
[stap_4117b34ed19454671e35f4d369a98ef_13067]
Jul 27 17:51:24 bkr-hv03-guest26 kernel:  __perf_event_overflow+0x68/0x100
Jul 27 17:51:24 bkr-hv03-guest26 kernel:  ? perf_swevent_event+0x80/0x80
Jul 27 17:51:24 bkr-hv03-guest26 kernel:  perf_swevent_hrtimer+0x14a/0x160
Jul 27 17:51:24 bkr-hv03-guest26 kernel:  ? kvm_sched_clock_read+0x25/0x40
Jul 27 17:51:24 bkr-hv03-guest26 kernel:  ? kvm_sched_clock_read+0x25/0x40
Jul 27 17:51:24 bkr-hv03-guest26 kernel:  ? debug_object_deactivate+0x13b/0x160
Jul 27 17:51:24 bkr-hv03-guest26 kernel:  ? kvm_sched_clock_read+0x25/0x40
Jul 27 17:51:24 bkr-hv03-guest26 kernel:  ? __lock_is_held+0x65/0xb0
Jul 27 17:51:24 bkr-hv03-guest26 kernel:  ? perf_swevent_event+0x80/0x80
Jul 27 17:51:24 bkr-hv03-guest26 kernel:  __hrtimer_run_queues+0xf0/0x4e0
Jul 27 17:51:24 bkr-hv03-guest26 kernel:  ? __hrtimer_run_queues+0xf0/0x4e0
Jul 27 17:51:24 bkr-hv03-guest26 kernel:  hrtimer_interrupt+0xb6/0x210
Jul 27 17:51:24 bkr-hv03-guest26 kernel:  ? prepend_path+0x45b/0x590
Jul 27 17:51:24 bkr-hv03-guest26 kernel:  local_apic_timer_interrupt+0x38/0x60
Jul 27 17:51:24 bkr-hv03-guest26 kernel:  smp_apic_timer_interrupt+0x38/0x50
Jul 27 17:51:24 bkr-hv03-guest26 kernel:  apic_timer_interrupt+0x9d/0xb0
Jul 27 17:51:24 bkr-hv03-guest26 kernel: RIP: 0010:lock_release+0x14c/0x4c0
Jul 27 17:51:24 bkr-hv03-guest26 kernel: RSP: 0018:ffffbbbd4062fb50 EFLAGS:
00000246 ORIG_RAX: ffffffffffffff10
Jul 27 17:51:24 bkr-hv03-guest26 kernel: RAX: ffff98b6bab98000 RBX:
ffff98b6bab98d78 RCX: 0000000000000002
Jul 27 17:51:24 bkr-hv03-guest26 kernel: RDX: 0000000000000000 RSI:
0000000000000002 RDI: 0000000000000246
Jul 27 17:51:24 bkr-hv03-guest26 kernel: RBP: ffffbbbd4062fb90 R08:
0000156d014ed1ed R09: 0000000000000000
Jul 27 17:51:24 bkr-hv03-guest26 kernel: R10: 0000000000000001 R11:
0000000000000000 R12: ffff98b6bab98000
Jul 27 17:51:24 bkr-hv03-guest26 kernel: R13: 0000000000000c71 R14:
0000000000000001 R15: ffffffff8b2ed27b
Jul 27 17:51:24 bkr-hv03-guest26 kernel:  </IRQ>
Jul 27 17:51:24 bkr-hv03-guest26 kernel:  ? prepend_path+0x45b/0x590
Jul 27 17:51:24 bkr-hv03-guest26 kernel:  prepend_path+0x47a/0x590
Jul 27 17:51:24 bkr-hv03-guest26 kernel:  d_path+0x19b/0x2a0
Jul 27 17:51:24 bkr-hv03-guest26 kernel: 
__stp_call_mmap_callbacks_for_task+0x1a5/0x230
[stap_4117b34ed19454671e35f4d369a98ef_13067]
Jul 27 17:51:24 bkr-hv03-guest26 kernel:  __stp_tf_quiesce_worker+0x126/0x140
[stap_4117b34ed19454671e35f4d369a98ef_13067]
Jul 27 17:51:24 bkr-hv03-guest26 kernel:  task_work_run+0x7a/0xb0
Jul 27 17:51:24 bkr-hv03-guest26 kernel:  get_signal+0x804/0x900
Jul 27 17:51:24 bkr-hv03-guest26 kernel:  do_signal+0x37/0x6c0
Jul 27 17:51:24 bkr-hv03-guest26 kernel:  ? trace_hardirqs_on_caller+0xf4/0x190
Jul 27 17:51:24 bkr-hv03-guest26 kernel:  ? trace_hardirqs_on+0xd/0x10
Jul 27 17:51:24 bkr-hv03-guest26 kernel:  ? __stp_tf_get_map_entry+0xa1/0xc0
[stap_4117b34ed19454671e35f4d369a98ef_13067]
Jul 27 17:51:24 bkr-hv03-guest26 kernel:  ?
__stp_utrace_task_finder_target_syscall_exit+0x56/0x320
[stap_4117b34ed19454671e35f4d369a98ef_13067]
Jul 27 17:51:24 bkr-hv03-guest26 kernel:  ? start_callback.isra.42+0x64/0xd0
[stap_4117b34ed19454671e35f4d369a98ef_13067]
Jul 27 17:51:24 bkr-hv03-guest26 kernel:  exit_to_usermode_loop+0x80/0xc0
Jul 27 17:51:24 bkr-hv03-guest26 kernel:  syscall_return_slowpath+0xb6/0x110
Jul 27 17:51:24 bkr-hv03-guest26 kernel:  entry_SYSCALL_64_fastpath+0xbc/0xbe
Jul 27 17:51:24 bkr-hv03-guest26 kernel: RIP: 0033:0x7ff8fb6804d6
Jul 27 17:51:24 bkr-hv03-guest26 kernel: RSP: 002b:00007fffa537eff0 EFLAGS:
00000293 ORIG_RAX: 0000000000000119
Jul 27 17:51:24 bkr-hv03-guest26 kernel: RAX: fffffffffffffffc RBX:
0000000000000000 RCX: 00007ff8fb6804d6
Jul 27 17:51:24 bkr-hv03-guest26 kernel: RDX: 000000000000003c RSI:
00007fffa537f030 RDI: 0000000000000004
Jul 27 17:51:24 bkr-hv03-guest26 kernel: RBP: 00007fffa537f030 R08:
0000000000000000 R09: 0000000000000008
Jul 27 17:51:24 bkr-hv03-guest26 kernel: R10: ffffffffffffffff R11:
0000000000000293 R12: 0000000000000000
Jul 27 17:51:24 bkr-hv03-guest26 kernel: R13: ffffffffffffffff R14:
00007fffa537f030 R15: 0000000000000001
====

-- 
You are receiving this mail because:
You are the assignee for the bug.