Hikey 960 UEFI boot hangs when SD card present

Thanks for the link. I will try it as soon as I get back to my desk (24 hours) and report results here.

@sbsteele @psyhtest I got the issue now and I can reproduce it on my board. When SD card is inserted during boot time, UEFI tries to boot from it and apparently the boot process got stuck at some point.

Will look into this issue. Thanks for reporting.

-Mani

@sbsteele @psyhtest So the issue is with the UFS driver. In the default kernel config, UFS drivers are compiled as kernel modules and that somehow causes boot hang when booting from SD.

Making those drivers as built-in, allows booting from SD card without any issues.

CONFIG_SCSI_UFSHCD=y
CONFIG_SCSI_UFSHCD_PLATFORM=y
CONFIG_SCSI_UFS_HISI=y
root@linaro-developer:~# uname -a
Linux linaro-developer 4.19.5-00014-g40f4901212dd-dirty #2 SMP PREEMPT Wed Jul 24 00:05:5x
root@linaro-developer:~# df -h
Filesystem      Size  Used Avail Use% Mounted on
udev            1.5G     0  1.5G   0% /dev
tmpfs           297M  4.1M  293M   2% /run
/dev/mmcblk0p2  1.7G  1.1G  475M  70% /
tmpfs           1.5G     0  1.5G   0% /dev/shm
tmpfs           5.0M     0  5.0M   0% /run/lock
tmpfs           1.5G     0  1.5G   0% /sys/fs/cgroup
/dev/mmcblk0p1   64M  848K   64M   2% /boot/efi
tmpfs           297M     0  297M   0% /run/user/0
root@linaro-developer:~# 

Will make this change in the kernel tree so that the next image build can work straightaway.

Thanks,
Mani

Done: manivannan.sadhasivam/linux.git - Linux kernel tree for personal upstream work

@doitright No difference with version 95 and an sd card with a single ext4 partition. But it seems it may be a debian kernel issue as reported by @mani below. Thanks for the link to latest UEFI nonetheless. For whatever reason I never came across it using the documentation and searching the forum.

Thank you @Mani. How long will it take until the next image build is published?

Thanks, @Mani. I assume it will be 20 August before the next automatic build of Debian with this change. I build a new kernel from your tree, but do not know how to generate a proper boot.img from it the way your internal build tools do so. When I use abootimg or mkbootimg I of course get Android image format which is not suitable for booting with UEFI. How can I get a proper image suitable for booting with UEFI?

@Mani, I used your kernel tree to build the kernel and I substituted it for the snapshot #33 kernel to try it out. With the kernel in UFS I was able to boot with the rootfs in SD as long as I waited to insert the SD card until entering Grub. There still seems to be a couple of problems.

  1. As before, if the SD card is inserted at reset time, boot stalls within UEFI with the “Press ESC for boot options” message - the boot manager menu is never displayed and pressing ESC has no effect. Seems like UEFI still has a problem with the SD card.

  2. If I insert the SD card once Grub runs and displays its boot selection menu, the kernel boots (from UFS) and mounts rootfs from the SD card, but the SD card initialization reports some problems at first, specifically:

[ 3.777896] mmc1: new SDIO card at address 0001
[ 3.791114] dwmmc_k3 ff37f000.dwmmc1: tuning ok best_clksmpl 16 tuning_sample_flag cefffeff
[ 3.791123] mmc0: new ultra high speed SDR104 SDHC card at address 59b4
[ 3.791576] mmcblk0: mmc0:59b4 SD 14.7 GiB
[ 3.810713] uart-pl011 fff32000.serial: no DMA platform data
[ 3.818788] mmcblk0: p1 p2
[ 3.823374] dwc3 ff100000.dwc3: Failed to get clk ‘ref’: -2
[ 3.829328] dwc3 ff100000.dwc3: failed to initialize core
[ 4.930704] ufshcd-hisi ff3b0000.ufs: ufshcd_query_flag: Sending flag query for idn 3 failed, err = -11
[ 6.466666] ufshcd-hisi ff3b0000.ufs: ufshcd_query_flag: Sending flag query for idn 3 failed, err = -11
[ 6.476086] ufshcd-hisi ff3b0000.ufs: ufshcd_query_flag_retry: query attribute, opcode 5, idn 3, failed with error -11 after 3 retires
[ 8.002706] ufshcd-hisi ff3b0000.ufs: __ufshcd_query_descriptor: opcode 0x01 for idn 8 failed, index 0, err = -11
[ 9.538692] ufshcd-hisi ff3b0000.ufs: __ufshcd_query_descriptor: opcode 0x01 for idn 8 failed, index 0, err = -11
[ 11.074575] ufshcd-hisi ff3b0000.ufs: __ufshcd_query_descriptor: opcode 0x01 for idn 8 failed, index 0, err = -11
[ 11.084869] ufshcd-hisi ff3b0000.ufs: ufshcd_read_desc_param: Failed reading descriptor. desc_id 8, desc_index 0, param_offset 0, ret -11
[ 11.097218] ufshcd-hisi ff3b0000.ufs: ufshcd_init_icc_levels: Failed reading power descriptor.len = 98 ret = -11
[ 32.047465] ufshcd-hisi ff3b0000.ufs: ufshcd_print_pwr_info:[RX, TX]: gear=[1, 1], lane[1, 1], pwr[SLOWAUTO_MODE, SLOWAUTO_MODE], rate = 0
[ 32.064336] ufshcd-hisi ff3b0000.ufs: UPIU[0] - issue time 11103939 us
[ 32.070889] ufshcd-hisi ff3b0000.ufs: UPIU[0] - complete time 0 us
[ 32.077067] ufshcd-hisi ff3b0000.ufs: UPIU[0] - Transfer Request Descriptor phys@0x20c58000
[ 32.085426] UPIU TRD: 00000000: 15000000 00000000 0000000f 00000000
[ 32.091692] UPIU TRD: 00000010: 20c40000 00000000 00800080 01000001
[ 32.097957] ufshcd-hisi ff3b0000.ufs: UPIU[0] - Request UPIU phys@0x20c40000
[ 32.105005] UPIU REQ: 00000000: 00d04001 00000000 00000000 24000000
[ 32.111271] UPIU REQ: 00000010: 00000012 00000024 00000000 00000000
[ 32.117536] ufshcd-hisi ff3b0000.ufs: UPIU[0] - Response UPIU phys@0x20c40200
[ 32.124670] UPIU RSP: 00000000: 00000000 00000000 00000000 00000000
[ 32.130935] UPIU RSP: 00000010: 00000000 00000000 00000000 00000000
[ 32.137201] UPIU RSP: 00000020: 00000000 00000000 00000000 00000000
[ 32.143465] UPIU RSP: 00000030: 00000000
[ 32.147383] ufshcd-hisi ff3b0000.ufs: UPIU[0] - PRDT - 1 entries phys@0x20c40400
[ 32.154866] UPIU PRDT: 00000000: 1940e000 00000002 00000000 00000023
[ 32.314663] ufs final power mode: gear = 3, lane = 2, pwr = 1, rate = 2
[ 32.328930] ufshcd-hisi ff3b0000.ufs: ufshcd_print_pwr_info:[RX, TX]: gear=[3, 3], lane[2, 2], pwr[FAST MODE, FAST MODE], rate = 2
[ 32.343115] Freeing unused kernel memory: 1344K
[ 32.347746] Run /init as init process

Ultimately after that twenty second delay everything boots successfully. But I have yet to boot successfully with the kernel coming from the SD card.

@sbsteele I’d suggest you to flash the existing SD image to uSD card and replace the vmlinuz image in FAT partition.

This looks strange. Unfortunately I cannot reproduce this issue at my end. What is the uSD card model you’re using?

This looks like UFS issue. Could you please share the UFS part number? Does this issue still applies when booting without uSD?

I am using a PNY 16 GB microSD card.

The UFS is SKhynix H28U62301AMR.

There are three cases I have tried. In each case, the new kernel with your defconfig fixes and the snapshot rootfs installed in UFS, and the snapshot rootfs and kernel are on the SD card.

Case 1 - SD card present at reset time. Result: UEFI hangs with “Press ESCAPE for boot options” message.

Case 2 - SD card not present at reset time but inserted when grub runs and displays its selection menu. Result: SD card is recognized (with some error messages as above) and system ultimately boots using SD card rootfs.

Case 3 - SD never inserted. Result: Same error messages with respect to ufshcd-hisi, but in this case the system cannot find the rootfs, even though it is also installed in UFS (with the same UUID).

[ 1.532563] ufshcd-hisi ff3b0000.ufs: ufshcd_populate_vreg: Unable to find vdd-hba-supply regulator, assuming enabled
[ 1.532598] ufshcd-hisi ff3b0000.ufs: ufshcd_populate_vreg: Unable to find vcc-supply regulator, assuming enabled
[ 1.532611] ufshcd-hisi ff3b0000.ufs: ufshcd_populate_vreg: Unable to find vccq-supply regulator, assuming enabled
[ 1.532623] ufshcd-hisi ff3b0000.ufs: ufshcd_populate_vreg: Unable to find vccq2-supply regulator, assuming enabled
[ 1.559864] scsi host0: ufshcd
[ 1.573745] libphy: Fixed MDIO Bus: probed
[ 1.573993] tun: Universal TUN/TAP device driver, 1.6
[ 1.574625] thunder_xcv, ver 1.0
[ 1.574664] thunder_bgx, ver 1.0
[ 1.574694] nicpf, ver 1.0
[ 1.574961] e1000e: Intel(R) PRO/1000 Network Driver - 3.2.6-k
[ 1.574969] e1000e: Copyright(c) 1999 - 2015 Intel Corporation.
[ 1.575004] igb: Intel(R) Gigabit Ethernet Network Driver - version 5.4.0-k
[ 1.575013] igb: Copyright (c) 2007-2014 Intel Corporation.
[ 1.575047] igbvf: Intel(R) Gigabit Virtual Function Network Driver - version 2.4.0-k
[ 1.575057] igbvf: Copyright (c) 2009 - 2012 Intel Corporation.
[ 1.575268] sky2: driver version 1.30
[ 1.575710] VFIO - User Level meta-driver version: 0.3
[ 1.577432] dwc3 ff100000.dwc3: Failed to get clk ‘ref’: -2
[ 1.577632] dwc3 ff100000.dwc3: failed to initialize core
[ 1.577699] usb-hisi-dwc3 soc:hisi_dwc3: finish dwc3 hisi probe
[ 1.578295] ehci_hcd: USB 2.0 ‘Enhanced’ Host Controller (EHCI) Driver
[ 1.578307] ehci-pci: EHCI PCI platform driver
[ 1.578340] ehci-platform: EHCI generic platform driver
[ 1.578443] ehci-orion: EHCI orion driver
[ 1.578513] ehci-exynos: EHCI EXYNOS driver
[ 1.578569] ohci_hcd: USB 1.1 ‘Open’ Host Controller (OHCI) Driver
[ 1.578599] ohci-pci: OHCI PCI platform driver
[ 1.578642] ohci-platform: OHCI generic platform driver
[ 1.578717] ohci-exynos: OHCI EXYNOS driver
[ 1.579015] usbcore: registered new interface driver usb-storage
[ 1.581068] rtc-efi rtc-efi: rtc core: registered rtc-efi as rtc0
[ 1.581431] rtc-pl031 fff04000.rtc: rtc core: registered pl031 as rtc1
[ 1.581884] i2c /dev entries driver
[ 1.585000] sp805-wdt e8a06000.watchetup for DMA on RX dma0chan2, TX dma0chan3
[ 3.515493] dwc3 ff100000.dwc3: Failed to get clk ‘ref’: -2
[ 3.521319] dwc3 ff100000.dwc3: failed to initialize core
[ 3.528465] dwmmc_k3 ff3ff000.dwmmc2: fifo-depth property not found, using value of FIFOTH register as default
[ 3.540617] dwmmc_k3 ff3ff000.dwmmc2: IDMAC supports 64-bit address mode.
[ 3.547594] dwmmc_k3 ff3ff000.dwmmc2: Using internal DMA controller.
[ 3.553959] dwmmc_k3 ff3ff000.dwmmc2: Version ID is 270a
[ 3.559297] dwmmc_k3 ff3ff000.dwmmc2: DW MMC controller at irq 60,32 bit host data width,128 deep fifo
[ 3.568696] dwmmc_k3 ff3ff000.dwmmc2: Linked as a consumer to regulator.6
[ 3.575533] mmc_host mmc1: card is non-removable.
[ 3.675191] mmc_host mmc1: Bus speed (slot 0) = 400000Hz (slot req 400000Hz, actual 400000HZ div = 0)
[ 3.699511] dwc3 ff100000.dwc3: Failed to get clk ‘ref’: -2
[ 3.705308] dwc3 ff100000.dwc3: failed to initialize core
[ 3.712675] dwc3 ff100000.dwc3: Failed to get clk ‘ref’: -2
[ 3.719090] dwc3 ff100000.dwc3: failed to initialize core
[ 3.720094] dwmmc_k3 ff3ff000.dwmmc2: card claims to support voltages below defined range
[ 3.725963] input: keys as /devices/platform/keys/input/input0
[ 3.740353] dwc3 ff100000.dwc3: Failed to get clk ‘ref’: -2
[ 3.745958] rtc-efi rtc-efi: setting system clock to 1970-01-06 18:26:30 UTC (498390)
[ 3.754338] ALSA device list:
[ 3.754475] dwc3 ff100000.dwc3: failed to initialize core
[ 3.757318] No soundcards found.
[ 3.766597] uart-pl011 fff32000.serial: no DMA platform data
[ 3.780830] mmc_host mmc1: Bus speed (slot 0) = 25000000Hz (slot req 25000000Hz, actual 25000000HZ div = 0)
[ 3.805373] random: fast init done
[ 3.817596] mmc1: new SDIO card at address 0001
[ 4.928369] ufshcd-hisi ff3b0000.ufs: ufshcd_query_flag: Sending flag query for idn 3 failed, err = -11
[ 6.465296] ufshcd-hisi ff3b0000.ufs: ufshcd_query_flag: Sending flag query for idn 3 failed, err = -11
[ 6.474738] ufshcd-hisi ff3b0000.ufs: ufshcd_query_flag_retry: query attribute, opcode 5, idn 3, failed with error -11 after 3 retires
[ 8.000358] ufshcd-hisi ff3b0000.ufs: __ufshcd_query_descriptor: opcode 0x01 for idn 8 failed, index 0, err = -11
[ 9.536350] ufshcd-hisi ff3b0000.ufs: __ufshcd_query_descriptor: opcode 0x01 for idn 8 failed, index 0, err = -11
[ 11.072338] ufshcd-hisi ff3b0000.ufs: __ufshcd_query_descriptor: opcode 0x01 for idn 8 failed, index 0, err = -11
[ 11.082667] ufshcd-hisi ff3b0000.ufs: ufshcd_read_desc_param: Failed reading descriptor. desc_id 8, desc_index 0, param_offset 0, ret -11
[ 11.095023] ufshcd-hisi ff3b0000.ufs: ufshcd_init_icc_levels: Failed reading power descriptor.len = 98 ret = -11
[ 32.049556] ufshcd-hisi ff3b0000.ufs: ufshcd_print_pwr_info:[RX, TX]: gear=[1, 1], lane[1, 1], pwr[SLOWAUTO_MODE, SLOWAUTO_MODE], rate = 0
[ 32.064883] ufshcd-hisi ff3b0000.ufs: UPIU[0] - issue time 11102326 us
[ 32.071439] ufshcd-hisi ff3b0000.ufs: UPIU[0] - complete time 0 us
[ 32.077616] ufshcd-hisi ff3b0000.ufs: UPIU[0] - Transfer Request Descriptor phys@0x20c58000
[ 32.085975] UPIU TRD: 00000000: 15000000 00000000 0000000f 00000000
[ 32.092242] UPIU TRD: 00000010: 20c40000 00000000 00800080 01000001
[ 32.098507] ufshcd-hisi ff3b0000.ufs: UPIU[0] - Request UPIU phys@0x20c40000
[ 32.105556] UPIU REQ: 00000000: 00d04001 00000000 00000000 24000000
[ 32.111821] UPIU REQ: 00000010: 00000012 00000024 00000000 00000000
[ 32.118085] ufshcd-hisi ff3b0000.ufs: UPIU[0] - Response UPIU phys@0x20c40200
[ 32.125220] UPIU RSP: 00000000: 00000000 00000000 00000000 00000000
[ 32.131485] UPIU RSP: 00000010: 00000000 00000000 00000000 00000000
[ 32.137751] UPIU RSP: 00000020: 00000000 00000000 00000000 00000000
[ 32.144015] UPIU RSP: 00000030: 00000000
[ 32.147934] ufshcd-hisi ff3b0000.ufs: UPIU[0] - PRDT - 1 entries phys@0x20c40400
[ 32.155417] UPIU PRDT: 00000000: 18bb3000 00000002 00000000 00000023
[ 32.324391] ufs final power mode: gear = 3, lane = 2, pwr = 1, rate = 2
[ 32.340345] ufshcd-hisi ff3b0000.ufs: ufshcd_print_pwr_info:[RX, TX]: gear=[3, 3], lane[2, 2], pwr[FAST MODE, FAST MODE], rate = 2
[ 32.353106] Freeing unused kernel memory: 1344K
[ 32.357736] Run /init as init process
Loading, please wait…
starting version 232
[ 32.375740] random: systemd-udevd: uninitialized urandom read (16 bytes read)
[ 32.376581] random: udevadm: uninitialized urandom read (16 bytes read)
[ 32.383882] random: systemd-udevd: uninitialized urandom read (16 bytes read)
Begin: Loading essential drivers … done.
Begin: Running /scripts/init-premount … done.
Begin: Mounting root file system … Begin: Running /scripts/local-top … done.
Begin: Running /scripts/local-premount … done.
Begin: Waiting for root file system … Begin: Running /scripts/local-block … done.
Begin: Running /scripts/local-block … done.
Begin: Running /scripts/local-block … done.
Begin: Running /scripts/local-block … done.
Begin: Running /scripts/local-block … done.
Begin: Running /scripts/local-block … done.
Begin: Running /scripts/local-block … done.
Begin: Running /scripts/local-block … done.
Begin: Running /scripts/local-block … done.
Begin: Running /scripts/local-block … done.
Begin: Running /scripts/local-block … done.
Begin: Running /scripts/local-block … done.
Begin: Running /scripts/local-block … done.
Begin: Running /scripts/local-block … done.
Begin: Running /scripts/local-block … done.
Begin: Running /scripts/local-block … done.
Begin: Running /scripts/local-block … done.
Begin: Running /scripts/local-block … done.
Begin: Running /scripts/local-block … done.
Begin: Running /scripts/local-block … done.
Begin: Running /scripts/local-block … done.
Begin: Running /scripts/local-block … done.
Begin: Running /scripts/local-block … done.
Begin: Running /scripts/local-block … done.
Begin: Running /scripts/local-block … done.
Begin: Running /scripts/local-block … done.
Begin: Running /scripts/local-block … done.
[ 60.723785] random: crng init done
[ 60.727203] random: 7 urandom warning(s) missed due to ratelimiting
Begin: Running /scripts/local-block … done.
Begin: Running /scripts/local-block … done.
Begin: Running /scripts/local-block … done.
Begin: Running /scripts/local-block … done.
done.
Gave up waiting for root file system device. Common problems:

  • Boot args (cat /proc/cmdline)
    • Check rootdelay= (did the system wait long enough?)
  • Missing modules (cat /proc/modules; ls /dev)
    ALERT! UUID=8b58cef0-6d56-4af5-b05c-8c00774239cf does not exist. Dropping to a shell!

@Mani Just to confirm that with the latest Debian snapshot (20190822-37) all is good for me now. Many thanks!