On Thu, Jul 31, 2014 at 04:30:52PM +0200, Mike Galbraith wrote:
> On Thu, 2014-07-31 at 15:13 +0200, Peter Zijlstra wrote:
> 
> > Smells like maybe current->state != TASK_RUNNING
> 
> Bingo
> 
> [ 1200.851004] kjournald       D 0000000000000002     0  4398      2 0x00000000
> [ 1200.858283]  ffff8803537bb788 0000000000000046 ffff8803537bb7a8 0000000000000000
> [ 1200.865914]  ffff880423324b60 0000000000012f80 ffff8803537bbfd8 0000000000012f80
> [ 1200.873590]  ffff88042937cb60 ffff880423324b60 ffff880428ceb240 ffff8804231e59b8
> [ 1200.881256] Call Trace:
> [ 1200.883724]  [<ffffffff816981c9>] schedule+0x29/0x70
> [ 1200.888798]  [<ffffffff8169849e>] schedule_preempt_disabled+0xe/0x10
> [ 1200.895239]  [<ffffffff81699fe5>] __mutex_lock_slowpath+0x1b5/0x1c0
> [ 1200.901673]  [<ffffffffa0479826>] ? ceph_str_hash+0x26/0x80 [libceph]
> [ 1200.908198]  [<ffffffff8169a013>] mutex_lock+0x23/0x37
> [ 1200.913430]  [<ffffffffa046751d>] ceph_con_send+0x4d/0x130 [libceph]
> [ 1200.919912]  [<ffffffffa046c540>] __send_queued+0x120/0x150 [libceph]
> [ 1200.926444]  [<ffffffffa046ec5b>] __ceph_osdc_start_request+0x5b/0xd0 [libceph]
> [ 1200.933855]  [<ffffffffa046ed21>] ceph_osdc_start_request+0x51/0x80 [libceph]
> [ 1200.941126]  [<ffffffffa042bf60>] rbd_obj_request_submit.isra.25+0x10/0x20 [rbd]
> [ 1200.948622]  [<ffffffffa042e8ee>] rbd_img_obj_request_submit+0x1ce/0x460 [rbd]
> [ 1200.956040]  [<ffffffffa042ebcc>] rbd_img_request_submit+0x4c/0x60 [rbd]
> [ 1200.962845]  [<ffffffffa042f2a8>] rbd_request_fn+0x238/0x290 [rbd]
> [ 1200.969108]  [<ffffffff8133a397>] __blk_run_queue+0x37/0x50
> [ 1200.974764]  [<ffffffff8133affd>] queue_unplugged+0x3d/0xc0
> [ 1200.980424]  [<ffffffff8133fddb>] blk_flush_plug_list+0x1db/0x210
> [ 1200.986635]  [<ffffffff81698288>] io_schedule+0x78/0xd0
> [ 1200.991954]  [<ffffffff8133b864>] get_request+0x414/0x800
> [ 1200.997440]  [<ffffffff8133f477>] ? bio_attempt_back_merge+0x37/0x100
> [ 1201.004013]  [<ffffffff8109b9e0>] ? __wake_up_sync+0x20/0x20
> [ 1201.009782]  [<ffffffff8133ff2c>] blk_queue_bio+0xcc/0x360
> [ 1201.015353]  [<ffffffff8133c2d0>] generic_make_request+0xc0/0x100
> [ 1201.021605]  [<ffffffff8133c385>] submit_bio+0x75/0x140
> [ 1201.026921]  [<ffffffff811de4e6>] _submit_bh+0x136/0x1f0
> [ 1201.032390]  [<ffffffff81290081>] journal_do_submit_data+0x41/0x50
> [ 1201.038662]  [<ffffffff81291380>] journal_commit_transaction+0x1150/0x1350
> [ 1201.045683]  [<ffffffff81063aff>] ? try_to_del_timer_sync+0x4f/0x70
> [ 1201.052043]  [<ffffffff81293e01>] kjournald+0xe1/0x260
> [ 1201.057324]  [<ffffffff8109b9e0>] ? __wake_up_sync+0x20/0x20
> [ 1201.063072]  [<ffffffff81293d20>] ? commit_timeout+0x10/0x10
> [ 1201.068855]  [<ffffffff81078829>] kthread+0xc9/0xe0
> [ 1201.073819]  [<ffffffff81078760>] ? flush_kthread_worker+0xb0/0xb0
> [ 1201.080084]  [<ffffffff8169bb6c>] ret_from_fork+0x7c/0xb0
> [ 1201.085573]  [<ffffffff81078760>] ? flush_kthread_worker+0xb0/0xb0

Ohh. that's properly broken indeed.

You can't just call blocking primitives on the way to schedule(), that's
fail.

Also, if I look at blk_flush_plug_list(), it calls queue_unplugged()
with IRQs disabled, so _who_ is enabling them again and calling blocking
stuff?

/me stares more..

rbd_request_fn() does.. *argh*

Someone needs to go fix, this cannot work right.