trace_irqsoff.c 15 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290291292293294295296297298299300301302303304305306307308309310311312313314315316317318319320321322323324325326327328329330331332333334335336337338339340341342343344345346347348349350351352353354355356357358359360361362363364365366367368369370371372373374375376377378379380381382383384385386387388389390391392393394395396397398399400401402403404405406407408409410411412413414415416417418419420421422423424425426427428429430431432433434435436437438439440441442443444445446447448449450451452453454455456457458459460461462463464465466467468469470471472473474475476477478479480481482483484485486487488489490491492493494495496497498499500501502503504505506507508509510511512513514515516517518519520521522523524525526527528529530531532533534535536537538539540541542543544545546547548549550551552553554555556557558559560561562563564565566567568569570571572573574575576577578579580581582583584585586587588589590591592593594595596597598599600601602603604605606607608609610611612613614615616617618619620621622623624625626627628629630631632633634635636637638639640641642643644645646647648649650651652653654655656657658659660661662663664665666667668669670671672673674675676677678679680681682683684685686687688
  1. /*
  2. * trace irqs off critical timings
  3. *
  4. * Copyright (C) 2007-2008 Steven Rostedt <srostedt@redhat.com>
  5. * Copyright (C) 2008 Ingo Molnar <mingo@redhat.com>
  6. *
  7. * From code in the latency_tracer, that is:
  8. *
  9. * Copyright (C) 2004-2006 Ingo Molnar
  10. * Copyright (C) 2004 William Lee Irwin III
  11. */
  12. #include <linux/kallsyms.h>
  13. #include <linux/debugfs.h>
  14. #include <linux/uaccess.h>
  15. #include <linux/module.h>
  16. #include <linux/ftrace.h>
  17. #include <linux/fs.h>
  18. #include "trace.h"
  19. static struct trace_array *irqsoff_trace __read_mostly;
  20. static int tracer_enabled __read_mostly;
  21. static DEFINE_PER_CPU(int, tracing_cpu);
  22. static DEFINE_SPINLOCK(max_trace_lock);
  23. enum {
  24. TRACER_IRQS_OFF = (1 << 1),
  25. TRACER_PREEMPT_OFF = (1 << 2),
  26. };
  27. static int trace_type __read_mostly;
  28. static int save_lat_flag;
  29. static void stop_irqsoff_tracer(struct trace_array *tr, int graph);
  30. static int start_irqsoff_tracer(struct trace_array *tr, int graph);
  31. #ifdef CONFIG_PREEMPT_TRACER
  32. static inline int
  33. preempt_trace(void)
  34. {
  35. return ((trace_type & TRACER_PREEMPT_OFF) && preempt_count());
  36. }
  37. #else
  38. # define preempt_trace() (0)
  39. #endif
  40. #ifdef CONFIG_IRQSOFF_TRACER
  41. static inline int
  42. irq_trace(void)
  43. {
  44. return ((trace_type & TRACER_IRQS_OFF) &&
  45. irqs_disabled());
  46. }
  47. #else
  48. # define irq_trace() (0)
  49. #endif
  50. #define TRACE_DISPLAY_GRAPH 1
  51. static struct tracer_opt trace_opts[] = {
  52. #ifdef CONFIG_FUNCTION_GRAPH_TRACER
  53. /* display latency trace as call graph */
  54. { TRACER_OPT(display-graph, TRACE_DISPLAY_GRAPH) },
  55. #endif
  56. { } /* Empty entry */
  57. };
  58. static struct tracer_flags tracer_flags = {
  59. .val = 0,
  60. .opts = trace_opts,
  61. };
  62. #define is_graph() (tracer_flags.val & TRACE_DISPLAY_GRAPH)
  63. /*
  64. * Sequence count - we record it when starting a measurement and
  65. * skip the latency if the sequence has changed - some other section
  66. * did a maximum and could disturb our measurement with serial console
  67. * printouts, etc. Truly coinciding maximum latencies should be rare
  68. * and what happens together happens separately as well, so this doesn't
  69. * decrease the validity of the maximum found:
  70. */
  71. static __cacheline_aligned_in_smp unsigned long max_sequence;
  72. #ifdef CONFIG_FUNCTION_TRACER
  73. /*
  74. * Prologue for the preempt and irqs off function tracers.
  75. *
  76. * Returns 1 if it is OK to continue, and data->disabled is
  77. * incremented.
  78. * 0 if the trace is to be ignored, and data->disabled
  79. * is kept the same.
  80. *
  81. * Note, this function is also used outside this ifdef but
  82. * inside the #ifdef of the function graph tracer below.
  83. * This is OK, since the function graph tracer is
  84. * dependent on the function tracer.
  85. */
  86. static int func_prolog_dec(struct trace_array *tr,
  87. struct trace_array_cpu **data,
  88. unsigned long *flags)
  89. {
  90. long disabled;
  91. int cpu;
  92. /*
  93. * Does not matter if we preempt. We test the flags
  94. * afterward, to see if irqs are disabled or not.
  95. * If we preempt and get a false positive, the flags
  96. * test will fail.
  97. */
  98. cpu = raw_smp_processor_id();
  99. if (likely(!per_cpu(tracing_cpu, cpu)))
  100. return 0;
  101. local_save_flags(*flags);
  102. /* slight chance to get a false positive on tracing_cpu */
  103. if (!irqs_disabled_flags(*flags))
  104. return 0;
  105. *data = tr->data[cpu];
  106. disabled = atomic_inc_return(&(*data)->disabled);
  107. if (likely(disabled == 1))
  108. return 1;
  109. atomic_dec(&(*data)->disabled);
  110. return 0;
  111. }
  112. /*
  113. * irqsoff uses its own tracer function to keep the overhead down:
  114. */
  115. static void
  116. irqsoff_tracer_call(unsigned long ip, unsigned long parent_ip)
  117. {
  118. struct trace_array *tr = irqsoff_trace;
  119. struct trace_array_cpu *data;
  120. unsigned long flags;
  121. if (!func_prolog_dec(tr, &data, &flags))
  122. return;
  123. trace_function(tr, ip, parent_ip, flags, preempt_count());
  124. atomic_dec(&data->disabled);
  125. }
  126. static struct ftrace_ops trace_ops __read_mostly =
  127. {
  128. .func = irqsoff_tracer_call,
  129. .flags = FTRACE_OPS_FL_GLOBAL,
  130. };
  131. #endif /* CONFIG_FUNCTION_TRACER */
  132. #ifdef CONFIG_FUNCTION_GRAPH_TRACER
  133. static int irqsoff_set_flag(u32 old_flags, u32 bit, int set)
  134. {
  135. int cpu;
  136. if (!(bit & TRACE_DISPLAY_GRAPH))
  137. return -EINVAL;
  138. if (!(is_graph() ^ set))
  139. return 0;
  140. stop_irqsoff_tracer(irqsoff_trace, !set);
  141. for_each_possible_cpu(cpu)
  142. per_cpu(tracing_cpu, cpu) = 0;
  143. tracing_max_latency = 0;
  144. tracing_reset_online_cpus(irqsoff_trace);
  145. return start_irqsoff_tracer(irqsoff_trace, set);
  146. }
  147. static int irqsoff_graph_entry(struct ftrace_graph_ent *trace)
  148. {
  149. struct trace_array *tr = irqsoff_trace;
  150. struct trace_array_cpu *data;
  151. unsigned long flags;
  152. int ret;
  153. int pc;
  154. if (!func_prolog_dec(tr, &data, &flags))
  155. return 0;
  156. pc = preempt_count();
  157. ret = __trace_graph_entry(tr, trace, flags, pc);
  158. atomic_dec(&data->disabled);
  159. return ret;
  160. }
  161. static void irqsoff_graph_return(struct ftrace_graph_ret *trace)
  162. {
  163. struct trace_array *tr = irqsoff_trace;
  164. struct trace_array_cpu *data;
  165. unsigned long flags;
  166. int pc;
  167. if (!func_prolog_dec(tr, &data, &flags))
  168. return;
  169. pc = preempt_count();
  170. __trace_graph_return(tr, trace, flags, pc);
  171. atomic_dec(&data->disabled);
  172. }
  173. static void irqsoff_trace_open(struct trace_iterator *iter)
  174. {
  175. if (is_graph())
  176. graph_trace_open(iter);
  177. }
  178. static void irqsoff_trace_close(struct trace_iterator *iter)
  179. {
  180. if (iter->private)
  181. graph_trace_close(iter);
  182. }
  183. #define GRAPH_TRACER_FLAGS (TRACE_GRAPH_PRINT_CPU | \
  184. TRACE_GRAPH_PRINT_PROC)
  185. static enum print_line_t irqsoff_print_line(struct trace_iterator *iter)
  186. {
  187. /*
  188. * In graph mode call the graph tracer output function,
  189. * otherwise go with the TRACE_FN event handler
  190. */
  191. if (is_graph())
  192. return print_graph_function_flags(iter, GRAPH_TRACER_FLAGS);
  193. return TRACE_TYPE_UNHANDLED;
  194. }
  195. static void irqsoff_print_header(struct seq_file *s)
  196. {
  197. if (is_graph())
  198. print_graph_headers_flags(s, GRAPH_TRACER_FLAGS);
  199. else
  200. trace_default_header(s);
  201. }
  202. static void
  203. __trace_function(struct trace_array *tr,
  204. unsigned long ip, unsigned long parent_ip,
  205. unsigned long flags, int pc)
  206. {
  207. if (is_graph())
  208. trace_graph_function(tr, ip, parent_ip, flags, pc);
  209. else
  210. trace_function(tr, ip, parent_ip, flags, pc);
  211. }
  212. #else
  213. #define __trace_function trace_function
  214. static int irqsoff_set_flag(u32 old_flags, u32 bit, int set)
  215. {
  216. return -EINVAL;
  217. }
  218. static int irqsoff_graph_entry(struct ftrace_graph_ent *trace)
  219. {
  220. return -1;
  221. }
  222. static enum print_line_t irqsoff_print_line(struct trace_iterator *iter)
  223. {
  224. return TRACE_TYPE_UNHANDLED;
  225. }
  226. static void irqsoff_graph_return(struct ftrace_graph_ret *trace) { }
  227. static void irqsoff_print_header(struct seq_file *s) { }
  228. static void irqsoff_trace_open(struct trace_iterator *iter) { }
  229. static void irqsoff_trace_close(struct trace_iterator *iter) { }
  230. #endif /* CONFIG_FUNCTION_GRAPH_TRACER */
  231. /*
  232. * Should this new latency be reported/recorded?
  233. */
  234. static int report_latency(cycle_t delta)
  235. {
  236. if (tracing_thresh) {
  237. if (delta < tracing_thresh)
  238. return 0;
  239. } else {
  240. if (delta <= tracing_max_latency)
  241. return 0;
  242. }
  243. return 1;
  244. }
  245. static void
  246. check_critical_timing(struct trace_array *tr,
  247. struct trace_array_cpu *data,
  248. unsigned long parent_ip,
  249. int cpu)
  250. {
  251. cycle_t T0, T1, delta;
  252. unsigned long flags;
  253. int pc;
  254. T0 = data->preempt_timestamp;
  255. T1 = ftrace_now(cpu);
  256. delta = T1-T0;
  257. local_save_flags(flags);
  258. pc = preempt_count();
  259. if (!report_latency(delta))
  260. goto out;
  261. spin_lock_irqsave(&max_trace_lock, flags);
  262. /* check if we are still the max latency */
  263. if (!report_latency(delta))
  264. goto out_unlock;
  265. __trace_function(tr, CALLER_ADDR0, parent_ip, flags, pc);
  266. /* Skip 5 functions to get to the irq/preempt enable function */
  267. __trace_stack(tr, flags, 5, pc);
  268. if (data->critical_sequence != max_sequence)
  269. goto out_unlock;
  270. data->critical_end = parent_ip;
  271. if (likely(!is_tracing_stopped())) {
  272. tracing_max_latency = delta;
  273. update_max_tr_single(tr, current, cpu);
  274. }
  275. max_sequence++;
  276. out_unlock:
  277. spin_unlock_irqrestore(&max_trace_lock, flags);
  278. out:
  279. data->critical_sequence = max_sequence;
  280. data->preempt_timestamp = ftrace_now(cpu);
  281. __trace_function(tr, CALLER_ADDR0, parent_ip, flags, pc);
  282. }
  283. static inline void
  284. start_critical_timing(unsigned long ip, unsigned long parent_ip)
  285. {
  286. int cpu;
  287. struct trace_array *tr = irqsoff_trace;
  288. struct trace_array_cpu *data;
  289. unsigned long flags;
  290. if (likely(!tracer_enabled))
  291. return;
  292. cpu = raw_smp_processor_id();
  293. if (per_cpu(tracing_cpu, cpu))
  294. return;
  295. data = tr->data[cpu];
  296. if (unlikely(!data) || atomic_read(&data->disabled))
  297. return;
  298. atomic_inc(&data->disabled);
  299. data->critical_sequence = max_sequence;
  300. data->preempt_timestamp = ftrace_now(cpu);
  301. data->critical_start = parent_ip ? : ip;
  302. local_save_flags(flags);
  303. __trace_function(tr, ip, parent_ip, flags, preempt_count());
  304. per_cpu(tracing_cpu, cpu) = 1;
  305. atomic_dec(&data->disabled);
  306. }
  307. static inline void
  308. stop_critical_timing(unsigned long ip, unsigned long parent_ip)
  309. {
  310. int cpu;
  311. struct trace_array *tr = irqsoff_trace;
  312. struct trace_array_cpu *data;
  313. unsigned long flags;
  314. cpu = raw_smp_processor_id();
  315. /* Always clear the tracing cpu on stopping the trace */
  316. if (unlikely(per_cpu(tracing_cpu, cpu)))
  317. per_cpu(tracing_cpu, cpu) = 0;
  318. else
  319. return;
  320. if (!tracer_enabled)
  321. return;
  322. data = tr->data[cpu];
  323. if (unlikely(!data) ||
  324. !data->critical_start || atomic_read(&data->disabled))
  325. return;
  326. atomic_inc(&data->disabled);
  327. local_save_flags(flags);
  328. __trace_function(tr, ip, parent_ip, flags, preempt_count());
  329. check_critical_timing(tr, data, parent_ip ? : ip, cpu);
  330. data->critical_start = 0;
  331. atomic_dec(&data->disabled);
  332. }
  333. /* start and stop critical timings used to for stoppage (in idle) */
  334. void start_critical_timings(void)
  335. {
  336. if (preempt_trace() || irq_trace())
  337. start_critical_timing(CALLER_ADDR0, CALLER_ADDR1);
  338. }
  339. EXPORT_SYMBOL_GPL(start_critical_timings);
  340. void stop_critical_timings(void)
  341. {
  342. if (preempt_trace() || irq_trace())
  343. stop_critical_timing(CALLER_ADDR0, CALLER_ADDR1);
  344. }
  345. EXPORT_SYMBOL_GPL(stop_critical_timings);
  346. #ifdef CONFIG_IRQSOFF_TRACER
  347. #ifdef CONFIG_PROVE_LOCKING
  348. void time_hardirqs_on(unsigned long a0, unsigned long a1)
  349. {
  350. if (!preempt_trace() && irq_trace())
  351. stop_critical_timing(a0, a1);
  352. }
  353. void time_hardirqs_off(unsigned long a0, unsigned long a1)
  354. {
  355. if (!preempt_trace() && irq_trace())
  356. start_critical_timing(a0, a1);
  357. }
  358. #else /* !CONFIG_PROVE_LOCKING */
  359. /*
  360. * Stubs:
  361. */
  362. void trace_softirqs_on(unsigned long ip)
  363. {
  364. }
  365. void trace_softirqs_off(unsigned long ip)
  366. {
  367. }
  368. inline void print_irqtrace_events(struct task_struct *curr)
  369. {
  370. }
  371. /*
  372. * We are only interested in hardirq on/off events:
  373. */
  374. void trace_hardirqs_on(void)
  375. {
  376. if (!preempt_trace() && irq_trace())
  377. stop_critical_timing(CALLER_ADDR0, CALLER_ADDR1);
  378. }
  379. EXPORT_SYMBOL(trace_hardirqs_on);
  380. void trace_hardirqs_off(void)
  381. {
  382. if (!preempt_trace() && irq_trace())
  383. start_critical_timing(CALLER_ADDR0, CALLER_ADDR1);
  384. }
  385. EXPORT_SYMBOL(trace_hardirqs_off);
  386. void trace_hardirqs_on_caller(unsigned long caller_addr)
  387. {
  388. if (!preempt_trace() && irq_trace())
  389. stop_critical_timing(CALLER_ADDR0, caller_addr);
  390. }
  391. EXPORT_SYMBOL(trace_hardirqs_on_caller);
  392. void trace_hardirqs_off_caller(unsigned long caller_addr)
  393. {
  394. if (!preempt_trace() && irq_trace())
  395. start_critical_timing(CALLER_ADDR0, caller_addr);
  396. }
  397. EXPORT_SYMBOL(trace_hardirqs_off_caller);
  398. #endif /* CONFIG_PROVE_LOCKING */
  399. #endif /* CONFIG_IRQSOFF_TRACER */
  400. #ifdef CONFIG_PREEMPT_TRACER
  401. void trace_preempt_on(unsigned long a0, unsigned long a1)
  402. {
  403. if (preempt_trace())
  404. stop_critical_timing(a0, a1);
  405. }
  406. void trace_preempt_off(unsigned long a0, unsigned long a1)
  407. {
  408. if (preempt_trace())
  409. start_critical_timing(a0, a1);
  410. }
  411. #endif /* CONFIG_PREEMPT_TRACER */
  412. static int start_irqsoff_tracer(struct trace_array *tr, int graph)
  413. {
  414. int ret = 0;
  415. if (!graph)
  416. ret = register_ftrace_function(&trace_ops);
  417. else
  418. ret = register_ftrace_graph(&irqsoff_graph_return,
  419. &irqsoff_graph_entry);
  420. if (!ret && tracing_is_enabled())
  421. tracer_enabled = 1;
  422. else
  423. tracer_enabled = 0;
  424. return ret;
  425. }
  426. static void stop_irqsoff_tracer(struct trace_array *tr, int graph)
  427. {
  428. tracer_enabled = 0;
  429. if (!graph)
  430. unregister_ftrace_function(&trace_ops);
  431. else
  432. unregister_ftrace_graph();
  433. }
  434. static void __irqsoff_tracer_init(struct trace_array *tr)
  435. {
  436. save_lat_flag = trace_flags & TRACE_ITER_LATENCY_FMT;
  437. trace_flags |= TRACE_ITER_LATENCY_FMT;
  438. tracing_max_latency = 0;
  439. irqsoff_trace = tr;
  440. /* make sure that the tracer is visible */
  441. smp_wmb();
  442. tracing_reset_online_cpus(tr);
  443. if (start_irqsoff_tracer(tr, is_graph()))
  444. printk(KERN_ERR "failed to start irqsoff tracer\n");
  445. }
  446. static void irqsoff_tracer_reset(struct trace_array *tr)
  447. {
  448. stop_irqsoff_tracer(tr, is_graph());
  449. if (!save_lat_flag)
  450. trace_flags &= ~TRACE_ITER_LATENCY_FMT;
  451. }
  452. static void irqsoff_tracer_start(struct trace_array *tr)
  453. {
  454. tracer_enabled = 1;
  455. }
  456. static void irqsoff_tracer_stop(struct trace_array *tr)
  457. {
  458. tracer_enabled = 0;
  459. }
  460. #ifdef CONFIG_IRQSOFF_TRACER
  461. static int irqsoff_tracer_init(struct trace_array *tr)
  462. {
  463. trace_type = TRACER_IRQS_OFF;
  464. __irqsoff_tracer_init(tr);
  465. return 0;
  466. }
  467. static struct tracer irqsoff_tracer __read_mostly =
  468. {
  469. .name = "irqsoff",
  470. .init = irqsoff_tracer_init,
  471. .reset = irqsoff_tracer_reset,
  472. .start = irqsoff_tracer_start,
  473. .stop = irqsoff_tracer_stop,
  474. .print_max = 1,
  475. .print_header = irqsoff_print_header,
  476. .print_line = irqsoff_print_line,
  477. .flags = &tracer_flags,
  478. .set_flag = irqsoff_set_flag,
  479. #ifdef CONFIG_FTRACE_SELFTEST
  480. .selftest = trace_selftest_startup_irqsoff,
  481. #endif
  482. .open = irqsoff_trace_open,
  483. .close = irqsoff_trace_close,
  484. .use_max_tr = 1,
  485. };
  486. # define register_irqsoff(trace) register_tracer(&trace)
  487. #else
  488. # define register_irqsoff(trace) do { } while (0)
  489. #endif
  490. #ifdef CONFIG_PREEMPT_TRACER
  491. static int preemptoff_tracer_init(struct trace_array *tr)
  492. {
  493. trace_type = TRACER_PREEMPT_OFF;
  494. __irqsoff_tracer_init(tr);
  495. return 0;
  496. }
  497. static struct tracer preemptoff_tracer __read_mostly =
  498. {
  499. .name = "preemptoff",
  500. .init = preemptoff_tracer_init,
  501. .reset = irqsoff_tracer_reset,
  502. .start = irqsoff_tracer_start,
  503. .stop = irqsoff_tracer_stop,
  504. .print_max = 1,
  505. .print_header = irqsoff_print_header,
  506. .print_line = irqsoff_print_line,
  507. .flags = &tracer_flags,
  508. .set_flag = irqsoff_set_flag,
  509. #ifdef CONFIG_FTRACE_SELFTEST
  510. .selftest = trace_selftest_startup_preemptoff,
  511. #endif
  512. .open = irqsoff_trace_open,
  513. .close = irqsoff_trace_close,
  514. .use_max_tr = 1,
  515. };
  516. # define register_preemptoff(trace) register_tracer(&trace)
  517. #else
  518. # define register_preemptoff(trace) do { } while (0)
  519. #endif
  520. #if defined(CONFIG_IRQSOFF_TRACER) && \
  521. defined(CONFIG_PREEMPT_TRACER)
  522. static int preemptirqsoff_tracer_init(struct trace_array *tr)
  523. {
  524. trace_type = TRACER_IRQS_OFF | TRACER_PREEMPT_OFF;
  525. __irqsoff_tracer_init(tr);
  526. return 0;
  527. }
  528. static struct tracer preemptirqsoff_tracer __read_mostly =
  529. {
  530. .name = "preemptirqsoff",
  531. .init = preemptirqsoff_tracer_init,
  532. .reset = irqsoff_tracer_reset,
  533. .start = irqsoff_tracer_start,
  534. .stop = irqsoff_tracer_stop,
  535. .print_max = 1,
  536. .print_header = irqsoff_print_header,
  537. .print_line = irqsoff_print_line,
  538. .flags = &tracer_flags,
  539. .set_flag = irqsoff_set_flag,
  540. #ifdef CONFIG_FTRACE_SELFTEST
  541. .selftest = trace_selftest_startup_preemptirqsoff,
  542. #endif
  543. .open = irqsoff_trace_open,
  544. .close = irqsoff_trace_close,
  545. .use_max_tr = 1,
  546. };
  547. # define register_preemptirqsoff(trace) register_tracer(&trace)
  548. #else
  549. # define register_preemptirqsoff(trace) do { } while (0)
  550. #endif
  551. __init static int init_irqsoff_tracer(void)
  552. {
  553. register_irqsoff(irqsoff_tracer);
  554. register_preemptoff(preemptoff_tracer);
  555. register_preemptirqsoff(preemptirqsoff_tracer);
  556. return 0;
  557. }
  558. device_initcall(init_irqsoff_tracer);