Linux kernel mirror (for testing) git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git
kernel os linux

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}
...

+933 -65
+5 -1
Documentation/trace/events.rst
··· 338 338 339 339 The syntax for event triggers is roughly based on the syntax for 340 340 set_ftrace_filter 'ftrace filter commands' (see the 'Filter commands' 341 - section of Documentation/trace/ftrace.txt), but there are major 341 + section of Documentation/trace/ftrace.rst), but there are major 342 342 differences and the implementation isn't currently tied to it in any 343 343 way, so beware about making generalizations between the two. 344 + 345 + Note: 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 344 348 345 349 6.1 Expression syntax 346 350 ---------------------
+5
Documentation/trace/ftrace.rst
··· 512 512 513 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 520 trace_marker_raw: 516 521 517 522 This is similar to trace_marker above, but is meant for for binary data
+544 -1
Documentation/trace/histogram.txt
··· 1604 1604 Entries: 7 1605 1605 Dropped: 0 1606 1606 1607 - 1608 1607 2.2 Inter-event hist triggers 1609 1608 ----------------------------- 1610 1609 ··· 1992 1993 Hits: 12970 1993 1994 Entries: 2 1994 1995 Dropped: 0 1996 + 1997 + 3. User space creating a trigger 1998 + -------------------------------- 1999 + 2000 + Writing into /sys/kernel/tracing/trace_marker writes into the ftrace 2001 + ring buffer. This can also act like an event, by writing into the trigger 2002 + file located in /sys/kernel/tracing/events/ftrace/print/ 2003 + 2004 + Modifying cyclictest to write into the trace_marker file before it sleeps 2005 + and after it wakes up, something like this: 2006 + 2007 + static void traceputs(char *str) 2008 + { 2009 + /* tracemark_fd is the trace_marker file descriptor */ 2010 + if (tracemark_fd < 0) 2011 + return; 2012 + /* write the tracemark message */ 2013 + write(tracemark_fd, str, strlen(str)); 2014 + } 2015 + 2016 + And later add something like: 2017 + 2018 + traceputs("start"); 2019 + clock_nanosleep(...); 2020 + traceputs("end"); 2021 + 2022 + We can make a histogram from this: 2023 + 2024 + # cd /sys/kernel/tracing 2025 + # echo 'latency u64 lat' > synthetic_events 2026 + # echo 'hist:keys=common_pid:ts0=common_timestamp.usecs if buf == "start"' > events/ftrace/print/trigger 2027 + # echo 'hist:keys=common_pid:lat=common_timestamp.usecs-$ts0:onmatch(ftrace.print).latency($lat) if buf == "end"' >> events/ftrace/print/trigger 2028 + # echo 'hist:keys=lat,common_pid:sort=lat' > events/synthetic/latency/trigger 2029 + 2030 + The above created a synthetic event called "latency" and two histograms 2031 + against the trace_marker, one gets triggered when "start" is written into the 2032 + trace_marker file and the other when "end" is written. If the pids match, then 2033 + it will call the "latency" synthetic event with the calculated latency as its 2034 + parameter. Finally, a histogram is added to the latency synthetic event to 2035 + record the calculated latency along with the pid. 2036 + 2037 + Now running cyclictest with: 2038 + 2039 + # ./cyclictest -p80 -d0 -i250 -n -a -t --tracemark -b 1000 2040 + 2041 + -p80 : run threads at priority 80 2042 + -d0 : have all threads run at the same interval 2043 + -i250 : start the interval at 250 microseconds (all threads will do this) 2044 + -n : sleep with nanosleep 2045 + -a : affine all threads to a separate CPU 2046 + -t : one thread per available CPU 2047 + --tracemark : enable trace mark writing 2048 + -b 1000 : stop if any latency is greater than 1000 microseconds 2049 + 2050 + Note, the -b 1000 is used just to make --tracemark available. 2051 + 2052 + Then we can see the histogram created by this with: 2053 + 2054 + # cat events/synthetic/latency/hist 2055 + # event histogram 2056 + # 2057 + # trigger info: hist:keys=lat,common_pid:vals=hitcount:sort=lat:size=2048 [active] 2058 + # 2059 + 2060 + { lat: 107, common_pid: 2039 } hitcount: 1 2061 + { lat: 122, common_pid: 2041 } hitcount: 1 2062 + { lat: 166, common_pid: 2039 } hitcount: 1 2063 + { lat: 174, common_pid: 2039 } hitcount: 1 2064 + { lat: 194, common_pid: 2041 } hitcount: 1 2065 + { lat: 196, common_pid: 2036 } hitcount: 1 2066 + { lat: 197, common_pid: 2038 } hitcount: 1 2067 + { lat: 198, common_pid: 2039 } hitcount: 1 2068 + { lat: 199, common_pid: 2039 } hitcount: 1 2069 + { lat: 200, common_pid: 2041 } hitcount: 1 2070 + { lat: 201, common_pid: 2039 } hitcount: 2 2071 + { lat: 202, common_pid: 2038 } hitcount: 1 2072 + { lat: 202, common_pid: 2043 } hitcount: 1 2073 + { lat: 203, common_pid: 2039 } hitcount: 1 2074 + { lat: 203, common_pid: 2036 } hitcount: 1 2075 + { lat: 203, common_pid: 2041 } hitcount: 1 2076 + { lat: 206, common_pid: 2038 } hitcount: 2 2077 + { lat: 207, common_pid: 2039 } hitcount: 1 2078 + { lat: 207, common_pid: 2036 } hitcount: 1 2079 + { lat: 208, common_pid: 2040 } hitcount: 1 2080 + { lat: 209, common_pid: 2043 } hitcount: 1 2081 + { lat: 210, common_pid: 2039 } hitcount: 1 2082 + { lat: 211, common_pid: 2039 } hitcount: 4 2083 + { lat: 212, common_pid: 2043 } hitcount: 1 2084 + { lat: 212, common_pid: 2039 } hitcount: 2 2085 + { lat: 213, common_pid: 2039 } hitcount: 1 2086 + { lat: 214, common_pid: 2038 } hitcount: 1 2087 + { lat: 214, common_pid: 2039 } hitcount: 2 2088 + { lat: 214, common_pid: 2042 } hitcount: 1 2089 + { lat: 215, common_pid: 2039 } hitcount: 1 2090 + { lat: 217, common_pid: 2036 } hitcount: 1 2091 + { lat: 217, common_pid: 2040 } hitcount: 1 2092 + { lat: 217, common_pid: 2039 } hitcount: 1 2093 + { lat: 218, common_pid: 2039 } hitcount: 6 2094 + { lat: 219, common_pid: 2039 } hitcount: 9 2095 + { lat: 220, common_pid: 2039 } hitcount: 11 2096 + { lat: 221, common_pid: 2039 } hitcount: 5 2097 + { lat: 221, common_pid: 2042 } hitcount: 1 2098 + { lat: 222, common_pid: 2039 } hitcount: 7 2099 + { lat: 223, common_pid: 2036 } hitcount: 1 2100 + { lat: 223, common_pid: 2039 } hitcount: 3 2101 + { lat: 224, common_pid: 2039 } hitcount: 4 2102 + { lat: 224, common_pid: 2037 } hitcount: 1 2103 + { lat: 224, common_pid: 2036 } hitcount: 2 2104 + { lat: 225, common_pid: 2039 } hitcount: 5 2105 + { lat: 225, common_pid: 2042 } hitcount: 1 2106 + { lat: 226, common_pid: 2039 } hitcount: 7 2107 + { lat: 226, common_pid: 2036 } hitcount: 4 2108 + { lat: 227, common_pid: 2039 } hitcount: 6 2109 + { lat: 227, common_pid: 2036 } hitcount: 12 2110 + { lat: 227, common_pid: 2043 } hitcount: 1 2111 + { lat: 228, common_pid: 2039 } hitcount: 7 2112 + { lat: 228, common_pid: 2036 } hitcount: 14 2113 + { lat: 229, common_pid: 2039 } hitcount: 9 2114 + { lat: 229, common_pid: 2036 } hitcount: 8 2115 + { lat: 229, common_pid: 2038 } hitcount: 1 2116 + { lat: 230, common_pid: 2039 } hitcount: 11 2117 + { lat: 230, common_pid: 2036 } hitcount: 6 2118 + { lat: 230, common_pid: 2043 } hitcount: 1 2119 + { lat: 230, common_pid: 2042 } hitcount: 2 2120 + { lat: 231, common_pid: 2041 } hitcount: 1 2121 + { lat: 231, common_pid: 2036 } hitcount: 6 2122 + { lat: 231, common_pid: 2043 } hitcount: 1 2123 + { lat: 231, common_pid: 2039 } hitcount: 8 2124 + { lat: 232, common_pid: 2037 } hitcount: 1 2125 + { lat: 232, common_pid: 2039 } hitcount: 6 2126 + { lat: 232, common_pid: 2040 } hitcount: 2 2127 + { lat: 232, common_pid: 2036 } hitcount: 5 2128 + { lat: 232, common_pid: 2043 } hitcount: 1 2129 + { lat: 233, common_pid: 2036 } hitcount: 5 2130 + { lat: 233, common_pid: 2039 } hitcount: 11 2131 + { lat: 234, common_pid: 2039 } hitcount: 4 2132 + { lat: 234, common_pid: 2038 } hitcount: 2 2133 + { lat: 234, common_pid: 2043 } hitcount: 2 2134 + { lat: 234, common_pid: 2036 } hitcount: 11 2135 + { lat: 234, common_pid: 2040 } hitcount: 1 2136 + { lat: 235, common_pid: 2037 } hitcount: 2 2137 + { lat: 235, common_pid: 2036 } hitcount: 8 2138 + { lat: 235, common_pid: 2043 } hitcount: 2 2139 + { lat: 235, common_pid: 2039 } hitcount: 5 2140 + { lat: 235, common_pid: 2042 } hitcount: 2 2141 + { lat: 235, common_pid: 2040 } hitcount: 4 2142 + { lat: 235, common_pid: 2041 } hitcount: 1 2143 + { lat: 236, common_pid: 2036 } hitcount: 7 2144 + { lat: 236, common_pid: 2037 } hitcount: 1 2145 + { lat: 236, common_pid: 2041 } hitcount: 5 2146 + { lat: 236, common_pid: 2039 } hitcount: 3 2147 + { lat: 236, common_pid: 2043 } hitcount: 9 2148 + { lat: 236, common_pid: 2040 } hitcount: 7 2149 + { lat: 237, common_pid: 2037 } hitcount: 1 2150 + { lat: 237, common_pid: 2040 } hitcount: 1 2151 + { lat: 237, common_pid: 2036 } hitcount: 9 2152 + { lat: 237, common_pid: 2039 } hitcount: 3 2153 + { lat: 237, common_pid: 2043 } hitcount: 8 2154 + { lat: 237, common_pid: 2042 } hitcount: 2 2155 + { lat: 237, common_pid: 2041 } hitcount: 2 2156 + { lat: 238, common_pid: 2043 } hitcount: 10 2157 + { lat: 238, common_pid: 2040 } hitcount: 1 2158 + { lat: 238, common_pid: 2037 } hitcount: 9 2159 + { lat: 238, common_pid: 2038 } hitcount: 1 2160 + { lat: 238, common_pid: 2039 } hitcount: 1 2161 + { lat: 238, common_pid: 2042 } hitcount: 3 2162 + { lat: 238, common_pid: 2036 } hitcount: 7 2163 + { lat: 239, common_pid: 2041 } hitcount: 1 2164 + { lat: 239, common_pid: 2043 } hitcount: 11 2165 + { lat: 239, common_pid: 2037 } hitcount: 11 2166 + { lat: 239, common_pid: 2038 } hitcount: 6 2167 + { lat: 239, common_pid: 2036 } hitcount: 7 2168 + { lat: 239, common_pid: 2040 } hitcount: 1 2169 + { lat: 239, common_pid: 2042 } hitcount: 9 2170 + { lat: 240, common_pid: 2037 } hitcount: 29 2171 + { lat: 240, common_pid: 2043 } hitcount: 15 2172 + { lat: 240, common_pid: 2040 } hitcount: 44 2173 + { lat: 240, common_pid: 2039 } hitcount: 1 2174 + { lat: 240, common_pid: 2041 } hitcount: 2 2175 + { lat: 240, common_pid: 2038 } hitcount: 1 2176 + { lat: 240, common_pid: 2036 } hitcount: 10 2177 + { lat: 240, common_pid: 2042 } hitcount: 13 2178 + { lat: 241, common_pid: 2036 } hitcount: 21 2179 + { lat: 241, common_pid: 2041 } hitcount: 36 2180 + { lat: 241, common_pid: 2037 } hitcount: 34 2181 + { lat: 241, common_pid: 2042 } hitcount: 14 2182 + { lat: 241, common_pid: 2040 } hitcount: 94 2183 + { lat: 241, common_pid: 2039 } hitcount: 12 2184 + { lat: 241, common_pid: 2038 } hitcount: 2 2185 + { lat: 241, common_pid: 2043 } hitcount: 28 2186 + { lat: 242, common_pid: 2040 } hitcount: 109 2187 + { lat: 242, common_pid: 2041 } hitcount: 506 2188 + { lat: 242, common_pid: 2039 } hitcount: 155 2189 + { lat: 242, common_pid: 2042 } hitcount: 21 2190 + { lat: 242, common_pid: 2037 } hitcount: 52 2191 + { lat: 242, common_pid: 2043 } hitcount: 21 2192 + { lat: 242, common_pid: 2036 } hitcount: 16 2193 + { lat: 242, common_pid: 2038 } hitcount: 156 2194 + { lat: 243, common_pid: 2037 } hitcount: 46 2195 + { lat: 243, common_pid: 2039 } hitcount: 40 2196 + { lat: 243, common_pid: 2042 } hitcount: 119 2197 + { lat: 243, common_pid: 2041 } hitcount: 611 2198 + { lat: 243, common_pid: 2036 } hitcount: 69 2199 + { lat: 243, common_pid: 2038 } hitcount: 784 2200 + { lat: 243, common_pid: 2040 } hitcount: 323 2201 + { lat: 243, common_pid: 2043 } hitcount: 14 2202 + { lat: 244, common_pid: 2043 } hitcount: 35 2203 + { lat: 244, common_pid: 2042 } hitcount: 305 2204 + { lat: 244, common_pid: 2039 } hitcount: 8 2205 + { lat: 244, common_pid: 2040 } hitcount: 4515 2206 + { lat: 244, common_pid: 2038 } hitcount: 371 2207 + { lat: 244, common_pid: 2037 } hitcount: 31 2208 + { lat: 244, common_pid: 2036 } hitcount: 114 2209 + { lat: 244, common_pid: 2041 } hitcount: 3396 2210 + { lat: 245, common_pid: 2036 } hitcount: 700 2211 + { lat: 245, common_pid: 2041 } hitcount: 2772 2212 + { lat: 245, common_pid: 2037 } hitcount: 268 2213 + { lat: 245, common_pid: 2039 } hitcount: 472 2214 + { lat: 245, common_pid: 2038 } hitcount: 2758 2215 + { lat: 245, common_pid: 2042 } hitcount: 3833 2216 + { lat: 245, common_pid: 2040 } hitcount: 3105 2217 + { lat: 245, common_pid: 2043 } hitcount: 645 2218 + { lat: 246, common_pid: 2038 } hitcount: 3451 2219 + { lat: 246, common_pid: 2041 } hitcount: 142 2220 + { lat: 246, common_pid: 2037 } hitcount: 5101 2221 + { lat: 246, common_pid: 2040 } hitcount: 68 2222 + { lat: 246, common_pid: 2043 } hitcount: 5099 2223 + { lat: 246, common_pid: 2039 } hitcount: 5608 2224 + { lat: 246, common_pid: 2042 } hitcount: 3723 2225 + { lat: 246, common_pid: 2036 } hitcount: 4738 2226 + { lat: 247, common_pid: 2042 } hitcount: 312 2227 + { lat: 247, common_pid: 2043 } hitcount: 2385 2228 + { lat: 247, common_pid: 2041 } hitcount: 452 2229 + { lat: 247, common_pid: 2038 } hitcount: 792 2230 + { lat: 247, common_pid: 2040 } hitcount: 78 2231 + { lat: 247, common_pid: 2036 } hitcount: 2375 2232 + { lat: 247, common_pid: 2039 } hitcount: 1834 2233 + { lat: 247, common_pid: 2037 } hitcount: 2655 2234 + { lat: 248, common_pid: 2037 } hitcount: 36 2235 + { lat: 248, common_pid: 2042 } hitcount: 11 2236 + { lat: 248, common_pid: 2038 } hitcount: 122 2237 + { lat: 248, common_pid: 2036 } hitcount: 135 2238 + { lat: 248, common_pid: 2039 } hitcount: 26 2239 + { lat: 248, common_pid: 2041 } hitcount: 503 2240 + { lat: 248, common_pid: 2043 } hitcount: 66 2241 + { lat: 248, common_pid: 2040 } hitcount: 46 2242 + { lat: 249, common_pid: 2037 } hitcount: 29 2243 + { lat: 249, common_pid: 2038 } hitcount: 1 2244 + { lat: 249, common_pid: 2043 } hitcount: 29 2245 + { lat: 249, common_pid: 2039 } hitcount: 8 2246 + { lat: 249, common_pid: 2042 } hitcount: 56 2247 + { lat: 249, common_pid: 2040 } hitcount: 27 2248 + { lat: 249, common_pid: 2041 } hitcount: 11 2249 + { lat: 249, common_pid: 2036 } hitcount: 27 2250 + { lat: 250, common_pid: 2038 } hitcount: 1 2251 + { lat: 250, common_pid: 2036 } hitcount: 30 2252 + { lat: 250, common_pid: 2040 } hitcount: 19 2253 + { lat: 250, common_pid: 2043 } hitcount: 22 2254 + { lat: 250, common_pid: 2042 } hitcount: 20 2255 + { lat: 250, common_pid: 2041 } hitcount: 1 2256 + { lat: 250, common_pid: 2039 } hitcount: 6 2257 + { lat: 250, common_pid: 2037 } hitcount: 48 2258 + { lat: 251, common_pid: 2037 } hitcount: 43 2259 + { lat: 251, common_pid: 2039 } hitcount: 1 2260 + { lat: 251, common_pid: 2036 } hitcount: 12 2261 + { lat: 251, common_pid: 2042 } hitcount: 2 2262 + { lat: 251, common_pid: 2041 } hitcount: 1 2263 + { lat: 251, common_pid: 2043 } hitcount: 15 2264 + { lat: 251, common_pid: 2040 } hitcount: 3 2265 + { lat: 252, common_pid: 2040 } hitcount: 1 2266 + { lat: 252, common_pid: 2036 } hitcount: 12 2267 + { lat: 252, common_pid: 2037 } hitcount: 21 2268 + { lat: 252, common_pid: 2043 } hitcount: 14 2269 + { lat: 253, common_pid: 2037 } hitcount: 21 2270 + { lat: 253, common_pid: 2039 } hitcount: 2 2271 + { lat: 253, common_pid: 2036 } hitcount: 9 2272 + { lat: 253, common_pid: 2043 } hitcount: 6 2273 + { lat: 253, common_pid: 2040 } hitcount: 1 2274 + { lat: 254, common_pid: 2036 } hitcount: 8 2275 + { lat: 254, common_pid: 2043 } hitcount: 3 2276 + { lat: 254, common_pid: 2041 } hitcount: 1 2277 + { lat: 254, common_pid: 2042 } hitcount: 1 2278 + { lat: 254, common_pid: 2039 } hitcount: 1 2279 + { lat: 254, common_pid: 2037 } hitcount: 12 2280 + { lat: 255, common_pid: 2043 } hitcount: 1 2281 + { lat: 255, common_pid: 2037 } hitcount: 2 2282 + { lat: 255, common_pid: 2036 } hitcount: 2 2283 + { lat: 255, common_pid: 2039 } hitcount: 8 2284 + { lat: 256, common_pid: 2043 } hitcount: 1 2285 + { lat: 256, common_pid: 2036 } hitcount: 4 2286 + { lat: 256, common_pid: 2039 } hitcount: 6 2287 + { lat: 257, common_pid: 2039 } hitcount: 5 2288 + { lat: 257, common_pid: 2036 } hitcount: 4 2289 + { lat: 258, common_pid: 2039 } hitcount: 5 2290 + { lat: 258, common_pid: 2036 } hitcount: 2 2291 + { lat: 259, common_pid: 2036 } hitcount: 7 2292 + { lat: 259, common_pid: 2039 } hitcount: 7 2293 + { lat: 260, common_pid: 2036 } hitcount: 8 2294 + { lat: 260, common_pid: 2039 } hitcount: 6 2295 + { lat: 261, common_pid: 2036 } hitcount: 5 2296 + { lat: 261, common_pid: 2039 } hitcount: 7 2297 + { lat: 262, common_pid: 2039 } hitcount: 5 2298 + { lat: 262, common_pid: 2036 } hitcount: 5 2299 + { lat: 263, common_pid: 2039 } hitcount: 7 2300 + { lat: 263, common_pid: 2036 } hitcount: 7 2301 + { lat: 264, common_pid: 2039 } hitcount: 9 2302 + { lat: 264, common_pid: 2036 } hitcount: 9 2303 + { lat: 265, common_pid: 2036 } hitcount: 5 2304 + { lat: 265, common_pid: 2039 } hitcount: 1 2305 + { lat: 266, common_pid: 2036 } hitcount: 1 2306 + { lat: 266, common_pid: 2039 } hitcount: 3 2307 + { lat: 267, common_pid: 2036 } hitcount: 1 2308 + { lat: 267, common_pid: 2039 } hitcount: 3 2309 + { lat: 268, common_pid: 2036 } hitcount: 1 2310 + { lat: 268, common_pid: 2039 } hitcount: 6 2311 + { lat: 269, common_pid: 2036 } hitcount: 1 2312 + { lat: 269, common_pid: 2043 } hitcount: 1 2313 + { lat: 269, common_pid: 2039 } hitcount: 2 2314 + { lat: 270, common_pid: 2040 } hitcount: 1 2315 + { lat: 270, common_pid: 2039 } hitcount: 6 2316 + { lat: 271, common_pid: 2041 } hitcount: 1 2317 + { lat: 271, common_pid: 2039 } hitcount: 5 2318 + { lat: 272, common_pid: 2039 } hitcount: 10 2319 + { lat: 273, common_pid: 2039 } hitcount: 8 2320 + { lat: 274, common_pid: 2039 } hitcount: 2 2321 + { lat: 275, common_pid: 2039 } hitcount: 1 2322 + { lat: 276, common_pid: 2039 } hitcount: 2 2323 + { lat: 276, common_pid: 2037 } hitcount: 1 2324 + { lat: 276, common_pid: 2038 } hitcount: 1 2325 + { lat: 277, common_pid: 2039 } hitcount: 1 2326 + { lat: 277, common_pid: 2042 } hitcount: 1 2327 + { lat: 278, common_pid: 2039 } hitcount: 1 2328 + { lat: 279, common_pid: 2039 } hitcount: 4 2329 + { lat: 279, common_pid: 2043 } hitcount: 1 2330 + { lat: 280, common_pid: 2039 } hitcount: 3 2331 + { lat: 283, common_pid: 2036 } hitcount: 2 2332 + { lat: 284, common_pid: 2039 } hitcount: 1 2333 + { lat: 284, common_pid: 2043 } hitcount: 1 2334 + { lat: 288, common_pid: 2039 } hitcount: 1 2335 + { lat: 289, common_pid: 2039 } hitcount: 1 2336 + { lat: 300, common_pid: 2039 } hitcount: 1 2337 + { lat: 384, common_pid: 2039 } hitcount: 1 2338 + 2339 + Totals: 2340 + Hits: 67625 2341 + Entries: 278 2342 + Dropped: 0 2343 + 2344 + Note, the writes are around the sleep, so ideally they will all be of 250 2345 + microseconds. If you are wondering how there are several that are under 2346 + 250 microseconds, that is because the way cyclictest works, is if one 2347 + iteration comes in late, the next one will set the timer to wake up less that 2348 + 250. That is, if an iteration came in 50 microseconds late, the next wake up 2349 + will be at 200 microseconds. 2350 + 2351 + But this could easily be done in userspace. To make this even more 2352 + interesting, we can mix the histogram between events that happened in the 2353 + kernel with trace_marker. 2354 + 2355 + # cd /sys/kernel/tracing 2356 + # echo 'latency u64 lat' > synthetic_events 2357 + # echo 'hist:keys=pid:ts0=common_timestamp.usecs' > events/sched/sched_waking/trigger 2358 + # echo 'hist:keys=common_pid:lat=common_timestamp.usecs-$ts0:onmatch(sched.sched_waking).latency($lat) if buf == "end"' > events/ftrace/print/trigger 2359 + # echo 'hist:keys=lat,common_pid:sort=lat' > events/synthetic/latency/trigger 2360 + 2361 + The difference this time is that instead of using the trace_marker to start 2362 + the latency, the sched_waking event is used, matching the common_pid for the 2363 + trace_marker write with the pid that is being woken by sched_waking. 2364 + 2365 + After running cyclictest again with the same parameters, we now have: 2366 + 2367 + # cat events/synthetic/latency/hist 2368 + # event histogram 2369 + # 2370 + # trigger info: hist:keys=lat,common_pid:vals=hitcount:sort=lat:size=2048 [active] 2371 + # 2372 + 2373 + { lat: 7, common_pid: 2302 } hitcount: 640 2374 + { lat: 7, common_pid: 2299 } hitcount: 42 2375 + { lat: 7, common_pid: 2303 } hitcount: 18 2376 + { lat: 7, common_pid: 2305 } hitcount: 166 2377 + { lat: 7, common_pid: 2306 } hitcount: 1 2378 + { lat: 7, common_pid: 2301 } hitcount: 91 2379 + { lat: 7, common_pid: 2300 } hitcount: 17 2380 + { lat: 8, common_pid: 2303 } hitcount: 8296 2381 + { lat: 8, common_pid: 2304 } hitcount: 6864 2382 + { lat: 8, common_pid: 2305 } hitcount: 9464 2383 + { lat: 8, common_pid: 2301 } hitcount: 9213 2384 + { lat: 8, common_pid: 2306 } hitcount: 6246 2385 + { lat: 8, common_pid: 2302 } hitcount: 8797 2386 + { lat: 8, common_pid: 2299 } hitcount: 8771 2387 + { lat: 8, common_pid: 2300 } hitcount: 8119 2388 + { lat: 9, common_pid: 2305 } hitcount: 1519 2389 + { lat: 9, common_pid: 2299 } hitcount: 2346 2390 + { lat: 9, common_pid: 2303 } hitcount: 2841 2391 + { lat: 9, common_pid: 2301 } hitcount: 1846 2392 + { lat: 9, common_pid: 2304 } hitcount: 3861 2393 + { lat: 9, common_pid: 2302 } hitcount: 1210 2394 + { lat: 9, common_pid: 2300 } hitcount: 2762 2395 + { lat: 9, common_pid: 2306 } hitcount: 4247 2396 + { lat: 10, common_pid: 2299 } hitcount: 16 2397 + { lat: 10, common_pid: 2306 } hitcount: 333 2398 + { lat: 10, common_pid: 2303 } hitcount: 16 2399 + { lat: 10, common_pid: 2304 } hitcount: 168 2400 + { lat: 10, common_pid: 2302 } hitcount: 240 2401 + { lat: 10, common_pid: 2301 } hitcount: 28 2402 + { lat: 10, common_pid: 2300 } hitcount: 95 2403 + { lat: 10, common_pid: 2305 } hitcount: 18 2404 + { lat: 11, common_pid: 2303 } hitcount: 5 2405 + { lat: 11, common_pid: 2305 } hitcount: 8 2406 + { lat: 11, common_pid: 2306 } hitcount: 221 2407 + { lat: 11, common_pid: 2302 } hitcount: 76 2408 + { lat: 11, common_pid: 2304 } hitcount: 26 2409 + { lat: 11, common_pid: 2300 } hitcount: 125 2410 + { lat: 11, common_pid: 2299 } hitcount: 2 2411 + { lat: 12, common_pid: 2305 } hitcount: 3 2412 + { lat: 12, common_pid: 2300 } hitcount: 6 2413 + { lat: 12, common_pid: 2306 } hitcount: 90 2414 + { lat: 12, common_pid: 2302 } hitcount: 4 2415 + { lat: 12, common_pid: 2303 } hitcount: 1 2416 + { lat: 12, common_pid: 2304 } hitcount: 122 2417 + { lat: 13, common_pid: 2300 } hitcount: 12 2418 + { lat: 13, common_pid: 2301 } hitcount: 1 2419 + { lat: 13, common_pid: 2306 } hitcount: 32 2420 + { lat: 13, common_pid: 2302 } hitcount: 5 2421 + { lat: 13, common_pid: 2305 } hitcount: 1 2422 + { lat: 13, common_pid: 2303 } hitcount: 1 2423 + { lat: 13, common_pid: 2304 } hitcount: 61 2424 + { lat: 14, common_pid: 2303 } hitcount: 4 2425 + { lat: 14, common_pid: 2306 } hitcount: 5 2426 + { lat: 14, common_pid: 2305 } hitcount: 4 2427 + { lat: 14, common_pid: 2304 } hitcount: 62 2428 + { lat: 14, common_pid: 2302 } hitcount: 19 2429 + { lat: 14, common_pid: 2300 } hitcount: 33 2430 + { lat: 14, common_pid: 2299 } hitcount: 1 2431 + { lat: 14, common_pid: 2301 } hitcount: 4 2432 + { lat: 15, common_pid: 2305 } hitcount: 1 2433 + { lat: 15, common_pid: 2302 } hitcount: 25 2434 + { lat: 15, common_pid: 2300 } hitcount: 11 2435 + { lat: 15, common_pid: 2299 } hitcount: 5 2436 + { lat: 15, common_pid: 2301 } hitcount: 1 2437 + { lat: 15, common_pid: 2304 } hitcount: 8 2438 + { lat: 15, common_pid: 2303 } hitcount: 1 2439 + { lat: 15, common_pid: 2306 } hitcount: 6 2440 + { lat: 16, common_pid: 2302 } hitcount: 31 2441 + { lat: 16, common_pid: 2306 } hitcount: 3 2442 + { lat: 16, common_pid: 2300 } hitcount: 5 2443 + { lat: 17, common_pid: 2302 } hitcount: 6 2444 + { lat: 17, common_pid: 2303 } hitcount: 1 2445 + { lat: 18, common_pid: 2304 } hitcount: 1 2446 + { lat: 18, common_pid: 2302 } hitcount: 8 2447 + { lat: 18, common_pid: 2299 } hitcount: 1 2448 + { lat: 18, common_pid: 2301 } hitcount: 1 2449 + { lat: 19, common_pid: 2303 } hitcount: 4 2450 + { lat: 19, common_pid: 2304 } hitcount: 5 2451 + { lat: 19, common_pid: 2302 } hitcount: 4 2452 + { lat: 19, common_pid: 2299 } hitcount: 3 2453 + { lat: 19, common_pid: 2306 } hitcount: 1 2454 + { lat: 19, common_pid: 2300 } hitcount: 4 2455 + { lat: 19, common_pid: 2305 } hitcount: 5 2456 + { lat: 20, common_pid: 2299 } hitcount: 2 2457 + { lat: 20, common_pid: 2302 } hitcount: 3 2458 + { lat: 20, common_pid: 2305 } hitcount: 1 2459 + { lat: 20, common_pid: 2300 } hitcount: 2 2460 + { lat: 20, common_pid: 2301 } hitcount: 2 2461 + { lat: 20, common_pid: 2303 } hitcount: 3 2462 + { lat: 21, common_pid: 2305 } hitcount: 1 2463 + { lat: 21, common_pid: 2299 } hitcount: 5 2464 + { lat: 21, common_pid: 2303 } hitcount: 4 2465 + { lat: 21, common_pid: 2302 } hitcount: 7 2466 + { lat: 21, common_pid: 2300 } hitcount: 1 2467 + { lat: 21, common_pid: 2301 } hitcount: 5 2468 + { lat: 21, common_pid: 2304 } hitcount: 2 2469 + { lat: 22, common_pid: 2302 } hitcount: 5 2470 + { lat: 22, common_pid: 2303 } hitcount: 1 2471 + { lat: 22, common_pid: 2306 } hitcount: 3 2472 + { lat: 22, common_pid: 2301 } hitcount: 2 2473 + { lat: 22, common_pid: 2300 } hitcount: 1 2474 + { lat: 22, common_pid: 2299 } hitcount: 1 2475 + { lat: 22, common_pid: 2305 } hitcount: 1 2476 + { lat: 22, common_pid: 2304 } hitcount: 1 2477 + { lat: 23, common_pid: 2299 } hitcount: 1 2478 + { lat: 23, common_pid: 2306 } hitcount: 2 2479 + { lat: 23, common_pid: 2302 } hitcount: 6 2480 + { lat: 24, common_pid: 2302 } hitcount: 3 2481 + { lat: 24, common_pid: 2300 } hitcount: 1 2482 + { lat: 24, common_pid: 2306 } hitcount: 2 2483 + { lat: 24, common_pid: 2305 } hitcount: 1 2484 + { lat: 24, common_pid: 2299 } hitcount: 1 2485 + { lat: 25, common_pid: 2300 } hitcount: 1 2486 + { lat: 25, common_pid: 2302 } hitcount: 4 2487 + { lat: 26, common_pid: 2302 } hitcount: 2 2488 + { lat: 27, common_pid: 2305 } hitcount: 1 2489 + { lat: 27, common_pid: 2300 } hitcount: 1 2490 + { lat: 27, common_pid: 2302 } hitcount: 3 2491 + { lat: 28, common_pid: 2306 } hitcount: 1 2492 + { lat: 28, common_pid: 2302 } hitcount: 4 2493 + { lat: 29, common_pid: 2302 } hitcount: 1 2494 + { lat: 29, common_pid: 2300 } hitcount: 2 2495 + { lat: 29, common_pid: 2306 } hitcount: 1 2496 + { lat: 29, common_pid: 2304 } hitcount: 1 2497 + { lat: 30, common_pid: 2302 } hitcount: 4 2498 + { lat: 31, common_pid: 2302 } hitcount: 6 2499 + { lat: 32, common_pid: 2302 } hitcount: 1 2500 + { lat: 33, common_pid: 2299 } hitcount: 1 2501 + { lat: 33, common_pid: 2302 } hitcount: 3 2502 + { lat: 34, common_pid: 2302 } hitcount: 2 2503 + { lat: 35, common_pid: 2302 } hitcount: 1 2504 + { lat: 35, common_pid: 2304 } hitcount: 1 2505 + { lat: 36, common_pid: 2302 } hitcount: 4 2506 + { lat: 37, common_pid: 2302 } hitcount: 6 2507 + { lat: 38, common_pid: 2302 } hitcount: 2 2508 + { lat: 39, common_pid: 2302 } hitcount: 2 2509 + { lat: 39, common_pid: 2304 } hitcount: 1 2510 + { lat: 40, common_pid: 2304 } hitcount: 2 2511 + { lat: 40, common_pid: 2302 } hitcount: 5 2512 + { lat: 41, common_pid: 2304 } hitcount: 1 2513 + { lat: 41, common_pid: 2302 } hitcount: 8 2514 + { lat: 42, common_pid: 2302 } hitcount: 6 2515 + { lat: 42, common_pid: 2304 } hitcount: 1 2516 + { lat: 43, common_pid: 2302 } hitcount: 3 2517 + { lat: 43, common_pid: 2304 } hitcount: 4 2518 + { lat: 44, common_pid: 2302 } hitcount: 6 2519 + { lat: 45, common_pid: 2302 } hitcount: 5 2520 + { lat: 46, common_pid: 2302 } hitcount: 5 2521 + { lat: 47, common_pid: 2302 } hitcount: 7 2522 + { lat: 48, common_pid: 2301 } hitcount: 1 2523 + { lat: 48, common_pid: 2302 } hitcount: 9 2524 + { lat: 49, common_pid: 2302 } hitcount: 3 2525 + { lat: 50, common_pid: 2302 } hitcount: 1 2526 + { lat: 50, common_pid: 2301 } hitcount: 1 2527 + { lat: 51, common_pid: 2302 } hitcount: 2 2528 + { lat: 51, common_pid: 2301 } hitcount: 1 2529 + { lat: 61, common_pid: 2302 } hitcount: 1 2530 + { lat: 110, common_pid: 2302 } hitcount: 1 2531 + 2532 + Totals: 2533 + Hits: 89565 2534 + Entries: 158 2535 + Dropped: 0 2536 + 2537 + This doesn't tell us any information about how late cyclictest may have 2538 + woken up, but it does show us a nice histogram of how long it took from 2539 + the time that cyclictest was woken to the time it made it into user space.
+1 -1
include/linux/compiler.h
··· 21 21 #define unlikely_notrace(x) __builtin_expect(!!(x), 0) 22 22 23 23 #define __branch_check__(x, expect, is_constant) ({ \ 24 - int ______r; \ 24 + long ______r; \ 25 25 static struct ftrace_likely_data \ 26 26 __attribute__((__aligned__(4))) \ 27 27 __attribute__((section("_ftrace_annotated_branch"))) \
+1 -1
include/linux/ring_buffer.h
··· 65 65 66 66 /* 67 67 * ring_buffer_discard_commit will remove an event that has not 68 - * ben committed yet. If this is used, then ring_buffer_unlock_commit 68 + * been committed yet. If this is used, then ring_buffer_unlock_commit 69 69 * must not be called on the discarded event. This function 70 70 * will try to remove the event from the ring buffer completely 71 71 * if another event has not been written after it.
+1 -2
include/linux/trace_events.h
··· 435 435 struct ring_buffer_event *event); 436 436 extern void 437 437 event_triggers_post_call(struct trace_event_file *file, 438 - enum event_trigger_type tt, 439 - void *rec, struct ring_buffer_event *event); 438 + enum event_trigger_type tt); 440 439 441 440 bool trace_event_ignore_this_pid(struct trace_event_file *trace_file); 442 441
+1
include/trace/trace_events.h
··· 422 422 do { \ 423 423 char *type_str = #type"["__stringify(len)"]"; \ 424 424 BUILD_BUG_ON(len > MAX_FILTER_STR_VAL); \ 425 + BUILD_BUG_ON(len <= 0); \ 425 426 ret = trace_define_field(event_call, type_str, #item, \ 426 427 offsetof(typeof(field), item), \ 427 428 sizeof(field.item), \
+10 -10
kernel/trace/ring_buffer.c
··· 809 809 * 810 810 * You can see, it is legitimate for the previous pointer of 811 811 * the head (or any page) not to point back to itself. But only 812 - * temporarially. 812 + * temporarily. 813 813 */ 814 814 815 815 #define RB_PAGE_NORMAL 0UL ··· 906 906 } 907 907 908 908 /* 909 - * rb_head_page_dactivate - clears head page ptr (for free list) 909 + * rb_head_page_deactivate - clears head page ptr (for free list) 910 910 */ 911 911 static void 912 912 rb_head_page_deactivate(struct ring_buffer_per_cpu *cpu_buffer) ··· 1780 1780 1781 1781 put_online_cpus(); 1782 1782 } else { 1783 - /* Make sure this CPU has been intitialized */ 1783 + /* Make sure this CPU has been initialized */ 1784 1784 if (!cpumask_test_cpu(cpu_id, buffer->cpumask)) 1785 1785 goto out; 1786 1786 ··· 2325 2325 2326 2326 /* 2327 2327 * If we need to add a timestamp, then we 2328 - * add it to the start of the resevered space. 2328 + * add it to the start of the reserved space. 2329 2329 */ 2330 2330 if (unlikely(info->add_timestamp)) { 2331 2331 bool abs = ring_buffer_time_stamp_abs(cpu_buffer->buffer); ··· 2681 2681 * ring_buffer_nest_start - Allow to trace while nested 2682 2682 * @buffer: The ring buffer to modify 2683 2683 * 2684 - * The ring buffer has a safty mechanism to prevent recursion. 2684 + * The ring buffer has a safety mechanism to prevent recursion. 2685 2685 * But there may be a case where a trace needs to be done while 2686 2686 * tracing something else. In this case, calling this function 2687 2687 * will allow this function to nest within a currently active ··· 2699 2699 preempt_disable_notrace(); 2700 2700 cpu = raw_smp_processor_id(); 2701 2701 cpu_buffer = buffer->buffers[cpu]; 2702 - /* This is the shift value for the above recusive locking */ 2702 + /* This is the shift value for the above recursive locking */ 2703 2703 cpu_buffer->nest += NESTED_BITS; 2704 2704 } 2705 2705 ··· 2718 2718 /* disabled by ring_buffer_nest_start() */ 2719 2719 cpu = raw_smp_processor_id(); 2720 2720 cpu_buffer = buffer->buffers[cpu]; 2721 - /* This is the shift value for the above recusive locking */ 2721 + /* This is the shift value for the above recursive locking */ 2722 2722 cpu_buffer->nest -= NESTED_BITS; 2723 2723 preempt_enable_notrace(); 2724 2724 } ··· 2907 2907 * @buffer: the ring buffer to reserve from 2908 2908 * @length: the length of the data to reserve (excluding event header) 2909 2909 * 2910 - * Returns a reseverd event on the ring buffer to copy directly to. 2910 + * Returns a reserved event on the ring buffer to copy directly to. 2911 2911 * The user of this interface will need to get the body to write into 2912 2912 * and can use the ring_buffer_event_data() interface. 2913 2913 * ··· 3009 3009 * This function lets the user discard an event in the ring buffer 3010 3010 * and then that event will not be read later. 3011 3011 * 3012 - * This function only works if it is called before the the item has been 3012 + * This function only works if it is called before the item has been 3013 3013 * committed. It will try to free the event from the ring buffer 3014 3014 * if another event has not been added behind it. 3015 3015 * ··· 4127 4127 * through the buffer. Memory is allocated, buffer recording 4128 4128 * is disabled, and the iterator pointer is returned to the caller. 4129 4129 * 4130 - * Disabling buffer recordng prevents the reading from being 4130 + * Disabling buffer recording prevents the reading from being 4131 4131 * corrupted. This is not a consuming read, so a producer is not 4132 4132 * expected. 4133 4133 *
+24 -10
kernel/trace/trace.c
··· 4395 4395 { 4396 4396 char *cmp; 4397 4397 int neg = 0; 4398 - int ret = -ENODEV; 4399 - int i; 4398 + int ret; 4400 4399 size_t orig_len = strlen(option); 4401 4400 4402 4401 cmp = strstrip(option); ··· 4407 4408 4408 4409 mutex_lock(&trace_types_lock); 4409 4410 4410 - for (i = 0; trace_options[i]; i++) { 4411 - if (strcmp(cmp, trace_options[i]) == 0) { 4412 - ret = set_tracer_flag(tr, 1 << i, !neg); 4413 - break; 4414 - } 4415 - } 4416 - 4411 + ret = match_string(trace_options, -1, cmp); 4417 4412 /* If no option could be set, test the specific tracer options */ 4418 - if (!trace_options[i]) 4413 + if (ret < 0) 4419 4414 ret = set_tracer_option(tr, cmp, neg); 4415 + else 4416 + ret = set_tracer_flag(tr, 1 << ret, !neg); 4420 4417 4421 4418 mutex_unlock(&trace_types_lock); 4422 4419 ··· 6069 6074 { 6070 6075 struct trace_array *tr = filp->private_data; 6071 6076 struct ring_buffer_event *event; 6077 + enum event_trigger_type tt = ETT_NONE; 6072 6078 struct ring_buffer *buffer; 6073 6079 struct print_entry *entry; 6074 6080 unsigned long irq_flags; ··· 6118 6122 written = cnt; 6119 6123 len = cnt; 6120 6124 6125 + if (tr->trace_marker_file && !list_empty(&tr->trace_marker_file->triggers)) { 6126 + /* do not add \n before testing triggers, but add \0 */ 6127 + entry->buf[cnt] = '\0'; 6128 + tt = event_triggers_call(tr->trace_marker_file, entry, event); 6129 + } 6130 + 6121 6131 if (entry->buf[cnt - 1] != '\n') { 6122 6132 entry->buf[cnt] = '\n'; 6123 6133 entry->buf[cnt + 1] = '\0'; ··· 6131 6129 entry->buf[cnt] = '\0'; 6132 6130 6133 6131 __buffer_unlock_commit(buffer, event); 6132 + 6133 + if (tt) 6134 + event_triggers_post_call(tr->trace_marker_file, tt); 6134 6135 6135 6136 if (written > 0) 6136 6137 *fpos += written; ··· 7901 7896 static void 7902 7897 init_tracer_tracefs(struct trace_array *tr, struct dentry *d_tracer) 7903 7898 { 7899 + struct trace_event_file *file; 7904 7900 int cpu; 7905 7901 7906 7902 trace_create_file("available_tracers", 0444, d_tracer, ··· 7933 7927 7934 7928 trace_create_file("trace_marker", 0220, d_tracer, 7935 7929 tr, &tracing_mark_fops); 7930 + 7931 + file = __find_event_file(tr, "ftrace", "print"); 7932 + if (file && file->dir) 7933 + trace_create_file("trigger", 0644, file->dir, file, 7934 + &event_trigger_fops); 7935 + tr->trace_marker_file = file; 7936 7936 7937 7937 trace_create_file("trace_marker_raw", 0220, d_tracer, 7938 7938 tr, &tracing_mark_raw_fops); ··· 8122 8110 d_tracer = tracing_init_dentry(); 8123 8111 if (IS_ERR(d_tracer)) 8124 8112 return 0; 8113 + 8114 + event_trace_init(); 8125 8115 8126 8116 init_tracer_tracefs(&global_trace, d_tracer); 8127 8117 ftrace_init_tracefs_toplevel(&global_trace, d_tracer);
+7 -2
kernel/trace/trace.h
··· 259 259 struct trace_options *topts; 260 260 struct list_head systems; 261 261 struct list_head events; 262 + struct trace_event_file *trace_marker_file; 262 263 cpumask_var_t tracing_cpumask; /* only trace on set CPUs */ 263 264 int ref; 264 265 #ifdef CONFIG_FUNCTION_TRACER ··· 1335 1334 trace_buffer_unlock_commit(file->tr, buffer, event, irq_flags, pc); 1336 1335 1337 1336 if (tt) 1338 - event_triggers_post_call(file, tt, entry, event); 1337 + event_triggers_post_call(file, tt); 1339 1338 } 1340 1339 1341 1340 /** ··· 1368 1367 irq_flags, pc, regs); 1369 1368 1370 1369 if (tt) 1371 - event_triggers_post_call(file, tt, entry, event); 1370 + event_triggers_post_call(file, tt); 1372 1371 } 1373 1372 1374 1373 #define FILTER_PRED_INVALID ((unsigned short)-1) ··· 1452 1451 extern void trace_event_enable_cmd_record(bool enable); 1453 1452 extern void trace_event_enable_tgid_record(bool enable); 1454 1453 1454 + extern int event_trace_init(void); 1455 1455 extern int event_trace_add_tracer(struct dentry *parent, struct trace_array *tr); 1456 1456 extern int event_trace_del_tracer(struct trace_array *tr); 1457 1457 1458 + extern struct trace_event_file *__find_event_file(struct trace_array *tr, 1459 + const char *system, 1460 + const char *event); 1458 1461 extern struct trace_event_file *find_event_file(struct trace_array *tr, 1459 1462 const char *system, 1460 1463 const char *event);
+4 -2
kernel/trace/trace_entries.h
··· 230 230 FILTER_OTHER 231 231 ); 232 232 233 - FTRACE_ENTRY(print, print_entry, 233 + FTRACE_ENTRY_REG(print, print_entry, 234 234 235 235 TRACE_PRINT, 236 236 ··· 242 242 F_printk("%ps: %s", 243 243 (void *)__entry->ip, __entry->buf), 244 244 245 - FILTER_OTHER 245 + FILTER_OTHER, 246 + 247 + ftrace_event_register 246 248 ); 247 249 248 250 FTRACE_ENTRY(raw_data, raw_data_entry,
+24 -12
kernel/trace/trace_events.c
··· 2007 2007 return -1; 2008 2008 } 2009 2009 } 2010 - trace_create_file("filter", 0644, file->dir, file, 2011 - &ftrace_event_filter_fops); 2012 2010 2013 2011 /* 2014 2012 * Only event directories that can be enabled should have 2015 - * triggers. 2013 + * triggers or filters. 2016 2014 */ 2017 - if (!(call->flags & TRACE_EVENT_FL_IGNORE_ENABLE)) 2015 + if (!(call->flags & TRACE_EVENT_FL_IGNORE_ENABLE)) { 2016 + trace_create_file("filter", 0644, file->dir, file, 2017 + &ftrace_event_filter_fops); 2018 + 2018 2019 trace_create_file("trigger", 0644, file->dir, file, 2019 2020 &event_trigger_fops); 2021 + } 2020 2022 2021 2023 #ifdef CONFIG_HIST_TRIGGERS 2022 2024 trace_create_file("hist", 0444, file->dir, file, ··· 2475 2473 } 2476 2474 } 2477 2475 2476 + /* Returns any file that matches the system and event */ 2478 2477 struct trace_event_file * 2479 - find_event_file(struct trace_array *tr, const char *system, const char *event) 2478 + __find_event_file(struct trace_array *tr, const char *system, const char *event) 2480 2479 { 2481 2480 struct trace_event_file *file; 2482 2481 struct trace_event_call *call; ··· 2488 2485 call = file->event_call; 2489 2486 name = trace_event_name(call); 2490 2487 2491 - if (!name || !call->class || !call->class->reg) 2492 - continue; 2493 - 2494 - if (call->flags & TRACE_EVENT_FL_IGNORE_ENABLE) 2488 + if (!name || !call->class) 2495 2489 continue; 2496 2490 2497 2491 if (strcmp(event, name) == 0 && ··· 2496 2496 return file; 2497 2497 } 2498 2498 return NULL; 2499 + } 2500 + 2501 + /* Returns valid trace event files that match system and event */ 2502 + struct trace_event_file * 2503 + find_event_file(struct trace_array *tr, const char *system, const char *event) 2504 + { 2505 + struct trace_event_file *file; 2506 + 2507 + file = __find_event_file(tr, system, event); 2508 + if (!file || !file->event_call->class->reg || 2509 + file->event_call->flags & TRACE_EVENT_FL_IGNORE_ENABLE) 2510 + return NULL; 2511 + 2512 + return file; 2499 2513 } 2500 2514 2501 2515 #ifdef CONFIG_DYNAMIC_FTRACE ··· 3146 3132 3147 3133 early_initcall(event_trace_enable_again); 3148 3134 3149 - static __init int event_trace_init(void) 3135 + __init int event_trace_init(void) 3150 3136 { 3151 3137 struct trace_array *tr; 3152 3138 struct dentry *d_tracer; ··· 3190 3176 init_ftrace_syscalls(); 3191 3177 event_trace_enable(); 3192 3178 } 3193 - 3194 - fs_initcall(event_trace_init); 3195 3179 3196 3180 #ifdef CONFIG_FTRACE_STARTUP_TEST 3197 3181
+12 -11
kernel/trace/trace_events_filter.c
··· 750 750 * 751 751 * Note: 752 752 * - @str might not be NULL-terminated if it's of type DYN_STRING 753 - * or STATIC_STRING 753 + * or STATIC_STRING, unless @len is zero. 754 754 */ 755 755 756 756 static int regex_match_full(char *str, struct regex *r, int len) 757 757 { 758 - if (strncmp(str, r->pattern, len) == 0) 759 - return 1; 760 - return 0; 758 + /* len of zero means str is dynamic and ends with '\0' */ 759 + if (!len) 760 + return strcmp(str, r->pattern) == 0; 761 + 762 + return strncmp(str, r->pattern, len) == 0; 761 763 } 762 764 763 765 static int regex_match_front(char *str, struct regex *r, int len) 764 766 { 765 - if (len < r->len) 767 + if (len && len < r->len) 766 768 return 0; 767 769 768 - if (strncmp(str, r->pattern, r->len) == 0) 769 - return 1; 770 - return 0; 770 + return strncmp(str, r->pattern, r->len) == 0; 771 771 } 772 772 773 773 static int regex_match_middle(char *str, struct regex *r, int len) 774 774 { 775 - if (strnstr(str, r->pattern, len)) 776 - return 1; 777 - return 0; 775 + if (!len) 776 + return strstr(str, r->pattern) != NULL; 777 + 778 + return strnstr(str, r->pattern, len) != NULL; 778 779 } 779 780 780 781 static int regex_match_end(char *str, struct regex *r, int len)
+1 -1
kernel/trace/trace_events_hist.c
··· 2865 2865 { 2866 2866 struct trace_event_file *file; 2867 2867 2868 - file = find_event_file(tr, system, event_name); 2868 + file = __find_event_file(tr, system, event_name); 2869 2869 if (!file) 2870 2870 return ERR_PTR(-EINVAL); 2871 2871
+2 -4
kernel/trace/trace_events_trigger.c
··· 97 97 * event_triggers_post_call - Call 'post_triggers' for a trace event 98 98 * @file: The trace_event_file associated with the event 99 99 * @tt: enum event_trigger_type containing a set bit for each trigger to invoke 100 - * @rec: The trace entry for the event 101 100 * 102 101 * For each trigger associated with an event, invoke the trigger 103 102 * function registered with the associated trigger command, if the ··· 107 108 */ 108 109 void 109 110 event_triggers_post_call(struct trace_event_file *file, 110 - enum event_trigger_type tt, 111 - void *rec, struct ring_buffer_event *event) 111 + enum event_trigger_type tt) 112 112 { 113 113 struct event_trigger_data *data; 114 114 ··· 115 117 if (data->paused) 116 118 continue; 117 119 if (data->cmd_ops->trigger_type & tt) 118 - data->ops->func(data, rec, event); 120 + data->ops->func(data, NULL, NULL); 119 121 } 120 122 } 121 123 EXPORT_SYMBOL_GPL(event_triggers_post_call);
+8 -1
kernel/trace/trace_export.c
··· 14 14 15 15 #include "trace_output.h" 16 16 17 + /* Stub function for events with triggers */ 18 + static int ftrace_event_register(struct trace_event_call *call, 19 + enum trace_reg type, void *data) 20 + { 21 + return 0; 22 + } 23 + 17 24 #undef TRACE_SYSTEM 18 25 #define TRACE_SYSTEM ftrace 19 26 ··· 124 117 125 118 #undef __dynamic_array 126 119 #define __dynamic_array(type, item) \ 127 - ret = trace_define_field(event_call, #type, #item, \ 120 + ret = trace_define_field(event_call, #type "[]", #item, \ 128 121 offsetof(typeof(field), item), \ 129 122 0, is_signed_type(type), filter_type);\ 130 123 if (ret) \
+1 -2
kernel/tracepoint.c
··· 257 257 } 258 258 259 259 /** 260 - * tracepoint_probe_register - Connect a probe to a tracepoint 260 + * tracepoint_probe_register_prio - Connect a probe to a tracepoint with priority 261 261 * @tp: tracepoint 262 262 * @probe: probe handler 263 263 * @data: tracepoint data ··· 290 290 * @tp: tracepoint 291 291 * @probe: probe handler 292 292 * @data: tracepoint data 293 - * @prio: priority of this function over other registered functions 294 293 * 295 294 * Returns 0 if ok, error value on error. 296 295 * Note: if @tp is within a module, the caller is responsible for
+6
scripts/Makefile.build
··· 206 206 endif 207 207 208 208 ifdef CONFIG_FTRACE_MCOUNT_RECORD 209 + # gcc 5 supports generating the mcount tables directly 210 + ifneq ($(call cc-option,-mrecord-mcount,y),y) 211 + KBUILD_CFLAGS += -mrecord-mcount 212 + else 213 + # else do it all manually 209 214 ifdef BUILD_C_RECORDMCOUNT 210 215 ifeq ("$(origin RECORDMCOUNT_WARN)", "command line") 211 216 RECORDMCOUNT_FLAGS = -w ··· 261 256 ifdef CONFIG_RETPOLINE 262 257 ifneq ($(RETPOLINE_CFLAGS),) 263 258 objtool_args += --retpoline 259 + endif 264 260 endif 265 261 endif 266 262
+19 -4
tools/testing/selftests/ftrace/test.d/functions
··· 15 15 echo nop > current_tracer 16 16 } 17 17 18 - reset_trigger() { # reset all current setting triggers 19 - grep -v ^# events/*/*/trigger | 18 + reset_trigger_file() { 19 + # remove action triggers first 20 + grep -H ':on[^:]*(' $@ | 20 21 while read line; do 21 - cmd=`echo $line | cut -f2- -d: | cut -f1 -d" "` 22 - echo "!$cmd" > `echo $line | cut -f1 -d:` 22 + cmd=`echo $line | cut -f2- -d: | cut -f1 -d"["` 23 + file=`echo $line | cut -f1 -d:` 24 + echo "!$cmd" >> $file 23 25 done 26 + grep -Hv ^# $@ | 27 + while read line; do 28 + cmd=`echo $line | cut -f2- -d: | cut -f1 -d"["` 29 + file=`echo $line | cut -f1 -d:` 30 + echo "!$cmd" > $file 31 + done 32 + } 33 + 34 + reset_trigger() { # reset all current setting triggers 35 + if [ -d events/synthetic ]; then 36 + reset_trigger_file events/synthetic/*/trigger 37 + fi 38 + reset_trigger_file events/*/*/trigger 24 39 } 25 40 26 41 reset_events_filter() { # reset all current setting filters
+49
tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-hist.tc
··· 1 + #!/bin/sh 2 + # SPDX-License-Identifier: GPL-2.0 3 + # description: trace_marker trigger - test histogram trigger 4 + # flags: instance 5 + 6 + do_reset() { 7 + reset_trigger 8 + echo > set_event 9 + clear_trace 10 + } 11 + 12 + fail() { #msg 13 + do_reset 14 + echo $1 15 + exit_fail 16 + } 17 + 18 + if [ ! -f set_event ]; then 19 + echo "event tracing is not supported" 20 + exit_unsupported 21 + fi 22 + 23 + if [ ! -d events/ftrace/print ]; then 24 + echo "event trace_marker is not supported" 25 + exit_unsupported 26 + fi 27 + 28 + if [ ! -f events/ftrace/print/trigger ]; then 29 + echo "event trigger is not supported" 30 + exit_unsupported 31 + fi 32 + 33 + if [ ! -f events/ftrace/print/hist ]; then 34 + echo "hist trigger is not supported" 35 + exit_unsupported 36 + fi 37 + 38 + do_reset 39 + 40 + echo "Test histogram trace_marker tigger" 41 + 42 + echo 'hist:keys=common_pid' > events/ftrace/print/trigger 43 + for i in `seq 1 10` ; do echo "hello" > trace_marker; done 44 + grep 'hitcount: *10$' events/ftrace/print/hist > /dev/null || \ 45 + fail "hist trigger did not trigger correct times on trace_marker" 46 + 47 + do_reset 48 + 49 + exit 0
+74
tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-snapshot.tc
··· 1 + #!/bin/sh 2 + # SPDX-License-Identifier: GPL-2.0 3 + # description: trace_marker trigger - test snapshot trigger 4 + # flags: instance 5 + 6 + do_reset() { 7 + reset_trigger 8 + echo > set_event 9 + echo 0 > snapshot 10 + clear_trace 11 + } 12 + 13 + fail() { #msg 14 + do_reset 15 + echo $1 16 + exit_fail 17 + } 18 + 19 + if [ ! -f set_event ]; then 20 + echo "event tracing is not supported" 21 + exit_unsupported 22 + fi 23 + 24 + if [ ! -f snapshot ]; then 25 + echo "snapshot is not supported" 26 + exit_unsupported 27 + fi 28 + 29 + if [ ! -d events/ftrace/print ]; then 30 + echo "event trace_marker is not supported" 31 + exit_unsupported 32 + fi 33 + 34 + if [ ! -f events/ftrace/print/trigger ]; then 35 + echo "event trigger is not supported" 36 + exit_unsupported 37 + fi 38 + 39 + test_trace() { 40 + file=$1 41 + x=$2 42 + 43 + cat $file | while read line; do 44 + comment=`echo $line | sed -e 's/^#//'` 45 + if [ "$line" != "$comment" ]; then 46 + continue 47 + fi 48 + echo "testing $line for >$x<" 49 + match=`echo $line | sed -e "s/>$x<//"` 50 + if [ "$line" == "$match" ]; then 51 + fail "$line does not have >$x< in it" 52 + fi 53 + let x=$x+2 54 + done 55 + } 56 + 57 + do_reset 58 + 59 + echo "Test snapshot trace_marker tigger" 60 + 61 + echo 'snapshot' > events/ftrace/print/trigger 62 + 63 + # make sure the snapshot is allocated 64 + 65 + grep -q 'Snapshot is allocated' snapshot 66 + 67 + for i in `seq 1 10` ; do echo "hello >$i<" > trace_marker; done 68 + 69 + test_trace trace 1 70 + test_trace snapshot 2 71 + 72 + do_reset 73 + 74 + exit 0
+68
tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-synthetic-kernel.tc
··· 1 + #!/bin/sh 2 + # SPDX-License-Identifier: GPL-2.0 3 + # description: trace_marker trigger - test histogram with synthetic event against kernel event 4 + # flags: 5 + 6 + do_reset() { 7 + reset_trigger 8 + echo > set_event 9 + echo > synthetic_events 10 + clear_trace 11 + } 12 + 13 + fail() { #msg 14 + do_reset 15 + echo $1 16 + exit_fail 17 + } 18 + 19 + if [ ! -f set_event ]; then 20 + echo "event tracing is not supported" 21 + exit_unsupported 22 + fi 23 + 24 + if [ ! -f synthetic_events ]; then 25 + echo "synthetic events not supported" 26 + exit_unsupported 27 + fi 28 + 29 + if [ ! -d events/ftrace/print ]; then 30 + echo "event trace_marker is not supported" 31 + exit_unsupported 32 + fi 33 + 34 + if [ ! -d events/sched/sched_waking ]; then 35 + echo "event sched_waking is not supported" 36 + exit_unsupported 37 + fi 38 + 39 + if [ ! -f events/ftrace/print/trigger ]; then 40 + echo "event trigger is not supported" 41 + exit_unsupported 42 + fi 43 + 44 + if [ ! -f events/ftrace/print/hist ]; then 45 + echo "hist trigger is not supported" 46 + exit_unsupported 47 + fi 48 + 49 + do_reset 50 + 51 + echo "Test histogram kernel event to trace_marker latency histogram trigger" 52 + 53 + echo 'latency u64 lat' > synthetic_events 54 + echo 'hist:keys=pid:ts0=common_timestamp.usecs' > events/sched/sched_waking/trigger 55 + echo 'hist:keys=common_pid:lat=common_timestamp.usecs-$ts0:onmatch(sched.sched_waking).latency($lat)' > events/ftrace/print/trigger 56 + echo 'hist:keys=common_pid,lat:sort=lat' > events/synthetic/latency/trigger 57 + sleep 1 58 + echo "hello" > trace_marker 59 + 60 + grep 'hitcount: *1$' events/ftrace/print/hist > /dev/null || \ 61 + fail "hist trigger did not trigger correct times on trace_marker" 62 + 63 + grep 'hitcount: *1$' events/synthetic/latency/hist > /dev/null || \ 64 + fail "hist trigger did not trigger " 65 + 66 + do_reset 67 + 68 + exit 0
+66
tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-synthetic.tc
··· 1 + #!/bin/sh 2 + # SPDX-License-Identifier: GPL-2.0 3 + # description: trace_marker trigger - test histogram with synthetic event 4 + # flags: 5 + 6 + do_reset() { 7 + reset_trigger 8 + echo > set_event 9 + echo > synthetic_events 10 + clear_trace 11 + } 12 + 13 + fail() { #msg 14 + do_reset 15 + echo $1 16 + exit_fail 17 + } 18 + 19 + if [ ! -f set_event ]; then 20 + echo "event tracing is not supported" 21 + exit_unsupported 22 + fi 23 + 24 + if [ ! -f synthetic_events ]; then 25 + echo "synthetic events not supported" 26 + exit_unsupported 27 + fi 28 + 29 + if [ ! -d events/ftrace/print ]; then 30 + echo "event trace_marker is not supported" 31 + exit_unsupported 32 + fi 33 + 34 + if [ ! -f events/ftrace/print/trigger ]; then 35 + echo "event trigger is not supported" 36 + exit_unsupported 37 + fi 38 + 39 + if [ ! -f events/ftrace/print/hist ]; then 40 + echo "hist trigger is not supported" 41 + exit_unsupported 42 + fi 43 + 44 + do_reset 45 + 46 + echo "Test histogram trace_marker to trace_marker latency histogram trigger" 47 + 48 + echo 'latency u64 lat' > synthetic_events 49 + echo 'hist:keys=common_pid:ts0=common_timestamp.usecs if buf == "start"' > events/ftrace/print/trigger 50 + echo 'hist:keys=common_pid:lat=common_timestamp.usecs-$ts0:onmatch(ftrace.print).latency($lat) if buf == "end"' >> events/ftrace/print/trigger 51 + echo 'hist:keys=common_pid,lat:sort=lat' > events/synthetic/latency/trigger 52 + echo -n "start" > trace_marker 53 + echo -n "end" > trace_marker 54 + 55 + cnt=`grep 'hitcount: *1$' events/ftrace/print/hist | wc -l` 56 + 57 + if [ $cnt -ne 2 ]; then 58 + fail "hist trace_marker trigger did not trigger correctly" 59 + fi 60 + 61 + grep 'hitcount: *1$' events/synthetic/latency/hist > /dev/null || \ 62 + fail "hist trigger did not trigger " 63 + 64 + do_reset 65 + 66 + exit 0