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