[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]
Message-ID: <20140501115042.GC13658@twins.programming.kicks-ass.net>
Date: Thu, 1 May 2014 13:50:42 +0200
From: Peter Zijlstra <peterz@...radead.org>
To: Thomas Gleixner <tglx@...utronix.de>
Cc: Vince Weaver <vincent.weaver@...ne.edu>,
Ingo Molnar <mingo@...nel.org>, linux-kernel@...r.kernel.org,
Steven Rostedt <rostedt@...dmis.org>
Subject: Re: [perf] more perf_fuzzer memory corruption
On Thu, May 01, 2014 at 12:26:02PM +0200, Peter Zijlstra wrote:
> On Thu, May 01, 2014 at 12:51:33AM +0200, Thomas Gleixner wrote:
> > And that's the issue which puzzles us. Let's look at what we expect:
> >
> > Now the trace shows a different story:
> >
> > perf_fuzzer-4387 [001] 1802.628659: sys_enter: NR 298 (69bb58, 0, ffffffff, 12, 0, 0)
>
> That's a per-cpu event (.pid = -1, .cpu = 12), they don't get inherited,
> so the only thing keeping it alive is the fd the child got. So
> exit_files() killing this thing makes perfect sense.
>
> Onwards to find another funny.
awk '/alloc/ {
for(i=1; i<=NF; i++) {
if ($i ~ /^ptr=/) {
ptr=gensub("^ptr=","","g",$i);
if (ptr ~ /nil/) break;
seen[ptr]=1;
m = ++memory[ptr];
if (m != 1) {
printf "alloc: %d ptr=%s\n", m, ptr;
memory[ptr] = 0;
}
break;
}
}
}
/free/ {
for(i=1; i<=NF; i++) {
if ($i ~ /^ptr=/) {
ptr=gensub("^ptr=","","g",$i);
if (ptr ~ /nil/)
break;
m = --memory[ptr];
if (m != 0) {
memory[ptr] = 0;
s = seen[ptr];
seen[ptr] = 1;
if (!s)
break;
printf "free: %d ptr=%s\n", m, ptr;
}
break;
}
}
}' bug.out | less
Gives fun things like:
alloc: 2 ptr=0xffff880118fda000
free: -1 ptr=0xffff880118fda000
alloc: 2 ptr=0xffff880118fda000
And if we then look at
grep ptr=0xffff880118fda000 bug.out | less
We find lovely bits such as:
perf_fuzzer-4387 [001] 1773.427175: kmalloc: (perf_event_alloc+0x5a) call_site=ffffffff8113a8fa ptr=0xffff880118fda000 bytes_req=1272 bytes_alloc=2048 gfp_flags=GFP_KERNEL|GFP_ZERO
ksoftirqd/6-38 [006] 1773.457770: kfree: (free_event_rcu+0x2f) call_site=ffffffff8113177f ptr=0xffff880118fda000
<idle>-0 [007] 1774.020378: kfree: (free_event_rcu+0x2f) call_site=ffffffff8113177f ptr=0xffff880118fda000
perf_fuzzer-4387 [000] 1774.096354: kmalloc: (perf_event_alloc+0x5a) call_site=ffffffff8113a8fa ptr=0xffff880118fda000 bytes_req=1272 bytes_alloc=2048 gfp_flags=GFP_KERNEL|GFP_ZERO
That's almost half a second between the double free, Vince, is your TSC
solid?
# grep sched_clock_stable /proc/sched_debug
sched_clock_stable() : 1
Should tell, if that's a 0 reading the trace becomes a whole lot more
'interesting'.
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@...r.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/
Powered by blists - more mailing lists