[PATCH] tracing/irq: use softirq_to_name instead of __print_symbolic

[PATCH] tracing/irq: use softirq_to_name instead of __print_symbolic

[Li Zefan]

| commit c2adae0970ca1db8adb92fb56ae3bcabd916e8bd
| Author: Steven Rostedt <srostedt@redhat.com>
| Date:   Wed May 20 19:56:19 2009 -0400
|
|    tracing: convert irq events to use __print_symbolic
|
|    The recording of the names at trace time is inefficient. This patch
|    implements the softirq event recording to only record the vector
|    and then use the __print_symbolic interface to print out the names.
|
|    [ Impact: faster recording of softirq events ]

It's great to boost recording of softirq events, but why not simply
use softirq_to_name in TP_printk()?

The above commit has 2 flaws:

  - we waste memory defining local static struct trace_print_flags array
    in each softirq TRACE_EVENT
  - if someone adds/removes a softirq, he may not know show_softirq_name()
    needs to be updated

Another issue with the above commit, that the output of softirq events
becomes:

  X-1701  [000]  1595.220739: softirq_entry: softirq=1 action=TIMER_SOFTIRQ

Compared to the original output:

  X-1701  [000]  1595.220739: softirq_entry: softirq=1 action=TIMER

[ Impact: reserve the original output format of softirq events ]

Signed-off-by: Li Zefan <lizf@cn.fujitsu.com>
---
 include/trace/events/irq.h |   17 ++---------------
 1 files changed, 2 insertions(+), 15 deletions(-)

diff --git a/include/trace/events/irq.h b/include/trace/events/irq.h
index 683fb36..2ff9998 100644
--- a/include/trace/events/irq.h
+++ b/include/trace/events/irq.h
@@ -7,19 +7,6 @@
 #undef TRACE_SYSTEM
 #define TRACE_SYSTEM irq
 
-#define softirq_name(sirq) { sirq, #sirq }
-#define show_softirq_name(val)						\
-	__print_symbolic(val,						\
-			 softirq_name(HI_SOFTIRQ),			\
-			 softirq_name(TIMER_SOFTIRQ),			\
-			 softirq_name(NET_TX_SOFTIRQ),			\
-			 softirq_name(NET_RX_SOFTIRQ),			\
-			 softirq_name(BLOCK_SOFTIRQ),			\
-			 softirq_name(TASKLET_SOFTIRQ),			\
-			 softirq_name(SCHED_SOFTIRQ),			\
-			 softirq_name(HRTIMER_SOFTIRQ),			\
-			 softirq_name(RCU_SOFTIRQ))
-
 /**
  * irq_handler_entry - called immediately before the irq action handler
  * @irq: irq number
@@ -107,7 +94,7 @@ TRACE_EVENT(softirq_entry,
 	),
 
 	TP_printk("softirq=%d action=%s", __entry->vec,
-		  show_softirq_name(__entry->vec))
+		  softirq_to_name[__entry->vec])
 );
 
 /**
@@ -136,7 +123,7 @@ TRACE_EVENT(softirq_exit,
 	),
 
 	TP_printk("softirq=%d action=%s", __entry->vec,
-		  show_softirq_name(__entry->vec))
+		  softirq_to_name[__entry->vec])
 );
 
 #endif /*  _TRACE_IRQ_H */
-- 
1.5.4.rc3

Re: [PATCH] tracing/irq: use softirq_to_name instead of __print_symbolic

[Christoph Hellwig]

On Mon, Jun 01, 2009 at 04:52:23PM +0800, Li Zefan wrote:
> It's great to boost recording of softirq events, but why not simply
> use softirq_to_name in TP_printk()?

Because userspace programs using the binary trace buffer have no chance to
retrieve the values from softirq_to_name.

> The above commit has 2 flaws:
> 
>   - we waste memory defining local static struct trace_print_flags array
>     in each softirq TRACE_EVENT

That could be solved by declaring the array manually and just passing
the address to __print_symbolic.  Steve, would that work?  (also for
__print_flags)

>   - if someone adds/removes a softirq, he may not know show_softirq_name()
>     needs to be updated

Just make sure you have the translation defined next to the actual
flags.  This is what I do in the XFS tracer:

typedef enum xfs_alloctype
{
	XFS_ALLOCTYPE_ANY_AG,           /* allocate anywhere, use rotor */
	XFS_ALLOCTYPE_FIRST_AG,         /* ... start at ag 0 */
	XFS_ALLOCTYPE_START_AG,         /* anywhere, start in this a.g. */
	XFS_ALLOCTYPE_THIS_AG,          /* anywhere in this a.g. */
	XFS_ALLOCTYPE_START_BNO,	/* near this block else anywhere */
	XFS_ALLOCTYPE_NEAR_BNO,		/* in this a.g. and near this block */
	XFS_ALLOCTYPE_THIS_BNO		/* at exactly this block */
} xfs_alloctype_t;

#define XFS_ALLOC_TYPES \
	{ XFS_ALLOCTYPE_ANY_AG,         "ANY_AG" }, \
	{ XFS_ALLOCTYPE_FIRST_AG,       "FIRST_AG" }, \
	{ XFS_ALLOCTYPE_START_AG,       "START_AG" }, \
	{ XFS_ALLOCTYPE_THIS_AG,	"THIS_AG" }, \
	{ XFS_ALLOCTYPE_START_BNO,	"START_BNO" }, \
	{ XFS_ALLOCTYPE_NEAR_BNO,	"NEAR_BNO" }, \
	{ XFS_ALLOCTYPE_THIS_BNO,	"THIS_BNO" }

> Another issue with the above commit, that the output of softirq events
> becomes:
> 
>   X-1701  [000]  1595.220739: softirq_entry: softirq=1 action=TIMER_SOFTIRQ
> 
> Compared to the original output:
> 
>   X-1701  [000]  1595.220739: softirq_entry: softirq=1 action=TIMER

Which is trivially fixable, see above :)

Re: [PATCH] tracing/irq: use softirq_to_name instead of __print_symbolic

[Steven Rostedt]

On Mon, 1 Jun 2009, Christoph Hellwig wrote:

> On Mon, Jun 01, 2009 at 04:52:23PM +0800, Li Zefan wrote:
> > It's great to boost recording of softirq events, but why not simply
> > use softirq_to_name in TP_printk()?
> 
> Because userspace programs using the binary trace buffer have no chance to
> retrieve the values from softirq_to_name.
> 
> > The above commit has 2 flaws:
> > 
> >   - we waste memory defining local static struct trace_print_flags array
> >     in each softirq TRACE_EVENT
> 
> That could be solved by declaring the array manually and just passing
> the address to __print_symbolic.  Steve, would that work?  (also for
> __print_flags)

I added the code to make it an array, but we still need to allocate it for 
every trace call. Otherwise, how do we export the information to 
userspace. One trace event (currently) has no way of depending on another 
trace event. If two trace events want the same array, currently they both 
must allocate it. I haven't looked too deeply into seeing how to manage 
that. It's not that much memory duplicated. I hate to make the code even 
more complex just to save a couple of hundred of bytes.

> 
> >   - if someone adds/removes a softirq, he may not know show_softirq_name()
> >     needs to be updated
> 
> Just make sure you have the translation defined next to the actual
> flags.  This is what I do in the XFS tracer:
> 
> typedef enum xfs_alloctype
> {
> 	XFS_ALLOCTYPE_ANY_AG,           /* allocate anywhere, use rotor */
> 	XFS_ALLOCTYPE_FIRST_AG,         /* ... start at ag 0 */
> 	XFS_ALLOCTYPE_START_AG,         /* anywhere, start in this a.g. */
> 	XFS_ALLOCTYPE_THIS_AG,          /* anywhere in this a.g. */
> 	XFS_ALLOCTYPE_START_BNO,	/* near this block else anywhere */
> 	XFS_ALLOCTYPE_NEAR_BNO,		/* in this a.g. and near this block */
> 	XFS_ALLOCTYPE_THIS_BNO		/* at exactly this block */
> } xfs_alloctype_t;
> 
> #define XFS_ALLOC_TYPES \
> 	{ XFS_ALLOCTYPE_ANY_AG,         "ANY_AG" }, \
> 	{ XFS_ALLOCTYPE_FIRST_AG,       "FIRST_AG" }, \
> 	{ XFS_ALLOCTYPE_START_AG,       "START_AG" }, \
> 	{ XFS_ALLOCTYPE_THIS_AG,	"THIS_AG" }, \
> 	{ XFS_ALLOCTYPE_START_BNO,	"START_BNO" }, \
> 	{ XFS_ALLOCTYPE_NEAR_BNO,	"NEAR_BNO" }, \
> 	{ XFS_ALLOCTYPE_THIS_BNO,	"THIS_BNO" }
> 
> > Another issue with the above commit, that the output of softirq events
> > becomes:
> > 
> >   X-1701  [000]  1595.220739: softirq_entry: softirq=1 action=TIMER_SOFTIRQ
> > 
> > Compared to the original output:
> > 
> >   X-1701  [000]  1595.220739: softirq_entry: softirq=1 action=TIMER
> 
> Which is trivially fixable, see above :)

Hmm, I thought I fixed that already. Perhaps it is in the code that Ingo 
has not pulled.

-- Steve

Re: [PATCH] tracing/irq: use softirq_to_name instead of __print_symbolic

[Li Zefan]

Steven Rostedt wrote:
> On Mon, 1 Jun 2009, Christoph Hellwig wrote:
> 
>> On Mon, Jun 01, 2009 at 04:52:23PM +0800, Li Zefan wrote:
>>> It's great to boost recording of softirq events, but why not simply
>>> use softirq_to_name in TP_printk()?
>> Because userspace programs using the binary trace buffer have no chance to
>> retrieve the values from softirq_to_name.
>>

Do you mean, by parsing the format file?

# cat events/irq/softirq_entry/format
	...
print fmt: "softirq=%d action=%s", REC->vec, ({ static const struct trace_print_flags
symbols[] =  { { HI_SOFTIRQ, "HI_SOFTIRQ" }, { TIMER_SOFTIRQ, "TIMER_SOFTIRQ" },
{ NET_TX_SOFTIRQ, "NET_TX_SOFTIRQ" }, { NET_RX_SOFTIRQ, "NET_RX_SOFTIRQ" },
{ BLOCK_SOFTIRQ, "BLOCK_SOFTIRQ" }, { TASKLET_SOFTIRQ, "TASKLET_SOFTIRQ" }, 
{ SCHED_SOFTIRQ, "SCHED_SOFTIRQ" }, { HRTIMER_SOFTIRQ, "HRTIMER_SOFTIRQ" },
{ RCU_SOFTIRQ, "RCU_SOFTIRQ" },  { -1, ((void *)0) }};
ftrace_print_symbols_seq(p, REC->vec, symbols); })

>>> The above commit has 2 flaws:
>>>
>>>   - we waste memory defining local static struct trace_print_flags array
>>>     in each softirq TRACE_EVENT
>> That could be solved by declaring the array manually and just passing
>> the address to __print_symbolic.  Steve, would that work?  (also for
>> __print_flags)
> 
> I added the code to make it an array, but we still need to allocate it for 
> every trace call. Otherwise, how do we export the information to 
> userspace. One trace event (currently) has no way of depending on another 
> trace event. If two trace events want the same array, currently they both 
> must allocate it. I haven't looked too deeply into seeing how to manage 
> that. It's not that much memory duplicated. I hate to make the code even 
> more complex just to save a couple of hundred of bytes.
> 
>>>   - if someone adds/removes a softirq, he may not know show_softirq_name()
>>>     needs to be updated
>> Just make sure you have the translation defined next to the actual
>> flags.  This is what I do in the XFS tracer:
>>
>> typedef enum xfs_alloctype
>> {
>> 	XFS_ALLOCTYPE_ANY_AG,           /* allocate anywhere, use rotor */
>> 	XFS_ALLOCTYPE_FIRST_AG,         /* ... start at ag 0 */
>> 	XFS_ALLOCTYPE_START_AG,         /* anywhere, start in this a.g. */
>> 	XFS_ALLOCTYPE_THIS_AG,          /* anywhere in this a.g. */
>> 	XFS_ALLOCTYPE_START_BNO,	/* near this block else anywhere */
>> 	XFS_ALLOCTYPE_NEAR_BNO,		/* in this a.g. and near this block */
>> 	XFS_ALLOCTYPE_THIS_BNO		/* at exactly this block */
>> } xfs_alloctype_t;
>>
>> #define XFS_ALLOC_TYPES \
>> 	{ XFS_ALLOCTYPE_ANY_AG,         "ANY_AG" }, \
>> 	{ XFS_ALLOCTYPE_FIRST_AG,       "FIRST_AG" }, \
>> 	{ XFS_ALLOCTYPE_START_AG,       "START_AG" }, \
>> 	{ XFS_ALLOCTYPE_THIS_AG,	"THIS_AG" }, \
>> 	{ XFS_ALLOCTYPE_START_BNO,	"START_BNO" }, \
>> 	{ XFS_ALLOCTYPE_NEAR_BNO,	"NEAR_BNO" }, \
>> 	{ XFS_ALLOCTYPE_THIS_BNO,	"THIS_BNO" }
>>
>>> Another issue with the above commit, that the output of softirq events
>>> becomes:
>>>
>>>   X-1701  [000]  1595.220739: softirq_entry: softirq=1 action=TIMER_SOFTIRQ
>>>
>>> Compared to the original output:
>>>
>>>   X-1701  [000]  1595.220739: softirq_entry: softirq=1 action=TIMER
>> Which is trivially fixable, see above :)
> 
> Hmm, I thought I fixed that already. Perhaps it is in the code that Ingo 
> has not pulled.
> 

I guess you forgot to fix it. ;)

I made a comment on that patch, but seems you didn't update the patch:
	http://lkml.org/lkml/2009/5/21/9

I'll make a patch for this.