builtin-stat.c 12.5 KB
Newer Older
1
/*
2 3 4 5 6 7
 * builtin-stat.c
 *
 * Builtin stat command: Give a precise performance counters summary
 * overview about any workload, CPU or specific PID.
 *
 * Sample output:
8

9 10
   $ perf stat ~/hackbench 10
   Time: 0.104
11

12
    Performance counter stats for '/home/mingo/hackbench':
13

14 15 16 17 18 19 20 21
       1255.538611  task clock ticks     #      10.143 CPU utilization factor
             54011  context switches     #       0.043 M/sec
               385  CPU migrations       #       0.000 M/sec
             17755  pagefaults           #       0.014 M/sec
        3808323185  CPU cycles           #    3033.219 M/sec
        1575111190  instructions         #    1254.530 M/sec
          17367895  cache references     #      13.833 M/sec
           7674421  cache misses         #       6.112 M/sec
22

23
    Wall-clock time elapsed:   123.786620 msecs
24

25 26 27 28 29 30 31 32 33 34 35 36
 *
 * Copyright (C) 2008, Red Hat Inc, Ingo Molnar <mingo@redhat.com>
 *
 * Improvements and fixes by:
 *
 *   Arjan van de Ven <arjan@linux.intel.com>
 *   Yanmin Zhang <yanmin.zhang@intel.com>
 *   Wu Fengguang <fengguang.wu@intel.com>
 *   Mike Galbraith <efault@gmx.de>
 *   Paul Mackerras <paulus@samba.org>
 *
 * Released under the GPL v2. (and only v2, not any later version)
37 38
 */

39
#include "perf.h"
40
#include "builtin.h"
41
#include "util/util.h"
42 43
#include "util/parse-options.h"
#include "util/parse-events.h"
44 45

#include <sys/prctl.h>
46
#include <math.h>
47

48
static struct perf_counter_attr default_attrs[MAX_COUNTERS] = {
49

50 51 52 53 54 55 56 57 58 59
  { .type = PERF_TYPE_SOFTWARE, .config = PERF_COUNT_SW_TASK_CLOCK	},
  { .type = PERF_TYPE_SOFTWARE, .config = PERF_COUNT_SW_CONTEXT_SWITCHES},
  { .type = PERF_TYPE_SOFTWARE, .config = PERF_COUNT_SW_CPU_MIGRATIONS	},
  { .type = PERF_TYPE_SOFTWARE, .config = PERF_COUNT_SW_PAGE_FAULTS	},

  { .type = PERF_TYPE_HARDWARE, .config = PERF_COUNT_HW_CPU_CYCLES	},
  { .type = PERF_TYPE_HARDWARE, .config = PERF_COUNT_HW_INSTRUCTIONS	},
  { .type = PERF_TYPE_HARDWARE, .config = PERF_COUNT_HW_CACHE_REFERENCES},
  { .type = PERF_TYPE_HARDWARE, .config = PERF_COUNT_HW_CACHE_MISSES	},

60
};
61

62 63
static int			system_wide			=  0;
static int			inherit				=  1;
64
static int			verbose				=  0;
65

66 67
static int			fd[MAX_NR_CPUS][MAX_COUNTERS];

68
static int			target_pid			= -1;
69 70 71
static int			nr_cpus				=  0;
static unsigned int		page_size;

72
static int			scale				=  1;
73 74 75 76 77 78 79 80 81 82

static const unsigned int default_count[] = {
	1000000,
	1000000,
	  10000,
	  10000,
	1000000,
	  10000,
};

83
#define MAX_RUN 100
84

85 86 87
static int			run_count		=  1;
static int			run_idx			=  0;

88 89
static u64			event_res[MAX_RUN][MAX_COUNTERS][3];
static u64			event_scaled[MAX_RUN][MAX_COUNTERS];
90

91
//static u64			event_hist[MAX_RUN][MAX_COUNTERS][3];
92 93


94 95 96
static u64			runtime_nsecs[MAX_RUN];
static u64			walltime_nsecs[MAX_RUN];
static u64			runtime_cycles[MAX_RUN];
97

98 99
static u64			event_res_avg[MAX_COUNTERS][3];
static u64			event_res_noise[MAX_COUNTERS][3];
100

101
static u64			event_scaled_avg[MAX_COUNTERS];
102

103 104
static u64			runtime_nsecs_avg;
static u64			runtime_nsecs_noise;
105

106 107
static u64			walltime_nsecs_avg;
static u64			walltime_nsecs_noise;
108

109 110
static u64			runtime_cycles_avg;
static u64			runtime_cycles_noise;
111

112
static void create_perf_stat_counter(int counter)
113
{
114
	struct perf_counter_attr *attr = attrs + counter;
115

116
	if (scale)
117 118
		attr->read_format = PERF_FORMAT_TOTAL_TIME_ENABLED |
				    PERF_FORMAT_TOTAL_TIME_RUNNING;
119 120 121 122

	if (system_wide) {
		int cpu;
		for (cpu = 0; cpu < nr_cpus; cpu ++) {
123
			fd[cpu][counter] = sys_perf_counter_open(attr, -1, cpu, -1, 0);
124 125
			if (fd[cpu][counter] < 0 && verbose) {
				printf("Error: counter %d, sys_perf_counter_open() syscall returned with %d (%s)\n", counter, fd[cpu][counter], strerror(errno));
126 127 128
			}
		}
	} else {
129 130
		attr->inherit	= inherit;
		attr->disabled	= 1;
131

132
		fd[0][counter] = sys_perf_counter_open(attr, 0, -1, -1, 0);
133 134
		if (fd[0][counter] < 0 && verbose) {
			printf("Error: counter %d, sys_perf_counter_open() syscall returned with %d (%s)\n", counter, fd[0][counter], strerror(errno));
135 136 137 138
		}
	}
}

139 140 141 142 143
/*
 * Does the counter have nsecs as a unit?
 */
static inline int nsec_counter(int counter)
{
144 145 146
	if (attrs[counter].type != PERF_TYPE_SOFTWARE)
		return 0;

147
	if (attrs[counter].config == PERF_COUNT_SW_CPU_CLOCK)
148
		return 1;
149

150
	if (attrs[counter].config == PERF_COUNT_SW_TASK_CLOCK)
151 152 153 154 155 156
		return 1;

	return 0;
}

/*
157
 * Read out the results of a single counter:
158
 */
159
static void read_counter(int counter)
160
{
161
	u64 *count, single_count[3];
162 163 164 165
	ssize_t res;
	int cpu, nv;
	int scaled;

166
	count = event_res[run_idx][counter];
167

168
	count[0] = count[1] = count[2] = 0;
169

170 171
	nv = scale ? 3 : 1;
	for (cpu = 0; cpu < nr_cpus; cpu ++) {
172 173 174
		if (fd[cpu][counter] < 0)
			continue;

175 176
		res = read(fd[cpu][counter], single_count, nv * sizeof(u64));
		assert(res == nv * sizeof(u64));
177 178
		close(fd[cpu][counter]);
		fd[cpu][counter] = -1;
179 180 181 182 183 184 185 186 187 188 189

		count[0] += single_count[0];
		if (scale) {
			count[1] += single_count[1];
			count[2] += single_count[2];
		}
	}

	scaled = 0;
	if (scale) {
		if (count[2] == 0) {
190
			event_scaled[run_idx][counter] = -1;
191
			count[0] = 0;
192 193
			return;
		}
194

195
		if (count[2] < count[1]) {
196
			event_scaled[run_idx][counter] = 1;
197 198 199 200
			count[0] = (unsigned long long)
				((double)count[0] * count[1] / count[2] + 0.5);
		}
	}
201 202 203
	/*
	 * Save the full runtime - to allow normalization during printout:
	 */
204
	if (attrs[counter].type == PERF_TYPE_SOFTWARE &&
205
		attrs[counter].config == PERF_COUNT_SW_TASK_CLOCK)
206
		runtime_nsecs[run_idx] = count[0];
207
	if (attrs[counter].type == PERF_TYPE_HARDWARE &&
208
		attrs[counter].config == PERF_COUNT_HW_CPU_CYCLES)
209
		runtime_cycles[run_idx] = count[0];
210 211
}

212 213 214 215 216 217 218 219 220 221 222 223 224 225 226 227 228 229 230 231 232 233 234 235 236 237 238 239 240 241 242 243 244 245 246 247 248 249 250 251 252 253
static int run_perf_stat(int argc, const char **argv)
{
	unsigned long long t0, t1;
	int status = 0;
	int counter;
	int pid;

	if (!system_wide)
		nr_cpus = 1;

	for (counter = 0; counter < nr_counters; counter++)
		create_perf_stat_counter(counter);

	/*
	 * Enable counters and exec the command:
	 */
	t0 = rdclock();
	prctl(PR_TASK_PERF_COUNTERS_ENABLE);

	if ((pid = fork()) < 0)
		perror("failed to fork");

	if (!pid) {
		if (execvp(argv[0], (char **)argv)) {
			perror(argv[0]);
			exit(-1);
		}
	}

	wait(&status);

	prctl(PR_TASK_PERF_COUNTERS_DISABLE);
	t1 = rdclock();

	walltime_nsecs[run_idx] = t1 - t0;

	for (counter = 0; counter < nr_counters; counter++)
		read_counter(counter);

	return WEXITSTATUS(status);
}

254
static void print_noise(u64 *count, u64 *noise)
255 256 257 258 259 260
{
	if (run_count > 1)
		fprintf(stderr, "   ( +- %7.3f%% )",
			(double)noise[0]/(count[0]+1)*100.0);
}

261
static void nsec_printout(int counter, u64 *count, u64 *noise)
I
Ingo Molnar 已提交
262 263 264 265 266 267 268 269
{
	double msecs = (double)count[0] / 1000000;

	fprintf(stderr, " %14.6f  %-20s", msecs, event_name(counter));

	if (attrs[counter].type == PERF_TYPE_SOFTWARE &&
		attrs[counter].config == PERF_COUNT_SW_TASK_CLOCK) {

270 271 272
		if (walltime_nsecs_avg)
			fprintf(stderr, " # %10.3f CPUs ",
				(double)count[0] / (double)walltime_nsecs_avg);
I
Ingo Molnar 已提交
273
	}
274
	print_noise(count, noise);
I
Ingo Molnar 已提交
275 276
}

277
static void abs_printout(int counter, u64 *count, u64 *noise)
I
Ingo Molnar 已提交
278 279 280
{
	fprintf(stderr, " %14Ld  %-20s", count[0], event_name(counter));

281
	if (runtime_cycles_avg &&
I
Ingo Molnar 已提交
282 283 284
		attrs[counter].type == PERF_TYPE_HARDWARE &&
			attrs[counter].config == PERF_COUNT_HW_INSTRUCTIONS) {

285 286 287 288 289 290 291
		fprintf(stderr, " # %10.3f IPC  ",
			(double)count[0] / (double)runtime_cycles_avg);
	} else {
		if (runtime_nsecs_avg) {
			fprintf(stderr, " # %10.3f M/sec",
				(double)count[0]/runtime_nsecs_avg*1000.0);
		}
I
Ingo Molnar 已提交
292
	}
293
	print_noise(count, noise);
I
Ingo Molnar 已提交
294 295
}

296 297 298 299 300
/*
 * Print out the results of a single counter:
 */
static void print_counter(int counter)
{
301
	u64 *count, *noise;
302 303
	int scaled;

304 305 306
	count = event_res_avg[counter];
	noise = event_res_noise[counter];
	scaled = event_scaled_avg[counter];
307 308 309 310 311 312

	if (scaled == -1) {
		fprintf(stderr, " %14s  %-20s\n",
			"<not counted>", event_name(counter));
		return;
	}
313

I
Ingo Molnar 已提交
314
	if (nsec_counter(counter))
315
		nsec_printout(counter, count, noise);
I
Ingo Molnar 已提交
316
	else
317
		abs_printout(counter, count, noise);
318

319 320 321
	if (scaled)
		fprintf(stderr, "  (scaled from %.2f%%)",
			(double) count[2] / count[1] * 100);
I
Ingo Molnar 已提交
322

323 324 325
	fprintf(stderr, "\n");
}

326
/*
327
 * normalize_noise noise values down to stddev:
328
 */
329
static void normalize_noise(u64 *val)
330
{
331
	double res;
332

333
	res = (double)*val / (run_count * sqrt((double)run_count));
334

335
	*val = (u64)res;
336
}
337

338
static void update_avg(const char *name, int idx, u64 *avg, u64 *val)
339 340 341 342 343 344
{
	*avg += *val;

	if (verbose > 1)
		fprintf(stderr, "debug: %20s[%d]: %Ld\n", name, idx, *val);
}
345 346 347 348 349 350 351
/*
 * Calculate the averages and noises:
 */
static void calc_avg(void)
{
	int i, j;

352 353 354
	if (verbose > 1)
		fprintf(stderr, "\n");

355
	for (i = 0; i < run_count; i++) {
356 357 358
		update_avg("runtime", 0, &runtime_nsecs_avg, runtime_nsecs + i);
		update_avg("walltime", 0, &walltime_nsecs_avg, walltime_nsecs + i);
		update_avg("runtime_cycles", 0, &runtime_cycles_avg, runtime_cycles + i);
359 360

		for (j = 0; j < nr_counters; j++) {
361 362 363 364 365 366 367 368
			update_avg("counter/0", j,
				event_res_avg[j]+0, event_res[i][j]+0);
			update_avg("counter/1", j,
				event_res_avg[j]+1, event_res[i][j]+1);
			update_avg("counter/2", j,
				event_res_avg[j]+2, event_res[i][j]+2);
			update_avg("scaled", j,
				event_scaled_avg + j, event_scaled[i]+j);
369 370 371 372 373 374 375 376 377 378 379
		}
	}
	runtime_nsecs_avg /= run_count;
	walltime_nsecs_avg /= run_count;
	runtime_cycles_avg /= run_count;

	for (j = 0; j < nr_counters; j++) {
		event_res_avg[j][0] /= run_count;
		event_res_avg[j][1] /= run_count;
		event_res_avg[j][2] /= run_count;
	}
I
Ingo Molnar 已提交
380

381 382
	for (i = 0; i < run_count; i++) {
		runtime_nsecs_noise +=
383
			abs((s64)(runtime_nsecs[i] - runtime_nsecs_avg));
384
		walltime_nsecs_noise +=
385
			abs((s64)(walltime_nsecs[i] - walltime_nsecs_avg));
386
		runtime_cycles_noise +=
387
			abs((s64)(runtime_cycles[i] - runtime_cycles_avg));
388 389 390

		for (j = 0; j < nr_counters; j++) {
			event_res_noise[j][0] +=
391
				abs((s64)(event_res[i][j][0] - event_res_avg[j][0]));
392
			event_res_noise[j][1] +=
393
				abs((s64)(event_res[i][j][1] - event_res_avg[j][1]));
394
			event_res_noise[j][2] +=
395
				abs((s64)(event_res[i][j][2] - event_res_avg[j][2]));
396 397
		}
	}
I
Ingo Molnar 已提交
398

399 400 401
	normalize_noise(&runtime_nsecs_noise);
	normalize_noise(&walltime_nsecs_noise);
	normalize_noise(&runtime_cycles_noise);
I
Ingo Molnar 已提交
402

403
	for (j = 0; j < nr_counters; j++) {
404 405 406
		normalize_noise(&event_res_noise[j][0]);
		normalize_noise(&event_res_noise[j][1]);
		normalize_noise(&event_res_noise[j][2]);
407 408 409 410 411 412 413 414
	}
}

static void print_stat(int argc, const char **argv)
{
	int i, counter;

	calc_avg();
415 416 417 418

	fflush(stdout);

	fprintf(stderr, "\n");
I
Ingo Molnar 已提交
419 420 421 422 423
	fprintf(stderr, " Performance counter stats for \'%s", argv[0]);

	for (i = 1; i < argc; i++)
		fprintf(stderr, " %s", argv[i]);

424 425 426 427
	fprintf(stderr, "\'");
	if (run_count > 1)
		fprintf(stderr, " (%d runs)", run_count);
	fprintf(stderr, ":\n\n");
428

429 430
	for (counter = 0; counter < nr_counters; counter++)
		print_counter(counter);
431 432 433


	fprintf(stderr, "\n");
434 435
	fprintf(stderr, " %14.9f  seconds time elapsed.\n",
			(double)walltime_nsecs_avg/1e9);
436 437 438
	fprintf(stderr, "\n");
}

439 440
static volatile int signr = -1;

441
static void skip_signal(int signo)
442
{
443 444 445 446 447 448 449 450 451 452
	signr = signo;
}

static void sig_atexit(void)
{
	if (signr == -1)
		return;

	signal(signr, SIG_DFL);
	kill(getpid(), signr);
453 454 455 456 457 458 459 460 461
}

static const char * const stat_usage[] = {
	"perf stat [<options>] <command>",
	NULL
};

static const struct option options[] = {
	OPT_CALLBACK('e', "event", NULL, "event",
462 463
		     "event selector. use 'perf list' to list available events",
		     parse_events),
464 465 466 467 468 469
	OPT_BOOLEAN('i', "inherit", &inherit,
		    "child tasks inherit counters"),
	OPT_INTEGER('p', "pid", &target_pid,
		    "stat events on existing pid"),
	OPT_BOOLEAN('a', "all-cpus", &system_wide,
			    "system-wide collection from all CPUs"),
470
	OPT_BOOLEAN('S', "scale", &scale,
471
			    "scale/normalize counters"),
472 473
	OPT_BOOLEAN('v', "verbose", &verbose,
		    "be more verbose (show counter open errors, etc)"),
474 475
	OPT_INTEGER('r', "repeat", &run_count,
		    "repeat command and print average + stddev (max: 100)"),
476 477 478 479 480
	OPT_END()
};

int cmd_stat(int argc, const char **argv, const char *prefix)
{
481 482
	int status;

483 484
	page_size = sysconf(_SC_PAGE_SIZE);

485
	memcpy(attrs, default_attrs, sizeof(attrs));
486 487 488 489

	argc = parse_options(argc, argv, options, stat_usage, 0);
	if (!argc)
		usage_with_options(stat_usage, options);
490 491
	if (run_count <= 0 || run_count > MAX_RUN)
		usage_with_options(stat_usage, options);
492

493
	if (!nr_counters)
494 495 496 497 498 499
		nr_counters = 8;

	nr_cpus = sysconf(_SC_NPROCESSORS_ONLN);
	assert(nr_cpus <= MAX_NR_CPUS);
	assert(nr_cpus >= 0);

I
Ingo Molnar 已提交
500 501 502 503 504 505
	/*
	 * We dont want to block the signals - that would cause
	 * child tasks to inherit that and Ctrl-C would not work.
	 * What we want is for Ctrl-C to work in the exec()-ed
	 * task, but being ignored by perf stat itself:
	 */
506
	atexit(sig_atexit);
I
Ingo Molnar 已提交
507 508 509 510
	signal(SIGINT,  skip_signal);
	signal(SIGALRM, skip_signal);
	signal(SIGABRT, skip_signal);

511 512 513 514 515 516 517 518 519 520
	status = 0;
	for (run_idx = 0; run_idx < run_count; run_idx++) {
		if (run_count != 1 && verbose)
			fprintf(stderr, "[ perf stat: executing run #%d ... ]\n", run_idx+1);
		status = run_perf_stat(argc, argv);
	}

	print_stat(argc, argv);

	return status;
521
}