Boot issues of "device mapper detecting vendor partition on eMMC device sometimes took too long"

[WWang2909]

Hi Everyone,

I came across this kind of boot issues on iMX8MQ based board.

uname -a
Linux localhost 4.14.98 #7 SMP PREEMPT Fri Nov 10 14:12:19 GMT 2023 aarch64

Android 9

Please refer to below logs:

Boot failed logs:

[ 5.071440] rtc-rv8803 3-0032: Voltage low, data is invalid.
[ 5.077128] rtc-rv8803 3-0032: hctosys: unable to read the hardware clock
[ 5.084906] VSD_3V3: disabling
[ 5.087999] gpio_dvfs: disabling
[ 5.091330] VGEN1: disabling
[ 5.650322] random: crng init done
[ 6.113017] [drm] HDMI/DP Cable Plug Out
[ 7.373103] i.mx8-hdp 32c00000.hdmi: 0,ff,ff,ff,ff,ff,ff,0
[ 7.382986] [drm] Pixel clock frequency: 148500 KHz, character clock frequency: 148500, color depth is 8-bit.
[ 7.382992] [drm] Pixel clock frequency (148500 KHz) is supported in this color depth (8-bit). Settings found in row 16
[ 7.382995] [drm] VCO frequency is 5940000
[ 7.382999] [drm] VCO frequency (5940000 KHz) is supported. Settings found in row 14
[ 7.396543] [drm] CDN_API_General_Write_Register_blocking LANES_CONFIG ret = 0
[ 8.094768] Console: switching to colour frame buffer device 240x67
[ 8.174132] imx-drm display-subsystem: fb0: frame buffer device
[ 8.180223] [drm] HDMI/DP Cable Plug In
[ 62.577115] imx-sdma 302c0000.sdma: external firmware not found, using ROM firmware
[ 62.584931] imx-sdma 30bd0000.sdma: external firmware not found, using ROM firmware
[ 62.593199] VGEN6: disabling
[ 62.596813] ALSA device list:
[ 62.599801] #0: imx-audio-hdmi
[ 62.603237] device-mapper: init: attempting early device configuration.
[ 62.610917] device-mapper: init: adding target '0 3611944 verity 1 PARTUUID=467c78f7-3e96-477c-a13e-a133e7640388 PARTUUID=467c78f7-3e96-477c-a13e-a133e7640388 4096 4096 451493 451493 sha1 302a38fb6716d171d739de29cbf8eee9931f0de7 aee2f13acc855ca9c55f353575116a8629a78a41 10 restart_on_corruption ignore_zero_blocks use_fec_from_device PARTUUID=467c78f7-3e96-477c-a13e-a133e7640388 fec_roots 2 fec_blocks 455050 fec_start 455050'
[ 62.650715] device-mapper: init: dm-0 is ready
[ 62.672659] EXT4-fs (dm-0): mounted filesystem without journal. Opts: (null)
[ 62.679753] VFS: Mounted root (ext4 filesystem) readonly on device 252:0.
[ 62.687101] devtmpfs: mounted
[ 62.691567] Freeing unused kernel memory: 5568K
[ 62.739266] init: init first stage started!
[ 62.744139] init: Using Android DT directory /proc/device-tree/firmware/android/
[ 62.753625] init: [libfs_mgr]fs_mgr_read_fstab_default(): failed to find device default fstab
[ 62.808127] init: [libfs_mgr]Returning avb_handle with status: 0
[ 62.815778] init: [libfs_mgr]Loading verity table: '1 /dev/block/platform/30b40000.usdhc/by-name/vendor_a /dev/block/platform/30b40000.usdhc/by-name/vendor_a 4096 4096 64481 64481 sha1 1c62ee1e411105e48c48794909f38bcf2cff998d 1e011729fb3bb1579bba13972d4eb4077f4b6573 10 use_fec_from_device /dev/block/platform/30b40000.usdhc/by-name/vendor_a fec_roots 2 fec_blocks 64990 fec_start 64990 restart_on_corruption ignore_zero_blocks'
[ 62.864246] EXT4-fs (dm-1): mounted filesystem without journal. Opts: barrier=1,inode_readahead_blks=8
[ 62.873644] init: [libfs_mgr]__mount(source=/dev/block/dm-1,target=/vendor,type=ext4)=0: Success
[ 62.882612] init: Skipped setting INIT_AVB_VERSION (not in recovery mode)

Boot succeed logs:

[ 4.787494] rtc-rv8803 3-0032: Voltage low, data is invalid.
[ 4.787498] rtc-rv8803 3-0032: hctosys: unable to read the hardware clock
[ 4.788308] VSD_3V3: disabling
[ 4.788311] gpio_dvfs: disabling
[ 4.788324] VGEN1: disabling
[ 4.789024] VGEN6: disabling
[ 4.789752] ALSA device list:
[ 4.789755] #0: imx-audio-hdmi
[ 5.389058] Console: switching to colour frame buffer device 240x67
[ 5.535581] random: crng init done
[ 5.538120] imx-drm display-subsystem: fb0: frame buffer device
[ 5.676836] [drm] HDMI/DP Cable Plug In
[ 5.680776] device-mapper: init: attempting early device configuration.
[ 5.688481] device-mapper: init: adding target '0 3611944 verity 1 PARTUUID=467c78f7-3e96-477c-a13e-a133e7640388 PARTUUID=467c78f7-3e96-477c-a13e-a133e7640388 4096 4096 451493 451493 sha1 302a38fb6716d171d739de29cbf8eee9931f0de7 aee2f13acc855ca9c55f353575116a8629a78a41 10 restart_on_corruption ignore_zero_blocks use_fec_from_device PARTUUID=467c78f7-3e96-477c-a13e-a133e7640388 fec_roots 2 fec_blocks 455050 fec_start 455050'
[ 5.732437] device-mapper: init: dm-0 is ready
[ 5.754264] EXT4-fs (dm-0): mounted filesystem without journal. Opts: (null)
[ 5.761406] VFS: Mounted root (ext4 filesystem) readonly on device 252:0.
[ 5.768798] devtmpfs: mounted
[ 5.773308] Freeing unused kernel memory: 5568K
[ 5.819475] init: init first stage started!
[ 5.824402] init: Using Android DT directory /proc/device-tree/firmware/android/
[ 5.833857] init: [libfs_mgr]fs_mgr_read_fstab_default(): failed to find device default fstab
[ 5.888016] init: [libfs_mgr]Returning avb_handle with status: 0
[ 5.895733] init: [libfs_mgr]Loading verity table: '1 /dev/block/platform/30b40000.usdhc/by-name/vendor_a /dev/block/platform/30b40000.usdhc/by-name/vendor_a 4096 4096 64481 64481 sha1 1c62ee1e411105e48c48794909f38bcf2cff998d 1e011729fb3bb1579bba13972d4eb4077f4b6573 10 use_fec_from_device /dev/block/platform/30b40000.usdhc/by-name/vendor_a fec_roots 2 fec_blocks 64990 fec_start 64990 restart_on_corruption ignore_zero_blocks'
[ 5.944423] EXT4-fs (dm-1): mounted filesystem without journal. Opts: barrier=1,inode_readahead_blks=8
[ 5.953814] init: [libfs_mgr]__mount(source=/dev/block/dm-1,target=/vendor,type=ext4)=0: Success
[ 5.962785] init: Skipped setting INIT_AVB_VERSION (not in recovery mode)
[ 5.969748] init: Loading SELinux policy
[ 6.001297] SELinux: Class process2 not defined in policy.
[ 6.007349] SELinux: Class infiniband_pkey not defined in policy.
[ 6.013539] SELinux: Class infiniband_endport not defined in policy.
[ 6.019989] SELinux: the above unknown classes and permissions will be denied
[ 6.027152] SELinux: policy capability network_peer_controls=1
[ 6.033078] SELinux: policy capability open_perms=1
[ 6.038048] SELinux: policy capability extended_socket_class=1
[ 6.043974] SELinux: policy capability always_check_network=0
[ 6.049812] SELinux: policy capability cgroup_seclabel=0
[ 6.055216] SELinux: policy capability nnp_nosuid_transition=0
[ 6.147545] audit: type=1403 audit(5.995:2): policy loaded auid=4294967295 ses=4294967295
[ 6.147725] selinux: SELinux: Loaded policy from /vendor/etc/selinux/precompiled_sepolicy
[ 6.147725]
[ 6.165891] audit: type=1404 audit(6.011:3): enforcing=1 old_enforcing=0 auid=4294967295 ses=4294967295
[ 6.198332] selinux: SELinux: Loaded file_contexts
[ 6.198332]
[ 6.208429] init: init second stage started!
[ 6.231146] init: Using Android DT directory /proc/device-tree/firmware/android/
[ 6.242613] selinux: SELinux: Loaded file_contexts
[ 6.242613]
[ 6.248970] init: Running restorecon...
[ 6.259544] init: waitid failed: No child processes
[ 6.268407] init: Couldn't load property file '/odm/default.prop': open() failed: No such file or directory: No such file or directory
[ 6.284227] init: Created socket '/dev/socket/property_service', mode 666, user 0, group 0
[ 6.293173] init: Forked subcontext for 'u:r:vendor_init:s0' with pid 2524
[ 6.300695] init: Forked subcontext for 'u:r:vendor_init:s0' with pid 2525
[ 6.307867] init: Parsing file /init.rc...
[ 6.434085] audit: type=1400 audit(6.279:4): avc: denied { dac_read_search } for pid=1 comm="init" capability=2 scontext=u:r:init:s0 tcontext=u:r:init:s0 tclass=capability permissive=0
[ 6.437047] ueventd: ueventd started!
[ 6.451321] audit: type=1400 audit(6.299:5): avc: denied { dac_read_search } for pid=1 comm="init" capability=2 scontext=u:r:init:s0 tcontext=u:r:init:s0 tclass=capability permissive=0
[ 6.457083] selinux: SELinux: Loaded file_contexts
[ 6.457083]
[ 6.471618] audit: type=1400 audit(6.299:6): avc: denied { dac_read_search } for pid=1 comm="init" capability=2 scontext=u:r:init:s0 tcontext=u:r:init:s0 tclass=capability permissive=0
[ 6.477816] ueventd: Parsing file /ueventd.rc...
[ 6.482088] ueventd: Parsing file /vendor/ueventd.rc...
[ 6.494640] audit: type=1400 audit(6.299:7): avc: denied { dac_read_search } for pid=1 comm="init" capability=2 scontext=u:r:init:s0 tcontext=u:r:init:s0 tclass=capability permissive=0
[ 6.500654] ueventd: Parsing file /odm/ueventd.rc...
[ 6.504620] audit: type=1400 audit(6.331:8): avc: denied { dac_read_search } for pid=1 comm="init" capability=2 scontext=u:r:init:s0 tcontext=u:r:init:s0 tclass=capability permissive=0
[ 6.521470] ueventd: Unable to read config file '/odm/ueventd.rc': open() failed: No such file or directory
[ 6.521575] ueventd: Parsing file /ueventd.freescale.rc...
[ 6.526498] audit: type=1400 audit(6.331:9): avc: denied { dac_read_search } for pid=1 comm="init" capability=2 scontext=u:r:init:s0 tcontext=u:r:init:s0 tclass=capability permissive=0
[ 6.526503] audit: type=1400 audit(6.331:10): avc: denied { dac_read_search } for pid=1 comm="init" capability=2 scontext=u:r:init:s0 tcontext=u:r:init:s0 tclass=capability permissive=0
[ 6.526507] audit: type=1400 audit(6.331:11): avc: denied { dac_read_search } for pid=1 comm="init" capability=2 scontext=u:r:init:s0 tcontext=u:r:init:s0 tclass=capability permissive=0
[ 6.609340] ueventd: Unable to read config file '/ueventd.freescale.rc': open() failed: No such file or directory
[ 6.636437] ueventd: firmware: loading 'rtl_bt/rtl8821a_config.bin' for '/devices/platform/usb@38200000/38200000.dwc3/xhci-hcd.1.auto/usb3/3-1/3-1.2/3-1.2.2/3-1.2.2:1.0/bluetooth/hci0/rtl_bt!rtl8821a_config.bin'
[ 6.645626] ueventd: firmware: loading 'imx/sdma/sdma-imx7d.bin' for '/devices/platform/30bd0000.sdma/firmware/imx!sdma!sdma-imx7d.bin'
[ 6.693484] imx-sdma 30bd0000.sdma: loaded firmware 4.4
[ 6.699297] imx-sdma 302c0000.sdma: loaded firmware 4.4

Compared the two logs, in terms of the process of eMMC/MicroSD initialisation, we can see:

The normal process will take about 1 second (starting from "VSD_3V3: disabling" @4.788308 to "EXT4-fs (dm-0): mounted filesystem without journal" @5.754264 seconds), while abnormal process started from 5.084906 and ended at 62.672659! Here the "VSD_3V3" is a regulator as vmmc-supply for usdhc2 device on our board.

Such abnormal delay caused other issues, for example, "imx-sdma 302c0000.sdma: external firmware not found, using ROM firmware" as the required firmware file is on /vendor/.. that was not ready yet at that point.

So what may cause such a delay? Any suggestions/clues are welcome!

[AldoG]

Hello,

Sometimes loading sdma firmware may take around 60 seconds, so this delay may be expected, please refer to the following commit:
https://github.com/nxp-imx/linux-imx/commit/5b75ed72b5f93d4e52aeb0fdbac3f232b7ac3590

Best regards,
Aldo.

[WWang2909 · Accepted solution]

Hi Aldo,

Thank you for your response!

The boot issue is not directly link to sdma firmware loading, nor eMMC/MicroSD initialisation. It is caused by a tcpci driver for PTN5110 device that is not present on our board. This driver registered an interrupt handler on I2C1 bus in device tree. While such interrupt process was keeping in the state of "D" for most of time and also costing 40% a CPU core (as constantly interrupts trying to find the non-present device of PTN5110) so that sometimes blocked system.

After removed such interrupt routine from the tcpci driver, the issue has no longer appeared.

Thanks