[PATCH] irq_work: Add event-tracing points for irq_work

[PATCH] irq_work: Add event-tracing points for irq_work

[Zqiang]

Add irq_work_queue_on tracepoints allow tracing when and how
a irq-work is queued, irq_work_execute_start/end tracepoints
allow know when a irq-work is executed and the executed time.

Signed-off-by: Zqiang <qiang1.zhang@intel.com>
---
 include/trace/events/irq_work.h | 79 +++++++++++++++++++++++++++++++++
 kernel/irq_work.c               |  9 +++-
 2 files changed, 87 insertions(+), 1 deletion(-)
 create mode 100644 include/trace/events/irq_work.h

diff --git a/include/trace/events/irq_work.h b/include/trace/events/irq_work.h
new file mode 100644
index 000000000000..823cb48666c4
--- /dev/null
+++ b/include/trace/events/irq_work.h
@@ -0,0 +1,79 @@
+/* SPDX-License-Identifier: GPL-2.0 */
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM irq_work
+
+#if !defined(_TRACE_IRQ_WORK_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_IRQ_WORK_H
+
+#include <linux/tracepoint.h>
+#include <linux/irq_work.h>
+
+TRACE_EVENT(irq_work_queue_on,
+
+	TP_PROTO(unsigned int req_cpu, struct irq_work *work),
+
+	TP_ARGS(req_cpu, work),
+
+	TP_STRUCT__entry(
+		__field( void *,	work	)
+		__field( void *,	function)
+		__field( unsigned int,	req_cpu	)
+		__field( int,		flags	)
+	),
+
+	TP_fast_assign(
+		__entry->work		= work;
+		__entry->function	= work->func;
+		__entry->req_cpu	= req_cpu;
+		__entry->flags		= atomic_read(&work->node.a_flags);
+	),
+
+	TP_printk("irq_work=%p func=%ps req_cpu=%u flags=%x",
+			__entry->work, __entry->function, __entry->req_cpu, __entry->flags)
+);
+
+TRACE_EVENT(irq_work_execute_start,
+
+	TP_PROTO(struct irq_work *work),
+
+	TP_ARGS(work),
+
+	TP_STRUCT__entry(
+		__field( void *,	work	)
+		__field( void *,	function)
+		__field( int,		flags	)
+	),
+
+	TP_fast_assign(
+		__entry->work		= work;
+		__entry->function	= work->func;
+		__entry->flags		= atomic_read(&work->node.a_flags);
+	),
+
+	TP_printk("irq_work=%p: func=%ps flags=%x",
+			__entry->work, __entry->function,  __entry->flags)
+);
+
+TRACE_EVENT(irq_work_execute_end,
+
+	TP_PROTO(struct irq_work *work),
+
+	TP_ARGS(work),
+
+	TP_STRUCT__entry(
+		__field( void *,	work	)
+		__field( void *,	function)
+		__field( int,		flags	)
+	),
+
+	TP_fast_assign(
+		__entry->work		= work;
+		__entry->function	= work->func;
+		__entry->flags		= atomic_read(&work->node.a_flags);
+	),
+
+	TP_printk("irq_work=%p: func=%ps flags=%x",
+			__entry->work, __entry->function, __entry->flags)
+);
+#endif
+#include <trace/define_trace.h>
diff --git a/kernel/irq_work.c b/kernel/irq_work.c
index 7afa40fe5cc4..edad992556d0 100644
--- a/kernel/irq_work.c
+++ b/kernel/irq_work.c
@@ -22,6 +22,9 @@
 #include <asm/processor.h>
 #include <linux/kasan.h>
 
+#define CREATE_TRACE_POINTS
+#include <trace/events/irq_work.h>
+
 static DEFINE_PER_CPU(struct llist_head, raised_list);
 static DEFINE_PER_CPU(struct llist_head, lazy_list);
 static DEFINE_PER_CPU(struct task_struct *, irq_workd);
@@ -81,7 +84,9 @@ static void __irq_work_queue_local(struct irq_work *work)
 	bool rt_lazy_work = false;
 	bool lazy_work = false;
 	int work_flags;
+	int cpu = smp_processor_id();
 
+	trace_irq_work_queue_on(cpu, work);
 	work_flags = atomic_read(&work->node.a_flags);
 	if (work_flags & IRQ_WORK_LAZY)
 		lazy_work = true;
@@ -143,7 +148,7 @@ bool irq_work_queue_on(struct irq_work *work, int cpu)
 	if (cpu != smp_processor_id()) {
 		/* Arch remote IPI send/receive backend aren't NMI safe */
 		WARN_ON_ONCE(in_nmi());
-
+		trace_irq_work_queue_on(cpu, work);
 		/*
 		 * On PREEMPT_RT the items which are not marked as
 		 * IRQ_WORK_HARD_IRQ are added to the lazy list and a HARD work
@@ -208,7 +213,9 @@ void irq_work_single(void *arg)
 	smp_mb();
 
 	lockdep_irq_work_enter(flags);
+	trace_irq_work_execute_start(work);
 	work->func(work);
+	trace_irq_work_execute_end(work);
 	lockdep_irq_work_exit(flags);
 
 	/*
-- 
2.25.1

Re: [PATCH] irq_work: Add event-tracing points for irq_work

[Peter Zijlstra]

On Thu, Apr 14, 2022 at 02:38:29PM +0800, Zqiang wrote:
> Add irq_work_queue_on tracepoints allow tracing when and how
> a irq-work is queued, irq_work_execute_start/end tracepoints
> allow know when a irq-work is executed and the executed time.

Yeah, but why?

> diff --git a/kernel/irq_work.c b/kernel/irq_work.c
> index 7afa40fe5cc4..edad992556d0 100644
> --- a/kernel/irq_work.c
> +++ b/kernel/irq_work.c
> @@ -22,6 +22,9 @@
>  #include <asm/processor.h>
>  #include <linux/kasan.h>
>  
> +#define CREATE_TRACE_POINTS
> +#include <trace/events/irq_work.h>
> +
>  static DEFINE_PER_CPU(struct llist_head, raised_list);
>  static DEFINE_PER_CPU(struct llist_head, lazy_list);
>  static DEFINE_PER_CPU(struct task_struct *, irq_workd);
> @@ -81,7 +84,9 @@ static void __irq_work_queue_local(struct irq_work *work)
>  	bool rt_lazy_work = false;
>  	bool lazy_work = false;
>  	int work_flags;
> +	int cpu = smp_processor_id();
>  
> +	trace_irq_work_queue_on(cpu, work);

That's not very nice, you made this function more expensive for no
reason. And you violated coding style while doing it :/

>  	work_flags = atomic_read(&work->node.a_flags);
>  	if (work_flags & IRQ_WORK_LAZY)
>  		lazy_work = true;
> @@ -143,7 +148,7 @@ bool irq_work_queue_on(struct irq_work *work, int cpu)
>  	if (cpu != smp_processor_id()) {
>  		/* Arch remote IPI send/receive backend aren't NMI safe */
>  		WARN_ON_ONCE(in_nmi());
> -
> +		trace_irq_work_queue_on(cpu, work);
>  		/*
>  		 * On PREEMPT_RT the items which are not marked as
>  		 * IRQ_WORK_HARD_IRQ are added to the lazy list and a HARD work
> @@ -208,7 +213,9 @@ void irq_work_single(void *arg)
>  	smp_mb();
>  
>  	lockdep_irq_work_enter(flags);
> +	trace_irq_work_execute_start(work);
>  	work->func(work);
> +	trace_irq_work_execute_end(work);
>  	lockdep_irq_work_exit(flags);
>  
>  	/*

Re: [PATCH] irq_work: Add event-tracing points for irq_work

[Thomas Gleixner]

On Thu, Apr 14 2022 at 14:38, Zqiang wrote:
> +#define CREATE_TRACE_POINTS
> +#include <trace/events/irq_work.h>
> +
>  static DEFINE_PER_CPU(struct llist_head, raised_list);
>  static DEFINE_PER_CPU(struct llist_head, lazy_list);
>  static DEFINE_PER_CPU(struct task_struct *, irq_workd);
> @@ -81,7 +84,9 @@ static void __irq_work_queue_local(struct irq_work *work)
>  	bool rt_lazy_work = false;
>  	bool lazy_work = false;
>  	int work_flags;
> +	int cpu = smp_processor_id();
>  
> +	trace_irq_work_queue_on(cpu, work);

What about work_flags to see on which list this ends up?

Thanks,

        tglx

RE: [PATCH] irq_work: Add event-tracing points for irq_work

[Zhang, Qiang1]

On Thu, Apr 14, 2022 at 02:38:29PM +0800, Zqiang wrote:
> Add irq_work_queue_on tracepoints allow tracing when and how a 
> irq-work is queued, irq_work_execute_start/end tracepoints allow know 
> when a irq-work is executed and the executed time.

Yeah, but why?	

Tracing stacktrace help find where a irq-work is queued, and view whether a irq-work
be executed  in irq context or task context,  if in task context, is it because there are lots of
lazy irq-works executed in irq_work rt kthreads,  cause other fair task can not get CPU, 
for example, there is a problem in RCU which I find in testing
Enable RCU_STRICT_GRACE_PERIOD in preempt-rt, the system booting occur hang, 
through add irq-work tracepoints find a lot of irq-work (rcu_preempt_deferred_qs_handler)
be executed in rt-fifo irq_work kthreads,  init kthreads  unable to obtain CPUs, cause hang.

 
> diff --git a/kernel/irq_work.c b/kernel/irq_work.c index 
> 7afa40fe5cc4..edad992556d0 100644
> --- a/kernel/irq_work.c
> +++ b/kernel/irq_work.c
> @@ -22,6 +22,9 @@
>  #include <asm/processor.h>
>  #include <linux/kasan.h>
>  
> +#define CREATE_TRACE_POINTS
> +#include <trace/events/irq_work.h>
> +
>  static DEFINE_PER_CPU(struct llist_head, raised_list);  static 
> DEFINE_PER_CPU(struct llist_head, lazy_list);  static 
> DEFINE_PER_CPU(struct task_struct *, irq_workd); @@ -81,7 +84,9 @@ 
> static void __irq_work_queue_local(struct irq_work *work)
>  	bool rt_lazy_work = false;
>  	bool lazy_work = false;
>  	int work_flags;
> +	int cpu = smp_processor_id();
>  
> +	trace_irq_work_queue_on(cpu, work);

That's not very nice, you made this function more expensive for no reason. And you violated coding style while doing it :/

You mean the trace_irq_work_queue_on() tracepoints should not be added in this place ? or
replace this tracepoint with  trace_irq_work_queue_on(raw_smp_processor_id(), work) ?

Thanks,
Zqiang

>  	work_flags = atomic_read(&work->node.a_flags);
>  	if (work_flags & IRQ_WORK_LAZY)
>  		lazy_work = true;
> @@ -143,7 +148,7 @@ bool irq_work_queue_on(struct irq_work *work, int cpu)
>  	if (cpu != smp_processor_id()) {
>  		/* Arch remote IPI send/receive backend aren't NMI safe */
>  		WARN_ON_ONCE(in_nmi());
> -
> +		trace_irq_work_queue_on(cpu, work);
>  		/*
>  		 * On PREEMPT_RT the items which are not marked as
>  		 * IRQ_WORK_HARD_IRQ are added to the lazy list and a HARD work @@ 
> -208,7 +213,9 @@ void irq_work_single(void *arg)
>  	smp_mb();
>  
>  	lockdep_irq_work_enter(flags);
> +	trace_irq_work_execute_start(work);
>  	work->func(work);
> +	trace_irq_work_execute_end(work);
>  	lockdep_irq_work_exit(flags);
>  
>  	/*

RE: [PATCH] irq_work: Add event-tracing points for irq_work

[Zhang, Qiang1]

On Thu, Apr 14 2022 at 14:38, Zqiang wrote:
> +#define CREATE_TRACE_POINTS
> +#include <trace/events/irq_work.h>
> +
>  static DEFINE_PER_CPU(struct llist_head, raised_list);  static 
> DEFINE_PER_CPU(struct llist_head, lazy_list);  static 
> DEFINE_PER_CPU(struct task_struct *, irq_workd); @@ -81,7 +84,9 @@ 
> static void __irq_work_queue_local(struct irq_work *work)
>  	bool rt_lazy_work = false;
>  	bool lazy_work = false;
>  	int work_flags;
> +	int cpu = smp_processor_id();
>  
> +	trace_irq_work_queue_on(cpu, work);

>What about work_flags to see on which list this ends up?

The tracepoint have been record 'work->node.a_flags'  through check it to sure 
this irq-wrok is queued on which list

Thanks
Zqiang

>Thanks,
>
>        tglx