Re: libata/sata_nv latency on NVIDIA CK804 [was Re: AMD64 X2 lost ticks on PM timer]

["Bill Rugolsky Jr." <brugolsky@telemetry-investments.com>]

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/