From: Fengguang Wu <fengguang.wu@intel.com>
To: Steven Rostedt <srostedt@redhat.com>
Cc: "Paul E. McKenney" <paulmck@linux.vnet.ibm.com>,
LKML <linux-kernel@vger.kernel.org>,
rostedt@goodmis.org
Subject: Re: __update_max_tr: rcu_read_lock() used illegally while idle!
Date: Tue, 31 Jul 2012 20:05:56 +0800 [thread overview]
Message-ID: <20120731120556.GB17252@localhost> (raw)
In-Reply-To: <1343662752.3847.2.camel@fedora>
On Mon, Jul 30, 2012 at 11:39:12AM -0400, Steven Rostedt wrote:
> On Tue, 2012-07-24 at 17:03 +0800, Fengguang Wu wrote:
> > Hi Steven,
>
> Hi Fengguang,
>
> Just an FYI, It's best to send email to my rostedt@goodmis.org account.
> I don't check my redhat account every day.
OK, sorry for forgetting about that!
> >
> > This looks like some old bug, so I directly report to you w/o trying
> > to bisect it. It only happens on the attached i386 randconfig and
> > happens in about half of the kvm boots.
> >
> > [ 1.380369] Testing tracer irqsoff: [ 1.524917]
> > [ 1.525217] ===============================
> > [ 1.525868] [ INFO: suspicious RCU usage. ]
> > [ 1.526556] 3.5.0+ #1289 Not tainted
> > [ 1.527124] -------------------------------
> > [ 1.527799] /c/kernel-tests/src/linux/include/linux/rcupdate.h:730 rcu_read_lock() used illegally while idle!
> > [ 1.529375]
> > [ 1.529375] other info that might help us debug this:
> > [ 1.529375]
> > [ 1.530667]
> > [ 1.530667] RCU used illegally from idle CPU!
> > [ 1.530667] rcu_scheduler_active = 1, debug_locks = 1
> > [ 1.532383] RCU used illegally from extended quiescent state!
> > [ 1.533297] 2 locks held by swapper/0/0:
> >
> > [ 1.533924] #0: [ 1.534271] (max_trace_lock){......}, at: [<410e9d67>] check_critical_timing+0x67/0x1b0
> > [ 1.534883] #1: (rcu_read_lock){.+.+..}, at: [<410e1ea0>] __update_max_tr+0x0/0x200
> >
> > [ 1.534883] stack backtrace:
> > [ 1.534883] Pid: 0, comm: swapper/0 Not tainted 3.5.0+ #1289
> > [ 1.534883] Call Trace:
> > [ 1.534883] [<41093a76>] lockdep_rcu_suspicious+0xc6/0x100
> > [ 1.534883] [<410e2071>] __update_max_tr+0x1d1/0x200
>
> This is very weird because __update_max_tr does not use rcu_read lock().
> If you still have the kernel around (or can reproduce it), can you show
> the objdump of the __update_max_tr function. I wonder if some debug
> option requires RCU usage somewhere there.
Here is part of trace.s, where lockdep_rcu_suspicious shows up in 3
places:
.LFE2107:
.size tracing_record_cmdline, .-tracing_record_cmdline
.section .rodata.str1.1
.LC50:
.string "rcu_read_lock() used illegally while idle"
.LC51:
.string "/c/wfg/linux/include/linux/rcupdate.h"
.LC52:
.string "suspicious rcu_dereference_check() usage"
.LC53:
.string "rcu_read_unlock() used illegally while idle"
.text
.type __update_max_tr, @function
__update_max_tr:
.LFB2091:
.loc 4 661 0
.cfi_startproc
.LVL1255:
.L796:
pushl %ebp #
.LCFI356:
.cfi_def_cfa_offset 8
.cfi_offset 5, -8
movl %esp, %ebp #,
.LCFI357:
.cfi_def_cfa_register 5
pushl %edi #
pushl %esi #
pushl %ebx #
.cfi_offset 7, -12
.cfi_offset 6, -16
.cfi_offset 3, -20
.loc 4 662 0
leal 4(%ecx), %edi #, tmp91
.loc 4 661 0
pushl %ebx #
.loc 4 662 0
movl 8(%eax,%edi,4), %esi # tr_1(D)->data, data
.LVL1256:
.loc 4 661 0
movl %edx, %ebx # tsk, tsk
.loc 4 665 0
movl %ecx, max_tr+4 # cpu, max_tr.cpu
.loc 4 673 0
movl $4, %ecx #, tmp102
.LVL1257:
.loc 4 666 0
movl 44(%esi), %eax # data_3->preempt_timestamp, data_3->preempt_timestamp
.LVL1258:
movl 48(%esi), %edx # data_3->preempt_timestamp, data_3->preempt_timestamp
.LVL1259:
movl %eax, max_tr+12 # data_3->preempt_timestamp, max_tr.time_start
.loc 4 669 0
movl tracing_max_latency, %eax # tracing_max_latency, tracing_max_latency
.loc 4 666 0
movl %edx, max_tr+16 # data_3->preempt_timestamp, max_tr.time_start
.loc 4 668 0
movl max_tr+8(,%edi,4), %edi # max_tr.data,
.loc 4 669 0
movl %eax, 12(%edi) # tracing_max_latency, max_data_5->saved_latency
.loc 4 670 0
movl 16(%esi), %eax # data_3->critical_start, D.35758
movl %edi, %edx #,
.loc 4 668 0
movl %edi, -16(%ebp) #, %sfp
.LVL1260:
.loc 4 670 0
movl %eax, 16(%edi) # D.35758, max_data_5->critical_start
.loc 4 671 0
movl 20(%esi), %eax # data_3->critical_end, D.35759
.loc 4 673 0
leal 468(%ebx), %esi #, tmp99
.LVL1261:
.loc 4 671 0
movl %eax, 20(%edi) # D.35759, max_data_5->critical_end
.loc 4 673 0
movl %edi, %eax # tmp1, tmp98
addl $60, %eax #, tmp98
movl %eax, %edi # tmp98, tmp100
rep movsl
.loc 4 674 0
movl 248(%ebx), %eax # tsk_9(D)->pid, D.35762
movl %eax, 52(%edx) # D.35762, max_data_5->pid
.LBB1126:
.LBB1127:
.LBB1128:
.file 20 "/c/wfg/linux/include/linux/rcupdate.h"
.loc 20 721 0
call __rcu_read_lock #
.LVL1262:
.LBB1129:
.LBB1130:
.loc 20 276 0
xorl %ecx, %ecx #
xorl %edx, %edx #
movl $rcu_lock_map, %eax #,
pushl $.L796 #
pushl $0 #
pushl $1 #
pushl $2 #
call lock_acquire #
.LVL1263:
.LBE1130:
.LBE1129:
.LBB1131:
.loc 20 724 0
call debug_lockdep_rcu_enabled #
.LVL1264:
addl $16, %esp #,
testl %eax, %eax # D.38819
je .L798 #,
cmpb $0, __warned.7078 #, __warned
jne .L798 #,
call rcu_is_cpu_idle #
.LVL1265:
testl %eax, %eax # D.38816
je .L798 #,
movl $.LC50, %ecx #,
movl $725, %edx #,
movl $.LC51, %eax #,
movb $1, __warned.7078 #, __warned
call lockdep_rcu_suspicious #
.LVL1266:
.L798:
.LBE1131:
.LBE1128:
.LBE1127:
.LBB1132:
.loc 4 675 0
movl 460(%ebx), %esi # tsk_9(D)->real_cred, _________p1
.LVL1267:
.LBB1133:
call debug_lockdep_rcu_enabled #
.LVL1268:
testl %eax, %eax # D.35763
je .L801 #,
.loc 4 675 0 is_stmt 0 discriminator 1
cmpb $0, __warned.29430 #, __warned
jne .L801 #,
.LBB1134:
.LBB1135:
.loc 20 311 0 is_stmt 1
call debug_lockdep_rcu_enabled #
.LVL1269:
testl %eax, %eax # D.38826
je .L801 #,
.loc 20 313 0
call rcu_is_cpu_idle #
.LVL1270:
testl %eax, %eax # D.38824
je .L803 #,
.L804:
.LBE1135:
.LBE1134:
.loc 4 675 0
movl $.LC52, %ecx #,
movl $675, %edx #,
movl $.LC25, %eax #,
movb $1, __warned.29430 #, __warned
call lockdep_rcu_suspicious #
.LVL1271:
jmp .L801 #
.L803:
.LBB1137:
.LBB1136:
.loc 20 317 0
movl $rcu_lock_map, %eax #,
call lock_is_held #
.LVL1272:
.LBE1136:
.LBE1137:
.loc 4 675 0
testl %eax, %eax # D.38823
je .L804 #,
.L801:
.LBE1133:
.LBE1132:
.loc 4 675 0 is_stmt 0 discriminator 2
movl 4(%esi), %esi # _________p1_13->uid, ___val
.LVL1273:
.LBB1138:
.LBB1139:
.LBB1140:
.loc 20 745 0 is_stmt 1 discriminator 2
call debug_lockdep_rcu_enabled #
.LVL1274:
testl %eax, %eax # D.38830
je .L806 #,
.loc 20 745 0 is_stmt 0
cmpb $0, __warned.7082 #, __warned
jne .L806 #,
call rcu_is_cpu_idle #
.LVL1275:
testl %eax, %eax # D.38827
je .L806 #,
movl $.LC53, %ecx #,
movl $746, %edx #,
movl $.LC51, %eax #,
movb $1, __warned.7082 #, __warned
call lockdep_rcu_suspicious #
.LVL1276:
.L806:
.LBE1140:
.LBB1141:
.LBB1142:
.loc 20 281 0 is_stmt 1
movl $.L806, %ecx #,
movl $1, %edx #,
movl $rcu_lock_map, %eax #,
call lock_release #
.LVL1277:
.LBE1142:
.LBE1141:
.loc 20 749 0
call __rcu_read_unlock #
.LVL1278:
.LBE1139:
.LBE1138:
.LBE1126:
.loc 4 675 0
movl -16(%ebp), %eax # %sfp,
.loc 4 676 0
movl -16(%ebp), %edx # %sfp,
.loc 4 675 0
movl %esi, 56(%eax) # ___val, max_data_5->uid
.loc 4 676 0
movl 36(%ebx), %eax # tsk_9(D)->static_prio, tmp103
subl $120, %eax #, tmp103
movl %eax, 28(%edx) # tmp103, max_data_5->nice
.loc 4 677 0
movl 148(%ebx), %eax # tsk_9(D)->policy, D.35776
movl %eax, 32(%edx) # D.35776, max_data_5->policy
.loc 4 678 0
movl 44(%ebx), %eax # tsk_9(D)->rt_priority, D.35777
movl %eax, 36(%edx) # D.35777, max_data_5->rt_priority
.loc 4 681 0
movl %ebx, %eax # tsk,
call tracing_record_cmdline #
.LVL1279:
.loc 4 682 0
leal -12(%ebp), %esp #,
popl %ebx #
.cfi_restore 3
.LVL1280:
popl %esi #
.cfi_restore 6
.LVL1281:
popl %edi #
.cfi_restore 7
popl %ebp #
.LCFI358:
.cfi_restore 5
.cfi_def_cfa 4, 4
ret
.cfi_endproc
.LFE2091:
next prev parent reply other threads:[~2012-07-31 12:06 UTC|newest]
Thread overview: 51+ messages / expand[flat|nested] mbox.gz Atom feed top
2012-07-24 9:03 __update_max_tr: rcu_read_lock() used illegally while idle! Fengguang Wu
2012-07-24 9:07 ` Testing tracer wakeup_rt: .. no entries found ..FAILED! Fengguang Wu
2012-07-25 1:31 ` Testing tracer wakeup: " Fengguang Wu
2012-07-30 15:45 ` Testing tracer wakeup_rt: " Steven Rostedt
2012-07-31 12:17 ` Fengguang Wu
2012-07-31 12:37 ` Avi Kivity
2012-07-31 12:43 ` Steven Rostedt
2012-07-31 12:50 ` Avi Kivity
2012-07-31 13:13 ` Steven Rostedt
2012-07-31 23:43 ` Fengguang Wu
2012-07-31 23:51 ` Steven Rostedt
2012-07-31 23:57 ` Paul E. McKenney
2012-08-01 0:09 ` Steven Rostedt
2012-08-01 0:18 ` Paul E. McKenney
2012-08-01 0:43 ` pci_get_subsys: GFP_KERNEL allocations with IRQs disabled Fengguang Wu
2012-08-22 2:50 ` Fengguang Wu
2012-08-22 7:49 ` Feng Tang
2012-08-22 13:02 ` Fengguang Wu
2012-08-22 18:02 ` Bjorn Helgaas
2012-08-23 5:45 ` Feng Tang
2012-08-23 7:45 ` [PATCH 1/2] PCI: Use local parameter pci_device_id for pci_get_subsys/class() Feng Tang
2012-09-08 1:00 ` Yinghai Lu
2012-09-08 1:32 ` Yinghai Lu
2012-09-08 1:59 ` Greg Kroah-Hartman
2012-09-08 13:42 ` Fengguang Wu
2012-09-08 15:30 ` Yinghai Lu
2012-09-08 15:34 ` Feng Tang
2012-09-08 18:40 ` Yinghai Lu
2012-09-08 21:06 ` Bjorn Helgaas
2012-08-23 7:45 ` [PATCH 2/2] PCI: Remove the obsolete no_pci_devices() check Feng Tang
2012-07-31 23:57 ` Testing tracer wakeup_rt: .. no entries found ..FAILED! Fengguang Wu
2012-08-07 13:29 ` Steven Rostedt
2012-08-07 13:32 ` Fengguang Wu
2012-08-21 15:16 ` [tip:perf/core] tracing: Fix wakeup_rt self test on virtual machines tip-bot for Steven Rostedt
2012-07-30 15:39 ` __update_max_tr: rcu_read_lock() used illegally while idle! Steven Rostedt
2012-07-31 12:05 ` Fengguang Wu [this message]
2012-07-31 12:10 ` Fengguang Wu
2012-07-31 13:44 ` Steven Rostedt
2012-07-31 14:41 ` Paul E. McKenney
2012-07-31 13:33 ` Steven Rostedt
2012-07-31 14:44 ` Paul E. McKenney
2012-07-31 14:51 ` Steven Rostedt
2012-07-31 14:56 ` Steven Rostedt
2012-07-31 15:18 ` Paul E. McKenney
2012-07-31 15:45 ` Steven Rostedt
2012-07-31 17:17 ` Paul E. McKenney
2012-07-31 17:24 ` Steven Rostedt
2012-07-31 17:44 ` Paul E. McKenney
2012-07-31 18:06 ` Steven Rostedt
2012-07-31 18:21 ` Paul E. McKenney
2012-07-31 15:00 ` Paul E. McKenney
Reply instructions:
You may reply publicly 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=20120731120556.GB17252@localhost \
--to=fengguang.wu@intel.com \
--cc=linux-kernel@vger.kernel.org \
--cc=paulmck@linux.vnet.ibm.com \
--cc=rostedt@goodmis.org \
--cc=srostedt@redhat.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
Be sure your reply has a Subject: header at the top and a blank line
before the message body.
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox