enable zfs_dbgmsg() by default, without dprintf()

zfs_dbgmsg() should record a message by default.  As a general
principal, these messages shouldn't be too verbose.  Furthermore, the
amount of memory used is limited to 4MB (by default).

dprintf() should only record a message if this is a debug build, and
ZFS_DEBUG_DPRINTF is set in zfs_flags.  This flag is not set by default
(even on debug builds).  These messages are extremely verbose, and
sometimes nontrivial to compute.

SET_ERROR() should only record a message if ZFS_DEBUG_SET_ERROR is set
in zfs_flags.  This flag is not set by default (even on debug builds).

This brings our behavior in line with illumos.  Note that the message
format is unchanged (including file, line, and function, even though
these are not recorded on illumos).

Reviewed-by: Giuseppe Di Natale <dinatale2@llnl.gov>
Reviewed-by: Brian Behlendorf <behlendorf1@llnl.gov>
Reviewed-by: Prakash Surya <prakash.surya@delphix.com>
Signed-off-by: Matthew Ahrens <mahrens@delphix.com>
Closes #7314

include/sys/zfs_debug.h

@@ -41,6 +41,7 @@ extern "C" {
 extern int zfs_flags;
 extern int zfs_recover;
 extern int zfs_free_leak_on_eio;
+extern int zfs_dbgmsg_enable;
 
 #define	ZFS_DEBUG_DPRINTF		(1 << 0)
 #define	ZFS_DEBUG_DBUF_VERIFY		(1 << 1)
@@ -55,10 +56,22 @@ extern int zfs_free_leak_on_eio;
 
 extern void __dprintf(const char *file, const char *func,
     int line, const char *fmt, ...);
-#define	dprintf(...) \
-	__dprintf(__FILE__, __func__, __LINE__, __VA_ARGS__)
 #define	zfs_dbgmsg(...) \
-	__dprintf(__FILE__, __func__, __LINE__, __VA_ARGS__)
+	if (zfs_dbgmsg_enable) \
+		__dprintf(__FILE__, __func__, __LINE__, __VA_ARGS__)
+
+#ifdef ZFS_DEBUG
+/*
+ * To enable this:
+ *
+ * $ echo 1 >/sys/module/zfs/parameters/zfs_flags
+ */
+#define	dprintf(...) \
+	if (zfs_flags & ZFS_DEBUG_DPRINTF) \
+		__dprintf(__FILE__, __func__, __LINE__, __VA_ARGS__)
+#else
+#define	dprintf(...) ((void)0)
+#endif /* ZFS_DEBUG */
 
 extern void zfs_panic_recover(const char *fmt, ...);
 

module/zfs/arc.c

@@ -7138,6 +7138,7 @@ arc_tempreserve_space(uint64_t reserve, uint64_t txg)
 
 	if (reserve + arc_tempreserve + anon_size > arc_c / 2 &&
 	    anon_size > arc_c / 4) {
+#ifdef ZFS_DEBUG
 		uint64_t meta_esize =
 		    refcount_count(&arc_anon->arcs_esize[ARC_BUFC_METADATA]);
 		uint64_t data_esize =
@@ -7146,6 +7147,7 @@ arc_tempreserve_space(uint64_t reserve, uint64_t txg)
 		    "anon_data=%lluK tempreserve=%lluK arc_c=%lluK\n",
 		    arc_tempreserve >> 10, meta_esize >> 10,
 		    data_esize >> 10, reserve >> 10, arc_c >> 10);
+#endif
 		DMU_TX_STAT_BUMP(dmu_tx_dirty_throttle);
 		return (SET_ERROR(ERESTART));
 	}

module/zfs/dmu_send.c

@@ -3440,6 +3440,7 @@ receive_read_record(struct receive_arg *ra)
 static void
 dprintf_drr(struct receive_record_arg *rrd, int err)
 {
+#ifdef ZFS_DEBUG
 	switch (rrd->header.drr_type) {
 	case DRR_OBJECT:
 	{
@@ -3520,6 +3521,7 @@ dprintf_drr(struct receive_record_arg *rrd, int err)
 	default:
 		return;
 	}
+#endif
 }
 
 /*

module/zfs/spa_misc.c

@@ -243,8 +243,7 @@ kmem_cache_t *spa_buffer_pool;
 int spa_mode_global;
 
 #ifdef ZFS_DEBUG
-/* Everything except dprintf and spa is on by default in debug builds */
+int zfs_flags = ~(ZFS_DEBUG_DPRINTF | ZFS_DEBUG_SET_ERROR | ZFS_DEBUG_SPA);
-int zfs_flags = ~(ZFS_DEBUG_DPRINTF | ZFS_DEBUG_SPA);
 #else
 int zfs_flags = 0;
 #endif

module/zfs/zfs_debug.c

@@ -33,20 +33,18 @@ int zfs_dbgmsg_maxsize = 4<<20; /* 4MB */
 kstat_t *zfs_dbgmsg_kstat;
 
 /*
- * By default only enable the internal ZFS debug messages when running
+ * Internal ZFS debug messages are enabled by default.
- * in userspace (ztest).  The kernel log must be manually enabled.
  *
- * # Enable the kernel debug message log.
+ * # Print debug messages
- * echo 1 > /sys/module/zfs/parameters/zfs_dbgmsg_enable
+ * cat /proc/spl/kstat/zfs/dbgmsg
+ *
+ * # Disable the kernel debug message log.
+ * echo 0 > /sys/module/zfs/parameters/zfs_dbgmsg_enable
  *
  * # Clear the kernel debug message log.
  * echo 0 >/proc/spl/kstat/zfs/dbgmsg
  */
-#if defined(_KERNEL) && !defined(ZFS_DEBUG)
-int zfs_dbgmsg_enable = 0;
-#else
 int zfs_dbgmsg_enable = 1;
-#endif
 
 static int
 zfs_dbgmsg_headers(char *buf, size_t size)
@@ -164,6 +162,11 @@ __zfs_dbgmsg(char *buf)
 void
 __set_error(const char *file, const char *func, int line, int err)
 {
+	/*
+	 * To enable this:
+	 *
+	 * $ echo 512 >/sys/module/zfs/parameters/zfs_flags
+	 */
 	if (zfs_flags & ZFS_DEBUG_SET_ERROR)
 		__dprintf(file, func, line, "error %lu", err);
 }
@@ -179,10 +182,6 @@ __dprintf(const char *file, const char *func, int line, const char *fmt, ...)
 	char *nl;
 	int i;
 
-	if (!zfs_dbgmsg_enable &&
-	    !(zfs_flags & (ZFS_DEBUG_DPRINTF | ZFS_DEBUG_SET_ERROR)))
-		return;
-
 	size = 1024;
 	buf = kmem_alloc(size, KM_SLEEP);
 
@@ -215,28 +214,23 @@ __dprintf(const char *file, const char *func, int line, const char *fmt, ...)
 	 * To get this data enable the zfs__dprintf trace point as shown:
 	 *
 	 * # Enable zfs__dprintf tracepoint, clear the tracepoint ring buffer
-	 * $ echo 1 > /sys/module/zfs/parameters/zfs_flags
 	 * $ echo 1 > /sys/kernel/debug/tracing/events/zfs/enable
 	 * $ echo 0 > /sys/kernel/debug/tracing/trace
 	 *
 	 * # Dump the ring buffer.
 	 * $ cat /sys/kernel/debug/tracing/trace
 	 */
-	if (zfs_flags & (ZFS_DEBUG_DPRINTF | ZFS_DEBUG_SET_ERROR))
+	DTRACE_PROBE1(zfs__dprintf, char *, buf);
-		DTRACE_PROBE1(zfs__dprintf, char *, buf);
 
 	/*
-	 * To get this data enable the zfs debug log as shown:
+	 * To get this data:
 	 *
-	 * # Set zfs_dbgmsg enable, clear the log buffer
-	 * $ echo 1 > /sys/module/zfs/parameters/zfs_dbgmsg_enable
-	 * $ echo 0 > /proc/spl/kstat/zfs/dbgmsg
-	 *
-	 * # Dump the log buffer.
 	 * $ cat /proc/spl/kstat/zfs/dbgmsg
+	 *
+	 * To clear the buffer:
+	 * $ echo 0 > /proc/spl/kstat/zfs/dbgmsg
 	 */
-	if (zfs_dbgmsg_enable)
+	__zfs_dbgmsg(buf);
-		__zfs_dbgmsg(buf);
 
 	kmem_free(buf, size);
 }