这篇文章全是干货，我们一起聊聊安卓系统稳定性问题、部分性能问题。本篇列举了作者在某厂工作中遇到实际问题，大部分只有日志概率性问题，通过日志分析问题。

自己对这半年工作做个笔记，也希望对大家有用。方便你我他，希望大家多多支持原创。

目录

一、应用类问题相关日志

Crash 提示“应用停止运行”

ANR 提示“应用无响应“

界面卡顿：

启动activity日志：

Key事件动作：

二、系统问题相关日志

1.内存类关键词

2. watchDog关键词：

3. 死机重启前操作：

4.Google应用

系统问题案例分析及相关日志

1.Framework-Google-GMS （com.google.android.gms Crash）

2.有多个anr及crash弹窗提示太过频繁

3.[Framework-Google-GMS] com.google.android.gms.persistent Crash

4.[Framework-Google-GMS] com.google.android.googlequicksearchbox:search Crash

5.[Framework-Google-GMS] com.google.android.calendar Anr

6.点击相册显示“相册屡次停止运行”

7.[Framework Performance Stablility] com.android.vending Anr

8.[Google Services Framework]切换40多种语言后，测试机切换语言出现卡顿，一台出现“Google Services Framework keeps stopping”，重启无法恢复

9.电容笔放置屏幕上，开启youtube播放视频，同时开启录屏。待机至第二天屏幕黑屏，打开界面为主界面，录屏只录制40分钟

10.测试机从暗环境切换到亮环境，亮度数值变化与进度条变化不一致（进度条有点慢）

一、应用类问题相关日志

Crash 提示“应用停止运行”

搜索Android崩溃的日志。

按Fatal > Crash > AndroidRuntime > Shutting down VM > Exception > Error 的顺序逐个搜索。

Crash：关键log:androidlog:Shutting down VM|am_crash|FATAL EXCEPTION|FAILED BINDER TRANSACTION|system_app_crash|JavaBinder主要看：system_app_crash文件堆栈调用

ANR 提示“应用无响应“

ANR即（application not responding），即应用无响应，程序会弹出一个dialog提示用户程序无响应，而这对于用户体验无疑是很不好的

至于程序为何会“无响应”，主要有以下几个原因

1：InputDispatching (5 seconds) --主要类型

按键或触摸等输入事件在特定时间内无响应

2：BroadcastTimeout(10 seconds)

BroadcastReceiver在特定时间内无法处理完成

3：ServiceTimeout(20 seconds) --小概率类型

Service在特定的时间内无法处理完成

4：ContentProviderTimeout(10 seconds) --小概率类型

内容提供者,在publish过超时10s;

关键日志:" ANR in "、"Reason: " 、“Dumping to ”、“anr_in”

如：Dumping to /data/anr/

Reason: Input dispatching timed out

ANR关键log:androidlog:am_anr|anr in|Dumping to|Collecting stacks for pidtrace:查看Dumping to后生成对应trace文件需要看：anr之前xxms当前进程log

dropbox —— 系统服务dropbox以文件形式记录了系统各种异常信息，例如app crash、native crash、anr、kernel panic、event记录、wtf输出等等。可以使用如下命令手动导出：adb shell dumpsys dropbox

界面卡顿：

//跳帧时间

Choreographer: Frame time delta

//跳帧

Choreographer: Skipped 56 frames! The application may be doing too much work on its main thread.

启动activity日志：

//启一个Activity

start u0

//查看相关进程id

Already Exists in BG. So sending its PID

//显示一个Activity

ActivityTaskManager: Displayed

窗口焦点切换：input_focus:Focus request|Focus leaving|Focus entering

Key事件动作：

KeyButtonView: Back button event: ACTION_DOWN //按下

KeyButtonView: Back button event: ACTION_UP //弹上

WindowManager: KeyEvent:4 //Back键，

InputDispatcher: Asynchronous input event injection succeeded. //表示点击动作成功

Recent:（只是A12有log）D OverviewProxyRecentsImpl: toggleRecentAppsD OverviewProxyRecentsImpl: toggleRecentApps: device is unlockedD OverviewProxyRecentsImpl: toggleRecentApps: notify launcher through proxyHome:I sysui_multi_action: [757,931,758,4,759,3,932,0,933,0] //home键downI sysui_multi_action: [757,931,758,4,759,3,932,0,933,1] //home键upBack:sysui_multi_action: [757,931,758,4,759,4,932,0,933,0] //back键downsysui_multi_action: [757,931,758,4,759,4,932,0,933,1] //back键upI KeyButtonView: Back button event: ACTION_DOWNI KeyButtonView: Back button event: ACTION_UP

//正常log:down->up时长只有200多毫秒D InputReader: dispatchTouches action DOWN now(ns): 174899239412D InputReader: notifyMotion call dispatcherI sysui_multi_action: [757,931,758,4,759,3,932,0,933,0] //home键downV InputDispatcher: Asynchronous input event injection succeeded.

KeyEvent 常用按键KeyCode值：

Home键：3

Back键：4

Recent键：无

音量上/+键：24

音量下/-键：25

电源键：26

intercept_power: [ACTION_DOWN,0,1]---power键按下intercept_power: [ACTION_UP,0,1]---power键抬起

切换导航样式log：Settings进程会打印sysui_multi_action: [757,830,758,4,833,0,854,system_nav_3buttons,1089,0]sysui_multi_action: [757,830,758,4,833,0,854,system_nav_gestural,1089,0]

二、系统问题相关日志

切换用户starting user |show calledusb拔掉广播ACTION_POWER_DISCONNECTED

深色主题

persist.sys.theme,2 深色

persist.sys.theme,1 正常

旋转屏幕：

mRotation=ROTATION_0/mRotation=ROTATION_90/mRotation=ROTATION_180/mRotation=ROTATION_270

1.内存类关键词

（bugreport里会打印）：diskstats:|ps -A |- CPU INFO|Free RAM:内存泄露关键

日志：

blocking GC Alloc|WaitForGcToComplete|Clamp target GC heap from|Throwing OutOfMemoryError|Failed to allocate

重要日志：

Throwing OutOfMemoryError "Failed to allocate a 112 byte allocation with 0 free bytes and 0B until OOM, target footprint 134217728, growth limit 134217728"

查系统给应用分配内存：

J606L:/ # getprop|grep heapgrowthlimit

[dalvik.vm.heapgrowthlimit]: [128m]

J606L:/ # getprop|grep heapstart

[dalvik.vm.heapstartsize]: [8m]

J606L:/ # getprop|grep heapsize

[dalvik.vm.heapsize]: [512m]

参考案例分析：

1.1.Framework-Google-GMS crashFinalizerWatchdogDaemon

1.2.有多个anr及crash弹窗提示太过频繁

2. watchDog关键词：

WATCHDOG IS GOING TO KILL SYSTEM PROCESS |W Watchdog:

3. 死机重启前操作：

dmesglog/------ KERNEL LOG (dmesg) ------

4.Google应用

4.1.下载:

Finsky

status=DOWNLOADING

Finsky:download_service: [189] jug.a(3): Broadcasting <30:RUNNING:97%[97%]>.

4.2.安装：

Begin install of

status=INSTALLING

Successful install of

系统问题案例分析及相关日志

1.Framework-Google-GMS （com.google.android.gms Crash）

问题分析：

应用内部存在内存泄漏，多处不必要的对象创建，未来得及释放。造成GC压力过大，Finalize对象累积太多，导致FinalizerDaemon线程来不及处理。FinalizerWatchdogDaemon线程会让VM退出，应用程序程序crash。

应用内部逻辑问题，建议保持更新，申请wont do。

应用最小内存：8M

J606L:/ # getprop|grep heapstart

[dalvik.vm.heapstartsize]: [8m]

应用最大内存：128M

J606L:/ # getprop|grep heapgrowthlimit

[dalvik.vm.heapgrowthlimit]: [128m]

关键日志：

allocation with 0 free bytes and 0B until OOM, target footprint 134217728, growth limit 134217728

相关日志：

应用中存在多次内存泄露

Line 61834: 10-26 10:19:26.157 3167 3199 I ogle.android.g: Clamp target GC heap from 135MB to 128MB

内存泄露

Line 11833: 10-26 10:20:52.926 3167 3199 I ogle.android.g: Clamp target GC heap from 135MB to 128MB

Line 11841: 10-26 10:20:52.958 3167 6401 I ogle.android.g: WaitForGcToComplete blocked Alloc on HeapTrim for 24.371ms

Line 11843: 10-26 10:20:52.959 3167 6401 I ogle.android.g: Starting a blocking GC Alloc

Line 11874: 10-26 10:20:53.215 3167 4541 I ogle.android.g: Waiting for a blocking GC Alloc

不必要的对象创建造成GC压力过大，Finalize对象累积太多，导致FinalizerDaemon线程来不及处理

10-26 10:21:17.903 3167 3203 E AndroidRuntime: FATAL EXCEPTION: FinalizerWatchdogDaemon

10-26 10:21:17.903 3167 3203 E AndroidRuntime: Process: com.google.android.gm, PID: 3167

10-26 10:21:17.903 3167 3203 E AndroidRuntime: java.util.concurrent.TimeoutException: com.android.internal.os.BinderInternal$GcWatcher.finalize() timed out after 10 seconds

10-26 10:21:17.903 3167 3203 E AndroidRuntime: at com.android.internal.os.BinderInternal$GcWatcher.finalize(BinderInternal.java:63)

10-26 10:21:17.903 3167 3203 E AndroidRuntime: at java.lang.Daemons$FinalizerDaemon.doFinalize(Daemons.java:289)

10-26 10:21:17.903 3167 3203 E AndroidRuntime: at java.lang.Daemons$FinalizerDaemon.runInternal(Daemons.java:276)

10-26 10:21:17.903 3167 3203 E AndroidRuntime: at java.lang.Daemons$Daemon.run(Daemons.java:137)

10-26 10:21:17.903 3167 3203 E AndroidRuntime: at java.lang.Thread.run(Thread.java:919)

应用中存在内存溢出，即将OOM

Line 3073: 10-26 10:24:38.657 3167 3202 W ogle.android.g: Throwing OutOfMemoryError "Failed to allocate a 40 byte allocation with 0 free bytes and 0B until OOM, target footprint 134217728, growth limit 134217728" (VmSize 5614796 kB)

Line 3211: 10-26 10:24:57.678 3167 3202 W ogle.android.g: Throwing OutOfMemoryError "Failed to allocate a 112 byte allocation with 0 free bytes and 0B until OOM, target footprint 134217728, growth limit 134217728" (VmSize 5614796 kB, recursive case)

2.有多个anr及crash弹窗提示太过频繁

crash弹框：Contacts Storage keeps stopping和android.process.acore keeps stopping

关键日志：FATAL EXCEPTION|No space left on device|Device free memory is insufficient

Line 365148: 10-09 09:13:07.621 1000 978 978 I CNSS : Device free memory is insufficient //设备可用内存不足

Line 365151: 10-09 09:13:07.627 1000 978 978 I CNSS : Device free memory is insufficient

10-09 09:13:07.784 1000 1340 31659 E DropBoxManagerService: Can't write: system_app_crash

10-09 09:13:07.784 1000 1340 31659 E DropBoxManagerService: java.io.FileNotFoundException: /data/system/dropbox/drop19792.tmp: open failed: ENOSPC (No space left on device)

结合视频及log分析，该设备应用Contacts多次发生crash，crash弹窗提示属于安卓机制正常现象。

经排查：1.diskstats的信息核算和设备EMMC的容量一致，LenovoTB-J606L设备 ROM:64G。

问题log中:

DUMP OF SERVICE diskstats:

Latency: 0ms [512B Data Write] Recent Disk Write Speed (kB/s) = 19974

Data-Free: 316692K / 44952396K total = 0% free 总：42.8G

Cache-Free: 316692K / 44952396K total = 0% free 总：42.8G

System-Free: 0K / 1254320K total = 0% free 1.3G

2.和其他的issue中得到信息在总容量一致

DUMP OF SERVICE diskstats:

Latency: 6ms [512B Data Write]

Recent Disk Write Speed (kB/s) = 10165

Data-Free: 38999292K / 44952396K total = 86% free 总：42.8G

Cache-Free: 38999292K / 44952396K total = 86% free 总：42.8G

System-Free: 3633076K / 3932528K total = 92% free 3.75G

3.开启了dump的 蓝牙Log的功能，Ramdump停止录制，可以看到存储被用完。

10-09 09:37:11.354 1000 2314 2314 D LenovoLogger: stopLogger

10-09 09:37:11.369 1000 1340 1485 D BluetoothManagerService: MESSAGE_REGISTER_ADAPTER

10-09 09:37:11.370 1000 2314 2314 D LenovoLogger: Disable bluetooth btsnoop log

10-09 09:37:11.374 1000 2314 2314 W lenovologgerpannel avail size in MB:: /data0

4.检查防止Data分区被写满的修改生效，用apk—normal可以填充 剩 212m，apk—system可以填充满。

测试结论：经查看，这32G基本为LTR测试中的log，可能由于国庆假期测试时间过长，log存储太多。

经过分析及排查和测试一起确认，该设备由于长时间测试，LTR测试log大量占用设备空间，导致空间不足引起应用Contacts多次发生crash，crash弹窗提示属于安卓机制正常现象。

因此申请wont do。

3.[Framework-Google-GMS] com.google.android.gms.persistent Crash

从log看，出现此现象之前，用户一直在调整小窗口。小窗口存在异常log，导致systemserver 的 android.anim 线程发生了ne，引起system died 。

已走Productivity mode-Full。

关键日志：

//update size

11-24 00:41:40.250 4125 19815 E TelecomFramework: MultiWindowService: updateTaskResizerBounds: Rect(819, 91 - 1865, 297)

//systemserver 的 android.anim 线程发生了ne

11-24 00:41:40.319 1355 1558 F libc : Fatal signal 11 (SIGSEGV), code 1 (SEGV_MAPERR), fault addr 0x968 in tid 1558 (android.anim), pid 1355 (system_server)

11-24 00:41:40.517 3096 3096 F DEBUG : pid: 1355, tid: 1558, name: android.anim >>> system_server <<<

11-24 00:41:40.517 3096 3096 F DEBUG : uid: 1000

11-24 00:41:40.517 3096 3096 F DEBUG : signal 11 (SIGSEGV), code 1 (SEGV_MAPERR), fault addr 0x968

11-24 00:41:40.517 3096 3096 F DEBUG : Cause: null pointer dereference

//系统死亡

11-24 00:41:44.453 527 527 I ServiceManager: service 'account' died

11-24 00:41:44.456 527 527 I ServiceManager: service 'content' died

.....

11-24 00:41:44.456 527 527 I ServiceManager: service 'settings' died

11-24 00:41:44.464 527 527 I ServiceManager: service 'network_score' died

11-24 00:41:44.464 527 527 I ServiceManager: service 'package' died

// system died;引起上层重启

11-24 00:41:44.490 2869 2869 D AndroidRuntime: Shutting down VM

11-24 00:41:44.499 2869 2869 E AndroidRuntime: FATAL EXCEPTION: main

11-24 00:41:44.499 2869 2869 E AndroidRuntime: Process: com.google.android.gms.persistent, PID: 2869

11-24 00:41:44.499 2869 2869 E AndroidRuntime: DeadSystemException: The system died; earlier logs will point to the root cause

11-24 00:41:44.520 2869 2869 E GCore-Chimera-Crash: Hit an exception while processing the UncaughtExceptionHandler:

11-24 00:41:44.520 2869 2869 E GCore-Chimera-Crash: DeadSystemException: The system died; earlier logs will point to the root cause

4.[Framework-Google-GMS] com.google.android.googlequicksearchbox:search Crash

问题分析：

GMS应用内部存在未释放引用，出现内存泄露，频繁GC可看出内存空间超过512M无法释放可用空间,导致应用内存溢出。建议保持更新，建议wont do.

11-29 04:32:01.825 1399 1420 I system_server: NativeAlloc concurrent copying GC freed 174831(9150KB) AllocSpace objects, 63(3512KB) LOS objects, 42% free, 31MB/55MB, paused 140us total 209.732ms

//应用最早出现内存泄露

11-29 06:02:39.667 5681 5681 I earchbox:searc: Waiting for a blocking GC Alloc

11-29 06:02:39.686 5681 5681 I earchbox:searc: WaitForGcToComplete blocked Alloc on ProfileSaver for 18.173ms

11-29 06:02:39.686 5681 5681 I earchbox:searc: Starting a blocking GC Alloc

11-29 06:06:41.688 5681 5681 I earchbox:searc: Waiting for a blocking GC Alloc

11-29 06:06:42.363 5681 5926 I earchbox:searc: Clamp target GC heap from 523MB to 512MB

11-29 06:06:42.363 5681 5926 I earchbox:searc: Alloc concurrent copying GC freed 22771(1031KB) AllocSpace objects, 131(11MB) LOS objects, 2% free, 499MB/512MB, paused 82us total 687.552ms

11-29 06:15:13.797 5681 5681 I earchbox:searc: Alloc concurrent copying GC freed 27(648B) AllocSpace objects, 0(0B) LOS objects, 0% free, 511MB/512MB, paused 75us total 809.071ms

1-29 06:15:14.287 5681 5738 I earchbox:searc: Waiting for a blocking GC Alloc

11-29 06:15:14.287 5681 5782 I earchbox:searc: Waiting for a blocking GC Alloc

11-29 06:15:14.442 5681 5735 I earchbox:searc: Waiting for a blocking GC Alloc

11-29 06:15:14.461 5681 5681 I earchbox:searc: Clamp target GC heap from 535MB to 512MB

11-29 06:15:14.461 5681 5681 I earchbox:searc: Alloc concurrent copying GC freed 752(57KB) AllocSpace objects, 2(192KB) LOS objects, 0% free, 511MB/512MB, paused 77us total 603.968ms

11-29 06:15:14.461 5681 5681 E AndroidRuntime: FATAL EXCEPTION: main

11-29 06:15:14.461 5681 5681 E AndroidRuntime: Process: com.google.android.googlequicksearchbox:search, PID: 5681

11-29 06:15:14.461 5681 5681 E AndroidRuntime: com.facebook.litho.ap: ElementsRootFlat

11-29 06:15:14.461 5681 5681 E AndroidRuntime: Caused by: com.facebook.litho.ap: ComponentType

11-29 06:15:14.461 5681 5681 E AndroidRuntime: Caused by: java.lang.OutOfMemoryError: Failed to allocate a 97360 byte allocation with 72352 free bytes and 70KB until OOM, target footprint 536870912, growth limit 536870912

5.[Framework-Google-GMS] com.google.android.calendar Anr

结合mainlog和trace信息看，是Google Calendar 内部发生互锁导致导致广播超时发生 anr。

从堆栈看，均为 Calendar 内部调用，无法修改。申请 wont fix。

关键log:

11-27 21:23:48.049 13202 13202 I Choreographer: Skipped 39 frames! The application may be doing too much work on its main thread.

11-27 21:23:48.805 13202 13214 W ndroid.calenda: Suspending all threads took: 5.063ms

// 真正发生anr，Dump到堆栈data/anr/anr_-11-27-21-32-15-752文件

11-27 21:32:15.752 1354 1483 I ActivityManager: Dumping to /data/anr/anr_-11-27-21-32-15-752

11-27 21:32:15.752 1354 1483 I ActivityManager: Collecting stacks for pid 13202

11-27 21:32:15.781 1354 1483 I system_server: libdebuggerd_client: started dumping process 13202

11-27 21:32:15.788 1083 1083 I /system/bin/tombstoned: registered intercept for pid 13202 and type kDebuggerdJavaBacktrace

11-27 21:32:15.796 13202 13213 I ndroid.calenda: Thread[3,tid=13213,WaitingInMainSignalCatcherLoop,Thread*=0x79d8ca5800,peer=0x132803f8,"Signal Catcher"]: reacting to signal 3

11-27 21:32:15.798 13202 13213 I ndroid.calenda:

11-27 21:32:16.219 1083 1083 I /system/bin/tombstoned: received crash request for pid 13202

11-27 21:32:16.219 1083 1083 I /system/bin/tombstoned: found intercept fd 512 for pid 13202 and type kDebuggerdJavaBacktrace

11-27 21:32:16.222 13202 13213 I ndroid.calenda: Wrote stack traces to tombstoned

11-27 21:32:16.222 1354 1483 I system_server: libdebuggerd_client: done dumping process 13202

// 程序无响应

11-27 21:32:29.013 1354 1483 I ActivityManager: Done dumping

11-27 21:32:29.071 1354 1483 E ActivityManager: ANR in com.google.android.calendar

11-27 21:32:29.071 1354 1483 E ActivityManager: PID: 13202

11-27 21:32:29.071 1354 1483 E ActivityManager: Reason: Broadcast of Intent { act=com.google.android.c2dm.intent.RECEIVE flg=0x1000010 pkg=com.google.android.calendar cmp=com.google.android.calendar/com.google.android.libraries.notifications.entrypoints.gcm.GcmBroadcastReceiver (has extras) }

anr_-11-27-21-32-15-752：

----- pid 13202 at -11-27 21:32:15 -----

Cmd line: com.google.android.calendar

// calendar 主线程 thread 1，在等待 34号线程

"main" prio=5 tid=1 Blocked

| group="main" sCount=1 dsCount=0 flags=1 obj=0x719a7e78 self=0x79d8ca3c00

| sysTid=13202 nice=-10 cgrp=default sched=0/0 handle=0x79da20bed0

| state=S schedstat=( 16269419750 1686751945 9297 ) utm=1414 stm=212 core=5 HZ=100

| stack=0x7fdafe9000-0x7fdafeb000 stackSize=8192KB

| held mutexes=

at cal.owy.l(PG:-1)

- waiting to lock <0x0e021f24> (a cal.owy) held by thread 34

at cal.owx.b(PG:1)

at cal.pba.d(PG:5)

- locked <0x063c6a8d> (a cal.pba)

// calendar 34号线程，在等待主线程 thread 1

"BACKGROUND_0" prio=5 tid=34 Blocked

| group="BACKGROUND" sCount=1 dsCount=0 flags=1 obj=0x13282cd8 self=0x794795d800

| sysTid=13262 nice=1 cgrp=default sched=0/0 handle=0x78d7c89d50

| state=S schedstat=( 567132691 274993231 1363 ) utm=48 stm=8 core=0 HZ=100

| stack=0x78d7b87000-0x78d7b89000 stackSize=1039KB

| held mutexes=

at cal.pba.c(PG:-1)

- waiting to lock <0x063c6a8d> (a cal.pba) held by thread 1

at cal.owy.o(PG:1)

- locked <0x0e021f24> (a cal.owy)

6.点击相册显示“相册屡次停止运行”

测试在安装GMS过程中使用Photos应用导致，操作问题。建议wont do

关键日志信息：

正在下载GMS

10-15 22:40:19.424 14579 1454 I Finsky:download_service: [189] jug.a(3): Broadcasting <30:RUNNING:97%[97%]>.

10-15 22:40:19.441 14406 14406 I Finsky : [2] nrg.a(191): Installer: Notifying status update. package=com.google.android.gms, status=DOWNLOADING

10-15 22:40:19.452 14406 14617 I Finsky : [171] odk.b(67): IQ: Notifying installation update. package=com.google.android.gms, status=DOWNLOADING

开始安装GMS

10-15 22:40:28.795 14406 14501 I Finsky : [132] nuc.c(55): IT: Begin install of com.google.android.gms (isid: s91KhTJiQFuh0UDD1JH91g)

10-15 22:40:28.827 14406 14501 I Finsky : [132] nrg.a(191): Installer: Notifying status update. package=com.google.android.gms, status=INSTALLING

10-15 22:40:28.838 14406 14617 I Finsky : [171] odk.b(67): IQ: Notifying installation update. package=com.google.android.gms, status=INSTALLING

强制停止GMS服务

10-15 22:40:29.668 1415 1504 I ActivityManager: Force stopping com.google.android.gms appid=10119 user=-1: installPackageLI

10-15 22:40:29.669 1415 1504 I ActivityManager: Killing 26613:com.google.android.youtube/u0a153 (adj 995): stop com.google.android.gms

Photos Crash 两次

10-15 22:40:47.880 1415 3656 I am_crash: [16556,0,com.google.android.apps.photos,953794117,java.lang.SecurityException,Unable to start service Intent{ act=com.google.android.c2dm.intent.REGISTER pkg=com.google.android.gms (has extras) }: Unable to launch app com.google.android.gms/10119 for service Intent

{ act=com.google.android.c2dm.intent.REGISTER pkg=com.google.android.gms }: process is bad,ContextImpl.java,1613]

10-15 22:40:52.665 1415 5215 I am_crash: [2971,0,com.google.android.apps.photos,953794117,java.lang.SecurityException,Unable to start service Intent

{ act=com.google.android.c2dm.intent.REGISTER pkg=com.google.android.gms (has extras) }: Unable to launch app com.google.android.gms/10119 for service Intent

{ act=com.google.android.c2dm.intent.REGISTER pkg=com.google.android.gms }: process is bad,ContextImpl.java,1613]

GMS安装完成

10-15 22:40:57.738 14406 14406 I Finsky : [2] ntz.c(4): IT: Successful install of com.google.android.gms (isid: s91KhTJiQFuh0UDD1JH91g)

7.[Framework Performance Stablility] com.android.vending Anr

问题分析：

Google PlayStore应用内部存在死锁，导致主线程超时引起Anr。建议保持更新，建议wont do。

关键日志信息：

//存储anr的dump信息

12-04 14:06:12.541 1000 1374 1488 I ActivityManager: Dumping to /data/anr/anr_-12-04-14-06-12-540

//应用弹出无响应

12-04 14:06:23.518 1000 1374 1488 E ActivityManager: ANR in com.android.vending

12-04 14:06:23.518 1000 1374 1488 E ActivityManager: PID: 677

12-04 14:06:23.518 1000 1374 1488 E ActivityManager: Reason: executing service com.android.vending/com.google.android.finsky.scheduler.process.mainimpl.PhoneskyJobServiceMain

------ VM TRACES AT LAST ANR (/data/anr/anr_-12-04-14-06-12-540: -12-04 14:06:23) ------

----- pid 677 at -12-04 14:06:12 -----

Cmd line: com.android.vending

//等待<0x05ee37cf>锁，被线程83持有

"main" prio=5 tid=1 Blocked

| group="main" sCount=1 dsCount=0 flags=1 obj=0x72877a78 self=0xea05ce00

| sysTid=677 nice=0 cgrp=default sched=0/0 handle=0xea560dc0

| state=S schedstat=( 14831821629 2738463385 17496 ) utm=1151 stm=331 core=0 HZ=100

| stack=0xff7bb000-0xff7bd000 stackSize=8192KB

| held mutexes=

at aciw.n(PG:1)

- waiting to lock <0x05ee37cf> (a com.google.android.finsky.installqueue.impl.InstallQueuePhoneskyJob) held by thread 83

at aciw.m(PG:-1)

at rdv.E(PG:1)

at rdv.r(PG:1)

at com.google.android.finsky.installqueue.impl.InstallQueuePhoneskyJob.t(PG:-1)

at aciw.q(PG:8)

at aciv.a(unavailable:7)

at acha.e(PG:7)

- locked <0x0ba1fdff> (a acha)

//等待<0x0ba1fdff>锁，被主线程持有

"InstallQueueUsingScheduler" prio=5 tid=83 Blocked

| group="main" sCount=1 dsCount=0 flags=1 obj=0x14544230 self=0xd4081800

| sysTid=6628 nice=10 cgrp=default sched=0/0 handle=0xa5d0b230

| state=S schedstat=( 367180002 388557770 934 ) utm=28 stm=8 core=1 HZ=100

| stack=0xa5c08000-0xa5c0a000 stackSize=1040KB

| held mutexes=

at acha.b(PG:-1)

- waiting to lock <0x0ba1fdff> (a acha) held by thread 1

at aciw.n(PG:5)

- locked <0x05ee37cf> (a com.google.android.finsky.installqueue.impl.InstallQueuePhoneskyJob)

at aciw.m(PG:-1)

8.[Google Services Framework]切换40多种语言后，测试机切换语言出现卡顿，一台出现“Google Services Framework keeps stopping”，重启无法恢复

从Log分析，gms服务相关应用binder数据传输的数据太大导致system server挂了，引起死机 、卡顿 、Google GMS应用大量OutOfMemoryError，等一系列性能问题。

Line 68764: 12-29 03:21:46.057 10119 3535 3535 E gle.android.gm: Not starting debugger since process cannot load the jdwp agent.

Line 68827: 12-29 03:21:46.476 1000 1329 2411 E JavaBinder: !!! FAILED BINDER TRANSACTION !!! (parcel size = 523848)

12-29 03:21:46.476 1000 1329 2411 E JavaBinder: !!! FAILED BINDER TRANSACTION !!! (parcel size = 523848)

12-29 03:21:46.477 1000 1329 2411 E ActivityManager: Exception thrown during bind of ProcessRecord{824ad91 3535:com.google.android.gms/u0a119{color}}

12-29 03:21:46.477 1000 1329 2411 E ActivityManager: android.os.TransactionTooLargeException: data parcel size 523848 bytes

12-29 03:21:46.477 1000 1329 2411 E ActivityManager: at android.os.BinderProxy.transactNative(Native Method)

12-29 03:21:46.477 1000 1329 2411 E ActivityManager: at android.os.BinderProxy.transact(BinderProxy.java:511)

12-29 03:21:46.477 1000 1329 2411 E ActivityManager: at android.app.IApplicationThread$Stub$Proxy.bindApplication(IApplicationThread.java:1479)

12-29 03:21:46.477 1000 1329 2411 E ActivityManager: at com.android.server.am.ActivityManagerService.attachApplicationLocked(ActivityManagerService.java:5137)

12-29 03:21:46.477 1000 1329 2411 E ActivityManager: at com.android.server.am.ActivityManagerService.attachApplication(ActivityManagerService.java:5262)

12-29 03:21:46.477 1000 1329 2411 E ActivityManager: at android.app.IActivityManager$Stub.onTransact(IActivityManager.java:)

12-29 03:21:46.477 1000 1329 2411 E ActivityManager: at com.android.server.am.ActivityManagerService.onTransact(ActivityManagerService.java:2763)

12-29 03:21:46.477 1000 1329 2411 E ActivityManager: at android.os.Binder.execTransactInternal(Binder.java:1021)

12-29 03:21:46.477 1000 1329 2411 E ActivityManager: at android.os.Binder.execTransact(Binder.java:994)

......

12-29 03:21:46.591 1000 3631 3631 F DEBUG : Timestamp: -12-29 03:21:46-0500

12-29 03:21:46.591 1000 3631 3631 F DEBUG : pid: 1329, tid: 2411, name: Binder:1329_6 >>> system_server <<<

12-29 03:21:46.591 1000 3631 3631 F DEBUG : uid: 1000

12-29 03:21:46.591 1000 3631 3631 F DEBUG : signal 35 (<debuggerd signal>), code 0 (SI_USER), fault addr --------

12-29 03:21:46.591 1000 3631 3631 F DEBUG : x0 0000000000000000 x1 00000000c0306201 x2 00000071960dcb28 x3 00000000000002d0

12-29 03:21:46.591 1000 3631 3631 F DEBUG : x4 00000071960dcc10 x5 00000071dfdd7e44 x6 00000000000002d0 x7 0000000000000000

12-29 03:21:46.591 1000 3631 3631 F DEBUG : x8 000000000000001d x9 00000071960dcad8 x10 00000071960dcaa0 x11 00000071960dcad8

12-29 03:21:46.591 1000 3631 3631 F DEBUG : x12 00000071960dcb20 x13 00000071d6178400 x14 0000000070e33b78 x15 000000007083036c

12-29 03:21:46.591 1000 3631 3631 F DEBUG : x16 00000072e8423e60 x17 00000072e4e2762c x18 000000718b35c000 x19 00000071960de020

12-29 03:21:46.591 1000 3631 3631 F DEBUG : x20 00000071dfe44200 x21 00000071dfe44320 x22 0000000000000044 x23 0000000000000100

12-29 03:21:46.591 1000 3631 3631 F DEBUG : x24 00000071960de020 x25 0000000000000000 x26 0000000012f5df68 x27 0000000000000000

12-29 03:21:46.591 1000 3631 3631 F DEBUG : x28 0000000000000000 x29 00000071960dcb10

12-29 03:21:46.591 1000 3631 3631 F DEBUG : sp 00000071960dca20 lr 00000072e4e276b4 pc 00000072e4e6d098

之前复现相关log:

最近1分钟，5分钟的CPU负载较高，1分钟的CPU负载 > 5分钟的CPU负载，说明服务器目前处在CPU负载高峰期

------ UPTIME (uptime) ------

01:21:23 up 6 min, 0 users, load average: 16.29, 8.25, 3.58

------ UPTIME (uptime) ------

01:31:59 up 17 min, 0 users, load average: 1047.38, 237.35, 81.10

------ UPTIME (uptime) ------

04:52:56 up 1 day, 3:38, 0 users, load average: 119.31, 31.11, 11.94

------ UPTIME (uptime) ------

05:02:58 up 1 day, 3:48, 0 users, load average: 20.44, 14.49, 11.06

从测试提供的现场内存、CPU截图来看，卡顿是因为系统内存不足 system server占比较高。

12-17 01:15:03.787 2772 2772 E ActivityThread: Failed to find provider info for com.google.android.gsf.gservices

12-17 01:17:04.842 2797 25450 E AndroidRuntime: FATAL EXCEPTION: [com.google.android.gms.chimera.PersistentIntentOperationService$ChimeraService-Executor] idle

12-17 01:17:04.842 2797 25450 E AndroidRuntime: Process: com.google.android.gms.persistent, PID: 2797

12-17 01:17:04.842 2797 25450 E AndroidRuntime: java.lang.OutOfMemoryError: pthread_create (1040KB stack) failed: Try again

GMS相关应用偶现问题，无代码无法修改，建议保持更新，建议wont do。

9.电容笔放置屏幕上，开启youtube播放视频，同时开启录屏。待机至第二天屏幕黑屏，打开界面为主界面，录屏只录制40分钟

结合Log和视频分析：

06:05:46打开youtube，06:06:12开始录屏，43分12秒后录屏结束恰好为06:49:24左右， 06:49:25左右MPEG4Writer.cpp 提示:记录的文件大小超出限制(4294967295byte=4G)，视频大小也3.8G。

综上：录屏超过4G大小限制，引起 BufferQueue has been abandoned。

Line 7560: 10-16 06:05:46.327 1241 2031 I ActivityTaskManager: START u0 {act=android.intent.action.MAIN cat=[android.intent.category.LAUNCHER] flg=0x4000000 cmp=com.google.android.youtube/com.google.android.apps.youtube.app.WatchWhileActivity bnds=[1000,841][1329,1056] (has extras)} from uid 10163

Line 12797: 10-16 06:06:08.058 1241 5873 I ActivityTaskManager: START u0 {flg=0x10008000 cmp=com.lenovo.screencapture/.activity.GetPermissionActivity (has extras)} from uid 10124

Line 12892: 10-16 06:06:08.182 1241 5856 I ActivityTaskManager: START u0 {act=android.content.pm.action.REQUEST_PERMISSIONS pkg=com.google.android.permissioncontroller cmp=com.google.android.permissioncontroller/com.android.packageinstaller.permission.ui.GrantPermissionsActivity (has extras)} from uid 10124

Line 13452: 10-16 06:06:09.892 1241 2959 I ActivityTaskManager: START u0 {act=android.content.pm.action.REQUEST_PERMISSIONS pkg=com.google.android.permissioncontroller cmp=com.google.android.permissioncontroller/com.android.packageinstaller.permission.ui.GrantPermissionsActivity (has extras)} from uid 10124

Line 13576: 10-16 06:06:10.995 1241 5868 I ActivityTaskManager: START u0 {cmp=com.android.systemui/.media.MediaProjectionPermissionActivity} from uid 10124

Line 13887: 10-16 06:06:12.258 799 825 I /vendor/bin/hw/vendor.qti.hardware.servicetracker@1.1-service: startService() is called for servicecom.lenovo.screencapture/.service.RecorderService

Line 13897: 10-16 06:06:12.270 17784 17784 D FZY : startRecorderService: SCREEN_RECORDING_START

Line 13898: 10-16 06:06:12.280 1241 1485 V ActivityManager: Attempted to start a foreground service (com.lenovo.screencapture/.service.RecorderService) with a broken notification (no icon: Notification(channel=channelId pri=0 contentView=null vibrate=null sound=null defaults=0x0 flags=0x40 color=0x00000000 vis=PRIVATE))

Line 13899: 10-16 06:06:12.280 17784 17784 D FZY : RecorderService onCreate:

Line 13915: 10-16 06:06:12.354 17784 17784 D FZY : RecorderService onStartCommand: SCREEN_RECORDING_START

Line 14083: 10-16 06:06:13.501 1035 5230 I MPEG4Writer: limits: 4294967295/0 bytes/us, bit rate: 12595112 bps and the estimated moov size 3192 bytes

.......

Line 47185: 10-16 06:47:09.571 1035 18011 W MPEG4Writer: Recorded file size is approaching limit 4294967295bytes

Line 49291: 10-16 06:49:25.854 1035 18011 W MPEG4Writer: No FileDescripter for next recording

Line 49292: 10-16 06:49:25.857 1035 18011 W MPEG4Writer: Recorded file size exceeds limit 4294967295bytes

10-16 06:49:25.904 1056 20272 W GraphicBufferSource: onFrameAvailable: EOS is sent, ignoring frame

​ Line 49300: 10-16 06:49:25.917 1035 18016 W MPEG4Writer: No FileDescripter for next recording

​ Line 49301: 10-16 06:49:25.917 1035 18016 W MPEG4Writer: Recorded file size exceeds limit 4294967295bytes

​ Line 49368: 10-16 06:49:26.493 1035 18016 I MPEG4Writer: Received total/0-length (20249/0) buffers and encoded 20247 frames. - Audio

​ Line 49369: 10-16 06:49:26.493 1035 18016 I MPEG4Writer: Audio track drift time: 0 us

​ Line 49376: 10-16 06:49:26.556 1056 3062 E BufferQueueProducer: [GraphicBufferSource] dequeueBuffer: **BufferQueue has been abandoned**

​ Line 49378: 10-16 06:49:26.557 866 866 W SurfaceFlinger: **Dequeuing buffer for display [MainActivity] failed, bailing out of client composition for this frame**

视频文件大小：3.8G,已走给录屏

10.测试机从暗环境切换到亮环境，亮度数值变化与进度条变化不一致（进度条有点慢）

分析：

从复现log看有这些从暗到亮的变化：

第一次经历大约2s

10-27 20:15:10.795 D/RampAnimator( 1089): mTargetValue 254 mCurrentValue 30 mAnimatedValue 29.908333

10-27 20:15:12.789 D/RampAnimator( 1089): mTargetValue 254 mCurrentValue 254 mAnimatedValue 254.0

第二次经历大约900ms

10-27 20:17:06.171 D/RampAnimator( 1089): mTargetValue 198 mCurrentValue 72 mAnimatedValue 71.90833

10-27 20:17:07.283 D/RampAnimator( 1089): mTargetValue 198 mCurrentValue 198 mAnimatedValue 197.85858

屏幕从暗到亮的时间允许范围以内，屏幕的自动背光功能本身没有问题。

背光自动更新的时候是每个step调整都会调用 DisplayPowerController中updateSecreenBrightnessSetting来更新setting背光值。

这个设置状态和上面log是一个函数内的调用，是同步的，属于LV自动背光方案，调整余地不大。

走systemUI同事确认下亮度条的更新方式，是否有优化的可能。

已走systemUI

如果觉得《Android系统问题及日志分析》对你有帮助，请点赞、收藏，并留下你的观点哦！