[PATCH v2] kernel: sched: fix preempt_disable_ip recodring for preempt_disable()

[PATCH v2] kernel: sched: fix preempt_disable_ip recodring for preempt_disable()

[Sebastian Andrzej Siewior]

The preempt_disable() invokes preempt_count_add() which saves the caller
in ->preempt_disable_ip. It uses CALLER_ADDR1 which does not look for
its caller but for the parent of the caller. Which means we get the correct
caller for something like spin_lock() unless the architectures inlines
those invocations. It is always wrong for preempt_disable() or
local_bh_disable().

This patch makes the function get_parent_ip() which tries
CALLER_ADDR0,1,2 if the former is a locking function.
This seems to record the preempt_disable() caller properly for
preempt_disable() itself as well as for get_cpu_var() or
local_bh_disable().

Signed-off-by: Sebastian Andrzej Siewior <bigeasy@linutronix.de>
---
v1…v2: drop the header split and move it to ftrace.h instead

 include/linux/ftrace.h | 12 ++++++++++++
 include/linux/sched.h  |  2 --
 kernel/sched/core.c    | 14 ++------------
 kernel/softirq.c       |  4 ++--
 4 files changed, 16 insertions(+), 16 deletions(-)

diff --git a/include/linux/ftrace.h b/include/linux/ftrace.h
index 81de7123959d..f473d9408bc3 100644
--- a/include/linux/ftrace.h
+++ b/include/linux/ftrace.h
@@ -711,6 +711,18 @@ static inline void __ftrace_enabled_restore(int enabled)
 #define CALLER_ADDR5 ((unsigned long)ftrace_return_address(5))
 #define CALLER_ADDR6 ((unsigned long)ftrace_return_address(6))
 
+static inline unsigned long get_parent_ip(void)
+{
+	unsigned long addr = CALLER_ADDR0;
+
+	if (!in_lock_functions(addr))
+		return addr;
+	addr = CALLER_ADDR1;
+	if (!in_lock_functions(addr))
+		return addr;
+	return CALLER_ADDR2;
+}
+
 #ifdef CONFIG_IRQSOFF_TRACER
   extern void time_hardirqs_on(unsigned long a0, unsigned long a1);
   extern void time_hardirqs_off(unsigned long a0, unsigned long a1);
diff --git a/include/linux/sched.h b/include/linux/sched.h
index a10494a94cc3..f45f947500c9 100644
--- a/include/linux/sched.h
+++ b/include/linux/sched.h
@@ -182,8 +182,6 @@ extern void update_cpu_load_nohz(int active);
 static inline void update_cpu_load_nohz(int active) { }
 #endif
 
-extern unsigned long get_parent_ip(unsigned long addr);
-
 extern void dump_cpu_task(int cpu);
 
 struct seq_file;
diff --git a/kernel/sched/core.c b/kernel/sched/core.c
index 9503d590e5ef..12c2527f5957 100644
--- a/kernel/sched/core.c
+++ b/kernel/sched/core.c
@@ -3010,16 +3010,6 @@ u64 scheduler_tick_max_deferment(void)
 }
 #endif
 
-notrace unsigned long get_parent_ip(unsigned long addr)
-{
-	if (in_lock_functions(addr)) {
-		addr = CALLER_ADDR2;
-		if (in_lock_functions(addr))
-			addr = CALLER_ADDR3;
-	}
-	return addr;
-}
-
 #if defined(CONFIG_PREEMPT) && (defined(CONFIG_DEBUG_PREEMPT) || \
 				defined(CONFIG_PREEMPT_TRACER))
 
@@ -3041,7 +3031,7 @@ void preempt_count_add(int val)
 				PREEMPT_MASK - 10);
 #endif
 	if (preempt_count() == val) {
-		unsigned long ip = get_parent_ip(CALLER_ADDR1);
+		unsigned long ip = get_parent_ip();
 #ifdef CONFIG_DEBUG_PREEMPT
 		current->preempt_disable_ip = ip;
 #endif
@@ -3068,7 +3058,7 @@ void preempt_count_sub(int val)
 #endif
 
 	if (preempt_count() == val)
-		trace_preempt_on(CALLER_ADDR0, get_parent_ip(CALLER_ADDR1));
+		trace_preempt_on(CALLER_ADDR0, get_parent_ip());
 	__preempt_count_sub(val);
 }
 EXPORT_SYMBOL(preempt_count_sub);
diff --git a/kernel/softirq.c b/kernel/softirq.c
index 479e4436f787..ec71033a87a2 100644
--- a/kernel/softirq.c
+++ b/kernel/softirq.c
@@ -116,9 +116,9 @@ void __local_bh_disable_ip(unsigned long ip, unsigned int cnt)
 
 	if (preempt_count() == cnt) {
 #ifdef CONFIG_DEBUG_PREEMPT
-		current->preempt_disable_ip = get_parent_ip(CALLER_ADDR1);
+		current->preempt_disable_ip = get_parent_ip();
 #endif
-		trace_preempt_off(CALLER_ADDR0, get_parent_ip(CALLER_ADDR1));
+		trace_preempt_off(CALLER_ADDR0, get_parent_ip());
 	}
 }
 EXPORT_SYMBOL(__local_bh_disable_ip);
-- 
2.7.0

Re: [PATCH v2] kernel: sched: fix preempt_disable_ip recodring for preempt_disable()

[Steven Rostedt]

On Fri, 12 Feb 2016 16:20:20 +0100
Sebastian Andrzej Siewior <bigeasy@linutronix.de> wrote:

> The preempt_disable() invokes preempt_count_add() which saves the caller
> in ->preempt_disable_ip. It uses CALLER_ADDR1 which does not look for
> its caller but for the parent of the caller. Which means we get the correct
> caller for something like spin_lock() unless the architectures inlines
> those invocations. It is always wrong for preempt_disable() or
> local_bh_disable().
> 
> This patch makes the function get_parent_ip() which tries
> CALLER_ADDR0,1,2 if the former is a locking function.
> This seems to record the preempt_disable() caller properly for
> preempt_disable() itself as well as for get_cpu_var() or
> local_bh_disable().
> 
> Signed-off-by: Sebastian Andrzej Siewior <bigeasy@linutronix.de>
> ---
> v1…v2: drop the header split and move it to ftrace.h instead
> 
>  include/linux/ftrace.h | 12 ++++++++++++
>  include/linux/sched.h  |  2 --
>  kernel/sched/core.c    | 14 ++------------
>  kernel/softirq.c       |  4 ++--
>  4 files changed, 16 insertions(+), 16 deletions(-)
> 
> diff --git a/include/linux/ftrace.h b/include/linux/ftrace.h
> index 81de7123959d..f473d9408bc3 100644
> --- a/include/linux/ftrace.h
> +++ b/include/linux/ftrace.h
> @@ -711,6 +711,18 @@ static inline void __ftrace_enabled_restore(int enabled)
>  #define CALLER_ADDR5 ((unsigned long)ftrace_return_address(5))
>  #define CALLER_ADDR6 ((unsigned long)ftrace_return_address(6))
>  
> +static inline unsigned long get_parent_ip(void)

I wonder if we should rename this to get_lock_parent_ip(). I know you
are keeping the original name, but placing it into a header makes it
more visible to others, and making it a less generic name is probably a
good idea.

You have to modify all users anyway, to get rid of the parameter.

Want to send a v3?

-- Steve


> +{
> +	unsigned long addr = CALLER_ADDR0;
> +
> +	if (!in_lock_functions(addr))
> +		return addr;
> +	addr = CALLER_ADDR1;
> +	if (!in_lock_functions(addr))
> +		return addr;
> +	return CALLER_ADDR2;
> +}
> +
>  #ifdef CONFIG_IRQSOFF_TRACER
>    extern void time_hardirqs_on(unsigned long a0, unsigned long a1);
>    extern void time_hardirqs_off(unsigned long a0, unsigned long a1);
> diff --git a/include/linux/sched.h b/include/linux/sched.h
> index a10494a94cc3..f45f947500c9 100644
> --- a/include/linux/sched.h
> +++ b/include/linux/sched.h
> @@ -182,8 +182,6 @@ extern void update_cpu_load_nohz(int active);
>  static inline void update_cpu_load_nohz(int active) { }
>  #endif
>  
> -extern unsigned long get_parent_ip(unsigned long addr);
> -
>  extern void dump_cpu_task(int cpu);
>  
>  struct seq_file;
> diff --git a/kernel/sched/core.c b/kernel/sched/core.c
> index 9503d590e5ef..12c2527f5957 100644
> --- a/kernel/sched/core.c
> +++ b/kernel/sched/core.c
> @@ -3010,16 +3010,6 @@ u64 scheduler_tick_max_deferment(void)
>  }
>  #endif
>  
> -notrace unsigned long get_parent_ip(unsigned long addr)
> -{
> -	if (in_lock_functions(addr)) {
> -		addr = CALLER_ADDR2;
> -		if (in_lock_functions(addr))
> -			addr = CALLER_ADDR3;
> -	}
> -	return addr;
> -}
> -
>  #if defined(CONFIG_PREEMPT) && (defined(CONFIG_DEBUG_PREEMPT) || \
>  				defined(CONFIG_PREEMPT_TRACER))
>  
> @@ -3041,7 +3031,7 @@ void preempt_count_add(int val)
>  				PREEMPT_MASK - 10);
>  #endif
>  	if (preempt_count() == val) {
> -		unsigned long ip = get_parent_ip(CALLER_ADDR1);
> +		unsigned long ip = get_parent_ip();
>  #ifdef CONFIG_DEBUG_PREEMPT
>  		current->preempt_disable_ip = ip;
>  #endif
> @@ -3068,7 +3058,7 @@ void preempt_count_sub(int val)
>  #endif
>  
>  	if (preempt_count() == val)
> -		trace_preempt_on(CALLER_ADDR0, get_parent_ip(CALLER_ADDR1));
> +		trace_preempt_on(CALLER_ADDR0, get_parent_ip());
>  	__preempt_count_sub(val);
>  }
>  EXPORT_SYMBOL(preempt_count_sub);
> diff --git a/kernel/softirq.c b/kernel/softirq.c
> index 479e4436f787..ec71033a87a2 100644
> --- a/kernel/softirq.c
> +++ b/kernel/softirq.c
> @@ -116,9 +116,9 @@ void __local_bh_disable_ip(unsigned long ip, unsigned int cnt)
>  
>  	if (preempt_count() == cnt) {
>  #ifdef CONFIG_DEBUG_PREEMPT
> -		current->preempt_disable_ip = get_parent_ip(CALLER_ADDR1);
> +		current->preempt_disable_ip = get_parent_ip();
>  #endif
> -		trace_preempt_off(CALLER_ADDR0, get_parent_ip(CALLER_ADDR1));
> +		trace_preempt_off(CALLER_ADDR0, get_parent_ip());
>  	}
>  }
>  EXPORT_SYMBOL(__local_bh_disable_ip);

[PATCH v3] kernel: sched: fix preempt_disable_ip recodring for preempt_disable()

[Sebastian Andrzej Siewior]

The preempt_disable() invokes preempt_count_add() which saves the caller
in ->preempt_disable_ip. It uses CALLER_ADDR1 which does not look for
its caller but for the parent of the caller. Which means we get the correct
caller for something like spin_lock() unless the architectures inlines
those invocations. It is always wrong for preempt_disable() or
local_bh_disable().

This patch makes the function get_lock_parent_ip() which tries
CALLER_ADDR0,1,2 if the former is a locking function.
This seems to record the preempt_disable() caller properly for
preempt_disable() itself as well as for get_cpu_var() or
local_bh_disable().
Steven asked for the get_parent_ip() -> get_lock_parent_ip() rename.

Signed-off-by: Sebastian Andrzej Siewior <bigeasy@linutronix.de>
---
v2…v3: get_parent_ip() -> get_lock_parent_ip()
v1…v2: drop the header split and move it to ftrace.h instead                                     

 include/linux/ftrace.h | 12 ++++++++++++
 include/linux/sched.h  |  2 --
 kernel/sched/core.c    | 14 ++------------
 kernel/softirq.c       |  4 ++--
 4 files changed, 16 insertions(+), 16 deletions(-)

diff --git a/include/linux/ftrace.h b/include/linux/ftrace.h
index c2b340e23f62..6d9df3f7e334 100644
--- a/include/linux/ftrace.h
+++ b/include/linux/ftrace.h
@@ -713,6 +713,18 @@ static inline void __ftrace_enabled_restore(int enabled)
 #define CALLER_ADDR5 ((unsigned long)ftrace_return_address(5))
 #define CALLER_ADDR6 ((unsigned long)ftrace_return_address(6))
 
+static inline unsigned long get_lock_parent_ip(void)
+{
+	unsigned long addr = CALLER_ADDR0;
+
+	if (!in_lock_functions(addr))
+		return addr;
+	addr = CALLER_ADDR1;
+	if (!in_lock_functions(addr))
+		return addr;
+	return CALLER_ADDR2;
+}
+
 #ifdef CONFIG_IRQSOFF_TRACER
   extern void time_hardirqs_on(unsigned long a0, unsigned long a1);
   extern void time_hardirqs_off(unsigned long a0, unsigned long a1);
diff --git a/include/linux/sched.h b/include/linux/sched.h
index a10494a94cc3..f45f947500c9 100644
--- a/include/linux/sched.h
+++ b/include/linux/sched.h
@@ -182,8 +182,6 @@ extern void update_cpu_load_nohz(int active);
 static inline void update_cpu_load_nohz(int active) { }
 #endif
 
-extern unsigned long get_parent_ip(unsigned long addr);
-
 extern void dump_cpu_task(int cpu);
 
 struct seq_file;
diff --git a/kernel/sched/core.c b/kernel/sched/core.c
index 9503d590e5ef..700f87b27667 100644
--- a/kernel/sched/core.c
+++ b/kernel/sched/core.c
@@ -3010,16 +3010,6 @@ u64 scheduler_tick_max_deferment(void)
 }
 #endif
 
-notrace unsigned long get_parent_ip(unsigned long addr)
-{
-	if (in_lock_functions(addr)) {
-		addr = CALLER_ADDR2;
-		if (in_lock_functions(addr))
-			addr = CALLER_ADDR3;
-	}
-	return addr;
-}
-
 #if defined(CONFIG_PREEMPT) && (defined(CONFIG_DEBUG_PREEMPT) || \
 				defined(CONFIG_PREEMPT_TRACER))
 
@@ -3041,7 +3031,7 @@ void preempt_count_add(int val)
 				PREEMPT_MASK - 10);
 #endif
 	if (preempt_count() == val) {
-		unsigned long ip = get_parent_ip(CALLER_ADDR1);
+		unsigned long ip = get_lock_parent_ip();
 #ifdef CONFIG_DEBUG_PREEMPT
 		current->preempt_disable_ip = ip;
 #endif
@@ -3068,7 +3058,7 @@ void preempt_count_sub(int val)
 #endif
 
 	if (preempt_count() == val)
-		trace_preempt_on(CALLER_ADDR0, get_parent_ip(CALLER_ADDR1));
+		trace_preempt_on(CALLER_ADDR0, get_lock_parent_ip());
 	__preempt_count_sub(val);
 }
 EXPORT_SYMBOL(preempt_count_sub);
diff --git a/kernel/softirq.c b/kernel/softirq.c
index 479e4436f787..8aae49dd7da8 100644
--- a/kernel/softirq.c
+++ b/kernel/softirq.c
@@ -116,9 +116,9 @@ void __local_bh_disable_ip(unsigned long ip, unsigned int cnt)
 
 	if (preempt_count() == cnt) {
 #ifdef CONFIG_DEBUG_PREEMPT
-		current->preempt_disable_ip = get_parent_ip(CALLER_ADDR1);
+		current->preempt_disable_ip = get_lock_parent_ip();
 #endif
-		trace_preempt_off(CALLER_ADDR0, get_parent_ip(CALLER_ADDR1));
+		trace_preempt_off(CALLER_ADDR0, get_lock_parent_ip());
 	}
 }
 EXPORT_SYMBOL(__local_bh_disable_ip);
-- 
2.7.0

Re: [PATCH v3] kernel: sched: fix preempt_disable_ip recodring for preempt_disable()

[Daniel Bristot de Oliveira]

On 02/26/2016 10:54 AM, Sebastian Andrzej Siewior wrote:
> -		trace_preempt_off(CALLER_ADDR0, get_parent_ip(CALLER_ADDR1));
> +		trace_preempt_off(CALLER_ADDR0, get_lock_parent_ip());

If !lock_functions(CALLER_ADDR0), the start/stop_critical_timing() will
be called with parent_ip == ip.

Hence, the following trace on start_critical_timing():

        __trace_function(tr, ip, parent_ip, flags, preempt_count());

Will show the function calling itself.

Is it a problem? am I missing something?

-- Daniel

[tip:sched/core] sched/debug: Fix preempt_disable_ip recording for preempt_disable()

[tip-bot for Sebastian Andrzej Siewior]

Commit-ID:  f904f58263e1df5f70feb8b283f4bbe662847334
Gitweb:     http://git.kernel.org/tip/f904f58263e1df5f70feb8b283f4bbe662847334
Author:     Sebastian Andrzej Siewior <bigeasy@linutronix.de>
AuthorDate: Fri, 26 Feb 2016 14:54:56 +0100
Committer:  Ingo Molnar <mingo@kernel.org>
CommitDate: Mon, 29 Feb 2016 09:53:10 +0100

sched/debug: Fix preempt_disable_ip recording for preempt_disable()

The preempt_disable() invokes preempt_count_add() which saves the caller
in ->preempt_disable_ip. It uses CALLER_ADDR1 which does not look for
its caller but for the parent of the caller. Which means we get the correct
caller for something like spin_lock() unless the architectures inlines
those invocations. It is always wrong for preempt_disable() or
local_bh_disable().

This patch makes the function get_lock_parent_ip() which tries
CALLER_ADDR0,1,2 if the former is a locking function.
This seems to record the preempt_disable() caller properly for
preempt_disable() itself as well as for get_cpu_var() or
local_bh_disable().

Steven asked for the get_parent_ip() -> get_lock_parent_ip() rename.

Signed-off-by: Sebastian Andrzej Siewior <bigeasy@linutronix.de>
Signed-off-by: Peter Zijlstra (Intel) <peterz@infradead.org>
Cc: Linus Torvalds <torvalds@linux-foundation.org>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Steven Rostedt <rostedt@goodmis.org>
Cc: Thomas Gleixner <tglx@linutronix.de>
Link: http://lkml.kernel.org/r/20160226135456.GB18244@linutronix.de
Signed-off-by: Ingo Molnar <mingo@kernel.org>
---
 include/linux/ftrace.h | 12 ++++++++++++
 include/linux/sched.h  |  2 --
 kernel/sched/core.c    | 14 ++------------
 kernel/softirq.c       |  4 ++--
 4 files changed, 16 insertions(+), 16 deletions(-)

diff --git a/include/linux/ftrace.h b/include/linux/ftrace.h
index c2b340e..6d9df3f 100644
--- a/include/linux/ftrace.h
+++ b/include/linux/ftrace.h
@@ -713,6 +713,18 @@ static inline void __ftrace_enabled_restore(int enabled)
 #define CALLER_ADDR5 ((unsigned long)ftrace_return_address(5))
 #define CALLER_ADDR6 ((unsigned long)ftrace_return_address(6))
 
+static inline unsigned long get_lock_parent_ip(void)
+{
+	unsigned long addr = CALLER_ADDR0;
+
+	if (!in_lock_functions(addr))
+		return addr;
+	addr = CALLER_ADDR1;
+	if (!in_lock_functions(addr))
+		return addr;
+	return CALLER_ADDR2;
+}
+
 #ifdef CONFIG_IRQSOFF_TRACER
   extern void time_hardirqs_on(unsigned long a0, unsigned long a1);
   extern void time_hardirqs_off(unsigned long a0, unsigned long a1);
diff --git a/include/linux/sched.h b/include/linux/sched.h
index 87e5f98..9519b66 100644
--- a/include/linux/sched.h
+++ b/include/linux/sched.h
@@ -182,8 +182,6 @@ extern void update_cpu_load_nohz(int active);
 static inline void update_cpu_load_nohz(int active) { }
 #endif
 
-extern unsigned long get_parent_ip(unsigned long addr);
-
 extern void dump_cpu_task(int cpu);
 
 struct seq_file;
diff --git a/kernel/sched/core.c b/kernel/sched/core.c
index 6dbb21f..423452c 100644
--- a/kernel/sched/core.c
+++ b/kernel/sched/core.c
@@ -2946,16 +2946,6 @@ u64 scheduler_tick_max_deferment(void)
 }
 #endif
 
-notrace unsigned long get_parent_ip(unsigned long addr)
-{
-	if (in_lock_functions(addr)) {
-		addr = CALLER_ADDR2;
-		if (in_lock_functions(addr))
-			addr = CALLER_ADDR3;
-	}
-	return addr;
-}
-
 #if defined(CONFIG_PREEMPT) && (defined(CONFIG_DEBUG_PREEMPT) || \
 				defined(CONFIG_PREEMPT_TRACER))
 
@@ -2977,7 +2967,7 @@ void preempt_count_add(int val)
 				PREEMPT_MASK - 10);
 #endif
 	if (preempt_count() == val) {
-		unsigned long ip = get_parent_ip(CALLER_ADDR1);
+		unsigned long ip = get_lock_parent_ip();
 #ifdef CONFIG_DEBUG_PREEMPT
 		current->preempt_disable_ip = ip;
 #endif
@@ -3004,7 +2994,7 @@ void preempt_count_sub(int val)
 #endif
 
 	if (preempt_count() == val)
-		trace_preempt_on(CALLER_ADDR0, get_parent_ip(CALLER_ADDR1));
+		trace_preempt_on(CALLER_ADDR0, get_lock_parent_ip());
 	__preempt_count_sub(val);
 }
 EXPORT_SYMBOL(preempt_count_sub);
diff --git a/kernel/softirq.c b/kernel/softirq.c
index 479e443..8aae49d 100644
--- a/kernel/softirq.c
+++ b/kernel/softirq.c
@@ -116,9 +116,9 @@ void __local_bh_disable_ip(unsigned long ip, unsigned int cnt)
 
 	if (preempt_count() == cnt) {
 #ifdef CONFIG_DEBUG_PREEMPT
-		current->preempt_disable_ip = get_parent_ip(CALLER_ADDR1);
+		current->preempt_disable_ip = get_lock_parent_ip();
 #endif
-		trace_preempt_off(CALLER_ADDR0, get_parent_ip(CALLER_ADDR1));
+		trace_preempt_off(CALLER_ADDR0, get_lock_parent_ip());
 	}
 }
 EXPORT_SYMBOL(__local_bh_disable_ip);

Re: [PATCH v3] kernel: sched: fix preempt_disable_ip recodring for preempt_disable()

[Sebastian Andrzej Siewior]

On 02/26/2016 08:11 PM, Daniel Bristot de Oliveira wrote:
> 
> 
> On 02/26/2016 10:54 AM, Sebastian Andrzej Siewior wrote:
>> -		trace_preempt_off(CALLER_ADDR0, get_parent_ip(CALLER_ADDR1));
>> +		trace_preempt_off(CALLER_ADDR0, get_lock_parent_ip());
> 
> If !lock_functions(CALLER_ADDR0), the start/stop_critical_timing() will
> be called with parent_ip == ip.
> 
> Hence, the following trace on start_critical_timing():
> 
>         __trace_function(tr, ip, parent_ip, flags, preempt_count());
> 
> Will show the function calling itself.
> 
> Is it a problem? am I missing something?

It might be that for !lock_functions() we get the same caller. But then
get_parent_ip() was not inlined (in my .o file) so ADDR1 in
get_parent_ip() should correspond to ADDR0 in the inline case.

> -- Daniel

Sebastian