spinlocks: print lock profile info in panic()

Print the lock profile data when the system crashes and add some more
information for each lock data (lock address, cpu holding the lock).
While at it use the PRI_stime format specifier for printing time data.

This is especially beneficial for watchdog triggered crashes in case
of deadlocks.

In order to have the cpu holding the lock available let the
lock profile config option select DEBUG_LOCKS.

As printing the lock profile data will make use of locking, too, we
need to disable spinlock debugging before calling
spinlock_profile_printall() from panic().

While at it remove a superfluous #ifdef CONFIG_LOCK_PROFILE and rename
CONFIG_LOCK_PROFILE to CONFIG_DEBUG_LOCK_PROFILE.

Also move the .lockprofile.data section to init area in linker scripts
as the data is no longer needed after boot.

Signed-off-by: Juergen Gross <jgross@suse.com>
Acked-by: Jan Beulich <jbeulich@suse.com>

diff --git a/xen/Kconfig.debug b/xen/Kconfig.debug
index 1faaa3ba6a7f8a77f9caad08b02f0755f9e286eb..22573e74dbef749917441ab4dcbbd4fac42510d2 100644 (file)
--- a/xen/Kconfig.debug
+++ b/xen/Kconfig.debug
@@ -44,8 +44,9 @@ config COVERAGE
 
          If unsure, say N here.
 
-config LOCK_PROFILE
+config DEBUG_LOCK_PROFILE
        bool "Lock Profiling"
+       select DEBUG_LOCKS
        ---help---
          Lock profiling allows you to see how often locks are taken and blocked.
          You can use serial console to print (and reset) using 'l' and 'L'

diff --git a/xen/arch/arm/xen.lds.S b/xen/arch/arm/xen.lds.S
index 16ce1dd01e24b1c483f505708a7b5dc11595904e..a497f6a48d8204a6477772264ea5866c3531ad67 100644 (file)
--- a/xen/arch/arm/xen.lds.S
+++ b/xen/arch/arm/xen.lds.S
@@ -54,12 +54,6 @@ SECTIONS
        *(.data.rel.ro)
        *(.data.rel.ro.*)
 
-#ifdef CONFIG_LOCK_PROFILE
-       . = ALIGN(POINTER_ALIGN);
-       __lock_profile_start = .;
-       *(.lockprofile.data)
-       __lock_profile_end = .;
-#endif
        . = ALIGN(POINTER_ALIGN);
        __param_start = .;
        *(.data.param)
@@ -173,6 +167,13 @@ SECTIONS
        . = ALIGN(4);
        *(.altinstr_replacement)
 
+#ifdef CONFIG_DEBUG_LOCK_PROFILE
+       . = ALIGN(POINTER_ALIGN);
+       __lock_profile_start = .;
+       *(.lockprofile.data)
+       __lock_profile_end = .;
+#endif
+
        *(.init.data)
        *(.init.data.rel)
        *(.init.data.rel.*)

diff --git a/xen/arch/x86/domain.c b/xen/arch/x86/domain.c
index 4b0ad5e15da3d8fe564f299cedeb61b1fc1e7794..dbdf6b1bc247801d53f72a73fc4cca64a52c067c 100644 (file)
--- a/xen/arch/x86/domain.c
+++ b/xen/arch/x86/domain.c
@@ -305,7 +305,7 @@ struct domain *alloc_domain_struct(void)
 #endif
 
 
-#ifndef CONFIG_LOCK_PROFILE
+#ifndef CONFIG_DEBUG_LOCK_PROFILE
     BUILD_BUG_ON(sizeof(*d) > PAGE_SIZE);
 #endif
     d = alloc_xenheap_pages(order, MEMF_bits(bits));

diff --git a/xen/arch/x86/xen.lds.S b/xen/arch/x86/xen.lds.S
index 87fa02b9b54df3081d8d52057c743b9e7c4f721a..111edb5360ac4a441b8ce907cc2b6857c89f41ca 100644 (file)
--- a/xen/arch/x86/xen.lds.S
+++ b/xen/arch/x86/xen.lds.S
@@ -128,12 +128,6 @@ SECTIONS
        *(.ex_table.pre)
        __stop___pre_ex_table = .;
 
-#ifdef CONFIG_LOCK_PROFILE
-       . = ALIGN(POINTER_ALIGN);
-       __lock_profile_start = .;
-       *(.lockprofile.data)
-       __lock_profile_end = .;
-#endif
        . = ALIGN(POINTER_ALIGN);
        __param_start = .;
        *(.data.param)
@@ -251,6 +245,13 @@ SECTIONS
         *(.altinstructions)
         __alt_instructions_end = .;
 
+#ifdef CONFIG_DEBUG_LOCK_PROFILE
+       . = ALIGN(POINTER_ALIGN);
+       __lock_profile_start = .;
+       *(.lockprofile.data)
+       __lock_profile_end = .;
+#endif
+
        . = ALIGN(8);
        __ctors_start = .;
        *(.ctors)

diff --git a/xen/common/keyhandler.c b/xen/common/keyhandler.c
index 57b360ee4b88c8750cf205991116686cc5dc0677..c36baa4dff49c85ab452545ab7d61648d9288330 100644 (file)
--- a/xen/common/keyhandler.c
+++ b/xen/common/keyhandler.c
@@ -62,7 +62,7 @@ static struct keyhandler {
     KEYHANDLER('P', perfc_reset, "reset performance counters", 0),
 #endif
 
-#ifdef CONFIG_LOCK_PROFILE
+#ifdef CONFIG_DEBUG_LOCK_PROFILE
     KEYHANDLER('l', spinlock_profile_printall, "print lock profile info", 1),
     KEYHANDLER('L', spinlock_profile_reset, "reset lock profile info", 0),
 #endif

diff --git a/xen/common/spinlock.c b/xen/common/spinlock.c
index 6ca1b38f844b3db523bfbaf9c02e6bb72a8bae61..ed69f0a4d2c1e829debda8b211332de8b72c496e 100644 (file)
--- a/xen/common/spinlock.c
+++ b/xen/common/spinlock.c
@@ -108,7 +108,7 @@ void spin_debug_disable(void)
 
 #endif
 
-#ifdef CONFIG_LOCK_PROFILE
+#ifdef CONFIG_DEBUG_LOCK_PROFILE
 
 #define LOCK_PROFILE_REL                                                     \
     if (lock->profile)                                                       \
@@ -245,7 +245,7 @@ int _spin_trylock(spinlock_t *lock)
                  old.head_tail, new.head_tail) != old.head_tail )
         return 0;
     got_lock(&lock->debug);
-#ifdef CONFIG_LOCK_PROFILE
+#ifdef CONFIG_DEBUG_LOCK_PROFILE
     if (lock->profile)
         lock->profile->time_locked = NOW();
 #endif
@@ -260,7 +260,7 @@ int _spin_trylock(spinlock_t *lock)
 void _spin_barrier(spinlock_t *lock)
 {
     spinlock_tickets_t sample;
-#ifdef CONFIG_LOCK_PROFILE
+#ifdef CONFIG_DEBUG_LOCK_PROFILE
     s_time_t block = NOW();
 #endif
 
@@ -271,7 +271,7 @@ void _spin_barrier(spinlock_t *lock)
     {
         while ( observe_head(&lock->tickets) == sample.head )
             arch_lock_relax();
-#ifdef CONFIG_LOCK_PROFILE
+#ifdef CONFIG_DEBUG_LOCK_PROFILE
         if ( lock->profile )
         {
             lock->profile->time_block += NOW() - block;
@@ -330,7 +330,7 @@ void _spin_unlock_recursive(spinlock_t *lock)
     }
 }
 
-#ifdef CONFIG_LOCK_PROFILE
+#ifdef CONFIG_DEBUG_LOCK_PROFILE
 
 struct lock_profile_anc {
     struct lock_profile_qhead *head_q;   /* first head of this type */
@@ -365,14 +365,19 @@ static void spinlock_profile_iterate(lock_profile_subfunc *sub, void *par)
 static void spinlock_profile_print_elem(struct lock_profile *data,
     int32_t type, int32_t idx, void *par)
 {
-    if ( type == LOCKPROF_TYPE_GLOBAL )
-        printk("%s %s:\n", lock_profile_ancs[type].name, data->name);
+    struct spinlock *lock = data->lock;
+
+    printk("%s ", lock_profile_ancs[type].name);
+    if ( type != LOCKPROF_TYPE_GLOBAL )
+        printk("%d ", idx);
+    printk("%s: addr=%p, lockval=%08x, ", data->name, lock,
+           lock->tickets.head_tail);
+    if ( lock->debug.cpu == SPINLOCK_NO_CPU )
+        printk("not locked\n");
     else
-        printk("%s %d %s:\n", lock_profile_ancs[type].name, idx, data->name);
-    printk("  lock:%12"PRId64"(%08X:%08X), block:%12"PRId64"(%08X:%08X)\n",
-           data->lock_cnt, (u32)(data->time_hold >> 32), (u32)data->time_hold,
-           data->block_cnt, (u32)(data->time_block >> 32),
-           (u32)data->time_block);
+        printk("cpu=%d\n", lock->debug.cpu);
+    printk("  lock:%" PRId64 "(%" PRI_stime "), block:%" PRId64 "(%" PRI_stime ")\n",
+           data->lock_cnt, data->time_hold, data->block_cnt, data->time_block);
 }
 
 void spinlock_profile_printall(unsigned char key)
@@ -491,7 +496,6 @@ void _lock_profile_deregister_struct(
     spin_unlock(&lock_profile_lock);
 }
 
-#ifdef CONFIG_LOCK_PROFILE
 static int __init lock_prof_init(void)
 {
     struct lock_profile **q;
@@ -510,6 +514,5 @@ static int __init lock_prof_init(void)
     return 0;
 }
 __initcall(lock_prof_init);
-#endif
 
-#endif /* LOCK_PROFILE */
+#endif /* CONFIG_DEBUG_LOCK_PROFILE */

diff --git a/xen/common/sysctl.c b/xen/common/sysctl.c
index 92b4ea0d21a33ca0162396b6f727da25893e8ea4..c8f86424d54befe8e2447f7ff1892847261316cd 100644 (file)
--- a/xen/common/sysctl.c
+++ b/xen/common/sysctl.c
@@ -119,7 +119,7 @@ long do_sysctl(XEN_GUEST_HANDLE_PARAM(xen_sysctl_t) u_sysctl)
         break;
 #endif
 
-#ifdef CONFIG_LOCK_PROFILE
+#ifdef CONFIG_DEBUG_LOCK_PROFILE
     case XEN_SYSCTL_lockprof_op:
         ret = spinlock_profile_control(&op->u.lockprof_op);
         break;

diff --git a/xen/drivers/char/console.c b/xen/drivers/char/console.c
index 7f29190eafdbce7e67672129f41421103ca15057..e133534be7e63cb67b8245d45ca30b58617474ee 100644 (file)
--- a/xen/drivers/char/console.c
+++ b/xen/drivers/char/console.c
@@ -1170,7 +1170,9 @@ void panic(const char *fmt, ...)
     unsigned long flags;
     static DEFINE_SPINLOCK(lock);
     static char buf[128];
-    
+
+    spin_debug_disable();
+    spinlock_profile_printall('\0');
     debugtrace_dump();
 
     /* Protects buf[] and ensure multi-line message prints atomically. */

diff --git a/xen/include/xen/spinlock.h b/xen/include/xen/spinlock.h
index 79b582e05d08e8d21e7ebc830d117c3d5958ea28..468b9ac9ef639cf66d807d97939c6c61c71ddc64 100644 (file)
--- a/xen/include/xen/spinlock.h
+++ b/xen/include/xen/spinlock.h
@@ -1,6 +1,7 @@
 #ifndef __SPINLOCK_H__
 #define __SPINLOCK_H__
 
+#include <xen/time.h>
 #include <asm/system.h>
 #include <asm/spinlock.h>
 #include <asm/types.h>
@@ -29,7 +30,7 @@ union lock_debug { };
 #define spin_debug_disable() ((void)0)
 #endif
 
-#ifdef CONFIG_LOCK_PROFILE
+#ifdef CONFIG_DEBUG_LOCK_PROFILE
 
 #include <public/sysctl.h>
 
@@ -75,9 +76,9 @@ struct lock_profile {
     struct spinlock     *lock;       /* the lock itself */
     u64                 lock_cnt;    /* # of complete locking ops */
     u64                 block_cnt;   /* # of complete wait for lock */
-    s64                 time_hold;   /* cumulated lock time */
-    s64                 time_block;  /* cumulated wait time */
-    s64                 time_locked; /* system time of last locking */
+    s_time_t            time_hold;   /* cumulated lock time */
+    s_time_t            time_block;  /* cumulated wait time */
+    s_time_t            time_locked; /* system time of last locking */
 };
 
 struct lock_profile_qhead {
@@ -133,6 +134,7 @@ struct lock_profile_qhead { };
 #define spin_lock_init_prof(s, l) spin_lock_init(&((s)->l))
 #define lock_profile_register_struct(type, ptr, idx, print)
 #define lock_profile_deregister_struct(type, ptr)
+#define spinlock_profile_printall(key)
 
 #endif
 
@@ -154,7 +156,7 @@ typedef struct spinlock {
     u16 recurse_cnt:SPINLOCK_RECURSE_BITS;
 #define SPINLOCK_MAX_RECURSE   ((1u << SPINLOCK_RECURSE_BITS) - 1)
     union lock_debug debug;
-#ifdef CONFIG_LOCK_PROFILE
+#ifdef CONFIG_DEBUG_LOCK_PROFILE
     struct lock_profile *profile;
 #endif
 } spinlock_t;