* timers: Make flags output in the timer_start tracepoint useful
@ 2017-02-10 13:25 Thomas Gleixner
2017-02-10 14:19 ` Steven Rostedt
0 siblings, 1 reply; 7+ messages in thread
From: Thomas Gleixner @ 2017-02-10 13:25 UTC (permalink / raw)
To: LKML; +Cc: Peter Zijlstra, Steven Rostedt, Arjan van de Ven
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))
);
/**
^ permalink raw reply [flat|nested] 7+ messages in thread* Re: timers: Make flags output in the timer_start tracepoint useful
2017-02-10 13:25 timers: Make flags output in the timer_start tracepoint useful Thomas Gleixner
@ 2017-02-10 14:19 ` Steven Rostedt
2017-02-10 14:37 ` Thomas Gleixner
0 siblings, 1 reply; 7+ messages in thread
From: Steven Rostedt @ 2017-02-10 14:19 UTC (permalink / raw)
To: Thomas Gleixner; +Cc: LKML, Peter Zijlstra, Arjan van de Ven
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
> );
>
> /**
^ permalink raw reply [flat|nested] 7+ messages in thread* Re: timers: Make flags output in the timer_start tracepoint useful
2017-02-10 14:19 ` Steven Rostedt
@ 2017-02-10 14:37 ` Thomas Gleixner
2017-02-10 14:51 ` Steven Rostedt
0 siblings, 1 reply; 7+ messages in thread
From: Thomas Gleixner @ 2017-02-10 14:37 UTC (permalink / raw)
To: Steven Rostedt; +Cc: LKML, Peter Zijlstra, Arjan van de Ven
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 ....
^ permalink raw reply [flat|nested] 7+ messages in thread* Re: timers: Make flags output in the timer_start tracepoint useful
2017-02-10 14:37 ` Thomas Gleixner
@ 2017-02-10 14:51 ` Steven Rostedt
2017-02-10 15:28 ` Thomas Gleixner
0 siblings, 1 reply; 7+ messages in thread
From: Steven Rostedt @ 2017-02-10 14:51 UTC (permalink / raw)
To: Thomas Gleixner; +Cc: LKML, Peter Zijlstra, Arjan van de Ven
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
^ permalink raw reply [flat|nested] 7+ messages in thread* Re: timers: Make flags output in the timer_start tracepoint useful
2017-02-10 14:51 ` Steven Rostedt
@ 2017-02-10 15:28 ` Thomas Gleixner
2017-02-10 15:41 ` [PATCH V2] " Thomas Gleixner
0 siblings, 1 reply; 7+ messages in thread
From: Thomas Gleixner @ 2017-02-10 15:28 UTC (permalink / raw)
To: Steven Rostedt; +Cc: LKML, Peter Zijlstra, Arjan van de Ven
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), \
^ permalink raw reply [flat|nested] 7+ messages in thread* [PATCH V2] timers: Make flags output in the timer_start tracepoint useful
2017-02-10 15:28 ` Thomas Gleixner
@ 2017-02-10 15:41 ` Thomas Gleixner
2017-02-10 16:11 ` Steven Rostedt
0 siblings, 1 reply; 7+ messages in thread
From: Thomas Gleixner @ 2017-02-10 15:41 UTC (permalink / raw)
To: Steven Rostedt; +Cc: LKML, Peter Zijlstra, Arjan van de Ven
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))
);
/**
^ permalink raw reply [flat|nested] 7+ messages in thread* Re: [PATCH V2] timers: Make flags output in the timer_start tracepoint useful
2017-02-10 15:41 ` [PATCH V2] " Thomas Gleixner
@ 2017-02-10 16:11 ` Steven Rostedt
0 siblings, 0 replies; 7+ messages in thread
From: Steven Rostedt @ 2017-02-10 16:11 UTC (permalink / raw)
To: Thomas Gleixner; +Cc: LKML, Peter Zijlstra, Arjan van de Ven
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
^ permalink raw reply [flat|nested] 7+ messages in thread
end of thread, other threads:[~2017-02-10 16:11 UTC | newest]
Thread overview: 7+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2017-02-10 13:25 timers: Make flags output in the timer_start tracepoint useful Thomas Gleixner
2017-02-10 14:19 ` Steven Rostedt
2017-02-10 14:37 ` Thomas Gleixner
2017-02-10 14:51 ` Steven Rostedt
2017-02-10 15:28 ` Thomas Gleixner
2017-02-10 15:41 ` [PATCH V2] " Thomas Gleixner
2017-02-10 16:11 ` Steven Rostedt
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox
all inboxes | Powered by JetHome®