Hi Peter,

On Tue, Jul 31, 2018 at 08:47:45AM -0400, Peter Geis wrote:

quoted

Good Morning,

On 07/30/2018 09:38 PM, Ming Lei wrote:

quoted

Hi Peter,

Thanks for collecting the log.

On Mon, Jul 30, 2018 at 02:55:42PM -0400, Peter Geis wrote:

quoted

On 07/28/2018 09:37 AM, Ming Lei wrote:

...

quoted

[   10.887209] systemd--112     0.n.1 2411122us : blk_mq_make_request: make
rq -1
[   10.890274] kworker/-98      0...1 2411506us : blk_mq_free_request:
complete: rq -1
[   10.893313] systemd--107     0...1 2412025us : blk_mq_make_request: make
rq -1
[   10.896354] systemd--107     0.... 2412323us : mmc_mq_queue_rq: queue rq
-1, 0
[   10.899388] systemd--107     0.... 2412327us :
blk_mq_try_issue_list_directly: issue direct: rq -1, ret 0
[   10.902463] (direxec-111     1...1 2413829us : blk_mq_make_request: make
rq -1
[   10.905513] systemd--114     1...1 2415159us : blk_mq_make_request: make
rq -1

Above is the most interesting part in the log. MMC sets hw queue depth
as 1, and you are using none scheduler, that means the max number of
in-flight requests should be one, but the above log shows that there may
be 3 in-flight requests.

That's odd, I have CFQ set as the default, is something changing this during
boot?
CONFIG_CFQ_GROUP_IOSCHED=y
CONFIG_DEFAULT_IOSCHED="cfq"

No, now mmc has been converted to blk-mq, and the default mq io sched
should have been mq-deadline for mmc, but not sure why it is none in
your case.

quoted

quoted

That seems really weird, but it shouldn't be related with my two patches,
which won't change the tag allocation behaviour at all. However, what matters
may be that the patch speeds up the request dispatch. Maybe one bug
in lib/sbitmap.c block/blk-mq-tag.c.

Unfortunately rq->tag wasn't shown in the log because I forget to dump
it in the debug patch, so could you apply the following new debug patch and
provide us the log again? BTW, please attach the ftrace log in the reply
mail directly, then it may be parsed/looked easily.

I have resynced to the latest linux-next and applied your new patch.
The log is attached.

Of note, it took several boots this time before it would progress to where I
could grab the log.
Instead it was blocking the moment RW was requested.
Also of note, it seems only the emmc is affected, the SD card (mmcblk2) does
not trigger any errors.

quoted

quoted

From the log you captured, seems there are three requests(33, 34, 60) blocked,

which should have been inside mmc, but still need to confirm, could you apply the
following one-line patch against the last debug patch and collect the log again?

diff --git a/drivers/mmc/core/queue.c b/drivers/mmc/core/queue.c
index d35f265cd5e0..ac2ffc5a8ed4 100644
--- a/drivers/mmc/core/queue.c
+++ b/drivers/mmc/core/queue.c

@@ -321,6 +321,8 @@ static blk_status_t mmc_mq_queue_rq(struct blk_mq_hw_ctx *hctx,
                                   !host->hold_retune;
        }

+       if (blk_queue_debug(q))
+               trace_printk("mmc before issue rq %d %d\n", req->internal_tag, req->tag);
        blk_mq_start_request(req);

        issued = mmc_blk_mq_issue_rq(mq, req);

Also see comments in mmc_mq_queue_rq():

	/*
	 * We use BLK_MQ_F_BLOCKING and have only 1 hardware queue, which means requests
	 * will not be dispatched in parallel.
	 */

which isn't correct, given blk-mq has multiple sw queue and mmc sets the queue depth
as > 1, and requests may be dispatched to the unique hw queue in parallel.

Adrian, Ulf Hansson and anyone, could you take a look at the warning of WARN_ON(host->cmd)
in sdhci_send_command()? Seems you only allow to queue one command, but not sure how you
guarantee that.