Add line info and SET_ERROR() to ZFS debug log

Redefine the SET_ERROR macro in terms of __dprintf() so the error
return codes get logged as both tracepoint events (if tracepoints are
enabled) and as ZFS debug log entries.  This also allows us to use
the same definition of SET_ERROR() in kernel and user space.

Define a new debug flag ZFS_DEBUG_SET_ERROR=512 that may be bitwise
or'd into zfs_flags. Setting this flag enables both dprintf() and
SET_ERROR() messages in the debug log. That is, setting
ZFS_DEBUG_SET_ERROR and ZFS_DEBUG_DPRINTF|ZFS_DEBUG_SET_ERROR are
equivalent (this was done for sake of simplicity). Leaving
ZFS_DEBUG_SET_ERROR unset suppresses the SET_ERROR() messages which
helps avoid cluttering up the logs.

To enable SET_ERROR() logging, run:

  echo 1 >   /sys/module/zfs/parameters/zfs_dbgmsg_enable
  echo 512 > /sys/module/zfs/parameters/zfs_flags

Remove the zfs_set_error_class tracepoints event class since
SET_ERROR() now uses __dprintf(). This sacrifices a bit of
granularity when selecting individual tracepoint events to enable but
it makes the code simpler.

Include file, function, and line number information in debug log
entries.  The information is now added to the message buffer in
__dprintf() and as a result the zfs_dprintf_class tracepoints event
class was changed from a 4 parameter interface to a single parameter.

Reviewed-by: Brian Behlendorf <behlendorf1@llnl.gov>
Signed-off-by: Ned Bass <bass6@llnl.gov>
Closes #6400

diff --git a/include/sys/sdt.h b/include/sys/sdt.h
index 56efa1b3998b291bea2fee9c372b0d7f8147b395..9704072cb7474fa0149353fd63740da3c34f3cb9 100644 (file)
--- a/include/sys/sdt.h
+++ b/include/sys/sdt.h
@@ -34,13 +34,8 @@
 #define        ZFS_PROBE2(a, c, e)             ((void) 0)
 #define        ZFS_PROBE3(a, c, e, g)          ((void) 0)
 #define        ZFS_PROBE4(a, c, e, g, i)       ((void) 0)
-#define        ZFS_SET_ERROR(err)              ((void) 0)
 
-#else
-
-#if defined(HAVE_DECLARE_EVENT_CLASS)
-
-#include <sys/trace.h>
+#endif /* _KERNEL */
 
 /*
  * The set-error SDT probe is extra static, in that we declare its fake
@@ -55,16 +50,9 @@
  * twice, so it should not have side effects (e.g. something like:
  * "return (SET_ERROR(log_error(EINVAL, info)));" would log the error twice).
  */
-#define        SET_ERROR(err) \
-       (trace_zfs_set__error(__FILE__, __func__, __LINE__, err), err)
-
-#else
-
+extern void __set_error(const char *file, const char *func, int line, int err);
 #undef SET_ERROR
-#define        SET_ERROR(err) (err)
-
-#endif /* HAVE_DECLARE_EVENT_CLASS */
-
-#endif /* _KERNEL */
+#define        SET_ERROR(err) \
+       (__set_error(__FILE__, __func__, __LINE__, err), err)
 
 #endif /* _SYS_SDT_H */

diff --git a/include/sys/trace_dbgmsg.h b/include/sys/trace_dbgmsg.h
index 08d96c59c2fb091ac60dc895d697c30dff53948a..a4aab1e63f756146f521e5871f34d93cd40dfdda 100644 (file)
--- a/include/sys/trace_dbgmsg.h
+++ b/include/sys/trace_dbgmsg.h
@@ -37,92 +37,29 @@
  */
 
 /*
- * Generic support for four argument tracepoints of the form:
+ * Generic support for one argument tracepoints of the form:
  *
- * DTRACE_PROBE4(...,
- *     const char *, ...,
- *     const char *, ...,
- *     int, ...,
+ * DTRACE_PROBE1(...,
  *     const char *, ...);
  */
 /* BEGIN CSTYLED */
 DECLARE_EVENT_CLASS(zfs_dprintf_class,
-       TP_PROTO(const char *file, const char *function, int line,
-           const char *msg),
-       TP_ARGS(file, function, line, msg),
+       TP_PROTO(const char *msg),
+       TP_ARGS(msg),
        TP_STRUCT__entry(
-           __string(file, file)
-           __string(function, function)
-           __field(int,                line)
            __string(msg, msg)
        ),
        TP_fast_assign(
-           __assign_str(file, strchr(file, '/') ?
-               strrchr(file, '/') + 1 : file)
-           __assign_str(function, function);
-           __entry->line               = line;
            __assign_str(msg, msg);
        ),
-       TP_printk("%s:%d:%s(): %s", __get_str(file), __entry->line,
-           __get_str(function), __get_str(msg))
+       TP_printk("%s", __get_str(msg))
 );
 /* END CSTYLED */
 
 /* BEGIN CSTYLED */
 #define        DEFINE_DPRINTF_EVENT(name) \
 DEFINE_EVENT(zfs_dprintf_class, name, \
-       TP_PROTO(const char *file, const char *function, int line, \
-           const char *msg), \
-       TP_ARGS(file, function, line, msg))
+       TP_PROTO(const char *msg), \
+       TP_ARGS(msg))
 /* END CSTYLED */
 DEFINE_DPRINTF_EVENT(zfs_zfs__dprintf);
-
-/*
- * Generic support for four argument tracepoints of the form:
- *
- * DTRACE_PROBE4(...,
- *     const char *, ...,
- *     const char *, ...,
- *     int, ...,
- *     uintptr_t, ...);
- */
-/* BEGIN CSTYLED */
-DECLARE_EVENT_CLASS(zfs_set_error_class,
-       TP_PROTO(const char *file, const char *function, int line,
-           uintptr_t error),
-       TP_ARGS(file, function, line, error),
-       TP_STRUCT__entry(
-           __string(file, file)
-           __string(function, function)
-           __field(int,                line)
-           __field(uintptr_t,          error)
-       ),
-       TP_fast_assign(
-           __assign_str(file, strchr(file, '/') ?
-               strrchr(file, '/') + 1 : file)
-           __assign_str(function, function);
-           __entry->line               = line;
-           __entry->error              = error;
-       ),
-       TP_printk("%s:%d:%s(): error 0x%lx", __get_str(file), __entry->line,
-           __get_str(function), __entry->error)
-);
-/* END CSTYLED */
-
-/* BEGIN CSTYLED */
-#ifdef TP_CONDITION
-#define        DEFINE_SET_ERROR_EVENT(name) \
-DEFINE_EVENT_CONDITION(zfs_set_error_class, name, \
-       TP_PROTO(const char *file, const char *function, int line, \
-           uintptr_t error), \
-       TP_ARGS(file, function, line, error), \
-       TP_CONDITION(error))
-#else
-#define        DEFINE_SET_ERROR_EVENT(name) \
-DEFINE_EVENT(zfs_set_error_class, name, \
-       TP_PROTO(const char *file, const char *function, int line, \
-           uintptr_t error), \
-       TP_ARGS(file, function, line, error))
-#endif
-/* END CSTYLED */
-DEFINE_SET_ERROR_EVENT(zfs_set__error);

diff --git a/include/sys/zfs_context.h b/include/sys/zfs_context.h
index 6163b2fbfb7c0e417d6ed6be088ac52f52417d0e..4fe35342dee78336db8847db59f19f6338659f23 100644 (file)
--- a/include/sys/zfs_context.h
+++ b/include/sys/zfs_context.h
@@ -206,15 +206,6 @@ extern int aok;
        ZFS_PROBE4(#a, (unsigned long)c, (unsigned long)e, (unsigned long)g, \
        (unsigned long)i)
 
-/*
- * We use the comma operator so that this macro can be used without much
- * additional code.  For example, "return (EINVAL);" becomes
- * "return (SET_ERROR(EINVAL));".  Note that the argument will be evaluated
- * twice, so it should not have side effects (e.g. something like:
- * "return (SET_ERROR(log_error(EINVAL, info)));" would log the error twice).
- */
-#define        SET_ERROR(err) (ZFS_SET_ERROR(err), err)
-
 /*
  * Threads.  TS_STACK_MIN is dictated by the minimum allowed pthread stack
  * size.  While TS_STACK_MAX is somewhat arbitrary, it was selected to be

diff --git a/include/sys/zfs_debug.h b/include/sys/zfs_debug.h
index b9b06a5ad13f455ddfe2b5c3c10895e7efec9626..226aaa2b84ab59581b9d3c01cffaa18dd68b281e 100644 (file)
--- a/include/sys/zfs_debug.h
+++ b/include/sys/zfs_debug.h
@@ -51,6 +51,7 @@ extern int zfs_free_leak_on_eio;
 #define        ZFS_DEBUG_ZIO_FREE              (1 << 6)
 #define        ZFS_DEBUG_HISTOGRAM_VERIFY      (1 << 7)
 #define        ZFS_DEBUG_METASLAB_VERIFY       (1 << 8)
+#define        ZFS_DEBUG_SET_ERROR             (1 << 9)
 
 extern void __dprintf(const char *file, const char *func,
     int line, const char *fmt, ...);

diff --git a/man/man5/zfs-module-parameters.5 b/man/man5/zfs-module-parameters.5
index 0447debf73222dfd9b46a8d876274d8e0cb1a978..f7bb2eb8cc0bd210f0683ddd99eeaaa981f82726 100644 (file)
--- a/man/man5/zfs-module-parameters.5
+++ b/man/man5/zfs-module-parameters.5
@@ -1258,6 +1258,12 @@ _
 _
 128    ZFS_DEBUG_HISTOGRAM_VERIFY
        Enable extra spacemap histogram verifications.
+_
+256    ZFS_DEBUG_METASLAB_VERIFY
+       Verify space accounting on disk matches in-core range_trees.
+_
+512    ZFS_DEBUG_SET_ERROR
+       Enable SET_ERROR and dprintf entries in the debug log.
 .TE
 .sp
 * Requires debug build.

diff --git a/module/zfs/zfs_debug.c b/module/zfs/zfs_debug.c
index 90c1d7361d7c70e050bc5cd9fdb773456f4ff53c..d1dba3f8f5747e8bacf56bb5c02cb322e4f4734c 100644 (file)
--- a/module/zfs/zfs_debug.c
+++ b/module/zfs/zfs_debug.c
@@ -161,6 +161,13 @@ __zfs_dbgmsg(char *buf)
        mutex_exit(&zfs_dbgmsgs_lock);
 }
 
+void
+__set_error(const char *file, const char *func, int line, int err)
+{
+       if (zfs_flags & ZFS_DEBUG_SET_ERROR)
+               __dprintf(file, func, line, "error %lu", err);
+}
+
 #ifdef _KERNEL
 void
 __dprintf(const char *file, const char *func, int line, const char *fmt, ...)
@@ -170,8 +177,10 @@ __dprintf(const char *file, const char *func, int line, const char *fmt, ...)
        size_t size;
        char *buf;
        char *nl;
+       int i;
 
-       if (!zfs_dbgmsg_enable && !(zfs_flags & ZFS_DEBUG_DPRINTF))
+       if (!zfs_dbgmsg_enable &&
+           !(zfs_flags & (ZFS_DEBUG_DPRINTF | ZFS_DEBUG_SET_ERROR)))
                return;
 
        size = 1024;
@@ -187,9 +196,13 @@ __dprintf(const char *file, const char *func, int line, const char *fmt, ...)
                newfile = file;
        }
 
-       va_start(adx, fmt);
-       (void) vsnprintf(buf, size, fmt, adx);
-       va_end(adx);
+       i = snprintf(buf, size, "%s:%d:%s(): ", newfile, line, func);
+
+       if (i < size) {
+               va_start(adx, fmt);
+               (void) vsnprintf(buf + i, size - i, fmt, adx);
+               va_end(adx);
+       }
 
        /*
         * Get rid of trailing newline.
@@ -209,9 +222,8 @@ __dprintf(const char *file, const char *func, int line, const char *fmt, ...)
         * # Dump the ring buffer.
         * $ cat /sys/kernel/debug/tracing/trace
         */
-       if (zfs_flags & ZFS_DEBUG_DPRINTF)
-               DTRACE_PROBE4(zfs__dprintf,
-                   char *, newfile, char *, func, int, line, char *, buf);
+       if (zfs_flags & (ZFS_DEBUG_DPRINTF | ZFS_DEBUG_SET_ERROR))
+               DTRACE_PROBE1(zfs__dprintf, char *, buf);
 
        /*
         * To get this data enable the zfs debug log as shown: