Sensor记录日志导致的亮屏慢问题分析

一. 问题描述

1.1 现象

      手机解锁卡顿

1.2 结论

    diag记录数据慢导致系统卡顿

二. 问题分析

2.1日志分析

    在大量的日志中发现Slow Looper的日志，都是DisplayPowerController的DisplayControllerHandler处理消息超时，并且有大量的dvm_lock_sample提示registerListenerImpl耗时了，亮屏过程中无论system_server还是systemui都会去注册很多sensor，由于大量异常的

registerListenerImpl慢不得不怀疑是sensor注册慢导致的:

关键日志1： 11-19 20:03:43.936 1000 1683 1903 W Looper : Slow Looper PowerManagerService: Long Msg: seq=93258 plan=20:03:40.597 late=0ms wall=3340ms running=9ms runnable=6ms h=com.android.server.display.DisplayPowerController$DisplayControllerHandler w=1     关键日志2： 11-19 20:41:21.495 1000 2834 18488 I dvm_lock_sample: 43,1751*,SystemSensorManager.java,183,boolean android.hardware.SystemSensorManager.registerListenerImpl(android.ha rdware.SensorEventListener, android.hardware.Sensor, int, android.os.Handler, int, int),,183,boolean android.hardware.SystemSensorManager.registerListenerImpl(android.hardware.SensorEventListener, androi d.hardware.Sensor, int, android.os.Handler, int, int),100">com.android.systemui,0,AsyncTask #43,1751,SystemSensorManager.java,183,boolean android.hardware.SystemSensorManager.registerListenerImpl(android.ha rdware.SensorEventListener, android.hardware.Sensor, int, android.os.Handler, int, int),,183,boolean android.hardware.SystemSensorManager.registerListenerImpl(android.hardware.SensorEventListener, androi d.hardware.Sensor, int, android.os.Handler, int, int),100

怀疑归怀疑，但是有没有直接的证据来证明是sensor注册慢导致的，光看这日志没法继续分析到底是哪里慢了

2.2复现分析

    在想办法复现的过程中，刚好被拉进一卡顿群，说有个卡顿的问题想找framework的同学帮忙看一下。那我就去看了一下，发现他们有一个大概率复现的方法。打开打开小爱同学（其实和小爱没关系），设置指纹解锁，然后不断的指纹解锁就能复现卡顿的问题了。

    我就用这个方法去复现，发现还真的很好复现，复现之后当然需要知道在哪里卡顿了，这时候十八般武艺可以轮番上阵了：

1.查看system_server卡住的原因

    既然是system_server卡顿，那么就在卡顿的时候抓system_server 的trace，具体命令为kill -3 pid（system_server的pid），然后我抓到的关键trace如下：

"main" prio=5 tid=1 Native   | group="main" sCount=1 dsCount=0 flags=1 obj=0x7610b3c8 self=0x7153469c00   | sysTid=1636 nice=-2 cgrp=default sched=0/0 handle=0x71d94d7ed0   | state=S schedstat=( 12607677644 3411181337 21636 ) utm=905 stm=355 core=5 HZ=100   | stack=0x7fc32bf000-0x7fc32c1000 stackSize=8192KB   | held mutexes=   kernel: (couldn't read /proc/self/task/1636/stack)   native: #00 pc 00000000000c14a4  /apex/com.android.runtime/lib64/bionic/libc.so (__ioctl+4)   native: #01 pc 000000000007bb2c  /apex/com.android.runtime/lib64/bionic/libc.so (ioctl+132)   native: #02 pc 000000000008a338  /system/lib64/libhidlbase.so (android::hardware::IPCThreadState::transact(int, unsigned int, android::hardware::Parcel const&, android::hardware::Parcel*, unsigned int)+1772)   native: #03 pc 0000000000085824  /system/lib64/libhidlbase.so (android::hardware::BpHwBinder::transact(unsigned int, android::hardware::Parcel const&, android::hardware::Parcel*, unsigned int, std::__1::function<void (android::hardware::Parcel&)>)+72)   native: #04 pc 000000000000c8d8  /system/lib64/android.hardware.sensors@1.0.so (android::hardware::sensors::V1_0::BpHwSensors::_hidl_activate(android::hardware::IInterface*, android::hardware::details::HidlInstrumentor*, int, bool)+236)   native: #05 pc 000000000001b8e4  /system/lib64/libsensorservice.so (android::SensorDevice::activateLocked(void*, int, int)+784)   native: #06 pc 000000000001ca78  /system/lib64/libsensorservice.so (android::SensorDevice::activate(void*, int, int)+72)   native: #07 pc 0000000000031530  /system/lib64/libsensorservice.so (android::SensorService::enable(android::sp<android::SensorService::SensorEventConnection> const&, int, long, long, int, android::String16 const&)+1972)   native: #08 pc 0000000000026194  /system/lib64/libsensorservice.so (android::SensorService::SensorEventConnection::enableDisable(int, bool, long, long, int)+216)   native: #09 pc 00000000001a84f8  /system/lib64/libandroid_runtime.so ((anonymous namespace)::nativeEnableSensor(_JNIEnv*, _jclass*, long, int, int, int)+116)   at android.hardware.SystemSensorManager$BaseEventQueue.nativeEnableSensor(Native method)   at android.hardware.SystemSensorManager$BaseEventQueue.enableSensor(SystemSensorManager.java:761)   at android.hardware.SystemSensorManager$BaseEventQueue.addSensor(SystemSensorManager.java:686)   at android.hardware.SystemSensorManager.registerListenerImpl(SystemSensorManager.java:192)   - locked <0x088006b6> (a java.util.HashMap)   at android.hardware.SensorManager.registerListener(SensorManager.java:823)   at android.hardware.SensorManager.registerListener(SensorManager.java:730)   at miui.util.ProximitySensorWrapper.registerListener(ProximitySensorWrapper.java:96)   - locked <0x01fcf5a1> (a java.util.ArrayList)   at com.android.server.policy.MiuiScreenOnProximityLock.aquire(MiuiScreenOnProximityLock.java:115)   - locked <0x0f945324> (a com.android.server.policy.MiuiScreenOnProximityLock)   at com.android.server.policy.BaseMiuiPhoneWindowManager.startedWakingUp(BaseMiuiPhoneWindowManager.java:424)   at com.android.server.power.Notifier$2.run(Notifier.java:460)   at android.os.Handler.handleCallback(Handler.java:883)   at android.os.Handler.dispatchMessage(Handler.java:100)   at android.os.Looper.loop(Looper.java:224)   at com.android.server.SystemServer.run(SystemServer.java:556)   at com.android.server.SystemServer.main(SystemServer.java:362)   at java.lang.reflect.Method.invoke(Native method)   at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:539)   at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:928)         "PowerManagerService" prio=5 tid=34 Native   | group="main" sCount=1 dsCount=0 flags=1 obj=0x143c1770 self=0x713aabf800   | sysTid=1834 nice=-4 cgrp=default sched=0/0 handle=0x70d5919d50   | state=S schedstat=( 1568883166 1516633035 9751 ) utm=101 stm=55 core=6 HZ=100   | stack=0x70d5817000-0x70d5819000 stackSize=1039KB   | held mutexes=   kernel: (couldn't read /proc/self/task/1834/stack)   native: #00 pc 000000000007067c  /apex/com.android.runtime/lib64/bionic/libc.so (syscall+28)   native: #01 pc 0000000000073be8  /apex/com.android.runtime/lib64/bionic/libc.so (__futex_wait_ex(void volatile*, bool, int, bool, timespec const*)+140)   native: #02 pc 00000000000d7a68  /apex/com.android.runtime/lib64/bionic/libc.so (NonPI::MutexLockWithTimeout(pthread_mutex_internal_t*, bool, timespec const*)+212)   native: #03 pc 000000000002fb24  /system/lib64/libsensorservice.so (android::SensorService::createSensorEventConnection(android::String8 const&, int, android::String16 const&)+80)   native: #04 pc 000000000001177c  /system/lib64/libsensor.so (android::SensorManager::createEventQueue(android::String8, int)+96)   native: #05 pc 00000000001a81fc  /system/lib64/libandroid_runtime.so ((anonymous namespace)::nativeInitSensorEventQueue(_JNIEnv*, _jclass*, long, _jobject*, _jobject*, _jstring*, int)+160)   at android.hardware.SystemSensorManager$BaseEventQueue.nativeInitBaseEventQueue(Native method)   at android.hardware.SystemSensorManager$BaseEventQueue.<init>(SystemSensorManager.java:666)   at android.hardware.SystemSensorManager$SensorEventQueue.<init>(SystemSensorManager.java:798)   at android.hardware.SystemSensorManager.registerListenerImpl(SystemSensorManager.java:191)   - locked <0x05548e8d> (a java.util.HashMap)   at android.hardware.SensorManager.registerListener(SensorManager.java:823)   at com.android.server.display.AutomaticBrightnessController.setLightSensorEnabled(AutomaticBrightnessController.java:511)   at com.android.server.display.AutomaticBrightnessController.configure(AutomaticBrightnessController.java:367)   at com.android.server.display.DisplayPowerController.updatePowerState(DisplayPowerController.java:976)   at com.android.server.display.DisplayPowerController.access$600(DisplayPowerController.java:92)   at com.android.server.display.DisplayPowerController$DisplayControllerHandler.handleMessage(DisplayPowerController.java:2027)   at android.os.Handler.dispatchMessage(Handler.java:107)   at android.os.Looper.loop(Looper.java:224)   at android.os.HandlerThread.run(HandlerThread.java:67)   at com.android.server.ServiceThread.run(ServiceThread.java:45)

我们能发现PowerMangerService在亮屏的时候去注册sensor卡住了，在等一个锁。那么我们继续看看这个锁被哪个线程拿着的，最后发现是main现场拿着这个锁。main线程拿着这个锁去注册activate 对应的sensor，那么我们就得去看看对端为什么卡住了。

 

2.查看android.hardware.sensors@1.0-service卡在的原因

   查看native进程的trace我们一般用的是debuggerd -b pid（android.hardware.sensors@1.0-service进程的pid），我抓取的关键trace如下：