All of lore.kernel.org
 help / color / mirror / Atom feed
* Re: qemu-system-aarch64: Failed to retrieve host CPU features
       [not found] ` <20220812084529.ur5qcyws5qvoyvuc@altlinux.org>
@ 2022-08-12  9:25     ` Peter Maydell
  0 siblings, 0 replies; 12+ messages in thread
From: Peter Maydell @ 2022-08-12  9:25 UTC (permalink / raw)
  To: Vitaly Chikunov; +Cc: qemu-arm, kvmarm, QEMU Developers, Dmitry V. Levin

I've added some more relevant mailing lists to the cc.

On Fri, 12 Aug 2022 at 09:45, Vitaly Chikunov <vt@altlinux.org> wrote:
> On Fri, Aug 12, 2022 at 05:14:27AM +0300, Vitaly Chikunov wrote:
> > I noticed that we starting to get many errors like this:
> >
> >   qemu-system-aarch64: Failed to retrieve host CPU features
> >
> > Where many is 1-2% per run, depends on host, host is Kunpeng-920, and
> > Linux kernel is v5.15.59, but it started to appear months before that.
> >
> > strace shows in erroneous case:
> >
> >   1152244 ioctl(9, KVM_CREATE_VM, 0x30)   = -1 EINTR (Interrupted system call)
> >
> > And I see in target/arm/kvm.c:kvm_arm_create_scratch_host_vcpu:
> >
> >     vmfd = ioctl(kvmfd, KVM_CREATE_VM, max_vm_pa_size);
> >     if (vmfd < 0) {
> >         goto err;
> >     }
> >
> > Maybe it should restart ioctl on EINTR?
> >
> > I don't see EINTR documented in ioctl(2) nor in Linux'
> > Documentation/virt/kvm/api.rst for KVM_CREATE_VM, but for KVM_RUN it
> > says "an unmasked signal is pending".
>
> I am suggested that almost any blocking syscall could return EINTR, so I
> checked the strace log and it does not show evidence of arriving a signal,
> the log ends like this:
>
>   1152244 openat(AT_FDCWD, "/dev/kvm", O_RDWR|O_CLOEXEC) = 9
>   1152244 ioctl(9, KVM_CHECK_EXTENSION, KVM_CAP_ARM_VM_IPA_SIZE) = 48
>   1152244 ioctl(9, KVM_CREATE_VM, 0x30)   = -1 EINTR (Interrupted system call)
>   1152244 close(9)                        = 0
>   1152244 newfstatat(2, "", {st_dev=makedev(0, 0xd), st_ino=57869925, st_mode=S_IFIFO|0600, st_nlink=1, st_uid=517, st_gid=517, st_blksize=4096, st_blocks=0, st_size=0, st_atime=1660268019 /* 2022-08-12T01:33:39.850436293+0000 */, st_atime_nsec=850436293, st_mtime=1660268019 /* 2022-08-12T01:33:39.850436293+0000 */, st_mtime_nsec=850436293, st_ctime=1660268019 /* 2022-08-12T01:33:39.850436293+0000 */, st_ctime_nsec=850436293}, AT_EMPTY_PATH) = 0
>   1152244 write(2, "qemu-system-aarch64: Failed to r"..., 58) = 58
>   1152244 exit_group(1)                   = ?
>   1152245 <... clock_nanosleep resumed> <unfinished ...>) = ?
>   1152245 +++ exited with 1 +++
>   1152244 +++ exited with 1 +++

KVM folks: should we expect that KVM_CREATE_VM might fail EINTR
and need retrying?

(I suspect the answer is "yes", given we do this in the generic
code in kvm-all.c.)

thanks
-- PMM
_______________________________________________
kvmarm mailing list
kvmarm@lists.cs.columbia.edu
https://lists.cs.columbia.edu/mailman/listinfo/kvmarm

^ permalink raw reply	[flat|nested] 12+ messages in thread

* Re: qemu-system-aarch64: Failed to retrieve host CPU features
@ 2022-08-12  9:25     ` Peter Maydell
  0 siblings, 0 replies; 12+ messages in thread
From: Peter Maydell @ 2022-08-12  9:25 UTC (permalink / raw)
  To: Vitaly Chikunov; +Cc: qemu-arm, Dmitry V. Levin, QEMU Developers, kvmarm

I've added some more relevant mailing lists to the cc.

On Fri, 12 Aug 2022 at 09:45, Vitaly Chikunov <vt@altlinux.org> wrote:
> On Fri, Aug 12, 2022 at 05:14:27AM +0300, Vitaly Chikunov wrote:
> > I noticed that we starting to get many errors like this:
> >
> >   qemu-system-aarch64: Failed to retrieve host CPU features
> >
> > Where many is 1-2% per run, depends on host, host is Kunpeng-920, and
> > Linux kernel is v5.15.59, but it started to appear months before that.
> >
> > strace shows in erroneous case:
> >
> >   1152244 ioctl(9, KVM_CREATE_VM, 0x30)   = -1 EINTR (Interrupted system call)
> >
> > And I see in target/arm/kvm.c:kvm_arm_create_scratch_host_vcpu:
> >
> >     vmfd = ioctl(kvmfd, KVM_CREATE_VM, max_vm_pa_size);
> >     if (vmfd < 0) {
> >         goto err;
> >     }
> >
> > Maybe it should restart ioctl on EINTR?
> >
> > I don't see EINTR documented in ioctl(2) nor in Linux'
> > Documentation/virt/kvm/api.rst for KVM_CREATE_VM, but for KVM_RUN it
> > says "an unmasked signal is pending".
>
> I am suggested that almost any blocking syscall could return EINTR, so I
> checked the strace log and it does not show evidence of arriving a signal,
> the log ends like this:
>
>   1152244 openat(AT_FDCWD, "/dev/kvm", O_RDWR|O_CLOEXEC) = 9
>   1152244 ioctl(9, KVM_CHECK_EXTENSION, KVM_CAP_ARM_VM_IPA_SIZE) = 48
>   1152244 ioctl(9, KVM_CREATE_VM, 0x30)   = -1 EINTR (Interrupted system call)
>   1152244 close(9)                        = 0
>   1152244 newfstatat(2, "", {st_dev=makedev(0, 0xd), st_ino=57869925, st_mode=S_IFIFO|0600, st_nlink=1, st_uid=517, st_gid=517, st_blksize=4096, st_blocks=0, st_size=0, st_atime=1660268019 /* 2022-08-12T01:33:39.850436293+0000 */, st_atime_nsec=850436293, st_mtime=1660268019 /* 2022-08-12T01:33:39.850436293+0000 */, st_mtime_nsec=850436293, st_ctime=1660268019 /* 2022-08-12T01:33:39.850436293+0000 */, st_ctime_nsec=850436293}, AT_EMPTY_PATH) = 0
>   1152244 write(2, "qemu-system-aarch64: Failed to r"..., 58) = 58
>   1152244 exit_group(1)                   = ?
>   1152245 <... clock_nanosleep resumed> <unfinished ...>) = ?
>   1152245 +++ exited with 1 +++
>   1152244 +++ exited with 1 +++

KVM folks: should we expect that KVM_CREATE_VM might fail EINTR
and need retrying?

(I suspect the answer is "yes", given we do this in the generic
code in kvm-all.c.)

thanks
-- PMM


^ permalink raw reply	[flat|nested] 12+ messages in thread

* Re: qemu-system-aarch64: Failed to retrieve host CPU features
  2022-08-12  9:25     ` Peter Maydell
@ 2022-08-12 15:02       ` Marc Zyngier
  -1 siblings, 0 replies; 12+ messages in thread
From: Marc Zyngier @ 2022-08-12 15:02 UTC (permalink / raw)
  To: Peter Maydell, Vitaly Chikunov
  Cc: qemu-arm, Dmitry V. Levin, kvmarm, QEMU Developers

Hi Peter,

On Fri, 12 Aug 2022 10:25:55 +0100,
Peter Maydell <peter.maydell@linaro.org> wrote:
> 
> I've added some more relevant mailing lists to the cc.
> 
> On Fri, 12 Aug 2022 at 09:45, Vitaly Chikunov <vt@altlinux.org> wrote:
> > On Fri, Aug 12, 2022 at 05:14:27AM +0300, Vitaly Chikunov wrote:
> > > I noticed that we starting to get many errors like this:
> > >
> > >   qemu-system-aarch64: Failed to retrieve host CPU features
> > >
> > > Where many is 1-2% per run, depends on host, host is Kunpeng-920, and
> > > Linux kernel is v5.15.59, but it started to appear months before that.
> > >
> > > strace shows in erroneous case:
> > >
> > >   1152244 ioctl(9, KVM_CREATE_VM, 0x30)   = -1 EINTR (Interrupted system call)
> > >
> > > And I see in target/arm/kvm.c:kvm_arm_create_scratch_host_vcpu:
> > >
> > >     vmfd = ioctl(kvmfd, KVM_CREATE_VM, max_vm_pa_size);
> > >     if (vmfd < 0) {
> > >         goto err;
> > >     }
> > >
> > > Maybe it should restart ioctl on EINTR?
> > >
> > > I don't see EINTR documented in ioctl(2) nor in Linux'
> > > Documentation/virt/kvm/api.rst for KVM_CREATE_VM, but for KVM_RUN it
> > > says "an unmasked signal is pending".
> >
> > I am suggested that almost any blocking syscall could return EINTR, so I
> > checked the strace log and it does not show evidence of arriving a signal,
> > the log ends like this:
> >
> >   1152244 openat(AT_FDCWD, "/dev/kvm", O_RDWR|O_CLOEXEC) = 9
> >   1152244 ioctl(9, KVM_CHECK_EXTENSION, KVM_CAP_ARM_VM_IPA_SIZE) = 48
> >   1152244 ioctl(9, KVM_CREATE_VM, 0x30)   = -1 EINTR (Interrupted system call)
> >   1152244 close(9)                        = 0
> >   1152244 newfstatat(2, "", {st_dev=makedev(0, 0xd), st_ino=57869925, st_mode=S_IFIFO|0600, st_nlink=1, st_uid=517, st_gid=517, st_blksize=4096, st_blocks=0, st_size=0, st_atime=1660268019 /* 2022-08-12T01:33:39.850436293+0000 */, st_atime_nsec=850436293, st_mtime=1660268019 /* 2022-08-12T01:33:39.850436293+0000 */, st_mtime_nsec=850436293, st_ctime=1660268019 /* 2022-08-12T01:33:39.850436293+0000 */, st_ctime_nsec=850436293}, AT_EMPTY_PATH) = 0
> >   1152244 write(2, "qemu-system-aarch64: Failed to r"..., 58) = 58
> >   1152244 exit_group(1)                   = ?
> >   1152245 <... clock_nanosleep resumed> <unfinished ...>) = ?
> >   1152245 +++ exited with 1 +++
> >   1152244 +++ exited with 1 +++
> 
> KVM folks: should we expect that KVM_CREATE_VM might fail EINTR
> and need retrying?

In general, yes. But for this particular one, this is pretty odd.

The only path I can so far see that would match this behaviour is if
mm_take_all_locks() (called from __mmu_notifier_register()) was
getting interrupted by a signal (I'm looking at a 5.19-ish kernel,
which may slightly differ from the 5.15 mentioned above).

But as Vitaly points out, it doesn't seem to be a signal delivered
here.

Vitaly: could you please share your exact test case (full qemu command
line), and instrument your kernel to see if mm_take_all_locks() is the
one failing?

Thanks,

	M.

-- 
Without deviation from the norm, progress is not possible.
_______________________________________________
kvmarm mailing list
kvmarm@lists.cs.columbia.edu
https://lists.cs.columbia.edu/mailman/listinfo/kvmarm

^ permalink raw reply	[flat|nested] 12+ messages in thread

* Re: qemu-system-aarch64: Failed to retrieve host CPU features
@ 2022-08-12 15:02       ` Marc Zyngier
  0 siblings, 0 replies; 12+ messages in thread
From: Marc Zyngier @ 2022-08-12 15:02 UTC (permalink / raw)
  To: Peter Maydell, Vitaly Chikunov
  Cc: qemu-arm, kvmarm, QEMU Developers, Dmitry V. Levin

Hi Peter,

On Fri, 12 Aug 2022 10:25:55 +0100,
Peter Maydell <peter.maydell@linaro.org> wrote:
> 
> I've added some more relevant mailing lists to the cc.
> 
> On Fri, 12 Aug 2022 at 09:45, Vitaly Chikunov <vt@altlinux.org> wrote:
> > On Fri, Aug 12, 2022 at 05:14:27AM +0300, Vitaly Chikunov wrote:
> > > I noticed that we starting to get many errors like this:
> > >
> > >   qemu-system-aarch64: Failed to retrieve host CPU features
> > >
> > > Where many is 1-2% per run, depends on host, host is Kunpeng-920, and
> > > Linux kernel is v5.15.59, but it started to appear months before that.
> > >
> > > strace shows in erroneous case:
> > >
> > >   1152244 ioctl(9, KVM_CREATE_VM, 0x30)   = -1 EINTR (Interrupted system call)
> > >
> > > And I see in target/arm/kvm.c:kvm_arm_create_scratch_host_vcpu:
> > >
> > >     vmfd = ioctl(kvmfd, KVM_CREATE_VM, max_vm_pa_size);
> > >     if (vmfd < 0) {
> > >         goto err;
> > >     }
> > >
> > > Maybe it should restart ioctl on EINTR?
> > >
> > > I don't see EINTR documented in ioctl(2) nor in Linux'
> > > Documentation/virt/kvm/api.rst for KVM_CREATE_VM, but for KVM_RUN it
> > > says "an unmasked signal is pending".
> >
> > I am suggested that almost any blocking syscall could return EINTR, so I
> > checked the strace log and it does not show evidence of arriving a signal,
> > the log ends like this:
> >
> >   1152244 openat(AT_FDCWD, "/dev/kvm", O_RDWR|O_CLOEXEC) = 9
> >   1152244 ioctl(9, KVM_CHECK_EXTENSION, KVM_CAP_ARM_VM_IPA_SIZE) = 48
> >   1152244 ioctl(9, KVM_CREATE_VM, 0x30)   = -1 EINTR (Interrupted system call)
> >   1152244 close(9)                        = 0
> >   1152244 newfstatat(2, "", {st_dev=makedev(0, 0xd), st_ino=57869925, st_mode=S_IFIFO|0600, st_nlink=1, st_uid=517, st_gid=517, st_blksize=4096, st_blocks=0, st_size=0, st_atime=1660268019 /* 2022-08-12T01:33:39.850436293+0000 */, st_atime_nsec=850436293, st_mtime=1660268019 /* 2022-08-12T01:33:39.850436293+0000 */, st_mtime_nsec=850436293, st_ctime=1660268019 /* 2022-08-12T01:33:39.850436293+0000 */, st_ctime_nsec=850436293}, AT_EMPTY_PATH) = 0
> >   1152244 write(2, "qemu-system-aarch64: Failed to r"..., 58) = 58
> >   1152244 exit_group(1)                   = ?
> >   1152245 <... clock_nanosleep resumed> <unfinished ...>) = ?
> >   1152245 +++ exited with 1 +++
> >   1152244 +++ exited with 1 +++
> 
> KVM folks: should we expect that KVM_CREATE_VM might fail EINTR
> and need retrying?

In general, yes. But for this particular one, this is pretty odd.

The only path I can so far see that would match this behaviour is if
mm_take_all_locks() (called from __mmu_notifier_register()) was
getting interrupted by a signal (I'm looking at a 5.19-ish kernel,
which may slightly differ from the 5.15 mentioned above).

But as Vitaly points out, it doesn't seem to be a signal delivered
here.

Vitaly: could you please share your exact test case (full qemu command
line), and instrument your kernel to see if mm_take_all_locks() is the
one failing?

Thanks,

	M.

-- 
Without deviation from the norm, progress is not possible.


^ permalink raw reply	[flat|nested] 12+ messages in thread

* Re: qemu-system-aarch64: Failed to retrieve host CPU features
  2022-08-12  9:25     ` Peter Maydell
@ 2022-08-12 15:10       ` Marc Zyngier
  -1 siblings, 0 replies; 12+ messages in thread
From: Marc Zyngier @ 2022-08-12 15:10 UTC (permalink / raw)
  To: Peter Maydell
  Cc: Vitaly Chikunov, qemu-arm, Dmitry V. Levin, kvmarm, QEMU Developers

On Fri, 12 Aug 2022 10:25:55 +0100,
Peter Maydell <peter.maydell@linaro.org> wrote:
> 
> I've added some more relevant mailing lists to the cc.
> 
> On Fri, 12 Aug 2022 at 09:45, Vitaly Chikunov <vt@altlinux.org> wrote:
> > On Fri, Aug 12, 2022 at 05:14:27AM +0300, Vitaly Chikunov wrote:
> > > I noticed that we starting to get many errors like this:
> > >
> > >   qemu-system-aarch64: Failed to retrieve host CPU features
> > >
> > > Where many is 1-2% per run, depends on host, host is Kunpeng-920, and
> > > Linux kernel is v5.15.59, but it started to appear months before that.
> > >
> > > strace shows in erroneous case:
> > >
> > >   1152244 ioctl(9, KVM_CREATE_VM, 0x30)   = -1 EINTR (Interrupted system call)
> > >
> > > And I see in target/arm/kvm.c:kvm_arm_create_scratch_host_vcpu:
> > >
> > >     vmfd = ioctl(kvmfd, KVM_CREATE_VM, max_vm_pa_size);
> > >     if (vmfd < 0) {
> > >         goto err;
> > >     }
> > >
> > > Maybe it should restart ioctl on EINTR?
> > >
> > > I don't see EINTR documented in ioctl(2) nor in Linux'
> > > Documentation/virt/kvm/api.rst for KVM_CREATE_VM, but for KVM_RUN it
> > > says "an unmasked signal is pending".
> >
> > I am suggested that almost any blocking syscall could return EINTR, so I
> > checked the strace log and it does not show evidence of arriving a signal,
> > the log ends like this:
> >
> >   1152244 openat(AT_FDCWD, "/dev/kvm", O_RDWR|O_CLOEXEC) = 9
> >   1152244 ioctl(9, KVM_CHECK_EXTENSION, KVM_CAP_ARM_VM_IPA_SIZE) = 48
> >   1152244 ioctl(9, KVM_CREATE_VM, 0x30)   = -1 EINTR (Interrupted system call)
> >   1152244 close(9)                        = 0
> >   1152244 newfstatat(2, "", {st_dev=makedev(0, 0xd), st_ino=57869925, st_mode=S_IFIFO|0600, st_nlink=1, st_uid=517, st_gid=517, st_blksize=4096, st_blocks=0, st_size=0, st_atime=1660268019 /* 2022-08-12T01:33:39.850436293+0000 */, st_atime_nsec=850436293, st_mtime=1660268019 /* 2022-08-12T01:33:39.850436293+0000 */, st_mtime_nsec=850436293, st_ctime=1660268019 /* 2022-08-12T01:33:39.850436293+0000 */, st_ctime_nsec=850436293}, AT_EMPTY_PATH) = 0
> >   1152244 write(2, "qemu-system-aarch64: Failed to r"..., 58) = 58
> >   1152244 exit_group(1)                   = ?
> >   1152245 <... clock_nanosleep resumed> <unfinished ...>) = ?
> >   1152245 +++ exited with 1 +++
> >   1152244 +++ exited with 1 +++
> 
> KVM folks: should we expect that KVM_CREATE_VM might fail EINTR
> and need retrying?
> 
> (I suspect the answer is "yes", given we do this in the generic
> code in kvm-all.c.)

Interestingly, this has cropped up in the (distant) past:

https://lists.gnu.org/archive/html/qemu-devel/2014-01/msg01031.html

and seems to point at the path I was mentioning earlier (the code
hasn't changed too much since, apparently).

I'd still like to understand the underlying reason though.

Thanks,

	M.

-- 
Without deviation from the norm, progress is not possible.
_______________________________________________
kvmarm mailing list
kvmarm@lists.cs.columbia.edu
https://lists.cs.columbia.edu/mailman/listinfo/kvmarm

^ permalink raw reply	[flat|nested] 12+ messages in thread

* Re: qemu-system-aarch64: Failed to retrieve host CPU features
@ 2022-08-12 15:10       ` Marc Zyngier
  0 siblings, 0 replies; 12+ messages in thread
From: Marc Zyngier @ 2022-08-12 15:10 UTC (permalink / raw)
  To: Peter Maydell
  Cc: Vitaly Chikunov, qemu-arm, kvmarm, QEMU Developers, Dmitry V. Levin

On Fri, 12 Aug 2022 10:25:55 +0100,
Peter Maydell <peter.maydell@linaro.org> wrote:
> 
> I've added some more relevant mailing lists to the cc.
> 
> On Fri, 12 Aug 2022 at 09:45, Vitaly Chikunov <vt@altlinux.org> wrote:
> > On Fri, Aug 12, 2022 at 05:14:27AM +0300, Vitaly Chikunov wrote:
> > > I noticed that we starting to get many errors like this:
> > >
> > >   qemu-system-aarch64: Failed to retrieve host CPU features
> > >
> > > Where many is 1-2% per run, depends on host, host is Kunpeng-920, and
> > > Linux kernel is v5.15.59, but it started to appear months before that.
> > >
> > > strace shows in erroneous case:
> > >
> > >   1152244 ioctl(9, KVM_CREATE_VM, 0x30)   = -1 EINTR (Interrupted system call)
> > >
> > > And I see in target/arm/kvm.c:kvm_arm_create_scratch_host_vcpu:
> > >
> > >     vmfd = ioctl(kvmfd, KVM_CREATE_VM, max_vm_pa_size);
> > >     if (vmfd < 0) {
> > >         goto err;
> > >     }
> > >
> > > Maybe it should restart ioctl on EINTR?
> > >
> > > I don't see EINTR documented in ioctl(2) nor in Linux'
> > > Documentation/virt/kvm/api.rst for KVM_CREATE_VM, but for KVM_RUN it
> > > says "an unmasked signal is pending".
> >
> > I am suggested that almost any blocking syscall could return EINTR, so I
> > checked the strace log and it does not show evidence of arriving a signal,
> > the log ends like this:
> >
> >   1152244 openat(AT_FDCWD, "/dev/kvm", O_RDWR|O_CLOEXEC) = 9
> >   1152244 ioctl(9, KVM_CHECK_EXTENSION, KVM_CAP_ARM_VM_IPA_SIZE) = 48
> >   1152244 ioctl(9, KVM_CREATE_VM, 0x30)   = -1 EINTR (Interrupted system call)
> >   1152244 close(9)                        = 0
> >   1152244 newfstatat(2, "", {st_dev=makedev(0, 0xd), st_ino=57869925, st_mode=S_IFIFO|0600, st_nlink=1, st_uid=517, st_gid=517, st_blksize=4096, st_blocks=0, st_size=0, st_atime=1660268019 /* 2022-08-12T01:33:39.850436293+0000 */, st_atime_nsec=850436293, st_mtime=1660268019 /* 2022-08-12T01:33:39.850436293+0000 */, st_mtime_nsec=850436293, st_ctime=1660268019 /* 2022-08-12T01:33:39.850436293+0000 */, st_ctime_nsec=850436293}, AT_EMPTY_PATH) = 0
> >   1152244 write(2, "qemu-system-aarch64: Failed to r"..., 58) = 58
> >   1152244 exit_group(1)                   = ?
> >   1152245 <... clock_nanosleep resumed> <unfinished ...>) = ?
> >   1152245 +++ exited with 1 +++
> >   1152244 +++ exited with 1 +++
> 
> KVM folks: should we expect that KVM_CREATE_VM might fail EINTR
> and need retrying?
> 
> (I suspect the answer is "yes", given we do this in the generic
> code in kvm-all.c.)

Interestingly, this has cropped up in the (distant) past:

https://lists.gnu.org/archive/html/qemu-devel/2014-01/msg01031.html

and seems to point at the path I was mentioning earlier (the code
hasn't changed too much since, apparently).

I'd still like to understand the underlying reason though.

Thanks,

	M.

-- 
Without deviation from the norm, progress is not possible.


^ permalink raw reply	[flat|nested] 12+ messages in thread

* Re: qemu-system-aarch64: Failed to retrieve host CPU features
  2022-08-12 15:02       ` Marc Zyngier
@ 2022-08-13 11:11         ` Vitaly Chikunov
  -1 siblings, 0 replies; 12+ messages in thread
From: Vitaly Chikunov @ 2022-08-13 11:11 UTC (permalink / raw)
  To: Marc Zyngier
  Cc: Peter Maydell, qemu-arm, kvmarm, QEMU Developers, Dmitry V. Levin

Marc,

On Fri, Aug 12, 2022 at 04:02:37PM +0100, Marc Zyngier wrote:
> On Fri, 12 Aug 2022 10:25:55 +0100,
> Peter Maydell <peter.maydell@linaro.org> wrote:
> > 
> > I've added some more relevant mailing lists to the cc.
> > 
> > On Fri, 12 Aug 2022 at 09:45, Vitaly Chikunov <vt@altlinux.org> wrote:
> > > On Fri, Aug 12, 2022 at 05:14:27AM +0300, Vitaly Chikunov wrote:
> > > > I noticed that we starting to get many errors like this:
> > > >
> > > >   qemu-system-aarch64: Failed to retrieve host CPU features
> > > >
> > > > Where many is 1-2% per run, depends on host, host is Kunpeng-920, and
> > > > Linux kernel is v5.15.59, but it started to appear months before that.
> > > >
> > > > strace shows in erroneous case:
> > > >
> > > >   1152244 ioctl(9, KVM_CREATE_VM, 0x30)   = -1 EINTR (Interrupted system call)
> > > >
> > > > And I see in target/arm/kvm.c:kvm_arm_create_scratch_host_vcpu:
> > > >
> > > >     vmfd = ioctl(kvmfd, KVM_CREATE_VM, max_vm_pa_size);
> > > >     if (vmfd < 0) {
> > > >         goto err;
> > > >     }
> > > >
> > > > Maybe it should restart ioctl on EINTR?
> > > >
> > > > I don't see EINTR documented in ioctl(2) nor in Linux'
> > > > Documentation/virt/kvm/api.rst for KVM_CREATE_VM, but for KVM_RUN it
> > > > says "an unmasked signal is pending".
> > >
> > > I am suggested that almost any blocking syscall could return EINTR, so I
> > > checked the strace log and it does not show evidence of arriving a signal,
> > > the log ends like this:
> > >
> > >   1152244 openat(AT_FDCWD, "/dev/kvm", O_RDWR|O_CLOEXEC) = 9
> > >   1152244 ioctl(9, KVM_CHECK_EXTENSION, KVM_CAP_ARM_VM_IPA_SIZE) = 48
> > >   1152244 ioctl(9, KVM_CREATE_VM, 0x30)   = -1 EINTR (Interrupted system call)
> > >   1152244 close(9)                        = 0
> > >   1152244 newfstatat(2, "", {st_dev=makedev(0, 0xd), st_ino=57869925, st_mode=S_IFIFO|0600, st_nlink=1, st_uid=517, st_gid=517, st_blksize=4096, st_blocks=0, st_size=0, st_atime=1660268019 /* 2022-08-12T01:33:39.850436293+0000 */, st_atime_nsec=850436293, st_mtime=1660268019 /* 2022-08-12T01:33:39.850436293+0000 */, st_mtime_nsec=850436293, st_ctime=1660268019 /* 2022-08-12T01:33:39.850436293+0000 */, st_ctime_nsec=850436293}, AT_EMPTY_PATH) = 0
> > >   1152244 write(2, "qemu-system-aarch64: Failed to r"..., 58) = 58
> > >   1152244 exit_group(1)                   = ?
> > >   1152245 <... clock_nanosleep resumed> <unfinished ...>) = ?
> > >   1152245 +++ exited with 1 +++
> > >   1152244 +++ exited with 1 +++
> > 
> > KVM folks: should we expect that KVM_CREATE_VM might fail EINTR
> > and need retrying?
> 
> In general, yes. But for this particular one, this is pretty odd.
> 
> The only path I can so far see that would match this behaviour is if
> mm_take_all_locks() (called from __mmu_notifier_register()) was
> getting interrupted by a signal (I'm looking at a 5.19-ish kernel,
> which may slightly differ from the 5.15 mentioned above).
> 
> But as Vitaly points out, it doesn't seem to be a signal delivered
> here.
> 
> Vitaly: could you please share your exact test case (full qemu command
> line), and instrument your kernel to see if mm_take_all_locks() is the
> one failing?

Full command is `qemu-system-aarch64 -M accel=kvm:tcg -m 4096M -smp
  cores=8 -nodefaults -nographic -no-reboot -fsdev
  local,id=root,path=/,security_model=none,multidevs=remap -device
  virtio-9p-pci,fsdev=root,mount_tag=/dev/root -device virtio-rng-pci
  -serial mon:stdio -kernel /boot/vmlinuz-5.18.16-un-def-alt1 -initrd
  /usr/src/tmp/initramfs-5.18.16-un-def-alt1.img -sandbox on,spawn=deny -M
  virt,gic-version=3 -cpu max -append 'console=ttyAMA0 mitigations=off
  nokaslr quiet panic=-1 SCRIPT=/usr/src/tmp/tmp.458pkF5r8d'`.

But a minified reproducer is `qemu-system-aarch64 -M virt,accel=kvm -cpu max -kernel qwe`. 

I traced with kprobe event tracer with the probes:

  echo 'p kvm_dev_ioctl'               > kprobe_events
  echo 'r kvm_dev_ioctl $retval'      >> kprobe_events
  echo 'p mm_take_all_locks'          >> kprobe_events
  echo 'r mm_take_all_locks $retval'  >> kprobe_events

Then run reproducer in the loop

  for ((i=0;i<100;i++));do echo $i; strace -fvo bb.$i qemu-system-aarch64 -M virt,accel=kvm -cpu max -kernel qwe 2>&1 | grep Failed && break; done

And on 97th iteration it's failed, strace log to check that PID is the same with
the following trace:

  3611463 ioctl(9, KVM_CREATE_VM, 0x30)   = -1 EINTR (Interrupted system call)

Event trace log:

  qemu-system-aar-3611463 [002] d.... 342920.535549: p_kvm_dev_ioctl_0: (kvm_dev_ioctl+0x0/0x910)
  qemu-system-aar-3611463 [002] d.... 342920.535635: p_mm_take_all_locks_0: (mm_take_all_locks+0x0/0x390)
  qemu-system-aar-3611463 [002] ..... 342920.535657: r_mm_take_all_locks_0: (__mmu_notifier_register+0x44/0x200 <- mm_take_all_locks) arg1=0xfffffffc
  qemu-system-aar-3611463 [002] ..... 342920.535695: r_kvm_dev_ioctl_0: (__arm64_sys_ioctl+0xcc/0x124 <- kvm_dev_ioctl) arg1=0xfffffffffffffffc

So that's mm_take_all_locks returns EINTR.

(I tried also to make C reproducer which opens /dev/kvm and call
`ioctl(kvm, KVM_CREATE_VM, 0)` in the loop and it does not reproduce the
problem, so it seems it's also something additional that QEMU does.)

Thanks,


^ permalink raw reply	[flat|nested] 12+ messages in thread

* Re: qemu-system-aarch64: Failed to retrieve host CPU features
@ 2022-08-13 11:11         ` Vitaly Chikunov
  0 siblings, 0 replies; 12+ messages in thread
From: Vitaly Chikunov @ 2022-08-13 11:11 UTC (permalink / raw)
  To: Marc Zyngier; +Cc: qemu-arm, Dmitry V. Levin, kvmarm, QEMU Developers

Marc,

On Fri, Aug 12, 2022 at 04:02:37PM +0100, Marc Zyngier wrote:
> On Fri, 12 Aug 2022 10:25:55 +0100,
> Peter Maydell <peter.maydell@linaro.org> wrote:
> > 
> > I've added some more relevant mailing lists to the cc.
> > 
> > On Fri, 12 Aug 2022 at 09:45, Vitaly Chikunov <vt@altlinux.org> wrote:
> > > On Fri, Aug 12, 2022 at 05:14:27AM +0300, Vitaly Chikunov wrote:
> > > > I noticed that we starting to get many errors like this:
> > > >
> > > >   qemu-system-aarch64: Failed to retrieve host CPU features
> > > >
> > > > Where many is 1-2% per run, depends on host, host is Kunpeng-920, and
> > > > Linux kernel is v5.15.59, but it started to appear months before that.
> > > >
> > > > strace shows in erroneous case:
> > > >
> > > >   1152244 ioctl(9, KVM_CREATE_VM, 0x30)   = -1 EINTR (Interrupted system call)
> > > >
> > > > And I see in target/arm/kvm.c:kvm_arm_create_scratch_host_vcpu:
> > > >
> > > >     vmfd = ioctl(kvmfd, KVM_CREATE_VM, max_vm_pa_size);
> > > >     if (vmfd < 0) {
> > > >         goto err;
> > > >     }
> > > >
> > > > Maybe it should restart ioctl on EINTR?
> > > >
> > > > I don't see EINTR documented in ioctl(2) nor in Linux'
> > > > Documentation/virt/kvm/api.rst for KVM_CREATE_VM, but for KVM_RUN it
> > > > says "an unmasked signal is pending".
> > >
> > > I am suggested that almost any blocking syscall could return EINTR, so I
> > > checked the strace log and it does not show evidence of arriving a signal,
> > > the log ends like this:
> > >
> > >   1152244 openat(AT_FDCWD, "/dev/kvm", O_RDWR|O_CLOEXEC) = 9
> > >   1152244 ioctl(9, KVM_CHECK_EXTENSION, KVM_CAP_ARM_VM_IPA_SIZE) = 48
> > >   1152244 ioctl(9, KVM_CREATE_VM, 0x30)   = -1 EINTR (Interrupted system call)
> > >   1152244 close(9)                        = 0
> > >   1152244 newfstatat(2, "", {st_dev=makedev(0, 0xd), st_ino=57869925, st_mode=S_IFIFO|0600, st_nlink=1, st_uid=517, st_gid=517, st_blksize=4096, st_blocks=0, st_size=0, st_atime=1660268019 /* 2022-08-12T01:33:39.850436293+0000 */, st_atime_nsec=850436293, st_mtime=1660268019 /* 2022-08-12T01:33:39.850436293+0000 */, st_mtime_nsec=850436293, st_ctime=1660268019 /* 2022-08-12T01:33:39.850436293+0000 */, st_ctime_nsec=850436293}, AT_EMPTY_PATH) = 0
> > >   1152244 write(2, "qemu-system-aarch64: Failed to r"..., 58) = 58
> > >   1152244 exit_group(1)                   = ?
> > >   1152245 <... clock_nanosleep resumed> <unfinished ...>) = ?
> > >   1152245 +++ exited with 1 +++
> > >   1152244 +++ exited with 1 +++
> > 
> > KVM folks: should we expect that KVM_CREATE_VM might fail EINTR
> > and need retrying?
> 
> In general, yes. But for this particular one, this is pretty odd.
> 
> The only path I can so far see that would match this behaviour is if
> mm_take_all_locks() (called from __mmu_notifier_register()) was
> getting interrupted by a signal (I'm looking at a 5.19-ish kernel,
> which may slightly differ from the 5.15 mentioned above).
> 
> But as Vitaly points out, it doesn't seem to be a signal delivered
> here.
> 
> Vitaly: could you please share your exact test case (full qemu command
> line), and instrument your kernel to see if mm_take_all_locks() is the
> one failing?

Full command is `qemu-system-aarch64 -M accel=kvm:tcg -m 4096M -smp
  cores=8 -nodefaults -nographic -no-reboot -fsdev
  local,id=root,path=/,security_model=none,multidevs=remap -device
  virtio-9p-pci,fsdev=root,mount_tag=/dev/root -device virtio-rng-pci
  -serial mon:stdio -kernel /boot/vmlinuz-5.18.16-un-def-alt1 -initrd
  /usr/src/tmp/initramfs-5.18.16-un-def-alt1.img -sandbox on,spawn=deny -M
  virt,gic-version=3 -cpu max -append 'console=ttyAMA0 mitigations=off
  nokaslr quiet panic=-1 SCRIPT=/usr/src/tmp/tmp.458pkF5r8d'`.

But a minified reproducer is `qemu-system-aarch64 -M virt,accel=kvm -cpu max -kernel qwe`. 

I traced with kprobe event tracer with the probes:

  echo 'p kvm_dev_ioctl'               > kprobe_events
  echo 'r kvm_dev_ioctl $retval'      >> kprobe_events
  echo 'p mm_take_all_locks'          >> kprobe_events
  echo 'r mm_take_all_locks $retval'  >> kprobe_events

Then run reproducer in the loop

  for ((i=0;i<100;i++));do echo $i; strace -fvo bb.$i qemu-system-aarch64 -M virt,accel=kvm -cpu max -kernel qwe 2>&1 | grep Failed && break; done

And on 97th iteration it's failed, strace log to check that PID is the same with
the following trace:

  3611463 ioctl(9, KVM_CREATE_VM, 0x30)   = -1 EINTR (Interrupted system call)

Event trace log:

  qemu-system-aar-3611463 [002] d.... 342920.535549: p_kvm_dev_ioctl_0: (kvm_dev_ioctl+0x0/0x910)
  qemu-system-aar-3611463 [002] d.... 342920.535635: p_mm_take_all_locks_0: (mm_take_all_locks+0x0/0x390)
  qemu-system-aar-3611463 [002] ..... 342920.535657: r_mm_take_all_locks_0: (__mmu_notifier_register+0x44/0x200 <- mm_take_all_locks) arg1=0xfffffffc
  qemu-system-aar-3611463 [002] ..... 342920.535695: r_kvm_dev_ioctl_0: (__arm64_sys_ioctl+0xcc/0x124 <- kvm_dev_ioctl) arg1=0xfffffffffffffffc

So that's mm_take_all_locks returns EINTR.

(I tried also to make C reproducer which opens /dev/kvm and call
`ioctl(kvm, KVM_CREATE_VM, 0)` in the loop and it does not reproduce the
problem, so it seems it's also something additional that QEMU does.)

Thanks,
_______________________________________________
kvmarm mailing list
kvmarm@lists.cs.columbia.edu
https://lists.cs.columbia.edu/mailman/listinfo/kvmarm

^ permalink raw reply	[flat|nested] 12+ messages in thread

* Re: qemu-system-aarch64: Failed to retrieve host CPU features
  2022-08-13 11:11         ` Vitaly Chikunov
@ 2022-08-13 13:32           ` Marc Zyngier
  -1 siblings, 0 replies; 12+ messages in thread
From: Marc Zyngier @ 2022-08-13 13:32 UTC (permalink / raw)
  To: Vitaly Chikunov; +Cc: qemu-arm, Dmitry V. Levin, kvmarm, QEMU Developers

On Sat, 13 Aug 2022 12:11:37 +0100,
Vitaly Chikunov <vt@altlinux.org> wrote:
> 
> Marc,
> 
> On Fri, Aug 12, 2022 at 04:02:37PM +0100, Marc Zyngier wrote:
> > On Fri, 12 Aug 2022 10:25:55 +0100,
> > Peter Maydell <peter.maydell@linaro.org> wrote:
> > > 
> > > I've added some more relevant mailing lists to the cc.
> > > 
> > > On Fri, 12 Aug 2022 at 09:45, Vitaly Chikunov <vt@altlinux.org> wrote:
> > > > On Fri, Aug 12, 2022 at 05:14:27AM +0300, Vitaly Chikunov wrote:
> > > > > I noticed that we starting to get many errors like this:
> > > > >
> > > > >   qemu-system-aarch64: Failed to retrieve host CPU features
> > > > >
> > > > > Where many is 1-2% per run, depends on host, host is Kunpeng-920, and
> > > > > Linux kernel is v5.15.59, but it started to appear months before that.
> > > > >
> > > > > strace shows in erroneous case:
> > > > >
> > > > >   1152244 ioctl(9, KVM_CREATE_VM, 0x30)   = -1 EINTR (Interrupted system call)
> > > > >
> > > > > And I see in target/arm/kvm.c:kvm_arm_create_scratch_host_vcpu:
> > > > >
> > > > >     vmfd = ioctl(kvmfd, KVM_CREATE_VM, max_vm_pa_size);
> > > > >     if (vmfd < 0) {
> > > > >         goto err;
> > > > >     }
> > > > >
> > > > > Maybe it should restart ioctl on EINTR?
> > > > >
> > > > > I don't see EINTR documented in ioctl(2) nor in Linux'
> > > > > Documentation/virt/kvm/api.rst for KVM_CREATE_VM, but for KVM_RUN it
> > > > > says "an unmasked signal is pending".
> > > >
> > > > I am suggested that almost any blocking syscall could return EINTR, so I
> > > > checked the strace log and it does not show evidence of arriving a signal,
> > > > the log ends like this:
> > > >
> > > >   1152244 openat(AT_FDCWD, "/dev/kvm", O_RDWR|O_CLOEXEC) = 9
> > > >   1152244 ioctl(9, KVM_CHECK_EXTENSION, KVM_CAP_ARM_VM_IPA_SIZE) = 48
> > > >   1152244 ioctl(9, KVM_CREATE_VM, 0x30)   = -1 EINTR (Interrupted system call)
> > > >   1152244 close(9)                        = 0
> > > >   1152244 newfstatat(2, "", {st_dev=makedev(0, 0xd), st_ino=57869925, st_mode=S_IFIFO|0600, st_nlink=1, st_uid=517, st_gid=517, st_blksize=4096, st_blocks=0, st_size=0, st_atime=1660268019 /* 2022-08-12T01:33:39.850436293+0000 */, st_atime_nsec=850436293, st_mtime=1660268019 /* 2022-08-12T01:33:39.850436293+0000 */, st_mtime_nsec=850436293, st_ctime=1660268019 /* 2022-08-12T01:33:39.850436293+0000 */, st_ctime_nsec=850436293}, AT_EMPTY_PATH) = 0
> > > >   1152244 write(2, "qemu-system-aarch64: Failed to r"..., 58) = 58
> > > >   1152244 exit_group(1)                   = ?
> > > >   1152245 <... clock_nanosleep resumed> <unfinished ...>) = ?
> > > >   1152245 +++ exited with 1 +++
> > > >   1152244 +++ exited with 1 +++
> > > 
> > > KVM folks: should we expect that KVM_CREATE_VM might fail EINTR
> > > and need retrying?
> > 
> > In general, yes. But for this particular one, this is pretty odd.
> > 
> > The only path I can so far see that would match this behaviour is if
> > mm_take_all_locks() (called from __mmu_notifier_register()) was
> > getting interrupted by a signal (I'm looking at a 5.19-ish kernel,
> > which may slightly differ from the 5.15 mentioned above).
> > 
> > But as Vitaly points out, it doesn't seem to be a signal delivered
> > here.
> > 
> > Vitaly: could you please share your exact test case (full qemu command
> > line), and instrument your kernel to see if mm_take_all_locks() is the
> > one failing?
> 
> Full command is `qemu-system-aarch64 -M accel=kvm:tcg -m 4096M -smp
>   cores=8 -nodefaults -nographic -no-reboot -fsdev
>   local,id=root,path=/,security_model=none,multidevs=remap -device
>   virtio-9p-pci,fsdev=root,mount_tag=/dev/root -device virtio-rng-pci
>   -serial mon:stdio -kernel /boot/vmlinuz-5.18.16-un-def-alt1 -initrd
>   /usr/src/tmp/initramfs-5.18.16-un-def-alt1.img -sandbox on,spawn=deny -M
>   virt,gic-version=3 -cpu max -append 'console=ttyAMA0 mitigations=off
>   nokaslr quiet panic=-1 SCRIPT=/usr/src/tmp/tmp.458pkF5r8d'`.
> 
> But a minified reproducer is `qemu-system-aarch64 -M virt,accel=kvm -cpu max -kernel qwe`. 

Ah, couldn't be smaller! ;-) Thanks for that!

>
> I traced with kprobe event tracer with the probes:
> 
>   echo 'p kvm_dev_ioctl'               > kprobe_events
>   echo 'r kvm_dev_ioctl $retval'      >> kprobe_events
>   echo 'p mm_take_all_locks'          >> kprobe_events
>   echo 'r mm_take_all_locks $retval'  >> kprobe_events
> 
> Then run reproducer in the loop
> 
>   for ((i=0;i<100;i++));do echo $i; strace -fvo bb.$i qemu-system-aarch64 -M virt,accel=kvm -cpu max -kernel qwe 2>&1 | grep Failed && break; done
> 
> And on 97th iteration it's failed, strace log to check that PID is the same with
> the following trace:
> 
>   3611463 ioctl(9, KVM_CREATE_VM, 0x30)   = -1 EINTR (Interrupted system call)
> 
> Event trace log:
> 
>   qemu-system-aar-3611463 [002] d.... 342920.535549: p_kvm_dev_ioctl_0: (kvm_dev_ioctl+0x0/0x910)
>   qemu-system-aar-3611463 [002] d.... 342920.535635: p_mm_take_all_locks_0: (mm_take_all_locks+0x0/0x390)
>   qemu-system-aar-3611463 [002] ..... 342920.535657: r_mm_take_all_locks_0: (__mmu_notifier_register+0x44/0x200 <- mm_take_all_locks) arg1=0xfffffffc
>   qemu-system-aar-3611463 [002] ..... 342920.535695: r_kvm_dev_ioctl_0: (__arm64_sys_ioctl+0xcc/0x124 <- kvm_dev_ioctl) arg1=0xfffffffffffffffc
> 
> So that's mm_take_all_locks returns EINTR.
> 
> (I tried also to make C reproducer which opens /dev/kvm and call
> `ioctl(kvm, KVM_CREATE_VM, 0)` in the loop and it does not reproduce the
> problem, so it seems it's also something additional that QEMU does.)

On my fast test box, it takes several hundreds of iterations to fire,
but that's not completely impossible to trigger (strace actually helps
here). I was expecting it to fire more on a slow one, but that's not
the case.

And indeed, no signal seems to be delivered. I suspect that
FIT_NOTIFY_SIGNAL is set, but I need to investigate more. With a
reproducer, it should be easier to diagnose fully.

But we probably need to handle EINTR when creating the mini VM.

	M.

-- 
Without deviation from the norm, progress is not possible.
_______________________________________________
kvmarm mailing list
kvmarm@lists.cs.columbia.edu
https://lists.cs.columbia.edu/mailman/listinfo/kvmarm

^ permalink raw reply	[flat|nested] 12+ messages in thread

* Re: qemu-system-aarch64: Failed to retrieve host CPU features
@ 2022-08-13 13:32           ` Marc Zyngier
  0 siblings, 0 replies; 12+ messages in thread
From: Marc Zyngier @ 2022-08-13 13:32 UTC (permalink / raw)
  To: Vitaly Chikunov
  Cc: Peter Maydell, qemu-arm, kvmarm, QEMU Developers, Dmitry V. Levin

On Sat, 13 Aug 2022 12:11:37 +0100,
Vitaly Chikunov <vt@altlinux.org> wrote:
> 
> Marc,
> 
> On Fri, Aug 12, 2022 at 04:02:37PM +0100, Marc Zyngier wrote:
> > On Fri, 12 Aug 2022 10:25:55 +0100,
> > Peter Maydell <peter.maydell@linaro.org> wrote:
> > > 
> > > I've added some more relevant mailing lists to the cc.
> > > 
> > > On Fri, 12 Aug 2022 at 09:45, Vitaly Chikunov <vt@altlinux.org> wrote:
> > > > On Fri, Aug 12, 2022 at 05:14:27AM +0300, Vitaly Chikunov wrote:
> > > > > I noticed that we starting to get many errors like this:
> > > > >
> > > > >   qemu-system-aarch64: Failed to retrieve host CPU features
> > > > >
> > > > > Where many is 1-2% per run, depends on host, host is Kunpeng-920, and
> > > > > Linux kernel is v5.15.59, but it started to appear months before that.
> > > > >
> > > > > strace shows in erroneous case:
> > > > >
> > > > >   1152244 ioctl(9, KVM_CREATE_VM, 0x30)   = -1 EINTR (Interrupted system call)
> > > > >
> > > > > And I see in target/arm/kvm.c:kvm_arm_create_scratch_host_vcpu:
> > > > >
> > > > >     vmfd = ioctl(kvmfd, KVM_CREATE_VM, max_vm_pa_size);
> > > > >     if (vmfd < 0) {
> > > > >         goto err;
> > > > >     }
> > > > >
> > > > > Maybe it should restart ioctl on EINTR?
> > > > >
> > > > > I don't see EINTR documented in ioctl(2) nor in Linux'
> > > > > Documentation/virt/kvm/api.rst for KVM_CREATE_VM, but for KVM_RUN it
> > > > > says "an unmasked signal is pending".
> > > >
> > > > I am suggested that almost any blocking syscall could return EINTR, so I
> > > > checked the strace log and it does not show evidence of arriving a signal,
> > > > the log ends like this:
> > > >
> > > >   1152244 openat(AT_FDCWD, "/dev/kvm", O_RDWR|O_CLOEXEC) = 9
> > > >   1152244 ioctl(9, KVM_CHECK_EXTENSION, KVM_CAP_ARM_VM_IPA_SIZE) = 48
> > > >   1152244 ioctl(9, KVM_CREATE_VM, 0x30)   = -1 EINTR (Interrupted system call)
> > > >   1152244 close(9)                        = 0
> > > >   1152244 newfstatat(2, "", {st_dev=makedev(0, 0xd), st_ino=57869925, st_mode=S_IFIFO|0600, st_nlink=1, st_uid=517, st_gid=517, st_blksize=4096, st_blocks=0, st_size=0, st_atime=1660268019 /* 2022-08-12T01:33:39.850436293+0000 */, st_atime_nsec=850436293, st_mtime=1660268019 /* 2022-08-12T01:33:39.850436293+0000 */, st_mtime_nsec=850436293, st_ctime=1660268019 /* 2022-08-12T01:33:39.850436293+0000 */, st_ctime_nsec=850436293}, AT_EMPTY_PATH) = 0
> > > >   1152244 write(2, "qemu-system-aarch64: Failed to r"..., 58) = 58
> > > >   1152244 exit_group(1)                   = ?
> > > >   1152245 <... clock_nanosleep resumed> <unfinished ...>) = ?
> > > >   1152245 +++ exited with 1 +++
> > > >   1152244 +++ exited with 1 +++
> > > 
> > > KVM folks: should we expect that KVM_CREATE_VM might fail EINTR
> > > and need retrying?
> > 
> > In general, yes. But for this particular one, this is pretty odd.
> > 
> > The only path I can so far see that would match this behaviour is if
> > mm_take_all_locks() (called from __mmu_notifier_register()) was
> > getting interrupted by a signal (I'm looking at a 5.19-ish kernel,
> > which may slightly differ from the 5.15 mentioned above).
> > 
> > But as Vitaly points out, it doesn't seem to be a signal delivered
> > here.
> > 
> > Vitaly: could you please share your exact test case (full qemu command
> > line), and instrument your kernel to see if mm_take_all_locks() is the
> > one failing?
> 
> Full command is `qemu-system-aarch64 -M accel=kvm:tcg -m 4096M -smp
>   cores=8 -nodefaults -nographic -no-reboot -fsdev
>   local,id=root,path=/,security_model=none,multidevs=remap -device
>   virtio-9p-pci,fsdev=root,mount_tag=/dev/root -device virtio-rng-pci
>   -serial mon:stdio -kernel /boot/vmlinuz-5.18.16-un-def-alt1 -initrd
>   /usr/src/tmp/initramfs-5.18.16-un-def-alt1.img -sandbox on,spawn=deny -M
>   virt,gic-version=3 -cpu max -append 'console=ttyAMA0 mitigations=off
>   nokaslr quiet panic=-1 SCRIPT=/usr/src/tmp/tmp.458pkF5r8d'`.
> 
> But a minified reproducer is `qemu-system-aarch64 -M virt,accel=kvm -cpu max -kernel qwe`. 

Ah, couldn't be smaller! ;-) Thanks for that!

>
> I traced with kprobe event tracer with the probes:
> 
>   echo 'p kvm_dev_ioctl'               > kprobe_events
>   echo 'r kvm_dev_ioctl $retval'      >> kprobe_events
>   echo 'p mm_take_all_locks'          >> kprobe_events
>   echo 'r mm_take_all_locks $retval'  >> kprobe_events
> 
> Then run reproducer in the loop
> 
>   for ((i=0;i<100;i++));do echo $i; strace -fvo bb.$i qemu-system-aarch64 -M virt,accel=kvm -cpu max -kernel qwe 2>&1 | grep Failed && break; done
> 
> And on 97th iteration it's failed, strace log to check that PID is the same with
> the following trace:
> 
>   3611463 ioctl(9, KVM_CREATE_VM, 0x30)   = -1 EINTR (Interrupted system call)
> 
> Event trace log:
> 
>   qemu-system-aar-3611463 [002] d.... 342920.535549: p_kvm_dev_ioctl_0: (kvm_dev_ioctl+0x0/0x910)
>   qemu-system-aar-3611463 [002] d.... 342920.535635: p_mm_take_all_locks_0: (mm_take_all_locks+0x0/0x390)
>   qemu-system-aar-3611463 [002] ..... 342920.535657: r_mm_take_all_locks_0: (__mmu_notifier_register+0x44/0x200 <- mm_take_all_locks) arg1=0xfffffffc
>   qemu-system-aar-3611463 [002] ..... 342920.535695: r_kvm_dev_ioctl_0: (__arm64_sys_ioctl+0xcc/0x124 <- kvm_dev_ioctl) arg1=0xfffffffffffffffc
> 
> So that's mm_take_all_locks returns EINTR.
> 
> (I tried also to make C reproducer which opens /dev/kvm and call
> `ioctl(kvm, KVM_CREATE_VM, 0)` in the loop and it does not reproduce the
> problem, so it seems it's also something additional that QEMU does.)

On my fast test box, it takes several hundreds of iterations to fire,
but that's not completely impossible to trigger (strace actually helps
here). I was expecting it to fire more on a slow one, but that's not
the case.

And indeed, no signal seems to be delivered. I suspect that
FIT_NOTIFY_SIGNAL is set, but I need to investigate more. With a
reproducer, it should be easier to diagnose fully.

But we probably need to handle EINTR when creating the mini VM.

	M.

-- 
Without deviation from the norm, progress is not possible.


^ permalink raw reply	[flat|nested] 12+ messages in thread

* Re: qemu-system-aarch64: Failed to retrieve host CPU features
  2022-08-13 13:32           ` Marc Zyngier
@ 2022-08-16 12:31             ` Peter Maydell
  -1 siblings, 0 replies; 12+ messages in thread
From: Peter Maydell @ 2022-08-16 12:31 UTC (permalink / raw)
  To: Marc Zyngier
  Cc: Vitaly Chikunov, qemu-arm, Dmitry V. Levin, kvmarm, QEMU Developers

On Sat, 13 Aug 2022 at 14:32, Marc Zyngier <maz@kernel.org> wrote:
> But we probably need to handle EINTR when creating the mini VM.

It's easy enough to add a retry-on-EINTR loop to the KVM_CREATE_VM
ioctl in the target/arm/ code. But do we need to do that more
widely ? At the moment QEMU seems to assume that KVM ioctls
will never fail EINTR except for the one special-cased
KVM_CREATE_VM, plus (more obviously) KVM_RUN...

thanks
-- PMM
_______________________________________________
kvmarm mailing list
kvmarm@lists.cs.columbia.edu
https://lists.cs.columbia.edu/mailman/listinfo/kvmarm

^ permalink raw reply	[flat|nested] 12+ messages in thread

* Re: qemu-system-aarch64: Failed to retrieve host CPU features
@ 2022-08-16 12:31             ` Peter Maydell
  0 siblings, 0 replies; 12+ messages in thread
From: Peter Maydell @ 2022-08-16 12:31 UTC (permalink / raw)
  To: Marc Zyngier
  Cc: Vitaly Chikunov, qemu-arm, kvmarm, QEMU Developers, Dmitry V. Levin

On Sat, 13 Aug 2022 at 14:32, Marc Zyngier <maz@kernel.org> wrote:
> But we probably need to handle EINTR when creating the mini VM.

It's easy enough to add a retry-on-EINTR loop to the KVM_CREATE_VM
ioctl in the target/arm/ code. But do we need to do that more
widely ? At the moment QEMU seems to assume that KVM ioctls
will never fail EINTR except for the one special-cased
KVM_CREATE_VM, plus (more obviously) KVM_RUN...

thanks
-- PMM


^ permalink raw reply	[flat|nested] 12+ messages in thread

end of thread, other threads:[~2022-08-16 12:39 UTC | newest]

Thread overview: 12+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
     [not found] <20220812021427.cwenhciuftgtaj64@altlinux.org>
     [not found] ` <20220812084529.ur5qcyws5qvoyvuc@altlinux.org>
2022-08-12  9:25   ` qemu-system-aarch64: Failed to retrieve host CPU features Peter Maydell
2022-08-12  9:25     ` Peter Maydell
2022-08-12 15:02     ` Marc Zyngier
2022-08-12 15:02       ` Marc Zyngier
2022-08-13 11:11       ` Vitaly Chikunov
2022-08-13 11:11         ` Vitaly Chikunov
2022-08-13 13:32         ` Marc Zyngier
2022-08-13 13:32           ` Marc Zyngier
2022-08-16 12:31           ` Peter Maydell
2022-08-16 12:31             ` Peter Maydell
2022-08-12 15:10     ` Marc Zyngier
2022-08-12 15:10       ` Marc Zyngier

This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.