aboutsummaryrefslogtreecommitdiffstats
path: root/kernel
diff options
context:
space:
mode:
authorByungchul Park <byungchul.park@lge.com>2014-11-23 19:34:19 -0500
committerSteven Rostedt <rostedt@goodmis.org>2014-12-03 17:10:13 -0500
commit8e1e1df29d837c589c8b4d7b49864481ff7795b8 (patch)
treec87b06e913b6ea361681e51cd2d7d91cc4f4345a /kernel
parent3e6fb8e94329270c70ea00867112a2c6f348207f (diff)
tracing: Add additional marks to signal very large time deltas
Currently, function graph tracer prints "!" or "+" just before function execution time to signal a function overhead, depending on the time. And some tracers tracing latency also print "!" or "+" just after time to signal overhead, depending on the interval between events. Even it is usually enough to do that, we sometimes need to signal for bigger execution time than 100 micro seconds. For example, I used function graph tracer to detect if there is any case that exit_mm() takes too much time. I did following steps in /sys/kernel/debug/tracing. It was easier to detect very large excution time with patched kernel than with original kernel. $ echo exit_mm > set_graph_function $ echo function_graph > current_tracer $ echo > trace $ cat trace_pipe > $LOGFILE ... (do something and terminate logging) $ grep "\\$" $LOGFILE 3) $ 22082032 us | } /* kernel_map_pages */ 3) $ 22082040 us | } /* free_pages_prepare */ 3) $ 22082113 us | } /* free_hot_cold_page */ 3) $ 22083455 us | } /* free_hot_cold_page_list */ 3) $ 22083895 us | } /* release_pages */ 3) $ 22177873 us | } /* free_pages_and_swap_cache */ 3) $ 22178929 us | } /* unmap_single_vma */ 3) $ 22198885 us | } /* unmap_vmas */ 3) $ 22206949 us | } /* exit_mmap */ 3) $ 22207659 us | } /* mmput */ 3) $ 22207793 us | } /* exit_mm */ And then, it was easy to find out that a schedule-out occured by sub_preempt_count() within kernel_map_pages(). To detect very large function exection time caused by either problematic function implementation or scheduling issues, this patch can be useful. Link: http://lkml.kernel.org/r/1416789259-24038-1-git-send-email-byungchul.park@lge.com Signed-off-by: Byungchul Park <byungchul.park@lge.com> Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
Diffstat (limited to 'kernel')
-rw-r--r--kernel/trace/trace.h2
-rw-r--r--kernel/trace/trace_functions_graph.c23
-rw-r--r--kernel/trace/trace_output.c34
3 files changed, 34 insertions, 25 deletions
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index c3a37e55ec8b..3255dfb054a0 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -708,6 +708,8 @@ enum print_line_t print_trace_line(struct trace_iterator *iter);
708 708
709extern unsigned long trace_flags; 709extern unsigned long trace_flags;
710 710
711extern char trace_find_mark(unsigned long long duration);
712
711/* Standard output formatting function used for function return traces */ 713/* Standard output formatting function used for function return traces */
712#ifdef CONFIG_FUNCTION_GRAPH_TRACER 714#ifdef CONFIG_FUNCTION_GRAPH_TRACER
713 715
diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
index 100288d10e1f..6c2ab955018c 100644
--- a/kernel/trace/trace_functions_graph.c
+++ b/kernel/trace/trace_functions_graph.c
@@ -730,8 +730,6 @@ static void
730print_graph_duration(unsigned long long duration, struct trace_seq *s, 730print_graph_duration(unsigned long long duration, struct trace_seq *s,
731 u32 flags) 731 u32 flags)
732{ 732{
733 bool duration_printed = false;
734
735 if (!(flags & TRACE_GRAPH_PRINT_DURATION) || 733 if (!(flags & TRACE_GRAPH_PRINT_DURATION) ||
736 !(trace_flags & TRACE_ITER_CONTEXT_INFO)) 734 !(trace_flags & TRACE_ITER_CONTEXT_INFO))
737 return; 735 return;
@@ -750,24 +748,9 @@ print_graph_duration(unsigned long long duration, struct trace_seq *s,
750 } 748 }
751 749
752 /* Signal a overhead of time execution to the output */ 750 /* Signal a overhead of time execution to the output */
753 if (flags & TRACE_GRAPH_PRINT_OVERHEAD) { 751 if (flags & TRACE_GRAPH_PRINT_OVERHEAD)
754 /* Duration exceeded 100 usecs */ 752 trace_seq_printf(s, "%c ", trace_find_mark(duration));
755 if (duration > 100000ULL) { 753 else
756 trace_seq_puts(s, "! ");
757 duration_printed = true;
758
759 /* Duration exceeded 10 usecs */
760 } else if (duration > 10000ULL) {
761 trace_seq_puts(s, "+ ");
762 duration_printed = true;
763 }
764 }
765
766 /*
767 * If we did not exceed the duration tresholds or we dont want
768 * to print out the overhead. Either way we need to fill out the space.
769 */
770 if (!duration_printed)
771 trace_seq_puts(s, " "); 754 trace_seq_puts(s, " ");
772 755
773 trace_print_graph_duration(duration, s); 756 trace_print_graph_duration(duration, s);
diff --git a/kernel/trace/trace_output.c b/kernel/trace/trace_output.c
index 723818bc83b4..b77b9a697619 100644
--- a/kernel/trace/trace_output.c
+++ b/kernel/trace/trace_output.c
@@ -115,7 +115,7 @@ ftrace_print_symbols_seq(struct trace_seq *p, unsigned long val,
115 115
116 if (ret == (const char *)(trace_seq_buffer_ptr(p))) 116 if (ret == (const char *)(trace_seq_buffer_ptr(p)))
117 trace_seq_printf(p, "0x%lx", val); 117 trace_seq_printf(p, "0x%lx", val);
118 118
119 trace_seq_putc(p, 0); 119 trace_seq_putc(p, 0);
120 120
121 return ret; 121 return ret;
@@ -443,7 +443,32 @@ lat_print_generic(struct trace_seq *s, struct trace_entry *entry, int cpu)
443 return trace_print_lat_fmt(s, entry); 443 return trace_print_lat_fmt(s, entry);
444} 444}
445 445
446static unsigned long preempt_mark_thresh_us = 100; 446#undef MARK
447#define MARK(v, s) {.val = v, .sym = s}
448/* trace overhead mark */
449static const struct trace_mark {
450 unsigned long long val; /* unit: nsec */
451 char sym;
452} mark[] = {
453 MARK(1000000000ULL , '$'), /* 1 sec */
454 MARK(1000000ULL , '#'), /* 1000 usecs */
455 MARK(100000ULL , '!'), /* 100 usecs */
456 MARK(10000ULL , '+'), /* 10 usecs */
457};
458#undef MARK
459
460char trace_find_mark(unsigned long long d)
461{
462 int i;
463 int size = ARRAY_SIZE(mark);
464
465 for (i = 0; i < size; i++) {
466 if (d >= mark[i].val)
467 break;
468 }
469
470 return (i == size) ? ' ' : mark[i].sym;
471}
447 472
448static int 473static int
449lat_print_timestamp(struct trace_iterator *iter, u64 next_ts) 474lat_print_timestamp(struct trace_iterator *iter, u64 next_ts)
@@ -480,8 +505,7 @@ lat_print_timestamp(struct trace_iterator *iter, u64 next_ts)
480 trace_seq_printf( 505 trace_seq_printf(
481 s, " %4lldus%c: ", 506 s, " %4lldus%c: ",
482 abs_ts, 507 abs_ts,
483 rel_ts > preempt_mark_thresh_us ? '!' : 508 trace_find_mark(rel_ts * NSEC_PER_USEC));
484 rel_ts > 1 ? '+' : ' ');
485 509
486 } else { /* !verbose && !in_ns */ 510 } else { /* !verbose && !in_ns */
487 trace_seq_printf(s, " %4lld: ", abs_ts); 511 trace_seq_printf(s, " %4lld: ", abs_ts);
@@ -663,7 +687,7 @@ int register_ftrace_event(struct trace_event *event)
663 goto out; 687 goto out;
664 688
665 } else { 689 } else {
666 690
667 event->type = next_event_type++; 691 event->type = next_event_type++;
668 list = &ftrace_event_list; 692 list = &ftrace_event_list;
669 } 693 }