Messages in this thread | | | Date | Wed, 7 Mar 2018 10:22:12 -0800 | From | Matthew Wilcox <> | Subject | Re: [PATCH] slub: Fix misleading 'age' in verbose slub prints |
| |
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.
| |