Bug 111440 - [CI][DRMTIP] igt@gem_pwrite@small-cpu-randomigt@gem_pwrite@small-cpu-random - dmesg-warn - INFO: task kworker/u16:4:154 blocked for more than 61 seconds.
Summary: [CI][DRMTIP] igt@gem_pwrite@small-cpu-randomigt@gem_pwrite@small-cpu-random -...
Status: RESOLVED NOTOURBUG
Alias: None
Product: DRI
Classification: Unclassified
Component: DRM/Intel (show other bugs)
Version: DRI git
Hardware: Other All
: medium normal
Assignee: Intel GFX Bugs mailing list
QA Contact: Intel GFX Bugs mailing list
URL:
Whiteboard: ReadyForDev
Keywords:
Depends on:
Blocks:
 
Reported: 2019-08-20 10:37 UTC by Lakshmi
Modified: 2019-09-08 14:45 UTC (History)
1 user (show)

See Also:
i915 platform: G33
i915 features: GEM/Other


Attachments

Description Lakshmi 2019-08-20 10:37:42 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_347/fi-blb-e6850/igt@gem_pwrite@small-cpu-random.html

<6> [34.633962] Console: switching to colour dummy device 80x25
<6> [34.634076] [IGT] gem_pwrite: executing
<6> [34.645570] [IGT] gem_pwrite: starting subtest small-cpu-random
<6> [34.660994] gem_pwrite (1005): drop_caches: 4
<6> [38.869235] [IGT] gem_pwrite: exiting, ret=0
<5> [38.871552] Setting dangerous option reset - tainting kernel
<3> [124.235542] INFO: task kworker/u16:4:154 blocked for more than 61 seconds.
<3> [124.235628]       Tainted: G     U  W         5.3.0-rc4-ge64af2bda23c-drmtip_347+ #1
<3> [124.235681] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
<6> [124.235719] kworker/u16:4   D13272   154      2 0x80004000
<6> [124.235734] Workqueue: events_unbound async_run_entry_fn
<4> [124.235738] Call Trace:
<4> [124.235748]  ? __schedule+0x30e/0x860
<4> [124.235756]  ? wait_for_common+0x116/0x1f0
<4> [124.235761]  schedule+0x2e/0xb0
<4> [124.235765]  schedule_timeout+0x21b/0x3d0
<4> [124.235773]  ? wait_for_common+0x116/0x1f0
<4> [124.235777]  ? mark_held_locks+0x49/0x70
<4> [124.235781]  ? _raw_spin_unlock_irq+0x24/0x50
<4> [124.235787]  ? wait_for_common+0x116/0x1f0
<4> [124.235791]  wait_for_common+0x13a/0x1f0
<4> [124.235797]  ? wake_up_q+0x80/0x80
<4> [124.235806]  __flush_work+0x28f/0x4d0
<4> [124.235812]  ? flush_workqueue_prep_pwqs+0x1b0/0x1b0
<4> [124.235825]  ? work_busy+0x150/0x150
<4> [124.235829]  __cancel_work_timer+0x13b/0x1e0
<4> [124.235847]  mei_cancel_work+0x1c/0x30 [mei]
<4> [124.235855]  mei_me_probe+0x316/0x380 [mei_me]
<4> [124.235863]  pci_device_probe+0x9e/0x120
<4> [124.235871]  really_probe+0xea/0x3d0
<4> [124.235877]  driver_probe_device+0x10b/0x120
<4> [124.235882]  __driver_attach_async_helper+0x7f/0x90
<4> [124.235887]  async_run_entry_fn+0x34/0x160
<4> [124.235893]  process_one_work+0x245/0x610
<4> [124.235903]  worker_thread+0x37/0x380
<4> [124.235910]  ? process_one_work+0x610/0x610
<4> [124.235913]  kthread+0x119/0x130
<4> [124.235917]  ? kthread_park+0xa0/0xa0
<4> [124.235924]  ret_from_fork+0x3a/0x50
<3> [124.235941] INFO: task systemd-udevd:264 blocked for more than 61 seconds.
<3> [124.235975]       Tainted: G     U  W         5.3.0-rc4-ge64af2bda23c-drmtip_347+ #1
<3> [124.236013] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
<6> [124.236051] systemd-udevd   D12504   264    214 0x80004100
<4> [124.236058] Call Trace:
<4> [124.236066]  ? __schedule+0x30e/0x860
<4> [124.236075]  schedule+0x2e/0xb0
<4> [124.236080]  async_synchronize_cookie_domain+0x9f/0x150
<4> [124.236084]  ? wait_woken+0xa0/0xa0
<4> [124.236094]  do_init_module+0xb7/0x1f6
<4> [124.236099]  load_module+0x25bd/0x2a40
<4> [124.236123]  ? __se_sys_finit_module+0xd3/0xf0
<4> [124.236127]  __se_sys_finit_module+0xd3/0xf0
<4> [124.236143]  do_syscall_64+0x55/0x1c0
<4> [124.236148]  entry_SYSCALL_64_after_hwframe+0x49/0xbe
<4> [124.236151] RIP: 0033:0x7fe3834c8839
<4> [124.236159] Code: Bad RIP value.
<4> [124.236162] RSP: 002b:00007ffe64261328 EFLAGS: 00000246 ORIG_RAX: 0000000000000139
<4> [124.236166] RAX: ffffffffffffffda RBX: 0000558d1f9eebb0 RCX: 00007fe3834c8839
<4> [124.236169] RDX: 0000000000000000 RSI: 00007fe3831a7145 RDI: 000000000000000f
<4> [124.236172] RBP: 00007fe3831a7145 R08: 0000000000000000 R09: 00007ffe64261440
<4> [124.236175] R10: 000000000000000f R11: 0000000000000246 R12: 0000000000000000
<4> [124.236178] R13: 0000558d1fa10e90 R14: 0000000000020000 R15: 0000558d1f9eebb0
<3> [124.236192] INFO: task systemd-udevd:266 blocked for more than 61 seconds.
<3> [124.236227]       Tainted: G     U  W         5.3.0-rc4-ge64af2bda23c-drmtip_347+ #1
<3> [124.236264] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
<6> [124.236302] systemd-udevd   D13176   266    214 0x80004100
<4> [124.236310] Call Trace:
<4> [124.236317]  ? __schedule+0x30e/0x860
<4> [124.236327]  schedule+0x2e/0xb0
<4> [124.236331]  async_synchronize_cookie_domain+0x9f/0x150
<4> [124.236336]  ? wait_woken+0xa0/0xa0
<4> [124.236343]  do_init_module+0xb7/0x1f6
<4> [124.236348]  load_module+0x25bd/0x2a40
<4> [124.236372]  ? __se_sys_finit_module+0xd3/0xf0
<4> [124.236375]  __se_sys_finit_module+0xd3/0xf0
<4> [124.236391]  do_syscall_64+0x55/0x1c0
<4> [124.236395]  entry_SYSCALL_64_after_hwframe+0x49/0xbe
<4> [124.236398] RIP: 0033:0x7fe3834c8839
<4> [124.236403] Code: Bad RIP value.
<4> [124.236406] RSP: 002b:00007ffe64261328 EFLAGS: 00000246 ORIG_RAX: 0000000000000139
<4> [124.236410] RAX: ffffffffffffffda RBX: 0000558d1f9eebb0 RCX: 00007fe3834c8839
<4> [124.236413] RDX: 0000000000000000 RSI: 00007fe3831a7145 RDI: 000000000000000f
<4> [124.236416] RBP: 00007fe3831a7145 R08: 0000000000000000 R09: 00007ffe64261440
<4> [124.236419] R10: 000000000000000f R11: 0000000000000246 R12: 0000000000000000
<4> [124.236422] R13: 0000558d1fa10e90 R14: 0000000000020000 R15: 0000558d1f9eebb0
<3> [124.236440] INFO: task kworker/1:4:455 blocked for more than 61 seconds.
<3> [124.236473]       Tainted: G     U  W         5.3.0-rc4-ge64af2bda23c-drmtip_347+ #1
<3> [124.236551] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
<6> [124.236590] kworker/1:4     D14480   455      2 0x80004000
<6> [124.236602] Workqueue: events output_poll_execute
<4> [124.236606] Call Trace:
<4> [124.236613]  ? __schedule+0x30e/0x860
<4> [124.236623]  schedule+0x2e/0xb0
<4> [124.236627]  async_synchronize_cookie_domain+0x9f/0x150
<4> [124.236632]  ? wait_woken+0xa0/0xa0
<4> [124.236801]  intel_fbdev_output_poll_changed+0x7e/0x90 [i915]
<4> [124.236809]  drm_kms_helper_hotplug_event+0x21/0x30
<4> [124.236813]  output_poll_execute+0x1a0/0x1b0
<4> [124.236822]  process_one_work+0x245/0x610
<4> [124.236832]  worker_thread+0x37/0x380
<4> [124.236839]  ? process_one_work+0x610/0x610
<4> [124.236842]  kthread+0x119/0x130
<4> [124.236846]  ? kthread_park+0xa0/0xa0
<4> [124.236852]  ret_from_fork+0x3a/0x50
<3> [124.236876] INFO: task gem_pwrite:1005 blocked for more than 61 seconds.
<3> [124.236910]       Tainted: G     U  W         5.3.0-rc4-ge64af2bda23c-drmtip_347+ #1
<3> [124.236949] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
<6> [124.236988] gem_pwrite      D12808  1005   1004 0x00000000
<4> [124.236995] Call Trace:
<4> [124.237002]  ? __schedule+0x30e/0x860
<4> [124.237012]  schedule+0x2e/0xb0
<4> [124.237016]  async_synchronize_cookie_domain+0x9f/0x150
<4> [124.237021]  ? wait_woken+0xa0/0xa0
<4> [124.237105]  intel_fbdev_restore_mode+0x3a/0x60 [i915]
<4> [124.237110]  drm_lastclose+0x2a/0x50
<4> [124.237114]  drm_release+0xb9/0xe0
<4> [124.237120]  __fput+0xc2/0x250
<4> [124.237128]  task_work_run+0x82/0xb0
<4> [124.237135]  exit_to_usermode_loop+0x93/0xa0
<4> [124.237139]  do_syscall_64+0x16d/0x1c0
<4> [124.237143]  entry_SYSCALL_64_after_hwframe+0x49/0xbe
<4> [124.237147] RIP: 0033:0x7f27e2779421
<4> [124.237152] Code: Bad RIP value.
<4> [124.237155] RSP: 002b:00007ffe421b4678 EFLAGS: 00000246 ORIG_RAX: 0000000000000003
<4> [124.237159] RAX: 0000000000000000 RBX: 0000000000000001 RCX: 00007f27e2779421
<4> [124.237162] RDX: 0000000000000000 RSI: 00007ffe421b44b0 RDI: 0000000000000006
<4> [124.237165] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000000
<4> [124.237168] R10: 0000000000000000 R11: 0000000000000246 R12: 00007f27e2c0d860
<4> [124.237171] R13: 0000000000000003 R14: 00007f27e2767628 R15: 00007f27e2763d80
<4> [124.237184] 
Showing all locks held in the system:
<4> [124.237190] 1 lock held by khungtaskd/23:
<4> [124.237192]  #0: 00000000d5e7ba30 (rcu_read_lock){....}, at: debug_show_all_locks+0xe/0x1a0
<4> [124.237204] 3 locks held by kworker/u16:4/154:
<4> [124.237207]  #0: 00000000d401d32d ((wq_completion)events_unbound){+.+.}, at: process_one_work+0x1bf/0x610
<4> [124.237214]  #1: 000000008c682750 ((work_completion)(&entry->work)){+.+.}, at: process_one_work+0x1bf/0x610
<4> [124.237221]  #2: 00000000439a769d (&dev->mutex){....}, at: __driver_attach_async_helper+0x13/0x90
<4> [124.237229] 3 locks held by kworker/1:2/159:
<4> [124.237232]  #0: 00000000a264814d ((wq_completion)events){+.+.}, at: process_one_work+0x1bf/0x610
<4> [124.237238]  #1: 00000000f59b9d9b ((work_completion)(&dev->bus_rescan_work)){+.+.}, at: process_one_work+0x1bf/0x610
<4> [124.237245]  #2: 0000000062295e78 (&dev->cl_bus_lock){+.+.}, at: mei_cl_bus_rescan_work+0x2f/0x350 [mei]
<4> [124.237258] 1 lock held by in:imklog/281:
<4> [124.237262] 2 locks held by kworker/1:4/455:
<4> [124.237265]  #0: 00000000a264814d ((wq_completion)events){+.+.}, at: process_one_work+0x1bf/0x610
<4> [124.237271]  #1: 00000000c7d25de6 ((work_completion)(&(&dev->mode_config.output_poll_work)->work)){+.+.}, at: process_one_work+0x1bf/0x610
<4> [124.237283] 3 locks held by dmesg/987:
<4> [124.237286] 1 lock held by gem_pwrite/1005:
<4> [124.237288]  #0: 00000000b0cf4ab7 (drm_global_mutex){+.+.}, at: drm_release+0x26/0xe0
Comment 1 CI Bug Log 2019-08-20 10:38:20 UTC
The CI Bug Log issue associated to this bug has been updated.

### New filters associated

* BLB: igt@gem_pwrite@small-cpu-randomigt@gem_pwrite@small-cpu-random - dmesg-warn - INFO: task kworker/u16:4:154 blocked for more than 61 seconds.
  - https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_347/fi-blb-e6850/igt@gem_pwrite@small-cpu-random.html
Comment 2 Chris Wilson 2019-08-20 10:40:30 UTC
mei strikes again. We must already have a bug open for this because it regularly takes out module-reload on blb.
Comment 3 Chris Wilson 2019-09-08 14:45:57 UTC
Pure mei bug.


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.