Results for igt@perf_pmu@busy-hang-bcs0

Result: dmesg-warn

integration-manifest git-log-oneline igt_runner9 run9 boot9 dmesg9 runtimes9

DetailValue
Duration 1.79 seconds
Igt-Version
IGT-Version: 1.24-g4d1f6036d (x86_64) (Linux: 5.4.0-rc4-g54520983c610-drmtip_395+ x86_64)
Out
IGT-Version: 1.24-g4d1f6036d (x86_64) (Linux: 5.4.0-rc4-g54520983c610-drmtip_395+ x86_64)
Starting subtest: busy-hang-bcs0
Subtest busy-hang-bcs0: SUCCESS (1.790s)
Err
Starting subtest: busy-hang-bcs0
Subtest busy-hang-bcs0: SUCCESS (1.790s)
Dmesg-Warnings
<4> [211.966082]  #3: ffff910e1d6a21e0 (wakeref#3){+.+.}, at: __intel_wakeref_put_last+0x25/0x50 [i915]
<4> [211.967045]    intel_gt_retire_requests_timeout+0x1b9/0x540 [i915]
<4> [211.967507]                      intel_timeline_enter+0x64/0x150 [i915]
<4> [211.967844]                      ____intel_wakeref_put_last+0x1c/0x70 [i915]
<4> [211.968014]                      intel_gt_resume+0x1d7/0x2a0 [i915]
<4> [211.968197]                      i915_gem_init+0x36a/0x8d0 [i915]
<4> [211.968357]                      i915_driver_probe+0xb76/0x15a0 [i915]
<4> [211.968519]                      i915_pci_probe+0x43/0x1b0 [i915]
<4> [211.969109]    intel_timeline_enter+0x64/0x150 [i915]
<4> [211.969437]    ____intel_wakeref_put_last+0x1c/0x70 [i915]
<4> [211.969605]    intel_gt_resume+0x1d7/0x2a0 [i915]
<4> [211.969786]    i915_gem_init+0x36a/0x8d0 [i915]
<4> [211.969944]    i915_driver_probe+0xb76/0x15a0 [i915]
<4> [211.970103]    i915_pci_probe+0x43/0x1b0 [i915]
<4> [211.970670]                     ____intel_wakeref_put_last+0x1c/0x70 [i915]
<4> [211.970821]                     i915_sample+0x2e8/0x310 [i915]
<4> [211.971273]                    ____intel_wakeref_put_last+0x1c/0x70 [i915]
<4> [211.971409]                    intel_gt_resume+0x1d7/0x2a0 [i915]
<4> [211.971555]                    i915_gem_init+0x36a/0x8d0 [i915]
<4> [211.971683]                    i915_driver_probe+0xb76/0x15a0 [i915]
<4> [211.971813]                    i915_pci_probe+0x43/0x1b0 [i915]
<4> [211.972419]    ____intel_wakeref_put_last+0x1c/0x70 [i915]
<4> [211.972551]    i915_sample+0x2e8/0x310 [i915]
<4> [211.973379]  ____intel_wakeref_put_last+0x1c/0x70 [i915]
<4> [211.973513]  i915_sample+0x2e8/0x310 [i915]
<4> [211.973647]  ? i915_pmu_cpu_online+0x70/0x70 [i915]
Dmesg
<6> [211.440154] Console: switching to colour dummy device 80x25
<6> [211.440434] [IGT] perf_pmu: executing
<6> [211.453174] [IGT] perf_pmu: starting subtest busy-hang-bcs0
<5> [211.454772] Setting dangerous option reset - tainting kernel
<7> [211.959243] [drm:intel_gt_reset_global [i915]] resetting chip
<5> [211.961179] i915 0000:00:02.0: Resetting chip for Manually set wedged engine mask = ffffffffffffffff
<4> [211.965487] 
<4> [211.965503] ========================================================
<4> [211.965518] WARNING: possible irq lock inversion dependency detected
<4> [211.965534] 5.4.0-rc4-g54520983c610-drmtip_395+ #1 Tainted: G     U           
<4> [211.965549] --------------------------------------------------------
<4> [211.965563] systemd-udevd/215 just changed the state of lock:
<4> [211.965577] ffff910e3411e270 (&kernel/2){-...}, at: __engine_park+0x175/0x420 [i915]
<4> [211.965780] but this lock took another, HARDIRQ-unsafe lock in the past:
<4> [211.965793]  (&(&lock->wait_lock)->rlock){+.+.}
<4> [211.965796] 

and interrupts could create inverse lock ordering between them.

<4> [211.965825] 
other info that might help us debug this:
<4> [211.965839] Chain exists of:
  &kernel/2 --> &(&timelines->lock)->rlock --> &(&lock->wait_lock)->rlock

<4> [211.965867]  Possible interrupt unsafe locking scenario:

<4> [211.965883]        CPU0                    CPU1
<4> [211.965894]        ----                    ----
<4> [211.965904]   lock(&(&lock->wait_lock)->rlock);
<4> [211.965918]                                local_irq_disable();
<4> [211.965930]                                lock(&kernel/2);
<4> [211.965945]                                lock(&(&timelines->lock)->rlock);
<4> [211.965961]   <Interrupt>
<4> [211.965969]     lock(&kernel/2);
<4> [211.965981] 
 *** DEADLOCK ***

<4> [211.965997] 4 locks held by systemd-udevd/215:
<4> [211.966008]  #0: ffffffffa8458350 (dup_mmap_sem.rw_sem){.+.+}, at: dup_mm+0x7e/0x550
<4> [211.966035]  #1: ffff910e3b22db58 (&mm->mmap_sem#2){++++}, at: dup_mm+0x92/0x550
<4> [211.966059]  #2: ffff910e2a9353d8 (&mm->mmap_sem/1){+.+.}, at: dup_mm+0xbf/0x550
<4> [211.966082]  #3: ffff910e1d6a21e0 (wakeref#3){+.+.}, at: __intel_wakeref_put_last+0x25/0x50 [i915]
<4> [211.966269] 
the shortest dependencies between 2nd lock and 1st lock:
<4> [211.966302]   -> (&(&lock->wait_lock)->rlock){+.+.} ops: 229 {
<4> [211.966322]      HARDIRQ-ON-W at:
<4> [211.966338]                         lock_acquire+0xa7/0x1c0
<4> [211.966356]                         _raw_spin_lock+0x2a/0x40
<4> [211.966372]                         __mutex_lock+0x198/0x9d0
<4> [211.966388]                         pipe_wait+0x8f/0xc0
<4> [211.966402]                         pipe_read+0x235/0x310
<4> [211.966418]                         new_sync_read+0x10f/0x1a0
<4> [211.966433]                         vfs_read+0x96/0x160
<4> [211.966448]                         ksys_read+0x9f/0xe0
<4> [211.966463]                         do_syscall_64+0x4f/0x210
<4> [211.966478]                         entry_SYSCALL_64_after_hwframe+0x49/0xbe
<4> [211.966493]      SOFTIRQ-ON-W at:
<4> [211.966507]                         lock_acquire+0xa7/0x1c0
<4> [211.966523]                         _raw_spin_lock+0x2a/0x40
<4> [211.966538]                         __mutex_lock+0x198/0x9d0
<4> [211.966553]                         pipe_wait+0x8f/0xc0
<4> [211.966568]                         pipe_read+0x235/0x310
<4> [211.966583]                         new_sync_read+0x10f/0x1a0
<4> [211.966598]                         vfs_read+0x96/0x160
<4> [211.966612]                         ksys_read+0x9f/0xe0
<4> [211.966627]                         do_syscall_64+0x4f/0x210
<4> [211.966642]                         entry_SYSCALL_64_after_hwframe+0x49/0xbe
<4> [211.966657]      INITIAL USE at:
<4> [211.966670]                        lock_acquire+0xa7/0x1c0
<4> [211.966686]                        _raw_spin_lock+0x2a/0x40
<4> [211.966702]                        __mutex_lock+0x198/0x9d0
<4> [211.966716]                        pipe_wait+0x8f/0xc0
<4> [211.966730]                        pipe_read+0x235/0x310
<4> [211.966746]                        new_sync_read+0x10f/0x1a0
<4> [211.966760]                        vfs_read+0x96/0x160
<4> [211.966774]                        ksys_read+0x9f/0xe0
<4> [211.966789]                        do_syscall_64+0x4f/0x210
<4> [211.966804]                        entry_SYSCALL_64_after_hwframe+0x49/0xbe
<4> [211.966819]    }
<4> [211.966832]    ... key      at: [<ffffffffa8a54df0>] __key.18970+0x0/0x10
<4> [211.966847]    ... acquired at:
<4> [211.966859]    _raw_spin_lock+0x2a/0x40
<4> [211.966873]    __mutex_unlock_slowpath+0x18e/0x2b0
<4> [211.967045]    intel_gt_retire_requests_timeout+0x1b9/0x540 [i915]
<4> [211.967214]    retire_work_handler+0x12/0x40 [i915]
<4> [211.967230]    process_one_work+0x26a/0x620
<4> [211.967243]    worker_thread+0x37/0x380
<4> [211.967256]    kthread+0x119/0x130
<4> [211.967267]    ret_from_fork+0x3a/0x50
<4> [211.967278] 
<4> [211.967285]  -> (&(&timelines->lock)->rlock){....} ops: 370 {
<4> [211.967303]     INITIAL USE at:
<4> [211.967316]                      lock_acquire+0xa7/0x1c0
<4> [211.967332]                      _raw_spin_lock_irqsave+0x33/0x50
<4> [211.967507]                      intel_timeline_enter+0x64/0x150 [i915]
<4> [211.967676]                      __engine_park+0x1ef/0x420 [i915]
<4> [211.967844]                      ____intel_wakeref_put_last+0x1c/0x70 [i915]
<4> [211.968014]                      intel_gt_resume+0x1d7/0x2a0 [i915]
<4> [211.968197]                      i915_gem_init+0x36a/0x8d0 [i915]
<4> [211.968357]                      i915_driver_probe+0xb76/0x15a0 [i915]
<4> [211.968519]                      i915_pci_probe+0x43/0x1b0 [i915]
<4> [211.968537]                      pci_device_probe+0x9e/0x120
<4> [211.968554]                      really_probe+0xea/0x420
<4> [211.968569]                      driver_probe_device+0x10b/0x120
<4> [211.968585]                      device_driver_attach+0x4a/0x50
<4> [211.968601]                      __driver_attach+0x97/0x130
<4> [211.968616]                      bus_for_each_dev+0x74/0xc0
<4> [211.968632]                      bus_add_driver+0x142/0x220
<4> [211.968647]                      driver_register+0x56/0xf0
<4> [211.968662]                      do_one_initcall+0x58/0x2ff
<4> [211.968678]                      do_init_module+0x56/0x1f8
<4> [211.968694]                      load_module+0x243e/0x29f0
<4> [211.968709]                      __do_sys_finit_module+0xe9/0x110
<4> [211.968725]                      do_syscall_64+0x4f/0x210
<4> [211.968741]                      entry_SYSCALL_64_after_hwframe+0x49/0xbe
<4> [211.968755]   }
<4> [211.968905]   ... key      at: [<ffffffffc0699890>] __key.70194+0x0/0xffffffffffeed770 [i915]
<4> [211.968923]   ... acquired at:
<4> [211.968936]    _raw_spin_lock_irqsave+0x33/0x50
<4> [211.969109]    intel_timeline_enter+0x64/0x150 [i915]
<4> [211.969275]    __engine_park+0x1ef/0x420 [i915]
<4> [211.969437]    ____intel_wakeref_put_last+0x1c/0x70 [i915]
<4> [211.969605]    intel_gt_resume+0x1d7/0x2a0 [i915]
<4> [211.969786]    i915_gem_init+0x36a/0x8d0 [i915]
<4> [211.969944]    i915_driver_probe+0xb76/0x15a0 [i915]
<4> [211.970103]    i915_pci_probe+0x43/0x1b0 [i915]
<4> [211.970118]    pci_device_probe+0x9e/0x120
<4> [211.970132]    really_probe+0xea/0x420
<4> [211.970145]    driver_probe_device+0x10b/0x120
<4> [211.970158]    device_driver_attach+0x4a/0x50
<4> [211.970172]    __driver_attach+0x97/0x130
<4> [211.970185]    bus_for_each_dev+0x74/0xc0
<4> [211.970198]    bus_add_driver+0x142/0x220
<4> [211.970211]    driver_register+0x56/0xf0
<4> [211.970223]    do_one_initcall+0x58/0x2ff
<4> [211.970236]    do_init_module+0x56/0x1f8
<4> [211.970249]    load_module+0x243e/0x29f0
<4> [211.970262]    __do_sys_finit_module+0xe9/0x110
<4> [211.970276]    do_syscall_64+0x4f/0x210
<4> [211.970288]    entry_SYSCALL_64_after_hwframe+0x49/0xbe
<4> [211.970300] 
<4> [211.970307] -> (&kernel/2){-...} ops: 47 {
<4> [211.970324]    IN-HARDIRQ-W at:
<4> [211.970337]                     lock_acquire+0xa7/0x1c0
<4> [211.970505]                     __engine_park+0x1ac/0x420 [i915]
<4> [211.970670]                     ____intel_wakeref_put_last+0x1c/0x70 [i915]
<4> [211.970821]                     i915_sample+0x2e8/0x310 [i915]
<4> [211.970835]                     __hrtimer_run_queues+0x121/0x4a0
<4> [211.970847]                     hrtimer_interrupt+0xea/0x250
<4> [211.970860]                     smp_apic_timer_interrupt+0x96/0x280
<4> [211.970873]                     apic_timer_interrupt+0xf/0x20
<4> [211.970887]                     __slab_alloc.isra.84.constprop.89+0x4f/0x70
<4> [211.970901]                     kmem_cache_alloc+0x24a/0x2a0
<4> [211.970915]                     vm_area_dup+0x15/0x40
<4> [211.970926]                     dup_mm+0x2dd/0x550
<4> [211.970938]                     copy_process+0xea9/0x1d80
<4> [211.970950]                     _do_fork+0x71/0x670
<4> [211.970962]                     __x64_sys_clone+0x81/0xb0
<4> [211.970974]                     do_syscall_64+0x4f/0x210
<4> [211.970986]                     entry_SYSCALL_64_after_hwframe+0x49/0xbe
<4> [211.970997]    INITIAL USE at:
<4> [211.971008]                    lock_acquire+0xa7/0x1c0
<4> [211.971141]                    __engine_park+0x1ac/0x420 [i915]
<4> [211.971273]                    ____intel_wakeref_put_last+0x1c/0x70 [i915]
<4> [211.971409]                    intel_gt_resume+0x1d7/0x2a0 [i915]
<4> [211.971555]                    i915_gem_init+0x36a/0x8d0 [i915]
<4> [211.971683]                    i915_driver_probe+0xb76/0x15a0 [i915]
<4> [211.971813]                    i915_pci_probe+0x43/0x1b0 [i915]
<4> [211.971826]                    pci_device_probe+0x9e/0x120
<4> [211.971839]                    really_probe+0xea/0x420
<4> [211.971851]                    driver_probe_device+0x10b/0x120
<4> [211.971863]                    device_driver_attach+0x4a/0x50
<4> [211.971876]                    __driver_attach+0x97/0x130
<4> [211.971888]                    bus_for_each_dev+0x74/0xc0
<4> [211.971900]                    bus_add_driver+0x142/0x220
<4> [211.971912]                    driver_register+0x56/0xf0
<4> [211.971923]                    do_one_initcall+0x58/0x2ff
<4> [211.971935]                    do_init_module+0x56/0x1f8
<4> [211.971947]                    load_module+0x243e/0x29f0
<4> [211.971960]                    __do_sys_finit_module+0xe9/0x110
<4> [211.971972]                    do_syscall_64+0x4f/0x210
<4> [211.971984]                    entry_SYSCALL_64_after_hwframe+0x49/0xbe
<4> [211.971995]  }
<4> [211.972114]  ... key      at: [<ffffffffc0699652>] kernel.70703+0x2/0xffffffffffeed9b0 [i915]
<4> [211.972128]  ... acquired at:
<4> [211.972138]    mark_lock+0x382/0x500
<4> [211.972147]    __lock_acquire+0x7e1/0x15d0
<4> [211.972158]    lock_acquire+0xa7/0x1c0
<4> [211.972289]    __engine_park+0x1ac/0x420 [i915]
<4> [211.972419]    ____intel_wakeref_put_last+0x1c/0x70 [i915]
<4> [211.972551]    i915_sample+0x2e8/0x310 [i915]
<4> [211.972562]    __hrtimer_run_queues+0x121/0x4a0
<4> [211.972573]    hrtimer_interrupt+0xea/0x250
<4> [211.972584]    smp_apic_timer_interrupt+0x96/0x280
<4> [211.972595]    apic_timer_interrupt+0xf/0x20
<4> [211.972607]    __slab_alloc.isra.84.constprop.89+0x4f/0x70
<4> [211.972619]    kmem_cache_alloc+0x24a/0x2a0
<4> [211.972630]    vm_area_dup+0x15/0x40
<4> [211.972640]    dup_mm+0x2dd/0x550
<4> [211.972650]    copy_process+0xea9/0x1d80
<4> [211.972661]    _do_fork+0x71/0x670
<4> [211.972671]    __x64_sys_clone+0x81/0xb0
<4> [211.972681]    do_syscall_64+0x4f/0x210
<4> [211.972691]    entry_SYSCALL_64_after_hwframe+0x49/0xbe
<4> [211.972700] 
<4> [211.972706] 
stack backtrace:
<4> [211.972719] CPU: 0 PID: 215 Comm: systemd-udevd Tainted: G     U            5.4.0-rc4-g54520983c610-drmtip_395+ #1
<4> [211.972735] Hardware name: GIGABYTE GB-BXBT-1900/MZBAYAB-00, BIOS F6 02/17/2015
<4> [211.972749] Call Trace:
<4> [211.972758]  <IRQ>
<4> [211.972769]  dump_stack+0x67/0x9b
<4> [211.972781]  check_usage_forwards+0x13c/0x150
<4> [211.972797]  ? mark_lock+0x382/0x500
<4> [211.972807]  mark_lock+0x382/0x500
<4> [211.972817]  ? check_usage_backwards+0x140/0x140
<4> [211.972830]  __lock_acquire+0x7e1/0x15d0
<4> [211.972844]  lock_acquire+0xa7/0x1c0
<4> [211.972978]  ? __engine_park+0x175/0x420 [i915]
<4> [211.973113]  __engine_park+0x1ac/0x420 [i915]
<4> [211.973248]  ? __engine_park+0x175/0x420 [i915]
<4> [211.973379]  ____intel_wakeref_put_last+0x1c/0x70 [i915]
<4> [211.973513]  i915_sample+0x2e8/0x310 [i915]
<4> [211.973647]  ? i915_pmu_cpu_online+0x70/0x70 [i915]
<4> [211.973659]  __hrtimer_run_queues+0x121/0x4a0
<4> [211.973673]  hrtimer_interrupt+0xea/0x250
<4> [211.973686]  smp_apic_timer_interrupt+0x96/0x280
<4> [211.973698]  apic_timer_interrupt+0xf/0x20
<4> [211.973708]  </IRQ>
<4> [211.973718] RIP: 0010:__slab_alloc.isra.84.constprop.89+0x4f/0x70
<4> [211.973732] Code: 89 f2 44 89 ee 48 8b 0c c5 80 66 33 a8 4c 89 e7 48 01 d9 e8 23 f8 ff ff f7 c5 00 02 00 00 48 89 c3 74 13 e8 93 fb f4 ff 55 9d <48> 89 d8 5b 5d 41 5c 41 5d 41 5e c3 55 9d e8 7e fd f4 ff 48 89 d8
<4> [211.973759] RSP: 0018:ffff987b801d7ca0 EFLAGS: 00000246 ORIG_RAX: ffffffffffffff13
<4> [211.973774] RAX: ffff910e35d98040 RBX: ffff910e2a8aaab0 RCX: 0000000000000000
<4> [211.973787] RDX: 000000000000023a RSI: ffff910e35d98920 RDI: ffffffffa830d121
<4> [211.973799] RBP: 0000000000000246 R08: 0000000000000001 R09: 0000000000000000
<4> [211.973812] R10: 0000000000000000 R11: 0000000000000000 R12: ffff910e3b17d1c0
<4> [211.973824] R13: 0000000000000cc0 R14: ffffffffa70b0685 R15: ffff910e3b17d1c0
<4> [211.973840]  ? vm_area_dup+0x15/0x40
<4> [211.973855]  ? vm_area_dup+0x15/0x40
<4> [211.973866]  kmem_cache_alloc+0x24a/0x2a0
<4> [211.973879]  vm_area_dup+0x15/0x40
<4> [211.973890]  dup_mm+0x2dd/0x550
<4> [211.973903]  copy_process+0xea9/0x1d80
<4> [211.973918]  _do_fork+0x71/0x670
<4> [211.973929]  ? sock_setsockopt+0x56c/0xf60
<4> [211.973940]  ? __local_bh_enable_ip+0x74/0x100
<4> [211.973952]  ? sock_setsockopt+0x56c/0xf60
<4> [211.973966]  __x64_sys_clone+0x81/0xb0
<4> [211.973978]  do_syscall_64+0x4f/0x210
<4> [211.973989]  entry_SYSCALL_64_after_hwframe+0x49/0xbe
<4> [211.974001] RIP: 0033:0x7fa688b79b1c
<4> [211.974012] Code: c5 45 85 f6 0f 85 b4 01 00 00 64 4c 8b 04 25 10 00 00 00 31 d2 4d 8d 90 d0 02 00 00 31 f6 bf 11 00 20 01 b8 38 00 00 00 0f 05 <48> 3d 00 f0 ff ff 0f 87 f0 00 00 00 85 c0 41 89 c4 0f 85 fd 00 00
<4> [211.974038] RSP: 002b:00007ffec1507e10 EFLAGS: 00000246 ORIG_RAX: 0000000000000038
<4> [211.974053] RAX: ffffffffffffffda RBX: 00007ffec1507e10 RCX: 00007fa688b79b1c
<4> [211.974066] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000001200011
<4> [211.974078] RBP: 00007ffec1507ea0 R08: 00007fa68908f680 R09: 0000000000000000
<4> [211.974091] R10: 00007fa68908f950 R11: 0000000000000246 R12: 0000000000000000
<4> [211.974103] R13: 0000000000000020 R14: 0000000000000000 R15: 000055b58188ae90
<6> [213.246243] [IGT] perf_pmu: exiting, ret=0
<5> [213.247176] Setting dangerous option reset - tainting kernel
<5> [213.248306] Setting dangerous option reset - tainting kernel
<6> [213.257195] Console: switching to colour frame buffer device 240x67
Created at 2019-10-31 07:16:11