From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from mout.gmx.net ([212.227.17.21]:44785 "EHLO mout.gmx.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1750803AbeBQFay (ORCPT ); Sat, 17 Feb 2018 00:30:54 -0500 Message-ID: <1518845448.11399.4.camel@gmx.de> Subject: Re: [PATCH BUGFIX V3] block, bfq: add requeue-request hook From: Mike Galbraith To: Jens Axboe , Paolo Valente Cc: Oleksandr Natalenko , stable Date: Sat, 17 Feb 2018 06:30:48 +0100 In-Reply-To: <06d0f749-511b-885b-d55f-922d99dcc24e@kernel.dk> References: <20180207211920.6343-1-paolo.valente@linaro.org> <1518197379.26824.31.camel@gmx.de> <6394471.U0O273vb9H@natalenko.name> <9E24F648-C93A-4CEA-A1B6-B041540CEAAE@linaro.org> <1518434553.13087.7.camel@gmx.de> <805e9d5af9aed3fbc2697fdb0ce51e88@natalenko.name> <1518498175.6944.48.camel@gmx.de> <816E0B1B-B2D9-4604-A8CB-1E32AFBF6C22@linaro.org> <1518504174.6944.71.camel@gmx.de> <1518504640.6944.73.camel@gmx.de> <1518532236.15792.25.camel@gmx.de> <1518587910.5647.14.camel@gmx.de> <1518591888.6752.12.camel@gmx.de> <1518592512.6752.14.camel@gmx.de> <07DA441B-C2E8-4F65-B674-11C87D2F084B@linaro.org> <0cdbafe7-fe13-51b4-4e86-e7453026508e@kernel.dk> <6A22B75D-B033-4EB0-8CDB-91A2E6755664@linaro.org> <06d0f749-511b-885b-d55f-922d99dcc24e@kernel.dk> Content-Type: text/plain; charset="ISO-8859-15" Mime-Version: 1.0 Content-Transfer-Encoding: 8BIT Sender: stable-owner@vger.kernel.org List-ID: On Wed, 2018-02-14 at 08:44 -0700, Jens Axboe wrote: > > Mike, when you see a hang like that, would it be possible for you to > dump the contents of /sys/kernel/debug/block/ to inspect? That will tell us a lot about the internal state at that > time. Finally. �4.15.4 stalled this morning while building other updated trees. #!/bin/sh for i in `find��/sys/kernel/debug/block/sd[bd] -type f` do echo $i: cat $i echo done /sys/kernel/debug/block/sdb/hctx0/cpu7/completed: 7483 4884 /sys/kernel/debug/block/sdb/hctx0/cpu7/merged: 0 /sys/kernel/debug/block/sdb/hctx0/cpu7/dispatched: 7483 4884 /sys/kernel/debug/block/sdb/hctx0/cpu7/rq_list: /sys/kernel/debug/block/sdb/hctx0/cpu6/completed: 12240 7814 /sys/kernel/debug/block/sdb/hctx0/cpu6/merged: 0 /sys/kernel/debug/block/sdb/hctx0/cpu6/dispatched: 12240 7814 /sys/kernel/debug/block/sdb/hctx0/cpu6/rq_list: /sys/kernel/debug/block/sdb/hctx0/cpu5/completed: 8549 7842 /sys/kernel/debug/block/sdb/hctx0/cpu5/merged: 0 /sys/kernel/debug/block/sdb/hctx0/cpu5/dispatched: 8549 7842 /sys/kernel/debug/block/sdb/hctx0/cpu5/rq_list: /sys/kernel/debug/block/sdb/hctx0/cpu4/completed: 10115 5073 /sys/kernel/debug/block/sdb/hctx0/cpu4/merged: 0 /sys/kernel/debug/block/sdb/hctx0/cpu4/dispatched: 10115 5073 /sys/kernel/debug/block/sdb/hctx0/cpu4/rq_list: /sys/kernel/debug/block/sdb/hctx0/cpu3/completed: 13181 4867 /sys/kernel/debug/block/sdb/hctx0/cpu3/merged: 0 /sys/kernel/debug/block/sdb/hctx0/cpu3/dispatched: 13181 4867 /sys/kernel/debug/block/sdb/hctx0/cpu3/rq_list: /sys/kernel/debug/block/sdb/hctx0/cpu2/completed: 101270 9089 /sys/kernel/debug/block/sdb/hctx0/cpu2/merged: 0 /sys/kernel/debug/block/sdb/hctx0/cpu2/dispatched: 101270 9089 /sys/kernel/debug/block/sdb/hctx0/cpu2/rq_list: /sys/kernel/debug/block/sdb/hctx0/cpu1/completed: 8158 4392 /sys/kernel/debug/block/sdb/hctx0/cpu1/merged: 0 /sys/kernel/debug/block/sdb/hctx0/cpu1/dispatched: 8158 4392 /sys/kernel/debug/block/sdb/hctx0/cpu1/rq_list: /sys/kernel/debug/block/sdb/hctx0/cpu0/completed: 8605 5819 /sys/kernel/debug/block/sdb/hctx0/cpu0/merged: 0 /sys/kernel/debug/block/sdb/hctx0/cpu0/dispatched: 8605 5819 /sys/kernel/debug/block/sdb/hctx0/cpu0/rq_list: /sys/kernel/debug/block/sdb/hctx0/active: 0 /sys/kernel/debug/block/sdb/hctx0/run: 373736 /sys/kernel/debug/block/sdb/hctx0/queued: 219336 /sys/kernel/debug/block/sdb/hctx0/dispatched: 0 7629 1 216748 2 446 4 0 8 0 16 0 32+ 0 /sys/kernel/debug/block/sdb/hctx0/io_poll: considered=0 invoked=0 success=0 /sys/kernel/debug/block/sdb/hctx0/sched_tags_bitmap: 00000000: 0000 0000 0000 0000 /sys/kernel/debug/block/sdb/hctx0/sched_tags: nr_tags=62 nr_reserved_tags=0 active_queues=0 bitmap_tags: depth=62 busy=0 bits_per_word=8 map_nr=8 alloc_hint={9, 1, 3, 0, 17, 0, 9, 17} wake_batch=7 wake_index=4 ws={ {.wait_cnt=7, .wait=active}, {.wait_cnt=7, .wait=active}, {.wait_cnt=7, .wait=inactive}, {.wait_cnt=7, .wait=inactive}, {.wait_cnt=1, .wait=active}, {.wait_cnt=7, .wait=active}, {.wait_cnt=7, .wait=inactive}, {.wait_cnt=7, .wait=active}, } round_robin=1 /sys/kernel/debug/block/sdb/hctx0/tags_bitmap: 00000000: 0000 0000 /sys/kernel/debug/block/sdb/hctx0/tags: nr_tags=31 nr_reserved_tags=0 active_queues=0 bitmap_tags: depth=31 busy=0 bits_per_word=4 map_nr=8 alloc_hint={3, 12, 2, 9, 18, 2, 4, 11} wake_batch=3 wake_index=0 ws={ {.wait_cnt=3, .wait=inactive}, {.wait_cnt=3, .wait=inactive}, {.wait_cnt=3, .wait=inactive}, {.wait_cnt=3, .wait=inactive}, {.wait_cnt=3, .wait=inactive}, {.wait_cnt=3, .wait=inactive}, {.wait_cnt=3, .wait=inactive}, {.wait_cnt=3, .wait=inactive}, } round_robin=1 /sys/kernel/debug/block/sdb/hctx0/ctx_map: 00000000: 00 /sys/kernel/debug/block/sdb/hctx0/busy: /sys/kernel/debug/block/sdb/hctx0/dispatch: /sys/kernel/debug/block/sdb/hctx0/flags: alloc_policy=RR SHOULD_MERGE|SG_MERGE /sys/kernel/debug/block/sdb/hctx0/state: /sys/kernel/debug/block/sdb/write_hints: hint0: 0 hint1: 0 hint2: 0 hint3: 0 hint4: 0 /sys/kernel/debug/block/sdb/state: SAME_COMP|IO_STAT|INIT_DONE|POLL|WC|FLUSH_NQ|REGISTERED|SCSI_PASSTHROUGH /sys/kernel/debug/block/sdb/requeue_list: /sys/kernel/debug/block/sdb/poll_stat: read (512 Bytes): samples=0 write (512 Bytes): samples=0 read (1024 Bytes): samples=0 write (1024 Bytes): samples=0 read (2048 Bytes): samples=0 write (2048 Bytes): samples=0 read (4096 Bytes): samples=0 write (4096 Bytes): samples=0 read (8192 Bytes): samples=0 write (8192 Bytes): samples=0 read (16384 Bytes): samples=0 write (16384 Bytes): samples=0 read (32768 Bytes): samples=0 write (32768 Bytes): samples=0 read (65536 Bytes): samples=0 write (65536 Bytes): samples=0 /sys/kernel/debug/block/sdd/hctx0/cpu7/completed: 2642 5235 /sys/kernel/debug/block/sdd/hctx0/cpu7/merged: 0 /sys/kernel/debug/block/sdd/hctx0/cpu7/dispatched: 2642 5235 /sys/kernel/debug/block/sdd/hctx0/cpu7/rq_list: /sys/kernel/debug/block/sdd/hctx0/cpu6/completed: 2873 15051 /sys/kernel/debug/block/sdd/hctx0/cpu6/merged: 0 /sys/kernel/debug/block/sdd/hctx0/cpu6/dispatched: 2873 15051 /sys/kernel/debug/block/sdd/hctx0/cpu6/rq_list: /sys/kernel/debug/block/sdd/hctx0/cpu5/completed: 3212 13912 /sys/kernel/debug/block/sdd/hctx0/cpu5/merged: 0 /sys/kernel/debug/block/sdd/hctx0/cpu5/dispatched: 3212 13912 /sys/kernel/debug/block/sdd/hctx0/cpu5/rq_list: /sys/kernel/debug/block/sdd/hctx0/cpu4/completed: 4304 8158 /sys/kernel/debug/block/sdd/hctx0/cpu4/merged: 0 /sys/kernel/debug/block/sdd/hctx0/cpu4/dispatched: 4304 8158 /sys/kernel/debug/block/sdd/hctx0/cpu4/rq_list: /sys/kernel/debug/block/sdd/hctx0/cpu3/completed: 3034 6275 /sys/kernel/debug/block/sdd/hctx0/cpu3/merged: 0 /sys/kernel/debug/block/sdd/hctx0/cpu3/dispatched: 3034 6275 /sys/kernel/debug/block/sdd/hctx0/cpu3/rq_list: /sys/kernel/debug/block/sdd/hctx0/cpu2/completed: 10339 21025 /sys/kernel/debug/block/sdd/hctx0/cpu2/merged: 0 /sys/kernel/debug/block/sdd/hctx0/cpu2/dispatched: 10339 21025 /sys/kernel/debug/block/sdd/hctx0/cpu2/rq_list: /sys/kernel/debug/block/sdd/hctx0/cpu1/completed: 3237 9737 /sys/kernel/debug/block/sdd/hctx0/cpu1/merged: 0 /sys/kernel/debug/block/sdd/hctx0/cpu1/dispatched: 3237 9737 /sys/kernel/debug/block/sdd/hctx0/cpu1/rq_list: /sys/kernel/debug/block/sdd/hctx0/cpu0/completed: 1490 6101 /sys/kernel/debug/block/sdd/hctx0/cpu0/merged: 0 /sys/kernel/debug/block/sdd/hctx0/cpu0/dispatched: 1490 6101 /sys/kernel/debug/block/sdd/hctx0/cpu0/rq_list: /sys/kernel/debug/block/sdd/hctx0/active: 0 /sys/kernel/debug/block/sdd/hctx0/run: 116625 /sys/kernel/debug/block/sdd/hctx0/queued: 116625 /sys/kernel/debug/block/sdd/hctx0/dispatched: 0 2438 1 116700 2 92 4 0 8 0 16 0 32+ 0 /sys/kernel/debug/block/sdd/hctx0/io_poll: considered=0 invoked=0 success=0 /sys/kernel/debug/block/sdd/hctx0/sched_tags_bitmap: 00000000: 0000 0000 0000 0000 /sys/kernel/debug/block/sdd/hctx0/sched_tags: nr_tags=62 nr_reserved_tags=0 active_queues=0 bitmap_tags: depth=62 busy=0 bits_per_word=8 map_nr=8 alloc_hint={9, 51, 57, 0, 0, 2, 2, 21} wake_batch=7 wake_index=0 ws={ {.wait_cnt=7, .wait=inactive}, {.wait_cnt=7, .wait=inactive}, {.wait_cnt=7, .wait=inactive}, {.wait_cnt=7, .wait=inactive}, {.wait_cnt=7, .wait=inactive}, {.wait_cnt=7, .wait=inactive}, {.wait_cnt=7, .wait=inactive}, {.wait_cnt=7, .wait=inactive}, } round_robin=1 /sys/kernel/debug/block/sdd/hctx0/tags_bitmap: 00000000: 0000 0000 /sys/kernel/debug/block/sdd/hctx0/tags: nr_tags=31 nr_reserved_tags=0 active_queues=0 bitmap_tags: depth=31 busy=0 bits_per_word=4 map_nr=8 alloc_hint={7, 21, 26, 26, 25, 2, 22, 6} wake_batch=3 wake_index=0 ws={ {.wait_cnt=3, .wait=inactive}, {.wait_cnt=3, .wait=inactive}, {.wait_cnt=3, .wait=inactive}, {.wait_cnt=3, .wait=inactive}, {.wait_cnt=3, .wait=inactive}, {.wait_cnt=3, .wait=inactive}, {.wait_cnt=3, .wait=inactive}, {.wait_cnt=3, .wait=inactive}, } round_robin=1 /sys/kernel/debug/block/sdd/hctx0/ctx_map: 00000000: 00 /sys/kernel/debug/block/sdd/hctx0/busy: /sys/kernel/debug/block/sdd/hctx0/dispatch: /sys/kernel/debug/block/sdd/hctx0/flags: alloc_policy=RR SHOULD_MERGE|SG_MERGE /sys/kernel/debug/block/sdd/hctx0/state: /sys/kernel/debug/block/sdd/write_hints: hint0: 0 hint1: 0 hint2: 0 hint3: 0 hint4: 0 /sys/kernel/debug/block/sdd/state: SAME_COMP|IO_STAT|INIT_DONE|POLL|WC|FLUSH_NQ|REGISTERED|SCSI_PASSTHROUGH /sys/kernel/debug/block/sdd/requeue_list: /sys/kernel/debug/block/sdd/poll_stat: read (512 Bytes): samples=0 write (512 Bytes): samples=0 read (1024 Bytes): samples=0 write (1024 Bytes): samples=0 read (2048 Bytes): samples=0 write (2048 Bytes): samples=0 read (4096 Bytes): samples=0 write (4096 Bytes): samples=0 read (8192 Bytes): samples=0 write (8192 Bytes): samples=0 read (16384 Bytes): samples=0 write (16384 Bytes): samples=0 read (32768 Bytes): samples=0 write (32768 Bytes): samples=0 read (65536 Bytes): samples=0 write (65536 Bytes): samples=0