slub: Fix misleading 'age' in verbose slub prints
Subsystems (2)
PATCH 1/1 slub: Fix misleading 'age' in verbose slub prints
When SLUB_DEBUG catches the some issues, it prints all the required debug info being verbose. However, in few cases where allocation and free of the object has have happened in a very short time, 'age' might mislead. See the example below,
[ 6044.137581] ============================================================================= [ 6044.145863] BUG kmalloc-256 (Tainted: G W O ): Poison overwritten [ 6044.152889] ----------------------------------------------------------------------------- [ 6044.152889] [ 6044.162618] INFO: 0xfffffff14956a878-0xfffffff14956a878. First byte 0x67 instead of 0x6b [ 6044.170804] INFO: Allocated in binder_transaction+0x4b0/0x2448 age=731 cpu=3 pid=5314 [ 6044.178711] __slab_alloc.isra.68.constprop.71+0x58/0x98 [ 6044.184070] kmem_cache_alloc_trace+0x198/0x2c4 [ 6044.188642] binder_transaction+0x4b0/0x2448 [ 6044.192953] binder_thread_write+0x998/0x1410 [ 6044.197350] binder_ioctl_write_read+0x130/0x370 [ 6044.202016] binder_ioctl+0x550/0x7dc [ 6044.205726] do_vfs_ioctl+0xcc/0x888 [ 6044.209510] SyS_ioctl+0x90/0xa4 [ 6044.212821] __sys_trace_return+0x0/0x4 [ 6044.216696] INFO: Freed in binder_free_transaction+0x2c/0x58 age=735 cpu=6 pid=2079 [ 6044.224415] kfree+0x28c/0x290 [ 6044.227505] binder_free_transaction+0x2c/0x58 [ 6044.231991] binder_transaction+0x1f78/0x2448 [ 6044.236392] binder_thread_write+0x998/0x1410 [ 6044.240789] binder_ioctl_write_read+0x130/0x370 [ 6044.245455] binder_ioctl+0x550/0x7dc [ 6044.249152] do_vfs_ioctl+0xcc/0x888 [ 6044.252772] SyS_ioctl+0x90/0xa4 [ 6044.256041] __sys_trace_return+0x0/0x4 [ 6044.259924] INFO: Slab 0xffffffbfc5255a00 objects=21 used=20 fp=0xfffffff14956a480 flags=0x4080 [ 6044.268695] INFO: Object 0xfffffff14956a780 @offset=10112 fp=0xfffffff149568680 ... [ 6044.494293] Object fffffff14956a870: 6b 6b 6b 6b 6b 6b 6b 6b 67 6b 6b 6b 6b 6b 6b a5 kkkkkkkkgkkkkkk.
In this case, object got freed later but 'age' shows otherwise. This could be because, while printing this info, we print allocation traces first and free traces thereafter. In between, if we get schedule out, (jiffies - t->when) could become meaningless.
So, simply print when the object was allocated/freed.
--- mm/slub.c | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-)
mm/slub.c +2 -2
@@ -603,8 +603,8 @@ static void print_track(const char *s, struct track *t)if (!t->addr)return ; -pr_err ("INFO: %s in %pS age=%lu cpu=%u pid=%d\n" , - s, (void *)t->addr, jiffies - t->when, t->cpu, t->pid); +pr_err ("INFO: %s in %pS when=%lu cpu=%u pid=%d\n" , + s, (void *)t->addr, t->when, t->cpu, t->pid);#ifdef CONFIG_STACKTRACE {int i;
Signature · 9 lines
Qualcomm India Private Limited, on behalf of Qualcomm Innovation Center, Inc., is a member of Code Aurora Forum, a Linux Foundation Collaborative Project -- To unsubscribe, send a message with 'unsubscribe linux-mm' in the body to [email protected]. For more info on Linux MM, see: http://www.linux-mm.org/ . Don't email: <a href=mailto:"[email protected]"> [email protected] </a>
Quoted 5 lines · Chintan Pandya
In this case, object got freed later but 'age' shows otherwise. This could be because, while printing this info, we print allocation traces first and free traces thereafter. In between, if we get schedule out, (jiffies -
t->when) could become meaningless.
Ok then get the jiffies earlier?
Quoted 1 line
So, simply print when the object was allocated/freed.
The tick value may not related to anything in the logs that is why the "age" is there. How do I know how long ago the allocation was if I look at the log and only see long and large number of ticks since bootup?
--
To unsubscribe, send a message with 'unsubscribe linux-mm' in the body to [email protected]. For more info on Linux MM,
see: http://www.linux-mm.org/ .
Don't email: <a href=mailto:"[email protected]"> [email protected] </a>
Quoted 7 lines · Christopher Lameter
Quoted 5 lines · Chintan Pandya
In this case, object got freed later but 'age' shows otherwise. This could be because, while printing this info, we print allocation traces first and free traces thereafter. In between, if we get schedule out, (jiffies -
t->when) could become meaningless.
Quoted 7 lines
Ok then get the jiffies earlier?
Quoted 1 line
So, simply print when the object was allocated/freed.
The tick value may not related to anything in the logs that is why the "age" is there. How do I know how long ago the allocation was if I look at the log and only see long and large number of ticks since bootup?
I missed that the first read-through too. The trick is that there are two printks:
[ 6044.170804] INFO: Allocated in binder_transaction+0x4b0/0x2448 age=731 cpu=3 pid=5314 ... [ 6044.216696] INFO: Freed in binder_free_transaction+0x2c/0x58 age=735 cpu=6 pid=2079
If you print the raw value, then you can do the subtraction yourself; if you've subtracted it from jiffies each time, you've at least introduced jitter, and possibly enough jitter to confuse and mislead.
--
To unsubscribe, send a message with 'unsubscribe linux-mm' in the body to [email protected]. For more info on Linux MM,
see: http://www.linux-mm.org/ .
Don't email: <a href=mailto:"[email protected]"> [email protected] </a>
Quoted 18 lines · Matthew Wilcox
Quoted 7 lines · Christopher Lameter
Quoted 5 lines · Chintan Pandya
In this case, object got freed later but 'age' shows otherwise. This could be because, while printing this info, we print allocation traces first and free traces thereafter. In between, if we get schedule out, (jiffies -
t->when) could become meaningless.Quoted 7 lines
Ok then get the jiffies earlier?
Quoted 1 line
So, simply print when the object was allocated/freed.
The tick value may not related to anything in the logs that is why the "age" is there. How do I know how long ago the allocation was if I look at the log and only see long and large number of ticks since bootup?
I missed that the first read-through too. The trick is that there are two printks:
Quoted 8 lines
[ 6044.170804] INFO: Allocated in binder_transaction+0x4b0/0x2448 age=731 cpu=3 pid=5314 ... [ 6044.216696] INFO: Freed in binder_free_transaction+0x2c/0x58 age=735 cpu=6 pid=2079If you print the raw value, then you can do the subtraction yourself; if you've subtracted it from jiffies each time, you've at least introduced jitter, and possibly enough jitter to confuse and mislead.
This is exactly what I was thinking. But looking up 'age' is easy compared to 'when' and this seems required as from Christopher's reply. So, will raise new patch cleaning commit message a bit.
Chintan
Signature · 3 lines
Qualcomm India Private Limited, on behalf of Qualcomm Innovation Center, Inc. is a member of the Code Aurora Forum, a Linux Foundation Collaborative Project
Quoted 7 lines · Chintan Pandya
Quoted 4 lines
If you print the raw value, then you can do the subtraction yourself; if you've subtracted it from jiffies each time, you've at least introduced jitter, and possibly enough jitter to confuse and mislead.
This is exactly what I was thinking. But looking up 'age' is easy compared to 'when' and this seems required as from Christopher's
reply. So, will raise new patch cleaning commit message a bit.
Well then you need to provide some sort of log text processor I think. Otherwise you need to get the object address from the log message, then scan back through the log to find the correct allocation entry, retrieve both jiffy values and subtract them. If the age is there then you can simply see how far in the past the object was allocated.
One advantage in favor of jiffies would be the ability to correlate multiple events if each log line would have a jiffies like timestamps.
But it does not. So I think outputting jiffies there is causing more problems that benefits.