On Sat, Oct 27, 2012 at 09:26:51PM +0530, Srivatsa Bhat wrote:

On Sat, Oct 27, 2012 at 10:11 AM, Kumar amit mehta <gmate.amit@gmail.com> wrote:

...

Hi,

I recently came across this tool called KEDR[1] for checking memory leak in kernel modules. I'm using it to check If my trivial kernel modules (based on LDD3 examples) are leaking memory. I was wondering if there exist a similar tool for checking incorrect usage of locking techniques implemented by kernel module.

You can make use of the in-kernel "lockdep" framework to check your locking. Just enable it in your .config, and build and boot your kernel. Lockdep detects a variety of locking problems at run time and warns you if there is a possibility of deadlock etc.

Regards, Srivatsa S. Bhat Thank you Srivatsa. It seems that lockdep framework is enabled on my running kernel.

<snip> amit@ubuntu:/boot$ egrep -i "debug_kernel|lockdep" config-3.2.0-29-generic-pae CONFIG_LOCKDEP_SUPPORT=y CONFIG_DEBUG_KERNEL=y <snip> If above configuration is all that I need, then should I be seeing warning/error messages in kernel logs(/var/log/kern.log) when there is inconsistency in locking ? To test my hypothesis, I modified my simple kernel module to deliberately induce locking error (After initializing read-write semaphore, I call down_write() and do not free this semaphore lock by commenting out up_write() invocation). But still I don't see any error or warning message trace in kernel logs, I think, I'm missing something. I've just now found out that there is a tutorial on runtime locking correctness validator[1] under Documentation. I'll go through it. On the other hand, I found this KEDR utility very simple and accurate in finding out the erroneous memory handling. For example, this is how the KEDR reports memory leakage in my kernel module: <snip> 2670043 Oct 27 06:32:38 ubuntu kernel: [16963.930621] Inside echo_exit: kfree() 2670044 Oct 27 06:32:38 ubuntu kernel: [16963.930886] [leak_check] LeakCheck has detected possible memory leaks: 2670045 Oct 27 06:32:38 ubuntu kernel: [16963.930897] [leak_check] Address: 0xeeafbb70, size: 9; stack trace of the allocation: 2670046 Oct 27 06:32:38 ubuntu kernel: [16963.930907] [leak_check] [<f86ac0b2>] echo_write+0x42/0xd0 [echo] 2670047 Oct 27 06:32:38 ubuntu kernel: [16964.001413] [leak_check] [<c11448bf>] vfs_write+0x8f/0x160 2670048 Oct 27 06:32:38 ubuntu kernel: [16964.001421] [leak_check] [<c1144b9d>] sys_write+0x3d/0x70 2670049 Oct 27 06:32:38 ubuntu kernel: [16964.002214] [leak_check] [<c15ac7df>] sysenter_do_call+0x12/0x28 2670050 Oct 27 06:32:38 ubuntu kernel: [16964.002238] [leak_check] [<ffffffff>] 0xffffffff 2670051 Oct 27 06:32:38 ubuntu kernel: [16964.002242] [leak_check] ---------------------------------------- 2670052 Oct 27 06:32:38 ubuntu kernel: [16964.002248] [leak_check] Totals: 2670053 Oct 27 06:32:38 ubuntu kernel: [16964.002251] [leak_check] Allocations: 3 2670054 Oct 27 06:32:38 ubuntu kernel: [16964.002255] [leak_check] Possible leaks: 1 2670055 Oct 27 06:32:38 ubuntu kernel: [16964.002257] [leak_check] Unallocated frees: 0 2670056 Oct 27 06:32:38 ubuntu kernel: [16964.002260] [leak_check] ======== end of LeakCheck report ======== <snip> As you can see that with reports generated by KEDR like above, it becomes easy to detect the memory leak and therefore I'm looking at something similar like KEDR for detecting locking errors in kernel module. -Amit [1] http://lxr.linux.no/#linux+v3.6.3/Documentation/lockdep-design.txt

On Mon, Oct 29, 2012 at 12:03:08AM +0530, Srivatsa Bhat wrote:

You'll need CONFIG_LOCKDEP=y as well. An easy way to configure lock debugging checks is to run 'make menuconfig' and enable the required options under the "Kernel hacking" section.

...

If above configuration is all that I need, then should I be seeing warning/error messages in kernel logs(/var/log/kern.log) when there is inconsistency in locking ? To test my hypothesis, I modified my simple kernel module to deliberately induce locking error (After initializing read-write semaphore, I call down_write() and do not free this semaphore lock by commenting out up_write() invocation). But still I don't see any error or warning message trace in kernel logs, I think, I'm missing something.

Hi Srivatsa, Thank you for your mail. As per your suggestion, this time I've enabled CONFIG_LOCKDEP aslo in my running kernel and did the same experiment, but still I dont't see any warning/error messages in the kernel log. To give you more idea about what I'm doing, Please see the code below.(This is a simple char driver based on LDD3 examples) <echo.c> #include <linux/module.h> #include <linux/init.h> #include <linux/types.h> //MAJOR, MINOR #include <linux/fs.h> //register_chrdev_region, file_operations #include <linux/moduleparam.h> #include <linux/kernel.h> //container_of #include <linux/slab.h> //kmalloc #include <linux/cdev.h> //struct cdev #include <linux/version.h> #include <linux/uaccess.h> //copy_from/to_user() #include <linux/errno.h> //error code ssize_t echo_read(struct file *, char __user *, size_t, loff_t *); ssize_t echo_write(struct file *, const char __user *, size_t, loff_t *); int echo_open(struct inode *, struct file *); int echo_release(struct inode *, struct file *); struct echo_cdev { char *data; unsigned long size; //amount of data stored struct semaphore sem; struct cdev cdev; }; MODULE_LICENSE("GPL v2"); MODULE_AUTHOR("amit"); int nr_major; module_param(nr_major, int, S_IRUGO); MODULE_PARM_DESC(nr_major, "major number"); int nr_minor; char *chrdev_name = "echo"; static dev_t device; static int echo_dev_count = 1; struct echo_cdev *echo_dev = NULL; static struct file_operations echo_fs_ops = { .open = echo_open, .release = echo_release, .read = echo_read, .write = echo_write, .owner = THIS_MODULE, }; int echo_open(struct inode *inode, struct file *filp) { struct echo_cdev *dev; pr_debug("%s: f_flags: 0x%x\n",__FUNCTION__,filp->f_flags); //container_of(pointer, container_type, container_field); dev = container_of(inode->i_cdev, struct echo_cdev, cdev); filp->private_data = dev; if ((filp->f_flags & O_ACCMODE) == O_WRONLY) { //trim the device size to 0 dev->size = 0; } return 0; } int echo_release(struct inode *inode, struct file *filp) { return 0; } ssize_t echo_read(struct file *filp, char __user *ubuff, size_t count, loff_t *poffset) { struct echo_cdev *dev = filp->private_data; pr_debug("%s: f_flags: 0x%x\n",__FUNCTION__,filp->f_flags); //user trying to access an offset which is beyond the end of file if (down_interruptible(&dev->sem)) return -ERESTARTSYS; if (*poffset >= dev->size) { up(&dev->sem); return 0; } //user trying to access more than eof, return bytes read till the eof if (*poffset + count >= dev->size) //count = dev->size - *poffset; count = dev->size; //kspace --> uspace if (copy_to_user(ubuff, (dev->data + *poffset), count) < 0) { up(&dev->sem); return -EFAULT; } //update the offset *poffset += count; up(&dev->sem); return count; } //count is the size of requested data transfer ssize_t echo_write(struct file *filp, const char __user *ubuff, size_t count, loff_t *poffset) { int ret; struct echo_cdev *dev = filp->private_data; pr_debug("%s: f_flags: 0x%x\n",__FUNCTION__,filp->f_flags); if (down_interruptible(&dev->sem)) return -ERESTARTSYS; if (dev->data == NULL) { dev->data = (char *)kmalloc(count, GFP_KERNEL); if (!dev->data) { up(&dev->sem); return -ENOMEM; } else { memset(dev->data, 0, sizeof(count)); } } dev->size = count; //uspace --> kspace if (copy_from_user(dev->data, ubuff, count) < 0) { up(&dev->sem); return -EFAULT; } *poffset += count; ret = count; if (dev->size < *poffset) dev->size = *poffset; //Force lock error //up(&dev->sem); return ret; } static int __init echo_init(void) { int ret; printk(KERN_EMERG "entering %s\n",__FUNCTION__); //let the user provide the major number. if (nr_major) { device = MKDEV(nr_major, nr_minor); if ((ret = register_chrdev_region(device, echo_dev_count, chrdev_name)) < 0) { pr_debug("%s: failed to register %s\n",__FUNCTION__, chrdev_name); return ret; } } else { ret = alloc_chrdev_region(&device, 0, echo_dev_count, chrdev_name); if (ret < 0) { pr_debug("%s: failed to register %s\n",__FUNCTION__, chrdev_name); return ret; } } nr_major = MAJOR(device); nr_minor = MINOR(device); //print the major and minor numbers pr_debug("%s: major/minor:: %d/%d\n",__FUNCTION__, nr_major, nr_minor); echo_dev = (struct echo_cdev *)kmalloc(sizeof(struct echo_cdev), GFP_KERNEL); if (!echo_dev) { printk(KERN_EMERG "Not enough memory\n"); unregister_chrdev_region(device, echo_dev_count); return -ENOMEM; } memset(echo_dev, 0, sizeof(struct echo_cdev)); echo_dev->cdev.owner = THIS_MODULE; echo_dev->cdev.ops = &echo_fs_ops; //initialize the semaphore, before it is presented to the world sema_init(&echo_dev->sem,1); cdev_init(&echo_dev->cdev, &echo_fs_ops); device = MKDEV(nr_major, nr_minor); //tell the kernel about this char device //telling the VFS layer to associate echo driver's fs operation for file r/w etc. ret = cdev_add(&echo_dev->cdev, device, 1); if (ret) { kfree(echo_dev); unregister_chrdev_region(device, echo_dev_count); return ret; } return 0; } static void __exit echo_exit(void) { printk(KERN_EMERG "entering %s\n",__FUNCTION__); if (echo_dev->data) { printk("Inside %s: kfree()\n",__FUNCTION__); kfree(echo_dev->data); } cdev_del(&echo_dev->cdev); kfree(echo_dev); unregister_chrdev_region(device, echo_dev_count); } module_init(echo_init); module_exit(echo_exit); <echo.c> <Makefile> obj-m := echo.o CFLAGS_echo.o := -DDEBUG -Wall -Werror -Wmissing-prototypes \ -Wstrict-prototypes -Wunused-variable -O2 \ -Wunused-function -g modules: make -C /lib/modules/`uname -r`/build M=`pwd` clean: make -C /lib/modules/`uname -r`/build M=`pwd` clean <Makefile> Logs: root@ubuntu:/boot# egrep -i "debug_kernel|lockdep" config-3.7.0-rc3-next-20121029 CONFIG_LOCKDEP_SUPPORT=y CONFIG_DEBUG_KERNEL=y CONFIG_LOCKDEP=y # CONFIG_DEBUG_LOCKDEP is not set root@ubuntu:/home/amit/ldd3/misc-modules/echo# uname -a Linux ubuntu 3.7.0-rc3-next-20121029 #1 SMP Mon Oct 29 21:42:20 PDT 2012 i686 i686 i386 GNU/Linux root@ubuntu:/home/amit/ldd3/misc-modules/echo# dmesg root@ubuntu:/home/amit/ldd3/misc-modules/echo# insmod echo.ko root@ubuntu:/home/amit/ldd3/misc-modules/echo# dmesg [ 1156.704072] entering echo_init [ 1156.704914] echo_init: major/minor:: 249/0 root@ubuntu:/home/amit/ldd3/misc-modules/echo# mknod /dev/echo c 249 0 root@ubuntu:/home/amit/ldd3/misc-modules/echo# ll /dev/echo crw-r--r-- 1 root root 249, 0 Oct 29 22:29 /dev/echo root@ubuntu:/home/amit/ldd3/misc-modules/echo# echo "kernel newbiee" >/dev/echo root@ubuntu:/home/amit/ldd3/misc-modules/echo# dmesg [ 1156.704072] entering echo_init [ 1156.704914] echo_init: major/minor:: 249/0 [ 1237.377205] echo_open: f_flags: 0x8241 [ 1237.377392] echo_write: f_flags: 0x8001 root@ubuntu:/home/amit/ldd3/misc-modules/echo# cat /dev/echo --> Here the driver read routine gets stuck as I've not reliquished the semaphore lock root@ubuntu:/home/amit/ldd3/misc-modules/echo# cat /dev/echo ^C <-- killing the user process root@ubuntu:/home/amit/ldd3/misc-modules/echo# rmmod echo root@ubuntu:/home/amit/ldd3/misc-modules/echo# dmesg [ 1156.704072] entering echo_init [ 1156.704914] echo_init: major/minor:: 249/0 [ 1237.377205] echo_open: f_flags: 0x8241 [ 1237.377392] echo_write: f_flags: 0x8001 [ 1270.622337] echo_open: f_flags: 0x8000 [ 1270.622477] echo_read: f_flags: 0x8000 [ 1394.180962] entering echo_exit [ 1394.180996] Inside echo_exit: kfree() As you can see, no warning/error messages reported by kernel. -Amit

  Hi All,   While building the new kernel their are many option for kernel debugging   please refer the below link.   http://my.safaribooksonline.com/book/operating-systems-and-server-administra...   Hope this will help you catch the lock problem.   -Anand Moon ________________________________ From: Vladimir Murzin <murzin.v@gmail.com> To: Kumar amit mehta <gmate.amit@gmail.com> Cc: Srivatsa Bhat <bhat.srivatsa@gmail.com>; kernelnewbies@kernelnewbies.org Sent: Monday, November 5, 2012 11:21 AM Subject: Re: Tools for checking incorrect usage of locking techniques in k-space On Tue, Oct 30, 2012 at 9:41 AM, Kumar amit mehta <gmate.amit@gmail.com> wrote:

On Mon, Oct 29, 2012 at 12:03:08AM +0530, Srivatsa Bhat wrote:

...

You'll need CONFIG_LOCKDEP=y as well. An easy way to configure lock debugging checks is to run 'make menuconfig' and enable the required options under the "Kernel hacking" section.

...

If above configuration is all that I need, then should I be seeing warning/error messages in kernel logs(/var/log/kern.log) when there is inconsistency in locking ? To test my hypothesis, I modified my simple kernel module to deliberately induce locking error (After initializing read-write semaphore, I call down_write() and do not free this semaphore lock by commenting out up_write() invocation). But still I don't see any error or warning message trace in kernel logs, I think, I'm missing something.

Hi Srivatsa,

Thank you for your mail. As per your suggestion, this time I've enabled CONFIG_LOCKDEP aslo in my running kernel and did the same experiment, but still I dont't see any warning/error messages in the kernel log. To give you more idea about what I'm doing, Please see the code below.(This is a simple char driver based on LDD3 examples)

<echo.c>

#include <linux/module.h> #include <linux/init.h> #include <linux/types.h> //MAJOR, MINOR #include <linux/fs.h> //register_chrdev_region, file_operations #include <linux/moduleparam.h> #include <linux/kernel.h> //container_of #include <linux/slab.h> //kmalloc #include <linux/cdev.h> //struct cdev #include <linux/version.h> #include <linux/uaccess.h> //copy_from/to_user() #include <linux/errno.h> //error code

ssize_t echo_read(struct file *, char __user *, size_t, loff_t *); ssize_t echo_write(struct file *, const char __user *, size_t, loff_t *); int echo_open(struct inode *, struct file *); int echo_release(struct inode *, struct file *);

struct echo_cdev {         char *data;         unsigned long size; //amount of data stored         struct semaphore sem;         struct cdev cdev; }; MODULE_LICENSE("GPL v2"); MODULE_AUTHOR("amit");

int nr_major; module_param(nr_major, int, S_IRUGO); MODULE_PARM_DESC(nr_major, "major number");

int nr_minor; char *chrdev_name = "echo";

static dev_t device; static int echo_dev_count = 1; struct echo_cdev *echo_dev = NULL;

static struct file_operations echo_fs_ops = {         .open = echo_open,         .release = echo_release,         .read = echo_read,         .write = echo_write,         .owner = THIS_MODULE, };

int echo_open(struct inode *inode, struct file *filp) {         struct echo_cdev *dev;         pr_debug("%s: f_flags: 0x%x\n",__FUNCTION__,filp->f_flags);         //container_of(pointer, container_type, container_field);         dev = container_of(inode->i_cdev, struct echo_cdev, cdev);         filp->private_data = dev;         if ((filp->f_flags & O_ACCMODE) == O_WRONLY) {                 //trim the device size to 0                 dev->size = 0;         }         return 0; }

int echo_release(struct inode *inode, struct file *filp) {         return 0; }

ssize_t echo_read(struct file *filp, char __user *ubuff, size_t count, loff_t *poffset) {         struct echo_cdev *dev = filp->private_data;         pr_debug("%s: f_flags: 0x%x\n",__FUNCTION__,filp->f_flags);

        //user trying to access an offset which is beyond the end of file         if (down_interruptible(&dev->sem))                 return -ERESTARTSYS;         if (*poffset >= dev->size) {                 up(&dev->sem);                 return 0;         }

        //user trying to access more than eof, return bytes read till the eof         if (*poffset + count >= dev->size)                 //count = dev->size - *poffset;                 count = dev->size;         //kspace --> uspace         if (copy_to_user(ubuff, (dev->data + *poffset), count) < 0) {                 up(&dev->sem);                 return -EFAULT;         }         //update the offset         *poffset += count;         up(&dev->sem);         return count; }

//count is the size of requested data transfer ssize_t echo_write(struct file *filp, const char __user *ubuff, size_t count, loff_t *poffset) {         int ret;         struct echo_cdev *dev = filp->private_data;         pr_debug("%s: f_flags: 0x%x\n",__FUNCTION__,filp->f_flags);         if (down_interruptible(&dev->sem))                 return -ERESTARTSYS;         if (dev->data == NULL) {                 dev->data = (char *)kmalloc(count, GFP_KERNEL);                 if (!dev->data) {                         up(&dev->sem);                         return -ENOMEM;                 } else {                         memset(dev->data, 0, sizeof(count));                 }         }         dev->size = count;         //uspace --> kspace         if (copy_from_user(dev->data, ubuff, count) < 0) {                 up(&dev->sem);                 return -EFAULT;         }

        *poffset += count;         ret = count;

        if (dev->size < *poffset)                 dev->size = *poffset;         //Force lock error         //up(&dev->sem);         return ret; }

static int __init echo_init(void) {         int ret;         printk(KERN_EMERG "entering %s\n",__FUNCTION__);         //let the user provide the major number.         if (nr_major) {                 device = MKDEV(nr_major, nr_minor);                 if ((ret = register_chrdev_region(device, echo_dev_count, chrdev_name)) < 0) {                         pr_debug("%s: failed to register %s\n",__FUNCTION__,                                         chrdev_name);                         return ret;                 }         } else {                 ret = alloc_chrdev_region(&device, 0, echo_dev_count, chrdev_name);                 if (ret < 0) {                         pr_debug("%s: failed to register %s\n",__FUNCTION__,                                         chrdev_name);                         return ret;                 }         }         nr_major = MAJOR(device);         nr_minor = MINOR(device);         //print the major and minor numbers         pr_debug("%s: major/minor:: %d/%d\n",__FUNCTION__,                         nr_major, nr_minor);         echo_dev = (struct echo_cdev *)kmalloc(sizeof(struct echo_cdev), GFP_KERNEL);         if (!echo_dev) {                 printk(KERN_EMERG "Not enough memory\n");                 unregister_chrdev_region(device, echo_dev_count);                 return -ENOMEM;         }         memset(echo_dev, 0, sizeof(struct echo_cdev));         echo_dev->cdev.owner = THIS_MODULE;         echo_dev->cdev.ops = &echo_fs_ops;         //initialize the semaphore, before it is presented to the world         sema_init(&echo_dev->sem,1);         cdev_init(&echo_dev->cdev, &echo_fs_ops);         device = MKDEV(nr_major, nr_minor);         //tell the kernel about this char device         //telling the VFS layer to associate echo driver's fs operation for file r/w etc.         ret = cdev_add(&echo_dev->cdev, device, 1);         if (ret) {                 kfree(echo_dev);                 unregister_chrdev_region(device, echo_dev_count);                 return ret;         }         return 0; }

static void __exit echo_exit(void) {         printk(KERN_EMERG "entering %s\n",__FUNCTION__);         if (echo_dev->data) {                 printk("Inside %s: kfree()\n",__FUNCTION__);                 kfree(echo_dev->data);         }         cdev_del(&echo_dev->cdev);         kfree(echo_dev);         unregister_chrdev_region(device, echo_dev_count); }

module_init(echo_init); module_exit(echo_exit);

<echo.c>

<Makefile> obj-m := echo.o CFLAGS_echo.o := -DDEBUG -Wall -Werror -Wmissing-prototypes \         -Wstrict-prototypes -Wunused-variable -O2 \         -Wunused-function -g

modules:         make -C /lib/modules/`uname -r`/build M=`pwd` clean:         make -C /lib/modules/`uname -r`/build M=`pwd` clean <Makefile>

Logs: root@ubuntu:/boot# egrep -i "debug_kernel|lockdep" config-3.7.0-rc3-next-20121029 CONFIG_LOCKDEP_SUPPORT=y CONFIG_DEBUG_KERNEL=y CONFIG_LOCKDEP=y # CONFIG_DEBUG_LOCKDEP is not set

root@ubuntu:/home/amit/ldd3/misc-modules/echo# uname -a Linux ubuntu 3.7.0-rc3-next-20121029 #1 SMP Mon Oct 29 21:42:20 PDT 2012 i686 i686 i386 GNU/Linux

root@ubuntu:/home/amit/ldd3/misc-modules/echo# dmesg

root@ubuntu:/home/amit/ldd3/misc-modules/echo# insmod echo.ko

root@ubuntu:/home/amit/ldd3/misc-modules/echo# dmesg [ 1156.704072] entering echo_init [ 1156.704914] echo_init: major/minor:: 249/0

root@ubuntu:/home/amit/ldd3/misc-modules/echo# mknod /dev/echo c 249 0

root@ubuntu:/home/amit/ldd3/misc-modules/echo# ll /dev/echo crw-r--r-- 1 root root 249, 0 Oct 29 22:29 /dev/echo

root@ubuntu:/home/amit/ldd3/misc-modules/echo# echo "kernel newbiee" >/dev/echo

root@ubuntu:/home/amit/ldd3/misc-modules/echo# dmesg [ 1156.704072] entering echo_init [ 1156.704914] echo_init: major/minor:: 249/0 [ 1237.377205] echo_open: f_flags: 0x8241 [ 1237.377392] echo_write: f_flags: 0x8001

root@ubuntu:/home/amit/ldd3/misc-modules/echo# cat /dev/echo --> Here the driver read routine gets stuck as I've not reliquished the semaphore lock

root@ubuntu:/home/amit/ldd3/misc-modules/echo# cat /dev/echo ^C <-- killing the user process

root@ubuntu:/home/amit/ldd3/misc-modules/echo# rmmod echo

root@ubuntu:/home/amit/ldd3/misc-modules/echo# dmesg [ 1156.704072] entering echo_init [ 1156.704914] echo_init: major/minor:: 249/0 [ 1237.377205] echo_open: f_flags: 0x8241 [ 1237.377392] echo_write: f_flags: 0x8001 [ 1270.622337] echo_open: f_flags: 0x8000 [ 1270.622477] echo_read: f_flags: 0x8000 [ 1394.180962] entering echo_exit [ 1394.180996] Inside echo_exit: kfree()

As you can see, no warning/error messages reported by kernel. -Amit

_______________________________________________ Kernelnewbies mailing list Kernelnewbies@kernelnewbies.org http://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies

Hi I've not tried your module, but I suppose that you should get warning as soon as you try to take write semaphore once again. Best wishes Vladimir Murzin _______________________________________________ Kernelnewbies mailing list Kernelnewbies@kernelnewbies.org http://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies