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
Index: include/asm-ia64/system.h
===================================================================
--- include/asm-ia64/system.h   (revision 202)
+++ include/asm-ia64/system.h   (working copy)
@@ -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;
Index: include/asm-generic/system.h
===================================================================
--- include/asm-generic/system.h        (revision 202)
+++ include/asm-generic/system.h        (working copy)
@@ -54,16 +54,20 @@
 #define splget(x)   rthal_local_irq_flags(x)
 #define splsync(x)  rthal_local_irq_sync(x)
 
-#if defined(CONFIG_SMP) && \
-    (defined(CONFIG_XENO_OPT_STATS) || defined(CONFIG_XENO_OPT_DEBUG))
+/*#if defined(CONFIG_SMP) && \
+    (defined(CONFIG_XENO_OPT_STATS) || defined(CONFIG_XENO_OPT_DEBUG))*/
+#ifdef CONFIG_XENO_OPT_SPINLOCK_DEBUG
 
 typedef struct {
 
         unsigned long long spin_time;
         unsigned long long lock_time;
-        const char *file;
-        const char *function;
-        unsigned line;
+        const char *get_file;
+        const char *get_function;
+        unsigned get_line;
+        const char *put_file;
+        const char *put_function;
+        unsigned put_line;
 
 } xnlockinfo_t;
 
@@ -89,9 +93,9 @@
         0LL,                                    \
 }
 
-#define CONFIG_XENO_SPINLOCK_DEBUG  1
+//#define CONFIG_XENO_SPINLOCK_DEBUG  1
 
-#else /* !(CONFIG_XENO_OPT_STATS && CONFIG_SMP) */
+#else /* !CONFIG_XENO_OPT_SPINLOCK_DEBUG */
 
 typedef struct { volatile unsigned long lock; } xnlock_t;
 
@@ -197,14 +201,17 @@
     return !!s;
 }
 
-#ifdef CONFIG_SMP
+#if defined(CONFIG_SMP) || defined(CONFIG_XENO_OPT_SPINLOCK_DEBUG)
 
-#ifdef CONFIG_XENO_SPINLOCK_DEBUG
+#ifdef CONFIG_XENO_OPT_SPINLOCK_DEBUG
 #define xnlock_get_irqsave(lock,x) \
     ((x) = __xnlock_get_irqsave(lock, __FILE__, __LINE__,__FUNCTION__))
-#else /* !CONFIG_XENO_SPINLOCK_DEBUG */
+#define xnlock_put_irqrestore(lock,x) \
+    __xnlock_put_irqrestore(lock, x, __FILE__, __LINE__,__FUNCTION__)
+#else /* !CONFIG_XENO_OPT_SPINLOCK_DEBUG */
 #define xnlock_get_irqsave(lock,x)  ((x) = __xnlock_get_irqsave(lock))
-#endif /* CONFIG_XENO_SPINLOCK_DEBUG */
+#define xnlock_put_irqrestore(lock,x) __xnlock_put_irqrestore(lock,x)
+#endif /* CONFIG_XENO_OPT_SPINLOCK_DEBUG */
 #define xnlock_clear_irqoff(lock)   xnlock_put_irqrestore(lock,1)
 #define xnlock_clear_irqon(lock)    xnlock_put_irqrestore(lock,0)
 
@@ -213,7 +220,7 @@
     *lock = XNARCH_LOCK_UNLOCKED;
 }
 
-#ifdef CONFIG_XENO_SPINLOCK_DEBUG
+#ifdef CONFIG_XENO_OPT_SPINLOCK_DEBUG
 
 #define XNARCH_DEBUG_SPIN_LIMIT 3000000
 
@@ -223,10 +230,10 @@
                                           const char *function)
 {
     unsigned spin_count = 0;
-#else /* !CONFIG_XENO_SPINLOCK_DEBUG */
+#else /* !CONFIG_XENO_OPT_SPINLOCK_DEBUG */
 static inline spl_t __xnlock_get_irqsave (xnlock_t *lock)
 {
-#endif /* CONFIG_XENO_SPINLOCK_DEBUG */
+#endif /* CONFIG_XENO_OPT_SPINLOCK_DEBUG */
     rthal_declare_cpuid;
     unsigned long flags;
 
@@ -236,9 +243,9 @@
 
     if (!test_and_set_bit(cpuid,&lock->lock))
         {
-#ifdef CONFIG_XENO_SPINLOCK_DEBUG
+#ifdef CONFIG_XENO_OPT_SPINLOCK_DEBUG
         unsigned long long lock_date = rthal_rdtsc();
-#endif /* CONFIG_XENO_SPINLOCK_DEBUG */
+#endif /* CONFIG_XENO_OPT_SPINLOCK_DEBUG */
         while (test_and_set_bit(BITS_PER_LONG - 1,&lock->lock))
             /* Use an non-locking test in the inner loop, as Linux'es
                bit_spin_lock. */
@@ -246,7 +253,7 @@
                 {
                 cpu_relax();
 
-#ifdef CONFIG_XENO_SPINLOCK_DEBUG
+#ifdef CONFIG_XENO_OPT_SPINLOCK_DEBUG
                 if (++spin_count == XNARCH_DEBUG_SPIN_LIMIT)
                     {
                     rthal_emergency_console();
@@ -260,17 +267,17 @@
                     for (;;)
                         cpu_relax();
                     }
-#endif /* CONFIG_XENO_SPINLOCK_DEBUG */
+#endif /* CONFIG_XENO_OPT_SPINLOCK_DEBUG */
                 }
 
-#ifdef CONFIG_XENO_SPINLOCK_DEBUG
+#ifdef CONFIG_XENO_OPT_SPINLOCK_DEBUG
         lock->spin_time = rthal_rdtsc() - lock_date;
         lock->lock_date = lock_date;
         lock->file = file;
         lock->function = function;
         lock->line = line;
         lock->cpu = cpuid;
-#endif /* CONFIG_XENO_SPINLOCK_DEBUG */
+#endif /* CONFIG_XENO_OPT_SPINLOCK_DEBUG */
         }
     else
         flags |= 2;
@@ -278,8 +285,15 @@
     return flags;
 }
 
-static inline void xnlock_put_irqrestore (xnlock_t *lock, spl_t flags)
-
+#ifdef CONFIG_XENO_OPT_SPINLOCK_DEBUG
+static inline void __xnlock_put_irqrestore (xnlock_t *lock,
+                                            spl_t flags,
+                                            const char *file,
+                                            unsigned line,
+                                            const char *function)
+#else /* !CONFIG_XENO_OPT_SPINLOCK_DEBUG */
+static inline void __xnlock_put_irqrestore (xnlock_t *lock, spl_t flags)
+#endif /* CONFIG_XENO_OPT_SPINLOCK_DEBUG */
 {
     if (!(flags & 2))
         {
@@ -299,15 +313,18 @@
                 {
                 xnlock_stats[cpuid].lock_time = lock_time;
                 xnlock_stats[cpuid].spin_time = lock->spin_time;
-                xnlock_stats[cpuid].file = lock->file;
-                xnlock_stats[cpuid].function = lock->function;
-                xnlock_stats[cpuid].line = lock->line;
+                xnlock_stats[cpuid].get_file = lock->file;
+                xnlock_stats[cpuid].get_function = lock->function;
+                xnlock_stats[cpuid].get_line = lock->line;
+                xnlock_stats[cpuid].put_file = file;
+                xnlock_stats[cpuid].put_function = function;
+                xnlock_stats[cpuid].put_line = line;
                 }
 #endif /* CONFIG_XENO_OPT_STATS */
 
             clear_bit(BITS_PER_LONG - 1,&lock->lock);
            }
-#ifdef CONFIG_XENO_SPINLOCK_DEBUG
+#ifdef CONFIG_XENO_OPT_SPINLOCK_DEBUG
         else
             {
             rthal_emergency_console();
@@ -325,7 +342,7 @@
     rthal_local_irq_restore(flags & 1);
 }
 
-#else /* !CONFIG_SMP */
+#else /* !(CONFIG_SMP || CONFIG_XENO_OPT_SPINLOCK_DEBUG) */
 
 #define xnlock_init(lock)              do { } while(0)
 #define xnlock_get_irqsave(lock,x)     rthal_local_irq_save(x)
@@ -333,7 +350,7 @@
 #define xnlock_clear_irqoff(lock)      rthal_local_irq_disable()
 #define xnlock_clear_irqon(lock)       rthal_local_irq_enable()
 
-#endif /* CONFIG_SMP */
+#endif /* CONFIG_SMP || CONFIG_XENO_OPT_SPINLOCK_DEBUG */
 
 #ifdef XENO_POD_MODULE
 
Index: include/rtdm/core.h
===================================================================
--- include/rtdm/core.h (revision 202)
+++ include/rtdm/core.h (working copy)
@@ -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;
Index: include/nucleus/heap.h
===================================================================
--- include/nucleus/heap.h      (revision 202)
+++ include/nucleus/heap.h      (working copy)
@@ -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 */
 
Index: include/nucleus/pod.h
===================================================================
--- include/nucleus/pod.h       (revision 202)
+++ include/nucleus/pod.h       (working copy)
@@ -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 */
 
Index: include/nucleus/queue.h
===================================================================
--- include/nucleus/queue.h     (revision 202)
+++ include/nucleus/queue.h     (working copy)
@@ -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 */
 
Index: ksrc/skins/posix/signal.c
===================================================================
--- ksrc/skins/posix/signal.c   (revision 202)
+++ ksrc/skins/posix/signal.c   (working copy)
@@ -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;
Index: ksrc/skins/rtdm/device.c
===================================================================
--- ksrc/skins/rtdm/device.c    (revision 202)
+++ ksrc/skins/rtdm/device.c    (working copy)
@@ -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 */
 
Index: ksrc/skins/rtdm/core.c
===================================================================
--- ksrc/skins/rtdm/core.c      (revision 202)
+++ ksrc/skins/rtdm/core.c      (working copy)
@@ -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 */
 
Index: ksrc/nucleus/Kconfig
===================================================================
--- ksrc/nucleus/Kconfig        (revision 202)
+++ ksrc/nucleus/Kconfig        (working copy)
@@ -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
Index: ksrc/nucleus/pod.c
===================================================================
--- ksrc/nucleus/pod.c  (revision 202)
+++ ksrc/nucleus/pod.c  (working copy)
@@ -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 */
Index: ksrc/nucleus/module.c
===================================================================
--- ksrc/nucleus/module.c       (revision 202)
+++ ksrc/nucleus/module.c       (working copy)
@@ -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 */
 }
 

Attachment: signature.asc
Description: OpenPGP digital signature

Reply via email to