From c554aef0e1cc5a391a38cf790dfce205dd0d3e33 Mon Sep 17 00:00:00 2001
From: Tomas Hruby <tom@minix3.org>
Date: Wed, 15 Sep 2010 14:10:37 +0000
Subject: [PATCH] SMP - BKL statistics

- pressing 'B' on the serial cnsole prints statistics for BKL per cpu.

- 'b' resets the counters

- it presents number of cycles each CPU spends in kernel, how many
  cycyles it spends spinning while waiting for the BKL

- it shows optimistic estimation in how many cases we get the lock
  immediately without spinning. As the test is not atomic the lock may
  be already held by some other cpu before we actually try to acquire
  it.
---
 kernel/arch/i386/arch_clock.c  | 18 +++++++++++++++++-
 kernel/arch/i386/arch_system.c | 33 +++++++++++++++++++++++++++++++++
 kernel/glo.h                   |  6 ++++++
 3 files changed, 56 insertions(+), 1 deletion(-)

diff --git a/kernel/arch/i386/arch_clock.c b/kernel/arch/i386/arch_clock.c
index 27483fccf..d56fd4492 100644
--- a/kernel/arch/i386/arch_clock.c
+++ b/kernel/arch/i386/arch_clock.c
@@ -217,9 +217,25 @@ PUBLIC void context_stop(struct proc * p)
 		p->p_cycles = add64(p->p_cycles, sub64(tsc, *__tsc_ctr_switch));
 		BKL_UNLOCK();
 	} else {
+		u64_t bkl_tsc, tmp;
+		unsigned cpu = cpuid;
+		atomic_t succ;
+		
+		read_tsc_64(&bkl_tsc);
+		/* this only gives a good estimate */
+		succ = big_kernel_lock.val;
+		
 		BKL_LOCK();
+		
 		read_tsc_64(&tsc);
-		p->p_cycles = add64(p->p_cycles, sub64(tsc, *__tsc_ctr_switch));
+
+		bkl_ticks[cpu] = add64(bkl_ticks[cpu], sub64(tsc, bkl_tsc));
+		bkl_tries[cpu]++;
+		bkl_succ[cpu] += !(!(succ == 0));
+
+		tmp = sub64(tsc, *__tsc_ctr_switch);
+		kernel_ticks[cpu] = add64(kernel_ticks[cpu], tmp);
+		p->p_cycles = add64(p->p_cycles, tmp);
 	}
 	
 	*__tsc_ctr_switch = tsc;
diff --git a/kernel/arch/i386/arch_system.c b/kernel/arch/i386/arch_system.c
index 84fd53892..5cc381adc 100644
--- a/kernel/arch/i386/arch_system.c
+++ b/kernel/arch/i386/arch_system.c
@@ -420,6 +420,31 @@ PRIVATE void ser_dump_segs(void)
 	}
 }
 
+#ifdef CONFIG_SMP
+PRIVATE void dump_bkl_usage(void)
+{
+	unsigned cpu;
+
+	printf("--- BKL usage ---\n");
+	for (cpu = 0; cpu < ncpus; cpu++) {
+		printf("cpu %3d kernel ticks 0x%x%08x bkl ticks 0x%x%08x succ %d tries %d\n", cpu,
+				kernel_ticks[cpu].hi, kernel_ticks[cpu].lo, 
+				bkl_ticks[cpu].hi, bkl_ticks[cpu].lo,
+				bkl_succ[cpu], bkl_tries[cpu]);
+	}
+}
+
+PRIVATE void reset_bkl_usage(void)
+{
+	unsigned cpu;
+
+	memset(kernel_ticks, 0, sizeof(kernel_ticks));
+	memset(bkl_ticks, 0, sizeof(bkl_ticks));
+	memset(bkl_tries, 0, sizeof(bkl_tries));
+	memset(bkl_succ, 0, sizeof(bkl_succ));
+}
+#endif
+
 PRIVATE void ser_debug(const int c)
 {
 	serial_debug_active = 1;
@@ -429,6 +454,14 @@ PRIVATE void ser_debug(const int c)
 	case 'Q':
 		minix_shutdown(NULL);
 		NOT_REACHABLE;
+#ifdef CONFIG_SMP
+	case 'B':
+		dump_bkl_usage();
+		break;
+	case 'b':
+		reset_bkl_usage();
+		break;
+#endif
 	case '1':
 		ser_dump_proc();
 		break;
diff --git a/kernel/glo.h b/kernel/glo.h
index 3ac06075a..3c790acda 100644
--- a/kernel/glo.h
+++ b/kernel/glo.h
@@ -80,4 +80,10 @@ extern struct segdesc_s gdt[];		/* global descriptor table */
 
 EXTERN volatile int serial_debug_active;
 
+/* BKL stats */
+EXTERN u64_t kernel_ticks[CONFIG_MAX_CPUS];
+EXTERN u64_t bkl_ticks[CONFIG_MAX_CPUS];
+EXTERN unsigned bkl_tries[CONFIG_MAX_CPUS];
+EXTERN unsigned bkl_succ[CONFIG_MAX_CPUS];
+
 #endif /* GLO_H */
-- 
2.44.0