[BUG] Error in copy_process, when enable CONFIG_PROVE_LOCKING.

[BUG] Error in copy_process, when enable CONFIG_PROVE_LOCKING.

[Nobuhiro Iwamatsu]

[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #1: Type: text/plain; charset="windows-1254", Size: 6188 bytes --]

Hi, all.

Error in copy_process, when enable CONFIG_PROVE_LOCKING.
This error has p->hardirqs_enabled in kernel.fork.c

 987 #ifdef CONFIG_PROVE_LOCKING
 988     DEBUG_LOCKS_WARN_ON(!p->hardirqs_enabled);
 989     DEBUG_LOCKS_WARN_ON(!p->softirqs_enabled);
 990 #endif
 991     retval = -EAGAIN;

The error message is as follows.
I am debuging this. Please teach if you know the revision method of
this problem.

------
   Image Name:   Linux-2.6.30-rc4-00170-gccc1956
   Image Type:   SuperH Linux Kernel Image (gzip compressed)
   Data Size:    2035930 Bytes =  1.9 MB
   Load Address: 88001000
   Entry Point:  88002000
   Verifying Checksum ... OK
   Uncompressing Kernel Image ... OK
[    0.000000] Linux version 2.6.30-rc4-00170-gccc1956
(iwamatsu@xps-iwamatsu) (gcc version 4.1.2 (Gentoo 4.1.2 p1.0.2)) #52
PREEMPT Tue May 12 13:26:25 JST 2009
[    0.000000] Boot params:
[    0.000000] ... MOUNT_ROOT_RDONLY - 00000000
[    0.000000] ... RAMDISK_FLAGS     - 00000000
[    0.000000] ... ORIG_ROOT_DEV     - 00000000
[    0.000000] ... LOADER_TYPE       - 00000000
[    0.000000] ... INITRD_START      - 00000000
[    0.000000] ... INITRD_SIZE       - 00000000
[    0.000000] Booting machvec: Highlander
[    0.000000] Renesas Solutions Highlander R7780MP support.
[    0.000000] Board version: 2 (revision 1), FPGA version: 2 (revision 1)
[    0.000000] Node 0: start_pfn = 0x8000, low = 0x10000
[    0.000000] Zone PFN ranges:
[    0.000000]   Normal   0x00008000 -> 0x00010000
[    0.000000] Movable zone start PFN for each node
[    0.000000] early_node_map[1] active PFN ranges
[    0.000000]     0: 0x00008000 -> 0x00010000
[    0.000000] On node 0 totalpages: 32768
[    0.000000] free_area_init_node: node 0, pgdat 8835d598,
node_mem_map 88831000
[    0.000000]   Normal zone: 256 pages used for memmap
[    0.000000]   Normal zone: 0 pages reserved
[    0.000000]   Normal zone: 32512 pages, LIFO batch:7
[    0.000000] Built 1 zonelists in Zone order, mobility grouping on.
Total pages: 32512
[    0.000000] Kernel command line: console=ttySC0,115200 root=/dev/nfs ip=bootp
[    0.000000] NR_IRQS:256
[    0.000000] Using r7780mp interrupt controller.
[    0.000000] PID hash table entries: 512 (order: 9, 2048 bytes)
[    0.000000] Lock dependency validator: Copyright (c) 2006 Red Hat,
Inc., Ingo Molnar
[    0.000000] ... MAX_LOCKDEP_SUBCLASSES:  8
[    0.000000] ... MAX_LOCK_DEPTH:          48
[    0.000000] ... MAX_LOCKDEP_KEYS:        8191
[    0.000000] ... CLASSHASH_SIZE:          4096
[    0.000000] ... MAX_LOCKDEP_ENTRIES:     8192
[    0.000000] ... MAX_LOCKDEP_CHAINS:      16384
[    0.000000] ... CHAINHASH_SIZE:          8192
[    0.000000]  memory used by lock dependency info: 2847 kB
[    0.000000]  per task-struct memory footprint: 1152 bytes
[    0.000000] Dentry cache hash table entries: 16384 (order: 4, 65536 bytes)
[    0.000000] Inode-cache hash table entries: 8192 (order: 3, 32768 bytes)
[    0.000000] Memory: 121400k/131072k available (2310k kernel code,
1134k data, 104k init)
[    0.000000] PVR\x10200a00 CVRs440010 PRR\0000920
[    0.000000] I-cache : n_ways=4 n_sets%6 way_incr92
[    0.000000] I-cache : entry_mask=0x00001fe0 alias_mask=0x00001000 n_aliases=2
[    0.000000] D-cache : n_ways=4 n_sets%6 way_incr92
[    0.000000] D-cache : entry_mask=0x00001fe0 alias_mask=0x00001000 n_aliases=2
[    0.000321] Using tmu for system timer
[    0.000376] Calibrating delay loop (skipped)... 384.00 BogoMIPS
PRESET (lpjv8000)
[    0.001523] Mount-cache hash table entries: 512
[    0.014202] CPU: SH7780
[    0.033495] net_namespace: 660 bytes
[    0.038498] NET: Registered protocol family 16
[    0.052935] PCI: Starting intialization.
[    0.052982] PCI: Found a Renesas SH7780 host controller, revision 0.
[    0.053010] PCI: Using configuration type 1
[    0.053205] registering PCI controller with io_map_base unset
[    0.060177] ------------[ cut here ]------------
[    0.060225] Badness at 88014c8e [verbose debug info unavailable]
[    0.060249]
[    0.060269] Pid : 6, Comm:           khelper
[    0.060299] CPU : 0                  Not tainted
(2.6.30-rc4-00170-gccc1956 #52)
[    0.060316]
[    0.060371] PC is at copy_process+0x14e/0xd88
[    0.060406] PR is at copy_process+0x142/0xd88
[    0.060435] PC  : 88014c8e SP  : 8f835e0c SR  : 40000101 TEA : 00000000
[    0.060477] R0  : 00000001 R1  : 00000000 R2  : 00000001 R3  : 00000007
[    0.060513] R4  : 8837a26c R5  : 882d5850 R6  : 8837a26c R7  : 8833aad0
[    0.060548] R8  : 8f874000 R9  : 00000000 R10 : 8f826060 R11 : fffffff4
[    0.060581] R12 : 8f86a100 R13 : 00000000 R14 : 8f835e0c
[    0.060613] MACH: 000211c5 MACL: 00004840 GBR : 00000000 PR  : 88014c82
[    0.060639]
[    0.060646] Call trace:
[    0.060701] [<88035224>] __lock_acquire+0x616/0x6a6
[    0.060742] [<88015a8c>] do_fork+0xf8/0x2b0
[    0.060788] [<880331ec>] trace_hardirqs_on_caller+0xd4/0x114
[    0.060842] [<88241074>] _spin_unlock_irq+0x20/0x64
[    0.060880] [<88035224>] __lock_acquire+0x616/0x6a6
[    0.060917] [<8800386c>] kernel_thread+0x48/0x70
[    0.060966] [<88024ecc>] ____call_usermodehelper+0x0/0x110
[    0.061009] [<88024ecc>] ____call_usermodehelper+0x0/0x110
[    0.061050] [<88003894>] kernel_thread_helper+0x0/0x14
[    0.061091] [<88024bac>] __call_usermodehelper+0x38/0x70
[    0.061134] [<88025dc0>] worker_thread+0x150/0x274
[    0.061172] [<88035b9c>] lock_release+0x0/0x198
[    0.061208] [<88024b74>] __call_usermodehelper+0x0/0x70
[    0.061248] [<88028cf0>] autoremove_wake_function+0x0/0x30
[    0.061285] [<88028bf2>] kthread+0x3e/0x70
[    0.061323] [<88025c70>] worker_thread+0x0/0x274
[    0.061359] [<8800389c>] kernel_thread_helper+0x8/0x14
[    0.061398] [<88028bb4>] kthread+0x0/0x70
[    0.061436] [<88003894>] kernel_thread_helper+0x0/0x14
[    0.061461]
[    0.061478] INFO: lockdep is turned off.
[    0.079578] bio: create slab <bio-0> at 0
[    0.084827] SCSI subsystem initialized
[    0.097912] libata version 3.00 loaded.


-- 
Nobuhiro Iwamatsu
--
To unsubscribe from this list: send the line "unsubscribe linux-sh" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: [BUG] Error in copy_process, when enable CONFIG_PROVE_LOCKING.

[Stuart MENEFY]

Nobuhiro Iwamatsu wrote:
> Error in copy_process, when enable CONFIG_PROVE_LOCKING.
> This error has p->hardirqs_enabled in kernel.fork.c
> 
>  987 #ifdef CONFIG_PROVE_LOCKING
>  988     DEBUG_LOCKS_WARN_ON(!p->hardirqs_enabled);
>  989     DEBUG_LOCKS_WARN_ON(!p->softirqs_enabled);
>  990 #endif
>  991     retval = -EAGAIN;
> 
> The error message is as follows.
> I am debuging this. Please teach if you know the revision method of
> this problem.

As it happens I was looking at this recently. I think there are some
missing calls to trace_hardirqs_on/off in the assembly
code. Unfortunately my kernel is quite different from the mainline in
this area, but you could try this patch which is an *untested* forward
port of the code I'm currently running successfully.

--

A couple of fixes are required for the IRQ tracing. Also switch to using
a macro which removes quite a few #ifdefs.

Signed-off-by: Stuart Menefy <stuart.menefy@st.com>
Index: x/arch/sh/kernel/cpu/sh3/entry.S
=================================--- x.orig/arch/sh/kernel/cpu/sh3/entry.S
+++ x/arch/sh/kernel/cpu/sh3/entry.S
@@ -217,6 +217,16 @@ ENTRY(sh_bios_handler)
 ! BL=0 on entry, on exit BL=1 (depending on r8).

 ENTRY(restore_regs)
+#ifdef CONFIG_TRACE_IRQFLAGS
+	mov	#OFF_SR, r0
+	mov.l	@(r0,r15), r0		! get status register
+	shlr2	r0
+	and	#0x3c, r0
+	cmp/eq	#0x3c, r0
+	bt	6f
+	TRACE_IRQS_ON
+6:
+#endif
 	mov.l	@r15+, r0
 	mov.l	@r15+, r1
 	mov.l	@r15+, r2
Index: x/arch/sh/kernel/entry-common.S
=================================--- x.orig/arch/sh/kernel/entry-common.S
+++ x/arch/sh/kernel/entry-common.S
@@ -45,7 +45,7 @@
  */

 #if defined(CONFIG_PREEMPT)
-#  define preempt_stop()	cli
+#  define preempt_stop()	cli; TRACE_IRQS_OFF
 #else
 #  define preempt_stop()
 #  define resume_kernel		__restore_all
@@ -55,11 +55,7 @@
 	.align	2
 ENTRY(exception_error)
 	!
-#ifdef CONFIG_TRACE_IRQFLAGS
-	mov.l	2f, r0
-	jsr	@r0
-	 nop
-#endif
+	TRACE_IRQS_ON
 	sti
 	mov.l	1f, r0
 	jmp	@r0
@@ -67,18 +63,10 @@ ENTRY(exception_error)

 	.align	2
 1:	.long	do_exception_error
-#ifdef CONFIG_TRACE_IRQFLAGS
-2:	.long	trace_hardirqs_on
-#endif

 	.align	2
 ret_from_exception:
 	preempt_stop()
-#ifdef CONFIG_TRACE_IRQFLAGS
-	mov.l	4f, r0
-	jsr	@r0
-	 nop
-#endif
 ENTRY(ret_from_irq)
 	!
 	mov	#OFF_SR, r0
@@ -125,11 +113,7 @@ noresched:
 ENTRY(resume_userspace)
 	! r8: current_thread_info
 	cli
-#ifdef CONFIG_TRACE_IRQFLAGS
-	mov.l	5f, r0
-	jsr	@r0
-	 nop
-#endif
+	TRACE_IRQS_OFF
 	mov.l	@(TI_FLAGS,r8), r0		! current_thread_info->flags
 	tst	#_TIF_WORK_MASK, r0
 	bt/s	__restore_all
@@ -156,11 +140,7 @@ work_resched:
 	jsr	@r1				! schedule
 	 nop
 	cli
-#ifdef CONFIG_TRACE_IRQFLAGS
-	mov.l	5f, r0
-	jsr	@r0
-	 nop
-#endif
+	TRACE_IRQS_OFF
 	!
 	mov.l	@(TI_FLAGS,r8), r0		! current_thread_info->flags
 	tst	#_TIF_WORK_MASK, r0
@@ -172,10 +152,6 @@ work_resched:
 1:	.long	schedule
 2:	.long	do_notify_resume
 3:	.long	resume_userspace
-#ifdef CONFIG_TRACE_IRQFLAGS
-4:	.long	trace_hardirqs_on
-5:	.long	trace_hardirqs_off
-#endif

 	.align	2
 syscall_exit_work:
@@ -184,11 +160,7 @@ syscall_exit_work:
 	tst	#_TIF_WORK_SYSCALL_MASK, r0
 	bt/s	work_pending
 	 tst	#_TIF_NEED_RESCHED, r0
-#ifdef CONFIG_TRACE_IRQFLAGS
-	mov.l	5f, r0
-	jsr	@r0
-	 nop
-#endif
+	TRACE_IRQS_ON
 	sti
 	mov	r15, r4
 	mov.l	8f, r0			! do_syscall_trace_leave
@@ -322,9 +294,10 @@ ENTRY(system_call)
 	 nop

 #ifdef CONFIG_TRACE_IRQFLAGS
-	mov.l	5f, r10
-	jsr	@r10
-	 nop
+	/* Need to preserve r3 */
+	mov	r3, r8
+	TRACE_IRQS_ON
+	mov	r8, r3
 #endif
 	sti

@@ -351,11 +324,7 @@ syscall_call:
 	!
 syscall_exit:
 	cli
-#ifdef CONFIG_TRACE_IRQFLAGS
-	mov.l	6f, r0
-	jsr	@r0
-	 nop
-#endif
+	TRACE_IRQS_OFF
 	!
 	get_current_thread_info r8, r0
 	mov.l	@(TI_FLAGS,r8), r0		! current_thread_info->flags
@@ -369,9 +338,5 @@ syscall_exit:
 #endif
 2:	.long	NR_syscalls
 3:	.long	sys_call_table
-#ifdef CONFIG_TRACE_IRQFLAGS
-5:	.long	trace_hardirqs_on
-6:	.long	trace_hardirqs_off
-#endif
 7:	.long	do_syscall_trace_enter
 8:	.long	do_syscall_trace_leave
Index: x/arch/sh/include/asm/entry-macros.S
=================================--- x.orig/arch/sh/include/asm/entry-macros.S
+++ x/arch/sh/include/asm/entry-macros.S
@@ -31,6 +31,37 @@
 #endif	
 	.endm

+#ifdef CONFIG_TRACE_IRQFLAGS
+
+	.macro	TRACE_IRQS_ON
+	mov.l	7834f, r0
+	jsr	@r0
+	 nop
+	bra	7835f
+	 nop
+	.balign	4
+7834:	.long	trace_hardirqs_on
+7835:
+	.endm
+	.macro	TRACE_IRQS_OFF
+	mov.l	7834f, r0
+	jsr	@r0
+	 nop
+	bra	7835f
+	 nop
+	.balign	4
+7834:	.long	trace_hardirqs_off
+7835:
+	.endm
+
+#else
+	.macro	TRACE_IRQS_ON
+	.endm
+
+	.macro	TRACE_IRQS_OFF
+	.endm
+#endif
+
 #if defined(CONFIG_CPU_SH2A) || defined(CONFIG_CPU_SH4)
 # define PREF(x)	pref	@x
 #else

Re: [BUG] Error in copy_process, when enable CONFIG_PROVE_LOCKING.

[Paul Mundt]

On Tue, May 12, 2009 at 01:15:22PM +0100, Stuart MENEFY wrote:
> Nobuhiro Iwamatsu wrote:
> > Error in copy_process, when enable CONFIG_PROVE_LOCKING.
> > This error has p->hardirqs_enabled in kernel.fork.c
> > 
> >  987 #ifdef CONFIG_PROVE_LOCKING
> >  988     DEBUG_LOCKS_WARN_ON(!p->hardirqs_enabled);
> >  989     DEBUG_LOCKS_WARN_ON(!p->softirqs_enabled);
> >  990 #endif
> >  991     retval = -EAGAIN;
> > 
> > The error message is as follows.
> > I am debuging this. Please teach if you know the revision method of
> > this problem.
> 
> As it happens I was looking at this recently. I think there are some
> missing calls to trace_hardirqs_on/off in the assembly
> code. Unfortunately my kernel is quite different from the mainline in
> this area, but you could try this patch which is an *untested* forward
> port of the code I'm currently running successfully.
> 
This deadlocks for me with PROVE_LOCKING enabled, though it is certainly
an improvement over what we had before. I'll try and debug it a bit more
over the next few days when I get some spare cycles. If you have your
kernel source available somewhere it would certainly make comparing the
differences easier.

Re: [BUG] Error in copy_process, when enable CONFIG_PROVE_LOCKING.

[Stuart MENEFY]

Paul Mundt wrote:
> On Tue, May 12, 2009 at 01:15:22PM +0100, Stuart MENEFY wrote:
>> Nobuhiro Iwamatsu wrote:
>>> Error in copy_process, when enable CONFIG_PROVE_LOCKING.
>>> This error has p->hardirqs_enabled in kernel.fork.c
>>>
>>>  987 #ifdef CONFIG_PROVE_LOCKING
>>>  988     DEBUG_LOCKS_WARN_ON(!p->hardirqs_enabled);
>>>  989     DEBUG_LOCKS_WARN_ON(!p->softirqs_enabled);
>>>  990 #endif
>>>  991     retval = -EAGAIN;
>>>
>>> The error message is as follows.
>>> I am debuging this. Please teach if you know the revision method of
>>> this problem.
>> As it happens I was looking at this recently. I think there are some
>> missing calls to trace_hardirqs_on/off in the assembly
>> code. Unfortunately my kernel is quite different from the mainline in
>> this area, but you could try this patch which is an *untested* forward
>> port of the code I'm currently running successfully.
>>
> This deadlocks for me with PROVE_LOCKING enabled, though it is certainly
> an improvement over what we had before. I'll try and debug it a bit more
> over the next few days when I get some spare cycles. If you have your
> kernel source available somewhere it would certainly make comparing the
> differences easier.

There's a git tree at:
  git://git.stlinux.com/stm/linux-sh4-2.6.23.y.git
now.

Stuart

Re: [BUG] Error in copy_process, when enable CONFIG_PROVE_LOCKING.

[Paul Mundt]

On Tue, May 12, 2009 at 01:40:35PM +0900, Nobuhiro Iwamatsu wrote:
> Error in copy_process, when enable CONFIG_PROVE_LOCKING.
> This error has p->hardirqs_enabled in kernel.fork.c
> 
>  987 #ifdef CONFIG_PROVE_LOCKING
>  988     DEBUG_LOCKS_WARN_ON(!p->hardirqs_enabled);
>  989     DEBUG_LOCKS_WARN_ON(!p->softirqs_enabled);
>  990 #endif
>  991     retval = -EAGAIN;
> 
> The error message is as follows.
> I am debuging this. Please teach if you know the revision method of
> this problem.
> 
This should be fixed now in current git. Can you give it a try?

Re: [BUG] Error in copy_process, when enable CONFIG_PROVE_LOCKING.

[Nobuhiro Iwamatsu]

2009/7/29 Paul Mundt <lethal@linux-sh.org>:
> On Tue, May 12, 2009 at 01:40:35PM +0900, Nobuhiro Iwamatsu wrote:
>> Error in copy_process, when enable CONFIG_PROVE_LOCKING.
>> This error has p->hardirqs_enabled in kernel.fork.c
>>
>>  987 #ifdef CONFIG_PROVE_LOCKING
>>  988     DEBUG_LOCKS_WARN_ON(!p->hardirqs_enabled);
>>  989     DEBUG_LOCKS_WARN_ON(!p->softirqs_enabled);
>>  990 #endif
>>  991     retval = -EAGAIN;
>>
>> The error message is as follows.
>> I am debuging this. Please teach if you know the revision method of
>> this problem.
>>
> This should be fixed now in current git. Can you give it a try?
>

OK.


-- 
Nobuhiro Iwamatsu / Debian Developer
   iwamatsu at {nigauri.org / debian.org}

Re: [BUG] Error in copy_process, when enable CONFIG_PROVE_LOCKING.

[Nobuhiro Iwamatsu]

Nobuhiro Iwamatsu wrote:
> 2009/7/29 Paul Mundt <lethal@linux-sh.org>:
>> On Tue, May 12, 2009 at 01:40:35PM +0900, Nobuhiro Iwamatsu wrote:
>>> Error in copy_process, when enable CONFIG_PROVE_LOCKING.
>>> This error has p->hardirqs_enabled in kernel.fork.c
>>>
>>>  987 #ifdef CONFIG_PROVE_LOCKING
>>>  988     DEBUG_LOCKS_WARN_ON(!p->hardirqs_enabled);
>>>  989     DEBUG_LOCKS_WARN_ON(!p->softirqs_enabled);
>>>  990 #endif
>>>  991     retval = -EAGAIN;
>>>
>>> The error message is as follows.
>>> I am debuging this. Please teach if you know the revision method of
>>> this problem.
>>>
>> This should be fixed now in current git. Can you give it a try?
>>
> 
> OK.

I checked this.
Work fine.

Best regards,
   Nobuhiro