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 Nadia Yvette Chambers 11 */ 12#include <linux/kallsyms.h> 13#include <linux/uaccess.h> 14#include <linux/module.h> 15#include <linux/ftrace.h> 16 17#include "trace.h" 18 19static struct trace_array *irqsoff_trace __read_mostly; 20static int tracer_enabled __read_mostly; 21 22static DEFINE_PER_CPU(int, tracing_cpu); 23 24static DEFINE_RAW_SPINLOCK(max_trace_lock); 25 26enum { 27 TRACER_IRQS_OFF = (1 << 1), 28 TRACER_PREEMPT_OFF = (1 << 2), 29}; 30 31static int trace_type __read_mostly; 32 33static int save_flags; 34static bool function_enabled; 35 36static void stop_irqsoff_tracer(struct trace_array *tr, int graph); 37static int start_irqsoff_tracer(struct trace_array *tr, int graph); 38 39#ifdef CONFIG_PREEMPT_TRACER 40static inline int 41preempt_trace(void) 42{ 43 return ((trace_type & TRACER_PREEMPT_OFF) && preempt_count()); 44} 45#else 46# define preempt_trace() (0) 47#endif 48 49#ifdef CONFIG_IRQSOFF_TRACER 50static inline int 51irq_trace(void) 52{ 53 return ((trace_type & TRACER_IRQS_OFF) && 54 irqs_disabled()); 55} 56#else 57# define irq_trace() (0) 58#endif 59 60#define TRACE_DISPLAY_GRAPH 1 61 62static struct tracer_opt trace_opts[] = { 63#ifdef CONFIG_FUNCTION_GRAPH_TRACER 64 /* display latency trace as call graph */ 65 { TRACER_OPT(display-graph, TRACE_DISPLAY_GRAPH) }, 66#endif 67 { } /* Empty entry */ 68}; 69 70static struct tracer_flags tracer_flags = { 71 .val = 0, 72 .opts = trace_opts, 73}; 74 75#define is_graph() (tracer_flags.val & TRACE_DISPLAY_GRAPH) 76 77/* 78 * Sequence count - we record it when starting a measurement and 79 * skip the latency if the sequence has changed - some other section 80 * did a maximum and could disturb our measurement with serial console 81 * printouts, etc. Truly coinciding maximum latencies should be rare 82 * and what happens together happens separately as well, so this doesn't 83 * decrease the validity of the maximum found: 84 */ 85static __cacheline_aligned_in_smp unsigned long max_sequence; 86 87#ifdef CONFIG_FUNCTION_TRACER 88/* 89 * Prologue for the preempt and irqs off function tracers. 90 * 91 * Returns 1 if it is OK to continue, and data->disabled is 92 * incremented. 93 * 0 if the trace is to be ignored, and data->disabled 94 * is kept the same. 95 * 96 * Note, this function is also used outside this ifdef but 97 * inside the #ifdef of the function graph tracer below. 98 * This is OK, since the function graph tracer is 99 * dependent on the function tracer. 100 */ 101static int func_prolog_dec(struct trace_array *tr, 102 struct trace_array_cpu **data, 103 unsigned long *flags) 104{ 105 long disabled; 106 int cpu; 107 108 /* 109 * Does not matter if we preempt. We test the flags 110 * afterward, to see if irqs are disabled or not. 111 * If we preempt and get a false positive, the flags 112 * test will fail. 113 */ 114 cpu = raw_smp_processor_id(); 115 if (likely(!per_cpu(tracing_cpu, cpu))) 116 return 0; 117 118 local_save_flags(*flags); 119 /* slight chance to get a false positive on tracing_cpu */ 120 if (!irqs_disabled_flags(*flags)) 121 return 0; 122 123 *data = per_cpu_ptr(tr->trace_buffer.data, cpu); 124 disabled = atomic_inc_return(&(*data)->disabled); 125 126 if (likely(disabled == 1)) 127 return 1; 128 129 atomic_dec(&(*data)->disabled); 130 131 return 0; 132} 133 134/* 135 * irqsoff uses its own tracer function to keep the overhead down: 136 */ 137static void 138irqsoff_tracer_call(unsigned long ip, unsigned long parent_ip, 139 struct ftrace_ops *op, struct pt_regs *pt_regs) 140{ 141 struct trace_array *tr = irqsoff_trace; 142 struct trace_array_cpu *data; 143 unsigned long flags; 144 145 if (!func_prolog_dec(tr, &data, &flags)) 146 return; 147 148 trace_function(tr, ip, parent_ip, flags, preempt_count()); 149 150 atomic_dec(&data->disabled); 151} 152#endif /* CONFIG_FUNCTION_TRACER */ 153 154#ifdef CONFIG_FUNCTION_GRAPH_TRACER 155static int 156irqsoff_set_flag(struct trace_array *tr, u32 old_flags, u32 bit, int set) 157{ 158 int cpu; 159 160 if (!(bit & TRACE_DISPLAY_GRAPH)) 161 return -EINVAL; 162 163 if (!(is_graph() ^ set)) 164 return 0; 165 166 stop_irqsoff_tracer(irqsoff_trace, !set); 167 168 for_each_possible_cpu(cpu) 169 per_cpu(tracing_cpu, cpu) = 0; 170 171 tr->max_latency = 0; 172 tracing_reset_online_cpus(&irqsoff_trace->trace_buffer); 173 174 return start_irqsoff_tracer(irqsoff_trace, set); 175} 176 177static int irqsoff_graph_entry(struct ftrace_graph_ent *trace) 178{ 179 struct trace_array *tr = irqsoff_trace; 180 struct trace_array_cpu *data; 181 unsigned long flags; 182 int ret; 183 int pc; 184 185 if (!func_prolog_dec(tr, &data, &flags)) 186 return 0; 187 188 pc = preempt_count(); 189 ret = __trace_graph_entry(tr, trace, flags, pc); 190 atomic_dec(&data->disabled); 191 192 return ret; 193} 194 195static void irqsoff_graph_return(struct ftrace_graph_ret *trace) 196{ 197 struct trace_array *tr = irqsoff_trace; 198 struct trace_array_cpu *data; 199 unsigned long flags; 200 int pc; 201 202 if (!func_prolog_dec(tr, &data, &flags)) 203 return; 204 205 pc = preempt_count(); 206 __trace_graph_return(tr, trace, flags, pc); 207 atomic_dec(&data->disabled); 208} 209 210static void irqsoff_trace_open(struct trace_iterator *iter) 211{ 212 if (is_graph()) 213 graph_trace_open(iter); 214 215} 216 217static void irqsoff_trace_close(struct trace_iterator *iter) 218{ 219 if (iter->private) 220 graph_trace_close(iter); 221} 222 223#define GRAPH_TRACER_FLAGS (TRACE_GRAPH_PRINT_CPU | \ 224 TRACE_GRAPH_PRINT_PROC | \ 225 TRACE_GRAPH_PRINT_ABS_TIME | \ 226 TRACE_GRAPH_PRINT_DURATION) 227 228static enum print_line_t irqsoff_print_line(struct trace_iterator *iter) 229{ 230 /* 231 * In graph mode call the graph tracer output function, 232 * otherwise go with the TRACE_FN event handler 233 */ 234 if (is_graph()) 235 return print_graph_function_flags(iter, GRAPH_TRACER_FLAGS); 236 237 return TRACE_TYPE_UNHANDLED; 238} 239 240static void irqsoff_print_header(struct seq_file *s) 241{ 242 if (is_graph()) 243 print_graph_headers_flags(s, GRAPH_TRACER_FLAGS); 244 else 245 trace_default_header(s); 246} 247 248static void 249__trace_function(struct trace_array *tr, 250 unsigned long ip, unsigned long parent_ip, 251 unsigned long flags, int pc) 252{ 253 if (is_graph()) 254 trace_graph_function(tr, ip, parent_ip, flags, pc); 255 else 256 trace_function(tr, ip, parent_ip, flags, pc); 257} 258 259#else 260#define __trace_function trace_function 261 262static int 263irqsoff_set_flag(struct trace_array *tr, u32 old_flags, u32 bit, int set) 264{ 265 return -EINVAL; 266} 267 268static int irqsoff_graph_entry(struct ftrace_graph_ent *trace) 269{ 270 return -1; 271} 272 273static enum print_line_t irqsoff_print_line(struct trace_iterator *iter) 274{ 275 return TRACE_TYPE_UNHANDLED; 276} 277 278static void irqsoff_graph_return(struct ftrace_graph_ret *trace) { } 279static void irqsoff_trace_open(struct trace_iterator *iter) { } 280static void irqsoff_trace_close(struct trace_iterator *iter) { } 281 282#ifdef CONFIG_FUNCTION_TRACER 283static void irqsoff_print_header(struct seq_file *s) 284{ 285 trace_default_header(s); 286} 287#else 288static void irqsoff_print_header(struct seq_file *s) 289{ 290 trace_latency_header(s); 291} 292#endif /* CONFIG_FUNCTION_TRACER */ 293#endif /* CONFIG_FUNCTION_GRAPH_TRACER */ 294 295/* 296 * Should this new latency be reported/recorded? 297 */ 298static int report_latency(struct trace_array *tr, cycle_t delta) 299{ 300 if (tracing_thresh) { 301 if (delta < tracing_thresh) 302 return 0; 303 } else { 304 if (delta <= tr->max_latency) 305 return 0; 306 } 307 return 1; 308} 309 310static void 311check_critical_timing(struct trace_array *tr, 312 struct trace_array_cpu *data, 313 unsigned long parent_ip, 314 int cpu) 315{ 316 cycle_t T0, T1, delta; 317 unsigned long flags; 318 int pc; 319 320 T0 = data->preempt_timestamp; 321 T1 = ftrace_now(cpu); 322 delta = T1-T0; 323 324 local_save_flags(flags); 325 326 pc = preempt_count(); 327 328 if (!report_latency(tr, delta)) 329 goto out; 330 331 raw_spin_lock_irqsave(&max_trace_lock, flags); 332 333 /* check if we are still the max latency */ 334 if (!report_latency(tr, delta)) 335 goto out_unlock; 336 337 __trace_function(tr, CALLER_ADDR0, parent_ip, flags, pc); 338 /* Skip 5 functions to get to the irq/preempt enable function */ 339 __trace_stack(tr, flags, 5, pc); 340 341 if (data->critical_sequence != max_sequence) 342 goto out_unlock; 343 344 data->critical_end = parent_ip; 345 346 if (likely(!is_tracing_stopped())) { 347 tr->max_latency = delta; 348 update_max_tr_single(tr, current, cpu); 349 } 350 351 max_sequence++; 352 353out_unlock: 354 raw_spin_unlock_irqrestore(&max_trace_lock, flags); 355 356out: 357 data->critical_sequence = max_sequence; 358 data->preempt_timestamp = ftrace_now(cpu); 359 __trace_function(tr, CALLER_ADDR0, parent_ip, flags, pc); 360} 361 362static inline void 363start_critical_timing(unsigned long ip, unsigned long parent_ip) 364{ 365 int cpu; 366 struct trace_array *tr = irqsoff_trace; 367 struct trace_array_cpu *data; 368 unsigned long flags; 369 370 if (!tracer_enabled || !tracing_is_enabled()) 371 return; 372 373 cpu = raw_smp_processor_id(); 374 375 if (per_cpu(tracing_cpu, cpu)) 376 return; 377 378 data = per_cpu_ptr(tr->trace_buffer.data, cpu); 379 380 if (unlikely(!data) || atomic_read(&data->disabled)) 381 return; 382 383 atomic_inc(&data->disabled); 384 385 data->critical_sequence = max_sequence; 386 data->preempt_timestamp = ftrace_now(cpu); 387 data->critical_start = parent_ip ? : ip; 388 389 local_save_flags(flags); 390 391 __trace_function(tr, ip, parent_ip, flags, preempt_count()); 392 393 per_cpu(tracing_cpu, cpu) = 1; 394 395 atomic_dec(&data->disabled); 396} 397 398static inline void 399stop_critical_timing(unsigned long ip, unsigned long parent_ip) 400{ 401 int cpu; 402 struct trace_array *tr = irqsoff_trace; 403 struct trace_array_cpu *data; 404 unsigned long flags; 405 406 cpu = raw_smp_processor_id(); 407 /* Always clear the tracing cpu on stopping the trace */ 408 if (unlikely(per_cpu(tracing_cpu, cpu))) 409 per_cpu(tracing_cpu, cpu) = 0; 410 else 411 return; 412 413 if (!tracer_enabled || !tracing_is_enabled()) 414 return; 415 416 data = per_cpu_ptr(tr->trace_buffer.data, cpu); 417 418 if (unlikely(!data) || 419 !data->critical_start || atomic_read(&data->disabled)) 420 return; 421 422 atomic_inc(&data->disabled); 423 424 local_save_flags(flags); 425 __trace_function(tr, ip, parent_ip, flags, preempt_count()); 426 check_critical_timing(tr, data, parent_ip ? : ip, cpu); 427 data->critical_start = 0; 428 atomic_dec(&data->disabled); 429} 430 431/* start and stop critical timings used to for stoppage (in idle) */ 432void start_critical_timings(void) 433{ 434 if (preempt_trace() || irq_trace()) 435 start_critical_timing(CALLER_ADDR0, CALLER_ADDR1); 436} 437EXPORT_SYMBOL_GPL(start_critical_timings); 438 439void stop_critical_timings(void) 440{ 441 if (preempt_trace() || irq_trace()) 442 stop_critical_timing(CALLER_ADDR0, CALLER_ADDR1); 443} 444EXPORT_SYMBOL_GPL(stop_critical_timings); 445 446#ifdef CONFIG_IRQSOFF_TRACER 447#ifdef CONFIG_PROVE_LOCKING 448void time_hardirqs_on(unsigned long a0, unsigned long a1) 449{ 450 if (!preempt_trace() && irq_trace()) 451 stop_critical_timing(a0, a1); 452} 453 454void time_hardirqs_off(unsigned long a0, unsigned long a1) 455{ 456 if (!preempt_trace() && irq_trace()) 457 start_critical_timing(a0, a1); 458} 459 460#else /* !CONFIG_PROVE_LOCKING */ 461 462/* 463 * Stubs: 464 */ 465 466void trace_softirqs_on(unsigned long ip) 467{ 468} 469 470void trace_softirqs_off(unsigned long ip) 471{ 472} 473 474inline void print_irqtrace_events(struct task_struct *curr) 475{ 476} 477 478/* 479 * We are only interested in hardirq on/off events: 480 */ 481void trace_hardirqs_on(void) 482{ 483 if (!preempt_trace() && irq_trace()) 484 stop_critical_timing(CALLER_ADDR0, CALLER_ADDR1); 485} 486EXPORT_SYMBOL(trace_hardirqs_on); 487 488void trace_hardirqs_off(void) 489{ 490 if (!preempt_trace() && irq_trace()) 491 start_critical_timing(CALLER_ADDR0, CALLER_ADDR1); 492} 493EXPORT_SYMBOL(trace_hardirqs_off); 494 495__visible void trace_hardirqs_on_caller(unsigned long caller_addr) 496{ 497 if (!preempt_trace() && irq_trace()) 498 stop_critical_timing(CALLER_ADDR0, caller_addr); 499} 500EXPORT_SYMBOL(trace_hardirqs_on_caller); 501 502__visible void trace_hardirqs_off_caller(unsigned long caller_addr) 503{ 504 if (!preempt_trace() && irq_trace()) 505 start_critical_timing(CALLER_ADDR0, caller_addr); 506} 507EXPORT_SYMBOL(trace_hardirqs_off_caller); 508 509#endif /* CONFIG_PROVE_LOCKING */ 510#endif /* CONFIG_IRQSOFF_TRACER */ 511 512#ifdef CONFIG_PREEMPT_TRACER 513void trace_preempt_on(unsigned long a0, unsigned long a1) 514{ 515 if (preempt_trace() && !irq_trace()) 516 stop_critical_timing(a0, a1); 517} 518 519void trace_preempt_off(unsigned long a0, unsigned long a1) 520{ 521 if (preempt_trace() && !irq_trace()) 522 start_critical_timing(a0, a1); 523} 524#endif /* CONFIG_PREEMPT_TRACER */ 525 526static int register_irqsoff_function(struct trace_array *tr, int graph, int set) 527{ 528 int ret; 529 530 /* 'set' is set if TRACE_ITER_FUNCTION is about to be set */ 531 if (function_enabled || (!set && !(trace_flags & TRACE_ITER_FUNCTION))) 532 return 0; 533 534 if (graph) 535 ret = register_ftrace_graph(&irqsoff_graph_return, 536 &irqsoff_graph_entry); 537 else 538 ret = register_ftrace_function(tr->ops); 539 540 if (!ret) 541 function_enabled = true; 542 543 return ret; 544} 545 546static void unregister_irqsoff_function(struct trace_array *tr, int graph) 547{ 548 if (!function_enabled) 549 return; 550 551 if (graph) 552 unregister_ftrace_graph(); 553 else 554 unregister_ftrace_function(tr->ops); 555 556 function_enabled = false; 557} 558 559static void irqsoff_function_set(struct trace_array *tr, int set) 560{ 561 if (set) 562 register_irqsoff_function(tr, is_graph(), 1); 563 else 564 unregister_irqsoff_function(tr, is_graph()); 565} 566 567static int irqsoff_flag_changed(struct trace_array *tr, u32 mask, int set) 568{ 569 struct tracer *tracer = tr->current_trace; 570 571 if (mask & TRACE_ITER_FUNCTION) 572 irqsoff_function_set(tr, set); 573 574 return trace_keep_overwrite(tracer, mask, set); 575} 576 577static int start_irqsoff_tracer(struct trace_array *tr, int graph) 578{ 579 int ret; 580 581 ret = register_irqsoff_function(tr, graph, 0); 582 583 if (!ret && tracing_is_enabled()) 584 tracer_enabled = 1; 585 else 586 tracer_enabled = 0; 587 588 return ret; 589} 590 591static void stop_irqsoff_tracer(struct trace_array *tr, int graph) 592{ 593 tracer_enabled = 0; 594 595 unregister_irqsoff_function(tr, graph); 596} 597 598static bool irqsoff_busy; 599 600static int __irqsoff_tracer_init(struct trace_array *tr) 601{ 602 if (irqsoff_busy) 603 return -EBUSY; 604 605 save_flags = trace_flags; 606 607 /* non overwrite screws up the latency tracers */ 608 set_tracer_flag(tr, TRACE_ITER_OVERWRITE, 1); 609 set_tracer_flag(tr, TRACE_ITER_LATENCY_FMT, 1); 610 611 tr->max_latency = 0; 612 irqsoff_trace = tr; 613 /* make sure that the tracer is visible */ 614 smp_wmb(); 615 tracing_reset_online_cpus(&tr->trace_buffer); 616 617 ftrace_init_array_ops(tr, irqsoff_tracer_call); 618 619 /* Only toplevel instance supports graph tracing */ 620 if (start_irqsoff_tracer(tr, (tr->flags & TRACE_ARRAY_FL_GLOBAL && 621 is_graph()))) 622 printk(KERN_ERR "failed to start irqsoff tracer\n"); 623 624 irqsoff_busy = true; 625 return 0; 626} 627 628static void irqsoff_tracer_reset(struct trace_array *tr) 629{ 630 int lat_flag = save_flags & TRACE_ITER_LATENCY_FMT; 631 int overwrite_flag = save_flags & TRACE_ITER_OVERWRITE; 632 633 stop_irqsoff_tracer(tr, is_graph()); 634 635 set_tracer_flag(tr, TRACE_ITER_LATENCY_FMT, lat_flag); 636 set_tracer_flag(tr, TRACE_ITER_OVERWRITE, overwrite_flag); 637 ftrace_reset_array_ops(tr); 638 639 irqsoff_busy = false; 640} 641 642static void irqsoff_tracer_start(struct trace_array *tr) 643{ 644 tracer_enabled = 1; 645} 646 647static void irqsoff_tracer_stop(struct trace_array *tr) 648{ 649 tracer_enabled = 0; 650} 651 652#ifdef CONFIG_IRQSOFF_TRACER 653static int irqsoff_tracer_init(struct trace_array *tr) 654{ 655 trace_type = TRACER_IRQS_OFF; 656 657 return __irqsoff_tracer_init(tr); 658} 659static struct tracer irqsoff_tracer __read_mostly = 660{ 661 .name = "irqsoff", 662 .init = irqsoff_tracer_init, 663 .reset = irqsoff_tracer_reset, 664 .start = irqsoff_tracer_start, 665 .stop = irqsoff_tracer_stop, 666 .print_max = true, 667 .print_header = irqsoff_print_header, 668 .print_line = irqsoff_print_line, 669 .flags = &tracer_flags, 670 .set_flag = irqsoff_set_flag, 671 .flag_changed = irqsoff_flag_changed, 672#ifdef CONFIG_FTRACE_SELFTEST 673 .selftest = trace_selftest_startup_irqsoff, 674#endif 675 .open = irqsoff_trace_open, 676 .close = irqsoff_trace_close, 677 .allow_instances = true, 678 .use_max_tr = true, 679}; 680# define register_irqsoff(trace) register_tracer(&trace) 681#else 682# define register_irqsoff(trace) do { } while (0) 683#endif 684 685#ifdef CONFIG_PREEMPT_TRACER 686static int preemptoff_tracer_init(struct trace_array *tr) 687{ 688 trace_type = TRACER_PREEMPT_OFF; 689 690 return __irqsoff_tracer_init(tr); 691} 692 693static struct tracer preemptoff_tracer __read_mostly = 694{ 695 .name = "preemptoff", 696 .init = preemptoff_tracer_init, 697 .reset = irqsoff_tracer_reset, 698 .start = irqsoff_tracer_start, 699 .stop = irqsoff_tracer_stop, 700 .print_max = true, 701 .print_header = irqsoff_print_header, 702 .print_line = irqsoff_print_line, 703 .flags = &tracer_flags, 704 .set_flag = irqsoff_set_flag, 705 .flag_changed = irqsoff_flag_changed, 706#ifdef CONFIG_FTRACE_SELFTEST 707 .selftest = trace_selftest_startup_preemptoff, 708#endif 709 .open = irqsoff_trace_open, 710 .close = irqsoff_trace_close, 711 .allow_instances = true, 712 .use_max_tr = true, 713}; 714# define register_preemptoff(trace) register_tracer(&trace) 715#else 716# define register_preemptoff(trace) do { } while (0) 717#endif 718 719#if defined(CONFIG_IRQSOFF_TRACER) && \ 720 defined(CONFIG_PREEMPT_TRACER) 721 722static int preemptirqsoff_tracer_init(struct trace_array *tr) 723{ 724 trace_type = TRACER_IRQS_OFF | TRACER_PREEMPT_OFF; 725 726 return __irqsoff_tracer_init(tr); 727} 728 729static struct tracer preemptirqsoff_tracer __read_mostly = 730{ 731 .name = "preemptirqsoff", 732 .init = preemptirqsoff_tracer_init, 733 .reset = irqsoff_tracer_reset, 734 .start = irqsoff_tracer_start, 735 .stop = irqsoff_tracer_stop, 736 .print_max = true, 737 .print_header = irqsoff_print_header, 738 .print_line = irqsoff_print_line, 739 .flags = &tracer_flags, 740 .set_flag = irqsoff_set_flag, 741 .flag_changed = irqsoff_flag_changed, 742#ifdef CONFIG_FTRACE_SELFTEST 743 .selftest = trace_selftest_startup_preemptirqsoff, 744#endif 745 .open = irqsoff_trace_open, 746 .close = irqsoff_trace_close, 747 .allow_instances = true, 748 .use_max_tr = true, 749}; 750 751# define register_preemptirqsoff(trace) register_tracer(&trace) 752#else 753# define register_preemptirqsoff(trace) do { } while (0) 754#endif 755 756__init static int init_irqsoff_tracer(void) 757{ 758 register_irqsoff(irqsoff_tracer); 759 register_preemptoff(preemptoff_tracer); 760 register_preemptirqsoff(preemptirqsoff_tracer); 761 762 return 0; 763} 764core_initcall(init_irqsoff_tracer); 765