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 unsigned long latency, t0, t1; 133 cycle_t T0, T1, delta; 134 unsigned long flags; 135 int pc; 136 137 /* 138 * usecs conversion is slow so we try to delay the conversion 139 * as long as possible: 140 */ 141 T0 = data->preempt_timestamp; 142 T1 = ftrace_now(cpu); 143 delta = T1-T0; 144 145 local_save_flags(flags); 146 147 pc = preempt_count(); 148 149 if (!report_latency(delta)) 150 goto out; 151 152 spin_lock_irqsave(&max_trace_lock, flags); 153 154 /* check if we are still the max latency */ 155 if (!report_latency(delta)) 156 goto out_unlock; 157 158 trace_function(tr, CALLER_ADDR0, parent_ip, flags, pc); 159 160 latency = nsecs_to_usecs(delta); 161 162 if (data->critical_sequence != max_sequence) 163 goto out_unlock; 164 165 tracing_max_latency = delta; 166 t0 = nsecs_to_usecs(T0); 167 t1 = nsecs_to_usecs(T1); 168 169 data->critical_end = parent_ip; 170 171 update_max_tr_single(tr, current, cpu); 172 173 max_sequence++; 174 175 out_unlock: 176 spin_unlock_irqrestore(&max_trace_lock, flags); 177 178 out: 179 data->critical_sequence = max_sequence; 180 data->preempt_timestamp = ftrace_now(cpu); 181 tracing_reset(tr, cpu); 182 trace_function(tr, CALLER_ADDR0, parent_ip, flags, pc); 183 } 184 185 static inline void 186 start_critical_timing(unsigned long ip, unsigned long parent_ip) 187 { 188 int cpu; 189 struct trace_array *tr = irqsoff_trace; 190 struct trace_array_cpu *data; 191 unsigned long flags; 192 193 if (likely(!tracer_enabled)) 194 return; 195 196 cpu = raw_smp_processor_id(); 197 198 if (per_cpu(tracing_cpu, cpu)) 199 return; 200 201 data = tr->data[cpu]; 202 203 if (unlikely(!data) || atomic_read(&data->disabled)) 204 return; 205 206 atomic_inc(&data->disabled); 207 208 data->critical_sequence = max_sequence; 209 data->preempt_timestamp = ftrace_now(cpu); 210 data->critical_start = parent_ip ? : ip; 211 tracing_reset(tr, cpu); 212 213 local_save_flags(flags); 214 215 trace_function(tr, ip, parent_ip, flags, preempt_count()); 216 217 per_cpu(tracing_cpu, cpu) = 1; 218 219 atomic_dec(&data->disabled); 220 } 221 222 static inline void 223 stop_critical_timing(unsigned long ip, unsigned long parent_ip) 224 { 225 int cpu; 226 struct trace_array *tr = irqsoff_trace; 227 struct trace_array_cpu *data; 228 unsigned long flags; 229 230 cpu = raw_smp_processor_id(); 231 /* Always clear the tracing cpu on stopping the trace */ 232 if (unlikely(per_cpu(tracing_cpu, cpu))) 233 per_cpu(tracing_cpu, cpu) = 0; 234 else 235 return; 236 237 if (!tracer_enabled) 238 return; 239 240 data = tr->data[cpu]; 241 242 if (unlikely(!data) || 243 !data->critical_start || atomic_read(&data->disabled)) 244 return; 245 246 atomic_inc(&data->disabled); 247 248 local_save_flags(flags); 249 trace_function(tr, ip, parent_ip, flags, preempt_count()); 250 check_critical_timing(tr, data, parent_ip ? : ip, cpu); 251 data->critical_start = 0; 252 atomic_dec(&data->disabled); 253 } 254 255 /* start and stop critical timings used to for stoppage (in idle) */ 256 void start_critical_timings(void) 257 { 258 if (preempt_trace() || irq_trace()) 259 start_critical_timing(CALLER_ADDR0, CALLER_ADDR1); 260 } 261 EXPORT_SYMBOL_GPL(start_critical_timings); 262 263 void stop_critical_timings(void) 264 { 265 if (preempt_trace() || irq_trace()) 266 stop_critical_timing(CALLER_ADDR0, CALLER_ADDR1); 267 } 268 EXPORT_SYMBOL_GPL(stop_critical_timings); 269 270 #ifdef CONFIG_IRQSOFF_TRACER 271 #ifdef CONFIG_PROVE_LOCKING 272 void time_hardirqs_on(unsigned long a0, unsigned long a1) 273 { 274 if (!preempt_trace() && irq_trace()) 275 stop_critical_timing(a0, a1); 276 } 277 278 void time_hardirqs_off(unsigned long a0, unsigned long a1) 279 { 280 if (!preempt_trace() && irq_trace()) 281 start_critical_timing(a0, a1); 282 } 283 284 #else /* !CONFIG_PROVE_LOCKING */ 285 286 /* 287 * Stubs: 288 */ 289 290 void early_boot_irqs_off(void) 291 { 292 } 293 294 void early_boot_irqs_on(void) 295 { 296 } 297 298 void trace_softirqs_on(unsigned long ip) 299 { 300 } 301 302 void trace_softirqs_off(unsigned long ip) 303 { 304 } 305 306 inline void print_irqtrace_events(struct task_struct *curr) 307 { 308 } 309 310 /* 311 * We are only interested in hardirq on/off events: 312 */ 313 void trace_hardirqs_on(void) 314 { 315 if (!preempt_trace() && irq_trace()) 316 stop_critical_timing(CALLER_ADDR0, CALLER_ADDR1); 317 } 318 EXPORT_SYMBOL(trace_hardirqs_on); 319 320 void trace_hardirqs_off(void) 321 { 322 if (!preempt_trace() && irq_trace()) 323 start_critical_timing(CALLER_ADDR0, CALLER_ADDR1); 324 } 325 EXPORT_SYMBOL(trace_hardirqs_off); 326 327 void trace_hardirqs_on_caller(unsigned long caller_addr) 328 { 329 if (!preempt_trace() && irq_trace()) 330 stop_critical_timing(CALLER_ADDR0, caller_addr); 331 } 332 EXPORT_SYMBOL(trace_hardirqs_on_caller); 333 334 void trace_hardirqs_off_caller(unsigned long caller_addr) 335 { 336 if (!preempt_trace() && irq_trace()) 337 start_critical_timing(CALLER_ADDR0, caller_addr); 338 } 339 EXPORT_SYMBOL(trace_hardirqs_off_caller); 340 341 #endif /* CONFIG_PROVE_LOCKING */ 342 #endif /* CONFIG_IRQSOFF_TRACER */ 343 344 #ifdef CONFIG_PREEMPT_TRACER 345 void trace_preempt_on(unsigned long a0, unsigned long a1) 346 { 347 if (preempt_trace()) 348 stop_critical_timing(a0, a1); 349 } 350 351 void trace_preempt_off(unsigned long a0, unsigned long a1) 352 { 353 if (preempt_trace()) 354 start_critical_timing(a0, a1); 355 } 356 #endif /* CONFIG_PREEMPT_TRACER */ 357 358 static void start_irqsoff_tracer(struct trace_array *tr) 359 { 360 register_ftrace_function(&trace_ops); 361 if (tracing_is_enabled()) 362 tracer_enabled = 1; 363 else 364 tracer_enabled = 0; 365 } 366 367 static void stop_irqsoff_tracer(struct trace_array *tr) 368 { 369 tracer_enabled = 0; 370 unregister_ftrace_function(&trace_ops); 371 } 372 373 static void __irqsoff_tracer_init(struct trace_array *tr) 374 { 375 save_lat_flag = trace_flags & TRACE_ITER_LATENCY_FMT; 376 trace_flags |= TRACE_ITER_LATENCY_FMT; 377 378 tracing_max_latency = 0; 379 irqsoff_trace = tr; 380 /* make sure that the tracer is visible */ 381 smp_wmb(); 382 start_irqsoff_tracer(tr); 383 } 384 385 static void irqsoff_tracer_reset(struct trace_array *tr) 386 { 387 stop_irqsoff_tracer(tr); 388 389 if (!save_lat_flag) 390 trace_flags &= ~TRACE_ITER_LATENCY_FMT; 391 } 392 393 static void irqsoff_tracer_start(struct trace_array *tr) 394 { 395 tracer_enabled = 1; 396 } 397 398 static void irqsoff_tracer_stop(struct trace_array *tr) 399 { 400 tracer_enabled = 0; 401 } 402 403 #ifdef CONFIG_IRQSOFF_TRACER 404 static int irqsoff_tracer_init(struct trace_array *tr) 405 { 406 trace_type = TRACER_IRQS_OFF; 407 408 __irqsoff_tracer_init(tr); 409 return 0; 410 } 411 static struct tracer irqsoff_tracer __read_mostly = 412 { 413 .name = "irqsoff", 414 .init = irqsoff_tracer_init, 415 .reset = irqsoff_tracer_reset, 416 .start = irqsoff_tracer_start, 417 .stop = irqsoff_tracer_stop, 418 .print_max = 1, 419 #ifdef CONFIG_FTRACE_SELFTEST 420 .selftest = trace_selftest_startup_irqsoff, 421 #endif 422 }; 423 # define register_irqsoff(trace) register_tracer(&trace) 424 #else 425 # define register_irqsoff(trace) do { } while (0) 426 #endif 427 428 #ifdef CONFIG_PREEMPT_TRACER 429 static int preemptoff_tracer_init(struct trace_array *tr) 430 { 431 trace_type = TRACER_PREEMPT_OFF; 432 433 __irqsoff_tracer_init(tr); 434 return 0; 435 } 436 437 static struct tracer preemptoff_tracer __read_mostly = 438 { 439 .name = "preemptoff", 440 .init = preemptoff_tracer_init, 441 .reset = irqsoff_tracer_reset, 442 .start = irqsoff_tracer_start, 443 .stop = irqsoff_tracer_stop, 444 .print_max = 1, 445 #ifdef CONFIG_FTRACE_SELFTEST 446 .selftest = trace_selftest_startup_preemptoff, 447 #endif 448 }; 449 # define register_preemptoff(trace) register_tracer(&trace) 450 #else 451 # define register_preemptoff(trace) do { } while (0) 452 #endif 453 454 #if defined(CONFIG_IRQSOFF_TRACER) && \ 455 defined(CONFIG_PREEMPT_TRACER) 456 457 static int preemptirqsoff_tracer_init(struct trace_array *tr) 458 { 459 trace_type = TRACER_IRQS_OFF | TRACER_PREEMPT_OFF; 460 461 __irqsoff_tracer_init(tr); 462 return 0; 463 } 464 465 static struct tracer preemptirqsoff_tracer __read_mostly = 466 { 467 .name = "preemptirqsoff", 468 .init = preemptirqsoff_tracer_init, 469 .reset = irqsoff_tracer_reset, 470 .start = irqsoff_tracer_start, 471 .stop = irqsoff_tracer_stop, 472 .print_max = 1, 473 #ifdef CONFIG_FTRACE_SELFTEST 474 .selftest = trace_selftest_startup_preemptirqsoff, 475 #endif 476 }; 477 478 # define register_preemptirqsoff(trace) register_tracer(&trace) 479 #else 480 # define register_preemptirqsoff(trace) do { } while (0) 481 #endif 482 483 __init static int init_irqsoff_tracer(void) 484 { 485 register_irqsoff(irqsoff_tracer); 486 register_preemptoff(preemptoff_tracer); 487 register_preemptirqsoff(preemptirqsoff_tracer); 488 489 return 0; 490 } 491 device_initcall(init_irqsoff_tracer); 492