Commit 7e9c6396 authored by Tim Shimmin's avatar Tim Shimmin Committed by Nathan Scott
Browse files

[XFS] 929956 add log debugging and tracing info 



SGI-PV: 931456
SGI-Modid: xfs-linux:xfs-kern:23155a

Signed-off-by: default avatarTim Shimmin <tes@sgi.com>
Signed-off-by: default avatarNathan Scott <nathans@sgi.com>
parent 32fb9b57

fs/xfs/quota/xfs_dquot_item.c

+1 −0
Original line number Diff line number Diff line
@@ -509,6 +509,7 @@ xfs_qm_qoff_logitem_format(xfs_qoff_logitem_t *qf, 


	log_vector->i_addr = (xfs_caddr_t)&(qf->qql_format);

	log_vector->i_len = sizeof(xfs_qoff_logitem_t);

	XLOG_VEC_SET_TYPE(log_vector, XLOG_REG_TYPE_QUOTAOFF);

	qf->qql_format.qf_size = 1;

}

fs/xfs/xfs_buf_item.c

+4 −0
Original line number Diff line number Diff line
@@ -274,6 +274,7 @@ xfs_buf_item_format( 
		       ((bip->bli_format.blf_map_size - 1) * sizeof(uint)));

	vecp->i_addr = (xfs_caddr_t)&bip->bli_format;

	vecp->i_len = base_size;

	XLOG_VEC_SET_TYPE(vecp, XLOG_REG_TYPE_BFORMAT);

	vecp++;

	nvecs = 1;
@@ -320,12 +321,14 @@ xfs_buf_item_format( 
			buffer_offset = first_bit * XFS_BLI_CHUNK;

			vecp->i_addr = xfs_buf_offset(bp, buffer_offset);

			vecp->i_len = nbits * XFS_BLI_CHUNK;

			XLOG_VEC_SET_TYPE(vecp, XLOG_REG_TYPE_BCHUNK);

			nvecs++;

			break;

		} else if (next_bit != last_bit + 1) {

			buffer_offset = first_bit * XFS_BLI_CHUNK;

			vecp->i_addr = xfs_buf_offset(bp, buffer_offset);

			vecp->i_len = nbits * XFS_BLI_CHUNK;

			XLOG_VEC_SET_TYPE(vecp, XLOG_REG_TYPE_BCHUNK);

			nvecs++;

			vecp++;

			first_bit = next_bit;
@@ -337,6 +340,7 @@ xfs_buf_item_format( 
			buffer_offset = first_bit * XFS_BLI_CHUNK;

			vecp->i_addr = xfs_buf_offset(bp, buffer_offset);

			vecp->i_len = nbits * XFS_BLI_CHUNK;

			XLOG_VEC_SET_TYPE(vecp, XLOG_REG_TYPE_BCHUNK);

/* You would think we need to bump the nvecs here too, but we do not

 * this number is used by recovery, and it gets confused by the boundary

 * split here

fs/xfs/xfs_extfree_item.c

+2 −0
Original line number Diff line number Diff line
@@ -107,6 +107,7 @@ xfs_efi_item_format(xfs_efi_log_item_t *efip, 


	log_vector->i_addr = (xfs_caddr_t)&(efip->efi_format);

	log_vector->i_len = size;

	XLOG_VEC_SET_TYPE(log_vector, XLOG_REG_TYPE_EFI_FORMAT);

	ASSERT(size >= sizeof(xfs_efi_log_format_t));

}
@@ -426,6 +427,7 @@ xfs_efd_item_format(xfs_efd_log_item_t *efdp, 


	log_vector->i_addr = (xfs_caddr_t)&(efdp->efd_format);

	log_vector->i_len = size;

	XLOG_VEC_SET_TYPE(log_vector, XLOG_REG_TYPE_EFD_FORMAT);

	ASSERT(size >= sizeof(xfs_efd_log_format_t));

}

fs/xfs/xfs_inode_item.c

+9 −0
Original line number Diff line number Diff line
@@ -248,6 +248,7 @@ xfs_inode_item_format( 


	vecp->i_addr = (xfs_caddr_t)&iip->ili_format;

	vecp->i_len  = sizeof(xfs_inode_log_format_t);

	XLOG_VEC_SET_TYPE(vecp, XLOG_REG_TYPE_IFORMAT);

	vecp++;

	nvecs	     = 1;
@@ -292,6 +293,7 @@ xfs_inode_item_format( 


	vecp->i_addr = (xfs_caddr_t)&ip->i_d;

	vecp->i_len  = sizeof(xfs_dinode_core_t);

	XLOG_VEC_SET_TYPE(vecp, XLOG_REG_TYPE_ICORE);

	vecp++;

	nvecs++;

	iip->ili_format.ilf_fields |= XFS_ILOG_CORE;
@@ -349,6 +351,7 @@ xfs_inode_item_format( 
				vecp->i_addr =

					(char *)(ip->i_df.if_u1.if_extents);

				vecp->i_len = ip->i_df.if_bytes;

				XLOG_VEC_SET_TYPE(vecp, XLOG_REG_TYPE_IEXT);

			} else

#endif

			{
@@ -367,6 +370,7 @@ xfs_inode_item_format( 
				vecp->i_addr = (xfs_caddr_t)ext_buffer;

				vecp->i_len = xfs_iextents_copy(ip, ext_buffer,

						XFS_DATA_FORK);

				XLOG_VEC_SET_TYPE(vecp, XLOG_REG_TYPE_IEXT);

			}

			ASSERT(vecp->i_len <= ip->i_df.if_bytes);

			iip->ili_format.ilf_dsize = vecp->i_len;
@@ -384,6 +388,7 @@ xfs_inode_item_format( 
			ASSERT(ip->i_df.if_broot != NULL);

			vecp->i_addr = (xfs_caddr_t)ip->i_df.if_broot;

			vecp->i_len = ip->i_df.if_broot_bytes;

			XLOG_VEC_SET_TYPE(vecp, XLOG_REG_TYPE_IBROOT);

			vecp++;

			nvecs++;

			iip->ili_format.ilf_dsize = ip->i_df.if_broot_bytes;
@@ -409,6 +414,7 @@ xfs_inode_item_format( 
			ASSERT((ip->i_df.if_real_bytes == 0) ||

			       (ip->i_df.if_real_bytes == data_bytes));

			vecp->i_len = (int)data_bytes;

			XLOG_VEC_SET_TYPE(vecp, XLOG_REG_TYPE_ILOCAL);

			vecp++;

			nvecs++;

			iip->ili_format.ilf_dsize = (unsigned)data_bytes;
@@ -486,6 +492,7 @@ xfs_inode_item_format( 
			vecp->i_len = xfs_iextents_copy(ip, ext_buffer,

					XFS_ATTR_FORK);

#endif

			XLOG_VEC_SET_TYPE(vecp, XLOG_REG_TYPE_IATTR_EXT);

			iip->ili_format.ilf_asize = vecp->i_len;

			vecp++;

			nvecs++;
@@ -500,6 +507,7 @@ xfs_inode_item_format( 
			ASSERT(ip->i_afp->if_broot != NULL);

			vecp->i_addr = (xfs_caddr_t)ip->i_afp->if_broot;

			vecp->i_len = ip->i_afp->if_broot_bytes;

			XLOG_VEC_SET_TYPE(vecp, XLOG_REG_TYPE_IATTR_BROOT);

			vecp++;

			nvecs++;

			iip->ili_format.ilf_asize = ip->i_afp->if_broot_bytes;
@@ -523,6 +531,7 @@ xfs_inode_item_format( 
			ASSERT((ip->i_afp->if_real_bytes == 0) ||

			       (ip->i_afp->if_real_bytes == data_bytes));

			vecp->i_len = (int)data_bytes;

			XLOG_VEC_SET_TYPE(vecp, XLOG_REG_TYPE_IATTR_LOCAL);

			vecp++;

			nvecs++;

			iip->ili_format.ilf_asize = (unsigned)data_bytes;

fs/xfs/xfs_log.c

+151 −10
Original line number Diff line number Diff line
@@ -159,11 +159,15 @@ xfs_buftarg_t *xlog_target; 
void

xlog_trace_loggrant(xlog_t *log, xlog_ticket_t *tic, xfs_caddr_t string)

{

	unsigned long cnts;



	if (!log->l_grant_trace) {

		log->l_grant_trace = ktrace_alloc(1024, KM_NOSLEEP);

		log->l_grant_trace = ktrace_alloc(2048, KM_NOSLEEP);

		if (!log->l_grant_trace)

			return;

	}

	/* ticket counts are 1 byte each */

	cnts = ((unsigned long)tic->t_ocnt) | ((unsigned long)tic->t_cnt) << 8;



	ktrace_enter(log->l_grant_trace,

		     (void *)tic,
@@ -178,10 +182,10 @@ xlog_trace_loggrant(xlog_t *log, xlog_ticket_t *tic, xfs_caddr_t string) 
		     (void *)((unsigned long)CYCLE_LSN(log->l_tail_lsn)),

		     (void *)((unsigned long)BLOCK_LSN(log->l_tail_lsn)),

		     (void *)string,

		     (void *)((unsigned long)13),

		     (void *)((unsigned long)14),

		     (void *)((unsigned long)15),

		     (void *)((unsigned long)16));

		     (void *)((unsigned long)tic->t_trans_type),

		     (void *)cnts,

		     (void *)((unsigned long)tic->t_curr_res),

		     (void *)((unsigned long)tic->t_unit_res));

}



void
@@ -274,9 +278,11 @@ xfs_log_done(xfs_mount_t *mp, 
		 * Release ticket if not permanent reservation or a specifc

		 * request has been made to release a permanent reservation.

		 */

		xlog_trace_loggrant(log, ticket, "xfs_log_done: (non-permanent)");

		xlog_ungrant_log_space(log, ticket);

		xlog_state_put_ticket(log, ticket);

	} else {

		xlog_trace_loggrant(log, ticket, "xfs_log_done: (permanent)");

		xlog_regrant_reserve_log_space(log, ticket);

	}
@@ -399,7 +405,8 @@ xfs_log_reserve(xfs_mount_t *mp, 
		int		 cnt,

		xfs_log_ticket_t *ticket,

		__uint8_t	 client,

		uint		 flags)

		uint		 flags,

		uint		 t_type)

{

	xlog_t		*log = mp->m_log;

	xlog_ticket_t	*internal_ticket;
@@ -421,13 +428,19 @@ xfs_log_reserve(xfs_mount_t *mp, 
	if (*ticket != NULL) {

		ASSERT(flags & XFS_LOG_PERM_RESERV);

		internal_ticket = (xlog_ticket_t *)*ticket;

		xlog_trace_loggrant(log, internal_ticket, "xfs_log_reserve: existing ticket (permanent trans)");

		xlog_grant_push_ail(mp, internal_ticket->t_unit_res);

		retval = xlog_regrant_write_log_space(log, internal_ticket);

	} else {

		/* may sleep if need to allocate more tickets */

		internal_ticket = xlog_ticket_get(log, unit_bytes, cnt,

						  client, flags);

		internal_ticket->t_trans_type = t_type;

		*ticket = internal_ticket;

		xlog_trace_loggrant(log, internal_ticket, 

			(internal_ticket->t_flags & XLOG_TIC_PERM_RESERV) ?

			"xfs_log_reserve: create new ticket (permanent trans)" :

			"xfs_log_reserve: create new ticket");

		xlog_grant_push_ail(mp,

				    (internal_ticket->t_unit_res *

				     internal_ticket->t_cnt));
@@ -601,8 +614,9 @@ xfs_log_unmount_write(xfs_mount_t *mp) 
	if (! (XLOG_FORCED_SHUTDOWN(log))) {

		reg[0].i_addr = (void*)&magic;

		reg[0].i_len  = sizeof(magic);

		XLOG_VEC_SET_TYPE(&reg[0], XLOG_REG_TYPE_UNMOUNT);



		error = xfs_log_reserve(mp, 600, 1, &tic, XFS_LOG, 0);

		error = xfs_log_reserve(mp, 600, 1, &tic, XFS_LOG, 0, 0);

		if (!error) {

			/* remove inited flag */

			((xlog_ticket_t *)tic)->t_flags = 0;
@@ -1272,6 +1286,7 @@ xlog_commit_record(xfs_mount_t *mp, 


	reg[0].i_addr = NULL;

	reg[0].i_len = 0;

	XLOG_VEC_SET_TYPE(&reg[0], XLOG_REG_TYPE_COMMIT);



	ASSERT_ALWAYS(iclog);

	if ((error = xlog_write(mp, reg, 1, ticket, commitlsnp,
@@ -1604,6 +1619,117 @@ xlog_state_finish_copy(xlog_t *log, 






/*

 * print out info relating to regions written which consume

 * the reservation

 */

#if defined(XFS_LOG_RES_DEBUG)

STATIC void

xlog_print_tic_res(xfs_mount_t *mp, xlog_ticket_t *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 */

	static char *res_type_str[XLOG_REG_TYPE_MAX] = {

	    "bformat",

	    "bchunk",

	    "efi_format",

	    "efd_format",

	    "iformat",

	    "icore",

	    "iext",

	    "ibroot",

	    "ilocal",

	    "iattr_ext",

	    "iattr_broot",

	    "iattr_local",

	    "qformat",

	    "dquot",

	    "quotaoff",

	    "LR header",

	    "unmount",

	    "commit",

	    "trans header"

	};

	static char *trans_type_str[XFS_TRANS_TYPE_MAX] = {

	    "SETATTR_NOT_SIZE",

	    "SETATTR_SIZE",

	    "INACTIVE",

	    "CREATE",

	    "CREATE_TRUNC",

	    "TRUNCATE_FILE",

	    "REMOVE",

	    "LINK",

	    "RENAME",

	    "MKDIR",

	    "RMDIR",

	    "SYMLINK",

	    "SET_DMATTRS",

	    "GROWFS",

	    "STRAT_WRITE",

	    "DIOSTRAT",

	    "WRITE_SYNC",

	    "WRITEID",

	    "ADDAFORK",

	    "ATTRINVAL",

	    "ATRUNCATE",

	    "ATTR_SET",

	    "ATTR_RM",

	    "ATTR_FLAG",

	    "CLEAR_AGI_BUCKET",

	    "QM_SBCHANGE",

	    "DUMMY1",

	    "DUMMY2",

	    "QM_QUOTAOFF",

	    "QM_DQALLOC",

	    "QM_SETQLIM",

	    "QM_DQCLUSTER",

	    "QM_QINOCREATE",

	    "QM_QUOTAOFF_END",

	    "SB_UNIT",

	    "FSYNC_TS",

	    "GROWFSRT_ALLOC",

	    "GROWFSRT_ZERO",

	    "GROWFSRT_FREE",

	    "SWAPEXT"

	};



	xfs_fs_cmn_err(CE_WARN, mp,

			"xfs_log_write: reservation summary:\n"

			"  trans type  = %s (%u)\n"

			"  unit res    = %d bytes\n"

			"  current res = %d bytes\n"

			"  total reg   = %u bytes (o/flow = %u bytes)\n"

			"  ophdrs      = %u (ophdr space = %u bytes)\n"

			"  ophdr + reg = %u bytes\n"

			"  num regions = %u\n",

			((ticket->t_trans_type <= 0 ||

			  ticket->t_trans_type > XFS_TRANS_TYPE_MAX) ?

			  "bad-trans-type" : trans_type_str[ticket->t_trans_type-1]),

			ticket->t_trans_type,

			ticket->t_unit_res,

			ticket->t_curr_res,

			ticket->t_res_arr_sum, ticket->t_res_o_flow,

			ticket->t_res_num_ophdrs, ophdr_spc,

			ticket->t_res_arr_sum + 

			  ticket->t_res_o_flow + ophdr_spc,

			ticket->t_res_num);



	for (i = 0; i < ticket->t_res_num; i++) {

	   	uint r_type = ticket->t_res_arr[i].r_type; 

		cmn_err(CE_WARN,

			    "region[%u]: %s - %u bytes\n",

			    i, 

			    ((r_type <= 0 || r_type > XLOG_REG_TYPE_MAX) ?

			    "bad-rtype" : res_type_str[r_type-1]),

			    ticket->t_res_arr[i].r_len);

	}

}

#else

#define xlog_print_tic_res(mp, ticket)

#endif



/*

 * Write some region out to in-core log

 *
@@ -1677,16 +1803,21 @@ xlog_write(xfs_mount_t * mp, 
     * xlog_op_header_t and may need to be double word aligned.

     */

    len = 0;

    if (ticket->t_flags & XLOG_TIC_INITED)     /* acct for start rec of xact */

    if (ticket->t_flags & XLOG_TIC_INITED) {    /* acct for start rec of xact */

	len += sizeof(xlog_op_header_t);

	XLOG_TIC_ADD_OPHDR(ticket);

    }



    for (index = 0; index < nentries; index++) {

	len += sizeof(xlog_op_header_t);	    /* each region gets >= 1 */

	XLOG_TIC_ADD_OPHDR(ticket);

	len += reg[index].i_len;

	XLOG_TIC_ADD_REGION(ticket, reg[index].i_len, reg[index].i_type);

    }

    contwr = *start_lsn = 0;



    if (ticket->t_curr_res < len) {

	xlog_print_tic_res(mp, ticket);

#ifdef DEBUG

	xlog_panic(

		"xfs_log_write: reservation ran out. Need to up reservation");
@@ -1790,6 +1921,7 @@ xlog_write(xfs_mount_t * mp, 
		len += sizeof(xlog_op_header_t); /* from splitting of region */

		/* account for new log op header */

		ticket->t_curr_res -= sizeof(xlog_op_header_t);

		XLOG_TIC_ADD_OPHDR(ticket);

	    }

	    xlog_verify_dest_ptr(log, ptr);
@@ -2282,6 +2414,9 @@ xlog_state_get_iclog_space(xlog_t *log, 
	 */

	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);

		INT_SET(head->h_cycle, ARCH_CONVERT, log->l_curr_cycle);

		ASSIGN_LSN(head->h_lsn, log);

		ASSERT(log->l_curr_block >= 0);
@@ -2468,6 +2603,7 @@ xlog_regrant_write_log_space(xlog_t *log, 
#endif



	tic->t_curr_res = tic->t_unit_res;

	XLOG_TIC_RESET_RES(tic);



	if (tic->t_cnt > 0)

		return (0);
@@ -2608,6 +2744,7 @@ xlog_regrant_reserve_log_space(xlog_t *log, 
	XLOG_GRANT_SUB_SPACE(log, ticket->t_curr_res, 'w');

	XLOG_GRANT_SUB_SPACE(log, ticket->t_curr_res, 'r');

	ticket->t_curr_res = ticket->t_unit_res;

	XLOG_TIC_RESET_RES(ticket);

	xlog_trace_loggrant(log, ticket,

			    "xlog_regrant_reserve_log_space: sub current res");

	xlog_verify_grant_head(log, 1);
@@ -2624,6 +2761,7 @@ xlog_regrant_reserve_log_space(xlog_t *log, 
	xlog_verify_grant_head(log, 0);

	GRANT_UNLOCK(log, s);

	ticket->t_curr_res = ticket->t_unit_res;

	XLOG_TIC_RESET_RES(ticket);

}	/* xlog_regrant_reserve_log_space */
@@ -3237,10 +3375,13 @@ xlog_ticket_get(xlog_t *log, 
	tic->t_tid		= (xlog_tid_t)((__psint_t)tic & 0xffffffff);

	tic->t_clientid		= client;

	tic->t_flags		= XLOG_TIC_INITED;

	tic->t_trans_type	= 0;

	if (xflags & XFS_LOG_PERM_RESERV)

		tic->t_flags |= XLOG_TIC_PERM_RESERV;

	sv_init(&(tic->t_sema), SV_DEFAULT, "logtick");



	XLOG_TIC_RESET_RES(tic);



	return tic;

}	/* xlog_ticket_get */