From 4b2220f0b937018b79154ac368c845e6176a8a66 Mon Sep 17 00:00:00 2001 From: Brian Behlendorf Date: Fri, 20 Jan 2012 16:39:12 -0800 Subject: [PATCH] Add --enable-debug-log configure option Until now the notion of an internal debug logging infrastructure was conflated with enabling ASSERT()s. This patch clarifies things by cleanly breaking the two subsystem apart. The result of this is the following behavior. --enable-debug - Enable/disable code wrapped in ASSERT()s. --disable-debug ASSERT()s are used to check invariants and are never required for correct operation. They are disabled by default because they may impact performance. --enable-debug-log - Enable/disable the debug log infrastructure. --disable-debug-log This infrastructure allows the spl code and its consumer to log messages to an in-kernel log. The granularity of the logging can be controlled by a debug mask. By default the mask disables most debug messages resulting in a negligible performance impact. Because of this the debug log is enabled by default. Signed-off-by: Brian Behlendorf --- config/spl-build.m4 | 28 +++++++++++++++ configure | 78 ++++++++++++++++++++++++++++++++++-------- include/spl-debug.h | 56 +++++++++++++++++++++--------- include/sys/debug.h | 7 ++-- module/spl/spl-debug.c | 5 +++ module/spl/spl-err.c | 2 +- module/spl/spl-kmem.c | 2 +- module/spl/spl-proc.c | 8 +++++ scripts/check.sh | 3 +- spl_config.h.in | 3 ++ 10 files changed, 152 insertions(+), 40 deletions(-) diff --git a/config/spl-build.m4 b/config/spl-build.m4 index a20ee38d1e..205eb6bc51 100644 --- a/config/spl-build.m4 +++ b/config/spl-build.m4 @@ -19,6 +19,7 @@ AC_DEFUN([SPL_AC_CONFIG_KERNEL], [ AC_SUBST(KERNELCPPFLAGS) SPL_AC_DEBUG + SPL_AC_DEBUG_LOG SPL_AC_DEBUG_KMEM SPL_AC_DEBUG_KMEM_TRACKING SPL_AC_ATOMIC_SPINLOCK @@ -485,6 +486,33 @@ AC_DEFUN([SPL_AC_DEBUG], [ AC_MSG_RESULT([$enable_debug]) ]) +dnl # +dnl # Enabled by default it provides a basic debug log infrastructure. +dnl # Each subsystem registers itself with a name and logs messages +dnl # using predefined types. If the debug mask it set to allow the +dnl # message type it will be written to the internal log. The log +dnl # can be dumped to a file by echoing 1 to the 'dump' proc entry, +dnl # after dumping the log it must be decoded using the spl utility. +dnl # +dnl # echo 1 >/proc/sys/kernel/spl/debug/dump +dnl # spl /tmp/spl-log.xxx.yyy /tmp/spl-log.xxx.yyy.txt +dnl # +AC_DEFUN([SPL_AC_DEBUG_LOG], [ + AC_ARG_ENABLE([debug-log], + [AS_HELP_STRING([--enable-debug-log], + [Enable basic debug logging @<:@default=yes@:>@])], + [], + [enable_debug_log=yes]) + + AS_IF([test "x$enable_debug_log" = xyes], + [AC_DEFINE([DEBUG_LOG], [1], + [Define to 1 to enable basic debug logging]) + KERNELCPPFLAGS="${KERNELCPPFLAGS} -DDEBUG_LOG"]) + + AC_MSG_CHECKING([whether basic debug logging is enabled]) + AC_MSG_RESULT([$enable_debug_log]) +]) + dnl # dnl # Enabled by default it provides a minimal level of memory tracking. dnl # A total count of bytes allocated is kept for each alloc and free. diff --git a/configure b/configure index 7b93f564f5..3b3439ad19 100755 --- a/configure +++ b/configure @@ -961,6 +961,7 @@ with_config with_linux with_linux_obj enable_debug +enable_debug_log enable_debug_kmem enable_debug_kmem_tracking enable_atomic_spinlocks @@ -1615,6 +1616,7 @@ Optional Features: optimize for fast installation [default=yes] --disable-libtool-lock avoid locking (might break parallel builds) --enable-debug Enable generic debug support [default=no] + --enable-debug-log Enable basic debug logging [default=yes] --enable-debug-kmem Enable basic kmem accounting [default=yes] --enable-debug-kmem-tracking Enable detailed kmem tracking [default=no] @@ -4783,13 +4785,13 @@ if test "${lt_cv_nm_interface+set}" = set; then else lt_cv_nm_interface="BSD nm" echo "int some_variable = 0;" > conftest.$ac_ext - (eval echo "\"\$as_me:4786: $ac_compile\"" >&5) + (eval echo "\"\$as_me:4788: $ac_compile\"" >&5) (eval "$ac_compile" 2>conftest.err) cat conftest.err >&5 - (eval echo "\"\$as_me:4789: $NM \\\"conftest.$ac_objext\\\"\"" >&5) + (eval echo "\"\$as_me:4791: $NM \\\"conftest.$ac_objext\\\"\"" >&5) (eval "$NM \"conftest.$ac_objext\"" 2>conftest.err > conftest.out) cat conftest.err >&5 - (eval echo "\"\$as_me:4792: output\"" >&5) + (eval echo "\"\$as_me:4794: output\"" >&5) cat conftest.out >&5 if $GREP 'External.*some_variable' conftest.out > /dev/null; then lt_cv_nm_interface="MS dumpbin" @@ -5995,7 +5997,7 @@ ia64-*-hpux*) ;; *-*-irix6*) # Find out which ABI we are using. - echo '#line 5998 "configure"' > conftest.$ac_ext + echo '#line 6000 "configure"' > conftest.$ac_ext if { (eval echo "$as_me:$LINENO: \"$ac_compile\"") >&5 (eval $ac_compile) 2>&5 ac_status=$? @@ -7848,11 +7850,11 @@ else -e 's:.*FLAGS}\{0,1\} :&$lt_compiler_flag :; t' \ -e 's: [^ ]*conftest\.: $lt_compiler_flag&:; t' \ -e 's:$: $lt_compiler_flag:'` - (eval echo "\"\$as_me:7851: $lt_compile\"" >&5) + (eval echo "\"\$as_me:7853: $lt_compile\"" >&5) (eval "$lt_compile" 2>conftest.err) ac_status=$? cat conftest.err >&5 - echo "$as_me:7855: \$? = $ac_status" >&5 + echo "$as_me:7857: \$? = $ac_status" >&5 if (exit $ac_status) && test -s "$ac_outfile"; then # The compiler can only warn and ignore the option if not recognized # So say no if there are warnings other than the usual output. @@ -8187,11 +8189,11 @@ else -e 's:.*FLAGS}\{0,1\} :&$lt_compiler_flag :; t' \ -e 's: [^ ]*conftest\.: $lt_compiler_flag&:; t' \ -e 's:$: $lt_compiler_flag:'` - (eval echo "\"\$as_me:8190: $lt_compile\"" >&5) + (eval echo "\"\$as_me:8192: $lt_compile\"" >&5) (eval "$lt_compile" 2>conftest.err) ac_status=$? cat conftest.err >&5 - echo "$as_me:8194: \$? = $ac_status" >&5 + echo "$as_me:8196: \$? = $ac_status" >&5 if (exit $ac_status) && test -s "$ac_outfile"; then # The compiler can only warn and ignore the option if not recognized # So say no if there are warnings other than the usual output. @@ -8292,11 +8294,11 @@ else -e 's:.*FLAGS}\{0,1\} :&$lt_compiler_flag :; t' \ -e 's: [^ ]*conftest\.: $lt_compiler_flag&:; t' \ -e 's:$: $lt_compiler_flag:'` - (eval echo "\"\$as_me:8295: $lt_compile\"" >&5) + (eval echo "\"\$as_me:8297: $lt_compile\"" >&5) (eval "$lt_compile" 2>out/conftest.err) ac_status=$? cat out/conftest.err >&5 - echo "$as_me:8299: \$? = $ac_status" >&5 + echo "$as_me:8301: \$? = $ac_status" >&5 if (exit $ac_status) && test -s out/conftest2.$ac_objext then # The compiler can only warn and ignore the option if not recognized @@ -8347,11 +8349,11 @@ else -e 's:.*FLAGS}\{0,1\} :&$lt_compiler_flag :; t' \ -e 's: [^ ]*conftest\.: $lt_compiler_flag&:; t' \ -e 's:$: $lt_compiler_flag:'` - (eval echo "\"\$as_me:8350: $lt_compile\"" >&5) + (eval echo "\"\$as_me:8352: $lt_compile\"" >&5) (eval "$lt_compile" 2>out/conftest.err) ac_status=$? cat out/conftest.err >&5 - echo "$as_me:8354: \$? = $ac_status" >&5 + echo "$as_me:8356: \$? = $ac_status" >&5 if (exit $ac_status) && test -s out/conftest2.$ac_objext then # The compiler can only warn and ignore the option if not recognized @@ -11150,7 +11152,7 @@ else lt_dlunknown=0; lt_dlno_uscore=1; lt_dlneed_uscore=2 lt_status=$lt_dlunknown cat > conftest.$ac_ext <<_LT_EOF -#line 11153 "configure" +#line 11155 "configure" #include "confdefs.h" #if HAVE_DLFCN_H @@ -11246,7 +11248,7 @@ else lt_dlunknown=0; lt_dlno_uscore=1; lt_dlneed_uscore=2 lt_status=$lt_dlunknown cat > conftest.$ac_ext <<_LT_EOF -#line 11249 "configure" +#line 11251 "configure" #include "confdefs.h" #if HAVE_DLFCN_H @@ -11980,6 +11982,30 @@ fi $as_echo "$enable_debug" >&6; } + # Check whether --enable-debug-log was given. +if test "${enable_debug_log+set}" = set; then + enableval=$enable_debug_log; +else + enable_debug_log=yes +fi + + + if test "x$enable_debug_log" = xyes; then + +cat >>confdefs.h <<\_ACEOF +#define DEBUG_LOG 1 +_ACEOF + + KERNELCPPFLAGS="${KERNELCPPFLAGS} -DDEBUG_LOG" +fi + + + { $as_echo "$as_me:$LINENO: checking whether basic debug logging is enabled" >&5 +$as_echo_n "checking whether basic debug logging is enabled... " >&6; } + { $as_echo "$as_me:$LINENO: result: $enable_debug_log" >&5 +$as_echo "$enable_debug_log" >&6; } + + # Check whether --enable-debug-kmem was given. if test "${enable_debug_kmem+set}" = set; then enableval=$enable_debug_kmem; @@ -16359,6 +16385,30 @@ fi $as_echo "$enable_debug" >&6; } + # Check whether --enable-debug-log was given. +if test "${enable_debug_log+set}" = set; then + enableval=$enable_debug_log; +else + enable_debug_log=yes +fi + + + if test "x$enable_debug_log" = xyes; then + +cat >>confdefs.h <<\_ACEOF +#define DEBUG_LOG 1 +_ACEOF + + KERNELCPPFLAGS="${KERNELCPPFLAGS} -DDEBUG_LOG" +fi + + + { $as_echo "$as_me:$LINENO: checking whether basic debug logging is enabled" >&5 +$as_echo_n "checking whether basic debug logging is enabled... " >&6; } + { $as_echo "$as_me:$LINENO: result: $enable_debug_log" >&5 +$as_echo "$enable_debug_log" >&6; } + + # Check whether --enable-debug-kmem was given. if test "${enable_debug_kmem+set}" = set; then enableval=$enable_debug_kmem; diff --git a/include/spl-debug.h b/include/spl-debug.h index 1e08e77bc2..98164966c3 100644 --- a/include/spl-debug.h +++ b/include/spl-debug.h @@ -43,6 +43,7 @@ #define _SPL_DEBUG_INTERNAL_H #include +#include #define SS_UNDEFINED 0x00000001 #define SS_ATOMIC 0x00000002 @@ -86,21 +87,8 @@ #define SD_OTHER 0x00000100 #define SD_CANTMASK (SD_ERROR | SD_EMERG | SD_WARNING | SD_CONSOLE) -#ifdef NDEBUG /* Debugging Disabled */ - -#define SDEBUG(mask, fmt, a...) ((void)0) -#define SDEBUG_LIMIT(x, y, fmt, a...) ((void)0) -#define SWARN(fmt, a...) ((void)0) -#define SERROR(fmt, a...) ((void)0) -#define SEMERG(fmt, a...) ((void)0) -#define SCONSOLE(mask, fmt, a...) ((void)0) - -#define SENTRY ((void)0) -#define SEXIT ((void)0) -#define SRETURN(x) return (x) -#define SGOTO(x, y) { ((void)(y)); goto x; } - -#else /* Debugging Enabled */ +/* Debug log support enabled */ +#ifdef DEBUG_LOG #define __SDEBUG(cdls, subsys, mask, format, a...) \ do { \ @@ -149,8 +137,6 @@ do { \ goto label; \ } while (0) -#endif /* NDEBUG */ - typedef struct { unsigned long cdls_next; int cdls_count; @@ -183,10 +169,46 @@ extern int spl_debug_set_mb(int mb); extern int spl_debug_get_mb(void); extern int spl_debug_dumplog(int flags); extern void spl_debug_dumpstack(struct task_struct *tsk); +extern void spl_debug_bug(char *file, const char *fn, const int line, int fl); +extern int spl_debug_msg(void *arg, int subsys, int mask, const char *file, + const char *fn, const int line, const char *format, ...); extern int spl_debug_clear_buffer(void); extern int spl_debug_mark_buffer(char *text); int spl_debug_init(void); void spl_debug_fini(void); +/* Debug log support disabled */ +#else /* DEBUG_LOG */ + +#define SDEBUG(mask, fmt, a...) ((void)0) +#define SDEBUG_LIMIT(x, y, fmt, a...) ((void)0) +#define SWARN(fmt, a...) ((void)0) +#define SERROR(fmt, a...) ((void)0) +#define SEMERG(fmt, a...) ((void)0) +#define SCONSOLE(mask, fmt, a...) ((void)0) + +#define SENTRY ((void)0) +#define SEXIT ((void)0) +#define SRETURN(x) return (x) +#define SGOTO(x, y) { ((void)(y)); goto x; } + +static inline int spl_debug_init(void) { return (0); } +static inline void spl_debug_fini(void) { return; } + +static inline void +spl_debug_bug(char *file, const char *fn, const int line, int fl) +{ + return; +} + +static inline int +spl_debug_msg(void *arg, int subsys, int mask, const char *file, + const char *fn, const int line, const char *format, ...) +{ + return (0); +} + +#endif /* DEBUG_LOG */ + #endif /* SPL_DEBUG_INTERNAL_H */ diff --git a/include/sys/debug.h b/include/sys/debug.h index fbf15143f8..271dbc2109 100644 --- a/include/sys/debug.h +++ b/include/sys/debug.h @@ -44,6 +44,8 @@ #ifndef _SPL_DEBUG_H #define _SPL_DEBUG_H +#include + #ifdef NDEBUG /* Debugging Disabled */ /* Define SPL_DEBUG_STR to make clear which ASSERT definitions are used */ @@ -137,9 +139,4 @@ do { \ #define VERIFY(x) ASSERT(x) #endif /* NDEBUG */ - -extern void spl_debug_bug(char *file, const char *fn, const int line, int fl); -extern int spl_debug_msg(void *arg, int subsys, int mask, const char *file, - const char *fn, const int line, const char *format, ...); - #endif /* SPL_DEBUG_H */ diff --git a/module/spl/spl-debug.c b/module/spl/spl-debug.c index 0dbbb5a7ca..4bcc34a8ef 100644 --- a/module/spl/spl-debug.c +++ b/module/spl/spl-debug.c @@ -47,6 +47,9 @@ #define SS_DEBUG_SUBSYS SS_DEBUG +/* Debug log support enabled */ +#ifdef DEBUG_LOG + unsigned long spl_debug_subsys = ~0; EXPORT_SYMBOL(spl_debug_subsys); module_param(spl_debug_subsys, ulong, 0644); @@ -1248,3 +1251,5 @@ spl_debug_fini(void) { trace_fini(); } + +#endif /* DEBUG_LOG */ diff --git a/module/spl/spl-err.c b/module/spl/spl-err.c index 200028f3bb..c837d1eaaa 100644 --- a/module/spl/spl-err.c +++ b/module/spl/spl-err.c @@ -34,7 +34,7 @@ #define SS_DEBUG_SUBSYS SS_GENERIC -#ifndef NDEBUG +#ifdef DEBUG_LOG static char ce_prefix[CE_IGNORE][10] = { "", "NOTICE: ", "WARNING: ", "" }; static char ce_suffix[CE_IGNORE][2] = { "", "\n", "\n", "" }; #endif diff --git a/module/spl/spl-kmem.c b/module/spl/spl-kmem.c index 5a6011ad61..446dab128f 100644 --- a/module/spl/spl-kmem.c +++ b/module/spl/spl-kmem.c @@ -672,7 +672,7 @@ kmem_alloc_debug(size_t size, int flags, const char *func, int line, "large kmem_alloc(%llu, 0x%x) at %s:%d (%lld/%llu)\n", (unsigned long long) size, flags, func, line, kmem_alloc_used_read(), kmem_alloc_max); - spl_debug_dumpstack(NULL); + dump_stack(); } /* Use the correct allocator */ diff --git a/module/spl/spl-proc.c b/module/spl/spl-proc.c index 745b107141..8149143ae2 100644 --- a/module/spl/spl-proc.c +++ b/module/spl/spl-proc.c @@ -125,6 +125,7 @@ enum { CTL_HW_SERIAL, /* Hardware serial number from hostid */ CTL_KALLSYMS, /* Address of kallsyms_lookup_name */ +#ifdef DEBUG_LOG CTL_DEBUG_SUBSYS, /* Debug subsystem */ CTL_DEBUG_MASK, /* Debug mask */ CTL_DEBUG_PRINTK, /* Force all messages to console */ @@ -136,6 +137,7 @@ enum { CTL_DEBUG_DUMP, /* Dump debug buffer to file */ CTL_DEBUG_FORCE_BUG, /* Hook to force a BUG */ CTL_DEBUG_STACK_SIZE, /* Max observed stack size */ +#endif CTL_CONSOLE_RATELIMIT, /* Ratelimit console messages */ CTL_CONSOLE_MAX_DELAY_CS, /* Max delay which we skip messages */ @@ -221,6 +223,7 @@ proc_copyout_string(char *ubuffer, int ubuffer_size, return size; } +#ifdef DEBUG_LOG SPL_PROC_HANDLER(proc_dobitmasks) { unsigned long *mask = table->data; @@ -407,6 +410,7 @@ SPL_PROC_HANDLER(proc_console_backoff) SRETURN(rc); } +#endif /* DEBUG_LOG */ #ifdef DEBUG_KMEM SPL_PROC_HANDLER(proc_domemused) @@ -716,6 +720,7 @@ static struct file_operations proc_slab_operations = { }; #endif /* DEBUG_KMEM */ +#ifdef DEBUG_LOG static struct ctl_table spl_debug_table[] = { { CTL_NAME (CTL_DEBUG_SUBSYS) @@ -829,6 +834,7 @@ static struct ctl_table spl_debug_table[] = { }, {0}, }; +#endif /* DEBUG_LOG */ static struct ctl_table spl_vm_table[] = { { @@ -1056,12 +1062,14 @@ static struct ctl_table spl_table[] = { .proc_handler = &proc_dokallsyms_lookup_name, }, #endif +#ifdef DEBUG_LOG { CTL_NAME (CTL_SPL_DEBUG) .procname = "debug", .mode = 0555, .child = spl_debug_table, }, +#endif { CTL_NAME (CTL_SPL_VM) .procname = "vm", diff --git a/scripts/check.sh b/scripts/check.sh index 8c0e0c5cbe..4334ff3a52 100755 --- a/scripts/check.sh +++ b/scripts/check.sh @@ -65,9 +65,8 @@ fi /sbin/modprobe zlib_inflate &>/dev/null /sbin/modprobe zlib_deflate &>/dev/null -spl_module_params="spl_debug_mask=0xffffffff spl_debug_subsys=0xffffffff" echo "Loading ${spl_module}" -/sbin/insmod ${spl_module} ${spl_module_params} || die "Failed to load ${spl_module}" +/sbin/insmod ${spl_module} || die "Failed to load ${spl_module}" echo "Loading ${splat_module}" /sbin/insmod ${splat_module} || die "Unable to load ${splat_module}" diff --git a/spl_config.h.in b/spl_config.h.in index 847da2137a..05dcdc5045 100644 --- a/spl_config.h.in +++ b/spl_config.h.in @@ -9,6 +9,9 @@ /* Define to 1 to enable detailed kmem tracking */ #undef DEBUG_KMEM_TRACKING +/* Define to 1 to enable basic debug logging */ +#undef DEBUG_LOG + /* invalidate_inodes() wants 2 args */ #undef HAVE_2ARGS_INVALIDATE_INODES