[PATCH v2] kprobes: Use dedicated kthread for kprobe optimizer

Masami Hiramatsu (Google) posted 1 patch 3 weeks, 4 days ago
There is a newer version of this series
kernel/kprobes.c |  104 ++++++++++++++++++++++++++++++++++++++++++++----------
1 file changed, 84 insertions(+), 20 deletions(-)
[PATCH v2] kprobes: Use dedicated kthread for kprobe optimizer
Posted by Masami Hiramatsu (Google) 3 weeks, 4 days ago
From: Masami Hiramatsu (Google) <mhiramat@kernel.org>

Instead of using generic workqueue, use a dedicated kthread for optimizing
kprobes, because it can wait (sleep) for a long time inside the process
by synchronize_rcu_task(). This means other works can be stopped until it
finishes.

Suggested-by: Steven Rostedt <rostedt@goodmis.org>
Signed-off-by: Masami Hiramatsu (Google) <mhiramat@kernel.org>
---
 Changes in v2:
  - Make the kthread unfreezable same as workqueue.
  - Add kthread_should_stop() check right before calling optimizer too.
  - Initialize optimizer_state to OPTIMIZER_ST_IDLE instead of 0.
---
 kernel/kprobes.c |  104 ++++++++++++++++++++++++++++++++++++++++++++----------
 1 file changed, 84 insertions(+), 20 deletions(-)

diff --git a/kernel/kprobes.c b/kernel/kprobes.c
index ab8f9fc1f0d1..4778bfca19b8 100644
--- a/kernel/kprobes.c
+++ b/kernel/kprobes.c
@@ -32,6 +32,7 @@
 #include <linux/debugfs.h>
 #include <linux/sysctl.h>
 #include <linux/kdebug.h>
+#include <linux/kthread.h>
 #include <linux/memory.h>
 #include <linux/ftrace.h>
 #include <linux/cpu.h>
@@ -40,6 +41,7 @@
 #include <linux/perf_event.h>
 #include <linux/execmem.h>
 #include <linux/cleanup.h>
+#include <linux/wait.h>
 
 #include <asm/sections.h>
 #include <asm/cacheflush.h>
@@ -514,8 +516,17 @@ static LIST_HEAD(optimizing_list);
 static LIST_HEAD(unoptimizing_list);
 static LIST_HEAD(freeing_list);
 
-static void kprobe_optimizer(struct work_struct *work);
-static DECLARE_DELAYED_WORK(optimizing_work, kprobe_optimizer);
+static struct task_struct *kprobe_optimizer_task;
+static wait_queue_head_t kprobe_optimizer_wait;
+static atomic_t optimizer_state;
+enum {
+	OPTIMIZER_ST_IDLE = 0,
+	OPTIMIZER_ST_KICKED = 1,
+	OPTIMIZER_ST_FLUSHING = 2,
+};
+
+static DECLARE_COMPLETION(optimizer_completion);
+
 #define OPTIMIZE_DELAY 5
 
 /*
@@ -597,14 +608,10 @@ static void do_free_cleaned_kprobes(void)
 	}
 }
 
-/* Start optimizer after OPTIMIZE_DELAY passed */
-static void kick_kprobe_optimizer(void)
-{
-	schedule_delayed_work(&optimizing_work, OPTIMIZE_DELAY);
-}
+static void kick_kprobe_optimizer(void);
 
 /* Kprobe jump optimizer */
-static void kprobe_optimizer(struct work_struct *work)
+static void kprobe_optimizer(void)
 {
 	guard(mutex)(&kprobe_mutex);
 
@@ -635,9 +642,51 @@ static void kprobe_optimizer(struct work_struct *work)
 		do_free_cleaned_kprobes();
 	}
 
-	/* Step 5: Kick optimizer again if needed */
+	/* Step 5: Kick optimizer again if needed. But if there is a flush requested, */
+	if (completion_done(&optimizer_completion))
+		complete(&optimizer_completion);
+
 	if (!list_empty(&optimizing_list) || !list_empty(&unoptimizing_list))
-		kick_kprobe_optimizer();
+		kick_kprobe_optimizer();	/*normal kick*/
+}
+
+static int kprobe_optimizer_thread(void *data)
+{
+	while (!kthread_should_stop()) {
+		wait_event(kprobe_optimizer_wait,
+			   atomic_read(&optimizer_state) != OPTIMIZER_ST_IDLE ||
+			   kthread_should_stop());
+
+		if (kthread_should_stop())
+			break;
+
+		/*
+		 * If it was a normal kick, wait for OPTIMIZE_DELAY.
+		 * This wait can be interrupted by a flush request.
+		 */
+		if (atomic_read(&optimizer_state) == 1)
+			wait_event_timeout(kprobe_optimizer_wait,
+				atomic_read(&optimizer_state) == OPTIMIZER_ST_FLUSHING ||
+				kthread_should_stop(),
+				OPTIMIZE_DELAY);
+
+		if (kthread_should_stop())
+			break;
+
+		atomic_set(&optimizer_state, OPTIMIZER_ST_IDLE);
+
+		kprobe_optimizer();
+	}
+	return 0;
+}
+
+/* Start optimizer after OPTIMIZE_DELAY passed */
+static void kick_kprobe_optimizer(void)
+{
+	lockdep_assert_held(&kprobe_mutex);
+	if (atomic_cmpxchg(&optimizer_state,
+		OPTIMIZER_ST_IDLE, OPTIMIZER_ST_KICKED) == OPTIMIZER_ST_IDLE)
+		wake_up(&kprobe_optimizer_wait);
 }
 
 static void wait_for_kprobe_optimizer_locked(void)
@@ -645,13 +694,17 @@ static void wait_for_kprobe_optimizer_locked(void)
 	lockdep_assert_held(&kprobe_mutex);
 
 	while (!list_empty(&optimizing_list) || !list_empty(&unoptimizing_list)) {
-		mutex_unlock(&kprobe_mutex);
-
-		/* This will also make 'optimizing_work' execute immmediately */
-		flush_delayed_work(&optimizing_work);
-		/* 'optimizing_work' might not have been queued yet, relax */
-		cpu_relax();
+		init_completion(&optimizer_completion);
+		/*
+		 * Set state to OPTIMIZER_ST_FLUSHING and wake up the thread if it's
+		 * idle. If it's already kicked, it will see the state change.
+		 */
+		if (atomic_xchg_acquire(&optimizer_state,
+			OPTIMIZER_ST_FLUSHING) != OPTIMIZER_ST_FLUSHING)
+			wake_up(&kprobe_optimizer_wait);
 
+		mutex_unlock(&kprobe_mutex);
+		wait_for_completion(&optimizer_completion);
 		mutex_lock(&kprobe_mutex);
 	}
 }
@@ -1010,8 +1063,21 @@ static void __disarm_kprobe(struct kprobe *p, bool reopt)
 	 */
 }
 
+static void __init init_optprobe(void)
+{
+#ifdef __ARCH_WANT_KPROBES_INSN_SLOT
+	/* Init 'kprobe_optinsn_slots' for allocation */
+	kprobe_optinsn_slots.insn_size = MAX_OPTINSN_SIZE;
+#endif
+
+	init_waitqueue_head(&kprobe_optimizer_wait);
+	atomic_set(&optimizer_state, OPTIMIZER_ST_IDLE);
+	kprobe_optimizer_task = kthread_run(kprobe_optimizer_thread, NULL,
+					    "kprobe-optimizer");
+}
 #else /* !CONFIG_OPTPROBES */
 
+#define init_optprobe()				do {} while (0)
 #define optimize_kprobe(p)			do {} while (0)
 #define unoptimize_kprobe(p, f)			do {} while (0)
 #define kill_optimized_kprobe(p)		do {} while (0)
@@ -2694,10 +2760,8 @@ static int __init init_kprobes(void)
 	/* By default, kprobes are armed */
 	kprobes_all_disarmed = false;
 
-#if defined(CONFIG_OPTPROBES) && defined(__ARCH_WANT_KPROBES_INSN_SLOT)
-	/* Init 'kprobe_optinsn_slots' for allocation */
-	kprobe_optinsn_slots.insn_size = MAX_OPTINSN_SIZE;
-#endif
+	/* Initialize the optimization infrastructure */
+	init_optprobe();
 
 	err = arch_init_kprobes();
 	if (!err)
Re: [PATCH v2] kprobes: Use dedicated kthread for kprobe optimizer
Posted by kernel test robot 2 weeks, 5 days ago

Hello,

kernel test robot noticed "INFO:task_blocked_for_more_than#seconds" on:

commit: 62f65c2531ad66e84c1a5ef91389322357ef6db4 ("[PATCH v2] kprobes: Use dedicated kthread for kprobe optimizer")
url: https://github.com/intel-lab-lkp/linux/commits/Masami-Hiramatsu-Google/kprobes-Use-dedicated-kthread-for-kprobe-optimizer/20260113-094928
base: https://git.kernel.org/cgit/linux/kernel/git/trace/linux-trace for-next
patch link: https://lore.kernel.org/all/176826884613.429923.16578111751623731056.stgit@devnote2/
patch subject: [PATCH v2] kprobes: Use dedicated kthread for kprobe optimizer

in testcase: trinity
version: trinity-x86_64-294c4652-1_20251011
with following parameters:

	runtime: 300s
	group: group-03
	nr_groups: 5



config: x86_64-kexec
compiler: clang-20
test machine: qemu-system-x86_64 -enable-kvm -cpu SandyBridge -smp 2 -m 32G

(please refer to attached dmesg/kmsg for entire log/backtrace)


+-----------------------------------------+------------+------------+
|                                         | 78a419b44e | 62f65c2531 |
+-----------------------------------------+------------+------------+
| INFO:task_blocked_for_more_than#seconds | 0          | 6          |
+-----------------------------------------+------------+------------+


If you fix the issue in a separate patch/commit (i.e. not just a new version of
the same patch/commit), kindly add following tags
| Reported-by: kernel test robot <oliver.sang@intel.com>
| Closes: https://lore.kernel.org/oe-lkp/202601191507.74fccd0c-lkp@intel.com



[  972.359932][   T32] INFO: task kprobe-optimize:18 blocked for more than 491 seconds.
[  972.361221][   T32]       Not tainted 6.19.0-rc5-00040-g62f65c2531ad #1
[  972.362516][   T32] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  972.364322][   T32] task:kprobe-optimize state:D stack:0     pid:18    tgid:18    ppid:2      task_flags:0x208040 flags:0x00080000
[  972.366628][   T32] Call Trace:
[  972.367378][   T32]  <TASK>
[  972.368066][   T32]  __schedule (kernel/sched/core.c:5259)
[  972.370837][   T32]  schedule (arch/x86/include/asm/preempt.h:85 kernel/sched/core.c:6946 kernel/sched/core.c:6960)
[  972.371679][   T32]  kprobe_optimizer_thread (kernel/kprobes.c:656)
[  972.373219][   T32]  ? __pfx_autoremove_wake_function (kernel/sched/wait.c:402)
[  972.374017][   T32]  kthread (kernel/kthread.c:465)
[  972.374573][   T32]  ? __pfx_kprobe_optimizer_thread (kernel/kprobes.c:654)
[  972.375364][   T32]  ? __pfx_kthread (kernel/kthread.c:412)
[  972.376005][   T32]  ret_from_fork (arch/x86/kernel/process.c:164)
[  972.376679][   T32]  ? __pfx_kthread (kernel/kthread.c:412)
[  972.377305][   T32]  ret_from_fork_asm (arch/x86/entry/entry_64.S:256)
[  972.377958][   T32]  </TASK>
[ 1463.879952][   T32] INFO: task kprobe-optimize:18 blocked for more than 983 seconds.
[ 1463.882239][   T32]       Not tainted 6.19.0-rc5-00040-g62f65c2531ad #1
[ 1463.884371][   T32] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1463.887443][   T32] task:kprobe-optimize state:D stack:0     pid:18    tgid:18    ppid:2      task_flags:0x208040 flags:0x00080000
[ 1463.891867][   T32] Call Trace:
[ 1463.893396][   T32]  <TASK>
[ 1463.894468][   T32]  __schedule (kernel/sched/core.c:5259)
[ 1463.903984][   T32]  schedule (arch/x86/include/asm/preempt.h:85 kernel/sched/core.c:6946 kernel/sched/core.c:6960)
[ 1463.904926][   T32]  kprobe_optimizer_thread (kernel/kprobes.c:656)
[ 1463.905949][   T32]  ? __pfx_autoremove_wake_function (kernel/sched/wait.c:402)
[ 1463.907111][   T32]  kthread (kernel/kthread.c:465)
[ 1463.907954][   T32]  ? __pfx_kprobe_optimizer_thread (kernel/kprobes.c:654)
[ 1463.909157][   T32]  ? __pfx_kthread (kernel/kthread.c:412)
[ 1463.910045][   T32]  ret_from_fork (arch/x86/kernel/process.c:164)
[ 1463.910939][   T32]  ? __pfx_kthread (kernel/kthread.c:412)
[ 1463.911933][   T32]  ret_from_fork_asm (arch/x86/entry/entry_64.S:256)
[ 1463.912947][   T32]  </TASK>
[ 1955.399991][   T32] INFO: task kprobe-optimize:18 blocked for more than 1474 seconds.
[ 1955.404266][   T32]       Not tainted 6.19.0-rc5-00040-g62f65c2531ad #1
[ 1955.407452][   T32] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1955.414557][   T32] task:kprobe-optimize state:D stack:0     pid:18    tgid:18    ppid:2      task_flags:0x208040 flags:0x00080000
[ 1955.416961][   T32] Call Trace:
[ 1955.417705][   T32]  <TASK>
[ 1955.418382][   T32]  __schedule (kernel/sched/core.c:5259)
[ 1955.419274][   T32]  schedule (arch/x86/include/asm/preempt.h:85 kernel/sched/core.c:6946 kernel/sched/core.c:6960)
[ 1955.419929][   T32]  kprobe_optimizer_thread (kernel/kprobes.c:656)
[ 1955.421071][   T32]  ? __pfx_autoremove_wake_function (kernel/sched/wait.c:402)
[ 1955.422303][   T32]  kthread (kernel/kthread.c:465)
[ 1955.423217][   T32]  ? __pfx_kprobe_optimizer_thread (kernel/kprobes.c:654)
[ 1955.424452][   T32]  ? __pfx_kthread (kernel/kthread.c:412)
[ 1955.425189][   T32]  ret_from_fork (arch/x86/kernel/process.c:164)
[ 1955.425913][   T32]  ? __pfx_kthread (kernel/kthread.c:412)
[ 1955.426645][   T32]  ret_from_fork_asm (arch/x86/entry/entry_64.S:256)
[ 1955.427357][   T32]  </TASK>
[ 2446.919964][   T32] INFO: task kprobe-optimize:18 blocked for more than 1966 seconds.
[ 2446.922105][   T32]       Not tainted 6.19.0-rc5-00040-g62f65c2531ad #1
[ 2446.925697][   T32] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 2446.926569][   T32] task:kprobe-optimize state:D stack:0     pid:18    tgid:18    ppid:2      task_flags:0x208040 flags:0x00080000
[ 2446.927775][   T32] Call Trace:
[ 2446.928242][   T32]  <TASK>
[ 2446.928609][   T32]  __schedule (kernel/sched/core.c:5259)
[ 2446.929827][   T32]  schedule (arch/x86/include/asm/preempt.h:85 kernel/sched/core.c:6946 kernel/sched/core.c:6960)
[ 2446.930256][   T32]  kprobe_optimizer_thread (kernel/kprobes.c:656)
[ 2446.930789][   T32]  ? __pfx_autoremove_wake_function (kernel/sched/wait.c:402)
[ 2446.931434][   T32]  kthread (kernel/kthread.c:465)
[ 2446.931926][   T32]  ? __pfx_kprobe_optimizer_thread (kernel/kprobes.c:654)
[ 2446.932624][   T32]  ? __pfx_kthread (kernel/kthread.c:412)
[ 2446.933079][   T32]  ret_from_fork (arch/x86/kernel/process.c:164)
[ 2446.933534][   T32]  ? __pfx_kthread (kernel/kthread.c:412)
[ 2446.933983][   T32]  ret_from_fork_asm (arch/x86/entry/entry_64.S:256)
[ 2446.934450][   T32]  </TASK>
[ 2938.439916][   T32] INFO: task kprobe-optimize:18 blocked for more than 2457 seconds.
[ 2938.441278][   T32]       Not tainted 6.19.0-rc5-00040-g62f65c2531ad #1
[ 2938.442281][   T32] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 2938.444599][   T32] task:kprobe-optimize state:D stack:0     pid:18    tgid:18    ppid:2      task_flags:0x208040 flags:0x00080000
[ 2938.446316][   T32] Call Trace:
[ 2938.446892][   T32]  <TASK>
[ 2938.447449][   T32]  __schedule (kernel/sched/core.c:5259)
[ 2938.449286][   T32]  schedule (arch/x86/include/asm/preempt.h:85 kernel/sched/core.c:6946 kernel/sched/core.c:6960)
[ 2938.450230][   T32]  kprobe_optimizer_thread (kernel/kprobes.c:656)
[ 2938.451347][   T32]  ? __pfx_autoremove_wake_function (kernel/sched/wait.c:402)
[ 2938.452611][   T32]  kthread (kernel/kthread.c:465)
[ 2938.453462][   T32]  ? __pfx_kprobe_optimizer_thread (kernel/kprobes.c:654)
[ 2938.454622][   T32]  ? __pfx_kthread (kernel/kthread.c:412)
[ 2938.455583][   T32]  ret_from_fork (arch/x86/kernel/process.c:164)
[ 2938.456604][   T32]  ? __pfx_kthread (kernel/kthread.c:412)
[ 2938.457614][   T32]  ret_from_fork_asm (arch/x86/entry/entry_64.S:256)
[ 2938.458645][   T32]  </TASK>
[ 3429.960057][   T32] INFO: task kprobe-optimize:18 blocked for more than 2949 seconds.
[ 3429.962853][   T32]       Not tainted 6.19.0-rc5-00040-g62f65c2531ad #1
[ 3429.965133][   T32] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 3429.967986][   T32] task:kprobe-optimize state:D stack:0     pid:18    tgid:18    ppid:2      task_flags:0x208040 flags:0x00080000
[ 3429.971731][   T32] Call Trace:
[ 3429.973021][   T32]  <TASK>
[ 3429.974169][   T32]  __schedule (kernel/sched/core.c:5259)
[ 3429.975713][   T32]  schedule (arch/x86/include/asm/preempt.h:85 kernel/sched/core.c:6946 kernel/sched/core.c:6960)
[ 3429.977206][   T32]  kprobe_optimizer_thread (kernel/kprobes.c:656)
[ 3429.978375][   T32]  ? __pfx_autoremove_wake_function (kernel/sched/wait.c:402)
[ 3429.979623][   T32]  kthread (kernel/kthread.c:465)
[ 3429.980602][   T32]  ? __pfx_kprobe_optimizer_thread (kernel/kprobes.c:654)
[ 3429.981810][   T32]  ? __pfx_kthread (kernel/kthread.c:412)
[ 3429.982797][   T32]  ret_from_fork (arch/x86/kernel/process.c:164)
[ 3429.983793][   T32]  ? __pfx_kthread (kernel/kthread.c:412)
[ 3429.984838][   T32]  ret_from_fork_asm (arch/x86/entry/entry_64.S:256)
[ 3429.985864][   T32]  </TASK>
[ 3921.480064][   T32] INFO: task kprobe-optimize:18 blocked for more than 3440 seconds.
[ 3921.482942][   T32]       Not tainted 6.19.0-rc5-00040-g62f65c2531ad #1
[ 3921.485260][   T32] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 3921.488269][   T32] task:kprobe-optimize state:D stack:0     pid:18    tgid:18    ppid:2      task_flags:0x208040 flags:0x00080000
[ 3921.491811][   T32] Call Trace:
[ 3921.493488][   T32]  <TASK>
[ 3921.494960][   T32]  __schedule (kernel/sched/core.c:5259)
[ 3921.508616][   T32]  schedule (arch/x86/include/asm/preempt.h:85 kernel/sched/core.c:6946 kernel/sched/core.c:6960)
[ 3921.509430][   T32]  kprobe_optimizer_thread (kernel/kprobes.c:656)
[ 3921.510413][   T32]  ? __pfx_autoremove_wake_function (kernel/sched/wait.c:402)
[ 3921.511467][   T32]  kthread (kernel/kthread.c:465)
[ 3921.512331][   T32]  ? __pfx_kprobe_optimizer_thread (kernel/kprobes.c:654)
[ 3921.513388][   T32]  ? __pfx_kthread (kernel/kthread.c:412)
[ 3921.514202][   T32]  ret_from_fork (arch/x86/kernel/process.c:164)
[ 3921.514976][   T32]  ? __pfx_kthread (kernel/kthread.c:412)
[ 3921.515773][   T32]  ret_from_fork_asm (arch/x86/entry/entry_64.S:256)
[ 3921.516817][   T32]  </TASK>
[ 4413.000017][   T32] INFO: task kprobe-optimize:18 blocked for more than 3932 seconds.
[ 4413.004653][   T32]       Not tainted 6.19.0-rc5-00040-g62f65c2531ad #1
[ 4413.007745][   T32] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 4413.010446][   T32] task:kprobe-optimize state:D stack:0     pid:18    tgid:18    ppid:2      task_flags:0x208040 flags:0x00080000
[ 4413.013906][   T32] Call Trace:
[ 4413.015027][   T32]  <TASK>
[ 4413.016134][   T32]  __schedule (kernel/sched/core.c:5259)
[ 4413.017465][   T32]  schedule (arch/x86/include/asm/preempt.h:85 kernel/sched/core.c:6946 kernel/sched/core.c:6960)
[ 4413.018294][   T32]  kprobe_optimizer_thread (kernel/kprobes.c:656)
[ 4413.019366][   T32]  ? __pfx_autoremove_wake_function (kernel/sched/wait.c:402)
[ 4413.020594][   T32]  kthread (kernel/kthread.c:465)
[ 4413.021350][   T32]  ? __pfx_kprobe_optimizer_thread (kernel/kprobes.c:654)
[ 4413.022331][   T32]  ? __pfx_kthread (kernel/kthread.c:412)
[ 4413.023124][   T32]  ret_from_fork (arch/x86/kernel/process.c:164)
[ 4413.023925][   T32]  ? __pfx_kthread (kernel/kthread.c:412)
[ 4413.025015][   T32]  ret_from_fork_asm (arch/x86/entry/entry_64.S:256)
[ 4413.026074][   T32]  </TASK>
[ 4904.520028][   T32] INFO: task kprobe-optimize:18 blocked for more than 4423 seconds.
[ 4904.521949][   T32]       Not tainted 6.19.0-rc5-00040-g62f65c2531ad #1
[ 4904.528612][   T32] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 4904.529924][   T32] task:kprobe-optimize state:D stack:0     pid:18    tgid:18    ppid:2      task_flags:0x208040 flags:0x00080000
[ 4904.531461][   T32] Call Trace:
[ 4904.531896][   T32]  <TASK>
[ 4904.532406][   T32]  __schedule (kernel/sched/core.c:5259)
[ 4904.532947][   T32]  schedule (arch/x86/include/asm/preempt.h:85 kernel/sched/core.c:6946 kernel/sched/core.c:6960)
[ 4904.533381][   T32]  kprobe_optimizer_thread (kernel/kprobes.c:656)
[ 4904.533944][   T32]  ? __pfx_autoremove_wake_function (kernel/sched/wait.c:402)
[ 4904.534547][   T32]  kthread (kernel/kthread.c:465)
[ 4904.534985][   T32]  ? __pfx_kprobe_optimizer_thread (kernel/kprobes.c:654)
[ 4904.535670][   T32]  ? __pfx_kthread (kernel/kthread.c:412)
[ 4904.536359][   T32]  ret_from_fork (arch/x86/kernel/process.c:164)
[ 4904.536831][   T32]  ? __pfx_kthread (kernel/kthread.c:412)
[ 4904.537310][   T32]  ret_from_fork_asm (arch/x86/entry/entry_64.S:256)
[ 4904.537788][   T32]  </TASK>
[ 5396.039936][   T32] INFO: task kprobe-optimize:18 blocked for more than 4915 seconds.
[ 5396.040939][   T32]       Not tainted 6.19.0-rc5-00040-g62f65c2531ad #1
[ 5396.041631][   T32] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 5396.042742][   T32] task:kprobe-optimize state:D stack:0     pid:18    tgid:18    ppid:2      task_flags:0x208040 flags:0x00080000
[ 5396.045182][   T32] Call Trace:
[ 5396.045723][   T32]  <TASK>
[ 5396.046266][   T32]  __schedule (kernel/sched/core.c:5259)
[ 5396.046928][   T32]  schedule (arch/x86/include/asm/preempt.h:85 kernel/sched/core.c:6946 kernel/sched/core.c:6960)
[ 5396.047542][   T32]  kprobe_optimizer_thread (kernel/kprobes.c:656)
[ 5396.048329][   T32]  ? __pfx_autoremove_wake_function (kernel/sched/wait.c:402)
[ 5396.049182][   T32]  kthread (kernel/kthread.c:465)
[ 5396.049803][   T32]  ? __pfx_kprobe_optimizer_thread (kernel/kprobes.c:654)
[ 5396.050654][   T32]  ? __pfx_kthread (kernel/kthread.c:412)
[ 5396.051353][   T32]  ret_from_fork (arch/x86/kernel/process.c:164)
[ 5396.052048][   T32]  ? __pfx_kthread (kernel/kthread.c:412)
[ 5396.052723][   T32]  ret_from_fork_asm (arch/x86/entry/entry_64.S:256)
[ 5396.053187][   T32]  </TASK>
[ 5396.053524][   T32] Future hung task reports are suppressed, see sysctl kernel.hung_task_warnings
BUG: kernel hang in test stage



The kernel config and materials to reproduce are available at:
https://download.01.org/0day-ci/archive/20260119/202601191507.74fccd0c-lkp@intel.com



-- 
0-DAY CI Kernel Test Service
https://github.com/intel/lkp-tests/wiki
Re: [PATCH v2] kprobes: Use dedicated kthread for kprobe optimizer
Posted by Masami Hiramatsu (Google) 2 weeks, 3 days ago
On Mon, 19 Jan 2026 15:29:58 +0800
kernel test robot <oliver.sang@intel.com> wrote:

> 
> 
> Hello,
> 
> kernel test robot noticed "INFO:task_blocked_for_more_than#seconds" on:

OOps, yes. It should be wait in interruptible.

Thanks,

> 
> commit: 62f65c2531ad66e84c1a5ef91389322357ef6db4 ("[PATCH v2] kprobes: Use dedicated kthread for kprobe optimizer")
> url: https://github.com/intel-lab-lkp/linux/commits/Masami-Hiramatsu-Google/kprobes-Use-dedicated-kthread-for-kprobe-optimizer/20260113-094928
> base: https://git.kernel.org/cgit/linux/kernel/git/trace/linux-trace for-next
> patch link: https://lore.kernel.org/all/176826884613.429923.16578111751623731056.stgit@devnote2/
> patch subject: [PATCH v2] kprobes: Use dedicated kthread for kprobe optimizer
> 
> in testcase: trinity
> version: trinity-x86_64-294c4652-1_20251011
> with following parameters:
> 
> 	runtime: 300s
> 	group: group-03
> 	nr_groups: 5
> 
> 
> 
> config: x86_64-kexec
> compiler: clang-20
> test machine: qemu-system-x86_64 -enable-kvm -cpu SandyBridge -smp 2 -m 32G
> 
> (please refer to attached dmesg/kmsg for entire log/backtrace)
> 
> 
> +-----------------------------------------+------------+------------+
> |                                         | 78a419b44e | 62f65c2531 |
> +-----------------------------------------+------------+------------+
> | INFO:task_blocked_for_more_than#seconds | 0          | 6          |
> +-----------------------------------------+------------+------------+
> 
> 
> If you fix the issue in a separate patch/commit (i.e. not just a new version of
> the same patch/commit), kindly add following tags
> | Reported-by: kernel test robot <oliver.sang@intel.com>
> | Closes: https://lore.kernel.org/oe-lkp/202601191507.74fccd0c-lkp@intel.com
> 
> 
> 
> [  972.359932][   T32] INFO: task kprobe-optimize:18 blocked for more than 491 seconds.
> [  972.361221][   T32]       Not tainted 6.19.0-rc5-00040-g62f65c2531ad #1
> [  972.362516][   T32] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [  972.364322][   T32] task:kprobe-optimize state:D stack:0     pid:18    tgid:18    ppid:2      task_flags:0x208040 flags:0x00080000
> [  972.366628][   T32] Call Trace:
> [  972.367378][   T32]  <TASK>
> [  972.368066][   T32]  __schedule (kernel/sched/core.c:5259)
> [  972.370837][   T32]  schedule (arch/x86/include/asm/preempt.h:85 kernel/sched/core.c:6946 kernel/sched/core.c:6960)
> [  972.371679][   T32]  kprobe_optimizer_thread (kernel/kprobes.c:656)
> [  972.373219][   T32]  ? __pfx_autoremove_wake_function (kernel/sched/wait.c:402)
> [  972.374017][   T32]  kthread (kernel/kthread.c:465)
> [  972.374573][   T32]  ? __pfx_kprobe_optimizer_thread (kernel/kprobes.c:654)
> [  972.375364][   T32]  ? __pfx_kthread (kernel/kthread.c:412)
> [  972.376005][   T32]  ret_from_fork (arch/x86/kernel/process.c:164)
> [  972.376679][   T32]  ? __pfx_kthread (kernel/kthread.c:412)
> [  972.377305][   T32]  ret_from_fork_asm (arch/x86/entry/entry_64.S:256)
> [  972.377958][   T32]  </TASK>
> [ 1463.879952][   T32] INFO: task kprobe-optimize:18 blocked for more than 983 seconds.
> [ 1463.882239][   T32]       Not tainted 6.19.0-rc5-00040-g62f65c2531ad #1
> [ 1463.884371][   T32] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [ 1463.887443][   T32] task:kprobe-optimize state:D stack:0     pid:18    tgid:18    ppid:2      task_flags:0x208040 flags:0x00080000
> [ 1463.891867][   T32] Call Trace:
> [ 1463.893396][   T32]  <TASK>
> [ 1463.894468][   T32]  __schedule (kernel/sched/core.c:5259)
> [ 1463.903984][   T32]  schedule (arch/x86/include/asm/preempt.h:85 kernel/sched/core.c:6946 kernel/sched/core.c:6960)
> [ 1463.904926][   T32]  kprobe_optimizer_thread (kernel/kprobes.c:656)
> [ 1463.905949][   T32]  ? __pfx_autoremove_wake_function (kernel/sched/wait.c:402)
> [ 1463.907111][   T32]  kthread (kernel/kthread.c:465)
> [ 1463.907954][   T32]  ? __pfx_kprobe_optimizer_thread (kernel/kprobes.c:654)
> [ 1463.909157][   T32]  ? __pfx_kthread (kernel/kthread.c:412)
> [ 1463.910045][   T32]  ret_from_fork (arch/x86/kernel/process.c:164)
> [ 1463.910939][   T32]  ? __pfx_kthread (kernel/kthread.c:412)
> [ 1463.911933][   T32]  ret_from_fork_asm (arch/x86/entry/entry_64.S:256)
> [ 1463.912947][   T32]  </TASK>
> [ 1955.399991][   T32] INFO: task kprobe-optimize:18 blocked for more than 1474 seconds.
> [ 1955.404266][   T32]       Not tainted 6.19.0-rc5-00040-g62f65c2531ad #1
> [ 1955.407452][   T32] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [ 1955.414557][   T32] task:kprobe-optimize state:D stack:0     pid:18    tgid:18    ppid:2      task_flags:0x208040 flags:0x00080000
> [ 1955.416961][   T32] Call Trace:
> [ 1955.417705][   T32]  <TASK>
> [ 1955.418382][   T32]  __schedule (kernel/sched/core.c:5259)
> [ 1955.419274][   T32]  schedule (arch/x86/include/asm/preempt.h:85 kernel/sched/core.c:6946 kernel/sched/core.c:6960)
> [ 1955.419929][   T32]  kprobe_optimizer_thread (kernel/kprobes.c:656)
> [ 1955.421071][   T32]  ? __pfx_autoremove_wake_function (kernel/sched/wait.c:402)
> [ 1955.422303][   T32]  kthread (kernel/kthread.c:465)
> [ 1955.423217][   T32]  ? __pfx_kprobe_optimizer_thread (kernel/kprobes.c:654)
> [ 1955.424452][   T32]  ? __pfx_kthread (kernel/kthread.c:412)
> [ 1955.425189][   T32]  ret_from_fork (arch/x86/kernel/process.c:164)
> [ 1955.425913][   T32]  ? __pfx_kthread (kernel/kthread.c:412)
> [ 1955.426645][   T32]  ret_from_fork_asm (arch/x86/entry/entry_64.S:256)
> [ 1955.427357][   T32]  </TASK>
> [ 2446.919964][   T32] INFO: task kprobe-optimize:18 blocked for more than 1966 seconds.
> [ 2446.922105][   T32]       Not tainted 6.19.0-rc5-00040-g62f65c2531ad #1
> [ 2446.925697][   T32] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [ 2446.926569][   T32] task:kprobe-optimize state:D stack:0     pid:18    tgid:18    ppid:2      task_flags:0x208040 flags:0x00080000
> [ 2446.927775][   T32] Call Trace:
> [ 2446.928242][   T32]  <TASK>
> [ 2446.928609][   T32]  __schedule (kernel/sched/core.c:5259)
> [ 2446.929827][   T32]  schedule (arch/x86/include/asm/preempt.h:85 kernel/sched/core.c:6946 kernel/sched/core.c:6960)
> [ 2446.930256][   T32]  kprobe_optimizer_thread (kernel/kprobes.c:656)
> [ 2446.930789][   T32]  ? __pfx_autoremove_wake_function (kernel/sched/wait.c:402)
> [ 2446.931434][   T32]  kthread (kernel/kthread.c:465)
> [ 2446.931926][   T32]  ? __pfx_kprobe_optimizer_thread (kernel/kprobes.c:654)
> [ 2446.932624][   T32]  ? __pfx_kthread (kernel/kthread.c:412)
> [ 2446.933079][   T32]  ret_from_fork (arch/x86/kernel/process.c:164)
> [ 2446.933534][   T32]  ? __pfx_kthread (kernel/kthread.c:412)
> [ 2446.933983][   T32]  ret_from_fork_asm (arch/x86/entry/entry_64.S:256)
> [ 2446.934450][   T32]  </TASK>
> [ 2938.439916][   T32] INFO: task kprobe-optimize:18 blocked for more than 2457 seconds.
> [ 2938.441278][   T32]       Not tainted 6.19.0-rc5-00040-g62f65c2531ad #1
> [ 2938.442281][   T32] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [ 2938.444599][   T32] task:kprobe-optimize state:D stack:0     pid:18    tgid:18    ppid:2      task_flags:0x208040 flags:0x00080000
> [ 2938.446316][   T32] Call Trace:
> [ 2938.446892][   T32]  <TASK>
> [ 2938.447449][   T32]  __schedule (kernel/sched/core.c:5259)
> [ 2938.449286][   T32]  schedule (arch/x86/include/asm/preempt.h:85 kernel/sched/core.c:6946 kernel/sched/core.c:6960)
> [ 2938.450230][   T32]  kprobe_optimizer_thread (kernel/kprobes.c:656)
> [ 2938.451347][   T32]  ? __pfx_autoremove_wake_function (kernel/sched/wait.c:402)
> [ 2938.452611][   T32]  kthread (kernel/kthread.c:465)
> [ 2938.453462][   T32]  ? __pfx_kprobe_optimizer_thread (kernel/kprobes.c:654)
> [ 2938.454622][   T32]  ? __pfx_kthread (kernel/kthread.c:412)
> [ 2938.455583][   T32]  ret_from_fork (arch/x86/kernel/process.c:164)
> [ 2938.456604][   T32]  ? __pfx_kthread (kernel/kthread.c:412)
> [ 2938.457614][   T32]  ret_from_fork_asm (arch/x86/entry/entry_64.S:256)
> [ 2938.458645][   T32]  </TASK>
> [ 3429.960057][   T32] INFO: task kprobe-optimize:18 blocked for more than 2949 seconds.
> [ 3429.962853][   T32]       Not tainted 6.19.0-rc5-00040-g62f65c2531ad #1
> [ 3429.965133][   T32] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [ 3429.967986][   T32] task:kprobe-optimize state:D stack:0     pid:18    tgid:18    ppid:2      task_flags:0x208040 flags:0x00080000
> [ 3429.971731][   T32] Call Trace:
> [ 3429.973021][   T32]  <TASK>
> [ 3429.974169][   T32]  __schedule (kernel/sched/core.c:5259)
> [ 3429.975713][   T32]  schedule (arch/x86/include/asm/preempt.h:85 kernel/sched/core.c:6946 kernel/sched/core.c:6960)
> [ 3429.977206][   T32]  kprobe_optimizer_thread (kernel/kprobes.c:656)
> [ 3429.978375][   T32]  ? __pfx_autoremove_wake_function (kernel/sched/wait.c:402)
> [ 3429.979623][   T32]  kthread (kernel/kthread.c:465)
> [ 3429.980602][   T32]  ? __pfx_kprobe_optimizer_thread (kernel/kprobes.c:654)
> [ 3429.981810][   T32]  ? __pfx_kthread (kernel/kthread.c:412)
> [ 3429.982797][   T32]  ret_from_fork (arch/x86/kernel/process.c:164)
> [ 3429.983793][   T32]  ? __pfx_kthread (kernel/kthread.c:412)
> [ 3429.984838][   T32]  ret_from_fork_asm (arch/x86/entry/entry_64.S:256)
> [ 3429.985864][   T32]  </TASK>
> [ 3921.480064][   T32] INFO: task kprobe-optimize:18 blocked for more than 3440 seconds.
> [ 3921.482942][   T32]       Not tainted 6.19.0-rc5-00040-g62f65c2531ad #1
> [ 3921.485260][   T32] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [ 3921.488269][   T32] task:kprobe-optimize state:D stack:0     pid:18    tgid:18    ppid:2      task_flags:0x208040 flags:0x00080000
> [ 3921.491811][   T32] Call Trace:
> [ 3921.493488][   T32]  <TASK>
> [ 3921.494960][   T32]  __schedule (kernel/sched/core.c:5259)
> [ 3921.508616][   T32]  schedule (arch/x86/include/asm/preempt.h:85 kernel/sched/core.c:6946 kernel/sched/core.c:6960)
> [ 3921.509430][   T32]  kprobe_optimizer_thread (kernel/kprobes.c:656)
> [ 3921.510413][   T32]  ? __pfx_autoremove_wake_function (kernel/sched/wait.c:402)
> [ 3921.511467][   T32]  kthread (kernel/kthread.c:465)
> [ 3921.512331][   T32]  ? __pfx_kprobe_optimizer_thread (kernel/kprobes.c:654)
> [ 3921.513388][   T32]  ? __pfx_kthread (kernel/kthread.c:412)
> [ 3921.514202][   T32]  ret_from_fork (arch/x86/kernel/process.c:164)
> [ 3921.514976][   T32]  ? __pfx_kthread (kernel/kthread.c:412)
> [ 3921.515773][   T32]  ret_from_fork_asm (arch/x86/entry/entry_64.S:256)
> [ 3921.516817][   T32]  </TASK>
> [ 4413.000017][   T32] INFO: task kprobe-optimize:18 blocked for more than 3932 seconds.
> [ 4413.004653][   T32]       Not tainted 6.19.0-rc5-00040-g62f65c2531ad #1
> [ 4413.007745][   T32] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [ 4413.010446][   T32] task:kprobe-optimize state:D stack:0     pid:18    tgid:18    ppid:2      task_flags:0x208040 flags:0x00080000
> [ 4413.013906][   T32] Call Trace:
> [ 4413.015027][   T32]  <TASK>
> [ 4413.016134][   T32]  __schedule (kernel/sched/core.c:5259)
> [ 4413.017465][   T32]  schedule (arch/x86/include/asm/preempt.h:85 kernel/sched/core.c:6946 kernel/sched/core.c:6960)
> [ 4413.018294][   T32]  kprobe_optimizer_thread (kernel/kprobes.c:656)
> [ 4413.019366][   T32]  ? __pfx_autoremove_wake_function (kernel/sched/wait.c:402)
> [ 4413.020594][   T32]  kthread (kernel/kthread.c:465)
> [ 4413.021350][   T32]  ? __pfx_kprobe_optimizer_thread (kernel/kprobes.c:654)
> [ 4413.022331][   T32]  ? __pfx_kthread (kernel/kthread.c:412)
> [ 4413.023124][   T32]  ret_from_fork (arch/x86/kernel/process.c:164)
> [ 4413.023925][   T32]  ? __pfx_kthread (kernel/kthread.c:412)
> [ 4413.025015][   T32]  ret_from_fork_asm (arch/x86/entry/entry_64.S:256)
> [ 4413.026074][   T32]  </TASK>
> [ 4904.520028][   T32] INFO: task kprobe-optimize:18 blocked for more than 4423 seconds.
> [ 4904.521949][   T32]       Not tainted 6.19.0-rc5-00040-g62f65c2531ad #1
> [ 4904.528612][   T32] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [ 4904.529924][   T32] task:kprobe-optimize state:D stack:0     pid:18    tgid:18    ppid:2      task_flags:0x208040 flags:0x00080000
> [ 4904.531461][   T32] Call Trace:
> [ 4904.531896][   T32]  <TASK>
> [ 4904.532406][   T32]  __schedule (kernel/sched/core.c:5259)
> [ 4904.532947][   T32]  schedule (arch/x86/include/asm/preempt.h:85 kernel/sched/core.c:6946 kernel/sched/core.c:6960)
> [ 4904.533381][   T32]  kprobe_optimizer_thread (kernel/kprobes.c:656)
> [ 4904.533944][   T32]  ? __pfx_autoremove_wake_function (kernel/sched/wait.c:402)
> [ 4904.534547][   T32]  kthread (kernel/kthread.c:465)
> [ 4904.534985][   T32]  ? __pfx_kprobe_optimizer_thread (kernel/kprobes.c:654)
> [ 4904.535670][   T32]  ? __pfx_kthread (kernel/kthread.c:412)
> [ 4904.536359][   T32]  ret_from_fork (arch/x86/kernel/process.c:164)
> [ 4904.536831][   T32]  ? __pfx_kthread (kernel/kthread.c:412)
> [ 4904.537310][   T32]  ret_from_fork_asm (arch/x86/entry/entry_64.S:256)
> [ 4904.537788][   T32]  </TASK>
> [ 5396.039936][   T32] INFO: task kprobe-optimize:18 blocked for more than 4915 seconds.
> [ 5396.040939][   T32]       Not tainted 6.19.0-rc5-00040-g62f65c2531ad #1
> [ 5396.041631][   T32] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [ 5396.042742][   T32] task:kprobe-optimize state:D stack:0     pid:18    tgid:18    ppid:2      task_flags:0x208040 flags:0x00080000
> [ 5396.045182][   T32] Call Trace:
> [ 5396.045723][   T32]  <TASK>
> [ 5396.046266][   T32]  __schedule (kernel/sched/core.c:5259)
> [ 5396.046928][   T32]  schedule (arch/x86/include/asm/preempt.h:85 kernel/sched/core.c:6946 kernel/sched/core.c:6960)
> [ 5396.047542][   T32]  kprobe_optimizer_thread (kernel/kprobes.c:656)
> [ 5396.048329][   T32]  ? __pfx_autoremove_wake_function (kernel/sched/wait.c:402)
> [ 5396.049182][   T32]  kthread (kernel/kthread.c:465)
> [ 5396.049803][   T32]  ? __pfx_kprobe_optimizer_thread (kernel/kprobes.c:654)
> [ 5396.050654][   T32]  ? __pfx_kthread (kernel/kthread.c:412)
> [ 5396.051353][   T32]  ret_from_fork (arch/x86/kernel/process.c:164)
> [ 5396.052048][   T32]  ? __pfx_kthread (kernel/kthread.c:412)
> [ 5396.052723][   T32]  ret_from_fork_asm (arch/x86/entry/entry_64.S:256)
> [ 5396.053187][   T32]  </TASK>
> [ 5396.053524][   T32] Future hung task reports are suppressed, see sysctl kernel.hung_task_warnings
> BUG: kernel hang in test stage
> 
> 
> 
> The kernel config and materials to reproduce are available at:
> https://download.01.org/0day-ci/archive/20260119/202601191507.74fccd0c-lkp@intel.com
> 
> 
> 
> -- 
> 0-DAY CI Kernel Test Service
> https://github.com/intel/lkp-tests/wiki
> 


-- 
Masami Hiramatsu (Google) <mhiramat@kernel.org>