Re: MHI driver issue with Sierra Wireless AirPrime EM919X

[Bhaumik Bhatt <bbhatt@codeaurora.org>]

On 2021-08-02 09:33 AM, Loic Poulain wrote:
>> > On Fri, 30 Jul 2021 at 19:52, Thomas Perrot <
>> > thomas.perrot@bootlin.com> wrote:
>> > >
>> > > Hello,
>> > >
>> > > I’m trying to use the MHI driver with a Sierra Wireless AirPrime
>> > > EM919X
>> > > connected to an NXP i.MX6DL through a PCIe gen2 bus, on 5.13.6, but
>> > > the
>> > > device initialisation fails, as follows:
>> > >
>> > > [    3.029401] mhi-pci-generic 0000:01:00.0: BAR 0: assigned [mem
>> > > 0x01100000-0x01100fff 64bit]
>> > > [    3.041095] mhi-pci-generic 0000:01:00.0: enabling device (0140 ->
>> > > 0142)
>> > > [    3.118299] mhi mhi0: Requested to power ON
>> > > [   11.370361] mhi mhi0: Power on setup success
>> > > [   11.372503] mhi mhi0: Wait for device to enter SBL or Mission mode
>> > > [   15.664068] mhi-pci-generic 0000:01:00.0: failed to suspend
>> > > device:
>> > > -16
>> > > [   22.619948] mhi-pci-generic 0000:01:00.0: refused to change power
>> > > state from D3hot to D0
>> > > [   57.289998] mhi-pci-generic 0000:01:00.0: can't change power state
>> > > from D3hot to D0 (config space inaccessible)
>> > > [   73.769675] mhi-pci-generic 0000:01:00.0: can't change power state
>> > > from D3cold to D0 (config space inaccessible)
>> > > [   73.780188] mhi-pci-generic 0000:01:00.0: can't change power state
>> > > from D3hot to D0 (config space inaccessible)
>> > > [   73.836150] PC is at mhi_pci_read_reg+0xc/0x14
>> > > [   73.840642] LR is at mhi_get_mhi_state+0x2c/0x5c
>> > > [   74.121120] [<c05dcaf4>] (mhi_pci_read_reg) from [<c05d754c>]
>> > > (mhi_get_mhi_state+0x2c/0x5c)
>> > > [   74.129529] [<c05d754c>] (mhi_get_mhi_state) from [<c05da440>]
>> > > (mhi_pm_resume+0x38/0x298)
>> > > [   74.137754] [<c05da440>] (mhi_pm_resume) from [<c05dcbd0>]
>> > > (mhi_pci_runtime_resume+0x70/0xe0)
>> > > [   74.146326] [<c05dcbd0>] (mhi_pci_runtime_resume) from
>> > > [<c0604da0>]
>> > > (pci_pm_runtime_resume+0x84/0xa0)
>> > >
>> > > Do you have any idea where the issue might come from?
>> > >
>> > > MHI seems to enter in READY state and waiting to enter in SBL or
>> > > Mission mode when the issue occurs, the host can start MHI
>> > > initialization by programming MMIO registers and sets the device into
>> > > MHI_M0 state.
>> >
>> > runtime-pm is only enabled when the device is in mission mode, so the
>> > device has likely been successfully initialized, It is just that there
>> > is no info message indicating initialization completion and we should
>> > probably add that. I think maybe about some PCIe suspend/resume
>> > issues, could you try disabling runtime-pm for that device? or simply
>> > comment `pm_runtime_allow` call?
>> 
>> Thanks for your help, I disabled the power management, I obtains the
>> following trace:
>> 
>> [    0.000000] Booting Linux on physical CPU 0x0
>> [    0.000000] Linux version 5.13.6 (arm-oe-linux-gnueabi-gcc (GCC)
>> 9.2.0, GNU ld (GNU Binutils) 2.32.0.20190204) #1 SMP Mon Aug 2 
>> 14:27:03
>> UTC 2021
>> [    0.000000] CPU: ARMv7 Processor [412fc09a] revision 10 (ARMv7),
>> cr=10c5387d
>> [    0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing
>> instruction cache
>> [    0.000000] OF: fdt: Machine model: i.MX6 Duallite module
>> [    0.000000] Memory policy: Data cache writealloc
>> [    0.000000] cma: Reserved 64 MiB at 0x4c000000
>> [    0.000000] Zone ranges:
>> [    0.000000]   Normal   [mem 0x0000000010000000-0x000000003fffffff]
>> [    0.000000]   HighMem  [mem 0x0000000040000000-0x000000004fffffff]
>> [    0.000000] Movable zone start for each node
>> [    0.000000] Early memory node ranges
>> [    0.000000]   node   0: [mem 0x0000000010000000-0x000000004fffffff]
>> [    0.000000] Initmem setup node 0 [mem 0x0000000010000000-
>> 0x000000004fffffff]
>> [    0.000000] On node 0 totalpages: 262144
>> [    0.000000]   Normal zone: 1536 pages used for memmap
>> [    0.000000]   Normal zone: 0 pages reserved
>> [    0.000000]   Normal zone: 196608 pages, LIFO batch:63
>> [    0.000000]   HighMem zone: 65536 pages, LIFO batch:15
>> [    0.000000] percpu: Embedded 20 pages/cpu s52396 r8192 d21332 
>> u81920
>> [    0.000000] pcpu-alloc: s52396 r8192 d21332 u81920 alloc=20*4096
>> [    0.000000] pcpu-alloc: [0] 0 [0] 1
>> [    0.000000] Built 1 zonelists, mobility grouping on.  Total pages:
>> 260608
>> [    0.000000] Kernel command line: console=ttymxc3,115200n8 
>> loglevel=8
>> root=/dev/nfs ip=10.0.0.2:255.255.255.0
>> nfsroot=10.0.0.1:/var/lib/nfsboot,v4,tcp
>> [    0.000000] Dentry cache hash table entries: 131072 (order: 7,
>> 524288 bytes, linear)
>> [    0.000000] Inode-cache hash table entries: 65536 (order: 6, 262144
>> bytes, linear)
>> [    0.000000] mem auto-init: stack:off, heap alloc:off, heap free:off
>> [    0.000000] Memory: 945728K/1048576K available (13312K kernel code,
>> 1910K rwdata, 4228K rodata, 1024K init, 6621K bss, 37312K reserved,
>> 65536K cma-reserved, 196608K highmem)
>> [    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=2,
>> Nodes=1
>> [    0.000000] trace event string verifier disabled
>> [    0.000000] Running RCU self tests
>> [    0.000000] rcu: Hierarchical RCU implementation.
>> [    0.000000] rcu:     RCU event tracing is enabled.
>> [    0.000000] rcu:     RCU lockdep checking is enabled.
>> [    0.000000] rcu:     RCU restricting CPUs from NR_CPUS=4 to
>> nr_cpu_ids=2.
>> [    0.000000] rcu: RCU calculated value of scheduler-enlistment delay
>> is 10 jiffies.
>> [    0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16,
>> nr_cpu_ids=2
>> [    0.000000] NR_IRQS: 16, nr_irqs: 16, preallocated irqs: 16
>> [    0.000000] L2C-310 erratum 769419 enabled
>> [    0.000000] L2C-310 enabling early BRESP for Cortex-A9
>> [    0.000000] L2C-310 full line of zeros enabled for Cortex-A9
>> [    0.000000] L2C-310 ID prefetch enabled, offset 16 lines
>> [    0.000000] L2C-310 dynamic clock gating enabled, standby mode
>> enabled
>> [    0.000000] L2C-310 cache controller enabled, 16 ways, 512 kB
>> [    0.000000] L2C-310: CACHE_ID 0x410000c8, AUX_CTRL 0x76450001
>> [    0.000000] random: get_random_bytes called from
>> start_kernel+0x364/0x58c with crng_init=0
>> [    0.000000] Switching to timer-based delay loop, resolution 333ns
>> [    0.000001] sched_clock: 32 bits at 3000kHz, resolution 333ns, 
>> wraps
>> every 715827882841ns
>> [    0.000033] clocksource: mxc_timer1: mask: 0xffffffff max_cycles:
>> 0xffffffff, max_idle_ns: 637086815595 ns
>> [    0.001600] Console: colour dummy device 80x30
>> [    0.001663] Lock dependency validator: Copyright (c) 2006 Red Hat,
>> Inc., Ingo Molnar
>> [    0.001685] ... MAX_LOCKDEP_SUBCLASSES:  8
>> [    0.001703] ... MAX_LOCK_DEPTH:          48
>> [    0.001721] ... MAX_LOCKDEP_KEYS:        8192
>> [    0.001742] ... CLASSHASH_SIZE:          4096
>> [    0.001760] ... MAX_LOCKDEP_ENTRIES:     32768
>> [    0.001777] ... MAX_LOCKDEP_CHAINS:      65536
>> [    0.001795] ... CHAINHASH_SIZE:          32768
>> [    0.001812]  memory used by lock dependency info: 4061 kB
>> [    0.001831]  memory used for stack traces: 2112 kB
>> [    0.001849]  per task-struct memory footprint: 1536 bytes
>> [    0.001979] Calibrating delay loop (skipped), value calculated 
>> using
>> timer frequency.. 6.00 BogoMIPS (lpj=30000)
>> [    0.002020] pid_max: default: 32768 minimum: 301
>> [    0.002324] Mount-cache hash table entries: 2048 (order: 1, 8192
>> bytes, linear)
>> [    0.002375] Mountpoint-cache hash table entries: 2048 (order: 1,
>> 8192 bytes, linear)
>> [    0.006205] CPU: Testing write buffer coherency: ok
>> [    0.006386] CPU0: Spectre v2: using BPIALL workaround
>> [    0.007450] CPU0: thread -1, cpu 0, socket 0, mpidr 80000000
>> [    0.010927] Setting up static identity map for 0x10100000 -
>> 0x10100078
>> [    0.011749] rcu: Hierarchical SRCU implementation.
>> [    0.013800] smp: Bringing up secondary CPUs ...
>> [    0.017275] CPU1: thread -1, cpu 1, socket 0, mpidr 80000001
>> [    0.017300] CPU1: Spectre v2: using BPIALL workaround
>> [    0.018621] smp: Brought up 1 node, 2 CPUs
>> [    0.018660] SMP: Total of 2 processors activated (12.00 BogoMIPS).
>> [    0.018691] CPU: All CPU(s) started in SVC mode.
>> [    0.022001] devtmpfs: initialized
>> [    0.061678] VFP support v0.3: implementor 41 architecture 3 part 30
>> variant 9 rev 4
>> [    0.064662] clocksource: jiffies: mask: 0xffffffff max_cycles:
>> 0xffffffff, max_idle_ns: 19112604462750000 ns
>> [    0.064755] futex hash table entries: 512 (order: 3, 32768 bytes,
>> linear)
>> [    0.068750] pinctrl core: initialized pinctrl subsystem
>> [    0.075244] NET: Registered protocol family 16
>> [    0.102637] DMA: preallocated 256 KiB pool for atomic coherent
>> allocations
>> [    0.108783] thermal_sys: Registered thermal governor 'step_wise'
>> [    0.109361] cpuidle: using governor menu
>> [    0.109609] NET: Registered protocol family 42
>> [    0.110336] CPU identified as i.MX6DL, silicon rev 1.3
>> [    0.157666] vdd1p1: supplied by regulator-dummy
>> [    0.160738] vdd3p0: supplied by regulator-dummy
>> [    0.163009] vdd2p5: supplied by regulator-dummy
>> [    0.166539] vddpu: supplied by regulator-dummy
>> [    0.204081] platform 2400000.ipu: Fixing up cyclic dependency with
>> 20e0000.iomuxc-gpr:ipu1_csi1_mux
>> [    0.204560] platform 2400000.ipu: Fixing up cyclic dependency with
>> 20e0000.iomuxc-gpr:ipu1_csi0_mux
>> [    0.216152] No ATAGs?
>> [    0.216575] hw-breakpoint: found 5 (+1 reserved) breakpoint and 1
>> watchpoint registers.
>> [    0.216689] hw-breakpoint: maximum watchpoint size is 4 bytes.
>> [    0.218287] debugfs: Directory 'dummy-iomuxc-gpr@20e0000' with
>> parent 'regmap' already present!
>> [    0.219892] imx6dl-pinctrl 20e0000.pinctrl: initialized IMX pinctrl
>> driver
>> [    0.336589] mxs-dma 110000.dma-apbh: initialized
>> [    0.366282] vgaarb: loaded
>> [    0.368879] SCSI subsystem initialized
>> [    0.369795] libata version 3.00 loaded.
>> [    0.371044] usbcore: registered new interface driver usbfs
>> [    0.371350] usbcore: registered new interface driver hub
>> [    0.371534] usbcore: registered new device driver usb
>> [    0.372134] usb_phy_generic usbphynop1: supply vcc not found, using
>> dummy regulator
>> [    0.373424] usb_phy_generic usbphynop2: supply vcc not found, using
>> dummy regulator
>> [    0.380083] i2c i2c-1: IMX I2C adapter registered
>> [    0.381434] pps_core: LinuxPPS API ver. 1 registered
>> [    0.381470] pps_core: Software ver. 5.3.6 - Copyright 2005-2007
>> Rodolfo Giometti <giometti@linux.it>
>> [    0.381551] PTP clock support registered
>> [    0.386332] Bluetooth: Core ver 2.22
>> [    0.386506] NET: Registered protocol family 31
>> [    0.386535] Bluetooth: HCI device and connection manager 
>> initialized
>> [    0.386695] Bluetooth: HCI socket layer initialized
>> [    0.386748] Bluetooth: L2CAP socket layer initialized
>> [    0.386945] Bluetooth: SCO socket layer initialized
>> [    0.391017] clocksource: Switched to clocksource mxc_timer1
>> [    0.763351] VFS: Disk quotas dquot_6.6.0
>> [    0.763583] VFS: Dquot-cache hash table entries: 1024 (order 0, 
>> 4096
>> bytes)
>> [    0.800699] NET: Registered protocol family 2
>> [    0.801465] IP idents hash table entries: 16384 (order: 5, 131072
>> bytes, linear)
>> [    0.805081] tcp_listen_portaddr_hash hash table entries: 512 
>> (order:
>> 2, 22528 bytes, linear)
>> [    0.805228] TCP established hash table entries: 8192 (order: 3,
>> 32768 bytes, linear)
>> [    0.805411] TCP bind hash table entries: 8192 (order: 6, 327680
>> bytes, linear)
>> [    0.806559] TCP: Hash tables configured (established 8192 bind 
>> 8192)
>> [    0.807250] UDP hash table entries: 512 (order: 3, 49152 bytes,
>> linear)
>> [    0.807475] UDP-Lite hash table entries: 512 (order: 3, 49152 
>> bytes,
>> linear)
>> [    0.808140] NET: Registered protocol family 1
>> [    0.811976] RPC: Registered named UNIX socket transport module.
>> [    0.812100] RPC: Registered udp transport module.
>> [    0.812129] RPC: Registered tcp transport module.
>> [    0.812155] RPC: Registered tcp NFSv4.1 backchannel transport
>> module.
>> [    0.814412] PCI: CLS 0 bytes, default 64
>> [    0.815722] armv7-pmu pmu: hw perfevents: no interrupt-affinity
>> property, guessing.
>> [    1.395389] hw perfevents: enabled with armv7_cortex_a9 PMU driver,
>> 7 counters available
>> [    1.401550] Initialise system trusted keyrings
>> [    1.402567] workingset: timestamp_bits=30 max_order=18
>> bucket_order=0
>> [    1.431576] NFS: Registering the id_resolver key type
>> [    1.431773] Key type id_resolver registered
>> [    1.431892] Key type id_legacy registered
>> [    1.432131] jffs2: version 2.2. (NAND) © 2001-2006 Red Hat, Inc.
>> [    1.434360] fuse: init (API version 7.34)
>> [    1.538869] Key type asymmetric registered
>> [    1.539043] Asymmetric key parser 'x509' registered
>> [    1.539425] bounce: pool size: 64 pages
>> [    1.539666] io scheduler mq-deadline registered
>> [    1.539706] io scheduler kyber registered
>> [    1.546350] imx6q-pcie 1ffc000.pcie: host bridge /soc/pcie@1ffc000
>> ranges:
>> [    1.546683] imx6q-pcie 1ffc000.pcie:       IO
>> 0x0001f80000..0x0001f8ffff -> 0x0000000000
>> [    1.546998] imx6q-pcie 1ffc000.pcie:      MEM
>> 0x0001000000..0x0001efffff -> 0x0001000000
>> [    1.561233] imx-sdma 20ec000.sdma: Direct firmware load for
>> imx/sdma/sdma-imx6q.bin failed with error -2
>> [    1.561380] imx-sdma 20ec000.sdma: Falling back to sysfs fallback
>> for: imx/sdma/sdma-imx6q.bin
>> [    1.576583] pfuze100-regulator 1-0008: Full layer: 2, Metal layer: 
>> 1
>> [    1.577276] pfuze100-regulator 1-0008: FAB: 0, FIN: 0
>> [    1.577316] pfuze100-regulator 1-0008: pfuze100 found.
>> [    1.608012] 21f0000.serial: ttymxc3 at MMIO 0x21f0000 (irq = 72,
>> base_baud = 5000000) is a IMX
>> [    1.662256] imx6q-pcie 1ffc000.pcie: iATU unroll: disabled
>> [    1.662287] imx6q-pcie 1ffc000.pcie: Detected iATU regions: 4
>> outbound, 4 inbound
>> [    1.962914] imx6q-pcie 1ffc000.pcie: Link up
>> [    2.061645] imx6q-pcie 1ffc000.pcie: Link up
>> [    2.061667] imx6q-pcie 1ffc000.pcie: Link up, Gen2
>> [    2.061687] imx6q-pcie 1ffc000.pcie: Link up
>> [    2.062985] imx6q-pcie 1ffc000.pcie: PCI host bridge to bus 0000:00
>> [    2.063019] pci_bus 0000:00: root bus resource [bus 00-ff]
>> [    2.063044] pci_bus 0000:00: root bus resource [io  0x0000-0xffff]
>> [    2.063067] pci_bus 0000:00: root bus resource [mem 0x01000000-
>> 0x01efffff]
>> [    2.063496] pci 0000:00:00.0: [16c3:abcd] type 01 class 0x060400
>> [    2.063572] pci 0000:00:00.0: reg 0x10: [mem 0x00000000-0x000fffff]
>> [    2.063637] pci 0000:00:00.0: reg 0x38: [mem 0x00000000-0x0000ffff
>> pref]
>> [    2.063745] pci 0000:00:00.0: Limiting cfg_size to 512
>> [    2.064120] pci 0000:00:00.0: supports D1
>> [    2.064138] pci 0000:00:00.0: PME# supported from D0 D1 D3hot 
>> D3cold
>> [    2.068753] PCI: bus0: Fast back to back transfers disabled
>> [    2.069419] pci 0000:01:00.0: [17cb:0306] type 00 class 0xff0000
>> [    2.069550] pci 0000:01:00.0: reg 0x10: [mem 0x00000000-0x00000fff
>> 64bit]
>> [    2.069633] pci 0000:01:00.0: reg 0x18: [mem 0x00000000-0x00000fff
>> 64bit]
>> [    2.070265] pci 0000:01:00.0: PME# supported from D0 D3hot D3cold
>> [    2.070437] pci 0000:01:00.0: 4.000 Gb/s available PCIe bandwidth,
>> limited by 5.0 GT/s PCIe x1 link at 0000:00:00.0 (capable of 31.506
>> Gb/s with 16.0 GT/s PCIe x2 link)
>> [    2.074462] PCI: bus1: Fast back to back transfers disabled
>> [    2.076179] printk: console [ttymxc3] enabled
>> [    2.079173] pci 0000:00:00.0: BAR 0: assigned [mem 0x01000000-
>> 0x010fffff]
>> [    2.702298] pci 0000:00:00.0: BAR 8: assigned [mem 0x01100000-
>> 0x011fffff]
>> [    2.709133] pci 0000:00:00.0: BAR 6: assigned [mem 0x01200000-
>> 0x0120ffff pref]
>> [    2.716589] pci 0000:01:00.0: BAR 0: assigned [mem 0x01100000-
>> 0x01100fff 64bit]
>> [    2.724097] pci 0000:01:00.0: BAR 2: assigned [mem 0x01101000-
>> 0x01101fff 64bit]
>> [    2.725446] etnaviv etnaviv: bound 130000.gpu (ops gpu_ops)
>> [    2.731578] pci 0000:00:00.0: PCI bridge to [bus 01-ff]
>> [    2.738177] etnaviv etnaviv: bound 134000.gpu (ops gpu_ops)
>> [    2.742511] pci 0000:00:00.0:   bridge window [mem 0x01100000-
>> 0x011fffff]
>> [    2.748092] etnaviv-gpu 130000.gpu: model: GC880, revision: 5106
>> [    2.755855] mhi-pci-generic 0000:01:00.0: MHI PCI device found:
>> qcom-sdx55m
>> [    2.768315] mhi-pci-generic 0000:01:00.0: BAR 0: assigned [mem
>> 0x01100000-0x01100fff 64bit]
>> [    2.769015] etnaviv-gpu 134000.gpu: model: GC320, revision: 5007
>> [    2.776912] mhi-pci-generic 0000:01:00.0: enabling device (0140 ->
>> 0142)
>> [    2.786483] [drm] Initialized etnaviv 1.3.0 20151214 for etnaviv on
>> minor 0
>> [    2.801751] mhi mhi0: Requested to power ON
>> [    2.808489] mhi mhi0: Power on setup success
>> [    2.810346] imx-drm display-subsystem: bound imx-ipuv3-crtc.2 (ops
>> ipu_crtc_ops)
>> [    2.821931] imx-drm display-subsystem: bound imx-ipuv3-crtc.3 (ops
>> ipu_crtc_ops)
>> [    2.831489] [drm] Initialized imx-drm 1.0.0 20120507 for display-
>> subsystem on minor 1
>> [    2.839891] imx-ipuv3 2400000.ipu: IPUv3H probed
>> [    2.891577] brd: module loaded
>> [    2.939853] loop: module loaded
>> [    2.951691] spi@0 enforce active low on chipselect handle
>> [    2.957268] spi@1 enforce active low on chipselect handle
>> [    2.972776] spi@0 enforce active low on chipselect handle
>> [    2.978398] spi@1 enforce active low on chipselect handle
>> [    2.994315] libphy: Fixed MDIO Bus: probed
>> [    3.000604] CAN device driver interface
>> [    3.010081] pps pps0: new PPS source ptp0
>> [    3.028687] libphy: fec_enet_mii_bus: probed
>> [    3.036072] fec 2188000.ethernet eth0: registered PHC device 0
>> [    3.044184] PPP generic driver version 2.4.2
>> [    3.049501] PPP BSD Compression module registered
>> [    3.054353] PPP Deflate Compression module registered
>> [    3.059991] usbcore: registered new interface driver r8152
>> [    3.065701] usbcore: registered new interface driver lan78xx
>> [    3.071583] usbcore: registered new interface driver cdc_ether
>> [    3.077562] usbcore: registered new interface driver cdc_eem
>> [    3.083500] usbcore: registered new interface driver smsc95xx
>> [    3.089413] usbcore: registered new interface driver net1080
>> [    3.095293] usbcore: registered new interface driver cdc_subset
>> [    3.101424] usbcore: registered new interface driver zaurus
>> [    3.107144] usbcore: registered new interface driver MOSCHIP usb-
>> ethernet driver
>> [    3.114840] usbcore: registered new interface driver sierra_net
>> [    3.121028] usbcore: registered new interface driver cdc_ncm
>> [    3.126862] usbcore: registered new interface driver qmi_wwan
>> [    3.132835] usbcore: registered new interface driver cdc_mbim
>> [    3.138607] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI)
>> Driver
>> [    3.145209] ehci-pci: EHCI PCI platform driver
>> [    3.149951] usbcore: registered new interface driver cdc_wdm
>> [    3.155907] usbcore: registered new interface driver usb-storage
>> [    3.162458] usbcore: registered new interface driver
>> usbserial_generic
>> [    3.169462] usbserial: USB Serial support registered for generic
>> [    3.175898] usbcore: registered new interface driver ftdi_sio
>> [    3.181889] usbserial: USB Serial support registered for FTDI USB
>> Serial Device
>> [    3.189345] usbcore: registered new interface driver option
>> [    3.195086] usbserial: USB Serial support registered for GSM modem
>> (1-port)
>> [    3.202258] usbcore: registered new interface driver qcserial
>> [    3.208119] usbserial: USB Serial support registered for Qualcomm
>> USB modem
>> [    3.233880] snvs_rtc 20cc000.snvs:snvs-rtc-lp: registered as rtc0
>> [    3.240101] snvs_rtc 20cc000.snvs:snvs-rtc-lp: setting system clock
>> to 1970-01-01T00:00:00 UTC (0)
>> [    3.249753] i2c /dev entries driver
>> [    3.268851] sdhci: Secure Digital Host Controller Interface driver
>> [    3.275192] sdhci: Copyright(c) Pierre Ossman
>> [    3.279581] sdhci-pltfm: SDHCI platform and OF driver helper
>> [    3.289992] caam 2100000.crypto: Entropy delay = 3200
>> [    3.331171] mmc1: SDHCI controller on 2194000.mmc [2194000.mmc]
>> using ADMA
>> [    3.338991] mmc2: SDHCI controller on 2198000.mmc [2198000.mmc]
>> using ADMA
>> [    3.356018] caam 2100000.crypto: Instantiated RNG4 SH0
>> [    3.416778] caam 2100000.crypto: Instantiated RNG4 SH1
>> [    3.422116] caam 2100000.crypto: device ID = 0x0a16010000000100 
>> (Era
>> 4)
>> [    3.428768] caam 2100000.crypto: job rings = 2, qi = 0
>> [    3.453774] mmc3: SDHCI controller on 219c000.mmc [219c000.mmc]
>> using ADMA
>> [    3.462624] mmc2: new DDR MMC card at address 0001
>> [    3.473278] mmcblk2: mmc2:0001 00016G 14.6 GiB
>> [    3.480232] mmcblk2boot0: mmc2:0001 00016G 4.00 MiB
>> [    3.481917] caam algorithms registered in /proc/crypto
>> [    3.487898] mmcblk2boot1: mmc2:0001 00016G 4.00 MiB
>> [    3.498687] caam 2100000.crypto: registering rng-caam
>> [    3.499061] mmcblk2rpmb: mmc2:0001 00016G 4.00 MiB, chardev (244:0)
>> [    3.524714] usbcore: registered new interface driver usbhid
>> [    3.530329] usbhid: USB HID core driver
>> [    3.543229] Initializing XFRM netlink socket
>> [    3.549810] NET: Registered protocol family 10
>> [    3.551444] mmc3: new DDR MMC card at address 0001
>> [    3.563454] Segment Routing with IPv6
>> [    3.568381] sit: IPv6, IPv4 and MPLS over IPv4 tunneling driver
>> [    3.572261] mmcblk3: mmc3:0001 E0004G 3.64 GiB
>> [    3.577406] NET: Registered protocol family 17
>> [    3.579848] mmcblk3boot0: mmc3:0001 E0004G 4.00 MiB
>> [    3.583595] NET: Registered protocol family 15
>> [    3.589477] mmcblk3boot1: mmc3:0001 E0004G 4.00 MiB
>> [    3.593057] can: controller area network core
>> [    3.593470] NET: Registered protocol family 29
>> [    3.603122] mmcblk3rpmb: mmc3:0001 E0004G 4.00 MiB, chardev (244:1)
>> [    3.607179] can: raw protocol
>> [    3.617067] can: broadcast manager protocol
>> [    3.621569] can: netlink gateway - max_hops=1
>> [    3.624307]  mmcblk3: p1 p2
>> [    3.626619] Key type dns_resolver registered
>> [    3.633579] random: fast init done
>> [    3.643820] Registering SWP/SWPB emulation handler
>> [    3.649438] Loading compiled-in X.509 certificates
>> [    3.748476] random: crng init done
>> [    3.821484] vddarm: supplied by SW1AB
>> [    3.828699] vddsoc: supplied by SW1C
>> [    4.431354] mhi mhi0: Wait for device to enter SBL or Mission mode
>> [    4.453212] mxs_phy 20c9000.usbphy: Data pin can't make good
>> contact.
>> [    4.469544] ci_hdrc ci_hdrc.1: EHCI Host Controller
>> [    4.475134] ci_hdrc ci_hdrc.1: new USB bus registered, assigned bus
>> number 1
>> [    4.511146] ci_hdrc ci_hdrc.1: USB 2.0 started, EHCI 1.00
>> [    4.518600] usb usb1: New USB device found, idVendor=1d6b,
>> idProduct=0002, bcdDevice= 5.13
>> [    4.527211] usb usb1: New USB device strings: Mfr=3, Product=2,
>> SerialNumber=1
>> [    4.534557] usb usb1: Product: EHCI Host Controller
>> [    4.539469] usb usb1: Manufacturer: Linux 5.13.6 ehci_hcd
>> [    4.544979] usb usb1: SerialNumber: ci_hdrc.1
>> [    4.556250] hub 1-0:1.0: USB hub found
>> [    4.560622] hub 1-0:1.0: 1 port detected
>> [    4.590745] imx_thermal 20c8000.anatop:tempmon: Industrial CPU
>> temperature grade - max:105C critical:100C passive:95C
>> [    4.861299] usb 1-1: new high-speed USB device number 2 using
>> ci_hdrc
>> [    5.064624] usb 1-1: New USB device found, idVendor=04b4,
>> idProduct=bd30, bcdDevice= 1.00
>> [    5.073441] usb 1-1: New USB device strings: Mfr=0, Product=0,
>> SerialNumber=0
>> [    5.087382] hub 1-1:1.0: USB hub found
>> [    5.091740] hub 1-1:1.0: 2 ports detected
>> [    5.511390] usb 1-1.1: new high-speed USB device number 3 using
>> ci_hdrc
>> [    5.664449] usb 1-1.1: New USB device found, idVendor=04b4,
>> idProduct=bd29, bcdDevice= 0.01
>> [    5.673182] usb 1-1.1: New USB device strings: Mfr=1, Product=2,
>> SerialNumber=3
>> [    5.680706] usb 1-1.1: Product: Remote Download Wireless Adapter
>> [    5.687033] usb 1-1.1: Manufacturer: Cypress Semiconductor Corp.
>> [    5.693268] usb 1-1.1: SerialNumber: 000000000001
>> [    5.801394] usb 1-1.2: new high-speed USB device number 4 using
>> ci_hdrc
>> [    5.955345] usb 1-1.2: New USB device found, idVendor=04b4,
>> idProduct=640c, bcdDevice= 1.12
>> [    5.964169] usb 1-1.2: New USB device strings: Mfr=1, Product=2,
>> SerialNumber=3
>> [    5.971823] usb 1-1.2: Product: BCM2045A0
>> [    5.975900] usb 1-1.2: Manufacturer: Cypress Semiconductor Corp.
>> [    5.982131] usb 1-1.2: SerialNumber: C0EE408051DF
>> [   11.355278] mhi-pci-generic 0000:01:00.0: failed to power up MHI
>> controller
>> [   11.388118] mhi-pci-generic: probe of 0000:01:00.0 failed with 
>> error
>> -110
> 
> Did you build MHI as builtin? maybe it's just a timeout issue, would
> you be able to increase the timeout_ms value of the
> mhi_controller_config in pci_generic from 8000ms to something like
> 20000ms, just to be sure, I saw some modems taking a long to boot...
> 
> Regards,
> Loic

As Loic suggested, I would just increase the timeout to 30 or 60 seconds 
to
be sure.

You could also monitor changes in debugfs which can tell you what the
registers read and get states at an interval of every second if you'd 
like.

watch -n 1 cat /sys/kernel/debug/mhi/mhi0/states
watch -n 1 cat /sys/kernel/debug/mhi/mhi0/regdump

You could start this after you load the kernel module to get most out of
the debug rather than building as Y, just build as M as Loic suggested.

Thanks,
Bhaumik
---
The Qualcomm Innovation Center, Inc. is a member of the Code Aurora 
Forum,
a Linux Foundation Collaborative Project