lkml.org 
[lkml]   [2006]   [Mar]   [22]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
    Patch in this message
    /
    Date
    From
    SubjectRe: libata/sata_nv latency on NVIDIA CK804 [was Re: AMD64 X2 lost ticks on PM timer]
    On Wed, Mar 22, 2006 at 05:09:08PM +0100, Andi Kleen wrote:
    > Also my latest patchkit has a debugging patch for lost tries
    >
    > ftp://ftp.firstfloor.org/pub/ak/x86_64/quilt/patches/lost-cli-debug
    >
    > Can you test it with this patch?

    It didn't apply cleanly against vanilla 2.6.16; rediffed patch below.

    Typical output:

    time.c: Lost 12 timer tick(s)! rip 10:__do_softirq+0x4b/0xdf
    last cli handle_IRQ_event+0x62/0x71
    last cli caller __do_IRQ+0xa6/0x104
    time.c: Lost 5 timer tick(s)! rip 10:__do_softirq+0x4b/0xdf
    last cli handle_IRQ_event+0x62/0x71
    last cli caller __do_IRQ+0xa6/0x104
    time.c: Lost 4 timer tick(s)! rip 10:__do_softirq+0x4b/0xdf
    last cli handle_IRQ_event+0x62/0x71
    last cli caller __do_IRQ+0xa6/0x104
    time.c: Lost 8 timer tick(s)! rip 10:__do_softirq+0x4b/0xdf
    last cli handle_IRQ_event+0x62/0x71
    last cli caller __do_IRQ+0xa6/0x104
    time.c: Lost 3 timer tick(s)! rip 10:__do_softirq+0x4b/0xdf
    last cli handle_IRQ_event+0x62/0x71
    last cli caller __do_IRQ+0xa6/0x104

    Some statistics:

    rugolsky@ti94: grep 'last cli' /var/log/messages | sed -n -e '1p;$p'
    Mar 22 17:37:06 ti94 kernel: last cli 0x0
    Mar 22 17:43:48 ti94 kernel: last cli caller __do_IRQ+0xa6/0x104

    rugolsky@ti94: grep 'last cli' /var/log/messages | cut -d' ' -f6- | sort | uniq -c | sort -nr
    782 last cli handle_IRQ_event+0x62/0x71
    782 last cli caller __do_IRQ+0xa6/0x104
    2 last cli _spin_lock_irqsave+0x16/0x27
    1 last cli setup_boot_APIC_clock+0x48/0x12e
    1 last cli pci_direct_init+0x47/0x190
    1 last cli kmem_cache_free+0x1d/0x62
    1 last cli caller smp_prepare_cpus+0x36a/0x394
    1 last cli caller release_console_sem+0x1a/0x1c9
    1 last cli caller init+0x1c3/0x338
    1 last cli caller acpi_os_release_object+0x9/0xd
    1 last cli caller __up_read+0x19/0x9e
    1 last cli caller 0x0
    1 last cli 0x0

    Thanks.

    -Bill


    --- linux-2.6.16/arch/x86_64/kernel/time.c.lost-cli-debug 2006-03-20 00:53:29.000000000 -0500
    +++ linux-2.6.16/arch/x86_64/kernel/time.c 2006-03-22 17:09:14.000000000 -0500
    @@ -43,7 +43,7 @@
    #endif

    #ifdef CONFIG_CPU_FREQ
    -static void cpufreq_delayed_get(void);
    +static void cpufreq_delayed_get(struct pt_regs *);
    #endif
    extern void i8254_timer_resume(void);
    extern int using_apic_timer;
    @@ -63,7 +63,7 @@ static unsigned long hpet_period; /* f
    unsigned long hpet_tick; /* HPET clocks / interrupt */
    int hpet_use_timer; /* Use counter of hpet for time keeping, otherwise PIT */
    unsigned long vxtime_hz = PIT_TICK_RATE;
    -int report_lost_ticks; /* command line option */
    +int report_lost_ticks = 1; /* command line option */
    unsigned long long monotonic_base;

    struct vxtime_data __vxtime __section_vxtime; /* for vsyscalls */
    @@ -309,15 +309,20 @@ unsigned long long monotonic_clock(void)
    }
    EXPORT_SYMBOL(monotonic_clock);

    +extern unsigned long last_clier, last_clier_caller;
    +
    static noinline void handle_lost_ticks(int lost, struct pt_regs *regs)
    {
    static long lost_count;
    static int warned;

    if (report_lost_ticks) {
    - printk(KERN_WARNING "time.c: Lost %d timer "
    - "tick(s)! ", lost);
    - print_symbol("rip %s)\n", regs->rip);
    + printk(KERN_WARNING
    + "time.c: Lost %d timer tick(s)! rip %02lx",
    + lost, regs->cs);
    + print_symbol(":%s\n", regs->rip);
    + print_symbol("last cli %s\n", last_clier);
    + print_symbol("last cli caller %s\n", last_clier_caller);
    }

    if (lost_count == 1000 && !warned) {
    @@ -345,7 +350,7 @@ static noinline void handle_lost_ticks(i
    (like going into thermal throttle)
    Give cpufreq a change to catch up. */
    if ((lost_count+1) % 25 == 0) {
    - cpufreq_delayed_get();
    + cpufreq_delayed_get(regs);
    }
    #endif
    }
    @@ -599,14 +604,15 @@ static void handle_cpufreq_delayed_get(v
    * to verify the CPU frequency the timing core thinks the CPU is running
    * at is still correct.
    */
    -static void cpufreq_delayed_get(void)
    +static void cpufreq_delayed_get(struct pt_regs *regs)
    {
    static int warned;
    if (cpufreq_init && !cpufreq_delayed_issched) {
    cpufreq_delayed_issched = 1;
    if (!warned) {
    warned = 1;
    - printk(KERN_DEBUG "Losing some ticks... checking if CPU frequency changed.\n");
    + print_symbol(KERN_DEBUG
    + "Losing some ticks... checking if CPU frequency changed (rip=%s)\n", regs->rip);
    }
    schedule_work(&cpufreq_delayed_get_work);
    }
    --- linux-2.6.16/arch/x86_64/kernel/process.c.lost-cli-debug 2006-03-20 00:53:29.000000000 -0500
    +++ linux-2.6.16/arch/x86_64/kernel/process.c 2006-03-22 17:12:01.000000000 -0500
    @@ -841,3 +841,16 @@ unsigned long arch_align_stack(unsigned
    sp -= get_random_int() % 8192;
    return sp & ~0xf;
    }
    +
    +unsigned long last_clier, last_clier_caller;
    +
    +void __local_irq_disable(void *caller)
    +{
    + if (!irqs_disabled()) {
    + last_clier = __builtin_return_address(0);
    + last_clier = (unsigned long)__builtin_return_address(0);
    + last_clier_caller = (unsigned long)caller;
    + asm volatile("cli":::"memory");
    + }
    +}
    +EXPORT_SYMBOL(__local_irq_disable);
    --- linux-2.6.16/include/asm-x86_64/system.h.lost-cli-debug 2006-03-20 00:53:29.000000000 -0500
    +++ linux-2.6.16/include/asm-x86_64/system.h 2006-03-22 17:01:50.000000000 -0500
    @@ -351,7 +351,10 @@ static inline unsigned long __cmpxchg(vo
    /* For spinlocks etc */
    #define local_irq_save(x) do { local_save_flags(x); local_irq_restore((x & ~(1 << 9)) | (1 << 18)); } while (0)
    #else /* CONFIG_X86_VSMP */
    -#define local_irq_disable() __asm__ __volatile__("cli": : :"memory")
    +
    +extern void __local_irq_disable(void *caller);
    +#define local_irq_disable() __local_irq_disable(__builtin_return_address(0))
    +
    #define local_irq_enable() __asm__ __volatile__("sti": : :"memory")

    #define irqs_disabled() \
    @@ -362,7 +365,7 @@ static inline unsigned long __cmpxchg(vo
    })

    /* For spinlocks etc */
    -#define local_irq_save(x) do { warn_if_not_ulong(x); __asm__ __volatile__("# local_irq_save \n\t pushfq ; popq %0 ; cli":"=g" (x): /* no input */ :"memory"); } while (0)
    +#define local_irq_save(x) do { warn_if_not_ulong(x); __asm__ __volatile__("# local_irq_save \n\t pushfq ; popq %0":"=g" (x): /* no input */ :"memory"); local_irq_disable(); } while (0)
    #endif

    /* used in the idle loop; sti takes one instruction cycle to complete */
    -
    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: 2006-03-23 00:10    [W:0.029 / U:32.452 seconds]
    ©2003-2016 Jasper Spaans. hosted at Digital OceanAdvertise on this site