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
* Luis Henriques <[email protected]> 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
Ingo Molnar wrote:
> * Luis Henriques <[email protected]> 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
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.
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
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
* Avi Kivity <[email protected]> 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
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
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
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?
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.