問題描述

開機時間相對參考機過慢，大約慢15s左右。Android 系統7.0。

問題分析

開機問題涉及的層次較多，大致有bootloader-->kernel-->Zygote-->PMS-->AMS-->Launcher
可以藉助bootchart來分析，也可以直接通過log分析。不幸的是本專案機器因未知原因導致無法抓取到bootchart。
幸好在我瀏覽原始碼時發現了一個神器perfboot工具。具體在system/core/init/perfboot.py。
執行該命令需要在原始碼編譯環境下。詳細請參考原始碼檔案，此處不做過多介紹。
使用命令：
./perfboot.py --iterations=5 --interval=30 -v --output=/data/My_Doc/Performance/Bugs/bootup_op_4200151/J5D_UE.tsv

上圖X軸是開機啟動過程中的一些重要節點。Y軸是開機時間。
詳細說明下X軸上各個節點表徵的含義。

|boot_progress_start|系統進入使用者空間，標誌著kernel啟動完成，本例中可以看出kernel啟動耗時30s左右
|:---
|boot_progress_preload_start|Zygote啟動
|boot_progress_preload_end|Zygote結束
|boot_progress_system_run|SystemServer ready,開始啟動Android系統服務，如PMS，APMS等
|boot_progress_pms_start|PMS開始掃描安裝的應用
|boot_progress_pms_system_scan_start|PMS先行掃描/system目錄下的安裝包
|boot_progress_pms_data_scan_start|PMS掃描/data目錄下的安裝包
|boot_progress_pms_scan_end|PMS掃描結束
|boot_progress_pms_ready|PMS就緒
|boot_progress_ams_ready|AMS就緒
|boot_progress_enable_screen|AMS啟動完成後開始啟用螢幕，從此以後螢幕才能響應使用者的觸控，它在WindowManagerService發出退出開機動畫的時間節點之前，而真正退出開機動畫還會花費少許時間，具體依賴animation zip 包中的desc.txt。wm_boot_animation_done才是使用者感知到的動畫結束時間節點
|sf_stop_bootanim|SF設定service.bootanim.exit屬性值為1，標誌系統要結束開機動畫了，可以用來跟蹤開機動畫結尾部分消耗的時間
|wm_boot_animation_done|開機動畫結束，這一步使用者能直觀感受到開機結束
通過上圖可以直觀的看到問題機在進入boot_progress_start節點之前相對參考機耗時較多。而這之前主要涉及bootloader和kernel。

bootloader 優化

這一塊沒有接觸過，交給底層同事優化。大概說下抓取log的方式.

adb shell cat /proc/bootmsg > bootmsg.txt.

從log裡底層同事發現是bootimg簽名有問題，更詳細的分析，自己對這塊真心不懂，總結不出幫助性的意見。

kernel層優化

kernel的優化先check一遍config的配置，kernel中config的配置種類繁多，就算是工作幾年的kernel工程師也不一定能清楚每一個config值的作用。Android提供了一個基礎配置表。
可以用指令碼：kernel/scripts/kconfig/merge_config.sh來生成一份config檔案。具體用法

CONFIG_MTD_TESTS=m ----> m改為n
CONFIG_SERIAL_MSM_HSL=y ----> y改為n
CONFIG_SERIAL_MSM_HSL_CONSOLE=y ----> y改為n
CONFIG_MMC_BLOCK_TEST=m ---->註釋掉
CONFIG_MMC_TEST=m ---->註釋掉
CONFIG_SERIAL_MSM_HSL=y ----> y改為n
CONFIG_SERIAL_MSM_HSL_CONSOLE=y ----> y改為n
CONFIG_MSM_SMD_DEBUG=y ---->註釋掉
CONFIG_CGROUP_DEBUG=y ---->註釋掉
CONFIG_RELAY=y ---->註釋掉
CONFIG_RMNET_DATA_DEBUG_PKT=y ---->註釋掉
CONFIG_DEBUG_GPIO=y ---->註釋掉
CONFIG_CORESIGHT=y ---->註釋掉
CONFIG_CORESIGHT_EVENT=y ---->註釋掉
CONFIG_CORESIGHT_FUSE=y ---->註釋掉
CONFIG_CORESIGHT_CTI=y ---->註釋掉
CONFIG_CORESIGHT_TMC=y ---->註釋掉
CONFIG_CORESIGHT_TPIU=y ---->註釋掉
CONFIG_CORESIGHT_FUNNEL=y ---->註釋掉
CONFIG_CORESIGHT_REPLICATOR=y ---->註釋掉
CONFIG_CORESIGHT_STM=y ---->註釋掉
CONFIG_CORESIGHT_HWEVENT=y ---->註釋掉
CONFIG_DEBUG_MEMORY_INIT=y ---->註釋掉
CONFIG_DYNAMIC_DEBUG=y ---->註釋掉
//以下也全部註釋掉
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 

這裡說下config的配置有y,n,m，m表示編譯成模組，不編譯進核心。不配置的話相當於n。
CONFIG_DEBUG_INFO 不能去掉， 會引起CTS不過。由於config的的各項值可能散落在kernel的不同檔案中，我們可以單獨編譯下kernel，然後去out目錄下檢視obj/KERNEL_OBJ/.config 檔案，這裡面的配置項是完全的。

kernel關閉掉一些debug開關後。在新版本上覆測結果如下：

這裡提下如何看kernel的log，
開機後用命令：adb shell dmesg > dmesg.txt抓取Log
log裡面搜關鍵字"Bootloader start count"-->LK 啟動
“Bootloader end count”-->LK 結束
"Kernel MPM timestamp"-->bootloader執行完成

通過對bootloader和kernel的優化，直接減少了14s左右的開機時間，可以看到優化的效果還是比較明顯的。

frameworks層優化

用命令: adb logcat -b events|grep boot我們過濾出啟動階段的主要事件。

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

結合對比圖看，boot_progress_enable_screen之前問題機跟對比機各個節點耗時相差不大。在這裡說明下，Android M上啟動階段到boot_progress_enable_screen就結束了，而Android N上還多了sf_stop_bootanim和wm_boot_animation_done兩個事件。這也就是圖-優化kernel後棕紅色的線條到boot_progress_enable_screen就沒有延生的原因，因為它表示的參考機，而參考機正好是Android M系統。
從log的時間戳可以看出:
boot_progress_enable_screen--->花費2s左右的時間到達sf_stop_bootanim--->花費1s多時間到達wm_boot_animation_done。多出來的兩個過程總共多花接近4s的時間。
我們要重點看下這個過程發生了什麼，為什麼會多出來這近4s時間。

1.先看下boot_progress_enable_screen出現的位置。
它在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_bootanim出現的位置。
它在frameworks/native/services/surfaceflinger/SurfaceFlinger_hwc1.cpp。
這裡特別說明下SurfaceFlinger_hwc1.cpp是SurfaceFlinger.cpp的升級版，它支援HWC 2.0，使用的是SurfaceFlinger.cpp還是SurfaceFlinger_hwc1.cpp跟平臺選擇相關。

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_done出現的位置。
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());
    ...
}

找到了3個節點出現的位置，現在再來分析如何將這3個節點串聯起來。
1-->2過程： AMS的enableScreenAfterBoot呼叫WMS的enableScreenAfterBoot方法，在WMS中的enableScreenAfterBoot會繼續呼叫內部方法performEnableScreen，該方法內部判斷開機動畫如果沒有停止，就呼叫SurfaceFlinger去停止開機動畫

surfaceFlinger.transact(IBinder.FIRST_CALL_TRANSACTION, // BOOT_FINISHED
                                data, null, 0);

這裡的FIRST_CALL_TRANSACTION實際上就是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.transact發出的呼叫請求會被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;
            }
    }
    ...
}

這裡的bootFinished就是SurfaceFlinger_hwc1.cpp定義的bootFinished()方法，最終來到了第2個節點sf_stop_bootanim。
為了驗證上述呼叫過程，我們新增上列印呼叫棧的log看看輸出。

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

上述log也印證了之前的分析，至此1-->2的過程算是通了。在來看2-->3過程，在3節點出現之前還有一次判斷：

if (!mForceDisplayEnabled && !checkBootAnimationCompleteLocked()) {
                if (DEBUG_BOOT) Slog.i(TAG_WM, "performEnableScreen: Waiting for anim complete");
                return;
}

這裡系統需要去檢測開機動畫是否還在播放，

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是在初始化SurfaceFlinger時啟動的。
frameworks/native/services/surfaceflinger/SurfaceFlinger_hwc1.cpp

void SurfaceFlinger::init() {
    ...
    // start boot animation
    startBootAnim();
}

順藤摸瓜來到了BootAnimation，前面分析過在SurfaceFlinger的bootFinished方法中將"service.bootanim.exit"置為了1，這個設定在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();
        }
    }
}

跟蹤到這2-->3過程也就通暢了。在理清了該過程的呼叫邏輯後，問題也浮出了水面。原來之前的同事在解決一個開機進桌面出現黑屏問題時，在checkExit內部人為delay了幾秒的時間...

在排查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)

adb shell 進入手機發現確實沒有/data/system/users/0/wallpaper_orig檔案。
會不會是是wallpaper異常導致消耗時間多餘呢?
為了清晰debug在過濾下log

adb logcat -b all|grep -E "Wallpaper may change|haveWall|sf_stop_bootanim|boot_progress_enable_screen"

輸出如下log：

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

然後在做實驗push一個wallpaper_orig到指定目錄，BitmapFactory的錯誤雖然不見了。然而對於縮短時間並沒有什麼卵用。
看來不是這個異常沒有拖慢開機速度。但我注意到

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

這段log中haveWall=true之前一直都是haveWall=false,haveWall表示系統Window已經成功載入好了Wallpaper。Log中不斷的輸出
WindowManager: Wallpaper may change! Adjusting
這裡究竟為什麼Wallpaper會不斷的Adjusting呢?看起來一旦Wallpaper調整好就會將haveWall置true。
追蹤了下該句log在程式碼中的位置：
frameworks/base/services/core/java/com/android/server/wm/WindowManagerService.java

private boolean checkWaitingForWindowsLocked() {
        //省略無關程式碼

        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;
    }

這個checkWaitingForWindowsLocked表示是否需要等待系統Windows就緒。被同在WindowManagerService類中的performEnableScreen方法呼叫

public void performEnableScreen() {
        // Don't enable the screen until all existing windows have been drawn.
        if (!mForceDisplayEnabled && checkWaitingForWindowsLocked()) {
            return;
        }
}

從註釋看performEnableScreen執行的是啟用螢幕動作，然而在此之前需要等待系統必要的windows已經被畫好了，也就是說我螢幕一旦激活了，繪製好的windows就能馬上顯示出來。否則performEnableScreen直接就退出了。
而performEnableScreen又是被同在WindowManagerService類中enableScreenAfterBoot方法呼叫。大致的呼叫過程如下：
AMS打印出boot_progress_enable_screen---->呼叫WMS的enableScreenAfterBoot--->呼叫WMS的performEnableScreen--->呼叫WMS的checkWaitingForWindowsLocked檢查是否可以Enable Screen，因為Wallpaper沒有準備好，因此checkWaitingForWindowsLocked返回了true，進而導致performEnableScreen直接返回，沒有去執行本來要做的Enable Screen動作。

WindowManager: Wallpaper may change! Adjusting
是在下面的code打印出來的。
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) {
        //省略無關程式碼
        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);
        }
       //省略無關程式碼
}

debug呼叫棧如下：

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)

這塊沒有檢查出多餘的操作，沒繼續check了。
經過以上分析後修改程式碼，最終問題機的開機速度達到了參考機的標準。效能問題是一個持續挖掘改善的過程，開機過程中還能優化的地方肯定還有。

debug 技術說明

彙總下分析該問題時，彙集的一些debug技術。

• java程式碼中列印堆疊 Slog.d("azhengye", "Stack=="+new RuntimeException("azhengye debug").fillInStackTrace());
  或者new Exception("print stack").printStackTrace(); 然後log中搜索"System.err:"

• c++ debug: 為了在native檢視函式呼叫棧可以在需要的地方新增如下程式碼。
  #include <utils/CallStack.h>
  android::CallStack stack;
  stack.update();
  String8 strtemp = stack.toString("");
  ALOGD("\t%s", strtemp.string());
  過濾出的log還需要用arm-linux-androideabi-addr2line轉行下，好在有現成的指令碼幫我們做這件事，這裡一併貼出來。

#!/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資料夾下執行上面的指令碼，除錯 SF 的bootFinished就用的該指令碼，下面是個輸出例子。

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

• 堆疊dump

  adb shell kill -3 <pid>

輸出的trace會儲存在 /data/anr/traces.txt檔案中。這個需要注意，如果沒有 /data/anr/這個目錄 或/data/anr/traces.txt這個檔案，需要手工建立一下，並設定好讀寫許可權。如果是native thread的堆疊列印，可能需要修改dalvik/vm/Thread.cpp的dumpNativeThread方法。

• debuggerd coredump 這個是開始分析問題查資料找到的debug方法，不過自己沒有實踐，僅作記錄參考。
  debuggerd是android的一個daemon程序，負責在程序異常出錯時，將程序的執行時資訊dump出來供分析。debuggerd生成的coredump資料是以文字形式呈現，被儲存在 /data/tombstone/ 目錄下，它可以在不中斷程序執行的情況下列印當前程序的native堆疊。使用方法是:

debuggerd -b <pid>

這可以協助我們分析程序執行行為，也可以用來定位native程序中鎖死或錯誤邏輯引起的死迴圈的程式碼位置。

總結

各家廠商都會定製不同的開機行為，因此沒有一個固定的方法能fix所有的開機問題，但通過本文我們總結分析該類問題的套路，那就是關注boot階段的各個event事件，先量化出開機慢在哪裡，然後在去針對性的優化。
原始碼真的是個寶庫，多讀吧。