Bug 104218 - [CI] igt@gem_tiled_swapping@non-threaded - cause incompletes on following tests
Summary: [CI] igt@gem_tiled_swapping@non-threaded - cause incompletes on following tests
Status: CLOSED WORKSFORME
Alias: None
Product: DRI
Classification: Unclassified
Component: DRM/Intel (show other bugs)
Version: DRI git
Hardware: Other All
: medium normal
Assignee: Marta Löfstedt
QA Contact: Intel GFX Bugs mailing list
URL:
Whiteboard: ReadyForDev
Keywords:
: 103525 104009 104479 (view as bug list)
Depends on:
Blocks:
 
Reported: 2017-12-12 07:39 UTC by Marta Löfstedt
Modified: 2018-01-26 08:26 UTC (History)
1 user (show)

See Also:
i915 platform: HSW, SNB
i915 features: GEM/Other


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Marta Löfstedt 2017-12-12 07:39:33 UTC
These HSW-shards incompletes has igt@gem_tiled_swapping@non-threaded as last test in run.log, however the incomplete is linked to tests running after.

https://intel-gfx-ci.01.org/tree/drm-tip/IGT_4052/shard-hsw7/igt@gem_exec_flush@basic-wb-pro-default.html
https://intel-gfx-ci.01.org/tree/drm-tip/IGT_4050/shard-hsw3/igt@kms_flip@absolute-wf_vblank.html
https://intel-gfx-ci.01.org/tree/drm-tip/IGT_4057/shard-hsw6/igt@gem_exec_flush@basic-uc-set-default.html
https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_3499/shard-hsw6/igt@perf_pmu@render-node-busy-vcs0.html

I use bug 103540 for generic HSW incompletes timeout/system hang, but decided to unduplicate above due to the pattern with igt@gem_tiled_swapping@non-threaded.
Comment 1 Marta Löfstedt 2017-12-12 07:45:24 UTC
Also see bug 104009 and bug 103525
Comment 2 Chris Wilson 2017-12-12 09:12:53 UTC
Note bug 103525 has the most likely clue:

<14>[  495.250162] [IGT] gem_tiled_swapping: executing
<3>[  615.691911] INFO: task gem_tiled_swapp:6686 blocked for more than 60 seconds.
<3>[  615.691963]       Tainted: G     U          4.14.0-rc6-CI-CI_DRM_3294+ #1
<3>[  615.691996] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
<6>[  615.692033] gem_tiled_swapp D    0  6686   3317 0x00000000
<4>[  615.692042] Call Trace:
<4>[  615.692054]  __schedule+0x3c3/0xaf0
<4>[  615.692064]  schedule+0x40/0x90
<4>[  615.692071]  io_schedule+0x16/0x40
<4>[  615.692077]  __lock_page+0x10d/0x140
<4>[  615.692085]  ? add_to_page_cache_lru+0xd0/0xd0
<4>[  615.692094]  deferred_split_scan+0x25e/0x2b0
<4>[  615.692104]  shrink_slab.part.17+0x202/0x5e0
<4>[  615.692118]  shrink_node+0x2f7/0x300
<4>[  615.692129]  do_try_to_free_pages+0xc6/0x310
<4>[  615.692138]  try_to_free_pages+0x122/0x330
<4>[  615.692147]  __alloc_pages_nodemask+0x6f9/0x1380
<4>[  615.692167]  ksm_might_need_to_copy+0x84/0x210
<4>[  615.692176]  do_swap_page+0x1c0/0x7f0
<4>[  615.692185]  __handle_mm_fault+0x7ef/0xed0
<4>[  615.692198]  handle_mm_fault+0x156/0x300
<4>[  615.692204]  __get_user_pages+0x10a/0x5c0
<4>[  615.692210]  ? lock_acquire+0xb0/0x200
<4>[  615.692221]  populate_vma_page_range+0x71/0x80
<4>[  615.692226]  __mm_populate+0x97/0x110
<4>[  615.692233]  do_mlock+0xf5/0x230
<4>[  615.692240]  SyS_mlock+0x13/0x20
<4>[  615.692247]  entry_SYSCALL_64_fastpath+0x1c/0xb1
<4>[  615.692251] RIP: 0033:0x7fdabda9cdc7
<4>[  615.692254] RSP: 002b:00007ffee3c75e28 EFLAGS: 00000246 ORIG_RAX: 0000000000000095
<4>[  615.692261] RAX: ffffffffffffffda RBX: ffffffff81491ef3 RCX: 00007fdabda9cdc7
<4>[  615.692265] RDX: 0000000000000000 RSI: 00000003a9100000 RDI: 00007fd71367c010
<4>[  615.692268] RBP: ffffc90000707f88 R08: 0000561cce907480 R09: 0000000000000000
<4>[  615.692271] R10: 0000000000000073 R11: 0000000000000246 R12: 0000000000000000
<4>[  615.692275] R13: 00007ffee3c75fc0 R14: 0000000000000003 R15: 0000000000001000
<4>[  615.692282]  ? __this_cpu_preempt_check+0x13/0x20
<4>[  615.692290] 
<4>[  615.692290] Showing all locks held in the system:
<4>[  615.692305] 2 locks held by khungtaskd/66:
<4>[  615.692312]  #0:  (rcu_read_lock){....}, at: [<ffffffff8113f083>] watchdog+0xa3/0x610
<4>[  615.692331]  #1:  (tasklist_lock){.+.+}, at: [<ffffffff810d945d>] debug_show_all_locks+0x3d/0x1a0
<4>[  615.692358] 1 lock held by in:imklog/538:
<4>[  615.692361]  #0:  (&f->f_pos_lock){+.+.}, at: [<ffffffff81243233>] __fdget_pos+0x43/0x50
<4>[  615.692390] 1 lock held by dmesg/3085:
<4>[  615.692393]  #0:  (&user->lock){+.+.}, at: [<ffffffff810eefce>] devkmsg_read+0x3e/0x300
<4>[  615.692419] 2 locks held by gem_tiled_swapp/6686:
<4>[  615.692422]  #0:  (&mm->mmap_sem){++++}, at: [<ffffffff811cbb73>] __mm_populate+0xc3/0x110
<4>[  615.692438]  #1:  (shrinker_rwsem){++++}, at: [<ffffffff811a8dff>] shrink_slab.part.17+0x4f/0x5e0
<4>[  615.692456] 
<4>[  615.692459] =============================================
<4>[  615.692459] 
<4>[  615.692463] NMI backtrace for cpu 5
<4>[  615.692468] CPU: 5 PID: 66 Comm: khungtaskd Tainted: G     U          4.14.0-rc6-CI-CI_DRM_3294+ #1
<4>[  615.692471] Hardware name: MSI MS-7924/Z97M-G43(MS-7924), BIOS V1.12 02/15/2016
<4>[  615.692474] Call Trace:
<4>[  615.692481]  dump_stack+0x68/0x9f
<4>[  615.692487]  nmi_cpu_backtrace+0xbe/0xc0
<4>[  615.692495]  ? irq_force_complete_move+0xe0/0xe0
<4>[  615.692499]  nmi_trigger_cpumask_backtrace+0xc0/0x100
<4>[  615.692506]  arch_trigger_cpumask_backtrace+0x19/0x20
<4>[  615.692510]  watchdog+0x454/0x610
<4>[  615.692517]  kthread+0x114/0x150
<4>[  615.692521]  ? reset_hung_task_detector+0x20/0x20
<4>[  615.692525]  ? kthread_create_on_node+0x40/0x40
<4>[  615.692532]  ret_from_fork+0x27/0x40
<6>[  615.692544] Sending NMI from CPU 5 to CPUs 0-4,6-7:
<4>[  615.692557] NMI backtrace for cpu 1 skipped: idling at pc 0xffffffff819106fe
<4>[  615.692574] NMI backtrace for cpu 6 skipped: idling at pc 0xffffffff819106fe
<4>[  615.692578] NMI backtrace for cpu 0 skipped: idling at pc 0xffffffff819106fe
<4>[  615.692582] NMI backtrace for cpu 2 skipped: idling at pc 0xffffffff819106fe
<4>[  615.692586] NMI backtrace for cpu 4 skipped: idling at pc 0xffffffff819106fe
<4>[  615.692591] NMI backtrace for cpu 7 skipped: idling at pc 0xffffffff819106fe
<4>[  615.692595] NMI backtrace for cpu 3 skipped: idling at pc 0xffffffff819106fe
<0>[  615.693737] Kernel panic - not syncing: hung_task: blocked tasks
<4>[  615.693795] CPU: 5 PID: 66 Comm: khungtaskd Tainted: G     U          4.14.0-rc6-CI-CI_DRM_3294+ #1
<4>[  615.693872] Hardware name: MSI MS-7924/Z97M-G43(MS-7924), BIOS V1.12 02/15/2016
<4>[  615.693936] Call Trace:
<4>[  615.693966]  dump_stack+0x68/0x9f
<4>[  615.694002]  panic+0xd4/0x21d
<4>[  615.694041]  watchdog+0x460/0x610
<4>[  615.694079]  kthread+0x114/0x150
<4>[  615.694111]  ? reset_hung_task_detector+0x20/0x20
<4>[  615.694155]  ? kthread_create_on_node+0x40/0x40
<4>[  615.694200]  ret_from_fork+0x27/0x40
<0>[  615.694959] Kernel Offset: disabled
Comment 3 Marta Löfstedt 2017-12-13 06:53:23 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_3503/shard-hsw8/igt@gem_pwrite@huge-gtt-backwards.html

Again run.log:
running: igt/gem_tiled_swapping/non-threaded

[45/77] skip: 18, pass: 27 /                
FATAL: command execution failed
java.io.EOFException

but igt@gem_pwrite@huge-gtt-backwards is last in results.

from dmesg:
<7>[  302.516333] [IGT] gem_tiled_swapping: executing
<6>[  302.540194] gem_tiled_swapp (1691): drop_caches: 4
<7>[  304.318540] [IGT] gem_tiled_swapping: starting subtest non-threaded
<7>[  328.341323] [IGT] gem_tiled_swapping: exiting, ret=0
...
see nothing special
last dmesg:
<7>[  330.450679] [IGT] gem_exec_reloc: exiting, ret=0
<7>[  330.589845] [IGT] gem_pwrite: executing
<7>[  330.605445] [IGT] gem_pwrite: starting subtest huge-gtt-backwards
Comment 4 Marta Löfstedt 2017-12-14 12:39:20 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/IGT_4063/shard-hsw7/igt@gem_tiled_pread_basic.html

from pstore:
<14>[   56.825306] [IGT] gem_tiled_swapping: exiting, ret=0
<14>[   57.631391] [IGT] gem_tiled_pread_basic: executing
<3>[  123.820940] INFO: task kswapd0:80 blocked for more than 60 seconds.
<3>[  123.820963]       Tainted: G     U           4.15.0-rc3-CI-CI_DRM_3513+ #1
<3>[  123.820983] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
<6>[  123.821006] kswapd0         D    0    80      2 0x80000000
<4>[  123.821011] Call Trace:
<4>[  123.821019]  ? __schedule+0x3c3/0xaf0
<4>[  123.821027]  schedule+0x37/0x90
<4>[  123.821031]  io_schedule+0xd/0x30
<4>[  123.821034]  __lock_page+0x107/0x130
<4>[  123.821039]  ? add_to_page_cache_lru+0xc0/0xc0
<4>[  123.821046]  deferred_split_scan+0x25a/0x2b0
<4>[  123.821053]  shrink_slab.part.17+0x201/0x5d0
<4>[  123.821065]  shrink_node+0x2fd/0x310
<4>[  123.821073]  kswapd+0x31c/0x910
<4>[  123.821085]  kthread+0x173/0x1b0
<4>[  123.821088]  ? mem_cgroup_shrink_node+0x300/0x300
<4>[  123.821090]  ? _kthread_create_on_node+0x30/0x30
<4>[  123.821095]  ret_from_fork+0x24/0x30
<4>[  123.821105] 
<4>[  123.821105] Showing all locks held in the system:
<4>[  123.821113] 2 locks held by khungtaskd/67:
<4>[  123.821116]  #0:  (rcu_read_lock){....}, at: [<00000000899df8e4>] watchdog+0x9b/0x5e0
<4>[  123.821127]  #1:  (tasklist_lock){.+.+}, at: [<00000000bcdb3c63>] debug_show_all_locks+0x37/0x190
<4>[  123.821139] 1 lock held by kswapd0/80:
<4>[  123.821141]  #0:  (shrinker_rwsem){++++}, at: [<000000008a60ca11>] shrink_slab.part.17+0x46/0x5d0
<4>[  123.821157] 1 lock held by in:imklog/593:
<4>[  123.821159]  #0:  (&f->f_pos_lock){+.+.}, at: [<00000000109958e5>] __fdget_pos+0x40/0x50
<4>[  123.821172] 2 locks held by systemd-hostnam/767:
<4>[  123.821174]  #0:  (&type->s_umount_key#29){++++}, at: [<000000005dafd8e5>] deactivate_super+0x3e/0x50
<4>[  123.821185]  #1:  (shrinker_rwsem){++++}, at: [<00000000771ee75f>] unregister_shrinker+0x10/0x60
<4>[  123.821198] 1 lock held by dmesg/1079:
<4>[  123.821200]  #0:  (&user->lock){+.+.}, at: [<00000000eb7fbce0>] devkmsg_read+0x35/0x2f0
<4>[  123.821213] 1 lock held by gem_tiled_pread/1526:
<4>[  123.821214]  #0:  (&type->s_umount_key#29){++++}, at: [<00000000c0065d2f>] iterate_supers+0x8d/0xf0

but igt@gem_tiled_swapping@non-threaded is last in run.log and we appear to run out of mem:
<7>[   22.506021] [IGT] gem_tiled_swapping: executing
<6>[   22.531591] gem_tiled_swapp (1433): drop_caches: 4
<7>[   24.044626] [IGT] gem_tiled_swapping: starting subtest non-threaded
<5>[   24.206026] random: crng init done
<6>[   38.088325] Purging GPU memory, 51712 pages freed, 935 pages still pinned.
<6>[   41.465720] Purging GPU memory, 52224 pages freed, 935 pages still pinned.
<6>[   44.272472] Purging GPU memory, 51968 pages freed, 935 pages still pinned.
<4>[   47.709105] gem_tiled_swapp: page allocation failure: order:0, mode:0x14204d2(GFP_HIGHUSER|__GFP_RETRY_MAYFAIL|__GFP_RECLAIMABLE), nodemask=(null)
<4>[   47.709131] CPU: 5 PID: 1433 Comm: gem_tiled_swapp Tainted: G     U           4.15.0-rc3-CI-CI_DRM_3513+ #1
<4>[   47.709133] Hardware name: MSI MS-7924/Z97M-G43(MS-7924), BIOS V1.12 02/15/2016
<4>[   47.709135] Call Trace:
<4>[   47.709141]  dump_stack+0x5f/0x86
<4>[   47.709146]  warn_alloc+0xad/0x130
<4>[   47.709153]  ? __mutex_unlock_slowpath+0x38/0x270
<4>[   47.709159]  __alloc_pages_nodemask+0xeb5/0x11d0
<4>[   47.709175]  __read_swap_cache_async+0x146/0x250
<4>[   47.709180]  swapin_readahead+0x14b/0x230
<4>[   47.709191]  ? shmem_swapin+0x40/0x50
<4>[   47.709194]  shmem_swapin+0x40/0x50
<4>[   47.709198]  ? find_get_entry+0x160/0x210
<4>[   47.709202]  ? pagecache_get_page+0x2b/0x230
<4>[   47.709207]  ? lookup_swap_cache+0x46/0x100
<4>[   47.709211]  shmem_getpage_gfp.isra.9+0x925/0xc90
<4>[   47.709222]  shmem_read_mapping_page_gfp+0x2e/0x50
<4>[   47.709251]  i915_gem_object_get_pages_gtt+0x13b/0x660 [i915]
<4>[   47.709278]  ? i915_gem_obj_prepare_shmem_write+0x190/0x220 [i915]
<4>[   47.709299]  ____i915_gem_object_get_pages+0x17/0x70 [i915]
<4>[   47.709318]  __i915_gem_object_get_pages+0x59/0x80 [i915]
<4>[   47.709339]  i915_gem_set_domain_ioctl+0x377/0x3e0 [i915]
<4>[   47.709359]  ? i915_gem_obj_prepare_shmem_write+0x220/0x220 [i915]
<4>[   47.709363]  drm_ioctl_kernel+0x60/0xa0
<4>[   47.709367]  drm_ioctl+0x290/0x330
<4>[   47.709387]  ? i915_gem_obj_prepare_shmem_write+0x220/0x220 [i915]
<4>[   47.709392]  ? vm_mmap_pgoff+0xa1/0xd0
<4>[   47.709401]  do_vfs_ioctl+0x8a/0x680
<4>[   47.709404]  ? entry_SYSCALL_64_fastpath+0x5/0x89
<4>[   47.709408]  ? trace_hardirqs_on_caller+0xde/0x1c0
<4>[   47.709413]  SyS_ioctl+0x36/0x70
<4>[   47.709417]  entry_SYSCALL_64_fastpath+0x1c/0x89
<4>[   47.709420] RIP: 0033:0x7f4ed426a587
<4>[   47.709422] RSP: 002b:00007fffba7f6cc8 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
<4>[   47.709425] RAX: ffffffffffffffda RBX: 0000000000000026 RCX: 00007f4ed426a587
<4>[   47.709427] RDX: 00007fffba7f6d0c RSI: 00000000400c645f RDI: 0000000000000003
<4>[   47.709429] RBP: 0000000000000098 R08: 0000000000000003 R09: 000000010fa00000
<4>[   47.709431] R10: 0000000000000001 R11: 0000000000000246 R12: 000055a474724240
<4>[   47.709433] R13: 00007f4ed5c5d000 R14: 0000000000000003 R15: 000000000000025f
<4>[   47.709461] Mem-Info:
<4>[   47.709465] active_anon:2810 inactive_anon:53101 isolated_anon:32
                   active_file:79 inactive_file:76 isolated_file:0
                   unevictable:3836673 dirty:5 writeback:0 unstable:0
                   slab_reclaimable:7694 slab_unreclaimable:16315
                   mapped:1000 shmem:53120 pagetables:8816 bounce:0
                   free:33343 free_pcp:30 free_cma:0
<4>[   47.709469] Node 0 active_anon:11240kB inactive_anon:212404kB active_file:316kB inactive_file:304kB unevictable:15346692kB isolated(anon):128kB isolated(file):0kB mapped:4000kB dirty:20kB writeback:0kB shmem:212480kB shmem_thp: 0kB shmem_pmdmapped: 0kB anon_thp: 14948352kB writeback_tmp:0kB unstable:0kB all_unreclaimable? no
<4>[   47.709472] DMA free:15884kB min:64kB low:80kB high:96kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB writepending:0kB present:15988kB managed:15884kB mlocked:0kB kernel_stack:0kB pagetables:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
<4>[   47.709474] lowmem_reserve[]: 0 2894 15416 15416
<4>[   47.709485] DMA32 free:62488kB min:12676kB low:15844kB high:19012kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:2970008kB writepending:0kB present:3077188kB managed:3032508kB mlocked:2970008kB kernel_stack:0kB pagetables:8kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
<4>[   47.709487] lowmem_reserve[]: 0 0 12522 12522
<4>[   47.709498] Normal free:55000kB min:54836kB low:68544kB high:82252kB active_anon:11240kB inactive_anon:212404kB active_file:316kB inactive_file:304kB unevictable:12376684kB writepending:20kB present:13105152kB managed:12823268kB mlocked:12376684kB kernel_stack:3760kB pagetables:35256kB bounce:0kB free_pcp:120kB local_pcp:0kB free_cma:0kB
<4>[   47.709500] lowmem_reserve[]: 0 0 0 0
<4>[   47.709509] DMA: 3*4kB (U) 2*8kB (U) 3*16kB (U) 0*32kB 3*64kB (U) 2*128kB (U) 0*256kB 0*512kB 1*1024kB (U) 1*2048kB (M) 3*4096kB (M) = 15884kB
<4>[   47.709544] DMA32: 4*4kB (UM) 3*8kB (U) 3*16kB (U) 4*32kB (UM) 1*64kB (U) 0*128kB 9*256kB (UM) 9*512kB (UM) 6*1024kB (UM) 2*2048kB (UM) 11*4096kB (M) = 62488kB
<4>[   47.709582] Normal: 2436*4kB (UME) 1167*8kB (UME) 633*16kB (UM) 250*32kB (UM) 100*64kB (UME) 53*128kB (UME) 16*256kB (M) 1*512kB (M) 0*1024kB 0*2048kB 0*4096kB = 55000kB
<6>[   47.709617] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB
<4>[   47.709618] 54774 total pagecache pages
<4>[   47.709669] 1490 pages in swap cache
<4>[   47.709671] Swap cache stats: add 852548, delete 851079, find 285364/336301
<4>[   47.709672] Free swap  = 1349884kB
<4>[   47.709674] Total swap = 2097148kB
<4>[   47.709676] 4049582 pages RAM
<4>[   47.709677] 0 pages HighMem/MovableOnly
<4>[   47.709679] 81667 pages reserved
<6>[   47.740907] Purging GPU memory, 51968 pages freed, 935 pages still pinned.
<6>[   51.532571] Purging GPU memory, 51968 pages freed, 935 pages still pinned.
<6>[   54.663518] Purging GPU memory, 51968 pages freed, 935 pages still pinned.
Comment 5 Marta Löfstedt 2017-12-15 08:52:39 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_3520/shard-snb2/igt@kms_plane_lowres@pipe-b-tiling-none.html

run.log:
running: igt/gem_tiled_swapping/non-threaded

[08/76] skip: 3, pass: 5 |                  
FATAL: command execution failed
java.io.EOFException
...
CI_IGT_test runtime 152 seconds
Rebooting shard-snb2

dmesg:
<7>[   32.977139] [IGT] gem_tiled_swapping: executing
<6>[   32.997404] gem_tiled_swapp (1553): drop_caches: 4
<7>[   34.348389] [IGT] gem_tiled_swapping: starting subtest non-threaded
...
<7>[  123.271626] [IGT] kms_frontbuffer_tracking: starting subtest fbcpsr-1p-primscrn-cur-indfb-draw-mmap-gtt
<7>[  123.271973] [IGT] kms_frontbuffer_tracking: exiting, ret=77
<6>[  123.314223] Console: switching to colour frame buffer device 128x48
<6>[  123.421863] Console: switching to colour dummy device 80x25
<7>[  123.421910] [IGT] kms_ccs: executing
<7>[  123.430763] [IGT] kms_ccs: exiting, ret=77
<6>[  123.447962] Console: switching to colour frame buffer device 128x48
Comment 6 Marta Löfstedt 2017-12-15 12:48:08 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/IGT_4064/shard-hsw1/igt@tools_test@sysfs_l3_parity.html

run.log:
running: igt/gem_tiled_swapping/non-threaded
[12/76] skip: 7, pass: 5 |                  
FATAL: command execution failed
...
CI_IGT_test runtime 156 seconds
Rebooting shard-hsw1

dmesg:
<7>[   14.674798] [IGT] gem_tiled_swapping: executing
<5>[   16.001694] random: crng init done
<7>[   16.031139] [IGT] gem_tiled_swapping: starting subtest non-threaded
<6>[   36.481077] Purging GPU memory, 49664 pages freed, 935 pages still pinned.
<6>[   41.760477] Purging GPU memory, 49920 pages freed, 935 pages still pinned.
<6>[   45.495909] Purging GPU memory, 50176 pages freed, 935 pages still pinned.
<4>[   49.314504] gem_tiled_swapp: page allocation failure: order:0, mode:0x14204d2(GFP_HIGHUSER|__GFP_RETRY_MAYFAIL|__GFP_RECLAIMABLE), nodemask=(null)
<4>[   49.314529] CPU: 5 PID: 1377 Comm: gem_tiled_swapp Tainted: G     U           4.15.0-rc3-CI-CI_DRM_3521+ #1
<4>[   49.314531] Hardware name: MSI MS-7924/Z97M-G43(MS-7924), BIOS V1.12 02/15/2016
<4>[   49.314533] Call Trace:
<4>[   49.314538]  dump_stack+0x5f/0x86
<4>[   49.314543]  warn_alloc+0xad/0x130
<4>[   49.314551]  ? __mutex_unlock_slowpath+0x38/0x270
<4>[   49.314556]  __alloc_pages_nodemask+0xeb5/0x11d0
<4>[   49.314572]  __read_swap_cache_async+0x146/0x250
<4>[   49.314578]  swapin_readahead+0x14b/0x230
<4>[   49.314588]  ? shmem_swapin+0x40/0x50
<4>[   49.314590]  shmem_swapin+0x40/0x50
<4>[   49.314594]  ? find_get_entry+0x160/0x210
<4>[   49.314599]  ? pagecache_get_page+0x2b/0x230
<4>[   49.314604]  ? lookup_swap_cache+0x46/0x100
<4>[   49.314607]  shmem_getpage_gfp.isra.9+0x925/0xc90
<4>[   49.314618]  shmem_read_mapping_page_gfp+0x2e/0x50
<4>[   49.314645]  i915_gem_object_get_pages_gtt+0x13b/0x660 [i915]
<4>[   49.314671]  ? i915_gem_obj_prepare_shmem_write+0x160/0x220 [i915]
<4>[   49.314692]  ____i915_gem_object_get_pages+0x17/0x70 [i915]
<4>[   49.314711]  __i915_gem_object_get_pages+0x59/0x80 [i915]
<4>[   49.314731]  i915_gem_set_domain_ioctl+0x377/0x3e0 [i915]
<4>[   49.314751]  ? i915_gem_obj_prepare_shmem_write+0x220/0x220 [i915]
<4>[   49.314755]  drm_ioctl_kernel+0x60/0xa0
<4>[   49.314759]  drm_ioctl+0x290/0x330
<4>[   49.314779]  ? i915_gem_obj_prepare_shmem_write+0x220/0x220 [i915]
<4>[   49.314784]  ? vm_mmap_pgoff+0xa1/0xd0
<4>[   49.314792]  do_vfs_ioctl+0x8a/0x680
<4>[   49.314795]  ? entry_SYSCALL_64_fastpath+0x5/0x89
<4>[   49.314799]  ? trace_hardirqs_on_caller+0xde/0x1c0
<4>[   49.314804]  SyS_ioctl+0x36/0x70
<4>[   49.314808]  entry_SYSCALL_64_fastpath+0x1c/0x89
<4>[   49.314811] RIP: 0033:0x7ff9bfd2b587
<4>[   49.314812] RSP: 002b:00007ffc2bf69768 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
<4>[   49.314816] RAX: ffffffffffffffda RBX: 0000000000000208 RCX: 00007ff9bfd2b587
<4>[   49.314818] RDX: 00007ffc2bf697ac RSI: 00000000400c645f RDI: 0000000000000003
<4>[   49.314820] RBP: 0000000000000820 R08: 0000000000000003 R09: 0000000103400000
<4>[   49.314821] R10: 0000000000000001 R11: 0000000000000246 R12: 0000561a5a6bb240
<4>[   49.314823] R13: 00007ff9c171e000 R14: 0000000000000003 R15: 00000000000001c4
<4>[   49.314849] Mem-Info:
<4>[   49.314853] active_anon:3609 inactive_anon:52097 isolated_anon:64
                   active_file:183 inactive_file:0 isolated_file:0
                   unevictable:3836673 dirty:6 writeback:0 unstable:0
                   slab_reclaimable:7469 slab_unreclaimable:16527
                   mapped:1051 shmem:51116 pagetables:8793 bounce:0
                   free:33246 free_pcp:0 free_cma:0
<4>[   49.314856] Node 0 active_anon:14436kB inactive_anon:208388kB active_file:732kB inactive_file:0kB unevictable:15346692kB isolated(anon):256kB isolated(file):0kB mapped:4204kB dirty:24kB writeback:0kB shmem:204464kB shmem_thp: 0kB shmem_pmdmapped: 0kB anon_thp: 14983168kB writeback_tmp:0kB unstable:0kB all_unreclaimable? no
<4>[   49.314860] DMA free:15884kB min:64kB low:80kB high:96kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB writepending:0kB present:15988kB managed:15884kB mlocked:0kB kernel_stack:0kB pagetables:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
<4>[   49.314862] lowmem_reserve[]: 0 2894 15416 15416
<4>[   49.314873] DMA32 free:62600kB min:12676kB low:15844kB high:19012kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:2969896kB writepending:0kB present:3077188kB managed:3032508kB mlocked:2969896kB kernel_stack:0kB pagetables:8kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
<4>[   49.314874] lowmem_reserve[]: 0 0 12522 12522
<4>[   49.314885] Normal free:54500kB min:54836kB low:68544kB high:82252kB active_anon:14436kB inactive_anon:208388kB active_file:472kB inactive_file:436kB unevictable:12376796kB writepending:24kB present:13105152kB managed:12823268kB mlocked:12376796kB kernel_stack:3760kB pagetables:35164kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
<4>[   49.314887] lowmem_reserve[]: 0 0 0 0
<4>[   49.314896] DMA: 3*4kB (U) 2*8kB (U) 3*16kB (U) 0*32kB 3*64kB (U) 2*128kB (U) 0*256kB 0*512kB 1*1024kB (U) 1*2048kB (M) 3*4096kB (M) = 15884kB
<4>[   49.314929] DMA32: 2*4kB (UM) 2*8kB (U) 3*16kB (UM) 2*32kB (U) 0*64kB 2*128kB (UM) 9*256kB (UM) 9*512kB (UM) 6*1024kB (UM) 2*2048kB (UM) 11*4096kB (M) = 62600kB
<4>[   49.314966] Normal: 2344*4kB (UME) 1174*8kB (UME) 639*16kB (UME) 310*32kB (UME) 151*64kB (UME) 53*128kB (UME) 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 55360kB
<6>[   49.314997] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB
<4>[   49.314999] 53975 total pagecache pages
<4>[   49.315003] 2600 pages in swap cache
<4>[   49.315005] Swap cache stats: add 1100872, delete 1098357, find 392943/463271
<4>[   49.315007] Free swap  = 1360636kB
<4>[   49.315008] Total swap = 2097148kB
<4>[   49.315010] 4049582 pages RAM
<4>[   49.315012] 0 pages HighMem/MovableOnly
<4>[   49.315013] 81667 pages reserved
<6>[   49.540631] Purging GPU memory, 49920 pages freed, 935 pages still pinned.
<7>[   51.122908] [IGT] gem_tiled_swapping: exiting, ret=0
<7>[   52.042053] [IGT] tools_test: executing
Comment 7 Marta Löfstedt 2017-12-15 13:35:32 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/IGT_4065/shard-hsw1/igt@kms_flip@2x-plain-flip.html

run.log:
running: igt/gem_tiled_swapping/non-threaded
[05/76] skip: 4, pass: 1 /                  
FATAL: command execution failed
...
CI_IGT_test runtime 161 seconds
Rebooting shard-hsw1

dmesg:
<7>[   13.358466] [IGT] gem_tiled_swapping: executing
<6>[   13.394024] gem_tiled_swapp (2371): drop_caches: 4
<7>[   14.957300] [IGT] gem_tiled_swapping: starting subtest non-threaded
<5>[   15.622972] random: crng init done
<6>[   37.256936] Purging GPU memory, 50944 pages freed, 935 pages still pinned.
<6>[   42.864843] Purging GPU memory, 51200 pages freed, 1191 pages still pinned.
<6>[   46.506086] Purging GPU memory, 51456 pages freed, 935 pages still pinned.
<7>[   49.122289] [IGT] gem_tiled_swapping: exiting, ret=0
<7>[   49.978209] [IGT] kms_flip: executing
Comment 8 Marta Löfstedt 2017-12-18 08:41:02 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_3523/shard-hsw6/igt@kms_flip@blt-wf_vblank-vs-modeset-interruptible.html

run.log:
running: igt/gem_tiled_swapping/non-threaded

[17/76] skip: 8, pass: 9 /                  
FATAL: command execution failed
java.io.EOFException
...
Completed CI_IGT_test CI_DRM_3523/shard-hsw6/24 : FAILURE
CI_IGT_test runtime 276 seconds
Rebooting shard-hsw6

pstore:

<7>[  246.768557] [drm:intel_reference_shared_dpll [i915]] using SPLL for pipe C
<3>[  246.864103] INFO: task kswapd0:80 blocked for more than 60 seconds.
<3>[  246.864126]       Tainted: G     U           4.15.0-rc3-CI-CI_DRM_3523+ #1
<3>[  246.864136] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
<6>[  246.864146] kswapd0         D    0    80      2 0x80000000
<4>[  246.864163] Call Trace:
<4>[  246.864185]  ? __schedule+0x3c3/0xaf0
<4>[  246.864211]  schedule+0x37/0x90
<4>[  246.864222]  io_schedule+0xd/0x30
<4>[  246.864233]  __lock_page+0x107/0x130
<4>[  246.864250]  ? add_to_page_cache_lru+0xc0/0xc0
<4>[  246.864271]  deferred_split_scan+0x25a/0x2b0
<4>[  246.864284]  shrink_slab.part.17+0x201/0x5d0
<4>[  246.864305]  shrink_node+0x2fd/0x310
<4>[  246.864320]  kswapd+0x31c/0x910
<4>[  246.864341]  kthread+0x173/0x1b0
<4>[  246.864347]  ? mem_cgroup_shrink_node+0x300/0x300
<4>[  246.864352]  ? _kthread_create_on_node+0x30/0x30
<4>[  246.864360]  ret_from_fork+0x24/0x30
<4>[  246.864378] 
<4>[  246.864378] Showing all locks held in the system:
<4>[  246.864388] 2 locks held by khungtaskd/67:
<4>[  246.864395]  #0:  (rcu_read_lock){....}, at: [<00000000d5a49218>] watchdog+0x9b/0x5e0
<4>[  246.864416]  #1:  (tasklist_lock){.+.+}, at: [<000000005d61d7e3>] debug_show_all_locks+0x37/0x190
<4>[  246.864437] 1 lock held by kswapd0/80:
<4>[  246.864440]  #0:  (shrinker_rwsem){++++}, at: [<000000005a3fbf39>] shrink_slab.part.17+0x46/0x5d0
<4>[  246.864465] 1 lock held by systemd-journal/229:
<4>[  246.864468]  #0:  (&mm->mmap_sem){++++}, at: [<00000000896672dd>] __do_page_fault+0x106/0x560
<4>[  246.864493] 1 lock held by in:imklog/587:
<4>[  246.864496]  #0:  (&f->f_pos_lock){+.+.}, at: [<00000000b4ab2786>] __fdget_pos+0x40/0x50
<4>[  246.864524] 1 lock held by dmesg/1086:
<4>[  246.864527]  #0:  (&user->lock){+.+.}, at: [<0000000028cca19f>] devkmsg_read+0x35/0x2f0
<4>[  246.864550] 3 locks held by kms_flip/1786:
<4>[  246.864553]  #0:  (&dev->mode_config.mutex){+.+.}, at: [<000000008153aa3a>] drm_mode_setcrtc+0xba/0x5d0
<4>[  246.864572]  #1:  (crtc_ww_class_acquire){+.+.}, at: [<00000000d02cfa34>] drm_mode_setcrtc+0xcc/0x5d0
<4>[  246.864590]  #2:  (crtc_ww_class_mutex){+.+.}, at: [<00000000f306771c>] drm_modeset_backoff+0x7e/0x1c0
<4>[  246.864609] 
<4>[  246.864612] =============================================
<4>[  246.864612] 
<4>[  246.864617] NMI backtrace for cpu 1
<4>[  246.864623] CPU: 1 PID: 67 Comm: khungtaskd Tainted: G     U           4.15.0-rc3-CI-CI_DRM_3523+ #1
<4>[  246.864627] Hardware name: MSI MS-7924/Z97M-G43(MS-7924), BIOS V1.12 02/15/2016
<4>[  246.864630] Call Trace:
<4>[  246.864639]  dump_stack+0x5f/0x86
<4>[  246.864646]  nmi_cpu_backtrace+0xb4/0xc0
<4>[  246.864654]  ? irq_force_complete_move+0xe0/0xe0
<4>[  246.864659]  nmi_trigger_cpumask_backtrace+0xb8/0xf0
<4>[  246.864667]  watchdog+0x43e/0x5e0
<4>[  246.864677]  kthread+0x173/0x1b0
<4>[  246.864682]  ? reset_hung_task_detector+0x10/0x10
<4>[  246.864687]  ? _kthread_create_on_node+0x30/0x30
<4>[  246.864694]  ret_from_fork+0x24/0x30
<6>[  246.864713] Sending NMI from CPU 1 to CPUs 0,2-7:
<4>[  246.864730] NMI backtrace for cpu 5 skipped: idling at intel_idle+0x6f/0x120
<4>[  246.864748] NMI backtrace for cpu 6 skipped: idling at intel_idle+0x6f/0x120
<4>[  246.864757] NMI backtrace for cpu 7 skipped: idling at intel_idle+0x6f/0x120
<4>[  246.864766] NMI backtrace for cpu 4 skipped: idling at intel_idle+0x6f/0x120
<4>[  246.864773] NMI backtrace for cpu 2 skipped: idling at intel_idle+0x6f/0x120
<4>[  246.864781] NMI backtrace for cpu 0 skipped: idling at intel_idle+0x6f/0x120
<4>[  246.864788] NMI backtrace for cpu 3 skipped: idling at intel_idle+0x6f/0x120
<0>[  246.865728] Kernel panic - not syncing: hung_task: blocked tasks
<4>[  246.865736] CPU: 1 PID: 67 Comm: khungtaskd Tainted: G     U           4.15.0-rc3-CI-CI_DRM_3523+ #1
<4>[  246.865741] Hardware name: MSI MS-7924/Z97M-G43(MS-7924), BIOS V1.12 02/15/2016
<4>[  246.865746] Call Trace:
<4>[  246.865756]  dump_stack+0x5f/0x86
<4>[  246.865764]  panic+0xcf/0x20d
<4>[  246.865781]  watchdog+0x44a/0x5e0
<4>[  246.865792]  kthread+0x173/0x1b0
<4>[  246.865800]  ? reset_hung_task_detector+0x10/0x10
<4>[  246.865805]  ? _kthread_create_on_node+0x30/0x30
<4>[  246.865814]  ret_from_fork+0x24/0x30
<0>[  246.866626] Dumping ftrace buffer:
<0>[  246.866708]    (ftrace buffer empty)
<0>[  246.866715] Kernel Offset: disabled
Comment 9 Marta Löfstedt 2017-12-18 08:43:01 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_3531/shard-hsw7/igt@kms_flip@vblank-vs-hang.html
run.log:
running: igt/gem_tiled_swapping/non-threaded
[49/76] skip: 24, pass: 25 /                
FATAL: command execution failed
java.io.EOFException
...
CI_IGT_test runtime 234 seconds
Rebooting shard-hsw7

pstore:
<7>[  184.837602] [drm:init_workarounds_ring [i915]] rcs0: Number of context specific w/a: 0
<3>[  185.396854] INFO: task kswapd0:80 blocked for more than 60 seconds.
<3>[  185.396865]       Tainted: G     U           4.15.0-rc3-CI-CI_DRM_3531+ #1
<6>[  185.396870] kswapd0         D    0    80      2 0x80000000
<4>[  185.396875] Call Trace:
<4>[  185.396883]  ? __schedule+0x3c3/0xaf0
<4>[  185.396890]  schedule+0x37/0x90
<4>[  185.396895]  io_schedule+0xd/0x30
<4>[  185.396899]  __lock_page+0x107/0x130
<4>[  185.396903]  ? add_to_page_cache_lru+0xc0/0xc0
<4>[  185.396910]  deferred_split_scan+0x25a/0x2b0
<4>[  185.396917]  shrink_slab.part.17+0x201/0x5d0
<4>[  185.396927]  shrink_node+0x2fd/0x310
<4>[  185.396934]  kswapd+0x31c/0x910
<4>[  185.396945]  kthread+0x173/0x1b0
<4>[  185.396948]  ? mem_cgroup_shrink_node+0x300/0x300
<4>[  185.396950]  ? _kthread_create_on_node+0x30/0x30
<4>[  185.396955]  ret_from_fork+0x24/0x30
<4>[  185.396963] 
<4>[  185.396963] Showing all locks held in the system:
<4>[  185.396972] 2 locks held by khungtaskd/67:
<4>[  185.396976]  #0:  (rcu_read_lock){....}, at: [<000000002436718a>] watchdog+0x9b/0x5e0
<4>[  185.396987]  #1:  (tasklist_lock){.+.+}, at: [<00000000e0223fab>] debug_show_all_locks+0x37/0x190
<4>[  185.396999] 1 lock held by kswapd0/80:
<4>[  185.397001]  #0:  (shrinker_rwsem){++++}, at: [<000000007ca46b62>] shrink_slab.part.17+0x46/0x5d0
<4>[  185.397018] 1 lock held by in:imklog/602:
<4>[  185.397020]  #0:  (&f->f_pos_lock){+.+.}, at: [<0000000036b693d1>] __fdget_pos+0x40/0x50
<4>[  185.397036] 1 lock held by dmesg/1090:
<4>[  185.397038]  #0:  (&user->lock){+.+.}, at: [<00000000400b3ddf>] devkmsg_read+0x35/0x2f0
<4>[  185.397061] 
<4>[  185.397063] =============================================
<4>[  185.397063] 
<4>[  185.397065] NMI backtrace for cpu 0
<4>[  185.397068] CPU: 0 PID: 67 Comm: khungtaskd Tainted: G     U           4.15.0-rc3-CI-CI_DRM_3531+ #1
<4>[  185.397070] Hardware name: MSI MS-7924/Z97M-G43(MS-7924), BIOS V1.12 02/15/2016
<4>[  185.397071] Call Trace:
<4>[  185.397075]  dump_stack+0x5f/0x86
<4>[  185.397079]  nmi_cpu_backtrace+0xb4/0xc0
<4>[  185.397084]  ? lapic_can_unplug_cpu+0x90/0x90
<4>[  185.397087]  nmi_trigger_cpumask_backtrace+0xb8/0xf0
<4>[  185.397091]  watchdog+0x43e/0x5e0
<4>[  185.397095]  kthread+0x173/0x1b0
<4>[  185.397098]  ? reset_hung_task_detector+0x10/0x10
<4>[  185.397100]  ? _kthread_create_on_node+0x30/0x30
<4>[  185.397104]  ret_from_fork+0x24/0x30
<6>[  185.397113] Sending NMI from CPU 0 to CPUs 1-7:
<4>[  185.397121] NMI backtrace for cpu 4 skipped: idling at intel_idle+0x6f/0x120
<4>[  185.397135] NMI backtrace for cpu 7 skipped: idling at intel_idle+0x6f/0x120
<4>[  185.397137] NMI backtrace for cpu 3 skipped: idling at intel_idle+0x6f/0x120
<4>[  185.397141] NMI backtrace for cpu 2 skipped: idling at intel_idle+0x6f/0x120
<4>[  185.397145] NMI backtrace for cpu 5 skipped: idling at intel_idle+0x6f/0x120
<4>[  185.397148] NMI backtrace for cpu 6 skipped: idling at intel_idle+0x6f/0x120
<4>[  185.397151] NMI backtrace for cpu 1 skipped: idling at intel_idle+0x6f/0x120
<0>[  185.398121] Kernel panic - not syncing: hung_task: blocked tasks
<4>[  185.398126] CPU: 0 PID: 67 Comm: khungtaskd Tainted: G     U           4.15.0-rc3-CI-CI_DRM_3531+ #1
<4>[  185.398129] Hardware name: MSI MS-7924/Z97M-G43(MS-7924), BIOS V1.12 02/15/2016
<4>[  185.398131] Call Trace:
<4>[  185.398136]  dump_stack+0x5f/0x86
<4>[  185.398141]  panic+0xcf/0x20d
<4>[  185.398150]  watchdog+0x44a/0x5e0
<4>[  185.398156]  kthread+0x173/0x1b0
<4>[  185.398159]  ? reset_hung_task_detector+0x10/0x10
<4>[  185.398162]  ? _kthread_create_on_node+0x30/0x30
<4>[  185.398168]  ret_from_fork+0x24/0x30
<0>[  185.398576] Dumping ftrace buffer:
<0>[  185.398642]    (ftrace buffer empty)
<0>[  185.398646] Kernel Offset: disabled
Comment 10 Marta Löfstedt 2017-12-18 08:45:00 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_3536/shard-hsw5/igt@kms_frontbuffer_tracking@psr-1p-primscrn-spr-indfb-draw-pwrite.html

run.log:
running: igt/gem_tiled_swapping/non-threaded
[01/76] skip: 1 /                           
FATAL: command execution failed
...
CI_IGT_test runtime 148 seconds
Rebooting shard-hsw5

no pstore, however dmesg has page allocation failure:


<7>[   17.216349] [IGT] gem_tiled_swapping: starting subtest non-threaded
<5>[   17.471796] random: crng init done
<4>[   35.220136] gem_tiled_swapp: page allocation failure: order:0, mode:0x14204d2(GFP_HIGHUSER|__GFP_RETRY_MAYFAIL|__GFP_RECLAIMABLE), nodemask=(null)
<4>[   35.220161] CPU: 5 PID: 1337 Comm: gem_tiled_swapp Not tainted 4.15.0-rc3-CI-CI_DRM_3536+ #1
<4>[   35.220162] Hardware name: MSI MS-7924/Z97M-G43(MS-7924), BIOS V1.12 02/15/2016
<4>[   35.220164] Call Trace:
<4>[   35.220169]  dump_stack+0x5f/0x86
<4>[   35.220174]  warn_alloc+0xad/0x130
<4>[   35.220181]  ? __mutex_unlock_slowpath+0x38/0x270
<4>[   35.220186]  __alloc_pages_nodemask+0xeb5/0x11d0
<4>[   35.220202]  __read_swap_cache_async+0x146/0x250
<4>[   35.220208]  swapin_readahead+0x14b/0x230
<4>[   35.220218]  ? shmem_swapin+0x40/0x50
<4>[   35.220220]  shmem_swapin+0x40/0x50
<4>[   35.220225]  ? find_get_entry+0x160/0x210
<4>[   35.220229]  ? pagecache_get_page+0x2b/0x230
<4>[   35.220234]  ? lookup_swap_cache+0x46/0x100
<4>[   35.220237]  shmem_getpage_gfp.isra.9+0x925/0xc90
<4>[   35.220248]  shmem_read_mapping_page_gfp+0x2e/0x50
<4>[   35.220277]  i915_gem_object_get_pages_gtt+0x13b/0x660 [i915]
<4>[   35.220304]  ? i915_gem_obj_prepare_shmem_write+0x220/0x220 [i915]
<4>[   35.220323]  ____i915_gem_object_get_pages+0x17/0x70 [i915]
<4>[   35.220343]  __i915_gem_object_get_pages+0x59/0x80 [i915]
<4>[   35.220363]  i915_gem_set_domain_ioctl+0x377/0x3e0 [i915]
<4>[   35.220383]  ? i915_gem_obj_prepare_shmem_write+0x220/0x220 [i915]
<4>[   35.220387]  drm_ioctl_kernel+0x60/0xa0
<4>[   35.220391]  drm_ioctl+0x290/0x330
<4>[   35.220411]  ? i915_gem_obj_prepare_shmem_write+0x220/0x220 [i915]
<4>[   35.220417]  ? vm_mmap_pgoff+0xa1/0xd0
<4>[   35.220425]  do_vfs_ioctl+0x8a/0x680
<4>[   35.220428]  ? entry_SYSCALL_64_fastpath+0x5/0x89
<4>[   35.220432]  ? trace_hardirqs_on_caller+0xde/0x1c0
<4>[   35.220436]  SyS_ioctl+0x36/0x70
<4>[   35.220441]  entry_SYSCALL_64_fastpath+0x1c/0x89
<4>[   35.220443] RIP: 0033:0x7f0921008587
<4>[   35.220445] RSP: 002b:00007ffee6321228 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
<4>[   35.220449] RAX: ffffffffffffffda RBX: 00000000000001ed RCX: 00007f0921008587
<4>[   35.220450] RDX: 00007ffee632126c RSI: 00000000400c645f RDI: 0000000000000003
<4>[   35.220452] RBP: 00000000000007b4 R08: 0000000000000003 R09: 0000000107200000
<4>[   35.220454] R10: 0000000000000001 R11: 0000000000000246 R12: 000055d074a98240
<4>[   35.220455] R13: 00007f09229fb000 R14: 0000000000000003 R15: 000000000000010a
<4>[   35.220478] Mem-Info:
<4>[   35.220482] active_anon:15445 inactive_anon:40672 isolated_anon:0
                   active_file:158 inactive_file:24 isolated_file:0
                   unevictable:3836673 dirty:2 writeback:0 unstable:0
                   slab_reclaimable:7406 slab_unreclaimable:16278
                   mapped:989 shmem:39096 pagetables:8876 bounce:0
                   free:33353 free_pcp:0 free_cma:0
<4>[   35.220486] Node 0 active_anon:61780kB inactive_anon:162688kB active_file:632kB inactive_file:96kB unevictable:15346692kB isolated(anon):0kB isolated(file):0kB mapped:3956kB dirty:8kB writeback:0kB shmem:156384kB shmem_thp: 0kB shmem_pmdmapped: 0kB anon_thp: 15034368kB writeback_tmp:0kB unstable:0kB all_unreclaimable? no
<4>[   35.220489] DMA free:15884kB min:64kB low:80kB high:96kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB writepending:0kB present:15988kB managed:15884kB mlocked:0kB kernel_stack:0kB pagetables:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
<4>[   35.220491] lowmem_reserve[]: 0 2894 15416 15416
<4>[   35.220502] DMA32 free:62724kB min:12676kB low:15844kB high:19012kB active_anon:12kB inactive_anon:1964kB active_file:0kB inactive_file:0kB unevictable:2967624kB writepending:0kB present:3077188kB managed:3032468kB mlocked:2967624kB kernel_stack:0kB pagetables:4kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
<4>[   35.220504] lowmem_reserve[]: 0 0 12522 12522
<4>[   35.220515] Normal free:54804kB min:54836kB low:68544kB high:82252kB active_anon:61768kB inactive_anon:160724kB active_file:372kB inactive_file:380kB unevictable:12379068kB writepending:8kB present:13105152kB managed:12823268kB mlocked:12379068kB kernel_stack:3840kB pagetables:35500kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
<4>[   35.220516] lowmem_reserve[]: 0 0 0 0
<4>[   35.220525] DMA: 3*4kB (U) 2*8kB (U) 3*16kB (U) 0*32kB 3*64kB (U) 2*128kB (U) 0*256kB 0*512kB 1*1024kB (U) 1*2048kB (M) 3*4096kB (M) = 15884kB
<4>[   35.220559] DMA32: 5*4kB (ME) 4*8kB (M) 5*16kB (UME) 4*32kB (UM) 6*64kB (UME) 3*128kB (ME) 9*256kB (UME) 10*512kB (UME) 7*1024kB (UME) 3*2048kB (UM) 10*4096kB (M) = 62724kB
<4>[   35.220598] Normal: 2827*4kB (UM) 1542*8kB (UME) 558*16kB (UME) 265*32kB (UME) 132*64kB (UME) 37*128kB (UME) 3*256kB (ME) 0*512kB 0*1024kB 0*2048kB 0*4096kB = 55004kB
<6>[   35.220631] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB
<4>[   35.220633] 42906 total pagecache pages
<4>[   35.220637] 3622 pages in swap cache
<4>[   35.220639] Swap cache stats: add 776597, delete 772999, find 248832/296870
<4>[   35.220640] Free swap  = 1331196kB
<4>[   35.220642] Total swap = 2097148kB
<4>[   35.220644] 4049582 pages RAM
<4>[   35.220645] 0 pages HighMem/MovableOnly
<4>[   35.220647] 81677 pages reserved
<6>[   35.344763] Purging GPU memory, 37888 pages freed, 918 pages still pinned.
<6>[   38.241462] Purging GPU memory, 37888 pages freed, 918 pages still pinned.
<6>[   40.758512] Purging GPU memory, 37632 pages freed, 918 pages still pinned.
<6>[   43.458096] Purging GPU memory, 38400 pages freed, 918 pages still pinned.
<6>[   45.888864] Purging GPU memory, 38144 pages freed, 918 pages still pinned.
<6>[   49.200430] Purging GPU memory, 38144 pages freed, 918 pages still pinned.
<7>[   49.787596] [IGT] gem_tiled_swapping: exiting, ret=0
<7>[   50.603454] [IGT] kms_frontbuffer_tracking: executing
Comment 11 Marta Löfstedt 2018-01-02 06:51:07 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_3540/shard-snb5/igt@kms_flip@flip-vs-panning-interruptible.html

run.log:
running: igt/gem_tiled_swapping/non-threaded

[51/76] skip: 26, pass: 25 \                
FATAL: command execution failed

dmesg:
<7>[  108.364472] [IGT] gem_tiled_swapping: executing
<7>[  109.750063] [IGT] gem_tiled_swapping: starting subtest non-threaded
...
<6>[  166.322120] Console: switching to colour dummy device 80x25
<7>[  166.322168] [IGT] kms_flip: executing
Followed by stray
Comment 12 Marta Löfstedt 2018-01-02 08:25:07 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_3568/shard-hsw6/igt@kms_draw_crc@draw-method-xrgb2101010-mmap-gtt-untiled.html

<5>[   31.693010] random: crng init done
<14>[   32.107395] [IGT] gem_tiled_swapping: starting subtest non-threaded
<6>[   58.761579] Purging GPU memory, 53504 pages freed, 918 pages still pinned.
<14>[   60.652382] [IGT] gem_tiled_swapping: exiting, ret=0
<14>[   61.450548] [IGT] kms_draw_crc: executing
<3>[  123.823341] INFO: task kswapd0:80 blocked for more than 60 seconds.
<3>[  123.823355]       Not tainted 4.15.0-rc4-CI-CI_DRM_3568+ #1
<3>[  123.823364] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
<6>[  123.823376] kswapd0         D    0    80      2 0x80000000
<4>[  123.823379] Call Trace:
<4>[  123.823385]  ? __schedule+0x3c3/0xaf0
<4>[  123.823389]  schedule+0x37/0x90
<4>[  123.823392]  io_schedule+0xd/0x30
<4>[  123.823395]  __lock_page+0x107/0x130
<4>[  123.823397]  ? add_to_page_cache_lru+0xc0/0xc0
<4>[  123.823401]  deferred_split_scan+0x25a/0x2b0
<4>[  123.823406]  shrink_slab.part.17+0x201/0x5d0
<4>[  123.823412]  shrink_node+0x2fd/0x310
<4>[  123.823417]  kswapd+0x31c/0x910
<4>[  123.823423]  kthread+0xfb/0x130
<4>[  123.823425]  ? mem_cgroup_shrink_node+0x300/0x300
<4>[  123.823426]  ? _kthread_create_on_node+0x30/0x30
<4>[  123.823429]  ret_from_fork+0x24/0x30
<4>[  123.823434] 
<4>[  123.823434] Showing all locks held in the system:
<4>[  123.823440] 2 locks held by khungtaskd/67:
<4>[  123.823442]  #0:  (rcu_read_lock){....}, at: [<0000000073142e66>] watchdog+0x9b/0x5e0
<4>[  123.823449]  #1:  (tasklist_lock){.+.+}, at: [<000000008bb68302>] debug_show_all_locks+0x37/0x190
<4>[  123.823456] 1 lock held by kswapd0/80:
<4>[  123.823457]  #0:  (shrinker_rwsem){++++}, at: [<00000000222c0c5d>] shrink_slab.part.17+0x46/0x5d0
<4>[  123.823472] 1 lock held by in:imklog/586:
<4>[  123.823473]  #0:  (&f->f_pos_lock){+.+.}, at: [<00000000a31cfa2e>] __fdget_pos+0x3a/0x50
<4>[  123.823481] 2 locks held by systemd-hostnam/764:
<4>[  123.823481]  #0:  (&type->s_umount_key#29){++++}, at: [<000000001e90c47d>] deactivate_super+0x3e/0x50
<4>[  123.823488]  #1:  (shrinker_rwsem){++++}, at: [<00000000bf09f442>] unregister_shrinker+0x10/0x60
<4>[  123.823496] 1 lock held by dmesg/1160:
<4>[  123.823497]  #0:  (&user->lock){+.+.}, at: [<00000000a9303139>] devkmsg_read+0x35/0x2f0
<4>[  123.823513] 1 lock held by kms_draw_crc/1615:
<4>[  123.823514]  #0:  (&type->s_umount_key#29){++++}, at: [<000000003cf12e6f>] iterate_supers+0x8d/0xf0
<4>[  123.823520] 
<4>[  123.823521] =============================================
<4>[  123.823521] 
<4>[  123.823522] NMI backtrace for cpu 0
<4>[  123.823524] CPU: 0 PID: 67 Comm: khungtaskd Not tainted 4.15.0-rc4-CI-CI_DRM_3568+ #1
<4>[  123.823525] Hardware name: MSI MS-7924/Z97M-G43(MS-7924), BIOS V1.12 02/15/2016
<4>[  123.823526] Call Trace:
<4>[  123.823528]  dump_stack+0x5f/0x86
<4>[  123.823530]  nmi_cpu_backtrace+0xb4/0xc0
<4>[  123.823534]  ? lapic_can_unplug_cpu+0x90/0x90
<4>[  123.823536]  nmi_trigger_cpumask_backtrace+0xb8/0xf0
<4>[  123.823539]  watchdog+0x43e/0x5e0
<4>[  123.823541]  kthread+0xfb/0x130
<4>[  123.823543]  ? reset_hung_task_detector+0x10/0x10
<4>[  123.823544]  ? _kthread_create_on_node+0x30/0x30
<4>[  123.823546]  ret_from_fork+0x24/0x30
<6>[  123.823552] Sending NMI from CPU 0 to CPUs 1-7:
<4>[  123.823554] NMI backtrace for cpu 5
<4>[  123.823556] CPU: 5 PID: 1064 Comm: java Not tainted 4.15.0-rc4-CI-CI_DRM_3568+ #1
<4>[  123.823556] Hardware name: MSI MS-7924/Z97M-G43(MS-7924), BIOS V1.12 02/15/2016
<4>[  123.823569] RIP: 0010:lock_is_held_type+0x59/0x80
<4>[  123.823570] RSP: 0018:ffffc90000b93dd8 EFLAGS: 00000092
<4>[  123.823570] RAX: 0000000000000000 RBX: ffff880405da2880 RCX: 0000000000000001
<4>[  123.823571] RDX: 0000000000000000 RSI: 00000000ffffffff RDI: ffffffff81e4b7c0
<4>[  123.823571] RBP: ffff880405da27c0 R08: ffff880405da3098 R09: 00000000e0c4a53a
<4>[  123.823572] R10: ffffc90000b93d80 R11: ffffffff810b553f R12: 0000000000000092
<4>[  123.823572] R13: ffff880409554248 R14: ffff880405da27c0 R15: ffff88041fb5ab40
<4>[  123.823573] FS:  00007f9b58ace700(0000) GS:ffff88041fb40000(0000) knlGS:0000000000000000
<4>[  123.823574] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
<4>[  123.823574] CR2: 00007f9b730470a0 CR3: 0000000404958004 CR4: 00000000001606e0
<4>[  123.823575] Call Trace:
<4>[  123.823577]  update_curr+0x363/0x460
<4>[  123.823578]  pick_next_task_fair+0xa9/0x8a0
<4>[  123.823581]  __schedule+0x123/0xaf0
<4>[  123.823582]  schedule+0x37/0x90
<4>[  123.823584]  sys_sched_yield+0x8c/0xa0
<4>[  123.823585]  entry_SYSCALL_64_fastpath+0x1c/0x89
<4>[  123.823586] RIP: 0033:0x7f9b730470a7
<4>[  123.823586] RSP: 002b:00007f9b58acdc78 EFLAGS: 00000297 ORIG_RAX: 0000000000000018
<4>[  123.823587] RAX: ffffffffffffffda RBX: 00007f9ae00aa000 RCX: 00007f9b730470a7
<4>[  123.823587] RDX: 00007f9b728c8170 RSI: 00007f9b5d005300 RDI: 000000000317b28f
<4>[  123.823588] RBP: 00007f9b58acdd00 R08: 0000000000000000 R09: 00007f9b72907800
<4>[  123.823588] R10: 0000000000000001 R11: 0000000000000297 R12: 00007f9ae00a8d40
<4>[  123.823589] R13: 000000000317b132 R14: 0000000000000003 R15: 000000000317b131
<4>[  123.823590] Code: 8b 2c 25 80 c5 00 00 48 89 df c7 85 ac 08 00 00 01 00 00 00 e8 99 b0 ff ff c7 85 ac 08 00 00 00 00 00 00 41 54 9d 48 83 c4 08 5b <5d> 41 5c c3 4c 89 e7 89 74 24 04 e8 57 f5 ff ff 8b 74 24 04 eb 
<4>[  123.823606] NMI backtrace for cpu 1 skipped: idling at intel_idle+0x6f/0x120
<4>[  123.823608] NMI backtrace for cpu 4 skipped: idling at intel_idle+0x6f/0x120
<4>[  123.823610] NMI backtrace for cpu 2 skipped: idling at intel_idle+0x6f/0x120
<4>[  123.823612] NMI backtrace for cpu 6 skipped: idling at intel_idle+0x6f/0x120
<4>[  123.823614] NMI backtrace for cpu 3 skipped: idling at intel_idle+0x6f/0x120
<4>[  123.823616] NMI backtrace for cpu 7 skipped: idling at intel_idle+0x6f/0x120
<0>[  123.824556] Kernel panic - not syncing: hung_task: blocked tasks
<4>[  123.824566] CPU: 0 PID: 67 Comm: khungtaskd Not tainted 4.15.0-rc4-CI-CI_DRM_3568+ #1
<4>[  123.824577] Hardware name: MSI MS-7924/Z97M-G43(MS-7924), BIOS V1.12 02/15/2016
<4>[  123.824588] Call Trace:
<4>[  123.824593]  dump_stack+0x5f/0x86
<4>[  123.824600]  panic+0xcf/0x20d
<4>[  123.824608]  watchdog+0x44a/0x5e0
<4>[  123.824615]  kthread+0xfb/0x130
<4>[  123.824621]  ? reset_hung_task_detector+0x10/0x10
<4>[  123.824629]  ? _kthread_create_on_node+0x30/0x30
<4>[  123.824637]  ret_from_fork+0x24/0x30
<0>[  123.824885] Dumping ftrace buffer:
<0>[  123.824946]    (ftrace buffer empty)
Comment 13 Marta Löfstedt 2018-01-02 08:27:00 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_3568/shard-kbl1/igt@kms_draw_crc@draw-method-xrgb2101010-mmap-gtt-untiled.html

<14>[   24.151933] [IGT] kms_cursor_crc: starting subtest cursor-512x170-sliding
<14>[   24.151997] [IGT] kms_cursor_crc: exiting, ret=77
<14>[   24.213039] [IGT] gem_tiled_swapping: executing
<6>[   24.740852] e1000e: eno1 NIC Link is Up 1000 Mbps Full Duplex, Flow Control: None
<14>[   25.065109] [IGT] gem_tiled_swapping: starting subtest non-threaded
<4>[   53.664359] gem_tiled_swapp: page allocation failure: order:0, mode:0x14204d2(GFP_HIGHUSER|__GFP_RETRY_MAYFAIL|__GFP_RECLAIMABLE), nodemask=(null)
<4>[   53.664384] CPU: 1 PID: 1495 Comm: gem_tiled_swapp Not tainted 4.15.0-rc4-CI-CI_DRM_3568+ #1
<4>[   53.664387] Hardware name:                  /NUC7i5BNB, BIOS BNKBL357.86A.0054.2017.1025.1822 10/25/2017
<4>[   53.664388] Call Trace:
<4>[   53.664394]  dump_stack+0x5f/0x86
<4>[   53.664399]  warn_alloc+0xad/0x130
<4>[   53.664406]  ? __mutex_unlock_slowpath+0x38/0x270
<4>[   53.664412]  __alloc_pages_nodemask+0xeb5/0x11d0
<4>[   53.664428]  __read_swap_cache_async+0x141/0x250
<4>[   53.664434]  swapin_readahead+0x14b/0x230
<4>[   53.664445]  ? shmem_swapin+0x40/0x50
<4>[   53.664447]  shmem_swapin+0x40/0x50
<4>[   53.664452]  ? find_get_entry+0x160/0x210
<4>[   53.664456]  ? pagecache_get_page+0x2b/0x230
<4>[   53.664461]  ? lookup_swap_cache+0x3b/0xf0
<4>[   53.664465]  shmem_getpage_gfp.isra.9+0x91f/0xc80
<4>[   53.664477]  shmem_read_mapping_page_gfp+0x2e/0x50
<4>[   53.664507]  i915_gem_object_get_pages_gtt+0x13b/0x660 [i915]
<4>[   53.664538]  ? i915_gem_obj_prepare_shmem_write+0x1b0/0x220 [i915]
<4>[   53.664561]  ____i915_gem_object_get_pages+0x17/0x70 [i915]
<4>[   53.664584]  __i915_gem_object_get_pages+0x59/0x80 [i915]
<4>[   53.664607]  i915_gem_set_domain_ioctl+0x377/0x3e0 [i915]
<4>[   53.664632]  ? i915_gem_obj_prepare_shmem_write+0x220/0x220 [i915]
<4>[   53.664636]  drm_ioctl_kernel+0x60/0xa0
<4>[   53.664641]  drm_ioctl+0x290/0x330
<4>[   53.664666]  ? i915_gem_obj_prepare_shmem_write+0x220/0x220 [i915]
<4>[   53.664671]  ? __handle_mm_fault+0x83a/0xdc0
<4>[   53.664681]  do_vfs_ioctl+0x8a/0x670
<4>[   53.664684]  ? entry_SYSCALL_64_fastpath+0x5/0x89
<4>[   53.664688]  ? trace_hardirqs_on_caller+0xde/0x1c0
<4>[   53.664693]  SyS_ioctl+0x36/0x70
<4>[   53.664697]  entry_SYSCALL_64_fastpath+0x1c/0x89
<4>[   53.664699] RIP: 0033:0x7ff7fce86587
<4>[   53.664701] RSP: 002b:00007fff38d25758 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
<4>[   53.664706] RAX: ffffffffffffffda RBX: 00007ff7fe879000 RCX: 00007ff7fce86587
<4>[   53.664707] RDX: 00007fff38d2579c RSI: 00000000400c645f RDI: 0000000000000003
<4>[   53.664709] RBP: 0000000000100000 R08: 0000000000000003 R09: 0000000104b00000
<4>[   53.664711] R10: 0000000000000001 R11: 0000000000000246 R12: 0000000000000001
<4>[   53.664713] R13: 00007ff7fe879000 R14: 0000000000000003 R15: 000000000000004c
<4>[   53.664767] Mem-Info:
<4>[   53.664772] active_anon:19795 inactive_anon:51910 isolated_anon:32
<4>[   53.664772]  active_file:59 inactive_file:0 isolated_file:0
<4>[   53.664772]  unevictable:1874945 dirty:26 writeback:0 unstable:0
<4>[   53.664772]  slab_reclaimable:6821 slab_unreclaimable:14453
<4>[   53.664772]  mapped:774 shmem:52156 pagetables:4991 bounce:0
<4>[   53.664772]  free:26672 free_pcp:0 free_cma:0
<4>[   53.664776] Node 0 active_anon:79180kB inactive_anon:207640kB active_file:236kB inactive_file:0kB unevictable:7499780kB isolated(anon):128kB isolated(file):0kB mapped:3096kB dirty:104kB writeback:0kB shmem:208624kB shmem_thp: 0kB shmem_pmdmapped: 0kB anon_thp: 7153664kB writeback_tmp:0kB unstable:0kB all_unreclaimable? no
<4>[   53.664779] DMA free:15892kB min:132kB low:164kB high:196kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB writepending:0kB present:15988kB managed:15892kB mlocked:0kB kernel_stack:0kB pagetables:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
<4>[   53.664781] lowmem_reserve[]: 0 1831 7817 7817
<4>[   53.664793] DMA32 free:39416kB min:15804kB low:19752kB high:23700kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:1839348kB writepending:0kB present:1986972kB managed:1878772kB mlocked:1839348kB kernel_stack:0kB pagetables:4kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
<4>[   53.664794] lowmem_reserve[]: 0 0 5985 5985
<4>[   53.664806] Normal free:51380kB min:51644kB low:64552kB high:77460kB active_anon:79180kB inactive_anon:207640kB active_file:212kB inactive_file:144kB unevictable:5660432kB writepending:104kB present:6275072kB managed:6129624kB mlocked:5660432kB kernel_stack:3968kB pagetables:19960kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
<4>[   53.664807] lowmem_reserve[]: 0 0 0 0
<4>[   53.664816] DMA: 3*4kB (U) 3*8kB (U) 3*16kB (U) 0*32kB 3*64kB (U) 2*128kB (U) 0*256kB 0*512kB 1*1024kB (U) 1*2048kB (M) 3*4096kB (M) = 15892kB
<4>[   53.664851] DMA32: 0*4kB 1*8kB (U) 1*16kB (U) 1*32kB (U) 1*64kB (U) 7*128kB (UM) 10*256kB (UM) 6*512kB (UM) 8*1024kB (UM) 2*2048kB (UM) 5*4096kB (M) = 39416kB
<4>[   53.664890] Normal: 2865*4kB (UME) 1399*8kB (UME) 657*16kB (UM) 332*32kB (ME) 111*64kB (ME) 4*128kB (ME) 1*256kB (M) 0*512kB 0*1024kB 0*2048kB 0*4096kB = 51660kB
<6>[   53.664925] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB
<4>[   53.664927] 53752 total pagecache pages
<4>[   53.664931] 1424 pages in swap cache
<4>[   53.664933] Swap cache stats: add 1063614, delete 1062202, find 386034/455333
<4>[   53.664935] Free swap  = 1457660kB
<4>[   53.664937] Total swap = 2097148kB
<4>[   53.664939] 2069508 pages RAM
<4>[   53.664940] 0 pages HighMem/MovableOnly
<4>[   53.664942] 63436 pages reserved
<6>[   53.708393] Purging GPU memory, 51200 pages freed, 2336 pages still pinned.
<3>[   53.708407] 1 and 0 pages still available in the bound and unbound GPU page lists.
<14>[   59.595834] [IGT] gem_tiled_swapping: exiting, ret=0
<14>[   60.171881] [IGT] kms_draw_crc: executing
<6>[   87.410277] usb 1-3.1: new low-speed USB device number 5 using xhci_hcd
<6>[   87.505870] usb 1-3.1: New USB device found, idVendor=275d, idProduct=0ba6
<6>[   87.505885] usb 1-3.1: New USB device strings: Mfr=0, Product=1, SerialNumber=0
<6>[   87.505895] usb 1-3.1: Product: USB OPTICAL MOUSE 
<6>[   87.514169] input: USB OPTICAL MOUSE  as /devices/pci0000:00/0000:00:14.0/usb1/1-3/1-3.1/1-3.1:1.0/0003:275D:0BA6.0003/input/input12
<6>[   87.515070] hid-generic 0003:275D:0BA6.0003: input,hidraw2: USB HID v1.11 Mouse [USB OPTICAL MOUSE ] on usb-0000:00:14.0-3.1/input0
<3>[  123.925608] INFO: task kswapd0:52 blocked for more than 60 seconds.
<3>[  123.925704]       Not tainted 4.15.0-rc4-CI-CI_DRM_3568+ #1
<3>[  123.925764] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
<6>[  123.925845] kswapd0         D    0    52      2 0x80000000
<4>[  123.925863] Call Trace:
<4>[  123.925895]  ? __schedule+0x3c3/0xaf0
<4>[  123.925923]  schedule+0x37/0x90
<4>[  123.925937]  io_schedule+0xd/0x30
<4>[  123.925949]  __lock_page+0x107/0x130
<4>[  123.925967]  ? add_to_page_cache_lru+0xc0/0xc0
<4>[  123.925989]  deferred_split_scan+0x25a/0x2b0
<4>[  123.926013]  shrink_slab.part.17+0x201/0x5d0
<4>[  123.926055]  shrink_node+0x2fd/0x310
<4>[  123.926085]  kswapd+0x31c/0x910
<4>[  123.926126]  kthread+0xfb/0x130
<4>[  123.926137]  ? mem_cgroup_shrink_node+0x300/0x300
<4>[  123.926146]  ? _kthread_create_on_node+0x30/0x30
<4>[  123.926163]  ret_from_fork+0x24/0x30
<4>[  123.926197] 
<4>[  123.926197] Showing all locks held in the system:
<4>[  123.926338] 2 locks held by khungtaskd/39:
<4>[  123.926363]  #0:  (rcu_read_lock){....}, at: [<00000000ead4b3f7>] watchdog+0x9b/0x5e0
<4>[  123.926451]  #1:  (tasklist_lock){.+.+}, at: [<0000000080919296>] debug_show_all_locks+0x37/0x190
<4>[  123.926537] 1 lock held by kswapd0/52:
<4>[  123.926551]  #0:  (shrinker_rwsem){++++}, at: [<000000006cab8d6b>] shrink_slab.part.17+0x46/0x5d0
<4>[  123.926661] 2 locks held by systemd-hostnam/680:
<4>[  123.926673]  #0:  (&type->s_umount_key#29){++++}, at: [<000000001efd5b9a>] deactivate_super+0x3e/0x50
<4>[  123.926742]  #1:  (shrinker_rwsem){++++}, at: [<00000000d595b380>] unregister_shrinker+0x10/0x60
<4>[  123.926856] 1 lock held by kms_draw_crc/1699:
<4>[  123.926869]  #0:  (&type->s_umount_key#29){++++}, at: [<0000000068f69647>] iterate_supers+0x8d/0xf0
<4>[  123.926940] 
<4>[  123.926951] =============================================
<4>[  123.926951] 
<4>[  123.926965] NMI backtrace for cpu 0
<4>[  123.926983] CPU: 0 PID: 39 Comm: khungtaskd Not tainted 4.15.0-rc4-CI-CI_DRM_3568+ #1
<4>[  123.926995] Hardware name:                  /NUC7i5BNB, BIOS BNKBL357.86A.0054.2017.1025.1822 10/25/2017
<4>[  123.927004] Call Trace:
<4>[  123.927024]  dump_stack+0x5f/0x86
<4>[  123.927045]  nmi_cpu_backtrace+0xb4/0xc0
<4>[  123.927069]  ? lapic_can_unplug_cpu+0x90/0x90
<4>[  123.927086]  nmi_trigger_cpumask_backtrace+0xb8/0xf0
<4>[  123.927111]  watchdog+0x43e/0x5e0
<4>[  123.927145]  kthread+0xfb/0x130
<4>[  123.927161]  ? reset_hung_task_detector+0x10/0x10
<4>[  123.927174]  ? _kthread_create_on_node+0x30/0x30
<4>[  123.927199]  ret_from_fork+0x24/0x30
<6>[  123.927341] Sending NMI from CPU 0 to CPUs 1-3:
<4>[  123.927364] NMI backtrace for cpu 2
<4>[  123.927370] CPU: 2 PID: 953 Comm: dmesg Not tainted 4.15.0-rc4-CI-CI_DRM_3568+ #1
<4>[  123.927373] Hardware name:                  /NUC7i5BNB, BIOS BNKBL357.86A.0054.2017.1025.1822 10/25/2017
<4>[  123.927383] RIP: 0010:unwind_next_frame+0x4ed/0x700
<4>[  123.927387] RSP: 0018:ffffc9000095b9a8 EFLAGS: 00000002
<4>[  123.927391] RAX: ffffffff812928ff RBX: ffffc9000095b9e0 RCX: ffffffff81175d7b
<4>[  123.927394] RDX: ffffc9000095c000 RSI: ffffc9000095be00 RDI: ffffc9000095b9e0
<4>[  123.927397] RBP: 0000000000000001 R08: ffffffff81175ccc R09: ffffffff81f8dd94
<4>[  123.927399] R10: ffffffff81f8dd90 R11: 0000000000000000 R12: ffffffff81175d7c
<4>[  123.927402] R13: ffffc9000095bdc0 R14: ffffffff820e6690 R15: ffffc9000095be08
<4>[  123.927406] FS:  00007fb6bacfc040(0000) GS:ffff88027ed00000(0000) knlGS:0000000000000000
<4>[  123.927409] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
<4>[  123.927412] CR2: 00007f6a3ea995d3 CR3: 000000025f429005 CR4: 00000000003606e0
<4>[  123.927414] Call Trace:
<4>[  123.927424]  __save_stack_trace+0x6e/0xd0
<4>[  123.927436]  ? ext4_file_write_iter+0x10f/0x3a0
<4>[  123.927444]  ? jbd2_journal_stop+0x1c4/0x500
<4>[  123.927453]  set_track+0x5c/0x120
<4>[  123.927460]  free_debug_processing+0x281/0x370
<4>[  123.927465]  ? jbd2_journal_stop+0x1c4/0x500
<4>[  123.927472]  __slab_free+0x39c/0x580
<4>[  123.927482]  ? mark_held_locks+0x64/0x90
<4>[  123.927487]  ? _raw_spin_unlock_irqrestore+0x4c/0x60
<4>[  123.927490]  ? _raw_spin_unlock_irqrestore+0x4c/0x60
<4>[  123.927498]  ? trace_hardirqs_on_caller+0xde/0x1c0
<4>[  123.927502]  ? _raw_spin_unlock_irqrestore+0x39/0x60
<4>[  123.927509]  ? debug_check_no_obj_freed+0x11f/0x230
<4>[  123.927517]  ? kmem_cache_free+0x28a/0x320
<4>[  123.927523]  ? jbd2_journal_stop+0x1c4/0x500
<4>[  123.927526]  kmem_cache_free+0x28a/0x320
<4>[  123.927533]  jbd2_journal_stop+0x1c4/0x500
<4>[  123.927542]  ? rcu_read_lock_sched_held+0x6f/0x80
<4>[  123.927546]  ? __mark_inode_dirty+0x3a1/0x690
<4>[  123.927555]  __ext4_journal_stop+0x31/0x90
<4>[  123.927562]  ext4_da_write_end+0x160/0x370
<4>[  123.927571]  generic_perform_write+0xef/0x1a0
<4>[  123.927581]  __generic_file_write_iter+0x13c/0x1b0
<4>[  123.927590]  ext4_file_write_iter+0x10f/0x3a0
<4>[  123.927598]  ? lock_acquire+0xaf/0x200
<4>[  123.927605]  __vfs_write+0xc5/0x130
<4>[  123.927613]  vfs_write+0xbd/0x1b0
<4>[  123.927618]  SyS_write+0x40/0xa0
<4>[  123.927626]  entry_SYSCALL_64_fastpath+0x1c/0x89
<4>[  123.927630] RIP: 0033:0x7fb6ba3f68f0
<4>[  123.927633] RSP: 002b:00007fff03230a48 EFLAGS: 00000246 ORIG_RAX: 0000000000000001
<4>[  123.927638] RAX: ffffffffffffffda RBX: 00005573b7cae0db RCX: 00007fb6ba3f68f0
<4>[  123.927640] RDX: 000000000000002c RSI: 00005573b8220f70 RDI: 0000000000000001
<4>[  123.927642] RBP: 00007fff03230cd0 R08: 00007fb6ba6c1760 R09: 00007fb6bacfc040
<4>[  123.927645] R10: 0000000000000004 R11: 0000000000000246 R12: 00005573b7aab2bb
<4>[  123.927647] R13: 00005573b7cae0a0 R14: 00005573b7cae0b2 R15: 00007fff03230cc8
<4>[  123.927655] Code: 00 00 00 48 89 df e8 c3 fa ff ff 84 c0 0f 84 6b fb ff ff 49 8b 47 f8 4c 89 7b 38 48 c7 43 50 00 00 00 00 c6 43 35 00 48 89 43 48 <41> 0f b6 46 04 c0 e8 04 3c 01 0f 84 a7 00 00 00 0f 83 8c fd ff 
<4>[  123.927735] NMI backtrace for cpu 1
<4>[  123.927742] CPU: 1 PID: 424 Comm: rs:main Q:Reg Not tainted 4.15.0-rc4-CI-CI_DRM_3568+ #1
<4>[  123.927745] Hardware name:                  /NUC7i5BNB, BIOS BNKBL357.86A.0054.2017.1025.1822 10/25/2017
<4>[  123.927759] RIP: 0010:rcu_segcblist_pend_cbs+0x5/0x20
<4>[  123.927767] RSP: 0018:ffff88027ec83ec0 EFLAGS: 00000082
<4>[  123.927772] RAX: 0000000000000001 RBX: ffff88027ec9b800 RCX: 1a707d6f00000000
<4>[  123.927774] RDX: 0000000000000000 RSI: 00000000ffffffff RDI: ffff88027ec9b838
<4>[  123.927777] RBP: ffff88027ec9b838 R08: 0000000000000000 R09: 0000000000000000
<4>[  123.927779] R10: ffff88027ec83e88 R11: ffff88026e42b0f0 R12: ffffffff81e44500
<4>[  123.927781] R13: ffffffff81e44500 R14: 0000000000000009 R15: 0000000000000000
<4>[  123.927785] FS:  00007f2875357700(0000) GS:ffff88027ec80000(0000) knlGS:0000000000000000
<4>[  123.927788] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
<4>[  123.927791] CR2: 00007fc283e983a0 CR3: 0000000269645005 CR4: 00000000003606e0
<4>[  123.927793] Call Trace:
<4>[  123.927798]  <IRQ>
<4>[  123.927806]  rcu_advance_cbs+0x25/0x70
<4>[  123.927815]  rcu_start_gp+0x29/0x50
<4>[  123.927823]  rcu_process_callbacks+0x44f/0x6f0
<4>[  123.927834]  __do_softirq+0xc1/0x4aa
<4>[  123.927845]  irq_exit+0xa4/0xb0
<4>[  123.927852]  smp_apic_timer_interrupt+0x90/0x2d0
<4>[  123.927858]  apic_timer_interrupt+0x93/0xa0
<4>[  123.927861]  </IRQ>
<4>[  123.927869] RIP: 0010:lock_acquire+0xc4/0x200
<4>[  123.927872] RSP: 0018:ffffc9000086fa78 EFLAGS: 00000282 ORIG_RAX: ffffffffffffff11
<4>[  123.927877] RAX: ffff88026e42a840 RBX: 0000000000000282 RCX: 524c906500000000
<4>[  123.927879] RDX: 0000000000000001 RSI: 0000000083c6b9ee RDI: 0000000000000000
<4>[  123.927882] RBP: 0000000000000000 R08: ffff88026e42b190 R09: 0000000091e0afb1
<4>[  123.927884] R10: ffffc9000086fa78 R11: ffffffff81172490 R12: 0000000000000000
<4>[  123.927886] R13: 0000000000000002 R14: 0000000000000000 R15: 0000000000000000
<4>[  123.927894]  ? find_get_pages_range_tag+0x340/0x340
<4>[  123.927905]  ? find_get_pages_range_tag+0x340/0x340
<4>[  123.927913]  find_get_entry+0x38/0x210
<4>[  123.927918]  ? find_get_pages_range_tag+0x340/0x340
<4>[  123.927924]  pagecache_get_page+0x2b/0x230
<4>[  123.927932]  ? __find_get_block+0xcb/0x3b0
<4>[  123.927940]  __find_get_block+0x1da/0x3b0
<4>[  123.927949]  __getblk_gfp+0x1f/0x2d0
<4>[  123.927956]  ? start_this_handle+0xff/0x440
<4>[  123.927964]  __ext4_get_inode_loc+0xff/0x500
<4>[  123.927972]  ? ext4_dirty_inode+0x3e/0x60
<4>[  123.927977]  ext4_reserve_inode_write+0x47/0xb0
<4>[  123.927984]  ext4_mark_inode_dirty+0x63/0x270
<4>[  123.927992]  ? rcu_read_lock_sched_held+0x6f/0x80
<4>[  123.927999]  ext4_dirty_inode+0x3e/0x60
<4>[  123.928004]  __mark_inode_dirty+0x67/0x690
<4>[  123.928011]  generic_update_time+0x73/0xc0
<4>[  123.928017]  ? current_time+0x2d/0x60
<4>[  123.928022]  file_update_time+0x90/0xe0
<4>[  123.928030]  __generic_file_write_iter+0x94/0x1b0
<4>[  123.928040]  ext4_file_write_iter+0x10f/0x3a0
<4>[  123.928048]  ? lock_acquire+0xaf/0x200
<4>[  123.928054]  __vfs_write+0xc5/0x130
<4>[  123.928061]  vfs_write+0xbd/0x1b0
<4>[  123.928068]  SyS_write+0x40/0xa0
<4>[  123.928076]  entry_SYSCALL_64_fastpath+0x1c/0x89
<4>[  123.928080] RIP: 0033:0x7f2877fa468d
<4>[  123.928083] RSP: 002b:00007f28753565c0 EFLAGS: 00000293 ORIG_RAX: 0000000000000001
<4>[  123.928087] RAX: ffffffffffffffda RBX: 000000000000005b RCX: 00007f2877fa468d
<4>[  123.928089] RDX: 000000000000099d RSI: 00007f2868003780 RDI: 0000000000000005
<4>[  123.928091] RBP: 0000000000000005 R08: 0000559440ee3e30 R09: 0000000000000003
<4>[  123.928094] R10: 0000559440ee2da0 R11: 0000000000000293 R12: 0000559440ee1a00
<4>[  123.928096] R13: 0000000000000082 R14: 0000000000000000 R15: 0000559440ee4430
<4>[  123.928103] Code: 00 00 00 c3 66 90 48 83 7f 20 00 74 08 48 39 7f 08 0f 95 c0 c3 31 c0 c3 0f 1f 40 00 66 2e 0f 1f 84 00 00 00 00 00 48 83 7f 20 00 <74> 0c 48 8b 47 08 48 83 38 00 0f 95 c0 c3 31 c0 c3 66 2e 0f 1f 
<4>[  123.928179] NMI backtrace for cpu 3
<4>[  123.928187] CPU: 3 PID: 189 Comm: systemd-journal Not tainted 4.15.0-rc4-CI-CI_DRM_3568+ #1
<4>[  123.928190] Hardware name:                  /NUC7i5BNB, BIOS BNKBL357.86A.0054.2017.1025.1822 10/25/2017
<4>[  123.928200] RIP: 0010:mark_lock+0x5c/0x640
<4>[  123.928203] RSP: 0018:ffff88027ed83d50 EFLAGS: 00000002
<4>[  123.928209] RAX: 000000000000008f RBX: 0000000000000100 RCX: 0000000000000008
<4>[  123.928212] RDX: 00000000000002cb RSI: ffff880271920918 RDI: ffff880271920040
<4>[  123.928215] RBP: 0000000000000008 R08: 0000000000000001 R09: 0000000000000001
<4>[  123.928219] R10: 0000000000000000 R11: ffffffff810c815a R12: ffff880271920918
<4>[  123.928222] R13: ffff880271920040 R14: 0000000000000001 R15: 000000000000000c
<4>[  123.928227] FS:  00007f94eb80e8c0(0000) GS:ffff88027ed80000(0000) knlGS:0000000000000000
<4>[  123.928231] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
<4>[  123.928235] CR2: 0000000001998498 CR3: 00000002728c8002 CR4: 00000000003606e0
<4>[  123.928236] Call Trace:
<4>[  123.928241]  <IRQ>
<4>[  123.928257]  __lock_acquire+0x34a/0x1b60
<4>[  123.928275]  ? lock_acquire+0xaf/0x200
<4>[  123.928282]  lock_acquire+0xaf/0x200
<4>[  123.928292]  ? swake_up+0xa/0x30
<4>[  123.928302]  _raw_spin_lock_irqsave+0x33/0x50
<4>[  123.928310]  ? swake_up+0xa/0x30
<4>[  123.928317]  swake_up+0xa/0x30
<4>[  123.928329]  rcu_process_callbacks+0xa1/0x6f0
<4>[  123.928341]  __do_softirq+0xc1/0x4aa
<4>[  123.928354]  irq_exit+0xa4/0xb0
<4>[  123.928361]  smp_apic_timer_interrupt+0x90/0x2d0
<4>[  123.928368]  apic_timer_interrupt+0x93/0xa0
<4>[  123.928371]  </IRQ>
<4>[  123.928378] RIP: 0010:__follow_mount_rcu.isra.5+0x119/0x160
<4>[  123.928382] RSP: 0018:ffffc900002dbc00 EFLAGS: 00000202 ORIG_RAX: ffffffffffffff11
<4>[  123.928388] RAX: ffff880271920040 RBX: ffffc900002dbde8 RCX: 0000000000000001
<4>[  123.928391] RDX: 0000000000000007 RSI: ffffffff81d070c9 RDI: ffffffff81cb860e
<4>[  123.928395] RBP: ffffc900002dbc9c R08: ffff8802719208f0 R09: 00000000ca811012
<4>[  123.928398] R10: 0000000000000000 R11: 0000000000000000 R12: ffffc900002dbca0
<4>[  123.928402] R13: ffff880273e3a978 R14: 0000000000000202 R15: ffffc900002dbca8
<4>[  123.928420]  lookup_fast+0xb3/0x440
<4>[  123.928430]  walk_component+0x33/0x2c0
<4>[  123.928441]  link_path_walk+0x185/0x570
<4>[  123.928447]  ? path_init+0x4ae/0x6c0
<4>[  123.928458]  path_lookupat+0x81/0x1f0
<4>[  123.928465]  ? ___slab_alloc.constprop.30+0x152/0x3d0
<4>[  123.928470]  ? ___slab_alloc.constprop.30+0x152/0x3d0
<4>[  123.928478]  ? prepare_creds+0x1b/0xb0
<4>[  123.928487]  filename_lookup+0xa0/0x120
<4>[  123.928497]  ? getname_flags+0x2d/0x180
<4>[  123.928506]  ? rcu_read_lock_sched_held+0x6f/0x80
<4>[  123.928512]  ? kmem_cache_alloc+0x24a/0x2b0
<4>[  123.928520]  ? getname_flags+0x49/0x180
<4>[  123.928531]  ? SyS_faccessat+0xa2/0x200
<4>[  123.928538]  SyS_faccessat+0xa2/0x200
<4>[  123.928548]  do_syscall_64+0x59/0x1a0
<4>[  123.928556]  entry_SYSCALL64_slow_path+0x25/0x25
<4>[  123.928563] RIP: 0033:0x7f94eaae4947
<4>[  123.928566] RSP: 002b:00007ffd00f19298 EFLAGS: 00000246 ORIG_RAX: 0000000000000015
<4>[  123.928572] RAX: ffffffffffffffda RBX: 00007ffd00f1c1a0 RCX: 00007f94eaae4947
<4>[  123.928575] RDX: 00007f94eb5543e0 RSI: 0000000000000000 RDI: 0000557724830881
<4>[  123.928578] RBP: 00007ffd00f192d0 R08: 0000000000002000 R09: 0000000000000000
<4>[  123.928581] R10: 0000000000000080 R11: 0000000000000246 R12: 0000000000000000
<4>[  123.928585] R13: 0000000000000000 R14: 00007ffd00f1c1a0 R15: 0000000000000009
<4>[  123.928595] Code: 0f 84 89 00 00 00 31 c0 48 85 58 30 74 37 bb 01 00 00 00 48 83 c4 08 89 d8 5b 5d 41 5c 41 5d 41 5e 41 5f c3 0f b7 c0 48 8d 14 80 <48> 8d 04 90 48 c1 e0 04 48 2d 50 01 00 00 48 05 20 fb da 82 48 
<6>[  123.928875] INFO: NMI handler (nmi_cpu_backtrace_handler) took too long to run: 1.328 msecs
<0>[  123.929376] Kernel panic - not syncing: hung_task: blocked tasks
<4>[  123.929493] CPU: 0 PID: 39 Comm: khungtaskd Not tainted 4.15.0-rc4-CI-CI_DRM_3568+ #1
<4>[  123.929642] Hardware name:                  /NUC7i5BNB, BIOS BNKBL357.86A.0054.2017.1025.1822 10/25/2017
<4>[  123.929805] Call Trace:
<4>[  123.929879]  dump_stack+0x5f/0x86
<4>[  123.929964]  panic+0xcf/0x20d
<4>[  123.930075]  watchdog+0x44a/0x5e0
<4>[  123.930173]  kthread+0xfb/0x130
<4>[  123.930246]  ? reset_hung_task_detector+0x10/0x10
<4>[  123.930337]  ? _kthread_create_on_node+0x30/0x30
<4>[  123.930449]  ret_from_fork+0x24/0x30
<0>[  123.930607] Dumping ftrace buffer:
Comment 16 Marta Löfstedt 2018-01-04 13:41:36 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/IGT_4113/shard-hsw4/igt@kms_frontbuffer_tracking@fbc-2p-primscrn-pri-shrfb-draw-pwrite.html

run.log:
running: igt/gem_tiled_swapping/non-threaded

[41/76] skip: 20, pass: 20, fail: 1 /       
FATAL: command execution failed
...
Completed CI_IGT_test CI_DRM_3596/shard-hsw4/17 : FAILURE
CI_IGT_test runtime 253 seconds
Rebooting shard-hsw4


last dmesg:
<7>[   60.901875] [IGT] gem_tiled_swapping: starting subtest non-threaded
<6>[   91.184616] Purging GPU memory, 50432 pages freed, 918 pages still pinned.
<6>[   96.742171] Purging GPU memory, 50176 pages freed, 918 pages still pinned.
<7>[   98.617512] [IGT] gem_tiled_swapping: exiting, ret=0
Comment 17 Marta Löfstedt 2018-01-05 07:35:28 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_3600/shard-hsw2/igt@drv_suspend@fence-restore-tiled2untiled.html

last test in run.log:
running: igt/gem_tiled_swapping/non-threaded

pstore:
<14>[  115.538394] [IGT] drv_suspend: executing
<14>[  115.565337] [IGT] drv_suspend: starting subtest fence-restore-tiled2untiled
<6>[  115.666004] PM: suspend entry (deep)
<6>[  115.666007] PM: Syncing filesystems ... done.
<6>[  115.687994] Freezing user space processes ... 
<3>[  123.825063] INFO: task kswapd0:79 blocked for more than 60 seconds.
<3>[  123.825086]       Tainted: G     U           4.15.0-rc6-CI-CI_DRM_3600+ #1
<3>[  123.825104] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
<6>[  123.825123] kswapd0         D    0    79      2 0x80000000
<4>[  123.825140] Call Trace:
<4>[  123.825148]  ? __schedule+0x3c3/0xaf0
<4>[  123.825156]  schedule+0x37/0x90
<4>[  123.825160]  io_schedule+0xd/0x30
<4>[  123.825164]  __lock_page+0x107/0x130
<4>[  123.825169]  ? add_to_page_cache_lru+0xc0/0xc0
<4>[  123.825176]  deferred_split_scan+0x25a/0x2b0
<4>[  123.825183]  shrink_slab.part.17+0x201/0x5d0
<4>[  123.825194]  shrink_node+0x2fd/0x310
<4>[  123.825201]  kswapd+0x31c/0x910
<4>[  123.825212]  kthread+0xfb/0x130
<4>[  123.825215]  ? mem_cgroup_shrink_node+0x300/0x300
<4>[  123.825217]  ? _kthread_create_on_node+0x30/0x30
<4>[  123.825223]  ret_from_fork+0x24/0x30
<4>[  123.825231] 
<4>[  123.825231] Showing all locks held in the system:
<4>[  123.825236] 2 locks held by khungtaskd/66:
<4>[  123.825240]  #0:  (rcu_read_lock){....}, at: [<00000000cdb621f1>] watchdog+0x9b/0x5e0
<4>[  123.825251]  #1:  (tasklist_lock){.+.+}, at: [<000000001ce28407>] debug_show_all_locks+0x37/0x190
<4>[  123.825262] 1 lock held by kswapd0/79:
<4>[  123.825264]  #0:  (shrinker_rwsem){++++}, at: [<0000000024cf4e12>] shrink_slab.part.17+0x46/0x5d0
<4>[  123.825281] 4 locks held by rtcwake/1826:
<4>[  123.825282]  #0:  (sb_writers#5){.+.+}, at: [<00000000ec581cf0>] vfs_write+0x158/0x1b0
<4>[  123.825292]  #1:  (&of->mutex){+.+.}, at: [<00000000b1aae5e2>] kernfs_fop_write+0xd9/0x1a0
<4>[  123.825303]  #2:  (kn->count#132){.+.+}, at: [<00000000f959bbda>] kernfs_fop_write+0xe2/0x1a0
<4>[  123.825313]  #3:  (pm_mutex){+.+.}, at: [<0000000013ef834e>] pm_suspend+0x9b/0x9d0
<4>[  123.825323] 
<4>[  123.825324] =============================================
<4>[  123.825324] 
<4>[  123.825327] NMI backtrace for cpu 0
<4>[  123.825330] CPU: 0 PID: 66 Comm: khungtaskd Tainted: G     U           4.15.0-rc6-CI-CI_DRM_3600+ #1
<4>[  123.825332] Hardware name: MSI MS-7924/Z97M-G43(MS-7924), BIOS V1.12 02/15/2016
<4>[  123.825333] Call Trace:
<4>[  123.825337]  dump_stack+0x5f/0x86
<4>[  123.825340]  nmi_cpu_backtrace+0xb4/0xc0
<4>[  123.825346]  ? lapic_can_unplug_cpu+0x90/0x90
<4>[  123.825349]  nmi_trigger_cpumask_backtrace+0xb8/0xf0
<4>[  123.825353]  watchdog+0x43e/0x5e0
<4>[  123.825358]  kthread+0xfb/0x130
<4>[  123.825360]  ? reset_hung_task_detector+0x10/0x10
<4>[  123.825362]  ? _kthread_create_on_node+0x30/0x30
<4>[  123.825366]  ret_from_fork+0x24/0x30
<6>[  123.825375] Sending NMI from CPU 0 to CPUs 1-7:
<4>[  123.825383] NMI backtrace for cpu 4 skipped: idling at intel_idle+0x6f/0x120
<4>[  123.825394] NMI backtrace for cpu 7 skipped: idling at intel_idle+0x6f/0x120
<4>[  123.825397] NMI backtrace for cpu 3 skipped: idling at intel_idle+0x6f/0x120
<4>[  123.825400] NMI backtrace for cpu 5 skipped: idling at intel_idle+0x6f/0x120
<4>[  123.825403] NMI backtrace for cpu 1 skipped: idling at intel_idle+0x6f/0x120
<4>[  123.825407] NMI backtrace for cpu 6 skipped: idling at intel_idle+0x6f/0x120
<4>[  123.825410] NMI backtrace for cpu 2 skipped: idling at intel_idle+0x6f/0x120
<0>[  123.826383] Kernel panic - not syncing: hung_task: blocked tasks
<4>[  123.826400] CPU: 0 PID: 66 Comm: khungtaskd Tainted: G     U           4.15.0-rc6-CI-CI_DRM_3600+ #1
<4>[  123.826421] Hardware name: MSI MS-7924/Z97M-G43(MS-7924), BIOS V1.12 02/15/2016
<4>[  123.826439] Call Trace:
<4>[  123.826448]  dump_stack+0x5f/0x86
<4>[  123.826459]  panic+0xcf/0x20d
<4>[  123.826474]  watchdog+0x44a/0x5e0
<4>[  123.826486]  kthread+0xfb/0x130
<4>[  123.826496]  ? reset_hung_task_detector+0x10/0x10
<4>[  123.826508]  ? _kthread_create_on_node+0x30/0x30
<4>[  123.826522]  ret_from_fork+0x24/0x30
<0>[  123.826922] Dumping ftrace buffer:
<0>[  123.826995]    (ftrace buffer empty)
<0>[  123.827006] Kernel Offset: disabled
Comment 19 Marta Löfstedt 2018-01-11 08:22:05 UTC
*** Bug 104009 has been marked as a duplicate of this bug. ***
Comment 20 Marta Löfstedt 2018-01-11 08:24:29 UTC
*** Bug 103525 has been marked as a duplicate of this bug. ***
Comment 21 Marta Löfstedt 2018-01-12 13:18:36 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/IGT_4133/shard-snb6/igt@prime_self_import@reimport-vs-gem_close-race.html

run.log doesn't match results:
run.log:
running: igt/gem_tiled_swapping/non-threaded

[34/76] skip: 18, pass: 16 -                
FATAL: command execution failed
...
Completed CI_IGT_test CI_DRM_3624/shard-snb6/12 : FAILURE
CI_IGT_test runtime 212 seconds
Rebooting shard-snb6

dmesg:
<7>[  105.739615] [IGT] gem_tiled_swapping: starting subtest non-threaded
...
<7>[  181.532388] [IGT] gem_flink_basic: starting subtest flink-lifetime
<7>[  181.532706] [IGT] gem_flink_basic: exiting, ret=0
<6>[  181.542119] Console: switching to colour frame buffer device 128x48
Comment 22 Marta Löfstedt 2018-01-15 07:17:21 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_3625/shard-snb6/igt@gem_ctx_switch@basic-default-heavy.html

run.log doesn't match results last test is igt@gem_tiled_swapping@non-threaded:
running: igt/gem_tiled_swapping/non-threaded

[34/76] skip: 18, pass: 16 -                
FATAL: command execution failed

last dmesg:
<7>[  181.361294] [IGT] kms_flip: starting subtest 2x-busy-flip
<7>[  181.366829] [IGT] kms_flip: exiting, ret=77
<6>[  181.394551] Console: switching to colour frame buffer device 128x48
<6>[  181.495430] Console: switching to colour dummy device 80x25
<7>[  181.495480] [IGT] gem_ctx_switch: executing
Comment 23 Marta Löfstedt 2018-01-15 07:18:59 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_3629/shard-hsw5/igt@kms_flip@dpms-off-confusion-interruptible.html

run.log doesn't match result last test in run.log:
running: igt/gem_tiled_swapping/non-threaded

[07/77] skip: 2, pass: 5 \                  
FATAL: command execution failed

last dmesg:
<7>[  169.549258] [IGT] kms_frontbuffer_tracking: starting subtest psr-2p-scndscrn-pri-indfb-draw-mmap-gtt
<7>[  169.549593] [IGT] kms_frontbuffer_tracking: exiting, ret=77
Comment 24 Marta Löfstedt 2018-01-15 12:52:53 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_3631/shard-hsw3/igt@gem_exec_flush@basic-wb-set-default.html


[07/77] skip: 2, pass: 5 -
running: igt/gem_tiled_swapping/non-threaded

[07/77] skip: 2, pass: 5 \                  
FATAL: command execution failed
Comment 25 Marta Löfstedt 2018-01-18 06:44:34 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/IGT_4149/shard-snb6/igt@kms_cursor_legacy@pipe-b-forked-bo.html

last test in run.log:
running: igt/gem_tiled_swapping/non-threaded

from dmesg:
<7>[  105.736234] [IGT] gem_tiled_swapping: starting subtest non-threaded
...
<7>[  165.295673] [IGT] kms_cursor_legacy: starting subtest pipe-B-forked-bo
Comment 26 Marta Löfstedt 2018-01-18 07:21:58 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/IGT_4152/shard-glkb2/igt@kms_plane@plane-panning-bottom-right-suspend-pipe-d-planes.html

run.log:
pass: igt/gem_tiled_swapping/non-threaded

[53/77] skip: 15, pass: 32, fail: 6 |
running: igt/kms_plane/plane-panning-bottom-right-suspend-pipe-d-planes

[53/77] skip: 15, pass: 32, fail: 6 /                                  
FATAL: command execution failed
java.io.EOFException

last dmesg:
<7>[  342.794006] [IGT] gem_tiled_swapping: executing
<4>[  342.941191] hpet1: lost 7160 rtc interrupts
<4>[  343.833082] hpet1: lost 7161 rtc interrupts
<4>[  344.722754] hpet1: lost 7161 rtc interrupts
<4>[  345.643445] hpet1: lost 7161 rtc interrupts
<4>[  346.540868] hpet1: lost 7161 rtc interrupts
<7>[  346.829679] [IGT] gem_tiled_swapping: starting subtest non-threaded
<4>[  347.439913] hpet1: lost 7160 rtc interrupts
<4>[  348.328927] hpet1: lost 7161 rtc interrupts
<4>[  349.218968] hpet1: lost 7160 rtc interrupts
<4>[  350.114868] hpet1: lost 7160 rtc interrupts
<4>[  350.982943] hpet1: lost 7161 rtc interrupts
<4>[  351.870914] hpet1: lost 7161 rtc interrupts
<4>[  352.758969] hpet1: lost 7160 rtc interrupts
<4>[  353.660559] hpet1: lost 7161 rtc interrupts
<4>[  354.575417] hpet1: lost 7161 rtc interrupts
<4>[  355.490256] hpet1: lost 7161 rtc interrupts
<4>[  356.404387] hpet1: lost 7161 rtc interrupts
<4>[  357.318114] hpet1: lost 7161 rtc interrupts
<4>[  358.230353] hpet1: lost 7161 rtc interrupts
<4>[  359.117455] hpet1: lost 7161 rtc interrupts
<4>[  359.989715] hpet1: lost 7161 rtc interrupts
<4>[  360.880813] hpet1: lost 7161 rtc interrupts
<4>[  361.771852] hpet1: lost 7160 rtc interrupts
<4>[  362.663542] hpet1: lost 7161 rtc interrupts
<4>[  363.554807] hpet1: lost 7161 rtc interrupts
<4>[  364.445222] hpet1: lost 7161 rtc interrupts
<4>[  365.336485] hpet1: lost 7161 rtc interrupts
<7>[  382.277695] [IGT] gem_tiled_swapping: exiting, ret=0

pstore has a lot of:
<0>[  743.048761] gem_pers-1647    3..s1 238987857us : execlists_submission_tasklet: bcs0 in[0]:  ctx=2.2, seqno=2f1
and then just backtrace of sysrq trigger.
Comment 27 Marta Löfstedt 2018-01-18 07:30:06 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/IGT_4152/shard-apl3/igt@pm_rps@reset.html

last in run.log:
running: igt/gem_tiled_swapping/non-threaded

from dmesg:
<4>[  292.845498] hpet1: lost 7160 rtc interrupts
<7>[  293.200218] [IGT] gem_tiled_swapping: starting subtest non-threaded
<4>[  293.760511] hpet1: lost 7161 rtc interrupts
...
<7>[  367.284472] [drm:intel_dp_read_dpcd [i915]] DPCD: 11 0a 82 01 00 03 01 01 02 00 00 00 00 00 00
<7>[  367.630311] [IGT] pm_rps: executing

pstore starts with:
<4>[  369.811603] 1 lock held by dmesg/1056:
<4>[  369.811606]  #0:  (&user->lock){+.+.}, at: [<000000000c0f2971>] devkmsg_read+0x35/0x2f0

so maybe some deadlocky thing, then there is ftrace.
Comment 28 Marta Löfstedt 2018-01-19 09:08:01 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_3652/shard-hsw4/igt@gem_wait@write-wait-render.html

last in run.log:
running: igt/gem_tiled_swapping/non-threaded

from dmesg:
<7>[   90.805782] [IGT] gem_tiled_swapping: starting subtest non-threaded
<7>[  128.124226] [IGT] gem_tiled_swapping: exiting, ret=0
...
<7>[  184.200292] [IGT] perf: executing
<7>[  184.214368] [IGT] perf: starting subtest invalid-open-flags
<7>[  184.214467] [IGT] perf: exiting, ret=0

pstore say:
<3>[  185.311947] INFO: task kswapd0:80 blocked for more than 60 seconds.

so kswap has been blocked 60 seconds, i.e. when gem_tiled_swapping@non-threaded
was run.
Comment 29 Marta Löfstedt 2018-01-22 08:46:01 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/IGT_4161/shard-hsw7/igt@gem_cpu_reloc@full.html

last test in run.log:
running: igt/gem_tiled_swapping/non-threaded

from dmesg:
<7>[   48.618066] [IGT] gem_tiled_swapping: starting subtest non-threaded
...
<7>[   89.998332] [IGT] gem_cpu_reloc: executing
<7>[   90.017340] [IGT] gem_cpu_reloc: starting subtest full
Comment 30 Marta Löfstedt 2018-01-23 07:44:34 UTC
*** Bug 104479 has been marked as a duplicate of this bug. ***
Comment 31 Marta Löfstedt 2018-01-23 07:59:39 UTC
Last occurrence of this issue appear to be here:
https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_3663/shard-hsw8/igt@kms_flip@flip-vs-panning.html

We are now at CI_DRM_3671.

I will keep monitoring, I have no idea of what that may have changed that could have fixed this issue.
Comment 32 Marta Löfstedt 2018-01-24 11:11:27 UTC
went through all shard run.logs CI_DRM_3671 - CI_DRM_3677, still no issues on shards with igt@gem_tiled_swapping@non-threaded in them.
Comment 33 Marta Löfstedt 2018-01-26 08:26:40 UTC
Went trough all run.log CI_DRM_3677 - CI_DRM_3684, only one incomplete where igt@gem_tiled_swapping@non-threaded was run before:

https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_3684/shard-kbl3/igt@gem_tiled_swapping@non-threaded.html

However,
<7>[   38.122175] [IGT] gem_tiled_swapping: starting subtest non-threaded

last test in run.log is:
igt/drv_suspend/debugfs-reader-hibernate

<7>[  154.190154] [IGT] drv_suspend: starting subtest debugfs-reader-hibernate

so more than 60 seconds rules out the previous non-threaded issue.

The "Last seen" calculation in cibuglog is not suitable for bugs with big impact, and KBL hitting Link training on previously affected subtests. 

I will close this.


Use of freedesktop.org services, including Bugzilla, is subject to our Code of Conduct.