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

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

[Brian Foster]

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

[PATCH 1/3] xfs: separate shutdown from ticket reservation print helper

[Brian Foster]

xlog_print_tic_res() pre-dates delayed logging and the committed
items list (CIL) and thus retains some factoring warts, such as hard
coded function names in the output and the fact that it induces a
shutdown.

In preparation for more detailed logging of regular transaction
overrun situations, refactor xlog_print_tic_res() to be slightly
more generic. Reword some of the warning messages and pull the
shutdown into the callers.

Signed-off-by: Brian Foster <bfoster@redhat.com>
---
 fs/xfs/xfs_log.c     | 12 ++++++------
 fs/xfs/xfs_log_cil.c |  4 +++-
 2 files changed, 9 insertions(+), 7 deletions(-)

diff --git a/fs/xfs/xfs_log.c b/fs/xfs/xfs_log.c
index 3731f13..8b283f7 100644
--- a/fs/xfs/xfs_log.c
+++ b/fs/xfs/xfs_log.c
@@ -2024,7 +2024,7 @@ xlog_print_tic_res(
 	};
 #undef REG_TYPE_STR
 
-	xfs_warn(mp, "xlog_write: reservation summary:");
+	xfs_warn(mp, "ticket reservation summary:");
 	xfs_warn(mp, "  unit res    = %d bytes",
 		 ticket->t_unit_res);
 	xfs_warn(mp, "  current res = %d bytes",
@@ -2045,10 +2045,6 @@ xlog_print_tic_res(
 			    "bad-rtype" : res_type_str[r_type]),
 			    ticket->t_res_arr[i].r_len);
 	}
-
-	xfs_alert_tag(mp, XFS_PTAG_LOGRES,
-		"xlog_write: reservation ran out. Need to up reservation");
-	xfs_force_shutdown(mp, SHUTDOWN_LOG_IO_ERROR);
 }
 
 /*
@@ -2321,8 +2317,12 @@ xlog_write(
 	if (flags & (XLOG_COMMIT_TRANS | XLOG_UNMOUNT_TRANS))
 		ticket->t_curr_res -= sizeof(xlog_op_header_t);
 
-	if (ticket->t_curr_res < 0)
+	if (ticket->t_curr_res < 0) {
+		xfs_alert_tag(log->l_mp, XFS_PTAG_LOGRES,
+		     "ctx ticket reservation ran out. Need to up reservation");
 		xlog_print_tic_res(log->l_mp, ticket);
+		xfs_force_shutdown(log->l_mp, SHUTDOWN_LOG_IO_ERROR);
+	}
 
 	index = 0;
 	lv = log_vector;
diff --git a/fs/xfs/xfs_log_cil.c b/fs/xfs/xfs_log_cil.c
index 82f1cbc..52fe042 100644
--- a/fs/xfs/xfs_log_cil.c
+++ b/fs/xfs/xfs_log_cil.c
@@ -987,8 +987,10 @@ xfs_log_commit_cil(
 	xlog_cil_insert_items(log, tp);
 
 	/* check we didn't blow the reservation */
-	if (tp->t_ticket->t_curr_res < 0)
+	if (tp->t_ticket->t_curr_res < 0) {
 		xlog_print_tic_res(mp, tp->t_ticket);
+		xfs_force_shutdown(log->l_mp, SHUTDOWN_LOG_IO_ERROR);
+	}
 
 	tp->t_commit_lsn = cil->xc_ctx->sequence;
 	if (commit_lsn)
-- 
2.7.4

[PATCH 2/3] xfs: refactor xlog_cil_insert_items() to facilitate transaction dump

[Brian Foster]

Transaction reservation overrun detection currently occurs too late
to print useful information about the offending transaction.
Ideally, the transaction data is printed before the associated log
items are moved from the transaction to the CIL, which occurs in
xlog_cil_insert_items(), such that details of the items logged by
the transaction are available for analysis.

Refactor xlog_cil_insert_items() to facilitate moving tx overrun
detection to this function. Update the function to track each bit of
extra log reservation stolen from the transaction (i.e., such as for
the CIL context ticket) and perform the log item migration as the
last operation before the CIL lock is released. This creates a
context where the transaction reservation consumption has been fully
calculated when the log items are moved to the CIL. This patch makes
no functional changes.

Signed-off-by: Brian Foster <bfoster@redhat.com>
---
 fs/xfs/xfs_log_cil.c | 62 +++++++++++++++++++++++++++-------------------------
 1 file changed, 32 insertions(+), 30 deletions(-)

diff --git a/fs/xfs/xfs_log_cil.c b/fs/xfs/xfs_log_cil.c
index 52fe042..8de3baa 100644
--- a/fs/xfs/xfs_log_cil.c
+++ b/fs/xfs/xfs_log_cil.c
@@ -410,6 +410,7 @@ xlog_cil_insert_items(
 	int			len = 0;
 	int			diff_iovecs = 0;
 	int			iclog_space;
+	int			iovhdr_res = 0, split_res = 0, ctx_res = 0;
 
 	ASSERT(tp);
 
@@ -419,30 +420,11 @@ xlog_cil_insert_items(
 	 */
 	xlog_cil_insert_format_items(log, tp, &len, &diff_iovecs);
 
-	/*
-	 * Now (re-)position everything modified at the tail of the CIL.
-	 * We do this here so we only need to take the CIL lock once during
-	 * the transaction commit.
-	 */
 	spin_lock(&cil->xc_cil_lock);
-	list_for_each_entry(lidp, &tp->t_items, lid_trans) {
-		struct xfs_log_item	*lip = lidp->lid_item;
-
-		/* Skip items which aren't dirty in this transaction. */
-		if (!(lidp->lid_flags & XFS_LID_DIRTY))
-			continue;
-
-		/*
-		 * Only move the item if it isn't already at the tail. This is
-		 * to prevent a transient list_empty() state when reinserting
-		 * an item that is already the only item in the CIL.
-		 */
-		if (!list_is_last(&lip->li_cil, &cil->xc_cil))
-			list_move_tail(&lip->li_cil, &cil->xc_cil);
-	}
 
 	/* account for space used by new iovec headers  */
-	len += diff_iovecs * sizeof(xlog_op_header_t);
+	iovhdr_res = diff_iovecs * sizeof(xlog_op_header_t);
+	len += iovhdr_res;
 	ctx->nvecs += diff_iovecs;
 
 	/* attach the transaction to the CIL if it has any busy extents */
@@ -457,27 +439,47 @@ xlog_cil_insert_items(
 	 * during the transaction commit.
 	 */
 	if (ctx->ticket->t_curr_res == 0) {
-		ctx->ticket->t_curr_res = ctx->ticket->t_unit_res;
-		tp->t_ticket->t_curr_res -= ctx->ticket->t_unit_res;
+		ctx_res = ctx->ticket->t_unit_res;
+		ctx->ticket->t_curr_res = ctx_res;
+		tp->t_ticket->t_curr_res -= ctx_res;
 	}
 
 	/* do we need space for more log record headers? */
 	iclog_space = log->l_iclog_size - log->l_iclog_hsize;
 	if (len > 0 && (ctx->space_used / iclog_space !=
 				(ctx->space_used + len) / iclog_space)) {
-		int hdrs;
-
-		hdrs = (len + iclog_space - 1) / iclog_space;
+		split_res = (len + iclog_space - 1) / iclog_space;
 		/* need to take into account split region headers, too */
-		hdrs *= log->l_iclog_hsize + sizeof(struct xlog_op_header);
-		ctx->ticket->t_unit_res += hdrs;
-		ctx->ticket->t_curr_res += hdrs;
-		tp->t_ticket->t_curr_res -= hdrs;
+		split_res *= log->l_iclog_hsize + sizeof(struct xlog_op_header);
+		ctx->ticket->t_unit_res += split_res;
+		ctx->ticket->t_curr_res += split_res;
+		tp->t_ticket->t_curr_res -= split_res;
 		ASSERT(tp->t_ticket->t_curr_res >= len);
 	}
 	tp->t_ticket->t_curr_res -= len;
 	ctx->space_used += len;
 
+	/*
+	 * Now (re-)position everything modified at the tail of the CIL.
+	 * We do this here so we only need to take the CIL lock once during
+	 * the transaction commit.
+	 */
+	list_for_each_entry(lidp, &tp->t_items, lid_trans) {
+		struct xfs_log_item	*lip = lidp->lid_item;
+
+		/* Skip items which aren't dirty in this transaction. */
+		if (!(lidp->lid_flags & XFS_LID_DIRTY))
+			continue;
+
+		/*
+		 * Only move the item if it isn't already at the tail. This is
+		 * to prevent a transient list_empty() state when reinserting
+		 * an item that is already the only item in the CIL.
+		 */
+		if (!list_is_last(&lip->li_cil, &cil->xc_cil))
+			list_move_tail(&lip->li_cil, &cil->xc_cil);
+	}
+
 	spin_unlock(&cil->xc_cil_lock);
 }
 
-- 
2.7.4

[PATCH 3/3] xfs: dump transaction usage details on log reservation overrun

[Brian Foster]

If a transaction log reservation overrun occurs, the ticket data
associated with the reservation is dumped in xfs_log_commit_cil().
This occurs long after the transaction items and details have been
removed from the transaction and effectively lost. This limited set
of ticket data provides very little information to support debugging
transaction overruns based on the typical report.

To improve transaction log reservation overrun reporting, create a
helper to dump transaction details such as log items, log vector
data, etc., as well as the underlying ticket data for the
transaction. Move the overrun detection from xfs_log_commit_cil() to
xlog_cil_insert_items() so it occurs prior to migration of the
logged items to the CIL. Call the new helper such that it is able to
dump this transaction data before it is lost.

Also, warn on overrun to provide callstack context for the offending
transaction and include a few additional messages from
xlog_cil_insert_items() to display the reservation consumed locally
for overhead such as log vector headers, split region headers and
the context ticket. This provides a complete general breakdown of
the reservation consumption of a transaction when/if it happens to
overrun the reservation.

Signed-off-by: Brian Foster <bfoster@redhat.com>
---
 fs/xfs/xfs_log.c      | 49 +++++++++++++++++++++++++++++++++++++++++++++++++
 fs/xfs/xfs_log_cil.c  | 24 ++++++++++++++++++------
 fs/xfs/xfs_log_priv.h |  1 +
 3 files changed, 68 insertions(+), 6 deletions(-)

diff --git a/fs/xfs/xfs_log.c b/fs/xfs/xfs_log.c
index 8b283f7..c8d0481 100644
--- a/fs/xfs/xfs_log.c
+++ b/fs/xfs/xfs_log.c
@@ -2048,6 +2048,55 @@ xlog_print_tic_res(
 }
 
 /*
+ * Print a summary of the transaction.
+ */
+void
+xlog_print_trans(
+	struct xfs_trans		*tp)
+{
+	struct xfs_mount		*mp = tp->t_mountp;
+	struct xfs_log_item_desc	*lidp;
+
+	/* dump core transaction and ticket info */
+	xfs_warn(mp, "transaction summary:");
+	xfs_warn(mp, "  flags	= 0x%x", tp->t_flags);
+
+	xlog_print_tic_res(mp, tp->t_ticket);
+
+	/* dump each log item */
+	list_for_each_entry(lidp, &tp->t_items, lid_trans) {
+		struct xfs_log_item	*lip = lidp->lid_item;
+		struct xfs_log_vec	*lv = lip->li_lv;
+		struct xfs_log_iovec	*vec;
+		int			i;
+
+		xfs_warn(mp, "log item: ");
+		xfs_warn(mp, "  type	= 0x%x", lip->li_type);
+		xfs_warn(mp, "  flags	= 0x%x", lip->li_flags);
+		if (!lv)
+			continue;
+		xfs_warn(mp, "  niovecs	= %d", lv->lv_niovecs);
+		xfs_warn(mp, "  size	= %d", lv->lv_size);
+		xfs_warn(mp, "  bytes	= %d", lv->lv_bytes);
+		xfs_warn(mp, "  buf len	= %d", lv->lv_buf_len);
+
+		/* dump each iovec for the log item */
+		vec = lv->lv_iovecp;
+		for (i = 0; i < lv->lv_niovecs; i++) {
+			int dumplen = min(vec->i_len, 32);
+
+			xfs_warn(mp, "  iovec[%d]", i);
+			xfs_warn(mp, "    type	= 0x%x", vec->i_type);
+			xfs_warn(mp, "    len	= %d", vec->i_len);
+			xfs_warn(mp, "    first %d bytes of iovec[%d]:", dumplen, i);
+			xfs_hex_dump(vec->i_addr, dumplen);;
+
+			vec++;
+		}
+	}
+}
+
+/*
  * Calculate the potential space needed by the log vector.  Each region gets
  * its own xlog_op_header_t and may need to be double word aligned.
  */
diff --git a/fs/xfs/xfs_log_cil.c b/fs/xfs/xfs_log_cil.c
index 8de3baa..04b3892 100644
--- a/fs/xfs/xfs_log_cil.c
+++ b/fs/xfs/xfs_log_cil.c
@@ -460,6 +460,21 @@ xlog_cil_insert_items(
 	ctx->space_used += len;
 
 	/*
+	 * If we've overrun the reservation, dump the tx details before we move
+	 * the log items. Shutdown is imminent...
+	 */
+	if (WARN_ON(tp->t_ticket->t_curr_res < 0)) {
+		xfs_warn(log->l_mp, "Transaction log reservation overrun:");
+		xfs_warn(log->l_mp,
+			 "  log items: %d bytes (iov hdrs: %d bytes)",
+			 len, iovhdr_res);
+		xfs_warn(log->l_mp, "  split region headers: %d bytes",
+			 split_res);
+		xfs_warn(log->l_mp, "  ctx ticket: %d bytes", ctx_res);
+		xlog_print_trans(tp);
+	}
+
+	/*
 	 * Now (re-)position everything modified at the tail of the CIL.
 	 * We do this here so we only need to take the CIL lock once during
 	 * the transaction commit.
@@ -481,6 +496,9 @@ xlog_cil_insert_items(
 	}
 
 	spin_unlock(&cil->xc_cil_lock);
+
+	if (tp->t_ticket->t_curr_res < 0)
+		xfs_force_shutdown(log->l_mp, SHUTDOWN_LOG_IO_ERROR);
 }
 
 static void
@@ -988,12 +1006,6 @@ xfs_log_commit_cil(
 
 	xlog_cil_insert_items(log, tp);
 
-	/* check we didn't blow the reservation */
-	if (tp->t_ticket->t_curr_res < 0) {
-		xlog_print_tic_res(mp, tp->t_ticket);
-		xfs_force_shutdown(log->l_mp, SHUTDOWN_LOG_IO_ERROR);
-	}
-
 	tp->t_commit_lsn = cil->xc_ctx->sequence;
 	if (commit_lsn)
 		*commit_lsn = tp->t_commit_lsn;
diff --git a/fs/xfs/xfs_log_priv.h b/fs/xfs/xfs_log_priv.h
index c2604a5..62113a5 100644
--- a/fs/xfs/xfs_log_priv.h
+++ b/fs/xfs/xfs_log_priv.h
@@ -456,6 +456,7 @@ xlog_write_adv_cnt(void **ptr, int *len, int *off, size_t bytes)
 }
 
 void	xlog_print_tic_res(struct xfs_mount *mp, struct xlog_ticket *ticket);
+void	xlog_print_trans(struct xfs_trans *);
 int
 xlog_write(
 	struct xlog		*log,
-- 
2.7.4

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

[Darrick J. Wong]

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@oracle.com>

--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@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html