]> git.proxmox.com Git - mirror_zfs.git/commitdiff
Add dbgmsg kstat
authorBrian Behlendorf <behlendorf1@llnl.gov>
Tue, 1 Sep 2015 20:19:10 +0000 (13:19 -0700)
committerBrian Behlendorf <behlendorf1@llnl.gov>
Fri, 4 Sep 2015 23:08:14 +0000 (16:08 -0700)
Internally ZFS keeps a small log to facilitate debugging.  By default
the log is disabled, to enable it set zfs_dbgmsg_enable=1.  The contents
of the log can be accessed by reading the /proc/spl/kstat/zfs/dbgmsg file.
Writing 0 to this proc file clears the log.

$ echo 1 >/sys/module/zfs/parameters/zfs_dbgmsg_enable
$ echo 0 >/proc/spl/kstat/zfs/dbgmsg
$ zpool import tank
$ cat /proc/spl/kstat/zfs/dbgmsg
1 0 0x01 -1 0 2492357525542 2525836565501
timestamp    message
1441141408   spa=tank async request task=1
1441141408   txg 70 open pool version 5000; software version 5000/5; ...
1441141409   spa=tank async request task=32
1441141409   txg 72 import pool version 5000; software version 5000/5; ...
1441141414   command: lt-zpool import tank

Note the zfs_dbgmsg() and dprintf() functions are both now mapped to
the same log.  As mentioned above the kernel debug log can be accessed
though the /proc/spl/kstat/zfs/dbgmsg kstat.  For user space consumers
log messages are immediately written to stdout after applying the
ZFS_DEBUG environment variable.

$ ZFS_DEBUG=on ./cmd/ztest/ztest -V

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

cmd/ztest/ztest.c
include/sys/trace_dbgmsg.h
include/sys/zfs_debug.h
man/man5/zfs-module-parameters.5
module/zfs/zfs_debug.c
module/zfs/zfs_ioctl.c

index f2ffcaf3e6340049b7f9127112c075b8b57f6912..afe6faab01ef61c77b18f7a51bbf879da3b214cc 100644 (file)
@@ -827,9 +827,6 @@ ztest_kill(ztest_shared_t *zs)
        spa_config_sync(ztest_spa, B_FALSE, B_FALSE);
        mutex_exit(&spa_namespace_lock);
 
-       if (ztest_opts.zo_verbose >= 3)
-               zfs_dbgmsg_print(FTAG);
-
        (void) kill(getpid(), SIGKILL);
 }
 
@@ -5894,9 +5891,6 @@ ztest_run(ztest_shared_t *zs)
        zs->zs_alloc = metaslab_class_get_alloc(spa_normal_class(spa));
        zs->zs_space = metaslab_class_get_space(spa_normal_class(spa));
 
-       if (ztest_opts.zo_verbose >= 3)
-               zfs_dbgmsg_print(FTAG);
-
        umem_free(tid, ztest_opts.zo_threads * sizeof (kt_did_t));
 
        /* Kill the resume thread */
index 24b34bcf3e65fa050356ce4e041d6bb30107c488..e493a45802ed8cb8646e0e51b6e384c8a9d608d3 100644 (file)
  * be guarded separately.
  */
 
-/*
- * Generic support for one argument tracepoints of the form:
- *
- * DTRACE_PROBE1(...,
- *     const char *, ...);
- */
-
-DECLARE_EVENT_CLASS(zfs_dbgmsg_class,
-       TP_PROTO(const char *msg),
-       TP_ARGS(msg),
-       TP_STRUCT__entry(
-           __string(msg, msg)
-       ),
-       TP_fast_assign(
-           __assign_str(msg, msg);
-       ),
-       TP_printk("%s", __get_str(msg))
-);
-
-#define        DEFINE_DBGMSG_EVENT(name) \
-DEFINE_EVENT(zfs_dbgmsg_class, name, \
-       TP_PROTO(const char *msg), \
-       TP_ARGS(msg))
-DEFINE_DBGMSG_EVENT(zfs_zfs__dbgmsg);
-
-
 /*
  * Generic support for four argument tracepoints of the form:
  *
index 1a7062408e04a878cd118d1f694234393f881052..2f0064ee045bd45f52364ade0e07081855e56e0e 100644 (file)
@@ -51,28 +51,24 @@ extern int zfs_free_leak_on_eio;
 #define        ZFS_DEBUG_ZIO_FREE              (1<<6)
 #define        ZFS_DEBUG_HISTOGRAM_VERIFY      (1<<7)
 
-#if defined(HAVE_DECLARE_EVENT_CLASS) || !defined(_KERNEL)
 extern void __dprintf(const char *file, const char *func,
     int line, const char *fmt, ...);
 #define        dprintf(...) \
-       if (zfs_flags & ZFS_DEBUG_DPRINTF) \
-               __dprintf(__FILE__, __func__, __LINE__, __VA_ARGS__)
-#else
-#define        dprintf(...) ((void)0)
-#endif /* HAVE_DECLARE_EVENT_CLASS || !_KERNEL */
+       __dprintf(__FILE__, __func__, __LINE__, __VA_ARGS__)
+#define        zfs_dbgmsg(...) \
+       __dprintf(__FILE__, __func__, __LINE__, __VA_ARGS__)
 
 extern void zfs_panic_recover(const char *fmt, ...);
 
 typedef struct zfs_dbgmsg {
        list_node_t zdm_node;
        time_t zdm_timestamp;
+       int zdm_size;
        char zdm_msg[1]; /* variable length allocation */
 } zfs_dbgmsg_t;
 
 extern void zfs_dbgmsg_init(void);
 extern void zfs_dbgmsg_fini(void);
-extern void zfs_dbgmsg(const char *fmt, ...);
-extern void zfs_dbgmsg_print(const char *tag);
 
 #ifndef _KERNEL
 extern int dprintf_find_string(const char *string);
index 27b5346e264ca8d729c0d1f94f69fc36a535016f..6d4a8c3048ccf8b0dc32f272ce8cbebf605d1efe 100644 (file)
@@ -607,6 +607,31 @@ Disable pool import at module load by ignoring the cache file (typically \fB/etc
 Use \fB1\fR for yes (default) and \fB0\fR for no.
 .RE
 
+.sp
+.ne 2
+.na
+\fBzfs_dbgmsg_enable\fR (int)
+.ad
+.RS 12n
+Internally ZFS keeps a small log to facilitate debugging.  By default the log
+is disabled, to enable it set this option to 1.  The contents of the log can
+be accessed by reading the /proc/spl/kstat/zfs/dbgmsg file.  Writing 0 to
+this proc file clears the log.
+.sp
+Default value: \fB0\fR.
+.RE
+
+.sp
+.ne 2
+.na
+\fBzfs_dbgmsg_maxsize\fR (int)
+.ad
+.RS 12n
+The maximum size in bytes of the internal ZFS debug log.
+.sp
+Default value: \fB4M\fR.
+.RE
+
 .sp
 .ne 2
 .na
index e835397e9453bd15492fd84825afa05a4b641f7f..2770359c8b48e459d63c69faa003eb90b63aff04 100644 (file)
  */
 
 #include <sys/zfs_context.h>
+#include <sys/kstat.h>
 
 list_t zfs_dbgmsgs;
-int zfs_dbgmsg_size;
+int zfs_dbgmsg_size = 0;
 kmutex_t zfs_dbgmsgs_lock;
 int zfs_dbgmsg_maxsize = 4<<20; /* 4MB */
+kstat_t *zfs_dbgmsg_kstat;
+
+/*
+ * By default only enable the internal ZFS debug messages when running
+ * in userspace (ztest).  The kernel log must be manually enabled.
+ *
+ * # Enable the kernel debug message log.
+ * echo 1 > /sys/module/zfs/parameters/zfs_dbgmsg_enable
+ *
+ * # Clear the kernel debug message log.
+ * echo 0 >/proc/spl/kstat/zfs/dbgmsg
+ */
+#if defined(_KERNEL)
+int zfs_dbgmsg_enable = 0;
+#else
+int zfs_dbgmsg_enable = 1;
+#endif
+
+static int
+zfs_dbgmsg_headers(char *buf, size_t size)
+{
+       (void) snprintf(buf, size, "%-12s %-8s\n", "timestamp", "message");
+
+       return (0);
+}
+
+static int
+zfs_dbgmsg_data(char *buf, size_t size, void *data)
+{
+       zfs_dbgmsg_t *zdm = (zfs_dbgmsg_t *)data;
+
+       (void) snprintf(buf, size, "%-12llu %-s\n",
+           (u_longlong_t) zdm->zdm_timestamp, zdm->zdm_msg);
+
+       return (0);
+}
+
+static void *
+zfs_dbgmsg_addr(kstat_t *ksp, loff_t n)
+{
+       zfs_dbgmsg_t *zdm = (zfs_dbgmsg_t *)ksp->ks_private;
+
+       ASSERT(MUTEX_HELD(&zfs_dbgmsgs_lock));
+
+       if (n == 0)
+               ksp->ks_private = list_head(&zfs_dbgmsgs);
+       else if (zdm)
+               ksp->ks_private = list_next(&zfs_dbgmsgs, zdm);
+
+       return (ksp->ks_private);
+}
+
+static void
+zfs_dbgmsg_purge(int max_size)
+{
+       zfs_dbgmsg_t *zdm;
+       int size;
+
+       ASSERT(MUTEX_HELD(&zfs_dbgmsgs_lock));
+
+       while (zfs_dbgmsg_size > max_size) {
+               zdm = list_remove_head(&zfs_dbgmsgs);
+               if (zdm == NULL)
+                       return;
+
+               size = zdm->zdm_size;
+               kmem_free(zdm, size);
+               zfs_dbgmsg_size -= size;
+       }
+}
+
+static int
+zfs_dbgmsg_update(kstat_t *ksp, int rw)
+{
+       if (rw == KSTAT_WRITE)
+               zfs_dbgmsg_purge(0);
+
+       return (0);
+}
 
 void
 zfs_dbgmsg_init(void)
@@ -36,87 +116,124 @@ 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);
+
+       zfs_dbgmsg_kstat = kstat_create("zfs", 0, "dbgmsg", "misc",
+           KSTAT_TYPE_RAW, 0, KSTAT_FLAG_VIRTUAL);
+       if (zfs_dbgmsg_kstat) {
+               zfs_dbgmsg_kstat->ks_lock = &zfs_dbgmsgs_lock;
+               zfs_dbgmsg_kstat->ks_ndata = UINT32_MAX;
+               zfs_dbgmsg_kstat->ks_private = NULL;
+               zfs_dbgmsg_kstat->ks_update = zfs_dbgmsg_update;
+               kstat_set_raw_ops(zfs_dbgmsg_kstat, zfs_dbgmsg_headers,
+                   zfs_dbgmsg_data, zfs_dbgmsg_addr);
+               kstat_install(zfs_dbgmsg_kstat);
+       }
 }
 
 void
 zfs_dbgmsg_fini(void)
 {
-       zfs_dbgmsg_t *zdm;
+       if (zfs_dbgmsg_kstat)
+               kstat_delete(zfs_dbgmsg_kstat);
 
-       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_enter(&zfs_dbgmsgs_lock);
+       zfs_dbgmsg_purge(0);
+       mutex_exit(&zfs_dbgmsgs_lock);
        mutex_destroy(&zfs_dbgmsgs_lock);
-       ASSERT0(zfs_dbgmsg_size);
 }
 
-/*
- * To get this data enable the zfs__dbgmsg tracepoint as shown:
- *
- * # Enable zfs__dbgmsg tracepoint, clear the tracepoint ring buffer
- * $ 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
- */
 void
-zfs_dbgmsg(const char *fmt, ...)
+__zfs_dbgmsg(char *buf)
 {
+       zfs_dbgmsg_t *zdm;
        int size;
+
+       size = sizeof (zfs_dbgmsg_t) + strlen(buf);
+       zdm = kmem_zalloc(size, KM_SLEEP);
+       zdm->zdm_size = size;
+       zdm->zdm_timestamp = gethrestime_sec();
+       strcpy(zdm->zdm_msg, buf);
+
+       mutex_enter(&zfs_dbgmsgs_lock);
+       list_insert_tail(&zfs_dbgmsgs, zdm);
+       zfs_dbgmsg_size += size;
+       zfs_dbgmsg_purge(MAX(zfs_dbgmsg_maxsize, 0));
+       mutex_exit(&zfs_dbgmsgs_lock);
+}
+
+#ifdef _KERNEL
+void
+__dprintf(const char *file, const char *func, int line, const char *fmt, ...)
+{
+       const char *newfile;
        va_list adx;
+       size_t size;
+       char *buf;
        char *nl;
-       zfs_dbgmsg_t *zdm;
 
-       va_start(adx, fmt);
-       size = vsnprintf(NULL, 0, fmt, adx);
-       va_end(adx);
+       if (!zfs_dbgmsg_enable && !(zfs_flags & ZFS_DEBUG_DPRINTF))
+               return;
+
+       size = 1024;
+       buf = kmem_alloc(size, KM_SLEEP);
 
        /*
-        * There is one byte of string in sizeof (zfs_dbgmsg_t), used
-        * for the terminating null.
+        * Get rid of annoying prefix to filename.
         */
-       zdm = kmem_alloc(sizeof (zfs_dbgmsg_t) + size, KM_SLEEP);
-       zdm->zdm_timestamp = gethrestime_sec();
+       newfile = strrchr(file, '/');
+       if (newfile != NULL) {
+               newfile = newfile + 1; /* Get rid of leading / */
+       } else {
+               newfile = file;
+       }
 
        va_start(adx, fmt);
-       (void) vsnprintf(zdm->zdm_msg, size + 1, fmt, adx);
+       (void) vsnprintf(buf, size, fmt, adx);
        va_end(adx);
 
        /*
         * Get rid of trailing newline.
         */
-       nl = strrchr(zdm->zdm_msg, '\n');
+       nl = strrchr(buf, '\n');
        if (nl != NULL)
                *nl = '\0';
 
-       DTRACE_PROBE1(zfs__dbgmsg, char *, zdm->zdm_msg);
+       /*
+        * 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)
+               DTRACE_PROBE4(zfs__dprintf,
+                   char *, newfile, char *, func, int, line, char *, buf);
 
-       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);
+       /*
+        * To get this data enable the zfs debug log as shown:
+        *
+        * # 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
+        */
+       if (zfs_dbgmsg_enable)
+               __zfs_dbgmsg(buf);
+
+       kmem_free(buf, size);
 }
+#endif /* _KERNEL */
 
-void
-zfs_dbgmsg_print(const char *tag)
-{
-#if !defined(_KERNEL)
-       zfs_dbgmsg_t *zdm;
+#ifdef _KERNEL
+module_param(zfs_dbgmsg_enable, int, 0644);
+MODULE_PARM_DESC(zfs_dbgmsg_enable, "Enable ZFS debug message log");
 
-       (void) printf("ZFS_DBGMSG(%s):\n", tag);
-       mutex_enter(&zfs_dbgmsgs_lock);
-       for (zdm = list_head(&zfs_dbgmsgs); zdm;
-           zdm = list_next(&zfs_dbgmsgs, zdm))
-               (void) printf("%s\n", zdm->zdm_msg);
-       mutex_exit(&zfs_dbgmsgs_lock);
-#endif /* !_KERNEL */
-}
+module_param(zfs_dbgmsg_maxsize, int, 0644);
+MODULE_PARM_DESC(zfs_dbgmsg_maxsize, "Maximum ZFS debug log size");
+#endif
index 06aae82a10e38dfe5c975f9eba576735115eb66a..7ce19693e2d40fc596271dfddac407e1073df001 100644 (file)
@@ -247,55 +247,6 @@ static int zfs_fill_zplprops_root(uint64_t, nvlist_t *, nvlist_t *,
 int zfs_set_prop_nvlist(const char *, zprop_source_t, nvlist_t *, nvlist_t *);
 static int get_nvlist(uint64_t nvl, uint64_t size, int iflag, nvlist_t **nvp);
 
-#if defined(HAVE_DECLARE_EVENT_CLASS)
-void
-__dprintf(const char *file, const char *func, int line, const char *fmt, ...)
-{
-       const char *newfile;
-       size_t size = 4096;
-       char *buf = kmem_alloc(size, KM_SLEEP);
-       char *nl;
-       va_list adx;
-
-       /*
-        * Get rid of annoying 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, size, fmt, adx);
-       va_end(adx);
-
-       /*
-        * Get rid of trailing newline.
-        */
-       nl = strrchr(buf, '\n');
-       if (nl != NULL)
-               *nl = '\0';
-
-       /*
-        * 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
-        */
-       DTRACE_PROBE4(zfs__dprintf,
-           char *, newfile, char *, func, int, line, char *, buf);
-
-       kmem_free(buf, size);
-}
-#endif /* HAVE_DECLARE_EVENT_CLASS */
-
 static void
 history_str_free(char *buf)
 {