Xen devel - May 2013 - Re: [Xen-users] FreeBSD PVHVM call for testing

(dropping the BSD lists & xen-users, adding Konrad)

On Wed, 2013-05-29 at 19:03 +0200, Roger Pau Monné
wrote:
> Thanks Matt and Colin for the testing and help! I''ve pushed yet
another
> version, now it''s branch pvhvm_v12, which I *think* should solve
the
> issues with cpuid != acpi_id:
> 
>
http://xenbits.xen.org/gitweb/?p=people/royger/freebsd.git;a=shortlog;h=refs/heads/pvhvm_v12
> 
> Since I''m not able to reproduce the cpuid != acpi_id case, could
you
> give it a try and report the results?
Konrad,

Might this same problem be related to the issue you saw doing PVHVM VCPU
hotplug which you mentioned the other day?

In general for HVM I suppose there isn''t a strict relationship between
the CPU number the kernel chooses for a CPU (which is somewhat
arbitrarily up to the kernel) and the hypervisors VCPU number (which is
exposed via the virtual APIC ID).

Ian.

On Wed, May 29, 2013 at 06:25:56PM +0100, Ian Campbell
wrote:
> (dropping the BSD lists & xen-users, adding Konrad)
> 
> On Wed, 2013-05-29 at 19:03 +0200, Roger Pau Monné wrote:
> > Thanks Matt and Colin for the testing and help! I''ve pushed
yet another
> > version, now it''s branch pvhvm_v12, which I *think* should
solve the
> > issues with cpuid != acpi_id:
> > 
> >
http://xenbits.xen.org/gitweb/?p=people/royger/freebsd.git;a=shortlog;h=refs/heads/pvhvm_v12
> > 
> > Since I''m not able to reproduce the cpuid != acpi_id case,
could you
> > give it a try and report the results?
> 
> Konrad,
> 
> Might this same problem be related to the issue you saw doing PVHVM VCPU
> hotplug which you mentioned the other day?
This was http://article.gmane.org/gmane.comp.emulators.xen.devel/159105
> 
> In general for HVM I suppose there isn''t a strict relationship
between
> the CPU number the kernel chooses for a CPU (which is somewhat
> arbitrarily up to the kernel) and the hypervisors VCPU number (which is
> exposed via the virtual APIC ID).
Right. To troubleshoot this I added some instrumentation to make sure
that the xen_vcpuop_set_mode function was using the right vCPU number.

Initially it got it from smp_processor_id(), which gets it from the
APIC ID (at least that is what it looks like). But perhaps it was not.
I can''t seem to reproduce the issue anymore :-(

On Wed, May 29, 2013 at 06:25:56PM +0100, Ian Campbell
wrote:
> On Wed, 2013-05-29 at 19:03 +0200, Roger Pau Monné wrote:
> > 
> > Since I''m not able to reproduce the cpuid != acpi_id case,
could you
> > give it a try and report the results?
> 
> Konrad,
> 
> Might this same problem be related to the issue you saw doing PVHVM VCPU
> hotplug which you mentioned the other day?
>
> In general for HVM I suppose there isn''t a strict relationship
between
> the CPU number the kernel chooses for a CPU (which is somewhat
> arbitrarily up to the kernel) and the hypervisors VCPU number (which is
> exposed via the virtual APIC ID).
The CPU enumeration should follow the ACPI ID order in MADT (or
MP-table), right?  The local APIC ID (returned by cpuid
EAX=0000_0001h => EBX bits 31:24) shouldn''t be used for
enumeration. Under Xen, the LAPIC ID is hardcoded to vCPU idx * 2:

void hvm_cpuid(unsigned int input, unsigned int *eax, unsigned int *ebx,
[...]
     case 0x1:
         /* Fix up VLAPIC details. */
         *ebx &= 0x00FFFFFFu;
         *ebx |= (v->vcpu_id * 2) << 24;
[...]
     case 0xb:
         /* Fix the x2APIC identifier. */
         *edx = v->vcpu_id * 2;
         break;

This isn''t the way it works on some of our EC2 instances.  On our high
performance instance types, we provide x2APIC IDs that distinguish
threads, cores and sockets to provide the guest OS with CPU topology
information. The OS and applications can use CPUID EAX=0000_000Bh,
ECX=level (HT=0, Core=1, Socket=2) => EAX bits 4:0 to determine the
topology.

--msw

On Wed, 2013-05-29 at 14:24 -0400, Konrad Rzeszutek Wilk
wrote:
> On Wed, May 29, 2013 at 06:25:56PM +0100, Ian Campbell wrote:
> > (dropping the BSD lists & xen-users, adding Konrad)
> > 
> > On Wed, 2013-05-29 at 19:03 +0200, Roger Pau Monné wrote:
> > > Thanks Matt and Colin for the testing and help! I've pushed
yet another
> > > version, now it's branch pvhvm_v12, which I *think* should
solve the
> > > issues with cpuid != acpi_id:
> > > 
> > >
http://xenbits.xen.org/gitweb/?p=people/royger/freebsd.git;a=shortlog;h=refs/heads/pvhvm_v12
> > > 
> > > Since I'm not able to reproduce the cpuid != acpi_id case,
could you
> > > give it a try and report the results?
> > 
> > Konrad,
> > 
> > Might this same problem be related to the issue you saw doing PVHVM
VCPU
> > hotplug which you mentioned the other day?
> 
> This was http://article.gmane.org/gmane.comp.emulators.xen.devel/159105
> 
> > 
> > In general for HVM I suppose there isn't a strict relationship
between
> > the CPU number the kernel chooses for a CPU (which is somewhat
> > arbitrarily up to the kernel) and the hypervisors VCPU number (which
is
> > exposed via the virtual APIC ID).
> 
> Right. To troubleshoot this I added some instrumentation to make sure
> that the xen_vcpuop_set_mode function was using the right vCPU number.
> 
> Initially it got it from smp_processor_id(), which gets it from the
> APIC ID (at least that is what it looks like). But perhaps it was not.
Is smp_processor_id() always from APIC ID? For x86 I see:
        raw_smp_processor_id()
        stack_smp_processor_id()
        safe_smp_processor_id()
        smp_processor_id()
        logical_smp_processor_id()
        hard_smp_processor_id()
also things like cpu_physical_id(). I'd have to assume they aren't all
equivalent ;-)
> I can't seem to reproduce the issue anymore :-(
Well, that sounds like a good thing to me ;-)

Ian.


_______________________________________________
Xen-devel mailing list
Xen-devel@lists.xen.org
http://lists.xen.org/xen-devel

On Wed, 2013-05-29 at 15:10 -0700, Matt Wilson wrote:
> On Wed, May 29, 2013 at 06:25:56PM +0100, Ian Campbell wrote:
> > On Wed, 2013-05-29 at 19:03 +0200, Roger Pau Monné wrote:
> > > 
> > > Since I'm not able to reproduce the cpuid != acpi_id case,
could you
> > > give it a try and report the results?
> > 
> > Konrad,
> > 
> > Might this same problem be related to the issue you saw doing PVHVM
VCPU
> > hotplug which you mentioned the other day?
> >
> > In general for HVM I suppose there isn't a strict relationship
between
> > the CPU number the kernel chooses for a CPU (which is somewhat
> > arbitrarily up to the kernel) and the hypervisors VCPU number (which
is
> > exposed via the virtual APIC ID).
> 
> The CPU enumeration should follow the ACPI ID order in MADT (or
> MP-table), right?
You mean the guest's enumeration? I'd have thought that was entirely up
to the guest. Using the APIC ID might be a reasonable implementation but
there are surely others (e.g. collapsing sparse LAPIC IDs into
contiguous cpu ids, using the top bits for NUMA node, etc etc).
>   The local APIC ID (returned by cpuid
> EAX=0000_0001h => EBX bits 31:24) shouldn't be used for
> enumeration. Under Xen, the LAPIC ID is hardcoded to vCPU idx * 2:
> 
> void hvm_cpuid(unsigned int input, unsigned int *eax, unsigned int *ebx,
> [...]
>      case 0x1:
>          /* Fix up VLAPIC details. */
>          *ebx &= 0x00FFFFFFu;
>          *ebx |= (v->vcpu_id * 2) << 24;
> [...]
>      case 0xb:
>          /* Fix the x2APIC identifier. */
>          *edx = v->vcpu_id * 2;
>          break;
> 
> This isn't the way it works on some of our EC2 instances.  On our high
> performance instance types, we provide x2APIC IDs that distinguish
> threads, cores and sockets to provide the guest OS with CPU topology
> information. The OS and applications can use CPUID EAX=0000_000Bh,
> ECX=level (HT=0, Core=1, Socket=2) => EAX bits 4:0 to determine the
> topology.
Hrm, that does beg the question of how an HVM guest is supposed to
determine what Xen's idea of the VCPU number is for a given CPU.

I can't see anything which reverses that * 2 on the vcpu_op path and I
don't suppose you implemented the inverse of your scheme.

Ian.


_______________________________________________
Xen-devel mailing list
Xen-devel@lists.xen.org
http://lists.xen.org/xen-devel

On Thu, May 30, 2013 at 10:31:43AM +0100, Ian Campbell
wrote:
> On Wed, 2013-05-29 at 15:10 -0700, Matt Wilson wrote:
> > On Wed, May 29, 2013 at 06:25:56PM +0100, Ian Campbell wrote:
> > > On Wed, 2013-05-29 at 19:03 +0200, Roger Pau Monné wrote:
> > > > 
> > > > Since I''m not able to reproduce the cpuid !=
acpi_id case, could you
> > > > give it a try and report the results?
> > > 
> > > Konrad,
> > > 
> > > Might this same problem be related to the issue you saw doing
PVHVM VCPU
> > > hotplug which you mentioned the other day?
> > >
> > > In general for HVM I suppose there isn''t a strict
relationship between
> > > the CPU number the kernel chooses for a CPU (which is somewhat
> > > arbitrarily up to the kernel) and the hypervisors VCPU number
(which is
> > > exposed via the virtual APIC ID).
> > 
> > The CPU enumeration should follow the ACPI ID order in MADT (or
> > MP-table), right?
> You mean the guest''s enumeration?
Right.
> I''d have thought that was entirely up to the guest. Using the APIC
> ID might be a reasonable implementation but there are surely others
> (e.g. collapsing sparse LAPIC IDs into contiguous cpu ids, using the
> top bits for NUMA node, etc etc).
On bare metal x86 Linux, the kernel enumerates CPUs based on an order
defined by the BIOS. Typically this means that all the cores are
enumerated first, followed by logical processors (HT/SMT). For Linux,
maxcpus=N/2 should disable HT on systems that enumerate processors in
the recommended order. Some history:
  https://bugzilla.kernel.org/show_bug.cgi?id=2317
> >   The local APIC ID (returned by cpuid
> > EAX=0000_0001h => EBX bits 31:24) shouldn''t be used for
> > enumeration. Under Xen, the LAPIC ID is hardcoded to vCPU idx * 2:
> > 
> > void hvm_cpuid(unsigned int input, unsigned int *eax, unsigned int
*ebx,
> > [...]
> >      case 0x1:
> >          /* Fix up VLAPIC details. */
> >          *ebx &= 0x00FFFFFFu;
> >          *ebx |= (v->vcpu_id * 2) << 24;
> > [...]
> >      case 0xb:
> >          /* Fix the x2APIC identifier. */
> >          *edx = v->vcpu_id * 2;
> >          break;
> > 
> > This isn''t the way it works on some of our EC2 instances.  On
our high
> > performance instance types, we provide x2APIC IDs that distinguish
> > threads, cores and sockets to provide the guest OS with CPU topology
> > information. The OS and applications can use CPUID EAX=0000_000Bh,
> > ECX=level (HT=0, Core=1, Socket=2) => EAX bits 4:0 to determine the
> > topology.
> 
> Hrm, that does beg the question of how an HVM guest is supposed to
> determine what Xen''s idea of the VCPU number is for a given CPU.
The virtual BIOS provides both ACPI tables and a legacy MP-table that
gives the LAPIC id mapping. The guest could infer the Xen vCPU ID from
a processor''s position in these tables. Or we could add a VCPUOP that
an enlightened guest could use to get the information more directly.

One question: why does a hypercall take a parameter that only has one
valid value? That value can be determined by looking at the current
running vCPU.
> I can''t see anything which reverses that * 2 on the vcpu_op path
and I
> don''t suppose you implemented the inverse of your scheme.
The *2 is just for assigning the LAPIC ID, and I''m pretty sure that
Linux is assigning processor IDs sequentially at ACPI parse time.

--msw

On Thu, 2013-05-30 at 10:16 -0700, Matt Wilson wrote:
> On Thu, May 30, 2013 at 10:31:43AM +0100, Ian Campbell wrote:
> > On Wed, 2013-05-29 at 15:10 -0700, Matt Wilson wrote:
> > > On Wed, May 29, 2013 at 06:25:56PM +0100, Ian Campbell wrote:
> > > > On Wed, 2013-05-29 at 19:03 +0200, Roger Pau Monné wrote:
> > > > > 
> > > > > Since I'm not able to reproduce the cpuid !=
acpi_id case, could you
> > > > > give it a try and report the results?
> > > > 
> > > > Konrad,
> > > > 
> > > > Might this same problem be related to the issue you saw
doing PVHVM VCPU
> > > > hotplug which you mentioned the other day?
> > > >
> > > > In general for HVM I suppose there isn't a strict
relationship between
> > > > the CPU number the kernel chooses for a CPU (which is
somewhat
> > > > arbitrarily up to the kernel) and the hypervisors VCPU
number (which is
> > > > exposed via the virtual APIC ID).
> > > 
> > > The CPU enumeration should follow the ACPI ID order in MADT (or
> > > MP-table), right?
> 
> > You mean the guest's enumeration?
> 
> Right.
> 
> > I'd have thought that was entirely up to the guest. Using the APIC
> > ID might be a reasonable implementation but there are surely others
> > (e.g. collapsing sparse LAPIC IDs into contiguous cpu ids, using the
> > top bits for NUMA node, etc etc).
> 
> On bare metal x86 Linux, the kernel enumerates CPUs based on an order
> defined by the BIOS.
>  Typically this means that all the cores are
> enumerated first, followed by logical processors (HT/SMT). For Linux,
> maxcpus=N/2 should disable HT on systems that enumerate processors in
> the recommended order. Some history:
>   https://bugzilla.kernel.org/show_bug.cgi?id=2317
How the guest chooses to enumerate the CPUs is not terribly relevant so
long as the Xen specific code for that OS knows how to invert that
mapping to get at the underlying ABI which determines Xen's VCPUID for a
CPU.

I think I was wrong to focus on the guest enumeration scheme before,
what actually matters is where in our ABI we expose the VCPUID, which
isn't at all clear to me.
> > >   The local APIC ID (returned by cpuid
> > > EAX=0000_0001h => EBX bits 31:24) shouldn't be used for
> > > enumeration. Under Xen, the LAPIC ID is hardcoded to vCPU idx *
2:
> > > 
> > > void hvm_cpuid(unsigned int input, unsigned int *eax, unsigned
int *ebx,
> > > [...]
> > >      case 0x1:
> > >          /* Fix up VLAPIC details. */
> > >          *ebx &= 0x00FFFFFFu;
> > >          *ebx |= (v->vcpu_id * 2) << 24;
> > > [...]
> > >      case 0xb:
> > >          /* Fix the x2APIC identifier. */
> > >          *edx = v->vcpu_id * 2;
> > >          break;
> > > 
> > > This isn't the way it works on some of our EC2 instances.  On
our high
> > > performance instance types, we provide x2APIC IDs that
distinguish
> > > threads, cores and sockets to provide the guest OS with CPU
topology
> > > information. The OS and applications can use CPUID
EAX=0000_000Bh,
> > > ECX=level (HT=0, Core=1, Socket=2) => EAX bits 4:0 to
determine the
> > > topology.
> > 
> > Hrm, that does beg the question of how an HVM guest is supposed to
> > determine what Xen's idea of the VCPU number is for a given CPU.
> 
> The virtual BIOS provides both ACPI tables and a legacy MP-table that
> gives the LAPIC id mapping. The guest could infer the Xen vCPU ID from
> a processor's position in these tables.
Do we consider the ordering given in any of those tables to be an HVM
guest ABI? What about the lapic_id == 2*vcpuid -- is that multiplication
factor part of the ABI (i.e. is the guest expected to pass lapic_id/2 to
vcpuop)?
>  Or we could add a VCPUOP that an enlightened guest could use to get
> the information more directly.
I'm hoping that there is some existing interface which I simply don't
know about, but yes this could be the answer if such a thing doesn't
exist.
> One question: why does a hypercall take a parameter that only has one
> valid value? That value can be determined by looking at the current
> running vCPU.
The generic prototype is:
        vcpu_op(int cmd, int vcpuid, void *extra_args)
Some cmds can act on any vcpuid and others can only act on the current
vcpu. In an ideal world we would have had VCPUID_SELF or something but
its a bit late for that.
> > I can't see anything which reverses that * 2 on the vcpu_op path
and I
> > don't suppose you implemented the inverse of your scheme.
> 
> The *2 is just for assigning the LAPIC ID, and I'm pretty sure that
> Linux is assigning processor IDs sequentially at ACPI parse time.
That probably doesn't matter, what matters is the Xen specific parts of
the kernel's ability to reverse that assignment to get at the underlying
APIC ID, assuming that is actually an ABI from which we can infer the
VCPU ID...

Ian


_______________________________________________
Xen-devel mailing list
Xen-devel@lists.xen.org
http://lists.xen.org/xen-devel

On Fri, May 31, 2013 at 09:21:50AM +0100, Ian Campbell
wrote:
> On Thu, 2013-05-30 at 10:16 -0700, Matt Wilson wrote:
> > 
> > On bare metal x86 Linux, the kernel enumerates CPUs based on an order
> > defined by the BIOS.
> >  Typically this means that all the cores are
> > enumerated first, followed by logical processors (HT/SMT). For Linux,
> > maxcpus=N/2 should disable HT on systems that enumerate processors in
> > the recommended order. Some history:
> >   https://bugzilla.kernel.org/show_bug.cgi?id=2317
> 
> How the guest chooses to enumerate the CPUs is not terribly relevant so
> long as the Xen specific code for that OS knows how to invert that
> mapping to get at the underlying ABI which determines Xen''s VCPUID
for a
> CPU.
Indeed.
> I think I was wrong to focus on the guest enumeration scheme before,
> what actually matters is where in our ABI we expose the VCPUID, which
> isn''t at all clear to me.
Agreed.
> > The virtual BIOS provides both ACPI tables and a legacy MP-table that
> > gives the LAPIC id mapping. The guest could infer the Xen vCPU ID from
> > a processor''s position in these tables.
> 
> Do we consider the ordering given in any of those tables to be an HVM
> guest ABI? What about the lapic_id == 2*vcpuid -- is that multiplication
> factor part of the ABI (i.e. is the guest expected to pass lapic_id/2 to
> vcpuop)?
I strongly prefer the order in the BIOS tables, *not* the
lapic_id = 2*vcpuid formula. Once I''ve done some libxl work,
I''ll be
proposing a patch that makes the LAPIC / x2APIC IDs configurable,
and that will break this assumption.
> >  Or we could add a VCPUOP that an enlightened guest could use to get
> > the information more directly.
> 
> I''m hoping that there is some existing interface which I simply
don''t
> know about, but yes this could be the answer if such a thing
doesn''t
> exist.
I don''t know of one that provide the information explicitly. It might
be easiest to provide this as a hypervisor CPUID leaf so it can be
used in early boot.
> > One question: why does a hypercall take a parameter that only has one
> > valid value? That value can be determined by looking at the current
> > running vCPU.
> 
> The generic prototype is:
>         vcpu_op(int cmd, int vcpuid, void *extra_args)
> Some cmds can act on any vcpuid and others can only act on the current
> vcpu. In an ideal world we would have had VCPUID_SELF or something but
> its a bit late for that.
Yea, that makes sense.
> > The *2 is just for assigning the LAPIC ID, and I''m pretty
sure that
> > Linux is assigning processor IDs sequentially at ACPI parse time.
> 
> That probably doesn''t matter, what matters is the Xen specific
parts of
> the kernel''s ability to reverse that assignment to get at the
underlying
> APIC ID, assuming that is actually an ABI from which we can infer the
> VCPU ID...
Indeed. This seems to be loosely defined so far, and easy to get wrong
as happened with this FreeBSD work.

Konrad, Keir - any thoughts here?

--msw

On Fri, May 31, 2013 at 11:53:22AM -0700, Matt Wilson
wrote:
> On Fri, May 31, 2013 at 09:21:50AM +0100, Ian Campbell wrote:
> > On Thu, 2013-05-30 at 10:16 -0700, Matt Wilson wrote:
> > > 
> > > On bare metal x86 Linux, the kernel enumerates CPUs based on an
order
> > > defined by the BIOS.
> > >  Typically this means that all the cores are
> > > enumerated first, followed by logical processors (HT/SMT). For
Linux,
> > > maxcpus=N/2 should disable HT on systems that enumerate
processors in
> > > the recommended order. Some history:
> > >   https://bugzilla.kernel.org/show_bug.cgi?id=2317
> > 
> > How the guest chooses to enumerate the CPUs is not terribly relevant
so
> > long as the Xen specific code for that OS knows how to invert that
> > mapping to get at the underlying ABI which determines Xen''s
VCPUID for a
> > CPU.
> 
> Indeed.
> 
> > I think I was wrong to focus on the guest enumeration scheme before,
> > what actually matters is where in our ABI we expose the VCPUID, which
> > isn''t at all clear to me.
> 
> Agreed.
> 
> > > The virtual BIOS provides both ACPI tables and a legacy MP-table
that
> > > gives the LAPIC id mapping. The guest could infer the Xen vCPU ID
from
> > > a processor''s position in these tables.
> > 
> > Do we consider the ordering given in any of those tables to be an HVM
> > guest ABI? What about the lapic_id == 2*vcpuid -- is that
multiplication
> > factor part of the ABI (i.e. is the guest expected to pass lapic_id/2
to
> > vcpuop)?
> 
> I strongly prefer the order in the BIOS tables, *not* the
> lapic_id = 2*vcpuid formula. Once I''ve done some libxl work,
I''ll be
> proposing a patch that makes the LAPIC / x2APIC IDs configurable,
> and that will break this assumption.
> 
> > >  Or we could add a VCPUOP that an enlightened guest could use to
get
> > > the information more directly.
> > 
> > I''m hoping that there is some existing interface which I
simply don''t
> > know about, but yes this could be the answer if such a thing
doesn''t
> > exist.
> 
> I don''t know of one that provide the information explicitly. It
might
> be easiest to provide this as a hypervisor CPUID leaf so it can be
> used in early boot.
> 
> > > One question: why does a hypercall take a parameter that only has
one
> > > valid value? That value can be determined by looking at the
current
> > > running vCPU.
> > 
> > The generic prototype is:
> >         vcpu_op(int cmd, int vcpuid, void *extra_args)
> > Some cmds can act on any vcpuid and others can only act on the current
> > vcpu. In an ideal world we would have had VCPUID_SELF or something but
> > its a bit late for that.
> 
> Yea, that makes sense.
> 
> > > The *2 is just for assigning the LAPIC ID, and I''m
pretty sure that
> > > Linux is assigning processor IDs sequentially at ACPI parse time.
> > 
> > That probably doesn''t matter, what matters is the Xen
specific parts of
> > the kernel''s ability to reverse that assignment to get at the
underlying
> > APIC ID, assuming that is actually an ABI from which we can infer the
> > VCPU ID...
> 
> Indeed. This seems to be loosely defined so far, and easy to get wrong
> as happened with this FreeBSD work.
> 
> Konrad, Keir - any thoughts here?
I am a bit confused by ''I strongly prefer the order in the BIOS
tables''.
The way I understand it - Linux setup up the vCPUs based on the LAPIC
which are created by the hvmloader. There are no hypercalls or any
lapic_id =2*vcpuid formule in the Linux kernel. I presume what you meant
by the lapic_id = 2 * vcpuid is more of this:

144     for ( i = 0; i < nr_processor_objects; i++ )
145     {
146         memset(lapic, 0, sizeof(*lapic));
147         lapic->type    = ACPI_PROCESSOR_LOCAL_APIC;
148         lapic->length  = sizeof(*lapic);
149         /* Processor ID must match processor-object IDs in the DSDT. */
150         lapic->acpi_processor_id = i;
151         lapic->apic_id = LAPIC_ID(i);                        

Which sets this up.

So .. assuming this was thought out, why are we starting on vCPUs
that don''t match to this? That seems like a bug? (Note, this is 
with maxvcpus=32, vcpus=1 and the starting of a VCPU1 actually
ended up starting at VCPU4?!).

I think all of this can be sorted out if the hvmloader sets the
LAPIC CPU == VCPU ID properly. So perhaps a better question is - why
is it not setup properly nowadays? If the formal is baked in for
the PVHVM guests, somewhere the formula is not being evaluated properly?

The new hypercall to figure this out could be used, but that wouldn''t
explain why we are failing to start on the correct VCPU?
> 
> --msw

On Mon, Jun 03, 2013 at 10:44:43AM -0400, Konrad Rzeszutek Wilk
wrote:
> On Fri, May 31, 2013 at 11:53:22AM -0700, Matt Wilson wrote:
> > On Fri, May 31, 2013 at 09:21:50AM +0100, Ian Campbell wrote:
> > > On Thu, 2013-05-30 at 10:16 -0700, Matt Wilson wrote:
> > > > 
> > > > On bare metal x86 Linux, the kernel enumerates CPUs based on
an order
> > > > defined by the BIOS.
> > > >  Typically this means that all the cores are
> > > > enumerated first, followed by logical processors (HT/SMT).
For Linux,
> > > > maxcpus=N/2 should disable HT on systems that enumerate
processors in
> > > > the recommended order. Some history:
> > > >   https://bugzilla.kernel.org/show_bug.cgi?id=2317
> > > 
> > > How the guest chooses to enumerate the CPUs is not terribly
relevant so
> > > long as the Xen specific code for that OS knows how to invert
that
> > > mapping to get at the underlying ABI which determines
Xen''s VCPUID for a
> > > CPU.
> > 
> > Indeed.
> > 
> > > I think I was wrong to focus on the guest enumeration scheme
before,
> > > what actually matters is where in our ABI we expose the VCPUID,
which
> > > isn''t at all clear to me.
> > 
> > Agreed.
> > 
> > > > The virtual BIOS provides both ACPI tables and a legacy
MP-table that
> > > > gives the LAPIC id mapping. The guest could infer the Xen
vCPU ID from
> > > > a processor''s position in these tables.
> > > 
> > > Do we consider the ordering given in any of those tables to be an
HVM
> > > guest ABI? What about the lapic_id == 2*vcpuid -- is that
multiplication
> > > factor part of the ABI (i.e. is the guest expected to pass
lapic_id/2 to
> > > vcpuop)?
> > 
> > I strongly prefer the order in the BIOS tables, *not* the
> > lapic_id = 2*vcpuid formula. Once I''ve done some libxl work,
I''ll be
> > proposing a patch that makes the LAPIC / x2APIC IDs configurable,
> > and that will break this assumption.
> > 
> > > >  Or we could add a VCPUOP that an enlightened guest could
use to get
> > > > the information more directly.
> > > 
> > > I''m hoping that there is some existing interface which I
simply don''t
> > > know about, but yes this could be the answer if such a thing
doesn''t
> > > exist.
> > 
> > I don''t know of one that provide the information explicitly.
It might
> > be easiest to provide this as a hypervisor CPUID leaf so it can be
> > used in early boot.
> > 
> > > > One question: why does a hypercall take a parameter that
only has one
> > > > valid value? That value can be determined by looking at the
current
> > > > running vCPU.
> > > 
> > > The generic prototype is:
> > >         vcpu_op(int cmd, int vcpuid, void *extra_args)
> > > Some cmds can act on any vcpuid and others can only act on the
current
> > > vcpu. In an ideal world we would have had VCPUID_SELF or
something but
> > > its a bit late for that.
> > 
> > Yea, that makes sense.
> > 
> > > > The *2 is just for assigning the LAPIC ID, and I''m
pretty sure that
> > > > Linux is assigning processor IDs sequentially at ACPI parse
time.
> > > 
> > > That probably doesn''t matter, what matters is the Xen
specific parts of
> > > the kernel''s ability to reverse that assignment to get
at the underlying
> > > APIC ID, assuming that is actually an ABI from which we can infer
the
> > > VCPU ID...
> > 
> > Indeed. This seems to be loosely defined so far, and easy to get wrong
> > as happened with this FreeBSD work.
> > 
> > Konrad, Keir - any thoughts here?
> 
> I am a bit confused by ''I strongly prefer the order in the BIOS
tables''.
> The way I understand it - Linux setup up the vCPUs based on the LAPIC
> which are created by the hvmloader. There are no hypercalls or any
> lapic_id =2*vcpuid formule in the Linux kernel. I presume what you meant
> by the lapic_id = 2 * vcpuid is more of this:
> 
> 144     for ( i = 0; i < nr_processor_objects; i++ )
> 145     {
> 146         memset(lapic, 0, sizeof(*lapic));
> 147         lapic->type    = ACPI_PROCESSOR_LOCAL_APIC;
> 148         lapic->length  = sizeof(*lapic);
> 149         /* Processor ID must match processor-object IDs in the DSDT. */
> 150         lapic->acpi_processor_id = i;
> 151         lapic->apic_id = LAPIC_ID(i);                        
> 
> Which sets this up.
Right, all of the LAPIC information is provided to the guest OS via
the MADT. I believe what I''m observing is that Linux and Windows use
the order of entries to enumerate processors in the system.

What we typically see on bare metal Intel systems is something like
this (example system has 16 cores with HT):

All of the "cores"...
[    0.000000] ACPI: Local APIC address 0xfee00000
[    0.000000] ACPI: LAPIC (acpi_id[0x00] lapic_id[0x00] enabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x01] lapic_id[0x02] enabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x02] lapic_id[0x04] enabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x03] lapic_id[0x06] enabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x04] lapic_id[0x08] enabled)
...

Followed by all of the "threads"...
[    0.000000] ACPI: LAPIC (acpi_id[0x10] lapic_id[0x01] enabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x11] lapic_id[0x03] enabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x12] lapic_id[0x05] enabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x13] lapic_id[0x07] enabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x14] lapic_id[0x09] enabled)

Since Xen hard codes the LAPIC ID (and x2APIC ID) to 0, 2, 4, 6, 8,
etc. (vCPUID * 2), everything looks like a core.
> So .. assuming this was thought out, why are we starting on vCPUs
> that don''t match to this? That seems like a bug? (Note, this is 
> with maxvcpus=32, vcpus=1 and the starting of a VCPU1 actually
> ended up starting at VCPU4?!).
I''m lost. What?
> I think all of this can be sorted out if the hvmloader sets the
> LAPIC CPU == VCPU ID properly.
No, that''s not the right answer. Or, at least, not completely. Right
now Xen provides the same ID for both the LAPIC and x2APIC. In order
for cpu topology discovery to work, the x2APIC needs to follow a
particular structure. See the Intel whitepaper on processor topology
enumeration:
 
http://software.intel.com/sites/default/files/m/d/4/1/d/8/Kuo_CpuTopology_rc1.rh1.final.pdf
> So perhaps a better question is - why is it not setup properly
> nowadays? If the formal is baked in for the PVHVM guests, somewhere
> the formula is not being evaluated properly?
The "LAPIC ID = 2 * vCPUID" formula is not baked into any OS that I
know of, and it shouldn''t be. It should all be discovered via
firmware/BIOS tables. The enumeration order in the tables should,
under best practices, match the logical processor ID assignment in the
OS.
> The new hypercall to figure this out could be used, but that
wouldn''t
> explain why we are failing to start on the correct VCPU?
I didn''t follow the jump here. Can you provide an example?

--msw

On Mon, Jun 03, 2013 at 08:57:26AM -0700, Matt Wilson
wrote:
> On Mon, Jun 03, 2013 at 10:44:43AM -0400, Konrad Rzeszutek Wilk wrote:
> > On Fri, May 31, 2013 at 11:53:22AM -0700, Matt Wilson wrote:
> > > On Fri, May 31, 2013 at 09:21:50AM +0100, Ian Campbell wrote:
> > > > On Thu, 2013-05-30 at 10:16 -0700, Matt Wilson wrote:
> > > > > 
> > > > > On bare metal x86 Linux, the kernel enumerates CPUs
based on an order
> > > > > defined by the BIOS.
> > > > >  Typically this means that all the cores are
> > > > > enumerated first, followed by logical processors
(HT/SMT). For Linux,
> > > > > maxcpus=N/2 should disable HT on systems that enumerate
processors in
> > > > > the recommended order. Some history:
> > > > >   https://bugzilla.kernel.org/show_bug.cgi?id=2317
> > > > 
> > > > How the guest chooses to enumerate the CPUs is not terribly
relevant so
> > > > long as the Xen specific code for that OS knows how to
invert that
> > > > mapping to get at the underlying ABI which determines
Xen''s VCPUID for a
> > > > CPU.
> > > 
> > > Indeed.
> > > 
> > > > I think I was wrong to focus on the guest enumeration scheme
before,
> > > > what actually matters is where in our ABI we expose the
VCPUID, which
> > > > isn''t at all clear to me.
> > > 
> > > Agreed.
> > > 
> > > > > The virtual BIOS provides both ACPI tables and a legacy
MP-table that
> > > > > gives the LAPIC id mapping. The guest could infer the
Xen vCPU ID from
> > > > > a processor''s position in these tables.
> > > > 
> > > > Do we consider the ordering given in any of those tables to
be an HVM
> > > > guest ABI? What about the lapic_id == 2*vcpuid -- is that
multiplication
> > > > factor part of the ABI (i.e. is the guest expected to pass
lapic_id/2 to
> > > > vcpuop)?
> > > 
> > > I strongly prefer the order in the BIOS tables, *not* the
> > > lapic_id = 2*vcpuid formula. Once I''ve done some libxl
work, I''ll be
> > > proposing a patch that makes the LAPIC / x2APIC IDs configurable,
> > > and that will break this assumption.
> > > 
> > > > >  Or we could add a VCPUOP that an enlightened guest
could use to get
> > > > > the information more directly.
> > > > 
> > > > I''m hoping that there is some existing interface
which I simply don''t
> > > > know about, but yes this could be the answer if such a thing
doesn''t
> > > > exist.
> > > 
> > > I don''t know of one that provide the information
explicitly. It might
> > > be easiest to provide this as a hypervisor CPUID leaf so it can
be
> > > used in early boot.
> > > 
> > > > > One question: why does a hypercall take a parameter
that only has one
> > > > > valid value? That value can be determined by looking at
the current
> > > > > running vCPU.
> > > > 
> > > > The generic prototype is:
> > > >         vcpu_op(int cmd, int vcpuid, void *extra_args)
> > > > Some cmds can act on any vcpuid and others can only act on
the current
> > > > vcpu. In an ideal world we would have had VCPUID_SELF or
something but
> > > > its a bit late for that.
> > > 
> > > Yea, that makes sense.
> > > 
> > > > > The *2 is just for assigning the LAPIC ID, and
I''m pretty sure that
> > > > > Linux is assigning processor IDs sequentially at ACPI
parse time.
> > > > 
> > > > That probably doesn''t matter, what matters is the
Xen specific parts of
> > > > the kernel''s ability to reverse that assignment to
get at the underlying
> > > > APIC ID, assuming that is actually an ABI from which we can
infer the
> > > > VCPU ID...
> > > 
> > > Indeed. This seems to be loosely defined so far, and easy to get
wrong
> > > as happened with this FreeBSD work.
> > > 
> > > Konrad, Keir - any thoughts here?
> > 
> > I am a bit confused by ''I strongly prefer the order in the
BIOS tables''.
> > The way I understand it - Linux setup up the vCPUs based on the LAPIC
> > which are created by the hvmloader. There are no hypercalls or any
> > lapic_id =2*vcpuid formule in the Linux kernel. I presume what you
meant
> > by the lapic_id = 2 * vcpuid is more of this:
> > 
> > 144     for ( i = 0; i < nr_processor_objects; i++ )
> > 145     {
> > 146         memset(lapic, 0, sizeof(*lapic));
> > 147         lapic->type    = ACPI_PROCESSOR_LOCAL_APIC;
> > 148         lapic->length  = sizeof(*lapic);
> > 149         /* Processor ID must match processor-object IDs in the
DSDT. */
> > 150         lapic->acpi_processor_id = i;
> > 151         lapic->apic_id = LAPIC_ID(i);                        
> > 
> > Which sets this up.
> 
> Right, all of the LAPIC information is provided to the guest OS via
> the MADT. I believe what I''m observing is that Linux and Windows
use
> the order of entries to enumerate processors in the system.
> 
> What we typically see on bare metal Intel systems is something like
> this (example system has 16 cores with HT):
> 
> All of the "cores"...
> [    0.000000] ACPI: Local APIC address 0xfee00000
> [    0.000000] ACPI: LAPIC (acpi_id[0x00] lapic_id[0x00] enabled)
> [    0.000000] ACPI: LAPIC (acpi_id[0x01] lapic_id[0x02] enabled)
> [    0.000000] ACPI: LAPIC (acpi_id[0x02] lapic_id[0x04] enabled)
> [    0.000000] ACPI: LAPIC (acpi_id[0x03] lapic_id[0x06] enabled)
> [    0.000000] ACPI: LAPIC (acpi_id[0x04] lapic_id[0x08] enabled)
> ...
> 
> Followed by all of the "threads"...
> [    0.000000] ACPI: LAPIC (acpi_id[0x10] lapic_id[0x01] enabled)
> [    0.000000] ACPI: LAPIC (acpi_id[0x11] lapic_id[0x03] enabled)
> [    0.000000] ACPI: LAPIC (acpi_id[0x12] lapic_id[0x05] enabled)
> [    0.000000] ACPI: LAPIC (acpi_id[0x13] lapic_id[0x07] enabled)
> [    0.000000] ACPI: LAPIC (acpi_id[0x14] lapic_id[0x09] enabled)
> 
> Since Xen hard codes the LAPIC ID (and x2APIC ID) to 0, 2, 4, 6, 8,
> etc. (vCPUID * 2), everything looks like a core.
OK.
> 
> > So .. assuming this was thought out, why are we starting on vCPUs
> > that don''t match to this? That seems like a bug? (Note, this
is
> > with maxvcpus=32, vcpus=1 and the starting of a VCPU1 actually
> > ended up starting at VCPU4?!).
> 
> I''m lost. What?
http://lists.xen.org/archives/html/xen-devel/2013-05/msg00941.html
> 
> > I think all of this can be sorted out if the hvmloader sets the
> > LAPIC CPU == VCPU ID properly.
> 
> No, that''s not the right answer. Or, at least, not completely.
Right
> now Xen provides the same ID for both the LAPIC and x2APIC. In order
> for cpu topology discovery to work, the x2APIC needs to follow a
> particular structure. See the Intel whitepaper on processor topology
> enumeration:
>  
http://software.intel.com/sites/default/files/m/d/4/1/d/8/Kuo_CpuTopology_rc1.rh1.final.pdf
Nice explanation. However, I was under impression that right now we
don''t virtualize the x2APIC registers?
> 
> > So perhaps a better question is - why is it not setup properly
> > nowadays? If the formal is baked in for the PVHVM guests, somewhere
> > the formula is not being evaluated properly?
> 
> The "LAPIC ID = 2 * vCPUID" formula is not baked into any OS that
I
> know of, and it shouldn''t be. It should all be discovered via
> firmware/BIOS tables. The enumeration order in the tables should,
> under best practices, match the logical processor ID assignment in the
> OS.
OK, good. That is my understanding too.
> 
> > The new hypercall to figure this out could be used, but that
wouldn''t
> > explain why we are failing to start on the correct VCPU?
> 
> I didn''t follow the jump here. Can you provide an example?
http://lists.xen.org/archives/html/xen-devel/2013-05/msg00941.html
> 
> --msw

On Mon, Jun 03, 2013 at 01:33:51PM -0400, Konrad Rzeszutek Wilk
wrote:
> On Mon, Jun 03, 2013 at 08:57:26AM -0700, Matt Wilson wrote:
[...]
> > 
> > Right, all of the LAPIC information is provided to the guest OS via
> > the MADT. I believe what I''m observing is that Linux and
Windows use
> > the order of entries to enumerate processors in the system.
> > 
> > What we typically see on bare metal Intel systems is something like
> > this (example system has 16 cores with HT):
> > 
> > All of the "cores"...
> > [    0.000000] ACPI: Local APIC address 0xfee00000
> > [    0.000000] ACPI: LAPIC (acpi_id[0x00] lapic_id[0x00] enabled)
> > [    0.000000] ACPI: LAPIC (acpi_id[0x01] lapic_id[0x02] enabled)
> > [    0.000000] ACPI: LAPIC (acpi_id[0x02] lapic_id[0x04] enabled)
> > [    0.000000] ACPI: LAPIC (acpi_id[0x03] lapic_id[0x06] enabled)
> > [    0.000000] ACPI: LAPIC (acpi_id[0x04] lapic_id[0x08] enabled)
> > ...
> > 
> > Followed by all of the "threads"...
> > [    0.000000] ACPI: LAPIC (acpi_id[0x10] lapic_id[0x01] enabled)
> > [    0.000000] ACPI: LAPIC (acpi_id[0x11] lapic_id[0x03] enabled)
> > [    0.000000] ACPI: LAPIC (acpi_id[0x12] lapic_id[0x05] enabled)
> > [    0.000000] ACPI: LAPIC (acpi_id[0x13] lapic_id[0x07] enabled)
> > [    0.000000] ACPI: LAPIC (acpi_id[0x14] lapic_id[0x09] enabled)
> > 
> > Since Xen hard codes the LAPIC ID (and x2APIC ID) to 0, 2, 4, 6, 8,
> > etc. (vCPUID * 2), everything looks like a core.
> 
> OK.
>
> > > So .. assuming this was thought out, why are we starting on vCPUs
> > > that don''t match to this? That seems like a bug? (Note,
this is
> > > with maxvcpus=32, vcpus=1 and the starting of a VCPU1 actually
> > > ended up starting at VCPU4?!).
> > 
> > I''m lost. What?
> 
> http://lists.xen.org/archives/html/xen-devel/2013-05/msg00941.html
Aah, gotcha.
> > > I think all of this can be sorted out if the hvmloader sets the
> > > LAPIC CPU == VCPU ID properly.
> > 
> > No, that''s not the right answer. Or, at least, not
completely. Right
> > now Xen provides the same ID for both the LAPIC and x2APIC. In order
> > for cpu topology discovery to work, the x2APIC needs to follow a
> > particular structure. See the Intel whitepaper on processor topology
> > enumeration:
> >  
http://software.intel.com/sites/default/files/m/d/4/1/d/8/Kuo_CpuTopology_rc1.rh1.final.pdf
> 
> Nice explanation. However, I was under impression that right now we
> don''t virtualize the x2APIC registers?
Hmm?

http://xenbits.xen.org/gitweb/?p=xen.git;a=commitdiff;h=21c4d089ba2a236dcf33a06222070bd6c60c6e3d
> > > So perhaps a better question is - why is it not setup properly
> > > nowadays? If the formal is baked in for the PVHVM guests,
somewhere
> > > the formula is not being evaluated properly?
> > 
> > The "LAPIC ID = 2 * vCPUID" formula is not baked into any OS
that I
> > know of, and it shouldn''t be. It should all be discovered via
> > firmware/BIOS tables. The enumeration order in the tables should,
> > under best practices, match the logical processor ID assignment in the
> > OS.
> 
> OK, good. That is my understanding too.
> 
> > 
> > > The new hypercall to figure this out could be used, but that
wouldn''t
> > > explain why we are failing to start on the correct VCPU?
> > 
> > I didn''t follow the jump here. Can you provide an example?
> 
> http://lists.xen.org/archives/html/xen-devel/2013-05/msg00941.html
OK, got it.

[   84.619508] smpboot: Booting Node 0 Processor 1 APIC 0x8

So it seems like, in this case:

int __cpuinit native_cpu_up(unsigned int cpu)
{
        int apicid = apic->cpu_present_to_apicid(cpu);

apic->cpu_present_to_apicid(1) returned 8 instead of 2.

All of that should have been set up correctly ahead of time by
generic_processor_info() for all possible CPUs. Do you have the full
boot log?

--msw

> > > > The new hypercall to figure this out could be used, but that
wouldn''t
> > > > explain why we are failing to start on the correct VCPU?
> > > 
> > > I didn''t follow the jump here. Can you provide an
example?
> > 
> > http://lists.xen.org/archives/html/xen-devel/2013-05/msg00941.html
> 
> OK, got it.
> 
> [   84.619508] smpboot: Booting Node 0 Processor 1 APIC 0x8
> 
> So it seems like, in this case:
> 
> int __cpuinit native_cpu_up(unsigned int cpu)
> {
>         int apicid = apic->cpu_present_to_apicid(cpu);
> 
> apic->cpu_present_to_apicid(1) returned 8 instead of 2.
> 
> All of that should have been set up correctly ahead of time by
> generic_processor_info() for all possible CPUs. Do you have the full
> boot log?
> 
Loading
initramf.gz.............................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................
 ..............................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................
 .......................................................................................................................................................................................................................................................................................................................................................................................................................ready.
[    0.000000] Initializing cgroup subsys cpuset
[    0.000000] Initializing cgroup subsys cpu
[    0.000000] Linux version 3.9.0upstream-00022-g49c1bf1-dirty
(konrad@build-external.dumpdata.com) (gcc version 4.4.4 20100503 (Red Hat
4.4.4-2) (GCC) ) #6 SMP Tue May 7 15:02:36 EDT 2013
[    0.000000] Command line: initrd=initramf.gz  console=ttyS0,115200 test=net
nofb BOOT_IMAGE=vmlinuz
[    0.000000] e820: BIOS-provided physical RAM map:
[    0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009dfff] usable
[    0.000000] BIOS-e820: [mem 0x000000000009e000-0x000000000009ffff] reserved
[    0.000000] BIOS-e820: [mem 0x00000000000e0000-0x00000000000fffff] reserved
[    0.000000] BIOS-e820: [mem 0x0000000000100000-0x000000007f7fffff] usable
[    0.000000] BIOS-e820: [mem 0x00000000fc000000-0x00000000ffffffff] reserved
[    0.000000] NX (Execute Disable) protection: active
[    0.000000] SMBIOS 2.4 present.
[    0.000000] Hypervisor detected: Xen HVM
[    0.000000] Xen version 4.3.
[    0.000000] Netfront and the Xen platform PCI driver have been compiled for
this kernel: unplug emulated NICs.
[    0.000000] Blkfront and the Xen platform PCI driver have been compiled for
this kernel: unplug emulated disks.
[    0.000000] You might have to change the root device
[    0.000000] from /dev/hd[a-d] to /dev/xvd[a-d]
[    0.000000] in your root= kernel command line option
[    0.000000] No AGP bridge found
[    0.000000] e820: last_pfn = 0x7f800 max_arch_pfn = 0x400000000
[    0.000000] x86 PAT enabled: cpu 0, old 0x7040600070406, new 0x7010600070106
[    0.000000] found SMP MP-table at [mem 0x000fbba0-0x000fbbaf] mapped at
[ffff8800000fbba0]
[    0.000000] Scanning 1 areas for low memory corruption
[    0.000000] init_memory_mapping: [mem 0x00000000-0x000fffff]
[    0.000000] init_memory_mapping: [mem 0x77800000-0x779fffff]
[    0.000000] init_memory_mapping: [mem 0x74000000-0x777fffff]
[    0.000000] init_memory_mapping: [mem 0x00100000-0x73ffffff]
[    0.000000] init_memory_mapping: [mem 0x77a00000-0x7f7fffff]
[    0.000000] RAMDISK: [mem 0x77bec000-0x7f7defff]
[    0.000000] ACPI: RSDP 00000000000ea020 00024 (v02    Xen)
[    0.000000] ACPI: XSDT 00000000fc0150c0 00054 (v01    Xen      HVM 00000000
HVML 00000000)
[    0.000000] ACPI: FACP 00000000fc0149f0 000F4 (v04    Xen      HVM 00000000
HVML 00000000)
[    0.000000] ACPI: DSDT 00000000fc0035e0 1138D (v02    Xen      HVM 00000000
INTL 20090123)
[    0.000000] ACPI: FACS 00000000fc0035a0 00040
[    0.000000] ACPI: APIC 00000000fc014af0 00460 (v02    Xen      HVM 00000000
HVML 00000000)
[    0.000000] ACPI: HPET 00000000fc014fd0 00038 (v01    Xen      HVM 00000000
HVML 00000000)
[    0.000000] ACPI: WAET 00000000fc015010 00028 (v01    Xen      HVM 00000000
HVML 00000000)
[    0.000000] ACPI: SSDT 00000000fc015040 00031 (v02    Xen      HVM 00000000
INTL 20090123)
[    0.000000] ACPI: SSDT 00000000fc015080 00031 (v02    Xen      HVM 00000000
INTL 20090123)
[    0.000000] No NUMA configuration found
[    0.000000] Faking a node at [mem 0x0000000000000000-0x000000007f7fffff]
[    0.000000] Initmem setup node 0 [mem 0x00000000-0x7f7fffff]
[    0.000000]   NODE_DATA [mem 0x7f7fb000-0x7f7fffff]
[    0.000000] Zone ranges:
[    0.000000]   DMA      [mem 0x00001000-0x00ffffff]
[    0.000000]   DMA32    [mem 0x01000000-0xffffffff]
[    0.000000]   Normal   empty
[    0.000000] Movable zone start for each node
[    0.000000] Early memory node ranges
[    0.000000]   node   0: [mem 0x00001000-0x0009dfff]
[    0.000000]   node   0: [mem 0x00100000-0x7f7fffff]
[    0.000000] ACPI: PM-Timer IO Port: 0xb008
[    0.000000] ACPI: LAPIC (acpi_id[0x00] lapic_id[0x00] enabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x01] lapic_id[0x02] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x02] lapic_id[0x04] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x03] lapic_id[0x06] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x04] lapic_id[0x08] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x05] lapic_id[0x0a] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x06] lapic_id[0x0c] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x07] lapic_id[0x0e] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x08] lapic_id[0x10] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x09] lapic_id[0x12] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x0a] lapic_id[0x14] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x0b] lapic_id[0x16] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x0c] lapic_id[0x18] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x0d] lapic_id[0x1a] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x0e] lapic_id[0x1c] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x0f] lapic_id[0x1e] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x10] lapic_id[0x20] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x11] lapic_id[0x22] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x12] lapic_id[0x24] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x13] lapic_id[0x26] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x14] lapic_id[0x28] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x15] lapic_id[0x2a] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x16] lapic_id[0x2c] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x17] lapic_id[0x2e] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x18] lapic_id[0x30] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x19] lapic_id[0x32] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x1a] lapic_id[0x34] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x1b] lapic_id[0x36] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x1c] lapic_id[0x38] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x1d] lapic_id[0x3a] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x1e] lapic_id[0x3c] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x1f] lapic_id[0x3e] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x20] lapic_id[0x40] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x21] lapic_id[0x42] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x22] lapic_id[0x44] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x23] lapic_id[0x46] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x24] lapic_id[0x48] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x25] lapic_id[0x4a] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x26] lapic_id[0x4c] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x27] lapic_id[0x4e] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x28] lapic_id[0x50] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x29] lapic_id[0x52] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x2a] lapic_id[0x54] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x2b] lapic_id[0x56] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x2c] lapic_id[0x58] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x2d] lapic_id[0x5a] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x2e] lapic_id[0x5c] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x2f] lapic_id[0x5e] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x30] lapic_id[0x60] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x31] lapic_id[0x62] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x32] lapic_id[0x64] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x33] lapic_id[0x66] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x34] lapic_id[0x68] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x35] lapic_id[0x6a] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x36] lapic_id[0x6c] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x37] lapic_id[0x6e] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x38] lapic_id[0x70] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x39] lapic_id[0x72] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x3a] lapic_id[0x74] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x3b] lapic_id[0x76] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x3c] lapic_id[0x78] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x3d] lapic_id[0x7a] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x3e] lapic_id[0x7c] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x3f] lapic_id[0x7e] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x40] lapic_id[0x80] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x41] lapic_id[0x82] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x42] lapic_id[0x84] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x43] lapic_id[0x86] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x44] lapic_id[0x88] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x45] lapic_id[0x8a] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x46] lapic_id[0x8c] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x47] lapic_id[0x8e] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x48] lapic_id[0x90] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x49] lapic_id[0x92] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x4a] lapic_id[0x94] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x4b] lapic_id[0x96] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x4c] lapic_id[0x98] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x4d] lapic_id[0x9a] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x4e] lapic_id[0x9c] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x4f] lapic_id[0x9e] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x50] lapic_id[0xa0] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x51] lapic_id[0xa2] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x52] lapic_id[0xa4] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x53] lapic_id[0xa6] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x54] lapic_id[0xa8] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x55] lapic_id[0xaa] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x56] lapic_id[0xac] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x57] lapic_id[0xae] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x58] lapic_id[0xb0] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x59] lapic_id[0xb2] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x5a] lapic_id[0xb4] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x5b] lapic_id[0xb6] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x5c] lapic_id[0xb8] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x5d] lapic_id[0xba] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x5e] lapic_id[0xbc] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x5f] lapic_id[0xbe] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x60] lapic_id[0xc0] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x61] lapic_id[0xc2] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x62] lapic_id[0xc4] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x63] lapic_id[0xc6] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x64] lapic_id[0xc8] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x65] lapic_id[0xca] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x66] lapic_id[0xcc] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x67] lapic_id[0xce] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x68] lapic_id[0xd0] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x69] lapic_id[0xd2] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x6a] lapic_id[0xd4] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x6b] lapic_id[0xd6] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x6c] lapic_id[0xd8] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x6d] lapic_id[0xda] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x6e] lapic_id[0xdc] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x6f] lapic_id[0xde] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x70] lapic_id[0xe0] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x71] lapic_id[0xe2] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x72] lapic_id[0xe4] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x73] lapic_id[0xe6] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x74] lapic_id[0xe8] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x75] lapic_id[0xea] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x76] lapic_id[0xec] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x77] lapic_id[0xee] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x78] lapic_id[0xf0] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x79] lapic_id[0xf2] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x7a] lapic_id[0xf4] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x7b] lapic_id[0xf6] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x7c] lapic_id[0xf8] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x7d] lapic_id[0xfa] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x7e] lapic_id[0xfc] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x7f] lapic_id[0xfe] disabled)
[    0.000000] ACPI: IOAPIC (id[0x01] address[0xfec00000] gsi_base[0])
[    0.000000] IOAPIC[0]: apic_id 1, version 17, address 0xfec00000, GSI 0-47
[    0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl)
[    0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 low level)
[    0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 low level)
[    0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 low level)
[    0.000000] Using ACPI (MADT) for SMP configuration information
[    0.000000] ACPI: HPET id: 0x8086a201 base: 0xfed00000
[    0.000000] smpboot: Allowing 128 CPUs, 127 hotplug CPUs
[    0.000000] PM: Registered nosave memory: 000000000009e000 - 00000000000a0000
[    0.000000] PM: Registered nosave memory: 00000000000a0000 - 00000000000e0000
[    0.000000] PM: Registered nosave memory: 00000000000e0000 - 0000000000100000
[    0.000000] e820: [mem 0x7f800000-0xfbffffff] available for PCI devices
[    0.000000] Booting paravirtualized kernel on Xen HVM
[    0.000000] setup_percpu: NR_CPUS:512 nr_cpumask_bits:512 nr_cpu_ids:128
nr_node_ids:1
[    0.000000] PERCPU: Embedded 29 pages/cpu @ffff880074200000 s87808 r8192
d22784 u131072
[    0.000000] Built 1 zonelists in Node order, mobility grouping on.  Total
pages: 514980
[    0.000000] Policy zone: DMA32
[    0.000000] Kernel command line: initrd=initramf.gz  console=ttyS0,115200
test=net nofb BOOT_IMAGE=vmlinuz
[    0.000000] PID hash table entries: 4096 (order: 3, 32768 bytes)
[    0.000000] __ex_table already sorted, skipping sort
[    0.000000] xsave: enabled xstate_bv 0x7, cntxt size 0x340
[    0.000000] Checking aperture...
[    0.000000] No AGP bridge found
[    0.000000] Memory: 1893840k/2088960k available (6809k kernel code, 396k
absent, 194724k reserved, 6266k data, 1060k init)
[    0.000000] kmemleak: Kernel memory leak detector disabled
[    0.000000] Hierarchical RCU implementation.
[    0.000000] 	RCU restricting CPUs from NR_CPUS=512 to nr_cpu_ids=128.
[    0.000000] NR_IRQS:33024 nr_irqs:2112 16
[    0.000000] Xen HVM callback vector for event delivery is enabled
[    0.000000] Console: colour VGA+ 80x25
[    0.000000] console [ttyS0] enabled
[    0.000000] Lock dependency validator: Copyright (c) 2006 Red Hat, Inc., Ingo
Molnar
[    0.000000] ... MAX_LOCKDEP_SUBCLASSES:  8
[    0.000000] ... MAX_LOCK_DEPTH:          48
[    0.000000] ... MAX_LOCKDEP_KEYS:        8191
[    0.000000] ... CLASSHASH_SIZE:          4096
[    0.000000] ... MAX_LOCKDEP_ENTRIES:     16384
[    0.000000] ... MAX_LOCKDEP_CHAINS:      32768
[    0.000000] ... CHAINHASH_SIZE:          16384
[    0.000000]  memory used by lock dependency info: 5855 kB
[    0.000000]  per task-struct memory footprint: 1920 bytes
[    0.000000] kmemleak: Early log buffer exceeded (799), please increase
DEBUG_KMEMLEAK_EARLY_LOG_SIZE
[    0.000000] tsc: Detected 3093.074 MHz processor
[    0.006000] Calibrating delay loop (skipped), value calculated using timer
frequency.. 6186.14 BogoMIPS (lpj=3093074)
[    0.018004] pid_max: default: 131072 minimum: 1024
[    0.023082] Security Framework initialized
[    0.028004] SELinux:  Initializing.
[    0.032178] Dentry cache hash table entries: 262144 (order: 9, 2097152 bytes)
[    0.040332] Inode-cache hash table entries: 131072 (order: 8, 1048576 bytes)
[    0.049167] Mount-cache hash table entries: 256
[    0.055547] Initializing cgroup subsys cpuacct
[    0.060010] Initializing cgroup subsys freezer
[    0.066115] CPU: Physical Processor ID: 0
[    0.070004] CPU: Processor Core ID: 0
[    0.075005] mce: CPU supports 2 MCE banks
[    0.079027] Last level iTLB entries: 4KB 512, 2MB 0, 4MB 0
[    0.079027] Last level dTLB entries: 4KB 512, 2MB 32, 4MB 32
[    0.079027] tlb_flushall_shift: 5
[    0.108691] ACPI: Core revision 20130117
[    0.127967] ACPI: All ACPI Tables successfully acquired
[    0.134575] Switched APIC routing to physical flat.
[    0.143211] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=0 pin2=0
[    0.160552] smpboot: CPU0: Intel(R) Xeon(R) CPU E31225 @ 3.10GHz (fam: 06,
model: 2a, stepping: 07)
[    0.171020] installing Xen timer for CPU 0
[    0.176285] Performance Events: unsupported p6 CPU model 42 no PMU driver,
software events only.
[    0.181742] Brought up 1 CPUs
[    0.182008] smpboot: Total of 1 processors activated (6186.14 BogoMIPS)
[    0.183549] NMI watchdog: disabled (cpu0): hardware events not enabled
[    0.187218] kworker/u:0 (15) used greatest stack depth: 5728 bytes left
[    0.188091] RTC time: 16:02:23, date: 05/08/13
[    0.189197] NET: Registered protocol family 16
[    0.190567] kworker/u:0 (26) used greatest stack depth: 5656 bytes left
[    0.191270] ACPI: bus type PCI registered
[    0.192223] dca service started, version 1.12.1
[    0.193510] PCI: Using configuration type 1 for base access
[    0.203121] bio: create slab <bio-0> at 0
[    0.204246] ACPI: Added _OSI(Module Device)
[    0.205070] ACPI: Added _OSI(Processor Device)
[    0.206007] ACPI: Added _OSI(3.0 _SCP Extensions)
[    0.207021] ACPI: Added _OSI(Processor Aggregator Device)
[    0.230407] ACPI: Interpreter enabled
[    0.231010] ACPI Exception: AE_NOT_FOUND, While evaluating Sleep State
[\_S1_] (20130117/hwxface-568)
[    0.234008] ACPI Exception: AE_NOT_FOUND, While evaluating Sleep State
[\_S2_] (20130117/hwxface-568)
[    0.237030] ACPI: (supports S0 S3 S4 S5)
[    0.238006] ACPI: Using IOAPIC for interrupt routing
[    0.239097] PCI: Using host bridge windows from ACPI; if necessary, use
"pci=nocrs" and report a bug
[    0.304682] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff])
[    0.305233] acpi PNP0A03:00: fail to add MMCONFIG information, can''t
access extended PCI configuration space under this bridge.
[    0.306150] PCI host bridge to bus 0000:00
[    0.307013] pci_bus 0000:00: root bus resource [bus 00-ff]
[    0.308009] pci_bus 0000:00: root bus resource [io  0x0000-0x0cf7]
[    0.309009] pci_bus 0000:00: root bus resource [io  0x0d00-0xffff]
[    0.310008] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff]
[    0.311007] pci_bus 0000:00: root bus resource [mem 0xf0000000-0xfbffffff]
[    0.321122] * Found PM-Timer Bug on the chipset. Due to workarounds for a
bug,
[    0.321122] * this clock source is slow. Consider trying other clock sources
[    0.324801] pci 0000:00:01.3: quirk: [io  0xb000-0xb03f] claimed by PIIX4
ACPI
[    0.334009] acpi PNP0A03:00: ACPI _OSC support notification failed, disabling
PCIe ASPM
[    0.335008] acpi PNP0A03:00: Unable to request _OSC control (_OSC support
mask: 0x08)
[    0.336488] ACPI: PCI Interrupt Link [LNKA] (IRQs *5 10 11)
[    0.339000] ACPI: PCI Interrupt Link [LNKB] (IRQs 5 *10 11)
[    0.341023] ACPI: PCI Interrupt Link [LNKC] (IRQs 5 10 *11)
[    0.344029] ACPI: PCI Interrupt Link [LNKD] (IRQs *5 10 11)
[    0.375796] ACPI: Enabled 2 GPEs in block 00 to 0F
[    0.408515] ACPI: No dock devices found.
[    0.409127] xen/balloon: Initialising balloon driver.
[    0.412082] xen-balloon: Initialising balloon driver.
[    0.413350] vgaarb: device added:
PCI:0000:00:02.0,decodes=io+mem,owns=io+mem,locks=none
[    0.414015] vgaarb: loaded
[    0.415007] vgaarb: bridge control possible 0000:00:02.0
[    0.416216] ACPI: bus type USB registered
[    0.417132] usbcore: registered new interface driver usbfs
[    0.418087] usbcore: registered new interface driver hub
[    0.419109] usbcore: registered new device driver usb
[    0.420197] pps_core: LinuxPPS API ver. 1 registered
[    0.421013] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo
Giometti <giometti@linux.it>
[    0.422067] PTP clock support registered
[    0.423147] PCI: Using ACPI for IRQ routing
[    0.425142] NetLabel: Initializing
[    0.426016] NetLabel:  domain hash size = 128
[    0.427006] NetLabel:  protocols = UNLABELED CIPSOv4
[    0.428041] NetLabel:  unlabeled traffic allowed by default
[    0.429261] HPET: 3 timers in total, 0 timers will be used for per-cpu timer
[    0.430032] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0
[    0.432343] hpet0: 3 comparators, 64-bit 62.500000 MHz counter
[    0.434050] Switching to clocksource xen
[    0.445570] pnp: PnP ACPI init
[    0.449585] ACPI: bus type PNP registered
[    0.454852] system 00:00: [mem 0x00000000-0x0009ffff] could not be reserved
[    0.463906] system 00:02: [io  0x08a0-0x08a3] has been reserved
[    0.471170] system 00:02: [io  0x0cc0-0x0ccf] has been reserved
[    0.478425] system 00:02: [io  0x04d0-0x04d1] has been reserved
[    0.486674] system 00:0b: [io  0x10c0-0x1141] has been reserved
[    0.494022] system 00:0b: [io  0xb044-0xb047] has been reserved
[    0.529363] pnp: PnP ACPI: found 12 devices
[    0.534578] ACPI: bus type PNP unregistered
[    0.548620] NET: Registered protocol family 2
[    0.554102] TCP established hash table entries: 16384 (order: 6, 262144
bytes)
[    0.562833] TCP bind hash table entries: 16384 (order: 8, 1048576 bytes)
[    0.571383] TCP: Hash tables configured (established 16384 bind 16384)
[    0.579085] TCP: reno registered
[    0.583084] UDP hash table entries: 1024 (order: 5, 163840 bytes)
[    0.590605] UDP-Lite hash table entries: 1024 (order: 5, 163840 bytes)
[    0.599144] NET: Registered protocol family 1
[    0.604570] RPC: Registered named UNIX socket transport module.
[    0.611845] RPC: Registered udp transport module.
[    0.617442] RPC: Registered tcp transport module.
[    0.623361] RPC: Registered tcp NFSv4.1 backchannel transport module.
[    0.631110] pci 0000:00:00.0: Limiting direct PCI/PCI transfers
[    0.638355] pci 0000:00:01.0: PIIX3: Enabling Passive Release
[    0.645352] pci 0000:00:01.0: Activating ISA DMA hang workarounds
[    0.653163] Unpacking initramfs...
[    2.665438] Freeing initrd memory: 126924k freed
[    2.685115] Machine check injector initialized
[    2.691259] microcode: CPU0 sig=0x206a7, pf=0x2, revision=0x25
[    2.698107] microcode: Microcode Update Driver: v2.00
<tigran@aivazian.fsnet.co.uk>, Peter Oruba
[    2.708013] Scanning for low memory corruption every 60 seconds
[    2.715204] audit: initializing netlink socket (disabled)
[    2.721340] type=2000 audit(1368028946.427:1): initialized
[    2.746153] HugeTLB registered 2 MB page size, pre-allocated 0 pages
[    2.754076] VFS: Disk quotas dquot_6.5.2
[    2.758740] Dquot-cache hash table entries: 512 (order 0, 4096 bytes)
[    2.766586] NFS: Registering the id_resolver key type
[    2.772412] Key type id_resolver registered
[    2.777297] Key type id_legacy registered
[    2.782015] NTFS driver 2.1.30 [Flags: R/W].
[    2.787057] msgmni has been set to 3946
[    2.792475] Block layer SCSI generic (bsg) driver version 0.4 loaded (major
251)
[    2.801055] io scheduler noop registered
[    2.805620] io scheduler deadline registered
[    2.810571] io scheduler cfq registered (default)
[    2.816243] pci_hotplug: PCI Hot Plug PCI Core version: 0.5
[    2.823155] cirrusfb 0000:00:02.0: Cirrus Logic chipset on PCI bus, RAM (4096
kB) at 0xf0000000
[    2.833820] input: Power Button as
/devices/LNXSYSTM:00/LNXPWRBN:00/input/input0
[    2.842362] ACPI: Power Button [PWRF]
[    2.846802] input: Sleep Button as
/devices/LNXSYSTM:00/LNXSLPBN:00/input/input1
[    2.855305] ACPI: Sleep Button [SLPF]
[    2.896600] GHES: HEST is not enabled!
[    2.901377] ioatdma: Intel(R) QuickData Technology Driver 4.00
[    2.908901] Grant tables using version 1 layout.
[    2.914474] Grant table initialized
[    2.944409] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
[    2.983474] 00:09: ttyS0 at I/O 0x3f8 (irq = 4) is a 16550A
[    2.991905] Non-volatile memory driver v1.3
[    2.996920] Linux agpgart interface v0.103
[    3.002120] [drm] Initialized drm 1.1.0 20060810
[    3.009382] loop: module loaded
[    3.013471] libphy: Fixed MDIO Bus: probed
[    3.018145] tun: Universal TUN/TAP device driver, 1.6
[    3.023930] tun: (C) 1999-2004 Max Krasnyansky <maxk@qualcomm.com>
[    3.031109] ixgbevf: Intel(R) 10 Gigabit PCI Express Virtual Function Network
Driver - version 2.7.12-k
[    3.041764] ixgbevf: Copyright (c) 2009 - 2012 Intel Corporation.
[    3.049129] ehci_hcd: USB 2.0 ''Enhanced'' Host Controller
(EHCI) Driver
[    3.056864] ehci-pci: EHCI PCI platform driver
[    3.062223] ohci_hcd: USB 1.1 ''Open'' Host Controller (OHCI)
Driver
[    3.069486] uhci_hcd: USB Universal Host Controller Interface driver
[    3.077003] usbcore: registered new interface driver usblp
[    3.083477] i8042: PNP: PS/2 Controller [PNP0303:PS2K,PNP0f13:PS2M] at
0x60,0x64 irq 1,12
[    3.095464] serio: i8042 KBD port at 0x60,0x64 irq 1
[    3.101303] serio: i8042 AUX port at 0x60,0x64 irq 12
[    3.107627] mousedev: PS/2 mouse device common for all mice
[    3.115733] input: AT Translated Set 2 keyboard as
/devices/platform/i8042/serio0/input/input2
[    3.133702] rtc_cmos 00:04: rtc core: registered rtc_cmos as rtc0
[    3.140779] rtc_cmos 00:04: alarms up to one day, 114 bytes nvram, hpet irqs
[    3.149263] cpuidle: using governor ladder
[    3.154239] cpuidle: using governor menu
[    3.159122] EFI Variables Facility v0.08 2004-May-17
[    3.165190] zram: Created 1 device(s) ...
[    3.170185] Netfilter messages via NETLINK v0.30.
[    3.176241] nf_conntrack version 0.5.0 (16384 buckets, 65536 max)
[    3.183848] ctnetlink v0.93: registering with nfnetlink.
[    3.190689] ip_tables: (C) 2000-2006 Netfilter Core Team
[    3.197472] TCP: cubic registered
[    3.201780] Initializing XFRM netlink socket
[    3.207111] NET: Registered protocol family 10
[    3.213416] ip6_tables: (C) 2000-2006 Netfilter Core Team
[    3.220348] sit: IPv6 over IPv4 tunneling driver
[    3.226247] NET: Registered protocol family 17
[    3.231481] Key type dns_resolver registered
[    3.236849] registered taskstats version 1
[    3.242382] XENBUS: Device with no driver: device/vbd/5632
[    3.248633] XENBUS: Device with no driver: device/vkbd/0
[    3.254808] XENBUS: Device with no driver: device/vif/0
[    3.261081]   Magic number: 13:252:34
[    3.267863] Freeing unused kernel memory: 1060k freed
[    3.273942] Write protecting the kernel read-only data: 12288k
[    3.283168] Freeing unused kernel memory: 1372k freed
[    3.291587] Freeing unused kernel memory: 1492k freed
init started: BusyBox v1.14.3 (2013-05-05 20:35:32 EDT)
[    3.306168] consoletype (1092) used greatest stack depth: 5192 bytes left
Mounting directories  [  OK  ]
[    3.419189] mv (1106) used greatest stack depth: 5024 bytes left
mount: mount point /proc/bus/usb does not exist
[    3.445186] modprobe (1121) used greatest stack depth: 4496 bytes left
mount: mount point /sys/kernel/config does not exist
[    3.467269] input: Xen Virtual Keyboard as /devices/virtual/input/input3
[    3.475315] input: Xen Virtual Pointer as /devices/virtual/input/input4
FATAL: Error inserting xen_fbfront
(/lib/modules/3.9.0upstream-00022-g49c1bf1-dirty/kernel/drivers/video/xen-fbfront.ko):
No such device
[    3.601797] Initialising Xen virtual ethernet driver.
[    3.710082] vbd vbd-5632: 19 xenbus_dev_probe on device/vbd/5632
[    3.717646] tsc: Refined TSC clocksource calibration: 3092.973 MHz
[    3.721460] vbd vbd-5632: failed to write error node for device/vbd/5632 (19
xenbus_dev_probe on device/vbd/5632)
[    3.750127] input: ImExPS/2 Generic Explorer Mouse as
/devices/platform/i8042/serio1/input/input5
[    3.761383] udevd (1159): /proc/1159/oom_adj is deprecated, please use
/proc/1159/oom_score_adj instead.
[    3.833519] SCSI subsystem initialized
[    3.840470] ACPI: bus type ATA registered
[    3.847543] libata version 3.00 loaded.
[    3.853983] ata_piix 0000:00:01.1: version 2.13
[    3.859870] ata_piix 0000:00:01.1: setting latency timer to 64
[    3.878641] scsi0 : ata_piix
[    3.885457] scsi1 : ata_piix
[    3.889541] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc200 irq 14
[    3.898192] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc208 irq 15
udevd-work[1391]: error opening ATTR{/sys/devices/system/cpu/cpu0/online} for
writing: No such file or directory

[    4.050772] ip (1723) used greatest stack depth: 3440 bytes left
[    4.061922] ata2.01: NODEV after polling detection
[    4.069697] ata2.00: ATAPI: QEMU DVD-ROM, 0.10.2, max UDMA/100
[    4.078630] ata2.00: configured for MWDMA2
[    4.086794] scsi 1:0:0:0: CD-ROM            QEMU     QEMU DVD-ROM     0.10
PQ: 0 ANSI: 5
[    4.156734] sr0: scsi3-mmc drive: 4x/4x xa/form2 tray
[    4.163052] cdrom: Uniform CD-ROM driver Revision: 3.20
[    4.197236] sr 1:0:0:0: Attached scsi CD-ROM sr0
[    4.220390] sr 1:0:0:0: Attached scsi generic sg0 type 5
Waiting for devices [  OK  ]
Waiting for init.pre_custom [  OK  ]
Waiting for fb [  OK  ]
Waiting for network [  OK  ]
Bringing up loopback interface:  [  OK  ]
Bringing up interface eth0:  
Determining IP information for eth0... done.
[  OK  ]
Waiting for init.custom [  OK  ]

Starting SSHd ...

    SSH started [2414]


Waiting for SSHd [  OK  ]
WARNING: ssh currently running [2414] ignoring start request
FATAL: Module dump_dma not found.
ERROR: Module dump_dma does not exist in /proc/modules
[    7.609564] Loading iSCSI transport class v2.0-870.
[    7.618305] iscsi: registered transport (tcp)
hostname: Name or service not known
iscsistart: transport class version 2.0-870. iscsid version 2.0-872
Could not get list of targets from firmware.
May  8 16:02:31 (none) syslogd 1.5.0: restart.
Running in HVM context on Xen v4.3.
You might have to do kill -1 1 if you see ''can''t open
/dev/hvc0''
[1:0:0:0]    cd/dvd  QEMU     QEMU DVD-ROM     0.10  /dev/sr0 
00:00.0 Host bridge: Intel Corporation 440FX - 82441FX PMC [Natoma] (rev 02)
00:01.0 ISA bridge: Intel Corporation 82371SB PIIX3 ISA [Natoma/Triton II]
00:01.1 IDE interface: Intel Corporation 82371SB PIIX3 IDE [Natoma/Triton II]
00:01.3 Bridge: Intel Corporation 82371AB/EB/MB PIIX4 ACPI (rev 01)
00:02.0 VGA compatible controller: Cirrus Logic GD 5446
00:03.0 Class ff80: XenSource, Inc. Xen Platform Device (rev 01)
            CPU0       
   0:        176   IO-APIC-edge      timer
   1:          9  xen-pirq-ioapic-edge  i8042
   4:        235  xen-pirq-ioapic-edge  serial
   8:          4  xen-pirq-ioapic-edge  rtc0
   9:          0   IO-APIC-fasteoi   acpi
  12:        125  xen-pirq-ioapic-edge  i8042
  14:          0   IO-APIC-edge      ata_piix
  15:         96   IO-APIC-edge      ata_piix
  64:       3675  xen-percpu-virq      timer0
  65:          0  xen-percpu-ipi       resched0
  66:          0  xen-percpu-ipi       callfunc0
  67:          0  xen-percpu-virq      debug0
  68:          0  xen-percpu-ipi       callfuncsingle0
  69:        300   xen-dyn-event     xenbus
  71:          0   xen-dyn-event     vkbd
  72:         19   xen-dyn-event     eth0
 NMI:          0   Non-maskable interrupts
 LOC:          0   Local timer interrupts
 SPU:          0   Spurious interrupts
 PMI:          0   Performance monitoring interrupts
 IWI:          0   IRQ work interrupts
 RTR:          0   APIC ICR read retries
 RES:          0   Rescheduling interrupts
 CAL:          0   Function call interrupts
 TLB:          0   TLB shootdowns
 TRM:          0   Thermal event interrupts
 THR:          0   Threshold APIC interrupts
 MCE:          0   Machine check exceptions
 MCP:          1   Machine check polls
 ERR:          0
 MIS:          0
00000000-00000fff : reserved
00001000-0009dfff : System RAM
0009e000-0009ffff : reserved
000a0000-000bffff : PCI Bus 0000:00
000c0000-000c8bff : Video ROM
000c9000-000c99ff : Adapter ROM
000e0000-000fffff : reserved
  000f0000-000fffff : System ROM
00100000-7f7fffff : System RAM
  01000000-016a6728 : Kernel code
  016a6729-01cc52bf : Kernel data
  01dd7000-026f5fff : Kernel bss
7f800000-7fffffff : RAM buffer
f0000000-fbffffff : PCI Bus 0000:00
  f0000000-f1ffffff : 0000:00:02.0
    f0000000-f1ffffff : cirrusfb
  f2000000-f2ffffff : 0000:00:03.0
    f2000000-f2ffffff : xen-platform-pci
  f3000000-f3000fff : 0000:00:02.0
    f3000000-f3000fff : cirrusfb
fc000000-ffffffff : reserved
  fec00000-fec003ff : IOAPIC 0
  fed00000-fed003ff : HPET 0
  fee00000-fee00fff : Local APIC
MemTotal:        2024688 kB
MemFree:         1510268 kB
Buffers:               0 kB
Cached:           458324 kB
SwapCached:            0 kB
Active:            14096 kB
Inactive:         443996 kB
Active(anon):       7944 kB
Inactive(anon):    86980 kB
Active(file):       6152 kB
Inactive(file):   357016 kB
Unevictable:        4952 kB
Mlocked:            4952 kB
SwapTotal:             0 kB
SwapFree:              0 kB
Dirty:                 0 kB
Writeback:             0 kB
AnonPages:          4736 kB
Mapped:             5024 kB
Shmem:             91572 kB
Slab:              38928 kB
SReclaimable:      20052 kB
SUnreclaim:        18876 kB
KernelStack:        1448 kB
PageTables:          660 kB
NFS_Unstable:          0 kB
Bounce:                0 kB
WritebackTmp:          0 kB
CommitLimit:     1012344 kB
Committed_AS:     100504 kB
VmallocTotal:   34359738367 kB
VmallocUsed:        9184 kB
VmallocChunk:   34359728763 kB
AnonHugePages:         0 kB
HugePages_Total:       0
HugePages_Free:        0
HugePages_Rsvd:        0
HugePages_Surp:        0
Hugepagesize:       2048 kB
DirectMap4k:       49152 kB
DirectMap2M:     2039808 kB
Waiting for init.late [  OK  ]
PING build.dumpdata.com (192.168.102.1) 56(84) bytes of data.

--- build.dumpdata.com ping statistics ---
1 packets transmitted, 1 received, 0% packet loss, time 1ms
rtt min/avg/max/mdev = 0.303/0.303/0.303/0.000 ms
[    8.135473] mount.nfs (2505) used greatest stack depth: 2768 bytes left
NFS done
libxl: error: libxl.c:87:libxl_ctx_alloc: Is xenstore daemon running?
failed to stat /var/run/xenstored.pid: No such file or directory
cannot init xl context
[    8.164452] device-mapper: ioctl: 4.24.0-ioctl (2013-01-15) initialised:
dm-devel@redhat.com
[    8.175591] device-mapper: multipath: version 1.5.1 loaded
  No matching physical volumes found
  No volume groups found
 8 May 16:02:34 ntpdate[2524]: step time server 17.171.4.14 offset -0.507791 sec
Wed May  8 16:02:35 UTC 2013
Starting net testcase..
May  8 16:02:35 (none) init: starting pid 2541, tty
''/dev/tty0'': ''/bin/sh''


BusyBox v1.14.3 (2013-05-05 20:35:32 EDT) built-in shell (ash)
Enter ''help'' for a list of built-in commands.

May  8 16:02:35 (none) init: starting pid 2542, tty
''/dev/tty1'': ''/bin/sh''
May  8 16:02:35 (none) init: starting pid 2543, tty
''/dev/ttyS0'': ''/bin/sh''
May  8 16:02:35 (none) init: starting pid 2544, tty
''/dev/hvc0'': ''/bin/sh''
Running Iperf Server as a daemon
Starting netserver at port 12865
The Iperf daemon process ID : 2545
Starting netserver at hostname 0.0.0.0 port 12865 and family AF_UNSPEC
# May  8 16:02:36 (none) init: process ''/bin/sh'' (pid 2544)
exited. Scheduling for restart.
May  8 16:02:36 (none) init: starting pid 2547, tty
''/dev/hvc0'': ''/bin/sh''
May  8 16:02:37 (none) init: process ''/bin/sh'' (pid 2547)
exited. Scheduling for restart.
May  8 16:02:37 (none) init: starting pid 2548, tty
''/dev/hvc0'': ''/bin/sh''
May  8 16:02:38 (none) init: process ''/bin/sh'' (pid 2548)
exited. Scheduling for restart.
May  8 16:02:38 (none) init: starting pid 2549, tty
''/dev/hvc0'': ''/bin/sh''
May  8 16:02:39 (none) init: process ''/bin/sh'' (pid 2549)
exited. Scheduling for restart.
May  8 16:02:39 (none) init: starting pid 2550, tty
''/dev/hvc0'': ''/bin/sh''
May  8 16:02:40 (none) init: process ''/bin/sh'' (pid 2550)
exited. Scheduling for restart.
May  8 16:02:40 (none) init: starting pid 2551, tty
''/dev/hvc0'': ''/bin/sh''
May  8 16:02:41 (none) init: process ''/bin/sh'' (pid 2551)
exited. Scheduling for restart.
May  8 16:02:41 (none) init: starting pid 2552, tty
''/dev/hvc0'': ''/bin/sh''
May  8 16:02:42 (none) init: process ''/bin/sh'' (pid 2552)
exited. Scheduling for restart.
May  8 16:02:42 (none) init: starting pid 2553, tty
''/dev/hvc0'': ''/bin/sh''
May  8 16:02:43 (none) init: process ''/bin/sh'' (pid 2553)
exited. Scheduling for restart.
May  8 16:02:43 (none) init: starting pid 2554, tty
''/dev/hvc0'': ''/bin/sh''
May  8 16:02:44 (none) init: process ''/bin/sh'' (pid 2554)
exited. Scheduling for restart.
May  8 16:02:44 (none) init: starting pid 2555, tty
''/dev/hvc0'': ''/bin/sh''
May  8 16:02:45 (none) init: process ''/bin/sh'' (pid 2555)
exited. Scheduling for restart.
May  8 16:02:45 (none) init: starting pid 2556, tty
''/dev/hvc0'': ''/bin/sh''
May  8 16:02:46 (none) init: process ''/bin/sh'' (pid 2556)
exited. Scheduling for restart.
May  8 16:02:46 (none) init: starting pid 2557, tty
''/dev/hvc0'': ''/bin/sh''
May  8 16:02:47 (none) init: process ''/bin/sh'' (pid 2557)
exited. Scheduling for restart.
May  8 16:02:47 (none) init: starting pid 2558, tty
''/dev/hvc0'': ''/bin/sh''
May  8 16:02:48 (none) init: process ''/bin/sh'' (pid 2558)
exited. Scheduling for restart.
May  8 16:02:48 (none) init: starting pid 2559, tty
''/dev/hvc0'': ''/bin/sh''
May  8 16:02:49 (none) init: process ''/bin/sh'' (pid 2559)
exited. Scheduling for restart.
May  8 16:02:49 (none) init: starting pid 2560, tty
''/dev/hvc0'': ''/bin/sh''
May  8 16:02:50 (none) init: process ''/bin/sh'' (pid 2560)
exited. Scheduling for restart.
May  8 16:02:50 (none) init: starting pid 2561, tty
''/dev/hvc0'': ''/bin/sh''
May  8 16:02:51 (none) init: process ''/bin/sh'' (pid 2561)
exited. Scheduling for restart.
May  8 16:02:51 (none) init: starting pid 2562, tty
''/dev/hvc0'': ''/bin/sh''
May  8 16:02:52 (none) init: process ''/bin/sh'' (pid 2562)
exited. Scheduling for restart.
May  8 16:02:52 (none) init: starting pid 2563, tty
''/dev/hvc0'': ''/bin/sh''
May  8 16:02:53 (none) init: process ''/bin/sh'' (pid 2563)
exited. Scheduling for restart.
May  8 16:02:53 (none) init: starting pid 2564, tty
''/dev/hvc0'': ''/bin/sh''
May  8 16:02:54 (none) init: process ''/bin/sh'' (pid 2564)
exited. Scheduling for restart.
May  8 16:02:54 (none) init: starting pid 2565, tty
''/dev/hvc0'': ''/bin/sh''
May  8 16:02:55 (none) init: process ''/bin/sh'' (pid 2565)
exited. Scheduling for restart.
May  8 16:02:55 (none) init: starting pid 2566, tty
''/dev/hvc0'': ''/bin/sh''
May  8 16:02:56 (none) init: process ''/bin/sh'' (pid 2566)
exited. Scheduling for restart.
May  8 16:02:56 (none) init: starting pid 2567, tty
''/dev/hvc0'': ''/bin/sh''
May  8 16:02:57 (none) init: process ''/bin/sh'' (pid 2567)
exited. Scheduling for restart.
May  8 16:02:57 (none) init: starting pid 2568, tty
''/dev/hvc0'': ''/bin/sh''
May  8 16:02:58 (none) init: process ''/bin/sh'' (pid 2568)
exited. Scheduling for restart.
May  8 16:02:58 (none) init: starting pid 2569, tty
''/dev/hvc0'': ''/bin/sh''
May  8 16:02:59 (none) init: process ''/bin/sh'' (pid 2569)
exited. Scheduling for restart.
May  8 16:02:59 (none) init: starting pid 2570, tty
''/dev/hvc0'': ''/bin/sh''
May  8 16:03:00 (none) init: process ''/bin/sh'' (pid 2570)
exited. Scheduling for restart.
May  8 16:03:00 (none) init: starting pid 2571, tty
''/dev/hvc0'': ''/bin/sh''
May  8 16:03:01 (none) init: process ''/bin/sh'' (pid 2571)
exited. Scheduling for restart.
May  8 16:03:01 (none) init: starting pid 2572, tty
''/dev/hvc0'': ''/bin/sh''
May  8 16:03:02 (none) init: process ''/bin/sh'' (pid 2572)
exited. Scheduling for restart.
May  8 16:03:02 (none) init: starting pid 2573, tty
''/dev/hvc0'': ''/bin/sh''
May  8 16:03:03 (none) init: process ''/bin/sh'' (pid 2573)
exited. Scheduling for restart.
May  8 16:03:03 (none) init: starting pid 2574, tty
''/dev/hvc0'': ''/bin/sh''
May  8 16:03:04 (none) init: process ''/bin/sh'' (pid 2574)
exited. Scheduling for restart.
May  8 16:03:04 (none) init: starting pid 2575, tty
''/dev/hvc0'': ''/bin/sh''
May  8 16:03:05 (none) init: process ''/bin/sh'' (pid 2575)
exited. Scheduling for restart.
May  8 16:03:05 (none) init: starting pid 2576, tty
''/dev/hvc0'': ''/bin/sh''
May  8 16:03:06 (none) init: process ''/bin/sh'' (pid 2576)
exited. Scheduling for restart.
May  8 16:03:06 (none) init: starting pid 2577, tty
''/dev/hvc0'': ''/bin/sh''
May  8 16:03:07 (none) init: process ''/bin/sh'' (pid 2577)
exited. Scheduling for restart.
May  8 16:03:07 (none) init: starting pid 2578, tty
''/dev/hvc0'': ''/bin/sh''
May  8 16:03:08 (none) init: process ''/bin/sh'' (pid 2578)
exited. Scheduling for restart.
May  8 16:03:08 (none) init: starting pid 2579, tty
''/dev/hvc0'': ''/bin/sh''
May  8 16:03:09 (none) init: process ''/bin/sh'' (pid 2579)
exited. Scheduling for restart.
May  8 16:03:09 (none) init: starting pid 2580, tty
''/dev/hvc0'': ''/bin/sh''
May  8 16:03:10 (none) init: process ''/bin/sh'' (pid 2580)
exited. Scheduling for restart.
May  8 16:03:10 (none) init: starting pid 2581, tty
''/dev/hvc0'': ''/bin/sh''
May  8 16:03:11 (none) init: process ''/bin/sh'' (pid 2581)
exited. Scheduling for restart.
May  8 16:03:11 (none) init: starting pid 2582, tty
''/dev/hvc0'': ''/bin/sh''
May  8 16:03:12 (none) init: process ''/bin/sh'' (pid 2582)
exited. Scheduling for restart.
May  8 16:03:12 (none) init: starting pid 2583, tty
''/dev/hvc0'': ''/bin/sh''
May  8 16:03:13 (none) init: process ''/bin/sh'' (pid 2583)
exited. Scheduling for restart.
May  8 16:03:13 (none) init: starting pid 2584, tty
''/dev/hvc0'': ''/bin/sh''
May  8 16:03:14 (none) init: process ''/bin/sh'' (pid 2584)
exited. Scheduling for restart.
May  8 16:03:14 (none) init: starting pid 2585, tty
''/dev/hvc0'': ''/bin/sh''
May  8 16:03:15 (none) init: process ''/bin/sh'' (pid 2585)
exited. Scheduling for restart.
May  8 16:03:15 (none) init: starting pid 2586, tty
''/dev/hvc0'': ''/bin/sh''
May  8 16:03:16 (none) init: process ''/bin/sh'' (pid 2586)
exited. Scheduling for restart.
May  8 16:03:16 (none) init: starting pid 2587, tty
''/dev/hvc0'': ''/bin/sh''
May  8 16:03:17 (none) init: process ''/bin/sh'' (pid 2587)
exited. Scheduling for restart.
May  8 16:03:17 (none) init: starting pid 2588, tty
''/dev/hvc0'': ''/bin/sh''
May  8 16:03:18 (none) init: process ''/bin/sh'' (pid 2588)
exited. Scheduling for restart.
May  8 16:03:18 (none) init: starting pid 2589, tty
''/dev/hvc0'': ''/bin/sh''
May  8 16:03:19 (none) init: process ''/bin/sh'' (pid 2589)
exited. Scheduling for restart.
May  8 16:03:19 (none) init: starting pid 2590, tty
''/dev/hvc0'': ''/bin/sh''
May  8 16:03:20 (none) init: process ''/bin/sh'' (pid 2590)
exited. Scheduling for restart.
May  8 16:03:20 (none) init: starting pid 2591, tty
''/dev/hvc0'': ''/bin/sh''
May  8 16:03:21 (none) init: process ''/bin/sh'' (pid 2591)
exited. Scheduling for restart.
May  8 16:03:21 (none) init: starting pid 2592, tty
''/dev/hvc0'': ''/bin/sh''
May  8 16:03:22 (none) init: process ''/bin/sh'' (pid 2592)
exited. Scheduling for restart.
May  8 16:03:22 (none) init: starting pid 2593, tty
''/dev/hvc0'': ''/bin/sh''
May  8 16:03:23 (none) init: process ''/bin/sh'' (pid 2593)
exited. Scheduling for restart.
May  8 16:03:23 (none) init: starting pid 2594, tty
''/dev/hvc0'': ''/bin/sh''
May  8 16:03:24 (none) init: process ''/bin/sh'' (pid 2594)
exited. Scheduling for restart.
May  8 16:03:24 (none) init: starting pid 2595, tty
''/dev/hvc0'': ''/bin/sh''
May  8 16:03:25 (none) init: process ''/bin/sh'' (pid 2595)
exited. Scheduling for restart.
May  8 16:03:25 (none) init: starting pid 2596, tty
''/dev/hvc0'': ''/bin/sh''
May  8 16:03:26 (none) init: process ''/bin/sh'' (pid 2596)
exited. Scheduling for restart.
May  8 16:03:26 (none) init: starting pid 2597, tty
''/dev/hvc0'': ''/bin/sh''
May  8 16:03:27 (none) init: process ''/bin/sh'' (pid 2597)
exited. Scheduling for restart.
May  8 16:03:27 (none) init: starting pid 2598, tty
''/dev/hvc0'': ''/bin/sh''
May  8 16:03:28 (none) init: process ''/bin/sh'' (pid 2598)
exited. Scheduling for restart.
May  8 16:03:28 (none) init: starting pid 2599, tty
''/dev/hvc0'': ''/bin/sh''
May  8 16:03:29 (none) init: process ''/bin/sh'' (pid 2599)
exited. Scheduling for restart.
May  8 16:03:29 (none) init: starting pid 2600, tty
''/dev/hvc0'': ''/bin/sh''
May  8 16:03:30 (none) init: process ''/bin/sh'' (pid 2600)
exited. Scheduling for restart.
May  8 16:03:30 (none) init: starting pid 2601, tty
''/dev/hvc0'': ''/bin/sh''
May  8 16:03:31 (none) init: process ''/bin/sh'' (pid 2601)
exited. Scheduling for restart.
May  8 16:03:31 (none) init: starting pid 2602, tty
''/dev/hvc0'': ''/bin/sh''
May  8 16:03:32 (none) init: process ''/bin/sh'' (pid 2602)
exited. Scheduling for restart.
May  8 16:03:32 (none) init: starting pid 2603, tty
''/dev/hvc0'': ''/bin/sh''
May  8 16:03:33 (none) init: process ''/bin/sh'' (pid 2603)
exited. Scheduling for restart.
May  8 16:03:33 (none) init: starting pid 2604, tty
''/dev/hvc0'': ''/bin/sh''
May  8 16:03:34 (none) init: process ''/bin/sh'' (pid 2604)
exited. Scheduling for restart.
May  8 16:03:34 (none) init: starting pid 2605, tty
''/dev/hvc0'': ''/bin/sh''
May  8 16:03:35 (none) init: process ''/bin/sh'' (pid 2605)
exited. Scheduling for restart.
May  8 16:03:35 (none) init: starting pid 2606, tty
''/dev/hvc0'': ''/bin/sh''
May  8 16:03:36 (none) init: process ''/bin/sh'' (pid 2606)
exited. Scheduling for restart.
May  8 16:03:36 (none) init: starting pid 2607, tty
''/dev/hvc0'': ''/bin/sh''
May  8 16:03:37 (none) init: process ''/bin/sh'' (pid 2607)
exited. Scheduling for restart.
May  8 16:03:37 (none) init: starting pid 2608, tty
''/dev/hvc0'': ''/bin/sh''
May  8 16:03:38 (none) init: process ''/bin/sh'' (pid 2608)
exited. Scheduling for restart.
May  8 16:03:38 (none) init: starting pid 2609, tty
''/dev/hvc0'': ''/bin/sh''
May  8 16:03:39 (none) init: process ''/bin/sh'' (pid 2609)
exited. Scheduling for restart.
May  8 16:03:39 (none) init: starting pid 2610, tty
''/dev/hvc0'': ''/bin/sh''
May  8 16:03:40 (none) init: process ''/bin/sh'' (pid 2610)
exited. Scheduling for restart.
May  8 16:03:40 (none) init: starting pid 2611, tty
''/dev/hvc0'': ''/bin/sh''
May  8 16:03:41 (none) init: process ''/bin/sh'' (pid 2611)
exited. Scheduling for restart.
May  8 16:03:41 (none) init: starting pid 2612, tty
''/dev/hvc0'': ''/bin/sh''
May  8 16:03:42 (none) init: process ''/bin/sh'' (pid 2612)
exited. Scheduling for restart.
May  8 16:03:42 (none) init: starting pid 2613, tty
''/dev/hvc0'': ''/bin/sh''
May  8 16:03:43 (none) init: process ''/bin/sh'' (pid 2613)
exited. Scheduling for restart.
May  8 16:03:43 (none) init: starting pid 2614, tty
''/dev/hvc0'': ''/bin/sh''
May  8 16:03:44 (none) init: process ''/bin/sh'' (pid 2614)
exited. Scheduling for restart.
May  8 16:03:44 (none) init: starting pid 2615, tty
''/dev/hvc0'': ''/bin/sh''
May  8 16:03:45 (none) init: process ''/bin/sh'' (pid 2615)
exited. Scheduling for restart.
May  8 16:03:45 (none) init: starting pid 2616, tty
''/dev/hvc0'': ''/bin/sh''
May  8 16:03:46 (none) init: process ''/bin/sh'' (pid 2616)
exited. Scheduling for restart.
May  8 16:03:46 (none) init: starting pid 2617, tty
''/dev/hvc0'': ''/bin/sh''
May  8 16:03:47 (none) init: process ''/bin/sh'' (pid 2617)
exited. Scheduling for restart.
May  8 16:03:47 (none) init: starting pid 2618, tty
''/dev/hvc0'': ''/bin/sh''
May  8 16:03:48 (none) udevd-work[2153]: error opening
ATTR{/sys/devices/system/cpu/cpu1/online} for writing: No such file or directory
[   84.585905] CPU 1 got hotplugged
[   84.590192] installing Xen timer for CPU 1
[   84.596371] SMP alternatives: lockdep: fixing up alternatives
[   84.603560] SMP alternatives: switching to SMP code
[   84.619508] smpboot: Booting Node 0 Processor 1 APIC 0x8
[   84.639766] ------------[ cut here ]------------
[   84.639766] WARNING: at /home/konrad/ssd/konrad/linux/arch/x86/xen/time.c:336
xen_vcpuop_set_mode+0xc2/0xd0()
[   84.639766] Hardware name: HVM domU
[   84.639766] VCPUOP_stop_singleshot_timer on CPU1 ret: -22
[   84.639766] Modules linked in: dm_multipath dm_mod iscsi_boot_sysfs iscsi_tcp
libiscsi_tcp libiscsi scsi_transport_iscsi libcrc32c crc32c sg sr_mod cdrom
ata_generic crc32c_intel ata_piix libata scsi_mod xen_blkfront xen_netfront
fb_sys_fops sysimgblt sysfillrect syscopyarea xen_kbdfront xenfs xen_privcmd
[   84.639766] Pid: 0, comm: swapper/1 Not tainted
3.9.0upstream-00022-g49c1bf1-dirty #6
[   84.639766] Call Trace:
[   84.639766]  [<ffffffff8109261a>] warn_slowpath_common+0x7a/0xc0
[   84.639766]  [<ffffffff81092701>] warn_slowpath_fmt+0x41/0x50
[   84.639766]  [<ffffffff810e8ae4>] ? tick_notify+0x114/0x420
[   84.639766]  [<ffffffff81044fe2>] xen_vcpuop_set_mode+0xc2/0xd0
[   84.639766]  [<ffffffff810e8385>] clockevents_set_mode+0x25/0x70
[   84.639766]  [<ffffffff810e83e6>] clockevents_shutdown+0x16/0x30
[   84.639766]  [<ffffffff810e84b7>]
clockevents_exchange_device+0xb7/0x110
[   84.639766]  [<ffffffff810e8ae4>] ? tick_notify+0x114/0x420
[   84.639766]  [<ffffffff810e8b99>] tick_notify+0x1c9/0x420
[   84.639766]  [<ffffffff810e8221>] ?
clockevents_register_device+0x31/0x170
[   84.639766]  [<ffffffff8169dddd>] notifier_call_chain+0x4d/0x70
[   84.639766]  [<ffffffff810be851>] raw_notifier_call_chain+0x11/0x20
[   84.639766]  [<ffffffff810e82d0>]
clockevents_register_device+0xe0/0x170
[   84.639766]  [<ffffffff8104507c>] xen_setup_cpu_clockevents+0x2c/0x50
[   84.639766]  [<ffffffff810450b6>]
xen_hvm_setup_cpu_clockevents+0x16/0x20
[   84.639766]  [<ffffffff8168d4af>] start_secondary+0x1ea/0x1f9
[   84.639766] ---[ end trace f218984223a7067d ]---
[   84.639766] ------------[ cut here ]------------
[   84.639766] WARNING: at /home/konrad/ssd/konrad/linux/arch/x86/xen/time.c:338
xen_vcpuop_set_mode+0x9f/0xd0()
[   84.639766] Hardware name: HVM domU
[   84.639766] VCPUOP_stop_periodic_timer on CPU1 ret: -22
[   84.639766] Modules linked in: dm_multipath dm_mod iscsi_boot_sysfs iscsi_tcp
libiscsi_tcp libiscsi scsi_transport_iscsi libcrc32c crc32c sg sr_mod cdrom
ata_generic crc32c_intel ata_piix libata scsi_mod xen_blkfront xen_netfront
fb_sys_fops sysimgblt sysfillrect syscopyarea xen_kbdfront xenfs xen_privcmd
[   84.639766] Pid: 0, comm: swapper/1 Tainted: G        W   
3.9.0upstream-00022-g49c1bf1-dirty #6
[   84.639766] Call Trace:
[   84.639766]  [<ffffffff8109261a>] warn_slowpath_common+0x7a/0xc0
[   84.639766]  [<ffffffff81092701>] warn_slowpath_fmt+0x41/0x50
[   84.639766]  [<ffffffff810e8ae4>] ? tick_notify+0x114/0x420
[   84.639766]  [<ffffffff81044fbf>] xen_vcpuop_set_mode+0x9f/0xd0
[   84.639766]  [<ffffffff810e8385>] clockevents_set_mode+0x25/0x70
[   84.639766]  [<ffffffff810e83e6>] clockevents_shutdown+0x16/0x30
[   84.639766]  [<ffffffff810e84b7>]
clockevents_exchange_device+0xb7/0x110
[   84.639766]  [<ffffffff810e8ae4>] ? tick_notify+0x114/0x420
[   84.639766]  [<ffffffff810e8b99>] tick_notify+0x1c9/0x420
[   84.639766]  [<ffffffff810e8221>] ?
clockevents_register_device+0x31/0x170
[   84.639766]  [<ffffffff8169dddd>] notifier_call_chain+0x4d/0x70
[   84.639766]  [<ffffffff810be851>] raw_notifier_call_chain+0x11/0x20
[   84.639766]  [<ffffffff810e82d0>]
clockevents_register_device+0xe0/0x170
[   84.639766]  [<ffffffff8104507c>] xen_setup_cpu_clockevents+0x2c/0x50
[   84.639766]  [<ffffffff810450b6>]
xen_hvm_setup_cpu_clockevents+0x16/0x20
[   84.639766]  [<ffffffff8168d4af>] start_secondary+0x1ea/0x1f9
[   84.639766] ---[ end trace f218984223a7067e ]---
[   84.639766] ------------[ cut here ]------------
[   84.639766] kernel BUG at
/home/konrad/ssd/konrad/linux/arch/x86/xen/time.c:340!
[   84.639766] invalid opcode: 0000 [#1] SMP 
[   84.639766] Modules linked in: dm_multipath dm_mod iscsi_boot_sysfs iscsi_tcp
libiscsi_tcp libiscsi scsi_transport_iscsi libcrc32c crc32c sg sr_mod cdrom
ata_generic crc32c_intel ata_piix libata scsi_mod xen_blkfront xen_netfront
fb_sys_fops sysimgblt sysfillrect syscopyarea xen_kbdfront xenfs xen_privcmd
[   84.639766] CPU 1 
[   84.639766] Pid: 0, comm: swapper/1 Tainted: G        W   
3.9.0upstream-00022-g49c1bf1-dirty #6 Xen HVM domU
[   84.639766] RIP: 0010:[<ffffffff81044fbf>]  [<ffffffff81044fbf>]
xen_vcpuop_set_mode+0x9f/0xd0
[   84.639766] RSP: 0000:ffff880073c6bd98  EFLAGS: 00010092
[   84.639766] RAX: 0000000000000024 RBX: 0000000000000001 RCX: 0000000000000000
[   84.639766] RDX: ffff880073c68300 RSI: 0000000000000000 RDI: 0000000000000009
[   84.639766] RBP: ffff880073c6bdb8 R08: 0000000000000001 R09: 0000000000000000
[   84.639766] R10: 0000000000000258 R11: 0000000000000000 R12: 00000000ffffffea
[   84.639766] R13: 0000000000000001 R14: 0000000000000000 R15: 0000000000000082
[   84.639766] FS:  0000000000000000(0000) GS:ffff880074220000(0000)
knlGS:0000000000000000
[   84.639766] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[   84.639766] CR2: 0000000000000000 CR3: 0000000001c0c000 CR4: 00000000000406e0
[   84.639766] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[   84.639766] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
[   84.639766] Process swapper/1 (pid: 0, threadinfo ffff880073c6a000, task
ffff880073c68300)
[   84.639766] Stack:
[   84.639766]  0000000000000000 ffff88007422be40 0000000000000001
0000000000000082
[   84.639766]  ffff880073c6bdd8 ffffffff810e8385 ffff88007422be40
ffff88007422be40
[   84.639766]  ffff880073c6bdf8 ffffffff810e83e6 ffff880073c6bdf8
0000000000000000
[   84.639766] Call Trace:
[   84.639766]  [<ffffffff810e8385>] clockevents_set_mode+0x25/0x70
[   84.639766]  [<ffffffff810e83e6>] clockevents_shutdown+0x16/0x30
[   84.639766]  [<ffffffff810e84b7>]
clockevents_exchange_device+0xb7/0x110
[   84.639766]  [<ffffffff810e8ae4>] ? tick_notify+0x114/0x420
[   84.639766]  [<ffffffff810e8b99>] tick_notify+0x1c9/0x420
[   84.639766]  [<ffffffff810e8221>] ?
clockevents_register_device+0x31/0x170
[   84.639766]  [<ffffffff8169dddd>] notifier_call_chain+0x4d/0x70
[   84.639766]  [<ffffffff810be851>] raw_notifier_call_chain+0x11/0x20
[   84.639766]  [<ffffffff810e82d0>]
clockevents_register_device+0xe0/0x170
[   84.639766]  [<ffffffff8104507c>] xen_setup_cpu_clockevents+0x2c/0x50
[   84.639766]  [<ffffffff810450b6>]
xen_hvm_setup_cpu_clockevents+0x16/0x20
[   84.639766]  [<ffffffff8168d4af>] start_secondary+0x1ea/0x1f9
[   84.639766] Code: 00 48 c7 c7 f8 bc 9b 81 e8 bf d6 04 00 eb c9 89 d9 48 c7 c2
98 bd 9b 81 be 52 01 00 00 48 c7 c7 f8 bc 9b 81 31 c0 e8 01 d7 04 00 <0f>
0b eb fe 41 89 c0 89 d9 48 c7 c2 68 bd 9b 81 be 50 01 00 00
[   84.639766] RIP  [<ffffffff81044fbf>] xen_vcpuop_set_mode+0x9f/0xd0
[   84.639766]  RSP <ffff880073c6bd98>
[   84.639766] ---[ end trace f218984223a7067f ]---
[   84.639766] Kernel panic - not syncing: Attempted to kill the idle task!
Parsing config from /mnt/lab/latest/vm.cfg
Daemon running with PID 7341

On Tue, Jun 04, 2013 at 10:22:24AM -0400, Konrad Rzeszutek Wilk
wrote:
> > > > > The new hypercall to figure this out could be used, but
that wouldn''t
> > > > > explain why we are failing to start on the correct
VCPU?
> > > > 
> > > > I didn''t follow the jump here. Can you provide an
example?
> > > 
> > >
http://lists.xen.org/archives/html/xen-devel/2013-05/msg00941.html
> > 
> > OK, got it.
> > 
> > [   84.619508] smpboot: Booting Node 0 Processor 1 APIC 0x8
> > 
> > So it seems like, in this case:
> > 
> > int __cpuinit native_cpu_up(unsigned int cpu)
> > {
> >         int apicid = apic->cpu_present_to_apicid(cpu);
> > 
> > apic->cpu_present_to_apicid(1) returned 8 instead of 2.
> > 
> > All of that should have been set up correctly ahead of time by
> > generic_processor_info() for all possible CPUs. Do you have the full
> > boot log?
> > 
[...]
> [    0.000000] ACPI: LAPIC (acpi_id[0x00] lapic_id[0x00] enabled)
> [    0.000000] ACPI: LAPIC (acpi_id[0x01] lapic_id[0x02] disabled)
> [    0.000000] ACPI: LAPIC (acpi_id[0x02] lapic_id[0x04] disabled)
> [    0.000000] ACPI: LAPIC (acpi_id[0x03] lapic_id[0x06] disabled)
> [    0.000000] ACPI: LAPIC (acpi_id[0x04] lapic_id[0x08] disabled)
> [    0.000000] ACPI: LAPIC (acpi_id[0x05] lapic_id[0x0a] disabled)
[...]
> [    0.000000] ACPI: LAPIC (acpi_id[0x7b] lapic_id[0xf6] disabled)
> [    0.000000] ACPI: LAPIC (acpi_id[0x7c] lapic_id[0xf8] disabled)
> [    0.000000] ACPI: LAPIC (acpi_id[0x7d] lapic_id[0xfa] disabled)
> [    0.000000] ACPI: LAPIC (acpi_id[0x7e] lapic_id[0xfc] disabled)
> [    0.000000] ACPI: LAPIC (acpi_id[0x7f] lapic_id[0xfe] disabled)
OK, so generic_processor_info() is not called for disabled processors,
so it must happen at processor UP time.

Can you boot with "acpi.debug_layer=0x20000000 acpi.debug_level=0x4"?

--msw

On Wed, Jun 05, 2013 at 09:15:41AM -0700, Matt Wilson
wrote:
> On Tue, Jun 04, 2013 at 10:22:24AM -0400, Konrad Rzeszutek Wilk wrote:
> > > > > > The new hypercall to figure this out could be
used, but that wouldn''t
> > > > > > explain why we are failing to start on the correct
VCPU?
> > > > > 
> > > > > I didn''t follow the jump here. Can you provide
an example?
> > > > 
> > > >
http://lists.xen.org/archives/html/xen-devel/2013-05/msg00941.html
> > > 
> > > OK, got it.
> > > 
> > > [   84.619508] smpboot: Booting Node 0 Processor 1 APIC 0x8
> > > 
> > > So it seems like, in this case:
> > > 
> > > int __cpuinit native_cpu_up(unsigned int cpu)
> > > {
> > >         int apicid = apic->cpu_present_to_apicid(cpu);
> > > 
> > > apic->cpu_present_to_apicid(1) returned 8 instead of 2.
> > > 
> > > All of that should have been set up correctly ahead of time by
> > > generic_processor_info() for all possible CPUs. Do you have the
full
> > > boot log?
> > > 
> 
> [...]
> 
> > [    0.000000] ACPI: LAPIC (acpi_id[0x00] lapic_id[0x00] enabled)
> > [    0.000000] ACPI: LAPIC (acpi_id[0x01] lapic_id[0x02] disabled)
> > [    0.000000] ACPI: LAPIC (acpi_id[0x02] lapic_id[0x04] disabled)
> > [    0.000000] ACPI: LAPIC (acpi_id[0x03] lapic_id[0x06] disabled)
> > [    0.000000] ACPI: LAPIC (acpi_id[0x04] lapic_id[0x08] disabled)
> > [    0.000000] ACPI: LAPIC (acpi_id[0x05] lapic_id[0x0a] disabled)
> [...]
> > [    0.000000] ACPI: LAPIC (acpi_id[0x7b] lapic_id[0xf6] disabled)
> > [    0.000000] ACPI: LAPIC (acpi_id[0x7c] lapic_id[0xf8] disabled)
> > [    0.000000] ACPI: LAPIC (acpi_id[0x7d] lapic_id[0xfa] disabled)
> > [    0.000000] ACPI: LAPIC (acpi_id[0x7e] lapic_id[0xfc] disabled)
> > [    0.000000] ACPI: LAPIC (acpi_id[0x7f] lapic_id[0xfe] disabled)
> 
> OK, so generic_processor_info() is not called for disabled processors,
> so it must happen at processor UP time.
> 
> Can you boot with "acpi.debug_layer=0x20000000
acpi.debug_level=0x4"?
If I can reproduce it again - absolutly. Right now the race seems to have
gone away and the APIC id is 0x02 (the right value) instead of 0x08.

On Tue, Jun 04, 2013 at 10:22:24AM -0400, Konrad Rzeszutek Wilk
wrote:
> > > > > The new hypercall to figure this out could be used, but
that wouldn''t
> > > > > explain why we are failing to start on the correct
VCPU?
> > > > 
> > > > I didn''t follow the jump here. Can you provide an
example?
> > > 
> > >
http://lists.xen.org/archives/html/xen-devel/2013-05/msg00941.html
> > 
> > OK, got it.
> > 
> > [   84.619508] smpboot: Booting Node 0 Processor 1 APIC 0x8
> > 
> > So it seems like, in this case:
> > 
> > int __cpuinit native_cpu_up(unsigned int cpu)
> > {
> >         int apicid = apic->cpu_present_to_apicid(cpu);
> > 
> > apic->cpu_present_to_apicid(1) returned 8 instead of 2.
> > 
> > All of that should have been set up correctly ahead of time by
> > generic_processor_info() for all possible CPUs. Do you have the full
> > boot log?
> > 
> 
..snip...
> [    0.000000] ACPI: PM-Timer IO Port: 0xb008
> [    0.000000] ACPI: LAPIC (acpi_id[0x00] lapic_id[0x00] enabled)
> [    0.000000] ACPI: LAPIC (acpi_id[0x01] lapic_id[0x02] disabled)
> [    0.000000] ACPI: LAPIC (acpi_id[0x02] lapic_id[0x04] disabled)
> [    0.000000] ACPI: LAPIC (acpi_id[0x03] lapic_id[0x06] disabled)
> [    0.000000] ACPI: LAPIC (acpi_id[0x04] lapic_id[0x08] disabled)
                                                     ^^^^ - take a note of that
.. snip..
> [   84.585905] CPU 1 got hotplugged
> [   84.590192] installing Xen timer for CPU 1
> [   84.596371] SMP alternatives: lockdep: fixing up alternatives
> [   84.603560] SMP alternatives: switching to SMP code
> [   84.619508] smpboot: Booting Node 0 Processor 1 APIC 0x8
                                                          ^^^ and that
> [   84.639766] ------------[ cut here ]------------
> [   84.639766] WARNING: at
/home/konrad/ssd/konrad/linux/arch/x86/xen/time.c:336
xen_vcpuop_set_mode+0xc2/0xd0()
> [   84.639766] Hardware name: HVM domU
I discussed this with Matt over IRC, but the analysis was that the APIC
ID is wrong. Instead of using APIC 0x02 for CPU1, it ended up using APIC 0x08
(which is for CPU4). And that triggered the xen_vcpuop_set_mode to fail
(as the hypervisor would say - you are running on CPU4, not CPU1, return
-ENODEV) and we hit the BUG_ON() in the Linux.

Chuck Anderson (CC-ed here) discovered that he was hitting this as well
and realized that if he was using the QEMU with these three patches:

169b8fa piix4acpi, xen, hotplug: Fix race with ACPI AML code and hotplug.
309149c piix4acpi, xen: Clarify that the qemu_set_irq calls just do an IRQ
pulse.
82b10d1 piix4acpi, xen, vcpu hotplug: Split the notification from the changes.

the problem would go away. We did not go any deeper to figure out the culprit.

My money is on the AML code modifying the MADT and while it is executing
another ACPI GSI is triggered (the old code would trigger it for every CPU
being hot-plugged) and as the Linux ACPI AML interpreter reads the MADT and
writes
out the newly updated MADT another of the CPUs ends up reading the MADT as well
-
but ends up with the data being bogus as the AML interpreter did not finish
and got garbage.

Either way, the resolution is if you see this - the fix is to update the
qemu to have those patches.

Thanks Chuck for digging in this and finding the clues.


P.S.
I don''t know how SeaBIOS does the CPU hotplug, but it might be worth
looking
at that too at some point.