Re: [patch] voluntary-preempt-2.6.8.1-P5

[Karl Vogel]

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@xxxxxxxxxxxxxxx
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/