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