Bug 103307

Summary: [CI] igt@gem_ppgtt@blt-vs-render-ctx0 - incomplete - INFO: task gem_ppgtt:1593 blocked for more than 60 seconds
Product: DRI Reporter: Marta Löfstedt <marta.lofstedt>
Component: DRM/IntelAssignee: Intel GFX Bugs mailing list <intel-gfx-bugs>
Status: CLOSED INVALID QA Contact: Intel GFX Bugs mailing list <intel-gfx-bugs>
Severity: normal    
Priority: medium CC: intel-gfx-bugs
Version: DRI git   
Hardware: Other   
OS: All   
Whiteboard: ReadyForDev
i915 platform: KBL i915 features: GEM/Other

Description Marta Löfstedt 2017-10-17 07:43:34 UTC 
https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_3241/shard-kbl6/igt@gem_ppgtt@blt-vs-render-ctx0.html

<7>[  609.760608] [drm:missed_breadcrumb [i915]] rcs0 missed breadcrumb at intel_breadcrumbs_hangcheck+0x61/0x80 [i915], irq posted? yes, current seqno=8492, last=8492
<14>[  609.774340] [IGT] gem_ppgtt: starting subtest blt-vs-render-ctx0
<5>[  615.712884] i915 0000:00:02.0: Resetting vcs0 after gpu hang
<7>[  615.714018] [drm:gen8_init_common_ring [i915]] Execlists enabled for vcs0
<5>[  615.714465] i915 0000:00:02.0: Resetting vecs0 after gpu hang
<7>[  615.715672] [drm:gen8_init_common_ring [i915]] Execlists enabled for vecs0
<5>[  619.744884] i915 0000:00:02.0: Resetting bcs0 after gpu hang
<7>[  619.745924] [drm:gen8_init_common_ring [i915]] Execlists enabled for bcs0
<5>[  623.712978] i915 0000:00:02.0: Resetting rcs0 after gpu hang
<7>[  623.713645] [drm:gen8_init_common_ring [i915]] Execlists enabled for rcs0
<7>[  623.713864] [drm:init_workarounds_ring [i915]] rcs0: Number of context specific w/a: 15
<5>[  631.713076] i915 0000:00:02.0: Resetting bcs0 after gpu hang
<7>[  631.713756] [drm:gen8_init_common_ring [i915]] Execlists enabled for bcs0
<5>[  639.712790] i915 0000:00:02.0: Resetting rcs0 after gpu hang
<7>[  639.713747] [drm:gen8_init_common_ring [i915]] Execlists enabled for rcs0
<7>[  639.714101] [drm:init_workarounds_ring [i915]] rcs0: Number of context specific w/a: 15
<5>[  653.728930] i915 0000:00:02.0: Resetting rcs0 after gpu hang
<7>[  653.729990] [drm:gen8_init_common_ring [i915]] Execlists enabled for rcs0
<7>[  653.730627] [drm:init_workarounds_ring [i915]] rcs0: Number of context specific w/a: 15
<5>[  669.728821] i915 0000:00:02.0: Resetting rcs0 after gpu hang
<7>[  669.729763] [drm:gen8_init_common_ring [i915]] Execlists enabled for rcs0
<7>[  669.729984] [drm:init_workarounds_ring [i915]] rcs0: Number of context specific w/a: 15
<3>[  676.832262] INFO: task gem_ppgtt:1593 blocked for more than 60 seconds.
<3>[  676.832371]       Tainted: G     U          4.14.0-rc4-CI-CI_DRM_3241+ #1
<3>[  676.832453] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
<6>[  676.832547] gem_ppgtt       D    0  1593   1589 0x00000000
<4>[  676.832579] Call Trace:
<4>[  676.832612]  __schedule+0x3c3/0xb10
<4>[  676.832639]  schedule+0x40/0x90
<4>[  676.832657]  schedule_preempt_disabled+0x18/0x30
<4>[  676.832675]  __mutex_lock+0x2bb/0x9b0
<4>[  676.832807]  ? i915_gem_close_object+0x41/0x1b0 [i915]
<4>[  676.832836]  ? entry_SYSCALL_64_fastpath+0x1c/0xb1
<4>[  676.832863]  mutex_lock_nested+0x1b/0x20
<4>[  676.832879]  ? mutex_lock_nested+0x1b/0x20
<4>[  676.832986]  i915_gem_close_object+0x41/0x1b0 [i915]
<4>[  676.833205]  drm_gem_object_release_handle+0x30/0x90
<4>[  676.833247]  drm_gem_handle_delete+0x5e/0x90
<4>[  676.833285]  ? drm_gem_handle_create+0x40/0x40
<4>[  676.833318]  drm_gem_close_ioctl+0x20/0x30
<4>[  676.833349]  drm_ioctl_kernel+0x69/0xb0
<4>[  676.833388]  drm_ioctl+0x2f9/0x3d0
<4>[  676.833423]  ? drm_gem_handle_create+0x40/0x40
<4>[  676.833474]  ? __do_page_fault+0x2f3/0x570
<4>[  676.833526]  do_vfs_ioctl+0x94/0x670
<4>[  676.833560]  ? entry_SYSCALL_64_fastpath+0x5/0xb1
<4>[  676.833593]  ? __this_cpu_preempt_check+0x13/0x20
<4>[  676.833625]  ? trace_hardirqs_on_caller+0xe3/0x1b0
<4>[  676.833664]  SyS_ioctl+0x41/0x70
<4>[  676.833705]  entry_SYSCALL_64_fastpath+0x1c/0xb1
<4>[  676.833735] RIP: 0033:0x7f0f14e7c587
<4>[  676.833761] RSP: 002b:00007ffc74b8a6a8 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
<4>[  676.833813] RAX: ffffffffffffffda RBX: ffffffff81493f33 RCX: 00007f0f14e7c587
<4>[  676.833840] RDX: 00007ffc74b8a6e0 RSI: 0000000040086409 RDI: 0000000000000007
<4>[  676.833866] RBP: ffffc90000997f88 R08: 000055ba33de36d0 R09: 0000000000000001
<4>[  676.833891] R10: 000000000009844a R11: 0000000000000246 R12: 0000000000000058
<4>[  676.833916] R13: 0000000000000007 R14: 0000000040086409 R15: 000055ba33deca20
<4>[  676.833957]  ? __this_cpu_preempt_check+0x13/0x20
<4>[  676.834098] 
<4>[  676.834098] Showing all locks held in the system:
<4>[  676.834151] 2 locks held by khungtaskd/38:
<4>[  676.834189]  #0:  (rcu_read_lock){....}, at: [<ffffffff81140303>] watchdog+0xa3/0x610
<4>[  676.834321]  #1:  (tasklist_lock){.+.+}, at: [<ffffffff810d982d>] debug_show_all_locks+0x3d/0x1a0
<4>[  676.834465] 1 lock held by in:imklog/388:
<4>[  676.834488]  #0:  (&f->f_pos_lock){+.+.}, at: [<ffffffff812449e9>] __fdget_pos+0x49/0x50
<4>[  676.834645] 1 lock held by gem_ppgtt/1590:
<4>[  676.834669]  #0:  (&dev->struct_mutex){+.+.}, at: [<ffffffffa0192a21>] i915_mutex_lock_interruptible+0x51/0x130 [i915]
<4>[  676.834916] 1 lock held by gem_ppgtt/1591:
<4>[  676.834939]  #0:  (&dev->struct_mutex){+.+.}, at: [<ffffffffa0192a21>] i915_mutex_lock_interruptible+0x51/0x130 [i915]
<4>[  676.835316] 1 lock held by gem_ppgtt/1592:
<4>[  676.835340]  #0:  (&dev->struct_mutex){+.+.}, at: [<ffffffffa0192a21>] i915_mutex_lock_interruptible+0x51/0x130 [i915]
<4>[  676.835563] 1 lock held by gem_ppgtt/1593:
<4>[  676.835586]  #0:  (&dev->struct_mutex){+.+.}, at: [<ffffffffa019b291>] i915_gem_close_object+0x41/0x1b0 [i915]
<4>[  676.835795] 1 lock held by gem_ppgtt/1594:
<4>[  676.835818]  #0:  (&dev->struct_mutex){+.+.}, at: [<ffffffffa0192a21>] i915_mutex_lock_interruptible+0x51/0x130 [i915]
<4>[  676.836135] 1 lock held by gem_ppgtt/1595:
<4>[  676.836162]  #0:  (&dev->struct_mutex){+.+.}, at: [<ffffffffa0192a21>] i915_mutex_lock_interruptible+0x51/0x130 [i915]
<4>[  676.836385] 1 lock held by gem_ppgtt/1596:
<4>[  676.836409]  #0:  (&dev->struct_mutex){+.+.}, at: [<ffffffffa0192a21>] i915_mutex_lock_interruptible+0x51/0x130 [i915]
<4>[  676.836613] 1 lock held by gem_ppgtt/1597:
<4>[  676.836636]  #0:  (&dev->struct_mutex){+.+.}, at: [<ffffffffa0192a21>] i915_mutex_lock_interruptible+0x51/0x130 [i915]
<4>[  676.836836] 1 lock held by gem_ppgtt/1598:
<4>[  676.836860]  #0:  (&dev->struct_mutex){+.+.}, at: [<ffffffffa0192a21>] i915_mutex_lock_interruptible+0x51/0x130 [i915]
<4>[  676.837075] 
<4>[  676.837079] =============================================
<4>[  676.837079] 
<4>[  676.837084] NMI backtrace for cpu 2
<4>[  676.837090] CPU: 2 PID: 38 Comm: khungtaskd Tainted: G     U          4.14.0-rc4-CI-CI_DRM_3241+ #1
<4>[  676.837095] Hardware name:                  /NUC7i5BNB, BIOS BNKBL357.86A.0048.2017.0704.1415 07/04/2017
<4>[  676.837099] Call Trace:
<4>[  676.837106]  dump_stack+0x68/0x9f
<4>[  676.837112]  nmi_cpu_backtrace+0xbe/0xc0
<4>[  676.837119]  ? irq_force_complete_move+0xe0/0xe0
<4>[  676.837124]  nmi_trigger_cpumask_backtrace+0xc0/0x100
<4>[  676.837131]  arch_trigger_cpumask_backtrace+0x19/0x20
<4>[  676.837136]  watchdog+0x454/0x610
<4>[  676.837143]  kthread+0x152/0x190
<4>[  676.837148]  ? reset_hung_task_detector+0x20/0x20
<4>[  676.837153]  ? kthread_create_on_node+0x40/0x40
<4>[  676.837159]  ? kthread_create_on_node+0x40/0x40
<4>[  676.837165]  ret_from_fork+0x27/0x40
<6>[  676.837176] Sending NMI from CPU 2 to CPUs 0-1,3:
<4>[  676.837183] NMI backtrace for cpu 0
<4>[  676.837185] CPU: 0 PID: 1062 Comm: dmesg Tainted: G     U          4.14.0-rc4-CI-CI_DRM_3241+ #1
<4>[  676.837185] Hardware name:                  /NUC7i5BNB, BIOS BNKBL357.86A.0048.2017.0704.1415 07/04/2017
<4>[  676.837186] task: ffff8802712d5440 task.stack: ffffc900008f8000
<4>[  676.837186] RIP: 0033:0x7f39e0698fb7
<4>[  676.837187] RSP: 002b:00007ffdb7486f80 EFLAGS: 00000212
<4>[  676.837188] RAX: 0000000000000005 RBX: 00007ffdb748704c RCX: 0000000000000000
<4>[  676.837188] RDX: 0000000000000001 RSI: 0000000000000001 RDI: 00007ffdb7487054
<4>[  676.837189] RBP: 000055f2a13080c4 R08: 0000000000000000 R09: 00007ffdb7486fa0
<4>[  676.837189] R10: 0000000000000005 R11: 0000000000000000 R12: 000055f2a13080cc
<4>[  676.837190] R13: 00007f39e0612380 R14: 000055f2a256bf80 R15: 000055f2a13080c4
<4>[  676.837190] FS:  00007f39e0fe8040(0000) GS:ffff88027ec00000(0000) knlGS:0000000000000000
<4>[  676.837191] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
<4>[  676.837192] CR2: 00007f5212bf8148 CR3: 000000025e845001 CR4: 00000000003606f0
<4>[  676.837193] NMI backtrace for cpu 1
<4>[  676.837194] CPU: 1 PID: 388 Comm: in:imklog Tainted: G     U          4.14.0-rc4-CI-CI_DRM_3241+ #1
<4>[  676.837194] Hardware name:                  /NUC7i5BNB, BIOS BNKBL357.86A.0048.2017.0704.1415 07/04/2017
<4>[  676.837195] task: ffff88026968d440 task.stack: ffffc9000057c000
<4>[  676.837197] RIP: 0010:__save_stack_trace+0x76/0xd0
<4>[  676.837198] RSP: 0018:ffffc9000057fb48 EFLAGS: 00000002
<4>[  676.837199] RAX: 0000000000000001 RBX: ffffc9000057fbe0 RCX: ffffc9000057ff50
<4>[  676.837199] RDX: 0000000000000001 RSI: ffffc9000057fb78 RDI: ffff88026968d440
<4>[  676.837200] RBP: ffffc9000057fbc0 R08: ffffc9000057ff40 R09: 000000000000005a
<4>[  676.837200] R10: 00000000000000bb R11: 000000005ba0b8e2 R12: 0000000000000000
<4>[  676.837201] R13: 0000000000000000 R14: ffff88026968d440 R15: ffff880275806a80
<4>[  676.837201] FS:  00007f3616a6a700(0000) GS:ffff88027ec80000(0000) knlGS:0000000000000000
<4>[  676.837202] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
<4>[  676.837202] CR2: 00007f5239de23a0 CR3: 000000026ef33004 CR4: 00000000003606e0
<4>[  676.837203] Call Trace:
<4>[  676.837205]  ? entry_SYSCALL_64_fastpath+0x1c/0xb1
<4>[  676.837207]  ? do_syslog+0x2ae/0x510
<4>[  676.837208]  ? do_syslog+0x2ae/0x510
<4>[  676.837209]  save_stack_trace+0x1b/0x20
<4>[  676.837211]  set_track+0x64/0x120
<4>[  676.837212]  alloc_debug_processing+0x16f/0x1b0
<4>[  676.837214]  ___slab_alloc.constprop.29+0x3ad/0x3d0
<4>[  676.837215]  ? do_syslog+0x2ae/0x510
<4>[  676.837216]  ? do_syslog+0x2ae/0x510
<4>[  676.837218]  ? do_syslog+0x2ae/0x510
<4>[  676.837219]  __slab_alloc.isra.23.constprop.28+0x48/0x80
<4>[  676.837219]  ? __slab_alloc.isra.23.constprop.28+0x48/0x80
<4>[  676.837220]  ? do_syslog+0x2ae/0x510
<4>[  676.837221]  kmem_cache_alloc_trace+0x233/0x2d0
<4>[  676.837223]  do_syslog+0x2ae/0x510
<4>[  676.837224]  kmsg_read+0x47/0x60
<4>[  676.837226]  proc_reg_read+0x42/0x70
<4>[  676.837227]  __vfs_read+0x28/0x130
<4>[  676.837228]  vfs_read+0xab/0x150
<4>[  676.837229]  SyS_read+0x49/0xb0
<4>[  676.837231]  entry_SYSCALL_64_fastpath+0x1c/0xb1
<4>[  676.837232] RIP: 0033:0x7f3618eb66ed
<4>[  676.837232] RSP: 002b:00007f3616a49580 EFLAGS: 00000293 ORIG_RAX: 0000000000000000
<4>[  676.837233] RAX: ffffffffffffffda RBX: ffffffff81493f33 RCX: 00007f3618eb66ed
<4>[  676.837233] RDX: 0000000000001fa0 RSI: 00007f3616a49da0 RDI: 0000000000000004
<4>[  676.837234] RBP: ffffc9000057ff88 R08: 0000000000000000 R09: 0000000000000000
<4>[  676.837234] R10: 2ce33e6c02ce33e7 R11: 0000000000000293 R12: 0000000000001f9f
<4>[  676.837235] R13: 0000000000001fa0 R14: 00007f3616a49da0 R15: 0000000000000000
<4>[  676.837236]  ? __this_cpu_preempt_check+0x13/0x20
<4>[  676.837237] Code: 91 c4 01 00 8b 55 88 85 d2 75 24 eb 30 44 89 e2 48 89 c6 48 89 df e8 2a ff ff ff 85 c0 75 1e 48 8d 7d 88 e8 4d c4 01 00 8b 45 88 <85> c0 74 0e 48 8d 7d 88 e8 0d c2 01 00 48 85 c0 75 d0 8b 03 3b 
<4>[  676.837251] NMI backtrace for cpu 3
<4>[  676.837252] CPU: 3 PID: 183 Comm: systemd-journal Tainted: G     U          4.14.0-rc4-CI-CI_DRM_3241+ #1
<4>[  676.837253] Hardware name:                  /NUC7i5BNB, BIOS BNKBL357.86A.0048.2017.0704.1415 07/04/2017
<4>[  676.837253] task: ffff880272e42a40 task.stack: ffffc90000298000
<4>[  676.837256] RIP: 0010:___bpf_prog_run+0x8c1/0x11f0
<4>[  676.837257] RSP: 0018:ffffc9000029bcd0 EFLAGS: 00000202
<4>[  676.837258] RAX: 000000000000005d RBX: ffffc90000089058 RCX: 0000000000000004
<4>[  676.837259] RDX: 0000000000000000 RSI: 00000000c000003e RDI: ffffc9000029bd28
<4>[  676.837260] RBP: ffffc9000029bcf8 R08: 0000000000002000 R09: 0000000000000000
<4>[  676.837260] R10: 0000000000000000 R11: 0000000000000000 R12: ffffc9000029bd28
<4>[  676.837262] R13: ffffffff81a17a40 R14: 0000000000000000 R15: 0000000000000100
<4>[  676.837262] FS:  00007f807849e8c0(0000) GS:ffff88027ed80000(0000) knlGS:0000000000000000
<4>[  676.837264] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
<4>[  676.837264] CR2: 00007f52137b4c38 CR3: 0000000272cd8005 CR4: 00000000003606e0
<4>[  676.837265] Call Trace:
<4>[  676.837267]  __bpf_prog_run32+0x2a/0x30
<4>[  676.837269]  ? _raw_spin_unlock_irqrestore+0x57/0x70
<4>[  676.837271]  seccomp_run_filters+0x48/0x120
<4>[  676.837273]  ? trace_hardirqs_on+0xd/0x10
<4>[  676.837274]  ? _raw_spin_unlock_irqrestore+0x42/0x70
<4>[  676.837276]  ? debug_object_active_state+0xfa/0x140
<4>[  676.837278]  __seccomp_filter+0x35/0x250
<4>[  676.837279]  ? __this_cpu_preempt_check+0x13/0x20
<4>[  676.837281]  ? trace_hardirqs_on_caller+0xe3/0x1b0
<4>[  676.837282]  ? trace_hardirqs_on+0xd/0x10
<4>[  676.837285]  __secure_computing+0x35/0xb0
<4>[  676.837286]  syscall_trace_enter+0xc2/0x350
<4>[  676.837289]  do_syscall_64+0xfe/0x170
<4>[  676.837291]  entry_SYSCALL64_slow_path+0x25/0x25
<4>[  676.837292] RIP: 0033:0x7f8077776607
<4>[  676.837292] RSP: 002b:00007ffdfb5275e8 EFLAGS: 00000293 ORIG_RAX: 0000000000000053
<4>[  676.837294] RAX: ffffffffffffffda RBX: 00007ffdfb52a4f0 RCX: 00007f8077776607
<4>[  676.837294] RDX: 00007f80781e61c0 RSI: 00000000000001ed RDI: 00005648b1d867a0
<4>[  676.837295] RBP: 00007ffdfb527620 R08: 0000000000002000 R09: 0000000000000000
<4>[  676.837296] R10: 0000000000000080 R11: 0000000000000293 R12: 0000000000000000
<4>[  676.837296] R13: 0000000000000000 R14: 00007ffdfb52a4f0 R15: 0000000000000009
<4>[  676.837298] Code: c3 08 0f b6 03 41 ff 64 c5 00 0f b6 43 01 48 63 53 04 83 e0 0f 49 39 14 c4 0f 84 ba 08 00 00 48 83 c3 08 0f b6 03 41 ff 64 c5 00 <0f> b6 43 01 48 89 c2 c0 e8 04 83 e2 0f 0f b6 c0 49 8b 04 c4 49 
<0>[  676.838202] Kernel panic - not syncing: hung_task: blocked tasks
<4>[  676.838228] CPU: 2 PID: 38 Comm: khungtaskd Tainted: G     U          4.14.0-rc4-CI-CI_DRM_3241+ #1
<4>[  676.838260] Hardware name:                  /NUC7i5BNB, BIOS BNKBL357.86A.0048.2017.0704.1415 07/04/2017
<4>[  676.838294] Call Trace:
<4>[  676.838309]  dump_stack+0x68/0x9f
<4>[  676.838326]  panic+0xd4/0x21d
<4>[  676.838345]  watchdog+0x460/0x610
<4>[  676.838364]  kthread+0x152/0x190
<4>[  676.838380]  ? reset_hung_task_detector+0x20/0x20
<4>[  676.838401]  ? kthread_create_on_node+0x40/0x40
<4>[  676.838421]  ? kthread_create_on_node+0x40/0x40
<4>[  676.838442]  ret_from_fork+0x27/0x40
<0>[  676.838721] Kernel Offset: disabled
Comment 1 Chris Wilson 2017-10-17 07:58:53 UTC 

*** This bug has been marked as a duplicate of bug 103170 ***
Comment 2 Marta Löfstedt 2017-10-17 11:28:16 UTC 
This bug has pstore log, so it is NOT a duplicate of bug 103170. BUG 103170 is about incompletes who are either timeouts or system hangs, where we don't have pstore logs and can only guess if it was timeout or system hang incomplete.
Comment 3 Chris Wilson 2017-10-17 13:13:16 UTC 
(In reply to Marta Löfstedt from comment #2)
> This bug has pstore log, so it is NOT a duplicate of bug 103170. BUG 103170
> is about incompletes who are either timeouts or system hangs, where we don't
> have pstore logs and can only guess if it was timeout or system hang
> incomplete.
Comment 4 Marta Löfstedt 2017-10-19 12:30:37 UTC 
(In reply to Chris Wilson from comment #3)
> (In reply to Marta Löfstedt from comment #2)
> > This bug has pstore log, so it is NOT a duplicate of bug 103170. BUG 103170
> > is about incompletes who are either timeouts or system hangs, where we don't
> > have pstore logs and can only guess if it was timeout or system hang
> > incomplete.

Chris what where you saying?

Use of freedesktop.org services, including Bugzilla, is subject to our Code of Conduct. How we collect and use information is described in our Privacy Policy.