Re: [PATCH] kernel/{lockdep,hung_task}: Show locks and backtrace of running tasks.

[Tetsuo Handa]

On 2018/09/03 20:44, Tetsuo Handa wrote:
> We are getting reports from syzbot where running task seems to be
> relevant to a hung task problem but NMI backtrace does not print useful
> information [1].

According to my local cache, 69% of hung task reports from syzbot say that
one CPU was running check_hung_uninterruptible_tasks() and the other CPU
was idle. I think that this patch would in many cases give more useful
information than trigger_all_cpu_backtrace() reports. Can we try this patch?

$ ls -l */CrashLog.*[0-9a-f] | wc -l
1666
$ for i in */CrashLog.*; do awk ' BEGIN { flag = 0; } { if (index($0, "NMI backtrace") > 0) { flag = 1; } else if (index($0, "panic") > 0) { exit; } if (flag == 1) { print $0; } }' $i > $i.tmp; done
$ ls -l */*.tmp | wc -l
1666
$ grep -i watchdog+ */*.tmp | wc -l
1662
$ grep -i "idling at" */*.tmp | wc -l
1151
$ grep -F '<IRQ>' */*.tmp | wc -l
220

> 
> Although commit 8cc05c71ba5f7936 ("locking/lockdep: Move sanity check to
> inside lockdep_print_held_locks()") says that calling
> lockdep_print_held_locks() on a running thread is considered unsafe,
> it is useful for syzbot to show locks and backtrace of running tasks.
> Thus, let's allow it if CONFIG_DEBUG_AID_FOR_SYZBOT is defined.
> 
> [1] https://syzkaller.appspot.com/bug?id=8bab7a6a5597bb10f90e8227a7d8a483748d93be
> 
> Signed-off-by: Tetsuo Handa <penguin-kernel@xxxxxxxxxxxxxxxxxxx>
> Cc: Dmitry Vyukov <dvyukov@xxxxxxxxxx>
> ---
>  kernel/hung_task.c       | 20 ++++++++++++++++++++
>  kernel/locking/lockdep.c |  9 +++++++++
>  2 files changed, 29 insertions(+)
> 
> diff --git a/kernel/hung_task.c b/kernel/hung_task.c
> index b9132d1..1ac49a5 100644
> --- a/kernel/hung_task.c
> +++ b/kernel/hung_task.c
> @@ -201,6 +201,26 @@ static void check_hung_uninterruptible_tasks(unsigned long timeout)
>  	if (hung_task_show_lock)
>  		debug_show_all_locks();
>  	if (hung_task_call_panic) {
> +#ifdef CONFIG_DEBUG_AID_FOR_SYZBOT
> +		/*
> +		 * debug_show_all_locks() above forcibly dumped locks held by
> +		 * running tasks with locks held. Now, let's dump backtrace of
> +		 * running tasks as well, for NMI backtrace below tends to show
> +		 * current thread (i.e. khungtaskd thread itself) and idle CPU
> +		 * which are useless for debugging hung task problems.
> +		 */
> +		rcu_read_lock();
> +		for_each_process_thread(g, t) {
> +			if (t->state != TASK_RUNNING || t == current)
> +				continue;
> +			pr_err("INFO: task %s:%d was running.\n", t->comm,
> +			       t->pid);
> +			sched_show_task(t);
> +			touch_nmi_watchdog();
> +			touch_all_softlockup_watchdogs();
> +		}
> +		rcu_read_unlock();
> +#endif
>  		trigger_all_cpu_backtrace();
>  		panic("hung_task: blocked tasks");
>  	}
> diff --git a/kernel/locking/lockdep.c b/kernel/locking/lockdep.c
> index e406c5f..efeebf6 100644
> --- a/kernel/locking/lockdep.c
> +++ b/kernel/locking/lockdep.c
> @@ -565,12 +565,21 @@ static void lockdep_print_held_locks(struct task_struct *p)
>  	else
>  		printk("%d lock%s held by %s/%d:\n", depth,
>  		       depth > 1 ? "s" : "", p->comm, task_pid_nr(p));
> +#ifndef CONFIG_DEBUG_AID_FOR_SYZBOT
>  	/*
>  	 * It's not reliable to print a task's held locks if it's not sleeping
>  	 * and it's not the current task.
>  	 */
>  	if (p->state == TASK_RUNNING && p != current)
>  		return;
> +#else
> +	/*
> +	 * But showing locks and backtrace of running tasks seems to be helpful
> +	 * for debugging hung task problems. Since syzbot will call panic()
> +	 * shortly, risking problems caused by accessing stale information is
> +	 * acceptable here.
> +	 */
> +#endif
>  	for (i = 0; i < depth; i++) {
>  		printk(" #%d: ", i);
>  		print_lock(p->held_locks + i);
>