1 // SPDX-License-Identifier: GPL-2.0 2 #include "builtin.h" 3 #include "perf.h" 4 #include "perf-sys.h" 5 6 #include "util/cpumap.h" 7 #include "util/evlist.h" 8 #include "util/evsel.h" 9 #include "util/evsel_fprintf.h" 10 #include "util/mutex.h" 11 #include "util/symbol.h" 12 #include "util/thread.h" 13 #include "util/header.h" 14 #include "util/session.h" 15 #include "util/tool.h" 16 #include "util/cloexec.h" 17 #include "util/thread_map.h" 18 #include "util/color.h" 19 #include "util/stat.h" 20 #include "util/string2.h" 21 #include "util/callchain.h" 22 #include "util/time-utils.h" 23 24 #include <subcmd/pager.h> 25 #include <subcmd/parse-options.h> 26 #include "util/trace-event.h" 27 28 #include "util/debug.h" 29 #include "util/event.h" 30 #include "util/util.h" 31 #include "util/synthetic-events.h" 32 #include "util/target.h" 33 34 #include <linux/kernel.h> 35 #include <linux/log2.h> 36 #include <linux/zalloc.h> 37 #include <sys/prctl.h> 38 #include <sys/resource.h> 39 #include <sys/wait.h> 40 #include <inttypes.h> 41 42 #include <errno.h> 43 #include <semaphore.h> 44 #include <pthread.h> 45 #include <math.h> 46 #include <api/fs/fs.h> 47 #include <perf/cpumap.h> 48 #include <linux/time64.h> 49 #include <linux/err.h> 50 51 #include <linux/ctype.h> 52 53 #define PR_SET_NAME 15 /* Set process name */ 54 #define MAX_CPUS 4096 55 #define COMM_LEN 20 56 #define SYM_LEN 129 57 #define MAX_PID 1024000 58 #define PID_MAX_LIMIT 4194304 /* kernel limit on 64-bit */ 59 #define MAX_PRIO 140 60 #define SEP_LEN 100 61 62 static const char *cpu_list; 63 static struct perf_cpu_map *user_requested_cpus; 64 static DECLARE_BITMAP(cpu_bitmap, MAX_NR_CPUS); 65 66 struct sched_atom; 67 68 struct task_desc { 69 unsigned long nr; 70 unsigned long pid; 71 char comm[COMM_LEN]; 72 73 unsigned long nr_events; 74 unsigned long curr_event; 75 struct sched_atom **atoms; 76 77 pthread_t thread; 78 79 sem_t ready_for_work; 80 sem_t work_done_sem; 81 82 u64 cpu_usage; 83 }; 84 85 enum sched_event_type { 86 SCHED_EVENT_RUN, 87 SCHED_EVENT_SLEEP, 88 SCHED_EVENT_WAKEUP, 89 }; 90 91 struct sched_atom { 92 enum sched_event_type type; 93 u64 timestamp; 94 u64 duration; 95 unsigned long nr; 96 sem_t *wait_sem; 97 struct task_desc *wakee; 98 }; 99 100 enum thread_state { 101 THREAD_SLEEPING = 0, 102 THREAD_WAIT_CPU, 103 THREAD_SCHED_IN, 104 THREAD_IGNORE 105 }; 106 107 struct work_atom { 108 struct list_head list; 109 enum thread_state state; 110 u64 sched_out_time; 111 u64 wake_up_time; 112 u64 sched_in_time; 113 u64 runtime; 114 }; 115 116 struct work_atoms { 117 struct list_head work_list; 118 struct thread *thread; 119 struct rb_node node; 120 u64 max_lat; 121 u64 max_lat_start; 122 u64 max_lat_end; 123 u64 total_lat; 124 u64 nb_atoms; 125 u64 total_runtime; 126 int num_merged; 127 }; 128 129 typedef int (*sort_fn_t)(struct work_atoms *, struct work_atoms *); 130 131 struct perf_sched; 132 133 struct trace_sched_handler { 134 int (*switch_event)(struct perf_sched *sched, struct perf_sample *sample, 135 struct machine *machine); 136 137 int (*runtime_event)(struct perf_sched *sched, struct perf_sample *sample, 138 struct machine *machine); 139 140 int (*wakeup_event)(struct perf_sched *sched, struct perf_sample *sample, 141 struct machine *machine); 142 143 /* PERF_RECORD_FORK event, not sched_process_fork tracepoint */ 144 int (*fork_event)(struct perf_sched *sched, union perf_event *event, 145 struct machine *machine); 146 147 int (*migrate_task_event)(struct perf_sched *sched, 148 struct perf_sample *sample, 149 struct machine *machine); 150 }; 151 152 #define COLOR_PIDS PERF_COLOR_BLUE 153 #define COLOR_CPUS PERF_COLOR_BG_RED 154 155 struct perf_sched_map { 156 DECLARE_BITMAP(comp_cpus_mask, MAX_CPUS); 157 struct perf_cpu *comp_cpus; 158 bool comp; 159 struct perf_thread_map *color_pids; 160 const char *color_pids_str; 161 struct perf_cpu_map *color_cpus; 162 const char *color_cpus_str; 163 const char *task_name; 164 struct strlist *task_names; 165 bool fuzzy; 166 struct perf_cpu_map *cpus; 167 const char *cpus_str; 168 }; 169 170 struct perf_sched { 171 struct perf_tool tool; 172 const char *sort_order; 173 unsigned long nr_tasks; 174 struct task_desc **pid_to_task; 175 struct task_desc **tasks; 176 const struct trace_sched_handler *tp_handler; 177 struct mutex start_work_mutex; 178 struct mutex work_done_wait_mutex; 179 int profile_cpu; 180 /* 181 * Track the current task - that way we can know whether there's any 182 * weird events, such as a task being switched away that is not current. 183 */ 184 struct perf_cpu max_cpu; 185 u32 *curr_pid; 186 struct thread **curr_thread; 187 struct thread **curr_out_thread; 188 char next_shortname1; 189 char next_shortname2; 190 unsigned int replay_repeat; 191 unsigned long nr_run_events; 192 unsigned long nr_sleep_events; 193 unsigned long nr_wakeup_events; 194 unsigned long nr_sleep_corrections; 195 unsigned long nr_run_events_optimized; 196 unsigned long targetless_wakeups; 197 unsigned long multitarget_wakeups; 198 unsigned long nr_runs; 199 unsigned long nr_timestamps; 200 unsigned long nr_unordered_timestamps; 201 unsigned long nr_context_switch_bugs; 202 unsigned long nr_events; 203 unsigned long nr_lost_chunks; 204 unsigned long nr_lost_events; 205 u64 run_measurement_overhead; 206 u64 sleep_measurement_overhead; 207 u64 start_time; 208 u64 cpu_usage; 209 u64 runavg_cpu_usage; 210 u64 parent_cpu_usage; 211 u64 runavg_parent_cpu_usage; 212 u64 sum_runtime; 213 u64 sum_fluct; 214 u64 run_avg; 215 u64 all_runtime; 216 u64 all_count; 217 u64 *cpu_last_switched; 218 struct rb_root_cached atom_root, sorted_atom_root, merged_atom_root; 219 struct list_head sort_list, cmp_pid; 220 bool force; 221 bool skip_merge; 222 struct perf_sched_map map; 223 224 /* options for timehist command */ 225 bool summary; 226 bool summary_only; 227 bool idle_hist; 228 bool show_callchain; 229 unsigned int max_stack; 230 bool show_cpu_visual; 231 bool show_wakeups; 232 bool show_next; 233 bool show_migrations; 234 bool pre_migrations; 235 bool show_state; 236 bool show_prio; 237 u64 skipped_samples; 238 const char *time_str; 239 struct perf_time_interval ptime; 240 struct perf_time_interval hist_time; 241 volatile bool thread_funcs_exit; 242 const char *prio_str; 243 DECLARE_BITMAP(prio_bitmap, MAX_PRIO); 244 245 struct perf_session *session; 246 struct perf_data *data; 247 }; 248 249 /* per thread run time data */ 250 struct thread_runtime { 251 u64 last_time; /* time of previous sched in/out event */ 252 u64 dt_run; /* run time */ 253 u64 dt_sleep; /* time between CPU access by sleep (off cpu) */ 254 u64 dt_iowait; /* time between CPU access by iowait (off cpu) */ 255 u64 dt_preempt; /* time between CPU access by preempt (off cpu) */ 256 u64 dt_delay; /* time between wakeup and sched-in */ 257 u64 dt_pre_mig; /* time between migration and wakeup */ 258 u64 ready_to_run; /* time of wakeup */ 259 u64 migrated; /* time when a thread is migrated */ 260 261 struct stats run_stats; 262 u64 total_run_time; 263 u64 total_sleep_time; 264 u64 total_iowait_time; 265 u64 total_preempt_time; 266 u64 total_delay_time; 267 u64 total_pre_mig_time; 268 269 char last_state; 270 271 char shortname[3]; 272 bool comm_changed; 273 274 u64 migrations; 275 276 int prio; 277 }; 278 279 /* per event run time data */ 280 struct evsel_runtime { 281 u64 *last_time; /* time this event was last seen per cpu */ 282 u32 ncpu; /* highest cpu slot allocated */ 283 }; 284 285 /* per cpu idle time data */ 286 struct idle_thread_runtime { 287 struct thread_runtime tr; 288 struct thread *last_thread; 289 struct rb_root_cached sorted_root; 290 struct callchain_root callchain; 291 struct callchain_cursor cursor; 292 }; 293 294 /* track idle times per cpu */ 295 static struct thread **idle_threads; 296 static int idle_max_cpu; 297 static char idle_comm[] = "<idle>"; 298 299 static u64 get_nsecs(void) 300 { 301 struct timespec ts; 302 303 clock_gettime(CLOCK_MONOTONIC, &ts); 304 305 return ts.tv_sec * NSEC_PER_SEC + ts.tv_nsec; 306 } 307 308 static void burn_nsecs(struct perf_sched *sched, u64 nsecs) 309 { 310 u64 T0 = get_nsecs(), T1; 311 312 do { 313 T1 = get_nsecs(); 314 } while (T1 + sched->run_measurement_overhead < T0 + nsecs); 315 } 316 317 static void sleep_nsecs(u64 nsecs) 318 { 319 struct timespec ts; 320 321 ts.tv_nsec = nsecs % 999999999; 322 ts.tv_sec = nsecs / 999999999; 323 324 nanosleep(&ts, NULL); 325 } 326 327 static void calibrate_run_measurement_overhead(struct perf_sched *sched) 328 { 329 u64 T0, T1, delta, min_delta = NSEC_PER_SEC; 330 int i; 331 332 for (i = 0; i < 10; i++) { 333 T0 = get_nsecs(); 334 burn_nsecs(sched, 0); 335 T1 = get_nsecs(); 336 delta = T1-T0; 337 min_delta = min(min_delta, delta); 338 } 339 sched->run_measurement_overhead = min_delta; 340 341 printf("run measurement overhead: %" PRIu64 " nsecs\n", min_delta); 342 } 343 344 static void calibrate_sleep_measurement_overhead(struct perf_sched *sched) 345 { 346 u64 T0, T1, delta, min_delta = NSEC_PER_SEC; 347 int i; 348 349 for (i = 0; i < 10; i++) { 350 T0 = get_nsecs(); 351 sleep_nsecs(10000); 352 T1 = get_nsecs(); 353 delta = T1-T0; 354 min_delta = min(min_delta, delta); 355 } 356 min_delta -= 10000; 357 sched->sleep_measurement_overhead = min_delta; 358 359 printf("sleep measurement overhead: %" PRIu64 " nsecs\n", min_delta); 360 } 361 362 static struct sched_atom * 363 get_new_event(struct task_desc *task, u64 timestamp) 364 { 365 struct sched_atom *event = zalloc(sizeof(*event)); 366 unsigned long idx = task->nr_events; 367 size_t size; 368 struct sched_atom **atoms_p; 369 370 if (event == NULL) { 371 pr_err("ERROR: sched: failed to allocate event\n"); 372 return NULL; 373 } 374 375 event->timestamp = timestamp; 376 event->nr = idx; 377 378 size = sizeof(struct sched_atom *) * (task->nr_events + 1); 379 atoms_p = realloc(task->atoms, size); 380 if (!atoms_p) { 381 pr_err("ERROR: sched: failed to grow atoms array\n"); 382 free(event); 383 return NULL; 384 } 385 task->atoms = atoms_p; 386 task->nr_events++; 387 388 task->atoms[idx] = event; 389 390 return event; 391 } 392 393 static struct sched_atom *last_event(struct task_desc *task) 394 { 395 if (!task->nr_events) 396 return NULL; 397 398 return task->atoms[task->nr_events - 1]; 399 } 400 401 static void add_sched_event_run(struct perf_sched *sched, struct task_desc *task, 402 u64 timestamp, u64 duration) 403 { 404 struct sched_atom *event, *curr_event = last_event(task); 405 406 /* 407 * optimize an existing RUN event by merging this one 408 * to it: 409 */ 410 if (curr_event && curr_event->type == SCHED_EVENT_RUN) { 411 sched->nr_run_events_optimized++; 412 curr_event->duration += duration; 413 return; 414 } 415 416 event = get_new_event(task, timestamp); 417 if (event == NULL) 418 return; 419 420 event->type = SCHED_EVENT_RUN; 421 event->duration = duration; 422 423 sched->nr_run_events++; 424 } 425 426 static void add_sched_event_wakeup(struct perf_sched *sched, struct task_desc *task, 427 u64 timestamp, struct task_desc *wakee) 428 { 429 struct sched_atom *event, *wakee_event; 430 431 event = get_new_event(task, timestamp); 432 if (event == NULL) 433 return; 434 event->type = SCHED_EVENT_WAKEUP; 435 event->wakee = wakee; 436 437 wakee_event = last_event(wakee); 438 if (!wakee_event || wakee_event->type != SCHED_EVENT_SLEEP) { 439 sched->targetless_wakeups++; 440 return; 441 } 442 if (wakee_event->wait_sem) { 443 sched->multitarget_wakeups++; 444 return; 445 } 446 447 wakee_event->wait_sem = zalloc(sizeof(*wakee_event->wait_sem)); 448 if (!wakee_event->wait_sem) { 449 pr_err("ERROR: sched: failed to allocate semaphore\n"); 450 return; 451 } 452 sem_init(wakee_event->wait_sem, 0, 0); 453 event->wait_sem = wakee_event->wait_sem; 454 455 sched->nr_wakeup_events++; 456 } 457 458 static void add_sched_event_sleep(struct perf_sched *sched, struct task_desc *task, 459 u64 timestamp) 460 { 461 struct sched_atom *event = get_new_event(task, timestamp); 462 463 if (event == NULL) 464 return; 465 466 event->type = SCHED_EVENT_SLEEP; 467 468 sched->nr_sleep_events++; 469 } 470 471 static struct task_desc *register_pid(struct perf_sched *sched, 472 unsigned long pid, const char *comm) 473 { 474 struct task_desc *task, **tasks_p; 475 static int pid_max; 476 477 /* perf.data is untrusted — cap pid to prevent overflow in size calculations */ 478 if (pid >= PID_MAX_LIMIT) { 479 pr_err("pid %lu exceeds limit %d, skipping\n", pid, PID_MAX_LIMIT); 480 return NULL; 481 } 482 483 if (sched->pid_to_task == NULL) { 484 if (sysctl__read_int("kernel/pid_max", &pid_max) < 0) 485 pid_max = MAX_PID; 486 sched->pid_to_task = calloc(pid_max, sizeof(struct task_desc *)); 487 if (sched->pid_to_task == NULL) 488 return NULL; 489 } 490 if (pid >= (unsigned long)pid_max) { 491 void *p = realloc(sched->pid_to_task, (pid + 1) * sizeof(struct task_desc *)); 492 493 if (p == NULL) 494 return NULL; 495 sched->pid_to_task = p; 496 while (pid >= (unsigned long)pid_max) 497 sched->pid_to_task[pid_max++] = NULL; 498 } 499 500 task = sched->pid_to_task[pid]; 501 502 if (task) 503 return task; 504 505 task = zalloc(sizeof(*task)); 506 if (task == NULL) 507 return NULL; 508 task->pid = pid; 509 if (comm) 510 strlcpy(task->comm, comm, sizeof(task->comm)); 511 /* 512 * every task starts in sleeping state - this gets ignored 513 * if there's no wakeup pointing to this sleep state: 514 */ 515 add_sched_event_sleep(sched, task, 0); 516 517 sched->pid_to_task[pid] = task; 518 tasks_p = realloc(sched->tasks, (sched->nr_tasks + 1) * sizeof(struct task_desc *)); 519 if (!tasks_p) 520 return NULL; 521 sched->tasks = tasks_p; 522 sched->tasks[sched->nr_tasks] = task; 523 task->nr = sched->nr_tasks++; 524 525 if (verbose > 0) 526 printf("registered task #%ld, PID %ld (%s)\n", sched->nr_tasks, pid, comm); 527 528 return task; 529 } 530 531 532 static void print_task_traces(struct perf_sched *sched) 533 { 534 struct task_desc *task; 535 unsigned long i; 536 537 for (i = 0; i < sched->nr_tasks; i++) { 538 task = sched->tasks[i]; 539 printf("task %6ld (%20s:%10ld), nr_events: %ld\n", 540 task->nr, task->comm, task->pid, task->nr_events); 541 } 542 } 543 544 static void add_cross_task_wakeups(struct perf_sched *sched) 545 { 546 struct task_desc *task1, *task2; 547 unsigned long i, j; 548 549 for (i = 0; i < sched->nr_tasks; i++) { 550 task1 = sched->tasks[i]; 551 j = i + 1; 552 if (j == sched->nr_tasks) 553 j = 0; 554 task2 = sched->tasks[j]; 555 add_sched_event_wakeup(sched, task1, 0, task2); 556 } 557 } 558 559 static void perf_sched__process_event(struct perf_sched *sched, 560 struct sched_atom *atom) 561 { 562 int ret = 0; 563 564 switch (atom->type) { 565 case SCHED_EVENT_RUN: 566 burn_nsecs(sched, atom->duration); 567 break; 568 case SCHED_EVENT_SLEEP: 569 if (atom->wait_sem) 570 ret = sem_wait(atom->wait_sem); 571 BUG_ON(ret); 572 break; 573 case SCHED_EVENT_WAKEUP: 574 if (atom->wait_sem) 575 ret = sem_post(atom->wait_sem); 576 BUG_ON(ret); 577 break; 578 default: 579 BUG_ON(1); 580 } 581 } 582 583 static u64 get_cpu_usage_nsec_parent(void) 584 { 585 struct rusage ru; 586 u64 sum; 587 int err; 588 589 err = getrusage(RUSAGE_SELF, &ru); 590 BUG_ON(err); 591 592 sum = ru.ru_utime.tv_sec * NSEC_PER_SEC + ru.ru_utime.tv_usec * NSEC_PER_USEC; 593 sum += ru.ru_stime.tv_sec * NSEC_PER_SEC + ru.ru_stime.tv_usec * NSEC_PER_USEC; 594 595 return sum; 596 } 597 598 static int self_open_counters(struct perf_sched *sched, unsigned long cur_task) 599 { 600 struct perf_event_attr attr; 601 char sbuf[STRERR_BUFSIZE], info[STRERR_BUFSIZE]; 602 int fd; 603 struct rlimit limit; 604 bool need_privilege = false; 605 606 memset(&attr, 0, sizeof(attr)); 607 608 attr.type = PERF_TYPE_SOFTWARE; 609 attr.config = PERF_COUNT_SW_TASK_CLOCK; 610 611 force_again: 612 fd = sys_perf_event_open(&attr, 0, -1, -1, 613 perf_event_open_cloexec_flag()); 614 615 if (fd < 0) { 616 if (errno == EMFILE) { 617 if (sched->force) { 618 BUG_ON(getrlimit(RLIMIT_NOFILE, &limit) == -1); 619 limit.rlim_cur += sched->nr_tasks - cur_task; 620 if (limit.rlim_cur > limit.rlim_max) { 621 limit.rlim_max = limit.rlim_cur; 622 need_privilege = true; 623 } 624 if (setrlimit(RLIMIT_NOFILE, &limit) == -1) { 625 if (need_privilege && errno == EPERM) 626 strcpy(info, "Need privilege\n"); 627 } else 628 goto force_again; 629 } else 630 strcpy(info, "Have a try with -f option\n"); 631 } 632 pr_err("Error: sys_perf_event_open() syscall returned " 633 "with %d (%s)\n%s", fd, 634 str_error_r(errno, sbuf, sizeof(sbuf)), info); 635 exit(EXIT_FAILURE); 636 } 637 return fd; 638 } 639 640 static u64 get_cpu_usage_nsec_self(int fd) 641 { 642 u64 runtime; 643 int ret; 644 645 ret = read(fd, &runtime, sizeof(runtime)); 646 BUG_ON(ret != sizeof(runtime)); 647 648 return runtime; 649 } 650 651 struct sched_thread_parms { 652 struct task_desc *task; 653 struct perf_sched *sched; 654 int fd; 655 }; 656 657 static void *thread_func(void *ctx) 658 { 659 struct sched_thread_parms *parms = ctx; 660 struct task_desc *this_task = parms->task; 661 struct perf_sched *sched = parms->sched; 662 u64 cpu_usage_0, cpu_usage_1; 663 unsigned long i, ret; 664 char comm2[22]; 665 int fd = parms->fd; 666 667 zfree(&parms); 668 669 sprintf(comm2, ":%s", this_task->comm); 670 prctl(PR_SET_NAME, comm2); 671 if (fd < 0) 672 return NULL; 673 674 while (!sched->thread_funcs_exit) { 675 ret = sem_post(&this_task->ready_for_work); 676 BUG_ON(ret); 677 mutex_lock(&sched->start_work_mutex); 678 mutex_unlock(&sched->start_work_mutex); 679 680 cpu_usage_0 = get_cpu_usage_nsec_self(fd); 681 682 for (i = 0; i < this_task->nr_events; i++) { 683 this_task->curr_event = i; 684 perf_sched__process_event(sched, this_task->atoms[i]); 685 } 686 687 cpu_usage_1 = get_cpu_usage_nsec_self(fd); 688 this_task->cpu_usage = cpu_usage_1 - cpu_usage_0; 689 ret = sem_post(&this_task->work_done_sem); 690 BUG_ON(ret); 691 692 mutex_lock(&sched->work_done_wait_mutex); 693 mutex_unlock(&sched->work_done_wait_mutex); 694 } 695 return NULL; 696 } 697 698 static void create_tasks(struct perf_sched *sched) 699 EXCLUSIVE_LOCK_FUNCTION(sched->start_work_mutex) 700 EXCLUSIVE_LOCK_FUNCTION(sched->work_done_wait_mutex) 701 { 702 struct task_desc *task; 703 pthread_attr_t attr; 704 unsigned long i; 705 int err; 706 707 err = pthread_attr_init(&attr); 708 BUG_ON(err); 709 err = pthread_attr_setstacksize(&attr, 710 (size_t) max(16 * 1024, (int)PTHREAD_STACK_MIN)); 711 BUG_ON(err); 712 mutex_lock(&sched->start_work_mutex); 713 mutex_lock(&sched->work_done_wait_mutex); 714 for (i = 0; i < sched->nr_tasks; i++) { 715 struct sched_thread_parms *parms = malloc(sizeof(*parms)); 716 BUG_ON(parms == NULL); 717 parms->task = task = sched->tasks[i]; 718 parms->sched = sched; 719 parms->fd = self_open_counters(sched, i); 720 sem_init(&task->ready_for_work, 0, 0); 721 sem_init(&task->work_done_sem, 0, 0); 722 task->curr_event = 0; 723 err = pthread_create(&task->thread, &attr, thread_func, parms); 724 BUG_ON(err); 725 } 726 } 727 728 static void destroy_tasks(struct perf_sched *sched) 729 UNLOCK_FUNCTION(sched->start_work_mutex) 730 UNLOCK_FUNCTION(sched->work_done_wait_mutex) 731 { 732 struct task_desc *task; 733 unsigned long i; 734 int err; 735 736 mutex_unlock(&sched->start_work_mutex); 737 mutex_unlock(&sched->work_done_wait_mutex); 738 /* Get rid of threads so they won't be upset by mutex destrunction */ 739 for (i = 0; i < sched->nr_tasks; i++) { 740 task = sched->tasks[i]; 741 err = pthread_join(task->thread, NULL); 742 BUG_ON(err); 743 sem_destroy(&task->ready_for_work); 744 sem_destroy(&task->work_done_sem); 745 } 746 } 747 748 static void wait_for_tasks(struct perf_sched *sched) 749 EXCLUSIVE_LOCKS_REQUIRED(sched->work_done_wait_mutex) 750 EXCLUSIVE_LOCKS_REQUIRED(sched->start_work_mutex) 751 { 752 u64 cpu_usage_0, cpu_usage_1; 753 struct task_desc *task; 754 unsigned long i, ret; 755 756 sched->start_time = get_nsecs(); 757 sched->cpu_usage = 0; 758 mutex_unlock(&sched->work_done_wait_mutex); 759 760 for (i = 0; i < sched->nr_tasks; i++) { 761 task = sched->tasks[i]; 762 ret = sem_wait(&task->ready_for_work); 763 BUG_ON(ret); 764 sem_init(&task->ready_for_work, 0, 0); 765 } 766 mutex_lock(&sched->work_done_wait_mutex); 767 768 cpu_usage_0 = get_cpu_usage_nsec_parent(); 769 770 mutex_unlock(&sched->start_work_mutex); 771 772 for (i = 0; i < sched->nr_tasks; i++) { 773 task = sched->tasks[i]; 774 ret = sem_wait(&task->work_done_sem); 775 BUG_ON(ret); 776 sem_init(&task->work_done_sem, 0, 0); 777 sched->cpu_usage += task->cpu_usage; 778 task->cpu_usage = 0; 779 } 780 781 cpu_usage_1 = get_cpu_usage_nsec_parent(); 782 if (!sched->runavg_cpu_usage) 783 sched->runavg_cpu_usage = sched->cpu_usage; 784 sched->runavg_cpu_usage = (sched->runavg_cpu_usage * (sched->replay_repeat - 1) + sched->cpu_usage) / sched->replay_repeat; 785 786 sched->parent_cpu_usage = cpu_usage_1 - cpu_usage_0; 787 if (!sched->runavg_parent_cpu_usage) 788 sched->runavg_parent_cpu_usage = sched->parent_cpu_usage; 789 sched->runavg_parent_cpu_usage = (sched->runavg_parent_cpu_usage * (sched->replay_repeat - 1) + 790 sched->parent_cpu_usage)/sched->replay_repeat; 791 792 mutex_lock(&sched->start_work_mutex); 793 794 for (i = 0; i < sched->nr_tasks; i++) { 795 task = sched->tasks[i]; 796 task->curr_event = 0; 797 } 798 } 799 800 static void run_one_test(struct perf_sched *sched) 801 EXCLUSIVE_LOCKS_REQUIRED(sched->work_done_wait_mutex) 802 EXCLUSIVE_LOCKS_REQUIRED(sched->start_work_mutex) 803 { 804 u64 T0, T1, delta, avg_delta, fluct; 805 806 T0 = get_nsecs(); 807 wait_for_tasks(sched); 808 T1 = get_nsecs(); 809 810 delta = T1 - T0; 811 sched->sum_runtime += delta; 812 sched->nr_runs++; 813 814 avg_delta = sched->sum_runtime / sched->nr_runs; 815 if (delta < avg_delta) 816 fluct = avg_delta - delta; 817 else 818 fluct = delta - avg_delta; 819 sched->sum_fluct += fluct; 820 if (!sched->run_avg) 821 sched->run_avg = delta; 822 sched->run_avg = (sched->run_avg * (sched->replay_repeat - 1) + delta) / sched->replay_repeat; 823 824 printf("#%-3ld: %0.3f, ", sched->nr_runs, (double)delta / NSEC_PER_MSEC); 825 826 printf("ravg: %0.2f, ", (double)sched->run_avg / NSEC_PER_MSEC); 827 828 printf("cpu: %0.2f / %0.2f", 829 (double)sched->cpu_usage / NSEC_PER_MSEC, (double)sched->runavg_cpu_usage / NSEC_PER_MSEC); 830 831 #if 0 832 /* 833 * rusage statistics done by the parent, these are less 834 * accurate than the sched->sum_exec_runtime based statistics: 835 */ 836 printf(" [%0.2f / %0.2f]", 837 (double)sched->parent_cpu_usage / NSEC_PER_MSEC, 838 (double)sched->runavg_parent_cpu_usage / NSEC_PER_MSEC); 839 #endif 840 841 printf("\n"); 842 843 if (sched->nr_sleep_corrections) 844 printf(" (%ld sleep corrections)\n", sched->nr_sleep_corrections); 845 sched->nr_sleep_corrections = 0; 846 } 847 848 static void test_calibrations(struct perf_sched *sched) 849 { 850 u64 T0, T1; 851 852 T0 = get_nsecs(); 853 burn_nsecs(sched, NSEC_PER_MSEC); 854 T1 = get_nsecs(); 855 856 printf("the run test took %" PRIu64 " nsecs\n", T1 - T0); 857 858 T0 = get_nsecs(); 859 sleep_nsecs(NSEC_PER_MSEC); 860 T1 = get_nsecs(); 861 862 printf("the sleep test took %" PRIu64 " nsecs\n", T1 - T0); 863 } 864 865 static int 866 replay_wakeup_event(struct perf_sched *sched, 867 struct perf_sample *sample, 868 struct machine *machine __maybe_unused) 869 { 870 const char *comm = perf_sample__strval(sample, "comm"); 871 const u32 pid = perf_sample__intval(sample, "pid"); 872 struct task_desc *waker, *wakee; 873 874 if (verbose > 0) { 875 printf("sched_wakeup event %p\n", sample->evsel); 876 877 printf(" ... pid %d woke up %s/%d\n", sample->tid, comm, pid); 878 } 879 880 waker = register_pid(sched, sample->tid, "<unknown>"); 881 wakee = register_pid(sched, pid, comm); 882 if (waker == NULL || wakee == NULL) 883 return -1; 884 885 add_sched_event_wakeup(sched, waker, sample->time, wakee); 886 return 0; 887 } 888 889 static int replay_switch_event(struct perf_sched *sched, 890 struct perf_sample *sample, 891 struct machine *machine __maybe_unused) 892 { 893 const char *prev_comm = perf_sample__strval(sample, "prev_comm"), 894 *next_comm = perf_sample__strval(sample, "next_comm"); 895 const u32 prev_pid = perf_sample__intval(sample, "prev_pid"), 896 next_pid = perf_sample__intval(sample, "next_pid"); 897 struct task_desc *prev, __maybe_unused *next; 898 u64 timestamp0, timestamp = sample->time; 899 int cpu = sample->cpu; 900 s64 delta; 901 902 if (verbose > 0) 903 printf("sched_switch event %p\n", sample->evsel); 904 905 if (cpu >= MAX_CPUS || cpu < 0) 906 return 0; 907 908 timestamp0 = sched->cpu_last_switched[cpu]; 909 if (timestamp0) 910 delta = timestamp - timestamp0; 911 else 912 delta = 0; 913 914 if (delta < 0) { 915 pr_err("hm, delta: %" PRIu64 " < 0 ?\n", delta); 916 return -1; 917 } 918 919 pr_debug(" ... switch from %s/%d to %s/%d [ran %" PRIu64 " nsecs]\n", 920 prev_comm, prev_pid, next_comm, next_pid, delta); 921 922 prev = register_pid(sched, prev_pid, prev_comm); 923 next = register_pid(sched, next_pid, next_comm); 924 if (prev == NULL || next == NULL) 925 return -1; 926 927 sched->cpu_last_switched[cpu] = timestamp; 928 929 add_sched_event_run(sched, prev, timestamp, delta); 930 add_sched_event_sleep(sched, prev, timestamp); 931 932 return 0; 933 } 934 935 static int replay_fork_event(struct perf_sched *sched, 936 union perf_event *event, 937 struct machine *machine) 938 { 939 struct thread *child, *parent; 940 941 child = machine__findnew_thread(machine, event->fork.pid, 942 event->fork.tid); 943 parent = machine__findnew_thread(machine, event->fork.ppid, 944 event->fork.ptid); 945 946 if (child == NULL || parent == NULL) { 947 pr_debug("thread does not exist on fork event: child %p, parent %p\n", 948 child, parent); 949 goto out_put; 950 } 951 952 if (verbose > 0) { 953 printf("fork event\n"); 954 printf("... parent: %s/%d\n", thread__comm_str(parent), thread__tid(parent)); 955 printf("... child: %s/%d\n", thread__comm_str(child), thread__tid(child)); 956 } 957 958 register_pid(sched, thread__tid(parent), thread__comm_str(parent)); 959 register_pid(sched, thread__tid(child), thread__comm_str(child)); 960 out_put: 961 thread__put(child); 962 thread__put(parent); 963 return 0; 964 } 965 966 struct sort_dimension { 967 const char *name; 968 sort_fn_t cmp; 969 struct list_head list; 970 }; 971 972 static inline void init_prio(struct thread_runtime *r) 973 { 974 r->prio = -1; 975 } 976 977 /* 978 * handle runtime stats saved per thread 979 */ 980 static struct thread_runtime *thread__init_runtime(struct thread *thread) 981 { 982 struct thread_runtime *r; 983 984 r = zalloc(sizeof(struct thread_runtime)); 985 if (!r) 986 return NULL; 987 988 init_stats(&r->run_stats); 989 init_prio(r); 990 thread__set_priv(thread, r); 991 992 return r; 993 } 994 995 static struct thread_runtime *thread__get_runtime(struct thread *thread) 996 { 997 struct thread_runtime *tr; 998 999 tr = thread__priv(thread); 1000 if (tr == NULL) { 1001 tr = thread__init_runtime(thread); 1002 if (tr == NULL) 1003 pr_debug("Failed to malloc memory for runtime data.\n"); 1004 } 1005 1006 return tr; 1007 } 1008 1009 static int 1010 thread_lat_cmp(struct list_head *list, struct work_atoms *l, struct work_atoms *r) 1011 { 1012 struct sort_dimension *sort; 1013 int ret = 0; 1014 1015 BUG_ON(list_empty(list)); 1016 1017 list_for_each_entry(sort, list, list) { 1018 ret = sort->cmp(l, r); 1019 if (ret) 1020 return ret; 1021 } 1022 1023 return ret; 1024 } 1025 1026 static struct work_atoms * 1027 thread_atoms_search(struct rb_root_cached *root, struct thread *thread, 1028 struct list_head *sort_list) 1029 { 1030 struct rb_node *node = root->rb_root.rb_node; 1031 struct work_atoms key = { .thread = thread }; 1032 1033 while (node) { 1034 struct work_atoms *atoms; 1035 int cmp; 1036 1037 atoms = container_of(node, struct work_atoms, node); 1038 1039 cmp = thread_lat_cmp(sort_list, &key, atoms); 1040 if (cmp > 0) 1041 node = node->rb_left; 1042 else if (cmp < 0) 1043 node = node->rb_right; 1044 else { 1045 BUG_ON(!RC_CHK_EQUAL(thread, atoms->thread)); 1046 return atoms; 1047 } 1048 } 1049 return NULL; 1050 } 1051 1052 static void 1053 __thread_latency_insert(struct rb_root_cached *root, struct work_atoms *data, 1054 struct list_head *sort_list) 1055 { 1056 struct rb_node **new = &(root->rb_root.rb_node), *parent = NULL; 1057 bool leftmost = true; 1058 1059 while (*new) { 1060 struct work_atoms *this; 1061 int cmp; 1062 1063 this = container_of(*new, struct work_atoms, node); 1064 parent = *new; 1065 1066 cmp = thread_lat_cmp(sort_list, data, this); 1067 1068 if (cmp > 0) 1069 new = &((*new)->rb_left); 1070 else { 1071 new = &((*new)->rb_right); 1072 leftmost = false; 1073 } 1074 } 1075 1076 rb_link_node(&data->node, parent, new); 1077 rb_insert_color_cached(&data->node, root, leftmost); 1078 } 1079 1080 static int thread_atoms_insert(struct perf_sched *sched, struct thread *thread) 1081 { 1082 struct work_atoms *atoms = zalloc(sizeof(*atoms)); 1083 if (!atoms) { 1084 pr_err("No memory at %s\n", __func__); 1085 return -1; 1086 } 1087 1088 atoms->thread = thread__get(thread); 1089 INIT_LIST_HEAD(&atoms->work_list); 1090 __thread_latency_insert(&sched->atom_root, atoms, &sched->cmp_pid); 1091 return 0; 1092 } 1093 1094 static int 1095 add_sched_out_event(struct work_atoms *atoms, 1096 char run_state, 1097 u64 timestamp) 1098 { 1099 struct work_atom *atom = zalloc(sizeof(*atom)); 1100 if (!atom) { 1101 pr_err("Non memory at %s", __func__); 1102 return -1; 1103 } 1104 1105 atom->sched_out_time = timestamp; 1106 1107 if (run_state == 'R') { 1108 atom->state = THREAD_WAIT_CPU; 1109 atom->wake_up_time = atom->sched_out_time; 1110 } 1111 1112 list_add_tail(&atom->list, &atoms->work_list); 1113 return 0; 1114 } 1115 1116 static void 1117 add_runtime_event(struct work_atoms *atoms, u64 delta, 1118 u64 timestamp __maybe_unused) 1119 { 1120 struct work_atom *atom; 1121 1122 BUG_ON(list_empty(&atoms->work_list)); 1123 1124 atom = list_entry(atoms->work_list.prev, struct work_atom, list); 1125 1126 atom->runtime += delta; 1127 atoms->total_runtime += delta; 1128 } 1129 1130 static void 1131 add_sched_in_event(struct work_atoms *atoms, u64 timestamp) 1132 { 1133 struct work_atom *atom; 1134 u64 delta; 1135 1136 if (list_empty(&atoms->work_list)) 1137 return; 1138 1139 atom = list_entry(atoms->work_list.prev, struct work_atom, list); 1140 1141 if (atom->state != THREAD_WAIT_CPU) 1142 return; 1143 1144 if (timestamp < atom->wake_up_time) { 1145 atom->state = THREAD_IGNORE; 1146 return; 1147 } 1148 1149 atom->state = THREAD_SCHED_IN; 1150 atom->sched_in_time = timestamp; 1151 1152 delta = atom->sched_in_time - atom->wake_up_time; 1153 atoms->total_lat += delta; 1154 if (delta > atoms->max_lat) { 1155 atoms->max_lat = delta; 1156 atoms->max_lat_start = atom->wake_up_time; 1157 atoms->max_lat_end = timestamp; 1158 } 1159 atoms->nb_atoms++; 1160 } 1161 1162 static void free_work_atoms(struct work_atoms *atoms) 1163 { 1164 struct work_atom *atom, *tmp; 1165 1166 if (atoms == NULL) 1167 return; 1168 1169 list_for_each_entry_safe(atom, tmp, &atoms->work_list, list) { 1170 list_del(&atom->list); 1171 free(atom); 1172 } 1173 thread__zput(atoms->thread); 1174 free(atoms); 1175 } 1176 1177 static int latency_switch_event(struct perf_sched *sched, 1178 struct perf_sample *sample, 1179 struct machine *machine) 1180 { 1181 const u32 prev_pid = perf_sample__intval(sample, "prev_pid"), 1182 next_pid = perf_sample__intval(sample, "next_pid"); 1183 const char prev_state = perf_sample__taskstate(sample, "prev_state"); 1184 struct work_atoms *out_events, *in_events; 1185 struct thread *sched_out, *sched_in; 1186 u64 timestamp0, timestamp = sample->time; 1187 int cpu = sample->cpu, err = -1; 1188 s64 delta; 1189 1190 /* perf.data is untrusted input — CPU may be absent or corrupted */ 1191 if (cpu >= MAX_CPUS || cpu < 0) { 1192 pr_warning("WARNING: at offset %#" PRIx64 ": out-of-bound sample CPU %d, skipping sample\n", 1193 sample->file_offset, cpu); 1194 return 0; 1195 } 1196 1197 timestamp0 = sched->cpu_last_switched[cpu]; 1198 sched->cpu_last_switched[cpu] = timestamp; 1199 if (timestamp0) 1200 delta = timestamp - timestamp0; 1201 else 1202 delta = 0; 1203 1204 if (delta < 0) { 1205 pr_err("hm, delta: %" PRIu64 " < 0 ?\n", delta); 1206 return -1; 1207 } 1208 1209 sched_out = machine__findnew_thread(machine, -1, prev_pid); 1210 sched_in = machine__findnew_thread(machine, -1, next_pid); 1211 if (sched_out == NULL || sched_in == NULL) 1212 goto out_put; 1213 1214 out_events = thread_atoms_search(&sched->atom_root, sched_out, &sched->cmp_pid); 1215 if (!out_events) { 1216 if (thread_atoms_insert(sched, sched_out)) 1217 goto out_put; 1218 out_events = thread_atoms_search(&sched->atom_root, sched_out, &sched->cmp_pid); 1219 if (!out_events) { 1220 pr_err("out-event: Internal tree error"); 1221 goto out_put; 1222 } 1223 } 1224 if (add_sched_out_event(out_events, prev_state, timestamp)) 1225 goto out_put; 1226 1227 in_events = thread_atoms_search(&sched->atom_root, sched_in, &sched->cmp_pid); 1228 if (!in_events) { 1229 if (thread_atoms_insert(sched, sched_in)) 1230 goto out_put; 1231 in_events = thread_atoms_search(&sched->atom_root, sched_in, &sched->cmp_pid); 1232 if (!in_events) { 1233 pr_err("in-event: Internal tree error"); 1234 goto out_put; 1235 } 1236 /* 1237 * Take came in we have not heard about yet, 1238 * add in an initial atom in runnable state: 1239 */ 1240 if (add_sched_out_event(in_events, 'R', timestamp)) 1241 goto out_put; 1242 } 1243 add_sched_in_event(in_events, timestamp); 1244 err = 0; 1245 out_put: 1246 thread__put(sched_out); 1247 thread__put(sched_in); 1248 return err; 1249 } 1250 1251 static int latency_runtime_event(struct perf_sched *sched, 1252 struct perf_sample *sample, 1253 struct machine *machine) 1254 { 1255 const u32 pid = perf_sample__intval(sample, "pid"); 1256 const u64 runtime = perf_sample__intval(sample, "runtime"); 1257 struct thread *thread = machine__findnew_thread(machine, -1, pid); 1258 struct work_atoms *atoms; 1259 u64 timestamp = sample->time; 1260 int cpu = sample->cpu, err = -1; 1261 1262 if (thread == NULL) 1263 return -1; 1264 1265 atoms = thread_atoms_search(&sched->atom_root, thread, &sched->cmp_pid); 1266 1267 /* perf.data is untrusted input — CPU may be absent or corrupted */ 1268 if (cpu >= MAX_CPUS || cpu < 0) { 1269 pr_warning("WARNING: at offset %#" PRIx64 ": out-of-bound sample CPU %d, skipping sample\n", 1270 sample->file_offset, cpu); 1271 err = 0; 1272 goto out_put; 1273 } 1274 if (!atoms) { 1275 if (thread_atoms_insert(sched, thread)) 1276 goto out_put; 1277 atoms = thread_atoms_search(&sched->atom_root, thread, &sched->cmp_pid); 1278 if (!atoms) { 1279 pr_err("in-event: Internal tree error"); 1280 goto out_put; 1281 } 1282 if (add_sched_out_event(atoms, 'R', timestamp)) 1283 goto out_put; 1284 } 1285 1286 add_runtime_event(atoms, runtime, timestamp); 1287 err = 0; 1288 out_put: 1289 thread__put(thread); 1290 return err; 1291 } 1292 1293 static int latency_wakeup_event(struct perf_sched *sched, 1294 struct perf_sample *sample, 1295 struct machine *machine) 1296 { 1297 const u32 pid = perf_sample__intval(sample, "pid"); 1298 struct work_atoms *atoms; 1299 struct work_atom *atom; 1300 struct thread *wakee; 1301 u64 timestamp = sample->time; 1302 int err = -1; 1303 1304 wakee = machine__findnew_thread(machine, -1, pid); 1305 if (wakee == NULL) 1306 return -1; 1307 atoms = thread_atoms_search(&sched->atom_root, wakee, &sched->cmp_pid); 1308 if (!atoms) { 1309 if (thread_atoms_insert(sched, wakee)) 1310 goto out_put; 1311 atoms = thread_atoms_search(&sched->atom_root, wakee, &sched->cmp_pid); 1312 if (!atoms) { 1313 pr_err("wakeup-event: Internal tree error"); 1314 goto out_put; 1315 } 1316 if (add_sched_out_event(atoms, 'S', timestamp)) 1317 goto out_put; 1318 } 1319 1320 BUG_ON(list_empty(&atoms->work_list)); 1321 1322 atom = list_entry(atoms->work_list.prev, struct work_atom, list); 1323 1324 /* 1325 * As we do not guarantee the wakeup event happens when 1326 * task is out of run queue, also may happen when task is 1327 * on run queue and wakeup only change ->state to TASK_RUNNING, 1328 * then we should not set the ->wake_up_time when wake up a 1329 * task which is on run queue. 1330 * 1331 * You WILL be missing events if you've recorded only 1332 * one CPU, or are only looking at only one, so don't 1333 * skip in this case. 1334 */ 1335 if (sched->profile_cpu == -1 && atom->state != THREAD_SLEEPING) 1336 goto out_ok; 1337 1338 sched->nr_timestamps++; 1339 if (atom->sched_out_time > timestamp) { 1340 sched->nr_unordered_timestamps++; 1341 goto out_ok; 1342 } 1343 1344 atom->state = THREAD_WAIT_CPU; 1345 atom->wake_up_time = timestamp; 1346 out_ok: 1347 err = 0; 1348 out_put: 1349 thread__put(wakee); 1350 return err; 1351 } 1352 1353 static int latency_migrate_task_event(struct perf_sched *sched, 1354 struct perf_sample *sample, 1355 struct machine *machine) 1356 { 1357 const u32 pid = perf_sample__intval(sample, "pid"); 1358 u64 timestamp = sample->time; 1359 struct work_atoms *atoms; 1360 struct work_atom *atom; 1361 struct thread *migrant; 1362 int err = -1; 1363 1364 /* 1365 * Only need to worry about migration when profiling one CPU. 1366 */ 1367 if (sched->profile_cpu == -1) 1368 return 0; 1369 1370 migrant = machine__findnew_thread(machine, -1, pid); 1371 if (migrant == NULL) 1372 return -1; 1373 atoms = thread_atoms_search(&sched->atom_root, migrant, &sched->cmp_pid); 1374 if (!atoms) { 1375 if (thread_atoms_insert(sched, migrant)) 1376 goto out_put; 1377 register_pid(sched, thread__tid(migrant), thread__comm_str(migrant)); 1378 atoms = thread_atoms_search(&sched->atom_root, migrant, &sched->cmp_pid); 1379 if (!atoms) { 1380 pr_err("migration-event: Internal tree error"); 1381 goto out_put; 1382 } 1383 if (add_sched_out_event(atoms, 'R', timestamp)) 1384 goto out_put; 1385 } 1386 1387 BUG_ON(list_empty(&atoms->work_list)); 1388 1389 atom = list_entry(atoms->work_list.prev, struct work_atom, list); 1390 atom->sched_in_time = atom->sched_out_time = atom->wake_up_time = timestamp; 1391 1392 sched->nr_timestamps++; 1393 1394 if (atom->sched_out_time > timestamp) 1395 sched->nr_unordered_timestamps++; 1396 err = 0; 1397 out_put: 1398 thread__put(migrant); 1399 return err; 1400 } 1401 1402 static void output_lat_thread(struct perf_sched *sched, struct work_atoms *work_list) 1403 { 1404 int i; 1405 int ret; 1406 u64 avg; 1407 char max_lat_start[32], max_lat_end[32]; 1408 1409 if (!work_list->nb_atoms) 1410 return; 1411 /* 1412 * Ignore idle threads: 1413 */ 1414 if (!strcmp(thread__comm_str(work_list->thread), "swapper")) 1415 return; 1416 1417 sched->all_runtime += work_list->total_runtime; 1418 sched->all_count += work_list->nb_atoms; 1419 1420 if (work_list->num_merged > 1) { 1421 ret = printf(" %s:(%d) ", thread__comm_str(work_list->thread), 1422 work_list->num_merged); 1423 } else { 1424 ret = printf(" %s:%d ", thread__comm_str(work_list->thread), 1425 thread__tid(work_list->thread)); 1426 } 1427 1428 for (i = 0; i < 24 - ret; i++) 1429 printf(" "); 1430 1431 avg = work_list->total_lat / work_list->nb_atoms; 1432 timestamp__scnprintf_usec(work_list->max_lat_start, max_lat_start, sizeof(max_lat_start)); 1433 timestamp__scnprintf_usec(work_list->max_lat_end, max_lat_end, sizeof(max_lat_end)); 1434 1435 printf("|%11.3f ms |%9" PRIu64 " | avg:%8.3f ms | max:%8.3f ms | max start: %12s s | max end: %12s s\n", 1436 (double)work_list->total_runtime / NSEC_PER_MSEC, 1437 work_list->nb_atoms, (double)avg / NSEC_PER_MSEC, 1438 (double)work_list->max_lat / NSEC_PER_MSEC, 1439 max_lat_start, max_lat_end); 1440 } 1441 1442 static int pid_cmp(struct work_atoms *l, struct work_atoms *r) 1443 { 1444 pid_t l_tid, r_tid; 1445 1446 if (RC_CHK_EQUAL(l->thread, r->thread)) 1447 return 0; 1448 l_tid = thread__tid(l->thread); 1449 r_tid = thread__tid(r->thread); 1450 if (l_tid < r_tid) 1451 return -1; 1452 if (l_tid > r_tid) 1453 return 1; 1454 return (int)(RC_CHK_ACCESS(l->thread) - RC_CHK_ACCESS(r->thread)); 1455 } 1456 1457 static int avg_cmp(struct work_atoms *l, struct work_atoms *r) 1458 { 1459 u64 avgl, avgr; 1460 1461 if (!l->nb_atoms) 1462 return -1; 1463 1464 if (!r->nb_atoms) 1465 return 1; 1466 1467 avgl = l->total_lat / l->nb_atoms; 1468 avgr = r->total_lat / r->nb_atoms; 1469 1470 if (avgl < avgr) 1471 return -1; 1472 if (avgl > avgr) 1473 return 1; 1474 1475 return 0; 1476 } 1477 1478 static int max_cmp(struct work_atoms *l, struct work_atoms *r) 1479 { 1480 if (l->max_lat < r->max_lat) 1481 return -1; 1482 if (l->max_lat > r->max_lat) 1483 return 1; 1484 1485 return 0; 1486 } 1487 1488 static int switch_cmp(struct work_atoms *l, struct work_atoms *r) 1489 { 1490 if (l->nb_atoms < r->nb_atoms) 1491 return -1; 1492 if (l->nb_atoms > r->nb_atoms) 1493 return 1; 1494 1495 return 0; 1496 } 1497 1498 static int runtime_cmp(struct work_atoms *l, struct work_atoms *r) 1499 { 1500 if (l->total_runtime < r->total_runtime) 1501 return -1; 1502 if (l->total_runtime > r->total_runtime) 1503 return 1; 1504 1505 return 0; 1506 } 1507 1508 static int sort_dimension__add(const char *tok, struct list_head *list) 1509 { 1510 size_t i; 1511 static struct sort_dimension avg_sort_dimension = { 1512 .name = "avg", 1513 .cmp = avg_cmp, 1514 }; 1515 static struct sort_dimension max_sort_dimension = { 1516 .name = "max", 1517 .cmp = max_cmp, 1518 }; 1519 static struct sort_dimension pid_sort_dimension = { 1520 .name = "pid", 1521 .cmp = pid_cmp, 1522 }; 1523 static struct sort_dimension runtime_sort_dimension = { 1524 .name = "runtime", 1525 .cmp = runtime_cmp, 1526 }; 1527 static struct sort_dimension switch_sort_dimension = { 1528 .name = "switch", 1529 .cmp = switch_cmp, 1530 }; 1531 struct sort_dimension *available_sorts[] = { 1532 &pid_sort_dimension, 1533 &avg_sort_dimension, 1534 &max_sort_dimension, 1535 &switch_sort_dimension, 1536 &runtime_sort_dimension, 1537 }; 1538 1539 for (i = 0; i < ARRAY_SIZE(available_sorts); i++) { 1540 if (!strcmp(available_sorts[i]->name, tok)) { 1541 list_add_tail(&available_sorts[i]->list, list); 1542 1543 return 0; 1544 } 1545 } 1546 1547 return -1; 1548 } 1549 1550 static void perf_sched__sort_lat(struct perf_sched *sched) 1551 { 1552 struct rb_node *node; 1553 struct rb_root_cached *root = &sched->atom_root; 1554 again: 1555 for (;;) { 1556 struct work_atoms *data; 1557 node = rb_first_cached(root); 1558 if (!node) 1559 break; 1560 1561 rb_erase_cached(node, root); 1562 data = rb_entry(node, struct work_atoms, node); 1563 __thread_latency_insert(&sched->sorted_atom_root, data, &sched->sort_list); 1564 } 1565 if (root == &sched->atom_root) { 1566 root = &sched->merged_atom_root; 1567 goto again; 1568 } 1569 } 1570 1571 static int process_sched_wakeup_event(const struct perf_tool *tool, 1572 struct perf_sample *sample, 1573 struct machine *machine) 1574 { 1575 struct perf_sched *sched = container_of(tool, struct perf_sched, tool); 1576 1577 if (sched->tp_handler->wakeup_event) 1578 return sched->tp_handler->wakeup_event(sched, sample, machine); 1579 1580 return 0; 1581 } 1582 1583 static int process_sched_wakeup_ignore(const struct perf_tool *tool __maybe_unused, 1584 struct perf_sample *sample __maybe_unused, 1585 struct machine *machine __maybe_unused) 1586 { 1587 return 0; 1588 } 1589 1590 static bool thread__has_color(struct thread *thread) 1591 { 1592 return thread__priv(thread) != NULL; 1593 } 1594 1595 static struct thread* 1596 map__findnew_thread(struct perf_sched *sched, struct machine *machine, pid_t pid, pid_t tid) 1597 { 1598 struct thread *thread = machine__findnew_thread(machine, pid, tid); 1599 bool color = false; 1600 1601 if (!sched->map.color_pids || !thread || thread__priv(thread)) 1602 return thread; 1603 1604 if (thread_map__has(sched->map.color_pids, tid)) 1605 color = true; 1606 1607 thread__set_priv(thread, color ? ((void*)1) : NULL); 1608 return thread; 1609 } 1610 1611 static bool sched_match_task(struct perf_sched *sched, const char *comm_str) 1612 { 1613 bool fuzzy_match = sched->map.fuzzy; 1614 struct strlist *task_names = sched->map.task_names; 1615 struct str_node *node; 1616 1617 strlist__for_each_entry(node, task_names) { 1618 bool match_found = fuzzy_match ? !!strstr(comm_str, node->s) : 1619 !strcmp(comm_str, node->s); 1620 if (match_found) 1621 return true; 1622 } 1623 1624 return false; 1625 } 1626 1627 static void print_sched_map(struct perf_sched *sched, struct perf_cpu this_cpu, int cpus_nr, 1628 const char *color, bool sched_out) 1629 { 1630 for (int i = 0; i < cpus_nr; i++) { 1631 struct perf_cpu cpu = { 1632 .cpu = sched->map.comp ? sched->map.comp_cpus[i].cpu : i, 1633 }; 1634 struct thread *curr_thread = sched->curr_thread[cpu.cpu]; 1635 struct thread *curr_out_thread = sched->curr_out_thread[cpu.cpu]; 1636 struct thread_runtime *curr_tr; 1637 const char *pid_color = color; 1638 const char *cpu_color = color; 1639 char symbol = ' '; 1640 struct thread *thread_to_check = sched_out ? curr_out_thread : curr_thread; 1641 1642 if (thread_to_check && thread__has_color(thread_to_check)) 1643 pid_color = COLOR_PIDS; 1644 1645 if (sched->map.color_cpus && perf_cpu_map__has(sched->map.color_cpus, cpu)) 1646 cpu_color = COLOR_CPUS; 1647 1648 if (cpu.cpu == this_cpu.cpu) 1649 symbol = '*'; 1650 1651 color_fprintf(stdout, cpu.cpu != this_cpu.cpu ? color : cpu_color, "%c", symbol); 1652 1653 thread_to_check = sched_out ? sched->curr_out_thread[cpu.cpu] : 1654 sched->curr_thread[cpu.cpu]; 1655 1656 if (thread_to_check) { 1657 curr_tr = thread__get_runtime(thread_to_check); 1658 if (curr_tr == NULL) 1659 return; 1660 1661 if (sched_out) { 1662 if (cpu.cpu == this_cpu.cpu) 1663 color_fprintf(stdout, color, "- "); 1664 else { 1665 curr_tr = thread__get_runtime(sched->curr_thread[cpu.cpu]); 1666 if (curr_tr != NULL) 1667 color_fprintf(stdout, pid_color, "%2s ", 1668 curr_tr->shortname); 1669 } 1670 } else 1671 color_fprintf(stdout, pid_color, "%2s ", curr_tr->shortname); 1672 } else 1673 color_fprintf(stdout, color, " "); 1674 } 1675 } 1676 1677 static int map_switch_event(struct perf_sched *sched, struct perf_sample *sample, 1678 struct machine *machine) 1679 { 1680 const u32 next_pid = perf_sample__intval(sample, "next_pid"); 1681 const u32 prev_pid = perf_sample__intval(sample, "prev_pid"); 1682 struct thread *sched_in, *sched_out; 1683 struct thread_runtime *tr; 1684 int new_shortname; 1685 u64 timestamp0, timestamp = sample->time; 1686 s64 delta; 1687 struct perf_cpu this_cpu = { 1688 .cpu = sample->cpu, 1689 }; 1690 int cpus_nr; 1691 int proceed; 1692 bool new_cpu = false; 1693 const char *color = PERF_COLOR_NORMAL; 1694 char stimestamp[32]; 1695 const char *str; 1696 int ret = -1; 1697 1698 /* perf.data is untrusted input — CPU may be absent or corrupted */ 1699 if (this_cpu.cpu >= MAX_CPUS || this_cpu.cpu < 0) { 1700 pr_warning("WARNING: at offset %#" PRIx64 ": out-of-bound sample CPU %d, skipping sample\n", 1701 sample->file_offset, this_cpu.cpu); 1702 return 0; 1703 } 1704 1705 if (this_cpu.cpu > sched->max_cpu.cpu) 1706 sched->max_cpu = this_cpu; 1707 1708 if (sched->map.comp) { 1709 cpus_nr = bitmap_weight(sched->map.comp_cpus_mask, MAX_CPUS); 1710 if (!__test_and_set_bit(this_cpu.cpu, sched->map.comp_cpus_mask)) { 1711 sched->map.comp_cpus[cpus_nr++] = this_cpu; 1712 new_cpu = true; 1713 } 1714 } else 1715 cpus_nr = sched->max_cpu.cpu + 1; 1716 1717 timestamp0 = sched->cpu_last_switched[this_cpu.cpu]; 1718 sched->cpu_last_switched[this_cpu.cpu] = timestamp; 1719 if (timestamp0) 1720 delta = timestamp - timestamp0; 1721 else 1722 delta = 0; 1723 1724 if (delta < 0) { 1725 pr_err("hm, delta: %" PRIu64 " < 0 ?\n", delta); 1726 return -1; 1727 } 1728 1729 sched_in = map__findnew_thread(sched, machine, -1, next_pid); 1730 sched_out = map__findnew_thread(sched, machine, -1, prev_pid); 1731 if (sched_in == NULL || sched_out == NULL) 1732 goto out; 1733 1734 tr = thread__get_runtime(sched_in); 1735 if (tr == NULL) 1736 goto out; 1737 1738 thread__put(sched->curr_thread[this_cpu.cpu]); 1739 thread__put(sched->curr_out_thread[this_cpu.cpu]); 1740 1741 sched->curr_thread[this_cpu.cpu] = thread__get(sched_in); 1742 sched->curr_out_thread[this_cpu.cpu] = thread__get(sched_out); 1743 1744 ret = 0; 1745 1746 str = thread__comm_str(sched_in); 1747 new_shortname = 0; 1748 if (!tr->shortname[0]) { 1749 if (!strcmp(thread__comm_str(sched_in), "swapper")) { 1750 /* 1751 * Don't allocate a letter-number for swapper:0 1752 * as a shortname. Instead, we use '.' for it. 1753 */ 1754 tr->shortname[0] = '.'; 1755 tr->shortname[1] = ' '; 1756 } else if (!sched->map.task_name || sched_match_task(sched, str)) { 1757 tr->shortname[0] = sched->next_shortname1; 1758 tr->shortname[1] = sched->next_shortname2; 1759 1760 if (sched->next_shortname1 < 'Z') { 1761 sched->next_shortname1++; 1762 } else { 1763 sched->next_shortname1 = 'A'; 1764 if (sched->next_shortname2 < '9') 1765 sched->next_shortname2++; 1766 else 1767 sched->next_shortname2 = '0'; 1768 } 1769 } else { 1770 tr->shortname[0] = '-'; 1771 tr->shortname[1] = ' '; 1772 } 1773 new_shortname = 1; 1774 } 1775 1776 if (sched->map.cpus && !perf_cpu_map__has(sched->map.cpus, this_cpu)) 1777 goto out; 1778 1779 proceed = 0; 1780 str = thread__comm_str(sched_in); 1781 /* 1782 * Check which of sched_in and sched_out matches the passed --task-name 1783 * arguments and call the corresponding print_sched_map. 1784 */ 1785 if (sched->map.task_name && !sched_match_task(sched, str)) { 1786 if (!sched_match_task(sched, thread__comm_str(sched_out))) 1787 goto out; 1788 else 1789 goto sched_out; 1790 1791 } else { 1792 str = thread__comm_str(sched_out); 1793 if (!(sched->map.task_name && !sched_match_task(sched, str))) 1794 proceed = 1; 1795 } 1796 1797 printf(" "); 1798 1799 print_sched_map(sched, this_cpu, cpus_nr, color, false); 1800 1801 timestamp__scnprintf_usec(timestamp, stimestamp, sizeof(stimestamp)); 1802 color_fprintf(stdout, color, " %12s secs ", stimestamp); 1803 if (new_shortname || tr->comm_changed || (verbose > 0 && thread__tid(sched_in))) { 1804 const char *pid_color = color; 1805 1806 if (thread__has_color(sched_in)) 1807 pid_color = COLOR_PIDS; 1808 1809 color_fprintf(stdout, pid_color, "%s => %s:%d", 1810 tr->shortname, thread__comm_str(sched_in), thread__tid(sched_in)); 1811 tr->comm_changed = false; 1812 } 1813 1814 if (sched->map.comp && new_cpu) 1815 color_fprintf(stdout, color, " (CPU %d)", this_cpu.cpu); 1816 1817 if (proceed != 1) { 1818 color_fprintf(stdout, color, "\n"); 1819 goto out; 1820 } 1821 1822 sched_out: 1823 if (sched->map.task_name) { 1824 tr = thread__get_runtime(sched->curr_out_thread[this_cpu.cpu]); 1825 if (strcmp(tr->shortname, "") == 0) 1826 goto out; 1827 1828 if (proceed == 1) 1829 color_fprintf(stdout, color, "\n"); 1830 1831 printf(" "); 1832 print_sched_map(sched, this_cpu, cpus_nr, color, true); 1833 timestamp__scnprintf_usec(timestamp, stimestamp, sizeof(stimestamp)); 1834 color_fprintf(stdout, color, " %12s secs ", stimestamp); 1835 } 1836 1837 color_fprintf(stdout, color, "\n"); 1838 1839 out: 1840 thread__put(sched_out); 1841 thread__put(sched_in); 1842 1843 return ret; 1844 } 1845 1846 static int process_sched_switch_event(const struct perf_tool *tool, 1847 struct perf_sample *sample, 1848 struct machine *machine) 1849 { 1850 struct perf_sched *sched = container_of(tool, struct perf_sched, tool); 1851 int this_cpu = sample->cpu, err = 0; 1852 u32 prev_pid = perf_sample__intval(sample, "prev_pid"), 1853 next_pid = perf_sample__intval(sample, "next_pid"); 1854 1855 /* perf.data is untrusted input — CPU may be absent or corrupted */ 1856 if (this_cpu < 0 || this_cpu >= MAX_CPUS) { 1857 pr_warning("WARNING: at offset %#" PRIx64 ": out-of-bound sample CPU %d, skipping sample\n", 1858 sample->file_offset, this_cpu); 1859 return 0; 1860 } 1861 1862 if (sched->curr_pid[this_cpu] != (u32)-1) { 1863 /* 1864 * Are we trying to switch away a PID that is 1865 * not current? 1866 */ 1867 if (sched->curr_pid[this_cpu] != prev_pid) 1868 sched->nr_context_switch_bugs++; 1869 } 1870 1871 if (sched->tp_handler->switch_event) 1872 err = sched->tp_handler->switch_event(sched, sample, machine); 1873 1874 sched->curr_pid[this_cpu] = next_pid; 1875 return err; 1876 } 1877 1878 static int process_sched_runtime_event(const struct perf_tool *tool, 1879 struct perf_sample *sample, 1880 struct machine *machine) 1881 { 1882 struct perf_sched *sched = container_of(tool, struct perf_sched, tool); 1883 1884 /* perf.data is untrusted input — CPU may be absent or corrupted */ 1885 if (sample->cpu >= MAX_CPUS) { 1886 pr_warning("WARNING: at offset %#" PRIx64 ": out-of-bound sample CPU %u, skipping sample\n", 1887 sample->file_offset, sample->cpu); 1888 return 0; 1889 } 1890 1891 if (sched->tp_handler->runtime_event) 1892 return sched->tp_handler->runtime_event(sched, sample, machine); 1893 1894 return 0; 1895 } 1896 1897 static int perf_sched__process_fork_event(const struct perf_tool *tool, 1898 union perf_event *event, 1899 struct perf_sample *sample, 1900 struct machine *machine) 1901 { 1902 struct perf_sched *sched = container_of(tool, struct perf_sched, tool); 1903 1904 /* run the fork event through the perf machinery */ 1905 perf_event__process_fork(tool, event, sample, machine); 1906 1907 /* and then run additional processing needed for this command */ 1908 if (sched->tp_handler->fork_event) 1909 return sched->tp_handler->fork_event(sched, event, machine); 1910 1911 return 0; 1912 } 1913 1914 static int process_sched_migrate_task_event(const struct perf_tool *tool, 1915 struct perf_sample *sample, 1916 struct machine *machine) 1917 { 1918 struct perf_sched *sched = container_of(tool, struct perf_sched, tool); 1919 1920 if (sched->tp_handler->migrate_task_event) 1921 return sched->tp_handler->migrate_task_event(sched, sample, machine); 1922 1923 return 0; 1924 } 1925 1926 typedef int (*tracepoint_handler)(const struct perf_tool *tool, 1927 struct perf_sample *sample, 1928 struct machine *machine); 1929 1930 static int perf_sched__process_tracepoint_sample(const struct perf_tool *tool __maybe_unused, 1931 union perf_event *event __maybe_unused, 1932 struct perf_sample *sample, 1933 struct machine *machine) 1934 { 1935 struct evsel *evsel = sample->evsel; 1936 int err = 0; 1937 1938 if (evsel->handler != NULL) { 1939 tracepoint_handler f = evsel->handler; 1940 err = f(tool, sample, machine); 1941 } 1942 1943 return err; 1944 } 1945 1946 static int perf_sched__process_comm(const struct perf_tool *tool __maybe_unused, 1947 union perf_event *event, 1948 struct perf_sample *sample, 1949 struct machine *machine) 1950 { 1951 struct thread *thread; 1952 struct thread_runtime *tr; 1953 int err; 1954 1955 err = perf_event__process_comm(tool, event, sample, machine); 1956 if (err) 1957 return err; 1958 1959 thread = machine__find_thread(machine, sample->pid, sample->tid); 1960 if (!thread) { 1961 pr_err("Internal error: can't find thread\n"); 1962 return -1; 1963 } 1964 1965 tr = thread__get_runtime(thread); 1966 if (tr == NULL) { 1967 thread__put(thread); 1968 return -1; 1969 } 1970 1971 tr->comm_changed = true; 1972 thread__put(thread); 1973 1974 return 0; 1975 } 1976 1977 static int perf_sched__read_events(struct perf_sched *sched) 1978 { 1979 struct evsel_str_handler handlers[] = { 1980 { "sched:sched_switch", process_sched_switch_event, }, 1981 { "sched:sched_stat_runtime", process_sched_runtime_event, }, 1982 { "sched:sched_wakeup", process_sched_wakeup_event, }, 1983 { "sched:sched_waking", process_sched_wakeup_event, }, 1984 { "sched:sched_wakeup_new", process_sched_wakeup_event, }, 1985 { "sched:sched_migrate_task", process_sched_migrate_task_event, }, 1986 }; 1987 struct perf_session *session; 1988 struct perf_data data = { 1989 .path = input_name, 1990 .mode = PERF_DATA_MODE_READ, 1991 .force = sched->force, 1992 }; 1993 int rc = -1; 1994 1995 session = perf_session__new(&data, &sched->tool); 1996 if (IS_ERR(session)) { 1997 pr_debug("Error creating perf session"); 1998 return PTR_ERR(session); 1999 } 2000 2001 symbol__init(perf_session__env(session)); 2002 2003 /* prefer sched_waking if it is captured */ 2004 if (evlist__find_tracepoint_by_name(session->evlist, "sched:sched_waking")) 2005 handlers[2].handler = process_sched_wakeup_ignore; 2006 2007 if (perf_session__set_tracepoints_handlers(session, handlers)) 2008 goto out_delete; 2009 2010 if (perf_session__has_traces(session, "record -R")) { 2011 int err = perf_session__process_events(session); 2012 if (err) { 2013 pr_err("Failed to process events, error %d", err); 2014 goto out_delete; 2015 } 2016 2017 sched->nr_events = session->evlist->stats.nr_events[0]; 2018 sched->nr_lost_events = session->evlist->stats.total_lost; 2019 sched->nr_lost_chunks = session->evlist->stats.nr_events[PERF_RECORD_LOST]; 2020 } 2021 2022 rc = 0; 2023 out_delete: 2024 perf_session__delete(session); 2025 return rc; 2026 } 2027 2028 /* 2029 * scheduling times are printed as msec.usec 2030 */ 2031 static inline void print_sched_time(unsigned long long nsecs, int width) 2032 { 2033 unsigned long msecs; 2034 unsigned long usecs; 2035 2036 msecs = nsecs / NSEC_PER_MSEC; 2037 nsecs -= msecs * NSEC_PER_MSEC; 2038 usecs = nsecs / NSEC_PER_USEC; 2039 printf("%*lu.%03lu ", width, msecs, usecs); 2040 } 2041 2042 /* 2043 * returns runtime data for event, allocating memory for it the 2044 * first time it is used. 2045 */ 2046 static struct evsel_runtime *evsel__get_runtime(struct evsel *evsel) 2047 { 2048 struct evsel_runtime *r = evsel->priv; 2049 2050 if (r == NULL) { 2051 r = zalloc(sizeof(struct evsel_runtime)); 2052 evsel->priv = r; 2053 } 2054 2055 return r; 2056 } 2057 2058 /* 2059 * save last time event was seen per cpu 2060 */ 2061 static void evsel__save_time(struct evsel *evsel, u64 timestamp, u32 cpu) 2062 { 2063 struct evsel_runtime *r = evsel__get_runtime(evsel); 2064 2065 if (r == NULL) 2066 return; 2067 2068 if ((cpu >= r->ncpu) || (r->last_time == NULL)) { 2069 int i, n = __roundup_pow_of_two(cpu+1); 2070 void *p = r->last_time; 2071 2072 p = realloc(r->last_time, n * sizeof(u64)); 2073 if (!p) 2074 return; 2075 2076 r->last_time = p; 2077 for (i = r->ncpu; i < n; ++i) 2078 r->last_time[i] = (u64) 0; 2079 2080 r->ncpu = n; 2081 } 2082 2083 r->last_time[cpu] = timestamp; 2084 } 2085 2086 /* returns last time this event was seen on the given cpu */ 2087 static u64 evsel__get_time(struct evsel *evsel, u32 cpu) 2088 { 2089 struct evsel_runtime *r = evsel__get_runtime(evsel); 2090 2091 if ((r == NULL) || (r->last_time == NULL) || (cpu >= r->ncpu)) 2092 return 0; 2093 2094 return r->last_time[cpu]; 2095 } 2096 2097 static void timehist__evsel_priv_destructor(void *priv) 2098 { 2099 struct evsel_runtime *r = priv; 2100 2101 if (r) { 2102 free(r->last_time); 2103 free(r); 2104 } 2105 } 2106 2107 static int comm_width = 30; 2108 2109 static char *timehist_get_commstr(struct thread *thread) 2110 { 2111 static char str[32]; 2112 const char *comm = thread__comm_str(thread); 2113 pid_t tid = thread__tid(thread); 2114 pid_t pid = thread__pid(thread); 2115 int n; 2116 2117 if (pid == 0) 2118 n = scnprintf(str, sizeof(str), "%s", comm); 2119 2120 else if (tid != pid) 2121 n = scnprintf(str, sizeof(str), "%s[%d/%d]", comm, tid, pid); 2122 2123 else 2124 n = scnprintf(str, sizeof(str), "%s[%d]", comm, tid); 2125 2126 if (n > comm_width) 2127 comm_width = n; 2128 2129 return str; 2130 } 2131 2132 /* prio field format: xxx or xxx->yyy */ 2133 #define MAX_PRIO_STR_LEN 8 2134 static char *timehist_get_priostr(struct thread *thread, 2135 struct perf_sample *sample) 2136 { 2137 static char prio_str[16]; 2138 int prev_prio = (int)perf_sample__intval(sample, "prev_prio"); 2139 struct thread_runtime *tr = thread__priv(thread); 2140 2141 if (tr->prio != prev_prio && tr->prio != -1) 2142 scnprintf(prio_str, sizeof(prio_str), "%d->%d", tr->prio, prev_prio); 2143 else 2144 scnprintf(prio_str, sizeof(prio_str), "%d", prev_prio); 2145 2146 return prio_str; 2147 } 2148 2149 static void timehist_header(struct perf_sched *sched) 2150 { 2151 u32 ncpus = sched->max_cpu.cpu + 1; 2152 u32 i, j; 2153 2154 printf("%15s %6s ", "time", "cpu"); 2155 2156 if (sched->show_cpu_visual) { 2157 printf(" "); 2158 for (i = 0, j = 0; i < ncpus; ++i) { 2159 printf("%x", j++); 2160 if (j > 15) 2161 j = 0; 2162 } 2163 printf(" "); 2164 } 2165 2166 printf(" %-*s", comm_width, "task name"); 2167 2168 if (sched->show_prio) 2169 printf(" %-*s", MAX_PRIO_STR_LEN, "prio"); 2170 2171 printf(" %9s %9s %9s", "wait time", "sch delay", "run time"); 2172 2173 if (sched->pre_migrations) 2174 printf(" %9s", "pre-mig time"); 2175 2176 if (sched->show_state) 2177 printf(" %s", "state"); 2178 2179 printf("\n"); 2180 2181 /* 2182 * units row 2183 */ 2184 printf("%15s %-6s ", "", ""); 2185 2186 if (sched->show_cpu_visual) 2187 printf(" %*s ", ncpus, ""); 2188 2189 printf(" %-*s", comm_width, "[tid/pid]"); 2190 2191 if (sched->show_prio) 2192 printf(" %-*s", MAX_PRIO_STR_LEN, ""); 2193 2194 printf(" %9s %9s %9s", "(msec)", "(msec)", "(msec)"); 2195 2196 if (sched->pre_migrations) 2197 printf(" %9s", "(msec)"); 2198 2199 printf("\n"); 2200 2201 /* 2202 * separator 2203 */ 2204 printf("%.15s %.6s ", graph_dotted_line, graph_dotted_line); 2205 2206 if (sched->show_cpu_visual) 2207 printf(" %.*s ", ncpus, graph_dotted_line); 2208 2209 printf(" %.*s", comm_width, graph_dotted_line); 2210 2211 if (sched->show_prio) 2212 printf(" %.*s", MAX_PRIO_STR_LEN, graph_dotted_line); 2213 2214 printf(" %.9s %.9s %.9s", graph_dotted_line, graph_dotted_line, graph_dotted_line); 2215 2216 if (sched->pre_migrations) 2217 printf(" %.9s", graph_dotted_line); 2218 2219 if (sched->show_state) 2220 printf(" %.5s", graph_dotted_line); 2221 2222 printf("\n"); 2223 } 2224 2225 static void timehist_print_sample(struct perf_sched *sched, 2226 struct perf_sample *sample, 2227 struct addr_location *al, 2228 struct thread *thread, 2229 u64 t, const char state) 2230 { 2231 struct thread_runtime *tr = thread__priv(thread); 2232 const char *next_comm = perf_sample__strval(sample, "next_comm"); 2233 const u32 next_pid = perf_sample__intval(sample, "next_pid"); 2234 u32 max_cpus = sched->max_cpu.cpu + 1; 2235 char tstr[64]; 2236 char nstr[30]; 2237 u64 wait_time; 2238 2239 if (cpu_list && (sample->cpu >= MAX_NR_CPUS || 2240 !test_bit(sample->cpu, cpu_bitmap))) 2241 return; 2242 2243 timestamp__scnprintf_usec(t, tstr, sizeof(tstr)); 2244 printf("%15s [%04d] ", tstr, sample->cpu); 2245 2246 if (sched->show_cpu_visual) { 2247 u32 i; 2248 char c; 2249 2250 printf(" "); 2251 for (i = 0; i < max_cpus; ++i) { 2252 /* flag idle times with 'i'; others are sched events */ 2253 if (i == sample->cpu) 2254 c = (thread__tid(thread) == 0) ? 'i' : 's'; 2255 else 2256 c = ' '; 2257 printf("%c", c); 2258 } 2259 printf(" "); 2260 } 2261 2262 if (!thread__comm_set(thread)) { 2263 const char *prev_comm = perf_sample__strval(sample, "prev_comm"); 2264 2265 thread__set_comm(thread, prev_comm, sample->time); 2266 } 2267 2268 printf(" %-*s ", comm_width, timehist_get_commstr(thread)); 2269 2270 if (sched->show_prio) 2271 printf(" %-*s ", MAX_PRIO_STR_LEN, timehist_get_priostr(thread, sample)); 2272 2273 wait_time = tr->dt_sleep + tr->dt_iowait + tr->dt_preempt; 2274 print_sched_time(wait_time, 6); 2275 2276 print_sched_time(tr->dt_delay, 6); 2277 print_sched_time(tr->dt_run, 6); 2278 if (sched->pre_migrations) 2279 print_sched_time(tr->dt_pre_mig, 6); 2280 2281 if (sched->show_state) 2282 printf(" %5c ", thread__tid(thread) == 0 ? 'I' : state); 2283 2284 if (sched->show_next) { 2285 snprintf(nstr, sizeof(nstr), "next: %s[%d]", next_comm, next_pid); 2286 printf(" %-*s", comm_width, nstr); 2287 } 2288 2289 if (sched->show_wakeups && !sched->show_next) 2290 printf(" %-*s", comm_width, ""); 2291 2292 if (thread__tid(thread) == 0) 2293 goto out; 2294 2295 if (sched->show_callchain) 2296 printf(" "); 2297 2298 sample__fprintf_sym(sample, al, 0, 2299 EVSEL__PRINT_SYM | EVSEL__PRINT_ONELINE | 2300 EVSEL__PRINT_CALLCHAIN_ARROW | 2301 EVSEL__PRINT_SKIP_IGNORED, 2302 get_tls_callchain_cursor(), symbol_conf.bt_stop_list, stdout); 2303 2304 out: 2305 printf("\n"); 2306 } 2307 2308 /* 2309 * Explanation of delta-time stats: 2310 * 2311 * t = time of current schedule out event 2312 * tprev = time of previous sched out event 2313 * also time of schedule-in event for current task 2314 * last_time = time of last sched change event for current task 2315 * (i.e, time process was last scheduled out) 2316 * ready_to_run = time of wakeup for current task 2317 * migrated = time of task migration to another CPU 2318 * 2319 * -----|-------------|-------------|-------------|-------------|----- 2320 * last ready migrated tprev t 2321 * time to run 2322 * 2323 * |---------------- dt_wait ----------------| 2324 * |--------- dt_delay ---------|-- dt_run --| 2325 * |- dt_pre_mig -| 2326 * 2327 * dt_run = run time of current task 2328 * dt_wait = time between last schedule out event for task and tprev 2329 * represents time spent off the cpu 2330 * dt_delay = time between wakeup and schedule-in of task 2331 * dt_pre_mig = time between wakeup and migration to another CPU 2332 */ 2333 2334 static void timehist_update_runtime_stats(struct thread_runtime *r, 2335 u64 t, u64 tprev) 2336 { 2337 r->dt_delay = 0; 2338 r->dt_sleep = 0; 2339 r->dt_iowait = 0; 2340 r->dt_preempt = 0; 2341 r->dt_run = 0; 2342 r->dt_pre_mig = 0; 2343 2344 if (tprev) { 2345 r->dt_run = t - tprev; 2346 if (r->ready_to_run) { 2347 if (r->ready_to_run > tprev) 2348 pr_debug("time travel: wakeup time for task > previous sched_switch event\n"); 2349 else 2350 r->dt_delay = tprev - r->ready_to_run; 2351 2352 if ((r->migrated > r->ready_to_run) && (r->migrated < tprev)) 2353 r->dt_pre_mig = r->migrated - r->ready_to_run; 2354 } 2355 2356 if (r->last_time > tprev) 2357 pr_debug("time travel: last sched out time for task > previous sched_switch event\n"); 2358 else if (r->last_time) { 2359 u64 dt_wait = tprev - r->last_time; 2360 2361 if (r->last_state == 'R') 2362 r->dt_preempt = dt_wait; 2363 else if (r->last_state == 'D') 2364 r->dt_iowait = dt_wait; 2365 else 2366 r->dt_sleep = dt_wait; 2367 } 2368 } 2369 2370 update_stats(&r->run_stats, r->dt_run); 2371 2372 r->total_run_time += r->dt_run; 2373 r->total_delay_time += r->dt_delay; 2374 r->total_sleep_time += r->dt_sleep; 2375 r->total_iowait_time += r->dt_iowait; 2376 r->total_preempt_time += r->dt_preempt; 2377 r->total_pre_mig_time += r->dt_pre_mig; 2378 } 2379 2380 static bool is_idle_sample(struct perf_sample *sample) 2381 { 2382 /* pid 0 == swapper == idle task */ 2383 if (evsel__name_is(sample->evsel, "sched:sched_switch")) 2384 return perf_sample__intval(sample, "prev_pid") == 0; 2385 2386 return sample->pid == 0; 2387 } 2388 2389 static void save_task_callchain(struct perf_sched *sched, 2390 struct perf_sample *sample, 2391 struct machine *machine) 2392 { 2393 struct callchain_cursor *cursor; 2394 struct thread *thread; 2395 2396 /* want main thread for process - has maps */ 2397 thread = machine__findnew_thread(machine, sample->pid, sample->pid); 2398 if (thread == NULL) { 2399 pr_debug("Failed to get thread for pid %d.\n", sample->pid); 2400 return; 2401 } 2402 2403 if (!sched->show_callchain || sample->callchain == NULL) { 2404 thread__put(thread); 2405 return; 2406 } 2407 2408 cursor = get_tls_callchain_cursor(); 2409 2410 if (thread__resolve_callchain(thread, cursor, sample, 2411 NULL, NULL, sched->max_stack + 2) != 0) { 2412 if (verbose > 0) 2413 pr_err("Failed to resolve callchain. Skipping\n"); 2414 2415 thread__put(thread); 2416 return; 2417 } 2418 2419 callchain_cursor_commit(cursor); 2420 thread__put(thread); 2421 2422 while (true) { 2423 struct callchain_cursor_node *node; 2424 struct symbol *sym; 2425 2426 node = callchain_cursor_current(cursor); 2427 if (node == NULL) 2428 break; 2429 2430 sym = node->ms.sym; 2431 if (sym) { 2432 if (!strcmp(sym->name, "schedule") || 2433 !strcmp(sym->name, "__schedule") || 2434 !strcmp(sym->name, "preempt_schedule")) 2435 symbol__set_ignore(sym, true); 2436 } 2437 2438 callchain_cursor_advance(cursor); 2439 } 2440 } 2441 2442 static int init_idle_thread(struct thread *thread) 2443 { 2444 struct idle_thread_runtime *itr; 2445 2446 thread__set_comm(thread, idle_comm, 0); 2447 2448 itr = zalloc(sizeof(*itr)); 2449 if (itr == NULL) 2450 return -ENOMEM; 2451 2452 init_prio(&itr->tr); 2453 init_stats(&itr->tr.run_stats); 2454 callchain_init(&itr->callchain); 2455 callchain_cursor_reset(&itr->cursor); 2456 thread__set_priv(thread, itr); 2457 2458 return 0; 2459 } 2460 2461 /* 2462 * Track idle stats per cpu by maintaining a local thread 2463 * struct for the idle task on each cpu. 2464 */ 2465 static int init_idle_threads(int ncpu) 2466 { 2467 int i, ret; 2468 2469 idle_threads = calloc(ncpu, sizeof(struct thread *)); 2470 if (!idle_threads) 2471 return -ENOMEM; 2472 2473 idle_max_cpu = ncpu; 2474 2475 /* allocate the actual thread struct if needed */ 2476 for (i = 0; i < ncpu; ++i) { 2477 idle_threads[i] = thread__new(0, 0); 2478 if (idle_threads[i] == NULL) 2479 return -ENOMEM; 2480 2481 ret = init_idle_thread(idle_threads[i]); 2482 if (ret < 0) 2483 return ret; 2484 } 2485 2486 return 0; 2487 } 2488 2489 static void free_idle_threads(void) 2490 { 2491 int i; 2492 2493 if (idle_threads == NULL) 2494 return; 2495 2496 for (i = 0; i < idle_max_cpu; ++i) { 2497 struct thread *idle = idle_threads[i]; 2498 2499 if (idle) { 2500 struct idle_thread_runtime *itr; 2501 2502 itr = thread__priv(idle); 2503 if (itr) { 2504 thread__put(itr->last_thread); 2505 free_callchain(&itr->callchain); 2506 callchain_cursor_cleanup(&itr->cursor); 2507 } 2508 2509 thread__put(idle); 2510 } 2511 } 2512 2513 free(idle_threads); 2514 } 2515 2516 static struct thread *get_idle_thread(int cpu) 2517 { 2518 /* 2519 * expand/allocate array of pointers to local thread 2520 * structs if needed 2521 */ 2522 if ((cpu >= idle_max_cpu) || (idle_threads == NULL)) { 2523 int i, j = __roundup_pow_of_two(cpu+1); 2524 void *p; 2525 2526 p = realloc(idle_threads, j * sizeof(struct thread *)); 2527 if (!p) 2528 return NULL; 2529 2530 idle_threads = (struct thread **) p; 2531 for (i = idle_max_cpu; i < j; ++i) 2532 idle_threads[i] = NULL; 2533 2534 idle_max_cpu = j; 2535 } 2536 2537 /* allocate a new thread struct if needed */ 2538 if (idle_threads[cpu] == NULL) { 2539 idle_threads[cpu] = thread__new(0, 0); 2540 2541 if (idle_threads[cpu]) { 2542 if (init_idle_thread(idle_threads[cpu]) < 0) { 2543 /* clean up so next call doesn't find a half-initialized thread */ 2544 thread__zput(idle_threads[cpu]); 2545 return NULL; 2546 } 2547 } 2548 } 2549 2550 return thread__get(idle_threads[cpu]); 2551 } 2552 2553 static void save_idle_callchain(struct perf_sched *sched, 2554 struct idle_thread_runtime *itr, 2555 struct perf_sample *sample) 2556 { 2557 struct callchain_cursor *cursor; 2558 2559 if (!sched->show_callchain || sample->callchain == NULL) 2560 return; 2561 2562 cursor = get_tls_callchain_cursor(); 2563 if (cursor == NULL) 2564 return; 2565 2566 callchain_cursor__copy(&itr->cursor, cursor); 2567 } 2568 2569 static struct thread *timehist_get_thread(struct perf_sched *sched, 2570 struct perf_sample *sample, 2571 struct machine *machine) 2572 { 2573 struct thread *thread; 2574 2575 if (is_idle_sample(sample)) { 2576 thread = get_idle_thread(sample->cpu); 2577 if (thread == NULL) 2578 pr_err("Failed to get idle thread for cpu %d.\n", sample->cpu); 2579 2580 } else { 2581 /* there were samples with tid 0 but non-zero pid */ 2582 thread = machine__findnew_thread(machine, sample->pid, 2583 sample->tid ?: sample->pid); 2584 if (thread == NULL) { 2585 pr_debug("Failed to get thread for tid %d. skipping sample.\n", 2586 sample->tid); 2587 } 2588 2589 save_task_callchain(sched, sample, machine); 2590 if (sched->idle_hist) { 2591 struct thread *idle; 2592 struct idle_thread_runtime *itr; 2593 2594 idle = get_idle_thread(sample->cpu); 2595 if (idle == NULL) { 2596 pr_err("Failed to get idle thread for cpu %d.\n", sample->cpu); 2597 thread__put(thread); 2598 return NULL; 2599 } 2600 2601 itr = thread__priv(idle); 2602 if (itr == NULL) { 2603 thread__put(idle); 2604 thread__put(thread); 2605 return NULL; 2606 } 2607 2608 thread__put(itr->last_thread); 2609 itr->last_thread = thread__get(thread); 2610 2611 /* copy task callchain when entering to idle */ 2612 if (perf_sample__intval(sample, "next_pid") == 0) 2613 save_idle_callchain(sched, itr, sample); 2614 2615 thread__put(idle); 2616 } 2617 } 2618 2619 return thread; 2620 } 2621 2622 static bool timehist_skip_sample(struct perf_sched *sched, 2623 struct thread *thread, 2624 struct perf_sample *sample) 2625 { 2626 bool rc = false; 2627 int prio = -1; 2628 struct thread_runtime *tr = NULL; 2629 2630 if (thread__is_filtered(thread)) { 2631 rc = true; 2632 sched->skipped_samples++; 2633 } 2634 2635 if (sched->prio_str) { 2636 /* 2637 * Because priority may be changed during task execution, 2638 * first read priority from prev sched_in event for current task. 2639 * If prev sched_in event is not saved, then read priority from 2640 * current task sched_out event. 2641 */ 2642 tr = thread__get_runtime(thread); 2643 if (tr && tr->prio != -1) 2644 prio = tr->prio; 2645 else if (evsel__name_is(sample->evsel, "sched:sched_switch")) 2646 prio = perf_sample__intval(sample, "prev_prio"); 2647 2648 /* negative prio means no info; out-of-range prio can't match the filter */ 2649 if (prio >= 0 && 2650 (prio >= MAX_PRIO || !test_bit(prio, sched->prio_bitmap))) { 2651 rc = true; 2652 sched->skipped_samples++; 2653 } 2654 } 2655 2656 if (sched->idle_hist) { 2657 if (!evsel__name_is(sample->evsel, "sched:sched_switch")) 2658 rc = true; 2659 else if (perf_sample__intval(sample, "prev_pid") != 0 && 2660 perf_sample__intval(sample, "next_pid") != 0) 2661 rc = true; 2662 } 2663 2664 return rc; 2665 } 2666 2667 static void timehist_print_wakeup_event(struct perf_sched *sched, 2668 struct perf_sample *sample, 2669 struct machine *machine, 2670 struct thread *awakened) 2671 { 2672 struct thread *thread; 2673 char tstr[64]; 2674 2675 thread = machine__findnew_thread(machine, sample->pid, sample->tid); 2676 if (thread == NULL) 2677 return; 2678 2679 /* show wakeup unless both awakee and awaker are filtered */ 2680 if (timehist_skip_sample(sched, thread, sample) && 2681 timehist_skip_sample(sched, awakened, sample)) { 2682 thread__put(thread); 2683 return; 2684 } 2685 2686 timestamp__scnprintf_usec(sample->time, tstr, sizeof(tstr)); 2687 printf("%15s [%04d] ", tstr, sample->cpu); 2688 if (sched->show_cpu_visual) 2689 printf(" %*s ", sched->max_cpu.cpu + 1, ""); 2690 2691 printf(" %-*s ", comm_width, timehist_get_commstr(thread)); 2692 2693 /* dt spacer */ 2694 printf(" %9s %9s %9s ", "", "", ""); 2695 2696 printf("awakened: %s", timehist_get_commstr(awakened)); 2697 2698 printf("\n"); 2699 2700 thread__put(thread); 2701 } 2702 2703 static int timehist_sched_wakeup_ignore(const struct perf_tool *tool __maybe_unused, 2704 union perf_event *event __maybe_unused, 2705 struct perf_sample *sample __maybe_unused, 2706 struct machine *machine __maybe_unused) 2707 { 2708 return 0; 2709 } 2710 2711 static int timehist_sched_wakeup_event(const struct perf_tool *tool, 2712 union perf_event *event __maybe_unused, 2713 struct perf_sample *sample, 2714 struct machine *machine) 2715 { 2716 struct perf_sched *sched = container_of(tool, struct perf_sched, tool); 2717 struct thread *thread; 2718 struct thread_runtime *tr = NULL; 2719 /* want pid of awakened task not pid in sample */ 2720 const u32 pid = perf_sample__intval(sample, "pid"); 2721 2722 thread = machine__findnew_thread(machine, 0, pid); 2723 if (thread == NULL) 2724 return -1; 2725 2726 tr = thread__get_runtime(thread); 2727 if (tr == NULL) { 2728 thread__put(thread); 2729 return -1; 2730 } 2731 2732 if (tr->ready_to_run == 0) 2733 tr->ready_to_run = sample->time; 2734 2735 /* show wakeups if requested */ 2736 if (sched->show_wakeups && 2737 !perf_time__skip_sample(&sched->ptime, sample->time)) 2738 timehist_print_wakeup_event(sched, sample, machine, thread); 2739 2740 thread__put(thread); 2741 return 0; 2742 } 2743 2744 static void timehist_print_migration_event(struct perf_sched *sched, 2745 struct perf_sample *sample, 2746 struct machine *machine, 2747 struct thread *migrated) 2748 { 2749 struct thread *thread; 2750 char tstr[64]; 2751 u32 max_cpus; 2752 u32 ocpu, dcpu; 2753 2754 if (sched->summary_only) 2755 return; 2756 2757 max_cpus = sched->max_cpu.cpu + 1; 2758 ocpu = perf_sample__intval(sample, "orig_cpu"); 2759 dcpu = perf_sample__intval(sample, "dest_cpu"); 2760 2761 thread = machine__findnew_thread(machine, sample->pid, sample->tid); 2762 if (thread == NULL) 2763 return; 2764 2765 if (timehist_skip_sample(sched, thread, sample) && 2766 timehist_skip_sample(sched, migrated, sample)) { 2767 thread__put(thread); 2768 return; 2769 } 2770 2771 timestamp__scnprintf_usec(sample->time, tstr, sizeof(tstr)); 2772 printf("%15s [%04d] ", tstr, sample->cpu); 2773 2774 if (sched->show_cpu_visual) { 2775 u32 i; 2776 char c; 2777 2778 printf(" "); 2779 for (i = 0; i < max_cpus; ++i) { 2780 c = (i == sample->cpu) ? 'm' : ' '; 2781 printf("%c", c); 2782 } 2783 printf(" "); 2784 } 2785 2786 printf(" %-*s ", comm_width, timehist_get_commstr(thread)); 2787 2788 /* dt spacer */ 2789 printf(" %9s %9s %9s ", "", "", ""); 2790 2791 printf("migrated: %s", timehist_get_commstr(migrated)); 2792 printf(" cpu %d => %d", ocpu, dcpu); 2793 2794 printf("\n"); 2795 thread__put(thread); 2796 } 2797 2798 static int timehist_migrate_task_event(const struct perf_tool *tool, 2799 union perf_event *event __maybe_unused, 2800 struct perf_sample *sample, 2801 struct machine *machine) 2802 { 2803 struct perf_sched *sched = container_of(tool, struct perf_sched, tool); 2804 struct thread *thread; 2805 struct thread_runtime *tr = NULL; 2806 /* want pid of migrated task not pid in sample */ 2807 const u32 pid = perf_sample__intval(sample, "pid"); 2808 2809 thread = machine__findnew_thread(machine, 0, pid); 2810 if (thread == NULL) 2811 return -1; 2812 2813 tr = thread__get_runtime(thread); 2814 if (tr == NULL) { 2815 thread__put(thread); 2816 return -1; 2817 } 2818 2819 tr->migrations++; 2820 tr->migrated = sample->time; 2821 2822 /* show migrations if requested */ 2823 if (sched->show_migrations) { 2824 timehist_print_migration_event(sched, sample, machine, thread); 2825 } 2826 thread__put(thread); 2827 2828 return 0; 2829 } 2830 2831 static void timehist_update_task_prio(struct perf_sample *sample, 2832 struct machine *machine) 2833 { 2834 struct thread *thread; 2835 struct thread_runtime *tr = NULL; 2836 const u32 next_pid = perf_sample__intval(sample, "next_pid"); 2837 const u32 next_prio = perf_sample__intval(sample, "next_prio"); 2838 2839 if (next_pid == 0) 2840 thread = get_idle_thread(sample->cpu); 2841 else 2842 thread = machine__findnew_thread(machine, -1, next_pid); 2843 2844 if (thread == NULL) 2845 return; 2846 2847 tr = thread__get_runtime(thread); 2848 if (tr != NULL) 2849 tr->prio = next_prio; 2850 2851 thread__put(thread); 2852 } 2853 2854 static int timehist_sched_change_event(const struct perf_tool *tool, 2855 union perf_event *event, 2856 struct perf_sample *sample, 2857 struct machine *machine) 2858 { 2859 struct perf_sched *sched = container_of(tool, struct perf_sched, tool); 2860 struct perf_time_interval *ptime = &sched->ptime; 2861 struct addr_location al; 2862 struct thread *thread = NULL; 2863 struct thread_runtime *tr = NULL; 2864 u64 tprev, t = sample->time; 2865 int rc = 0; 2866 const char state = perf_sample__taskstate(sample, "prev_state"); 2867 2868 /* perf.data is untrusted input — CPU may be absent or corrupted */ 2869 if (sample->cpu >= MAX_CPUS) { 2870 pr_warning("WARNING: at offset %#" PRIx64 ": out-of-bound sample CPU %d, skipping sample\n", 2871 sample->file_offset, sample->cpu); 2872 return 0; 2873 } 2874 2875 addr_location__init(&al); 2876 if (machine__resolve(machine, &al, sample) < 0) { 2877 pr_err("problem processing %s (%u) event at offset %#" PRIx64 ", skipping it\n", 2878 perf_event__name(event->header.type), event->header.type, 2879 sample->file_offset); 2880 rc = -1; 2881 goto out; 2882 } 2883 2884 if (sched->show_prio || sched->prio_str) 2885 timehist_update_task_prio(sample, machine); 2886 2887 thread = timehist_get_thread(sched, sample, machine); 2888 if (thread == NULL) { 2889 rc = -1; 2890 goto out; 2891 } 2892 2893 if (timehist_skip_sample(sched, thread, sample)) 2894 goto out; 2895 2896 tr = thread__get_runtime(thread); 2897 if (tr == NULL) { 2898 rc = -1; 2899 goto out; 2900 } 2901 2902 tprev = evsel__get_time(sample->evsel, sample->cpu); 2903 2904 /* 2905 * If start time given: 2906 * - sample time is under window user cares about - skip sample 2907 * - tprev is under window user cares about - reset to start of window 2908 */ 2909 if (ptime->start && ptime->start > t) 2910 goto out; 2911 2912 if (tprev && ptime->start > tprev) 2913 tprev = ptime->start; 2914 2915 /* 2916 * If end time given: 2917 * - previous sched event is out of window - we are done 2918 * - sample time is beyond window user cares about - reset it 2919 * to close out stats for time window interest 2920 * - If tprev is 0, that is, sched_in event for current task is 2921 * not recorded, cannot determine whether sched_in event is 2922 * within time window interest - ignore it 2923 */ 2924 if (ptime->end) { 2925 if (!tprev || tprev > ptime->end) 2926 goto out; 2927 2928 if (t > ptime->end) 2929 t = ptime->end; 2930 } 2931 2932 /* 2933 * Use is_idle_sample() not thread__tid() == 0: a crafted perf.data 2934 * can set common_pid=0 with prev_pid!=0, giving us a machine thread 2935 * whose priv is thread_runtime, not idle_thread_runtime — the cast 2936 * below would read past the allocation. 2937 */ 2938 if (!sched->idle_hist || is_idle_sample(sample)) { 2939 if (!cpu_list || (sample->cpu < MAX_NR_CPUS && 2940 test_bit(sample->cpu, cpu_bitmap))) 2941 timehist_update_runtime_stats(tr, t, tprev); 2942 2943 if (sched->idle_hist) { 2944 struct idle_thread_runtime *itr = (void *)tr; 2945 struct thread_runtime *last_tr; 2946 2947 if (itr->last_thread == NULL) 2948 goto out; 2949 2950 /* add current idle time as last thread's runtime */ 2951 last_tr = thread__get_runtime(itr->last_thread); 2952 if (last_tr == NULL) 2953 goto out; 2954 2955 timehist_update_runtime_stats(last_tr, t, tprev); 2956 /* 2957 * remove delta time of last thread as it's not updated 2958 * and otherwise it will show an invalid value next 2959 * time. we only care total run time and run stat. 2960 */ 2961 last_tr->dt_run = 0; 2962 last_tr->dt_delay = 0; 2963 last_tr->dt_sleep = 0; 2964 last_tr->dt_iowait = 0; 2965 last_tr->dt_preempt = 0; 2966 2967 if (itr->cursor.nr) 2968 callchain_append(&itr->callchain, &itr->cursor, t - tprev); 2969 2970 thread__zput(itr->last_thread); 2971 } 2972 2973 if (!sched->summary_only) 2974 timehist_print_sample(sched, sample, &al, thread, t, state); 2975 } 2976 2977 out: 2978 if (sched->hist_time.start == 0 && t >= ptime->start) 2979 sched->hist_time.start = t; 2980 if (ptime->end == 0 || t <= ptime->end) 2981 sched->hist_time.end = t; 2982 2983 if (tr) { 2984 /* time of this sched_switch event becomes last time task seen */ 2985 tr->last_time = sample->time; 2986 2987 /* last state is used to determine where to account wait time */ 2988 tr->last_state = state; 2989 2990 /* sched out event for task so reset ready to run time and migrated time */ 2991 if (state == 'R') 2992 tr->ready_to_run = t; 2993 else 2994 tr->ready_to_run = 0; 2995 2996 tr->migrated = 0; 2997 } 2998 2999 evsel__save_time(sample->evsel, sample->time, sample->cpu); 3000 3001 thread__put(thread); 3002 addr_location__exit(&al); 3003 return rc; 3004 } 3005 3006 static int timehist_sched_switch_event(const struct perf_tool *tool, 3007 union perf_event *event, 3008 struct perf_sample *sample, 3009 struct machine *machine __maybe_unused) 3010 { 3011 return timehist_sched_change_event(tool, event, sample, machine); 3012 } 3013 3014 static int process_lost(const struct perf_tool *tool __maybe_unused, 3015 union perf_event *event, 3016 struct perf_sample *sample, 3017 struct machine *machine __maybe_unused) 3018 { 3019 char tstr[64]; 3020 3021 timestamp__scnprintf_usec(sample->time, tstr, sizeof(tstr)); 3022 printf("%15s ", tstr); 3023 printf("lost %" PRI_lu64 " events on cpu %d\n", event->lost.lost, sample->cpu); 3024 3025 return 0; 3026 } 3027 3028 3029 static void print_thread_runtime(struct thread *t, 3030 struct thread_runtime *r) 3031 { 3032 double mean = avg_stats(&r->run_stats); 3033 float stddev; 3034 3035 printf("%*s %5d %9" PRIu64 " ", 3036 comm_width, timehist_get_commstr(t), thread__ppid(t), 3037 (u64) r->run_stats.n); 3038 3039 print_sched_time(r->total_run_time, 8); 3040 stddev = rel_stddev_stats(stddev_stats(&r->run_stats), mean); 3041 print_sched_time(r->run_stats.min, 6); 3042 printf(" "); 3043 print_sched_time((u64) mean, 6); 3044 printf(" "); 3045 print_sched_time(r->run_stats.max, 6); 3046 printf(" "); 3047 printf("%5.2f", stddev); 3048 printf(" %5" PRIu64, r->migrations); 3049 printf("\n"); 3050 } 3051 3052 static void print_thread_waittime(struct thread *t, 3053 struct thread_runtime *r) 3054 { 3055 printf("%*s %5d %9" PRIu64 " ", 3056 comm_width, timehist_get_commstr(t), thread__ppid(t), 3057 (u64) r->run_stats.n); 3058 3059 print_sched_time(r->total_run_time, 8); 3060 print_sched_time(r->total_sleep_time, 6); 3061 printf(" "); 3062 print_sched_time(r->total_iowait_time, 6); 3063 printf(" "); 3064 print_sched_time(r->total_preempt_time, 6); 3065 printf(" "); 3066 print_sched_time(r->total_delay_time, 6); 3067 printf("\n"); 3068 } 3069 3070 struct total_run_stats { 3071 struct perf_sched *sched; 3072 u64 sched_count; 3073 u64 task_count; 3074 u64 total_run_time; 3075 }; 3076 3077 static int show_thread_runtime(struct thread *t, void *priv) 3078 { 3079 struct total_run_stats *stats = priv; 3080 struct thread_runtime *r; 3081 3082 if (thread__is_filtered(t)) 3083 return 0; 3084 3085 r = thread__priv(t); 3086 if (r && r->run_stats.n) { 3087 stats->task_count++; 3088 stats->sched_count += r->run_stats.n; 3089 stats->total_run_time += r->total_run_time; 3090 3091 if (stats->sched->show_state) 3092 print_thread_waittime(t, r); 3093 else 3094 print_thread_runtime(t, r); 3095 } 3096 3097 return 0; 3098 } 3099 3100 static size_t callchain__fprintf_folded(FILE *fp, struct callchain_node *node) 3101 { 3102 const char *sep = " <- "; 3103 struct callchain_list *chain; 3104 size_t ret = 0; 3105 char bf[1024]; 3106 bool first; 3107 3108 if (node == NULL) 3109 return 0; 3110 3111 ret = callchain__fprintf_folded(fp, node->parent); 3112 first = (ret == 0); 3113 3114 list_for_each_entry(chain, &node->val, list) { 3115 if (chain->ip >= PERF_CONTEXT_MAX) 3116 continue; 3117 if (chain->ms.sym && symbol__ignore(chain->ms.sym)) 3118 continue; 3119 ret += fprintf(fp, "%s%s", first ? "" : sep, 3120 callchain_list__sym_name(chain, bf, sizeof(bf), 3121 false)); 3122 first = false; 3123 } 3124 3125 return ret; 3126 } 3127 3128 static size_t timehist_print_idlehist_callchain(struct rb_root_cached *root) 3129 { 3130 size_t ret = 0; 3131 FILE *fp = stdout; 3132 struct callchain_node *chain; 3133 /* sort() uses rb_insert_color() on rb_root, not rb_root_cached */ 3134 struct rb_node *rb_node = rb_first(&root->rb_root); 3135 3136 printf(" %16s %8s %s\n", "Idle time (msec)", "Count", "Callchains"); 3137 printf(" %.16s %.8s %.50s\n", graph_dotted_line, graph_dotted_line, 3138 graph_dotted_line); 3139 3140 while (rb_node) { 3141 chain = rb_entry(rb_node, struct callchain_node, rb_node); 3142 rb_node = rb_next(rb_node); 3143 3144 ret += fprintf(fp, " "); 3145 print_sched_time(chain->hit, 12); 3146 ret += 16; /* print_sched_time returns 2nd arg + 4 */ 3147 ret += fprintf(fp, " %8d ", chain->count); 3148 ret += callchain__fprintf_folded(fp, chain); 3149 ret += fprintf(fp, "\n"); 3150 } 3151 3152 return ret; 3153 } 3154 3155 static void timehist_print_summary(struct perf_sched *sched, 3156 struct perf_session *session) 3157 { 3158 struct machine *m = &session->machines.host; 3159 struct total_run_stats totals; 3160 u64 task_count; 3161 struct thread *t; 3162 struct thread_runtime *r; 3163 int i; 3164 u64 hist_time = sched->hist_time.end - sched->hist_time.start; 3165 3166 memset(&totals, 0, sizeof(totals)); 3167 totals.sched = sched; 3168 3169 if (sched->idle_hist) { 3170 printf("\nIdle-time summary\n"); 3171 printf("%*s parent sched-out ", comm_width, "comm"); 3172 printf(" idle-time min-idle avg-idle max-idle stddev migrations\n"); 3173 } else if (sched->show_state) { 3174 printf("\nWait-time summary\n"); 3175 printf("%*s parent sched-in ", comm_width, "comm"); 3176 printf(" run-time sleep iowait preempt delay\n"); 3177 } else { 3178 printf("\nRuntime summary\n"); 3179 printf("%*s parent sched-in ", comm_width, "comm"); 3180 printf(" run-time min-run avg-run max-run stddev migrations\n"); 3181 } 3182 printf("%*s (count) ", comm_width, ""); 3183 printf(" (msec) (msec) (msec) (msec) %s\n", 3184 sched->show_state ? "(msec)" : "%"); 3185 printf("%.117s\n", graph_dotted_line); 3186 3187 machine__for_each_thread(m, show_thread_runtime, &totals); 3188 task_count = totals.task_count; 3189 if (!task_count) 3190 printf("<no still running tasks>\n"); 3191 3192 /* CPU idle stats not tracked when samples were skipped */ 3193 if (sched->skipped_samples && !sched->idle_hist) 3194 return; 3195 3196 printf("\nIdle stats:\n"); 3197 for (i = 0; i < idle_max_cpu; ++i) { 3198 if (cpu_list && !test_bit(i, cpu_bitmap)) 3199 continue; 3200 3201 t = idle_threads[i]; 3202 if (!t) 3203 continue; 3204 3205 r = thread__priv(t); 3206 if (r && r->run_stats.n) { 3207 totals.sched_count += r->run_stats.n; 3208 printf(" CPU %2d idle for ", i); 3209 print_sched_time(r->total_run_time, 6); 3210 printf(" msec (%6.2f%%)\n", 100.0 * r->total_run_time / hist_time); 3211 } else 3212 printf(" CPU %2d idle entire time window\n", i); 3213 } 3214 3215 if (sched->idle_hist && sched->show_callchain) { 3216 callchain_param.mode = CHAIN_FOLDED; 3217 callchain_param.value = CCVAL_PERIOD; 3218 3219 callchain_register_param(&callchain_param); 3220 3221 printf("\nIdle stats by callchain:\n"); 3222 for (i = 0; i < idle_max_cpu; ++i) { 3223 struct idle_thread_runtime *itr; 3224 3225 t = idle_threads[i]; 3226 if (!t) 3227 continue; 3228 3229 itr = thread__priv(t); 3230 if (itr == NULL) 3231 continue; 3232 3233 callchain_param.sort(&itr->sorted_root.rb_root, &itr->callchain, 3234 0, &callchain_param); 3235 3236 printf(" CPU %2d:", i); 3237 print_sched_time(itr->tr.total_run_time, 6); 3238 printf(" msec\n"); 3239 timehist_print_idlehist_callchain(&itr->sorted_root); 3240 printf("\n"); 3241 } 3242 } 3243 3244 printf("\n" 3245 " Total number of unique tasks: %" PRIu64 "\n" 3246 "Total number of context switches: %" PRIu64 "\n", 3247 totals.task_count, totals.sched_count); 3248 3249 printf(" Total run time (msec): "); 3250 print_sched_time(totals.total_run_time, 2); 3251 printf("\n"); 3252 3253 printf(" Total scheduling time (msec): "); 3254 print_sched_time(hist_time, 2); 3255 printf(" (x %d)\n", sched->max_cpu.cpu); 3256 } 3257 3258 typedef int (*sched_handler)(const struct perf_tool *tool, 3259 union perf_event *event, 3260 struct perf_sample *sample, 3261 struct machine *machine); 3262 3263 static int perf_timehist__process_sample(const struct perf_tool *tool, 3264 union perf_event *event, 3265 struct perf_sample *sample, 3266 struct machine *machine) 3267 { 3268 struct perf_sched *sched = container_of(tool, struct perf_sched, tool); 3269 struct evsel *evsel = sample->evsel; 3270 int err = 0; 3271 struct perf_cpu this_cpu = { 3272 .cpu = sample->cpu, 3273 }; 3274 3275 /* max_cpu indexes arrays allocated with MAX_CPUS entries */ 3276 if (this_cpu.cpu >= 0 && this_cpu.cpu < MAX_CPUS && 3277 this_cpu.cpu > sched->max_cpu.cpu) 3278 sched->max_cpu = this_cpu; 3279 3280 if (evsel->handler != NULL) { 3281 sched_handler f = evsel->handler; 3282 3283 err = f(tool, event, sample, machine); 3284 } 3285 3286 return err; 3287 } 3288 3289 static int timehist_check_attr(struct perf_sched *sched, 3290 struct evlist *evlist) 3291 { 3292 struct evsel *evsel; 3293 struct evsel_runtime *er; 3294 3295 list_for_each_entry(evsel, &evlist->core.entries, core.node) { 3296 er = evsel__get_runtime(evsel); 3297 if (er == NULL) { 3298 pr_err("Failed to allocate memory for evsel runtime data\n"); 3299 return -1; 3300 } 3301 3302 /* only need to save callchain related to sched_switch event */ 3303 if (sched->show_callchain && 3304 evsel__name_is(evsel, "sched:sched_switch") && 3305 !evsel__has_callchain(evsel)) { 3306 pr_info("Samples of sched_switch event do not have callchains.\n"); 3307 sched->show_callchain = 0; 3308 symbol_conf.use_callchain = 0; 3309 } 3310 } 3311 3312 return 0; 3313 } 3314 3315 static int timehist_parse_prio_str(struct perf_sched *sched) 3316 { 3317 char *p; 3318 unsigned long start_prio, end_prio; 3319 const char *str = sched->prio_str; 3320 3321 if (!str) 3322 return 0; 3323 3324 while (isdigit(*str)) { 3325 p = NULL; 3326 start_prio = strtoul(str, &p, 0); 3327 if (start_prio >= MAX_PRIO || (*p != '\0' && *p != ',' && *p != '-')) 3328 return -1; 3329 3330 if (*p == '-') { 3331 str = ++p; 3332 p = NULL; 3333 end_prio = strtoul(str, &p, 0); 3334 3335 if (end_prio >= MAX_PRIO || (*p != '\0' && *p != ',')) 3336 return -1; 3337 3338 if (end_prio < start_prio) 3339 return -1; 3340 } else { 3341 end_prio = start_prio; 3342 } 3343 3344 for (; start_prio <= end_prio; start_prio++) 3345 __set_bit(start_prio, sched->prio_bitmap); 3346 3347 if (*p) 3348 ++p; 3349 3350 str = p; 3351 } 3352 3353 return 0; 3354 } 3355 3356 static int perf_sched__timehist(struct perf_sched *sched) 3357 { 3358 struct evsel_str_handler handlers[] = { 3359 { "sched:sched_switch", timehist_sched_switch_event, }, 3360 { "sched:sched_wakeup", timehist_sched_wakeup_event, }, 3361 { "sched:sched_waking", timehist_sched_wakeup_event, }, 3362 { "sched:sched_wakeup_new", timehist_sched_wakeup_event, }, 3363 }; 3364 const struct evsel_str_handler migrate_handlers[] = { 3365 { "sched:sched_migrate_task", timehist_migrate_task_event, }, 3366 }; 3367 struct perf_data data = { 3368 .path = input_name, 3369 .mode = PERF_DATA_MODE_READ, 3370 .force = sched->force, 3371 }; 3372 3373 struct perf_session *session; 3374 struct perf_env *env; 3375 struct evlist *evlist; 3376 int err = -1; 3377 3378 /* 3379 * event handlers for timehist option 3380 */ 3381 sched->tool.sample = perf_timehist__process_sample; 3382 sched->tool.mmap = perf_event__process_mmap; 3383 sched->tool.mmap2 = perf_event__process_mmap2; 3384 sched->tool.comm = perf_event__process_comm; 3385 sched->tool.exit = perf_event__process_exit; 3386 sched->tool.fork = perf_event__process_fork; 3387 sched->tool.lost = process_lost; 3388 sched->tool.attr = perf_event__process_attr; 3389 sched->tool.tracing_data = perf_event__process_tracing_data; 3390 sched->tool.build_id = perf_event__process_build_id; 3391 3392 sched->tool.ordering_requires_timestamps = true; 3393 3394 symbol_conf.use_callchain = sched->show_callchain; 3395 3396 session = perf_session__new(&data, &sched->tool); 3397 if (IS_ERR(session)) 3398 return PTR_ERR(session); 3399 3400 env = perf_session__env(session); 3401 if (cpu_list) { 3402 err = perf_session__cpu_bitmap(session, cpu_list, cpu_bitmap); 3403 if (err < 0) 3404 goto out; 3405 } 3406 3407 evlist = session->evlist; 3408 3409 symbol__init(env); 3410 3411 if (perf_time__parse_str(&sched->ptime, sched->time_str) != 0) { 3412 pr_err("Invalid time string\n"); 3413 err = -EINVAL; 3414 goto out; 3415 } 3416 3417 if (timehist_check_attr(sched, evlist) != 0) 3418 goto out; 3419 3420 if (timehist_parse_prio_str(sched) != 0) { 3421 pr_err("Invalid prio string\n"); 3422 goto out; 3423 } 3424 3425 setup_pager(); 3426 3427 evsel__set_priv_destructor(timehist__evsel_priv_destructor); 3428 3429 /* prefer sched_waking if it is captured */ 3430 if (evlist__find_tracepoint_by_name(session->evlist, "sched:sched_waking")) 3431 handlers[1].handler = timehist_sched_wakeup_ignore; 3432 3433 /* setup per-evsel handlers */ 3434 if (perf_session__set_tracepoints_handlers(session, handlers)) 3435 goto out; 3436 3437 /* sched_switch event at a minimum needs to exist */ 3438 if (!evlist__find_tracepoint_by_name(session->evlist, "sched:sched_switch")) { 3439 pr_err("No sched_switch events found. Have you run 'perf sched record'?\n"); 3440 goto out; 3441 } 3442 3443 if ((sched->show_migrations || sched->pre_migrations) && 3444 perf_session__set_tracepoints_handlers(session, migrate_handlers)) 3445 goto out; 3446 3447 /* pre-allocate struct for per-CPU idle stats; cap to array bounds */ 3448 sched->max_cpu.cpu = min(env->nr_cpus_online, MAX_CPUS); 3449 if (sched->max_cpu.cpu == 0) 3450 sched->max_cpu.cpu = 4; 3451 if (init_idle_threads(sched->max_cpu.cpu)) 3452 goto out; 3453 3454 /* summary_only implies summary option, but don't overwrite summary if set */ 3455 if (sched->summary_only) 3456 sched->summary = sched->summary_only; 3457 3458 if (!sched->summary_only) 3459 timehist_header(sched); 3460 3461 err = perf_session__process_events(session); 3462 if (err) { 3463 pr_err("Failed to process events, error %d", err); 3464 goto out; 3465 } 3466 3467 sched->nr_events = evlist->stats.nr_events[0]; 3468 sched->nr_lost_events = evlist->stats.total_lost; 3469 sched->nr_lost_chunks = evlist->stats.nr_events[PERF_RECORD_LOST]; 3470 3471 if (sched->summary) 3472 timehist_print_summary(sched, session); 3473 3474 out: 3475 free_idle_threads(); 3476 perf_session__delete(session); 3477 3478 return err; 3479 } 3480 3481 3482 static void print_bad_events(struct perf_sched *sched) 3483 { 3484 if (sched->nr_unordered_timestamps && sched->nr_timestamps) { 3485 printf(" INFO: %.3f%% unordered timestamps (%ld out of %ld)\n", 3486 (double)sched->nr_unordered_timestamps/(double)sched->nr_timestamps*100.0, 3487 sched->nr_unordered_timestamps, sched->nr_timestamps); 3488 } 3489 if (sched->nr_lost_events && sched->nr_events) { 3490 printf(" INFO: %.3f%% lost events (%ld out of %ld, in %ld chunks)\n", 3491 (double)sched->nr_lost_events/(double)sched->nr_events * 100.0, 3492 sched->nr_lost_events, sched->nr_events, sched->nr_lost_chunks); 3493 } 3494 if (sched->nr_context_switch_bugs && sched->nr_timestamps) { 3495 printf(" INFO: %.3f%% context switch bugs (%ld out of %ld)", 3496 (double)sched->nr_context_switch_bugs/(double)sched->nr_timestamps*100.0, 3497 sched->nr_context_switch_bugs, sched->nr_timestamps); 3498 if (sched->nr_lost_events) 3499 printf(" (due to lost events?)"); 3500 printf("\n"); 3501 } 3502 } 3503 3504 static void __merge_work_atoms(struct rb_root_cached *root, struct work_atoms *data) 3505 { 3506 struct rb_node **new = &(root->rb_root.rb_node), *parent = NULL; 3507 struct work_atoms *this; 3508 const char *comm = thread__comm_str(data->thread), *this_comm; 3509 bool leftmost = true; 3510 3511 while (*new) { 3512 int cmp; 3513 3514 this = container_of(*new, struct work_atoms, node); 3515 parent = *new; 3516 3517 this_comm = thread__comm_str(this->thread); 3518 cmp = strcmp(comm, this_comm); 3519 if (cmp > 0) { 3520 new = &((*new)->rb_left); 3521 } else if (cmp < 0) { 3522 new = &((*new)->rb_right); 3523 leftmost = false; 3524 } else { 3525 this->num_merged++; 3526 this->total_runtime += data->total_runtime; 3527 this->nb_atoms += data->nb_atoms; 3528 this->total_lat += data->total_lat; 3529 list_splice_init(&data->work_list, &this->work_list); 3530 if (this->max_lat < data->max_lat) { 3531 this->max_lat = data->max_lat; 3532 this->max_lat_start = data->max_lat_start; 3533 this->max_lat_end = data->max_lat_end; 3534 } 3535 free_work_atoms(data); 3536 return; 3537 } 3538 } 3539 3540 data->num_merged++; 3541 rb_link_node(&data->node, parent, new); 3542 rb_insert_color_cached(&data->node, root, leftmost); 3543 } 3544 3545 static void perf_sched__merge_lat(struct perf_sched *sched) 3546 { 3547 struct work_atoms *data; 3548 struct rb_node *node; 3549 3550 if (sched->skip_merge) 3551 return; 3552 3553 while ((node = rb_first_cached(&sched->atom_root))) { 3554 rb_erase_cached(node, &sched->atom_root); 3555 data = rb_entry(node, struct work_atoms, node); 3556 __merge_work_atoms(&sched->merged_atom_root, data); 3557 } 3558 } 3559 3560 static int setup_cpus_switch_event(struct perf_sched *sched) 3561 { 3562 unsigned int i; 3563 3564 sched->cpu_last_switched = calloc(MAX_CPUS, sizeof(*(sched->cpu_last_switched))); 3565 if (!sched->cpu_last_switched) 3566 return -1; 3567 3568 sched->curr_pid = calloc(MAX_CPUS, sizeof(*(sched->curr_pid))); 3569 if (!sched->curr_pid) { 3570 zfree(&sched->cpu_last_switched); 3571 return -1; 3572 } 3573 3574 for (i = 0; i < MAX_CPUS; i++) 3575 sched->curr_pid[i] = -1; 3576 3577 return 0; 3578 } 3579 3580 static void free_cpus_switch_event(struct perf_sched *sched) 3581 { 3582 zfree(&sched->curr_pid); 3583 zfree(&sched->cpu_last_switched); 3584 } 3585 3586 static int perf_sched__lat(struct perf_sched *sched) 3587 { 3588 int rc = -1; 3589 struct rb_node *next; 3590 3591 setup_pager(); 3592 3593 if (setup_cpus_switch_event(sched)) 3594 return rc; 3595 3596 if (perf_sched__read_events(sched)) 3597 goto out_free_cpus_switch_event; 3598 3599 perf_sched__merge_lat(sched); 3600 perf_sched__sort_lat(sched); 3601 3602 printf("\n -------------------------------------------------------------------------------------------------------------------------------------------\n"); 3603 printf(" Task | Runtime ms | Count | Avg delay ms | Max delay ms | Max delay start | Max delay end |\n"); 3604 printf(" -------------------------------------------------------------------------------------------------------------------------------------------\n"); 3605 3606 next = rb_first_cached(&sched->sorted_atom_root); 3607 3608 while (next) { 3609 struct work_atoms *work_list; 3610 3611 work_list = rb_entry(next, struct work_atoms, node); 3612 output_lat_thread(sched, work_list); 3613 next = rb_next(next); 3614 } 3615 3616 printf(" -----------------------------------------------------------------------------------------------------------------\n"); 3617 printf(" TOTAL: |%11.3f ms |%9" PRIu64 " |\n", 3618 (double)sched->all_runtime / NSEC_PER_MSEC, sched->all_count); 3619 3620 printf(" ---------------------------------------------------\n"); 3621 3622 print_bad_events(sched); 3623 printf("\n"); 3624 3625 rc = 0; 3626 3627 while ((next = rb_first_cached(&sched->sorted_atom_root))) { 3628 struct work_atoms *data; 3629 3630 data = rb_entry(next, struct work_atoms, node); 3631 rb_erase_cached(next, &sched->sorted_atom_root); 3632 free_work_atoms(data); 3633 } 3634 out_free_cpus_switch_event: 3635 free_cpus_switch_event(sched); 3636 return rc; 3637 } 3638 3639 static int setup_map_cpus(struct perf_sched *sched) 3640 { 3641 if (sched->map.comp) { 3642 sched->map.comp_cpus = calloc(MAX_CPUS, sizeof(*sched->map.comp_cpus)); 3643 if (!sched->map.comp_cpus) 3644 return -1; 3645 } 3646 3647 if (sched->map.cpus_str) { 3648 sched->map.cpus = perf_cpu_map__new(sched->map.cpus_str); 3649 if (!sched->map.cpus) { 3650 pr_err("failed to get cpus map from %s\n", sched->map.cpus_str); 3651 zfree(&sched->map.comp_cpus); 3652 return -1; 3653 } 3654 } 3655 3656 return 0; 3657 } 3658 3659 static int setup_color_pids(struct perf_sched *sched) 3660 { 3661 struct perf_thread_map *map; 3662 3663 if (!sched->map.color_pids_str) 3664 return 0; 3665 3666 map = thread_map__new_by_tid_str(sched->map.color_pids_str); 3667 if (!map) { 3668 pr_err("failed to get thread map from %s\n", sched->map.color_pids_str); 3669 return -1; 3670 } 3671 3672 sched->map.color_pids = map; 3673 return 0; 3674 } 3675 3676 static int setup_color_cpus(struct perf_sched *sched) 3677 { 3678 struct perf_cpu_map *map; 3679 3680 if (!sched->map.color_cpus_str) 3681 return 0; 3682 3683 map = perf_cpu_map__new(sched->map.color_cpus_str); 3684 if (!map) { 3685 pr_err("failed to get thread map from %s\n", sched->map.color_cpus_str); 3686 return -1; 3687 } 3688 3689 sched->map.color_cpus = map; 3690 return 0; 3691 } 3692 3693 static int perf_sched__map(struct perf_sched *sched) 3694 { 3695 int rc = -1; 3696 3697 sched->curr_thread = calloc(MAX_CPUS, sizeof(*(sched->curr_thread))); 3698 if (!sched->curr_thread) 3699 return rc; 3700 3701 sched->curr_out_thread = calloc(MAX_CPUS, sizeof(*(sched->curr_out_thread))); 3702 if (!sched->curr_out_thread) 3703 goto out_free_curr_thread; 3704 3705 if (setup_cpus_switch_event(sched)) 3706 goto out_free_curr_out_thread; 3707 3708 if (setup_map_cpus(sched)) 3709 goto out_free_cpus_switch_event; 3710 3711 if (setup_color_pids(sched)) 3712 goto out_put_map_cpus; 3713 3714 if (setup_color_cpus(sched)) 3715 goto out_put_color_pids; 3716 3717 setup_pager(); 3718 if (perf_sched__read_events(sched)) 3719 goto out_put_color_cpus; 3720 3721 rc = 0; 3722 print_bad_events(sched); 3723 3724 out_put_color_cpus: 3725 perf_cpu_map__put(sched->map.color_cpus); 3726 3727 out_put_color_pids: 3728 perf_thread_map__put(sched->map.color_pids); 3729 3730 out_put_map_cpus: 3731 zfree(&sched->map.comp_cpus); 3732 perf_cpu_map__put(sched->map.cpus); 3733 3734 out_free_cpus_switch_event: 3735 free_cpus_switch_event(sched); 3736 3737 out_free_curr_out_thread: 3738 for (int i = 0; i < MAX_CPUS; i++) 3739 thread__put(sched->curr_out_thread[i]); 3740 zfree(&sched->curr_out_thread); 3741 3742 out_free_curr_thread: 3743 for (int i = 0; i < MAX_CPUS; i++) 3744 thread__put(sched->curr_thread[i]); 3745 zfree(&sched->curr_thread); 3746 return rc; 3747 } 3748 3749 static int perf_sched__replay(struct perf_sched *sched) 3750 { 3751 int ret; 3752 unsigned long i; 3753 3754 mutex_init(&sched->start_work_mutex); 3755 mutex_init(&sched->work_done_wait_mutex); 3756 3757 ret = setup_cpus_switch_event(sched); 3758 if (ret) 3759 goto out_mutex_destroy; 3760 3761 calibrate_run_measurement_overhead(sched); 3762 calibrate_sleep_measurement_overhead(sched); 3763 3764 test_calibrations(sched); 3765 3766 ret = perf_sched__read_events(sched); 3767 if (ret) 3768 goto out_free_cpus_switch_event; 3769 3770 printf("nr_run_events: %ld\n", sched->nr_run_events); 3771 printf("nr_sleep_events: %ld\n", sched->nr_sleep_events); 3772 printf("nr_wakeup_events: %ld\n", sched->nr_wakeup_events); 3773 3774 if (sched->targetless_wakeups) 3775 printf("target-less wakeups: %ld\n", sched->targetless_wakeups); 3776 if (sched->multitarget_wakeups) 3777 printf("multi-target wakeups: %ld\n", sched->multitarget_wakeups); 3778 if (sched->nr_run_events_optimized) 3779 printf("run atoms optimized: %ld\n", 3780 sched->nr_run_events_optimized); 3781 3782 print_task_traces(sched); 3783 add_cross_task_wakeups(sched); 3784 3785 sched->thread_funcs_exit = false; 3786 create_tasks(sched); 3787 printf("------------------------------------------------------------\n"); 3788 if (sched->replay_repeat == 0) 3789 sched->replay_repeat = UINT_MAX; 3790 3791 for (i = 0; i < sched->replay_repeat; i++) 3792 run_one_test(sched); 3793 3794 sched->thread_funcs_exit = true; 3795 destroy_tasks(sched); 3796 3797 out_free_cpus_switch_event: 3798 free_cpus_switch_event(sched); 3799 3800 out_mutex_destroy: 3801 mutex_destroy(&sched->start_work_mutex); 3802 mutex_destroy(&sched->work_done_wait_mutex); 3803 return ret; 3804 } 3805 3806 static void setup_sorting(struct perf_sched *sched, const struct option *options, 3807 const char * const usage_msg[]) 3808 { 3809 char *tmp, *tok, *str = strdup(sched->sort_order); 3810 3811 for (tok = strtok_r(str, ", ", &tmp); 3812 tok; tok = strtok_r(NULL, ", ", &tmp)) { 3813 if (sort_dimension__add(tok, &sched->sort_list) < 0) { 3814 usage_with_options_msg(usage_msg, options, 3815 "Unknown --sort key: `%s'", tok); 3816 } 3817 } 3818 3819 free(str); 3820 3821 sort_dimension__add("pid", &sched->cmp_pid); 3822 } 3823 3824 static int process_synthesized_schedstat_event(const struct perf_tool *tool, 3825 union perf_event *event, 3826 struct perf_sample *sample __maybe_unused, 3827 struct machine *machine __maybe_unused) 3828 { 3829 struct perf_sched *sched = container_of(tool, struct perf_sched, tool); 3830 3831 if (perf_data__write(sched->data, event, event->header.size) <= 0) { 3832 pr_err("failed to write perf data, error: %m\n"); 3833 return -1; 3834 } 3835 3836 sched->session->header.data_size += event->header.size; 3837 return 0; 3838 } 3839 3840 static volatile sig_atomic_t done; 3841 3842 static void sighandler(int sig __maybe_unused) 3843 { 3844 done = 1; 3845 } 3846 3847 static int enable_sched_schedstats(int *reset) 3848 { 3849 char path[PATH_MAX]; 3850 FILE *fp; 3851 char ch; 3852 3853 snprintf(path, PATH_MAX, "%s/sys/kernel/sched_schedstats", procfs__mountpoint()); 3854 fp = fopen(path, "w+"); 3855 if (!fp) { 3856 pr_err("Failed to open %s\n", path); 3857 return -1; 3858 } 3859 3860 ch = getc(fp); 3861 if (ch == '0') { 3862 *reset = 1; 3863 rewind(fp); 3864 putc('1', fp); 3865 fclose(fp); 3866 } 3867 return 0; 3868 } 3869 3870 static int disable_sched_schedstat(void) 3871 { 3872 char path[PATH_MAX]; 3873 FILE *fp; 3874 3875 snprintf(path, PATH_MAX, "%s/sys/kernel/sched_schedstats", procfs__mountpoint()); 3876 fp = fopen(path, "w"); 3877 if (!fp) { 3878 pr_err("Failed to open %s\n", path); 3879 return -1; 3880 } 3881 3882 putc('0', fp); 3883 fclose(fp); 3884 return 0; 3885 } 3886 3887 /* perf.data or any other output file name used by stats subcommand (only). */ 3888 const char *output_name; 3889 3890 static int perf_sched__schedstat_record(struct perf_sched *sched, 3891 int argc, const char **argv) 3892 { 3893 struct perf_session *session; 3894 struct target target = {}; 3895 struct evlist *evlist; 3896 int reset = 0; 3897 int err = 0; 3898 int fd; 3899 struct perf_data data = { 3900 .path = output_name, 3901 .mode = PERF_DATA_MODE_WRITE, 3902 }; 3903 3904 done = 0; 3905 signal(SIGINT, sighandler); 3906 signal(SIGCHLD, sighandler); 3907 signal(SIGTERM, sighandler); 3908 3909 evlist = evlist__new(); 3910 if (!evlist) 3911 return -ENOMEM; 3912 3913 session = perf_session__new(&data, &sched->tool); 3914 if (IS_ERR(session)) { 3915 pr_err("Perf session creation failed.\n"); 3916 evlist__delete(evlist); 3917 return PTR_ERR(session); 3918 } 3919 3920 session->evlist = evlist; 3921 3922 sched->session = session; 3923 sched->data = &data; 3924 3925 fd = perf_data__fd(&data); 3926 3927 /* 3928 * Capture all important metadata about the system. Although they are 3929 * not used by `perf sched stats` tool directly, they provide useful 3930 * information about profiled environment. 3931 */ 3932 perf_header__set_feat(&session->header, HEADER_HOSTNAME); 3933 perf_header__set_feat(&session->header, HEADER_OSRELEASE); 3934 perf_header__set_feat(&session->header, HEADER_VERSION); 3935 perf_header__set_feat(&session->header, HEADER_ARCH); 3936 perf_header__set_feat(&session->header, HEADER_NRCPUS); 3937 perf_header__set_feat(&session->header, HEADER_CPUDESC); 3938 perf_header__set_feat(&session->header, HEADER_CPUID); 3939 perf_header__set_feat(&session->header, HEADER_TOTAL_MEM); 3940 perf_header__set_feat(&session->header, HEADER_CMDLINE); 3941 perf_header__set_feat(&session->header, HEADER_CPU_TOPOLOGY); 3942 perf_header__set_feat(&session->header, HEADER_NUMA_TOPOLOGY); 3943 perf_header__set_feat(&session->header, HEADER_CACHE); 3944 perf_header__set_feat(&session->header, HEADER_MEM_TOPOLOGY); 3945 perf_header__set_feat(&session->header, HEADER_HYBRID_TOPOLOGY); 3946 perf_header__set_feat(&session->header, HEADER_CPU_DOMAIN_INFO); 3947 3948 err = perf_session__write_header(session, evlist, fd, false); 3949 if (err < 0) 3950 goto out; 3951 3952 /* 3953 * `perf sched stats` does not support workload profiling (-p pid) 3954 * since /proc/schedstat file contains cpu specific data only. Hence, a 3955 * profile target is either set of cpus or systemwide, never a process. 3956 * Note that, although `-- <workload>` is supported, profile data are 3957 * still cpu/systemwide. 3958 */ 3959 if (cpu_list) 3960 target.cpu_list = cpu_list; 3961 else 3962 target.system_wide = true; 3963 3964 if (argc) { 3965 err = evlist__prepare_workload(evlist, &target, argv, false, NULL); 3966 if (err) 3967 goto out; 3968 } 3969 3970 err = evlist__create_maps(evlist, &target); 3971 if (err < 0) 3972 goto out; 3973 3974 user_requested_cpus = evlist->core.user_requested_cpus; 3975 3976 err = perf_event__synthesize_schedstat(&(sched->tool), 3977 process_synthesized_schedstat_event, 3978 user_requested_cpus); 3979 if (err < 0) 3980 goto out; 3981 3982 err = enable_sched_schedstats(&reset); 3983 if (err < 0) 3984 goto out; 3985 3986 if (argc) 3987 evlist__start_workload(evlist); 3988 3989 while (!done) { 3990 if (argc && waitpid(evlist->workload.pid, NULL, WNOHANG) > 0) 3991 break; 3992 sleep(1); 3993 } 3994 3995 if (reset) { 3996 err = disable_sched_schedstat(); 3997 if (err < 0) 3998 goto out; 3999 } 4000 4001 err = perf_event__synthesize_schedstat(&(sched->tool), 4002 process_synthesized_schedstat_event, 4003 user_requested_cpus); 4004 if (err < 0) 4005 goto out; 4006 4007 err = perf_session__write_header(session, evlist, fd, true); 4008 4009 out: 4010 if (!err) 4011 fprintf(stderr, "[ perf sched stats: Wrote samples to %s ]\n", data.path); 4012 else 4013 fprintf(stderr, "[ perf sched stats: Failed !! ]\n"); 4014 4015 evlist__delete(evlist); 4016 close(fd); 4017 return err; 4018 } 4019 4020 struct schedstat_domain { 4021 struct list_head domain_list; 4022 struct perf_record_schedstat_domain *domain_data; 4023 }; 4024 4025 struct schedstat_cpu { 4026 struct list_head cpu_list; 4027 struct list_head domain_head; 4028 struct perf_record_schedstat_cpu *cpu_data; 4029 }; 4030 4031 static struct list_head cpu_head = LIST_HEAD_INIT(cpu_head); 4032 static struct schedstat_cpu *cpu_second_pass; 4033 static struct schedstat_domain *domain_second_pass; 4034 static bool after_workload_flag; 4035 static bool verbose_field; 4036 4037 static void free_schedstat(struct list_head *head); 4038 4039 static void store_schedstat_cpu_diff(struct schedstat_cpu *after_workload) 4040 { 4041 struct perf_record_schedstat_cpu *before = cpu_second_pass->cpu_data; 4042 struct perf_record_schedstat_cpu *after = after_workload->cpu_data; 4043 __u16 version = after_workload->cpu_data->version; 4044 4045 #define CPU_FIELD(_type, _name, _desc, _format, _is_pct, _pct_of, _ver) \ 4046 (before->_ver._name = after->_ver._name - before->_ver._name) 4047 4048 if (version == 15) { 4049 #include <perf/schedstat-v15.h> 4050 } else if (version == 16) { 4051 #include <perf/schedstat-v16.h> 4052 } else if (version == 17) { 4053 #include <perf/schedstat-v17.h> 4054 } 4055 4056 #undef CPU_FIELD 4057 } 4058 4059 static void store_schedstat_domain_diff(struct schedstat_domain *after_workload) 4060 { 4061 struct perf_record_schedstat_domain *before = domain_second_pass->domain_data; 4062 struct perf_record_schedstat_domain *after = after_workload->domain_data; 4063 __u16 version = after_workload->domain_data->version; 4064 4065 #define DOMAIN_FIELD(_type, _name, _desc, _format, _is_jiffies, _ver) \ 4066 (before->_ver._name = after->_ver._name - before->_ver._name) 4067 4068 if (version == 15) { 4069 #include <perf/schedstat-v15.h> 4070 } else if (version == 16) { 4071 #include <perf/schedstat-v16.h> 4072 } else if (version == 17) { 4073 #include <perf/schedstat-v17.h> 4074 } 4075 #undef DOMAIN_FIELD 4076 } 4077 4078 #define PCT_CHNG(_x, _y) ((_x) ? ((double)((double)(_y) - (_x)) / (_x)) * 100 : 0.0) 4079 static inline void print_cpu_stats(struct perf_record_schedstat_cpu *cs1, 4080 struct perf_record_schedstat_cpu *cs2) 4081 { 4082 printf("%-65s ", "DESC"); 4083 if (!cs2) 4084 printf("%12s %12s", "COUNT", "PCT_CHANGE"); 4085 else 4086 printf("%12s %11s %12s %14s %10s", "COUNT1", "COUNT2", "PCT_CHANGE", 4087 "PCT_CHANGE1", "PCT_CHANGE2"); 4088 4089 printf("\n"); 4090 print_separator2(SEP_LEN, "", 0); 4091 4092 #define CALC_PCT(_x, _y) ((_y) ? ((double)(_x) / (_y)) * 100 : 0.0) 4093 4094 #define CPU_FIELD(_type, _name, _desc, _format, _is_pct, _pct_of, _ver) \ 4095 do { \ 4096 printf("%-65s: " _format, verbose_field ? _desc : #_name, \ 4097 cs1->_ver._name); \ 4098 if (!cs2) { \ 4099 if (_is_pct) \ 4100 printf(" ( %8.2lf%% )", \ 4101 CALC_PCT(cs1->_ver._name, cs1->_ver._pct_of)); \ 4102 } else { \ 4103 printf("," _format " | %8.2lf%% |", cs2->_ver._name, \ 4104 PCT_CHNG(cs1->_ver._name, cs2->_ver._name)); \ 4105 if (_is_pct) \ 4106 printf(" ( %8.2lf%%, %8.2lf%% )", \ 4107 CALC_PCT(cs1->_ver._name, cs1->_ver._pct_of), \ 4108 CALC_PCT(cs2->_ver._name, cs2->_ver._pct_of)); \ 4109 } \ 4110 printf("\n"); \ 4111 } while (0) 4112 4113 if (cs1->version == 15) { 4114 #include <perf/schedstat-v15.h> 4115 } else if (cs1->version == 16) { 4116 #include <perf/schedstat-v16.h> 4117 } else if (cs1->version == 17) { 4118 #include <perf/schedstat-v17.h> 4119 } 4120 4121 #undef CPU_FIELD 4122 #undef CALC_PCT 4123 } 4124 4125 static inline void print_domain_stats(struct perf_record_schedstat_domain *ds1, 4126 struct perf_record_schedstat_domain *ds2, 4127 __u64 jiffies1, __u64 jiffies2) 4128 { 4129 printf("%-65s ", "DESC"); 4130 if (!ds2) 4131 printf("%12s %14s", "COUNT", "AVG_JIFFIES"); 4132 else 4133 printf("%12s %11s %12s %16s %12s", "COUNT1", "COUNT2", "PCT_CHANGE", 4134 "AVG_JIFFIES1", "AVG_JIFFIES2"); 4135 printf("\n"); 4136 4137 #define DOMAIN_CATEGORY(_desc) \ 4138 do { \ 4139 size_t _len = strlen(_desc); \ 4140 size_t _pre_dash_cnt = (SEP_LEN - _len) / 2; \ 4141 size_t _post_dash_cnt = SEP_LEN - _len - _pre_dash_cnt; \ 4142 print_separator2((int)_pre_dash_cnt, _desc, (int)_post_dash_cnt);\ 4143 } while (0) 4144 4145 #define CALC_AVG(_x, _y) ((_y) ? (long double)(_x) / (_y) : 0.0) 4146 4147 #define DOMAIN_FIELD(_type, _name, _desc, _format, _is_jiffies, _ver) \ 4148 do { \ 4149 printf("%-65s: " _format, verbose_field ? _desc : #_name, \ 4150 ds1->_ver._name); \ 4151 if (!ds2) { \ 4152 if (_is_jiffies) \ 4153 printf(" $ %11.2Lf $", \ 4154 CALC_AVG(jiffies1, ds1->_ver._name)); \ 4155 } else { \ 4156 printf("," _format " | %8.2lf%% |", ds2->_ver._name, \ 4157 PCT_CHNG(ds1->_ver._name, ds2->_ver._name)); \ 4158 if (_is_jiffies) \ 4159 printf(" $ %11.2Lf, %11.2Lf $", \ 4160 CALC_AVG(jiffies1, ds1->_ver._name), \ 4161 CALC_AVG(jiffies2, ds2->_ver._name)); \ 4162 } \ 4163 printf("\n"); \ 4164 } while (0) 4165 4166 #define DERIVED_CNT_FIELD(_name, _desc, _format, _x, _y, _z, _ver) \ 4167 do { \ 4168 __u32 t1 = ds1->_ver._x - ds1->_ver._y - ds1->_ver._z; \ 4169 printf("*%-64s: " _format, verbose_field ? _desc : #_name, t1); \ 4170 if (ds2) { \ 4171 __u32 t2 = ds2->_ver._x - ds2->_ver._y - ds2->_ver._z; \ 4172 printf("," _format " | %8.2lf%% |", t2, \ 4173 PCT_CHNG(t1, t2)); \ 4174 } \ 4175 printf("\n"); \ 4176 } while (0) 4177 4178 #define DERIVED_AVG_FIELD(_name, _desc, _format, _x, _y, _z, _w, _ver) \ 4179 do { \ 4180 __u32 t1 = ds1->_ver._x - ds1->_ver._y - ds1->_ver._z; \ 4181 printf("*%-64s: " _format, verbose_field ? _desc : #_name, \ 4182 CALC_AVG(ds1->_ver._w, t1)); \ 4183 if (ds2) { \ 4184 __u32 t2 = ds2->_ver._x - ds2->_ver._y - ds2->_ver._z; \ 4185 printf("," _format " | %8.2Lf%% |", \ 4186 CALC_AVG(ds2->_ver._w, t2), \ 4187 PCT_CHNG(CALC_AVG(ds1->_ver._w, t1), \ 4188 CALC_AVG(ds2->_ver._w, t2))); \ 4189 } \ 4190 printf("\n"); \ 4191 } while (0) 4192 4193 if (ds1->version == 15) { 4194 #include <perf/schedstat-v15.h> 4195 } else if (ds1->version == 16) { 4196 #include <perf/schedstat-v16.h> 4197 } else if (ds1->version == 17) { 4198 #include <perf/schedstat-v17.h> 4199 } 4200 4201 #undef DERIVED_AVG_FIELD 4202 #undef DERIVED_CNT_FIELD 4203 #undef DOMAIN_FIELD 4204 #undef CALC_AVG 4205 #undef DOMAIN_CATEGORY 4206 } 4207 #undef PCT_CHNG 4208 4209 static void summarize_schedstat_cpu(struct schedstat_cpu *summary_cpu, 4210 struct schedstat_cpu *cptr, 4211 int cnt, bool is_last) 4212 { 4213 struct perf_record_schedstat_cpu *summary_cs = summary_cpu->cpu_data, 4214 *temp_cs = cptr->cpu_data; 4215 4216 #define CPU_FIELD(_type, _name, _desc, _format, _is_pct, _pct_of, _ver) \ 4217 do { \ 4218 summary_cs->_ver._name += temp_cs->_ver._name; \ 4219 if (is_last) \ 4220 summary_cs->_ver._name /= cnt; \ 4221 } while (0) 4222 4223 if (cptr->cpu_data->version == 15) { 4224 #include <perf/schedstat-v15.h> 4225 } else if (cptr->cpu_data->version == 16) { 4226 #include <perf/schedstat-v16.h> 4227 } else if (cptr->cpu_data->version == 17) { 4228 #include <perf/schedstat-v17.h> 4229 } 4230 #undef CPU_FIELD 4231 } 4232 4233 static void summarize_schedstat_domain(struct schedstat_domain *summary_domain, 4234 struct schedstat_domain *dptr, 4235 int cnt, bool is_last) 4236 { 4237 struct perf_record_schedstat_domain *summary_ds = summary_domain->domain_data, 4238 *temp_ds = dptr->domain_data; 4239 4240 #define DOMAIN_FIELD(_type, _name, _desc, _format, _is_jiffies, _ver) \ 4241 do { \ 4242 summary_ds->_ver._name += temp_ds->_ver._name; \ 4243 if (is_last) \ 4244 summary_ds->_ver._name /= cnt; \ 4245 } while (0) 4246 4247 if (dptr->domain_data->version == 15) { 4248 #include <perf/schedstat-v15.h> 4249 } else if (dptr->domain_data->version == 16) { 4250 #include <perf/schedstat-v16.h> 4251 } else if (dptr->domain_data->version == 17) { 4252 #include <perf/schedstat-v17.h> 4253 } 4254 #undef DOMAIN_FIELD 4255 } 4256 4257 /* 4258 * get_all_cpu_stats() appends the summary to the head of the list. 4259 */ 4260 static int get_all_cpu_stats(struct list_head *head) 4261 { 4262 struct schedstat_cpu *cptr, *summary_head = NULL; 4263 struct schedstat_domain *dptr, *tdptr; 4264 bool is_last = false; 4265 int cnt = 1; 4266 int ret = 0; 4267 struct list_head tmp_cleanup_list; 4268 4269 assert(!list_empty(head)); 4270 cptr = list_first_entry(head, struct schedstat_cpu, cpu_list); 4271 4272 INIT_LIST_HEAD(&tmp_cleanup_list); 4273 4274 summary_head = zalloc(sizeof(*summary_head)); 4275 if (!summary_head) 4276 return -ENOMEM; 4277 4278 INIT_LIST_HEAD(&summary_head->domain_head); 4279 INIT_LIST_HEAD(&summary_head->cpu_list); 4280 list_add(&summary_head->cpu_list, &tmp_cleanup_list); 4281 4282 summary_head->cpu_data = zalloc(sizeof(*summary_head->cpu_data)); 4283 if (!summary_head->cpu_data) { 4284 ret = -ENOMEM; 4285 goto out_cleanup; 4286 } 4287 memcpy(summary_head->cpu_data, cptr->cpu_data, sizeof(*summary_head->cpu_data)); 4288 4289 list_for_each_entry(dptr, &cptr->domain_head, domain_list) { 4290 tdptr = zalloc(sizeof(*tdptr)); 4291 if (!tdptr) { 4292 ret = -ENOMEM; 4293 goto out_cleanup; 4294 } 4295 INIT_LIST_HEAD(&tdptr->domain_list); 4296 4297 tdptr->domain_data = zalloc(sizeof(*tdptr->domain_data)); 4298 if (!tdptr->domain_data) { 4299 free(tdptr); 4300 ret = -ENOMEM; 4301 goto out_cleanup; 4302 } 4303 4304 memcpy(tdptr->domain_data, dptr->domain_data, sizeof(*tdptr->domain_data)); 4305 list_add_tail(&tdptr->domain_list, &summary_head->domain_head); 4306 } 4307 4308 list_for_each_entry(cptr, head, cpu_list) { 4309 if (list_is_first(&cptr->cpu_list, head)) 4310 continue; 4311 4312 if (list_is_last(&cptr->cpu_list, head)) 4313 is_last = true; 4314 4315 cnt++; 4316 summarize_schedstat_cpu(summary_head, cptr, cnt, is_last); 4317 if (list_empty(&summary_head->domain_head)) 4318 continue; 4319 4320 tdptr = list_first_entry(&summary_head->domain_head, struct schedstat_domain, 4321 domain_list); 4322 4323 list_for_each_entry(dptr, &cptr->domain_head, domain_list) { 4324 summarize_schedstat_domain(tdptr, dptr, cnt, is_last); 4325 if (list_is_last(&tdptr->domain_list, &summary_head->domain_head)) { 4326 tdptr = NULL; 4327 break; 4328 } 4329 tdptr = list_next_entry(tdptr, domain_list); 4330 } 4331 } 4332 4333 list_del_init(&summary_head->cpu_list); 4334 list_add(&summary_head->cpu_list, head); 4335 return 0; 4336 4337 out_cleanup: 4338 free_schedstat(&tmp_cleanup_list); 4339 return ret; 4340 } 4341 4342 static int show_schedstat_data(struct list_head *head1, struct cpu_domain_map **cd_map1, int nr1, 4343 struct list_head *head2, struct cpu_domain_map **cd_map2, int nr2, 4344 bool summary_only) 4345 { 4346 struct schedstat_cpu *cptr1 = list_first_entry(head1, struct schedstat_cpu, cpu_list); 4347 struct perf_record_schedstat_domain *ds1 = NULL, *ds2 = NULL; 4348 struct schedstat_domain *dptr1 = NULL, *dptr2 = NULL; 4349 struct schedstat_cpu *cptr2 = NULL; 4350 __u64 jiffies1 = 0, jiffies2 = 0; 4351 bool is_summary = true; 4352 int ret = 0; 4353 4354 if (!cd_map1) { 4355 pr_err("Error: CPU domain map 1 is missing.\n"); 4356 return -1; 4357 } 4358 if (head2 && !cd_map2) { 4359 pr_err("Error: CPU domain map 2 is missing.\n"); 4360 return -1; 4361 } 4362 4363 printf("Description\n"); 4364 print_separator2(SEP_LEN, "", 0); 4365 printf("%-30s-> %s\n", "DESC", "Description of the field"); 4366 printf("%-30s-> %s\n", "COUNT", "Value of the field"); 4367 printf("%-30s-> %s\n", "PCT_CHANGE", "Percent change with corresponding base value"); 4368 printf("%-30s-> %s\n", "AVG_JIFFIES", 4369 "Avg time in jiffies between two consecutive occurrence of event"); 4370 4371 print_separator2(SEP_LEN, "", 0); 4372 printf("\n"); 4373 4374 printf("%-65s: ", "Time elapsed (in jiffies)"); 4375 jiffies1 = cptr1->cpu_data->timestamp; 4376 printf("%11llu", jiffies1); 4377 if (head2) { 4378 cptr2 = list_first_entry(head2, struct schedstat_cpu, cpu_list); 4379 jiffies2 = cptr2->cpu_data->timestamp; 4380 printf(",%11llu", jiffies2); 4381 } 4382 printf("\n"); 4383 4384 ret = get_all_cpu_stats(head1); 4385 if (ret) 4386 return ret; 4387 if (cptr2) { 4388 ret = get_all_cpu_stats(head2); 4389 if (ret) 4390 return ret; 4391 cptr2 = list_first_entry(head2, struct schedstat_cpu, cpu_list); 4392 } 4393 4394 list_for_each_entry(cptr1, head1, cpu_list) { 4395 struct cpu_domain_map *cd_info1 = NULL, *cd_info2 = NULL; 4396 struct perf_record_schedstat_cpu *cs1 = cptr1->cpu_data; 4397 struct perf_record_schedstat_cpu *cs2 = NULL; 4398 4399 dptr2 = NULL; 4400 if (cs1->cpu >= (u32)nr1) { 4401 pr_err("Error: CPU %d exceeds domain map size %d\n", cs1->cpu, nr1); 4402 return -1; 4403 } 4404 cd_info1 = cd_map1[cs1->cpu]; 4405 if (!cd_info1) { 4406 pr_err("Error: CPU %d domain info is missing in map 1.\n", 4407 cs1->cpu); 4408 return -1; 4409 } 4410 if (cptr2) { 4411 cs2 = cptr2->cpu_data; 4412 if (cs2->cpu >= (u32)nr2) { 4413 pr_err("Error: CPU %d exceeds domain map size %d\n", cs2->cpu, nr2); 4414 return -1; 4415 } 4416 cd_info2 = cd_map2[cs2->cpu]; 4417 if (!cd_info2) { 4418 pr_err("Error: CPU %d domain info is missing in map 2.\n", 4419 cs2->cpu); 4420 return -1; 4421 } 4422 if (!list_empty(&cptr2->domain_head)) 4423 dptr2 = list_first_entry(&cptr2->domain_head, 4424 struct schedstat_domain, 4425 domain_list); 4426 } 4427 4428 if (cs2 && cs1->cpu != cs2->cpu) { 4429 pr_err("Failed because matching cpus not found for diff\n"); 4430 return -1; 4431 } 4432 4433 if (cd_info2 && cd_info1->nr_domains != cd_info2->nr_domains) { 4434 pr_err("Failed because nr_domains is not same for cpus\n"); 4435 return -1; 4436 } 4437 4438 print_separator2(SEP_LEN, "", 0); 4439 4440 if (is_summary) 4441 printf("CPU: <ALL CPUS SUMMARY>\n"); 4442 else 4443 printf("CPU: %d\n", cs1->cpu); 4444 4445 print_separator2(SEP_LEN, "", 0); 4446 print_cpu_stats(cs1, cs2); 4447 print_separator2(SEP_LEN, "", 0); 4448 4449 list_for_each_entry(dptr1, &cptr1->domain_head, domain_list) { 4450 struct domain_info *dinfo1 = NULL, *dinfo2 = NULL; 4451 4452 ds1 = dptr1->domain_data; 4453 ds2 = NULL; 4454 if (ds1->domain >= cd_info1->nr_domains) { 4455 pr_err("Error: Domain %d exceeds max domains %d for CPU %d in map 1.\n", 4456 ds1->domain, cd_info1->nr_domains, cs1->cpu); 4457 return -1; 4458 } 4459 dinfo1 = cd_info1->domains[ds1->domain]; 4460 if (!dinfo1) { 4461 pr_err("Error: Domain %d info is missing for CPU %d in map 1.\n", 4462 ds1->domain, cs1->cpu); 4463 return -1; 4464 } 4465 if (dptr2) { 4466 ds2 = dptr2->domain_data; 4467 if (ds2->domain >= cd_info2->nr_domains) { 4468 pr_err("Error: Domain %d exceeds max domains %d for CPU %d in map 2.\n", 4469 ds2->domain, cd_info2->nr_domains, cs2->cpu); 4470 return -1; 4471 } 4472 dinfo2 = cd_info2->domains[ds2->domain]; 4473 if (!dinfo2) { 4474 pr_err("Error: Domain %d info is missing for CPU %d in map 2.\n", 4475 ds2->domain, cs2->cpu); 4476 return -1; 4477 } 4478 } 4479 4480 if (dinfo2 && dinfo1->domain != dinfo2->domain) { 4481 pr_err("Failed because matching domain not found for diff\n"); 4482 return -1; 4483 } 4484 4485 if (is_summary) { 4486 if (dinfo1->dname) 4487 printf("CPU: <ALL CPUS SUMMARY> | DOMAIN: %s\n", 4488 dinfo1->dname); 4489 else 4490 printf("CPU: <ALL CPUS SUMMARY> | DOMAIN: %d\n", 4491 dinfo1->domain); 4492 } else { 4493 if (dinfo1->dname) 4494 printf("CPU: %d | DOMAIN: %s | DOMAIN_CPUS: ", 4495 cs1->cpu, dinfo1->dname); 4496 else 4497 printf("CPU: %d | DOMAIN: %d | DOMAIN_CPUS: ", 4498 cs1->cpu, dinfo1->domain); 4499 4500 printf("%s\n", dinfo1->cpulist); 4501 } 4502 print_separator2(SEP_LEN, "", 0); 4503 print_domain_stats(ds1, ds2, jiffies1, jiffies2); 4504 print_separator2(SEP_LEN, "", 0); 4505 4506 if (dptr2) { 4507 if (list_is_last(&dptr2->domain_list, &cptr2->domain_head)) 4508 dptr2 = NULL; 4509 else 4510 dptr2 = list_next_entry(dptr2, domain_list); 4511 } 4512 } 4513 if (summary_only) 4514 break; 4515 4516 if (cptr2) { 4517 if (list_is_last(&cptr2->cpu_list, head2)) 4518 cptr2 = NULL; 4519 else 4520 cptr2 = list_next_entry(cptr2, cpu_list); 4521 } 4522 4523 is_summary = false; 4524 } 4525 return ret; 4526 } 4527 4528 /* 4529 * Creates a linked list of cpu_data and domain_data. Below represents the structure of the linked 4530 * list where CPU0,CPU1,CPU2, ..., CPU(N-1) stores the cpu_data. Here N is the total number of cpus. 4531 * Each of the CPU points to the list of domain_data. Here DOMAIN0, DOMAIN1, DOMAIN2, ... represents 4532 * the domain_data. Here D0, D1, D2, ..., Dm are the number of domains in the respective cpus. 4533 * 4534 * +----------+ 4535 * | CPU_HEAD | 4536 * +----------+ 4537 * | 4538 * v 4539 * +----------+ +---------+ +---------+ +---------+ +--------------+ 4540 * | CPU0 | -> | DOMAIN0 | -> | DOMAIN1 | -> | DOMAIN2 | -> ... -> | DOMAIN(D0-1) | 4541 * +----------+ +---------+ +---------+ +---------+ +--------------+ 4542 * | 4543 * v 4544 * +----------+ +---------+ +---------+ +---------+ +--------------+ 4545 * | CPU1 | -> | DOMAIN0 | -> | DOMAIN1 | -> | DOMAIN2 | -> ... -> | DOMAIN(D1-1) | 4546 * +----------+ +---------+ +---------+ +---------+ +--------------+ 4547 * | 4548 * v 4549 * +----------+ +---------+ +---------+ +---------+ +--------------+ 4550 * | CPU2 | -> | DOMAIN0 | -> | DOMAIN1 | -> | DOMAIN2 | -> ... -> | DOMAIN(D2-1) | 4551 * +----------+ +---------+ +---------+ +---------+ +--------------+ 4552 * | 4553 * v 4554 * ... 4555 * | 4556 * v 4557 * +----------+ +---------+ +---------+ +---------+ +--------------+ 4558 * | CPU(N-1) | -> | DOMAIN0 | -> | DOMAIN1 | -> | DOMAIN2 | -> ... -> | DOMAIN(Dm-1) | 4559 * +----------+ +---------+ +---------+ +---------+ +--------------+ 4560 * 4561 * Each cpu as well as domain has 2 enties in the event list one before the workload starts and 4562 * other after completion of the workload. The above linked list stores the diff of the cpu and 4563 * domain statistics. 4564 */ 4565 static int perf_sched__process_schedstat(const struct perf_tool *tool __maybe_unused, 4566 struct perf_session *session __maybe_unused, 4567 union perf_event *event) 4568 { 4569 struct perf_cpu this_cpu; 4570 static __u32 initial_cpu; 4571 4572 switch (event->header.type) { 4573 case PERF_RECORD_SCHEDSTAT_CPU: 4574 this_cpu.cpu = event->schedstat_cpu.cpu; 4575 break; 4576 case PERF_RECORD_SCHEDSTAT_DOMAIN: 4577 this_cpu.cpu = event->schedstat_domain.cpu; 4578 break; 4579 default: 4580 return 0; 4581 } 4582 4583 if (user_requested_cpus && !perf_cpu_map__has(user_requested_cpus, this_cpu)) 4584 return 0; 4585 4586 if (event->header.type == PERF_RECORD_SCHEDSTAT_CPU) { 4587 struct schedstat_cpu *temp = zalloc(sizeof(*temp)); 4588 4589 if (!temp) 4590 return -ENOMEM; 4591 4592 temp->cpu_data = zalloc(sizeof(*temp->cpu_data)); 4593 if (!temp->cpu_data) 4594 return -ENOMEM; 4595 4596 memcpy(temp->cpu_data, &event->schedstat_cpu, sizeof(*temp->cpu_data)); 4597 4598 if (!list_empty(&cpu_head) && temp->cpu_data->cpu == initial_cpu) 4599 after_workload_flag = true; 4600 4601 if (!after_workload_flag) { 4602 if (list_empty(&cpu_head)) 4603 initial_cpu = temp->cpu_data->cpu; 4604 4605 list_add_tail(&temp->cpu_list, &cpu_head); 4606 INIT_LIST_HEAD(&temp->domain_head); 4607 } else { 4608 if (temp->cpu_data->cpu == initial_cpu) { 4609 cpu_second_pass = list_first_entry(&cpu_head, struct schedstat_cpu, 4610 cpu_list); 4611 cpu_second_pass->cpu_data->timestamp = 4612 temp->cpu_data->timestamp - cpu_second_pass->cpu_data->timestamp; 4613 } else { 4614 cpu_second_pass = list_next_entry(cpu_second_pass, cpu_list); 4615 } 4616 domain_second_pass = list_first_entry(&cpu_second_pass->domain_head, 4617 struct schedstat_domain, domain_list); 4618 store_schedstat_cpu_diff(temp); 4619 } 4620 } else if (event->header.type == PERF_RECORD_SCHEDSTAT_DOMAIN) { 4621 struct schedstat_cpu *cpu_tail; 4622 struct schedstat_domain *temp = zalloc(sizeof(*temp)); 4623 4624 if (!temp) 4625 return -ENOMEM; 4626 4627 temp->domain_data = zalloc(sizeof(*temp->domain_data)); 4628 if (!temp->domain_data) 4629 return -ENOMEM; 4630 4631 memcpy(temp->domain_data, &event->schedstat_domain, sizeof(*temp->domain_data)); 4632 4633 if (!after_workload_flag) { 4634 cpu_tail = list_last_entry(&cpu_head, struct schedstat_cpu, cpu_list); 4635 list_add_tail(&temp->domain_list, &cpu_tail->domain_head); 4636 } else { 4637 store_schedstat_domain_diff(temp); 4638 domain_second_pass = list_next_entry(domain_second_pass, domain_list); 4639 } 4640 } 4641 4642 return 0; 4643 } 4644 4645 static void free_schedstat(struct list_head *head) 4646 { 4647 struct schedstat_domain *dptr, *n1; 4648 struct schedstat_cpu *cptr, *n2; 4649 4650 list_for_each_entry_safe(cptr, n2, head, cpu_list) { 4651 list_for_each_entry_safe(dptr, n1, &cptr->domain_head, domain_list) { 4652 list_del_init(&dptr->domain_list); 4653 free(dptr->domain_data); 4654 free(dptr); 4655 } 4656 list_del_init(&cptr->cpu_list); 4657 free(cptr->cpu_data); 4658 free(cptr); 4659 } 4660 } 4661 4662 static int perf_sched__schedstat_report(struct perf_sched *sched) 4663 { 4664 struct cpu_domain_map **cd_map; 4665 struct perf_session *session; 4666 struct target target = {}; 4667 struct perf_data data = { 4668 .path = input_name, 4669 .mode = PERF_DATA_MODE_READ, 4670 }; 4671 int err = 0; 4672 4673 sched->tool.schedstat_cpu = perf_sched__process_schedstat; 4674 sched->tool.schedstat_domain = perf_sched__process_schedstat; 4675 4676 session = perf_session__new(&data, &sched->tool); 4677 if (IS_ERR(session)) { 4678 pr_err("Perf session creation failed.\n"); 4679 return PTR_ERR(session); 4680 } 4681 4682 if (cpu_list) 4683 target.cpu_list = cpu_list; 4684 else 4685 target.system_wide = true; 4686 4687 err = evlist__create_maps(session->evlist, &target); 4688 if (err < 0) 4689 goto out; 4690 4691 user_requested_cpus = session->evlist->core.user_requested_cpus; 4692 4693 err = perf_session__process_events(session); 4694 4695 if (!err) { 4696 setup_pager(); 4697 4698 if (list_empty(&cpu_head)) { 4699 pr_err("Data is not available\n"); 4700 err = -1; 4701 goto out; 4702 } 4703 4704 cd_map = session->header.env.cpu_domain; 4705 err = show_schedstat_data(&cpu_head, cd_map, 4706 session->header.env.nr_cpus_avail, 4707 NULL, NULL, 0, false); 4708 } 4709 4710 out: 4711 free_schedstat(&cpu_head); 4712 perf_session__delete(session); 4713 return err; 4714 } 4715 4716 static int perf_sched__schedstat_diff(struct perf_sched *sched, 4717 int argc, const char **argv) 4718 { 4719 struct cpu_domain_map **cd_map0 = NULL, **cd_map1 = NULL; 4720 struct list_head cpu_head_ses0, cpu_head_ses1; 4721 struct perf_session *session[2]; 4722 struct perf_data data[2] = {0}; 4723 int ret = 0, err = 0; 4724 static const char *defaults[] = { 4725 "perf.data.old", 4726 "perf.data", 4727 }; 4728 4729 if (argc) { 4730 if (argc == 1) 4731 defaults[1] = argv[0]; 4732 else if (argc == 2) { 4733 defaults[0] = argv[0]; 4734 defaults[1] = argv[1]; 4735 } else { 4736 pr_err("perf sched stats diff is not supported with more than 2 files.\n"); 4737 goto out_ret; 4738 } 4739 } 4740 4741 INIT_LIST_HEAD(&cpu_head_ses0); 4742 INIT_LIST_HEAD(&cpu_head_ses1); 4743 4744 sched->tool.schedstat_cpu = perf_sched__process_schedstat; 4745 sched->tool.schedstat_domain = perf_sched__process_schedstat; 4746 4747 data[0].path = defaults[0]; 4748 data[0].mode = PERF_DATA_MODE_READ; 4749 session[0] = perf_session__new(&data[0], &sched->tool); 4750 if (IS_ERR(session[0])) { 4751 ret = PTR_ERR(session[0]); 4752 pr_err("Failed to open %s\n", data[0].path); 4753 goto out_delete_ses0; 4754 } 4755 4756 err = perf_session__process_events(session[0]); 4757 if (err) { 4758 free_schedstat(&cpu_head); 4759 goto out_delete_ses0; 4760 } 4761 4762 cd_map0 = session[0]->header.env.cpu_domain; 4763 list_replace_init(&cpu_head, &cpu_head_ses0); 4764 after_workload_flag = false; 4765 4766 data[1].path = defaults[1]; 4767 data[1].mode = PERF_DATA_MODE_READ; 4768 session[1] = perf_session__new(&data[1], &sched->tool); 4769 if (IS_ERR(session[1])) { 4770 ret = PTR_ERR(session[1]); 4771 pr_err("Failed to open %s\n", data[1].path); 4772 goto out_delete_ses1; 4773 } 4774 4775 err = perf_session__process_events(session[1]); 4776 if (err) { 4777 free_schedstat(&cpu_head); 4778 goto out_delete_ses1; 4779 } 4780 4781 cd_map1 = session[1]->header.env.cpu_domain; 4782 list_replace_init(&cpu_head, &cpu_head_ses1); 4783 after_workload_flag = false; 4784 setup_pager(); 4785 4786 if (list_empty(&cpu_head_ses1)) { 4787 pr_err("Data is not available\n"); 4788 ret = -1; 4789 goto out_delete_ses1; 4790 } 4791 4792 if (list_empty(&cpu_head_ses0)) { 4793 pr_err("Data is not available\n"); 4794 ret = -1; 4795 goto out_delete_ses1; 4796 } 4797 4798 ret = show_schedstat_data(&cpu_head_ses0, cd_map0, session[0]->header.env.nr_cpus_avail, 4799 &cpu_head_ses1, cd_map1, session[1]->header.env.nr_cpus_avail, true); 4800 if (ret) 4801 goto out_delete_ses1; 4802 4803 out_delete_ses1: 4804 free_schedstat(&cpu_head_ses1); 4805 if (!IS_ERR(session[1])) 4806 perf_session__delete(session[1]); 4807 4808 out_delete_ses0: 4809 free_schedstat(&cpu_head_ses0); 4810 if (!IS_ERR(session[0])) 4811 perf_session__delete(session[0]); 4812 4813 out_ret: 4814 return ret; 4815 } 4816 4817 static int process_synthesized_event_live(const struct perf_tool *tool __maybe_unused, 4818 union perf_event *event, 4819 struct perf_sample *sample __maybe_unused, 4820 struct machine *machine __maybe_unused) 4821 { 4822 return perf_sched__process_schedstat(tool, NULL, event); 4823 } 4824 4825 static int perf_sched__schedstat_live(struct perf_sched *sched, 4826 int argc, const char **argv) 4827 { 4828 struct cpu_domain_map **cd_map = NULL; 4829 struct target target = {}; 4830 u32 __maybe_unused md; 4831 struct evlist *evlist; 4832 u32 nr = 0, sv; 4833 int reset = 0; 4834 int err = 0; 4835 4836 done = 0; 4837 signal(SIGINT, sighandler); 4838 signal(SIGCHLD, sighandler); 4839 signal(SIGTERM, sighandler); 4840 4841 evlist = evlist__new(); 4842 if (!evlist) 4843 return -ENOMEM; 4844 4845 /* 4846 * `perf sched schedstat` does not support workload profiling (-p pid) 4847 * since /proc/schedstat file contains cpu specific data only. Hence, a 4848 * profile target is either set of cpus or systemwide, never a process. 4849 * Note that, although `-- <workload>` is supported, profile data are 4850 * still cpu/systemwide. 4851 */ 4852 if (cpu_list) 4853 target.cpu_list = cpu_list; 4854 else 4855 target.system_wide = true; 4856 4857 if (argc) { 4858 err = evlist__prepare_workload(evlist, &target, argv, false, NULL); 4859 if (err) 4860 goto out; 4861 } 4862 4863 err = evlist__create_maps(evlist, &target); 4864 if (err < 0) 4865 goto out; 4866 4867 user_requested_cpus = evlist->core.user_requested_cpus; 4868 4869 err = perf_event__synthesize_schedstat(&(sched->tool), 4870 process_synthesized_event_live, 4871 user_requested_cpus); 4872 if (err < 0) 4873 goto out; 4874 4875 err = enable_sched_schedstats(&reset); 4876 if (err < 0) 4877 goto out; 4878 4879 if (argc) 4880 evlist__start_workload(evlist); 4881 4882 while (!done) { 4883 if (argc && waitpid(evlist->workload.pid, NULL, WNOHANG) > 0) 4884 break; 4885 sleep(1); 4886 } 4887 4888 if (reset) { 4889 err = disable_sched_schedstat(); 4890 if (err < 0) 4891 goto out; 4892 } 4893 4894 err = perf_event__synthesize_schedstat(&(sched->tool), 4895 process_synthesized_event_live, 4896 user_requested_cpus); 4897 if (err) 4898 goto out; 4899 4900 setup_pager(); 4901 4902 if (list_empty(&cpu_head)) { 4903 pr_err("Data is not available\n"); 4904 err = -1; 4905 goto out; 4906 } 4907 4908 nr = cpu__max_present_cpu().cpu; 4909 cd_map = build_cpu_domain_map(&sv, &md, nr); 4910 if (!cd_map) { 4911 pr_err("Unable to generate cpu-domain relation info"); 4912 goto out; 4913 } 4914 4915 err = show_schedstat_data(&cpu_head, cd_map, nr, NULL, NULL, 0, false); 4916 free_cpu_domain_info(cd_map, sv, nr); 4917 out: 4918 free_schedstat(&cpu_head); 4919 evlist__delete(evlist); 4920 return err; 4921 } 4922 4923 static bool schedstat_events_exposed(void) 4924 { 4925 /* 4926 * Select "sched:sched_stat_wait" event to check 4927 * whether schedstat tracepoints are exposed. 4928 */ 4929 return IS_ERR(trace_event__tp_format("sched", "sched_stat_wait")) ? 4930 false : true; 4931 } 4932 4933 static int __cmd_record(int argc, const char **argv) 4934 { 4935 unsigned int rec_argc, i, j; 4936 char **rec_argv; 4937 const char **rec_argv_copy; 4938 const char * const record_args[] = { 4939 "record", 4940 "-a", 4941 "-R", 4942 "-m", "1024", 4943 "-c", "1", 4944 "-e", "sched:sched_switch", 4945 "-e", "sched:sched_stat_runtime", 4946 "-e", "sched:sched_process_fork", 4947 "-e", "sched:sched_wakeup_new", 4948 "-e", "sched:sched_migrate_task", 4949 }; 4950 4951 /* 4952 * The tracepoints trace_sched_stat_{wait, sleep, iowait} 4953 * are not exposed to user if CONFIG_SCHEDSTATS is not set, 4954 * to prevent "perf sched record" execution failure, determine 4955 * whether to record schedstat events according to actual situation. 4956 */ 4957 const char * const schedstat_args[] = { 4958 "-e", "sched:sched_stat_wait", 4959 "-e", "sched:sched_stat_sleep", 4960 "-e", "sched:sched_stat_iowait", 4961 }; 4962 unsigned int schedstat_argc = schedstat_events_exposed() ? 4963 ARRAY_SIZE(schedstat_args) : 0; 4964 4965 struct tep_event *waking_event; 4966 int ret; 4967 4968 /* 4969 * +2 for either "-e", "sched:sched_wakeup" or 4970 * "-e", "sched:sched_waking" 4971 */ 4972 rec_argc = ARRAY_SIZE(record_args) + 2 + schedstat_argc + argc - 1; 4973 rec_argv = calloc(rec_argc + 1, sizeof(char *)); 4974 if (rec_argv == NULL) 4975 return -ENOMEM; 4976 rec_argv_copy = calloc(rec_argc + 1, sizeof(char *)); 4977 if (rec_argv_copy == NULL) { 4978 free(rec_argv); 4979 return -ENOMEM; 4980 } 4981 4982 for (i = 0; i < ARRAY_SIZE(record_args); i++) 4983 rec_argv[i] = strdup(record_args[i]); 4984 4985 rec_argv[i++] = strdup("-e"); 4986 waking_event = trace_event__tp_format("sched", "sched_waking"); 4987 if (!IS_ERR(waking_event)) 4988 rec_argv[i++] = strdup("sched:sched_waking"); 4989 else 4990 rec_argv[i++] = strdup("sched:sched_wakeup"); 4991 4992 for (j = 0; j < schedstat_argc; j++) 4993 rec_argv[i++] = strdup(schedstat_args[j]); 4994 4995 for (j = 1; j < (unsigned int)argc; j++, i++) 4996 rec_argv[i] = strdup(argv[j]); 4997 4998 BUG_ON(i != rec_argc); 4999 5000 memcpy(rec_argv_copy, rec_argv, sizeof(char *) * rec_argc); 5001 ret = cmd_record(rec_argc, rec_argv_copy); 5002 5003 for (i = 0; i < rec_argc; i++) 5004 free(rec_argv[i]); 5005 free(rec_argv); 5006 free(rec_argv_copy); 5007 5008 return ret; 5009 } 5010 5011 int cmd_sched(int argc, const char **argv) 5012 { 5013 static const char default_sort_order[] = "avg, max, switch, runtime"; 5014 struct perf_sched sched = { 5015 .cmp_pid = LIST_HEAD_INIT(sched.cmp_pid), 5016 .sort_list = LIST_HEAD_INIT(sched.sort_list), 5017 .sort_order = default_sort_order, 5018 .replay_repeat = 10, 5019 .profile_cpu = -1, 5020 .next_shortname1 = 'A', 5021 .next_shortname2 = '0', 5022 .skip_merge = 0, 5023 .show_callchain = 1, 5024 .max_stack = 5, 5025 }; 5026 const struct option sched_options[] = { 5027 OPT_STRING('i', "input", &input_name, "file", 5028 "input file name"), 5029 OPT_INCR('v', "verbose", &verbose, 5030 "be more verbose (show symbol address, etc)"), 5031 OPT_BOOLEAN('D', "dump-raw-trace", &dump_trace, 5032 "dump raw trace in ASCII"), 5033 OPT_BOOLEAN('f', "force", &sched.force, "don't complain, do it"), 5034 OPT_END() 5035 }; 5036 const struct option latency_options[] = { 5037 OPT_STRING('s', "sort", &sched.sort_order, "key[,key2...]", 5038 "sort by key(s): runtime, switch, avg, max"), 5039 OPT_INTEGER('C', "CPU", &sched.profile_cpu, 5040 "CPU to profile on"), 5041 OPT_BOOLEAN('p', "pids", &sched.skip_merge, 5042 "latency stats per pid instead of per comm"), 5043 OPT_PARENT(sched_options) 5044 }; 5045 const struct option replay_options[] = { 5046 OPT_UINTEGER('r', "repeat", &sched.replay_repeat, 5047 "repeat the workload replay N times (0: infinite)"), 5048 OPT_PARENT(sched_options) 5049 }; 5050 const struct option map_options[] = { 5051 OPT_BOOLEAN(0, "compact", &sched.map.comp, 5052 "map output in compact mode"), 5053 OPT_STRING(0, "color-pids", &sched.map.color_pids_str, "pids", 5054 "highlight given pids in map"), 5055 OPT_STRING(0, "color-cpus", &sched.map.color_cpus_str, "cpus", 5056 "highlight given CPUs in map"), 5057 OPT_STRING(0, "cpus", &sched.map.cpus_str, "cpus", 5058 "display given CPUs in map"), 5059 OPT_STRING(0, "task-name", &sched.map.task_name, "task", 5060 "map output only for the given task name(s)."), 5061 OPT_BOOLEAN(0, "fuzzy-name", &sched.map.fuzzy, 5062 "given command name can be partially matched (fuzzy matching)"), 5063 OPT_PARENT(sched_options) 5064 }; 5065 const struct option timehist_options[] = { 5066 OPT_STRING('k', "vmlinux", &symbol_conf.vmlinux_name, 5067 "file", "vmlinux pathname"), 5068 OPT_STRING(0, "kallsyms", &symbol_conf.kallsyms_name, 5069 "file", "kallsyms pathname"), 5070 OPT_BOOLEAN('g', "call-graph", &sched.show_callchain, 5071 "Display call chains if present (default on)"), 5072 OPT_UINTEGER(0, "max-stack", &sched.max_stack, 5073 "Maximum number of functions to display backtrace."), 5074 OPT_CALLBACK(0, "symfs", NULL, "directory[,layout]", SYMFS_HELP, 5075 symbol__config_symfs), 5076 OPT_BOOLEAN('s', "summary", &sched.summary_only, 5077 "Show only syscall summary with statistics"), 5078 OPT_BOOLEAN('S', "with-summary", &sched.summary, 5079 "Show all syscalls and summary with statistics"), 5080 OPT_BOOLEAN('w', "wakeups", &sched.show_wakeups, "Show wakeup events"), 5081 OPT_BOOLEAN('n', "next", &sched.show_next, "Show next task"), 5082 OPT_BOOLEAN('M', "migrations", &sched.show_migrations, "Show migration events"), 5083 OPT_BOOLEAN('V', "cpu-visual", &sched.show_cpu_visual, "Add CPU visual"), 5084 OPT_BOOLEAN('I', "idle-hist", &sched.idle_hist, "Show idle events only"), 5085 OPT_STRING(0, "time", &sched.time_str, "str", 5086 "Time span for analysis (start,stop)"), 5087 OPT_BOOLEAN(0, "state", &sched.show_state, "Show task state when sched-out"), 5088 OPT_STRING('p', "pid", &symbol_conf.pid_list_str, "pid[,pid...]", 5089 "analyze events only for given process id(s)"), 5090 OPT_STRING('t', "tid", &symbol_conf.tid_list_str, "tid[,tid...]", 5091 "analyze events only for given thread id(s)"), 5092 OPT_STRING('C', "cpu", &cpu_list, "cpu", "list of cpus to profile"), 5093 OPT_BOOLEAN(0, "show-prio", &sched.show_prio, "Show task priority"), 5094 OPT_STRING(0, "prio", &sched.prio_str, "prio", 5095 "analyze events only for given task priority(ies)"), 5096 OPT_BOOLEAN('P', "pre-migrations", &sched.pre_migrations, "Show pre-migration wait time"), 5097 OPT_PARENT(sched_options) 5098 }; 5099 const struct option stats_options[] = { 5100 OPT_STRING('i', "input", &input_name, "file", 5101 "`stats report` with input filename"), 5102 OPT_STRING('o', "output", &output_name, "file", 5103 "`stats record` with output filename"), 5104 OPT_STRING('C', "cpu", &cpu_list, "cpu", "list of cpus to profile"), 5105 OPT_BOOLEAN('v', "verbose", &verbose_field, "Show explanation for fields in the report"), 5106 OPT_END() 5107 }; 5108 5109 const char * const latency_usage[] = { 5110 "perf sched latency [<options>]", 5111 NULL 5112 }; 5113 const char * const replay_usage[] = { 5114 "perf sched replay [<options>]", 5115 NULL 5116 }; 5117 const char * const map_usage[] = { 5118 "perf sched map [<options>]", 5119 NULL 5120 }; 5121 const char * const timehist_usage[] = { 5122 "perf sched timehist [<options>]", 5123 NULL 5124 }; 5125 const char *stats_usage[] = { 5126 "perf sched stats {record|report} [<options>]", 5127 NULL 5128 }; 5129 const char *const sched_subcommands[] = { "record", "latency", "map", 5130 "replay", "script", 5131 "timehist", "stats", NULL }; 5132 const char *sched_usage[] = { 5133 NULL, 5134 NULL 5135 }; 5136 struct trace_sched_handler lat_ops = { 5137 .wakeup_event = latency_wakeup_event, 5138 .switch_event = latency_switch_event, 5139 .runtime_event = latency_runtime_event, 5140 .migrate_task_event = latency_migrate_task_event, 5141 }; 5142 struct trace_sched_handler map_ops = { 5143 .switch_event = map_switch_event, 5144 }; 5145 struct trace_sched_handler replay_ops = { 5146 .wakeup_event = replay_wakeup_event, 5147 .switch_event = replay_switch_event, 5148 .fork_event = replay_fork_event, 5149 }; 5150 struct trace_sched_handler stats_ops = {}; 5151 int ret; 5152 5153 perf_tool__init(&sched.tool, /*ordered_events=*/true); 5154 sched.tool.sample = perf_sched__process_tracepoint_sample; 5155 sched.tool.comm = perf_sched__process_comm; 5156 sched.tool.namespaces = perf_event__process_namespaces; 5157 sched.tool.lost = perf_event__process_lost; 5158 sched.tool.fork = perf_sched__process_fork_event; 5159 5160 argc = parse_options_subcommand(argc, argv, sched_options, sched_subcommands, 5161 sched_usage, PARSE_OPT_STOP_AT_NON_OPTION); 5162 if (!argc) 5163 usage_with_options(sched_usage, sched_options); 5164 5165 thread__set_priv_destructor(free); 5166 5167 /* 5168 * Aliased to 'perf script' for now: 5169 */ 5170 if (!strcmp(argv[0], "script")) { 5171 ret = cmd_script(argc, argv); 5172 } else if (strlen(argv[0]) > 2 && strstarts("record", argv[0])) { 5173 ret = __cmd_record(argc, argv); 5174 } else if (strlen(argv[0]) > 2 && strstarts("latency", argv[0])) { 5175 sched.tp_handler = &lat_ops; 5176 if (argc > 1) { 5177 argc = parse_options(argc, argv, latency_options, latency_usage, 0); 5178 if (argc) 5179 usage_with_options(latency_usage, latency_options); 5180 } 5181 setup_sorting(&sched, latency_options, latency_usage); 5182 ret = perf_sched__lat(&sched); 5183 } else if (!strcmp(argv[0], "map")) { 5184 if (argc) { 5185 argc = parse_options(argc, argv, map_options, map_usage, 0); 5186 if (argc) 5187 usage_with_options(map_usage, map_options); 5188 5189 if (sched.map.task_name) { 5190 sched.map.task_names = strlist__new(sched.map.task_name, NULL); 5191 if (sched.map.task_names == NULL) { 5192 fprintf(stderr, "Failed to parse task names\n"); 5193 ret = -1; 5194 goto out; 5195 } 5196 } 5197 } 5198 sched.tp_handler = &map_ops; 5199 setup_sorting(&sched, latency_options, latency_usage); 5200 ret = perf_sched__map(&sched); 5201 } else if (strlen(argv[0]) > 2 && strstarts("replay", argv[0])) { 5202 sched.tp_handler = &replay_ops; 5203 if (argc) { 5204 argc = parse_options(argc, argv, replay_options, replay_usage, 0); 5205 if (argc) 5206 usage_with_options(replay_usage, replay_options); 5207 } 5208 ret = perf_sched__replay(&sched); 5209 } else if (!strcmp(argv[0], "timehist")) { 5210 if (argc) { 5211 argc = parse_options(argc, argv, timehist_options, 5212 timehist_usage, 0); 5213 if (argc) 5214 usage_with_options(timehist_usage, timehist_options); 5215 } 5216 if ((sched.show_wakeups || sched.show_next) && 5217 sched.summary_only) { 5218 pr_err(" Error: -s and -[n|w] are mutually exclusive.\n"); 5219 parse_options_usage(timehist_usage, timehist_options, "s", true); 5220 if (sched.show_wakeups) 5221 parse_options_usage(NULL, timehist_options, "w", true); 5222 if (sched.show_next) 5223 parse_options_usage(NULL, timehist_options, "n", true); 5224 ret = -EINVAL; 5225 goto out; 5226 } 5227 ret = symbol__validate_sym_arguments(); 5228 if (!ret) 5229 ret = perf_sched__timehist(&sched); 5230 } else if (!strcmp(argv[0], "stats")) { 5231 const char *const stats_subcommands[] = {"record", "report", NULL}; 5232 5233 sched.tp_handler = &stats_ops; 5234 argc = parse_options_subcommand(argc, argv, stats_options, 5235 stats_subcommands, 5236 stats_usage, 5237 PARSE_OPT_STOP_AT_NON_OPTION); 5238 5239 if (argv[0] && !strcmp(argv[0], "record")) { 5240 if (argc) 5241 argc = parse_options(argc, argv, stats_options, 5242 stats_usage, 0); 5243 return perf_sched__schedstat_record(&sched, argc, argv); 5244 } else if (argv[0] && !strcmp(argv[0], "report")) { 5245 if (argc) 5246 argc = parse_options(argc, argv, stats_options, 5247 stats_usage, 0); 5248 return perf_sched__schedstat_report(&sched); 5249 } else if (argv[0] && !strcmp(argv[0], "diff")) { 5250 if (argc) 5251 argc = parse_options(argc, argv, stats_options, 5252 stats_usage, 0); 5253 return perf_sched__schedstat_diff(&sched, argc, argv); 5254 } 5255 return perf_sched__schedstat_live(&sched, argc, argv); 5256 } else { 5257 usage_with_options(sched_usage, sched_options); 5258 } 5259 5260 out: 5261 /* free usage string allocated by parse_options_subcommand */ 5262 free((void *)sched_usage[0]); 5263 5264 return ret; 5265 } 5266