spinlock latency debugging

PATCH New Jan Kiszka 1 participant 1 message Nov 29, 2005

lore

Share & tools

lore

Jan Kiszka

author

2005-11-29 19:15 UTC #0 lore raw

PATCH 1/1 spinlock latency debugging

Hi,

this is a first attempt to add some more instrumentation to the Xenomai core and related modules. It enables the existing spinlock profiling also for non-SMP setups and adds the exit location to the log. Note that this is likely not yet ready for inclusion, it's only tested with debugging on and may break with other configs.

Comments are welcome.

Some first observations: this kind of instrumentation is unfortunately insufficient to trace the full latency a task may suffer from. In case some IRQ hits inside a critical section, the tracing will not start before some functions finally called by the IRQ handler acquires a xnlock. Task latencies and longest locking periods differ by factor 2 *at least*. What we finally need is IRQ-off tracing.

Jan

asm-ia64/system.h +1 -1

Index: include/asm-ia64/system.h
===================================================================
@@ -525,7 +525,7 @@
 
 static rthal_trap_handler_t xnarch_old_trap_handler;
 
-#ifdef CONFIG_SMP
+#if defined(CONFIG_SMP) || defined(CONFIG_XENO_OPT_SPINLOCK_DEBUG)
 static xnlock_t xnarch_stacks_lock = XNARCH_LOCK_UNLOCKED;
 #endif
 static atomic_counter_t xnarch_allocated_stacks;

asm-generic/system.h +45 ~~-28~~

171 lines not on this page · raw message

rtdm/core.h +0 -3

Index: include/rtdm/core.h
===================================================================
@@ -33,10 +33,7 @@
 };
 
 
-#ifdef CONFIG_SMP
 extern xnlock_t             rt_fildes_lock;
-#endif /* CONFIG_SMP */
-
 extern unsigned int         fd_count;
 extern struct rtdm_fildes   *fildes_table;
 extern int                  open_fildes;

nucleus/heap.h +1 -1

Index: include/nucleus/heap.h
===================================================================
@@ -87,7 +87,7 @@
 
     xnqueue_t extents;
 
-#ifdef CONFIG_SMP
+#if defined(CONFIG_SMP) || defined(CONFIG_XENO_OPT_SPINLOCK_DEBUG)
     xnlock_t lock;
 #endif /* CONFIG_SMP */

nucleus/pod.h +1 -1

Index: include/nucleus/pod.h
===================================================================
@@ -233,7 +233,7 @@
 
 extern xnpod_t *nkpod;
 
-#ifdef CONFIG_SMP
+#if defined(CONFIG_SMP) || defined(CONFIG_XENO_OPT_SPINLOCK_DEBUG)
 extern xnlock_t nklock;
 #endif /* CONFIG_SMP */

nucleus/queue.h +2 -1

Index: include/nucleus/queue.h
===================================================================
@@ -57,7 +57,8 @@
 
     xnholder_t head;
     int elems;
-#if defined(__KERNEL__) && defined(CONFIG_XENO_OPT_DEBUG) && defined(CONFIG_SMP)
+#if defined(__KERNEL__) && defined(CONFIG_XENO_OPT_DEBUG) && \
+        (defined(CONFIG_SMP) || defined(CONFIG_XENO_OPT_SPINLOCKDEBUG))
     xnlock_t lock;
 #endif /* __KERNEL__ && CONFIG_XENO_OPT_DEBUG && CONFIG_SMP */

skins/posix/signal.c +1 -1

Index: ksrc/skins/posix/signal.c
===================================================================
@@ -32,7 +32,7 @@
 
 static struct sigaction actions[SIGRTMAX];
 static pse51_siginfo_t pse51_infos_pool[PSE51_SIGQUEUE_MAX];
-#ifdef CONFIG_SMP
+#if defined(CONFIG_SMP) || defined(CONFIG_XENO_OPT_SPINLOCK_DEBUG)
 static xnlock_t pse51_infos_lock;
 #endif
 static xnpqueue_t pse51_infos_free_list;

skins/rtdm/device.c +1 -1

Index: ksrc/skins/rtdm/device.c
===================================================================
@@ -62,7 +62,7 @@
 
 DECLARE_MUTEX(nrt_dev_lock);
 
-#ifdef CONFIG_SMP
+#if defined(CONFIG_SMP) || defined(CONFIG_XENO_OPT_SPINLOCK_DEBUG)
 xnlock_t             rt_dev_lock = XNARCH_LOCK_UNLOCKED;
 #endif /* CONFIG_SMP */

skins/rtdm/core.c +1 -1

Index: ksrc/skins/rtdm/core.c
===================================================================
@@ -44,7 +44,7 @@
 static struct rtdm_fildes   *free_fildes;   /* chain of free descriptors */
 int                         open_fildes;    /* number of used descriptors */
 
-#ifdef CONFIG_SMP
+#if defined(CONFIG_SMP) || defined(CONFIG_XENO_OPT_SPINLOCK_DEBUG)
 xnlock_t                    rt_fildes_lock = XNARCH_LOCK_UNLOCKED;
 #endif /* !CONFIG_SMP */

nucleus/Kconfig +8 -0

Index: ksrc/nucleus/Kconfig
===================================================================
@@ -87,6 +87,14 @@
 	Do not switch this option on unless you really know what you
 	are doing.
 
+config XENO_OPT_SPINLOCK_DEBUG
+	bool "Spinlock debugging"
+	default n
+#	depends on XENO_OPT_DEBUG
+	help
+
+	no help
+
 config XENO_OPT_WATCHDOG
 	bool "Watchdog support"
 	default n

nucleus/pod.c +2 -2

Index: ksrc/nucleus/pod.c
===================================================================
@@ -48,7 +48,7 @@
 
 xnpod_t *nkpod = NULL;
 
-#ifdef CONFIG_SMP
+#if defined(CONFIG_SMP) || defined(CONFIG_XENO_OPT_SPINLOCK_DEBUG)
 xnlock_t nklock = XNARCH_LOCK_UNLOCKED;
 #endif /* CONFIG_SMP */

@@ -3431,6 +3431,6 @@
 EXPORT_SYMBOL(nkclock);
 EXPORT_SYMBOL(nkpod);
 
-#ifdef CONFIG_SMP
+#if defined(CONFIG_SMP) || defined(CONFIG_XENO_OPT_SPINLOCK_DEBUG)
 EXPORT_SYMBOL(nklock);
 #endif /* CONFIG_SMP */

nucleus/module.c +14 ~~-10~~

Index: ksrc/nucleus/module.c
===================================================================
@@ -375,7 +375,7 @@
     .release = seq_release_private,
 };
 
-#ifdef CONFIG_SMP
+#if defined(CONFIG_SMP) || defined(CONFIG_XENO_OPT_SPINLOCK_DEBUG)
 
 xnlockinfo_t xnlock_stats[RTHAL_NR_CPUS];

@@ -405,12 +405,16 @@
         p += sprintf(p,
                      "  longest locked section: %llu ns\n"
                      "  spinning time: %llu ns\n"
-                     "  section entry: %s:%d (%s)\n",
+                     "  section entry: %s:%d (%s)\n"
+                     "  section exit: %s:%d (%s)\n",
                      xnarch_tsc_to_ns(lockinfo.lock_time),
                      xnarch_tsc_to_ns(lockinfo.spin_time),
-                     lockinfo.file,
-                     lockinfo.line,
-                     lockinfo.function);
+                     lockinfo.get_file,
+                     lockinfo.get_line,
+                     lockinfo.get_function,
+                     lockinfo.put_file,
+                     lockinfo.put_line,
+                     lockinfo.put_function);
     }
 
     len = p - page - off;

@@ -425,7 +429,7 @@
 
 EXPORT_SYMBOL(xnlock_stats);
 
-#endif /* CONFIG_SMP */
+#endif /* CONFIG_SMP || CONFIG_XENO_OPT_SPINLOCK_DEBUG */
 
 #endif /* CONFIG_XENO_OPT_STATS */

@@ -612,13 +616,13 @@
 		  &stat_seq_operations,
 		  0,
 		  rthal_proc_root);
-#ifdef CONFIG_SMP
+#if defined(CONFIG_SMP) || defined(CONFIG_XENO_OPT_SPINLOCK_DEBUG)
     add_proc_leaf("lock",
 		  &lock_read_proc,
 		  NULL,
 		  NULL,
 		  rthal_proc_root);
-#endif /* CONFIG_SMP */
+#endif /* CONFIG_SMP || CONFIG_XENO_OPT_SPINLOCK_DEBUG */
 
 #endif /* CONFIG_XENO_OPT_STATS */

@@ -675,9 +679,9 @@
     remove_proc_entry("sched",rthal_proc_root);
 #ifdef CONFIG_XENO_OPT_STATS
     remove_proc_entry("stat",rthal_proc_root);
-#ifdef CONFIG_SMP
+#if defined(CONFIG_SMP) || defined(CONFIG_XENO_OPT_SPINLOCK_DEBUG)
     remove_proc_entry("lock",rthal_proc_root);
-#endif /* CONFIG_SMP */
+#endif /* CONFIG_SMP || CONFIG_XENO_OPT_SPINLOCK_DEBUG */
 #endif /* CONFIG_XENO_OPT_STATS */
 }