Re: __update_max_tr: rcu_read_lock() used illegally while idle!

["Paul E. McKenney" <paulmck@linux.vnet.ibm.com>]

On Tue, Jul 31, 2012 at 09:33:45AM -0400, Steven Rostedt wrote:
> 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?

OK, I will bite.  How about using something like RCU_NONIDLE(), either
directly or open-coded, to make it a legal call site?

							Thanx, Paul

> -- 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:
> 
>