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 164 irqsoff_set_flag(struct trace_array *tr, u32 old_flags, u32 bit, int set) 165 { 166 int cpu; 167 168 if (!(bit & TRACE_DISPLAY_GRAPH)) 169 return -EINVAL; 170 171 if (!(is_graph() ^ set)) 172 return 0; 173 174 stop_irqsoff_tracer(irqsoff_trace, !set); 175 176 for_each_possible_cpu(cpu) 177 per_cpu(tracing_cpu, cpu) = 0; 178 179 tracing_max_latency = 0; 180 tracing_reset_online_cpus(&irqsoff_trace->trace_buffer); 181 182 return start_irqsoff_tracer(irqsoff_trace, set); 183 } 184 185 static int irqsoff_graph_entry(struct ftrace_graph_ent *trace) 186 { 187 struct trace_array *tr = irqsoff_trace; 188 struct trace_array_cpu *data; 189 unsigned long flags; 190 int ret; 191 int pc; 192 193 if (!func_prolog_dec(tr, &data, &flags)) 194 return 0; 195 196 pc = preempt_count(); 197 ret = __trace_graph_entry(tr, trace, flags, pc); 198 atomic_dec(&data->disabled); 199 200 return ret; 201 } 202 203 static void irqsoff_graph_return(struct ftrace_graph_ret *trace) 204 { 205 struct trace_array *tr = irqsoff_trace; 206 struct trace_array_cpu *data; 207 unsigned long flags; 208 int pc; 209 210 if (!func_prolog_dec(tr, &data, &flags)) 211 return; 212 213 pc = preempt_count(); 214 __trace_graph_return(tr, trace, flags, pc); 215 atomic_dec(&data->disabled); 216 } 217 218 static void irqsoff_trace_open(struct trace_iterator *iter) 219 { 220 if (is_graph()) 221 graph_trace_open(iter); 222 223 } 224 225 static void irqsoff_trace_close(struct trace_iterator *iter) 226 { 227 if (iter->private) 228 graph_trace_close(iter); 229 } 230 231 #define GRAPH_TRACER_FLAGS (TRACE_GRAPH_PRINT_CPU | \ 232 TRACE_GRAPH_PRINT_PROC | \ 233 TRACE_GRAPH_PRINT_ABS_TIME | \ 234 TRACE_GRAPH_PRINT_DURATION) 235 236 static enum print_line_t irqsoff_print_line(struct trace_iterator *iter) 237 { 238 /* 239 * In graph mode call the graph tracer output function, 240 * otherwise go with the TRACE_FN event handler 241 */ 242 if (is_graph()) 243 return print_graph_function_flags(iter, GRAPH_TRACER_FLAGS); 244 245 return TRACE_TYPE_UNHANDLED; 246 } 247 248 static void irqsoff_print_header(struct seq_file *s) 249 { 250 if (is_graph()) 251 print_graph_headers_flags(s, GRAPH_TRACER_FLAGS); 252 else 253 trace_default_header(s); 254 } 255 256 static void 257 __trace_function(struct trace_array *tr, 258 unsigned long ip, unsigned long parent_ip, 259 unsigned long flags, int pc) 260 { 261 if (is_graph()) 262 trace_graph_function(tr, ip, parent_ip, flags, pc); 263 else 264 trace_function(tr, ip, parent_ip, flags, pc); 265 } 266 267 #else 268 #define __trace_function trace_function 269 270 static int 271 irqsoff_set_flag(struct trace_array *tr, u32 old_flags, u32 bit, int set) 272 { 273 return -EINVAL; 274 } 275 276 static int irqsoff_graph_entry(struct ftrace_graph_ent *trace) 277 { 278 return -1; 279 } 280 281 static enum print_line_t irqsoff_print_line(struct trace_iterator *iter) 282 { 283 return TRACE_TYPE_UNHANDLED; 284 } 285 286 static void irqsoff_graph_return(struct ftrace_graph_ret *trace) { } 287 static void irqsoff_trace_open(struct trace_iterator *iter) { } 288 static void irqsoff_trace_close(struct trace_iterator *iter) { } 289 290 #ifdef CONFIG_FUNCTION_TRACER 291 static void irqsoff_print_header(struct seq_file *s) 292 { 293 trace_default_header(s); 294 } 295 #else 296 static void irqsoff_print_header(struct seq_file *s) 297 { 298 trace_latency_header(s); 299 } 300 #endif /* CONFIG_FUNCTION_TRACER */ 301 #endif /* CONFIG_FUNCTION_GRAPH_TRACER */ 302 303 /* 304 * Should this new latency be reported/recorded? 305 */ 306 static int report_latency(cycle_t delta) 307 { 308 if (tracing_thresh) { 309 if (delta < tracing_thresh) 310 return 0; 311 } else { 312 if (delta <= tracing_max_latency) 313 return 0; 314 } 315 return 1; 316 } 317 318 static void 319 check_critical_timing(struct trace_array *tr, 320 struct trace_array_cpu *data, 321 unsigned long parent_ip, 322 int cpu) 323 { 324 cycle_t T0, T1, delta; 325 unsigned long flags; 326 int pc; 327 328 T0 = data->preempt_timestamp; 329 T1 = ftrace_now(cpu); 330 delta = T1-T0; 331 332 local_save_flags(flags); 333 334 pc = preempt_count(); 335 336 if (!report_latency(delta)) 337 goto out; 338 339 raw_spin_lock_irqsave(&max_trace_lock, flags); 340 341 /* check if we are still the max latency */ 342 if (!report_latency(delta)) 343 goto out_unlock; 344 345 __trace_function(tr, CALLER_ADDR0, parent_ip, flags, pc); 346 /* Skip 5 functions to get to the irq/preempt enable function */ 347 __trace_stack(tr, flags, 5, pc); 348 349 if (data->critical_sequence != max_sequence) 350 goto out_unlock; 351 352 data->critical_end = parent_ip; 353 354 if (likely(!is_tracing_stopped())) { 355 tracing_max_latency = delta; 356 update_max_tr_single(tr, current, cpu); 357 } 358 359 max_sequence++; 360 361 out_unlock: 362 raw_spin_unlock_irqrestore(&max_trace_lock, flags); 363 364 out: 365 data->critical_sequence = max_sequence; 366 data->preempt_timestamp = ftrace_now(cpu); 367 __trace_function(tr, CALLER_ADDR0, parent_ip, flags, pc); 368 } 369 370 static inline void 371 start_critical_timing(unsigned long ip, unsigned long parent_ip) 372 { 373 int cpu; 374 struct trace_array *tr = irqsoff_trace; 375 struct trace_array_cpu *data; 376 unsigned long flags; 377 378 if (!tracer_enabled || !tracing_is_enabled()) 379 return; 380 381 cpu = raw_smp_processor_id(); 382 383 if (per_cpu(tracing_cpu, cpu)) 384 return; 385 386 data = per_cpu_ptr(tr->trace_buffer.data, cpu); 387 388 if (unlikely(!data) || atomic_read(&data->disabled)) 389 return; 390 391 atomic_inc(&data->disabled); 392 393 data->critical_sequence = max_sequence; 394 data->preempt_timestamp = ftrace_now(cpu); 395 data->critical_start = parent_ip ? : ip; 396 397 local_save_flags(flags); 398 399 __trace_function(tr, ip, parent_ip, flags, preempt_count()); 400 401 per_cpu(tracing_cpu, cpu) = 1; 402 403 atomic_dec(&data->disabled); 404 } 405 406 static inline void 407 stop_critical_timing(unsigned long ip, unsigned long parent_ip) 408 { 409 int cpu; 410 struct trace_array *tr = irqsoff_trace; 411 struct trace_array_cpu *data; 412 unsigned long flags; 413 414 cpu = raw_smp_processor_id(); 415 /* Always clear the tracing cpu on stopping the trace */ 416 if (unlikely(per_cpu(tracing_cpu, cpu))) 417 per_cpu(tracing_cpu, cpu) = 0; 418 else 419 return; 420 421 if (!tracer_enabled || !tracing_is_enabled()) 422 return; 423 424 data = per_cpu_ptr(tr->trace_buffer.data, cpu); 425 426 if (unlikely(!data) || 427 !data->critical_start || atomic_read(&data->disabled)) 428 return; 429 430 atomic_inc(&data->disabled); 431 432 local_save_flags(flags); 433 __trace_function(tr, ip, parent_ip, flags, preempt_count()); 434 check_critical_timing(tr, data, parent_ip ? : ip, cpu); 435 data->critical_start = 0; 436 atomic_dec(&data->disabled); 437 } 438 439 /* start and stop critical timings used to for stoppage (in idle) */ 440 void start_critical_timings(void) 441 { 442 if (preempt_trace() || irq_trace()) 443 start_critical_timing(CALLER_ADDR0, CALLER_ADDR1); 444 } 445 EXPORT_SYMBOL_GPL(start_critical_timings); 446 447 void stop_critical_timings(void) 448 { 449 if (preempt_trace() || irq_trace()) 450 stop_critical_timing(CALLER_ADDR0, CALLER_ADDR1); 451 } 452 EXPORT_SYMBOL_GPL(stop_critical_timings); 453 454 #ifdef CONFIG_IRQSOFF_TRACER 455 #ifdef CONFIG_PROVE_LOCKING 456 void time_hardirqs_on(unsigned long a0, unsigned long a1) 457 { 458 if (!preempt_trace() && irq_trace()) 459 stop_critical_timing(a0, a1); 460 } 461 462 void time_hardirqs_off(unsigned long a0, unsigned long a1) 463 { 464 if (!preempt_trace() && irq_trace()) 465 start_critical_timing(a0, a1); 466 } 467 468 #else /* !CONFIG_PROVE_LOCKING */ 469 470 /* 471 * Stubs: 472 */ 473 474 void trace_softirqs_on(unsigned long ip) 475 { 476 } 477 478 void trace_softirqs_off(unsigned long ip) 479 { 480 } 481 482 inline void print_irqtrace_events(struct task_struct *curr) 483 { 484 } 485 486 /* 487 * We are only interested in hardirq on/off events: 488 */ 489 void trace_hardirqs_on(void) 490 { 491 if (!preempt_trace() && irq_trace()) 492 stop_critical_timing(CALLER_ADDR0, CALLER_ADDR1); 493 } 494 EXPORT_SYMBOL(trace_hardirqs_on); 495 496 void trace_hardirqs_off(void) 497 { 498 if (!preempt_trace() && irq_trace()) 499 start_critical_timing(CALLER_ADDR0, CALLER_ADDR1); 500 } 501 EXPORT_SYMBOL(trace_hardirqs_off); 502 503 __visible void trace_hardirqs_on_caller(unsigned long caller_addr) 504 { 505 if (!preempt_trace() && irq_trace()) 506 stop_critical_timing(CALLER_ADDR0, caller_addr); 507 } 508 EXPORT_SYMBOL(trace_hardirqs_on_caller); 509 510 __visible void trace_hardirqs_off_caller(unsigned long caller_addr) 511 { 512 if (!preempt_trace() && irq_trace()) 513 start_critical_timing(CALLER_ADDR0, caller_addr); 514 } 515 EXPORT_SYMBOL(trace_hardirqs_off_caller); 516 517 #endif /* CONFIG_PROVE_LOCKING */ 518 #endif /* CONFIG_IRQSOFF_TRACER */ 519 520 #ifdef CONFIG_PREEMPT_TRACER 521 void trace_preempt_on(unsigned long a0, unsigned long a1) 522 { 523 if (preempt_trace() && !irq_trace()) 524 stop_critical_timing(a0, a1); 525 } 526 527 void trace_preempt_off(unsigned long a0, unsigned long a1) 528 { 529 if (preempt_trace() && !irq_trace()) 530 start_critical_timing(a0, a1); 531 } 532 #endif /* CONFIG_PREEMPT_TRACER */ 533 534 static int register_irqsoff_function(int graph, int set) 535 { 536 int ret; 537 538 /* 'set' is set if TRACE_ITER_FUNCTION is about to be set */ 539 if (function_enabled || (!set && !(trace_flags & TRACE_ITER_FUNCTION))) 540 return 0; 541 542 if (graph) 543 ret = register_ftrace_graph(&irqsoff_graph_return, 544 &irqsoff_graph_entry); 545 else 546 ret = register_ftrace_function(&trace_ops); 547 548 if (!ret) 549 function_enabled = true; 550 551 return ret; 552 } 553 554 static void unregister_irqsoff_function(int graph) 555 { 556 if (!function_enabled) 557 return; 558 559 if (graph) 560 unregister_ftrace_graph(); 561 else 562 unregister_ftrace_function(&trace_ops); 563 564 function_enabled = false; 565 } 566 567 static void irqsoff_function_set(int set) 568 { 569 if (set) 570 register_irqsoff_function(is_graph(), 1); 571 else 572 unregister_irqsoff_function(is_graph()); 573 } 574 575 static int irqsoff_flag_changed(struct trace_array *tr, u32 mask, int set) 576 { 577 struct tracer *tracer = tr->current_trace; 578 579 if (mask & TRACE_ITER_FUNCTION) 580 irqsoff_function_set(set); 581 582 return trace_keep_overwrite(tracer, mask, set); 583 } 584 585 static int start_irqsoff_tracer(struct trace_array *tr, int graph) 586 { 587 int ret; 588 589 ret = register_irqsoff_function(graph, 0); 590 591 if (!ret && tracing_is_enabled()) 592 tracer_enabled = 1; 593 else 594 tracer_enabled = 0; 595 596 return ret; 597 } 598 599 static void stop_irqsoff_tracer(struct trace_array *tr, int graph) 600 { 601 tracer_enabled = 0; 602 603 unregister_irqsoff_function(graph); 604 } 605 606 static void __irqsoff_tracer_init(struct trace_array *tr) 607 { 608 save_flags = trace_flags; 609 610 /* non overwrite screws up the latency tracers */ 611 set_tracer_flag(tr, TRACE_ITER_OVERWRITE, 1); 612 set_tracer_flag(tr, TRACE_ITER_LATENCY_FMT, 1); 613 614 tracing_max_latency = 0; 615 irqsoff_trace = tr; 616 /* make sure that the tracer is visible */ 617 smp_wmb(); 618 tracing_reset_online_cpus(&tr->trace_buffer); 619 620 if (start_irqsoff_tracer(tr, is_graph())) 621 printk(KERN_ERR "failed to start irqsoff tracer\n"); 622 } 623 624 static void irqsoff_tracer_reset(struct trace_array *tr) 625 { 626 int lat_flag = save_flags & TRACE_ITER_LATENCY_FMT; 627 int overwrite_flag = save_flags & TRACE_ITER_OVERWRITE; 628 629 stop_irqsoff_tracer(tr, is_graph()); 630 631 set_tracer_flag(tr, TRACE_ITER_LATENCY_FMT, lat_flag); 632 set_tracer_flag(tr, TRACE_ITER_OVERWRITE, overwrite_flag); 633 } 634 635 static void irqsoff_tracer_start(struct trace_array *tr) 636 { 637 tracer_enabled = 1; 638 } 639 640 static void irqsoff_tracer_stop(struct trace_array *tr) 641 { 642 tracer_enabled = 0; 643 } 644 645 #ifdef CONFIG_IRQSOFF_TRACER 646 static int irqsoff_tracer_init(struct trace_array *tr) 647 { 648 trace_type = TRACER_IRQS_OFF; 649 650 __irqsoff_tracer_init(tr); 651 return 0; 652 } 653 static struct tracer irqsoff_tracer __read_mostly = 654 { 655 .name = "irqsoff", 656 .init = irqsoff_tracer_init, 657 .reset = irqsoff_tracer_reset, 658 .start = irqsoff_tracer_start, 659 .stop = irqsoff_tracer_stop, 660 .print_max = true, 661 .print_header = irqsoff_print_header, 662 .print_line = irqsoff_print_line, 663 .flags = &tracer_flags, 664 .set_flag = irqsoff_set_flag, 665 .flag_changed = irqsoff_flag_changed, 666 #ifdef CONFIG_FTRACE_SELFTEST 667 .selftest = trace_selftest_startup_irqsoff, 668 #endif 669 .open = irqsoff_trace_open, 670 .close = irqsoff_trace_close, 671 .use_max_tr = true, 672 }; 673 # define register_irqsoff(trace) register_tracer(&trace) 674 #else 675 # define register_irqsoff(trace) do { } while (0) 676 #endif 677 678 #ifdef CONFIG_PREEMPT_TRACER 679 static int preemptoff_tracer_init(struct trace_array *tr) 680 { 681 trace_type = TRACER_PREEMPT_OFF; 682 683 __irqsoff_tracer_init(tr); 684 return 0; 685 } 686 687 static struct tracer preemptoff_tracer __read_mostly = 688 { 689 .name = "preemptoff", 690 .init = preemptoff_tracer_init, 691 .reset = irqsoff_tracer_reset, 692 .start = irqsoff_tracer_start, 693 .stop = irqsoff_tracer_stop, 694 .print_max = true, 695 .print_header = irqsoff_print_header, 696 .print_line = irqsoff_print_line, 697 .flags = &tracer_flags, 698 .set_flag = irqsoff_set_flag, 699 .flag_changed = irqsoff_flag_changed, 700 #ifdef CONFIG_FTRACE_SELFTEST 701 .selftest = trace_selftest_startup_preemptoff, 702 #endif 703 .open = irqsoff_trace_open, 704 .close = irqsoff_trace_close, 705 .use_max_tr = true, 706 }; 707 # define register_preemptoff(trace) register_tracer(&trace) 708 #else 709 # define register_preemptoff(trace) do { } while (0) 710 #endif 711 712 #if defined(CONFIG_IRQSOFF_TRACER) && \ 713 defined(CONFIG_PREEMPT_TRACER) 714 715 static int preemptirqsoff_tracer_init(struct trace_array *tr) 716 { 717 trace_type = TRACER_IRQS_OFF | TRACER_PREEMPT_OFF; 718 719 __irqsoff_tracer_init(tr); 720 return 0; 721 } 722 723 static struct tracer preemptirqsoff_tracer __read_mostly = 724 { 725 .name = "preemptirqsoff", 726 .init = preemptirqsoff_tracer_init, 727 .reset = irqsoff_tracer_reset, 728 .start = irqsoff_tracer_start, 729 .stop = irqsoff_tracer_stop, 730 .print_max = true, 731 .print_header = irqsoff_print_header, 732 .print_line = irqsoff_print_line, 733 .flags = &tracer_flags, 734 .set_flag = irqsoff_set_flag, 735 .flag_changed = irqsoff_flag_changed, 736 #ifdef CONFIG_FTRACE_SELFTEST 737 .selftest = trace_selftest_startup_preemptirqsoff, 738 #endif 739 .open = irqsoff_trace_open, 740 .close = irqsoff_trace_close, 741 .use_max_tr = true, 742 }; 743 744 # define register_preemptirqsoff(trace) register_tracer(&trace) 745 #else 746 # define register_preemptirqsoff(trace) do { } while (0) 747 #endif 748 749 __init static int init_irqsoff_tracer(void) 750 { 751 register_irqsoff(irqsoff_tracer); 752 register_preemptoff(preemptoff_tracer); 753 register_preemptirqsoff(preemptirqsoff_tracer); 754 755 return 0; 756 } 757 core_initcall(init_irqsoff_tracer); 758