BUG: spinlock trylock failure on UP on CPU#0, vgchange/936

BUG: spinlock trylock failure on UP on CPU#0, vgchange/936

[Christian Kujau]

Hi,

today's git checkout boots fine on powerpc32, but has this message during 
bootup:

BUG: spinlock trylock failure on UP on CPU#0, vgchange/936
 lock: ef32a9f8, .magic: dead4ead, .owner: vgchange/936, .owner_cpu: 0
Call Trace:
[eed459e0] [c0009de4] show_stack+0x70/0x1bc (unreliable)
[eed45a20] [c0326da8] spin_dump+0x70/0xe0
[eed45a30] [c0326f8c] do_raw_spin_trylock+0x58/0x70
[eed45a40] [c0512b28] _raw_spin_trylock+0x34/0xa0
[eed45a60] [c02f5510] put_io_context+0xd8/0x184
[eed45a80] [c0303428] __cfq_slice_expired+0x1e4/0x43c
[eed45ac0] [c03053d8] cfq_insert_request+0x264/0x5b0
[eed45ae0] [c02edef4] __elv_add_request+0x1a4/0x2d4
[eed45af0] [c02f1024] blk_flush_plug_list+0x22c/0x270
[eed45b20] [c05112dc] io_schedule+0x74/0xec
[eed45b30] [c0110f88] dio_await_completion+0x60/0xf4
[eed45b50] [c0112d0c] __blockdev_direct_IO+0x1b80/0x3574
[eed45d70] [c010f4a4] blkdev_direct_IO+0x54/0x64
[eed45d90] [c009a424] generic_file_aio_read+0x7b8/0x808
[eed45e40] [c00d4f68] do_sync_read+0xb8/0x144
[eed45ef0] [c00d6168] vfs_read+0xcc/0x1c0
[eed45f10] [c00d6394] sys_read+0x58/0xc8
[eed45f40] [c00127a0] ret_from_syscall+0x0/0x38
--- Exception: c01 at 0xfe52b90
    LR = 0x1003e834

The system is running fine so far and has before with 3.2.0-rc7, without 
that warning. The "vgchange" could be the result of some LVM2 initscripts 
(lvm2-2.02.66-5 are installed on this Debian/stable system), but there are 
no LVM disks anywhere on the system.

Full .config & dmesg: http://nerdbynature.de/bits/3.2.0/

Is this BUG something to worry about?

Thanks,
Christian.
-- 
BOFH excuse #100:

IRQ dropout

Re: BUG: spinlock trylock failure on UP on CPU#0, vgchange/936

[Christian Kujau]

On Wed, 18 Jan 2012 at 00:18, Christian Kujau wrote:
> today's git checkout boots fine on powerpc32, but has this message during 
> bootup:
> 
> BUG: spinlock trylock failure on UP on CPU#0, vgchange/936
>  lock: ef32a9f8, .magic: dead4ead, .owner: vgchange/936, .owner_cpu: 0
> Call Trace:

Still happening with 3.3.0-rc1.

Anyone?

Thanks,
Christian.

> [eed459e0] [c0009de4] show_stack+0x70/0x1bc (unreliable)
> [eed45a20] [c0326da8] spin_dump+0x70/0xe0
> [eed45a30] [c0326f8c] do_raw_spin_trylock+0x58/0x70
> [eed45a40] [c0512b28] _raw_spin_trylock+0x34/0xa0
> [eed45a60] [c02f5510] put_io_context+0xd8/0x184
> [eed45a80] [c0303428] __cfq_slice_expired+0x1e4/0x43c
> [eed45ac0] [c03053d8] cfq_insert_request+0x264/0x5b0
> [eed45ae0] [c02edef4] __elv_add_request+0x1a4/0x2d4
> [eed45af0] [c02f1024] blk_flush_plug_list+0x22c/0x270
> [eed45b20] [c05112dc] io_schedule+0x74/0xec
> [eed45b30] [c0110f88] dio_await_completion+0x60/0xf4
> [eed45b50] [c0112d0c] __blockdev_direct_IO+0x1b80/0x3574
> [eed45d70] [c010f4a4] blkdev_direct_IO+0x54/0x64
> [eed45d90] [c009a424] generic_file_aio_read+0x7b8/0x808
> [eed45e40] [c00d4f68] do_sync_read+0xb8/0x144
> [eed45ef0] [c00d6168] vfs_read+0xcc/0x1c0
> [eed45f10] [c00d6394] sys_read+0x58/0xc8
> [eed45f40] [c00127a0] ret_from_syscall+0x0/0x38
> --- Exception: c01 at 0xfe52b90
>     LR = 0x1003e834
> 
> The system is running fine so far and has before with 3.2.0-rc7, without 
> that warning. The "vgchange" could be the result of some LVM2 initscripts 
> (lvm2-2.02.66-5 are installed on this Debian/stable system), but there are 
> no LVM disks anywhere on the system.
> 
> Full .config & dmesg: http://nerdbynature.de/bits/3.2.0/
> 
> Is this BUG something to worry about?
> 
> Thanks,
> Christian.
> -- 
> BOFH excuse #100:
> 
> IRQ dropout
> --
> To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
> Please read the FAQ at  http://www.tux.org/lkml/
> 

-- 
BOFH excuse #63:

not properly grounded, please bury computer

Re: BUG: spinlock trylock failure on UP on CPU#0, vgchange/936

[Jens Axboe]

On 2012-01-21 12:42, Christian Kujau wrote:
> On Wed, 18 Jan 2012 at 00:18, Christian Kujau wrote:
>> today's git checkout boots fine on powerpc32, but has this message during 
>> bootup:
>>
>> BUG: spinlock trylock failure on UP on CPU#0, vgchange/936
>>  lock: ef32a9f8, .magic: dead4ead, .owner: vgchange/936, .owner_cpu: 0
>> Call Trace:
> 
> Still happening with 3.3.0-rc1.

Can you try and pull:

git://git.kernel.dk/linux-block.git for-linus

and see if it helps?

-- 
Jens Axboe

Re: BUG: spinlock trylock failure on UP on CPU#0, vgchange/936

[Christian Kujau]

On Sat, 21 Jan 2012 at 13:46, Jens Axboe wrote:
> Can you try and pull:
> 
> git://git.kernel.dk/linux-block.git for-linus
> 
> and see if it helps?

Pulled, compiled, bootet - but the BUG: stays. Please see .config and full 
dmesg: http://nerdbynature.de/bits/3.2.0/   (the 3.3.0-rc1 files)

Note that I don't have an actual problem here: the machine (PowerBook G4) 
is booting & running fine, I'm currently not using any LVM devices, so 
it's merely the BUG: being printed during bootup I'm whining about.

Thanks,
Christian.
-- 
BOFH excuse #292:

We ran out of dial tone and we're and waiting for the phone company to deliver another bottle.

Re: BUG: spinlock trylock failure on UP on CPU#0, vgchange/936

[Jens Axboe]

On 01/21/2012 11:35 PM, Christian Kujau wrote:
> On Sat, 21 Jan 2012 at 13:46, Jens Axboe wrote:
>> Can you try and pull:
>>
>> git://git.kernel.dk/linux-block.git for-linus
>>
>> and see if it helps?
> 
> Pulled, compiled, bootet - but the BUG: stays. Please see .config and full 
> dmesg: http://nerdbynature.de/bits/3.2.0/   (the 3.3.0-rc1 files)
> 
> Note that I don't have an actual problem here: the machine (PowerBook G4) 
> is booting & running fine, I'm currently not using any LVM devices, so 
> it's merely the BUG: being printed during bootup I'm whining about.

What about with this on top?


diff --git a/block/blk-core.c b/block/blk-core.c
index e6c05a9..75eba5c 100644
--- a/block/blk-core.c
+++ b/block/blk-core.c
@@ -1283,7 +1283,7 @@ static bool attempt_plug_merge(struct request_queue *q, struct bio *bio,
 		if (rq->q != q)
 			continue;
 
-		el_ret = elv_try_merge(rq, bio);
+		el_ret = blk_try_merge(rq, bio);
 		if (el_ret == ELEVATOR_BACK_MERGE) {
 			ret = bio_attempt_back_merge(q, rq, bio);
 			if (ret)
diff --git a/block/blk-merge.c b/block/blk-merge.c
index cfcc37c..ee9ec90 100644
--- a/block/blk-merge.c
+++ b/block/blk-merge.c
@@ -471,3 +471,59 @@ int blk_attempt_req_merge(struct request_queue *q, struct request *rq,
 {
 	return attempt_merge(q, rq, next);
 }
+
+int blk_rq_merge_ok(struct request *rq, struct bio *bio)
+{
+	if (!rq_mergeable(rq))
+		return 0;
+
+	/*
+	 * Don't merge file system requests and discard requests
+	 */
+	if ((bio->bi_rw & REQ_DISCARD) != (rq->bio->bi_rw & REQ_DISCARD))
+		return 0;
+
+	/*
+	 * Don't merge discard requests and secure discard requests
+	 */
+	if ((bio->bi_rw & REQ_SECURE) != (rq->bio->bi_rw & REQ_SECURE))
+		return 0;
+
+	/*
+	 * different data direction or already started, don't merge
+	 */
+	if (bio_data_dir(bio) != rq_data_dir(rq))
+		return 0;
+
+	/*
+	 * must be same device and not a special request
+	 */
+	if (rq->rq_disk != bio->bi_bdev->bd_disk || rq->special)
+		return 0;
+
+	/*
+	 * only merge integrity protected bio into ditto rq
+	 */
+	if (bio_integrity(bio) != blk_integrity_rq(rq))
+		return 0;
+
+	return 1;
+}
+EXPORT_SYMBOL(blk_rq_merge_ok);
+
+int blk_try_merge(struct request *__rq, struct bio *bio)
+{
+	int ret = ELEVATOR_NO_MERGE;
+
+	/*
+	 * we can merge and sequence is ok, check if it's possible
+	 */
+	if (blk_rq_merge_ok(__rq, bio)) {
+		if (blk_rq_pos(__rq) + blk_rq_sectors(__rq) == bio->bi_sector)
+			ret = ELEVATOR_BACK_MERGE;
+		else if (blk_rq_pos(__rq) - bio_sectors(bio) == bio->bi_sector)
+			ret = ELEVATOR_FRONT_MERGE;
+	}
+
+	return ret;
+}
diff --git a/block/blk.h b/block/blk.h
index 7efd772..a117fa9 100644
--- a/block/blk.h
+++ b/block/blk.h
@@ -137,6 +137,8 @@ int blk_attempt_req_merge(struct request_queue *q, struct request *rq,
 				struct request *next);
 void blk_recalc_rq_segments(struct request *rq);
 void blk_rq_set_mixed_merge(struct request *rq);
+int blk_rq_merge_ok(struct request *rq, struct bio *bio);
+int blk_try_merge(struct request *rq, struct bio *bio);
 
 void blk_queue_congestion_threshold(struct request_queue *q);
 
diff --git a/block/elevator.c b/block/elevator.c
index 91e18f8..a1a75f7 100644
--- a/block/elevator.c
+++ b/block/elevator.c
@@ -72,39 +72,8 @@ static int elv_iosched_allow_merge(struct request *rq, struct bio *bio)
  */
 int elv_rq_merge_ok(struct request *rq, struct bio *bio)
 {
-	if (!rq_mergeable(rq))
+	if (!blk_rq_merge_ok(rq, bio))
 		return 0;
-
-	/*
-	 * Don't merge file system requests and discard requests
-	 */
-	if ((bio->bi_rw & REQ_DISCARD) != (rq->bio->bi_rw & REQ_DISCARD))
-		return 0;
-
-	/*
-	 * Don't merge discard requests and secure discard requests
-	 */
-	if ((bio->bi_rw & REQ_SECURE) != (rq->bio->bi_rw & REQ_SECURE))
-		return 0;
-
-	/*
-	 * different data direction or already started, don't merge
-	 */
-	if (bio_data_dir(bio) != rq_data_dir(rq))
-		return 0;
-
-	/*
-	 * must be same device and not a special request
-	 */
-	if (rq->rq_disk != bio->bi_bdev->bd_disk || rq->special)
-		return 0;
-
-	/*
-	 * only merge integrity protected bio into ditto rq
-	 */
-	if (bio_integrity(bio) != blk_integrity_rq(rq))
-		return 0;
-
 	if (!elv_iosched_allow_merge(rq, bio))
 		return 0;
 
@@ -114,19 +83,13 @@ EXPORT_SYMBOL(elv_rq_merge_ok);
 
 int elv_try_merge(struct request *__rq, struct bio *bio)
 {
-	int ret = ELEVATOR_NO_MERGE;
-
 	/*
 	 * we can merge and sequence is ok, check if it's possible
 	 */
-	if (elv_rq_merge_ok(__rq, bio)) {
-		if (blk_rq_pos(__rq) + blk_rq_sectors(__rq) == bio->bi_sector)
-			ret = ELEVATOR_BACK_MERGE;
-		else if (blk_rq_pos(__rq) - bio_sectors(bio) == bio->bi_sector)
-			ret = ELEVATOR_FRONT_MERGE;
-	}
+	if (elv_rq_merge_ok(__rq, bio))
+		return blk_try_merge(__rq, bio);
 
-	return ret;
+	return ELEVATOR_NO_MERGE;
 }
 
 static struct elevator_type *elevator_find(const char *name)


-- 
Jens Axboe

Re: BUG: spinlock trylock failure on UP on CPU#0, vgchange/936

[Christian Kujau]

On Sun, 22 Jan 2012 at 11:30, Jens Axboe wrote:
> What about with this on top?

Will try. A compile on this box takes almost two hours (PowerBook G4, 
throttled to 70MHz), would it be enough to remove the block/*.o files and 
continue from there?

Thanks,
Christian.
-- 
BOFH excuse #17:

fat electrons in the lines

Re: BUG: spinlock trylock failure on UP on CPU#0, vgchange/936

[Christian Kujau]

On Sun, 22 Jan 2012 at 02:36, Christian Kujau wrote:
> On Sun, 22 Jan 2012 at 11:30, Jens Axboe wrote:
> > What about with this on top?
> 
> Will try. A compile on this box takes almost two hours (PowerBook G4, 
> throttled to 70MHz), would it be enough to remove the block/*.o files and 
> continue from there?

OK, I did that. With the pull from linux-block.git ("for-linus") and your 
diff[0], the BUG is still there:

[   15.048991] BUG: spinlock trylock failure on UP on CPU#0, vgchange/911
[   15.050579]  lock: ef32a9f8, .magic: dead4ead, .owner: vgchange/911, .owner_cpu: 0
[   15.052081] Call Trace:
[   15.053561] [eecaf9e0] [c0009de4] show_stack+0x70/0x1bc (unreliable)
[   15.055078] [eecafa20] [c0326d64] spin_dump+0x70/0xe0
[   15.056576] [eecafa30] [c0326f48] do_raw_spin_trylock+0x58/0x70
[   15.058052] [eecafa40] [c0512b88] _raw_spin_trylock+0x34/0xa0
[   15.059496] [eecafa60] [c02f53f4] put_io_context+0xd8/0x184
[   15.060953] [eecafa80] [c030343c] __cfq_slice_expired+0x1e4/0x43c
[   15.062426] [eecafac0] [c03053bc] cfq_insert_request+0x234/0x558
[   15.063908] [eecafae0] [c02edc00] __elv_add_request+0x1a4/0x2d4
[   15.065371] [eecafaf0] [c02f0f14] blk_flush_plug_list+0x22c/0x270
[   15.066833] [eecafb20] [c051133c] io_schedule+0x74/0xec
[   15.068270] [eecafb30] [c0110f1c] dio_await_completion+0x60/0xf4
[   15.069692] [eecafb50] [c0112ca0] __blockdev_direct_IO+0x1b80/0x3574
[   15.071110] [eecafd70] [c010f438] blkdev_direct_IO+0x54/0x64
[   15.072512] [eecafd90] [c009a424] generic_file_aio_read+0x7b8/0x808
[   15.073890] [eecafe40] [c00d4f68] do_sync_read+0xb8/0x144
[   15.075254] [eecafef0] [c00d6168] vfs_read+0xcc/0x1c0
[   15.076610] [eecaff10] [c00d6394] sys_read+0x58/0xc8
[   15.077958] [eecaff40] [c00127a0] ret_from_syscall+0x0/0x38
[   15.079299] --- Exception: c01 at 0xfe52b90
[   15.079302]     LR = 0x1003e834


As I said before, I do have lvm2 tools installed, but I'm not actually 
using LVM. Grepping through the initscripts, the lvm2 init script 
seems to be doing the following during bootup:

  do_start()
  {
        modprobe dm-mod 2> /dev/null || :
        /sbin/vgscan --ignorelockingfailure --mknodes || :
        /sbin/vgchange -aly --ignorelockingfailure || return 2
  }


Running "vgchange -aly --ignorelockingfailure" again (that is, after 
the machine finished booting and printed the BUG already) does not print 
the BUG again, I guess that's intentional.

Thanks,
Christian.

[0] http://nerdbynature.de/bits/3.2.0/block-axboe-1.diff
-- 
BOFH excuse #262:

Our POP server was kidnapped by a weasel.

Re: BUG: spinlock trylock failure on UP on CPU#0, vgchange/936

[Jens Axboe]

On 2012-01-22 11:36, Christian Kujau wrote:
> On Sun, 22 Jan 2012 at 11:30, Jens Axboe wrote:
>> What about with this on top?
> 
> Will try. A compile on this box takes almost two hours (PowerBook G4, 
> throttled to 70MHz), would it be enough to remove the block/*.o files and 
> continue from there?

Yes, just recompiling block/*.o is enough.

-- 
Jens Axboe

Re: BUG: spinlock trylock failure on UP on CPU#0, vgchange/936

[Jens Axboe]

On 2012-01-22 12:38, Christian Kujau wrote:
> On Sun, 22 Jan 2012 at 02:36, Christian Kujau wrote:
>> On Sun, 22 Jan 2012 at 11:30, Jens Axboe wrote:
>>> What about with this on top?
>>
>> Will try. A compile on this box takes almost two hours (PowerBook G4, 
>> throttled to 70MHz), would it be enough to remove the block/*.o files and 
>> continue from there?
> 
> OK, I did that. With the pull from linux-block.git ("for-linus") and your 
> diff[0], the BUG is still there:
> 
> [   15.048991] BUG: spinlock trylock failure on UP on CPU#0, vgchange/911
> [   15.050579]  lock: ef32a9f8, .magic: dead4ead, .owner: vgchange/911, .owner_cpu: 0
> [   15.052081] Call Trace:
> [   15.053561] [eecaf9e0] [c0009de4] show_stack+0x70/0x1bc (unreliable)
> [   15.055078] [eecafa20] [c0326d64] spin_dump+0x70/0xe0
> [   15.056576] [eecafa30] [c0326f48] do_raw_spin_trylock+0x58/0x70
> [   15.058052] [eecafa40] [c0512b88] _raw_spin_trylock+0x34/0xa0
> [   15.059496] [eecafa60] [c02f53f4] put_io_context+0xd8/0x184
> [   15.060953] [eecafa80] [c030343c] __cfq_slice_expired+0x1e4/0x43c
> [   15.062426] [eecafac0] [c03053bc] cfq_insert_request+0x234/0x558
> [   15.063908] [eecafae0] [c02edc00] __elv_add_request+0x1a4/0x2d4
> [   15.065371] [eecafaf0] [c02f0f14] blk_flush_plug_list+0x22c/0x270
> [   15.066833] [eecafb20] [c051133c] io_schedule+0x74/0xec
> [   15.068270] [eecafb30] [c0110f1c] dio_await_completion+0x60/0xf4
> [   15.069692] [eecafb50] [c0112ca0] __blockdev_direct_IO+0x1b80/0x3574
> [   15.071110] [eecafd70] [c010f438] blkdev_direct_IO+0x54/0x64
> [   15.072512] [eecafd90] [c009a424] generic_file_aio_read+0x7b8/0x808
> [   15.073890] [eecafe40] [c00d4f68] do_sync_read+0xb8/0x144
> [   15.075254] [eecafef0] [c00d6168] vfs_read+0xcc/0x1c0
> [   15.076610] [eecaff10] [c00d6394] sys_read+0x58/0xc8
> [   15.077958] [eecaff40] [c00127a0] ret_from_syscall+0x0/0x38
> [   15.079299] --- Exception: c01 at 0xfe52b90
> [   15.079302]     LR = 0x1003e834
> 
> 
> As I said before, I do have lvm2 tools installed, but I'm not actually 
> using LVM. Grepping through the initscripts, the lvm2 init script 
> seems to be doing the following during bootup:
> 
>   do_start()
>   {
>         modprobe dm-mod 2> /dev/null || :
>         /sbin/vgscan --ignorelockingfailure --mknodes || :
>         /sbin/vgchange -aly --ignorelockingfailure || return 2
>   }
> 
> 
> Running "vgchange -aly --ignorelockingfailure" again (that is, after 
> the machine finished booting and printed the BUG already) does not print 
> the BUG again, I guess that's intentional.

OK, I will see if I can reproduce this. Thanks for testing!

-- 
Jens Axboe