Android Framework Problem Analysis Case - Who Killed the Desktop?

The opportunity to write this article is due to a practical problem. This problem is not difficult, but when I analyzed the problem and wrote a diary, I suddenly felt that it was necessary to record the analysis process of this problem and share it with everyone. Some tools and methods were used in the analysis process, and I also learned some analysis skills and tool usage skills from another smart friend Mei Ming.

The analysis process in this article includes some of the tools I mentioned in my previous article Overview of the causes of lag and frame drop in Android - Methodology, including: Reproduction Video\ Event Log\ Android Studio Source Code and App Debug\ Android Studio Profile\ Systrace\ Dumpsys\ PS, etc. Most of these tools have been used in the development process, and this analysis used these tools to work together to find the cause of the problem.

You may think, is it necessary to write an article for such a simple question? The purpose of writing this article is to record it for myself, and secondly, I think the analysis process is more universal, including the analysis ideas and the use of tools. If it can help everyone, it would be the best. If you also have good ideas or unique debugging skills, you are welcome to scan the QR code of the discussion group in About Me to join the group chat and make progress together!

Phenomenon

This problem was reported directly by the test. The bug description is a typical description of the phenomenon: " Desktop icons load slowly when returning to the desktop from the application ." The test provides the recorded video and captured log, as well as the corresponding Systrace, etc. Since the phenomenon and log are all there, let's start analyzing.

Analysis process

Determine when the problem occurred

1. Since the test provides a recurrence video, first watch the recurrence video to determine when the event occurred
2. According to the approximate time in the video (accurate to minutes), check the corresponding EventLog, compare it with the video, and determine the exact time of occurrence (accurate to seconds)
3. Check EventLog and MainLog to restore the user operation when it happened. In this example, it was found that after starting the Woxin App, the Launcher was killed.

 EventLog
 // Start the com.jx.cmcc.ict.ibelieve App  
 09 - 10   10 : 14 : 48.877    1456    2269 I am_set_resumed_activity: [ 0 ,com.jx.cmcc.ict.ibelieve/.ui.MainTabActivity,resumeTopActivityInnerLocked]
 09 - 10   10 : 14 : 48.886    1456    2269 I am_resume_activity: [ 0 , 80317506 , 54938 , com.jx.cmcc.ict.ibelieve/.ui.MainTabActivity]
 09 - 10   10 : 14 : 48.891    1456    1485 I sysui_count: [window_time_0, 0 ]
 09 - 10   10 : 14 : 48.891    1456    1485 I sysui_multi_action: [ 757 , 803 , 799 , window_time_0, 802 , 0 ]
 09 - 10   10 : 14 : 48.902    1456    2269 I am_uid_stopped: 10021   
 
 // The desktop is killed here  
 09 - 10   10 : 14 : 48.903    1456    2269 I am_kill : [ 0 , 13509 ,com.meizu.flyme.launcher, 600 ,kill background] 
 
 // Start returning to the desktop from the App here  
 09 - 10   10 : 14 : 51.990    1456    1791 I am_pause_activity: [ 0 , 80317506 ,com.jx.cmcc.ict.ibelieve/.ui.MainTabActivity]
 09 - 10   10 : 14 : 51.994    1456    1791 I am_task_to_front: [ 0 , 54923 ]
 09 - 10   10 : 14 : 51.996   13674   13674 I am_on_paused_called: [ 0 ,com.jx.cmcc.ict.ibelieve.ui.MainTabActivity,handlePauseActivity]
 09 - 10   10 : 14 : 52.013    1456    2270 I am_uid_running: 10021   
 
 // Recreate the desktop process  
 09 - 10   10 : 14 : 52.025    1456    2270 I am_proc_start: [ 0 , 14013 , 10021 ,com.meizu.flyme.launcher,activity,com.meizu.flyme.launcher/.Launcher]
 09 - 10   10 : 14 : 52.045    1456    2270 I am_proc_bound: [ 0 , 14013 , com.meizu.flyme.launcher]
 09 - 10   10 : 14 : 52.069    1456    2270 I am_uid_active: 10021  
 09 - 10   10 : 14 : 52.069    1456    2270 I am_restart_activity: [ 0 , 238217861 , 54923 , com.meizu.flyme.launcher/.Launcher] 
 
 //Desktop display  
 09 - 10   10 : 14 : 52.071    1456    2270 I am_set_resumed_activity: [ 0 ,com.meizu.flyme.launcher/.Launcher,minimalResumeActivityLocked]
 09 - 10   10 : 14 : 52.335   14013   14013 I am_on_resume_called: [ 0 ,com.meizu.flyme.launcher.Launcher,LAUNCH_ACTIVITY]
 09 - 10   10 : 14 : 52.437    1456    1504 I am_activity_launch_time: [ 0 , 238217861 ,com.meizu.flyme.launcher/.Launcher, 413 , 413 ]

Then we can simply restore the problem here. The test report is that the desktop icons load slowly when returning from the application . From the Event Log, the desktop displays slowly because the desktop is killed . Therefore, when returning from the App, the desktop needs to be reloaded. It takes 413ms from the creation of the desktop process to the full display of the desktop (it actually takes at least 2s to fully display the desktop, because the Launcher needs to reload the content when it is cold started).

Analysis of the reasons for the killing

From the above analysis, we need to find out why the Launcher was killed. From the phenomenon, it seems to be related to the process com.jx.cmcc.ict.ibelieve, but we currently have no way to confirm it.

Here we focus on this Event Log

 am_kill: [ 0 , 13509 , com.meizu.flyme.launcher, 600 , kill background]

Here we can see that the reason why Launcher was killed is kill background. Looking at the corresponding source code, we can see that reason = kill background is issued by AMS.killBackgroundProcesses.

ActivityManagerService.killBackgroundProcesses

 public   void killBackgroundProcesses( final String packageName, int userId) {
 ......
 synchronized ( this ) {
                killPackageProcessesLocked(packageName, appId, targetUserId,
                        ProcessList.SERVICE_ADJ, false , true , true , false , "kill background" );
 }
 }

Students who are familiar with the source code can quickly find out that the AMS.killBackgroundProcesses interface will be provided to third-party applications for calling, and its Binder client is in ActivityManager.killBackgroundProcesses here

ActivityManager.killBackgroundProcesses

 /**
 * Have the system immediately kill all background processes associated
 * with the given package. This is the same as the kernel killing those
 * processes to reclaim memory; the system will take care of restarting
 * these processes in the future as needed.
 *
 * @param packageName The name of the package whose processes are to
 * be killed.
 */  
 @RequiresPermission (Manifest.permission.KILL_BACKGROUND_PROCESSES)
 public   void killBackgroundProcesses(String packageName) {
 try {
        getService().killBackgroundProcesses(packageName,
                mContext.getUserId());
    } catch (RemoteException e) {
 throw e.rethrowFromSystemServer();
 }
 }

Debug the SystemServer process

Knowing the logic of the above code, what we need to do is to find which application calls ActivityManager.killBackgroundProcesses to kill the desktop in this scenario. Since we don't know which application it is (although we suspect it is com.jx.cmcc.ict.ibelieve, but there is no evidence), we first debug the SystemServer process.

1. First debug the source code. First, click the debug button in Android, select the system_process process (what we call SystemServer), and then click OK. The code breakpoint is set in the ActivityManagerService.killBackgroundProcesses method listed above.

2. Click to start the suspected App (you can work backwards from EventLog and the video to find the more suspicious App, and perform local testing to reproduce it after installation. Here we select several apps that appear in the video, including com.jx.cmcc.ict.ibelieve-和信that we suspected before). Clicking other apps will not enter this breakpoint, but clicking the 和信App will reach the breakpoint after it is started.

3. Here we can see that the call stack is a Binder call. We need to find the client of this Binder call. Continue to operate in AS, click the calculator button as shown below, enter getRealCallingPid() and click Evaluate below to see the result. Result = 29771

4. Use the PS command to view the app corresponding to this pid.

You can see that it is this application that calls killBackgroundProcesses.

Debug the App process

To investigate further, we debugged the app. Since we don’t have the source code, we set the breakpoint directly to android/app/ActivityManager.killBackgroundProcesses (because this is client code, we can set the breakpoint directly when debugging the App process).

I installed this application locally for debugging and found that after logging in and starting it again, the desktop would be killed, confirming that the problem was with this App.

At this point, we have basically determined that the problem is caused by this app, but if we want to see more detailed calls, we can use Android Studio Profile.

Using the Android Studio Profiler tool

Open Android Studio, click the Profiler button, click the + sign, select the com.jx.cmcc.ict.ibelieve process, and then click the CPU column.

Select Trace Java Methods here, then click Record next to it to start the operation. After the operation is completed, click Stop and AS will automatically start parsing.

We can see the analysis results here:

At the bottom is the detailed function call stack corresponding to the operation just now, which is displayed in the actual running order. (I often use this tool to view the source code logic and the code logic of third-party applications. It is a very good method whether it is for learning or solving problems.)

We use ctrl+f to search for killBackgroundProcesses. If there is one, it will be highlighted. We just need to zoom in with the mouse to see the detailed call stack.

You can see that the app executes the killBackground method in the loadComplete callback. (At this point, the app developer already knows what the problem is and can fix it quickly).

Analysis of permissions issues

As shown above, calling killBackgroundProcesses requires the permission Manifest.permission.KILL_BACKGROUND_PROCESSES.

 @RequiresPermission (Manifest.permission.KILL_BACKGROUND_PROCESSES)
 public   void killBackgroundProcesses(String packageName) {
 }

Execute adb shell dumpsys package com.jx.cmcc.ict.ibelieve to view the permissions applied for by the com.jx.cmcc.ict.ibelieve process. It is found that this application applied for the KILL_BACKGROUND_PROCESSES permission when it was installed, and it is granted by default.

 install permissions:
 ......
  android.permission.ACCESS_NETWORK_STATE: granted= true  
  android.permission.KILL_BACKGROUND_PROCESSES: granted= true  
  android.permission.WRITE_USER_DICTIONARY: granted= true  
 ......

The corresponding permission level is normal.

In other words, all third-party applications can have this permission by default, as long as you apply for it. In this case, it was because this App applied for this permission and performed the wrong behavior, which killed the desktop and seriously affected the user experience. Sad!

Can the Systrace tool find out the culprit that killed the desktop?

Since Systrace is often used, can Systrace find the culprit? The answer is yes (if you don't know how to view the wakeup information on Systrace, you can read this article Preliminary knowledge for analyzing Systrace). Let's record a Systrace and install the following sequence to see

1. First, look at the trace corresponding to the system_server process, find the point corresponding to killProcessGroup, and check its wake-up status. You can see that thread 19688 wakes up the killProcessGroup that executes AMS.

Searching for 19688 in Systrace, you can see that it is Binder:1295_1E, and 1295 is SystemServer.

Check the corresponding Binder:1295_1E to see which thread wakes up this thread.

Search the thread 7289 and you can see that this thread is the main thread of the Woxin App.

Check 7289 and confirm that it is the process com.jx.cmcc.ict.ibelieve. That is, the same as the WoXin App (tumor).

We can also infer that the Kill was initiated by the Woxin App. We can further confirm this by using the MethodTrace of the AS above.

Summarize

From the above analysis, we can see that this problem is caused by the application applying for inappropriate permissions and incorrectly using the corresponding functions, which seriously affects user usage. Generally speaking, our work is basically completed after this step of analysis. We only need to communicate with the store and contact the App developer to make modifications.

But what surprised me was that Google was so lax about the permission android.permission.KILL_BACKGROUND_PROCESSES. I always thought that this permission should be applied for specifically to prevent apps from abusing it or using it for nothing (after all, it involves the life and death of other apps).

5. About Me

I am a system development engineer in a small factory. For more information, please click About me. I really hope to communicate with you and make progress together.