1055316 - [Gecko][Flame][I/O] Connect backoff scheme broken, causing NFC to hog CPU on KK

Status: RESOLVED FIXED

(Firefox OS Graveyard :: Runtime, defect)

Description

[Andrew Osmond [:aosmond] (he/him)]

On Flame KK v165 with a b2g-inbound gecko/gaia, b2g is constantly spinning causing device slowdowns.

root@flame:/ # top -m 5 -t

User 38%, System 39%, IOW 0%, IRQ 0%
User 234 + Nice 0 + Sys 240 + Idle 134 + IOW 0 + IRQ 0 + SIRQ 0 = 608

  PID   TID PR CPU% S     VSS     RSS PCY UID      Thread          Proc
  207   501  0  44% R 176188K  83804K     root     Gecko_IOThread  /system/b2g/b2g
  207   207  0  32% R 176188K  83804K     root     b2g             /system/b2g/b2g
 1119  1119  1   1% R   1376K    620K     root     top             top
   98    98  1   0% S      0K      0K     root     ksmd            
   12    12  1   0% S      0K      0K     root     ksoftirqd/1

The adb log shows this is because of a connect/disconnected cycle where it is not backing off at all:

08-18 18:37:49.459   207   207 I Gonk    : NFC: OnConnectError
08-18 18:37:49.459   207   207 I Gonk    : NFC: OnDisconnect
08-18 18:37:49.459   207   501 I Gecko   : [Parent 207] WARNING: 'NS_FAILED(rv)', file ../../../../B2G_HG/b2g-inbound/ipc/unixsocket/UnixSocket.cpp, line 287
08-18 18:37:49.459   207   501 I Gecko   : [Parent 207] WARNING: '!IsOpen()', file ../../../../B2G_HG/b2g-inbound/ipc/unixfd/UnixFdWatcher.cpp, line 36
08-18 18:37:49.459   207   501 I I/O     : connect failed with error 2 (No such file or directory)
08-18 18:37:49.459   207   207 I Gonk    : NFC: OnConnectError
08-18 18:37:49.459   207   207 I Gonk    : NFC: OnDisconnect
08-18 18:37:49.459   207   501 I Gecko   : [Parent 207] WARNING: 'NS_FAILED(rv)', file ../../../../B2G_HG/b2g-inbound/ipc/unixsocket/UnixSocket.cpp, line 287
08-18 18:37:49.459   207   501 I Gecko   : [Parent 207] WARNING: '!IsOpen()', file ../../../../B2G_HG/b2g-inbound/ipc/unixfd/UnixFdWatcher.cpp, line 36
08-18 18:37:49.459   207   501 I I/O     : connect failed with error 2 (No such file or directory)
08-18 18:37:49.459   207   207 I Gonk    : NFC: OnConnectError
08-18 18:37:49.459   207   207 I Gonk    : NFC: OnDisconnect
08-18 18:37:49.459   207   501 I Gecko   : [Parent 207] WARNING: 'NS_FAILED(rv)', file ../../../../B2G_HG/b2g-inbound/ipc/unixsocket/UnixSocket.cpp, line 287
08-18 18:37:49.459   207   501 I Gecko   : [Parent 207] WARNING: '!IsOpen()', file ../../../../B2G_HG/b2g-inbound/ipc/unixfd/UnixFdWatcher.cpp, line 36
08-18 18:37:49.459   207   501 I I/O     : connect failed with error 2 (No such file or directory)
08-18 18:37:49.459   207   207 I Gonk    : NFC: OnConnectError
08-18 18:37:49.459   207   207 I Gonk    : NFC: OnDisconnect
08-18 18:37:49.459   207   501 I Gecko   : [Parent 207] WARNING: 'NS_FAILED(rv)', file ../../../../B2G_HG/b2g-inbound/ipc/unixsocket/UnixSocket.cpp, line 287
08-18 18:37:49.459   207   501 I Gecko   : [Parent 207] WARNING: '!IsOpen()', file ../../../../B2G_HG/b2g-inbound/ipc/unixfd/UnixFdWatcher.cpp, line 36
08-18 18:37:49.459   207   501 I I/O     : connect failed with error 2 (No such file or directory)
08-18 18:37:49.459   207   207 I Gonk    : NFC: OnConnectError
08-18 18:37:49.459   207   207 I Gonk    : NFC: OnDisconnect
08-18 18:37:49.479   207   501 I Gecko   : [Parent 207] WARNING: 'NS_FAILED(rv)', file ../../../../B2G_HG/b2g-inbound/ipc/unixsocket/UnixSocket.cpp, line 287
08-18 18:37:49.479   207   501 I Gecko   : [Parent 207] WARNING: '!IsOpen()', file ../../../../B2G_HG/b2g-inbound/ipc/unixfd/UnixFdWatcher.cpp, line 36
08-18 18:37:49.479   207   501 I I/O     : connect failed with error 2 (No such file or directory)
08-18 18:37:49.479   207   501 I Gecko   : [Parent 207] WARNING: 'NS_FAILED(rv)', file ../../../../B2G_HG/b2g-inbound/ipc/unixsocket/UnixSocket.cpp, line 287
08-18 18:37:49.539   207   207 I Gonk    : NFC: OnConnectError
08-18 18:37:49.539   207   207 I Gonk    : NFC: OnDisconnect

There is a backoff scheme provided in ipc/unixsocket/SocketBase.cpp but the conditions on which to backoff are incorrect.

Comment 1

[Andrew Osmond [:aosmond] (he/him)]

Attachment: bug1055316.patch, v1

Comment 2

[Thomas Zimmermann [:tzimmermann] [:tdz]]

Comment on attachment 8474842 [details] [diff] [review]
bug1055316.patch, v1

Review of attachment 8474842 [details] [diff] [review]:
-----------------------------------------------------------------

Thanks!

Comment 3

[Thomas Zimmermann [:tzimmermann] [:tdz]]

I'm surprised to see this fail. The backoff scheme was intended to fix this problem for RIL, where it works. Do you know what the the difference with NFC is?

Comment 4

[Andrew Osmond [:aosmond] (he/him)]

(In reply to Thomas Zimmermann [:tzimmermann] [:tdz] from comment #3)
> I'm surprised to see this fail. The backoff scheme was intended to fix this
> problem for RIL, where it works. Do you know what the the difference with
> NFC is?

Hm. No idea. I looked over the RIL code since it uses the same base class but I concluded it suffered from the same problem. CalculateConnectDelayMs, mConnectTimestamp and mConnectDelayMs are all private members of SocketConsumerBase and I don't see any friends declared, so the only direct usage should be in that class through NotifyError and NotifyDisconnect. Whether or not mConnectTimestamp gets set due to a successful connect, the gap should widen between it and the present timestamp rapidly and cause us to fall into the first if always....?

(Just nn case this is different with RIL, note that from the log NotifyError and NotifyDisconnect both get called. That will cause it to backoff twice, but I didn't fully appreciate when each is called so I didn't change it.)

Comment 5

[Andrew Osmond [:aosmond] (he/him)]

try: https://tbpl.mozilla.org/?tree=Try&rev=1d6787cf1579

Comment 6

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/integration/b2g-inbound/rev/9de0463fb1c7

Comment 7

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/9de0463fb1c7