linux-cifs.vger.kernel.org archive mirror
 help / color / mirror / Atom feed
* [5.0+ CIFS regression] fsstress hang on CIFS
@ 2019-03-14 14:25 Murphy Zhou
  2019-03-14 15:29 ` ronnie sahlberg
  2019-03-14 16:12 ` ronnie sahlberg
  0 siblings, 2 replies; 4+ messages in thread
From: Murphy Zhou @ 2019-03-14 14:25 UTC (permalink / raw)
  To: linux-cifs; +Cc: Steve French, Pavel Shilovsky

Hi,

xfstests generic/013 on CIFS hangs on Linus tree now.

Bisect points to

commit 7091bcaba9f34c83e1e6f418b6de5c6d987571da (HEAD, refs/bisect/bad)
Author: Pavel Shilovsky <pshilov@microsoft.com>
Date:   Wed Jan 30 16:58:09 2019 -0800

    CIFS: Try to acquire credits at once for compound requests

as the first bad commit.

It should be easy to reproduce.

Thanks,
M

dmesg:
run fstests generic/013 at 2019-03-14 09:51:56
INFO: task kworker/3:1:104 blocked for more than 120 seconds.
      Not tainted 5.0.0-bisect-7091bcaba9f3+ #15
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
kworker/3:1     D    0   104      2 0x80000000
Workqueue: cifsiod cifs_uncached_writev_complete [cifs]
Call Trace:
 ? __schedule+0x24e/0x860
 schedule+0x28/0x70
 schedule_preempt_disabled+0xa/0x10
 __mutex_lock.isra.8+0x2d0/0x4b0
 cifs_uncached_writev_complete+0xcd/0x570 [cifs]
 ? __switch_to_asm+0x40/0x70
 ? __switch_to_asm+0x40/0x70
 ? __switch_to_asm+0x34/0x70
 ? __switch_to_asm+0x40/0x70
 process_one_work+0x1a1/0x3a0
 worker_thread+0x30/0x380
 ? mod_delayed_work_on+0x90/0x90
 kthread+0x112/0x130
 ? __kthread_parkme+0x70/0x70
 ret_from_fork+0x35/0x40
INFO: task kworker/5:1:106 blocked for more than 120 seconds.
      Not tainted 5.0.0-bisect-7091bcaba9f3+ #15
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
kworker/5:1     D    0   106      2 0x80000000
Workqueue: cifsiod cifs_uncached_writev_complete [cifs]
Call Trace:
 ? __schedule+0x24e/0x860
 ? ttwu_do_wakeup+0x19/0x140
 schedule+0x28/0x70
 schedule_preempt_disabled+0xa/0x10
 __mutex_lock.isra.8+0x2d0/0x4b0
 cifs_uncached_writev_complete+0xcd/0x570 [cifs]
 ? __switch_to_asm+0x40/0x70
 ? __switch_to_asm+0x34/0x70
 ? __switch_to_asm+0x40/0x70
 process_one_work+0x1a1/0x3a0
 worker_thread+0x30/0x380
 ? mod_delayed_work_on+0x90/0x90
 kthread+0x112/0x130
 ? __kthread_parkme+0x70/0x70
 ret_from_fork+0x35/0x40
INFO: task kworker/7:1:108 blocked for more than 120 seconds.
      Not tainted 5.0.0-bisect-7091bcaba9f3+ #15
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
kworker/7:1     D    0   108      2 0x80000000
Workqueue: cifsiod cifs_uncached_writev_complete [cifs]
Call Trace:
 ? __schedule+0x24e/0x860
 ? ttwu_do_wakeup+0x19/0x140
 schedule+0x28/0x70
 schedule_preempt_disabled+0xa/0x10
 __mutex_lock.isra.8+0x2d0/0x4b0
 cifs_uncached_writev_complete+0xcd/0x570 [cifs]
 ? __switch_to_asm+0x40/0x70
 ? __switch_to_asm+0x40/0x70
 ? __switch_to_asm+0x34/0x70
 ? __switch_to_asm+0x40/0x70
 process_one_work+0x1a1/0x3a0
 worker_thread+0x30/0x380
 ? mod_delayed_work_on+0x90/0x90
 kthread+0x112/0x130
 ? __kthread_parkme+0x70/0x70
 ret_from_fork+0x35/0x40
INFO: task kworker/7:3:391 blocked for more than 120 seconds.
      Not tainted 5.0.0-bisect-7091bcaba9f3+ #15
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
kworker/7:3     D    0   391      2 0x80000000
Workqueue: cifsiod cifs_uncached_writev_complete [cifs]
Call Trace:
 ? __schedule+0x24e/0x860
 ? ttwu_do_wakeup+0x19/0x140
 schedule+0x28/0x70
 schedule_preempt_disabled+0xa/0x10
 __mutex_lock.isra.8+0x2d0/0x4b0
 cifs_uncached_writev_complete+0xcd/0x570 [cifs]
 ? __switch_to_asm+0x40/0x70
 ? __switch_to_asm+0x40/0x70
 ? __switch_to_asm+0x34/0x70
 ? __switch_to_asm+0x40/0x70
 process_one_work+0x1a1/0x3a0
 worker_thread+0x30/0x380
 ? mod_delayed_work_on+0x90/0x90
 kthread+0x112/0x130
 ? __kthread_parkme+0x70/0x70
 ret_from_fork+0x35/0x40
INFO: task kworker/1:3:807 blocked for more than 120 seconds.
      Not tainted 5.0.0-bisect-7091bcaba9f3+ #15
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
kworker/1:3     D    0   807      2 0x80000000
Workqueue: cifsiod cifs_uncached_writev_complete [cifs]
Call Trace:
 ? __schedule+0x24e/0x860
 schedule+0x28/0x70
 schedule_preempt_disabled+0xa/0x10
 __mutex_lock.isra.8+0x2d0/0x4b0
 cifs_uncached_writev_complete+0xcd/0x570 [cifs]
 ? __switch_to_asm+0x40/0x70
 ? __switch_to_asm+0x40/0x70
 ? __switch_to_asm+0x34/0x70
 ? __switch_to_asm+0x40/0x70
 process_one_work+0x1a1/0x3a0
 worker_thread+0x30/0x380
 ? mod_delayed_work_on+0x90/0x90
 kthread+0x112/0x130
 ? __kthread_parkme+0x70/0x70
 ret_from_fork+0x35/0x40
INFO: task kworker/13:2:1077 blocked for more than 120 seconds.
      Not tainted 5.0.0-bisect-7091bcaba9f3+ #15
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
kworker/13:2    D    0  1077      2 0x80000080
Workqueue: cifsiod cifs_uncached_readv_complete [cifs]
Call Trace:
 ? __schedule+0x24e/0x860
 schedule+0x28/0x70
 schedule_preempt_disabled+0xa/0x10
 __mutex_lock.isra.8+0x2d0/0x4b0
 ? __switch_to_asm+0x40/0x70
 cifs_uncached_readv_complete+0x78/0x4d0 [cifs]
 ? __switch_to_asm+0x34/0x70
 process_one_work+0x1a1/0x3a0
 worker_thread+0x30/0x380
 ? mod_delayed_work_on+0x90/0x90
 kthread+0x112/0x130
 ? __kthread_parkme+0x70/0x70
 ret_from_fork+0x35/0x40
INFO: task kworker/3:0:1910 blocked for more than 120 seconds.
      Not tainted 5.0.0-bisect-7091bcaba9f3+ #15
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
kworker/3:0     D    0  1910      2 0x80000080
Workqueue: cifsiod cifs_uncached_writev_complete [cifs]
Call Trace:
 ? __schedule+0x24e/0x860
 schedule+0x28/0x70
 schedule_preempt_disabled+0xa/0x10
 __mutex_lock.isra.8+0x2d0/0x4b0
 cifs_uncached_writev_complete+0xcd/0x570 [cifs]
 ? __switch_to_asm+0x40/0x70
 ? __switch_to_asm+0x40/0x70
 ? __switch_to_asm+0x34/0x70
 ? __switch_to_asm+0x40/0x70
 process_one_work+0x1a1/0x3a0
 worker_thread+0x30/0x380
 ? mod_delayed_work_on+0x90/0x90
 kthread+0x112/0x130
 ? __kthread_parkme+0x70/0x70
 ret_from_fork+0x35/0x40
INFO: task kworker/5:5:3930 blocked for more than 120 seconds.
      Not tainted 5.0.0-bisect-7091bcaba9f3+ #15
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
kworker/5:5     D    0  3930      2 0x80000080
Workqueue: cifsiod cifs_uncached_writev_complete [cifs]
Call Trace:
 ? __schedule+0x24e/0x860
 schedule+0x28/0x70
 schedule_preempt_disabled+0xa/0x10
 __mutex_lock.isra.8+0x2d0/0x4b0
 cifs_uncached_writev_complete+0xcd/0x570 [cifs]
 ? __switch_to_asm+0x40/0x70
 ? __switch_to_asm+0x40/0x70
 ? __switch_to_asm+0x34/0x70
 ? __switch_to_asm+0x40/0x70
 process_one_work+0x1a1/0x3a0
 worker_thread+0x30/0x380
 ? mod_delayed_work_on+0x90/0x90
 kthread+0x112/0x130
 ? __kthread_parkme+0x70/0x70
 ret_from_fork+0x35/0x40
INFO: task kworker/1:2:3932 blocked for more than 120 seconds.
      Not tainted 5.0.0-bisect-7091bcaba9f3+ #15
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
kworker/1:2     D    0  3932      2 0x80000080
Workqueue: cifsiod cifs_uncached_readv_complete [cifs]
Call Trace:
 ? __schedule+0x24e/0x860
 schedule+0x28/0x70
 schedule_preempt_disabled+0xa/0x10
 __mutex_lock.isra.8+0x2d0/0x4b0
 ? __switch_to_asm+0x40/0x70
 cifs_uncached_readv_complete+0x78/0x4d0 [cifs]
 ? __switch_to_asm+0x34/0x70
 process_one_work+0x1a1/0x3a0
 worker_thread+0x30/0x380
 ? mod_delayed_work_on+0x90/0x90
 kthread+0x112/0x130
 ? __kthread_parkme+0x70/0x70
 ret_from_fork+0x35/0x40
INFO: task kworker/1:5:3934 blocked for more than 120 seconds.
      Not tainted 5.0.0-bisect-7091bcaba9f3+ #15
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
kworker/1:5     D    0  3934      2 0x80000080
Workqueue: cifsiod cifs_uncached_readv_complete [cifs]
Call Trace:
 ? __schedule+0x24e/0x860
 schedule+0x28/0x70
 schedule_preempt_disabled+0xa/0x10
 __mutex_lock.isra.8+0x2d0/0x4b0
 ? __switch_to_asm+0x40/0x70
 cifs_uncached_readv_complete+0x78/0x4d0 [cifs]
 ? __switch_to_asm+0x34/0x70
 process_one_work+0x1a1/0x3a0
 worker_thread+0x30/0x380
 ? mod_delayed_work_on+0x90/0x90
 kthread+0x112/0x130
 ? __kthread_parkme+0x70/0x70
 ret_from_fork+0x35/0x40

^ permalink raw reply	[flat|nested] 4+ messages in thread

* Re: [5.0+ CIFS regression] fsstress hang on CIFS
  2019-03-14 14:25 [5.0+ CIFS regression] fsstress hang on CIFS Murphy Zhou
@ 2019-03-14 15:29 ` ronnie sahlberg
  2019-03-14 16:12 ` ronnie sahlberg
  1 sibling, 0 replies; 4+ messages in thread
From: ronnie sahlberg @ 2019-03-14 15:29 UTC (permalink / raw)
  To: Murphy Zhou; +Cc: linux-cifs, Steve French, Pavel Shilovsky

On Fri, Mar 15, 2019 at 12:25 AM Murphy Zhou <jencce.kernel@gmail.com> wrote:
>
> Hi,
>
> xfstests generic/013 on CIFS hangs on Linus tree now.

generic/013 works on Steves for-next branch, but it contains changes
in this area.
We do have generic/013 in our buildbot so it should have been tested and passed.

Can you describe your configuration? It could be a configuration that
we do not have proper cover for.



>
> Bisect points to
>
> commit 7091bcaba9f34c83e1e6f418b6de5c6d987571da (HEAD, refs/bisect/bad)
> Author: Pavel Shilovsky <pshilov@microsoft.com>
> Date:   Wed Jan 30 16:58:09 2019 -0800
>
>     CIFS: Try to acquire credits at once for compound requests
>
> as the first bad commit.
>
> It should be easy to reproduce.
>
> Thanks,
> M
>
> dmesg:
> run fstests generic/013 at 2019-03-14 09:51:56
> INFO: task kworker/3:1:104 blocked for more than 120 seconds.
>       Not tainted 5.0.0-bisect-7091bcaba9f3+ #15
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> kworker/3:1     D    0   104      2 0x80000000
> Workqueue: cifsiod cifs_uncached_writev_complete [cifs]
> Call Trace:
>  ? __schedule+0x24e/0x860
>  schedule+0x28/0x70
>  schedule_preempt_disabled+0xa/0x10
>  __mutex_lock.isra.8+0x2d0/0x4b0
>  cifs_uncached_writev_complete+0xcd/0x570 [cifs]
>  ? __switch_to_asm+0x40/0x70
>  ? __switch_to_asm+0x40/0x70
>  ? __switch_to_asm+0x34/0x70
>  ? __switch_to_asm+0x40/0x70
>  process_one_work+0x1a1/0x3a0
>  worker_thread+0x30/0x380
>  ? mod_delayed_work_on+0x90/0x90
>  kthread+0x112/0x130
>  ? __kthread_parkme+0x70/0x70
>  ret_from_fork+0x35/0x40
> INFO: task kworker/5:1:106 blocked for more than 120 seconds.
>       Not tainted 5.0.0-bisect-7091bcaba9f3+ #15
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> kworker/5:1     D    0   106      2 0x80000000
> Workqueue: cifsiod cifs_uncached_writev_complete [cifs]
> Call Trace:
>  ? __schedule+0x24e/0x860
>  ? ttwu_do_wakeup+0x19/0x140
>  schedule+0x28/0x70
>  schedule_preempt_disabled+0xa/0x10
>  __mutex_lock.isra.8+0x2d0/0x4b0
>  cifs_uncached_writev_complete+0xcd/0x570 [cifs]
>  ? __switch_to_asm+0x40/0x70
>  ? __switch_to_asm+0x34/0x70
>  ? __switch_to_asm+0x40/0x70
>  process_one_work+0x1a1/0x3a0
>  worker_thread+0x30/0x380
>  ? mod_delayed_work_on+0x90/0x90
>  kthread+0x112/0x130
>  ? __kthread_parkme+0x70/0x70
>  ret_from_fork+0x35/0x40
> INFO: task kworker/7:1:108 blocked for more than 120 seconds.
>       Not tainted 5.0.0-bisect-7091bcaba9f3+ #15
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> kworker/7:1     D    0   108      2 0x80000000
> Workqueue: cifsiod cifs_uncached_writev_complete [cifs]
> Call Trace:
>  ? __schedule+0x24e/0x860
>  ? ttwu_do_wakeup+0x19/0x140
>  schedule+0x28/0x70
>  schedule_preempt_disabled+0xa/0x10
>  __mutex_lock.isra.8+0x2d0/0x4b0
>  cifs_uncached_writev_complete+0xcd/0x570 [cifs]
>  ? __switch_to_asm+0x40/0x70
>  ? __switch_to_asm+0x40/0x70
>  ? __switch_to_asm+0x34/0x70
>  ? __switch_to_asm+0x40/0x70
>  process_one_work+0x1a1/0x3a0
>  worker_thread+0x30/0x380
>  ? mod_delayed_work_on+0x90/0x90
>  kthread+0x112/0x130
>  ? __kthread_parkme+0x70/0x70
>  ret_from_fork+0x35/0x40
> INFO: task kworker/7:3:391 blocked for more than 120 seconds.
>       Not tainted 5.0.0-bisect-7091bcaba9f3+ #15
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> kworker/7:3     D    0   391      2 0x80000000
> Workqueue: cifsiod cifs_uncached_writev_complete [cifs]
> Call Trace:
>  ? __schedule+0x24e/0x860
>  ? ttwu_do_wakeup+0x19/0x140
>  schedule+0x28/0x70
>  schedule_preempt_disabled+0xa/0x10
>  __mutex_lock.isra.8+0x2d0/0x4b0
>  cifs_uncached_writev_complete+0xcd/0x570 [cifs]
>  ? __switch_to_asm+0x40/0x70
>  ? __switch_to_asm+0x40/0x70
>  ? __switch_to_asm+0x34/0x70
>  ? __switch_to_asm+0x40/0x70
>  process_one_work+0x1a1/0x3a0
>  worker_thread+0x30/0x380
>  ? mod_delayed_work_on+0x90/0x90
>  kthread+0x112/0x130
>  ? __kthread_parkme+0x70/0x70
>  ret_from_fork+0x35/0x40
> INFO: task kworker/1:3:807 blocked for more than 120 seconds.
>       Not tainted 5.0.0-bisect-7091bcaba9f3+ #15
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> kworker/1:3     D    0   807      2 0x80000000
> Workqueue: cifsiod cifs_uncached_writev_complete [cifs]
> Call Trace:
>  ? __schedule+0x24e/0x860
>  schedule+0x28/0x70
>  schedule_preempt_disabled+0xa/0x10
>  __mutex_lock.isra.8+0x2d0/0x4b0
>  cifs_uncached_writev_complete+0xcd/0x570 [cifs]
>  ? __switch_to_asm+0x40/0x70
>  ? __switch_to_asm+0x40/0x70
>  ? __switch_to_asm+0x34/0x70
>  ? __switch_to_asm+0x40/0x70
>  process_one_work+0x1a1/0x3a0
>  worker_thread+0x30/0x380
>  ? mod_delayed_work_on+0x90/0x90
>  kthread+0x112/0x130
>  ? __kthread_parkme+0x70/0x70
>  ret_from_fork+0x35/0x40
> INFO: task kworker/13:2:1077 blocked for more than 120 seconds.
>       Not tainted 5.0.0-bisect-7091bcaba9f3+ #15
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> kworker/13:2    D    0  1077      2 0x80000080
> Workqueue: cifsiod cifs_uncached_readv_complete [cifs]
> Call Trace:
>  ? __schedule+0x24e/0x860
>  schedule+0x28/0x70
>  schedule_preempt_disabled+0xa/0x10
>  __mutex_lock.isra.8+0x2d0/0x4b0
>  ? __switch_to_asm+0x40/0x70
>  cifs_uncached_readv_complete+0x78/0x4d0 [cifs]
>  ? __switch_to_asm+0x34/0x70
>  process_one_work+0x1a1/0x3a0
>  worker_thread+0x30/0x380
>  ? mod_delayed_work_on+0x90/0x90
>  kthread+0x112/0x130
>  ? __kthread_parkme+0x70/0x70
>  ret_from_fork+0x35/0x40
> INFO: task kworker/3:0:1910 blocked for more than 120 seconds.
>       Not tainted 5.0.0-bisect-7091bcaba9f3+ #15
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> kworker/3:0     D    0  1910      2 0x80000080
> Workqueue: cifsiod cifs_uncached_writev_complete [cifs]
> Call Trace:
>  ? __schedule+0x24e/0x860
>  schedule+0x28/0x70
>  schedule_preempt_disabled+0xa/0x10
>  __mutex_lock.isra.8+0x2d0/0x4b0
>  cifs_uncached_writev_complete+0xcd/0x570 [cifs]
>  ? __switch_to_asm+0x40/0x70
>  ? __switch_to_asm+0x40/0x70
>  ? __switch_to_asm+0x34/0x70
>  ? __switch_to_asm+0x40/0x70
>  process_one_work+0x1a1/0x3a0
>  worker_thread+0x30/0x380
>  ? mod_delayed_work_on+0x90/0x90
>  kthread+0x112/0x130
>  ? __kthread_parkme+0x70/0x70
>  ret_from_fork+0x35/0x40
> INFO: task kworker/5:5:3930 blocked for more than 120 seconds.
>       Not tainted 5.0.0-bisect-7091bcaba9f3+ #15
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> kworker/5:5     D    0  3930      2 0x80000080
> Workqueue: cifsiod cifs_uncached_writev_complete [cifs]
> Call Trace:
>  ? __schedule+0x24e/0x860
>  schedule+0x28/0x70
>  schedule_preempt_disabled+0xa/0x10
>  __mutex_lock.isra.8+0x2d0/0x4b0
>  cifs_uncached_writev_complete+0xcd/0x570 [cifs]
>  ? __switch_to_asm+0x40/0x70
>  ? __switch_to_asm+0x40/0x70
>  ? __switch_to_asm+0x34/0x70
>  ? __switch_to_asm+0x40/0x70
>  process_one_work+0x1a1/0x3a0
>  worker_thread+0x30/0x380
>  ? mod_delayed_work_on+0x90/0x90
>  kthread+0x112/0x130
>  ? __kthread_parkme+0x70/0x70
>  ret_from_fork+0x35/0x40
> INFO: task kworker/1:2:3932 blocked for more than 120 seconds.
>       Not tainted 5.0.0-bisect-7091bcaba9f3+ #15
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> kworker/1:2     D    0  3932      2 0x80000080
> Workqueue: cifsiod cifs_uncached_readv_complete [cifs]
> Call Trace:
>  ? __schedule+0x24e/0x860
>  schedule+0x28/0x70
>  schedule_preempt_disabled+0xa/0x10
>  __mutex_lock.isra.8+0x2d0/0x4b0
>  ? __switch_to_asm+0x40/0x70
>  cifs_uncached_readv_complete+0x78/0x4d0 [cifs]
>  ? __switch_to_asm+0x34/0x70
>  process_one_work+0x1a1/0x3a0
>  worker_thread+0x30/0x380
>  ? mod_delayed_work_on+0x90/0x90
>  kthread+0x112/0x130
>  ? __kthread_parkme+0x70/0x70
>  ret_from_fork+0x35/0x40
> INFO: task kworker/1:5:3934 blocked for more than 120 seconds.
>       Not tainted 5.0.0-bisect-7091bcaba9f3+ #15
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> kworker/1:5     D    0  3934      2 0x80000080
> Workqueue: cifsiod cifs_uncached_readv_complete [cifs]
> Call Trace:
>  ? __schedule+0x24e/0x860
>  schedule+0x28/0x70
>  schedule_preempt_disabled+0xa/0x10
>  __mutex_lock.isra.8+0x2d0/0x4b0
>  ? __switch_to_asm+0x40/0x70
>  cifs_uncached_readv_complete+0x78/0x4d0 [cifs]
>  ? __switch_to_asm+0x34/0x70
>  process_one_work+0x1a1/0x3a0
>  worker_thread+0x30/0x380
>  ? mod_delayed_work_on+0x90/0x90
>  kthread+0x112/0x130
>  ? __kthread_parkme+0x70/0x70
>  ret_from_fork+0x35/0x40

^ permalink raw reply	[flat|nested] 4+ messages in thread

* Re: [5.0+ CIFS regression] fsstress hang on CIFS
  2019-03-14 14:25 [5.0+ CIFS regression] fsstress hang on CIFS Murphy Zhou
  2019-03-14 15:29 ` ronnie sahlberg
@ 2019-03-14 16:12 ` ronnie sahlberg
  2019-03-14 18:40   ` Pavel Shilovsky
  1 sibling, 1 reply; 4+ messages in thread
From: ronnie sahlberg @ 2019-03-14 16:12 UTC (permalink / raw)
  To: Murphy Zhou; +Cc: linux-cifs, Steve French, Pavel Shilovsky

On Fri, Mar 15, 2019 at 12:25 AM Murphy Zhou <jencce.kernel@gmail.com> wrote:
>
> Hi,
>
> xfstests generic/013 on CIFS hangs on Linus tree now.
>
> Bisect points to
>
> commit 7091bcaba9f34c83e1e6f418b6de5c6d987571da (HEAD, refs/bisect/bad)
> Author: Pavel Shilovsky <pshilov@microsoft.com>
> Date:   Wed Jan 30 16:58:09 2019 -0800
>
>     CIFS: Try to acquire credits at once for compound requests
>
> as the first bad commit.
>
> It should be easy to reproduce.

I built a kernel at 7091bcaba9f34c83e1e6
and it passes generic/013 against a windows2016 server for me.

It could be a configuration difference.  What are the mount options
you use and what server do you use?

The code in the commit you find has been majorly re-worked in the
for-next branch: https://github.com/smfrench/smb3-kernel
Can you try cherry-picking these patches and see if the problem remains ?

https://github.com/smfrench/smb3-kernel/commit/4b62ba8c7e9380f7274e3b4c90d41ab5e329ba08
https://github.com/smfrench/smb3-kernel/commit/e2d79dccc7929257f7a2c824b397092de596b5c1
https://github.com/smfrench/smb3-kernel/commit/15736c7f36cd55ef8c4e5df65c1a97ecd4b6e44f
https://github.com/smfrench/smb3-kernel/commit/1bb731eaf331cec630a0371db2d0b79d5344d1e3
https://github.com/smfrench/smb3-kernel/commit/a32fd3e57c3b15b456bbf39235d6555a88e20600
https://github.com/smfrench/smb3-kernel/commit/9ed2d4dce312973e2f998d520f8c976c899e0dd9



regards
ronnie sahlberg



>
> Thanks,
> M
>
> dmesg:
> run fstests generic/013 at 2019-03-14 09:51:56
> INFO: task kworker/3:1:104 blocked for more than 120 seconds.
>       Not tainted 5.0.0-bisect-7091bcaba9f3+ #15
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> kworker/3:1     D    0   104      2 0x80000000
> Workqueue: cifsiod cifs_uncached_writev_complete [cifs]
> Call Trace:
>  ? __schedule+0x24e/0x860
>  schedule+0x28/0x70
>  schedule_preempt_disabled+0xa/0x10
>  __mutex_lock.isra.8+0x2d0/0x4b0
>  cifs_uncached_writev_complete+0xcd/0x570 [cifs]
>  ? __switch_to_asm+0x40/0x70
>  ? __switch_to_asm+0x40/0x70
>  ? __switch_to_asm+0x34/0x70
>  ? __switch_to_asm+0x40/0x70
>  process_one_work+0x1a1/0x3a0
>  worker_thread+0x30/0x380
>  ? mod_delayed_work_on+0x90/0x90
>  kthread+0x112/0x130
>  ? __kthread_parkme+0x70/0x70
>  ret_from_fork+0x35/0x40
> INFO: task kworker/5:1:106 blocked for more than 120 seconds.
>       Not tainted 5.0.0-bisect-7091bcaba9f3+ #15
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> kworker/5:1     D    0   106      2 0x80000000
> Workqueue: cifsiod cifs_uncached_writev_complete [cifs]
> Call Trace:
>  ? __schedule+0x24e/0x860
>  ? ttwu_do_wakeup+0x19/0x140
>  schedule+0x28/0x70
>  schedule_preempt_disabled+0xa/0x10
>  __mutex_lock.isra.8+0x2d0/0x4b0
>  cifs_uncached_writev_complete+0xcd/0x570 [cifs]
>  ? __switch_to_asm+0x40/0x70
>  ? __switch_to_asm+0x34/0x70
>  ? __switch_to_asm+0x40/0x70
>  process_one_work+0x1a1/0x3a0
>  worker_thread+0x30/0x380
>  ? mod_delayed_work_on+0x90/0x90
>  kthread+0x112/0x130
>  ? __kthread_parkme+0x70/0x70
>  ret_from_fork+0x35/0x40
> INFO: task kworker/7:1:108 blocked for more than 120 seconds.
>       Not tainted 5.0.0-bisect-7091bcaba9f3+ #15
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> kworker/7:1     D    0   108      2 0x80000000
> Workqueue: cifsiod cifs_uncached_writev_complete [cifs]
> Call Trace:
>  ? __schedule+0x24e/0x860
>  ? ttwu_do_wakeup+0x19/0x140
>  schedule+0x28/0x70
>  schedule_preempt_disabled+0xa/0x10
>  __mutex_lock.isra.8+0x2d0/0x4b0
>  cifs_uncached_writev_complete+0xcd/0x570 [cifs]
>  ? __switch_to_asm+0x40/0x70
>  ? __switch_to_asm+0x40/0x70
>  ? __switch_to_asm+0x34/0x70
>  ? __switch_to_asm+0x40/0x70
>  process_one_work+0x1a1/0x3a0
>  worker_thread+0x30/0x380
>  ? mod_delayed_work_on+0x90/0x90
>  kthread+0x112/0x130
>  ? __kthread_parkme+0x70/0x70
>  ret_from_fork+0x35/0x40
> INFO: task kworker/7:3:391 blocked for more than 120 seconds.
>       Not tainted 5.0.0-bisect-7091bcaba9f3+ #15
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> kworker/7:3     D    0   391      2 0x80000000
> Workqueue: cifsiod cifs_uncached_writev_complete [cifs]
> Call Trace:
>  ? __schedule+0x24e/0x860
>  ? ttwu_do_wakeup+0x19/0x140
>  schedule+0x28/0x70
>  schedule_preempt_disabled+0xa/0x10
>  __mutex_lock.isra.8+0x2d0/0x4b0
>  cifs_uncached_writev_complete+0xcd/0x570 [cifs]
>  ? __switch_to_asm+0x40/0x70
>  ? __switch_to_asm+0x40/0x70
>  ? __switch_to_asm+0x34/0x70
>  ? __switch_to_asm+0x40/0x70
>  process_one_work+0x1a1/0x3a0
>  worker_thread+0x30/0x380
>  ? mod_delayed_work_on+0x90/0x90
>  kthread+0x112/0x130
>  ? __kthread_parkme+0x70/0x70
>  ret_from_fork+0x35/0x40
> INFO: task kworker/1:3:807 blocked for more than 120 seconds.
>       Not tainted 5.0.0-bisect-7091bcaba9f3+ #15
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> kworker/1:3     D    0   807      2 0x80000000
> Workqueue: cifsiod cifs_uncached_writev_complete [cifs]
> Call Trace:
>  ? __schedule+0x24e/0x860
>  schedule+0x28/0x70
>  schedule_preempt_disabled+0xa/0x10
>  __mutex_lock.isra.8+0x2d0/0x4b0
>  cifs_uncached_writev_complete+0xcd/0x570 [cifs]
>  ? __switch_to_asm+0x40/0x70
>  ? __switch_to_asm+0x40/0x70
>  ? __switch_to_asm+0x34/0x70
>  ? __switch_to_asm+0x40/0x70
>  process_one_work+0x1a1/0x3a0
>  worker_thread+0x30/0x380
>  ? mod_delayed_work_on+0x90/0x90
>  kthread+0x112/0x130
>  ? __kthread_parkme+0x70/0x70
>  ret_from_fork+0x35/0x40
> INFO: task kworker/13:2:1077 blocked for more than 120 seconds.
>       Not tainted 5.0.0-bisect-7091bcaba9f3+ #15
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> kworker/13:2    D    0  1077      2 0x80000080
> Workqueue: cifsiod cifs_uncached_readv_complete [cifs]
> Call Trace:
>  ? __schedule+0x24e/0x860
>  schedule+0x28/0x70
>  schedule_preempt_disabled+0xa/0x10
>  __mutex_lock.isra.8+0x2d0/0x4b0
>  ? __switch_to_asm+0x40/0x70
>  cifs_uncached_readv_complete+0x78/0x4d0 [cifs]
>  ? __switch_to_asm+0x34/0x70
>  process_one_work+0x1a1/0x3a0
>  worker_thread+0x30/0x380
>  ? mod_delayed_work_on+0x90/0x90
>  kthread+0x112/0x130
>  ? __kthread_parkme+0x70/0x70
>  ret_from_fork+0x35/0x40
> INFO: task kworker/3:0:1910 blocked for more than 120 seconds.
>       Not tainted 5.0.0-bisect-7091bcaba9f3+ #15
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> kworker/3:0     D    0  1910      2 0x80000080
> Workqueue: cifsiod cifs_uncached_writev_complete [cifs]
> Call Trace:
>  ? __schedule+0x24e/0x860
>  schedule+0x28/0x70
>  schedule_preempt_disabled+0xa/0x10
>  __mutex_lock.isra.8+0x2d0/0x4b0
>  cifs_uncached_writev_complete+0xcd/0x570 [cifs]
>  ? __switch_to_asm+0x40/0x70
>  ? __switch_to_asm+0x40/0x70
>  ? __switch_to_asm+0x34/0x70
>  ? __switch_to_asm+0x40/0x70
>  process_one_work+0x1a1/0x3a0
>  worker_thread+0x30/0x380
>  ? mod_delayed_work_on+0x90/0x90
>  kthread+0x112/0x130
>  ? __kthread_parkme+0x70/0x70
>  ret_from_fork+0x35/0x40
> INFO: task kworker/5:5:3930 blocked for more than 120 seconds.
>       Not tainted 5.0.0-bisect-7091bcaba9f3+ #15
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> kworker/5:5     D    0  3930      2 0x80000080
> Workqueue: cifsiod cifs_uncached_writev_complete [cifs]
> Call Trace:
>  ? __schedule+0x24e/0x860
>  schedule+0x28/0x70
>  schedule_preempt_disabled+0xa/0x10
>  __mutex_lock.isra.8+0x2d0/0x4b0
>  cifs_uncached_writev_complete+0xcd/0x570 [cifs]
>  ? __switch_to_asm+0x40/0x70
>  ? __switch_to_asm+0x40/0x70
>  ? __switch_to_asm+0x34/0x70
>  ? __switch_to_asm+0x40/0x70
>  process_one_work+0x1a1/0x3a0
>  worker_thread+0x30/0x380
>  ? mod_delayed_work_on+0x90/0x90
>  kthread+0x112/0x130
>  ? __kthread_parkme+0x70/0x70
>  ret_from_fork+0x35/0x40
> INFO: task kworker/1:2:3932 blocked for more than 120 seconds.
>       Not tainted 5.0.0-bisect-7091bcaba9f3+ #15
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> kworker/1:2     D    0  3932      2 0x80000080
> Workqueue: cifsiod cifs_uncached_readv_complete [cifs]
> Call Trace:
>  ? __schedule+0x24e/0x860
>  schedule+0x28/0x70
>  schedule_preempt_disabled+0xa/0x10
>  __mutex_lock.isra.8+0x2d0/0x4b0
>  ? __switch_to_asm+0x40/0x70
>  cifs_uncached_readv_complete+0x78/0x4d0 [cifs]
>  ? __switch_to_asm+0x34/0x70
>  process_one_work+0x1a1/0x3a0
>  worker_thread+0x30/0x380
>  ? mod_delayed_work_on+0x90/0x90
>  kthread+0x112/0x130
>  ? __kthread_parkme+0x70/0x70
>  ret_from_fork+0x35/0x40
> INFO: task kworker/1:5:3934 blocked for more than 120 seconds.
>       Not tainted 5.0.0-bisect-7091bcaba9f3+ #15
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> kworker/1:5     D    0  3934      2 0x80000080
> Workqueue: cifsiod cifs_uncached_readv_complete [cifs]
> Call Trace:
>  ? __schedule+0x24e/0x860
>  schedule+0x28/0x70
>  schedule_preempt_disabled+0xa/0x10
>  __mutex_lock.isra.8+0x2d0/0x4b0
>  ? __switch_to_asm+0x40/0x70
>  cifs_uncached_readv_complete+0x78/0x4d0 [cifs]
>  ? __switch_to_asm+0x34/0x70
>  process_one_work+0x1a1/0x3a0
>  worker_thread+0x30/0x380
>  ? mod_delayed_work_on+0x90/0x90
>  kthread+0x112/0x130
>  ? __kthread_parkme+0x70/0x70
>  ret_from_fork+0x35/0x40

^ permalink raw reply	[flat|nested] 4+ messages in thread

* Re: [5.0+ CIFS regression] fsstress hang on CIFS
  2019-03-14 16:12 ` ronnie sahlberg
@ 2019-03-14 18:40   ` Pavel Shilovsky
  0 siblings, 0 replies; 4+ messages in thread
From: Pavel Shilovsky @ 2019-03-14 18:40 UTC (permalink / raw)
  To: Murphy Zhou, ronnie sahlberg
  Cc: linux-cifs, Steve French, Pavel Shilovsky, Long Li

чт, 14 мар. 2019 г. в 09:14, ronnie sahlberg <ronniesahlberg@gmail.com>:
>
> On Fri, Mar 15, 2019 at 12:25 AM Murphy Zhou <jencce.kernel@gmail.com> wrote:
> >
> > Hi,
> >
> > xfstests generic/013 on CIFS hangs on Linus tree now.
> >
> > Bisect points to
> >
> > commit 7091bcaba9f34c83e1e6f418b6de5c6d987571da (HEAD, refs/bisect/bad)
> > Author: Pavel Shilovsky <pshilov@microsoft.com>
> > Date:   Wed Jan 30 16:58:09 2019 -0800
> >
> >     CIFS: Try to acquire credits at once for compound requests
> >
> > as the first bad commit.
> >
> > It should be easy to reproduce.
>
> I built a kernel at 7091bcaba9f34c83e1e6
> and it passes generic/013 against a windows2016 server for me.
>
> It could be a configuration difference.  What are the mount options
> you use and what server do you use?
>
> The code in the commit you find has been majorly re-worked in the
> for-next branch: https://github.com/smfrench/smb3-kernel
> Can you try cherry-picking these patches and see if the problem remains ?
>
> https://github.com/smfrench/smb3-kernel/commit/4b62ba8c7e9380f7274e3b4c90d41ab5e329ba08
> https://github.com/smfrench/smb3-kernel/commit/e2d79dccc7929257f7a2c824b397092de596b5c1
> https://github.com/smfrench/smb3-kernel/commit/15736c7f36cd55ef8c4e5df65c1a97ecd4b6e44f
> https://github.com/smfrench/smb3-kernel/commit/1bb731eaf331cec630a0371db2d0b79d5344d1e3
> https://github.com/smfrench/smb3-kernel/commit/a32fd3e57c3b15b456bbf39235d6555a88e20600
> https://github.com/smfrench/smb3-kernel/commit/9ed2d4dce312973e2f998d520f8c976c899e0dd9
>
>
>
> regards
> ronnie sahlberg
>
>
>
> >
> > Thanks,
> > M
> >
> > dmesg:
> > run fstests generic/013 at 2019-03-14 09:51:56
> > INFO: task kworker/3:1:104 blocked for more than 120 seconds.
> >       Not tainted 5.0.0-bisect-7091bcaba9f3+ #15
> > "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> > kworker/3:1     D    0   104      2 0x80000000
> > Workqueue: cifsiod cifs_uncached_writev_complete [cifs]
> > Call Trace:
> >  ? __schedule+0x24e/0x860
> >  schedule+0x28/0x70
> >  schedule_preempt_disabled+0xa/0x10
> >  __mutex_lock.isra.8+0x2d0/0x4b0
> >  cifs_uncached_writev_complete+0xcd/0x570 [cifs]
> >  ? __switch_to_asm+0x40/0x70
> >  ? __switch_to_asm+0x40/0x70
> >  ? __switch_to_asm+0x34/0x70
> >  ? __switch_to_asm+0x40/0x70
> >  process_one_work+0x1a1/0x3a0
> >  worker_thread+0x30/0x380
> >  ? mod_delayed_work_on+0x90/0x90
> >  kthread+0x112/0x130
> >  ? __kthread_parkme+0x70/0x70
> >  ret_from_fork+0x35/0x40
> > INFO: task kworker/5:1:106 blocked for more than 120 seconds.
> >       Not tainted 5.0.0-bisect-7091bcaba9f3+ #15
> > "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> > kworker/5:1     D    0   106      2 0x80000000
> > Workqueue: cifsiod cifs_uncached_writev_complete [cifs]
> > Call Trace:
> >  ? __schedule+0x24e/0x860
> >  ? ttwu_do_wakeup+0x19/0x140
> >  schedule+0x28/0x70
> >  schedule_preempt_disabled+0xa/0x10
> >  __mutex_lock.isra.8+0x2d0/0x4b0
> >  cifs_uncached_writev_complete+0xcd/0x570 [cifs]
> >  ? __switch_to_asm+0x40/0x70
> >  ? __switch_to_asm+0x34/0x70
> >  ? __switch_to_asm+0x40/0x70
> >  process_one_work+0x1a1/0x3a0
> >  worker_thread+0x30/0x380
> >  ? mod_delayed_work_on+0x90/0x90
> >  kthread+0x112/0x130
> >  ? __kthread_parkme+0x70/0x70
> >  ret_from_fork+0x35/0x40
> > INFO: task kworker/7:1:108 blocked for more than 120 seconds.
> >       Not tainted 5.0.0-bisect-7091bcaba9f3+ #15
> > "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> > kworker/7:1     D    0   108      2 0x80000000
> > Workqueue: cifsiod cifs_uncached_writev_complete [cifs]
> > Call Trace:
> >  ? __schedule+0x24e/0x860
> >  ? ttwu_do_wakeup+0x19/0x140
> >  schedule+0x28/0x70
> >  schedule_preempt_disabled+0xa/0x10
> >  __mutex_lock.isra.8+0x2d0/0x4b0
> >  cifs_uncached_writev_complete+0xcd/0x570 [cifs]
> >  ? __switch_to_asm+0x40/0x70
> >  ? __switch_to_asm+0x40/0x70
> >  ? __switch_to_asm+0x34/0x70
> >  ? __switch_to_asm+0x40/0x70
> >  process_one_work+0x1a1/0x3a0
> >  worker_thread+0x30/0x380
> >  ? mod_delayed_work_on+0x90/0x90
> >  kthread+0x112/0x130
> >  ? __kthread_parkme+0x70/0x70
> >  ret_from_fork+0x35/0x40
> > INFO: task kworker/7:3:391 blocked for more than 120 seconds.
> >       Not tainted 5.0.0-bisect-7091bcaba9f3+ #15
> > "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> > kworker/7:3     D    0   391      2 0x80000000
> > Workqueue: cifsiod cifs_uncached_writev_complete [cifs]
> > Call Trace:
> >  ? __schedule+0x24e/0x860
> >  ? ttwu_do_wakeup+0x19/0x140
> >  schedule+0x28/0x70
> >  schedule_preempt_disabled+0xa/0x10
> >  __mutex_lock.isra.8+0x2d0/0x4b0
> >  cifs_uncached_writev_complete+0xcd/0x570 [cifs]
> >  ? __switch_to_asm+0x40/0x70
> >  ? __switch_to_asm+0x40/0x70
> >  ? __switch_to_asm+0x34/0x70
> >  ? __switch_to_asm+0x40/0x70
> >  process_one_work+0x1a1/0x3a0
> >  worker_thread+0x30/0x380
> >  ? mod_delayed_work_on+0x90/0x90
> >  kthread+0x112/0x130
> >  ? __kthread_parkme+0x70/0x70
> >  ret_from_fork+0x35/0x40
> > INFO: task kworker/1:3:807 blocked for more than 120 seconds.
> >       Not tainted 5.0.0-bisect-7091bcaba9f3+ #15
> > "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> > kworker/1:3     D    0   807      2 0x80000000
> > Workqueue: cifsiod cifs_uncached_writev_complete [cifs]
> > Call Trace:
> >  ? __schedule+0x24e/0x860
> >  schedule+0x28/0x70
> >  schedule_preempt_disabled+0xa/0x10
> >  __mutex_lock.isra.8+0x2d0/0x4b0
> >  cifs_uncached_writev_complete+0xcd/0x570 [cifs]
> >  ? __switch_to_asm+0x40/0x70
> >  ? __switch_to_asm+0x40/0x70
> >  ? __switch_to_asm+0x34/0x70
> >  ? __switch_to_asm+0x40/0x70
> >  process_one_work+0x1a1/0x3a0
> >  worker_thread+0x30/0x380
> >  ? mod_delayed_work_on+0x90/0x90
> >  kthread+0x112/0x130
> >  ? __kthread_parkme+0x70/0x70
> >  ret_from_fork+0x35/0x40
> > INFO: task kworker/13:2:1077 blocked for more than 120 seconds.
> >       Not tainted 5.0.0-bisect-7091bcaba9f3+ #15
> > "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> > kworker/13:2    D    0  1077      2 0x80000080
> > Workqueue: cifsiod cifs_uncached_readv_complete [cifs]
> > Call Trace:
> >  ? __schedule+0x24e/0x860
> >  schedule+0x28/0x70
> >  schedule_preempt_disabled+0xa/0x10
> >  __mutex_lock.isra.8+0x2d0/0x4b0
> >  ? __switch_to_asm+0x40/0x70
> >  cifs_uncached_readv_complete+0x78/0x4d0 [cifs]
> >  ? __switch_to_asm+0x34/0x70
> >  process_one_work+0x1a1/0x3a0
> >  worker_thread+0x30/0x380
> >  ? mod_delayed_work_on+0x90/0x90
> >  kthread+0x112/0x130
> >  ? __kthread_parkme+0x70/0x70
> >  ret_from_fork+0x35/0x40
> > INFO: task kworker/3:0:1910 blocked for more than 120 seconds.
> >       Not tainted 5.0.0-bisect-7091bcaba9f3+ #15
> > "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> > kworker/3:0     D    0  1910      2 0x80000080
> > Workqueue: cifsiod cifs_uncached_writev_complete [cifs]
> > Call Trace:
> >  ? __schedule+0x24e/0x860
> >  schedule+0x28/0x70
> >  schedule_preempt_disabled+0xa/0x10
> >  __mutex_lock.isra.8+0x2d0/0x4b0
> >  cifs_uncached_writev_complete+0xcd/0x570 [cifs]
> >  ? __switch_to_asm+0x40/0x70
> >  ? __switch_to_asm+0x40/0x70
> >  ? __switch_to_asm+0x34/0x70
> >  ? __switch_to_asm+0x40/0x70
> >  process_one_work+0x1a1/0x3a0
> >  worker_thread+0x30/0x380
> >  ? mod_delayed_work_on+0x90/0x90
> >  kthread+0x112/0x130
> >  ? __kthread_parkme+0x70/0x70
> >  ret_from_fork+0x35/0x40
> > INFO: task kworker/5:5:3930 blocked for more than 120 seconds.
> >       Not tainted 5.0.0-bisect-7091bcaba9f3+ #15
> > "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> > kworker/5:5     D    0  3930      2 0x80000080
> > Workqueue: cifsiod cifs_uncached_writev_complete [cifs]
> > Call Trace:
> >  ? __schedule+0x24e/0x860
> >  schedule+0x28/0x70
> >  schedule_preempt_disabled+0xa/0x10
> >  __mutex_lock.isra.8+0x2d0/0x4b0
> >  cifs_uncached_writev_complete+0xcd/0x570 [cifs]
> >  ? __switch_to_asm+0x40/0x70
> >  ? __switch_to_asm+0x40/0x70
> >  ? __switch_to_asm+0x34/0x70
> >  ? __switch_to_asm+0x40/0x70
> >  process_one_work+0x1a1/0x3a0
> >  worker_thread+0x30/0x380
> >  ? mod_delayed_work_on+0x90/0x90
> >  kthread+0x112/0x130
> >  ? __kthread_parkme+0x70/0x70
> >  ret_from_fork+0x35/0x40
> > INFO: task kworker/1:2:3932 blocked for more than 120 seconds.
> >       Not tainted 5.0.0-bisect-7091bcaba9f3+ #15
> > "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> > kworker/1:2     D    0  3932      2 0x80000080
> > Workqueue: cifsiod cifs_uncached_readv_complete [cifs]
> > Call Trace:
> >  ? __schedule+0x24e/0x860
> >  schedule+0x28/0x70
> >  schedule_preempt_disabled+0xa/0x10
> >  __mutex_lock.isra.8+0x2d0/0x4b0
> >  ? __switch_to_asm+0x40/0x70
> >  cifs_uncached_readv_complete+0x78/0x4d0 [cifs]
> >  ? __switch_to_asm+0x34/0x70
> >  process_one_work+0x1a1/0x3a0
> >  worker_thread+0x30/0x380
> >  ? mod_delayed_work_on+0x90/0x90
> >  kthread+0x112/0x130
> >  ? __kthread_parkme+0x70/0x70
> >  ret_from_fork+0x35/0x40
> > INFO: task kworker/1:5:3934 blocked for more than 120 seconds.
> >       Not tainted 5.0.0-bisect-7091bcaba9f3+ #15
> > "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> > kworker/1:5     D    0  3934      2 0x80000080
> > Workqueue: cifsiod cifs_uncached_readv_complete [cifs]
> > Call Trace:
> >  ? __schedule+0x24e/0x860
> >  schedule+0x28/0x70
> >  schedule_preempt_disabled+0xa/0x10
> >  __mutex_lock.isra.8+0x2d0/0x4b0
> >  ? __switch_to_asm+0x40/0x70
> >  cifs_uncached_readv_complete+0x78/0x4d0 [cifs]
> >  ? __switch_to_asm+0x34/0x70
> >  process_one_work+0x1a1/0x3a0
> >  worker_thread+0x30/0x380
> >  ? mod_delayed_work_on+0x90/0x90
> >  kthread+0x112/0x130
> >  ? __kthread_parkme+0x70/0x70
> >  ret_from_fork+0x35/0x40

(cc'ing Long)

I think this is one more occurrence of the known bug in the direct IO
resend code path: the process is most likely stuck in
cifs_resend_wdata thus not allowing other process to acquire the
mutex. We had two patches fixing it that is currently being re-worked:

https://patchwork.kernel.org/patch/10836349/
https://patchwork.kernel.org/patch/10836355/

But you can try them out to see if they fix your issue.

--
Best regards,
Pavel Shilovsky

^ permalink raw reply	[flat|nested] 4+ messages in thread

end of thread, other threads:[~2019-03-14 18:40 UTC | newest]

Thread overview: 4+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2019-03-14 14:25 [5.0+ CIFS regression] fsstress hang on CIFS Murphy Zhou
2019-03-14 15:29 ` ronnie sahlberg
2019-03-14 16:12 ` ronnie sahlberg
2019-03-14 18:40   ` Pavel Shilovsky

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).