[PATCH v2 liburing] test: Add kworker-hang test

[Ammar Faizi <ammar.faizi@students.amikom.ac.id>]

Add kworker-hang test to reproduce this:

  [28335.037622] INFO: task kworker/u8:3:77596 blocked for more than 10 seconds.
  [28335.037629]       Tainted: G        W  OE     5.15.0-rc4-for-5.16-io-uring-00060-g4922ab639eb6 #4
  [28335.037637] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
  [28335.037642] task:kworker/u8:3    state:D stack:    0 pid:77596 ppid:     2 flags:0x00004000
  [28335.037650] Workqueue: events_unbound io_ring_exit_work
  [28335.037658] Call Trace:
  [28335.037667]  __schedule+0x453/0x1850
  [28335.037681]  ? lock_acquire+0xc8/0x2d0
  [28335.037688]  ? io_ring_exit_work+0x98/0x44a
  [28335.037700]  ? usleep_range+0x90/0x90
  [28335.037707]  schedule+0x59/0xc0
  [28335.037715]  schedule_timeout+0x1aa/0x1f0
  [28335.037723]  ? mark_held_locks+0x49/0x70
  [28335.037733]  ? lockdep_hardirqs_on_prepare+0xff/0x180
  [28335.037740]  ? _raw_spin_unlock_irq+0x24/0x40
  [28335.037750]  __wait_for_common+0xc2/0x170
  [28335.037767]  io_ring_exit_work+0x42c/0x44a
  [28335.037776]  ? io_uring_del_tctx_node+0xad/0xad
  [28335.037790]  ? verify_cpu+0xf0/0x100
  [28335.037806]  process_one_work+0x23b/0x550
  [28335.037824]  worker_thread+0x55/0x3c0
  [28335.037830]  ? process_one_work+0x550/0x550
  [28335.037840]  kthread+0x140/0x160
  [28335.037846]  ? set_kthread_struct+0x40/0x40
  [28335.037856]  ret_from_fork+0x1f/0x30
  [28335.037887] INFO: task kworker/u8:4:78057 blocked for more than 10 seconds.
  [28335.037895]       Tainted: G        W  OE     5.15.0-rc4-for-5.16-io-uring-00060-g4922ab639eb6 #4
  [28335.037901] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
  [28335.037907] task:kworker/u8:4    state:D stack:    0 pid:78057 ppid:     2 flags:0x00004000
  [28335.037915] Workqueue: events_unbound io_ring_exit_work
  [28335.037922] Call Trace:
  [28335.037931]  __schedule+0x453/0x1850
  [28335.037946]  ? lock_acquire+0xc8/0x2d0
  [28335.037953]  ? io_ring_exit_work+0x98/0x44a
  [28335.037965]  ? usleep_range+0x90/0x90
  [28335.037973]  schedule+0x59/0xc0
  [28335.037980]  schedule_timeout+0x1aa/0x1f0
  [28335.037989]  ? mark_held_locks+0x49/0x70
  [28335.037999]  ? lockdep_hardirqs_on_prepare+0xff/0x180
  [28335.038005]  ? _raw_spin_unlock_irq+0x24/0x40
  [28335.038016]  __wait_for_common+0xc2/0x170
  [28335.038032]  io_ring_exit_work+0x42c/0x44a
  [28335.038041]  ? io_uring_del_tctx_node+0xad/0xad
  [28335.038055]  ? verify_cpu+0xf0/0x100
  [28335.038070]  process_one_work+0x23b/0x550
  [28335.038089]  worker_thread+0x55/0x3c0
  [28335.038095]  ? process_one_work+0x550/0x550
  [28335.038105]  kthread+0x140/0x160
  [28335.038111]  ? set_kthread_struct+0x40/0x40
  [28335.038120]  ret_from_fork+0x1f/0x30
  [28335.038148]
                 Showing all locks held in the system:
  [28335.038155] 1 lock held by khungtaskd/39:
  [28335.038159]  #0: ffffffff82977740 (rcu_read_lock){....}-{1:2}, at: debug_show_all_locks+0x15/0x174
  [28335.038189] 1 lock held by in:imklog/926:
  [28335.038193]  #0: ffff88813208c2f0 (&f->f_pos_lock){+.+.}-{3:3}, at: __fdget_pos+0x4a/0x60
  [28335.038253] 2 locks held by kworker/u8:1/68219:
  [28335.038257]  #0: ffff888100106938 ((wq_completion)events_unbound){+.+.}-{0:0}, at: process_one_work+0x1c1/0x550
  [28335.038274]  #1: ffffc90003f7fe70 ((work_completion)(&ctx->exit_work)){+.+.}-{0:0}, at: process_one_work+0x1c1/0x550
  [28335.038291] 2 locks held by kworker/u8:0/76320:
  [28335.038295]  #0: ffff888100106938 ((wq_completion)events_unbound){+.+.}-{0:0}, at: process_one_work+0x1c1/0x550
  [28335.038311]  #1: ffffc90003ca7e70 ((work_completion)(&ctx->exit_work)){+.+.}-{0:0}, at: process_one_work+0x1c1/0x550
  [28335.038328] 2 locks held by kworker/u8:2/76681:
  [28335.038331]  #0: ffff888100106938 ((wq_completion)events_unbound){+.+.}-{0:0}, at: process_one_work+0x1c1/0x550
  [28335.038347]  #1: ffffc9000837be70 ((work_completion)(&ctx->exit_work)){+.+.}-{0:0}, at: process_one_work+0x1c1/0x550
  [28335.038365] 2 locks held by kworker/u8:3/77596:
  [28335.038368]  #0: ffff888100106938 ((wq_completion)events_unbound){+.+.}-{0:0}, at: process_one_work+0x1c1/0x550
  [28335.038384]  #1: ffffc900083e3e70 ((work_completion)(&ctx->exit_work)){+.+.}-{0:0}, at: process_one_work+0x1c1/0x550
  [28335.038401] 1 lock held by dmesg/78014:
  [28335.038405]  #0: ffff888217c180d0 (&user->lock){+.+.}-{3:3}, at: devkmsg_read+0x4b/0x230
  [28335.038423] 2 locks held by kworker/u8:4/78057:
  [28335.038427]  #0: ffff888100106938 ((wq_completion)events_unbound){+.+.}-{0:0}, at: process_one_work+0x1c1/0x550
  [28335.038443]  #1: ffffc900088b7e70 ((work_completion)(&ctx->exit_work)){+.+.}-{0:0}, at: process_one_work+0x1c1/0x550

  [28335.038463] =============================================

  [28335.038468] NMI backtrace for cpu 2
  [28335.038471] CPU: 2 PID: 39 Comm: khungtaskd Tainted: G        W  OE     5.15.0-rc4-for-5.16-io-uring-00060-g4922ab639eb6 #4 8b24b2500a34cedea2e69c8d84eb4c855e713e61
  [28335.038478] Hardware name: Acer Aspire ES1-421/OLVIA_BE, BIOS V1.05 07/02/2015
  [28335.038481] Call Trace:
  [28335.038486]  dump_stack_lvl+0x57/0x72
  [28335.038495]  nmi_cpu_backtrace.cold+0x32/0x7f
  [28335.038500]  ? lapic_can_unplug_cpu+0x80/0x80
  [28335.038510]  nmi_trigger_cpumask_backtrace+0xd1/0xe0
  [28335.038520]  watchdog+0x5b3/0x670
  [28335.038528]  ? _raw_spin_unlock_irqrestore+0x37/0x40
  [28335.038535]  ? hungtask_pm_notify+0x40/0x40
  [28335.038544]  kthread+0x140/0x160
  [28335.038549]  ? set_kthread_struct+0x40/0x40
  [28335.038558]  ret_from_fork+0x1f/0x30
  [28335.038586] Sending NMI from CPU 2 to CPUs 0-1,3:
  [28335.038601] NMI backtrace for cpu 0 skipped: idling at native_safe_halt+0xb/0x10
  [28335.038609] NMI backtrace for cpu 1 skipped: idling at native_safe_halt+0xb/0x10
  [28335.038615] NMI backtrace for cpu 3
  [28335.038618] CPU: 3 PID: 0 Comm: swapper/3 Tainted: G        W  OE     5.15.0-rc4-for-5.16-io-uring-00060-g4922ab639eb6 #4 8b24b2500a34cedea2e69c8d84eb4c855e713e61
  [28335.038622] Hardware name: Acer Aspire ES1-421/OLVIA_BE, BIOS V1.05 07/02/2015
  [28335.038624] RIP: 0010:acpi_idle_enter+0x92/0x100
  [28335.038631] Code: 00 41 bc 01 00 00 00 48 8b 2c 02 0f b6 45 01 3c 03 75 07 0f 09 0f 1f 44 00 00 0f b6 45 08 3c 01 74 3a 3c 02 74 45 8b 55 04 ec <48> 8b 05 07 fd 51 01 a9 00 00 00 80 75 08 48 8b 15 3d 74 9d 02 ed
  [28335.038634] RSP: 0018:ffffc900001d7e90 EFLAGS: 00000093
  [28335.038637] RAX: 0000000000000000 RBX: 0000000000000002 RCX: 0000000000000040
  [28335.038639] RDX: 0000000000000414 RSI: ffff88810135b000 RDI: ffff888103161000
  [28335.038641] RBP: ffff88810135b098 R08: ffffffff82ae8f00 R09: 0000000000000018
  [28335.038643] R10: 0000000000000170 R11: 0000000000000af8 R12: 0000000000000002
  [28335.038644] R13: ffffffff82ae8fe8 R14: 0000000000000002 R15: 0000000000000000
  [28335.038646] FS:  0000000000000000(0000) GS:ffff888313d80000(0000) knlGS:0000000000000000
  [28335.038649] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
  [28335.038651] CR2: 00001e5478e1a518 CR3: 0000000199650000 CR4: 00000000000406e0
  [28335.038653] Call Trace:
  [28335.038656]  cpuidle_enter_state+0x9b/0x460
  [28335.038665]  cpuidle_enter+0x29/0x40
  [28335.038670]  do_idle+0x1fb/0x2a0
  [28335.038676]  cpu_startup_entry+0x19/0x20
  [28335.038680]  secondary_startup_64_no_verify+0xc2/0xcb

Cc: Pavel Begunkov <asml.silence@gmail.com>
Link: https://github.com/axboe/liburing/issues/448
Signed-off-by: Ammar Faizi <ammar.faizi@students.amikom.ac.id>
---

 v2:
  - Add child exit code check.
  - closedir() the opendir().
  - Add test/kworker-hang to .gitignore.
  - Small trival cleanups.

 .gitignore          |   1 +
 test/Makefile       |   2 +
 test/kworker-hang.c | 309 ++++++++++++++++++++++++++++++++++++++++++++
 3 files changed, 312 insertions(+)
 create mode 100644 test/kworker-hang.c

diff --git a/.gitignore b/.gitignore
index fb3a859..b0f5edf 100644
--- a/.gitignore
+++ b/.gitignore
@@ -65,6 +65,7 @@
 /test/io_uring_register
 /test/io_uring_setup
 /test/iopoll
+/test/kworker-hang
 /test/lfs-openat
 /test/lfs-openat-write
 /test/link
diff --git a/test/Makefile b/test/Makefile
index 1a10a24..7c8691d 100644
--- a/test/Makefile
+++ b/test/Makefile
@@ -75,6 +75,7 @@ test_targets += \
 	io_uring_register \
 	io_uring_setup \
 	iopoll \
+	kworker-hang \
 	lfs-openat \
 	lfs-openat-write \
 	link \
@@ -227,6 +228,7 @@ test_srcs := \
 	io_uring_register.c \
 	io_uring_setup.c \
 	iopoll.c \
+	kworker-hang.c \
 	lfs-openat-write.c \
 	lfs-openat.c \
 	link-timeout.c \
diff --git a/test/kworker-hang.c b/test/kworker-hang.c
new file mode 100644
index 0000000..6b52926
--- /dev/null
+++ b/test/kworker-hang.c
@@ -0,0 +1,309 @@
+/* SPDX-License-Identifier: MIT */
+
+/*
+ * kworker-hang
+ *
+ * Link: https://github.com/axboe/liburing/issues/448
+ */
+
+#include <dirent.h>
+#include <errno.h>
+#include <stdio.h>
+#include <unistd.h>
+#include <stdlib.h>
+#include <string.h>
+#include <fcntl.h>
+#include <sys/types.h>
+#include <sys/poll.h>
+#include <sys/eventfd.h>
+#include <sys/resource.h>
+#include <sys/wait.h>
+
+#include "helpers.h"
+#include "liburing.h"
+
+#define NR_RINGS			5
+#define WAIT_FOR_KWORKER_SECS		10
+#define WAIT_FOR_KWORKER_SECS_STR	"10"
+
+static bool is_all_numeric(const char *pid)
+{
+	size_t i, l;
+	char c;
+
+	l = strnlen(pid, 32);
+	if (l == 0)
+		return false;
+
+	for (i = 0; i < l; i++) {
+		c = pid[i];
+		if (!('0' <= c && c <= '9'))
+			return false;
+	}
+
+	return true;
+}
+
+static bool is_kworker_event_unbound(const char *pid)
+{
+	int fd;
+	bool ret = false;
+	char fpath[256];
+	char read_buf[256] = {0};
+	ssize_t read_size;
+
+	snprintf(fpath, sizeof(fpath), "/proc/%s/comm", pid);
+
+	fd = open(fpath, O_RDONLY);
+	if (fd < 0)
+		return false;
+
+	read_size = read(fd, read_buf, sizeof(read_buf) - 1);
+	if (read_size < 0)
+		goto out;
+
+	if (!strncmp(read_buf, "kworker", 7) && strstr(read_buf, "events_unbound"))
+		ret = true;
+out:
+	close(fd);
+	return ret;
+}
+
+static bool is_on_io_ring_exit_work(const char *pid)
+{
+	int fd;
+	bool ret = false;
+	char fpath[256];
+	char read_buf[4096] = {0};
+	ssize_t read_size;
+
+	snprintf(fpath, sizeof(fpath), "/proc/%s/stack", pid);
+
+	fd = open(fpath, O_RDONLY);
+	if (fd < 0)
+		return false;
+
+	read_size = read(fd, read_buf, sizeof(read_buf) - 1);
+	if (read_size < 0)
+		goto out;
+
+	if (strstr(read_buf, "io_ring_exit_work"))
+		ret = true;
+out:
+	close(fd);
+	return ret;
+}
+
+static bool is_in_dreaded_d_state(const char *pid)
+{
+	int fd;
+	bool ret = false;
+	char fpath[256];
+	char read_buf[4096] = {0};
+	ssize_t read_size;
+	const char *p = read_buf;
+
+	snprintf(fpath, sizeof(fpath), "/proc/%s/stat", pid);
+
+	fd = open(fpath, O_RDONLY);
+	if (fd < 0)
+		return false;
+
+	read_size = read(fd, read_buf, sizeof(read_buf) - 1);
+	if (read_size < 0)
+		goto out;
+
+	/*
+	 * It looks like this:
+	 * 9384 (kworker/u8:8+events_unbound) D 2 0 0 0 -1 69238880 0 0 0 0 0 0 0 0 20 0 1 0
+	 *
+	 * Catch the 'D'!
+	 */
+	while (*p != ')') {
+		p++;
+		if (&p[2] >= &read_buf[sizeof(read_buf) - 1])
+			/*
+			 * /proc/$pid/stack shows the wrong output?
+			 */
+			goto out;
+	}
+
+	ret = (p[2] == 'D');
+out:
+	close(fd);
+	return ret;
+}
+
+/*
+ * Returns 1 if we have kworker hang or fail to open `/proc`.
+ */
+static int scan_kworker_hang(void)
+{
+	DIR *dr;
+	int ret = 0;
+	struct dirent *de;
+
+	dr = opendir("/proc");
+	if (dr == NULL) {
+		perror("opendir");
+		return 1;
+	}
+
+	while (1) {
+		const char *pid;
+
+		de = readdir(dr);
+		if (!de)
+			break;
+
+		pid = de->d_name;
+		if (!is_all_numeric(pid))
+			continue;
+
+		if (!is_kworker_event_unbound(pid))
+			continue;
+
+		if (!is_on_io_ring_exit_work(pid))
+			continue;
+
+		if (is_in_dreaded_d_state(pid)) {
+			/* kworker is hang?! */
+			printf("Bug: found hang kworker on io_ring_exit_work "
+			       "/proc/%s\n", pid);
+			ret = 1;
+		}
+	}
+
+	closedir(dr);
+	return ret;
+}
+
+static void set_hung_entries(void)
+{
+	const char *cmds[] = {
+		/* Backup current values. */
+		"cat /proc/sys/kernel/hung_task_all_cpu_backtrace > hung_task_all_cpu_backtrace.bak",
+		"cat /proc/sys/kernel/hung_task_check_count > hung_task_check_count.bak",
+		"cat /proc/sys/kernel/hung_task_panic > hung_task_panic.bak",
+		"cat /proc/sys/kernel/hung_task_check_interval_secs > hung_task_check_interval_secs.bak",
+		"cat /proc/sys/kernel/hung_task_timeout_secs > hung_task_timeout_secs.bak",
+		"cat /proc/sys/kernel/hung_task_warnings > hung_task_warnings.bak",
+
+		/* Set to do the test. */
+		"echo 1 > /proc/sys/kernel/hung_task_all_cpu_backtrace",
+		"echo 99999999 > /proc/sys/kernel/hung_task_check_count",
+		"echo 0 > /proc/sys/kernel/hung_task_panic",
+		"echo 1 > /proc/sys/kernel/hung_task_check_interval_secs",
+		"echo " WAIT_FOR_KWORKER_SECS_STR " > /proc/sys/kernel/hung_task_timeout_secs",
+		"echo -1 > /proc/sys/kernel/hung_task_warnings",
+	};
+	int p;
+	size_t i;
+
+	for (i = 0; i < ARRAY_SIZE(cmds); i++)
+		p = system(cmds[i]);
+
+	(void)p;
+}
+
+static void restore_hung_entries(void)
+{
+	const char *cmds[] = {
+		/* Restore old values. */
+		"cat hung_task_all_cpu_backtrace.bak > /proc/sys/kernel/hung_task_all_cpu_backtrace",
+		"cat hung_task_check_count.bak > /proc/sys/kernel/hung_task_check_count",
+		"cat hung_task_panic.bak > /proc/sys/kernel/hung_task_panic",
+		"cat hung_task_check_interval_secs.bak > /proc/sys/kernel/hung_task_check_interval_secs",
+		"cat hung_task_timeout_secs.bak > /proc/sys/kernel/hung_task_timeout_secs",
+		"cat hung_task_warnings.bak > /proc/sys/kernel/hung_task_warnings",
+
+		/* Clean up! */
+		"rm -f " \
+		"hung_task_all_cpu_backtrace.bak " \
+		"hung_task_check_count.bak " \
+		"hung_task_panic.bak " \
+		"hung_task_check_interval_secs.bak " \
+		"hung_task_timeout_secs.bak " \
+		"hung_task_warnings.bak"
+	};
+	int p;
+	size_t i;
+
+	for (i = 0; i < ARRAY_SIZE(cmds); i++)
+		p = system(cmds[i]);
+
+	(void)p;
+}
+
+
+static int run_child(void)
+{
+	int ret, i;
+	struct io_uring rings[NR_RINGS];
+
+	for (i = 0; i < NR_RINGS; i++) {
+		struct io_uring_params p = { };
+
+		ret = io_uring_queue_init_params(64, &rings[i], &p);
+		if (ret) {
+			printf("io_uring_queue_init_params(): (%d) %s\n",
+			       ret, strerror(-ret));
+			return 1;
+		}
+	}
+
+	for (i = 0; i < NR_RINGS; i++)
+		io_uring_queue_exit(&rings[i]);
+
+	kill(getpid(), SIGSTOP);
+	/*
+	 * kworker hang right after it sends SIGSTOP to itself.
+	 * The parent process will check it.
+	 */
+	return 0;
+}
+
+int main(void)
+{
+	pid_t child_pid;
+	int ret, wstatus = 0;
+
+	/*
+	 * We need root to check /proc/$pid/stack and set /proc/sys/kernel/hung*
+	 */
+	if (getuid() != 0 && geteuid() != 0) {
+		printf("Skipping kworker-hang: not root\n");
+		return 0;
+	}
+
+	set_hung_entries();
+	child_pid = fork();
+	if (child_pid < 0) {
+		perror("fork()");
+		return 1;
+	}
+
+	if (!child_pid)
+		return run_child();
+
+	atexit(restore_hung_entries);
+
+	/* +2 just to add small extra time for khungtaskd. */
+	sleep(WAIT_FOR_KWORKER_SECS + 2);
+	ret = scan_kworker_hang();
+
+	kill(child_pid, SIGCONT);
+
+	if (waitpid(child_pid, &wstatus, 0) < 0) {
+		perror("waitpid()");
+		return 1;
+	}
+
+	if (!WIFEXITED(wstatus)) {
+		printf("Child process won't exit!\n");
+		return 1;
+	}
+
+	/* Make sure child process exited properly as well. */
+	return ret | WEXITSTATUS(wstatus);
+}
-- 
2.30.2