Skip to content

Commit 989d478

Browse files
committed
taskq: deadman: log a message if a taskq has not made progress
It is very difficult to debug situations where all threads on a taskq go to sleep waiting for some condition that will not be satisfied until some task queued on that taskq performs some task. Its usually easy to see that the threads are waiting, but less easy to see that unscheduled tasks exist. This adds a simple deadman logging function to each taskq. The first time a taskq picks up a thread, it arms the timer to expire in spl_taskq_deadman_timeout seconds (default 20s). If another thread picks up a new task, the timer is rearmed. When the last active thread completes its task, the timer is disarmed. All together, this means the deadman will fire if no new tasks have started or existing tasks have completed within the configured time. As long as the taskq is making progress, everything will be silent. When it fires, it will log a notice to the kernel log: [ 28.715019] spl: taskq stuck for 20s: z_null_int.0 [1/1 threads active, 35 tasks queued] If it clears by itself, that is, this was a genuinely long-running task, a second message will be logged: [ 38.819171] spl: taskq resumed after s105s: z_null_iss.0 spl_taskq_deadman_timeout=0 will disable the facility entirely. Sponsored-by: Klara, Inc. Sponsored-by: Wasabi Technology, Inc. Signed-off-by: Rob Norris <[email protected]>
1 parent 24aaf3a commit 989d478

File tree

4 files changed

+103
-6
lines changed

4 files changed

+103
-6
lines changed

config/kernel-timer.m4

Lines changed: 25 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -1,8 +1,19 @@
11
dnl #
2-
dnl # 6.2: timer_delete_sync introduced, del_timer_sync deprecated and made
3-
dnl # into a simple wrapper
2+
dnl # 6.2: timer_delete & timer_delete_sync introduced, del_timer &
3+
dnl del_timer_sync deprecated and made into a simple wrapper
44
dnl # 6.15: del_timer_sync removed
55
dnl #
6+
dnl # We test for them separately as they appear to have not always been
7+
dnl # backported together
8+
dnl #
9+
AC_DEFUN([ZFS_AC_KERNEL_SRC_TIMER_DELETE], [
10+
ZFS_LINUX_TEST_SRC([timer_delete], [
11+
#include <linux/timer.h>
12+
],[
13+
struct timer_list *timer __attribute__((unused)) = NULL;
14+
timer_delete(timer);
15+
])
16+
])
617
AC_DEFUN([ZFS_AC_KERNEL_SRC_TIMER_DELETE_SYNC], [
718
ZFS_LINUX_TEST_SRC([timer_delete_sync], [
819
#include <linux/timer.h>
@@ -12,6 +23,16 @@ AC_DEFUN([ZFS_AC_KERNEL_SRC_TIMER_DELETE_SYNC], [
1223
])
1324
])
1425

26+
AC_DEFUN([ZFS_AC_KERNEL_TIMER_DELETE], [
27+
AC_MSG_CHECKING([whether timer_delete() is available])
28+
ZFS_LINUX_TEST_RESULT([timer_delete], [
29+
AC_MSG_RESULT(yes)
30+
AC_DEFINE(HAVE_TIMER_DELETE, 1,
31+
[timer_delete is available])
32+
],[
33+
AC_MSG_RESULT(no)
34+
])
35+
])
1536
AC_DEFUN([ZFS_AC_KERNEL_TIMER_DELETE_SYNC], [
1637
AC_MSG_CHECKING([whether timer_delete_sync() is available])
1738
ZFS_LINUX_TEST_RESULT([timer_delete_sync], [
@@ -24,9 +45,11 @@ AC_DEFUN([ZFS_AC_KERNEL_TIMER_DELETE_SYNC], [
2445
])
2546

2647
AC_DEFUN([ZFS_AC_KERNEL_SRC_TIMER], [
48+
ZFS_AC_KERNEL_SRC_TIMER_DELETE
2749
ZFS_AC_KERNEL_SRC_TIMER_DELETE_SYNC
2850
])
2951

3052
AC_DEFUN([ZFS_AC_KERNEL_TIMER], [
53+
ZFS_AC_KERNEL_TIMER_DELETE
3154
ZFS_AC_KERNEL_TIMER_DELETE_SYNC
3255
])

include/os/linux/spl/sys/taskq.h

Lines changed: 3 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -22,7 +22,7 @@
2222
* with the SPL. If not, see <http://www.gnu.org/licenses/>.
2323
*/
2424
/*
25-
* Copyright (c) 2024, Klara Inc.
25+
* Copyright (c) 2024, 2025, Klara, Inc.
2626
* Copyright (c) 2024, Syneto
2727
*/
2828

@@ -134,6 +134,8 @@ typedef struct taskq {
134134
wait_queue_head_t tq_work_waitq; /* new work waitq */
135135
wait_queue_head_t tq_wait_waitq; /* wait waitq */
136136
tq_lock_role_t tq_lock_class; /* class when taking tq_lock */
137+
struct timer_list tq_deadman; /* deadman timer */
138+
unsigned long tq_deadman_at; /* time of last deadman trip */
137139
/* list node for the cpu hotplug callback */
138140
struct hlist_node tq_hp_cb_node;
139141
boolean_t tq_hp_support;

man/man4/spl.4

Lines changed: 10 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -14,8 +14,9 @@
1414
.\" Portions Copyright [yyyy] [name of copyright owner]
1515
.\"
1616
.\" Copyright 2013 Turbo Fredriksson <[email protected]>. All rights reserved.
17+
.\" Copyright (c) 2025, Klara, Inc.
1718
.\"
18-
.Dd May 7, 2025
19+
.Dd November 12, 2025
1920
.Dt SPL 4
2021
.Os
2122
.
@@ -130,6 +131,14 @@ When not enabled, the thread is halted to facilitate further debugging.
130131
.Pp
131132
Set to a non-zero value to enable.
132133
.
134+
.It Sy spl_taskq_deadman_timeout Ns = Ns Sy 20 Pq uint
135+
Log a warning if a taskq has not made progress in N seconds.
136+
"Progress" here means a taskq thread has not picked up a new task in this
137+
time,
138+
or all threads have not completed in this time.
139+
This can be useful for deadlock debugging.
140+
Setting this value to 0 will disable this function.
141+
.
133142
.It Sy spl_taskq_kick Ns = Ns Sy 0 Pq uint
134143
Kick stuck taskq to spawn threads.
135144
When writing a non-zero value to it, it will scan all the taskqs.

module/os/linux/spl/spl-taskq.c

Lines changed: 65 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -24,7 +24,7 @@
2424
* Solaris Porting Layer (SPL) Task Queue Implementation.
2525
*/
2626
/*
27-
* Copyright (c) 2024, Klara Inc.
27+
* Copyright (c) 2024, 2025, Klara, Inc.
2828
* Copyright (c) 2024, Syneto
2929
*/
3030

@@ -39,7 +39,14 @@
3939
#include <linux/cpuhotplug.h>
4040
#include <linux/mod_compat.h>
4141

42-
/* Linux 6.2 renamed timer_delete_sync(); point it at its old name for those. */
42+
/*
43+
* Linux 6.2 renamed del_timer()/del_timer_sync() to
44+
* timer_delete()/timer_delete_sync(). For kernels before that, point the new
45+
* names to the old.
46+
*/
47+
#ifndef HAVE_TIMER_DELETE
48+
#define timer_delete(t) del_timer(t)
49+
#endif
4350
#ifndef HAVE_TIMER_DELETE_SYNC
4451
#define timer_delete_sync(t) del_timer_sync(t)
4552
#endif
@@ -142,6 +149,11 @@ module_param(spl_taskq_thread_sequential, uint, 0644);
142149
MODULE_PARM_DESC(spl_taskq_thread_sequential,
143150
"Create new taskq threads after N sequential tasks");
144151

152+
static uint_t spl_taskq_deadman_timeout = 20;
153+
module_param(spl_taskq_deadman_timeout, uint, 0644);
154+
MODULE_PARM_DESC(spl_taskq_deadman_timeout,
155+
"Log a warning if the taskq has not made progress in N seconds");
156+
145157
/*
146158
* Global system-wide dynamic task queue available for all consumers. This
147159
* taskq is not intended for long-running tasks; instead, a dedicated taskq
@@ -357,6 +369,34 @@ task_expire(struct timer_list *tl)
357369
task_expire_impl(t);
358370
}
359371

372+
static void
373+
taskq_deadman(struct timer_list *tl)
374+
{
375+
unsigned long irqflags;
376+
taskq_t *tq = container_of(tl, taskq_t, tq_deadman);
377+
378+
spin_lock_irqsave_nested(&tq->tq_lock, irqflags, tq->tq_lock_class);
379+
if (tq->tq_nactive == 0 || spl_taskq_deadman_timeout == 0) {
380+
spin_unlock_irqrestore(&tq->tq_lock, irqflags);
381+
return;
382+
}
383+
384+
unsigned long nqueued = 0;
385+
struct list_head *pos;
386+
list_for_each(pos, &tq->tq_pend_list)
387+
nqueued++;
388+
list_for_each(pos, &tq->tq_prio_list)
389+
nqueued++;
390+
391+
printk(KERN_INFO "spl: taskq stuck for %us: %s.%d "
392+
"[%d/%d threads active, %lu tasks queued]\n",
393+
spl_taskq_deadman_timeout, tq->tq_name, tq->tq_instance,
394+
tq->tq_nthreads, tq->tq_nactive, nqueued);
395+
396+
tq->tq_deadman_at = jiffies;
397+
spin_unlock_irqrestore(&tq->tq_lock, irqflags);
398+
}
399+
360400
/*
361401
* Returns the lowest incomplete taskqid_t. The taskqid_t may
362402
* be queued on the pending list, on the priority list, on the
@@ -1071,6 +1111,11 @@ taskq_thread(void *args)
10711111

10721112
taskq_insert_in_order(tq, tqt);
10731113
tq->tq_nactive++;
1114+
1115+
if (spl_taskq_deadman_timeout > 0)
1116+
mod_timer(&tq->tq_deadman,
1117+
jiffies + spl_taskq_deadman_timeout * HZ);
1118+
10741119
spin_unlock_irqrestore(&tq->tq_lock, flags);
10751120

10761121
TQSTAT_INC(tq, threads_active);
@@ -1096,6 +1141,21 @@ taskq_thread(void *args)
10961141
list_del_init(&tqt->tqt_active_list);
10971142
tqt->tqt_task = NULL;
10981143

1144+
if (tq->tq_nactive == 0 ||
1145+
spl_taskq_deadman_timeout == 0)
1146+
timer_delete(&tq->tq_deadman);
1147+
1148+
if (tq->tq_deadman_at > 0) {
1149+
unsigned long stuck_for =
1150+
jiffies - tq->tq_deadman_at;
1151+
tq->tq_deadman_at = 0;
1152+
1153+
printk(KERN_INFO
1154+
"spl: taskq resumed after %lus: %s.%d\n",
1155+
stuck_for / HZ, tq->tq_name,
1156+
tq->tq_instance);
1157+
}
1158+
10991159
/* For prealloc'd tasks, we don't free anything. */
11001160
if (!(tqt->tqt_flags & TQENT_FLAG_PREALLOC))
11011161
task_done(tq, t);
@@ -1375,6 +1435,9 @@ taskq_create(const char *name, int threads_arg, pri_t pri,
13751435
tq->tq_next_id = TASKQID_INITIAL;
13761436
tq->tq_lowest_id = TASKQID_INITIAL;
13771437
tq->lastspawnstop = jiffies;
1438+
timer_setup(&tq->tq_deadman, NULL, 0);
1439+
tq->tq_deadman.function = taskq_deadman;
1440+
tq->tq_deadman_at = 0;
13781441
INIT_LIST_HEAD(&tq->tq_free_list);
13791442
INIT_LIST_HEAD(&tq->tq_pend_list);
13801443
INIT_LIST_HEAD(&tq->tq_prio_list);

0 commit comments

Comments
 (0)