Android卡顿分析中常见的log

1 看内存

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

2 找system log中关键部分

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

3keyCode: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})atat{持锁的方法}(文件名:文件名:{行数}) waiters=等锁的线程数量in等锁的线程数量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]



转载自:https://blog.csdn.net/woai110120130/article/details/80252617

©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 206,214评论 6 481
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 88,307评论 2 382
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 152,543评论 0 341
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 55,221评论 1 279
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 64,224评论 5 371
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 49,007评论 1 284
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 38,313评论 3 399
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 36,956评论 0 259
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 43,441评论 1 300
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 35,925评论 2 323
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 38,018评论 1 333
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 33,685评论 4 322
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 39,234评论 3 307
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 30,240评论 0 19
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 31,464评论 1 261
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 45,467评论 2 352
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 42,762评论 2 345

推荐阅读更多精彩内容