linux/Documentation/trace
Byungchul Park 8e1e1df29d 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>
2014-12-03 17:10:13 -05:00
..
postprocess mm: trace-vmscan-postprocess.pl: report the number of file/anon pages respectively 2014-08-06 18:01:20 -07:00
events-kmem.txt mm-tracepoint: rename page-free events 2012-01-10 16:30:41 -08:00
events-nmi.txt x86: Add NMI duration tracepoints 2013-06-23 11:52:58 +02:00
events-power.txt PM / QoS: Rename device resume latency QoS items 2014-02-11 00:35:23 +01:00
events.txt doc: spelling error changes 2014-05-05 15:32:05 +02:00
ftrace-design.txt ftrace: Remove check for HAVE_FUNCTION_TRACE_MCOUNT_TEST 2014-07-18 13:57:01 -04:00
ftrace.txt tracing: Add additional marks to signal very large time deltas 2014-12-03 17:10:13 -05:00
function-graph-fold.vim tracing: Add vim script to enable folding for function_graph traces 2009-08-26 00:32:04 -04:00
kprobetrace.txt doc: fix old config name of kprobetrace 2012-09-27 12:11:29 +02:00
mmiotrace.txt Documentation: Update mmiotrace.txt 2009-12-20 06:18:23 +01:00
ring-buffer-design.txt doc: fix double words 2014-03-21 13:16:58 +01:00
tracepoint-analysis.txt mm-tracepoint: fix documentation and examples 2012-01-10 16:30:41 -08:00
tracepoints.txt tracing: Add trace_<tracepoint>_enabled() function 2014-05-07 12:10:51 -04:00
uprobetracer.txt tracing/uprobes: Add @+file_offset fetch method 2014-01-02 20:57:05 -05:00