ofono between 30% and 40% CPU usage when roaming

[Sergio Schvezov]

HARDWARE=maguro
JENKINS_BUILD=153

This is probably the first roaming bug, so may miss some important key elements. What's important about this bug is not that it does not work, but that ofono overuses the CPU due to it. I would consider the former a feature and not a bug for the lack of its implementation.

After booting, depending if in movement or not, this is the minimum I would see with top while sedentary:
  456 root 20 0 5312 1828 1444 R 31.1 0.3 15:27.03 ofonod
  456 root 20 0 5312 1828 1444 R 32.9 0.3 15:33.45 ofonod
  456 root 20 0 5312 1828 1444 R 26.3 0.3 15:36.35 ofonod
  456 root 20 0 5312 1828 1444 R 33.0 0.3 15:39.19 ofonod

The latest messages seen from ofono -d are
Jun 6 09:16:12 ubuntu-phablet ofonod[460]: [235755]< RIL_REQUEST_DATA_REGISTRATION_STATE {5,0067,000a5091,3,(null),(null)}
Jun 6 09:16:12 ubuntu-phablet ofonod[460]: [235756]> RIL_REQUEST_DATA_REGISTRATION_STATE
Jun 6 09:16:12 ubuntu-phablet ofonod[460]: [235756]< RIL_REQUEST_DATA_REGISTRATION_STATE {5,0067,000a5091,3,(null),(null)}
Jun 6 09:16:12 ubuntu-phablet ofonod[460]: [235757]> RIL_REQUEST_DATA_REGISTRATION_STATE
Jun 6 09:16:12 ubuntu-phablet ofonod[460]: [235757]< RIL_REQUEST_DATA_REGISTRATION_STATE {5,0067,000a5091,3,(null),(null)}
Jun 6 09:16:12 ubuntu-phablet ofonod[460]: [235758]> RIL_REQUEST_DATA_REGISTRATION_STATE
Jun 6 09:16:12 ubuntu-phablet ofonod[460]: [235758]< RIL_REQUEST_DATA_REGISTRATION_STATE {5,0067,000a5091,3,(null),(null)}
Jun 6 09:16:12 ubuntu-phablet ofonod[460]: [235759]> RIL_REQUEST_DATA_REGISTRATION_STATE
Jun 6 09:16:12 ubuntu-phablet ofonod[460]: [235759]< RIL_REQUEST_DATA_REGISTRATION_STATE {5,0067,000a5091,3,(null),(null)}
Jun 6 09:16:12 ubuntu-phablet ofonod[460]: [235760]> RIL_REQUEST_DATA_REGISTRATION_STATE

The full logs leading to this can be checked at http://people.canonical.com/~sergiusens/ofono_syslog.gz

Finally, this is the context and modem lists, notice Attached = 0 in this last snapshot
phablet@ubuntu-phablet:~$ /usr/share/ofono/scripts/list-contexts
[ /ril_0 ]
    [ /ril_0/context1 ]
        Username =
        Protocol = ip
        Name = Internet
        Settings = { }
        IPv6.Settings = { }
        Active = 0
        AccessPointName =
        Password =
        Type = internet

    [ /ril_0/context2 ]
        Username =
        Protocol = ip
        Name = Internet
        Settings = { }
        IPv6.Settings = { }
        Active = 0
        AccessPointName = gprs.personal.com
        Password =
        Type = internet

    [ /ril_0/context3 ]
        Username =
        Protocol = ip
        Name = Internet
        Settings = { }
        IPv6.Settings = { }
        Active = 0
        AccessPointName = gprs.personal.com
        Password =
        Type = internet

    [ /ril_0/context4 ]
        Username =
        Protocol = ip
        Name = Internet
        Settings = { }
        IPv6.Settings = { }
        Active = 0
        AccessPointName = gprs.personal.com
        Password =
        Type = internet

phablet@ubuntu-phablet:~$ /usr/share/ofono/scripts/list-modems
[ /ril_0 ]
    Features = sms net gprs sim
    Emergency = 0
    Powered = 1
    Lockdown = 0
    Interfaces = org.ofono.CallVolume org.ofono.SmartMessaging org.ofono.PushNotification org.ofono.MessageManager org.ofono.NetworkRegistration org.ofono.VoiceCallManager org.ofono.ConnectionManager org.ofono.SimManager
    Online = 1
    Model = Fake Modem Model
    Revision = Fake Revision
    Type = hardware
    Serial = THIS-IS-A-FAKE-SERIAL-NO
    Manufacturer = Fake Manufacturer
    [ org.ofono.CallVolume ]
        Muted = 1
        SpeakerVolume = 0
        MicrophoneVolume = 0
    [ org.ofono.SmartMessaging ]
    [ org.ofono.PushNotification ]
    [ org.ofono.MessageManager ]
        Alphabet = default
        UseDeliveryReports = 0
        Bearer = cs-preferred
        ServiceCenterAddress =
    [ org.ofono.NetworkRegistration ]
        Status = roaming
        Strength = 48
        Name = Personal (ANTEL)
        LocationAreaCode = 109
        Mode = auto
        MobileCountryCode = 748
        Technology = umts
        CellId = 1059907
        MobileNetworkCode = 01
    [ org.ofono.VoiceCallManager ]
        EmergencyNumbers = 08 000 999 110 112 911 118 119
    [ org.ofono.ConnectionManager ]
        Powered = 1
        Attached = 0
        Bearer = none
        RoamingAllowed = 0
    [ org.ofono.SimManager ]
        Retries =
        MobileCountryCode = 722
        FixedDialing = 0
        SubscriberNumbers =
        PreferredLanguages = es en pt it
        BarredDialing = 0
        ServiceNumbers = [Personal] = '+810' [Club Personal] = '*2582' [At. Clientes] = '*111' [Llam. a su Cargo] = '1111111111'
        CardIdentifier = 89543421211145542111
        LockedPins =
        MobileNetworkCode = 34
        SubscriberIdentity = 722341214554211
        Present = 1
        PinRequired = none

[Sergio Schvezov (sergiusens)]

Setting roaming to allowed
/usr/share/ofono/scripts/set-roaming-allowed 1

set the modem to attached and brought the cpu down.

[Sergio Schvezov (sergiusens)]

After doing
/usr/share/ofono/scripts/set-roaming-allowed 1

The modem is now attached
/usr/share/ofono/scripts/list-modems
[ /ril_0 ]
    Features = sms net gprs sim
    Emergency = 0
    Powered = 1
    Lockdown = 0
    Interfaces = org.ofono.CallVolume org.ofono.SmartMessaging org.ofono.PushNotification org.ofono.MessageManager org.ofono.NetworkRegistration org.ofono.VoiceCallManager org.ofono.ConnectionManager org.ofono.SimManager
    Online = 1
    Model = Fake Modem Model
    Revision = Fake Revision
    Type = hardware
    Serial = THIS-IS-A-FAKE-SERIAL-NO
    Manufacturer = Fake Manufacturer
    [ org.ofono.CallVolume ]
        Muted = 1
        SpeakerVolume = 0
        MicrophoneVolume = 0
    [ org.ofono.SmartMessaging ]
    [ org.ofono.PushNotification ]
    [ org.ofono.MessageManager ]
        Alphabet = default
        UseDeliveryReports = 0
        Bearer = cs-preferred
        ServiceCenterAddress =
    [ org.ofono.NetworkRegistration ]
        Status = roaming
        Strength = 83
        Name = Personal (ANTEL)
        LocationAreaCode = 109
        Mode = auto
        MobileCountryCode = 748
        Technology = umts
        CellId = 1078772
        MobileNetworkCode = 01
    [ org.ofono.VoiceCallManager ]
        EmergencyNumbers = 08 000 999 110 112 911 118 119
    [ org.ofono.ConnectionManager ]
        Powered = 1
        Attached = 1
        Bearer = none
        Suspended = 0
        RoamingAllowed = 1
    [ org.ofono.SimManager ]
        Retries =
        MobileCountryCode = 722
        FixedDialing = 0
        SubscriberNumbers =
        PreferredLanguages = es en pt it
        BarredDialing = 0
        ServiceNumbers = [Personal] = '+810' [Club Personal] = '*2582' [At. Clientes] = '*111' [Llam. a su Cargo] = '1111111111'
        CardIdentifier = 89543421211145542111
        LockedPins =
        MobileNetworkCode = 34
        SubscriberIdentity = 722341214554211
        Present = 1
        PinRequired = none

[Sergio Schvezov (sergiusens)]

phablet@ubuntu-phablet:~$ nmcli con up id Personal
phablet@ubuntu-phablet:~$ nmcli d
DEVICE TYPE STATE
/ril_0 gsm connected
wlan0 802-11-wireless disconnected
phablet@ubuntu-phablet:~$ netstat -rn
Kernel IP routing table
Destination Gateway Genmask Flags MSS Window irtt Iface
0.0.0.0 0.0.0.0 0.0.0.0 U 0 0 0 rmnet0
181.4.218.0 0.0.0.0 255.255.255.0 U 0 0 0 rmnet0
phablet@ubuntu-phablet:~$ ping www.google.com
PING www.google.com (181.15.96.25) 56(84) bytes of data.
64 bytes from host25.181-15-96.telecom.net.ar (181.15.96.25): icmp_req=1 ttl=55 time=94.2 ms
64 bytes from host25.181-15-96.telecom.net.ar (181.15.96.25): icmp_req=2 ttl=55 time=71.8 ms
^C
--- www.google.com ping statistics ---
2 packets transmitted, 2 received, 0% packet loss, time 1001ms
rtt min/avg/max/mdev = 71.802/83.027/94.252/11.225 ms

[Tony Espy (awe)]

@Sergio

Here's a test version of ofono with improved logging.

First, can you re-run your scenario both with, and without the "-d" switch with the roaming flag disabled. I'd like to see whether or not the CPU usage is due to the logging. It seems that when roaming, an excessive number of VOICE_NETWORK_STATE_CHANGED events are processed, and these in turn result in multiple requests to the RIL.

One trick to keeping the logs small when you do this is to delete the syslog in between reboots. Another alternative is to drop an ofono.override containing the keyword "manual" into /etc/init, then use the script command to capture the output of ofono run as a foreground process ( be sure to specify "-n" to prevent ofonod from becoming a daemon ).

[Tiago Salem Herrmann (tiagosh)]

Hi,

I ran the following command and got the attached logs.
/usr/share/ofono/scripts/set-roaming-allowed 0

Looks like syslog is being flooded with RIL_REQUEST_DATA_REGISTRATION_STATE messages.

[Tiago Salem Herrmann (tiagosh)]

Either with or without -d the ofonod cpu usage remains the same.

10% ofonod
15% rild

Once I set roaming to "enabled", the cpu usage of both are back to 0%.

[Tony Espy (awe)]

Just a quick update...

I'm actually working on this bug now, and should not have left the Status as "InProgress" for so long without an update.

The first issue is that we're definitely sending more REQUEST_DATA_REGISTRATION_STATE requests than necessary. This is due to the fact that both the network-registration and gprs rilmodem code cause these requests to be sent to RILD ( the former through a core netreg_watch by the core ofono gprs code ).

I also think there's further room for reduction, but need to play around with the code some more.

Hopefully I'll have a test package available soon ( maybe tomorrow ).

[Sergio Schvezov (sergiusens)]

Sounds good, I am in no place where I can trigger this easily now, but
I'm betting Tiago could

On Tue, Jul 9, 2013 at 10:25 PM, Tony Espy <email address hidden> wrote:
> Just a quick update...
>
> I'm actually working on this bug now, and should not have left the
> Status as "InProgress" for so long without an update.
>
> The first issue is that we're definitely sending more
> REQUEST_DATA_REGISTRATION_STATE requests than necessary. This is due
> to the fact that both the network-registration and gprs rilmodem code
> cause these requests to be sent to RILD ( the former through a core
> netreg_watch by the core ofono gprs code ).
>
> I also think there's further room for reduction, but need to play around
> with the code some more.
>
> Hopefully I'll have a test package available soon ( maybe tomorrow ).
>
> --
> You received this bug notification because you are subscribed to the bug
> report.
> https://bugs.launchpad.net/bugs/1188404
>
> Title:
> ofono between 30% and 40% CPU usage when roaming
>
> To manage notifications about this bug go to:
> https://bugs.launchpad.net/touch-preview-images/+bug/1188404/+subscriptions

[Tiago Salem Herrmann (tiagosh)]

Sure, I can test it.

[Tony Espy (awe)]

I have a preliminary fix which appears to work.

The problem was caused by a tight loop n the GPRS code where the callback for a RIL_REQ_DATA_REGISTRATION_STATE called back into the ofono core gprs code, and basically triggered another REQ_DATA_REGISTRATION_STATE, ...

See the attached branch.

[Tiago Salem Herrmann (tiagosh)]

I can confirm the linked branch fixes the problem.

[Martin Pitt (pitti)]

WFM as well, see my comment on the MP: https://code.launchpad.net/~awe/phablet-extras/ofono-lp1188404/+merge/174516/comments/393721