* Added the possibility to debug latency issues with spinlocks.

* When DEBUG_SPINLOCK_LATENCIES is 1, the system will panic if any spinlock is
  held longer than DEBUG_LATENCY micro seconds (currently 200). If your system
  doesn't boot anymore, a new safemode setting can disable the panic.
* Besides some problems during boot when the MTRRs are set up, 200 usecs work
  fine here if all debug output is turned off (the output stuff is definitely
  problematic, though I don't have a good idea on how to improve upon it a lot).
* Renamed the formerly BeOS compatible safemode settings to look better; there
  is no need to be compatible there.


git-svn-id: file:///srv/svn/repos/haiku/haiku/trunk@33953 a95241bf-73f2-0310-859d-f6bbb57e9c96

build/config_headers/kernel_debug_config.h

@@ -75,6 +75,8 @@
 // available.
 #define DEBUG_SPINLOCKS					KDEBUG_LEVEL_2
 
+#define DEBUG_SPINLOCK_LATENCIES		0
+
 
 // VM
 

headers/private/system/safemode_defs.h

@@ -1,16 +1,13 @@
 /*
- * Copyright 2004-2008, Axel Dörfler, [email protected]. All rights reserved.
+ * Copyright 2004-2009, Axel Dörfler, [email protected].
  * Distributed under the terms of the MIT License.
  */
 #ifndef _SYSTEM_SAFEMODE_DEFS_H
 #define _SYSTEM_SAFEMODE_DEFS_H
 
 
-// these are BeOS compatible additions to the safemode
+#define B_SAFEMODE_DISABLE_USER_ADD_ONS		"disable_user_addons"
-// constants in the driver_settings.h header
+#define B_SAFEMODE_DISABLE_IDE_DMA			"disable_ide_dma"
-
-#define B_SAFEMODE_DISABLE_USER_ADD_ONS		"disableuseraddons"
-#define B_SAFEMODE_DISABLE_IDE_DMA			"disableidedma"
 #define B_SAFEMODE_DISABLE_IOAPIC			"disable_ioapic"
 #define B_SAFEMODE_DISABLE_ACPI				"disable_acpi"
 #define B_SAFEMODE_DISABLE_APIC				"disable_apic"
@@ -19,5 +16,9 @@
 #define B_SAFEMODE_DISABLE_HYPER_THREADING	"disable_hyperthreading"
 #define B_SAFEMODE_FAIL_SAFE_VIDEO_MODE		"fail_safe_video_mode"
 
+#if DEBUG_SPINLOCK_LATENCIES
+#	define B_SAFEMODE_DISABLE_LATENCY_CHECK	"disable_latency_check"
+#endif
+
 
 #endif	/* _SYSTEM_SAFEMODE_DEFS_H */

src/system/boot/loader/menu.cpp

@@ -457,6 +457,16 @@ add_safe_mode_menu()
 
 	platform_add_menus(safeMenu);
 
+#if DEBUG_SPINLOCK_LATENCIES
+	item = new(std::nothrow) MenuItem("Disable latency checks");
+	if (item != NULL) {
+		item->SetType(MENU_ITEM_MARKABLE);
+		item->SetData(B_SAFEMODE_DISABLE_LATENCY_CHECK);
+		item->SetHelpText("Disables latency check panics.");
+		safeMenu->AddItem(item);
+	}
+#endif
+
 	safeMenu->AddItem(item
 		= new(nothrow) MenuItem("Enable serial debug output"));
 	item->SetData("serial_debug_output");

src/system/kernel/smp.cpp

@@ -1,13 +1,15 @@
 /*
  * Copyright 2008-2009, Ingo Weinhold, [email protected].
- * Copyright 2002-2008, Axel Dörfler, [email protected].
+ * Copyright 2002-2009, Axel Dörfler, [email protected].
  * Distributed under the terms of the MIT License.
  *
  * Copyright 2001-2002, Travis Geiselbrecht. All rights reserved.
  * Distributed under the terms of the NewOS License.
  */
 
-/* Functionality for symetrical multi-processors */
+
+/*! Functionality for symetrical multi-processors */
+
 
 #include <smp.h>
 
@@ -23,18 +25,21 @@
 #include <int.h>
 #include <spinlock_contention.h>
 #include <thread.h>
+#if DEBUG_SPINLOCK_LATENCIES
+#	include <safemode.h>
+#endif
 
 #include "kernel_debug_config.h"
 
 
 //#define TRACE_SMP
-
 #ifdef TRACE_SMP
 #	define TRACE(x) dprintf x
 #else
 #	define TRACE(x) ;
 #endif
 
+
 #define MSG_POOL_SIZE (SMP_MAX_CPUS * 4)
 
 // These macros define the number of unsuccessful iterations in
@@ -145,6 +150,61 @@ dump_spinlock(int argc, char** argv)
 #endif	// DEBUG_SPINLOCKS
 
 
+#if DEBUG_SPINLOCK_LATENCIES
+
+
+#define NUM_LATENCY_LOCKS	4
+#define DEBUG_LATENCY		200
+
+
+static struct {
+	spinlock	*lock;
+	bigtime_t	timestamp;
+} sLatency[B_MAX_CPU_COUNT][NUM_LATENCY_LOCKS];
+
+static int32 sLatencyIndex[B_MAX_CPU_COUNT];
+static bool sEnableLatencyCheck;
+
+
+static void
+push_latency(spinlock* lock)
+{
+	if (!sEnableLatencyCheck)
+		return;
+
+	int32 cpu = smp_get_current_cpu();
+	int32 index = (++sLatencyIndex[cpu]) % NUM_LATENCY_LOCKS;
+
+	sLatency[cpu][index].lock = lock;
+	sLatency[cpu][index].timestamp = system_time();
+}
+
+
+static void
+test_latency(spinlock* lock)
+{
+	if (!sEnableLatencyCheck)
+		return;
+
+	int32 cpu = smp_get_current_cpu();
+
+	for (int32 i = 0; i < NUM_LATENCY_LOCKS; i++) {
+		if (sLatency[cpu][i].lock == lock) {
+			bigtime_t diff = system_time() - sLatency[cpu][i].timestamp;
+			if (diff > DEBUG_LATENCY && diff < 500000) {
+				panic("spinlock %p were held for %lld usecs (%d allowed)\n",
+					lock, diff, DEBUG_LATENCY);
+			}
+
+			sLatency[cpu][i].lock = NULL;
+		}
+	}
+}
+
+
+#endif	// DEBUG_SPINLOCK_LATENCIES
+
+
 int
 dump_ici_messages(int argc, char** argv)
 {
@@ -253,9 +313,9 @@ acquire_spinlock(spinlock *lock)
 				break;
 		}
 
-#if DEBUG_SPINLOCKS
+#	if DEBUG_SPINLOCKS
 		push_lock_caller(arch_debug_get_caller(), lock);
-#endif
+#	endif
 #endif
 	} else {
 #if DEBUG_SPINLOCKS
@@ -270,6 +330,9 @@ acquire_spinlock(spinlock *lock)
 		push_lock_caller(arch_debug_get_caller(), lock);
 #endif
 	}
+#if DEBUG_SPINLOCK_LATENCIES
+	push_latency(lock);
+#endif
 }
 
 
@@ -347,9 +410,9 @@ acquire_spinlock_cpu(int32 currentCPU, spinlock *lock)
 				break;
 		}
 
-#if DEBUG_SPINLOCKS
+#	if DEBUG_SPINLOCKS
 		push_lock_caller(arch_debug_get_caller(), lock);
-#endif
+#	endif
 #endif
 	} else {
 #if DEBUG_SPINLOCKS
@@ -370,6 +433,10 @@ acquire_spinlock_cpu(int32 currentCPU, spinlock *lock)
 void
 release_spinlock(spinlock *lock)
 {
+#if DEBUG_SPINLOCK_LATENCIES
+	test_latency(lock);
+#endif
+
 	if (sNumCPUs > 1) {
 		if (are_interrupts_enabled())
 			panic("release_spinlock: attempt to release lock %p with interrupts enabled\n", lock);
@@ -391,12 +458,15 @@ release_spinlock(spinlock *lock)
 			panic("release_spinlock: lock %p was already released\n", lock);
 #endif
 	} else {
-		#if DEBUG_SPINLOCKS
+#if DEBUG_SPINLOCKS
-			if (are_interrupts_enabled())
+		if (are_interrupts_enabled())
-				panic("release_spinlock: attempt to release lock %p with interrupts enabled\n", lock);
+			panic("release_spinlock: attempt to release lock %p with interrupts enabled\n", lock);
-			if (atomic_set((int32 *)lock, 0) != 1)
+		if (atomic_set((int32 *)lock, 0) != 1)
-				panic("release_spinlock: lock %p was already released\n", lock);
+			panic("release_spinlock: lock %p was already released\n", lock);
-		#endif
+#endif
+#if DEBUG_SPINLOCK_LATENCIES
+		test_latency(lock);
+#endif
 	}
 }
 
@@ -1002,11 +1072,13 @@ smp_cpu_rendezvous(volatile uint32 *var, int current_cpu)
 status_t
 smp_init(kernel_args *args)
 {
-	struct smp_msg *msg;
-	int i;
-
 	TRACE(("smp_init: entry\n"));
 
+#if DEBUG_SPINLOCK_LATENCIES
+	sEnableLatencyCheck
+		= !get_safemode_boolean(B_SAFEMODE_DISABLE_LATENCY_CHECK, false);
+#endif
+
 #if DEBUG_SPINLOCKS
 	add_debugger_command_etc("spinlock", &dump_spinlock,
 		"Dump info on a spinlock",
@@ -1025,8 +1097,9 @@ smp_init(kernel_args *args)
 	if (args->num_cpus > 1) {
 		sFreeMessages = NULL;
 		sFreeMessageCount = 0;
-		for (i = 0; i < MSG_POOL_SIZE; i++) {
+		for (int i = 0; i < MSG_POOL_SIZE; i++) {
-			msg = (struct smp_msg *)malloc(sizeof(struct smp_msg));
+			struct smp_msg *msg
+				= (struct smp_msg *)malloc(sizeof(struct smp_msg));
 			if (msg == NULL) {
 				panic("error creating smp mailboxes\n");
 				return B_ERROR;