time accounting problem (powerpc only?)

time accounting problem (powerpc only?)

[Johannes Berg]

Hi,

On my powerbook, with NO_HZ and HIGH_RES_TIMERS, I observed recently
that powernowd would not ever switch between CPU speeds.

Doing some scripting to read /proc/stat every half second and print the
differences, I get output like this on a mostly idle system:

# for reference:
# [user, nice, system, idle, iowait, irq, softirq, steal, guest]

[4, 0, 3, 46, 0, 264, 0, 0, 0]
[5, 0, 4, 41, 0, 266, 0, 0, 0]
[4, 0, 7, 37, 0, 299, 0, 0, 0]

Now starting an empty while (1) loop, I see:

[53, 0, 1, 0, 0, 243, 0, 0, 0]
[53, 0, 2, 0, 0, 224, 0, 0, 0]
[45, 0, 7, 0, 0, 249, 0, 0, 0]

As you can see, the "irq" time is very high so that "user" (mostly my
CPU burning program) only accounts for maybe 15%. This leads to
powernowd thinking that all is fine and no switching is required. Also,
the whole stuff leads to top(1) displaying about 80-90% "hi" (hard irq?
calculated as irq - softirq?) time.

Does anybody have an idea why the irq time is so high? And no, I don't
think it can actually be true, I'm seeing maybe 500 interrupts/second
(most due to USB).

johannes

Re: time accounting problem (powerpc only?)

[Jörg Sommer]

Hallo Johannes,

Johannes Berg <johannes@sipsolutions.net> wrote:
> Doing some scripting to read /proc/stat every half second and print the
> differences, I get output like this on a mostly idle system:
>
> # for reference:
> # [user, nice, system, idle, iowait, irq, softirq, steal, guest]
>
> [4, 0, 3, 46, 0, 264, 0, 0, 0]
>
> As you can see, the "irq" time is very high so that "user" (mostly my
> CPU burning program) only accounts for maybe 15%. This leads to
> powernowd thinking that all is fine and no switching is required. Also,
> the whole stuff leads to top(1) displaying about 80-90% "hi" (hard irq?
> calculated as irq - softirq?) time.

I've the same problem and I see these interrupts in /proc/interrups:

% diff /proc/interrupts <(sleep 2; cat /proc/interrupts)
--- /proc/interrupts    2007-11-23 15:04:06.004846901 +0100
+++ /proc/self/fd/11    2007-11-23 15:04:05.952841422 +0100
@@ -1,15 +1,15 @@
            CPU0       
  21:          5   MPIC 1    Edge      PMac Output
  24:         68   MPIC 1    Level     ide1
- 25:   18063968   MPIC 1    Level     VIA-PMU
+ 25:   18064241   MPIC 1    Level     VIA-PMU
  26:       2426   MPIC 1    Level     keywest i2c
  29:          1   MPIC 1    Level     ohci_hcd:usb2
  30:          1   MPIC 1    Edge      PMac Input
  39:     843910   MPIC 1    Level     ide0
  41:     990592   MPIC 1    Level     eth0
- 42:    1415066   MPIC 1    Level     keywest i2c
- 47:    2075159   MPIC 1    Level     GPIO1 ADB
- 48:    6686659   MPIC 1    Level     radeon@pci:0000:00:10.0
+ 42:    1415084   MPIC 1    Level     keywest i2c
+ 47:    2075193   MPIC 1    Level     GPIO1 ADB
+ 48:    6686778   MPIC 1    Level     radeon@pci:0000:00:10.0
  61:          0   MPIC 1    Edge      Sound Headphone Detection
  63:      94238   MPIC 1    Level     ehci_hcd:usb1, ohci_hcd:usb3, ohci_hcd:usb4
 BAD:         19

I don't know where they come from, but that's the cause of the high IRQ
time.

Bye, Jörg.
-- 
Je planmäßiger ein Mensch vorgeht,
desto stärker mag ihn der Zufall treffen.
		    Erich Krunau ‚Die Physiker‘

Re: time accounting problem (powerpc only?)

[Johannes Berg]

[-- Attachment #1: Type: text/plain, Size: 1533 bytes --]

Hi,

> % diff /proc/interrupts <(sleep 2; cat /proc/interrupts)
> --- /proc/interrupts    2007-11-23 15:04:06.004846901 +0100
> +++ /proc/self/fd/11    2007-11-23 15:04:05.952841422 +0100
> @@ -1,15 +1,15 @@
>             CPU0       
>   21:          5   MPIC 1    Edge      PMac Output
>   24:         68   MPIC 1    Level     ide1
> - 25:   18063968   MPIC 1    Level     VIA-PMU
> + 25:   18064241   MPIC 1    Level     VIA-PMU
>   26:       2426   MPIC 1    Level     keywest i2c
>   29:          1   MPIC 1    Level     ohci_hcd:usb2
>   30:          1   MPIC 1    Edge      PMac Input
>   39:     843910   MPIC 1    Level     ide0
>   41:     990592   MPIC 1    Level     eth0
> - 42:    1415066   MPIC 1    Level     keywest i2c
> - 47:    2075159   MPIC 1    Level     GPIO1 ADB
> - 48:    6686659   MPIC 1    Level     radeon@pci:0000:00:10.0
> + 42:    1415084   MPIC 1    Level     keywest i2c
> + 47:    2075193   MPIC 1    Level     GPIO1 ADB
> + 48:    6686778   MPIC 1    Level     radeon@pci:0000:00:10.0
>   61:          0   MPIC 1    Edge      Sound Headphone Detection
>   63:      94238   MPIC 1    Level     ehci_hcd:usb1, ohci_hcd:usb3, ohci_hcd:usb4
>  BAD:         19
> 
> I don't know where they come from, but that's the cause of the high IRQ
> time.

Are you sure about that? I'm fairly sure that I always had rather high
numbers of interrupt here. And the system isn't sluggish or unresponsive
as you'd expect if the IRQs actually did take 90% of the CPU time!

johannes

[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 828 bytes --]

Re: time accounting problem (powerpc only?)

[Johannes Berg]

[-- Attachment #1: Type: text/plain, Size: 908 bytes --]


On Fri, 2007-11-23 at 21:37 +0100, Johannes Berg wrote:
> Hi,

> > - 25:   18063968   MPIC 1    Level     VIA-PMU
> > + 25:   18064241   MPIC 1    Level     VIA-PMU

> > - 42:    1415066   MPIC 1    Level     keywest i2c
> > - 47:    2075159   MPIC 1    Level     GPIO1 ADB
> > - 48:    6686659   MPIC 1    Level     radeon@pci:0000:00:10.0
> > + 42:    1415084   MPIC 1    Level     keywest i2c
> > + 47:    2075193   MPIC 1    Level     GPIO1 ADB
> > + 48:    6686778   MPIC 1    Level     radeon@pci:0000:00:10.0

> Are you sure about that? I'm fairly sure that I always had rather high
> numbers of interrupt here. And the system isn't sluggish or unresponsive
> as you'd expect if the IRQs actually did take 90% of the CPU time!

Also, I'm pretty sure I see the same on my powermac (haven't tested but
I did see the same symptoms) and it has neither a PMU nor radeon :)

johannes

[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 828 bytes --]

Re: time accounting problem (powerpc only?)

[Jörg Sommer]

Hi,

Johannes Berg <johannes@sipsolutions.net> wrote:
>> % diff /proc/interrupts <(sleep 2; cat /proc/interrupts)
>> --- /proc/interrupts    2007-11-23 15:04:06.004846901 +0100
>> +++ /proc/self/fd/11    2007-11-23 15:04:05.952841422 +0100
>> @@ -1,15 +1,15 @@
>>             CPU0       
>> - 25:   18063968   MPIC 1    Level     VIA-PMU
>> + 25:   18064241   MPIC 1    Level     VIA-PMU
>> - 42:    1415066   MPIC 1    Level     keywest i2c
>> - 47:    2075159   MPIC 1    Level     GPIO1 ADB
>> - 48:    6686659   MPIC 1    Level     radeon@pci:0000:00:10.0
>> + 42:    1415084   MPIC 1    Level     keywest i2c
>> + 47:    2075193   MPIC 1    Level     GPIO1 ADB
>> + 48:    6686778   MPIC 1    Level     radeon@pci:0000:00:10.0
>> 
>> I don't know where they come from, but that's the cause of the high IRQ
>> time.
>
> Are you sure about that?

No, I saw the high hardware interrupt value in top and looked at
/proc/interrupts and concluded that those are the evil source of the
high load.

> I'm fairly sure that I always had rather high numbers of interrupt
> here. And the system isn't sluggish or unresponsive as you'd expect if
> the IRQs actually did take 90% of the CPU time!

Okay, so what might be the source?

Doesn't really nobody else see this values? At least, Elimar
Riesebieter has the same problem. He reported on debian-powerpc.

Bye, Jörg.
-- 
Treffen sich zwei Funktionen.
Sagt die eine: „Verschwinde oder ich differenzier' dich!“
Erwidert die andere: „Ätsch, ich bin exponentiell!“

Re: time accounting problem (powerpc only?)

[Johannes Berg]

[-- Attachment #1: Type: text/plain, Size: 599 bytes --]

Hi,

[can you CC me? I can sometimes only skim the lists]

> No, I saw the high hardware interrupt value in top and looked at
> /proc/interrupts and concluded that those are the evil source of the
> high load.
> 
> > I'm fairly sure that I always had rather high numbers of interrupt
> > here. And the system isn't sluggish or unresponsive as you'd expect if
> > the IRQs actually did take 90% of the CPU time!
> 
> Okay, so what might be the source?

I'd guess NOHZ is the problem because we're letting the CPU not do
anything rather than doing idle ticks or something.

johannes

[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 828 bytes --]

Re: time accounting problem (powerpc only?)

[Johannes Berg]

[-- Attachment #1: Type: text/plain, Size: 207 bytes --]

Contrary to what I claimed later in the thread, my 64-bit powerpc box
(quad-core G5) doesn't suffer from this problem.

Does anybody have any idea? I don't even know how to debug it further.

johannes

[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 828 bytes --]

Re: time accounting problem (powerpc only?)

[Tony Breeds]

On Mon, Nov 26, 2007 at 05:23:13PM +0100, Johannes Berg wrote:
> Contrary to what I claimed later in the thread, my 64-bit powerpc box
> (quad-core G5) doesn't suffer from this problem.
> 
> Does anybody have any idea? I don't even know how to debug it further.

I'll see if I can grab an appropriate machine tomorrow and have a look at
it.  I think it's just an accounting bug, which is probably my fault :)

Yours Tony

  linux.conf.au        http://linux.conf.au/ || http://lca2008.linux.org.au/
  Jan 28 - Feb 02 2008 The Australian Linux Technical Conference!

Re: time accounting problem (powerpc only?)

[Johannes Berg]

[-- Attachment #1: Type: text/plain, Size: 547 bytes --]


On Tue, 2007-11-27 at 16:00 +1100, Tony Breeds wrote:
> On Mon, Nov 26, 2007 at 05:23:13PM +0100, Johannes Berg wrote:
> > Contrary to what I claimed later in the thread, my 64-bit powerpc box
> > (quad-core G5) doesn't suffer from this problem.
> > 
> > Does anybody have any idea? I don't even know how to debug it further.
> 
> I'll see if I can grab an appropriate machine tomorrow and have a look at
> it.  I think it's just an accounting bug, which is probably my fault :)

Thanks. Let me know if you need any info.

johannes

[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 828 bytes --]

Re: time accounting problem (powerpc only?)

[Paul Mackerras]

Johannes Berg writes:

> Contrary to what I claimed later in the thread, my 64-bit powerpc box
> (quad-core G5) doesn't suffer from this problem.
> 
> Does anybody have any idea? I don't even know how to debug it further.

I see it on my G4 powerbook.  However, a compute-bound task runs just
as fast (i.e. completes in the same elapsed time) as on older kernels,
so it does look like it is just an accounting problem.  If the CPU was
really spending more than half its time servicing hardware interrupts,
the task should take more than twice as long to complete.

Paul.

Re: time accounting problem (powerpc only?)

[Johannes Berg]

[-- Attachment #1: Type: text/plain, Size: 727 bytes --]


On Tue, 2007-11-27 at 20:57 +1100, Paul Mackerras wrote:
> Johannes Berg writes:
> 
> > Contrary to what I claimed later in the thread, my 64-bit powerpc box
> > (quad-core G5) doesn't suffer from this problem.
> > 
> > Does anybody have any idea? I don't even know how to debug it further.
> 
> I see it on my G4 powerbook.  However, a compute-bound task runs just
> as fast (i.e. completes in the same elapsed time) as on older kernels,
> so it does look like it is just an accounting problem.  If the CPU was
> really spending more than half its time servicing hardware interrupts,
> the task should take more than twice as long to complete.

Exactly. So where do I look for the accounting bug?

johannes

[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 828 bytes --]

Re: time accounting problem (powerpc only?)

[Johannes Berg]

[-- Attachment #1: Type: text/plain, Size: 200 bytes --]


> On my powerbook, with NO_HZ and HIGH_RES_TIMERS, I observed recently
> that powernowd would not ever switch between CPU speeds.

Also happens without NO_HZ (with HIGH_RES_TIMERS).

johannes

[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 828 bytes --]