[PATCH 0/3] xfs: improve transaction log res. overrun reporting

[Brian Foster <bfoster@redhat.com>]

Hi all,

This is a first pass at improved transaction log reservation overrun
reporting based on Dave's suggestion[1]. This essentially creates a new
helper to dump transaction info (i.e., logged items) along with ticket
data in the event of an overrun and refactors things a bit to be able to
call it from a context where an accurate calculation of the reservation
requirement is available but the log items have not been removed from
the transaction.

Note that this increases the amount of output on a tx overrun quite a
bit, particularly if the transaction includes multiple log
items/vectors, but I opted for verbosity and to retain the current
format for the first iteration. I'm curious if anybody has thoughts on
formatting, what data to include or not, whether to tie certain things
(i.e., raw buffer data?) to the current log level, general level of
detail, etc. Sample output from a fabricated overrun is shown below[2].

Lightly tested so far. Thoughts, reviews, flames appreciated.

Brian

[1] http://www.spinics.net/lists/linux-xfs/msg06446.html
[2] Output from an fallocate request after the write transaction
reservation is erroneously reduced to 32 bytes:

 ------------[ cut here ]------------
 WARNING: CPU: 1 PID: 1621 at fs/xfs//xfs_log_cil.c:466 xfs_log_commit_cil+0x6d5/0x790 [xfs]
 ...
 Call Trace:
  dump_stack+0x86/0xc3
  __warn+0xcb/0xf0
  warn_slowpath_null+0x1d/0x20
  xfs_log_commit_cil+0x6d5/0x790 [xfs]
  __xfs_trans_commit+0x82/0x280 [xfs]
  xfs_trans_commit+0x10/0x20 [xfs]
  xfs_alloc_file_space+0x22a/0x4c0 [xfs]
  xfs_file_fallocate+0x230/0x3b0 [xfs]
  ? rcu_read_lock_sched_held+0x4a/0x80
  ? rcu_sync_lockdep_assert+0x2f/0x60
  ? __sb_start_write+0xe9/0x210
  ? vfs_fallocate+0x214/0x280
  vfs_fallocate+0x159/0x280
  SyS_fallocate+0x48/0x80
  entry_SYSCALL_64_fastpath+0x1f/0xc2
 ...
 ---[ end trace e928d52baa488ea3 ]---
 XFS (dm-3): Transaction log reservation overrun:
 XFS (dm-3):   log items: 876 bytes (iov hdrs: 120 bytes)
 XFS (dm-3):   split region headers: 0 bytes
 XFS (dm-3):   ctx ticket: 2100 bytes
 XFS (dm-3): transaction summary:
 XFS (dm-3):   flags	= 0x5
 XFS (dm-3): ticket reservation summary:
 XFS (dm-3):   unit res    = 2132 bytes
 XFS (dm-3):   current res = -844 bytes
 XFS (dm-3):   total reg   = 0 bytes (o/flow = 0 bytes)
 XFS (dm-3):   ophdrs      = 0 (ophdr space = 0 bytes)
 XFS (dm-3):   ophdr + reg = 0 bytes
 XFS (dm-3):   num regions = 0
 XFS (dm-3): log item: 
 XFS (dm-3):   type	= 0x123b
 XFS (dm-3):   flags	= 0x1
 XFS (dm-3):   niovecs	= 4
 XFS (dm-3):   size	= 720
 XFS (dm-3):   bytes	= 300
 XFS (dm-3):   buf len	= 304
 XFS (dm-3):   iovec[0]
 XFS (dm-3):     type	= 0x5
 XFS (dm-3):     len	= 56
 XFS (dm-3):     first 32 bytes of iovec[0]:
 ffff984954ea2c78: 3b 12 04 00 45 00 00 00 34 00 10 00 49 98 ff ff  ;...E...4...I...
 ffff984954ea2c88: 63 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  c...............
 XFS (dm-3):   iovec[1]
 XFS (dm-3):     type	= 0x6
 XFS (dm-3):     len	= 176
 XFS (dm-3):     first 32 bytes of iovec[1]:
 ffff984954ea2cb0: 4e 49 a4 81 03 02 00 00 00 00 00 00 00 00 00 00  NI..............
 ffff984954ea2cc0: 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
 XFS (dm-3):   iovec[2]
 XFS (dm-3):     type	= 0x7
 XFS (dm-3):     len	= 16
 XFS (dm-3):     first 16 bytes of iovec[2]:
 ffff984954ea2d60: 80 00 00 00 00 00 00 00 00 00 00 00 02 80 01 00  ................
 XFS (dm-3):   iovec[3]
 XFS (dm-3):     type	= 0xc
 XFS (dm-3):     len	= 52
 XFS (dm-3):     first 32 bytes of iovec[3]:
 ffff984954ea2d70: 00 33 01 00 07 25 04 73 65 6c 69 6e 75 78 75 6e  .3...%.selinuxun
 ffff984954ea2d80: 63 6f 6e 66 69 6e 65 64 5f 75 3a 6f 62 6a 65 63  confined_u:objec
 XFS (dm-3): log item: 
 XFS (dm-3):   type	= 0x123c
 XFS (dm-3):   flags	= 0x0
 XFS (dm-3):   niovecs	= 2
 XFS (dm-3):   size	= 256
 XFS (dm-3):   bytes	= 152
 XFS (dm-3):   buf len	= 152
 XFS (dm-3):   iovec[0]
 XFS (dm-3):     type	= 0x1
 XFS (dm-3):     len	= 24
 XFS (dm-3):     first 24 bytes of iovec[0]:
 ffff9849532d1258: 3c 12 02 00 00 28 01 00 01 00 00 00 00 00 00 00  <....(..........
 ffff9849532d1268: 01 00 00 00 01 00 00 00                          ........
 XFS (dm-3):   iovec[1]
 XFS (dm-3):     type	= 0x2
 XFS (dm-3):     len	= 128
 XFS (dm-3):     first 32 bytes of iovec[1]:
 ffff9849532d1270: 58 41 47 46 00 00 00 01 00 00 00 00 00 0f 00 00  XAGF............
 ffff9849532d1280: 00 00 00 01 00 00 00 02 00 00 00 00 00 00 00 01  ................
 XFS (dm-3): log item: 
 XFS (dm-3):   type	= 0x123c
 XFS (dm-3):   flags	= 0x0
 XFS (dm-3):   niovecs	= 2
 XFS (dm-3):   size	= 256
 XFS (dm-3):   bytes	= 152
 XFS (dm-3):   buf len	= 152
 XFS (dm-3):   iovec[0]
 XFS (dm-3):     type	= 0x1
 XFS (dm-3):     len	= 24
 XFS (dm-3):     first 24 bytes of iovec[0]:
 ffff9849532d1358: 3c 12 02 00 00 20 08 00 10 00 00 00 00 00 00 00  <.... ..........
 ffff9849532d1368: 01 00 00 00 01 00 00 00                          ........
 XFS (dm-3):   iovec[1]
 XFS (dm-3):     type	= 0x2
 XFS (dm-3):     len	= 128
 XFS (dm-3):     first 32 bytes of iovec[1]:
 ffff9849532d1370: 41 42 33 43 00 00 00 02 ff ff ff ff ff ff ff ff  AB3C............
 ffff9849532d1380: 00 00 00 00 00 00 00 10 00 00 00 01 00 00 00 54  ...............T
 XFS (dm-3): log item: 
 XFS (dm-3):   type	= 0x123c
 XFS (dm-3):   flags	= 0x0
 XFS (dm-3):   niovecs	= 2
 XFS (dm-3):   size	= 256
 XFS (dm-3):   bytes	= 152
 XFS (dm-3):   buf len	= 152
 XFS (dm-3):   iovec[0]
 XFS (dm-3):     type	= 0x1
 XFS (dm-3):     len	= 24
 XFS (dm-3):     first 24 bytes of iovec[0]:
 ffff9849532d1558: 3c 12 02 00 00 20 08 00 08 00 00 00 00 00 00 00  <.... ..........
 ffff9849532d1568: 01 00 00 00 01 00 00 00                          ........
 XFS (dm-3):   iovec[1]
 XFS (dm-3):     type	= 0x2
 XFS (dm-3):     len	= 128
 XFS (dm-3):     first 32 bytes of iovec[1]:
 ffff9849532d1570: 41 42 33 42 00 00 00 02 ff ff ff ff ff ff ff ff  AB3B............
 ffff9849532d1580: 00 00 00 00 00 00 00 08 00 00 00 01 00 00 00 54  ...............T
 XFS (dm-3): xfs_do_force_shutdown(0x2) called from line 501 of file fs/xfs//xfs_log_cil.c.  Return address = 0xffffffffc041e56b
 XFS (dm-3): Log I/O Error Detected.  Shutting down filesystem
 XFS (dm-3): Please umount the filesystem and rectify the problem(s)

Brian Foster (3):
  xfs: separate shutdown from ticket reservation print helper
  xfs: refactor xlog_cil_insert_items() to facilitate transaction dump
  xfs: dump transaction usage details on log reservation overrun

 fs/xfs/xfs_log.c      | 59 +++++++++++++++++++++++++++++++++---
 fs/xfs/xfs_log_cil.c  | 84 ++++++++++++++++++++++++++++++---------------------
 fs/xfs/xfs_log_priv.h |  1 +
 3 files changed, 105 insertions(+), 39 deletions(-)

-- 
2.7.4