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

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

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

#include "util/debug.h"

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

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

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

43
struct sched_atom;
I
Ingo Molnar 已提交
44

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

50 51
	unsigned long		nr_events;
	unsigned long		curr_event;
52
	struct sched_atom	**atoms;
53 54 55

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

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

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

80
#define TASK_STATE_TO_CHAR_STR "RSDTtZXxKWP"
81

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

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

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

126
typedef int (*sort_fn_t)(struct work_atoms *, struct work_atoms *);
127

128
struct perf_sched;
129

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

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

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

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

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

J
Jiri Olsa 已提交
150
#define COLOR_PIDS PERF_COLOR_BLUE
J
Jiri Olsa 已提交
151
#define COLOR_CPUS PERF_COLOR_BG_RED
J
Jiri Olsa 已提交
152

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

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

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

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

	struct stats run_stats;
	u64 total_run_time;
247 248 249 250
	u64 total_sleep_time;
	u64 total_iowait_time;
	u64 total_preempt_time;
	u64 total_delay_time;
251

252
	int last_state;
253
	u64 migrations;
254 255 256 257 258 259 260 261
};

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

262 263 264 265 266 267 268 269 270
/* 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;
};

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

276
static u64 get_nsecs(void)
I
Ingo Molnar 已提交
277 278 279 280 281
{
	struct timespec ts;

	clock_gettime(CLOCK_MONOTONIC, &ts);

282
	return ts.tv_sec * NSEC_PER_SEC + ts.tv_nsec;
I
Ingo Molnar 已提交
283 284
}

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

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

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

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

	nanosleep(&ts, NULL);
}

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

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

318
	printf("run measurement overhead: %" PRIu64 " nsecs\n", min_delta);
I
Ingo Molnar 已提交
319 320
}

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

336
	printf("sleep measurement overhead: %" PRIu64 " nsecs\n", min_delta);
I
Ingo Molnar 已提交
337 338
}

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

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

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

354
	task->atoms[idx] = event;
I
Ingo Molnar 已提交
355 356 357 358

	return event;
}

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

364
	return task->atoms[task->nr_events - 1];
I
Ingo Molnar 已提交
365 366
}

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

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

	event = get_new_event(task, timestamp);

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

387
	sched->nr_run_events++;
I
Ingo Molnar 已提交
388 389
}

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

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

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

414
	sched->nr_wakeup_events++;
I
Ingo Molnar 已提交
415 416
}

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

	event->type = SCHED_EVENT_SLEEP;

424
	sched->nr_sleep_events++;
I
Ingo Molnar 已提交
425 426
}

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

433 434 435 436 437
	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);
	}
438 439 440 441 442 443
	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 已提交
444

445
	task = sched->pid_to_task[pid];
I
Ingo Molnar 已提交
446 447 448 449

	if (task)
		return task;

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

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

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

	return task;
}


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

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

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

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

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

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

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

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

535 536
	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 已提交
537 538 539 540

	return sum;
}

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

549
	memset(&attr, 0, sizeof(attr));
I
Ingo Molnar 已提交
550

551 552
	attr.type = PERF_TYPE_SOFTWARE;
	attr.config = PERF_COUNT_SW_TASK_CLOCK;
I
Ingo Molnar 已提交
553

554
force_again:
555 556
	fd = sys_perf_event_open(&attr, 0, -1, -1,
				 perf_event_open_cloexec_flag());
557

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

594 595 596
struct sched_thread_parms {
	struct task_desc  *task;
	struct perf_sched *sched;
597
	int fd;
598 599
};

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

610
	zfree(&parms);
611

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

624
	cpu_usage_0 = get_cpu_usage_nsec_self(fd);
I
Ingo Molnar 已提交
625 626 627

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

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

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

	goto again;
}

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

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

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

681 682 683
	sched->start_time = get_nsecs();
	sched->cpu_usage = 0;
	pthread_mutex_unlock(&sched->work_done_wait_mutex);
I
Ingo Molnar 已提交
684

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

	cpu_usage_0 = get_cpu_usage_nsec_parent();

696
	pthread_mutex_unlock(&sched->start_work_mutex);
I
Ingo Molnar 已提交
697

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

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

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

718
	ret = pthread_mutex_lock(&sched->start_work_mutex);
I
Ingo Molnar 已提交
719 720
	BUG_ON(ret);

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

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

	T0 = get_nsecs();
733
	wait_for_tasks(sched);
I
Ingo Molnar 已提交
734 735 736
	T1 = get_nsecs();

	delta = T1 - T0;
737 738
	sched->sum_runtime += delta;
	sched->nr_runs++;
I
Ingo Molnar 已提交
739

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

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

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

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

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

I
Ingo Molnar 已提交
767
	printf("\n");
I
Ingo Molnar 已提交
768

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

774
static void test_calibrations(struct perf_sched *sched)
I
Ingo Molnar 已提交
775
{
776
	u64 T0, T1;
I
Ingo Molnar 已提交
777 778

	T0 = get_nsecs();
779
	burn_nsecs(sched, NSEC_PER_MSEC);
I
Ingo Molnar 已提交
780 781
	T1 = get_nsecs();

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

	T0 = get_nsecs();
785
	sleep_nsecs(NSEC_PER_MSEC);
I
Ingo Molnar 已提交
786 787
	T1 = get_nsecs();

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

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

800
	if (verbose > 0) {
801
		printf("sched_wakeup event %p\n", evsel);
802

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

806
	waker = register_pid(sched, sample->tid, "<unknown>");
807
	wakee = register_pid(sched, pid, comm);
808

809
	add_sched_event_wakeup(sched, waker, sample->time, wakee);
810
	return 0;
I
Ingo Molnar 已提交
811 812
}

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

828
	if (verbose > 0)
829
		printf("sched_switch event %p\n", evsel);
I
Ingo Molnar 已提交
830

831
	if (cpu >= MAX_CPUS || cpu < 0)
832
		return 0;
833

834
	timestamp0 = sched->cpu_last_switched[cpu];
835 836 837 838 839
	if (timestamp0)
		delta = timestamp - timestamp0;
	else
		delta = 0;

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

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

848 849
	prev = register_pid(sched, prev_pid, prev_comm);
	next = register_pid(sched, next_pid, next_comm);
850

851
	sched->cpu_last_switched[cpu] = timestamp;
852

853
	add_sched_event_run(sched, prev, timestamp, delta);
854
	add_sched_event_sleep(sched, prev, timestamp, prev_state);
855 856

	return 0;
857 858
}

859 860 861
static int replay_fork_event(struct perf_sched *sched,
			     union perf_event *event,
			     struct machine *machine)
862
{
863 864
	struct thread *child, *parent;

865 866 867 868
	child = machine__findnew_thread(machine, event->fork.pid,
					event->fork.tid);
	parent = machine__findnew_thread(machine, event->fork.ppid,
					 event->fork.ptid);
869 870 871 872

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

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

882 883
	register_pid(sched, parent->tid, thread__comm_str(parent));
	register_pid(sched, child->tid, thread__comm_str(child));
884 885 886
out_put:
	thread__put(child);
	thread__put(parent);
887
	return 0;
888
}
889

890 891
struct sort_dimension {
	const char		*name;
892
	sort_fn_t		cmp;
893 894 895
	struct list_head	list;
};

896
static int
897
thread_lat_cmp(struct list_head *list, struct work_atoms *l, struct work_atoms *r)
898 899 900 901
{
	struct sort_dimension *sort;
	int ret = 0;

902 903
	BUG_ON(list_empty(list));

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

	return ret;
}

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

	while (node) {
921
		struct work_atoms *atoms;
922 923
		int cmp;

924
		atoms = container_of(node, struct work_atoms, node);
925 926 927 928 929 930 931 932 933 934 935 936 937 938

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

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

	while (*new) {
946
		struct work_atoms *this;
947
		int cmp;
948

949
		this = container_of(*new, struct work_atoms, node);
950
		parent = *new;
951 952 953 954

		cmp = thread_lat_cmp(sort_list, data, this);

		if (cmp > 0)
955 956
			new = &((*new)->rb_left);
		else
957
			new = &((*new)->rb_right);
958 959 960 961 962 963
	}

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

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

972
	atoms->thread = thread__get(thread);
973
	INIT_LIST_HEAD(&atoms->work_list);
974
	__thread_latency_insert(&sched->atom_root, atoms, &sched->cmp_pid);
975
	return 0;
976 977
}

978
static char sched_out_state(u64 prev_state)
979 980 981
{
	const char *str = TASK_STATE_TO_CHAR_STR;

982
	return str[prev_state];
983 984
}

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

996 997
	atom->sched_out_time = timestamp;

998
	if (run_state == 'R') {
999
		atom->state = THREAD_WAIT_CPU;
1000
		atom->wake_up_time = atom->sched_out_time;
1001 1002
	}

1003
	list_add_tail(&atom->list, &atoms->work_list);
1004
	return 0;
1005 1006 1007
}

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

1027
	if (list_empty(&atoms->work_list))
1028 1029
		return;

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

1032
	if (atom->state != THREAD_WAIT_CPU)
1033 1034
		return;

1035 1036
	if (timestamp < atom->wake_up_time) {
		atom->state = THREAD_IGNORE;
1037 1038 1039
		return;
	}

1040 1041
	atom->state = THREAD_SCHED_IN;
	atom->sched_in_time = timestamp;
1042

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

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

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

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

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

1080 1081
	sched_out = machine__findnew_thread(machine, -1, prev_pid);
	sched_in = machine__findnew_thread(machine, -1, next_pid);
1082 1083
	if (sched_out == NULL || sched_in == NULL)
		goto out_put;
1084

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

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

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

	if (thread == NULL)
		return -1;
1136 1137 1138

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

1150
	add_runtime_event(atoms, runtime, timestamp);
1151 1152 1153 1154
	err = 0;
out_put:
	thread__put(thread);
	return err;
1155 1156
}

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

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

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

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

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

1203
	sched->nr_timestamps++;
1204
	if (atom->sched_out_time > timestamp) {
1205
		sched->nr_unordered_timestamps++;
1206
		goto out_ok;
1207
	}
1208

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

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

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

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

	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;

1258
	sched->nr_timestamps++;
1259 1260

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

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

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

1283 1284
	sched->all_runtime += work_list->total_runtime;
	sched->all_count   += work_list->nb_atoms;
1285

1286 1287 1288 1289
	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);
1290

M
mingo 已提交
1291
	for (i = 0; i < 24 - ret; i++)
1292 1293
		printf(" ");

1294
	avg = work_list->total_lat / work_list->nb_atoms;
1295
	timestamp__scnprintf_usec(work_list->max_lat_at, max_lat_at, sizeof(max_lat_at));
1296

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

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

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

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

	return 0;
}

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

	return 0;
}

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

	return 0;
}

1366
static int sort_dimension__add(const char *tok, struct list_head *list)
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 1393 1394 1395
	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,
	};
1396

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

			return 0;
		}
	}

	return -1;
}

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

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

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

1436 1437
	if (sched->tp_handler->wakeup_event)
		return sched->tp_handler->wakeup_event(sched, evsel, sample, machine);
1438

1439
	return 0;
1440 1441
}

J
Jiri Olsa 已提交
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 1471 1472 1473
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;
}

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

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

1490 1491
	if (this_cpu > sched->max_cpu)
		sched->max_cpu = this_cpu;
1492

1493 1494 1495 1496 1497 1498 1499 1500 1501
	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;

1502 1503
	timestamp0 = sched->cpu_last_switched[this_cpu];
	sched->cpu_last_switched[this_cpu] = timestamp;
1504 1505 1506 1507 1508
	if (timestamp0)
		delta = timestamp - timestamp0;
	else
		delta = 0;

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

J
Jiri Olsa 已提交
1514
	sched_in = map__findnew_thread(sched, machine, -1, next_pid);
1515 1516
	if (sched_in == NULL)
		return -1;
1517

1518
	sched->curr_thread[this_cpu] = thread__get(sched_in);
1519 1520 1521 1522 1523

	printf("  ");

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

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

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

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

1557 1558 1559
		if (sched->map.cpus && !cpu_map__has(sched->map.cpus, cpu))
			continue;

J
Jiri Olsa 已提交
1560 1561 1562
		if (sched->map.color_cpus && cpu_map__has(sched->map.color_cpus, cpu))
			cpu_color = COLOR_CPUS;

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

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

1574 1575 1576
	if (sched->map.cpus && !cpu_map__has(sched->map.cpus, this_cpu))
		goto out;

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

		if (thread__has_color(sched_in))
			pid_color = COLOR_PIDS;

		color_fprintf(stdout, pid_color, "%s => %s:%d",
1586
		       sched_in->shortname, thread__comm_str(sched_in), sched_in->tid);
1587
	}
1588

1589
	if (sched->map.comp && new_cpu)
1590
		color_fprintf(stdout, color, " (CPU %d)", this_cpu);
1591

1592
out:
1593
	color_fprintf(stdout, color, "\n");
1594

1595 1596
	thread__put(sched_in);

1597
	return 0;
1598 1599
}

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

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

1619 1620
	if (sched->tp_handler->switch_event)
		err = sched->tp_handler->switch_event(sched, evsel, sample, machine);
1621 1622

	sched->curr_pid[this_cpu] = next_pid;
1623
	return err;
1624 1625
}

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

1633 1634
	if (sched->tp_handler->runtime_event)
		return sched->tp_handler->runtime_event(sched, evsel, sample, machine);
1635

1636
	return 0;
1637 1638
}

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

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

1653
	return 0;
1654 1655
}

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

1663 1664
	if (sched->tp_handler->migrate_task_event)
		return sched->tp_handler->migrate_task_event(sched, evsel, sample, machine);
1665

1666
	return 0;
1667 1668
}

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

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

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

1687
	return err;
I
Ingo Molnar 已提交
1688 1689
}

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

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

1713
	symbol__init(&session->header.env);
1714

1715 1716
	if (perf_session__set_tracepoints_handlers(session, handlers))
		goto out_delete;
1717

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

1725 1726 1727
		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];
1728
	}
1729

1730
	rc = 0;
1731 1732
out_delete:
	perf_session__delete(session);
1733
	return rc;
I
Ingo Molnar 已提交
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 1803 1804 1805
/*
 * 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];
}

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

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

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

1836 1837
	printf("%15s %6s ", "time", "cpu");

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

1848
	printf(" %-*s  %9s  %9s  %9s", comm_width,
1849 1850
		"task name", "wait time", "sch delay", "run time");

1851 1852 1853
	if (sched->show_state)
		printf("  %s", "state");

1854 1855 1856 1857 1858 1859 1860
	printf("\n");

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

1861 1862 1863
	if (sched->show_cpu_visual)
		printf(" %*s ", ncpus, "");

1864
	printf(" %-*s  %9s  %9s  %9s", comm_width,
1865
	       "[tid/pid]", "(msec)", "(msec)", "(msec)");
1866

1867 1868 1869 1870 1871
	if (sched->show_state)
		printf("  %5s", "");

	printf("\n");

1872 1873 1874 1875 1876
	/*
	 * separator
	 */
	printf("%.15s %.6s ", graph_dotted_line, graph_dotted_line);

1877 1878 1879
	if (sched->show_cpu_visual)
		printf(" %.*s ", ncpus, graph_dotted_line);

1880
	printf(" %.*s  %.9s  %.9s  %.9s", comm_width,
1881 1882 1883
		graph_dotted_line, graph_dotted_line, graph_dotted_line,
		graph_dotted_line);

1884 1885 1886
	if (sched->show_state)
		printf("  %.5s", graph_dotted_line);

1887 1888 1889
	printf("\n");
}

1890 1891 1892 1893 1894 1895 1896 1897 1898 1899 1900 1901
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] : '?';
}

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

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

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

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

1938 1939 1940
	wait_time = tr->dt_sleep + tr->dt_iowait + tr->dt_preempt;
	print_sched_time(wait_time, 6);

1941 1942
	print_sched_time(tr->dt_delay, 6);
	print_sched_time(tr->dt_run, 6);
1943

1944 1945 1946
	if (sched->show_state)
		printf(" %5c ", task_state_char(thread, state));

1947 1948 1949 1950 1951 1952
	if (sched->show_next) {
		snprintf(nstr, sizeof(nstr), "next: %s[%d]", next_comm, next_pid);
		printf(" %-*s", comm_width, nstr);
	}

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

1955 1956 1957 1958 1959 1960 1961 1962
	if (thread->tid == 0)
		goto out;

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

	sample__fprintf_sym(sample, al, 0,
			    EVSEL__PRINT_SYM | EVSEL__PRINT_ONELINE |
1963 1964
			    EVSEL__PRINT_CALLCHAIN_ARROW |
			    EVSEL__PRINT_SKIP_IGNORED,
1965 1966 1967
			    &callchain_cursor, stdout);

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

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

	update_stats(&r->run_stats, r->dt_run);
2027 2028 2029 2030 2031 2032

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

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

2042 2043 2044 2045 2046 2047 2048 2049 2050 2051
	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;
2052 2053 2054 2055 2056

	/* 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);
2057
		return;
2058 2059 2060
	}

	if (!symbol_conf.use_callchain || sample->callchain == NULL)
2061
		return;
2062 2063

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

2068
		return;
2069
	}
2070

2071
	callchain_cursor_commit(cursor);
2072 2073 2074 2075 2076 2077 2078 2079 2080 2081

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

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

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

		callchain_cursor_advance(cursor);
	}
2091 2092
}

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

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

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

2123
	idle_max_cpu = ncpu;
2124 2125 2126 2127 2128 2129 2130

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

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

	return 0;
}

static void free_idle_threads(void)
{
	int i;

	if (idle_threads == NULL)
		return;

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

	return idle_threads[cpu];
}

2188 2189 2190 2191 2192 2193 2194 2195 2196
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);
}

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

2228 2229
static struct thread *timehist_get_thread(struct perf_sched *sched,
					  struct perf_sample *sample,
2230 2231 2232 2233 2234
					  struct machine *machine,
					  struct perf_evsel *evsel)
{
	struct thread *thread;

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

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

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

	return thread;
}

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

2282
	if (thread__is_filtered(thread)) {
2283
		rc = true;
2284 2285
		sched->skipped_samples++;
	}
2286

2287 2288 2289 2290 2291 2292 2293 2294
	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;
	}

2295 2296 2297
	return rc;
}

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

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

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

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

2360 2361 2362
	return 0;
}

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

2385 2386
	if (timehist_skip_sample(sched, thread, evsel, sample) &&
	    timehist_skip_sample(sched, migrated, evsel, sample)) {
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 2432 2433 2434 2435 2436 2437 2438 2439 2440 2441 2442 2443
		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;
}

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

2459 2460 2461 2462 2463 2464 2465 2466

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

2467
	thread = timehist_get_thread(sched, sample, machine, evsel);
2468 2469 2470 2471 2472
	if (thread == NULL) {
		rc = -1;
		goto out;
	}

2473
	if (timehist_skip_sample(sched, thread, evsel, sample))
2474 2475 2476 2477 2478 2479 2480 2481 2482 2483
		goto out;

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

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

2484 2485 2486 2487 2488 2489 2490 2491
	/*
	 * 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;

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

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

2538 2539 2540
			if (itr->cursor.nr)
				callchain_append(&itr->callchain, &itr->cursor, t - tprev);

2541 2542 2543
			itr->last_thread = NULL;
		}
	}
2544

2545
	if (!sched->summary_only)
2546
		timehist_print_sample(sched, evsel, sample, &al, thread, t, state);
2547 2548

out:
2549 2550 2551 2552 2553
	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;

2554 2555 2556 2557
	if (tr) {
		/* time of this sched_switch event becomes last time task seen */
		tr->last_time = sample->time;

2558
		/* last state is used to determine where to account wait time */
2559
		tr->last_state = state;
2560

2561 2562 2563 2564 2565 2566 2567 2568 2569 2570 2571 2572 2573 2574 2575 2576 2577 2578 2579 2580 2581 2582 2583 2584 2585 2586 2587 2588 2589 2590 2591 2592 2593
		/* 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;
}


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

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

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

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

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

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 2723 2724 2725 2726 2727 2728 2729 2730 2731 2732 2733 2734
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;
}

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

	memset(&totals, 0, sizeof(totals));
2747
	totals.sched = sched;
2748

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

	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 */
2778
	if (sched->skipped_samples && !sched->idle_hist)
2779 2780 2781
		return;

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

2797 2798 2799 2800 2801 2802 2803 2804 2805 2806 2807 2808 2809 2810 2811 2812 2813 2814 2815 2816 2817 2818 2819 2820 2821 2822 2823 2824 2825
	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");
		}
	}

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

2831
	printf("           Total run time (msec): ");
2832 2833
	print_sched_time(totals.total_run_time, 2);
	printf("\n");
2834 2835 2836 2837

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

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

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

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

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

2928 2929
	symbol_conf.use_callchain = sched->show_callchain;

2930 2931 2932 2933
	session = perf_session__new(&file, false, &sched->tool);
	if (session == NULL)
		return -ENOMEM;

2934 2935
	evlist = session->evlist;

2936 2937
	symbol__init(&session->header.env);

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

2943 2944 2945
	if (timehist_check_attr(sched, evlist) != 0)
		goto out;

2946 2947 2948 2949 2950 2951
	setup_pager();

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

2952 2953 2954 2955
	/* 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");
2956
		goto out;
2957
	}
2958

2959 2960 2961 2962
	if (sched->show_migrations &&
	    perf_session__set_tracepoints_handlers(session, migrate_handlers))
		goto out;

2963 2964 2965 2966 2967 2968 2969
	/* 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;

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

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

2983 2984 2985 2986 2987 2988 2989
	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);

2990 2991 2992 2993 2994 2995 2996 2997
out:
	free_idle_threads();
	perf_session__delete(session);

	return err;
}


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

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 3061 3062 3063 3064 3065 3066 3067 3068 3069 3070 3071 3072
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);
	}
}

3073
static int perf_sched__lat(struct perf_sched *sched)
3074 3075 3076 3077
{
	struct rb_node *next;

	setup_pager();
3078

3079
	if (perf_sched__read_events(sched))
3080
		return -1;
3081

3082
	perf_sched__merge_lat(sched);
3083
	perf_sched__sort_lat(sched);
3084

3085 3086 3087
	printf("\n -----------------------------------------------------------------------------------------------------------------\n");
	printf("  Task                  |   Runtime ms  | Switches | Average delay ms | Maximum delay ms | Maximum delay at       |\n");
	printf(" -----------------------------------------------------------------------------------------------------------------\n");
3088

3089
	next = rb_first(&sched->sorted_atom_root);
3090 3091 3092 3093 3094

	while (next) {
		struct work_atoms *work_list;

		work_list = rb_entry(next, struct work_atoms, node);
3095
		output_lat_thread(sched, work_list);
3096
		next = rb_next(next);
3097
		thread__zput(work_list->thread);
3098 3099
	}

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

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

3106
	print_bad_events(sched);
3107 3108
	printf("\n");

3109
	return 0;
3110 3111
}

3112 3113
static int setup_map_cpus(struct perf_sched *sched)
{
3114 3115
	struct cpu_map *map;

3116 3117 3118 3119
	sched->max_cpu  = sysconf(_SC_NPROCESSORS_CONF);

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

3124 3125 3126 3127 3128 3129 3130 3131 3132 3133
	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;
3134 3135 3136
	return 0;
}

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

3171
static int perf_sched__map(struct perf_sched *sched)
3172
{
3173 3174
	if (setup_map_cpus(sched))
		return -1;
3175

J
Jiri Olsa 已提交
3176 3177 3178
	if (setup_color_pids(sched))
		return -1;

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

3182
	setup_pager();
3183
	if (perf_sched__read_events(sched))
3184
		return -1;
3185
	print_bad_events(sched);
3186
	return 0;
3187 3188
}

3189
static int perf_sched__replay(struct perf_sched *sched)
3190 3191 3192
{
	unsigned long i;

3193 3194
	calibrate_run_measurement_overhead(sched);
	calibrate_sleep_measurement_overhead(sched);
3195

3196
	test_calibrations(sched);
3197

3198
	if (perf_sched__read_events(sched))
3199
		return -1;
3200

3201 3202 3203
	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);
3204

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

3213 3214
	print_task_traces(sched);
	add_cross_task_wakeups(sched);
3215

3216
	create_tasks(sched);
3217
	printf("------------------------------------------------------------\n");
3218 3219
	for (i = 0; i < sched->replay_repeat; i++)
		run_one_test(sched);
3220 3221

	return 0;
3222 3223
}

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

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

	free(str);

3239
	sort_dimension__add("pid", &sched->cmp_pid);
3240 3241
}

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

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

3266
	if (rec_argv == NULL)
3267 3268
		return -ENOMEM;

3269 3270 3271 3272 3273 3274 3275 3276
	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);

3277
	return cmd_record(i, rec_argv);
3278 3279
}

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

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

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

3408 3409
	argc = parse_options_subcommand(argc, argv, sched_options, sched_subcommands,
					sched_usage, PARSE_OPT_STOP_AT_NON_OPTION);
3410 3411
	if (!argc)
		usage_with_options(sched_usage, sched_options);
I
Ingo Molnar 已提交
3412

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

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

3465
		return perf_sched__timehist(&sched);
3466 3467 3468 3469
	} else {
		usage_with_options(sched_usage, sched_options);
	}

I
Ingo Molnar 已提交
3470
	return 0;
I
Ingo Molnar 已提交
3471
}