[lttng-dev] current_thread_info() not respecting program order with gcc 4.8.x

Mathieu Desnoyers mathieu.desnoyers at efficios.com
Fri Nov 22 08:02:26 EST 2013 

----- Original Message -----

> From: "Luis Lozano" <llozano at chromium.org>
> To: "Mathieu Desnoyers" <mathieu.desnoyers at efficios.com>
> Cc: "Jakub Jelinek" <jakub at redhat.com>, "Alexander Holler"
> <holler at ahsoftware.de>, "Linus Torvalds" <torvalds at linux-foundation.org>,
> "Richard Henderson" <rth at twiddle.net>, "Linux Kernel Mailing List"
> <linux-kernel at vger.kernel.org>, "Will Deacon" <will.deacon at arm.com>,
> "Catalin Marinas" <catalin.marinas at arm.com>, "Peter Zijlstra"
> <peterz at infradead.org>, lttng-dev at lists.lttng.org, "Nathan Lynch"
> <Nathan_Lynch at mentor.com>, "Paul E. McKenney" <paulmck at linux.vnet.ibm.com>,
> "Andrew Morton" <akpm at linux-foundation.org>, "Bhaskar Janakiraman"
> <bjanakiraman at chromium.org>, "Han Shen" <shenhan at chromium.org>
> Sent: Friday, November 22, 2013 3:16:27 AM
> Subject: Re: current_thread_info() not respecting program order with gcc
> 4.8.x

> On Thu, Nov 21, 2013 at 7:38 PM, Mathieu Desnoyers <
> mathieu.desnoyers at efficios.com > wrote:

> > ----- Original Message -----
> 
> > > From: "Luis Lozano" < llozano at google.com >
> 
> > > To: "Mathieu Desnoyers" < mathieu.desnoyers at efficios.com >
> 
> > > Cc: "Jakub Jelinek" < jakub at redhat.com >, "Alexander Holler" <
> > > holler at ahsoftware.de >, "Linus Torvalds"
> 
> > > < torvalds at linux-foundation.org >, "Richard Henderson" < rth at twiddle.net
> > > >,
> > > "Linux Kernel Mailing List"
> 
> > > < linux-kernel at vger.kernel.org >, "Will Deacon" < will.deacon at arm.com >,
> > > "Catalin Marinas" < catalin.marinas at arm.com >,
> 
> > > "Peter Zijlstra" < peterz at infradead.org >, lttng-dev at lists.lttng.org ,
> > > "Nathan Lynch" < Nathan_Lynch at mentor.com >, "Paul
> 
> > > E. McKenney" < paulmck at linux.vnet.ibm.com >, "Andrew Morton" <
> > > akpm at linux-foundation.org >, "Bhaskar Janakiraman"
> 
> > > < bjanakiraman at chromium.org >, "Han Shen" < shenhan at chromium.org >
> 
> > > Sent: Thursday, November 21, 2013 9:36:27 PM
> 
> > > Subject: Re: current_thread_info() not respecting program order with gcc
> > > 4.8.x
> 
> > >
> 
> > > Hi Mathieu,
> 
> > >
> 
> > > Yes the problem we were seeing with GCC bug 58854 is that an interrupt
> 
> > > handler was corrupting the stack of a routine which had an invalid
> 
> > > value of SP (not really on "top" of the stack) for part of the
> 
> > > routine.
> 
> > > But in the assembly code you sent, I don't see where sp is being
> 
> > > modified... or where the access to "below" sp is happening.
> 

> > The following instruction
> 

> > f1c: e50b1048 str r1, [fp, #-72] ; 0xffffffb8
> 

> > appears in the assembly generated by gcc 4.8.2, but not in the one
> 
> > generated by 4.7.3, which makes me wonder if it's good or not.
> 
> It is there in 4.7.3 just a few lines difference.
> I don't see any meaningful difference between the 2 assembly snippets...
> Just instructions ordered a little different?

Assembly generated by 4.7.3 vs 4.8.2 are much more different. 

The diff I've presented yesterday is between 4.8.2 and 4.8.2+barrier() at the end of 
the function error path. When I can get a cross compiler to work, I will send out more 
the complete assembly listings of the function. 

Thanks, 

Mathieu 

> Luis

> > With
> 
> > slightly different build output from the diff (probably a different config
> 
> > from Nathan), the first function instructions look like:
> 

> > 00000efc <lttng_event_reserve>:
> 
> > efc: e1a0c00d mov ip, sp
> 
> > f00: e92ddff0 push {r4, r5, r6, r7, r8, r9, sl, fp, ip, lr, pc}
> 
> > f04: e24cb004 sub fp, ip, #4
> 
> > f08: e24dd03c sub sp, sp, #60 ; 0x3c
> 
> > f0c: e52de004 push {lr} ; (str lr, [sp, #-4]!)
> 
> > f10: ebfffffe bl 0 <__gnu_mcount_nc>
> 
> > f14: e5903000 ldr r3, [r0]
> 
> > f18: e1a04000 mov r4, r0
> 
> > f1c: e1a0000d mov r0, sp
> 
> > f20: e5936030 ldr r6, [r3, #48] ; 0x30
> 
> > f24: e3c03d7f bic r3, r0, #8128 ; 0x1fc0
> 
> > f28: e3c3303f bic r3, r3, #63 ; 0x3f
> 
> > f2c: e50b104c str r1, [fp, #-76] ; 0xffffffb4
> 
> > f30: e5932004 ldr r2, [r3, #4]
> 
> > f34: e2822001 add r2, r2, #1
> 
> > f38: e5832004 str r2, [r3, #4]
> 
> > f3c: ebfffffe bl 0 <debug_smp_processor_id>
> 
> > f40: e59f2e44 ldr r2, [pc, #3652] ; 1d8c <lttng_event_reserve+0xe90>
> 
> > f44: e59f3e44 ldr r3, [pc, #3652] ; 1d90 <lttng_event_reserve+0xe94>
> 
> > f48: e7921100 ldr r1, [r2, r0, lsl #2]
> 
> > f4c: e1a05000 mov r5, r0
> 
> > f50: e7932001 ldr r2, [r3, r1]
> 

> > My rusty ARM assembler knowledge analyzes this like:
> 

> > ip = sp (ip being the scratch register)
> 
> > push 11 registers * 4 bytes = 44 bytes onto the stack
> 
> > fp = ip - 4
> 
> > sp = sp - 60 (sp = ip - 104)
> 
> > push {lr} bl
> 
> > 0 <__gnu_mcount_nc> (dynamically patched to a pop {lr})
> 
> > [...]
> 
> > store r1 into mem location fp - 76
> 

> > So yes, it does look like the -76 from fp is within the stack.
> 

> > > In GCC bug 58854 it was pretty clear that the restore of the sp
> 
> > > register in the epilogue is moved to somewhere close to the prologue
> 
> > > of the routine.
> 
> > > Are we missing some diffs from the assembly comparison?
> 

> > My next step is to setup my own 4.8.2 ARM cross-compiler. I've tried this
> > morning,
> 
> > did not manage to get one working even after following 2 howtos, trying
> > with
> > Debian
> 
> > packages, etc. Nathan told me this diff was the full comparison between the
> > two
> 
> > functions, but you'll understand that at this point I want to reproduce
> 
> > everything myself, because this is a _weird_ issue.
> 

> > But after a long day of debugging, it's time for some sleep. I will get
> > back
> > to this
> 
> > tomorrow,
> 

> > Thanks,
> 

> > Mathieu
> 

> > >
> 
> > > Thanks
> 
> > >
> 
> > > Luis
> 
> > >
> 
> > >
> 
> > >
> 
> > >
> 
> > > On Thu, Nov 21, 2013 at 5:57 PM, Mathieu Desnoyers
> 
> > > < mathieu.desnoyers at efficios.com > wrote:
> 
> > > > ----- Original Message -----
> 
> > > >> From: "Jakub Jelinek" < jakub at redhat.com >
> 
> > > >> To: "Luis Lozano" < llozano at google.com >
> 
> > > >> Cc: "Alexander Holler" < holler at ahsoftware.de >, "Linus Torvalds"
> 
> > > >> < torvalds at linux-foundation.org >, "Mathieu Desnoyers"
> 
> > > >> < mathieu.desnoyers at efficios.com >, "Richard Henderson" <
> > > >> rth at twiddle.net >,
> 
> > > >> "Linux Kernel Mailing List"
> 
> > > >> < linux-kernel at vger.kernel.org >, "Will Deacon" < will.deacon at arm.com
> > > >> >,
> 
> > > >> "Catalin Marinas" < catalin.marinas at arm.com >,
> 
> > > >> "Peter Zijlstra" < peterz at infradead.org >, lttng-dev at lists.lttng.org ,
> 
> > > >> "Nathan Lynch" < Nathan_Lynch at mentor.com >, "Paul
> 
> > > >> E. McKenney" < paulmck at linux.vnet.ibm.com >, "Andrew Morton"
> 
> > > >> < akpm at linux-foundation.org >, "Bhaskar Janakiraman"
> 
> > > >> < bjanakiraman at chromium.org >, "Han Shen" < shenhan at chromium.org >
> 
> > > >> Sent: Thursday, November 21, 2013 7:39:04 PM
> 
> > > >> Subject: Re: current_thread_info() not respecting program order with
> > > >> gcc
> 
> > > >> 4.8.x
> 
> > > >>
> 
> > > >> On Thu, Nov 21, 2013 at 03:45:35PM -0800, Luis Lozano wrote:
> 
> > > >> > I think we need a reproducer. Without this we may all be going on
> > > >> > the
> 
> > > >> > wrong path. This whole conversation started on an *assumption* that
> 
> > > >> > some accesses were being reordered.
> 
> > > >> >
> 
> > > >> > evidence of the reorder or reproducer please?
> 
> > > >>
> 
> > > >> Yeah, if a compiler bug is suspected, can anybody please open
> 
> > > >> a bugreport in http://gcc.gnu.org/bugzilla/ with the preprocessed
> > > >> source,
> 
> > > >> compiler version, flags and how it was configured and some hint in
> > > >> which
> 
> > > >> function to look for what exactly? We don't necessarily need a runtime
> 
> > > >> small reproducer, but if it can be shown in the assembly what has been
> 
> > > >> reordered and why you think it shouldn't, with the above mentioned
> > > >> input
> 
> > > >> that ought to be sufficient. Thanks.
> 
> > > >
> 
> > > > OK OK, let me reply on list first so I can share the result of a full
> > > > day
> 
> > > > of bug hunting. We're not there yet, but many options have been
> > > > eliminated.
> 
> > > >
> 
> > > > The issue shows up in stress test, when tracing with lttng-modules
> > > > 2.4-rc1,
> 
> > > > on ARM. It's been reproduced with a Linux kernel 3.12 so far, with
> 
> > > > lttng-modules
> 
> > > > compiled against that kernel.
> 
> > > >
> 
> > > > First, I asked Nathan to compile his kernel with gcc 4.7, and
> > > > lttng-modules
> 
> > > > with gcc 4.8.x (and vice-versa). The problem only appears when
> 
> > > > lttng-modules
> 
> > > > are compiled with gcc 4.8.x. The compiler version used to compile the
> > > > rest
> 
> > > > of the kernel does not matter.
> 
> > > >
> 
> > > > Then I looked at gcc 4.8 changelog for ARM, new feature:
> 
> > > > -fno-sched-pressure
> 
> > > > (sched pressure is there by default). Nathan tried compiling
> > > > lttng-modules
> 
> > > > with
> 
> > > > -fno-sched-pressure. The problem still reproduces.
> 
> > > >
> 
> > > > Knowing that adding barrier() outside of preempt_disable()/enable() was
> 
> > > > fixing the issue, we tried identifying which code location was
> > > > responsible
> 
> > > > for working around the issue. Skipping a long investigation, here is
> > > > the
> 
> > > > executive summary:
> 
> > > >
> 
> > > > http://git.lttng.org/?p=lttng-modules.git;a=blob;f=lttng-ring-buffer-client.h;h=50c47b3bf49f6c2dd24e250cf1a9b97808cd8e27;hb=HEAD
> 
> > > >
> 
> > > > Has the following function. We identified that adding a barrier() as
> > > > shown
> 
> > > > below
> 
> > > > works around the issue:
> 
> > > >
> 
> > > > static
> 
> > > > int lttng_event_reserve(struct lib_ring_buffer_ctx *ctx,
> 
> > > > uint32_t event_id)
> 
> > > > {
> 
> > > > struct lttng_channel *lttng_chan = channel_get_private(ctx->chan);
> 
> > > > int ret, cpu;
> 
> > > >
> 
> > > > cpu = lib_ring_buffer_get_cpu(&client_config);
> 
> > > > if (cpu < 0)
> 
> > > > return -EPERM;
> 
> > > > ctx->cpu = cpu;
> 
> > > >
> 
> > > > switch (lttng_chan->header_type) {
> 
> > > > case 1: /* compact */
> 
> > > > if (event_id > 30)
> 
> > > > ctx->rflags |= LTTNG_RFLAG_EXTENDED;
> 
> > > > break;
> 
> > > > case 2: /* large */
> 
> > > > if (event_id > 65534)
> 
> > > > ctx->rflags |= LTTNG_RFLAG_EXTENDED;
> 
> > > > break;
> 
> > > > default:
> 
> > > > WARN_ON_ONCE(1);
> 
> > > > }
> 
> > > >
> 
> > > > ret = lib_ring_buffer_reserve(&client_config, ctx);
> 
> > > > if (ret)
> 
> > > > goto put;
> 
> > > > lttng_write_event_header(&client_config, ctx, event_id);
> 
> > > > return 0;
> 
> > > > put:
> 
> > > > lib_ring_buffer_put_cpu(&client_config);
> 
> > > > ---------------> barrier() added here;
> 
> > > > <----------------------------
> 
> > > > return ret;
> 
> > > > }
> 
> > > >
> 
> > > > Where barrier() is the usual asm volatile with "memory" clobber,
> > > > nothing
> 
> > > > else.
> 
> > > >
> 
> > > > Nathan gave me the binary diff for the assembly generated for this
> > > > function
> 
> > > > without
> 
> > > > the barrier and with the barrier:
> 
> > > >
> 
> > > > --- /tmp/lttng_event_reserve-4.8.2.dump 2013-11-21 11:14:14.536495079
> > > > -0600
> 
> > > > +++ /tmp/lttng_event_reserve-with-barrier-4.8.2.dump 2013-11-21
> 
> > > > 14:12:52.997355907 -0600
> 
> > > > @@ -7,11 +7,11 @@
> 
> > > > f10: ebfffffe bl 0 <__gnu_mcount_nc>
> 
> > > > f14: e5903000 ldr r3, [r0]
> 
> > > > f18: e1a04000 mov r4, r0
> 
> > > > - f1c: e50b1048 str r1, [fp, #-72] ; 0xffffffb8
> 
> > > > + f1c: e1a0000d mov r0, sp
> 
> > > > f20: e5936030 ldr r6, [r3, #48] ; 0x30
> 
> > > > - f24: e1a0000d mov r0, sp
> 
> > > > - f28: e3c03d7f bic r3, r0, #8128 ; 0x1fc0
> 
> > > > - f2c: e3c3303f bic r3, r3, #63 ; 0x3f
> 
> > > > + f24: e3c03d7f bic r3, r0, #8128 ; 0x1fc0
> 
> > > > + f28: e3c3303f bic r3, r3, #63 ; 0x3f
> 
> > > > + f2c: e50b1048 str r1, [fp, #-72] ; 0xffffffb8
> 
> > > > f30: e5932004 ldr r2, [r3, #4]
> 
> > > > f34: e2822001 add r2, r2, #1
> 
> > > > f38: e5832004 str r2, [r3, #4]
> 
> > > > @@ -53,7 +53,7 @@
> 
> > > > fc8: e3c3303f bic r3, r3, #63 ; 0x3f
> 
> > > > fcc: e5933000 ldr r3, [r3]
> 
> > > > fd0: e3130002 tst r3, #2
> 
> > > > - fd4: 0a000000 beq fdc <lttng_event_reserve+0xe0>
> 
> > > > + fd4: 0a0002be beq 1ad4 <lttng_event_reserve+0xbd8>
> 
> > > > fd8: ebfffffe bl 0 <preempt_schedule>
> 
> > > > fdc: ea0002bc b 1ad4 <lttng_event_reserve+0xbd8>
> 
> > > > fe0: e3500000 cmp r0, #0
> 
> > > >
> 
> > > > We tried disabling the ftrace function tracing to get mcount out of the
> 
> > > > way,
> 
> > > > and the problem still reproduces.
> 
> > > >
> 
> > > > I'm stopping here in terms of details about the disassembly, because I
> 
> > > > need to double check with Nathan that I get the right disassembly for
> > > > the
> 
> > > > right
> 
> > > > cases. I also terribly need to setup a 4.8.2 ARM cross-compiler on my
> 
> > > > machine.
> 
> > > >
> 
> > > > I'm attaching Nathan's ARM configuration.
> 
> > > >
> 
> > > > It does look behave a bit like this bug pointed out by Luis:
> 
> > > >
> 
> > > > http://gcc.gnu.org/bugzilla/show_bug.cgi?id=58854
> 
> > > >
> 
> > > > AFAIU (please correct me if I am wrong), ARM's interrupt handler run
> 
> > > > on top of the thread stack (?). If it's the case, then anything stored
> 
> > > > on the stack below "sp" could be overwritten by an interrupt handler.
> 
> > > > This would fit well the reproduction scenario for this bug: Nathan runs
> 
> > > > LTTng tracing of kmem_cache_free tracepoint with hackbench running.
> 
> > > > A race between a short window of stack use below sp and interrupt
> > > > handlers
> 
> > > > would trigger with this kind of stress-test.
> 
> > > >
> 
> > > > Thoughts ?
> 
> > > >
> 
> > > > Thanks,
> 
> > > >
> 
> > > > Mathieu
> 
> > > >
> 
> > > >
> 
> > > > --
> 
> > > > Mathieu Desnoyers
> 
> > > > EfficiOS Inc.
> 
> > > > http://www.efficios.com
> 
> > >
> 
> > >
> 
> > >
> 
> > > --
> 
> > >
> 
> > > Luis A. Lozano | Software Engineer | llozano at google.com | +1
> > > (408)431-5164
> 
> > >
> 

> > --
> 
> > Mathieu Desnoyers
> 
> > EfficiOS Inc.
> 
> > http://www.efficios.com
> 

-- 
Mathieu Desnoyers 
EfficiOS Inc. 
http://www.efficios.com 
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.lttng.org/pipermail/lttng-dev/attachments/20131122/1a178f68/attachment-0001.html>

More information about the lttng-dev mailing list