trace_selftest.c 16 KB

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