[PATCH] sample-trace-array: Fix sleeping function called from invalid context

[PATCH] sample-trace-array: Fix sleeping function called from invalid context

[Kefeng Wang]

 BUG: sleeping function called from invalid context at kernel/locking/mutex.c:935
 in_atomic(): 1, irqs_disabled(): 0, non_block: 0, pid: 0, name: swapper/5
 1 lock held by swapper/5/0:
  #0: ffff80001002bd90 (samples/ftrace/sample-trace-array.c:38){+.-.}-{0:0}, at: call_timer_fn+0x8/0x3e0
 CPU: 5 PID: 0 Comm: swapper/5 Not tainted 5.7.0+ #8
 Hardware name: QEMU QEMU Virtual Machine, BIOS 0.0.0 02/06/2015
 Call trace:
  dump_backtrace+0x0/0x1a0
  show_stack+0x20/0x30
  dump_stack+0xe4/0x150
  ___might_sleep+0x160/0x200
  __might_sleep+0x58/0x90
  __mutex_lock+0x64/0x948
  mutex_lock_nested+0x3c/0x58
  __ftrace_set_clr_event+0x44/0x88
  trace_array_set_clr_event+0x24/0x38
  mytimer_handler+0x34/0x40 [sample_trace_array]

mutex_lock() will be called in interrupt context, using workqueueu to fix it.

Signed-off-by: Kefeng Wang <wangkefeng.wang@huawei.com>
---
 samples/ftrace/sample-trace-array.c | 16 +++++++++++-----
 1 file changed, 11 insertions(+), 5 deletions(-)

diff --git a/samples/ftrace/sample-trace-array.c b/samples/ftrace/sample-trace-array.c
index d523450d73eb..41684c7dbd7b 100644
--- a/samples/ftrace/sample-trace-array.c
+++ b/samples/ftrace/sample-trace-array.c
@@ -20,6 +20,16 @@ struct trace_array *tr;
 static void mytimer_handler(struct timer_list *unused);
 static struct task_struct *simple_tsk;
 
+static void trace_work_fn(struct work_struct *work)
+{
+	/*
+	 * Disable tracing for event "sample_event".
+	 */
+	trace_array_set_clr_event(tr, "sample-subsystem", "sample_event",
+			false);
+}
+static DECLARE_WORK(trace_work, trace_work_fn);
+
 /*
  * mytimer: Timer setup to disable tracing for event "sample_event". This
  * timer is only for the purposes of the sample module to demonstrate access of
@@ -29,11 +39,7 @@ static DEFINE_TIMER(mytimer, mytimer_handler);
 
 static void mytimer_handler(struct timer_list *unused)
 {
-	/*
-	 * Disable tracing for event "sample_event".
-	 */
-	trace_array_set_clr_event(tr, "sample-subsystem", "sample_event",
-			false);
+	schedule_work(&trace_work);
 }
 
 static void simple_thread_func(int count)
-- 
2.27.0

Re: [PATCH] sample-trace-array: Fix sleeping function called from invalid context

[Steven Rostedt]

On Mon, 8 Jun 2020 07:54:37 +0000
Kefeng Wang <wangkefeng.wang@huawei.com> wrote:

>  BUG: sleeping function called from invalid context at kernel/locking/mutex.c:935
>  in_atomic(): 1, irqs_disabled(): 0, non_block: 0, pid: 0, name: swapper/5
>  1 lock held by swapper/5/0:
>   #0: ffff80001002bd90 (samples/ftrace/sample-trace-array.c:38){+.-.}-{0:0}, at: call_timer_fn+0x8/0x3e0
>  CPU: 5 PID: 0 Comm: swapper/5 Not tainted 5.7.0+ #8
>  Hardware name: QEMU QEMU Virtual Machine, BIOS 0.0.0 02/06/2015
>  Call trace:
>   dump_backtrace+0x0/0x1a0
>   show_stack+0x20/0x30
>   dump_stack+0xe4/0x150
>   ___might_sleep+0x160/0x200
>   __might_sleep+0x58/0x90
>   __mutex_lock+0x64/0x948
>   mutex_lock_nested+0x3c/0x58
>   __ftrace_set_clr_event+0x44/0x88
>   trace_array_set_clr_event+0x24/0x38
>   mytimer_handler+0x34/0x40 [sample_trace_array]
> 
> mutex_lock() will be called in interrupt context, using workqueueu to fix it.
> 
> Signed-off-by: Kefeng Wang <wangkefeng.wang@huawei.com>
> 

Divya,

Can you give a Reviewed-by for this?

-- Steve

Re: [PATCH] sample-trace-array: Fix sleeping function called from invalid context

[Divya Indi]

Hi Steve,

Sure, I am looking into it and reviewing the patch.

Thanks,
Divya

On 6/8/20 7:37 AM, Steven Rostedt wrote:
> On Mon, 8 Jun 2020 07:54:37 +0000
> Kefeng Wang <wangkefeng.wang@huawei.com> wrote:
>
>>  BUG: sleeping function called from invalid context at kernel/locking/mutex.c:935
>>  in_atomic(): 1, irqs_disabled(): 0, non_block: 0, pid: 0, name: swapper/5
>>  1 lock held by swapper/5/0:
>>   #0: ffff80001002bd90 (samples/ftrace/sample-trace-array.c:38){+.-.}-{0:0}, at: call_timer_fn+0x8/0x3e0
>>  CPU: 5 PID: 0 Comm: swapper/5 Not tainted 5.7.0+ #8
>>  Hardware name: QEMU QEMU Virtual Machine, BIOS 0.0.0 02/06/2015
>>  Call trace:
>>   dump_backtrace+0x0/0x1a0
>>   show_stack+0x20/0x30
>>   dump_stack+0xe4/0x150
>>   ___might_sleep+0x160/0x200
>>   __might_sleep+0x58/0x90
>>   __mutex_lock+0x64/0x948
>>   mutex_lock_nested+0x3c/0x58
>>   __ftrace_set_clr_event+0x44/0x88
>>   trace_array_set_clr_event+0x24/0x38
>>   mytimer_handler+0x34/0x40 [sample_trace_array]
>>
>> mutex_lock() will be called in interrupt context, using workqueueu to fix it.
>>
>> Signed-off-by: Kefeng Wang <wangkefeng.wang@huawei.com>
>>
> Divya,
>
> Can you give a Reviewed-by for this?
>
> -- Steve

Re: [PATCH] sample-trace-array: Fix sleeping function called from invalid context

[Divya Indi]

Hi Kefeng,

Thanks for catching this issue.

Please find my comments line -

On 6/8/20 12:54 AM, Kefeng Wang wrote:
>  BUG: sleeping function called from invalid context at kernel/locking/mutex.c:935
>  in_atomic(): 1, irqs_disabled(): 0, non_block: 0, pid: 0, name: swapper/5
>  1 lock held by swapper/5/0:
>   #0: ffff80001002bd90 (samples/ftrace/sample-trace-array.c:38){+.-.}-{0:0}, at: call_timer_fn+0x8/0x3e0
>  CPU: 5 PID: 0 Comm: swapper/5 Not tainted 5.7.0+ #8
>  Hardware name: QEMU QEMU Virtual Machine, BIOS 0.0.0 02/06/2015
>  Call trace:
>   dump_backtrace+0x0/0x1a0
>   show_stack+0x20/0x30
>   dump_stack+0xe4/0x150
>   ___might_sleep+0x160/0x200
>   __might_sleep+0x58/0x90
>   __mutex_lock+0x64/0x948
>   mutex_lock_nested+0x3c/0x58
>   __ftrace_set_clr_event+0x44/0x88
>   trace_array_set_clr_event+0x24/0x38
>   mytimer_handler+0x34/0x40 [sample_trace_array]
>
> mutex_lock() will be called in interrupt context, using workqueueu to fix it.

/s/workqueueu/workqueue

Fixes: 89ed42495ef4 ("tracing: Sample module to demonstrate kernel access to Ftrace instances.")

> Signed-off-by: Kefeng Wang <wangkefeng.wang@huawei.com>
> ---
>  samples/ftrace/sample-trace-array.c | 16 +++++++++++-----
>  1 file changed, 11 insertions(+), 5 deletions(-)
>
> diff --git a/samples/ftrace/sample-trace-array.c b/samples/ftrace/sample-trace-array.c
> index d523450d73eb..41684c7dbd7b 100644
> --- a/samples/ftrace/sample-trace-array.c
> +++ b/samples/ftrace/sample-trace-array.c
> @@ -20,6 +20,16 @@ struct trace_array *tr;
>  static void mytimer_handler(struct timer_list *unused);
>  static struct task_struct *simple_tsk;
>  
> +static void trace_work_fn(struct work_struct *work)
> +{
> +	/*
> +	 * Disable tracing for event "sample_event".
> +	 */
> +	trace_array_set_clr_event(tr, "sample-subsystem", "sample_event",
> +			false);
> +}
> +static DECLARE_WORK(trace_work, trace_work_fn);
> +
>  /*
>   * mytimer: Timer setup to disable tracing for event "sample_event". This
>   * timer is only for the purposes of the sample module to demonstrate access of
> @@ -29,11 +39,7 @@ static DEFINE_TIMER(mytimer, mytimer_handler);
>  
>  static void mytimer_handler(struct timer_list *unused)
>  {
> -	/*
> -	 * Disable tracing for event "sample_event".
> -	 */
> -	trace_array_set_clr_event(tr, "sample-subsystem", "sample_event",
> -			false);
> +	schedule_work(&trace_work);
>  }
>  
>  static void simple_thread_func(int count)

I think we also need to use cancel_work_sync() to handle the case -
1. Module unloaded
2. Timer already ran and scheduled work to disable trace event
3. When the work runs we no longer have the relevant trace array.

static int simple_thread(void *arg)
{
.....

 del_timer(&mytimer);

 <cancel_work_sync> 
.....
 return 0;
}

Thanks,
Divya

[PATCH v2] sample-trace-array: Fix sleeping function called from invalid context

[Kefeng Wang]

 BUG: sleeping function called from invalid context at kernel/locking/mutex.c:935
 in_atomic(): 1, irqs_disabled(): 0, non_block: 0, pid: 0, name: swapper/5
 1 lock held by swapper/5/0:
  #0: ffff80001002bd90 (samples/ftrace/sample-trace-array.c:38){+.-.}-{0:0}, at: call_timer_fn+0x8/0x3e0
 CPU: 5 PID: 0 Comm: swapper/5 Not tainted 5.7.0+ #8
 Hardware name: QEMU QEMU Virtual Machine, BIOS 0.0.0 02/06/2015
 Call trace:
  dump_backtrace+0x0/0x1a0
  show_stack+0x20/0x30
  dump_stack+0xe4/0x150
  ___might_sleep+0x160/0x200
  __might_sleep+0x58/0x90
  __mutex_lock+0x64/0x948
  mutex_lock_nested+0x3c/0x58
  __ftrace_set_clr_event+0x44/0x88
  trace_array_set_clr_event+0x24/0x38
  mytimer_handler+0x34/0x40 [sample_trace_array]

mutex_lock() will be called in interrupt context, using workqueue to fix it.

Signed-off-by: Kefeng Wang <wangkefeng.wang@huawei.com>
---
v2:
- add include of linux/workqueue.h
- add missing cancel_work_sync() suggested by Divya Indi

 samples/ftrace/sample-trace-array.c | 18 +++++++++++++-----
 1 file changed, 13 insertions(+), 5 deletions(-)

diff --git a/samples/ftrace/sample-trace-array.c b/samples/ftrace/sample-trace-array.c
index d523450d73eb..9e437f930280 100644
--- a/samples/ftrace/sample-trace-array.c
+++ b/samples/ftrace/sample-trace-array.c
@@ -6,6 +6,7 @@
 #include <linux/timer.h>
 #include <linux/err.h>
 #include <linux/jiffies.h>
+#include <linux/workqueue.h>
 
 /*
  * Any file that uses trace points, must include the header.
@@ -20,6 +21,16 @@ struct trace_array *tr;
 static void mytimer_handler(struct timer_list *unused);
 static struct task_struct *simple_tsk;
 
+static void trace_work_fn(struct work_struct *work)
+{
+	/*
+	 * Disable tracing for event "sample_event".
+	 */
+	trace_array_set_clr_event(tr, "sample-subsystem", "sample_event",
+			false);
+}
+static DECLARE_WORK(trace_work, trace_work_fn);
+
 /*
  * mytimer: Timer setup to disable tracing for event "sample_event". This
  * timer is only for the purposes of the sample module to demonstrate access of
@@ -29,11 +40,7 @@ static DEFINE_TIMER(mytimer, mytimer_handler);
 
 static void mytimer_handler(struct timer_list *unused)
 {
-	/*
-	 * Disable tracing for event "sample_event".
-	 */
-	trace_array_set_clr_event(tr, "sample-subsystem", "sample_event",
-			false);
+	schedule_work(&trace_work);
 }
 
 static void simple_thread_func(int count)
@@ -76,6 +83,7 @@ static int simple_thread(void *arg)
 		simple_thread_func(count++);
 
 	del_timer(&mytimer);
+	cancel_work_sync(&trace_work);
 
 	/*
 	 * trace_array_put() decrements the reference counter associated with
-- 
2.27.0

Re: [PATCH v2] sample-trace-array: Fix sleeping function called from invalid context

[Divya Indi]

On 6/9/20 6:51 AM, Kefeng Wang wrote:
>  BUG: sleeping function called from invalid context at kernel/locking/mutex.c:935
>  in_atomic(): 1, irqs_disabled(): 0, non_block: 0, pid: 0, name: swapper/5
>  1 lock held by swapper/5/0:
>   #0: ffff80001002bd90 (samples/ftrace/sample-trace-array.c:38){+.-.}-{0:0}, at: call_timer_fn+0x8/0x3e0
>  CPU: 5 PID: 0 Comm: swapper/5 Not tainted 5.7.0+ #8
>  Hardware name: QEMU QEMU Virtual Machine, BIOS 0.0.0 02/06/2015
>  Call trace:
>   dump_backtrace+0x0/0x1a0
>   show_stack+0x20/0x30
>   dump_stack+0xe4/0x150
>   ___might_sleep+0x160/0x200
>   __might_sleep+0x58/0x90
>   __mutex_lock+0x64/0x948
>   mutex_lock_nested+0x3c/0x58
>   __ftrace_set_clr_event+0x44/0x88
>   trace_array_set_clr_event+0x24/0x38
>   mytimer_handler+0x34/0x40 [sample_trace_array]
>
> mutex_lock() will be called in interrupt context, using workqueue to fix it.
Fixes:
> Signed-off-by: Kefeng Wang <wangkefeng.wang@huawei.com>

Reviewed-by: Divya Indi <divya.indi@oracle.com>

> ---
> v2:
> - add include of linux/workqueue.h
> - add missing cancel_work_sync() suggested by Divya Indi
>
>  samples/ftrace/sample-trace-array.c | 18 +++++++++++++-----
>  1 file changed, 13 insertions(+), 5 deletions(-)
>
> diff --git a/samples/ftrace/sample-trace-array.c b/samples/ftrace/sample-trace-array.c
> index d523450d73eb..9e437f930280 100644
> --- a/samples/ftrace/sample-trace-array.c
> +++ b/samples/ftrace/sample-trace-array.c
> @@ -6,6 +6,7 @@
>  #include <linux/timer.h>
>  #include <linux/err.h>
>  #include <linux/jiffies.h>
> +#include <linux/workqueue.h>
>  
>  /*
>   * Any file that uses trace points, must include the header.
> @@ -20,6 +21,16 @@ struct trace_array *tr;
>  static void mytimer_handler(struct timer_list *unused);
>  static struct task_struct *simple_tsk;
>  
> +static void trace_work_fn(struct work_struct *work)
> +{
> +	/*
> +	 * Disable tracing for event "sample_event".
> +	 */
> +	trace_array_set_clr_event(tr, "sample-subsystem", "sample_event",
> +			false);
> +}
> +static DECLARE_WORK(trace_work, trace_work_fn);
> +
>  /*
>   * mytimer: Timer setup to disable tracing for event "sample_event". This
>   * timer is only for the purposes of the sample module to demonstrate access of
> @@ -29,11 +40,7 @@ static DEFINE_TIMER(mytimer, mytimer_handler);
>  
>  static void mytimer_handler(struct timer_list *unused)
>  {
> -	/*
> -	 * Disable tracing for event "sample_event".
> -	 */
> -	trace_array_set_clr_event(tr, "sample-subsystem", "sample_event",
> -			false);
> +	schedule_work(&trace_work);
>  }
>  
>  static void simple_thread_func(int count)
> @@ -76,6 +83,7 @@ static int simple_thread(void *arg)
>  		simple_thread_func(count++);
>  
>  	del_timer(&mytimer);
> +	cancel_work_sync(&trace_work);
>  
>  	/*
>  	 * trace_array_put() decrements the reference counter associated with

Re: [PATCH v2] sample-trace-array: Fix sleeping function called from invalid context

[Kefeng Wang]

On 2020/6/10 0:29, Divya Indi wrote:
> On 6/9/20 6:51 AM, Kefeng Wang wrote:
>>   BUG: sleeping function called from invalid context at kernel/locking/mutex.c:935
>>   in_atomic(): 1, irqs_disabled(): 0, non_block: 0, pid: 0, name: swapper/5
>>   1 lock held by swapper/5/0:
>>    #0: ffff80001002bd90 (samples/ftrace/sample-trace-array.c:38){+.-.}-{0:0}, at: call_timer_fn+0x8/0x3e0
>>   CPU: 5 PID: 0 Comm: swapper/5 Not tainted 5.7.0+ #8
>>   Hardware name: QEMU QEMU Virtual Machine, BIOS 0.0.0 02/06/2015
>>   Call trace:
>>    dump_backtrace+0x0/0x1a0
>>    show_stack+0x20/0x30
>>    dump_stack+0xe4/0x150
>>    ___might_sleep+0x160/0x200
>>    __might_sleep+0x58/0x90
>>    __mutex_lock+0x64/0x948
>>    mutex_lock_nested+0x3c/0x58
>>    __ftrace_set_clr_event+0x44/0x88
>>    trace_array_set_clr_event+0x24/0x38
>>    mytimer_handler+0x34/0x40 [sample_trace_array]
>>
>> mutex_lock() will be called in interrupt context, using workqueue to fix it.
> Fixes:
Missing it， will send v3， thanks.
>> Signed-off-by: Kefeng Wang <wangkefeng.wang@huawei.com>
> Reviewed-by: Divya Indi <divya.indi@oracle.com>
>
>

[PATCH v3] sample-trace-array: Fix sleeping function called from invalid context

[Kefeng Wang]

 BUG: sleeping function called from invalid context at kernel/locking/mutex.c:935
 in_atomic(): 1, irqs_disabled(): 0, non_block: 0, pid: 0, name: swapper/5
 1 lock held by swapper/5/0:
  #0: ffff80001002bd90 (samples/ftrace/sample-trace-array.c:38){+.-.}-{0:0}, at: call_timer_fn+0x8/0x3e0
 CPU: 5 PID: 0 Comm: swapper/5 Not tainted 5.7.0+ #8
 Hardware name: QEMU QEMU Virtual Machine, BIOS 0.0.0 02/06/2015
 Call trace:
  dump_backtrace+0x0/0x1a0
  show_stack+0x20/0x30
  dump_stack+0xe4/0x150
  ___might_sleep+0x160/0x200
  __might_sleep+0x58/0x90
  __mutex_lock+0x64/0x948
  mutex_lock_nested+0x3c/0x58
  __ftrace_set_clr_event+0x44/0x88
  trace_array_set_clr_event+0x24/0x38
  mytimer_handler+0x34/0x40 [sample_trace_array]

mutex_lock() will be called in interrupt context, using workqueue to fix it.

Fixes: 89ed42495ef4 ("tracing: Sample module to demonstrate kernel access to Ftrace instances.")
Signed-off-by: Kefeng Wang <wangkefeng.wang@huawei.com>
Reviewed-by: Divya Indi <divya.indi@oracle.com>
---
V3:
- add Fixes and RB
v2:
- add include of linux/workqueue.h
- add missing cancel_work_sync() suggested by Divya Indi

 samples/ftrace/sample-trace-array.c | 18 +++++++++++++-----
 1 file changed, 13 insertions(+), 5 deletions(-)

diff --git a/samples/ftrace/sample-trace-array.c b/samples/ftrace/sample-trace-array.c
index d523450d73eb..9e437f930280 100644
--- a/samples/ftrace/sample-trace-array.c
+++ b/samples/ftrace/sample-trace-array.c
@@ -6,6 +6,7 @@
 #include <linux/timer.h>
 #include <linux/err.h>
 #include <linux/jiffies.h>
+#include <linux/workqueue.h>
 
 /*
  * Any file that uses trace points, must include the header.
@@ -20,6 +21,16 @@ struct trace_array *tr;
 static void mytimer_handler(struct timer_list *unused);
 static struct task_struct *simple_tsk;
 
+static void trace_work_fn(struct work_struct *work)
+{
+	/*
+	 * Disable tracing for event "sample_event".
+	 */
+	trace_array_set_clr_event(tr, "sample-subsystem", "sample_event",
+			false);
+}
+static DECLARE_WORK(trace_work, trace_work_fn);
+
 /*
  * mytimer: Timer setup to disable tracing for event "sample_event". This
  * timer is only for the purposes of the sample module to demonstrate access of
@@ -29,11 +40,7 @@ static DEFINE_TIMER(mytimer, mytimer_handler);
 
 static void mytimer_handler(struct timer_list *unused)
 {
-	/*
-	 * Disable tracing for event "sample_event".
-	 */
-	trace_array_set_clr_event(tr, "sample-subsystem", "sample_event",
-			false);
+	schedule_work(&trace_work);
 }
 
 static void simple_thread_func(int count)
@@ -76,6 +83,7 @@ static int simple_thread(void *arg)
 		simple_thread_func(count++);
 
 	del_timer(&mytimer);
+	cancel_work_sync(&trace_work);
 
 	/*
 	 * trace_array_put() decrements the reference counter associated with
-- 
2.27.0