firebase-ios-sdk icon indicating copy to clipboard operation
firebase-ios-sdk copied to clipboard

High CPU usage on a real device - background -> foreground

Open Ovid-iu opened this issue 5 years ago • 44 comments

Environment

  • Xcode version: 10.2.1
  • Firebase SDK version: 6.3.0
  • Firebase Component: Core, Messaging
  • Component version: Core - 6.0.3, Messaging - 4.1.0

Describe the problem On a real device, after the an app was launched, moving the application from foreground to background and then back to foreground, the CPU usage increases to 100% for ~24 seconds. I have tried using Instruments to identify the source of the problem, and from what I can see, on a background thread the CPU usage increases to 100%.

Steps to reproduce: This happens only on a real device, and not on the simulator.

In the didFinishLaunchingWithOptions, the method FirebaseApp.configure() is called - and that's pretty much all needed.

Then simply run the app on the device, move the app to background and then to foreground, and notice the CPU usage increase. Note: this may not happen on the first try, it should happen on the second attempt or third one.

Screenshot 2019-06-24 at 14 59 42

Ovid-iu avatar Jun 24 '19 12:06 Ovid-iu

Screenshot 2019-06-24 at 13 39 21 As you can see, the usage is on another thread and not on the main one.

Ovid-iu avatar Jun 24 '19 12:06 Ovid-iu

Hi @Ovid-iu, thanks for the report.

A few pieces if information that could help us debug this further:

  • What device are you running on?
  • What version OS does the device have?
  • Are you using only Messaging, or other Firebase SDKs as well?
  • If you comment out the FirebaseApp.configure() (not configuring Firebase at all), does the problem go away?

Thanks, hopefully we can track this down quickly.

ryanwilson avatar Jun 24 '19 13:06 ryanwilson

Hello,

I have tested this issue on an iPhone 6 plus running iOS 12.3, an iPhone X running 12.1.4, and iPhone XR running 12.3.1 I have only Messaging as a pod. If I comment the FirebaseApp.configure() method, this problem will go away.

Thank you very much!

Ovid-iu avatar Jun 24 '19 13:06 Ovid-iu

Hi @Ovid-iu, will it be possible to provide the heaviest stack trace for the treads, e.g. like this or, ideally, the export of the profiler trace if you don't have private information there. It will provide us the required information to find the source of the issue.

Alternatively, if you can provide a test project with the steps to reproduce the issue, we can collect the data ourself.

Thanks!

maksymmalyhin avatar Jun 24 '19 14:06 maksymmalyhin

Hi @maksymmalyhin,

Unfortunately, I cannot provide you the trace as there is some sensitive data. I will create a test project to see if I can reproduce the issue.

This is the heaviest stack trace: Screenshot 2019-06-24 at 17 33 57 Screenshot 2019-06-24 at 17 34 20

Ovid-iu avatar Jun 24 '19 14:06 Ovid-iu

@Ovid-iu Yeah, the test project will be appreciated, because the stack trace does not really provide much information on the issue.

maksymmalyhin avatar Jun 24 '19 14:06 maksymmalyhin

I have made a really simple test project that I can provide you with, but I cannot provide the GoogleService-Info.plist since it has sensitive data.

Using my plist file, I could reproduce the issue. testApp.zip

Ovid-iu avatar Jun 24 '19 14:06 Ovid-iu

@Ovid-iu Nice, that's exactly what we need. We will try to reproduce the issue and update the ticket with the results. Thanks!

maksymmalyhin avatar Jun 24 '19 15:06 maksymmalyhin

@Ovid-iu As far as I can see, the activity is related to FirebaseAnalytics that is mostly sending the data collected during the previous foreground period (I assume, you may find APMMeasurement related calls to schedule the tasks at the beginning of the background, the tasks are finished on the app going to the foreground). Though, the CPU time is still relatively small for me for the provided test app. I have not found anything unusual so far. The CPU load looks reasonable to me for such kind of operations (Analytics reads the data from the database, encodes, sends the data to the server, processes the result and updates the database).

I can suggest following steps for you:

  1. If the consumed CPU time still looks too big for your app, then please let us know including info on what will be the reasonable CPU load for you. We will pass this data to the FirebaseAnalytics team to consider a solution.
  2. If you don't actually need Analytics and would like to save CPU time on it, you may just remove the FirebaseAnalytics pod from your Podfile.

maksymmalyhin avatar Jun 24 '19 18:06 maksymmalyhin

Hello @maksymmalyhin,

Thank you very much for the investigation, you have been really helpful with your reply! Regarding your suggestions:

  1. The consumed CPU time looks pretty big, I mean I have noticed that by performing the background-foreground action will induce around 24 - 30s of 100% CPU usage, and this may occur every time this action is done. Doing this flow 3-4 times will increase the battery consumption, as my application already has some other cpu-dependant actions. I find weird the fact that the application was just launched, then it’s sent in the background and when entering foreground the CPU load is 100% for 24s, if it was 2 seconds or 6 seconds maybe it’s not that much, but 25 seconds seems a lot. I thought that maybe this was an issue.

  2. I don’t need Analytics, setting the FIREBASE_ANALYTICS_COLLECTION_DEACTIVATED to YES in the Info.plist file (not the GoogleService-Info.plist file) will be enough? I did this and I still noticed the CPU high load, not as frequent as before, and especially after using the app more , plus when starting the application I get in the logs: <AppMeasurement>[I-ACS036002] Analytics screen reporting is enabled or Analytics started. So how it is the best way to disable the analytics completely? PS: I do not have FirebaseAnalytics pod, all that I have are the Firebase/Core and Firebase/Messaging Thank you very much for all the help!

Ovid-iu avatar Jun 25 '19 07:06 Ovid-iu

If you don't want Analytics, it's probably best not to build it into the app at all. Remove the Firebase/Core from the Podfile.

paulb777 avatar Jun 25 '19 14:06 paulb777

@paulb777 according to https://firebase.google.com/docs/cloud-messaging/ios/client, it's mandatory to have the Firebase/Core in order to have push notifications for the application.

Ovid-iu avatar Jun 25 '19 14:06 Ovid-iu

The FirebaseMessaging pod should be sufficient for push notifications. The Firebase/Core is necessary to pull in Analytics to get associated analytics with push notifications.

paulb777 avatar Jun 25 '19 14:06 paulb777

@Ovid-iu Happy to help! I have one question as for the CPU usage for your case. From the screenshots you posted (which are consistent with the trace I got on my end) I can see that the Firebase activity consumes ~5-10% CPU time with a small amount of spikes ~15-20%. The number 99% in the stack trace indicates that it is the only app activity. I wonder, can you see different traces indicating 100% CPU load? Trace screenshot

Sometimes the Profiler data can be a bit difficult to read, so I would like to be sure we are on the same page. If you really have 100% CPU load for half a minute just because of Analytics, it does not look right and indicates an issue that should be fixed ASAP.

maksymmalyhin avatar Jun 25 '19 14:06 maksymmalyhin

@maksymmalyhin Screenshot 2019-06-25 at 17 42 29

Am I interpreting the data wrong in this case? I will try to profile with the Time Profiler again to get the data.

Ovid-iu avatar Jun 25 '19 14:06 Ovid-iu

I found an older sample which indicates to what you were saying, the CPU load is not that high all the time, but there are moments when it reaches 100% (usually for about 6 seconds). Screenshot 2019-06-25 at 17 49 35

Ovid-iu avatar Jun 25 '19 14:06 Ovid-iu

@Ovid-iu Thank you for the update. I'll pass the data to our Analytics team.

maksymmalyhin avatar Jun 25 '19 14:06 maksymmalyhin

@maksymmalyhin I just did a pass and this is the result I received: Screenshot 2019-06-25 at 17 54 42 The duration of the 100% cpu load is around 29s: Screenshot 2019-06-25 at 17 57 37 Screenshot 2019-06-25 at 17 58 08

The scenario that I have used is simply launching the application, then background->foreground, that's all, no other interactions.

Ovid-iu avatar Jun 25 '19 14:06 Ovid-iu

@Ovid-iu Thank you for your report and data provided! We will post updates on the issue in this ticket.

maksymmalyhin avatar Jun 25 '19 15:06 maksymmalyhin

Tracked internally in b/135997194

maksymmalyhin avatar Jun 25 '19 15:06 maksymmalyhin

Hello @maksymmalyhin, I have conducted another test with an iPhone 6 plus, iOS 12.3. I have attached the results, hopefully it may be of any help. instrumentsScreens.zip I have noticed that before the app is sent to the background, there are some APM... methods called. During the CPU usage, which lasts for a while, there are only methods called from the system. If there is any other way to track them, please let me know.

Thank you!

Ovid-iu avatar Jun 26 '19 13:06 Ovid-iu

@Ovid-iu, in the last screenshot, can you expand the kevent_id call all the way down to the root?

The APM* method activity you're seeing is normal; the CPU locked at 100% afterward is not.

morganchen12 avatar Jun 26 '19 20:06 morganchen12

@morganchen12 Feel free to use my trace from b/135997194 if you want investigate the issue.

maksymmalyhin avatar Jun 26 '19 20:06 maksymmalyhin

@morganchen12 Screenshot 2019-06-27 at 09 54 58

Ovid-iu avatar Jun 27 '19 06:06 Ovid-iu

We have exactly the same issue, I'm following. If you need more data I'll be happy to provide it.

federicocappelli avatar Jul 21 '19 18:07 federicocappelli

Hi, as Federico says above, we are also seeing this issue. In our case, this CPU spike can be up to 2 minutes. I also created a test app that shows the same issue. I have also seen cases where putting the app to the background while it is spiking will continue the spike for up to 2 minutes.

I raised a case with Firebase support already (Case 00002503: Excessive CPU use triggered by Firebase)

gutley avatar Jul 22 '19 08:07 gutley

Upgraded to 6.9.0 yesterday and still seeing these issues. Renders Firebase practically unusable.

tspecht avatar Sep 30 '19 12:09 tspecht

Tracked to the Analytics team at b/141852197

paulb777 avatar Sep 30 '19 15:09 paulb777

I had the same problem.

Environment

Xcode 11.2.1
iPhone X 13.2.2
Firebase component and version:
  - Firebase/Analytics (6.13.0):
    - Firebase/Core
  - Firebase/Core (6.13.0):
    - Firebase/CoreOnly
    - FirebaseAnalytics (= 6.1.6)
  - Firebase/CoreOnly (6.13.0):
    - FirebaseCore (= 6.4.0)
  - FirebaseAnalytics (6.1.6):
    - FirebaseCore (~> 6.4)
    - FirebaseInstanceID (~> 4.2)
    - GoogleAppMeasurement (= 6.1.6)
    - GoogleUtilities/AppDelegateSwizzler (~> 6.0)
    - GoogleUtilities/MethodSwizzler (~> 6.0)
    - GoogleUtilities/Network (~> 6.0)
    - "GoogleUtilities/NSData+zlib (~> 6.0)"
    - nanopb (= 0.3.9011)
  - FirebaseCore (6.4.0):
    - FirebaseCoreDiagnostics (~> 1.0)
    - FirebaseCoreDiagnosticsInterop (~> 1.0)
    - GoogleUtilities/Environment (~> 6.2)
    - GoogleUtilities/Logger (~> 6.2)
  - FirebaseCoreDiagnostics (1.1.2):
    - FirebaseCoreDiagnosticsInterop (~> 1.0)
    - GoogleDataTransportCCTSupport (~> 1.0)
    - GoogleUtilities/Environment (~> 6.2)
    - GoogleUtilities/Logger (~> 6.2)
    - nanopb (~> 0.3.901)
  - FirebaseCoreDiagnosticsInterop (1.1.0)
  - FirebaseInstanceID (4.2.7):
    - FirebaseCore (~> 6.0)
    - GoogleUtilities/Environment (~> 6.0)
    - GoogleUtilities/UserDefaults (~> 6.0)
  - fishhook (0.2)
  - GoogleAppMeasurement (6.1.6):
    - GoogleUtilities/AppDelegateSwizzler (~> 6.0)
    - GoogleUtilities/MethodSwizzler (~> 6.0)
    - GoogleUtilities/Network (~> 6.0)
    - "GoogleUtilities/NSData+zlib (~> 6.0)"
    - nanopb (= 0.3.9011)
  - GoogleDataTransport (3.2.0)
  - GoogleDataTransportCCTSupport (1.2.2):
    - GoogleDataTransport (~> 3.2)
    - nanopb (~> 0.3.901)
  - GoogleUtilities/AppDelegateSwizzler (6.3.2):
    - GoogleUtilities/Environment
    - GoogleUtilities/Logger
    - GoogleUtilities/Network
  - GoogleUtilities/Environment (6.3.2)
  - GoogleUtilities/Logger (6.3.2):
    - GoogleUtilities/Environment
  - GoogleUtilities/MethodSwizzler (6.3.2):
    - GoogleUtilities/Logger
  - GoogleUtilities/Network (6.3.2):
    - GoogleUtilities/Logger
    - "GoogleUtilities/NSData+zlib"
    - GoogleUtilities/Reachability
  - "GoogleUtilities/NSData+zlib (6.3.2)"
  - GoogleUtilities/Reachability (6.3.2):
    - GoogleUtilities/Logger
  - GoogleUtilities/UserDefaults (6.3.2):
    - GoogleUtilities/Logger

UI operation: Launch the application, switch to the background, and then activate. The CPU usage is 100%, which lasts about one minute. 2019-12-03_7 34 58

Workaround: Comment code [FIRApp configure].

klaus01 avatar Dec 03 '19 11:12 klaus01

@klaus01 That's not a workaround, you simply disabled Firebase :)

federicocappelli avatar Dec 03 '19 16:12 federicocappelli