builtin-sched.c 86.0 KB
Newer Older
I
Ingo Molnar 已提交
1
#include "builtin.h"
2
#include "perf.h"
I
Ingo Molnar 已提交
3 4

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

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

#include "util/debug.h"

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

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

38 39
#include "sane_ctype.h"

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

46
struct sched_atom;
I
Ingo Molnar 已提交
47

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

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

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

60 61 62 63 64 65 66 67 68 69
	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,
70
	SCHED_EVENT_MIGRATION,
71 72
};

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

83
#define TASK_STATE_TO_CHAR_STR "RSDTtZXxKWP"
84

85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100
/* 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

101 102 103 104 105 106 107 108 109 110
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;
111
	u64			sched_out_time;
112 113 114 115 116
	u64			wake_up_time;
	u64			sched_in_time;
	u64			runtime;
};

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

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

131
struct perf_sched;
132

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

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

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

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

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

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

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

168 169 170 171
struct perf_sched {
	struct perf_tool tool;
	const char	 *sort_order;
	unsigned long	 nr_tasks;
172
	struct task_desc **pid_to_task;
173 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
	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];
215
	struct rb_root	 atom_root, sorted_atom_root, merged_atom_root;
216
	struct list_head sort_list, cmp_pid;
217
	bool force;
218
	bool skip_merge;
219
	struct perf_sched_map map;
220 221 222 223

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

238 239 240 241
/* per thread run time data */
struct thread_runtime {
	u64 last_time;      /* time of previous sched in/out event */
	u64 dt_run;         /* run time */
242 243 244
	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) */
245 246 247 248 249
	u64 dt_delay;       /* time between wakeup and sched-in */
	u64 ready_to_run;   /* time of wakeup */

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

255
	int last_state;
256
	u64 migrations;
257 258 259 260 261 262 263 264
};

/* 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 */
};

265 266 267 268 269 270 271 272 273
/* 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;
};

274 275 276 277 278
/* track idle times per cpu */
static struct thread **idle_threads;
static int idle_max_cpu;
static char idle_comm[] = "<idle>";

279
static u64 get_nsecs(void)
I
Ingo Molnar 已提交
280 281 282 283 284
{
	struct timespec ts;

	clock_gettime(CLOCK_MONOTONIC, &ts);

285
	return ts.tv_sec * NSEC_PER_SEC + ts.tv_nsec;
I
Ingo Molnar 已提交
286 287
}

288
static void burn_nsecs(struct perf_sched *sched, u64 nsecs)
I
Ingo Molnar 已提交
289
{
290
	u64 T0 = get_nsecs(), T1;
I
Ingo Molnar 已提交
291 292 293

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

297
static void sleep_nsecs(u64 nsecs)
I
Ingo Molnar 已提交
298 299 300 301 302 303 304 305 306
{
	struct timespec ts;

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

	nanosleep(&ts, NULL);
}

307
static void calibrate_run_measurement_overhead(struct perf_sched *sched)
I
Ingo Molnar 已提交
308
{
309
	u64 T0, T1, delta, min_delta = NSEC_PER_SEC;
I
Ingo Molnar 已提交
310 311 312 313
	int i;

	for (i = 0; i < 10; i++) {
		T0 = get_nsecs();
314
		burn_nsecs(sched, 0);
I
Ingo Molnar 已提交
315 316 317 318
		T1 = get_nsecs();
		delta = T1-T0;
		min_delta = min(min_delta, delta);
	}
319
	sched->run_measurement_overhead = min_delta;
I
Ingo Molnar 已提交
320

321
	printf("run measurement overhead: %" PRIu64 " nsecs\n", min_delta);
I
Ingo Molnar 已提交
322 323
}

324
static void calibrate_sleep_measurement_overhead(struct perf_sched *sched)
I
Ingo Molnar 已提交
325
{
326
	u64 T0, T1, delta, min_delta = NSEC_PER_SEC;
I
Ingo Molnar 已提交
327 328 329 330 331 332 333 334 335 336
	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;
337
	sched->sleep_measurement_overhead = min_delta;
I
Ingo Molnar 已提交
338

339
	printf("sleep measurement overhead: %" PRIu64 " nsecs\n", min_delta);
I
Ingo Molnar 已提交
340 341
}

342
static struct sched_atom *
343
get_new_event(struct task_desc *task, u64 timestamp)
I
Ingo Molnar 已提交
344
{
345
	struct sched_atom *event = zalloc(sizeof(*event));
I
Ingo Molnar 已提交
346 347 348 349 350 351 352
	unsigned long idx = task->nr_events;
	size_t size;

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

	task->nr_events++;
353 354 355
	size = sizeof(struct sched_atom *) * task->nr_events;
	task->atoms = realloc(task->atoms, size);
	BUG_ON(!task->atoms);
I
Ingo Molnar 已提交
356

357
	task->atoms[idx] = event;
I
Ingo Molnar 已提交
358 359 360 361

	return event;
}

362
static struct sched_atom *last_event(struct task_desc *task)
I
Ingo Molnar 已提交
363 364 365 366
{
	if (!task->nr_events)
		return NULL;

367
	return task->atoms[task->nr_events - 1];
I
Ingo Molnar 已提交
368 369
}

370 371
static void add_sched_event_run(struct perf_sched *sched, struct task_desc *task,
				u64 timestamp, u64 duration)
I
Ingo Molnar 已提交
372
{
373
	struct sched_atom *event, *curr_event = last_event(task);
I
Ingo Molnar 已提交
374 375

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

	event = get_new_event(task, timestamp);

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

390
	sched->nr_run_events++;
I
Ingo Molnar 已提交
391 392
}

393 394
static void add_sched_event_wakeup(struct perf_sched *sched, struct task_desc *task,
				   u64 timestamp, struct task_desc *wakee)
I
Ingo Molnar 已提交
395
{
396
	struct sched_atom *event, *wakee_event;
I
Ingo Molnar 已提交
397 398 399 400 401 402 403

	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) {
404
		sched->targetless_wakeups++;
I
Ingo Molnar 已提交
405 406 407
		return;
	}
	if (wakee_event->wait_sem) {
408
		sched->multitarget_wakeups++;
I
Ingo Molnar 已提交
409 410 411
		return;
	}

412
	wakee_event->wait_sem = zalloc(sizeof(*wakee_event->wait_sem));
I
Ingo Molnar 已提交
413 414 415 416
	sem_init(wakee_event->wait_sem, 0, 0);
	wakee_event->specific_wait = 1;
	event->wait_sem = wakee_event->wait_sem;

417
	sched->nr_wakeup_events++;
I
Ingo Molnar 已提交
418 419
}

420 421
static void add_sched_event_sleep(struct perf_sched *sched, struct task_desc *task,
				  u64 timestamp, u64 task_state __maybe_unused)
I
Ingo Molnar 已提交
422
{
423
	struct sched_atom *event = get_new_event(task, timestamp);
I
Ingo Molnar 已提交
424 425 426

	event->type = SCHED_EVENT_SLEEP;

427
	sched->nr_sleep_events++;
I
Ingo Molnar 已提交
428 429
}

430 431
static struct task_desc *register_pid(struct perf_sched *sched,
				      unsigned long pid, const char *comm)
I
Ingo Molnar 已提交
432 433
{
	struct task_desc *task;
434
	static int pid_max;
I
Ingo Molnar 已提交
435

436 437 438 439 440
	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);
	}
441 442 443 444 445 446
	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 已提交
447

448
	task = sched->pid_to_task[pid];
I
Ingo Molnar 已提交
449 450 451 452

	if (task)
		return task;

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

463 464
	sched->pid_to_task[pid] = task;
	sched->nr_tasks++;
465
	sched->tasks = realloc(sched->tasks, sched->nr_tasks * sizeof(struct task_desc *));
466 467
	BUG_ON(!sched->tasks);
	sched->tasks[task->nr] = task;
I
Ingo Molnar 已提交
468

469
	if (verbose > 0)
470
		printf("registered task #%ld, PID %ld (%s)\n", sched->nr_tasks, pid, comm);
I
Ingo Molnar 已提交
471 472 473 474 475

	return task;
}


476
static void print_task_traces(struct perf_sched *sched)
I
Ingo Molnar 已提交
477 478 479 480
{
	struct task_desc *task;
	unsigned long i;

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

488
static void add_cross_task_wakeups(struct perf_sched *sched)
I
Ingo Molnar 已提交
489 490 491 492
{
	struct task_desc *task1, *task2;
	unsigned long i, j;

493 494
	for (i = 0; i < sched->nr_tasks; i++) {
		task1 = sched->tasks[i];
I
Ingo Molnar 已提交
495
		j = i + 1;
496
		if (j == sched->nr_tasks)
I
Ingo Molnar 已提交
497
			j = 0;
498 499
		task2 = sched->tasks[j];
		add_sched_event_wakeup(sched, task1, 0, task2);
I
Ingo Molnar 已提交
500 501 502
	}
}

503 504
static void perf_sched__process_event(struct perf_sched *sched,
				      struct sched_atom *atom)
I
Ingo Molnar 已提交
505 506 507
{
	int ret = 0;

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

529
static u64 get_cpu_usage_nsec_parent(void)
I
Ingo Molnar 已提交
530 531
{
	struct rusage ru;
532
	u64 sum;
I
Ingo Molnar 已提交
533 534 535 536 537
	int err;

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

538 539
	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 已提交
540 541 542 543

	return sum;
}

544
static int self_open_counters(struct perf_sched *sched, unsigned long cur_task)
I
Ingo Molnar 已提交
545
{
546
	struct perf_event_attr attr;
547
	char sbuf[STRERR_BUFSIZE], info[STRERR_BUFSIZE];
548
	int fd;
549 550
	struct rlimit limit;
	bool need_privilege = false;
I
Ingo Molnar 已提交
551

552
	memset(&attr, 0, sizeof(attr));
I
Ingo Molnar 已提交
553

554 555
	attr.type = PERF_TYPE_SOFTWARE;
	attr.config = PERF_COUNT_SW_TASK_CLOCK;
I
Ingo Molnar 已提交
556

557
force_again:
558 559
	fd = sys_perf_event_open(&attr, 0, -1, -1,
				 perf_event_open_cloexec_flag());
560

561
	if (fd < 0) {
562 563 564 565 566 567 568 569 570 571 572 573 574 575 576 577
		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");
		}
578
		pr_err("Error: sys_perf_event_open() syscall returned "
579
		       "with %d (%s)\n%s", fd,
580
		       str_error_r(errno, sbuf, sizeof(sbuf)), info);
581 582
		exit(EXIT_FAILURE);
	}
583 584 585 586 587 588 589 590 591 592 593 594
	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 已提交
595 596
}

597 598 599
struct sched_thread_parms {
	struct task_desc  *task;
	struct perf_sched *sched;
600
	int fd;
601 602
};

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

613
	zfree(&parms);
614

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

627
	cpu_usage_0 = get_cpu_usage_nsec_self(fd);
I
Ingo Molnar 已提交
628 629 630

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

634
	cpu_usage_1 = get_cpu_usage_nsec_self(fd);
I
Ingo Molnar 已提交
635 636 637 638
	this_task->cpu_usage = cpu_usage_1 - cpu_usage_0;
	ret = sem_post(&this_task->work_done_sem);
	BUG_ON(ret);

639
	ret = pthread_mutex_lock(&sched->work_done_wait_mutex);
I
Ingo Molnar 已提交
640
	BUG_ON(ret);
641
	ret = pthread_mutex_unlock(&sched->work_done_wait_mutex);
I
Ingo Molnar 已提交
642 643 644 645 646
	BUG_ON(ret);

	goto again;
}

647
static void create_tasks(struct perf_sched *sched)
I
Ingo Molnar 已提交
648 649 650 651 652 653 654 655
{
	struct task_desc *task;
	pthread_attr_t attr;
	unsigned long i;
	int err;

	err = pthread_attr_init(&attr);
	BUG_ON(err);
656 657
	err = pthread_attr_setstacksize(&attr,
			(size_t) max(16 * 1024, PTHREAD_STACK_MIN));
I
Ingo Molnar 已提交
658
	BUG_ON(err);
659
	err = pthread_mutex_lock(&sched->start_work_mutex);
I
Ingo Molnar 已提交
660
	BUG_ON(err);
661
	err = pthread_mutex_lock(&sched->work_done_wait_mutex);
I
Ingo Molnar 已提交
662
	BUG_ON(err);
663 664 665 666 667
	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;
668
		parms->fd = self_open_counters(sched, i);
I
Ingo Molnar 已提交
669 670 671 672
		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;
673
		err = pthread_create(&task->thread, &attr, thread_func, parms);
I
Ingo Molnar 已提交
674 675 676 677
		BUG_ON(err);
	}
}

678
static void wait_for_tasks(struct perf_sched *sched)
I
Ingo Molnar 已提交
679
{
680
	u64 cpu_usage_0, cpu_usage_1;
I
Ingo Molnar 已提交
681 682 683
	struct task_desc *task;
	unsigned long i, ret;

684 685 686
	sched->start_time = get_nsecs();
	sched->cpu_usage = 0;
	pthread_mutex_unlock(&sched->work_done_wait_mutex);
I
Ingo Molnar 已提交
687

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

	cpu_usage_0 = get_cpu_usage_nsec_parent();

699
	pthread_mutex_unlock(&sched->start_work_mutex);
I
Ingo Molnar 已提交
700

701 702
	for (i = 0; i < sched->nr_tasks; i++) {
		task = sched->tasks[i];
I
Ingo Molnar 已提交
703 704 705
		ret = sem_wait(&task->work_done_sem);
		BUG_ON(ret);
		sem_init(&task->work_done_sem, 0, 0);
706
		sched->cpu_usage += task->cpu_usage;
I
Ingo Molnar 已提交
707 708 709 710
		task->cpu_usage = 0;
	}

	cpu_usage_1 = get_cpu_usage_nsec_parent();
711 712
	if (!sched->runavg_cpu_usage)
		sched->runavg_cpu_usage = sched->cpu_usage;
713
	sched->runavg_cpu_usage = (sched->runavg_cpu_usage * (sched->replay_repeat - 1) + sched->cpu_usage) / sched->replay_repeat;
I
Ingo Molnar 已提交
714

715 716 717
	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;
718 719
	sched->runavg_parent_cpu_usage = (sched->runavg_parent_cpu_usage * (sched->replay_repeat - 1) +
					 sched->parent_cpu_usage)/sched->replay_repeat;
I
Ingo Molnar 已提交
720

721
	ret = pthread_mutex_lock(&sched->start_work_mutex);
I
Ingo Molnar 已提交
722 723
	BUG_ON(ret);

724 725
	for (i = 0; i < sched->nr_tasks; i++) {
		task = sched->tasks[i];
I
Ingo Molnar 已提交
726 727 728 729 730
		sem_init(&task->sleep_sem, 0, 0);
		task->curr_event = 0;
	}
}

731
static void run_one_test(struct perf_sched *sched)
I
Ingo Molnar 已提交
732
{
K
Kyle McMartin 已提交
733
	u64 T0, T1, delta, avg_delta, fluct;
I
Ingo Molnar 已提交
734 735

	T0 = get_nsecs();
736
	wait_for_tasks(sched);
I
Ingo Molnar 已提交
737 738 739
	T1 = get_nsecs();

	delta = T1 - T0;
740 741
	sched->sum_runtime += delta;
	sched->nr_runs++;
I
Ingo Molnar 已提交
742

743
	avg_delta = sched->sum_runtime / sched->nr_runs;
I
Ingo Molnar 已提交
744 745 746 747
	if (delta < avg_delta)
		fluct = avg_delta - delta;
	else
		fluct = delta - avg_delta;
748 749 750
	sched->sum_fluct += fluct;
	if (!sched->run_avg)
		sched->run_avg = delta;
751
	sched->run_avg = (sched->run_avg * (sched->replay_repeat - 1) + delta) / sched->replay_repeat;
I
Ingo Molnar 已提交
752

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

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

I
Ingo Molnar 已提交
757
	printf("cpu: %0.2f / %0.2f",
758
		(double)sched->cpu_usage / NSEC_PER_MSEC, (double)sched->runavg_cpu_usage / NSEC_PER_MSEC);
I
Ingo Molnar 已提交
759 760 761

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

I
Ingo Molnar 已提交
770
	printf("\n");
I
Ingo Molnar 已提交
771

772 773 774
	if (sched->nr_sleep_corrections)
		printf(" (%ld sleep corrections)\n", sched->nr_sleep_corrections);
	sched->nr_sleep_corrections = 0;
I
Ingo Molnar 已提交
775 776
}

777
static void test_calibrations(struct perf_sched *sched)
I
Ingo Molnar 已提交
778
{
779
	u64 T0, T1;
I
Ingo Molnar 已提交
780 781

	T0 = get_nsecs();
782
	burn_nsecs(sched, NSEC_PER_MSEC);
I
Ingo Molnar 已提交
783 784
	T1 = get_nsecs();

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

	T0 = get_nsecs();
788
	sleep_nsecs(NSEC_PER_MSEC);
I
Ingo Molnar 已提交
789 790
	T1 = get_nsecs();

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

794
static int
795
replay_wakeup_event(struct perf_sched *sched,
796 797
		    struct perf_evsel *evsel, struct perf_sample *sample,
		    struct machine *machine __maybe_unused)
798
{
799 800
	const char *comm = perf_evsel__strval(evsel, sample, "comm");
	const u32 pid	 = perf_evsel__intval(evsel, sample, "pid");
801
	struct task_desc *waker, *wakee;
802

803
	if (verbose > 0) {
804
		printf("sched_wakeup event %p\n", evsel);
805

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

809
	waker = register_pid(sched, sample->tid, "<unknown>");
810
	wakee = register_pid(sched, pid, comm);
811

812
	add_sched_event_wakeup(sched, waker, sample->time, wakee);
813
	return 0;
I
Ingo Molnar 已提交
814 815
}

816 817 818 819
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 已提交
820
{
821 822 823 824 825
	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");
826
	struct task_desc *prev, __maybe_unused *next;
827 828
	u64 timestamp0, timestamp = sample->time;
	int cpu = sample->cpu;
829 830
	s64 delta;

831
	if (verbose > 0)
832
		printf("sched_switch event %p\n", evsel);
I
Ingo Molnar 已提交
833

834
	if (cpu >= MAX_CPUS || cpu < 0)
835
		return 0;
836

837
	timestamp0 = sched->cpu_last_switched[cpu];
838 839 840 841 842
	if (timestamp0)
		delta = timestamp - timestamp0;
	else
		delta = 0;

843
	if (delta < 0) {
844
		pr_err("hm, delta: %" PRIu64 " < 0 ?\n", delta);
845 846
		return -1;
	}
847

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

851 852
	prev = register_pid(sched, prev_pid, prev_comm);
	next = register_pid(sched, next_pid, next_comm);
853

854
	sched->cpu_last_switched[cpu] = timestamp;
855

856
	add_sched_event_run(sched, prev, timestamp, delta);
857
	add_sched_event_sleep(sched, prev, timestamp, prev_state);
858 859

	return 0;
860 861
}

862 863 864
static int replay_fork_event(struct perf_sched *sched,
			     union perf_event *event,
			     struct machine *machine)
865
{
866 867
	struct thread *child, *parent;

868 869 870 871
	child = machine__findnew_thread(machine, event->fork.pid,
					event->fork.tid);
	parent = machine__findnew_thread(machine, event->fork.ppid,
					 event->fork.ptid);
872 873 874 875

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

879
	if (verbose > 0) {
880
		printf("fork event\n");
881 882
		printf("... parent: %s/%d\n", thread__comm_str(parent), parent->tid);
		printf("...  child: %s/%d\n", thread__comm_str(child), child->tid);
883
	}
884

885 886
	register_pid(sched, parent->tid, thread__comm_str(parent));
	register_pid(sched, child->tid, thread__comm_str(child));
887 888 889
out_put:
	thread__put(child);
	thread__put(parent);
890
	return 0;
891
}
892

893 894
struct sort_dimension {
	const char		*name;
895
	sort_fn_t		cmp;
896 897 898
	struct list_head	list;
};

899
static int
900
thread_lat_cmp(struct list_head *list, struct work_atoms *l, struct work_atoms *r)
901 902 903 904
{
	struct sort_dimension *sort;
	int ret = 0;

905 906
	BUG_ON(list_empty(list));

907 908 909 910 911 912 913 914 915
	list_for_each_entry(sort, list, list) {
		ret = sort->cmp(l, r);
		if (ret)
			return ret;
	}

	return ret;
}

916
static struct work_atoms *
917 918 919 920
thread_atoms_search(struct rb_root *root, struct thread *thread,
			 struct list_head *sort_list)
{
	struct rb_node *node = root->rb_node;
921
	struct work_atoms key = { .thread = thread };
922 923

	while (node) {
924
		struct work_atoms *atoms;
925 926
		int cmp;

927
		atoms = container_of(node, struct work_atoms, node);
928 929 930 931 932 933 934 935 936 937 938 939 940 941

		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;
}

942
static void
943
__thread_latency_insert(struct rb_root *root, struct work_atoms *data,
944
			 struct list_head *sort_list)
945 946 947 948
{
	struct rb_node **new = &(root->rb_node), *parent = NULL;

	while (*new) {
949
		struct work_atoms *this;
950
		int cmp;
951

952
		this = container_of(*new, struct work_atoms, node);
953
		parent = *new;
954 955 956 957

		cmp = thread_lat_cmp(sort_list, data, this);

		if (cmp > 0)
958 959
			new = &((*new)->rb_left);
		else
960
			new = &((*new)->rb_right);
961 962 963 964 965 966
	}

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

967
static int thread_atoms_insert(struct perf_sched *sched, struct thread *thread)
968
{
969
	struct work_atoms *atoms = zalloc(sizeof(*atoms));
970 971 972 973
	if (!atoms) {
		pr_err("No memory at %s\n", __func__);
		return -1;
	}
974

975
	atoms->thread = thread__get(thread);
976
	INIT_LIST_HEAD(&atoms->work_list);
977
	__thread_latency_insert(&sched->atom_root, atoms, &sched->cmp_pid);
978
	return 0;
979 980
}

981
static char sched_out_state(u64 prev_state)
982 983 984
{
	const char *str = TASK_STATE_TO_CHAR_STR;

985
	return str[prev_state];
986 987
}

988
static int
989 990 991
add_sched_out_event(struct work_atoms *atoms,
		    char run_state,
		    u64 timestamp)
992
{
993
	struct work_atom *atom = zalloc(sizeof(*atom));
994 995 996 997
	if (!atom) {
		pr_err("Non memory at %s", __func__);
		return -1;
	}
998

999 1000
	atom->sched_out_time = timestamp;

1001
	if (run_state == 'R') {
1002
		atom->state = THREAD_WAIT_CPU;
1003
		atom->wake_up_time = atom->sched_out_time;
1004 1005
	}

1006
	list_add_tail(&atom->list, &atoms->work_list);
1007
	return 0;
1008 1009 1010
}

static void
1011 1012
add_runtime_event(struct work_atoms *atoms, u64 delta,
		  u64 timestamp __maybe_unused)
1013 1014 1015 1016 1017 1018 1019 1020 1021 1022 1023 1024 1025
{
	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)
1026
{
1027
	struct work_atom *atom;
1028
	u64 delta;
1029

1030
	if (list_empty(&atoms->work_list))
1031 1032
		return;

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

1035
	if (atom->state != THREAD_WAIT_CPU)
1036 1037
		return;

1038 1039
	if (timestamp < atom->wake_up_time) {
		atom->state = THREAD_IGNORE;
1040 1041 1042
		return;
	}

1043 1044
	atom->state = THREAD_SCHED_IN;
	atom->sched_in_time = timestamp;
1045

1046
	delta = atom->sched_in_time - atom->wake_up_time;
1047
	atoms->total_lat += delta;
1048
	if (delta > atoms->max_lat) {
1049
		atoms->max_lat = delta;
1050 1051
		atoms->max_lat_at = timestamp;
	}
1052
	atoms->nb_atoms++;
1053 1054
}

1055 1056 1057 1058
static int latency_switch_event(struct perf_sched *sched,
				struct perf_evsel *evsel,
				struct perf_sample *sample,
				struct machine *machine)
1059
{
1060 1061 1062
	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");
1063
	struct work_atoms *out_events, *in_events;
1064
	struct thread *sched_out, *sched_in;
1065
	u64 timestamp0, timestamp = sample->time;
1066
	int cpu = sample->cpu, err = -1;
I
Ingo Molnar 已提交
1067 1068
	s64 delta;

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

1071 1072
	timestamp0 = sched->cpu_last_switched[cpu];
	sched->cpu_last_switched[cpu] = timestamp;
I
Ingo Molnar 已提交
1073 1074 1075 1076 1077
	if (timestamp0)
		delta = timestamp - timestamp0;
	else
		delta = 0;

1078 1079 1080 1081
	if (delta < 0) {
		pr_err("hm, delta: %" PRIu64 " < 0 ?\n", delta);
		return -1;
	}
1082

1083 1084
	sched_out = machine__findnew_thread(machine, -1, prev_pid);
	sched_in = machine__findnew_thread(machine, -1, next_pid);
1085 1086
	if (sched_out == NULL || sched_in == NULL)
		goto out_put;
1087

1088
	out_events = thread_atoms_search(&sched->atom_root, sched_out, &sched->cmp_pid);
1089
	if (!out_events) {
1090
		if (thread_atoms_insert(sched, sched_out))
1091
			goto out_put;
1092
		out_events = thread_atoms_search(&sched->atom_root, sched_out, &sched->cmp_pid);
1093 1094
		if (!out_events) {
			pr_err("out-event: Internal tree error");
1095
			goto out_put;
1096
		}
1097
	}
1098
	if (add_sched_out_event(out_events, sched_out_state(prev_state), timestamp))
1099
		return -1;
1100

1101
	in_events = thread_atoms_search(&sched->atom_root, sched_in, &sched->cmp_pid);
1102
	if (!in_events) {
1103
		if (thread_atoms_insert(sched, sched_in))
1104
			goto out_put;
1105
		in_events = thread_atoms_search(&sched->atom_root, sched_in, &sched->cmp_pid);
1106 1107
		if (!in_events) {
			pr_err("in-event: Internal tree error");
1108
			goto out_put;
1109
		}
1110 1111 1112 1113
		/*
		 * Take came in we have not heard about yet,
		 * add in an initial atom in runnable state:
		 */
1114
		if (add_sched_out_event(in_events, 'R', timestamp))
1115
			goto out_put;
1116
	}
1117
	add_sched_in_event(in_events, timestamp);
1118 1119 1120 1121 1122
	err = 0;
out_put:
	thread__put(sched_out);
	thread__put(sched_in);
	return err;
1123
}
1124

1125 1126 1127 1128
static int latency_runtime_event(struct perf_sched *sched,
				 struct perf_evsel *evsel,
				 struct perf_sample *sample,
				 struct machine *machine)
1129
{
1130 1131
	const u32 pid	   = perf_evsel__intval(evsel, sample, "pid");
	const u64 runtime  = perf_evsel__intval(evsel, sample, "runtime");
1132
	struct thread *thread = machine__findnew_thread(machine, -1, pid);
1133
	struct work_atoms *atoms = thread_atoms_search(&sched->atom_root, thread, &sched->cmp_pid);
1134
	u64 timestamp = sample->time;
1135 1136 1137 1138
	int cpu = sample->cpu, err = -1;

	if (thread == NULL)
		return -1;
1139 1140 1141

	BUG_ON(cpu >= MAX_CPUS || cpu < 0);
	if (!atoms) {
1142
		if (thread_atoms_insert(sched, thread))
1143
			goto out_put;
1144
		atoms = thread_atoms_search(&sched->atom_root, thread, &sched->cmp_pid);
1145
		if (!atoms) {
1146
			pr_err("in-event: Internal tree error");
1147
			goto out_put;
1148 1149
		}
		if (add_sched_out_event(atoms, 'R', timestamp))
1150
			goto out_put;
1151 1152
	}

1153
	add_runtime_event(atoms, runtime, timestamp);
1154 1155 1156 1157
	err = 0;
out_put:
	thread__put(thread);
	return err;
1158 1159
}

1160 1161 1162 1163
static int latency_wakeup_event(struct perf_sched *sched,
				struct perf_evsel *evsel,
				struct perf_sample *sample,
				struct machine *machine)
1164
{
1165
	const u32 pid	  = perf_evsel__intval(evsel, sample, "pid");
1166
	struct work_atoms *atoms;
1167
	struct work_atom *atom;
1168
	struct thread *wakee;
1169
	u64 timestamp = sample->time;
1170
	int err = -1;
1171

1172
	wakee = machine__findnew_thread(machine, -1, pid);
1173 1174
	if (wakee == NULL)
		return -1;
1175
	atoms = thread_atoms_search(&sched->atom_root, wakee, &sched->cmp_pid);
1176
	if (!atoms) {
1177
		if (thread_atoms_insert(sched, wakee))
1178
			goto out_put;
1179
		atoms = thread_atoms_search(&sched->atom_root, wakee, &sched->cmp_pid);
1180
		if (!atoms) {
1181
			pr_err("wakeup-event: Internal tree error");
1182
			goto out_put;
1183 1184
		}
		if (add_sched_out_event(atoms, 'S', timestamp))
1185
			goto out_put;
1186 1187
	}

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

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

1192
	/*
1193 1194 1195 1196 1197 1198
	 * 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.
	 *
1199 1200
	 * You WILL be missing events if you've recorded only
	 * one CPU, or are only looking at only one, so don't
1201
	 * skip in this case.
1202
	 */
1203
	if (sched->profile_cpu == -1 && atom->state != THREAD_SLEEPING)
1204
		goto out_ok;
1205

1206
	sched->nr_timestamps++;
1207
	if (atom->sched_out_time > timestamp) {
1208
		sched->nr_unordered_timestamps++;
1209
		goto out_ok;
1210
	}
1211

1212 1213
	atom->state = THREAD_WAIT_CPU;
	atom->wake_up_time = timestamp;
1214 1215 1216 1217 1218
out_ok:
	err = 0;
out_put:
	thread__put(wakee);
	return err;
1219 1220
}

1221 1222 1223 1224
static int latency_migrate_task_event(struct perf_sched *sched,
				      struct perf_evsel *evsel,
				      struct perf_sample *sample,
				      struct machine *machine)
1225
{
1226
	const u32 pid = perf_evsel__intval(evsel, sample, "pid");
1227
	u64 timestamp = sample->time;
1228 1229 1230
	struct work_atoms *atoms;
	struct work_atom *atom;
	struct thread *migrant;
1231
	int err = -1;
1232 1233 1234 1235

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

1239
	migrant = machine__findnew_thread(machine, -1, pid);
1240 1241
	if (migrant == NULL)
		return -1;
1242
	atoms = thread_atoms_search(&sched->atom_root, migrant, &sched->cmp_pid);
1243
	if (!atoms) {
1244
		if (thread_atoms_insert(sched, migrant))
1245
			goto out_put;
1246
		register_pid(sched, migrant->tid, thread__comm_str(migrant));
1247
		atoms = thread_atoms_search(&sched->atom_root, migrant, &sched->cmp_pid);
1248
		if (!atoms) {
1249
			pr_err("migration-event: Internal tree error");
1250
			goto out_put;
1251 1252
		}
		if (add_sched_out_event(atoms, 'R', timestamp))
1253
			goto out_put;
1254 1255 1256 1257 1258 1259 1260
	}

	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;

1261
	sched->nr_timestamps++;
1262 1263

	if (atom->sched_out_time > timestamp)
1264
		sched->nr_unordered_timestamps++;
1265 1266 1267 1268
	err = 0;
out_put:
	thread__put(migrant);
	return err;
1269 1270
}

1271
static void output_lat_thread(struct perf_sched *sched, struct work_atoms *work_list)
1272 1273 1274
{
	int i;
	int ret;
1275
	u64 avg;
1276
	char max_lat_at[32];
1277

1278
	if (!work_list->nb_atoms)
1279
		return;
1280 1281 1282
	/*
	 * Ignore idle threads:
	 */
1283
	if (!strcmp(thread__comm_str(work_list->thread), "swapper"))
1284
		return;
1285

1286 1287
	sched->all_runtime += work_list->total_runtime;
	sched->all_count   += work_list->nb_atoms;
1288

1289 1290 1291 1292
	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);
1293

M
mingo 已提交
1294
	for (i = 0; i < 24 - ret; i++)
1295 1296
		printf(" ");

1297
	avg = work_list->total_lat / work_list->nb_atoms;
1298
	timestamp__scnprintf_usec(work_list->max_lat_at, max_lat_at, sizeof(max_lat_at));
1299

1300
	printf("|%11.3f ms |%9" PRIu64 " | avg:%9.3f ms | max:%9.3f ms | max at: %13s s\n",
1301 1302 1303
	      (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,
1304
		 max_lat_at);
1305 1306
}

1307
static int pid_cmp(struct work_atoms *l, struct work_atoms *r)
1308
{
1309 1310
	if (l->thread == r->thread)
		return 0;
1311
	if (l->thread->tid < r->thread->tid)
1312
		return -1;
1313
	if (l->thread->tid > r->thread->tid)
1314
		return 1;
1315
	return (int)(l->thread - r->thread);
1316 1317
}

1318
static int avg_cmp(struct work_atoms *l, struct work_atoms *r)
1319 1320 1321 1322 1323 1324 1325 1326 1327 1328 1329 1330 1331 1332 1333 1334 1335 1336 1337 1338
{
	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;
}

1339
static int max_cmp(struct work_atoms *l, struct work_atoms *r)
1340 1341 1342 1343 1344 1345 1346 1347 1348
{
	if (l->max_lat < r->max_lat)
		return -1;
	if (l->max_lat > r->max_lat)
		return 1;

	return 0;
}

1349
static int switch_cmp(struct work_atoms *l, struct work_atoms *r)
1350 1351 1352 1353 1354 1355 1356 1357 1358
{
	if (l->nb_atoms < r->nb_atoms)
		return -1;
	if (l->nb_atoms > r->nb_atoms)
		return 1;

	return 0;
}

1359
static int runtime_cmp(struct work_atoms *l, struct work_atoms *r)
1360 1361 1362 1363 1364 1365 1366 1367 1368
{
	if (l->total_runtime < r->total_runtime)
		return -1;
	if (l->total_runtime > r->total_runtime)
		return 1;

	return 0;
}

1369
static int sort_dimension__add(const char *tok, struct list_head *list)
1370
{
1371 1372 1373 1374 1375 1376 1377 1378 1379 1380 1381 1382 1383 1384 1385 1386 1387 1388 1389 1390 1391 1392 1393 1394 1395 1396 1397 1398
	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,
	};
1399

1400
	for (i = 0; i < ARRAY_SIZE(available_sorts); i++) {
1401 1402 1403 1404 1405 1406 1407 1408 1409 1410
		if (!strcmp(available_sorts[i]->name, tok)) {
			list_add_tail(&available_sorts[i]->list, list);

			return 0;
		}
	}

	return -1;
}

1411
static void perf_sched__sort_lat(struct perf_sched *sched)
1412 1413
{
	struct rb_node *node;
1414 1415
	struct rb_root *root = &sched->atom_root;
again:
1416
	for (;;) {
1417
		struct work_atoms *data;
1418
		node = rb_first(root);
1419 1420 1421
		if (!node)
			break;

1422
		rb_erase(node, root);
1423
		data = rb_entry(node, struct work_atoms, node);
1424
		__thread_latency_insert(&sched->sorted_atom_root, data, &sched->sort_list);
1425
	}
1426 1427 1428 1429
	if (root == &sched->atom_root) {
		root = &sched->merged_atom_root;
		goto again;
	}
1430 1431
}

1432
static int process_sched_wakeup_event(struct perf_tool *tool,
1433
				      struct perf_evsel *evsel,
1434
				      struct perf_sample *sample,
1435
				      struct machine *machine)
1436
{
1437
	struct perf_sched *sched = container_of(tool, struct perf_sched, tool);
1438

1439 1440
	if (sched->tp_handler->wakeup_event)
		return sched->tp_handler->wakeup_event(sched, evsel, sample, machine);
1441

1442
	return 0;
1443 1444
}

J
Jiri Olsa 已提交
1445 1446 1447 1448 1449 1450 1451 1452 1453 1454 1455 1456 1457 1458 1459 1460 1461 1462 1463 1464 1465 1466 1467 1468 1469 1470 1471 1472 1473 1474 1475 1476
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;
}

1477 1478
static int map_switch_event(struct perf_sched *sched, struct perf_evsel *evsel,
			    struct perf_sample *sample, struct machine *machine)
1479
{
1480 1481
	const u32 next_pid = perf_evsel__intval(evsel, sample, "next_pid");
	struct thread *sched_in;
1482
	int new_shortname;
1483
	u64 timestamp0, timestamp = sample->time;
1484
	s64 delta;
1485 1486 1487
	int i, this_cpu = sample->cpu;
	int cpus_nr;
	bool new_cpu = false;
1488
	const char *color = PERF_COLOR_NORMAL;
1489
	char stimestamp[32];
1490 1491 1492

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

1493 1494
	if (this_cpu > sched->max_cpu)
		sched->max_cpu = this_cpu;
1495

1496 1497 1498 1499 1500 1501 1502 1503 1504
	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;

1505 1506
	timestamp0 = sched->cpu_last_switched[this_cpu];
	sched->cpu_last_switched[this_cpu] = timestamp;
1507 1508 1509 1510 1511
	if (timestamp0)
		delta = timestamp - timestamp0;
	else
		delta = 0;

1512
	if (delta < 0) {
1513
		pr_err("hm, delta: %" PRIu64 " < 0 ?\n", delta);
1514 1515
		return -1;
	}
1516

J
Jiri Olsa 已提交
1517
	sched_in = map__findnew_thread(sched, machine, -1, next_pid);
1518 1519
	if (sched_in == NULL)
		return -1;
1520

1521
	sched->curr_thread[this_cpu] = thread__get(sched_in);
1522 1523 1524 1525 1526

	printf("  ");

	new_shortname = 0;
	if (!sched_in->shortname[0]) {
1527 1528 1529 1530 1531 1532 1533
		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.
			 */
			sched_in->shortname[0] = '.';
			sched_in->shortname[1] = ' ';
1534
		} else {
1535 1536 1537 1538 1539
			sched_in->shortname[0] = sched->next_shortname1;
			sched_in->shortname[1] = sched->next_shortname2;

			if (sched->next_shortname1 < 'Z') {
				sched->next_shortname1++;
1540
			} else {
1541 1542 1543 1544 1545
				sched->next_shortname1 = 'A';
				if (sched->next_shortname2 < '9')
					sched->next_shortname2++;
				else
					sched->next_shortname2 = '0';
1546 1547 1548 1549 1550
			}
		}
		new_shortname = 1;
	}

1551 1552
	for (i = 0; i < cpus_nr; i++) {
		int cpu = sched->map.comp ? sched->map.comp_cpus[i] : i;
J
Jiri Olsa 已提交
1553 1554
		struct thread *curr_thread = sched->curr_thread[cpu];
		const char *pid_color = color;
J
Jiri Olsa 已提交
1555
		const char *cpu_color = color;
J
Jiri Olsa 已提交
1556 1557 1558

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

1560 1561 1562
		if (sched->map.cpus && !cpu_map__has(sched->map.cpus, cpu))
			continue;

J
Jiri Olsa 已提交
1563 1564 1565
		if (sched->map.color_cpus && cpu_map__has(sched->map.color_cpus, cpu))
			cpu_color = COLOR_CPUS;

1566
		if (cpu != this_cpu)
1567
			color_fprintf(stdout, color, " ");
1568
		else
J
Jiri Olsa 已提交
1569
			color_fprintf(stdout, cpu_color, "*");
1570

1571
		if (sched->curr_thread[cpu])
J
Jiri Olsa 已提交
1572
			color_fprintf(stdout, pid_color, "%2s ", sched->curr_thread[cpu]->shortname);
1573
		else
1574
			color_fprintf(stdout, color, "   ");
1575 1576
	}

1577 1578 1579
	if (sched->map.cpus && !cpu_map__has(sched->map.cpus, this_cpu))
		goto out;

1580 1581
	timestamp__scnprintf_usec(timestamp, stimestamp, sizeof(stimestamp));
	color_fprintf(stdout, color, "  %12s secs ", stimestamp);
1582
	if (new_shortname || (verbose > 0 && sched_in->tid)) {
J
Jiri Olsa 已提交
1583 1584 1585 1586 1587 1588
		const char *pid_color = color;

		if (thread__has_color(sched_in))
			pid_color = COLOR_PIDS;

		color_fprintf(stdout, pid_color, "%s => %s:%d",
1589
		       sched_in->shortname, thread__comm_str(sched_in), sched_in->tid);
1590
	}
1591

1592
	if (sched->map.comp && new_cpu)
1593
		color_fprintf(stdout, color, " (CPU %d)", this_cpu);
1594

1595
out:
1596
	color_fprintf(stdout, color, "\n");
1597

1598 1599
	thread__put(sched_in);

1600
	return 0;
1601 1602
}

1603
static int process_sched_switch_event(struct perf_tool *tool,
1604
				      struct perf_evsel *evsel,
1605
				      struct perf_sample *sample,
1606
				      struct machine *machine)
1607
{
1608
	struct perf_sched *sched = container_of(tool, struct perf_sched, tool);
1609
	int this_cpu = sample->cpu, err = 0;
1610 1611
	u32 prev_pid = perf_evsel__intval(evsel, sample, "prev_pid"),
	    next_pid = perf_evsel__intval(evsel, sample, "next_pid");
1612

1613
	if (sched->curr_pid[this_cpu] != (u32)-1) {
1614 1615 1616 1617
		/*
		 * Are we trying to switch away a PID that is
		 * not current?
		 */
1618
		if (sched->curr_pid[this_cpu] != prev_pid)
1619
			sched->nr_context_switch_bugs++;
1620 1621
	}

1622 1623
	if (sched->tp_handler->switch_event)
		err = sched->tp_handler->switch_event(sched, evsel, sample, machine);
1624 1625

	sched->curr_pid[this_cpu] = next_pid;
1626
	return err;
1627 1628
}

1629
static int process_sched_runtime_event(struct perf_tool *tool,
1630
				       struct perf_evsel *evsel,
1631
				       struct perf_sample *sample,
1632
				       struct machine *machine)
1633
{
1634
	struct perf_sched *sched = container_of(tool, struct perf_sched, tool);
1635

1636 1637
	if (sched->tp_handler->runtime_event)
		return sched->tp_handler->runtime_event(sched, evsel, sample, machine);
1638

1639
	return 0;
1640 1641
}

1642 1643 1644 1645
static int perf_sched__process_fork_event(struct perf_tool *tool,
					  union perf_event *event,
					  struct perf_sample *sample,
					  struct machine *machine)
1646
{
1647
	struct perf_sched *sched = container_of(tool, struct perf_sched, tool);
1648

1649 1650 1651 1652
	/* 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 */
1653
	if (sched->tp_handler->fork_event)
1654
		return sched->tp_handler->fork_event(sched, event, machine);
1655

1656
	return 0;
1657 1658
}

1659
static int process_sched_migrate_task_event(struct perf_tool *tool,
1660
					    struct perf_evsel *evsel,
1661
					    struct perf_sample *sample,
1662
					    struct machine *machine)
1663
{
1664
	struct perf_sched *sched = container_of(tool, struct perf_sched, tool);
1665

1666 1667
	if (sched->tp_handler->migrate_task_event)
		return sched->tp_handler->migrate_task_event(sched, evsel, sample, machine);
1668

1669
	return 0;
1670 1671
}

1672
typedef int (*tracepoint_handler)(struct perf_tool *tool,
1673
				  struct perf_evsel *evsel,
1674
				  struct perf_sample *sample,
1675
				  struct machine *machine);
I
Ingo Molnar 已提交
1676

1677 1678
static int perf_sched__process_tracepoint_sample(struct perf_tool *tool __maybe_unused,
						 union perf_event *event __maybe_unused,
1679 1680 1681
						 struct perf_sample *sample,
						 struct perf_evsel *evsel,
						 struct machine *machine)
I
Ingo Molnar 已提交
1682
{
1683
	int err = 0;
I
Ingo Molnar 已提交
1684

1685 1686
	if (evsel->handler != NULL) {
		tracepoint_handler f = evsel->handler;
1687
		err = f(tool, evsel, sample, machine);
1688
	}
I
Ingo Molnar 已提交
1689

1690
	return err;
I
Ingo Molnar 已提交
1691 1692
}

1693
static int perf_sched__read_events(struct perf_sched *sched)
I
Ingo Molnar 已提交
1694
{
1695 1696 1697 1698 1699 1700 1701
	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, },
	};
1702
	struct perf_session *session;
1703 1704 1705
	struct perf_data_file file = {
		.path = input_name,
		.mode = PERF_DATA_MODE_READ,
1706
		.force = sched->force,
1707
	};
1708
	int rc = -1;
1709

1710
	session = perf_session__new(&file, false, &sched->tool);
1711 1712 1713 1714
	if (session == NULL) {
		pr_debug("No Memory for session\n");
		return -1;
	}
1715

1716
	symbol__init(&session->header.env);
1717

1718 1719
	if (perf_session__set_tracepoints_handlers(session, handlers))
		goto out_delete;
1720

1721
	if (perf_session__has_traces(session, "record -R")) {
1722
		int err = perf_session__process_events(session);
1723 1724 1725 1726
		if (err) {
			pr_err("Failed to process events, error %d", err);
			goto out_delete;
		}
1727

1728 1729 1730
		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];
1731
	}
1732

1733
	rc = 0;
1734 1735
out_delete:
	perf_session__delete(session);
1736
	return rc;
I
Ingo Molnar 已提交
1737 1738
}

1739 1740 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 1774 1775 1776 1777 1778 1779 1780 1781 1782 1783 1784 1785 1786 1787 1788 1789 1790 1791 1792 1793 1794 1795 1796 1797 1798 1799 1800 1801 1802 1803 1804 1805 1806 1807 1808
/*
 * 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];
}

1809
static int comm_width = 30;
1810 1811 1812 1813 1814 1815 1816 1817 1818 1819 1820 1821 1822 1823 1824 1825 1826 1827 1828 1829 1830 1831 1832 1833

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;
}

1834
static void timehist_header(struct perf_sched *sched)
1835
{
1836 1837 1838
	u32 ncpus = sched->max_cpu + 1;
	u32 i, j;

1839 1840
	printf("%15s %6s ", "time", "cpu");

1841 1842 1843 1844 1845 1846 1847 1848 1849 1850
	if (sched->show_cpu_visual) {
		printf(" ");
		for (i = 0, j = 0; i < ncpus; ++i) {
			printf("%x", j++);
			if (j > 15)
				j = 0;
		}
		printf(" ");
	}

1851
	printf(" %-*s  %9s  %9s  %9s", comm_width,
1852 1853
		"task name", "wait time", "sch delay", "run time");

1854 1855 1856
	if (sched->show_state)
		printf("  %s", "state");

1857 1858 1859 1860 1861 1862 1863
	printf("\n");

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

1864 1865 1866
	if (sched->show_cpu_visual)
		printf(" %*s ", ncpus, "");

1867
	printf(" %-*s  %9s  %9s  %9s", comm_width,
1868
	       "[tid/pid]", "(msec)", "(msec)", "(msec)");
1869

1870 1871 1872 1873 1874
	if (sched->show_state)
		printf("  %5s", "");

	printf("\n");

1875 1876 1877 1878 1879
	/*
	 * separator
	 */
	printf("%.15s %.6s ", graph_dotted_line, graph_dotted_line);

1880 1881 1882
	if (sched->show_cpu_visual)
		printf(" %.*s ", ncpus, graph_dotted_line);

1883
	printf(" %.*s  %.9s  %.9s  %.9s", comm_width,
1884 1885 1886
		graph_dotted_line, graph_dotted_line, graph_dotted_line,
		graph_dotted_line);

1887 1888 1889
	if (sched->show_state)
		printf("  %.5s", graph_dotted_line);

1890 1891 1892
	printf("\n");
}

1893 1894 1895 1896 1897 1898 1899 1900 1901 1902 1903 1904
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] : '?';
}

1905
static void timehist_print_sample(struct perf_sched *sched,
1906
				  struct perf_evsel *evsel,
1907
				  struct perf_sample *sample,
1908
				  struct addr_location *al,
1909
				  struct thread *thread,
1910
				  u64 t, int state)
1911 1912
{
	struct thread_runtime *tr = thread__priv(thread);
1913 1914
	const char *next_comm = perf_evsel__strval(evsel, sample, "next_comm");
	const u32 next_pid = perf_evsel__intval(evsel, sample, "next_pid");
1915
	u32 max_cpus = sched->max_cpu + 1;
1916
	char tstr[64];
1917
	char nstr[30];
1918
	u64 wait_time;
1919

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

1923 1924 1925 1926 1927 1928 1929 1930 1931 1932 1933 1934 1935 1936 1937 1938
	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(" ");
	}

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

1941 1942 1943
	wait_time = tr->dt_sleep + tr->dt_iowait + tr->dt_preempt;
	print_sched_time(wait_time, 6);

1944 1945
	print_sched_time(tr->dt_delay, 6);
	print_sched_time(tr->dt_run, 6);
1946

1947 1948 1949
	if (sched->show_state)
		printf(" %5c ", task_state_char(thread, state));

1950 1951 1952 1953 1954 1955
	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)
1956 1957
		printf("  %-*s", comm_width, "");

1958 1959 1960 1961 1962 1963 1964 1965
	if (thread->tid == 0)
		goto out;

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

	sample__fprintf_sym(sample, al, 0,
			    EVSEL__PRINT_SYM | EVSEL__PRINT_ONELINE |
1966 1967
			    EVSEL__PRINT_CALLCHAIN_ARROW |
			    EVSEL__PRINT_SKIP_IGNORED,
1968 1969 1970
			    &callchain_cursor, stdout);

out:
1971 1972 1973 1974 1975 1976 1977 1978 1979 1980 1981 1982 1983 1984 1985 1986 1987 1988 1989 1990 1991 1992 1993 1994 1995 1996 1997 1998 1999 2000
	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;
2001 2002 2003
	r->dt_sleep   = 0;
	r->dt_iowait  = 0;
	r->dt_preempt = 0;
2004
	r->dt_run     = 0;
2005

2006 2007 2008 2009 2010 2011 2012 2013 2014 2015 2016
	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");
2017 2018 2019 2020 2021 2022 2023 2024 2025 2026
		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;
		}
2027 2028 2029
	}

	update_stats(&r->run_stats, r->dt_run);
2030 2031 2032 2033 2034 2035

	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;
2036 2037
}

2038 2039
static bool is_idle_sample(struct perf_sample *sample,
			   struct perf_evsel *evsel)
2040 2041
{
	/* pid 0 == swapper == idle task */
2042 2043
	if (strcmp(perf_evsel__name(evsel), "sched:sched_switch") == 0)
		return perf_evsel__intval(evsel, sample, "prev_pid") == 0;
2044

2045 2046 2047 2048 2049 2050 2051 2052 2053 2054
	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;
2055 2056 2057 2058 2059

	/* 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);
2060
		return;
2061 2062 2063
	}

	if (!symbol_conf.use_callchain || sample->callchain == NULL)
2064
		return;
2065 2066

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

2071
		return;
2072
	}
2073

2074
	callchain_cursor_commit(cursor);
2075 2076 2077 2078 2079 2080 2081 2082 2083 2084

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

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

		sym = node->sym;
2085
		if (sym) {
2086 2087 2088 2089 2090 2091 2092 2093
			if (!strcmp(sym->name, "schedule") ||
			    !strcmp(sym->name, "__schedule") ||
			    !strcmp(sym->name, "preempt_schedule"))
				sym->ignore = 1;
		}

		callchain_cursor_advance(cursor);
	}
2094 2095
}

2096 2097 2098 2099 2100 2101 2102 2103 2104 2105 2106 2107 2108 2109 2110 2111 2112 2113
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;
}

2114 2115 2116 2117 2118 2119
/*
 * 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)
{
2120
	int i, ret;
2121 2122 2123 2124 2125

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

2126
	idle_max_cpu = ncpu;
2127 2128 2129 2130 2131 2132 2133

	/* 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;

2134 2135 2136
		ret = init_idle_thread(idle_threads[i]);
		if (ret < 0)
			return ret;
2137 2138 2139 2140 2141 2142 2143 2144 2145 2146 2147 2148
	}

	return 0;
}

static void free_idle_threads(void)
{
	int i;

	if (idle_threads == NULL)
		return;

2149
	for (i = 0; i < idle_max_cpu; ++i) {
2150 2151 2152 2153 2154 2155 2156 2157 2158 2159 2160 2161 2162 2163 2164 2165 2166 2167 2168 2169 2170 2171
		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;
2172
		for (i = idle_max_cpu; i < j; ++i)
2173 2174 2175 2176 2177 2178 2179 2180 2181 2182
			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]) {
2183 2184
			if (init_idle_thread(idle_threads[cpu]) < 0)
				return NULL;
2185 2186 2187 2188 2189 2190
		}
	}

	return idle_threads[cpu];
}

2191 2192 2193 2194 2195 2196 2197 2198 2199
static void save_idle_callchain(struct idle_thread_runtime *itr,
				struct perf_sample *sample)
{
	if (!symbol_conf.use_callchain || sample->callchain == NULL)
		return;

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

2200 2201 2202 2203 2204 2205 2206 2207 2208 2209 2210 2211 2212 2213 2214 2215 2216 2217 2218 2219 2220 2221 2222 2223 2224 2225 2226 2227 2228 2229 2230
/*
 * 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;
}

2231 2232
static struct thread *timehist_get_thread(struct perf_sched *sched,
					  struct perf_sample *sample,
2233 2234 2235 2236 2237
					  struct machine *machine,
					  struct perf_evsel *evsel)
{
	struct thread *thread;

2238
	if (is_idle_sample(sample, evsel)) {
2239 2240 2241 2242 2243
		thread = get_idle_thread(sample->cpu);
		if (thread == NULL)
			pr_err("Failed to get idle thread for cpu %d.\n", sample->cpu);

	} else {
2244 2245 2246
		/* there were samples with tid 0 but non-zero pid */
		thread = machine__findnew_thread(machine, sample->pid,
						 sample->tid ?: sample->pid);
2247 2248 2249 2250
		if (thread == NULL) {
			pr_debug("Failed to get thread for tid %d. skipping sample.\n",
				 sample->tid);
		}
2251 2252

		save_task_callchain(sched, sample, evsel, machine);
2253 2254 2255 2256 2257 2258 2259 2260 2261 2262 2263 2264 2265 2266 2267 2268 2269 2270 2271 2272
		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)
				save_idle_callchain(itr, sample);
		}
2273 2274 2275 2276 2277
	}

	return thread;
}

2278
static bool timehist_skip_sample(struct perf_sched *sched,
2279 2280 2281
				 struct thread *thread,
				 struct perf_evsel *evsel,
				 struct perf_sample *sample)
2282 2283 2284
{
	bool rc = false;

2285
	if (thread__is_filtered(thread)) {
2286
		rc = true;
2287 2288
		sched->skipped_samples++;
	}
2289

2290 2291 2292 2293 2294 2295 2296 2297
	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;
	}

2298 2299 2300
	return rc;
}

2301
static void timehist_print_wakeup_event(struct perf_sched *sched,
2302
					struct perf_evsel *evsel,
2303 2304 2305 2306 2307 2308 2309 2310 2311 2312 2313 2314
					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 */
2315 2316
	if (timehist_skip_sample(sched, thread, evsel, sample) &&
	    timehist_skip_sample(sched, awakened, evsel, sample)) {
2317 2318 2319 2320 2321
		return;
	}

	timestamp__scnprintf_usec(sample->time, tstr, sizeof(tstr));
	printf("%15s [%04d] ", tstr, sample->cpu);
2322 2323
	if (sched->show_cpu_visual)
		printf(" %*s ", sched->max_cpu + 1, "");
2324 2325 2326 2327 2328 2329 2330 2331 2332 2333 2334 2335

	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,
2336 2337 2338 2339 2340
				       union perf_event *event __maybe_unused,
				       struct perf_evsel *evsel,
				       struct perf_sample *sample,
				       struct machine *machine)
{
2341
	struct perf_sched *sched = container_of(tool, struct perf_sched, tool);
2342 2343 2344 2345 2346 2347 2348 2349 2350 2351 2352 2353 2354 2355 2356 2357
	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;

2358
	/* show wakeups if requested */
2359 2360
	if (sched->show_wakeups &&
	    !perf_time__skip_sample(&sched->ptime, sample->time))
2361
		timehist_print_wakeup_event(sched, evsel, sample, machine, thread);
2362

2363 2364 2365
	return 0;
}

2366 2367 2368 2369 2370 2371 2372 2373 2374 2375 2376 2377 2378 2379 2380 2381 2382 2383 2384 2385 2386 2387
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;

2388 2389
	if (timehist_skip_sample(sched, thread, evsel, sample) &&
	    timehist_skip_sample(sched, migrated, evsel, sample)) {
2390 2391 2392 2393 2394 2395 2396 2397 2398 2399 2400 2401 2402 2403 2404 2405 2406 2407 2408 2409 2410 2411 2412 2413 2414 2415 2416 2417 2418 2419 2420 2421 2422 2423 2424 2425 2426 2427 2428 2429 2430 2431 2432 2433 2434 2435 2436 2437 2438 2439 2440 2441 2442 2443 2444 2445 2446
		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;
}

2447
static int timehist_sched_change_event(struct perf_tool *tool,
2448 2449 2450 2451 2452
				       union perf_event *event,
				       struct perf_evsel *evsel,
				       struct perf_sample *sample,
				       struct machine *machine)
{
2453
	struct perf_sched *sched = container_of(tool, struct perf_sched, tool);
2454
	struct perf_time_interval *ptime = &sched->ptime;
2455 2456 2457
	struct addr_location al;
	struct thread *thread;
	struct thread_runtime *tr = NULL;
2458
	u64 tprev, t = sample->time;
2459
	int rc = 0;
2460 2461
	int state = perf_evsel__intval(evsel, sample, "prev_state");

2462 2463 2464 2465 2466 2467 2468 2469

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

2470
	thread = timehist_get_thread(sched, sample, machine, evsel);
2471 2472 2473 2474 2475
	if (thread == NULL) {
		rc = -1;
		goto out;
	}

2476
	if (timehist_skip_sample(sched, thread, evsel, sample))
2477 2478 2479 2480 2481 2482 2483 2484 2485 2486
		goto out;

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

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

2487 2488 2489 2490 2491 2492 2493 2494
	/*
	 * 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;

2495
	if (tprev && ptime->start > tprev)
2496 2497 2498 2499 2500 2501 2502 2503 2504 2505 2506 2507 2508 2509 2510 2511
		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;
	}

2512 2513 2514 2515 2516 2517 2518 2519 2520 2521 2522 2523 2524 2525 2526 2527 2528 2529 2530 2531 2532 2533 2534 2535 2536
	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;
2537 2538 2539
			last_tr->dt_sleep = 0;
			last_tr->dt_iowait = 0;
			last_tr->dt_preempt = 0;
2540

2541 2542 2543
			if (itr->cursor.nr)
				callchain_append(&itr->callchain, &itr->cursor, t - tprev);

2544 2545 2546
			itr->last_thread = NULL;
		}
	}
2547

2548
	if (!sched->summary_only)
2549
		timehist_print_sample(sched, evsel, sample, &al, thread, t, state);
2550 2551

out:
2552 2553 2554 2555 2556
	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;

2557 2558 2559 2560
	if (tr) {
		/* time of this sched_switch event becomes last time task seen */
		tr->last_time = sample->time;

2561
		/* last state is used to determine where to account wait time */
2562
		tr->last_state = state;
2563

2564 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 2590 2591 2592 2593 2594 2595 2596
		/* 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;
}


2597 2598 2599 2600 2601 2602 2603 2604 2605 2606 2607 2608 2609 2610 2611 2612 2613 2614 2615
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);
2616
	printf("   %5" PRIu64, r->migrations);
2617 2618 2619
	printf("\n");
}

2620 2621 2622 2623 2624 2625 2626 2627 2628 2629 2630 2631 2632 2633 2634 2635 2636 2637
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");
}

2638
struct total_run_stats {
2639
	struct perf_sched *sched;
2640 2641 2642 2643 2644 2645 2646 2647 2648 2649 2650 2651 2652 2653 2654 2655 2656 2657
	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;
2658 2659 2660 2661 2662

		if (stats->sched->show_state)
			print_thread_waittime(t, r);
		else
			print_thread_runtime(t, r);
2663 2664 2665 2666 2667 2668 2669 2670 2671 2672 2673 2674 2675 2676 2677 2678 2679 2680 2681 2682 2683
	}

	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);
}

2684 2685 2686 2687 2688 2689 2690 2691 2692 2693 2694 2695 2696 2697 2698 2699 2700 2701 2702 2703 2704 2705 2706 2707 2708 2709 2710 2711 2712 2713 2714 2715 2716 2717 2718 2719 2720 2721 2722 2723 2724 2725 2726 2727 2728 2729 2730 2731 2732 2733 2734 2735 2736 2737
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;
}

2738 2739 2740 2741 2742 2743 2744 2745 2746
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;
2747
	u64 hist_time = sched->hist_time.end - sched->hist_time.start;
2748 2749

	memset(&totals, 0, sizeof(totals));
2750
	totals.sched = sched;
2751

2752 2753 2754 2755
	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");
2756 2757 2758 2759
	} 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");
2760 2761 2762 2763 2764
	} 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");
	}
2765
	printf("%*s            (count)  ", comm_width, "");
2766 2767
	printf("     (msec)     (msec)      (msec)      (msec)       %s\n",
	       sched->show_state ? "(msec)" : "%");
2768
	printf("%.117s\n", graph_dotted_line);
2769 2770 2771 2772 2773 2774 2775 2776 2777 2778 2779 2780

	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 */
2781
	if (sched->skipped_samples && !sched->idle_hist)
2782 2783 2784
		return;

	printf("\nIdle stats:\n");
2785
	for (i = 0; i < idle_max_cpu; ++i) {
2786 2787 2788 2789 2790 2791 2792 2793 2794
		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);
2795
			printf(" msec  (%6.2f%%)\n", 100.0 * r->total_run_time / hist_time);
2796 2797 2798 2799
		} else
			printf("    CPU %2d idle entire time window\n", i);
	}

2800 2801 2802 2803 2804 2805 2806 2807 2808 2809 2810 2811 2812 2813 2814 2815 2816 2817 2818 2819 2820 2821 2822 2823 2824 2825 2826 2827 2828
	if (sched->idle_hist && symbol_conf.use_callchain) {
		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");
		}
	}

2829 2830
	printf("\n"
	       "    Total number of unique tasks: %" PRIu64 "\n"
2831
	       "Total number of context switches: %" PRIu64 "\n",
2832 2833
	       totals.task_count, totals.sched_count);

2834
	printf("           Total run time (msec): ");
2835 2836
	print_sched_time(totals.total_run_time, 2);
	printf("\n");
2837 2838 2839 2840

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

2843 2844 2845 2846 2847 2848 2849 2850 2851 2852 2853 2854 2855 2856 2857 2858 2859 2860 2861 2862 2863 2864 2865 2866 2867 2868 2869 2870
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;
}

2871 2872 2873 2874 2875 2876 2877 2878 2879 2880 2881 2882 2883 2884 2885 2886 2887 2888 2889 2890 2891 2892 2893 2894
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;
		}

		if (sched->show_callchain &&
		    !(evsel->attr.sample_type & PERF_SAMPLE_CALLCHAIN)) {
			pr_info("Samples do not have callchains.\n");
			sched->show_callchain = 0;
			symbol_conf.use_callchain = 0;
		}
	}

	return 0;
}

2895 2896 2897 2898 2899 2900 2901
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, },
	};
2902 2903 2904
	const struct perf_evsel_str_handler migrate_handlers[] = {
		{ "sched:sched_migrate_task", timehist_migrate_task_event, },
	};
2905 2906 2907
	struct perf_data_file file = {
		.path = input_name,
		.mode = PERF_DATA_MODE_READ,
2908
		.force = sched->force,
2909 2910 2911
	};

	struct perf_session *session;
2912
	struct perf_evlist *evlist;
2913 2914 2915 2916 2917 2918 2919 2920 2921 2922 2923 2924 2925 2926 2927 2928 2929 2930
	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;

2931 2932
	symbol_conf.use_callchain = sched->show_callchain;

2933 2934 2935 2936
	session = perf_session__new(&file, false, &sched->tool);
	if (session == NULL)
		return -ENOMEM;

2937 2938
	evlist = session->evlist;

2939 2940
	symbol__init(&session->header.env);

2941 2942 2943 2944 2945
	if (perf_time__parse_str(&sched->ptime, sched->time_str) != 0) {
		pr_err("Invalid time string\n");
		return -EINVAL;
	}

2946 2947 2948
	if (timehist_check_attr(sched, evlist) != 0)
		goto out;

2949 2950 2951 2952 2953 2954
	setup_pager();

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

2955 2956 2957 2958
	/* 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");
2959
		goto out;
2960
	}
2961

2962 2963 2964 2965
	if (sched->show_migrations &&
	    perf_session__set_tracepoints_handlers(session, migrate_handlers))
		goto out;

2966 2967 2968 2969 2970 2971 2972
	/* 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;

2973 2974 2975 2976 2977
	/* 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)
2978
		timehist_header(sched);
2979 2980 2981 2982 2983 2984 2985

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

2986 2987 2988 2989 2990 2991 2992
	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);

2993 2994 2995 2996 2997 2998 2999 3000
out:
	free_idle_threads();
	perf_session__delete(session);

	return err;
}


3001
static void print_bad_events(struct perf_sched *sched)
3002
{
3003
	if (sched->nr_unordered_timestamps && sched->nr_timestamps) {
3004
		printf("  INFO: %.3f%% unordered timestamps (%ld out of %ld)\n",
3005 3006
			(double)sched->nr_unordered_timestamps/(double)sched->nr_timestamps*100.0,
			sched->nr_unordered_timestamps, sched->nr_timestamps);
3007
	}
3008
	if (sched->nr_lost_events && sched->nr_events) {
3009
		printf("  INFO: %.3f%% lost events (%ld out of %ld, in %ld chunks)\n",
3010 3011
			(double)sched->nr_lost_events/(double)sched->nr_events * 100.0,
			sched->nr_lost_events, sched->nr_events, sched->nr_lost_chunks);
3012
	}
3013
	if (sched->nr_context_switch_bugs && sched->nr_timestamps) {
3014
		printf("  INFO: %.3f%% context switch bugs (%ld out of %ld)",
3015 3016 3017
			(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)
3018 3019 3020 3021 3022
			printf(" (due to lost events?)");
		printf("\n");
	}
}

3023 3024 3025 3026 3027 3028 3029 3030 3031 3032 3033 3034 3035 3036 3037 3038 3039 3040 3041 3042 3043 3044 3045 3046 3047 3048 3049 3050 3051 3052 3053 3054 3055 3056 3057 3058 3059 3060 3061 3062 3063 3064 3065 3066 3067 3068 3069 3070 3071 3072 3073 3074 3075
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);
	}
}

3076
static int perf_sched__lat(struct perf_sched *sched)
3077 3078 3079 3080
{
	struct rb_node *next;

	setup_pager();
3081

3082
	if (perf_sched__read_events(sched))
3083
		return -1;
3084

3085
	perf_sched__merge_lat(sched);
3086
	perf_sched__sort_lat(sched);
3087

3088 3089 3090
	printf("\n -----------------------------------------------------------------------------------------------------------------\n");
	printf("  Task                  |   Runtime ms  | Switches | Average delay ms | Maximum delay ms | Maximum delay at       |\n");
	printf(" -----------------------------------------------------------------------------------------------------------------\n");
3091

3092
	next = rb_first(&sched->sorted_atom_root);
3093 3094 3095 3096 3097

	while (next) {
		struct work_atoms *work_list;

		work_list = rb_entry(next, struct work_atoms, node);
3098
		output_lat_thread(sched, work_list);
3099
		next = rb_next(next);
3100
		thread__zput(work_list->thread);
3101 3102
	}

3103
	printf(" -----------------------------------------------------------------------------------------------------------------\n");
3104
	printf("  TOTAL:                |%11.3f ms |%9" PRIu64 " |\n",
3105
		(double)sched->all_runtime / NSEC_PER_MSEC, sched->all_count);
3106 3107 3108

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

3109
	print_bad_events(sched);
3110 3111
	printf("\n");

3112
	return 0;
3113 3114
}

3115 3116
static int setup_map_cpus(struct perf_sched *sched)
{
3117 3118
	struct cpu_map *map;

3119 3120 3121 3122
	sched->max_cpu  = sysconf(_SC_NPROCESSORS_CONF);

	if (sched->map.comp) {
		sched->map.comp_cpus = zalloc(sched->max_cpu * sizeof(int));
J
Jiri Olsa 已提交
3123 3124
		if (!sched->map.comp_cpus)
			return -1;
3125 3126
	}

3127 3128 3129 3130 3131 3132 3133 3134 3135 3136
	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;
3137 3138 3139
	return 0;
}

J
Jiri Olsa 已提交
3140 3141 3142 3143 3144 3145 3146 3147 3148 3149 3150 3151 3152 3153 3154 3155 3156
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 已提交
3157 3158 3159 3160 3161 3162 3163 3164 3165 3166 3167 3168 3169 3170 3171 3172 3173
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;
}

3174
static int perf_sched__map(struct perf_sched *sched)
3175
{
3176 3177
	if (setup_map_cpus(sched))
		return -1;
3178

J
Jiri Olsa 已提交
3179 3180 3181
	if (setup_color_pids(sched))
		return -1;

J
Jiri Olsa 已提交
3182 3183 3184
	if (setup_color_cpus(sched))
		return -1;

3185
	setup_pager();
3186
	if (perf_sched__read_events(sched))
3187
		return -1;
3188
	print_bad_events(sched);
3189
	return 0;
3190 3191
}

3192
static int perf_sched__replay(struct perf_sched *sched)
3193 3194 3195
{
	unsigned long i;

3196 3197
	calibrate_run_measurement_overhead(sched);
	calibrate_sleep_measurement_overhead(sched);
3198

3199
	test_calibrations(sched);
3200

3201
	if (perf_sched__read_events(sched))
3202
		return -1;
3203

3204 3205 3206
	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);
3207

3208 3209 3210 3211 3212
	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)
3213
		printf("run atoms optimized: %ld\n",
3214
			sched->nr_run_events_optimized);
3215

3216 3217
	print_task_traces(sched);
	add_cross_task_wakeups(sched);
3218

3219
	create_tasks(sched);
3220
	printf("------------------------------------------------------------\n");
3221 3222
	for (i = 0; i < sched->replay_repeat; i++)
		run_one_test(sched);
3223 3224

	return 0;
3225 3226
}

3227 3228
static void setup_sorting(struct perf_sched *sched, const struct option *options,
			  const char * const usage_msg[])
3229
{
3230
	char *tmp, *tok, *str = strdup(sched->sort_order);
3231 3232 3233

	for (tok = strtok_r(str, ", ", &tmp);
			tok; tok = strtok_r(NULL, ", ", &tmp)) {
3234
		if (sort_dimension__add(tok, &sched->sort_list) < 0) {
3235 3236
			usage_with_options_msg(usage_msg, options,
					"Unknown --sort key: `%s'", tok);
3237 3238 3239 3240 3241
		}
	}

	free(str);

3242
	sort_dimension__add("pid", &sched->cmp_pid);
3243 3244
}

3245 3246 3247 3248
static int __cmd_record(int argc, const char **argv)
{
	unsigned int rec_argc, i, j;
	const char **rec_argv;
3249 3250 3251 3252 3253 3254 3255 3256 3257 3258 3259 3260 3261
	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",
3262
		"-e", "sched:sched_wakeup_new",
3263 3264
		"-e", "sched:sched_migrate_task",
	};
3265 3266 3267 3268

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

3269
	if (rec_argv == NULL)
3270 3271
		return -ENOMEM;

3272 3273 3274 3275 3276 3277 3278 3279
	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);

3280
	return cmd_record(i, rec_argv);
3281 3282
}

3283
int cmd_sched(int argc, const char **argv)
I
Ingo Molnar 已提交
3284
{
3285 3286 3287 3288 3289
	const char default_sort_order[] = "avg, max, switch, runtime";
	struct perf_sched sched = {
		.tool = {
			.sample		 = perf_sched__process_tracepoint_sample,
			.comm		 = perf_event__process_comm,
3290
			.namespaces	 = perf_event__process_namespaces,
3291 3292
			.lost		 = perf_event__process_lost,
			.fork		 = perf_sched__process_fork_event,
3293
			.ordered_events = true,
3294 3295 3296 3297 3298 3299 3300 3301 3302 3303
		},
		.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',
3304
		.skip_merge           = 0,
3305 3306
		.show_callchain	      = 1,
		.max_stack            = 5,
3307
	};
3308 3309 3310 3311 3312 3313 3314
	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"),
3315
	OPT_BOOLEAN('f', "force", &sched.force, "don't complain, do it"),
3316 3317
	OPT_END()
	};
3318 3319 3320 3321 3322
	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"),
3323 3324
	OPT_BOOLEAN('p', "pids", &sched.skip_merge,
		    "latency stats per pid instead of per comm"),
3325
	OPT_PARENT(sched_options)
3326 3327 3328 3329
	};
	const struct option replay_options[] = {
	OPT_UINTEGER('r', "repeat", &sched.replay_repeat,
		     "repeat the workload replay N times (-1: infinite)"),
3330
	OPT_PARENT(sched_options)
3331
	};
3332 3333 3334
	const struct option map_options[] = {
	OPT_BOOLEAN(0, "compact", &sched.map.comp,
		    "map output in compact mode"),
J
Jiri Olsa 已提交
3335 3336
	OPT_STRING(0, "color-pids", &sched.map.color_pids_str, "pids",
		   "highlight given pids in map"),
J
Jiri Olsa 已提交
3337 3338
	OPT_STRING(0, "color-cpus", &sched.map.color_cpus_str, "cpus",
                    "highlight given CPUs in map"),
3339 3340
	OPT_STRING(0, "cpus", &sched.map.cpus_str, "cpus",
                    "display given CPUs in map"),
3341
	OPT_PARENT(sched_options)
3342
	};
3343 3344 3345 3346 3347
	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"),
3348 3349 3350 3351
	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."),
3352 3353
	OPT_STRING(0, "symfs", &symbol_conf.symfs, "directory",
		    "Look for files with symbols relative to this directory"),
3354 3355 3356 3357
	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"),
3358
	OPT_BOOLEAN('w', "wakeups", &sched.show_wakeups, "Show wakeup events"),
3359
	OPT_BOOLEAN('n', "next", &sched.show_next, "Show next task"),
3360
	OPT_BOOLEAN('M', "migrations", &sched.show_migrations, "Show migration events"),
3361
	OPT_BOOLEAN('V', "cpu-visual", &sched.show_cpu_visual, "Add CPU visual"),
3362
	OPT_BOOLEAN('I', "idle-hist", &sched.idle_hist, "Show idle events only"),
3363 3364
	OPT_STRING(0, "time", &sched.time_str, "str",
		   "Time span for analysis (start,stop)"),
3365
	OPT_BOOLEAN(0, "state", &sched.show_state, "Show task state when sched-out"),
3366 3367 3368
	OPT_PARENT(sched_options)
	};

3369 3370 3371 3372 3373 3374 3375 3376
	const char * const latency_usage[] = {
		"perf sched latency [<options>]",
		NULL
	};
	const char * const replay_usage[] = {
		"perf sched replay [<options>]",
		NULL
	};
3377 3378 3379 3380
	const char * const map_usage[] = {
		"perf sched map [<options>]",
		NULL
	};
3381 3382 3383 3384
	const char * const timehist_usage[] = {
		"perf sched timehist [<options>]",
		NULL
	};
3385
	const char *const sched_subcommands[] = { "record", "latency", "map",
3386 3387
						  "replay", "script",
						  "timehist", NULL };
3388 3389
	const char *sched_usage[] = {
		NULL,
3390 3391 3392 3393 3394 3395 3396 3397 3398 3399 3400 3401 3402 3403 3404 3405
		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 已提交
3406 3407 3408 3409
	unsigned int i;

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

3411 3412
	argc = parse_options_subcommand(argc, argv, sched_options, sched_subcommands,
					sched_usage, PARSE_OPT_STOP_AT_NON_OPTION);
3413 3414
	if (!argc)
		usage_with_options(sched_usage, sched_options);
I
Ingo Molnar 已提交
3415

3416
	/*
3417
	 * Aliased to 'perf script' for now:
3418
	 */
3419
	if (!strcmp(argv[0], "script"))
3420
		return cmd_script(argc, argv);
3421

3422 3423 3424
	if (!strncmp(argv[0], "rec", 3)) {
		return __cmd_record(argc, argv);
	} else if (!strncmp(argv[0], "lat", 3)) {
3425
		sched.tp_handler = &lat_ops;
3426 3427 3428 3429 3430
		if (argc > 1) {
			argc = parse_options(argc, argv, latency_options, latency_usage, 0);
			if (argc)
				usage_with_options(latency_usage, latency_options);
		}
3431 3432
		setup_sorting(&sched, latency_options, latency_usage);
		return perf_sched__lat(&sched);
3433
	} else if (!strcmp(argv[0], "map")) {
3434
		if (argc) {
J
Jiri Olsa 已提交
3435
			argc = parse_options(argc, argv, map_options, map_usage, 0);
3436 3437 3438
			if (argc)
				usage_with_options(map_usage, map_options);
		}
3439 3440 3441
		sched.tp_handler = &map_ops;
		setup_sorting(&sched, latency_options, latency_usage);
		return perf_sched__map(&sched);
3442
	} else if (!strncmp(argv[0], "rep", 3)) {
3443
		sched.tp_handler = &replay_ops;
3444 3445 3446 3447 3448
		if (argc) {
			argc = parse_options(argc, argv, replay_options, replay_usage, 0);
			if (argc)
				usage_with_options(replay_usage, replay_options);
		}
3449
		return perf_sched__replay(&sched);
3450 3451 3452 3453 3454 3455 3456
	} 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);
		}
3457 3458 3459
		if ((sched.show_wakeups || sched.show_next) &&
		    sched.summary_only) {
			pr_err(" Error: -s and -[n|w] are mutually exclusive.\n");
3460
			parse_options_usage(timehist_usage, timehist_options, "s", true);
3461 3462 3463 3464
			if (sched.show_wakeups)
				parse_options_usage(NULL, timehist_options, "w", true);
			if (sched.show_next)
				parse_options_usage(NULL, timehist_options, "n", true);
3465 3466 3467
			return -EINVAL;
		}

3468
		return perf_sched__timehist(&sched);
3469 3470 3471 3472
	} else {
		usage_with_options(sched_usage, sched_options);
	}

I
Ingo Molnar 已提交
3473
	return 0;
I
Ingo Molnar 已提交
3474
}