lkml.org 
[lkml]   [2004]   [Aug]   [21]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
/
From
SubjectRe: [patch] voluntary-preempt-2.6.8.1-P5
Date
I'm regularly seeing acpi_ec_read latencies. (e.g. when closing the lid of
my notebook, when the processor cooler activates, ...)

I'm guessing there isn't much that can be done about this, right?!


preemption latency trace v1.0.1
-------------------------------
latency: 1151 us, entries: 94 (94)
-----------------
| task: kacpid/6, uid:0 nice:-10 policy:0 rt_prio:0
-----------------
=> started at: acpi_ec_read+0x6b/0xf7
=> ended at: acpi_ec_read+0xc8/0xf7
=======>
00000001 0.000ms (+0.000ms): acpi_ec_read (acpi_ec_space_handler)
00000001 0.000ms (+0.000ms): acpi_hw_low_level_write (acpi_ec_read)
00000001 0.000ms (+0.000ms): acpi_os_write_port (acpi_hw_low_level_write)
00000001 0.001ms (+0.001ms): acpi_ec_wait (acpi_ec_read)
00000001 0.001ms (+0.000ms): acpi_hw_low_level_read (acpi_ec_wait)
00000001 0.001ms (+0.000ms): acpi_os_read_port (acpi_hw_low_level_read)
00000001 0.003ms (+0.001ms): __const_udelay (acpi_ec_wait)
00000001 0.003ms (+0.000ms): __delay (acpi_ec_wait)
00000001 0.003ms (+0.000ms): delay_tsc (__delay)
[...]
00000001 1.113ms (+0.001ms): smp_apic_timer_interrupt (acpi_ec_read)
00010001 1.113ms (+0.000ms): profile_hook (smp_apic_timer_interrupt)
00010002 1.113ms (+0.000ms): notifier_call_chain (profile_hook)
00000002 1.113ms (+0.000ms): do_softirq (smp_apic_timer_interrupt)
00000100 1.113ms (+0.000ms): __do_softirq (do_softirq)
00010001 1.113ms (+0.000ms): do_IRQ (acpi_ec_read)
00010002 1.113ms (+0.000ms): ack_edge_ioapic_irq (do_IRQ)
00010002 1.113ms (+0.000ms): generic_redirect_hardirq (do_IRQ)
00010000 1.113ms (+0.000ms): generic_handle_IRQ_event (do_IRQ)
00010000 1.113ms (+0.000ms): timer_interrupt (generic_handle_IRQ_event)
00010001 1.113ms (+0.000ms): mark_offset_tsc (timer_interrupt)
00010001 1.123ms (+0.009ms): do_timer (timer_interrupt)
00010001 1.123ms (+0.000ms): update_process_times (do_timer)
00010001 1.123ms (+0.000ms): update_one_process (update_process_times)
00010001 1.123ms (+0.000ms): run_local_timers (update_process_times)
00010001 1.123ms (+0.000ms): raise_softirq (update_process_times)
00010001 1.123ms (+0.000ms): scheduler_tick (update_process_times)
00010001 1.123ms (+0.000ms): sched_clock (scheduler_tick)
00010002 1.123ms (+0.000ms): task_timeslice (scheduler_tick)
00010001 1.123ms (+0.000ms): update_wall_time (do_timer)
00010001 1.123ms (+0.000ms): update_wall_time_one_tick (update_wall_time)
00010002 1.123ms (+0.000ms): generic_note_interrupt (do_IRQ)
00010002 1.123ms (+0.000ms): end_edge_ioapic_irq (do_IRQ)
00000002 1.123ms (+0.000ms): do_softirq (do_IRQ)
00000100 1.123ms (+0.000ms): __do_softirq (do_softirq)
00000001 1.124ms (+0.000ms): sub_preempt_count (acpi_ec_read)

Full trace output available on:
http://users.telenet.be/kvogel/ec-latency.txt

Culprit is the following code in drivers/acpi/ec.c
function acpi_ec_wait (edited for mail):

----
#define ACPI_EC_UDELAY 100 /* Poll @ 100us increments */
#define ACPI_EC_UDELAY_COUNT 1000 /* Wait 10ms max. during EC ops */

u32 i = ACPI_EC_UDELAY_COUNT;

do {
acpi_hw_low_level_read(8, &acpi_ec_status, &ec->status_addr);
if (acpi_ec_status & ACPI_EC_FLAG_OBF)
return 0;
udelay(ACPI_EC_UDELAY);
} while (--i>0);
----

NOTE: isn't the comment on the ACPI_EC_UDELAY_COUNT wrong?! Or is my
arithmetic not what it used to be. (1000 loops of 100us = 100ms instead of
10ms, no?)



-
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/

\
 
 \ /
  Last update: 2005-03-22 14:05    [W:0.371 / U:7.932 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site