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