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