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 an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.