kernel/trace/trace_selftest.c

   1 /* Include in trace.c */
   2
   3 #include <linux/stringify.h>
   4 #include <linux/kthread.h>
   5 #include <linux/delay.h>
   6 #include <linux/slab.h>
   7
   8 static inline int trace_valid_entry(struct trace_entry *entry)
   9 {
  10         switch (entry->type) {
  11         case TRACE_FN:
  12         case TRACE_CTX:
  13         case TRACE_WAKE:
  14         case TRACE_STACK:
  15         case TRACE_PRINT:
  16         case TRACE_SPECIAL:
  17         case TRACE_BRANCH:
  18         case TRACE_GRAPH_ENT:
  19         case TRACE_GRAPH_RET:
  20                 return 1;
  21         }
  22         return 0;
  23 }
  24
  25 static int trace_test_buffer_cpu(struct trace_array *tr, int cpu)
  26 {
  27         struct ring_buffer_event *event;
  28         struct trace_entry *entry;
  29         unsigned int loops = 0;
  30
  31         while ((event = ring_buffer_consume(tr->buffer, cpu, NULL, NULL))) {
  32                 entry = ring_buffer_event_data(event);
  33
  34                 /*
  35                  * The ring buffer is a size of trace_buf_size, if
  36                  * we loop more than the size, there's something wrong
  37                  * with the ring buffer.
  38                  */
  39                 if (loops++ > trace_buf_size) {
  40                         printk(KERN_CONT ".. bad ring buffer ");
  41                         goto failed;
  42                 }
  43                 if (!trace_valid_entry(entry)) {
  44                         printk(KERN_CONT ".. invalid entry %d ",
  45                                 entry->type);
  46                         goto failed;
  47                 }
  48         }
  49         return 0;
  50
  51  failed:
  52         /* disable tracing */
  53         tracing_disabled = 1;
  54         printk(KERN_CONT ".. corrupted trace buffer .. ");
  55         return -1;
  56 }
  57
  58 /*
  59  * Test the trace buffer to see if all the elements
  60  * are still sane.
  61  */
  62 static int trace_test_buffer(struct trace_array *tr, unsigned long *count)
  63 {
  64         unsigned long flags, cnt = 0;
  65         int cpu, ret = 0;
  66
  67         /* Don't allow flipping of max traces now */
  68         local_irq_save(flags);
  69         arch_spin_lock(&ftrace_max_lock);
  70
  71         cnt = ring_buffer_entries(tr->buffer);
  72
  73         /*
  74          * The trace_test_buffer_cpu runs a while loop to consume all data.
  75          * If the calling tracer is broken, and is constantly filling
  76          * the buffer, this will run forever, and hard lock the box.
  77          * We disable the ring buffer while we do this test to prevent
  78          * a hard lock up.
  79          */
  80         tracing_off();
  81         for_each_possible_cpu(cpu) {
  82                 ret = trace_test_buffer_cpu(tr, cpu);
  83                 if (ret)
  84                         break;
  85         }
  86         tracing_on();
  87         arch_spin_unlock(&ftrace_max_lock);
  88         local_irq_restore(flags);
  89
  90         if (count)
  91                 *count = cnt;
  92
  93         return ret;
  94 }
  95
  96 static inline void warn_failed_init_tracer(struct tracer *trace, int init_ret)
  97 {
  98         printk(KERN_WARNING "Failed to init %s tracer, init returned %d\n",
  99                 trace->name, init_ret);
 100 }
 101 #ifdef CONFIG_FUNCTION_TRACER
 102
 103 #ifdef CONFIG_DYNAMIC_FTRACE
 104
 105 /* Test dynamic code modification and ftrace filters */
 106 int trace_selftest_startup_dynamic_tracing(struct tracer *trace,
 107                                            struct trace_array *tr,
 108                                            int (*func)(void))
 109 {
 110         int save_ftrace_enabled = ftrace_enabled;
 111         int save_tracer_enabled = tracer_enabled;
 112         unsigned long count;
 113         char *func_name;
 114         int ret;
 115
 116         /* The ftrace test PASSED */
 117         printk(KERN_CONT "PASSED\n");
 118         pr_info("Testing dynamic ftrace: ");
 119
 120         /* enable tracing, and record the filter function */
 121         ftrace_enabled = 1;
 122         tracer_enabled = 1;
 123
 124         /* passed in by parameter to fool gcc from optimizing */
 125         func();
 126
 127         /*
 128          * Some archs *cough*PowerPC*cough* add characters to the
 129          * start of the function names. We simply put a '*' to
 130          * accommodate them.
 131          */
 132         func_name = "*" __stringify(DYN_FTRACE_TEST_NAME);
 133
 134         /* filter only on our function */
 135         ftrace_set_filter(func_name, strlen(func_name), 1);
 136
 137         /* enable tracing */
 138         ret = tracer_init(trace, tr);
 139         if (ret) {
 140                 warn_failed_init_tracer(trace, ret);
 141                 goto out;
 142         }
 143
 144         /* Sleep for a 1/10 of a second */
 145         msleep(100);
 146
 147         /* we should have nothing in the buffer */
 148         ret = trace_test_buffer(tr, &count);
 149         if (ret)
 150                 goto out;
 151
 152         if (count) {
 153                 ret = -1;
 154                 printk(KERN_CONT ".. filter did not filter .. ");
 155                 goto out;
 156         }
 157
 158         /* call our function again */
 159         func();
 160
 161         /* sleep again */
 162         msleep(100);
 163
 164         /* stop the tracing. */
 165         tracing_stop();
 166         ftrace_enabled = 0;
 167
 168         /* check the trace buffer */
 169         ret = trace_test_buffer(tr, &count);
 170         trace->reset(tr);
 171         tracing_start();
 172
 173         /* we should only have one item */
 174         if (!ret && count != 1) {
 175                 printk(KERN_CONT ".. filter failed count=%ld ..", count);
 176                 ret = -1;
 177                 goto out;
 178         }
 179
 180  out:
 181         ftrace_enabled = save_ftrace_enabled;
 182         tracer_enabled = save_tracer_enabled;
 183
 184         /* Enable tracing on all functions again */
 185         ftrace_set_filter(NULL, 0, 1);
 186
 187         return ret;
 188 }
 189 #else
 190 # define trace_selftest_startup_dynamic_tracing(trace, tr, func) ({ 0; })
 191 #endif /* CONFIG_DYNAMIC_FTRACE */
 192
 193 /*
 194  * Simple verification test of ftrace function tracer.
 195  * Enable ftrace, sleep 1/10 second, and then read the trace
 196  * buffer to see if all is in order.
 197  */
 198 int
 199 trace_selftest_startup_function(struct tracer *trace, struct trace_array *tr)
 200 {
 201         int save_ftrace_enabled = ftrace_enabled;
 202         int save_tracer_enabled = tracer_enabled;
 203         unsigned long count;
 204         int ret;
 205
 206         /* make sure msleep has been recorded */
 207         msleep(1);
 208
 209         /* start the tracing */
 210         ftrace_enabled = 1;
 211         tracer_enabled = 1;
 212
 213         ret = tracer_init(trace, tr);
 214         if (ret) {
 215                 warn_failed_init_tracer(trace, ret);
 216                 goto out;
 217         }
 218
 219         /* Sleep for a 1/10 of a second */
 220         msleep(100);
 221         /* stop the tracing. */
 222         tracing_stop();
 223         ftrace_enabled = 0;
 224
 225         /* check the trace buffer */
 226         ret = trace_test_buffer(tr, &count);
 227         trace->reset(tr);
 228         tracing_start();
 229
 230         if (!ret && !count) {
 231                 printk(KERN_CONT ".. no entries found ..");
 232                 ret = -1;
 233                 goto out;
 234         }
 235
 236         ret = trace_selftest_startup_dynamic_tracing(trace, tr,
 237                                                      DYN_FTRACE_TEST_NAME);
 238
 239  out:
 240         ftrace_enabled = save_ftrace_enabled;
 241         tracer_enabled = save_tracer_enabled;
 242
 243         /* kill ftrace totally if we failed */
 244         if (ret)
 245                 ftrace_kill();
 246
 247         return ret;
 248 }
 249 #endif /* CONFIG_FUNCTION_TRACER */
 250
 251
 252 #ifdef CONFIG_FUNCTION_GRAPH_TRACER
 253
 254 /* Maximum number of functions to trace before diagnosing a hang */
 255 #define GRAPH_MAX_FUNC_TEST     100000000
 256
 257 static void
 258 __ftrace_dump(bool disable_tracing, enum ftrace_dump_mode oops_dump_mode);
 259 static unsigned int graph_hang_thresh;
 260
 261 /* Wrap the real function entry probe to avoid possible hanging */
 262 static int trace_graph_entry_watchdog(struct ftrace_graph_ent *trace)
 263 {
 264         /* This is harmlessly racy, we want to approximately detect a hang */
 265         if (unlikely(++graph_hang_thresh > GRAPH_MAX_FUNC_TEST)) {
 266                 ftrace_graph_stop();
 267                 printk(KERN_WARNING "BUG: Function graph tracer hang!\n");
 268                 if (ftrace_dump_on_oops)
 269                         __ftrace_dump(false, DUMP_ALL);
 270                 return 0;
 271         }
 272
 273         return trace_graph_entry(trace);
 274 }
 275
 276 /*
 277  * Pretty much the same than for the function tracer from which the selftest
 278  * has been borrowed.
 279  */
 280 int
 281 trace_selftest_startup_function_graph(struct tracer *trace,
 282                                         struct trace_array *tr)
 283 {
 284         int ret;
 285         unsigned long count;
 286
 287         /*
 288          * Simulate the init() callback but we attach a watchdog callback
 289          * to detect and recover from possible hangs
 290          */
 291         tracing_reset_online_cpus(tr);
 292         set_graph_array(tr);
 293         ret = register_ftrace_graph(&trace_graph_return,
 294                                     &trace_graph_entry_watchdog);
 295         if (ret) {
 296                 warn_failed_init_tracer(trace, ret);
 297                 goto out;
 298         }
 299         tracing_start_cmdline_record();
 300
 301         /* Sleep for a 1/10 of a second */
 302         msleep(100);
 303
 304         /* Have we just recovered from a hang? */
 305         if (graph_hang_thresh > GRAPH_MAX_FUNC_TEST) {
 306                 tracing_selftest_disabled = true;
 307                 ret = -1;
 308                 goto out;
 309         }
 310
 311         tracing_stop();
 312
 313         /* check the trace buffer */
 314         ret = trace_test_buffer(tr, &count);
 315
 316         trace->reset(tr);
 317         tracing_start();
 318
 319         if (!ret && !count) {
 320                 printk(KERN_CONT ".. no entries found ..");
 321                 ret = -1;
 322                 goto out;
 323         }
 324
 325         /* Don't test dynamic tracing, the function tracer already did */
 326
 327 out:
 328         /* Stop it if we failed */
 329         if (ret)
 330                 ftrace_graph_stop();
 331
 332         return ret;
 333 }
 334 #endif /* CONFIG_FUNCTION_GRAPH_TRACER */
 335
 336
 337 #ifdef CONFIG_IRQSOFF_TRACER
 338 int
 339 trace_selftest_startup_irqsoff(struct tracer *trace, struct trace_array *tr)
 340 {
 341         unsigned long save_max = tracing_max_latency;
 342         unsigned long count;
 343         int ret;
 344
 345         /* start the tracing */
 346         ret = tracer_init(trace, tr);
 347         if (ret) {
 348                 warn_failed_init_tracer(trace, ret);
 349                 return ret;
 350         }
 351
 352         /* reset the max latency */
 353         tracing_max_latency = 0;
 354         /* disable interrupts for a bit */
 355         local_irq_disable();
 356         udelay(100);
 357         local_irq_enable();
 358
 359         /*
 360          * Stop the tracer to avoid a warning subsequent
 361          * to buffer flipping failure because tracing_stop()
 362          * disables the tr and max buffers, making flipping impossible
 363          * in case of parallels max irqs off latencies.
 364          */
 365         trace->stop(tr);
 366         /* stop the tracing. */
 367         tracing_stop();
 368         /* check both trace buffers */
 369         ret = trace_test_buffer(tr, NULL);
 370         if (!ret)
 371                 ret = trace_test_buffer(&max_tr, &count);
 372         trace->reset(tr);
 373         tracing_start();
 374
 375         if (!ret && !count) {
 376                 printk(KERN_CONT ".. no entries found ..");
 377                 ret = -1;
 378         }
 379
 380         tracing_max_latency = save_max;
 381
 382         return ret;
 383 }
 384 #endif /* CONFIG_IRQSOFF_TRACER */
 385
 386 #ifdef CONFIG_PREEMPT_TRACER
 387 int
 388 trace_selftest_startup_preemptoff(struct tracer *trace, struct trace_array *tr)
 389 {
 390         unsigned long save_max = tracing_max_latency;
 391         unsigned long count;
 392         int ret;
 393
 394         /*
 395          * Now that the big kernel lock is no longer preemptable,
 396          * and this is called with the BKL held, it will always
 397          * fail. If preemption is already disabled, simply
 398          * pass the test. When the BKL is removed, or becomes
 399          * preemptible again, we will once again test this,
 400          * so keep it in.
 401          */
 402         if (preempt_count()) {
 403                 printk(KERN_CONT "can not test ... force ");
 404                 return 0;
 405         }
 406
 407         /* start the tracing */
 408         ret = tracer_init(trace, tr);
 409         if (ret) {
 410                 warn_failed_init_tracer(trace, ret);
 411                 return ret;
 412         }
 413
 414         /* reset the max latency */
 415         tracing_max_latency = 0;
 416         /* disable preemption for a bit */
 417         preempt_disable();
 418         udelay(100);
 419         preempt_enable();
 420
 421         /*
 422          * Stop the tracer to avoid a warning subsequent
 423          * to buffer flipping failure because tracing_stop()
 424          * disables the tr and max buffers, making flipping impossible
 425          * in case of parallels max preempt off latencies.
 426          */
 427         trace->stop(tr);
 428         /* stop the tracing. */
 429         tracing_stop();
 430         /* check both trace buffers */
 431         ret = trace_test_buffer(tr, NULL);
 432         if (!ret)
 433                 ret = trace_test_buffer(&max_tr, &count);
 434         trace->reset(tr);
 435         tracing_start();
 436
 437         if (!ret && !count) {
 438                 printk(KERN_CONT ".. no entries found ..");
 439                 ret = -1;
 440         }
 441
 442         tracing_max_latency = save_max;
 443
 444         return ret;
 445 }
 446 #endif /* CONFIG_PREEMPT_TRACER */
 447
 448 #if defined(CONFIG_IRQSOFF_TRACER) && defined(CONFIG_PREEMPT_TRACER)
 449 int
 450 trace_selftest_startup_preemptirqsoff(struct tracer *trace, struct trace_array *tr)
 451 {
 452         unsigned long save_max = tracing_max_latency;
 453         unsigned long count;
 454         int ret;
 455
 456         /*
 457          * Now that the big kernel lock is no longer preemptable,
 458          * and this is called with the BKL held, it will always
 459          * fail. If preemption is already disabled, simply
 460          * pass the test. When the BKL is removed, or becomes
 461          * preemptible again, we will once again test this,
 462          * so keep it in.
 463          */
 464         if (preempt_count()) {
 465                 printk(KERN_CONT "can not test ... force ");
 466                 return 0;
 467         }
 468
 469         /* start the tracing */
 470         ret = tracer_init(trace, tr);
 471         if (ret) {
 472                 warn_failed_init_tracer(trace, ret);
 473                 goto out_no_start;
 474         }
 475
 476         /* reset the max latency */
 477         tracing_max_latency = 0;
 478
 479         /* disable preemption and interrupts for a bit */
 480         preempt_disable();
 481         local_irq_disable();
 482         udelay(100);
 483         preempt_enable();
 484         /* reverse the order of preempt vs irqs */
 485         local_irq_enable();
 486
 487         /*
 488          * Stop the tracer to avoid a warning subsequent
 489          * to buffer flipping failure because tracing_stop()
 490          * disables the tr and max buffers, making flipping impossible
 491          * in case of parallels max irqs/preempt off latencies.
 492          */
 493         trace->stop(tr);
 494         /* stop the tracing. */
 495         tracing_stop();
 496         /* check both trace buffers */
 497         ret = trace_test_buffer(tr, NULL);
 498         if (ret)
 499                 goto out;
 500
 501         ret = trace_test_buffer(&max_tr, &count);
 502         if (ret)
 503                 goto out;
 504
 505         if (!ret && !count) {
 506                 printk(KERN_CONT ".. no entries found ..");
 507                 ret = -1;
 508                 goto out;
 509         }
 510
 511         /* do the test by disabling interrupts first this time */
 512         tracing_max_latency = 0;
 513         tracing_start();
 514         trace->start(tr);
 515
 516         preempt_disable();
 517         local_irq_disable();
 518         udelay(100);
 519         preempt_enable();
 520         /* reverse the order of preempt vs irqs */
 521         local_irq_enable();
 522
 523         trace->stop(tr);
 524         /* stop the tracing. */
 525         tracing_stop();
 526         /* check both trace buffers */
 527         ret = trace_test_buffer(tr, NULL);
 528         if (ret)
 529                 goto out;
 530
 531         ret = trace_test_buffer(&max_tr, &count);
 532
 533         if (!ret && !count) {
 534                 printk(KERN_CONT ".. no entries found ..");
 535                 ret = -1;
 536                 goto out;
 537         }
 538
 539 out:
 540         tracing_start();
 541 out_no_start:
 542         trace->reset(tr);
 543         tracing_max_latency = save_max;
 544
 545         return ret;
 546 }
 547 #endif /* CONFIG_IRQSOFF_TRACER && CONFIG_PREEMPT_TRACER */
 548
 549 #ifdef CONFIG_NOP_TRACER
 550 int
 551 trace_selftest_startup_nop(struct tracer *trace, struct trace_array *tr)
 552 {
 553         /* What could possibly go wrong? */
 554         return 0;
 555 }
 556 #endif
 557
 558 #ifdef CONFIG_SCHED_TRACER
 559 static int trace_wakeup_test_thread(void *data)
 560 {
 561         /* Make this a RT thread, doesn't need to be too high */
 562         struct sched_param param = { .sched_priority = 5 };
 563         struct completion *x = data;
 564
 565         sched_setscheduler(current, SCHED_FIFO, &param);
 566
 567         /* Make it know we have a new prio */
 568         complete(x);
 569
 570         /* now go to sleep and let the test wake us up */
 571         set_current_state(TASK_INTERRUPTIBLE);
 572         schedule();
 573
 574         /* we are awake, now wait to disappear */
 575         while (!kthread_should_stop()) {
 576                 /*
 577                  * This is an RT task, do short sleeps to let
 578                  * others run.
 579                  */
 580                 msleep(100);
 581         }
 582
 583         return 0;
 584 }
 585
 586 int
 587 trace_selftest_startup_wakeup(struct tracer *trace, struct trace_array *tr)
 588 {
 589         unsigned long save_max = tracing_max_latency;
 590         struct task_struct *p;
 591         struct completion isrt;
 592         unsigned long count;
 593         int ret;
 594
 595         init_completion(&isrt);
 596
 597         /* create a high prio thread */
 598         p = kthread_run(trace_wakeup_test_thread, &isrt, "ftrace-test");
 599         if (IS_ERR(p)) {
 600                 printk(KERN_CONT "Failed to create ftrace wakeup test thread ");
 601                 return -1;
 602         }
 603
 604         /* make sure the thread is running at an RT prio */
 605         wait_for_completion(&isrt);
 606
 607         /* start the tracing */
 608         ret = tracer_init(trace, tr);
 609         if (ret) {
 610                 warn_failed_init_tracer(trace, ret);
 611                 return ret;
 612         }
 613
 614         /* reset the max latency */
 615         tracing_max_latency = 0;
 616
 617         /* sleep to let the RT thread sleep too */
 618         msleep(100);
 619
 620         /*
 621          * Yes this is slightly racy. It is possible that for some
 622          * strange reason that the RT thread we created, did not
 623          * call schedule for 100ms after doing the completion,
 624          * and we do a wakeup on a task that already is awake.
 625          * But that is extremely unlikely, and the worst thing that
 626          * happens in such a case, is that we disable tracing.
 627          * Honestly, if this race does happen something is horrible
 628          * wrong with the system.
 629          */
 630
 631         wake_up_process(p);
 632
 633         /* give a little time to let the thread wake up */
 634         msleep(100);
 635
 636         /* stop the tracing. */
 637         tracing_stop();
 638         /* check both trace buffers */
 639         ret = trace_test_buffer(tr, NULL);
 640         if (!ret)
 641                 ret = trace_test_buffer(&max_tr, &count);
 642
 643
 644         trace->reset(tr);
 645         tracing_start();
 646
 647         tracing_max_latency = save_max;
 648
 649         /* kill the thread */
 650         kthread_stop(p);
 651
 652         if (!ret && !count) {
 653                 printk(KERN_CONT ".. no entries found ..");
 654                 ret = -1;
 655         }
 656
 657         return ret;
 658 }
 659 #endif /* CONFIG_SCHED_TRACER */
 660
 661 #ifdef CONFIG_CONTEXT_SWITCH_TRACER
 662 int
 663 trace_selftest_startup_sched_switch(struct tracer *trace, struct trace_array *tr)
 664 {
 665         unsigned long count;
 666         int ret;
 667
 668         /* start the tracing */
 669         ret = tracer_init(trace, tr);
 670         if (ret) {
 671                 warn_failed_init_tracer(trace, ret);
 672                 return ret;
 673         }
 674
 675         /* Sleep for a 1/10 of a second */
 676         msleep(100);
 677         /* stop the tracing. */
 678         tracing_stop();
 679         /* check the trace buffer */
 680         ret = trace_test_buffer(tr, &count);
 681         trace->reset(tr);
 682         tracing_start();
 683
 684         if (!ret && !count) {
 685                 printk(KERN_CONT ".. no entries found ..");
 686                 ret = -1;
 687         }
 688
 689         return ret;
 690 }
 691 #endif /* CONFIG_CONTEXT_SWITCH_TRACER */
 692
 693 #ifdef CONFIG_SYSPROF_TRACER
 694 int
 695 trace_selftest_startup_sysprof(struct tracer *trace, struct trace_array *tr)
 696 {
 697         unsigned long count;
 698         int ret;
 699
 700         /* start the tracing */
 701         ret = tracer_init(trace, tr);
 702         if (ret) {
 703                 warn_failed_init_tracer(trace, ret);
 704                 return ret;
 705         }
 706
 707         /* Sleep for a 1/10 of a second */
 708         msleep(100);
 709         /* stop the tracing. */
 710         tracing_stop();
 711         /* check the trace buffer */
 712         ret = trace_test_buffer(tr, &count);
 713         trace->reset(tr);
 714         tracing_start();
 715
 716         if (!ret && !count) {
 717                 printk(KERN_CONT ".. no entries found ..");
 718                 ret = -1;
 719         }
 720
 721         return ret;
 722 }
 723 #endif /* CONFIG_SYSPROF_TRACER */
 724
 725 #ifdef CONFIG_BRANCH_TRACER
 726 int
 727 trace_selftest_startup_branch(struct tracer *trace, struct trace_array *tr)
 728 {
 729         unsigned long count;
 730         int ret;
 731
 732         /* start the tracing */
 733         ret = tracer_init(trace, tr);
 734         if (ret) {
 735                 warn_failed_init_tracer(trace, ret);
 736                 return ret;
 737         }
 738
 739         /* Sleep for a 1/10 of a second */
 740         msleep(100);
 741         /* stop the tracing. */
 742         tracing_stop();
 743         /* check the trace buffer */
 744         ret = trace_test_buffer(tr, &count);
 745         trace->reset(tr);
 746         tracing_start();
 747
 748         if (!ret && !count) {
 749                 printk(KERN_CONT ".. no entries found ..");
 750                 ret = -1;
 751         }
 752
 753         return ret;
 754 }
 755 #endif /* CONFIG_BRANCH_TRACER */
 756