Re: [PATCH V15 06/22] mmc: block: Add blk-mq support

From: Adrian Hunter
Date: Thu Feb 22 2018 - 02:43:15 EST

Next message: Matias BjÃrling: "Re: [PATCH 07/20] lightnvm: rename sect_* to sec_*"
Previous message: Matias BjÃrling: "Re: [PATCH 04/20] lightnvm: add minor version to generic geometry"
In reply to: Dmitry Osipenko: "Re: [PATCH V15 06/22] mmc: block: Add blk-mq support"
Next in thread: Dmitry Osipenko: "Re: [PATCH V15 06/22] mmc: block: Add blk-mq support"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

On 21/02/18 22:50, Dmitry Osipenko wrote:
> On 29.11.2017 16:41, Adrian Hunter wrote:
>> Define and use a blk-mq queue. Discards and flushes are processed
>> synchronously, but reads and writes asynchronously. In order to support
>> slow DMA unmapping, DMA unmapping is not done until after the next request
>> is started. That means the request is not completed until then. If there is
>> no next request then the completion is done by queued work.
>
> Hello,
>
> I'm using (running linux-next and doing some upstream development for) some old
> NVIDIA Tegra tablet that has built-in (internal) and external MMC's and with the
> blk-mq being enabled I'm observing a soft lockup. The lockup seems is
> reproducible quite reliably by running fsck on any MMC partition, sometimes
> kernels lockups on boot during probing partitions table (weirdly only when both
> SDHCI's are present, i.e. internal storage enabled in DT and external SD is
> inserted/enabled) and it also lockups pretty quickly in a case of just a general
> use. Reverting mmc/ commits up to 1bec43a3b18 ("Remove option not to use
> blk-mq") and disabling CONFIG_MMC_MQ_DEFAULT makes everything working fine
> again. There is also a third SDHCI populated with built-in WiFi/Bluetooth SDIO
> and I'm observing odd MMC timeouts with the blk-mq enabled, disabling
> CONFIG_MMC_MQ_DEFAULT fixes these timeouts as well.
>
> Any thoughts?

SDIO (unless it is a combo card) should be unaffected by changes to the
block driver.

I don't have any ideas. Adding more NVIDIA people.

>
> WiFi issue
> ========================
>
> [ 38.247006] mmc2: Timeout waiting for hardware interrupt.
> [ 38.247027] brcmfmac: brcmf_escan_timeout: timer expired
> [ 38.247036] mmc2: sdhci: ============ SDHCI REGISTER DUMP ===========
> [ 38.247047] mmc2: sdhci: Sys addr: 0x00000000 | Version: 0x00000001
> [ 38.247055] mmc2: sdhci: Blk size: 0x00007008 | Blk cnt: 0x00000000
> [ 38.247062] mmc2: sdhci: Argument: 0x21000008 | Trn mode: 0x00000013
> [ 38.247070] mmc2: sdhci: Present: 0x01d70000 | Host ctl: 0x00000013
> [ 38.247077] mmc2: sdhci: Power: 0x00000001 | Blk gap: 0x00000000
> [ 38.247084] mmc2: sdhci: Wake-up: 0x00000000 | Clock: 0x00000007
> [ 38.247091] mmc2: sdhci: Timeout: 0x0000000e | Int stat: 0x00000000
> [ 38.247098] mmc2: sdhci: Int enab: 0x02ff000b | Sig enab: 0x02fc000b
> [ 38.247105] mmc2: sdhci: AC12 err: 0x00000000 | Slot int: 0x00000000
> [ 38.247112] mmc2: sdhci: Caps: 0x61ff30b0 | Caps_1: 0x00000000
> [ 38.247119] mmc2: sdhci: Cmd: 0x0000353a | Max curr: 0x00000001
> [ 38.247126] mmc2: sdhci: Resp[0]: 0x00001800 | Resp[1]: 0x08002db5
> [ 38.247133] mmc2: sdhci: Resp[2]: 0x16da8000 | Resp[3]: 0x00000400
> [ 38.247139] mmc2: sdhci: Host ctl2: 0x00000000
> [ 38.247146] mmc2: sdhci: ADMA Err: 0x00000000 | ADMA Ptr: 0x17c47200
> [ 38.247152] mmc2: sdhci: ============================================
> [ 38.247250] brcmfmac: brcmf_sdio_readframes: read 520 bytes from channel 1
> failed: -84
> [ 38.247274] brcmfmac: brcmf_sdio_rxfail: abort command, terminate frame, send NAK
> [ 40.807019] brcmfmac: brcmf_sdio_bus_rxctl: resumed on timeout
> [ 40.807042] brcmfmac: brcmf_notify_escan_complete: Scan abort failed
> [ 48.487007] mmc2: Timeout waiting for hardware interrupt.
> [ 48.487057] mmc2: sdhci: ============ SDHCI REGISTER DUMP ===========
> [ 48.487096] mmc2: sdhci: Sys addr: 0x00000000 | Version: 0x00000001
> [ 48.487128] mmc2: sdhci: Blk size: 0x00007040 | Blk cnt: 0x00000001
> [ 48.487160] mmc2: sdhci: Argument: 0x21000040 | Trn mode: 0x00000013
> [ 48.487191] mmc2: sdhci: Present: 0x01d70000 | Host ctl: 0x00000013
> [ 48.487221] mmc2: sdhci: Power: 0x00000001 | Blk gap: 0x00000000
> [ 48.487251] mmc2: sdhci: Wake-up: 0x00000000 | Clock: 0x00000007
> [ 48.487281] mmc2: sdhci: Timeout: 0x0000000e | Int stat: 0x00000000
> [ 48.487313] mmc2: sdhci: Int enab: 0x02ff000b | Sig enab: 0x02fc000b
> [ 48.487343] mmc2: sdhci: AC12 err: 0x00000000 | Slot int: 0x00000000
> [ 48.487374] mmc2: sdhci: Caps: 0x61ff30b0 | Caps_1: 0x00000000
> [ 48.487404] mmc2: sdhci: Cmd: 0x0000353a | Max curr: 0x00000001
> [ 48.487435] mmc2: sdhci: Resp[0]: 0x00001000 | Resp[1]: 0x08002db5
> [ 48.487466] mmc2: sdhci: Resp[2]: 0x16da8000 | Resp[3]: 0x00000400
> [ 48.487493] mmc2: sdhci: Host ctl2: 0x00000000
> [ 48.487525] mmc2: sdhci: ADMA Err: 0x00000000 | ADMA Ptr: 0x17c47200
> [ 48.487552] mmc2: sdhci: ============================================
> [ 48.487749] brcmfmac: brcmf_sdio_readframes: read 480 bytes from channel 1
> failed: -84
> [ 48.487822] brcmfmac: brcmf_sdio_rxfail: abort command, terminate frame, send NAK
>
>
> Soft lockup issue
> ========================
>
> # fsck -f /dev/disk/by-uuid/6768309f-3545-49d5-9ac7-d5be24d35ef2
> fsck ÐÐ util-linux 2.30.2
> e2fsck 1.43.9 (8-Feb-2018)
> ÐÑÐÑÐÐ 1: ÐÑÐÐÐÑÐÐ inodes, ÐÐÐÐs, Ð ÑÐÐÐÐ ÑÐÐÐÐÑÐÐ
> Pass 2: Checking ÐÐÑÐÐÐÐ structure
> Pass 3: Checking ÐÐÑÐÐÐÐ connectivity
> Pass 4: Checking reference counts
> Pass 5: Checking ÐÑÑÐÐÐ summary information
> ....
>
> [ 125.925436] INFO: task kworker/0:3H:263 blocked for more than 60 seconds.
> [ 125.925496] Not tainted
> 4.16.0-rc2-next-20180220-00101-gaefde91c3955-dirty #2041
> [ 125.925530] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this
> message.
> [ 125.925562] kworker/0:3H D 0 263 2 0x00000000
> [ 125.925653] Workqueue: kblockd mmc_blk_mq_complete_work
> [ 125.925747] [<c0b991cc>] (__schedule) from [<c0b998f0>] (schedule+0x60/0xcc)
> [ 125.925805] [<c0b998f0>] (schedule) from [<c086c870>]
> (__mmc_claim_host+0xdc/0x24c)
> [ 125.925849] [<c086c870>] (__mmc_claim_host) from [<c08750bc>]

That claim host should not be there. Here is a fix for that:

diff --git a/drivers/mmc/core/mmc_ops.c b/drivers/mmc/core/mmc_ops.c
index 908e4db03535..62049f95116b 100644
--- a/drivers/mmc/core/mmc_ops.c
+++ b/drivers/mmc/core/mmc_ops.c
@@ -932,9 +932,7 @@ static int mmc_read_bkops_status(struct mmc_card *card)
int err;
u8 *ext_csd;

- mmc_claim_host(card->host);
err = mmc_get_ext_csd(card, &ext_csd);
- mmc_release_host(card->host);
if (err)
return err;

> (mmc_start_bkops+0x4c/0x190)
> [ 125.925895] [<c08750bc>] (mmc_start_bkops) from [<c087d254>]
> (mmc_blk_urgent_bkops+0x48/0x5c)
> [ 125.925945] [<c087d254>] (mmc_blk_urgent_bkops) from [<c087f2e0>]
> (mmc_blk_mq_complete_prev_req.part.5+0x74/0x210)
> [ 125.925995] [<c087f2e0>] (mmc_blk_mq_complete_prev_req.part.5) from
> [<c08813d0>] (mmc_blk_mq_complete_work+0x30/0x34)
> [ 125.926049] [<c08813d0>] (mmc_blk_mq_complete_work) from [<c014306c>]
> (process_one_work+0x1f8/0x584)
> [ 125.926093] [<c014306c>] (process_one_work) from [<c014402c>]
> (worker_thread+0x68/0x5d4)
> [ 125.926144] [<c014402c>] (worker_thread) from [<c014965c>] (kthread+0x178/0x184)
> [ 125.926188] [<c014965c>] (kthread) from [<c01010e8>] (ret_from_fork+0x14/0x2c)
> [ 125.926209] Exception stack(0xd579ffb0 to 0xd579fff8)
> [ 125.926239] ffa0: 00000000 00000000
> 00000000 00000000
> [ 125.926272] ffc0: 00000000 00000000 00000000 00000000 00000000 00000000
> 00000000 00000000
> [ 125.926301] ffe0: 00000000 00000000 00000000 00000000 00000013 00000000
> [ 125.926361] INFO: task fsck.ext4:471 blocked for more than 60 seconds.
> [ 125.926399] Not tainted
> 4.16.0-rc2-next-20180220-00101-gaefde91c3955-dirty #2041
> [ 125.926427] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this
> message.
> [ 125.926455] fsck.ext4 D 0 471 470 0x00000000
> [ 125.926536] [<c0b991cc>] (__schedule) from [<c0b998f0>] (schedule+0x60/0xcc)
> [ 125.926593] [<c0b998f0>] (schedule) from [<c015823c>] (io_schedule+0x20/0x40)
> [ 125.926654] [<c015823c>] (io_schedule) from [<c0220acc>]
> (wait_on_page_bit+0x120/0x144)
> [ 125.926705] [<c0220acc>] (wait_on_page_bit) from [<c0220bc4>]
> (__filemap_fdatawait_range+0xd4/0x114)
> [ 125.926757] [<c0220bc4>] (__filemap_fdatawait_range) from [<c0223784>]
> (file_write_and_wait_range+0x98/0xb4)
> [ 125.926810] [<c0223784>] (file_write_and_wait_range) from [<c02c0300>]
> (blkdev_fsync+0x2c/0x5c)
> [ 125.926867] [<c02c0300>] (blkdev_fsync) from [<c02b7ce8>]
> (vfs_fsync_range+0x4c/0xb0)
> [ 125.926912] [<c02b7ce8>] (vfs_fsync_range) from [<c02b7dd4>] (do_fsync+0x4c/0x74)
> [ 125.926954] [<c02b7dd4>] (do_fsync) from [<c02b80a0>] (SyS_fsync+0x1c/0x20)
> [ 125.926996] [<c02b80a0>] (SyS_fsync) from [<c0101000>]
> (ret_fast_syscall+0x0/0x54)
> [ 125.927016] Exception stack(0xd5631fa8 to 0xd5631ff0)
> [ 125.927050] 1fa0: 00480fc8 00481108 00000004 00481108
> 00000000 00000000
> [ 125.927086] 1fc0: 00480fc8 00481108 00000000 00000076 00000000 7f2bb750
> 00483268 bec602e8
> [ 125.927113] 1fe0: 00000076 bec60288 b6de5e8b b6d67cf6
> [ 177.015618] random: crng init done
> [ 187.365434] INFO: task kworker/0:3H:263 blocked for more than 60 seconds.
> [ 187.365491] Not tainted
> 4.16.0-rc2-next-20180220-00101-gaefde91c3955-dirty #2041
> [ 187.365524] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this
> message.
> [ 187.365556] kworker/0:3H D 0 263 2 0x00000000
> [ 187.365647] Workqueue: kblockd mmc_blk_mq_complete_work
> [ 187.365741] [<c0b991cc>] (__schedule) from [<c0b998f0>] (schedule+0x60/0xcc)
> [ 187.365798] [<c0b998f0>] (schedule) from [<c086c870>]
> (__mmc_claim_host+0xdc/0x24c)
> [ 187.365842] [<c086c870>] (__mmc_claim_host) from [<c08750bc>]
> (mmc_start_bkops+0x4c/0x190)
> [ 187.365887] [<c08750bc>] (mmc_start_bkops) from [<c087d254>]
> (mmc_blk_urgent_bkops+0x48/0x5c)
> [ 187.365936] [<c087d254>] (mmc_blk_urgent_bkops) from [<c087f2e0>]
> (mmc_blk_mq_complete_prev_req.part.5+0x74/0x210)
> [ 187.365986] [<c087f2e0>] (mmc_blk_mq_complete_prev_req.part.5) from
> [<c08813d0>] (mmc_blk_mq_complete_work+0x30/0x34)
> [ 187.366039] [<c08813d0>] (mmc_blk_mq_complete_work) from [<c014306c>]
> (process_one_work+0x1f8/0x584)
> [ 187.366083] [<c014306c>] (process_one_work) from [<c014402c>]
> (worker_thread+0x68/0x5d4)
> [ 187.366134] [<c014402c>] (worker_thread) from [<c014965c>] (kthread+0x178/0x184)
> [ 187.366178] [<c014965c>] (kthread) from [<c01010e8>] (ret_from_fork+0x14/0x2c)
> [ 187.366200] Exception stack(0xd579ffb0 to 0xd579fff8)
> [ 187.366229] ffa0: 00000000 00000000
> 00000000 00000000
> [ 187.366262] ffc0: 00000000 00000000 00000000 00000000 00000000 00000000
> 00000000 00000000
> [ 187.366291] ffe0: 00000000 00000000 00000000 00000000 00000013 00000000
> [ 187.366350] INFO: task fsck.ext4:471 blocked for more than 60 seconds.
> [ 187.366388] Not tainted
> 4.16.0-rc2-next-20180220-00101-gaefde91c3955-dirty #2041
> [ 187.366416] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this
> message.
> [ 187.366445] fsck.ext4 D 0 471 470 0x00000000
> [ 187.366526] [<c0b991cc>] (__schedule) from [<c0b998f0>] (schedule+0x60/0xcc)
> [ 187.366582] [<c0b998f0>] (schedule) from [<c015823c>] (io_schedule+0x20/0x40)
> [ 187.366644] [<c015823c>] (io_schedule) from [<c0220acc>]
> (wait_on_page_bit+0x120/0x144)
> [ 187.366693] [<c0220acc>] (wait_on_page_bit) from [<c0220bc4>]
> (__filemap_fdatawait_range+0xd4/0x114)
> [ 187.366745] [<c0220bc4>] (__filemap_fdatawait_range) from [<c0223784>]
> (file_write_and_wait_range+0x98/0xb4)
> [ 187.366799] [<c0223784>] (file_write_and_wait_range) from [<c02c0300>]
> (blkdev_fsync+0x2c/0x5c)
> [ 187.366857] [<c02c0300>] (blkdev_fsync) from [<c02b7ce8>]
> (vfs_fsync_range+0x4c/0xb0)
> [ 187.366902] [<c02b7ce8>] (vfs_fsync_range) from [<c02b7dd4>] (do_fsync+0x4c/0x74)
> [ 187.366944] [<c02b7dd4>] (do_fsync) from [<c02b80a0>] (SyS_fsync+0x1c/0x20)
> [ 187.366987] [<c02b80a0>] (SyS_fsync) from [<c0101000>]
> (ret_fast_syscall+0x0/0x54)
> [ 187.367008] Exception stack(0xd5631fa8 to 0xd5631ff0)
> [ 187.367041] 1fa0: 00480fc8 00481108 00000004 00481108
> 00000000 00000000
> [ 187.367078] 1fc0: 00480fc8 00481108 00000000 00000076 00000000 7f2bb750
> 00483268 bec602e8
> [ 187.367103] 1fe0: 00000076 bec60288 b6de5e8b b6d67cf6
>

Next message: Matias BjÃrling: "Re: [PATCH 07/20] lightnvm: rename sect_* to sec_*"
Previous message: Matias BjÃrling: "Re: [PATCH 04/20] lightnvm: add minor version to generic geometry"
In reply to: Dmitry Osipenko: "Re: [PATCH V15 06/22] mmc: block: Add blk-mq support"
Next in thread: Dmitry Osipenko: "Re: [PATCH V15 06/22] mmc: block: Add blk-mq support"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]