1 /*
2 * Copyright (C) 2019 The Android Open Source Project
3 *
4 * Licensed under the Apache License, Version 2.0 (the "License");
5 * you may not use this file except in compliance with the License.
6 * You may obtain a copy of the License at
7 *
8 * http://www.apache.org/licenses/LICENSE-2.0
9 *
10 * Unless required by applicable law or agreed to in writing, software
11 * distributed under the License is distributed on an "AS IS" BASIS,
12 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
13 * See the License for the specific language governing permissions and
14 * limitations under the License.
15 */
16
17 #include "src/trace_processor/importers/ftrace/binder_tracker.h"
18 #include <cstdint>
19 #include <optional>
20 #include <string>
21 #include <utility>
22 #include "perfetto/base/compiler.h"
23 #include "perfetto/ext/base/string_utils.h"
24 #include "perfetto/ext/base/string_view.h"
25 #include "src/trace_processor/importers/common/flow_tracker.h"
26 #include "src/trace_processor/importers/common/process_tracker.h"
27 #include "src/trace_processor/importers/common/slice_tracker.h"
28 #include "src/trace_processor/importers/common/track_tracker.h"
29 #include "src/trace_processor/storage/trace_storage.h"
30 #include "src/trace_processor/types/trace_processor_context.h"
31 #include "src/trace_processor/types/variadic.h"
32
33 // Binder tracker: displays slices for binder transactions and other operations.
34 // =============================================================================
35 //
36 // Supported events
37 // ----------------
38 // # Transactions
39 //
40 // * binder/binder_transaction
41 // * binder/binder_transaction_reply
42 //
43 // With these two events the tracker can display slices for binder transactions
44 // in the sending and receiving threads. Rarely, when transactions fail in some
45 // way, it's possible that the tracker doesn't have enough information to
46 // properly terminate slices. See "Commands" below for a solution.
47 //
48 // # Buffer allocations
49 //
50 // * binder/binder_transaction_alloc_buf
51 //
52 // This annotates the transaction slices (from the above events) with info about
53 // allocations. The event alone doesn't make sense without the "Transactions"
54 // events.
55 //
56 // # Commands
57 //
58 // * binder/binder_command
59 // * binder/binder_return
60 //
61 // These two events are only useful in conjunction with the "Transactions"
62 // events. Their presence allow the tracker to terminate slices more reliably
63 // when a transaction fails.
64 //
65 // # Locking
66 //
67 // * binder/binder_lock
68 // * binder/binder_locked
69 // * binder/binder_unlock
70 //
71 // Obsolete: this was removed from kernel v4.14
72 //
73 // Implementation details
74 // ----------------------
75 //
76 // # Basic transaction tracking:
77 //
78 // For each transaction, two threads are involved.
79 //
80 // A oneway (aka asynchronous) transaction has these events:
81 //
82 // ```
83 // Thread Snd Thread Rcv
84 // | |
85 // binder_transaction(id, is_oneway) |
86 // |
87 // binder_transaction_received(id)
88 // ```
89 //
90 // The tracker will create one instant events one each thread.
91 //
92 // A regular (aka synchronous) transaction has these events:
93 //
94 // ```
95 // Thread Snd Thread Rcv
96 // | |
97 // binder_transaction(id) |
98 // | |
99 // | binder_transaction_received(id)
100 // | |
101 // | binder_transaction(other_id, is_reply)
102 // |
103 // binder_transaction_received(other_id, is_reply)
104 // ```
105 //
106 // The tracker will create a "binder transaction" slice on Thread 1 and a
107 // "binder reply" slice on Thread 2.
108 //
109 // synchronous transactions can be nested: inside a "binder reply", a thread can
110 // make a binder transaction to another thread (just regular synchronous
111 // function calls).
112 //
113 // If a regular transaction fails, the kernel will not emit some events, causing
114 // the tracker to leave some slices open forever, while the threads are actually
115 // not working on the transaction anymore.
116 //
117 // ```
118 // Thread Snd Thread Rcv
119 // | |
120 // binder_transaction(id) |
121 // | |
122 // ```
123 //
124 // or
125 //
126 // ```
127 // Thread Snd Thread Rcv
128 // | |
129 // binder_transaction(id) |
130 // | |
131 // | binder_transaction_received(id)
132 // | |
133 // | binder_transaction(other_id, is_reply)
134 // |
135 // ```
136 //
137 // In order to solve this problem (https://b.corp.google.com/issues/295124679),
138 // the tracker also understand commands and return commands. Binder commands are
139 // instructions that a userspace thread passes to the binder kernel driver (they
140 // all start with BC_), while binder return commands (they all start with BR_)
141 // are instructions that the binder kernel driver passes to the userspace
142 // thread.
143 //
144 // A synchronous transaction with commands and returns looks like this:
145 //
146 // ```
147 // Thread Snd Thread Rcv
148 // | |
149 // binder_command(BC_TRANSACTION) |
150 // | |
151 // binder_transaction(id) |
152 // | |
153 // | binder_transaction_received(id)
154 // | |
155 // | binder_return(BR_TRANSACTION)
156 // | |
157 // | binder_command(BC_REPLY)
158 // | |
159 // | binder_transaction(other_id, is_reply)
160 // | |
161 // | binder_return(BR_TRANSACTION_COMPLETE)
162 // | |
163 // binder_return(BR_TRANSACTION_COMPLETE) |
164 // | |
165 // binder_transaction_received(other_id, is_reply) |
166 // | |
167 // binder_return(BR_REPLY)
168 // ```
169 //
170 // For each thread, the tracker keeps a stack (since synchronous transactions
171 // can be nested). In case of failure, the tracker can observe special return
172 // commands (BR_DEAD_REPLY, BR_FROZEN_REPLY, ...): based on the state of the top
173 // of the stack it knows is it needs to terminate a slice.
174 //
175 // The tracking for commands and returns also tries to keep a correct stack, to
176 // avoid unbounded growth of the stack itself (even though it's internal only).
177 namespace perfetto {
178 namespace trace_processor {
179
180 namespace {
181 constexpr int kOneWay = 0x01;
182 constexpr int kRootObject = 0x04;
183 constexpr int kStatusCode = 0x08;
184 constexpr int kAcceptFds = 0x10;
185 constexpr int kNoFlags = 0;
186
BinderFlagsToHuman(uint32_t flag)187 std::string BinderFlagsToHuman(uint32_t flag) {
188 std::string str;
189 if (flag & kOneWay) {
190 str += "this is a one-way call: async, no return; ";
191 }
192 if (flag & kRootObject) {
193 str += "contents are the components root object; ";
194 }
195 if (flag & kStatusCode) {
196 str += "contents are a 32-bit status code; ";
197 }
198 if (flag & kAcceptFds) {
199 str += "allow replies with file descriptors; ";
200 }
201 if (flag == kNoFlags) {
202 str += "No Flags Set";
203 }
204 return str;
205 }
206
207 } // namespace
208
209 enum BinderTracker::TxnFrame::State : uint32_t {
210 kSndAfterBC_TRANSACTION,
211 kSndAfterTransaction,
212 kSndAfterBR_TRANSACTION_COMPLETE,
213 kSndAfterTransactionReceived,
214 kRcvAfterTransactionReceived,
215 kRcvAfterBR_TRANSACTION,
216 kRcvAfterBC_REPLY,
217 kRcvAfterTransaction,
218 };
219
BinderTracker(TraceProcessorContext * context)220 BinderTracker::BinderTracker(TraceProcessorContext* context)
221 : context_(context),
222 binder_category_id_(context->storage->InternString("binder")),
223 lock_waiting_id_(context->storage->InternString("binder lock waiting")),
224 lock_held_id_(context->storage->InternString("binder lock held")),
225 transaction_slice_id_(
226 context->storage->InternString("binder transaction")),
227 transaction_async_id_(
228 context->storage->InternString("binder transaction async")),
229 reply_id_(context->storage->InternString("binder reply")),
230 async_rcv_id_(context->storage->InternString("binder async rcv")),
231 transaction_id_(context->storage->InternString("transaction id")),
232 dest_node_(context->storage->InternString("destination node")),
233 dest_process_(context->storage->InternString("destination process")),
234 dest_thread_(context->storage->InternString("destination thread")),
235 dest_name_(context->storage->InternString("destination name")),
236 is_reply_(context->storage->InternString("reply transaction?")),
237 flags_(context->storage->InternString("flags")),
238 code_(context->storage->InternString("code")),
239 calling_tid_(context->storage->InternString("calling tid")),
240 data_size_(context->storage->InternString("data size")),
241 offsets_size_(context->storage->InternString("offsets size")) {}
242
243 BinderTracker::~BinderTracker() = default;
244
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)245 void BinderTracker::Transaction(int64_t ts,
246 uint32_t tid,
247 int32_t transaction_id,
248 int32_t dest_node,
249 uint32_t dest_tgid,
250 uint32_t dest_tid,
251 bool is_reply,
252 uint32_t flags,
253 StringId code) {
254 UniqueTid src_utid = context_->process_tracker->GetOrCreateThread(tid);
255 TrackId track_id = context_->track_tracker->InternThreadTrack(src_utid);
256
257 auto args_inserter = [this, transaction_id, dest_node, dest_tgid, is_reply,
258 flags, code,
259 tid](ArgsTracker::BoundInserter* inserter) {
260 inserter->AddArg(transaction_id_, Variadic::Integer(transaction_id));
261 inserter->AddArg(dest_node_, Variadic::Integer(dest_node));
262 inserter->AddArg(dest_process_, Variadic::Integer(dest_tgid));
263 inserter->AddArg(is_reply_, Variadic::Boolean(is_reply));
264 std::string flag_str =
265 base::IntToHexString(flags) + " " + BinderFlagsToHuman(flags);
266 inserter->AddArg(flags_, Variadic::String(context_->storage->InternString(
267 base::StringView(flag_str))));
268 inserter->AddArg(code_, Variadic::String(code));
269 inserter->AddArg(calling_tid_, Variadic::UnsignedInteger(tid));
270 };
271
272 bool is_oneway = (flags & kOneWay) == kOneWay;
273 auto insert_slice = [&]() {
274 if (is_reply) {
275 UniqueTid utid = context_->process_tracker->GetOrCreateThread(
276 static_cast<uint32_t>(dest_tid));
277 auto dest_thread_name = context_->storage->thread_table()[utid].name();
278 auto dest_args_inserter = [this, dest_tid, &dest_thread_name](
279 ArgsTracker::BoundInserter* inserter) {
280 inserter->AddArg(dest_thread_, Variadic::Integer(dest_tid));
281 if (dest_thread_name.has_value()) {
282 inserter->AddArg(dest_name_, Variadic::String(*dest_thread_name));
283 }
284 };
285 context_->slice_tracker->AddArgs(track_id, binder_category_id_, reply_id_,
286 dest_args_inserter);
287 return context_->slice_tracker->End(ts, track_id, kNullStringId,
288 kNullStringId, args_inserter);
289 }
290 if (is_oneway) {
291 return context_->slice_tracker->Scoped(ts, track_id, binder_category_id_,
292 transaction_async_id_, 0,
293 args_inserter);
294 }
295 return context_->slice_tracker->Begin(ts, track_id, binder_category_id_,
296 transaction_slice_id_, args_inserter);
297 };
298
299 OutstandingTransaction transaction;
300 transaction.is_reply = is_reply;
301 transaction.is_oneway = is_oneway;
302 transaction.args_inserter = args_inserter;
303 transaction.send_track_id = track_id;
304 transaction.send_slice_id = insert_slice();
305 outstanding_transactions_[transaction_id] = std::move(transaction);
306 auto* frame = GetTidTopFrame(tid);
307 if (frame) {
308 if (frame->state == TxnFrame::kSndAfterBC_TRANSACTION) {
309 frame->state = TxnFrame::kSndAfterTransaction;
310 frame->txn_info = {is_oneway, is_reply};
311 } else if (frame->state == TxnFrame::kRcvAfterBC_REPLY) {
312 frame->state = TxnFrame::kRcvAfterTransaction;
313 frame->txn_info = {is_oneway, is_reply};
314 } else if (frame->state == TxnFrame::kRcvAfterTransactionReceived) {
315 // Probably command tracking is disabled. Let's remove the frame.
316 PopTidFrame(tid);
317 }
318 }
319 }
320
TransactionReceived(int64_t ts,uint32_t pid,int32_t transaction_id)321 void BinderTracker::TransactionReceived(int64_t ts,
322 uint32_t pid,
323 int32_t transaction_id) {
324 auto it = outstanding_transactions_.find(transaction_id);
325 if (it == outstanding_transactions_.end()) {
326 // If we don't know what type of transaction it is, we don't know how to
327 // insert the slice.
328 // TODO(lalitm): maybe we should insert a dummy slice anyway - seems like
329 // a questionable idea to just ignore these completely.
330 return;
331 }
332 OutstandingTransaction transaction(std::move(it->second));
333 outstanding_transactions_.erase(it);
334
335 UniqueTid utid = context_->process_tracker->GetOrCreateThread(pid);
336 TrackId track_id = context_->track_tracker->InternThreadTrack(utid);
337
338 // If it's a oneway transaction, there's no stack to track on the receiving
339 // side.
340 if (!transaction.is_oneway) {
341 if (!transaction.is_reply) {
342 TxnFrame* frame = PushTidFrame(pid);
343 frame->state = TxnFrame::kRcvAfterTransactionReceived;
344 frame->txn_info.emplace();
345 frame->txn_info->is_oneway = transaction.is_oneway;
346 frame->txn_info->is_reply = transaction.is_reply;
347 } else {
348 TxnFrame* frame = GetTidTopFrame(pid);
349 if (frame && frame->state == TxnFrame::kSndAfterBR_TRANSACTION_COMPLETE) {
350 frame->state = TxnFrame::kSndAfterTransactionReceived;
351 }
352 }
353 }
354
355 if (transaction.is_reply) {
356 // Simply end the slice started back when the first |expects_reply|
357 // transaction was sent.
358 context_->slice_tracker->End(ts, track_id);
359 return;
360 }
361
362 std::optional<SliceId> recv_slice_id;
363 if (transaction.is_oneway) {
364 recv_slice_id = context_->slice_tracker->Scoped(
365 ts, track_id, binder_category_id_, async_rcv_id_, 0,
366 std::move(transaction.args_inserter));
367 } else {
368 if (transaction.send_track_id) {
369 auto args_inserter = [this, utid,
370 pid](ArgsTracker::BoundInserter* inserter) {
371 inserter->AddArg(dest_thread_, Variadic::UnsignedInteger(pid));
372 auto dest_thread_name = context_->storage->thread_table()[utid].name();
373 if (dest_thread_name.has_value()) {
374 inserter->AddArg(dest_name_, Variadic::String(*dest_thread_name));
375 }
376 };
377 context_->slice_tracker->AddArgs(*transaction.send_track_id,
378 binder_category_id_,
379 transaction_slice_id_, args_inserter);
380 }
381 recv_slice_id = context_->slice_tracker->Begin(
382 ts, track_id, binder_category_id_, reply_id_);
383 }
384
385 // Create a flow between the sending slice and this slice.
386 if (transaction.send_slice_id && recv_slice_id) {
387 context_->flow_tracker->InsertFlow(*transaction.send_slice_id,
388 *recv_slice_id);
389 }
390 }
391
CommandToKernel(int64_t,uint32_t tid,uint32_t cmd)392 void BinderTracker::CommandToKernel(int64_t /*ts*/,
393 uint32_t tid,
394 uint32_t cmd) {
395 switch (cmd) {
396 case kBC_TRANSACTION:
397 case kBC_TRANSACTION_SG: {
398 TxnFrame* frame = PushTidFrame(tid);
399 frame->state = TxnFrame::kSndAfterBC_TRANSACTION;
400 break;
401 }
402 case kBC_REPLY:
403 case kBC_REPLY_SG: {
404 TxnFrame* frame = GetTidTopFrame(tid);
405 if (frame && frame->state == TxnFrame::kRcvAfterBR_TRANSACTION) {
406 frame->state = TxnFrame::kRcvAfterBC_REPLY;
407 }
408 break;
409 }
410 default:
411 break;
412 }
413 }
414
ReturnFromKernel(int64_t ts,uint32_t tid,uint32_t cmd)415 void BinderTracker::ReturnFromKernel(int64_t ts, uint32_t tid, uint32_t cmd) {
416 switch (cmd) {
417 case kBR_DEAD_REPLY:
418 case kBR_FAILED_REPLY:
419 case kBR_FROZEN_REPLY:
420 case kBR_TRANSACTION_PENDING_FROZEN: {
421 TxnFrame* frame = GetTidTopFrame(tid);
422 if (frame) {
423 switch (frame->state) {
424 case TxnFrame::kSndAfterBC_TRANSACTION:
425 // The transaction has failed before we received the
426 // binder_transaction event, therefore no slice has been opened.
427 PopTidFrame(tid);
428 break;
429 case TxnFrame::kRcvAfterBC_REPLY:
430 case TxnFrame::kSndAfterTransaction:
431 case TxnFrame::kRcvAfterTransaction:
432 case TxnFrame::kSndAfterBR_TRANSACTION_COMPLETE:
433 if (frame->txn_info.has_value()) {
434 if (!frame->txn_info->is_oneway && !frame->txn_info->is_reply) {
435 UniqueTid utid =
436 context_->process_tracker->GetOrCreateThread(tid);
437 TrackId track_id =
438 context_->track_tracker->InternThreadTrack(utid);
439 context_->slice_tracker->End(ts, track_id);
440 }
441 }
442 PopTidFrame(tid);
443 break;
444 case TxnFrame::kSndAfterTransactionReceived:
445 case TxnFrame::kRcvAfterTransactionReceived:
446 case TxnFrame::kRcvAfterBR_TRANSACTION:
447 break;
448 }
449 }
450 break;
451 }
452
453 case kBR_TRANSACTION_COMPLETE:
454 case kBR_ONEWAY_SPAM_SUSPECT: {
455 TxnFrame* frame = GetTidTopFrame(tid);
456 if (frame) {
457 if (frame->state == TxnFrame::kRcvAfterTransaction) {
458 PopTidFrame(tid);
459 } else if (frame->state == TxnFrame::kSndAfterBC_TRANSACTION) {
460 // The transaction has failed before we received the
461 // binder_transaction event, therefore no slice has been opened.
462 // It's possible that the binder_transaction event was not enabled.
463 PopTidFrame(tid);
464 } else if (frame->state == TxnFrame::kSndAfterTransaction) {
465 if (frame->txn_info.has_value() && !frame->txn_info->is_oneway) {
466 frame->state = TxnFrame::kSndAfterBR_TRANSACTION_COMPLETE;
467 } else {
468 // For a oneway transaction, this is the last event. In any case, no
469 // slice has been opened.
470 PopTidFrame(tid);
471 }
472 }
473 }
474 break;
475 }
476
477 case kBR_REPLY: {
478 TxnFrame* frame = GetTidTopFrame(tid);
479 if (frame && frame->state == TxnFrame::kSndAfterTransactionReceived) {
480 // For a synchronous transaction, this is the last event.
481 PopTidFrame(tid);
482 }
483 break;
484 }
485
486 case kBR_TRANSACTION:
487 case kBR_TRANSACTION_SEC_CTX: {
488 TxnFrame* frame = GetTidTopFrame(tid);
489 if (frame) {
490 if (frame->state == TxnFrame::kRcvAfterTransactionReceived) {
491 frame->state = TxnFrame::kRcvAfterBR_TRANSACTION;
492 }
493 }
494 break;
495 }
496
497 default:
498 break;
499 }
500 }
501
Lock(int64_t ts,uint32_t pid)502 void BinderTracker::Lock(int64_t ts, uint32_t pid) {
503 attempt_lock_[pid] = ts;
504
505 UniqueTid utid = context_->process_tracker->GetOrCreateThread(pid);
506 TrackId track_id = context_->track_tracker->InternThreadTrack(utid);
507 context_->slice_tracker->Begin(ts, track_id, binder_category_id_,
508 lock_waiting_id_);
509 }
510
Locked(int64_t ts,uint32_t pid)511 void BinderTracker::Locked(int64_t ts, uint32_t pid) {
512 UniqueTid utid = context_->process_tracker->GetOrCreateThread(pid);
513
514 if (!attempt_lock_.Find(pid))
515 return;
516
517 TrackId track_id = context_->track_tracker->InternThreadTrack(utid);
518 context_->slice_tracker->End(ts, track_id);
519 context_->slice_tracker->Begin(ts, track_id, binder_category_id_,
520 lock_held_id_);
521
522 lock_acquired_[pid] = ts;
523 attempt_lock_.Erase(pid);
524 }
525
Unlock(int64_t ts,uint32_t pid)526 void BinderTracker::Unlock(int64_t ts, uint32_t pid) {
527 UniqueTid utid = context_->process_tracker->GetOrCreateThread(pid);
528
529 if (!lock_acquired_.Find(pid))
530 return;
531
532 TrackId track_id = context_->track_tracker->InternThreadTrack(utid);
533 context_->slice_tracker->End(ts, track_id, binder_category_id_,
534 lock_held_id_);
535 lock_acquired_.Erase(pid);
536 }
537
TransactionAllocBuf(int64_t ts,uint32_t pid,uint64_t data_size,uint64_t offsets_size)538 void BinderTracker::TransactionAllocBuf(int64_t ts,
539 uint32_t pid,
540 uint64_t data_size,
541 uint64_t offsets_size) {
542 UniqueTid utid = context_->process_tracker->GetOrCreateThread(pid);
543 TrackId track_id = context_->track_tracker->InternThreadTrack(utid);
544
545 auto args_inserter = [this, &data_size,
546 offsets_size](ArgsTracker::BoundInserter* inserter) {
547 inserter->AddArg(data_size_, Variadic::UnsignedInteger(data_size));
548 inserter->AddArg(offsets_size_, Variadic::UnsignedInteger(offsets_size));
549 };
550 context_->slice_tracker->AddArgs(track_id, binder_category_id_,
551 transaction_slice_id_, args_inserter);
552
553 base::ignore_result(ts);
554 }
555
GetTidTopFrame(uint32_t tid)556 BinderTracker::TxnFrame* BinderTracker::GetTidTopFrame(uint32_t tid) {
557 UniqueTid utid = context_->process_tracker->GetOrCreateThread(tid);
558 std::stack<BinderTracker::TxnFrame>* stack = utid_stacks_.Find(utid);
559 if (stack == nullptr || stack->empty()) {
560 return nullptr;
561 }
562 return &stack->top();
563 }
564
PushTidFrame(uint32_t tid)565 BinderTracker::TxnFrame* BinderTracker::PushTidFrame(uint32_t tid) {
566 UniqueTid utid = context_->process_tracker->GetOrCreateThread(tid);
567 auto& stack = utid_stacks_[utid];
568 stack.push({});
569 return &stack.top();
570 }
571
PopTidFrame(uint32_t tid)572 void BinderTracker::PopTidFrame(uint32_t tid) {
573 UniqueTid utid = context_->process_tracker->GetOrCreateThread(tid);
574 std::stack<BinderTracker::TxnFrame>* stack = utid_stacks_.Find(utid);
575 PERFETTO_CHECK(stack);
576 stack->pop();
577 if (stack->empty()) {
578 utid_stacks_.Erase(utid);
579 }
580 }
581
582 } // namespace trace_processor
583 } // namespace perfetto
584