记录一次解决onDestroy 延迟10s调用问题

HelloBan
4,350 阅读6分钟

一、问题表现

FirstActivity有个点击事件可以进入到SecondActivity，但是点击的时候有个Tag防止起多个SecondActivity，而这个Tag是在SecondActivity#onDestroy()里重置的，在某种情况下，Tag不生效了，于是便在SecondActivity#onDestroy()增加日志，发现onPause()未调用，onDestroy()延迟了10s调用。

二、问题原因

前人栽树后人乘凉，感谢ZCJ风飞大佬的分析:

深入分析Android中Activity的onStop和onDestroy()回调延时及延时10s的问题

通过这位大佬分析可以得知：在下一个要显示的Activity的回调onResume之后，ActivityThread会注册一个主线程消息队列的一个IdleHandler，用于ActivityManagerService处理Activity#onStop()和Activity#onDestroy()，若主线程一直在循环处理消息队列中累积的Message，则上述的IdleHandler一直得不得调用，作为一个健壮的ROM，AMS会发送一个延时10s的消息，确保正常流程行不通的情况下也能销毁Activity，从而表现上便是onPause()未调用，onDestroy()延迟了10s调用。

三、问题验证

再次感谢ZCJ风飞大佬：

public class SecondActivity extends Activity {
    private static final String TAG = "SecondActivity";
    private Handler handler = new Handler();
    @Override
    protected void onCreate(@Nullable Bundle savedInstanceState) {
        super.onCreate(savedInstanceState);
        setContentView(R.layout.activity_main);
        postMsg();
    }

    private void postMsg() {
        handler.post(new Runnable() {
            @Override
            public void run() {
                try {
                    // 在主线程中休眠一小段时间
                    // 用来模拟主线程中诸如复杂的绘制、复杂数据处理、帧动画等等操作
                    Thread.sleep(20);
                } catch (InterruptedException e) {
                    e.printStackTrace();
                }
            }
        });
        handler.postDelayed(new Runnable() {
            @Override
            public void run() {
                postMsg();
            }
        }, 10);
    }

    @Override
    protected void onDestroy() {
        super.onDestroy();
        Log.i(TAG, "onDestroy: ");
    }

    @Override
    protected void onStop() {
        super.onStop();
        Log.i(TAG, "onStop: ");
    }
}

通过上述示例代码，的确出现了onDestroy()延迟了10s调用，故问题原因肯定是主线程MessageQueue在循环处理累积的Message。那么问题来了，这些累积的Message是什么？又是谁发送的？

四、问题解决

1.累积的Message是什么

由Handler机制可以，主线程持有Looper, 而Looper内部维持了一个MessageQueue用于调度各种Message，故可以尝试通过MessageQueue去了解Message是什么；阅读Looper的源码，发现有以下代码:

    /**
     * Dumps the state of the looper for debugging purposes.
     *
     * @param pw A printer to receive the contents of the dump.
     * @param prefix A prefix to prepend to each line which is printed.
     */
    public void dump(@NonNull Printer pw, @NonNull String prefix) {
        pw.println(prefix + toString());
        mQueue.dump(pw, prefix + "  ", null);
    }

MessageQueue#dump()源码如下：

    void dump(Printer pw, String prefix, Handler h) {
        synchronized (this) {
            long now = SystemClock.uptimeMillis();
            int n = 0;
            for (Message msg = mMessages; msg != null; msg = msg.next) {
                if (h == null || h == msg.target) {
                    pw.println(prefix + "Message " + n + ": " + msg.toString(now));
                }
                n++;
            }
            pw.println(prefix + "(Total messages: " + n + ", polling=" + isPollingLocked()
                    + ", quitting=" + mQuitting + ")");
        }
    }

看起来可以拉取到主线程消息队列中某一刻的Message列表，尝试以下代码:

private void tryDump() {
        // 仅仅用于示例，不建议直接new Thread()
        new Thread() {
            @Override
            public void run() {
                while (true) {
                    Looper.getMainLooper().dump(new Printer() {
                        @Override
                        public void println(String x) {
                            Log.i("SecondActivity", "println: " + x);
                        }
                    }, "");
                    try {
                        Thread.sleep(500);
                    } catch (Exception ignore) { }
                }
            }
        }.start();
    }

得到类似如下日志:

其中when是指当前时候之后多少ms之后该执行此Message,看起来似乎这个SlideShineImageView有问题，便兴奋的将其修改成普通的ImageView，沮丧的是仍旧有问题，修改后的日志如下：

于是便陷入了沉思，细想可以发现此方法存在致命漏洞：无法打印主线程中所有的Message！！！再次阅读Looper的源码，发现有如下代码:

    public static void loop() {
        // *** 省略部分代码 ***
        for (; ; ) {
            Message msg = queue.next(); // might block
            if (msg == null) {
                // No message indicates that the message queue is quitting.
                return;
            }

            // This must be in a local variable, in case a UI event sets the logger
            final Printer logging = me.mLogging;
            if (logging != null) {
                logging.println(">>>>> Dispatching to " + msg.target + " " +
                        msg.callback + ": " + msg.what);
            }
            // *** 省略部分代码 ***

            if (logging != null) {
                logging.println("<<<<< Finished to " + msg.target + " " + msg.callback);
            }
            // *** 省略部分代码 ***
        }
    }

故若设置了Printer则可打印出主线程执行的Message，Looper中提供了此方法：

/**
     * @param printer A Printer object that will receive log messages, or
     * null to disable message logging.
     */
    public void setMessageLogging(@Nullable Printer printer) {
        mLogging = printer;
    }

尝试设置，得到类似如下日志：

通过了解View的绘制了解便知，主线程累积的Message是系统的绘制消息。一般来说，只有调用了View#requestLayout()或者View#invalidate()才会引起重绘

2.罪魁祸首是谁

虽然知道了问题的原因，但是由于View纵多，直接在所有View中增加日志工作量大且容易做无用功，联想到View本身是一棵树，View#requestLayout()或者View#invalidate()最终肯定会回调到树根上(DecorView)，故可以尝试通过重写FirstActivity的ContentView中的某些方法从而找到问题View。 查看View#requestLayout()源码:

    public void requestLayout() {
        // *** 省略部分代码 ***
        if (mParent != null && !mParent.isLayoutRequested()) {
            mParent.requestLayout();
        }
        if (mAttachInfo != null && mAttachInfo.mViewRequestingLayout == this) {
            mAttachInfo.mViewRequestingLayout = null;
        }
    }

最终回调到ViewRootImpl#requestLayout(),代码如下:

    public void requestLayout() {
        if (!mHandlingLayoutInLayoutRequest) {
            checkThread();
            mLayoutRequested = true;
            scheduleTraversals();
        }
    }

看代码意思便是接下来会触发View的绘制流程相关逻辑，故尝试使用如下ViewGroup作为FirstActivity的根布局:

public class FirstActivityRootLayout extends FrameLayout {
    private static final String TAG = "FirstActivityRootLayout";

    public FirstActivityRootLayout(Context context, AttributeSet attributeSet) {
        super(context, attributeSet);
    }

    @Override
    public void requestLayout() {
        Log.i(TAG, "requestLayout: ", new Exception());
        super.requestLayout();
    }
}

但是requestLayout()的代码逻辑执行正常，于是便查看View#invalidate()的相关流程，invalidate()代码如下：

 public void invalidate() {
        invalidate(true);
}

public void invalidate(boolean invalidateCache) {
        invalidateInternal(0, 0, mRight - mLeft, mBottom - mTop, invalidateCache, true);
}

void invalidateInternal(int l, int t, int r, int b, boolean invalidateCache,
                            boolean fullInvalidate) {
        // *** 省略部分代码
        if ((mPrivateFlags & (PFLAG_DRAWN | PFLAG_HAS_BOUNDS)) == (PFLAG_DRAWN | PFLAG_HAS_BOUNDS)
                || (invalidateCache && (mPrivateFlags & PFLAG_DRAWING_CACHE_VALID) == PFLAG_DRAWING_CACHE_VALID)
                || (mPrivateFlags & PFLAG_INVALIDATED) != PFLAG_INVALIDATED
                || (fullInvalidate && isOpaque() != mLastIsOpaque)) {
            // *** 省略部分代码
            final ViewParent p = mParent;
            if (p != null && ai != null && l < r && t < b) {
                final Rect damage = ai.mTmpInvalRect;
                damage.set(l, t, r, b);
                // 关键代码
                p.invalidateChild(this, damage);
            }

            // *** 省略部分代码
        }
    }

从上述代码可知，invalide()只会刷新当前View所在的区域，故直接在FirstActivityRootLayout重写invalide()方法是不能找到问题View的，因为其可能不是全屏的；注意到上述代码中的invalidateChild()方法，其在ViewGroup中代码如下:

    /**
     * Don't call or override this method. It is used for the implementation of
     * the view hierarchy.
     *
     * @deprecated Use {@link #onDescendantInvalidated(View, View)} instead to observe updates to
     * draw state in descendants.
     */
    @Deprecated
    @Override
    public final void invalidateChild(View child, final Rect dirty) {
        final AttachInfo attachInfo = mAttachInfo;
        if (attachInfo != null && attachInfo.mHardwareAccelerated) {
            // HW accelerated fast path
            onDescendantInvalidated(child, child);
            return;
        }

        ViewParent parent = this;
        if (attachInfo != null) {
            // *** 省略部分代码
            do {
                View view = null;
                if (parent instanceof View) {
                    view = (View) parent;
                }
                // *** 省略部分代码
                parent = parent.invalidateChildInParent(location, dirty);
                // *** 省略部分代码
            } while (parent != null);
        }
    }

此方式是final方法，故无法被子类重写;支持硬件加速的设备会走onDescendantInvalidated()，否则走invalidateChildInParent()，其最终都会调用到ViewRootImpl#scheduleTraversals()，触发View的绘制流程相关逻辑，注意到这两个方法均非final，于是修改FirstActivityRootLayout代码:

public class FirstActivityRootLayout extends FrameLayout {
    private static final String TAG = "FirstActivityRootLayout";

    public FirstActivityRootLayout(Context context, AttributeSet attributeSet) {
        super(context, attributeSet);
    }

    @Override
    public void requestLayout() {
        Log.i(TAG, "requestLayout: ", new Exception());
        super.requestLayout();
    }

    @Override
    public ViewParent invalidateChildInParent(int[] location, Rect dirty) {
        Log.i(TAG, "invalidateChildInParent: ", new Exception());
        return super.invalidateChildInParent(location, dirty);
    }

    @Override
    public void onDescendantInvalidated(@NonNull View child, @NonNull View target) {
        super.onDescendantInvalidated(child, target);
        Log.i(TAG, "onDescendantInvalidated: ", new Exception());
    }
}

终于，满屏重复日志:

故问题原因便是：在自定义TextView#onDraw()中调用了setTextColor()，间接调用了invalidate()，造成循环调用，从而造成主线程中全是请求绘制的消息，于是便出现onPause()未调用，onDestroy()延迟了10s调用现象。

avatar
文章
阅读
粉丝