Latencies writing to memory mapped files

[Dave Chinner]

On Mon, Sep 20, 2010 at 05:17:26PM -0500, Shawn Bohrer wrote:
> Thanks Dave for your explanations.
> 
> On Mon, Sep 20, 2010 at 10:05:35AM +1000, Dave Chinner wrote:
> > FWIW, if you can work out the magic necessary (perhaps systemtap) it
> > woul dbe really interesting to know whether it is the same buffer
> > that is causing the latency every time (i.e. get the bp->b_bn field
> > from the metadata buffer). With the block number, we can use xfs_db
> > to dig out what the buffer actually is....
> 
> I'm working on a dev box right now so I just added a trace_printk() to
> print out the bp->b_bn field when the xfs_buf_lock blocks for more
> than 300ms.  Here are some numbers (I can easily get a lot more):
> 
> _xfs_buf_find: xfs_buf_lock blocked for 1843ms on bp->b_bn: 812730376
> _xfs_buf_find: xfs_buf_lock blocked for 1504ms on bp->b_bn: 406702514
> _xfs_buf_find: xfs_buf_lock blocked for 307ms on bp->b_bn: 881190896
> _xfs_buf_find: xfs_buf_lock blocked for 433ms on bp->b_bn: 406703400
> _xfs_buf_find: xfs_buf_lock blocked for 420ms on bp->b_bn: 541595968
> _xfs_buf_find: xfs_buf_lock blocked for 308ms on bp->b_bn: 44945968
> _xfs_buf_find: xfs_buf_lock blocked for 702ms on bp->b_bn: 406027744
> _xfs_buf_find: xfs_buf_lock blocked for 454ms on bp->b_bn: 474486504
> _xfs_buf_find: xfs_buf_lock blocked for 869ms on bp->b_bn: 881195976
> _xfs_buf_find: xfs_buf_lock blocked for 387ms on bp->b_bn: 1287891544
> _xfs_buf_find: xfs_buf_lock blocked for 397ms on bp->b_bn: 1220116224
> _xfs_buf_find: xfs_buf_lock blocked for 461ms on bp->b_bn: 2101644280
> _xfs_buf_find: xfs_buf_lock blocked for 312ms on bp->b_bn: 338919728
> _xfs_buf_find: xfs_buf_lock blocked for 356ms on bp->b_bn: 1016769536
> _xfs_buf_find: xfs_buf_lock blocked for 593ms on bp->b_bn: 474488848
> _xfs_buf_find: xfs_buf_lock blocked for 323ms on bp->b_bn: 1022248984
> 
> I should say that not every one of these results in a stall in my
> application, since my app needs to generate a page fault while that
> lock is held.

Hmmm - it would be good to know which one produced the latency,
given there does not appear to be a pattern in the block numbers.

> What do I need to do to convert the block numbers to a buffer?

# xfs_db -r -c "daddr 812730376" -c "print" <dev>

Will dump the sector at that address. That should be enough to tell
us what is in the buffer (by the magic number).

Cheers,

Dave.
-- 
Dave Chinner
david at fromorbit.com