lkml.org 
[lkml]   [2013]   [Aug]   [28]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
    /
    Date
    From
    SubjectRe: [patch|rfc] block: fix race between request completion and timeout handling
    On 08/28/2013 09:04 AM, Hannes Reinecke wrote:
    > On 08/27/2013 04:28 PM, Jeff Moyer wrote:
    >> Hi,
    >>
    >> We have several reports (against a distro kernel) of panics in
    >> blk_requeue_request that look like this:
    >>
    >> kernel BUG at block/blk-core.c:1045!
    >> invalid opcode: 0000 [#1] SMP
    >> last sysfs file: /sys/devices/pci0000:40/0000:40:03.0/0000:55:00.0/infiniband_mad/umad0/port
    >> CPU 0
    >> Modules linked in: ipmi_si ipmi_devintf ipmi_msghandler bonding rdma_ucm(U) rdma_cm(U) iw_cm(U) ib_addr(U) ib_ipoib(U) ib_cm(U) ib_sa(U) ipv6 ib_uverbs(U) ib_umad(U) iw_nes(U) libcrc32c mlx4_ib(U) mlx4_en(U) mlx4_core(U) ib_mthca(U) ib_mad(U) ib_core(U) cdc_ether usbnet mii microcode i2c_i801 i2c_core iTCO_wdt iTCO_vendor_support shpchp ioatdma dca be2net sg ses enclosure ext4 mbcache jbd2 sd_mod crc_t10dif ahci megaraid_sas(U) dm_mirror dm_region_hash dm_log dm_mod [last unloaded: scsi_wait_scan]
    >>
    >> Pid: 491, comm: scsi_eh_0 Tainted: G W ---------------- 2.6.32-220.13.1.el6.x86_64 #1 IBM -[8722PAX]-/00D1461
    >> RIP: 0010:[<ffffffff8124e424>] [<ffffffff8124e424>] blk_requeue_request+0x94/0xa0
    >> RSP: 0018:ffff881057eefd60 EFLAGS: 00010012
    >> RAX: ffff881d99e3e8a8 RBX: ffff881d99e3e780 RCX: ffff881d99e3e8a8
    >> RDX: ffff881d99e3e8a8 RSI: ffff881d99e3e780 RDI: ffff881d99e3e780
    >> RBP: ffff881057eefd80 R08: ffff881057eefe90 R09: 0000000000000000
    >> R10: 0000000000000000 R11: 0000000000000000 R12: ffff881057f92338
    >> R13: 0000000000000000 R14: ffff881057f92338 R15: ffff883058188000
    >> FS: 0000000000000000(0000) GS:ffff880040200000(0000) knlGS:0000000000000000
    >> CS: 0010 DS: 0018 ES: 0018 CR0: 000000008005003b
    >> CR2: 00000000006d3ec0 CR3: 000000302cd7d000 CR4: 00000000000406b0
    >> DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
    >> DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
    >> Process scsi_eh_0 (pid: 491, threadinfo ffff881057eee000, task ffff881057e29540)
    >> Stack:
    >> 0000000000001057 0000000000000286 ffff8810275efdc0 ffff881057f16000
    >> <0> ffff881057eefdd0 ffffffff81362323 ffff881057eefe20 ffffffff8135f393
    >> <0> ffff881057e29af8 ffff8810275efdc0 ffff881057eefe78 ffff881057eefe90
    >> Call Trace:
    >> [<ffffffff81362323>] __scsi_queue_insert+0xa3/0x150
    >> [<ffffffff8135f393>] ? scsi_eh_ready_devs+0x5e3/0x850
    >> [<ffffffff81362a23>] scsi_queue_insert+0x13/0x20
    >> [<ffffffff8135e4d4>] scsi_eh_flush_done_q+0x104/0x160
    >> [<ffffffff8135fb6b>] scsi_error_handler+0x35b/0x660
    >> [<ffffffff8135f810>] ? scsi_error_handler+0x0/0x660
    >> [<ffffffff810908c6>] kthread+0x96/0xa0
    >> [<ffffffff8100c14a>] child_rip+0xa/0x20
    >> [<ffffffff81090830>] ? kthread+0x0/0xa0
    >> [<ffffffff8100c140>] ? child_rip+0x0/0x20
    >> Code: 00 00 eb d1 4c 8b 2d 3c 8f 97 00 4d 85 ed 74 bf 49 8b 45 00 49 83 c5 08 48 89 de 4c 89 e7 ff d0 49 8b 45 00 48 85 c0 75 eb eb a4 <0f> 0b eb fe 0f 1f 84 00 00 00 00 00 55 48 89 e5 0f 1f 44 00 00
    >> RIP [<ffffffff8124e424>] blk_requeue_request+0x94/0xa0
    >> RSP <ffff881057eefd60>
    >>
    >> The RIP is this line:
    >> BUG_ON(blk_queued_rq(rq));
    >>
    >> After digging through the code, I think there may be a race between the
    >> request completion and the timer handler running.
    >>
    >> A timer is started for each request put on the device's queue (see
    >> blk_start_request->blk_add_timer). If the request does not complete
    >> before the timer expires, the timer handler (blk_rq_timed_out_timer)
    >> will mark the request complete atomically:
    >>
    >> static inline int blk_mark_rq_complete(struct request *rq)
    >> {
    >> return test_and_set_bit(REQ_ATOM_COMPLETE, &rq->atomic_flags);
    >> }
    >>
    >> and then call blk_rq_timed_out. The latter function will call
    >> scsi_times_out, which will return one of BLK_EH_HANDLED,
    >> BLK_EH_RESET_TIMER or BLK_EH_NOT_HANDLED. If BLK_EH_RESET_TIMER is
    >> returned, blk_clear_rq_complete is called, and blk_add_timer is again
    >> called to simply wait longer for the request to complete.
    >>
    >> Now, if the request happens to complete while this is going on, what
    >> happens? Given that we know the completion handler will bail if it
    >> finds the REQ_ATOM_COMPLETE bit set, we need to focus on the completion
    >> handler running after that bit is cleared. So, from the above
    >> paragraph, after the call to blk_clear_rq_complete. If the completion
    >> sets REQ_ATOM_COMPLETE before the BUG_ON in blk_add_timer, we go boom
    >> there (I haven't seen this in the cores). Next, if we get the
    >> completion before the call to list_add_tail, then the timer will
    >> eventually fire for an old req, which may either be freed or reallocated
    >> (there is evidence that this might be the case). Finally, if the
    >> completion comes in *after* the addition to the timeout list, I think
    >> it's harmless. The request will be removed from the timeout list,
    >> req_atom_complete will be set, and all will be well.
    >>
    >> This RFC patch moves the BUG_ON(test_bit(REQ_ATOM_COMPLETE,
    >> &req->atomic_flags)); from blk_add_timer to the only caller that could
    >> trip over it (blk_start_request). It then inverts the calls to
    >> blk_clear_rq_complete and blk_add_timer in blk_rq_timed_out to address
    >> the race. I've boot tested this patch, but nothing more.
    >>
    >> Jens, James, others, what do you think?
    >>
    >> Cheers,
    >> Jeff
    >>
    >> diff --git a/block/blk-core.c b/block/blk-core.c
    >> index 93a18d1..236ae0a 100644
    >> --- a/block/blk-core.c
    >> +++ b/block/blk-core.c
    >> @@ -2229,6 +2229,7 @@ void blk_start_request(struct request *req)
    >> if (unlikely(blk_bidi_rq(req)))
    >> req->next_rq->resid_len = blk_rq_bytes(req->next_rq);
    >>
    >> + BUG_ON(test_bit(REQ_ATOM_COMPLETE, &req->atomic_flags));
    >> blk_add_timer(req);
    >> }
    >> EXPORT_SYMBOL(blk_start_request);
    >> diff --git a/block/blk-timeout.c b/block/blk-timeout.c
    >> index 65f1035..655ba90 100644
    >> --- a/block/blk-timeout.c
    >> +++ b/block/blk-timeout.c
    >> @@ -91,8 +91,8 @@ static void blk_rq_timed_out(struct request *req)
    >> __blk_complete_request(req);
    >> break;
    >> case BLK_EH_RESET_TIMER:
    >> - blk_clear_rq_complete(req);
    >> blk_add_timer(req);
    >> + blk_clear_rq_complete(req);
    >> break;
    >> case BLK_EH_NOT_HANDLED:
    >> /*
    >> @@ -174,7 +174,6 @@ void blk_add_timer(struct request *req)
    >> return;
    >>
    >> BUG_ON(!list_empty(&req->timeout_list));
    >> - BUG_ON(test_bit(REQ_ATOM_COMPLETE, &req->atomic_flags));
    >>
    >> /*
    >> * Some LLDs, like scsi, peek at the timeout to prevent a
    >> --
    >> To unsubscribe from this list: send the line "unsubscribe linux-scsi" in
    >> the body of a message to majordomo@vger.kernel.org
    >> More majordomo info at http://vger.kernel.org/majordomo-info.html
    >>
    >
    > So, looked into things a bit more.
    > It looks as if you're on the right track, although I doubt your
    > patch will fix the issue for me :-(
    >
    > Thing is, you're right there is a race window between requeuing
    > and softirq triggering, which could well be fixed by your patch.
    > So for that reason alone I would like to take it.
    >
    > However, including your patch will end up opening another can of
    > worms: the softirq might now be triggering _while the request is
    > queued on the request queue_.
    > blk_requeue_request will be putting the request back on the request
    > queue, where it'll be stuck until being pulled off from
    > scsi_request_fn().
    > So if the softirq triggers during that condition we'll end up
    > calling the BUG_ON((!list_empty(&req->queuelist)) in
    > __blk_put_request().
    >
    > Guess we'd need to fix that one, too ...
    >
    Ah. Now I see it.

    We're requeuing from the softirq context, ie after the completion
    has triggered. So the above scenario can't actually happen and the
    patch is valid.

    So:

    Acked-by: Hannes Reinecke <hare@suse.de>

    Cheers,

    Hannes
    --
    Dr. Hannes Reinecke zSeries & Storage
    hare@suse.de +49 911 74053 688
    SUSE LINUX Products GmbH, Maxfeldstr. 5, 90409 Nürnberg
    GF: J. Hawn, J. Guild, F. Imendörffer, HRB 16746 (AG Nürnberg)
    --
    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/

    \
     
     \ /
      Last update: 2013-08-28 10:01    [W:8.375 / U:0.004 seconds]
    ©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site