VMI broken on tip/master...

VMI broken on tip/master...

[Alok Kataria]

Hi Peter, 

I was seeing a early fault when running tip/master with VMI enabled on
VMware platform. 
This early fault was in the vmi_patch code where we are applying
paravirt_alternatives. After some trials i noticed that this is
reproducible only with CONFIG_TRACING. With that disabled my VM boots
again. 

I started a git bisect after that, and git pointed to this as the bad
commit

commit 6cc3c6e12bb039047974ad2e7e2d46d15a1b762f
    trace_clock: fix preemption bug

I then reverted that commit from tip/master and the system did boot. 
But I fail to understand how this simple patch would be causing things
to fail in VMI. Any ideas ?

Thanks,
Alok

Re: VMI broken on tip/master...

[Peter Zijlstra]

On Fri, 2009-03-13 at 10:56 -0700, Alok Kataria wrote:
> Hi Peter, 
> 
> I was seeing a early fault when running tip/master with VMI enabled on
> VMware platform. 
> This early fault was in the vmi_patch code where we are applying
> paravirt_alternatives. After some trials i noticed that this is
> reproducible only with CONFIG_TRACING. With that disabled my VM boots
> again. 
> 
> I started a git bisect after that, and git pointed to this as the bad
> commit
> 
> commit 6cc3c6e12bb039047974ad2e7e2d46d15a1b762f
>     trace_clock: fix preemption bug
> 
> I then reverted that commit from tip/master and the system did boot. 
> But I fail to understand how this simple patch would be causing things
> to fail in VMI. Any ideas ?

Looking at arch/x86/include/asm/paravirt.h (god I wish paravirt would go
away, not only does it screw over ctags, it also hurts my brain), it
appears its playing icky games with primitives like
raw_local_irq_disable():

static inline void raw_local_irq_disable(void)
{
        asm volatile(paravirt_alt(PARAVIRT_CALL)
                     :
                     : paravirt_type(pv_irq_ops.irq_disable),
                       paravirt_clobber(CLBR_EAX)
                     : "memory", "eax", "cc");
}

So what was supposed to be a simple op, now gets expanded into god knows
what, and might lead to tracer recursion or something.

Maybe a simple notrace annotation somewhere in that paravirt code is all
it takes, who knows.

Steve, you've been known to work on virt stuff too, happen to have a
bright idea? :-)

Re: VMI broken on tip/master...

[Jeremy Fitzhardinge]

Peter Zijlstra wrote:
> So what was supposed to be a simple op, now gets expanded into god knows
> what, and might lead to tracer recursion or something.

I don't think that's relevent in this case; Alok's report is not that 
this code crashes, but that this changeset causes a crash somewhere in 
the VMI/paravirt patching code.  Very odd.

    J

Re: VMI broken on tip/master...

[Jeremy Fitzhardinge]

Alok Kataria wrote:
> Hi Peter, 
>
> I was seeing a early fault when running tip/master with VMI enabled on
> VMware platform. 
> This early fault was in the vmi_patch code where we are applying
> paravirt_alternatives. After some trials i noticed that this is
> reproducible only with CONFIG_TRACING. With that disabled my VM boots
> again. 
>
> I started a git bisect after that, and git pointed to this as the bad
> commit
>
> commit 6cc3c6e12bb039047974ad2e7e2d46d15a1b762f
>     trace_clock: fix preemption bug
>
> I then reverted that commit from tip/master and the system did boot. 
> But I fail to understand how this simple patch would be causing things
> to fail in VMI. Any ideas ?
>   

Nope.  My first guess is that this is a misbisection, but the fact that 
reverting helps tends to undermine that diagnosis.

What crash are you seeing?  What kind of fault?  At what instruction?  
Doing what?  It's a bit hard to tell what you're actually seeing.

Does reverting the text_poke() changes make a difference?

    J

Re: VMI broken on tip/master...

[Steven Rostedt]

On Sun, 15 Mar 2009, Peter Zijlstra wrote:
> 
> Looking at arch/x86/include/asm/paravirt.h (god I wish paravirt would go
> away, not only does it screw over ctags, it also hurts my brain), it
> appears its playing icky games with primitives like
> raw_local_irq_disable():
> 
> static inline void raw_local_irq_disable(void)
> {
>         asm volatile(paravirt_alt(PARAVIRT_CALL)
>                      :
>                      : paravirt_type(pv_irq_ops.irq_disable),
>                        paravirt_clobber(CLBR_EAX)
>                      : "memory", "eax", "cc");
> }
> 
> So what was supposed to be a simple op, now gets expanded into god knows
> what, and might lead to tracer recursion or something.

It should only blow up if a guest is using tracing, and the code to call
the hypervisor is also being traced.

> 
> Maybe a simple notrace annotation somewhere in that paravirt code is all
> it takes, who knows.
> 
> Steve, you've been known to work on virt stuff too, happen to have a
> bright idea? :-)

I have noticed that some paravirt ops calls (like this 
raw_local_irq_disable) does not get inlined. It sometimes gets made into a 
function.  This would cause raw_local_irq_disable to actually be traced!

One answer is to use "always_inline" or I can dig out a patch that makes 
inline also include "notrace".

-- Steve

Re: VMI broken on tip/master...

[Jeremy Fitzhardinge]

Steven Rostedt wrote:
> On Sun, 15 Mar 2009, Peter Zijlstra wrote:
>   
>> Looking at arch/x86/include/asm/paravirt.h (god I wish paravirt would go
>> away, not only does it screw over ctags, it also hurts my brain), it
>> appears its playing icky games with primitives like
>> raw_local_irq_disable():
>>
>> static inline void raw_local_irq_disable(void)
>> {
>>         asm volatile(paravirt_alt(PARAVIRT_CALL)
>>                      :
>>                      : paravirt_type(pv_irq_ops.irq_disable),
>>                        paravirt_clobber(CLBR_EAX)
>>                      : "memory", "eax", "cc");
>> }
>>
>> So what was supposed to be a simple op, now gets expanded into god knows
>> what, and might lead to tracer recursion or something.
>>     
>
> It should only blow up if a guest is using tracing, and the code to call
> the hypervisor is also being traced.
>
>   
>> Maybe a simple notrace annotation somewhere in that paravirt code is all
>> it takes, who knows.
>>
>> Steve, you've been known to work on virt stuff too, happen to have a
>> bright idea? :-)
>>     
>
> I have noticed that some paravirt ops calls (like this 
> raw_local_irq_disable) does not get inlined. It sometimes gets made into a 
> function.  This would cause raw_local_irq_disable to actually be traced!
>
> One answer is to use "always_inline" or I can dig out a patch that makes 
> inline also include "notrace".

Yes, these should probably be always_inline and notrace (just in case 
gcc gets it into its head that it might be a good idea to put mcount 
calls into inlined functions).

    J

Re: VMI broken on tip/master...

[Alok Kataria]

On Sat, 2009-03-14 at 16:45 -0700, Jeremy Fitzhardinge wrote:
> Alok Kataria wrote:
> > Hi Peter, 
> >
> > I was seeing a early fault when running tip/master with VMI enabled on
> > VMware platform. 
> > This early fault was in the vmi_patch code where we are applying
> > paravirt_alternatives. After some trials i noticed that this is
> > reproducible only with CONFIG_TRACING. With that disabled my VM boots
> > again. 
> >
> > I started a git bisect after that, and git pointed to this as the bad
> > commit
> >
> > commit 6cc3c6e12bb039047974ad2e7e2d46d15a1b762f
> >     trace_clock: fix preemption bug
> >
> > I then reverted that commit from tip/master and the system did boot. 
> > But I fail to understand how this simple patch would be causing things
> > to fail in VMI. Any ideas ?
> >   
> 
> Nope.  My first guess is that this is a misbisection, but the fact that 
> reverting helps tends to undermine that diagnosis.
> 
> What crash are you seeing?  What kind of fault?  At what instruction?  

It being a early fault, nothing is printed on the console the system
just stays stuck in this early_fault code in arch/x86/kernel/head_32.S

I don't understand why is this not printing anything at this early fault
though, the system just enters the hlt_loop and stays there.

> Doing what?  It's a bit hard to tell what you're actually seeing.
I did some more debugging and I think i know what the problem is 
The objdump for trace_clock_local looks like this

c1070c24 <trace_clock_local>:
c1070c24:       55                      push   %ebp
c1070c25:       89 e5                   mov    %esp,%ebp
c1070c27:       53                      push   %ebx
c1070c28:       83 ec 08                sub    $0x8,%esp
c1070c2b:       ff 15 5c 87 3d c1       call   *0xc13d875c
c1070c31:       ba 64 87 3d c1          mov    $0xc13d8764,%edx
c1070c36:       89 45 f4                mov    %eax,0xfffffff4(%ebp)
c1070c39:       ff 12                   call   *(%edx)		<<=====*
c1070c3b:       e8 cd 68 f9 ff          call   c100750d <sched_clock>
c1070c40:       89 c1                   mov    %eax,%ecx
c1070c42:       8b 45 f4                mov    0xfffffff4(%ebp),%eax
c1070c45:       ff 15 60 87 3d c1       call   *0xc13d8760

Notice instruction on c1070c39 we have "call *(edx)",
edx was just loaded with the address for the paravirt call.
when we try to replace that to a call to vmi specific function, maybe we
hit a BUG_ON(len < 5) in vmi's patch_internal code, because now the
instruction length is less than 5.

Is there is a way to get GCC to not do such fancy tricks, and instead do
a direct "call 0xc13d8764"  ?

Thanks,
Alok
> 
> Does reverting the text_poke() changes make a difference?
> 
>     J

Re: VMI broken on tip/master...

[Jeremy Fitzhardinge]

Alok Kataria wrote:
> On Sat, 2009-03-14 at 16:45 -0700, Jeremy Fitzhardinge wrote:
>   
>> Alok Kataria wrote:
>>     
>>> Hi Peter, 
>>>
>>> I was seeing a early fault when running tip/master with VMI enabled on
>>> VMware platform. 
>>> This early fault was in the vmi_patch code where we are applying
>>> paravirt_alternatives. After some trials i noticed that this is
>>> reproducible only with CONFIG_TRACING. With that disabled my VM boots
>>> again. 
>>>
>>> I started a git bisect after that, and git pointed to this as the bad
>>> commit
>>>
>>> commit 6cc3c6e12bb039047974ad2e7e2d46d15a1b762f
>>>     trace_clock: fix preemption bug
>>>
>>> I then reverted that commit from tip/master and the system did boot. 
>>> But I fail to understand how this simple patch would be causing things
>>> to fail in VMI. Any ideas ?
>>>   
>>>       
>> Nope.  My first guess is that this is a misbisection, but the fact that 
>> reverting helps tends to undermine that diagnosis.
>>
>> What crash are you seeing?  What kind of fault?  At what instruction?  
>>     
>
> It being a early fault, nothing is printed on the console the system
> just stays stuck in this early_fault code in arch/x86/kernel/head_32.S
>
> I don't understand why is this not printing anything at this early fault
> though, the system just enters the hlt_loop and stays there.
>   

It should drop something onto the vga console (and/or serial port?).

>> Doing what?  It's a bit hard to tell what you're actually seeing.
>>     
> I did some more debugging and I think i know what the problem is 
> The objdump for trace_clock_local looks like this
>
> c1070c24 <trace_clock_local>:
> c1070c24:       55                      push   %ebp
> c1070c25:       89 e5                   mov    %esp,%ebp
> c1070c27:       53                      push   %ebx
> c1070c28:       83 ec 08                sub    $0x8,%esp
> c1070c2b:       ff 15 5c 87 3d c1       call   *0xc13d875c
> c1070c31:       ba 64 87 3d c1          mov    $0xc13d8764,%edx
> c1070c36:       89 45 f4                mov    %eax,0xfffffff4(%ebp)
> c1070c39:       ff 12                   call   *(%edx)		<<=====*
> c1070c3b:       e8 cd 68 f9 ff          call   c100750d <sched_clock>
> c1070c40:       89 c1                   mov    %eax,%ecx
> c1070c42:       8b 45 f4                mov    0xfffffff4(%ebp),%eax
> c1070c45:       ff 15 60 87 3d c1       call   *0xc13d8760
>
> Notice instruction on c1070c39 we have "call *(edx)",
> edx was just loaded with the address for the paravirt call.
> when we try to replace that to a call to vmi specific function, maybe we
> hit a BUG_ON(len < 5) in vmi's patch_internal code, because now the
> instruction length is less than 5.
>
> Is there is a way to get GCC to not do such fancy tricks, and instead do
> a direct "call 0xc13d8764"  ?
Well, indirect "call *0xc13d875c".   But yes, its hard to see what gcc 
thinks its getting out of doing the indirect call via %edx.  We 
definitely don't want gcc doing such things, even if it does make sense 
(such as calling an op multiple times, and CSEing the pointer); given 
that we generate all this in asm anyway, we could force it.  Does this help?

diff --git a/arch/x86/include/asm/paravirt.h b/arch/x86/include/asm/paravirt.h
index d4fec1f..62dfc51 100644
--- a/arch/x86/include/asm/paravirt.h
+++ b/arch/x86/include/asm/paravirt.h
@@ -395,7 +395,7 @@ extern struct pv_lock_ops pv_lock_ops;
 
 #define paravirt_type(op)				\
 	[paravirt_typenum] "i" (PARAVIRT_PATCH(op)),	\
-	[paravirt_opptr] "m" (op)
+	[paravirt_opptr] "i" (&(op))
 #define paravirt_clobber(clobber)		\
 	[paravirt_clobber] "i" (clobber)
 
@@ -449,7 +449,7 @@ int paravirt_disable_iospace(void);
  * offset into the paravirt_patch_template structure, and can therefore be
  * freely converted back into a structure offset.
  */
-#define PARAVIRT_CALL	"call *%[paravirt_opptr];"
+#define PARAVIRT_CALL	"call *%c[paravirt_opptr];"
 
 /*
  * These macros are intended to wrap calls through one of the paravirt


    J

Re: VMI broken on tip/master...

[Alok Kataria]

On Mon, 2009-03-16 at 15:54 -0700, Jeremy Fitzhardinge wrote:
> > I don't understand why is this not printing anything at this early fault
> > though, the system just enters the hlt_loop and stays there.
> >   
> 
> It should drop something onto the vga console (and/or serial port?).
Surprisingly it doesn't, but anyways...

> 
> >> Doing what?  It's a bit hard to tell what you're actually seeing.
> >>     
> > I did some more debugging and I think i know what the problem is 
> > The objdump for trace_clock_local looks like this
> >
> > c1070c24 <trace_clock_local>:
> > c1070c24:       55                      push   %ebp
> > c1070c25:       89 e5                   mov    %esp,%ebp
> > c1070c27:       53                      push   %ebx
> > c1070c28:       83 ec 08                sub    $0x8,%esp
> > c1070c2b:       ff 15 5c 87 3d c1       call   *0xc13d875c
> > c1070c31:       ba 64 87 3d c1          mov    $0xc13d8764,%edx
> > c1070c36:       89 45 f4                mov    %eax,0xfffffff4(%ebp)
> > c1070c39:       ff 12                   call   *(%edx)		<<=====*
> > c1070c3b:       e8 cd 68 f9 ff          call   c100750d <sched_clock>
> > c1070c40:       89 c1                   mov    %eax,%ecx
> > c1070c42:       8b 45 f4                mov    0xfffffff4(%ebp),%eax
> > c1070c45:       ff 15 60 87 3d c1       call   *0xc13d8760
> >
> > Notice instruction on c1070c39 we have "call *(edx)",
> > edx was just loaded with the address for the paravirt call.
> > when we try to replace that to a call to vmi specific function, maybe we
> > hit a BUG_ON(len < 5) in vmi's patch_internal code, because now the
> > instruction length is less than 5.
> >
> > Is there is a way to get GCC to not do such fancy tricks, and instead do
> > a direct "call 0xc13d8764"  ?
> Well, indirect "call *0xc13d875c".   But yes, its hard to see what gcc 
> thinks its getting out of doing the indirect call via %edx.  We 
> definitely don't want gcc doing such things, even if it does make sense 
> (such as calling an op multiple times, and CSEing the pointer); given 
> that we generate all this in asm anyway, we could force it.  Does this help?

Yes, This does the trick 
The disassembly for trace_clock_local is now correct, and this boots
too.

c107105c <trace_clock_local>:
c107105c:       55                      push   %ebp
c107105d:       89 e5                   mov    %esp,%ebp
c107105f:       53                      push   %ebx
c1071060:       83 ec 08                sub    $0x8,%esp
c1071063:       ff 15 7c 07 3e c1       call   *0xc13e077c
c1071069:       89 45 f4                mov    %eax,0xfffffff4(%ebp)
c107106c:       ff 15 84 07 3e c1       call   *0xc13e0784
c1071072:       e8 36 65 f9 ff          call   c10075ad <sched_clock>
c1071077:       89 c1                   mov    %eax,%ecx
c1071079:       8b 45 f4                mov    0xfffffff4(%ebp),%eax
c107107c:       ff 15 80 07 3e c1       call   *0xc13e0780

Thanks,
Alok

> 
> diff --git a/arch/x86/include/asm/paravirt.h b/arch/x86/include/asm/paravirt.h
> index d4fec1f..62dfc51 100644
> --- a/arch/x86/include/asm/paravirt.h
> +++ b/arch/x86/include/asm/paravirt.h
> @@ -395,7 +395,7 @@ extern struct pv_lock_ops pv_lock_ops;
>  
>  #define paravirt_type(op)				\
>  	[paravirt_typenum] "i" (PARAVIRT_PATCH(op)),	\
> -	[paravirt_opptr] "m" (op)
> +	[paravirt_opptr] "i" (&(op))
>  #define paravirt_clobber(clobber)		\
>  	[paravirt_clobber] "i" (clobber)
>  
> @@ -449,7 +449,7 @@ int paravirt_disable_iospace(void);
>   * offset into the paravirt_patch_template structure, and can therefore be
>   * freely converted back into a structure offset.
>   */
> -#define PARAVIRT_CALL	"call *%[paravirt_opptr];"
> +#define PARAVIRT_CALL	"call *%c[paravirt_opptr];"
>  
>  /*
>   * These macros are intended to wrap calls through one of the paravirt
> 
>