Reading EeePC900 battery info causes stalls

(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/

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.

index 86c0388..3c715d0 100644
@@ -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;
 }
 

Hi Alexey,

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/

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

index c06238e..33cd061 100644
@@ -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);
 }
 

acpi_ps_parse_aml() is called not so often (~10000usec), so maybe it is a "sweet spot"

index 15e1702..ceab67c 100644
@@ -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);
 }

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/

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.

ACPICA: add preemption point after each opcode parse

From: Alexey Starikovskiy <[email protected]>

---
 drivers/acpi/parser/psloop.c    |    2 ++
 include/acpi/acmacros.h         |    5 +++++
 include/acpi/platform/aclinux.h |    6 ++++++
 3 files changed, 13 insertions(+), 0 deletions(-)

index c06238e..4647039 100644
@@ -719,6 +719,8 @@ acpi_ps_complete_op(struct acpi_walk_state *walk_state,
 		*op = NULL;
 	}
 
+	ACPI_PREEMPTION_POINT();
+
 	return_ACPI_STATUS(AE_OK);
 }
 

index 57ab9e9..b402685 100644
@@ -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 */

index 9af4645..029c8c0 100644
@@ -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__ */

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.

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

(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/

Hi Alexey,

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/