Can background notifications be causing app to use CPU from background for many hours?

[gilbertl]

Hi all,

Two users have reported to us that our app is draining their batteries. They send us screenshots of the battery dashboard while it shows that our app is in the background using the CPU for 4+ hours.

When I look at our logs, we see that during those hours, the user received notification in background 2-3 times.

We are wondering if maybe the background message handler might be causing some kind of wake lock to be stuck. I looked into background messaging code and understand that it's using Headless JS. I also understand there's a wakelock there to run the background task.

Other than the fact that the wake lock is acquired without any timeouts though, I don't see anything obviously wrong. I also figure since the core Headless JS code has been around for several years, such obvious wake lock problems would've been discovered already.

Does anyone have insights about this? Perhaps other reasons why this might be happening, or theories on where the background message handler might be going wrong?

Thanks.

[mikehardy]

I'm unsure of your exact use case, but I know it's possible to use background messages without CPU usage as my most important work app does so and has done so for a couple years, and I watch the battery usage. I suspect something else in your project (in response to the message maybe?) is doing it.
Unfortunately for performance-related things that require profiling etc there is no substitute for a reproduction - something built from https://github.com/mikehardy/rnfbdemo/blob/master/make-demo.sh with nothing but an index.js/App.js that can trigger the issue would be the ticket (https://stackoverflow.com/help/minimal-reproducible-example) otherwise we'll be stuck in a "my app works" / "my app doesn't" stalemate as I don't reproduce this

[gilbertl]

Thanks for jumping in, Mike. Since the problem is so nebulous at point, I'm trying to draw ideas from you and others on what can possibly cause this. Hoping those ideas can help me pin down the area of concern and help re-produce the issues.

My reading of the code suggests that Headless JS has a timeout after which the task will be marked as complete and the wake lock released. So even if my JS code is causing an exception or blocking, it shouldn't cause the app to run in background indefinitely.

My other theory then is maybe my background message handler is accidentally triggering code that acquires and fails to release a wakelock

[gilbertl]

I think there's also the possibility that this has nothing to do with background message handler and headless JS. However, the only I know through which an app can use CPU from background for so many hours is via wakelocks. I grepped my node_modules and the only packages using wakelocks is react native firebase messaging and react-native-background-timer. We don't have any active code path going through the latter's wakelock. If anyone has ideas on how it might be possible for an Android app to be draining battery from background like this, I'm all ears as well.

[mikehardy]

https://stackoverflow.com/questions/5780280/how-can-i-see-which-wakelocks-are-active
https://developer.android.com/studio/profile/energy-profiler

I'd start with Android Studio energy profiler I think.

[gilbertl]

After a bit of experimentation, here's what I've found so far.

When our app receives a notification from background, some locks are acquired but released properly

 adb shell dumpsys power | grep react

 10-28 16:23:17.767 - 10418 - ACQ com.facebook.react.HeadlessJsTaskService (partial)
  10-28 16:23:17.915 - 10418 - REL com.facebook.react.HeadlessJsTaskService
  10-28 16:23:39.737 - 10418 - ACQ com.facebook.react.HeadlessJsTaskService (partial)
  10-28 16:23:39.779 - 10418 - REL com.facebook.react.HeadlessJsTaskService
  10-28 16:28:56.905 - 10418 - ACQ com.facebook.react.HeadlessJsTaskService (partial)
  10-28 16:28:58.028 - 10418 - REL com.facebook.react.HeadlessJsTaskService
  10-28 16:29:49.734 - 10418 - ACQ com.facebook.react.HeadlessJsTaskService (partial)
  10-28 16:29:49.842 - 10418 - REL com.facebook.react.HeadlessJsTaskService
  10-28 16:31:00.280 - 10418 - ACQ com.facebook.react.HeadlessJsTaskService (partial)
  10-28 16:31:00.332 - 10418 - REL com.facebook.react.HeadlessJsTaskService

however, the process remains using the CPU and doesn't get killed

CPU usage from 442288ms to 142210ms ago (2021-10-28 16:33:18.241 to 2021-10-28 16:38:18.319):
  99% 23743/(our app): 99% user + 0.1% kernel / faults: 1244 minor
  17% 22911/com.shopee.sg: 9% user + 8.4% kernel / faults: 25681 minor
  6.5% 1045/surfaceflinger: 2.9% user + 3.5% kernel / faults: 185 minor
  6.4% 1687/system_server: 4.2% user + 2.2% kernel / faults: 64653 minor 21 major
  4% 2585/com.android.bluetooth: 3.3% user + 0.6% kernel / faults: 2114 minor 1 major
  3.4% 3996/cnss_diag: 2.9% user + 0.5% kernel

Notice the timestamps: the headless js task finished at 16:31, but the app is still running from 16:33 to 16:38

Will investigate more but if anyone has ideas we'd really appreciate it!

[mikehardy]

Sounds like something in the logic itself is spinning / infinite loop. There will be no substitute for a https://stackoverflow.com/help/minimal-reproducible-example here unfortunately