builtin-sched.c 87.3 KB
Newer Older
1
// SPDX-License-Identifier: GPL-2.0
I
Ingo Molnar 已提交
2
#include "builtin.h"
3
#include "perf.h"
I
Ingo Molnar 已提交
4 5

#include "util/util.h"
6
#include "util/evlist.h"
I
Ingo Molnar 已提交
7
#include "util/cache.h"
8
#include "util/evsel.h"
I
Ingo Molnar 已提交
9 10 11
#include "util/symbol.h"
#include "util/thread.h"
#include "util/header.h"
12
#include "util/session.h"
13
#include "util/tool.h"
14
#include "util/cloexec.h"
J
Jiri Olsa 已提交
15
#include "util/thread_map.h"
16
#include "util/color.h"
17
#include "util/stat.h"
18
#include "util/callchain.h"
19
#include "util/time-utils.h"
I
Ingo Molnar 已提交
20

21
#include <subcmd/parse-options.h>
22
#include "util/trace-event.h"
I
Ingo Molnar 已提交
23 24 25

#include "util/debug.h"

26
#include <linux/kernel.h>
27
#include <linux/log2.h>
28
#include <sys/prctl.h>
29
#include <sys/resource.h>
30
#include <inttypes.h>
I
Ingo Molnar 已提交
31

32
#include <errno.h>
33 34 35
#include <semaphore.h>
#include <pthread.h>
#include <math.h>
36
#include <api/fs/fs.h>
37
#include <linux/time64.h>
38

39 40
#include "sane_ctype.h"

41 42 43 44
#define PR_SET_NAME		15               /* Set process name */
#define MAX_CPUS		4096
#define COMM_LEN		20
#define SYM_LEN			129
45
#define MAX_PID			1024000
I
Ingo Molnar 已提交
46

47
struct sched_atom;
I
Ingo Molnar 已提交
48

49 50 51 52
struct task_desc {
	unsigned long		nr;
	unsigned long		pid;
	char			comm[COMM_LEN];
I
Ingo Molnar 已提交
53

54 55
	unsigned long		nr_events;
	unsigned long		curr_event;
56
	struct sched_atom	**atoms;
57 58 59

	pthread_t		thread;
	sem_t			sleep_sem;
I
Ingo Molnar 已提交
60

61 62 63 64 65 66 67 68 69 70
	sem_t			ready_for_work;
	sem_t			work_done_sem;

	u64			cpu_usage;
};

enum sched_event_type {
	SCHED_EVENT_RUN,
	SCHED_EVENT_SLEEP,
	SCHED_EVENT_WAKEUP,
71
	SCHED_EVENT_MIGRATION,
72 73
};

74
struct sched_atom {
75
	enum sched_event_type	type;
76
	int			specific_wait;
77 78 79 80 81 82 83
	u64			timestamp;
	u64			duration;
	unsigned long		nr;
	sem_t			*wait_sem;
	struct task_desc	*wakee;
};

84
#define TASK_STATE_TO_CHAR_STR "RSDTtZXxKWP"
85

86 87 88 89 90 91 92 93 94 95 96 97 98 99 100 101
/* task state bitmask, copied from include/linux/sched.h */
#define TASK_RUNNING		0
#define TASK_INTERRUPTIBLE	1
#define TASK_UNINTERRUPTIBLE	2
#define __TASK_STOPPED		4
#define __TASK_TRACED		8
/* in tsk->exit_state */
#define EXIT_DEAD		16
#define EXIT_ZOMBIE		32
#define EXIT_TRACE		(EXIT_ZOMBIE | EXIT_DEAD)
/* in tsk->state again */
#define TASK_DEAD		64
#define TASK_WAKEKILL		128
#define TASK_WAKING		256
#define TASK_PARKED		512

102 103 104 105 106 107 108 109 110 111
enum thread_state {
	THREAD_SLEEPING = 0,
	THREAD_WAIT_CPU,
	THREAD_SCHED_IN,
	THREAD_IGNORE
};

struct work_atom {
	struct list_head	list;
	enum thread_state	state;
112
	u64			sched_out_time;
113 114 115 116 117
	u64			wake_up_time;
	u64			sched_in_time;
	u64			runtime;
};

118 119
struct work_atoms {
	struct list_head	work_list;
120 121 122
	struct thread		*thread;
	struct rb_node		node;
	u64			max_lat;
123
	u64			max_lat_at;
124 125 126
	u64			total_lat;
	u64			nb_atoms;
	u64			total_runtime;
127
	int			num_merged;
128 129
};

130
typedef int (*sort_fn_t)(struct work_atoms *, struct work_atoms *);
131

132
struct perf_sched;
133

134 135 136
struct trace_sched_handler {
	int (*switch_event)(struct perf_sched *sched, struct perf_evsel *evsel,
			    struct perf_sample *sample, struct machine *machine);
137

138 139
	int (*runtime_event)(struct perf_sched *sched, struct perf_evsel *evsel,
			     struct perf_sample *sample, struct machine *machine);
140

141 142
	int (*wakeup_event)(struct perf_sched *sched, struct perf_evsel *evsel,
			    struct perf_sample *sample, struct machine *machine);
143

144 145 146
	/* PERF_RECORD_FORK event, not sched_process_fork tracepoint */
	int (*fork_event)(struct perf_sched *sched, union perf_event *event,
			  struct machine *machine);
147 148

	int (*migrate_task_event)(struct perf_sched *sched,
149 150 151
				  struct perf_evsel *evsel,
				  struct perf_sample *sample,
				  struct machine *machine);
152 153
};

J
Jiri Olsa 已提交
154
#define COLOR_PIDS PERF_COLOR_BLUE
J
Jiri Olsa 已提交
155
#define COLOR_CPUS PERF_COLOR_BG_RED
J
Jiri Olsa 已提交
156

157 158 159 160
struct perf_sched_map {
	DECLARE_BITMAP(comp_cpus_mask, MAX_CPUS);
	int			*comp_cpus;
	bool			 comp;
J
Jiri Olsa 已提交
161 162
	struct thread_map	*color_pids;
	const char		*color_pids_str;
J
Jiri Olsa 已提交
163 164
	struct cpu_map		*color_cpus;
	const char		*color_cpus_str;
165 166
	struct cpu_map		*cpus;
	const char		*cpus_str;
167 168
};

169 170 171 172
struct perf_sched {
	struct perf_tool tool;
	const char	 *sort_order;
	unsigned long	 nr_tasks;
173
	struct task_desc **pid_to_task;
174 175 176 177 178 179 180 181 182 183 184 185 186 187 188 189 190 191 192 193 194 195 196 197 198 199 200 201 202 203 204 205 206 207 208 209 210 211 212 213 214 215
	struct task_desc **tasks;
	const struct trace_sched_handler *tp_handler;
	pthread_mutex_t	 start_work_mutex;
	pthread_mutex_t	 work_done_wait_mutex;
	int		 profile_cpu;
/*
 * Track the current task - that way we can know whether there's any
 * weird events, such as a task being switched away that is not current.
 */
	int		 max_cpu;
	u32		 curr_pid[MAX_CPUS];
	struct thread	 *curr_thread[MAX_CPUS];
	char		 next_shortname1;
	char		 next_shortname2;
	unsigned int	 replay_repeat;
	unsigned long	 nr_run_events;
	unsigned long	 nr_sleep_events;
	unsigned long	 nr_wakeup_events;
	unsigned long	 nr_sleep_corrections;
	unsigned long	 nr_run_events_optimized;
	unsigned long	 targetless_wakeups;
	unsigned long	 multitarget_wakeups;
	unsigned long	 nr_runs;
	unsigned long	 nr_timestamps;
	unsigned long	 nr_unordered_timestamps;
	unsigned long	 nr_context_switch_bugs;
	unsigned long	 nr_events;
	unsigned long	 nr_lost_chunks;
	unsigned long	 nr_lost_events;
	u64		 run_measurement_overhead;
	u64		 sleep_measurement_overhead;
	u64		 start_time;
	u64		 cpu_usage;
	u64		 runavg_cpu_usage;
	u64		 parent_cpu_usage;
	u64		 runavg_parent_cpu_usage;
	u64		 sum_runtime;
	u64		 sum_fluct;
	u64		 run_avg;
	u64		 all_runtime;
	u64		 all_count;
	u64		 cpu_last_switched[MAX_CPUS];
216
	struct rb_root	 atom_root, sorted_atom_root, merged_atom_root;
217
	struct list_head sort_list, cmp_pid;
218
	bool force;
219
	bool skip_merge;
220
	struct perf_sched_map map;
221 222 223 224

	/* options for timehist command */
	bool		summary;
	bool		summary_only;
225
	bool		idle_hist;
226 227
	bool		show_callchain;
	unsigned int	max_stack;
228
	bool		show_cpu_visual;
229
	bool		show_wakeups;
230
	bool		show_next;
231
	bool		show_migrations;
232
	bool		show_state;
233
	u64		skipped_samples;
234 235
	const char	*time_str;
	struct perf_time_interval ptime;
236
	struct perf_time_interval hist_time;
237
};
238

239 240 241 242
/* per thread run time data */
struct thread_runtime {
	u64 last_time;      /* time of previous sched in/out event */
	u64 dt_run;         /* run time */
243 244 245
	u64 dt_sleep;       /* time between CPU access by sleep (off cpu) */
	u64 dt_iowait;      /* time between CPU access by iowait (off cpu) */
	u64 dt_preempt;     /* time between CPU access by preempt (off cpu) */
246 247 248 249 250
	u64 dt_delay;       /* time between wakeup and sched-in */
	u64 ready_to_run;   /* time of wakeup */

	struct stats run_stats;
	u64 total_run_time;
251 252 253 254
	u64 total_sleep_time;
	u64 total_iowait_time;
	u64 total_preempt_time;
	u64 total_delay_time;
255

256
	int last_state;
257 258

	char shortname[3];
259 260
	bool comm_changed;

261
	u64 migrations;
262 263 264 265 266 267 268 269
};

/* per event run time data */
struct evsel_runtime {
	u64 *last_time; /* time this event was last seen per cpu */
	u32 ncpu;       /* highest cpu slot allocated */
};

270 271 272 273 274 275 276 277 278
/* per cpu idle time data */
struct idle_thread_runtime {
	struct thread_runtime	tr;
	struct thread		*last_thread;
	struct rb_root		sorted_root;
	struct callchain_root	callchain;
	struct callchain_cursor	cursor;
};

279 280 281 282 283
/* track idle times per cpu */
static struct thread **idle_threads;
static int idle_max_cpu;
static char idle_comm[] = "<idle>";

284
static u64 get_nsecs(void)
I
Ingo Molnar 已提交
285 286 287 288 289
{
	struct timespec ts;

	clock_gettime(CLOCK_MONOTONIC, &ts);

290
	return ts.tv_sec * NSEC_PER_SEC + ts.tv_nsec;
I
Ingo Molnar 已提交
291 292
}

293
static void burn_nsecs(struct perf_sched *sched, u64 nsecs)
I
Ingo Molnar 已提交
294
{
295
	u64 T0 = get_nsecs(), T1;
I
Ingo Molnar 已提交
296 297 298

	do {
		T1 = get_nsecs();
299
	} while (T1 + sched->run_measurement_overhead < T0 + nsecs);
I
Ingo Molnar 已提交
300 301
}

302
static void sleep_nsecs(u64 nsecs)
I
Ingo Molnar 已提交
303 304 305 306 307 308 309 310 311
{
	struct timespec ts;

	ts.tv_nsec = nsecs % 999999999;
	ts.tv_sec = nsecs / 999999999;

	nanosleep(&ts, NULL);
}

312
static void calibrate_run_measurement_overhead(struct perf_sched *sched)
I
Ingo Molnar 已提交
313
{
314
	u64 T0, T1, delta, min_delta = NSEC_PER_SEC;
I
Ingo Molnar 已提交
315 316 317 318
	int i;

	for (i = 0; i < 10; i++) {
		T0 = get_nsecs();
319
		burn_nsecs(sched, 0);
I
Ingo Molnar 已提交
320 321 322 323
		T1 = get_nsecs();
		delta = T1-T0;
		min_delta = min(min_delta, delta);
	}
324
	sched->run_measurement_overhead = min_delta;
I
Ingo Molnar 已提交
325

326
	printf("run measurement overhead: %" PRIu64 " nsecs\n", min_delta);
I
Ingo Molnar 已提交
327 328
}

329
static void calibrate_sleep_measurement_overhead(struct perf_sched *sched)
I
Ingo Molnar 已提交
330
{
331
	u64 T0, T1, delta, min_delta = NSEC_PER_SEC;
I
Ingo Molnar 已提交
332 333 334 335 336 337 338 339 340 341
	int i;

	for (i = 0; i < 10; i++) {
		T0 = get_nsecs();
		sleep_nsecs(10000);
		T1 = get_nsecs();
		delta = T1-T0;
		min_delta = min(min_delta, delta);
	}
	min_delta -= 10000;
342
	sched->sleep_measurement_overhead = min_delta;
I
Ingo Molnar 已提交
343

344
	printf("sleep measurement overhead: %" PRIu64 " nsecs\n", min_delta);
I
Ingo Molnar 已提交
345 346
}

347
static struct sched_atom *
348
get_new_event(struct task_desc *task, u64 timestamp)
I
Ingo Molnar 已提交
349
{
350
	struct sched_atom *event = zalloc(sizeof(*event));
I
Ingo Molnar 已提交
351 352 353 354 355 356 357
	unsigned long idx = task->nr_events;
	size_t size;

	event->timestamp = timestamp;
	event->nr = idx;

	task->nr_events++;
358 359 360
	size = sizeof(struct sched_atom *) * task->nr_events;
	task->atoms = realloc(task->atoms, size);
	BUG_ON(!task->atoms);
I
Ingo Molnar 已提交
361

362
	task->atoms[idx] = event;
I
Ingo Molnar 已提交
363 364 365 366

	return event;
}

367
static struct sched_atom *last_event(struct task_desc *task)
I
Ingo Molnar 已提交
368 369 370 371
{
	if (!task->nr_events)
		return NULL;

372
	return task->atoms[task->nr_events - 1];
I
Ingo Molnar 已提交
373 374
}

375 376
static void add_sched_event_run(struct perf_sched *sched, struct task_desc *task,
				u64 timestamp, u64 duration)
I
Ingo Molnar 已提交
377
{
378
	struct sched_atom *event, *curr_event = last_event(task);
I
Ingo Molnar 已提交
379 380

	/*
381 382 383
	 * optimize an existing RUN event by merging this one
	 * to it:
	 */
I
Ingo Molnar 已提交
384
	if (curr_event && curr_event->type == SCHED_EVENT_RUN) {
385
		sched->nr_run_events_optimized++;
I
Ingo Molnar 已提交
386 387 388 389 390 391 392 393 394
		curr_event->duration += duration;
		return;
	}

	event = get_new_event(task, timestamp);

	event->type = SCHED_EVENT_RUN;
	event->duration = duration;

395
	sched->nr_run_events++;
I
Ingo Molnar 已提交
396 397
}

398 399
static void add_sched_event_wakeup(struct perf_sched *sched, struct task_desc *task,
				   u64 timestamp, struct task_desc *wakee)
I
Ingo Molnar 已提交
400
{
401
	struct sched_atom *event, *wakee_event;
I
Ingo Molnar 已提交
402 403 404 405 406 407 408

	event = get_new_event(task, timestamp);
	event->type = SCHED_EVENT_WAKEUP;
	event->wakee = wakee;

	wakee_event = last_event(wakee);
	if (!wakee_event || wakee_event->type != SCHED_EVENT_SLEEP) {
409
		sched->targetless_wakeups++;
I
Ingo Molnar 已提交
410 411 412
		return;
	}
	if (wakee_event->wait_sem) {
413
		sched->multitarget_wakeups++;
I
Ingo Molnar 已提交
414 415 416
		return;
	}

417
	wakee_event->wait_sem = zalloc(sizeof(*wakee_event->wait_sem));
I
Ingo Molnar 已提交
418 419 420 421
	sem_init(wakee_event->wait_sem, 0, 0);
	wakee_event->specific_wait = 1;
	event->wait_sem = wakee_event->wait_sem;

422
	sched->nr_wakeup_events++;
I
Ingo Molnar 已提交
423 424
}

425 426
static void add_sched_event_sleep(struct perf_sched *sched, struct task_desc *task,
				  u64 timestamp, u64 task_state __maybe_unused)
I
Ingo Molnar 已提交
427
{
428
	struct sched_atom *event = get_new_event(task, timestamp);
I
Ingo Molnar 已提交
429 430 431

	event->type = SCHED_EVENT_SLEEP;

432
	sched->nr_sleep_events++;
I
Ingo Molnar 已提交
433 434
}

435 436
static struct task_desc *register_pid(struct perf_sched *sched,
				      unsigned long pid, const char *comm)
I
Ingo Molnar 已提交
437 438
{
	struct task_desc *task;
439
	static int pid_max;
I
Ingo Molnar 已提交
440

441 442 443 444 445
	if (sched->pid_to_task == NULL) {
		if (sysctl__read_int("kernel/pid_max", &pid_max) < 0)
			pid_max = MAX_PID;
		BUG_ON((sched->pid_to_task = calloc(pid_max, sizeof(struct task_desc *))) == NULL);
	}
446 447 448 449 450 451
	if (pid >= (unsigned long)pid_max) {
		BUG_ON((sched->pid_to_task = realloc(sched->pid_to_task, (pid + 1) *
			sizeof(struct task_desc *))) == NULL);
		while (pid >= (unsigned long)pid_max)
			sched->pid_to_task[pid_max++] = NULL;
	}
I
Ingo Molnar 已提交
452

453
	task = sched->pid_to_task[pid];
I
Ingo Molnar 已提交
454 455 456 457

	if (task)
		return task;

458
	task = zalloc(sizeof(*task));
I
Ingo Molnar 已提交
459
	task->pid = pid;
460
	task->nr = sched->nr_tasks;
I
Ingo Molnar 已提交
461 462 463 464 465
	strcpy(task->comm, comm);
	/*
	 * every task starts in sleeping state - this gets ignored
	 * if there's no wakeup pointing to this sleep state:
	 */
466
	add_sched_event_sleep(sched, task, 0, 0);
I
Ingo Molnar 已提交
467

468 469
	sched->pid_to_task[pid] = task;
	sched->nr_tasks++;
470
	sched->tasks = realloc(sched->tasks, sched->nr_tasks * sizeof(struct task_desc *));
471 472
	BUG_ON(!sched->tasks);
	sched->tasks[task->nr] = task;
I
Ingo Molnar 已提交
473

474
	if (verbose > 0)
475
		printf("registered task #%ld, PID %ld (%s)\n", sched->nr_tasks, pid, comm);
I
Ingo Molnar 已提交
476 477 478 479 480

	return task;
}


481
static void print_task_traces(struct perf_sched *sched)
I
Ingo Molnar 已提交
482 483 484 485
{
	struct task_desc *task;
	unsigned long i;

486 487
	for (i = 0; i < sched->nr_tasks; i++) {
		task = sched->tasks[i];
I
Ingo Molnar 已提交
488
		printf("task %6ld (%20s:%10ld), nr_events: %ld\n",
I
Ingo Molnar 已提交
489 490 491 492
			task->nr, task->comm, task->pid, task->nr_events);
	}
}

493
static void add_cross_task_wakeups(struct perf_sched *sched)
I
Ingo Molnar 已提交
494 495 496 497
{
	struct task_desc *task1, *task2;
	unsigned long i, j;

498 499
	for (i = 0; i < sched->nr_tasks; i++) {
		task1 = sched->tasks[i];
I
Ingo Molnar 已提交
500
		j = i + 1;
501
		if (j == sched->nr_tasks)
I
Ingo Molnar 已提交
502
			j = 0;
503 504
		task2 = sched->tasks[j];
		add_sched_event_wakeup(sched, task1, 0, task2);
I
Ingo Molnar 已提交
505 506 507
	}
}

508 509
static void perf_sched__process_event(struct perf_sched *sched,
				      struct sched_atom *atom)
I
Ingo Molnar 已提交
510 511 512
{
	int ret = 0;

513
	switch (atom->type) {
I
Ingo Molnar 已提交
514
		case SCHED_EVENT_RUN:
515
			burn_nsecs(sched, atom->duration);
I
Ingo Molnar 已提交
516 517
			break;
		case SCHED_EVENT_SLEEP:
518 519
			if (atom->wait_sem)
				ret = sem_wait(atom->wait_sem);
I
Ingo Molnar 已提交
520 521 522
			BUG_ON(ret);
			break;
		case SCHED_EVENT_WAKEUP:
523 524
			if (atom->wait_sem)
				ret = sem_post(atom->wait_sem);
I
Ingo Molnar 已提交
525 526
			BUG_ON(ret);
			break;
527 528
		case SCHED_EVENT_MIGRATION:
			break;
I
Ingo Molnar 已提交
529 530 531 532 533
		default:
			BUG_ON(1);
	}
}

534
static u64 get_cpu_usage_nsec_parent(void)
I
Ingo Molnar 已提交
535 536
{
	struct rusage ru;
537
	u64 sum;
I
Ingo Molnar 已提交
538 539 540 541 542
	int err;

	err = getrusage(RUSAGE_SELF, &ru);
	BUG_ON(err);

543 544
	sum =  ru.ru_utime.tv_sec * NSEC_PER_SEC + ru.ru_utime.tv_usec * NSEC_PER_USEC;
	sum += ru.ru_stime.tv_sec * NSEC_PER_SEC + ru.ru_stime.tv_usec * NSEC_PER_USEC;
I
Ingo Molnar 已提交
545 546 547 548

	return sum;
}

549
static int self_open_counters(struct perf_sched *sched, unsigned long cur_task)
I
Ingo Molnar 已提交
550
{
551
	struct perf_event_attr attr;
552
	char sbuf[STRERR_BUFSIZE], info[STRERR_BUFSIZE];
553
	int fd;
554 555
	struct rlimit limit;
	bool need_privilege = false;
I
Ingo Molnar 已提交
556

557
	memset(&attr, 0, sizeof(attr));
I
Ingo Molnar 已提交
558

559 560
	attr.type = PERF_TYPE_SOFTWARE;
	attr.config = PERF_COUNT_SW_TASK_CLOCK;
I
Ingo Molnar 已提交
561

562
force_again:
563 564
	fd = sys_perf_event_open(&attr, 0, -1, -1,
				 perf_event_open_cloexec_flag());
565

566
	if (fd < 0) {
567 568 569 570 571 572 573 574 575 576 577 578 579 580 581 582
		if (errno == EMFILE) {
			if (sched->force) {
				BUG_ON(getrlimit(RLIMIT_NOFILE, &limit) == -1);
				limit.rlim_cur += sched->nr_tasks - cur_task;
				if (limit.rlim_cur > limit.rlim_max) {
					limit.rlim_max = limit.rlim_cur;
					need_privilege = true;
				}
				if (setrlimit(RLIMIT_NOFILE, &limit) == -1) {
					if (need_privilege && errno == EPERM)
						strcpy(info, "Need privilege\n");
				} else
					goto force_again;
			} else
				strcpy(info, "Have a try with -f option\n");
		}
583
		pr_err("Error: sys_perf_event_open() syscall returned "
584
		       "with %d (%s)\n%s", fd,
585
		       str_error_r(errno, sbuf, sizeof(sbuf)), info);
586 587
		exit(EXIT_FAILURE);
	}
588 589 590 591 592 593 594 595 596 597 598 599
	return fd;
}

static u64 get_cpu_usage_nsec_self(int fd)
{
	u64 runtime;
	int ret;

	ret = read(fd, &runtime, sizeof(runtime));
	BUG_ON(ret != sizeof(runtime));

	return runtime;
I
Ingo Molnar 已提交
600 601
}

602 603 604
struct sched_thread_parms {
	struct task_desc  *task;
	struct perf_sched *sched;
605
	int fd;
606 607
};

I
Ingo Molnar 已提交
608 609
static void *thread_func(void *ctx)
{
610 611 612
	struct sched_thread_parms *parms = ctx;
	struct task_desc *this_task = parms->task;
	struct perf_sched *sched = parms->sched;
613
	u64 cpu_usage_0, cpu_usage_1;
I
Ingo Molnar 已提交
614 615
	unsigned long i, ret;
	char comm2[22];
616
	int fd = parms->fd;
I
Ingo Molnar 已提交
617

618
	zfree(&parms);
619

I
Ingo Molnar 已提交
620 621
	sprintf(comm2, ":%s", this_task->comm);
	prctl(PR_SET_NAME, comm2);
622 623
	if (fd < 0)
		return NULL;
I
Ingo Molnar 已提交
624 625 626
again:
	ret = sem_post(&this_task->ready_for_work);
	BUG_ON(ret);
627
	ret = pthread_mutex_lock(&sched->start_work_mutex);
I
Ingo Molnar 已提交
628
	BUG_ON(ret);
629
	ret = pthread_mutex_unlock(&sched->start_work_mutex);
I
Ingo Molnar 已提交
630 631
	BUG_ON(ret);

632
	cpu_usage_0 = get_cpu_usage_nsec_self(fd);
I
Ingo Molnar 已提交
633 634 635

	for (i = 0; i < this_task->nr_events; i++) {
		this_task->curr_event = i;
636
		perf_sched__process_event(sched, this_task->atoms[i]);
I
Ingo Molnar 已提交
637 638
	}

639
	cpu_usage_1 = get_cpu_usage_nsec_self(fd);
I
Ingo Molnar 已提交
640 641 642 643
	this_task->cpu_usage = cpu_usage_1 - cpu_usage_0;
	ret = sem_post(&this_task->work_done_sem);
	BUG_ON(ret);

644
	ret = pthread_mutex_lock(&sched->work_done_wait_mutex);
I
Ingo Molnar 已提交
645
	BUG_ON(ret);
646
	ret = pthread_mutex_unlock(&sched->work_done_wait_mutex);
I
Ingo Molnar 已提交
647 648 649 650 651
	BUG_ON(ret);

	goto again;
}

652
static void create_tasks(struct perf_sched *sched)
I
Ingo Molnar 已提交
653 654 655 656 657 658 659 660
{
	struct task_desc *task;
	pthread_attr_t attr;
	unsigned long i;
	int err;

	err = pthread_attr_init(&attr);
	BUG_ON(err);
661 662
	err = pthread_attr_setstacksize(&attr,
			(size_t) max(16 * 1024, PTHREAD_STACK_MIN));
I
Ingo Molnar 已提交
663
	BUG_ON(err);
664
	err = pthread_mutex_lock(&sched->start_work_mutex);
I
Ingo Molnar 已提交
665
	BUG_ON(err);
666
	err = pthread_mutex_lock(&sched->work_done_wait_mutex);
I
Ingo Molnar 已提交
667
	BUG_ON(err);
668 669 670 671 672
	for (i = 0; i < sched->nr_tasks; i++) {
		struct sched_thread_parms *parms = malloc(sizeof(*parms));
		BUG_ON(parms == NULL);
		parms->task = task = sched->tasks[i];
		parms->sched = sched;
673
		parms->fd = self_open_counters(sched, i);
I
Ingo Molnar 已提交
674 675 676 677
		sem_init(&task->sleep_sem, 0, 0);
		sem_init(&task->ready_for_work, 0, 0);
		sem_init(&task->work_done_sem, 0, 0);
		task->curr_event = 0;
678
		err = pthread_create(&task->thread, &attr, thread_func, parms);
I
Ingo Molnar 已提交
679 680 681 682
		BUG_ON(err);
	}
}

683
static void wait_for_tasks(struct perf_sched *sched)
I
Ingo Molnar 已提交
684
{
685
	u64 cpu_usage_0, cpu_usage_1;
I
Ingo Molnar 已提交
686 687 688
	struct task_desc *task;
	unsigned long i, ret;

689 690 691
	sched->start_time = get_nsecs();
	sched->cpu_usage = 0;
	pthread_mutex_unlock(&sched->work_done_wait_mutex);
I
Ingo Molnar 已提交
692

693 694
	for (i = 0; i < sched->nr_tasks; i++) {
		task = sched->tasks[i];
I
Ingo Molnar 已提交
695 696 697 698
		ret = sem_wait(&task->ready_for_work);
		BUG_ON(ret);
		sem_init(&task->ready_for_work, 0, 0);
	}
699
	ret = pthread_mutex_lock(&sched->work_done_wait_mutex);
I
Ingo Molnar 已提交
700 701 702 703
	BUG_ON(ret);

	cpu_usage_0 = get_cpu_usage_nsec_parent();

704
	pthread_mutex_unlock(&sched->start_work_mutex);
I
Ingo Molnar 已提交
705

706 707
	for (i = 0; i < sched->nr_tasks; i++) {
		task = sched->tasks[i];
I
Ingo Molnar 已提交
708 709 710
		ret = sem_wait(&task->work_done_sem);
		BUG_ON(ret);
		sem_init(&task->work_done_sem, 0, 0);
711
		sched->cpu_usage += task->cpu_usage;
I
Ingo Molnar 已提交
712 713 714 715
		task->cpu_usage = 0;
	}

	cpu_usage_1 = get_cpu_usage_nsec_parent();
716 717
	if (!sched->runavg_cpu_usage)
		sched->runavg_cpu_usage = sched->cpu_usage;
718
	sched->runavg_cpu_usage = (sched->runavg_cpu_usage * (sched->replay_repeat - 1) + sched->cpu_usage) / sched->replay_repeat;
I
Ingo Molnar 已提交
719

720 721 722
	sched->parent_cpu_usage = cpu_usage_1 - cpu_usage_0;
	if (!sched->runavg_parent_cpu_usage)
		sched->runavg_parent_cpu_usage = sched->parent_cpu_usage;
723 724
	sched->runavg_parent_cpu_usage = (sched->runavg_parent_cpu_usage * (sched->replay_repeat - 1) +
					 sched->parent_cpu_usage)/sched->replay_repeat;
I
Ingo Molnar 已提交
725

726
	ret = pthread_mutex_lock(&sched->start_work_mutex);
I
Ingo Molnar 已提交
727 728
	BUG_ON(ret);

729 730
	for (i = 0; i < sched->nr_tasks; i++) {
		task = sched->tasks[i];
I
Ingo Molnar 已提交
731 732 733 734 735
		sem_init(&task->sleep_sem, 0, 0);
		task->curr_event = 0;
	}
}

736
static void run_one_test(struct perf_sched *sched)
I
Ingo Molnar 已提交
737
{
K
Kyle McMartin 已提交
738
	u64 T0, T1, delta, avg_delta, fluct;
I
Ingo Molnar 已提交
739 740

	T0 = get_nsecs();
741
	wait_for_tasks(sched);
I
Ingo Molnar 已提交
742 743 744
	T1 = get_nsecs();

	delta = T1 - T0;
745 746
	sched->sum_runtime += delta;
	sched->nr_runs++;
I
Ingo Molnar 已提交
747

748
	avg_delta = sched->sum_runtime / sched->nr_runs;
I
Ingo Molnar 已提交
749 750 751 752
	if (delta < avg_delta)
		fluct = avg_delta - delta;
	else
		fluct = delta - avg_delta;
753 754 755
	sched->sum_fluct += fluct;
	if (!sched->run_avg)
		sched->run_avg = delta;
756
	sched->run_avg = (sched->run_avg * (sched->replay_repeat - 1) + delta) / sched->replay_repeat;
I
Ingo Molnar 已提交
757

758
	printf("#%-3ld: %0.3f, ", sched->nr_runs, (double)delta / NSEC_PER_MSEC);
I
Ingo Molnar 已提交
759

760
	printf("ravg: %0.2f, ", (double)sched->run_avg / NSEC_PER_MSEC);
I
Ingo Molnar 已提交
761

I
Ingo Molnar 已提交
762
	printf("cpu: %0.2f / %0.2f",
763
		(double)sched->cpu_usage / NSEC_PER_MSEC, (double)sched->runavg_cpu_usage / NSEC_PER_MSEC);
I
Ingo Molnar 已提交
764 765 766

#if 0
	/*
767
	 * rusage statistics done by the parent, these are less
768
	 * accurate than the sched->sum_exec_runtime based statistics:
769
	 */
I
Ingo Molnar 已提交
770
	printf(" [%0.2f / %0.2f]",
771 772
		(double)sched->parent_cpu_usage / NSEC_PER_MSEC,
		(double)sched->runavg_parent_cpu_usage / NSEC_PER_MSEC);
I
Ingo Molnar 已提交
773 774
#endif

I
Ingo Molnar 已提交
775
	printf("\n");
I
Ingo Molnar 已提交
776

777 778 779
	if (sched->nr_sleep_corrections)
		printf(" (%ld sleep corrections)\n", sched->nr_sleep_corrections);
	sched->nr_sleep_corrections = 0;
I
Ingo Molnar 已提交
780 781
}

782
static void test_calibrations(struct perf_sched *sched)
I
Ingo Molnar 已提交
783
{
784
	u64 T0, T1;
I
Ingo Molnar 已提交
785 786

	T0 = get_nsecs();
787
	burn_nsecs(sched, NSEC_PER_MSEC);
I
Ingo Molnar 已提交
788 789
	T1 = get_nsecs();

790
	printf("the run test took %" PRIu64 " nsecs\n", T1 - T0);
I
Ingo Molnar 已提交
791 792

	T0 = get_nsecs();
793
	sleep_nsecs(NSEC_PER_MSEC);
I
Ingo Molnar 已提交
794 795
	T1 = get_nsecs();

796
	printf("the sleep test took %" PRIu64 " nsecs\n", T1 - T0);
I
Ingo Molnar 已提交
797 798
}

799
static int
800
replay_wakeup_event(struct perf_sched *sched,
801 802
		    struct perf_evsel *evsel, struct perf_sample *sample,
		    struct machine *machine __maybe_unused)
803
{
804 805
	const char *comm = perf_evsel__strval(evsel, sample, "comm");
	const u32 pid	 = perf_evsel__intval(evsel, sample, "pid");
806
	struct task_desc *waker, *wakee;
807

808
	if (verbose > 0) {
809
		printf("sched_wakeup event %p\n", evsel);
810

811
		printf(" ... pid %d woke up %s/%d\n", sample->tid, comm, pid);
I
Ingo Molnar 已提交
812
	}
813

814
	waker = register_pid(sched, sample->tid, "<unknown>");
815
	wakee = register_pid(sched, pid, comm);
816

817
	add_sched_event_wakeup(sched, waker, sample->time, wakee);
818
	return 0;
I
Ingo Molnar 已提交
819 820
}

821 822 823 824
static int replay_switch_event(struct perf_sched *sched,
			       struct perf_evsel *evsel,
			       struct perf_sample *sample,
			       struct machine *machine __maybe_unused)
I
Ingo Molnar 已提交
825
{
826 827 828 829 830
	const char *prev_comm  = perf_evsel__strval(evsel, sample, "prev_comm"),
		   *next_comm  = perf_evsel__strval(evsel, sample, "next_comm");
	const u32 prev_pid = perf_evsel__intval(evsel, sample, "prev_pid"),
		  next_pid = perf_evsel__intval(evsel, sample, "next_pid");
	const u64 prev_state = perf_evsel__intval(evsel, sample, "prev_state");
831
	struct task_desc *prev, __maybe_unused *next;
832 833
	u64 timestamp0, timestamp = sample->time;
	int cpu = sample->cpu;
834 835
	s64 delta;

836
	if (verbose > 0)
837
		printf("sched_switch event %p\n", evsel);
I
Ingo Molnar 已提交
838

839
	if (cpu >= MAX_CPUS || cpu < 0)
840
		return 0;
841

842
	timestamp0 = sched->cpu_last_switched[cpu];
843 844 845 846 847
	if (timestamp0)
		delta = timestamp - timestamp0;
	else
		delta = 0;

848
	if (delta < 0) {
849
		pr_err("hm, delta: %" PRIu64 " < 0 ?\n", delta);
850 851
		return -1;
	}
852

853 854
	pr_debug(" ... switch from %s/%d to %s/%d [ran %" PRIu64 " nsecs]\n",
		 prev_comm, prev_pid, next_comm, next_pid, delta);
855

856 857
	prev = register_pid(sched, prev_pid, prev_comm);
	next = register_pid(sched, next_pid, next_comm);
858

859
	sched->cpu_last_switched[cpu] = timestamp;
860

861
	add_sched_event_run(sched, prev, timestamp, delta);
862
	add_sched_event_sleep(sched, prev, timestamp, prev_state);
863 864

	return 0;
865 866
}

867 868 869
static int replay_fork_event(struct perf_sched *sched,
			     union perf_event *event,
			     struct machine *machine)
870
{
871 872
	struct thread *child, *parent;

873 874 875 876
	child = machine__findnew_thread(machine, event->fork.pid,
					event->fork.tid);
	parent = machine__findnew_thread(machine, event->fork.ppid,
					 event->fork.ptid);
877 878 879 880

	if (child == NULL || parent == NULL) {
		pr_debug("thread does not exist on fork event: child %p, parent %p\n",
				 child, parent);
881
		goto out_put;
882
	}
883

884
	if (verbose > 0) {
885
		printf("fork event\n");
886 887
		printf("... parent: %s/%d\n", thread__comm_str(parent), parent->tid);
		printf("...  child: %s/%d\n", thread__comm_str(child), child->tid);
888
	}
889

890 891
	register_pid(sched, parent->tid, thread__comm_str(parent));
	register_pid(sched, child->tid, thread__comm_str(child));
892 893 894
out_put:
	thread__put(child);
	thread__put(parent);
895
	return 0;
896
}
897

898 899
struct sort_dimension {
	const char		*name;
900
	sort_fn_t		cmp;
901 902 903
	struct list_head	list;
};

904 905 906 907 908 909 910 911 912 913 914 915 916 917 918 919 920 921 922 923 924 925 926 927 928 929 930 931 932 933 934
/*
 * handle runtime stats saved per thread
 */
static struct thread_runtime *thread__init_runtime(struct thread *thread)
{
	struct thread_runtime *r;

	r = zalloc(sizeof(struct thread_runtime));
	if (!r)
		return NULL;

	init_stats(&r->run_stats);
	thread__set_priv(thread, r);

	return r;
}

static struct thread_runtime *thread__get_runtime(struct thread *thread)
{
	struct thread_runtime *tr;

	tr = thread__priv(thread);
	if (tr == NULL) {
		tr = thread__init_runtime(thread);
		if (tr == NULL)
			pr_debug("Failed to malloc memory for runtime data.\n");
	}

	return tr;
}

935
static int
936
thread_lat_cmp(struct list_head *list, struct work_atoms *l, struct work_atoms *r)
937 938 939 940
{
	struct sort_dimension *sort;
	int ret = 0;

941 942
	BUG_ON(list_empty(list));

943 944 945 946 947 948 949 950 951
	list_for_each_entry(sort, list, list) {
		ret = sort->cmp(l, r);
		if (ret)
			return ret;
	}

	return ret;
}

952
static struct work_atoms *
953 954 955 956
thread_atoms_search(struct rb_root *root, struct thread *thread,
			 struct list_head *sort_list)
{
	struct rb_node *node = root->rb_node;
957
	struct work_atoms key = { .thread = thread };
958 959

	while (node) {
960
		struct work_atoms *atoms;
961 962
		int cmp;

963
		atoms = container_of(node, struct work_atoms, node);
964 965 966 967 968 969 970 971 972 973 974 975 976 977

		cmp = thread_lat_cmp(sort_list, &key, atoms);
		if (cmp > 0)
			node = node->rb_left;
		else if (cmp < 0)
			node = node->rb_right;
		else {
			BUG_ON(thread != atoms->thread);
			return atoms;
		}
	}
	return NULL;
}

978
static void
979
__thread_latency_insert(struct rb_root *root, struct work_atoms *data,
980
			 struct list_head *sort_list)
981 982 983 984
{
	struct rb_node **new = &(root->rb_node), *parent = NULL;

	while (*new) {
985
		struct work_atoms *this;
986
		int cmp;
987

988
		this = container_of(*new, struct work_atoms, node);
989
		parent = *new;
990 991 992 993

		cmp = thread_lat_cmp(sort_list, data, this);

		if (cmp > 0)
994 995
			new = &((*new)->rb_left);
		else
996
			new = &((*new)->rb_right);
997 998 999 1000 1001 1002
	}

	rb_link_node(&data->node, parent, new);
	rb_insert_color(&data->node, root);
}

1003
static int thread_atoms_insert(struct perf_sched *sched, struct thread *thread)
1004
{
1005
	struct work_atoms *atoms = zalloc(sizeof(*atoms));
1006 1007 1008 1009
	if (!atoms) {
		pr_err("No memory at %s\n", __func__);
		return -1;
	}
1010

1011
	atoms->thread = thread__get(thread);
1012
	INIT_LIST_HEAD(&atoms->work_list);
1013
	__thread_latency_insert(&sched->atom_root, atoms, &sched->cmp_pid);
1014
	return 0;
1015 1016
}

1017
static char sched_out_state(u64 prev_state)
1018 1019 1020
{
	const char *str = TASK_STATE_TO_CHAR_STR;

1021
	return str[prev_state];
1022 1023
}

1024
static int
1025 1026 1027
add_sched_out_event(struct work_atoms *atoms,
		    char run_state,
		    u64 timestamp)
1028
{
1029
	struct work_atom *atom = zalloc(sizeof(*atom));
1030 1031 1032 1033
	if (!atom) {
		pr_err("Non memory at %s", __func__);
		return -1;
	}
1034

1035 1036
	atom->sched_out_time = timestamp;

1037
	if (run_state == 'R') {
1038
		atom->state = THREAD_WAIT_CPU;
1039
		atom->wake_up_time = atom->sched_out_time;
1040 1041
	}

1042
	list_add_tail(&atom->list, &atoms->work_list);
1043
	return 0;
1044 1045 1046
}

static void
1047 1048
add_runtime_event(struct work_atoms *atoms, u64 delta,
		  u64 timestamp __maybe_unused)
1049 1050 1051 1052 1053 1054 1055 1056 1057 1058 1059 1060 1061
{
	struct work_atom *atom;

	BUG_ON(list_empty(&atoms->work_list));

	atom = list_entry(atoms->work_list.prev, struct work_atom, list);

	atom->runtime += delta;
	atoms->total_runtime += delta;
}

static void
add_sched_in_event(struct work_atoms *atoms, u64 timestamp)
1062
{
1063
	struct work_atom *atom;
1064
	u64 delta;
1065

1066
	if (list_empty(&atoms->work_list))
1067 1068
		return;

1069
	atom = list_entry(atoms->work_list.prev, struct work_atom, list);
1070

1071
	if (atom->state != THREAD_WAIT_CPU)
1072 1073
		return;

1074 1075
	if (timestamp < atom->wake_up_time) {
		atom->state = THREAD_IGNORE;
1076 1077 1078
		return;
	}

1079 1080
	atom->state = THREAD_SCHED_IN;
	atom->sched_in_time = timestamp;
1081

1082
	delta = atom->sched_in_time - atom->wake_up_time;
1083
	atoms->total_lat += delta;
1084
	if (delta > atoms->max_lat) {
1085
		atoms->max_lat = delta;
1086 1087
		atoms->max_lat_at = timestamp;
	}
1088
	atoms->nb_atoms++;
1089 1090
}

1091 1092 1093 1094
static int latency_switch_event(struct perf_sched *sched,
				struct perf_evsel *evsel,
				struct perf_sample *sample,
				struct machine *machine)
1095
{
1096 1097 1098
	const u32 prev_pid = perf_evsel__intval(evsel, sample, "prev_pid"),
		  next_pid = perf_evsel__intval(evsel, sample, "next_pid");
	const u64 prev_state = perf_evsel__intval(evsel, sample, "prev_state");
1099
	struct work_atoms *out_events, *in_events;
1100
	struct thread *sched_out, *sched_in;
1101
	u64 timestamp0, timestamp = sample->time;
1102
	int cpu = sample->cpu, err = -1;
I
Ingo Molnar 已提交
1103 1104
	s64 delta;

1105
	BUG_ON(cpu >= MAX_CPUS || cpu < 0);
I
Ingo Molnar 已提交
1106

1107 1108
	timestamp0 = sched->cpu_last_switched[cpu];
	sched->cpu_last_switched[cpu] = timestamp;
I
Ingo Molnar 已提交
1109 1110 1111 1112 1113
	if (timestamp0)
		delta = timestamp - timestamp0;
	else
		delta = 0;

1114 1115 1116 1117
	if (delta < 0) {
		pr_err("hm, delta: %" PRIu64 " < 0 ?\n", delta);
		return -1;
	}
1118

1119 1120
	sched_out = machine__findnew_thread(machine, -1, prev_pid);
	sched_in = machine__findnew_thread(machine, -1, next_pid);
1121 1122
	if (sched_out == NULL || sched_in == NULL)
		goto out_put;
1123

1124
	out_events = thread_atoms_search(&sched->atom_root, sched_out, &sched->cmp_pid);
1125
	if (!out_events) {
1126
		if (thread_atoms_insert(sched, sched_out))
1127
			goto out_put;
1128
		out_events = thread_atoms_search(&sched->atom_root, sched_out, &sched->cmp_pid);
1129 1130
		if (!out_events) {
			pr_err("out-event: Internal tree error");
1131
			goto out_put;
1132
		}
1133
	}
1134
	if (add_sched_out_event(out_events, sched_out_state(prev_state), timestamp))
1135
		return -1;
1136

1137
	in_events = thread_atoms_search(&sched->atom_root, sched_in, &sched->cmp_pid);
1138
	if (!in_events) {
1139
		if (thread_atoms_insert(sched, sched_in))
1140
			goto out_put;
1141
		in_events = thread_atoms_search(&sched->atom_root, sched_in, &sched->cmp_pid);
1142 1143
		if (!in_events) {
			pr_err("in-event: Internal tree error");
1144
			goto out_put;
1145
		}
1146 1147 1148 1149
		/*
		 * Take came in we have not heard about yet,
		 * add in an initial atom in runnable state:
		 */
1150
		if (add_sched_out_event(in_events, 'R', timestamp))
1151
			goto out_put;
1152
	}
1153
	add_sched_in_event(in_events, timestamp);
1154 1155 1156 1157 1158
	err = 0;
out_put:
	thread__put(sched_out);
	thread__put(sched_in);
	return err;
1159
}
1160

1161 1162 1163 1164
static int latency_runtime_event(struct perf_sched *sched,
				 struct perf_evsel *evsel,
				 struct perf_sample *sample,
				 struct machine *machine)
1165
{
1166 1167
	const u32 pid	   = perf_evsel__intval(evsel, sample, "pid");
	const u64 runtime  = perf_evsel__intval(evsel, sample, "runtime");
1168
	struct thread *thread = machine__findnew_thread(machine, -1, pid);
1169
	struct work_atoms *atoms = thread_atoms_search(&sched->atom_root, thread, &sched->cmp_pid);
1170
	u64 timestamp = sample->time;
1171 1172 1173 1174
	int cpu = sample->cpu, err = -1;

	if (thread == NULL)
		return -1;
1175 1176 1177

	BUG_ON(cpu >= MAX_CPUS || cpu < 0);
	if (!atoms) {
1178
		if (thread_atoms_insert(sched, thread))
1179
			goto out_put;
1180
		atoms = thread_atoms_search(&sched->atom_root, thread, &sched->cmp_pid);
1181
		if (!atoms) {
1182
			pr_err("in-event: Internal tree error");
1183
			goto out_put;
1184 1185
		}
		if (add_sched_out_event(atoms, 'R', timestamp))
1186
			goto out_put;
1187 1188
	}

1189
	add_runtime_event(atoms, runtime, timestamp);
1190 1191 1192 1193
	err = 0;
out_put:
	thread__put(thread);
	return err;
1194 1195
}

1196 1197 1198 1199
static int latency_wakeup_event(struct perf_sched *sched,
				struct perf_evsel *evsel,
				struct perf_sample *sample,
				struct machine *machine)
1200
{
1201
	const u32 pid	  = perf_evsel__intval(evsel, sample, "pid");
1202
	struct work_atoms *atoms;
1203
	struct work_atom *atom;
1204
	struct thread *wakee;
1205
	u64 timestamp = sample->time;
1206
	int err = -1;
1207

1208
	wakee = machine__findnew_thread(machine, -1, pid);
1209 1210
	if (wakee == NULL)
		return -1;
1211
	atoms = thread_atoms_search(&sched->atom_root, wakee, &sched->cmp_pid);
1212
	if (!atoms) {
1213
		if (thread_atoms_insert(sched, wakee))
1214
			goto out_put;
1215
		atoms = thread_atoms_search(&sched->atom_root, wakee, &sched->cmp_pid);
1216
		if (!atoms) {
1217
			pr_err("wakeup-event: Internal tree error");
1218
			goto out_put;
1219 1220
		}
		if (add_sched_out_event(atoms, 'S', timestamp))
1221
			goto out_put;
1222 1223
	}

1224
	BUG_ON(list_empty(&atoms->work_list));
1225

1226
	atom = list_entry(atoms->work_list.prev, struct work_atom, list);
1227

1228
	/*
1229 1230 1231 1232 1233 1234
	 * As we do not guarantee the wakeup event happens when
	 * task is out of run queue, also may happen when task is
	 * on run queue and wakeup only change ->state to TASK_RUNNING,
	 * then we should not set the ->wake_up_time when wake up a
	 * task which is on run queue.
	 *
1235 1236
	 * You WILL be missing events if you've recorded only
	 * one CPU, or are only looking at only one, so don't
1237
	 * skip in this case.
1238
	 */
1239
	if (sched->profile_cpu == -1 && atom->state != THREAD_SLEEPING)
1240
		goto out_ok;
1241

1242
	sched->nr_timestamps++;
1243
	if (atom->sched_out_time > timestamp) {
1244
		sched->nr_unordered_timestamps++;
1245
		goto out_ok;
1246
	}
1247

1248 1249
	atom->state = THREAD_WAIT_CPU;
	atom->wake_up_time = timestamp;
1250 1251 1252 1253 1254
out_ok:
	err = 0;
out_put:
	thread__put(wakee);
	return err;
1255 1256
}

1257 1258 1259 1260
static int latency_migrate_task_event(struct perf_sched *sched,
				      struct perf_evsel *evsel,
				      struct perf_sample *sample,
				      struct machine *machine)
1261
{
1262
	const u32 pid = perf_evsel__intval(evsel, sample, "pid");
1263
	u64 timestamp = sample->time;
1264 1265 1266
	struct work_atoms *atoms;
	struct work_atom *atom;
	struct thread *migrant;
1267
	int err = -1;
1268 1269 1270 1271

	/*
	 * Only need to worry about migration when profiling one CPU.
	 */
1272
	if (sched->profile_cpu == -1)
1273
		return 0;
1274

1275
	migrant = machine__findnew_thread(machine, -1, pid);
1276 1277
	if (migrant == NULL)
		return -1;
1278
	atoms = thread_atoms_search(&sched->atom_root, migrant, &sched->cmp_pid);
1279
	if (!atoms) {
1280
		if (thread_atoms_insert(sched, migrant))
1281
			goto out_put;
1282
		register_pid(sched, migrant->tid, thread__comm_str(migrant));
1283
		atoms = thread_atoms_search(&sched->atom_root, migrant, &sched->cmp_pid);
1284
		if (!atoms) {
1285
			pr_err("migration-event: Internal tree error");
1286
			goto out_put;
1287 1288
		}
		if (add_sched_out_event(atoms, 'R', timestamp))
1289
			goto out_put;
1290 1291 1292 1293 1294 1295 1296
	}

	BUG_ON(list_empty(&atoms->work_list));

	atom = list_entry(atoms->work_list.prev, struct work_atom, list);
	atom->sched_in_time = atom->sched_out_time = atom->wake_up_time = timestamp;

1297
	sched->nr_timestamps++;
1298 1299

	if (atom->sched_out_time > timestamp)
1300
		sched->nr_unordered_timestamps++;
1301 1302 1303 1304
	err = 0;
out_put:
	thread__put(migrant);
	return err;
1305 1306
}

1307
static void output_lat_thread(struct perf_sched *sched, struct work_atoms *work_list)
1308 1309 1310
{
	int i;
	int ret;
1311
	u64 avg;
1312
	char max_lat_at[32];
1313

1314
	if (!work_list->nb_atoms)
1315
		return;
1316 1317 1318
	/*
	 * Ignore idle threads:
	 */
1319
	if (!strcmp(thread__comm_str(work_list->thread), "swapper"))
1320
		return;
1321

1322 1323
	sched->all_runtime += work_list->total_runtime;
	sched->all_count   += work_list->nb_atoms;
1324

1325 1326 1327 1328
	if (work_list->num_merged > 1)
		ret = printf("  %s:(%d) ", thread__comm_str(work_list->thread), work_list->num_merged);
	else
		ret = printf("  %s:%d ", thread__comm_str(work_list->thread), work_list->thread->tid);
1329

M
mingo 已提交
1330
	for (i = 0; i < 24 - ret; i++)
1331 1332
		printf(" ");

1333
	avg = work_list->total_lat / work_list->nb_atoms;
1334
	timestamp__scnprintf_usec(work_list->max_lat_at, max_lat_at, sizeof(max_lat_at));
1335

1336
	printf("|%11.3f ms |%9" PRIu64 " | avg:%9.3f ms | max:%9.3f ms | max at: %13s s\n",
1337 1338 1339
	      (double)work_list->total_runtime / NSEC_PER_MSEC,
		 work_list->nb_atoms, (double)avg / NSEC_PER_MSEC,
		 (double)work_list->max_lat / NSEC_PER_MSEC,
1340
		 max_lat_at);
1341 1342
}

1343
static int pid_cmp(struct work_atoms *l, struct work_atoms *r)
1344
{
1345 1346
	if (l->thread == r->thread)
		return 0;
1347
	if (l->thread->tid < r->thread->tid)
1348
		return -1;
1349
	if (l->thread->tid > r->thread->tid)
1350
		return 1;
1351
	return (int)(l->thread - r->thread);
1352 1353
}

1354
static int avg_cmp(struct work_atoms *l, struct work_atoms *r)
1355 1356 1357 1358 1359 1360 1361 1362 1363 1364 1365 1366 1367 1368 1369 1370 1371 1372 1373 1374
{
	u64 avgl, avgr;

	if (!l->nb_atoms)
		return -1;

	if (!r->nb_atoms)
		return 1;

	avgl = l->total_lat / l->nb_atoms;
	avgr = r->total_lat / r->nb_atoms;

	if (avgl < avgr)
		return -1;
	if (avgl > avgr)
		return 1;

	return 0;
}

1375
static int max_cmp(struct work_atoms *l, struct work_atoms *r)
1376 1377 1378 1379 1380 1381 1382 1383 1384
{
	if (l->max_lat < r->max_lat)
		return -1;
	if (l->max_lat > r->max_lat)
		return 1;

	return 0;
}

1385
static int switch_cmp(struct work_atoms *l, struct work_atoms *r)
1386 1387 1388 1389 1390 1391 1392 1393 1394
{
	if (l->nb_atoms < r->nb_atoms)
		return -1;
	if (l->nb_atoms > r->nb_atoms)
		return 1;

	return 0;
}

1395
static int runtime_cmp(struct work_atoms *l, struct work_atoms *r)
1396 1397 1398 1399 1400 1401 1402 1403 1404
{
	if (l->total_runtime < r->total_runtime)
		return -1;
	if (l->total_runtime > r->total_runtime)
		return 1;

	return 0;
}

1405
static int sort_dimension__add(const char *tok, struct list_head *list)
1406
{
1407 1408 1409 1410 1411 1412 1413 1414 1415 1416 1417 1418 1419 1420 1421 1422 1423 1424 1425 1426 1427 1428 1429 1430 1431 1432 1433 1434
	size_t i;
	static struct sort_dimension avg_sort_dimension = {
		.name = "avg",
		.cmp  = avg_cmp,
	};
	static struct sort_dimension max_sort_dimension = {
		.name = "max",
		.cmp  = max_cmp,
	};
	static struct sort_dimension pid_sort_dimension = {
		.name = "pid",
		.cmp  = pid_cmp,
	};
	static struct sort_dimension runtime_sort_dimension = {
		.name = "runtime",
		.cmp  = runtime_cmp,
	};
	static struct sort_dimension switch_sort_dimension = {
		.name = "switch",
		.cmp  = switch_cmp,
	};
	struct sort_dimension *available_sorts[] = {
		&pid_sort_dimension,
		&avg_sort_dimension,
		&max_sort_dimension,
		&switch_sort_dimension,
		&runtime_sort_dimension,
	};
1435

1436
	for (i = 0; i < ARRAY_SIZE(available_sorts); i++) {
1437 1438 1439 1440 1441 1442 1443 1444 1445 1446
		if (!strcmp(available_sorts[i]->name, tok)) {
			list_add_tail(&available_sorts[i]->list, list);

			return 0;
		}
	}

	return -1;
}

1447
static void perf_sched__sort_lat(struct perf_sched *sched)
1448 1449
{
	struct rb_node *node;
1450 1451
	struct rb_root *root = &sched->atom_root;
again:
1452
	for (;;) {
1453
		struct work_atoms *data;
1454
		node = rb_first(root);
1455 1456 1457
		if (!node)
			break;

1458
		rb_erase(node, root);
1459
		data = rb_entry(node, struct work_atoms, node);
1460
		__thread_latency_insert(&sched->sorted_atom_root, data, &sched->sort_list);
1461
	}
1462 1463 1464 1465
	if (root == &sched->atom_root) {
		root = &sched->merged_atom_root;
		goto again;
	}
1466 1467
}

1468
static int process_sched_wakeup_event(struct perf_tool *tool,
1469
				      struct perf_evsel *evsel,
1470
				      struct perf_sample *sample,
1471
				      struct machine *machine)
1472
{
1473
	struct perf_sched *sched = container_of(tool, struct perf_sched, tool);
1474

1475 1476
	if (sched->tp_handler->wakeup_event)
		return sched->tp_handler->wakeup_event(sched, evsel, sample, machine);
1477

1478
	return 0;
1479 1480
}

J
Jiri Olsa 已提交
1481 1482 1483 1484 1485 1486 1487 1488 1489 1490 1491 1492 1493 1494 1495 1496 1497 1498 1499 1500 1501 1502 1503 1504 1505 1506 1507 1508 1509 1510 1511 1512
union map_priv {
	void	*ptr;
	bool	 color;
};

static bool thread__has_color(struct thread *thread)
{
	union map_priv priv = {
		.ptr = thread__priv(thread),
	};

	return priv.color;
}

static struct thread*
map__findnew_thread(struct perf_sched *sched, struct machine *machine, pid_t pid, pid_t tid)
{
	struct thread *thread = machine__findnew_thread(machine, pid, tid);
	union map_priv priv = {
		.color = false,
	};

	if (!sched->map.color_pids || !thread || thread__priv(thread))
		return thread;

	if (thread_map__has(sched->map.color_pids, tid))
		priv.color = true;

	thread__set_priv(thread, priv.ptr);
	return thread;
}

1513 1514
static int map_switch_event(struct perf_sched *sched, struct perf_evsel *evsel,
			    struct perf_sample *sample, struct machine *machine)
1515
{
1516 1517
	const u32 next_pid = perf_evsel__intval(evsel, sample, "next_pid");
	struct thread *sched_in;
1518
	struct thread_runtime *tr;
1519
	int new_shortname;
1520
	u64 timestamp0, timestamp = sample->time;
1521
	s64 delta;
1522 1523 1524
	int i, this_cpu = sample->cpu;
	int cpus_nr;
	bool new_cpu = false;
1525
	const char *color = PERF_COLOR_NORMAL;
1526
	char stimestamp[32];
1527 1528 1529

	BUG_ON(this_cpu >= MAX_CPUS || this_cpu < 0);

1530 1531
	if (this_cpu > sched->max_cpu)
		sched->max_cpu = this_cpu;
1532

1533 1534 1535 1536 1537 1538 1539 1540 1541
	if (sched->map.comp) {
		cpus_nr = bitmap_weight(sched->map.comp_cpus_mask, MAX_CPUS);
		if (!test_and_set_bit(this_cpu, sched->map.comp_cpus_mask)) {
			sched->map.comp_cpus[cpus_nr++] = this_cpu;
			new_cpu = true;
		}
	} else
		cpus_nr = sched->max_cpu;

1542 1543
	timestamp0 = sched->cpu_last_switched[this_cpu];
	sched->cpu_last_switched[this_cpu] = timestamp;
1544 1545 1546 1547 1548
	if (timestamp0)
		delta = timestamp - timestamp0;
	else
		delta = 0;

1549
	if (delta < 0) {
1550
		pr_err("hm, delta: %" PRIu64 " < 0 ?\n", delta);
1551 1552
		return -1;
	}
1553

J
Jiri Olsa 已提交
1554
	sched_in = map__findnew_thread(sched, machine, -1, next_pid);
1555 1556
	if (sched_in == NULL)
		return -1;
1557

1558 1559 1560 1561 1562 1563
	tr = thread__get_runtime(sched_in);
	if (tr == NULL) {
		thread__put(sched_in);
		return -1;
	}

1564
	sched->curr_thread[this_cpu] = thread__get(sched_in);
1565 1566 1567 1568

	printf("  ");

	new_shortname = 0;
1569
	if (!tr->shortname[0]) {
1570 1571 1572 1573 1574
		if (!strcmp(thread__comm_str(sched_in), "swapper")) {
			/*
			 * Don't allocate a letter-number for swapper:0
			 * as a shortname. Instead, we use '.' for it.
			 */
1575 1576
			tr->shortname[0] = '.';
			tr->shortname[1] = ' ';
1577
		} else {
1578 1579
			tr->shortname[0] = sched->next_shortname1;
			tr->shortname[1] = sched->next_shortname2;
1580 1581 1582

			if (sched->next_shortname1 < 'Z') {
				sched->next_shortname1++;
1583
			} else {
1584 1585 1586 1587 1588
				sched->next_shortname1 = 'A';
				if (sched->next_shortname2 < '9')
					sched->next_shortname2++;
				else
					sched->next_shortname2 = '0';
1589 1590 1591 1592 1593
			}
		}
		new_shortname = 1;
	}

1594 1595
	for (i = 0; i < cpus_nr; i++) {
		int cpu = sched->map.comp ? sched->map.comp_cpus[i] : i;
J
Jiri Olsa 已提交
1596
		struct thread *curr_thread = sched->curr_thread[cpu];
1597
		struct thread_runtime *curr_tr;
J
Jiri Olsa 已提交
1598
		const char *pid_color = color;
J
Jiri Olsa 已提交
1599
		const char *cpu_color = color;
J
Jiri Olsa 已提交
1600 1601 1602

		if (curr_thread && thread__has_color(curr_thread))
			pid_color = COLOR_PIDS;
1603

1604 1605 1606
		if (sched->map.cpus && !cpu_map__has(sched->map.cpus, cpu))
			continue;

J
Jiri Olsa 已提交
1607 1608 1609
		if (sched->map.color_cpus && cpu_map__has(sched->map.color_cpus, cpu))
			cpu_color = COLOR_CPUS;

1610
		if (cpu != this_cpu)
1611
			color_fprintf(stdout, color, " ");
1612
		else
J
Jiri Olsa 已提交
1613
			color_fprintf(stdout, cpu_color, "*");
1614

1615 1616 1617 1618 1619 1620 1621 1622
		if (sched->curr_thread[cpu]) {
			curr_tr = thread__get_runtime(sched->curr_thread[cpu]);
			if (curr_tr == NULL) {
				thread__put(sched_in);
				return -1;
			}
			color_fprintf(stdout, pid_color, "%2s ", curr_tr->shortname);
		} else
1623
			color_fprintf(stdout, color, "   ");
1624 1625
	}

1626 1627 1628
	if (sched->map.cpus && !cpu_map__has(sched->map.cpus, this_cpu))
		goto out;

1629 1630
	timestamp__scnprintf_usec(timestamp, stimestamp, sizeof(stimestamp));
	color_fprintf(stdout, color, "  %12s secs ", stimestamp);
1631
	if (new_shortname || tr->comm_changed || (verbose > 0 && sched_in->tid)) {
J
Jiri Olsa 已提交
1632 1633 1634 1635 1636 1637
		const char *pid_color = color;

		if (thread__has_color(sched_in))
			pid_color = COLOR_PIDS;

		color_fprintf(stdout, pid_color, "%s => %s:%d",
1638
		       tr->shortname, thread__comm_str(sched_in), sched_in->tid);
1639
		tr->comm_changed = false;
1640
	}
1641

1642
	if (sched->map.comp && new_cpu)
1643
		color_fprintf(stdout, color, " (CPU %d)", this_cpu);
1644

1645
out:
1646
	color_fprintf(stdout, color, "\n");
1647

1648 1649
	thread__put(sched_in);

1650
	return 0;
1651 1652
}

1653
static int process_sched_switch_event(struct perf_tool *tool,
1654
				      struct perf_evsel *evsel,
1655
				      struct perf_sample *sample,
1656
				      struct machine *machine)
1657
{
1658
	struct perf_sched *sched = container_of(tool, struct perf_sched, tool);
1659
	int this_cpu = sample->cpu, err = 0;
1660 1661
	u32 prev_pid = perf_evsel__intval(evsel, sample, "prev_pid"),
	    next_pid = perf_evsel__intval(evsel, sample, "next_pid");
1662

1663
	if (sched->curr_pid[this_cpu] != (u32)-1) {
1664 1665 1666 1667
		/*
		 * Are we trying to switch away a PID that is
		 * not current?
		 */
1668
		if (sched->curr_pid[this_cpu] != prev_pid)
1669
			sched->nr_context_switch_bugs++;
1670 1671
	}

1672 1673
	if (sched->tp_handler->switch_event)
		err = sched->tp_handler->switch_event(sched, evsel, sample, machine);
1674 1675

	sched->curr_pid[this_cpu] = next_pid;
1676
	return err;
1677 1678
}

1679
static int process_sched_runtime_event(struct perf_tool *tool,
1680
				       struct perf_evsel *evsel,
1681
				       struct perf_sample *sample,
1682
				       struct machine *machine)
1683
{
1684
	struct perf_sched *sched = container_of(tool, struct perf_sched, tool);
1685

1686 1687
	if (sched->tp_handler->runtime_event)
		return sched->tp_handler->runtime_event(sched, evsel, sample, machine);
1688

1689
	return 0;
1690 1691
}

1692 1693 1694 1695
static int perf_sched__process_fork_event(struct perf_tool *tool,
					  union perf_event *event,
					  struct perf_sample *sample,
					  struct machine *machine)
1696
{
1697
	struct perf_sched *sched = container_of(tool, struct perf_sched, tool);
1698

1699 1700 1701 1702
	/* run the fork event through the perf machineruy */
	perf_event__process_fork(tool, event, sample, machine);

	/* and then run additional processing needed for this command */
1703
	if (sched->tp_handler->fork_event)
1704
		return sched->tp_handler->fork_event(sched, event, machine);
1705

1706
	return 0;
1707 1708
}

1709
static int process_sched_migrate_task_event(struct perf_tool *tool,
1710
					    struct perf_evsel *evsel,
1711
					    struct perf_sample *sample,
1712
					    struct machine *machine)
1713
{
1714
	struct perf_sched *sched = container_of(tool, struct perf_sched, tool);
1715

1716 1717
	if (sched->tp_handler->migrate_task_event)
		return sched->tp_handler->migrate_task_event(sched, evsel, sample, machine);
1718

1719
	return 0;
1720 1721
}

1722
typedef int (*tracepoint_handler)(struct perf_tool *tool,
1723
				  struct perf_evsel *evsel,
1724
				  struct perf_sample *sample,
1725
				  struct machine *machine);
I
Ingo Molnar 已提交
1726

1727 1728
static int perf_sched__process_tracepoint_sample(struct perf_tool *tool __maybe_unused,
						 union perf_event *event __maybe_unused,
1729 1730 1731
						 struct perf_sample *sample,
						 struct perf_evsel *evsel,
						 struct machine *machine)
I
Ingo Molnar 已提交
1732
{
1733
	int err = 0;
I
Ingo Molnar 已提交
1734

1735 1736
	if (evsel->handler != NULL) {
		tracepoint_handler f = evsel->handler;
1737
		err = f(tool, evsel, sample, machine);
1738
	}
I
Ingo Molnar 已提交
1739

1740
	return err;
I
Ingo Molnar 已提交
1741 1742
}

1743 1744 1745 1746 1747 1748 1749 1750 1751 1752 1753 1754 1755 1756 1757 1758 1759 1760 1761 1762 1763 1764 1765 1766 1767 1768 1769 1770 1771 1772 1773
static int perf_sched__process_comm(struct perf_tool *tool __maybe_unused,
				    union perf_event *event,
				    struct perf_sample *sample,
				    struct machine *machine)
{
	struct thread *thread;
	struct thread_runtime *tr;
	int err;

	err = perf_event__process_comm(tool, event, sample, machine);
	if (err)
		return err;

	thread = machine__find_thread(machine, sample->pid, sample->tid);
	if (!thread) {
		pr_err("Internal error: can't find thread\n");
		return -1;
	}

	tr = thread__get_runtime(thread);
	if (tr == NULL) {
		thread__put(thread);
		return -1;
	}

	tr->comm_changed = true;
	thread__put(thread);

	return 0;
}

1774
static int perf_sched__read_events(struct perf_sched *sched)
I
Ingo Molnar 已提交
1775
{
1776 1777 1778 1779 1780 1781 1782
	const struct perf_evsel_str_handler handlers[] = {
		{ "sched:sched_switch",	      process_sched_switch_event, },
		{ "sched:sched_stat_runtime", process_sched_runtime_event, },
		{ "sched:sched_wakeup",	      process_sched_wakeup_event, },
		{ "sched:sched_wakeup_new",   process_sched_wakeup_event, },
		{ "sched:sched_migrate_task", process_sched_migrate_task_event, },
	};
1783
	struct perf_session *session;
1784
	struct perf_data data = {
J
Jiri Olsa 已提交
1785 1786 1787 1788 1789
		.file      = {
			.path = input_name,
		},
		.mode      = PERF_DATA_MODE_READ,
		.force     = sched->force,
1790
	};
1791
	int rc = -1;
1792

1793
	session = perf_session__new(&data, false, &sched->tool);
1794 1795 1796 1797
	if (session == NULL) {
		pr_debug("No Memory for session\n");
		return -1;
	}
1798

1799
	symbol__init(&session->header.env);
1800

1801 1802
	if (perf_session__set_tracepoints_handlers(session, handlers))
		goto out_delete;
1803

1804
	if (perf_session__has_traces(session, "record -R")) {
1805
		int err = perf_session__process_events(session);
1806 1807 1808 1809
		if (err) {
			pr_err("Failed to process events, error %d", err);
			goto out_delete;
		}
1810

1811 1812 1813
		sched->nr_events      = session->evlist->stats.nr_events[0];
		sched->nr_lost_events = session->evlist->stats.total_lost;
		sched->nr_lost_chunks = session->evlist->stats.nr_events[PERF_RECORD_LOST];
1814
	}
1815

1816
	rc = 0;
1817 1818
out_delete:
	perf_session__delete(session);
1819
	return rc;
I
Ingo Molnar 已提交
1820 1821
}

1822 1823 1824 1825 1826 1827 1828 1829 1830 1831 1832 1833 1834 1835 1836 1837 1838 1839 1840 1841 1842 1843 1844 1845 1846 1847 1848 1849 1850 1851 1852 1853 1854 1855 1856 1857 1858 1859 1860 1861 1862 1863 1864 1865 1866 1867 1868 1869 1870 1871 1872 1873 1874 1875 1876 1877 1878 1879 1880 1881 1882 1883 1884 1885 1886 1887 1888 1889 1890 1891
/*
 * scheduling times are printed as msec.usec
 */
static inline void print_sched_time(unsigned long long nsecs, int width)
{
	unsigned long msecs;
	unsigned long usecs;

	msecs  = nsecs / NSEC_PER_MSEC;
	nsecs -= msecs * NSEC_PER_MSEC;
	usecs  = nsecs / NSEC_PER_USEC;
	printf("%*lu.%03lu ", width, msecs, usecs);
}

/*
 * returns runtime data for event, allocating memory for it the
 * first time it is used.
 */
static struct evsel_runtime *perf_evsel__get_runtime(struct perf_evsel *evsel)
{
	struct evsel_runtime *r = evsel->priv;

	if (r == NULL) {
		r = zalloc(sizeof(struct evsel_runtime));
		evsel->priv = r;
	}

	return r;
}

/*
 * save last time event was seen per cpu
 */
static void perf_evsel__save_time(struct perf_evsel *evsel,
				  u64 timestamp, u32 cpu)
{
	struct evsel_runtime *r = perf_evsel__get_runtime(evsel);

	if (r == NULL)
		return;

	if ((cpu >= r->ncpu) || (r->last_time == NULL)) {
		int i, n = __roundup_pow_of_two(cpu+1);
		void *p = r->last_time;

		p = realloc(r->last_time, n * sizeof(u64));
		if (!p)
			return;

		r->last_time = p;
		for (i = r->ncpu; i < n; ++i)
			r->last_time[i] = (u64) 0;

		r->ncpu = n;
	}

	r->last_time[cpu] = timestamp;
}

/* returns last time this event was seen on the given cpu */
static u64 perf_evsel__get_time(struct perf_evsel *evsel, u32 cpu)
{
	struct evsel_runtime *r = perf_evsel__get_runtime(evsel);

	if ((r == NULL) || (r->last_time == NULL) || (cpu >= r->ncpu))
		return 0;

	return r->last_time[cpu];
}

1892
static int comm_width = 30;
1893 1894 1895 1896 1897 1898 1899 1900 1901 1902 1903 1904 1905 1906 1907 1908 1909 1910 1911 1912 1913 1914 1915 1916

static char *timehist_get_commstr(struct thread *thread)
{
	static char str[32];
	const char *comm = thread__comm_str(thread);
	pid_t tid = thread->tid;
	pid_t pid = thread->pid_;
	int n;

	if (pid == 0)
		n = scnprintf(str, sizeof(str), "%s", comm);

	else if (tid != pid)
		n = scnprintf(str, sizeof(str), "%s[%d/%d]", comm, tid, pid);

	else
		n = scnprintf(str, sizeof(str), "%s[%d]", comm, tid);

	if (n > comm_width)
		comm_width = n;

	return str;
}

1917
static void timehist_header(struct perf_sched *sched)
1918
{
1919 1920 1921
	u32 ncpus = sched->max_cpu + 1;
	u32 i, j;

1922 1923
	printf("%15s %6s ", "time", "cpu");

1924 1925 1926 1927 1928 1929 1930 1931 1932 1933
	if (sched->show_cpu_visual) {
		printf(" ");
		for (i = 0, j = 0; i < ncpus; ++i) {
			printf("%x", j++);
			if (j > 15)
				j = 0;
		}
		printf(" ");
	}

1934
	printf(" %-*s  %9s  %9s  %9s", comm_width,
1935 1936
		"task name", "wait time", "sch delay", "run time");

1937 1938 1939
	if (sched->show_state)
		printf("  %s", "state");

1940 1941 1942 1943 1944 1945 1946
	printf("\n");

	/*
	 * units row
	 */
	printf("%15s %-6s ", "", "");

1947 1948 1949
	if (sched->show_cpu_visual)
		printf(" %*s ", ncpus, "");

1950
	printf(" %-*s  %9s  %9s  %9s", comm_width,
1951
	       "[tid/pid]", "(msec)", "(msec)", "(msec)");
1952

1953 1954 1955 1956 1957
	if (sched->show_state)
		printf("  %5s", "");

	printf("\n");

1958 1959 1960 1961 1962
	/*
	 * separator
	 */
	printf("%.15s %.6s ", graph_dotted_line, graph_dotted_line);

1963 1964 1965
	if (sched->show_cpu_visual)
		printf(" %.*s ", ncpus, graph_dotted_line);

1966
	printf(" %.*s  %.9s  %.9s  %.9s", comm_width,
1967 1968 1969
		graph_dotted_line, graph_dotted_line, graph_dotted_line,
		graph_dotted_line);

1970 1971 1972
	if (sched->show_state)
		printf("  %.5s", graph_dotted_line);

1973 1974 1975
	printf("\n");
}

1976 1977 1978 1979 1980 1981 1982 1983 1984 1985 1986 1987
static char task_state_char(struct thread *thread, int state)
{
	static const char state_to_char[] = TASK_STATE_TO_CHAR_STR;
	unsigned bit = state ? ffs(state) : 0;

	/* 'I' for idle */
	if (thread->tid == 0)
		return 'I';

	return bit < sizeof(state_to_char) - 1 ? state_to_char[bit] : '?';
}

1988
static void timehist_print_sample(struct perf_sched *sched,
1989
				  struct perf_evsel *evsel,
1990
				  struct perf_sample *sample,
1991
				  struct addr_location *al,
1992
				  struct thread *thread,
1993
				  u64 t, int state)
1994 1995
{
	struct thread_runtime *tr = thread__priv(thread);
1996 1997
	const char *next_comm = perf_evsel__strval(evsel, sample, "next_comm");
	const u32 next_pid = perf_evsel__intval(evsel, sample, "next_pid");
1998
	u32 max_cpus = sched->max_cpu + 1;
1999
	char tstr[64];
2000
	char nstr[30];
2001
	u64 wait_time;
2002

2003
	timestamp__scnprintf_usec(t, tstr, sizeof(tstr));
2004 2005
	printf("%15s [%04d] ", tstr, sample->cpu);

2006 2007 2008 2009 2010 2011 2012 2013 2014 2015 2016 2017 2018 2019 2020 2021
	if (sched->show_cpu_visual) {
		u32 i;
		char c;

		printf(" ");
		for (i = 0; i < max_cpus; ++i) {
			/* flag idle times with 'i'; others are sched events */
			if (i == sample->cpu)
				c = (thread->tid == 0) ? 'i' : 's';
			else
				c = ' ';
			printf("%c", c);
		}
		printf(" ");
	}

2022 2023
	printf(" %-*s ", comm_width, timehist_get_commstr(thread));

2024 2025 2026
	wait_time = tr->dt_sleep + tr->dt_iowait + tr->dt_preempt;
	print_sched_time(wait_time, 6);

2027 2028
	print_sched_time(tr->dt_delay, 6);
	print_sched_time(tr->dt_run, 6);
2029

2030 2031 2032
	if (sched->show_state)
		printf(" %5c ", task_state_char(thread, state));

2033 2034 2035 2036 2037 2038
	if (sched->show_next) {
		snprintf(nstr, sizeof(nstr), "next: %s[%d]", next_comm, next_pid);
		printf(" %-*s", comm_width, nstr);
	}

	if (sched->show_wakeups && !sched->show_next)
2039 2040
		printf("  %-*s", comm_width, "");

2041 2042 2043 2044 2045 2046 2047 2048
	if (thread->tid == 0)
		goto out;

	if (sched->show_callchain)
		printf("  ");

	sample__fprintf_sym(sample, al, 0,
			    EVSEL__PRINT_SYM | EVSEL__PRINT_ONELINE |
2049 2050
			    EVSEL__PRINT_CALLCHAIN_ARROW |
			    EVSEL__PRINT_SKIP_IGNORED,
2051 2052 2053
			    &callchain_cursor, stdout);

out:
2054 2055 2056 2057 2058 2059 2060 2061 2062 2063 2064 2065 2066 2067 2068 2069 2070 2071 2072 2073 2074 2075 2076 2077 2078 2079 2080 2081 2082 2083
	printf("\n");
}

/*
 * Explanation of delta-time stats:
 *
 *            t = time of current schedule out event
 *        tprev = time of previous sched out event
 *                also time of schedule-in event for current task
 *    last_time = time of last sched change event for current task
 *                (i.e, time process was last scheduled out)
 * ready_to_run = time of wakeup for current task
 *
 * -----|------------|------------|------------|------
 *    last         ready        tprev          t
 *    time         to run
 *
 *      |-------- dt_wait --------|
 *                   |- dt_delay -|-- dt_run --|
 *
 *   dt_run = run time of current task
 *  dt_wait = time between last schedule out event for task and tprev
 *            represents time spent off the cpu
 * dt_delay = time between wakeup and schedule-in of task
 */

static void timehist_update_runtime_stats(struct thread_runtime *r,
					 u64 t, u64 tprev)
{
	r->dt_delay   = 0;
2084 2085 2086
	r->dt_sleep   = 0;
	r->dt_iowait  = 0;
	r->dt_preempt = 0;
2087
	r->dt_run     = 0;
2088

2089 2090 2091 2092 2093 2094 2095 2096 2097 2098 2099
	if (tprev) {
		r->dt_run = t - tprev;
		if (r->ready_to_run) {
			if (r->ready_to_run > tprev)
				pr_debug("time travel: wakeup time for task > previous sched_switch event\n");
			else
				r->dt_delay = tprev - r->ready_to_run;
		}

		if (r->last_time > tprev)
			pr_debug("time travel: last sched out time for task > previous sched_switch event\n");
2100 2101 2102 2103 2104 2105 2106 2107 2108 2109
		else if (r->last_time) {
			u64 dt_wait = tprev - r->last_time;

			if (r->last_state == TASK_RUNNING)
				r->dt_preempt = dt_wait;
			else if (r->last_state == TASK_UNINTERRUPTIBLE)
				r->dt_iowait = dt_wait;
			else
				r->dt_sleep = dt_wait;
		}
2110 2111 2112
	}

	update_stats(&r->run_stats, r->dt_run);
2113 2114 2115 2116 2117 2118

	r->total_run_time     += r->dt_run;
	r->total_delay_time   += r->dt_delay;
	r->total_sleep_time   += r->dt_sleep;
	r->total_iowait_time  += r->dt_iowait;
	r->total_preempt_time += r->dt_preempt;
2119 2120
}

2121 2122
static bool is_idle_sample(struct perf_sample *sample,
			   struct perf_evsel *evsel)
2123 2124
{
	/* pid 0 == swapper == idle task */
2125 2126
	if (strcmp(perf_evsel__name(evsel), "sched:sched_switch") == 0)
		return perf_evsel__intval(evsel, sample, "prev_pid") == 0;
2127

2128 2129 2130 2131 2132 2133 2134 2135 2136 2137
	return sample->pid == 0;
}

static void save_task_callchain(struct perf_sched *sched,
				struct perf_sample *sample,
				struct perf_evsel *evsel,
				struct machine *machine)
{
	struct callchain_cursor *cursor = &callchain_cursor;
	struct thread *thread;
2138 2139 2140 2141 2142

	/* want main thread for process - has maps */
	thread = machine__findnew_thread(machine, sample->pid, sample->pid);
	if (thread == NULL) {
		pr_debug("Failed to get thread for pid %d.\n", sample->pid);
2143
		return;
2144 2145
	}

2146
	if (!sched->show_callchain || sample->callchain == NULL)
2147
		return;
2148 2149

	if (thread__resolve_callchain(thread, cursor, evsel, sample,
2150
				      NULL, NULL, sched->max_stack + 2) != 0) {
2151
		if (verbose > 0)
2152
			pr_err("Failed to resolve callchain. Skipping\n");
2153

2154
		return;
2155
	}
2156

2157
	callchain_cursor_commit(cursor);
2158 2159 2160 2161 2162 2163 2164 2165 2166 2167

	while (true) {
		struct callchain_cursor_node *node;
		struct symbol *sym;

		node = callchain_cursor_current(cursor);
		if (node == NULL)
			break;

		sym = node->sym;
2168
		if (sym) {
2169 2170 2171 2172 2173 2174 2175 2176
			if (!strcmp(sym->name, "schedule") ||
			    !strcmp(sym->name, "__schedule") ||
			    !strcmp(sym->name, "preempt_schedule"))
				sym->ignore = 1;
		}

		callchain_cursor_advance(cursor);
	}
2177 2178
}

2179 2180 2181 2182 2183 2184 2185 2186 2187 2188 2189 2190 2191 2192 2193 2194 2195 2196
static int init_idle_thread(struct thread *thread)
{
	struct idle_thread_runtime *itr;

	thread__set_comm(thread, idle_comm, 0);

	itr = zalloc(sizeof(*itr));
	if (itr == NULL)
		return -ENOMEM;

	init_stats(&itr->tr.run_stats);
	callchain_init(&itr->callchain);
	callchain_cursor_reset(&itr->cursor);
	thread__set_priv(thread, itr);

	return 0;
}

2197 2198 2199 2200 2201 2202
/*
 * Track idle stats per cpu by maintaining a local thread
 * struct for the idle task on each cpu.
 */
static int init_idle_threads(int ncpu)
{
2203
	int i, ret;
2204 2205 2206 2207 2208

	idle_threads = zalloc(ncpu * sizeof(struct thread *));
	if (!idle_threads)
		return -ENOMEM;

2209
	idle_max_cpu = ncpu;
2210 2211 2212 2213 2214 2215 2216

	/* allocate the actual thread struct if needed */
	for (i = 0; i < ncpu; ++i) {
		idle_threads[i] = thread__new(0, 0);
		if (idle_threads[i] == NULL)
			return -ENOMEM;

2217 2218 2219
		ret = init_idle_thread(idle_threads[i]);
		if (ret < 0)
			return ret;
2220 2221 2222 2223 2224 2225 2226 2227 2228 2229 2230 2231
	}

	return 0;
}

static void free_idle_threads(void)
{
	int i;

	if (idle_threads == NULL)
		return;

2232
	for (i = 0; i < idle_max_cpu; ++i) {
2233 2234 2235 2236 2237 2238 2239 2240 2241 2242 2243 2244 2245 2246 2247 2248 2249 2250 2251 2252 2253 2254
		if ((idle_threads[i]))
			thread__delete(idle_threads[i]);
	}

	free(idle_threads);
}

static struct thread *get_idle_thread(int cpu)
{
	/*
	 * expand/allocate array of pointers to local thread
	 * structs if needed
	 */
	if ((cpu >= idle_max_cpu) || (idle_threads == NULL)) {
		int i, j = __roundup_pow_of_two(cpu+1);
		void *p;

		p = realloc(idle_threads, j * sizeof(struct thread *));
		if (!p)
			return NULL;

		idle_threads = (struct thread **) p;
2255
		for (i = idle_max_cpu; i < j; ++i)
2256 2257 2258 2259 2260 2261 2262 2263 2264 2265
			idle_threads[i] = NULL;

		idle_max_cpu = j;
	}

	/* allocate a new thread struct if needed */
	if (idle_threads[cpu] == NULL) {
		idle_threads[cpu] = thread__new(0, 0);

		if (idle_threads[cpu]) {
2266 2267
			if (init_idle_thread(idle_threads[cpu]) < 0)
				return NULL;
2268 2269 2270 2271 2272 2273
		}
	}

	return idle_threads[cpu];
}

2274 2275
static void save_idle_callchain(struct perf_sched *sched,
				struct idle_thread_runtime *itr,
2276 2277
				struct perf_sample *sample)
{
2278
	if (!sched->show_callchain || sample->callchain == NULL)
2279 2280 2281 2282 2283
		return;

	callchain_cursor__copy(&itr->cursor, &callchain_cursor);
}

2284 2285
static struct thread *timehist_get_thread(struct perf_sched *sched,
					  struct perf_sample *sample,
2286 2287 2288 2289 2290
					  struct machine *machine,
					  struct perf_evsel *evsel)
{
	struct thread *thread;

2291
	if (is_idle_sample(sample, evsel)) {
2292 2293 2294 2295 2296
		thread = get_idle_thread(sample->cpu);
		if (thread == NULL)
			pr_err("Failed to get idle thread for cpu %d.\n", sample->cpu);

	} else {
2297 2298 2299
		/* there were samples with tid 0 but non-zero pid */
		thread = machine__findnew_thread(machine, sample->pid,
						 sample->tid ?: sample->pid);
2300 2301 2302 2303
		if (thread == NULL) {
			pr_debug("Failed to get thread for tid %d. skipping sample.\n",
				 sample->tid);
		}
2304 2305

		save_task_callchain(sched, sample, evsel, machine);
2306 2307 2308 2309 2310 2311 2312 2313 2314 2315 2316 2317 2318 2319 2320 2321 2322 2323
		if (sched->idle_hist) {
			struct thread *idle;
			struct idle_thread_runtime *itr;

			idle = get_idle_thread(sample->cpu);
			if (idle == NULL) {
				pr_err("Failed to get idle thread for cpu %d.\n", sample->cpu);
				return NULL;
			}

			itr = thread__priv(idle);
			if (itr == NULL)
				return NULL;

			itr->last_thread = thread;

			/* copy task callchain when entering to idle */
			if (perf_evsel__intval(evsel, sample, "next_pid") == 0)
2324
				save_idle_callchain(sched, itr, sample);
2325
		}
2326 2327 2328 2329 2330
	}

	return thread;
}

2331
static bool timehist_skip_sample(struct perf_sched *sched,
2332 2333 2334
				 struct thread *thread,
				 struct perf_evsel *evsel,
				 struct perf_sample *sample)
2335 2336 2337
{
	bool rc = false;

2338
	if (thread__is_filtered(thread)) {
2339
		rc = true;
2340 2341
		sched->skipped_samples++;
	}
2342

2343 2344 2345 2346 2347 2348 2349 2350
	if (sched->idle_hist) {
		if (strcmp(perf_evsel__name(evsel), "sched:sched_switch"))
			rc = true;
		else if (perf_evsel__intval(evsel, sample, "prev_pid") != 0 &&
			 perf_evsel__intval(evsel, sample, "next_pid") != 0)
			rc = true;
	}

2351 2352 2353
	return rc;
}

2354
static void timehist_print_wakeup_event(struct perf_sched *sched,
2355
					struct perf_evsel *evsel,
2356 2357 2358 2359 2360 2361 2362 2363 2364 2365 2366 2367
					struct perf_sample *sample,
					struct machine *machine,
					struct thread *awakened)
{
	struct thread *thread;
	char tstr[64];

	thread = machine__findnew_thread(machine, sample->pid, sample->tid);
	if (thread == NULL)
		return;

	/* show wakeup unless both awakee and awaker are filtered */
2368 2369
	if (timehist_skip_sample(sched, thread, evsel, sample) &&
	    timehist_skip_sample(sched, awakened, evsel, sample)) {
2370 2371 2372 2373 2374
		return;
	}

	timestamp__scnprintf_usec(sample->time, tstr, sizeof(tstr));
	printf("%15s [%04d] ", tstr, sample->cpu);
2375 2376
	if (sched->show_cpu_visual)
		printf(" %*s ", sched->max_cpu + 1, "");
2377 2378 2379 2380 2381 2382 2383 2384 2385 2386 2387 2388

	printf(" %-*s ", comm_width, timehist_get_commstr(thread));

	/* dt spacer */
	printf("  %9s  %9s  %9s ", "", "", "");

	printf("awakened: %s", timehist_get_commstr(awakened));

	printf("\n");
}

static int timehist_sched_wakeup_event(struct perf_tool *tool,
2389 2390 2391 2392 2393
				       union perf_event *event __maybe_unused,
				       struct perf_evsel *evsel,
				       struct perf_sample *sample,
				       struct machine *machine)
{
2394
	struct perf_sched *sched = container_of(tool, struct perf_sched, tool);
2395 2396 2397 2398 2399 2400 2401 2402 2403 2404 2405 2406 2407 2408 2409 2410
	struct thread *thread;
	struct thread_runtime *tr = NULL;
	/* want pid of awakened task not pid in sample */
	const u32 pid = perf_evsel__intval(evsel, sample, "pid");

	thread = machine__findnew_thread(machine, 0, pid);
	if (thread == NULL)
		return -1;

	tr = thread__get_runtime(thread);
	if (tr == NULL)
		return -1;

	if (tr->ready_to_run == 0)
		tr->ready_to_run = sample->time;

2411
	/* show wakeups if requested */
2412 2413
	if (sched->show_wakeups &&
	    !perf_time__skip_sample(&sched->ptime, sample->time))
2414
		timehist_print_wakeup_event(sched, evsel, sample, machine, thread);
2415

2416 2417 2418
	return 0;
}

2419 2420 2421 2422 2423 2424 2425 2426 2427 2428 2429 2430 2431 2432 2433 2434 2435 2436 2437 2438 2439 2440
static void timehist_print_migration_event(struct perf_sched *sched,
					struct perf_evsel *evsel,
					struct perf_sample *sample,
					struct machine *machine,
					struct thread *migrated)
{
	struct thread *thread;
	char tstr[64];
	u32 max_cpus = sched->max_cpu + 1;
	u32 ocpu, dcpu;

	if (sched->summary_only)
		return;

	max_cpus = sched->max_cpu + 1;
	ocpu = perf_evsel__intval(evsel, sample, "orig_cpu");
	dcpu = perf_evsel__intval(evsel, sample, "dest_cpu");

	thread = machine__findnew_thread(machine, sample->pid, sample->tid);
	if (thread == NULL)
		return;

2441 2442
	if (timehist_skip_sample(sched, thread, evsel, sample) &&
	    timehist_skip_sample(sched, migrated, evsel, sample)) {
2443 2444 2445 2446 2447 2448 2449 2450 2451 2452 2453 2454 2455 2456 2457 2458 2459 2460 2461 2462 2463 2464 2465 2466 2467 2468 2469 2470 2471 2472 2473 2474 2475 2476 2477 2478 2479 2480 2481 2482 2483 2484 2485 2486 2487 2488 2489 2490 2491 2492 2493 2494 2495 2496 2497 2498 2499
		return;
	}

	timestamp__scnprintf_usec(sample->time, tstr, sizeof(tstr));
	printf("%15s [%04d] ", tstr, sample->cpu);

	if (sched->show_cpu_visual) {
		u32 i;
		char c;

		printf("  ");
		for (i = 0; i < max_cpus; ++i) {
			c = (i == sample->cpu) ? 'm' : ' ';
			printf("%c", c);
		}
		printf("  ");
	}

	printf(" %-*s ", comm_width, timehist_get_commstr(thread));

	/* dt spacer */
	printf("  %9s  %9s  %9s ", "", "", "");

	printf("migrated: %s", timehist_get_commstr(migrated));
	printf(" cpu %d => %d", ocpu, dcpu);

	printf("\n");
}

static int timehist_migrate_task_event(struct perf_tool *tool,
				       union perf_event *event __maybe_unused,
				       struct perf_evsel *evsel,
				       struct perf_sample *sample,
				       struct machine *machine)
{
	struct perf_sched *sched = container_of(tool, struct perf_sched, tool);
	struct thread *thread;
	struct thread_runtime *tr = NULL;
	/* want pid of migrated task not pid in sample */
	const u32 pid = perf_evsel__intval(evsel, sample, "pid");

	thread = machine__findnew_thread(machine, 0, pid);
	if (thread == NULL)
		return -1;

	tr = thread__get_runtime(thread);
	if (tr == NULL)
		return -1;

	tr->migrations++;

	/* show migrations if requested */
	timehist_print_migration_event(sched, evsel, sample, machine, thread);

	return 0;
}

2500
static int timehist_sched_change_event(struct perf_tool *tool,
2501 2502 2503 2504 2505
				       union perf_event *event,
				       struct perf_evsel *evsel,
				       struct perf_sample *sample,
				       struct machine *machine)
{
2506
	struct perf_sched *sched = container_of(tool, struct perf_sched, tool);
2507
	struct perf_time_interval *ptime = &sched->ptime;
2508 2509 2510
	struct addr_location al;
	struct thread *thread;
	struct thread_runtime *tr = NULL;
2511
	u64 tprev, t = sample->time;
2512
	int rc = 0;
2513 2514
	int state = perf_evsel__intval(evsel, sample, "prev_state");

2515 2516 2517 2518 2519 2520 2521 2522

	if (machine__resolve(machine, &al, sample) < 0) {
		pr_err("problem processing %d event. skipping it\n",
		       event->header.type);
		rc = -1;
		goto out;
	}

2523
	thread = timehist_get_thread(sched, sample, machine, evsel);
2524 2525 2526 2527 2528
	if (thread == NULL) {
		rc = -1;
		goto out;
	}

2529
	if (timehist_skip_sample(sched, thread, evsel, sample))
2530 2531 2532 2533 2534 2535 2536 2537 2538 2539
		goto out;

	tr = thread__get_runtime(thread);
	if (tr == NULL) {
		rc = -1;
		goto out;
	}

	tprev = perf_evsel__get_time(evsel, sample->cpu);

2540 2541 2542 2543 2544 2545 2546 2547
	/*
	 * If start time given:
	 * - sample time is under window user cares about - skip sample
	 * - tprev is under window user cares about  - reset to start of window
	 */
	if (ptime->start && ptime->start > t)
		goto out;

2548
	if (tprev && ptime->start > tprev)
2549 2550 2551 2552 2553 2554 2555 2556 2557 2558 2559 2560 2561 2562 2563 2564
		tprev = ptime->start;

	/*
	 * If end time given:
	 * - previous sched event is out of window - we are done
	 * - sample time is beyond window user cares about - reset it
	 *   to close out stats for time window interest
	 */
	if (ptime->end) {
		if (tprev > ptime->end)
			goto out;

		if (t > ptime->end)
			t = ptime->end;
	}

2565 2566 2567 2568 2569 2570 2571 2572 2573 2574 2575 2576 2577 2578 2579 2580 2581 2582 2583 2584 2585 2586 2587 2588 2589
	if (!sched->idle_hist || thread->tid == 0) {
		timehist_update_runtime_stats(tr, t, tprev);

		if (sched->idle_hist) {
			struct idle_thread_runtime *itr = (void *)tr;
			struct thread_runtime *last_tr;

			BUG_ON(thread->tid != 0);

			if (itr->last_thread == NULL)
				goto out;

			/* add current idle time as last thread's runtime */
			last_tr = thread__get_runtime(itr->last_thread);
			if (last_tr == NULL)
				goto out;

			timehist_update_runtime_stats(last_tr, t, tprev);
			/*
			 * remove delta time of last thread as it's not updated
			 * and otherwise it will show an invalid value next
			 * time.  we only care total run time and run stat.
			 */
			last_tr->dt_run = 0;
			last_tr->dt_delay = 0;
2590 2591 2592
			last_tr->dt_sleep = 0;
			last_tr->dt_iowait = 0;
			last_tr->dt_preempt = 0;
2593

2594 2595 2596
			if (itr->cursor.nr)
				callchain_append(&itr->callchain, &itr->cursor, t - tprev);

2597 2598 2599
			itr->last_thread = NULL;
		}
	}
2600

2601
	if (!sched->summary_only)
2602
		timehist_print_sample(sched, evsel, sample, &al, thread, t, state);
2603 2604

out:
2605 2606 2607 2608 2609
	if (sched->hist_time.start == 0 && t >= ptime->start)
		sched->hist_time.start = t;
	if (ptime->end == 0 || t <= ptime->end)
		sched->hist_time.end = t;

2610 2611 2612 2613
	if (tr) {
		/* time of this sched_switch event becomes last time task seen */
		tr->last_time = sample->time;

2614
		/* last state is used to determine where to account wait time */
2615
		tr->last_state = state;
2616

2617 2618 2619 2620 2621 2622 2623 2624 2625 2626 2627 2628 2629 2630 2631 2632 2633 2634 2635 2636 2637 2638 2639 2640 2641 2642 2643 2644 2645 2646 2647 2648 2649
		/* sched out event for task so reset ready to run time */
		tr->ready_to_run = 0;
	}

	perf_evsel__save_time(evsel, sample->time, sample->cpu);

	return rc;
}

static int timehist_sched_switch_event(struct perf_tool *tool,
			     union perf_event *event,
			     struct perf_evsel *evsel,
			     struct perf_sample *sample,
			     struct machine *machine __maybe_unused)
{
	return timehist_sched_change_event(tool, event, evsel, sample, machine);
}

static int process_lost(struct perf_tool *tool __maybe_unused,
			union perf_event *event,
			struct perf_sample *sample,
			struct machine *machine __maybe_unused)
{
	char tstr[64];

	timestamp__scnprintf_usec(sample->time, tstr, sizeof(tstr));
	printf("%15s ", tstr);
	printf("lost %" PRIu64 " events on cpu %d\n", event->lost.lost, sample->cpu);

	return 0;
}


2650 2651 2652 2653 2654 2655 2656 2657 2658 2659 2660 2661 2662 2663 2664 2665 2666 2667 2668
static void print_thread_runtime(struct thread *t,
				 struct thread_runtime *r)
{
	double mean = avg_stats(&r->run_stats);
	float stddev;

	printf("%*s   %5d  %9" PRIu64 " ",
	       comm_width, timehist_get_commstr(t), t->ppid,
	       (u64) r->run_stats.n);

	print_sched_time(r->total_run_time, 8);
	stddev = rel_stddev_stats(stddev_stats(&r->run_stats), mean);
	print_sched_time(r->run_stats.min, 6);
	printf(" ");
	print_sched_time((u64) mean, 6);
	printf(" ");
	print_sched_time(r->run_stats.max, 6);
	printf("  ");
	printf("%5.2f", stddev);
2669
	printf("   %5" PRIu64, r->migrations);
2670 2671 2672
	printf("\n");
}

2673 2674 2675 2676 2677 2678 2679 2680 2681 2682 2683 2684 2685 2686 2687 2688 2689 2690
static void print_thread_waittime(struct thread *t,
				  struct thread_runtime *r)
{
	printf("%*s   %5d  %9" PRIu64 " ",
	       comm_width, timehist_get_commstr(t), t->ppid,
	       (u64) r->run_stats.n);

	print_sched_time(r->total_run_time, 8);
	print_sched_time(r->total_sleep_time, 6);
	printf(" ");
	print_sched_time(r->total_iowait_time, 6);
	printf(" ");
	print_sched_time(r->total_preempt_time, 6);
	printf(" ");
	print_sched_time(r->total_delay_time, 6);
	printf("\n");
}

2691
struct total_run_stats {
2692
	struct perf_sched *sched;
2693 2694 2695 2696 2697 2698 2699 2700 2701 2702 2703 2704 2705 2706 2707 2708 2709 2710
	u64  sched_count;
	u64  task_count;
	u64  total_run_time;
};

static int __show_thread_runtime(struct thread *t, void *priv)
{
	struct total_run_stats *stats = priv;
	struct thread_runtime *r;

	if (thread__is_filtered(t))
		return 0;

	r = thread__priv(t);
	if (r && r->run_stats.n) {
		stats->task_count++;
		stats->sched_count += r->run_stats.n;
		stats->total_run_time += r->total_run_time;
2711 2712 2713 2714 2715

		if (stats->sched->show_state)
			print_thread_waittime(t, r);
		else
			print_thread_runtime(t, r);
2716 2717 2718 2719 2720 2721 2722 2723 2724 2725 2726 2727 2728 2729 2730 2731 2732 2733 2734 2735 2736
	}

	return 0;
}

static int show_thread_runtime(struct thread *t, void *priv)
{
	if (t->dead)
		return 0;

	return __show_thread_runtime(t, priv);
}

static int show_deadthread_runtime(struct thread *t, void *priv)
{
	if (!t->dead)
		return 0;

	return __show_thread_runtime(t, priv);
}

2737 2738 2739 2740 2741 2742 2743 2744 2745 2746 2747 2748 2749 2750 2751 2752 2753 2754 2755 2756 2757 2758 2759 2760 2761 2762 2763 2764 2765 2766 2767 2768 2769 2770 2771 2772 2773 2774 2775 2776 2777 2778 2779 2780 2781 2782 2783 2784 2785 2786 2787 2788 2789 2790
static size_t callchain__fprintf_folded(FILE *fp, struct callchain_node *node)
{
	const char *sep = " <- ";
	struct callchain_list *chain;
	size_t ret = 0;
	char bf[1024];
	bool first;

	if (node == NULL)
		return 0;

	ret = callchain__fprintf_folded(fp, node->parent);
	first = (ret == 0);

	list_for_each_entry(chain, &node->val, list) {
		if (chain->ip >= PERF_CONTEXT_MAX)
			continue;
		if (chain->ms.sym && chain->ms.sym->ignore)
			continue;
		ret += fprintf(fp, "%s%s", first ? "" : sep,
			       callchain_list__sym_name(chain, bf, sizeof(bf),
							false));
		first = false;
	}

	return ret;
}

static size_t timehist_print_idlehist_callchain(struct rb_root *root)
{
	size_t ret = 0;
	FILE *fp = stdout;
	struct callchain_node *chain;
	struct rb_node *rb_node = rb_first(root);

	printf("  %16s  %8s  %s\n", "Idle time (msec)", "Count", "Callchains");
	printf("  %.16s  %.8s  %.50s\n", graph_dotted_line, graph_dotted_line,
	       graph_dotted_line);

	while (rb_node) {
		chain = rb_entry(rb_node, struct callchain_node, rb_node);
		rb_node = rb_next(rb_node);

		ret += fprintf(fp, "  ");
		print_sched_time(chain->hit, 12);
		ret += 16;  /* print_sched_time returns 2nd arg + 4 */
		ret += fprintf(fp, " %8d  ", chain->count);
		ret += callchain__fprintf_folded(fp, chain);
		ret += fprintf(fp, "\n");
	}

	return ret;
}

2791 2792 2793 2794 2795 2796 2797 2798 2799
static void timehist_print_summary(struct perf_sched *sched,
				   struct perf_session *session)
{
	struct machine *m = &session->machines.host;
	struct total_run_stats totals;
	u64 task_count;
	struct thread *t;
	struct thread_runtime *r;
	int i;
2800
	u64 hist_time = sched->hist_time.end - sched->hist_time.start;
2801 2802

	memset(&totals, 0, sizeof(totals));
2803
	totals.sched = sched;
2804

2805 2806 2807 2808
	if (sched->idle_hist) {
		printf("\nIdle-time summary\n");
		printf("%*s  parent  sched-out  ", comm_width, "comm");
		printf("  idle-time   min-idle    avg-idle    max-idle  stddev  migrations\n");
2809 2810 2811 2812
	} else if (sched->show_state) {
		printf("\nWait-time summary\n");
		printf("%*s  parent   sched-in  ", comm_width, "comm");
		printf("   run-time      sleep      iowait     preempt       delay\n");
2813 2814 2815 2816 2817
	} else {
		printf("\nRuntime summary\n");
		printf("%*s  parent   sched-in  ", comm_width, "comm");
		printf("   run-time    min-run     avg-run     max-run  stddev  migrations\n");
	}
2818
	printf("%*s            (count)  ", comm_width, "");
2819 2820
	printf("     (msec)     (msec)      (msec)      (msec)       %s\n",
	       sched->show_state ? "(msec)" : "%");
2821
	printf("%.117s\n", graph_dotted_line);
2822 2823 2824 2825 2826 2827 2828 2829 2830 2831 2832 2833

	machine__for_each_thread(m, show_thread_runtime, &totals);
	task_count = totals.task_count;
	if (!task_count)
		printf("<no still running tasks>\n");

	printf("\nTerminated tasks:\n");
	machine__for_each_thread(m, show_deadthread_runtime, &totals);
	if (task_count == totals.task_count)
		printf("<no terminated tasks>\n");

	/* CPU idle stats not tracked when samples were skipped */
2834
	if (sched->skipped_samples && !sched->idle_hist)
2835 2836 2837
		return;

	printf("\nIdle stats:\n");
2838
	for (i = 0; i < idle_max_cpu; ++i) {
2839 2840 2841 2842 2843 2844 2845 2846 2847
		t = idle_threads[i];
		if (!t)
			continue;

		r = thread__priv(t);
		if (r && r->run_stats.n) {
			totals.sched_count += r->run_stats.n;
			printf("    CPU %2d idle for ", i);
			print_sched_time(r->total_run_time, 6);
2848
			printf(" msec  (%6.2f%%)\n", 100.0 * r->total_run_time / hist_time);
2849 2850 2851 2852
		} else
			printf("    CPU %2d idle entire time window\n", i);
	}

2853
	if (sched->idle_hist && sched->show_callchain) {
2854 2855 2856 2857 2858 2859 2860 2861 2862 2863 2864 2865 2866 2867 2868 2869 2870 2871 2872 2873 2874 2875 2876 2877 2878 2879 2880 2881
		callchain_param.mode  = CHAIN_FOLDED;
		callchain_param.value = CCVAL_PERIOD;

		callchain_register_param(&callchain_param);

		printf("\nIdle stats by callchain:\n");
		for (i = 0; i < idle_max_cpu; ++i) {
			struct idle_thread_runtime *itr;

			t = idle_threads[i];
			if (!t)
				continue;

			itr = thread__priv(t);
			if (itr == NULL)
				continue;

			callchain_param.sort(&itr->sorted_root, &itr->callchain,
					     0, &callchain_param);

			printf("  CPU %2d:", i);
			print_sched_time(itr->tr.total_run_time, 6);
			printf(" msec\n");
			timehist_print_idlehist_callchain(&itr->sorted_root);
			printf("\n");
		}
	}

2882 2883
	printf("\n"
	       "    Total number of unique tasks: %" PRIu64 "\n"
2884
	       "Total number of context switches: %" PRIu64 "\n",
2885 2886
	       totals.task_count, totals.sched_count);

2887
	printf("           Total run time (msec): ");
2888 2889
	print_sched_time(totals.total_run_time, 2);
	printf("\n");
2890 2891 2892 2893

	printf("    Total scheduling time (msec): ");
	print_sched_time(hist_time, 2);
	printf(" (x %d)\n", sched->max_cpu);
2894 2895
}

2896 2897 2898 2899 2900 2901 2902 2903 2904 2905 2906 2907 2908 2909 2910 2911 2912 2913 2914 2915 2916 2917 2918 2919 2920 2921 2922 2923
typedef int (*sched_handler)(struct perf_tool *tool,
			  union perf_event *event,
			  struct perf_evsel *evsel,
			  struct perf_sample *sample,
			  struct machine *machine);

static int perf_timehist__process_sample(struct perf_tool *tool,
					 union perf_event *event,
					 struct perf_sample *sample,
					 struct perf_evsel *evsel,
					 struct machine *machine)
{
	struct perf_sched *sched = container_of(tool, struct perf_sched, tool);
	int err = 0;
	int this_cpu = sample->cpu;

	if (this_cpu > sched->max_cpu)
		sched->max_cpu = this_cpu;

	if (evsel->handler != NULL) {
		sched_handler f = evsel->handler;

		err = f(tool, event, evsel, sample, machine);
	}

	return err;
}

2924 2925 2926 2927 2928 2929 2930 2931 2932 2933 2934 2935 2936
static int timehist_check_attr(struct perf_sched *sched,
			       struct perf_evlist *evlist)
{
	struct perf_evsel *evsel;
	struct evsel_runtime *er;

	list_for_each_entry(evsel, &evlist->entries, node) {
		er = perf_evsel__get_runtime(evsel);
		if (er == NULL) {
			pr_err("Failed to allocate memory for evsel runtime data\n");
			return -1;
		}

2937
		if (sched->show_callchain && !evsel__has_callchain(evsel)) {
2938 2939 2940 2941 2942 2943 2944 2945 2946
			pr_info("Samples do not have callchains.\n");
			sched->show_callchain = 0;
			symbol_conf.use_callchain = 0;
		}
	}

	return 0;
}

2947 2948 2949 2950 2951 2952 2953
static int perf_sched__timehist(struct perf_sched *sched)
{
	const struct perf_evsel_str_handler handlers[] = {
		{ "sched:sched_switch",       timehist_sched_switch_event, },
		{ "sched:sched_wakeup",	      timehist_sched_wakeup_event, },
		{ "sched:sched_wakeup_new",   timehist_sched_wakeup_event, },
	};
2954 2955 2956
	const struct perf_evsel_str_handler migrate_handlers[] = {
		{ "sched:sched_migrate_task", timehist_migrate_task_event, },
	};
2957
	struct perf_data data = {
J
Jiri Olsa 已提交
2958 2959 2960 2961 2962
		.file      = {
			.path = input_name,
		},
		.mode      = PERF_DATA_MODE_READ,
		.force     = sched->force,
2963 2964 2965
	};

	struct perf_session *session;
2966
	struct perf_evlist *evlist;
2967 2968 2969 2970 2971 2972 2973 2974 2975 2976 2977 2978 2979 2980 2981 2982 2983 2984
	int err = -1;

	/*
	 * event handlers for timehist option
	 */
	sched->tool.sample	 = perf_timehist__process_sample;
	sched->tool.mmap	 = perf_event__process_mmap;
	sched->tool.comm	 = perf_event__process_comm;
	sched->tool.exit	 = perf_event__process_exit;
	sched->tool.fork	 = perf_event__process_fork;
	sched->tool.lost	 = process_lost;
	sched->tool.attr	 = perf_event__process_attr;
	sched->tool.tracing_data = perf_event__process_tracing_data;
	sched->tool.build_id	 = perf_event__process_build_id;

	sched->tool.ordered_events = true;
	sched->tool.ordering_requires_timestamps = true;

2985 2986
	symbol_conf.use_callchain = sched->show_callchain;

2987
	session = perf_session__new(&data, false, &sched->tool);
2988 2989 2990
	if (session == NULL)
		return -ENOMEM;

2991 2992
	evlist = session->evlist;

2993 2994
	symbol__init(&session->header.env);

2995 2996 2997 2998 2999
	if (perf_time__parse_str(&sched->ptime, sched->time_str) != 0) {
		pr_err("Invalid time string\n");
		return -EINVAL;
	}

3000 3001 3002
	if (timehist_check_attr(sched, evlist) != 0)
		goto out;

3003 3004 3005 3006 3007 3008
	setup_pager();

	/* setup per-evsel handlers */
	if (perf_session__set_tracepoints_handlers(session, handlers))
		goto out;

3009 3010 3011 3012
	/* sched_switch event at a minimum needs to exist */
	if (!perf_evlist__find_tracepoint_by_name(session->evlist,
						  "sched:sched_switch")) {
		pr_err("No sched_switch events found. Have you run 'perf sched record'?\n");
3013
		goto out;
3014
	}
3015

3016 3017 3018 3019
	if (sched->show_migrations &&
	    perf_session__set_tracepoints_handlers(session, migrate_handlers))
		goto out;

3020 3021 3022 3023 3024 3025 3026
	/* pre-allocate struct for per-CPU idle stats */
	sched->max_cpu = session->header.env.nr_cpus_online;
	if (sched->max_cpu == 0)
		sched->max_cpu = 4;
	if (init_idle_threads(sched->max_cpu))
		goto out;

3027 3028 3029 3030 3031
	/* summary_only implies summary option, but don't overwrite summary if set */
	if (sched->summary_only)
		sched->summary = sched->summary_only;

	if (!sched->summary_only)
3032
		timehist_header(sched);
3033 3034 3035 3036 3037 3038 3039

	err = perf_session__process_events(session);
	if (err) {
		pr_err("Failed to process events, error %d", err);
		goto out;
	}

3040 3041 3042 3043 3044 3045 3046
	sched->nr_events      = evlist->stats.nr_events[0];
	sched->nr_lost_events = evlist->stats.total_lost;
	sched->nr_lost_chunks = evlist->stats.nr_events[PERF_RECORD_LOST];

	if (sched->summary)
		timehist_print_summary(sched, session);

3047 3048 3049 3050 3051 3052 3053 3054
out:
	free_idle_threads();
	perf_session__delete(session);

	return err;
}


3055
static void print_bad_events(struct perf_sched *sched)
3056
{
3057
	if (sched->nr_unordered_timestamps && sched->nr_timestamps) {
3058
		printf("  INFO: %.3f%% unordered timestamps (%ld out of %ld)\n",
3059 3060
			(double)sched->nr_unordered_timestamps/(double)sched->nr_timestamps*100.0,
			sched->nr_unordered_timestamps, sched->nr_timestamps);
3061
	}
3062
	if (sched->nr_lost_events && sched->nr_events) {
3063
		printf("  INFO: %.3f%% lost events (%ld out of %ld, in %ld chunks)\n",
3064 3065
			(double)sched->nr_lost_events/(double)sched->nr_events * 100.0,
			sched->nr_lost_events, sched->nr_events, sched->nr_lost_chunks);
3066
	}
3067
	if (sched->nr_context_switch_bugs && sched->nr_timestamps) {
3068
		printf("  INFO: %.3f%% context switch bugs (%ld out of %ld)",
3069 3070 3071
			(double)sched->nr_context_switch_bugs/(double)sched->nr_timestamps*100.0,
			sched->nr_context_switch_bugs, sched->nr_timestamps);
		if (sched->nr_lost_events)
3072 3073 3074 3075 3076
			printf(" (due to lost events?)");
		printf("\n");
	}
}

3077 3078 3079 3080 3081 3082 3083 3084 3085 3086 3087 3088 3089 3090 3091 3092 3093 3094 3095 3096 3097 3098 3099 3100 3101 3102 3103 3104 3105 3106 3107 3108 3109 3110 3111 3112 3113 3114 3115 3116 3117 3118 3119 3120 3121 3122 3123 3124 3125 3126 3127 3128 3129
static void __merge_work_atoms(struct rb_root *root, struct work_atoms *data)
{
	struct rb_node **new = &(root->rb_node), *parent = NULL;
	struct work_atoms *this;
	const char *comm = thread__comm_str(data->thread), *this_comm;

	while (*new) {
		int cmp;

		this = container_of(*new, struct work_atoms, node);
		parent = *new;

		this_comm = thread__comm_str(this->thread);
		cmp = strcmp(comm, this_comm);
		if (cmp > 0) {
			new = &((*new)->rb_left);
		} else if (cmp < 0) {
			new = &((*new)->rb_right);
		} else {
			this->num_merged++;
			this->total_runtime += data->total_runtime;
			this->nb_atoms += data->nb_atoms;
			this->total_lat += data->total_lat;
			list_splice(&data->work_list, &this->work_list);
			if (this->max_lat < data->max_lat) {
				this->max_lat = data->max_lat;
				this->max_lat_at = data->max_lat_at;
			}
			zfree(&data);
			return;
		}
	}

	data->num_merged++;
	rb_link_node(&data->node, parent, new);
	rb_insert_color(&data->node, root);
}

static void perf_sched__merge_lat(struct perf_sched *sched)
{
	struct work_atoms *data;
	struct rb_node *node;

	if (sched->skip_merge)
		return;

	while ((node = rb_first(&sched->atom_root))) {
		rb_erase(node, &sched->atom_root);
		data = rb_entry(node, struct work_atoms, node);
		__merge_work_atoms(&sched->merged_atom_root, data);
	}
}

3130
static int perf_sched__lat(struct perf_sched *sched)
3131 3132 3133 3134
{
	struct rb_node *next;

	setup_pager();
3135

3136
	if (perf_sched__read_events(sched))
3137
		return -1;
3138

3139
	perf_sched__merge_lat(sched);
3140
	perf_sched__sort_lat(sched);
3141

3142 3143 3144
	printf("\n -----------------------------------------------------------------------------------------------------------------\n");
	printf("  Task                  |   Runtime ms  | Switches | Average delay ms | Maximum delay ms | Maximum delay at       |\n");
	printf(" -----------------------------------------------------------------------------------------------------------------\n");
3145

3146
	next = rb_first(&sched->sorted_atom_root);
3147 3148 3149 3150 3151

	while (next) {
		struct work_atoms *work_list;

		work_list = rb_entry(next, struct work_atoms, node);
3152
		output_lat_thread(sched, work_list);
3153
		next = rb_next(next);
3154
		thread__zput(work_list->thread);
3155 3156
	}

3157
	printf(" -----------------------------------------------------------------------------------------------------------------\n");
3158
	printf("  TOTAL:                |%11.3f ms |%9" PRIu64 " |\n",
3159
		(double)sched->all_runtime / NSEC_PER_MSEC, sched->all_count);
3160 3161 3162

	printf(" ---------------------------------------------------\n");

3163
	print_bad_events(sched);
3164 3165
	printf("\n");

3166
	return 0;
3167 3168
}

3169 3170
static int setup_map_cpus(struct perf_sched *sched)
{
3171 3172
	struct cpu_map *map;

3173 3174 3175 3176
	sched->max_cpu  = sysconf(_SC_NPROCESSORS_CONF);

	if (sched->map.comp) {
		sched->map.comp_cpus = zalloc(sched->max_cpu * sizeof(int));
J
Jiri Olsa 已提交
3177 3178
		if (!sched->map.comp_cpus)
			return -1;
3179 3180
	}

3181 3182 3183 3184 3185 3186 3187 3188 3189 3190
	if (!sched->map.cpus_str)
		return 0;

	map = cpu_map__new(sched->map.cpus_str);
	if (!map) {
		pr_err("failed to get cpus map from %s\n", sched->map.cpus_str);
		return -1;
	}

	sched->map.cpus = map;
3191 3192 3193
	return 0;
}

J
Jiri Olsa 已提交
3194 3195 3196 3197 3198 3199 3200 3201 3202 3203 3204 3205 3206 3207 3208 3209 3210
static int setup_color_pids(struct perf_sched *sched)
{
	struct thread_map *map;

	if (!sched->map.color_pids_str)
		return 0;

	map = thread_map__new_by_tid_str(sched->map.color_pids_str);
	if (!map) {
		pr_err("failed to get thread map from %s\n", sched->map.color_pids_str);
		return -1;
	}

	sched->map.color_pids = map;
	return 0;
}

J
Jiri Olsa 已提交
3211 3212 3213 3214 3215 3216 3217 3218 3219 3220 3221 3222 3223 3224 3225 3226 3227
static int setup_color_cpus(struct perf_sched *sched)
{
	struct cpu_map *map;

	if (!sched->map.color_cpus_str)
		return 0;

	map = cpu_map__new(sched->map.color_cpus_str);
	if (!map) {
		pr_err("failed to get thread map from %s\n", sched->map.color_cpus_str);
		return -1;
	}

	sched->map.color_cpus = map;
	return 0;
}

3228
static int perf_sched__map(struct perf_sched *sched)
3229
{
3230 3231
	if (setup_map_cpus(sched))
		return -1;
3232

J
Jiri Olsa 已提交
3233 3234 3235
	if (setup_color_pids(sched))
		return -1;

J
Jiri Olsa 已提交
3236 3237 3238
	if (setup_color_cpus(sched))
		return -1;

3239
	setup_pager();
3240
	if (perf_sched__read_events(sched))
3241
		return -1;
3242
	print_bad_events(sched);
3243
	return 0;
3244 3245
}

3246
static int perf_sched__replay(struct perf_sched *sched)
3247 3248 3249
{
	unsigned long i;

3250 3251
	calibrate_run_measurement_overhead(sched);
	calibrate_sleep_measurement_overhead(sched);
3252

3253
	test_calibrations(sched);
3254

3255
	if (perf_sched__read_events(sched))
3256
		return -1;
3257

3258 3259 3260
	printf("nr_run_events:        %ld\n", sched->nr_run_events);
	printf("nr_sleep_events:      %ld\n", sched->nr_sleep_events);
	printf("nr_wakeup_events:     %ld\n", sched->nr_wakeup_events);
3261

3262 3263 3264 3265 3266
	if (sched->targetless_wakeups)
		printf("target-less wakeups:  %ld\n", sched->targetless_wakeups);
	if (sched->multitarget_wakeups)
		printf("multi-target wakeups: %ld\n", sched->multitarget_wakeups);
	if (sched->nr_run_events_optimized)
3267
		printf("run atoms optimized: %ld\n",
3268
			sched->nr_run_events_optimized);
3269

3270 3271
	print_task_traces(sched);
	add_cross_task_wakeups(sched);
3272

3273
	create_tasks(sched);
3274
	printf("------------------------------------------------------------\n");
3275 3276
	for (i = 0; i < sched->replay_repeat; i++)
		run_one_test(sched);
3277 3278

	return 0;
3279 3280
}

3281 3282
static void setup_sorting(struct perf_sched *sched, const struct option *options,
			  const char * const usage_msg[])
3283
{
3284
	char *tmp, *tok, *str = strdup(sched->sort_order);
3285 3286 3287

	for (tok = strtok_r(str, ", ", &tmp);
			tok; tok = strtok_r(NULL, ", ", &tmp)) {
3288
		if (sort_dimension__add(tok, &sched->sort_list) < 0) {
3289 3290
			usage_with_options_msg(usage_msg, options,
					"Unknown --sort key: `%s'", tok);
3291 3292 3293 3294 3295
		}
	}

	free(str);

3296
	sort_dimension__add("pid", &sched->cmp_pid);
3297 3298
}

3299 3300 3301 3302
static int __cmd_record(int argc, const char **argv)
{
	unsigned int rec_argc, i, j;
	const char **rec_argv;
3303 3304 3305 3306 3307 3308 3309 3310 3311 3312 3313 3314 3315
	const char * const record_args[] = {
		"record",
		"-a",
		"-R",
		"-m", "1024",
		"-c", "1",
		"-e", "sched:sched_switch",
		"-e", "sched:sched_stat_wait",
		"-e", "sched:sched_stat_sleep",
		"-e", "sched:sched_stat_iowait",
		"-e", "sched:sched_stat_runtime",
		"-e", "sched:sched_process_fork",
		"-e", "sched:sched_wakeup",
3316
		"-e", "sched:sched_wakeup_new",
3317 3318
		"-e", "sched:sched_migrate_task",
	};
3319 3320 3321 3322

	rec_argc = ARRAY_SIZE(record_args) + argc - 1;
	rec_argv = calloc(rec_argc + 1, sizeof(char *));

3323
	if (rec_argv == NULL)
3324 3325
		return -ENOMEM;

3326 3327 3328 3329 3330 3331 3332 3333
	for (i = 0; i < ARRAY_SIZE(record_args); i++)
		rec_argv[i] = strdup(record_args[i]);

	for (j = 1; j < (unsigned int)argc; j++, i++)
		rec_argv[i] = argv[j];

	BUG_ON(i != rec_argc);

3334
	return cmd_record(i, rec_argv);
3335 3336
}

3337
int cmd_sched(int argc, const char **argv)
I
Ingo Molnar 已提交
3338
{
3339 3340 3341 3342
	const char default_sort_order[] = "avg, max, switch, runtime";
	struct perf_sched sched = {
		.tool = {
			.sample		 = perf_sched__process_tracepoint_sample,
3343
			.comm		 = perf_sched__process_comm,
3344
			.namespaces	 = perf_event__process_namespaces,
3345 3346
			.lost		 = perf_event__process_lost,
			.fork		 = perf_sched__process_fork_event,
3347
			.ordered_events = true,
3348 3349 3350 3351 3352 3353 3354 3355 3356 3357
		},
		.cmp_pid	      = LIST_HEAD_INIT(sched.cmp_pid),
		.sort_list	      = LIST_HEAD_INIT(sched.sort_list),
		.start_work_mutex     = PTHREAD_MUTEX_INITIALIZER,
		.work_done_wait_mutex = PTHREAD_MUTEX_INITIALIZER,
		.sort_order	      = default_sort_order,
		.replay_repeat	      = 10,
		.profile_cpu	      = -1,
		.next_shortname1      = 'A',
		.next_shortname2      = '0',
3358
		.skip_merge           = 0,
3359 3360
		.show_callchain	      = 1,
		.max_stack            = 5,
3361
	};
3362 3363 3364 3365 3366 3367 3368
	const struct option sched_options[] = {
	OPT_STRING('i', "input", &input_name, "file",
		    "input file name"),
	OPT_INCR('v', "verbose", &verbose,
		    "be more verbose (show symbol address, etc)"),
	OPT_BOOLEAN('D', "dump-raw-trace", &dump_trace,
		    "dump raw trace in ASCII"),
3369
	OPT_BOOLEAN('f', "force", &sched.force, "don't complain, do it"),
3370 3371
	OPT_END()
	};
3372 3373 3374 3375 3376
	const struct option latency_options[] = {
	OPT_STRING('s', "sort", &sched.sort_order, "key[,key2...]",
		   "sort by key(s): runtime, switch, avg, max"),
	OPT_INTEGER('C', "CPU", &sched.profile_cpu,
		    "CPU to profile on"),
3377 3378
	OPT_BOOLEAN('p', "pids", &sched.skip_merge,
		    "latency stats per pid instead of per comm"),
3379
	OPT_PARENT(sched_options)
3380 3381 3382 3383
	};
	const struct option replay_options[] = {
	OPT_UINTEGER('r', "repeat", &sched.replay_repeat,
		     "repeat the workload replay N times (-1: infinite)"),
3384
	OPT_PARENT(sched_options)
3385
	};
3386 3387 3388
	const struct option map_options[] = {
	OPT_BOOLEAN(0, "compact", &sched.map.comp,
		    "map output in compact mode"),
J
Jiri Olsa 已提交
3389 3390
	OPT_STRING(0, "color-pids", &sched.map.color_pids_str, "pids",
		   "highlight given pids in map"),
J
Jiri Olsa 已提交
3391 3392
	OPT_STRING(0, "color-cpus", &sched.map.color_cpus_str, "cpus",
                    "highlight given CPUs in map"),
3393 3394
	OPT_STRING(0, "cpus", &sched.map.cpus_str, "cpus",
                    "display given CPUs in map"),
3395
	OPT_PARENT(sched_options)
3396
	};
3397 3398 3399 3400 3401
	const struct option timehist_options[] = {
	OPT_STRING('k', "vmlinux", &symbol_conf.vmlinux_name,
		   "file", "vmlinux pathname"),
	OPT_STRING(0, "kallsyms", &symbol_conf.kallsyms_name,
		   "file", "kallsyms pathname"),
3402 3403 3404 3405
	OPT_BOOLEAN('g', "call-graph", &sched.show_callchain,
		    "Display call chains if present (default on)"),
	OPT_UINTEGER(0, "max-stack", &sched.max_stack,
		   "Maximum number of functions to display backtrace."),
3406 3407
	OPT_STRING(0, "symfs", &symbol_conf.symfs, "directory",
		    "Look for files with symbols relative to this directory"),
3408 3409 3410 3411
	OPT_BOOLEAN('s', "summary", &sched.summary_only,
		    "Show only syscall summary with statistics"),
	OPT_BOOLEAN('S', "with-summary", &sched.summary,
		    "Show all syscalls and summary with statistics"),
3412
	OPT_BOOLEAN('w', "wakeups", &sched.show_wakeups, "Show wakeup events"),
3413
	OPT_BOOLEAN('n', "next", &sched.show_next, "Show next task"),
3414
	OPT_BOOLEAN('M', "migrations", &sched.show_migrations, "Show migration events"),
3415
	OPT_BOOLEAN('V', "cpu-visual", &sched.show_cpu_visual, "Add CPU visual"),
3416
	OPT_BOOLEAN('I', "idle-hist", &sched.idle_hist, "Show idle events only"),
3417 3418
	OPT_STRING(0, "time", &sched.time_str, "str",
		   "Time span for analysis (start,stop)"),
3419
	OPT_BOOLEAN(0, "state", &sched.show_state, "Show task state when sched-out"),
3420 3421 3422 3423
	OPT_STRING('p', "pid", &symbol_conf.pid_list_str, "pid[,pid...]",
		   "analyze events only for given process id(s)"),
	OPT_STRING('t', "tid", &symbol_conf.tid_list_str, "tid[,tid...]",
		   "analyze events only for given thread id(s)"),
3424 3425 3426
	OPT_PARENT(sched_options)
	};

3427 3428 3429 3430 3431 3432 3433 3434
	const char * const latency_usage[] = {
		"perf sched latency [<options>]",
		NULL
	};
	const char * const replay_usage[] = {
		"perf sched replay [<options>]",
		NULL
	};
3435 3436 3437 3438
	const char * const map_usage[] = {
		"perf sched map [<options>]",
		NULL
	};
3439 3440 3441 3442
	const char * const timehist_usage[] = {
		"perf sched timehist [<options>]",
		NULL
	};
3443
	const char *const sched_subcommands[] = { "record", "latency", "map",
3444 3445
						  "replay", "script",
						  "timehist", NULL };
3446 3447
	const char *sched_usage[] = {
		NULL,
3448 3449 3450 3451 3452 3453 3454 3455 3456 3457 3458 3459 3460 3461 3462 3463
		NULL
	};
	struct trace_sched_handler lat_ops  = {
		.wakeup_event	    = latency_wakeup_event,
		.switch_event	    = latency_switch_event,
		.runtime_event	    = latency_runtime_event,
		.migrate_task_event = latency_migrate_task_event,
	};
	struct trace_sched_handler map_ops  = {
		.switch_event	    = map_switch_event,
	};
	struct trace_sched_handler replay_ops  = {
		.wakeup_event	    = replay_wakeup_event,
		.switch_event	    = replay_switch_event,
		.fork_event	    = replay_fork_event,
	};
A
Adrian Hunter 已提交
3464 3465 3466 3467
	unsigned int i;

	for (i = 0; i < ARRAY_SIZE(sched.curr_pid); i++)
		sched.curr_pid[i] = -1;
3468

3469 3470
	argc = parse_options_subcommand(argc, argv, sched_options, sched_subcommands,
					sched_usage, PARSE_OPT_STOP_AT_NON_OPTION);
3471 3472
	if (!argc)
		usage_with_options(sched_usage, sched_options);
I
Ingo Molnar 已提交
3473

3474
	/*
3475
	 * Aliased to 'perf script' for now:
3476
	 */
3477
	if (!strcmp(argv[0], "script"))
3478
		return cmd_script(argc, argv);
3479

3480 3481 3482
	if (!strncmp(argv[0], "rec", 3)) {
		return __cmd_record(argc, argv);
	} else if (!strncmp(argv[0], "lat", 3)) {
3483
		sched.tp_handler = &lat_ops;
3484 3485 3486 3487 3488
		if (argc > 1) {
			argc = parse_options(argc, argv, latency_options, latency_usage, 0);
			if (argc)
				usage_with_options(latency_usage, latency_options);
		}
3489 3490
		setup_sorting(&sched, latency_options, latency_usage);
		return perf_sched__lat(&sched);
3491
	} else if (!strcmp(argv[0], "map")) {
3492
		if (argc) {
J
Jiri Olsa 已提交
3493
			argc = parse_options(argc, argv, map_options, map_usage, 0);
3494 3495 3496
			if (argc)
				usage_with_options(map_usage, map_options);
		}
3497 3498 3499
		sched.tp_handler = &map_ops;
		setup_sorting(&sched, latency_options, latency_usage);
		return perf_sched__map(&sched);
3500
	} else if (!strncmp(argv[0], "rep", 3)) {
3501
		sched.tp_handler = &replay_ops;
3502 3503 3504 3505 3506
		if (argc) {
			argc = parse_options(argc, argv, replay_options, replay_usage, 0);
			if (argc)
				usage_with_options(replay_usage, replay_options);
		}
3507
		return perf_sched__replay(&sched);
3508 3509 3510 3511 3512 3513 3514
	} else if (!strcmp(argv[0], "timehist")) {
		if (argc) {
			argc = parse_options(argc, argv, timehist_options,
					     timehist_usage, 0);
			if (argc)
				usage_with_options(timehist_usage, timehist_options);
		}
3515 3516 3517
		if ((sched.show_wakeups || sched.show_next) &&
		    sched.summary_only) {
			pr_err(" Error: -s and -[n|w] are mutually exclusive.\n");
3518
			parse_options_usage(timehist_usage, timehist_options, "s", true);
3519 3520 3521 3522
			if (sched.show_wakeups)
				parse_options_usage(NULL, timehist_options, "w", true);
			if (sched.show_next)
				parse_options_usage(NULL, timehist_options, "n", true);
3523 3524 3525
			return -EINVAL;
		}

3526
		return perf_sched__timehist(&sched);
3527 3528 3529 3530
	} else {
		usage_with_options(sched_usage, sched_options);
	}

I
Ingo Molnar 已提交
3531
	return 0;
I
Ingo Molnar 已提交
3532
}