msa/EventProcessing.hpp

   1 //
   2 //  EventProcessing.hpp
   3 //  msa
   4 //
   5 //  Created by James McIlree on 2/5/14.
   6 //  Copyright (c) 2014 Apple. All rights reserved.
   7 //
   8
   9 #ifndef msa_EventProcessing_hpp
  10 #define msa_EventProcessing_hpp
  11
  12 template <typename SIZE>
  13 bool is_mach_msg_interesting(const Machine<SIZE>& machine, const MachineMachMsg<SIZE>* mach_msg)
  14 {
  15         // If this message is carrying importance, it is interesting.
  16         if ((mach_msg->has_sender() && MACH_MSGH_BITS_RAISED_IMPORTANCE(mach_msg->send_msgh_bits())) ||
  17             (mach_msg->has_receiver() && MACH_MSGH_BITS_RAISED_IMPORTANCE(mach_msg->recv_msgh_bits())))
  18                 return true;
  19
  20         // If this message has a non-null voucher, it is interesting.
  21         if ((mach_msg->has_sender() && !mach_msg->send_voucher()->is_null()) ||
  22             (mach_msg->has_receiver() && !mach_msg->recv_voucher()->is_null()))
  23                 return true;
  24
  25         // If the message does NOT have a voucher, and the sender has a voucher set, it is interesting.
  26         if (mach_msg->has_sender()) {
  27                 if (const MachineThread<SIZE>* sender_thread = machine.thread(mach_msg->send_tid(), mach_msg->send_time())) {
  28                         const MachineVoucher<SIZE>* sender_voucher = sender_thread->voucher(mach_msg->send_time());
  29                         if (!sender_voucher->is_unset() && !sender_voucher->is_null()) {
  30                                 return true;
  31                         }
  32                 }
  33         }
  34
  35         return false;
  36 }
  37
  38 template <typename SIZE>
  39 void reset_task_data_on_exec_or_exit(const MachineProcess<SIZE>& process,
  40                                      std::unordered_map<pid_t, bool>& task_appnap_state,
  41                                      std::unordered_map<pid_t, TaskRequestedPolicy>& task_requested_state,
  42                                      std::unordered_map<pid_t, std::pair<TaskEffectivePolicy, uint32_t>>& task_effective_state,
  43                                      std::unordered_map<pid_t, std::pair<uint32_t, uint32_t>>& task_boosts)
  44 {
  45         ASSERT(!process.is_kernel(), "Kernel process should not ever exec or exit");
  46         ASSERT(process.pid() > 0, "Process with pid less than 1 exec'd ?");
  47
  48         if (pid_t pid = process.pid()) {
  49                 auto task_appnap_it = task_appnap_state.find(pid);
  50                 if (task_appnap_it != task_appnap_state.end()) {
  51                         task_appnap_state.erase(task_appnap_it);
  52                 }
  53
  54                 auto task_requested_it = task_requested_state.find(pid);
  55                 if (task_requested_it != task_requested_state.end()) {
  56                         task_requested_state.erase(task_requested_it);
  57                 }
  58
  59                 auto task_effective_it = task_effective_state.find(pid);
  60                 if (task_effective_it != task_effective_state.end()) {
  61                         task_effective_state.erase(task_effective_it);
  62                 }
  63
  64                 auto task_boosts_it = task_boosts.find(pid);
  65                 if (task_boosts_it != task_boosts.end()) {
  66                         task_boosts.erase(task_boosts_it);
  67                 }
  68         }
  69 }
  70
  71 // From osfmk/kern/task.h
  72 #define TASK_POLICY_INTERNAL            0x0
  73 #define TASK_POLICY_EXTERNAL            0x1
  74
  75 #define TASK_POLICY_TASK                0x4
  76 #define TASK_POLICY_THREAD              0x8
  77
  78 template <typename SIZE>
  79 void process_events(Globals& globals,
  80                     const Machine<SIZE>& machine,
  81                     std::unordered_map<pid_t, bool>& task_appnap_state,
  82                     std::unordered_map<pid_t, TaskRequestedPolicy>& task_requested_state,
  83                     std::unordered_map<typename SIZE::ptr_t, TaskRequestedPolicy>& thread_requested_state,
  84                     std::unordered_map<pid_t, std::pair<TaskEffectivePolicy, uint32_t>>& task_effective_state,
  85                     std::unordered_map<typename SIZE::ptr_t, std::pair<TaskEffectivePolicy, uint32_t>>& thread_effective_state,
  86                     std::unordered_map<pid_t, std::pair<uint32_t, uint32_t>>& task_boosts)
  87 {
  88         const KDEvent<SIZE>* events = machine.events();
  89         uintptr_t count = machine.event_count();
  90
  91         ASSERT(count, "Expected at least one event");
  92
  93         //
  94         // Filtering thoughts...
  95         //
  96         // Two levels of filtering.
  97         //
  98         // 1) global supression of events that are "uninteresting".
  99         //
 100         // We filter on each event "class", with a keyword, so something like
 101         //
 102         // --lifecycle [ all | user | none ]                    ;; This is fork, exec, exit, thread-create, thread-exit
 103         // --mach-msgs [ all | user | voucher | none ]          ;; This is all mach msgs
 104         //
 105         // 2) targetted supression of events that are not related to a user focus.
 106         //
 107         // We filter by process name/pid
 108         //
 109         // --track [ pid | name ]
 110         //
 111
 112         PrintBuffer print_buffer(8192, 1024, globals.output_fd());
 113
 114         for (uintptr_t index=0; index < count; ++index) {
 115                 const KDEvent<SIZE>& event = events[index];
 116
 117                 //
 118                 // Printing ...
 119                 //
 120
 121                 switch (event.dbg_cooked()) {
 122                         case TRACE_DATA_EXEC: {
 123                                 bool should_print = false;
 124                                 if (globals.lifecycle_filter() >= kLifecycleFilter::User)
 125                                         should_print = true;
 126
 127                                 if (should_print)
 128                                         print_generic(print_buffer, globals, machine, event, index, "exec");
 129
 130                                 if (const MachineThread<SIZE>* exec_thread = machine.thread(event.tid(), event.timestamp())) {
 131                                         reset_task_data_on_exec_or_exit(exec_thread->process(), task_appnap_state, task_requested_state, task_effective_state, task_boosts);
 132                                 }
 133                                 break;
 134                         }
 135
 136                         case TRACE_DATA_NEWTHREAD: {
 137                                 bool should_print = false;
 138                                 auto new_thread_tid = (typename SIZE::ptr_t)event.arg1();
 139                                 if (const MachineThread<SIZE>* new_thread = machine.thread(new_thread_tid, event.timestamp())) {
 140                                         switch (globals.lifecycle_filter()) {
 141                                                 case kLifecycleFilter::None:
 142                                                         break;
 143                                                 case kLifecycleFilter::User:
 144                                                         if (!new_thread->process().is_kernel())
 145                                                                 should_print = true;
 146                                                         break;
 147                                                 case kLifecycleFilter::All:
 148                                                         should_print = true;
 149                                                         break;
 150                                         }
 151
 152                                         if (should_print) {
 153                                                 auto& new_process = new_thread->process();
 154                                                 ASSERT(new_process.pid() == (pid_t)event.arg2(), "Pid does not match");
 155                                                 if (new_process.timespan().location() == event.timestamp()) {
 156                                                         print_fork(print_buffer, globals, machine, event, index, new_process);
 157                                                 }
 158
 159                                                 // We're not printing the actual event data, but instead the exiting thread's data:
 160                                                 print_base(print_buffer, globals,  event.timestamp(), new_thread, event, index, "thread-create", true);
 161                                         }
 162                                 }
 163                                 break;
 164                         }
 165
 166                         case TRACEDBG_CODE(DBG_TRACE_DATA, TRACE_DATA_THREAD_TERMINATE): {
 167                                 // This event may spawn two prints
 168                                 //
 169                                 // 1) thread termination
 170                                 // 2) task termination
 171                                 bool should_print = false;
 172                                 typename SIZE::ptr_t terminated_tid = event.arg1();
 173                                 if (const MachineThread<SIZE>* terminated_thread = machine.thread(terminated_tid, event.timestamp())) {
 174                                         switch (globals.lifecycle_filter()) {
 175                                                 case kLifecycleFilter::None:
 176                                                         break;
 177                                                 case kLifecycleFilter::User:
 178                                                         if (!terminated_thread->process().is_kernel())
 179                                                                 should_print = true;
 180                                                         break;
 181                                                 case kLifecycleFilter::All:
 182                                                         should_print = true;
 183                                                         break;
 184                                         }
 185
 186                                         if (should_print) {
 187                                                 // We're not printing the actual event data, but instead the exiting thread's data:
 188                                                 print_base(print_buffer, globals,  event.timestamp(), terminated_thread, event, index, "thread-exit", true);
 189                                         }
 190
 191                                         // Was this the last thread in the process? (Do we also need to print a process exit?)
 192                                         auto& terminated_process = terminated_thread->process();
 193                                         if (terminated_process.is_trace_terminated()) {
 194                                                 if (event.timestamp() >= terminated_process.exit_timestamp()) {
 195                                                         if (should_print) {
 196                                                                 print_exit(print_buffer, globals,  event, terminated_thread, index);
 197                                                         }
 198                                                         reset_task_data_on_exec_or_exit(terminated_process, task_appnap_state, task_requested_state, task_effective_state, task_boosts);
 199                                                 }
 200                                         }
 201
 202                                         auto thread_requested_it = thread_requested_state.find(terminated_tid);
 203                                         if (thread_requested_it != thread_requested_state.end()) {
 204                                                 thread_requested_state.erase(thread_requested_it);
 205                                         }
 206
 207                                         auto thread_effective_it = thread_effective_state.find(terminated_tid);
 208                                         if (thread_effective_it != thread_effective_state.end()) {
 209                                                 thread_effective_state.erase(thread_effective_it);
 210                                         }
 211                                 } else
 212                                         ASSERT(false, "Failed to find exit thread");
 213                                 break;
 214                         }
 215
 216                         case MACHDBG_CODE(DBG_MACH_IPC, MACH_IPC_MSG_SEND): {
 217                                 // trace event data is:
 218                                 // kmsg_addr, msgh_bits, msgh_id, voucher_addr,
 219
 220                                 // FIX ME!
 221                                 //
 222                                 // For now, we aren't recording mach msg's with endpoints in
 223                                 // the kernel. If we don't find a mach msg, assume its a kernel
 224                                 // msg.
 225                                 if (const MachineMachMsg<SIZE>* mach_msg = machine.mach_msg(index)) {
 226                                         if (is_mach_msg_interesting(machine, mach_msg)) {
 227                                                 print_mach_msg(print_buffer, globals, machine, event, index, true, mach_msg);
 228                                         }
 229                                 }
 230                                 break;
 231                         }
 232
 233                         case MACHDBG_CODE(DBG_MACH_IPC, MACH_IPC_MSG_RECV):
 234                         case MACHDBG_CODE(DBG_MACH_IPC, MACH_IPC_MSG_RECV_VOUCHER_REFUSED): {
 235                                 // trace event data is
 236                                 // kmsg_addr, msgh_bits, msgh_id, recv_voucher_addr
 237
 238                                 // FIX ME!
 239                                 //
 240                                 // For now, we aren't recording mach msg's with endpoints in
 241                                 // the kernel. If we don't find a mach msg, assume its a kernel
 242                                 // msg.
 243                                 if (const MachineMachMsg<SIZE>* mach_msg = machine.mach_msg(index)) {
 244                                         if (is_mach_msg_interesting(machine, mach_msg)) {
 245                                                 print_mach_msg(print_buffer, globals, machine, event, index, false, mach_msg);
 246                                         }
 247                                 }
 248                                 break;
 249                         }
 250
 251                         case MACHDBG_CODE(DBG_MACH_IPC, MACH_IPC_VOUCHER_CREATE): {
 252                                 // trace event data is
 253                                 // voucher address, voucher table size, system voucher count, voucher content bytes
 254
 255                                 if (auto voucher = machine.voucher(event.arg1(), event.timestamp())) {
 256                                         print_voucher(print_buffer, globals, machine, event, index, "voucher_create", voucher, true);
 257
 258                                         if (voucher->has_valid_contents()) {
 259                                                 print_voucher_contents(print_buffer, globals, machine, event, index, voucher);
 260                                         }
 261                                 } else {
 262                                         ASSERT(false, "Failed to find voucher");
 263                                 }
 264                                 break;
 265                         }
 266
 267                         case MACHDBG_CODE(DBG_MACH_IPC, MACH_IPC_VOUCHER_DESTROY): {
 268                                 // trace event data is
 269                                 // voucher address, 0, system voucher count, 0
 270                                 if (auto voucher = machine.voucher(event.arg1(), event.timestamp())) {
 271                                         print_voucher(print_buffer, globals, machine, event, index, "voucher_destroy", voucher, false);
 272                                 } else {
 273                                         ASSERT(false, "Failed to find voucher");
 274                                 }
 275                                 break;
 276                         }
 277
 278                         case MACHDBG_CODE(DBG_MACH_IPC, MACH_THREAD_SET_VOUCHER): {
 279                                 print_generic(print_buffer, globals, machine, event, index, "thread_adopt_voucher");
 280                                 break;
 281                         }
 282
 283                         case IMPORTANCE_CODE(IMP_ASSERTION, IMP_EXTERN):
 284                                 print_importance_assert(print_buffer, globals, machine, event, index, "externalize_importance", task_boosts);
 285                                 break;
 286
 287                         case IMPORTANCE_CODE(IMP_ASSERTION, IMP_HOLD | TASK_POLICY_EXTERNAL):
 288                         case IMPORTANCE_CODE(IMP_ASSERTION, IMP_HOLD | TASK_POLICY_INTERNAL):
 289                                 print_importance_assert(print_buffer, globals, machine, event, index, "importance_hold", task_boosts);
 290                                 break;
 291
 292                         case IMPORTANCE_CODE(IMP_ASSERTION, IMP_DROP | TASK_POLICY_EXTERNAL):
 293                         case IMPORTANCE_CODE(IMP_ASSERTION, IMP_DROP | TASK_POLICY_INTERNAL):
 294                                 print_importance_assert(print_buffer, globals, machine, event, index, "importance_drop", task_boosts);
 295                                 break;
 296
 297                         case IMPORTANCE_CODE(IMP_WATCHPORT, 0):
 298                                 // trace data is
 299                                 // proc_selfpid(), pid, boost, released_pid, 0);
 300                                 if (event.arg3() > 0) {
 301                                         print_watchport_importance_transfer(print_buffer, globals, machine, event, index);
 302                                 }
 303                                 break;
 304
 305                         case IMPORTANCE_CODE(IMP_TASK_SUPPRESSION, 0):
 306                         case IMPORTANCE_CODE(IMP_TASK_SUPPRESSION, 1):
 307                                 // Trace data is
 308                                 // self_pid, audit_token_pid_from_task(task), trequested_0(task, NULL), trequested_1(task, NULL)
 309                                 print_appnap(print_buffer, globals, machine, event, index, (bool)event.dbg_code(), task_appnap_state, task_requested_state);
 310                                 break;
 311
 312                         case IMPORTANCE_CODE(IMP_BOOST, IMP_BOOSTED):
 313                         case IMPORTANCE_CODE(IMP_BOOST, IMP_UNBOOSTED):
 314                                 // trace data is
 315                                 // proc_selfpid(), audit_token_pid_from_task(task), trequested_0(task, NULL), trequested_1(task, NULL)
 316                                 if (event.is_func_start()) {
 317                                         print_boost(print_buffer, globals, machine, event, index, (pid_t)event.arg2(), (event.dbg_code() == IMP_BOOSTED));
 318                                 }
 319                                 break;
 320
 321                                 //
 322                                 // IMP_TASK_APPTYPE trace args are:
 323                                 //
 324                                 // start:
 325                                 //      target_pid, trequested_0, trequested_1, apptype
 326                                 // end:
 327                                 //      target_pid, trequested_0, trequested_1, is_importance_receiver
 328                         case IMPORTANCE_CODE(IMP_TASK_APPTYPE, TASK_APPTYPE_NONE):
 329                         case IMPORTANCE_CODE(IMP_TASK_APPTYPE, TASK_APPTYPE_DAEMON_INTERACTIVE):
 330                         case IMPORTANCE_CODE(IMP_TASK_APPTYPE, TASK_APPTYPE_DAEMON_STANDARD):
 331                         case IMPORTANCE_CODE(IMP_TASK_APPTYPE, TASK_APPTYPE_DAEMON_ADAPTIVE):
 332                         case IMPORTANCE_CODE(IMP_TASK_APPTYPE, TASK_APPTYPE_DAEMON_BACKGROUND):
 333                         case IMPORTANCE_CODE(IMP_TASK_APPTYPE, TASK_APPTYPE_APP_DEFAULT):
 334                         case IMPORTANCE_CODE(IMP_TASK_APPTYPE, TASK_APPTYPE_APP_TAL):
 335                                 if (event.is_func_end()) {
 336                                         print_importance_apptype(print_buffer, globals, machine, event, index);
 337                                 }
 338                                 // FIX ME, not handling trequested status.
 339                                 //
 340                                 // process_trequested_task(print_buffer, globals, machine, event, index, (pid_t)event.arg1(), event.arg2(), event.arg3(), task_requested_policies);
 341                                 break;
 342
 343
 344                         case IMPORTANCE_CODE(IMP_UPDATE, (IMP_UPDATE_TASK_CREATE | TASK_POLICY_TASK)):
 345                                 // trace data is
 346                                 // targetpid, teffective_0(task, NULL), teffective_1(task, NULL), tpriority(task, NULL)
 347                                 print_importance_update_task(print_buffer, globals, machine, event, index, "imp_update_task_create", task_effective_state);
 348                                 break;
 349
 350                         case IMPORTANCE_CODE(IMP_UPDATE, (IMP_UPDATE_TASK_CREATE | TASK_POLICY_THREAD)):
 351                                 // trace data is
 352                                 // targettid, teffective_0(task, thread), teffective_1(task, thread), tpriority(thread, NULL)
 353                                 print_importance_update_thread(print_buffer, globals, machine, event, index, "imp_update_thread_create", thread_effective_state);
 354                                 break;
 355
 356                         case IMPORTANCE_CODE(IMP_UPDATE, TASK_POLICY_TASK):
 357                                 // trace data is
 358                                 // targetpid, teffective_0(task, NULL), teffective_1(task, NULL), tpriority(task, THREAD_NULL)
 359                                 print_importance_update_task(print_buffer, globals, machine, event, index, "imp_update_task", task_effective_state);
 360                                 break;
 361
 362                         case IMPORTANCE_CODE(IMP_UPDATE, TASK_POLICY_THREAD):
 363                                 // trace data is
 364                                 // targettid, teffective_0(task, thread), teffective_1(task, thread), tpriority(task, THREAD_NULL)
 365                                 print_importance_update_thread(print_buffer, globals, machine, event, index, "imp_update_thread", thread_effective_state);
 366                                 break;
 367
 368                         case IMPORTANCE_CODE(IMP_MSG, IMP_MSG_SEND):
 369                                 // trace data is
 370                                 // current_pid, sender_pid, imp_msgh_id, (bool)importance_cleared
 371
 372                                 // NOTE! Only end events carry "importance cleared"
 373                                 if (event.is_func_end() && (event.arg4() != 0)) {
 374                                         print_importance_send_failed(print_buffer, globals, machine, event, index);
 375                                 }
 376                                 break;
 377
 378                         case IMPORTANCE_CODE(IMP_MSG, IMP_MSG_DELV): {
 379                                 // trace data is
 380                                 // sending_pid, task_pid /* recv_pid?? */, msgh_id, impresult
 381                                 //
 382                                 // for impresult:
 383                                 //
 384                                 // 0: BOOST NOT APPLIED
 385                                 // 1: BOOST EXTERNALIZED
 386                                 // 2: LIVE_IMPORTANCE_LINKAGE!
 387                                 print_impdelv(print_buffer, globals, machine, event, index, (pid_t)event.arg1(), (uint32_t)event.arg4());
 388                                 break;
 389                         }
 390
 391                         default:
 392                                 if (event.dbg_class() == DBG_IMPORTANCE) {
 393                                         //
 394                                         // Every task policy set trace code carries "trequested" data, we would like to grab them all.
 395                                         //
 396                                         // This subclass spans the range of 0x20 through 0x3F
 397                                         //
 398
 399                                         uint32_t subclass = event.dbg_subclass();
 400                                         if (subclass >= 0x20 && subclass <= 0x3F) {
 401                                                 // Trace event data is
 402                                                 // targetid(task, thread), trequested_0(task, thread), trequested_1(task, thread), value
 403
 404                                                 bool is_task_event = (event.dbg_code() & TASK_POLICY_TASK) > 0;
 405
 406                                                 // Should not be both a task and thread event.
 407                                                 ASSERT(is_task_event != (event.dbg_code() & TASK_POLICY_THREAD), "BEWM!");
 408
 409                                                 if (is_task_event) {
 410                                                         // FIX ME, not handling trequested status.
 411                                                         //
 412                                                         // process_trequested_task(print_buffer, globals, machine, event, index, (pid_t)event.arg1(), event.arg2(), event.arg3(), task_requested_policies);
 413                                                 } else {
 414                                                         // FIX ME, not handling trequested status.
 415                                                         //
 416                                                         // process_trequested_thread(print_buffer, globals, machine, event, index, event.arg1(), event.arg2(), event.arg3(), task_requested_policies, thread_requested_policies);
 417                                                 }
 418                                         }
 419                                 }
 420                                 break;
 421                 }
 422         }
 423 }
 424
 425 #endif