Reading EeePC900 battery info causes stalls (was Re: How how latent should non-preemptive scheduling be?)

Reading EeePC900 battery info causes stalls (was Re: How how latent should non-preemptive scheduling be?)

[Sitsofe Wheeler]

Peter Zijlstra wrote:
> Its actually function tracer output I'm interested in.. that shows what
> all its doing to make it take 120+ms.

I switched the tracer to ftrace and waited for the problem to occur.
When stall did happen it was far worse than usual with the tracing on
(instead of looping sound of < 0.5 second it looped it for about 2-3
seconds). Looking atthe trace it was filled with hald events. Killing 
off all of hald made the 30 second stalls go away.

A quick strace showed that what hal was doing every 30 seconds was
reading various battery stats from /sys. Doing a simple
cat /sys/class/power_supply/BAT0/manufacturer
is enough to provoke a stall. The stalls only occur if you are on 
battery or are on AC and the battery is not reporting that it is 100% 
charged (but in the latter case the stalls are less pronounced).

I can reliably hear the stalls at runlevel 1 by running
speaker-test -b75000
and
watch --interval=1 cat /proc/acpi/battery/BAT0/info
within separate terminals within screen.

A 5 second ftrace of the stall being provoked is provided on 
<http://sucs.org/~sits/test/eeepc-ftrace.txt.gz> (it's 6Mbytes 
uncompressed).

Putting the alsa buffer size up to 100000 allows you to still hear
stalls but far less frequently. Putting to 150000 will stop you from
hearing stalls. Even though xruns is set to 2 alsa not report any buffer
underruns to syslog.

Another way of seeing the stalls is to run glxgears and every second the
gears' spinning will jump (even on an unloaded system).

(I guess this works as the stalls are over 100ms)

The xandros provided 2.6.21.4 kernel does not exhibit this problem at 
all but my hand compiled 2.6.24something and ubuntu 2.6.24 kernels do.

For some reason latencytop did not really finger ACPI as a cause of
stalls (although some acpi stuff does show up but never in the top
spot). Is this simply a part of the kernel that latencytop does not trace?

> I thought we had a wakeup latency tracer exacty like we have preempt and
> irq off latency tracers, Steve, where'd that go?

I rebuilt my kernel after a make clean and wakeup was still not there. 
It might be a good idea to modify the kernel documentation currently
provided with 2.6.27 if it has gone away for now (or document the extra
switches needed to turn it on if that's why it didn't show up for me)...

--
Sitsofe | http://sucs.org/~sits/

Re: Reading EeePC900 battery info causes stalls (was Re: How how latent should non-preemptive scheduling be?)

[Alexey Starikovskiy]

Hi Sitsofe,

eeePC is known to be affected by EC GPE storm bug, and there is a patch for 
2.6.27 to workaround the problem. please look at
http://bugzilla.kernel.org/show_bug.cgi?id=11549
for latest patch and bugs 10724/9998 for problem discussion.

Thanks,
Alex.

Sitsofe Wheeler wrote:
> Peter Zijlstra wrote:
>> Its actually function tracer output I'm interested in.. that shows what
>> all its doing to make it take 120+ms.
> 
> I switched the tracer to ftrace and waited for the problem to occur.
> When stall did happen it was far worse than usual with the tracing on
> (instead of looping sound of < 0.5 second it looped it for about 2-3
> seconds). Looking atthe trace it was filled with hald events. Killing 
> off all of hald made the 30 second stalls go away.
> 
> A quick strace showed that what hal was doing every 30 seconds was
> reading various battery stats from /sys. Doing a simple
> cat /sys/class/power_supply/BAT0/manufacturer
> is enough to provoke a stall. The stalls only occur if you are on 
> battery or are on AC and the battery is not reporting that it is 100% 
> charged (but in the latter case the stalls are less pronounced).
> 
> I can reliably hear the stalls at runlevel 1 by running
> speaker-test -b75000
> and
> watch --interval=1 cat /proc/acpi/battery/BAT0/info
> within separate terminals within screen.
> 
> A 5 second ftrace of the stall being provoked is provided on 
> <http://sucs.org/~sits/test/eeepc-ftrace.txt.gz> (it's 6Mbytes 
> uncompressed).
> 
> Putting the alsa buffer size up to 100000 allows you to still hear
> stalls but far less frequently. Putting to 150000 will stop you from
> hearing stalls. Even though xruns is set to 2 alsa not report any buffer
> underruns to syslog.
> 
> Another way of seeing the stalls is to run glxgears and every second the
> gears' spinning will jump (even on an unloaded system).
> 
> (I guess this works as the stalls are over 100ms)
> 
> The xandros provided 2.6.21.4 kernel does not exhibit this problem at 
> all but my hand compiled 2.6.24something and ubuntu 2.6.24 kernels do.
> 
> For some reason latencytop did not really finger ACPI as a cause of
> stalls (although some acpi stuff does show up but never in the top
> spot). Is this simply a part of the kernel that latencytop does not trace?
> 
>> I thought we had a wakeup latency tracer exacty like we have preempt and
>> irq off latency tracers, Steve, where'd that go?
> 
> I rebuilt my kernel after a make clean and wakeup was still not there. 
> It might be a good idea to modify the kernel documentation currently
> provided with 2.6.27 if it has gone away for now (or document the extra
> switches needed to turn it on if that's why it didn't show up for me)...
> 
> -- 
> Sitsofe | http://sucs.org/~sits/

Re: Reading EeePC900 battery info causes stalls (was Re: How how latent should non-preemptive scheduling be?)

[Sitsofe Wheeler]

Hi Alexey,

Alexey Starikovskiy wrote:
> eeePC is known to be affected by EC GPE storm bug, and there is a patch 
> for 2.6.27 to workaround the problem. please look at
> http://bugzilla.kernel.org/show_bug.cgi?id=11549
> for latest patch and bugs 10724/9998 for problem discussion.

Even with http://bugzilla.kernel.org/attachment.cgi?id=17845&action=view 
(fast transaction) applied the stalls are still present (and seemingly 
just as bad as before).

Re: Reading EeePC900 battery info causes stalls

[Sitsofe Wheeler]

Sitsofe Wheeler wrote:
> Hi Alexey,
> 
> Alexey Starikovskiy wrote:
>> eeePC is known to be affected by EC GPE storm bug, and there is a 
>> patch for 2.6.27 to workaround the problem. please look at
>> http://bugzilla.kernel.org/show_bug.cgi?id=11549
>> for latest patch and bugs 10724/9998 for problem discussion.
> 
> Even with http://bugzilla.kernel.org/attachment.cgi?id=17845&action=view 
> (fast transaction) applied the stalls are still present (and seemingly 
> just as bad as before).

I should note that the patch DOES fix the slow volume hotkey repeat rate 
that I was seeing.

Re: Reading EeePC900 battery info causes stalls

[Alexey Starikovskiy]

Sitsofe Wheeler wrote:
> Sitsofe Wheeler wrote:
>> Hi Alexey,
>>
>> Alexey Starikovskiy wrote:
>>> eeePC is known to be affected by EC GPE storm bug, and there is a 
>>> patch for 2.6.27 to workaround the problem. please look at
>>> http://bugzilla.kernel.org/show_bug.cgi?id=11549
>>> for latest patch and bugs 10724/9998 for problem discussion.
>>
>> Even with 
>> http://bugzilla.kernel.org/attachment.cgi?id=17845&action=view (fast 
>> transaction) applied the stalls are still present (and seemingly just 
>> as bad as before).
> 
> I should note that the patch DOES fix the slow volume hotkey repeat rate 
> that I was seeing.
Could you cat /proc/interrupts ?

Re: Reading EeePC900 battery info causes stalls

[Sitsofe Wheeler]

Alexey Starikovskiy wrote:
> Could you cat /proc/interrupts ?

            CPU0
   0:     106942   IO-APIC-edge      timer
   1:        426   IO-APIC-edge      i8042
   8:         41   IO-APIC-edge      rtc0
   9:      27346   IO-APIC-fasteoi   acpi
  12:       6840   IO-APIC-edge      i8042
  14:          0   IO-APIC-edge      ata_piix
  15:        203   IO-APIC-edge      ata_piix
  16:      92357   IO-APIC-fasteoi   uhci_hcd:usb5, HDA Intel, 
i915@pci:0000:00:02.0
  18:      38195   IO-APIC-fasteoi   ath, uhci_hcd:usb4
  19:          0   IO-APIC-fasteoi   uhci_hcd:usb3
  23:      25150   IO-APIC-fasteoi   ehci_hcd:usb1, uhci_hcd:usb2
NMI:          0   Non-maskable interrupts
LOC:     142112   Local timer interrupts
TRM:          0   Thermal event interrupts
SPU:          0   Spurious interrupts
ERR:          0
MIS:          0

Re: Reading EeePC900 battery info causes stalls

[Sitsofe Wheeler]

Sitsofe Wheeler wrote:
> Alexey Starikovskiy wrote:
>> Could you cat /proc/interrupts ?
> 
>            CPU0
>   0:     106942   IO-APIC-edge      timer
>   1:        426   IO-APIC-edge      i8042
>   8:         41   IO-APIC-edge      rtc0
>   9:      27346   IO-APIC-fasteoi   acpi
>  12:       6840   IO-APIC-edge      i8042
>  14:          0   IO-APIC-edge      ata_piix
>  15:        203   IO-APIC-edge      ata_piix
>  16:      92357   IO-APIC-fasteoi   uhci_hcd:usb5, HDA Intel, 
> i915@pci:0000:00:02.0
>  18:      38195   IO-APIC-fasteoi   ath, uhci_hcd:usb4
>  19:          0   IO-APIC-fasteoi   uhci_hcd:usb3
>  23:      25150   IO-APIC-fasteoi   ehci_hcd:usb1, uhci_hcd:usb2
> NMI:          0   Non-maskable interrupts
> LOC:     142112   Local timer interrupts
> TRM:          0   Thermal event interrupts
> SPU:          0   Spurious interrupts
> ERR:          0
> MIS:          0

and here are the interrupts from the (seemingly working) EeePC's Xandros 
2.6.21.4 install:

            CPU0
   0:       6486    XT-PIC-XT        timer
   1:        107    XT-PIC-XT        i8042
   2:          0    XT-PIC-XT        cascade
   3:          0    XT-PIC-XT        uhci_hcd:usb2
   5:        735    XT-PIC-XT        uhci_hcd:usb1, ehci_hcd:usb5
   9:        219    XT-PIC-XT        acpi
  10:       8171    XT-PIC-XT        uhci_hcd:usb3, pciehp, wifi0
  11:        107    XT-PIC-XT        HDA Intel, i915@pci:0000:00:02.0, 
uhci_hcd:usb4, pciehp
  12:        236    XT-PIC-XT        i8042
  14:          0    XT-PIC-XT        libata
  15:       3475    XT-PIC-XT        libata
NMI:          0
ERR:          0

and here is the kernel cmdline that the Xandros install uses:
quiet rw vga=785 irqpoll root=/dev/sda1

I've got a feeling I know what direction this is going in...

-- 
Sitsofe | http://sucs.org/~sits/

Re: Reading EeePC900 battery info causes stalls

[Alexey Starikovskiy]

Sitsofe Wheeler wrote:
> Sitsofe Wheeler wrote:
>> Alexey Starikovskiy wrote:
>>> Could you cat /proc/interrupts ?
>>
>>            CPU0
>>   0:     106942   IO-APIC-edge      timer
>>   1:        426   IO-APIC-edge      i8042
>>   8:         41   IO-APIC-edge      rtc0
>>   9:      27346   IO-APIC-fasteoi   acpi
>>  12:       6840   IO-APIC-edge      i8042
>>  14:          0   IO-APIC-edge      ata_piix
>>  15:        203   IO-APIC-edge      ata_piix
>>  16:      92357   IO-APIC-fasteoi   uhci_hcd:usb5, HDA Intel, 
>> i915@pci:0000:00:02.0
>>  18:      38195   IO-APIC-fasteoi   ath, uhci_hcd:usb4
>>  19:          0   IO-APIC-fasteoi   uhci_hcd:usb3
>>  23:      25150   IO-APIC-fasteoi   ehci_hcd:usb1, uhci_hcd:usb2
>> NMI:          0   Non-maskable interrupts
>> LOC:     142112   Local timer interrupts
>> TRM:          0   Thermal event interrupts
>> SPU:          0   Spurious interrupts
>> ERR:          0
>> MIS:          0
> 
> and here are the interrupts from the (seemingly working) EeePC's Xandros 
> 2.6.21.4 install:
> 
>            CPU0
>   0:       6486    XT-PIC-XT        timer
>   1:        107    XT-PIC-XT        i8042
>   2:          0    XT-PIC-XT        cascade
>   3:          0    XT-PIC-XT        uhci_hcd:usb2
>   5:        735    XT-PIC-XT        uhci_hcd:usb1, ehci_hcd:usb5
>   9:        219    XT-PIC-XT        acpi
>  10:       8171    XT-PIC-XT        uhci_hcd:usb3, pciehp, wifi0
>  11:        107    XT-PIC-XT        HDA Intel, i915@pci:0000:00:02.0, 
> uhci_hcd:usb4, pciehp
>  12:        236    XT-PIC-XT        i8042
>  14:          0    XT-PIC-XT        libata
>  15:       3475    XT-PIC-XT        libata
> NMI:          0
> ERR:          0
> 
> and here is the kernel cmdline that the Xandros install uses:
> quiet rw vga=785 irqpoll root=/dev/sda1
> 
> I've got a feeling I know what direction this is going in...
> 
Right, could you please check if irqpoll is the key to success?

Thanks,
Alex.

Re: Reading EeePC900 battery info causes stalls

[Sitsofe Wheeler]

Alexey Starikovskiy wrote:
> Sitsofe Wheeler wrote:
>> and here is the kernel cmdline that the Xandros install uses:
>> quiet rw vga=785 irqpoll root=/dev/sda1
>>
>> I've got a feeling I know what direction this is going in...
>>
> Right, could you please check if irqpoll is the key to success?

So I tried just irqpoll (along with nolapic irqpool which changed the 
output in /proc/interrupts) but it made no difference to the stalling. 
I'm baffled.

-- 
Sitsofe | http://sucs.org/~sits/

Re: Reading EeePC900 battery info causes stalls

[Alexey Starikovskiy]

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

Sitsofe Wheeler wrote:
> Alexey Starikovskiy wrote:
>> Could you cat /proc/interrupts ?
> 
>            CPU0
>   0:     106942   IO-APIC-edge      timer
>   1:        426   IO-APIC-edge      i8042
>   8:         41   IO-APIC-edge      rtc0
>   9:      27346   IO-APIC-fasteoi   acpi
>  12:       6840   IO-APIC-edge      i8042
>  14:          0   IO-APIC-edge      ata_piix
>  15:        203   IO-APIC-edge      ata_piix
>  16:      92357   IO-APIC-fasteoi   uhci_hcd:usb5, HDA Intel, 
> i915@pci:0000:00:02.0
>  18:      38195   IO-APIC-fasteoi   ath, uhci_hcd:usb4
>  19:          0   IO-APIC-fasteoi   uhci_hcd:usb3
>  23:      25150   IO-APIC-fasteoi   ehci_hcd:usb1, uhci_hcd:usb2
> NMI:          0   Non-maskable interrupts
> LOC:     142112   Local timer interrupts
> TRM:          0   Thermal event interrupts
> SPU:          0   Spurious interrupts
> ERR:          0
> MIS:          0
Could you please try following patch on top?

[-- Attachment #2: more_storm.patch --]
[-- Type: text/x-diff, Size: 1582 bytes --]

ACPI: EC: disable GPE during QUERY handling too.

From: Alexey Starikovskiy <astarikovskiy@suse.de>


---

 drivers/acpi/ec.c |   14 +++++++++++---
 1 files changed, 11 insertions(+), 3 deletions(-)


diff --git a/drivers/acpi/ec.c b/drivers/acpi/ec.c
index 8d6b7e9..e027077 100644
--- a/drivers/acpi/ec.c
+++ b/drivers/acpi/ec.c
@@ -226,9 +226,16 @@ static void acpi_ec_gpe_query(void *ec_cxt);
 static int ec_check_sci(struct acpi_ec *ec, u8 state)
 {
 	if (state & ACPI_EC_FLAG_SCI) {
-		if (!test_and_set_bit(EC_FLAGS_QUERY_PENDING, &ec->flags))
+		if (!test_and_set_bit(EC_FLAGS_QUERY_PENDING, &ec->flags)) {
+			/* disable GPE until next transaction */
+			if (in_interrupt() &&
+			    test_bit(EC_FLAGS_GPE_STORM, &ec->flags)) {
+				clear_bit(EC_FLAGS_GPE_MODE, &ec->flags);
+				acpi_disable_gpe(NULL, ec->gpe, ACPI_ISR);
+			}
 			return acpi_os_execute(OSL_EC_BURST_HANDLER,
 				acpi_ec_gpe_query, ec);
+		}
 	}
 	return 0;
 }
@@ -281,8 +288,9 @@ static int acpi_ec_transaction_unlocked(struct acpi_ec *ec, u8 command,
 	if (test_bit(EC_FLAGS_GPE_STORM, &ec->flags)) {
 		/* check if we received SCI during transaction */
 		ec_check_sci(ec, acpi_ec_read_status(ec));
-		/* it is safe to enable GPE outside of transaction */
-		acpi_enable_gpe(NULL, ec->gpe, ACPI_NOT_ISR);
+		/* we expect query, enable GPE back */
+		if (!test_bit(EC_FLAGS_QUERY_PENDING, &ec->flags))
+			acpi_enable_gpe(NULL, ec->gpe, ACPI_NOT_ISR);
 	} else if (test_bit(EC_FLAGS_GPE_MODE, &ec->flags) &&
 		   ec->irq_count > ACPI_EC_STORM_THRESHOLD) {
 		pr_debug(PREFIX "GPE storm detected\n");

Re: Reading EeePC900 battery info causes stalls

[Sitsofe Wheeler]

Alexey Starikovskiy wrote:
> Sitsofe Wheeler wrote:
>> Alexey Starikovskiy wrote:
>>> Could you cat /proc/interrupts ?
>>
>>            CPU0
>>   0:     106942   IO-APIC-edge      timer
>>   1:        426   IO-APIC-edge      i8042
>>   8:         41   IO-APIC-edge      rtc0
>>   9:      27346   IO-APIC-fasteoi   acpi
>>  12:       6840   IO-APIC-edge      i8042
>>  14:          0   IO-APIC-edge      ata_piix
>>  15:        203   IO-APIC-edge      ata_piix
>>  16:      92357   IO-APIC-fasteoi   uhci_hcd:usb5, HDA Intel, 
>> i915@pci:0000:00:02.0
>>  18:      38195   IO-APIC-fasteoi   ath, uhci_hcd:usb4
>>  19:          0   IO-APIC-fasteoi   uhci_hcd:usb3
>>  23:      25150   IO-APIC-fasteoi   ehci_hcd:usb1, uhci_hcd:usb2
>> NMI:          0   Non-maskable interrupts
>> LOC:     142112   Local timer interrupts
>> TRM:          0   Thermal event interrupts
>> SPU:          0   Spurious interrupts
>> ERR:          0
>> MIS:          0
> Could you please try following patch on top?

Unfortunately it still stalls (hotkeys still seem to be working 
correctly though).

-- 
Sitsofe | http://sucs.org/~sits/

Re: Reading EeePC900 battery info causes stalls (was Re: How how latent should non-preemptive scheduling be?)

[Steven Rostedt]

On Sat, 20 Sep 2008, Sitsofe Wheeler wrote:
> 
> > I thought we had a wakeup latency tracer exacty like we have preempt and
> > irq off latency tracers, Steve, where'd that go?
> 
> I rebuilt my kernel after a make clean and wakeup was still not there. It
> might be a good idea to modify the kernel documentation currently
> provided with 2.6.27 if it has gone away for now (or document the extra
> switches needed to turn it on if that's why it didn't show up for me)...

The wake up tracing is CONFIG_SCHED_TRACER. If you do not see 
"wakeup" as one of the available tracers in available_tracers, then check
your dmesg and see if you have CONFIG_FTRACE_STARTUP_TEST enabled. There 
was a known bug that would cause the wakeup tracing to fail the test. When 
a trace fails the startup test, it is disabled.

-- Steve

Re: Reading EeePC900 battery info causes stalls (was Re: How how latent should non-preemptive scheduling be?)

[Sitsofe Wheeler]

Steven Rostedt wrote:
> The wake up tracing is CONFIG_SCHED_TRACER. If you do not see 
> "wakeup" as one of the available tracers in available_tracers, then check
> your dmesg and see if you have CONFIG_FTRACE_STARTUP_TEST enabled. There 
> was a known bug that would cause the wakeup tracing to fail the test. When 
> a trace fails the startup test, it is disabled.

This is exactly the case (dmesg reports the ftrace wakeup startup test 
failed). That's what I get for not reading my dmesg more carefully...

-- 
Sitsofe | http://sucs.org/~sits/

Re: Reading EeePC900 battery info causes stalls (was Re: How how latent should non-preemptive scheduling be?)

[Steven Rostedt]

On Sat, 20 Sep 2008, Sitsofe Wheeler wrote:

> Steven Rostedt wrote:
> > The wake up tracing is CONFIG_SCHED_TRACER. If you do not see "wakeup" as
> > one of the available tracers in available_tracers, then check
> > your dmesg and see if you have CONFIG_FTRACE_STARTUP_TEST enabled. There was
> > a known bug that would cause the wakeup tracing to fail the test. When a
> > trace fails the startup test, it is disabled.
> 
> This is exactly the case (dmesg reports the ftrace wakeup startup test
> failed). That's what I get for not reading my dmesg more carefully...

OK, that is probably the known bug you are hitting. Simply disable the 
CONFIG_FTRACE_STARTUP_TEST and you should have the wakeup tracer. The bug 
is with the test, not the tracer, so it should not hurt you.

-- Steve

Re: Reading EeePC900 battery info causes stalls

[Sitsofe Wheeler]

Steven Rostedt wrote:
> OK, that is probably the known bug you are hitting. Simply disable the 
> CONFIG_FTRACE_STARTUP_TEST and you should have the wakeup tracer. The bug 
> is with the test, not the tracer, so it should not hurt you.

Thanks - this made the wakeup tracer appear a you said. I have put two 
wakeup traces up:

http://sucs.org/~sits/test/eeepc-debug/20080920/latency_trace.txt.gz
http://sucs.org/~sits/test/eeepc-debug/20080920/trace.txt.gz
(each file is around 6Mbytes uncompressed)

Here's a small extract of latency_trace.txt:

> # tracer: wakeup
> #
> wakeup latency trace v1.1.5 on 2.6.27-rc6skw-dirty
> --------------------------------------------------------------------
>  latency: 3232905 us, #65620/6180619, CPU#0 | (M:desktop VP:0, KP:0, SP:0 HP:0)
>     -----------------
>     | task: speaker-test-5074 (uid:1000 nice:0 policy:1 rt_prio:25)
>     -----------------
> 
> #                _------=> CPU#            
> #               / _-----=> irqs-off        
> #              | / _----=> need-resched    
> #              || / _---=> hardirq/softirq 
> #              ||| / _--=> preempt-depth   
> #              |||| /                      
> #              |||||     delay             
> #  cmd     pid ||||| time  |   caller      
> #     \   /    |||||   \   |   /           
>      cat-6743  0.N.. 3198412us : acpi_ut_update_ref_count (acpi_ut_update_object_reference)
>      cat-6743  0.N.. 3198413us : acpi_ut_pop_generic_state (acpi_ut_update_object_reference)
>      cat-6743  0.N.. 3198413us : acpi_ut_delete_generic_state (acpi_ut_update_object_reference)
>      cat-6743  0.N.. 3198414us : acpi_os_release_object (acpi_ut_delete_generic_state)
>      cat-6743  0.N.. 3198414us : kmem_cache_free (acpi_os_release_object)
[...]
>      cat-6743  0.N.. 3232893us : acpi_ut_create_update_state (acpi_ut_create_update_state_and_push)
>      cat-6743  0.N.. 3232893us : acpi_ut_create_generic_state (acpi_ut_create_update_state)
>      cat-6743  0.N.. 3232894us : kmem_cache_alloc (acpi_ut_create_generic_state)
>      cat-6743  0dN.. 3232895us : __slab_alloc (kmem_cache_alloc)
>      cat-6743  0dN.. 3232895us : deactivate_slab (__slab_alloc)
>      cat-6743  0.N.. 3232896us+: __alloc_pages_internal (__slab_alloc)
>      cat-6743  0d... 3232904us+: marker_probe_cb (schedule)
>      cat-6743  0d... 3232905us!: schedule (__cond_resched)
>      cat-6743  0.N.. 3198412us : acpi_ut_push_generic_state (acpi_ut_create_update_state_and_push)

Is it intentional that the last event has a time earlier closer to that 
of the first event?

-- 
Sitsofe | http://sucs.org/~sits/

Re: Reading EeePC900 battery info causes stalls

[Steven Rostedt]

On Sat, 20 Sep 2008, Sitsofe Wheeler wrote:

> Steven Rostedt wrote:
> > OK, that is probably the known bug you are hitting. Simply disable the
> > CONFIG_FTRACE_STARTUP_TEST and you should have the wakeup tracer. The bug is
> > with the test, not the tracer, so it should not hurt you.
> 
> Thanks - this made the wakeup tracer appear a you said. I have put two wakeup
> traces up:
> 
> http://sucs.org/~sits/test/eeepc-debug/20080920/latency_trace.txt.gz
> http://sucs.org/~sits/test/eeepc-debug/20080920/trace.txt.gz
> (each file is around 6Mbytes uncompressed)
> 
> Here's a small extract of latency_trace.txt:
> 
> > # tracer: wakeup
> > #
> > wakeup latency trace v1.1.5 on 2.6.27-rc6skw-dirty
> > --------------------------------------------------------------------
> >  latency: 3232905 us, #65620/6180619, CPU#0 | (M:desktop VP:0, KP:0, SP:0

Peter, these times are crazy, mainly due to the cpu_clock. He probably 
wants to use the sched_clock. Below is a patch to use it instead.

Sitsofe, I notice that the trace states "desktop". This means that you
are running with CONFIG_PREEMPT_VOLUNTARY. You want 
CONFIG_PREEMPT.

[...]
> 
> Is it intentional that the last event has a time earlier closer to that of the
> first event?
> 

Change the config, and see what you get with this patch:

Note this is not compiled tested:

---
 kernel/trace/trace.c |    2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

Index: linus.git/kernel/trace/trace.c
===================================================================
--- linus.git.orig/kernel/trace/trace.c	2008-09-20 17:49:00.000000000 -0400
+++ linus.git/kernel/trace/trace.c	2008-09-20 17:49:35.000000000 -0400
@@ -60,7 +60,7 @@ ns2usecs(cycle_t nsec)
 
 cycle_t ftrace_now(int cpu)
 {
-	return cpu_clock(cpu);
+	return sched_clock();
 }
 
 /*


-- Steve

Re: Reading EeePC900 battery info causes stalls

[Sitsofe Wheeler]

Steven Rostedt wrote:
> On Sat, 20 Sep 2008, Sitsofe Wheeler wrote:
> 
>> Thanks - this made the wakeup tracer appear a you said. I have put two wakeup
>> traces up:
>>
>> http://sucs.org/~sits/test/eeepc-debug/20080920/latency_trace.txt.gz
>> http://sucs.org/~sits/test/eeepc-debug/20080920/trace.txt.gz
>> (each file is around 6Mbytes uncompressed)
>>
>> Here's a small extract of latency_trace.txt:
>>
>>> # tracer: wakeup
>>> #
>>> wakeup latency trace v1.1.5 on 2.6.27-rc6skw-dirty
>>> --------------------------------------------------------------------
>>>  latency: 3232905 us, #65620/6180619, CPU#0 | (M:desktop VP:0, KP:0, SP:0
> 
> Peter, these times are crazy, mainly due to the cpu_clock. He probably 
> wants to use the sched_clock. Below is a patch to use it instead.
> 
> Sitsofe, I notice that the trace states "desktop". This means that you
> are running with CONFIG_PREEMPT_VOLUNTARY. You want 
> CONFIG_PREEMPT.

Dagnabit I keep confusing people. This was actually intentional because 
I wanted to know whether the latency I was seeing should have been 
present in a non-preempt (but voluntary) kernel. You can see the subject 
at that start of this thread: http://tinyurl.com/4akxa5 (How how latent 
should non-preemptive scheduling be?). I'm not running a sound studio 
where I need the lowest possible latency at all costs. Further my 
current understanding is that the desktop distros don't tend to ship 
"regular desktop kernels" with preemption (I know Ubuntu 8.04 and Fedora 
9 didn't).

Basically I have the following queries: Do you have to have preemption 
on if you are listening to music (without noticeable skips) and playing 
the odd game (without noticeable pauses) on a desktop? What's the 
allowed highest latency going to be over a few minutes in such kernels? 
Is it simply the case that if it's a non-preemptive kernel latency no 
longer matters?

Just for the record I just tested a preempt kernel I had lying around 
and the speakter-test -b75000 while looking at battery did not stall. 
However latencytop still reported a "waiting for cpu" value of 75ms.

> [...]
>> Is it intentional that the last event has a time earlier closer to that of the
>> first event?
>>
> 
> Change the config, and see what you get with this patch:

I'll see if I can test the patch tomorrow. Does the config change also 
have to be made or the timestamps to be "narrower"?

-- 
Sitsofe | http://sucs.org/~sits/

Re: Reading EeePC900 battery info causes stalls

[Ingo Molnar]

* Sitsofe Wheeler <sitsofe@yahoo.com> wrote:

> Dagnabit I keep confusing people. This was actually intentional 
> because I wanted to know whether the latency I was seeing should have 
> been present in a non-preempt (but voluntary) kernel. You can see the 
> subject at that start of this thread: http://tinyurl.com/4akxa5 (How 
> how latent should non-preemptive scheduling be?). I'm not running a 
> sound studio where I need the lowest possible latency at all costs. 
> Further my current understanding is that the desktop distros don't 
> tend to ship "regular desktop kernels" with preemption (I know Ubuntu 
> 8.04 and Fedora 9 didn't).
>
> Basically I have the following queries: Do you have to have preemption 
> on if you are listening to music (without noticeable skips) and 
> playing the odd game (without noticeable pauses) on a desktop? What's 
> the allowed highest latency going to be over a few minutes in such 
> kernels?  Is it simply the case that if it's a non-preemptive kernel 
> latency no longer matters?

milliseconds of stalls is definitely excessive under a non-preempt 
kernel - and you have up to 500 msecs of stalls, right?

The simplest way you can fix such latencies is to look at the function 
trace, figure out which loop in the kernel takes so long to execute, and 
add a cond_resched() call to it. [there are other situations where a 
more complicated fix is needed, but this seems like a simpler scenario.]

	Ingo

Re: Reading EeePC900 battery info causes stalls

[Sitsofe Wheeler]

Steven Rostedt wrote:
> On Sat, 20 Sep 2008, Sitsofe Wheeler wrote:
> 
>> Steven Rostedt wrote:
>>> OK, that is probably the known bug you are hitting. Simply disable the
>>> CONFIG_FTRACE_STARTUP_TEST and you should have the wakeup tracer. The bug is
>>> with the test, not the tracer, so it should not hurt you.
>> Thanks - this made the wakeup tracer appear a you said. I have put two wakeup
>> traces up:
>>
>> http://sucs.org/~sits/test/eeepc-debug/20080920/latency_trace.txt.gz
>> http://sucs.org/~sits/test/eeepc-debug/20080920/trace.txt.gz
>> (each file is around 6Mbytes uncompressed)
>>
>> Here's a small extract of latency_trace.txt:
>>
>>> # tracer: wakeup
>>> #
>>> wakeup latency trace v1.1.5 on 2.6.27-rc6skw-dirty
>>> --------------------------------------------------------------------
>>>  latency: 3232905 us, #65620/6180619, CPU#0 | (M:desktop VP:0, KP:0, SP:0
> 
> Peter, these times are crazy, mainly due to the cpu_clock. He probably 
> wants to use the sched_clock. Below is a patch to use it instead.
> 
> Sitsofe, I notice that the trace states "desktop". This means that you
> are running with CONFIG_PREEMPT_VOLUNTARY. You want 
> CONFIG_PREEMPT.
> 
> [...]
>> Is it intentional that the last event has a time earlier closer to that of the
>> first event?
>>
> 
> Change the config, and see what you get with this patch:
> 
> Note this is not compiled tested:

OK I've made the changes you suggested. Without preempt enabled the last 
event will have a stamp closer to the first event and the times are very 
high. With preempt enabled that beahviour has gone. Here are results 
with preempt enabled:

latency: 19657 us, #3268/3268, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0):
http://sucs.org/~sits/test/eeepc-debug/20080922/preempt/ath5k/latency_trace.txt 


latency: 104 us, #182/182, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0)
http://sucs.org/~sits/test/eeepc-debug/20080922/preempt/unplug/latency_trace.txt

latency: 95 us, #134/134, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0):
http://sucs.org/~sits/test/eeepc-debug/20080922/preempt/acpi/latency_trace.txt

latency: 91 us, #152/152, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0)
http://sucs.org/~sits/test/eeepc-debug/20080922/preempt/touchpad/latency_trace.txt

Are these the type of latencies to be expected with preemption on?

-- 
Sitsofe | http://sucs.org/~sits/