[PATCH] rt_spin_lock: To list the correct owner of rt_spin_lock

[PATCH] rt_spin_lock: To list the correct owner of rt_spin_lock

[Mintu Patel]

   rt_spin_lock is actually mutex on RT Kernel so it goes for contention
   for lock. Currently owners of rt_spin_lock are decided before actual
   acquiring of lock. This patch would depict the correct owner of
   rt_spin_lock. The patch would help in solving crashes and deadlock
   due to race condition of lock

acquiring rt_spin_lock        acquired the lock       released the lock
                    <-------->                <------->
                    contention period         Held period

Thread1                                 Thread2

__try_to_take_rt_mutex+0x95c+0x74   enqueue_task_dl+0x8cc/0x8dc
rt_spin_lock_slowlock_locked+0xac+2 rt_mutex_setprio+0x28c/0x574
rt_spin_lock_slowlock+0x5c/0x90     task_blocks_rt_mutex+0x240/0x310
rt_spin_lock+0x58/0x5c              rt_spin_lock_slowlock_locked+0xac/0x2
driverA_acquire_lock+0x28/0x56      rt_spin_lock_slowlock+0x5c/0x90
				    rt_spin_lock+0x58/0x5c
                                    driverB_acquire_lock+0x48/0x6c

As per above call traces sample, Thread1 acquired the rt_spin_lock and
went to critical section on the other hand Thread2 kept trying to acquire
the same rt_spin_lock held by Thread1 ie contention period is too high.
Finally Thread2 entered to dl queue due to high held time of the lock by
Thread1. The below patch would help us to know the correct owner of
rt_spin_lock and point us the driver's critical section. Respective driver
need to be debugged for longer held period of lock.

   ex: cat /sys/kernel/debug/tracing/trace

   kworker/u13:0-150   [003] .....11   202.761025: rt_spinlock_acquire:
Process: kworker/u13:0 is acquiring lock: &kbdev->hwaccess_lock
   kworker/u13:0-150   [003] .....11   202.761039: rt_spinlock_acquired:
Process: kworker/u13:0 has acquired lock: &kbdev->hwaccess_lock
   kworker/u13:0-150   [003] .....11   202.761042: rt_spinlock_released:
Process: kworker/u13:0 has released lock: &kbdev->hwaccess_lock

Signed-off-by: Mintu Patel <mintupatel89@gmail.com>
Signed-off-by: Chinmoy Ghosh <chinmoyghosh2001@gmail.com>
Signed-off-by: Vishal Badole <badolevishal1116@gmail.com>
Signed-off-by: Vimal Kumar <vimal.kumar32@gmail.com>
---
 include/trace/events/lock.h | 60 +++++++++++++++++++++++++++++++++++++
 kernel/locking/rtmutex.c    | 10 +++++++
 2 files changed, 70 insertions(+)

diff --git a/include/trace/events/lock.h b/include/trace/events/lock.h
index d7512129a324..8bb21b31c9a9 100644
--- a/include/trace/events/lock.h
+++ b/include/trace/events/lock.h
@@ -36,6 +36,66 @@ TRACE_EVENT(lock_acquire,
 		  __get_str(name))
 );
 
+TRACE_EVENT(rt_spinlock_acquire,
+
+	TP_PROTO(struct lockdep_map *lock, struct task_struct *pname),
+
+	TP_ARGS(lock, pname),
+
+	TP_STRUCT__entry(
+		__string(name, lock->name)
+		__string(process_name, pname->comm)
+	),
+
+	TP_fast_assign(
+		__assign_str(name, lock->name);
+		__assign_str(process_name, pname->comm);
+	),
+
+	TP_printk("Process: %s is acquiring lock: %s",  __get_str(process_name),
+		  __get_str(name))
+);
+
+TRACE_EVENT(rt_spinlock_acquired,
+
+	TP_PROTO(struct lockdep_map *lock, struct task_struct *pname),
+
+	TP_ARGS(lock, pname),
+
+	TP_STRUCT__entry(
+		__string(name, lock->name)
+		__string(process_name, pname->comm)
+	),
+
+	TP_fast_assign(
+		__assign_str(name, lock->name);
+		__assign_str(process_name, pname->comm);
+	),
+
+	TP_printk("Process: %s has acquired lock: %s", __get_str(process_name),
+		  __get_str(name))
+);
+
+TRACE_EVENT(rt_spinlock_released,
+
+	TP_PROTO(struct lockdep_map *lock, struct task_struct *pname),
+
+	TP_ARGS(lock, pname),
+
+	TP_STRUCT__entry(
+		__string(name, lock->name)
+		__string(process_name, pname->comm)
+	),
+
+	TP_fast_assign(
+		__assign_str(name, lock->name);
+		__assign_str(process_name, pname->comm);
+	),
+
+	TP_printk("Process: %s has released lock: %s", __get_str(process_name),
+		  __get_str(name))
+);
+
 DECLARE_EVENT_CLASS(lock,
 
 	TP_PROTO(struct lockdep_map *lock, unsigned long ip),
diff --git a/kernel/locking/rtmutex.c b/kernel/locking/rtmutex.c
index 08e233b7dc21..fb10c4e44f09 100644
--- a/kernel/locking/rtmutex.c
+++ b/kernel/locking/rtmutex.c
@@ -25,6 +25,7 @@
 #include <linux/timer.h>
 #include <linux/ww_mutex.h>
 #include <linux/blkdev.h>
+#include <trace/events/lock.h>
 
 #include "rtmutex_common.h"
 
@@ -1144,7 +1145,13 @@ void __lockfunc rt_spin_lock(spinlock_t *lock)
 	sleeping_lock_inc();
 	migrate_disable();
 	spin_acquire(&lock->dep_map, 0, 0, _RET_IP_);
+#ifdef CONFIG_RT_SPIN_LOCK_TRACING
+	trace_rt_spinlock_acquire(&lock->dep_map, current);
+#endif
 	rt_spin_lock_fastlock(&lock->lock, rt_spin_lock_slowlock);
+#ifdef CONFIG_RT_SPIN_LOCK_TRACING
+	trace_rt_spinlock_acquired(&lock->dep_map, current);
+#endif
 }
 EXPORT_SYMBOL(rt_spin_lock);
 
@@ -1168,6 +1175,9 @@ void __lockfunc rt_spin_unlock(spinlock_t *lock)
 {
 	/* NOTE: we always pass in '1' for nested, for simplicity */
 	spin_release(&lock->dep_map, 1, _RET_IP_);
+#ifdef CONFIG_RT_SPIN_LOCK_TRACING
+	trace_rt_spinlock_released(&lock->dep_map, current);
+#endif
 	rt_spin_lock_fastunlock(&lock->lock, rt_spin_lock_slowunlock);
 	migrate_enable();
 	sleeping_lock_dec();
-- 
2.25.1

Re: [PATCH] rt_spin_lock: To list the correct owner of rt_spin_lock

[Steven Rostedt]

On Sun, 19 Jun 2022 19:50:38 +0530
Mintu Patel <mintupatel89@gmail.com> wrote:

>    rt_spin_lock is actually mutex on RT Kernel so it goes for contention
>    for lock. Currently owners of rt_spin_lock are decided before actual
>    acquiring of lock. This patch would depict the correct owner of
>    rt_spin_lock. The patch would help in solving crashes and deadlock
>    due to race condition of lock
> 
> acquiring rt_spin_lock        acquired the lock       released the lock
>                     <-------->                <------->
>                     contention period         Held period
> 
> Thread1                             Thread2
> _try_to_take_rt_mutex+0x95c+0x74    enqueue_task_dl+0x8cc/0x8dc
> rt_spin_lock_slowlock_locked+0xac+2 rt_mutex_setprio+0x28c/0x574
> rt_spin_lock_slowlock+0x5c/0x90     task_blocks_rt_mutex+0x240/0x310
> rt_spin_lock+0x58/0x5c              rt_spin_lock_slowlock_locked+0xac/0x2
> driverA_acquire_lock+0x28/0x56      rt_spin_lock_slowlock+0x5c/0x90
> 				    rt_spin_lock+0x58/0x5c
>                                     driverB_acquire_lock+0x48/0x6c
> 
> As per above call traces sample, Thread1 acquired the rt_spin_lock and
> went to critical section on the other hand Thread2 kept trying to acquire
> the same rt_spin_lock held by Thread1 ie contention period is too high.
> Finally Thread2 entered to dl queue due to high held time of the lock by
> Thread1. The below patch would help us to know the correct owner of
> rt_spin_lock and point us the driver's critical section. Respective
> driver need to be debugged for longer held period of lock.
> 
>    ex: cat /sys/kernel/debug/tracing/trace
> 
>    kworker/u13:0-150   [003] .....11   202.761025: rt_spinlock_acquire:
> Process: kworker/u13:0 is acquiring lock: &kbdev->hwaccess_lock
>    kworker/u13:0-150   [003] .....11   202.761039: rt_spinlock_acquired:
> Process: kworker/u13:0 has acquired lock: &kbdev->hwaccess_lock
>    kworker/u13:0-150   [003] .....11   202.761042: rt_spinlock_released:
> Process: kworker/u13:0 has released lock: &kbdev->hwaccess_lock
> 
> Signed-off-by: Mintu Patel <mintupatel89@gmail.com>
> Signed-off-by: Chinmoy Ghosh <chinmoyghosh2001@gmail.com>
> Signed-off-by: Vishal Badole <badolevishal1116@gmail.com>
> Signed-off-by: Vimal Kumar <vimal.kumar32@gmail.com>
> ---
>  include/trace/events/lock.h | 59 +++++++++++++++++++++++++++++++++++++
>  kernel/locking/rtmutex.c    | 10 +++++++
>  2 files changed, 69 insertions(+)
> 
> diff --git a/include/trace/events/lock.h b/include/trace/events/lock.h
> index d7512129a324..c250a83ed995 100644
> --- a/include/trace/events/lock.h
> +++ b/include/trace/events/lock.h
> @@ -35,6 +35,65 @@ TRACE_EVENT(lock_acquire,
>  		  (__entry->flags & 2) ? "read " : "",
>  		  __get_str(name))
>  );
> +TRACE_EVENT(rt_spinlock_acquire,
> +
> +	TP_PROTO(struct lockdep_map *lock, struct task_struct *pname),
> +
> +	TP_ARGS(lock, pname),
> +
> +	TP_STRUCT__entry(
> +		__string(name, lock->name)
> +		__string(process_name, pname->comm)
> +	),
> +
> +	TP_fast_assign(
> +		__assign_str(name, lock->name);
> +		__assign_str(process_name, pname->comm);
> +	),
> +
> +	TP_printk("Process: %s is acquiring lock: %s",  __get_str(process_name),
> +		__get_str(name))
> +);
> +
> +TRACE_EVENT(rt_spinlock_acquired,
> +
> +	TP_PROTO(struct lockdep_map *lock, struct task_struct *pname),
> +
> +	TP_ARGS(lock, pname),
> +
> +	TP_STRUCT__entry(
> +		__string(name, lock->name)
> +		__string(process_name, pname->comm)
> +	),
> +
> +	TP_fast_assign(
> +		__assign_str(name, lock->name);
> +		__assign_str(process_name, pname->comm);
> +	),
> +
> +	TP_printk("Process: %s has acquired lock: %s", __get_str(process_name),
> +		__get_str(name))
> +);
> +
> +TRACE_EVENT(rt_spinlock_released,
> +
> +	TP_PROTO(struct lockdep_map *lock, struct task_struct *pname),
> +
> +	TP_ARGS(lock, pname),
> +
> +	TP_STRUCT__entry(
> +		__string(name, lock->name)
> +		__string(process_name, pname->comm)
> +	),
> +
> +	TP_fast_assign(
> +		__assign_str(name, lock->name);
> +		__assign_str(process_name, pname->comm);
> +	),
> +
> +	TP_printk("Process: %s has released lock: %s", __get_str(process_name),
> +		__get_str(name))
> +);

The above three are the same except for the TP_printk() please convert it to:

DECLARE_EVENT_CLASS(rt_lock_class,

	TP_PROTO(struct lockdep_map *lock, struct task_struct *pname),

	TP_ARGS(lock, pname),

	TP_STRUCT__entry(
		__string(name, lock->name)
		__string(process_name, pname->comm)
	),

	TP_fast_assign(
		__assign_str(name, lock->name);
		__assign_str(process_name, pname->comm);
	),

	TP_printk("Process: %s is acquiring lock: %s",  __get_str(process_name),
		__get_str(name))
);

/* Uses the tp_printk of the class */
DEFINE_EVENT(rt_lock_class, rt_spinlock_acquire,
	TP_PROTO(struct lockdep_map *lock, struct task_struct *pname),
	TP_ARGS(lock, pname));

DEFINE_EVENT_PRINT(rt_lock_class, rt_spinlock_acquired,
	TP_PROTO(struct lockdep_map *lock, struct task_struct *pname),
	TP_ARGS(lock, pname),
	TP_printk("Process: %s has acquired lock: %s", __get_str(process_name),
		__get_str(name));

DEFINE_EVENT_PRINT(rt_lock_class, rt_spinlock_released,
	TP_PROTO(struct lockdep_map *lock, struct task_struct *pname),
	TP_ARGS(lock, pname),
	TP_printk("Process: %s has released lock: %s", __get_str(process_name),
		__get_str(name));


>  
>  DECLARE_EVENT_CLASS(lock,
>  
> diff --git a/kernel/locking/rtmutex.c b/kernel/locking/rtmutex.c
> index 602eb7821a1b..f7cba05fbe74 100644
> --- a/kernel/locking/rtmutex.c
> +++ b/kernel/locking/rtmutex.c
> @@ -26,6 +26,7 @@
>  #include <linux/timer.h>
>  #include <linux/ww_mutex.h>
>  #include <linux/blkdev.h>
> +#include <trace/events/lock.h>
>  
>  #include "rtmutex_common.h"
>  
> @@ -1144,7 +1145,13 @@ void __lockfunc rt_spin_lock(spinlock_t *lock)
>  	rcu_read_lock();
>  	migrate_disable();
>  	spin_acquire(&lock->dep_map, 0, 0, _RET_IP_);
> +#ifdef CONFIG_RT_SPIN_LOCK_TRACING
> +	trace_rt_spinlock_acquire(&lock->dep_map, current);
> +#endif
>  	rt_spin_lock_fastlock(&lock->lock, rt_spin_lock_slowlock);
> +#ifdef CONFIG_RT_SPIN_LOCK_TRACING
> +	trace_rt_spinlock_acquired(&lock->dep_map, current);
> +#endif

Can you make a wrapper above so the C functions are not messed up with
#ifdefs.

#ifdef CONFIG_RT_SPIN_LOCK_TRACING
# define do_trace_rt_spinlock_aquire(lock, task) trace_rt_spinlock_acquire(lock, task)
# define do_trace_rt_spinlock_aquired(lock, task) trace_rt_spinlock_acquired(lock, task)
# define do_trace_rt_spinlock_released(lock, task) trace_rt_spinlock_released(lock, task)
#else
# define do_trace_rt_spinlock_aquire(lock, task) do {} while(0)
# define do_trace_rt_spinlock_aquired(lock, task) do {} while(0)
# define do_trace_rt_spinlock_released(lock, task) do {} while(0)
#endif

Or perhaps just have (in the code):

	if (ENABLED(CONFIG_RT_SPIN_LOCK_TRACING))
		trace_rt_spinlock_acquire(...);

-- Steve

>  }
>  EXPORT_SYMBOL(rt_spin_lock);
>  
> @@ -1169,6 +1176,9 @@ void __lockfunc rt_spin_unlock(spinlock_t *lock)
>  {
>  	/* NOTE: we always pass in '1' for nested, for simplicity */
>  	spin_release(&lock->dep_map, 1, _RET_IP_);
> +#ifdef CONFIG_RT_SPIN_LOCK_TRACING
> +	trace_rt_spinlock_released(&lock->dep_map, current);
> +#endif
>  	rt_spin_lock_fastunlock(&lock->lock, rt_spin_lock_slowunlock);
>  	migrate_enable();
>  	rcu_read_unlock();

[PATCH] rt_spin_lock: To list the correct owner of rt_spin_lock

[Mintu Patel]

   rt_spin_lock is actually mutex on RT Kernel so it goes for contention
   for lock. Currently owners of rt_spin_lock are decided before actual
   acquiring of lock. This patch would depict the correct owner of
   rt_spin_lock. The patch would help in solving crashes and deadlock
   due to race condition of lock

acquiring rt_spin_lock        acquired the lock       released the lock
                    <-------->                <------->
                    contention period         Held period

Thread1                             Thread2
_try_to_take_rt_mutex+0x95c+0x74    enqueue_task_dl+0x8cc/0x8dc
rt_spin_lock_slowlock_locked+0xac+2 rt_mutex_setprio+0x28c/0x574
rt_spin_lock_slowlock+0x5c/0x90     task_blocks_rt_mutex+0x240/0x310
rt_spin_lock+0x58/0x5c              rt_spin_lock_slowlock_locked+0xac/0x2
driverA_acquire_lock+0x28/0x56      rt_spin_lock_slowlock+0x5c/0x90
				    rt_spin_lock+0x58/0x5c
                                    driverB_acquire_lock+0x48/0x6c

As per above call traces sample, Thread1 acquired the rt_spin_lock and
went to critical section on the other hand Thread2 kept trying to acquire
the same rt_spin_lock held by Thread1 ie contention period is too high.
Finally Thread2 entered to dl queue due to high held time of the lock by
Thread1. The below patch would help us to know the correct owner of
rt_spin_lock and point us the driver's critical section. Respective
driver need to be debugged for longer held period of lock.

   ex: cat /sys/kernel/debug/tracing/trace

   kworker/u13:0-150   [003] .....11   202.761025: rt_spinlock_acquire:
Process: kworker/u13:0 is acquiring lock: &kbdev->hwaccess_lock
   kworker/u13:0-150   [003] .....11   202.761039: rt_spinlock_acquired:
Process: kworker/u13:0 has acquired lock: &kbdev->hwaccess_lock
   kworker/u13:0-150   [003] .....11   202.761042: rt_spinlock_released:
Process: kworker/u13:0 has released lock: &kbdev->hwaccess_lock

Signed-off-by: Mintu Patel <mintupatel89@gmail.com>
Signed-off-by: Chinmoy Ghosh <chinmoyghosh2001@gmail.com>
Signed-off-by: Vishal Badole <badolevishal1116@gmail.com>
Signed-off-by: Vimal Kumar <vimal.kumar32@gmail.com>
---
 include/trace/events/lock.h | 59 +++++++++++++++++++++++++++++++++++++
 kernel/locking/rtmutex.c    | 10 +++++++
 2 files changed, 69 insertions(+)

diff --git a/include/trace/events/lock.h b/include/trace/events/lock.h
index d7512129a324..c250a83ed995 100644
--- a/include/trace/events/lock.h
+++ b/include/trace/events/lock.h
@@ -35,6 +35,65 @@ TRACE_EVENT(lock_acquire,
 		  (__entry->flags & 2) ? "read " : "",
 		  __get_str(name))
 );
+TRACE_EVENT(rt_spinlock_acquire,
+
+	TP_PROTO(struct lockdep_map *lock, struct task_struct *pname),
+
+	TP_ARGS(lock, pname),
+
+	TP_STRUCT__entry(
+		__string(name, lock->name)
+		__string(process_name, pname->comm)
+	),
+
+	TP_fast_assign(
+		__assign_str(name, lock->name);
+		__assign_str(process_name, pname->comm);
+	),
+
+	TP_printk("Process: %s is acquiring lock: %s",  __get_str(process_name),
+		__get_str(name))
+);
+
+TRACE_EVENT(rt_spinlock_acquired,
+
+	TP_PROTO(struct lockdep_map *lock, struct task_struct *pname),
+
+	TP_ARGS(lock, pname),
+
+	TP_STRUCT__entry(
+		__string(name, lock->name)
+		__string(process_name, pname->comm)
+	),
+
+	TP_fast_assign(
+		__assign_str(name, lock->name);
+		__assign_str(process_name, pname->comm);
+	),
+
+	TP_printk("Process: %s has acquired lock: %s", __get_str(process_name),
+		__get_str(name))
+);
+
+TRACE_EVENT(rt_spinlock_released,
+
+	TP_PROTO(struct lockdep_map *lock, struct task_struct *pname),
+
+	TP_ARGS(lock, pname),
+
+	TP_STRUCT__entry(
+		__string(name, lock->name)
+		__string(process_name, pname->comm)
+	),
+
+	TP_fast_assign(
+		__assign_str(name, lock->name);
+		__assign_str(process_name, pname->comm);
+	),
+
+	TP_printk("Process: %s has released lock: %s", __get_str(process_name),
+		__get_str(name))
+);
 
 DECLARE_EVENT_CLASS(lock,
 
diff --git a/kernel/locking/rtmutex.c b/kernel/locking/rtmutex.c
index 602eb7821a1b..f7cba05fbe74 100644
--- a/kernel/locking/rtmutex.c
+++ b/kernel/locking/rtmutex.c
@@ -26,6 +26,7 @@
 #include <linux/timer.h>
 #include <linux/ww_mutex.h>
 #include <linux/blkdev.h>
+#include <trace/events/lock.h>
 
 #include "rtmutex_common.h"
 
@@ -1144,7 +1145,13 @@ void __lockfunc rt_spin_lock(spinlock_t *lock)
 	rcu_read_lock();
 	migrate_disable();
 	spin_acquire(&lock->dep_map, 0, 0, _RET_IP_);
+#ifdef CONFIG_RT_SPIN_LOCK_TRACING
+	trace_rt_spinlock_acquire(&lock->dep_map, current);
+#endif
 	rt_spin_lock_fastlock(&lock->lock, rt_spin_lock_slowlock);
+#ifdef CONFIG_RT_SPIN_LOCK_TRACING
+	trace_rt_spinlock_acquired(&lock->dep_map, current);
+#endif
 }
 EXPORT_SYMBOL(rt_spin_lock);
 
@@ -1169,6 +1176,9 @@ void __lockfunc rt_spin_unlock(spinlock_t *lock)
 {
 	/* NOTE: we always pass in '1' for nested, for simplicity */
 	spin_release(&lock->dep_map, 1, _RET_IP_);
+#ifdef CONFIG_RT_SPIN_LOCK_TRACING
+	trace_rt_spinlock_released(&lock->dep_map, current);
+#endif
 	rt_spin_lock_fastunlock(&lock->lock, rt_spin_lock_slowunlock);
 	migrate_enable();
 	rcu_read_unlock();
-- 
2.25.1