builtin-sched.c 85.4 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/log2.h>
26
#include <sys/prctl.h>
27
#include <sys/resource.h>
I
Ingo Molnar 已提交
28

29 30 31
#include <semaphore.h>
#include <pthread.h>
#include <math.h>
32
#include <api/fs/fs.h>
33
#include <linux/time64.h>
34

35 36 37 38
#define PR_SET_NAME		15               /* Set process name */
#define MAX_CPUS		4096
#define COMM_LEN		20
#define SYM_LEN			129
39
#define MAX_PID			1024000
I
Ingo Molnar 已提交
40

41
struct sched_atom;
I
Ingo Molnar 已提交
42

43 44 45 46
struct task_desc {
	unsigned long		nr;
	unsigned long		pid;
	char			comm[COMM_LEN];
I
Ingo Molnar 已提交
47

48 49
	unsigned long		nr_events;
	unsigned long		curr_event;
50
	struct sched_atom	**atoms;
51 52 53

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

55 56 57 58 59 60 61 62 63 64
	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,
65
	SCHED_EVENT_MIGRATION,
66 67
};

68
struct sched_atom {
69
	enum sched_event_type	type;
70
	int			specific_wait;
71 72 73 74 75 76 77
	u64			timestamp;
	u64			duration;
	unsigned long		nr;
	sem_t			*wait_sem;
	struct task_desc	*wakee;
};

78
#define TASK_STATE_TO_CHAR_STR "RSDTtZXxKWP"
79

80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95
/* 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

96 97 98 99 100 101 102 103 104 105
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;
106
	u64			sched_out_time;
107 108 109 110 111
	u64			wake_up_time;
	u64			sched_in_time;
	u64			runtime;
};

112 113
struct work_atoms {
	struct list_head	work_list;
114 115 116
	struct thread		*thread;
	struct rb_node		node;
	u64			max_lat;
117
	u64			max_lat_at;
118 119 120
	u64			total_lat;
	u64			nb_atoms;
	u64			total_runtime;
121
	int			num_merged;
122 123
};

124
typedef int (*sort_fn_t)(struct work_atoms *, struct work_atoms *);
125

126
struct perf_sched;
127

128 129 130
struct trace_sched_handler {
	int (*switch_event)(struct perf_sched *sched, struct perf_evsel *evsel,
			    struct perf_sample *sample, struct machine *machine);
131

132 133
	int (*runtime_event)(struct perf_sched *sched, struct perf_evsel *evsel,
			     struct perf_sample *sample, struct machine *machine);
134

135 136
	int (*wakeup_event)(struct perf_sched *sched, struct perf_evsel *evsel,
			    struct perf_sample *sample, struct machine *machine);
137

138 139 140
	/* PERF_RECORD_FORK event, not sched_process_fork tracepoint */
	int (*fork_event)(struct perf_sched *sched, union perf_event *event,
			  struct machine *machine);
141 142

	int (*migrate_task_event)(struct perf_sched *sched,
143 144 145
				  struct perf_evsel *evsel,
				  struct perf_sample *sample,
				  struct machine *machine);
146 147
};

J
Jiri Olsa 已提交
148
#define COLOR_PIDS PERF_COLOR_BLUE
J
Jiri Olsa 已提交
149
#define COLOR_CPUS PERF_COLOR_BG_RED
J
Jiri Olsa 已提交
150

151 152 153 154
struct perf_sched_map {
	DECLARE_BITMAP(comp_cpus_mask, MAX_CPUS);
	int			*comp_cpus;
	bool			 comp;
J
Jiri Olsa 已提交
155 156
	struct thread_map	*color_pids;
	const char		*color_pids_str;
J
Jiri Olsa 已提交
157 158
	struct cpu_map		*color_cpus;
	const char		*color_cpus_str;
159 160
	struct cpu_map		*cpus;
	const char		*cpus_str;
161 162
};

163 164 165 166
struct perf_sched {
	struct perf_tool tool;
	const char	 *sort_order;
	unsigned long	 nr_tasks;
167
	struct task_desc **pid_to_task;
168 169 170 171 172 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
	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];
210
	struct rb_root	 atom_root, sorted_atom_root, merged_atom_root;
211
	struct list_head sort_list, cmp_pid;
212
	bool force;
213
	bool skip_merge;
214
	struct perf_sched_map map;
215 216 217 218

	/* options for timehist command */
	bool		summary;
	bool		summary_only;
219
	bool		idle_hist;
220 221
	bool		show_callchain;
	unsigned int	max_stack;
222
	bool		show_cpu_visual;
223
	bool		show_wakeups;
224
	bool		show_migrations;
225
	bool		show_state;
226
	u64		skipped_samples;
227 228
	const char	*time_str;
	struct perf_time_interval ptime;
229
	struct perf_time_interval hist_time;
230
};
231

232 233 234 235
/* per thread run time data */
struct thread_runtime {
	u64 last_time;      /* time of previous sched in/out event */
	u64 dt_run;         /* run time */
236 237 238
	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) */
239 240 241 242 243
	u64 dt_delay;       /* time between wakeup and sched-in */
	u64 ready_to_run;   /* time of wakeup */

	struct stats run_stats;
	u64 total_run_time;
244 245 246 247
	u64 total_sleep_time;
	u64 total_iowait_time;
	u64 total_preempt_time;
	u64 total_delay_time;
248

249
	int last_state;
250
	u64 migrations;
251 252 253 254 255 256 257 258
};

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

259 260 261 262 263 264 265 266 267
/* 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;
};

268 269 270 271 272
/* track idle times per cpu */
static struct thread **idle_threads;
static int idle_max_cpu;
static char idle_comm[] = "<idle>";

273
static u64 get_nsecs(void)
I
Ingo Molnar 已提交
274 275 276 277 278
{
	struct timespec ts;

	clock_gettime(CLOCK_MONOTONIC, &ts);

279
	return ts.tv_sec * NSEC_PER_SEC + ts.tv_nsec;
I
Ingo Molnar 已提交
280 281
}

282
static void burn_nsecs(struct perf_sched *sched, u64 nsecs)
I
Ingo Molnar 已提交
283
{
284
	u64 T0 = get_nsecs(), T1;
I
Ingo Molnar 已提交
285 286 287

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

291
static void sleep_nsecs(u64 nsecs)
I
Ingo Molnar 已提交
292 293 294 295 296 297 298 299 300
{
	struct timespec ts;

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

	nanosleep(&ts, NULL);
}

301
static void calibrate_run_measurement_overhead(struct perf_sched *sched)
I
Ingo Molnar 已提交
302
{
303
	u64 T0, T1, delta, min_delta = NSEC_PER_SEC;
I
Ingo Molnar 已提交
304 305 306 307
	int i;

	for (i = 0; i < 10; i++) {
		T0 = get_nsecs();
308
		burn_nsecs(sched, 0);
I
Ingo Molnar 已提交
309 310 311 312
		T1 = get_nsecs();
		delta = T1-T0;
		min_delta = min(min_delta, delta);
	}
313
	sched->run_measurement_overhead = min_delta;
I
Ingo Molnar 已提交
314

315
	printf("run measurement overhead: %" PRIu64 " nsecs\n", min_delta);
I
Ingo Molnar 已提交
316 317
}

318
static void calibrate_sleep_measurement_overhead(struct perf_sched *sched)
I
Ingo Molnar 已提交
319
{
320
	u64 T0, T1, delta, min_delta = NSEC_PER_SEC;
I
Ingo Molnar 已提交
321 322 323 324 325 326 327 328 329 330
	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;
331
	sched->sleep_measurement_overhead = min_delta;
I
Ingo Molnar 已提交
332

333
	printf("sleep measurement overhead: %" PRIu64 " nsecs\n", min_delta);
I
Ingo Molnar 已提交
334 335
}

336
static struct sched_atom *
337
get_new_event(struct task_desc *task, u64 timestamp)
I
Ingo Molnar 已提交
338
{
339
	struct sched_atom *event = zalloc(sizeof(*event));
I
Ingo Molnar 已提交
340 341 342 343 344 345 346
	unsigned long idx = task->nr_events;
	size_t size;

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

	task->nr_events++;
347 348 349
	size = sizeof(struct sched_atom *) * task->nr_events;
	task->atoms = realloc(task->atoms, size);
	BUG_ON(!task->atoms);
I
Ingo Molnar 已提交
350

351
	task->atoms[idx] = event;
I
Ingo Molnar 已提交
352 353 354 355

	return event;
}

356
static struct sched_atom *last_event(struct task_desc *task)
I
Ingo Molnar 已提交
357 358 359 360
{
	if (!task->nr_events)
		return NULL;

361
	return task->atoms[task->nr_events - 1];
I
Ingo Molnar 已提交
362 363
}

364 365
static void add_sched_event_run(struct perf_sched *sched, struct task_desc *task,
				u64 timestamp, u64 duration)
I
Ingo Molnar 已提交
366
{
367
	struct sched_atom *event, *curr_event = last_event(task);
I
Ingo Molnar 已提交
368 369

	/*
370 371 372
	 * optimize an existing RUN event by merging this one
	 * to it:
	 */
I
Ingo Molnar 已提交
373
	if (curr_event && curr_event->type == SCHED_EVENT_RUN) {
374
		sched->nr_run_events_optimized++;
I
Ingo Molnar 已提交
375 376 377 378 379 380 381 382 383
		curr_event->duration += duration;
		return;
	}

	event = get_new_event(task, timestamp);

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

384
	sched->nr_run_events++;
I
Ingo Molnar 已提交
385 386
}

387 388
static void add_sched_event_wakeup(struct perf_sched *sched, struct task_desc *task,
				   u64 timestamp, struct task_desc *wakee)
I
Ingo Molnar 已提交
389
{
390
	struct sched_atom *event, *wakee_event;
I
Ingo Molnar 已提交
391 392 393 394 395 396 397

	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) {
398
		sched->targetless_wakeups++;
I
Ingo Molnar 已提交
399 400 401
		return;
	}
	if (wakee_event->wait_sem) {
402
		sched->multitarget_wakeups++;
I
Ingo Molnar 已提交
403 404 405
		return;
	}

406
	wakee_event->wait_sem = zalloc(sizeof(*wakee_event->wait_sem));
I
Ingo Molnar 已提交
407 408 409 410
	sem_init(wakee_event->wait_sem, 0, 0);
	wakee_event->specific_wait = 1;
	event->wait_sem = wakee_event->wait_sem;

411
	sched->nr_wakeup_events++;
I
Ingo Molnar 已提交
412 413
}

414 415
static void add_sched_event_sleep(struct perf_sched *sched, struct task_desc *task,
				  u64 timestamp, u64 task_state __maybe_unused)
I
Ingo Molnar 已提交
416
{
417
	struct sched_atom *event = get_new_event(task, timestamp);
I
Ingo Molnar 已提交
418 419 420

	event->type = SCHED_EVENT_SLEEP;

421
	sched->nr_sleep_events++;
I
Ingo Molnar 已提交
422 423
}

424 425
static struct task_desc *register_pid(struct perf_sched *sched,
				      unsigned long pid, const char *comm)
I
Ingo Molnar 已提交
426 427
{
	struct task_desc *task;
428
	static int pid_max;
I
Ingo Molnar 已提交
429

430 431 432 433 434
	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);
	}
435 436 437 438 439 440
	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 已提交
441

442
	task = sched->pid_to_task[pid];
I
Ingo Molnar 已提交
443 444 445 446

	if (task)
		return task;

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

457 458
	sched->pid_to_task[pid] = task;
	sched->nr_tasks++;
459
	sched->tasks = realloc(sched->tasks, sched->nr_tasks * sizeof(struct task_desc *));
460 461
	BUG_ON(!sched->tasks);
	sched->tasks[task->nr] = task;
I
Ingo Molnar 已提交
462

I
Ingo Molnar 已提交
463
	if (verbose)
464
		printf("registered task #%ld, PID %ld (%s)\n", sched->nr_tasks, pid, comm);
I
Ingo Molnar 已提交
465 466 467 468 469

	return task;
}


470
static void print_task_traces(struct perf_sched *sched)
I
Ingo Molnar 已提交
471 472 473 474
{
	struct task_desc *task;
	unsigned long i;

475 476
	for (i = 0; i < sched->nr_tasks; i++) {
		task = sched->tasks[i];
I
Ingo Molnar 已提交
477
		printf("task %6ld (%20s:%10ld), nr_events: %ld\n",
I
Ingo Molnar 已提交
478 479 480 481
			task->nr, task->comm, task->pid, task->nr_events);
	}
}

482
static void add_cross_task_wakeups(struct perf_sched *sched)
I
Ingo Molnar 已提交
483 484 485 486
{
	struct task_desc *task1, *task2;
	unsigned long i, j;

487 488
	for (i = 0; i < sched->nr_tasks; i++) {
		task1 = sched->tasks[i];
I
Ingo Molnar 已提交
489
		j = i + 1;
490
		if (j == sched->nr_tasks)
I
Ingo Molnar 已提交
491
			j = 0;
492 493
		task2 = sched->tasks[j];
		add_sched_event_wakeup(sched, task1, 0, task2);
I
Ingo Molnar 已提交
494 495 496
	}
}

497 498
static void perf_sched__process_event(struct perf_sched *sched,
				      struct sched_atom *atom)
I
Ingo Molnar 已提交
499 500 501
{
	int ret = 0;

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

523
static u64 get_cpu_usage_nsec_parent(void)
I
Ingo Molnar 已提交
524 525
{
	struct rusage ru;
526
	u64 sum;
I
Ingo Molnar 已提交
527 528 529 530 531
	int err;

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

532 533
	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 已提交
534 535 536 537

	return sum;
}

538
static int self_open_counters(struct perf_sched *sched, unsigned long cur_task)
I
Ingo Molnar 已提交
539
{
540
	struct perf_event_attr attr;
541
	char sbuf[STRERR_BUFSIZE], info[STRERR_BUFSIZE];
542
	int fd;
543 544
	struct rlimit limit;
	bool need_privilege = false;
I
Ingo Molnar 已提交
545

546
	memset(&attr, 0, sizeof(attr));
I
Ingo Molnar 已提交
547

548 549
	attr.type = PERF_TYPE_SOFTWARE;
	attr.config = PERF_COUNT_SW_TASK_CLOCK;
I
Ingo Molnar 已提交
550

551
force_again:
552 553
	fd = sys_perf_event_open(&attr, 0, -1, -1,
				 perf_event_open_cloexec_flag());
554

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

591 592 593
struct sched_thread_parms {
	struct task_desc  *task;
	struct perf_sched *sched;
594
	int fd;
595 596
};

I
Ingo Molnar 已提交
597 598
static void *thread_func(void *ctx)
{
599 600 601
	struct sched_thread_parms *parms = ctx;
	struct task_desc *this_task = parms->task;
	struct perf_sched *sched = parms->sched;
602
	u64 cpu_usage_0, cpu_usage_1;
I
Ingo Molnar 已提交
603 604
	unsigned long i, ret;
	char comm2[22];
605
	int fd = parms->fd;
I
Ingo Molnar 已提交
606

607
	zfree(&parms);
608

I
Ingo Molnar 已提交
609 610
	sprintf(comm2, ":%s", this_task->comm);
	prctl(PR_SET_NAME, comm2);
611 612
	if (fd < 0)
		return NULL;
I
Ingo Molnar 已提交
613 614 615
again:
	ret = sem_post(&this_task->ready_for_work);
	BUG_ON(ret);
616
	ret = pthread_mutex_lock(&sched->start_work_mutex);
I
Ingo Molnar 已提交
617
	BUG_ON(ret);
618
	ret = pthread_mutex_unlock(&sched->start_work_mutex);
I
Ingo Molnar 已提交
619 620
	BUG_ON(ret);

621
	cpu_usage_0 = get_cpu_usage_nsec_self(fd);
I
Ingo Molnar 已提交
622 623 624

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

628
	cpu_usage_1 = get_cpu_usage_nsec_self(fd);
I
Ingo Molnar 已提交
629 630 631 632
	this_task->cpu_usage = cpu_usage_1 - cpu_usage_0;
	ret = sem_post(&this_task->work_done_sem);
	BUG_ON(ret);

633
	ret = pthread_mutex_lock(&sched->work_done_wait_mutex);
I
Ingo Molnar 已提交
634
	BUG_ON(ret);
635
	ret = pthread_mutex_unlock(&sched->work_done_wait_mutex);
I
Ingo Molnar 已提交
636 637 638 639 640
	BUG_ON(ret);

	goto again;
}

641
static void create_tasks(struct perf_sched *sched)
I
Ingo Molnar 已提交
642 643 644 645 646 647 648 649
{
	struct task_desc *task;
	pthread_attr_t attr;
	unsigned long i;
	int err;

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

672
static void wait_for_tasks(struct perf_sched *sched)
I
Ingo Molnar 已提交
673
{
674
	u64 cpu_usage_0, cpu_usage_1;
I
Ingo Molnar 已提交
675 676 677
	struct task_desc *task;
	unsigned long i, ret;

678 679 680
	sched->start_time = get_nsecs();
	sched->cpu_usage = 0;
	pthread_mutex_unlock(&sched->work_done_wait_mutex);
I
Ingo Molnar 已提交
681

682 683
	for (i = 0; i < sched->nr_tasks; i++) {
		task = sched->tasks[i];
I
Ingo Molnar 已提交
684 685 686 687
		ret = sem_wait(&task->ready_for_work);
		BUG_ON(ret);
		sem_init(&task->ready_for_work, 0, 0);
	}
688
	ret = pthread_mutex_lock(&sched->work_done_wait_mutex);
I
Ingo Molnar 已提交
689 690 691 692
	BUG_ON(ret);

	cpu_usage_0 = get_cpu_usage_nsec_parent();

693
	pthread_mutex_unlock(&sched->start_work_mutex);
I
Ingo Molnar 已提交
694

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

	cpu_usage_1 = get_cpu_usage_nsec_parent();
705 706
	if (!sched->runavg_cpu_usage)
		sched->runavg_cpu_usage = sched->cpu_usage;
707
	sched->runavg_cpu_usage = (sched->runavg_cpu_usage * (sched->replay_repeat - 1) + sched->cpu_usage) / sched->replay_repeat;
I
Ingo Molnar 已提交
708

709 710 711
	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;
712 713
	sched->runavg_parent_cpu_usage = (sched->runavg_parent_cpu_usage * (sched->replay_repeat - 1) +
					 sched->parent_cpu_usage)/sched->replay_repeat;
I
Ingo Molnar 已提交
714

715
	ret = pthread_mutex_lock(&sched->start_work_mutex);
I
Ingo Molnar 已提交
716 717
	BUG_ON(ret);

718 719
	for (i = 0; i < sched->nr_tasks; i++) {
		task = sched->tasks[i];
I
Ingo Molnar 已提交
720 721 722 723 724
		sem_init(&task->sleep_sem, 0, 0);
		task->curr_event = 0;
	}
}

725
static void run_one_test(struct perf_sched *sched)
I
Ingo Molnar 已提交
726
{
K
Kyle McMartin 已提交
727
	u64 T0, T1, delta, avg_delta, fluct;
I
Ingo Molnar 已提交
728 729

	T0 = get_nsecs();
730
	wait_for_tasks(sched);
I
Ingo Molnar 已提交
731 732 733
	T1 = get_nsecs();

	delta = T1 - T0;
734 735
	sched->sum_runtime += delta;
	sched->nr_runs++;
I
Ingo Molnar 已提交
736

737
	avg_delta = sched->sum_runtime / sched->nr_runs;
I
Ingo Molnar 已提交
738 739 740 741
	if (delta < avg_delta)
		fluct = avg_delta - delta;
	else
		fluct = delta - avg_delta;
742 743 744
	sched->sum_fluct += fluct;
	if (!sched->run_avg)
		sched->run_avg = delta;
745
	sched->run_avg = (sched->run_avg * (sched->replay_repeat - 1) + delta) / sched->replay_repeat;
I
Ingo Molnar 已提交
746

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

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

I
Ingo Molnar 已提交
751
	printf("cpu: %0.2f / %0.2f",
752
		(double)sched->cpu_usage / NSEC_PER_MSEC, (double)sched->runavg_cpu_usage / NSEC_PER_MSEC);
I
Ingo Molnar 已提交
753 754 755

#if 0
	/*
756
	 * rusage statistics done by the parent, these are less
757
	 * accurate than the sched->sum_exec_runtime based statistics:
758
	 */
I
Ingo Molnar 已提交
759
	printf(" [%0.2f / %0.2f]",
760 761
		(double)sched->parent_cpu_usage / NSEC_PER_MSEC,
		(double)sched->runavg_parent_cpu_usage / NSEC_PER_MSEC);
I
Ingo Molnar 已提交
762 763
#endif

I
Ingo Molnar 已提交
764
	printf("\n");
I
Ingo Molnar 已提交
765

766 767 768
	if (sched->nr_sleep_corrections)
		printf(" (%ld sleep corrections)\n", sched->nr_sleep_corrections);
	sched->nr_sleep_corrections = 0;
I
Ingo Molnar 已提交
769 770
}

771
static void test_calibrations(struct perf_sched *sched)
I
Ingo Molnar 已提交
772
{
773
	u64 T0, T1;
I
Ingo Molnar 已提交
774 775

	T0 = get_nsecs();
776
	burn_nsecs(sched, NSEC_PER_MSEC);
I
Ingo Molnar 已提交
777 778
	T1 = get_nsecs();

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

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

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

788
static int
789
replay_wakeup_event(struct perf_sched *sched,
790 791
		    struct perf_evsel *evsel, struct perf_sample *sample,
		    struct machine *machine __maybe_unused)
792
{
793 794
	const char *comm = perf_evsel__strval(evsel, sample, "comm");
	const u32 pid	 = perf_evsel__intval(evsel, sample, "pid");
795
	struct task_desc *waker, *wakee;
796

I
Ingo Molnar 已提交
797
	if (verbose) {
798
		printf("sched_wakeup event %p\n", evsel);
799

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

803
	waker = register_pid(sched, sample->tid, "<unknown>");
804
	wakee = register_pid(sched, pid, comm);
805

806
	add_sched_event_wakeup(sched, waker, sample->time, wakee);
807
	return 0;
I
Ingo Molnar 已提交
808 809
}

810 811 812 813
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 已提交
814
{
815 816 817 818 819
	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");
820
	struct task_desc *prev, __maybe_unused *next;
821 822
	u64 timestamp0, timestamp = sample->time;
	int cpu = sample->cpu;
823 824
	s64 delta;

I
Ingo Molnar 已提交
825
	if (verbose)
826
		printf("sched_switch event %p\n", evsel);
I
Ingo Molnar 已提交
827

828
	if (cpu >= MAX_CPUS || cpu < 0)
829
		return 0;
830

831
	timestamp0 = sched->cpu_last_switched[cpu];
832 833 834 835 836
	if (timestamp0)
		delta = timestamp - timestamp0;
	else
		delta = 0;

837
	if (delta < 0) {
838
		pr_err("hm, delta: %" PRIu64 " < 0 ?\n", delta);
839 840
		return -1;
	}
841

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

845 846
	prev = register_pid(sched, prev_pid, prev_comm);
	next = register_pid(sched, next_pid, next_comm);
847

848
	sched->cpu_last_switched[cpu] = timestamp;
849

850
	add_sched_event_run(sched, prev, timestamp, delta);
851
	add_sched_event_sleep(sched, prev, timestamp, prev_state);
852 853

	return 0;
854 855
}

856 857 858
static int replay_fork_event(struct perf_sched *sched,
			     union perf_event *event,
			     struct machine *machine)
859
{
860 861
	struct thread *child, *parent;

862 863 864 865
	child = machine__findnew_thread(machine, event->fork.pid,
					event->fork.tid);
	parent = machine__findnew_thread(machine, event->fork.ppid,
					 event->fork.ptid);
866 867 868 869

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

873
	if (verbose) {
874
		printf("fork event\n");
875 876
		printf("... parent: %s/%d\n", thread__comm_str(parent), parent->tid);
		printf("...  child: %s/%d\n", thread__comm_str(child), child->tid);
877
	}
878

879 880
	register_pid(sched, parent->tid, thread__comm_str(parent));
	register_pid(sched, child->tid, thread__comm_str(child));
881 882 883
out_put:
	thread__put(child);
	thread__put(parent);
884
	return 0;
885
}
886

887 888
struct sort_dimension {
	const char		*name;
889
	sort_fn_t		cmp;
890 891 892
	struct list_head	list;
};

893
static int
894
thread_lat_cmp(struct list_head *list, struct work_atoms *l, struct work_atoms *r)
895 896 897 898
{
	struct sort_dimension *sort;
	int ret = 0;

899 900
	BUG_ON(list_empty(list));

901 902 903 904 905 906 907 908 909
	list_for_each_entry(sort, list, list) {
		ret = sort->cmp(l, r);
		if (ret)
			return ret;
	}

	return ret;
}

910
static struct work_atoms *
911 912 913 914
thread_atoms_search(struct rb_root *root, struct thread *thread,
			 struct list_head *sort_list)
{
	struct rb_node *node = root->rb_node;
915
	struct work_atoms key = { .thread = thread };
916 917

	while (node) {
918
		struct work_atoms *atoms;
919 920
		int cmp;

921
		atoms = container_of(node, struct work_atoms, node);
922 923 924 925 926 927 928 929 930 931 932 933 934 935

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

936
static void
937
__thread_latency_insert(struct rb_root *root, struct work_atoms *data,
938
			 struct list_head *sort_list)
939 940 941 942
{
	struct rb_node **new = &(root->rb_node), *parent = NULL;

	while (*new) {
943
		struct work_atoms *this;
944
		int cmp;
945

946
		this = container_of(*new, struct work_atoms, node);
947
		parent = *new;
948 949 950 951

		cmp = thread_lat_cmp(sort_list, data, this);

		if (cmp > 0)
952 953
			new = &((*new)->rb_left);
		else
954
			new = &((*new)->rb_right);
955 956 957 958 959 960
	}

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

961
static int thread_atoms_insert(struct perf_sched *sched, struct thread *thread)
962
{
963
	struct work_atoms *atoms = zalloc(sizeof(*atoms));
964 965 966 967
	if (!atoms) {
		pr_err("No memory at %s\n", __func__);
		return -1;
	}
968

969
	atoms->thread = thread__get(thread);
970
	INIT_LIST_HEAD(&atoms->work_list);
971
	__thread_latency_insert(&sched->atom_root, atoms, &sched->cmp_pid);
972
	return 0;
973 974
}

975
static char sched_out_state(u64 prev_state)
976 977 978
{
	const char *str = TASK_STATE_TO_CHAR_STR;

979
	return str[prev_state];
980 981
}

982
static int
983 984 985
add_sched_out_event(struct work_atoms *atoms,
		    char run_state,
		    u64 timestamp)
986
{
987
	struct work_atom *atom = zalloc(sizeof(*atom));
988 989 990 991
	if (!atom) {
		pr_err("Non memory at %s", __func__);
		return -1;
	}
992

993 994
	atom->sched_out_time = timestamp;

995
	if (run_state == 'R') {
996
		atom->state = THREAD_WAIT_CPU;
997
		atom->wake_up_time = atom->sched_out_time;
998 999
	}

1000
	list_add_tail(&atom->list, &atoms->work_list);
1001
	return 0;
1002 1003 1004
}

static void
1005 1006
add_runtime_event(struct work_atoms *atoms, u64 delta,
		  u64 timestamp __maybe_unused)
1007 1008 1009 1010 1011 1012 1013 1014 1015 1016 1017 1018 1019
{
	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)
1020
{
1021
	struct work_atom *atom;
1022
	u64 delta;
1023

1024
	if (list_empty(&atoms->work_list))
1025 1026
		return;

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

1029
	if (atom->state != THREAD_WAIT_CPU)
1030 1031
		return;

1032 1033
	if (timestamp < atom->wake_up_time) {
		atom->state = THREAD_IGNORE;
1034 1035 1036
		return;
	}

1037 1038
	atom->state = THREAD_SCHED_IN;
	atom->sched_in_time = timestamp;
1039

1040
	delta = atom->sched_in_time - atom->wake_up_time;
1041
	atoms->total_lat += delta;
1042
	if (delta > atoms->max_lat) {
1043
		atoms->max_lat = delta;
1044 1045
		atoms->max_lat_at = timestamp;
	}
1046
	atoms->nb_atoms++;
1047 1048
}

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

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

1065 1066
	timestamp0 = sched->cpu_last_switched[cpu];
	sched->cpu_last_switched[cpu] = timestamp;
I
Ingo Molnar 已提交
1067 1068 1069 1070 1071
	if (timestamp0)
		delta = timestamp - timestamp0;
	else
		delta = 0;

1072 1073 1074 1075
	if (delta < 0) {
		pr_err("hm, delta: %" PRIu64 " < 0 ?\n", delta);
		return -1;
	}
1076

1077 1078
	sched_out = machine__findnew_thread(machine, -1, prev_pid);
	sched_in = machine__findnew_thread(machine, -1, next_pid);
1079 1080
	if (sched_out == NULL || sched_in == NULL)
		goto out_put;
1081

1082
	out_events = thread_atoms_search(&sched->atom_root, sched_out, &sched->cmp_pid);
1083
	if (!out_events) {
1084
		if (thread_atoms_insert(sched, sched_out))
1085
			goto out_put;
1086
		out_events = thread_atoms_search(&sched->atom_root, sched_out, &sched->cmp_pid);
1087 1088
		if (!out_events) {
			pr_err("out-event: Internal tree error");
1089
			goto out_put;
1090
		}
1091
	}
1092
	if (add_sched_out_event(out_events, sched_out_state(prev_state), timestamp))
1093
		return -1;
1094

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

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

	if (thread == NULL)
		return -1;
1133 1134 1135

	BUG_ON(cpu >= MAX_CPUS || cpu < 0);
	if (!atoms) {
1136
		if (thread_atoms_insert(sched, thread))
1137
			goto out_put;
1138
		atoms = thread_atoms_search(&sched->atom_root, thread, &sched->cmp_pid);
1139
		if (!atoms) {
1140
			pr_err("in-event: Internal tree error");
1141
			goto out_put;
1142 1143
		}
		if (add_sched_out_event(atoms, 'R', timestamp))
1144
			goto out_put;
1145 1146
	}

1147
	add_runtime_event(atoms, runtime, timestamp);
1148 1149 1150 1151
	err = 0;
out_put:
	thread__put(thread);
	return err;
1152 1153
}

1154 1155 1156 1157
static int latency_wakeup_event(struct perf_sched *sched,
				struct perf_evsel *evsel,
				struct perf_sample *sample,
				struct machine *machine)
1158
{
1159
	const u32 pid	  = perf_evsel__intval(evsel, sample, "pid");
1160
	struct work_atoms *atoms;
1161
	struct work_atom *atom;
1162
	struct thread *wakee;
1163
	u64 timestamp = sample->time;
1164
	int err = -1;
1165

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

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

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

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

1200
	sched->nr_timestamps++;
1201
	if (atom->sched_out_time > timestamp) {
1202
		sched->nr_unordered_timestamps++;
1203
		goto out_ok;
1204
	}
1205

1206 1207
	atom->state = THREAD_WAIT_CPU;
	atom->wake_up_time = timestamp;
1208 1209 1210 1211 1212
out_ok:
	err = 0;
out_put:
	thread__put(wakee);
	return err;
1213 1214
}

1215 1216 1217 1218
static int latency_migrate_task_event(struct perf_sched *sched,
				      struct perf_evsel *evsel,
				      struct perf_sample *sample,
				      struct machine *machine)
1219
{
1220
	const u32 pid = perf_evsel__intval(evsel, sample, "pid");
1221
	u64 timestamp = sample->time;
1222 1223 1224
	struct work_atoms *atoms;
	struct work_atom *atom;
	struct thread *migrant;
1225
	int err = -1;
1226 1227 1228 1229

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

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

	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;

1255
	sched->nr_timestamps++;
1256 1257

	if (atom->sched_out_time > timestamp)
1258
		sched->nr_unordered_timestamps++;
1259 1260 1261 1262
	err = 0;
out_put:
	thread__put(migrant);
	return err;
1263 1264
}

1265
static void output_lat_thread(struct perf_sched *sched, struct work_atoms *work_list)
1266 1267 1268
{
	int i;
	int ret;
1269
	u64 avg;
1270
	char max_lat_at[32];
1271

1272
	if (!work_list->nb_atoms)
1273
		return;
1274 1275 1276
	/*
	 * Ignore idle threads:
	 */
1277
	if (!strcmp(thread__comm_str(work_list->thread), "swapper"))
1278
		return;
1279

1280 1281
	sched->all_runtime += work_list->total_runtime;
	sched->all_count   += work_list->nb_atoms;
1282

1283 1284 1285 1286
	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);
1287

M
mingo 已提交
1288
	for (i = 0; i < 24 - ret; i++)
1289 1290
		printf(" ");

1291
	avg = work_list->total_lat / work_list->nb_atoms;
1292
	timestamp__scnprintf_usec(work_list->max_lat_at, max_lat_at, sizeof(max_lat_at));
1293

1294
	printf("|%11.3f ms |%9" PRIu64 " | avg:%9.3f ms | max:%9.3f ms | max at: %13s s\n",
1295 1296 1297
	      (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,
1298
		 max_lat_at);
1299 1300
}

1301
static int pid_cmp(struct work_atoms *l, struct work_atoms *r)
1302
{
1303 1304
	if (l->thread == r->thread)
		return 0;
1305
	if (l->thread->tid < r->thread->tid)
1306
		return -1;
1307
	if (l->thread->tid > r->thread->tid)
1308
		return 1;
1309
	return (int)(l->thread - r->thread);
1310 1311
}

1312
static int avg_cmp(struct work_atoms *l, struct work_atoms *r)
1313 1314 1315 1316 1317 1318 1319 1320 1321 1322 1323 1324 1325 1326 1327 1328 1329 1330 1331 1332
{
	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;
}

1333
static int max_cmp(struct work_atoms *l, struct work_atoms *r)
1334 1335 1336 1337 1338 1339 1340 1341 1342
{
	if (l->max_lat < r->max_lat)
		return -1;
	if (l->max_lat > r->max_lat)
		return 1;

	return 0;
}

1343
static int switch_cmp(struct work_atoms *l, struct work_atoms *r)
1344 1345 1346 1347 1348 1349 1350 1351 1352
{
	if (l->nb_atoms < r->nb_atoms)
		return -1;
	if (l->nb_atoms > r->nb_atoms)
		return 1;

	return 0;
}

1353
static int runtime_cmp(struct work_atoms *l, struct work_atoms *r)
1354 1355 1356 1357 1358 1359 1360 1361 1362
{
	if (l->total_runtime < r->total_runtime)
		return -1;
	if (l->total_runtime > r->total_runtime)
		return 1;

	return 0;
}

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

1394
	for (i = 0; i < ARRAY_SIZE(available_sorts); i++) {
1395 1396 1397 1398 1399 1400 1401 1402 1403 1404
		if (!strcmp(available_sorts[i]->name, tok)) {
			list_add_tail(&available_sorts[i]->list, list);

			return 0;
		}
	}

	return -1;
}

1405
static void perf_sched__sort_lat(struct perf_sched *sched)
1406 1407
{
	struct rb_node *node;
1408 1409
	struct rb_root *root = &sched->atom_root;
again:
1410
	for (;;) {
1411
		struct work_atoms *data;
1412
		node = rb_first(root);
1413 1414 1415
		if (!node)
			break;

1416
		rb_erase(node, root);
1417
		data = rb_entry(node, struct work_atoms, node);
1418
		__thread_latency_insert(&sched->sorted_atom_root, data, &sched->sort_list);
1419
	}
1420 1421 1422 1423
	if (root == &sched->atom_root) {
		root = &sched->merged_atom_root;
		goto again;
	}
1424 1425
}

1426
static int process_sched_wakeup_event(struct perf_tool *tool,
1427
				      struct perf_evsel *evsel,
1428
				      struct perf_sample *sample,
1429
				      struct machine *machine)
1430
{
1431
	struct perf_sched *sched = container_of(tool, struct perf_sched, tool);
1432

1433 1434
	if (sched->tp_handler->wakeup_event)
		return sched->tp_handler->wakeup_event(sched, evsel, sample, machine);
1435

1436
	return 0;
1437 1438
}

J
Jiri Olsa 已提交
1439 1440 1441 1442 1443 1444 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
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;
}

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

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

1487 1488
	if (this_cpu > sched->max_cpu)
		sched->max_cpu = this_cpu;
1489

1490 1491 1492 1493 1494 1495 1496 1497 1498
	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;

1499 1500
	timestamp0 = sched->cpu_last_switched[this_cpu];
	sched->cpu_last_switched[this_cpu] = timestamp;
1501 1502 1503 1504 1505
	if (timestamp0)
		delta = timestamp - timestamp0;
	else
		delta = 0;

1506
	if (delta < 0) {
1507
		pr_err("hm, delta: %" PRIu64 " < 0 ?\n", delta);
1508 1509
		return -1;
	}
1510

J
Jiri Olsa 已提交
1511
	sched_in = map__findnew_thread(sched, machine, -1, next_pid);
1512 1513
	if (sched_in == NULL)
		return -1;
1514

1515
	sched->curr_thread[this_cpu] = thread__get(sched_in);
1516 1517 1518 1519 1520

	printf("  ");

	new_shortname = 0;
	if (!sched_in->shortname[0]) {
1521 1522 1523 1524 1525 1526 1527
		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] = ' ';
1528
		} else {
1529 1530 1531 1532 1533
			sched_in->shortname[0] = sched->next_shortname1;
			sched_in->shortname[1] = sched->next_shortname2;

			if (sched->next_shortname1 < 'Z') {
				sched->next_shortname1++;
1534
			} else {
1535 1536 1537 1538 1539
				sched->next_shortname1 = 'A';
				if (sched->next_shortname2 < '9')
					sched->next_shortname2++;
				else
					sched->next_shortname2 = '0';
1540 1541 1542 1543 1544
			}
		}
		new_shortname = 1;
	}

1545 1546
	for (i = 0; i < cpus_nr; i++) {
		int cpu = sched->map.comp ? sched->map.comp_cpus[i] : i;
J
Jiri Olsa 已提交
1547 1548
		struct thread *curr_thread = sched->curr_thread[cpu];
		const char *pid_color = color;
J
Jiri Olsa 已提交
1549
		const char *cpu_color = color;
J
Jiri Olsa 已提交
1550 1551 1552

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

1554 1555 1556
		if (sched->map.cpus && !cpu_map__has(sched->map.cpus, cpu))
			continue;

J
Jiri Olsa 已提交
1557 1558 1559
		if (sched->map.color_cpus && cpu_map__has(sched->map.color_cpus, cpu))
			cpu_color = COLOR_CPUS;

1560
		if (cpu != this_cpu)
1561
			color_fprintf(stdout, color, " ");
1562
		else
J
Jiri Olsa 已提交
1563
			color_fprintf(stdout, cpu_color, "*");
1564

1565
		if (sched->curr_thread[cpu])
J
Jiri Olsa 已提交
1566
			color_fprintf(stdout, pid_color, "%2s ", sched->curr_thread[cpu]->shortname);
1567
		else
1568
			color_fprintf(stdout, color, "   ");
1569 1570
	}

1571 1572 1573
	if (sched->map.cpus && !cpu_map__has(sched->map.cpus, this_cpu))
		goto out;

1574 1575
	timestamp__scnprintf_usec(timestamp, stimestamp, sizeof(stimestamp));
	color_fprintf(stdout, color, "  %12s secs ", stimestamp);
1576
	if (new_shortname || (verbose && sched_in->tid)) {
J
Jiri Olsa 已提交
1577 1578 1579 1580 1581 1582
		const char *pid_color = color;

		if (thread__has_color(sched_in))
			pid_color = COLOR_PIDS;

		color_fprintf(stdout, pid_color, "%s => %s:%d",
1583
		       sched_in->shortname, thread__comm_str(sched_in), sched_in->tid);
1584
	}
1585

1586
	if (sched->map.comp && new_cpu)
1587
		color_fprintf(stdout, color, " (CPU %d)", this_cpu);
1588

1589
out:
1590
	color_fprintf(stdout, color, "\n");
1591

1592 1593
	thread__put(sched_in);

1594
	return 0;
1595 1596
}

1597
static int process_sched_switch_event(struct perf_tool *tool,
1598
				      struct perf_evsel *evsel,
1599
				      struct perf_sample *sample,
1600
				      struct machine *machine)
1601
{
1602
	struct perf_sched *sched = container_of(tool, struct perf_sched, tool);
1603
	int this_cpu = sample->cpu, err = 0;
1604 1605
	u32 prev_pid = perf_evsel__intval(evsel, sample, "prev_pid"),
	    next_pid = perf_evsel__intval(evsel, sample, "next_pid");
1606

1607
	if (sched->curr_pid[this_cpu] != (u32)-1) {
1608 1609 1610 1611
		/*
		 * Are we trying to switch away a PID that is
		 * not current?
		 */
1612
		if (sched->curr_pid[this_cpu] != prev_pid)
1613
			sched->nr_context_switch_bugs++;
1614 1615
	}

1616 1617
	if (sched->tp_handler->switch_event)
		err = sched->tp_handler->switch_event(sched, evsel, sample, machine);
1618 1619

	sched->curr_pid[this_cpu] = next_pid;
1620
	return err;
1621 1622
}

1623
static int process_sched_runtime_event(struct perf_tool *tool,
1624
				       struct perf_evsel *evsel,
1625
				       struct perf_sample *sample,
1626
				       struct machine *machine)
1627
{
1628
	struct perf_sched *sched = container_of(tool, struct perf_sched, tool);
1629

1630 1631
	if (sched->tp_handler->runtime_event)
		return sched->tp_handler->runtime_event(sched, evsel, sample, machine);
1632

1633
	return 0;
1634 1635
}

1636 1637 1638 1639
static int perf_sched__process_fork_event(struct perf_tool *tool,
					  union perf_event *event,
					  struct perf_sample *sample,
					  struct machine *machine)
1640
{
1641
	struct perf_sched *sched = container_of(tool, struct perf_sched, tool);
1642

1643 1644 1645 1646
	/* 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 */
1647
	if (sched->tp_handler->fork_event)
1648
		return sched->tp_handler->fork_event(sched, event, machine);
1649

1650
	return 0;
1651 1652
}

1653
static int process_sched_migrate_task_event(struct perf_tool *tool,
1654
					    struct perf_evsel *evsel,
1655
					    struct perf_sample *sample,
1656
					    struct machine *machine)
1657
{
1658
	struct perf_sched *sched = container_of(tool, struct perf_sched, tool);
1659

1660 1661
	if (sched->tp_handler->migrate_task_event)
		return sched->tp_handler->migrate_task_event(sched, evsel, sample, machine);
1662

1663
	return 0;
1664 1665
}

1666
typedef int (*tracepoint_handler)(struct perf_tool *tool,
1667
				  struct perf_evsel *evsel,
1668
				  struct perf_sample *sample,
1669
				  struct machine *machine);
I
Ingo Molnar 已提交
1670

1671 1672
static int perf_sched__process_tracepoint_sample(struct perf_tool *tool __maybe_unused,
						 union perf_event *event __maybe_unused,
1673 1674 1675
						 struct perf_sample *sample,
						 struct perf_evsel *evsel,
						 struct machine *machine)
I
Ingo Molnar 已提交
1676
{
1677
	int err = 0;
I
Ingo Molnar 已提交
1678

1679 1680
	if (evsel->handler != NULL) {
		tracepoint_handler f = evsel->handler;
1681
		err = f(tool, evsel, sample, machine);
1682
	}
I
Ingo Molnar 已提交
1683

1684
	return err;
I
Ingo Molnar 已提交
1685 1686
}

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

1704
	session = perf_session__new(&file, false, &sched->tool);
1705 1706 1707 1708
	if (session == NULL) {
		pr_debug("No Memory for session\n");
		return -1;
	}
1709

1710
	symbol__init(&session->header.env);
1711

1712 1713
	if (perf_session__set_tracepoints_handlers(session, handlers))
		goto out_delete;
1714

1715
	if (perf_session__has_traces(session, "record -R")) {
1716
		int err = perf_session__process_events(session);
1717 1718 1719 1720
		if (err) {
			pr_err("Failed to process events, error %d", err);
			goto out_delete;
		}
1721

1722 1723 1724
		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];
1725
	}
1726

1727
	rc = 0;
1728 1729
out_delete:
	perf_session__delete(session);
1730
	return rc;
I
Ingo Molnar 已提交
1731 1732
}

1733 1734 1735 1736 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
/*
 * 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];
}

1803
static int comm_width = 30;
1804 1805 1806 1807 1808 1809 1810 1811 1812 1813 1814 1815 1816 1817 1818 1819 1820 1821 1822 1823 1824 1825 1826 1827

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

1828
static void timehist_header(struct perf_sched *sched)
1829
{
1830 1831 1832
	u32 ncpus = sched->max_cpu + 1;
	u32 i, j;

1833 1834
	printf("%15s %6s ", "time", "cpu");

1835 1836 1837 1838 1839 1840 1841 1842 1843 1844
	if (sched->show_cpu_visual) {
		printf(" ");
		for (i = 0, j = 0; i < ncpus; ++i) {
			printf("%x", j++);
			if (j > 15)
				j = 0;
		}
		printf(" ");
	}

1845
	printf(" %-*s  %9s  %9s  %9s", comm_width,
1846 1847
		"task name", "wait time", "sch delay", "run time");

1848 1849 1850
	if (sched->show_state)
		printf("  %s", "state");

1851 1852 1853 1854 1855 1856 1857
	printf("\n");

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

1858 1859 1860
	if (sched->show_cpu_visual)
		printf(" %*s ", ncpus, "");

1861
	printf(" %-*s  %9s  %9s  %9s", comm_width,
1862
	       "[tid/pid]", "(msec)", "(msec)", "(msec)");
1863

1864 1865 1866 1867 1868
	if (sched->show_state)
		printf("  %5s", "");

	printf("\n");

1869 1870 1871 1872 1873
	/*
	 * separator
	 */
	printf("%.15s %.6s ", graph_dotted_line, graph_dotted_line);

1874 1875 1876
	if (sched->show_cpu_visual)
		printf(" %.*s ", ncpus, graph_dotted_line);

1877
	printf(" %.*s  %.9s  %.9s  %.9s", comm_width,
1878 1879 1880
		graph_dotted_line, graph_dotted_line, graph_dotted_line,
		graph_dotted_line);

1881 1882 1883
	if (sched->show_state)
		printf("  %.5s", graph_dotted_line);

1884 1885 1886
	printf("\n");
}

1887 1888 1889 1890 1891 1892 1893 1894 1895 1896 1897 1898
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] : '?';
}

1899 1900
static void timehist_print_sample(struct perf_sched *sched,
				  struct perf_sample *sample,
1901
				  struct addr_location *al,
1902
				  struct thread *thread,
1903
				  u64 t, int state)
1904 1905
{
	struct thread_runtime *tr = thread__priv(thread);
1906
	u32 max_cpus = sched->max_cpu + 1;
1907
	char tstr[64];
1908
	u64 wait_time;
1909

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

1913 1914 1915 1916 1917 1918 1919 1920 1921 1922 1923 1924 1925 1926 1927 1928
	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(" ");
	}

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

1931 1932 1933
	wait_time = tr->dt_sleep + tr->dt_iowait + tr->dt_preempt;
	print_sched_time(wait_time, 6);

1934 1935
	print_sched_time(tr->dt_delay, 6);
	print_sched_time(tr->dt_run, 6);
1936

1937 1938 1939
	if (sched->show_state)
		printf(" %5c ", task_state_char(thread, state));

1940 1941 1942
	if (sched->show_wakeups)
		printf("  %-*s", comm_width, "");

1943 1944 1945 1946 1947 1948 1949 1950
	if (thread->tid == 0)
		goto out;

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

	sample__fprintf_sym(sample, al, 0,
			    EVSEL__PRINT_SYM | EVSEL__PRINT_ONELINE |
1951 1952
			    EVSEL__PRINT_CALLCHAIN_ARROW |
			    EVSEL__PRINT_SKIP_IGNORED,
1953 1954 1955
			    &callchain_cursor, stdout);

out:
1956 1957 1958 1959 1960 1961 1962 1963 1964 1965 1966 1967 1968 1969 1970 1971 1972 1973 1974 1975 1976 1977 1978 1979 1980 1981 1982 1983 1984 1985
	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;
1986 1987 1988
	r->dt_sleep   = 0;
	r->dt_iowait  = 0;
	r->dt_preempt = 0;
1989
	r->dt_run     = 0;
1990

1991 1992 1993 1994 1995 1996 1997 1998 1999 2000 2001
	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");
2002 2003 2004 2005 2006 2007 2008 2009 2010 2011
		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;
		}
2012 2013 2014
	}

	update_stats(&r->run_stats, r->dt_run);
2015 2016 2017 2018 2019 2020

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

2023 2024
static bool is_idle_sample(struct perf_sample *sample,
			   struct perf_evsel *evsel)
2025 2026
{
	/* pid 0 == swapper == idle task */
2027 2028
	if (strcmp(perf_evsel__name(evsel), "sched:sched_switch") == 0)
		return perf_evsel__intval(evsel, sample, "prev_pid") == 0;
2029

2030 2031 2032 2033 2034 2035 2036 2037 2038 2039
	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;
2040 2041 2042 2043 2044

	/* 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);
2045
		return;
2046 2047 2048
	}

	if (!symbol_conf.use_callchain || sample->callchain == NULL)
2049
		return;
2050 2051

	if (thread__resolve_callchain(thread, cursor, evsel, sample,
2052
				      NULL, NULL, sched->max_stack + 2) != 0) {
2053 2054 2055
		if (verbose)
			error("Failed to resolve callchain. Skipping\n");

2056
		return;
2057
	}
2058

2059
	callchain_cursor_commit(cursor);
2060 2061 2062 2063 2064 2065 2066 2067 2068 2069 2070 2071 2072 2073 2074 2075 2076 2077 2078

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

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

		sym = node->sym;
		if (sym && sym->name) {
			if (!strcmp(sym->name, "schedule") ||
			    !strcmp(sym->name, "__schedule") ||
			    !strcmp(sym->name, "preempt_schedule"))
				sym->ignore = 1;
		}

		callchain_cursor_advance(cursor);
	}
2079 2080
}

2081 2082 2083 2084 2085 2086 2087 2088 2089 2090 2091 2092 2093 2094 2095 2096 2097 2098
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;
}

2099 2100 2101 2102 2103 2104
/*
 * 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)
{
2105
	int i, ret;
2106 2107 2108 2109 2110

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

2111
	idle_max_cpu = ncpu;
2112 2113 2114 2115 2116 2117 2118

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

2119 2120 2121
		ret = init_idle_thread(idle_threads[i]);
		if (ret < 0)
			return ret;
2122 2123 2124 2125 2126 2127 2128 2129 2130 2131 2132 2133
	}

	return 0;
}

static void free_idle_threads(void)
{
	int i;

	if (idle_threads == NULL)
		return;

2134
	for (i = 0; i < idle_max_cpu; ++i) {
2135 2136 2137 2138 2139 2140 2141 2142 2143 2144 2145 2146 2147 2148 2149 2150 2151 2152 2153 2154 2155 2156
		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;
2157
		for (i = idle_max_cpu; i < j; ++i)
2158 2159 2160 2161 2162 2163 2164 2165 2166 2167
			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]) {
2168 2169
			if (init_idle_thread(idle_threads[cpu]) < 0)
				return NULL;
2170 2171 2172 2173 2174 2175
		}
	}

	return idle_threads[cpu];
}

2176 2177 2178 2179 2180 2181 2182 2183 2184
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);
}

2185 2186 2187 2188 2189 2190 2191 2192 2193 2194 2195 2196 2197 2198 2199 2200 2201 2202 2203 2204 2205 2206 2207 2208 2209 2210 2211 2212 2213 2214 2215
/*
 * 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;
}

2216 2217
static struct thread *timehist_get_thread(struct perf_sched *sched,
					  struct perf_sample *sample,
2218 2219 2220 2221 2222
					  struct machine *machine,
					  struct perf_evsel *evsel)
{
	struct thread *thread;

2223
	if (is_idle_sample(sample, evsel)) {
2224 2225 2226 2227 2228
		thread = get_idle_thread(sample->cpu);
		if (thread == NULL)
			pr_err("Failed to get idle thread for cpu %d.\n", sample->cpu);

	} else {
2229 2230 2231
		/* there were samples with tid 0 but non-zero pid */
		thread = machine__findnew_thread(machine, sample->pid,
						 sample->tid ?: sample->pid);
2232 2233 2234 2235
		if (thread == NULL) {
			pr_debug("Failed to get thread for tid %d. skipping sample.\n",
				 sample->tid);
		}
2236 2237

		save_task_callchain(sched, sample, evsel, machine);
2238 2239 2240 2241 2242 2243 2244 2245 2246 2247 2248 2249 2250 2251 2252 2253 2254 2255 2256 2257
		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);
		}
2258 2259 2260 2261 2262
	}

	return thread;
}

2263
static bool timehist_skip_sample(struct perf_sched *sched,
2264 2265 2266
				 struct thread *thread,
				 struct perf_evsel *evsel,
				 struct perf_sample *sample)
2267 2268 2269
{
	bool rc = false;

2270
	if (thread__is_filtered(thread)) {
2271
		rc = true;
2272 2273
		sched->skipped_samples++;
	}
2274

2275 2276 2277 2278 2279 2280 2281 2282
	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;
	}

2283 2284 2285
	return rc;
}

2286
static void timehist_print_wakeup_event(struct perf_sched *sched,
2287
					struct perf_evsel *evsel,
2288 2289 2290 2291 2292 2293 2294 2295 2296 2297 2298 2299
					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 */
2300 2301
	if (timehist_skip_sample(sched, thread, evsel, sample) &&
	    timehist_skip_sample(sched, awakened, evsel, sample)) {
2302 2303 2304 2305 2306
		return;
	}

	timestamp__scnprintf_usec(sample->time, tstr, sizeof(tstr));
	printf("%15s [%04d] ", tstr, sample->cpu);
2307 2308
	if (sched->show_cpu_visual)
		printf(" %*s ", sched->max_cpu + 1, "");
2309 2310 2311 2312 2313 2314 2315 2316 2317 2318 2319 2320

	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,
2321 2322 2323 2324 2325
				       union perf_event *event __maybe_unused,
				       struct perf_evsel *evsel,
				       struct perf_sample *sample,
				       struct machine *machine)
{
2326
	struct perf_sched *sched = container_of(tool, struct perf_sched, tool);
2327 2328 2329 2330 2331 2332 2333 2334 2335 2336 2337 2338 2339 2340 2341 2342
	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;

2343
	/* show wakeups if requested */
2344 2345
	if (sched->show_wakeups &&
	    !perf_time__skip_sample(&sched->ptime, sample->time))
2346
		timehist_print_wakeup_event(sched, evsel, sample, machine, thread);
2347

2348 2349 2350
	return 0;
}

2351 2352 2353 2354 2355 2356 2357 2358 2359 2360 2361 2362 2363 2364 2365 2366 2367 2368 2369 2370 2371 2372
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;

2373 2374
	if (timehist_skip_sample(sched, thread, evsel, sample) &&
	    timehist_skip_sample(sched, migrated, evsel, sample)) {
2375 2376 2377 2378 2379 2380 2381 2382 2383 2384 2385 2386 2387 2388 2389 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
		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;
}

2432
static int timehist_sched_change_event(struct perf_tool *tool,
2433 2434 2435 2436 2437
				       union perf_event *event,
				       struct perf_evsel *evsel,
				       struct perf_sample *sample,
				       struct machine *machine)
{
2438
	struct perf_sched *sched = container_of(tool, struct perf_sched, tool);
2439
	struct perf_time_interval *ptime = &sched->ptime;
2440 2441 2442
	struct addr_location al;
	struct thread *thread;
	struct thread_runtime *tr = NULL;
2443
	u64 tprev, t = sample->time;
2444
	int rc = 0;
2445 2446
	int state = perf_evsel__intval(evsel, sample, "prev_state");

2447 2448 2449 2450 2451 2452 2453 2454

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

2455
	thread = timehist_get_thread(sched, sample, machine, evsel);
2456 2457 2458 2459 2460
	if (thread == NULL) {
		rc = -1;
		goto out;
	}

2461
	if (timehist_skip_sample(sched, thread, evsel, sample))
2462 2463 2464 2465 2466 2467 2468 2469 2470 2471
		goto out;

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

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

2472 2473 2474 2475 2476 2477 2478 2479
	/*
	 * 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;

2480
	if (tprev && ptime->start > tprev)
2481 2482 2483 2484 2485 2486 2487 2488 2489 2490 2491 2492 2493 2494 2495 2496
		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;
	}

2497 2498 2499 2500 2501 2502 2503 2504 2505 2506 2507 2508 2509 2510 2511 2512 2513 2514 2515 2516 2517 2518 2519 2520 2521
	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;
2522 2523 2524
			last_tr->dt_sleep = 0;
			last_tr->dt_iowait = 0;
			last_tr->dt_preempt = 0;
2525

2526 2527 2528
			if (itr->cursor.nr)
				callchain_append(&itr->callchain, &itr->cursor, t - tprev);

2529 2530 2531
			itr->last_thread = NULL;
		}
	}
2532

2533
	if (!sched->summary_only)
2534
		timehist_print_sample(sched, sample, &al, thread, t, state);
2535 2536

out:
2537 2538 2539 2540 2541
	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;

2542 2543 2544 2545
	if (tr) {
		/* time of this sched_switch event becomes last time task seen */
		tr->last_time = sample->time;

2546
		/* last state is used to determine where to account wait time */
2547
		tr->last_state = state;
2548

2549 2550 2551 2552 2553 2554 2555 2556 2557 2558 2559 2560 2561 2562 2563 2564 2565 2566 2567 2568 2569 2570 2571 2572 2573 2574 2575 2576 2577 2578 2579 2580 2581
		/* 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;
}


2582 2583 2584 2585 2586 2587 2588 2589 2590 2591 2592 2593 2594 2595 2596 2597 2598 2599 2600
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);
2601
	printf("   %5" PRIu64, r->migrations);
2602 2603 2604
	printf("\n");
}

2605 2606 2607 2608 2609 2610 2611 2612 2613 2614 2615 2616 2617 2618 2619 2620 2621 2622
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");
}

2623
struct total_run_stats {
2624
	struct perf_sched *sched;
2625 2626 2627 2628 2629 2630 2631 2632 2633 2634 2635 2636 2637 2638 2639 2640 2641 2642
	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;
2643 2644 2645 2646 2647

		if (stats->sched->show_state)
			print_thread_waittime(t, r);
		else
			print_thread_runtime(t, r);
2648 2649 2650 2651 2652 2653 2654 2655 2656 2657 2658 2659 2660 2661 2662 2663 2664 2665 2666 2667 2668
	}

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

2669 2670 2671 2672 2673 2674 2675 2676 2677 2678 2679 2680 2681 2682 2683 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
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;
}

2723 2724 2725 2726 2727 2728 2729 2730 2731
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;
2732
	u64 hist_time = sched->hist_time.end - sched->hist_time.start;
2733 2734

	memset(&totals, 0, sizeof(totals));
2735
	totals.sched = sched;
2736

2737 2738 2739 2740
	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");
2741 2742 2743 2744
	} 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");
2745 2746 2747 2748 2749
	} 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");
	}
2750
	printf("%*s            (count)  ", comm_width, "");
2751 2752
	printf("     (msec)     (msec)      (msec)      (msec)       %s\n",
	       sched->show_state ? "(msec)" : "%");
2753
	printf("%.117s\n", graph_dotted_line);
2754 2755 2756 2757 2758 2759 2760 2761 2762 2763 2764 2765

	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 */
2766
	if (sched->skipped_samples && !sched->idle_hist)
2767 2768 2769
		return;

	printf("\nIdle stats:\n");
2770
	for (i = 0; i < idle_max_cpu; ++i) {
2771 2772 2773 2774 2775 2776 2777 2778 2779
		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);
2780
			printf(" msec  (%6.2f%%)\n", 100.0 * r->total_run_time / hist_time);
2781 2782 2783 2784
		} else
			printf("    CPU %2d idle entire time window\n", i);
	}

2785 2786 2787 2788 2789 2790 2791 2792 2793 2794 2795 2796 2797 2798 2799 2800 2801 2802 2803 2804 2805 2806 2807 2808 2809 2810 2811 2812 2813
	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");
		}
	}

2814 2815
	printf("\n"
	       "    Total number of unique tasks: %" PRIu64 "\n"
2816
	       "Total number of context switches: %" PRIu64 "\n",
2817 2818
	       totals.task_count, totals.sched_count);

2819
	printf("           Total run time (msec): ");
2820 2821
	print_sched_time(totals.total_run_time, 2);
	printf("\n");
2822 2823 2824 2825

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

2828 2829 2830 2831 2832 2833 2834 2835 2836 2837 2838 2839 2840 2841 2842 2843 2844 2845 2846 2847 2848 2849 2850 2851 2852 2853 2854 2855
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;
}

2856 2857 2858 2859 2860 2861 2862 2863 2864 2865 2866 2867 2868 2869 2870 2871 2872 2873 2874 2875 2876 2877 2878 2879
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;
}

2880 2881 2882 2883 2884 2885 2886
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, },
	};
2887 2888 2889
	const struct perf_evsel_str_handler migrate_handlers[] = {
		{ "sched:sched_migrate_task", timehist_migrate_task_event, },
	};
2890 2891 2892
	struct perf_data_file file = {
		.path = input_name,
		.mode = PERF_DATA_MODE_READ,
2893
		.force = sched->force,
2894 2895 2896
	};

	struct perf_session *session;
2897
	struct perf_evlist *evlist;
2898 2899 2900 2901 2902 2903 2904 2905 2906 2907 2908 2909 2910 2911 2912 2913 2914 2915
	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;

2916 2917
	symbol_conf.use_callchain = sched->show_callchain;

2918 2919 2920 2921
	session = perf_session__new(&file, false, &sched->tool);
	if (session == NULL)
		return -ENOMEM;

2922 2923
	evlist = session->evlist;

2924 2925
	symbol__init(&session->header.env);

2926 2927 2928 2929 2930
	if (perf_time__parse_str(&sched->ptime, sched->time_str) != 0) {
		pr_err("Invalid time string\n");
		return -EINVAL;
	}

2931 2932 2933
	if (timehist_check_attr(sched, evlist) != 0)
		goto out;

2934 2935 2936 2937 2938 2939
	setup_pager();

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

2940 2941 2942 2943
	/* 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");
2944
		goto out;
2945
	}
2946

2947 2948 2949 2950
	if (sched->show_migrations &&
	    perf_session__set_tracepoints_handlers(session, migrate_handlers))
		goto out;

2951 2952 2953 2954 2955 2956 2957
	/* 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;

2958 2959 2960 2961 2962
	/* 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)
2963
		timehist_header(sched);
2964 2965 2966 2967 2968 2969 2970

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

2971 2972 2973 2974 2975 2976 2977
	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);

2978 2979 2980 2981 2982 2983 2984 2985
out:
	free_idle_threads();
	perf_session__delete(session);

	return err;
}


2986
static void print_bad_events(struct perf_sched *sched)
2987
{
2988
	if (sched->nr_unordered_timestamps && sched->nr_timestamps) {
2989
		printf("  INFO: %.3f%% unordered timestamps (%ld out of %ld)\n",
2990 2991
			(double)sched->nr_unordered_timestamps/(double)sched->nr_timestamps*100.0,
			sched->nr_unordered_timestamps, sched->nr_timestamps);
2992
	}
2993
	if (sched->nr_lost_events && sched->nr_events) {
2994
		printf("  INFO: %.3f%% lost events (%ld out of %ld, in %ld chunks)\n",
2995 2996
			(double)sched->nr_lost_events/(double)sched->nr_events * 100.0,
			sched->nr_lost_events, sched->nr_events, sched->nr_lost_chunks);
2997
	}
2998
	if (sched->nr_context_switch_bugs && sched->nr_timestamps) {
2999
		printf("  INFO: %.3f%% context switch bugs (%ld out of %ld)",
3000 3001 3002
			(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)
3003 3004 3005 3006 3007
			printf(" (due to lost events?)");
		printf("\n");
	}
}

3008 3009 3010 3011 3012 3013 3014 3015 3016 3017 3018 3019 3020 3021 3022 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
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);
	}
}

3061
static int perf_sched__lat(struct perf_sched *sched)
3062 3063 3064 3065
{
	struct rb_node *next;

	setup_pager();
3066

3067
	if (perf_sched__read_events(sched))
3068
		return -1;
3069

3070
	perf_sched__merge_lat(sched);
3071
	perf_sched__sort_lat(sched);
3072

3073 3074 3075
	printf("\n -----------------------------------------------------------------------------------------------------------------\n");
	printf("  Task                  |   Runtime ms  | Switches | Average delay ms | Maximum delay ms | Maximum delay at       |\n");
	printf(" -----------------------------------------------------------------------------------------------------------------\n");
3076

3077
	next = rb_first(&sched->sorted_atom_root);
3078 3079 3080 3081 3082

	while (next) {
		struct work_atoms *work_list;

		work_list = rb_entry(next, struct work_atoms, node);
3083
		output_lat_thread(sched, work_list);
3084
		next = rb_next(next);
3085
		thread__zput(work_list->thread);
3086 3087
	}

3088
	printf(" -----------------------------------------------------------------------------------------------------------------\n");
3089
	printf("  TOTAL:                |%11.3f ms |%9" PRIu64 " |\n",
3090
		(double)sched->all_runtime / NSEC_PER_MSEC, sched->all_count);
3091 3092 3093

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

3094
	print_bad_events(sched);
3095 3096
	printf("\n");

3097
	return 0;
3098 3099
}

3100 3101
static int setup_map_cpus(struct perf_sched *sched)
{
3102 3103
	struct cpu_map *map;

3104 3105 3106 3107
	sched->max_cpu  = sysconf(_SC_NPROCESSORS_CONF);

	if (sched->map.comp) {
		sched->map.comp_cpus = zalloc(sched->max_cpu * sizeof(int));
J
Jiri Olsa 已提交
3108 3109
		if (!sched->map.comp_cpus)
			return -1;
3110 3111
	}

3112 3113 3114 3115 3116 3117 3118 3119 3120 3121
	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;
3122 3123 3124
	return 0;
}

J
Jiri Olsa 已提交
3125 3126 3127 3128 3129 3130 3131 3132 3133 3134 3135 3136 3137 3138 3139 3140 3141
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 已提交
3142 3143 3144 3145 3146 3147 3148 3149 3150 3151 3152 3153 3154 3155 3156 3157 3158
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;
}

3159
static int perf_sched__map(struct perf_sched *sched)
3160
{
3161 3162
	if (setup_map_cpus(sched))
		return -1;
3163

J
Jiri Olsa 已提交
3164 3165 3166
	if (setup_color_pids(sched))
		return -1;

J
Jiri Olsa 已提交
3167 3168 3169
	if (setup_color_cpus(sched))
		return -1;

3170
	setup_pager();
3171
	if (perf_sched__read_events(sched))
3172
		return -1;
3173
	print_bad_events(sched);
3174
	return 0;
3175 3176
}

3177
static int perf_sched__replay(struct perf_sched *sched)
3178 3179 3180
{
	unsigned long i;

3181 3182
	calibrate_run_measurement_overhead(sched);
	calibrate_sleep_measurement_overhead(sched);
3183

3184
	test_calibrations(sched);
3185

3186
	if (perf_sched__read_events(sched))
3187
		return -1;
3188

3189 3190 3191
	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);
3192

3193 3194 3195 3196 3197
	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)
3198
		printf("run atoms optimized: %ld\n",
3199
			sched->nr_run_events_optimized);
3200

3201 3202
	print_task_traces(sched);
	add_cross_task_wakeups(sched);
3203

3204
	create_tasks(sched);
3205
	printf("------------------------------------------------------------\n");
3206 3207
	for (i = 0; i < sched->replay_repeat; i++)
		run_one_test(sched);
3208 3209

	return 0;
3210 3211
}

3212 3213
static void setup_sorting(struct perf_sched *sched, const struct option *options,
			  const char * const usage_msg[])
3214
{
3215
	char *tmp, *tok, *str = strdup(sched->sort_order);
3216 3217 3218

	for (tok = strtok_r(str, ", ", &tmp);
			tok; tok = strtok_r(NULL, ", ", &tmp)) {
3219
		if (sort_dimension__add(tok, &sched->sort_list) < 0) {
3220 3221
			usage_with_options_msg(usage_msg, options,
					"Unknown --sort key: `%s'", tok);
3222 3223 3224 3225 3226
		}
	}

	free(str);

3227
	sort_dimension__add("pid", &sched->cmp_pid);
3228 3229
}

3230 3231 3232 3233
static int __cmd_record(int argc, const char **argv)
{
	unsigned int rec_argc, i, j;
	const char **rec_argv;
3234 3235 3236 3237 3238 3239 3240 3241 3242 3243 3244 3245 3246
	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",
3247
		"-e", "sched:sched_wakeup_new",
3248 3249
		"-e", "sched:sched_migrate_task",
	};
3250 3251 3252 3253

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

3254
	if (rec_argv == NULL)
3255 3256
		return -ENOMEM;

3257 3258 3259 3260 3261 3262 3263 3264 3265 3266 3267
	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);

	return cmd_record(i, rec_argv, NULL);
}

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

3352 3353 3354 3355 3356 3357 3358 3359
	const char * const latency_usage[] = {
		"perf sched latency [<options>]",
		NULL
	};
	const char * const replay_usage[] = {
		"perf sched replay [<options>]",
		NULL
	};
3360 3361 3362 3363
	const char * const map_usage[] = {
		"perf sched map [<options>]",
		NULL
	};
3364 3365 3366 3367
	const char * const timehist_usage[] = {
		"perf sched timehist [<options>]",
		NULL
	};
3368
	const char *const sched_subcommands[] = { "record", "latency", "map",
3369 3370
						  "replay", "script",
						  "timehist", NULL };
3371 3372
	const char *sched_usage[] = {
		NULL,
3373 3374 3375 3376 3377 3378 3379 3380 3381 3382 3383 3384 3385 3386 3387 3388
		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 已提交
3389 3390 3391 3392
	unsigned int i;

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

3394 3395
	argc = parse_options_subcommand(argc, argv, sched_options, sched_subcommands,
					sched_usage, PARSE_OPT_STOP_AT_NON_OPTION);
3396 3397
	if (!argc)
		usage_with_options(sched_usage, sched_options);
I
Ingo Molnar 已提交
3398

3399
	/*
3400
	 * Aliased to 'perf script' for now:
3401
	 */
3402 3403
	if (!strcmp(argv[0], "script"))
		return cmd_script(argc, argv, prefix);
3404

3405 3406 3407
	if (!strncmp(argv[0], "rec", 3)) {
		return __cmd_record(argc, argv);
	} else if (!strncmp(argv[0], "lat", 3)) {
3408
		sched.tp_handler = &lat_ops;
3409 3410 3411 3412 3413
		if (argc > 1) {
			argc = parse_options(argc, argv, latency_options, latency_usage, 0);
			if (argc)
				usage_with_options(latency_usage, latency_options);
		}
3414 3415
		setup_sorting(&sched, latency_options, latency_usage);
		return perf_sched__lat(&sched);
3416
	} else if (!strcmp(argv[0], "map")) {
3417
		if (argc) {
J
Jiri Olsa 已提交
3418
			argc = parse_options(argc, argv, map_options, map_usage, 0);
3419 3420 3421
			if (argc)
				usage_with_options(map_usage, map_options);
		}
3422 3423 3424
		sched.tp_handler = &map_ops;
		setup_sorting(&sched, latency_options, latency_usage);
		return perf_sched__map(&sched);
3425
	} else if (!strncmp(argv[0], "rep", 3)) {
3426
		sched.tp_handler = &replay_ops;
3427 3428 3429 3430 3431
		if (argc) {
			argc = parse_options(argc, argv, replay_options, replay_usage, 0);
			if (argc)
				usage_with_options(replay_usage, replay_options);
		}
3432
		return perf_sched__replay(&sched);
3433 3434 3435 3436 3437 3438 3439
	} 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);
		}
3440 3441 3442 3443 3444 3445 3446
		if (sched.show_wakeups && sched.summary_only) {
			pr_err(" Error: -s and -w are mutually exclusive.\n");
			parse_options_usage(timehist_usage, timehist_options, "s", true);
			parse_options_usage(NULL, timehist_options, "w", true);
			return -EINVAL;
		}

3447
		return perf_sched__timehist(&sched);
3448 3449 3450 3451
	} else {
		usage_with_options(sched_usage, sched_options);
	}

I
Ingo Molnar 已提交
3452
	return 0;
I
Ingo Molnar 已提交
3453
}