Re: Modemmanager significant startup delay
Hey! On Mon, Aug 26, 2019 at 5:14 AM Amol Lad wrote: > > Same here. Paul's rules brought the ModemManager start-up delay to almost nil! > I've pushed a MR to get these port type hints included in the release, review/tests welcome: https://gitlab.freedesktop.org/mobile-broadband/ModemManager/merge_requests/141 -- Aleksander https://aleksander.es ___ ModemManager-devel mailing list ModemManager-devel@lists.freedesktop.org https://lists.freedesktop.org/mailman/listinfo/modemmanager-devel
RE: Modemmanager significant startup delay
Same here. Paul's rules brought the ModemManager start-up delay to almost nil! 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).-Original Message- From: Nick Sent: Monday, 26 August 2019 3:47 AM To: Aleksander Morgado Cc: Paul Bartell ; modemmanager-devel@lists.freedesktop.org; Amol Lad Subject: Re: Modemmanager significant startup delay Hey, FWIW, Testing Paul’s rules on my MC7430 and ModemManager starts up the connection noticeably faster, shaves off about 20 seconds for me. I haven’t cleaned up the rules per Aleksander’s suggestions yet. Best, Nick ___ ModemManager-devel mailing list ModemManager-devel@lists.freedesktop.org https://lists.freedesktop.org/mailman/listinfo/modemmanager-devel
Re: Modemmanager significant startup delay
Hey, FWIW, Testing Paul’s rules on my MC7430 and ModemManager starts up the connection noticeably faster, shaves off about 20 seconds for me. I haven’t cleaned up the rules per Aleksander’s suggestions yet. Best, Nick ___ ModemManager-devel mailing list ModemManager-devel@lists.freedesktop.org https://lists.freedesktop.org/mailman/listinfo/modemmanager-devel
Re: Modemmanager significant startup delay
On Thu, Aug 22, 2019 at 11:06 AM Bjørn Mork wrote: > > Dan Williams writes: > > On Wed, 2019-08-21 at 12:23 +, 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. > > Not prepared to write the code, so I should probably not make > suggestions... But do anyway ;-) > > How about caching protocol probe results and skipping the full probe if > a match is found? > > Keying the cached data and knowing when to ignore the cache is probably > the hard part. But I believe there is a lot to gain for normal use > cases. Most people don't use lots of modems. Many systems will have > the same modem connected to the same port for extended periods. Some > system designs cause the MM probing to run very often, "always" > returning the same result. Looking at my laptop for example: It turns > off power to the internal wwan slot on suspend. So MM must probe the > modem on every resume, causing a significant delay from the system > appears to be up until the network is up again. > > The protocol probes are obviously a waste of time in this case. Unless I > am messing with drivers or descriptors :-) But that's easy to detect. > You could just ignore the protocol cache if any of the udev data > changed. It would still be a large win for most cases. > I like this idea very much! I've opened a new issue to track this: https://gitlab.freedesktop.org/mobile-broadband/ModemManager/issues/142 -- Aleksander https://aleksander.es ___ ModemManager-devel mailing list ModemManager-devel@lists.freedesktop.org https://lists.freedesktop.org/mailman/listinfo/modemmanager-devel
Re: Modemmanager significant startup delay
Hey all,
From Paul's email, the port type hints for the TTYs exposed by the
MC74xx could help make the probing much faster. I haven't tested them
myself, but we could definitely add them in the release.
# MC74XX: Add port hints
# if 03: primary port
# if 02: raw NMEA port
# if 00: diag/qcdm port
ATTRS{idVendor}=="1199", ATTRS{idProduct}=="9071",
ENV{.MM_USBIFNUM}=="03", ENV{ID_MM_PORT_TYPE_AT_PRIMARY}="1"
ATTRS{idVendor}=="1199", ATTRS{idProduct}=="9071",
ENV{.MM_USBIFNUM}=="02", ENV{ID_MM_PORT_TYPE_GPS}="1"
ATTRS{idVendor}=="1199", ATTRS{idProduct}=="9071",
ENV{.MM_USBIFNUM}=="00", ENV{ID_MM_PORT_TYPE_QCDM}="1"
This rule is not required because (FOR NOW) ID_MM_DEVICE_IGNORE
applies exclusively to TTYs, which is something I'd like to change in
the next release (there's an open MR to do that):
# MC74XX: Ignore "wwan0" net interface
ATTRS{idVendor}=="1199", ATTRS{idProduct}=="9071",
ENV{.MM_USBIFNUM}=="08", ENV{ID_MM_DEVICE_IGNORE}="1"
And this one should also not be required, as there are other generic
built-in rules to ignore the device in QDL mode:
# MC74XX: ignore QDL port
ATTRS{idVendor}=="1199", ATTRS{idProduct}=="9070", ENV{ID_MM_DEVICE_IGNORE}="1"
On Wed, Aug 21, 2019 at 9:20 PM Paul Bartell wrote:
>
> Amol,
>
> Try this 77-mm-sierra.rules udev rules file with port type hints for
> Sierra MDM9x30 chipset modems.
>
> Thanks,
> Paul
>
> On Wed, Aug 21, 2019 at 5:23 AM Amol Lad wrote:
> >
> > Please help with this. What could be the cause of significant MM startup
> > delay?
> >
> >
> >
> > From: ModemManager-devel
> > On Behalf Of Amol Lad
> > Sent: Monday, 19 August 2019 4:05 PM
> > To: modemmanager-devel@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]: [1566209465.535657]
> > (ttyUSB2): <-- ''
> >
> > Mon Aug 19 10:11:05 2019 daemon.debug [2086]: [1566209465.535956]
> > (ttyUSB2): <-- 'OK'
> >
> > Mon Aug 19 10:11:05 2019 daemon.debug [2086]: [1566209465.536110]
> > (tty/ttyUSB2) port is AT-capable
> >
> > Mon Aug 19 10:11:05 2019 daemon.debug [2086]: [1566209465.536188]
> > [plugin manager] task 0,ttyUSB2: found best plugin for port (Sierra)
> >
> > Mon Aug 19 10:11:05 2019 daemon.debug [2086]: [1566209465.536269]
> > [plugin manager] task 0,ttyUSB2: finished in '1.604063' seconds
> >
> > Mon Aug 19 10:11:05 2019 daemon.debug [2086]: [1566209465.536348]
> > [plugin manager] task 0,ttyUSB2: best plugin matches device reported one:
> > Sierra
> >
> > Mon Aug 19 10:11:05 2019 daemon.debug [2086]: [1566209465.536433]
> > [plugin Manager] task 0: still 2 running probes (2 active): ttyUSB1, ttyUSB0
> >
> > Mon Aug 19 10:11:05 2019 daemon.debug [2086]: [1566209465.536565]
> > (ttyUSB2) device open count is 0 (close)
> >
> > Mon Aug 19 10:11:05 2019 daemon.debug [2086]: [1566209465.536702]
> > (ttyUSB2) closing
> >
> > port...
> >
> > Mon Aug 19 10:11:05 2019 daemon.debug [2086]: [1566209465.537143]
> > (ttyUSB2) serial port closed
> >
> > Mon Aug 19 10:11:05 2019 daemon.debug [2086]: [1566209465.537304]
> > (ttyUSB2) forced to close port
> >
> > Mon Aug 19 10:11:06 2019 daemon.debug [2086]: [1566209466.220126]
> > [plugin manager] task 0: min probing time elapsed
> >
> > Mon Aug 19 10:11:06 2019 daemon.debug [2086]: [1566209466.220187]
> > [plugin Manager] task 0: still 2 running probes (2 active): ttyUSB1, ttyUSB0
&g
Re: Modemmanager significant startup delay
Dan Williams writes: > On Wed, 2019-08-21 at 12:23 +, 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. Not prepared to write the code, so I should probably not make suggestions... But do anyway ;-) How about caching protocol probe results and skipping the full probe if a match is found? Keying the cached data and knowing when to ignore the cache is probably the hard part. But I believe there is a lot to gain for normal use cases. Most people don't use lots of modems. Many systems will have the same modem connected to the same port for extended periods. Some system designs cause the MM probing to run very often, "always" returning the same result. Looking at my laptop for example: It turns off power to the internal wwan slot on suspend. So MM must probe the modem on every resume, causing a significant delay from the system appears to be up until the network is up again. The protocol probes are obviously a waste of time in this case. Unless I am messing with drivers or descriptors :-) But that's easy to detect. You could just ignore the protocol cache if any of the udev data changed. It would still be a large win for most cases. Bjørn ___ ModemManager-devel mailing list ModemManager-devel@lists.freedesktop.org https://lists.freedesktop.org/mailman/listinfo/modemmanager-devel
Re: Modemmanager significant startup delay
On Wed, 2019-08-21 at 12:23 +, 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-boun...@lists.freedesktop.org> On Behalf Of Amol > Lad > Sent: Monday, 19 August 2019 4:05 PM > To: modemmanager-devel@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]: > [1566209465.535657] (ttyUSB2): <-- '' > Mon Aug 19 10:11:05 2019 daemon.debug [2086]: > [1566209465.535956] (ttyUSB2): <-- 'OK' > Mon Aug 19 10:11:05 2019 daemon.debug [2086]: > [1566209465.536110] (tty/ttyUSB2) port is AT-capable > Mon Aug 19 10:11:05 2019 daemon.debug [2086]: > [1566209465.536188] [plugin manager] task 0,ttyUSB2: found best > plugin for port (Sierra) > Mon Aug 19 10:11:05 2019 daemon.debug [2086]: > [1566209465.536269] [plugin manager] task 0,ttyUSB2: finished in > '1.604063' seconds > Mon Aug 19 10:11:05 2019 daemon.debug [2086]: > [1566209465.536348] [plugin manager] task 0,ttyUSB2: best plugin > matches device reported one: Sierra > Mon Aug 19 10:11:05 2019 daemon.debug [2086]: > [1566209465.536433] [plugin Manager] task 0: still 2 running probes > (2 active): ttyUSB1, ttyUSB0 > Mon Aug 19 10:11:05 2019 daemon.debug [2086]: > [1566209465.536565] (ttyUSB2) device open count is 0 (close) > Mon Aug 19 10:11:05 2019 daemon.debug [2086]: > [1566209465.536702] (ttyUSB2) closing > port... > Mon Aug 19 10:11:05 2019 daemon.debug [2086]: > [1566209465.537143] (ttyUSB2) serial port closed > Mon Aug 19 10:11:05 2019 daemon.debug [2086]: > [1566209465.537304] (ttyUSB2) forced to close port > Mon Aug 19 10:11:06 2019 daemon.debug [2086]: > [1566209466.220126] [plugin manager] task 0: min probing time elapsed > Mon Aug 19 10:11:06 2019 daemon.debug [2086]: > [1566209466.220187] [plugin Manager] task 0: still 2 running probes > (2 active): ttyUSB1, ttyUSB0 > Mon Aug 19 10:11:08 2019 daemon.debug [2086]: > [1566209468.868113] Parsing AT got: 'Serial command timed out' > Mon Aug 19 10:11:08 2019 daemon.debug [2086]: > [1566209468.868197] Parsing AT got: 'Serial command timed out' > Mon Aug 19 10:11:08 2019 daemon.debug [2086]: > [1566209468.868282] (ttyUSB1): --> 'AT' > Mon Aug 19 10:11:08 2019 daemon.debug [2086]: > [1566209468.868351] (ttyUSB0): --> 'AT' > Mon Aug 19 10:11:11 2019 daemon.debug [2086]: > [1566209471.869749] Parsing AT got: 'Serial command timed out' > Mon Aug 19 10:11:11 2019 daemon.debug [2086]: > [1566209471.869831] Parsing AT got: 'Serial command timed out' > Mon Aug 19 10:11:11 2019 daemon.debug [2086]: > [1566209471.869917] (ttyUSB1): --> 'AT' > Mon Aug 19 10:11:11 2019 daemon.debug [2086]: > [1566209471.869984] (ttyUSB0): --> 'AT' > Mon Aug 19 10:11:14 2019 daemon.debug [2086]: > [1566209474.869689] Parsing AT got: 'Serial command timed out' > Mon Aug 19 10:11:14 2019 daemon.debug [2086]: > [1566209474.869745] (tty/ttyUSB1) port is not AT-capable > Mon Aug 19 10:11:14 2019 daemon.debug [2086]: > [1566209474.869806] Parsing AT got: 'Serial command timed out' > Mon Aug 19 10:11:14 2019 daemon.debug [2086]: > [1566209474.869834] (tty/ttyUSB0) port is not AT-capable > Mon Aug 19 10:11:14 2019 daemon.debug [2086]: > [1566209474.869884] (tty/ttyUSB1) probing QCDM... > Mon Aug 19 10:11:14 2019 daemon.debug [2086]: > [1566209474.869916] (ttyUSB1) device open count is 0 (close) > Mon Aug 19 10:11:14 2019
Re: Modemmanager significant startup delay
Amol, Try this 77-mm-sierra.rules udev rules file with port type hints for Sierra MDM9x30 chipset modems. Thanks, Paul On Wed, Aug 21, 2019 at 5:23 AM Amol Lad wrote: > > Please help with this. What could be the cause of significant MM startup > delay? > > > > From: ModemManager-devel > On Behalf Of Amol Lad > Sent: Monday, 19 August 2019 4:05 PM > To: modemmanager-devel@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]: [1566209465.535657] > (ttyUSB2): <-- '' > > Mon Aug 19 10:11:05 2019 daemon.debug [2086]: [1566209465.535956] > (ttyUSB2): <-- 'OK' > > Mon Aug 19 10:11:05 2019 daemon.debug [2086]: [1566209465.536110] > (tty/ttyUSB2) port is AT-capable > > Mon Aug 19 10:11:05 2019 daemon.debug [2086]: [1566209465.536188] > [plugin manager] task 0,ttyUSB2: found best plugin for port (Sierra) > > Mon Aug 19 10:11:05 2019 daemon.debug [2086]: [1566209465.536269] > [plugin manager] task 0,ttyUSB2: finished in '1.604063' seconds > > Mon Aug 19 10:11:05 2019 daemon.debug [2086]: [1566209465.536348] > [plugin manager] task 0,ttyUSB2: best plugin matches device reported one: > Sierra > > Mon Aug 19 10:11:05 2019 daemon.debug [2086]: [1566209465.536433] > [plugin Manager] task 0: still 2 running probes (2 active): ttyUSB1, ttyUSB0 > > Mon Aug 19 10:11:05 2019 daemon.debug [2086]: [1566209465.536565] > (ttyUSB2) device open count is 0 (close) > > Mon Aug 19 10:11:05 2019 daemon.debug [2086]: [1566209465.536702] > (ttyUSB2) closing > > port... > > Mon Aug 19 10:11:05 2019 daemon.debug [2086]: [1566209465.537143] > (ttyUSB2) serial port closed > > Mon Aug 19 10:11:05 2019 daemon.debug [2086]: [1566209465.537304] > (ttyUSB2) forced to close port > > Mon Aug 19 10:11:06 2019 daemon.debug [2086]: [1566209466.220126] > [plugin manager] task 0: min probing time elapsed > > Mon Aug 19 10:11:06 2019 daemon.debug [2086]: [1566209466.220187] > [plugin Manager] task 0: still 2 running probes (2 active): ttyUSB1, ttyUSB0 > > Mon Aug 19 10:11:08 2019 daemon.debug [2086]: [1566209468.868113] > Parsing AT got: 'Serial command timed out' > > Mon Aug 19 10:11:08 2019 daemon.debug [2086]: [1566209468.868197] > Parsing AT got: 'Serial command timed out' > > Mon Aug 19 10:11:08 2019 daemon.debug [2086]: [1566209468.868282] > (ttyUSB1): --> 'AT' > > Mon Aug 19 10:11:08 2019 daemon.debug [2086]: [1566209468.868351] > (ttyUSB0): --> 'AT' > > Mon Aug 19 10:11:11 2019 daemon.debug [2086]: [1566209471.869749] > Parsing AT got: 'Serial command timed out' > > Mon Aug 19 10:11:11 2019 daemon.debug [2086]: [1566209471.869831] > Parsing AT got: 'Serial command timed out' > > Mon Aug 19 10:11:11 2019 daemon.debug [2086]: [1566209471.869917] > (ttyUSB1): --> 'AT' > > Mon Aug 19 10:11:11 2019 daemon.debug [2086]: [1566209471.869984] > (ttyUSB0): --> 'AT' > > Mon Aug 19 10:11:14 2019 daemon.debug [2086]: [1566209474.869689] > Parsing AT got: 'Serial command timed out' > > Mon Aug 19 10:11:14 2019 daemon.debug [2086]: [1566209474.869745] > (tty/ttyUSB1) port is not AT-capable > > Mon Aug 19 10:11:14 2019 daemon.debug [2086]: [1566209474.869806] > Parsing AT got: 'Serial command timed out' > > Mon Aug 19 10:11:14 2019 daemon.debug [2086]: [1566209474.869834] > (tty/ttyUSB0) port is not AT-capable > > Mon Aug 19 10:11:14 2019 daemon.debug [2086]: [1566209474.869884] > (tty/ttyUSB1) probing QCDM... > > Mon Aug 19 10:11:14 2019 daemon.debug [2086]: [1566209474.869916] > (ttyUSB1) device open count is 0 (close) > > Mon Aug 19 10:11:14 2019 daemon.debug [2086]: [1566209474.869943] > (ttyUSB1) closing serial port... > > Mon Aug 19 10:11:14 2019 daemon
RE: Modemmanager significant startup delay
Please help with this. What could be the cause of significant MM startup delay? From: ModemManager-devel On Behalf Of Amol Lad Sent: Monday, 19 August 2019 4:05 PM To: modemmanager-devel@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]: [1566209465.535657] (ttyUSB2): <-- '' Mon Aug 19 10:11:05 2019 daemon.debug [2086]: [1566209465.535956] (ttyUSB2): <-- 'OK' Mon Aug 19 10:11:05 2019 daemon.debug [2086]: [1566209465.536110] (tty/ttyUSB2) port is AT-capable Mon Aug 19 10:11:05 2019 daemon.debug [2086]: [1566209465.536188] [plugin manager] task 0,ttyUSB2: found best plugin for port (Sierra) Mon Aug 19 10:11:05 2019 daemon.debug [2086]: [1566209465.536269] [plugin manager] task 0,ttyUSB2: finished in '1.604063' seconds Mon Aug 19 10:11:05 2019 daemon.debug [2086]: [1566209465.536348] [plugin manager] task 0,ttyUSB2: best plugin matches device reported one: Sierra Mon Aug 19 10:11:05 2019 daemon.debug [2086]: [1566209465.536433] [plugin Manager] task 0: still 2 running probes (2 active): ttyUSB1, ttyUSB0 Mon Aug 19 10:11:05 2019 daemon.debug [2086]: [1566209465.536565] (ttyUSB2) device open count is 0 (close) Mon Aug 19 10:11:05 2019 daemon.debug [2086]: [1566209465.536702] (ttyUSB2) closing port... Mon Aug 19 10:11:05 2019 daemon.debug [2086]: [1566209465.537143] (ttyUSB2) serial port closed Mon Aug 19 10:11:05 2019 daemon.debug [2086]: [1566209465.537304] (ttyUSB2) forced to close port Mon Aug 19 10:11:06 2019 daemon.debug [2086]: [1566209466.220126] [plugin manager] task 0: min probing time elapsed Mon Aug 19 10:11:06 2019 daemon.debug [2086]: [1566209466.220187] [plugin Manager] task 0: still 2 running probes (2 active): ttyUSB1, ttyUSB0 Mon Aug 19 10:11:08 2019 daemon.debug [2086]: [1566209468.868113] Parsing AT got: 'Serial command timed out' Mon Aug 19 10:11:08 2019 daemon.debug [2086]: [1566209468.868197] Parsing AT got: 'Serial command timed out' Mon Aug 19 10:11:08 2019 daemon.debug [2086]: [1566209468.868282] (ttyUSB1): --> 'AT' Mon Aug 19 10:11:08 2019 daemon.debug [2086]: [1566209468.868351] (ttyUSB0): --> 'AT' Mon Aug 19 10:11:11 2019 daemon.debug [2086]: [1566209471.869749] Parsing AT got: 'Serial command timed out' Mon Aug 19 10:11:11 2019 daemon.debug [2086]: [1566209471.869831] Parsing AT got: 'Serial command timed out' Mon Aug 19 10:11:11 2019 daemon.debug [2086]: [1566209471.869917] (ttyUSB1): --> 'AT' Mon Aug 19 10:11:11 2019 daemon.debug [2086]: [1566209471.869984] (ttyUSB0): --> 'AT' Mon Aug 19 10:11:14 2019 daemon.debug [2086]: [1566209474.869689] Parsing AT got: 'Serial command timed out' Mon Aug 19 10:11:14 2019 daemon.debug [2086]: [1566209474.869745] (tty/ttyUSB1) port is not AT-capable Mon Aug 19 10:11:14 2019 daemon.debug [2086]: [1566209474.869806] Parsing AT got: 'Serial command timed out' Mon Aug 19 10:11:14 2019 daemon.debug [2086]: [1566209474.869834] (tty/ttyUSB0) port is not AT-capable Mon Aug 19 10:11:14 2019 daemon.debug [2086]: [1566209474.869884] (tty/ttyUSB1) probing QCDM... Mon Aug 19 10:11:14 2019 daemon.debug [2086]: [1566209474.869916] (ttyUSB1) device open count is 0 (close) Mon Aug 19 10:11:14 2019 daemon.debug [2086]: [1566209474.869943] (ttyUSB1) closing serial port... Mon Aug 19 10:11:14 2019 daemon.debug [2086]: [1566209474.870349] (ttyUSB1) serial port closed Mon Aug 19 10:11:14 2019 daemon.debug [2086]: [1566209474.870415] (ttyUSB1) forced to close port Mon Aug 19 10:11:14 2019 daemon.debug [2086]: [1566209474.870517] (ttyUSB1) opening serial port... Mon Aug 19 10:11:14 2019 daemon.debug [2086]: [1566209474.870779] (ttyUSB1) device open count is 1 (open) Mon Aug 19 10:11:14 2019 daemon.debug [2086]: [1566209474.870851] (tty/ttyUSB0) probing QCDM... Mon Aug 19 10:11:14 2019 daemon.debug [2086]: [1566209474.870886] (ttyUSB0) device open count is 0 (close) Mon Aug 19 10:11:14 2019 daemon.debug [2086]: [1566209474.870913] (ttyUSB0) closing serial port... Mon Aug 19 10:11:14 2019 daemon.debug [2086]: [1566209474.871138] (ttyUSB0) serial port
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]: [1566209465.535657] (ttyUSB2): <-- '' Mon Aug 19 10:11:05 2019 daemon.debug [2086]: [1566209465.535956] (ttyUSB2): <-- 'OK' Mon Aug 19 10:11:05 2019 daemon.debug [2086]: [1566209465.536110] (tty/ttyUSB2) port is AT-capable Mon Aug 19 10:11:05 2019 daemon.debug [2086]: [1566209465.536188] [plugin manager] task 0,ttyUSB2: found best plugin for port (Sierra) Mon Aug 19 10:11:05 2019 daemon.debug [2086]: [1566209465.536269] [plugin manager] task 0,ttyUSB2: finished in '1.604063' seconds Mon Aug 19 10:11:05 2019 daemon.debug [2086]: [1566209465.536348] [plugin manager] task 0,ttyUSB2: best plugin matches device reported one: Sierra Mon Aug 19 10:11:05 2019 daemon.debug [2086]: [1566209465.536433] [plugin Manager] task 0: still 2 running probes (2 active): ttyUSB1, ttyUSB0 Mon Aug 19 10:11:05 2019 daemon.debug [2086]: [1566209465.536565] (ttyUSB2) device open count is 0 (close) Mon Aug 19 10:11:05 2019 daemon.debug [2086]: [1566209465.536702] (ttyUSB2) closing port... Mon Aug 19 10:11:05 2019 daemon.debug [2086]: [1566209465.537143] (ttyUSB2) serial port closed Mon Aug 19 10:11:05 2019 daemon.debug [2086]: [1566209465.537304] (ttyUSB2) forced to close port Mon Aug 19 10:11:06 2019 daemon.debug [2086]: [1566209466.220126] [plugin manager] task 0: min probing time elapsed Mon Aug 19 10:11:06 2019 daemon.debug [2086]: [1566209466.220187] [plugin Manager] task 0: still 2 running probes (2 active): ttyUSB1, ttyUSB0 Mon Aug 19 10:11:08 2019 daemon.debug [2086]: [1566209468.868113] Parsing AT got: 'Serial command timed out' Mon Aug 19 10:11:08 2019 daemon.debug [2086]: [1566209468.868197] Parsing AT got: 'Serial command timed out' Mon Aug 19 10:11:08 2019 daemon.debug [2086]: [1566209468.868282] (ttyUSB1): --> 'AT' Mon Aug 19 10:11:08 2019 daemon.debug [2086]: [1566209468.868351] (ttyUSB0): --> 'AT' Mon Aug 19 10:11:11 2019 daemon.debug [2086]: [1566209471.869749] Parsing AT got: 'Serial command timed out' Mon Aug 19 10:11:11 2019 daemon.debug [2086]: [1566209471.869831] Parsing AT got: 'Serial command timed out' Mon Aug 19 10:11:11 2019 daemon.debug [2086]: [1566209471.869917] (ttyUSB1): --> 'AT' Mon Aug 19 10:11:11 2019 daemon.debug [2086]: [1566209471.869984] (ttyUSB0): --> 'AT' Mon Aug 19 10:11:14 2019 daemon.debug [2086]: [1566209474.869689] Parsing AT got: 'Serial command timed out' Mon Aug 19 10:11:14 2019 daemon.debug [2086]: [1566209474.869745] (tty/ttyUSB1) port is not AT-capable Mon Aug 19 10:11:14 2019 daemon.debug [2086]: [1566209474.869806] Parsing AT got: 'Serial command timed out' Mon Aug 19 10:11:14 2019 daemon.debug [2086]: [1566209474.869834] (tty/ttyUSB0) port is not AT-capable Mon Aug 19 10:11:14 2019 daemon.debug [2086]: [1566209474.869884] (tty/ttyUSB1) probing QCDM... Mon Aug 19 10:11:14 2019 daemon.debug [2086]: [1566209474.869916] (ttyUSB1) device open count is 0 (close) Mon Aug 19 10:11:14 2019 daemon.debug [2086]: [1566209474.869943] (ttyUSB1) closing serial port... Mon Aug 19 10:11:14 2019 daemon.debug [2086]: [1566209474.870349] (ttyUSB1) serial port closed Mon Aug 19 10:11:14 2019 daemon.debug [2086]: [1566209474.870415] (ttyUSB1) forced to close port Mon Aug 19 10:11:14 2019 daemon.debug [2086]: [1566209474.870517] (ttyUSB1) opening serial port... Mon Aug 19 10:11:14 2019 daemon.debug [2086]: [1566209474.870779] (ttyUSB1) device open count is 1 (open) Mon Aug 19 10:11:14 2019 daemon.debug [2086]: [1566209474.870851] (tty/ttyUSB0) probing QCDM... Mon Aug 19 10:11:14 2019 daemon.debug [2086]: [1566209474.870886] (ttyUSB0) device open count is 0 (close) Mon Aug 19 10:11:14 2019 daemon.debug [2086]: [1566209474.870913] (ttyUSB0) closing serial port... Mon Aug 19 10:11:14 2019 daemon.debug [2086]: [1566209474.871138] (ttyUSB0) serial port closed Mon Aug 19 10:11:14 2019 daemon.debug [2086]: [1566209474.871196] (ttyUSB0) forced to close port Mon Aug 19 10:11:14 2019 daemon.debug [2086]: [1566209474.871261] (ttyUSB0) opening serial port... Mon Aug 19 10:11:14 2019 daemon.debug [2086]: [1566209474.871351] (ttyUSB0) device open count is 1 (open) Mon Aug 19 10:11:14 2019 daemon.debug [2086]: [1566209474.871423] (ttyUSB1): --> 7e 00 78 f0 7e Mon Aug 19 10:11:14 2019 daemon.debug [2086]: [156620
