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

[Steven Rostedt]

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


--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/