Re: [PATCH 26/45] xfs: log ticket region debug is largely useless

["Darrick J. Wong" <djwong@kernel.org>]

On Fri, Mar 05, 2021 at 04:11:24PM +1100, Dave Chinner wrote:
> From: Dave Chinner <dchinner@redhat.com>
> 
> xlog_tic_add_region() is used to trace the regions being added to a
> log ticket to provide information in the situation where a ticket
> reservation overrun occurs. The information gathered is stored int
> the ticket, and dumped if xlog_print_tic_res() is called.
> 
> For a front end struct xfs_trans overrun, the ticket only contains
> reservation tracking information - the ticket is never handed to the
> log so has no regions attached to it. The overrun debug information in this
> case comes from xlog_print_trans(), which walks the items attached
> to the transaction and dumps their attached formatted log vectors
> directly. It also dumps the ticket state, but that only contains
> reservation accounting and nothing else. Hence xlog_print_tic_res()
> never dumps region or overrun information from this path.
> 
> xlog_tic_add_region() is actually called from xlog_write(), which
> means it is being used to track the regions seen in a
> CIL checkpoint log vector chain. In looking at CIL behaviour
> recently, I've seen 32MB checkpoints regularly exceed 250,000
> regions in the LV chain. The log ticket debug code can track *15*

Yikes.  I /had/ noticed that the amount of overrun ledger info didn't
seem to come anywhere close to the numbers in the accounting data.

Reviewed-by: Darrick J. Wong <djwong@kernel.org>

--D

> regions. IOWs, if there is a ticket overrun in the CIL code, the
> ticket region tracking code is going to be completely useless for
> determining what went wrong. The only thing it can tell us is how
> much of an overrun occurred, and we really don't need extra debug
> information in the log ticket to tell us that.
> 
> Indeed, the main place we call xlog_tic_add_region() is also adding
> up the number of regions and the space used so that xlog_write()
> knows how much will be written to the log. This is exactly the same
> information that log ticket is storing once we take away the useless
> region tracking array. Hence xlog_tic_add_region() is not useful,
> but can be called 250,000 times a CIL push...
> 
> Just strip all that debug "information" out of the of the log ticket
> and only have it report reservation space information when an
> overrun occurs. This also reduces the size of a log ticket down by
> about 150 bytes...
> 
> Signed-off-by: Dave Chinner <dchinner@redhat.com>
> Reviewed-by: Christoph Hellwig <hch@lst.de>
> ---
>  fs/xfs/xfs_log.c      | 107 +++---------------------------------------
>  fs/xfs/xfs_log_priv.h |  17 -------
>  2 files changed, 6 insertions(+), 118 deletions(-)
> 
> diff --git a/fs/xfs/xfs_log.c b/fs/xfs/xfs_log.c
> index 98de45be80c0..412b167d8d0e 100644
> --- a/fs/xfs/xfs_log.c
> +++ b/fs/xfs/xfs_log.c
> @@ -377,30 +377,6 @@ xlog_grant_head_check(
>  	return error;
>  }
>  
> -static void
> -xlog_tic_reset_res(xlog_ticket_t *tic)
> -{
> -	tic->t_res_num = 0;
> -	tic->t_res_arr_sum = 0;
> -	tic->t_res_num_ophdrs = 0;
> -}
> -
> -static void
> -xlog_tic_add_region(xlog_ticket_t *tic, uint len, uint type)
> -{
> -	if (tic->t_res_num == XLOG_TIC_LEN_MAX) {
> -		/* add to overflow and start again */
> -		tic->t_res_o_flow += tic->t_res_arr_sum;
> -		tic->t_res_num = 0;
> -		tic->t_res_arr_sum = 0;
> -	}
> -
> -	tic->t_res_arr[tic->t_res_num].r_len = len;
> -	tic->t_res_arr[tic->t_res_num].r_type = type;
> -	tic->t_res_arr_sum += len;
> -	tic->t_res_num++;
> -}
> -
>  bool
>  xfs_log_writable(
>  	struct xfs_mount	*mp)
> @@ -448,8 +424,6 @@ xfs_log_regrant(
>  	xlog_grant_push_ail(log, tic->t_unit_res);
>  
>  	tic->t_curr_res = tic->t_unit_res;
> -	xlog_tic_reset_res(tic);
> -
>  	if (tic->t_cnt > 0)
>  		return 0;
>  
> @@ -2066,63 +2040,11 @@ xlog_print_tic_res(
>  	struct xfs_mount	*mp,
>  	struct xlog_ticket	*ticket)
>  {
> -	uint i;
> -	uint ophdr_spc = ticket->t_res_num_ophdrs * (uint)sizeof(xlog_op_header_t);
> -
> -	/* match with XLOG_REG_TYPE_* in xfs_log.h */
> -#define REG_TYPE_STR(type, str)	[XLOG_REG_TYPE_##type] = str
> -	static char *res_type_str[] = {
> -	    REG_TYPE_STR(BFORMAT, "bformat"),
> -	    REG_TYPE_STR(BCHUNK, "bchunk"),
> -	    REG_TYPE_STR(EFI_FORMAT, "efi_format"),
> -	    REG_TYPE_STR(EFD_FORMAT, "efd_format"),
> -	    REG_TYPE_STR(IFORMAT, "iformat"),
> -	    REG_TYPE_STR(ICORE, "icore"),
> -	    REG_TYPE_STR(IEXT, "iext"),
> -	    REG_TYPE_STR(IBROOT, "ibroot"),
> -	    REG_TYPE_STR(ILOCAL, "ilocal"),
> -	    REG_TYPE_STR(IATTR_EXT, "iattr_ext"),
> -	    REG_TYPE_STR(IATTR_BROOT, "iattr_broot"),
> -	    REG_TYPE_STR(IATTR_LOCAL, "iattr_local"),
> -	    REG_TYPE_STR(QFORMAT, "qformat"),
> -	    REG_TYPE_STR(DQUOT, "dquot"),
> -	    REG_TYPE_STR(QUOTAOFF, "quotaoff"),
> -	    REG_TYPE_STR(LRHEADER, "LR header"),
> -	    REG_TYPE_STR(UNMOUNT, "unmount"),
> -	    REG_TYPE_STR(COMMIT, "commit"),
> -	    REG_TYPE_STR(TRANSHDR, "trans header"),
> -	    REG_TYPE_STR(ICREATE, "inode create"),
> -	    REG_TYPE_STR(RUI_FORMAT, "rui_format"),
> -	    REG_TYPE_STR(RUD_FORMAT, "rud_format"),
> -	    REG_TYPE_STR(CUI_FORMAT, "cui_format"),
> -	    REG_TYPE_STR(CUD_FORMAT, "cud_format"),
> -	    REG_TYPE_STR(BUI_FORMAT, "bui_format"),
> -	    REG_TYPE_STR(BUD_FORMAT, "bud_format"),
> -	};
> -	BUILD_BUG_ON(ARRAY_SIZE(res_type_str) != XLOG_REG_TYPE_MAX + 1);
> -#undef REG_TYPE_STR
> -
>  	xfs_warn(mp, "ticket reservation summary:");
> -	xfs_warn(mp, "  unit res    = %d bytes",
> -		 ticket->t_unit_res);
> -	xfs_warn(mp, "  current res = %d bytes",
> -		 ticket->t_curr_res);
> -	xfs_warn(mp, "  total reg   = %u bytes (o/flow = %u bytes)",
> -		 ticket->t_res_arr_sum, ticket->t_res_o_flow);
> -	xfs_warn(mp, "  ophdrs      = %u (ophdr space = %u bytes)",
> -		 ticket->t_res_num_ophdrs, ophdr_spc);
> -	xfs_warn(mp, "  ophdr + reg = %u bytes",
> -		 ticket->t_res_arr_sum + ticket->t_res_o_flow + ophdr_spc);
> -	xfs_warn(mp, "  num regions = %u",
> -		 ticket->t_res_num);
> -
> -	for (i = 0; i < ticket->t_res_num; i++) {
> -		uint r_type = ticket->t_res_arr[i].r_type;
> -		xfs_warn(mp, "region[%u]: %s - %u bytes", i,
> -			    ((r_type <= 0 || r_type > XLOG_REG_TYPE_MAX) ?
> -			    "bad-rtype" : res_type_str[r_type]),
> -			    ticket->t_res_arr[i].r_len);
> -	}
> +	xfs_warn(mp, "  unit res    = %d bytes", ticket->t_unit_res);
> +	xfs_warn(mp, "  current res = %d bytes", ticket->t_curr_res);
> +	xfs_warn(mp, "  original count  = %d", ticket->t_ocnt);
> +	xfs_warn(mp, "  remaining count = %d", ticket->t_cnt);
>  }
>  
>  /*
> @@ -2187,7 +2109,6 @@ xlog_write_calc_vec_length(
>  	uint			optype)
>  {
>  	struct xfs_log_vec	*lv;
> -	int			headers = 0;
>  	int			len = 0;
>  	int			i;
>  
> @@ -2196,17 +2117,9 @@ xlog_write_calc_vec_length(
>  		if (lv->lv_buf_len == XFS_LOG_VEC_ORDERED)
>  			continue;
>  
> -		headers += lv->lv_niovecs;
> -
> -		for (i = 0; i < lv->lv_niovecs; i++) {
> -			struct xfs_log_iovec	*vecp = &lv->lv_iovecp[i];
> -
> -			len += vecp->i_len;
> -			xlog_tic_add_region(ticket, vecp->i_len, vecp->i_type);
> -		}
> +		for (i = 0; i < lv->lv_niovecs; i++)
> +			len += lv->lv_iovecp[i].i_len;
>  	}
> -	ticket->t_res_num_ophdrs += headers;
> -
>  	return len;
>  }
>  
> @@ -2265,7 +2178,6 @@ xlog_write_setup_copy(
>  
>  	/* account for new log op header */
>  	ticket->t_curr_res -= sizeof(struct xlog_op_header);
> -	ticket->t_res_num_ophdrs++;
>  
>  	return sizeof(struct xlog_op_header);
>  }
> @@ -2973,9 +2885,6 @@ xlog_state_get_iclog_space(
>  	 */
>  	if (log_offset == 0) {
>  		ticket->t_curr_res -= log->l_iclog_hsize;
> -		xlog_tic_add_region(ticket,
> -				    log->l_iclog_hsize,
> -				    XLOG_REG_TYPE_LRHEADER);
>  		head->h_cycle = cpu_to_be32(log->l_curr_cycle);
>  		head->h_lsn = cpu_to_be64(
>  			xlog_assign_lsn(log->l_curr_cycle, log->l_curr_block));
> @@ -3055,7 +2964,6 @@ xfs_log_ticket_regrant(
>  	xlog_grant_sub_space(log, &log->l_write_head.grant,
>  					ticket->t_curr_res);
>  	ticket->t_curr_res = ticket->t_unit_res;
> -	xlog_tic_reset_res(ticket);
>  
>  	trace_xfs_log_ticket_regrant_sub(log, ticket);
>  
> @@ -3066,7 +2974,6 @@ xfs_log_ticket_regrant(
>  		trace_xfs_log_ticket_regrant_exit(log, ticket);
>  
>  		ticket->t_curr_res = ticket->t_unit_res;
> -		xlog_tic_reset_res(ticket);
>  	}
>  
>  	xfs_log_ticket_put(ticket);
> @@ -3529,8 +3436,6 @@ xlog_ticket_alloc(
>  	if (permanent)
>  		tic->t_flags |= XLOG_TIC_PERM_RESERV;
>  
> -	xlog_tic_reset_res(tic);
> -
>  	return tic;
>  }
>  
> diff --git a/fs/xfs/xfs_log_priv.h b/fs/xfs/xfs_log_priv.h
> index 7f601c1c9f45..8ee6a5f74396 100644
> --- a/fs/xfs/xfs_log_priv.h
> +++ b/fs/xfs/xfs_log_priv.h
> @@ -139,16 +139,6 @@ enum xlog_iclog_state {
>  /* Ticket reservation region accounting */ 
>  #define XLOG_TIC_LEN_MAX	15
>  
> -/*
> - * Reservation region
> - * As would be stored in xfs_log_iovec but without the i_addr which
> - * we don't care about.
> - */
> -typedef struct xlog_res {
> -	uint	r_len;	/* region length		:4 */
> -	uint	r_type;	/* region's transaction type	:4 */
> -} xlog_res_t;
> -
>  typedef struct xlog_ticket {
>  	struct list_head   t_queue;	 /* reserve/write queue */
>  	struct task_struct *t_task;	 /* task that owns this ticket */
> @@ -159,13 +149,6 @@ typedef struct xlog_ticket {
>  	char		   t_ocnt;	 /* original count		 : 1  */
>  	char		   t_cnt;	 /* current count		 : 1  */
>  	char		   t_flags;	 /* properties of reservation	 : 1  */
> -
> -        /* reservation array fields */
> -	uint		   t_res_num;                    /* num in array : 4 */
> -	uint		   t_res_num_ophdrs;		 /* num op hdrs  : 4 */
> -	uint		   t_res_arr_sum;		 /* array sum    : 4 */
> -	uint		   t_res_o_flow;		 /* sum overflow : 4 */
> -	xlog_res_t	   t_res_arr[XLOG_TIC_LEN_MAX];  /* array of res : 8 * 15 */ 
>  } xlog_ticket_t;
>  
>  /*
> -- 
> 2.28.0
>