开机过程关键日志记录和介绍
前言
开机阶段描述
先用命令:
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_start | Zygote启动 |
| boot_progress_preload_end | Zygote结束 |
| boot_progress_system_run | SystemServer ready,开始启动Android系统服务 |
| 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发出退出开机动画的时间节点之前 |
| sf_stop_bootanim | SF设置service.bootanim.exit属性值为1,标志系统要结束开机动画了 |
| wm_boot_animation_done | 开机动画结束,这一步用户能直观感受到开机结束 |
一.各个阶段对应的代码
1. boot_progress_start
frameworks/base/core/jni/AndroidRuntime.cpp
void AndroidRuntime::start(const char* className, const Vector<String8>& 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_start
3. boot_progress_preload_end
/frameworks/base/core/java/com/android/internal/os/ZygoteInit.java
private 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 startup
bootTimingsTraceLog.traceBegin("PostZygoteInitGC");
gcAndFinalize();
bootTimingsTraceLog.traceEnd(); // PostZygoteInitGC
bootTimingsTraceLog.traceEnd(); // ZygoteInit
Zygote.initNativeState(isPrimaryZygote);
/// M: Added for BOOTPROF
addBootEvent("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_run
frameworks/base/services/java/com/android/server/SystemServer.java
private 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_start
frameworks/base/services/core/java/com/android/server/pm/PackageManagerService.java
public 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_start
frameworks/base/services/core/java/com/android/server/pm/PackageManagerService.java
public 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_start
frameworks/base/services/core/java/com/android/server/pm/PackageManagerService.java
public 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_end
frameworks/base/services/core/java/com/android/server/pm/PackageManagerService.java
public 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_ready
frameworks/base/services/core/java/com/android/server/pm/PackageManagerService.java
public 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_ready
frameworks/base/services/core/java/com/android/server/am/ActivityManagerService.java
public 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_screen
frameworks/base/services/core/java/com/android/server/wm/ActivityTaskManagerService.java
@Override public void enableScreenAfterBoot(boolean booted) {writeBootProgressEnableScreen(SystemClock.uptimeMillis()); mWindowManager.enableScreenAfterBoot(); synchronized (mGlobalLock) { updateEventDispatchingLocked(booted); } }12. sf_stop_bootanim
frameworks/native/services/surfaceflinger/SurfaceFlinger.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 intLOGTAG_SF_STOP_BOOTANIM= 60110; LOG_EVENT_LONG(LOGTAG_SF_STOP_BOOTANIM, ns2ms(systemTime(SYSTEM_TIME_MONOTONIC))); sp<IBinder> input(defaultServiceManager()->getService(String16("inputflinger"))); ... }frameworks/native/services/surfaceflinger/EventLog/EventLogTags.logtags
60100sf_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_done
frameworks/base/services/core/java/com/android/server/wm/WindowManagerService.java
private 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 0x100
<14>[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 seconds
01-29 01:33:41.223 478 478 I boot_progress_start: 9462//zygote starts up
01-29 01:33:44.894 478 478 I boot_progress_preload_start: 13133
//zygote startup completed
01-29 01:33:49.997 478 478 I boot_progress_preload_end: 18236//system server ready
01-29 01:33:51.088 1257 1257 I boot_progress_system_run: 19327//PM scans the installation packages in the /system directory
01-29 01:33:52.213 1257 1257 I boot_progress_pms_start: 20452
////PM scans the installation packages in the /data directory
01-29 01:33:53.918 1257 1257 I boot_progress_pms_data_scan_start: 22157
//PM ends scanning
01-29 01:33:53.947 1257 1257 I boot_progress_pms_scan_end: 22186
//PM ready
01-29 01:33:54.172 1257 1257 I boot_progress_pms_ready: 22410//The system has calibrated the time and there was a time jump
01-29 01:33:54.588 1257 1257 I AlarmManager: Current time only 2396034588,
advancing to build time 1721297206000
07-18 18:06:46.000 1257 1257 W AlarmManagerService: Unable to set rtc to
1721297206: No such device3.2 log
// bootup logo AT&T amiGO Jr watch end
// The startup animation(AT&T Logo) starts playing
07-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 animation
07-18 18:07:20.408599 1396 I sf_stop_bootanim: 57236
//Boot animation ends
07-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:false
07-11 05:16:12.663 1366 1485 I WindowManager: shouldWaitForSystemDecorWindowsOnBoot haveApp:true,haveKeyguard:true,wallpaperEnabled:true,haveWallpaper:false
07-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 doesn't come up after 30 seconds, give
3395// 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, don't do it until the boot
3813 // message is actually displayed.
3814 if (!mWmService.mSystemBooted && !haveBootMsg) {
3815 return true;
3816 }
3817
3818 // If we are turning on the screen after the boot is completed normally, don't do so until
3819 // we have the application and wallpaper.
3820 if (mWmService.mSystemBooted
3821 && ((!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:false
07-11 05:16:12.663 1366 1485 I WindowManager: shouldWaitForSystemDecorWindowsOnBoot haveApp:true,haveKeyguard:true,wallpaperEnabled:true,haveWallpaper:false
07-11 17:16:39.328 1366 1485 W WindowManager: ***** BOOT TIMEOUT: forcing display enabled
根本原因:
在做项目裁剪时,因为觉得wallpaper 没有用到,将wallpaper service移除,但是, 系统有需要支持wallpaper,所以只是在systemui 中移除,造成此问题.
