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 <[email protected]>
Signed-off-by: Chinmoy Ghosh <[email protected]>
Signed-off-by: Vishal Badole <[email protected]>
Signed-off-by: Vimal Kumar <[email protected]>
---
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
On Sun, 19 Jun 2022 19:50:38 +0530
Mintu Patel <[email protected]> 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 <[email protected]>
> Signed-off-by: Chinmoy Ghosh <[email protected]>
> Signed-off-by: Vishal Badole <[email protected]>
> Signed-off-by: Vimal Kumar <[email protected]>
> ---
> 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();
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 <[email protected]>
Signed-off-by: Chinmoy Ghosh <[email protected]>
Signed-off-by: Vishal Badole <[email protected]>
Signed-off-by: Vimal Kumar <[email protected]>
---
include/trace/events/lock.h | 38 +++++++++++++++++++++++++++++++++
kernel/locking/rtmutex.c | 4 ++++
kernel/locking/rtmutex_common.h | 14 ++++++++++++
3 files changed, 56 insertions(+)
diff --git a/include/trace/events/lock.h b/include/trace/events/lock.h
index d7512129a324..0564474341c8 100644
--- a/include/trace/events/lock.h
+++ b/include/trace/events/lock.h
@@ -36,6 +36,44 @@ TRACE_EVENT(lock_acquire,
__get_str(name))
);
+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))
+);
+
+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,
TP_PROTO(struct lockdep_map *lock, unsigned long ip),
diff --git a/kernel/locking/rtmutex.c b/kernel/locking/rtmutex.c
index 602eb7821a1b..80ba2c0d7923 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,9 @@ void __lockfunc rt_spin_lock(spinlock_t *lock)
rcu_read_lock();
migrate_disable();
spin_acquire(&lock->dep_map, 0, 0, _RET_IP_);
+ do_trace_rt_spinlock_acquire(lock, current);
rt_spin_lock_fastlock(&lock->lock, rt_spin_lock_slowlock);
+ do_trace_rt_spinlock_acquired(lock, current);
}
EXPORT_SYMBOL(rt_spin_lock);
@@ -1169,6 +1172,7 @@ 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_);
+ do_trace_rt_spinlock_released(lock, current);
rt_spin_lock_fastunlock(&lock->lock, rt_spin_lock_slowunlock);
migrate_enable();
rcu_read_unlock();
diff --git a/kernel/locking/rtmutex_common.h b/kernel/locking/rtmutex_common.h
index 546aaf058b9e..185ffc1e7015 100644
--- a/kernel/locking/rtmutex_common.h
+++ b/kernel/locking/rtmutex_common.h
@@ -25,6 +25,20 @@
* @pi_tree_entry: pi node to enqueue into the mutex owner waiters tree
* @task: task reference to the blocked task
*/
+
+#ifdef CONFIG_RT_SPIN_LOCK_TRACING
+#define do_trace_rt_spinlock_acquire(lock, task) \
+ trace_rt_spinlock_acquire(&lock->dep_map, task)
+#define do_trace_rt_spinlock_acquired(lock, task) \
+ trace_rt_spinlock_acquired(&lock->dep_map, task)
+#define do_trace_rt_spinlock_released(lock, task) \
+ trace_rt_spinlock_released(&lock->dep_map, task)
+#else
+#define do_trace_rt_spinlock_acquire(lock, task) do {} while(0)
+#define do_trace_rt_spinlock_acquired(lock, task) do {} while(0)
+#define do_trace_rt_spinlock_released(lock, task) do {} while(0)
+#endif
+
struct rt_mutex_waiter {
struct rb_node tree_entry;
struct rb_node pi_tree_entry;
--
2.25.1
On Mon, 27 Jun 2022 21:41:38 +0530
Mintu Patel <[email protected]> wrote:
Hi Mintu,
FYI, a v2 should never be a reply to the v1. It should always start its own
thread, otherwise tooling and such will miss it.
> 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 <[email protected]>
> Signed-off-by: Chinmoy Ghosh <[email protected]>
> Signed-off-by: Vishal Badole <[email protected]>
> Signed-off-by: Vimal Kumar <[email protected]>
> ---
> include/trace/events/lock.h | 38 +++++++++++++++++++++++++++++++++
> kernel/locking/rtmutex.c | 4 ++++
> kernel/locking/rtmutex_common.h | 14 ++++++++++++
> 3 files changed, 56 insertions(+)
>
> diff --git a/include/trace/events/lock.h b/include/trace/events/lock.h
> index d7512129a324..0564474341c8 100644
> --- a/include/trace/events/lock.h
> +++ b/include/trace/events/lock.h
> @@ -36,6 +36,44 @@ TRACE_EVENT(lock_acquire,
> __get_str(name))
> );
>
> +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))
> +);
> +
> +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,
>
> TP_PROTO(struct lockdep_map *lock, unsigned long ip),
> diff --git a/kernel/locking/rtmutex.c b/kernel/locking/rtmutex.c
> index 602eb7821a1b..80ba2c0d7923 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,9 @@ void __lockfunc rt_spin_lock(spinlock_t *lock)
> rcu_read_lock();
> migrate_disable();
> spin_acquire(&lock->dep_map, 0, 0, _RET_IP_);
> + do_trace_rt_spinlock_acquire(lock, current);
> rt_spin_lock_fastlock(&lock->lock, rt_spin_lock_slowlock);
> + do_trace_rt_spinlock_acquired(lock, current);
> }
> EXPORT_SYMBOL(rt_spin_lock);
>
> @@ -1169,6 +1172,7 @@ 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_);
> + do_trace_rt_spinlock_released(lock, current);
> rt_spin_lock_fastunlock(&lock->lock, rt_spin_lock_slowunlock);
> migrate_enable();
> rcu_read_unlock();
> diff --git a/kernel/locking/rtmutex_common.h b/kernel/locking/rtmutex_common.h
> index 546aaf058b9e..185ffc1e7015 100644
> --- a/kernel/locking/rtmutex_common.h
> +++ b/kernel/locking/rtmutex_common.h
> @@ -25,6 +25,20 @@
> * @pi_tree_entry: pi node to enqueue into the mutex owner waiters tree
> * @task: task reference to the blocked task
> */
> +
> +#ifdef CONFIG_RT_SPIN_LOCK_TRACING
> +#define do_trace_rt_spinlock_acquire(lock, task) \
> + trace_rt_spinlock_acquire(&lock->dep_map, task)
> +#define do_trace_rt_spinlock_acquired(lock, task) \
> + trace_rt_spinlock_acquired(&lock->dep_map, task)
> +#define do_trace_rt_spinlock_released(lock, task) \
> + trace_rt_spinlock_released(&lock->dep_map, task)
> +#else
> +#define do_trace_rt_spinlock_acquire(lock, task) do {} while(0)
> +#define do_trace_rt_spinlock_acquired(lock, task) do {} while(0)
> +#define do_trace_rt_spinlock_released(lock, task) do {} while(0)
> +#endif
> +
Acked-by: Steven Rostedt (Google) <[email protected]>
Although it will need to be accepted by Peter Zijlstra.
-- Steve
> struct rt_mutex_waiter {
> struct rb_node tree_entry;
> struct rb_node pi_tree_entry;
On Fri, Jul 08, 2022 at 04:21:58PM -0400, Steven Rostedt wrote:
> On Mon, 27 Jun 2022 21:41:38 +0530
> Mintu Patel <[email protected]> wrote:
>
> Hi Mintu,
>
> FYI, a v2 should never be a reply to the v1. It should always start its own
> thread, otherwise tooling and such will miss it.
>
> > 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 <[email protected]>
> > Signed-off-by: Chinmoy Ghosh <[email protected]>
> > Signed-off-by: Vishal Badole <[email protected]>
> > Signed-off-by: Vimal Kumar <[email protected]>
> > ---
> > include/trace/events/lock.h | 38 +++++++++++++++++++++++++++++++++
> > kernel/locking/rtmutex.c | 4 ++++
> > kernel/locking/rtmutex_common.h | 14 ++++++++++++
> > 3 files changed, 56 insertions(+)
> >
> > diff --git a/include/trace/events/lock.h b/include/trace/events/lock.h
> > index d7512129a324..0564474341c8 100644
> > --- a/include/trace/events/lock.h
> > +++ b/include/trace/events/lock.h
> > @@ -36,6 +36,44 @@ TRACE_EVENT(lock_acquire,
> > __get_str(name))
> > );
> >
> > +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))
> > +);
> > +
> > +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,
> >
> > TP_PROTO(struct lockdep_map *lock, unsigned long ip),
> > diff --git a/kernel/locking/rtmutex.c b/kernel/locking/rtmutex.c
> > index 602eb7821a1b..80ba2c0d7923 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,9 @@ void __lockfunc rt_spin_lock(spinlock_t *lock)
> > rcu_read_lock();
> > migrate_disable();
> > spin_acquire(&lock->dep_map, 0, 0, _RET_IP_);
> > + do_trace_rt_spinlock_acquire(lock, current);
> > rt_spin_lock_fastlock(&lock->lock, rt_spin_lock_slowlock);
> > + do_trace_rt_spinlock_acquired(lock, current);
> > }
> > EXPORT_SYMBOL(rt_spin_lock);
> >
> > @@ -1169,6 +1172,7 @@ 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_);
> > + do_trace_rt_spinlock_released(lock, current);
> > rt_spin_lock_fastunlock(&lock->lock, rt_spin_lock_slowunlock);
> > migrate_enable();
> > rcu_read_unlock();
> > diff --git a/kernel/locking/rtmutex_common.h b/kernel/locking/rtmutex_common.h
> > index 546aaf058b9e..185ffc1e7015 100644
> > --- a/kernel/locking/rtmutex_common.h
> > +++ b/kernel/locking/rtmutex_common.h
> > @@ -25,6 +25,20 @@
> > * @pi_tree_entry: pi node to enqueue into the mutex owner waiters tree
> > * @task: task reference to the blocked task
> > */
> > +
> > +#ifdef CONFIG_RT_SPIN_LOCK_TRACING
> > +#define do_trace_rt_spinlock_acquire(lock, task) \
> > + trace_rt_spinlock_acquire(&lock->dep_map, task)
> > +#define do_trace_rt_spinlock_acquired(lock, task) \
> > + trace_rt_spinlock_acquired(&lock->dep_map, task)
> > +#define do_trace_rt_spinlock_released(lock, task) \
> > + trace_rt_spinlock_released(&lock->dep_map, task)
> > +#else
> > +#define do_trace_rt_spinlock_acquire(lock, task) do {} while(0)
> > +#define do_trace_rt_spinlock_acquired(lock, task) do {} while(0)
> > +#define do_trace_rt_spinlock_released(lock, task) do {} while(0)
> > +#endif
> > +
>
> Acked-by: Steven Rostedt (Google) <[email protected]>
>
> Although it will need to be accepted by Peter Zijlstra.
>
> -- Steve
>
>
> > struct rt_mutex_waiter {
> > struct rb_node tree_entry;
> > struct rb_node pi_tree_entry;
>
Hi Peter,
Could you please review this patch.
Regards,
Vishal Badole
On Mon, Jun 27, 2022 at 09:41:38PM +0530, Mintu Patel 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
>
The above is word salad and makes no sense. No other lock has special
tracing like this, so rt_lock doesn't need it either.
On Wed, Dec 06, 2023 at 07:58:37PM +0100, Peter Zijlstra wrote:
> On Mon, Jun 27, 2022 at 09:41:38PM +0530, Mintu Patel 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
> >
>
> The above is word salad and makes no sense. No other lock has special
> tracing like this, so rt_lock doesn't need it either.
>
Hi Peter,
As per current implementation of rt_spin_lock tracing mechanism on RTLinux,
if more than one threads are trying to acquire a rt_spin_lock,
then multiple threads are assigned as owners of the same lock, more over
only one thread is actual owner of lock and others are still
contending for the same lock. Such trace logs can mislead the developers
during debugging of critical issues like deadlock, crashes etc
The above patch would generate rt_spin_lock locking traces which would
depict correct owner of the lock and other thread details which
are trying to acquire the lock.
Regards,
Mintu Patel
On Thu, Dec 07, 2023 at 10:31:30PM +0530, <Mintu Patel> wrote:
> On Wed, Dec 06, 2023 at 07:58:37PM +0100, Peter Zijlstra wrote:
> > On Mon, Jun 27, 2022 at 09:41:38PM +0530, Mintu Patel 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
> > >
> >
> > The above is word salad and makes no sense. No other lock has special
> > tracing like this, so rt_lock doesn't need it either.
> >
> Hi Peter,
>
> As per current implementation of rt_spin_lock tracing mechanism on RTLinux,
> if more than one threads are trying to acquire a rt_spin_lock,
> then multiple threads are assigned as owners of the same lock, more over
> only one thread is actual owner of lock and others are still
> contending for the same lock. Such trace logs can mislead the developers
> during debugging of critical issues like deadlock, crashes etc
>
> The above patch would generate rt_spin_lock locking traces which would
> depict correct owner of the lock and other thread details which
> are trying to acquire the lock.
>
> Regards,
> Mintu Patel
Hi Peter,
Hope you got a chance to check the reply.
Regards,
Mintu Patel