[v5,5/5] xen: add function name to lock profiling data
diff mbox series

Message ID 20190912132813.6509-6-jgross@suse.com
State New
Headers show
Series
  • enhance lock debugging
Related show

Commit Message

Juergen Gross Sept. 12, 2019, 1:28 p.m. UTC
A spinlock defined via DEFINE_SPINLOCK() as a static variable local to
a function shows up in lock profiling just with its local variable
name. This results in multiple locks just named "lock".

In order to be able to distinguish those locks in the lock profiling
output add the function name to struct lock_profile and initialize it
with __PRETTY_FUNCTION__ (__func__ or __FUNCTION__ are not usable
outside of functions with some compilers).

Signed-off-by: Juergen Gross <jgross@suse.com>
---
 xen/common/spinlock.c      | 16 +++++++++++++---
 xen/include/xen/spinlock.h |  4 +++-
 2 files changed, 16 insertions(+), 4 deletions(-)

Comments

Jan Beulich Sept. 13, 2019, 9:53 a.m. UTC | #1
On 12.09.2019 15:28, Juergen Gross wrote:
> --- a/xen/common/spinlock.c
> +++ b/xen/common/spinlock.c
> @@ -348,6 +348,7 @@ static s_time_t lock_profile_start;
>  static struct lock_profile_anc *lock_profile_ancs;
>  static struct lock_profile_qhead lock_profile_glb_q;
>  static spinlock_t lock_profile_lock = SPIN_LOCK_UNLOCKED;
> +static const char *lock_profile_nofunc = __PRETTY_FUNCTION__;

const also for the variable itself?

> @@ -371,8 +372,10 @@ static void spinlock_profile_print_elem(struct lock_profile *data,
>      printk("%s ", type);
>      if ( idx != LOCKPROF_IDX_NONE )
>          printk("%d ", idx);
> -    printk("%s: addr=%p, lockval=%08x, ", data->name, lock,
> -           lock->tickets.head_tail);
> +    printk("%s", data->name);
> +    if ( data->func && strcmp(data->func, lock_profile_nofunc) )
> +        printk("@%s", data->func);
> +    printk(": addr=%p, lockval=%08x, ", lock, lock->tickets.head_tail);

As long as this is used from a key handler only, I guess the
splitting of the printk()s isn't much of a problem.

> @@ -427,7 +430,14 @@ static void spinlock_profile_ucopy_elem(struct lock_profile *data,
>  
>      if ( p->pc->nr_elem < p->pc->max_elem )
>      {
> -        safe_strcpy(elem.name, data->name);
> +        if ( data->func && strcmp(data->func, lock_profile_nofunc) )
> +        {
> +            snprintf(elem.name, sizeof(elem.name), "%s@%s", data->name,
> +                     data->func);
> +            elem.name[sizeof(elem.name) - 1] = 0;

This isn't needed after snprintf(), is it?

With the two suggested adjustments (provided you agree, and
which could probably be done while committing)
Reviewed-by: Jan Beulich <jbeulich@suse.com>

Jan
Juergen Gross Sept. 13, 2019, 10:21 a.m. UTC | #2
On 13.09.19 11:53, Jan Beulich wrote:
> On 12.09.2019 15:28, Juergen Gross wrote:
>> --- a/xen/common/spinlock.c
>> +++ b/xen/common/spinlock.c
>> @@ -348,6 +348,7 @@ static s_time_t lock_profile_start;
>>   static struct lock_profile_anc *lock_profile_ancs;
>>   static struct lock_profile_qhead lock_profile_glb_q;
>>   static spinlock_t lock_profile_lock = SPIN_LOCK_UNLOCKED;
>> +static const char *lock_profile_nofunc = __PRETTY_FUNCTION__;
> 
> const also for the variable itself?
> 
>> @@ -371,8 +372,10 @@ static void spinlock_profile_print_elem(struct lock_profile *data,
>>       printk("%s ", type);
>>       if ( idx != LOCKPROF_IDX_NONE )
>>           printk("%d ", idx);
>> -    printk("%s: addr=%p, lockval=%08x, ", data->name, lock,
>> -           lock->tickets.head_tail);
>> +    printk("%s", data->name);
>> +    if ( data->func && strcmp(data->func, lock_profile_nofunc) )
>> +        printk("@%s", data->func);
>> +    printk(": addr=%p, lockval=%08x, ", lock, lock->tickets.head_tail);
> 
> As long as this is used from a key handler only, I guess the
> splitting of the printk()s isn't much of a problem.
> 
>> @@ -427,7 +430,14 @@ static void spinlock_profile_ucopy_elem(struct lock_profile *data,
>>   
>>       if ( p->pc->nr_elem < p->pc->max_elem )
>>       {
>> -        safe_strcpy(elem.name, data->name);
>> +        if ( data->func && strcmp(data->func, lock_profile_nofunc) )
>> +        {
>> +            snprintf(elem.name, sizeof(elem.name), "%s@%s", data->name,
>> +                     data->func);
>> +            elem.name[sizeof(elem.name) - 1] = 0;
> 
> This isn't needed after snprintf(), is it?
> 
> With the two suggested adjustments (provided you agree, and
> which could probably be done while committing)
> Reviewed-by: Jan Beulich <jbeulich@suse.com>

Yes, I agree, thanks


Juergen

Patch
diff mbox series

diff --git a/xen/common/spinlock.c b/xen/common/spinlock.c
index 673ef168da..3147bc3a7a 100644
--- a/xen/common/spinlock.c
+++ b/xen/common/spinlock.c
@@ -348,6 +348,7 @@  static s_time_t lock_profile_start;
 static struct lock_profile_anc *lock_profile_ancs;
 static struct lock_profile_qhead lock_profile_glb_q;
 static spinlock_t lock_profile_lock = SPIN_LOCK_UNLOCKED;
+static const char *lock_profile_nofunc = __PRETTY_FUNCTION__;
 
 static void spinlock_profile_iterate(lock_profile_subfunc *sub, void *par)
 {
@@ -371,8 +372,10 @@  static void spinlock_profile_print_elem(struct lock_profile *data,
     printk("%s ", type);
     if ( idx != LOCKPROF_IDX_NONE )
         printk("%d ", idx);
-    printk("%s: addr=%p, lockval=%08x, ", data->name, lock,
-           lock->tickets.head_tail);
+    printk("%s", data->name);
+    if ( data->func && strcmp(data->func, lock_profile_nofunc) )
+        printk("@%s", data->func);
+    printk(": addr=%p, lockval=%08x, ", lock, lock->tickets.head_tail);
     if ( lock->debug.cpu == SPINLOCK_NO_CPU )
         printk("not locked\n");
     else
@@ -427,7 +430,14 @@  static void spinlock_profile_ucopy_elem(struct lock_profile *data,
 
     if ( p->pc->nr_elem < p->pc->max_elem )
     {
-        safe_strcpy(elem.name, data->name);
+        if ( data->func && strcmp(data->func, lock_profile_nofunc) )
+        {
+            snprintf(elem.name, sizeof(elem.name), "%s@%s", data->name,
+                     data->func);
+            elem.name[sizeof(elem.name) - 1] = 0;
+        }
+        else
+            safe_strcpy(elem.name, data->name);
         safe_strcpy(elem.type, type);
         elem.idx = idx;
         elem.lock_cnt = data->lock_cnt;
diff --git a/xen/include/xen/spinlock.h b/xen/include/xen/spinlock.h
index 401cc345fe..49b29f7c54 100644
--- a/xen/include/xen/spinlock.h
+++ b/xen/include/xen/spinlock.h
@@ -78,6 +78,7 @@  struct spinlock;
 struct lock_profile {
     struct lock_profile *next;       /* forward link */
     char                *name;       /* lock name */
+    const char          *func;       /* function name */
     struct spinlock     *lock;       /* the lock itself */
     u64                 lock_cnt;    /* # of complete locking ops */
     u64                 block_cnt;   /* # of complete wait for lock */
@@ -92,7 +93,8 @@  struct lock_profile_qhead {
     int32_t                   idx;     /* index for printout */
 };
 
-#define _LOCK_PROFILE(name) { 0, #name, &name, 0, 0, 0, 0, 0 }
+#define _LOCK_PROFILE(name) { 0, #name, __PRETTY_FUNCTION__, &name,           \
+                              0, 0, 0, 0, 0 }
 #define _LOCK_PROFILE_PTR(name)                                               \
     static struct lock_profile * const __lock_profile_##name                  \
     __used_section(".lockprofile.data") =                                     \