aboutsummaryrefslogtreecommitdiffstats
path: root/Documentation/trace
diff options
context:
space:
mode:
authorLinus Torvalds <torvalds@linux-foundation.org>2018-06-06 19:39:18 -0400
committerLinus Torvalds <torvalds@linux-foundation.org>2018-06-06 19:39:18 -0400
commit5eb6eed7e0fe880dc8de8da203cc888716bbf196 (patch)
tree05a7c83182b34a567c68b35c091cf31200d5ddec /Documentation/trace
parent8b5c6a3a49d9ebc7dc288870b9c56c4f946035d8 (diff)
parent591a033dc17ff6f684b6b6d1d7426e22d178194f (diff)
Merge tag 'trace-v4.18' of git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-trace
Pull tracing updates from Steven Rostedt: "One new feature was added to ftrace, which is the trace_marker now supports triggers. For example: # cd /sys/kernel/debug/tracing # echo 'snapshot' > events/ftrace/print/trigger # echo 'cause snapshot' > trace_marker The rest of the changes are various clean ups and also one stable fix that was added late in the cycle" * tag 'trace-v4.18' of git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-trace: (21 commits) tracing: Use match_string() instead of open coding it in trace_set_options() branch-check: fix long->int truncation when profiling branches ring-buffer: Fix typo in comment ring-buffer: Fix a bunch of typos in comments tracing/selftest: Add test to test simple snapshot trigger for trace_marker tracing/selftest: Add test to test hist trigger between kernel event and trace_marker tracing/selftest: Add selftests to test trace_marker histogram triggers ftrace/selftest: Fix reset_trigger() to handle triggers with filters ftrace/selftest: Have the reset_trigger code be a bit more careful tracing: Document trace_marker triggers tracing: Allow histogram triggers to access ftrace internal events tracing: Prevent further users of zero size static arrays in trace events tracing: Have zero size length in filter logic be full string tracing: Add trigger file for trace_markers tracefs/ftrace/print tracing: Do not show filter file for ftrace internal events tracing: Add brackets in ftrace event dynamic arrays tracing: Have event_trace_init() called by trace_init_tracefs() tracing: Add __find_event_file() to find event files without restrictions tracing: Do not reference event data in post call triggers tracepoints: Fix the descriptions of tracepoint_probe_register{_prio} ...
Diffstat (limited to 'Documentation/trace')
-rw-r--r--Documentation/trace/events.rst6
-rw-r--r--Documentation/trace/ftrace.rst5
-rw-r--r--Documentation/trace/histogram.txt545
3 files changed, 554 insertions, 2 deletions
diff --git a/Documentation/trace/events.rst b/Documentation/trace/events.rst
index a5ea2cb0082b..1afae55dc55c 100644
--- a/Documentation/trace/events.rst
+++ b/Documentation/trace/events.rst
@@ -338,10 +338,14 @@ used for conditionally invoking triggers.
338 338
339The syntax for event triggers is roughly based on the syntax for 339The syntax for event triggers is roughly based on the syntax for
340set_ftrace_filter 'ftrace filter commands' (see the 'Filter commands' 340set_ftrace_filter 'ftrace filter commands' (see the 'Filter commands'
341section of Documentation/trace/ftrace.txt), but there are major 341section of Documentation/trace/ftrace.rst), but there are major
342differences and the implementation isn't currently tied to it in any 342differences and the implementation isn't currently tied to it in any
343way, so beware about making generalizations between the two. 343way, so beware about making generalizations between the two.
344 344
345Note: Writing into trace_marker (See Documentation/trace/ftrace.rst)
346 can also enable triggers that are written into
347 /sys/kernel/tracing/events/ftrace/print/trigger
348
3456.1 Expression syntax 3496.1 Expression syntax
346--------------------- 350---------------------
347 351
diff --git a/Documentation/trace/ftrace.rst b/Documentation/trace/ftrace.rst
index 6b80ac4bbaae..a20d34955333 100644
--- a/Documentation/trace/ftrace.rst
+++ b/Documentation/trace/ftrace.rst
@@ -512,6 +512,11 @@ of ftrace. Here is a list of some of the key files:
512 512
513 trace_fd = open("trace_marker", WR_ONLY); 513 trace_fd = open("trace_marker", WR_ONLY);
514 514
515 Note: Writing into the trace_marker file can also initiate triggers
516 that are written into /sys/kernel/tracing/events/ftrace/print/trigger
517 See "Event triggers" in Documentation/trace/events.rst and an
518 example in Documentation/trace/histogram.rst (Section 3.)
519
515 trace_marker_raw: 520 trace_marker_raw:
516 521
517 This is similar to trace_marker above, but is meant for for binary data 522 This is similar to trace_marker above, but is meant for for binary data
diff --git a/Documentation/trace/histogram.txt b/Documentation/trace/histogram.txt
index 6e05510afc28..b13771cb12c1 100644
--- a/Documentation/trace/histogram.txt
+++ b/Documentation/trace/histogram.txt
@@ -1604,7 +1604,6 @@
1604 Entries: 7 1604 Entries: 7
1605 Dropped: 0 1605 Dropped: 0
1606 1606
1607
16082.2 Inter-event hist triggers 16072.2 Inter-event hist triggers
1609----------------------------- 1608-----------------------------
1610 1609
@@ -1993,3 +1992,547 @@ hist trigger specification.
1993 Hits: 12970 1992 Hits: 12970
1994 Entries: 2 1993 Entries: 2
1995 Dropped: 0 1994 Dropped: 0
1995
19963. User space creating a trigger
1997--------------------------------
1998
1999Writing into /sys/kernel/tracing/trace_marker writes into the ftrace
2000ring buffer. This can also act like an event, by writing into the trigger
2001file located in /sys/kernel/tracing/events/ftrace/print/
2002
2003Modifying cyclictest to write into the trace_marker file before it sleeps
2004and after it wakes up, something like this:
2005
2006static void traceputs(char *str)
2007{
2008 /* tracemark_fd is the trace_marker file descriptor */
2009 if (tracemark_fd < 0)
2010 return;
2011 /* write the tracemark message */
2012 write(tracemark_fd, str, strlen(str));
2013}
2014
2015And later add something like:
2016
2017 traceputs("start");
2018 clock_nanosleep(...);
2019 traceputs("end");
2020
2021We can make a histogram from this:
2022
2023 # cd /sys/kernel/tracing
2024 # echo 'latency u64 lat' > synthetic_events
2025 # echo 'hist:keys=common_pid:ts0=common_timestamp.usecs if buf == "start"' > events/ftrace/print/trigger
2026 # echo 'hist:keys=common_pid:lat=common_timestamp.usecs-$ts0:onmatch(ftrace.print).latency($lat) if buf == "end"' >> events/ftrace/print/trigger
2027 # echo 'hist:keys=lat,common_pid:sort=lat' > events/synthetic/latency/trigger
2028
2029The above created a synthetic event called "latency" and two histograms
2030against the trace_marker, one gets triggered when "start" is written into the
2031trace_marker file and the other when "end" is written. If the pids match, then
2032it will call the "latency" synthetic event with the calculated latency as its
2033parameter. Finally, a histogram is added to the latency synthetic event to
2034record the calculated latency along with the pid.
2035
2036Now running cyclictest with:
2037
2038 # ./cyclictest -p80 -d0 -i250 -n -a -t --tracemark -b 1000
2039
2040 -p80 : run threads at priority 80
2041 -d0 : have all threads run at the same interval
2042 -i250 : start the interval at 250 microseconds (all threads will do this)
2043 -n : sleep with nanosleep
2044 -a : affine all threads to a separate CPU
2045 -t : one thread per available CPU
2046 --tracemark : enable trace mark writing
2047 -b 1000 : stop if any latency is greater than 1000 microseconds
2048
2049Note, the -b 1000 is used just to make --tracemark available.
2050
2051Then we can see the histogram created by this with:
2052
2053 # cat events/synthetic/latency/hist
2054# event histogram
2055#
2056# trigger info: hist:keys=lat,common_pid:vals=hitcount:sort=lat:size=2048 [active]
2057#
2058
2059{ lat: 107, common_pid: 2039 } hitcount: 1
2060{ lat: 122, common_pid: 2041 } hitcount: 1
2061{ lat: 166, common_pid: 2039 } hitcount: 1
2062{ lat: 174, common_pid: 2039 } hitcount: 1
2063{ lat: 194, common_pid: 2041 } hitcount: 1
2064{ lat: 196, common_pid: 2036 } hitcount: 1
2065{ lat: 197, common_pid: 2038 } hitcount: 1
2066{ lat: 198, common_pid: 2039 } hitcount: 1
2067{ lat: 199, common_pid: 2039 } hitcount: 1
2068{ lat: 200, common_pid: 2041 } hitcount: 1
2069{ lat: 201, common_pid: 2039 } hitcount: 2
2070{ lat: 202, common_pid: 2038 } hitcount: 1
2071{ lat: 202, common_pid: 2043 } hitcount: 1
2072{ lat: 203, common_pid: 2039 } hitcount: 1
2073{ lat: 203, common_pid: 2036 } hitcount: 1
2074{ lat: 203, common_pid: 2041 } hitcount: 1
2075{ lat: 206, common_pid: 2038 } hitcount: 2
2076{ lat: 207, common_pid: 2039 } hitcount: 1
2077{ lat: 207, common_pid: 2036 } hitcount: 1
2078{ lat: 208, common_pid: 2040 } hitcount: 1
2079{ lat: 209, common_pid: 2043 } hitcount: 1
2080{ lat: 210, common_pid: 2039 } hitcount: 1
2081{ lat: 211, common_pid: 2039 } hitcount: 4
2082{ lat: 212, common_pid: 2043 } hitcount: 1
2083{ lat: 212, common_pid: 2039 } hitcount: 2
2084{ lat: 213, common_pid: 2039 } hitcount: 1
2085{ lat: 214, common_pid: 2038 } hitcount: 1
2086{ lat: 214, common_pid: 2039 } hitcount: 2
2087{ lat: 214, common_pid: 2042 } hitcount: 1
2088{ lat: 215, common_pid: 2039 } hitcount: 1
2089{ lat: 217, common_pid: 2036 } hitcount: 1
2090{ lat: 217, common_pid: 2040 } hitcount: 1
2091{ lat: 217, common_pid: 2039 } hitcount: 1
2092{ lat: 218, common_pid: 2039 } hitcount: 6
2093{ lat: 219, common_pid: 2039 } hitcount: 9
2094{ lat: 220, common_pid: 2039 } hitcount: 11
2095{ lat: 221, common_pid: 2039 } hitcount: 5
2096{ lat: 221, common_pid: 2042 } hitcount: 1
2097{ lat: 222, common_pid: 2039 } hitcount: 7
2098{ lat: 223, common_pid: 2036 } hitcount: 1
2099{ lat: 223, common_pid: 2039 } hitcount: 3
2100{ lat: 224, common_pid: 2039 } hitcount: 4
2101{ lat: 224, common_pid: 2037 } hitcount: 1
2102{ lat: 224, common_pid: 2036 } hitcount: 2
2103{ lat: 225, common_pid: 2039 } hitcount: 5
2104{ lat: 225, common_pid: 2042 } hitcount: 1
2105{ lat: 226, common_pid: 2039 } hitcount: 7
2106{ lat: 226, common_pid: 2036 } hitcount: 4
2107{ lat: 227, common_pid: 2039 } hitcount: 6
2108{ lat: 227, common_pid: 2036 } hitcount: 12
2109{ lat: 227, common_pid: 2043 } hitcount: 1
2110{ lat: 228, common_pid: 2039 } hitcount: 7
2111{ lat: 228, common_pid: 2036 } hitcount: 14
2112{ lat: 229, common_pid: 2039 } hitcount: 9
2113{ lat: 229, common_pid: 2036 } hitcount: 8
2114{ lat: 229, common_pid: 2038 } hitcount: 1
2115{ lat: 230, common_pid: 2039 } hitcount: 11
2116{ lat: 230, common_pid: 2036 } hitcount: 6
2117{ lat: 230, common_pid: 2043 } hitcount: 1
2118{ lat: 230, common_pid: 2042 } hitcount: 2
2119{ lat: 231, common_pid: 2041 } hitcount: 1
2120{ lat: 231, common_pid: 2036 } hitcount: 6
2121{ lat: 231, common_pid: 2043 } hitcount: 1
2122{ lat: 231, common_pid: 2039 } hitcount: 8
2123{ lat: 232, common_pid: 2037 } hitcount: 1
2124{ lat: 232, common_pid: 2039 } hitcount: 6
2125{ lat: 232, common_pid: 2040 } hitcount: 2
2126{ lat: 232, common_pid: 2036 } hitcount: 5
2127{ lat: 232, common_pid: 2043 } hitcount: 1
2128{ lat: 233, common_pid: 2036 } hitcount: 5
2129{ lat: 233, common_pid: 2039 } hitcount: 11
2130{ lat: 234, common_pid: 2039 } hitcount: 4
2131{ lat: 234, common_pid: 2038 } hitcount: 2
2132{ lat: 234, common_pid: 2043 } hitcount: 2
2133{ lat: 234, common_pid: 2036 } hitcount: 11
2134{ lat: 234, common_pid: 2040 } hitcount: 1
2135{ lat: 235, common_pid: 2037 } hitcount: 2
2136{ lat: 235, common_pid: 2036 } hitcount: 8
2137{ lat: 235, common_pid: 2043 } hitcount: 2
2138{ lat: 235, common_pid: 2039 } hitcount: 5
2139{ lat: 235, common_pid: 2042 } hitcount: 2
2140{ lat: 235, common_pid: 2040 } hitcount: 4
2141{ lat: 235, common_pid: 2041 } hitcount: 1
2142{ lat: 236, common_pid: 2036 } hitcount: 7
2143{ lat: 236, common_pid: 2037 } hitcount: 1
2144{ lat: 236, common_pid: 2041 } hitcount: 5
2145{ lat: 236, common_pid: 2039 } hitcount: 3
2146{ lat: 236, common_pid: 2043 } hitcount: 9
2147{ lat: 236, common_pid: 2040 } hitcount: 7
2148{ lat: 237, common_pid: 2037 } hitcount: 1
2149{ lat: 237, common_pid: 2040 } hitcount: 1
2150{ lat: 237, common_pid: 2036 } hitcount: 9
2151{ lat: 237, common_pid: 2039 } hitcount: 3
2152{ lat: 237, common_pid: 2043 } hitcount: 8
2153{ lat: 237, common_pid: 2042 } hitcount: 2
2154{ lat: 237, common_pid: 2041 } hitcount: 2
2155{ lat: 238, common_pid: 2043 } hitcount: 10
2156{ lat: 238, common_pid: 2040 } hitcount: 1
2157{ lat: 238, common_pid: 2037 } hitcount: 9
2158{ lat: 238, common_pid: 2038 } hitcount: 1
2159{ lat: 238, common_pid: 2039 } hitcount: 1
2160{ lat: 238, common_pid: 2042 } hitcount: 3
2161{ lat: 238, common_pid: 2036 } hitcount: 7
2162{ lat: 239, common_pid: 2041 } hitcount: 1
2163{ lat: 239, common_pid: 2043 } hitcount: 11
2164{ lat: 239, common_pid: 2037 } hitcount: 11
2165{ lat: 239, common_pid: 2038 } hitcount: 6
2166{ lat: 239, common_pid: 2036 } hitcount: 7
2167{ lat: 239, common_pid: 2040 } hitcount: 1
2168{ lat: 239, common_pid: 2042 } hitcount: 9
2169{ lat: 240, common_pid: 2037 } hitcount: 29
2170{ lat: 240, common_pid: 2043 } hitcount: 15
2171{ lat: 240, common_pid: 2040 } hitcount: 44
2172{ lat: 240, common_pid: 2039 } hitcount: 1
2173{ lat: 240, common_pid: 2041 } hitcount: 2
2174{ lat: 240, common_pid: 2038 } hitcount: 1
2175{ lat: 240, common_pid: 2036 } hitcount: 10
2176{ lat: 240, common_pid: 2042 } hitcount: 13
2177{ lat: 241, common_pid: 2036 } hitcount: 21
2178{ lat: 241, common_pid: 2041 } hitcount: 36
2179{ lat: 241, common_pid: 2037 } hitcount: 34
2180{ lat: 241, common_pid: 2042 } hitcount: 14
2181{ lat: 241, common_pid: 2040 } hitcount: 94
2182{ lat: 241, common_pid: 2039 } hitcount: 12
2183{ lat: 241, common_pid: 2038 } hitcount: 2
2184{ lat: 241, common_pid: 2043 } hitcount: 28
2185{ lat: 242, common_pid: 2040 } hitcount: 109
2186{ lat: 242, common_pid: 2041 } hitcount: 506
2187{ lat: 242, common_pid: 2039 } hitcount: 155
2188{ lat: 242, common_pid: 2042 } hitcount: 21
2189{ lat: 242, common_pid: 2037 } hitcount: 52
2190{ lat: 242, common_pid: 2043 } hitcount: 21
2191{ lat: 242, common_pid: 2036 } hitcount: 16
2192{ lat: 242, common_pid: 2038 } hitcount: 156
2193{ lat: 243, common_pid: 2037 } hitcount: 46
2194{ lat: 243, common_pid: 2039 } hitcount: 40
2195{ lat: 243, common_pid: 2042 } hitcount: 119
2196{ lat: 243, common_pid: 2041 } hitcount: 611
2197{ lat: 243, common_pid: 2036 } hitcount: 69
2198{ lat: 243, common_pid: 2038 } hitcount: 784
2199{ lat: 243, common_pid: 2040 } hitcount: 323
2200{ lat: 243, common_pid: 2043 } hitcount: 14
2201{ lat: 244, common_pid: 2043 } hitcount: 35
2202{ lat: 244, common_pid: 2042 } hitcount: 305
2203{ lat: 244, common_pid: 2039 } hitcount: 8
2204{ lat: 244, common_pid: 2040 } hitcount: 4515
2205{ lat: 244, common_pid: 2038 } hitcount: 371
2206{ lat: 244, common_pid: 2037 } hitcount: 31
2207{ lat: 244, common_pid: 2036 } hitcount: 114
2208{ lat: 244, common_pid: 2041 } hitcount: 3396
2209{ lat: 245, common_pid: 2036 } hitcount: 700
2210{ lat: 245, common_pid: 2041 } hitcount: 2772
2211{ lat: 245, common_pid: 2037 } hitcount: 268
2212{ lat: 245, common_pid: 2039 } hitcount: 472
2213{ lat: 245, common_pid: 2038 } hitcount: 2758
2214{ lat: 245, common_pid: 2042 } hitcount: 3833
2215{ lat: 245, common_pid: 2040 } hitcount: 3105
2216{ lat: 245, common_pid: 2043 } hitcount: 645
2217{ lat: 246, common_pid: 2038 } hitcount: 3451
2218{ lat: 246, common_pid: 2041 } hitcount: 142
2219{ lat: 246, common_pid: 2037 } hitcount: 5101
2220{ lat: 246, common_pid: 2040 } hitcount: 68
2221{ lat: 246, common_pid: 2043 } hitcount: 5099
2222{ lat: 246, common_pid: 2039 } hitcount: 5608
2223{ lat: 246, common_pid: 2042 } hitcount: 3723
2224{ lat: 246, common_pid: 2036 } hitcount: 4738
2225{ lat: 247, common_pid: 2042 } hitcount: 312
2226{ lat: 247, common_pid: 2043 } hitcount: 2385
2227{ lat: 247, common_pid: 2041 } hitcount: 452
2228{ lat: 247, common_pid: 2038 } hitcount: 792
2229{ lat: 247, common_pid: 2040 } hitcount: 78
2230{ lat: 247, common_pid: 2036 } hitcount: 2375
2231{ lat: 247, common_pid: 2039 } hitcount: 1834
2232{ lat: 247, common_pid: 2037 } hitcount: 2655
2233{ lat: 248, common_pid: 2037 } hitcount: 36
2234{ lat: 248, common_pid: 2042 } hitcount: 11
2235{ lat: 248, common_pid: 2038 } hitcount: 122
2236{ lat: 248, common_pid: 2036 } hitcount: 135
2237{ lat: 248, common_pid: 2039 } hitcount: 26
2238{ lat: 248, common_pid: 2041 } hitcount: 503
2239{ lat: 248, common_pid: 2043 } hitcount: 66
2240{ lat: 248, common_pid: 2040 } hitcount: 46
2241{ lat: 249, common_pid: 2037 } hitcount: 29
2242{ lat: 249, common_pid: 2038 } hitcount: 1
2243{ lat: 249, common_pid: 2043 } hitcount: 29
2244{ lat: 249, common_pid: 2039 } hitcount: 8
2245{ lat: 249, common_pid: 2042 } hitcount: 56
2246{ lat: 249, common_pid: 2040 } hitcount: 27
2247{ lat: 249, common_pid: 2041 } hitcount: 11
2248{ lat: 249, common_pid: 2036 } hitcount: 27
2249{ lat: 250, common_pid: 2038 } hitcount: 1
2250{ lat: 250, common_pid: 2036 } hitcount: 30
2251{ lat: 250, common_pid: 2040 } hitcount: 19
2252{ lat: 250, common_pid: 2043 } hitcount: 22
2253{ lat: 250, common_pid: 2042 } hitcount: 20
2254{ lat: 250, common_pid: 2041 } hitcount: 1
2255{ lat: 250, common_pid: 2039 } hitcount: 6
2256{ lat: 250, common_pid: 2037 } hitcount: 48
2257{ lat: 251, common_pid: 2037 } hitcount: 43
2258{ lat: 251, common_pid: 2039 } hitcount: 1
2259{ lat: 251, common_pid: 2036 } hitcount: 12
2260{ lat: 251, common_pid: 2042 } hitcount: 2
2261{ lat: 251, common_pid: 2041 } hitcount: 1
2262{ lat: 251, common_pid: 2043 } hitcount: 15
2263{ lat: 251, common_pid: 2040 } hitcount: 3
2264{ lat: 252, common_pid: 2040 } hitcount: 1
2265{ lat: 252, common_pid: 2036 } hitcount: 12
2266{ lat: 252, common_pid: 2037 } hitcount: 21
2267{ lat: 252, common_pid: 2043 } hitcount: 14
2268{ lat: 253, common_pid: 2037 } hitcount: 21
2269{ lat: 253, common_pid: 2039 } hitcount: 2
2270{ lat: 253, common_pid: 2036 } hitcount: 9
2271{ lat: 253, common_pid: 2043 } hitcount: 6
2272{ lat: 253, common_pid: 2040 } hitcount: 1
2273{ lat: 254, common_pid: 2036 } hitcount: 8
2274{ lat: 254, common_pid: 2043 } hitcount: 3
2275{ lat: 254, common_pid: 2041 } hitcount: 1
2276{ lat: 254, common_pid: 2042 } hitcount: 1
2277{ lat: 254, common_pid: 2039 } hitcount: 1
2278{ lat: 254, common_pid: 2037 } hitcount: 12
2279{ lat: 255, common_pid: 2043 } hitcount: 1
2280{ lat: 255, common_pid: 2037 } hitcount: 2
2281{ lat: 255, common_pid: 2036 } hitcount: 2
2282{ lat: 255, common_pid: 2039 } hitcount: 8
2283{ lat: 256, common_pid: 2043 } hitcount: 1
2284{ lat: 256, common_pid: 2036 } hitcount: 4
2285{ lat: 256, common_pid: 2039 } hitcount: 6
2286{ lat: 257, common_pid: 2039 } hitcount: 5
2287{ lat: 257, common_pid: 2036 } hitcount: 4
2288{ lat: 258, common_pid: 2039 } hitcount: 5
2289{ lat: 258, common_pid: 2036 } hitcount: 2
2290{ lat: 259, common_pid: 2036 } hitcount: 7
2291{ lat: 259, common_pid: 2039 } hitcount: 7
2292{ lat: 260, common_pid: 2036 } hitcount: 8
2293{ lat: 260, common_pid: 2039 } hitcount: 6
2294{ lat: 261, common_pid: 2036 } hitcount: 5
2295{ lat: 261, common_pid: 2039 } hitcount: 7
2296{ lat: 262, common_pid: 2039 } hitcount: 5
2297{ lat: 262, common_pid: 2036 } hitcount: 5
2298{ lat: 263, common_pid: 2039 } hitcount: 7
2299{ lat: 263, common_pid: 2036 } hitcount: 7
2300{ lat: 264, common_pid: 2039 } hitcount: 9
2301{ lat: 264, common_pid: 2036 } hitcount: 9
2302{ lat: 265, common_pid: 2036 } hitcount: 5
2303{ lat: 265, common_pid: 2039 } hitcount: 1
2304{ lat: 266, common_pid: 2036 } hitcount: 1
2305{ lat: 266, common_pid: 2039 } hitcount: 3
2306{ lat: 267, common_pid: 2036 } hitcount: 1
2307{ lat: 267, common_pid: 2039 } hitcount: 3
2308{ lat: 268, common_pid: 2036 } hitcount: 1
2309{ lat: 268, common_pid: 2039 } hitcount: 6
2310{ lat: 269, common_pid: 2036 } hitcount: 1
2311{ lat: 269, common_pid: 2043 } hitcount: 1
2312{ lat: 269, common_pid: 2039 } hitcount: 2
2313{ lat: 270, common_pid: 2040 } hitcount: 1
2314{ lat: 270, common_pid: 2039 } hitcount: 6
2315{ lat: 271, common_pid: 2041 } hitcount: 1
2316{ lat: 271, common_pid: 2039 } hitcount: 5
2317{ lat: 272, common_pid: 2039 } hitcount: 10
2318{ lat: 273, common_pid: 2039 } hitcount: 8
2319{ lat: 274, common_pid: 2039 } hitcount: 2
2320{ lat: 275, common_pid: 2039 } hitcount: 1
2321{ lat: 276, common_pid: 2039 } hitcount: 2
2322{ lat: 276, common_pid: 2037 } hitcount: 1
2323{ lat: 276, common_pid: 2038 } hitcount: 1
2324{ lat: 277, common_pid: 2039 } hitcount: 1
2325{ lat: 277, common_pid: 2042 } hitcount: 1
2326{ lat: 278, common_pid: 2039 } hitcount: 1
2327{ lat: 279, common_pid: 2039 } hitcount: 4
2328{ lat: 279, common_pid: 2043 } hitcount: 1
2329{ lat: 280, common_pid: 2039 } hitcount: 3
2330{ lat: 283, common_pid: 2036 } hitcount: 2
2331{ lat: 284, common_pid: 2039 } hitcount: 1
2332{ lat: 284, common_pid: 2043 } hitcount: 1
2333{ lat: 288, common_pid: 2039 } hitcount: 1
2334{ lat: 289, common_pid: 2039 } hitcount: 1
2335{ lat: 300, common_pid: 2039 } hitcount: 1
2336{ lat: 384, common_pid: 2039 } hitcount: 1
2337
2338Totals:
2339 Hits: 67625
2340 Entries: 278
2341 Dropped: 0
2342
2343Note, the writes are around the sleep, so ideally they will all be of 250
2344microseconds. If you are wondering how there are several that are under
2345250 microseconds, that is because the way cyclictest works, is if one
2346iteration comes in late, the next one will set the timer to wake up less that
2347250. That is, if an iteration came in 50 microseconds late, the next wake up
2348will be at 200 microseconds.
2349
2350But this could easily be done in userspace. To make this even more
2351interesting, we can mix the histogram between events that happened in the
2352kernel with trace_marker.
2353
2354 # cd /sys/kernel/tracing
2355 # echo 'latency u64 lat' > synthetic_events
2356 # echo 'hist:keys=pid:ts0=common_timestamp.usecs' > events/sched/sched_waking/trigger
2357 # echo 'hist:keys=common_pid:lat=common_timestamp.usecs-$ts0:onmatch(sched.sched_waking).latency($lat) if buf == "end"' > events/ftrace/print/trigger
2358 # echo 'hist:keys=lat,common_pid:sort=lat' > events/synthetic/latency/trigger
2359
2360The difference this time is that instead of using the trace_marker to start
2361the latency, the sched_waking event is used, matching the common_pid for the
2362trace_marker write with the pid that is being woken by sched_waking.
2363
2364After running cyclictest again with the same parameters, we now have:
2365
2366 # cat events/synthetic/latency/hist
2367# event histogram
2368#
2369# trigger info: hist:keys=lat,common_pid:vals=hitcount:sort=lat:size=2048 [active]
2370#
2371
2372{ lat: 7, common_pid: 2302 } hitcount: 640
2373{ lat: 7, common_pid: 2299 } hitcount: 42
2374{ lat: 7, common_pid: 2303 } hitcount: 18
2375{ lat: 7, common_pid: 2305 } hitcount: 166
2376{ lat: 7, common_pid: 2306 } hitcount: 1
2377{ lat: 7, common_pid: 2301 } hitcount: 91
2378{ lat: 7, common_pid: 2300 } hitcount: 17
2379{ lat: 8, common_pid: 2303 } hitcount: 8296
2380{ lat: 8, common_pid: 2304 } hitcount: 6864
2381{ lat: 8, common_pid: 2305 } hitcount: 9464
2382{ lat: 8, common_pid: 2301 } hitcount: 9213
2383{ lat: 8, common_pid: 2306 } hitcount: 6246
2384{ lat: 8, common_pid: 2302 } hitcount: 8797
2385{ lat: 8, common_pid: 2299 } hitcount: 8771
2386{ lat: 8, common_pid: 2300 } hitcount: 8119
2387{ lat: 9, common_pid: 2305 } hitcount: 1519
2388{ lat: 9, common_pid: 2299 } hitcount: 2346
2389{ lat: 9, common_pid: 2303 } hitcount: 2841
2390{ lat: 9, common_pid: 2301 } hitcount: 1846
2391{ lat: 9, common_pid: 2304 } hitcount: 3861
2392{ lat: 9, common_pid: 2302 } hitcount: 1210
2393{ lat: 9, common_pid: 2300 } hitcount: 2762
2394{ lat: 9, common_pid: 2306 } hitcount: 4247
2395{ lat: 10, common_pid: 2299 } hitcount: 16
2396{ lat: 10, common_pid: 2306 } hitcount: 333
2397{ lat: 10, common_pid: 2303 } hitcount: 16
2398{ lat: 10, common_pid: 2304 } hitcount: 168
2399{ lat: 10, common_pid: 2302 } hitcount: 240
2400{ lat: 10, common_pid: 2301 } hitcount: 28
2401{ lat: 10, common_pid: 2300 } hitcount: 95
2402{ lat: 10, common_pid: 2305 } hitcount: 18
2403{ lat: 11, common_pid: 2303 } hitcount: 5
2404{ lat: 11, common_pid: 2305 } hitcount: 8
2405{ lat: 11, common_pid: 2306 } hitcount: 221
2406{ lat: 11, common_pid: 2302 } hitcount: 76
2407{ lat: 11, common_pid: 2304 } hitcount: 26
2408{ lat: 11, common_pid: 2300 } hitcount: 125
2409{ lat: 11, common_pid: 2299 } hitcount: 2
2410{ lat: 12, common_pid: 2305 } hitcount: 3
2411{ lat: 12, common_pid: 2300 } hitcount: 6
2412{ lat: 12, common_pid: 2306 } hitcount: 90
2413{ lat: 12, common_pid: 2302 } hitcount: 4
2414{ lat: 12, common_pid: 2303 } hitcount: 1
2415{ lat: 12, common_pid: 2304 } hitcount: 122
2416{ lat: 13, common_pid: 2300 } hitcount: 12
2417{ lat: 13, common_pid: 2301 } hitcount: 1
2418{ lat: 13, common_pid: 2306 } hitcount: 32
2419{ lat: 13, common_pid: 2302 } hitcount: 5
2420{ lat: 13, common_pid: 2305 } hitcount: 1
2421{ lat: 13, common_pid: 2303 } hitcount: 1
2422{ lat: 13, common_pid: 2304 } hitcount: 61
2423{ lat: 14, common_pid: 2303 } hitcount: 4
2424{ lat: 14, common_pid: 2306 } hitcount: 5
2425{ lat: 14, common_pid: 2305 } hitcount: 4
2426{ lat: 14, common_pid: 2304 } hitcount: 62
2427{ lat: 14, common_pid: 2302 } hitcount: 19
2428{ lat: 14, common_pid: 2300 } hitcount: 33
2429{ lat: 14, common_pid: 2299 } hitcount: 1
2430{ lat: 14, common_pid: 2301 } hitcount: 4
2431{ lat: 15, common_pid: 2305 } hitcount: 1
2432{ lat: 15, common_pid: 2302 } hitcount: 25
2433{ lat: 15, common_pid: 2300 } hitcount: 11
2434{ lat: 15, common_pid: 2299 } hitcount: 5
2435{ lat: 15, common_pid: 2301 } hitcount: 1
2436{ lat: 15, common_pid: 2304 } hitcount: 8
2437{ lat: 15, common_pid: 2303 } hitcount: 1
2438{ lat: 15, common_pid: 2306 } hitcount: 6
2439{ lat: 16, common_pid: 2302 } hitcount: 31
2440{ lat: 16, common_pid: 2306 } hitcount: 3
2441{ lat: 16, common_pid: 2300 } hitcount: 5
2442{ lat: 17, common_pid: 2302 } hitcount: 6
2443{ lat: 17, common_pid: 2303 } hitcount: 1
2444{ lat: 18, common_pid: 2304 } hitcount: 1
2445{ lat: 18, common_pid: 2302 } hitcount: 8
2446{ lat: 18, common_pid: 2299 } hitcount: 1
2447{ lat: 18, common_pid: 2301 } hitcount: 1
2448{ lat: 19, common_pid: 2303 } hitcount: 4
2449{ lat: 19, common_pid: 2304 } hitcount: 5
2450{ lat: 19, common_pid: 2302 } hitcount: 4
2451{ lat: 19, common_pid: 2299 } hitcount: 3
2452{ lat: 19, common_pid: 2306 } hitcount: 1
2453{ lat: 19, common_pid: 2300 } hitcount: 4
2454{ lat: 19, common_pid: 2305 } hitcount: 5
2455{ lat: 20, common_pid: 2299 } hitcount: 2
2456{ lat: 20, common_pid: 2302 } hitcount: 3
2457{ lat: 20, common_pid: 2305 } hitcount: 1
2458{ lat: 20, common_pid: 2300 } hitcount: 2
2459{ lat: 20, common_pid: 2301 } hitcount: 2
2460{ lat: 20, common_pid: 2303 } hitcount: 3
2461{ lat: 21, common_pid: 2305 } hitcount: 1
2462{ lat: 21, common_pid: 2299 } hitcount: 5
2463{ lat: 21, common_pid: 2303 } hitcount: 4
2464{ lat: 21, common_pid: 2302 } hitcount: 7
2465{ lat: 21, common_pid: 2300 } hitcount: 1
2466{ lat: 21, common_pid: 2301 } hitcount: 5
2467{ lat: 21, common_pid: 2304 } hitcount: 2
2468{ lat: 22, common_pid: 2302 } hitcount: 5
2469{ lat: 22, common_pid: 2303 } hitcount: 1
2470{ lat: 22, common_pid: 2306 } hitcount: 3
2471{ lat: 22, common_pid: 2301 } hitcount: 2
2472{ lat: 22, common_pid: 2300 } hitcount: 1
2473{ lat: 22, common_pid: 2299 } hitcount: 1
2474{ lat: 22, common_pid: 2305 } hitcount: 1
2475{ lat: 22, common_pid: 2304 } hitcount: 1
2476{ lat: 23, common_pid: 2299 } hitcount: 1
2477{ lat: 23, common_pid: 2306 } hitcount: 2
2478{ lat: 23, common_pid: 2302 } hitcount: 6
2479{ lat: 24, common_pid: 2302 } hitcount: 3
2480{ lat: 24, common_pid: 2300 } hitcount: 1
2481{ lat: 24, common_pid: 2306 } hitcount: 2
2482{ lat: 24, common_pid: 2305 } hitcount: 1
2483{ lat: 24, common_pid: 2299 } hitcount: 1
2484{ lat: 25, common_pid: 2300 } hitcount: 1
2485{ lat: 25, common_pid: 2302 } hitcount: 4
2486{ lat: 26, common_pid: 2302 } hitcount: 2
2487{ lat: 27, common_pid: 2305 } hitcount: 1
2488{ lat: 27, common_pid: 2300 } hitcount: 1
2489{ lat: 27, common_pid: 2302 } hitcount: 3
2490{ lat: 28, common_pid: 2306 } hitcount: 1
2491{ lat: 28, common_pid: 2302 } hitcount: 4
2492{ lat: 29, common_pid: 2302 } hitcount: 1
2493{ lat: 29, common_pid: 2300 } hitcount: 2
2494{ lat: 29, common_pid: 2306 } hitcount: 1
2495{ lat: 29, common_pid: 2304 } hitcount: 1
2496{ lat: 30, common_pid: 2302 } hitcount: 4
2497{ lat: 31, common_pid: 2302 } hitcount: 6
2498{ lat: 32, common_pid: 2302 } hitcount: 1
2499{ lat: 33, common_pid: 2299 } hitcount: 1
2500{ lat: 33, common_pid: 2302 } hitcount: 3
2501{ lat: 34, common_pid: 2302 } hitcount: 2
2502{ lat: 35, common_pid: 2302 } hitcount: 1
2503{ lat: 35, common_pid: 2304 } hitcount: 1
2504{ lat: 36, common_pid: 2302 } hitcount: 4
2505{ lat: 37, common_pid: 2302 } hitcount: 6
2506{ lat: 38, common_pid: 2302 } hitcount: 2
2507{ lat: 39, common_pid: 2302 } hitcount: 2
2508{ lat: 39, common_pid: 2304 } hitcount: 1
2509{ lat: 40, common_pid: 2304 } hitcount: 2
2510{ lat: 40, common_pid: 2302 } hitcount: 5
2511{ lat: 41, common_pid: 2304 } hitcount: 1
2512{ lat: 41, common_pid: 2302 } hitcount: 8
2513{ lat: 42, common_pid: 2302 } hitcount: 6
2514{ lat: 42, common_pid: 2304 } hitcount: 1
2515{ lat: 43, common_pid: 2302 } hitcount: 3
2516{ lat: 43, common_pid: 2304 } hitcount: 4
2517{ lat: 44, common_pid: 2302 } hitcount: 6
2518{ lat: 45, common_pid: 2302 } hitcount: 5
2519{ lat: 46, common_pid: 2302 } hitcount: 5
2520{ lat: 47, common_pid: 2302 } hitcount: 7
2521{ lat: 48, common_pid: 2301 } hitcount: 1
2522{ lat: 48, common_pid: 2302 } hitcount: 9
2523{ lat: 49, common_pid: 2302 } hitcount: 3
2524{ lat: 50, common_pid: 2302 } hitcount: 1
2525{ lat: 50, common_pid: 2301 } hitcount: 1
2526{ lat: 51, common_pid: 2302 } hitcount: 2
2527{ lat: 51, common_pid: 2301 } hitcount: 1
2528{ lat: 61, common_pid: 2302 } hitcount: 1
2529{ lat: 110, common_pid: 2302 } hitcount: 1
2530
2531Totals:
2532 Hits: 89565
2533 Entries: 158
2534 Dropped: 0
2535
2536This doesn't tell us any information about how late cyclictest may have
2537woken up, but it does show us a nice histogram of how long it took from
2538the time that cyclictest was woken to the time it made it into user space.
generated by cgit v1.2.2 (git 2.25.0) at 2026-01-10 04:19:26 -0500