On Mon, May 08, 2017 at 04:45:04PM -0400, Brian Foster wrote: > 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. Offhand this looks ok; will add it to my dev tree and go run something that exhausts a transaction reservation to see it in action. For now, Reviewed-by: Darrick J. Wong <darrick.wong@xxxxxxxxxx> --D > > 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 > > -- > To unsubscribe from this list: send the line "unsubscribe linux-xfs" in > the body of a message to majordomo@xxxxxxxxxxxxxxx > More majordomo info at http://vger.kernel.org/majordomo-info.html -- To unsubscribe from this list: send the line "unsubscribe linux-xfs" in the body of a message to majordomo@xxxxxxxxxxxxxxx More majordomo info at http://vger.kernel.org/majordomo-info.html
