Android的离奇陷阱 — 设置线程优先级导致的微信卡顿惨案

2021-06-17 15:10:52 浏览数 (1)

Android上如果在主线程执行下面的代码:

代码语言:javascript复制
Thread t = new Thread();t.start();t.setPriority(3);

我们的预期应该是子线程t的优先级被设置为了低优先级。

但真正运行后,我们惊奇的发现,不只是子线程t,主线程的优先级同样会被设置为低优先级!事实上,这三行代码甚至导致了Android微信客户端的一次线上故障!这是为什么?背后有怎样秘密?又如何管控和避免?我们来一起深入分析、研究下这个问题。

(传送门:如果不想深入了解这其中的原理,和一波三折的故事,可以直接跳到最后的 5.3 小节,那里提供了一些设置线程优先级的正确和错误的典型例子)

一、案件发生

微信Android客户端某个新版本发布之后,马上就收到了很多用户的反馈:公众号里的视频卡顿/音画不同步;朋友圈里的视频卡顿掉帧。看现象,初步可能会怀疑到是不是播放器有什么问题?甚至怀疑是不是CDN有什么问题?然而事情远没有想象的那么简单,在测试同学的帮助下,可以确定是Matrix的版本升级引起的。离谱!Matrix作为性能监控的工具,居然会影响到视频的播放?

二、案发现场

浏览器的同事先有了发现:音视频不同步,是因为pthread_cond_timedwait方法比设置的时间要长40ms左右导致。再经过测试,好家伙!不止是这个方法,新版本微信里,所有的sleep/wait方法,都要比原本设置的时间多出了40ms左右。可以用下面的代码,非常容易的复现:

代码语言:javascript复制
long startTime = System.currentTimeMillis();Thread.sleep(10);Log.i("Matrix","duration = "   (System.currentTimeMillis() - startTime));//结果为:duration = 50

一开始我们完全没有头绪,根本不清楚到底是哪里的代码引起的,好吧,最蠢的办法,在新旧两个Matrix版本的commit中,不断二分,找到第一次出现问题的commit。终于找到了案发现场,定位到了类似这样的一个修改:

啊?只是设置线程优先级与启动线程的顺序调换,况且设置的也只是一个特定子线程的优先级,居然会有这么大的破坏力?没错,读者有兴趣可以在Android上运行这样一段代码:

代码语言:javascript复制
Thread t = new Thread();t.start();t.setPriority(3);
long startTime = System.currentTimeMillis();Thread.sleep(10);Log.i("Matrix","duration = "   (System.currentTimeMillis() - startTime));  // 结果为duration = 50ms

非常离奇的现象就是:如果在Thread的start后马上调用setPriority,并且设置一个小于默认优先级(默认优先级为5)的优先级,就会出现sleep/wait等方法会比设置的时间多几十毫秒的现象。

而由于很多视频播放的逻辑中,都会通过系统的sleep/wait/pthread_cond_timedwait等方法来实现音视频的同步,会有非常频繁的调用,如果每次都多出几十毫秒,就会直接引起视频播放卡顿,音画不同步等问题,也就直接导致了这次微信的线上故障。

三、分析推理

离谱!只是想设置一个特定子线程的优先级,居然就直接影响了主线程主线程创建的所有子线程的sleep时间?这里绝对隐藏着什么秘密。

(在一起来探秘之前,需要补充一个小的背景(如果你已经充分了解Linux线程的nice值,可以直接跳过):不管是在Java层设置线程优先级,还是在Native层设置线程优先级,最终设置的,也是绝大部分情况下最终起到作用的,都是线程的nice值,nice值越高,也就说明这个线程的“脾气”越好,就越不容易抢到CPU,也就意味着线程的优先级越低。)

3.1. 罪魁祸首:TimerSlackHigh

既然Thread的start和setPriority的顺序改变会影响sleep/wait等方法的时间,我们就先看下setPriority做了什么事情,Thread.setPriority最终会调用到system/libartpalette/palette_android.cc里的PaletteSchedSetPriority方法:

代码语言:javascript复制
palette_status_t PaletteSchedSetPriority(int32_t tid, int32_t managed_priority) {    if (managed_priority < art::palette::kMinManagedThreadPriority ||        managed_priority > art::palette::kMaxManagedThreadPriority) {        return PALETTE_STATUS_INVALID_ARGUMENT;    }    int new_nice = kNiceValues[managed_priority - art::palette::kMinManagedThreadPriority];     int curr_nice = getpriority(PRIO_PROCESS, tid);
    if (curr_nice == new_nice) {        return PALETTE_STATUS_OK;    }
    if (new_nice >= ANDROID_PRIORITY_BACKGROUND) {        SetTaskProfiles(tid, {"SCHED_SP_BACKGROUND"}, true);    } else if (curr_nice >= ANDROID_PRIORITY_BACKGROUND) {        SchedPolicy policy;        // Change to the sched policy group of the process.        if (get_sched_policy(getpid(), &policy) != 0) {            policy = SP_FOREGROUND;        }        SetTaskProfiles(tid, {get_sched_policy_profile_name(policy)}, true);    }
    if (setpriority(PRIO_PROCESS, tid, new_nice) != 0) {        return PALETTE_STATUS_CHECK_ERRNO;    }    return PALETTE_STATUS_OK;}
static const int kNiceValues[art::palette::kNumManagedThreadPriorities] = {    ANDROID_PRIORITY_LOWEST, // 1 (MIN_PRIORITY)    ANDROID_PRIORITY_BACKGROUND   6,    ANDROID_PRIORITY_BACKGROUND   3,    ANDROID_PRIORITY_BACKGROUND,    ANDROID_PRIORITY_NORMAL, // 5 (NORM_PRIORITY)    ANDROID_PRIORITY_NORMAL - 2,    ANDROID_PRIORITY_NORMAL - 4,    ANDROID_PRIORITY_URGENT_DISPLAY   3,    ANDROID_PRIORITY_URGENT_DISPLAY   2,    ANDROID_PRIORITY_URGENT_DISPLAY // 10 (MAX_PRIORITY)};

该方法会根据kNiceValues数组,把Java层Thread的优先级映射为Linux的线程nice值,上面的例子中Java层priority是3,kMinManagedThreadPriority的值是1,所以经过映射后,得到的nice值为13,而ANDROID_PRIORITY_BACKGROUND是10,表示后台优先级,原来我们设置了比后台优先级的nice值更高的值(即比后台优先级更低),此时系统会把该线程设置为后台线程,具体做了什么呢?接着看SetTaskProfiles

代码语言:javascript复制
bool SetTaskProfiles(int tid, const std::vector<std::string>& profiles, bool use_fd_cache) {    return TaskProfiles::GetInstance().SetTaskProfiles(tid, profiles, use_fd_cache);}
TaskProfiles::TaskProfiles() {    // load system task profiles    if (!Load(CgroupMap::GetInstance(), TASK_PROFILE_DB_FILE)) {        LOG(ERROR) << "Loading " << TASK_PROFILE_DB_FILE << " for [" << getpid() << "] failed";    }    //省略...... } 
static constexpr const char* TASK_PROFILE_DB_FILE = "/etc/task_profiles.json";

这里会去读取/etc/task_profiles.json这个配置文件,我们在这个配置文件里搜索这里传入的参数SCHED_SP_BACKGROUND,找到了这样的配置:

代码语言:javascript复制
{    "Name": "SCHED_SP_BACKGROUND",    "Profiles": [ "HighEnergySaving", "LowIoPriority", "TimerSlackHigh" ]}
代码语言:javascript复制
    {      "Name": "TimerSlackHigh",      "Actions": [        {          "Name": "SetTimerSlack",          "Params":          {            "Slack": "40000000"          }        }      ]    },    {      "Name": "TimerSlackNormal",      "Actions": [        {          "Name": "SetTimerSlack",          "Params":          {            "Slack": "50000"          }        }      ]    }

被设置为后台线程后,会设置三个profile:"HighEnergySaving", "LowIoPriority", "TimerSlackHigh"。

聪明的你应该敏锐的发现了这个TimerSlackHigh,“懒惰定时器”,名字看起来就非常可疑,很有可能跟我们在查的sleep/wait延迟有关,赶快查一下TimerSlack是什么:

原来真凶就是他!

TimerSlack是Linux系统为了降低系统功耗,避免timer时间参差不齐,过于的频繁的唤醒cpu,而设置的一种对齐策略。

总而言之:如果系统设置了大于等于10的nice值,即设置了比后台优先级还要低的优先级,即把线程设置成了后台线程,那么系统就会设置一个比较高的TimerSlack,从默认的50微秒,提高到40毫秒,从而导致wait/sleep等挂起的时间多了40ms左右。

但是,还是不对劲啊,我设置的明明只是特定子线程的优先级,按道理说只会影响该子线程的TimerSlack才对啊,为什么看起来影响了所有的线程呢?确实,这个问题还有很多疑点,我们接着分析。

3.2. 大误会:糊涂的setPriority

我们首先就会怀疑Java层调用setPriority,设置错了线程,那么找到 art/runtime/thread.cc

代码语言:javascript复制
void Thread::SetNativePriority(int new_priority) {    palette_status_t status = PaletteSchedSetPriority(GetTid(), new_priority);    CHECK(status == PALETTE_STATUS_OK || status == PALETTE_STATUS_CHECK_ERRNO);}

在这里之后才会调用之前提到的PaletteSchedSetPriority方法,我们发现这里传递的参数也就是设置优先级的对象线程是GetTid(),继续找到GetTid()

代码语言:javascript复制
pid_t GetTid() const {    return tls32_.tid;}

tls32_是用来描述native线程的数据结构,继续找下tls32_.tid是在哪里赋值的,art/runtime/thread.cc

代码语言:javascript复制
void Thread::InitTid() {    tls32_.tid = ::art::GetTid();}
bool Thread::Init(ThreadList* thread_list, JavaVMExt* java_vm, JNIEnvExt* jni_env_ext) {    //......    InitTid();    //......}
void* Thread::CreateCallback(void* arg) {    //......    CHECK(self->Init(runtime->GetThreadList(), runtime->GetJavaVM(), self->tlsPtr_.tmp_jni_env));    //......}
void Thread::CreateNativeThread(JNIEnv* env, jobject java_peer, size_t stack_size, bool is_daemon) {    //......    pthread_create_result = pthread_create(&new_pthread,                                           &attr,                                           Thread::CreateCallback,                                           child_thread);    //......}

一层一层往上找,来到CreateNativeThread方法,原来是在线程创建的时候在pthread_create的回调方法CreateCallback里面调用的InitTid,来设置的。而CreateNativeThread是Thread.start调用来创建native线程的地方。

对!你可能已经想到了,这里是有时序问题的,pthread_create的回调CreateCallback是异步执行的,所以start执行完毕,并不能确保setNativePriority的tid参数已经赋值,而一旦tid还未被赋值,那么这个时候调用setPriority,tid就是默认值0

我们再看如果Native的系统调用setpriority的参数如果是0的话,会出现什么情况:

来了,如果第二个参数tid是0的话,就会设置调用线程的优先级!

那TimerSlack呢?在tid为0的情况下的表现是什么样呢?我们找到最终设置TimerSlack的地方,system/core/libprocessgroup/task_profiles.cpp

代码语言:javascript复制
bool SetTimerSlackAction::ExecuteForTask(int tid) const {    //......    if (tid == 0 || tid == GetThreadId()) {        if (prctl(PR_SET_TIMERSLACK, slack_) == -1) {            PLOG(ERROR) << "set_timerslack_ns prctl failed";        }    }
    return true;}

TimerSlack最终是通过系统调用prctl方法设置的,如果tid是0,同样会设置当前线程的TimerSlack。

所以结论是,如果GetTid为0,那么无论是nice值还是TimerSlack都会对当前的调用线程设置。

居然有这么诡异的陷阱!我们再回头看引起问题的代码,似乎就说得过去了:

代码语言:javascript复制
 Thread t = new Thread(); t.start(); t.setPriority(3);
 long startTime = System.currentTimeMillis(); Thread.sleep(10); Log.i("Matrix","duration = "   (System.currentTimeMillis() - startTime));

t.start()调用之后,在native的tid还没有被设置好的时候,就执行了下面的t.setPriority,这时GetTid返回值是0,native的setpriority的tid参数为0,就会把调用线程(Calling Thread)即主线程的nice设置为13,同时TimerSlack也被设置为40ms。有这样的结果就说得通了。

然而,结束了吗?因为时序问题,主线程被设置了高nice和高TimerSlack,理所当然的,主线程创建的子线程的nice值和TimerSlack理所当然地继承了父线程,也就是主线程,所以自然也被影响了,是这样吗?

用这样一段代码测试:

代码语言:javascript复制
Thread t = new Thread();t.start();t.setPriority(3);
long startTime = System.currentTimeMillis();Thread.sleep(10);Log.i("Matrix","MainThread duration = "   (System.currentTimeMillis() - startTime));  //结果为50
new Thread(new Runnable() {    @Override    public void run() {        long startTime = System.currentTimeMillis();        Thread.sleep(10);        Log.i("Matrix","Thread duration = "   (System.currentTimeMillis() - startTime));          //结果为10    }}).start();

我们发现,主线程被错误设置nice值和TimerSlack后,创建的子线程并没有继承主线程的nice值和TimerSlack,这又是为什么呢?我们继续分析。

在native层的线程,的确子线程会继承父线程也就是主线程的nice值和TimerSlack,但是,start和priority的时序问题,只会错误地设置主线程的native的nice值和TimerSlack,并不会影响主线程Java层的priority变量,而子线程同样会在Java层继承父线程Java层的priority,而在native层创建线程的时候,有这样的逻辑:

代码语言:javascript复制
void* Thread::CreateCallback(void* arg) {    //......    ArtField* priorityField =         jni::DecodeArtField(WellKnownClasses::java_lang_Thread_priority);    self->SetNativePriority(priorityField->GetInt(self->tlsPtr_.opeer));    //......}

在native创建线程调用到CreateCallback时,会根据Java层的priority,重新设置native层的priority/nice值和TimerSlack,而在上面的情况中,主线程的Java层priority并没有被设置,是默认的5,对应的nice值为0,所以子线程的nice值就被再次设置为了0,也就重新被设置为了前台线程,TimerSlack就又被设置为了低TimerSlack。

那么,问题又来了,既然主线程因为时序问题被错误地设置后台优先级后,并不影响其创建的子线程的nice值和TimerSlack,而线上故障中,引起音画不同步和视频掉帧的线程,却又都是在主线程创建的子线程中产生的。那又是什么让本来只会影响主线程的问题,进一步污染了它创建的全部子线程呢?

3.3. 帮凶:WebView推波助澜

再经过进一步排查,发现一个非常奇怪的现象,来看下面的代码:

代码语言:javascript复制
Thread t = new Thread();t.start();t.setPriority(3);
long startTime = System.currentTimeMillis();Thread.sleep(10);Log.i("Matrix","MainThread duration = "   (System.currentTimeMillis() - startTime));  //结果为50
new WebView(context);
new Thread(new Runnable() {    @Override    public void run() {        long startTime = System.currentTimeMillis();        Thread.sleep(10);        Log.i("Matrix","Thread duration = "   (System.currentTimeMillis() - startTime));          //结果为50    }}).start();

考验眼力的时候来了,发现了跟之前的测试代码有什么区别了吗?是的,只要在创建子线程前加一句new WebView(context),那么子线程的nice和TimerSlack就也被影响了!

事实上,微信在某些页面的确会有预加载webview的逻辑,我们也会发现,也的确在new了WebView之后,设置优先级的时序错误,就不止会影响主线程,而是其创建的所有的子线线程就都会被污染,都有了高TimerSlack,这是为什么呢?

我们在new Webview前后打印一下主线程nice值就会发现,主线程nice值在执行new WebView之前是13,之后变成了-4。

哦?new WebView居然会设置主线程的优先级?

找到Chromium的源码content/browser/browser_main_loop.cc

代码语言:javascript复制
// Up the priority of the UI thread unless it was already high (since Mac// and recent versions of Android (O ) do this automatically).if (base::FeatureList::IsEnabled(    features::kBrowserUseDisplayThreadPriority) &&    base::PlatformThread::GetCurrentThreadPriority() <          base::ThreadPriority::DISPLAY) {    base::PlatformThread::SetCurrentThreadPriority(        base::ThreadPriority::DISPLAY);}

其中ThreadPriority::DISPLAY的值就是-4,是的,Chromium有这样的逻辑:如果当前主线程的nice值大于-4(即优先级较低),就会提高主线程的优先级,并且这里设置优先级是直接调用了native的setpriority,所以并不会同时修改TimerSlack

这个操作其实也很容易理解,是Chromium的保护措施,它不希望渲染UI的主线程处在一个较低的优先级,不过却阴差阳错地成为了帮凶。

我们仔细看下,native线程在创建的时候根据Java层的priority设置nice值的时候的逻辑:

代码语言:javascript复制
if (new_nice >= ANDROID_PRIORITY_BACKGROUND) {    SetTaskProfiles(tid, {"SCHED_SP_BACKGROUND"}, true);} else if (curr_nice >= ANDROID_PRIORITY_BACKGROUND) {    SchedPolicy policy;    // Change to the sched policy group of the process.    if (get_sched_policy(getpid(), &policy) != 0) {        policy = SP_FOREGROUND;    }    SetTaskProfiles(tid, {get_sched_policy_profile_name(policy)}, true);}

如果新设置的nice值大于等于10,直接判断为后台线程,设置高的TimerSlack;但另一方面,只有当前的nice值大于10,新的nice值小于10,才会把线程设置为前台线程,设置低的TimerSlack。 

而执行new WebView之后,主线程nice值是-4,而子线程继承了主线程的nice值也是-4,-4 < 10,系统认为你已经是前台线程了,就不会走到else if的逻辑,也就不会重新把线程设置为前台线程,也就不会设置低TimerSlack,而子线程从主线程继承的TimerSlack就是高TimerSlack。从而,主线程创建的全部子线程就都被污染了,也就引起了,音画不同步和掉帧的故障。

至此才真正破案了,所有的疑问和“奇怪”现象也都可以解释通了。

该问题一开始是由Thread的start和setPriority的时序问题,导致主线程被设置为后台线程,同时被设置了高TimerSlack;而帮凶Chromium又在初始化WebView的时候默默地把主线程的nice值设置成了较低的nice值(较高的优先级),但又没有设置回低TimerSlack,从而主线程创建的子线程继承了主线程的nice值和高TimerSlack后,却认为自己已经是前台线程,所以也没有机会根据Java层的priority重新设置低TimerSlack,最后就导致了主线程连同其创建的所有子线程的TimerSlack全部都被设置为了高TimerSlack,从而产生了一系列的问题,导致了这次故障。

四、监控机制:

原理已经搞清楚后,我们需要建立一个监控机制,避免之后再出现这种情况。

首先我们需要确保住主线程优先级不被设置的过低,hook系统调用setpriority,如果对主线程设置过低的优先级(过高的nice值),则直接报错:

代码语言:javascript复制
int (*original_setpriority)(int __which, id_t __who, int __priority);
int my_setpriority(int __which, id_t __who, int __priority) {        if (__priority <= 0) {        return original_setpriority(__which, __who, __priority);    }        if (__who == 0 && getpid() == gettid()) {        // Throw Crash Here    } else if (__who == getpid()) {        // Throw Crash Here    }
    return original_setpriority(__which, __who, __priority);}

另外,我们还hook了设置TimerSlack的prctl方法,确保主线程的TimerSlack值不被设置的过大:

代码语言:javascript复制
int (*original_prctl)(int option, unsigned long arg2, unsigned long arg3,              unsigned long arg4, unsigned long arg5);
int my_prctl(int option, unsigned long arg2, unsigned long arg3,             unsigned long arg4, unsigned long arg5) {    if(option == PR_SET_TIMERSLACK) {        if (gettid()==getpid() && arg2 > 50000) {            // Throw Crash Here        }    }    return original_prctl(option, arg2, arg3, arg4, arg5);}

监控会在微信各种体验版和debug的时候打开,确保当再次出现主线程的优先级或者TimerSlack被错误设置的情况时,能够提前发现,避免这类问题被带到线上。

五、额外的结论:

最后,我们再讨论下,在设置优先级的时候我们容易出现的一些错误。

5.1. 线程优先级的“双标”

Thread在Java层的优先级与Native层或者说Linux系统层的线程优先级,也就是nice值,是两套不同的标准,数字大小的意义甚至也是相反的,容易产生混淆和误用。

通过Thread.setPriority方法设置的优先级是在Java层的优先级,数字从0到10,数字越大表优先级越高,默认是5,Android主线程默认是5。Java层的优先级通过native层的kNiceValues数组,映射为nice值,再起到作用。

通过android.os.Process.setThreadPriority方法设置的优先级是Native层的线程优先级/nice值,数字从-20到20,数字越大代表优先级越低,默认是0,Android主线程默认的nice值是-10。另外,native层的系统调用setpriority当然也是直接设置的nice值。

5.2. 正确设置HandlerThread的优先级

怎么设置HandlerThread的优先级呢?第一反应可能会这样写

代码语言:javascript复制
HandlerThread ht = new HandlerThread("leafjia-thread");ht.setPriority(3);ht.start();

似乎也没什么问题哦?但是这样设置,其实除了设置了Java层Thread对象的成员变量priority,并不会起到任何其他的效果。

我们看HandlerThread的源码:

代码语言:javascript复制
public class HandlerThread extends Thread {    int mPriority;    //......        public HandlerThread(String name) {        super(name);        mPriority = Process.THREAD_PRIORITY_DEFAULT;    }        public HandlerThread(String name, int priority) {        super(name);        mPriority = priority;    }
    //......
    @Override    public void run() {        mTid = Process.myTid();        Looper.prepare();        synchronized (this) {            mLooper = Looper.myLooper();            notifyAll();        }        Process.setThreadPriority(mPriority);        onLooperPrepared();        Looper.loop();        mTid = -1;    }    //......}

调用ht.serPriority(3)其实设置的是其父类Thread的priority成员变量,而HandlerThread本身有自己的mPriority成员变量,start之后,会在创建Native Thread的时候,在调用run回调方法前,根据Java层Thread的priority(我们已经设置为了3)设置Native的nice值,这时的确优先级能够设置成功。但是HandlerThread自己重写了run方法,在之后执行的run方法中,又再次通过Process.setThreadPriority(mPriority)设置了自己的优先级为mPriority,而mPriority并不能通过Thread.setPriority方法设置。所以上面的代码并不生效。

正确的方法也显而易见:

代码语言:javascript复制
HandlerThread ht = new HandlerThread("My-Thread", 13);ht.start();

需要注意的是,因为线程优先级最终是通过Process.setThreadPriority方法实现的,所以priority使用的是-20到20的nice值的优先级体系。

5.3. Some Cases

进一步,可以总结出下面几种设置线程优先级的case,如果我们的目的是设置thread线程的优先级为3(而不想改变调用线程的优先级),即nice值为13,那么:

代码语言:javascript复制
//Case1: 正确,thread线程的nice值被设置为13Thread thread = new Thread();thread.setPriority(3);thread.start();
//Case2: 正确,thread线程的nice值被设置为13Thread thread = new Thread(new Runnable() {    @Override    public void run() {        Thread.currentThread().setPriority(3);        // 或:        // Process.setThreadPriority(13);    }});thread.start();
//Case3: 错误,thread线程的nice值一定被设置为13//(可能直接被设置或从当前线程继承而来,视时序而定),// 当前线程的nice值很有可能被设置为13Thread thread = new Thread();thread.start();thread.setPriority(3);
//Case4: 错误,同上HandlerThread thread = new HandlerThread("My-Thread");thread.start();thread.setPriority(3);
//Case5: 错误,thread线程的nice值被设置为默认的0HandlerThread thread = new HandlerThread("My-Thread");thread.setPriority(3);thread.start();
//Case6: 正确,thread线程的nice值被设置为13HandlerThread thread = new HandlerThread("My-Thread", 13);thread.start();

至此,就是本文的全部内容。线程优先级的相关问题,大家平时可能关注的并不多,或者会认为线程优先级的影响并不会特别大。而看起来平平无奇的设置线程优先级的三行代码,就真的引起了一次线上故障。这也提醒大家,一旦涉及到多线程,就一定要对时序问题特别谨慎。

如果这篇文章对你有帮助,欢迎分享,收藏,点赞,在看四连!

0 人点赞