Re: [Regression] Linux-Next Merge 25Jul2018 breaks mmc on Tegra.

[Ming Lei <ming.lei@redhat.com>]

Hi Peter,

On Tue, Jul 31, 2018 at 08:47:45AM -0400, Peter Geis wrote:
> Good Morning,
> 
> On 07/30/2018 09:38 PM, Ming Lei wrote:
> > Hi Peter,
> > 
> > Thanks for collecting the log.
> > 
> > On Mon, Jul 30, 2018 at 02:55:42PM -0400, Peter Geis wrote:
> > > 
> > > 
> > > On 07/28/2018 09:37 AM, Ming Lei wrote:
> > 
> > ...
> > 
> > > [   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.

> 
> > 
> > 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.

>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.


Thanks,
Ming