kernel/trace/trace_selftest.c

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