xref: /aosp_15_r20/external/perfetto/src/trace_processor/importers/ftrace/binder_tracker.cc (revision 6dbdd20afdafa5e3ca9b8809fa73465d530080dc)
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