projects / linux-2.6-block.git / blame
| Commit | Line | Data |
|---|---|---|
| ea272257 MCC |
1 | ================ |
| 2 | Event Histograms | |
| 3 | ================ | |
| b8df4a36 | 4 | |
| ea272257 | 5 | Documentation written by Tom Zanussi |
| b8df4a36 TZ |
6 | |
| 7 | 1. Introduction | |
| 8 | =============== | |
| 9 | ||
| 10 | Histogram triggers are special event triggers that can be used to | |
| 11 | aggregate trace event data into histograms. For information on | |
| 5fb94e9c | 12 | trace events and event triggers, see Documentation/trace/events.rst. |
| b8df4a36 TZ |
13 | |
| 14 | ||
| 15 | 2. Histogram Trigger Command | |
| 16 | ============================ | |
| 17 | ||
| 18 | A histogram trigger command is an event trigger command that | |
| 19 | aggregates event hits into a hash table keyed on one or more trace | |
| 20 | event format fields (or stacktrace) and a set of running totals | |
| 21 | derived from one or more trace event format fields and/or event | |
| 22 | counts (hitcount). | |
| 23 | ||
| ea272257 | 24 | The format of a hist trigger is as follows:: |
| b8df4a36 TZ |
25 | |
| 26 | hist:keys=<field1[,field2,...]>[:values=<field1[,field2,...]>] | |
| 27 | [:sort=<field1[,field2,...]>][:size=#entries][:pause][:continue] | |
| 5032b381 | 28 | [:clear][:name=histname1][:<handler>.<action>] [if <filter>] |
| b8df4a36 TZ |
29 | |
| 30 | When a matching event is hit, an entry is added to a hash table | |
| 31 | using the key(s) and value(s) named. Keys and values correspond to | |
| 32 | fields in the event's format description. Values must correspond to | |
| 33 | numeric fields - on an event hit, the value(s) will be added to a | |
| 34 | sum kept for that field. The special string 'hitcount' can be used | |
| 35 | in place of an explicit value field - this is simply a count of | |
| 36 | event hits. If 'values' isn't specified, an implicit 'hitcount' | |
| 37 | value will be automatically created and used as the only value. | |
| 38 | Keys can be any field, or the special string 'stacktrace', which | |
| 39 | will use the event's kernel stacktrace as the key. The keywords | |
| 40 | 'keys' or 'key' can be used to specify keys, and the keywords | |
| 41 | 'values', 'vals', or 'val' can be used to specify values. Compound | |
| 42 | keys consisting of up to two fields can be specified by the 'keys' | |
| 43 | keyword. Hashing a compound key produces a unique entry in the | |
| 44 | table for each unique combination of component keys, and can be | |
| 45 | useful for providing more fine-grained summaries of event data. | |
| 46 | Additionally, sort keys consisting of up to two fields can be | |
| 47 | specified by the 'sort' keyword. If more than one field is | |
| 48 | specified, the result will be a 'sort within a sort': the first key | |
| 49 | is taken to be the primary sort key and the second the secondary | |
| 50 | key. If a hist trigger is given a name using the 'name' parameter, | |
| 51 | its histogram data will be shared with other triggers of the same | |
| 52 | name, and trigger hits will update this common data. Only triggers | |
| 53 | with 'compatible' fields can be combined in this way; triggers are | |
| 54 | 'compatible' if the fields named in the trigger share the same | |
| 55 | number and type of fields and those fields also have the same names. | |
| 56 | Note that any two events always share the compatible 'hitcount' and | |
| 57 | 'stacktrace' fields and can therefore be combined using those | |
| 58 | fields, however pointless that may be. | |
| 59 | ||
| 60 | 'hist' triggers add a 'hist' file to each event's subdirectory. | |
| 61 | Reading the 'hist' file for the event will dump the hash table in | |
| 62 | its entirety to stdout. If there are multiple hist triggers | |
| 63 | attached to an event, there will be a table for each trigger in the | |
| 64 | output. The table displayed for a named trigger will be the same as | |
| 65 | any other instance having the same name. Each printed hash table | |
| 66 | entry is a simple list of the keys and values comprising the entry; | |
| 67 | keys are printed first and are delineated by curly braces, and are | |
| 68 | followed by the set of value fields for the entry. By default, | |
| 69 | numeric fields are displayed as base-10 integers. This can be | |
| 70 | modified by appending any of the following modifiers to the field | |
| 71 | name: | |
| 72 | ||
| ea272257 | 73 | =========== ========================================== |
| b8df4a36 TZ |
74 | .hex display a number as a hex value |
| 75 | .sym display an address as a symbol | |
| 76 | .sym-offset display an address as a symbol and offset | |
| 77 | .syscall display a syscall id as a system call name | |
| 78 | .execname display a common_pid as a program name | |
| 442c9484 | 79 | .log2 display log2 value rather than raw number |
| 860f9f6b | 80 | .usecs display a common_timestamp in microseconds |
| ea272257 | 81 | =========== ========================================== |
| b8df4a36 TZ |
82 | |
| 83 | Note that in general the semantics of a given field aren't | |
| 84 | interpreted when applying a modifier to it, but there are some | |
| 85 | restrictions to be aware of in this regard: | |
| 86 | ||
| 87 | - only the 'hex' modifier can be used for values (because values | |
| 88 | are essentially sums, and the other modifiers don't make sense | |
| 89 | in that context). | |
| 90 | - the 'execname' modifier can only be used on a 'common_pid'. The | |
| 91 | reason for this is that the execname is simply the 'comm' value | |
| 92 | saved for the 'current' process when an event was triggered, | |
| 93 | which is the same as the common_pid value saved by the event | |
| 94 | tracing code. Trying to apply that comm value to other pid | |
| 95 | values wouldn't be correct, and typically events that care save | |
| 96 | pid-specific comm fields in the event itself. | |
| 97 | ||
| 98 | A typical usage scenario would be the following to enable a hist | |
| ea272257 | 99 | trigger, read its current contents, and then turn it off:: |
| b8df4a36 | 100 | |
| ea272257 MCC |
101 | # echo 'hist:keys=skbaddr.hex:vals=len' > \ |
| 102 | /sys/kernel/debug/tracing/events/net/netif_rx/trigger | |
| b8df4a36 | 103 | |
| ea272257 | 104 | # cat /sys/kernel/debug/tracing/events/net/netif_rx/hist |
| b8df4a36 | 105 | |
| ea272257 MCC |
106 | # echo '!hist:keys=skbaddr.hex:vals=len' > \ |
| 107 | /sys/kernel/debug/tracing/events/net/netif_rx/trigger | |
| b8df4a36 TZ |
108 | |
| 109 | The trigger file itself can be read to show the details of the | |
| 110 | currently attached hist trigger. This information is also displayed | |
| 111 | at the top of the 'hist' file when read. | |
| 112 | ||
| 113 | By default, the size of the hash table is 2048 entries. The 'size' | |
| 114 | parameter can be used to specify more or fewer than that. The units | |
| 115 | are in terms of hashtable entries - if a run uses more entries than | |
| 116 | specified, the results will show the number of 'drops', the number | |
| 117 | of hits that were ignored. The size should be a power of 2 between | |
| 118 | 128 and 131072 (any non- power-of-2 number specified will be rounded | |
| 119 | up). | |
| 120 | ||
| 121 | The 'sort' parameter can be used to specify a value field to sort | |
| 122 | on. The default if unspecified is 'hitcount' and the default sort | |
| 123 | order is 'ascending'. To sort in the opposite direction, append | |
| 124 | .descending' to the sort key. | |
| 125 | ||
| 126 | The 'pause' parameter can be used to pause an existing hist trigger | |
| 127 | or to start a hist trigger but not log any events until told to do | |
| 128 | so. 'continue' or 'cont' can be used to start or restart a paused | |
| 129 | hist trigger. | |
| 130 | ||
| 131 | The 'clear' parameter will clear the contents of a running hist | |
| 132 | trigger and leave its current paused/active state. | |
| 133 | ||
| 134 | Note that the 'pause', 'cont', and 'clear' parameters should be | |
| 135 | applied using 'append' shell operator ('>>') if applied to an | |
| 136 | existing trigger, rather than via the '>' operator, which will cause | |
| 137 | the trigger to be removed through truncation. | |
| 138 | ||
| 139 | - enable_hist/disable_hist | |
| 140 | ||
| 141 | The enable_hist and disable_hist triggers can be used to have one | |
| 142 | event conditionally start and stop another event's already-attached | |
| 143 | hist trigger. Any number of enable_hist and disable_hist triggers | |
| 144 | can be attached to a given event, allowing that event to kick off | |
| 145 | and stop aggregations on a host of other events. | |
| 146 | ||
| ea272257 | 147 | The format is very similar to the enable/disable_event triggers:: |
| b8df4a36 TZ |
148 | |
| 149 | enable_hist:<system>:<event>[:count] | |
| 150 | disable_hist:<system>:<event>[:count] | |
| 151 | ||
| 152 | Instead of enabling or disabling the tracing of the target event | |
| 153 | into the trace buffer as the enable/disable_event triggers do, the | |
| 154 | enable/disable_hist triggers enable or disable the aggregation of | |
| 155 | the target event into a hash table. | |
| 156 | ||
| 157 | A typical usage scenario for the enable_hist/disable_hist triggers | |
| 158 | would be to first set up a paused hist trigger on some event, | |
| 159 | followed by an enable_hist/disable_hist pair that turns the hist | |
| ea272257 | 160 | aggregation on and off when conditions of interest are hit:: |
| b8df4a36 | 161 | |
| ea272257 MCC |
162 | # echo 'hist:keys=skbaddr.hex:vals=len:pause' > \ |
| 163 | /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger | |
| b8df4a36 | 164 | |
| ea272257 MCC |
165 | # echo 'enable_hist:net:netif_receive_skb if filename==/usr/bin/wget' > \ |
| 166 | /sys/kernel/debug/tracing/events/sched/sched_process_exec/trigger | |
| b8df4a36 | 167 | |
| ea272257 MCC |
168 | # echo 'disable_hist:net:netif_receive_skb if comm==wget' > \ |
| 169 | /sys/kernel/debug/tracing/events/sched/sched_process_exit/trigger | |
| b8df4a36 TZ |
170 | |
| 171 | The above sets up an initially paused hist trigger which is unpaused | |
| 172 | and starts aggregating events when a given program is executed, and | |
| 173 | which stops aggregating when the process exits and the hist trigger | |
| 174 | is paused again. | |
| 175 | ||
| 176 | The examples below provide a more concrete illustration of the | |
| 177 | concepts and typical usage patterns discussed above. | |
| 178 | ||
| ea272257 MCC |
179 | 'special' event fields |
| 180 | ------------------------ | |
| 8b7622bf TZ |
181 | |
| 182 | There are a number of 'special event fields' available for use as | |
| 183 | keys or values in a hist trigger. These look like and behave as if | |
| 184 | they were actual event fields, but aren't really part of the event's | |
| 185 | field definition or format file. They are however available for any | |
| 186 | event, and can be used anywhere an actual event field could be. | |
| 187 | They are: | |
| 188 | ||
| ea272257 MCC |
189 | ====================== ==== ======================================= |
| 190 | common_timestamp u64 timestamp (from ring buffer) associated | |
| 191 | with the event, in nanoseconds. May be | |
| 192 | modified by .usecs to have timestamps | |
| 193 | interpreted as microseconds. | |
| 194 | cpu int the cpu on which the event occurred. | |
| 195 | ====================== ==== ======================================= | |
| b8df4a36 | 196 | |
| ea272257 MCC |
197 | Extended error information |
| 198 | -------------------------- | |
| f404da6e TZ |
199 | |
| 200 | For some error conditions encountered when invoking a hist trigger | |
| 201 | command, extended error information is available via the | |
| 202 | corresponding event's 'hist' file. Reading the hist file after an | |
| 203 | error will display more detailed information about what went wrong, | |
| 204 | if information is available. This extended error information will | |
| 205 | be available until the next hist trigger command for that event. | |
| 206 | ||
| 207 | If available for a given error condition, the extended error | |
| ea272257 | 208 | information and usage takes the following form:: |
| f404da6e TZ |
209 | |
| 210 | # echo xxx > /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger | |
| 211 | echo: write error: Invalid argument | |
| 212 | ||
| 213 | # cat /sys/kernel/debug/tracing/events/sched/sched_wakeup/hist | |
| 214 | ERROR: Couldn't yyy: zzz | |
| 215 | Last command: xxx | |
| 216 | ||
| b8df4a36 TZ |
217 | 6.2 'hist' trigger examples |
| 218 | --------------------------- | |
| 219 | ||
| 220 | The first set of examples creates aggregations using the kmalloc | |
| 221 | event. The fields that can be used for the hist trigger are listed | |
| ea272257 | 222 | in the kmalloc event's format file:: |
| b8df4a36 TZ |
223 | |
| 224 | # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/format | |
| 225 | name: kmalloc | |
| 226 | ID: 374 | |
| 227 | format: | |
| 228 | field:unsigned short common_type; offset:0; size:2; signed:0; | |
| 229 | field:unsigned char common_flags; offset:2; size:1; signed:0; | |
| 230 | field:unsigned char common_preempt_count; offset:3; size:1; signed:0; | |
| 231 | field:int common_pid; offset:4; size:4; signed:1; | |
| 232 | ||
| 233 | field:unsigned long call_site; offset:8; size:8; signed:0; | |
| 234 | field:const void * ptr; offset:16; size:8; signed:0; | |
| 235 | field:size_t bytes_req; offset:24; size:8; signed:0; | |
| 236 | field:size_t bytes_alloc; offset:32; size:8; signed:0; | |
| 237 | field:gfp_t gfp_flags; offset:40; size:4; signed:0; | |
| 238 | ||
| 239 | We'll start by creating a hist trigger that generates a simple table | |
| 240 | that lists the total number of bytes requested for each function in | |
| ea272257 | 241 | the kernel that made one or more calls to kmalloc:: |
| b8df4a36 TZ |
242 | |
| 243 | # echo 'hist:key=call_site:val=bytes_req' > \ | |
| 244 | /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger | |
| 245 | ||
| 246 | This tells the tracing system to create a 'hist' trigger using the | |
| 247 | call_site field of the kmalloc event as the key for the table, which | |
| 248 | just means that each unique call_site address will have an entry | |
| 249 | created for it in the table. The 'val=bytes_req' parameter tells | |
| 250 | the hist trigger that for each unique entry (call_site) in the | |
| 251 | table, it should keep a running total of the number of bytes | |
| 252 | requested by that call_site. | |
| 253 | ||
| 254 | We'll let it run for awhile and then dump the contents of the 'hist' | |
| 255 | file in the kmalloc event's subdirectory (for readability, a number | |
| ea272257 | 256 | of entries have been omitted):: |
| b8df4a36 TZ |
257 | |
| 258 | # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/hist | |
| 259 | # trigger info: hist:keys=call_site:vals=bytes_req:sort=hitcount:size=2048 [active] | |
| 260 | ||
| 261 | { call_site: 18446744072106379007 } hitcount: 1 bytes_req: 176 | |
| 262 | { call_site: 18446744071579557049 } hitcount: 1 bytes_req: 1024 | |
| 263 | { call_site: 18446744071580608289 } hitcount: 1 bytes_req: 16384 | |
| 264 | { call_site: 18446744071581827654 } hitcount: 1 bytes_req: 24 | |
| 265 | { call_site: 18446744071580700980 } hitcount: 1 bytes_req: 8 | |
| 266 | { call_site: 18446744071579359876 } hitcount: 1 bytes_req: 152 | |
| 267 | { call_site: 18446744071580795365 } hitcount: 3 bytes_req: 144 | |
| 268 | { call_site: 18446744071581303129 } hitcount: 3 bytes_req: 144 | |
| 269 | { call_site: 18446744071580713234 } hitcount: 4 bytes_req: 2560 | |
| 270 | { call_site: 18446744071580933750 } hitcount: 4 bytes_req: 736 | |
| 271 | . | |
| 272 | . | |
| 273 | . | |
| 274 | { call_site: 18446744072106047046 } hitcount: 69 bytes_req: 5576 | |
| 275 | { call_site: 18446744071582116407 } hitcount: 73 bytes_req: 2336 | |
| 276 | { call_site: 18446744072106054684 } hitcount: 136 bytes_req: 140504 | |
| 277 | { call_site: 18446744072106224230 } hitcount: 136 bytes_req: 19584 | |
| 278 | { call_site: 18446744072106078074 } hitcount: 153 bytes_req: 2448 | |
| 279 | { call_site: 18446744072106062406 } hitcount: 153 bytes_req: 36720 | |
| 280 | { call_site: 18446744071582507929 } hitcount: 153 bytes_req: 37088 | |
| 281 | { call_site: 18446744072102520590 } hitcount: 273 bytes_req: 10920 | |
| 282 | { call_site: 18446744071582143559 } hitcount: 358 bytes_req: 716 | |
| 283 | { call_site: 18446744072106465852 } hitcount: 417 bytes_req: 56712 | |
| 284 | { call_site: 18446744072102523378 } hitcount: 485 bytes_req: 27160 | |
| 285 | { call_site: 18446744072099568646 } hitcount: 1676 bytes_req: 33520 | |
| 286 | ||
| 287 | Totals: | |
| 288 | Hits: 4610 | |
| 289 | Entries: 45 | |
| 290 | Dropped: 0 | |
| 291 | ||
| 292 | The output displays a line for each entry, beginning with the key | |
| 293 | specified in the trigger, followed by the value(s) also specified in | |
| 294 | the trigger. At the beginning of the output is a line that displays | |
| 295 | the trigger info, which can also be displayed by reading the | |
| ea272257 | 296 | 'trigger' file:: |
| b8df4a36 TZ |
297 | |
| 298 | # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger | |
| 299 | hist:keys=call_site:vals=bytes_req:sort=hitcount:size=2048 [active] | |
| 300 | ||
| 301 | At the end of the output are a few lines that display the overall | |
| 302 | totals for the run. The 'Hits' field shows the total number of | |
| 303 | times the event trigger was hit, the 'Entries' field shows the total | |
| 304 | number of used entries in the hash table, and the 'Dropped' field | |
| 305 | shows the number of hits that were dropped because the number of | |
| 306 | used entries for the run exceeded the maximum number of entries | |
| 307 | allowed for the table (normally 0, but if not a hint that you may | |
| 308 | want to increase the size of the table using the 'size' parameter). | |
| 309 | ||
| 310 | Notice in the above output that there's an extra field, 'hitcount', | |
| 311 | which wasn't specified in the trigger. Also notice that in the | |
| 312 | trigger info output, there's a parameter, 'sort=hitcount', which | |
| 313 | wasn't specified in the trigger either. The reason for that is that | |
| 314 | every trigger implicitly keeps a count of the total number of hits | |
| 315 | attributed to a given entry, called the 'hitcount'. That hitcount | |
| 316 | information is explicitly displayed in the output, and in the | |
| 317 | absence of a user-specified sort parameter, is used as the default | |
| 318 | sort field. | |
| 319 | ||
| 320 | The value 'hitcount' can be used in place of an explicit value in | |
| 321 | the 'values' parameter if you don't really need to have any | |
| 322 | particular field summed and are mainly interested in hit | |
| 323 | frequencies. | |
| 324 | ||
| 325 | To turn the hist trigger off, simply call up the trigger in the | |
| ea272257 | 326 | command history and re-execute it with a '!' prepended:: |
| b8df4a36 TZ |
327 | |
| 328 | # echo '!hist:key=call_site:val=bytes_req' > \ | |
| 329 | /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger | |
| 330 | ||
| 331 | Finally, notice that the call_site as displayed in the output above | |
| 332 | isn't really very useful. It's an address, but normally addresses | |
| 333 | are displayed in hex. To have a numeric field displayed as a hex | |
| ea272257 | 334 | value, simply append '.hex' to the field name in the trigger:: |
| b8df4a36 TZ |
335 | |
| 336 | # echo 'hist:key=call_site.hex:val=bytes_req' > \ | |
| 337 | /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger | |
| 338 | ||
| 339 | # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/hist | |
| 340 | # trigger info: hist:keys=call_site.hex:vals=bytes_req:sort=hitcount:size=2048 [active] | |
| 341 | ||
| 342 | { call_site: ffffffffa026b291 } hitcount: 1 bytes_req: 433 | |
| 343 | { call_site: ffffffffa07186ff } hitcount: 1 bytes_req: 176 | |
| 344 | { call_site: ffffffff811ae721 } hitcount: 1 bytes_req: 16384 | |
| 345 | { call_site: ffffffff811c5134 } hitcount: 1 bytes_req: 8 | |
| 346 | { call_site: ffffffffa04a9ebb } hitcount: 1 bytes_req: 511 | |
| 347 | { call_site: ffffffff8122e0a6 } hitcount: 1 bytes_req: 12 | |
| 348 | { call_site: ffffffff8107da84 } hitcount: 1 bytes_req: 152 | |
| 349 | { call_site: ffffffff812d8246 } hitcount: 1 bytes_req: 24 | |
| 350 | { call_site: ffffffff811dc1e5 } hitcount: 3 bytes_req: 144 | |
| 351 | { call_site: ffffffffa02515e8 } hitcount: 3 bytes_req: 648 | |
| 352 | { call_site: ffffffff81258159 } hitcount: 3 bytes_req: 144 | |
| 353 | { call_site: ffffffff811c80f4 } hitcount: 4 bytes_req: 544 | |
| 354 | . | |
| 355 | . | |
| 356 | . | |
| 357 | { call_site: ffffffffa06c7646 } hitcount: 106 bytes_req: 8024 | |
| 358 | { call_site: ffffffffa06cb246 } hitcount: 132 bytes_req: 31680 | |
| 359 | { call_site: ffffffffa06cef7a } hitcount: 132 bytes_req: 2112 | |
| 360 | { call_site: ffffffff8137e399 } hitcount: 132 bytes_req: 23232 | |
| 361 | { call_site: ffffffffa06c941c } hitcount: 185 bytes_req: 171360 | |
| 362 | { call_site: ffffffffa06f2a66 } hitcount: 185 bytes_req: 26640 | |
| 363 | { call_site: ffffffffa036a70e } hitcount: 265 bytes_req: 10600 | |
| 364 | { call_site: ffffffff81325447 } hitcount: 292 bytes_req: 584 | |
| 365 | { call_site: ffffffffa072da3c } hitcount: 446 bytes_req: 60656 | |
| 366 | { call_site: ffffffffa036b1f2 } hitcount: 526 bytes_req: 29456 | |
| 367 | { call_site: ffffffffa0099c06 } hitcount: 1780 bytes_req: 35600 | |
| 368 | ||
| 369 | Totals: | |
| 370 | Hits: 4775 | |
| 371 | Entries: 46 | |
| 372 | Dropped: 0 | |
| 373 | ||
| 374 | Even that's only marginally more useful - while hex values do look | |
| 375 | more like addresses, what users are typically more interested in | |
| 376 | when looking at text addresses are the corresponding symbols | |
| 377 | instead. To have an address displayed as symbolic value instead, | |
| 378 | simply append '.sym' or '.sym-offset' to the field name in the | |
| ea272257 | 379 | trigger:: |
| b8df4a36 TZ |
380 | |
| 381 | # echo 'hist:key=call_site.sym:val=bytes_req' > \ | |
| 382 | /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger | |
| 383 | ||
| 384 | # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/hist | |
| 385 | # trigger info: hist:keys=call_site.sym:vals=bytes_req:sort=hitcount:size=2048 [active] | |
| 386 | ||
| 387 | { call_site: [ffffffff810adcb9] syslog_print_all } hitcount: 1 bytes_req: 1024 | |
| 388 | { call_site: [ffffffff8154bc62] usb_control_msg } hitcount: 1 bytes_req: 8 | |
| 389 | { call_site: [ffffffffa00bf6fe] hidraw_send_report [hid] } hitcount: 1 bytes_req: 7 | |
| 390 | { call_site: [ffffffff8154acbe] usb_alloc_urb } hitcount: 1 bytes_req: 192 | |
| 391 | { call_site: [ffffffffa00bf1ca] hidraw_report_event [hid] } hitcount: 1 bytes_req: 7 | |
| 392 | { call_site: [ffffffff811e3a25] __seq_open_private } hitcount: 1 bytes_req: 40 | |
| 393 | { call_site: [ffffffff8109524a] alloc_fair_sched_group } hitcount: 2 bytes_req: 128 | |
| 394 | { call_site: [ffffffff811febd5] fsnotify_alloc_group } hitcount: 2 bytes_req: 528 | |
| 395 | { call_site: [ffffffff81440f58] __tty_buffer_request_room } hitcount: 2 bytes_req: 2624 | |
| 396 | { call_site: [ffffffff81200ba6] inotify_new_group } hitcount: 2 bytes_req: 96 | |
| 397 | { call_site: [ffffffffa05e19af] ieee80211_start_tx_ba_session [mac80211] } hitcount: 2 bytes_req: 464 | |
| 398 | { call_site: [ffffffff81672406] tcp_get_metrics } hitcount: 2 bytes_req: 304 | |
| 399 | { call_site: [ffffffff81097ec2] alloc_rt_sched_group } hitcount: 2 bytes_req: 128 | |
| 400 | { call_site: [ffffffff81089b05] sched_create_group } hitcount: 2 bytes_req: 1424 | |
| 401 | . | |
| 402 | . | |
| 403 | . | |
| 404 | { call_site: [ffffffffa04a580c] intel_crtc_page_flip [i915] } hitcount: 1185 bytes_req: 123240 | |
| 405 | { call_site: [ffffffffa0287592] drm_mode_page_flip_ioctl [drm] } hitcount: 1185 bytes_req: 104280 | |
| 406 | { call_site: [ffffffffa04c4a3c] intel_plane_duplicate_state [i915] } hitcount: 1402 bytes_req: 190672 | |
| 407 | { call_site: [ffffffff812891ca] ext4_find_extent } hitcount: 1518 bytes_req: 146208 | |
| 408 | { call_site: [ffffffffa029070e] drm_vma_node_allow [drm] } hitcount: 1746 bytes_req: 69840 | |
| 409 | { call_site: [ffffffffa045e7c4] i915_gem_do_execbuffer.isra.23 [i915] } hitcount: 2021 bytes_req: 792312 | |
| 410 | { call_site: [ffffffffa02911f2] drm_modeset_lock_crtc [drm] } hitcount: 2592 bytes_req: 145152 | |
| 411 | { call_site: [ffffffffa0489a66] intel_ring_begin [i915] } hitcount: 2629 bytes_req: 378576 | |
| 412 | { call_site: [ffffffffa046041c] i915_gem_execbuffer2 [i915] } hitcount: 2629 bytes_req: 3783248 | |
| 413 | { call_site: [ffffffff81325607] apparmor_file_alloc_security } hitcount: 5192 bytes_req: 10384 | |
| 414 | { call_site: [ffffffffa00b7c06] hid_report_raw_event [hid] } hitcount: 5529 bytes_req: 110584 | |
| 415 | { call_site: [ffffffff8131ebf7] aa_alloc_task_context } hitcount: 21943 bytes_req: 702176 | |
| 416 | { call_site: [ffffffff8125847d] ext4_htree_store_dirent } hitcount: 55759 bytes_req: 5074265 | |
| 417 | ||
| 418 | Totals: | |
| 419 | Hits: 109928 | |
| 420 | Entries: 71 | |
| 421 | Dropped: 0 | |
| 422 | ||
| 423 | Because the default sort key above is 'hitcount', the above shows a | |
| 424 | the list of call_sites by increasing hitcount, so that at the bottom | |
| 425 | we see the functions that made the most kmalloc calls during the | |
| 426 | run. If instead we we wanted to see the top kmalloc callers in | |
| 427 | terms of the number of bytes requested rather than the number of | |
| 428 | calls, and we wanted the top caller to appear at the top, we can use | |
| ea272257 | 429 | the 'sort' parameter, along with the 'descending' modifier:: |
| b8df4a36 TZ |
430 | |
| 431 | # echo 'hist:key=call_site.sym:val=bytes_req:sort=bytes_req.descending' > \ | |
| 432 | /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger | |
| 433 | ||
| 434 | # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/hist | |
| 435 | # trigger info: hist:keys=call_site.sym:vals=bytes_req:sort=bytes_req.descending:size=2048 [active] | |
| 436 | ||
| 437 | { call_site: [ffffffffa046041c] i915_gem_execbuffer2 [i915] } hitcount: 2186 bytes_req: 3397464 | |
| 438 | { call_site: [ffffffffa045e7c4] i915_gem_do_execbuffer.isra.23 [i915] } hitcount: 1790 bytes_req: 712176 | |
| 439 | { call_site: [ffffffff8125847d] ext4_htree_store_dirent } hitcount: 8132 bytes_req: 513135 | |
| 440 | { call_site: [ffffffff811e2a1b] seq_buf_alloc } hitcount: 106 bytes_req: 440128 | |
| 441 | { call_site: [ffffffffa0489a66] intel_ring_begin [i915] } hitcount: 2186 bytes_req: 314784 | |
| 442 | { call_site: [ffffffff812891ca] ext4_find_extent } hitcount: 2174 bytes_req: 208992 | |
| 443 | { call_site: [ffffffff811ae8e1] __kmalloc } hitcount: 8 bytes_req: 131072 | |
| 444 | { call_site: [ffffffffa04c4a3c] intel_plane_duplicate_state [i915] } hitcount: 859 bytes_req: 116824 | |
| 445 | { call_site: [ffffffffa02911f2] drm_modeset_lock_crtc [drm] } hitcount: 1834 bytes_req: 102704 | |
| 446 | { call_site: [ffffffffa04a580c] intel_crtc_page_flip [i915] } hitcount: 972 bytes_req: 101088 | |
| 447 | { call_site: [ffffffffa0287592] drm_mode_page_flip_ioctl [drm] } hitcount: 972 bytes_req: 85536 | |
| 448 | { call_site: [ffffffffa00b7c06] hid_report_raw_event [hid] } hitcount: 3333 bytes_req: 66664 | |
| 449 | { call_site: [ffffffff8137e559] sg_kmalloc } hitcount: 209 bytes_req: 61632 | |
| 450 | . | |
| 451 | . | |
| 452 | . | |
| 453 | { call_site: [ffffffff81095225] alloc_fair_sched_group } hitcount: 2 bytes_req: 128 | |
| 454 | { call_site: [ffffffff81097ec2] alloc_rt_sched_group } hitcount: 2 bytes_req: 128 | |
| 455 | { call_site: [ffffffff812d8406] copy_semundo } hitcount: 2 bytes_req: 48 | |
| 456 | { call_site: [ffffffff81200ba6] inotify_new_group } hitcount: 1 bytes_req: 48 | |
| 457 | { call_site: [ffffffffa027121a] drm_getmagic [drm] } hitcount: 1 bytes_req: 48 | |
| 458 | { call_site: [ffffffff811e3a25] __seq_open_private } hitcount: 1 bytes_req: 40 | |
| 459 | { call_site: [ffffffff811c52f4] bprm_change_interp } hitcount: 2 bytes_req: 16 | |
| 460 | { call_site: [ffffffff8154bc62] usb_control_msg } hitcount: 1 bytes_req: 8 | |
| 461 | { call_site: [ffffffffa00bf1ca] hidraw_report_event [hid] } hitcount: 1 bytes_req: 7 | |
| 462 | { call_site: [ffffffffa00bf6fe] hidraw_send_report [hid] } hitcount: 1 bytes_req: 7 | |
| 463 | ||
| 464 | Totals: | |
| 465 | Hits: 32133 | |
| 466 | Entries: 81 | |
| 467 | Dropped: 0 | |
| 468 | ||
| 469 | To display the offset and size information in addition to the symbol | |
| ea272257 | 470 | name, just use 'sym-offset' instead:: |
| b8df4a36 TZ |
471 | |
| 472 | # echo 'hist:key=call_site.sym-offset:val=bytes_req:sort=bytes_req.descending' > \ | |
| 473 | /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger | |
| 474 | ||
| 475 | # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/hist | |
| 476 | # trigger info: hist:keys=call_site.sym-offset:vals=bytes_req:sort=bytes_req.descending:size=2048 [active] | |
| 477 | ||
| 478 | { call_site: [ffffffffa046041c] i915_gem_execbuffer2+0x6c/0x2c0 [i915] } hitcount: 4569 bytes_req: 3163720 | |
| 479 | { call_site: [ffffffffa0489a66] intel_ring_begin+0xc6/0x1f0 [i915] } hitcount: 4569 bytes_req: 657936 | |
| 480 | { call_site: [ffffffffa045e7c4] i915_gem_do_execbuffer.isra.23+0x694/0x1020 [i915] } hitcount: 1519 bytes_req: 472936 | |
| 481 | { call_site: [ffffffffa045e646] i915_gem_do_execbuffer.isra.23+0x516/0x1020 [i915] } hitcount: 3050 bytes_req: 211832 | |
| 482 | { call_site: [ffffffff811e2a1b] seq_buf_alloc+0x1b/0x50 } hitcount: 34 bytes_req: 148384 | |
| 483 | { call_site: [ffffffffa04a580c] intel_crtc_page_flip+0xbc/0x870 [i915] } hitcount: 1385 bytes_req: 144040 | |
| 484 | { call_site: [ffffffff811ae8e1] __kmalloc+0x191/0x1b0 } hitcount: 8 bytes_req: 131072 | |
| 485 | { call_site: [ffffffffa0287592] drm_mode_page_flip_ioctl+0x282/0x360 [drm] } hitcount: 1385 bytes_req: 121880 | |
| 486 | { call_site: [ffffffffa02911f2] drm_modeset_lock_crtc+0x32/0x100 [drm] } hitcount: 1848 bytes_req: 103488 | |
| 487 | { call_site: [ffffffffa04c4a3c] intel_plane_duplicate_state+0x2c/0xa0 [i915] } hitcount: 461 bytes_req: 62696 | |
| 488 | { call_site: [ffffffffa029070e] drm_vma_node_allow+0x2e/0xd0 [drm] } hitcount: 1541 bytes_req: 61640 | |
| 489 | { call_site: [ffffffff815f8d7b] sk_prot_alloc+0xcb/0x1b0 } hitcount: 57 bytes_req: 57456 | |
| 490 | . | |
| 491 | . | |
| 492 | . | |
| 493 | { call_site: [ffffffff8109524a] alloc_fair_sched_group+0x5a/0x1a0 } hitcount: 2 bytes_req: 128 | |
| 494 | { call_site: [ffffffffa027b921] drm_vm_open_locked+0x31/0xa0 [drm] } hitcount: 3 bytes_req: 96 | |
| 495 | { call_site: [ffffffff8122e266] proc_self_follow_link+0x76/0xb0 } hitcount: 8 bytes_req: 96 | |
| 496 | { call_site: [ffffffff81213e80] load_elf_binary+0x240/0x1650 } hitcount: 3 bytes_req: 84 | |
| 497 | { call_site: [ffffffff8154bc62] usb_control_msg+0x42/0x110 } hitcount: 1 bytes_req: 8 | |
| 498 | { call_site: [ffffffffa00bf6fe] hidraw_send_report+0x7e/0x1a0 [hid] } hitcount: 1 bytes_req: 7 | |
| 499 | { call_site: [ffffffffa00bf1ca] hidraw_report_event+0x8a/0x120 [hid] } hitcount: 1 bytes_req: 7 | |
| 500 | ||
| 501 | Totals: | |
| 502 | Hits: 26098 | |
| 503 | Entries: 64 | |
| 504 | Dropped: 0 | |
| 505 | ||
| 506 | We can also add multiple fields to the 'values' parameter. For | |
| 507 | example, we might want to see the total number of bytes allocated | |
| 508 | alongside bytes requested, and display the result sorted by bytes | |
| ea272257 | 509 | allocated in a descending order:: |
| b8df4a36 TZ |
510 | |
| 511 | # echo 'hist:keys=call_site.sym:values=bytes_req,bytes_alloc:sort=bytes_alloc.descending' > \ | |
| 512 | /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger | |
| 513 | ||
| 514 | # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/hist | |
| 515 | # trigger info: hist:keys=call_site.sym:vals=bytes_req,bytes_alloc:sort=bytes_alloc.descending:size=2048 [active] | |
| 516 | ||
| 517 | { call_site: [ffffffffa046041c] i915_gem_execbuffer2 [i915] } hitcount: 7403 bytes_req: 4084360 bytes_alloc: 5958016 | |
| 518 | { call_site: [ffffffff811e2a1b] seq_buf_alloc } hitcount: 541 bytes_req: 2213968 bytes_alloc: 2228224 | |
| 519 | { call_site: [ffffffffa0489a66] intel_ring_begin [i915] } hitcount: 7404 bytes_req: 1066176 bytes_alloc: 1421568 | |
| 520 | { call_site: [ffffffffa045e7c4] i915_gem_do_execbuffer.isra.23 [i915] } hitcount: 1565 bytes_req: 557368 bytes_alloc: 1037760 | |
| 521 | { call_site: [ffffffff8125847d] ext4_htree_store_dirent } hitcount: 9557 bytes_req: 595778 bytes_alloc: 695744 | |
| 522 | { call_site: [ffffffffa045e646] i915_gem_do_execbuffer.isra.23 [i915] } hitcount: 5839 bytes_req: 430680 bytes_alloc: 470400 | |
| 523 | { call_site: [ffffffffa04c4a3c] intel_plane_duplicate_state [i915] } hitcount: 2388 bytes_req: 324768 bytes_alloc: 458496 | |
| 524 | { call_site: [ffffffffa02911f2] drm_modeset_lock_crtc [drm] } hitcount: 3911 bytes_req: 219016 bytes_alloc: 250304 | |
| 525 | { call_site: [ffffffff815f8d7b] sk_prot_alloc } hitcount: 235 bytes_req: 236880 bytes_alloc: 240640 | |
| 526 | { call_site: [ffffffff8137e559] sg_kmalloc } hitcount: 557 bytes_req: 169024 bytes_alloc: 221760 | |
| 527 | { call_site: [ffffffffa00b7c06] hid_report_raw_event [hid] } hitcount: 9378 bytes_req: 187548 bytes_alloc: 206312 | |
| 528 | { call_site: [ffffffffa04a580c] intel_crtc_page_flip [i915] } hitcount: 1519 bytes_req: 157976 bytes_alloc: 194432 | |
| 529 | . | |
| 530 | . | |
| 531 | . | |
| 532 | { call_site: [ffffffff8109bd3b] sched_autogroup_create_attach } hitcount: 2 bytes_req: 144 bytes_alloc: 192 | |
| 533 | { call_site: [ffffffff81097ee8] alloc_rt_sched_group } hitcount: 2 bytes_req: 128 bytes_alloc: 128 | |
| 534 | { call_site: [ffffffff8109524a] alloc_fair_sched_group } hitcount: 2 bytes_req: 128 bytes_alloc: 128 | |
| 535 | { call_site: [ffffffff81095225] alloc_fair_sched_group } hitcount: 2 bytes_req: 128 bytes_alloc: 128 | |
| 536 | { call_site: [ffffffff81097ec2] alloc_rt_sched_group } hitcount: 2 bytes_req: 128 bytes_alloc: 128 | |
| 537 | { call_site: [ffffffff81213e80] load_elf_binary } hitcount: 3 bytes_req: 84 bytes_alloc: 96 | |
| 538 | { call_site: [ffffffff81079a2e] kthread_create_on_node } hitcount: 1 bytes_req: 56 bytes_alloc: 64 | |
| 539 | { call_site: [ffffffffa00bf6fe] hidraw_send_report [hid] } hitcount: 1 bytes_req: 7 bytes_alloc: 8 | |
| 540 | { call_site: [ffffffff8154bc62] usb_control_msg } hitcount: 1 bytes_req: 8 bytes_alloc: 8 | |
| 541 | { call_site: [ffffffffa00bf1ca] hidraw_report_event [hid] } hitcount: 1 bytes_req: 7 bytes_alloc: 8 | |
| 542 | ||
| 543 | Totals: | |
| 544 | Hits: 66598 | |
| 545 | Entries: 65 | |
| 546 | Dropped: 0 | |
| 547 | ||
| 548 | Finally, to finish off our kmalloc example, instead of simply having | |
| 549 | the hist trigger display symbolic call_sites, we can have the hist | |
| 550 | trigger additionally display the complete set of kernel stack traces | |
| 551 | that led to each call_site. To do that, we simply use the special | |
| ea272257 | 552 | value 'stacktrace' for the key parameter:: |
| b8df4a36 TZ |
553 | |
| 554 | # echo 'hist:keys=stacktrace:values=bytes_req,bytes_alloc:sort=bytes_alloc' > \ | |
| 555 | /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger | |
| 556 | ||
| 557 | The above trigger will use the kernel stack trace in effect when an | |
| 558 | event is triggered as the key for the hash table. This allows the | |
| 559 | enumeration of every kernel callpath that led up to a particular | |
| 560 | event, along with a running total of any of the event fields for | |
| 561 | that event. Here we tally bytes requested and bytes allocated for | |
| 562 | every callpath in the system that led up to a kmalloc (in this case | |
| ea272257 | 563 | every callpath to a kmalloc for a kernel compile):: |
| b8df4a36 TZ |
564 | |
| 565 | # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/hist | |
| 566 | # trigger info: hist:keys=stacktrace:vals=bytes_req,bytes_alloc:sort=bytes_alloc:size=2048 [active] | |
| 567 | ||
| 568 | { stacktrace: | |
| 569 | __kmalloc_track_caller+0x10b/0x1a0 | |
| 570 | kmemdup+0x20/0x50 | |
| 571 | hidraw_report_event+0x8a/0x120 [hid] | |
| 572 | hid_report_raw_event+0x3ea/0x440 [hid] | |
| 573 | hid_input_report+0x112/0x190 [hid] | |
| 574 | hid_irq_in+0xc2/0x260 [usbhid] | |
| 575 | __usb_hcd_giveback_urb+0x72/0x120 | |
| 576 | usb_giveback_urb_bh+0x9e/0xe0 | |
| 577 | tasklet_hi_action+0xf8/0x100 | |
| 578 | __do_softirq+0x114/0x2c0 | |
| 579 | irq_exit+0xa5/0xb0 | |
| 580 | do_IRQ+0x5a/0xf0 | |
| 581 | ret_from_intr+0x0/0x30 | |
| 582 | cpuidle_enter+0x17/0x20 | |
| 583 | cpu_startup_entry+0x315/0x3e0 | |
| 584 | rest_init+0x7c/0x80 | |
| 585 | } hitcount: 3 bytes_req: 21 bytes_alloc: 24 | |
| 586 | { stacktrace: | |
| 587 | __kmalloc_track_caller+0x10b/0x1a0 | |
| 588 | kmemdup+0x20/0x50 | |
| 589 | hidraw_report_event+0x8a/0x120 [hid] | |
| 590 | hid_report_raw_event+0x3ea/0x440 [hid] | |
| 591 | hid_input_report+0x112/0x190 [hid] | |
| 592 | hid_irq_in+0xc2/0x260 [usbhid] | |
| 593 | __usb_hcd_giveback_urb+0x72/0x120 | |
| 594 | usb_giveback_urb_bh+0x9e/0xe0 | |
| 595 | tasklet_hi_action+0xf8/0x100 | |
| 596 | __do_softirq+0x114/0x2c0 | |
| 597 | irq_exit+0xa5/0xb0 | |
| 598 | do_IRQ+0x5a/0xf0 | |
| 599 | ret_from_intr+0x0/0x30 | |
| 600 | } hitcount: 3 bytes_req: 21 bytes_alloc: 24 | |
| 601 | { stacktrace: | |
| 602 | kmem_cache_alloc_trace+0xeb/0x150 | |
| 603 | aa_alloc_task_context+0x27/0x40 | |
| 604 | apparmor_cred_prepare+0x1f/0x50 | |
| 605 | security_prepare_creds+0x16/0x20 | |
| 606 | prepare_creds+0xdf/0x1a0 | |
| 607 | SyS_capset+0xb5/0x200 | |
| 608 | system_call_fastpath+0x12/0x6a | |
| 609 | } hitcount: 1 bytes_req: 32 bytes_alloc: 32 | |
| 610 | . | |
| 611 | . | |
| 612 | . | |
| 613 | { stacktrace: | |
| 614 | __kmalloc+0x11b/0x1b0 | |
| 615 | i915_gem_execbuffer2+0x6c/0x2c0 [i915] | |
| 616 | drm_ioctl+0x349/0x670 [drm] | |
| 617 | do_vfs_ioctl+0x2f0/0x4f0 | |
| 618 | SyS_ioctl+0x81/0xa0 | |
| 619 | system_call_fastpath+0x12/0x6a | |
| 620 | } hitcount: 17726 bytes_req: 13944120 bytes_alloc: 19593808 | |
| 621 | { stacktrace: | |
| 622 | __kmalloc+0x11b/0x1b0 | |
| 623 | load_elf_phdrs+0x76/0xa0 | |
| 624 | load_elf_binary+0x102/0x1650 | |
| 625 | search_binary_handler+0x97/0x1d0 | |
| 626 | do_execveat_common.isra.34+0x551/0x6e0 | |
| 627 | SyS_execve+0x3a/0x50 | |
| 628 | return_from_execve+0x0/0x23 | |
| 629 | } hitcount: 33348 bytes_req: 17152128 bytes_alloc: 20226048 | |
| 630 | { stacktrace: | |
| 631 | kmem_cache_alloc_trace+0xeb/0x150 | |
| 632 | apparmor_file_alloc_security+0x27/0x40 | |
| 633 | security_file_alloc+0x16/0x20 | |
| 634 | get_empty_filp+0x93/0x1c0 | |
| 635 | path_openat+0x31/0x5f0 | |
| 636 | do_filp_open+0x3a/0x90 | |
| 637 | do_sys_open+0x128/0x220 | |
| 638 | SyS_open+0x1e/0x20 | |
| 639 | system_call_fastpath+0x12/0x6a | |
| 640 | } hitcount: 4766422 bytes_req: 9532844 bytes_alloc: 38131376 | |
| 641 | { stacktrace: | |
| 642 | __kmalloc+0x11b/0x1b0 | |
| 643 | seq_buf_alloc+0x1b/0x50 | |
| 644 | seq_read+0x2cc/0x370 | |
| 645 | proc_reg_read+0x3d/0x80 | |
| 646 | __vfs_read+0x28/0xe0 | |
| 647 | vfs_read+0x86/0x140 | |
| 648 | SyS_read+0x46/0xb0 | |
| 649 | system_call_fastpath+0x12/0x6a | |
| 650 | } hitcount: 19133 bytes_req: 78368768 bytes_alloc: 78368768 | |
| 651 | ||
| 652 | Totals: | |
| 653 | Hits: 6085872 | |
| 654 | Entries: 253 | |
| 655 | Dropped: 0 | |
| 656 | ||
| 657 | If you key a hist trigger on common_pid, in order for example to | |
| 658 | gather and display sorted totals for each process, you can use the | |
| 659 | special .execname modifier to display the executable names for the | |
| 660 | processes in the table rather than raw pids. The example below | |
| ea272257 | 661 | keeps a per-process sum of total bytes read:: |
| b8df4a36 TZ |
662 | |
| 663 | # echo 'hist:key=common_pid.execname:val=count:sort=count.descending' > \ | |
| 664 | /sys/kernel/debug/tracing/events/syscalls/sys_enter_read/trigger | |
| 665 | ||
| 666 | # cat /sys/kernel/debug/tracing/events/syscalls/sys_enter_read/hist | |
| 667 | # trigger info: hist:keys=common_pid.execname:vals=count:sort=count.descending:size=2048 [active] | |
| 668 | ||
| 669 | { common_pid: gnome-terminal [ 3196] } hitcount: 280 count: 1093512 | |
| 670 | { common_pid: Xorg [ 1309] } hitcount: 525 count: 256640 | |
| 671 | { common_pid: compiz [ 2889] } hitcount: 59 count: 254400 | |
| 672 | { common_pid: bash [ 8710] } hitcount: 3 count: 66369 | |
| 673 | { common_pid: dbus-daemon-lau [ 8703] } hitcount: 49 count: 47739 | |
| 674 | { common_pid: irqbalance [ 1252] } hitcount: 27 count: 27648 | |
| 675 | { common_pid: 01ifupdown [ 8705] } hitcount: 3 count: 17216 | |
| 676 | { common_pid: dbus-daemon [ 772] } hitcount: 10 count: 12396 | |
| 677 | { common_pid: Socket Thread [ 8342] } hitcount: 11 count: 11264 | |
| 678 | { common_pid: nm-dhcp-client. [ 8701] } hitcount: 6 count: 7424 | |
| 679 | { common_pid: gmain [ 1315] } hitcount: 18 count: 6336 | |
| 680 | . | |
| 681 | . | |
| 682 | . | |
| 683 | { common_pid: postgres [ 1892] } hitcount: 2 count: 32 | |
| 684 | { common_pid: postgres [ 1891] } hitcount: 2 count: 32 | |
| 685 | { common_pid: gmain [ 8704] } hitcount: 2 count: 32 | |
| 686 | { common_pid: upstart-dbus-br [ 2740] } hitcount: 21 count: 21 | |
| 687 | { common_pid: nm-dispatcher.a [ 8696] } hitcount: 1 count: 16 | |
| 688 | { common_pid: indicator-datet [ 2904] } hitcount: 1 count: 16 | |
| 689 | { common_pid: gdbus [ 2998] } hitcount: 1 count: 16 | |
| 690 | { common_pid: rtkit-daemon [ 2052] } hitcount: 1 count: 8 | |
| 691 | { common_pid: init [ 1] } hitcount: 2 count: 2 | |
| 692 | ||
| 693 | Totals: | |
| 694 | Hits: 2116 | |
| 695 | Entries: 51 | |
| 696 | Dropped: 0 | |
| 697 | ||
| 698 | Similarly, if you key a hist trigger on syscall id, for example to | |
| 699 | gather and display a list of systemwide syscall hits, you can use | |
| 700 | the special .syscall modifier to display the syscall names rather | |
| 701 | than raw ids. The example below keeps a running total of syscall | |
| ea272257 | 702 | counts for the system during the run:: |
| b8df4a36 TZ |
703 | |
| 704 | # echo 'hist:key=id.syscall:val=hitcount' > \ | |
| 705 | /sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/trigger | |
| 706 | ||
| 707 | # cat /sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/hist | |
| 708 | # trigger info: hist:keys=id.syscall:vals=hitcount:sort=hitcount:size=2048 [active] | |
| 709 | ||
| 710 | { id: sys_fsync [ 74] } hitcount: 1 | |
| 711 | { id: sys_newuname [ 63] } hitcount: 1 | |
| 712 | { id: sys_prctl [157] } hitcount: 1 | |
| 713 | { id: sys_statfs [137] } hitcount: 1 | |
| 714 | { id: sys_symlink [ 88] } hitcount: 1 | |
| 715 | { id: sys_sendmmsg [307] } hitcount: 1 | |
| 716 | { id: sys_semctl [ 66] } hitcount: 1 | |
| 717 | { id: sys_readlink [ 89] } hitcount: 3 | |
| 718 | { id: sys_bind [ 49] } hitcount: 3 | |
| 719 | { id: sys_getsockname [ 51] } hitcount: 3 | |
| 720 | { id: sys_unlink [ 87] } hitcount: 3 | |
| 721 | { id: sys_rename [ 82] } hitcount: 4 | |
| 722 | { id: unknown_syscall [ 58] } hitcount: 4 | |
| 723 | { id: sys_connect [ 42] } hitcount: 4 | |
| 724 | { id: sys_getpid [ 39] } hitcount: 4 | |
| 725 | . | |
| 726 | . | |
| 727 | . | |
| 728 | { id: sys_rt_sigprocmask [ 14] } hitcount: 952 | |
| 729 | { id: sys_futex [202] } hitcount: 1534 | |
| 730 | { id: sys_write [ 1] } hitcount: 2689 | |
| 731 | { id: sys_setitimer [ 38] } hitcount: 2797 | |
| 732 | { id: sys_read [ 0] } hitcount: 3202 | |
| 733 | { id: sys_select [ 23] } hitcount: 3773 | |
| 734 | { id: sys_writev [ 20] } hitcount: 4531 | |
| 735 | { id: sys_poll [ 7] } hitcount: 8314 | |
| 736 | { id: sys_recvmsg [ 47] } hitcount: 13738 | |
| 737 | { id: sys_ioctl [ 16] } hitcount: 21843 | |
| 738 | ||
| 739 | Totals: | |
| 740 | Hits: 67612 | |
| 741 | Entries: 72 | |
| 742 | Dropped: 0 | |
| 743 | ||
| ea272257 MCC |
744 | The syscall counts above provide a rough overall picture of system |
| 745 | call activity on the system; we can see for example that the most | |
| 746 | popular system call on this system was the 'sys_ioctl' system call. | |
| b8df4a36 | 747 | |
| ea272257 MCC |
748 | We can use 'compound' keys to refine that number and provide some |
| 749 | further insight as to which processes exactly contribute to the | |
| 750 | overall ioctl count. | |
| b8df4a36 | 751 | |
| ea272257 MCC |
752 | The command below keeps a hitcount for every unique combination of |
| 753 | system call id and pid - the end result is essentially a table | |
| 754 | that keeps a per-pid sum of system call hits. The results are | |
| 755 | sorted using the system call id as the primary key, and the | |
| 756 | hitcount sum as the secondary key:: | |
| b8df4a36 TZ |
757 | |
| 758 | # echo 'hist:key=id.syscall,common_pid.execname:val=hitcount:sort=id,hitcount' > \ | |
| 759 | /sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/trigger | |
| 760 | ||
| 761 | # cat /sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/hist | |
| 762 | # trigger info: hist:keys=id.syscall,common_pid.execname:vals=hitcount:sort=id.syscall,hitcount:size=2048 [active] | |
| 763 | ||
| 764 | { id: sys_read [ 0], common_pid: rtkit-daemon [ 1877] } hitcount: 1 | |
| 765 | { id: sys_read [ 0], common_pid: gdbus [ 2976] } hitcount: 1 | |
| 766 | { id: sys_read [ 0], common_pid: console-kit-dae [ 3400] } hitcount: 1 | |
| 767 | { id: sys_read [ 0], common_pid: postgres [ 1865] } hitcount: 1 | |
| 768 | { id: sys_read [ 0], common_pid: deja-dup-monito [ 3543] } hitcount: 2 | |
| 769 | { id: sys_read [ 0], common_pid: NetworkManager [ 890] } hitcount: 2 | |
| 770 | { id: sys_read [ 0], common_pid: evolution-calen [ 3048] } hitcount: 2 | |
| 771 | { id: sys_read [ 0], common_pid: postgres [ 1864] } hitcount: 2 | |
| 772 | { id: sys_read [ 0], common_pid: nm-applet [ 3022] } hitcount: 2 | |
| 773 | { id: sys_read [ 0], common_pid: whoopsie [ 1212] } hitcount: 2 | |
| 774 | . | |
| 775 | . | |
| 776 | . | |
| 777 | { id: sys_ioctl [ 16], common_pid: bash [ 8479] } hitcount: 1 | |
| 778 | { id: sys_ioctl [ 16], common_pid: bash [ 3472] } hitcount: 12 | |
| 779 | { id: sys_ioctl [ 16], common_pid: gnome-terminal [ 3199] } hitcount: 16 | |
| 780 | { id: sys_ioctl [ 16], common_pid: Xorg [ 1267] } hitcount: 1808 | |
| 781 | { id: sys_ioctl [ 16], common_pid: compiz [ 2994] } hitcount: 5580 | |
| 782 | . | |
| 783 | . | |
| 784 | . | |
| 785 | { id: sys_waitid [247], common_pid: upstart-dbus-br [ 2690] } hitcount: 3 | |
| 786 | { id: sys_waitid [247], common_pid: upstart-dbus-br [ 2688] } hitcount: 16 | |
| 787 | { id: sys_inotify_add_watch [254], common_pid: gmain [ 975] } hitcount: 2 | |
| 788 | { id: sys_inotify_add_watch [254], common_pid: gmain [ 3204] } hitcount: 4 | |
| 789 | { id: sys_inotify_add_watch [254], common_pid: gmain [ 2888] } hitcount: 4 | |
| 790 | { id: sys_inotify_add_watch [254], common_pid: gmain [ 3003] } hitcount: 4 | |
| 791 | { id: sys_inotify_add_watch [254], common_pid: gmain [ 2873] } hitcount: 4 | |
| 792 | { id: sys_inotify_add_watch [254], common_pid: gmain [ 3196] } hitcount: 6 | |
| 793 | { id: sys_openat [257], common_pid: java [ 2623] } hitcount: 2 | |
| 794 | { id: sys_eventfd2 [290], common_pid: ibus-ui-gtk3 [ 2760] } hitcount: 4 | |
| 795 | { id: sys_eventfd2 [290], common_pid: compiz [ 2994] } hitcount: 6 | |
| 796 | ||
| 797 | Totals: | |
| 798 | Hits: 31536 | |
| 799 | Entries: 323 | |
| 800 | Dropped: 0 | |
| 801 | ||
| ea272257 MCC |
802 | The above list does give us a breakdown of the ioctl syscall by |
| 803 | pid, but it also gives us quite a bit more than that, which we | |
| 804 | don't really care about at the moment. Since we know the syscall | |
| 805 | id for sys_ioctl (16, displayed next to the sys_ioctl name), we | |
| 806 | can use that to filter out all the other syscalls:: | |
| b8df4a36 TZ |
807 | |
| 808 | # echo 'hist:key=id.syscall,common_pid.execname:val=hitcount:sort=id,hitcount if id == 16' > \ | |
| 809 | /sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/trigger | |
| 810 | ||
| 811 | # cat /sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/hist | |
| 812 | # trigger info: hist:keys=id.syscall,common_pid.execname:vals=hitcount:sort=id.syscall,hitcount:size=2048 if id == 16 [active] | |
| 813 | ||
| 814 | { id: sys_ioctl [ 16], common_pid: gmain [ 2769] } hitcount: 1 | |
| 815 | { id: sys_ioctl [ 16], common_pid: evolution-addre [ 8571] } hitcount: 1 | |
| 816 | { id: sys_ioctl [ 16], common_pid: gmain [ 3003] } hitcount: 1 | |
| 817 | { id: sys_ioctl [ 16], common_pid: gmain [ 2781] } hitcount: 1 | |
| 818 | { id: sys_ioctl [ 16], common_pid: gmain [ 2829] } hitcount: 1 | |
| 819 | { id: sys_ioctl [ 16], common_pid: bash [ 8726] } hitcount: 1 | |
| 820 | { id: sys_ioctl [ 16], common_pid: bash [ 8508] } hitcount: 1 | |
| 821 | { id: sys_ioctl [ 16], common_pid: gmain [ 2970] } hitcount: 1 | |
| 822 | { id: sys_ioctl [ 16], common_pid: gmain [ 2768] } hitcount: 1 | |
| 823 | . | |
| 824 | . | |
| 825 | . | |
| 826 | { id: sys_ioctl [ 16], common_pid: pool [ 8559] } hitcount: 45 | |
| 827 | { id: sys_ioctl [ 16], common_pid: pool [ 8555] } hitcount: 48 | |
| 828 | { id: sys_ioctl [ 16], common_pid: pool [ 8551] } hitcount: 48 | |
| 829 | { id: sys_ioctl [ 16], common_pid: avahi-daemon [ 896] } hitcount: 66 | |
| 830 | { id: sys_ioctl [ 16], common_pid: Xorg [ 1267] } hitcount: 26674 | |
| 831 | { id: sys_ioctl [ 16], common_pid: compiz [ 2994] } hitcount: 73443 | |
| 832 | ||
| 833 | Totals: | |
| 834 | Hits: 101162 | |
| 835 | Entries: 103 | |
| 836 | Dropped: 0 | |
| 837 | ||
| ea272257 MCC |
838 | The above output shows that 'compiz' and 'Xorg' are far and away |
| 839 | the heaviest ioctl callers (which might lead to questions about | |
| 840 | whether they really need to be making all those calls and to | |
| 841 | possible avenues for further investigation.) | |
| b8df4a36 | 842 | |
| ea272257 MCC |
843 | The compound key examples used a key and a sum value (hitcount) to |
| 844 | sort the output, but we can just as easily use two keys instead. | |
| 845 | Here's an example where we use a compound key composed of the the | |
| 846 | common_pid and size event fields. Sorting with pid as the primary | |
| 847 | key and 'size' as the secondary key allows us to display an | |
| 848 | ordered summary of the recvfrom sizes, with counts, received by | |
| 849 | each process:: | |
| b8df4a36 TZ |
850 | |
| 851 | # echo 'hist:key=common_pid.execname,size:val=hitcount:sort=common_pid,size' > \ | |
| 852 | /sys/kernel/debug/tracing/events/syscalls/sys_enter_recvfrom/trigger | |
| 853 | ||
| 854 | # cat /sys/kernel/debug/tracing/events/syscalls/sys_enter_recvfrom/hist | |
| 855 | # trigger info: hist:keys=common_pid.execname,size:vals=hitcount:sort=common_pid.execname,size:size=2048 [active] | |
| 856 | ||
| 857 | { common_pid: smbd [ 784], size: 4 } hitcount: 1 | |
| 858 | { common_pid: dnsmasq [ 1412], size: 4096 } hitcount: 672 | |
| 859 | { common_pid: postgres [ 1796], size: 1000 } hitcount: 6 | |
| 860 | { common_pid: postgres [ 1867], size: 1000 } hitcount: 10 | |
| 861 | { common_pid: bamfdaemon [ 2787], size: 28 } hitcount: 2 | |
| 862 | { common_pid: bamfdaemon [ 2787], size: 14360 } hitcount: 1 | |
| 863 | { common_pid: compiz [ 2994], size: 8 } hitcount: 1 | |
| 864 | { common_pid: compiz [ 2994], size: 20 } hitcount: 11 | |
| 865 | { common_pid: gnome-terminal [ 3199], size: 4 } hitcount: 2 | |
| 866 | { common_pid: firefox [ 8817], size: 4 } hitcount: 1 | |
| 867 | { common_pid: firefox [ 8817], size: 8 } hitcount: 5 | |
| 868 | { common_pid: firefox [ 8817], size: 588 } hitcount: 2 | |
| 869 | { common_pid: firefox [ 8817], size: 628 } hitcount: 1 | |
| 870 | { common_pid: firefox [ 8817], size: 6944 } hitcount: 1 | |
| 871 | { common_pid: firefox [ 8817], size: 408880 } hitcount: 2 | |
| 872 | { common_pid: firefox [ 8822], size: 8 } hitcount: 2 | |
| 873 | { common_pid: firefox [ 8822], size: 160 } hitcount: 2 | |
| 874 | { common_pid: firefox [ 8822], size: 320 } hitcount: 2 | |
| 875 | { common_pid: firefox [ 8822], size: 352 } hitcount: 1 | |
| 876 | . | |
| 877 | . | |
| 878 | . | |
| 879 | { common_pid: pool [ 8923], size: 1960 } hitcount: 10 | |
| 880 | { common_pid: pool [ 8923], size: 2048 } hitcount: 10 | |
| 881 | { common_pid: pool [ 8924], size: 1960 } hitcount: 10 | |
| 882 | { common_pid: pool [ 8924], size: 2048 } hitcount: 10 | |
| 883 | { common_pid: pool [ 8928], size: 1964 } hitcount: 4 | |
| 884 | { common_pid: pool [ 8928], size: 1965 } hitcount: 2 | |
| 885 | { common_pid: pool [ 8928], size: 2048 } hitcount: 6 | |
| 886 | { common_pid: pool [ 8929], size: 1982 } hitcount: 1 | |
| 887 | { common_pid: pool [ 8929], size: 2048 } hitcount: 1 | |
| 888 | ||
| 889 | Totals: | |
| 890 | Hits: 2016 | |
| 891 | Entries: 224 | |
| 892 | Dropped: 0 | |
| 893 | ||
| 894 | The above example also illustrates the fact that although a compound | |
| 895 | key is treated as a single entity for hashing purposes, the sub-keys | |
| 896 | it's composed of can be accessed independently. | |
| 897 | ||
| 898 | The next example uses a string field as the hash key and | |
| 899 | demonstrates how you can manually pause and continue a hist trigger. | |
| 900 | In this example, we'll aggregate fork counts and don't expect a | |
| 901 | large number of entries in the hash table, so we'll drop it to a | |
| ea272257 | 902 | much smaller number, say 256:: |
| b8df4a36 TZ |
903 | |
| 904 | # echo 'hist:key=child_comm:val=hitcount:size=256' > \ | |
| 905 | /sys/kernel/debug/tracing/events/sched/sched_process_fork/trigger | |
| 906 | ||
| 907 | # cat /sys/kernel/debug/tracing/events/sched/sched_process_fork/hist | |
| 908 | # trigger info: hist:keys=child_comm:vals=hitcount:sort=hitcount:size=256 [active] | |
| 909 | ||
| 910 | { child_comm: dconf worker } hitcount: 1 | |
| 911 | { child_comm: ibus-daemon } hitcount: 1 | |
| 912 | { child_comm: whoopsie } hitcount: 1 | |
| 913 | { child_comm: smbd } hitcount: 1 | |
| 914 | { child_comm: gdbus } hitcount: 1 | |
| 915 | { child_comm: kthreadd } hitcount: 1 | |
| 916 | { child_comm: dconf worker } hitcount: 1 | |
| 917 | { child_comm: evolution-alarm } hitcount: 2 | |
| 918 | { child_comm: Socket Thread } hitcount: 2 | |
| 919 | { child_comm: postgres } hitcount: 2 | |
| 920 | { child_comm: bash } hitcount: 3 | |
| 921 | { child_comm: compiz } hitcount: 3 | |
| 922 | { child_comm: evolution-sourc } hitcount: 4 | |
| 923 | { child_comm: dhclient } hitcount: 4 | |
| 924 | { child_comm: pool } hitcount: 5 | |
| 925 | { child_comm: nm-dispatcher.a } hitcount: 8 | |
| 926 | { child_comm: firefox } hitcount: 8 | |
| 927 | { child_comm: dbus-daemon } hitcount: 8 | |
| 928 | { child_comm: glib-pacrunner } hitcount: 10 | |
| 929 | { child_comm: evolution } hitcount: 23 | |
| 930 | ||
| 931 | Totals: | |
| 932 | Hits: 89 | |
| 933 | Entries: 20 | |
| 934 | Dropped: 0 | |
| 935 | ||
| 936 | If we want to pause the hist trigger, we can simply append :pause to | |
| 937 | the command that started the trigger. Notice that the trigger info | |
| ea272257 | 938 | displays as [paused]:: |
| b8df4a36 TZ |
939 | |
| 940 | # echo 'hist:key=child_comm:val=hitcount:size=256:pause' >> \ | |
| 941 | /sys/kernel/debug/tracing/events/sched/sched_process_fork/trigger | |
| 942 | ||
| 943 | # cat /sys/kernel/debug/tracing/events/sched/sched_process_fork/hist | |
| 944 | # trigger info: hist:keys=child_comm:vals=hitcount:sort=hitcount:size=256 [paused] | |
| 945 | ||
| 946 | { child_comm: dconf worker } hitcount: 1 | |
| 947 | { child_comm: kthreadd } hitcount: 1 | |
| 948 | { child_comm: dconf worker } hitcount: 1 | |
| 949 | { child_comm: gdbus } hitcount: 1 | |
| 950 | { child_comm: ibus-daemon } hitcount: 1 | |
| 951 | { child_comm: Socket Thread } hitcount: 2 | |
| 952 | { child_comm: evolution-alarm } hitcount: 2 | |
| 953 | { child_comm: smbd } hitcount: 2 | |
| 954 | { child_comm: bash } hitcount: 3 | |
| 955 | { child_comm: whoopsie } hitcount: 3 | |
| 956 | { child_comm: compiz } hitcount: 3 | |
| 957 | { child_comm: evolution-sourc } hitcount: 4 | |
| 958 | { child_comm: pool } hitcount: 5 | |
| 959 | { child_comm: postgres } hitcount: 6 | |
| 960 | { child_comm: firefox } hitcount: 8 | |
| 961 | { child_comm: dhclient } hitcount: 10 | |
| 962 | { child_comm: emacs } hitcount: 12 | |
| 963 | { child_comm: dbus-daemon } hitcount: 20 | |
| 964 | { child_comm: nm-dispatcher.a } hitcount: 20 | |
| 965 | { child_comm: evolution } hitcount: 35 | |
| 966 | { child_comm: glib-pacrunner } hitcount: 59 | |
| 967 | ||
| 968 | Totals: | |
| 969 | Hits: 199 | |
| 970 | Entries: 21 | |
| 971 | Dropped: 0 | |
| 972 | ||
| 973 | To manually continue having the trigger aggregate events, append | |
| 974 | :cont instead. Notice that the trigger info displays as [active] | |
| ea272257 | 975 | again, and the data has changed:: |
| b8df4a36 TZ |
976 | |
| 977 | # echo 'hist:key=child_comm:val=hitcount:size=256:cont' >> \ | |
| 978 | /sys/kernel/debug/tracing/events/sched/sched_process_fork/trigger | |
| 979 | ||
| 980 | # cat /sys/kernel/debug/tracing/events/sched/sched_process_fork/hist | |
| 981 | # trigger info: hist:keys=child_comm:vals=hitcount:sort=hitcount:size=256 [active] | |
| 982 | ||
| 983 | { child_comm: dconf worker } hitcount: 1 | |
| 984 | { child_comm: dconf worker } hitcount: 1 | |
| 985 | { child_comm: kthreadd } hitcount: 1 | |
| 986 | { child_comm: gdbus } hitcount: 1 | |
| 987 | { child_comm: ibus-daemon } hitcount: 1 | |
| 988 | { child_comm: Socket Thread } hitcount: 2 | |
| 989 | { child_comm: evolution-alarm } hitcount: 2 | |
| 990 | { child_comm: smbd } hitcount: 2 | |
| 991 | { child_comm: whoopsie } hitcount: 3 | |
| 992 | { child_comm: compiz } hitcount: 3 | |
| 993 | { child_comm: evolution-sourc } hitcount: 4 | |
| 994 | { child_comm: bash } hitcount: 5 | |
| 995 | { child_comm: pool } hitcount: 5 | |
| 996 | { child_comm: postgres } hitcount: 6 | |
| 997 | { child_comm: firefox } hitcount: 8 | |
| 998 | { child_comm: dhclient } hitcount: 11 | |
| 999 | { child_comm: emacs } hitcount: 12 | |
| 1000 | { child_comm: dbus-daemon } hitcount: 22 | |
| 1001 | { child_comm: nm-dispatcher.a } hitcount: 22 | |
| 1002 | { child_comm: evolution } hitcount: 35 | |
| 1003 | { child_comm: glib-pacrunner } hitcount: 59 | |
| 1004 | ||
| 1005 | Totals: | |
| 1006 | Hits: 206 | |
| 1007 | Entries: 21 | |
| 1008 | Dropped: 0 | |
| 1009 | ||
| 1010 | The previous example showed how to start and stop a hist trigger by | |
| 1011 | appending 'pause' and 'continue' to the hist trigger command. A | |
| 1012 | hist trigger can also be started in a paused state by initially | |
| 1013 | starting the trigger with ':pause' appended. This allows you to | |
| 1014 | start the trigger only when you're ready to start collecting data | |
| 1015 | and not before. For example, you could start the trigger in a | |
| 1016 | paused state, then unpause it and do something you want to measure, | |
| 1017 | then pause the trigger again when done. | |
| 1018 | ||
| 1019 | Of course, doing this manually can be difficult and error-prone, but | |
| 1020 | it is possible to automatically start and stop a hist trigger based | |
| 1021 | on some condition, via the enable_hist and disable_hist triggers. | |
| 1022 | ||
| 1023 | For example, suppose we wanted to take a look at the relative | |
| 1024 | weights in terms of skb length for each callpath that leads to a | |
| 1025 | netif_receieve_skb event when downloading a decent-sized file using | |
| 1026 | wget. | |
| 1027 | ||
| 1028 | First we set up an initially paused stacktrace trigger on the | |
| ea272257 | 1029 | netif_receive_skb event:: |
| b8df4a36 TZ |
1030 | |
| 1031 | # echo 'hist:key=stacktrace:vals=len:pause' > \ | |
| 1032 | /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger | |
| 1033 | ||
| 1034 | Next, we set up an 'enable_hist' trigger on the sched_process_exec | |
| 1035 | event, with an 'if filename==/usr/bin/wget' filter. The effect of | |
| 1036 | this new trigger is that it will 'unpause' the hist trigger we just | |
| 1037 | set up on netif_receive_skb if and only if it sees a | |
| 1038 | sched_process_exec event with a filename of '/usr/bin/wget'. When | |
| 1039 | that happens, all netif_receive_skb events are aggregated into a | |
| ea272257 | 1040 | hash table keyed on stacktrace:: |
| b8df4a36 TZ |
1041 | |
| 1042 | # echo 'enable_hist:net:netif_receive_skb if filename==/usr/bin/wget' > \ | |
| 1043 | /sys/kernel/debug/tracing/events/sched/sched_process_exec/trigger | |
| 1044 | ||
| 1045 | The aggregation continues until the netif_receive_skb is paused | |
| 1046 | again, which is what the following disable_hist event does by | |
| 1047 | creating a similar setup on the sched_process_exit event, using the | |
| ea272257 | 1048 | filter 'comm==wget':: |
| b8df4a36 TZ |
1049 | |
| 1050 | # echo 'disable_hist:net:netif_receive_skb if comm==wget' > \ | |
| 1051 | /sys/kernel/debug/tracing/events/sched/sched_process_exit/trigger | |
| 1052 | ||
| 1053 | Whenever a process exits and the comm field of the disable_hist | |
| 1054 | trigger filter matches 'comm==wget', the netif_receive_skb hist | |
| 1055 | trigger is disabled. | |
| 1056 | ||
| 1057 | The overall effect is that netif_receive_skb events are aggregated | |
| 1058 | into the hash table for only the duration of the wget. Executing a | |
| 1059 | wget command and then listing the 'hist' file will display the | |
| ea272257 | 1060 | output generated by the wget command:: |
| b8df4a36 TZ |
1061 | |
| 1062 | $ wget https://www.kernel.org/pub/linux/kernel/v3.x/patch-3.19.xz | |
| 1063 | ||
| 1064 | # cat /sys/kernel/debug/tracing/events/net/netif_receive_skb/hist | |
| 1065 | # trigger info: hist:keys=stacktrace:vals=len:sort=hitcount:size=2048 [paused] | |
| 1066 | ||
| 1067 | { stacktrace: | |
| 1068 | __netif_receive_skb_core+0x46d/0x990 | |
| 1069 | __netif_receive_skb+0x18/0x60 | |
| 1070 | netif_receive_skb_internal+0x23/0x90 | |
| 1071 | napi_gro_receive+0xc8/0x100 | |
| 1072 | ieee80211_deliver_skb+0xd6/0x270 [mac80211] | |
| 1073 | ieee80211_rx_handlers+0xccf/0x22f0 [mac80211] | |
| 1074 | ieee80211_prepare_and_rx_handle+0x4e7/0xc40 [mac80211] | |
| 1075 | ieee80211_rx+0x31d/0x900 [mac80211] | |
| 1076 | iwlagn_rx_reply_rx+0x3db/0x6f0 [iwldvm] | |
| 1077 | iwl_rx_dispatch+0x8e/0xf0 [iwldvm] | |
| 1078 | iwl_pcie_irq_handler+0xe3c/0x12f0 [iwlwifi] | |
| 1079 | irq_thread_fn+0x20/0x50 | |
| 1080 | irq_thread+0x11f/0x150 | |
| 1081 | kthread+0xd2/0xf0 | |
| 1082 | ret_from_fork+0x42/0x70 | |
| 1083 | } hitcount: 85 len: 28884 | |
| 1084 | { stacktrace: | |
| 1085 | __netif_receive_skb_core+0x46d/0x990 | |
| 1086 | __netif_receive_skb+0x18/0x60 | |
| 1087 | netif_receive_skb_internal+0x23/0x90 | |
| 1088 | napi_gro_complete+0xa4/0xe0 | |
| 1089 | dev_gro_receive+0x23a/0x360 | |
| 1090 | napi_gro_receive+0x30/0x100 | |
| 1091 | ieee80211_deliver_skb+0xd6/0x270 [mac80211] | |
| 1092 | ieee80211_rx_handlers+0xccf/0x22f0 [mac80211] | |
| 1093 | ieee80211_prepare_and_rx_handle+0x4e7/0xc40 [mac80211] | |
| 1094 | ieee80211_rx+0x31d/0x900 [mac80211] | |
| 1095 | iwlagn_rx_reply_rx+0x3db/0x6f0 [iwldvm] | |
| 1096 | iwl_rx_dispatch+0x8e/0xf0 [iwldvm] | |
| 1097 | iwl_pcie_irq_handler+0xe3c/0x12f0 [iwlwifi] | |
| 1098 | irq_thread_fn+0x20/0x50 | |
| 1099 | irq_thread+0x11f/0x150 | |
| 1100 | kthread+0xd2/0xf0 | |
| 1101 | } hitcount: 98 len: 664329 | |
| 1102 | { stacktrace: | |
| 1103 | __netif_receive_skb_core+0x46d/0x990 | |
| 1104 | __netif_receive_skb+0x18/0x60 | |
| 1105 | process_backlog+0xa8/0x150 | |
| 1106 | net_rx_action+0x15d/0x340 | |
| 1107 | __do_softirq+0x114/0x2c0 | |
| 1108 | do_softirq_own_stack+0x1c/0x30 | |
| 1109 | do_softirq+0x65/0x70 | |
| 1110 | __local_bh_enable_ip+0xb5/0xc0 | |
| 1111 | ip_finish_output+0x1f4/0x840 | |
| 1112 | ip_output+0x6b/0xc0 | |
| 1113 | ip_local_out_sk+0x31/0x40 | |
| 1114 | ip_send_skb+0x1a/0x50 | |
| 1115 | udp_send_skb+0x173/0x2a0 | |
| 1116 | udp_sendmsg+0x2bf/0x9f0 | |
| 1117 | inet_sendmsg+0x64/0xa0 | |
| 1118 | sock_sendmsg+0x3d/0x50 | |
| 1119 | } hitcount: 115 len: 13030 | |
| 1120 | { stacktrace: | |
| 1121 | __netif_receive_skb_core+0x46d/0x990 | |
| 1122 | __netif_receive_skb+0x18/0x60 | |
| 1123 | netif_receive_skb_internal+0x23/0x90 | |
| 1124 | napi_gro_complete+0xa4/0xe0 | |
| 1125 | napi_gro_flush+0x6d/0x90 | |
| 1126 | iwl_pcie_irq_handler+0x92a/0x12f0 [iwlwifi] | |
| 1127 | irq_thread_fn+0x20/0x50 | |
| 1128 | irq_thread+0x11f/0x150 | |
| 1129 | kthread+0xd2/0xf0 | |
| 1130 | ret_from_fork+0x42/0x70 | |
| 1131 | } hitcount: 934 len: 5512212 | |
| 1132 | ||
| 1133 | Totals: | |
| 1134 | Hits: 1232 | |
| 1135 | Entries: 4 | |
| 1136 | Dropped: 0 | |
| 1137 | ||
| 1138 | The above shows all the netif_receive_skb callpaths and their total | |
| 1139 | lengths for the duration of the wget command. | |
| 1140 | ||
| 1141 | The 'clear' hist trigger param can be used to clear the hash table. | |
| 1142 | Suppose we wanted to try another run of the previous example but | |
| 1143 | this time also wanted to see the complete list of events that went | |
| 1144 | into the histogram. In order to avoid having to set everything up | |
| ea272257 | 1145 | again, we can just clear the histogram first:: |
| b8df4a36 TZ |
1146 | |
| 1147 | # echo 'hist:key=stacktrace:vals=len:clear' >> \ | |
| 1148 | /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger | |
| 1149 | ||
| 1150 | Just to verify that it is in fact cleared, here's what we now see in | |
| ea272257 | 1151 | the hist file:: |
| b8df4a36 TZ |
1152 | |
| 1153 | # cat /sys/kernel/debug/tracing/events/net/netif_receive_skb/hist | |
| 1154 | # trigger info: hist:keys=stacktrace:vals=len:sort=hitcount:size=2048 [paused] | |
| 1155 | ||
| 1156 | Totals: | |
| 1157 | Hits: 0 | |
| 1158 | Entries: 0 | |
| 1159 | Dropped: 0 | |
| 1160 | ||
| 1161 | Since we want to see the detailed list of every netif_receive_skb | |
| 1162 | event occurring during the new run, which are in fact the same | |
| 1163 | events being aggregated into the hash table, we add some additional | |
| 1164 | 'enable_event' events to the triggering sched_process_exec and | |
| ea272257 | 1165 | sched_process_exit events as such:: |
| b8df4a36 TZ |
1166 | |
| 1167 | # echo 'enable_event:net:netif_receive_skb if filename==/usr/bin/wget' > \ | |
| 1168 | /sys/kernel/debug/tracing/events/sched/sched_process_exec/trigger | |
| 1169 | ||
| 1170 | # echo 'disable_event:net:netif_receive_skb if comm==wget' > \ | |
| 1171 | /sys/kernel/debug/tracing/events/sched/sched_process_exit/trigger | |
| 1172 | ||
| 1173 | If you read the trigger files for the sched_process_exec and | |
| 1174 | sched_process_exit triggers, you should see two triggers for each: | |
| 1175 | one enabling/disabling the hist aggregation and the other | |
| ea272257 | 1176 | enabling/disabling the logging of events:: |
| b8df4a36 TZ |
1177 | |
| 1178 | # cat /sys/kernel/debug/tracing/events/sched/sched_process_exec/trigger | |
| 1179 | enable_event:net:netif_receive_skb:unlimited if filename==/usr/bin/wget | |
| 1180 | enable_hist:net:netif_receive_skb:unlimited if filename==/usr/bin/wget | |
| 1181 | ||
| 1182 | # cat /sys/kernel/debug/tracing/events/sched/sched_process_exit/trigger | |
| 1183 | enable_event:net:netif_receive_skb:unlimited if comm==wget | |
| 1184 | disable_hist:net:netif_receive_skb:unlimited if comm==wget | |
| 1185 | ||
| 1186 | In other words, whenever either of the sched_process_exec or | |
| 1187 | sched_process_exit events is hit and matches 'wget', it enables or | |
| 1188 | disables both the histogram and the event log, and what you end up | |
| 1189 | with is a hash table and set of events just covering the specified | |
| ea272257 | 1190 | duration. Run the wget command again:: |
| b8df4a36 TZ |
1191 | |
| 1192 | $ wget https://www.kernel.org/pub/linux/kernel/v3.x/patch-3.19.xz | |
| 1193 | ||
| 1194 | Displaying the 'hist' file should show something similar to what you | |
| 1195 | saw in the last run, but this time you should also see the | |
| ea272257 | 1196 | individual events in the trace file:: |
| b8df4a36 TZ |
1197 | |
| 1198 | # cat /sys/kernel/debug/tracing/trace | |
| 1199 | ||
| 1200 | # tracer: nop | |
| 1201 | # | |
| 1202 | # entries-in-buffer/entries-written: 183/1426 #P:4 | |
| 1203 | # | |
| 1204 | # _-----=> irqs-off | |
| 1205 | # / _----=> need-resched | |
| 1206 | # | / _---=> hardirq/softirq | |
| 1207 | # || / _--=> preempt-depth | |
| 1208 | # ||| / delay | |
| 1209 | # TASK-PID CPU# |||| TIMESTAMP FUNCTION | |
| 1210 | # | | | |||| | | | |
| 1211 | wget-15108 [000] ..s1 31769.606929: netif_receive_skb: dev=lo skbaddr=ffff88009c353100 len=60 | |
| 1212 | wget-15108 [000] ..s1 31769.606999: netif_receive_skb: dev=lo skbaddr=ffff88009c353200 len=60 | |
| 1213 | dnsmasq-1382 [000] ..s1 31769.677652: netif_receive_skb: dev=lo skbaddr=ffff88009c352b00 len=130 | |
| 1214 | dnsmasq-1382 [000] ..s1 31769.685917: netif_receive_skb: dev=lo skbaddr=ffff88009c352200 len=138 | |
| 1215 | ##### CPU 2 buffer started #### | |
| 1216 | irq/29-iwlwifi-559 [002] ..s. 31772.031529: netif_receive_skb: dev=wlan0 skbaddr=ffff88009d433d00 len=2948 | |
| 1217 | irq/29-iwlwifi-559 [002] ..s. 31772.031572: netif_receive_skb: dev=wlan0 skbaddr=ffff88009d432200 len=1500 | |
| 1218 | irq/29-iwlwifi-559 [002] ..s. 31772.032196: netif_receive_skb: dev=wlan0 skbaddr=ffff88009d433100 len=2948 | |
| 1219 | irq/29-iwlwifi-559 [002] ..s. 31772.032761: netif_receive_skb: dev=wlan0 skbaddr=ffff88009d433000 len=2948 | |
| 1220 | irq/29-iwlwifi-559 [002] ..s. 31772.033220: netif_receive_skb: dev=wlan0 skbaddr=ffff88009d432e00 len=1500 | |
| 1221 | . | |
| 1222 | . | |
| 1223 | . | |
| 1224 | ||
| 1225 | The following example demonstrates how multiple hist triggers can be | |
| 1226 | attached to a given event. This capability can be useful for | |
| 1227 | creating a set of different summaries derived from the same set of | |
| 1228 | events, or for comparing the effects of different filters, among | |
| ea272257 | 1229 | other things:: |
| b8df4a36 TZ |
1230 | |
| 1231 | # echo 'hist:keys=skbaddr.hex:vals=len if len < 0' >> \ | |
| 1232 | /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger | |
| 1233 | # echo 'hist:keys=skbaddr.hex:vals=len if len > 4096' >> \ | |
| 1234 | /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger | |
| 1235 | # echo 'hist:keys=skbaddr.hex:vals=len if len == 256' >> \ | |
| 1236 | /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger | |
| 1237 | # echo 'hist:keys=skbaddr.hex:vals=len' >> \ | |
| 1238 | /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger | |
| 1239 | # echo 'hist:keys=len:vals=common_preempt_count' >> \ | |
| 1240 | /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger | |
| 1241 | ||
| 1242 | The above set of commands create four triggers differing only in | |
| 1243 | their filters, along with a completely different though fairly | |
| 1244 | nonsensical trigger. Note that in order to append multiple hist | |
| 1245 | triggers to the same file, you should use the '>>' operator to | |
| 1246 | append them ('>' will also add the new hist trigger, but will remove | |
| 1247 | any existing hist triggers beforehand). | |
| 1248 | ||
| 1249 | Displaying the contents of the 'hist' file for the event shows the | |
| ea272257 | 1250 | contents of all five histograms:: |
| b8df4a36 TZ |
1251 | |
| 1252 | # cat /sys/kernel/debug/tracing/events/net/netif_receive_skb/hist | |
| 1253 | ||
| 1254 | # event histogram | |
| 1255 | # | |
| 1256 | # trigger info: hist:keys=len:vals=hitcount,common_preempt_count:sort=hitcount:size=2048 [active] | |
| 1257 | # | |
| 1258 | ||
| 1259 | { len: 176 } hitcount: 1 common_preempt_count: 0 | |
| 1260 | { len: 223 } hitcount: 1 common_preempt_count: 0 | |
| 1261 | { len: 4854 } hitcount: 1 common_preempt_count: 0 | |
| 1262 | { len: 395 } hitcount: 1 common_preempt_count: 0 | |
| 1263 | { len: 177 } hitcount: 1 common_preempt_count: 0 | |
| 1264 | { len: 446 } hitcount: 1 common_preempt_count: 0 | |
| 1265 | { len: 1601 } hitcount: 1 common_preempt_count: 0 | |
| 1266 | . | |
| 1267 | . | |
| 1268 | . | |
| 1269 | { len: 1280 } hitcount: 66 common_preempt_count: 0 | |
| 1270 | { len: 116 } hitcount: 81 common_preempt_count: 40 | |
| 1271 | { len: 708 } hitcount: 112 common_preempt_count: 0 | |
| 1272 | { len: 46 } hitcount: 221 common_preempt_count: 0 | |
| 1273 | { len: 1264 } hitcount: 458 common_preempt_count: 0 | |
| 1274 | ||
| 1275 | Totals: | |
| 1276 | Hits: 1428 | |
| 1277 | Entries: 147 | |
| 1278 | Dropped: 0 | |
| 1279 | ||
| 1280 | ||
| 1281 | # event histogram | |
| 1282 | # | |
| 1283 | # trigger info: hist:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 [active] | |
| 1284 | # | |
| 1285 | ||
| 1286 | { skbaddr: ffff8800baee5e00 } hitcount: 1 len: 130 | |
| 1287 | { skbaddr: ffff88005f3d5600 } hitcount: 1 len: 1280 | |
| 1288 | { skbaddr: ffff88005f3d4900 } hitcount: 1 len: 1280 | |
| 1289 | { skbaddr: ffff88009fed6300 } hitcount: 1 len: 115 | |
| 1290 | { skbaddr: ffff88009fe0ad00 } hitcount: 1 len: 115 | |
| 1291 | { skbaddr: ffff88008cdb1900 } hitcount: 1 len: 46 | |
| 1292 | { skbaddr: ffff880064b5ef00 } hitcount: 1 len: 118 | |
| 1293 | { skbaddr: ffff880044e3c700 } hitcount: 1 len: 60 | |
| 1294 | { skbaddr: ffff880100065900 } hitcount: 1 len: 46 | |
| 1295 | { skbaddr: ffff8800d46bd500 } hitcount: 1 len: 116 | |
| 1296 | { skbaddr: ffff88005f3d5f00 } hitcount: 1 len: 1280 | |
| 1297 | { skbaddr: ffff880100064700 } hitcount: 1 len: 365 | |
| 1298 | { skbaddr: ffff8800badb6f00 } hitcount: 1 len: 60 | |
| 1299 | . | |
| 1300 | . | |
| 1301 | . | |
| 1302 | { skbaddr: ffff88009fe0be00 } hitcount: 27 len: 24677 | |
| 1303 | { skbaddr: ffff88009fe0a400 } hitcount: 27 len: 23052 | |
| 1304 | { skbaddr: ffff88009fe0b700 } hitcount: 31 len: 25589 | |
| 1305 | { skbaddr: ffff88009fe0b600 } hitcount: 32 len: 27326 | |
| 1306 | { skbaddr: ffff88006a462800 } hitcount: 68 len: 71678 | |
| 1307 | { skbaddr: ffff88006a463700 } hitcount: 70 len: 72678 | |
| 1308 | { skbaddr: ffff88006a462b00 } hitcount: 71 len: 77589 | |
| 1309 | { skbaddr: ffff88006a463600 } hitcount: 73 len: 71307 | |
| 1310 | { skbaddr: ffff88006a462200 } hitcount: 81 len: 81032 | |
| 1311 | ||
| 1312 | Totals: | |
| 1313 | Hits: 1451 | |
| 1314 | Entries: 318 | |
| 1315 | Dropped: 0 | |
| 1316 | ||
| 1317 | ||
| 1318 | # event histogram | |
| 1319 | # | |
| 1320 | # trigger info: hist:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 if len == 256 [active] | |
| 1321 | # | |
| 1322 | ||
| 1323 | ||
| 1324 | Totals: | |
| 1325 | Hits: 0 | |
| 1326 | Entries: 0 | |
| 1327 | Dropped: 0 | |
| 1328 | ||
| 1329 | ||
| 1330 | # event histogram | |
| 1331 | # | |
| 1332 | # trigger info: hist:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 if len > 4096 [active] | |
| 1333 | # | |
| 1334 | ||
| 1335 | { skbaddr: ffff88009fd2c300 } hitcount: 1 len: 7212 | |
| 1336 | { skbaddr: ffff8800d2bcce00 } hitcount: 1 len: 7212 | |
| 1337 | { skbaddr: ffff8800d2bcd700 } hitcount: 1 len: 7212 | |
| 1338 | { skbaddr: ffff8800d2bcda00 } hitcount: 1 len: 21492 | |
| 1339 | { skbaddr: ffff8800ae2e2d00 } hitcount: 1 len: 7212 | |
| 1340 | { skbaddr: ffff8800d2bcdb00 } hitcount: 1 len: 7212 | |
| 1341 | { skbaddr: ffff88006a4df500 } hitcount: 1 len: 4854 | |
| 1342 | { skbaddr: ffff88008ce47b00 } hitcount: 1 len: 18636 | |
| 1343 | { skbaddr: ffff8800ae2e2200 } hitcount: 1 len: 12924 | |
| 1344 | { skbaddr: ffff88005f3e1000 } hitcount: 1 len: 4356 | |
| 1345 | { skbaddr: ffff8800d2bcdc00 } hitcount: 2 len: 24420 | |
| 1346 | { skbaddr: ffff8800d2bcc200 } hitcount: 2 len: 12996 | |
| 1347 | ||
| 1348 | Totals: | |
| 1349 | Hits: 14 | |
| 1350 | Entries: 12 | |
| 1351 | Dropped: 0 | |
| 1352 | ||
| 1353 | ||
| 1354 | # event histogram | |
| 1355 | # | |
| 1356 | # trigger info: hist:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 if len < 0 [active] | |
| 1357 | # | |
| 1358 | ||
| 1359 | ||
| 1360 | Totals: | |
| 1361 | Hits: 0 | |
| 1362 | Entries: 0 | |
| 1363 | Dropped: 0 | |
| 1364 | ||
| 1365 | Named triggers can be used to have triggers share a common set of | |
| 1366 | histogram data. This capability is mostly useful for combining the | |
| 1367 | output of events generated by tracepoints contained inside inline | |
| 1368 | functions, but names can be used in a hist trigger on any event. | |
| 1369 | For example, these two triggers when hit will update the same 'len' | |
| ea272257 | 1370 | field in the shared 'foo' histogram data:: |
| b8df4a36 TZ |
1371 | |
| 1372 | # echo 'hist:name=foo:keys=skbaddr.hex:vals=len' > \ | |
| 1373 | /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger | |
| 1374 | # echo 'hist:name=foo:keys=skbaddr.hex:vals=len' > \ | |
| 1375 | /sys/kernel/debug/tracing/events/net/netif_rx/trigger | |
| 1376 | ||
| 1377 | You can see that they're updating common histogram data by reading | |
| ea272257 | 1378 | each event's hist files at the same time:: |
| b8df4a36 TZ |
1379 | |
| 1380 | # cat /sys/kernel/debug/tracing/events/net/netif_receive_skb/hist; | |
| 1381 | cat /sys/kernel/debug/tracing/events/net/netif_rx/hist | |
| 1382 | ||
| 1383 | # event histogram | |
| 1384 | # | |
| 1385 | # trigger info: hist:name=foo:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 [active] | |
| 1386 | # | |
| 1387 | ||
| 1388 | { skbaddr: ffff88000ad53500 } hitcount: 1 len: 46 | |
| 1389 | { skbaddr: ffff8800af5a1500 } hitcount: 1 len: 76 | |
| 1390 | { skbaddr: ffff8800d62a1900 } hitcount: 1 len: 46 | |
| 1391 | { skbaddr: ffff8800d2bccb00 } hitcount: 1 len: 468 | |
| 1392 | { skbaddr: ffff8800d3c69900 } hitcount: 1 len: 46 | |
| 1393 | { skbaddr: ffff88009ff09100 } hitcount: 1 len: 52 | |
| 1394 | { skbaddr: ffff88010f13ab00 } hitcount: 1 len: 168 | |
| 1395 | { skbaddr: ffff88006a54f400 } hitcount: 1 len: 46 | |
| 1396 | { skbaddr: ffff8800d2bcc500 } hitcount: 1 len: 260 | |
| 1397 | { skbaddr: ffff880064505000 } hitcount: 1 len: 46 | |
| 1398 | { skbaddr: ffff8800baf24e00 } hitcount: 1 len: 32 | |
| 1399 | { skbaddr: ffff88009fe0ad00 } hitcount: 1 len: 46 | |
| 1400 | { skbaddr: ffff8800d3edff00 } hitcount: 1 len: 44 | |
| 1401 | { skbaddr: ffff88009fe0b400 } hitcount: 1 len: 168 | |
| 1402 | { skbaddr: ffff8800a1c55a00 } hitcount: 1 len: 40 | |
| 1403 | { skbaddr: ffff8800d2bcd100 } hitcount: 1 len: 40 | |
| 1404 | { skbaddr: ffff880064505f00 } hitcount: 1 len: 174 | |
| 1405 | { skbaddr: ffff8800a8bff200 } hitcount: 1 len: 160 | |
| 1406 | { skbaddr: ffff880044e3cc00 } hitcount: 1 len: 76 | |
| 1407 | { skbaddr: ffff8800a8bfe700 } hitcount: 1 len: 46 | |
| 1408 | { skbaddr: ffff8800d2bcdc00 } hitcount: 1 len: 32 | |
| 1409 | { skbaddr: ffff8800a1f64800 } hitcount: 1 len: 46 | |
| 1410 | { skbaddr: ffff8800d2bcde00 } hitcount: 1 len: 988 | |
| 1411 | { skbaddr: ffff88006a5dea00 } hitcount: 1 len: 46 | |
| 1412 | { skbaddr: ffff88002e37a200 } hitcount: 1 len: 44 | |
| 1413 | { skbaddr: ffff8800a1f32c00 } hitcount: 2 len: 676 | |
| 1414 | { skbaddr: ffff88000ad52600 } hitcount: 2 len: 107 | |
| 1415 | { skbaddr: ffff8800a1f91e00 } hitcount: 2 len: 92 | |
| 1416 | { skbaddr: ffff8800af5a0200 } hitcount: 2 len: 142 | |
| 1417 | { skbaddr: ffff8800d2bcc600 } hitcount: 2 len: 220 | |
| 1418 | { skbaddr: ffff8800ba36f500 } hitcount: 2 len: 92 | |
| 1419 | { skbaddr: ffff8800d021f800 } hitcount: 2 len: 92 | |
| 1420 | { skbaddr: ffff8800a1f33600 } hitcount: 2 len: 675 | |
| 1421 | { skbaddr: ffff8800a8bfff00 } hitcount: 3 len: 138 | |
| 1422 | { skbaddr: ffff8800d62a1300 } hitcount: 3 len: 138 | |
| 1423 | { skbaddr: ffff88002e37a100 } hitcount: 4 len: 184 | |
| 1424 | { skbaddr: ffff880064504400 } hitcount: 4 len: 184 | |
| 1425 | { skbaddr: ffff8800a8bfec00 } hitcount: 4 len: 184 | |
| 1426 | { skbaddr: ffff88000ad53700 } hitcount: 5 len: 230 | |
| 1427 | { skbaddr: ffff8800d2bcdb00 } hitcount: 5 len: 196 | |
| 1428 | { skbaddr: ffff8800a1f90000 } hitcount: 6 len: 276 | |
| 1429 | { skbaddr: ffff88006a54f900 } hitcount: 6 len: 276 | |
| 1430 | ||
| 1431 | Totals: | |
| 1432 | Hits: 81 | |
| 1433 | Entries: 42 | |
| 1434 | Dropped: 0 | |
| 1435 | # event histogram | |
| 1436 | # | |
| 1437 | # trigger info: hist:name=foo:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 [active] | |
| 1438 | # | |
| 1439 | ||
| 1440 | { skbaddr: ffff88000ad53500 } hitcount: 1 len: 46 | |
| 1441 | { skbaddr: ffff8800af5a1500 } hitcount: 1 len: 76 | |
| 1442 | { skbaddr: ffff8800d62a1900 } hitcount: 1 len: 46 | |
| 1443 | { skbaddr: ffff8800d2bccb00 } hitcount: 1 len: 468 | |
| 1444 | { skbaddr: ffff8800d3c69900 } hitcount: 1 len: 46 | |
| 1445 | { skbaddr: ffff88009ff09100 } hitcount: 1 len: 52 | |
| 1446 | { skbaddr: ffff88010f13ab00 } hitcount: 1 len: 168 | |
| 1447 | { skbaddr: ffff88006a54f400 } hitcount: 1 len: 46 | |
| 1448 | { skbaddr: ffff8800d2bcc500 } hitcount: 1 len: 260 | |
| 1449 | { skbaddr: ffff880064505000 } hitcount: 1 len: 46 | |
| 1450 | { skbaddr: ffff8800baf24e00 } hitcount: 1 len: 32 | |
| 1451 | { skbaddr: ffff88009fe0ad00 } hitcount: 1 len: 46 | |
| 1452 | { skbaddr: ffff8800d3edff00 } hitcount: 1 len: 44 | |
| 1453 | { skbaddr: ffff88009fe0b400 } hitcount: 1 len: 168 | |
| 1454 | { skbaddr: ffff8800a1c55a00 } hitcount: 1 len: 40 | |
| 1455 | { skbaddr: ffff8800d2bcd100 } hitcount: 1 len: 40 | |
| 1456 | { skbaddr: ffff880064505f00 } hitcount: 1 len: 174 | |
| 1457 | { skbaddr: ffff8800a8bff200 } hitcount: 1 len: 160 | |
| 1458 | { skbaddr: ffff880044e3cc00 } hitcount: 1 len: 76 | |
| 1459 | { skbaddr: ffff8800a8bfe700 } hitcount: 1 len: 46 | |
| 1460 | { skbaddr: ffff8800d2bcdc00 } hitcount: 1 len: 32 | |
| 1461 | { skbaddr: ffff8800a1f64800 } hitcount: 1 len: 46 | |
| 1462 | { skbaddr: ffff8800d2bcde00 } hitcount: 1 len: 988 | |
| 1463 | { skbaddr: ffff88006a5dea00 } hitcount: 1 len: 46 | |
| 1464 | { skbaddr: ffff88002e37a200 } hitcount: 1 len: 44 | |
| 1465 | { skbaddr: ffff8800a1f32c00 } hitcount: 2 len: 676 | |
| 1466 | { skbaddr: ffff88000ad52600 } hitcount: 2 len: 107 | |
| 1467 | { skbaddr: ffff8800a1f91e00 } hitcount: 2 len: 92 | |
| 1468 | { skbaddr: ffff8800af5a0200 } hitcount: 2 len: 142 | |
| 1469 | { skbaddr: ffff8800d2bcc600 } hitcount: 2 len: 220 | |
| 1470 | { skbaddr: ffff8800ba36f500 } hitcount: 2 len: 92 | |
| 1471 | { skbaddr: ffff8800d021f800 } hitcount: 2 len: 92 | |
| 1472 | { skbaddr: ffff8800a1f33600 } hitcount: 2 len: 675 | |
| 1473 | { skbaddr: ffff8800a8bfff00 } hitcount: 3 len: 138 | |
| 1474 | { skbaddr: ffff8800d62a1300 } hitcount: 3 len: 138 | |
| 1475 | { skbaddr: ffff88002e37a100 } hitcount: 4 len: 184 | |
| 1476 | { skbaddr: ffff880064504400 } hitcount: 4 len: 184 | |
| 1477 | { skbaddr: ffff8800a8bfec00 } hitcount: 4 len: 184 | |
| 1478 | { skbaddr: ffff88000ad53700 } hitcount: 5 len: 230 | |
| 1479 | { skbaddr: ffff8800d2bcdb00 } hitcount: 5 len: 196 | |
| 1480 | { skbaddr: ffff8800a1f90000 } hitcount: 6 len: 276 | |
| 1481 | { skbaddr: ffff88006a54f900 } hitcount: 6 len: 276 | |
| 1482 | ||
| 1483 | Totals: | |
| 1484 | Hits: 81 | |
| 1485 | Entries: 42 | |
| 1486 | Dropped: 0 | |
| 1487 | ||
| 1488 | And here's an example that shows how to combine histogram data from | |
| 1489 | any two events even if they don't share any 'compatible' fields | |
| 1490 | other than 'hitcount' and 'stacktrace'. These commands create a | |
| ea272257 | 1491 | couple of triggers named 'bar' using those fields:: |
| b8df4a36 TZ |
1492 | |
| 1493 | # echo 'hist:name=bar:key=stacktrace:val=hitcount' > \ | |
| 1494 | /sys/kernel/debug/tracing/events/sched/sched_process_fork/trigger | |
| 1495 | # echo 'hist:name=bar:key=stacktrace:val=hitcount' > \ | |
| 1496 | /sys/kernel/debug/tracing/events/net/netif_rx/trigger | |
| 1497 | ||
| 1498 | And displaying the output of either shows some interesting if | |
| ea272257 | 1499 | somewhat confusing output:: |
| b8df4a36 TZ |
1500 | |
| 1501 | # cat /sys/kernel/debug/tracing/events/sched/sched_process_fork/hist | |
| 1502 | # cat /sys/kernel/debug/tracing/events/net/netif_rx/hist | |
| 1503 | ||
| 1504 | # event histogram | |
| 1505 | # | |
| 1506 | # trigger info: hist:name=bar:keys=stacktrace:vals=hitcount:sort=hitcount:size=2048 [active] | |
| 1507 | # | |
| 1508 | ||
| 1509 | { stacktrace: | |
| 1510 | _do_fork+0x18e/0x330 | |
| 1511 | kernel_thread+0x29/0x30 | |
| 1512 | kthreadd+0x154/0x1b0 | |
| 1513 | ret_from_fork+0x3f/0x70 | |
| 1514 | } hitcount: 1 | |
| 1515 | { stacktrace: | |
| 1516 | netif_rx_internal+0xb2/0xd0 | |
| 1517 | netif_rx_ni+0x20/0x70 | |
| 1518 | dev_loopback_xmit+0xaa/0xd0 | |
| 1519 | ip_mc_output+0x126/0x240 | |
| 1520 | ip_local_out_sk+0x31/0x40 | |
| 1521 | igmp_send_report+0x1e9/0x230 | |
| 1522 | igmp_timer_expire+0xe9/0x120 | |
| 1523 | call_timer_fn+0x39/0xf0 | |
| 1524 | run_timer_softirq+0x1e1/0x290 | |
| 1525 | __do_softirq+0xfd/0x290 | |
| 1526 | irq_exit+0x98/0xb0 | |
| 1527 | smp_apic_timer_interrupt+0x4a/0x60 | |
| 1528 | apic_timer_interrupt+0x6d/0x80 | |
| 1529 | cpuidle_enter+0x17/0x20 | |
| 1530 | call_cpuidle+0x3b/0x60 | |
| 1531 | cpu_startup_entry+0x22d/0x310 | |
| 1532 | } hitcount: 1 | |
| 1533 | { stacktrace: | |
| 1534 | netif_rx_internal+0xb2/0xd0 | |
| 1535 | netif_rx_ni+0x20/0x70 | |
| 1536 | dev_loopback_xmit+0xaa/0xd0 | |
| 1537 | ip_mc_output+0x17f/0x240 | |
| 1538 | ip_local_out_sk+0x31/0x40 | |
| 1539 | ip_send_skb+0x1a/0x50 | |
| 1540 | udp_send_skb+0x13e/0x270 | |
| 1541 | udp_sendmsg+0x2bf/0x980 | |
| 1542 | inet_sendmsg+0x67/0xa0 | |
| 1543 | sock_sendmsg+0x38/0x50 | |
| 1544 | SYSC_sendto+0xef/0x170 | |
| 1545 | SyS_sendto+0xe/0x10 | |
| 1546 | entry_SYSCALL_64_fastpath+0x12/0x6a | |
| 1547 | } hitcount: 2 | |
| 1548 | { stacktrace: | |
| 1549 | netif_rx_internal+0xb2/0xd0 | |
| 1550 | netif_rx+0x1c/0x60 | |
| 1551 | loopback_xmit+0x6c/0xb0 | |
| 1552 | dev_hard_start_xmit+0x219/0x3a0 | |
| 1553 | __dev_queue_xmit+0x415/0x4f0 | |
| 1554 | dev_queue_xmit_sk+0x13/0x20 | |
| 1555 | ip_finish_output2+0x237/0x340 | |
| 1556 | ip_finish_output+0x113/0x1d0 | |
| 1557 | ip_output+0x66/0xc0 | |
| 1558 | ip_local_out_sk+0x31/0x40 | |
| 1559 | ip_send_skb+0x1a/0x50 | |
| 1560 | udp_send_skb+0x16d/0x270 | |
| 1561 | udp_sendmsg+0x2bf/0x980 | |
| 1562 | inet_sendmsg+0x67/0xa0 | |
| 1563 | sock_sendmsg+0x38/0x50 | |
| 1564 | ___sys_sendmsg+0x14e/0x270 | |
| 1565 | } hitcount: 76 | |
| 1566 | { stacktrace: | |
| 1567 | netif_rx_internal+0xb2/0xd0 | |
| 1568 | netif_rx+0x1c/0x60 | |
| 1569 | loopback_xmit+0x6c/0xb0 | |
| 1570 | dev_hard_start_xmit+0x219/0x3a0 | |
| 1571 | __dev_queue_xmit+0x415/0x4f0 | |
| 1572 | dev_queue_xmit_sk+0x13/0x20 | |
| 1573 | ip_finish_output2+0x237/0x340 | |
| 1574 | ip_finish_output+0x113/0x1d0 | |
| 1575 | ip_output+0x66/0xc0 | |
| 1576 | ip_local_out_sk+0x31/0x40 | |
| 1577 | ip_send_skb+0x1a/0x50 | |
| 1578 | udp_send_skb+0x16d/0x270 | |
| 1579 | udp_sendmsg+0x2bf/0x980 | |
| 1580 | inet_sendmsg+0x67/0xa0 | |
| 1581 | sock_sendmsg+0x38/0x50 | |
| 1582 | ___sys_sendmsg+0x269/0x270 | |
| 1583 | } hitcount: 77 | |
| 1584 | { stacktrace: | |
| 1585 | netif_rx_internal+0xb2/0xd0 | |
| 1586 | netif_rx+0x1c/0x60 | |
| 1587 | loopback_xmit+0x6c/0xb0 | |
| 1588 | dev_hard_start_xmit+0x219/0x3a0 | |
| 1589 | __dev_queue_xmit+0x415/0x4f0 | |
| 1590 | dev_queue_xmit_sk+0x13/0x20 | |
| 1591 | ip_finish_output2+0x237/0x340 | |
| 1592 | ip_finish_output+0x113/0x1d0 | |
| 1593 | ip_output+0x66/0xc0 | |
| 1594 | ip_local_out_sk+0x31/0x40 | |
| 1595 | ip_send_skb+0x1a/0x50 | |
| 1596 | udp_send_skb+0x16d/0x270 | |
| 1597 | udp_sendmsg+0x2bf/0x980 | |
| 1598 | inet_sendmsg+0x67/0xa0 | |
| 1599 | sock_sendmsg+0x38/0x50 | |
| 1600 | SYSC_sendto+0xef/0x170 | |
| 1601 | } hitcount: 88 | |
| 1602 | { stacktrace: | |
| 1603 | _do_fork+0x18e/0x330 | |
| 1604 | SyS_clone+0x19/0x20 | |
| 1605 | entry_SYSCALL_64_fastpath+0x12/0x6a | |
| 1606 | } hitcount: 244 | |
| 1607 | ||
| 1608 | Totals: | |
| 1609 | Hits: 489 | |
| 1610 | Entries: 7 | |
| 1611 | Dropped: 0 | |
| 033cbcee | 1612 | |
| 033cbcee TZ |
1613 | 2.2 Inter-event hist triggers |
| 1614 | ----------------------------- | |
| 1615 | ||
| 1616 | Inter-event hist triggers are hist triggers that combine values from | |
| 1617 | one or more other events and create a histogram using that data. Data | |
| 1618 | from an inter-event histogram can in turn become the source for | |
| 1619 | further combined histograms, thus providing a chain of related | |
| 1620 | histograms, which is important for some applications. | |
| 1621 | ||
| 1622 | The most important example of an inter-event quantity that can be used | |
| 1623 | in this manner is latency, which is simply a difference in timestamps | |
| 1624 | between two events. Although latency is the most important | |
| 1625 | inter-event quantity, note that because the support is completely | |
| 1626 | general across the trace event subsystem, any event field can be used | |
| 1627 | in an inter-event quantity. | |
| 1628 | ||
| 1629 | An example of a histogram that combines data from other histograms | |
| 1630 | into a useful chain would be a 'wakeupswitch latency' histogram that | |
| 1631 | combines a 'wakeup latency' histogram and a 'switch latency' | |
| 1632 | histogram. | |
| 1633 | ||
| 1634 | Normally, a hist trigger specification consists of a (possibly | |
| 1635 | compound) key along with one or more numeric values, which are | |
| 1636 | continually updated sums associated with that key. A histogram | |
| 1637 | specification in this case consists of individual key and value | |
| 1638 | specifications that refer to trace event fields associated with a | |
| 1639 | single event type. | |
| 1640 | ||
| 1641 | The inter-event hist trigger extension allows fields from multiple | |
| 1642 | events to be referenced and combined into a multi-event histogram | |
| 1643 | specification. In support of this overall goal, a few enabling | |
| 1644 | features have been added to the hist trigger support: | |
| 1645 | ||
| 1646 | - In order to compute an inter-event quantity, a value from one | |
| 1647 | event needs to saved and then referenced from another event. This | |
| 1648 | requires the introduction of support for histogram 'variables'. | |
| 1649 | ||
| 1650 | - The computation of inter-event quantities and their combination | |
| 1651 | require some minimal amount of support for applying simple | |
| 1652 | expressions to variables (+ and -). | |
| 1653 | ||
| 1654 | - A histogram consisting of inter-event quantities isn't logically a | |
| 1655 | histogram on either event (so having the 'hist' file for either | |
| 1656 | event host the histogram output doesn't really make sense). To | |
| 1657 | address the idea that the histogram is associated with a | |
| 1658 | combination of events, support is added allowing the creation of | |
| 1659 | 'synthetic' events that are events derived from other events. | |
| 1660 | These synthetic events are full-fledged events just like any other | |
| 1661 | and can be used as such, as for instance to create the | |
| 1662 | 'combination' histograms mentioned previously. | |
| 1663 | ||
| 1664 | - A set of 'actions' can be associated with histogram entries - | |
| 1665 | these can be used to generate the previously mentioned synthetic | |
| 1666 | events, but can also be used for other purposes, such as for | |
| 1667 | example saving context when a 'max' latency has been hit. | |
| 1668 | ||
| 1669 | - Trace events don't have a 'timestamp' associated with them, but | |
| 1670 | there is an implicit timestamp saved along with an event in the | |
| 1671 | underlying ftrace ring buffer. This timestamp is now exposed as a | |
| 1672 | a synthetic field named 'common_timestamp' which can be used in | |
| 1673 | histograms as if it were any other event field; it isn't an actual | |
| 1674 | field in the trace format but rather is a synthesized value that | |
| 1675 | nonetheless can be used as if it were an actual field. By default | |
| 1676 | it is in units of nanoseconds; appending '.usecs' to a | |
| 1677 | common_timestamp field changes the units to microseconds. | |
| 1678 | ||
| a4072fe8 TZ |
1679 | A note on inter-event timestamps: If common_timestamp is used in a |
| 1680 | histogram, the trace buffer is automatically switched over to using | |
| 1681 | absolute timestamps and the "global" trace clock, in order to avoid | |
| 1682 | bogus timestamp differences with other clocks that aren't coherent | |
| 1683 | across CPUs. This can be overridden by specifying one of the other | |
| 1684 | trace clocks instead, using the "clock=XXX" hist trigger attribute, | |
| 1685 | where XXX is any of the clocks listed in the tracing/trace_clock | |
| 1686 | pseudo-file. | |
| 1687 | ||
| 1688 | These features are described in more detail in the following sections. | |
| 033cbcee TZ |
1689 | |
| 1690 | 2.2.1 Histogram Variables | |
| 1691 | ------------------------- | |
| 1692 | ||
| 1693 | Variables are simply named locations used for saving and retrieving | |
| 1694 | values between matching events. A 'matching' event is defined as an | |
| 1695 | event that has a matching key - if a variable is saved for a histogram | |
| 1696 | entry corresponding to that key, any subsequent event with a matching | |
| 1697 | key can access that variable. | |
| 1698 | ||
| 1699 | A variable's value is normally available to any subsequent event until | |
| 1700 | it is set to something else by a subsequent event. The one exception | |
| 1701 | to that rule is that any variable used in an expression is essentially | |
| 1702 | 'read-once' - once it's used by an expression in a subsequent event, | |
| 1703 | it's reset to its 'unset' state, which means it can't be used again | |
| 1704 | unless it's set again. This ensures not only that an event doesn't | |
| 1705 | use an uninitialized variable in a calculation, but that that variable | |
| 1706 | is used only once and not for any unrelated subsequent match. | |
| 1707 | ||
| 1708 | The basic syntax for saving a variable is to simply prefix a unique | |
| 1709 | variable name not corresponding to any keyword along with an '=' sign | |
| 1710 | to any event field. | |
| 1711 | ||
| 1712 | Either keys or values can be saved and retrieved in this way. This | |
| 1713 | creates a variable named 'ts0' for a histogram entry with the key | |
| ea272257 | 1714 | 'next_pid':: |
| 033cbcee TZ |
1715 | |
| 1716 | # echo 'hist:keys=next_pid:vals=$ts0:ts0=common_timestamp ... >> \ | |
| 1717 | event/trigger | |
| 1718 | ||
| 1719 | The ts0 variable can be accessed by any subsequent event having the | |
| 1720 | same pid as 'next_pid'. | |
| 1721 | ||
| 1722 | Variable references are formed by prepending the variable name with | |
| 1723 | the '$' sign. Thus for example, the ts0 variable above would be | |
| 1724 | referenced as '$ts0' in expressions. | |
| 1725 | ||
| 1726 | Because 'vals=' is used, the common_timestamp variable value above | |
| 1727 | will also be summed as a normal histogram value would (though for a | |
| 1728 | timestamp it makes little sense). | |
| 1729 | ||
| ea272257 | 1730 | The below shows that a key value can also be saved in the same way:: |
| 033cbcee TZ |
1731 | |
| 1732 | # echo 'hist:timer_pid=common_pid:key=timer_pid ...' >> event/trigger | |
| 1733 | ||
| 1734 | If a variable isn't a key variable or prefixed with 'vals=', the | |
| 1735 | associated event field will be saved in a variable but won't be summed | |
| ea272257 | 1736 | as a value:: |
| 033cbcee | 1737 | |
| 064f35a9 | 1738 | # echo 'hist:keys=next_pid:ts1=common_timestamp ...' >> event/trigger |
| 033cbcee TZ |
1739 | |
| 1740 | Multiple variables can be assigned at the same time. The below would | |
| 1741 | result in both ts0 and b being created as variables, with both | |
| ea272257 | 1742 | common_timestamp and field1 additionally being summed as values:: |
| 033cbcee | 1743 | |
| 064f35a9 | 1744 | # echo 'hist:keys=pid:vals=$ts0,$b:ts0=common_timestamp,b=field1 ...' >> \ |
| 033cbcee TZ |
1745 | event/trigger |
| 1746 | ||
| 1747 | Note that variable assignments can appear either preceding or | |
| 1748 | following their use. The command below behaves identically to the | |
| ea272257 | 1749 | command above:: |
| 033cbcee | 1750 | |
| 064f35a9 | 1751 | # echo 'hist:keys=pid:ts0=common_timestamp,b=field1:vals=$ts0,$b ...' >> \ |
| 033cbcee TZ |
1752 | event/trigger |
| 1753 | ||
| 1754 | Any number of variables not bound to a 'vals=' prefix can also be | |
| 1755 | assigned by simply separating them with colons. Below is the same | |
| ea272257 | 1756 | thing but without the values being summed in the histogram:: |
| 033cbcee | 1757 | |
| 064f35a9 | 1758 | # echo 'hist:keys=pid:ts0=common_timestamp:b=field1 ...' >> event/trigger |
| 033cbcee TZ |
1759 | |
| 1760 | Variables set as above can be referenced and used in expressions on | |
| 1761 | another event. | |
| 1762 | ||
| ea272257 | 1763 | For example, here's how a latency can be calculated:: |
| 033cbcee | 1764 | |
| 064f35a9 JFG |
1765 | # echo 'hist:keys=pid,prio:ts0=common_timestamp ...' >> event1/trigger |
| 1766 | # echo 'hist:keys=next_pid:wakeup_lat=common_timestamp-$ts0 ...' >> event2/trigger | |
| 033cbcee | 1767 | |
| aea74de4 | 1768 | In the first line above, the event's timestamp is saved into the |
| 033cbcee TZ |
1769 | variable ts0. In the next line, ts0 is subtracted from the second |
| 1770 | event's timestamp to produce the latency, which is then assigned into | |
| 1771 | yet another variable, 'wakeup_lat'. The hist trigger below in turn | |
| 1772 | makes use of the wakeup_lat variable to compute a combined latency | |
| ea272257 | 1773 | using the same key and variable from yet another event:: |
| 033cbcee | 1774 | |
| 064f35a9 | 1775 | # echo 'hist:key=pid:wakeupswitch_lat=$wakeup_lat+$switchtime_lat ...' >> event3/trigger |
| 033cbcee TZ |
1776 | |
| 1777 | 2.2.2 Synthetic Events | |
| 1778 | ---------------------- | |
| 1779 | ||
| 1780 | Synthetic events are user-defined events generated from hist trigger | |
| 1781 | variables or fields associated with one or more other events. Their | |
| 1782 | purpose is to provide a mechanism for displaying data spanning | |
| 1783 | multiple events consistent with the existing and already familiar | |
| 1784 | usage for normal events. | |
| 1785 | ||
| 1786 | To define a synthetic event, the user writes a simple specification | |
| 1787 | consisting of the name of the new event along with one or more | |
| 1788 | variables and their types, which can be any valid field type, | |
| 1789 | separated by semicolons, to the tracing/synthetic_events file. | |
| 1790 | ||
| 1791 | For instance, the following creates a new event named 'wakeup_latency' | |
| 1792 | with 3 fields: lat, pid, and prio. Each of those fields is simply a | |
| ea272257 | 1793 | variable reference to a variable on another event:: |
| 033cbcee TZ |
1794 | |
| 1795 | # echo 'wakeup_latency \ | |
| 1796 | u64 lat; \ | |
| 1797 | pid_t pid; \ | |
| 1798 | int prio' >> \ | |
| 1799 | /sys/kernel/debug/tracing/synthetic_events | |
| 1800 | ||
| 1801 | Reading the tracing/synthetic_events file lists all the currently | |
| ea272257 | 1802 | defined synthetic events, in this case the event defined above:: |
| 033cbcee TZ |
1803 | |
| 1804 | # cat /sys/kernel/debug/tracing/synthetic_events | |
| 1805 | wakeup_latency u64 lat; pid_t pid; int prio | |
| 1806 | ||
| 1807 | An existing synthetic event definition can be removed by prepending | |
| ea272257 | 1808 | the command that defined it with a '!':: |
| 033cbcee TZ |
1809 | |
| 1810 | # echo '!wakeup_latency u64 lat pid_t pid int prio' >> \ | |
| 1811 | /sys/kernel/debug/tracing/synthetic_events | |
| 1812 | ||
| 1813 | At this point, there isn't yet an actual 'wakeup_latency' event | |
| aea74de4 | 1814 | instantiated in the event subsystem - for this to happen, a 'hist |
| 033cbcee | 1815 | trigger action' needs to be instantiated and bound to actual fields |
| 064f35a9 JFG |
1816 | and variables defined on other events (see Section 2.2.3 below on |
| 1817 | how that is done using hist trigger 'onmatch' action). Once that is | |
| 1818 | done, the 'wakeup_latency' synthetic event instance is created. | |
| 033cbcee | 1819 | |
| ea272257 | 1820 | A histogram can now be defined for the new synthetic event:: |
| 033cbcee TZ |
1821 | |
| 1822 | # echo 'hist:keys=pid,prio,lat.log2:sort=pid,lat' >> \ | |
| 1823 | /sys/kernel/debug/tracing/events/synthetic/wakeup_latency/trigger | |
| 1824 | ||
| 1825 | The new event is created under the tracing/events/synthetic/ directory | |
| ea272257 | 1826 | and looks and behaves just like any other event:: |
| 033cbcee TZ |
1827 | |
| 1828 | # ls /sys/kernel/debug/tracing/events/synthetic/wakeup_latency | |
| 1829 | enable filter format hist id trigger | |
| 1830 | ||
| 1831 | Like any other event, once a histogram is enabled for the event, the | |
| 1832 | output can be displayed by reading the event's 'hist' file. | |
| 1833 | ||
| 5032b381 TZ |
1834 | 2.2.3 Hist trigger 'handlers' and 'actions' |
| 1835 | ------------------------------------------- | |
| 033cbcee | 1836 | |
| 5032b381 TZ |
1837 | A hist trigger 'action' is a function that's executed (in most cases |
| 1838 | conditionally) whenever a histogram entry is added or updated. | |
| 033cbcee | 1839 | |
| 5032b381 TZ |
1840 | When a histogram entry is added or updated, a hist trigger 'handler' |
| 1841 | is what decides whether the corresponding action is actually invoked | |
| 1842 | or not. | |
| 033cbcee | 1843 | |
| 5032b381 TZ |
1844 | Hist trigger handlers and actions are paired together in the general |
| 1845 | form: | |
| 1846 | ||
| 1847 | <handler>.<action> | |
| 1848 | ||
| 1849 | To specify a handler.action pair for a given event, simply specify | |
| 1850 | that handler.action pair between colons in the hist trigger | |
| 1851 | specification. | |
| 1852 | ||
| 1853 | In theory, any handler can be combined with any action, but in | |
| 1854 | practice, not every handler.action combination is currently supported; | |
| 1855 | if a given handler.action combination isn't supported, the hist | |
| 1856 | trigger will fail with -EINVAL; | |
| 1857 | ||
| 1858 | The default 'handler.action' if none is explicity specified is as it | |
| 1859 | always has been, to simply update the set of values associated with an | |
| 1860 | entry. Some applications, however, may want to perform additional | |
| 1861 | actions at that point, such as generate another event, or compare and | |
| 1862 | save a maximum. | |
| 1863 | ||
| 1864 | The supported handlers and actions are listed below, and each is | |
| 1865 | described in more detail in the following paragraphs, in the context | |
| 1866 | of descriptions of some common and useful handler.action combinations. | |
| 1867 | ||
| 1868 | The available handlers are: | |
| 1869 | ||
| 1870 | - onmatch(matching.event) - invoke action on any addition or update | |
| 1871 | - onmax(var) - invoke action if var exceeds current max | |
| ff0d35e2 | 1872 | - onchange(var) - invoke action if var changes |
| 5032b381 TZ |
1873 | |
| 1874 | The available actions are: | |
| 1875 | ||
| e91eefd7 | 1876 | - trace(<synthetic_event_name>,param list) - generate synthetic event |
| 5032b381 | 1877 | - save(field,...) - save current event fields |
| fd451a3d | 1878 | - snapshot() - snapshot the trace buffer |
| 5032b381 TZ |
1879 | |
| 1880 | The following commonly-used handler.action pairs are available: | |
| 033cbcee | 1881 | |
| e91eefd7 | 1882 | - onmatch(matching.event).trace(<synthetic_event_name>,param list) |
| 033cbcee | 1883 | |
| e91eefd7 TZ |
1884 | The 'onmatch(matching.event).trace(<synthetic_event_name>,param |
| 1885 | list)' hist trigger action is invoked whenever an event matches | |
| 1886 | and the histogram entry would be added or updated. It causes the | |
| 1887 | named synthetic event to be generated with the values given in the | |
| 033cbcee TZ |
1888 | 'param list'. The result is the generation of a synthetic event |
| 1889 | that consists of the values contained in those variables at the | |
| e91eefd7 TZ |
1890 | time the invoking event was hit. For example, if the synthetic |
| 1891 | event name is 'wakeup_latency', a wakeup_latency event is | |
| 1892 | generated using onmatch(event).trace(wakeup_latency,arg1,arg2). | |
| 1893 | ||
| 1894 | There is also an equivalent alternative form available for | |
| 1895 | generating synthetic events. In this form, the synthetic event | |
| 1896 | name is used as if it were a function name. For example, using | |
| 1897 | the 'wakeup_latency' synthetic event name again, the | |
| 1898 | wakeup_latency event would be generated by invoking it as if it | |
| 1899 | were a function call, with the event field values passed in as | |
| 1900 | arguments: onmatch(event).wakeup_latency(arg1,arg2). The syntax | |
| 1901 | for this form is: | |
| 1902 | ||
| 1903 | onmatch(matching.event).<synthetic_event_name>(param list) | |
| 1904 | ||
| 1905 | In either case, the 'param list' consists of one or more | |
| 1906 | parameters which may be either variables or fields defined on | |
| 1907 | either the 'matching.event' or the target event. The variables or | |
| 1908 | fields specified in the param list may be either fully-qualified | |
| 1909 | or unqualified. If a variable is specified as unqualified, it | |
| 1910 | must be unique between the two events. A field name used as a | |
| 1911 | param can be unqualified if it refers to the target event, but | |
| 1912 | must be fully qualified if it refers to the matching event. A | |
| 1913 | fully-qualified name is of the form 'system.event_name.$var_name' | |
| 1914 | or 'system.event_name.field'. | |
| 033cbcee TZ |
1915 | |
| 1916 | The 'matching.event' specification is simply the fully qualified | |
| 1917 | event name of the event that matches the target event for the | |
| 1918 | onmatch() functionality, in the form 'system.event_name'. | |
| 1919 | ||
| 1920 | Finally, the number and type of variables/fields in the 'param | |
| 1921 | list' must match the number and types of the fields in the | |
| 1922 | synthetic event being generated. | |
| 1923 | ||
| 1924 | As an example the below defines a simple synthetic event and uses | |
| 1925 | a variable defined on the sched_wakeup_new event as a parameter | |
| 1926 | when invoking the synthetic event. Here we define the synthetic | |
| ea272257 | 1927 | event:: |
| 033cbcee | 1928 | |
| ea272257 MCC |
1929 | # echo 'wakeup_new_test pid_t pid' >> \ |
| 1930 | /sys/kernel/debug/tracing/synthetic_events | |
| 033cbcee | 1931 | |
| ea272257 MCC |
1932 | # cat /sys/kernel/debug/tracing/synthetic_events |
| 1933 | wakeup_new_test pid_t pid | |
| 033cbcee TZ |
1934 | |
| 1935 | The following hist trigger both defines the missing testpid | |
| 1936 | variable and specifies an onmatch() action that generates a | |
| 1937 | wakeup_new_test synthetic event whenever a sched_wakeup_new event | |
| 1938 | occurs, which because of the 'if comm == "cyclictest"' filter only | |
| ea272257 | 1939 | happens when the executable is cyclictest:: |
| 033cbcee | 1940 | |
| ea272257 MCC |
1941 | # echo 'hist:keys=$testpid:testpid=pid:onmatch(sched.sched_wakeup_new).\ |
| 1942 | wakeup_new_test($testpid) if comm=="cyclictest"' >> \ | |
| 1943 | /sys/kernel/debug/tracing/events/sched/sched_wakeup_new/trigger | |
| 033cbcee | 1944 | |
| e91eefd7 TZ |
1945 | Or, equivalently, using the 'trace' keyword syntax: |
| 1946 | ||
| 1947 | # echo 'hist:keys=$testpid:testpid=pid:onmatch(sched.sched_wakeup_new).\ | |
| 1948 | trace(wakeup_new_test,$testpid) if comm=="cyclictest"' >> \ | |
| 1949 | /sys/kernel/debug/tracing/events/sched/sched_wakeup_new/trigger | |
| 1950 | ||
| 033cbcee TZ |
1951 | Creating and displaying a histogram based on those events is now |
| 1952 | just a matter of using the fields and new synthetic event in the | |
| ea272257 | 1953 | tracing/events/synthetic directory, as usual:: |
| 033cbcee | 1954 | |
| ea272257 MCC |
1955 | # echo 'hist:keys=pid:sort=pid' >> \ |
| 1956 | /sys/kernel/debug/tracing/events/synthetic/wakeup_new_test/trigger | |
| 033cbcee TZ |
1957 | |
| 1958 | Running 'cyclictest' should cause wakeup_new events to generate | |
| 1959 | wakeup_new_test synthetic events which should result in histogram | |
| ea272257 | 1960 | output in the wakeup_new_test event's hist file:: |
| 033cbcee | 1961 | |
| ea272257 | 1962 | # cat /sys/kernel/debug/tracing/events/synthetic/wakeup_new_test/hist |
| 033cbcee TZ |
1963 | |
| 1964 | A more typical usage would be to use two events to calculate a | |
| 1965 | latency. The following example uses a set of hist triggers to | |
| ea272257 | 1966 | produce a 'wakeup_latency' histogram. |
| 033cbcee | 1967 | |
| ea272257 | 1968 | First, we define a 'wakeup_latency' synthetic event:: |
| 033cbcee | 1969 | |
| ea272257 MCC |
1970 | # echo 'wakeup_latency u64 lat; pid_t pid; int prio' >> \ |
| 1971 | /sys/kernel/debug/tracing/synthetic_events | |
| 033cbcee TZ |
1972 | |
| 1973 | Next, we specify that whenever we see a sched_waking event for a | |
| ea272257 | 1974 | cyclictest thread, save the timestamp in a 'ts0' variable:: |
| 033cbcee | 1975 | |
| ea272257 MCC |
1976 | # echo 'hist:keys=$saved_pid:saved_pid=pid:ts0=common_timestamp.usecs \ |
| 1977 | if comm=="cyclictest"' >> \ | |
| 1978 | /sys/kernel/debug/tracing/events/sched/sched_waking/trigger | |
| 033cbcee TZ |
1979 | |
| 1980 | Then, when the corresponding thread is actually scheduled onto the | |
| 1981 | CPU by a sched_switch event, calculate the latency and use that | |
| 1982 | along with another variable and an event field to generate a | |
| ea272257 | 1983 | wakeup_latency synthetic event:: |
| 033cbcee | 1984 | |
| ea272257 MCC |
1985 | # echo 'hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0:\ |
| 1986 | onmatch(sched.sched_waking).wakeup_latency($wakeup_lat,\ | |
| 1987 | $saved_pid,next_prio) if next_comm=="cyclictest"' >> \ | |
| 1988 | /sys/kernel/debug/tracing/events/sched/sched_switch/trigger | |
| 033cbcee TZ |
1989 | |
| 1990 | We also need to create a histogram on the wakeup_latency synthetic | |
| ea272257 | 1991 | event in order to aggregate the generated synthetic event data:: |
| 033cbcee | 1992 | |
| ea272257 MCC |
1993 | # echo 'hist:keys=pid,prio,lat:sort=pid,lat' >> \ |
| 1994 | /sys/kernel/debug/tracing/events/synthetic/wakeup_latency/trigger | |
| 033cbcee TZ |
1995 | |
| 1996 | Finally, once we've run cyclictest to actually generate some | |
| 1997 | events, we can see the output by looking at the wakeup_latency | |
| ea272257 | 1998 | synthetic event's hist file:: |
| 033cbcee | 1999 | |
| ea272257 | 2000 | # cat /sys/kernel/debug/tracing/events/synthetic/wakeup_latency/hist |
| 033cbcee TZ |
2001 | |
| 2002 | - onmax(var).save(field,.. .) | |
| 2003 | ||
| 2004 | The 'onmax(var).save(field,...)' hist trigger action is invoked | |
| 2005 | whenever the value of 'var' associated with a histogram entry | |
| 2006 | exceeds the current maximum contained in that variable. | |
| 2007 | ||
| 2008 | The end result is that the trace event fields specified as the | |
| 2009 | onmax.save() params will be saved if 'var' exceeds the current | |
| 2010 | maximum for that hist trigger entry. This allows context from the | |
| 2011 | event that exhibited the new maximum to be saved for later | |
| 2012 | reference. When the histogram is displayed, additional fields | |
| 2013 | displaying the saved values will be printed. | |
| 2014 | ||
| 2015 | As an example the below defines a couple of hist triggers, one for | |
| 2016 | sched_waking and another for sched_switch, keyed on pid. Whenever | |
| 2017 | a sched_waking occurs, the timestamp is saved in the entry | |
| 2018 | corresponding to the current pid, and when the scheduler switches | |
| 2019 | back to that pid, the timestamp difference is calculated. If the | |
| 2020 | resulting latency, stored in wakeup_lat, exceeds the current | |
| 2021 | maximum latency, the values specified in the save() fields are | |
| ea272257 | 2022 | recorded:: |
| 033cbcee | 2023 | |
| ea272257 MCC |
2024 | # echo 'hist:keys=pid:ts0=common_timestamp.usecs \ |
| 2025 | if comm=="cyclictest"' >> \ | |
| 2026 | /sys/kernel/debug/tracing/events/sched/sched_waking/trigger | |
| 033cbcee | 2027 | |
| ea272257 MCC |
2028 | # echo 'hist:keys=next_pid:\ |
| 2029 | wakeup_lat=common_timestamp.usecs-$ts0:\ | |
| 2030 | onmax($wakeup_lat).save(next_comm,prev_pid,prev_prio,prev_comm) \ | |
| 2031 | if next_comm=="cyclictest"' >> \ | |
| 2032 | /sys/kernel/debug/tracing/events/sched/sched_switch/trigger | |
| 033cbcee TZ |
2033 | |
| 2034 | When the histogram is displayed, the max value and the saved | |
| 2035 | values corresponding to the max are displayed following the rest | |
| ea272257 | 2036 | of the fields:: |
| 033cbcee | 2037 | |
| ea272257 MCC |
2038 | # cat /sys/kernel/debug/tracing/events/sched/sched_switch/hist |
| 2039 | { next_pid: 2255 } hitcount: 239 | |
| 2040 | common_timestamp-ts0: 0 | |
| 2041 | max: 27 | |
| 2042 | next_comm: cyclictest | |
| 2043 | prev_pid: 0 prev_prio: 120 prev_comm: swapper/1 | |
| 033cbcee | 2044 | |
| ea272257 MCC |
2045 | { next_pid: 2256 } hitcount: 2355 |
| 2046 | common_timestamp-ts0: 0 | |
| 2047 | max: 49 next_comm: cyclictest | |
| 2048 | prev_pid: 0 prev_prio: 120 prev_comm: swapper/0 | |
| 033cbcee | 2049 | |
| ea272257 MCC |
2050 | Totals: |
| 2051 | Hits: 12970 | |
| 2052 | Entries: 2 | |
| 2053 | Dropped: 0 | |
| d3439f9d | 2054 | |
| fd451a3d TZ |
2055 | - onmax(var).snapshot() |
| 2056 | ||
| 2057 | The 'onmax(var).snapshot()' hist trigger action is invoked | |
| 2058 | whenever the value of 'var' associated with a histogram entry | |
| 2059 | exceeds the current maximum contained in that variable. | |
| 2060 | ||
| 2061 | The end result is that a global snapshot of the trace buffer will | |
| 2062 | be saved in the tracing/snapshot file if 'var' exceeds the current | |
| 2063 | maximum for any hist trigger entry. | |
| 2064 | ||
| 2065 | Note that in this case the maximum is a global maximum for the | |
| 2066 | current trace instance, which is the maximum across all buckets of | |
| 2067 | the histogram. The key of the specific trace event that caused | |
| 2068 | the global maximum and the global maximum itself are displayed, | |
| 2069 | along with a message stating that a snapshot has been taken and | |
| 2070 | where to find it. The user can use the key information displayed | |
| 2071 | to locate the corresponding bucket in the histogram for even more | |
| 2072 | detail. | |
| 2073 | ||
| 2074 | As an example the below defines a couple of hist triggers, one for | |
| 2075 | sched_waking and another for sched_switch, keyed on pid. Whenever | |
| 2076 | a sched_waking event occurs, the timestamp is saved in the entry | |
| 2077 | corresponding to the current pid, and when the scheduler switches | |
| 2078 | back to that pid, the timestamp difference is calculated. If the | |
| 2079 | resulting latency, stored in wakeup_lat, exceeds the current | |
| 2080 | maximum latency, a snapshot is taken. As part of the setup, all | |
| 2081 | the scheduler events are also enabled, which are the events that | |
| 2082 | will show up in the snapshot when it is taken at some point: | |
| 2083 | ||
| 2084 | # echo 1 > /sys/kernel/debug/tracing/events/sched/enable | |
| 2085 | ||
| 2086 | # echo 'hist:keys=pid:ts0=common_timestamp.usecs \ | |
| 2087 | if comm=="cyclictest"' >> \ | |
| 2088 | /sys/kernel/debug/tracing/events/sched/sched_waking/trigger | |
| 2089 | ||
| 2090 | # echo 'hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0: \ | |
| 2091 | onmax($wakeup_lat).save(next_prio,next_comm,prev_pid,prev_prio, \ | |
| 2092 | prev_comm):onmax($wakeup_lat).snapshot() \ | |
| 2093 | if next_comm=="cyclictest"' >> \ | |
| 2094 | /sys/kernel/debug/tracing/events/sched/sched_switch/trigger | |
| 2095 | ||
| 2096 | When the histogram is displayed, for each bucket the max value | |
| 2097 | and the saved values corresponding to the max are displayed | |
| 2098 | following the rest of the fields. | |
| 2099 | ||
| 2100 | If a snaphot was taken, there is also a message indicating that, | |
| 2101 | along with the value and event that triggered the global maximum: | |
| 2102 | ||
| 2103 | # cat /sys/kernel/debug/tracing/events/sched/sched_switch/hist | |
| 2104 | { next_pid: 2101 } hitcount: 200 | |
| 2105 | max: 52 next_prio: 120 next_comm: cyclictest \ | |
| 2106 | prev_pid: 0 prev_prio: 120 prev_comm: swapper/6 | |
| 2107 | ||
| 2108 | { next_pid: 2103 } hitcount: 1326 | |
| 2109 | max: 572 next_prio: 19 next_comm: cyclictest \ | |
| 2110 | prev_pid: 0 prev_prio: 120 prev_comm: swapper/1 | |
| 2111 | ||
| 2112 | { next_pid: 2102 } hitcount: 1982 \ | |
| 2113 | max: 74 next_prio: 19 next_comm: cyclictest \ | |
| 2114 | prev_pid: 0 prev_prio: 120 prev_comm: swapper/5 | |
| 2115 | ||
| 2116 | Snapshot taken (see tracing/snapshot). Details: | |
| 2117 | triggering value { onmax($wakeup_lat) }: 572 \ | |
| 2118 | triggered by event with key: { next_pid: 2103 } | |
| 2119 | ||
| 2120 | Totals: | |
| 2121 | Hits: 3508 | |
| 2122 | Entries: 3 | |
| 2123 | Dropped: 0 | |
| 2124 | ||
| 2125 | In the above case, the event that triggered the global maximum has | |
| 2126 | the key with next_pid == 2103. If you look at the bucket that has | |
| 2127 | 2103 as the key, you'll find the additional values save()'d along | |
| 2128 | with the local maximum for that bucket, which should be the same | |
| 2129 | as the global maximum (since that was the same value that | |
| 2130 | triggered the global snapshot). | |
| 2131 | ||
| 2132 | And finally, looking at the snapshot data should show at or near | |
| 2133 | the end the event that triggered the snapshot (in this case you | |
| 2134 | can verify the timestamps between the sched_waking and | |
| 2135 | sched_switch events, which should match the time displayed in the | |
| 2136 | global maximum): | |
| 2137 | ||
| 2138 | # cat /sys/kernel/debug/tracing/snapshot | |
| 2139 | ||
| 2140 | <...>-2103 [005] d..3 309.873125: sched_switch: prev_comm=cyclictest prev_pid=2103 prev_prio=19 prev_state=D ==> next_comm=swapper/5 next_pid=0 next_prio=120 | |
| 2141 | <idle>-0 [005] d.h3 309.873611: sched_waking: comm=cyclictest pid=2102 prio=19 target_cpu=005 | |
| 2142 | <idle>-0 [005] dNh4 309.873613: sched_wakeup: comm=cyclictest pid=2102 prio=19 target_cpu=005 | |
| 2143 | <idle>-0 [005] d..3 309.873616: sched_switch: prev_comm=swapper/5 prev_pid=0 prev_prio=120 prev_state=S ==> next_comm=cyclictest next_pid=2102 next_prio=19 | |
| 2144 | <...>-2102 [005] d..3 309.873625: sched_switch: prev_comm=cyclictest prev_pid=2102 prev_prio=19 prev_state=D ==> next_comm=swapper/5 next_pid=0 next_prio=120 | |
| 2145 | <idle>-0 [005] d.h3 309.874624: sched_waking: comm=cyclictest pid=2102 prio=19 target_cpu=005 | |
| 2146 | <idle>-0 [005] dNh4 309.874626: sched_wakeup: comm=cyclictest pid=2102 prio=19 target_cpu=005 | |
| 2147 | <idle>-0 [005] dNh3 309.874628: sched_waking: comm=cyclictest pid=2103 prio=19 target_cpu=005 | |
| 2148 | <idle>-0 [005] dNh4 309.874630: sched_wakeup: comm=cyclictest pid=2103 prio=19 target_cpu=005 | |
| 2149 | <idle>-0 [005] d..3 309.874633: sched_switch: prev_comm=swapper/5 prev_pid=0 prev_prio=120 prev_state=S ==> next_comm=cyclictest next_pid=2102 next_prio=19 | |
| 2150 | <idle>-0 [004] d.h3 309.874757: sched_waking: comm=gnome-terminal- pid=1699 prio=120 target_cpu=004 | |
| 2151 | <idle>-0 [004] dNh4 309.874762: sched_wakeup: comm=gnome-terminal- pid=1699 prio=120 target_cpu=004 | |
| 2152 | <idle>-0 [004] d..3 309.874766: sched_switch: prev_comm=swapper/4 prev_pid=0 prev_prio=120 prev_state=S ==> next_comm=gnome-terminal- next_pid=1699 next_prio=120 | |
| 2153 | gnome-terminal--1699 [004] d.h2 309.874941: sched_stat_runtime: comm=gnome-terminal- pid=1699 runtime=180706 [ns] vruntime=1126870572 [ns] | |
| 2154 | <idle>-0 [003] d.s4 309.874956: sched_waking: comm=rcu_sched pid=9 prio=120 target_cpu=007 | |
| 2155 | <idle>-0 [003] d.s5 309.874960: sched_wake_idle_without_ipi: cpu=7 | |
| 2156 | <idle>-0 [003] d.s5 309.874961: sched_wakeup: comm=rcu_sched pid=9 prio=120 target_cpu=007 | |
| 2157 | <idle>-0 [007] d..3 309.874963: sched_switch: prev_comm=swapper/7 prev_pid=0 prev_prio=120 prev_state=S ==> next_comm=rcu_sched next_pid=9 next_prio=120 | |
| 2158 | rcu_sched-9 [007] d..3 309.874973: sched_stat_runtime: comm=rcu_sched pid=9 runtime=13646 [ns] vruntime=22531430286 [ns] | |
| 2159 | rcu_sched-9 [007] d..3 309.874978: sched_switch: prev_comm=rcu_sched prev_pid=9 prev_prio=120 prev_state=R+ ==> next_comm=swapper/7 next_pid=0 next_prio=120 | |
| 2160 | <...>-2102 [005] d..4 309.874994: sched_migrate_task: comm=cyclictest pid=2103 prio=19 orig_cpu=5 dest_cpu=1 | |
| 2161 | <...>-2102 [005] d..4 309.875185: sched_wake_idle_without_ipi: cpu=1 | |
| 2162 | <idle>-0 [001] d..3 309.875200: sched_switch: prev_comm=swapper/1 prev_pid=0 prev_prio=120 prev_state=S ==> next_comm=cyclictest next_pid=2103 next_prio=19 | |
| 2163 | ||
| ff0d35e2 TZ |
2164 | - onchange(var).save(field,.. .) |
| 2165 | ||
| 2166 | The 'onchange(var).save(field,...)' hist trigger action is invoked | |
| 2167 | whenever the value of 'var' associated with a histogram entry | |
| 2168 | changes. | |
| 2169 | ||
| 2170 | The end result is that the trace event fields specified as the | |
| 2171 | onchange.save() params will be saved if 'var' changes for that | |
| 2172 | hist trigger entry. This allows context from the event that | |
| 2173 | changed the value to be saved for later reference. When the | |
| 2174 | histogram is displayed, additional fields displaying the saved | |
| 2175 | values will be printed. | |
| 2176 | ||
| 2177 | - onchange(var).snapshot() | |
| 2178 | ||
| 2179 | The 'onchange(var).snapshot()' hist trigger action is invoked | |
| 2180 | whenever the value of 'var' associated with a histogram entry | |
| 2181 | changes. | |
| 2182 | ||
| 2183 | The end result is that a global snapshot of the trace buffer will | |
| 2184 | be saved in the tracing/snapshot file if 'var' changes for any | |
| 2185 | hist trigger entry. | |
| 2186 | ||
| 2187 | Note that in this case the changed value is a global variable | |
| 2188 | associated withe current trace instance. The key of the specific | |
| 2189 | trace event that caused the value to change and the global value | |
| 2190 | itself are displayed, along with a message stating that a snapshot | |
| 2191 | has been taken and where to find it. The user can use the key | |
| 2192 | information displayed to locate the corresponding bucket in the | |
| 2193 | histogram for even more detail. | |
| 2194 | ||
| 2195 | As an example the below defines a hist trigger on the tcp_probe | |
| 2196 | event, keyed on dport. Whenever a tcp_probe event occurs, the | |
| 2197 | cwnd field is checked against the current value stored in the | |
| 2198 | $cwnd variable. If the value has changed, a snapshot is taken. | |
| 2199 | As part of the setup, all the scheduler and tcp events are also | |
| 2200 | enabled, which are the events that will show up in the snapshot | |
| 2201 | when it is taken at some point: | |
| 2202 | ||
| 2203 | # echo 1 > /sys/kernel/debug/tracing/events/sched/enable | |
| 2204 | # echo 1 > /sys/kernel/debug/tracing/events/tcp/enable | |
| 2205 | ||
| 2206 | # echo 'hist:keys=dport:cwnd=snd_cwnd: \ | |
| 2207 | onchange($cwnd).save(snd_wnd,srtt,rcv_wnd): \ | |
| 2208 | onchange($cwnd).snapshot()' >> \ | |
| 2209 | /sys/kernel/debug/tracing/events/tcp/tcp_probe/trigger | |
| 2210 | ||
| 2211 | When the histogram is displayed, for each bucket the tracked value | |
| 2212 | and the saved values corresponding to that value are displayed | |
| 2213 | following the rest of the fields. | |
| 2214 | ||
| 2215 | If a snaphot was taken, there is also a message indicating that, | |
| 2216 | along with the value and event that triggered the snapshot: | |
| 2217 | ||
| 2218 | # cat /sys/kernel/debug/tracing/events/tcp/tcp_probe/hist | |
| 2219 | { dport: 1521 } hitcount: 8 | |
| 2220 | changed: 10 snd_wnd: 35456 srtt: 154262 rcv_wnd: 42112 | |
| 2221 | ||
| 2222 | { dport: 80 } hitcount: 23 | |
| 2223 | changed: 10 snd_wnd: 28960 srtt: 19604 rcv_wnd: 29312 | |
| 2224 | ||
| 2225 | { dport: 9001 } hitcount: 172 | |
| 2226 | changed: 10 snd_wnd: 48384 srtt: 260444 rcv_wnd: 55168 | |
| 2227 | ||
| 2228 | { dport: 443 } hitcount: 211 | |
| 2229 | changed: 10 snd_wnd: 26960 srtt: 17379 rcv_wnd: 28800 | |
| 2230 | ||
| 2231 | Snapshot taken (see tracing/snapshot). Details: | |
| 2232 | triggering value { onchange($cwnd) }: 10 | |
| 2233 | triggered by event with key: { dport: 80 } | |
| 2234 | ||
| 2235 | Totals: | |
| 2236 | Hits: 414 | |
| 2237 | Entries: 4 | |
| 2238 | Dropped: 0 | |
| 2239 | ||
| 2240 | In the above case, the event that triggered the snapshot has the | |
| 2241 | key with dport == 80. If you look at the bucket that has 80 as | |
| 2242 | the key, you'll find the additional values save()'d along with the | |
| 2243 | changed value for that bucket, which should be the same as the | |
| 2244 | global changed value (since that was the same value that triggered | |
| 2245 | the global snapshot). | |
| 2246 | ||
| 2247 | And finally, looking at the snapshot data should show at or near | |
| 2248 | the end the event that triggered the snapshot: | |
| 2249 | ||
| 2250 | # cat /sys/kernel/debug/tracing/snapshot | |
| 2251 | ||
| 2252 | gnome-shell-1261 [006] dN.3 49.823113: sched_stat_runtime: comm=gnome-shell pid=1261 runtime=49347 [ns] vruntime=1835730389 [ns] | |
| 2253 | kworker/u16:4-773 [003] d..3 49.823114: sched_switch: prev_comm=kworker/u16:4 prev_pid=773 prev_prio=120 prev_state=R+ ==> next_comm=kworker/3:2 next_pid=135 next_prio=120 | |
| 2254 | gnome-shell-1261 [006] d..3 49.823114: sched_switch: prev_comm=gnome-shell prev_pid=1261 prev_prio=120 prev_state=R+ ==> next_comm=kworker/6:2 next_pid=387 next_prio=120 | |
| 2255 | kworker/3:2-135 [003] d..3 49.823118: sched_stat_runtime: comm=kworker/3:2 pid=135 runtime=5339 [ns] vruntime=17815800388 [ns] | |
| 2256 | kworker/6:2-387 [006] d..3 49.823120: sched_stat_runtime: comm=kworker/6:2 pid=387 runtime=9594 [ns] vruntime=14589605367 [ns] | |
| 2257 | kworker/6:2-387 [006] d..3 49.823122: sched_switch: prev_comm=kworker/6:2 prev_pid=387 prev_prio=120 prev_state=R+ ==> next_comm=gnome-shell next_pid=1261 next_prio=120 | |
| 2258 | kworker/3:2-135 [003] d..3 49.823123: sched_switch: prev_comm=kworker/3:2 prev_pid=135 prev_prio=120 prev_state=T ==> next_comm=swapper/3 next_pid=0 next_prio=120 | |
| 2259 | <idle>-0 [004] ..s7 49.823798: tcp_probe: src=10.0.0.10:54326 dest=23.215.104.193:80 mark=0x0 length=32 snd_nxt=0xe3ae2ff5 snd_una=0xe3ae2ecd snd_cwnd=10 ssthresh=2147483647 snd_wnd=28960 srtt=19604 rcv_wnd=29312 | |
| 2260 | ||
| d3439f9d SRV |
2261 | 3. User space creating a trigger |
| 2262 | -------------------------------- | |
| 2263 | ||
| 2264 | Writing into /sys/kernel/tracing/trace_marker writes into the ftrace | |
| 2265 | ring buffer. This can also act like an event, by writing into the trigger | |
| 2266 | file located in /sys/kernel/tracing/events/ftrace/print/ | |
| 2267 | ||
| 2268 | Modifying cyclictest to write into the trace_marker file before it sleeps | |
| ea272257 | 2269 | and after it wakes up, something like this:: |
| d3439f9d | 2270 | |
| ea272257 MCC |
2271 | static void traceputs(char *str) |
| 2272 | { | |
| d3439f9d SRV |
2273 | /* tracemark_fd is the trace_marker file descriptor */ |
| 2274 | if (tracemark_fd < 0) | |
| 2275 | return; | |
| 2276 | /* write the tracemark message */ | |
| 2277 | write(tracemark_fd, str, strlen(str)); | |
| ea272257 | 2278 | } |
| d3439f9d | 2279 | |
| ea272257 | 2280 | And later add something like:: |
| d3439f9d SRV |
2281 | |
| 2282 | traceputs("start"); | |
| 2283 | clock_nanosleep(...); | |
| 2284 | traceputs("end"); | |
| 2285 | ||
| ea272257 | 2286 | We can make a histogram from this:: |
| d3439f9d SRV |
2287 | |
| 2288 | # cd /sys/kernel/tracing | |
| 2289 | # echo 'latency u64 lat' > synthetic_events | |
| 2290 | # echo 'hist:keys=common_pid:ts0=common_timestamp.usecs if buf == "start"' > events/ftrace/print/trigger | |
| 2291 | # echo 'hist:keys=common_pid:lat=common_timestamp.usecs-$ts0:onmatch(ftrace.print).latency($lat) if buf == "end"' >> events/ftrace/print/trigger | |
| 2292 | # echo 'hist:keys=lat,common_pid:sort=lat' > events/synthetic/latency/trigger | |
| 2293 | ||
| 2294 | The above created a synthetic event called "latency" and two histograms | |
| 2295 | against the trace_marker, one gets triggered when "start" is written into the | |
| 2296 | trace_marker file and the other when "end" is written. If the pids match, then | |
| 2297 | it will call the "latency" synthetic event with the calculated latency as its | |
| 2298 | parameter. Finally, a histogram is added to the latency synthetic event to | |
| 2299 | record the calculated latency along with the pid. | |
| 2300 | ||
| ea272257 | 2301 | Now running cyclictest with:: |
| d3439f9d SRV |
2302 | |
| 2303 | # ./cyclictest -p80 -d0 -i250 -n -a -t --tracemark -b 1000 | |
| 2304 | ||
| 2305 | -p80 : run threads at priority 80 | |
| 2306 | -d0 : have all threads run at the same interval | |
| 2307 | -i250 : start the interval at 250 microseconds (all threads will do this) | |
| 2308 | -n : sleep with nanosleep | |
| 2309 | -a : affine all threads to a separate CPU | |
| 2310 | -t : one thread per available CPU | |
| 2311 | --tracemark : enable trace mark writing | |
| 2312 | -b 1000 : stop if any latency is greater than 1000 microseconds | |
| 2313 | ||
| 2314 | Note, the -b 1000 is used just to make --tracemark available. | |
| 2315 | ||
| ea272257 | 2316 | Then we can see the histogram created by this with:: |
| d3439f9d SRV |
2317 | |
| 2318 | # cat events/synthetic/latency/hist | |
| ea272257 MCC |
2319 | # event histogram |
| 2320 | # | |
| 2321 | # trigger info: hist:keys=lat,common_pid:vals=hitcount:sort=lat:size=2048 [active] | |
| 2322 | # | |
| 2323 | ||
| 2324 | { lat: 107, common_pid: 2039 } hitcount: 1 | |
| 2325 | { lat: 122, common_pid: 2041 } hitcount: 1 | |
| 2326 | { lat: 166, common_pid: 2039 } hitcount: 1 | |
| 2327 | { lat: 174, common_pid: 2039 } hitcount: 1 | |
| 2328 | { lat: 194, common_pid: 2041 } hitcount: 1 | |
| 2329 | { lat: 196, common_pid: 2036 } hitcount: 1 | |
| 2330 | { lat: 197, common_pid: 2038 } hitcount: 1 | |
| 2331 | { lat: 198, common_pid: 2039 } hitcount: 1 | |
| 2332 | { lat: 199, common_pid: 2039 } hitcount: 1 | |
| 2333 | { lat: 200, common_pid: 2041 } hitcount: 1 | |
| 2334 | { lat: 201, common_pid: 2039 } hitcount: 2 | |
| 2335 | { lat: 202, common_pid: 2038 } hitcount: 1 | |
| 2336 | { lat: 202, common_pid: 2043 } hitcount: 1 | |
| 2337 | { lat: 203, common_pid: 2039 } hitcount: 1 | |
| 2338 | { lat: 203, common_pid: 2036 } hitcount: 1 | |
| 2339 | { lat: 203, common_pid: 2041 } hitcount: 1 | |
| 2340 | { lat: 206, common_pid: 2038 } hitcount: 2 | |
| 2341 | { lat: 207, common_pid: 2039 } hitcount: 1 | |
| 2342 | { lat: 207, common_pid: 2036 } hitcount: 1 | |
| 2343 | { lat: 208, common_pid: 2040 } hitcount: 1 | |
| 2344 | { lat: 209, common_pid: 2043 } hitcount: 1 | |
| 2345 | { lat: 210, common_pid: 2039 } hitcount: 1 | |
| 2346 | { lat: 211, common_pid: 2039 } hitcount: 4 | |
| 2347 | { lat: 212, common_pid: 2043 } hitcount: 1 | |
| 2348 | { lat: 212, common_pid: 2039 } hitcount: 2 | |
| 2349 | { lat: 213, common_pid: 2039 } hitcount: 1 | |
| 2350 | { lat: 214, common_pid: 2038 } hitcount: 1 | |
| 2351 | { lat: 214, common_pid: 2039 } hitcount: 2 | |
| 2352 | { lat: 214, common_pid: 2042 } hitcount: 1 | |
| 2353 | { lat: 215, common_pid: 2039 } hitcount: 1 | |
| 2354 | { lat: 217, common_pid: 2036 } hitcount: 1 | |
| 2355 | { lat: 217, common_pid: 2040 } hitcount: 1 | |
| 2356 | { lat: 217, common_pid: 2039 } hitcount: 1 | |
| 2357 | { lat: 218, common_pid: 2039 } hitcount: 6 | |
| 2358 | { lat: 219, common_pid: 2039 } hitcount: 9 | |
| 2359 | { lat: 220, common_pid: 2039 } hitcount: 11 | |
| 2360 | { lat: 221, common_pid: 2039 } hitcount: 5 | |
| 2361 | { lat: 221, common_pid: 2042 } hitcount: 1 | |
| 2362 | { lat: 222, common_pid: 2039 } hitcount: 7 | |
| 2363 | { lat: 223, common_pid: 2036 } hitcount: 1 | |
| 2364 | { lat: 223, common_pid: 2039 } hitcount: 3 | |
| 2365 | { lat: 224, common_pid: 2039 } hitcount: 4 | |
| 2366 | { lat: 224, common_pid: 2037 } hitcount: 1 | |
| 2367 | { lat: 224, common_pid: 2036 } hitcount: 2 | |
| 2368 | { lat: 225, common_pid: 2039 } hitcount: 5 | |
| 2369 | { lat: 225, common_pid: 2042 } hitcount: 1 | |
| 2370 | { lat: 226, common_pid: 2039 } hitcount: 7 | |
| 2371 | { lat: 226, common_pid: 2036 } hitcount: 4 | |
| 2372 | { lat: 227, common_pid: 2039 } hitcount: 6 | |
| 2373 | { lat: 227, common_pid: 2036 } hitcount: 12 | |
| 2374 | { lat: 227, common_pid: 2043 } hitcount: 1 | |
| 2375 | { lat: 228, common_pid: 2039 } hitcount: 7 | |
| 2376 | { lat: 228, common_pid: 2036 } hitcount: 14 | |
| 2377 | { lat: 229, common_pid: 2039 } hitcount: 9 | |
| 2378 | { lat: 229, common_pid: 2036 } hitcount: 8 | |
| 2379 | { lat: 229, common_pid: 2038 } hitcount: 1 | |
| 2380 | { lat: 230, common_pid: 2039 } hitcount: 11 | |
| 2381 | { lat: 230, common_pid: 2036 } hitcount: 6 | |
| 2382 | { lat: 230, common_pid: 2043 } hitcount: 1 | |
| 2383 | { lat: 230, common_pid: 2042 } hitcount: 2 | |
| 2384 | { lat: 231, common_pid: 2041 } hitcount: 1 | |
| 2385 | { lat: 231, common_pid: 2036 } hitcount: 6 | |
| 2386 | { lat: 231, common_pid: 2043 } hitcount: 1 | |
| 2387 | { lat: 231, common_pid: 2039 } hitcount: 8 | |
| 2388 | { lat: 232, common_pid: 2037 } hitcount: 1 | |
| 2389 | { lat: 232, common_pid: 2039 } hitcount: 6 | |
| 2390 | { lat: 232, common_pid: 2040 } hitcount: 2 | |
| 2391 | { lat: 232, common_pid: 2036 } hitcount: 5 | |
| 2392 | { lat: 232, common_pid: 2043 } hitcount: 1 | |
| 2393 | { lat: 233, common_pid: 2036 } hitcount: 5 | |
| 2394 | { lat: 233, common_pid: 2039 } hitcount: 11 | |
| 2395 | { lat: 234, common_pid: 2039 } hitcount: 4 | |
| 2396 | { lat: 234, common_pid: 2038 } hitcount: 2 | |
| 2397 | { lat: 234, common_pid: 2043 } hitcount: 2 | |
| 2398 | { lat: 234, common_pid: 2036 } hitcount: 11 | |
| 2399 | { lat: 234, common_pid: 2040 } hitcount: 1 | |
| 2400 | { lat: 235, common_pid: 2037 } hitcount: 2 | |
| 2401 | { lat: 235, common_pid: 2036 } hitcount: 8 | |
| 2402 | { lat: 235, common_pid: 2043 } hitcount: 2 | |
| 2403 | { lat: 235, common_pid: 2039 } hitcount: 5 | |
| 2404 | { lat: 235, common_pid: 2042 } hitcount: 2 | |
| 2405 | { lat: 235, common_pid: 2040 } hitcount: 4 | |
| 2406 | { lat: 235, common_pid: 2041 } hitcount: 1 | |
| 2407 | { lat: 236, common_pid: 2036 } hitcount: 7 | |
| 2408 | { lat: 236, common_pid: 2037 } hitcount: 1 | |
| 2409 | { lat: 236, common_pid: 2041 } hitcount: 5 | |
| 2410 | { lat: 236, common_pid: 2039 } hitcount: 3 | |
| 2411 | { lat: 236, common_pid: 2043 } hitcount: 9 | |
| 2412 | { lat: 236, common_pid: 2040 } hitcount: 7 | |
| 2413 | { lat: 237, common_pid: 2037 } hitcount: 1 | |
| 2414 | { lat: 237, common_pid: 2040 } hitcount: 1 | |
| 2415 | { lat: 237, common_pid: 2036 } hitcount: 9 | |
| 2416 | { lat: 237, common_pid: 2039 } hitcount: 3 | |
| 2417 | { lat: 237, common_pid: 2043 } hitcount: 8 | |
| 2418 | { lat: 237, common_pid: 2042 } hitcount: 2 | |
| 2419 | { lat: 237, common_pid: 2041 } hitcount: 2 | |
| 2420 | { lat: 238, common_pid: 2043 } hitcount: 10 | |
| 2421 | { lat: 238, common_pid: 2040 } hitcount: 1 | |
| 2422 | { lat: 238, common_pid: 2037 } hitcount: 9 | |
| 2423 | { lat: 238, common_pid: 2038 } hitcount: 1 | |
| 2424 | { lat: 238, common_pid: 2039 } hitcount: 1 | |
| 2425 | { lat: 238, common_pid: 2042 } hitcount: 3 | |
| 2426 | { lat: 238, common_pid: 2036 } hitcount: 7 | |
| 2427 | { lat: 239, common_pid: 2041 } hitcount: 1 | |
| 2428 | { lat: 239, common_pid: 2043 } hitcount: 11 | |
| 2429 | { lat: 239, common_pid: 2037 } hitcount: 11 | |
| 2430 | { lat: 239, common_pid: 2038 } hitcount: 6 | |
| 2431 | { lat: 239, common_pid: 2036 } hitcount: 7 | |
| 2432 | { lat: 239, common_pid: 2040 } hitcount: 1 | |
| 2433 | { lat: 239, common_pid: 2042 } hitcount: 9 | |
| 2434 | { lat: 240, common_pid: 2037 } hitcount: 29 | |
| 2435 | { lat: 240, common_pid: 2043 } hitcount: 15 | |
| 2436 | { lat: 240, common_pid: 2040 } hitcount: 44 | |
| 2437 | { lat: 240, common_pid: 2039 } hitcount: 1 | |
| 2438 | { lat: 240, common_pid: 2041 } hitcount: 2 | |
| 2439 | { lat: 240, common_pid: 2038 } hitcount: 1 | |
| 2440 | { lat: 240, common_pid: 2036 } hitcount: 10 | |
| 2441 | { lat: 240, common_pid: 2042 } hitcount: 13 | |
| 2442 | { lat: 241, common_pid: 2036 } hitcount: 21 | |
| 2443 | { lat: 241, common_pid: 2041 } hitcount: 36 | |
| 2444 | { lat: 241, common_pid: 2037 } hitcount: 34 | |
| 2445 | { lat: 241, common_pid: 2042 } hitcount: 14 | |
| 2446 | { lat: 241, common_pid: 2040 } hitcount: 94 | |
| 2447 | { lat: 241, common_pid: 2039 } hitcount: 12 | |
| 2448 | { lat: 241, common_pid: 2038 } hitcount: 2 | |
| 2449 | { lat: 241, common_pid: 2043 } hitcount: 28 | |
| 2450 | { lat: 242, common_pid: 2040 } hitcount: 109 | |
| 2451 | { lat: 242, common_pid: 2041 } hitcount: 506 | |
| 2452 | { lat: 242, common_pid: 2039 } hitcount: 155 | |
| 2453 | { lat: 242, common_pid: 2042 } hitcount: 21 | |
| 2454 | { lat: 242, common_pid: 2037 } hitcount: 52 | |
| 2455 | { lat: 242, common_pid: 2043 } hitcount: 21 | |
| 2456 | { lat: 242, common_pid: 2036 } hitcount: 16 | |
| 2457 | { lat: 242, common_pid: 2038 } hitcount: 156 | |
| 2458 | { lat: 243, common_pid: 2037 } hitcount: 46 | |
| 2459 | { lat: 243, common_pid: 2039 } hitcount: 40 | |
| 2460 | { lat: 243, common_pid: 2042 } hitcount: 119 | |
| 2461 | { lat: 243, common_pid: 2041 } hitcount: 611 | |
| 2462 | { lat: 243, common_pid: 2036 } hitcount: 69 | |
| 2463 | { lat: 243, common_pid: 2038 } hitcount: 784 | |
| 2464 | { lat: 243, common_pid: 2040 } hitcount: 323 | |
| 2465 | { lat: 243, common_pid: 2043 } hitcount: 14 | |
| 2466 | { lat: 244, common_pid: 2043 } hitcount: 35 | |
| 2467 | { lat: 244, common_pid: 2042 } hitcount: 305 | |
| 2468 | { lat: 244, common_pid: 2039 } hitcount: 8 | |
| 2469 | { lat: 244, common_pid: 2040 } hitcount: 4515 | |
| 2470 | { lat: 244, common_pid: 2038 } hitcount: 371 | |
| 2471 | { lat: 244, common_pid: 2037 } hitcount: 31 | |
| 2472 | { lat: 244, common_pid: 2036 } hitcount: 114 | |
| 2473 | { lat: 244, common_pid: 2041 } hitcount: 3396 | |
| 2474 | { lat: 245, common_pid: 2036 } hitcount: 700 | |
| 2475 | { lat: 245, common_pid: 2041 } hitcount: 2772 | |
| 2476 | { lat: 245, common_pid: 2037 } hitcount: 268 | |
| 2477 | { lat: 245, common_pid: 2039 } hitcount: 472 | |
| 2478 | { lat: 245, common_pid: 2038 } hitcount: 2758 | |
| 2479 | { lat: 245, common_pid: 2042 } hitcount: 3833 | |
| 2480 | { lat: 245, common_pid: 2040 } hitcount: 3105 | |
| 2481 | { lat: 245, common_pid: 2043 } hitcount: 645 | |
| 2482 | { lat: 246, common_pid: 2038 } hitcount: 3451 | |
| 2483 | { lat: 246, common_pid: 2041 } hitcount: 142 | |
| 2484 | { lat: 246, common_pid: 2037 } hitcount: 5101 | |
| 2485 | { lat: 246, common_pid: 2040 } hitcount: 68 | |
| 2486 | { lat: 246, common_pid: 2043 } hitcount: 5099 | |
| 2487 | { lat: 246, common_pid: 2039 } hitcount: 5608 | |
| 2488 | { lat: 246, common_pid: 2042 } hitcount: 3723 | |
| 2489 | { lat: 246, common_pid: 2036 } hitcount: 4738 | |
| 2490 | { lat: 247, common_pid: 2042 } hitcount: 312 | |
| 2491 | { lat: 247, common_pid: 2043 } hitcount: 2385 | |
| 2492 | { lat: 247, common_pid: 2041 } hitcount: 452 | |
| 2493 | { lat: 247, common_pid: 2038 } hitcount: 792 | |
| 2494 | { lat: 247, common_pid: 2040 } hitcount: 78 | |
| 2495 | { lat: 247, common_pid: 2036 } hitcount: 2375 | |
| 2496 | { lat: 247, common_pid: 2039 } hitcount: 1834 | |
| 2497 | { lat: 247, common_pid: 2037 } hitcount: 2655 | |
| 2498 | { lat: 248, common_pid: 2037 } hitcount: 36 | |
| 2499 | { lat: 248, common_pid: 2042 } hitcount: 11 | |
| 2500 | { lat: 248, common_pid: 2038 } hitcount: 122 | |
| 2501 | { lat: 248, common_pid: 2036 } hitcount: 135 | |
| 2502 | { lat: 248, common_pid: 2039 } hitcount: 26 | |
| 2503 | { lat: 248, common_pid: 2041 } hitcount: 503 | |
| 2504 | { lat: 248, common_pid: 2043 } hitcount: 66 | |
| 2505 | { lat: 248, common_pid: 2040 } hitcount: 46 | |
| 2506 | { lat: 249, common_pid: 2037 } hitcount: 29 | |
| 2507 | { lat: 249, common_pid: 2038 } hitcount: 1 | |
| 2508 | { lat: 249, common_pid: 2043 } hitcount: 29 | |
| 2509 | { lat: 249, common_pid: 2039 } hitcount: 8 | |
| 2510 | { lat: 249, common_pid: 2042 } hitcount: 56 | |
| 2511 | { lat: 249, common_pid: 2040 } hitcount: 27 | |
| 2512 | { lat: 249, common_pid: 2041 } hitcount: 11 | |
| 2513 | { lat: 249, common_pid: 2036 } hitcount: 27 | |
| 2514 | { lat: 250, common_pid: 2038 } hitcount: 1 | |
| 2515 | { lat: 250, common_pid: 2036 } hitcount: 30 | |
| 2516 | { lat: 250, common_pid: 2040 } hitcount: 19 | |
| 2517 | { lat: 250, common_pid: 2043 } hitcount: 22 | |
| 2518 | { lat: 250, common_pid: 2042 } hitcount: 20 | |
| 2519 | { lat: 250, common_pid: 2041 } hitcount: 1 | |
| 2520 | { lat: 250, common_pid: 2039 } hitcount: 6 | |
| 2521 | { lat: 250, common_pid: 2037 } hitcount: 48 | |
| 2522 | { lat: 251, common_pid: 2037 } hitcount: 43 | |
| 2523 | { lat: 251, common_pid: 2039 } hitcount: 1 | |
| 2524 | { lat: 251, common_pid: 2036 } hitcount: 12 | |
| 2525 | { lat: 251, common_pid: 2042 } hitcount: 2 | |
| 2526 | { lat: 251, common_pid: 2041 } hitcount: 1 | |
| 2527 | { lat: 251, common_pid: 2043 } hitcount: 15 | |
| 2528 | { lat: 251, common_pid: 2040 } hitcount: 3 | |
| 2529 | { lat: 252, common_pid: 2040 } hitcount: 1 | |
| 2530 | { lat: 252, common_pid: 2036 } hitcount: 12 | |
| 2531 | { lat: 252, common_pid: 2037 } hitcount: 21 | |
| 2532 | { lat: 252, common_pid: 2043 } hitcount: 14 | |
| 2533 | { lat: 253, common_pid: 2037 } hitcount: 21 | |
| 2534 | { lat: 253, common_pid: 2039 } hitcount: 2 | |
| 2535 | { lat: 253, common_pid: 2036 } hitcount: 9 | |
| 2536 | { lat: 253, common_pid: 2043 } hitcount: 6 | |
| 2537 | { lat: 253, common_pid: 2040 } hitcount: 1 | |
| 2538 | { lat: 254, common_pid: 2036 } hitcount: 8 | |
| 2539 | { lat: 254, common_pid: 2043 } hitcount: 3 | |
| 2540 | { lat: 254, common_pid: 2041 } hitcount: 1 | |
| 2541 | { lat: 254, common_pid: 2042 } hitcount: 1 | |
| 2542 | { lat: 254, common_pid: 2039 } hitcount: 1 | |
| 2543 | { lat: 254, common_pid: 2037 } hitcount: 12 | |
| 2544 | { lat: 255, common_pid: 2043 } hitcount: 1 | |
| 2545 | { lat: 255, common_pid: 2037 } hitcount: 2 | |
| 2546 | { lat: 255, common_pid: 2036 } hitcount: 2 | |
| 2547 | { lat: 255, common_pid: 2039 } hitcount: 8 | |
| 2548 | { lat: 256, common_pid: 2043 } hitcount: 1 | |
| 2549 | { lat: 256, common_pid: 2036 } hitcount: 4 | |
| 2550 | { lat: 256, common_pid: 2039 } hitcount: 6 | |
| 2551 | { lat: 257, common_pid: 2039 } hitcount: 5 | |
| 2552 | { lat: 257, common_pid: 2036 } hitcount: 4 | |
| 2553 | { lat: 258, common_pid: 2039 } hitcount: 5 | |
| 2554 | { lat: 258, common_pid: 2036 } hitcount: 2 | |
| 2555 | { lat: 259, common_pid: 2036 } hitcount: 7 | |
| 2556 | { lat: 259, common_pid: 2039 } hitcount: 7 | |
| 2557 | { lat: 260, common_pid: 2036 } hitcount: 8 | |
| 2558 | { lat: 260, common_pid: 2039 } hitcount: 6 | |
| 2559 | { lat: 261, common_pid: 2036 } hitcount: 5 | |
| 2560 | { lat: 261, common_pid: 2039 } hitcount: 7 | |
| 2561 | { lat: 262, common_pid: 2039 } hitcount: 5 | |
| 2562 | { lat: 262, common_pid: 2036 } hitcount: 5 | |
| 2563 | { lat: 263, common_pid: 2039 } hitcount: 7 | |
| 2564 | { lat: 263, common_pid: 2036 } hitcount: 7 | |
| 2565 | { lat: 264, common_pid: 2039 } hitcount: 9 | |
| 2566 | { lat: 264, common_pid: 2036 } hitcount: 9 | |
| 2567 | { lat: 265, common_pid: 2036 } hitcount: 5 | |
| 2568 | { lat: 265, common_pid: 2039 } hitcount: 1 | |
| 2569 | { lat: 266, common_pid: 2036 } hitcount: 1 | |
| 2570 | { lat: 266, common_pid: 2039 } hitcount: 3 | |
| 2571 | { lat: 267, common_pid: 2036 } hitcount: 1 | |
| 2572 | { lat: 267, common_pid: 2039 } hitcount: 3 | |
| 2573 | { lat: 268, common_pid: 2036 } hitcount: 1 | |
| 2574 | { lat: 268, common_pid: 2039 } hitcount: 6 | |
| 2575 | { lat: 269, common_pid: 2036 } hitcount: 1 | |
| 2576 | { lat: 269, common_pid: 2043 } hitcount: 1 | |
| 2577 | { lat: 269, common_pid: 2039 } hitcount: 2 | |
| 2578 | { lat: 270, common_pid: 2040 } hitcount: 1 | |
| 2579 | { lat: 270, common_pid: 2039 } hitcount: 6 | |
| 2580 | { lat: 271, common_pid: 2041 } hitcount: 1 | |
| 2581 | { lat: 271, common_pid: 2039 } hitcount: 5 | |
| 2582 | { lat: 272, common_pid: 2039 } hitcount: 10 | |
| 2583 | { lat: 273, common_pid: 2039 } hitcount: 8 | |
| 2584 | { lat: 274, common_pid: 2039 } hitcount: 2 | |
| 2585 | { lat: 275, common_pid: 2039 } hitcount: 1 | |
| 2586 | { lat: 276, common_pid: 2039 } hitcount: 2 | |
| 2587 | { lat: 276, common_pid: 2037 } hitcount: 1 | |
| 2588 | { lat: 276, common_pid: 2038 } hitcount: 1 | |
| 2589 | { lat: 277, common_pid: 2039 } hitcount: 1 | |
| 2590 | { lat: 277, common_pid: 2042 } hitcount: 1 | |
| 2591 | { lat: 278, common_pid: 2039 } hitcount: 1 | |
| 2592 | { lat: 279, common_pid: 2039 } hitcount: 4 | |
| 2593 | { lat: 279, common_pid: 2043 } hitcount: 1 | |
| 2594 | { lat: 280, common_pid: 2039 } hitcount: 3 | |
| 2595 | { lat: 283, common_pid: 2036 } hitcount: 2 | |
| 2596 | { lat: 284, common_pid: 2039 } hitcount: 1 | |
| 2597 | { lat: 284, common_pid: 2043 } hitcount: 1 | |
| 2598 | { lat: 288, common_pid: 2039 } hitcount: 1 | |
| 2599 | { lat: 289, common_pid: 2039 } hitcount: 1 | |
| 2600 | { lat: 300, common_pid: 2039 } hitcount: 1 | |
| 2601 | { lat: 384, common_pid: 2039 } hitcount: 1 | |
| 2602 | ||
| 2603 | Totals: | |
| 2604 | Hits: 67625 | |
| 2605 | Entries: 278 | |
| 2606 | Dropped: 0 | |
| d3439f9d SRV |
2607 | |
| 2608 | Note, the writes are around the sleep, so ideally they will all be of 250 | |
| 2609 | microseconds. If you are wondering how there are several that are under | |
| 2610 | 250 microseconds, that is because the way cyclictest works, is if one | |
| 2611 | iteration comes in late, the next one will set the timer to wake up less that | |
| 2612 | 250. That is, if an iteration came in 50 microseconds late, the next wake up | |
| 2613 | will be at 200 microseconds. | |
| 2614 | ||
| 2615 | But this could easily be done in userspace. To make this even more | |
| 2616 | interesting, we can mix the histogram between events that happened in the | |
| ea272257 | 2617 | kernel with trace_marker:: |
| d3439f9d SRV |
2618 | |
| 2619 | # cd /sys/kernel/tracing | |
| 2620 | # echo 'latency u64 lat' > synthetic_events | |
| 2621 | # echo 'hist:keys=pid:ts0=common_timestamp.usecs' > events/sched/sched_waking/trigger | |
| 2622 | # echo 'hist:keys=common_pid:lat=common_timestamp.usecs-$ts0:onmatch(sched.sched_waking).latency($lat) if buf == "end"' > events/ftrace/print/trigger | |
| 2623 | # echo 'hist:keys=lat,common_pid:sort=lat' > events/synthetic/latency/trigger | |
| 2624 | ||
| 2625 | The difference this time is that instead of using the trace_marker to start | |
| 2626 | the latency, the sched_waking event is used, matching the common_pid for the | |
| 2627 | trace_marker write with the pid that is being woken by sched_waking. | |
| 2628 | ||
| ea272257 | 2629 | After running cyclictest again with the same parameters, we now have:: |
| d3439f9d SRV |
2630 | |
| 2631 | # cat events/synthetic/latency/hist | |
| ea272257 MCC |
2632 | # event histogram |
| 2633 | # | |
| 2634 | # trigger info: hist:keys=lat,common_pid:vals=hitcount:sort=lat:size=2048 [active] | |
| 2635 | # | |
| 2636 | ||
| 2637 | { lat: 7, common_pid: 2302 } hitcount: 640 | |
| 2638 | { lat: 7, common_pid: 2299 } hitcount: 42 | |
| 2639 | { lat: 7, common_pid: 2303 } hitcount: 18 | |
| 2640 | { lat: 7, common_pid: 2305 } hitcount: 166 | |
| 2641 | { lat: 7, common_pid: 2306 } hitcount: 1 | |
| 2642 | { lat: 7, common_pid: 2301 } hitcount: 91 | |
| 2643 | { lat: 7, common_pid: 2300 } hitcount: 17 | |
| 2644 | { lat: 8, common_pid: 2303 } hitcount: 8296 | |
| 2645 | { lat: 8, common_pid: 2304 } hitcount: 6864 | |
| 2646 | { lat: 8, common_pid: 2305 } hitcount: 9464 | |
| 2647 | { lat: 8, common_pid: 2301 } hitcount: 9213 | |
| 2648 | { lat: 8, common_pid: 2306 } hitcount: 6246 | |
| 2649 | { lat: 8, common_pid: 2302 } hitcount: 8797 | |
| 2650 | { lat: 8, common_pid: 2299 } hitcount: 8771 | |
| 2651 | { lat: 8, common_pid: 2300 } hitcount: 8119 | |
| 2652 | { lat: 9, common_pid: 2305 } hitcount: 1519 | |
| 2653 | { lat: 9, common_pid: 2299 } hitcount: 2346 | |
| 2654 | { lat: 9, common_pid: 2303 } hitcount: 2841 | |
| 2655 | { lat: 9, common_pid: 2301 } hitcount: 1846 | |
| 2656 | { lat: 9, common_pid: 2304 } hitcount: 3861 | |
| 2657 | { lat: 9, common_pid: 2302 } hitcount: 1210 | |
| 2658 | { lat: 9, common_pid: 2300 } hitcount: 2762 | |
| 2659 | { lat: 9, common_pid: 2306 } hitcount: 4247 | |
| 2660 | { lat: 10, common_pid: 2299 } hitcount: 16 | |
| 2661 | { lat: 10, common_pid: 2306 } hitcount: 333 | |
| 2662 | { lat: 10, common_pid: 2303 } hitcount: 16 | |
| 2663 | { lat: 10, common_pid: 2304 } hitcount: 168 | |
| 2664 | { lat: 10, common_pid: 2302 } hitcount: 240 | |
| 2665 | { lat: 10, common_pid: 2301 } hitcount: 28 | |
| 2666 | { lat: 10, common_pid: 2300 } hitcount: 95 | |
| 2667 | { lat: 10, common_pid: 2305 } hitcount: 18 | |
| 2668 | { lat: 11, common_pid: 2303 } hitcount: 5 | |
| 2669 | { lat: 11, common_pid: 2305 } hitcount: 8 | |
| 2670 | { lat: 11, common_pid: 2306 } hitcount: 221 | |
| 2671 | { lat: 11, common_pid: 2302 } hitcount: 76 | |
| 2672 | { lat: 11, common_pid: 2304 } hitcount: 26 | |
| 2673 | { lat: 11, common_pid: 2300 } hitcount: 125 | |
| 2674 | { lat: 11, common_pid: 2299 } hitcount: 2 | |
| 2675 | { lat: 12, common_pid: 2305 } hitcount: 3 | |
| 2676 | { lat: 12, common_pid: 2300 } hitcount: 6 | |
| 2677 | { lat: 12, common_pid: 2306 } hitcount: 90 | |
| 2678 | { lat: 12, common_pid: 2302 } hitcount: 4 | |
| 2679 | { lat: 12, common_pid: 2303 } hitcount: 1 | |
| 2680 | { lat: 12, common_pid: 2304 } hitcount: 122 | |
| 2681 | { lat: 13, common_pid: 2300 } hitcount: 12 | |
| 2682 | { lat: 13, common_pid: 2301 } hitcount: 1 | |
| 2683 | { lat: 13, common_pid: 2306 } hitcount: 32 | |
| 2684 | { lat: 13, common_pid: 2302 } hitcount: 5 | |
| 2685 | { lat: 13, common_pid: 2305 } hitcount: 1 | |
| 2686 | { lat: 13, common_pid: 2303 } hitcount: 1 | |
| 2687 | { lat: 13, common_pid: 2304 } hitcount: 61 | |
| 2688 | { lat: 14, common_pid: 2303 } hitcount: 4 | |
| 2689 | { lat: 14, common_pid: 2306 } hitcount: 5 | |
| 2690 | { lat: 14, common_pid: 2305 } hitcount: 4 | |
| 2691 | { lat: 14, common_pid: 2304 } hitcount: 62 | |
| 2692 | { lat: 14, common_pid: 2302 } hitcount: 19 | |
| 2693 | { lat: 14, common_pid: 2300 } hitcount: 33 | |
| 2694 | { lat: 14, common_pid: 2299 } hitcount: 1 | |
| 2695 | { lat: 14, common_pid: 2301 } hitcount: 4 | |
| 2696 | { lat: 15, common_pid: 2305 } hitcount: 1 | |
| 2697 | { lat: 15, common_pid: 2302 } hitcount: 25 | |
| 2698 | { lat: 15, common_pid: 2300 } hitcount: 11 | |
| 2699 | { lat: 15, common_pid: 2299 } hitcount: 5 | |
| 2700 | { lat: 15, common_pid: 2301 } hitcount: 1 | |
| 2701 | { lat: 15, common_pid: 2304 } hitcount: 8 | |
| 2702 | { lat: 15, common_pid: 2303 } hitcount: 1 | |
| 2703 | { lat: 15, common_pid: 2306 } hitcount: 6 | |
| 2704 | { lat: 16, common_pid: 2302 } hitcount: 31 | |
| 2705 | { lat: 16, common_pid: 2306 } hitcount: 3 | |
| 2706 | { lat: 16, common_pid: 2300 } hitcount: 5 | |
| 2707 | { lat: 17, common_pid: 2302 } hitcount: 6 | |
| 2708 | { lat: 17, common_pid: 2303 } hitcount: 1 | |
| 2709 | { lat: 18, common_pid: 2304 } hitcount: 1 | |
| 2710 | { lat: 18, common_pid: 2302 } hitcount: 8 | |
| 2711 | { lat: 18, common_pid: 2299 } hitcount: 1 | |
| 2712 | { lat: 18, common_pid: 2301 } hitcount: 1 | |
| 2713 | { lat: 19, common_pid: 2303 } hitcount: 4 | |
| 2714 | { lat: 19, common_pid: 2304 } hitcount: 5 | |
| 2715 | { lat: 19, common_pid: 2302 } hitcount: 4 | |
| 2716 | { lat: 19, common_pid: 2299 } hitcount: 3 | |
| 2717 | { lat: 19, common_pid: 2306 } hitcount: 1 | |
| 2718 | { lat: 19, common_pid: 2300 } hitcount: 4 | |
| 2719 | { lat: 19, common_pid: 2305 } hitcount: 5 | |
| 2720 | { lat: 20, common_pid: 2299 } hitcount: 2 | |
| 2721 | { lat: 20, common_pid: 2302 } hitcount: 3 | |
| 2722 | { lat: 20, common_pid: 2305 } hitcount: 1 | |
| 2723 | { lat: 20, common_pid: 2300 } hitcount: 2 | |
| 2724 | { lat: 20, common_pid: 2301 } hitcount: 2 | |
| 2725 | { lat: 20, common_pid: 2303 } hitcount: 3 | |
| 2726 | { lat: 21, common_pid: 2305 } hitcount: 1 | |
| 2727 | { lat: 21, common_pid: 2299 } hitcount: 5 | |
| 2728 | { lat: 21, common_pid: 2303 } hitcount: 4 | |
| 2729 | { lat: 21, common_pid: 2302 } hitcount: 7 | |
| 2730 | { lat: 21, common_pid: 2300 } hitcount: 1 | |
| 2731 | { lat: 21, common_pid: 2301 } hitcount: 5 | |
| 2732 | { lat: 21, common_pid: 2304 } hitcount: 2 | |
| 2733 | { lat: 22, common_pid: 2302 } hitcount: 5 | |
| 2734 | { lat: 22, common_pid: 2303 } hitcount: 1 | |
| 2735 | { lat: 22, common_pid: 2306 } hitcount: 3 | |
| 2736 | { lat: 22, common_pid: 2301 } hitcount: 2 | |
| 2737 | { lat: 22, common_pid: 2300 } hitcount: 1 | |
| 2738 | { lat: 22, common_pid: 2299 } hitcount: 1 | |
| 2739 | { lat: 22, common_pid: 2305 } hitcount: 1 | |
| 2740 | { lat: 22, common_pid: 2304 } hitcount: 1 | |
| 2741 | { lat: 23, common_pid: 2299 } hitcount: 1 | |
| 2742 | { lat: 23, common_pid: 2306 } hitcount: 2 | |
| 2743 | { lat: 23, common_pid: 2302 } hitcount: 6 | |
| 2744 | { lat: 24, common_pid: 2302 } hitcount: 3 | |
| 2745 | { lat: 24, common_pid: 2300 } hitcount: 1 | |
| 2746 | { lat: 24, common_pid: 2306 } hitcount: 2 | |
| 2747 | { lat: 24, common_pid: 2305 } hitcount: 1 | |
| 2748 | { lat: 24, common_pid: 2299 } hitcount: 1 | |
| 2749 | { lat: 25, common_pid: 2300 } hitcount: 1 | |
| 2750 | { lat: 25, common_pid: 2302 } hitcount: 4 | |
| 2751 | { lat: 26, common_pid: 2302 } hitcount: 2 | |
| 2752 | { lat: 27, common_pid: 2305 } hitcount: 1 | |
| 2753 | { lat: 27, common_pid: 2300 } hitcount: 1 | |
| 2754 | { lat: 27, common_pid: 2302 } hitcount: 3 | |
| 2755 | { lat: 28, common_pid: 2306 } hitcount: 1 | |
| 2756 | { lat: 28, common_pid: 2302 } hitcount: 4 | |
| 2757 | { lat: 29, common_pid: 2302 } hitcount: 1 | |
| 2758 | { lat: 29, common_pid: 2300 } hitcount: 2 | |
| 2759 | { lat: 29, common_pid: 2306 } hitcount: 1 | |
| 2760 | { lat: 29, common_pid: 2304 } hitcount: 1 | |
| 2761 | { lat: 30, common_pid: 2302 } hitcount: 4 | |
| 2762 | { lat: 31, common_pid: 2302 } hitcount: 6 | |
| 2763 | { lat: 32, common_pid: 2302 } hitcount: 1 | |
| 2764 | { lat: 33, common_pid: 2299 } hitcount: 1 | |
| 2765 | { lat: 33, common_pid: 2302 } hitcount: 3 | |
| 2766 | { lat: 34, common_pid: 2302 } hitcount: 2 | |
| 2767 | { lat: 35, common_pid: 2302 } hitcount: 1 | |
| 2768 | { lat: 35, common_pid: 2304 } hitcount: 1 | |
| 2769 | { lat: 36, common_pid: 2302 } hitcount: 4 | |
| 2770 | { lat: 37, common_pid: 2302 } hitcount: 6 | |
| 2771 | { lat: 38, common_pid: 2302 } hitcount: 2 | |
| 2772 | { lat: 39, common_pid: 2302 } hitcount: 2 | |
| 2773 | { lat: 39, common_pid: 2304 } hitcount: 1 | |
| 2774 | { lat: 40, common_pid: 2304 } hitcount: 2 | |
| 2775 | { lat: 40, common_pid: 2302 } hitcount: 5 | |
| 2776 | { lat: 41, common_pid: 2304 } hitcount: 1 | |
| 2777 | { lat: 41, common_pid: 2302 } hitcount: 8 | |
| 2778 | { lat: 42, common_pid: 2302 } hitcount: 6 | |
| 2779 | { lat: 42, common_pid: 2304 } hitcount: 1 | |
| 2780 | { lat: 43, common_pid: 2302 } hitcount: 3 | |
| 2781 | { lat: 43, common_pid: 2304 } hitcount: 4 | |
| 2782 | { lat: 44, common_pid: 2302 } hitcount: 6 | |
| 2783 | { lat: 45, common_pid: 2302 } hitcount: 5 | |
| 2784 | { lat: 46, common_pid: 2302 } hitcount: 5 | |
| 2785 | { lat: 47, common_pid: 2302 } hitcount: 7 | |
| 2786 | { lat: 48, common_pid: 2301 } hitcount: 1 | |
| 2787 | { lat: 48, common_pid: 2302 } hitcount: 9 | |
| 2788 | { lat: 49, common_pid: 2302 } hitcount: 3 | |
| 2789 | { lat: 50, common_pid: 2302 } hitcount: 1 | |
| 2790 | { lat: 50, common_pid: 2301 } hitcount: 1 | |
| 2791 | { lat: 51, common_pid: 2302 } hitcount: 2 | |
| 2792 | { lat: 51, common_pid: 2301 } hitcount: 1 | |
| 2793 | { lat: 61, common_pid: 2302 } hitcount: 1 | |
| 2794 | { lat: 110, common_pid: 2302 } hitcount: 1 | |
| 2795 | ||
| 2796 | Totals: | |
| 2797 | Hits: 89565 | |
| 2798 | Entries: 158 | |
| 2799 | Dropped: 0 | |
| d3439f9d SRV |
2800 | |
| 2801 | This doesn't tell us any information about how late cyclictest may have | |
| 2802 | woken up, but it does show us a nice histogram of how long it took from | |
| 2803 | the time that cyclictest was woken to the time it made it into user space. |