kdprof/SummaryPrinting.hpp

   1 //
   2 //  SummaryPrinting.hpp
   3 //  kdprof
   4 //
   5 //  Created by James McIlree on 4/19/13.
   6 //  Copyright (c) 2013 Apple. All rights reserved.
   7 //
   8
   9 #ifndef kdprof_Printing_hpp
  10 #define kdprof_Printing_hpp
  11
  12 void print_summary_header(const Globals& globals);
  13
  14 struct SummaryLineData {
  15     protected:
  16         static constexpr const char* const indent_string[] = { "", "  ", "    ", "      " };
  17         static const uint32_t MAX_INDENT_LEVEL = 3; // Need to know this for time indenting to work correctly
  18
  19         uint32_t                _indent_level;
  20         const char*             _name;
  21
  22     public:
  23
  24         enum class SummaryType {
  25                 Unknown,
  26                 CPU,
  27                 Process,
  28                 Thread
  29         };
  30
  31         SummaryLineData(const char* name, uint32_t indent_level) :
  32                 _indent_level(indent_level),
  33                 _name(name),
  34                 should_print_timestamp(true),
  35                 num_intr_events(0),
  36                 context_switches(0),
  37                 actual_process_count(0),
  38                 wanted_process_count(0),
  39                 actual_thread_count(0),
  40                 wanted_thread_count(0),
  41                 num_vm_fault_events(0),
  42                 num_io_events(0),
  43                 io_bytes_completed(0),
  44                 num_jetsam_pids(0),
  45                 percent_multiplier(100.0),
  46                 type(SummaryType::Unknown),
  47                 is_colored(false),
  48                 begin_color(NULL),
  49                 end_color(NULL)
  50         {
  51                 ASSERT(_indent_level <= MAX_INDENT_LEVEL, "Sanity");
  52                 ASSERT(_name && strlen(_name) > 0, "Sanity");
  53         }
  54
  55         bool should_print_timestamp;
  56         AbsTime total_time;
  57         AbsTime total_run_time;
  58         AbsTime total_idle_time;
  59         AbsTime total_intr_time;
  60         AbsTime total_wanted_run_time;
  61         AbsTime total_wallclock_run_time;
  62         AbsTime total_all_cpus_idle_time;
  63         AbsTime total_vm_fault_time;
  64         AbsTime total_io_time;
  65         AbsTime total_jetsam_time;
  66         uint32_t num_intr_events;
  67         uint32_t context_switches;
  68         uint32_t actual_process_count;
  69         uint32_t wanted_process_count;
  70         uint32_t actual_thread_count;
  71         uint32_t wanted_thread_count;
  72         uint32_t num_vm_fault_events;
  73         uint32_t num_io_events;
  74         uint64_t io_bytes_completed;
  75         uint32_t num_jetsam_pids;
  76         double percent_multiplier;
  77         SummaryType type;
  78         bool is_colored;
  79         const char* begin_color;
  80         const char* end_color;
  81
  82         const char* name()                              { return _name; }
  83         const char* outdent()                           { return indent_string[MAX_INDENT_LEVEL - _indent_level]; }
  84         const char* indent()                            { return indent_string[_indent_level]; }
  85
  86         bool is_unknown()                               { return type == SummaryType::Unknown; }
  87         bool is_cpu()                                   { return type == SummaryType::CPU; }
  88         bool is_process()                               { return type == SummaryType::Process; }
  89         bool is_thread()                                { return type == SummaryType::Thread; }
  90 };
  91
  92 template <typename SIZE>
  93 void print_summary_line(const Globals& globals, const Machine<SIZE>& machine, AbsInterval summary_interval, struct SummaryLineData& line_data)
  94 {
  95         // Header is...
  96         //                                                                                                                                                         Avg     Actual     Wanted   Actual   Wanted                                                                       Jetsam
  97         //                                                                              All CPU                       Thr Avg        Actual        Wanted  Concurrency  Processes     To Run  Threads   To Run  VMFault       VMFault       IO Wait     # IO    IO Bytes     Jetsam    Proc
  98         // [Time(mS)]        Name                               Run%    Idle%    Intr%    Idle%    #Intr      #CSW  On CPU/µS        CPU/mS        CPU/mS      (# CPU)        Ran  Processes      Ran  Threads    Count     Time (mS)     Time (mS)      Ops   Completed  Time (mS)   Count
  99         // 123456789abcdef0  123456789012345678901234567890  1234567  1234567  1234567  1234567  1234567  12345678  123456789  123456789abc  123456789abc  123456789ab  123456789  123456789  1234567  1234567  1234567  123456789abc  123456789abc  1234567  1234567890  123456789  123456
 100         //    1119100000.00                                    76.58    16.53     6.89     0.00      230       112   10000.00     100000.00     100000.00         1.55          2          3       12       13     2280        230.48       1998.22     3318   123.40 MB       0.00
 101
 102         ASSERT(!line_data.is_unknown(), "Sanity");
 103
 104         //
 105         // It turns out that calling dprintf is very expensive; we're going to
 106         // accumulate to a string buffer and then flush once at the end.
 107         //
 108         char line[1024];
 109         char* cursor = line;
 110         char* line_end = line + sizeof(line);
 111
 112         //
 113         // Begin line coloring (if any)
 114         //
 115         if (line_data.is_colored) {
 116                 ASSERT(line_data.begin_color && line_data.end_color, "Sanity");
 117                 cursor += snprintf(cursor, line_end - cursor, "%s", line_data.begin_color);
 118
 119                 if (cursor > line_end)
 120                         cursor = line_end;
 121         }
 122
 123         if (line_data.should_print_timestamp) {
 124
 125                 //
 126                 // Time and Name get a special indent treatment, so they come out
 127                 // as heirarchically aligned, while not disturbing the rest of the
 128                 // columns. The time value is actually outdented, the name value
 129                 // is indented.
 130                 //
 131                 // The result is that you get something like this:
 132                 //
 133                 //       [Time(mS)]  Name                               Run%
 134                 // 123456789abcdef0  123456789012345678901234567890  1234567
 135                 //
 136                 //    1000.00        INDENT-LEVEL-0                    ##.##
 137                 //      1000.00        INDENT-LEVEL-1                  ##.##
 138                 //        1000.00        INDENT-LEVEL-2                ##.##
 139                 //          1000.00        INDENT-LEVEL-3              ##.##
 140                 //
 141
 142                 char time_buffer[64];
 143
 144                 //
 145                 // Time
 146                 //
 147                 if (globals.should_print_mach_absolute_timestamps()) {
 148                         if (globals.beginning_of_time().value() == 0)
 149                                 snprintf(time_buffer, sizeof(time_buffer), "%llX%s", (summary_interval.location() - globals.beginning_of_time()).value(), line_data.outdent());
 150                         else
 151                                 snprintf(time_buffer, sizeof(time_buffer), "%llu%s", (summary_interval.location() - globals.beginning_of_time()).value(), line_data.outdent());
 152                 } else {
 153                         NanoTime ntime = (summary_interval.location() - globals.beginning_of_time()).nano_time(globals.timebase());
 154                         snprintf(time_buffer, sizeof(time_buffer), "%3.2f%s", (double)ntime.value() / 1000000.0, line_data.outdent());
 155                 }
 156
 157                 cursor += snprintf(cursor, line_end - cursor, "%16s  ", time_buffer);
 158
 159                 if (cursor > line_end)
 160                         cursor = line_end;
 161         }
 162
 163         //
 164         // Name
 165         //
 166
 167         {
 168                 char name_buffer[64];
 169                 snprintf(name_buffer, sizeof(name_buffer), "%s%s", line_data.indent(), line_data.name());
 170
 171                 cursor += snprintf(cursor, line_end - cursor, "%-30s  ", name_buffer);
 172                 if (cursor > line_end)
 173                         cursor = line_end;
 174         }
 175
 176         //
 177         // Run% Idle% Intr% All-CPUs-Idle% #Intr
 178         //
 179
 180         // Special case for process/thread summary lines, print idle/intr as "-";
 181         if (line_data.is_process() || line_data.is_thread()) {
 182                 double run_percent = 0.0;
 183
 184                 if (line_data.total_time.value() > 0)
 185                         run_percent = line_data.total_run_time.double_value() / line_data.total_time.double_value() * line_data.percent_multiplier;
 186
 187                 cursor += snprintf(cursor, line_end - cursor, "%7.2f  %7s  %7s  %7s  %7u  ",
 188                                    run_percent,
 189                                    "-",
 190                                    "-",
 191                                    "-",
 192                                    line_data.num_intr_events);
 193         } else {
 194                 ASSERT(line_data.total_time.value() > 0, "Sanity");
 195
 196                 cursor += snprintf(cursor, line_end - cursor, "%7.2f  %7.2f  %7.2f  %7.2f  %7u  ",
 197                                    line_data.total_run_time.double_value() / line_data.total_time.double_value() * line_data.percent_multiplier,
 198                                    line_data.total_idle_time.double_value() / line_data.total_time.double_value() * line_data.percent_multiplier,
 199                                    line_data.total_intr_time.double_value() / line_data.total_time.double_value() * line_data.percent_multiplier,
 200                                    line_data.total_all_cpus_idle_time.double_value() / line_data.total_time.double_value() * line_data.percent_multiplier,
 201                                    line_data.num_intr_events);
 202         }
 203
 204         if (cursor > line_end)
 205                 cursor = line_end;
 206
 207         //
 208         // #context-switches  avg-on-cpu/µS
 209         //
 210         if (line_data.context_switches > 0) {
 211                 double avg_on_cpu_uS = (line_data.total_run_time / AbsTime(line_data.context_switches)).nano_time(globals.timebase()).value() / 1000.0;
 212                 cursor += snprintf(cursor, line_end - cursor, "%8u  %9.2f  ", line_data.context_switches, avg_on_cpu_uS);
 213         } else {
 214                 cursor += snprintf(cursor, line_end - cursor, "%8u  %9s  ", line_data.context_switches, "-");
 215         }
 216
 217         if (cursor > line_end)
 218                 cursor = line_end;
 219
 220         //
 221         // Actual CPU/mS, Wanted CPU/mS
 222         //
 223         if (line_data.total_wanted_run_time > 0) {
 224                 cursor += snprintf(cursor, line_end - cursor, "%12.2f  %12.2f  ",
 225                                    (double)line_data.total_run_time.nano_time(globals.timebase()).value() / 1000000.0,
 226                                    (double)(line_data.total_run_time + line_data.total_wanted_run_time).nano_time(globals.timebase()).value() / 1000000.0);
 227         } else {
 228                 cursor += snprintf(cursor, line_end - cursor, "%12.2f  %12s  ",
 229                                    (double)line_data.total_run_time.nano_time(globals.timebase()).value() / 1000000.0,
 230                                    "-");
 231         }
 232
 233         if (cursor > line_end)
 234                 cursor = line_end;
 235
 236         //
 237         // Proc Avg Concurrency
 238         //
 239
 240         if (line_data.total_wallclock_run_time > 0) {
 241                 cursor += snprintf(cursor, line_end - cursor, "%11.2f  ", (double)line_data.total_run_time.value() / (double)line_data.total_wallclock_run_time.value());
 242                 // cursor += snprintf(cursor, line_end - cursor, "%11.2f  ", (double)line_data.total_wallclock_run_time.nano_time(globals.timebase()).value() / 1000000.0);
 243         } else {
 244                 cursor += snprintf(cursor, line_end - cursor, "%11s  ", "-");
 245         }
 246
 247         if (cursor > line_end)
 248                 cursor = line_end;
 249
 250         //
 251         // Actual Processes, Wanted Processes
 252         //
 253         if (line_data.is_thread()) {
 254                 cursor += snprintf(cursor, line_end - cursor, "%9s  %9s  ", "-", "-");
 255         } else {
 256                 if (line_data.total_run_time > 0 && line_data.total_wanted_run_time > 0) {
 257                         cursor += snprintf(cursor, line_end - cursor, "%9u  %9u  ", (uint32_t)line_data.actual_process_count, (uint32_t)line_data.wanted_process_count);
 258                 } else if (line_data.total_run_time > 0) {
 259                         cursor += snprintf(cursor, line_end - cursor, "%9u  %9s  ", (uint32_t)line_data.actual_process_count, "-");
 260                 } else if (line_data.total_wanted_run_time > 0) {
 261                         cursor += snprintf(cursor, line_end - cursor, "%9s  %9u  ", "-", (uint32_t)line_data.wanted_process_count);
 262                 } else {
 263                         cursor += snprintf(cursor, line_end - cursor, "%9s  %9s  ", "-", "-");
 264                 }
 265         }
 266
 267         if (cursor > line_end)
 268                 cursor = line_end;
 269
 270         //
 271         // Actual Threads, Wanted Threads
 272         //
 273         if (line_data.total_run_time > 0 && line_data.total_wanted_run_time > 0) {
 274                 cursor += snprintf(cursor, line_end - cursor, "%7u  %7u  ", (uint32_t)line_data.actual_thread_count, (uint32_t)line_data.wanted_thread_count);
 275         } else if (line_data.total_run_time > 0) {
 276                 cursor += snprintf(cursor, line_end - cursor, "%7u  %7s  ", (uint32_t)line_data.actual_thread_count, "-");
 277         } else if (line_data.total_wanted_run_time > 0) {
 278                 cursor += snprintf(cursor, line_end - cursor, "%7s  %7u  ", "-", (uint32_t)line_data.wanted_thread_count);
 279         } else {
 280                 cursor += snprintf(cursor, line_end - cursor, "%7s  %7s  ", "-", "-");
 281         }
 282
 283         if (cursor > line_end)
 284                 cursor = line_end;
 285
 286
 287         //
 288         // #vmfaults, mS blocked in vmfault
 289         //
 290         if (line_data.num_vm_fault_events == 0 && line_data.total_vm_fault_time.value() == 0) {
 291                 cursor += snprintf(cursor, line_end - cursor, "%7s  %12s  ", "-", "-");
 292         } else {
 293                 cursor += snprintf(cursor, line_end - cursor, "%7u  %12.2f  ",
 294                                    line_data.num_vm_fault_events,
 295                                    (double)line_data.total_vm_fault_time.nano_time(globals.timebase()).value() / 1000000.0);
 296         }
 297
 298         //
 299         // mS blocked on IO activity
 300         //
 301         if (line_data.total_io_time.value() == 0) {
 302                 cursor += snprintf(cursor, line_end - cursor, "%12s  ", "-");
 303         } else {
 304                 cursor += snprintf(cursor, line_end - cursor, "%12.2f  ",
 305                                    (double)line_data.total_io_time.nano_time(globals.timebase()).value() / 1000000.0);
 306         }
 307
 308         //
 309         // # IO operations
 310         //
 311         if (line_data.num_io_events == 0) {
 312                 cursor += snprintf(cursor, line_end - cursor, "%7s  ", "-");
 313         } else {
 314                 cursor += snprintf(cursor, line_end - cursor, "%7u  ", line_data.num_io_events);
 315         }
 316
 317         //
 318         // IO bytes completed
 319         //
 320         if (line_data.io_bytes_completed == 0) {
 321                 cursor += snprintf(cursor, line_end - cursor, "%10s  ", "-");
 322         } else {
 323                 cursor += snprintf(cursor, line_end - cursor, "%10s  ", formated_byte_size(line_data.io_bytes_completed).c_str());
 324         }
 325
 326         //
 327         // Jetsam time
 328         //
 329         if (line_data.total_jetsam_time == 0) {
 330                 cursor += snprintf(cursor, line_end - cursor, "%9s  ", "-");
 331         } else {
 332                 cursor += snprintf(cursor, line_end - cursor, "%9.2f  ",
 333                                    (double)line_data.total_jetsam_time.nano_time(globals.timebase()).value() / 1000000.0);
 334         }
 335
 336         //
 337         // Jetsam count
 338         //
 339         if (line_data.is_cpu()) {
 340                 if (line_data.num_jetsam_pids == 0) {
 341                         cursor += snprintf(cursor, line_end - cursor, "%6s", "-");
 342                 } else {
 343                         cursor += snprintf(cursor, line_end - cursor, "%6u", line_data.num_jetsam_pids);
 344                 }
 345         } else {
 346                 cursor += snprintf(cursor, line_end - cursor, "%6s", "");
 347         }
 348
 349         //
 350         // End line coloring (if any)
 351         //
 352         if (line_data.is_colored) {
 353                 cursor += snprintf(cursor, line_end - cursor, "%s", line_data.end_color);
 354
 355                 if (cursor > line_end)
 356                         cursor = line_end;
 357         }
 358
 359         dprintf(globals.output_fd(), "%s\n", line);
 360 }
 361
 362 template <typename SIZE>
 363 void print_cpu_summary_with_name_and_indent(const Globals& globals, const Machine<SIZE>& machine, AbsInterval summary_interval, const CPUSummary<SIZE>& master_summary, const CPUSummary<SIZE>& cpu_summary, const char* name, uint32_t indent)
 364 {
 365         struct SummaryLineData data(name, indent);
 366
 367         data.should_print_timestamp = (globals.is_summary_start_set() || globals.is_summary_stop_set() || globals.is_summary_step_set());
 368         data.total_time = master_summary.total_time();
 369         data.total_run_time = cpu_summary.total_run_time();
 370         data.total_idle_time = cpu_summary.total_idle_time();
 371         data.total_intr_time = cpu_summary.total_intr_time();
 372         data.total_wanted_run_time = cpu_summary.total_future_run_time();
 373         data.total_wallclock_run_time = cpu_summary.total_wallclock_run_time();
 374         data.total_all_cpus_idle_time = cpu_summary.total_all_cpus_idle_time();
 375         data.total_vm_fault_time = cpu_summary.total_vm_fault_time();
 376         data.total_io_time = cpu_summary.total_io_time();
 377         data.total_jetsam_time = cpu_summary.total_jetsam_time();
 378         data.context_switches = cpu_summary.context_switches();
 379         data.num_intr_events = cpu_summary.num_intr_events();
 380         data.num_vm_fault_events = cpu_summary.num_vm_fault_events();
 381         data.num_io_events = cpu_summary.num_io_events();
 382         data.num_jetsam_pids = cpu_summary.num_processes_jetsammed();
 383         data.io_bytes_completed = cpu_summary.io_bytes_completed();
 384         data.type = SummaryLineData::SummaryType::CPU;
 385
 386         for (auto& process_summary : cpu_summary.process_summaries()) {
 387
 388                 if (process_summary.total_run_time() > 0) {
 389                         data.actual_process_count++;
 390                         data.wanted_process_count++;
 391                 } else if (process_summary.total_future_run_time() > 0) {
 392                         data.wanted_process_count++;
 393                 } else {
 394                         // ASSERT(cpu_summary.total_vm_fault_time() > 0, "Process in summary no actual or wanted run time, and no vm_fault time");
 395                 }
 396
 397                 for (auto& thread_summary : process_summary.thread_summaries()) {
 398                         if (thread_summary.total_run_time() > 0) {
 399                                 data.actual_thread_count++;
 400                                 data.wanted_thread_count++;
 401                         } else if (thread_summary.total_future_run_time() > 0) {
 402                                 data.wanted_thread_count++;
 403                         } else {
 404                                 // ASSERT((thread_summary.total_vm_fault_time() > 0) || (thread_summary.total_pgin_time() > 0), "Thread in summary no actual or wanted run time, and no vm_fault or pgin time");
 405                         }
 406                 }
 407         }
 408
 409         data.percent_multiplier *= (double)master_summary.active_cpus();
 410
 411         print_summary_line(globals, machine, summary_interval, data);
 412 }
 413
 414 template <typename SIZE>
 415 void print_process_summary_with_name_and_indent(const Globals& globals, const Machine<SIZE>& machine, AbsInterval summary_interval, const CPUSummary<SIZE>& master_summary, const ProcessSummary<SIZE>& process_summary, const char* name, uint32_t indent)
 416 {
 417         struct SummaryLineData data(name, indent);
 418
 419         data.should_print_timestamp = (globals.is_summary_start_set() || globals.is_summary_stop_set() || globals.is_summary_step_set());
 420         data.total_run_time = process_summary.total_run_time();
 421         data.total_wanted_run_time = process_summary.total_future_run_time();
 422         data.total_wallclock_run_time = process_summary.total_wallclock_run_time();
 423         data.total_vm_fault_time = process_summary.total_vm_fault_time();
 424         data.total_io_time = process_summary.total_io_time();
 425         data.total_jetsam_time = process_summary.total_jetsam_time();
 426         data.context_switches = process_summary.context_switches();
 427         data.num_intr_events = process_summary.num_intr_events();
 428         data.actual_process_count = 1;
 429         data.wanted_process_count = 1;
 430         data.num_vm_fault_events = process_summary.num_vm_fault_events();
 431         data.num_io_events = process_summary.num_io_events();
 432         data.num_jetsam_pids = process_summary.num_processes_jetsammed();
 433         data.io_bytes_completed = process_summary.io_bytes_completed();
 434         data.total_time = master_summary.total_time();
 435         // This causes the line printer to put "-" in the idle and intr % columns.
 436         data.type = SummaryLineData::SummaryType::Process;
 437         data.percent_multiplier *= (double)master_summary.active_cpus();
 438
 439         // We have to walk the threads to decide actual vs wanted to run
 440         for (auto& thread_summary : process_summary.thread_summaries()) {
 441                 if (thread_summary.total_run_time() > 0) {
 442                         data.actual_thread_count++;
 443                         data.wanted_thread_count++;
 444                 } else if (thread_summary.total_future_run_time() > 0) {
 445                         data.wanted_thread_count++;
 446                 } else {
 447                         // ASSERT(thread_summary.total_vm_fault_time() > 0, "Thread in summary no actual or wanted run time, and no vm_fault time");
 448                 }
 449         }
 450
 451         print_summary_line(globals, machine, summary_interval, data);
 452 }
 453
 454 template <typename SIZE>
 455 void print_thread_summary_with_name_and_indent(const Globals& globals, const Machine<SIZE>& machine, AbsInterval summary_interval, const CPUSummary<SIZE>& master_summary, const ThreadSummary<SIZE>& thread_summary, const char* name, uint32_t indent)
 456 {
 457         struct SummaryLineData data(name, indent);
 458
 459         /*data.is_colored = true;
 460          data.begin_color = TerminalColorStringFor(kTerminalColor::GREEN, true, false);
 461          data.end_color = TerminalColorResetString();*/
 462
 463         data.should_print_timestamp = (globals.is_summary_start_set() || globals.is_summary_stop_set() || globals.is_summary_step_set());
 464         data.total_run_time = thread_summary.total_run_time();
 465         data.total_wanted_run_time = thread_summary.total_future_run_time();
 466         data.total_vm_fault_time = thread_summary.total_vm_fault_time();
 467         data.total_io_time = thread_summary.total_io_time();
 468         data.total_jetsam_time = thread_summary.total_jetsam_time();
 469         data.context_switches = thread_summary.context_switches();
 470         data.num_intr_events = thread_summary.num_intr_events();
 471         data.num_vm_fault_events = thread_summary.num_vm_fault_events();
 472         data.num_io_events = thread_summary.num_io_events();
 473         data.num_jetsam_pids = 0;
 474         data.io_bytes_completed = thread_summary.io_bytes_completed();
 475         data.total_time = master_summary.total_time();
 476         data.percent_multiplier *= (double)master_summary.active_cpus();
 477         data.actual_thread_count = 1;
 478         data.wanted_thread_count = 1;
 479
 480         // This causes the line printer to put "-" in various columns that don't make sense for a thread summary
 481         data.type = SummaryLineData::SummaryType::Thread;
 482
 483         print_summary_line(globals, machine, summary_interval, data);
 484 }
 485
 486 template <typename SIZE>
 487 static void sort_processes(const Globals& globals, const CPUSummary<SIZE>& summary, std::vector<const MachineProcess<SIZE>*>& processes) {
 488         switch (globals.sort_key()) {
 489                 case kSortKey::CPU:
 490                         // Sort by Actual CPU, Future CPU, pid
 491                         std::sort(processes.begin(), processes.end(), [&summary](const MachineProcess<SIZE>* p0, const MachineProcess<SIZE>* p1) -> bool {
 492                                 auto p0_summary = summary.process_summary(p0);
 493                                 auto p1_summary = summary.process_summary(p1);
 494
 495                                 AbsTime p0_run_time = p0_summary->total_run_time();
 496                                 AbsTime p1_run_time = p1_summary->total_run_time();
 497
 498                                 if (p0_run_time == p1_run_time) {
 499                                         AbsTime p0_future_run_time = p0_summary->total_future_run_time();
 500                                         AbsTime p1_future_run_time = p1_summary->total_future_run_time();
 501
 502                                         if (p0_future_run_time == p1_future_run_time)
 503                                                 return p0->pid() < p1->pid();
 504
 505                                         return p1_future_run_time < p0_future_run_time;
 506                                 }
 507
 508                                 return p1_run_time < p0_run_time;
 509                         });
 510                         break;
 511
 512                 case kSortKey::VMFault:
 513                         // Sort by VMFault time, #-faults, pid
 514                         std::sort(processes.begin(), processes.end(), [&summary](const MachineProcess<SIZE>* p0, const MachineProcess<SIZE>* p1) -> bool {
 515                                 auto p0_summary = summary.process_summary(p0);
 516                                 auto p1_summary = summary.process_summary(p1);
 517
 518                                 AbsTime p0_vm_fault_time = p0_summary->total_vm_fault_time();
 519                                 AbsTime p1_vm_fault_time = p1_summary->total_vm_fault_time();
 520
 521                                 if (p0_vm_fault_time == p1_vm_fault_time) {
 522                                         uint32_t p0_vm_fault_count = p0_summary->num_vm_fault_events();
 523                                         uint32_t p1_vm_fault_count = p1_summary->num_vm_fault_events();
 524
 525                                         if (p0_vm_fault_count == p1_vm_fault_count)
 526                                                 return p0->pid() < p1->pid();
 527
 528                                         return p1_vm_fault_count < p0_vm_fault_count;
 529                                 }
 530
 531                                 return p1_vm_fault_time < p0_vm_fault_time;
 532                         });
 533                         break;
 534
 535                 case kSortKey::IO_Wait:
 536                         // Sort by IO time, pid
 537                         std::sort(processes.begin(), processes.end(), [&summary](const MachineProcess<SIZE>* p0, const MachineProcess<SIZE>* p1) -> bool {
 538                                 auto p0_summary = summary.process_summary(p0);
 539                                 auto p1_summary = summary.process_summary(p1);
 540
 541                                 AbsTime p0_io_time = p0_summary->total_io_time();
 542                                 AbsTime p1_io_time = p1_summary->total_io_time();
 543
 544                                 if (p0_io_time == p1_io_time) {
 545                                         uint32_t p0_io_ops = p0_summary->num_io_events();
 546                                         uint32_t p1_io_ops = p1_summary->num_io_events();
 547
 548                                         if (p0_io_ops == p1_io_ops)
 549                                                 return p0->pid() < p1->pid();
 550
 551                                         return p1_io_ops < p0_io_ops;
 552                                 }
 553
 554                                 return p1_io_time < p0_io_time;
 555                         });
 556                         break;
 557
 558                 case kSortKey::IO_Ops:
 559                         // Sort by IO time, pid
 560                         std::sort(processes.begin(), processes.end(), [&summary](const MachineProcess<SIZE>* p0, const MachineProcess<SIZE>* p1) -> bool {
 561                                 auto p0_summary = summary.process_summary(p0);
 562                                 auto p1_summary = summary.process_summary(p1);
 563
 564                                 uint32_t p0_io_ops = p0_summary->num_io_events();
 565                                 uint32_t p1_io_ops = p1_summary->num_io_events();
 566
 567                                 if (p0_io_ops == p1_io_ops) {
 568                                         AbsTime p0_io_time = p0_summary->total_io_time();
 569                                         AbsTime p1_io_time = p1_summary->total_io_time();
 570
 571                                         if (p0_io_time == p1_io_time)
 572                                                 return p0->pid() < p1->pid();
 573
 574                                         return p1_io_time < p0_io_time;
 575                                 }
 576
 577                                 return p1_io_ops < p0_io_ops;
 578                         });
 579                         break;
 580
 581                 case kSortKey::IO_Size:
 582                         // Sort by IO time, pid
 583                         std::sort(processes.begin(), processes.end(), [&summary](const MachineProcess<SIZE>* p0, const MachineProcess<SIZE>* p1) -> bool {
 584                                 auto p0_summary = summary.process_summary(p0);
 585                                 auto p1_summary = summary.process_summary(p1);
 586
 587                                 uint64_t p0_io_bytes_completed = p0_summary->io_bytes_completed();
 588                                 uint64_t p1_io_bytes_completed = p1_summary->io_bytes_completed();
 589
 590                                 if (p0_io_bytes_completed == p1_io_bytes_completed) {
 591                                         AbsTime p0_io_time = p0_summary->total_io_time();
 592                                         AbsTime p1_io_time = p1_summary->total_io_time();
 593
 594                                         if (p0_io_time == p1_io_time)
 595                                                 return p0->pid() < p1->pid();
 596
 597                                         return p1_io_time < p0_io_time;
 598                                 }
 599
 600                                 return p1_io_bytes_completed < p0_io_bytes_completed;
 601                         });
 602                         break;
 603
 604                 case kSortKey::ID:
 605                         // Sort by pid
 606                         std::sort(processes.begin(), processes.end(), [](const MachineProcess<SIZE>* p0, const MachineProcess<SIZE>* p1) -> bool {
 607                                 return p0->pid() < p1->pid();
 608                         });
 609                         break;
 610         }
 611 }
 612
 613 template <typename SIZE>
 614 static void sort_threads(const Globals& globals, const ProcessSummary<SIZE>& summary, std::vector<const MachineThread<SIZE>*>& threads) {
 615         switch (globals.sort_key()) {
 616                 case kSortKey::CPU:
 617                         std::sort(threads.begin(), threads.end(), [&summary](const MachineThread<SIZE>* t0, const MachineThread<SIZE>* t1) -> bool {
 618                                 auto t0_summary = summary.thread_summary(t0);
 619                                 auto t1_summary = summary.thread_summary(t1);
 620
 621                                 AbsTime t0_run_time = t0_summary->total_run_time();
 622                                 AbsTime t1_run_time = t1_summary->total_run_time();
 623
 624                                 if (t0_run_time == t1_run_time) {
 625                                         AbsTime t0_future_run_time = t0_summary->total_future_run_time();
 626                                         AbsTime t1_future_run_time = t1_summary->total_future_run_time();
 627
 628                                         if (t0_future_run_time == t1_future_run_time)
 629                                                 return t0->tid() < t1->tid();
 630
 631                                         return t1_future_run_time < t0_future_run_time;
 632                                 }
 633
 634                                 return t1_run_time < t0_run_time;
 635                         });
 636                         break;
 637
 638                 case kSortKey::VMFault:
 639                         // Sort by VMFault time, #-faults, pid
 640                         std::sort(threads.begin(), threads.end(), [&summary](const MachineThread<SIZE>* t0, const MachineThread<SIZE>* t1) -> bool {
 641                                 auto t0_summary = summary.thread_summary(t0);
 642                                 auto t1_summary = summary.thread_summary(t1);
 643
 644                                 AbsTime t0_vm_fault_time = t0_summary->total_vm_fault_time();
 645                                 AbsTime t1_vm_fault_time = t1_summary->total_vm_fault_time();
 646
 647                                 if (t0_vm_fault_time == t1_vm_fault_time) {
 648                                         uint32_t t0_vm_fault_count = t0_summary->num_vm_fault_events();
 649                                         uint32_t t1_vm_fault_count = t1_summary->num_vm_fault_events();
 650
 651                                         if (t0_vm_fault_count == t1_vm_fault_count)
 652                                                 return t0->tid() < t1->tid();
 653
 654                                         return t1_vm_fault_count < t0_vm_fault_count;
 655                                 }
 656
 657                                 return t1_vm_fault_time < t0_vm_fault_time;
 658                         });
 659                         break;
 660
 661                 case kSortKey::IO_Wait:
 662                         // Sort by IO time, pid
 663                         std::sort(threads.begin(), threads.end(), [&summary](const MachineThread<SIZE>* t0, const MachineThread<SIZE>* t1) -> bool {
 664                                 auto t0_summary = summary.thread_summary(t0);
 665                                 auto t1_summary = summary.thread_summary(t1);
 666
 667                                 AbsTime t0_io_time = t0_summary->total_io_time();
 668                                 AbsTime t1_io_time = t1_summary->total_io_time();
 669
 670                                 if (t0_io_time == t1_io_time) {
 671                                         uint32_t t0_io_ops = t0_summary->num_io_events();
 672                                         uint32_t t1_io_ops = t1_summary->num_io_events();
 673
 674                                         if (t0_io_ops == t1_io_ops)
 675                                                 return t0->tid() < t1->tid();
 676
 677                                         return t1_io_ops < t0_io_ops;
 678                                 }
 679
 680                                 return t1_io_time < t0_io_time;
 681                         });
 682                         break;
 683
 684                 case kSortKey::IO_Ops:
 685                         // Sort by IO time, pid
 686                         std::sort(threads.begin(), threads.end(), [&summary](const MachineThread<SIZE>* t0, const MachineThread<SIZE>* t1) -> bool {
 687                                 auto t0_summary = summary.thread_summary(t0);
 688                                 auto t1_summary = summary.thread_summary(t1);
 689
 690                                 uint32_t t0_io_ops = t0_summary->num_io_events();
 691                                 uint32_t t1_io_ops = t1_summary->num_io_events();
 692
 693                                 if (t0_io_ops == t1_io_ops) {
 694                                         AbsTime t0_io_time = t0_summary->total_io_time();
 695                                         AbsTime t1_io_time = t1_summary->total_io_time();
 696
 697                                         if (t0_io_time == t1_io_time)
 698                                                 return t0->tid() < t1->tid();
 699
 700                                         return t1_io_time < t0_io_time;
 701                                 }
 702
 703                                 return t1_io_ops < t0_io_ops;
 704                         });
 705                         break;
 706
 707                 case kSortKey::IO_Size:
 708                         // Sort by IO time, pid
 709                         std::sort(threads.begin(), threads.end(), [&summary](const MachineThread<SIZE>* t0, const MachineThread<SIZE>* t1) -> bool {
 710                                 auto t0_summary = summary.thread_summary(t0);
 711                                 auto t1_summary = summary.thread_summary(t1);
 712
 713                                 uint64_t t0_io_bytes_completed = t0_summary->io_bytes_completed();
 714                                 uint64_t t1_io_bytes_completed = t1_summary->io_bytes_completed();
 715
 716                                 if (t0_io_bytes_completed == t1_io_bytes_completed) {
 717                                         AbsTime t0_io_time = t0_summary->total_io_time();
 718                                         AbsTime t1_io_time = t1_summary->total_io_time();
 719
 720                                         if (t0_io_time == t1_io_time)
 721                                                 return t0->tid() < t1->tid();
 722
 723                                         return t1_io_time < t0_io_time;
 724                                 }
 725
 726                                 return t1_io_bytes_completed < t0_io_bytes_completed;
 727                         });
 728                         break;
 729
 730                 case kSortKey::ID:
 731                         std::sort(threads.begin(), threads.end(), [](const MachineThread<SIZE>* t0, const MachineThread<SIZE>* t1) -> bool {
 732                                 return t0->tid() < t1->tid();
 733                         });
 734                         break;
 735         }
 736 }
 737
 738 template <typename SIZE>
 739 void print_machine_summary(const Globals& globals, const Machine<SIZE>& machine) {
 740         AbsInterval machine_timespan = machine.timespan();
 741
 742         AbsTime start(globals.summary_start(machine_timespan));
 743         AbsTime stop(globals.summary_stop(machine_timespan));
 744         AbsTime step(globals.summary_step(machine_timespan));
 745
 746         print_summary_header(globals);
 747
 748         AbsInterval start_stop_timespan(start, stop - start);
 749         AbsInterval clipped_start_stop_timespan(start_stop_timespan.intersection_range(machine_timespan));
 750
 751         start = clipped_start_stop_timespan.location();
 752         stop = clipped_start_stop_timespan.max();
 753
 754         while (start < stop) {
 755                 AbsInterval base_interval(start, step);
 756                 AbsInterval summary_interval(base_interval.intersection_range(clipped_start_stop_timespan));
 757
 758                 //
 759                 // TOTAL summary
 760                 //
 761                 CPUSummary<SIZE> summary = machine.summary_for_timespan(summary_interval, NULL);
 762
 763                 //
 764                 // We want the TOTAL to include the number of ms elapsed, so print a duration
 765                 //
 766                 char total_buffer[64];
 767                 if (globals.should_print_mach_absolute_timestamps()) {
 768                         if (globals.beginning_of_time().value() == 0)
 769                                 snprintf(total_buffer, sizeof(total_buffer), "TOTAL (0x%llXmabs)", summary_interval.length().value());
 770                         else
 771                                 snprintf(total_buffer, sizeof(total_buffer), "TOTAL (%llumabs)", summary_interval.length().value());
 772                 } else {
 773                         NanoTime ntime = summary_interval.length().nano_time(globals.timebase());
 774                         snprintf(total_buffer, sizeof(total_buffer), "TOTAL (%3.2fms)", (double)ntime.value() / 1000000.0);
 775                 }
 776                 print_cpu_summary_with_name_and_indent(globals, machine, summary_interval, summary, summary, total_buffer, 0);
 777
 778                 std::vector<CPUSummary<SIZE>> per_cpu_summaries;
 779
 780                 //
 781                 // TOTAL per cpu summary
 782                 //
 783                 if (globals.should_print_cpu_summaries()) {
 784                         // summary.cpus() is unordered, we want to display sorted by cpu_id.
 785                         std::vector<const MachineCPU<SIZE>*> sorted_cpus;
 786
 787                         for (auto& cpu : summary.cpus()) {
 788                                 sorted_cpus.emplace_back(cpu);
 789                         }
 790
 791                         std::sort(sorted_cpus.begin(), sorted_cpus.end(), [](MachineCPU<SIZE> const* cpu0, MachineCPU<SIZE> const* cpu1) -> bool {
 792                                 return cpu0->id() < cpu1->id();
 793                         });
 794
 795                         for (auto cpu : sorted_cpus) {
 796                                 per_cpu_summaries.push_back(machine.summary_for_timespan(summary_interval, cpu));
 797
 798                                 char name[16];
 799                                 snprintf(name, sizeof(name), "CPU%d", cpu->id());
 800                                 print_cpu_summary_with_name_and_indent(globals, machine, summary_interval, summary, per_cpu_summaries.back(), name, 1);
 801                         }
 802                 }
 803
 804                 //
 805                 // PER PROCESS summary
 806                 //
 807                 if (globals.should_print_process_summaries()) {
 808                         //
 809                         // We want to sort the list of processes by PID, so they always display in the same order.
 810                         //
 811                         std::vector<const MachineProcess<SIZE>*> sorted_processes;
 812                         for (auto& process_summary : summary.process_summaries()) {
 813                                 sorted_processes.emplace_back(process_summary.process());
 814                         }
 815
 816                         sort_processes(globals, summary, sorted_processes);
 817
 818                         for (auto process : sorted_processes) {
 819                                 ASSERT(summary.process_summary(process), "Unable to find process summary by pointer lookup");
 820                                 if (const ProcessSummary<SIZE>* process_summary = summary.process_summary(process)) {
 821                                         char name[32];
 822                                         snprintf(name, sizeof(name), "%s (%d)%s", process->name(), process->pid(), process->is_exit_by_jetsam() ? " *" : "");
 823                                         print_process_summary_with_name_and_indent(globals, machine, summary_interval, summary, *process_summary, name, 1);
 824
 825                                         if (globals.should_print_cpu_summaries()) {
 826                                                 //
 827                                                 // PER PROCESS per cpu summary
 828                                                 //
 829                                                 for (auto& cpu_summary : per_cpu_summaries) {
 830                                                         if (const ProcessSummary<SIZE>* per_cpu_process_summary = cpu_summary.process_summary(process)) {
 831                                                                 char name[32];
 832                                                                 snprintf(name, sizeof(name), "CPU%d %s (%d)", (*cpu_summary.cpus().begin())->id(), process->name(), process->pid());
 833                                                                 print_process_summary_with_name_and_indent(globals, machine, summary_interval, summary, *per_cpu_process_summary, name, 2);
 834                                                         }
 835                                                 }
 836                                         }
 837
 838                                         if (globals.should_print_thread_summaries()) {
 839                                                 //
 840                                                 // PER PROCESS per thread summary
 841                                                 //
 842                                                 std::vector<const MachineThread<SIZE>*> sorted_threads;
 843                                                 for (auto& thread_summary : process_summary->thread_summaries()) {
 844                                                         sorted_threads.emplace_back(thread_summary.thread());
 845                                                 }
 846
 847                                                 sort_threads(globals, *process_summary, sorted_threads);
 848
 849                                                 for (auto thread : sorted_threads) {
 850                                                         ASSERT(process_summary->thread_summary(thread), "Unable to find thread summary by pointer lookup");
 851                                                         if (const ThreadSummary<SIZE>* thread_summary = process_summary->thread_summary(thread)) {
 852                                                                 char name[32];
 853                                                                 snprintf(name, sizeof(name), "tid-%llX", (uint64_t)thread->tid());
 854                                                                 print_thread_summary_with_name_and_indent(globals, machine, summary_interval, summary, *thread_summary, name, 2);
 855
 856                                                                 if (globals.should_print_cpu_summaries()) {
 857                                                                         //
 858                                                                         // PER PROCESS per thread per cpu summary
 859                                                                         //
 860                                                                         for (auto& cpu_summary : per_cpu_summaries) {
 861                                                                                 if (const ProcessSummary<SIZE>* per_cpu_process_summary = cpu_summary.process_summary(process)) {
 862                                                                                         if (const ThreadSummary<SIZE>* per_cpu_thread_summary = per_cpu_process_summary->thread_summary(thread)) {
 863                                                                                                 char name[32];
 864                                                                                                 snprintf(name, sizeof(name), "CPU%d tid-%llX", (*cpu_summary.cpus().begin())->id(), (uint64_t)thread->tid());
 865                                                                                                 print_thread_summary_with_name_and_indent(globals, machine, summary_interval, summary, *per_cpu_thread_summary, name, 3);
 866                                                                                         }
 867                                                                                 }
 868                                                                         }
 869                                                                 }
 870
 871                                                         }
 872                                                 }
 873                                         }
 874                                 }
 875                         }
 876                 }
 877
 878                 start += step;
 879         }
 880 }
 881
 882
 883 template <typename SIZE>
 884 void print_machine_csv_summary_header(const Globals& globals,
 885                                       const Machine<SIZE>& machine,
 886                                       std::vector<const MachineCPU<SIZE>*>& all_cpus,
 887                                       std::vector<const MachineProcess<SIZE>*>& all_processes,
 888                                       std::unordered_map<const MachineProcess<SIZE>*, std::vector<const MachineThread<SIZE>*>>& all_threads,
 889                                       const char* header_type)
 890 {
 891         // Header is...
 892         //
 893         // "", header_type
 894         //
 895         // "", "TOTAL", "CPU0", "CPU1", "proc1", "proc1-tid1", "proc1-tid2", "proc2", etc..
 896
 897         //
 898         // It turns out that calling dprintf is very expensive; we're going to
 899         // accumulate to a string buffer and then flush once at the end.
 900         //
 901         char line[16384]; // Header lines can be big!
 902         char* cursor = line;
 903         char* line_end = line + sizeof(line);
 904
 905         //
 906         // header + TOTAL
 907         //
 908         cursor += snprintf(cursor, line_end - cursor, "%s\n\nTIME, TOTAL", header_type);
 909         if (cursor > line_end)
 910                 cursor = line_end;
 911
 912         //
 913         // TOTAL per cpu summary
 914         //
 915         if (globals.should_print_cpu_summaries()) {
 916                 for (auto cpu : all_cpus) {
 917                         cursor += snprintf(cursor, line_end - cursor, ", CPU%d", cpu->id());
 918                         if (cursor > line_end)
 919                                 cursor = line_end;
 920                 }
 921         }
 922
 923         //
 924         // PER PROCESS summary
 925         //
 926         if (globals.should_print_process_summaries()) {
 927                 for (auto process : all_processes) {
 928                         cursor += snprintf(cursor, line_end - cursor, ", %s (%d)", process->name(), process->pid());
 929                         if (cursor > line_end)
 930                                 cursor = line_end;
 931
 932                         if (globals.should_print_cpu_summaries()) {
 933                                 //
 934                                 // PER PROCESS per cpu summary
 935                                 //
 936                                 for (auto cpu : all_cpus) {
 937                                         cursor += snprintf(cursor, line_end - cursor, ", CPU%d %s (%d)", cpu->id(), process->name(), process->pid());
 938                                         if (cursor > line_end)
 939                                                 cursor = line_end;
 940                                 }
 941                         }
 942
 943                         if (globals.should_print_thread_summaries()) {
 944                                 //
 945                                 // PER PROCESS per thread summary
 946                                 //
 947                                 for (auto thread : all_threads[process]) {
 948                                         cursor += snprintf(cursor, line_end - cursor, ", tid-%llX", (uint64_t)thread->tid());
 949                                         if (cursor > line_end)
 950                                                 cursor = line_end;
 951
 952                                         //
 953                                         // PER PROCESS per thread per cpu summary
 954                                         //
 955                                         for (auto cpu : all_cpus) {
 956                                                 cursor += snprintf(cursor, line_end - cursor, ", CPU%d tid-%llX", cpu->id(), (uint64_t)thread->tid());
 957                                                 if (cursor > line_end)
 958                                                         cursor = line_end;
 959                                         }
 960                                 }
 961                         }
 962                 }
 963         }
 964
 965         dprintf(globals.output_fd(), "%s\n", line);
 966 }
 967
 968 template <typename SIZE>
 969 void print_machine_csv_summary_actual_cpu_ms_line(const Globals& globals,
 970                                                   const Machine<SIZE>& machine,
 971                                                   AbsInterval summary_interval,
 972                                                   std::vector<const MachineCPU<SIZE>*>& all_cpus,
 973                                                   std::vector<const MachineProcess<SIZE>*>& all_processes,
 974                                                   std::unordered_map<const MachineProcess<SIZE>*, std::vector<const MachineThread<SIZE>*>>& all_threads,
 975                                                   CPUSummary<SIZE>& master_summary,
 976                                                   std::vector<CPUSummary<SIZE>>& per_cpu_summaries)
 977 {
 978         char line[16384]; // Header lines can be big!
 979         char* cursor = line;
 980         char* line_end = line + sizeof(line);
 981
 982         //
 983         // Time
 984         //
 985
 986         if (globals.should_print_mach_absolute_timestamps()) {
 987                 if (globals.beginning_of_time().value() == 0)
 988                         cursor += snprintf(cursor, line_end - cursor, "%llX", (summary_interval.location() - globals.beginning_of_time()).value());
 989                 else
 990                         cursor += snprintf(cursor, line_end - cursor, "%llu", (summary_interval.location() - globals.beginning_of_time()).value());
 991         } else {
 992                 NanoTime ntime = (summary_interval.location() - globals.beginning_of_time()).nano_time(globals.timebase());
 993                 cursor += snprintf(cursor, line_end - cursor, "%3.2f", (double)ntime.value() / 1000000.0);
 994         }
 995
 996         if (cursor > line_end)
 997                 cursor = line_end;
 998
 999         //
1000         // TOTAL
1001         //
1002         cursor += snprintf(cursor, line_end - cursor, ", %3.2f",
1003                            (double)master_summary.total_run_time().nano_time(globals.timebase()).value() / 1000000.0);
1004
1005         if (cursor > line_end)
1006                 cursor = line_end;
1007
1008         //
1009         // TOTAL per cpu summary
1010         //
1011         if (globals.should_print_cpu_summaries()) {
1012                 for (auto& cpu_summary : per_cpu_summaries) {
1013                         cursor += snprintf(cursor, line_end - cursor, ", %3.2f",
1014                                            (double)cpu_summary.total_run_time().nano_time(globals.timebase()).value() / 1000000.0);
1015
1016                         if (cursor > line_end)
1017                                 cursor = line_end;
1018                 }
1019         }
1020
1021         //
1022         // PER PROCESS summary
1023         //
1024         if (globals.should_print_process_summaries()) {
1025                 for (auto process : all_processes) {
1026                         const ProcessSummary<SIZE>* process_summary;
1027
1028                         // Not all summaries will have a matching process entry!
1029                         if ((process_summary = master_summary.process_summary(process))) {
1030                                 cursor += snprintf(cursor, line_end - cursor, ", %3.2f",
1031                                                    (double)process_summary->total_run_time().nano_time(globals.timebase()).value() / 1000000.0);
1032                         } else {
1033                                 cursor += snprintf(cursor, line_end - cursor, ",");
1034                         }
1035
1036                         if (cursor > line_end)
1037                                 cursor = line_end;
1038
1039                         if (globals.should_print_cpu_summaries()) {
1040                                 //
1041                                 // PER PROCESS per cpu summary
1042                                 //
1043                                 for (auto& cpu_summary : per_cpu_summaries) {
1044                                         if (const auto& process_summary = cpu_summary.process_summary(process)) {
1045                                                 cursor += snprintf(cursor, line_end - cursor, ", %3.2f",
1046                                                                    (double)process_summary->total_run_time().nano_time(globals.timebase()).value() / 1000000.0);
1047                                         } else {
1048                                                 cursor += snprintf(cursor, line_end - cursor, ",");
1049                                         }
1050
1051                                         if (cursor > line_end)
1052                                                 cursor = line_end;
1053                                 }
1054                         }
1055
1056                         if (globals.should_print_thread_summaries()) {
1057                                 //
1058                                 // PER PROCESS per thread summary
1059                                 //
1060
1061                                 //
1062                                 // We again have to do a bit more work, sometime a process is missing and we still need to print empty slots for its threads.
1063
1064
1065                                 for (auto thread : all_threads[process]) {
1066                                         if (process_summary) {
1067                                                 if (const auto& thread_summary = process_summary->thread_summary(thread)) {
1068                                                         cursor += snprintf(cursor, line_end - cursor, ", %3.2f",
1069                                                                            (double)thread_summary->total_run_time().nano_time(globals.timebase()).value() / 1000000.0);
1070                                                 } else
1071                                                         cursor += snprintf(cursor, line_end - cursor, ",");
1072                                         } else
1073                                                 cursor += snprintf(cursor, line_end - cursor, ",");
1074
1075                                         if (cursor > line_end)
1076                                                 cursor = line_end;
1077
1078
1079                                         if (globals.should_print_cpu_summaries()) {
1080                                                 //
1081                                                 // PER PROCESS per thread per cpu summary
1082                                                 //
1083                                                 for (auto& cpu_summary : per_cpu_summaries) {
1084                                                         if (const auto& per_cpu_process_summary = cpu_summary.process_summary(process)) {
1085                                                                 if (const auto& per_cpu_thread_summary = per_cpu_process_summary->thread_summary(thread)) {
1086                                                                         cursor += snprintf(cursor, line_end - cursor, ", %3.2f",
1087                                                                                            (double)per_cpu_thread_summary->total_run_time().nano_time(globals.timebase()).value() / 1000000.0);
1088                                                                 } else
1089                                                                         cursor += snprintf(cursor, line_end - cursor, ",");
1090                                                         } else
1091                                                                 cursor += snprintf(cursor, line_end - cursor, ",");
1092
1093                                                         if (cursor > line_end)
1094                                                                 cursor = line_end;
1095                                                 }
1096                                         }
1097                                 }
1098                         }
1099                 }
1100         }
1101
1102         dprintf(globals.output_fd(), "%s\n", line);
1103 }
1104
1105 template <typename SIZE>
1106 void print_machine_csv_summary_wanted_cpu_ms_line(const Globals& globals,
1107                                                   const Machine<SIZE>& machine,
1108                                                   AbsInterval summary_interval,
1109                                                   std::vector<const MachineCPU<SIZE>*>& all_cpus,
1110                                                   std::vector<const MachineProcess<SIZE>*>& all_processes,
1111                                                   std::unordered_map<const MachineProcess<SIZE>*, std::vector<const MachineThread<SIZE>*>>& all_threads,
1112                                                   CPUSummary<SIZE>& master_summary,
1113                                                   std::vector<CPUSummary<SIZE>>& per_cpu_summaries)
1114 {
1115         char line[16384]; // Header lines can be big!
1116         char* cursor = line;
1117         char* line_end = line + sizeof(line);
1118
1119         //
1120         // Time
1121         //
1122
1123         if (globals.should_print_mach_absolute_timestamps()) {
1124                 if (globals.beginning_of_time().value() == 0)
1125                         cursor += snprintf(cursor, line_end - cursor, "%llX", (summary_interval.location() - globals.beginning_of_time()).value());
1126                 else
1127                         cursor += snprintf(cursor, line_end - cursor, "%llu", (summary_interval.location() - globals.beginning_of_time()).value());
1128         } else {
1129                 NanoTime ntime = (summary_interval.location() - globals.beginning_of_time()).nano_time(globals.timebase());
1130                 cursor += snprintf(cursor, line_end - cursor, "%3.2f", (double)ntime.value() / 1000000.0);
1131         }
1132
1133         if (cursor > line_end)
1134                 cursor = line_end;
1135
1136         //
1137         // TOTAL
1138         //
1139         cursor += snprintf(cursor, line_end - cursor, ", %3.2f",
1140                            (double)master_summary.total_future_run_time().nano_time(globals.timebase()).value() / 1000000.0);
1141
1142         if (cursor > line_end)
1143                 cursor = line_end;
1144
1145         //
1146         // TOTAL per cpu summary
1147         //
1148         if (globals.should_print_cpu_summaries()) {
1149                 for (auto& cpu_summary : per_cpu_summaries) {
1150                         cursor += snprintf(cursor, line_end - cursor, ", %3.2f",
1151                                            (double)cpu_summary.total_future_run_time().nano_time(globals.timebase()).value() / 1000000.0);
1152
1153                         if (cursor > line_end)
1154                                 cursor = line_end;
1155                 }
1156         }
1157
1158         //
1159         // PER PROCESS summary
1160         //
1161         if (globals.should_print_process_summaries()) {
1162                 for (auto process : all_processes) {
1163                         const ProcessSummary<SIZE>* process_summary;
1164
1165                         // Not all summaries will have a matching process entry!
1166                         if ((process_summary = master_summary.process_summary(process))) {
1167                                 cursor += snprintf(cursor, line_end - cursor, ", %3.2f",
1168                                                    (double)process_summary->total_future_run_time().nano_time(globals.timebase()).value() / 1000000.0);
1169                         } else {
1170                                 cursor += snprintf(cursor, line_end - cursor, ",");
1171                         }
1172
1173                         if (cursor > line_end)
1174                                 cursor = line_end;
1175
1176                         if (globals.should_print_cpu_summaries()) {
1177                                 //
1178                                 // PER PROCESS per cpu summary
1179                                 //
1180                                 for (auto& cpu_summary : per_cpu_summaries) {
1181                                         if (const auto& process_summary = cpu_summary.process_summary(process)) {
1182                                                 cursor += snprintf(cursor, line_end - cursor, ", %3.2f",
1183                                                                    (double)process_summary->total_future_run_time().nano_time(globals.timebase()).value() / 1000000.0);
1184                                         } else {
1185                                                 cursor += snprintf(cursor, line_end - cursor, ",");
1186                                         }
1187
1188                                         if (cursor > line_end)
1189                                                 cursor = line_end;
1190                                 }
1191                         }
1192
1193                         if (globals.should_print_thread_summaries()) {
1194                                 //
1195                                 // PER PROCESS per thread summary
1196                                 //
1197
1198                                 //
1199                                 // We again have to do a bit more work, sometime a process is missing and we still need to print empty slots for its threads.
1200
1201
1202                                 for (auto thread : all_threads[process]) {
1203                                         if (process_summary) {
1204                                                 if (const auto& thread_summary = process_summary->thread_summary(thread)) {
1205                                                         cursor += snprintf(cursor, line_end - cursor, ", %3.2f",
1206                                                                            (double)thread_summary->total_future_run_time().nano_time(globals.timebase()).value() / 1000000.0);
1207                                                 } else
1208                                                         cursor += snprintf(cursor, line_end - cursor, ",");
1209                                         } else
1210                                                 cursor += snprintf(cursor, line_end - cursor, ",");
1211
1212                                         if (cursor > line_end)
1213                                                 cursor = line_end;
1214
1215
1216                                         if (globals.should_print_cpu_summaries()) {
1217                                                 //
1218                                                 // PER PROCESS per thread per cpu summary
1219                                                 //
1220                                                 for (auto& cpu_summary : per_cpu_summaries) {
1221                                                         if (const auto& per_cpu_process_summary = cpu_summary.process_summary(process)) {
1222                                                                 if (const auto& per_cpu_thread_summary = per_cpu_process_summary->thread_summary(thread)) {
1223                                                                         cursor += snprintf(cursor, line_end - cursor, ", %3.2f",
1224                                                                                            (double)per_cpu_thread_summary->total_future_run_time().nano_time(globals.timebase()).value() / 1000000.0);
1225                                                                 } else
1226                                                                         cursor += snprintf(cursor, line_end - cursor, ",");
1227                                                         } else
1228                                                                 cursor += snprintf(cursor, line_end - cursor, ",");
1229
1230                                                         if (cursor > line_end)
1231                                                                 cursor = line_end;
1232                                                 }
1233                                         }
1234                                 }
1235                         }
1236                 }
1237         }
1238
1239         dprintf(globals.output_fd(), "%s\n", line);
1240 }
1241
1242 template <typename SIZE>
1243 void print_machine_csv_summary(const Globals& globals, const Machine<SIZE>& machine) {
1244         AbsInterval machine_timespan = machine.timespan();
1245
1246         AbsTime start(globals.summary_start(machine_timespan));
1247         AbsTime stop(globals.summary_stop(machine_timespan));
1248         AbsTime step(globals.summary_step(machine_timespan));
1249
1250         AbsInterval start_stop_timespan(start, stop - start);
1251         AbsInterval clipped_start_stop_timespan(start_stop_timespan.intersection_range(machine_timespan));
1252
1253         start = clipped_start_stop_timespan.location();
1254         stop = clipped_start_stop_timespan.max();
1255
1256         //
1257         // While printing a csv summary, we need to use the entire set of processes/threads/cpus
1258         // from the range, even though they may not run in each sample. We first gather a summary
1259         // for the entire time, to get the master list.
1260         //
1261         CPUSummary<SIZE> start_stop_summary = machine.summary_for_timespan(clipped_start_stop_timespan, NULL);
1262
1263         std::vector<const MachineProcess<SIZE>*> all_processes;
1264         std::vector<const MachineCPU<SIZE>*> all_cpus;
1265         std::unordered_map<const MachineProcess<SIZE>*, std::vector<const MachineThread<SIZE>*>> all_threads;
1266
1267         //
1268         // gather all processes
1269         //
1270         {
1271                 for (auto& process_summary : start_stop_summary.process_summaries()) {
1272                         all_processes.emplace_back(process_summary.process());
1273                 }
1274
1275                 sort_processes(globals, start_stop_summary, all_processes);
1276         }
1277
1278         //
1279         // gather all cpus
1280         //
1281         if (globals.should_print_cpu_summaries()) {
1282                 for (auto& cpu : start_stop_summary.cpus()) {
1283                         all_cpus.emplace_back(cpu);
1284                 }
1285
1286                 std::sort(all_cpus.begin(), all_cpus.end(), [](MachineCPU<SIZE> const* cpu0, MachineCPU<SIZE> const* cpu1) -> bool {
1287                         return cpu0->id() < cpu1->id();
1288                 });
1289         }
1290
1291         //
1292         // gather all threads
1293         //
1294         if (globals.should_print_thread_summaries()) {
1295                 for (auto process : all_processes) {
1296                         ASSERT(start_stop_summary.process_summary(process), "Unable to find process summary by pointer lookup");
1297                         if (const ProcessSummary<SIZE>* process_summary = start_stop_summary.process_summary(process)) {
1298                                 //
1299                                 // PER PROCESS per thread summary
1300                                 //
1301                                 auto& sorted_threads = all_threads[process];
1302                                 for (auto& thread_summary : process_summary->thread_summaries()) {
1303                                         sorted_threads.emplace_back(thread_summary.thread());
1304                                 }
1305
1306                                 sort_threads(globals, *process_summary, sorted_threads);
1307                         }
1308                 }
1309         }
1310
1311         print_machine_csv_summary_header(globals, machine, all_cpus, all_processes, all_threads, "Actual CPU/ms");
1312
1313         while (start < stop) {
1314                 AbsInterval base_interval(start, step);
1315                 AbsInterval summary_interval(base_interval.intersection_range(clipped_start_stop_timespan));
1316
1317                 //
1318                 // TOTAL summary
1319                 //
1320                 CPUSummary<SIZE> summary = machine.summary_for_timespan(summary_interval, NULL);
1321
1322                 //
1323                 // Per CPU summaries...
1324                 //
1325                 std::vector<CPUSummary<SIZE>> per_cpu_summaries;
1326                 if (globals.should_print_cpu_summaries()) {
1327                         for (auto cpu : all_cpus) {
1328                                 per_cpu_summaries.push_back(machine.summary_for_timespan(summary_interval, cpu));
1329                         }
1330                 }
1331
1332                 print_machine_csv_summary_actual_cpu_ms_line(globals, machine, summary_interval, all_cpus, all_processes, all_threads, summary, per_cpu_summaries);
1333
1334                 start += step;
1335         }
1336
1337
1338         //
1339         // Now print Wanted CPU/ms
1340         //
1341         start = clipped_start_stop_timespan.location();
1342         stop = clipped_start_stop_timespan.max();
1343
1344         dprintf(globals.output_fd(), "\n");
1345         print_machine_csv_summary_header(globals, machine, all_cpus, all_processes, all_threads, "Wanted CPU/ms");
1346
1347         while (start < stop) {
1348                 AbsInterval base_interval(start, step);
1349                 AbsInterval summary_interval(base_interval.intersection_range(clipped_start_stop_timespan));
1350
1351                 //
1352                 // TOTAL summary
1353                 //
1354                 CPUSummary<SIZE> summary = machine.summary_for_timespan(summary_interval, NULL);
1355
1356                 //
1357                 // Per CPU summaries...
1358                 //
1359                 std::vector<CPUSummary<SIZE>> per_cpu_summaries;
1360                 if (globals.should_print_cpu_summaries()) {
1361                         for (auto cpu : all_cpus) {
1362                                 per_cpu_summaries.push_back(machine.summary_for_timespan(summary_interval, cpu));
1363                         }
1364                 }
1365
1366                 print_machine_csv_summary_wanted_cpu_ms_line(globals, machine, summary_interval, all_cpus, all_processes, all_threads, summary, per_cpu_summaries);
1367
1368                 start += step;
1369         }
1370 }
1371
1372 template <typename SIZE>
1373 void print_process_start_stop_timestamps(const Globals& globals, const Machine<SIZE>& machine) {
1374         for (auto process : machine.processes()) {
1375
1376                 //
1377                 // Skip processes with no events
1378                 //
1379
1380                 if (process->timespan().length() == 0) {
1381                         // Skip processes with nothing in them.
1382                         // The assert may be too strong.
1383                         ASSERT(process->is_created_by_thread_map(), "Expected a zero length process to be from the thread map");
1384                         continue;
1385                 }
1386
1387                 //
1388                 // Don't print the kernel process, it will occupy the entire trace
1389                 //
1390                 if (process->is_kernel())
1391                         continue;
1392
1393                 //
1394                 // Time
1395                 //
1396                 char time_buffer[64];
1397                 if (globals.beginning_of_time().value() == 0)
1398                         snprintf(time_buffer, sizeof(time_buffer), "%llumabs", process->timespan().location().value());
1399                 else
1400                         snprintf(time_buffer, sizeof(time_buffer), "%llumabs", (process->timespan().location() - globals.beginning_of_time()).value());
1401
1402                 //
1403                 // End time
1404                 //
1405                 char end_time_buffer[64];
1406                 if (globals.beginning_of_time().value() == 0)
1407                         snprintf(end_time_buffer, sizeof(end_time_buffer), "%llumabs", process->timespan().max().value());
1408                 else
1409                         snprintf(end_time_buffer, sizeof(end_time_buffer), "%llumabs", (process->timespan().max() - globals.beginning_of_time()).value());
1410
1411                 const char* create_reason;
1412                 if (process->is_created_by_thread_map())
1413                         create_reason = "Threadmap Entry";
1414                 else if (process->is_created_by_previous_machine_state())
1415                         create_reason = "Prev Machine State";
1416                 else if (process->is_created_by_fork_exec())
1417                         create_reason = "ForkExec";
1418                 else if (process->is_created_by_exec())
1419                         create_reason = "Exec";
1420                 else
1421                         create_reason = "???";
1422
1423                 if (globals.is_verbose()) {
1424                         printf(" %30s (%6d)  --start %-16s --stop %-16s\tCreated by %-18s %s\n",
1425                                process->name(),
1426                                process->pid(),
1427                                time_buffer,
1428                                end_time_buffer,
1429                                create_reason,
1430                                process->is_trace_terminated() ? "EXITED" : "");
1431                 } else {
1432                         printf(" %30s (%6d)  --start %s --stop %s\n",
1433                                process->name(),
1434                                process->pid(),
1435                                time_buffer,
1436                                end_time_buffer);
1437                 }
1438         }
1439 }
1440
1441 template <typename SIZE>
1442 void print_verbose_machine_info(const Globals& globals, const Machine<SIZE>& machine, uint32_t threadmap_count, uint32_t cpumap_count) {
1443         dprintf(globals.output_fd(), "\tEvent data is %s, and appears to be from %s\n", SIZE::is_64_bit ? "K64" : "K32", machine.is_ios() ? "iOS" : "OSX");
1444         dprintf(globals.output_fd(), "\tUsing a%stimebase of %d/%d\n", globals.is_timebase_set() ? " [User Set] " : " ", globals.timebase().numer, globals.timebase().denom);
1445
1446         if (threadmap_count) {
1447                 dprintf(globals.output_fd(), "\tA threadmap is present, and contains %u entries\n", threadmap_count);
1448         } else {
1449                 dprintf(globals.output_fd(), "\tA threadmap is not present");
1450         }
1451
1452         if (cpumap_count) {
1453                 dprintf(globals.output_fd(), "\tA cpumap is present, and contains %u entries\n", cpumap_count);
1454
1455         } else {
1456                 dprintf(globals.output_fd(), "\tA cpumap is not present, the system provided a default with %u cpus and %u iops\n", globals.cpu_count(), globals.iop_count());
1457         }
1458
1459         dprintf(globals.output_fd(), "\tFound %u active cpus in trace data\n", machine.active_cpus());
1460
1461         if (globals.is_summary_start_set()) {
1462                 AbsInterval machine_timespan = machine.timespan();
1463
1464                 if (globals.should_print_mach_absolute_timestamps()) {
1465                         if (globals.beginning_of_time().value() == 0)
1466                                 dprintf(globals.output_fd(), "\tUsing a --start value of 0x%llXmabs (raw)\n", globals.summary_start(machine_timespan).value());
1467                         else
1468                                 dprintf(globals.output_fd(), "\tUsing a --start value of %llumabs\n", (globals.summary_start(machine_timespan) - machine_timespan.location()).value());
1469                 } else {
1470                         NanoTime ntime = (globals.summary_start(machine_timespan) - machine_timespan.location()).nano_time(globals.timebase());
1471                         dprintf(globals.output_fd(), "\tUsing a --start value of %3.2fms\n", (double)ntime.value() / 1000000.0);
1472                 }
1473         }
1474
1475         if (globals.is_summary_stop_set()) {
1476                 AbsInterval machine_timespan = machine.timespan();
1477
1478                 if (globals.should_print_mach_absolute_timestamps()) {
1479                         if (globals.beginning_of_time().value() == 0)
1480                                 dprintf(globals.output_fd(), "\tUsing a --stop value of 0x%llXmabs (raw)\n", globals.summary_stop(machine_timespan).value());
1481                         else
1482                                 dprintf(globals.output_fd(), "\tUsing a --stop value of %llumabs\n", (globals.summary_stop(machine_timespan) - machine_timespan.location()).value());
1483                 } else {
1484                         NanoTime ntime = (globals.summary_stop(machine_timespan) - machine_timespan.location()).nano_time(globals.timebase());
1485                         dprintf(globals.output_fd(), "\tUsing a --stop value of %3.2fms\n", (double)ntime.value() / 1000000.0);
1486                 }
1487         }
1488
1489         if (globals.is_summary_step_set()) {
1490                 AbsInterval machine_timespan = machine.timespan();
1491
1492                 if (globals.should_print_mach_absolute_timestamps()) {
1493                         if (globals.beginning_of_time().value() == 0)
1494                                 dprintf(globals.output_fd(), "\tUsing a --step value of 0x%llXmabs (raw)\n", globals.summary_step(machine_timespan).value());
1495                         else
1496                                 dprintf(globals.output_fd(), "\tUsing a --step value of %llumabs\n", globals.summary_step(machine_timespan).value());
1497                 } else {
1498                         NanoTime ntime = globals.summary_step(machine_timespan).nano_time(globals.timebase());
1499                         dprintf( globals.output_fd(), "\tUsing a --step value of %3.2fms\n", (double)ntime.value() / 1000000.0);
1500                 }
1501         }
1502 }
1503
1504 #endif