Problem with kvm on -tip

Problem with kvm on -tip

[Luis Henriques]

Hi,

Since I am not sure if this problem has already been reported, here it goes.

My log gets the following messages in -tip tree.  I don't know for how long this
issue is around and whether the problem is on lockdep or on kvm.  After the
first lockdep message, I get a huge amount of BUGs from kvm (which stop only
when I kill kvm).  So, I believe issue is on kvm.

I am running on an AMD64.  Please let me know if more info is needed (config,
etc).

[ 3293.134688] BUG: MAX_LOCK_DEPTH too low!
[ 3293.134704] turning off the locking correctness validator.
[ 3293.134718] Pid: 5117, comm: kvm Not tainted 2.6.30-rc1-tip-01420-g58e70a8
#18
[ 3293.134727] Call Trace:
[ 3293.134749]  [<ffffffff802805f6>] __lock_acquire+0x4c6/0xbf0
[ 3293.134764]  [<ffffffff80280e2e>] lock_acquire+0x10e/0x160
[ 3293.134780]  [<ffffffff802f3760>] ? mm_take_all_locks+0x110/0x150
[ 3293.134798]  [<ffffffff80580c3b>] _spin_lock_nest_lock+0x3b/0x50
[ 3293.134811]  [<ffffffff802f3760>] ? mm_take_all_locks+0x110/0x150
[ 3293.134823]  [<ffffffff802f3760>] mm_take_all_locks+0x110/0x150
[ 3293.134838]  [<ffffffff803093af>] do_mmu_notifier_register+0xdf/0x1f0
[ 3293.134852]  [<ffffffff803094f3>] mmu_notifier_register+0x13/0x20
[ 3293.134899]  [<ffffffffa02edede>] kvm_dev_ioctl+0x1ae/0x360 [kvm]
[ 3293.134914]  [<ffffffff80327a16>] vfs_ioctl+0x36/0xb0
[ 3293.134927]  [<ffffffff80327b22>] do_vfs_ioctl+0x92/0x5c0
[ 3293.134942]  [<ffffffff80273d9b>] ? up_read+0x2b/0x40
[ 3293.134955]  [<ffffffff8032809f>] sys_ioctl+0x4f/0x80
[ 3293.134971]  [<ffffffff8020c1f2>] system_call_fastpath+0x16/0x1b request
[ 3297.598606] BUG: using smp_processor_id() in preemptible [00000000] code: kvm/5118
[ 3297.598630] caller is kvm_arch_vcpu_ioctl_run+0x61c/0xd10 [kvm]
[ 3297.598635] Pid: 5118, comm: kvm Not tainted 2.6.30-rc1-tip-01420-g58e70a8 #18
[ 3297.598638] Call Trace:
[ 3297.598647]  [<ffffffff803d9db3>] debug_smp_processor_id+0xe3/0xf0
[ 3297.598660]  [<ffffffffa02f684c>] kvm_arch_vcpu_ioctl_run+0x61c/0xd10 [kvm]
[ 3297.598667]  [<ffffffff8032de67>] ? file_update_time+0xc7/0x130
[ 3297.598672]  [<ffffffff802ed26b>] ? do_wp_page+0x1eb/0x7e0
[ 3297.598684]  [<ffffffffa02ebb23>] kvm_vcpu_ioctl+0x4b3/0x8f0 [kvm]
[ 3297.598691]  [<ffffffff805804d6>] ? trace_hardirqs_on_thunk+0x3a/0x3f
[ 3297.598696]  [<ffffffff80581a35>] ? do_IRQ+0x95/0x100
[ 3297.598702]  [<ffffffff8025c85a>] ? irq_exit+0x8a/0xc0
[ 3297.598707]  [<ffffffff80327a16>] vfs_ioctl+0x36/0xb0
[ 3297.598712]  [<ffffffff80327b22>] do_vfs_ioctl+0x92/0x5c0
[ 3297.598716]  [<ffffffff8032809f>] sys_ioctl+0x4f/0x80
[ 3297.598723]  [<ffffffff8020c1f2>] system_call_fastpath+0x16/0x1b

Re: Problem with kvm on -tip

[Ingo Molnar]

* Luis Henriques <henrix@sapo.pt> wrote:

> Hi,
> 
> Since I am not sure if this problem has already been reported, here it goes.
> 
> My log gets the following messages in -tip tree.  I don't know for 
> how long this issue is around and whether the problem is on 
> lockdep or on kvm.  After the first lockdep message, I get a huge 
> amount of BUGs from kvm (which stop only when I kill kvm).  So, I 
> believe issue is on kvm.

Jeremy, have you considered (and tested) KVM when doing the MMU/CPU 
notifier changes? It's these changes:

224101e: x86/paravirt: finish change from lazy cpu to context switch start/end
b407fc5: x86/paravirt: flush pending mmu updates on context switch
7fd7d83: x86/pvops: replace arch_enter_lazy_cpu_mode with arch_start_context_switch

	Ingo

Re: Problem with kvm on -tip

[Jeremy Fitzhardinge]

Ingo Molnar wrote:
> * Luis Henriques <henrix@sapo.pt> wrote:
>
>   
>> Hi,
>>
>> Since I am not sure if this problem has already been reported, here it goes.
>>
>> My log gets the following messages in -tip tree.  I don't know for 
>> how long this issue is around and whether the problem is on 
>> lockdep or on kvm.  After the first lockdep message, I get a huge 
>> amount of BUGs from kvm (which stop only when I kill kvm).  So, I 
>> believe issue is on kvm.
>>     
>
> Jeremy, have you considered (and tested) KVM when doing the MMU/CPU 
> notifier changes? It's these changes:
>   

I use kvm regularly with those changes in place, without seeing a 
problem.   KVM uses a different mechanism to be notified about context 
switches, so the context-switch hook changes should have no effect on 
it.  The preempt-lazy-mmu changes are near the mmu notifiers, but 
shouldn't interact any differently with them.  KVM also outright uses 
lazy mmu updates and the pte pvops, but not in any way that's unusual or 
be broken by these updates (as far as I can tell).

I would expect one of b8bcfe997e4, b407fc57b8 or 252a6bf2a to be the 
ones which would actually change preemption in a way which could cause 
problems (though the last just removes a preempt disable/enable pair 
added a few changes earlier).

Looking back at the lockdep messages, they're definitely not paths I 
would expect to be affected by these changes.  Did you identify them by 
bisection, or are you just trying to winnow out likely candidates?

> 224101e: x86/paravirt: finish change from lazy cpu to context switch start/end
>   
This just passes an extra parameter to arch_start_context_switch, but 
has no other code changes.

> b407fc5: x86/paravirt: flush pending mmu updates on context switch
>   
This shouldn't have any effect on a properly implemented pvops user.  I 
updated kvm along with the other pvops users when I made this change, 
and it appeared to be correct.
> 7fd7d83: x86/pvops: replace arch_enter_lazy_cpu_mode with arch_start_context_switch
This is a simple rename.

    J

Re: Problem with kvm on -tip

[Avi Kivity]

[-- Attachment #1: Type: text/plain, Size: 2977 bytes --]

Luis Henriques wrote:
> Hi,
>
> Since I am not sure if this problem has already been reported, here it goes.
>
> My log gets the following messages in -tip tree.  I don't know for how long this
> issue is around and whether the problem is on lockdep or on kvm.  After the
> first lockdep message, I get a huge amount of BUGs from kvm (which stop only
> when I kill kvm).  So, I believe issue is on kvm.
>
> I am running on an AMD64.  Please let me know if more info is needed (config,
> etc).
>
> [ 3293.134688] BUG: MAX_LOCK_DEPTH too low!
>   

Looks like a genuine issue, need to increase MAX_LOCK_DEPTH.  Andrea?

> [ 3293.134704] turning off the locking correctness validator.
> [ 3293.134718] Pid: 5117, comm: kvm Not tainted 2.6.30-rc1-tip-01420-g58e70a8
> #18
> [ 3293.134727] Call Trace:
> [ 3293.134749]  [<ffffffff802805f6>] __lock_acquire+0x4c6/0xbf0
> [ 3293.134764]  [<ffffffff80280e2e>] lock_acquire+0x10e/0x160
> [ 3293.134780]  [<ffffffff802f3760>] ? mm_take_all_locks+0x110/0x150
> [ 3293.134798]  [<ffffffff80580c3b>] _spin_lock_nest_lock+0x3b/0x50
> [ 3293.134811]  [<ffffffff802f3760>] ? mm_take_all_locks+0x110/0x150
> [ 3293.134823]  [<ffffffff802f3760>] mm_take_all_locks+0x110/0x150
> [ 3293.134838]  [<ffffffff803093af>] do_mmu_notifier_register+0xdf/0x1f0
> [ 3293.134852]  [<ffffffff803094f3>] mmu_notifier_register+0x13/0x20
> [ 3293.134899]  [<ffffffffa02edede>] kvm_dev_ioctl+0x1ae/0x360 [kvm]
> [ 3293.134914]  [<ffffffff80327a16>] vfs_ioctl+0x36/0xb0
> [ 3293.134927]  [<ffffffff80327b22>] do_vfs_ioctl+0x92/0x5c0
> [ 3293.134942]  [<ffffffff80273d9b>] ? up_read+0x2b/0x40
> [ 3293.134955]  [<ffffffff8032809f>] sys_ioctl+0x4f/0x80
> [ 3293.134971]  [<ffffffff8020c1f2>] system_call_fastpath+0x16/0x1b request
>   


> [ 3297.598606] BUG: using smp_processor_id() in preemptible [00000000] code: kvm/5118
> [ 3297.598630] caller is kvm_arch_vcpu_ioctl_run+0x61c/0xd10 [kvm]
> [ 3297.598635] Pid: 5118, comm: kvm Not tainted 2.6.30-rc1-tip-01420-g58e70a8 #18
> [ 3297.598638] Call Trace:
> [ 3297.598647]  [<ffffffff803d9db3>] debug_smp_processor_id+0xe3/0xf0
> [ 3297.598660]  [<ffffffffa02f684c>] kvm_arch_vcpu_ioctl_run+0x61c/0xd10 [kvm]
> [ 3297.598667]  [<ffffffff8032de67>] ? file_update_time+0xc7/0x130
> [ 3297.598672]  [<ffffffff802ed26b>] ? do_wp_page+0x1eb/0x7e0
> [ 3297.598684]  [<ffffffffa02ebb23>] kvm_vcpu_ioctl+0x4b3/0x8f0 [kvm]
> [ 3297.598691]  [<ffffffff805804d6>] ? trace_hardirqs_on_thunk+0x3a/0x3f
> [ 3297.598696]  [<ffffffff80581a35>] ? do_IRQ+0x95/0x100
> [ 3297.598702]  [<ffffffff8025c85a>] ? irq_exit+0x8a/0xc0
> [ 3297.598707]  [<ffffffff80327a16>] vfs_ioctl+0x36/0xb0
> [ 3297.598712]  [<ffffffff80327b22>] do_vfs_ioctl+0x92/0x5c0
> [ 3297.598716]  [<ffffffff8032809f>] sys_ioctl+0x4f/0x80
> [ 3297.598723]  [<ffffffff8020c1f2>] system_call_fastpath+0x16/0x1b
>   

This might be fixed by the attached patch.


-- 
I have a truly marvellous patch that fixes the bug which this
signature is too narrow to contain.


[-- Attachment #2: 0001-KVM-x86-silence-preempt-warning-on-kvm_write_guest.patch --]
[-- Type: text/x-patch, Size: 2318 bytes --]

>From 248a107e6d5d96fe276b48cef98daecec03804cf Mon Sep 17 00:00:00 2001
From: Matt T. Yourst <yourst@users.sourceforge.net>
Date: Tue, 24 Feb 2009 15:28:00 -0300
Subject: [PATCH] KVM: x86: silence preempt warning on kvm_write_guest_time

This issue just appeared in kvm-84 when running on 2.6.28.7 (x86-64)
with PREEMPT enabled.

We're getting syslog warnings like this many (but not all) times qemu
tells KVM to run the VCPU:

BUG: using smp_processor_id() in preemptible [00000000] code:
qemu-system-x86/28938
caller is kvm_arch_vcpu_ioctl_run+0x5d1/0xc70 [kvm]
Pid: 28938, comm: qemu-system-x86 2.6.28.7-mtyrel-64bit
Call Trace:
debug_smp_processor_id+0xf7/0x100
kvm_arch_vcpu_ioctl_run+0x5d1/0xc70 [kvm]
? __wake_up+0x4e/0x70
? wake_futex+0x27/0x40
kvm_vcpu_ioctl+0x2e9/0x5a0 [kvm]
enqueue_hrtimer+0x8a/0x110
_spin_unlock_irqrestore+0x27/0x50
vfs_ioctl+0x31/0xa0
do_vfs_ioctl+0x74/0x480
sys_futex+0xb4/0x140
sys_ioctl+0x99/0xa0
system_call_fastpath+0x16/0x1b

As it turns out, the call trace is messed up due to gcc's inlining, but
I isolated the problem anyway: kvm_write_guest_time() is being used in a
non-thread-safe manner on preemptable kernels.

Basically kvm_write_guest_time()'s body needs to be surrounded by
preempt_disable() and preempt_enable(), since the kernel won't let us
query any per-CPU data (indirectly using smp_processor_id()) without
preemption disabled. The attached patch fixes this issue by disabling
preemption inside kvm_write_guest_time().

[marcelo: surround only __get_cpu_var calls since the warning
is harmless]

Signed-off-by: Marcelo Tosatti <mtosatti@redhat.com>
Signed-off-by: Avi Kivity <avi@redhat.com>
---
 arch/x86/kvm/x86.c |    2 ++
 1 files changed, 2 insertions(+), 0 deletions(-)

diff --git a/arch/x86/kvm/x86.c b/arch/x86/kvm/x86.c
index a1ecec5..b556b6a 100644
--- a/arch/x86/kvm/x86.c
+++ b/arch/x86/kvm/x86.c
@@ -630,10 +630,12 @@ static void kvm_write_guest_time(struct kvm_vcpu *v)
 	if ((!vcpu->time_page))
 		return;
 
+	preempt_disable();
 	if (unlikely(vcpu->hv_clock_tsc_khz != __get_cpu_var(cpu_tsc_khz))) {
 		kvm_set_time_scale(__get_cpu_var(cpu_tsc_khz), &vcpu->hv_clock);
 		vcpu->hv_clock_tsc_khz = __get_cpu_var(cpu_tsc_khz);
 	}
+	preempt_enable();
 
 	/* Keep irq disabled to prevent changes to the clock */
 	local_irq_save(flags);
-- 
1.6.1.1

Re: Problem with kvm on -tip

[Luis Henriques]

Hi,

On Sat, Apr 11, 2009 at 03:08:55PM +0300, Avi Kivity wrote:
>
> This might be fixed by the attached patch.

I confirm that the patch you sent removes the warnings but does it really solve
the issue? (Sorry, I really do not know this code so I might be saying something
really stupid.)

What I understand from your patch is that the only portion of code that needs
protection is the __get_cpu_var().  If this is true then a patch like the one
below would do a better job.  But I am not sure that nothing else needs
protection since the code immediately following the preempt_enable (in your
patch) is an invocation to local_irq_save()...

---
 arch/x86/kvm/x86.c |   10 +++++++---
 1 files changed, 7 insertions(+), 3 deletions(-)

diff --git a/arch/x86/kvm/x86.c b/arch/x86/kvm/x86.c
index 8ca100a..cf918b5 100644
--- a/arch/x86/kvm/x86.c
+++ b/arch/x86/kvm/x86.c
@@ -626,13 +626,17 @@ static void kvm_write_guest_time(struct kvm_vcpu *v)
 	unsigned long flags;
 	struct kvm_vcpu_arch *vcpu = &v->arch;
 	void *shared_kaddr;
+	uint32_t tsc_khz;
 
 	if ((!vcpu->time_page))
 		return;
 
-	if (unlikely(vcpu->hv_clock_tsc_khz != __get_cpu_var(cpu_tsc_khz))) {
-		kvm_set_time_scale(__get_cpu_var(cpu_tsc_khz), &vcpu->hv_clock);
-		vcpu->hv_clock_tsc_khz = __get_cpu_var(cpu_tsc_khz);
+	preempt_disable();
+	tsc_khz = __get_cpu_var(cpu_tsc_khz);
+	preempt_enable();
+	if (unlikely(vcpu->hv_clock_tsc_khz != tsc_khz)) {
+		kvm_set_time_scale(tsc_khz, &vcpu->hv_clock);
+		vcpu->hv_clock_tsc_khz = tsc_khz;
 	}

 	/* Keep irq disabled to prevent changes to the clock */
-- 
1.6.2.1

Re: Problem with kvm on -tip

[Avi Kivity]

Luis Henriques wrote:
> Hi,
>
> On Sat, Apr 11, 2009 at 03:08:55PM +0300, Avi Kivity wrote:
>   
>> This might be fixed by the attached patch.
>>     
>
> I confirm that the patch you sent removes the warnings but does it really solve
> the issue? (Sorry, I really do not know this code so I might be saying something
> really stupid.)
>   

It does.  If we are later migrated to another cpu, this code snippet 
will be called again and re-set the clock.

> What I understand from your patch is that the only portion of code that needs
> protection is the __get_cpu_var().  If this is true then a patch like the one
> below would do a better job.  But I am not sure that nothing else needs
> protection since the code immediately following the preempt_enable (in your
> patch) is an invocation to local_irq_save()...
>
> ---
>  arch/x86/kvm/x86.c |   10 +++++++---
>  1 files changed, 7 insertions(+), 3 deletions(-)
>
> diff --git a/arch/x86/kvm/x86.c b/arch/x86/kvm/x86.c
> index 8ca100a..cf918b5 100644
> --- a/arch/x86/kvm/x86.c
> +++ b/arch/x86/kvm/x86.c
> @@ -626,13 +626,17 @@ static void kvm_write_guest_time(struct kvm_vcpu *v)
>  	unsigned long flags;
>  	struct kvm_vcpu_arch *vcpu = &v->arch;
>  	void *shared_kaddr;
> +	uint32_t tsc_khz;
>  
>  	if ((!vcpu->time_page))
>  		return;
>  
> -	if (unlikely(vcpu->hv_clock_tsc_khz != __get_cpu_var(cpu_tsc_khz))) {
> -		kvm_set_time_scale(__get_cpu_var(cpu_tsc_khz), &vcpu->hv_clock);
> -		vcpu->hv_clock_tsc_khz = __get_cpu_var(cpu_tsc_khz);
> +	preempt_disable();
> +	tsc_khz = __get_cpu_var(cpu_tsc_khz);
> +	preempt_enable();
> +	if (unlikely(vcpu->hv_clock_tsc_khz != tsc_khz)) {
> +		kvm_set_time_scale(tsc_khz, &vcpu->hv_clock);
> +		vcpu->hv_clock_tsc_khz = tsc_khz;
>  	}

Since the whole thing is unlikely(), there will be no runtime difference 
between the two patches.

-- 
error compiling committee.c: too many arguments to function

Re: Problem with kvm on -tip

[Luis Henriques]

On Sun, Apr 12, 2009 at 02:53:22PM +0300, Avi Kivity wrote:
> Luis Henriques wrote:
>> Hi,
>>
>> On Sat, Apr 11, 2009 at 03:08:55PM +0300, Avi Kivity wrote:
>>   
>>> This might be fixed by the attached patch.
>>>     
>>
>> I confirm that the patch you sent removes the warnings but does it really solve
>> the issue? (Sorry, I really do not know this code so I might be saying something
>> really stupid.)
>>   
>
> It does.  If we are later migrated to another cpu, this code snippet  
> will be called again and re-set the clock.

Ok, understood.  Thank you for the comment and sorry about the noise.

--
Luis Henriques

>> What I understand from your patch is that the only portion of code that needs
>> protection is the __get_cpu_var().  If this is true then a patch like the one
>> below would do a better job.  But I am not sure that nothing else needs
>> protection since the code immediately following the preempt_enable (in your
>> patch) is an invocation to local_irq_save()...
>>
>> ---
>>  arch/x86/kvm/x86.c |   10 +++++++---
>>  1 files changed, 7 insertions(+), 3 deletions(-)
>>
>> diff --git a/arch/x86/kvm/x86.c b/arch/x86/kvm/x86.c
>> index 8ca100a..cf918b5 100644
>> --- a/arch/x86/kvm/x86.c
>> +++ b/arch/x86/kvm/x86.c
>> @@ -626,13 +626,17 @@ static void kvm_write_guest_time(struct kvm_vcpu *v)
>>  	unsigned long flags;
>>  	struct kvm_vcpu_arch *vcpu = &v->arch;
>>  	void *shared_kaddr;
>> +	uint32_t tsc_khz;
>>   	if ((!vcpu->time_page))
>>  		return;
>>  -	if (unlikely(vcpu->hv_clock_tsc_khz != __get_cpu_var(cpu_tsc_khz))) 
>> {
>> -		kvm_set_time_scale(__get_cpu_var(cpu_tsc_khz), &vcpu->hv_clock);
>> -		vcpu->hv_clock_tsc_khz = __get_cpu_var(cpu_tsc_khz);
>> +	preempt_disable();
>> +	tsc_khz = __get_cpu_var(cpu_tsc_khz);
>> +	preempt_enable();
>> +	if (unlikely(vcpu->hv_clock_tsc_khz != tsc_khz)) {
>> +		kvm_set_time_scale(tsc_khz, &vcpu->hv_clock);
>> +		vcpu->hv_clock_tsc_khz = tsc_khz;
>>  	}
>
> Since the whole thing is unlikely(), there will be no runtime difference  
> between the two patches.
>
> -- 
> error compiling committee.c: too many arguments to function

Re: Problem with kvm on -tip

[Ingo Molnar]

* Avi Kivity <avi@redhat.com> wrote:

> index a1ecec5..b556b6a 100644
> --- a/arch/x86/kvm/x86.c
> +++ b/arch/x86/kvm/x86.c
> @@ -630,10 +630,12 @@ static void kvm_write_guest_time(struct kvm_vcpu *v)
>  	if ((!vcpu->time_page))
>  		return;
>  
> +	preempt_disable();
>  	if (unlikely(vcpu->hv_clock_tsc_khz != __get_cpu_var(cpu_tsc_khz))) {
>  		kvm_set_time_scale(__get_cpu_var(cpu_tsc_khz), &vcpu->hv_clock);
>  		vcpu->hv_clock_tsc_khz = __get_cpu_var(cpu_tsc_khz);
>  	}
> +	preempt_enable();

fix look good, but note that this is an open-coded get_cpu_var() 
sequence - please use get_cpu_var()/put_cpu_var() instead.

	Ingo

Re: Problem with kvm on -tip

[Avi Kivity]

Ingo Molnar wrote:
>> @@ -630,10 +630,12 @@ static void kvm_write_guest_time(struct kvm_vcpu *v)
>>  	if ((!vcpu->time_page))
>>  		return;
>>  
>> +	preempt_disable();
>>  	if (unlikely(vcpu->hv_clock_tsc_khz != __get_cpu_var(cpu_tsc_khz))) {
>>  		kvm_set_time_scale(__get_cpu_var(cpu_tsc_khz), &vcpu->hv_clock);
>>  		vcpu->hv_clock_tsc_khz = __get_cpu_var(cpu_tsc_khz);
>>  	}
>> +	preempt_enable();
>>     
>
> fix look good, but note that this is an open-coded get_cpu_var() 
> sequence - please use get_cpu_var()/put_cpu_var() instead.
>   

Right, will do.

-- 
error compiling committee.c: too many arguments to function

Re: Problem with kvm on -tip

[Peter Zijlstra]

On Sat, 2009-04-11 at 15:08 +0300, Avi Kivity wrote:
> > [ 3293.134688] BUG: MAX_LOCK_DEPTH too low!
> >   
> 
> Looks like a genuine issue, need to increase MAX_LOCK_DEPTH.  Andrea?
> 
> > [ 3293.134704] turning off the locking correctness validator.
> > [ 3293.134718] Pid: 5117, comm: kvm Not tainted 2.6.30-rc1-tip-01420-g58e70a8
> > #18
> > [ 3293.134727] Call Trace:
> > [ 3293.134749]  [<ffffffff802805f6>] __lock_acquire+0x4c6/0xbf0
> > [ 3293.134764]  [<ffffffff80280e2e>] lock_acquire+0x10e/0x160
> > [ 3293.134780]  [<ffffffff802f3760>] ? mm_take_all_locks+0x110/0x150
> > [ 3293.134798]  [<ffffffff80580c3b>] _spin_lock_nest_lock+0x3b/0x50
> > [ 3293.134811]  [<ffffffff802f3760>] ? mm_take_all_locks+0x110/0x150
> > [ 3293.134823]  [<ffffffff802f3760>] mm_take_all_locks+0x110/0x150
> > [ 3293.134838]  [<ffffffff803093af>] do_mmu_notifier_register+0xdf/0x1f0
> > [ 3293.134852]  [<ffffffff803094f3>] mmu_notifier_register+0x13/0x20
> > [ 3293.134899]  [<ffffffffa02edede>] kvm_dev_ioctl+0x1ae/0x360 [kvm]
> > [ 3293.134914]  [<ffffffff80327a16>] vfs_ioctl+0x36/0xb0
> > [ 3293.134927]  [<ffffffff80327b22>] do_vfs_ioctl+0x92/0x5c0
> > [ 3293.134942]  [<ffffffff80273d9b>] ? up_read+0x2b/0x40
> > [ 3293.134955]  [<ffffffff8032809f>] sys_ioctl+0x4f/0x80
> > [ 3293.134971]  [<ffffffff8020c1f2>] system_call_fastpath+0x16/0x1b request

Thing is, its grabbing all vma locks, and we have a lock depth limit of
48. Now when we started this, the claim was that kvm would only need
this when the process was very fresh and would thus not yet have many
vma, ergo we should never run into this limit.

Has that changed?

Re: Problem with kvm on -tip

[Avi Kivity]

Peter Zijlstra wrote:
> On Sat, 2009-04-11 at 15:08 +0300, Avi Kivity wrote:
>   
>>> [ 3293.134688] BUG: MAX_LOCK_DEPTH too low!
>>>   
>>>       
>> Looks like a genuine issue, need to increase MAX_LOCK_DEPTH.  Andrea?
>>
>>     
>>> [ 3293.134704] turning off the locking correctness validator.
>>> [ 3293.134718] Pid: 5117, comm: kvm Not tainted 2.6.30-rc1-tip-01420-g58e70a8
>>> #18
>>> [ 3293.134727] Call Trace:
>>> [ 3293.134749]  [<ffffffff802805f6>] __lock_acquire+0x4c6/0xbf0
>>> [ 3293.134764]  [<ffffffff80280e2e>] lock_acquire+0x10e/0x160
>>> [ 3293.134780]  [<ffffffff802f3760>] ? mm_take_all_locks+0x110/0x150
>>> [ 3293.134798]  [<ffffffff80580c3b>] _spin_lock_nest_lock+0x3b/0x50
>>> [ 3293.134811]  [<ffffffff802f3760>] ? mm_take_all_locks+0x110/0x150
>>> [ 3293.134823]  [<ffffffff802f3760>] mm_take_all_locks+0x110/0x150
>>> [ 3293.134838]  [<ffffffff803093af>] do_mmu_notifier_register+0xdf/0x1f0
>>> [ 3293.134852]  [<ffffffff803094f3>] mmu_notifier_register+0x13/0x20
>>> [ 3293.134899]  [<ffffffffa02edede>] kvm_dev_ioctl+0x1ae/0x360 [kvm]
>>> [ 3293.134914]  [<ffffffff80327a16>] vfs_ioctl+0x36/0xb0
>>> [ 3293.134927]  [<ffffffff80327b22>] do_vfs_ioctl+0x92/0x5c0
>>> [ 3293.134942]  [<ffffffff80273d9b>] ? up_read+0x2b/0x40
>>> [ 3293.134955]  [<ffffffff8032809f>] sys_ioctl+0x4f/0x80
>>> [ 3293.134971]  [<ffffffff8020c1f2>] system_call_fastpath+0x16/0x1b request
>>>       
>
> Thing is, its grabbing all vma locks, and we have a lock depth limit of
> 48. Now when we started this, the claim was that kvm would only need
> this when the process was very fresh and would thus not yet have many
> vma, ergo we should never run into this limit.
>
> Has that changed?
>   

Hasn't changed; this is on VM creation.

-- 
I have a truly marvellous patch that fixes the bug which this
signature is too narrow to contain.