During the emmc rootfs mount phase, my cunstom imx8mp device occasionally has this error. Looks like it has something to do with emmc cache flush.
Does anyone know what could be causing this? What are the risks?
Related emmc logs of kernel boot:
[2022-06-29 11:47:33][ 4.436953] cfg80211: Loading compiled-in X.509 certificates for regulatory database
[2022-06-29 11:47:33][ 4.447522] cfg80211: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7'
[2022-06-29 11:47:33][ 4.454129] platform regulatory.0: Direct firmware load for regulatory.db failed with error -2
[2022-06-29 11:47:33][ 4.462748] platform regulatory.0: Falling back to sysfs fallback for: regulatory.db
[2022-06-29 11:47:33][ 4.473608] ALSA device list:
[2022-06-29 11:47:33][ 4.476580] No soundcards found.
[2022-06-29 11:47:33][ 4.532249] mmc2: running CQE recovery
[2022-06-29 11:47:33][ 4.536474] mmc2: running CQE recovery
[2022-06-29 11:47:43][ 14.560992] mmc2: Timeout waiting for hardware interrupt.
[2022-06-29 11:47:43][ 14.566396] mmc2: sdhci: ============ SDHCI REGISTER DUMP ===========
[2022-06-29 11:47:43][ 14.572837] mmc2: sdhci: Sys addr: 0x00000000 | Version: 0x00000002
[2022-06-29 11:47:43][ 14.579277] mmc2: sdhci: Blk size: 0x00000200 | Blk cnt: 0x00000010
[2022-06-29 11:47:43][ 14.585716] mmc2: sdhci: Argument: 0x00000001 | Trn mode: 0x00000023
[2022-06-29 11:47:43][ 14.592157] mmc2: sdhci: Present: 0x01f88008 | Host ctl: 0x00000031
[2022-06-29 11:47:43][ 14.598596] mmc2: sdhci: Power: 0x00000002 | Blk gap: 0x00000080
[2022-06-29 11:47:43][ 14.605034] mmc2: sdhci: Wake-up: 0x00000008 | Clock: 0x0000000f
[2022-06-29 11:47:43][ 14.611474] mmc2: sdhci: Timeout: 0x0000008f | Int stat: 0x00000000
[2022-06-29 11:47:43][ 14.617914] mmc2: sdhci: Int enab: 0x107f4000 | Sig enab: 0x107f4000
[2022-06-29 11:47:43][ 14.624353] mmc2: sdhci: ACmd stat: 0x00000000 | Slot int: 0x00000502
[2022-06-29 11:47:43][ 14.630793] mmc2: sdhci: Caps: 0x07eb0000 | Caps_1: 0x8000b407
[2022-06-29 11:47:43][ 14.637232] mmc2: sdhci: Cmd: 0x00003013 | Max curr: 0x00ffffff
[2022-06-29 11:47:43][ 14.643672] mmc2: sdhci: Resp[0]: 0x00000900 | Resp[1]: 0xffffffff
[2022-06-29 11:47:43][ 14.650111] mmc2: sdhci: Resp[2]: 0x329f5903 | Resp[3]: 0x00d0ffff
[2022-06-29 11:47:43][ 14.656548] mmc2: sdhci: Host ctl2: 0x00000008
[2022-06-29 11:47:43][ 14.660991] mmc2: sdhci: ADMA Err: 0x00000000 | ADMA Ptr: 0x00000000
[2022-06-29 11:47:43][ 14.667431] mmc2: sdhci-esdhc-imx: ========= ESDHC IMX DEBUG STATUS DUMP =========
[2022-06-29 11:47:43][ 14.675000] mmc2: sdhci-esdhc-imx: cmd debug status: 0x2120
[2022-06-29 11:47:43][ 14.680656] mmc2: sdhci-esdhc-imx: data debug status: 0x2200
[2022-06-29 11:47:43][ 14.686403] mmc2: sdhci-esdhc-imx: trans debug status: 0x2300
[2022-06-29 11:47:43][ 14.692234] mmc2: sdhci-esdhc-imx: dma debug status: 0x2400
[2022-06-29 11:47:43][ 14.697890] mmc2: sdhci-esdhc-imx: adma debug status: 0x2500
[2022-06-29 11:47:43][ 14.703633] mmc2: sdhci-esdhc-imx: fifo debug status: 0x2680
[2022-06-29 11:47:43][ 14.709377] mmc2: sdhci-esdhc-imx: async fifo debug status: 0x2750
[2022-06-29 11:47:43][ 14.715644] mmc2: sdhci: ============================================
[2022-06-29 11:47:54][ 24.800998] mmc2: Timeout waiting for hardware interrupt.
[2022-06-29 11:47:54][ 24.806402] mmc2: sdhci: ============ SDHCI REGISTER DUMP ===========
[2022-06-29 11:47:54][ 24.812843] mmc2: sdhci: Sys addr: 0x00000000 | Version: 0x00000002
[2022-06-29 11:47:54][ 24.819282] mmc2: sdhci: Blk size: 0x00000200 | Blk cnt: 0x00000010
[2022-06-29 11:47:54][ 24.825721] mmc2: sdhci: Argument: 0x03200101 | Trn mode: 0x00000023
[2022-06-29 11:47:54][ 24.832160] mmc2: sdhci: Present: 0x01f88008 | Host ctl: 0x00000031
[2022-06-29 11:47:54][ 24.838601] mmc2: sdhci: Power: 0x00000002 | Blk gap: 0x00000080
[2022-06-29 11:47:54][ 24.845040] mmc2: sdhci: Wake-up: 0x00000008 | Clock: 0x0000000f
[2022-06-29 11:47:54][ 24.851480] mmc2: sdhci: Timeout: 0x0000008f | Int stat: 0x00000000
[2022-06-29 11:47:54][ 24.857917] mmc2: sdhci: Int enab: 0x107f4000 | Sig enab: 0x107f4000
[2022-06-29 11:47:54][ 24.864358] mmc2: sdhci: ACmd stat: 0x00000000 | Slot int: 0x00000502
[2022-06-29 11:47:54][ 24.870799] mmc2: sdhci: Caps: 0x07eb0000 | Caps_1: 0x8000b407
[2022-06-29 11:47:54][ 24.877238] mmc2: sdhci: Cmd: 0x0000061b | Max curr: 0x00ffffff
[2022-06-29 11:47:54][ 24.883678] mmc2: sdhci: Resp[0]: 0x00000900 | Resp[1]: 0xffffffff
[2022-06-29 11:47:54][ 24.890117] mmc2: sdhci: Resp[2]: 0x329f5903 | Resp[3]: 0x00d0ffff
[2022-06-29 11:47:54][ 24.896555] mmc2: sdhci: Host ctl2: 0x00000008
[2022-06-29 11:47:54][ 24.900998] mmc2: sdhci: ADMA Err: 0x00000000 | ADMA Ptr: 0x00000000
[2022-06-29 11:47:54][ 24.907437] mmc2: sdhci-esdhc-imx: ========= ESDHC IMX DEBUG STATUS DUMP =========
[2022-06-29 11:47:54][ 24.915006] mmc2: sdhci-esdhc-imx: cmd debug status: 0x2120
[2022-06-29 11:47:54][ 24.920662] mmc2: sdhci-esdhc-imx: data debug status: 0x2200
[2022-06-29 11:47:54][ 24.926410] mmc2: sdhci-esdhc-imx: trans debug status: 0x2300
[2022-06-29 11:47:54][ 24.932240] mmc2: sdhci-esdhc-imx: dma debug status: 0x2400
[2022-06-29 11:47:54][ 24.937898] mmc2: sdhci-esdhc-imx: adma debug status: 0x2500
[2022-06-29 11:47:54][ 24.943643] mmc2: sdhci-esdhc-imx: fifo debug status: 0x2680
[2022-06-29 11:47:54][ 24.949388] mmc2: sdhci-esdhc-imx: async fifo debug status: 0x2750
[2022-06-29 11:47:54][ 24.955655] mmc2: sdhci: ============================================
[2022-06-29 11:48:04][ 35.040995] mmc2: Timeout waiting for hardware interrupt.
[2022-06-29 11:48:04][ 35.046398] mmc2: sdhci: ============ SDHCI REGISTER DUMP ===========
[2022-06-29 11:48:04][ 35.052838] mmc2: sdhci: Sys addr: 0x00000000 | Version: 0x00000002
[2022-06-29 11:48:04][ 35.059277] mmc2: sdhci: Blk size: 0x00000200 | Blk cnt: 0x00000010
[2022-06-29 11:48:04][ 35.065716] mmc2: sdhci: Argument: 0x03200101 | Trn mode: 0x00000023
[2022-06-29 11:48:04][ 35.072157] mmc2: sdhci: Present: 0x01f88008 | Host ctl: 0x00000031
[2022-06-29 11:48:04][ 35.078596] mmc2: sdhci: Power: 0x00000002 | Blk gap: 0x00000080
[2022-06-29 11:48:04][ 35.085036] mmc2: sdhci: Wake-up: 0x00000008 | Clock: 0x0000000f
[2022-06-29 11:48:04][ 35.091476] mmc2: sdhci: Timeout: 0x0000008f | Int stat: 0x00000000
[2022-06-29 11:48:04][ 35.097914] mmc2: sdhci: Int enab: 0x107f4000 | Sig enab: 0x107f4000
[2022-06-29 11:48:04][ 35.104353] mmc2: sdhci: ACmd stat: 0x00000000 | Slot int: 0x00000502
[2022-06-29 11:48:04][ 35.110791] mmc2: sdhci: Caps: 0x07eb0000 | Caps_1: 0x8000b407
[2022-06-29 11:48:04][ 35.117232] mmc2: sdhci: Cmd: 0x0000061b | Max curr: 0x00ffffff
[2022-06-29 11:48:04][ 35.123672] mmc2: sdhci: Resp[0]: 0x00000900 | Resp[1]: 0xffffffff
[2022-06-29 11:48:04][ 35.130111] mmc2: sdhci: Resp[2]: 0x329f5903 | Resp[3]: 0x00d0ffff
[2022-06-29 11:48:04][ 35.136548] mmc2: sdhci: Host ctl2: 0x00000008
[2022-06-29 11:48:04][ 35.140993] mmc2: sdhci: ADMA Err: 0x00000000 | ADMA Ptr: 0x00000000
[2022-06-29 11:48:04][ 35.147432] mmc2: sdhci-esdhc-imx: ========= ESDHC IMX DEBUG STATUS DUMP =========
[2022-06-29 11:48:04][ 35.155000] mmc2: sdhci-esdhc-imx: cmd debug status: 0x2120
[2022-06-29 11:48:04][ 35.160657] mmc2: sdhci-esdhc-imx: data debug status: 0x2200
[2022-06-29 11:48:04][ 35.166402] mmc2: sdhci-esdhc-imx: trans debug status: 0x2300
[2022-06-29 11:48:04][ 35.172234] mmc2: sdhci-esdhc-imx: dma debug status: 0x2400
[2022-06-29 11:48:04][ 35.177892] mmc2: sdhci-esdhc-imx: adma debug status: 0x2500
[2022-06-29 11:48:04][ 35.183637] mmc2: sdhci-esdhc-imx: fifo debug status: 0x2680
[2022-06-29 11:48:04][ 35.189382] mmc2: sdhci-esdhc-imx: async fifo debug status: 0x2750
[2022-06-29 11:48:04][ 35.195647] mmc2: sdhci: ============================================
[2022-06-29 11:48:14][ 45.281004] mmc2: Timeout waiting for hardware interrupt.
[2022-06-29 11:48:14][ 45.286407] mmc2: sdhci: ============ SDHCI REGISTER DUMP ===========
[2022-06-29 11:48:14][ 45.292847] mmc2: sdhci: Sys addr: 0x00000000 | Version: 0x00000002
[2022-06-29 11:48:14][ 45.299286] mmc2: sdhci: Blk size: 0x00000200 | Blk cnt: 0x00000010
[2022-06-29 11:48:14][ 45.305726] mmc2: sdhci: Argument: 0x03200101 | Trn mode: 0x00000023
[2022-06-29 11:48:14][ 45.312166] mmc2: sdhci: Present: 0x01f88008 | Host ctl: 0x00000031
[2022-06-29 11:48:14][ 45.318606] mmc2: sdhci: Power: 0x00000002 | Blk gap: 0x00000080
[2022-06-29 11:48:14][ 45.325046] mmc2: sdhci: Wake-up: 0x00000008 | Clock: 0x0000000f
[2022-06-29 11:48:14][ 45.331486] mmc2: sdhci: Timeout: 0x0000008f | Int stat: 0x00000000
[2022-06-29 11:48:14][ 45.337924] mmc2: sdhci: Int enab: 0x107f4000 | Sig enab: 0x107f4000
[2022-06-29 11:48:14][ 45.344363] mmc2: sdhci: ACmd stat: 0x00000000 | Slot int: 0x00000502
[2022-06-29 11:48:14][ 45.350801] mmc2: sdhci: Caps: 0x07eb0000 | Caps_1: 0x8000b407
[2022-06-29 11:48:14][ 45.357242] mmc2: sdhci: Cmd: 0x0000061b | Max curr: 0x00ffffff
[2022-06-29 11:48:14][ 45.363682] mmc2: sdhci: Resp[0]: 0x00000900 | Resp[1]: 0xffffffff
[2022-06-29 11:48:14][ 45.370122] mmc2: sdhci: Resp[2]: 0x329f5903 | Resp[3]: 0x00d0ffff
[2022-06-29 11:48:14][ 45.376559] mmc2: sdhci: Host ctl2: 0x00000008
[2022-06-29 11:48:14][ 45.381002] mmc2: sdhci: ADMA Err: 0x00000000 | ADMA Ptr: 0x00000000
[2022-06-29 11:48:14][ 45.387444] mmc2: sdhci-esdhc-imx: ========= ESDHC IMX DEBUG STATUS DUMP =========
[2022-06-29 11:48:14][ 45.395012] mmc2: sdhci-esdhc-imx: cmd debug status: 0x2120
[2022-06-29 11:48:14][ 45.400671] mmc2: sdhci-esdhc-imx: data debug status: 0x2200
[2022-06-29 11:48:14][ 45.406416] mmc2: sdhci-esdhc-imx: trans debug status: 0x2300
[2022-06-29 11:48:14][ 45.412248] mmc2: sdhci-esdhc-imx: dma debug status: 0x2400
[2022-06-29 11:48:14][ 45.417906] mmc2: sdhci-esdhc-imx: adma debug status: 0x2500
[2022-06-29 11:48:14][ 45.423651] mmc2: sdhci-esdhc-imx: fifo debug status: 0x2680
[2022-06-29 11:48:14][ 45.429396] mmc2: sdhci-esdhc-imx: async fifo debug status: 0x2750
[2022-06-29 11:48:14][ 45.435661] mmc2: sdhci: ============================================
[2022-06-29 11:48:23][2022-06-29 11:48:23]
[2022-06-29 11:48:24][ 55.521005] mmc2: Timeout waiting for hardware interrupt.
[2022-06-29 11:48:24][ 55.526407] mmc2: sdhci: ============ SDHCI REGISTER DUMP ===========
[2022-06-29 11:48:24][ 55.532845] mmc2: sdhci: Sys addr: 0x00000000 | Version: 0x00000002
[2022-06-29 11:48:24][ 55.539283] mmc2: sdhci: Blk size: 0x00000200 | Blk cnt: 0x00000010
[2022-06-29 11:48:24][ 55.545724] mmc2: sdhci: Argument: 0x03200101 | Trn mode: 0x00000023
[2022-06-29 11:48:24][ 55.552164] mmc2: sdhci: Present: 0x01f88008 | Host ctl: 0x00000031
[2022-06-29 11:48:24][ 55.558604] mmc2: sdhci: Power: 0x00000002 | Blk gap: 0x00000080
[2022-06-29 11:48:24][ 55.565044] mmc2: sdhci: Wake-up: 0x00000008 | Clock: 0x0000000f
[2022-06-29 11:48:24][ 55.571483] mmc2: sdhci: Timeout: 0x0000008f | Int stat: 0x00000000
[2022-06-29 11:48:24][ 55.577921] mmc2: sdhci: Int enab: 0x107f4000 | Sig enab: 0x107f4000
[2022-06-29 11:48:24][ 55.584362] mmc2: sdhci: ACmd stat: 0x00000000 | Slot int: 0x00000502
[2022-06-29 11:48:24][ 55.590800] mmc2: sdhci: Caps: 0x07eb0000 | Caps_1: 0x8000b407
[2022-06-29 11:48:24][ 55.597239] mmc2: sdhci: Cmd: 0x0000061b | Max curr: 0x00ffffff
[2022-06-29 11:48:24][ 55.603679] mmc2: sdhci: Resp[0]: 0x00000900 | Resp[1]: 0xffffffff
[2022-06-29 11:48:24][ 55.610118] mmc2: sdhci: Resp[2]: 0x329f5903 | Resp[3]: 0x00d0ffff
[2022-06-29 11:48:24][ 55.616555] mmc2: sdhci: Host ctl2: 0x00000008
[2022-06-29 11:48:24][ 55.620999] mmc2: sdhci: ADMA Err: 0x00000000 | ADMA Ptr: 0x00000000
[2022-06-29 11:48:24][ 55.627440] mmc2: sdhci-esdhc-imx: ========= ESDHC IMX DEBUG STATUS DUMP =========
[2022-06-29 11:48:24][ 55.635008] mmc2: sdhci-esdhc-imx: cmd debug status: 0x2120
[2022-06-29 11:48:24][ 55.640664] mmc2: sdhci-esdhc-imx: data debug status: 0x2200
[2022-06-29 11:48:24][ 55.646410] mmc2: sdhci-esdhc-imx: trans debug status: 0x2300
[2022-06-29 11:48:24][ 55.652241] mmc2: sdhci-esdhc-imx: dma debug status: 0x2400
[2022-06-29 11:48:24][ 55.657899] mmc2: sdhci-esdhc-imx: adma debug status: 0x2500
[2022-06-29 11:48:24][ 55.663644] mmc2: sdhci-esdhc-imx: fifo debug status: 0x2680
[2022-06-29 11:48:24][ 55.669389] mmc2: sdhci-esdhc-imx: async fifo debug status: 0x2750
[2022-06-29 11:48:24][ 55.675655] mmc2: sdhci: ============================================
[2022-06-29 11:48:24][ 55.682425] mmc2: cache flush error -110
[2022-06-29 11:48:24][ 55.771809] EXT4-fs (mmcblk2p2): recovery complete
[2022-06-29 11:48:24][ 55.776764] EXT4-fs (mmcblk2p2): mounted filesystem with ordered data mode. Opts: (null)
[2022-06-29 11:48:24][ 55.784898] VFS: Mounted root (ext4 filesystem) on device 179:2.
[2022-06-29 11:48:24][ 55.793665] devtmpfs: mounted
[2022-06-29 11:48:24][ 55.797289] Freeing unused kernel memory: 2752K
[2022-06-29 11:48:24][ 55.801895] Run /sbin/init as init process
It takes 50s to mount rootfs with above error, but only takes 50ms normally.
BSP: Linux 5.4.70_2.3.0
Hardware: coustom board based i.mx8mp evk
Hi,
Can you share your eMMC type and part of the schematic where eMMC is connected to the CPU?
This will help to understand where the problem comes from.
Hello, @artsiomstaliaro
eMMC type: FORESEE FEMDRW016G-88A43
Here is part of emmc schematic :
Please let me know if you need more information.
Can you show also DTB settings related to eMMC?
pinctrl_usdhc3: usdhc3grp {
fsl,pins = <
MX8MP_IOMUXC_NAND_WE_B__USDHC3_CLK 0x190
MX8MP_IOMUXC_NAND_WP_B__USDHC3_CMD 0x1d0
MX8MP_IOMUXC_NAND_DATA04__USDHC3_DATA0 0x1d0
MX8MP_IOMUXC_NAND_DATA05__USDHC3_DATA1 0x1d0
MX8MP_IOMUXC_NAND_DATA06__USDHC3_DATA2 0x1d0
MX8MP_IOMUXC_NAND_DATA07__USDHC3_DATA3 0x1d0
MX8MP_IOMUXC_NAND_RE_B__USDHC3_DATA4 0x1d0
MX8MP_IOMUXC_NAND_CE2_B__USDHC3_DATA5 0x1d0
MX8MP_IOMUXC_NAND_CE3_B__USDHC3_DATA6 0x1d0
MX8MP_IOMUXC_NAND_CLE__USDHC3_DATA7 0x1d0
MX8MP_IOMUXC_NAND_CE1_B__USDHC3_STROBE 0x190
>;
};
pinctrl_usdhc3_100mhz: usdhc3grp-100mhz {
fsl,pins = <
MX8MP_IOMUXC_NAND_WE_B__USDHC3_CLK 0x194
MX8MP_IOMUXC_NAND_WP_B__USDHC3_CMD 0x1d4
MX8MP_IOMUXC_NAND_DATA04__USDHC3_DATA0 0x1d4
MX8MP_IOMUXC_NAND_DATA05__USDHC3_DATA1 0x1d4
MX8MP_IOMUXC_NAND_DATA06__USDHC3_DATA2 0x1d4
MX8MP_IOMUXC_NAND_DATA07__USDHC3_DATA3 0x1d4
MX8MP_IOMUXC_NAND_RE_B__USDHC3_DATA4 0x1d4
MX8MP_IOMUXC_NAND_CE2_B__USDHC3_DATA5 0x1d4
MX8MP_IOMUXC_NAND_CE3_B__USDHC3_DATA6 0x1d4
MX8MP_IOMUXC_NAND_CLE__USDHC3_DATA7 0x1d4
MX8MP_IOMUXC_NAND_CE1_B__USDHC3_STROBE 0x194
>;
};
pinctrl_usdhc3_200mhz: usdhc3grp-200mhz {
fsl,pins = <
MX8MP_IOMUXC_NAND_WE_B__USDHC3_CLK 0x196
MX8MP_IOMUXC_NAND_WP_B__USDHC3_CMD 0x1d6
MX8MP_IOMUXC_NAND_DATA04__USDHC3_DATA0 0x1d6
MX8MP_IOMUXC_NAND_DATA05__USDHC3_DATA1 0x1d6
MX8MP_IOMUXC_NAND_DATA06__USDHC3_DATA2 0x1d6
MX8MP_IOMUXC_NAND_DATA07__USDHC3_DATA3 0x1d6
MX8MP_IOMUXC_NAND_RE_B__USDHC3_DATA4 0x1d6
MX8MP_IOMUXC_NAND_CE2_B__USDHC3_DATA5 0x1d6
MX8MP_IOMUXC_NAND_CE3_B__USDHC3_DATA6 0x1d6
MX8MP_IOMUXC_NAND_CLE__USDHC3_DATA7 0x1d6
MX8MP_IOMUXC_NAND_CE1_B__USDHC3_STROBE 0x196
>;
};
usdhc3: mmc@30b60000 {
compatible = "fsl,imx8mm-usdhc", "fsl,imx7d-usdhc";
reg = <0x30b60000 0x10000>;
interrupts = <GIC_SPI 24 IRQ_TYPE_LEVEL_HIGH>;
clocks = <&clk IMX8MP_CLK_DUMMY>,
<&clk IMX8MP_CLK_NAND_USDHC_BUS>,
<&clk IMX8MP_CLK_USDHC3_ROOT>;
clock-names = "ipg", "ahb", "per";
assigned-clocks = <&clk IMX8MP_CLK_USDHC3>;
assigned-clock-rates = <400000000>;
fsl,tuning-start-tap = <20>;
fsl,tuning-step= <2>;
bus-width = <4>;
status = "disabled";
};
&usdhc3 {
pinctrl-names = "default", "state_100mhz", "state_200mhz";
pinctrl-0 = <&pinctrl_usdhc3>;
pinctrl-1 = <&pinctrl_usdhc3_100mhz>;
pinctrl-2 = <&pinctrl_usdhc3_200mhz>;
bus-width = <8>;
non-removable;
status = "okay";
};
The same as imx8mp-evk
Did you add CQE patch as described here:
https://community.nxp.com/t5/i-MX-Processors/eMMC-message-quot-mmc2-running-CQE-recovery-quot/m-p/10...
?
Hello, @artsiomstaliaro
No. In that patch you mentioned, they remove CQHCI feature form imx8 ESDHC controller driver. As you know CQE is used to improve emmc performance, so i think it is not a best choice to apply that patch.
the current workaround is that we disable EMMC command queue feature, the root cause is still
not identify, and under debugging
Is the problem there?
NXP guys mentioned that it works, you should try this patch and test the system.
Another alternative- is to reduce clock speed. Maybe issues with the layout.
Is this problem still there after disabling the feature?