kernel/trace/trace_irqsoff.c

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