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?
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>]
(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
--
Dmitry
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
>
On 22.02.2018 10:42, Adrian Hunter wrote:
> 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;
Looks like this patch fixes all the problems. I'll keep testing it for a couple
of days and then report back the final result. Thank you very much.
>> (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
>>
>
On 22.02.2018 20:54, Dmitry Osipenko wrote:
> On 22.02.2018 10:42, Adrian Hunter wrote:
>> 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 know whether it's a combo card or not. Where I can find info about that?
Is it mentioned in sysfs somewhere? Alternatively you may take a brief look at
what brcmfmac driver does, maybe it will tell you immediately whether blk-mq
affects it or not. And if it's not affected, then it could be that there is some
other issue that is masked by a properly working 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;
>
> Looks like this patch fixes all the problems. I'll keep testing it for a couple
> of days and then report back the final result. Thank you very much.
This patch fixes the lockup (and WiFi MMC timeouts), for that:
Tested-by: Dmitry Osipenko <[email protected]>
But still something is wrong... I've been getting occasional EXT4 Ooops's, like
the one below, and __wait_on_bit() is always figuring in the stacktrace. It
never happened with blk-mq disabled, though it could be a coincidence and
actually unrelated to blk-mq patches.
[ 6625.992337] Unable to handle kernel NULL pointer dereference at virtual
address 0000001c
[ 6625.993004] pgd = 00b30c03
[ 6625.993257] [0000001c] *pgd=00000000
[ 6625.993594] Internal error: Oops: 5 [#1] PREEMPT SMP ARM
[ 6625.994022] Modules linked in:
[ 6625.994326] CPU: 1 PID: 19355 Comm: dpkg Not tainted
4.16.0-rc2-next-20180220-00095-ge9c9f5689a84-dirty #2090
[ 6625.995078] Hardware name: NVIDIA Tegra SoC (Flattened Device Tree)
[ 6625.995595] PC is at dx_probe+0x68/0x684
[ 6625.995947] LR is at __wait_on_bit+0xac/0xc8
[ 6625.996307] pc : [<c033b960>] lr : [<c0bfbfd4>] psr: 800f0013
[ 6625.996806] sp : d55e3df0 ip : c0170e88 fp : d55e3e44
[ 6625.997227] r10: d55e3f4c r9 : d55e3e70 r8 : 00000000
[ 6625.997650] r7 : c4e13240 r6 : 00000000 r5 : d657db18 r4 : d55e3e8c
[ 6625.998165] r3 : 0000007b r2 : d5830800 r1 : d5831000 r0 : c4e13240
[ 6625.998686] Flags: Nzcv IRQs on FIQs on Mode SVC_32 ISA ARM Segment none
[ 6625.999246] Control: 10c5387d Table: 0a63004a DAC: 00000051
[ 6625.999710] Process dpkg (pid: 19355, stack limit = 0x139a48b6)
[ 6626.000184] Stack: (0xd55e3df0 to 0xd55e4000)
[ 6626.000560] 3de0: 000002e9 d55e3e00
c0c01964 c0278c70
[ 6626.001209] 3e00: d55e3e24 014000c0 c04f3580 c0c01958 d55e3e90 801a001a
d55e3e3c 00000012
[ 6626.001854] 3e20: d5830800 00000000 d657db18 c24b0000 d55e3e70 d55e3f4c
d55e3edc d55e3e48
[ 6626.002502] 3e40: c033d568 c033b904 00000000 600f0013 c029e640 d6cf3540
ffffe000 00000000
[ 6626.003150] 3e60: 00076e99 d55e3ef4 d55e3e8c d5830800 d409c440 d409c454
00000012 c029e640
[ 6626.003795] 3e80: d55e3ec4 d55e3e90 c02797b4 c4e13240 00000000 00000000
00000000 00000000
[ 6626.004442] 3ea0: 00000000 00000000 00000000 00000000 d409c428 d409c428
d657db18 d409c428
[ 6626.005088] 3ec0: 00000000 c24b0000 ffffff9c d55e3f4c d55e3f14 d55e3ee0
c033d7b0 c033d1b8
[ 6626.005732] 3ee0: c0c01964 c0180050 d55e3f14 d55e3ef8 c029e870 00000000
d409c428 d6546558
[ 6626.006382] 3f00: d55e3f58 00000000 d55e3f34 d55e3f18 c0291f04 c033d764
00000000 00000001
[ 6626.007032] 3f20: 00000000 d55e3f58 d55e3f94 d55e3f38 c0293d70 c0291ea0
d55e3f58 d55e3f4c
[ 6626.007679] 3f40: 00000000 0090abb0 d5467800 00000000 d6dd0110 d6546558
f3bc423c 00000012
[ 6626.008326] 3f60: c24b0019 80808080 00000000 015ce1b0 0090abb0 00d8d670
00000028 c01011e4
[ 6626.008971] 3f80: d55e2000 00000000 d55e3fa4 d55e3f98 c0294544 c0293c44
00000000 d55e3fa8
[ 6626.009620] 3fa0: c0101000 c0294530 015ce1b0 0090abb0 0090abb0 000002a8
7d5a8800 7d5a8800
[ 6626.010264] 3fc0: 015ce1b0 0090abb0 00d8d670 00000028 0048eb80 00487344
015eb160 004a6c10
[ 6626.010912] 3fe0: 004a6c8c bede3c0c 0048149d b6ecc6b8 600f0030 0090abb0
00000000 00000000
[ 6626.011577] [<c033b960>] (dx_probe) from [<c033d568>]
(ext4_find_entry+0x3bc/0x5ac)
[ 6626.012198] [<c033d568>] (ext4_find_entry) from [<c033d7b0>]
(ext4_lookup+0x58/0x1f4)
[ 6626.012844] [<c033d7b0>] (ext4_lookup) from [<c0291f04>]
(__lookup_hash+0x70/0x9c)
[ 6626.013468] [<c0291f04>] (__lookup_hash) from [<c0293d70>] (do_rmdir+0x138/0x1b8)
[ 6626.014071] [<c0293d70>] (do_rmdir) from [<c0294544>] (SyS_rmdir+0x20/0x24)
[ 6626.014642] [<c0294544>] (SyS_rmdir) from [<c0101000>]
(ret_fast_syscall+0x0/0x54)
[ 6626.015231] Exception stack(0xd55e3fa8 to 0xd55e3ff0)
[ 6626.015656] 3fa0: 015ce1b0 0090abb0 0090abb0 000002a8
7d5a8800 7d5a8800
[ 6626.016302] 3fc0: 015ce1b0 0090abb0 00d8d670 00000028 0048eb80 00487344
015eb160 004a6c10
[ 6626.035930] 3fe0: 004a6c8c bede3c0c 0048149d b6ecc6b8
[ 6626.055341] Code: e1a07000 e5840000 8a000078 e590601c (e5d6301c)
[ 6626.075632] ---[ end trace 034f3552437a92bc ]---
On Mon, Feb 26, 2018 at 10:48 PM, Dmitry Osipenko <[email protected]> wrote:
> On 22.02.2018 20:54, Dmitry Osipenko wrote:
>> On 22.02.2018 10:42, Adrian Hunter wrote:
>>> SDIO (unless it is a combo card) should be unaffected by changes to the
>>> block driver.
>
> I don't know whether it's a combo card or not. Where I can find info about that?
> Is it mentioned in sysfs somewhere?
Combo cards were used with very old (2000s) PDAs which had only
one SD card slot which they wanted to use for WiFi and storage
at the same time.
They are very uncommon and I haven't been able to locate any
even for testing.
It is very unlikely that you have one.
However you would notice it from seeing a partition attachment
message (like with an ordinary SD card) when you plug in your
card.
Yours,
Linus Walleij
On 26/02/18 23:48, Dmitry Osipenko wrote:
> On 22.02.2018 20:54, Dmitry Osipenko wrote:
>> On 22.02.2018 10:42, Adrian Hunter wrote:
>>> 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 know whether it's a combo card or not. Where I can find info about that?
> Is it mentioned in sysfs somewhere? Alternatively you may take a brief look at
> what brcmfmac driver does, maybe it will tell you immediately whether blk-mq
> affects it or not. And if it's not affected, then it could be that there is some
> other issue that is masked by a properly working block driver.
As linus wrote, if you had a combo card it would also show up as a block
device i.e. for mmc2 it would probably be /dev/mmcblk2 if it existed.
>
>>> 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;
>>
>> Looks like this patch fixes all the problems. I'll keep testing it for a couple
>> of days and then report back the final result. Thank you very much.
>
> This patch fixes the lockup (and WiFi MMC timeouts), for that:
>
> Tested-by: Dmitry Osipenko <[email protected]>
>
>
> But still something is wrong... I've been getting occasional EXT4 Ooops's, like
> the one below, and __wait_on_bit() is always figuring in the stacktrace. It
> never happened with blk-mq disabled, though it could be a coincidence and
> actually unrelated to blk-mq patches.
I can't think how an IO driver could cause that.
cc'ing ext4 mailing list for more advice.
>
>
> [ 6625.992337] Unable to handle kernel NULL pointer dereference at virtual
> address 0000001c
> [ 6625.993004] pgd = 00b30c03
> [ 6625.993257] [0000001c] *pgd=00000000
> [ 6625.993594] Internal error: Oops: 5 [#1] PREEMPT SMP ARM
> [ 6625.994022] Modules linked in:
> [ 6625.994326] CPU: 1 PID: 19355 Comm: dpkg Not tainted
> 4.16.0-rc2-next-20180220-00095-ge9c9f5689a84-dirty #2090
> [ 6625.995078] Hardware name: NVIDIA Tegra SoC (Flattened Device Tree)
> [ 6625.995595] PC is at dx_probe+0x68/0x684
> [ 6625.995947] LR is at __wait_on_bit+0xac/0xc8
> [ 6625.996307] pc : [<c033b960>] lr : [<c0bfbfd4>] psr: 800f0013
> [ 6625.996806] sp : d55e3df0 ip : c0170e88 fp : d55e3e44
> [ 6625.997227] r10: d55e3f4c r9 : d55e3e70 r8 : 00000000
> [ 6625.997650] r7 : c4e13240 r6 : 00000000 r5 : d657db18 r4 : d55e3e8c
> [ 6625.998165] r3 : 0000007b r2 : d5830800 r1 : d5831000 r0 : c4e13240
> [ 6625.998686] Flags: Nzcv IRQs on FIQs on Mode SVC_32 ISA ARM Segment none
> [ 6625.999246] Control: 10c5387d Table: 0a63004a DAC: 00000051
> [ 6625.999710] Process dpkg (pid: 19355, stack limit = 0x139a48b6)
> [ 6626.000184] Stack: (0xd55e3df0 to 0xd55e4000)
> [ 6626.000560] 3de0: 000002e9 d55e3e00
> c0c01964 c0278c70
> [ 6626.001209] 3e00: d55e3e24 014000c0 c04f3580 c0c01958 d55e3e90 801a001a
> d55e3e3c 00000012
> [ 6626.001854] 3e20: d5830800 00000000 d657db18 c24b0000 d55e3e70 d55e3f4c
> d55e3edc d55e3e48
> [ 6626.002502] 3e40: c033d568 c033b904 00000000 600f0013 c029e640 d6cf3540
> ffffe000 00000000
> [ 6626.003150] 3e60: 00076e99 d55e3ef4 d55e3e8c d5830800 d409c440 d409c454
> 00000012 c029e640
> [ 6626.003795] 3e80: d55e3ec4 d55e3e90 c02797b4 c4e13240 00000000 00000000
> 00000000 00000000
> [ 6626.004442] 3ea0: 00000000 00000000 00000000 00000000 d409c428 d409c428
> d657db18 d409c428
> [ 6626.005088] 3ec0: 00000000 c24b0000 ffffff9c d55e3f4c d55e3f14 d55e3ee0
> c033d7b0 c033d1b8
> [ 6626.005732] 3ee0: c0c01964 c0180050 d55e3f14 d55e3ef8 c029e870 00000000
> d409c428 d6546558
> [ 6626.006382] 3f00: d55e3f58 00000000 d55e3f34 d55e3f18 c0291f04 c033d764
> 00000000 00000001
> [ 6626.007032] 3f20: 00000000 d55e3f58 d55e3f94 d55e3f38 c0293d70 c0291ea0
> d55e3f58 d55e3f4c
> [ 6626.007679] 3f40: 00000000 0090abb0 d5467800 00000000 d6dd0110 d6546558
> f3bc423c 00000012
> [ 6626.008326] 3f60: c24b0019 80808080 00000000 015ce1b0 0090abb0 00d8d670
> 00000028 c01011e4
> [ 6626.008971] 3f80: d55e2000 00000000 d55e3fa4 d55e3f98 c0294544 c0293c44
> 00000000 d55e3fa8
> [ 6626.009620] 3fa0: c0101000 c0294530 015ce1b0 0090abb0 0090abb0 000002a8
> 7d5a8800 7d5a8800
> [ 6626.010264] 3fc0: 015ce1b0 0090abb0 00d8d670 00000028 0048eb80 00487344
> 015eb160 004a6c10
> [ 6626.010912] 3fe0: 004a6c8c bede3c0c 0048149d b6ecc6b8 600f0030 0090abb0
> 00000000 00000000
> [ 6626.011577] [<c033b960>] (dx_probe) from [<c033d568>]
> (ext4_find_entry+0x3bc/0x5ac)
> [ 6626.012198] [<c033d568>] (ext4_find_entry) from [<c033d7b0>]
> (ext4_lookup+0x58/0x1f4)
> [ 6626.012844] [<c033d7b0>] (ext4_lookup) from [<c0291f04>]
> (__lookup_hash+0x70/0x9c)
> [ 6626.013468] [<c0291f04>] (__lookup_hash) from [<c0293d70>] (do_rmdir+0x138/0x1b8)
> [ 6626.014071] [<c0293d70>] (do_rmdir) from [<c0294544>] (SyS_rmdir+0x20/0x24)
> [ 6626.014642] [<c0294544>] (SyS_rmdir) from [<c0101000>]
> (ret_fast_syscall+0x0/0x54)
> [ 6626.015231] Exception stack(0xd55e3fa8 to 0xd55e3ff0)
> [ 6626.015656] 3fa0: 015ce1b0 0090abb0 0090abb0 000002a8
> 7d5a8800 7d5a8800
> [ 6626.016302] 3fc0: 015ce1b0 0090abb0 00d8d670 00000028 0048eb80 00487344
> 015eb160 004a6c10
> [ 6626.035930] 3fe0: 004a6c8c bede3c0c 0048149d b6ecc6b8
> [ 6626.055341] Code: e1a07000 e5840000 8a000078 e590601c (e5d6301c)
> [ 6626.075632] ---[ end trace 034f3552437a92bc ]---
>
On 27.02.2018 11:57, Linus Walleij wrote:
> On Mon, Feb 26, 2018 at 10:48 PM, Dmitry Osipenko <[email protected]> wrote:
>> On 22.02.2018 20:54, Dmitry Osipenko wrote:
>>> On 22.02.2018 10:42, Adrian Hunter wrote:
>
>>>> SDIO (unless it is a combo card) should be unaffected by changes to the
>>>> block driver.
>>
>> I don't know whether it's a combo card or not. Where I can find info about that?
>> Is it mentioned in sysfs somewhere?
>
> Combo cards were used with very old (2000s) PDAs which had only
> one SD card slot which they wanted to use for WiFi and storage
> at the same time.
>
> They are very uncommon and I haven't been able to locate any
> even for testing.
>
> It is very unlikely that you have one.
>
> However you would notice it from seeing a partition attachment
> message (like with an ordinary SD card) when you plug in your
> card.
Thank you very much for the explanation. It's not a combo card.
On 27/02/18 11:28, Adrian Hunter wrote:
> On 26/02/18 23:48, Dmitry Osipenko wrote:
>> But still something is wrong... I've been getting occasional EXT4 Ooops's, like
>> the one below, and __wait_on_bit() is always figuring in the stacktrace. It
>> never happened with blk-mq disabled, though it could be a coincidence and
>> actually unrelated to blk-mq patches.
>
> I can't think how an IO driver could cause that.
>
> cc'ing ext4 mailing list for more advice.
+ Ted and Andreas
>
>>
>>
>> [ 6625.992337] Unable to handle kernel NULL pointer dereference at virtual
>> address 0000001c
>> [ 6625.993004] pgd = 00b30c03
>> [ 6625.993257] [0000001c] *pgd=00000000
>> [ 6625.993594] Internal error: Oops: 5 [#1] PREEMPT SMP ARM
>> [ 6625.994022] Modules linked in:
>> [ 6625.994326] CPU: 1 PID: 19355 Comm: dpkg Not tainted
>> 4.16.0-rc2-next-20180220-00095-ge9c9f5689a84-dirty #2090
>> [ 6625.995078] Hardware name: NVIDIA Tegra SoC (Flattened Device Tree)
>> [ 6625.995595] PC is at dx_probe+0x68/0x684
>> [ 6625.995947] LR is at __wait_on_bit+0xac/0xc8
>> [ 6625.996307] pc : [<c033b960>] lr : [<c0bfbfd4>] psr: 800f0013
>> [ 6625.996806] sp : d55e3df0 ip : c0170e88 fp : d55e3e44
>> [ 6625.997227] r10: d55e3f4c r9 : d55e3e70 r8 : 00000000
>> [ 6625.997650] r7 : c4e13240 r6 : 00000000 r5 : d657db18 r4 : d55e3e8c
>> [ 6625.998165] r3 : 0000007b r2 : d5830800 r1 : d5831000 r0 : c4e13240
>> [ 6625.998686] Flags: Nzcv IRQs on FIQs on Mode SVC_32 ISA ARM Segment none
>> [ 6625.999246] Control: 10c5387d Table: 0a63004a DAC: 00000051
>> [ 6625.999710] Process dpkg (pid: 19355, stack limit = 0x139a48b6)
>> [ 6626.000184] Stack: (0xd55e3df0 to 0xd55e4000)
>> [ 6626.000560] 3de0: 000002e9 d55e3e00
>> c0c01964 c0278c70
>> [ 6626.001209] 3e00: d55e3e24 014000c0 c04f3580 c0c01958 d55e3e90 801a001a
>> d55e3e3c 00000012
>> [ 6626.001854] 3e20: d5830800 00000000 d657db18 c24b0000 d55e3e70 d55e3f4c
>> d55e3edc d55e3e48
>> [ 6626.002502] 3e40: c033d568 c033b904 00000000 600f0013 c029e640 d6cf3540
>> ffffe000 00000000
>> [ 6626.003150] 3e60: 00076e99 d55e3ef4 d55e3e8c d5830800 d409c440 d409c454
>> 00000012 c029e640
>> [ 6626.003795] 3e80: d55e3ec4 d55e3e90 c02797b4 c4e13240 00000000 00000000
>> 00000000 00000000
>> [ 6626.004442] 3ea0: 00000000 00000000 00000000 00000000 d409c428 d409c428
>> d657db18 d409c428
>> [ 6626.005088] 3ec0: 00000000 c24b0000 ffffff9c d55e3f4c d55e3f14 d55e3ee0
>> c033d7b0 c033d1b8
>> [ 6626.005732] 3ee0: c0c01964 c0180050 d55e3f14 d55e3ef8 c029e870 00000000
>> d409c428 d6546558
>> [ 6626.006382] 3f00: d55e3f58 00000000 d55e3f34 d55e3f18 c0291f04 c033d764
>> 00000000 00000001
>> [ 6626.007032] 3f20: 00000000 d55e3f58 d55e3f94 d55e3f38 c0293d70 c0291ea0
>> d55e3f58 d55e3f4c
>> [ 6626.007679] 3f40: 00000000 0090abb0 d5467800 00000000 d6dd0110 d6546558
>> f3bc423c 00000012
>> [ 6626.008326] 3f60: c24b0019 80808080 00000000 015ce1b0 0090abb0 00d8d670
>> 00000028 c01011e4
>> [ 6626.008971] 3f80: d55e2000 00000000 d55e3fa4 d55e3f98 c0294544 c0293c44
>> 00000000 d55e3fa8
>> [ 6626.009620] 3fa0: c0101000 c0294530 015ce1b0 0090abb0 0090abb0 000002a8
>> 7d5a8800 7d5a8800
>> [ 6626.010264] 3fc0: 015ce1b0 0090abb0 00d8d670 00000028 0048eb80 00487344
>> 015eb160 004a6c10
>> [ 6626.010912] 3fe0: 004a6c8c bede3c0c 0048149d b6ecc6b8 600f0030 0090abb0
>> 00000000 00000000
>> [ 6626.011577] [<c033b960>] (dx_probe) from [<c033d568>]
>> (ext4_find_entry+0x3bc/0x5ac)
>> [ 6626.012198] [<c033d568>] (ext4_find_entry) from [<c033d7b0>]
>> (ext4_lookup+0x58/0x1f4)
>> [ 6626.012844] [<c033d7b0>] (ext4_lookup) from [<c0291f04>]
>> (__lookup_hash+0x70/0x9c)
>> [ 6626.013468] [<c0291f04>] (__lookup_hash) from [<c0293d70>] (do_rmdir+0x138/0x1b8)
>> [ 6626.014071] [<c0293d70>] (do_rmdir) from [<c0294544>] (SyS_rmdir+0x20/0x24)
>> [ 6626.014642] [<c0294544>] (SyS_rmdir) from [<c0101000>]
>> (ret_fast_syscall+0x0/0x54)
>> [ 6626.015231] Exception stack(0xd55e3fa8 to 0xd55e3ff0)
>> [ 6626.015656] 3fa0: 015ce1b0 0090abb0 0090abb0 000002a8
>> 7d5a8800 7d5a8800
>> [ 6626.016302] 3fc0: 015ce1b0 0090abb0 00d8d670 00000028 0048eb80 00487344
>> 015eb160 004a6c10
>> [ 6626.035930] 3fe0: 004a6c8c bede3c0c 0048149d b6ecc6b8
>> [ 6626.055341] Code: e1a07000 e5840000 8a000078 e590601c (e5d6301c)
>> [ 6626.075632] ---[ end trace 034f3552437a92bc ]---
>>
>
>
On Thu, Mar 1, 2018 at 12:55 AM, Adrian Hunter <[email protected]> wrote:
> On 27/02/18 11:28, Adrian Hunter wrote:
>> On 26/02/18 23:48, Dmitry Osipenko wrote:
>>> But still something is wrong... I've been getting occasional EXT4 Ooops's, like
>>> the one below, and __wait_on_bit() is always figuring in the stacktrace. It
>>> never happened with blk-mq disabled, though it could be a coincidence and
>>> actually unrelated to blk-mq patches.
>>
>> I can't think how an IO driver could cause that.
Probably it is not wise to place all your eggs (data) in one basket
(ext4) and diversify to viable alternatives which won't be affected by
UNIX 2038 year date problem, likewise?
< https://metztli.it/blog/index.php/amatl/reiser-nahui/reiser4-filesystem-and-the-unix
>
>>
>> cc'ing ext4 mailing list for more advice.
>
> + Ted and Andreas
>
>>
>>>
>>>
>>> [ 6625.992337] Unable to handle kernel NULL pointer dereference at virtual
>>> address 0000001c
>>> [ 6625.993004] pgd = 00b30c03
>>> [ 6625.993257] [0000001c] *pgd=00000000
>>> [ 6625.993594] Internal error: Oops: 5 [#1] PREEMPT SMP ARM
>>> [ 6625.994022] Modules linked in:
>>> [ 6625.994326] CPU: 1 PID: 19355 Comm: dpkg Not tainted
>>> 4.16.0-rc2-next-20180220-00095-ge9c9f5689a84-dirty #2090
>>> [ 6625.995078] Hardware name: NVIDIA Tegra SoC (Flattened Device Tree)
>>> [ 6625.995595] PC is at dx_probe+0x68/0x684
>>> [ 6625.995947] LR is at __wait_on_bit+0xac/0xc8
>>> [ 6625.996307] pc : [<c033b960>] lr : [<c0bfbfd4>] psr: 800f0013
>>> [ 6625.996806] sp : d55e3df0 ip : c0170e88 fp : d55e3e44
>>> [ 6625.997227] r10: d55e3f4c r9 : d55e3e70 r8 : 00000000
>>> [ 6625.997650] r7 : c4e13240 r6 : 00000000 r5 : d657db18 r4 : d55e3e8c
>>> [ 6625.998165] r3 : 0000007b r2 : d5830800 r1 : d5831000 r0 : c4e13240
>>> [ 6625.998686] Flags: Nzcv IRQs on FIQs on Mode SVC_32 ISA ARM Segment none
>>> [ 6625.999246] Control: 10c5387d Table: 0a63004a DAC: 00000051
>>> [ 6625.999710] Process dpkg (pid: 19355, stack limit = 0x139a48b6)
>>> [ 6626.000184] Stack: (0xd55e3df0 to 0xd55e4000)
>>> [ 6626.000560] 3de0: 000002e9 d55e3e00
>>> c0c01964 c0278c70
>>> [ 6626.001209] 3e00: d55e3e24 014000c0 c04f3580 c0c01958 d55e3e90 801a001a
>>> d55e3e3c 00000012
>>> [ 6626.001854] 3e20: d5830800 00000000 d657db18 c24b0000 d55e3e70 d55e3f4c
>>> d55e3edc d55e3e48
>>> [ 6626.002502] 3e40: c033d568 c033b904 00000000 600f0013 c029e640 d6cf3540
>>> ffffe000 00000000
>>> [ 6626.003150] 3e60: 00076e99 d55e3ef4 d55e3e8c d5830800 d409c440 d409c454
>>> 00000012 c029e640
>>> [ 6626.003795] 3e80: d55e3ec4 d55e3e90 c02797b4 c4e13240 00000000 00000000
>>> 00000000 00000000
>>> [ 6626.004442] 3ea0: 00000000 00000000 00000000 00000000 d409c428 d409c428
>>> d657db18 d409c428
>>> [ 6626.005088] 3ec0: 00000000 c24b0000 ffffff9c d55e3f4c d55e3f14 d55e3ee0
>>> c033d7b0 c033d1b8
>>> [ 6626.005732] 3ee0: c0c01964 c0180050 d55e3f14 d55e3ef8 c029e870 00000000
>>> d409c428 d6546558
>>> [ 6626.006382] 3f00: d55e3f58 00000000 d55e3f34 d55e3f18 c0291f04 c033d764
>>> 00000000 00000001
>>> [ 6626.007032] 3f20: 00000000 d55e3f58 d55e3f94 d55e3f38 c0293d70 c0291ea0
>>> d55e3f58 d55e3f4c
>>> [ 6626.007679] 3f40: 00000000 0090abb0 d5467800 00000000 d6dd0110 d6546558
>>> f3bc423c 00000012
>>> [ 6626.008326] 3f60: c24b0019 80808080 00000000 015ce1b0 0090abb0 00d8d670
>>> 00000028 c01011e4
>>> [ 6626.008971] 3f80: d55e2000 00000000 d55e3fa4 d55e3f98 c0294544 c0293c44
>>> 00000000 d55e3fa8
>>> [ 6626.009620] 3fa0: c0101000 c0294530 015ce1b0 0090abb0 0090abb0 000002a8
>>> 7d5a8800 7d5a8800
>>> [ 6626.010264] 3fc0: 015ce1b0 0090abb0 00d8d670 00000028 0048eb80 00487344
>>> 015eb160 004a6c10
>>> [ 6626.010912] 3fe0: 004a6c8c bede3c0c 0048149d b6ecc6b8 600f0030 0090abb0
>>> 00000000 00000000
>>> [ 6626.011577] [<c033b960>] (dx_probe) from [<c033d568>]
>>> (ext4_find_entry+0x3bc/0x5ac)
>>> [ 6626.012198] [<c033d568>] (ext4_find_entry) from [<c033d7b0>]
>>> (ext4_lookup+0x58/0x1f4)
>>> [ 6626.012844] [<c033d7b0>] (ext4_lookup) from [<c0291f04>]
>>> (__lookup_hash+0x70/0x9c)
>>> [ 6626.013468] [<c0291f04>] (__lookup_hash) from [<c0293d70>] (do_rmdir+0x138/0x1b8)
>>> [ 6626.014071] [<c0293d70>] (do_rmdir) from [<c0294544>] (SyS_rmdir+0x20/0x24)
>>> [ 6626.014642] [<c0294544>] (SyS_rmdir) from [<c0101000>]
>>> (ret_fast_syscall+0x0/0x54)
>>> [ 6626.015231] Exception stack(0xd55e3fa8 to 0xd55e3ff0)
>>> [ 6626.015656] 3fa0: 015ce1b0 0090abb0 0090abb0 000002a8
>>> 7d5a8800 7d5a8800
>>> [ 6626.016302] 3fc0: 015ce1b0 0090abb0 00d8d670 00000028 0048eb80 00487344
>>> 015eb160 004a6c10
>>> [ 6626.035930] 3fe0: 004a6c8c bede3c0c 0048149d b6ecc6b8
>>> [ 6626.055341] Code: e1a07000 e5840000 8a000078 e590601c (e5d6301c)
>>> [ 6626.075632] ---[ end trace 034f3552437a92bc ]---
>>>
>>
>>
>
Sorry if I intrude but just my 2¢.
Best Professional Regards.
--
Jose R R
http://metztli.it
---------------------------------------------------------------------------------------------
Download Metztli Reiser4: Debian Stretch w/ Linux 4.14 AMD64
---------------------------------------------------------------------------------------------
feats ZSTD compression https://sf.net/projects/metztli-reiser4/
-------------------------------------------------------------------------------------------
Official current Reiser4 resources: https://reiser4.wiki.kernel.org/
On Thu, Mar 01, 2018 at 10:55:37AM +0200, Adrian Hunter wrote:
> On 27/02/18 11:28, Adrian Hunter wrote:
> > On 26/02/18 23:48, Dmitry Osipenko wrote:
> >> But still something is wrong... I've been getting occasional EXT4 Ooops's, like
> >> the one below, and __wait_on_bit() is always figuring in the stacktrace. It
> >> never happened with blk-mq disabled, though it could be a coincidence and
> >> actually unrelated to blk-mq patches.
> >
> >> [ 6625.992337] Unable to handle kernel NULL pointer dereference at virtual
> >> address 0000001c
> >> [ 6625.993004] pgd = 00b30c03
> >> [ 6625.993257] [0000001c] *pgd=00000000
> >> [ 6625.993594] Internal error: Oops: 5 [#1] PREEMPT SMP ARM
> >> [ 6625.994022] Modules linked in:
> >> [ 6625.994326] CPU: 1 PID: 19355 Comm: dpkg Not tainted
> >> 4.16.0-rc2-next-20180220-00095-ge9c9f5689a84-dirty #2090
> >> [ 6625.995078] Hardware name: NVIDIA Tegra SoC (Flattened Device Tree)
> >> [ 6625.995595] PC is aht dx_probe+0x68/0x684
> >> [ 6625.995947] LR is at __wait_on_bit+0xac/0xc8
This doesn't seem to make sense; the PC is where we are currently
executing, and LR is the "Link Register" where the flow of control
will be returning after the current function returns, right? Well,
dx_probe should *not* be returning to __wait_on_bit(). So this just
seems.... weird.
Ignoring the LR register, this stack trace looks sane... I can't see
which pointer could be NULL and getting dereferenced, though. How
easily can you reproduce the problem? Can you either (a) translate
the PC into a line number, or better yet, if you can reproduce, add a
series of BUG_ON's so we can see what's going on?
+ BUG_ON(frame);
memset(frame_in, 0, EXT4_HTREE_LEVEL * sizeof(frame_in[0]));
frame->bh = ext4_read_dirblock(dir, 0, INDEX);
if (IS_ERR(frame->bh))
return (struct dx_frame *) frame->bh;
+ BUG_ON(frame->bh);
+ BUG_ON(frame->bh->b_data);
root = (struct dx_root *) frame->bh->b_data;
if (root->info.hash_version != DX_HASH_TEA &&
root->info.hash_version != DX_HASH_HALF_MD4 &&
root->info.hash_version != DX_HASH_LEGACY) {
These are "could never" happen scenarios from looking at the code, but
that will help explain what is going on.
If this is reliably only happening with mq, the only way I could see
that if is something is returning an error when it previously wasn't.
This isn't a problem we're seeing with any of our testing, though.
Cheers,
- Ted
On Thu, Mar 01, 2018 at 01:15:24AM -0800, Jose R R wrote:
> Probably it is not wise to place all your eggs (data) in one basket
> (ext4) and diversify to viable alternatives which won't be affected by
> UNIX 2038 year date problem, likewise?
> < https://metztli.it/blog/index.php/amatl8/reiser-nahui/reiser4-filesystem-and-the-unix
> >
All of the modern file systems (btrfs, ext4, f2fs, xfs, etc.) are fine
with respect to the 2038 problem.
- Ted
On Mar 1, 2018, at 9:04 AM, Theodore Ts'o <[email protected]> wrote:
> This doesn't seem to make sense; the PC is where we are currently
> executing, and LR is the "Link Register" where the flow of control
> will be returning after the current function returns, right? Well,
> dx_probe should *not* be returning to __wait_on_bit(). So this just
> seems.... weird.
>
> Ignoring the LR register, this stack trace looks sane... I can't see
> which pointer could be NULL and getting dereferenced, though. How
> easily can you reproduce the problem? Can you either (a) translate
> the PC into a line number, or better yet, if you can reproduce, add a
> series of BUG_ON's so we can see what's going on?
>
> + BUG_ON(frame);
I think you mean:
BUG_ON(frame == NULL);
or
BUG_ON(!frame);
> memset(frame_in, 0, EXT4_HTREE_LEVEL * sizeof(frame_in[0]));
> frame->bh = ext4_read_dirblock(dir, 0, INDEX);
> if (IS_ERR(frame->bh))
> return (struct dx_frame *) frame->bh;
>
> + BUG_ON(frame->bh);
> + BUG_ON(frame->bh->b_data);
Same here.
BUG_ON(frame->bh == NULL);
BUG_ON(frame->bh->b_data == NULL);
This is why I don't like implicit "is NULL" or "is non-zero" usage. Lustre
used to require "== NULL" or "!= NULL" to avoid bugs like this, but had to
abandon that because of upstream code style.
> root = (struct dx_root *) frame->bh->b_data;
> if (root->info.hash_version != DX_HASH_TEA &&
> root->info.hash_version != DX_HASH_HALF_MD4 &&
> root->info.hash_version != DX_HASH_LEGACY) {
>
> These are "could never" happen scenarios from looking at the code, but
> that will help explain what is going on.
>
> If this is reliably only happening with mq, the only way I could see
> that if is something is returning an error when it previously wasn't.
> This isn't a problem we're seeing with any of our testing, though.
>
> Cheers,
>
> - Ted
>
Cheers, Andreas
On 01.03.2018 23:20, Andreas Dilger wrote:
>
> On Mar 1, 2018, at 9:04 AM, Theodore Ts'o <[email protected]> wrote:
>> This doesn't seem to make sense; the PC is where we are currently
>> executing, and LR is the "Link Register" where the flow of control
>> will be returning after the current function returns, right? Well,
>> dx_probe should *not* be returning to __wait_on_bit(). So this just
>> seems.... weird.
>>
>> Ignoring the LR register, this stack trace looks sane... I can't see
>> which pointer could be NULL and getting dereferenced, though. How
>> easily can you reproduce the problem? Can you either (a) translate
>> the PC into a line number, or better yet, if you can reproduce, add a
>> series of BUG_ON's so we can see what's going on?
Ted, thank you for the suggestion. I don't have a bug-reproducer, it happens
only under some IO load and quite randomly. I've applied the BUG_ON()'s, but it
may take some time to catch the bug again.
>> + BUG_ON(frame);
>
> I think you mean:
> BUG_ON(frame == NULL);
> or
> BUG_ON(!frame);
>
>
>> memset(frame_in, 0, EXT4_HTREE_LEVEL * sizeof(frame_in[0]));
>> frame->bh = ext4_read_dirblock(dir, 0, INDEX);
>> if (IS_ERR(frame->bh))
>> return (struct dx_frame *) frame->bh;
>>
>> + BUG_ON(frame->bh);
>> + BUG_ON(frame->bh->b_data);
>
> Same here.
>
> BUG_ON(frame->bh == NULL);
> BUG_ON(frame->bh->b_data == NULL);
>
> This is why I don't like implicit "is NULL" or "is non-zero" usage. Lustre
> used to require "== NULL" or "!= NULL" to avoid bugs like this, but had to
> abandon that because of upstream code style.
Well spotted, thanks Andreas.
>> root = (struct dx_root *) frame->bh->b_data;
>> if (root->info.hash_version != DX_HASH_TEA &&
>> root->info.hash_version != DX_HASH_HALF_MD4 &&
>> root->info.hash_version != DX_HASH_LEGACY) {
>>
>> These are "could never" happen scenarios from looking at the code, but
>> that will help explain what is going on.
>>
>> If this is reliably only happening with mq, the only way I could see
>> that if is something is returning an error when it previously wasn't.
>> This isn't a problem we're seeing with any of our testing, though.
On 01.03.2018 19:04, Theodore Ts'o wrote:
> On Thu, Mar 01, 2018 at 10:55:37AM +0200, Adrian Hunter wrote:
>> On 27/02/18 11:28, Adrian Hunter wrote:
>>> On 26/02/18 23:48, Dmitry Osipenko wrote:
>>>> But still something is wrong... I've been getting occasional EXT4 Ooops's, like
>>>> the one below, and __wait_on_bit() is always figuring in the stacktrace. It
>>>> never happened with blk-mq disabled, though it could be a coincidence and
>>>> actually unrelated to blk-mq patches.
>>>
>>>> [ 6625.992337] Unable to handle kernel NULL pointer dereference at virtual
>>>> address 0000001c
>>>> [ 6625.993004] pgd = 00b30c03
>>>> [ 6625.993257] [0000001c] *pgd=00000000
>>>> [ 6625.993594] Internal error: Oops: 5 [#1] PREEMPT SMP ARM
>>>> [ 6625.994022] Modules linked in:
>>>> [ 6625.994326] CPU: 1 PID: 19355 Comm: dpkg Not tainted
>>>> 4.16.0-rc2-next-20180220-00095-ge9c9f5689a84-dirty #2090
>>>> [ 6625.995078] Hardware name: NVIDIA Tegra SoC (Flattened Device Tree)
>>>> [ 6625.995595] PC is aht dx_probe+0x68/0x684
>>>> [ 6625.995947] LR is at __wait_on_bit+0xac/0xc8
>
> This doesn't seem to make sense; the PC is where we are currently
> executing, and LR is the "Link Register" where the flow of control
> will be returning after the current function returns, right? Well,
> dx_probe should *not* be returning to __wait_on_bit(). So this just
> seems.... weird.
>
> Ignoring the LR register, this stack trace looks sane... I can't see
> which pointer could be NULL and getting dereferenced, though. How
> easily can you reproduce the problem? Can you either (a) translate
> the PC into a line number, or better yet, if you can reproduce, add a
> series of BUG_ON's so we can see what's going on?
>
> + BUG_ON(frame);
> memset(frame_in, 0, EXT4_HTREE_LEVEL * sizeof(frame_in[0]));
> frame->bh = ext4_read_dirblock(dir, 0, INDEX);
> if (IS_ERR(frame->bh))
> return (struct dx_frame *) frame->bh;
>
> + BUG_ON(frame->bh);
> + BUG_ON(frame->bh->b_data);
> root = (struct dx_root *) frame->bh->b_data;
> if (root->info.hash_version != DX_HASH_TEA &&
> root->info.hash_version != DX_HASH_HALF_MD4 &&
> root->info.hash_version != DX_HASH_LEGACY) {
>
> These are "could never" happen scenarios from looking at the code, but
> that will help explain what is going on.
>
> If this is reliably only happening with mq, the only way I could see
> that if is something is returning an error when it previously wasn't.
> This isn't a problem we're seeing with any of our testing, though.
It happened today again, "BUG_ON(!frame->bh->b_data);" has been trapped.
kernel BUG at fs/ext4/namei.c:751!
Internal error: Oops - BUG: 0 [#1] PREEMPT SMP ARM
Modules linked in:
CPU: 0 PID: 296 Comm: cron Not tainted
4.16.0-rc2-next-20180220-00095-ge9c9f5689a84-dirty #2100
Hardware name: NVIDIA Tegra SoC (Flattened Device Tree)
PC is at dx_probe+0x308/0x694
LR is at __wait_on_bit+0xac/0xc8
pc : [<c033bc00>] lr : [<c0bfbff4>] psr: 60040013
sp : d545bc20 ip : c0170e88 fp : d545bc74
r10: 00000000 r9 : d545bca0 r8 : d4209300
r7 : 00000000 r6 : 00000000 r5 : d656e838 r4 : d545bcbc
r3 : 0000007b r2 : d5830800 r1 : d5831000 r0 : d4209300
Flags: nZCv IRQs on FIQs on Mode SVC_32 ISA ARM Segment none
Control: 10c5387d Table: 1552004a DAC: 00000051
Process cron (pid: 296, stack limit = 0x4d1ebf14)
Stack: (0xd545bc20 to 0xd545c000)
bc20: 000002ea c0c019d4 60040113 014000c0 c029e640 d6cf3540 d545bc7c d545bc48
bc40: c02797f4 c0152804 d545bca4 00000007 d5830800 00000000 d656e838 00000001
bc60: d545bca0 00000000 d545bd0c d545bc78 c033d578 c033b904 c029e714 c029b088
bc80: 00000148 c0c01984 d65f6be0 00000000 d545be10 d545bd24 d545bd00 d5830800
bca0: d65f6bf8 d65f6c0c 00000007 d6547720 8420edbe c029eec8 00000000 d4209300
bcc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
bce0: d545bd48 d65f6be0 d656e838 d65f6be0 d6547720 00000001 d545be10 00000000
bd00: d545bd44 d545bd10 c033d7c0 c033d1c8 d545bd34 d656e8b8 d656e838 d545be08
bd20: d656e838 00000000 d65f6be0 d656e838 d656e8b8 d6547720 d545bd8c d545bd48
bd40: c028ea50 c033d774 00000000 dead4ead ffffffff ffffffff d545bd58 d545bd58
bd60: d6d7f015 d545be08 00000000 00000000 d545bee8 d545bee8 d545bf28 00000000
bd80: d545bdd4 d545bd90 c028f310 c028e9b0 d545be08 80808080 d545be08 d6d7f010
bda0: d545bdd4 d545bdb0 c028df9c d545be08 d6d7f010 00000000 d545bee8 d545bee8
bdc0: d545bf28 00000000 d545be04 d545bdd8 c0290e24 c028f160 c0111a1c c0111674
bde0: d545be04 d545bdf0 00000001 d6d7f000 d545be08 00000001 d545beb4 d545be08
be00: c0293848 c0290da4 d6dd0310 d6547720 8420edbe 00000007 d6d7f015 0000000c
be20: d6dd0310 d6547098 d656e838 00000001 00000002 00000fe0 00000000 00000000
be40: 00000000 d545be48 c02797f4 00000ff0 d6d7f010 c102b4c8 d5522db8 d6d7f000
be60: c130bbdc 004f73f8 00000000 00000001 d545bf28 00000000 d6d7f000 00000000
be80: c0293570 00000002 ffffff9c 00000001 ffffff9c 00000001 ffffff9c d545bee8
bea0: ffffff9c 004f73f8 d545bedc d545beb8 c0293990 c02937b4 00000000 00000000
bec0: 00000000 beb93970 00000001 00000800 d545bf1c d545bee0 c028859c c0293948
bee0: 00000000 d545bfb0 00509070 00508d7c d545bfac beb93970 00000003 beb95cd0
bf00: 000000c3 c01011e4 d545a000 00000000 d545bfa4 d545bf20 c0288df4 c0288540
bf20: 000007ff c0152868 00000fff 000043d8 00000002 00001000 00000000 00000000
bf40: 00000874 00000000 0006037f 00000000 0b300031 00000000 00000000 0000006d
bf60: 00001000 00000000 5a9c7e8b 2d4cae00 5a0d222f 00000000 5a8c9273 22358b29
bf80: 5a8c8591 301168da 00000008 b6ea94fc 00030030 b6f91ab8 00000000 d545bfa8
bfa0: c0101000 c0288dc8 b6f91ab8 00000003 004f73f8 beb93970 beb93a90 3dc50800
bfc0: b6f91ab8 00000003 beb95cd0 000000c3 00509cec 00509070 00508d7c 00000002
bfe0: 000000c3 beb93968 b6ea354b b6e2ccf6 20030030 004f73f8 17bfd861 17bfdc61
[<c033bc00>] (dx_probe) from [<c033d578>] (ext4_find_entry+0x3bc/0x5ac)
[<c033d578>] (ext4_find_entry) from [<c033d7c0>] (ext4_lookup+0x58/0x1f4)
[<c033d7c0>] (ext4_lookup) from [<c028ea50>] (lookup_slow+0xac/0x15c)
[<c028ea50>] (lookup_slow) from [<c028f310>] (walk_component+0x1bc/0x2f0)
[<c028f310>] (walk_component) from [<c0290e24>] (path_lookupat+0x8c/0x1f0)
[<c0290e24>] (path_lookupat) from [<c0293848>] (filename_lookup+0xa0/0xfc)
[<c0293848>] (filename_lookup) from [<c0293990>] (user_path_at_empty+0x54/0x5c)
[<c0293990>] (user_path_at_empty) from [<c028859c>] (vfs_statx+0x68/0xc4)
[<c028859c>] (vfs_statx) from [<c0288df4>] (SyS_stat64+0x38/0x54)
[<c0288df4>] (SyS_stat64) from [<c0101000>] (ret_fast_syscall+0x0/0x54)
Exception stack(0xd545bfa8 to 0xd545bff0)
bfa0: b6f91ab8 00000003 004f73f8 beb93970 beb93a90 3dc50800
bfc0: b6f91ab8 00000003 beb95cd0 000000c3 00509cec 00509070 00508d7c 00000002
bfe0: 000000c3 beb93968 b6ea354b b6e2ccf6
Code: e2833094 e587300c eaffff72 e7f001f2 (e7f001f2)
---[ end trace 60fa8eaa4e57e458 ]---