it takes an additional 20 seconds for the QMI interface to be available after the Linux kernel boot has finished. To be clear:
QMAP Enabled
usbcore: registered new interface driver GobiNet
usbcore: registered new interface driver usbserial
usbcore: registered new interface driver usbserial_generic
usbserial: USB Serial support registered for generic
usbcore: registered new interface driver GobiSerial
usbserial: USB Serial support registered for GobiSerial
GobiSerial xxxxxxx: GobiSerial converter detected
usb xxxx: GobiSerial converter now attached to ttyUSB0
GobiSerial xxxxxxx: GobiSerial converter detected
usb xxxx: GobiSerial converter now attached to ttyUSB1
GobiSerial xxxxxxx: GobiSerial converter detected
usb xxxx: GobiSerial converter now attached to ttyUSB2
GobiSerial: 2018-12-21/SWI_2.36:GobiSerial
***...20 second delay...***
creating qcqmi0
RawIP mode
Is this 20 seconds normal/expected? I thought the QMI-interface was supposed to bring an ‘improved performance/experience’ compared with the ‘old’ AT-interface. An additional 20 second post-boot delay seems to contradict this?
[840950.577656] usb 4-2: Manufacturer: Sierra Wireless, Incorporated
[840950.577662] usb 4-2: SerialNumber: UF81029002040635
[840950.578975] usb 4-2: Enable of device-initiated U1 failed.
[840950.579301] usb 4-2: Enable of device-initiated U2 failed.
[840950.579566] usb 4-2: Disable of device-initiated U1 failed.
[840950.579753] usb 4-2: Disable of device-initiated U2 failed.
[840950.580169] usb 4-2: Enable of device-initiated U1 failed.
[840950.580526] usb 4-2: Enable of device-initiated U2 failed.
[840950.580718] usb 4-2: Disable of device-initiated U1 failed.
[840950.580878] usb 4-2: Disable of device-initiated U2 failed.
[840950.581411] GobiSerial 4-2:1.0: GobiSerial converter detected
[840950.581685] usb 4-2: GobiSerial converter now attached to ttyUSB0
[840950.582027] usb 4-2: Enable of device-initiated U1 failed.
[840950.582329] usb 4-2: Enable of device-initiated U2 failed.
[840950.582544] usb 4-2: Disable of device-initiated U1 failed.
[840950.582661] usb 4-2: Disable of device-initiated U2 failed.
[840950.583226] usb 4-2: Enable of device-initiated U1 failed.
[840950.583568] usb 4-2: Enable of device-initiated U2 failed.
[840950.583727] usb 4-2: Disable of device-initiated U1 failed.
[840950.583836] usb 4-2: Disable of device-initiated U2 failed.
[840950.584363] GobiSerial 4-2:1.2: GobiSerial converter detected
[840950.584553] usb 4-2: GobiSerial converter now attached to ttyUSB1
[840950.585011] usb 4-2: Enable of device-initiated U1 failed.
[840950.585359] usb 4-2: Enable of device-initiated U2 failed.
[840950.585591] usb 4-2: Disable of device-initiated U1 failed.
[840950.585725] usb 4-2: Disable of device-initiated U2 failed.
[840950.586110] usb 4-2: Enable of device-initiated U1 failed.
[840950.586427] usb 4-2: Enable of device-initiated U2 failed.
[840950.586553] usb 4-2: Disable of device-initiated U1 failed.
[840950.586664] usb 4-2: Disable of device-initiated U2 failed.
[840950.587433] GobiSerial 4-2:1.3: GobiSerial converter detected
[840950.587657] usb 4-2: GobiSerial converter now attached to ttyUSB2
[840950.587983] usb 4-2: Enable of device-initiated U1 failed.
[840950.588362] usb 4-2: Enable of device-initiated U2 failed.
[840950.588832] usb 4-2: Disable of device-initiated U1 failed.
[840950.588945] usb 4-2: Disable of device-initiated U2 failed.
[840950.588989] QMAP Disabled
[840950.590341] GobiNet 4-2:1.8 eth1: register ‘GobiNet’ at usb-0000:00:14.0-2, GobiNet Ethernet Device, 52:33:f0:9a:86:64
[840950.590957] USB Speed : USB 3.0
[840950.591337] usb 4-2: Enable of device-initiated U1 failed.
[840950.591679] usb 4-2: Enable of device-initiated U2 failed.
[840961.062058] creating qcqmi0
[840961.062202] RawIP mode
From your post, I am guess you are running on a much more powerful platform (Ubuntu PC) than mine - I’m running on an ARM embedded platform.
Even so, your log shows it takes 11 seconds for QMI to be ready after ‘GobiNet’ ethernnet device is ready:
[840950.590341] GobiNet 4-2:1.8 eth1: register ‘GobiNet’ at usb-0000:00:14.0-2, GobiNet Ethernet Device, 52:33:f0:9a:86:64
[840950.590957] USB Speed : USB 3.0
[840950.591337] usb 4-2: Enable of device-initiated U1 failed.
[840950.591679] usb 4-2: Enable of device-initiated U2 failed.
[840961.062058] creating qcqmi0
[840961.062202] RawIP mode
OK, this is 2x faster than mine, but it still seems like a very long time??
Thanks jyijyi for confirming the time for a EM7430.
I’m still confused over what it is doing to take so long. My whole system boots in under 20 seconds, u-Boot, Kernel and enumerating numerous USB devices. But then QMI takes a further 20 seconds?
Seems this is related your ARM platform as there is no problem on ubuntu pc …
Maybe you can add some debug message on your platform to know the root cause.
I’ve looked into the driver a little. The 20 seconds is consumed by:
QMIDevice.c - RegisterQMIDevice()
…
// Device is not ready for QMI connections right away
// Wait up to 30 seconds before failing
result = QMIReady( pDev, 30000 );
…
QMIReady() loops for up to 30 seconds, polling for a response from the EM7565. My diagnostics show that it loops 5 times before it gets a response. The 5 loops equate to 20 seconds. Perhaps this is how long a EM7565 actually takes to be ready???
I’ve dug into the function QMIDevice() - what a mess!! This is where my 20 seconds is being consumed.
I’m not sure if I’m allowed to publish any of the code, so I’ll play safe and just describe it with pseudo-code.
QMIDevice() basically has an outer loop of 30 (curTime), within which there is an inner loop (iSCaleCount) of 100 x 10 mSecs. [At least the 100 x 10 mSecs is what the code is trying to achieve.] Unfortunately the 10 mSecs is implemented using function msleep(10), which according to kernel documentation will not be accurate. In reality this 10 mSecs wait actually take 30 mSecs.
Before the inner loop starts the driver polls the EM7565 and then enters the inner loop. If nothing goes wrong there is no way to exit this 100 x 30mSec loop (3 seconds). After the 3 seconds, the driver looks for a response from the EM7565. If no response, we loop around the outer. So in pseudo-code we’ve basically got:
for (outer=0; outer<30; outer++) {
poll EM7565;
for (inner=0; inner<100; inner++) {
delay 30 mSecs;
}
has EM7565 has responded?
if yes, exit.
}
Now, by removing the (seemingly redundant) inner loop, and replacing with a fixed 100 mSec delay [msleep(100)] I have effectively sped up the ‘poll-delay-response’ mechanism from once every 3 seconds, to once every 100 mSecs. The EM7565 is now ready after only 7 seconds.
An improvement from 20 seconds to 7 seconds by changing the ‘poll-delay-response’ timing implies that there is something wrong within the driver mechanism - maybe a race of some sort?