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 <[email protected]>
---
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
On Mon, 8 Jun 2020 07:54:37 +0000
Kefeng Wang <[email protected]> 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 <[email protected]>
>
Divya,
Can you give a Reviewed-by for this?
-- Steve
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 <[email protected]> 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 <[email protected]>
>>
> Divya,
>
> Can you give a Reviewed-by for this?
>
> -- Steve
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 <[email protected]>
> ---
> 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
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 <[email protected]>
---
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
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 <[email protected]>
Reviewed-by: Divya Indi <[email protected]>
> ---
> 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
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 <[email protected]>
> Reviewed-by: Divya Indi <[email protected]>
>
>
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 <[email protected]>
Reviewed-by: Divya Indi <[email protected]>
---
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