[PATCH] slub: Fix misleading 'age' in verbose slub prints

[PATCH] slub: Fix misleading 'age' in verbose slub prints

[Chintan Pandya]

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.

Signed-off-by: Chintan Pandya <cpandya@codeaurora.org>
---
 mm/slub.c | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/mm/slub.c b/mm/slub.c
index e381728..b173f85 100644
--- a/mm/slub.c
+++ b/mm/slub.c
@@ -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;
-- 
Qualcomm India Private Limited, on behalf of Qualcomm Innovation
Center, Inc., is a member of Code Aurora Forum, a Linux Foundation
Collaborative Project

[PATCH] slub: Fix misleading 'age' in verbose slub prints

[Chintan Pandya]

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.

Signed-off-by: Chintan Pandya <cpandya@codeaurora.org>
---
 mm/slub.c | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/mm/slub.c b/mm/slub.c
index e381728..b173f85 100644
--- a/mm/slub.c
+++ b/mm/slub.c
@@ -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;
-- 
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 majordomo@kvack.org.  For more info on Linux MM,
see: http://www.linux-mm.org/ .
Don't email: <a href=mailto:"dont@kvack.org"> email@kvack.org </a>

Re: [PATCH] slub: Fix misleading 'age' in verbose slub prints

[Christopher Lameter]

On Wed, 7 Mar 2018, Chintan Pandya wrote:

> 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?

> 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?

Re: [PATCH] slub: Fix misleading 'age' in verbose slub prints

[Christopher Lameter]

On Wed, 7 Mar 2018, Chintan Pandya wrote:

> 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?

> 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 majordomo@kvack.org.  For more info on Linux MM,
see: http://www.linux-mm.org/ .
Don't email: <a href=mailto:"dont@kvack.org"> email@kvack.org </a>

Re: [PATCH] slub: Fix misleading 'age' in verbose slub prints

[Matthew Wilcox]

On Wed, Mar 07, 2018 at 12:13:56PM -0600, Christopher Lameter wrote:
> On Wed, 7 Mar 2018, Chintan Pandya wrote:
> > 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?
> 
> > 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.

Re: [PATCH] slub: Fix misleading 'age' in verbose slub prints

[Matthew Wilcox]

On Wed, Mar 07, 2018 at 12:13:56PM -0600, Christopher Lameter wrote:
> On Wed, 7 Mar 2018, Chintan Pandya wrote:
> > 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?
> 
> > 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 majordomo@kvack.org.  For more info on Linux MM,
see: http://www.linux-mm.org/ .
Don't email: <a href=mailto:"dont@kvack.org"> email@kvack.org </a>

Re: [PATCH] slub: Fix misleading 'age' in verbose slub prints

[Chintan Pandya]

On 3/7/2018 11:52 PM, Matthew Wilcox wrote:
> On Wed, Mar 07, 2018 at 12:13:56PM -0600, Christopher Lameter wrote:
>> On Wed, 7 Mar 2018, Chintan Pandya wrote:
>>> 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?
>>
>>> 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.
> 
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
-- 
Qualcomm India Private Limited, on behalf of Qualcomm Innovation Center,
Inc. is a member of the Code Aurora Forum, a Linux Foundation
Collaborative Project

Re: [PATCH] slub: Fix misleading 'age' in verbose slub prints

[Christopher Lameter]

On Thu, 8 Mar 2018, Chintan Pandya wrote:

> > 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.