xfs
[Top] [All Lists]

Re: [PATCH 2/2] xfs: Nuke XFS_ERROR macro

To: Steven Rostedt <rostedt@xxxxxxxxxxx>
Subject: Re: [PATCH 2/2] xfs: Nuke XFS_ERROR macro
From: Dave Chinner <david@xxxxxxxxxxxxx>
Date: Thu, 17 Apr 2014 10:39:56 +1000
Cc: Eric Sandeen <sandeen@xxxxxxxxxxx>, Christoph Hellwig <hch@xxxxxxxxxxxxx>, xfs-oss <xfs@xxxxxxxxxxx>
Delivered-to: xfs@xxxxxxxxxxx
In-reply-to: <20140416194444.50176f0f@xxxxxxxxxxxxxxxxxx>
References: <534EC073.8090006@xxxxxxxxxxx> <534EC282.7010905@xxxxxxxxxxx> <20140416175117.GA23643@xxxxxxxxxxxxx> <534EC42D.1080704@xxxxxxxxxxx> <534ED5E4.60903@xxxxxxxxxxx> <20140416220807.GN15995@dastard> <20140416194444.50176f0f@xxxxxxxxxxxxxxxxxx>
User-agent: Mutt/1.5.21 (2010-09-15)
On Wed, Apr 16, 2014 at 07:44:44PM -0400, Steven Rostedt wrote:
> On Thu, 17 Apr 2014 08:08:08 +1000
> Dave Chinner <david@xxxxxxxxxxxxx> wrote:
> 
>  
> > > Here's the "best" I've come up with so far...
> > > 
> > > # for FUNCTION in `grep "t xfs_" /proc/kallsyms | awk '{print $3}'`; do 
> > > echo "r:ret_$FUNCTION $FUNCTION \$retval" >> 
> > > /sys/kernel/debug/tracing/kprobe_events; done
> 
> BTW, it's usually better to do:
> 
> grep 't xfs_' /proc/kallsyms | awk '{print $3}' ; while read FUNCTION; do ....

grep -i 't xfs' .....

> > > # for ENABLE in 
> > > /sys/kernel/debug/tracing/events/kprobes/ret_xfs_*/enable; do echo 1 > 
> > > $ENABLE; done
> > > 
> > > run a test that fails:
> > > 
> > > # dd if=/dev/zero of=newfile bs=513 oflag=direct
> > > dd: writing `newfile': Invalid argument
> > > 
> > > # for ENABLE in 
> > > /sys/kernel/debug/tracing/events/kprobes/ret_xfs_*/enable; do echo 0 > 
> > > $ENABLE; done
> > > 
> > > # cat /sys/kernel/debug/tracing/trace
> > > <snip>
> > >            <...>-63791 [000] d... 705435.568913: ret_xfs_vn_mknod: 
> > > (xfs_vn_create+0x13/0x20 [xfs] <- xfs_vn_mknod) arg1=0
> > >            <...>-63791 [000] d... 705435.568913: ret_xfs_vn_create: 
> > > (vfs_create+0xdb/0x100 <- xfs_vn_create) arg1=0
> > >            <...>-63791 [000] d... 705435.568918: ret_xfs_file_open: 
> > > (do_dentry_open+0x24e/0x2e0 <- xfs_file_open) arg1=0
> > >            <...>-63791 [000] d... 705435.568934: 
> > > ret_xfs_file_dio_aio_write: (xfs_file_aio_write+0x147/0x150 [xfs] <- 
> > > xfs_file_dio_aio_write) arg1=ffffffffffffffea
> > > 
> > > Hey look, it's "-22" in hex!  ;)
> > > 
> > > so it's possible, but bleah.
> > 
> > Steve, we want to be able to trap specific return codes from
> > functions. Say, for example, the first function that returns
> > EINVAL/-EINVAL in XFS under a given workload.
> > 
> > What's the most efficient way to do that with ftrace?
> > 
> > And can that be set up as a trigger so we can use it to dump a
> > snapshot of the last N events into the trace buffer or do other
> > interesting things with that event?
> 
> Well, after you do the above, you could also do a while loop to all
> those events and update the filter:
> 
> echo 'arg1 > 0xffffffffffffff00' > /debug/tracing/events/kprobes/filter
> 
> Which would trace only those functions that had an error code (assuming
> the error code is less than 256). You could also use the trigger files:
> 
> echo 'traceoff if arg1 > 0xffffffffffffff00' > 
> /debug/tracing/events/kprobes/*/trigger
> 
> The above wont actually work as is, you would need to do another while
> loop of trigger files and set them each individually.

so, basically a script that does:

#!/bin/bash

TRACEDIR=/sys/kernel/debug/tracing

grep -i 't xfs_' /proc/kallsyms | awk '{print $3}' ; while read F; do
        echo "r:ret_$F $F \$retval" >> $TRACEDIR/kprobe_events
done

for E in $TRACEDIR/events/kprobes/ret_xfs_*/enable; do
        echo 1 > $E
done;

echo 'arg1 > 0xffffffffffffff00' > $TRACEDIR/events/kprobes/filter

for T in $TRACEDIR/events/kprobes/ret_xfs_*/trigger; do
        echo 'traceoff if arg1 > 0xffffffffffffff00' > $T
done

And that gives:

# dd if=/dev/zero of=/mnt/scratch/newfile bs=513 oflag=direct
dd: error writing ¿/mnt/scratch/newfile¿: Invalid argument
1+0 records in
0+0 records out
0 bytes (0 B) copied, 0.000259882 s, 0.0 kB/s
root@test4:~# cat /sys/kernel/debug/tracing/trace
# tracer: nop
#
# entries-in-buffer/entries-written: 1/1   #P:16
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
           <...>-8073  [006] d... 145740.460546: ret_xfs_file_dio_aio_write: 
(xfs_file_aio_write+0x170/0x180 <- xfs_file_dio_aio_write) 
arg1=0xffffffffffffffea

Which is precisely the detection that XFS_ERROR would have given us.
Ok, so I guess we can now add whatever need need to that trigger...

Basically, pass in teh XFs function names you want to trace, the
sets up teh events, whatever trigger beahviour you want, and
we're off to the races...

Cheers,

Dave.
-- 
Dave Chinner
david@xxxxxxxxxxxxx

<Prev in Thread] Current Thread [Next in Thread>