如何分析Activity生命周期的logxiaoyantan的博客-

一、查看log的方向和方式

1. 涉及到Activity生命周期问题时，主要是查看event log（logcat -b events），本地可使用adb logcat
   -b events | grep am_
2. 涉及到某个生命周期（一般指am_on_xxx）耗时时，结合”Slow Looper main”查看是哪个消息耗时
3. app端log的形式: am_on_xxx_called: [userId,className,reason,duration]
   ,duration是miui加上的

二、常见场景的log

1、正常启动一个activity

• system_server

05-29 18:17:41.616 1898 4358 I am_create_activity: [0,199662628,22,com.miui.gallery/.activity.HomePageActivity,android.intent.action.MAIN,NULL,NULL,270532608] 05-29 18:17:41.693 1898 4358 I am_restart_activity: [0,199662628,22,com.miui.gallery/.activity.HomePageActivity,24197] // minimalResumeActivityLocked 代表从该方法调用过来 05-29 18:17:41.695 1898 4358 I am_set_resumed_activity: [0,com.miui.gallery/.activity.HomePageActivity,minimalResumeActivityLocked] 

• app 进程，最后两个分别是reason和时间

// 这三个reason组合的onCreate，onStart，onResume周期在app端是在同一个消息内被执行的。即这三个周期有什么延迟问题，均为app端问题。 05-29 18:17:42.400 24197 24197 I am_on_create_called: [0,com.miui.gallery.activity.HomePageActivity,performCreate,125] 05-29 18:17:42.402 24197 24197 I am_on_start_called: [0,com.miui.gallery.activity.HomePageActivity,handleStartActivity,0] // RESUME_ACTIVITY 代表由ResumeActivityItem调用过来的，这种为system_server触发的且要求activity最终状态为resumed 05-29 18:17:42.404 24197 24197 I am_on_resume_called: [0,com.miui.gallery.activity.HomePageActivity,RESUME_ACTIVITY,1] 

2、正常结束finish一个activity

• system_server

// reason代表是app触发的finish 05-29 18:28:16.495 1898 4358 I am_finish_activity: [24197,199662628,22,com.miui.gallery/.activity.HomePageActivity,app-request]  05-29 18:28:16.500 1898 4358 I am_pause_activity: [24197,199662628,com.miui.gallery/.activity.HomePageActivity,userLeaving=false] // finishCurrentActivityLocked 代表加入stoppping列表的原因 05-29 18:28:16.505 1898 2042 I am_add_to_stopping: [0,199662628,com.miui.gallery/.activity.HomePageActivity,finishCurrentActivityLocked] // 代表destroy的时机是activity idle的时候，不是立刻destroy 05-29 18:28:17.048 1898 2105 I am_destroy_activity: [24197,199662628,22,com.miui.gallery/.activity.HomePageActivity,finish-imm:activityIdleInternalLocked] 

• app端

// LIFECYCLER_STOP_ACTIVITY 表示该onStop是中间流程，因为初始状态是onPause，最终状态是onDestroy，会走完之间的流程，一般这种周期reason会带有LIFECYCLER前缀 05-29 18:28:16.504 24197 24197 I am_on_paused_called: [0,com.miui.gallery.activity.HomePageActivity,performPause,0] 05-29 18:28:17.079 24197 24197 I am_on_stop_called: [0,com.miui.gallery.activity.HomePageActivity,LIFECYCLER_STOP_ACTIVITY,1] 05-29 18:28:17.102 24197 24197 I am_on_destroy_called: [0,com.miui.gallery.activity.HomePageActivity,performDestroy,2] 

3、activity之间切换
如下是前一个activity的生命周期，后一个生命周期见1 ，具体时序图见Activity 的启动

流程大概是：

Attention:
下一个activity onResume执行完后在主线程处于idle的时候通知system_server去stop上一个activity，如果主线程在onResume之后一直很忙（如：某个ui组件有问题导致递归绘制）会导致onStop执行延迟，直到10s超时后system_server端主动去执行stop。

所以onStop执行慢基本都是App端的问题，与AMS无关。

• system_server

05-29 15:44:37.540 1595 2425 I am_pause_activity: [5045,41736446,com.miui.gallery/.activity.HomePageActivity,userLeaving=true] // 代表加入stopping列表的原因为要求activity不可见 05-29 15:46:41.052 1595 2425 I am_add_to_stopping: [0,41736446,com.miui.gallery/.activity.HomePageActivity,makeInvisible] 05-29 15:46:41.598 1595 1691 I am_stop_activity: [0,41736446,com.miui.gallery/.activity.HomePageActivity] 

• app端

// onStop的reason STOP_ACTIVITY_ITEM 表示StopActivityItem调用 05-29 15:44:37.543 5045 5045 I am_on_paused_called: [0,com.miui.gallery.activity.HomePageActivity,performPause,0] 05-29 15:46:41.615 5045 5045 I am_on_stop_called: [0,com.miui.gallery.activity.HomePageActivity,STOP_ACTIVITY_ITEM,0] 

4、息屏时resumed activity的变化

06-10 14:39:36.417  1551  1604 I am_pause_activity: [14045,192133053,com.miui.gallery/.activity.HomePageActivity,userLeaving=false] 06-10 14:39:36.423 14045 14045 I am_on_paused_called: [0,com.miui.gallery.activity.HomePageActivity,performPause,1] 06-10 14:39:36.463  1551  1593 I am_stop_activity: [0,192133053,com.miui.gallery/.activity.HomePageActivity] // 一般都是看onStop的原因为sleeping 06-10 14:39:36.470 14045 14045 I am_on_stop_called: [0,com.miui.gallery.activity.HomePageActivity,sleeping,0] 

5、唤醒屏幕

// 主要看onRestart和onStart的reason为handleSleeping，注意的是有的情况是不会走onResume的 06-10 14:44:42.829  1760  1915 I am_set_resumed_activity: [0,com.miui.gallery/.activity.HomePageActivity,resumeTopActivityInnerLocked] 06-10 14:44:42.830 16517 16517 I am_on_restart_called: [0,com.miui.gallery.activity.HomePageActivity,handleSleeping,0] 06-10 14:44:42.831  1760  1915 I am_resume_activity: [0,201508124,34,com.miui.gallery/.activity.HomePageActivity,16517] 06-10 14:44:42.832 16517 16517 I am_on_start_called: [0,com.miui.gallery.activity.HomePageActivity,handleSleeping,1] 06-10 14:44:42.872 16517 16517 I am_on_resume_called: [0,com.miui.gallery.activity.HomePageActivity,RESUME_ACTIVITY,0] 

经典案例

1. onStop/onDestroy延迟执行

// 这个是正常的按下返回键返回上个页面的流程 03-24 09:57:27.560 1563 2759 I am_finish_activity: [3044,40142426,32721,com.android.settings/.Settings$PageLayoutActivity,app-request] 03-24 09:57:27.561 1563 2759 I am_pause_activity: [3044,40142426,com.android.settings/.Settings$PageLayoutActivity,userLeaving=false] 03-24 09:57:27.564 3044 3044 I am_on_paused_called: [0,com.android.settings.Settings$PageLayoutActivity,performPause,1]* 03-24 09:57:27.566 1563 4735 I am_set_resumed_activity: [0,com.android.settings/.SubSettings,resumeTopActivityInnerLocked] 03-24 09:57:27.567 1563 4735 I am_resume_activity: [0,178668836,32721,com.android.settings/.SubSettings,3044] 03-24 09:57:27.572 3044 3044 I am_on_resume_called: [0,com.android.settings.SubSettings,RESUME_ACTIVITY,1]     // 上个PageLayoutActivity 的destroy回调是在下个SubSettings onResume后将近10s才回调的，刚好是DESTROY_TIMEOUT_MSG 超时时间，说明app端onResume回调后10s内主线程都未处于idle状态 // 即主线程一直在执行消息，后面经调试发现是一个控件递归绘制一个drawable导致，即主线程一直在执行绘制消息 03-24 09:57:37.568 1563 1641 I am_destroy_activity: [3044,40142426,32721,com.android.settings/.Settings$PageLayoutActivity,finish-imm:activityIdleInternalLocked] 03-24 09:57:37.663 3044 3044 I am_on_stop_called: [0,com.android.settings.Settings$PageLayoutActivity,LIFECYCLER_STOP_ACTIVITY,1]* 03-24 09:57:37.663 3044 3044 I am_on_destroy_called: [0,com.android.settings.Settings$PageLayoutActivity,performDestroy,0] 

2. onStart/onResume延迟执行

05-18 07:15:00.099 1000 1684 2700 I am_create_activity: [0,207685455,818,com.android.deskclock/.alarm.alert.AlarmAlertFullScreenActivity,NULL,NULL,NULL,277151744] 05-18 07:15:00.108 1000 1684 2700 I am_restart_activity: [0,207685455,818,com.android.deskclock/.alarm.alert.AlarmAlertFullScreenActivity,30177] 05-18 07:15:00.110 1000 1684 2700 I am_set_resumed_activity: [0,com.android.deskclock/.alarm.alert.AlarmAlertFullScreenActivity,minimalResumeActivityLocke     // 客户端的onCreate和onStart/onResume执行时间相差8s左右，鉴于客户端的LaunchActivityItem与ResumeActivityItem是同一个消息执行的，确定为客户端问题 05-18 07:15:00.288 10104 30177 30177 I am_on_create_called: [0,com.android.deskclock.alarm.alert.AlarmAlertFullScreenActivity,performCreate,8] 05-18 07:15:08.158 10104 30177 30177 I am_on_start_called: [0,com.android.deskclock.alarm.alert.AlarmAlertFullScreenActivity,handleStartActivity,0] 05-18 07:15:08.161 10104 30177 30177 I am_on_resume_called: [0,com.android.deskclock.alarm.alert.AlarmAlertFullScreenActivity,RESUME_ACTIVITY,2]     // 查找app主线程的log，查找可能的耗时原因，主线程调用IContentProvider的query接口耗时将近8s，确定原因 05-18 07:15:08.088 10104 30177 30177 W BpBinder: Slow Binder: BpBinder transact took 7742ms, interface=android.content.IContentProvider, code=1 oneway=false