trace_functions_graph.c 14 KB
Newer Older
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15
/*
 *
 * Function graph tracer.
 * Copyright (c) 2008 Frederic Weisbecker <fweisbec@gmail.com>
 * Mostly borrowed from function tracer which
 * is Copyright (c) Steven Rostedt <srostedt@redhat.com>
 *
 */
#include <linux/debugfs.h>
#include <linux/uaccess.h>
#include <linux/ftrace.h>
#include <linux/fs.h>

#include "trace.h"

16
#define TRACE_GRAPH_INDENT	2
17

18
/* Flag options */
19
#define TRACE_GRAPH_PRINT_OVERRUN	0x1
20 21
#define TRACE_GRAPH_PRINT_CPU		0x2
#define TRACE_GRAPH_PRINT_OVERHEAD	0x4
22
#define TRACE_GRAPH_PRINT_PROC		0x8
23

24
static struct tracer_opt trace_opts[] = {
25 26 27 28 29 30
	/* Display overruns ? */
	{ TRACER_OPT(funcgraph-overrun, TRACE_GRAPH_PRINT_OVERRUN) },
	/* Display CPU ? */
	{ TRACER_OPT(funcgraph-cpu, TRACE_GRAPH_PRINT_CPU) },
	/* Display Overhead ? */
	{ TRACER_OPT(funcgraph-overhead, TRACE_GRAPH_PRINT_OVERHEAD) },
31 32
	/* Display proc name/pid */
	{ TRACER_OPT(funcgraph-proc, TRACE_GRAPH_PRINT_PROC) },
33 34 35 36
	{ } /* Empty entry */
};

static struct tracer_flags tracer_flags = {
37
	/* Don't display overruns and proc by default */
38
	.val = TRACE_GRAPH_PRINT_CPU | TRACE_GRAPH_PRINT_OVERHEAD,
39 40 41
	.opts = trace_opts
};

42
/* pid on the last trace processed */
43
static pid_t last_pid[NR_CPUS] = { [0 ... NR_CPUS-1] = -1 };
44 45 46

static int graph_trace_init(struct trace_array *tr)
{
47 48
	int cpu, ret;

49 50 51
	for_each_online_cpu(cpu)
		tracing_reset(tr, cpu);

52
	ret = register_ftrace_graph(&trace_graph_return,
53
					&trace_graph_entry);
54 55 56 57 58
	if (ret)
		return ret;
	tracing_start_cmdline_record();

	return 0;
59 60 61 62
}

static void graph_trace_reset(struct trace_array *tr)
{
63 64
	tracing_stop_cmdline_record();
	unregister_ftrace_graph();
65 66
}

67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84
static inline int log10_cpu(int nb)
{
	if (nb / 100)
		return 3;
	if (nb / 10)
		return 2;
	return 1;
}

static enum print_line_t
print_graph_cpu(struct trace_seq *s, int cpu)
{
	int i;
	int ret;
	int log10_this = log10_cpu(cpu);
	int log10_all = log10_cpu(cpus_weight_nr(cpu_online_map));


85 86 87 88 89 90 91 92 93 94 95 96 97
	/*
	 * Start with a space character - to make it stand out
	 * to the right a bit when trace output is pasted into
	 * email:
	 */
	ret = trace_seq_printf(s, " ");

	/*
	 * Tricky - we space the CPU field according to the max
	 * number of online CPUs. On a 2-cpu system it would take
	 * a maximum of 1 digit - on a 128 cpu system it would
	 * take up to 3 digits:
	 */
98 99 100 101 102 103 104
	for (i = 0; i < log10_all - log10_this; i++) {
		ret = trace_seq_printf(s, " ");
		if (!ret)
			return TRACE_TYPE_PARTIAL_LINE;
	}
	ret = trace_seq_printf(s, "%d) ", cpu);
	if (!ret)
105 106
		return TRACE_TYPE_PARTIAL_LINE;

107 108 109
	return TRACE_TYPE_HANDLED;
}

110 111 112 113 114 115 116 117 118 119 120 121 122 123 124 125 126 127 128 129 130 131 132 133 134 135 136 137 138 139 140 141 142 143 144 145 146 147 148 149 150 151 152
#define TRACE_GRAPH_PROCINFO_LENGTH	14

static enum print_line_t
print_graph_proc(struct trace_seq *s, pid_t pid)
{
	int i;
	int ret;
	int len;
	char comm[8];
	int spaces = 0;
	/* sign + log10(MAX_INT) + '\0' */
	char pid_str[11];

	strncpy(comm, trace_find_cmdline(pid), 7);
	comm[7] = '\0';
	sprintf(pid_str, "%d", pid);

	/* 1 stands for the "-" character */
	len = strlen(comm) + strlen(pid_str) + 1;

	if (len < TRACE_GRAPH_PROCINFO_LENGTH)
		spaces = TRACE_GRAPH_PROCINFO_LENGTH - len;

	/* First spaces to align center */
	for (i = 0; i < spaces / 2; i++) {
		ret = trace_seq_printf(s, " ");
		if (!ret)
			return TRACE_TYPE_PARTIAL_LINE;
	}

	ret = trace_seq_printf(s, "%s-%s", comm, pid_str);
	if (!ret)
		return TRACE_TYPE_PARTIAL_LINE;

	/* Last spaces to align center */
	for (i = 0; i < spaces - (spaces / 2); i++) {
		ret = trace_seq_printf(s, " ");
		if (!ret)
			return TRACE_TYPE_PARTIAL_LINE;
	}
	return TRACE_TYPE_HANDLED;
}

153

154
/* If the pid changed since the last trace, output this event */
155 156
static enum print_line_t
verif_pid(struct trace_seq *s, pid_t pid, int cpu)
157
{
158 159
	pid_t prev_pid;
	int ret;
160

161
	if (last_pid[cpu] != -1 && last_pid[cpu] == pid)
162
		return TRACE_TYPE_HANDLED;
163

164
	prev_pid = last_pid[cpu];
165
	last_pid[cpu] = pid;
166 167 168 169 170 171 172 173 174 175

/*
 * Context-switch trace line:

 ------------------------------------------
 | 1)  migration/0--1  =>  sshd-1755
 ------------------------------------------

 */
	ret = trace_seq_printf(s,
176
		" ------------------------------------------\n");
177 178 179 180 181 182 183 184 185 186 187 188 189 190 191 192 193 194 195 196 197 198 199 200
	if (!ret)
		TRACE_TYPE_PARTIAL_LINE;

	ret = print_graph_cpu(s, cpu);
	if (ret == TRACE_TYPE_PARTIAL_LINE)
		TRACE_TYPE_PARTIAL_LINE;

	ret = print_graph_proc(s, prev_pid);
	if (ret == TRACE_TYPE_PARTIAL_LINE)
		TRACE_TYPE_PARTIAL_LINE;

	ret = trace_seq_printf(s, " => ");
	if (!ret)
		TRACE_TYPE_PARTIAL_LINE;

	ret = print_graph_proc(s, pid);
	if (ret == TRACE_TYPE_PARTIAL_LINE)
		TRACE_TYPE_PARTIAL_LINE;

	ret = trace_seq_printf(s,
		"\n ------------------------------------------\n\n");
	if (!ret)
		TRACE_TYPE_PARTIAL_LINE;

201
	return ret;
202 203
}

204 205 206 207 208 209 210 211 212 213 214 215 216
static bool
trace_branch_is_leaf(struct trace_iterator *iter,
		struct ftrace_graph_ent_entry *curr)
{
	struct ring_buffer_iter *ring_iter;
	struct ring_buffer_event *event;
	struct ftrace_graph_ret_entry *next;

	ring_iter = iter->buffer_iter[iter->cpu];

	if (!ring_iter)
		return false;

217
	event = ring_buffer_iter_peek(ring_iter, NULL);
218 219 220 221 222 223 224 225 226 227 228 229 230 231 232 233 234

	if (!event)
		return false;

	next = ring_buffer_event_data(event);

	if (next->ent.type != TRACE_GRAPH_RET)
		return false;

	if (curr->ent.pid != next->ent.pid ||
			curr->graph_ent.func != next->ret.func)
		return false;

	return true;
}


235
static enum print_line_t
236 237 238
print_graph_duration(unsigned long long duration, struct trace_seq *s)
{
	unsigned long nsecs_rem = do_div(duration, 1000);
239 240 241 242 243 244 245 246 247 248 249 250 251 252 253 254 255 256 257 258 259 260 261 262 263 264 265 266 267 268 269 270 271 272 273 274 275 276 277 278
	/* log10(ULONG_MAX) + '\0' */
	char msecs_str[21];
	char nsecs_str[5];
	int ret, len;
	int i;

	sprintf(msecs_str, "%lu", (unsigned long) duration);

	/* Print msecs */
	ret = trace_seq_printf(s, msecs_str);
	if (!ret)
		return TRACE_TYPE_PARTIAL_LINE;

	len = strlen(msecs_str);

	/* Print nsecs (we don't want to exceed 7 numbers) */
	if (len < 7) {
		snprintf(nsecs_str, 8 - len, "%03lu", nsecs_rem);
		ret = trace_seq_printf(s, ".%s", nsecs_str);
		if (!ret)
			return TRACE_TYPE_PARTIAL_LINE;
		len += strlen(nsecs_str);
	}

	ret = trace_seq_printf(s, " us ");
	if (!ret)
		return TRACE_TYPE_PARTIAL_LINE;

	/* Print remaining spaces to fit the row's width */
	for (i = len; i < 7; i++) {
		ret = trace_seq_printf(s, " ");
		if (!ret)
			return TRACE_TYPE_PARTIAL_LINE;
	}

	ret = trace_seq_printf(s, "|  ");
	if (!ret)
		return TRACE_TYPE_PARTIAL_LINE;
	return TRACE_TYPE_HANDLED;

279 280 281 282 283 284 285 286 287 288 289 290 291 292 293 294 295 296
}

/* Signal a overhead of time execution to the output */
static int
print_graph_overhead(unsigned long long duration, struct trace_seq *s)
{
	/* Duration exceeded 100 msecs */
	if (duration > 100000ULL)
		return trace_seq_printf(s, "! ");

	/* Duration exceeded 10 msecs */
	if (duration > 10000ULL)
		return trace_seq_printf(s, "+ ");

	return trace_seq_printf(s, "  ");
}

/* Case of a leaf function on its call entry */
297
static enum print_line_t
298 299
print_graph_entry_leaf(struct trace_iterator *iter,
		struct ftrace_graph_ent_entry *entry, struct trace_seq *s)
300
{
301 302 303 304 305
	struct ftrace_graph_ret_entry *ret_entry;
	struct ftrace_graph_ret *graph_ret;
	struct ring_buffer_event *event;
	struct ftrace_graph_ent *call;
	unsigned long long duration;
306
	int ret;
307
	int i;
308

309 310 311 312 313 314 315
	event = ring_buffer_read(iter->buffer_iter[iter->cpu], NULL);
	ret_entry = ring_buffer_event_data(event);
	graph_ret = &ret_entry->ret;
	call = &entry->graph_ent;
	duration = graph_ret->rettime - graph_ret->calltime;

	/* Overhead */
316 317 318 319 320 321 322 323
	if (tracer_flags.val & TRACE_GRAPH_PRINT_OVERHEAD) {
		ret = print_graph_overhead(duration, s);
		if (!ret)
			return TRACE_TYPE_PARTIAL_LINE;
	}

	/* Duration */
	ret = print_graph_duration(duration, s);
324
	if (ret == TRACE_TYPE_PARTIAL_LINE)
325 326
		return TRACE_TYPE_PARTIAL_LINE;

327 328 329 330 331 332 333 334 335 336 337
	/* Function */
	for (i = 0; i < call->depth * TRACE_GRAPH_INDENT; i++) {
		ret = trace_seq_printf(s, " ");
		if (!ret)
			return TRACE_TYPE_PARTIAL_LINE;
	}

	ret = seq_print_ip_sym(s, call->func, 0);
	if (!ret)
		return TRACE_TYPE_PARTIAL_LINE;

338
	ret = trace_seq_printf(s, "();\n");
339 340 341 342 343 344 345 346 347 348 349 350 351 352 353
	if (!ret)
		return TRACE_TYPE_PARTIAL_LINE;

	return TRACE_TYPE_HANDLED;
}

static enum print_line_t
print_graph_entry_nested(struct ftrace_graph_ent_entry *entry,
			struct trace_seq *s)
{
	int i;
	int ret;
	struct ftrace_graph_ent *call = &entry->graph_ent;

	/* No overhead */
354 355 356 357 358 359 360
	if (tracer_flags.val & TRACE_GRAPH_PRINT_OVERHEAD) {
		ret = trace_seq_printf(s, "  ");
		if (!ret)
			return TRACE_TYPE_PARTIAL_LINE;
	}

	/* No time */
361
	ret = trace_seq_printf(s, "            |  ");
362 363

	/* Function */
364 365
	for (i = 0; i < call->depth * TRACE_GRAPH_INDENT; i++) {
		ret = trace_seq_printf(s, " ");
366 367
		if (!ret)
			return TRACE_TYPE_PARTIAL_LINE;
368 369 370 371 372 373
	}

	ret = seq_print_ip_sym(s, call->func, 0);
	if (!ret)
		return TRACE_TYPE_PARTIAL_LINE;

374
	ret = trace_seq_printf(s, "() {\n");
375 376 377
	if (!ret)
		return TRACE_TYPE_PARTIAL_LINE;

378 379 380
	return TRACE_TYPE_HANDLED;
}

381 382 383 384 385 386 387
static enum print_line_t
print_graph_entry(struct ftrace_graph_ent_entry *field, struct trace_seq *s,
			struct trace_iterator *iter, int cpu)
{
	int ret;
	struct trace_entry *ent = iter->ent;

388
	/* Pid */
389
	if (verif_pid(s, ent->pid, cpu) == TRACE_TYPE_PARTIAL_LINE)
390 391
		return TRACE_TYPE_PARTIAL_LINE;

392 393 394
	/* Cpu */
	if (tracer_flags.val & TRACE_GRAPH_PRINT_CPU) {
		ret = print_graph_cpu(s, cpu);
395 396 397 398 399 400 401 402 403 404 405
		if (ret == TRACE_TYPE_PARTIAL_LINE)
			return TRACE_TYPE_PARTIAL_LINE;
	}

	/* Proc */
	if (tracer_flags.val & TRACE_GRAPH_PRINT_PROC) {
		ret = print_graph_proc(s, ent->pid);
		if (ret == TRACE_TYPE_PARTIAL_LINE)
			return TRACE_TYPE_PARTIAL_LINE;

		ret = trace_seq_printf(s, " | ");
406 407 408
		if (!ret)
			return TRACE_TYPE_PARTIAL_LINE;
	}
409 410 411 412 413 414 415 416

	if (trace_branch_is_leaf(iter, field))
		return print_graph_entry_leaf(iter, field, s);
	else
		return print_graph_entry_nested(field, s);

}

417 418
static enum print_line_t
print_graph_return(struct ftrace_graph_ret *trace, struct trace_seq *s,
419
		   struct trace_entry *ent, int cpu)
420 421 422
{
	int i;
	int ret;
423
	unsigned long long duration = trace->rettime - trace->calltime;
424

425
	/* Pid */
426
	if (verif_pid(s, ent->pid, cpu) == TRACE_TYPE_PARTIAL_LINE)
427 428
		return TRACE_TYPE_PARTIAL_LINE;

429
	/* Cpu */
430 431
	if (tracer_flags.val & TRACE_GRAPH_PRINT_CPU) {
		ret = print_graph_cpu(s, cpu);
432 433 434 435 436 437 438 439 440 441 442
		if (ret == TRACE_TYPE_PARTIAL_LINE)
			return TRACE_TYPE_PARTIAL_LINE;
	}

	/* Proc */
	if (tracer_flags.val & TRACE_GRAPH_PRINT_PROC) {
		ret = print_graph_proc(s, ent->pid);
		if (ret == TRACE_TYPE_PARTIAL_LINE)
			return TRACE_TYPE_PARTIAL_LINE;

		ret = trace_seq_printf(s, " | ");
443 444 445
		if (!ret)
			return TRACE_TYPE_PARTIAL_LINE;
	}
446

447
	/* Overhead */
448 449 450 451 452 453 454 455
	if (tracer_flags.val & TRACE_GRAPH_PRINT_OVERHEAD) {
		ret = print_graph_overhead(duration, s);
		if (!ret)
			return TRACE_TYPE_PARTIAL_LINE;
	}

	/* Duration */
	ret = print_graph_duration(duration, s);
456
	if (ret == TRACE_TYPE_PARTIAL_LINE)
457 458 459
		return TRACE_TYPE_PARTIAL_LINE;

	/* Closing brace */
460 461
	for (i = 0; i < trace->depth * TRACE_GRAPH_INDENT; i++) {
		ret = trace_seq_printf(s, " ");
462 463
		if (!ret)
			return TRACE_TYPE_PARTIAL_LINE;
464 465
	}

466
	ret = trace_seq_printf(s, "}\n");
467 468
	if (!ret)
		return TRACE_TYPE_PARTIAL_LINE;
469

470
	/* Overrun */
471 472 473
	if (tracer_flags.val & TRACE_GRAPH_PRINT_OVERRUN) {
		ret = trace_seq_printf(s, " (Overruns: %lu)\n",
					trace->overrun);
474 475
		if (!ret)
			return TRACE_TYPE_PARTIAL_LINE;
476 477 478 479
	}
	return TRACE_TYPE_HANDLED;
}

480 481 482 483 484 485 486 487 488 489 490 491 492 493 494 495 496 497 498 499 500 501 502 503 504 505 506 507 508 509 510 511 512 513 514 515 516 517 518 519 520 521 522 523 524 525 526 527 528 529 530 531 532 533 534 535 536 537 538 539 540 541 542 543 544
static enum print_line_t
print_graph_comment(struct print_entry *trace, struct trace_seq *s,
		   struct trace_entry *ent, struct trace_iterator *iter)
{
	int i;
	int ret;

	/* Pid */
	if (verif_pid(s, ent->pid, iter->cpu) == TRACE_TYPE_PARTIAL_LINE)
		return TRACE_TYPE_PARTIAL_LINE;

	/* Cpu */
	if (tracer_flags.val & TRACE_GRAPH_PRINT_CPU) {
		ret = print_graph_cpu(s, iter->cpu);
		if (ret == TRACE_TYPE_PARTIAL_LINE)
			return TRACE_TYPE_PARTIAL_LINE;
	}

	/* Proc */
	if (tracer_flags.val & TRACE_GRAPH_PRINT_PROC) {
		ret = print_graph_proc(s, ent->pid);
		if (ret == TRACE_TYPE_PARTIAL_LINE)
			return TRACE_TYPE_PARTIAL_LINE;

		ret = trace_seq_printf(s, " | ");
		if (!ret)
			return TRACE_TYPE_PARTIAL_LINE;
	}

	/* No overhead */
	if (tracer_flags.val & TRACE_GRAPH_PRINT_OVERHEAD) {
		ret = trace_seq_printf(s, "  ");
		if (!ret)
			return TRACE_TYPE_PARTIAL_LINE;
	}

	/* No time */
	ret = trace_seq_printf(s, "            |  ");
	if (!ret)
		return TRACE_TYPE_PARTIAL_LINE;

	/* Indentation */
	if (trace->depth > 0)
		for (i = 0; i < (trace->depth + 1) * TRACE_GRAPH_INDENT; i++) {
			ret = trace_seq_printf(s, " ");
			if (!ret)
				return TRACE_TYPE_PARTIAL_LINE;
		}

	/* The comment */
	ret = trace_seq_printf(s, "/* %s", trace->buf);
	if (!ret)
		return TRACE_TYPE_PARTIAL_LINE;

	if (ent->flags & TRACE_FLAG_CONT)
		trace_seq_print_cont(s, iter);

	ret = trace_seq_printf(s, " */\n");
	if (!ret)
		return TRACE_TYPE_PARTIAL_LINE;

	return TRACE_TYPE_HANDLED;
}


545 546 547 548 549
enum print_line_t
print_graph_function(struct trace_iterator *iter)
{
	struct trace_seq *s = &iter->seq;
	struct trace_entry *entry = iter->ent;
550

551 552 553 554
	switch (entry->type) {
	case TRACE_GRAPH_ENT: {
		struct ftrace_graph_ent_entry *field;
		trace_assign_type(field, entry);
555
		return print_graph_entry(field, s, iter,
556
					 iter->cpu);
557 558 559 560
	}
	case TRACE_GRAPH_RET: {
		struct ftrace_graph_ret_entry *field;
		trace_assign_type(field, entry);
561
		return print_graph_return(&field->ret, s, entry, iter->cpu);
562
	}
563 564 565 566 567
	case TRACE_PRINT: {
		struct print_entry *field;
		trace_assign_type(field, entry);
		return print_graph_comment(field, s, entry, iter);
	}
568 569
	default:
		return TRACE_TYPE_UNHANDLED;
570 571 572
	}
}

573 574 575 576 577 578 579 580 581 582 583 584 585 586 587 588 589 590 591 592 593 594 595 596
static void print_graph_headers(struct seq_file *s)
{
	/* 1st line */
	seq_printf(s, "# ");
	if (tracer_flags.val & TRACE_GRAPH_PRINT_CPU)
		seq_printf(s, "CPU ");
	if (tracer_flags.val & TRACE_GRAPH_PRINT_PROC)
		seq_printf(s, "TASK/PID     ");
	if (tracer_flags.val & TRACE_GRAPH_PRINT_OVERHEAD)
		seq_printf(s, "OVERHEAD/");
	seq_printf(s, "DURATION            FUNCTION CALLS\n");

	/* 2nd line */
	seq_printf(s, "# ");
	if (tracer_flags.val & TRACE_GRAPH_PRINT_CPU)
		seq_printf(s, "|   ");
	if (tracer_flags.val & TRACE_GRAPH_PRINT_PROC)
		seq_printf(s, "|      |     ");
	if (tracer_flags.val & TRACE_GRAPH_PRINT_OVERHEAD) {
		seq_printf(s, "|        ");
		seq_printf(s, "|                   |   |   |   |\n");
	} else
		seq_printf(s, "    |               |   |   |   |\n");
}
597
static struct tracer graph_trace __read_mostly = {
598 599 600 601 602
	.name	     	= "function_graph",
	.init	     	= graph_trace_init,
	.reset	     	= graph_trace_reset,
	.print_line	= print_graph_function,
	.print_header	= print_graph_headers,
603 604 605 606 607 608 609 610 611
	.flags		= &tracer_flags,
};

static __init int init_graph_trace(void)
{
	return register_tracer(&graph_trace);
}

device_initcall(init_graph_trace);