Problem description
The startup time is too slow compared with the reference machine, about 15s slow. Android system 7.0.
problem analysis
Bootloader -- > kernel -- > zygote -- > PMS -- > AMS -- > launcher involves many levels
It can be analyzed with bootchart or directly through log analysis. Unfortunately, the bootchart cannot be captured by the project machine due to unknown reasons.
Fortunately, I found an artifact perfboot tool while browsing the source code. See system / core / init / perfboot py.
The command needs to be run in the source code compilation environment. Please refer to the source code file for details, which will not be introduced here.
Use command:
./perfboot.py --iterations=5 --interval=30 -v --output=/data/My_Doc/Performance/Bugs/bootup_op_4200151/J5D_UE.tsv
Obtain the startup data of the problem machine and the reference machine. Generate the following figure
The X-axis in the figure above is some important nodes during startup. Y axis is the start-up time.
Specify the meaning of each node representation on the X-axis.
|boot_progress_start | the system enters the user space, marking the completion of kernel startup. In this example, it can be seen that the kernel startup takes about 30s
|:---
|boot_progress_preload_start|Zygote start
|boot_progress_preload_end|Zygote end
|boot_progress_system_run|SystemServer ready to start Android system services, such as PMS, APMS, etc
|boot_progress_pms_start|PMS starts scanning installed applications
|boot_progress_pms_system_scan_start|PMS scans the installation package in the / system directory first
|boot_progress_pms_data_scan_start|PMS scan the installation package in the / data directory
|boot_ progress_ pms_ scan_ End | end of PMS scanning
|boot_progress_pms_ready|PMS ready
|boot_progress_ams_ready|AMS ready
|boot_progress_enable_screen|AMS starts to activate the screen after it is started. From then on, the screen can respond to the user's touch. Before WindowManagerService sends the time node to exit the startup animation, it will take a little time to actually exit the startup animation, which depends on desc.txt in the animation zip package. wm_boot_animation_done is the end time node perceived by the user
|sf_stop_bootanim|SF set service bootanim. The value of exit attribute is 1, which indicates that the system is about to end the startup animation. It can be used to track the time consumed at the end of the startup animation
|wm_boot_animation_done | the startup animation ends. In this step, the user can intuitively feel the end of startup
From the above figure, you can visually see that the problem machine is entering the boot_ progress_ Before the start node, it takes more time than the reference machine. Before that, it mainly involved bootloader and kernel.
bootloader optimization
I haven't touched this one. I'll give it to my colleagues at the bottom for optimization. About how to grab log s
adb shell cat /proc/bootmsg > bootmsg.txt.
From the log, the bottom colleagues found that there was a problem with the bootimg signature. After more detailed analysis, they really didn't understand this and couldn't summarize helpful opinions.
kernel layer optimization
For kernel optimization, check the config configuration first. There are many kinds of config configurations in the kernel. Even kernel engineers who have worked for several years may not be able to understand the role of each config value. Android provides a basic configuration table.
You can use scripts: kernel/scripts/kconfig/merge_config.sh to generate a config file. Specific usage Poke this
Compare the generated config file with the config file in the current project, and also compare the config file of the reference machine. A ready-made tool kernel/scripts/diffconfig can be used for comparison.
After comprehensive comparison, debug a little bit locally and find data. Finally, the following config is removed:
CONFIG_MTD_TESTS=m ----> m Change to n CONFIG_SERIAL_MSM_HSL=y ----> y Change to n CONFIG_SERIAL_MSM_HSL_CONSOLE=y ----> y Change to n CONFIG_MMC_BLOCK_TEST=m ---->Comment out CONFIG_MMC_TEST=m ---->Comment out CONFIG_SERIAL_MSM_HSL=y ----> y Change to n CONFIG_SERIAL_MSM_HSL_CONSOLE=y ----> y Change to n CONFIG_MSM_SMD_DEBUG=y ---->Comment out CONFIG_CGROUP_DEBUG=y ---->Comment out CONFIG_RELAY=y ---->Comment out CONFIG_RMNET_DATA_DEBUG_PKT=y ---->Comment out CONFIG_DEBUG_GPIO=y ---->Comment out CONFIG_CORESIGHT=y ---->Comment out CONFIG_CORESIGHT_EVENT=y ---->Comment out CONFIG_CORESIGHT_FUSE=y ---->Comment out CONFIG_CORESIGHT_CTI=y ---->Comment out CONFIG_CORESIGHT_TMC=y ---->Comment out CONFIG_CORESIGHT_TPIU=y ---->Comment out CONFIG_CORESIGHT_FUNNEL=y ---->Comment out CONFIG_CORESIGHT_REPLICATOR=y ---->Comment out CONFIG_CORESIGHT_STM=y ---->Comment out CONFIG_CORESIGHT_HWEVENT=y ---->Comment out CONFIG_DEBUG_MEMORY_INIT=y ---->Comment out CONFIG_DYNAMIC_DEBUG=y ---->Comment out //All the following are also noted out CONFIG_SCHED_DEBUG CONFIG_DEBUG_KMEMLEAK CONFIG_DEBUG_KMEMLEAK_EARLY_LOG_SIZE=400 CONFIG_DEBUG_KMEMLEAK_DEFAULT_OFF CONFIG_DEBUG_SPINLOCK CONFIG_DEBUG_MUTEXES CONFIG_DEBUG_ATOMIC_SLEEP CONFIG_DEBUG_STACK_USAGE CONFIG_DEBUG_LIST CONFIG_FAULT_INJECTION_DEBUG_FS CONFIG_LOCKUP_DETECTOR CONFIG_DEBUG_PAGEALLOC CONFIG_PAGE_POISONING CONFIG_RMNET_DATA_DEBUG_PKT CONFIG_MMC_PERF_PROFILING CONFIG_DEBUG_BUS_VOTER CONFIG_SLUB_DEBUG CONFIG_DEBUG_BUGVERBOSE CONFIG_ALLOC_BUFFERS_IN_4K_CHUNK CONFIG_SERIAL_CORE CONFIG_SERIAL_CORE_CONSOLE CONFIG_SERIAL_MSM_HSL CONFIG_SERIAL_MSM_HSL_CONSOLE CONFIG_MSM_TZ_LOG CONFIG_DYNAMIC_DEBUG
Here, the configuration of config includes y,n,m, m, which means that it is compiled into a module and not into the kernel. If not configured, it is equivalent to n.
CONFIG_DEBUG_INFO cannot be removed, which will cause CTS. Since the values of config may be scattered in different kernel files, we can compile the kernel separately, and then check obj / kernel in the out directory_ OBJ/. Config file. The configuration items in this file are complete.
After the kernel turns off some debug switches. The retest results on the new version are as follows:
Here is how to view the kernel log,
After startup, use the command: ADB shell dmesg > dmesg Txt grab Log
Search the keyword "bootloader start count" -- > LK start in the log
"Bootloader end count" -- > LK end
"Kernel MPM timestamp" -- > bootloader running completed
Through the optimization of bootloader and kernel, the boot time of about 14s is directly reduced. It can be seen that the optimization effect is still obvious.
Framework layer optimization
Use the command: adb logcat -b events|grep boot to filter out the main events in the startup phase.
01-01 13:38:52.139 391 391 I boot_progress_start: 15452 01-01 13:38:53.329 391 391 I boot_progress_preload_start: 16641 01-01 13:38:56.675 391 391 I boot_progress_preload_end: 19989 01-01 13:38:57.020 1729 1729 I boot_progress_system_run: 20333 01-01 13:38:57.824 1729 1729 I boot_progress_pms_start: 21137 01-01 13:38:58.865 1729 1729 I boot_progress_pms_system_scan_start: 22179 01-01 13:39:08.852 1729 1729 I boot_progress_pms_data_scan_start: 32166 01-01 13:39:08.907 1729 1729 I boot_progress_pms_scan_end: 32221 01-01 13:39:10.109 1729 1729 I boot_progress_pms_ready: 33422 01-01 13:39:12.557 1729 1729 I boot_progress_ams_ready: 35871 01-01 13:39:15.189 1729 1782 I boot_progress_enable_screen: 38503 01-01 13:39:17.973 290 321 I sf_stop_bootanim: 41287 01-01 13:39:18.887 1729 1961 I wm_boot_animation_done: 42201
Combined with the comparison diagram, boot_ progress_ enable_ Before screen, the time consumption of each node of the problem machine is similar to that of the comparison machine. Here, the boot phase on Android m goes to boot_progress_enable_screen is over, and there is SF on Android N_ stop_ Bootanim and wm_boot_animation_done two events. This is the figure - the brownish red line to boot after optimizing the kernel_ progress_ enable_ Screen is not delayed because it represents a reference machine, which happens to be the Android M system.
As can be seen from the timestamp of the log:
boot_ progress_ enable_ Screen --- > it takes about 2s to reach SF_ stop_ Bootanim --- > take more than 1s to reach wm_boot_animation_done. The extra two processes take nearly 4s in total.
We should focus on what happened in this process and why it took nearly 4s more time.
1. Look at the boot first_ progress_ enable_ Where screen appears.
It is in frameworks / base / services / core / Java / COM / Android / server / AM / activitymanagerservice java
void enableScreenAfterBoot() {
EventLog.writeEvent(EventLogTags.BOOT_PROGRESS_ENABLE_SCREEN,
SystemClock.uptimeMillis());
mWindowManager.enableScreenAfterBoot();
synchronized (this) {
updateEventDispatchingLocked();
}
}
2.sf_ stop_ Where bootanim appears.
It's in frameworks / native / services / surfacelinker / surfaceflinger_ hwc1. cpp.
In particular, surface flinger_ hwc1. CPP is surfaceflinger CPP is an upgraded version. It supports HWC 2.0 and uses surfaceflinger CPP or SurfaceFlinger_hwc1.cpp is related to platform selection.
void SurfaceFlinger::bootFinished()
{
...
// stop boot animation
// formerly we would just kill the process, but we now ask it to exit so it
// can choose where to stop the animation.
property_set("service.bootanim.exit", "1");
const int LOGTAG_SF_STOP_BOOTANIM = 60110;
LOG_EVENT_LONG(LOGTAG_SF_STOP_BOOTANIM,
ns2ms(systemTime(SYSTEM_TIME_MONOTONIC)));
}
3.wm_ boot_ animation_ Where done appears.
frameworks/base/services/core/java/com/android/server/wm/WindowManagerService.java
public void performEnableScreen() {
...
// Don't enable the screen until all existing windows have been drawn.
if (!mForceDisplayEnabled && checkWaitingForWindowsLocked()) {
return;
}
if (!mBootAnimationStopped) {
// Do this one time.
Trace.asyncTraceBegin(Trace.TRACE_TAG_WINDOW_MANAGER, "Stop bootanim", 0);
try {
IBinder surfaceFlinger = ServiceManager.getService("SurfaceFlinger");
if (surfaceFlinger != null) {
//Slog.i(TAG_WM, "******* TELLING SURFACE FLINGER WE ARE BOOTED!");
Parcel data = Parcel.obtain();
data.writeInterfaceToken("android.ui.ISurfaceComposer");
surfaceFlinger.transact(IBinder.FIRST_CALL_TRANSACTION, // BOOT_FINISHED
data, null, 0);
data.recycle();
}
} catch (RemoteException ex) {
Slog.e(TAG_WM, "Boot completed: SurfaceFlinger is dead!");
}
mBootAnimationStopped = true;
}
if (!mForceDisplayEnabled && !checkBootAnimationCompleteLocked()) {
if (DEBUG_BOOT) Slog.i(TAG_WM, "performEnableScreen: Waiting for anim complete");
return;
}
...
EventLog.writeEvent(EventLogTags.WM_BOOT_ANIMATION_DONE, SystemClock.uptimeMillis());
...
}
After finding the location where the three nodes appear, let's analyze how to connect the three nodes in series.
1 -- > 2 process: the enablescreen afterboot of AMS calls the enablescreen afterboot method of WMS. The enablescreen afterboot in WMS will continue to call the internal method performEnableScreen, which internally judges that if the startup animation does not stop, it will call SurfaceFlinger to stop the startup animation
surfaceFlinger.transact(IBinder.FIRST_CALL_TRANSACTION, // BOOT_FINISHED
data, null, 0);First here_ CALL_ Transaction is actually a BOOT_FINISHED.
frameworks/native/include/gui/ISurfaceComposer.h
class BnSurfaceComposer: public BnInterface<ISurfaceComposer> {
public:
enum {
// Note: BOOT_FINISHED must remain this value, it is called from
// Java by ActivityManagerService.
BOOT_FINISHED = IBinder::FIRST_CALL_TRANSACTION,surfaceFlinger. The call request from transact will be processed by ISurfaceComposer.
frameworks/native/libs/gui/ISurfaceComposer.cpp
status_t BnSurfaceComposer::onTransact(
uint32_t code, const Parcel& data, Parcel* reply, uint32_t flags)
{
...
switch(code) {
case BOOT_FINISHED: {
CHECK_INTERFACE(ISurfaceComposer, data, reply);
bootFinished();
return NO_ERROR;
}
}
...
}
The bootFinished here is the surface flinger_ hwc1. The bootFinished() method defined by CPP finally comes to the second node sf_stop_bootanim.
In order to verify the above call process, we add the log of the print call stack to see the output.
void SurfaceFlinger::bootFinished()
{
const nsecs_t now = systemTime();
const nsecs_t duration = now - mBootTime;
ALOGI("Boot is finished (%ld ms)", long(ns2ms(duration)) );
mBootFinished = true;
android::CallStack stack;
stack.update();
stack.log("azhengye", ANDROID_LOG_DEBUG, " ");
String8 strtemp = stack.toString("");
ALOGD("Sunny\t%s", strtemp.string());
}
---------------------------------------------------------------------------------
04-28 12:41:15.978 308 2956 D azhengye: #00 pc 0002b761 /system/lib/libsurfaceflinger.so
04-28 12:41:15.978 308 2956 D azhengye: #01 pc 00045c9f /system/lib/libgui.so
04-28 12:41:15.978 308 2956 D azhengye: #02 pc 000310cf /system/lib/libsurfaceflinger.so
04-28 12:41:15.978 308 2956 D azhengye: #03 pc 000359b3 /system/lib/libbinder.so
04-28 12:41:15.979 308 2956 D azhengye: #04 pc 0003d159 /system/lib/libbinder.so
04-28 12:41:15.979 308 2956 D azhengye: #05 pc 0003cdb7 /system/lib/libbinder.so
04-28 12:41:15.979 308 2956 D azhengye: #06 pc 0003d2bb /system/lib/libbinder.so
04-28 12:41:15.979 308 2956 D azhengye: #07 pc 0004f5f5 /system/lib/libbinder.so
04-28 12:41:15.979 308 2956 D azhengye: #08 pc 0000e349 /system/lib/libutils.so
04-28 12:41:15.979 308 2956 D azhengye: #09 pc 000473d3 /system/lib/libc.so
04-28 12:41:15.979 308 2956 D azhengye: #10 pc 0001a0c9 /system/lib/libc.so
---------------------------------------------------------------------------------
SurfaceFlinger_hwc1.cpp:312 android::SurfaceFlinger::bootFinished()
ISurfaceComposer.cpp:371 android::BnSurfaceComposer::onTransact(unsigned int, android::Parcel const&, android::Parcel*, unsigned int)
SurfaceFlinger_hwc1.cpp:3103 android::SurfaceFlinger::onTransact(unsigned int, android::Parcel const&, android::Parcel*, unsigned int)
Binder.cpp:126 android::BBinder::transact(unsigned int, android::Parcel const&, android::Parcel*, unsigned int)
IPCThreadState.cpp:1111 android::IPCThreadState::executeCommand(int)
IPCThreadState.cpp:445 android::IPCThreadState::getAndExecuteCommand()
IPCThreadState.cpp:513 android::IPCThreadState::joinThreadPool(bool)
ProcessState.cpp:63 (discriminator 1)android::PoolThread::threadLoop()
Threads.cpp:751 android::Thread::_threadLoop(void*)
pthread_create.cpp:198 (discriminator 1)__pthread_start(void*)
clone.cpp:41 (discriminator 1)__start_thread
The above log also confirms the previous analysis. So far, the process of 1 -- > 2 is passed. Looking at the 2 -- > 3 process, there is another judgment before the 3 nodes appear:
if (!mForceDisplayEnabled && !checkBootAnimationCompleteLocked()) {
if (DEBUG_BOOT) Slog.i(TAG_WM, "performEnableScreen: Waiting for anim complete");
return;
}Here, the system needs to check whether the boot animation is still playing,
private boolean checkBootAnimationCompleteLocked() {
if (SystemService.isRunning(BOOT_ANIMATION_SERVICE)) {
mH.removeMessages(H.CHECK_IF_BOOT_ANIMATION_FINISHED);
mH.sendEmptyMessageDelayed(H.CHECK_IF_BOOT_ANIMATION_FINISHED,
BOOT_ANIMATION_POLL_INTERVAL);
return false;
}
return true;
}BOOT_ANIMATION_SERVICE is started when initializing SurfaceFlinger.
frameworks/native/services/surfaceflinger/SurfaceFlinger_hwc1.cpp
void SurfaceFlinger::init() {
...
// start boot animation
startBootAnim();
}
I came to BootAnimation. As analyzed earlier, set "service.bootanim.exit" to 1 in the bootFinished method of SurfaceFlinger. This setting is read in BootAnimation.
frameworks/base/cmds/bootanimation/BootAnimation.cpp
...
#define EXIT_PROP_NAME "service.bootanim.exit"
...
void BootAnimation::checkExit() {
// Allow surface flinger to gracefully request shutdown
char value[PROPERTY_VALUE_MAX];
property_get(EXIT_PROP_NAME, value, "0");
int exitnow = atoi(value);
if (exitnow) {
requestExit();
if (mAudioPlayer != NULL) {
mAudioPlayer->requestExit();
}
}
}
After tracking this 2 -- > 3, the process will be smooth. After sorting out the calling logic of the process, the problem also surfaced. It turned out that when a former colleague solved a black screen problem when he turned on the desktop, he artificially delay ed for a few seconds in checkExit
The following errors were also found when checking the log:
01-01 15:55:23.506 1865 1865 E BitmapFactory: Unable to decode stream: java.io.FileNotFoundException: /data/system/users/0/wallpaper_orig (No such file or directory)
The adb shell enters the mobile phone and finds that / data / system / users / 0 / wallpaper does not exist_ Orig file.
Is it because of the wallpper exception that it consumes too much time?
To clear debug, filter the log
adb logcat -b all|grep -E "Wallpaper may change|haveWall|sf_stop_bootanim|boot_progress_enable_screen"
The output is as follows:
01-02 12:13:03.814 1851 2082 V WindowManager: Wallpaper may change! Adjusting 01-02 12:13:04.865 1851 2082 V WindowManager: Wallpaper may change! Adjusting 01-02 12:13:06.986 1851 2006 I boot_progress_enable_screen: 40388 01-02 12:13:06.988 1851 2082 V WindowManager: Wallpaper may change! Adjusting 01-02 12:13:07.052 1851 2006 I WindowManager: ******** booted=true msg=false haveBoot=false haveApp=false haveWall=false wallEnabled=true haveKeyguard=true 01-02 12:13:07.056 1851 2082 I WindowManager: ******** booted=true msg=false haveBoot=false haveApp=false haveWall=false wallEnabled=true haveKeyguard=true 01-02 12:13:07.184 1851 2082 I WindowManager: ******** booted=true msg=false haveBoot=false haveApp=false haveWall=false wallEnabled=true haveKeyguard=true 01-02 12:13:08.049 1851 2082 V WindowManager: Wallpaper may change! Adjusting 01-02 12:13:08.066 1851 2082 I WindowManager: ******** booted=true msg=false haveBoot=false haveApp=false haveWall=false wallEnabled=true haveKeyguard=true 01-02 12:13:08.067 1851 2082 I WindowManager: ******** booted=true msg=false haveBoot=false haveApp=false haveWall=false wallEnabled=true haveKeyguard=true 01-02 12:13:08.071 1851 2082 I WindowManager: ******** booted=true msg=false haveBoot=false haveApp=false haveWall=false wallEnabled=true haveKeyguard=true 01-02 12:13:08.072 1851 2082 I WindowManager: ******** booted=true msg=false haveBoot=false haveApp=false haveWall=false wallEnabled=true haveKeyguard=true 01-02 12:13:08.076 1851 2082 I WindowManager: ******** booted=true msg=false haveBoot=false haveApp=false haveWall=false wallEnabled=true haveKeyguard=true 01-02 12:13:09.894 1851 2082 V WindowManager: Wallpaper may change! Adjusting 01-02 12:13:09.908 1851 3413 V WindowManager: Wallpaper may change! Adjusting 01-02 12:13:10.178 1851 2082 I WindowManager: ******** booted=true msg=false haveBoot=false haveApp=false haveWall=true wallEnabled=true haveKeyguard=true 01-02 12:13:10.186 292 3736 I sf_stop_bootanim: 43587 01-02 12:13:10.191 1851 2082 I WindowManager: ******** booted=true msg=false haveBoot=false haveApp=false haveWall=true wallEnabled=true haveKeyguard=true 01-02 12:13:10.196 1851 2082 I WindowManager: ******** booted=true msg=false haveBoot=false haveApp=false haveWall=true wallEnabled=true haveKeyguard=true 01-02 12:13:10.397 1851 2082 I WindowManager: ******** booted=true msg=false haveBoot=false haveApp=false haveWall=true wallEnabled=true haveKeyguard=true
Then I'm doing an experiment to push a wallpaper_orig to the specified directory, although the error of BitmapFactory is missing. However, it is of little use to shorten the time.
It seems that this is not the exception and does not slow down the boot speed. But I noticed
01-02 12:13:10.178 1851 2082 I WindowManager: ******** booted=true msg=false haveBoot=false haveApp=false haveWall=true wallEnabled=true haveKeyguard=true 01-02 12:13:10.186 292 3736 I sf_stop_bootanim: 43587
Havewall = false before haveWall=true in this log. Havewall indicates that the system Window has successfully loaded the Wallpaper. Continuous output in log
WindowManager: Wallpaper may change! Adjusting
Why on earth does Wallpaper constantly adjust here? It seems that once the Wallpaper is adjusted, it will set haveWall to true.
The position of the following sentence log in the code is tracked:
frameworks/base/services/core/java/com/android/server/wm/WindowManagerService.java
private boolean checkWaitingForWindowsLocked() {
//Omit irrelevant code
if (DEBUG_SCREEN_ON || DEBUG_BOOT) {
Slog.i(TAG_WM, "******** booted=" + mSystemBooted + " msg=" + mShowingBootMessages
+ " haveBoot=" + haveBootMsg + " haveApp=" + haveApp
+ " haveWall=" + haveWallpaper + " wallEnabled=" + wallpaperEnabled
+ " haveKeyguard=" + haveKeyguard);
}
// If we are turning on the screen to show the boot message,
// don't do it until the boot message is actually displayed.
if (!mSystemBooted && !haveBootMsg) {
return true;
}
// If we are turning on the screen after the boot is completed
// normally, don't do so until we have the application and
// wallpaper.
if (mSystemBooted && ((!haveApp && !haveKeyguard) ||
(wallpaperEnabled && !haveWallpaper))) {
return true;
}
return false;
}This checkWaitingForWindowsLocked indicates whether the system needs to wait for Windows to be ready. Called by the performEnableScreen method in the WindowManagerService class
public void performEnableScreen() {
// Don't enable the screen until all existing windows have been drawn.
if (!mForceDisplayEnabled && checkWaitingForWindowsLocked()) {
return;
}
}
From the comments, performEnableScreen performs the action of activating the screen. However, before that, you need to wait for the system. The necessary windows have been drawn, that is, once my screen is activated, the drawn windows can be displayed immediately. Otherwise performEnableScreen will exit directly.
performEnableScreen is called by the enablesecreen afterboot method in the WindowManagerService class. The general calling process is as follows:
AMS prints boot_ progress_ enable_ Screen --- > call WMS's enablescreen afterboot --- > call WMS's performEnableScreen --- > call WMS's checkWaitingForWindowsLocked to check whether you can Enable Screen. Because the Wallpaper is not ready, checkWaitingForWindowsLocked returns true, resulting in performEnableScreen returning directly without performing the original Enable Screen action.
WindowManager: Wallpaper may change! Adjusting
It is printed in the code below.
frameworks/base/services/core/java/com/android/server/wm/WindowSurfacePlacer.java
// "Something has changed! Let's make it correct now."
private void performSurfacePlacementInner(boolean recoveringMemory) {
//Omit irrelevant code
if (mWallpaperMayChange) {
if (DEBUG_WALLPAPER_LIGHT)
Slog.v(TAG, "Wallpaper may change! Adjusting");
defaultDisplay.pendingLayoutChanges |= FINISH_LAYOUT_REDO_WALLPAPER;
if (DEBUG_LAYOUT_REPEATS) debugLayoutRepeats("WallpaperMayChange",
defaultDisplay.pendingLayoutChanges);
}
//Omit irrelevant code
}The debug call stack is as follows:
1-01 21:18:30.572 2912 2962 W System.err: java.lang.Exception: print stack 01-01 21:18:30.573 2912 2962 W System.err: at com.android.server.wm.WindowManagerService.checkWaitingForWindowsLocked(WindowManagerService.java:5841) 01-01 21:18:30.574 2912 2962 W System.err: at com.android.server.wm.WindowManagerService.performEnableScreen(WindowManagerService.java:5905) 01-01 21:18:30.575 2912 2962 W System.err: at com.android.server.wm.WindowManagerService$H.handleMessage(WindowManagerService.java:8390) 01-01 21:18:30.576 2912 2962 W System.err: at android.os.Handler.dispatchMessage(Handler.java:102) 01-01 21:18:30.577 2912 2962 W System.err: at android.os.Looper.loop(Looper.java:154) 01-01 21:18:30.578 2912 2962 W System.err: at android.os.HandlerThread.run(HandlerThread.java:61) 01-01 21:18:30.578 2912 2962 W System.err: at com.android.server.ServiceThread.run(ServiceThread.java:46)
There are no redundant operations in this area, and the check is not continued.
After the above analysis, the code is modified, and finally the startup speed of the problem machine reaches the standard of the reference machine. The performance problem is a process of continuous mining and improvement. There must be some areas that can be optimized during startup.
debug technical description
Summarize some debug ging techniques collected when analyzing this problem.
-
Print stack slog. In java code d("azhengye", "Stack=="+new RuntimeException("azhengye debug"). fillInStackTrace());
Or new exception ("print stack") printStackTrace(); Then search the log for "System.err:" -
c++ debug: in order to view the function call stack in native, you can add the following code where necessary.
#include <utils/CallStack.h>
android::CallStack stack;
stack.update();
String8 strtemp = stack.toString("");
ALOGD("\t%s", strtemp.string());
The filtered log s need to be transferred to another line with arm linux Android addr2line. Fortunately, there are ready-made scripts to help us do this, which are posted here.
#!/usr/bin/python
# stack symbol parser
import os
import string
import sys
ANDROID_TARGET_OUT = os.getcwd()+"/"
# addr2line tool path and symbol path
addr2line_tool = 'arm-linux-androideabi-addr2line'
symbol_dir = ANDROID_TARGET_OUT + '/symbols'
symbol_bin = symbol_dir + '/system/bin/'
symbol_lib = symbol_dir + '/system/lib/'
class ReadLog:
def __init__(self,filename):
self.logname = filename
def parse(self):
f = file(self.logname,'r')
lines = f.readlines()
if lines != []:
print 'read file ok'
else:
print 'read file failed'
result =[]
for line in lines:
if line.find('stack') != -1:
print 'stop search'
break
elif line.find('system') != -1:
#print 'find one item' + line
result.append(line)
return result
class ParseContent:
def __init__(self,addr,lib):
self.address = addr # pc address
self.exename = lib # executable or shared library
def addr2line(self):
cmd = addr2line_tool + " -C -f -s -e " + symbol_dir + self.exename + " " + self.address
#print cmd
stream = os.popen(cmd)
lines = stream.readlines();
list = map(string.strip,lines)
return list
inputarg = sys.argv
if len(inputarg) < 2:
print 'Please input panic log'
exit()
filename = inputarg[1]
readlog = ReadLog(filename)
inputlist = readlog.parse()
for item in inputlist:
itemsplit = item.split()
test = ParseContent(itemsplit[-2],itemsplit[-1])
list = test.addr2line()
print "%-30s%s" % (list[1],list[0])
imge compiled in the source code
Execute the above script under the folder, and use the script to debug the bootFinished of SF. The following is an output example.
01-02 01:38:13.305 477 3072 D azhengye : #00 pc 000059b9 /system/bin/bootanimation 01-02 01:38:13.305 477 3072 D azhengye : #01 pc 00006515 /system/bin/bootanimation 01-02 01:38:13.305 477 3072 D azhengye : #02 pc 0000591f /system/bin/bootanimation 01-02 01:38:13.305 477 3072 D azhengye : #03 pc 000054f1 /system/bin/bootanimation 01-02 01:38:13.305 477 3072 D azhengye : #04 pc 0000e349 /system/lib/libutils.so 01-02 01:38:13.305 477 3072 D azhengye : #05 pc 000473d3 /system/lib/libc.so 01-02 01:38:13.305 477 3072 D azhengye : #06 pc 0001a0c9 /system/lib/libc.so ------------------------------------------------------------------------------------ python panic.py /data/My_Doc/Performance/boot_c_log read file ok BootAnimation.cpp:534 android::BootAnimation::checkExit() BootAnimation.cpp:972 android::BootAnimation::playAnimation(android::BootAnimation::Animation const&) BootAnimation.cpp:870 android::BootAnimation::movie() BootAnimation.cpp:452 android::BootAnimation::threadLoop() Threads.cpp:751 android::Thread::_threadLoop(void*) pthread_create.cpp:198 (discriminator 1)__pthread_start(void*) clone.cpp:41 (discriminator 1)__start_thread
- Stack dump
adb shell kill -3 <pid>
The output trace will be saved in / data/anr / traces Txt file. Note that if there is no / data/anr / directory or / data/anr / traces Txt this file needs to be created manually and set the read and write permissions. For stack printing of native thread, you may need to modify Dalvik / VM / thread The dumpNativeThread method of CPP.
- debuggerd coredump this is the debug method found by analyzing the problem and checking the data. However, I have no practice and it is only for record reference.
Debuggerd is a daemon process of android. It is responsible for dumping the runtime information of the process for analysis in case of abnormal errors. The coredump data generated by debuggerd is presented in text form and saved in the / data/tombstone / directory. It can print the native stack of the current process without interrupting the process execution. The method of use is:
debuggerd -b <pid>
This can help us analyze the process execution behavior, and can also be used to locate the code location of deadlock or dead loop caused by wrong logic in the native process.
summary
Each manufacturer will customize different boot behaviors, so there is no fixed method to fix all boot problems. However, through this paper, we summarize and analyze the routine of this kind of problems, that is, pay attention to each event event in the boot stage, first quantify where the boot is slow, and then go to targeted optimization.
The source code is really a treasure house. Read more.
Article reprint: