| /* |
| * Copyright (C) 2019 The Android Open Source Project |
| * |
| * Licensed under the Apache License, Version 2.0 (the "License"); |
| * you may not use this file except in compliance with the License. |
| * You may obtain a copy of the License at |
| * |
| * http://www.apache.org/licenses/LICENSE-2.0 |
| * |
| * Unless required by applicable law or agreed to in writing, software |
| * distributed under the License is distributed on an "AS IS" BASIS, |
| * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. |
| * See the License for the specific language governing permissions and |
| * limitations under the License. |
| */ |
| |
| #include "src/trace_processor/importers/ftrace/binder_tracker.h" |
| #include "perfetto/base/compiler.h" |
| #include "perfetto/ext/base/string_utils.h" |
| #include "src/trace_processor/importers/common/flow_tracker.h" |
| #include "src/trace_processor/importers/common/process_tracker.h" |
| #include "src/trace_processor/importers/common/slice_tracker.h" |
| #include "src/trace_processor/importers/common/track_tracker.h" |
| #include "src/trace_processor/storage/trace_storage.h" |
| #include "src/trace_processor/types/trace_processor_context.h" |
| |
| // Binder tracker: displays slices for binder transactions and other operations. |
| // ============================================================================= |
| // |
| // Supported events |
| // ---------------- |
| // # Transactions |
| // |
| // * binder/binder_transaction |
| // * binder/binder_transaction_reply |
| // |
| // With these two events the tracker can display slices for binder transactions |
| // in the sending and receiving threads. Rarely, when transactions fail in some |
| // way, it's possible that the tracker doesn't have enough information to |
| // properly terminate slices. See "Commands" below for a solution. |
| // |
| // # Buffer allocations |
| // |
| // * binder/binder_transaction_alloc_buf |
| // |
| // This annotates the transaction slices (from the above events) with info about |
| // allocations. The event alone doesn't make sense without the "Transactions" |
| // events. |
| // |
| // # Commands |
| // |
| // * binder/binder_command |
| // * binder/binder_return |
| // |
| // These two events are only useful in conjunction with the "Transactions" |
| // events. Their presence allow the tracker to terminate slices more reliably |
| // when a transaction fails. |
| // |
| // # Locking |
| // |
| // * binder/binder_lock |
| // * binder/binder_locked |
| // * binder/binder_unlock |
| // |
| // Obsolete: this was removed from kernel v4.14 |
| // |
| // Implementation details |
| // ---------------------- |
| // |
| // # Basic transaction tracking: |
| // |
| // For each transaction, two threads are involved. |
| // |
| // A oneway (aka asynchronous) transaction has these events: |
| // |
| // ``` |
| // Thread Snd Thread Rcv |
| // | | |
| // binder_transaction(id, is_oneway) | |
| // | |
| // binder_transaction_received(id) |
| // ``` |
| // |
| // The tracker will create one instant events one each thread. |
| // |
| // A regular (aka synchronous) transaction has these events: |
| // |
| // ``` |
| // Thread Snd Thread Rcv |
| // | | |
| // binder_transaction(id) | |
| // | | |
| // | binder_transaction_received(id) |
| // | | |
| // | binder_transaction(other_id, is_reply) |
| // | |
| // binder_transaction_received(other_id, is_reply) |
| // ``` |
| // |
| // The tracker will create a "binder transaction" slice on Thread 1 and a |
| // "binder reply" slice on Thread 2. |
| // |
| // synchronous transactions can be nested: inside a "binder reply", a thread can |
| // make a binder transaction to another thread (just regular synchronous |
| // function calls). |
| // |
| // If a regular transaction fails, the kernel will not emit some events, causing |
| // the tracker to leave some slices open forever, while the threads are actually |
| // not working on the transaction anymore. |
| // |
| // ``` |
| // Thread Snd Thread Rcv |
| // | | |
| // binder_transaction(id) | |
| // | | |
| // ``` |
| // |
| // or |
| // |
| // ``` |
| // Thread Snd Thread Rcv |
| // | | |
| // binder_transaction(id) | |
| // | | |
| // | binder_transaction_received(id) |
| // | | |
| // | binder_transaction(other_id, is_reply) |
| // | |
| // ``` |
| // |
| // In order to solve this problem (https://b.corp.google.com/issues/295124679), |
| // the tracker also understand commands and return commands. Binder commands are |
| // instructions that a userspace thread passes to the binder kernel driver (they |
| // all start with BC_), while binder return commands (they all start with BR_) |
| // are instructions that the binder kernel driver passes to the userspace |
| // thread. |
| // |
| // A synchronous transaction with commands and returns looks like this: |
| // |
| // ``` |
| // Thread Snd Thread Rcv |
| // | | |
| // binder_command(BC_TRANSACTION) | |
| // | | |
| // binder_transaction(id) | |
| // | | |
| // | binder_transaction_received(id) |
| // | | |
| // | binder_return(BR_TRANSACTION) |
| // | | |
| // | binder_command(BC_REPLY) |
| // | | |
| // | binder_transaction(other_id, is_reply) |
| // | | |
| // | binder_return(BR_TRANSACTION_COMPLETE) |
| // | | |
| // binder_return(BR_TRANSACTION_COMPLETE) | |
| // | | |
| // binder_transaction_received(other_id, is_reply) | |
| // | | |
| // binder_return(BR_REPLY) |
| // ``` |
| // |
| // For each thread, the tracker keeps a stack (since synchronous transactions |
| // can be nested). In case of failure, the tracker can observe special return |
| // commands (BR_DEAD_REPLY, BR_FROZEN_REPLY, ...): based on the state of the top |
| // of the stack it knows is it needs to terminate a slice. |
| // |
| // The tracking for commands and returns also tries to keep a correct stack, to |
| // avoid unbounded growth of the stack itself (even though it's internal only). |
| namespace perfetto { |
| namespace trace_processor { |
| |
| namespace { |
| constexpr int kOneWay = 0x01; |
| constexpr int kRootObject = 0x04; |
| constexpr int kStatusCode = 0x08; |
| constexpr int kAcceptFds = 0x10; |
| constexpr int kNoFlags = 0; |
| |
| std::string BinderFlagsToHuman(uint32_t flag) { |
| std::string str; |
| if (flag & kOneWay) { |
| str += "this is a one-way call: async, no return; "; |
| } |
| if (flag & kRootObject) { |
| str += "contents are the components root object; "; |
| } |
| if (flag & kStatusCode) { |
| str += "contents are a 32-bit status code; "; |
| } |
| if (flag & kAcceptFds) { |
| str += "allow replies with file descriptors; "; |
| } |
| if (flag == kNoFlags) { |
| str += "No Flags Set"; |
| } |
| return str; |
| } |
| |
| } // namespace |
| |
| enum BinderTracker::TxnFrame::State : uint32_t { |
| kSndAfterBC_TRANSACTION, |
| kSndAfterTransaction, |
| kSndAfterBR_TRANSACTION_COMPLETE, |
| kSndAfterTransactionReceived, |
| kRcvAfterTransactionReceived, |
| kRcvAfterBR_TRANSACTION, |
| kRcvAfterBC_REPLY, |
| kRcvAfterTransaction, |
| }; |
| |
| BinderTracker::BinderTracker(TraceProcessorContext* context) |
| : context_(context), |
| binder_category_id_(context->storage->InternString("binder")), |
| lock_waiting_id_(context->storage->InternString("binder lock waiting")), |
| lock_held_id_(context->storage->InternString("binder lock held")), |
| transaction_slice_id_( |
| context->storage->InternString("binder transaction")), |
| transaction_async_id_( |
| context->storage->InternString("binder transaction async")), |
| reply_id_(context->storage->InternString("binder reply")), |
| async_rcv_id_(context->storage->InternString("binder async rcv")), |
| transaction_id_(context->storage->InternString("transaction id")), |
| dest_node_(context->storage->InternString("destination node")), |
| dest_process_(context->storage->InternString("destination process")), |
| dest_thread_(context->storage->InternString("destination thread")), |
| dest_name_(context->storage->InternString("destination name")), |
| is_reply_(context->storage->InternString("reply transaction?")), |
| flags_(context->storage->InternString("flags")), |
| code_(context->storage->InternString("code")), |
| calling_tid_(context->storage->InternString("calling tid")), |
| data_size_(context->storage->InternString("data size")), |
| offsets_size_(context->storage->InternString("offsets size")) {} |
| |
| BinderTracker::~BinderTracker() = default; |
| |
| void BinderTracker::Transaction(int64_t ts, |
| uint32_t tid, |
| int32_t transaction_id, |
| int32_t dest_node, |
| uint32_t dest_tgid, |
| uint32_t dest_tid, |
| bool is_reply, |
| uint32_t flags, |
| StringId code) { |
| UniqueTid src_utid = context_->process_tracker->GetOrCreateThread(tid); |
| TrackId track_id = context_->track_tracker->InternThreadTrack(src_utid); |
| |
| auto args_inserter = [this, transaction_id, dest_node, dest_tgid, is_reply, |
| flags, code, |
| tid](ArgsTracker::BoundInserter* inserter) { |
| inserter->AddArg(transaction_id_, Variadic::Integer(transaction_id)); |
| inserter->AddArg(dest_node_, Variadic::Integer(dest_node)); |
| inserter->AddArg(dest_process_, Variadic::Integer(dest_tgid)); |
| inserter->AddArg(is_reply_, Variadic::Boolean(is_reply)); |
| std::string flag_str = |
| base::IntToHexString(flags) + " " + BinderFlagsToHuman(flags); |
| inserter->AddArg(flags_, Variadic::String(context_->storage->InternString( |
| base::StringView(flag_str)))); |
| inserter->AddArg(code_, Variadic::String(code)); |
| inserter->AddArg(calling_tid_, Variadic::UnsignedInteger(tid)); |
| }; |
| |
| bool is_oneway = (flags & kOneWay) == kOneWay; |
| auto insert_slice = [&]() { |
| if (is_reply) { |
| UniqueTid utid = context_->process_tracker->GetOrCreateThread( |
| static_cast<uint32_t>(dest_tid)); |
| auto dest_thread_name = context_->storage->thread_table().name()[utid]; |
| auto dest_args_inserter = [this, dest_tid, &dest_thread_name]( |
| ArgsTracker::BoundInserter* inserter) { |
| inserter->AddArg(dest_thread_, Variadic::Integer(dest_tid)); |
| if (dest_thread_name.has_value()) { |
| inserter->AddArg(dest_name_, Variadic::String(*dest_thread_name)); |
| } |
| }; |
| context_->slice_tracker->AddArgs(track_id, binder_category_id_, reply_id_, |
| dest_args_inserter); |
| return context_->slice_tracker->End(ts, track_id, kNullStringId, |
| kNullStringId, args_inserter); |
| } |
| if (is_oneway) { |
| return context_->slice_tracker->Scoped(ts, track_id, binder_category_id_, |
| transaction_async_id_, 0, |
| args_inserter); |
| } |
| return context_->slice_tracker->Begin(ts, track_id, binder_category_id_, |
| transaction_slice_id_, args_inserter); |
| }; |
| |
| OutstandingTransaction transaction; |
| transaction.is_reply = is_reply; |
| transaction.is_oneway = is_oneway; |
| transaction.args_inserter = args_inserter; |
| transaction.send_track_id = track_id; |
| transaction.send_slice_id = insert_slice(); |
| outstanding_transactions_.Insert(transaction_id, std::move(transaction)); |
| auto* frame = GetTidTopFrame(tid); |
| if (frame) { |
| if (frame->state == TxnFrame::kSndAfterBC_TRANSACTION) { |
| frame->state = TxnFrame::kSndAfterTransaction; |
| frame->txn_info = {is_oneway, is_reply}; |
| } else if (frame->state == TxnFrame::kRcvAfterBC_REPLY) { |
| frame->state = TxnFrame::kRcvAfterTransaction; |
| frame->txn_info = {is_oneway, is_reply}; |
| } else if (frame->state == TxnFrame::kRcvAfterTransactionReceived) { |
| // Probably command tracking is disabled. Let's remove the frame. |
| PopTidFrame(tid); |
| } |
| } |
| } |
| |
| void BinderTracker::TransactionReceived(int64_t ts, |
| uint32_t pid, |
| int32_t transaction_id) { |
| const OutstandingTransaction* opt_transaction = |
| outstanding_transactions_.Find(transaction_id); |
| if (!opt_transaction) { |
| // If we don't know what type of transaction it is, we don't know how to |
| // insert the slice. |
| // TODO(lalitm): maybe we should insert a dummy slice anyway - seems like |
| // a questionable idea to just ignore these completely. |
| return; |
| } |
| |
| OutstandingTransaction transaction(std::move(*opt_transaction)); |
| outstanding_transactions_.Erase(transaction_id); |
| |
| UniqueTid utid = context_->process_tracker->GetOrCreateThread(pid); |
| TrackId track_id = context_->track_tracker->InternThreadTrack(utid); |
| |
| // If it's a oneway transaction, there's no stack to track on the receiving |
| // side. |
| if (!transaction.is_oneway) { |
| if (!transaction.is_reply) { |
| TxnFrame* frame = PushTidFrame(pid); |
| frame->state = TxnFrame::kRcvAfterTransactionReceived; |
| frame->txn_info.emplace(); |
| frame->txn_info->is_oneway = transaction.is_oneway; |
| frame->txn_info->is_reply = transaction.is_reply; |
| } else { |
| TxnFrame* frame = GetTidTopFrame(pid); |
| if (frame && frame->state == TxnFrame::kSndAfterBR_TRANSACTION_COMPLETE) { |
| frame->state = TxnFrame::kSndAfterTransactionReceived; |
| } |
| } |
| } |
| |
| if (transaction.is_reply) { |
| // Simply end the slice started back when the first |expects_reply| |
| // transaction was sent. |
| context_->slice_tracker->End(ts, track_id); |
| return; |
| } |
| |
| std::optional<SliceId> recv_slice_id; |
| if (transaction.is_oneway) { |
| recv_slice_id = context_->slice_tracker->Scoped( |
| ts, track_id, binder_category_id_, async_rcv_id_, 0, |
| std::move(transaction.args_inserter)); |
| } else { |
| if (transaction.send_track_id) { |
| auto args_inserter = [this, utid, |
| pid](ArgsTracker::BoundInserter* inserter) { |
| inserter->AddArg(dest_thread_, Variadic::UnsignedInteger(pid)); |
| auto dest_thread_name = context_->storage->thread_table().name()[utid]; |
| if (dest_thread_name.has_value()) { |
| inserter->AddArg(dest_name_, Variadic::String(*dest_thread_name)); |
| } |
| }; |
| context_->slice_tracker->AddArgs(*transaction.send_track_id, |
| binder_category_id_, |
| transaction_slice_id_, args_inserter); |
| } |
| recv_slice_id = context_->slice_tracker->Begin( |
| ts, track_id, binder_category_id_, reply_id_); |
| } |
| |
| // Create a flow between the sending slice and this slice. |
| if (transaction.send_slice_id && recv_slice_id) { |
| context_->flow_tracker->InsertFlow(*transaction.send_slice_id, |
| *recv_slice_id); |
| } |
| } |
| |
| void BinderTracker::CommandToKernel(int64_t /*ts*/, |
| uint32_t tid, |
| uint32_t cmd) { |
| switch (cmd) { |
| case kBC_TRANSACTION: |
| case kBC_TRANSACTION_SG: { |
| TxnFrame* frame = PushTidFrame(tid); |
| frame->state = TxnFrame::kSndAfterBC_TRANSACTION; |
| break; |
| } |
| case kBC_REPLY: |
| case kBC_REPLY_SG: { |
| TxnFrame* frame = GetTidTopFrame(tid); |
| if (frame && frame->state == TxnFrame::kRcvAfterBR_TRANSACTION) { |
| frame->state = TxnFrame::kRcvAfterBC_REPLY; |
| } |
| break; |
| } |
| default: |
| break; |
| } |
| } |
| |
| void BinderTracker::ReturnFromKernel(int64_t ts, uint32_t tid, uint32_t cmd) { |
| switch (cmd) { |
| case kBR_DEAD_REPLY: |
| case kBR_FAILED_REPLY: |
| case kBR_FROZEN_REPLY: |
| case kBR_TRANSACTION_PENDING_FROZEN: { |
| TxnFrame* frame = GetTidTopFrame(tid); |
| if (frame) { |
| switch (frame->state) { |
| case TxnFrame::kSndAfterBC_TRANSACTION: |
| // The transaction has failed before we received the |
| // binder_transaction event, therefore no slice has been opened. |
| PopTidFrame(tid); |
| break; |
| case TxnFrame::kRcvAfterBC_REPLY: |
| case TxnFrame::kSndAfterTransaction: |
| case TxnFrame::kRcvAfterTransaction: |
| case TxnFrame::kSndAfterBR_TRANSACTION_COMPLETE: |
| if (frame->txn_info.has_value()) { |
| if (!frame->txn_info->is_oneway && !frame->txn_info->is_reply) { |
| UniqueTid utid = |
| context_->process_tracker->GetOrCreateThread(tid); |
| TrackId track_id = |
| context_->track_tracker->InternThreadTrack(utid); |
| context_->slice_tracker->End(ts, track_id); |
| } |
| } |
| PopTidFrame(tid); |
| break; |
| case TxnFrame::kSndAfterTransactionReceived: |
| case TxnFrame::kRcvAfterTransactionReceived: |
| case TxnFrame::kRcvAfterBR_TRANSACTION: |
| break; |
| } |
| } |
| break; |
| } |
| |
| case kBR_TRANSACTION_COMPLETE: |
| case kBR_ONEWAY_SPAM_SUSPECT: { |
| TxnFrame* frame = GetTidTopFrame(tid); |
| if (frame) { |
| if (frame->state == TxnFrame::kRcvAfterTransaction) { |
| PopTidFrame(tid); |
| } else if (frame->state == TxnFrame::kSndAfterBC_TRANSACTION) { |
| // The transaction has failed before we received the |
| // binder_transaction event, therefore no slice has been opened. |
| // It's possible that the binder_transaction event was not enabled. |
| PopTidFrame(tid); |
| } else if (frame->state == TxnFrame::kSndAfterTransaction) { |
| if (frame->txn_info.has_value() && !frame->txn_info->is_oneway) { |
| frame->state = TxnFrame::kSndAfterBR_TRANSACTION_COMPLETE; |
| } else { |
| // For a oneway transaction, this is the last event. In any case, no |
| // slice has been opened. |
| PopTidFrame(tid); |
| } |
| } |
| } |
| break; |
| } |
| |
| case kBR_REPLY: { |
| TxnFrame* frame = GetTidTopFrame(tid); |
| if (frame && frame->state == TxnFrame::kSndAfterTransactionReceived) { |
| // For a synchronous transaction, this is the last event. |
| PopTidFrame(tid); |
| } |
| break; |
| } |
| |
| case kBR_TRANSACTION: |
| case kBR_TRANSACTION_SEC_CTX: { |
| TxnFrame* frame = GetTidTopFrame(tid); |
| if (frame) { |
| if (frame->state == TxnFrame::kRcvAfterTransactionReceived) { |
| frame->state = TxnFrame::kRcvAfterBR_TRANSACTION; |
| } |
| } |
| break; |
| } |
| |
| default: |
| break; |
| } |
| } |
| |
| void BinderTracker::Lock(int64_t ts, uint32_t pid) { |
| attempt_lock_[pid] = ts; |
| |
| UniqueTid utid = context_->process_tracker->GetOrCreateThread(pid); |
| TrackId track_id = context_->track_tracker->InternThreadTrack(utid); |
| context_->slice_tracker->Begin(ts, track_id, binder_category_id_, |
| lock_waiting_id_); |
| } |
| |
| void BinderTracker::Locked(int64_t ts, uint32_t pid) { |
| UniqueTid utid = context_->process_tracker->GetOrCreateThread(pid); |
| |
| if (!attempt_lock_.Find(pid)) |
| return; |
| |
| TrackId track_id = context_->track_tracker->InternThreadTrack(utid); |
| context_->slice_tracker->End(ts, track_id); |
| context_->slice_tracker->Begin(ts, track_id, binder_category_id_, |
| lock_held_id_); |
| |
| lock_acquired_[pid] = ts; |
| attempt_lock_.Erase(pid); |
| } |
| |
| void BinderTracker::Unlock(int64_t ts, uint32_t pid) { |
| UniqueTid utid = context_->process_tracker->GetOrCreateThread(pid); |
| |
| if (!lock_acquired_.Find(pid)) |
| return; |
| |
| TrackId track_id = context_->track_tracker->InternThreadTrack(utid); |
| context_->slice_tracker->End(ts, track_id, binder_category_id_, |
| lock_held_id_); |
| lock_acquired_.Erase(pid); |
| } |
| |
| void BinderTracker::TransactionAllocBuf(int64_t ts, |
| uint32_t pid, |
| uint64_t data_size, |
| uint64_t offsets_size) { |
| UniqueTid utid = context_->process_tracker->GetOrCreateThread(pid); |
| TrackId track_id = context_->track_tracker->InternThreadTrack(utid); |
| |
| auto args_inserter = [this, &data_size, |
| offsets_size](ArgsTracker::BoundInserter* inserter) { |
| inserter->AddArg(data_size_, Variadic::UnsignedInteger(data_size)); |
| inserter->AddArg(offsets_size_, Variadic::UnsignedInteger(offsets_size)); |
| }; |
| context_->slice_tracker->AddArgs(track_id, binder_category_id_, |
| transaction_slice_id_, args_inserter); |
| |
| base::ignore_result(ts); |
| } |
| |
| BinderTracker::TxnFrame* BinderTracker::GetTidTopFrame(uint32_t tid) { |
| UniqueTid utid = context_->process_tracker->GetOrCreateThread(tid); |
| std::stack<BinderTracker::TxnFrame>* stack = utid_stacks_.Find(utid); |
| if (stack == nullptr || stack->empty()) { |
| return nullptr; |
| } |
| return &stack->top(); |
| } |
| |
| BinderTracker::TxnFrame* BinderTracker::PushTidFrame(uint32_t tid) { |
| UniqueTid utid = context_->process_tracker->GetOrCreateThread(tid); |
| auto& stack = utid_stacks_[utid]; |
| stack.push({}); |
| return &stack.top(); |
| } |
| |
| void BinderTracker::PopTidFrame(uint32_t tid) { |
| UniqueTid utid = context_->process_tracker->GetOrCreateThread(tid); |
| std::stack<BinderTracker::TxnFrame>* stack = utid_stacks_.Find(utid); |
| PERFETTO_CHECK(stack); |
| stack->pop(); |
| if (stack->empty()) { |
| utid_stacks_.Erase(utid); |
| } |
| } |
| |
| } // namespace trace_processor |
| } // namespace perfetto |
