Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > linux.kernel > #1578486 > unrolled thread

Re: timers: Make flags output in the timer_start tracepoint useful

Started bySteven Rostedt <rostedt@goodmis.org>
First post2017-02-10 15:20 +0100
Last post2017-02-10 17:20 +0100
Articles 6 — 2 participants

Back to article view | Back to linux.kernel

This discussion starts older than the indexed window; earlier articles aren't shown. The article labeled Started by below is the oldest one visible, not the original post.

Contents

  Re: timers:  Make flags output in the timer_start tracepoint useful Steven Rostedt <rostedt@goodmis.org> - 2017-02-10 15:20 +0100
    Re: timers: Make flags output in the timer_start tracepoint useful Thomas Gleixner <tglx@linutronix.de> - 2017-02-10 15:40 +0100
      Re: timers: Make flags output in the timer_start tracepoint useful Steven Rostedt <rostedt@goodmis.org> - 2017-02-10 16:00 +0100
        Re: timers: Make flags output in the timer_start tracepoint useful Thomas Gleixner <tglx@linutronix.de> - 2017-02-10 16:30 +0100
          [PATCH V2]  timers: Make flags output in the timer_start tracepoint  useful Thomas Gleixner <tglx@linutronix.de> - 2017-02-10 16:50 +0100
            Re: [PATCH V2]  timers: Make flags output in the timer_start  tracepoint useful Steven Rostedt <rostedt@goodmis.org> - 2017-02-10 17:20 +0100

#1578486 — Re: timers: Make flags output in the timer_start tracepoint useful

FromSteven Rostedt <rostedt@goodmis.org>
Date2017-02-10 15:20 +0100
SubjectRe: timers: Make flags output in the timer_start tracepoint useful
Message-ID<t9kdj-4sU-3@gated-at.bofh.it>
On Fri, 10 Feb 2017 14:25:03 +0100 (CET)
Thomas Gleixner <tglx@linutronix.de> wrote:

> The timer flags in the timer_start trace event contain lots of useful
> information, but the meaning is not clear in the trace output because its
> just printed as a hex value. Making tools rely on the bit positions is bad
> as they might change over time.
> 
> Decode the flags in the printout. Tools can retrieve the bits and their
> meaning from the trace format file.
> 
> Example output:
> kworker/2:1-47    <SNIP> [timeout=592] cpu=2 idx=170 flags=D|I
> 
> So the timer is Deferrable and Interruptsafe, queued on CPU 2 into bucket
> 170.
> 
> Requested-by: Arjan van de Ven <arjan@linux.intel.com>
> Signed-off-by: Thomas Gleixner <tglx@linutronix.de>
> ---
>  include/trace/events/timer.h |   14 ++++++++++++--
>  1 file changed, 12 insertions(+), 2 deletions(-)
> 
> --- a/include/trace/events/timer.h
> +++ b/include/trace/events/timer.h
> @@ -36,6 +36,13 @@ DEFINE_EVENT(timer_class, timer_init,
>  	TP_ARGS(timer)
>  );
>  
> +#define decode_timer_flags(flags)			\
> +	__print_flags(flags, "|",			\
> +		{  TIMER_MIGRATING,	"M" },		\
> +		{  TIMER_DEFERRABLE,	"D" },		\
> +		{  TIMER_PINNED,	"P" },		\
> +		{  TIMER_IRQSAFE,	"I" })
> +
>  /**
>   * timer_start - called when the timer is started
>   * @timer:	pointer to struct timer_list
> @@ -65,9 +72,12 @@ TRACE_EVENT(timer_start,
>  		__entry->flags		= flags;
>  	),
>  
> -	TP_printk("timer=%p function=%pf expires=%lu [timeout=%ld] flags=0x%08x",
> +	TP_printk("timer=%p function=%pf expires=%lu [timeout=%ld] cpu=%u idx=%u flags=%s",
>  		  __entry->timer, __entry->function, __entry->expires,
> -		  (long)__entry->expires - __entry->now, __entry->flags)
> +		  (long)__entry->expires - __entry->now,
> +		  __entry->flags & TIMER_CPUMASK,
> +		  __entry->flags >> TIMER_ARRAYSHIFT,
> +		  decode_timer_flags(__entry->flags & TIMER_TRACE_FLAGMASK))

Hi Thomas,

This all looks good, but I can't find TIMER_TRACE_FLAGMASK. Was that
added by another patch?

-- Steve

>  );
>  
>  /**

[toc] | [next] | [standalone]

#1578514 — Re: timers: Make flags output in the timer_start tracepoint useful

FromThomas Gleixner <tglx@linutronix.de>
Date2017-02-10 15:40 +0100
SubjectRe: timers: Make flags output in the timer_start tracepoint useful
Message-ID<t9kwG-4AQ-27@gated-at.bofh.it>
In reply to#1578486
On Fri, 10 Feb 2017, Steven Rostedt wrote:

> On Fri, 10 Feb 2017 14:25:03 +0100 (CET)
> Thomas Gleixner <tglx@linutronix.de> wrote:
> 
> > The timer flags in the timer_start trace event contain lots of useful
> > information, but the meaning is not clear in the trace output because its
> > just printed as a hex value. Making tools rely on the bit positions is bad
> > as they might change over time.
> > 
> > Decode the flags in the printout. Tools can retrieve the bits and their
> > meaning from the trace format file.
> > 
> > Example output:
> > kworker/2:1-47    <SNIP> [timeout=592] cpu=2 idx=170 flags=D|I
> > 
> > So the timer is Deferrable and Interruptsafe, queued on CPU 2 into bucket
> > 170.
> > 
> > Requested-by: Arjan van de Ven <arjan@linux.intel.com>
> > Signed-off-by: Thomas Gleixner <tglx@linutronix.de>
> > ---
> >  include/trace/events/timer.h |   14 ++++++++++++--
> >  1 file changed, 12 insertions(+), 2 deletions(-)
> > 
> > --- a/include/trace/events/timer.h
> > +++ b/include/trace/events/timer.h
> > @@ -36,6 +36,13 @@ DEFINE_EVENT(timer_class, timer_init,
> >  	TP_ARGS(timer)
> >  );
> >  
> > +#define decode_timer_flags(flags)			\
> > +	__print_flags(flags, "|",			\
> > +		{  TIMER_MIGRATING,	"M" },		\
> > +		{  TIMER_DEFERRABLE,	"D" },		\
> > +		{  TIMER_PINNED,	"P" },		\
> > +		{  TIMER_IRQSAFE,	"I" })
> > +
> >  /**
> >   * timer_start - called when the timer is started
> >   * @timer:	pointer to struct timer_list
> > @@ -65,9 +72,12 @@ TRACE_EVENT(timer_start,
> >  		__entry->flags		= flags;
> >  	),
> >  
> > -	TP_printk("timer=%p function=%pf expires=%lu [timeout=%ld] flags=0x%08x",
> > +	TP_printk("timer=%p function=%pf expires=%lu [timeout=%ld] cpu=%u idx=%u flags=%s",
> >  		  __entry->timer, __entry->function, __entry->expires,
> > -		  (long)__entry->expires - __entry->now, __entry->flags)
> > +		  (long)__entry->expires - __entry->now,
> > +		  __entry->flags & TIMER_CPUMASK,
> > +		  __entry->flags >> TIMER_ARRAYSHIFT,
> > +		  decode_timer_flags(__entry->flags & TIMER_TRACE_FLAGMASK))
> 
> Hi Thomas,
> 
> This all looks good, but I can't find TIMER_TRACE_FLAGMASK. Was that
> added by another patch?

-ENO_QUILT_REFRESH ....

[toc] | [prev] | [next] | [standalone]

#1578525 — Re: timers: Make flags output in the timer_start tracepoint useful

FromSteven Rostedt <rostedt@goodmis.org>
Date2017-02-10 16:00 +0100
SubjectRe: timers: Make flags output in the timer_start tracepoint useful
Message-ID<t9kQ2-4Jf-7@gated-at.bofh.it>
In reply to#1578514
On Fri, 10 Feb 2017 15:37:11 +0100 (CET)
Thomas Gleixner <tglx@linutronix.de> wrote:

> > > --- a/include/trace/events/timer.h
> > > +++ b/include/trace/events/timer.h
> > > @@ -36,6 +36,13 @@ DEFINE_EVENT(timer_class, timer_init,
> > >  	TP_ARGS(timer)
> > >  );
> > >  
> > > +#define decode_timer_flags(flags)			\
> > > +	__print_flags(flags, "|",			\
> > > +		{  TIMER_MIGRATING,	"M" },		\
> > > +		{  TIMER_DEFERRABLE,	"D" },		\
> > > +		{  TIMER_PINNED,	"P" },		\
> > > +		{  TIMER_IRQSAFE,	"I" })
> > > +
> > >  /**
> > >   * timer_start - called when the timer is started
> > >   * @timer:	pointer to struct timer_list
> > > @@ -65,9 +72,12 @@ TRACE_EVENT(timer_start,
> > >  		__entry->flags		= flags;
> > >  	),
> > >  
> > > -	TP_printk("timer=%p function=%pf expires=%lu [timeout=%ld] flags=0x%08x",
> > > +	TP_printk("timer=%p function=%pf expires=%lu [timeout=%ld] cpu=%u idx=%u flags=%s",
> > >  		  __entry->timer, __entry->function, __entry->expires,
> > > -		  (long)__entry->expires - __entry->now, __entry->flags)
> > > +		  (long)__entry->expires - __entry->now,
> > > +		  __entry->flags & TIMER_CPUMASK,
> > > +		  __entry->flags >> TIMER_ARRAYSHIFT,
> > > +		  decode_timer_flags(__entry->flags & TIMER_TRACE_FLAGMASK))  
> > 
> > Hi Thomas,
> > 
> > This all looks good, but I can't find TIMER_TRACE_FLAGMASK. Was that
> > added by another patch?  
> 
> -ENO_QUILT_REFRESH ....

I'm wondering if it wouldn't just make sense to add another mask in
include/linux/timer.h along with the other TIMER macros?

#define TIMER_TYPEMASK	0x003C0000

Or some other name?

-- Steve

[toc] | [prev] | [next] | [standalone]

#1578548 — Re: timers: Make flags output in the timer_start tracepoint useful

FromThomas Gleixner <tglx@linutronix.de>
Date2017-02-10 16:30 +0100
SubjectRe: timers: Make flags output in the timer_start tracepoint useful
Message-ID<t9lj3-5a6-3@gated-at.bofh.it>
In reply to#1578525
On Fri, 10 Feb 2017, Steven Rostedt wrote:

> On Fri, 10 Feb 2017 15:37:11 +0100 (CET)
> Thomas Gleixner <tglx@linutronix.de> wrote:
> 
> > > > --- a/include/trace/events/timer.h
> > > > +++ b/include/trace/events/timer.h
> > > > @@ -36,6 +36,13 @@ DEFINE_EVENT(timer_class, timer_init,
> > > >  	TP_ARGS(timer)
> > > >  );
> > > >  
> > > > +#define decode_timer_flags(flags)			\
> > > > +	__print_flags(flags, "|",			\
> > > > +		{  TIMER_MIGRATING,	"M" },		\
> > > > +		{  TIMER_DEFERRABLE,	"D" },		\
> > > > +		{  TIMER_PINNED,	"P" },		\
> > > > +		{  TIMER_IRQSAFE,	"I" })
> > > > +
> > > >  /**
> > > >   * timer_start - called when the timer is started
> > > >   * @timer:	pointer to struct timer_list
> > > > @@ -65,9 +72,12 @@ TRACE_EVENT(timer_start,
> > > >  		__entry->flags		= flags;
> > > >  	),
> > > >  
> > > > -	TP_printk("timer=%p function=%pf expires=%lu [timeout=%ld] flags=0x%08x",
> > > > +	TP_printk("timer=%p function=%pf expires=%lu [timeout=%ld] cpu=%u idx=%u flags=%s",
> > > >  		  __entry->timer, __entry->function, __entry->expires,
> > > > -		  (long)__entry->expires - __entry->now, __entry->flags)
> > > > +		  (long)__entry->expires - __entry->now,
> > > > +		  __entry->flags & TIMER_CPUMASK,
> > > > +		  __entry->flags >> TIMER_ARRAYSHIFT,
> > > > +		  decode_timer_flags(__entry->flags & TIMER_TRACE_FLAGMASK))  
> > > 
> > > Hi Thomas,
> > > 
> > > This all looks good, but I can't find TIMER_TRACE_FLAGMASK. Was that
> > > added by another patch?  
> > 
> > -ENO_QUILT_REFRESH ....
> 
> I'm wondering if it wouldn't just make sense to add another mask in
> include/linux/timer.h along with the other TIMER macros?

That's the missing hunk from timer.h which I did not refresh after testing it ....

--- a/include/linux/timer.h
+++ b/include/linux/timer.h
@@ -66,6 +66,8 @@ struct timer_list {
 #define TIMER_ARRAYSHIFT       22
 #define TIMER_ARRAYMASK                0xFFC00000
 
+#define TIMER_TRACE_FLAGMASK   (TIMER_MIGRATING | TIMER_DEFERRABLE | TIMER_PINNED | TIMER_IRQSAFE)
+
 #define __TIMER_INITIALIZER(_function, _expires, _data, _flags) { \
                .entry = { .next = TIMER_ENTRY_STATIC },        \
                .function = (_function),                        \

[toc] | [prev] | [next] | [standalone]

#1578563 — [PATCH V2] timers: Make flags output in the timer_start tracepoint useful

FromThomas Gleixner <tglx@linutronix.de>
Date2017-02-10 16:50 +0100
Subject[PATCH V2] timers: Make flags output in the timer_start tracepoint useful
Message-ID<t9lCp-5i1-5@gated-at.bofh.it>
In reply to#1578548
The timer flags in the timer_start trace event contain lots of useful
information, but the meaning is not clear in the trace output. Making tools
rely on the bit positions is bad as they might change over time.

Decode the flags in the print out. Tools can retrieve the bits and their
meaning from the trace format file.

Requested-by: Arjan van de Ven <arjan@linux.intel.com>
Signed-off-by: Thomas Gleixner <tglx@linutronix.de>
---
V2: Add the missing hunk defining the mask in timer.h
---
 include/linux/timer.h        |    2 ++
 include/trace/events/timer.h |   14 ++++++++++++--
 2 files changed, 14 insertions(+), 2 deletions(-)

--- a/include/linux/timer.h
+++ b/include/linux/timer.h
@@ -66,6 +66,8 @@ struct timer_list {
 #define TIMER_ARRAYSHIFT	22
 #define TIMER_ARRAYMASK		0xFFC00000
 
+#define TIMER_TRACE_FLAGMASK	(TIMER_MIGRATING | TIMER_DEFERRABLE | TIMER_PINNED | TIMER_IRQSAFE)
+
 #define __TIMER_INITIALIZER(_function, _expires, _data, _flags) { \
 		.entry = { .next = TIMER_ENTRY_STATIC },	\
 		.function = (_function),			\
--- a/include/trace/events/timer.h
+++ b/include/trace/events/timer.h
@@ -36,6 +36,13 @@ DEFINE_EVENT(timer_class, timer_init,
 	TP_ARGS(timer)
 );
 
+#define decode_timer_flags(flags)			\
+	__print_flags(flags, "|",			\
+		{  TIMER_MIGRATING,	"M" },		\
+		{  TIMER_DEFERRABLE,	"D" },		\
+		{  TIMER_PINNED,	"P" },		\
+		{  TIMER_IRQSAFE,	"I" })
+
 /**
  * timer_start - called when the timer is started
  * @timer:	pointer to struct timer_list
@@ -65,9 +72,12 @@ TRACE_EVENT(timer_start,
 		__entry->flags		= flags;
 	),
 
-	TP_printk("timer=%p function=%pf expires=%lu [timeout=%ld] flags=0x%08x",
+	TP_printk("timer=%p function=%pf expires=%lu [timeout=%ld] cpu=%u idx=%u flags=%s",
 		  __entry->timer, __entry->function, __entry->expires,
-		  (long)__entry->expires - __entry->now, __entry->flags)
+		  (long)__entry->expires - __entry->now,
+		  __entry->flags & TIMER_CPUMASK,
+		  __entry->flags >> TIMER_ARRAYSHIFT,
+		  decode_timer_flags(__entry->flags & TIMER_TRACE_FLAGMASK))
 );
 
 /**

[toc] | [prev] | [next] | [standalone]

#1578580 — Re: [PATCH V2] timers: Make flags output in the timer_start tracepoint useful

FromSteven Rostedt <rostedt@goodmis.org>
Date2017-02-10 17:20 +0100
SubjectRe: [PATCH V2] timers: Make flags output in the timer_start tracepoint useful
Message-ID<t9m5r-5JI-3@gated-at.bofh.it>
In reply to#1578563
On Fri, 10 Feb 2017 16:41:15 +0100 (CET)
Thomas Gleixner <tglx@linutronix.de> wrote:

> The timer flags in the timer_start trace event contain lots of useful
> information, but the meaning is not clear in the trace output. Making tools
> rely on the bit positions is bad as they might change over time.
> 
> Decode the flags in the print out. Tools can retrieve the bits and their
> meaning from the trace format file.
> 
> Requested-by: Arjan van de Ven <arjan@linux.intel.com>
> Signed-off-by: Thomas Gleixner <tglx@linutronix.de>
> ---
> V2: Add the missing hunk defining the mask in timer.h
> ---

Applied, Thanks!

-- Steve

[toc] | [prev] | [standalone]

Back to top | Article view | linux.kernel

csiph-web