d/freebsd-dev
1
0
Fork 0
Code Issues Pull Requests Packages Projects Releases Wiki Activity

Add dbgmsg kstat

Browse Source 
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
This commit is contained in:
Brian Behlendorf 2015-09-01 13:19:10 -07:00
parent 0500e835af
commit 3b36f8319d
6 changed files with 201 additions and 144 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

6
cmd/ztest/ztest.c
View 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 */

26
include/sys/trace_dbgmsg.h
View File

@ -36,32 +36,6 @@
* 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:
*

12
include/sys/zfs_debug.h
View 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);

25
man/man5/zfs-module-parameters.5
View 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

227
module/zfs/zfs_debug.c
View File

@ -24,11 +24,91 @@
*/
#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)
{
int size;
va_list adx;
char *nl;
zfs_dbgmsg_t *zdm;
int size;
va_start(adx, fmt);
size = vsnprintf(NULL, 0, fmt, adx);
va_end(adx);
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;
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

49
module/zfs/zfs_ioctl.c
View 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)
{