[PATCH] tools lib traceevent: Fix prev/next_prio for deadline tasks

[PATCH] tools lib traceevent: Fix prev/next_prio for deadline tasks

[Daniel Bristot de Oliveira]

From: Daniel Bristot de Oliveiva <bristot@redhat.com>

Currently, the sched:sched_switch tracepoint reports deadline tasks
with priority -1. But when reading the trace via perf script I've
got the following output:

  # ./d & # (d is a deadline task, see [1])
  # perf record -e sched:sched_switch -a sleep 1
  # perf script
      ...
         swapper     0 [000]  2146.962441: sched:sched_switch: swapper/0:0 [120] R ==> d:2593 [4294967295]
               d  2593 [000]  2146.972472: sched:sched_switch: d:2593 [4294967295] R ==> g:2590 [4294967295]

The task d reports the wrong priority [4294967295]. This happens because
the "int prio" is stored in an unsigned long long val. Although it is
set as a %lld, as int is shorter than unsigned long long,
trace_seq_printf prints it as a positive number.

The fix is just to cast the val as an int, and print it as a %d,
as in the sched:sched_switch tracepoint's "format".

The output with the fix is:

  # ./d &
  # perf record -e sched:sched_switch -a sleep 1
  # perf script
      ...
         swapper     0 [000]  4306.374037: sched:sched_switch: swapper/0:0 [120] R ==> d:10941 [-1]
               d 10941 [000]  4306.383823: sched:sched_switch: d:10941 [-1] R ==> swapper/0:0 [120]

[1] gcc -o d d.c - from http://bristot.me/lkml/d.c

Signed-off-by: Daniel Bristot de Oliveira <bristot@redhat.com>
Cc: Steven Rostedt <rostedt@goodmis.org>
Cc: Ingo Molnar <mingo@redhat.com>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Arnaldo Carvalho de Melo <acme@kernel.org>
Cc: Alexander Shishkin <alexander.shishkin@linux.intel.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: linux-kernel@vger.kernel.org

diff --git a/tools/lib/traceevent/plugin_sched_switch.c b/tools/lib/traceevent/plugin_sched_switch.c
index f1ce600..ec30c2f 100644
--- a/tools/lib/traceevent/plugin_sched_switch.c
+++ b/tools/lib/traceevent/plugin_sched_switch.c
@@ -111,7 +111,7 @@ static int sched_switch_handler(struct trace_seq *s,
 	trace_seq_printf(s, "%lld ", val);
 
 	if (pevent_get_field_val(s, event, "prev_prio", record, &val, 0) == 0)
-		trace_seq_printf(s, "[%lld] ", val);
+		trace_seq_printf(s, "[%d] ", (int) val);
 
 	if (pevent_get_field_val(s,  event, "prev_state", record, &val, 0) == 0)
 		write_state(s, val);
@@ -129,7 +129,7 @@ static int sched_switch_handler(struct trace_seq *s,
 	trace_seq_printf(s, "%lld", val);
 
 	if (pevent_get_field_val(s, event, "next_prio", record, &val, 0) == 0)
-		trace_seq_printf(s, " [%lld]", val);
+		trace_seq_printf(s, " [%d]", (int) val);
 
 	return 0;
 }
-- 
2.9.3

Re: [PATCH] tools lib traceevent: Fix prev/next_prio for deadline tasks

[Arnaldo Carvalho de Melo]

Em Tue, Jan 03, 2017 at 12:42:42PM +0100, Daniel Bristot de Oliveira escreveu:
> From: Daniel Bristot de Oliveiva <bristot@redhat.com>
> 
> Currently, the sched:sched_switch tracepoint reports deadline tasks
> with priority -1. But when reading the trace via perf script I've
> got the following output:
> 
>   # ./d & # (d is a deadline task, see [1])
>   # perf record -e sched:sched_switch -a sleep 1
>   # perf script
>       ...
>          swapper     0 [000]  2146.962441: sched:sched_switch: swapper/0:0 [120] R ==> d:2593 [4294967295]
>                d  2593 [000]  2146.972472: sched:sched_switch: d:2593 [4294967295] R ==> g:2590 [4294967295]
> 
> The task d reports the wrong priority [4294967295]. This happens because
> the "int prio" is stored in an unsigned long long val. Although it is
> set as a %lld, as int is shorter than unsigned long long,
> trace_seq_printf prints it as a positive number.
> 
> The fix is just to cast the val as an int, and print it as a %d,
> as in the sched:sched_switch tracepoint's "format".
> 
> The output with the fix is:
> 
>   # ./d &
>   # perf record -e sched:sched_switch -a sleep 1
>   # perf script
>       ...
>          swapper     0 [000]  4306.374037: sched:sched_switch: swapper/0:0 [120] R ==> d:10941 [-1]
>                d 10941 [000]  4306.383823: sched:sched_switch: d:10941 [-1] R ==> swapper/0:0 [120]
> 
> [1] gcc -o d d.c - from http://bristot.me/lkml/d.c
> 
> Signed-off-by: Daniel Bristot de Oliveira <bristot@redhat.com>
> Cc: Steven Rostedt <rostedt@goodmis.org>
> Cc: Ingo Molnar <mingo@redhat.com>
> Cc: Peter Zijlstra <peterz@infradead.org>
> Cc: Arnaldo Carvalho de Melo <acme@kernel.org>
> Cc: Alexander Shishkin <alexander.shishkin@linux.intel.com>
> Cc: Jiri Olsa <jolsa@redhat.com>
> Cc: linux-kernel@vger.kernel.org

you missed the delimiter here:

---

Without it, I get:

[acme@jouet linux]$ am /wb/1.patch 
Applying: tools lib traceevent: Fix prev/next_prio for deadline tasks
fatal: patch with only garbage at line 3
Patch failed at 0001 tools lib traceevent: Fix prev/next_prio for deadline tasks
The copy of the patch that failed is found in: .git/rebase-apply/patch
When you have resolved this problem, run "git am --continue".
If you prefer to skip this patch, run "git am --skip" instead.
To restore the original branch and stop patching, run "git am --abort".
[acme@jouet linux]$ git am --abort

I added it manually and applied, please consider using 'git format-patch' next time :-)
> 
> diff --git a/tools/lib/traceevent/plugin_sched_switch.c b/tools/lib/traceevent/plugin_sched_switch.c
> index f1ce600..ec30c2f 100644
> --- a/tools/lib/traceevent/plugin_sched_switch.c
> +++ b/tools/lib/traceevent/plugin_sched_switch.c
> @@ -111,7 +111,7 @@ static int sched_switch_handler(struct trace_seq *s,
>  	trace_seq_printf(s, "%lld ", val);
>  
>  	if (pevent_get_field_val(s, event, "prev_prio", record, &val, 0) == 0)
> -		trace_seq_printf(s, "[%lld] ", val);
> +		trace_seq_printf(s, "[%d] ", (int) val);
>  
>  	if (pevent_get_field_val(s,  event, "prev_state", record, &val, 0) == 0)
>  		write_state(s, val);
> @@ -129,7 +129,7 @@ static int sched_switch_handler(struct trace_seq *s,
>  	trace_seq_printf(s, "%lld", val);
>  
>  	if (pevent_get_field_val(s, event, "next_prio", record, &val, 0) == 0)
> -		trace_seq_printf(s, " [%lld]", val);
> +		trace_seq_printf(s, " [%d]", (int) val);
>  
>  	return 0;
>  }
> -- 
> 2.9.3

Re: [PATCH] tools lib traceevent: Fix prev/next_prio for deadline tasks

[Steven Rostedt]

On Tue,  3 Jan 2017 12:42:42 +0100
Daniel Bristot de Oliveira <bristot@redhat.com> wrote:

> From: Daniel Bristot de Oliveiva <bristot@redhat.com>
> 
> Currently, the sched:sched_switch tracepoint reports deadline tasks
> with priority -1. But when reading the trace via perf script I've
> got the following output:
> 
>   # ./d & # (d is a deadline task, see [1])
>   # perf record -e sched:sched_switch -a sleep 1
>   # perf script
>       ...
>          swapper     0 [000]  2146.962441: sched:sched_switch: swapper/0:0 [120] R ==> d:2593 [4294967295]
>                d  2593 [000]  2146.972472: sched:sched_switch: d:2593 [4294967295] R ==> g:2590 [4294967295]
> 
> The task d reports the wrong priority [4294967295]. This happens because
> the "int prio" is stored in an unsigned long long val. Although it is
> set as a %lld, as int is shorter than unsigned long long,
> trace_seq_printf prints it as a positive number.
> 
> The fix is just to cast the val as an int, and print it as a %d,
> as in the sched:sched_switch tracepoint's "format".
> 
> The output with the fix is:
> 
>   # ./d &
>   # perf record -e sched:sched_switch -a sleep 1
>   # perf script
>       ...
>          swapper     0 [000]  4306.374037: sched:sched_switch: swapper/0:0 [120] R ==> d:10941 [-1]
>                d 10941 [000]  4306.383823: sched:sched_switch: d:10941 [-1] R ==> swapper/0:0 [120]
> 
> [1] gcc -o d d.c - from http://bristot.me/lkml/d.c
> 
> Signed-off-by: Daniel Bristot de Oliveira <bristot@redhat.com>
> Cc: Steven Rostedt <rostedt@goodmis.org>
> Cc: Ingo Molnar <mingo@redhat.com>
> Cc: Peter Zijlstra <peterz@infradead.org>
> Cc: Arnaldo Carvalho de Melo <acme@kernel.org>
> Cc: Alexander Shishkin <alexander.shishkin@linux.intel.com>
> Cc: Jiri Olsa <jolsa@redhat.com>
> Cc: linux-kernel@vger.kernel.org
> 
Acked-by: Steven Rostedt <rostedt@goodmis.org>

---
:-)

-- Steve

Re: [PATCH] tools lib traceevent: Fix prev/next_prio for deadline tasks

[Daniel Bristot de Oliveira]

On 01/03/2017 03:46 PM, Arnaldo Carvalho de Melo wrote:
> you missed the delimiter here:
> 
> ---
> 
> Without it, I get:
> 
> [acme@jouet linux]$ am /wb/1.patch 
> Applying: tools lib traceevent: Fix prev/next_prio for deadline tasks
> fatal: patch with only garbage at line 3
> Patch failed at 0001 tools lib traceevent: Fix prev/next_prio for deadline tasks
> The copy of the patch that failed is found in: .git/rebase-apply/patch
> When you have resolved this problem, run "git am --continue".
> If you prefer to skip this patch, run "git am --skip" instead.
> To restore the original branch and stop patching, run "git am --abort".
> [acme@jouet linux]$ git am --abort
> 
> I added it manually and applied, please consider using 'git format-patch' next time :-)

Odd, I applied this patch using git am before send it to be
sure git would not remove lines starting with "   #". It worked fine.

I did everything using git.. git commit, format-patch, tested with git
am on another branch, then send it using git send-email... it worked fine.

Am I missing something?

-- Daniel

Re: [PATCH] tools lib traceevent: Fix prev/next_prio for deadline tasks

[Arnaldo Carvalho de Melo]

Em Tue, Jan 03, 2017 at 04:01:44PM +0100, Daniel Bristot de Oliveira escreveu:
> On 01/03/2017 03:46 PM, Arnaldo Carvalho de Melo wrote:
> > you missed the delimiter here:
> > 
> > ---
> > 
> > Without it, I get:
> > 
> > [acme@jouet linux]$ am /wb/1.patch 
> > Applying: tools lib traceevent: Fix prev/next_prio for deadline tasks
> > fatal: patch with only garbage at line 3
> > Patch failed at 0001 tools lib traceevent: Fix prev/next_prio for deadline tasks
> > The copy of the patch that failed is found in: .git/rebase-apply/patch
> > When you have resolved this problem, run "git am --continue".
> > If you prefer to skip this patch, run "git am --skip" instead.
> > To restore the original branch and stop patching, run "git am --abort".
> > [acme@jouet linux]$ git am --abort
> > 
> > I added it manually and applied, please consider using 'git format-patch' next time :-)
> 
> Odd, I applied this patch using git am before send it to be
> sure git would not remove lines starting with "   #". It worked fine.
> 
> I did everything using git.. git commit, format-patch, tested with git
> am on another branch, then send it using git send-email... it worked fine.
> 
> Am I missing something?

So maybe this is just my git-am frontend script, that expects a '---',
but then, here, if I use:

[acme@jouet linux]$ git format-patch -n --cover-letter tip/perf/urgent..

I get:

[acme@jouet linux]$ vim 0001-perf-sched-timehist-Show-total-scheduling-time.patch 
<SNIP>
Suggested-by: David Ahern <dsahern@gmail.com>
Signed-off-by: Namhyung Kim <namhyung@kernel.org>
Cc: Jiri Olsa <jolsa@kernel.org>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Link: http://lkml.kernel.org/r/20161222060350.17655-3-namhyung@kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
---
 tools/perf/builtin-sched.c | 17 ++++++++++++++---
 1 file changed, 14 insertions(+), 3 deletions(-)

diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
index d53e706a6f17..5b134b0d1ff3 100644
--- a/tools/perf/builtin-sched.c
+++ b/tools/perf/builtin-sched.c
@@ -209,6 +209,7 @@ struct perf_sched {
        u64             skipped_samples;

Re: [PATCH] tools lib traceevent: Fix prev/next_prio for deadline tasks

[Daniel Bristot de Oliveira]

On 01/03/2017 04:12 PM, Arnaldo Carvalho de Melo wrote:
> So maybe this is just my git-am frontend script, that expects a '---',
> but then, here, if I use:
> 
> [acme@jouet linux]$ git format-patch -n --cover-letter tip/perf/urgent..

I found the problem, I used the -p option in the format-patch. I will
not use it anymore. Sorry for the noise.

-- Daniel

[tip:perf/urgent] tools lib traceevent: Fix prev/next_prio for deadline tasks

[tip-bot for Daniel Bristot de Oliveira]

Commit-ID:  074859184d770824f4437dca716bdeb625ae8b1c
Gitweb:     http://git.kernel.org/tip/074859184d770824f4437dca716bdeb625ae8b1c
Author:     Daniel Bristot de Oliveira <bristot@redhat.com>
AuthorDate: Tue, 3 Jan 2017 12:42:42 +0100
Committer:  Arnaldo Carvalho de Melo <acme@redhat.com>
CommitDate: Tue, 3 Jan 2017 16:11:12 -0300

tools lib traceevent: Fix prev/next_prio for deadline tasks

Currently, the sched:sched_switch tracepoint reports deadline tasks with
priority -1. But when reading the trace via perf script I've got the
following output:

  # ./d & # (d is a deadline task, see [1])
  # perf record -e sched:sched_switch -a sleep 1
  # perf script
      ...
         swapper     0 [000]  2146.962441: sched:sched_switch: swapper/0:0 [120] R ==> d:2593 [4294967295]
               d  2593 [000]  2146.972472: sched:sched_switch: d:2593 [4294967295] R ==> g:2590 [4294967295]

The task d reports the wrong priority [4294967295]. This happens because
the "int prio" is stored in an unsigned long long val. Although it is
set as a %lld, as int is shorter than unsigned long long,
trace_seq_printf prints it as a positive number.

The fix is just to cast the val as an int, and print it as a %d,
as in the sched:sched_switch tracepoint's "format".

The output with the fix is:

  # ./d &
  # perf record -e sched:sched_switch -a sleep 1
  # perf script
      ...
         swapper     0 [000]  4306.374037: sched:sched_switch: swapper/0:0 [120] R ==> d:10941 [-1]
               d 10941 [000]  4306.383823: sched:sched_switch: d:10941 [-1] R ==> swapper/0:0 [120]

[1] d.c

 ---
  #include <stdio.h>
  #include <unistd.h>
  #include <sys/syscall.h>
  #include <linux/types.h>
  #include <linux/sched.h>

  struct sched_attr {
	__u32 size, sched_policy;
	__u64 sched_flags;
	__s32 sched_nice;
	__u32 sched_priority;
	__u64 sched_runtime, sched_deadline, sched_period;
  };

  int sched_setattr(pid_t pid, const struct sched_attr *attr, unsigned int flags)
  {
	return syscall(__NR_sched_setattr, pid, attr, flags);
  }

  int main(void)
  {
	struct sched_attr attr = {
		.size		= sizeof(attr),
		.sched_policy	= SCHED_DEADLINE, /* This creates a 10ms/30ms reservation */
		.sched_runtime	= 10 * 1000 * 1000,
		.sched_period	= attr.sched_deadline = 30 * 1000 * 1000,
	};

	if (sched_setattr(0, &attr, 0) < 0) {
		perror("sched_setattr");
		return -1;
	}

	for(;;);
  }
 ---

Committer notes:

Got the program from the provided URL, http://bristot.me/lkml/d.c,
trimmed it and included in the cset log above, so that we have
everything needed to test it in one place.

Signed-off-by: Daniel Bristot de Oliveira <bristot@redhat.com>
Acked-by: Steven Rostedt <rostedt@goodmis.org>
Tested-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Alexander Shishkin <alexander.shishkin@linux.intel.com>
Cc: Daniel Bristot de Oliveira <bristot@redhat.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Peter Zijlstra <peterz@infradead.org>
Link: http://lkml.kernel.org/r/866ef75bcebf670ae91c6a96daa63597ba981f0d.1483443552.git.bristot@redhat.com
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
---
 tools/lib/traceevent/plugin_sched_switch.c | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/tools/lib/traceevent/plugin_sched_switch.c b/tools/lib/traceevent/plugin_sched_switch.c
index f1ce600..ec30c2f 100644
--- a/tools/lib/traceevent/plugin_sched_switch.c
+++ b/tools/lib/traceevent/plugin_sched_switch.c
@@ -111,7 +111,7 @@ static int sched_switch_handler(struct trace_seq *s,
 	trace_seq_printf(s, "%lld ", val);
 
 	if (pevent_get_field_val(s, event, "prev_prio", record, &val, 0) == 0)
-		trace_seq_printf(s, "[%lld] ", val);
+		trace_seq_printf(s, "[%d] ", (int) val);
 
 	if (pevent_get_field_val(s,  event, "prev_state", record, &val, 0) == 0)
 		write_state(s, val);
@@ -129,7 +129,7 @@ static int sched_switch_handler(struct trace_seq *s,
 	trace_seq_printf(s, "%lld", val);
 
 	if (pevent_get_field_val(s, event, "next_prio", record, &val, 0) == 0)
-		trace_seq_printf(s, " [%lld]", val);
+		trace_seq_printf(s, " [%d]", (int) val);
 
 	return 0;
 }