tools/proftool.c

   1 /*
   2  * Copyright (c) 2013 Google, Inc
   3  *
   4  * SPDX-License-Identifier:     GPL-2.0+
   5  */
   6
   7 /* Decode and dump U-Boot profiling information */
   8
   9 #include <assert.h>
  10 #include <ctype.h>
  11 #include <limits.h>
  12 #include <regex.h>
  13 #include <stdarg.h>
  14 #include <stdio.h>
  15 #include <stdlib.h>
  16 #include <string.h>
  17 #include <unistd.h>
  18 #include <sys/param.h>
  19 #include <sys/types.h>
  20
  21 #include <compiler.h>
  22 #include <trace.h>
  23
  24 #define MAX_LINE_LEN 500
  25
  26 enum {
  27         FUNCF_TRACE     = 1 << 0,       /* Include this function in trace */
  28 };
  29
  30 struct func_info {
  31         unsigned long offset;
  32         const char *name;
  33         unsigned long code_size;
  34         unsigned long call_count;
  35         unsigned flags;
  36         /* the section this function is in */
  37         struct objsection_info *objsection;
  38 };
  39
  40 enum trace_line_type {
  41         TRACE_LINE_INCLUDE,
  42         TRACE_LINE_EXCLUDE,
  43 };
  44
  45 struct trace_configline_info {
  46         struct trace_configline_info *next;
  47         enum trace_line_type type;
  48         const char *name;       /* identifier name / wildcard */
  49         regex_t regex;          /* Regex to use if name starts with / */
  50 };
  51
  52 /* The contents of the trace config file */
  53 struct trace_configline_info *trace_config_head;
  54
  55 struct func_info *func_list;
  56 int func_count;
  57 struct trace_call *call_list;
  58 int call_count;
  59 int verbose;    /* Verbosity level 0=none, 1=warn, 2=notice, 3=info, 4=debug */
  60 unsigned long text_offset;              /* text address of first function */
  61
  62 static void outf(int level, const char *fmt, ...)
  63                 __attribute__ ((format (__printf__, 2, 3)));
  64 #define error(fmt, b...) outf(0, fmt, ##b)
  65 #define warn(fmt, b...) outf(1, fmt, ##b)
  66 #define notice(fmt, b...) outf(2, fmt, ##b)
  67 #define info(fmt, b...) outf(3, fmt, ##b)
  68 #define debug(fmt, b...) outf(4, fmt, ##b)
  69
  70
  71 static void outf(int level, const char *fmt, ...)
  72 {
  73         if (verbose >= level) {
  74                 va_list args;
  75
  76                 va_start(args, fmt);
  77                 vfprintf(stderr, fmt, args);
  78                 va_end(args);
  79         }
  80 }
  81
  82 static void usage(void)
  83 {
  84         fprintf(stderr,
  85                 "Usage: proftool -cds -v3 <cmd> <profdata>\n"
  86                 "\n"
  87                 "Commands\n"
  88                 "   dump-ftrace\t\tDump out textual data in ftrace format\n"
  89                 "\n"
  90                 "Options:\n"
  91                 "   -m <map>\tSpecify Systen.map file\n"
  92                 "   -t <trace>\tSpecific trace data file (from U-Boot)\n"
  93                 "   -v <0-4>\tSpecify verbosity\n");
  94         exit(EXIT_FAILURE);
  95 }
  96
  97 static int h_cmp_offset(const void *v1, const void *v2)
  98 {
  99         const struct func_info *f1 = v1, *f2 = v2;
 100
 101         return (f1->offset / FUNC_SITE_SIZE) - (f2->offset / FUNC_SITE_SIZE);
 102 }
 103
 104 static int read_system_map(FILE *fin)
 105 {
 106         unsigned long offset, start = 0;
 107         struct func_info *func;
 108         char buff[MAX_LINE_LEN];
 109         char symtype;
 110         char symname[MAX_LINE_LEN + 1];
 111         int linenum;
 112         int alloced;
 113
 114         for (linenum = 1, alloced = func_count = 0;; linenum++) {
 115                 int fields = 0;
 116
 117                 if (fgets(buff, sizeof(buff), fin))
 118                         fields = sscanf(buff, "%lx %c %100s\n", &offset,
 119                                 &symtype, symname);
 120                 if (fields == 2) {
 121                         continue;
 122                 } else if (feof(fin)) {
 123                         break;
 124                 } else if (fields < 2) {
 125                         error("Map file line %d: invalid format\n", linenum);
 126                         return 1;
 127                 }
 128
 129                 /* Must be a text symbol */
 130                 symtype = tolower(symtype);
 131                 if (symtype != 't' && symtype != 'w')
 132                         continue;
 133
 134                 if (func_count == alloced) {
 135                         alloced += 256;
 136                         func_list = realloc(func_list,
 137                                         sizeof(struct func_info) * alloced);
 138                         assert(func_list);
 139                 }
 140                 if (!func_count)
 141                         start = offset;
 142
 143                 func = &func_list[func_count++];
 144                 memset(func, '\0', sizeof(*func));
 145                 func->offset = offset - start;
 146                 func->name = strdup(symname);
 147                 func->flags = FUNCF_TRACE;      /* trace by default */
 148
 149                 /* Update previous function's code size */
 150                 if (func_count > 1)
 151                         func[-1].code_size = func->offset - func[-1].offset;
 152         }
 153         notice("%d functions found in map file\n", func_count);
 154         text_offset = start;
 155         return 0;
 156 }
 157
 158 static int read_data(FILE *fin, void *buff, int size)
 159 {
 160         int err;
 161
 162         err = fread(buff, 1, size, fin);
 163         if (!err)
 164                 return 1;
 165         if (err != size) {
 166                 error("Cannot read profile file at pos %ld\n", ftell(fin));
 167                 return -1;
 168         }
 169         return 0;
 170 }
 171
 172 static struct func_info *find_func_by_offset(uint32_t offset)
 173 {
 174         struct func_info key, *found;
 175
 176         key.offset = offset;
 177         found = bsearch(&key, func_list, func_count, sizeof(struct func_info),
 178                         h_cmp_offset);
 179
 180         return found;
 181 }
 182
 183 /* This finds the function which contains the given offset */
 184 static struct func_info *find_caller_by_offset(uint32_t offset)
 185 {
 186         int low;        /* least function that could be a match */
 187         int high;       /* greated function that could be a match */
 188         struct func_info key;
 189
 190         low = 0;
 191         high = func_count - 1;
 192         key.offset = offset;
 193         while (high > low + 1) {
 194                 int mid = (low + high) / 2;
 195                 int result;
 196
 197                 result = h_cmp_offset(&key, &func_list[mid]);
 198                 if (result > 0)
 199                         low = mid;
 200                 else if (result < 0)
 201                         high = mid;
 202                 else
 203                         return &func_list[mid];
 204         }
 205
 206         return low >= 0 ? &func_list[low] : NULL;
 207 }
 208
 209 static int read_calls(FILE *fin, int count)
 210 {
 211         struct trace_call *call_data;
 212         int i;
 213
 214         notice("call count: %d\n", count);
 215         call_list = (struct trace_call *)calloc(count, sizeof(*call_data));
 216         if (!call_list) {
 217                 error("Cannot allocate call_list\n");
 218                 return -1;
 219         }
 220         call_count = count;
 221
 222         call_data = call_list;
 223         for (i = 0; i < count; i++, call_data++) {
 224                 if (read_data(fin, call_data, sizeof(*call_data)))
 225                         return 1;
 226         }
 227         return 0;
 228 }
 229
 230 static int read_profile(FILE *fin, int *not_found)
 231 {
 232         struct trace_output_hdr hdr;
 233
 234         *not_found = 0;
 235         while (!feof(fin)) {
 236                 int err;
 237
 238                 err = read_data(fin, &hdr, sizeof(hdr));
 239                 if (err == 1)
 240                         break; /* EOF */
 241                 else if (err)
 242                         return 1;
 243
 244                 switch (hdr.type) {
 245                 case TRACE_CHUNK_FUNCS:
 246                         /* Ignored at present */
 247                         break;
 248
 249                 case TRACE_CHUNK_CALLS:
 250                         if (read_calls(fin, hdr.rec_count))
 251                                 return 1;
 252                         break;
 253                 }
 254         }
 255         return 0;
 256 }
 257
 258 static int read_map_file(const char *fname)
 259 {
 260         FILE *fmap;
 261         int err = 0;
 262
 263         fmap = fopen(fname, "r");
 264         if (!fmap) {
 265                 error("Cannot open map file '%s'\n", fname);
 266                 return 1;
 267         }
 268         if (fmap) {
 269                 err = read_system_map(fmap);
 270                 fclose(fmap);
 271         }
 272         return err;
 273 }
 274
 275 static int read_profile_file(const char *fname)
 276 {
 277         int not_found = INT_MAX;
 278         FILE *fprof;
 279         int err;
 280
 281         fprof = fopen(fname, "rb");
 282         if (!fprof) {
 283                 error("Cannot open profile data file '%s'\n",
 284                       fname);
 285                 return 1;
 286         } else {
 287                 err = read_profile(fprof, &not_found);
 288                 fclose(fprof);
 289                 if (err)
 290                         return err;
 291
 292                 if (not_found) {
 293                         warn("%d profile functions could not be found in the map file - are you sure that your profile data and map file correspond?\n",
 294                              not_found);
 295                         return 1;
 296                 }
 297         }
 298         return 0;
 299 }
 300
 301 static int regex_report_error(regex_t *regex, int err, const char *op,
 302                               const char *name)
 303 {
 304         char buf[200];
 305
 306         regerror(err, regex, buf, sizeof(buf));
 307         error("Regex error '%s' in %s '%s'\n", buf, op, name);
 308         return -1;
 309 }
 310
 311 static void check_trace_config_line(struct trace_configline_info *item)
 312 {
 313         struct func_info *func, *end;
 314         int err;
 315
 316         debug("Checking trace config line '%s'\n", item->name);
 317         for (func = func_list, end = func + func_count; func < end; func++) {
 318                 err = regexec(&item->regex, func->name, 0, NULL, 0);
 319                 debug("   - regex '%s', string '%s': %d\n", item->name,
 320                       func->name, err);
 321                 if (err == REG_NOMATCH)
 322                         continue;
 323
 324                 if (err) {
 325                         regex_report_error(&item->regex, err, "match",
 326                                            item->name);
 327                         break;
 328                 }
 329
 330                 /* It matches, so perform the action */
 331                 switch (item->type) {
 332                 case TRACE_LINE_INCLUDE:
 333                         info("      include %s at %lx\n", func->name,
 334                              text_offset + func->offset);
 335                         func->flags |= FUNCF_TRACE;
 336                         break;
 337
 338                 case TRACE_LINE_EXCLUDE:
 339                         info("      exclude %s at %lx\n", func->name,
 340                              text_offset + func->offset);
 341                         func->flags &= ~FUNCF_TRACE;
 342                         break;
 343                 }
 344         }
 345 }
 346
 347 static void check_trace_config(void)
 348 {
 349         struct trace_configline_info *line;
 350
 351         for (line = trace_config_head; line; line = line->next)
 352                 check_trace_config_line(line);
 353 }
 354
 355 /**
 356  * Check the functions to see if they each have an objsection. If not, then
 357  * the linker must have eliminated them.
 358  */
 359 static void check_functions(void)
 360 {
 361         struct func_info *func, *end;
 362         unsigned long removed_code_size = 0;
 363         int not_found = 0;
 364
 365         /* Look for missing functions */
 366         for (func = func_list, end = func + func_count; func < end; func++) {
 367                 if (!func->objsection) {
 368                         removed_code_size += func->code_size;
 369                         not_found++;
 370                 }
 371         }
 372
 373         /* Figure out what functions we want to trace */
 374         check_trace_config();
 375
 376         warn("%d functions removed by linker, %ld code size\n",
 377              not_found, removed_code_size);
 378 }
 379
 380 static int read_trace_config(FILE *fin)
 381 {
 382         char buff[200];
 383         int linenum = 0;
 384         struct trace_configline_info **tailp = &trace_config_head;
 385
 386         while (fgets(buff, sizeof(buff), fin)) {
 387                 int len = strlen(buff);
 388                 struct trace_configline_info *line;
 389                 char *saveptr;
 390                 char *s, *tok;
 391                 int err;
 392
 393                 linenum++;
 394                 if (len && buff[len - 1] == '\n')
 395                         buff[len - 1] = '\0';
 396
 397                 /* skip blank lines and comments */
 398                 for (s = buff; *s == ' ' || *s == '\t'; s++)
 399                         ;
 400                 if (!*s || *s == '#')
 401                         continue;
 402
 403                 line = (struct trace_configline_info *)calloc(1,
 404                                                               sizeof(*line));
 405                 if (!line) {
 406                         error("Cannot allocate config line\n");
 407                         return -1;
 408                 }
 409
 410                 tok = strtok_r(s, " \t", &saveptr);
 411                 if (!tok) {
 412                         error("Invalid trace config data on line %d\n",
 413                               linenum);
 414                         return -1;
 415                 }
 416                 if (0 == strcmp(tok, "include-func")) {
 417                         line->type = TRACE_LINE_INCLUDE;
 418                 } else if (0 == strcmp(tok, "exclude-func")) {
 419                         line->type = TRACE_LINE_EXCLUDE;
 420                 } else {
 421                         error("Unknown command in trace config data line %d\n",
 422                               linenum);
 423                         return -1;
 424                 }
 425
 426                 tok = strtok_r(NULL, " \t", &saveptr);
 427                 if (!tok) {
 428                         error("Missing pattern in trace config data line %d\n",
 429                               linenum);
 430                         return -1;
 431                 }
 432
 433                 err = regcomp(&line->regex, tok, REG_NOSUB);
 434                 if (err) {
 435                         free(line);
 436                         return regex_report_error(&line->regex, err, "compile",
 437                                                   tok);
 438                 }
 439
 440                 /* link this new one to the end of the list */
 441                 line->name = strdup(tok);
 442                 line->next = NULL;
 443                 *tailp = line;
 444                 tailp = &line->next;
 445         }
 446
 447         if (!feof(fin)) {
 448                 error("Cannot read from trace config file at position %ld\n",
 449                       ftell(fin));
 450                 return -1;
 451         }
 452         return 0;
 453 }
 454
 455 static int read_trace_config_file(const char *fname)
 456 {
 457         FILE *fin;
 458         int err;
 459
 460         fin = fopen(fname, "r");
 461         if (!fin) {
 462                 error("Cannot open trace_config file '%s'\n", fname);
 463                 return -1;
 464         }
 465         err = read_trace_config(fin);
 466         fclose(fin);
 467         return err;
 468 }
 469
 470 static void out_func(ulong func_offset, int is_caller, const char *suffix)
 471 {
 472         struct func_info *func;
 473
 474         func = (is_caller ? find_caller_by_offset : find_func_by_offset)
 475                 (func_offset);
 476
 477         if (func)
 478                 printf("%s%s", func->name, suffix);
 479         else
 480                 printf("%lx%s", func_offset, suffix);
 481 }
 482
 483 /*
 484  * # tracer: function
 485  * #
 486  * #           TASK-PID   CPU#    TIMESTAMP  FUNCTION
 487  * #              | |      |          |         |
 488  * #           bash-4251  [01] 10152.583854: path_put <-path_walk
 489  * #           bash-4251  [01] 10152.583855: dput <-path_put
 490  * #           bash-4251  [01] 10152.583855: _atomic_dec_and_lock <-dput
 491  */
 492 static int make_ftrace(void)
 493 {
 494         struct trace_call *call;
 495         int missing_count = 0, skip_count = 0;
 496         int i;
 497
 498         printf("# tracer: ftrace\n"
 499                 "#\n"
 500                 "#           TASK-PID   CPU#    TIMESTAMP  FUNCTION\n"
 501                 "#              | |      |          |         |\n");
 502         for (i = 0, call = call_list; i < call_count; i++, call++) {
 503                 struct func_info *func = find_func_by_offset(call->func);
 504                 ulong time = call->flags & FUNCF_TIMESTAMP_MASK;
 505
 506                 if (TRACE_CALL_TYPE(call) != FUNCF_ENTRY &&
 507                     TRACE_CALL_TYPE(call) != FUNCF_EXIT)
 508                         continue;
 509                 if (!func) {
 510                         warn("Cannot find function at %lx\n",
 511                              text_offset + call->func);
 512                         missing_count++;
 513                         continue;
 514                 }
 515
 516                 if (!(func->flags & FUNCF_TRACE)) {
 517                         debug("Funcion '%s' is excluded from trace\n",
 518                               func->name);
 519                         skip_count++;
 520                         continue;
 521                 }
 522
 523                 printf("%16s-%-5d [01] %lu.%06lu: ", "uboot", 1,
 524                        time / 1000000, time % 1000000);
 525
 526                 out_func(call->func, 0, " <- ");
 527                 out_func(call->caller, 1, "\n");
 528         }
 529         info("ftrace: %d functions not found, %d excluded\n", missing_count,
 530              skip_count);
 531
 532         return 0;
 533 }
 534
 535 static int prof_tool(int argc, char * const argv[],
 536                      const char *prof_fname, const char *map_fname,
 537                      const char *trace_config_fname)
 538 {
 539         int err = 0;
 540
 541         if (read_map_file(map_fname))
 542                 return -1;
 543         if (prof_fname && read_profile_file(prof_fname))
 544                 return -1;
 545         if (trace_config_fname && read_trace_config_file(trace_config_fname))
 546                 return -1;
 547
 548         check_functions();
 549
 550         for (; argc; argc--, argv++) {
 551                 const char *cmd = *argv;
 552
 553                 if (0 == strcmp(cmd, "dump-ftrace"))
 554                         err = make_ftrace();
 555                 else
 556                         warn("Unknown command '%s'\n", cmd);
 557         }
 558
 559         return err;
 560 }
 561
 562 int main(int argc, char *argv[])
 563 {
 564         const char *map_fname = "System.map";
 565         const char *prof_fname = NULL;
 566         const char *trace_config_fname = NULL;
 567         int opt;
 568
 569         verbose = 2;
 570         while ((opt = getopt(argc, argv, "m:p:t:v:")) != -1) {
 571                 switch (opt) {
 572                 case 'm':
 573                         map_fname = optarg;
 574                         break;
 575
 576                 case 'p':
 577                         prof_fname = optarg;
 578                         break;
 579
 580                 case 't':
 581                         trace_config_fname = optarg;
 582                         break;
 583
 584                 case 'v':
 585                         verbose = atoi(optarg);
 586                         break;
 587
 588                 default:
 589                         usage();
 590                 }
 591         }
 592         argc -= optind; argv += optind;
 593         if (argc < 1)
 594                 usage();
 595
 596         debug("Debug enabled\n");
 597         return prof_tool(argc, argv, prof_fname, map_fname,
 598                          trace_config_fname);
 599 }