2010-05-28 20:45:14 +00:00
|
|
|
/*
|
|
|
|
* CDDL HEADER START
|
|
|
|
*
|
|
|
|
* The contents of this file are subject to the terms of the
|
|
|
|
* Common Development and Distribution License (the "License").
|
|
|
|
* You may not use this file except in compliance with the License.
|
|
|
|
*
|
|
|
|
* You can obtain a copy of the license at usr/src/OPENSOLARIS.LICENSE
|
|
|
|
* or http://www.opensolaris.org/os/licensing.
|
|
|
|
* See the License for the specific language governing permissions
|
|
|
|
* and limitations under the License.
|
|
|
|
*
|
|
|
|
* When distributing Covered Code, include this CDDL HEADER in each
|
|
|
|
* file and include the License file at usr/src/OPENSOLARIS.LICENSE.
|
|
|
|
* If applicable, add the following below this CDDL HEADER, with the
|
|
|
|
* fields enclosed by brackets "[]" replaced with your own identifying
|
|
|
|
* information: Portions Copyright [yyyy] [name of copyright owner]
|
|
|
|
*
|
|
|
|
* CDDL HEADER END
|
|
|
|
*/
|
|
|
|
/*
|
|
|
|
* Copyright (c) 2010, Oracle and/or its affiliates. All rights reserved.
|
2014-09-22 23:42:03 +00:00
|
|
|
* Copyright (c) 2012, 2014 by Delphix. All rights reserved.
|
2010-05-28 20:45:14 +00:00
|
|
|
*/
|
|
|
|
|
|
|
|
#include <sys/zfs_context.h>
|
2015-09-01 20:19:10 +00:00
|
|
|
#include <sys/kstat.h>
|
2010-05-28 20:45:14 +00:00
|
|
|
|
2013-10-09 02:37:38 +00:00
|
|
|
list_t zfs_dbgmsgs;
|
2015-09-01 20:19:10 +00:00
|
|
|
int zfs_dbgmsg_size = 0;
|
2013-10-09 02:37:38 +00:00
|
|
|
kmutex_t zfs_dbgmsgs_lock;
|
2014-06-05 21:20:08 +00:00
|
|
|
int zfs_dbgmsg_maxsize = 4<<20; /* 4MB */
|
2015-09-01 20:19:10 +00:00
|
|
|
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
|
|
|
|
*/
|
2017-04-12 20:36:48 +00:00
|
|
|
#if defined(_KERNEL) && !defined(ZFS_DEBUG)
|
2015-09-01 20:19:10 +00:00
|
|
|
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",
|
2016-12-12 18:46:26 +00:00
|
|
|
(u_longlong_t)zdm->zdm_timestamp, zdm->zdm_msg);
|
2015-09-01 20:19:10 +00:00
|
|
|
|
|
|
|
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);
|
|
|
|
}
|
2013-10-09 02:37:38 +00:00
|
|
|
|
2010-05-28 20:45:14 +00:00
|
|
|
void
|
2012-01-20 23:02:57 +00:00
|
|
|
zfs_dbgmsg_init(void)
|
2010-05-28 20:45:14 +00:00
|
|
|
{
|
2013-10-09 02:37:38 +00:00
|
|
|
list_create(&zfs_dbgmsgs, sizeof (zfs_dbgmsg_t),
|
|
|
|
offsetof(zfs_dbgmsg_t, zdm_node));
|
|
|
|
mutex_init(&zfs_dbgmsgs_lock, NULL, MUTEX_DEFAULT, NULL);
|
2015-09-01 20:19:10 +00:00
|
|
|
|
|
|
|
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);
|
|
|
|
}
|
2012-01-20 23:02:57 +00:00
|
|
|
}
|
2010-05-28 20:45:14 +00:00
|
|
|
|
2012-01-20 23:02:57 +00:00
|
|
|
void
|
|
|
|
zfs_dbgmsg_fini(void)
|
|
|
|
{
|
2015-09-01 20:19:10 +00:00
|
|
|
if (zfs_dbgmsg_kstat)
|
|
|
|
kstat_delete(zfs_dbgmsg_kstat);
|
2013-10-09 02:37:38 +00:00
|
|
|
|
2015-09-01 20:19:10 +00:00
|
|
|
mutex_enter(&zfs_dbgmsgs_lock);
|
|
|
|
zfs_dbgmsg_purge(0);
|
|
|
|
mutex_exit(&zfs_dbgmsgs_lock);
|
2013-10-09 02:37:38 +00:00
|
|
|
mutex_destroy(&zfs_dbgmsgs_lock);
|
2012-01-20 23:02:57 +00:00
|
|
|
}
|
2010-05-28 20:45:14 +00:00
|
|
|
|
2013-10-09 02:37:38 +00:00
|
|
|
void
|
2015-09-01 20:19:10 +00:00
|
|
|
__zfs_dbgmsg(char *buf)
|
2013-10-09 02:37:38 +00:00
|
|
|
{
|
2015-09-01 20:19:10 +00:00
|
|
|
zfs_dbgmsg_t *zdm;
|
2013-10-09 02:37:38 +00:00
|
|
|
int size;
|
2015-09-01 20:19:10 +00:00
|
|
|
|
|
|
|
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);
|
|
|
|
}
|
|
|
|
|
2017-07-26 06:09:48 +00:00
|
|
|
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);
|
|
|
|
}
|
|
|
|
|
2015-09-01 20:19:10 +00:00
|
|
|
#ifdef _KERNEL
|
|
|
|
void
|
|
|
|
__dprintf(const char *file, const char *func, int line, const char *fmt, ...)
|
|
|
|
{
|
|
|
|
const char *newfile;
|
2013-10-09 02:37:38 +00:00
|
|
|
va_list adx;
|
2015-09-01 20:19:10 +00:00
|
|
|
size_t size;
|
|
|
|
char *buf;
|
Swap DTRACE_PROBE* with Linux tracepoints
This patch leverages Linux tracepoints from within the ZFS on Linux
code base. It also refactors the debug code to bring it back in sync
with Illumos.
The information exported via tracepoints can be used for a variety of
reasons (e.g. debugging, tuning, general exploration/understanding,
etc). It is advantageous to use Linux tracepoints as the mechanism to
export this kind of information (as opposed to something else) for a
number of reasons:
* A number of external tools can make use of our tracepoints
"automatically" (e.g. perf, systemtap)
* Tracepoints are designed to be extremely cheap when disabled
* It's one of the "accepted" ways to export this kind of
information; many other kernel subsystems use tracepoints too.
Unfortunately, though, there are a few caveats as well:
* Linux tracepoints appear to only be available to GPL licensed
modules due to the way certain kernel functions are exported.
Thus, to actually make use of the tracepoints introduced by this
patch, one might have to patch and re-compile the kernel;
exporting the necessary functions to non-GPL modules.
* Prior to upstream kernel version v3.14-rc6-30-g66cc69e, Linux
tracepoints are not available for unsigned kernel modules
(tracepoints will get disabled due to the module's 'F' taint).
Thus, one either has to sign the zfs kernel module prior to
loading it, or use a kernel versioned v3.14-rc6-30-g66cc69e or
newer.
Assuming the above two requirements are satisfied, lets look at an
example of how this patch can be used and what information it exposes
(all commands run as 'root'):
# list all zfs tracepoints available
$ ls /sys/kernel/debug/tracing/events/zfs
enable filter zfs_arc__delete
zfs_arc__evict zfs_arc__hit zfs_arc__miss
zfs_l2arc__evict zfs_l2arc__hit zfs_l2arc__iodone
zfs_l2arc__miss zfs_l2arc__read zfs_l2arc__write
zfs_new_state__mfu zfs_new_state__mru
# enable all zfs tracepoints, clear the tracepoint ring buffer
$ echo 1 > /sys/kernel/debug/tracing/events/zfs/enable
$ echo 0 > /sys/kernel/debug/tracing/trace
# import zpool called 'tank', inspect tracepoint data (each line was
# truncated, they're too long for a commit message otherwise)
$ zpool import tank
$ cat /sys/kernel/debug/tracing/trace | head -n35
# tracer: nop
#
# entries-in-buffer/entries-written: 1219/1219 #P:8
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / delay
# TASK-PID CPU# |||| TIMESTAMP FUNCTION
# | | | |||| | |
lt-zpool-30132 [003] .... 91344.200050: zfs_arc__miss: hdr...
z_rd_int/0-30156 [003] .... 91344.200611: zfs_new_state__mru...
lt-zpool-30132 [003] .... 91344.201173: zfs_arc__miss: hdr...
z_rd_int/1-30157 [003] .... 91344.201756: zfs_new_state__mru...
lt-zpool-30132 [003] .... 91344.201795: zfs_arc__miss: hdr...
z_rd_int/2-30158 [003] .... 91344.202099: zfs_new_state__mru...
lt-zpool-30132 [003] .... 91344.202126: zfs_arc__hit: hdr ...
lt-zpool-30132 [003] .... 91344.202130: zfs_arc__hit: hdr ...
lt-zpool-30132 [003] .... 91344.202134: zfs_arc__hit: hdr ...
lt-zpool-30132 [003] .... 91344.202146: zfs_arc__miss: hdr...
z_rd_int/3-30159 [003] .... 91344.202457: zfs_new_state__mru...
lt-zpool-30132 [003] .... 91344.202484: zfs_arc__miss: hdr...
z_rd_int/4-30160 [003] .... 91344.202866: zfs_new_state__mru...
lt-zpool-30132 [003] .... 91344.202891: zfs_arc__hit: hdr ...
lt-zpool-30132 [001] .... 91344.203034: zfs_arc__miss: hdr...
z_rd_iss/1-30149 [001] .... 91344.203749: zfs_new_state__mru...
lt-zpool-30132 [001] .... 91344.203789: zfs_arc__hit: hdr ...
lt-zpool-30132 [001] .... 91344.203878: zfs_arc__miss: hdr...
z_rd_iss/3-30151 [001] .... 91344.204315: zfs_new_state__mru...
lt-zpool-30132 [001] .... 91344.204332: zfs_arc__hit: hdr ...
lt-zpool-30132 [001] .... 91344.204337: zfs_arc__hit: hdr ...
lt-zpool-30132 [001] .... 91344.204352: zfs_arc__hit: hdr ...
lt-zpool-30132 [001] .... 91344.204356: zfs_arc__hit: hdr ...
lt-zpool-30132 [001] .... 91344.204360: zfs_arc__hit: hdr ...
To highlight the kind of detailed information that is being exported
using this infrastructure, I've taken the first tracepoint line from the
output above and reformatted it such that it fits in 80 columns:
lt-zpool-30132 [003] .... 91344.200050: zfs_arc__miss:
hdr {
dva 0x1:0x40082
birth 15491
cksum0 0x163edbff3a
flags 0x640
datacnt 1
type 1
size 2048
spa 3133524293419867460
state_type 0
access 0
mru_hits 0
mru_ghost_hits 0
mfu_hits 0
mfu_ghost_hits 0
l2_hits 0
refcount 1
} bp {
dva0 0x1:0x40082
dva1 0x1:0x3000e5
dva2 0x1:0x5a006e
cksum 0x163edbff3a:0x75af30b3dd6:0x1499263ff5f2b:0x288bd118815e00
lsize 2048
} zb {
objset 0
object 0
level -1
blkid 0
}
For the specific tracepoint shown here, 'zfs_arc__miss', data is
exported detailing the arc_buf_hdr_t (hdr), blkptr_t (bp), and
zbookmark_t (zb) that caused the ARC miss (down to the exact DVA!).
This kind of precise and detailed information can be extremely valuable
when trying to answer certain kinds of questions.
For anybody unfamiliar but looking to build on this, I found the XFS
source code along with the following three web links to be extremely
helpful:
* http://lwn.net/Articles/379903/
* http://lwn.net/Articles/381064/
* http://lwn.net/Articles/383362/
I should also node the more "boring" aspects of this patch:
* The ZFS_LINUX_COMPILE_IFELSE autoconf macro was modified to
support a sixth paramter. This parameter is used to populate the
contents of the new conftest.h file. If no sixth parameter is
provided, conftest.h will be empty.
* The ZFS_LINUX_TRY_COMPILE_HEADER autoconf macro was introduced.
This macro is nearly identical to the ZFS_LINUX_TRY_COMPILE macro,
except it has support for a fifth option that is then passed as
the sixth parameter to ZFS_LINUX_COMPILE_IFELSE.
These autoconf changes were needed to test the availability of the Linux
tracepoint macros. Due to the odd nature of the Linux tracepoint macro
API, a separate ".h" must be created (the path and filename is used
internally by the kernel's define_trace.h file).
* The HAVE_DECLARE_EVENT_CLASS autoconf macro was introduced. This
is to determine if we can safely enable the Linux tracepoint
functionality. We need to selectively disable the tracepoint code
due to the kernel exporting certain functions as GPL only. Without
this check, the build process will fail at link time.
In addition, the SET_ERROR macro was modified into a tracepoint as well.
To do this, the 'sdt.h' file was moved into the 'include/sys' directory
and now contains a userspace portion and a kernel space portion. The
dprintf and zfs_dbgmsg* interfaces are now implemented as tracepoint as
well.
Signed-off-by: Prakash Surya <surya1@llnl.gov>
Signed-off-by: Ned Bass <bass6@llnl.gov>
Signed-off-by: Brian Behlendorf <behlendorf1@llnl.gov>
2014-06-13 17:54:48 +00:00
|
|
|
char *nl;
|
2017-07-26 06:09:48 +00:00
|
|
|
int i;
|
2013-10-09 02:37:38 +00:00
|
|
|
|
2017-07-26 06:09:48 +00:00
|
|
|
if (!zfs_dbgmsg_enable &&
|
|
|
|
!(zfs_flags & (ZFS_DEBUG_DPRINTF | ZFS_DEBUG_SET_ERROR)))
|
2015-09-01 20:19:10 +00:00
|
|
|
return;
|
|
|
|
|
|
|
|
size = 1024;
|
|
|
|
buf = kmem_alloc(size, KM_SLEEP);
|
2013-10-09 02:37:38 +00:00
|
|
|
|
|
|
|
/*
|
2015-09-01 20:19:10 +00:00
|
|
|
* Get rid of annoying prefix to filename.
|
2013-10-09 02:37:38 +00:00
|
|
|
*/
|
2015-09-01 20:19:10 +00:00
|
|
|
newfile = strrchr(file, '/');
|
|
|
|
if (newfile != NULL) {
|
|
|
|
newfile = newfile + 1; /* Get rid of leading / */
|
|
|
|
} else {
|
|
|
|
newfile = file;
|
|
|
|
}
|
2013-10-09 02:37:38 +00:00
|
|
|
|
2017-07-26 06:09:48 +00:00
|
|
|
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);
|
|
|
|
}
|
2013-10-09 02:37:38 +00:00
|
|
|
|
Swap DTRACE_PROBE* with Linux tracepoints
This patch leverages Linux tracepoints from within the ZFS on Linux
code base. It also refactors the debug code to bring it back in sync
with Illumos.
The information exported via tracepoints can be used for a variety of
reasons (e.g. debugging, tuning, general exploration/understanding,
etc). It is advantageous to use Linux tracepoints as the mechanism to
export this kind of information (as opposed to something else) for a
number of reasons:
* A number of external tools can make use of our tracepoints
"automatically" (e.g. perf, systemtap)
* Tracepoints are designed to be extremely cheap when disabled
* It's one of the "accepted" ways to export this kind of
information; many other kernel subsystems use tracepoints too.
Unfortunately, though, there are a few caveats as well:
* Linux tracepoints appear to only be available to GPL licensed
modules due to the way certain kernel functions are exported.
Thus, to actually make use of the tracepoints introduced by this
patch, one might have to patch and re-compile the kernel;
exporting the necessary functions to non-GPL modules.
* Prior to upstream kernel version v3.14-rc6-30-g66cc69e, Linux
tracepoints are not available for unsigned kernel modules
(tracepoints will get disabled due to the module's 'F' taint).
Thus, one either has to sign the zfs kernel module prior to
loading it, or use a kernel versioned v3.14-rc6-30-g66cc69e or
newer.
Assuming the above two requirements are satisfied, lets look at an
example of how this patch can be used and what information it exposes
(all commands run as 'root'):
# list all zfs tracepoints available
$ ls /sys/kernel/debug/tracing/events/zfs
enable filter zfs_arc__delete
zfs_arc__evict zfs_arc__hit zfs_arc__miss
zfs_l2arc__evict zfs_l2arc__hit zfs_l2arc__iodone
zfs_l2arc__miss zfs_l2arc__read zfs_l2arc__write
zfs_new_state__mfu zfs_new_state__mru
# enable all zfs tracepoints, clear the tracepoint ring buffer
$ echo 1 > /sys/kernel/debug/tracing/events/zfs/enable
$ echo 0 > /sys/kernel/debug/tracing/trace
# import zpool called 'tank', inspect tracepoint data (each line was
# truncated, they're too long for a commit message otherwise)
$ zpool import tank
$ cat /sys/kernel/debug/tracing/trace | head -n35
# tracer: nop
#
# entries-in-buffer/entries-written: 1219/1219 #P:8
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / delay
# TASK-PID CPU# |||| TIMESTAMP FUNCTION
# | | | |||| | |
lt-zpool-30132 [003] .... 91344.200050: zfs_arc__miss: hdr...
z_rd_int/0-30156 [003] .... 91344.200611: zfs_new_state__mru...
lt-zpool-30132 [003] .... 91344.201173: zfs_arc__miss: hdr...
z_rd_int/1-30157 [003] .... 91344.201756: zfs_new_state__mru...
lt-zpool-30132 [003] .... 91344.201795: zfs_arc__miss: hdr...
z_rd_int/2-30158 [003] .... 91344.202099: zfs_new_state__mru...
lt-zpool-30132 [003] .... 91344.202126: zfs_arc__hit: hdr ...
lt-zpool-30132 [003] .... 91344.202130: zfs_arc__hit: hdr ...
lt-zpool-30132 [003] .... 91344.202134: zfs_arc__hit: hdr ...
lt-zpool-30132 [003] .... 91344.202146: zfs_arc__miss: hdr...
z_rd_int/3-30159 [003] .... 91344.202457: zfs_new_state__mru...
lt-zpool-30132 [003] .... 91344.202484: zfs_arc__miss: hdr...
z_rd_int/4-30160 [003] .... 91344.202866: zfs_new_state__mru...
lt-zpool-30132 [003] .... 91344.202891: zfs_arc__hit: hdr ...
lt-zpool-30132 [001] .... 91344.203034: zfs_arc__miss: hdr...
z_rd_iss/1-30149 [001] .... 91344.203749: zfs_new_state__mru...
lt-zpool-30132 [001] .... 91344.203789: zfs_arc__hit: hdr ...
lt-zpool-30132 [001] .... 91344.203878: zfs_arc__miss: hdr...
z_rd_iss/3-30151 [001] .... 91344.204315: zfs_new_state__mru...
lt-zpool-30132 [001] .... 91344.204332: zfs_arc__hit: hdr ...
lt-zpool-30132 [001] .... 91344.204337: zfs_arc__hit: hdr ...
lt-zpool-30132 [001] .... 91344.204352: zfs_arc__hit: hdr ...
lt-zpool-30132 [001] .... 91344.204356: zfs_arc__hit: hdr ...
lt-zpool-30132 [001] .... 91344.204360: zfs_arc__hit: hdr ...
To highlight the kind of detailed information that is being exported
using this infrastructure, I've taken the first tracepoint line from the
output above and reformatted it such that it fits in 80 columns:
lt-zpool-30132 [003] .... 91344.200050: zfs_arc__miss:
hdr {
dva 0x1:0x40082
birth 15491
cksum0 0x163edbff3a
flags 0x640
datacnt 1
type 1
size 2048
spa 3133524293419867460
state_type 0
access 0
mru_hits 0
mru_ghost_hits 0
mfu_hits 0
mfu_ghost_hits 0
l2_hits 0
refcount 1
} bp {
dva0 0x1:0x40082
dva1 0x1:0x3000e5
dva2 0x1:0x5a006e
cksum 0x163edbff3a:0x75af30b3dd6:0x1499263ff5f2b:0x288bd118815e00
lsize 2048
} zb {
objset 0
object 0
level -1
blkid 0
}
For the specific tracepoint shown here, 'zfs_arc__miss', data is
exported detailing the arc_buf_hdr_t (hdr), blkptr_t (bp), and
zbookmark_t (zb) that caused the ARC miss (down to the exact DVA!).
This kind of precise and detailed information can be extremely valuable
when trying to answer certain kinds of questions.
For anybody unfamiliar but looking to build on this, I found the XFS
source code along with the following three web links to be extremely
helpful:
* http://lwn.net/Articles/379903/
* http://lwn.net/Articles/381064/
* http://lwn.net/Articles/383362/
I should also node the more "boring" aspects of this patch:
* The ZFS_LINUX_COMPILE_IFELSE autoconf macro was modified to
support a sixth paramter. This parameter is used to populate the
contents of the new conftest.h file. If no sixth parameter is
provided, conftest.h will be empty.
* The ZFS_LINUX_TRY_COMPILE_HEADER autoconf macro was introduced.
This macro is nearly identical to the ZFS_LINUX_TRY_COMPILE macro,
except it has support for a fifth option that is then passed as
the sixth parameter to ZFS_LINUX_COMPILE_IFELSE.
These autoconf changes were needed to test the availability of the Linux
tracepoint macros. Due to the odd nature of the Linux tracepoint macro
API, a separate ".h" must be created (the path and filename is used
internally by the kernel's define_trace.h file).
* The HAVE_DECLARE_EVENT_CLASS autoconf macro was introduced. This
is to determine if we can safely enable the Linux tracepoint
functionality. We need to selectively disable the tracepoint code
due to the kernel exporting certain functions as GPL only. Without
this check, the build process will fail at link time.
In addition, the SET_ERROR macro was modified into a tracepoint as well.
To do this, the 'sdt.h' file was moved into the 'include/sys' directory
and now contains a userspace portion and a kernel space portion. The
dprintf and zfs_dbgmsg* interfaces are now implemented as tracepoint as
well.
Signed-off-by: Prakash Surya <surya1@llnl.gov>
Signed-off-by: Ned Bass <bass6@llnl.gov>
Signed-off-by: Brian Behlendorf <behlendorf1@llnl.gov>
2014-06-13 17:54:48 +00:00
|
|
|
/*
|
|
|
|
* Get rid of trailing newline.
|
|
|
|
*/
|
2015-09-01 20:19:10 +00:00
|
|
|
nl = strrchr(buf, '\n');
|
Swap DTRACE_PROBE* with Linux tracepoints
This patch leverages Linux tracepoints from within the ZFS on Linux
code base. It also refactors the debug code to bring it back in sync
with Illumos.
The information exported via tracepoints can be used for a variety of
reasons (e.g. debugging, tuning, general exploration/understanding,
etc). It is advantageous to use Linux tracepoints as the mechanism to
export this kind of information (as opposed to something else) for a
number of reasons:
* A number of external tools can make use of our tracepoints
"automatically" (e.g. perf, systemtap)
* Tracepoints are designed to be extremely cheap when disabled
* It's one of the "accepted" ways to export this kind of
information; many other kernel subsystems use tracepoints too.
Unfortunately, though, there are a few caveats as well:
* Linux tracepoints appear to only be available to GPL licensed
modules due to the way certain kernel functions are exported.
Thus, to actually make use of the tracepoints introduced by this
patch, one might have to patch and re-compile the kernel;
exporting the necessary functions to non-GPL modules.
* Prior to upstream kernel version v3.14-rc6-30-g66cc69e, Linux
tracepoints are not available for unsigned kernel modules
(tracepoints will get disabled due to the module's 'F' taint).
Thus, one either has to sign the zfs kernel module prior to
loading it, or use a kernel versioned v3.14-rc6-30-g66cc69e or
newer.
Assuming the above two requirements are satisfied, lets look at an
example of how this patch can be used and what information it exposes
(all commands run as 'root'):
# list all zfs tracepoints available
$ ls /sys/kernel/debug/tracing/events/zfs
enable filter zfs_arc__delete
zfs_arc__evict zfs_arc__hit zfs_arc__miss
zfs_l2arc__evict zfs_l2arc__hit zfs_l2arc__iodone
zfs_l2arc__miss zfs_l2arc__read zfs_l2arc__write
zfs_new_state__mfu zfs_new_state__mru
# enable all zfs tracepoints, clear the tracepoint ring buffer
$ echo 1 > /sys/kernel/debug/tracing/events/zfs/enable
$ echo 0 > /sys/kernel/debug/tracing/trace
# import zpool called 'tank', inspect tracepoint data (each line was
# truncated, they're too long for a commit message otherwise)
$ zpool import tank
$ cat /sys/kernel/debug/tracing/trace | head -n35
# tracer: nop
#
# entries-in-buffer/entries-written: 1219/1219 #P:8
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / delay
# TASK-PID CPU# |||| TIMESTAMP FUNCTION
# | | | |||| | |
lt-zpool-30132 [003] .... 91344.200050: zfs_arc__miss: hdr...
z_rd_int/0-30156 [003] .... 91344.200611: zfs_new_state__mru...
lt-zpool-30132 [003] .... 91344.201173: zfs_arc__miss: hdr...
z_rd_int/1-30157 [003] .... 91344.201756: zfs_new_state__mru...
lt-zpool-30132 [003] .... 91344.201795: zfs_arc__miss: hdr...
z_rd_int/2-30158 [003] .... 91344.202099: zfs_new_state__mru...
lt-zpool-30132 [003] .... 91344.202126: zfs_arc__hit: hdr ...
lt-zpool-30132 [003] .... 91344.202130: zfs_arc__hit: hdr ...
lt-zpool-30132 [003] .... 91344.202134: zfs_arc__hit: hdr ...
lt-zpool-30132 [003] .... 91344.202146: zfs_arc__miss: hdr...
z_rd_int/3-30159 [003] .... 91344.202457: zfs_new_state__mru...
lt-zpool-30132 [003] .... 91344.202484: zfs_arc__miss: hdr...
z_rd_int/4-30160 [003] .... 91344.202866: zfs_new_state__mru...
lt-zpool-30132 [003] .... 91344.202891: zfs_arc__hit: hdr ...
lt-zpool-30132 [001] .... 91344.203034: zfs_arc__miss: hdr...
z_rd_iss/1-30149 [001] .... 91344.203749: zfs_new_state__mru...
lt-zpool-30132 [001] .... 91344.203789: zfs_arc__hit: hdr ...
lt-zpool-30132 [001] .... 91344.203878: zfs_arc__miss: hdr...
z_rd_iss/3-30151 [001] .... 91344.204315: zfs_new_state__mru...
lt-zpool-30132 [001] .... 91344.204332: zfs_arc__hit: hdr ...
lt-zpool-30132 [001] .... 91344.204337: zfs_arc__hit: hdr ...
lt-zpool-30132 [001] .... 91344.204352: zfs_arc__hit: hdr ...
lt-zpool-30132 [001] .... 91344.204356: zfs_arc__hit: hdr ...
lt-zpool-30132 [001] .... 91344.204360: zfs_arc__hit: hdr ...
To highlight the kind of detailed information that is being exported
using this infrastructure, I've taken the first tracepoint line from the
output above and reformatted it such that it fits in 80 columns:
lt-zpool-30132 [003] .... 91344.200050: zfs_arc__miss:
hdr {
dva 0x1:0x40082
birth 15491
cksum0 0x163edbff3a
flags 0x640
datacnt 1
type 1
size 2048
spa 3133524293419867460
state_type 0
access 0
mru_hits 0
mru_ghost_hits 0
mfu_hits 0
mfu_ghost_hits 0
l2_hits 0
refcount 1
} bp {
dva0 0x1:0x40082
dva1 0x1:0x3000e5
dva2 0x1:0x5a006e
cksum 0x163edbff3a:0x75af30b3dd6:0x1499263ff5f2b:0x288bd118815e00
lsize 2048
} zb {
objset 0
object 0
level -1
blkid 0
}
For the specific tracepoint shown here, 'zfs_arc__miss', data is
exported detailing the arc_buf_hdr_t (hdr), blkptr_t (bp), and
zbookmark_t (zb) that caused the ARC miss (down to the exact DVA!).
This kind of precise and detailed information can be extremely valuable
when trying to answer certain kinds of questions.
For anybody unfamiliar but looking to build on this, I found the XFS
source code along with the following three web links to be extremely
helpful:
* http://lwn.net/Articles/379903/
* http://lwn.net/Articles/381064/
* http://lwn.net/Articles/383362/
I should also node the more "boring" aspects of this patch:
* The ZFS_LINUX_COMPILE_IFELSE autoconf macro was modified to
support a sixth paramter. This parameter is used to populate the
contents of the new conftest.h file. If no sixth parameter is
provided, conftest.h will be empty.
* The ZFS_LINUX_TRY_COMPILE_HEADER autoconf macro was introduced.
This macro is nearly identical to the ZFS_LINUX_TRY_COMPILE macro,
except it has support for a fifth option that is then passed as
the sixth parameter to ZFS_LINUX_COMPILE_IFELSE.
These autoconf changes were needed to test the availability of the Linux
tracepoint macros. Due to the odd nature of the Linux tracepoint macro
API, a separate ".h" must be created (the path and filename is used
internally by the kernel's define_trace.h file).
* The HAVE_DECLARE_EVENT_CLASS autoconf macro was introduced. This
is to determine if we can safely enable the Linux tracepoint
functionality. We need to selectively disable the tracepoint code
due to the kernel exporting certain functions as GPL only. Without
this check, the build process will fail at link time.
In addition, the SET_ERROR macro was modified into a tracepoint as well.
To do this, the 'sdt.h' file was moved into the 'include/sys' directory
and now contains a userspace portion and a kernel space portion. The
dprintf and zfs_dbgmsg* interfaces are now implemented as tracepoint as
well.
Signed-off-by: Prakash Surya <surya1@llnl.gov>
Signed-off-by: Ned Bass <bass6@llnl.gov>
Signed-off-by: Brian Behlendorf <behlendorf1@llnl.gov>
2014-06-13 17:54:48 +00:00
|
|
|
if (nl != NULL)
|
|
|
|
*nl = '\0';
|
|
|
|
|
2015-09-01 20:19:10 +00:00
|
|
|
/*
|
|
|
|
* 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
|
|
|
|
*/
|
2017-07-26 06:09:48 +00:00
|
|
|
if (zfs_flags & (ZFS_DEBUG_DPRINTF | ZFS_DEBUG_SET_ERROR))
|
|
|
|
DTRACE_PROBE1(zfs__dprintf, char *, buf);
|
2013-10-09 02:37:38 +00:00
|
|
|
|
2015-09-01 20:19:10 +00:00
|
|
|
/*
|
|
|
|
* 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);
|
2013-10-09 02:37:38 +00:00
|
|
|
}
|
2017-01-28 20:16:43 +00:00
|
|
|
|
|
|
|
#else
|
|
|
|
|
|
|
|
void
|
|
|
|
zfs_dbgmsg_print(const char *tag)
|
|
|
|
{
|
|
|
|
zfs_dbgmsg_t *zdm;
|
|
|
|
|
|
|
|
(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);
|
|
|
|
}
|
2015-09-01 20:19:10 +00:00
|
|
|
#endif /* _KERNEL */
|
2013-08-07 20:16:22 +00:00
|
|
|
|
2015-09-01 20:19:10 +00:00
|
|
|
#ifdef _KERNEL
|
|
|
|
module_param(zfs_dbgmsg_enable, int, 0644);
|
|
|
|
MODULE_PARM_DESC(zfs_dbgmsg_enable, "Enable ZFS debug message log");
|
2013-08-07 20:16:22 +00:00
|
|
|
|
2015-09-01 20:19:10 +00:00
|
|
|
module_param(zfs_dbgmsg_maxsize, int, 0644);
|
|
|
|
MODULE_PARM_DESC(zfs_dbgmsg_maxsize, "Maximum ZFS debug log size");
|
|
|
|
#endif
|