[PATCH] ARM fix syscall trace return value

[PATCH] ARM fix syscall trace return value

[Mathieu Desnoyers]

Hi Russell,

I am currently finding core bugs in the Linux kernel implementation of
the ARM architecture. :-( e.g. return value not being sent to the
syscall_trace function upon exit (upon which LTTng depends). (patch
below)

This is _very_ silly because there is no dependency on the syscall being
executed, and the syscall_entry/syscall_exit events are recorded at the
_exact_ same time. Yes, I mean the _exact_ same time : using a clock
which consists of atomic_add_return monotonic increments, it seems like
ARM is able to return the _same_ value of an atomic increment return
*twice* !! I think the atomic.h primitives are broken and that they
allow concurrent modification of a given atomic variable by the pipeline.
It sounds weird, and I hope I am not crazy (just getting into the ARM
world..). ;) Any thoughts ? I'll try adding some barriers to see if it
helps.

BTW, the patch below applies to 2.6.29-rc4.

Mathieu


ARM fix syscall trace return value

I noticed that the arm syscall_trace, when called upon syscall return,
passes the system call number rather than the return value to
syscall_trace. This caused very very weird behavior with LTTng probably
due to pipeline effects, because there was no dependency on the
syscall return value. Therefore, we were seeing the syscall entry,
syscall exit events (with the _same_ timestamp ! Is it possible that
the ARM atomic increment return is not really atomic wrt such pipeline
effects ?), then followed by fs.open (which should clearly have
happened in between.

This patch modifies entry-common.S to pass the correct register
to syscall_trace upon system call exit.

Signed-off-by: Mathieu Desnoyers <mathieu.desnoyers@polymtl.ca>
CC: rmk@arm.linux.org.uk
CC: Eero Tamminen <eero.tamminen@nokia.com>
---
 arch/arm/kernel/entry-common.S |    3 ++-
 1 file changed, 2 insertions(+), 1 deletion(-)

Index: linux-omap-2.6/arch/arm/kernel/entry-common.S
===================================================================
--- linux-omap-2.6.orig/arch/arm/kernel/entry-common.S	2009-02-17 16:58:14.000000000 +0000
+++ linux-omap-2.6/arch/arm/kernel/entry-common.S	2009-02-17 17:24:33.000000000 +0000
@@ -89,6 +89,7 @@
 	mov	why, #1
 	tst	r1, #_TIF_SYSCALL_TRACE		@ are we tracing syscalls?
 	beq	ret_slow_syscall
+	mov	r2, #0				@ fork returns 0 to the child
 	mov	r1, sp
 	mov	r0, #1				@ trace exit [IP = 1]
 	bl	syscall_trace
@@ -292,7 +293,7 @@
 
 __sys_trace_return:
 	str	r0, [sp, #S_R0 + S_OFF]!	@ save returned r0
-	mov	r2, scno
+	mov	r2, r0
 	mov	r1, sp
 	mov	r0, #1				@ trace exit [IP = 1]
 	bl	syscall_trace

-- 
Mathieu Desnoyers
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F  BA06 3F25 A8FE 3BAE 9A68

Re: [PATCH] ARM fix syscall trace return value

[Russell King]

On Tue, Feb 17, 2009 at 01:18:05PM -0500, Mathieu Desnoyers wrote:
> I am currently finding core bugs in the Linux kernel implementation of
> the ARM architecture. :-( e.g. return value not being sent to the
> syscall_trace function upon exit (upon which LTTng depends). (patch
> below)

Well then how can strace work?  The fact of the matter is that strace
can and does work, and so I suspect that the problem is not in the
kernel but whatever "LTTng" is trying to do.

> BTW, the patch below applies to 2.6.29-rc4.

And is wrong.

> Index: linux-omap-2.6/arch/arm/kernel/entry-common.S
> ===================================================================
> --- linux-omap-2.6.orig/arch/arm/kernel/entry-common.S	2009-02-17 16:58:14.000000000 +0000
> +++ linux-omap-2.6/arch/arm/kernel/entry-common.S	2009-02-17 17:24:33.000000000 +0000
> @@ -89,6 +89,7 @@
>  	mov	why, #1
>  	tst	r1, #_TIF_SYSCALL_TRACE		@ are we tracing syscalls?
>  	beq	ret_slow_syscall
> +	mov	r2, #0				@ fork returns 0 to the child

This may be incorrect.

>  	mov	r1, sp
>  	mov	r0, #1				@ trace exit [IP = 1]
>  	bl	syscall_trace
> @@ -292,7 +293,7 @@
>  
>  __sys_trace_return:
>  	str	r0, [sp, #S_R0 + S_OFF]!	@ save returned r0
> -	mov	r2, scno
> +	mov	r2, r0

This part is wrong.  'r2' *is* the syscall number.

The place to get the return value is by reading the registers, r0 to be
exact.  No other method is supported.

-- 
Russell King
 Linux kernel    2.6 ARM Linux   - http://www.arm.linux.org.uk/
 maintainer of:

Re: [PATCH] ARM fix syscall trace return value

[Viktor Rosendahl]

On Tue, 2009-02-17 at 19:18 +0100, ext Mathieu Desnoyers wrote: 
> Hi Russell,
> 
> I am currently finding core bugs in the Linux kernel implementation of
> the ARM architecture. :-( e.g. return value not being sent to the
> syscall_trace function upon exit (upon which LTTng depends). (patch
> below)
> 
> This is _very_ silly because there is no dependency on the syscall being
> executed, and the syscall_entry/syscall_exit events are recorded at the
> _exact_ same time. Yes, I mean the _exact_ same time : using a clock
> which consists of atomic_add_return monotonic increments, it seems like
> ARM is able to return the _same_ value of an atomic increment return
> *twice* !! I think the atomic.h primitives are broken and that they
> allow concurrent modification of a given atomic variable by the pipeline.
> It sounds weird, and I hope I am not crazy (just getting into the ARM
> world..). ;) Any thoughts ? I'll try adding some barriers to see if it
> helps.

Hi Mathieu,

I am currently investigating a very similar behavior,
(syscall_entry/syscall_exit events having the exact same time in lttng).

However, I am using the CCNT (together with trace-clock-32-to-64.c) for
timestamping. This is, if I understand you correctly, a different clock
than the one you are using, not using atomic_add_return(). Thus, I
suspect that the reason for getting the exact same time for entry/exit
events might be something else than the clocks being broken. 

I have to admit that I cannot explain how it can happen though. Could it
be some weird problem in the lttng trace recording ?

best regards,

Viktor

Re: [PATCH] ARM fix syscall trace return value

[Mathieu Desnoyers]

* Viktor Rosendahl (Viktor.Rosendahl@nokia.com) wrote:
> On Tue, 2009-02-17 at 19:18 +0100, ext Mathieu Desnoyers wrote: 
> > Hi Russell,
> > 
> > I am currently finding core bugs in the Linux kernel implementation of
> > the ARM architecture. :-( e.g. return value not being sent to the
> > syscall_trace function upon exit (upon which LTTng depends). (patch
> > below)
> > 
> > This is _very_ silly because there is no dependency on the syscall being
> > executed, and the syscall_entry/syscall_exit events are recorded at the
> > _exact_ same time. Yes, I mean the _exact_ same time : using a clock
> > which consists of atomic_add_return monotonic increments, it seems like
> > ARM is able to return the _same_ value of an atomic increment return
> > *twice* !! I think the atomic.h primitives are broken and that they
> > allow concurrent modification of a given atomic variable by the pipeline.
> > It sounds weird, and I hope I am not crazy (just getting into the ARM
> > world..). ;) Any thoughts ? I'll try adding some barriers to see if it
> > helps.
> 
> Hi Mathieu,
> 
> I am currently investigating a very similar behavior,
> (syscall_entry/syscall_exit events having the exact same time in lttng).
> 
> However, I am using the CCNT (together with trace-clock-32-to-64.c) for
> timestamping. This is, if I understand you correctly, a different clock
> than the one you are using, not using atomic_add_return(). Thus, I
> suspect that the reason for getting the exact same time for entry/exit
> events might be something else than the clocks being broken. 
> 
> I have to admit that I cannot explain how it can happen though. Could it
> be some weird problem in the lttng trace recording ?
> 

I had the same result as you with the ccnt-based clock I am currently
developing, so I went back to a more "solid" and atomic
atomic_add_return clock. But I noticed that we still had entry/exit with
the same timestamps, so I was really unsure about what was happening,
because there is no trace corruption and because I have never, ever,
seen that kind of problem on any other architecture (x86, powerpc,
mips...). So I fixed the syscall_trace exit parameter, which now makes
sure there is a dependency on the return value. But I want to find out
why the atomic add return failed to be atomic in that particular
condition. I suspect there is a missing memory barrier in atomic.h.

Mathieu

> best regards,
> 
> Viktor
> 
> 

-- 
Mathieu Desnoyers
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F  BA06 3F25 A8FE 3BAE 9A68

Re: [PATCH] ARM fix syscall trace return value

[Russell King]

On Tue, Feb 17, 2009 at 02:30:15PM -0500, Mathieu Desnoyers wrote:
> I had the same result as you with the ccnt-based clock I am currently
> developing, so I went back to a more "solid" and atomic
> atomic_add_return clock. But I noticed that we still had entry/exit with
> the same timestamps, so I was really unsure about what was happening,
> because there is no trace corruption and because I have never, ever,
> seen that kind of problem on any other architecture (x86, powerpc,
> mips...). So I fixed the syscall_trace exit parameter,

Correction: you broke syscall_trace exit by corrupting the syscall number
stored in the thread_info.

> which now makes sure there is a dependency on the return value.

I've no idea what dependency you're talking about.  ARM is for the most
part a very simple architecture and doesn't really have any dependencies.
The only kind it has are those which are automatically fixed up by the
hardware (so a load followed by an immediate use causes a pipeline stall.)

So I really can't figure out what you're going on about.  On top of that
you're trying to make things do stuff in ways they weren't designed.  Your
bug report makes zero sense to me.

> But I want to find out
> why the atomic add return failed to be atomic in that particular
> condition. I suspect there is a missing memory barrier in atomic.h.

In a single CPU context, memory barriers to the same location on ARM
don't have any effect as far as program accesses are concerned.

So again we disagree.

So, how about you tell me exactly what you're doing, give me pointers to
whatever test is failing, tell me about your hardware that you're testing
on.

Until that happens, I'm disinclined to believe any of this reported "bug".

-- 
Russell King
 Linux kernel    2.6 ARM Linux   - http://www.arm.linux.org.uk/
 maintainer of:

Re: [PATCH] ARM fix syscall trace return value

[Mathieu Desnoyers]

* Russell King (rmk+lkml@arm.linux.org.uk) wrote:
> On Tue, Feb 17, 2009 at 02:30:15PM -0500, Mathieu Desnoyers wrote:
> > I had the same result as you with the ccnt-based clock I am currently
> > developing, so I went back to a more "solid" and atomic
> > atomic_add_return clock. But I noticed that we still had entry/exit with
> > the same timestamps, so I was really unsure about what was happening,
> > because there is no trace corruption and because I have never, ever,
> > seen that kind of problem on any other architecture (x86, powerpc,
> > mips...). So I fixed the syscall_trace exit parameter,
> 
> Correction: you broke syscall_trace exit by corrupting the syscall number
> stored in the thread_info.
> 

Having a second look, yes, you are right. It's the instrumentation that
has been sent to me which was wrongly expecting scno to contain the
return value. So my patch is incorrect.

> > which now makes sure there is a dependency on the return value.
> 
> I've no idea what dependency you're talking about.  ARM is for the most
> part a very simple architecture and doesn't really have any dependencies.
> The only kind it has are those which are automatically fixed up by the
> hardware (so a load followed by an immediate use causes a pipeline stall.)
> 
> So I really can't figure out what you're going on about.  On top of that
> you're trying to make things do stuff in ways they weren't designed.  Your
> bug report makes zero sense to me.
> 
> > But I want to find out
> > why the atomic add return failed to be atomic in that particular
> > condition. I suspect there is a missing memory barrier in atomic.h.
> 
> In a single CPU context, memory barriers to the same location on ARM
> don't have any effect as far as program accesses are concerned.
> 
> So again we disagree.
> 
> So, how about you tell me exactly what you're doing, give me pointers to
> whatever test is failing, tell me about your hardware that you're testing
> on.
> 
> Until that happens, I'm disinclined to believe any of this reported "bug".
> 

Looking at my trace-clock-32-to-64 code tells me I might have problems
specific to little endian machines. I'll review that.

Thanks for the answer,

Best regards,

Mathieu

> -- 
> Russell King
>  Linux kernel    2.6 ARM Linux   - http://www.arm.linux.org.uk/
>  maintainer of:

-- 
Mathieu Desnoyers
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F  BA06 3F25 A8FE 3BAE 9A68