android: binder: error log: binder_alloc_buf, no vma

https://chengyihe.wordpress.com/2015/10/19/android-binder-error-log-binder_alloc_buf-no-vma/

This post is to discuss binder error log: binder_alloc_buf, no vma. The reference code base is android kernel 3.4. The log is borrowed from https://community.freescale.com/thread/342488.

symptom: after process pid=357 crashes, lots of binder: 3057: binder_alloc_buf, no vma logs show up

https://community.freescale.com/thread/342488

1 2 3 4 5 6 7 8 9 10 11 12 13

[  174.653668] init: untracked pid 3113 exited [  174.659857] init: untracked pid 3262 exited [  174.665214] init: untracked pid 3279 exited [  174.670170] init: untracked pid 3462 exited [  174.674735] init: untracked pid 3538 exited [  174.679930] init: untracked pid 3057 exited [  174.759346] init: untracked pid 3870 exited [  174.839368] alarm_release: clear alarm, pending 0 [  174.844092] alarm_release: clear alarm, pending 0 [  175.003312] binder: 3057: binder_alloc_buf, no vma [  175.008343] binder: 4008:4104 transaction failed 29201, size 124-4 [  175.015018] binder: 3057: binder_alloc_buf, no vma [  175.019899] binder: 4008:4104 transaction failed 29201, size 124-4

analysis
In android: binder: resources , we discuss that binder_vma and binder fd are both released within do_exit which is executed when a process crashes. Among these resources, binder_vma is released before binder fd is released. Thus, it’s very common to see these logs while a process crashes.

The log shows that the thread 4008:4104 tries to initiate a binder transaction and allocate a binder buffer within 3057’s binder_vma. However, 3057 is doing do_exit and has already released binder_vma but has not released binder fd, yet. Thus, 4008:4104 could initialise a binder transaction but fails to allocate binder buffer in 3057’s binder_vma, and get BR_FAILED_REPLY.

https://android.googlesource.com/kernel/common.git/+/android-3.4/drivers/staging/android/binder.c#732

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18

static struct binder_buffer *binder_alloc_buf(struct binder_proc *proc,                           size_t data_size,                           size_t offsets_size, int is_async) {     struct rb_node *n = proc->free_buffers.rb_node;     struct binder_buffer *buffer;     size_t buffer_size;     struct rb_node *best_fit = NULL;     void *has_page_addr;     void *end_page_addr;     size_t size;     if (proc->vma == NULL) {         printk(KERN_ERR "binder: %d: binder_alloc_buf, no vma\n",                proc->pid);         return NULL;     } ...... }

https://android.googlesource.com/kernel/common.git/+/android-3.4/drivers/staging/android/binder.c#1577

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31

static void binder_transaction(struct binder_proc *proc,                    struct binder_thread *thread,                    struct binder_transaction_data *tr, int reply) { ......     t->buffer = binder_alloc_buf(target_proc, tr->data_size,         tr->offsets_size, !reply && (t->flags & TF_ONE_WAY));     if (t->buffer == NULL) {         return_error = BR_FAILED_REPLY;         goto err_binder_alloc_buf_failed;     } ...... err_binder_alloc_buf_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_call_stack: err_empty_call_stack: err_dead_binder: err_invalid_target_handle: err_no_context_mgr_node:     binder_debug(BINDER_DEBUG_FAILED_TRANSACTION,              "binder: %d:%d transaction failed %d, size %zd-%zd\n",              proc->pid, thread->pid, return_error,              tr->data_size, tr->offsets_size);     { ...... }

conclusion
After a process crashes, it’s very common to see these logs since binder_vma has already been released. But if these log happen for a long time, it’s really an issue and we’ll discuss in another post.