On Mon, Jul 15, 2013 at 09:42:44PM -0400, Dave Jones wrote:
> On Tue, Jul 16, 2013 at 10:27:03AM +1000, Dave Chinner wrote:
> > On Mon, Jul 15, 2013 at 03:58:00PM -0400, Dave Jones wrote:
> > > On Sat, Jul 13, 2013 at 12:00:30PM +1000, Dave Chinner wrote:
> > >
> > > > > [ 97.162665] XFS: Assertion failed: xfs_dir2_sf_lookup(args) ==
> ENOENT, file: fs/xfs/xfs_dir2_sf.c, line: 358
> > > > ....
> > > >
> > > > So, it's not clear what has caused this yet. Is it reproducable?
> > >
> > > Just hit it again on the same machine.
> > >
> > > > would be good to get a trace of lookup vs addname events from XFS,
> > > > too (i.e. all the xfs_dir* and xfs_da* events) so we can see if the
> > > > correct lookups were done prior to the failing addname operation...
> > >
> > > <- xfs tracing noob. Got a recipe I can cut-n-paste ?
> > > Or a patch if that's necessary..
> > Just use your usual method of pulling tracepoints out of the kernel,
> > be it with perf or (my preferred method) trace-cmd:
> > # trace-cmd record -e xfs_dir\* -e xfs_da\* <command that dies>
> > ....
> > # trace-cmd report > trace.report.out
> > The trace.report.out file is what I'd like to see. The report file
> > could be large, so compressing it might be an idea...
> Hmm, will that only log traces from the command that I run ?
No, it will capture kernel wide. The command being run just gives it
a defined end-point to the capture. i.e. I often just use "sleep 30"
as the command.
$ sudo ~/trace-cmd/trace-cmd record -e xfs\* sleep 30 &
$ sudo mount /dev/vda /mnt/test
$ sudo umount /mnt/test
sudo ~/trace-cmd/trace-cmd record -e xfs\* sleep 30
trace-cmd: Interrupted system call
recorder error in splice input
Kernel buffer statistics:
Note: "entries" are the entries left in the kernel ring buffer and are not
recorded in the trace data. They should all be zero.
commit overrun: 0
oldest event ts: 48589.221789
now ts: 48607.261966
dropped events: 0
read events: 352
$ sudo ~/trace-cmd/trace-cmd report > ~/t.t
$ head -10 ~/t.t
version = 6
mount-4185  48582.777997: xfs_buf_init: dev 253:0 bno
0xffffffffffffffff nblks 0x1 hold 1 pincount 0 lock 0 flags caller
mount-4185  48582.778001: xfs_buf_get_uncached: dev 253:0 bno
0xffffffffffffffff nblks 0x1 hold 1 pincount 0 lock 0 flags PAGES caller
mount-4185  48582.778002: xfs_buf_iorequest: dev 253:0 bno
0x0 nblks 0x1 hold 1 pincount 0 lock 0 flags READ|PAGES caller xfsbdstrat
mount-4185  48582.778002: xfs_buf_hold: dev 253:0 bno
0x0 nblks 0x1 hold 1 pincount 0 lock 0 flags READ|PAGES caller xfs_buf_iorequest
mount-4185  48582.778017: xfs_buf_rele: dev 253:0 bno
0x0 nblks 0x1 hold 2 pincount 0 lock 0 flags READ|PAGES caller xfs_buf_iorequest
mount-4185  48582.778017: xfs_buf_iowait: dev 253:0 bno
0x0 nblks 0x1 hold 1 pincount 0 lock 0 flags READ|PAGES caller
<idle>-0  48582.778692: xfs_buf_ioerror: dev 253:0 bno
0x0 len 0x200 hold 1 pincount 0 lock 0 error 0 flags READ|PAGES caller
<idle>-0  48582.778693: xfs_buf_iodone: dev 253:0 bno
0x0 nblks 0x1 hold 1 pincount 0 lock 0 flags READ|PAGES caller _xfs_buf_ioend
> I might need to do some kind of system-wide tracing here,
> because every time this has happened so far, it's happened in
> a different process. (rpcbind the first [wtf?], and chrony the 2nd)
> Can trace-cmd do that ?
Yup. trace-cmd will trace global events unless you give it a
specific process filter to limit what PIDs it gathers events from.
Basically, trace-cmd is a much nicer front end to perf...