]> git.saurik.com Git - apple/system_cmds.git/blame - kdprof/SummaryPrinting.hpp
projects / apple / system_cmds.git / blame
? search:
summary | shortlog | log | commit | commitdiff | tree
blob | blame (incremental) | history | HEAD
system_cmds-670.1.2.tar.gz
[apple/system_cmds.git] / kdprof / SummaryPrinting.hpp
CommitLineData
bd6521f0
A		 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
12void print_summary_header(const Globals& globals);
13
14struct 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
92template <typename SIZE>
93void 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
362template <typename SIZE>
363void 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
414template <typename SIZE>
415void 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
454template <typename SIZE>
455void 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
486template <typename SIZE>
487static 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
613template <typename SIZE>
614static 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
738template <typename SIZE>
739void 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
883template <typename SIZE>
884void 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
968template <typename SIZE>
969void 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
1105template <typename SIZE>
1106void 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
1242template <typename SIZE>
1243void 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
1372template <typename SIZE>
1373void 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
1441template <typename SIZE>
1442void 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
mirror of system_cmds