Reading EeePC900 battery info causes stalls

Reading EeePC900 battery info causes stalls

[Sitsofe Wheeler]

(Long thread that was originally posted over here: 
http://tinyurl.com/4akxa5 )

I've found that when running on battery (and the battery is not full) 
the system will stall while battery information is read when using a non 
preemptive kernel.

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.

I have ftraces of the stalls but the traces become large very quickly. 
To that end I have disabled the tracing of certain functions to allow 
part of the traces to be produced.

By doing counts across multiple runs I would say that the most 
frequently called functions are the following (in most frequently called 
order). The counts are definitely approximate but are reasonable 
relative to each other.

  475325 acpi_os_release_object (acpi_ut_delete_generic_state)
  406895 kmem_cache_free (acpi_os_release_object)
  402838 kmem_cache_alloc (acpi_ut_create_generic_state)
  132968 acpi_ut_update_ref_count (acpi_ut_update_object_reference)
  131041 acpi_ut_pop_generic_state (acpi_ut_update_object_reference)
  131036 acpi_ut_delete_generic_state (acpi_ut_update_object_reference)
  131025 acpi_ut_create_generic_state (acpi_ut_create_update_state)
  131023 acpi_ut_create_update_state_and_push 
(acpi_ut_update_object_reference)
  131020 acpi_ut_create_update_state (acpi_ut_create_update_state_and_push)
  131018 acpi_ut_push_generic_state (acpi_ut_create_update_state_and_push)
   60147 acpi_ns_get_next_node (acpi_ns_delete_namespace_by_owner)
   28974 acpi_ns_get_next_valid_node (acpi_ns_get_next_node)


Here's the command line I used to disable the tracing of certain 
frequent functions:

echo acpi_os_release_object > set_ftrace_notrace && echo kmem_cache_* >> 
set_ftrace_notrace && echo acpi_ut_* >> set_ftrace_notrace

Logs with the filtering on can be seen here (15Mbytes decompressed each):
http://sucs.org/~sits/test/eeepc-debug/20080923/latency_trace.gz
http://sucs.org/~sits/test/eeepc-debug/20080923/trace.txt.gz

I guess the aim is to find a good point to put cond_resched() or 
otherwise solve the latency issue.

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

Re: Reading EeePC900 battery info causes stalls

[Alexey Starikovskiy]

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

Hi Sitsofe,

I think the least troubling place to add cond_resched() is then ACPICA 
is exiting interpreter.
Please check if the attached patch helps with latencies.

Regards,
Alex.

Sitsofe Wheeler wrote:
> (Long thread that was originally posted over here: 
> http://tinyurl.com/4akxa5 )
>
> I've found that when running on battery (and the battery is not full) 
> the system will stall while battery information is read when using a 
> non preemptive kernel.
>
> 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.
>
> I have ftraces of the stalls but the traces become large very quickly. 
> To that end I have disabled the tracing of certain functions to allow 
> part of the traces to be produced.
>
> By doing counts across multiple runs I would say that the most 
> frequently called functions are the following (in most frequently 
> called order). The counts are definitely approximate but are 
> reasonable relative to each other.
>
>  475325 acpi_os_release_object (acpi_ut_delete_generic_state)
>  406895 kmem_cache_free (acpi_os_release_object)
>  402838 kmem_cache_alloc (acpi_ut_create_generic_state)
>  132968 acpi_ut_update_ref_count (acpi_ut_update_object_reference)
>  131041 acpi_ut_pop_generic_state (acpi_ut_update_object_reference)
>  131036 acpi_ut_delete_generic_state (acpi_ut_update_object_reference)
>  131025 acpi_ut_create_generic_state (acpi_ut_create_update_state)
>  131023 acpi_ut_create_update_state_and_push 
> (acpi_ut_update_object_reference)
>  131020 acpi_ut_create_update_state 
> (acpi_ut_create_update_state_and_push)
>  131018 acpi_ut_push_generic_state (acpi_ut_create_update_state_and_push)
>   60147 acpi_ns_get_next_node (acpi_ns_delete_namespace_by_owner)
>   28974 acpi_ns_get_next_valid_node (acpi_ns_get_next_node)
>
>
> Here's the command line I used to disable the tracing of certain 
> frequent functions:
>
> echo acpi_os_release_object > set_ftrace_notrace && echo kmem_cache_* 
> >> set_ftrace_notrace && echo acpi_ut_* >> set_ftrace_notrace
>
> Logs with the filtering on can be seen here (15Mbytes decompressed each):
> http://sucs.org/~sits/test/eeepc-debug/20080923/latency_trace.gz
> http://sucs.org/~sits/test/eeepc-debug/20080923/trace.txt.gz
>
> I guess the aim is to find a good point to put cond_resched() or 
> otherwise solve the latency issue.
>


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

diff --git a/drivers/acpi/executer/exutils.c b/drivers/acpi/executer/exutils.c
index 86c0388..3c715d0 100644
--- a/drivers/acpi/executer/exutils.c
+++ b/drivers/acpi/executer/exutils.c
@@ -143,6 +143,8 @@ void acpi_ex_reacquire_interpreter(void)
  *
  ******************************************************************************/
 
+#include <linux/sched.h>
+
 void acpi_ex_exit_interpreter(void)
 {
 	acpi_status status;
@@ -154,7 +156,7 @@ void acpi_ex_exit_interpreter(void)
 		ACPI_ERROR((AE_INFO,
 			    "Could not release AML Interpreter mutex"));
 	}
-
+	cond_resched();
 	return_VOID;
 }
 

Re: Reading EeePC900 battery info causes stalls

[Sitsofe Wheeler]

Hi Alexey,

Alexey Starikovskiy wrote:
> I think the least troubling place to add cond_resched() is then ACPICA 
> is exiting interpreter.
> Please check if the attached patch helps with latencies.

There was no real change (latency was still bad). If you look at the 
trace (before your patch) on 
http://sucs.org/~sits/test/eeepc-debug/20080923/latency_trace.gz 
(700kbyte compressed, 15Mbytes uncompressed) you can see that 
acpi_ex_exit_interpreter is only called once near the end of the trace:

      cat-5901    0.N.. 270496us : acpi_ex_exit_interpreter 
(acpi_ev_address_space_dispatch)

By then the time had already been racked up...

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

Re: Reading EeePC900 battery info causes stalls

[Sitsofe Wheeler]

Hi Alexey,

Alexey Starikovskiy wrote:
> I think the least troubling place to add cond_resched() is then ACPICA 
> is exiting interpreter.
> Please check if the attached patch helps with latencies.

There was no real change (latency was still bad). If you look at the 
trace (before your patch) on 
http://sucs.org/~sits/test/eeepc-debug/20080923/latency_trace.gz 
(700kbyte compressed, 15Mbytes uncompressed) you can see that 
acpi_ex_exit_interpreter is only called once near the end of the trace:

      cat-5901    0.N.. 270496us : acpi_ex_exit_interpreter 
(acpi_ev_address_space_dispatch)

By then the time had already been racked up...

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

Re: Reading EeePC900 battery info causes stalls

[Alexey Starikovskiy]

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

Sitsofe Wheeler wrote:
> Hi Alexey,
>
> Alexey Starikovskiy wrote:
>> I think the least troubling place to add cond_resched() is then 
>> ACPICA is exiting interpreter.
>> Please check if the attached patch helps with latencies.
>
> There was no real change (latency was still bad). If you look at the 
> trace (before your patch) on 
> http://sucs.org/~sits/test/eeepc-debug/20080923/latency_trace.gz 
> (700kbyte compressed, 15Mbytes uncompressed) you can see that 
> acpi_ex_exit_interpreter is only called once near the end of the trace:
>
>      cat-5901    0.N.. 270496us : acpi_ex_exit_interpreter 
> (acpi_ev_address_space_dispatch)
>
> By then the time had already been racked up...
>
Ok, let's add it to the end of acpi_ps_complete_op() then... They appear 
every 100usec or so...


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

diff --git a/drivers/acpi/parser/psloop.c b/drivers/acpi/parser/psloop.c
index c06238e..33cd061 100644
--- a/drivers/acpi/parser/psloop.c
+++ b/drivers/acpi/parser/psloop.c
@@ -564,6 +564,8 @@ acpi_ps_get_arguments(struct acpi_walk_state *walk_state,
  *
  ******************************************************************************/
 
+#include <linux/sched.h>
+
 static acpi_status
 acpi_ps_complete_op(struct acpi_walk_state *walk_state,
 		    union acpi_parse_object **op, acpi_status status)
@@ -719,6 +721,8 @@ acpi_ps_complete_op(struct acpi_walk_state *walk_state,
 		*op = NULL;
 	}
 
+	cond_resched();
+
 	return_ACPI_STATUS(AE_OK);
 }
 

Re: Reading EeePC900 battery info causes stalls

[Alexey Starikovskiy]

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

Alexey Starikovskiy wrote:
> Sitsofe Wheeler wrote:
>> Hi Alexey,
>>
>> Alexey Starikovskiy wrote:
>>> I think the least troubling place to add cond_resched() is then 
>>> ACPICA is exiting interpreter.
>>> Please check if the attached patch helps with latencies.
>>
>> There was no real change (latency was still bad). If you look at the 
>> trace (before your patch) on 
>> http://sucs.org/~sits/test/eeepc-debug/20080923/latency_trace.gz 
>> (700kbyte compressed, 15Mbytes uncompressed) you can see that 
>> acpi_ex_exit_interpreter is only called once near the end of the trace:
>>
>>      cat-5901    0.N.. 270496us : acpi_ex_exit_interpreter 
>> (acpi_ev_address_space_dispatch)
>>
>> By then the time had already been racked up...
>>
> Ok, let's add it to the end of acpi_ps_complete_op() then... They 
> appear every 100usec or so...
>
acpi_ps_parse_aml() is called not so often (~10000usec), so maybe it is 
a "sweet spot"



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

diff --git a/drivers/acpi/parser/psparse.c b/drivers/acpi/parser/psparse.c
index 15e1702..ceab67c 100644
--- a/drivers/acpi/parser/psparse.c
+++ b/drivers/acpi/parser/psparse.c
@@ -439,6 +439,8 @@ acpi_ps_next_parse_state(struct acpi_walk_state *walk_state,
  *
  ******************************************************************************/
 
+#include <linux/sched.h>
+
 acpi_status acpi_ps_parse_aml(struct acpi_walk_state *walk_state)
 {
 	acpi_status status;
@@ -688,5 +690,6 @@ acpi_status acpi_ps_parse_aml(struct acpi_walk_state *walk_state)
 	acpi_ut_delete_generic_state(ACPI_CAST_PTR
 				     (union acpi_generic_state, thread));
 	acpi_gbl_current_walk_list = prev_walk_list;
+	cond_resched();
 	return_ACPI_STATUS(status);
 }

Re: Reading EeePC900 battery info causes stalls

[Sitsofe Wheeler]

Alexey Starikovskiy wrote:
> acpi_ps_parse_aml() is called not so often (~10000usec), so maybe it is 
> a "sweet spot"

The latency is pretty bad with this patch (assuming you did not want it 
applied on top of your previous patch)

Here's the tail end of a full trace:
http://sucs.org/~sits/test/eeepc-debug/20080925/1250/latency_trace_all_tail.gz 
(3.3Mbytes but close 100Mbytes when decompressed)
  latency: 2912285 us, #1000038/5344107, CPU#0 | (M:desktop VP:0, KP:0, 
SP:0 HP:0
)

Here's a complete (but filtered) trace:
http://sucs.org/~sits/test/eeepc-debug/20080925/1250/latency_trace.gz
  latency: 315814 us, #227600/227600, CPU#0 | (M:desktop VP:0, KP:0, 
SP:0 HP:0)

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

Re: Reading EeePC900 battery info causes stalls

[Alexey Starikovskiy]

Sitsofe Wheeler wrote:
> Alexey Starikovskiy wrote:
>> acpi_ps_parse_aml() is called not so often (~10000usec), so maybe it 
>> is a "sweet spot"
>
> The latency is pretty bad with this patch (assuming you did not want 
> it applied on top of your previous patch)
>
> Here's the tail end of a full trace:
> http://sucs.org/~sits/test/eeepc-debug/20080925/1250/latency_trace_all_tail.gz 
> (3.3Mbytes but close 100Mbytes when decompressed)
>  latency: 2912285 us, #1000038/5344107, CPU#0 | (M:desktop VP:0, KP:0, 
> SP:0 HP:0
> )
>
> Here's a complete (but filtered) trace:
> http://sucs.org/~sits/test/eeepc-debug/20080925/1250/latency_trace.gz
>  latency: 315814 us, #227600/227600, CPU#0 | (M:desktop VP:0, KP:0, 
> SP:0 HP:0)
>
Ok, let's stick with previous patch then.
It will be somewhat difficult to push though, because the code we 
touched belongs to ACPICA (multi-platform code),
so should not contain explicit Linux-only operands.
If you agree that the place is right, I'll make proper patch with all 
needed redirections to
make ACPICA happy.

Re: Reading EeePC900 battery info causes stalls

[Alexey Starikovskiy]

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

Alexey Starikovskiy wrote:
> Sitsofe Wheeler wrote:
>> Alexey Starikovskiy wrote:
>>> acpi_ps_parse_aml() is called not so often (~10000usec), so maybe it 
>>> is a "sweet spot"
>>
>> The latency is pretty bad with this patch (assuming you did not want 
>> it applied on top of your previous patch)
>>
>> Here's the tail end of a full trace:
>> http://sucs.org/~sits/test/eeepc-debug/20080925/1250/latency_trace_all_tail.gz 
>> (3.3Mbytes but close 100Mbytes when decompressed)
>>  latency: 2912285 us, #1000038/5344107, CPU#0 | (M:desktop VP:0, 
>> KP:0, SP:0 HP:0
>> )
>>
>> Here's a complete (but filtered) trace:
>> http://sucs.org/~sits/test/eeepc-debug/20080925/1250/latency_trace.gz
>>  latency: 315814 us, #227600/227600, CPU#0 | (M:desktop VP:0, KP:0, 
>> SP:0 HP:0)
>>
> Ok, let's stick with previous patch then.
> It will be somewhat difficult to push though, because the code we 
> touched belongs to ACPICA (multi-platform code),
> so should not contain explicit Linux-only operands.
> If you agree that the place is right, I'll make proper patch with all 
> needed redirections to
> make ACPICA happy.
Ok, here is the ACPICA-friendly patch, please check if it's still good.

Regards,
Alex.

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

ACPICA: add preemption point after each opcode parse

From: Alexey Starikovskiy <astarikovskiy@suse.de>

Signed-off-by: Alexey Starikovskiy <astarikovskiy@suse.de>
---
 drivers/acpi/parser/psloop.c    |    2 ++
 include/acpi/acmacros.h         |    5 +++++
 include/acpi/platform/aclinux.h |    6 ++++++
 3 files changed, 13 insertions(+), 0 deletions(-)

diff --git a/drivers/acpi/parser/psloop.c b/drivers/acpi/parser/psloop.c
index c06238e..4647039 100644
--- a/drivers/acpi/parser/psloop.c
+++ b/drivers/acpi/parser/psloop.c
@@ -719,6 +719,8 @@ acpi_ps_complete_op(struct acpi_walk_state *walk_state,
 		*op = NULL;
 	}
 
+	ACPI_PREEMPTION_POINT();
+
 	return_ACPI_STATUS(AE_OK);
 }
 
diff --git a/include/acpi/acmacros.h b/include/acpi/acmacros.h
index 57ab9e9..b402685 100644
--- a/include/acpi/acmacros.h
+++ b/include/acpi/acmacros.h
@@ -703,4 +703,9 @@ struct acpi_integer_overlay {
 
 #endif				/* ACPI_DBG_TRACK_ALLOCATIONS */
 
+/* Preemption point */
+#ifndef ACPI_PREEMPTION_POINT
+#define ACPI_PREEMPTION_POINT() /* no preemption */
+#endif
+
 #endif				/* ACMACROS_H */
diff --git a/include/acpi/platform/aclinux.h b/include/acpi/platform/aclinux.h
index 9af4645..029c8c0 100644
--- a/include/acpi/platform/aclinux.h
+++ b/include/acpi/platform/aclinux.h
@@ -53,6 +53,7 @@
 #include <linux/kernel.h>
 #include <linux/module.h>
 #include <linux/ctype.h>
+#include <linux/sched.h>
 #include <asm/system.h>
 #include <asm/atomic.h>
 #include <asm/div64.h>
@@ -137,4 +138,9 @@ static inline void *acpi_os_acquire_object(acpi_cache_t * cache)
 #define ACPI_ALLOCATE_ZEROED(a)	acpi_os_allocate_zeroed(a)
 #define ACPI_FREE(a)		kfree(a)
 
+/*
+ * We need to show where it is safe to preempt execution of ACPICA
+ */
+#define ACPI_PREEMPTION_POINT()	cond_resched()
+
 #endif				/* __ACLINUX_H__ */

Re: Reading EeePC900 battery info causes stalls

[Sitsofe Wheeler]

Alexey Starikovskiy wrote:
> Ok, here is the ACPICA-friendly patch, please check if it's still good.

I've tested it and it seems good enough to prevent music playing in 
rhythmbox being interrupted by battery checking. There are cases where 
you can still detect stalling (e.g. while playing games and the battery 
is read) but it's brought latency down from 3232905us to 13900us on a 
desktop kernel which is significant in and of itself.

Tested-by: Sitsofe Wheeler <sitsofe@yahoo.com>

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

Re: Reading EeePC900 battery info causes stalls

[Sitsofe Wheeler]

Alexey Starikovskiy wrote:
> Ok, let's add it to the end of acpi_ps_complete_op() then... They appear 
> every 100usec or so...

(I know you've posted something later but I've only just got results for 
this test - talk about fast!)

Massively better. I can still provoke small stalls that are now only 
noticeable when playing games.

wakeup latency trace v1.1.5 on 2.6.27-rc7-tipskw-00756-g6522eab-dirty
--------------------------------------------------------------------
  latency: 13900 us, #25557/25557, CPU#0 | (M:desktop VP:0, KP:0, SP:0 HP:0)
     -----------------
     | task: a7xpg-5739 (uid:1000 nice:0 policy:2 rt_prio:5)
     -----------------

The trace can be seen on 
http://sucs.org/~sits/test/eeepc-debug/20080925/acpi/latency_trace.gz .

Here are the top called functions from this much shorter trace:
    2526 acpi_ut_update_ref_count (acpi_ut_update_object_reference)
    2525 kmem_cache_free (acpi_os_release_object)
    2521 acpi_os_release_object (acpi_ut_delete_generic_state)
    2520 acpi_ut_delete_generic_state (acpi_ut_update_object_reference)
    2519 acpi_ut_pop_generic_state (acpi_ut_update_object_reference)
    2514 acpi_ut_create_generic_state (acpi_ut_create_update_state)
    2513 kmem_cache_alloc (acpi_ut_create_generic_state)
    2513 acpi_ut_push_generic_state (acpi_ut_create_update_state_and_push)
    2512 acpi_ut_create_update_state_and_push 
(acpi_ut_update_object_reference)
    2511 acpi_ut_create_update_state (acpi_ut_create_update_state_and_push)
     231 __slab_free (kmem_cache_free)

OK time to investigate your next mail...

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

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/