Re: [GIT PULL] Core block IO bits for 2.6.39 - early Oops

[Jens Axboe <jaxboe@fusionio.com>]

On 2011-03-25 13:33, Ted Ts'o wrote:
> On Fri, Mar 25, 2011 at 01:14:36PM +0100, Jens Axboe wrote:
>> But this plugging change is merged, so it is a very likely candidate.
>> With the oddness going on, I suspect that we end up flushing a plug that
>> resides on a stack that is no longer valid.
> 
> Ah, sorry, I was typing this while I was still doing my morning e-mail
> reading/deleting in bed, so I couldn't check to see if it had been
> merged already.
> 
> I'm downstairs now, and you could very well be right, since here's the
> the stack trace from the kvm console output, and it features
> flush_plug_list very prominently in the stack trace (see attached).
> 
>> So I'd really like to have something ala:
>>
>>         if (is_str_ptr_valid(current, ptr, size))
>>                 ...
>>
>> to aid the debugging.
> 
> Well, I can repro the problem in an hour or two of running xfstests
> under KVM, so I'm happy to try any debugging patches.  Let me know
> where you'd like that placed, and I'll do a run.

Tests are running here locally too, so far not much luck. Can you give
the patch at the end of this email a whirl?

>       	    	      	      	       	    - Ted
> 
> P.S.  Hmm, and I this one does have ext4 in the stack trace.  My bad;
> I misremembered.  The other one didn't, though.  (Oh, and this one
> died in test #130, but if it's related to some kind of plug/unplug
> race, it's probably quite random when it happens.)
> 
> BUG: unable to handle kernel NULL pointer dereference at 0000000c
> IP: [<c036429a>] cfq_insert_request+0x39/0x4a2
> *pdpt = 00000000017f0001 *pde = 0000000000000000 
> Oops: 0000 [#1] SMP DEBUG_PAGEALLOC
> last sysfs file: 
> Modules linked in:
> 
> Pid: 15723, comm: xfs_io Not tainted 2.6.38-08184-g108052f #1489 Bochs Bochs
> EIP: 0060:[<c036429a>] EFLAGS: 00010046 CPU: 0
> EIP is at cfq_insert_request+0x39/0x4a2
> EAX: 00000000 EBX: 00000000 ECX: c096e710 EDX: cb599870
> ESI: f596c000 EDI: cb599870 EBP: f6db3bfc ESP: f6db3bd0
>  DS: 007b ES: 007b FS: 00d8 GS: 0033 SS: 0068
> Process xfs_io (pid: 15723, ti=f6db2000 task=c5f6e7c0 task.ti=f6db2000)
> Stack:
>  f6db3c04 00000046 00000028 f6db3c14 00000046 00000000 c03573c8 c03573c8
>  cb599870 f5839d60 f6db3e84 f6db3c14 c0354613 00000006 02a00091 f5839d60
>  f6db3e84 f6db3c24 c03546a9 cb599870 f5839d60 f6db3c40 c03573dd f6db3e88
> Call Trace:
>  [<c03573c8>] ? flush_plug_list+0xa5/0x114
>  [<c03573c8>] ? flush_plug_list+0xa5/0x114
>  [<c0354613>] elv_insert+0x173/0x1a6
>  [<c03546a9>] __elv_add_request+0x63/0x67
>  [<c03573dd>] flush_plug_list+0xba/0x114
>  [<c035744c>] __blk_flush_plug+0x15/0x31
>  [<c0686899>] schedule+0x25b/0x6d9
>  [<c017c71d>] ? sched_clock_cpu+0x134/0x144
>  [<c03594f4>] ? __make_request+0x1fa/0x231
>  [<c06871ab>] schedule_timeout+0x1b/0x9b
>  [<c01876df>] ? mark_lock+0x1e/0x1df
>  [<c01878e3>] ? mark_held_locks+0x43/0x5b
>  [<c0688d3a>] ? _raw_spin_unlock_irq+0x27/0x30
>  [<c0187b3f>] ? trace_hardirqs_on_caller+0x104/0x125
>  [<c0187b6b>] ? trace_hardirqs_on+0xb/0xd
>  [<c0687042>] wait_for_common+0xc6/0x11f
>  [<c015d4d4>] ? default_wake_function+0x0/0x12
>  [<c068713a>] wait_for_completion+0x17/0x19
>  [<c035a837>] blkdev_issue_flush+0x96/0xcf
>  [<c0686fb2>] ? wait_for_common+0x36/0x11f
>  [<c025c06d>] ext4_sync_file+0x205/0x250
>  [<c021a04b>] vfs_fsync_range+0x46/0x68
>  [<c021a0c2>] generic_write_sync+0x55/0x64
>  [<c01cfd78>] generic_file_aio_write+0x99/0xb8
>  [<c025bd7c>] ext4_file_write+0x1df/0x22f
>  [<c01fbbd0>] do_sync_write+0x8f/0xca
>  [<c033622f>] ? security_file_permission+0x27/0x2b
>  [<c01fbd9f>] ? rw_verify_area+0xca/0xed
>  [<c01fbb41>] ? do_sync_write+0x0/0xca
>  [<c01fc51c>] vfs_write+0x85/0xe3
>  [<c0688ef6>] ? restore_all_notrace+0x0/0x18
>  [<c01fc5c2>] sys_pwrite64+0x48/0x61
>  [<c0688ebd>] syscall_call+0x7/0xb
> Code: 8b 40 0c 8b 5a 5c 89 d7 8b 70 04 8b 06 8b 80 74 04 00 00 85 c0 74 11 ff 73 74 68 33 0a 87 c0 50 e8 ce a7 e5 ff 83 c4 0c 8b 47 58 <8b> 50 0c 89 d8 e8 68 f0 ff ff 8b 57 20 a1 40 6a 92 c0 83 e2 11 
> EIP: [<c036429a>] cfq_insert_request+0x39/0x4a2 SS:ESP 0068:f6db3bd0
> CR2: 000000000000000c
> ---[ end trace da176424940e586f ]---

This looks somewhat similar to what Markus is reporting, essentially the
badness is coming out of the flush-on-schedule. Whether that is what
triggers this bug or if it's just a normal place to flush the plug, hard
to say. For this particular case it looks quite normal -
wait_for_completion() will block, so we flush it out.


diff --git a/block/blk-core.c b/block/blk-core.c
index 59b5c00..8906ff1 100644
--- a/block/blk-core.c
+++ b/block/blk-core.c
@@ -1197,6 +1197,7 @@ static bool attempt_plug_merge(struct task_struct *tsk, struct request_queue *q,
 	if (!plug)
 		goto out;
 
+	preempt_disable();
 	list_for_each_entry_reverse(rq, &plug->list, queuelist) {
 		int el_ret;
 
@@ -1214,6 +1215,7 @@ static bool attempt_plug_merge(struct task_struct *tsk, struct request_queue *q,
 				break;
 		}
 	}
+	preempt_enable();
 out:
 	return ret;
 }

-- 
Jens Axboe