Re: [LKP] [tty] 0b4f83d510: INFO:task_blocked_for_more_than#seconds

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 



On 09/07/2018, 06:50 AM, kernel test robot wrote:
> FYI, we noticed the following commit (built with gcc-7):
> 
> commit: 0b4f83d510f6fef6bb9da25f122c8d733d50516f ("[PATCH 2/4] tty: Hold tty_ldisc_lock() during tty_reopen()")
> url: https://github.com/0day-ci/linux/commits/Dmitry-Safonov/tty-Hold-write-ldisc-sem-in-tty_reopen/20180829-165618
> base: https://git.kernel.org/cgit/linux/kernel/git/gregkh/tty.git tty-testing
> 
> in testcase: trinity
> with following parameters:
> 
> 	runtime: 300s
> 
> test-description: Trinity is a linux system call fuzz tester.
> test-url: http://codemonkey.org.uk/projects/trinity/
> 
> 
> on test machine: qemu-system-x86_64 -enable-kvm -m 256M
> 
> caused below changes (please refer to attached dmesg/kmsg for entire log/backtrace):
> 
> 
> +--------------------------------------------------+------------+------------+
> |                                                  | 58dd163974 | 0b4f83d510 |
> +--------------------------------------------------+------------+------------+
> | boot_successes                                   | 14         | 4          |
> | boot_failures                                    | 0          | 6          |
> | INFO:task_blocked_for_more_than#seconds          | 0          | 6          |
> | Kernel_panic-not_syncing:hung_task:blocked_tasks | 0          | 6          |
> +--------------------------------------------------+------------+------------+
> 
> 
> 
> [  244.816801] INFO: task validate_data:655 blocked for more than 120 seconds.
> [  244.818833]       Not tainted 4.18.0-11684-g0b4f83d #1
> [  244.820028] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [  244.826965] validate_data   D    0   655    623 0x20020000
> [  244.828279] Call Trace:
> [  244.828958]  ? __schedule+0x843/0x950
> [  244.830173]  ? __ldsem_down_read_nested+0x1c4/0x3b0
> [  244.834903]  schedule+0x31/0x70
> [  244.835665]  schedule_timeout+0x34/0x760
> [  244.836613]  ? ftrace_likely_update+0x35/0x60
> [  244.837683]  ? __ldsem_down_read_nested+0x1c4/0x3b0
> [  244.838818]  ? ftrace_likely_update+0x35/0x60
> [  244.840127]  ? ftrace_likely_update+0x35/0x60
> [  244.845947]  ? __ldsem_down_read_nested+0x1c4/0x3b0
> [  244.847882]  __ldsem_down_read_nested+0x23a/0x3b0
> [  244.849886]  ? tty_ldisc_ref_wait+0x25/0x50
> [  244.853807]  tty_ldisc_ref_wait+0x25/0x50
> [  244.854946]  tty_compat_ioctl+0x8a/0x120
> [  244.855928]  ? this_tty+0x80/0x80
> [  244.856742]  __ia32_compat_sys_ioctl+0xc28/0x1ce0
> [  244.857981]  do_int80_syscall_32+0x1d2/0x5f0
> [  244.859003]  entry_INT80_compat+0x88/0xa0
> [  244.859972] INFO: task dnsmasq:668 blocked for more than 120 seconds.
> [  244.868315]       Not tainted 4.18.0-11684-g0b4f83d #1
> [  244.869583] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [  244.871744] dnsmasq         D    0   668      1 0x20020000
> [  244.873063] Call Trace:
> [  244.873697]  ? __schedule+0x843/0x950
> [  244.874572]  ? __ldsem_down_read_nested+0x1c4/0x3b0
> [  244.875725]  schedule+0x31/0x70
> [  244.876576]  schedule_timeout+0x34/0x760
> [  244.877573]  ? ftrace_likely_update+0x35/0x60
> [  244.878660]  ? __ldsem_down_read_nested+0x1c4/0x3b0
> [  244.879872]  ? ftrace_likely_update+0x35/0x60
> [  244.890522]  ? ftrace_likely_update+0x35/0x60
> [  244.891572]  ? __ldsem_down_read_nested+0x1c4/0x3b0
> [  244.892746]  __ldsem_down_read_nested+0x23a/0x3b0
> [  244.893861]  ? tty_ldisc_ref_wait+0x25/0x50
> [  244.894841]  tty_ldisc_ref_wait+0x25/0x50
> [  244.895911]  tty_compat_ioctl+0x8a/0x120
> [  244.896916]  ? this_tty+0x80/0x80
> [  244.897717]  __ia32_compat_sys_ioctl+0xc28/0x1ce0
> [  244.898821]  do_int80_syscall_32+0x1d2/0x5f0
> [  244.899830]  entry_INT80_compat+0x88/0xa0
> [  244.909466] INFO: task dropbear:734 blocked for more than 120 seconds.
> [  244.911173]       Not tainted 4.18.0-11684-g0b4f83d #1
> [  244.912394] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [  244.914176] dropbear        D    0   734      1 0x20020000
> [  244.915446] Call Trace:
> [  244.916068]  ? __schedule+0x843/0x950
> [  244.916945]  ? __ldsem_down_read_nested+0x1c4/0x3b0
> [  244.918076]  schedule+0x31/0x70
> [  244.918832]  schedule_timeout+0x34/0x760
> [  244.919781]  ? ftrace_likely_update+0x35/0x60
> [  244.921104]  ? __ldsem_down_read_nested+0x1c4/0x3b0
> [  244.922304]  ? ftrace_likely_update+0x35/0x60
> [  244.923347]  ? ftrace_likely_update+0x35/0x60
> [  244.924369]  ? __ldsem_down_read_nested+0x1c4/0x3b0
> [  244.925496]  __ldsem_down_read_nested+0x23a/0x3b0
> [  244.926598]  ? tty_ldisc_ref_wait+0x25/0x50
> [  244.927578]  tty_ldisc_ref_wait+0x25/0x50
> [  244.928526]  tty_compat_ioctl+0x8a/0x120
> [  244.929449]  ? this_tty+0x80/0x80
> [  244.930240]  __ia32_compat_sys_ioctl+0xc28/0x1ce0
> [  244.940083]  do_int80_syscall_32+0x1d2/0x5f0
> [  244.941310]  entry_INT80_compat+0x88/0xa0
> [  244.944070] 
> [  244.944070] Showing all locks held in the system:
> [  244.945558] 1 lock held by khungtaskd/18:
> [  244.946495]  #0: (____ptrval____) (rcu_read_lock){....}, at: debug_show_all_locks+0x16/0x190
> [  244.948503] 2 locks held by askfirst/235:
> [  244.949439]  #0: (____ptrval____) (&tty->ldisc_sem){++++}, at: tty_ldisc_ref_wait+0x25/0x50
> [  244.951762]  #1: (____ptrval____) (&ldata->atomic_read_lock){+.+.}, at: n_tty_read+0x13d/0xa00

Here, it just seems to wait for input from the user.

> [  244.953799] 1 lock held by validate_data/655:
> [  244.954814]  #0: (____ptrval____) (&tty->ldisc_sem){++++}, at: tty_ldisc_ref_wait+0x25/0x50
> [  244.956764] 1 lock held by dnsmasq/668:
> [  244.957649]  #0: (____ptrval____) (&tty->ldisc_sem){++++}, at: tty_ldisc_ref_wait+0x25/0x50
> [  244.959598] 1 lock held by dropbear/734:
> [  244.967564]  #0: (____ptrval____) (&tty->ldisc_sem){++++}, at: tty_ldisc_ref_wait+0x25/0x50

Hmm, I assume there is another task waiting for write_ldsem and that one
prevents these readers to proceed. Unfortunately, due to the defunct
__ptrval__ pointer hashing crap, we do not see who is waiting for what.
But I am guessing all are the same locks.

So I think, we are forced to limit the waiting to 5 seconds in reopen in
the end too (the same as we do for new open in tty_init_dev).

Dmitry, could you add the limit and handle the return value of
tty_ldisc_lock now?

thanks,
-- 
js
suse labs



[Index of Archives]     [Linux Kernel]     [Kernel Development Newbies]     [Linux USB Devel]     [Video for Linux]     [Linux Audio Users]     [Yosemite Hiking]     [Linux Kernel]     [Linux SCSI]

  Powered by Linux