Android技术进阶技术干货android基础知识

AIDL oneway 方法的隐患

2020-01-09  本文已影响0人  杰杰_88

结论:不要在服务端oneway接口中处理耗时操作,一旦用于高频调用,服务端又处理耗时,再偶尔碰上cpu负荷高,很可能会发生其他关键调用偶现失败的隐蔽问题,而且这个调用失败不会导致app crash严重问题,只会导致业务逻辑的缺失,如果错误log输出不完善,会让人莫名奇妙,而且很难复现,隐患就一直在那儿了。

最近遇到一个偶现问题,ROM刚OTA后,某个系统应用(App A)在重启过程中bind另一系统服务(服务B),后面却一直没有收到onServiceConnected回调,开始App A很合理的认为是服务B的问题(服务B最近修改过,会导致服务B启动慢,偶尔ANR)。

分析Log后发现,可能是由于OTA重启过程中在做大量的odex编译优化操作,导致CPU占用高,其启动过程比正常启动情况下慢很多(onCreate执行耗时长),但是虽然服务B启动较慢,但是也在ANR时间内完成启动,其他app也bind服务B成功,及时收到了onServiceConnected回调。App A并没有指定onServiceConnected在其他线程执行,于是怀疑App A主线程被他自己的操作block,导致onServiceConnected回调无法执行,但是在几分钟以后的log中发现了App A主线程有log输出,App A也并没有发生ANR,说明App A主线程并没有block,只是单纯的没有onServiceConnected回调。

好在其他App在绑定服务B的onServiceConnected回调中加了log,很明显的可以看到,其他App集中收到了回调,于是在其他App收到回调附近log仔细查看,发现这样的warnning log:

12-26 11:02:44.107  1095  2101 W ActivityManager: Failure sending service ComponentInfo{com.android.**/com.android.**.**} to connection android.os.BinderProxy@a3981ee (in com.**)
12-26 11:02:44.107  1095  2101 W ActivityManager: android.os.DeadObjectException: Transaction failed on small parcel; remote process probably died
12-26 11:02:44.107  1095  2101 W ActivityManager:   at android.os.BinderProxy.transactNative(Native Method)
12-26 11:02:44.107  1095  2101 W ActivityManager:   at android.os.BinderProxy.transact(Binder.java:764)
12-26 11:02:44.107  1095  2101 W ActivityManager:   at android.app.IServiceConnection$Stub$Proxy.connected(IServiceConnection.java:95)
12-26 11:02:44.107  1095  2101 W ActivityManager:   at com.android.server.am.ActiveServices.publishServiceLocked(ActiveServices.java:1526)
12-26 11:02:44.107  1095  2101 W ActivityManager:   at com.android.server.am.ActivityManagerService.publishService(ActivityManagerService.java:18828)
12-26 11:02:44.107  1095  2101 W ActivityManager:   at android.app.IActivityManager$Stub.onTransact(IActivityManager.java:627)
12-26 11:02:44.107  1095  2101 W ActivityManager:   at com.android.server.am.ActivityManagerService.onTransact(ActivityManagerService.java:3055)
12-26 11:02:44.107  1095  2101 W ActivityManager:   at android.os.Binder.execTransact(Binder.java:697)

很显然,这是ActivityManagerService向App A回调onServiceConnected接口时抛出的异常,应该是App A进程有问题,但是根据后面的log看,App A其他work线程有正常log输出,主线程也有log输出,进程运行的很好,怎么会抛这个异常呢?

直觉上觉得可能是Binder出问题了,但Binder是成熟的不能再成熟的IPC机制了,又不太可能出问题,联系到Binder是通过linux驱动来实现的,于是先去kernel log中对应时间点看看有没有什么线索,然后就看到了很多类似下面kernel中的错误log:

12-26 11:02:44.102     0     0 I k       : binder: 1095:2101 transaction failed 29201/-28, size 200-8 line 3142

注意 1095:2101是指binder client端的进程号和线程号,与上面Warning log一致。再找到对应该log的kernel代码。

aosp_kernel/common/drivers/android/binder.c

    binder_debug(BINDER_DEBUG_FAILED_TRANSACTION,
             "%d:%d transaction failed %d/%d, size %lld-%lld line %d\n",
             proc->pid, thread->pid, return_error, return_error_param,
             (u64)tr->data_size, (u64)tr->offsets_size,
             return_error_line);

可以看到log中其他信息分别是,return_error:29201, return_error_param: -28,这个-28是通用的linux错误码:

errno:/usr/include/asm-generic/errno-base.h

#define EPERM        1  /* Operation not permitted */
#define ENOENT       2  /* No such file or directory */
#define ESRCH        3  /* No such process */
#define EINTR        4  /* Interrupted system call */
#define EIO      5  /* I/O error */
#define ENXIO        6  /* No such device or address */
#define E2BIG        7  /* Argument list too long */
#define ENOEXEC      8  /* Exec format error */
#define EBADF        9  /* Bad file number */
#define ECHILD      10  /* No child processes */
#define EAGAIN      11  /* Try again */
#define ENOMEM      12  /* Out of memory */
#define EACCES      13  /* Permission denied */
#define EFAULT      14  /* Bad address */
#define ENOTBLK     15  /* Block device required */
#define EBUSY       16  /* Device or resource busy */
#define EEXIST      17  /* File exists */
#define EXDEV       18  /* Cross-device link */
#define ENODEV      19  /* No such device */
#define ENOTDIR     20  /* Not a directory */
#define EISDIR      21  /* Is a directory */
#define EINVAL      22  /* Invalid argument */
#define ENFILE      23  /* File table overflow */
#define EMFILE      24  /* Too many open files */
#define ENOTTY      25  /* Not a typewriter */
#define ETXTBSY     26  /* Text file busy */
#define EFBIG       27  /* File too large */
#define ENOSPC      28  /* No space left on device */
#define ESPIPE      29  /* Illegal seek */
#define EROFS       30  /* Read-only file system */
#define EMLINK      31  /* Too many links */
#define EPIPE       32  /* Broken pipe */
#define EDOM        33  /* Math argument out of domain of func */
#define ERANGE      34  /* Math result not representable */

可以看到错误是-ENOSPC,表示device上没有空间了,而binder在Android上,就是以设备驱动的形式存在,然后顺藤摸瓜,只有在下面的这个函数中找到返回了-ENOSPC:

aosp_kernel/common/drivers/android/binder_alloc.candroid/binder_alloc.c

static struct binder_buffer *binder_alloc_new_buf_locked(
                struct binder_alloc *alloc,
                size_t data_size,
                size_t offsets_size,
                size_t extra_buffers_size,
                int is_async)
{
}

往上跟踪,最终错误返回到:

aosp_kernel/common/drivers/android/binder.c 所在函数为binder_transaction,由函数名可以看出所有binder的传输,应该都有该函数处理(纯属猜测)

t->buffer = binder_alloc_new_buf(&target_proc->alloc, tr->data_size,
        tr->offsets_size, extra_buffers_size,
        !reply && (t->flags & TF_ONE_WAY));
    if (IS_ERR(t->buffer)) {
        /*
         * -ESRCH indicates VMA cleared. The target is dying.
         */
        return_error_param = PTR_ERR(t->buffer);
        return_error = return_error_param == -ESRCH ?
            BR_DEAD_REPLY : BR_FAILED_REPLY;
        return_error_line = __LINE__;
        t->buffer = NULL;
        goto err_binder_alloc_buf_failed;
    }

这里的PTR_ERR(t->buffer)就转换回了-ENOSPC然后跳转到了err_binder_alloc_buf_failed:打印出了kernel中的那行log

err_binder_alloc_buf_failed:
err_bad_extra_size:
    if (secctx)
        security_release_secctx(secctx, secctx_sz);
err_get_secctx_failed:
    kfree(tcomplete);
    binder_stats_deleted(BINDER_STAT_TRANSACTION_COMPLETE);
err_alloc_tcomplete_failed:
    kfree(t);
    binder_stats_deleted(BINDER_STAT_TRANSACTION);
err_alloc_t_failed:
err_bad_todo_list:
err_bad_call_stack:
err_empty_call_stack:
err_dead_binder:
err_invalid_target_handle:
    if (target_thread)
        binder_thread_dec_tmpref(target_thread);
    if (target_proc)
        binder_proc_dec_tmpref(target_proc);
    if (target_node) {
        binder_dec_node(target_node, 1, 0);
        binder_dec_node_tmpref(target_node);
    }

    binder_debug(BINDER_DEBUG_FAILED_TRANSACTION,
             "%d:%d transaction failed %d/%d, size %lld-%lld line %d\n",
             proc->pid, thread->pid, return_error, return_error_param,
             (u64)tr->data_size, (u64)tr->offsets_size,
             return_error_line);

再继续仔细分析抛出异常之前的log, App A有大量的“接收”数据的log输出,App A刚修改过一个sdk的配置,导致云端(另一个进程)可能大量给App A发数据,可能就是这个操作占满了Binder空间(不到1MB):

android/frameworks/native/libs/binder/ProcessState.cpp

#define BINDER_VM_SIZE ((1 * 1024 * 1024) - sysconf(_SC_PAGE_SIZE) * 2)

//......
        // mmap the binder, providing a chunk of virtual address space to receive transactions.
        mVMStart = mmap(0, BINDER_VM_SIZE, PROT_READ, MAP_PRIVATE | MAP_NORESERVE, mDriverFD, 0);

继续看其他kernel中的错误log:

12-26 11:02:43.694     0     0 I k       : binder: 828:957 transaction failed 29201/-28, size 5872-0 line 3142
12-26 11:02:43.694     0     0 I k       : binder: 828:957 transaction failed 29201/-28, size 136-0 line 3142
12-26 11:02:43.694     0     0 I k       : binder: 828:957 transaction failed 29201/-28, size 208-0 line 3142
12-26 11:02:43.694     0     0 I k       : binder: 828:957 transaction failed 29201/-28, size 136-0 line 3142
12-26 11:02:43.694     0     0 I k       : binder: 828:957 transaction failed 29201/-28, size 136-0 line 3142
12-26 11:02:43.694     0     0 I k       : binder: 828:957 transaction failed 29201/-28, size 140-0 line 3142
12-26 11:02:43.695     0     0 I k       : binder: 828:957 transaction failed 29201/-28, size 136-0 line 3142
12-26 11:02:43.695     0     0 I chatty  : uid=0(root) logd identical 2 lines
12-26 11:02:43.695     0     0 I k       : binder: 828:957 transaction failed 29201/-28, size 136-0 line 3142
12-26 11:02:43.695     0     0 I k       : binder: 828:957 transaction failed 29201/-28, size 140-0 line 3142
12-26 11:02:43.695     0     0 I k       : binder: 828:957 transaction failed 29201/-28, size 140-0 line 3142
12-26 11:02:43.695     0     0 I k       : binder: 828:957 transaction failed 29201/-28, size 136-0 line 3142
12-26 11:02:43.695     0     0 I k       : binder: 828:957 transaction failed 29201/-28, size 136-0 line 3142
12-26 11:02:43.695     0     0 I k       : binder: 828:957 transaction failed 29201/-28, size 140-0 line 3142
12-26 11:02:43.695     0     0 I k       : binder: 828:957 transaction failed 29201/-28, size 136-0 line 3142
12-26 11:02:43.695     0     0 I k       : binder: 828:957 transaction failed 29201/-28, size 140-0 line 3142
12-26 11:02:43.695     0     0 I k       : binder: 828:957 transaction failed 29201/-28, size 136-0 line 3142
12-26 11:02:43.695     0     0 I k       : binder: 828:957 transaction failed 29201/-28, size 136-0 line 3142

12-26 11:02:43.694
这个时间点是出现第一条错误的log,进程828,线程957执行的binder调用没有成功,可以看到在1ms内调用了好多次,可以怀疑前面没出错时这个线程也在一直进行binder调用导致了binder服务端处理不过来binder驱动缓存没有及时释放导致后面的调用分配空间失败。再去logcat中查找828进程的log:

12-26 11:02:43.694   828   957 W IDataCallback: transact data error! cmd=320, errorCode=-2147483646
12-26 11:02:43.694   828   957 W IDataCallback: transact data error! cmd=318, errorCode=-2147483646
12-26 11:02:43.694   828   957 W IDataCallback: transact data error! cmd=142, errorCode=-2147483646
12-26 11:02:43.694   828   957 W IDataCallback: transact data error! cmd=318, errorCode=-2147483646

在和kernel log出错相同时间点,相同的进程、线程输出了传输数据错误的log。到这基本确认就是binder传输太频繁导致服务端进程无法再接收其他binder调用(App版拒绝服务攻击??),包括AMS向App A调用onServiceConnected。

于是准备写个demo来复现这个错误:

验证demo

IRemoteService.aidl

// IRemoteService.aidl
package com.example.mycardemo;

// Declare any non-default types here with import statements
interface IRemoteService {
    /**
     * Demonstrates some basic types that you can use as parameters
     * and return values in AIDL.
     */
    void remoteCallbackTest();
}

RemoteService.java

package com.example.mycardemo;

import android.app.Service;
import android.content.Intent;
import android.os.IBinder;
import android.os.RemoteException;
import android.util.Log;

import androidx.annotation.Nullable;

public class RemoteService extends Service {
    private static final String TAG = "RemoteService";

    private BinderService mService;

    @Override
    public void onCreate() {
        super.onCreate();
        mService = new BinderService();
    }

    @Nullable
    @Override
    public IBinder onBind(Intent intent) {
        return mService;
    }

    private volatile int mCount = 0;

    private class BinderService extends IRemoteService.Stub {

        @Override
        public void remoteCallbackTest() throws RemoteException {
            Log.d(TAG, "remoteCallbackTest before wait " + (mCount++));
            try {
                Thread.sleep(10000);
            } catch (InterruptedException e) {
                e.printStackTrace();
            }
            Log.d(TAG, "remoteCallbackTest after wait " + (--mCount));
        }
    }
}

RemoteService2.java

package com.example.mycardemo;

import android.app.Service;
import android.content.ComponentName;
import android.content.Context;
import android.content.Intent;
import android.content.ServiceConnection;
import android.os.IBinder;
import android.os.RemoteException;
import android.util.Log;

import androidx.annotation.Nullable;

public class RemoteService2 extends Service {
    private static final String TAG = "RemoteService2";

    private IRemoteService mRemoteService;

    private volatile int mCallCount = 0;

    private Runnable mRemoteCall = new Runnable() {
        @Override
        public void run() {
            try {
                Log.d(TAG, "RemoteService2 client call remote " + (mCallCount++));
                mRemoteService.remoteCallbackTest();
                Log.d(TAG, "RemoteService2 client call remote end " + (--mCallCount));
            } catch (RemoteException e) {
                e.printStackTrace();
            }
        }
    };

    private ServiceConnection mConnection = new ServiceConnection() {
        @Override
        public void onServiceConnected(ComponentName componentName, IBinder iBinder) {
            Log.d(TAG, "onServiceConnected :" + componentName);
            mRemoteService = IRemoteService.Stub.asInterface(iBinder);
            for(int i = 0; i < 500; i++) {
                new Thread(mRemoteCall).start();
            }
        }

        @Override
        public void onServiceDisconnected(ComponentName componentName) {

        }
    };
    @Override
    public void onCreate() {
        super.onCreate();
        Intent intent = new Intent();
        intent.setPackage("com.example.mycardemo");
        intent.setAction("action.test.remote.call");
        bindService(intent, mConnection, Context.BIND_AUTO_CREATE);
    }

    @Nullable
    @Override
    public IBinder onBind(Intent intent) {
        return null;
    }

}

AndroidManifest.xml

    <application
        android:allowBackup="true"
        android:icon="@mipmap/ic_launcher"
        android:label="@string/app_name"
        android:roundIcon="@mipmap/ic_launcher_round"
        android:supportsRtl="true"
        android:theme="@style/AppTheme">
        <activity android:name=".MainActivity">
            <intent-filter>
                <action android:name="android.intent.action.MAIN" />

                <category android:name="android.intent.category.LAUNCHER" />
            </intent-filter>
        </activity>
        <service
            android:name=".RemoteService"
            android:process=":remote">
            <intent-filter>
                <action android:name="action.test.remote.call"/>
            </intent-filter>
        </service>
        <service android:name=".RemoteService2"
            android:process=":remote2">
            <intent-filter>
                <action android:name="action.test.remote.call2"/>
            </intent-filter>
        </service>
    </application>

信心满满运行(截取log):

01-09 14:18:02.990  1985  2742 D RemoteService2: RemoteService2 client call remote 497
01-09 14:18:02.992  1985  2743 D RemoteService2: RemoteService2 client call remote 498
01-09 14:18:02.993  1985  2745 D RemoteService2: RemoteService2 client call remote 499
01-09 14:18:11.475  1992  2037 D RemoteService: remoteCallbackTest after wait 15
01-09 14:18:11.475  1992  2037 D RemoteService: remoteCallbackTest before wait 15
01-09 14:18:11.475  1985  2044 D RemoteService2: RemoteService2 client call remote end 499
01-09 14:18:11.490  1992  2028 D RemoteService: remoteCallbackTest after wait 15
01-09 14:18:11.490  1985  2045 D RemoteService2: RemoteService2 client call remote end 498
01-09 14:18:11.490  1992  2028 D RemoteService: remoteCallbackTest before wait 15
01-09 14:18:11.491  1992  2029 D RemoteService: remoteCallbackTest after wait 15
01-09 14:18:11.492  1992  2029 D RemoteService: remoteCallbackTest before wait 15
01-09 14:18:11.492  1985  2050 D RemoteService2: RemoteService2 client call remote end 497
01-09 14:18:11.496  1992  2058 D RemoteService: remoteCallbackTest after wait 15
01-09 14:18:11.497  1992  2058 D RemoteService: remoteCallbackTest before wait 15
01-09 14:18:11.497  1985  2052 D RemoteService2: RemoteService2 client call remote end 496
01-09 14:18:11.504  1992  2059 D RemoteService: remoteCallbackTest after wait 15
01-09 14:18:11.504  1992  2059 D RemoteService: remoteCallbackTest before wait 15

居然没问题,井然有序的执行完了,疑惑不已,再和另一个同事讨论中,同事提醒onServiceConnected是oneway调用,会不会和这个有关,于是修改aidl:

oneway interface IRemoteService {
    /**
     * Demonstrates some basic types that you can use as parameters
     * and return values in AIDL.
     */
    void remoteCallbackTest();
}

再执行:

01-09 14:22:00.924  3290  3883 D RemoteService2: RemoteService2 client call remote 2
01-09 14:22:00.924  3290  3883 D RemoteService2: RemoteService2 client call remote end 2
01-09 14:22:00.925  3290  3884 D RemoteService2: RemoteService2 client call remote 2
01-09 14:22:00.925  3290  3884 D RemoteService2: RemoteService2 client call remote end 2
01-09 14:22:00.931  3290  3885 D RemoteService2: RemoteService2 client call remote 2
01-09 14:22:00.931  3290  3886 D RemoteService2: RemoteService2 client call remote 3
01-09 14:22:00.931  3290  3886 D RemoteService2: RemoteService2 client call remote end 3
01-09 14:22:00.931  3290  3885 D RemoteService2: RemoteService2 client call remote end 2
01-09 14:22:09.673  3295  3325 D RemoteService: remoteCallbackTest after wait 0
01-09 14:22:09.673  3295  3325 D RemoteService: remoteCallbackTest before wait 0
01-09 14:22:19.675  3295  3325 D RemoteService: remoteCallbackTest after wait 0
01-09 14:22:19.675  3295  3325 D RemoteService: remoteCallbackTest before wait 0
01-09 14:22:29.680  3295  3325 D RemoteService: remoteCallbackTest after wait 0
01-09 14:22:29.683  3295  3323 D RemoteService: remoteCallbackTest before wait 0
01-09 14:22:39.686  3295  3323 D RemoteService: remoteCallbackTest after wait 0
01-09 14:22:39.686  3295  3323 D RemoteService: remoteCallbackTest before wait 0
01-09 14:22:49.686  3295  3323 D RemoteService: remoteCallbackTest after wait 0
01-09 14:22:49.687  3295  3323 D RemoteService: remoteCallbackTest before wait 0

还是没问题T_T,不过意外的是,oneway方法服务端是依次执行,可以看到每个服务端的被调用都是隔10s调用一次,因为服务端接口中sleep了10s,同事和我在一块尝试复现,在修改调用次数到5000的时候,再执行:

01-09 14:31:11.258 15103 18251 E JavaBinder: !!! FAILED BINDER TRANSACTION !!!  (parcel size = 84)
01-09 14:31:11.258 15103 18236 W System.err: android.os.DeadObjectException: Transaction failed on small parcel; remote process probably died
01-09 14:31:11.258 15103 18236 W System.err:    at android.os.BinderProxy.transactNative(Native Method)
01-09 14:31:11.258 15103 18236 W System.err:    at android.os.BinderProxy.transact(Binder.java:764)
01-09 14:31:11.259 15103 18250 D RemoteService2: RemoteService2 client call remote 227
01-09 14:31:11.259 15103 18236 W System.err:    at com.example.mycardemo.IRemoteService$Stub$Proxy.remoteCallbackTest(IRemoteService.java:98)
01-09 14:31:11.259 15103 18236 W System.err:    at com.example.mycardemo.RemoteService2$1.run(RemoteService2.java:26)
01-09 14:31:11.259 15103 18236 W System.err:    at java.lang.Thread.run(Thread.java:764)
01-09 14:31:11.259 15103 18253 E JavaBinder: !!! FAILED BINDER TRANSACTION !!!  (parcel size = 84)
01-09 14:31:11.259 15103 18252 E JavaBinder: !!! FAILED BINDER TRANSACTION !!!  (parcel size = 84)
01-09 14:31:11.259 15103 18250 E JavaBinder: !!! FAILED BINDER TRANSACTION !!!  (parcel size = 84)
01-09 14:31:11.260 15103 18251 W System.err: android.os.DeadObjectException: Transaction failed on small parcel; remote process probably died
01-09 14:31:11.260 15103 18251 W System.err:    at android.os.BinderProxy.transactNative(Native Method)
01-09 14:31:11.260 15103 18251 W System.err:    at android.os.BinderProxy.transact(Binder.java:764)
01-09 14:31:11.260 15103 18249 D RemoteService2: RemoteService2 client call remote 228
01-09 14:31:11.262 15103 18251 W System.err:    at com.example.mycardemo.IRemoteService$Stub$Proxy.remoteCallbackTest(IRemoteService.java:98)
01-09 14:31:11.262 15103 18251 W System.err:    at com.example.mycardemo.RemoteService2$1.run(RemoteService2.java:26)
01-09 14:31:11.262 15103 18251 W System.err:    at java.lang.Thread.run(Thread.java:764)

复现了!和上面ActivityManagerService回调onServiceConnected一样的错误。

再改回非oneway接口测试,OOM,crash了,线程太多导致栈溢出了。但是binder调用还是正常。

01-09 14:27:42.286  9465  9465 E AndroidRuntime: java.lang.OutOfMemoryError: pthread_create (1040KB stack) failed: Try again
01-09 14:27:42.286  9465  9465 E AndroidRuntime:    at java.lang.Thread.nativeCreate(Native Method)
01-09 14:27:42.286  9465  9465 E AndroidRuntime:    at java.lang.Thread.start(Thread.java:733)
01-09 14:27:42.286  9465  9465 E AndroidRuntime:    at com.example.mycardemo.RemoteService2$2.onServiceConnected(RemoteService2.java:40)
01-09 14:27:42.286  9465  9465 E AndroidRuntime:    at android.app.LoadedApk$ServiceDispatcher.doConnected(LoadedApk.java:1652)
01-09 14:27:42.286  9465  9465 E AndroidRuntime:    at android.app.LoadedApk$ServiceDispatcher$RunConnection.run(LoadedApk.java:1681)
01-09 14:27:42.286  9465  9465 E AndroidRuntime:    at android.os.Handler.handleCallback(Handler.java:790)
01-09 14:27:42.286  9465  9465 E AndroidRuntime:    at android.os.Handler.dispatchMessage(Handler.java:99)
01-09 14:27:42.286  9465  9465 E AndroidRuntime:    at android.os.Looper.loop(Looper.java:164)
01-09 14:27:42.286  9465  9465 E AndroidRuntime:    at android.app.ActivityThread.main(ActivityThread.java:6494)
01-09 14:27:42.286  9465  9465 E AndroidRuntime:    at java.lang.reflect.Method.invoke(Native Method)
01-09 14:27:42.286  9465  9465 E AndroidRuntime:    at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:438)
01-09 14:27:42.286  9465  9465 E AndroidRuntime:    at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:807)

然后去官网看了看oneway接口的说明:

FLAG_ONEWAY
Added in API level 1
public static final int FLAG_ONEWAY
Flag to transact(int, Parcel, Parcel, int): this is a one-way call, meaning that the caller returns immediately, without waiting for a result from the callee. Applies only if the caller and callee are in different processes.
The system provides special ordering semantics for multiple oneway calls being made to the same IBinder object: these calls will be dispatched in the other process one at a time, with the same order as the original calls. These are still dispatched by the IPC thread pool, so may execute on different threads, but the next one will not be dispatched until the previous one completes. This ordering is not guaranteed for calls on different IBinder objects or when mixing oneway and non-oneway calls on the same IBinder object.

These are still dispatched by the IPC thread pool, so may execute on different threads, but the next one will not be dispatched until the previous one completes.

的确binder驱动对于oneway的调用是类似于handler sendmessage那样的,挨个处理,所以如果服务端的oneway接口处理太慢而客户端调用太多的话,来不及处理的调用会占满binder驱动的缓存,导致其他调用抛出上面的transaction failed!这个有点坑啊,oneway binder调用岂不是成了不可靠调用??照上面的分析,只有oneway调用会导致这个问题,回到实际的那个问题,根据log tag 找到了IDataCallback.aidl

oneway interface IDataCallback {
    void onReceiveBytes(int groupId, in byte[] data);
}

果然是个oneway的远程回调接口,到这应该能确定,就是oneway的使用导致了上面的那个偶现问题。

这个坑太隐蔽,本来oneway就是为了客户端不阻塞快速返回,一旦用于高频调用,服务端又处理耗时,再偶尔碰上cpu负荷高,很可能会发生其他关键调用偶现失败的隐蔽问题,而且这个调用失败不会导致app crash严重问题,只会导致业务逻辑的缺失,如果错误log输出不完善,会让人莫名奇妙,而且很难复现,隐患就一直在那儿了。

上一篇下一篇

猜你喜欢

热点阅读