Add some crude debugging support. It leaves alot to be

desired, but it should allow more easy kernel debugging for now.


git-svn-id: https://outreach.scidac.gov/svn/spl/trunk@59 7e1ea52c-4ff2-0310-8f11-9dd32ca42a1c

include/sys/debug.h

@@ -1,4 +1,11 @@
 #ifndef _SPL_DEBUG_H
 #define _SPL_DEBUG_H
 
+extern unsigned long spl_debug_mask;
+extern unsigned long spl_debug_subsys;
+
+void __dprintf(const char *file, const char *func, int line, const char *fmt, ...);
+void spl_set_debug_mask(unsigned long mask);
+void spl_set_debug_subsys(unsigned long mask);
+
 #endif /* SPL_DEBUG_H */

include/sys/kmem.h

@@ -35,14 +35,14 @@ extern int kmem_warning_flag;
                                                                               \
 	/* Marked unlikely because we should never be doing this */           \
         if (unlikely((size) > (PAGE_SIZE * 2)) && kmem_warning_flag)          \
-                printk("Warning: kmem_alloc(%d, 0x%x) large alloc at %s:%d "  \
+                printk("spl: Warning kmem_alloc(%d, 0x%x) large alloc at %s:%d "  \
                        "(%ld/%ld)\n", (int)(size), (int)(flags),              \
 		       __FILE__, __LINE__,                                    \
 		       atomic64_read(&kmem_alloc_used), kmem_alloc_max);      \
                                                                               \
         _ptr_ = (void *)allocator((size), (flags));                           \
         if (_ptr_ == NULL) {                                                  \
-                printk("Warning: kmem_alloc(%d, 0x%x) failed at %s:%d "       \
+                printk("spl: Warning kmem_alloc(%d, 0x%x) failed at %s:%d "       \
 		       "(%ld/%ld)\n", (int)(size), (int)(flags),              \
 		       __FILE__, __LINE__,                                    \
 		       atomic64_read(&kmem_alloc_used), kmem_alloc_max);      \
@@ -73,7 +73,7 @@ extern int kmem_warning_flag;
                                                                               \
         _ptr_ = (void *)vmalloc((size));                                      \
         if (_ptr_ == NULL) {                                                  \
-                printk("Warning: vmem_alloc(%d, 0x%x) failed at %s:%d "       \
+                printk("spl: Warning vmem_alloc(%d, 0x%x) failed at %s:%d "       \
 		       "(%ld/%ld)\n", (int)(size), (int)(flags),              \
 		       __FILE__, __LINE__,                                    \
 		       atomic64_read(&vmem_alloc_used), vmem_alloc_max);      \

include/sys/rwlock.h

@@ -236,7 +236,7 @@ rw_tryupgrade(krwlock_t *rwlp)
 	 * lock.  If there is, then we know we should
 	 * not try to upgrade the lock */
 	if (!list_empty(&rwlp->rw_sem.wait_list)) {
-		printk(KERN_WARNING "There are threads waiting\n");
+		printk("spl: Warning There are threads waiting\n");
 		spin_unlock(&rwlp->rw_sem.wait_lock);
 		return 0;
 	}

include/sys/sysmacros.h

@@ -80,7 +80,7 @@ extern "C" {
 	const TYPE __left = (TYPE)(LEFT);                           \
 	const TYPE __right = (TYPE)(RIGHT);                         \
 	if (!(__left OP __right)) {                                 \
-		printk("Failed VERIFY3(" FMT " " #OP " " FMT ")\n", \
+		printk("spl: Error VERIFY3(" FMT " " #OP " " FMT ")\n", \
 		        CAST __left,  CAST __right);                \
 		BUG();                                              \
 	}                                                           \

modules/spl/spl-generic.c

@@ -2,11 +2,24 @@
 #include <sys/vmsystm.h>
 #include <sys/vnode.h>
 #include <sys/kmem.h>
+#include <sys/debug.h>
+#include <linux/proc_fs.h>
 #include "config.h"
 
 /*
  * Generic support
  */
+static char spl_debug_buffer[MAXMSGLEN];
+static spinlock_t spl_debug_lock = SPIN_LOCK_UNLOCKED;
+
+unsigned long spl_debug_mask = 0;
+unsigned long spl_debug_subsys = 0xff;
+EXPORT_SYMBOL(spl_debug_mask);
+EXPORT_SYMBOL(spl_debug_subsys);
+
+static struct proc_dir_entry *spl_proc_root = NULL;
+static struct proc_dir_entry *spl_proc_debug_mask = NULL;
+static struct proc_dir_entry *spl_proc_debug_subsys = NULL;
 
 int p0 = 0;
 EXPORT_SYMBOL(p0);
@@ -17,6 +30,7 @@ EXPORT_SYMBOL(hw_serial);
 vmem_t *zio_alloc_arena = NULL;
 EXPORT_SYMBOL(zio_alloc_arena);
 
+
 int
 highbit(unsigned long i)
 {
@@ -56,27 +70,221 @@ ddi_strtoul(const char *str, char **nptr, int base, unsigned long *result)
 }
 EXPORT_SYMBOL(ddi_strtoul);
 
-static int __init spl_init(void)
+/* XXX: Not the most efficient debug function ever.  This should be re-done
+ * as an internal per-cpu in-memory debug log accessable via /proc/.  Not as
+ * a shared global buffer everything gets serialize though.  That said I'll
+ * worry about performance considerations once I've dealt with correctness.
+ */
+void
+__dprintf(const char *file, const char *func, int line, const char *fmt, ...)
+{
+        char *sfp, *start, *ptr;
+        struct timeval tv;
+        va_list ap;
+
+	start = ptr = spl_debug_buffer;
+        sfp = strrchr(file, '/');
+        do_gettimeofday(&tv);
+
+	spin_lock(&spl_debug_lock);
+        ptr += snprintf(ptr, MAXMSGLEN - 1,
+                        "spl: %lu.%06lu:%d:%u:%s:%d:%s(): ",
+                        tv.tv_sec, tv.tv_usec, current->pid,
+                        smp_processor_id(),
+                        sfp == NULL ? file : sfp + 1,
+                        line, func);
+
+        va_start(ap, fmt);
+        ptr += vsnprintf(ptr, MAXMSGLEN - (ptr - start) - 1, fmt, ap);
+        va_end(ap);
+
+        printk("%s", start);
+	spin_unlock(&spl_debug_lock);
+}
+EXPORT_SYMBOL(__dprintf);
+
+static int
+spl_proc_rd_generic_ul(char *page, char **start, off_t off,
+		       int count, int *eof, unsigned long val)
 {
 	int rc;
 
-	if ((rc = kmem_init()))
+        *start = page;
-		return rc;
+        *eof = 1;
 
-	if ((rc = vn_init()))
+	if (off || count > PAGE_SIZE)
-		return rc;
+		return 0;
 
-	strcpy(hw_serial, "007f0100"); /* loopback */
+	spin_lock(&spl_debug_lock);
-        printk(KERN_INFO "spl: Loaded Solaris Porting Layer v%s\n", VERSION);
+	rc = snprintf(page, PAGE_SIZE, "0x%lx\n", val);
+	spin_unlock(&spl_debug_lock);
+
+	return rc;
+}
+
+static int
+spl_proc_rd_debug_mask(char *page, char **start, off_t off,
+                       int count, int *eof, void *data)
+{
+	return spl_proc_rd_generic_ul(page, start, off, count,
+				      eof, spl_debug_mask);
+}
+
+static int
+spl_proc_rd_debug_subsys(char *page, char **start, off_t off,
+                         int count, int *eof, void *data)
+{
+	return spl_proc_rd_generic_ul(page, start, off, count,
+				      eof, spl_debug_subsys);
+}
+
+static int
+spl_proc_wr_generic_ul(const char *ubuf, unsigned long count,
+                       unsigned long *val, int base)
+{
+	char *end, kbuf[32];
+
+	if (count >= sizeof(kbuf))
+		return -EOVERFLOW;
+
+	if (copy_from_user(kbuf, ubuf, count))
+		return -EFAULT;
+
+	kbuf[count] = '\0';
+	*val = (int)simple_strtoul(kbuf, &end, base);
+	if (kbuf == end)
+		return -EINVAL;
 
 	return 0;
 }
 
+static int
+spl_proc_wr_debug_mask(struct file *file, const char *ubuf,
+                       unsigned long count, void *data, int mode)
+{
+	unsigned long val;
+	int rc;
+
+	rc = spl_proc_wr_generic_ul(ubuf, count, &val, 16);
+	if (rc)
+		return rc;
+
+	spin_lock(&spl_debug_lock);
+	spl_debug_mask = val;
+	spin_unlock(&spl_debug_lock);
+
+	return count;
+}
+
+static int
+spl_proc_wr_debug_subsys(struct file *file, const char *ubuf,
+                         unsigned long count, void *data, int mode)
+{
+	unsigned long val;
+	int rc;
+
+	rc = spl_proc_wr_generic_ul(ubuf, count, &val, 16);
+	if (rc)
+		return rc;
+
+	spin_lock(&spl_debug_lock);
+	spl_debug_subsys = val;
+	spin_unlock(&spl_debug_lock);
+
+	return count;
+}
+
+static struct proc_dir_entry *
+spl_register_proc_entry(const char *name, mode_t mode,
+                        struct proc_dir_entry *parent, void *data,
+                        void *read_proc, void *write_proc)
+{
+        struct proc_dir_entry *entry;
+
+        entry = create_proc_entry(name, mode, parent);
+        if (!entry)
+                return ERR_PTR(-EINVAL);
+
+        entry->data = data;
+        entry->read_proc = read_proc;
+        entry->write_proc = write_proc;
+
+        return entry;
+} /* register_proc_entry() */
+
+void spl_set_debug_mask(unsigned long mask) {
+	spin_lock(&spl_debug_lock);
+	spl_debug_mask = mask;
+	spin_unlock(&spl_debug_lock);
+}
+EXPORT_SYMBOL(spl_set_debug_mask);
+
+void spl_set_debug_subsys(unsigned long mask) {
+	spin_lock(&spl_debug_lock);
+	spl_debug_subsys = mask;
+	spin_unlock(&spl_debug_lock);
+}
+EXPORT_SYMBOL(spl_set_debug_subsys);
+
+static int __init spl_init(void)
+{
+	int rc = 0;
+
+        spl_proc_root = proc_mkdir("spl", NULL);
+        if (!spl_proc_root) {
+                printk("spl: Error unable to create /proc/spl/ directory\n");
+		return -EINVAL;
+        }
+
+	spl_proc_debug_mask = spl_register_proc_entry("debug_mask", 0644,
+	                                          spl_proc_root, NULL,
+	                                          spl_proc_rd_debug_mask,
+	                                          spl_proc_wr_debug_mask);
+	if (IS_ERR(spl_proc_debug_mask)) {
+		rc = PTR_ERR(spl_proc_debug_mask);
+		goto out;
+	}
+
+	spl_proc_debug_subsys = spl_register_proc_entry("debug_subsys", 0644,
+	                                            spl_proc_root, NULL,
+	                                            spl_proc_rd_debug_subsys,
+	                                            spl_proc_wr_debug_subsys);
+	if (IS_ERR(spl_proc_debug_subsys)) {
+		rc = PTR_ERR(spl_proc_debug_subsys);
+		goto out2;
+	}
+
+	if ((rc = kmem_init()))
+		goto out2;
+
+	if ((rc = vn_init()))
+		goto out2;
+
+	strcpy(hw_serial, "007f0100"); /* loopback */
+        printk("spl: Loaded Solaris Porting Layer v%s\n", VERSION);
+
+	return 0;
+out2:
+	if (spl_proc_debug_mask)
+		remove_proc_entry("debug_mask", spl_proc_root);
+
+	if (spl_proc_debug_subsys)
+		remove_proc_entry("debug_subsys", spl_proc_root);
+out:
+        remove_proc_entry("spl", NULL);
+
+	return rc;
+}
+
 static void spl_fini(void)
 {
 	vn_fini();
 	kmem_fini();
 
+	remove_proc_entry("debug_subsys", spl_proc_root);
+	remove_proc_entry("debug_mask", spl_proc_root);
+        remove_proc_entry("spl", NULL);
+
 	return;
 }
 

modules/spl/spl-kmem.c

@@ -291,11 +291,11 @@ kmem_fini(void)
 {
 #ifdef DEBUG_KMEM
         if (atomic64_read(&kmem_alloc_used) != 0)
-                printk("Warning: kmem leaked %ld/%ld bytes\n",
+                printk("spl: Warning kmem leaked %ld/%ld bytes\n",
                        atomic_read(&kmem_alloc_used), kmem_alloc_max);
 
         if (atomic64_read(&vmem_alloc_used) != 0)
-                printk("Warning: vmem leaked %ld/%ld bytes\n",
+                printk("spl: Warning vmem leaked %ld/%ld bytes\n",
                        atomic_read(&vmem_alloc_used), vmem_alloc_max);
 #endif
 }

modules/spl/spl-thread.c

@@ -90,7 +90,7 @@ __thread_create(caddr_t stk, size_t  stksize, thread_func_t func,
 
 	/* Solaris says this must never fail so we try forever */
 	while ((pid = kernel_thread(thread_generic_wrapper, (void *)&tp, 0)) < 0)
-		printk(KERN_ERR "Unable to create thread; pid = %ld\n", pid);
+		printk(KERN_ERR "spl: Error unable to create thread; pid = %ld\n", pid);
 
 	/* All signals are ignored due to sleeping TASK_UNINTERRUPTIBLE */
 	for (;;) {

modules/spl/spl-vnode.c

@@ -428,7 +428,6 @@ vn_getf(int fd)
 	if (fp) {
 		atomic_inc(&fp->f_ref);
 		spin_unlock(&vn_file_lock);
-		printk("found file\n");
 		return fp;
 	}
 
@@ -473,17 +472,13 @@ vn_getf(int fd)
 	return fp;
 
 out_vnode:
-	printk("out_vnode\n");
 	vn_free(vp);
 out_fget:
-	printk("out_fget\n");
 	fput(lfp);
 out_mutex:
-	printk("out_mutex\n");
 	mutex_exit(&fp->f_lock);
 	kmem_cache_free(vn_file_cache, fp);
 out:
-	printk("out\n");
         return NULL;
 } /* getf() */
 EXPORT_SYMBOL(getf);
@@ -593,17 +588,17 @@ vn_fini(void)
 
 	rc = kmem_cache_destroy(vn_file_cache);
 	if (rc)
-		printk("Warning leaked vn_file_cache objects\n");
+		printk("spl: Warning leaked vn_file_cache objects\n");
 
 	vn_file_cache = NULL;
 	spin_unlock(&vn_file_lock);
 
 	if (leaked > 0)
-		printk("Warning: %d files leaked\n", leaked);
+		printk("spl: Warning %d files leaked\n", leaked);
 
 	rc = kmem_cache_destroy(vn_cache);
 	if (rc)
-		printk("Warning leaked vn_cache objects\n");
+		printk("spl: Warning leaked vn_cache objects\n");
 
 	return;
 } /* vn_fini() */

modules/splat/splat-internal.h

@@ -38,47 +38,47 @@
 #include "splat-ctl.h"
 
 #define SPLAT_SUBSYSTEM_INIT(type)                                      \
-({      splat_subsystem_t *_sub_;                                         \
+({      splat_subsystem_t *_sub_;                                       \
                                                                         \
-        _sub_ = (splat_subsystem_t *)splat_##type##_init();                 \
+        _sub_ = (splat_subsystem_t *)splat_##type##_init();             \
         if (_sub_ == NULL) {                                            \
-                printk(KERN_ERR "Error initializing: " #type "\n");     \
+                printk(KERN_ERR "splat: Error initializing: " #type "\n"); \
         } else {                                                        \
-                spin_lock(&splat_module_lock);                            \
+                spin_lock(&splat_module_lock);                          \
-                list_add_tail(&(_sub_->subsystem_list),		\
+                list_add_tail(&(_sub_->subsystem_list),			\
 		              &splat_module_list);			\
-                spin_unlock(&splat_module_lock);                          \
+                spin_unlock(&splat_module_lock);                        \
         }                                                               \
 })
 
 #define SPLAT_SUBSYSTEM_FINI(type)                                      \
-({      splat_subsystem_t *_sub_, *_tmp_;                                 \
+({      splat_subsystem_t *_sub_, *_tmp_;                               \
         int _id_, _flag_ = 0;                                           \
                                                                         \
-	_id_ = splat_##type##_id();                                       \
+	_id_ = splat_##type##_id();                                     \
-        spin_lock(&splat_module_lock);                                    \
+        spin_lock(&splat_module_lock);                                  \
         list_for_each_entry_safe(_sub_, _tmp_,  &splat_module_list,	\
 		                 subsystem_list) {			\
                 if (_sub_->desc.id == _id_) {                           \
                         list_del_init(&(_sub_->subsystem_list));        \
-                        spin_unlock(&splat_module_lock);                  \
+                        spin_unlock(&splat_module_lock);                \
-                        splat_##type##_fini(_sub_);                       \
+                        splat_##type##_fini(_sub_);                     \
 			spin_lock(&splat_module_lock);			\
                         _flag_ = 1;                                     \
                 }                                                       \
         }                                                               \
-        spin_unlock(&splat_module_lock);                                  \
+        spin_unlock(&splat_module_lock);                                \
                                                                         \
 	if (!_flag_)                                                    \
-                printk(KERN_ERR "Error finalizing: " #type "\n");       \
+                printk(KERN_ERR "splat: Error finalizing: " #type "\n"); \
 })
 
 #define SPLAT_TEST_INIT(sub, n, d, tid, func)				\
-({      splat_test_t *_test_;                                             \
+({      splat_test_t *_test_;                                           \
                                                                         \
-	_test_ = (splat_test_t *)kmalloc(sizeof(*_test_), GFP_KERNEL);    \
+	_test_ = (splat_test_t *)kmalloc(sizeof(*_test_), GFP_KERNEL);  \
         if (_test_ == NULL) {						\
-		printk(KERN_ERR "Error initializing: " n "/" #tid" \n");\
+		printk(KERN_ERR "splat: Error initializing: " n "/" #tid" \n");\
 	} else {							\
 		memset(_test_, 0, sizeof(*_test_));			\
 		strncpy(_test_->desc.name, n, SPLAT_NAME_SIZE);		\
@@ -93,7 +93,7 @@
 })
 
 #define SPLAT_TEST_FINI(sub, tid)					\
-({      splat_test_t *_test_, *_tmp_;                                     \
+({      splat_test_t *_test_, *_tmp_;                                   \
         int _flag_ = 0;							\
                                                                         \
         spin_lock(&((sub)->test_lock));					\
@@ -107,7 +107,7 @@
         spin_unlock(&((sub)->test_lock));				\
                                                                         \
 	if (!_flag_)                                                    \
-                printk(KERN_ERR "Error finalizing: " #tid "\n");	\
+                printk(KERN_ERR "splat: Error finalizing: " #tid "\n");	\
 })
 
 typedef int (*splat_test_func_t)(struct file *, void *);