Android 从log中学习设备启动过程及代码执行流程
这段时间分析设备概率异常启动慢问题，特此记录。
补充log区分:
一般log里面有sys log、main log、events log、crash log、Rlog，而这些log是怎么实现这些区分？
sys log ---> android.util.Slog (hide类)
main log --> android.util.Log (常用的方式)
events log --> android.util.EventLog
crash log --> com.internal.os.RuntimeInit
radio log-->android.telephony.Rlog(hide类)
(特别注意：内部类LoggingHandler对Clog_e的调用)
进一步了解：
android.util.Log中有如下ID，这也就标明了log的类型：
/** @hide */ public static final int LOG_ID_MAIN = 0;//-- main log
/** @hide */ public static final int LOG_ID_RADIO = 1;//-- radio log
/** @hide */ public static final int LOG_ID_EVENTS = 2;//-- events log
/** @hide */ public static final int LOG_ID_SYSTEM = 3;// -- sys log
/** @hide */ public static final int LOG_ID_CRASH = 4;//--crash log
其实源头的调用就是：
/** @hide */ public static native int println_native(int bufID,
int priority, String tag, String msg);
bufID--就是传入上面的ID值
快速解析adb抓log的方式：
adb logcat 默认是main的，所以要抓取log应该如下操作：
adb logcat -b main -b system -b radio -b events -v time
从log中了解开机时间
从events的log中了解开机启动时间：
Android 从log中学习设备启动过程及代码执行流程
解析注意点：
为什么boot_progress_start -->boot_progress_preload_start时间这么长？
关键字："dex2oat" "dex2oat : dex2oat took"
通过看main log如下：
03-06 10:42:58.283609 479 479 I zygote64: GenerateImage: /system/bin/dex2oat --image=/data/dalvik-cache/arm64/system@framework@boot.art --dex-file=/system/framework/core-oj.jar --dex-file=/system/framework/core-libart.jar --dex-file=/system/framework/conscrypt.jar --dex-file=/system/framework/okhttp.jar --dex-file=/system/framework/bouncycastle.jar --dex-file=/system/framework/apache-xml.jar --dex-file=/system/framework/ext.jar --dex-file=/system/framework/framework.jar --dex-file=/system/framework/telephony-common.jar --dex-file=/system/framework/voip-common.jar --dex-file=/system/framework/ims-common.jar --dex-file=/system/framework/android.hidl.base-V1.0-java.jar --dex-file=/system/framework/android.hidl.manager-V1.0-java.jar --dex-file=/system/framework/framework-oahl-backward-compatibility.jar --dex-file=/system/framework/android.test.base.jar --dex-file=/system/framework/mediatek-common.jar --dex-file=/system/framework/mediatek-framework.jar --dex-file=/system/framework/mediatek-telephony-common.jar --dex-file=/system/framework/mediatek-teleph
03-06 10:43:55.453963 672 672 I dex2oat : dex2oat took 56.741s (81.581s cpu) (threads: 4) arena alloc=16MB (17795744B) java alloc=5MB (6045464B) native alloc=66MB (70099304B) free=17MB (17981080B)
为什么boot_progress_pms_ready -->boot_progress_ams_ready 时间这么长？
关键字：SystemServerTiming 涉及内容在：sys_log
1,826: 03-06 10:44:26.582524 1005 1005 D SystemServerTiming: StartPackageManagerService took to complete: 3768ms
2,172: 03-06 10:45:02.356858 1005 1005 D SystemServerTiming: UpdatePackagesIfNeeded took to complete: 33570ms
补充说明：
1.android.server.SystemServer中对具体方法执行时间有跟踪
Android 从log中学习设备启动过程及代码执行流程
2.使用的是隐藏类
android.util.TimingsTraceLog
进一步解析:
这些信息也可以通过代码获取意义
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
开机动画结束，这一步用户能直观感受到开机结束
。可以用此来衡量是否开机完成--7.0以上出现
注意java层使用的是EventLog.java
EventLog.writeEvent(EventLogTags.BOOT_PROGRESS_PMS_START,
参考学习：
http://www.mamicode.com/info-detail-1789654.html
https://blog.51cto.com/ticktick/1660996
https://blog.csdn.net/zhangbijun1230/article/details/80562616
https://blog.csdn.net/poolwater/article/details/51839402
https://blog.csdn.net/a04081122/article/details/52314709
从log中学习代码执行流程：
E SystemServiceRegistry: No service published for: dropbox
03-01 10:00:48.942572 973 1039 E SystemServiceRegistry: android.os.ServiceManager$ServiceNotFoundException: No service published for: dropbox
03-01 10:00:48.942572 973 1039 E SystemServiceRegistry: at android.os.ServiceManager.getServiceOrThrow(ServiceManager.java:143)
03-01 10:00:48.942572 973 1039 E SystemServiceRegistry: at android.app.SystemServiceRegistry$19.createService(SystemServiceRegistry.java:355)
03-01 10:00:48.942572 973 1039 E SystemServiceRegistry: at android.app.SystemServiceRegistry$19.createService(SystemServiceRegistry.java:352)
03-01 10:00:48.942572 973 1039 E SystemServiceRegistry: at android.app.SystemServiceRegistry$CachedServiceFetcher.getService(SystemServiceRegistry.java:1137)
03-01 10:00:48.942572 973 1039 E SystemServiceRegistry: at android.app.SystemServiceRegistry.getSystemService(SystemServiceRegistry.java:1053)
03-01 10:00:48.942572 973 1039 E SystemServiceRegistry: at android.app.ContextImpl.getSystemService(ContextImpl.java:1726)
03-01 10:00:48.942572 973 1039 E SystemServiceRegistry: at com.android.server.am.ActivityManagerService.logStrictModeViolationToDropBox(ActivityManagerService.java:15884)
03-01 10:00:48.942572 973 1039 E SystemServiceRegistry: at com.android.server.am.ActivityManagerService.handleApplicationStrictModeViolation(ActivityManagerService.java:15843)
03-01 10:00:48.942572 973 1039 E SystemServiceRegistry: at android.os.StrictMode.handleApplicationStrictModeViolation(StrictMode.java:1772)
03-01 10:00:48.942572 973 1039 E SystemServiceRegistry: at android.os.StrictMode.access$1400(StrictMode.java:141)
03-01 10:00:48.942572 973 1039 E SystemServiceRegistry: at android.os.StrictMode$AndroidBlockGuardPolicy.onThreadPolicyViolation(StrictMode.java:1702)
03-01 10:00:48.942572 973 1039 E SystemServiceRegistry: at android.os.StrictMode$AndroidBlockGuardPolicy.lambda$handleViolationWithTimingAttempt$0(StrictMode.java:1621)
03-01 10:00:48.942572 973 1039 E SystemServiceRegistry: at android.os.-$$Lambda$StrictMode$AndroidBlockGuardPolicy$9nBulCQKaMajrWr41SB7f7YRT1I.run(Unknown Source:6)
03-01 10:00:48.942572 973 1039 E SystemServiceRegistry: at android.os.Handler.handleCallback(Handler.java:873)
03-01 10:00:48.942572 973 1039 E SystemServiceRegistry: at android.os.Handler.dispatchMessage(Handler.java:99)
03-01 10:00:48.942572 973 1039 E SystemServiceRegistry: at android.os.Looper.loop(Looper.java:193)
03-01 10:00:48.942572 973 1039 E SystemServiceRegistry: at android.os.HandlerThread.run(HandlerThread.java:65)
03-01 10:00:48.942572 973 1039 E SystemServiceRegistry: at com.android.server.ServiceThread.run(ServiceThread.java:44)
展示常规Context调用服务的流程--MTK 9.0系统
展示mContext.getSystemService(Context.DROPBOX_SERVICE)调用服务的流程：
一、
DropBoxManager dbox = (DropBoxManager) mContext.getSystemService(Context.DROPBOX_SERVICE);
二、
android.app.ContextImpl.getSystemService(ContextImpl.java:1726)
三、
android.app.SystemServiceRegistry.getSystemService(SystemServiceRegistry.java:1053)
注：
这里面有一抽象类，运行的非常漂亮
public static abstract class CachedServiceFetcher<T> implements ServiceFetcher<T> {
}
四、
android.app.SystemServiceRegistry$CachedServiceFetcher.getService(SystemServiceRegistry.java:1137)
五、
android.app.SystemServiceRegistry$19.createService(SystemServiceRegistry.java:352)
六、
android.os.ServiceManager.getServiceOrThrow(ServiceManager.java:143)
Tips:
想了解某一个方法是怎么调用的，可以通过：
丢throw 异常来处理。
public static IBinder getServiceOrThrow(String name) throws ServiceNotFoundException {
final IBinder binder = getService(name);
if (binder != null) {
return binder;
} else {
throw new ServiceNotFoundException(name);
}
}
