trace_irqsoff.c 15 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290291292293294295296297298299300301302303304305306307308309310311312313314315316317318319320321322323324325326327328329330331332333334335336337338339340341342343344345346347348349350351352353354355356357358359360361362363364365366367368369370371372373374375376377378379380381382383384385386387388389390391392393394395396397398399400401402403404405406407408409410411412413414415416417418419420421422423424425426427428429430431432433434435436437438439440441442443444445446447448449450451452453454455456457458459460461462463464465466467468469470471472473474475476477478479480481482483484485486487488489490491492493494495496497498499500501502503504505506507508509510511512513514515516517518519520521522523524525526527528529530531532533534535536537538539540541542543544545546547548549550551552553554555556557558559560561562563564565566567568569570571572573574575576577578579580581582583584585586587588589590591592593594595596597598599600601602603604605606607608609610611612613614615616617618619620621622623624625626627628629630631632633634635636637638639640641642643644645646647648649650651652653654655656657658659660661662663664665666667668669670671672673674675676677678679680681682683684685686
  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 doesnt
  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. };
  130. #endif /* CONFIG_FUNCTION_TRACER */
  131. #ifdef CONFIG_FUNCTION_GRAPH_TRACER
  132. static int irqsoff_set_flag(u32 old_flags, u32 bit, int set)
  133. {
  134. int cpu;
  135. if (!(bit & TRACE_DISPLAY_GRAPH))
  136. return -EINVAL;
  137. if (!(is_graph() ^ set))
  138. return 0;
  139. stop_irqsoff_tracer(irqsoff_trace, !set);
  140. for_each_possible_cpu(cpu)
  141. per_cpu(tracing_cpu, cpu) = 0;
  142. tracing_max_latency = 0;
  143. tracing_reset_online_cpus(irqsoff_trace);
  144. return start_irqsoff_tracer(irqsoff_trace, set);
  145. }
  146. static int irqsoff_graph_entry(struct ftrace_graph_ent *trace)
  147. {
  148. struct trace_array *tr = irqsoff_trace;
  149. struct trace_array_cpu *data;
  150. unsigned long flags;
  151. int ret;
  152. int pc;
  153. if (!func_prolog_dec(tr, &data, &flags))
  154. return 0;
  155. pc = preempt_count();
  156. ret = __trace_graph_entry(tr, trace, flags, pc);
  157. atomic_dec(&data->disabled);
  158. return ret;
  159. }
  160. static void irqsoff_graph_return(struct ftrace_graph_ret *trace)
  161. {
  162. struct trace_array *tr = irqsoff_trace;
  163. struct trace_array_cpu *data;
  164. unsigned long flags;
  165. int pc;
  166. if (!func_prolog_dec(tr, &data, &flags))
  167. return;
  168. pc = preempt_count();
  169. __trace_graph_return(tr, trace, flags, pc);
  170. atomic_dec(&data->disabled);
  171. }
  172. static void irqsoff_trace_open(struct trace_iterator *iter)
  173. {
  174. if (is_graph())
  175. graph_trace_open(iter);
  176. }
  177. static void irqsoff_trace_close(struct trace_iterator *iter)
  178. {
  179. if (iter->private)
  180. graph_trace_close(iter);
  181. }
  182. #define GRAPH_TRACER_FLAGS (TRACE_GRAPH_PRINT_CPU | \
  183. TRACE_GRAPH_PRINT_PROC)
  184. static enum print_line_t irqsoff_print_line(struct trace_iterator *iter)
  185. {
  186. /*
  187. * In graph mode call the graph tracer output function,
  188. * otherwise go with the TRACE_FN event handler
  189. */
  190. if (is_graph())
  191. return print_graph_function_flags(iter, GRAPH_TRACER_FLAGS);
  192. return TRACE_TYPE_UNHANDLED;
  193. }
  194. static void irqsoff_print_header(struct seq_file *s)
  195. {
  196. if (is_graph())
  197. print_graph_headers_flags(s, GRAPH_TRACER_FLAGS);
  198. else
  199. trace_default_header(s);
  200. }
  201. static void
  202. __trace_function(struct trace_array *tr,
  203. unsigned long ip, unsigned long parent_ip,
  204. unsigned long flags, int pc)
  205. {
  206. if (is_graph())
  207. trace_graph_function(tr, ip, parent_ip, flags, pc);
  208. else
  209. trace_function(tr, ip, parent_ip, flags, pc);
  210. }
  211. #else
  212. #define __trace_function trace_function
  213. static int irqsoff_set_flag(u32 old_flags, u32 bit, int set)
  214. {
  215. return -EINVAL;
  216. }
  217. static int irqsoff_graph_entry(struct ftrace_graph_ent *trace)
  218. {
  219. return -1;
  220. }
  221. static enum print_line_t irqsoff_print_line(struct trace_iterator *iter)
  222. {
  223. return TRACE_TYPE_UNHANDLED;
  224. }
  225. static void irqsoff_graph_return(struct ftrace_graph_ret *trace) { }
  226. static void irqsoff_print_header(struct seq_file *s) { }
  227. static void irqsoff_trace_open(struct trace_iterator *iter) { }
  228. static void irqsoff_trace_close(struct trace_iterator *iter) { }
  229. #endif /* CONFIG_FUNCTION_GRAPH_TRACER */
  230. /*
  231. * Should this new latency be reported/recorded?
  232. */
  233. static int report_latency(cycle_t delta)
  234. {
  235. if (tracing_thresh) {
  236. if (delta < tracing_thresh)
  237. return 0;
  238. } else {
  239. if (delta <= tracing_max_latency)
  240. return 0;
  241. }
  242. return 1;
  243. }
  244. static void
  245. check_critical_timing(struct trace_array *tr,
  246. struct trace_array_cpu *data,
  247. unsigned long parent_ip,
  248. int cpu)
  249. {
  250. cycle_t T0, T1, delta;
  251. unsigned long flags;
  252. int pc;
  253. T0 = data->preempt_timestamp;
  254. T1 = ftrace_now(cpu);
  255. delta = T1-T0;
  256. local_save_flags(flags);
  257. pc = preempt_count();
  258. if (!report_latency(delta))
  259. goto out;
  260. spin_lock_irqsave(&max_trace_lock, flags);
  261. /* check if we are still the max latency */
  262. if (!report_latency(delta))
  263. goto out_unlock;
  264. __trace_function(tr, CALLER_ADDR0, parent_ip, flags, pc);
  265. /* Skip 5 functions to get to the irq/preempt enable function */
  266. __trace_stack(tr, flags, 5, pc);
  267. if (data->critical_sequence != max_sequence)
  268. goto out_unlock;
  269. data->critical_end = parent_ip;
  270. if (likely(!is_tracing_stopped())) {
  271. tracing_max_latency = delta;
  272. update_max_tr_single(tr, current, cpu);
  273. }
  274. max_sequence++;
  275. out_unlock:
  276. spin_unlock_irqrestore(&max_trace_lock, flags);
  277. out:
  278. data->critical_sequence = max_sequence;
  279. data->preempt_timestamp = ftrace_now(cpu);
  280. __trace_function(tr, CALLER_ADDR0, parent_ip, flags, pc);
  281. }
  282. static inline void
  283. start_critical_timing(unsigned long ip, unsigned long parent_ip)
  284. {
  285. int cpu;
  286. struct trace_array *tr = irqsoff_trace;
  287. struct trace_array_cpu *data;
  288. unsigned long flags;
  289. if (likely(!tracer_enabled))
  290. return;
  291. cpu = raw_smp_processor_id();
  292. if (per_cpu(tracing_cpu, cpu))
  293. return;
  294. data = tr->data[cpu];
  295. if (unlikely(!data) || atomic_read(&data->disabled))
  296. return;
  297. atomic_inc(&data->disabled);
  298. data->critical_sequence = max_sequence;
  299. data->preempt_timestamp = ftrace_now(cpu);
  300. data->critical_start = parent_ip ? : ip;
  301. local_save_flags(flags);
  302. __trace_function(tr, ip, parent_ip, flags, preempt_count());
  303. per_cpu(tracing_cpu, cpu) = 1;
  304. atomic_dec(&data->disabled);
  305. }
  306. static inline void
  307. stop_critical_timing(unsigned long ip, unsigned long parent_ip)
  308. {
  309. int cpu;
  310. struct trace_array *tr = irqsoff_trace;
  311. struct trace_array_cpu *data;
  312. unsigned long flags;
  313. cpu = raw_smp_processor_id();
  314. /* Always clear the tracing cpu on stopping the trace */
  315. if (unlikely(per_cpu(tracing_cpu, cpu)))
  316. per_cpu(tracing_cpu, cpu) = 0;
  317. else
  318. return;
  319. if (!tracer_enabled)
  320. return;
  321. data = tr->data[cpu];
  322. if (unlikely(!data) ||
  323. !data->critical_start || atomic_read(&data->disabled))
  324. return;
  325. atomic_inc(&data->disabled);
  326. local_save_flags(flags);
  327. __trace_function(tr, ip, parent_ip, flags, preempt_count());
  328. check_critical_timing(tr, data, parent_ip ? : ip, cpu);
  329. data->critical_start = 0;
  330. atomic_dec(&data->disabled);
  331. }
  332. /* start and stop critical timings used to for stoppage (in idle) */
  333. void start_critical_timings(void)
  334. {
  335. if (preempt_trace() || irq_trace())
  336. start_critical_timing(CALLER_ADDR0, CALLER_ADDR1);
  337. }
  338. EXPORT_SYMBOL_GPL(start_critical_timings);
  339. void stop_critical_timings(void)
  340. {
  341. if (preempt_trace() || irq_trace())
  342. stop_critical_timing(CALLER_ADDR0, CALLER_ADDR1);
  343. }
  344. EXPORT_SYMBOL_GPL(stop_critical_timings);
  345. #ifdef CONFIG_IRQSOFF_TRACER
  346. #ifdef CONFIG_PROVE_LOCKING
  347. void time_hardirqs_on(unsigned long a0, unsigned long a1)
  348. {
  349. if (!preempt_trace() && irq_trace())
  350. stop_critical_timing(a0, a1);
  351. }
  352. void time_hardirqs_off(unsigned long a0, unsigned long a1)
  353. {
  354. if (!preempt_trace() && irq_trace())
  355. start_critical_timing(a0, a1);
  356. }
  357. #else /* !CONFIG_PROVE_LOCKING */
  358. /*
  359. * Stubs:
  360. */
  361. void trace_softirqs_on(unsigned long ip)
  362. {
  363. }
  364. void trace_softirqs_off(unsigned long ip)
  365. {
  366. }
  367. inline void print_irqtrace_events(struct task_struct *curr)
  368. {
  369. }
  370. /*
  371. * We are only interested in hardirq on/off events:
  372. */
  373. void trace_hardirqs_on(void)
  374. {
  375. if (!preempt_trace() && irq_trace())
  376. stop_critical_timing(CALLER_ADDR0, CALLER_ADDR1);
  377. }
  378. EXPORT_SYMBOL(trace_hardirqs_on);
  379. void trace_hardirqs_off(void)
  380. {
  381. if (!preempt_trace() && irq_trace())
  382. start_critical_timing(CALLER_ADDR0, CALLER_ADDR1);
  383. }
  384. EXPORT_SYMBOL(trace_hardirqs_off);
  385. void trace_hardirqs_on_caller(unsigned long caller_addr)
  386. {
  387. if (!preempt_trace() && irq_trace())
  388. stop_critical_timing(CALLER_ADDR0, caller_addr);
  389. }
  390. EXPORT_SYMBOL(trace_hardirqs_on_caller);
  391. void trace_hardirqs_off_caller(unsigned long caller_addr)
  392. {
  393. if (!preempt_trace() && irq_trace())
  394. start_critical_timing(CALLER_ADDR0, caller_addr);
  395. }
  396. EXPORT_SYMBOL(trace_hardirqs_off_caller);
  397. #endif /* CONFIG_PROVE_LOCKING */
  398. #endif /* CONFIG_IRQSOFF_TRACER */
  399. #ifdef CONFIG_PREEMPT_TRACER
  400. void trace_preempt_on(unsigned long a0, unsigned long a1)
  401. {
  402. if (preempt_trace())
  403. stop_critical_timing(a0, a1);
  404. }
  405. void trace_preempt_off(unsigned long a0, unsigned long a1)
  406. {
  407. if (preempt_trace())
  408. start_critical_timing(a0, a1);
  409. }
  410. #endif /* CONFIG_PREEMPT_TRACER */
  411. static int start_irqsoff_tracer(struct trace_array *tr, int graph)
  412. {
  413. int ret = 0;
  414. if (!graph)
  415. ret = register_ftrace_function(&trace_ops);
  416. else
  417. ret = register_ftrace_graph(&irqsoff_graph_return,
  418. &irqsoff_graph_entry);
  419. if (!ret && tracing_is_enabled())
  420. tracer_enabled = 1;
  421. else
  422. tracer_enabled = 0;
  423. return ret;
  424. }
  425. static void stop_irqsoff_tracer(struct trace_array *tr, int graph)
  426. {
  427. tracer_enabled = 0;
  428. if (!graph)
  429. unregister_ftrace_function(&trace_ops);
  430. else
  431. unregister_ftrace_graph();
  432. }
  433. static void __irqsoff_tracer_init(struct trace_array *tr)
  434. {
  435. save_lat_flag = trace_flags & TRACE_ITER_LATENCY_FMT;
  436. trace_flags |= TRACE_ITER_LATENCY_FMT;
  437. tracing_max_latency = 0;
  438. irqsoff_trace = tr;
  439. /* make sure that the tracer is visible */
  440. smp_wmb();
  441. tracing_reset_online_cpus(tr);
  442. if (start_irqsoff_tracer(tr, is_graph()))
  443. printk(KERN_ERR "failed to start irqsoff tracer\n");
  444. }
  445. static void irqsoff_tracer_reset(struct trace_array *tr)
  446. {
  447. stop_irqsoff_tracer(tr, is_graph());
  448. if (!save_lat_flag)
  449. trace_flags &= ~TRACE_ITER_LATENCY_FMT;
  450. }
  451. static void irqsoff_tracer_start(struct trace_array *tr)
  452. {
  453. tracer_enabled = 1;
  454. }
  455. static void irqsoff_tracer_stop(struct trace_array *tr)
  456. {
  457. tracer_enabled = 0;
  458. }
  459. #ifdef CONFIG_IRQSOFF_TRACER
  460. static int irqsoff_tracer_init(struct trace_array *tr)
  461. {
  462. trace_type = TRACER_IRQS_OFF;
  463. __irqsoff_tracer_init(tr);
  464. return 0;
  465. }
  466. static struct tracer irqsoff_tracer __read_mostly =
  467. {
  468. .name = "irqsoff",
  469. .init = irqsoff_tracer_init,
  470. .reset = irqsoff_tracer_reset,
  471. .start = irqsoff_tracer_start,
  472. .stop = irqsoff_tracer_stop,
  473. .print_max = 1,
  474. .print_header = irqsoff_print_header,
  475. .print_line = irqsoff_print_line,
  476. .flags = &tracer_flags,
  477. .set_flag = irqsoff_set_flag,
  478. #ifdef CONFIG_FTRACE_SELFTEST
  479. .selftest = trace_selftest_startup_irqsoff,
  480. #endif
  481. .open = irqsoff_trace_open,
  482. .close = irqsoff_trace_close,
  483. .use_max_tr = 1,
  484. };
  485. # define register_irqsoff(trace) register_tracer(&trace)
  486. #else
  487. # define register_irqsoff(trace) do { } while (0)
  488. #endif
  489. #ifdef CONFIG_PREEMPT_TRACER
  490. static int preemptoff_tracer_init(struct trace_array *tr)
  491. {
  492. trace_type = TRACER_PREEMPT_OFF;
  493. __irqsoff_tracer_init(tr);
  494. return 0;
  495. }
  496. static struct tracer preemptoff_tracer __read_mostly =
  497. {
  498. .name = "preemptoff",
  499. .init = preemptoff_tracer_init,
  500. .reset = irqsoff_tracer_reset,
  501. .start = irqsoff_tracer_start,
  502. .stop = irqsoff_tracer_stop,
  503. .print_max = 1,
  504. .print_header = irqsoff_print_header,
  505. .print_line = irqsoff_print_line,
  506. .flags = &tracer_flags,
  507. .set_flag = irqsoff_set_flag,
  508. #ifdef CONFIG_FTRACE_SELFTEST
  509. .selftest = trace_selftest_startup_preemptoff,
  510. #endif
  511. .open = irqsoff_trace_open,
  512. .close = irqsoff_trace_close,
  513. .use_max_tr = 1,
  514. };
  515. # define register_preemptoff(trace) register_tracer(&trace)
  516. #else
  517. # define register_preemptoff(trace) do { } while (0)
  518. #endif
  519. #if defined(CONFIG_IRQSOFF_TRACER) && \
  520. defined(CONFIG_PREEMPT_TRACER)
  521. static int preemptirqsoff_tracer_init(struct trace_array *tr)
  522. {
  523. trace_type = TRACER_IRQS_OFF | TRACER_PREEMPT_OFF;
  524. __irqsoff_tracer_init(tr);
  525. return 0;
  526. }
  527. static struct tracer preemptirqsoff_tracer __read_mostly =
  528. {
  529. .name = "preemptirqsoff",
  530. .init = preemptirqsoff_tracer_init,
  531. .reset = irqsoff_tracer_reset,
  532. .start = irqsoff_tracer_start,
  533. .stop = irqsoff_tracer_stop,
  534. .print_max = 1,
  535. .print_header = irqsoff_print_header,
  536. .print_line = irqsoff_print_line,
  537. .flags = &tracer_flags,
  538. .set_flag = irqsoff_set_flag,
  539. #ifdef CONFIG_FTRACE_SELFTEST
  540. .selftest = trace_selftest_startup_preemptirqsoff,
  541. #endif
  542. .open = irqsoff_trace_open,
  543. .close = irqsoff_trace_close,
  544. .use_max_tr = 1,
  545. };
  546. # define register_preemptirqsoff(trace) register_tracer(&trace)
  547. #else
  548. # define register_preemptirqsoff(trace) do { } while (0)
  549. #endif
  550. __init static int init_irqsoff_tracer(void)
  551. {
  552. register_irqsoff(irqsoff_tracer);
  553. register_preemptoff(preemptoff_tracer);
  554. register_preemptirqsoff(preemptirqsoff_tracer);
  555. return 0;
  556. }
  557. device_initcall(init_irqsoff_tracer);