Bug 104479

Summary: [CI] igt@kms_cursor_legacy@all-pipes-single-move - Incomplete - INFO: task kswapd0:52 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 DUPLICATE 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: GLK i915 features: display/atomic

Description Marta Löfstedt 2018-01-03 14:05:31 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/IGT_4109/shard-glkb6/igt@kms_cursor_legacy@all-pipes-single-move.html

<7>[  115.915180] [drm:gen9_set_dc_state [i915]] Setting DC state from 00 to 01
<3>[  123.918946] INFO: task kswapd0:52 blocked for more than 60 seconds.
<3>[  123.918960]       Tainted: G     U           4.15.0-rc6-CI-CI_DRM_3589+ #1
<3>[  123.918963] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
<6>[  123.918967] kswapd0         D    0    52      2 0x80000000
<4>[  123.918973] Call Trace:
<4>[  123.918985]  ? __schedule+0x3c3/0xaf0
<4>[  123.918994]  schedule+0x37/0x90
<4>[  123.919000]  io_schedule+0xd/0x30
<4>[  123.919005]  __lock_page+0x107/0x130
<4>[  123.919011]  ? add_to_page_cache_lru+0xc0/0xc0
<4>[  123.919019]  deferred_split_scan+0x25a/0x2b0
<4>[  123.919027]  shrink_slab.part.17+0x201/0x5d0
<4>[  123.919041]  shrink_node+0x2fd/0x310
<4>[  123.919050]  kswapd+0x31c/0x910
<4>[  123.919064]  kthread+0xfb/0x130
<4>[  123.919067]  ? mem_cgroup_shrink_node+0x300/0x300
<4>[  123.919070]  ? _kthread_create_on_node+0x30/0x30
<4>[  123.919075]  ret_from_fork+0x24/0x30
<4>[  123.919087] 
<4>[  123.919087] Showing all locks held in the system:
<4>[  123.919092] 2 locks held by khungtaskd/39:
<4>[  123.919097]  #0:  (rcu_read_lock){....}, at: [<0000000013272121>] watchdog+0x9b/0x5e0
<4>[  123.919111]  #1:  (tasklist_lock){.+.+}, at: [<000000004959d449>] debug_show_all_locks+0x37/0x190
<4>[  123.919125] 1 lock held by kswapd0/52:
<4>[  123.919127]  #0:  (shrinker_rwsem){++++}, at: [<00000000dd3d5ed5>] shrink_slab.part.17+0x46/0x5d0
<4>[  123.919158] 1 lock held by in:imklog/572:
<4>[  123.919160]  #0:  (&f->f_pos_lock){+.+.}, at: [<00000000bc87fec0>] __fdget_pos+0x3a/0x50
<4>[  123.919185] 1 lock held by dmesg/1126:
<4>[  123.919187]  #0:  (&user->lock){+.+.}, at: [<000000005b6470df>] devkmsg_read+0x35/0x2f0
<4>[  123.919202] 
<4>[  123.919204] =============================================
<4>[  123.919204] 
<4>[  123.919207] NMI backtrace for cpu 1
<4>[  123.919211] CPU: 1 PID: 39 Comm: khungtaskd Tainted: G     U           4.15.0-rc6-CI-CI_DRM_3589+ #1
<4>[  123.919213] Hardware name: Intel Corp. Geminilake/GLK RVP2 LP4SD (07), BIOS GELKRVPA.X64.0069.B31.1710111133 10/11/2017
<4>[  123.919215] Call Trace:
<4>[  123.919220]  dump_stack+0x5f/0x86
<4>[  123.919225]  nmi_cpu_backtrace+0xb4/0xc0
<4>[  123.919230]  ? lapic_can_unplug_cpu+0x90/0x90
<4>[  123.919234]  nmi_trigger_cpumask_backtrace+0xb8/0xf0
<4>[  123.919238]  watchdog+0x43e/0x5e0
<4>[  123.919245]  kthread+0xfb/0x130
<4>[  123.919247]  ? reset_hung_task_detector+0x10/0x10
<4>[  123.919250]  ? _kthread_create_on_node+0x30/0x30
<4>[  123.919255]  ret_from_fork+0x24/0x30
<6>[  123.919267] Sending NMI from CPU 1 to CPUs 0,2-3:
<4>[  123.919272] NMI backtrace for cpu 0
<4>[  123.919274] CPU: 0 PID: 1473 Comm: kms_cursor_lega Tainted: G     U           4.15.0-rc6-CI-CI_DRM_3589+ #1
<4>[  123.919274] Hardware name: Intel Corp. Geminilake/GLK RVP2 LP4SD (07), BIOS GELKRVPA.X64.0069.B31.1710111133 10/11/2017
<4>[  123.919277] RIP: 0010:lock_release+0x2e/0x300
<4>[  123.919278] RSP: 0018:ffffc90000bbba08 EFLAGS: 00000082
<4>[  123.919279] RAX: ffff880171de2740 RBX: ffffffff82289bc0 RCX: ffff880166a1ed40
<4>[  123.919280] RDX: ffffffff8145d3c1 RSI: 0000000000000001 RDI: ffffffff82289bd8
<4>[  123.919280] RBP: ffffffff82289bd8 R08: ffff880171de3068 R09: 00000000d615ee8d
<4>[  123.919281] R10: 0000000000000000 R11: 0000000000000003 R12: ffffffff8145d3c1
<4>[  123.919281] R13: 0000000000000082 R14: 00000000000f9d40 R15: ffff8801714398b0
<4>[  123.919282] FS:  00007f4470bf4a40(0000) GS:ffff88017fc00000(0000) knlGS:0000000000000000
<4>[  123.919283] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
<4>[  123.919283] CR2: 00007f446edf3580 CR3: 00000001784f6000 CR4: 0000000000340ef0
<4>[  123.919284] Call Trace:
<4>[  123.919287]  _raw_spin_unlock+0x17/0x40
<4>[  123.919290]  __debug_object_init+0x171/0x430
<4>[  123.919371]  ? haswell_crtc_compute_clock+0x5c/0x5c [i915]
<4>[  123.919402]  __i915_sw_fence_init+0x29/0x50 [i915]
<4>[  123.919440]  intel_atomic_commit+0x49/0x320 [i915]
<4>[  123.919444]  drm_atomic_helper_update_plane+0xeb/0x100
<4>[  123.919465]  __setplane_internal+0x193/0x260
<4>[  123.919467]  ? __mutex_lock+0x432/0x9b0
<4>[  123.919468]  ? drm_mode_cursor_common+0x7a/0x1d0
<4>[  123.919470]  ? drm_modeset_lock+0x3b/0x110
<4>[  123.919472]  drm_mode_cursor_universal+0xdc/0x1c0
<4>[  123.919474]  drm_mode_cursor_common+0x168/0x1d0
<4>[  123.919476]  ? drm_mode_setplane+0x1a0/0x1a0
<4>[  123.919477]  drm_mode_cursor_ioctl+0x3f/0x50
<4>[  123.919480]  drm_ioctl_kernel+0x60/0xa0
<4>[  123.919481]  drm_ioctl+0x290/0x330
<4>[  123.919482]  ? drm_mode_setplane+0x1a0/0x1a0
<4>[  123.919485]  ? lock_acquire+0xaf/0x200
<4>[  123.919487]  do_vfs_ioctl+0x8a/0x670
<4>[  123.919489]  ? entry_SYSCALL_64_fastpath+0x5/0x89
<4>[  123.919490]  ? trace_hardirqs_on_caller+0xde/0x1c0
<4>[  123.919492]  SyS_ioctl+0x36/0x70
<4>[  123.919493]  entry_SYSCALL_64_fastpath+0x1c/0x89

Since igt@gem_tiled_swapping@non-threaded was run before this test, maybe this is related to bug 104218.
Comment 1 Chris Wilson 2018-01-03 18:28:15 UTC
(In reply to Marta Löfstedt from comment #0)
> https://intel-gfx-ci.01.org/tree/drm-tip/IGT_4109/shard-glkb6/
> igt@kms_cursor_legacy@all-pipes-single-move.html
> 
> <7>[  115.915180] [drm:gen9_set_dc_state [i915]] Setting DC state from 00 to
> 01
> <3>[  123.918946] INFO: task kswapd0:52 blocked for more than 60 seconds.
> <3>[  123.918960]       Tainted: G     U          
> 4.15.0-rc6-CI-CI_DRM_3589+ #1
> <3>[  123.918963] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
> disables this message.
> <6>[  123.918967] kswapd0         D    0    52      2 0x80000000
> <4>[  123.918973] Call Trace:
> <4>[  123.918985]  ? __schedule+0x3c3/0xaf0
> <4>[  123.918994]  schedule+0x37/0x90
> <4>[  123.919000]  io_schedule+0xd/0x30
> <4>[  123.919005]  __lock_page+0x107/0x130
> <4>[  123.919011]  ? add_to_page_cache_lru+0xc0/0xc0
> <4>[  123.919019]  deferred_split_scan+0x25a/0x2b0
> <4>[  123.919027]  shrink_slab.part.17+0x201/0x5d0
> <4>[  123.919041]  shrink_node+0x2fd/0x310
> <4>[  123.919050]  kswapd+0x31c/0x910
> <4>[  123.919064]  kthread+0xfb/0x130
> <4>[  123.919067]  ? mem_cgroup_shrink_node+0x300/0x300
> <4>[  123.919070]  ? _kthread_create_on_node+0x30/0x30
> <4>[  123.919075]  ret_from_fork+0x24/0x30
...
> Since igt@gem_tiled_swapping@non-threaded was run before this test, maybe
> this is related to bug 104218.

That seems very likely, the same waiting for deferred_split_scan::lock_page with nothing on the other cpus that would appear to be keeping a page locked.
Comment 2 Marta Löfstedt 2018-01-23 07:44:34 UTC

*** This bug has been marked as a duplicate of bug 104218 ***

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.