Currently, hardirq tracing log in riscv showing the last {enabled,disabled}
at __trace_hardirqs_{on,off} all the time.
We can use trace_hardirqs_on_caller to display the caller we really want
to see.
Yipeng Zou (2):
tracing: hold caller_addr to hardirq_{enable,disable}_ip
riscv: tracing: Improve hardirq tracing message
arch/riscv/kernel/trace_irq.c | 4 ++--
include/linux/irqflags.h | 2 ++
kernel/trace/trace_preemptirq.c | 4 ++--
3 files changed, 6 insertions(+), 4 deletions(-)
--
2.17.1
Use trace_hardirqs_on_caller to improve irq_tracing message.
lockdep log in riscv showing the last {enabled,disabled} at
__trace_hardirqs_{on,off} all the time(if called by).
But that's not what we want to see, the caller is what we want.
Before this commit:
[ 57.853175] hardirqs last enabled at (2519): __trace_hardirqs_on+0xc/0x14
[ 57.853848] hardirqs last disabled at (2520): __trace_hardirqs_off+0xc/0x14
After this commit
[ 53.781428] hardirqs last enabled at (2595): restore_all+0xe/0x66
[ 53.782185] hardirqs last disabled at (2596): ret_from_exception+0xa/0x10
Signed-off-by: Yipeng Zou <[email protected]>
---
arch/riscv/kernel/trace_irq.c | 4 ++--
include/linux/irqflags.h | 2 ++
2 files changed, 4 insertions(+), 2 deletions(-)
diff --git a/arch/riscv/kernel/trace_irq.c b/arch/riscv/kernel/trace_irq.c
index 095ac976d7da..7ca24b26e19f 100644
--- a/arch/riscv/kernel/trace_irq.c
+++ b/arch/riscv/kernel/trace_irq.c
@@ -16,12 +16,12 @@
void __trace_hardirqs_on(void)
{
- trace_hardirqs_on();
+ trace_hardirqs_on_caller(CALLER_ADDR0);
}
NOKPROBE_SYMBOL(__trace_hardirqs_on);
void __trace_hardirqs_off(void)
{
- trace_hardirqs_off();
+ trace_hardirqs_off_caller(CALLER_ADDR0);
}
NOKPROBE_SYMBOL(__trace_hardirqs_off);
diff --git a/include/linux/irqflags.h b/include/linux/irqflags.h
index 5ec0fa71399e..46774fa85cde 100644
--- a/include/linux/irqflags.h
+++ b/include/linux/irqflags.h
@@ -53,6 +53,8 @@ extern void trace_hardirqs_on_prepare(void);
extern void trace_hardirqs_off_finish(void);
extern void trace_hardirqs_on(void);
extern void trace_hardirqs_off(void);
+extern void trace_hardirqs_on_caller(unsigned long caller_addr);
+extern void trace_hardirqs_off_caller(unsigned long caller_addr);
# define lockdep_hardirq_context() (raw_cpu_read(hardirq_context))
# define lockdep_softirq_context(p) ((p)->softirq_context)
--
2.17.1
Currently, The arguments passing to lockdep_hardirqs_{on,off} was fixed
in CALLER_ADDR0.
The function trace_hardirqs_on_caller should have been intended to use
caller_addr to represent the address that caller wants to be traced.
For example, lockdep log in riscv showing the last {enabled,disabled} at
__trace_hardirqs_{on,off} all the time(if called by):
[ 57.853175] hardirqs last enabled at (2519): __trace_hardirqs_on+0xc/0x14
[ 57.853848] hardirqs last disabled at (2520): __trace_hardirqs_off+0xc/0x14
After use trace_hardirqs_xx_caller, we can get more effective information:
[ 53.781428] hardirqs last enabled at (2595): restore_all+0xe/0x66
[ 53.782185] hardirqs last disabled at (2596): ret_from_exception+0xa/0x10
Signed-off-by: Yipeng Zou <[email protected]>
---
kernel/trace/trace_preemptirq.c | 4 ++--
1 file changed, 2 insertions(+), 2 deletions(-)
diff --git a/kernel/trace/trace_preemptirq.c b/kernel/trace/trace_preemptirq.c
index 95b58bd757ce..1e130da1b742 100644
--- a/kernel/trace/trace_preemptirq.c
+++ b/kernel/trace/trace_preemptirq.c
@@ -95,14 +95,14 @@ __visible void trace_hardirqs_on_caller(unsigned long caller_addr)
}
lockdep_hardirqs_on_prepare();
- lockdep_hardirqs_on(CALLER_ADDR0);
+ lockdep_hardirqs_on(caller_addr);
}
EXPORT_SYMBOL(trace_hardirqs_on_caller);
NOKPROBE_SYMBOL(trace_hardirqs_on_caller);
__visible void trace_hardirqs_off_caller(unsigned long caller_addr)
{
- lockdep_hardirqs_off(CALLER_ADDR0);
+ lockdep_hardirqs_off(caller_addr);
if (!this_cpu_read(tracing_irq_cpu)) {
this_cpu_write(tracing_irq_cpu, 1);
--
2.17.1
On Thu, 1 Sep 2022 18:45:14 +0800
Yipeng Zou <[email protected]> wrote:
> Currently, The arguments passing to lockdep_hardirqs_{on,off} was fixed
> in CALLER_ADDR0.
> The function trace_hardirqs_on_caller should have been intended to use
> caller_addr to represent the address that caller wants to be traced.
>
> For example, lockdep log in riscv showing the last {enabled,disabled} at
> __trace_hardirqs_{on,off} all the time(if called by):
> [ 57.853175] hardirqs last enabled at (2519): __trace_hardirqs_on+0xc/0x14
> [ 57.853848] hardirqs last disabled at (2520): __trace_hardirqs_off+0xc/0x14
>
> After use trace_hardirqs_xx_caller, we can get more effective information:
> [ 53.781428] hardirqs last enabled at (2595): restore_all+0xe/0x66
> [ 53.782185] hardirqs last disabled at (2596): ret_from_exception+0xa/0x10
I'm going to mark this as stable and send it in my next push to Linus.
I'll also add:
Fixes: c3bc8fd637a96 ("tracing: Centralize preemptirq tracepoints and unify their usage")
The code was copied from functions that were originally called directly,
but now that they are called indirectly, CALLER_ADDR0 is not the right
thing to use.
Thanks!
-- Steve
>
> Signed-off-by: Yipeng Zou <[email protected]>
> ---
> kernel/trace/trace_preemptirq.c | 4 ++--
> 1 file changed, 2 insertions(+), 2 deletions(-)
>
> diff --git a/kernel/trace/trace_preemptirq.c b/kernel/trace/trace_preemptirq.c
> index 95b58bd757ce..1e130da1b742 100644
> --- a/kernel/trace/trace_preemptirq.c
> +++ b/kernel/trace/trace_preemptirq.c
> @@ -95,14 +95,14 @@ __visible void trace_hardirqs_on_caller(unsigned long caller_addr)
> }
>
> lockdep_hardirqs_on_prepare();
> - lockdep_hardirqs_on(CALLER_ADDR0);
> + lockdep_hardirqs_on(caller_addr);
> }
> EXPORT_SYMBOL(trace_hardirqs_on_caller);
> NOKPROBE_SYMBOL(trace_hardirqs_on_caller);
>
> __visible void trace_hardirqs_off_caller(unsigned long caller_addr)
> {
> - lockdep_hardirqs_off(CALLER_ADDR0);
> + lockdep_hardirqs_off(caller_addr);
>
> if (!this_cpu_read(tracing_irq_cpu)) {
> this_cpu_write(tracing_irq_cpu, 1);
Ping.
在 2022/9/1 18:45, Yipeng Zou 写道:
> Use trace_hardirqs_on_caller to improve irq_tracing message.
>
> lockdep log in riscv showing the last {enabled,disabled} at
> __trace_hardirqs_{on,off} all the time(if called by).
> But that's not what we want to see, the caller is what we want.
>
> Before this commit:
> [ 57.853175] hardirqs last enabled at (2519): __trace_hardirqs_on+0xc/0x14
> [ 57.853848] hardirqs last disabled at (2520): __trace_hardirqs_off+0xc/0x14
>
> After this commit
> [ 53.781428] hardirqs last enabled at (2595): restore_all+0xe/0x66
> [ 53.782185] hardirqs last disabled at (2596): ret_from_exception+0xa/0x10
>
> Signed-off-by: Yipeng Zou <[email protected]>
> ---
> arch/riscv/kernel/trace_irq.c | 4 ++--
> include/linux/irqflags.h | 2 ++
> 2 files changed, 4 insertions(+), 2 deletions(-)
>
> diff --git a/arch/riscv/kernel/trace_irq.c b/arch/riscv/kernel/trace_irq.c
> index 095ac976d7da..7ca24b26e19f 100644
> --- a/arch/riscv/kernel/trace_irq.c
> +++ b/arch/riscv/kernel/trace_irq.c
> @@ -16,12 +16,12 @@
>
> void __trace_hardirqs_on(void)
> {
> - trace_hardirqs_on();
> + trace_hardirqs_on_caller(CALLER_ADDR0);
> }
> NOKPROBE_SYMBOL(__trace_hardirqs_on);
>
> void __trace_hardirqs_off(void)
> {
> - trace_hardirqs_off();
> + trace_hardirqs_off_caller(CALLER_ADDR0);
> }
> NOKPROBE_SYMBOL(__trace_hardirqs_off);
> diff --git a/include/linux/irqflags.h b/include/linux/irqflags.h
> index 5ec0fa71399e..46774fa85cde 100644
> --- a/include/linux/irqflags.h
> +++ b/include/linux/irqflags.h
> @@ -53,6 +53,8 @@ extern void trace_hardirqs_on_prepare(void);
> extern void trace_hardirqs_off_finish(void);
> extern void trace_hardirqs_on(void);
> extern void trace_hardirqs_off(void);
> +extern void trace_hardirqs_on_caller(unsigned long caller_addr);
> +extern void trace_hardirqs_off_caller(unsigned long caller_addr);
>
> # define lockdep_hardirq_context() (raw_cpu_read(hardirq_context))
> # define lockdep_softirq_context(p) ((p)->softirq_context)
--
Regards,
Yipeng Zou