Cleanup ZFS debug infrastructure

Historically the internal zfs debug infrastructure has been
scattered throughout the code.  Since we expect to start making
more use of this code this patch performs some cleanup.

* Consolidate the zfs debug infrastructure in the zfs_debug.[ch]
  files.  This includes moving the zfs_flags and zfs_recover
  variables, plus moving the zfs_panic_recover() function.

* Remove the existing unused functionality in zfs_debug.c and
  replace it with code which correctly utilized the spl logging
  infrastructure.

* Remove the __dprintf() function from zfs_ioctl.c.  This is
  dead code, the dprintf() functionality in the kernel relies
  on the spl log support.

* Remove dprintf() from hdr_recl().  This wasn't particularly
  useful and was missing the required format specifier anyway.

* Subsequent patches should unify the dprintf() and zfs_dbgmsg()
  functions.

Signed-off-by: Brian Behlendorf <behlendorf1@llnl.gov>

include/sys/zfs_context.h

@@ -134,10 +134,9 @@ extern int aok;
  * ZFS debugging
  */
 
-#ifdef ZFS_DEBUG
 extern void dprintf_setup(int *argc, char **argv);
-#endif /* ZFS_DEBUG */
-
+extern void __dprintf(const char *file, const char *func,
+    int line, const char *fmt, ...);
 extern void cmn_err(int, const char *, ...);
 extern void vcmn_err(int, const char *, __va_list);
 extern void panic(const char *, ...);

include/sys/zfs_debug.h

@@ -25,10 +25,6 @@
 #ifndef _SYS_ZFS_DEBUG_H
 #define	_SYS_ZFS_DEBUG_H
 
-#ifdef	__cplusplus
-extern "C" {
-#endif
-
 #ifndef TRUE
 #define	TRUE 1
 #endif
@@ -38,58 +34,48 @@ extern "C" {
 #endif
 
 /*
- * ZFS debugging
+ * ZFS debugging - Always enabled for user space builds.
  */
-
 #if defined(DEBUG) || !defined(_KERNEL)
 #define	ZFS_DEBUG
 #endif
 
 extern int zfs_flags;
+extern int zfs_recover;
 
 #define	ZFS_DEBUG_DPRINTF	0x0001
 #define	ZFS_DEBUG_DBUF_VERIFY	0x0002
 #define	ZFS_DEBUG_DNODE_VERIFY	0x0004
 #define	ZFS_DEBUG_SNAPNAMES	0x0008
 #define	ZFS_DEBUG_MODIFY	0x0010
 
-#ifdef ZFS_DEBUG
-#if defined(_KERNEL) && defined(HAVE_SPL)
 /*
- * Log ZFS debug messages as the spl SS_USER1 subsystem.
+ * Always log zfs debug messages to the spl debug subsystem as SS_USER1.
+ * When the SPL is configured with debugging enabled these messages will
+ * appear in the internal spl debug log, otherwise they are a no-op.
  */
+#if defined(_KERNEL)
+
 #include <spl-debug.h>
+#define	dprintf(...)                                                   \
+	if (zfs_flags & ZFS_DEBUG_DPRINTF)                             \
+		__SDEBUG(NULL, SS_USER1, SD_DPRINTF, __VA_ARGS__)
 
-#ifdef SS_DEBUG_SUBSYS
-#undef SS_DEBUG_SUBSYS
-#endif
-#define SS_DEBUG_SUBSYS SS_USER1
-#define dprintf(...) SDEBUG_LIMIT(SD_DPRINTF, __VA_ARGS__)
+/*
+ * When zfs is running is user space the debugging is always enabled.
+ * The messages will be printed using the __dprintf() function and
+ * filtered based on the zfs_flags variable.
+ */
 #else
-extern void __dprintf(const char *file, const char *func,
-    int line, const char *fmt, ...);
-#define	dprintf(...) \
-	if (zfs_flags & ZFS_DEBUG_DPRINTF) \
+#define dprintf(...)                                                   \
+	if (zfs_flags & ZFS_DEBUG_DPRINTF)                             \
 		__dprintf(__FILE__, __func__, __LINE__, __VA_ARGS__)
-#endif /* _KERNEL && HAVE_SPL */
-#else
-#define	dprintf(...) ((void)0)
-#endif /* ZFS_DEBUG */
-
-extern void zfs_panic_recover(const char *fmt, ...);
 
-typedef struct zfs_dbgmsg {
-	list_node_t zdm_node;
-	time_t zdm_timestamp;
-	char zdm_msg[1]; /* variable length allocation */
-} zfs_dbgmsg_t;
+#endif /* _KERNEL */
 
-extern void zfs_dbgmsg_init(void);
-extern void zfs_dbgmsg_fini(void);
-extern void zfs_dbgmsg(const char *fmt, ...);
-
-#ifdef	__cplusplus
-}
-#endif
+void zfs_panic_recover(const char *fmt, ...);
+#define	zfs_dbgmsg(...)	dprintf(__VA_ARGS__)
+void zfs_dbgmsg_init(void);
+void zfs_dbgmsg_fini(void);
 
 #endif	/* _SYS_ZFS_DEBUG_H */

lib/libzpool/kernel.c

@@ -700,8 +700,6 @@ fop_getattr(vnode_t *vp, vattr_t *vap)
 	return (0);
 }
 
-#ifdef ZFS_DEBUG
-
 /*
  * =========================================================================
  * Figure out which debugging statements to print
@@ -814,8 +812,6 @@ __dprintf(const char *file, const char *func, int line, const char *fmt, ...)
 	}
 }
 
-#endif /* ZFS_DEBUG */
-
 /*
  * =========================================================================
  * cmn_err() and panic()

module/zfs/arc.c

@@ -885,7 +885,6 @@ buf_dest(void *vbuf, void *unused)
 static void
 hdr_recl(void *unused)
 {
-	dprintf("hdr_recl called\n");
 	/*
 	 * umem calls the reclaim func when we destroy the buf cache,
 	 * which is after we do arc_fini().

module/zfs/spa_misc.c

@@ -234,21 +234,6 @@ static avl_tree_t spa_l2cache_avl;
 kmem_cache_t *spa_buffer_pool;
 int spa_mode_global;
 
-#ifdef ZFS_DEBUG
-/* Everything except dprintf is on by default in debug builds */
-int zfs_flags = ~ZFS_DEBUG_DPRINTF;
-#else
-int zfs_flags = 0;
-#endif
-
-/*
- * zfs_recover can be set to nonzero to attempt to recover from
- * otherwise-fatal errors, typically caused by on-disk corruption.  When
- * set, calls to zfs_panic_recover() will turn into warning messages.
- */
-int zfs_recover = 0;
-
-
 /*
  * ==========================================================================
  * SPA config locking
@@ -1217,16 +1202,6 @@ spa_freeze(spa_t *spa)
 		txg_wait_synced(spa_get_dsl(spa), freeze_txg);
 }
 
-void
-zfs_panic_recover(const char *fmt, ...)
-{
-	va_list adx;
-
-	va_start(adx, fmt);
-	vcmn_err(zfs_recover ? CE_WARN : CE_PANIC, fmt, adx);
-	va_end(adx);
-}
-
 /*
  * This is a stripped-down version of strtoull, suitable only for converting
  * lowercase hexidecimal numbers that don't overflow.
@@ -1765,7 +1740,4 @@ EXPORT_SYMBOL(spa_writeable);
 EXPORT_SYMBOL(spa_mode);
 
 EXPORT_SYMBOL(spa_namespace_lock);
-
-module_param(zfs_recover, int, 0644);
-MODULE_PARM_DESC(zfs_recover, "Set to attempt to recover from fatal errors");
 #endif

module/zfs/zfs_debug.c

@@ -24,72 +24,60 @@
 
 #include <sys/zfs_context.h>
 
-list_t zfs_dbgmsgs;
-int zfs_dbgmsg_size;
-kmutex_t zfs_dbgmsgs_lock;
-int zfs_dbgmsg_maxsize = 1<<20; /* 1MB */
+/*
+ * Enable various debugging features.
+ */
+int zfs_flags = 0;
+
+/*
+ * zfs_recover can be set to nonzero to attempt to recover from
+ * otherwise-fatal errors, typically caused by on-disk corruption.  When
+ * set, calls to zfs_panic_recover() will turn into warning messages.
+ */
+int zfs_recover = 0;
 
-void
-zfs_dbgmsg_init(void)
-{
-	list_create(&zfs_dbgmsgs, sizeof (zfs_dbgmsg_t),
-	    offsetof(zfs_dbgmsg_t, zdm_node));
-	mutex_init(&zfs_dbgmsgs_lock, NULL, MUTEX_DEFAULT, NULL);
-}
 
 void
-zfs_dbgmsg_fini(void)
+zfs_panic_recover(const char *fmt, ...)
 {
-	zfs_dbgmsg_t *zdm;
+	va_list adx;
 
-	while ((zdm = list_remove_head(&zfs_dbgmsgs)) != NULL) {
-		int size = sizeof (zfs_dbgmsg_t) + strlen(zdm->zdm_msg);
-		kmem_free(zdm, size);
-		zfs_dbgmsg_size -= size;
-	}
-	mutex_destroy(&zfs_dbgmsgs_lock);
-	ASSERT3U(zfs_dbgmsg_size, ==, 0);
+	va_start(adx, fmt);
+	vcmn_err(zfs_recover ? CE_WARN : CE_PANIC, fmt, adx);
+	va_end(adx);
 }
 
 /*
- * Print these messages by running:
- * 	echo ::zfs_dbgmsg | mdb -k
- *
- * Monitor these messages by running:
- * 	dtrace -q -n 'zfs-dbgmsg{printf("%s\n", stringof(arg0))}'
+ * Debug logging is enabled by default for production kernel builds.
+ * The overhead for this is negligible and the logs can be valuable when
+ * debugging.  For non-production user space builds all debugging except
+ * logging is enabled since performance is no longer a concern.
  */
 void
-zfs_dbgmsg(const char *fmt, ...)
+zfs_dbgmsg_init(void)
 {
-	int size;
-	va_list adx;
-	zfs_dbgmsg_t *zdm;
-
-	va_start(adx, fmt);
-	size = vsnprintf(NULL, 0, fmt, adx);
-	va_end(adx);
+	if (zfs_flags == 0) {
+#if defined(_KERNEL)
+		zfs_flags = ZFS_DEBUG_DPRINTF;
+		spl_debug_mask |= SD_DPRINTF;
+		spl_debug_subsys |= SS_USER1;
+#else
+		zfs_flags = ~ZFS_DEBUG_DPRINTF;
+#endif /* _KERNEL */
+	}
+}
 
-	/*
-	 * There is one byte of string in sizeof (zfs_dbgmsg_t), used
-	 * for the terminating null.
-	 */
-	zdm = kmem_alloc(sizeof (zfs_dbgmsg_t) + size, KM_SLEEP);
-	zdm->zdm_timestamp = gethrestime_sec();
+void
+zfs_dbgmsg_fini(void)
+{
+	return;
+}
 
-	va_start(adx, fmt);
-	(void) vsnprintf(zdm->zdm_msg, size + 1, fmt, adx);
-	va_end(adx);
 
-	DTRACE_PROBE1(zfs__dbgmsg, char *, zdm->zdm_msg);
+#if defined(_KERNEL)
+module_param(zfs_flags, int, 0644);
+MODULE_PARM_DESC(zfs_flags, "Set additional debugging flags");
 
-	mutex_enter(&zfs_dbgmsgs_lock);
-	list_insert_tail(&zfs_dbgmsgs, zdm);
-	zfs_dbgmsg_size += sizeof (zfs_dbgmsg_t) + size;
-	while (zfs_dbgmsg_size > zfs_dbgmsg_maxsize) {
-		zdm = list_remove_head(&zfs_dbgmsgs);
-		size = sizeof (zfs_dbgmsg_t) + strlen(zdm->zdm_msg);
-		kmem_free(zdm, size);
-		zfs_dbgmsg_size -= size;
-	}
-	mutex_exit(&zfs_dbgmsgs_lock);
-}
+module_param(zfs_recover, int, 0644);
+MODULE_PARM_DESC(zfs_recover, "Set to attempt to recover from fatal errors");
+#endif /* _KERNEL */

module/zfs/zfs_ioctl.c

@@ -119,42 +119,6 @@ static int zfs_fill_zplprops_root(uint64_t, nvlist_t *, nvlist_t *,
     boolean_t *);
 int zfs_set_prop_nvlist(const char *, zprop_source_t, nvlist_t *, nvlist_t **);
 
-/* _NOTE(PRINTFLIKE(4)) - this is printf-like, but lint is too whiney */
-void
-__dprintf(const char *file, const char *func, int line, const char *fmt, ...)
-{
-	const char *newfile;
-	char buf[512];
-	va_list adx;
-
-	/*
-	 * Get rid of annoying "../common/" prefix to filename.
-	 */
-	newfile = strrchr(file, '/');
-	if (newfile != NULL) {
-		newfile = newfile + 1; /* Get rid of leading / */
-	} else {
-		newfile = file;
-	}
-
-	va_start(adx, fmt);
-	(void) vsnprintf(buf, sizeof (buf), fmt, adx);
-	va_end(adx);
-
-	/*
-	 * To get this data, use the zfs-dprintf probe as so:
-	 * dtrace -q -n 'zfs-dprintf \
-	 *	/stringof(arg0) == "dbuf.c"/ \
-	 *	{printf("%s: %s", stringof(arg1), stringof(arg3))}'
-	 * arg0 = file name
-	 * arg1 = function name
-	 * arg2 = line number
-	 * arg3 = message
-	 */
-	DTRACE_PROBE4(zfs__dprintf,
-	    char *, newfile, char *, func, int, line, char *, buf);
-}
-
 static void
 history_str_free(char *buf)
 {