Debian Bug report logs - #785557
QEMU: causes vCPU steal time overflow on live migration

Toggle useless messages

Message #5 received at submit@bugs.debian.org (full text, mbox, reply):

From: Niko Tyni <ntyni@debian.org>

To: submit@bugs.debian.org

Subject: perl: FTBFS on i386 and amd64: itimer problems on buildds?

Date: Sun, 17 May 2015 22:18:52 +0300

Package: perl
Version: 5.20.2-3
Severity: serious
Tags: unreproducible help stretch sid
X-Debbugs-Cc: Kurt Roeckx <kurt@roeckx.be>, debian-admin@lists.debian.org

As discussed in the thread at
 http://lists.alioth.debian.org/pipermail/perl-maintainers/2015-May/004855.html

perl currently fails to build on several i386 and amd64 buildds due
to failing / hanging timer related tests.

 https://buildd.debian.org/status/logs.php?pkg=perl&arch=amd64
 https://buildd.debian.org/status/logs.php?pkg=perl&arch=i386

Kurt (cc'd) says the buildds were recently upgraded to jessie, except
that x86-grnet-01 was running jessie already in late March when
the first failure of this kind happened (5.20.2-3/i386). 

So it looks like the tests only fail when the buildd is running jessie,
but not on every host and/or every build.

So far we haven't been able to reproduce this outside the buildds.

DSA (also cc'd): What's the virtualization setup with x86-grnet-01,
brahms and binet? Is there a difference with babin, which managed
to build the i386 binaries? Are the underlying virtualization hosts
running jessie too? 

Reporting this against the perl version in stable, but I'm not sure yet
if it affects stable buildds. I expect it does, but tagging as stretch+sid
for now. Clearly something somewhere needs to be fixed before a release...

 # Failed test 2 - very basic times test at op/time.t line 33
 t/op/time ..................................................... FAILED at test 2

 t/itimer.t: overall time allowed for tests (360s) exceeded!
 cpan/Time-HiRes/t/itimer ...................................... FAILED--expected 2 tests, saw 1

 lib/Benchmark ................................................. makefile:807: recipe for target 'test' failed
 Build killed with signal TERM after 150 minutes of inactivity
 
-- 
Niko Tyni   ntyni@debian.org

Message #10 received at 785557@bugs.debian.org (full text, mbox, reply):

From: Martin Zobel-Helas <zobel@ftbfs.de>

To: Niko Tyni <ntyni@debian.org>, 785557@bugs.debian.org

Subject: Re: Bug#785557: perl: FTBFS on i386 and amd64: itimer problems on buildds?

Date: Mon, 18 May 2015 09:44:24 +0200

Hi, 

On Sun May 17, 2015 at 22:18:52 +0300, Niko Tyni wrote:
> DSA (also cc'd): What's the virtualization setup with x86-grnet-01,
> brahms and binet? Is there a difference with babin, which managed
> to build the i386 binaries? Are the underlying virtualization hosts
> running jessie too? 

ganeti, using qemu for all architectures. The underlying virtualization
hosts for x86-grnet-01 and brahms run jessie, binet's virtualization
host still runs wheezy. All VMs are bootstraped by DSA with the same
script, which is available at [1]. After the bootstrapping is done,
buildd maintainers take over and setup the buildd on the VM.

Cheers,
Martin

[1]http://anonscm.debian.org/cgit/mirror/dsa-misc.git/tree/scripts/VM-installs/ganeti-unified
-- 
 Martin Zobel-Helas <zobel@debian.org>    Debian System Administrator
 Debian & GNU/Linux Developer                       Debian Listmaster
 http://about.me/zobel                               Debian Webmaster
 GPG Fingerprint:  6B18 5642 8E41 EC89 3D5D  BDBB 53B1 AC6D B11B 627B 

Message #15 received at 785557@bugs.debian.org (full text, mbox, reply):

From: Dominic Hargreaves <dom@earth.li>

To: 785557@bugs.debian.org

Subject: Re: Bug#785557: perl: FTBFS on i386 and amd64: itimer problems on buildds?

Date: Wed, 20 May 2015 21:01:26 +0100

On Mon, May 18, 2015 at 09:44:24AM +0200, Martin Zobel-Helas wrote:
> Hi, 
> 
> On Sun May 17, 2015 at 22:18:52 +0300, Niko Tyni wrote:
> > DSA (also cc'd): What's the virtualization setup with x86-grnet-01,
> > brahms and binet? Is there a difference with babin, which managed
> > to build the i386 binaries? Are the underlying virtualization hosts
> > running jessie too? 
> 
> ganeti, using qemu for all architectures. The underlying virtualization
> hosts for x86-grnet-01 and brahms run jessie, binet's virtualization
> host still runs wheezy. All VMs are bootstraped by DSA with the same
> script, which is available at [1]. After the bootstrapping is done,
> buildd maintainers take over and setup the buildd on the VM.

It seems to be reproducible on barriere.debian.org:

t/op/time ..................................................... # Failed test 2 - very basic times test at op/time.t line 33
FAILED at test 2

More digging needed.

Message #20 received at 785557@bugs.debian.org (full text, mbox, reply):

From: Dominic Hargreaves <dom@earth.li>

To: 785557@bugs.debian.org, debian-admin@lists.debian.org

Subject: Re: Bug#785557: perl: FTBFS on i386 and amd64: itimer problems on buildds?

Date: Sat, 23 May 2015 19:10:06 +0200

On Wed, May 20, 2015 at 09:01:26PM +0100, Dominic Hargreaves wrote:
> On Mon, May 18, 2015 at 09:44:24AM +0200, Martin Zobel-Helas wrote:
> > Hi, 
> > 
> > On Sun May 17, 2015 at 22:18:52 +0300, Niko Tyni wrote:
> > > DSA (also cc'd): What's the virtualization setup with x86-grnet-01,
> > > brahms and binet? Is there a difference with babin, which managed
> > > to build the i386 binaries? Are the underlying virtualization hosts
> > > running jessie too? 
> > 
> > ganeti, using qemu for all architectures. The underlying virtualization
> > hosts for x86-grnet-01 and brahms run jessie, binet's virtualization
> > host still runs wheezy. All VMs are bootstraped by DSA with the same
> > script, which is available at [1]. After the bootstrapping is done,
> > buildd maintainers take over and setup the buildd on the VM.
> 
> It seems to be reproducible on barriere.debian.org:
> 
> t/op/time ..................................................... # Failed test 2 - very basic times test at op/time.t line 33
> FAILED at test 2
> 
> More digging needed.

The test calls the times(2) system call, expecting to see the real  issue can be reduced to:

dom@barriere:~$ time yes > /dev/null
^C

real    0m2.768s
user    0m0.000s
sys 0m2.764s

We'd expect to instead 'yes' take 'user' time, like this:

dom@himalia:~$ time yes > /dev/null
^C

real    0m2.686s
user    0m2.656s
sys 0m0.032s

This is rather strange; any ideas from DSA?

Cheers,
Dominic.

Message #25 received at 785557@bugs.debian.org (full text, mbox, reply):

From: Paul Wise <pabs@debian.org>

To: 785557@bugs.debian.org, debian-admin@lists.debian.org

Subject: Re: Bug#785557: perl: FTBFS on i386 and amd64: itimer problems on buildds?

Date: Sun, 24 May 2015 14:55:00 +0800

[Message part 1 (text/plain, inline)]

On Sat, 2015-05-23 at 19:10 +0200, Dominic Hargreaves wrote:

> This is rather strange; any ideas from DSA?

The underlying hosts do not have the same issue.

All of the guests use the same virtual CPU version/flags.

All of the guests use the same Linux kernel version.

I guess diving into the Linux implementation of times(2) for clues would
be the next step for figuring out what the issue is here.

-- 
bye,
pabs

https://wiki.debian.org/PaulWise

[signature.asc (application/pgp-signature, inline)]

Message #30 received at 785557@bugs.debian.org (full text, mbox, reply):

From: Niko Tyni <ntyni@debian.org>

To: 785557@bugs.debian.org

Cc: debian-admin@lists.debian.org, debian-kernel@lists.debian.org

Subject: Re: Bug#785557: perl: FTBFS on i386 and amd64: itimer problems on buildds?

Date: Sun, 24 May 2015 14:09:47 +0300

On Sun, May 24, 2015 at 02:55:00PM +0800, Paul Wise wrote:
> On Sat, 2015-05-23 at 19:10 +0200, Dominic Hargreaves wrote:
> 
> > This is rather strange; any ideas from DSA?
> 
> The underlying hosts do not have the same issue.
> 
> All of the guests use the same virtual CPU version/flags.
> 
> All of the guests use the same Linux kernel version.

Thanks for the update.

> I guess diving into the Linux implementation of times(2) for clues would
> be the next step for figuring out what the issue is here.

I'm taking the kernel maintainers in the loop. The status here is that
times(2) seems to be misbehaving on some i386 and amd64 debian.org virtual
hosts running jessie (under ganeti/qemu, with jessie on the underlying
hosts too). These hosts include at least barriere and x86-grnet-01.

The misbehaviour is that user time stays at zero all the time, as seen
for example with 'time yes'. This is making perl fail to build from
source due to test failures, and I'd expect it to affect other things too.

Any help is appreciated.
-- 
Niko Tyni   ntyni@debian.org

Message #35 received at 785557@bugs.debian.org (full text, mbox, reply):

From: Ben Hutchings <ben@decadent.org.uk>

To: Niko Tyni <ntyni@debian.org>

Cc: 785557@bugs.debian.org, debian-admin@lists.debian.org, debian-kernel@lists.debian.org

Subject: Re: Bug#785557: perl: FTBFS on i386 and amd64: itimer problems on buildds?

Date: Sun, 24 May 2015 16:38:56 +0100

[Message part 1 (text/plain, inline)]

On Sun, 2015-05-24 at 14:09 +0300, Niko Tyni wrote:
> On Sun, May 24, 2015 at 02:55:00PM +0800, Paul Wise wrote:
> > On Sat, 2015-05-23 at 19:10 +0200, Dominic Hargreaves wrote:
> > 
> > > This is rather strange; any ideas from DSA?
> > 
> > The underlying hosts do not have the same issue.
> > 
> > All of the guests use the same virtual CPU version/flags.
> > 
> > All of the guests use the same Linux kernel version.
> 
> Thanks for the update.
> 
> > I guess diving into the Linux implementation of times(2) for clues would
> > be the next step for figuring out what the issue is here.
> 
> I'm taking the kernel maintainers in the loop. The status here is that
> times(2) seems to be misbehaving on some i386 and amd64 debian.org virtual
> hosts running jessie (under ganeti/qemu, with jessie on the underlying
> hosts too). These hosts include at least barriere and x86-grnet-01.
> 
> The misbehaviour is that user time stays at zero all the time, as seen
> for example with 'time yes'. This is making perl fail to build from
> source due to test failures, and I'd expect it to affect other things too.
> 
> Any help is appreciated.

I can't reproduce this, but wonder if it's related to #784960?

Ben.

-- 
Ben Hutchings
Experience is what causes a person to make new mistakes instead of old ones.

[signature.asc (application/pgp-signature, inline)]

Message #40 received at 785557@bugs.debian.org (full text, mbox, reply):

From: Apollon Oikonomopoulos <apoikos@debian.org>

To: Ben Hutchings <ben@decadent.org.uk>

Cc: Niko Tyni <ntyni@debian.org>, 785557@bugs.debian.org, debian-admin@lists.debian.org, debian-kernel@lists.debian.org

Subject: Re: Bug#785557: perl: FTBFS on i386 and amd64: itimer problems on buildds?

Date: Sun, 24 May 2015 19:38:19 +0300

On 16:38 Sun 24 May     , Ben Hutchings wrote:
> On Sun, 2015-05-24 at 14:09 +0300, Niko Tyni wrote:
> > On Sun, May 24, 2015 at 02:55:00PM +0800, Paul Wise wrote:
> > > On Sat, 2015-05-23 at 19:10 +0200, Dominic Hargreaves wrote:
> > > 
> > > > This is rather strange; any ideas from DSA?
> > > 
> > > The underlying hosts do not have the same issue.
> > > 
> > > All of the guests use the same virtual CPU version/flags.
> > > 
> > > All of the guests use the same Linux kernel version.
> > 
> > Thanks for the update.
> > 
> > > I guess diving into the Linux implementation of times(2) for clues would
> > > be the next step for figuring out what the issue is here.
> > 
> > I'm taking the kernel maintainers in the loop. The status here is that
> > times(2) seems to be misbehaving on some i386 and amd64 debian.org virtual
> > hosts running jessie (under ganeti/qemu, with jessie on the underlying
> > hosts too). These hosts include at least barriere and x86-grnet-01.
> > 
> > The misbehaviour is that user time stays at zero all the time, as seen
> > for example with 'time yes'. This is making perl fail to build from
> > source due to test failures, and I'd expect it to affect other things too.
> > 
> > Any help is appreciated.
> 
> I can't reproduce this, but wonder if it's related to #784960?

There seems to be something fundamentally broken in 
barriere.debian.org's CPU time accounting, not related to times(2) per 
se. Just issuing

  yes >/dev/null

and firing up top -d1 gives the following interesting results:

  - `yes' shows up taking 100% CPU time as expected, but
  - pressing `1' shows that all CPUs are idle (!)

htop OTOH displays all CPUs as constantly 100% busy, which is 
inconsistent with the system's load average (~0.8 at that point).

Also watching the output of `cat /proc/$(pidof yes)/stat | awk '{ print 
$14, $15 }'' ($14 is utime, $15 is stime per proc(5)) indeed shows 100% 
system time and 0 user time.

If you look at the `top' stats for all CPUs of barriere.debian.org, it 
looks as if the only thing that's correctly being accounted for is 
iowait time.

Cheers,
Apollon

Message #45 received at 785557@bugs.debian.org (full text, mbox, reply):

From: Dominic Hargreaves <dom@earth.li>

To: amd64@buildd.debian.org, 785557@bugs.debian.org, debian-admin@lists.debian.org, debian-kernel@lists.debian.org

Subject: Re: Bug#785557: perl: FTBFS on i386 and amd64: itimer problems on buildds?

Date: Mon, 1 Jun 2015 16:14:32 +0100

On Sun, May 24, 2015 at 07:38:19PM +0300, Apollon Oikonomopoulos wrote:
> On 16:38 Sun 24 May     , Ben Hutchings wrote:
> > On Sun, 2015-05-24 at 14:09 +0300, Niko Tyni wrote:
> > > On Sun, May 24, 2015 at 02:55:00PM +0800, Paul Wise wrote:
> > > > On Sat, 2015-05-23 at 19:10 +0200, Dominic Hargreaves wrote:
> > > > 
> > > > > This is rather strange; any ideas from DSA?
> > > > 
> > > > The underlying hosts do not have the same issue.
> > > > 
> > > > All of the guests use the same virtual CPU version/flags.
> > > > 
> > > > All of the guests use the same Linux kernel version.
> > > 
> > > Thanks for the update.
> > > 
> > > > I guess diving into the Linux implementation of times(2) for clues would
> > > > be the next step for figuring out what the issue is here.
> > > 
> > > I'm taking the kernel maintainers in the loop. The status here is that
> > > times(2) seems to be misbehaving on some i386 and amd64 debian.org virtual
> > > hosts running jessie (under ganeti/qemu, with jessie on the underlying
> > > hosts too). These hosts include at least barriere and x86-grnet-01.
> > > 
> > > The misbehaviour is that user time stays at zero all the time, as seen
> > > for example with 'time yes'. This is making perl fail to build from
> > > source due to test failures, and I'd expect it to affect other things too.
> > > 
> > > Any help is appreciated.
> > 
> > I can't reproduce this, but wonder if it's related to #784960?
> 
> There seems to be something fundamentally broken in 
> barriere.debian.org's CPU time accounting, not related to times(2) per 
> se. Just issuing
> 
>   yes >/dev/null
> 
> and firing up top -d1 gives the following interesting results:
> 
>   - `yes' shows up taking 100% CPU time as expected, but
>   - pressing `1' shows that all CPUs are idle (!)
> 
> htop OTOH displays all CPUs as constantly 100% busy, which is 
> inconsistent with the system's load average (~0.8 at that point).
> 
> Also watching the output of `cat /proc/$(pidof yes)/stat | awk '{ print 
> $14, $15 }'' ($14 is utime, $15 is stime per proc(5)) indeed shows 100% 
> system time and 0 user time.
> 
> If you look at the `top' stats for all CPUs of barriere.debian.org, it 
> looks as if the only thing that's correctly being accounted for is 
> iowait time.

It looks like the same thing has happened again on x86-grnet-01, meaning
we have issues[1] on

x86-grnet-01
brahms
binet

but not

babin
x86-csail-01

Buildd admins: please can the amd64 build of perl 5.22.0~rc2-2 be
given-back to see if it lands on a working host?

DSA: can you identify any differences between the working hosts and the
others which would help identify the root of this problem - assuming that
they all exhibit the same easy to reproduce behaviour seen above?

Thanks!
Dominic.

[1] <https://buildd.debian.org/status/logs.php?pkg=perl&arch=amd64>

Message #50 received at 785557@bugs.debian.org (full text, mbox, reply):

From: Kurt Roeckx <kurt@roeckx.be>

To: Dominic Hargreaves <dom@earth.li>

Cc: amd64@buildd.debian.org, 785557@bugs.debian.org, debian-admin@lists.debian.org, debian-kernel@lists.debian.org

Subject: Re: Bug#785557: perl: FTBFS on i386 and amd64: itimer problems on buildds?

Date: Mon, 1 Jun 2015 18:36:12 +0200

On Mon, Jun 01, 2015 at 04:14:32PM +0100, Dominic Hargreaves wrote:
> 
> Buildd admins: please can the amd64 build of perl 5.22.0~rc2-2 be
> given-back to see if it lands on a working host?

Given back.


Kurt

Message #55 received at 785557@bugs.debian.org (full text, mbox, reply):

From: Dominic Hargreaves <dom@earth.li>

To: 785557@bugs.debian.org, debian-admin@lists.debian.org, debian-kernel@lists.debian.org

Subject: Re: Bug#785557: perl: FTBFS on i386 and amd64: itimer problems on buildds?

Date: Fri, 5 Jun 2015 22:25:27 +0100

Control: severity -1 important
Control: retitle -1 perl: FTBFS on buildds with steal time issues

On Sun, May 24, 2015 at 07:38:19PM +0300, Apollon Oikonomopoulos wrote:
> On 16:38 Sun 24 May     , Ben Hutchings wrote:
> > On Sun, 2015-05-24 at 14:09 +0300, Niko Tyni wrote:
> > > On Sun, May 24, 2015 at 02:55:00PM +0800, Paul Wise wrote:
> > > > On Sat, 2015-05-23 at 19:10 +0200, Dominic Hargreaves wrote:
> > > > 
> > > > > This is rather strange; any ideas from DSA?
> > > > 
> > > > The underlying hosts do not have the same issue.
> > > > 
> > > > All of the guests use the same virtual CPU version/flags.
> > > > 
> > > > All of the guests use the same Linux kernel version.
> > > 
> > > Thanks for the update.
> > > 
> > > > I guess diving into the Linux implementation of times(2) for clues would
> > > > be the next step for figuring out what the issue is here.
> > > 
> > > I'm taking the kernel maintainers in the loop. The status here is that
> > > times(2) seems to be misbehaving on some i386 and amd64 debian.org virtual
> > > hosts running jessie (under ganeti/qemu, with jessie on the underlying
> > > hosts too). These hosts include at least barriere and x86-grnet-01.
> > > 
> > > The misbehaviour is that user time stays at zero all the time, as seen
> > > for example with 'time yes'. This is making perl fail to build from
> > > source due to test failures, and I'd expect it to affect other things too.
> > > 
> > > Any help is appreciated.
> > 
> > I can't reproduce this, but wonder if it's related to #784960?
> 
> There seems to be something fundamentally broken in 
> barriere.debian.org's CPU time accounting, not related to times(2) per 
> se. Just issuing
> 
>   yes >/dev/null
> 
> and firing up top -d1 gives the following interesting results:
> 
>   - `yes' shows up taking 100% CPU time as expected, but
>   - pressing `1' shows that all CPUs are idle (!)
> 
> htop OTOH displays all CPUs as constantly 100% busy, which is 
> inconsistent with the system's load average (~0.8 at that point).
> 
> Also watching the output of `cat /proc/$(pidof yes)/stat | awk '{ print 
> $14, $15 }'' ($14 is utime, $15 is stime per proc(5)) indeed shows 100% 
> system time and 0 user time.
> 
> If you look at the `top' stats for all CPUs of barriere.debian.org, it 
> looks as if the only thing that's correctly being accounted for is 
> iowait time.

Great to hear that you found the underlying cause[1] of this! I note
the workaround:

-cpu qemu64,-kvm_steal_time

which may be applicable to the Debian hosts?

Cheers,
Dominic.

[1] <https://lists.gnu.org/archive/html/qemu-devel/2015-06/msg01295.html>

Message #64 received at 785557@bugs.debian.org (full text, mbox, reply):

From: Apollon Oikonomopoulos <apoikos@debian.org>

To: 785557@bugs.debian.org

Cc: debian-admin@lists.debian.org, debian-kernel@lists.debian.org

Subject: Re: Bug#785557: perl: FTBFS on i386 and amd64: itimer problems on buildds?

Date: Wed, 10 Jun 2015 17:52:30 +0300

[Message part 1 (text/plain, inline)]

Control: reassign -1 qemu-system-x86
Control: severity -1 important
Control: found -1 qemu/1:2.1+dfsg-12
Control: retitle -1 QEMU: causes vCPU steal time overflow on live migration

On 22:25 Fri 05 Jun     , Dominic Hargreaves wrote:
> Great to hear that you found the underlying cause[1] of this! I note
> the workaround:
> 
> -cpu qemu64,-kvm_steal_time
> 
> which may be applicable to the Debian hosts?

> 
> [1] <https://lists.gnu.org/archive/html/qemu-devel/2015-06/msg01295.html>

After investigating a bit more, it looks like the issue comes from an overflow
in the kernel's accumulate_steal_time() (arch/x86/kvm/x86.c:2023):

  static void accumulate_steal_time(struct kvm_vcpu *vcpu)
  {
          u64 delta;
  
          if (!(vcpu->arch.st.msr_val & KVM_MSR_ENABLED))
                  return;
  
          delta = current->sched_info.run_delay - vcpu->arch.st.last_steal;
  
Using systemtap with the attached script to trace KVM execution on the 
receiving host kernel, we can see that shortly before marking the vCPUs 
as runnable on a migrated KVM instance with 2 vCPUs, the following 
happens (** marks lines of interest):

 **  0 qemu-system-x86(18446): kvm_arch_vcpu_load: run_delay=7856949 ns steal=7856949 ns
     0 qemu-system-x86(18446): -> kvm_arch_vcpu_load
     0 vhost-18446(18447): -> kvm_arch_vcpu_should_kick
     5 vhost-18446(18447): <- kvm_arch_vcpu_should_kick
    23 qemu-system-x86(18446): <- kvm_arch_vcpu_load
     0 qemu-system-x86(18446): -> kvm_arch_vcpu_ioctl
     2 qemu-system-x86(18446): <- kvm_arch_vcpu_ioctl
     0 qemu-system-x86(18446): -> kvm_arch_vcpu_put
     2 qemu-system-x86(18446):  -> kvm_put_guest_fpu
     3 qemu-system-x86(18446):  <- kvm_put_guest_fpu
     4 qemu-system-x86(18446): <- kvm_arch_vcpu_put
 **  0 qemu-system-x86(18446): kvm_arch_vcpu_load: run_delay=7856949 ns steal=7856949 ns
     0 qemu-system-x86(18446): -> kvm_arch_vcpu_load
     1 qemu-system-x86(18446): <- kvm_arch_vcpu_load
     0 qemu-system-x86(18446): -> kvm_arch_vcpu_ioctl
     1 qemu-system-x86(18446): <- kvm_arch_vcpu_ioctl
     0 qemu-system-x86(18446): -> kvm_arch_vcpu_put
     1 qemu-system-x86(18446):  -> kvm_put_guest_fpu
     2 qemu-system-x86(18446):  <- kvm_put_guest_fpu
     3 qemu-system-x86(18446): <- kvm_arch_vcpu_put
 **  0 qemu-system-x86(18449): kvm_arch_vcpu_load: run_delay=40304 ns steal=7856949 ns
     0 qemu-system-x86(18449): -> kvm_arch_vcpu_load
 **  7 qemu-system-x86(18449): delta: 18446744073701734971 ns, steal=7856949 ns, run_delay=40304 ns
    10 qemu-system-x86(18449): <- kvm_arch_vcpu_load
 **  0 qemu-system-x86(18449): -> kvm_arch_vcpu_ioctl_run
     4 qemu-system-x86(18449):  -> kvm_arch_vcpu_runnable
     6 qemu-system-x86(18449):  <- kvm_arch_vcpu_runnable
     ...
     0 qemu-system-x86(18448): kvm_arch_vcpu_load: run_delay=0 ns steal=7856949 ns
     0 qemu-system-x86(18448): -> kvm_arch_vcpu_load
 ** 34 qemu-system-x86(18448): delta: 18446744073701694667 ns, steal=7856949 ns, run_delay=0 ns
    40 qemu-system-x86(18448): <- kvm_arch_vcpu_load
 **  0 qemu-system-x86(18448): -> kvm_arch_vcpu_ioctl_run
     5 qemu-system-x86(18448):  -> kvm_arch_vcpu_runnable

Now, what's really interesting is that current->sched_info.run_delay 
gets reset because the tasks (threads) using the vCPUs change, and thus 
have a different current->sched_info: it looks like task 18446 created 
the two vCPUs, and then they were handed over to 18448 and 18449 
respectively. This is also verified by the fact that during the 
overflow, both vCPUs have the old steal time of the last vcpu_load of 
task 18446. However, according to Documentation/virtual/kvm/api.txt:

 - vcpu ioctls: These query and set attributes that control the operation
   of a single virtual cpu.

   Only run vcpu ioctls from the same thread that was used to create the vcpu.
 
So it seems qemu is doing something that it shouldn't: calling vCPU 
ioctls from a thread that didn't create the vCPU. Note that this 
probably happens on every QEMU startup, but is not visible because the 
guest kernel zeroes out the steal time on boot.

There are at least two ways to mitigate the issue without a kernel
recompilation:

 - The first one is to disable the steal time propagation from host to 
   guest by invoking qemu with `-cpu qemu64,-kvm_steal_time`. This will 
   short-circuit accumulate_steal_time() due to (vcpu->arch.st.msr_val & 
   KVM_MSR_ENABLED) and will completely disable steal time reporting in 
   the guest, which may not be desired if people rely on it to detect 
   CPU congestion.

 - The other one is using the following systemtap script to prevent the 
   steal time counter from overflowing by dropping the problematic 
   samples (WARNING: systemtap guru mode required, use at your own 
   risk):

      probe module("kvm").statement("*@arch/x86/kvm/x86.c:2024") {
        if (@defined($delta) && $delta < 0) {
          printk(4, "kvm: steal time delta < 0, dropping")
          $delta = 0
        }
      }

Note that not all *guests* handle this condition in the same way: 3.2 
guests still get the overflow in /proc/stat, but their scheduler 
continues to work as expected. 3.16 guests OTOH go nuts once steal time 
overflows and stop accumulating system & user time, while entering an 
erratic state where steal time in /proc/stat is *decreasing* on every 
clock tick.

Regards,
Apollon

[trace-kvm.stp (text/plain, attachment)]

Message #77 received at 785557@bugs.debian.org (full text, mbox, reply):

From: Apollon Oikonomopoulos <apoikos@debian.org>

To: 785557@bugs.debian.org, debian-admin@lists.debian.org

Subject: Re: Bug#785557: perl: FTBFS on i386 and amd64:

Date: Thu, 11 Jun 2015 23:29:18 +0300

[ -debian-kernel@l.d.o ]

On 17:52 Wed 10 Jun     , Apollon Oikonomopoulos wrote:
> Now, what's really interesting is that current->sched_info.run_delay 
> gets reset because the tasks (threads) using the vCPUs change, and 
> thus have a different current->sched_info: it looks like task 18446 
> created the two vCPUs, and then they were handed over to 18448 and 
> 18449 respectively. This is also verified by the fact that during the 
> overflow, both vCPUs have the old steal time of the last vcpu_load of 
> task 18446. However, according to Documentation/virtual/kvm/api.txt:

The above is not entirely accurate: the vCPUs were created by the 
threads that are used to run them (18448 and 18449 respectively), it's 
just that the main thread is issuing ioctls during initialization, as 
illustrated by the strace output on a different process:

 [ vCPU #0 thread creating vCPU #0 (fd 20) ]
 [pid  1861] ioctl(14, KVM_CREATE_VCPU, 0) = 20
 [pid  1861] ioctl(20, KVM_X86_SETUP_MCE, 0x7fbd3ca40cd8) = 0
 [pid  1861] ioctl(20, KVM_SET_CPUID2, 0x7fbd3ca40ce0) = 0
 [pid  1861] ioctl(20, KVM_SET_SIGNAL_MASK, 0x7fbd380008f0) = 0
 
 [ vCPU #1 thread creating vCPU #1 (fd 21) ]
 [pid  1862] ioctl(14, KVM_CREATE_VCPU, 0x1) = 21
 [pid  1862] ioctl(21, KVM_X86_SETUP_MCE, 0x7fbd37ffdcd8) = 0
 [pid  1862] ioctl(21, KVM_SET_CPUID2, 0x7fbd37ffdce0) = 0
 [pid  1862] ioctl(21, KVM_SET_SIGNAL_MASK, 0x7fbd300008f0) = 0
 
 [ Main thread calling kvm_arch_put_registers() on vCPU #0 ]
 [pid  1859] ioctl(20, KVM_SET_REGS, 0x7ffc98aac230) = 0
 [pid  1859] ioctl(20, KVM_SET_XSAVE or KVM_SIGNAL_MSI, 0x7fbd38001000) = 0
 [pid  1859] ioctl(20, KVM_PPC_ALLOCATE_HTAB or KVM_SET_XCRS, 0x7ffc98aac010) = 0
 [pid  1859] ioctl(20, KVM_SET_SREGS, 0x7ffc98aac050) = 0
 [pid  1859] ioctl(20, KVM_SET_MSRS, 0x7ffc98aab820) = 87
 [pid  1859] ioctl(20, KVM_SET_MP_STATE, 0x7ffc98aac230) = 0
 [pid  1859] ioctl(20, KVM_SET_LAPIC, 0x7ffc98aabd80) = 0
 [pid  1859] ioctl(20, KVM_SET_MSRS, 0x7ffc98aac1b0) = 1
 [pid  1859] ioctl(20, KVM_SET_PIT2 or KVM_SET_VCPU_EVENTS, 0x7ffc98aac1b0) = 0
 [pid  1859] ioctl(20, KVM_SET_DEBUGREGS or KVM_SET_TSC_KHZ, 0x7ffc98aac1b0) = 0
 
 [ Main thread calling kvm_arch_put_registers() on vCPU #1 ]
 [pid  1859] ioctl(21, KVM_SET_REGS, 0x7ffc98aac230) = 0
 [pid  1859] ioctl(21, KVM_SET_XSAVE or KVM_SIGNAL_MSI, 0x7fbd30001000) = 0
 [pid  1859] ioctl(21, KVM_PPC_ALLOCATE_HTAB or KVM_SET_XCRS, 0x7ffc98aac010) = 0
 [pid  1859] ioctl(21, KVM_SET_SREGS, 0x7ffc98aac050) = 0
 [pid  1859] ioctl(21, KVM_SET_MSRS, 0x7ffc98aab820) = 87
 [pid  1859] ioctl(21, KVM_SET_MP_STATE, 0x7ffc98aac230) = 0
 [pid  1859] ioctl(21, KVM_SET_LAPIC, 0x7ffc98aabd80) = 0
 [pid  1859] ioctl(21, KVM_SET_MSRS, 0x7ffc98aac1b0) = 1
 [pid  1859] ioctl(21, KVM_SET_PIT2 or KVM_SET_VCPU_EVENTS, 0x7ffc98aac1b0) = 0
 [pid  1859] ioctl(21, KVM_SET_DEBUGREGS or KVM_SET_TSC_KHZ, 0x7ffc98aac1b0) = 0
 
Using systemtap again, I noticed that the main thread's run_delay is copied to
last_steal only after a KVM_SET_MSRS ioctl which enables the steal time 
MSR is issued by the main thread (see linux 
3.16.7-ckt11-1/arch/x86/kvm/x86.c:2162). Taking an educated guess, I 
reverted the following qemu commits:

 commit 0e5035776df31380a44a1a851850d110b551ecb6
 Author: Marcelo Tosatti <mtosatti@redhat.com>
 Date:   Tue Sep 3 18:55:16 2013 -0300
 
     fix steal time MSR vmsd callback to proper opaque type
     
     Convert steal time MSR vmsd callback pointer to proper X86CPU type.
     
     Signed-off-by: Marcelo Tosatti <mtosatti@redhat.com>
     Signed-off-by: Paolo Bonzini <pbonzini@redhat.com>
 
 commit 917367aa968fd4fef29d340e0c7ec8c608dffaab
 Author: Marcelo Tosatti <mtosatti@redhat.com>
 Date:   Tue Feb 19 23:27:20 2013 -0300
 
     target-i386: kvm: save/restore steal time MSR
     
     Read and write steal time MSR, so that reporting is functional across
     migration.
     
     Signed-off-by: Marcelo Tosatti <mtosatti@redhat.com>
     Signed-off-by: Gleb Natapov <gleb@redhat.com>
 
and the steal time jump on migration went away. However, steal time was 
not reported at all after migration, which is expected after reverting 
917367aa.

So it seems that after 917367aa, the steal time MSR is correctly saved 
and copied to the receiving side, but then it is restored by the main 
thread (probably during cpu_synchronize_all_post_init()), causing the 
overflow when the vCPU threads are unpaused.

Message #92 received at 785557@bugs.debian.org (full text, mbox, reply):

From: Michael Tokarev <mjt@tls.msk.ru>

To: 785557@bugs.debian.org, Dominic Hargreaves <dom@earth.li>

Subject: Re: Processed: affects 785557

Date: Tue, 07 Jul 2015 12:24:44 +0300

07.07.2015 11:48, Debian Bug Tracking System wrote:
> Processing commands for control@bugs.debian.org:
> 
>> affects 785557 src:perl
> Bug #785557 [qemu-system-x86] QEMU: causes vCPU steal time overflow on live migration
> Added indication that 785557 affects src:perl

Dominic, care to explain?

Thanks,

/mjt

Message #97 received at 785557@bugs.debian.org (full text, mbox, reply):

From: Dominic Hargreaves <dom@earth.li>

To: Michael Tokarev <mjt@tls.msk.ru>

Cc: 785557@bugs.debian.org

Subject: Re: Processed: affects 785557

Date: Tue, 7 Jul 2015 10:28:22 +0100

On Tue, Jul 07, 2015 at 12:24:44PM +0300, Michael Tokarev wrote:
> 07.07.2015 11:48, Debian Bug Tracking System wrote:
> > Processing commands for control@bugs.debian.org:
> > 
> >> affects 785557 src:perl
> > Bug #785557 [qemu-system-x86] QEMU: causes vCPU steal time overflow on live migration
> > Added indication that 785557 affects src:perl
> 
> Dominic, care to explain?

The earlier part of the bug report (which started off as a bugreport in
perl) should explain. This bug (on Debian infrastructure) is causing
build failures on the buildds. Latest:

https://buildd.debian.org/status/fetch.php?pkg=perl&arch=i386&ver=5.22.0-2&stamp=1435871448

Message #102 received at 785557@bugs.debian.org (full text, mbox, reply):

From: Chad William Seys <cwseys@physics.wisc.edu>

To: 785557@bugs.debian.org

Subject: in QEMU bug tracker?

Date: Fri, 04 Sep 2015 09:03:30 -0500

Hi All,
I tried to find this bug in QEMU's bug tracker, but failed.  Also, it doesn't 
look like the messages to the mailing list:
	http://lists.gnu.org/archive/html/qemu-devel/2015-06/msg01295.html
are getting much attention.

Perhaps opening a bug in QEMU's bug tracker would be useful?  (Or I missed 
it.)

Thanks!
C.

Message #107 received at 785557@bugs.debian.org (full text, mbox, reply):

From: Chad William Seys <cwseys@physics.wisc.edu>

To: 785557@bugs.debian.org

Subject: upstream bug

Date: Thu, 10 Sep 2015 09:39:01 -0500

Submitted to upstream bug tracker:
https://bugs.launchpad.net/qemu/+bug/1494350

Message #114 received at 785557@bugs.debian.org (full text, mbox, reply):

From: Chad William Seys <cwseys@physics.wisc.edu>

To: 785557@bugs.debian.org

Subject: Re: Processed: Re: Bug#789566: Jessie guest 100% steal time after live migration

Date: Thu, 19 Nov 2015 08:53:31 -0600

Turns out the fix was applied to the kvm portion of the linux kernel.  Is in 
kernel version 4.4rc1 .

https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git/commit/?id=7cae2bedcbd4680b155999655e49c27b9cf020fa

see also upstream qemu issue tracker:
https://bugs.launchpad.net/qemu/+bug/1494350

Thanks,
Chad.

On Tuesday, November 03, 2015 07:45:16 Debian Bug Tracking System wrote:
> Processing control commands:
> > reassign -1 qemu-system-x86
> 
> Bug #789566 [qemu-kvm] Jessie guest 100% steal time after live migration
> Bug reassigned from package 'qemu-kvm' to 'qemu-system-x86'.
> No longer marked as found in versions qemu/1:2.1+dfsg-12~bpo70+1.
> Ignoring request to alter fixed versions of bug #789566 to the same values
> previously set
> > severity -1 important
> 
> Bug #789566 [qemu-system-x86] Jessie guest 100% steal time after live
> migration Severity set to 'important' from 'normal'
> 
> > forcemerge 785557 -1
> 
> Bug #785557 [qemu-system-x86] QEMU: causes vCPU steal time overflow on live
> migration Bug #789566 [qemu-system-x86] Jessie guest 100% steal time after
> live migration Set Bug forwarded-to-address to
> 'http://lists.gnu.org/archive/html/qemu-devel/2015-06/msg01295.html'. Added
> indication that 789566 affects src:perl
> Marked as found in versions qemu/1.5.0~rc0+dfsg-1 and qemu/1:2.1+dfsg-12.
> Added tag(s) upstream, sid, and stretch.
> Merged 785557 789566

Message #119 received at 785557-done@bugs.debian.org (full text, mbox, reply):

From: Michael Tokarev <mjt@tls.msk.ru>

To: 785557-done@bugs.debian.org

Subject: Re: Bug#789566: Jessie guest 100% steal time after live migration

Date: Mon, 11 Jan 2016 12:08:35 +0300

So, since the actual bug is in kernel, and it has been fixed
in there (in the upcoming 4.4 version), let's close it here
but keep it around in qemu.

Thanks,

/mjt

Send a report that this bug log contains spam.