kernel/trace/trace_functions_graph.c

   1 /*
   2  *
   3  * Function graph tracer.
   4  * Copyright (c) 2008 Frederic Weisbecker <fweisbec@gmail.com>
   5  * Mostly borrowed from function tracer which
   6  * is Copyright (c) Steven Rostedt <srostedt@redhat.com>
   7  *
   8  */
   9 #include <linux/debugfs.h>
  10 #include <linux/uaccess.h>
  11 #include <linux/ftrace.h>
  12 #include <linux/fs.h>
  13
  14 #include "trace.h"
  15
  16 #define TRACE_GRAPH_INDENT      2
  17
  18 /* Flag options */
  19 #define TRACE_GRAPH_PRINT_OVERRUN       0x1
  20 #define TRACE_GRAPH_PRINT_CPU           0x2
  21 #define TRACE_GRAPH_PRINT_OVERHEAD      0x4
  22 #define TRACE_GRAPH_PRINT_PROC          0x8
  23
  24 static struct tracer_opt trace_opts[] = {
  25         /* Display overruns ? */
  26         { TRACER_OPT(funcgraph-overrun, TRACE_GRAPH_PRINT_OVERRUN) },
  27         /* Display CPU ? */
  28         { TRACER_OPT(funcgraph-cpu, TRACE_GRAPH_PRINT_CPU) },
  29         /* Display Overhead ? */
  30         { TRACER_OPT(funcgraph-overhead, TRACE_GRAPH_PRINT_OVERHEAD) },
  31         /* Display proc name/pid */
  32         { TRACER_OPT(funcgraph-proc, TRACE_GRAPH_PRINT_PROC) },
  33         { } /* Empty entry */
  34 };
  35
  36 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         .opts = trace_opts
  40 };
  41
  42 /* pid on the last trace processed */
  43 static pid_t last_pid[NR_CPUS] = { [0 ... NR_CPUS-1] = -1 };
  44
  45 static int graph_trace_init(struct trace_array *tr)
  46 {
  47         int cpu, ret;
  48
  49         for_each_online_cpu(cpu)
  50                 tracing_reset(tr, cpu);
  51
  52         ret = register_ftrace_graph(&trace_graph_return,
  53                                         &trace_graph_entry);
  54         if (ret)
  55                 return ret;
  56         tracing_start_cmdline_record();
  57
  58         return 0;
  59 }
  60
  61 static void graph_trace_reset(struct trace_array *tr)
  62 {
  63         tracing_stop_cmdline_record();
  64         unregister_ftrace_graph();
  65 }
  66
  67 static inline int log10_cpu(int nb)
  68 {
  69         if (nb / 100)
  70                 return 3;
  71         if (nb / 10)
  72                 return 2;
  73         return 1;
  74 }
  75
  76 static enum print_line_t
  77 print_graph_cpu(struct trace_seq *s, int cpu)
  78 {
  79         int i;
  80         int ret;
  81         int log10_this = log10_cpu(cpu);
  82         int log10_all = log10_cpu(cpus_weight_nr(cpu_online_map));
  83
  84
  85         /*
  86          * Start with a space character - to make it stand out
  87          * to the right a bit when trace output is pasted into
  88          * email:
  89          */
  90         ret = trace_seq_printf(s, " ");
  91
  92         /*
  93          * Tricky - we space the CPU field according to the max
  94          * number of online CPUs. On a 2-cpu system it would take
  95          * a maximum of 1 digit - on a 128 cpu system it would
  96          * take up to 3 digits:
  97          */
  98         for (i = 0; i < log10_all - log10_this; i++) {
  99                 ret = trace_seq_printf(s, " ");
 100                 if (!ret)
 101                         return TRACE_TYPE_PARTIAL_LINE;
 102         }
 103         ret = trace_seq_printf(s, "%d) ", cpu);
 104         if (!ret)
 105                 return TRACE_TYPE_PARTIAL_LINE;
 106
 107         return TRACE_TYPE_HANDLED;
 108 }
 109
 110 #define TRACE_GRAPH_PROCINFO_LENGTH     14
 111
 112 static enum print_line_t
 113 print_graph_proc(struct trace_seq *s, pid_t pid)
 114 {
 115         int i;
 116         int ret;
 117         int len;
 118         char comm[8];
 119         int spaces = 0;
 120         /* sign + log10(MAX_INT) + '\0' */
 121         char pid_str[11];
 122
 123         strncpy(comm, trace_find_cmdline(pid), 7);
 124         comm[7] = '\0';
 125         sprintf(pid_str, "%d", pid);
 126
 127         /* 1 stands for the "-" character */
 128         len = strlen(comm) + strlen(pid_str) + 1;
 129
 130         if (len < TRACE_GRAPH_PROCINFO_LENGTH)
 131                 spaces = TRACE_GRAPH_PROCINFO_LENGTH - len;
 132
 133         /* First spaces to align center */
 134         for (i = 0; i < spaces / 2; i++) {
 135                 ret = trace_seq_printf(s, " ");
 136                 if (!ret)
 137                         return TRACE_TYPE_PARTIAL_LINE;
 138         }
 139
 140         ret = trace_seq_printf(s, "%s-%s", comm, pid_str);
 141         if (!ret)
 142                 return TRACE_TYPE_PARTIAL_LINE;
 143
 144         /* Last spaces to align center */
 145         for (i = 0; i < spaces - (spaces / 2); i++) {
 146                 ret = trace_seq_printf(s, " ");
 147                 if (!ret)
 148                         return TRACE_TYPE_PARTIAL_LINE;
 149         }
 150         return TRACE_TYPE_HANDLED;
 151 }
 152
 153
 154 /* If the pid changed since the last trace, output this event */
 155 static enum print_line_t
 156 verif_pid(struct trace_seq *s, pid_t pid, int cpu)
 157 {
 158         pid_t prev_pid;
 159         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  * Context-switch trace line:
 169
 170  ------------------------------------------
 171  | 1)  migration/0--1  =>  sshd-1755
 172  ------------------------------------------
 173
 174  */
 175         ret = trace_seq_printf(s,
 176                 " ------------------------------------------\n");
 177         if (!ret)
 178                 TRACE_TYPE_PARTIAL_LINE;
 179
 180         ret = print_graph_cpu(s, cpu);
 181         if (ret == TRACE_TYPE_PARTIAL_LINE)
 182                 TRACE_TYPE_PARTIAL_LINE;
 183
 184         ret = print_graph_proc(s, prev_pid);
 185         if (ret == TRACE_TYPE_PARTIAL_LINE)
 186                 TRACE_TYPE_PARTIAL_LINE;
 187
 188         ret = trace_seq_printf(s, " => ");
 189         if (!ret)
 190                 TRACE_TYPE_PARTIAL_LINE;
 191
 192         ret = print_graph_proc(s, pid);
 193         if (ret == TRACE_TYPE_PARTIAL_LINE)
 194                 TRACE_TYPE_PARTIAL_LINE;
 195
 196         ret = trace_seq_printf(s,
 197                 "\n ------------------------------------------\n\n");
 198         if (!ret)
 199                 TRACE_TYPE_PARTIAL_LINE;
 200
 201         return ret;
 202 }
 203
 204 static bool
 205 trace_branch_is_leaf(struct trace_iterator *iter,
 206                 struct ftrace_graph_ent_entry *curr)
 207 {
 208         struct ring_buffer_iter *ring_iter;
 209         struct ring_buffer_event *event;
 210         struct ftrace_graph_ret_entry *next;
 211
 212         ring_iter = iter->buffer_iter[iter->cpu];
 213
 214         if (!ring_iter)
 215                 return false;
 216
 217         event = ring_buffer_iter_peek(ring_iter, NULL);
 218
 219         if (!event)
 220                 return false;
 221
 222         next = ring_buffer_event_data(event);
 223
 224         if (next->ent.type != TRACE_GRAPH_RET)
 225                 return false;
 226
 227         if (curr->ent.pid != next->ent.pid ||
 228                         curr->graph_ent.func != next->ret.func)
 229                 return false;
 230
 231         return true;
 232 }
 233
 234
 235 static enum print_line_t
 236 print_graph_duration(unsigned long long duration, struct trace_seq *s)
 237 {
 238         unsigned long nsecs_rem = do_div(duration, 1000);
 239         /* log10(ULONG_MAX) + '\0' */
 240         char msecs_str[21];
 241         char nsecs_str[5];
 242         int ret, len;
 243         int i;
 244
 245         sprintf(msecs_str, "%lu", (unsigned long) duration);
 246
 247         /* Print msecs */
 248         ret = trace_seq_printf(s, msecs_str);
 249         if (!ret)
 250                 return TRACE_TYPE_PARTIAL_LINE;
 251
 252         len = strlen(msecs_str);
 253
 254         /* Print nsecs (we don't want to exceed 7 numbers) */
 255         if (len < 7) {
 256                 snprintf(nsecs_str, 8 - len, "%03lu", nsecs_rem);
 257                 ret = trace_seq_printf(s, ".%s", nsecs_str);
 258                 if (!ret)
 259                         return TRACE_TYPE_PARTIAL_LINE;
 260                 len += strlen(nsecs_str);
 261         }
 262
 263         ret = trace_seq_printf(s, " us ");
 264         if (!ret)
 265                 return TRACE_TYPE_PARTIAL_LINE;
 266
 267         /* Print remaining spaces to fit the row's width */
 268         for (i = len; i < 7; i++) {
 269                 ret = trace_seq_printf(s, " ");
 270                 if (!ret)
 271                         return TRACE_TYPE_PARTIAL_LINE;
 272         }
 273
 274         ret = trace_seq_printf(s, "|  ");
 275         if (!ret)
 276                 return TRACE_TYPE_PARTIAL_LINE;
 277         return TRACE_TYPE_HANDLED;
 278
 279 }
 280
 281 /* Signal a overhead of time execution to the output */
 282 static int
 283 print_graph_overhead(unsigned long long duration, struct trace_seq *s)
 284 {
 285         /* Duration exceeded 100 msecs */
 286         if (duration > 100000ULL)
 287                 return trace_seq_printf(s, "! ");
 288
 289         /* Duration exceeded 10 msecs */
 290         if (duration > 10000ULL)
 291                 return trace_seq_printf(s, "+ ");
 292
 293         return trace_seq_printf(s, "  ");
 294 }
 295
 296 /* Case of a leaf function on its call entry */
 297 static enum print_line_t
 298 print_graph_entry_leaf(struct trace_iterator *iter,
 299                 struct ftrace_graph_ent_entry *entry, struct trace_seq *s)
 300 {
 301         struct ftrace_graph_ret_entry *ret_entry;
 302         struct ftrace_graph_ret *graph_ret;
 303         struct ring_buffer_event *event;
 304         struct ftrace_graph_ent *call;
 305         unsigned long long duration;
 306         int ret;
 307         int i;
 308
 309         event = ring_buffer_read(iter->buffer_iter[iter->cpu], NULL);
 310         ret_entry = ring_buffer_event_data(event);
 311         graph_ret = &ret_entry->ret;
 312         call = &entry->graph_ent;
 313         duration = graph_ret->rettime - graph_ret->calltime;
 314
 315         /* Overhead */
 316         if (tracer_flags.val & TRACE_GRAPH_PRINT_OVERHEAD) {
 317                 ret = print_graph_overhead(duration, s);
 318                 if (!ret)
 319                         return TRACE_TYPE_PARTIAL_LINE;
 320         }
 321
 322         /* Duration */
 323         ret = print_graph_duration(duration, s);
 324         if (ret == TRACE_TYPE_PARTIAL_LINE)
 325                 return TRACE_TYPE_PARTIAL_LINE;
 326
 327         /* Function */
 328         for (i = 0; i < call->depth * TRACE_GRAPH_INDENT; i++) {
 329                 ret = trace_seq_printf(s, " ");
 330                 if (!ret)
 331                         return TRACE_TYPE_PARTIAL_LINE;
 332         }
 333
 334         ret = seq_print_ip_sym(s, call->func, 0);
 335         if (!ret)
 336                 return TRACE_TYPE_PARTIAL_LINE;
 337
 338         ret = trace_seq_printf(s, "();\n");
 339         if (!ret)
 340                 return TRACE_TYPE_PARTIAL_LINE;
 341
 342         return TRACE_TYPE_HANDLED;
 343 }
 344
 345 static enum print_line_t
 346 print_graph_entry_nested(struct ftrace_graph_ent_entry *entry,
 347                         struct trace_seq *s)
 348 {
 349         int i;
 350         int ret;
 351         struct ftrace_graph_ent *call = &entry->graph_ent;
 352
 353         /* No overhead */
 354         if (tracer_flags.val & TRACE_GRAPH_PRINT_OVERHEAD) {
 355                 ret = trace_seq_printf(s, "  ");
 356                 if (!ret)
 357                         return TRACE_TYPE_PARTIAL_LINE;
 358         }
 359
 360         /* No time */
 361         ret = trace_seq_printf(s, "            |  ");
 362
 363         /* Function */
 364         for (i = 0; i < call->depth * TRACE_GRAPH_INDENT; i++) {
 365                 ret = trace_seq_printf(s, " ");
 366                 if (!ret)
 367                         return TRACE_TYPE_PARTIAL_LINE;
 368         }
 369
 370         ret = seq_print_ip_sym(s, call->func, 0);
 371         if (!ret)
 372                 return TRACE_TYPE_PARTIAL_LINE;
 373
 374         ret = trace_seq_printf(s, "() {\n");
 375         if (!ret)
 376                 return TRACE_TYPE_PARTIAL_LINE;
 377
 378         return TRACE_TYPE_HANDLED;
 379 }
 380
 381 static enum print_line_t
 382 print_graph_entry(struct ftrace_graph_ent_entry *field, struct trace_seq *s,
 383                         struct trace_iterator *iter, int cpu)
 384 {
 385         int ret;
 386         struct trace_entry *ent = iter->ent;
 387
 388         /* Pid */
 389         if (verif_pid(s, ent->pid, cpu) == TRACE_TYPE_PARTIAL_LINE)
 390                 return TRACE_TYPE_PARTIAL_LINE;
 391
 392         /* Cpu */
 393         if (tracer_flags.val & TRACE_GRAPH_PRINT_CPU) {
 394                 ret = print_graph_cpu(s, cpu);
 395                 if (ret == TRACE_TYPE_PARTIAL_LINE)
 396                         return TRACE_TYPE_PARTIAL_LINE;
 397         }
 398
 399         /* Proc */
 400         if (tracer_flags.val & TRACE_GRAPH_PRINT_PROC) {
 401                 ret = print_graph_proc(s, ent->pid);
 402                 if (ret == TRACE_TYPE_PARTIAL_LINE)
 403                         return TRACE_TYPE_PARTIAL_LINE;
 404
 405                 ret = trace_seq_printf(s, " | ");
 406                 if (!ret)
 407                         return TRACE_TYPE_PARTIAL_LINE;
 408         }
 409
 410         if (trace_branch_is_leaf(iter, field))
 411                 return print_graph_entry_leaf(iter, field, s);
 412         else
 413                 return print_graph_entry_nested(field, s);
 414
 415 }
 416
 417 static enum print_line_t
 418 print_graph_return(struct ftrace_graph_ret *trace, struct trace_seq *s,
 419                    struct trace_entry *ent, int cpu)
 420 {
 421         int i;
 422         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                 return TRACE_TYPE_PARTIAL_LINE;
 428
 429         /* Cpu */
 430         if (tracer_flags.val & TRACE_GRAPH_PRINT_CPU) {
 431                 ret = print_graph_cpu(s, cpu);
 432                 if (ret == TRACE_TYPE_PARTIAL_LINE)
 433                         return TRACE_TYPE_PARTIAL_LINE;
 434         }
 435
 436         /* Proc */
 437         if (tracer_flags.val & TRACE_GRAPH_PRINT_PROC) {
 438                 ret = print_graph_proc(s, ent->pid);
 439                 if (ret == TRACE_TYPE_PARTIAL_LINE)
 440                         return TRACE_TYPE_PARTIAL_LINE;
 441
 442                 ret = trace_seq_printf(s, " | ");
 443                 if (!ret)
 444                         return TRACE_TYPE_PARTIAL_LINE;
 445         }
 446
 447         /* Overhead */
 448         if (tracer_flags.val & TRACE_GRAPH_PRINT_OVERHEAD) {
 449                 ret = print_graph_overhead(duration, s);
 450                 if (!ret)
 451                         return TRACE_TYPE_PARTIAL_LINE;
 452         }
 453
 454         /* Duration */
 455         ret = print_graph_duration(duration, s);
 456         if (ret == TRACE_TYPE_PARTIAL_LINE)
 457                 return TRACE_TYPE_PARTIAL_LINE;
 458
 459         /* Closing brace */
 460         for (i = 0; i < trace->depth * TRACE_GRAPH_INDENT; i++) {
 461                 ret = trace_seq_printf(s, " ");
 462                 if (!ret)
 463                         return TRACE_TYPE_PARTIAL_LINE;
 464         }
 465
 466         ret = trace_seq_printf(s, "}\n");
 467         if (!ret)
 468                 return TRACE_TYPE_PARTIAL_LINE;
 469
 470         /* Overrun */
 471         if (tracer_flags.val & TRACE_GRAPH_PRINT_OVERRUN) {
 472                 ret = trace_seq_printf(s, " (Overruns: %lu)\n",
 473                                         trace->overrun);
 474                 if (!ret)
 475                         return TRACE_TYPE_PARTIAL_LINE;
 476         }
 477         return TRACE_TYPE_HANDLED;
 478 }
 479
 480 static enum print_line_t
 481 print_graph_comment(struct print_entry *trace, struct trace_seq *s,
 482                    struct trace_entry *ent, struct trace_iterator *iter)
 483 {
 484         int i;
 485         int ret;
 486
 487         /* Pid */
 488         if (verif_pid(s, ent->pid, iter->cpu) == TRACE_TYPE_PARTIAL_LINE)
 489                 return TRACE_TYPE_PARTIAL_LINE;
 490
 491         /* Cpu */
 492         if (tracer_flags.val & TRACE_GRAPH_PRINT_CPU) {
 493                 ret = print_graph_cpu(s, iter->cpu);
 494                 if (ret == TRACE_TYPE_PARTIAL_LINE)
 495                         return TRACE_TYPE_PARTIAL_LINE;
 496         }
 497
 498         /* Proc */
 499         if (tracer_flags.val & TRACE_GRAPH_PRINT_PROC) {
 500                 ret = print_graph_proc(s, ent->pid);
 501                 if (ret == TRACE_TYPE_PARTIAL_LINE)
 502                         return TRACE_TYPE_PARTIAL_LINE;
 503
 504                 ret = trace_seq_printf(s, " | ");
 505                 if (!ret)
 506                         return TRACE_TYPE_PARTIAL_LINE;
 507         }
 508
 509         /* No overhead */
 510         if (tracer_flags.val & TRACE_GRAPH_PRINT_OVERHEAD) {
 511                 ret = trace_seq_printf(s, "  ");
 512                 if (!ret)
 513                         return TRACE_TYPE_PARTIAL_LINE;
 514         }
 515
 516         /* No time */
 517         ret = trace_seq_printf(s, "            |  ");
 518         if (!ret)
 519                 return TRACE_TYPE_PARTIAL_LINE;
 520
 521         /* Indentation */
 522         if (trace->depth > 0)
 523                 for (i = 0; i < (trace->depth + 1) * TRACE_GRAPH_INDENT; i++) {
 524                         ret = trace_seq_printf(s, " ");
 525                         if (!ret)
 526                                 return TRACE_TYPE_PARTIAL_LINE;
 527                 }
 528
 529         /* The comment */
 530         ret = trace_seq_printf(s, "/* %s", trace->buf);
 531         if (!ret)
 532                 return TRACE_TYPE_PARTIAL_LINE;
 533
 534         if (ent->flags & TRACE_FLAG_CONT)
 535                 trace_seq_print_cont(s, iter);
 536
 537         ret = trace_seq_printf(s, " */\n");
 538         if (!ret)
 539                 return TRACE_TYPE_PARTIAL_LINE;
 540
 541         return TRACE_TYPE_HANDLED;
 542 }
 543
 544
 545 enum print_line_t
 546 print_graph_function(struct trace_iterator *iter)
 547 {
 548         struct trace_seq *s = &iter->seq;
 549         struct trace_entry *entry = iter->ent;
 550
 551         switch (entry->type) {
 552         case TRACE_GRAPH_ENT: {
 553                 struct ftrace_graph_ent_entry *field;
 554                 trace_assign_type(field, entry);
 555                 return print_graph_entry(field, s, iter,
 556                                          iter->cpu);
 557         }
 558         case TRACE_GRAPH_RET: {
 559                 struct ftrace_graph_ret_entry *field;
 560                 trace_assign_type(field, entry);
 561                 return print_graph_return(&field->ret, s, entry, iter->cpu);
 562         }
 563         case TRACE_PRINT: {
 564                 struct print_entry *field;
 565                 trace_assign_type(field, entry);
 566                 return print_graph_comment(field, s, entry, iter);
 567         }
 568         default:
 569                 return TRACE_TYPE_UNHANDLED;
 570         }
 571 }
 572
 573 static void print_graph_headers(struct seq_file *s)
 574 {
 575         /* 1st line */
 576         seq_printf(s, "# ");
 577         if (tracer_flags.val & TRACE_GRAPH_PRINT_CPU)
 578                 seq_printf(s, "CPU ");
 579         if (tracer_flags.val & TRACE_GRAPH_PRINT_PROC)
 580                 seq_printf(s, "TASK/PID     ");
 581         if (tracer_flags.val & TRACE_GRAPH_PRINT_OVERHEAD)
 582                 seq_printf(s, "OVERHEAD/");
 583         seq_printf(s, "DURATION            FUNCTION CALLS\n");
 584
 585         /* 2nd line */
 586         seq_printf(s, "# ");
 587         if (tracer_flags.val & TRACE_GRAPH_PRINT_CPU)
 588                 seq_printf(s, "|   ");
 589         if (tracer_flags.val & TRACE_GRAPH_PRINT_PROC)
 590                 seq_printf(s, "|      |     ");
 591         if (tracer_flags.val & TRACE_GRAPH_PRINT_OVERHEAD) {
 592                 seq_printf(s, "|        ");
 593                 seq_printf(s, "|                   |   |   |   |\n");
 594         } else
 595                 seq_printf(s, "    |               |   |   |   |\n");
 596 }
 597 static struct tracer graph_trace __read_mostly = {
 598         .name           = "function_graph",
 599         .init           = graph_trace_init,
 600         .reset          = graph_trace_reset,
 601         .print_line     = print_graph_function,
 602         .print_header   = print_graph_headers,
 603         .flags          = &tracer_flags,
 604 };
 605
 606 static __init int init_graph_trace(void)
 607 {
 608         return register_tracer(&graph_trace);
 609 }
 610
 611 device_initcall(init_graph_trace);