Modemmanager significant startup delay

Wed Aug 21 21:14:22 UTC 2019

On Wed, 2019-08-21 at 12:23 +0000, Amol Lad wrote:
> Please help with this. What could be the cause of significant MM
> startup delay?

When started, or when a new modem is plugged attached, ModemManager
runs through a hardware detection sequence to figure out whether the
thing you attached is actually a modem and what ports it has and what
protocols those ports speak.

Is this the full probing log? This modem should be driven with QMI but
the log only shows probing for the serial ttys.

Dan

> From: ModemManager-devel <
> modemmanager-devel-bounces at lists.freedesktop.org> On Behalf Of Amol
> Lad
> Sent: Monday, 19 August 2019 4:05 PM
> To: modemmanager-devel at lists.freedesktop.org
> Subject: Modemmanager significant startup delay
> 
> Hi,
> 
> I'm using Solidrun's clearfog-base plarform with Sierra Wireless
> EM7430 LTE chipset. I'm running OpenWRT 18.06 with ModemManager feed
> from 
> https://gitlab.freedesktop.org/mobile-broadband/mobile-broadband-openwrt
> 
> It is taking around 20 seconds for modemanager to bring up the LTE IP
> interface (i.e. after around 20 seconds 'wwan1' interface is up and I
> can ping external world). With uqmi the interface comes up instantly.
> Please refer to below logs (captured in -debug mode). It seems most
> of this delay is because of "serial command timeout". As you can see
> from the last time "[plugin manager] task 0: finished in '17.149826'
> seconds
> "
> 
> Please advise what is going wrong.
> 
> ...
> Mon Aug 19 10:11:05 2019 daemon.debug [2086]: <debug>
> [1566209465.535657] (ttyUSB2): <-- '<CR>'
> Mon Aug 19 10:11:05 2019 daemon.debug [2086]: <debug>
> [1566209465.535956] (ttyUSB2): <-- '<CR><LF>OK<CR><LF>'
> Mon Aug 19 10:11:05 2019 daemon.debug [2086]: <debug>
> [1566209465.536110] (tty/ttyUSB2) port is AT-capable
> Mon Aug 19 10:11:05 2019 daemon.debug [2086]: <debug>
> [1566209465.536188] [plugin manager] task 0,ttyUSB2: found best
> plugin for port (Sierra)
> Mon Aug 19 10:11:05 2019 daemon.debug [2086]: <debug>
> [1566209465.536269] [plugin manager] task 0,ttyUSB2: finished in
> '1.604063' seconds
> Mon Aug 19 10:11:05 2019 daemon.debug [2086]: <debug>
> [1566209465.536348] [plugin manager] task 0,ttyUSB2: best plugin
> matches device reported one: Sierra
> Mon Aug 19 10:11:05 2019 daemon.debug [2086]: <debug>
> [1566209465.536433] [plugin Manager] task 0: still 2 running probes
> (2 active): ttyUSB1, ttyUSB0
> Mon Aug 19 10:11:05 2019 daemon.debug [2086]: <debug>
> [1566209465.536565] (ttyUSB2) device open count is 0 (close)
> Mon Aug 19 10:11:05 2019 daemon.debug [2086]: <debug>
> [1566209465.536702] (ttyUSB2) closing
>  port...
> Mon Aug 19 10:11:05 2019 daemon.debug [2086]: <debug>
> [1566209465.537143] (ttyUSB2) serial port closed
> Mon Aug 19 10:11:05 2019 daemon.debug [2086]: <debug>
> [1566209465.537304] (ttyUSB2) forced to close port
> Mon Aug 19 10:11:06 2019 daemon.debug [2086]: <debug>
> [1566209466.220126] [plugin manager] task 0: min probing time elapsed
> Mon Aug 19 10:11:06 2019 daemon.debug [2086]: <debug>
> [1566209466.220187] [plugin Manager] task 0: still 2 running probes
> (2 active): ttyUSB1, ttyUSB0
> Mon Aug 19 10:11:08 2019 daemon.debug [2086]: <debug>
> [1566209468.868113] Parsing AT got: 'Serial command timed out'
> Mon Aug 19 10:11:08 2019 daemon.debug [2086]: <debug>
> [1566209468.868197] Parsing AT got: 'Serial command timed out'
> Mon Aug 19 10:11:08 2019 daemon.debug [2086]: <debug>
> [1566209468.868282] (ttyUSB1): --> 'AT<CR>'
> Mon Aug 19 10:11:08 2019 daemon.debug [2086]: <debug>
> [1566209468.868351] (ttyUSB0): --> 'AT<CR>'
> Mon Aug 19 10:11:11 2019 daemon.debug [2086]: <debug>
> [1566209471.869749] Parsing AT got: 'Serial command timed out'
> Mon Aug 19 10:11:11 2019 daemon.debug [2086]: <debug>
> [1566209471.869831] Parsing AT got: 'Serial command timed out'
> Mon Aug 19 10:11:11 2019 daemon.debug [2086]: <debug>
> [1566209471.869917] (ttyUSB1): --> 'AT<CR>'
> Mon Aug 19 10:11:11 2019 daemon.debug [2086]: <debug>
> [1566209471.869984] (ttyUSB0): --> 'AT<CR>'
> Mon Aug 19 10:11:14 2019 daemon.debug [2086]: <debug>
> [1566209474.869689] Parsing AT got: 'Serial command timed out'
> Mon Aug 19 10:11:14 2019 daemon.debug [2086]: <debug>
> [1566209474.869745] (tty/ttyUSB1) port is not AT-capable
> Mon Aug 19 10:11:14 2019 daemon.debug [2086]: <debug>
> [1566209474.869806] Parsing AT got: 'Serial command timed out'
> Mon Aug 19 10:11:14 2019 daemon.debug [2086]: <debug>
> [1566209474.869834] (tty/ttyUSB0) port is not AT-capable
> Mon Aug 19 10:11:14 2019 daemon.debug [2086]: <debug>
> [1566209474.869884] (tty/ttyUSB1) probing QCDM...
> Mon Aug 19 10:11:14 2019 daemon.debug [2086]: <debug>
> [1566209474.869916] (ttyUSB1) device open count is 0 (close)
> Mon Aug 19 10:11:14 2019 daemon.debug [2086]: <debug>
> [1566209474.869943] (ttyUSB1) closing serial port...
> Mon Aug 19 10:11:14 2019 daemon.debug [2086]: <debug>
> [1566209474.870349] (ttyUSB1) serial port closed
> Mon Aug 19 10:11:14 2019 daemon.debug [2086]: <debug>
> [1566209474.870415] (ttyUSB1) forced to close port
> Mon Aug 19 10:11:14 2019 daemon.debug [2086]: <debug>
> [1566209474.870517] (ttyUSB1) opening serial port...
> Mon Aug 19 10:11:14 2019 daemon.debug [2086]: <debug>
> [1566209474.870779] (ttyUSB1) device open count is 1 (open)
> Mon Aug 19 10:11:14 2019 daemon.debug [2086]: <debug>
> [1566209474.870851] (tty/ttyUSB0) probing QCDM...
> Mon Aug 19 10:11:14 2019 daemon.debug [2086]: <debug>
> [1566209474.870886] (ttyUSB0) device open count is 0 (close)
> Mon Aug 19 10:11:14 2019 daemon.debug [2086]: <debug>
> [1566209474.870913] (ttyUSB0) closing serial port...
> Mon Aug 19 10:11:14 2019 daemon.debug [2086]: <debug>
> [1566209474.871138] (ttyUSB0) serial port closed
> Mon Aug 19 10:11:14 2019 daemon.debug [2086]: <debug>
> [1566209474.871196] (ttyUSB0) forced to close port
> Mon Aug 19 10:11:14 2019 daemon.debug [2086]: <debug>
> [1566209474.871261] (ttyUSB0) opening serial port...
> Mon Aug 19 10:11:14 2019 daemon.debug [2086]: <debug>
> [1566209474.871351] (ttyUSB0) device open count is 1 (open)
> Mon Aug 19 10:11:14 2019 daemon.debug [2086]: <debug>
> [1566209474.871423] (ttyUSB1): --> 7e 00 78 f0 7e
> Mon Aug 19 10:11:14 2019 daemon.debug [2086]: <debug>
> [1566209474.871485] (ttyUSB0): --> 7e 00 78 f0 7e
> Mon Aug 19 10:11:14 2019 daemon.debug [2086]: <debug>
> [1566209474.872338] (ttyUSB0): <-- 00 4f 63 74 20 32 32 20 32 30 31
> 36 30 39 3a 31 30 3a 30 33 4f 63 74 20 31 33 20 32 30 31 36 30 34 3a
> 30 30 3a 30 30 43 32 32 33 30 30 30 30 3a 06 ff 64 00 02 09 22 a3 95
> 7e
> Mon Aug 19 10:11:14 2019 daemon.debug [2086]: <debug>
> [1566209474.872410] (tty/ttyUSB0) port is QCDM-capable
> Mon Aug 19 10:11:14 2019 daemon.debug [2086]: <debug>
> [1566209474.872447] [plugin manager] task 0,ttyUSB0: found best
> plugin for port (Sierra)
> Mon Aug 19 10:11:14 2019 daemon.debug [2086]: <debug>
> [1566209474.872478] [plugin manager] task 0,ttyUSB0: finished in
> '11.009525' seconds
> Mon Aug 19 10:11:14 2019 daemon.debug [2086]: <debug>
> [1566209474.872510] [plugin manager] task 0,ttyUSB0: best plugin
> matches device reported one: Sierra
> Mon Aug 19 10:11:14 2019 daemon.debug [2086]: <debug>
> [1566209474.872539] [plugin Manager] task 0: still 1 running probes
> (1 active): ttyUSB1
> Mon Aug 19 10:11:14 2019 daemon.debug [2086]: <debug>
> [1566209474.872595] (ttyUSB0) device open count is 0 (close)
> Mon Aug 19 10:11:14 2019 daemon.debug [2086]: <debug>
> [1566209474.872624] (ttyUSB0) closing serial port...
> Mon Aug 19 10:11:14 2019 daemon.debug [2086]: <debug>
> [1566209474.872955] (ttyUSB0) serial port closed
> Mon Aug 19 10:11:14 2019 daemon.debug [2086]: <debug>
> [1566209474.873022] (ttyUSB0) forced to close port
> Mon Aug 19 10:11:17 2019 daemon.debug [2086]: <debug>
> [1566209477.870236] (ttyUSB1): --> 7e 00 78 f0 7e
> Mon Aug 19 10:11:20 2019 daemon.debug [2086]: <debug>
> [1566209480.868659] (tty/ttyUSB1) port is not QCDM-capable
> Mon Aug 19 10:11:20 2019 daemon.debug [2086]: <debug>
> [1566209480.868716] [plugin manager] task 0,ttyUSB1: found best
> plugin for port (Sierra)
> Mon Aug 19 10:11:20 2019 daemon.debug [2086]: <debug>
> [1566209480.868749] [plugin manager] task 0,ttyUSB1: finished in
> '16.971902' seconds
> Mon Aug 19 10:11:20 2019 daemon.debug [2086]: <debug>
> [1566209480.868783] [plugin manager] task 0,ttyUSB1: best plugin
> matches device reported one: Sierra
> Mon Aug 19 10:11:20 2019 daemon.debug [2086]: <debug>
> [1566209480.868811] [plugin manager] task 0: no more ports to probe
> Mon Aug 19 10:11:20 2019 daemon.debug [2086]: <debug>
> [1566209480.868836] [plugin manager] task 0: finished in '17.149826'
> seconds
> 
> Full log is available at: 
> https://drive.google.com/open?id=19DTc_FwKHmiuEB8VMoAczfzxaVsGPUAJ
> 
> Please help
> 
> Thanks in advance
> Amol
> 
> ________________________________
> The information in this email communication (inclusive of
> attachments) is confidential to 4RF Limited and the intended
> recipient(s). If you are not the intended recipient(s), please note
> that any use, disclosure, distribution or copying of this information
> or any part thereof is strictly prohibited and that the author
> accepts no liability for the consequences of any action taken on the
> basis of the information provided. If you have received this email in
> error, please notify the sender immediately by return email and then
> delete all instances of this email from your system. 4RF Limited will
> not accept responsibility for any consequences associated with the
> use of this email (including, but not limited to, damages sustained
> as a result of any viruses and/or any action or lack of action taken
> in reliance on it).
> _______________________________________________
> ModemManager-devel mailing list
> ModemManager-devel at lists.freedesktop.org
> https://lists.freedesktop.org/mailman/listinfo/modemmanager-devel