Message-ID: <0d7aa66d-d2b9-775c-56b3-543d132fdb84@huawei.com>
Date:   Mon, 14 Oct 2019 15:03:02 +0800
From:   Zhihao Cheng <chengzhihao1@...wei.com>
To:     LKML <linux-kernel@...r.kernel.org>, <peterz@...radead.org>,
        Ingo Molnar <mingo@...hat.com>,
        Andrew Morton <akpm@...ux-foundation.org>,
        <patrick.bellasi@....com>, <valentin.schneider@....com>,
        <tglx@...utronix.de>
CC:     Kefeng Wang <wangkefeng.wang@...wei.com>,
        "zhangyi (F)" <yi.zhang@...wei.com>
Subject: [QUESTION] Hung task warning while running syzkaller test

Hi, everyone. We met a hung task problem while running syzkaller test. The stacks of hung tasks vary in net/fs/sched, and we provide a stable reproduce test case in fs. The higher the kernel version, the lower the probability of reproduce. Maybe the mainline has gradually optimized the scheduling and mutex.

Environment:
	A. qemu(x86_64 8-core 16GB-RAM)
	B. physical machine (x86_64 8-core 314GB-RAM)

	./syz-execprog -executor=/home/abc/syz-executor -repeat=0 -procs=16 -cover=0 repro
repro is a configuration file containing syzkaller execution instructions, which shown as follows:
	syz_execute_func(&(0x7f0000000140)="f2aa984413e80f059532058300000071f32ef30f1b6f002e676666440f381d953b0000009fcc77a7141e8f6978e394db96000000928640c4e2b140da6c4f086447deecf2460fd6c40f49100045660fc462c0f726448047000040df6e32b8417e10bd61796e91565646bc16442ecbb1a978c33537771656c441add398b50000000feb76f7f7210173dddfc421785a6600a32c9f5d04ecc7c764660f600500040000c4035922770063c4217be62e450f8a0163000021f0c4e25dbe044c31e053b3eb53b3eb890f32d393400f383ca8faffec1f8dbf4feeee1e480404fb2e400f1ad30fae746d00ab07c4a2d538cb0ff803461439f5e3480f5140a3c4c4021bf7e8561eeaea0f6c3dce67460ffd1a000fb2430f12f5c423557904e774")
	socket(0x1, 0x80000, 0x4)

Hung task in kernel-4.4(See full message in hung_task_verbose.log):
	[  420.762345] INFO: task syz-executor.1:8244 blocked for more than 140 seconds.
	[  420.763691]       Not tainted 4.4.186-514.55.6.9.x86_64 #1
	[  420.764645] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
	[  420.765931] syz-executor.1  D ffff88040e6efc80 13728  8244   8242 0x00000000
	[  420.767189]  ffff88040e6efc80 ffff88040e71c990 ffff880400000000 ffff880077df3d80
	[  420.768497]  ffff88040e71bd80 ffff88040e6f0000 0000000000000246 ffff88041f5007c0
	[  420.769800]  ffff88040e71bd80 00000000ffffffff ffff88040e6efc98 ffffffff818c6ebc
	[  420.771109] Call Trace:
	[  420.771540]  [<ffffffff818c6ebc>] schedule+0x3c/0x90
	[  420.772369]  [<ffffffff818c72a5>] schedule_preempt_disabled+0x15/0x20
	[  420.773437]  [<ffffffff818c9692>] mutex_lock_nested+0x182/0x500
	[  420.774421]  [<ffffffff81252fdf>] ? walk_component+0x21f/0x310
	[  420.775396]  [<ffffffff8124fb4a>] ? __inode_permission+0x3a/0x80
	[  420.776391]  [<ffffffff81252fdf>] walk_component+0x21f/0x310
	[  420.777333]  [<ffffffff81253f3b>] ? path_lookupat+0x1b/0x110
	[  420.778273]  [<ffffffff81253f7d>] path_lookupat+0x5d/0x110
	[  420.779197]  [<ffffffff81255bc1>] filename_lookup+0xb1/0x180
	[  420.780130]  [<ffffffff811133dd>] ? rcu_read_lock_sched_held+0x6d/0x80
	[  420.781211]  [<ffffffff81228db0>] ? kmem_cache_alloc+0x240/0x2b0
	[  420.782212]  [<ffffffff811132ed>] ? debug_lockdep_rcu_enabled+0x1d/0x20
	[  420.783312]  [<ffffffff81255d66>] user_path_at_empty+0x36/0x40
	[  420.784284]  [<ffffffff8126fcd3>] path_removexattr+0x43/0xb0
	[  420.785229]  [<ffffffff81003044>] ? lockdep_sys_exit_thunk+0x12/0x14
	[  420.786283]  [<ffffffff81270c50>] SyS_lremovexattr+0x10/0x20
	[  420.787232]  [<ffffffff818cdda1>] entry_SYSCALL_64_fastpath+0x1e/0x9a
	[  420.788302] 1 lock held by syz-executor.1/8244:
	[  420.789051]  #0:  (&sb->s_type->i_mutex_key#2){+.+.+.}, at: [<ffffffff81252fdf>] walk_component+0x21f/0x310

Hung task in kernel-5.3-rc6:
	[30391.827102] INFO: task syz-executor.6:12211 blocked for more than 143 seconds.
	[30391.827194]       Not tainted 5.3.0-rc6-514.55.6.9.x86_64 #41
	[30391.827214] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
	[30391.827239] syz-executor.6  D13904 12211  12143 0x00000000
	[30391.827319] Call Trace:
	[30391.828583]  ? __schedule+0x3cc/0x8b0
	[30391.828669]  schedule+0x30/0xb0
	[30391.828785]  rwsem_down_write_slowpath+0x2d2/0x730
	[30391.829039]  ? filename_create+0x9d/0x1d0
	[30391.829110]  ? filename_create+0x9d/0x1d0
	[30391.829136]  ? rwsem_down_write_slowpath+0x5/0x730
	[30391.829163]  filename_create+0x9d/0x1d0
	[30391.829247]  do_mkdirat+0x54/0x120
	[30391.829361]  do_syscall_64+0x85/0x380
	[30391.829445]  entry_SYSCALL_64_after_hwframe+0x49/0xbe
	[30391.829509] RIP: 0033:0x20000148
	[30391.829562] Code: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 f2 aa 98 44 13 e8 0f 05 <95> 32 05 83 00 00 00 71 f3 2e f3 0f 1b 6f 00 2e 67 66 66 44 0f 38
	[30391.829604] RSP: 002b:00007fd154213bd8 EFLAGS: 00000203 ORIG_RAX: 0000000000000053
	[30391.829638] RAX: ffffffffffffffda RBX: 0000000000000009 RCX: 0000000020000148
	[30391.829659] RDX: da194cf4f57fa1d4 RSI: 0000000000000000 RDI: 00007fd15421460a
	[30391.829680] RBP: 0000000000000045 R08: 0000000000000005 R09: 0000000000000006
	[30391.829703] R10: 0000000000000007 R11: 0000000000000203 R12: 000000000000000b
	[30391.829724] R13: 000000000000014c R14: 000000000000000d R15: 00000000ffffffff


Intro of attachments:
	hung_task_verbose.log: verbose of hung task(with lockdep)
	repro: reproduction file which contains syzkaller execution instructions

Any ideas or suggestions? Thanks a lot.

View attachment "hung_task_verbose.log" of type "text/plain" (18069 bytes)

View attachment "repro" of type "text/plain" (632 bytes)

Powered by blists - more mailing lists