前言开机阶段描述先用命令:adb logcat -b events|grep boot过滤出启动阶段的主要事件。可以看到关键log基本把开机的每一步都打印了出来01-01 08:00:18.096 591 591 I boot_progress_start: 12229 01-01 08:00:19.291 591 591 I boot_progress_preload_start: 13425 01-01 08:00:21.902 591 591 I boot_progress_preload_end: 16035 01-01 08:00:22.196 1504 1504 I boot_progress_system_run: 16330 01-01 08:00:22.817 1504 1504 I boot_progress_pms_start: 16950 01-01 08:00:23.189 1504 1504 I boot_progress_pms_system_scan_start: 17322 01-01 08:00:25.347 1504 1504 I boot_progress_pms_data_scan_start: 19480 01-01 08:00:25.462 1504 1504 I boot_progress_pms_scan_end: 19595 01-01 08:00:25.626 1504 1504 I boot_progress_pms_ready: 19759 05-08 18:46:58.709 1504 1504 I boot_progress_ams_ready: 20802 05-08 18:47:00.093 1504 1632 I boot_progress_enable_screen: 22187 05-08 18:47:01.931 742 2191 I sf_stop_bootanim: 24024 05-08 18:47:01.934 1504 1632 I wm_boot_animation_done: 24027阶段描述boot_progress_start系统进入用户空间标志着kernel启动完成boot_progress_preload_startZygote启动boot_progress_preload_endZygote结束boot_progress_system_runSystemServer ready,开始启动Android系统服务boot_progress_pms_startPMS开始扫描安装的应用boot_progress_pms_system_scan_startPMS先行扫描/system目录下的安装包boot_progress_pms_data_scan_startPMS扫描/data目录下的安装包boot_progress_pms_scan_endPMS扫描结束boot_progress_pms_readyPMS就绪boot_progress_ams_readyAMS就绪boot_progress_enable_screenAMS启动完成后开始激活屏幕从此以后屏幕才能响应用户的触摸它在WindowManagerService发出退出开机动画的时间节点之前sf_stop_bootanimSF设置service.bootanim.exit属性值为1标志系统要结束开机动画了wm_boot_animation_done开机动画结束这一步用户能直观感受到开机结束一.各个阶段对应的代码1. boot_progress_startframeworks/base/core/jni/AndroidRuntime.cppvoid AndroidRuntime::start(const char* className, const VectorString8 options, bool zygote){.../** startSystemServer true means runtime is obsolete and not run from* init.rc anymore, so we print out the boot start event here.*/for (size_t i 0; i options.size(); i) {if (options[i] startSystemServer) {primary_zygote true;/* track our progress through the boot sequence */const intLOG_BOOT_PROGRESS_START 3000;//日志打印LOG_EVENT_LONG(LOG_BOOT_PROGRESS_START, ns2ms(systemTime(SYSTEM_TIME_MONOTONIC)));}}...}对应的3000boot_progress_start (time|2|3)2. boot_progress_preload_start3. boot_progress_preload_end/frameworks/base/core/java/com/android/internal/os/ZygoteInit.javaprivate static final intLOG_BOOT_PROGRESS_PRELOAD_START 3020;private static final intLOG_BOOT_PROGRESS_PRELOAD_END 3030;public static void main(String[] argv) {...// In some configurations, we avoid preloading resources and classes eagerly.// In such cases, we will preload things prior to our first fork.if (!enableLazyPreload) {bootTimingsTraceLog.traceBegin(ZygotePreload);EventLog.writeEvent(LOG_BOOT_PROGRESS_PRELOAD_START,SystemClock.uptimeMillis());preload(bootTimingsTraceLog); //输出日志EventLog.writeEvent(LOG_BOOT_PROGRESS_PRELOAD_END, SystemClock.uptimeMillis());bootTimingsTraceLog.traceEnd(); // ZygotePreload}// Do an initial gc to clean up after startupbootTimingsTraceLog.traceBegin(PostZygoteInitGC);gcAndFinalize();bootTimingsTraceLog.traceEnd(); // PostZygoteInitGCbootTimingsTraceLog.traceEnd(); // ZygoteInitZygote.initNativeState(isPrimaryZygote);/// M: Added for BOOTPROFaddBootEvent(Zygote:Preload End);...}system/logging/logcat/event.logtags# ZygoteInit class preloading starts:3020boot_progress_preload_start (time|2|3) # ZygoteInit class preloading ends:3030boot_progress_preload_end (time|2|3)4. boot_progress_system_runframeworks/base/services/java/com/android/server/SystemServer.javaprivate void run() { ...// Here we go!Slog.i(TAG, Entered the Android system server!); final long uptimeMillis SystemClock.elapsedRealtime(); EventLog.writeEvent(EventLogTags.BOOT_PROGRESS_SYSTEM_RUN, uptimeMillis); if (!mRuntimeRestart) { FrameworkStatsLog.write(FrameworkStatsLog.BOOT_TIME_EVENT_ELAPSED_TIME_REPORTED, FrameworkStatsLog .BOOT_TIME_EVENT_ELAPSED_TIME__EVENT__SYSTEM_SERVER_INIT_START, uptimeMillis); } ... }5. boot_progress_pms_startframeworks/base/services/core/java/com/android/server/pm/PackageManagerService.javapublic PackageManagerService(Injector injector, boolean onlyCore, boolean factoryTest) { ... mInjector injector; mInjector.bootstrap(this); mLock injector.getLock(); mInstallLock injector.getInstallLock(); LockGuard.installLock(mLock, LockGuard.INDEX_PACKAGES); EventLog.writeEvent(EventLogTags.BOOT_PROGRESS_PMS_START, SystemClock.uptimeMillis()); ... }6. boot_progress_pms_system_scan_startframeworks/base/services/core/java/com/android/server/pm/PackageManagerService.javapublic PackageManagerService(Injector injector, boolean onlyCore, boolean factoryTest) { ... long startTime SystemClock.uptimeMillis(); EventLog.writeEvent(EventLogTags.BOOT_PROGRESS_PMS_SYSTEM_SCAN_START, startTime); final String bootClassPath System.getenv(BOOTCLASSPATH); final String systemServerClassPath System.getenv(SYSTEMSERVERCLASSPATH); if (bootClassPath null) { Slog.w(TAG, No BOOTCLASSPATH found!); } if (systemServerClassPath null) { Slog.w(TAG, No SYSTEMSERVERCLASSPATH found!); } ... }7. boot_progress_pms_data_scan_startframeworks/base/services/core/java/com/android/server/pm/PackageManagerService.javapublic PackageManagerService(Injector injector, boolean onlyCore, boolean factoryTest) { ... // Remove any shared userIDs that have no associated packages mSettings.pruneSharedUsersLPw(); final long systemScanTime SystemClock.uptimeMillis() - startTime; final int systemPackagesCount mPackages.size(); Slog.i(TAG, Finished scanning system apps. Time: systemScanTime ms, packageCount: systemPackagesCount , timePerPackage: (systemPackagesCount 0 ? 0 : systemScanTime / systemPackagesCount) , cached: cachedSystemApps); if (mIsUpgrade systemPackagesCount 0) { //CHECKSTYLE:OFF IndentationCheck FrameworkStatsLog.write(FrameworkStatsLog.BOOT_TIME_EVENT_DURATION_REPORTED, BOOT_TIME_EVENT_DURATION__EVENT__OTA_PACKAGE_MANAGER_SYSTEM_APP_AVG_SCAN_TIME, systemScanTime / systemPackagesCount); //CHECKSTYLE:ON IndentationCheck } if (!mOnlyCore) { EventLog.writeEvent(EventLogTags.BOOT_PROGRESS_PMS_DATA_SCAN_START, SystemClock.uptimeMillis()); scanDirTracedLI(sAppInstallDir, 0, scanFlags | SCAN_REQUIRE_KNOWN, 0, packageParser, executorService); } ... }8. boot_progress_pms_scan_endframeworks/base/services/core/java/com/android/server/pm/PackageManagerService.javapublic PackageManagerService(Injector injector, boolean onlyCore, boolean factoryTest) { ... // Now that we know all the packages we are keeping, // read and update their last usage times. mPackageUsage.read(mSettings.mPackages); mCompilerStats.read(); EventLog.writeEvent(EventLogTags.BOOT_PROGRESS_PMS_SCAN_END, SystemClock.uptimeMillis()); //显示扫描时间 Slog.i(TAG, Time to scan packages: ((SystemClock.uptimeMillis()-startTime)/1000f) seconds); ... }9. boot_progress_pms_readyframeworks/base/services/core/java/com/android/server/pm/PackageManagerService.javapublic PackageManagerService(Injector injector, boolean onlyCore, boolean factoryTest) { ... // can downgrade to reader t.traceBegin(write settings); mSettings.writeLPr(); t.traceEnd(); EventLog.writeEvent(EventLogTags.BOOT_PROGRESS_PMS_READY, SystemClock.uptimeMillis()); ... }10. boot_progress_ams_readyframeworks/base/services/core/java/com/android/server/am/ActivityManagerService.javapublic void systemReady(final Runnable goingCallback, NonNull TimingsTraceAndSlog t) { ...**** t.traceEnd(); // KillProcesses Slog.i(TAG, System now ready); EventLogTags.writeBootProgressAmsReady(SystemClock.uptimeMillis()); t.traceBegin(updateTopComponentForFactoryTest); mAtmInternal.updateTopComponentForFactoryTest(); t.traceEnd(); ... }11. boot_progress_enable_screenframeworks/base/services/core/java/com/android/server/wm/ActivityTaskManagerService.javaOverride public void enableScreenAfterBoot(boolean booted) {writeBootProgressEnableScreen(SystemClock.uptimeMillis()); mWindowManager.enableScreenAfterBoot(); synchronized (mGlobalLock) { updateEventDispatchingLocked(booted); } }12. sf_stop_bootanimframeworks/native/services/surfaceflinger/SurfaceFlinger.cppvoid 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 intLOGTAG_SF_STOP_BOOTANIM 60110; LOG_EVENT_LONG(LOGTAG_SF_STOP_BOOTANIM, ns2ms(systemTime(SYSTEM_TIME_MONOTONIC))); spIBinder input(defaultServiceManager()-getService(String16(inputflinger))); ... }frameworks/native/services/surfaceflinger/EventLog/EventLogTags.logtags60100sf_frame_dur (window|3),(dur0|1),(dur1|1),(dur2|1),(dur3|1),(dur4|1),(dur5|1),(dur6|1) 39 60110 sf_stop_bootanim (time|2|3)13. wm_boot_animation_doneframeworks/base/services/core/java/com/android/server/wm/WindowManagerService.javaprivate void performEnableScreen() { ... try { IBinder surfaceFlinger ServiceManager.getService(SurfaceFlinger); if (surfaceFlinger ! null) { ProtoLog.i(WM_ERROR, ******* 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) { ProtoLog.e(WM_ERROR, Boot completed: SurfaceFlinger is dead!); } EventLogTags.writeWmBootAnimationDone(SystemClock.uptimeMillis()); Trace.asyncTraceEnd(TRACE_TAG_WINDOW_MANAGER, Stop bootanim, 0); mDisplayEnabled true; ProtoLog.i(WM_DEBUG_SCREEN_ON,******************** ENABLINGSCREEN!); ... }二. 案例:开机动画时间长.从日志中发现,boot_progress_ams_ready --sf_stop_bootanim 花费的时间特别长,消耗了27秒.从kernel 层开机开始统计.实例3.1 log// Linux kernel start[0.000000] Booting Linux on physical CPU 0x10014[1.765707] [01-29 01:33:34.500]init: init first stage started!14[3.709000] [01-29 01:33:36.439]init: init second stage started!//Kernel startup completed, 9462 means cost 9.462 seconds01-29 01:33:41.223 478 478 I boot_progress_start: 9462//zygote starts up01-29 01:33:44.894 478 478 I boot_progress_preload_start: 13133//zygote startup completed01-29 01:33:49.997 478 478 I boot_progress_preload_end: 18236//system server ready01-29 01:33:51.088 1257 1257 I boot_progress_system_run: 19327//PM scans the installation packages in the /system directory01-29 01:33:52.213 1257 1257 I boot_progress_pms_start: 20452////PM scans the installation packages in the /data directory01-29 01:33:53.918 1257 1257 I boot_progress_pms_data_scan_start: 22157//PM ends scanning01-29 01:33:53.947 1257 1257 I boot_progress_pms_scan_end: 22186//PM ready01-29 01:33:54.172 1257 1257 I boot_progress_pms_ready: 22410//The system has calibrated the time and there was a time jump01-29 01:33:54.588 1257 1257 I AlarmManager: Current time only 2396034588,advancing to build time 172129720600007-18 18:06:46.000 1257 1257 W AlarmManagerService: Unable to set rtc to1721297206: No such device3.2 log// bootup logo ATT amiGO Jr watch end// The startup animation(ATT Logo) starts playing07-18 18:06:47.414 897 1003 D bootanimation: TrackPlayerBase::TrackPlayerBase()//AM ready and waiting for the screen to be ready//Even after the system animation has finished, it will continue to display until all //system servers and core system applications have started completely.07-18 18:06:47.9081257 1257 I boot_progress_ams_ready: 24733//surfaceflinger stops boot animation07-18 18:07:20.408599 1396 I sf_stop_bootanim: 57236//Boot animation ends07-18 18:07:20.409 1257 1347 I wm_boot_animation_done: 57237发现异常点:开机能完成,是通过timeout的方式触发的.07-11 05:16:09.363 1366 1485 I WindowManager: shouldWaitForSystemDecorWindowsOnBoot haveApp:true,haveKeyguard:true,wallpaperEnabled:true,haveWallpaper:false07-11 05:16:12.663 1366 1485 I WindowManager: shouldWaitForSystemDecorWindowsOnBoot haveApp:true,haveKeyguard:true,wallpaperEnabled:true,haveWallpaper:false07-11 17:16:39.328 1366 1485 W WindowManager:***** BOOT TIMEOUT: forcing display enabled找到对应的代码:3382 public void enableScreenAfterBoot() {3383 synchronized (mGlobalLock) {3384 ProtoLog.i(WM_DEBUG_BOOT, enableScreenAfterBoot: mDisplayEnabled%b 3385 mForceDisplayEnabled%b mShowingBootMessages%b mSystemBooted%b. 3386 %s,3387 mDisplayEnabled, mForceDisplayEnabled, mShowingBootMessages, mSystemBooted,3388 new RuntimeException(here).fillInStackTrace());3389 if (mSystemBooted) {3390 return;3391 }3392 mSystemBooted true;3393 hideBootMessagesLocked();3394// If the screen still doesnt come up after 30 seconds, give3395// up and turn it on.3396 mH.sendEmptyMessageDelayed(H.BOOT_TIMEOUT,30 * 1000);3397 }然后,再查看出现原因是什么:怀疑SystemUI wallpaperservice 被移除,而没有禁止wallpaper的原因.3812 // If we are turning on the screen to show the boot message, dont do it until the boot3813 // message is actually displayed.3814 if (!mWmService.mSystemBooted !haveBootMsg) {3815 return true;3816 }38173818 // If we are turning on the screen after the boot is completed normally, dont do so until3819 // we have the application and wallpaper.3820 if (mWmService.mSystemBooted3821 ((!haveApp !haveKeyguard) || (wallpaperEnabled !haveWallpaper))) {3822 return true;3823 }通过加日志,调试:07-11 05:16:09.363 1366 1485 I WindowManager: shouldWaitForSystemDecorWindowsOnBoot haveApp:true,haveKeyguard:true,wallpaperEnabled:true,haveWallpaper:false07-11 05:16:12.663 1366 1485 I WindowManager: shouldWaitForSystemDecorWindowsOnBoot haveApp:true,haveKeyguard:true,wallpaperEnabled:true,haveWallpaper:false07-11 17:16:39.328 1366 1485 W WindowManager: ***** BOOT TIMEOUT: forcing display enabled根本原因:在做项目裁剪时,因为觉得wallpaper 没有用到,将wallpaper service移除,但是, 系统有需要支持wallpaper,所以只是在systemui 中移除,造成此问题. 开机过程关键日志记录和介绍
前言开机阶段描述先用命令:adb logcat -b events|grep boot过滤出启动阶段的主要事件。可以看到关键log基本把开机的每一步都打印了出来01-01 08:00:18.096 591 591 I boot_progress_start: 12229 01-01 08:00:19.291 591 591 I boot_progress_preload_start: 13425 01-01 08:00:21.902 591 591 I boot_progress_preload_end: 16035 01-01 08:00:22.196 1504 1504 I boot_progress_system_run: 16330 01-01 08:00:22.817 1504 1504 I boot_progress_pms_start: 16950 01-01 08:00:23.189 1504 1504 I boot_progress_pms_system_scan_start: 17322 01-01 08:00:25.347 1504 1504 I boot_progress_pms_data_scan_start: 19480 01-01 08:00:25.462 1504 1504 I boot_progress_pms_scan_end: 19595 01-01 08:00:25.626 1504 1504 I boot_progress_pms_ready: 19759 05-08 18:46:58.709 1504 1504 I boot_progress_ams_ready: 20802 05-08 18:47:00.093 1504 1632 I boot_progress_enable_screen: 22187 05-08 18:47:01.931 742 2191 I sf_stop_bootanim: 24024 05-08 18:47:01.934 1504 1632 I wm_boot_animation_done: 24027阶段描述boot_progress_start系统进入用户空间标志着kernel启动完成boot_progress_preload_startZygote启动boot_progress_preload_endZygote结束boot_progress_system_runSystemServer ready,开始启动Android系统服务boot_progress_pms_startPMS开始扫描安装的应用boot_progress_pms_system_scan_startPMS先行扫描/system目录下的安装包boot_progress_pms_data_scan_startPMS扫描/data目录下的安装包boot_progress_pms_scan_endPMS扫描结束boot_progress_pms_readyPMS就绪boot_progress_ams_readyAMS就绪boot_progress_enable_screenAMS启动完成后开始激活屏幕从此以后屏幕才能响应用户的触摸它在WindowManagerService发出退出开机动画的时间节点之前sf_stop_bootanimSF设置service.bootanim.exit属性值为1标志系统要结束开机动画了wm_boot_animation_done开机动画结束这一步用户能直观感受到开机结束一.各个阶段对应的代码1. boot_progress_startframeworks/base/core/jni/AndroidRuntime.cppvoid AndroidRuntime::start(const char* className, const VectorString8 options, bool zygote){.../** startSystemServer true means runtime is obsolete and not run from* init.rc anymore, so we print out the boot start event here.*/for (size_t i 0; i options.size(); i) {if (options[i] startSystemServer) {primary_zygote true;/* track our progress through the boot sequence */const intLOG_BOOT_PROGRESS_START 3000;//日志打印LOG_EVENT_LONG(LOG_BOOT_PROGRESS_START, ns2ms(systemTime(SYSTEM_TIME_MONOTONIC)));}}...}对应的3000boot_progress_start (time|2|3)2. boot_progress_preload_start3. boot_progress_preload_end/frameworks/base/core/java/com/android/internal/os/ZygoteInit.javaprivate static final intLOG_BOOT_PROGRESS_PRELOAD_START 3020;private static final intLOG_BOOT_PROGRESS_PRELOAD_END 3030;public static void main(String[] argv) {...// In some configurations, we avoid preloading resources and classes eagerly.// In such cases, we will preload things prior to our first fork.if (!enableLazyPreload) {bootTimingsTraceLog.traceBegin(ZygotePreload);EventLog.writeEvent(LOG_BOOT_PROGRESS_PRELOAD_START,SystemClock.uptimeMillis());preload(bootTimingsTraceLog); //输出日志EventLog.writeEvent(LOG_BOOT_PROGRESS_PRELOAD_END, SystemClock.uptimeMillis());bootTimingsTraceLog.traceEnd(); // ZygotePreload}// Do an initial gc to clean up after startupbootTimingsTraceLog.traceBegin(PostZygoteInitGC);gcAndFinalize();bootTimingsTraceLog.traceEnd(); // PostZygoteInitGCbootTimingsTraceLog.traceEnd(); // ZygoteInitZygote.initNativeState(isPrimaryZygote);/// M: Added for BOOTPROFaddBootEvent(Zygote:Preload End);...}system/logging/logcat/event.logtags# ZygoteInit class preloading starts:3020boot_progress_preload_start (time|2|3) # ZygoteInit class preloading ends:3030boot_progress_preload_end (time|2|3)4. boot_progress_system_runframeworks/base/services/java/com/android/server/SystemServer.javaprivate void run() { ...// Here we go!Slog.i(TAG, Entered the Android system server!); final long uptimeMillis SystemClock.elapsedRealtime(); EventLog.writeEvent(EventLogTags.BOOT_PROGRESS_SYSTEM_RUN, uptimeMillis); if (!mRuntimeRestart) { FrameworkStatsLog.write(FrameworkStatsLog.BOOT_TIME_EVENT_ELAPSED_TIME_REPORTED, FrameworkStatsLog .BOOT_TIME_EVENT_ELAPSED_TIME__EVENT__SYSTEM_SERVER_INIT_START, uptimeMillis); } ... }5. boot_progress_pms_startframeworks/base/services/core/java/com/android/server/pm/PackageManagerService.javapublic PackageManagerService(Injector injector, boolean onlyCore, boolean factoryTest) { ... mInjector injector; mInjector.bootstrap(this); mLock injector.getLock(); mInstallLock injector.getInstallLock(); LockGuard.installLock(mLock, LockGuard.INDEX_PACKAGES); EventLog.writeEvent(EventLogTags.BOOT_PROGRESS_PMS_START, SystemClock.uptimeMillis()); ... }6. boot_progress_pms_system_scan_startframeworks/base/services/core/java/com/android/server/pm/PackageManagerService.javapublic PackageManagerService(Injector injector, boolean onlyCore, boolean factoryTest) { ... long startTime SystemClock.uptimeMillis(); EventLog.writeEvent(EventLogTags.BOOT_PROGRESS_PMS_SYSTEM_SCAN_START, startTime); final String bootClassPath System.getenv(BOOTCLASSPATH); final String systemServerClassPath System.getenv(SYSTEMSERVERCLASSPATH); if (bootClassPath null) { Slog.w(TAG, No BOOTCLASSPATH found!); } if (systemServerClassPath null) { Slog.w(TAG, No SYSTEMSERVERCLASSPATH found!); } ... }7. boot_progress_pms_data_scan_startframeworks/base/services/core/java/com/android/server/pm/PackageManagerService.javapublic PackageManagerService(Injector injector, boolean onlyCore, boolean factoryTest) { ... // Remove any shared userIDs that have no associated packages mSettings.pruneSharedUsersLPw(); final long systemScanTime SystemClock.uptimeMillis() - startTime; final int systemPackagesCount mPackages.size(); Slog.i(TAG, Finished scanning system apps. Time: systemScanTime ms, packageCount: systemPackagesCount , timePerPackage: (systemPackagesCount 0 ? 0 : systemScanTime / systemPackagesCount) , cached: cachedSystemApps); if (mIsUpgrade systemPackagesCount 0) { //CHECKSTYLE:OFF IndentationCheck FrameworkStatsLog.write(FrameworkStatsLog.BOOT_TIME_EVENT_DURATION_REPORTED, BOOT_TIME_EVENT_DURATION__EVENT__OTA_PACKAGE_MANAGER_SYSTEM_APP_AVG_SCAN_TIME, systemScanTime / systemPackagesCount); //CHECKSTYLE:ON IndentationCheck } if (!mOnlyCore) { EventLog.writeEvent(EventLogTags.BOOT_PROGRESS_PMS_DATA_SCAN_START, SystemClock.uptimeMillis()); scanDirTracedLI(sAppInstallDir, 0, scanFlags | SCAN_REQUIRE_KNOWN, 0, packageParser, executorService); } ... }8. boot_progress_pms_scan_endframeworks/base/services/core/java/com/android/server/pm/PackageManagerService.javapublic PackageManagerService(Injector injector, boolean onlyCore, boolean factoryTest) { ... // Now that we know all the packages we are keeping, // read and update their last usage times. mPackageUsage.read(mSettings.mPackages); mCompilerStats.read(); EventLog.writeEvent(EventLogTags.BOOT_PROGRESS_PMS_SCAN_END, SystemClock.uptimeMillis()); //显示扫描时间 Slog.i(TAG, Time to scan packages: ((SystemClock.uptimeMillis()-startTime)/1000f) seconds); ... }9. boot_progress_pms_readyframeworks/base/services/core/java/com/android/server/pm/PackageManagerService.javapublic PackageManagerService(Injector injector, boolean onlyCore, boolean factoryTest) { ... // can downgrade to reader t.traceBegin(write settings); mSettings.writeLPr(); t.traceEnd(); EventLog.writeEvent(EventLogTags.BOOT_PROGRESS_PMS_READY, SystemClock.uptimeMillis()); ... }10. boot_progress_ams_readyframeworks/base/services/core/java/com/android/server/am/ActivityManagerService.javapublic void systemReady(final Runnable goingCallback, NonNull TimingsTraceAndSlog t) { ...**** t.traceEnd(); // KillProcesses Slog.i(TAG, System now ready); EventLogTags.writeBootProgressAmsReady(SystemClock.uptimeMillis()); t.traceBegin(updateTopComponentForFactoryTest); mAtmInternal.updateTopComponentForFactoryTest(); t.traceEnd(); ... }11. boot_progress_enable_screenframeworks/base/services/core/java/com/android/server/wm/ActivityTaskManagerService.javaOverride public void enableScreenAfterBoot(boolean booted) {writeBootProgressEnableScreen(SystemClock.uptimeMillis()); mWindowManager.enableScreenAfterBoot(); synchronized (mGlobalLock) { updateEventDispatchingLocked(booted); } }12. sf_stop_bootanimframeworks/native/services/surfaceflinger/SurfaceFlinger.cppvoid 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 intLOGTAG_SF_STOP_BOOTANIM 60110; LOG_EVENT_LONG(LOGTAG_SF_STOP_BOOTANIM, ns2ms(systemTime(SYSTEM_TIME_MONOTONIC))); spIBinder input(defaultServiceManager()-getService(String16(inputflinger))); ... }frameworks/native/services/surfaceflinger/EventLog/EventLogTags.logtags60100sf_frame_dur (window|3),(dur0|1),(dur1|1),(dur2|1),(dur3|1),(dur4|1),(dur5|1),(dur6|1) 39 60110 sf_stop_bootanim (time|2|3)13. wm_boot_animation_doneframeworks/base/services/core/java/com/android/server/wm/WindowManagerService.javaprivate void performEnableScreen() { ... try { IBinder surfaceFlinger ServiceManager.getService(SurfaceFlinger); if (surfaceFlinger ! null) { ProtoLog.i(WM_ERROR, ******* 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) { ProtoLog.e(WM_ERROR, Boot completed: SurfaceFlinger is dead!); } EventLogTags.writeWmBootAnimationDone(SystemClock.uptimeMillis()); Trace.asyncTraceEnd(TRACE_TAG_WINDOW_MANAGER, Stop bootanim, 0); mDisplayEnabled true; ProtoLog.i(WM_DEBUG_SCREEN_ON,******************** ENABLINGSCREEN!); ... }二. 案例:开机动画时间长.从日志中发现,boot_progress_ams_ready --sf_stop_bootanim 花费的时间特别长,消耗了27秒.从kernel 层开机开始统计.实例3.1 log// Linux kernel start[0.000000] Booting Linux on physical CPU 0x10014[1.765707] [01-29 01:33:34.500]init: init first stage started!14[3.709000] [01-29 01:33:36.439]init: init second stage started!//Kernel startup completed, 9462 means cost 9.462 seconds01-29 01:33:41.223 478 478 I boot_progress_start: 9462//zygote starts up01-29 01:33:44.894 478 478 I boot_progress_preload_start: 13133//zygote startup completed01-29 01:33:49.997 478 478 I boot_progress_preload_end: 18236//system server ready01-29 01:33:51.088 1257 1257 I boot_progress_system_run: 19327//PM scans the installation packages in the /system directory01-29 01:33:52.213 1257 1257 I boot_progress_pms_start: 20452////PM scans the installation packages in the /data directory01-29 01:33:53.918 1257 1257 I boot_progress_pms_data_scan_start: 22157//PM ends scanning01-29 01:33:53.947 1257 1257 I boot_progress_pms_scan_end: 22186//PM ready01-29 01:33:54.172 1257 1257 I boot_progress_pms_ready: 22410//The system has calibrated the time and there was a time jump01-29 01:33:54.588 1257 1257 I AlarmManager: Current time only 2396034588,advancing to build time 172129720600007-18 18:06:46.000 1257 1257 W AlarmManagerService: Unable to set rtc to1721297206: No such device3.2 log// bootup logo ATT amiGO Jr watch end// The startup animation(ATT Logo) starts playing07-18 18:06:47.414 897 1003 D bootanimation: TrackPlayerBase::TrackPlayerBase()//AM ready and waiting for the screen to be ready//Even after the system animation has finished, it will continue to display until all //system servers and core system applications have started completely.07-18 18:06:47.9081257 1257 I boot_progress_ams_ready: 24733//surfaceflinger stops boot animation07-18 18:07:20.408599 1396 I sf_stop_bootanim: 57236//Boot animation ends07-18 18:07:20.409 1257 1347 I wm_boot_animation_done: 57237发现异常点:开机能完成,是通过timeout的方式触发的.07-11 05:16:09.363 1366 1485 I WindowManager: shouldWaitForSystemDecorWindowsOnBoot haveApp:true,haveKeyguard:true,wallpaperEnabled:true,haveWallpaper:false07-11 05:16:12.663 1366 1485 I WindowManager: shouldWaitForSystemDecorWindowsOnBoot haveApp:true,haveKeyguard:true,wallpaperEnabled:true,haveWallpaper:false07-11 17:16:39.328 1366 1485 W WindowManager:***** BOOT TIMEOUT: forcing display enabled找到对应的代码:3382 public void enableScreenAfterBoot() {3383 synchronized (mGlobalLock) {3384 ProtoLog.i(WM_DEBUG_BOOT, enableScreenAfterBoot: mDisplayEnabled%b 3385 mForceDisplayEnabled%b mShowingBootMessages%b mSystemBooted%b. 3386 %s,3387 mDisplayEnabled, mForceDisplayEnabled, mShowingBootMessages, mSystemBooted,3388 new RuntimeException(here).fillInStackTrace());3389 if (mSystemBooted) {3390 return;3391 }3392 mSystemBooted true;3393 hideBootMessagesLocked();3394// If the screen still doesnt come up after 30 seconds, give3395// up and turn it on.3396 mH.sendEmptyMessageDelayed(H.BOOT_TIMEOUT,30 * 1000);3397 }然后,再查看出现原因是什么:怀疑SystemUI wallpaperservice 被移除,而没有禁止wallpaper的原因.3812 // If we are turning on the screen to show the boot message, dont do it until the boot3813 // message is actually displayed.3814 if (!mWmService.mSystemBooted !haveBootMsg) {3815 return true;3816 }38173818 // If we are turning on the screen after the boot is completed normally, dont do so until3819 // we have the application and wallpaper.3820 if (mWmService.mSystemBooted3821 ((!haveApp !haveKeyguard) || (wallpaperEnabled !haveWallpaper))) {3822 return true;3823 }通过加日志,调试:07-11 05:16:09.363 1366 1485 I WindowManager: shouldWaitForSystemDecorWindowsOnBoot haveApp:true,haveKeyguard:true,wallpaperEnabled:true,haveWallpaper:false07-11 05:16:12.663 1366 1485 I WindowManager: shouldWaitForSystemDecorWindowsOnBoot haveApp:true,haveKeyguard:true,wallpaperEnabled:true,haveWallpaper:false07-11 17:16:39.328 1366 1485 W WindowManager: ***** BOOT TIMEOUT: forcing display enabled根本原因:在做项目裁剪时,因为觉得wallpaper 没有用到,将wallpaper service移除,但是, 系统有需要支持wallpaper,所以只是在systemui 中移除,造成此问题.