RE: [Xen-devel] million cycle interrupt

[Dan Magenheimer <dan.magenheimer@xxxxxxxxxx>]

The IO-APIC-edge interrupt action is timer_interrupt.

The MSI interrupt action is showing up strange
(2010001)... I'll need to look into this more.

> lock contention?

Possible, though the consistent max numbers make it
seem unlikely.

> If it's really caused by SMT, it's more likely to be software
> caused resource contention due to doubled logical processors.

You mentioned PIT earlier... I wonder if PIT can be
read in parallel if read from different cores, but
if read from different threads, it must be serialized?
A million cycles is probably about right for a platform
timer read, true?

> -----Original Message-----
> From: Tian, Kevin [mailto:kevin.tian@xxxxxxxxx]
> Sent: Monday, April 13, 2009 9:05 PM
> To: Dan Magenheimer; Keir Fraser; Xen-Devel (E-mail)
> Subject: RE: [Xen-devel] million cycle interrupt
>
>
> >From: Dan Magenheimer [mailto:dan.magenheimer@xxxxxxxxxx]
> >Sent: 2009年4月14日 10:59
> >
> >Some more interesting data that echos my earlier
> >measurements:
> >
> >Booting with maxcpus=4, the three "large" interrupts
> >are all about 20000 cycles.  Booting with maxcpus=6,
> >the three are at 146896, 183260, and 240959 cycles.
> >
> >So it definitely appears to get worse as maxcpus
> >gets larger.
>
> lock contention?
>
> >
> >I also wonder if it might be related to SMT?
>
> If it's really caused by SMT, it's more likely to be software
> caused resource contention due to doubled logical processors.
> At hardware level although cache is shared, ISRs in Xen are
> normally short and I don't think such high factor could come
> from there...
>
> Thanks,
> Kevin
>
> >
> >> One immediate trick is to print handler address for problematic
> >
> >I'll give that a try, but probably not until tomorrow.
> >
> >> -----Original Message-----
> >> From: Tian, Kevin [mailto:kevin.tian@xxxxxxxxx]
> >> Sent: Monday, April 13, 2009 8:42 PM
> >> To: Dan Magenheimer; Keir Fraser; Xen-Devel (E-mail)
> >> Subject: RE: [Xen-devel] million cycle interrupt
> >>
> >>
> >> >From: Dan Magenheimer [mailto:dan.magenheimer@xxxxxxxxxx]
> >> >Sent: 2009年4月14日 10:34
> >> >
> >> >> handler, why not take one more step to measure every handler
> >> >
> >> >Great idea!  I added a max_cycles field to irq_desc_t
> >> >and check/update it at every interrupt in do_IRQ,
> >> >then print max_cycles in "xm debug-key i",
> >> >including a "max max".
> >> >
> >> >I'm not entirely sure how to interpret the output
> >> >from dump_irqs() but the only two IRQ's with
> >> >type==PCI-MSI have a "large"
> >> >max (450044 cycles and 730972 cycles).  The third is
> >> >Vec240, an IO-APIC-edge interrupt that maxes at 1047500
> >> >cycles.   No other interrupt has a max exceeding 10000.
> >> >
> >> >Here's the relevant output.  How do I map this to
> >> >something meaningful?
> >>
> >> One immediate trick is to print handler address for problematic
> >> vector, and then search its name in your dumpped Xen symbol
> >> file.
> >>
> >> Thanks,
> >> Kevin
> >>
> >> >
> >> >(XEN)    Vec 49 IRQ -1: type=PCI-MSI         status=00000010
> >> >max_cycles=450044 in-flight=0 domain-list=0:254(----),
> >> >
> >> >(XEN)    Vec208 IRQ -1: type=PCI-MSI         status=00000010
> >> >max_cycles=730972 in-flight=0 domain-list=0:255(----),
> >>
> >> Above two look like owned by dom0.
> >>
> >> >
> >> >(XEN)    Vec240 IRQ  0: type=IO-APIC-edge    status=00000000
> >> >max_cycles=1047500 mapped, unbound
> >>
> >>
> >> looks like PIT, but not quite sure.
> >>
> >> >
> >> >(XEN) max_max_cycles = 1047500
> >> >
> >> >
> >> >
> >> >
> >> >> -----Original Message-----
> >> >> From: Tian, Kevin [mailto:kevin.tian@xxxxxxxxx]
> >> >> Sent: Monday, April 13, 2009 5:19 PM
> >> >> To: Dan Magenheimer; Keir Fraser; Xen-Devel (E-mail)
> >> >> Subject: RE: [Xen-devel] million cycle interrupt
> >> >>
> >> >>
> >> >> >From: Dan Magenheimer
> >> >> >Sent: 2009年4月14日 5:15
> >> >> >
> >> >> >> You can instrument irq_enter() and irq_exit() to read TSC
> >> >> >
> >> >> >Rather than do this generically and ensure I get all the macros
> >> >> >correct (e.g. per_cpu, nesting) I manually instrumented three
> >> >> >likely suspect irq_enter/exit pairs, two in do_IRQ() and one
> >> >> >in smp_call_function().  ALL of them show an issue with max
> >> >> >readings in the 300K-1M range... with smp_call_function showing
> >> >> >the lowest max and the second in do_IRQ (the non-guest one)
> >> >> >showing readings over 1M (and the guest one at about 800K).
> >> >>
> >> >> Since you already reach this step around calling actual action's
> >> >> handler, why not take one more step to measure every handler
> >> >> (serial, apic, vtd, ...)? You can first simply print
> >which handlers
> >> >> are registered or invoked on your platform. If only one handler
> >> >> is experienced with abnormal high latency, it's possibly one
> >> >> specific point. Or else you can suspect on some common code
> >> >> shared by all handlers, or ... as Keir said, it could
> be SMM. :-)
> >> >>
> >> >> Thanks,
> >> >> Kevin
> >> >>
> >> >> >
> >> >> >Interestingly, I get no readings at all over 60K when I
> >> >> >recompile with max_phys_cpus=4 (and with nosmp) on my
> >> >> >quad-core-by-two-thread machine.  This is versus several
> >> >> >readings over 60K nearly every second when max_phys_cpus=8.
> >> >> >
> >> >> >> Otherwise who knows, it could even be system management mode
> >> >> >
> >> >> >I suppose measuring irq_enter/exist pairs still don't rule
> >> >> >this out.  But the "large" interrupts don't seem to happen
> >> >> >(at least not nearly as frequently) with fewer physical
> >> >> >processors enabled, so sys mgmt mode seems unlikely.
> >> >> >
> >> >> >Anyway, still a probable problem, still mostly a mystery
> >> >> >as to what is actually happening.  And, repeat, this has
> >> >> >nothing to do with tmem... I'm just observing it using
> >> >> >tmem as a convenient measurement tool.
> >> >> >
> >> >> >> -----Original Message-----
> >> >> >> From: Keir Fraser [mailto:keir.fraser@xxxxxxxxxxxxx]
> >> >> >> Sent: Monday, April 13, 2009 2:24 AM
> >> >> >> To: Dan Magenheimer; Xen-Devel (E-mail)
> >> >> >> Subject: Re: [Xen-devel] million cycle interrupt
> >> >> >>
> >> >> >>
> >> >> >> On 12/04/2009 21:16, "Dan Magenheimer"
> >> >> >> <dan.magenheimer@xxxxxxxxxx> wrote:
> >> >> >>
> >> >> >> > Is a million cycles in an interrupt handler bad?  Any
> >> idea what
> >> >> >> > might be consuming this?  The evidence might imply
> more cpus
> >> >> >> > means longer interrupt, which bodes poorly for larger
> >> machines.
> >> >> >> > I tried disabling the timer rendezvous code (not positive I
> >> >> >> > was successful), but still got large measurements, and
> >> >> >> > eventually the machine froze up (but not before I observed
> >> >> >> > the stime skew climbing quickly to the millisecond-plus
> >> >> >> > range).
> >> >> >>
> >> >> >> You can instrument irq_enter() and irq_exit() to read TSC and
> >> >> >> find out the
> >> >> >> distribution of irq handling times for interruptions that Xen
> >> >> >> knows about.
> >> >> >> Otherwise who knows, it could even be system management
> >> >> mode on that
> >> >> >> particular box.
> >> >> >>
> >> >> >>  -- Keir
> >> >> >>
> >> >> >>
> >> >> >>
> >> >> >
> >> >> >_______________________________________________
> >> >> >Xen-devel mailing list
> >> >> >Xen-devel@xxxxxxxxxxxxxxxxxxx
> >> >> >http://lists.xensource.com/xen-devel
> >> >> >
> >> >
> >

_______________________________________________
Xen-devel mailing list
Xen-devel@xxxxxxxxxxxxxxxxxxx
http://lists.xensource.com/xen-devel