Android卡顿分析中常见的log

 

 

Android卡顿分析中常见的log

https://blog.csdn.net/woai110120130/article/details/80252617

1 看内存
bugreport 开始的时候有pss的信息 并且进行排序 , 之后会写一个解析和计算的

2 找system log中关键部分

一般设备hang 住的时候用户会疯狂按keycode ,可以找相关log

３keyCode:3 down:true eventTime:831405 下面是常见的keycode

KEYCODE_CALL 拨号键 5
KEYCODE_ENDCALL 挂机键 6
KEYCODE_HOME 按键Home 3
KEYCODE_MENU 菜单键 82
KEYCODE_BACK 返回键 4
KEYCODE_SEARCH 搜索键 84
KEYCODE_CAMERA 拍照键 27
KEYCODE_FOCUS 拍照对焦键 80
KEYCODE_POWER 电源键 26
KEYCODE_NOTIFICATION 通知键 83
KEYCODE_MUTE 话筒静音键 91
KEYCODE_VOLUME_MUTE 扬声器静音键 164
KEYCODE_VOLUME_UP 音量增加键 24
KEYCODE_VOLUME_DOWN 音量减小键 25

3 lmk log

4 bugreport 启动位置
搜索：Starts to dump Bugreport 关键字，可以查看开始生产bugreport的时间

10-27 16:32:14.361 2108 6613 W XSpaceManagerService: checkXSpaceControl, from:com.miui.home, to:com.miui.bugreport, with act:android.intent.action.MAIN, callingUserId:0, toUserId:0
10-27 16:32:14.368 2108 6613 I ActivityManager: START u0 {act=android.intent.action.MAIN cat=[android.intent.category.LAUNCHER] flg=0x10200000 cmp=com.miui.bugreport/.ui.MainTabActivity bnds=[487,664][609,786] (has extras)} from uid 10027 on display 0
10-27 16:32:14.387 4399 4545 I WtProcessController: mCurTask:85
10-27 16:32:14.397 2108 2138 I ActiveServicesInjector: RESTART Low priority start of: ServiceRecord{10fc538 u10 com.google.android.gms/com.google.android.location.internal.GoogleLocationManagerService}
10-27 16:32:14.398 2108 2138 W ActivityManager: Scheduling restart of crashed service com.google.android.gms/com.google.android.location.internal.GoogleLocationManagerService in 192456ms
10-27 16:32:14.444 2108 6613 I ActivityManager: Start proc 11744:com.miui.bugreport/1000 for activity com.miui.bugreport/.ui.MainTabActivity caller=com.miui.home
10-27 16:32:14.481 11674 11714 E ActivityThread: Failed to find provider info for com.google.android.gms.common.phenotype
10-27 16:32:14.505 4399 4545 I WtProcessController: MOVE TO FOREGROUND: com.miui.bugreport 1000
10-27 16:32:14.506 4399 4545 I StatusController: Last foreground:com.miui.home uid:10027 Current foreground:com.miui.bugreport uid:1000
10-27 16:32:14.506 4399 4545 I WtProcessController: FOREGROUND INFO: name=com.miui.bugreport uid=1000 pid=11744 TaskId:85
10-27 16:32:14.538 2108 2138 W ActivityManager: Scheduling restart of crashed service com.google.android.gms/com.google.android.contextmanager.service.ContextManagerService in 1000ms
10-27 16:32:14.548 2108 2138 I ActiveServicesInjector: Low priority start of: ServiceRecord{671a411 u10 com.google.android.gms/com.google.location.nearby.direct.service.NearbyDirectService}
10-27 16:32:14.570 2108 27407 I ActivityManager: Process com.qualcomm.qti.services.secureui:sui_service (pid 11100) has died

5 cpu信息
—— DUMPSYS CPUINFO (dumpsys -t 10 cpuinfo -a) ——
Load: 25.52 / 21.97 / 14.3
CPU usage from 59342ms to 492ms ago (2017-11-23 19:28:38.401 to 2017-11-23 19:29:37.251):
65% 1643/system_server: 38% user + 27% kernel / faults: 23803 minor
57% 3505/android.process.acore: 30% user + 27% kernel / faults: 33751 minor 4 major
25% 11225/net.one97.paytm: 18% user + 6.9% kernel / faults: 43578 minor
8.1% 3160/com.facebook.katana: 7.2% user + 0.9% kernel / faults: 12876 minor 16 major
6.6% 732/surfaceflinger: 3.7% user + 2.8% kernel / faults: 336 minor
6.2% 3829/com.lbe.security.miui: 3.3% user + 2.8% kernel / faults: 3573 minor
5.2% 14218/android.process.media: 4.9% user + 0.2% kernel / faults: 5833 minor 1 major
5% 16004/com.android.systemui:screenshot: 3.9% user + 1.1% kernel / faults: 60453 minor 1 major
4.6% 16019/com.miui.gallery: 4.1% user + 0.5% kernel / faults: 21898 minor 8 major
3.9% 7096/com.imo.android.imoim: 3.8% user + 0.1% kernel / faults: 2909 minor

如上述log 搜索 DUMPSYS CPUINFO 可以看到 当时系统的平均负载很高, 按照8核cpu来算,负载也很高,一般负载不应该超过cpu核心数*1.5

另外从cpu使用率上来看 kernel消耗了大量cpu时间 显然不是正常情况,高吞吐率的系统,kernel应该使用较少cpu, 并且当时内存占用不高 iowait不高的情况下 很可能是进程上下文频繁切换引起

6 kernel重启
—— POWERUP_REASON (/sys/bootinfo/powerup_reason) ——
kpanic

7 WatchDog信息
watchdog发现系统卡顿的时候说明问题已经非常严重,有30s不响应就会打印traces.txt调用栈

超过一分钟不想赢则会打印 类似如下的log,和保存 名字如races_SystemServer_WDT_${time}.txt的文件,并重启system_server

Blocked in handler on foreground thread (android.fg), Blocked in handler on main thread (main), Blocked in handler on display thread (android.display), Blocked in handler on ActivityManager (ActivityManager)

“Blocked in monitor ” + mCurrentMonitor.getClass().getName() ” on ” + mName + ” (” + getThread().getName() + “)”

如果monkey过程中发生超过1s的超时,不会重启system_server,但是会保存一个anr_watchdog${time}.txt的bugreport文件

8 等锁的信息
12-19 00:24:34.836 6795 6795 I dvm_lock_sample: [com.android.commands.monkey,0,main,1429523,PrintStream.java,823,-,823,0]
12-19 00:24:34.837 1547 1547 I dvm_lock_sample: [system_server,0,main,1459069,ActivityManagerService.java,19053,ActivityStarter.java,855,0]
12-19 00:24:34.839 20217 20217 I binder_sample: [android.app.IActivityManager,3,1459614,android.process.mediaUI,100]
12-19 00:24:34.840 1547 1833 I dvm_lock_sample: [system_server,1,Binder:1547_4,1459612,ActivityManagerService.java,18001,ActivityStarter.java,855,0]
12-19 00:24:34.842 1547 2690 I dvm_lock_sample: [system_server,1,Binder:1547_C,1459614,ActivityManagerService.java,7480,ActivityStarter.java,855,0]
12-19 00:24:34.843 1547 2822 I dvm_lock_sample: [system_server,1,Binder:1547_11,1459560,UserController.java,1507,ActivityStarter.java,855,0]
12-19 00:24:34.843 1547 1726 I dvm_lock_sample: [system_server,0,InputDispatcher,1459561,ActivityManagerService.java,6136,ActivityStarter.java,855,0]
12-19 00:24:34.844 1547 1596 I dvm_lock_sample: [system_server,0,ActivityManager,1459543,ActivityManagerService.java,2161,ActivityStarter.java,855,0]
12-19 00:24:34.845 1547 1788 I dvm_lock_sample: [system_server,0,LazyTaskWriterThread,1458865,TaskPersister.java,547,ActivityStarter.java,855,0]
12-19 00:24:34.845 1547 1602 I dvm_lock_sample: [system_server,0,android.display,1454632,ActivityManagerService.java,22610,ActivityStarter.java,855,0]
12-19 00:24:34.846 1547 1600 I dvm_lock_sample: [system_server,0,android.fg,1455409,ActivityManagerService.java,19053,ActivityStarter.java,855,0]
12-19 00:24:34.846 1547 3486 I dvm_lock_sample: [system_server,1,Binder:1547_20,1393949,ActivityManagerService.java,17756,ActivityStarter.java,855,0]
12-19 00:24:34.847 1547 1725 I dvm_lock_sample: [system_server,0,AlarmManager,1443453,ActivityManagerService.java,7780,ActivityStarter.java,855,0]
12-19 00:24:34.847 1547 3444 I dvm_lock_sample: [system_server,1,Binder:1547_1F,1253238,ActivityManagerService.java,14429,ActivityStarter.java,855,0]
12-19 00:24:34.847 1809 1809 I binder_sample: [android.app.IActivityManager,145,1459563,com.android.systemui,100]
12-19 00:24:34.847 1547 3440 I dvm_lock_sample: [system_server,1,Binder:1547_1C,815593,ActivityManagerService.java,6078,ActivityStarter.java,855,0]

格式

进程名，主线程？，线程名字，锁等待时间，当前持有者的文件名，行号，上一个持有者文件名，行号，锁等待的百分比

打印此条LOG的时候，上一个锁的持有者已经释放锁，本线程为下一个锁的持有者，即将获取锁
上一个持有者的文件名，可能是“-”，表示与持有者是同一个文件。
经过最近分析,一般出现问题都是上一个只有者引起的该问题. 不过需要分析art源码确认这一点

9 art其他监控信息(感觉像是斥锁信息)
W art : Long monitor contention with owner Binder:1547_E (2818) at android.content.Intent com.android.server.am.ExtraActivityManagerService.checkStartActivityPermission(android.content.Context, com.android.server.am.ActivityManagerService, android.app.IApplicationThread, android.content.pm.ActivityInfo, android.content.Intent, java.lang.String, boolean, int, boolean, int, int, java.lang.String, android.os.Bundle)(ExtraActivityManagerService.java:213) waiters=8 in boolean com.android.server.am.ActivityManagerService.unbindService(android.app.IServiceConnection) for 1420.999s

代码在art/runtime/monitor.cc 的void Monitor::Lock(Thread* self) 函数里面 ,主要就是尝试获取锁获取不到的时候打印,如果开了ATRACE,也会有相应的trace信息

通过std::string Monitor::PrettyContentionInfo(const std::string& owner_name,
pid_t owner_tid,
ArtMethod* owners_method,
uint32_t owners_dex_pc,
size_t num_waiters) 函数打印

std::ostringstream oss;
oss << “monitor contention with owner ” << owner_name << ” (” << owner_tid << “)”;
if (owners_method != nullptr) {
oss << ” at ” << PrettyMethod(owners_method);
oss << “(” << owners_filename << “:” << owners_line_number << “)”;
}
oss << ” waiters=” << num_waiters;
该log在获取锁并且超过阀值后打印,阀值使用-Xlockprofthreshold:_设置,log中参数的意义如下

W art :monitor contention with owner持锁的线程名称(
{tid})at{持锁的方法}(文件名:{行数}) waiters=等锁的线程数量in

{等锁的方法} for ${等锁的时间}

10 miui的一些监控信息 (需要深入分析)
1 MIUI-BLOCK-MONITOR: 监控一些调用卡顿的信息

2 12-19 02:42:26.460 2753 2753 I Timeline: Timeline: Activity_launch_request time:33148551 intent:Intent { act=com.mi.android.globalpersonalassistant.CommonSettingDetailActivity flg=0x10008000 (has extras) } 应该是Activity从启动到可见过程的timeline 需要具体分析

如何提升ANR问题分析效率 参考这篇文章

11 原生binder监控机制 目前d2a上是关闭的
关键字:binder_sample 在小米手机java层的binder调用超过300ms必打这个log

原理 frameworks/base/core/jni/android_util_Binder.cpp:conditionally_log_binder_call 函数打印event log

binder_sample: [android.hardware.input.IInputManager,5,30002,com.android.commands.monkey,100]

binder_sample:[binder的desc,transaction code,耗时,进程名,相对于阀值的百分比]

12 Binder log分析
binder如何分析binder线程池耗尽? 进程在打开binder驱动的时候会设置该进程最大的binder线程个数

result = ioctl(fd, BINDER_SET_MAX_THREADS, &maxThreads);
这里在7.0的手机上默认的个数是15个. 15并不代表该线程所能创建的binder线程的最大个数.

只是代表由binder驱动被动请求创建线程的个数,当我们查看binder线程池是否耗尽的时候要区分线程是被动创建的还是主动创建的.

分析log的时候搜索关键字requested threads 就能找到被动创建的binder线程数量

—— 0.044s was the duration of ‘BINDER TRANSACTIONS’ ——
—— BINDER STATS (/sys/kernel/debug/binder/stats) ——

proc 12720
context binder
threads: 4 进程包含的binder线程个数
requested threads: 0+1/15 是否正在请求创建binder线程中+由binder驱动被动请求创建的binder个数/最大可以被动创建的binder线程个数
ready threads 2 空闲的线程个数
free async space 520192
nodes: 7 binder服务的个数
refs: 20 s 20 w 20 请求服务的个数 强引用个数 弱引用个数
buffers: 1
pages: 1:2:251 活跃的:分配未使用的:未分配的
pending transactions: 0 还没有执行的工作项
BC_TRANSACTION: 60 发起的BC_TRANSACTION请求次数
BC_FREE_BUFFER: 62 请求释放buffer次数
BC_INCREFS: 20 请求增加强引用
BC_ACQUIRE: 20
BC_INCREFS_DONE: 7
BC_ACQUIRE_DONE: 7
BC_REGISTER_LOOPER: 1 被动准备的线程 进入就绪状态的次数
BC_ENTER_LOOPER: 1 主动
BR_TRANSACTION: 3 收到的BR_TRANSACTION请求
BR_REPLY: 60 收到的结果(入过每次BC_TRANSACTION都有返回的话是一致的)
BR_TRANSACTION_COMPLETE: 60 TRANSACTION被驱动接收到的次数
BR_INCREFS: 7
BR_ACQUIRE: 7
BR_SPAWN_LOOPER: 1 请求创建binder线程次数

13 跳帧

当生产者的速度超过消费者,在开发术语中称作背压,通过systrace可以很容易看到这种情况,另外在使用进行合成的代码中也会有如下log输出

01-18 20:31:57.285 572 572 D SurfaceFlinger: Backpressure trigger, skipping transaction & refresh!
01-18 20:31:57.352 572 572 D SurfaceFlinger: Backpressure trigger, skipping transaction & refresh!
01-18 20:31:58.705 572 572 D SurfaceFlinger: Backpressure trigger, skipping transaction & refresh!

在systrace中的表现如下,在Surfaceflinger的ui线程中应该执行INVALIDATE的地方什么都没有做就返回了.说明有跳帧

这里写图片描述

如下面这种情况在INVALIDATE的时候执行了hanleMessageInvalidate而没有执行页面翻转是正常的,说明这段时间没有提交事务

这里写图片描述

这个值在hwc2 的设备中生效

14 Choreographer的跳帧信息

TAG, “Skipped ” + skippedFrames + ” frames! ”
+ “The application may be doing too much work on its main thread.”) 这里是收到vsync和处理这个vsync的时间太长超过大概30ms就会打印,说明应用主线程比较忙,TAG是Choreographer

Log.w(TAG, “Already have a pending vsync event. There should only be ”
+ “one at a time.”);
还有个vsync没有处理又新来了一个vsync

15 cpu使用信息 在trace中

state=S schedstat=( 116304198556 13649702167 189147 ) utm=9873 stm=1757 core=6 HZ=100

schedstat=( 116304198556 13649702167 189147 ) 中的三个值分别代表 :

1 累计运行的物理时间时间

2 /累计在就绪队列里的等待时间

3主动切换和被动切换的累计次数

utm/stm: 用户态/内核态的CPU时间(单位是jiffies)

core=6 最后运行的核心

HZ=100 频率 1/HZ - jiffies

17 SurfaceFlinger 统计信息

EventLog中

11-23 21:44:37.631 734 734 I sf_frame_dur: [naukriApp.appModules.login/com.naukri.jobsforyou.RecommendedJobsContainer,76,0,1,0,0,0,1]
11-23 21:44:37.631 734 734 I sf_frame_dur: [com.facebook.katana/com.facebook.katana.LoginActivity,1371,1387,40,25,12,5,3]
11-23 21:44:37.631 734 734 I sf_frame_dur: [com.facebook.katana/com.facebook.katana.LoginActivity,528,25,3,2,2,1,0]
11-23 21:44:37.631 734 734 I sf_frame_dur: [com.android.contacts/com.android.contacts.activities.TwelveKeyDialer,4,2,1,3,1,0,0]
11-23 21:44:37.631 734 734 I sf_frame_dur: [com.facebook.orca/com.facebook.orca.auth.StartScreenActivity,283,11,3,4,4,3,1]
11-23 21:44:37.631 734 734 I sf_frame_dur: [com.miui.gallery/com.miui.gallery.activity.HomePageActivity,225,6,8,5,7,4,8]
11-23 21:44:37.631 734 734 I sf_frame_dur: [com.android.settings/com.android.settings.MainSettings,16,0,0,0,0,0,1]
11-23 21:44:37.631 734 734 I sf_frame_dur: [ [com.android.email/com.android.email.activity.Welcome,344,143,9,2,2,2,8]
11-23 21:44:37.631 734 734 I sf_frame_dur: [StatusBar,282,11,13,101,17,55,53]
11-23 21:44:37.631 734 734 I sf_frame_dur: [NavigationBar,302,6,0,2,1,3,12]
11-23 21:44:37.631 734 734 I sf_frame_dur: [RoundCorner,0,0,0,0,0,0,8]
11-23 21:44:37.631 734 734 I sf_frame_dur: [RoundCorner,0,0,0,0,0,0,8]
11-23 21:44:37.632 734 734 I sf_frame_dur: [,9625,532,191,164,127,161,521]com.tencent.mm/com.tencent.mm.ui.LauncherUI,16,1,1,1,1,1,0]

定义

dur代表上帧被合成到当前帧被合成的时间.

DisplayPeriod= (1/fps)
durPeriod= (dur+DisplayPeriod/2)/DisplayPeriod

如上SF中layer被销毁后会打印该layer的一些统计信息 log的格式为 [window名称,<2durPeriod,(2-3)durPeriod,(4-7)durPeriod,(8-15)durPeriod,(16-31)durPeriod,(23-63)durPeriod,>128durPeriod]

该log虽然可以打印延迟,但是由于有时候界面并无变化,两帧之间差值太大并无什么意义

18 binder 线程池耗尽 线程池耗尽很容易引起anr

11-23 19:29:57.905 3505 9248 E IPCThreadState: binder thread pool (15 threads) starved for 1070 ms

19 Looper消息处理时间过长

Dispatch took 144ms on android.ui, h=Handler (android.view.Choreographer$FrameHandler) {a32d925} cb=android.view.Choreographe

public void setSlowDispatchThresholdMs(long slowDispatchThresholdMs) {
mSlowDispatchThresholdMs = slowDispatchThresholdMs;
}
设置looper的一个阀值,超过则打印该system log

20 AMS中会打印如下log在关键时刻

Slow operation:
private void checkTime(long startTime, String where) {
long now = SystemClock.uptimeMillis();
if ((now-startTime) > 50) {
// If we are taking more than 50ms, log about it.
Slog.w(TAG, “Slow operation: ” + (now-startTime) + “ms so far, now at ” + where);
}
}
20 Window 处理input时间太长

02-26 17:27:29.849 2583 3171 I InputDispatcher: Window ‘Window{8fd109b u0 InputMethod}

’ spent 3238.7ms processing the last input event: MotionEvent(deviceId=9, source=0x00001002, action=1, actionButton=0x00000000, flags=0x00000000, metaState=0x00000000, buttonState=0x00000000, edgeFlags=0x00000000, xPrecision=1.0, yPrecision=1.0, displayId=0, pointers=[0: (183.8, 1685.1)]), policyFlags=0x62000000

21 WtBlockMonitor: Package name :com.google.android.apps.maps MTK平台特有

03-19 14:23:46.538038 1702 1702 W WtBlockMonitor: Package name :com.google.android.apps.maps
03-19 14:23:46.538038 1702 1702 W WtBlockMonitor: The Message { when= what=114 obj=CreateServiceData{token=android.os.BinderProxy@c6cf096 className=com.google.android.apps.gmm.offline.update.OfflineAutoUpdateJobService packageName=com.google.android.apps.maps intent=null} target=android.app.ActivityThread$H } took 9995 ms

03-24 12:56:29.097 1000 2433 2473 I am_activity_launch_time: [0,184420527,com.google.android.dialer/com.google.android.apps.dialer.extensions.GoogleDialtactsActivity,738,738]
---------------------  
作者：111冷雨夜111  
来源：CSDN  
原文：https://blog.csdn.net/woai110120130/article/details/80252617  
版权声明：本文为博主原创文章，转载请附上博文链接！