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_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_lat_flag; 36 37 #ifdef CONFIG_PREEMPT_TRACER 38 static inline int 39 preempt_trace(void) 40 { 41 return ((trace_type & TRACER_PREEMPT_OFF) && preempt_count()); 42 } 43 #else 44 # define preempt_trace() (0) 45 #endif 46 47 #ifdef CONFIG_IRQSOFF_TRACER 48 static inline int 49 irq_trace(void) 50 { 51 return ((trace_type & TRACER_IRQS_OFF) && 52 irqs_disabled()); 53 } 54 #else 55 # define irq_trace() (0) 56 #endif 57 58 /* 59 * Sequence count - we record it when starting a measurement and 60 * skip the latency if the sequence has changed - some other section 61 * did a maximum and could disturb our measurement with serial console 62 * printouts, etc. Truly coinciding maximum latencies should be rare 63 * and what happens together happens separately as well, so this doesnt 64 * decrease the validity of the maximum found: 65 */ 66 static __cacheline_aligned_in_smp unsigned long max_sequence; 67 68 #ifdef CONFIG_FUNCTION_TRACER 69 /* 70 * irqsoff uses its own tracer function to keep the overhead down: 71 */ 72 static void 73 irqsoff_tracer_call(unsigned long ip, unsigned long parent_ip) 74 { 75 struct trace_array *tr = irqsoff_trace; 76 struct trace_array_cpu *data; 77 unsigned long flags; 78 long disabled; 79 int cpu; 80 81 /* 82 * Does not matter if we preempt. We test the flags 83 * afterward, to see if irqs are disabled or not. 84 * If we preempt and get a false positive, the flags 85 * test will fail. 86 */ 87 cpu = raw_smp_processor_id(); 88 if (likely(!per_cpu(tracing_cpu, cpu))) 89 return; 90 91 local_save_flags(flags); 92 /* slight chance to get a false positive on tracing_cpu */ 93 if (!irqs_disabled_flags(flags)) 94 return; 95 96 data = tr->data[cpu]; 97 disabled = atomic_inc_return(&data->disabled); 98 99 if (likely(disabled == 1)) 100 trace_function(tr, ip, parent_ip, flags, preempt_count()); 101 102 atomic_dec(&data->disabled); 103 } 104 105 static struct ftrace_ops trace_ops __read_mostly = 106 { 107 .func = irqsoff_tracer_call, 108 }; 109 #endif /* CONFIG_FUNCTION_TRACER */ 110 111 /* 112 * Should this new latency be reported/recorded? 113 */ 114 static int report_latency(cycle_t delta) 115 { 116 if (tracing_thresh) { 117 if (delta < tracing_thresh) 118 return 0; 119 } else { 120 if (delta <= tracing_max_latency) 121 return 0; 122 } 123 return 1; 124 } 125 126 static void 127 check_critical_timing(struct trace_array *tr, 128 struct trace_array_cpu *data, 129 unsigned long parent_ip, 130 int cpu) 131 { 132 cycle_t T0, T1, delta; 133 unsigned long flags; 134 int pc; 135 136 T0 = data->preempt_timestamp; 137 T1 = ftrace_now(cpu); 138 delta = T1-T0; 139 140 local_save_flags(flags); 141 142 pc = preempt_count(); 143 144 if (!report_latency(delta)) 145 goto out; 146 147 spin_lock_irqsave(&max_trace_lock, flags); 148 149 /* check if we are still the max latency */ 150 if (!report_latency(delta)) 151 goto out_unlock; 152 153 trace_function(tr, CALLER_ADDR0, parent_ip, flags, pc); 154 /* Skip 5 functions to get to the irq/preempt enable function */ 155 __trace_stack(tr, flags, 5, pc); 156 157 if (data->critical_sequence != max_sequence) 158 goto out_unlock; 159 160 data->critical_end = parent_ip; 161 162 if (likely(!is_tracing_stopped())) { 163 tracing_max_latency = delta; 164 update_max_tr_single(tr, current, cpu); 165 } 166 167 max_sequence++; 168 169 out_unlock: 170 spin_unlock_irqrestore(&max_trace_lock, flags); 171 172 out: 173 data->critical_sequence = max_sequence; 174 data->preempt_timestamp = ftrace_now(cpu); 175 trace_function(tr, CALLER_ADDR0, parent_ip, flags, pc); 176 } 177 178 static inline void 179 start_critical_timing(unsigned long ip, unsigned long parent_ip) 180 { 181 int cpu; 182 struct trace_array *tr = irqsoff_trace; 183 struct trace_array_cpu *data; 184 unsigned long flags; 185 186 if (likely(!tracer_enabled)) 187 return; 188 189 cpu = raw_smp_processor_id(); 190 191 if (per_cpu(tracing_cpu, cpu)) 192 return; 193 194 data = tr->data[cpu]; 195 196 if (unlikely(!data) || atomic_read(&data->disabled)) 197 return; 198 199 atomic_inc(&data->disabled); 200 201 data->critical_sequence = max_sequence; 202 data->preempt_timestamp = ftrace_now(cpu); 203 data->critical_start = parent_ip ? : ip; 204 205 local_save_flags(flags); 206 207 trace_function(tr, ip, parent_ip, flags, preempt_count()); 208 209 per_cpu(tracing_cpu, cpu) = 1; 210 211 atomic_dec(&data->disabled); 212 } 213 214 static inline void 215 stop_critical_timing(unsigned long ip, unsigned long parent_ip) 216 { 217 int cpu; 218 struct trace_array *tr = irqsoff_trace; 219 struct trace_array_cpu *data; 220 unsigned long flags; 221 222 cpu = raw_smp_processor_id(); 223 /* Always clear the tracing cpu on stopping the trace */ 224 if (unlikely(per_cpu(tracing_cpu, cpu))) 225 per_cpu(tracing_cpu, cpu) = 0; 226 else 227 return; 228 229 if (!tracer_enabled) 230 return; 231 232 data = tr->data[cpu]; 233 234 if (unlikely(!data) || 235 !data->critical_start || atomic_read(&data->disabled)) 236 return; 237 238 atomic_inc(&data->disabled); 239 240 local_save_flags(flags); 241 trace_function(tr, ip, parent_ip, flags, preempt_count()); 242 check_critical_timing(tr, data, parent_ip ? : ip, cpu); 243 data->critical_start = 0; 244 atomic_dec(&data->disabled); 245 } 246 247 /* start and stop critical timings used to for stoppage (in idle) */ 248 void start_critical_timings(void) 249 { 250 if (preempt_trace() || irq_trace()) 251 start_critical_timing(CALLER_ADDR0, CALLER_ADDR1); 252 } 253 EXPORT_SYMBOL_GPL(start_critical_timings); 254 255 void stop_critical_timings(void) 256 { 257 if (preempt_trace() || irq_trace()) 258 stop_critical_timing(CALLER_ADDR0, CALLER_ADDR1); 259 } 260 EXPORT_SYMBOL_GPL(stop_critical_timings); 261 262 #ifdef CONFIG_IRQSOFF_TRACER 263 #ifdef CONFIG_PROVE_LOCKING 264 void time_hardirqs_on(unsigned long a0, unsigned long a1) 265 { 266 if (!preempt_trace() && irq_trace()) 267 stop_critical_timing(a0, a1); 268 } 269 270 void time_hardirqs_off(unsigned long a0, unsigned long a1) 271 { 272 if (!preempt_trace() && irq_trace()) 273 start_critical_timing(a0, a1); 274 } 275 276 #else /* !CONFIG_PROVE_LOCKING */ 277 278 /* 279 * Stubs: 280 */ 281 282 void early_boot_irqs_off(void) 283 { 284 } 285 286 void early_boot_irqs_on(void) 287 { 288 } 289 290 void trace_softirqs_on(unsigned long ip) 291 { 292 } 293 294 void trace_softirqs_off(unsigned long ip) 295 { 296 } 297 298 inline void print_irqtrace_events(struct task_struct *curr) 299 { 300 } 301 302 /* 303 * We are only interested in hardirq on/off events: 304 */ 305 void trace_hardirqs_on(void) 306 { 307 if (!preempt_trace() && irq_trace()) 308 stop_critical_timing(CALLER_ADDR0, CALLER_ADDR1); 309 } 310 EXPORT_SYMBOL(trace_hardirqs_on); 311 312 void trace_hardirqs_off(void) 313 { 314 if (!preempt_trace() && irq_trace()) 315 start_critical_timing(CALLER_ADDR0, CALLER_ADDR1); 316 } 317 EXPORT_SYMBOL(trace_hardirqs_off); 318 319 void trace_hardirqs_on_caller(unsigned long caller_addr) 320 { 321 if (!preempt_trace() && irq_trace()) 322 stop_critical_timing(CALLER_ADDR0, caller_addr); 323 } 324 EXPORT_SYMBOL(trace_hardirqs_on_caller); 325 326 void trace_hardirqs_off_caller(unsigned long caller_addr) 327 { 328 if (!preempt_trace() && irq_trace()) 329 start_critical_timing(CALLER_ADDR0, caller_addr); 330 } 331 EXPORT_SYMBOL(trace_hardirqs_off_caller); 332 333 #endif /* CONFIG_PROVE_LOCKING */ 334 #endif /* CONFIG_IRQSOFF_TRACER */ 335 336 #ifdef CONFIG_PREEMPT_TRACER 337 void trace_preempt_on(unsigned long a0, unsigned long a1) 338 { 339 if (preempt_trace()) 340 stop_critical_timing(a0, a1); 341 } 342 343 void trace_preempt_off(unsigned long a0, unsigned long a1) 344 { 345 if (preempt_trace()) 346 start_critical_timing(a0, a1); 347 } 348 #endif /* CONFIG_PREEMPT_TRACER */ 349 350 static void start_irqsoff_tracer(struct trace_array *tr) 351 { 352 register_ftrace_function(&trace_ops); 353 if (tracing_is_enabled()) 354 tracer_enabled = 1; 355 else 356 tracer_enabled = 0; 357 } 358 359 static void stop_irqsoff_tracer(struct trace_array *tr) 360 { 361 tracer_enabled = 0; 362 unregister_ftrace_function(&trace_ops); 363 } 364 365 static void __irqsoff_tracer_init(struct trace_array *tr) 366 { 367 save_lat_flag = trace_flags & TRACE_ITER_LATENCY_FMT; 368 trace_flags |= TRACE_ITER_LATENCY_FMT; 369 370 tracing_max_latency = 0; 371 irqsoff_trace = tr; 372 /* make sure that the tracer is visible */ 373 smp_wmb(); 374 tracing_reset_online_cpus(tr); 375 start_irqsoff_tracer(tr); 376 } 377 378 static void irqsoff_tracer_reset(struct trace_array *tr) 379 { 380 stop_irqsoff_tracer(tr); 381 382 if (!save_lat_flag) 383 trace_flags &= ~TRACE_ITER_LATENCY_FMT; 384 } 385 386 static void irqsoff_tracer_start(struct trace_array *tr) 387 { 388 tracer_enabled = 1; 389 } 390 391 static void irqsoff_tracer_stop(struct trace_array *tr) 392 { 393 tracer_enabled = 0; 394 } 395 396 #ifdef CONFIG_IRQSOFF_TRACER 397 static int irqsoff_tracer_init(struct trace_array *tr) 398 { 399 trace_type = TRACER_IRQS_OFF; 400 401 __irqsoff_tracer_init(tr); 402 return 0; 403 } 404 static struct tracer irqsoff_tracer __read_mostly = 405 { 406 .name = "irqsoff", 407 .init = irqsoff_tracer_init, 408 .reset = irqsoff_tracer_reset, 409 .start = irqsoff_tracer_start, 410 .stop = irqsoff_tracer_stop, 411 .print_max = 1, 412 #ifdef CONFIG_FTRACE_SELFTEST 413 .selftest = trace_selftest_startup_irqsoff, 414 #endif 415 }; 416 # define register_irqsoff(trace) register_tracer(&trace) 417 #else 418 # define register_irqsoff(trace) do { } while (0) 419 #endif 420 421 #ifdef CONFIG_PREEMPT_TRACER 422 static int preemptoff_tracer_init(struct trace_array *tr) 423 { 424 trace_type = TRACER_PREEMPT_OFF; 425 426 __irqsoff_tracer_init(tr); 427 return 0; 428 } 429 430 static struct tracer preemptoff_tracer __read_mostly = 431 { 432 .name = "preemptoff", 433 .init = preemptoff_tracer_init, 434 .reset = irqsoff_tracer_reset, 435 .start = irqsoff_tracer_start, 436 .stop = irqsoff_tracer_stop, 437 .print_max = 1, 438 #ifdef CONFIG_FTRACE_SELFTEST 439 .selftest = trace_selftest_startup_preemptoff, 440 #endif 441 }; 442 # define register_preemptoff(trace) register_tracer(&trace) 443 #else 444 # define register_preemptoff(trace) do { } while (0) 445 #endif 446 447 #if defined(CONFIG_IRQSOFF_TRACER) && \ 448 defined(CONFIG_PREEMPT_TRACER) 449 450 static int preemptirqsoff_tracer_init(struct trace_array *tr) 451 { 452 trace_type = TRACER_IRQS_OFF | TRACER_PREEMPT_OFF; 453 454 __irqsoff_tracer_init(tr); 455 return 0; 456 } 457 458 static struct tracer preemptirqsoff_tracer __read_mostly = 459 { 460 .name = "preemptirqsoff", 461 .init = preemptirqsoff_tracer_init, 462 .reset = irqsoff_tracer_reset, 463 .start = irqsoff_tracer_start, 464 .stop = irqsoff_tracer_stop, 465 .print_max = 1, 466 #ifdef CONFIG_FTRACE_SELFTEST 467 .selftest = trace_selftest_startup_preemptirqsoff, 468 #endif 469 }; 470 471 # define register_preemptirqsoff(trace) register_tracer(&trace) 472 #else 473 # define register_preemptirqsoff(trace) do { } while (0) 474 #endif 475 476 __init static int init_irqsoff_tracer(void) 477 { 478 register_irqsoff(irqsoff_tracer); 479 register_preemptoff(preemptoff_tracer); 480 register_preemptirqsoff(preemptirqsoff_tracer); 481 482 return 0; 483 } 484 device_initcall(init_irqsoff_tracer); 485