trace_printk is doing weird things with my arguments

From: Josef Bacik
Date: Mon Dec 12 2011 - 13:59:54 EST


Hello,

I've been using trace_printk() to hash out where I want to put trace points so I
can do leak detection in the btrfs space accounting code. This has worked out
wonderfully, except in the case where I have trace_printk()'s towards the end of
umount() which is where everything gets freed up. After a lot of screwing
around I ended up with this in one of the functions

trace_printk("%pU is being released, fsinfo=%p\n", fs_info->fsid, fs_info);
printk(KERN_ERR "%pU is releaseing global_rsv\n", fs_info->fsid);

and then in my trace output I got this (I've cut the unnecessary line beginning)

0080880d-0488-ffff-0a0a-0a0a0a0a0a0a is being released, fsinfo=ffff88040d88b000

and in dmesg I got this

4e78b2a8-707a-4eef-97d5-11c0aa1b8f29 is releaseing global_rsv

The dmesg has the right fsid, and I have a ton of trace_printk()'s in
close_ctree() which is the function that we call from ->put_super, and all of
them will either randomly have the right fsid, they will all have the wrong
fsid, or some mixture, like half will have the right one but the last half will
not. The '0a' repeating thing is because i put a memset(fs_info, 0xa,
sizeof(*fsinfo)) in our freeing function because I thought we were screwing up,
but it looks like trace_printk is somehow not trying to fill in the arguments
until after the arguments have been freed, which seems wrong and is screwing me
up ;). Any thoughts? Thanks,

Josef
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/