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/