LKML Archive on lore.kernel.org
 help / color / Atom feed
From: Steven Rostedt <rostedt@goodmis.org>
To: "Paul E. McKenney" <paulmck@linux.vnet.ibm.com>
Cc: LKML <linux-kernel@vger.kernel.org>
Subject: [BUG] stack tracing causes: kernel/module.c:271 module_assert_mutex_or_preempt
Date: Wed, 5 Apr 2017 09:32:07 -0400
Message-ID: <20170405093207.404f8deb@gandalf.local.home> (raw)

Hi Paul,

My tests are triggering the following when I have lockdep enabled and
running the stack tracer:

------------[ cut here ]------------
WARNING: CPU: 0 PID: 0 at /work/autotest/nobackup/linux-test.git/kernel/module.c:271 module_assert_mutex_or_preempt+0x4f/0x51
Modules linked in: ppdev parport_pc parport [last unloaded: trace_events_sample]
CPU: 0 PID: 0 Comm: swapper/0 Not tainted 4.11.0-rc3-test+ #48
Hardware name: MSI MS-7823/CSM-H87M-G43 (MS-7823), BIOS V1.6 02/22/2014
Call Trace:

===============================
[ ERR: suspicious RCU usage.  ]
4.11.0-rc3-test+ #48 Not tainted
-------------------------------
/work/autotest/nobackup/linux-test.git/include/linux/rcupdate.h:837 rcu_read_lock() used illegally while idle!

other info that might help us debug this:


RCU used illegally from idle CPU!
rcu_scheduler_active = 2, debug_locks = 0
RCU used illegally from extended quiescent state!
1 lock held by swapper/0/0:
 #0:  (rcu_read_lock){......}, at: [<ffffffff810ebee3>] rcu_read_lock+0x0/0x61

stack backtrace:
CPU: 0 PID: 0 Comm: swapper/0 Not tainted 4.11.0-rc3-test+ #48
Hardware name: MSI MS-7823/CSM-H87M-G43 (MS-7823), BIOS V1.6 02/22/2014
Call Trace:
 dump_stack+0x68/0x92
 __warn+0xc2/0xdd
 ? 0xffffffffa0026077
 warn_slowpath_null+0x1d/0x1f
 module_assert_mutex_or_preempt+0x4f/0x51
 __module_address+0x2a/0xac
 ? 0xffffffffa0026077
 __module_text_address+0x12/0x59
 ? 0xffffffffa0026077
 is_module_text_address+0xe/0x16
 __kernel_text_address+0x2b/0x80
 ? 0xffffffffa0026077
 unwind_get_return_address+0x50/0x5c
 __save_stack_trace+0x76/0xbf
 ? rcu_eqs_enter_common.constprop.71+0x5/0x108
 save_stack_trace+0x1b/0x1d
 check_stack+0xec/0x24a
 stack_trace_call+0x40/0x53     <<-- This is the start of the stack tracer
 0xffffffffa0026077
 ? ftrace_graph_caller+0x78/0xa8
 ? trace_hardirqs_off+0xd/0xf
 ? rcu_eqs_enter_common.constprop.71+0x5/0x108
 rcu_eqs_enter_common.constprop.71+0x5/0x108   <<-- It appears to be testing the rcu internal code
 rcu_idle_enter+0x51/0x72
 ? rcu_eqs_enter_common.constprop.71+0x5/0x108
 ? rcu_idle_enter+0x51/0x72
 do_idle+0xbb/0x1e5
 cpu_startup_entry+0x1f/0x21
 rest_init+0x127/0x12d
 start_kernel+0x3f5/0x402
 x86_64_start_reservations+0x2f/0x31
 x86_64_start_kernel+0x17f/0x192
 start_cpu+0x14/0x14
 ? start_cpu+0x14/0x14
---[ end trace eeaad31bc52457e7 ]---


Now the check_stack() function in kernel/trace/trace_stack.c has the
following:

	/*
	 * RCU may not be watching, make it see us.
	 * The stack trace code uses rcu_sched.
	 */
	rcu_irq_enter();


What I'm guessing, is that because it is tracing the internals of the
rcu code, and checking its stack, the stack trace triggered in a
location where calling rcu_irq_enter() isn't sufficient to have rcu
become watchable.

I may add code to check if rcu is indeed watching after the
rcu_irq_enter() call, and if it still isn't to simply exit out.

Thoughts?

-- Steve

             reply index

Thread overview: 16+ messages / expand[flat|nested]  mbox.gz  Atom feed  top
2017-04-05 13:32 Steven Rostedt [this message]
2017-04-05 16:25 ` Paul E. McKenney
2017-04-05 16:45   ` Steven Rostedt
2017-04-05 17:59     ` Paul E. McKenney
2017-04-05 18:54       ` Steven Rostedt
2017-04-05 19:08         ` Paul E. McKenney
2017-04-05 19:21           ` Steven Rostedt
2017-04-05 19:39             ` Paul E. McKenney
2017-04-05 19:52               ` Steven Rostedt
2017-04-05 20:42                 ` Paul E. McKenney
2017-04-06  1:31                   ` Steven Rostedt
2017-04-06  4:07                     ` Paul E. McKenney
2017-04-06  2:12       ` Steven Rostedt
2017-04-06  4:15         ` Paul E. McKenney
2017-04-06 14:14           ` Steven Rostedt
2017-04-06 14:59             ` Paul E. McKenney

Reply instructions:

You may reply publically to this message via plain-text email
using any one of the following methods:

* Save the following mbox file, import it into your mail client,
  and reply-to-all from there: mbox

  Avoid top-posting and favor interleaved quoting:
  https://en.wikipedia.org/wiki/Posting_style#Interleaved_style

* Reply using the --to, --cc, and --in-reply-to
  switches of git-send-email(1):

  git send-email \
    --in-reply-to=20170405093207.404f8deb@gandalf.local.home \
    --to=rostedt@goodmis.org \
    --cc=linux-kernel@vger.kernel.org \
    --cc=paulmck@linux.vnet.ibm.com \
    /path/to/YOUR_REPLY

  https://kernel.org/pub/software/scm/git/docs/git-send-email.html

* If your mail client supports setting the In-Reply-To header
  via mailto: links, try the mailto: link

LKML Archive on lore.kernel.org

Archives are clonable:
	git clone --mirror https://lore.kernel.org/lkml/0 lkml/git/0.git
	git clone --mirror https://lore.kernel.org/lkml/1 lkml/git/1.git
	git clone --mirror https://lore.kernel.org/lkml/2 lkml/git/2.git
	git clone --mirror https://lore.kernel.org/lkml/3 lkml/git/3.git
	git clone --mirror https://lore.kernel.org/lkml/4 lkml/git/4.git
	git clone --mirror https://lore.kernel.org/lkml/5 lkml/git/5.git
	git clone --mirror https://lore.kernel.org/lkml/6 lkml/git/6.git
	git clone --mirror https://lore.kernel.org/lkml/7 lkml/git/7.git

	# If you have public-inbox 1.1+ installed, you may
	# initialize and index your mirror using the following commands:
	public-inbox-init -V2 lkml lkml/ https://lore.kernel.org/lkml \
		linux-kernel@vger.kernel.org
	public-inbox-index lkml

Example config snippet for mirrors

Newsgroup available over NNTP:
	nntp://nntp.lore.kernel.org/org.kernel.vger.linux-kernel


AGPL code for this site: git clone https://public-inbox.org/public-inbox.git