Re: [PATCH] xfs: prevent NMI timeouts in cmn_err

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 



Dave, overall it looks good - just a few minor points below.
Thanks for doing this.

----- "Dave Chinner" <david@xxxxxxxxxxxxx> wrote:

> From: Dave Chinner <dchinner@xxxxxxxxxx>
> 
> We currently have a global error message buffer in cmn_err that is
> protected by a spin lock that disables interrupts.  Recently there
> have been reports of NMI timeouts occurring when the console is
> being flooded by SCSI error reports due to cmn_err() getting stuck
> trying to print to the console while holding this lock (i.e. with
> interrupts disabled). The NMI watchdog is seeing this CPU as
> non-responding and so is triggering a panic.  While the trigger for
> the reported case is SCSI errors, pretty much anything that spams
> the kernel log could cause this to occur.
> 
> Realistically the only reason that we have the intemediate message
> buffer is to prepend the correct kernel log level prefix to the log
> message. The only reason we have the lock is to protect the global
> message buffer and the only reason the message buffer is global is
> to keep it off the stack. Hence if we can avoid needing a global
> message buffer we avoid needing the lock, and we can do this with a
> small amount of cleanup and some preprocessor tricks:
> 
> 	1. clean up xfs_cmn_err() panic mask functionality to avoid
> 	   needing debug code in xfs_cmn_err()
> 	2. remove the couple of "!" message prefixes that still exist that
> 	   the existing cmn_err() code steps over.
> 	3. redefine CE_* levels directly to KERN_*
> 	4. redefine cmn_err() and friends to use printk() directly
> 	   via variable argument length macros.
> 
> By doing this, we can completely remove the cmn_err() code and the
> lock that is causing the problems, and rely solely on printk()
> serialisation to ensure that we don't get garbled messages.
> 
> A series of followup patches is really needed to clean up all the
> cmn_err() calls and related messages properly, but that results in a
> series that is not easily back portable to enterprise kernels. Hence
> this initial fix is only to address the direct problem in the lowest
> impact way possible.
> 
> Signed-off-by: Dave Chinner <dchinner@xxxxxxxxxx>
> ---
>  fs/xfs/linux-2.6/xfs_sysctl.c |   22 +++++++++++-
>  fs/xfs/support/debug.c        |   76
> -----------------------------------------
>  fs/xfs/support/debug.h        |   40 +++++++++++++++++-----
>  fs/xfs/xfs_error.c            |   31 -----------------
>  fs/xfs/xfs_error.h            |   14 ++-----
>  fs/xfs/xfs_log.c              |    2 +-
>  fs/xfs/xfs_log_recover.c      |    2 +-
>  7 files changed, 58 insertions(+), 129 deletions(-)
> 
> diff --git a/fs/xfs/linux-2.6/xfs_sysctl.c
> b/fs/xfs/linux-2.6/xfs_sysctl.c
> index 7bb5092..768acd8 100644
> --- a/fs/xfs/linux-2.6/xfs_sysctl.c
> +++ b/fs/xfs/linux-2.6/xfs_sysctl.c
> @@ -51,6 +51,26 @@ xfs_stats_clear_proc_handler(
>  
>  	return ret;
>  }
> +
> +STATIC int
> +xfs_panic_mask_proc_handler(
> +	ctl_table	*ctl,
> +	int		write,
> +	void		__user *buffer,
> +	size_t		*lenp,
> +	loff_t		*ppos)
> +{
> +	int		ret, *valp = ctl->data;
> +
> +	ret = proc_dointvec_minmax(ctl, write, buffer, lenp, ppos);
> +	if (!ret && write) {
> +		xfs_panic_mask = *valp;
> +#ifdef DEBUG
> +		xfs_panic_mask |= (XFS_PTAG_SHUTDOWN_CORRUPT | XFS_PTAG_LOGRES);
> +#endif
> +	}
> +	return ret;
> +}
>  #endif /* CONFIG_PROC_FS */
>  
>  static ctl_table xfs_table[] = {
> @@ -77,7 +97,7 @@ static ctl_table xfs_table[] = {
>  		.data		= &xfs_params.panic_mask.val,
>  		.maxlen		= sizeof(int),
>  		.mode		= 0644,
> -		.proc_handler	= proc_dointvec_minmax,
> +		.proc_handler	= xfs_panic_mask_proc_handler,
>  		.extra1		= &xfs_params.panic_mask.min,
>  		.extra2		= &xfs_params.panic_mask.max
>  	},
> diff --git a/fs/xfs/support/debug.c b/fs/xfs/support/debug.c
> index 975aa10..fa39e98 100644
> --- a/fs/xfs/support/debug.c
> +++ b/fs/xfs/support/debug.c
> @@ -25,82 +25,6 @@
>  #include "xfs_mount.h"
>  #include "xfs_error.h"
>  
> -static char		message[1024];	/* keep it off the stack */
> -static DEFINE_SPINLOCK(xfs_err_lock);
> -
> -/* Translate from CE_FOO to KERN_FOO, err_level(CE_FOO) == KERN_FOO
> */
> -#define XFS_MAX_ERR_LEVEL	7
> -#define XFS_ERR_MASK		((1 << 3) - 1)
> -static const char * const	err_level[XFS_MAX_ERR_LEVEL+1] =
> -					{KERN_EMERG, KERN_ALERT, KERN_CRIT,
> -					 KERN_ERR, KERN_WARNING, KERN_NOTICE,
> -					 KERN_INFO, KERN_DEBUG};
> -
> -void
> -cmn_err(register int level, char *fmt, ...)
> -{
> -	char	*fp = fmt;
> -	int	len;
> -	ulong	flags;
> -	va_list	ap;
> -
> -	level &= XFS_ERR_MASK;
> -	if (level > XFS_MAX_ERR_LEVEL)
> -		level = XFS_MAX_ERR_LEVEL;
> -	spin_lock_irqsave(&xfs_err_lock,flags);
> -	va_start(ap, fmt);
> -	if (*fmt == '!') fp++;
> -	len = vsnprintf(message, sizeof(message), fp, ap);
> -	if (len >= sizeof(message))
> -		len = sizeof(message) - 1;
> -	if (message[len-1] == '\n')
> -		message[len-1] = 0;
> -	printk("%s%s\n", err_level[level], message);
> -	va_end(ap);
> -	spin_unlock_irqrestore(&xfs_err_lock,flags);
> -	BUG_ON(level == CE_PANIC);
> -}
> -
> -void
> -xfs_fs_vcmn_err(
> -	int			level,
> -	struct xfs_mount	*mp,
> -	char			*fmt,
> -	va_list			ap)
> -{
> -	unsigned long		flags;
> -	int			len = 0;
> -
> -	level &= XFS_ERR_MASK;
> -	if (level > XFS_MAX_ERR_LEVEL)
> -		level = XFS_MAX_ERR_LEVEL;
> -
> -	spin_lock_irqsave(&xfs_err_lock,flags);
> -
> -	if (mp) {
> -		len = sprintf(message, "Filesystem \"%s\": ", mp->m_fsname);
> -
> -		/*
> -		 * Skip the printk if we can't print anything useful
> -		 * due to an over-long device name.
> -		 */
> -		if (len >= sizeof(message))
> -			goto out;
> -	}
> -
> -	len = vsnprintf(message + len, sizeof(message) - len, fmt, ap);
> -	if (len >= sizeof(message))
> -		len = sizeof(message) - 1;
> -	if (message[len-1] == '\n')
> -		message[len-1] = 0;
> -
> -	printk("%s%s\n", err_level[level], message);
> - out:
> -	spin_unlock_irqrestore(&xfs_err_lock,flags);
> -
> -	BUG_ON(level == CE_PANIC);
> -}
> -
>  void
>  assfail(char *expr, char *file, int line)
>  {
> diff --git a/fs/xfs/support/debug.h b/fs/xfs/support/debug.h
> index d2d2046..f659bd0 100644
> --- a/fs/xfs/support/debug.h
> +++ b/fs/xfs/support/debug.h
> @@ -20,15 +20,37 @@
>  
>  #include <stdarg.h>
>  
> -#define CE_DEBUG        7               /* debug        */
> -#define CE_CONT         6               /* continuation */
> -#define CE_NOTE         5               /* notice       */
> -#define CE_WARN         4               /* warning      */
> -#define CE_ALERT        1               /* alert        */
> -#define CE_PANIC        0               /* panic        */
> -
> -extern void cmn_err(int, char *, ...)
> -	__attribute__ ((format (printf, 2, 3)));
> +#define CE_DEBUG        KERN_DEBUG
> +#define CE_CONT         KERN_INFO
> +#define CE_NOTE         KERN_NOTICE
> +#define CE_WARN         KERN_WARNING
> +#define CE_ALERT        KERN_ALERT
> +#define CE_PANIC        KERN_EMERG
> +
> +#define cmn_err(lvl, fmt, args...)	\
> +	do { \
> +		printk(lvl fmt, ## args); \

The old cmn_err() routine would append a newline if one was not supplied.
As far as I know printk() will not do the same so either we need to fix
all calls to cmn_err() to supply a '\n' or add it here (at the risk of
having two newlines) - maybe:

printk(lvl fmt "\n", ## args);

> +		BUG_ON(strncmp(lvl, KERN_EMERG, strlen(KERN_EMERG)) == 0); \
> +	} while (0)
> +
> +#define xfs_fs_cmn_err(lvl, mp, fmt, args...)	\
> +	do { \
> +		printk(lvl "Filesystem %s: " fmt, (mp)->m_fsname, ## args); \

printk(lvl "Filesystem %s: " fmt "\n", (mp)->m_fsname, ## args);

> +		BUG_ON(strncmp(lvl, KERN_EMERG, strlen(KERN_EMERG)) == 0); \
> +	} while (0)
> +
> +/* All callers to xfs_cmn_err use CE_ALERT, so don't bother testing
> lvl */
> +#define xfs_cmn_err(panic_tag, lvl, mp, fmt, args...)	\
> +	do { \
> +		int	panic = 0; \
> +		if (xfs_panic_mask && (xfs_panic_mask & panic_tag)) { \
> +			printk(KERN_ALERT "XFS: Transforming an alert into a BUG."); \
> +			panic = 1; \
> +		} \
> +		printk(KERN_ALERT "Filesystem %s: " fmt, (mp)->m_fsname, ## args);
> \
> +		BUG_ON(panic); \
> +	} while (0)

I think we can simplify this case a bit and remove the panic variable,
like this:

	do { \
		printk(KERN_ALERT "Filesystem %s: " fmt "\n", (mp)->m_fsname, ## args);
		if (xfs_panic_mask && (xfs_panic_mask & panic_tag)) { \
			printk(KERN_ALERT "XFS: Transforming an alert into a BUG.\n"); \
			BUG_ON(1); \
		} \
	} while (0)

This also reorders the messages which I think makes more sense.

> +
>  extern void assfail(char *expr, char *f, int l);
>  
>  #define ASSERT_ALWAYS(expr)	\
> diff --git a/fs/xfs/xfs_error.c b/fs/xfs/xfs_error.c
> index c78cc6a..4c7db74 100644
> --- a/fs/xfs/xfs_error.c
> +++ b/fs/xfs/xfs_error.c
> @@ -152,37 +152,6 @@ xfs_errortag_clearall(xfs_mount_t *mp, int loud)
>  }
>  #endif /* DEBUG */
>  
> -
> -void
> -xfs_fs_cmn_err(int level, xfs_mount_t *mp, char *fmt, ...)
> -{
> -	va_list ap;
> -
> -	va_start(ap, fmt);
> -	xfs_fs_vcmn_err(level, mp, fmt, ap);
> -	va_end(ap);
> -}
> -
> -void
> -xfs_cmn_err(int panic_tag, int level, xfs_mount_t *mp, char *fmt,
> ...)
> -{
> -	va_list ap;
> -
> -#ifdef DEBUG
> -	xfs_panic_mask |= (XFS_PTAG_SHUTDOWN_CORRUPT | XFS_PTAG_LOGRES);
> -#endif
> -
> -	if (xfs_panic_mask && (xfs_panic_mask & panic_tag)
> -	    && (level & CE_ALERT)) {
> -		level &= ~CE_ALERT;
> -		level |= CE_PANIC;
> -		cmn_err(CE_ALERT, "XFS: Transforming an alert into a BUG.");
> -	}
> -	va_start(ap, fmt);
> -	xfs_fs_vcmn_err(level, mp, fmt, ap);
> -	va_end(ap);
> -}
> -
>  void
>  xfs_error_report(
>  	const char		*tag,
> diff --git a/fs/xfs/xfs_error.h b/fs/xfs/xfs_error.h
> index f338847..6b518d2 100644
> --- a/fs/xfs/xfs_error.h
> +++ b/fs/xfs/xfs_error.h
> @@ -162,21 +162,15 @@ extern int xfs_errortag_clearall(xfs_mount_t
> *mp, int loud);
>  
>  struct xfs_mount;
>  
> -extern void xfs_fs_vcmn_err(int level, struct xfs_mount *mp,
> -		char *fmt, va_list ap)
> -	__attribute__ ((format (printf, 3, 0)));
> -extern void xfs_cmn_err(int panic_tag, int level, struct xfs_mount
> *mp,
> -			char *fmt, ...)
> -	__attribute__ ((format (printf, 4, 5)));
> -extern void xfs_fs_cmn_err(int level, struct xfs_mount *mp, char
> *fmt, ...)
> -	__attribute__ ((format (printf, 3, 4)));
> -
>  extern void xfs_hex_dump(void *p, int length);
>  
>  #define xfs_fs_repair_cmn_err(level, mp, fmt, args...) \
>  	xfs_fs_cmn_err(level, mp, fmt "  Unmount and run xfs_repair.", ##
> args)
>  
>  #define xfs_fs_mount_cmn_err(f, fmt, args...) \
> -	((f & XFS_MFSI_QUIET)? (void)0 : cmn_err(CE_WARN, "XFS: " fmt, ##
> args))
> +	do { \
> +		if (!(f & XFS_MFSI_QUIET)) 	\
> +			cmn_err(CE_WARN, "XFS: " fmt, ## args); \
> +	} while (0)
>  
>  #endif	/* __XFS_ERROR_H__ */
> diff --git a/fs/xfs/xfs_log.c b/fs/xfs/xfs_log.c
> index abdcbd0..2209035 100644
> --- a/fs/xfs/xfs_log.c
> +++ b/fs/xfs/xfs_log.c
> @@ -431,7 +431,7 @@ xfs_log_mount(
>  		cmn_err(CE_NOTE, "XFS mounting filesystem %s", mp->m_fsname);
>  	else {
>  		cmn_err(CE_NOTE,
> -			"!Mounting filesystem \"%s\" in no-recovery mode.  Filesystem will
> be inconsistent.",
> +			"Mounting filesystem \"%s\" in no-recovery mode.  Filesystem will
> be inconsistent.",
>  			mp->m_fsname);
>  		ASSERT(mp->m_flags & XFS_MOUNT_RDONLY);
>  	}
> diff --git a/fs/xfs/xfs_log_recover.c b/fs/xfs/xfs_log_recover.c
> index 6e7dfbb..411f3a9 100644
> --- a/fs/xfs/xfs_log_recover.c
> +++ b/fs/xfs/xfs_log_recover.c
> @@ -3934,7 +3934,7 @@ xlog_recover_finish(
>  		log->l_flags &= ~XLOG_RECOVERY_NEEDED;
>  	} else {
>  		cmn_err(CE_DEBUG,
> -			"!Ending clean XFS mount for filesystem: %s\n",
> +			"Ending clean XFS mount for filesystem: %s\n",
>  			log->l_mp->m_fsname);
>  	}
>  	return 0;
> -- 
> 1.7.2.3
> 
> _______________________________________________
> xfs mailing list
> xfs@xxxxxxxxxxx
> http://oss.sgi.com/mailman/listinfo/xfs

_______________________________________________
xfs mailing list
xfs@xxxxxxxxxxx
http://oss.sgi.com/mailman/listinfo/xfs


[Index of Archives]     [Linux XFS Devel]     [Linux Filesystem Development]     [Filesystem Testing]     [Linux USB Devel]     [Linux Audio Users]     [Yosemite News]     [Linux Kernel]     [Linux SCSI]

  Powered by Linux