一个surfaceflinger hang问题分析

1. Mobile log中有如下信息，说明是由于sf（surfaceflinger简称，下同） hang引起的SWT，如下41812表示sf hang的时间长度，单位为ms。

01-02 19:31:53.283   966  1316 V Watchdog: **SF hang Time **41812

01-02 19:31:53.284   966  1316 E Watchdog: **SWT happen **

  2. 直接看sf的back trace日志信息，对应DB中的SF_RTT_DUMP文件

"surfaceflinger" sysTid=425

  #00 pc 000000000005add0  /system/lib64/libgui.so (android::BufferQueueConsumer::setTransformHint(unsigned int)+72)

  #01 pc 000000000006e1d4  /system/lib64/libgui.so (android::GLConsumer::setTransformHint(unsigned int)+96)

  #02 pc 00000000000b7728  /system/lib64/libsurfaceflinger.so

  #03 pc 000000000007eff0  /system/lib64/libsurfaceflinger.so

  #04 pc 0000000000081260  /system/lib64/libsurfaceflinger.so

主线程425在BufferQueueConsumer::setTransformHint()中申请锁Mutex::Autolock lock(mCore->mMutex);时候block住了，该锁被其它线程持有，经过分析sf所有线程的backtrace，发现为如下线程持有了，对应如下红色栈帧处。

 "Binder:425_5" sysTid=1676

  #00 pc 000000000006a814  /system/lib64/libc.so (__ioctl+4)

  #01 pc 00000000000240a0  /system/lib64/libc.so (ioctl+136)

  #02 pc 0000000000054e38  /system/lib64/libbinder.so (android::IPCThreadState::talkWithDriver(bool)+260)

  #03 pc 0000000000055c64  /system/lib64/libbinder.so (android::IPCThreadState::waitForResponse(android::Parcel*, int*)+360)

#04 pc 000000000005599c  /system/lib64/libbinder.so (android::IPCThreadState::transact(int, unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+224)

  #05 pc 000000000004c6f4  /system/lib64/libbinder.so (android::BpBinder::transact(unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+72)

  #06 pc 0000000000078804  /system/lib64/libgui.so

#07 pc 0000000000062e30  /system/lib64/libgui.so (android::BufferQueueProducer::connect(android::sp<android::IProducerListener> const&, int, bool, android::IGraphicBufferProducer::QueueBufferOutput*)+1216)

  #08 pc 00000000000748d4  /system/lib64/libgui.so (android::BnGraphicBufferProducer::onTransact(unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+1744)

  #09 pc 000000000004b2f8  /system/lib64/libbinder.so (android::BBinder::transact(unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+136)

  #10 pc 000000000005534c  /system/lib64/libbinder.so (android::IPCThreadState::executeCommand(int)+624)

  #11 pc 000000000005502c  /system/lib64/libbinder.so (android::IPCThreadState::getAndExecuteCommand()+156)

  #12 pc 000000000005571c  /system/lib64/libbinder.so (android::IPCThreadState::joinThreadPool(bool)+60)

从该线程的back trace可以看出，该线程持有锁Mutex::Autolock lock(mCore->mMutex)之后，与其它进程进行binder通信，但是对端一直没有返回应答，从而导致该锁

一直不能释放。具体执行的代码如下：

if (listener->needsReleaseNotify()) {

  mCore->mConnectedProducerListener = listener;

}

此处的listener为IProducerListener实例，也就是ProducerListener的引用。

3.通过查看sf的binder info可以看到当前通信状态

proc 425

context binder

thread 1676: l 11 need_return 0 tr 0

outgoing transaction 88217069: ffffffc13407f900 from 425:1676 to 9768:9832 code 2 flags 10 pri 0:110 r1
incoming transaction 88217067: ffffffc13407fa00 from 9768:9832 to 425:1676 code 9 flags 10 pri 0:110 r1 node 88217008 size 116:8 data ffffff8019f00058

如上两个log可以看到对端为9768:9832，对应9768为一个应用进程com.manboker.headportrait，不过该应用进程的back trace未能打印出来。

虽然应用进程的trace没有看到，不过可以分析对端进程的needsReleaseNotify()方法在哪里实现的。

在Surface.cpp中有如下代码：

int Surface::connect(int api) {

    static sp<IProducerListener> listener = new DummyProducerListener();

    ALOGD("Surface:connect:pid=%d, listener=%p", getpid(), listener.get());

    return connect(api, listener);

}

而connect(api, listener);方法最终会调用到如下：

int err = mGraphicBufferProducer->connect(listener, api, mProducerControlledByApp, &output);

也就是它与sf通信了，这个与之前sf的backtrace对应上了。

        Surface::connect ()被Surface::lock()调用，那么Surface::lock()方法何时调用呢，就是java层的Surface对象调用LockCanvas()去锁定一块画布时候，就会通过jni层调用到 native层Surface对象的lock()，它主要目的就是通过binder通信请求sf创建一块graphic buffer给应用使用。

        DummyProducerListener的needsReleaseNotify() 只是简单返回一个bool值，

从上面描述信息来看，就是说应用进程自身并未实现IProducerListener的相关接口，因此问题不在于调用方法自身。

4. 不过通过event log可以看出端倪

01-02 19:31:10.573   966   982 I am_anr  : [0,9768,com.manboker.headportrait,951631364,Input dispatching timed out，

也就是说很早时候该应用就已经发生了ANR，但是进程真正死亡时候已经很晚了，如下log所示

01-02 19:31:53.677   532   532 I Zygote  : Process 9768 exited due to signal (6)

01-02 19:31:54.975   966  1416 I am_proc_died: [0,9768,com.manboker.headportrait,0,2]

这段时间应用本身其实已经干不了多少事情了，看看系统当前在干啥呢，其实系统这段时间在处理该应用进程的各种dump信息，尤其是抓取各种dump信息很耗时，

01-02 19:31:11.348   966   982 I zygote64: libdebuggerd_client: started dumping process 9768

01-02 19:31:53.063   966   982 I AnrManager: CPU usage from 5163ms to 45ms ago (2018-01-02 19:31:47.898 to 2018-01-02 19:31:53.016):

01-02 19:31:53.063   966   982 I AnrManager:   94% 10476/aee_core_forwarder: 89% user + 5.6% kernel

在抓取进程相关dump信息时候，进程的所有线程是被挂起的，此时进程还未真正退出，自然也就无法响应sf请求。如果不抓取这些信息，应用ANR流程很快就会结束，进程退出。

因此，本题的结论就是正常使用情况下（不会抓取三方应用DB），是不会存在这种sf hang问题的。