[PATCH] sched,tracing: Correct trace_sched_pi_setprio() for deboosting

[PATCH] sched,tracing: Correct trace_sched_pi_setprio() for deboosting

[Sebastian Andrzej Siewior]

This mostly a revert of commit b91473ff6e97 ("sched,tracing: Update
trace_sched_pi_setprio()") except for the XXX comments.
Since that commit I see during a deboost a task this:
|futex sched_pi_setprio: comm=futex_requeue_p pid=2234 oldprio=98 newprio=98
|futex sched_switch: prev_comm=futex_requeue_p prev_pid=2234 prev_prio=120

and after the revert, the `newprio' shows the correct value again:

|futex sched_pi_setprio: comm=futex_requeue_p pid=2220 oldprio=98 newprio=120
|futex sched_switch: prev_comm=futex_requeue_p prev_pid=2220 prev_prio=120

Reported-by: Mansky Christian <man@keba.com>
Fixes: b91473ff6e97 ("sched,tracing: Update trace_sched_pi_setprio()")
Signed-off-by: Sebastian Andrzej Siewior <bigeasy@linutronix.de>
---
 include/trace/events/sched.h | 6 +++---
 kernel/sched/core.c          | 2 +-
 2 files changed, 4 insertions(+), 4 deletions(-)

diff --git a/include/trace/events/sched.h b/include/trace/events/sched.h
index bc01e06bc716..c6fdb5aac723 100644
--- a/include/trace/events/sched.h
+++ b/include/trace/events/sched.h
@@ -420,9 +420,9 @@ DEFINE_EVENT(sched_stat_runtime, sched_stat_runtime,
  */
 TRACE_EVENT(sched_pi_setprio,
 
-	TP_PROTO(struct task_struct *tsk, struct task_struct *pi_task),
+	TP_PROTO(struct task_struct *tsk, int new_prio),
 
-	TP_ARGS(tsk, pi_task),
+	TP_ARGS(tsk, new_prio),
 
 	TP_STRUCT__entry(
 		__array( char,	comm,	TASK_COMM_LEN	)
@@ -435,7 +435,7 @@ TRACE_EVENT(sched_pi_setprio,
 		memcpy(__entry->comm, tsk->comm, TASK_COMM_LEN);
 		__entry->pid		= tsk->pid;
 		__entry->oldprio	= tsk->prio;
-		__entry->newprio	= pi_task ? pi_task->prio : tsk->prio;
+		__entry->newprio	= new_prio;
 		/* XXX SCHED_DEADLINE bits missing */
 	),
 
diff --git a/kernel/sched/core.c b/kernel/sched/core.c
index 092f7c4de903..888df643b99b 100644
--- a/kernel/sched/core.c
+++ b/kernel/sched/core.c
@@ -3823,7 +3823,7 @@ void rt_mutex_setprio(struct task_struct *p, struct task_struct *pi_task)
 		goto out_unlock;
 	}
 
-	trace_sched_pi_setprio(p, pi_task);
+	trace_sched_pi_setprio(p, prio);
 	oldprio = p->prio;
 
 	if (oldprio == prio)
-- 
2.17.0

Re: [PATCH] sched,tracing: Correct trace_sched_pi_setprio() for deboosting

[Peter Zijlstra]

On Wed, May 23, 2018 at 04:11:07PM +0200, Sebastian Andrzej Siewior wrote:

> Since that commit I see during a deboost a task this:
> |futex sched_pi_setprio: comm=futex_requeue_p pid=2234 oldprio=98 newprio=98
> |futex sched_switch: prev_comm=futex_requeue_p prev_pid=2234 prev_prio=120
> 
> and after the revert, the `newprio' shows the correct value again:
> 
> |futex sched_pi_setprio: comm=futex_requeue_p pid=2220 oldprio=98 newprio=120
> |futex sched_switch: prev_comm=futex_requeue_p prev_pid=2220 prev_prio=120

> @@ -435,7 +435,7 @@ TRACE_EVENT(sched_pi_setprio,
>  		memcpy(__entry->comm, tsk->comm, TASK_COMM_LEN);
>  		__entry->pid		= tsk->pid;
>  		__entry->oldprio	= tsk->prio;
> -		__entry->newprio	= pi_task ? pi_task->prio : tsk->prio;
> +		__entry->newprio	= new_prio;
>  		/* XXX SCHED_DEADLINE bits missing */
>  	),
>  
> diff --git a/kernel/sched/core.c b/kernel/sched/core.c
> index 092f7c4de903..888df643b99b 100644
> --- a/kernel/sched/core.c
> +++ b/kernel/sched/core.c
> @@ -3823,7 +3823,7 @@ void rt_mutex_setprio(struct task_struct *p, struct task_struct *pi_task)
>  		goto out_unlock;
>  	}
>  
> -	trace_sched_pi_setprio(p, pi_task);
> +	trace_sched_pi_setprio(p, prio);

at this point:

	prio = pi_task ? min(p->normal_prio, pi->task->prio) : p->normal_prio;

(aka __rt_effective_prio)

Should we put that in the tracepoint instead?

>  	oldprio = p->prio;
>  
>  	if (oldprio == prio)

Re: [PATCH] sched,tracing: Correct trace_sched_pi_setprio() for deboosting

[Sebastian Andrzej Siewior]

On 2018-05-23 19:28:19 [+0200], Peter Zijlstra wrote:
> On Wed, May 23, 2018 at 04:11:07PM +0200, Sebastian Andrzej Siewior wrote:
> 
> > Since that commit I see during a deboost a task this:
> > |futex sched_pi_setprio: comm=futex_requeue_p pid=2234 oldprio=98 newprio=98
> > |futex sched_switch: prev_comm=futex_requeue_p prev_pid=2234 prev_prio=120
> > 
> > and after the revert, the `newprio' shows the correct value again:
> > 
> > |futex sched_pi_setprio: comm=futex_requeue_p pid=2220 oldprio=98 newprio=120
> > |futex sched_switch: prev_comm=futex_requeue_p prev_pid=2220 prev_prio=120
> 
> > @@ -435,7 +435,7 @@ TRACE_EVENT(sched_pi_setprio,
> >  		memcpy(__entry->comm, tsk->comm, TASK_COMM_LEN);
> >  		__entry->pid		= tsk->pid;
> >  		__entry->oldprio	= tsk->prio;
> > -		__entry->newprio	= pi_task ? pi_task->prio : tsk->prio;
> > +		__entry->newprio	= new_prio;
> >  		/* XXX SCHED_DEADLINE bits missing */
> >  	),
> >  
> > diff --git a/kernel/sched/core.c b/kernel/sched/core.c
> > index 092f7c4de903..888df643b99b 100644
> > --- a/kernel/sched/core.c
> > +++ b/kernel/sched/core.c
> > @@ -3823,7 +3823,7 @@ void rt_mutex_setprio(struct task_struct *p, struct task_struct *pi_task)
> >  		goto out_unlock;
> >  	}
> >  
> > -	trace_sched_pi_setprio(p, pi_task);
> > +	trace_sched_pi_setprio(p, prio);
> 
> at this point:
> 
> 	prio = pi_task ? min(p->normal_prio, pi->task->prio) : p->normal_prio;
> 
> (aka __rt_effective_prio)
> 
> Should we put that in the tracepoint instead?

I don't see the point in open coding __rt_effective_prio() and
recomputing the value we already have. I'm a little worried that if
something happens to `prio' we might miss it and notice later while
debugging.
However, if they are reasons like breaking the trace-API for $tools, I
can update it.

Sebastian

Re: [PATCH] sched,tracing: Correct trace_sched_pi_setprio() for deboosting

[Peter Zijlstra]

On Thu, May 24, 2018 at 09:44:14AM +0200, Sebastian Andrzej Siewior wrote:
> On 2018-05-23 19:28:19 [+0200], Peter Zijlstra wrote:
> > On Wed, May 23, 2018 at 04:11:07PM +0200, Sebastian Andrzej Siewior wrote:

> > > diff --git a/kernel/sched/core.c b/kernel/sched/core.c
> > > index 092f7c4de903..888df643b99b 100644
> > > --- a/kernel/sched/core.c
> > > +++ b/kernel/sched/core.c
> > > @@ -3823,7 +3823,7 @@ void rt_mutex_setprio(struct task_struct *p, struct task_struct *pi_task)
> > >  		goto out_unlock;
> > >  	}
> > >  
> > > -	trace_sched_pi_setprio(p, pi_task);
> > > +	trace_sched_pi_setprio(p, prio);

> I don't see the point in open coding __rt_effective_prio() and
> recomputing the value we already have. I'm a little worried that if
> something happens to `prio' we might miss it and notice later while
> debugging.
> However, if they are reasons like breaking the trace-API for $tools, I
> can update it.

Thing is, with the pi_task as an argument, someone using the tracehook
can actually get the deadline data out, even if the normal 'event' does
not.

Re: [PATCH] sched,tracing: Correct trace_sched_pi_setprio() for deboosting

[Sebastian Andrzej Siewior]

On 2018-05-24 10:37:54 [+0200], Peter Zijlstra wrote:
> Thing is, with the pi_task as an argument, someone using the tracehook
> can actually get the deadline data out, even if the normal 'event' does
> not.

Okay, in that case an update will follow shortly.

Sebastian

[PATCH v2] sched,tracing: Correct trace_sched_pi_setprio() for deboosting

[Sebastian Andrzej Siewior]

Since commit b91473ff6e97 ("sched,tracing: Update
trace_sched_pi_setprio()") the sched_pi_setprio trace point shows the
"newprio" during a deboost:
|futex sched_pi_setprio: comm=futex_requeue_p pid=2234 oldprio=98 newprio=98
|futex sched_switch: prev_comm=futex_requeue_p prev_pid=2234 prev_prio=120

This patch open codes __rt_effective_prio() in the tracepoint as the
`newprio' to get the old behaviour back / the correct priority:

|futex sched_pi_setprio: comm=futex_requeue_p pid=2220 oldprio=98 newprio=120
|futex sched_switch: prev_comm=futex_requeue_p prev_pid=2220 prev_prio=120

Peter suggested to open code the new priority so people using tracehook
could get the deadline data out.

Reported-by: Mansky Christian <man@keba.com>
Fixes: b91473ff6e97 ("sched,tracing: Update trace_sched_pi_setprio()")
Signed-off-by: Sebastian Andrzej Siewior <bigeasy@linutronix.de>
---
v1…v2: Open code __rt_effective_prio() in sched_pi_setprio macro as
suggested by PeterZ.

 include/trace/events/sched.h | 4 +++-
 1 file changed, 3 insertions(+), 1 deletion(-)

diff --git a/include/trace/events/sched.h b/include/trace/events/sched.h
index bc01e06bc716..0be866c91f62 100644
--- a/include/trace/events/sched.h
+++ b/include/trace/events/sched.h
@@ -435,7 +435,9 @@ TRACE_EVENT(sched_pi_setprio,
 		memcpy(__entry->comm, tsk->comm, TASK_COMM_LEN);
 		__entry->pid		= tsk->pid;
 		__entry->oldprio	= tsk->prio;
-		__entry->newprio	= pi_task ? pi_task->prio : tsk->prio;
+		__entry->newprio	= pi_task ?
+				min(tsk->normal_prio, pi_task->prio) :
+				tsk->normal_prio;
 		/* XXX SCHED_DEADLINE bits missing */
 	),
 
-- 
2.17.0

[tip:sched/core] sched, tracing: Fix trace_sched_pi_setprio() for deboosting

[tip-bot for Sebastian Andrzej Siewior]

Commit-ID:  4ff648decf4712d39f184fc2df3163f43975575a
Gitweb:     https://git.kernel.org/tip/4ff648decf4712d39f184fc2df3163f43975575a
Author:     Sebastian Andrzej Siewior <bigeasy@linutronix.de>
AuthorDate: Thu, 24 May 2018 15:26:48 +0200
Committer:  Ingo Molnar <mingo@kernel.org>
CommitDate: Fri, 25 May 2018 08:04:01 +0200

sched, tracing: Fix trace_sched_pi_setprio() for deboosting

Since the following commit:

  b91473ff6e97 ("sched,tracing: Update trace_sched_pi_setprio()")

the sched_pi_setprio trace point shows the "newprio" during a deboost:

  |futex sched_pi_setprio: comm=futex_requeue_p pid"34 oldprio˜ newprio=3D98
  |futex sched_switch: prev_comm=futex_requeue_p prev_pid"34 prev_prio=120

This patch open codes __rt_effective_prio() in the tracepoint as the
'newprio' to get the old behaviour back / the correct priority:

  |futex sched_pi_setprio: comm=futex_requeue_p pid"20 oldprio˜ newprio=3D120
  |futex sched_switch: prev_comm=futex_requeue_p prev_pid"20 prev_prio=120

Peter suggested to open code the new priority so people using tracehook
could get the deadline data out.

Reported-by: Mansky Christian <man@keba.com>
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: Peter Zijlstra <peterz@infradead.org>
Cc: Steven Rostedt <rostedt@goodmis.org>
Cc: Thomas Gleixner <tglx@linutronix.de>
Fixes: b91473ff6e97 ("sched,tracing: Update trace_sched_pi_setprio()")
Link: http://lkml.kernel.org/r/20180524132647.gg6ziuogczdmjjzu@linutronix.de
Signed-off-by: Ingo Molnar <mingo@kernel.org>
---
 include/trace/events/sched.h | 4 +++-
 1 file changed, 3 insertions(+), 1 deletion(-)

diff --git a/include/trace/events/sched.h b/include/trace/events/sched.h
index bc01e06bc716..0be866c91f62 100644
--- a/include/trace/events/sched.h
+++ b/include/trace/events/sched.h
@@ -435,7 +435,9 @@ TRACE_EVENT(sched_pi_setprio,
 		memcpy(__entry->comm, tsk->comm, TASK_COMM_LEN);
 		__entry->pid		= tsk->pid;
 		__entry->oldprio	= tsk->prio;
-		__entry->newprio	= pi_task ? pi_task->prio : tsk->prio;
+		__entry->newprio	= pi_task ?
+				min(tsk->normal_prio, pi_task->prio) :
+				tsk->normal_prio;
 		/* XXX SCHED_DEADLINE bits missing */
 	),
 

Re: [tip:sched/core] sched, tracing: Fix trace_sched_pi_setprio() for deboosting

[Sebastian Andrzej Siewior]

On 2018-05-25 02:47:20 [-0700], tip-bot for Sebastian Andrzej Siewior wrote:
> Commit-ID:  4ff648decf4712d39f184fc2df3163f43975575a
> Gitweb:     https://git.kernel.org/tip/4ff648decf4712d39f184fc2df3163f43975575a
> Author:     Sebastian Andrzej Siewior <bigeasy@linutronix.de>
> AuthorDate: Thu, 24 May 2018 15:26:48 +0200
> Committer:  Ingo Molnar <mingo@kernel.org>
> CommitDate: Fri, 25 May 2018 08:04:01 +0200
> 
> sched, tracing: Fix trace_sched_pi_setprio() for deboosting
> 
> Since the following commit:
> 
>   b91473ff6e97 ("sched,tracing: Update trace_sched_pi_setprio()")
> 
> the sched_pi_setprio trace point shows the "newprio" during a deboost:
> 
>   |futex sched_pi_setprio: comm=futex_requeue_p pid"34 oldprio˜ newprio=3D98
>   |futex sched_switch: prev_comm=futex_requeue_p prev_pid"34 prev_prio=120

pid=2234 got turned into pid"34 the same for other fields.

Sebastian