From: Steven Rostedt <rostedt@goodmis.org>
To: Fengguang Wu <fengguang.wu@intel.com>
Cc: Steven Rostedt <srostedt@redhat.com>,
"Paul E. McKenney" <paulmck@linux.vnet.ibm.com>,
LKML <linux-kernel@vger.kernel.org>,
David Howells <dhowells@redhat.com>
Subject: Re: __update_max_tr: rcu_read_lock() used illegally while idle!
Date: Tue, 31 Jul 2012 09:33:45 -0400 [thread overview]
Message-ID: <1343741625.27983.39.camel@gandalf.stny.rr.com> (raw)
In-Reply-To: <20120731120556.GB17252@localhost>
On Tue, 2012-07-31 at 20:05 +0800, Fengguang Wu wrote:
> 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
Found it (and Cc'd David).
In __update_max_tr() we have:
max_data = task_uid(tsk);
where task_uid() is:
#define task_uid(task) (task_cred_xxx((task), uid))
#define task_cred_xxx(task, xxx) \
({ \
__typeof__(((struct cred *)NULL)->xxx) ___val; \
rcu_read_lock(); \
___val = __task_cred((task))->xxx; \
rcu_read_unlock(); \
___val; \
})
The __update_max_tr() is called at every location interrupts are enabled
(and a max time is discovered). But now this can include places that
rcu_read_lock can not be called, I'm not sure how to handle this. Is
there a non rcu way to get a tasks uid?
-- Steve
> .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 13:33 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
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 [this message]
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=1343741625.27983.39.camel@gandalf.stny.rr.com \
--to=rostedt@goodmis.org \
--cc=dhowells@redhat.com \
--cc=fengguang.wu@intel.com \
--cc=linux-kernel@vger.kernel.org \
--cc=paulmck@linux.vnet.ibm.com \
--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.