[011]一个看似是系统问题的应用问题的解决过程

前言

今天遇到一个问题,应用工程师分析是系统层的问题,然后就把这个锅给了我。最后我又把锅甩回给了应用工程师。

异常log如下:

I [2019-08-18 10:11:08 GMT+8] binder: 1433:1561 transaction failed 29201/-28, size 828-8 line 3135
W BroadcastQueue: Can't deliver broadcast to com.xxxx.xxxxx (pid 4712). Crashing it.
W BroadcastQueue: Failure sending broadcast Intent { act=android.intent.action.BATTERY_CHANGED flg=0x60000010 (has extras) }
W BroadcastQueue: android.os.DeadObjectException: Transaction failed on small parcel; remote process probably died
W BroadcastQueue:   at android.os.BinderProxy.transactNative(Native Method)
W BroadcastQueue:   at android.os.BinderProxy.transact(Binder.java:1127)
W BroadcastQueue:   at android.app.IApplicationThread$Stub$Proxy.scheduleRegisteredReceiver(IApplicationThread.java:1237)
W BroadcastQueue:   at com.android.server.am.BroadcastQueue.performReceiveLocked(BroadcastQueue.java:496)
W BroadcastQueue:   at com.android.server.am.BroadcastQueue.deliverToRegisteredReceiverLocked(BroadcastQueue.java:715)
W BroadcastQueue:   at com.android.server.am.BroadcastQueue.processNextBroadcastLocked(BroadcastQueue.java:875)
W BroadcastQueue:   at com.android.server.am.BroadcastQueue.processNextBroadcast(BroadcastQueue.java:834)
W BroadcastQueue:   at com.android.server.am.BroadcastQueue$BroadcastHandler.handleMessage(BroadcastQueue.java:172)
W BroadcastQueue:   at android.os.Handler.dispatchMessage(Handler.java:106)
W BroadcastQueue:   at android.os.Looper.loop(Looper.java:193)
W BroadcastQueue:   at android.os.HandlerThread.run(HandlerThread.java:65)
W BroadcastQueue:   at com.android.server.ServiceThread.run(ServiceThread.java:44)

初步分析

从log来看的确好像是binder驱动第3135行出现问题(line 3135)

binder: 1433:1561 transaction failed 29201/-28, size 828-8 line 3135

一看Binder.c的代码发现对不上3135行,估计是编译版本不一样,因为测试是user版本,代码优化了,这怎么办?我需要在userdebug的版本上你复现此问题。

Binder.c
3129    if (target_node && target_node->txn_security_ctx) {
3130              u32 secid;
3131           size_t added_size;
3132
3133            security_task_getsecid(proc->tsk, &secid);
3134         ret = security_secid_to_secctx(secid, &secctx, &secctx_sz);
3135           if (ret) {
3136                  return_error = BR_FAILED_REPLY;
3137                    return_error_param = ret;
3138                    return_error_line = __LINE__;
3139                        goto err_get_secctx_failed;
3140            }

聪明机智的我瞬间判断应该是对应到3164行,应该是binder server无法申请足够的buffer,别问我怎么想到的,有时候解决问题就得靠猜。

3154    t->buffer = binder_alloc_new_buf(&target_proc->alloc, tr->data_size,
3155           tr->offsets_size, extra_buffers_size,
3156             !reply && (t->flags & TF_ONE_WAY));
3157       if (IS_ERR(t->buffer)) {
3158                /*
3159            * -ESRCH indicates VMA cleared. The target is dying.
3160              */
3161         return_error_param = PTR_ERR(t->buffer);
3162          return_error = return_error_param == -ESRCH ?
3163                    BR_DEAD_REPLY : BR_FAILED_REPLY;
3164             return_error_line = __LINE__;
3165         t->buffer = NULL;
3166         goto err_binder_alloc_buf_failed;
3167       }

为了证明我判断是对的,我写了如下的一个demo安装到userdebug来制造binder server无法申请足够的buffer的情况

public class MainActivity extends Activity implements View.OnClickListener {
    private MyLinear mRoot;

    private IMyAidlInterface myAidlInterface;


    @Override
    protected void onCreate(Bundle savedInstanceState) {
        super.onCreate(savedInstanceState);
        setContentView(R.layout.activity_main);
        mRoot = (MyLinear) findViewById(R.id.root);
        mRoot.setOnClickListener(this);

        Intent intent = new Intent(this, MyService.class);
        bindService(intent, new ServiceConnection() {
            @Override
            public void onServiceConnected(ComponentName name, IBinder service) {
                myAidlInterface = IMyAidlInterface.Stub.asInterface(service);
            }

            @Override
            public void onServiceDisconnected(ComponentName name) {

            }
        }, Context.BIND_AUTO_CREATE);

    }

    @Override
    public void onClick(View v) {
        try {
            while (true) {
                myAidlInterface.send("dfdafsdfafdasdfadfadsfafd");
            }
        } catch (Exception e) {

        }
    }
}

public class MyService extends Service {

    @Override
    public IBinder onBind(Intent intent) {
        return new MyBinder();
    }

    public class MyBinder extends IMyAidlInterface.Stub {
        @Override
        public void send(String e) throws RemoteException {
            //后面发现这个4秒的卡顿,不加也可以复现此问题
            try {
                Thread.sleep(4000);
            } catch (Exception ee) {

            }
        }
    }
}

// IMyAidlInterface.aidl
package com.tct.activitydemo;

// Declare any non-default types here with import statements

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

出现的异常log,和之前log相比,除了行数不对,error code是一样的都是29201/-28,而且行数果然是3164行,所以我的推测是对的。

//binder: 1433:1561 transaction failed 29201/-28, size 828-8 line 3135
binder: 30286:30286 transaction failed 29201/-28, size 140-0 line 3164

初步分析结论

广播的发送失败是原因,在一次binder通信中,无法向广播注册的App的binder驱动中映射的共享内存申请足够buffer。

重大发现

我发现出问题的应用注册了300多个广播,都是监听android.intent.action.BATTERY_CHANGED,具体log就不贴了,在bugreport中会有当前系统所有广播的dumpsys的信息。我贴出meminfo的信息,发现三百多个activity没有被GC,因为那个广播是在activity中被动态注册的,所以变相可以证明注册了300多个广播

** MEMINFO in pid 4712 [com.xxxxxxxxxxx] **
.....省略没用的信息,看下面activity的数量是325 
 Objects
               Views:    13600         ViewRootImpl:        2
         AppContexts:      329           Activities:      325
              Assets:        3        AssetManagers:        0
       Local Binders:      352        Proxy Binders:      366
       Parcel memory:      887         Parcel count:     2235
    Death Recipients:        2      OpenSSL Sockets:        0
            WebViews:        0

推测

当这个广播发送的时候,由于他的接受者有300多个,每一次接收都会在申请一次buffer,如果短时间一下子申请,非常有可能超过binder驱动的(1mb-8kb)/2的限制,有人会问为什么是(1mb-8kb)/2而不是1mb-8kb,因为scheduleRegisteredReceiver是oneway的,对这个有疑问的,可以看一下我的另外一个文章:[007]一次Binder通信最大可以传输多大的数据?

进一步分析

其实一般分析到这里,对于我来说已经可以把锅甩回给了应用层,但是这个问题的好奇心促使我继续分析下去,一定要找到广播重复注册的原因。

涉及的保密,我把应用层代码的精简成自己的代码

public class MyActivity extends Activity {

    private MyReceiver receiver;

    @Override
    protected void onCreate(Bundle savedInstanceState) {
        super.onCreate(savedInstanceState);
        setContentView(R.layout.activity_main2);
        IntentFilter intentFilter = new IntentFilter();
        intentFilter.addAction("fdafdafsdafaffasdfad");
        receiver = new MyReceiver(this);
        getApplication().registerReceiver(receiver, intentFilter);
    }

    @Override
    protected void onDestroy() {
        try {
            //因为上下文不同,会导致unregisterReceiver失败,从而导致MyActivity和MyReceiver,无法被GC
            unregisterReceiver(receiver);
        } catch (Exception e) {

        }
        super.onDestroy();
    }

    public static class MyReceiver extends BroadcastReceiver {

        private Context mContext;

        public MyReceiver(Context context) {
            mContext = context;
        }

        @Override
        public void onReceive(Context context, Intent intent) {

        }
    }
}

水落石出

原来应用开发工程师,在registerReceiver和unregisterReceiver使用了不同的context,导致了unregisterReceiver的失败,从而导致MyReceiver的无法被释放,而且这个代码还会导致MyActivity的内存泄露。

举个例子来还原一下这个现场

小明寄了一份投诉信到信访局门口的信箱,然后信访局的1号工作人员拿了这份投诉信,进行处理。这个就是一次完整的oneway的binder通信。但是有一天小明一下子拿了300封投诉信,一封封的塞到信箱里,然后信访局的1~16号工作人员同时拿了16封信进行处理,但是还是架不住小明的塞信的速度,很快信箱就爆了,小明说了一句:垃圾信访局,我信还没有塞完呢。

2020年1月8日更新:

其实我上述例子这个解释中有点错误,结果一直没有人提出来,我更新一下,对于oneway的binder通信,server端的进程一次只有一个binder线程处理一个oneway的binder请求。

所以更正例子来还原一下现场:
小明寄了一份投诉信到信访局门口的信箱,然后信访局的1号工作人员拿了这份投诉信,进行处理。这个就是一次完整的oneway的binder通信。但是有一天小明一下子拿了300封投诉信,一封封的塞到信箱里,然后因为只有信访局的1号工作人员处理小明投诉,很快信箱就爆了,小明说了一句:垃圾信访局,我信还没有塞完呢。

其实大家可能有点难以理解一次binder通信,内核发生了什么,请看下面图,看懂下图,才能知道我在说什么:

binder通信
最后编辑于
©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 199,902评论 5 468
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 84,037评论 2 377
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 146,978评论 0 332
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 53,867评论 1 272
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 62,763评论 5 360
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 48,104评论 1 277
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 37,565评论 3 390
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 36,236评论 0 254
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 40,379评论 1 294
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 35,313评论 2 317
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 37,363评论 1 329
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 33,034评论 3 315
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 38,637评论 3 303
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 29,719评论 0 19
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 30,952评论 1 255
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 42,371评论 2 346
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 41,948评论 2 341

推荐阅读更多精彩内容