为什么AsyncTask调用execute方法后很久才执行doI

作者: 元亨利贞o | 来源:发表于2016-08-14 19:14 被阅读3307次

最近在项目中遇到一个比较奇葩的问题, 就是AsyncTask执行了execute方法之后, doInBackground方法很久才得到掉调用. 我们都知道doInBackground方法是在子线程中执行的, 而execute方法执行的线程(一般是在UI线程)肯定与doInBackground方法执行的线程不同.
从execute方法执行的线程切换到doInBackground方法执行的线程为什么会耗时这么久??
毫无疑问这是一个线程调度的问题. 我们不应该怀疑系统调度有问题, 那么剩下的只有我们自己调度的问题......

项目里有一个强制更新的功能, 如下图:

强制更新-未点击按钮

点击强制更新按钮后会显示进度调(正常情况), 如下图:

强制更新-下载中

点击"强制更新"按钮后, 按钮被禁止点击:
downloadApkBtn.setClickable(true);
但是按钮没有变灰, 按钮上的文本也没改成"正在下载..."
因此在某些手机上就出现这样的情况:

点击按钮后, 如图一, ProgressBar进度不动, 而且再点击按钮就没有反应了(按钮设置过selector, 是有按压效果的), 给用户感觉就是: 应用卡顿死掉了

初步怀疑是网络问题, 于是把网络连等相关步骤所耗的时间打印出来. 数据显示, 就算网络非常慢, 也不会花费十多秒的时间. (并且连接也有超时限制, 如果很久不能连接上, 那么就会超时, 总会得到一个结果) 有问题的手机, 点击按钮到进度条动起来的时间有几十秒, 甚至几分钟, 有的就一直卡着不动了. 对于用户来说, 几秒或者十几秒不动, 就直接退出了, 或者......

在调试中发现, 点击按钮后很久, doInBacground()方法中的日志输出都没打印出来. 因此可以得出结论: doInBackground()方法所在的线程没有执行.
于是我把execute()方法执行到doInBackground()方法执行之间的时间也打印出来, 代码如下:

private volatile long start_time;
private void downloadApk() {
    start_time = System.currentTimeMillis();
    new DownloadApkTask().execute();
}

class DownloadApkTask extends AsyncTask<Void, Integer, Boolean> {
    protected Boolean doInBackground(Void... params) {
        Log.e("_ajk_", "schedule time cast: " + ((System.currentTimeMillis() - start_time) / 1000.0));
        //省略 ...... 
    }
}

多次执行启动->点击强制更新按钮->退出动作, 日志输出如下:

macbook-stonedeMacBook-Pro:~ stone$ adb logcat *:E | grep schedule
E/_ajk_   (25685): schedule time cost: 0.014
E/_ajk_   (25685): schedule time cost: 21.618
E/_ajk_   (25685): schedule time cost: 27.859
E/_ajk_   (25685): schedule time cost: 0.004
E/_ajk_   (25685): schedule time cost: 38.368
E/_ajk_   (25685): schedule time cost: 10.722
E/_ajk_   (25685): schedule time cost: 1.66
E/_ajk_   (25685): schedule time cost: 45.632
E/_ajk_   (25685): schedule time cost: 25.374
E/_ajk_   (25685): schedule time cost: 23.161
E/_ajk_   (25685): schedule time cost: 28.733
E/_ajk_   (25685): schedule time cost: 44.852
E/_ajk_   (25685): schedule time cost: 62.171
E/_ajk_   (25685): schedule time cost: 93.201
E/_ajk_   (25685): schedule time cost: 95.367
E/_ajk_   (25685): schedule time cost: 108.974
E/_ajk_   (25685): schedule time cost: 122.609
E/_ajk_   (25685): schedule time cost: 129.158
E/_ajk_   (25685): schedule time cost: 134.632

为什么doInBackground()方法所在线程不能及时执行呢?

查看AsyncTask类源码, 发现AsyncTask里面是使用线程池来执行异步任务的, AsyncTask有两个方法来执行移步任务:

@MainThread
public final AsyncTask<Params, Progress, Result> execute(Params... params) {
    return executeOnExecutor(sDefaultExecutor, params);
}

@MainThread
public final AsyncTask<Params, Progress, Result> executeOnExecutor(Executor exec,
        Params... params) {
    if (mStatus != Status.PENDING) {
        switch (mStatus) {
            case RUNNING:
                throw new IllegalStateException("Cannot execute task:"
                        + " the task is already running.");
            case FINISHED:
                throw new IllegalStateException("Cannot execute task:"
                        + " the task has already been executed "
                        + "(a task can be executed only once)");
        }
    }

    mStatus = Status.RUNNING;

    onPreExecute();

    mWorker.mParams = params;
    exec.execute(mFuture);

    return this;
}

execute()方法使用的是AsyncTask内部定义的默认线程池, executeOnExecutor()使用的是开发者自定义的线程池. 我们来看看AsyncTask内部自定义的程池到底是什么?
AsyncTask内部定义的默认线程池是SerialExecutor, SerialExecutor及其相关变量的定义如下:

private static final int CPU_COUNT = Runtime.getRuntime().availableProcessors();
private static final int CORE_POOL_SIZE = CPU_COUNT + 1;
private static final int MAXIMUM_POOL_SIZE = CPU_COUNT * 2 + 1;
private static final int KEEP_ALIVE = 1;

private static final ThreadFactory sThreadFactory = new ThreadFactory() {
    private final AtomicInteger mCount = new AtomicInteger(1);

    public Thread newThread(Runnable r) {
        return new Thread(r, "AsyncTask #" + mCount.getAndIncrement());
    }
};

private static final BlockingQueue<Runnable> sPoolWorkQueue =
        new LinkedBlockingQueue<Runnable>(128);

/**
 * An {@link Executor} that can be used to execute tasks in parallel.
 */
public static final Executor THREAD_POOL_EXECUTOR
        = new ThreadPoolExecutor(CORE_POOL_SIZE, MAXIMUM_POOL_SIZE, KEEP_ALIVE,
                TimeUnit.SECONDS, sPoolWorkQueue, sThreadFactory);

/**
 * An {@link Executor} that executes tasks one at a time in serial
 * order.  This serialization is global to a particular process.
 */
public static final Executor SERIAL_EXECUTOR = new SerialExecutor();

private static volatile Executor sDefaultExecutor = SERIAL_EXECUTOR;

private static class SerialExecutor implements Executor {
    final ArrayDeque<Runnable> mTasks = new ArrayDeque<Runnable>();
    Runnable mActive;

    public synchronized void execute(final Runnable r) {
        mTasks.offer(new Runnable() {
            public void run() {
                try {
                    r.run();
                } finally {
                    scheduleNext();
                }
            }
        });
        if (mActive == null) {
            scheduleNext();
        }
    }

    protected synchronized void scheduleNext() {
        if ((mActive = mTasks.poll()) != null) {
            THREAD_POOL_EXECUTOR.execute(mActive);
        }
    }
}

从SerialExecutor这个名字可以看出, 它是一个顺序执行任务的执行器. 实际上SerialExecutor并不去执行任务, 它的execute()方法会委托AsyncTask内部定义的一个线程池去执行任务, 这个默认线程池(THREAD_POOL_EXECUTOR)的定义上面已经给出. THREAD_POOL_EXECUTOR是一个可同时处理处理器个数+1个任务的线程池. 然而使用execute()方法执行AsyncTask时, 并没什么卵用, 因为SerialExecutor的execute()方法会对异步任务进行封装, 使得任务顺序执行, 跟在同一个线程中执行一样, 从而失去并发处理特性. 如果有一个耗时任务正在执行, 那么后续任务将会一直等待前面的任务完成. 因此:

AsyncTask虽然是异步任务, 这个异步指的是与ui线程异步. 如果你想要并发执行多个任务, execute()方法不能实现, executeOnExecutor()方法可以达到目的 (必须提供正确的Executor) ----- 异步跟并发并非同一个概念.

经过上面的分析可以得知, 下载apk的异步任务之前肯定有一个耗时任务在执行, 因此导致下载apk的异步任务一直处于等待队列之中而得不到执行. 那么如何进行验证呢?

我们通过DDMS来查看线程状态, 看看在下载任务之前是有正在处理的任务, 操作如下:
启动DDMS, 在DDMS窗口左侧的Devices视图中选择我们要调试的进程, 然后点击顶部的Update Threads按钮, 这时我们可以在右侧的Threads视图中看到我们选中的进程的所有线程信息, 如图:

使用DDMS查看线程状态

查看AsyncTask类的源码, 我们知道AsyncTask默认线程池中的工作线程的命名格式是AsyncTask #index (index大小为 1~线程池的coreSize), 因此我们看名称为AsyncTask开头的线程就行了 (不得不吐槽一下DDMS做的太烂, 居然不能按线程名排序或分类, 如果线程多了, 那就AsyncTask使用的线程中间就会夹杂其他线程, 这给观察带来不便), 选中某个线程后下面的状态框中会输出此线程的堆栈信息.

通过DDMS查看线程状态, 发现出问题时有一个AsyncTask线程处于Native状态, Native状态是什么鬼? 关于线程状态可参考 DDMS中线程状态的说明, 此文对Native状态的说明是:

native – executing native code – 执行了原生代码，这个对于带有消息队列的线程是正常的状态，表示消息队列没有任何消息，线程在native 代码中进行无限循环，直到消息队列中出现新的消息，消息队列才会返回Java 代码处理消息。

呃, 线程在native代码中进行无限循环......

我猜想是native层导致某个task的运行一直处于阻塞状态, 这样后面的task也就无法执行, 查看处于native状态的线程的堆栈信息, 如下:

at libcore.io.Posix.recvfromBytes(Native Method)  
at libcore.io.Posix.recvfrom(Posix.java:141)  
at libcore.io.BlockGuardOs.recvfrom(BlockGuardOs.java:164)    
at libcore.io.IoBridge.recvfrom(IoBridge.java:550)    
at java.net.PlainSocketImpl.read(PlainSocketImpl.java:506)    
at java.net.PlainSocketImpl.access$000(PlainSocketImpl.java:46)   
at java.net.PlainSocketImpl$PlainSocketInputStream.read(PlainSocketImpl.java:240) 
at org.apache.http.impl.io.AbstractSessionInputBuffer.fillBuffer(AbstractSessionInputBuffer.java:103) 
at org.apache.http.impl.io.AbstractSessionInputBuffer.read(AbstractSessionInputBuffer.java:134)   
at org.apache.http.impl.io.ContentLengthInputStream.read(ContentLengthInputStream.java:174)   
at org.apache.http.impl.io.ContentLengthInputStream.read(ContentLengthInputStream.java:188)   
at org.apache.http.impl.io.ContentLengthInputStream.close(ContentLengthInputStream.java:121)  
at org.apache.http.conn.BasicManagedEntity.streamClosed(BasicManagedEntity.java:179)  
at org.apache.http.conn.EofSensorInputStream.checkClose(EofSensorInputStream.java:266)    
at org.apache.http.conn.EofSensorInputStream.close(EofSensorInputStream.java:213) 
at com.anjuke.android.newbroker.activity.AutoUpdateActivity$DownloadApkTask.closeInputStream(AutoUpdateActivity.java:345) 
at com.anjuke.android.newbroker.activity.AutoUpdateActivity$DownloadApkTask.doInBackground(AutoUpdateActivity.java:289)   
at com.anjuke.android.newbroker.activity.AutoUpdateActivity$DownloadApkTask.doInBackground(AutoUpdateActivity.java:202)   
at com.anjuke.android.newbroker.util.image.AsyncTask$2.call(AsyncTask.java:337)   
at java.util.concurrent.FutureTask.run(FutureTask.java:237)   
at com.anjuke.android.newbroker.util.image.AsyncTask$SerialExecutor$1.run(AsyncTask.java:279) 
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1112)    
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:587)    
at java.lang.Thread.run(Thread.java:848)

在堆栈中发现了这个com.anjuke.android.newbroker.util.image.AsyncTask, 这个类其实是从这里考过来的, 查看源码发现跟系统的区别不大, 只是对默认线程池进行了版本处理(android 11以下的版本使用单线程来处理异步任务), 代码如下:

/**
 * An {@link Executor} that executes tasks one at a time in serial order.
 * This serialization is global to a particular process.
 */
public static final Executor SERIAL_EXECUTOR = Utils.hasHoneycomb() ? new SerialExecutor() :
        Executors.newSingleThreadExecutor(sThreadFactory);

根据堆栈信息可以得知, 关闭下载输入流时, 系统阻塞了, 这是非正常关闭输入流, 它是这样发生的:

启动App, 点击强制更新按钮, 这时正在下载文件了, 然后退出退出App (用户下载了一半, 可能不想下载了), 这时就会关闭输入流. 这时的输入流中的数据还没读完, 这样关闭入流就会阻塞 (会不会等待数据读取完毕在关闭??). 再启动app时, 再点击强制更新按钮, 这时启动的下载任务会一直等待前一个下载任务关闭输入流完成. --- 退出APP, APP的进程并没有杀掉( 除非用户按HOME键手动划掉应用或在系统设置的应用管理中强制结束进程, 用户一般不会这么做), 因此下一次启动的APP和上一次启动的APP会共用AsyncTask的线程池.

我们还是用数据说话, 我在程序中打印了关闭输入流的时间, 代码如下:

private void closeInputStream(InputStream inputStream) throws IOException {
    if (inputStream != null) {
        long startTime = System.currentTimeMillis();
        inputStream.close();
        Log.e("_close_", "close inputstream cost: " +((System.currentTimeMillis() - startTime) / 1000.0) + "s");
        inputStream = null;
    }
}

运行调试, 输出信息如下 (反复启动同一个app, 进程是同一个 从下面的日志中可以看出, 圆括号中的为进程ID --- 杀过一次进程):

macbook-stonedeMacBook-Pro:~ stone$ adb logcat *:E | grep _close_
E/_close_ (20394): close inputstream cost: 76.06s
E/_close_ (20394): close inputstream cost: 0.0s
E/_close_ (20394): close inputstream cost: 30.284s
E/_close_ (20394): close inputstream cost: 0.0s
E/_close_ (20394): close inputstream cost: 31.251s
E/_close_ (20394): close inputstream cost: 0.0s
E/_close_ (20394): close inputstream cost: 28.734s
E/_close_ (20394): close inputstream cost: 0.0s
E/_close_ (20394): close inputstream cost: 27.762s
E/_close_ (20394): close inputstream cost: 0.0s
E/_close_ (20394): close inputstream cost: 35.533s
E/_close_ (20394): close inputstream cost: 0.0s
E/_close_ (20394): close inputstream cost: 25.023s
E/_close_ (20394): close inputstream cost: 0.001s
E/_close_ (20394): close inputstream cost: 17.888s
E/_close_ (20394): close inputstream cost: 0.0s
E/_close_ (20394): close inputstream cost: 17.883s
E/_close_ (20394): close inputstream cost: 0.0s
E/_close_ (20394): close inputstream cost: 23.678s
E/_close_ (20394): close inputstream cost: 0.0s
E/_close_ (21037): close inputstream cost: 134.213s
E/_close_ (21037): close inputstream cost: 0.0s
E/_close_ (21037): close inputstream cost: 56.464s
E/_close_ (21037): close inputstream cost: 0.0s
E/_close_ (21037): close inputstream cost: 40.104s
E/_close_ (21037): close inputstream cost: 0.0s
E/_close_ (21037): close inputstream cost: 34.067s
E/_close_ (21037): close inputstream cost: 0.0s

由于doInBackground中多次调用了closeInputStream方法, finally块中关闭输入流时间为0. doInBackground方法的基本逻辑如下:

protected Boolean doInBackground(Void... params) {
    InputStream inputStream = null;
    // 省略 ...... 
    try {
        // 省略 ......
        if (inputStream != null) {
            while (!isCancelDownload && !isFinishing()) { 
                //download apk file .......
            }
        }
        closeInputStream(inputStream);
        return true;
    } catch (Exception e) {
        // 省略 ...... 
        return false;
    } finally {
        try {
            closeInputStream(inputStream);
        } catch (IOException e) {
            // 省略 ...... 
        }
    }
}

还有一个问题就是, 用户启动一次发现下载不了, 就有退出, 那么这一动作就会加入一个下载任务, 如果用户反复执行这一动作, 那么AsyncTask的默认线程池中就会堆积越来越多的下载任务, 而execute()方法导致任务顺序执行, 这样关闭输入流的时间也会累积起来, 也就是启动次数越多, 下载任务等待的时间就会越久. 由于AsyncTask是自定义的, 所以我可以更改源码, 因此我在AsyncTask中加入了Log语句Log.e("_size_", "pending size: " + mTasks.size());, 输出等待执行的任务数量, 更完整的代码如下:

@TargetApi(11)
private static class SerialExecutor implements Executor {
    final ArrayDeque<Runnable> mTasks = new ArrayDeque<Runnable>();
    Runnable mActive;

    public synchronized void execute(final Runnable r) {
        mTasks.offer(new Runnable() {
            public void run() {
                try {
                    r.run();
                } finally {
                    scheduleNext();
                }
            }
        });
        if (mActive == null) {
            scheduleNext();
        }
        Log.e("_size_", "pending size: " + mTasks.size());
    }

    protected synchronized void scheduleNext() {
        if ((mActive = mTasks.poll()) != null) {
            THREAD_POOL_EXECUTOR.execute(mActive);
        }
    }
}

多次执行启动-点击强制更新按钮-退出动作, log日志如下:

macbook-stonedeMacBook-Pro:~ stone$ adb logcat *:E | grep _size_
E/_size_  (21890): pending size: 0
E/_size_  (21890): pending size: 1
E/_size_  (21890): pending size: 2
E/_size_  (21890): pending size: 2
E/_size_  (21890): pending size: 3
E/_size_  (21890): pending size: 4
E/_size_  (21890): pending size: 5
E/_size_  (21890): pending size: 6
E/_size_  (21890): pending size: 7

日志说明上面的分析是正确的, 任务的确会积累在等待队列中.

至此问题已经分析完毕 !

解决办法: 使用AsyncTask的executeOnExecutor()方法来执行异步任务,且为executeOnExcutor()方法提供一个合理的线程池, 或者直接用Thread来执行下载任务.

总结:

**AsyncTask的execute()方法是顺序执行异步任务的 (相当于Executors.newSingleThreadExecutor()), 每次只执行一个任务. 如果要并发执行多个异步任务, 必须使用AsyncTask的executeOnExecutor()方法, 且必须提供正确的线程池. **
建议: 尽量不要使用AsynTask的execute()方法来执行异步任务. 如果要使用execute()方法来执行异步任务, 你必须确定这个异步任务无论正常执行/或异常执行都不会耗时 (如果耗时, 会导致后续异步任务得不到及时执行), 且你并不关心它什么时候执行 (因为你无法确认在你执行异步任务之前别人是否已经使用execute()方法执行了一个耗时的异步任务).

如有错误, 欢迎指正!

为什么AsyncTask调用execute方法后很久才执行doI

总结:

相关文章

网友评论

延伸阅读

深度阅读

栏目导航

热点阅读

Java并发编程

Android-性能优化