Re: Latencies writing to memory mapped files

Shawn Bohrer
2010-09-20T22:16:41Z

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.

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