2116 lines · plain
1.. SPDX-License-Identifier: GPL-2.02 3======================4Histogram Design Notes5======================6 7:Author: Tom Zanussi <zanussi@kernel.org>8 9This document attempts to provide a description of how the ftrace10histograms work and how the individual pieces map to the data11structures used to implement them in trace_events_hist.c and12tracing_map.c.13 14Note: All the ftrace histogram command examples assume the working15 directory is the ftrace /tracing directory. For example::16 17 # cd /sys/kernel/tracing18 19Also, the histogram output displayed for those commands will be20generally be truncated - only enough to make the point is displayed.21 22'hist_debug' trace event files23==============================24 25If the kernel is compiled with CONFIG_HIST_TRIGGERS_DEBUG set, an26event file named 'hist_debug' will appear in each event's27subdirectory. This file can be read at any time and will display some28of the hist trigger internals described in this document. Specific29examples and output will be described in test cases below.30 31Basic histograms32================33 34First, basic histograms. Below is pretty much the simplest thing you35can do with histograms - create one with a single key on a single36event and cat the output::37 38 # echo 'hist:keys=pid' >> events/sched/sched_waking/trigger39 40 # cat events/sched/sched_waking/hist41 42 { pid: 18249 } hitcount: 143 { pid: 13399 } hitcount: 144 { pid: 17973 } hitcount: 145 { pid: 12572 } hitcount: 146 ...47 { pid: 10 } hitcount: 92148 { pid: 18255 } hitcount: 144449 { pid: 25526 } hitcount: 205550 { pid: 5257 } hitcount: 205551 { pid: 27367 } hitcount: 205552 { pid: 1728 } hitcount: 216153 54 Totals:55 Hits: 2130556 Entries: 18357 Dropped: 058 59What this does is create a histogram on the sched_waking event using60pid as a key and with a single value, hitcount, which even if not61explicitly specified, exists for every histogram regardless.62 63The hitcount value is a per-bucket value that's automatically64incremented on every hit for the given key, which in this case is the65pid.66 67So in this histogram, there's a separate bucket for each pid, and each68bucket contains a value for that bucket, counting the number of times69sched_waking was called for that pid.70 71Each histogram is represented by a hist_data struct.72 73To keep track of each key and value field in the histogram, hist_data74keeps an array of these fields named fields[]. The fields[] array is75an array containing struct hist_field representations of each76histogram val and key in the histogram (variables are also included77here, but are discussed later). So for the above histogram we have one78key and one value; in this case the one value is the hitcount value,79which all histograms have, regardless of whether they define that80value or not, which the above histogram does not.81 82Each struct hist_field contains a pointer to the ftrace_event_field83from the event's trace_event_file along with various bits related to84that such as the size, offset, type, and a hist_field_fn_t function,85which is used to grab the field's data from the ftrace event buffer86(in most cases - some hist_fields such as hitcount don't directly map87to an event field in the trace buffer - in these cases the function88implementation gets its value from somewhere else). The flags field89indicates which type of field it is - key, value, variable, variable90reference, etc., with value being the default.91 92The other important hist_data data structure in addition to the93fields[] array is the tracing_map instance created for the histogram,94which is held in the .map member. The tracing_map implements the95lock-free hash table used to implement histograms (see96kernel/trace/tracing_map.h for much more discussion about the97low-level data structures implementing the tracing_map). For the98purposes of this discussion, the tracing_map contains a number of99buckets, each bucket corresponding to a particular tracing_map_elt100object hashed by a given histogram key.101 102Below is a diagram the first part of which describes the hist_data and103associated key and value fields for the histogram described above. As104you can see, there are two fields in the fields array, one val field105for the hitcount and one key field for the pid key.106 107Below that is a diagram of a run-time snapshot of what the tracing_map108might look like for a given run. It attempts to show the109relationships between the hist_data fields and the tracing_map110elements for a couple hypothetical keys and values.::111 112 +------------------+113 | hist_data |114 +------------------+ +----------------+115 | .fields[] |---->| val = hitcount |----------------------------+116 +----------------+ +----------------+ |117 | .map | | .size | |118 +----------------+ +--------------+ |119 | .offset | |120 +--------------+ |121 | .fn() | |122 +--------------+ |123 . |124 . |125 . |126 +----------------+ <--- n_vals |127 | key = pid |----------------------------|--+128 +----------------+ | |129 | .size | | |130 +--------------+ | |131 | .offset | | |132 +--------------+ | |133 | .fn() | | |134 +----------------+ <--- n_fields | |135 | unused | | |136 +----------------+ | |137 | | | |138 +--------------+ | |139 | | | |140 +--------------+ | |141 | | | |142 +--------------+ | |143 n_keys = n_fields - n_vals | |144 145The hist_data n_vals and n_fields delineate the extent of the fields[] | |146array and separate keys from values for the rest of the code. | |147 148Below is a run-time representation of the tracing_map part of the | |149histogram, with pointers from various parts of the fields[] array | |150to corresponding parts of the tracing_map. | |151 152The tracing_map consists of an array of tracing_map_entrys and a set | |153of preallocated tracing_map_elts (abbreviated below as map_entry and | |154map_elt). The total number of map_entrys in the hist_data.map array = | |155map->max_elts (actually map->map_size but only max_elts of those are | |156used. This is a property required by the map_insert() algorithm). | |157 158If a map_entry is unused, meaning no key has yet hashed into it, its | |159.key value is 0 and its .val pointer is NULL. Once a map_entry has | |160been claimed, the .key value contains the key's hash value and the | |161.val member points to a map_elt containing the full key and an entry | |162for each key or value in the map_elt.fields[] array. There is an | |163entry in the map_elt.fields[] array corresponding to each hist_field | |164in the histogram, and this is where the continually aggregated sums | |165corresponding to each histogram value are kept. | |166 167The diagram attempts to show the relationship between the | |168hist_data.fields[] and the map_elt.fields[] with the links drawn | |169between diagrams::170 171 +-----------+ | |172 | hist_data | | |173 +-----------+ | |174 | .fields | | |175 +---------+ +-----------+ | |176 | .map |---->| map_entry | | |177 +---------+ +-----------+ | |178 | .key |---> 0 | |179 +---------+ | |180 | .val |---> NULL | |181 +-----------+ | |182 | map_entry | | |183 +-----------+ | |184 | .key |---> pid = 999 | |185 +---------+ +-----------+ | |186 | .val |--->| map_elt | | |187 +---------+ +-----------+ | |188 . | .key |---> full key * | |189 . +---------+ +---------------+ | |190 . | .fields |--->| .sum (val) |<-+ |191 +-----------+ +---------+ | 2345 | | |192 | map_entry | +---------------+ | |193 +-----------+ | .offset (key) |<----+194 | .key |---> 0 | 0 | | |195 +---------+ +---------------+ | |196 | .val |---> NULL . | |197 +-----------+ . | |198 | map_entry | . | |199 +-----------+ +---------------+ | |200 | .key | | .sum (val) or | | |201 +---------+ +---------+ | .offset (key) | | |202 | .val |--->| map_elt | +---------------+ | |203 +-----------+ +---------+ | .sum (val) or | | |204 | map_entry | | .offset (key) | | |205 +-----------+ +---------------+ | |206 | .key |---> pid = 4444 | |207 +---------+ +-----------+ | |208 | .val | | map_elt | | |209 +---------+ +-----------+ | |210 | .key |---> full key * | |211 +---------+ +---------------+ | |212 | .fields |--->| .sum (val) |<-+ |213 +---------+ | 65523 | |214 +---------------+ |215 | .offset (key) |<----+216 | 0 |217 +---------------+218 .219 .220 .221 +---------------+222 | .sum (val) or |223 | .offset (key) |224 +---------------+225 | .sum (val) or |226 | .offset (key) |227 +---------------+228 229Abbreviations used in the diagrams::230 231 hist_data = struct hist_trigger_data232 hist_data.fields = struct hist_field233 fn = hist_field_fn_t234 map_entry = struct tracing_map_entry235 map_elt = struct tracing_map_elt236 map_elt.fields = struct tracing_map_field237 238Whenever a new event occurs and it has a hist trigger associated with239it, event_hist_trigger() is called. event_hist_trigger() first deals240with the key: for each subkey in the key (in the above example, there241is just one subkey corresponding to pid), the hist_field that242represents that subkey is retrieved from hist_data.fields[] and the243hist_field_fn_t fn() associated with that field, along with the244field's size and offset, is used to grab that subkey's data from the245current trace record.246 247Once the complete key has been retrieved, it's used to look that key248up in the tracing_map. If there's no tracing_map_elt associated with249that key, an empty one is claimed and inserted in the map for the new250key. In either case, the tracing_map_elt associated with that key is251returned.252 253Once a tracing_map_elt available, hist_trigger_elt_update() is called.254As the name implies, this updates the element, which basically means255updating the element's fields. There's a tracing_map_field associated256with each key and value in the histogram, and each of these correspond257to the key and value hist_fields created when the histogram was258created. hist_trigger_elt_update() goes through each value hist_field259and, as for the keys, uses the hist_field's fn() and size and offset260to grab the field's value from the current trace record. Once it has261that value, it simply adds that value to that field's262continually-updated tracing_map_field.sum member. Some hist_field263fn()s, such as for the hitcount, don't actually grab anything from the264trace record (the hitcount fn() just increments the counter sum by 1),265but the idea is the same.266 267Once all the values have been updated, hist_trigger_elt_update() is268done and returns. Note that there are also tracing_map_fields for269each subkey in the key, but hist_trigger_elt_update() doesn't look at270them or update anything - those exist only for sorting, which can271happen later.272 273Basic histogram test274--------------------275 276This is a good example to try. It produces 3 value fields and 2 key277fields in the output::278 279 # echo 'hist:keys=common_pid,call_site.sym:values=bytes_req,bytes_alloc,hitcount' >> events/kmem/kmalloc/trigger280 281To see the debug data, cat the kmem/kmalloc's 'hist_debug' file. It282will show the trigger info of the histogram it corresponds to, along283with the address of the hist_data associated with the histogram, which284will become useful in later examples. It then displays the number of285total hist_fields associated with the histogram along with a count of286how many of those correspond to keys and how many correspond to values.287 288It then goes on to display details for each field, including the289field's flags and the position of each field in the hist_data's290fields[] array, which is useful information for verifying that things291internally appear correct or not, and which again will become even292more useful in further examples::293 294 # cat events/kmem/kmalloc/hist_debug295 296 # event histogram297 #298 # trigger info: hist:keys=common_pid,call_site.sym:vals=hitcount,bytes_req,bytes_alloc:sort=hitcount:size=2048 [active]299 #300 301 hist_data: 000000005e48c9a5302 303 n_vals: 3304 n_keys: 2305 n_fields: 5306 307 val fields:308 309 hist_data->fields[0]:310 flags:311 VAL: HIST_FIELD_FL_HITCOUNT312 type: u64313 size: 8314 is_signed: 0315 316 hist_data->fields[1]:317 flags:318 VAL: normal u64 value319 ftrace_event_field name: bytes_req320 type: size_t321 size: 8322 is_signed: 0323 324 hist_data->fields[2]:325 flags:326 VAL: normal u64 value327 ftrace_event_field name: bytes_alloc328 type: size_t329 size: 8330 is_signed: 0331 332 key fields:333 334 hist_data->fields[3]:335 flags:336 HIST_FIELD_FL_KEY337 ftrace_event_field name: common_pid338 type: int339 size: 8340 is_signed: 1341 342 hist_data->fields[4]:343 flags:344 HIST_FIELD_FL_KEY345 ftrace_event_field name: call_site346 type: unsigned long347 size: 8348 is_signed: 0349 350The commands below can be used to clean things up for the next test::351 352 # echo '!hist:keys=common_pid,call_site.sym:values=bytes_req,bytes_alloc,hitcount' >> events/kmem/kmalloc/trigger353 354Variables355=========356 357Variables allow data from one hist trigger to be saved by one hist358trigger and retrieved by another hist trigger. For example, a trigger359on the sched_waking event can capture a timestamp for a particular360pid, and later a sched_switch event that switches to that pid event361can grab the timestamp and use it to calculate a time delta between362the two events::363 364 # echo 'hist:keys=pid:ts0=common_timestamp.usecs' >>365 events/sched/sched_waking/trigger366 367 # echo 'hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0' >>368 events/sched/sched_switch/trigger369 370In terms of the histogram data structures, variables are implemented371as another type of hist_field and for a given hist trigger are added372to the hist_data.fields[] array just after all the val fields. To373distinguish them from the existing key and val fields, they're given a374new flag type, HIST_FIELD_FL_VAR (abbreviated FL_VAR) and they also375make use of a new .var.idx field member in struct hist_field, which376maps them to an index in a new map_elt.vars[] array added to the377map_elt specifically designed to store and retrieve variable values.378The diagram below shows those new elements and adds a new variable379entry, ts0, corresponding to the ts0 variable in the sched_waking380trigger above.381 382sched_waking histogram383----------------------::384 385 +------------------+386 | hist_data |<-------------------------------------------------------+387 +------------------+ +-------------------+ |388 | .fields[] |-->| val = hitcount | |389 +----------------+ +-------------------+ |390 | .map | | .size | |391 +----------------+ +-----------------+ |392 | .offset | |393 +-----------------+ |394 | .fn() | |395 +-----------------+ |396 | .flags | |397 +-----------------+ |398 | .var.idx | |399 +-------------------+ |400 | var = ts0 | |401 +-------------------+ |402 | .size | |403 +-----------------+ |404 | .offset | |405 +-----------------+ |406 | .fn() | |407 +-----------------+ |408 | .flags & FL_VAR | |409 +-----------------+ |410 | .var.idx |----------------------------+-+ |411 +-----------------+ | | |412 . | | |413 . | | |414 . | | |415 +-------------------+ <--- n_vals | | |416 | key = pid | | | |417 +-------------------+ | | |418 | .size | | | |419 +-----------------+ | | |420 | .offset | | | |421 +-----------------+ | | |422 | .fn() | | | |423 +-----------------+ | | |424 | .flags & FL_KEY | | | |425 +-----------------+ | | |426 | .var.idx | | | |427 +-------------------+ <--- n_fields | | |428 | unused | | | |429 +-------------------+ | | |430 | | | | |431 +-----------------+ | | |432 | | | | |433 +-----------------+ | | |434 | | | | |435 +-----------------+ | | |436 | | | | |437 +-----------------+ | | |438 | | | | |439 +-----------------+ | | |440 n_keys = n_fields - n_vals | | |441 | | |442 443This is very similar to the basic case. In the above diagram, we can | | |444see a new .flags member has been added to the struct hist_field | | |445struct, and a new entry added to hist_data.fields representing the ts0 | | |446variable. For a normal val hist_field, .flags is just 0 (modulo | | |447modifier flags), but if the value is defined as a variable, the .flags | | |448contains a set FL_VAR bit. | | |449 450As you can see, the ts0 entry's .var.idx member contains the index | | |451into the tracing_map_elts' .vars[] array containing variable values. | | |452This idx is used whenever the value of the variable is set or read. | | |453The map_elt.vars idx assigned to the given variable is assigned and | | |454saved in .var.idx by create_tracing_map_fields() after it calls | | |455tracing_map_add_var(). | | |456 457Below is a representation of the histogram at run-time, which | | |458populates the map, along with correspondence to the above hist_data and | | |459hist_field data structures. | | |460 461The diagram attempts to show the relationship between the | | |462hist_data.fields[] and the map_elt.fields[] and map_elt.vars[] with | | |463the links drawn between diagrams. For each of the map_elts, you can | | |464see that the .fields[] members point to the .sum or .offset of a key | | |465or val and the .vars[] members point to the value of a variable. The | | |466arrows between the two diagrams show the linkages between those | | |467tracing_map members and the field definitions in the corresponding | | |468hist_data fields[] members.::469 470 +-----------+ | | |471 | hist_data | | | |472 +-----------+ | | |473 | .fields | | | |474 +---------+ +-----------+ | | |475 | .map |---->| map_entry | | | |476 +---------+ +-----------+ | | |477 | .key |---> 0 | | |478 +---------+ | | |479 | .val |---> NULL | | |480 +-----------+ | | |481 | map_entry | | | |482 +-----------+ | | |483 | .key |---> pid = 999 | | |484 +---------+ +-----------+ | | |485 | .val |--->| map_elt | | | |486 +---------+ +-----------+ | | |487 . | .key |---> full key * | | |488 . +---------+ +---------------+ | | |489 . | .fields |--->| .sum (val) | | | |490 . +---------+ | 2345 | | | |491 . +--| .vars | +---------------+ | | |492 . | +---------+ | .offset (key) | | | |493 . | | 0 | | | |494 . | +---------------+ | | |495 . | . | | |496 . | . | | |497 . | . | | |498 . | +---------------+ | | |499 . | | .sum (val) or | | | |500 . | | .offset (key) | | | |501 . | +---------------+ | | |502 . | | .sum (val) or | | | |503 . | | .offset (key) | | | |504 . | +---------------+ | | |505 . | | | |506 . +---------------->+---------------+ | | |507 . | ts0 |<--+ | |508 . | 113345679876 | | | |509 . +---------------+ | | |510 . | unused | | | |511 . | | | | |512 . +---------------+ | | |513 . . | | |514 . . | | |515 . . | | |516 . +---------------+ | | |517 . | unused | | | |518 . | | | | |519 . +---------------+ | | |520 . | unused | | | |521 . | | | | |522 . +---------------+ | | |523 . | | |524 +-----------+ | | |525 | map_entry | | | |526 +-----------+ | | |527 | .key |---> pid = 4444 | | |528 +---------+ +-----------+ | | |529 | .val |--->| map_elt | | | |530 +---------+ +-----------+ | | |531 . | .key |---> full key * | | |532 . +---------+ +---------------+ | | |533 . | .fields |--->| .sum (val) | | | |534 +---------+ | 2345 | | | |535 +--| .vars | +---------------+ | | |536 | +---------+ | .offset (key) | | | |537 | | 0 | | | |538 | +---------------+ | | |539 | . | | |540 | . | | |541 | . | | |542 | +---------------+ | | |543 | | .sum (val) or | | | |544 | | .offset (key) | | | |545 | +---------------+ | | |546 | | .sum (val) or | | | |547 | | .offset (key) | | | |548 | +---------------+ | | |549 | | | |550 | +---------------+ | | |551 +---------------->| ts0 |<--+ | |552 | 213499240729 | | |553 +---------------+ | |554 | unused | | |555 | | | |556 +---------------+ | |557 . | |558 . | |559 . | |560 +---------------+ | |561 | unused | | |562 | | | |563 +---------------+ | |564 | unused | | |565 | | | |566 +---------------+ | |567 568For each used map entry, there's a map_elt pointing to an array of | |569.vars containing the current value of the variables associated with | |570that histogram entry. So in the above, the timestamp associated with | |571pid 999 is 113345679876, and the timestamp variable in the same | |572.var.idx for pid 4444 is 213499240729. | |573 574sched_switch histogram | |575---------------------- | |576 577The sched_switch histogram paired with the above sched_waking | |578histogram is shown below. The most important aspect of the | |579sched_switch histogram is that it references a variable on the | |580sched_waking histogram above. | |581 582The histogram diagram is very similar to the others so far displayed, | |583but it adds variable references. You can see the normal hitcount and | |584key fields along with a new wakeup_lat variable implemented in the | |585same way as the sched_waking ts0 variable, but in addition there's an | |586entry with the new FL_VAR_REF (short for HIST_FIELD_FL_VAR_REF) flag. | |587 588Associated with the new var ref field are a couple of new hist_field | |589members, var.hist_data and var_ref_idx. For a variable reference, the | |590var.hist_data goes with the var.idx, which together uniquely identify | |591a particular variable on a particular histogram. The var_ref_idx is | |592just the index into the var_ref_vals[] array that caches the values of | |593each variable whenever a hist trigger is updated. Those resulting | |594values are then finally accessed by other code such as trace action | |595code that uses the var_ref_idx values to assign param values. | |596 597The diagram below describes the situation for the sched_switch | |598histogram referred to before::599 600 # echo 'hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0' >> | |601 events/sched/sched_switch/trigger | |602 | |603 +------------------+ | |604 | hist_data | | |605 +------------------+ +-----------------------+ | |606 | .fields[] |-->| val = hitcount | | |607 +----------------+ +-----------------------+ | |608 | .map | | .size | | |609 +----------------+ +---------------------+ | |610 +--| .var_refs[] | | .offset | | |611 | +----------------+ +---------------------+ | |612 | | .fn() | | |613 | var_ref_vals[] +---------------------+ | |614 | +-------------+ | .flags | | |615 | | $ts0 |<---+ +---------------------+ | |616 | +-------------+ | | .var.idx | | |617 | | | | +---------------------+ | |618 | +-------------+ | | .var.hist_data | | |619 | | | | +---------------------+ | |620 | +-------------+ | | .var_ref_idx | | |621 | | | | +-----------------------+ | |622 | +-------------+ | | var = wakeup_lat | | |623 | . | +-----------------------+ | |624 | . | | .size | | |625 | . | +---------------------+ | |626 | +-------------+ | | .offset | | |627 | | | | +---------------------+ | |628 | +-------------+ | | .fn() | | |629 | | | | +---------------------+ | |630 | +-------------+ | | .flags & FL_VAR | | |631 | | +---------------------+ | |632 | | | .var.idx | | |633 | | +---------------------+ | |634 | | | .var.hist_data | | |635 | | +---------------------+ | |636 | | | .var_ref_idx | | |637 | | +---------------------+ | |638 | | . | |639 | | . | |640 | | . | |641 | | +-----------------------+ <--- n_vals | |642 | | | key = pid | | |643 | | +-----------------------+ | |644 | | | .size | | |645 | | +---------------------+ | |646 | | | .offset | | |647 | | +---------------------+ | |648 | | | .fn() | | |649 | | +---------------------+ | |650 | | | .flags | | |651 | | +---------------------+ | |652 | | | .var.idx | | |653 | | +-----------------------+ <--- n_fields | |654 | | | unused | | |655 | | +-----------------------+ | |656 | | | | | |657 | | +---------------------+ | |658 | | | | | |659 | | +---------------------+ | |660 | | | | | |661 | | +---------------------+ | |662 | | | | | |663 | | +---------------------+ | |664 | | | | | |665 | | +---------------------+ | |666 | | n_keys = n_fields - n_vals | |667 | | | |668 | | | |669 | | +-----------------------+ | |670 +---------------------->| var_ref = $ts0 | | |671 | +-----------------------+ | |672 | | .size | | |673 | +---------------------+ | |674 | | .offset | | |675 | +---------------------+ | |676 | | .fn() | | |677 | +---------------------+ | |678 | | .flags & FL_VAR_REF | | |679 | +---------------------+ | |680 | | .var.idx |--------------------------+ |681 | +---------------------+ |682 | | .var.hist_data |----------------------------+683 | +---------------------+684 +---| .var_ref_idx |685 +---------------------+686 687Abbreviations used in the diagrams::688 689 hist_data = struct hist_trigger_data690 hist_data.fields = struct hist_field691 fn = hist_field_fn_t692 FL_KEY = HIST_FIELD_FL_KEY693 FL_VAR = HIST_FIELD_FL_VAR694 FL_VAR_REF = HIST_FIELD_FL_VAR_REF695 696When a hist trigger makes use of a variable, a new hist_field is697created with flag HIST_FIELD_FL_VAR_REF. For a VAR_REF field, the698var.idx and var.hist_data take the same values as the referenced699variable, as well as the referenced variable's size, type, and700is_signed values. The VAR_REF field's .name is set to the name of the701variable it references. If a variable reference was created using the702explicit system.event.$var_ref notation, the hist_field's system and703event_name variables are also set.704 705So, in order to handle an event for the sched_switch histogram,706because we have a reference to a variable on another histogram, we707need to resolve all variable references first. This is done via the708resolve_var_refs() calls made from event_hist_trigger(). What this709does is grabs the var_refs[] array from the hist_data representing the710sched_switch histogram. For each one of those, the referenced711variable's var.hist_data along with the current key is used to look up712the corresponding tracing_map_elt in that histogram. Once found, the713referenced variable's var.idx is used to look up the variable's value714using tracing_map_read_var(elt, var.idx), which yields the value of715the variable for that element, ts0 in the case above. Note that both716the hist_fields representing both the variable and the variable717reference have the same var.idx, so this is straightforward.718 719Variable and variable reference test720------------------------------------721 722This example creates a variable on the sched_waking event, ts0, and723uses it in the sched_switch trigger. The sched_switch trigger also724creates its own variable, wakeup_lat, but nothing yet uses it::725 726 # echo 'hist:keys=pid:ts0=common_timestamp.usecs' >> events/sched/sched_waking/trigger727 728 # echo 'hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0' >> events/sched/sched_switch/trigger729 730Looking at the sched_waking 'hist_debug' output, in addition to the731normal key and value hist_fields, in the val fields section we see a732field with the HIST_FIELD_FL_VAR flag, which indicates that that field733represents a variable. Note that in addition to the variable name,734contained in the var.name field, it includes the var.idx, which is the735index into the tracing_map_elt.vars[] array of the actual variable736location. Note also that the output shows that variables live in the737same part of the hist_data->fields[] array as normal values::738 739 # cat events/sched/sched_waking/hist_debug740 741 # event histogram742 #743 # trigger info: hist:keys=pid:vals=hitcount:ts0=common_timestamp.usecs:sort=hitcount:size=2048:clock=global [active]744 #745 746 hist_data: 000000009536f554747 748 n_vals: 2749 n_keys: 1750 n_fields: 3751 752 val fields:753 754 hist_data->fields[0]:755 flags:756 VAL: HIST_FIELD_FL_HITCOUNT757 type: u64758 size: 8759 is_signed: 0760 761 hist_data->fields[1]:762 flags:763 HIST_FIELD_FL_VAR764 var.name: ts0765 var.idx (into tracing_map_elt.vars[]): 0766 type: u64767 size: 8768 is_signed: 0769 770 key fields:771 772 hist_data->fields[2]:773 flags:774 HIST_FIELD_FL_KEY775 ftrace_event_field name: pid776 type: pid_t777 size: 8778 is_signed: 1779 780Moving on to the sched_switch trigger hist_debug output, in addition781to the unused wakeup_lat variable, we see a new section displaying782variable references. Variable references are displayed in a separate783section because in addition to being logically separate from784variables and values, they actually live in a separate hist_data785array, var_refs[].786 787In this example, the sched_switch trigger has a reference to a788variable on the sched_waking trigger, $ts0. Looking at the details,789we can see that the var.hist_data value of the referenced variable790matches the previously displayed sched_waking trigger, and the var.idx791value matches the previously displayed var.idx value for that792variable. Also displayed is the var_ref_idx value for that variable793reference, which is where the value for that variable is cached for794use when the trigger is invoked::795 796 # cat events/sched/sched_switch/hist_debug797 798 # event histogram799 #800 # trigger info: hist:keys=next_pid:vals=hitcount:wakeup_lat=common_timestamp.usecs-$ts0:sort=hitcount:size=2048:clock=global [active]801 #802 803 hist_data: 00000000f4ee8006804 805 n_vals: 2806 n_keys: 1807 n_fields: 3808 809 val fields:810 811 hist_data->fields[0]:812 flags:813 VAL: HIST_FIELD_FL_HITCOUNT814 type: u64815 size: 8816 is_signed: 0817 818 hist_data->fields[1]:819 flags:820 HIST_FIELD_FL_VAR821 var.name: wakeup_lat822 var.idx (into tracing_map_elt.vars[]): 0823 type: u64824 size: 0825 is_signed: 0826 827 key fields:828 829 hist_data->fields[2]:830 flags:831 HIST_FIELD_FL_KEY832 ftrace_event_field name: next_pid833 type: pid_t834 size: 8835 is_signed: 1836 837 variable reference fields:838 839 hist_data->var_refs[0]:840 flags:841 HIST_FIELD_FL_VAR_REF842 name: ts0843 var.idx (into tracing_map_elt.vars[]): 0844 var.hist_data: 000000009536f554845 var_ref_idx (into hist_data->var_refs[]): 0846 type: u64847 size: 8848 is_signed: 0849 850The commands below can be used to clean things up for the next test::851 852 # echo '!hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0' >> events/sched/sched_switch/trigger853 854 # echo '!hist:keys=pid:ts0=common_timestamp.usecs' >> events/sched/sched_waking/trigger855 856Actions and Handlers857====================858 859Adding onto the previous example, we will now do something with that860wakeup_lat variable, namely send it and another field as a synthetic861event.862 863The onmatch() action below basically says that whenever we have a864sched_switch event, if we have a matching sched_waking event, in this865case if we have a pid in the sched_waking histogram that matches the866next_pid field on this sched_switch event, we retrieve the867variables specified in the wakeup_latency() trace action, and use868them to generate a new wakeup_latency event into the trace stream.869 870Note that the way the trace handlers such as wakeup_latency() (which871could equivalently be written trace(wakeup_latency,$wakeup_lat,next_pid)872are implemented, the parameters specified to the trace handler must be873variables. In this case, $wakeup_lat is obviously a variable, but874next_pid isn't, since it's just naming a field in the sched_switch875trace event. Since this is something that almost every trace() and876save() action does, a special shortcut is implemented to allow field877names to be used directly in those cases. How it works is that under878the covers, a temporary variable is created for the named field, and879this variable is what is actually passed to the trace handler. In the880code and documentation, this type of variable is called a 'field881variable'.882 883Fields on other trace event's histograms can be used as well. In that884case we have to generate a new histogram and an unfortunately named885'synthetic_field' (the use of synthetic here has nothing to do with886synthetic events) and use that special histogram field as a variable.887 888The diagram below illustrates the new elements described above in the889context of the sched_switch histogram using the onmatch() handler and890the trace() action.891 892First, we define the wakeup_latency synthetic event::893 894 # echo 'wakeup_latency u64 lat; pid_t pid' >> synthetic_events895 896Next, the sched_waking hist trigger as before::897 898 # echo 'hist:keys=pid:ts0=common_timestamp.usecs' >>899 events/sched/sched_waking/trigger900 901Finally, we create a hist trigger on the sched_switch event that902generates a wakeup_latency() trace event. In this case we pass903next_pid into the wakeup_latency synthetic event invocation, which904means it will be automatically converted into a field variable::905 906 # echo 'hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0: \907 onmatch(sched.sched_waking).wakeup_latency($wakeup_lat,next_pid)' >>908 /sys/kernel/tracing/events/sched/sched_switch/trigger909 910The diagram for the sched_switch event is similar to previous examples911but shows the additional field_vars[] array for hist_data and shows912the linkages between the field_vars and the variables and references913created to implement the field variables. The details are discussed914below::915 916 +------------------+917 | hist_data |918 +------------------+ +-----------------------+919 | .fields[] |-->| val = hitcount |920 +----------------+ +-----------------------+921 | .map | | .size |922 +----------------+ +---------------------+923 +---| .field_vars[] | | .offset |924 | +----------------+ +---------------------+925 |+--| .var_refs[] | | .offset |926 || +----------------+ +---------------------+927 || | .fn() |928 || var_ref_vals[] +---------------------+929 || +-------------+ | .flags |930 || | $ts0 |<---+ +---------------------+931 || +-------------+ | | .var.idx |932 || | $next_pid |<-+ | +---------------------+933 || +-------------+ | | | .var.hist_data |934 ||+>| $wakeup_lat | | | +---------------------+935 ||| +-------------+ | | | .var_ref_idx |936 ||| | | | | +-----------------------+937 ||| +-------------+ | | | var = wakeup_lat |938 ||| . | | +-----------------------+939 ||| . | | | .size |940 ||| . | | +---------------------+941 ||| +-------------+ | | | .offset |942 ||| | | | | +---------------------+943 ||| +-------------+ | | | .fn() |944 ||| | | | | +---------------------+945 ||| +-------------+ | | | .flags & FL_VAR |946 ||| | | +---------------------+947 ||| | | | .var.idx |948 ||| | | +---------------------+949 ||| | | | .var.hist_data |950 ||| | | +---------------------+951 ||| | | | .var_ref_idx |952 ||| | | +---------------------+953 ||| | | .954 ||| | | .955 ||| | | .956 ||| | | .957 ||| +--------------+ | | .958 +-->| field_var | | | .959 || +--------------+ | | .960 || | var | | | .961 || +------------+ | | .962 || | val | | | .963 || +--------------+ | | .964 || | field_var | | | .965 || +--------------+ | | .966 || | var | | | .967 || +------------+ | | .968 || | val | | | .969 || +------------+ | | .970 || . | | .971 || . | | .972 || . | | +-----------------------+ <--- n_vals973 || +--------------+ | | | key = pid |974 || | field_var | | | +-----------------------+975 || +--------------+ | | | .size |976 || | var |--+| +---------------------+977 || +------------+ ||| | .offset |978 || | val |-+|| +---------------------+979 || +------------+ ||| | .fn() |980 || ||| +---------------------+981 || ||| | .flags |982 || ||| +---------------------+983 || ||| | .var.idx |984 || ||| +---------------------+ <--- n_fields985 || |||986 || ||| n_keys = n_fields - n_vals987 || ||| +-----------------------+988 || |+->| var = next_pid |989 || | | +-----------------------+990 || | | | .size |991 || | | +---------------------+992 || | | | .offset |993 || | | +---------------------+994 || | | | .flags & FL_VAR |995 || | | +---------------------+996 || | | | .var.idx |997 || | | +---------------------+998 || | | | .var.hist_data |999 || | | +-----------------------+1000 || +-->| val for next_pid |1001 || | | +-----------------------+1002 || | | | .size |1003 || | | +---------------------+1004 || | | | .offset |1005 || | | +---------------------+1006 || | | | .fn() |1007 || | | +---------------------+1008 || | | | .flags |1009 || | | +---------------------+1010 || | | | |1011 || | | +---------------------+1012 || | |1013 || | |1014 || | | +-----------------------+1015 +|------------------|-|>| var_ref = $ts0 |1016 | | | +-----------------------+1017 | | | | .size |1018 | | | +---------------------+1019 | | | | .offset |1020 | | | +---------------------+1021 | | | | .fn() |1022 | | | +---------------------+1023 | | | | .flags & FL_VAR_REF |1024 | | | +---------------------+1025 | | +---| .var_ref_idx |1026 | | +-----------------------+1027 | | | var_ref = $next_pid |1028 | | +-----------------------+1029 | | | .size |1030 | | +---------------------+1031 | | | .offset |1032 | | +---------------------+1033 | | | .fn() |1034 | | +---------------------+1035 | | | .flags & FL_VAR_REF |1036 | | +---------------------+1037 | +-----| .var_ref_idx |1038 | +-----------------------+1039 | | var_ref = $wakeup_lat |1040 | +-----------------------+1041 | | .size |1042 | +---------------------+1043 | | .offset |1044 | +---------------------+1045 | | .fn() |1046 | +---------------------+1047 | | .flags & FL_VAR_REF |1048 | +---------------------+1049 +------------------------| .var_ref_idx |1050 +---------------------+1051 1052As you can see, for a field variable, two hist_fields are created: one1053representing the variable, in this case next_pid, and one to actually1054get the value of the field from the trace stream, like a normal val1055field does. These are created separately from normal variable1056creation and are saved in the hist_data->field_vars[] array. See1057below for how these are used. In addition, a reference hist_field is1058also created, which is needed to reference the field variables such as1059$next_pid variable in the trace() action.1060 1061Note that $wakeup_lat is also a variable reference, referencing the1062value of the expression common_timestamp-$ts0, and so also needs to1063have a hist field entry representing that reference created.1064 1065When hist_trigger_elt_update() is called to get the normal key and1066value fields, it also calls update_field_vars(), which goes through1067each field_var created for the histogram, and available from1068hist_data->field_vars and calls val->fn() to get the data from the1069current trace record, and then uses the var's var.idx to set the1070variable at the var.idx offset in the appropriate tracing_map_elt's1071variable at elt->vars[var.idx].1072 1073Once all the variables have been updated, resolve_var_refs() can be1074called from event_hist_trigger(), and not only can our $ts0 and1075$next_pid references be resolved but the $wakeup_lat reference as1076well. At this point, the trace() action can simply access the values1077assembled in the var_ref_vals[] array and generate the trace event.1078 1079The same process occurs for the field variables associated with the1080save() action.1081 1082Abbreviations used in the diagram::1083 1084 hist_data = struct hist_trigger_data1085 hist_data.fields = struct hist_field1086 field_var = struct field_var1087 fn = hist_field_fn_t1088 FL_KEY = HIST_FIELD_FL_KEY1089 FL_VAR = HIST_FIELD_FL_VAR1090 FL_VAR_REF = HIST_FIELD_FL_VAR_REF1091 1092trace() action field variable test1093----------------------------------1094 1095This example adds to the previous test example by finally making use1096of the wakeup_lat variable, but in addition also creates a couple of1097field variables that then are all passed to the wakeup_latency() trace1098action via the onmatch() handler.1099 1100First, we create the wakeup_latency synthetic event::1101 1102 # echo 'wakeup_latency u64 lat; pid_t pid; char comm[16]' >> synthetic_events1103 1104Next, the sched_waking trigger from previous examples::1105 1106 # echo 'hist:keys=pid:ts0=common_timestamp.usecs' >> events/sched/sched_waking/trigger1107 1108Finally, as in the previous test example, we calculate and assign the1109wakeup latency using the $ts0 reference from the sched_waking trigger1110to the wakeup_lat variable, and finally use it along with a couple1111sched_switch event fields, next_pid and next_comm, to generate a1112wakeup_latency trace event. The next_pid and next_comm event fields1113are automatically converted into field variables for this purpose::1114 1115 # echo 'hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0:onmatch(sched.sched_waking).wakeup_latency($wakeup_lat,next_pid,next_comm)' >> /sys/kernel/tracing/events/sched/sched_switch/trigger1116 1117The sched_waking hist_debug output shows the same data as in the1118previous test example::1119 1120 # cat events/sched/sched_waking/hist_debug1121 1122 # event histogram1123 #1124 # trigger info: hist:keys=pid:vals=hitcount:ts0=common_timestamp.usecs:sort=hitcount:size=2048:clock=global [active]1125 #1126 1127 hist_data: 00000000d60ff61f1128 1129 n_vals: 21130 n_keys: 11131 n_fields: 31132 1133 val fields:1134 1135 hist_data->fields[0]:1136 flags:1137 VAL: HIST_FIELD_FL_HITCOUNT1138 type: u641139 size: 81140 is_signed: 01141 1142 hist_data->fields[1]:1143 flags:1144 HIST_FIELD_FL_VAR1145 var.name: ts01146 var.idx (into tracing_map_elt.vars[]): 01147 type: u641148 size: 81149 is_signed: 01150 1151 key fields:1152 1153 hist_data->fields[2]:1154 flags:1155 HIST_FIELD_FL_KEY1156 ftrace_event_field name: pid1157 type: pid_t1158 size: 81159 is_signed: 11160 1161The sched_switch hist_debug output shows the same key and value fields1162as in the previous test example - note that wakeup_lat is still in the1163val fields section, but that the new field variables are not there -1164although the field variables are variables, they're held separately in1165the hist_data's field_vars[] array. Although the field variables and1166the normal variables are located in separate places, you can see that1167the actual variable locations for those variables in the1168tracing_map_elt.vars[] do have increasing indices as expected:1169wakeup_lat takes the var.idx = 0 slot, while the field variables for1170next_pid and next_comm have values var.idx = 1, and var.idx = 2. Note1171also that those are the same values displayed for the variable1172references corresponding to those variables in the variable reference1173fields section. Since there are two triggers and thus two hist_data1174addresses, those addresses also need to be accounted for when doing1175the matching - you can see that the first variable refers to the 01176var.idx on the previous hist trigger (see the hist_data address1177associated with that trigger), while the second variable refers to the11780 var.idx on the sched_switch hist trigger, as do all the remaining1179variable references.1180 1181Finally, the action tracking variables section just shows the system1182and event name for the onmatch() handler::1183 1184 # cat events/sched/sched_switch/hist_debug1185 1186 # event histogram1187 #1188 # trigger info: hist:keys=next_pid:vals=hitcount:wakeup_lat=common_timestamp.usecs-$ts0:sort=hitcount:size=2048:clock=global:onmatch(sched.sched_waking).wakeup_latency($wakeup_lat,next_pid,next_comm) [active]1189 #1190 1191 hist_data: 0000000008f551b71192 1193 n_vals: 21194 n_keys: 11195 n_fields: 31196 1197 val fields:1198 1199 hist_data->fields[0]:1200 flags:1201 VAL: HIST_FIELD_FL_HITCOUNT1202 type: u641203 size: 81204 is_signed: 01205 1206 hist_data->fields[1]:1207 flags:1208 HIST_FIELD_FL_VAR1209 var.name: wakeup_lat1210 var.idx (into tracing_map_elt.vars[]): 01211 type: u641212 size: 01213 is_signed: 01214 1215 key fields:1216 1217 hist_data->fields[2]:1218 flags:1219 HIST_FIELD_FL_KEY1220 ftrace_event_field name: next_pid1221 type: pid_t1222 size: 81223 is_signed: 11224 1225 variable reference fields:1226 1227 hist_data->var_refs[0]:1228 flags:1229 HIST_FIELD_FL_VAR_REF1230 name: ts01231 var.idx (into tracing_map_elt.vars[]): 01232 var.hist_data: 00000000d60ff61f1233 var_ref_idx (into hist_data->var_refs[]): 01234 type: u641235 size: 81236 is_signed: 01237 1238 hist_data->var_refs[1]:1239 flags:1240 HIST_FIELD_FL_VAR_REF1241 name: wakeup_lat1242 var.idx (into tracing_map_elt.vars[]): 01243 var.hist_data: 0000000008f551b71244 var_ref_idx (into hist_data->var_refs[]): 11245 type: u641246 size: 01247 is_signed: 01248 1249 hist_data->var_refs[2]:1250 flags:1251 HIST_FIELD_FL_VAR_REF1252 name: next_pid1253 var.idx (into tracing_map_elt.vars[]): 11254 var.hist_data: 0000000008f551b71255 var_ref_idx (into hist_data->var_refs[]): 21256 type: pid_t1257 size: 41258 is_signed: 01259 1260 hist_data->var_refs[3]:1261 flags:1262 HIST_FIELD_FL_VAR_REF1263 name: next_comm1264 var.idx (into tracing_map_elt.vars[]): 21265 var.hist_data: 0000000008f551b71266 var_ref_idx (into hist_data->var_refs[]): 31267 type: char[16]1268 size: 2561269 is_signed: 01270 1271 field variables:1272 1273 hist_data->field_vars[0]:1274 1275 field_vars[0].var:1276 flags:1277 HIST_FIELD_FL_VAR1278 var.name: next_pid1279 var.idx (into tracing_map_elt.vars[]): 11280 1281 field_vars[0].val:1282 ftrace_event_field name: next_pid1283 type: pid_t1284 size: 41285 is_signed: 11286 1287 hist_data->field_vars[1]:1288 1289 field_vars[1].var:1290 flags:1291 HIST_FIELD_FL_VAR1292 var.name: next_comm1293 var.idx (into tracing_map_elt.vars[]): 21294 1295 field_vars[1].val:1296 ftrace_event_field name: next_comm1297 type: char[16]1298 size: 2561299 is_signed: 01300 1301 action tracking variables (for onmax()/onchange()/onmatch()):1302 1303 hist_data->actions[0].match_data.event_system: sched1304 hist_data->actions[0].match_data.event: sched_waking1305 1306The commands below can be used to clean things up for the next test::1307 1308 # echo '!hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0:onmatch(sched.sched_waking).wakeup_latency($wakeup_lat,next_pid,next_comm)' >> /sys/kernel/tracing/events/sched/sched_switch/trigger1309 1310 # echo '!hist:keys=pid:ts0=common_timestamp.usecs' >> events/sched/sched_waking/trigger1311 1312 # echo '!wakeup_latency u64 lat; pid_t pid; char comm[16]' >> synthetic_events1313 1314action_data and the trace() action1315----------------------------------1316 1317As mentioned above, when the trace() action generates a synthetic1318event, all the parameters to the synthetic event either already are1319variables or are converted into variables (via field variables), and1320finally all those variable values are collected via references to them1321into a var_ref_vals[] array.1322 1323The values in the var_ref_vals[] array, however, don't necessarily1324follow the same ordering as the synthetic event params. To address1325that, struct action_data contains another array, var_ref_idx[] that1326maps the trace action params to the var_ref_vals[] values. Below is a1327diagram illustrating that for the wakeup_latency() synthetic event::1328 1329 +------------------+ wakeup_latency()1330 | action_data | event params var_ref_vals[]1331 +------------------+ +-----------------+ +-----------------+1332 | .var_ref_idx[] |--->| $wakeup_lat idx |---+ | |1333 +----------------+ +-----------------+ | +-----------------+1334 | .synth_event | | $next_pid idx |---|-+ | $wakeup_lat val |1335 +----------------+ +-----------------+ | | +-----------------+1336 . | +->| $next_pid val |1337 . | +-----------------+1338 . | .1339 +-----------------+ | .1340 | | | .1341 +-----------------+ | +-----------------+1342 +--->| $wakeup_lat val |1343 +-----------------+1344 1345Basically, how this ends up getting used in the synthetic event probe1346function, trace_event_raw_event_synth(), is as follows::1347 1348 for each field i in .synth_event1349 val_idx = .var_ref_idx[i]1350 val = var_ref_vals[val_idx]1351 1352action_data and the onXXX() handlers1353------------------------------------1354 1355The hist trigger onXXX() actions other than onmatch(), such as onmax()1356and onchange(), also make use of and internally create hidden1357variables. This information is contained in the1358action_data.track_data struct, and is also visible in the hist_debug1359output as will be described in the example below.1360 1361Typically, the onmax() or onchange() handlers are used in conjunction1362with the save() and snapshot() actions. For example::1363 1364 # echo 'hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0: \1365 onmax($wakeup_lat).save(next_comm,prev_pid,prev_prio,prev_comm)' >>1366 /sys/kernel/tracing/events/sched/sched_switch/trigger1367 1368or::1369 1370 # echo 'hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0: \1371 onmax($wakeup_lat).snapshot()' >>1372 /sys/kernel/tracing/events/sched/sched_switch/trigger1373 1374save() action field variable test1375---------------------------------1376 1377For this example, instead of generating a synthetic event, the save()1378action is used to save field values whenever an onmax() handler1379detects that a new max latency has been hit. As in the previous1380example, the values being saved are also field values, but in this1381case, are kept in a separate hist_data array named save_vars[].1382 1383As in previous test examples, we set up the sched_waking trigger::1384 1385 # echo 'hist:keys=pid:ts0=common_timestamp.usecs' >> events/sched/sched_waking/trigger1386 1387In this case, however, we set up the sched_switch trigger to save some1388sched_switch field values whenever we hit a new maximum latency. For1389both the onmax() handler and save() action, variables will be created,1390which we can use the hist_debug files to examine::1391 1392 # echo 'hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0:onmax($wakeup_lat).save(next_comm,prev_pid,prev_prio,prev_comm)' >> events/sched/sched_switch/trigger1393 1394The sched_waking hist_debug output shows the same data as in the1395previous test examples::1396 1397 # cat events/sched/sched_waking/hist_debug1398 1399 #1400 # trigger info: hist:keys=pid:vals=hitcount:ts0=common_timestamp.usecs:sort=hitcount:size=2048:clock=global [active]1401 #1402 1403 hist_data: 00000000e6290f481404 1405 n_vals: 21406 n_keys: 11407 n_fields: 31408 1409 val fields:1410 1411 hist_data->fields[0]:1412 flags:1413 VAL: HIST_FIELD_FL_HITCOUNT1414 type: u641415 size: 81416 is_signed: 01417 1418 hist_data->fields[1]:1419 flags:1420 HIST_FIELD_FL_VAR1421 var.name: ts01422 var.idx (into tracing_map_elt.vars[]): 01423 type: u641424 size: 81425 is_signed: 01426 1427 key fields:1428 1429 hist_data->fields[2]:1430 flags:1431 HIST_FIELD_FL_KEY1432 ftrace_event_field name: pid1433 type: pid_t1434 size: 81435 is_signed: 11436 1437The output of the sched_switch trigger shows the same val and key1438values as before, but also shows a couple new sections.1439 1440First, the action tracking variables section now shows the1441actions[].track_data information describing the special tracking1442variables and references used to track, in this case, the running1443maximum value. The actions[].track_data.var_ref member contains the1444reference to the variable being tracked, in this case the $wakeup_lat1445variable. In order to perform the onmax() handler function, there1446also needs to be a variable that tracks the current maximum by getting1447updated whenever a new maximum is hit. In this case, we can see that1448an auto-generated variable named ' __max' has been created and is1449visible in the actions[].track_data.track_var variable.1450 1451Finally, in the new 'save action variables' section, we can see that1452the 4 params to the save() function have resulted in 4 field variables1453being created for the purposes of saving the values of the named1454fields when the max is hit. These variables are kept in a separate1455save_vars[] array off of hist_data, so are displayed in a separate1456section::1457 1458 # cat events/sched/sched_switch/hist_debug1459 1460 # event histogram1461 #1462 # trigger info: hist:keys=next_pid:vals=hitcount:wakeup_lat=common_timestamp.usecs-$ts0:sort=hitcount:size=2048:clock=global:onmax($wakeup_lat).save(next_comm,prev_pid,prev_prio,prev_comm) [active]1463 #1464 1465 hist_data: 0000000057bcd28d1466 1467 n_vals: 21468 n_keys: 11469 n_fields: 31470 1471 val fields:1472 1473 hist_data->fields[0]:1474 flags:1475 VAL: HIST_FIELD_FL_HITCOUNT1476 type: u641477 size: 81478 is_signed: 01479 1480 hist_data->fields[1]:1481 flags:1482 HIST_FIELD_FL_VAR1483 var.name: wakeup_lat1484 var.idx (into tracing_map_elt.vars[]): 01485 type: u641486 size: 01487 is_signed: 01488 1489 key fields:1490 1491 hist_data->fields[2]:1492 flags:1493 HIST_FIELD_FL_KEY1494 ftrace_event_field name: next_pid1495 type: pid_t1496 size: 81497 is_signed: 11498 1499 variable reference fields:1500 1501 hist_data->var_refs[0]:1502 flags:1503 HIST_FIELD_FL_VAR_REF1504 name: ts01505 var.idx (into tracing_map_elt.vars[]): 01506 var.hist_data: 00000000e6290f481507 var_ref_idx (into hist_data->var_refs[]): 01508 type: u641509 size: 81510 is_signed: 01511 1512 hist_data->var_refs[1]:1513 flags:1514 HIST_FIELD_FL_VAR_REF1515 name: wakeup_lat1516 var.idx (into tracing_map_elt.vars[]): 01517 var.hist_data: 0000000057bcd28d1518 var_ref_idx (into hist_data->var_refs[]): 11519 type: u641520 size: 01521 is_signed: 01522 1523 action tracking variables (for onmax()/onchange()/onmatch()):1524 1525 hist_data->actions[0].track_data.var_ref:1526 flags:1527 HIST_FIELD_FL_VAR_REF1528 name: wakeup_lat1529 var.idx (into tracing_map_elt.vars[]): 01530 var.hist_data: 0000000057bcd28d1531 var_ref_idx (into hist_data->var_refs[]): 11532 type: u641533 size: 01534 is_signed: 01535 1536 hist_data->actions[0].track_data.track_var:1537 flags:1538 HIST_FIELD_FL_VAR1539 var.name: __max1540 var.idx (into tracing_map_elt.vars[]): 11541 type: u641542 size: 81543 is_signed: 01544 1545 save action variables (save() params):1546 1547 hist_data->save_vars[0]:1548 1549 save_vars[0].var:1550 flags:1551 HIST_FIELD_FL_VAR1552 var.name: next_comm1553 var.idx (into tracing_map_elt.vars[]): 21554 1555 save_vars[0].val:1556 ftrace_event_field name: next_comm1557 type: char[16]1558 size: 2561559 is_signed: 01560 1561 hist_data->save_vars[1]:1562 1563 save_vars[1].var:1564 flags:1565 HIST_FIELD_FL_VAR1566 var.name: prev_pid1567 var.idx (into tracing_map_elt.vars[]): 31568 1569 save_vars[1].val:1570 ftrace_event_field name: prev_pid1571 type: pid_t1572 size: 41573 is_signed: 11574 1575 hist_data->save_vars[2]:1576 1577 save_vars[2].var:1578 flags:1579 HIST_FIELD_FL_VAR1580 var.name: prev_prio1581 var.idx (into tracing_map_elt.vars[]): 41582 1583 save_vars[2].val:1584 ftrace_event_field name: prev_prio1585 type: int1586 size: 41587 is_signed: 11588 1589 hist_data->save_vars[3]:1590 1591 save_vars[3].var:1592 flags:1593 HIST_FIELD_FL_VAR1594 var.name: prev_comm1595 var.idx (into tracing_map_elt.vars[]): 51596 1597 save_vars[3].val:1598 ftrace_event_field name: prev_comm1599 type: char[16]1600 size: 2561601 is_signed: 01602 1603The commands below can be used to clean things up for the next test::1604 1605 # echo '!hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0:onmax($wakeup_lat).save(next_comm,prev_pid,prev_prio,prev_comm)' >> events/sched/sched_switch/trigger1606 1607 # echo '!hist:keys=pid:ts0=common_timestamp.usecs' >> events/sched/sched_waking/trigger1608 1609A couple special cases1610======================1611 1612While the above covers the basics of the histogram internals, there1613are a couple of special cases that should be discussed, since they1614tend to create even more confusion. Those are field variables on other1615histograms, and aliases, both described below through example tests1616using the hist_debug files.1617 1618Test of field variables on other histograms1619-------------------------------------------1620 1621This example is similar to the previous examples, but in this case,1622the sched_switch trigger references a hist trigger field on another1623event, namely the sched_waking event. In order to accomplish this, a1624field variable is created for the other event, but since an existing1625histogram can't be used, as existing histograms are immutable, a new1626histogram with a matching variable is created and used, and we'll see1627that reflected in the hist_debug output shown below.1628 1629First, we create the wakeup_latency synthetic event. Note the1630addition of the prio field::1631 1632 # echo 'wakeup_latency u64 lat; pid_t pid; int prio' >> synthetic_events1633 1634As in previous test examples, we set up the sched_waking trigger::1635 1636 # echo 'hist:keys=pid:ts0=common_timestamp.usecs' >> events/sched/sched_waking/trigger1637 1638Here we set up a hist trigger on sched_switch to send a wakeup_latency1639event using an onmatch handler naming the sched_waking event. Note1640that the third param being passed to the wakeup_latency() is prio,1641which is a field name that needs to have a field variable created for1642it. There isn't however any prio field on the sched_switch event so1643it would seem that it wouldn't be possible to create a field variable1644for it. The matching sched_waking event does have a prio field, so it1645should be possible to make use of it for this purpose. The problem1646with that is that it's not currently possible to define a new variable1647on an existing histogram, so it's not possible to add a new prio field1648variable to the existing sched_waking histogram. It is however1649possible to create an additional new 'matching' sched_waking histogram1650for the same event, meaning that it uses the same key and filters, and1651define the new prio field variable on that.1652 1653Here's the sched_switch trigger::1654 1655 # echo 'hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0:onmatch(sched.sched_waking).wakeup_latency($wakeup_lat,next_pid,prio)' >> events/sched/sched_switch/trigger1656 1657And here's the output of the hist_debug information for the1658sched_waking hist trigger. Note that there are two histograms1659displayed in the output: the first is the normal sched_waking1660histogram we've seen in the previous examples, and the second is the1661special histogram we created to provide the prio field variable.1662 1663Looking at the second histogram below, we see a variable with the name1664synthetic_prio. This is the field variable created for the prio field1665on that sched_waking histogram::1666 1667 # cat events/sched/sched_waking/hist_debug1668 1669 # event histogram1670 #1671 # trigger info: hist:keys=pid:vals=hitcount:ts0=common_timestamp.usecs:sort=hitcount:size=2048:clock=global [active]1672 #1673 1674 hist_data: 00000000349570e41675 1676 n_vals: 21677 n_keys: 11678 n_fields: 31679 1680 val fields:1681 1682 hist_data->fields[0]:1683 flags:1684 VAL: HIST_FIELD_FL_HITCOUNT1685 type: u641686 size: 81687 is_signed: 01688 1689 hist_data->fields[1]:1690 flags:1691 HIST_FIELD_FL_VAR1692 var.name: ts01693 var.idx (into tracing_map_elt.vars[]): 01694 type: u641695 size: 81696 is_signed: 01697 1698 key fields:1699 1700 hist_data->fields[2]:1701 flags:1702 HIST_FIELD_FL_KEY1703 ftrace_event_field name: pid1704 type: pid_t1705 size: 81706 is_signed: 11707 1708 1709 # event histogram1710 #1711 # trigger info: hist:keys=pid:vals=hitcount:synthetic_prio=prio:sort=hitcount:size=2048 [active]1712 #1713 1714 hist_data: 000000006920cf381715 1716 n_vals: 21717 n_keys: 11718 n_fields: 31719 1720 val fields:1721 1722 hist_data->fields[0]:1723 flags:1724 VAL: HIST_FIELD_FL_HITCOUNT1725 type: u641726 size: 81727 is_signed: 01728 1729 hist_data->fields[1]:1730 flags:1731 HIST_FIELD_FL_VAR1732 ftrace_event_field name: prio1733 var.name: synthetic_prio1734 var.idx (into tracing_map_elt.vars[]): 01735 type: int1736 size: 41737 is_signed: 11738 1739 key fields:1740 1741 hist_data->fields[2]:1742 flags:1743 HIST_FIELD_FL_KEY1744 ftrace_event_field name: pid1745 type: pid_t1746 size: 81747 is_signed: 11748 1749Looking at the sched_switch histogram below, we can see a reference to1750the synthetic_prio variable on sched_waking, and looking at the1751associated hist_data address we see that it is indeed associated with1752the new histogram. Note also that the other references are to a1753normal variable, wakeup_lat, and to a normal field variable, next_pid,1754the details of which are in the field variables section::1755 1756 # cat events/sched/sched_switch/hist_debug1757 1758 # event histogram1759 #1760 # trigger info: hist:keys=next_pid:vals=hitcount:wakeup_lat=common_timestamp.usecs-$ts0:sort=hitcount:size=2048:clock=global:onmatch(sched.sched_waking).wakeup_latency($wakeup_lat,next_pid,prio) [active]1761 #1762 1763 hist_data: 00000000a73b67df1764 1765 n_vals: 21766 n_keys: 11767 n_fields: 31768 1769 val fields:1770 1771 hist_data->fields[0]:1772 flags:1773 VAL: HIST_FIELD_FL_HITCOUNT1774 type: u641775 size: 81776 is_signed: 01777 1778 hist_data->fields[1]:1779 flags:1780 HIST_FIELD_FL_VAR1781 var.name: wakeup_lat1782 var.idx (into tracing_map_elt.vars[]): 01783 type: u641784 size: 01785 is_signed: 01786 1787 key fields:1788 1789 hist_data->fields[2]:1790 flags:1791 HIST_FIELD_FL_KEY1792 ftrace_event_field name: next_pid1793 type: pid_t1794 size: 81795 is_signed: 11796 1797 variable reference fields:1798 1799 hist_data->var_refs[0]:1800 flags:1801 HIST_FIELD_FL_VAR_REF1802 name: ts01803 var.idx (into tracing_map_elt.vars[]): 01804 var.hist_data: 00000000349570e41805 var_ref_idx (into hist_data->var_refs[]): 01806 type: u641807 size: 81808 is_signed: 01809 1810 hist_data->var_refs[1]:1811 flags:1812 HIST_FIELD_FL_VAR_REF1813 name: wakeup_lat1814 var.idx (into tracing_map_elt.vars[]): 01815 var.hist_data: 00000000a73b67df1816 var_ref_idx (into hist_data->var_refs[]): 11817 type: u641818 size: 01819 is_signed: 01820 1821 hist_data->var_refs[2]:1822 flags:1823 HIST_FIELD_FL_VAR_REF1824 name: next_pid1825 var.idx (into tracing_map_elt.vars[]): 11826 var.hist_data: 00000000a73b67df1827 var_ref_idx (into hist_data->var_refs[]): 21828 type: pid_t1829 size: 41830 is_signed: 01831 1832 hist_data->var_refs[3]:1833 flags:1834 HIST_FIELD_FL_VAR_REF1835 name: synthetic_prio1836 var.idx (into tracing_map_elt.vars[]): 01837 var.hist_data: 000000006920cf381838 var_ref_idx (into hist_data->var_refs[]): 31839 type: int1840 size: 41841 is_signed: 11842 1843 field variables:1844 1845 hist_data->field_vars[0]:1846 1847 field_vars[0].var:1848 flags:1849 HIST_FIELD_FL_VAR1850 var.name: next_pid1851 var.idx (into tracing_map_elt.vars[]): 11852 1853 field_vars[0].val:1854 ftrace_event_field name: next_pid1855 type: pid_t1856 size: 41857 is_signed: 11858 1859 action tracking variables (for onmax()/onchange()/onmatch()):1860 1861 hist_data->actions[0].match_data.event_system: sched1862 hist_data->actions[0].match_data.event: sched_waking1863 1864The commands below can be used to clean things up for the next test::1865 1866 # echo '!hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0:onmatch(sched.sched_waking).wakeup_latency($wakeup_lat,next_pid,prio)' >> events/sched/sched_switch/trigger1867 1868 # echo '!hist:keys=pid:ts0=common_timestamp.usecs' >> events/sched/sched_waking/trigger1869 1870 # echo '!wakeup_latency u64 lat; pid_t pid; int prio' >> synthetic_events1871 1872Alias test1873----------1874 1875This example is very similar to previous examples, but demonstrates1876the alias flag.1877 1878First, we create the wakeup_latency synthetic event::1879 1880 # echo 'wakeup_latency u64 lat; pid_t pid; char comm[16]' >> synthetic_events1881 1882Next, we create a sched_waking trigger similar to previous examples,1883but in this case we save the pid in the waking_pid variable::1884 1885 # echo 'hist:keys=pid:waking_pid=pid:ts0=common_timestamp.usecs' >> events/sched/sched_waking/trigger1886 1887For the sched_switch trigger, instead of using $waking_pid directly in1888the wakeup_latency synthetic event invocation, we create an alias of1889$waking_pid named $woken_pid, and use that in the synthetic event1890invocation instead::1891 1892 # echo 'hist:keys=next_pid:woken_pid=$waking_pid:wakeup_lat=common_timestamp.usecs-$ts0:onmatch(sched.sched_waking).wakeup_latency($wakeup_lat,$woken_pid,next_comm)' >> events/sched/sched_switch/trigger1893 1894Looking at the sched_waking hist_debug output, in addition to the1895normal fields, we can see the waking_pid variable::1896 1897 # cat events/sched/sched_waking/hist_debug1898 1899 # event histogram1900 #1901 # trigger info: hist:keys=pid:vals=hitcount:waking_pid=pid,ts0=common_timestamp.usecs:sort=hitcount:size=2048:clock=global [active]1902 #1903 1904 hist_data: 00000000a250528c1905 1906 n_vals: 31907 n_keys: 11908 n_fields: 41909 1910 val fields:1911 1912 hist_data->fields[0]:1913 flags:1914 VAL: HIST_FIELD_FL_HITCOUNT1915 type: u641916 size: 81917 is_signed: 01918 1919 hist_data->fields[1]:1920 flags:1921 HIST_FIELD_FL_VAR1922 ftrace_event_field name: pid1923 var.name: waking_pid1924 var.idx (into tracing_map_elt.vars[]): 01925 type: pid_t1926 size: 41927 is_signed: 11928 1929 hist_data->fields[2]:1930 flags:1931 HIST_FIELD_FL_VAR1932 var.name: ts01933 var.idx (into tracing_map_elt.vars[]): 11934 type: u641935 size: 81936 is_signed: 01937 1938 key fields:1939 1940 hist_data->fields[3]:1941 flags:1942 HIST_FIELD_FL_KEY1943 ftrace_event_field name: pid1944 type: pid_t1945 size: 81946 is_signed: 11947 1948The sched_switch hist_debug output shows that a variable named1949woken_pid has been created but that it also has the1950HIST_FIELD_FL_ALIAS flag set. It also has the HIST_FIELD_FL_VAR flag1951set, which is why it appears in the val field section.1952 1953Despite that implementation detail, an alias variable is actually more1954like a variable reference; in fact it can be thought of as a reference1955to a reference. The implementation copies the var_ref->fn() from the1956variable reference being referenced, in this case, the waking_pid1957fn(), which is hist_field_var_ref() and makes that the fn() of the1958alias. The hist_field_var_ref() fn() requires the var_ref_idx of the1959variable reference it's using, so waking_pid's var_ref_idx is also1960copied to the alias. The end result is that when the value of alias1961is retrieved, in the end it just does the same thing the original1962reference would have done and retrieves the same value from the1963var_ref_vals[] array. You can verify this in the output by noting1964that the var_ref_idx of the alias, in this case woken_pid, is the same1965as the var_ref_idx of the reference, waking_pid, in the variable1966reference fields section.1967 1968Additionally, once it gets that value, since it is also a variable, it1969then saves that value into its var.idx. So the var.idx of the1970woken_pid alias is 0, which it fills with the value from var_ref_idx 01971when its fn() is called to update itself. You'll also notice that1972there's a woken_pid var_ref in the variable refs section. That is the1973reference to the woken_pid alias variable, and you can see that it1974retrieves the value from the same var.idx as the woken_pid alias, 0,1975and then in turn saves that value in its own var_ref_idx slot, 3, and1976the value at this position is finally what gets assigned to the1977$woken_pid slot in the trace event invocation::1978 1979 # cat events/sched/sched_switch/hist_debug1980 1981 # event histogram1982 #1983 # trigger info: hist:keys=next_pid:vals=hitcount:woken_pid=$waking_pid,wakeup_lat=common_timestamp.usecs-$ts0:sort=hitcount:size=2048:clock=global:onmatch(sched.sched_waking).wakeup_latency($wakeup_lat,$woken_pid,next_comm) [active]1984 #1985 1986 hist_data: 0000000055d65ed01987 1988 n_vals: 31989 n_keys: 11990 n_fields: 41991 1992 val fields:1993 1994 hist_data->fields[0]:1995 flags:1996 VAL: HIST_FIELD_FL_HITCOUNT1997 type: u641998 size: 81999 is_signed: 02000 2001 hist_data->fields[1]:2002 flags:2003 HIST_FIELD_FL_VAR2004 HIST_FIELD_FL_ALIAS2005 var.name: woken_pid2006 var.idx (into tracing_map_elt.vars[]): 02007 var_ref_idx (into hist_data->var_refs[]): 02008 type: pid_t2009 size: 42010 is_signed: 12011 2012 hist_data->fields[2]:2013 flags:2014 HIST_FIELD_FL_VAR2015 var.name: wakeup_lat2016 var.idx (into tracing_map_elt.vars[]): 12017 type: u642018 size: 02019 is_signed: 02020 2021 key fields:2022 2023 hist_data->fields[3]:2024 flags:2025 HIST_FIELD_FL_KEY2026 ftrace_event_field name: next_pid2027 type: pid_t2028 size: 82029 is_signed: 12030 2031 variable reference fields:2032 2033 hist_data->var_refs[0]:2034 flags:2035 HIST_FIELD_FL_VAR_REF2036 name: waking_pid2037 var.idx (into tracing_map_elt.vars[]): 02038 var.hist_data: 00000000a250528c2039 var_ref_idx (into hist_data->var_refs[]): 02040 type: pid_t2041 size: 42042 is_signed: 12043 2044 hist_data->var_refs[1]:2045 flags:2046 HIST_FIELD_FL_VAR_REF2047 name: ts02048 var.idx (into tracing_map_elt.vars[]): 12049 var.hist_data: 00000000a250528c2050 var_ref_idx (into hist_data->var_refs[]): 12051 type: u642052 size: 82053 is_signed: 02054 2055 hist_data->var_refs[2]:2056 flags:2057 HIST_FIELD_FL_VAR_REF2058 name: wakeup_lat2059 var.idx (into tracing_map_elt.vars[]): 12060 var.hist_data: 0000000055d65ed02061 var_ref_idx (into hist_data->var_refs[]): 22062 type: u642063 size: 02064 is_signed: 02065 2066 hist_data->var_refs[3]:2067 flags:2068 HIST_FIELD_FL_VAR_REF2069 name: woken_pid2070 var.idx (into tracing_map_elt.vars[]): 02071 var.hist_data: 0000000055d65ed02072 var_ref_idx (into hist_data->var_refs[]): 32073 type: pid_t2074 size: 42075 is_signed: 12076 2077 hist_data->var_refs[4]:2078 flags:2079 HIST_FIELD_FL_VAR_REF2080 name: next_comm2081 var.idx (into tracing_map_elt.vars[]): 22082 var.hist_data: 0000000055d65ed02083 var_ref_idx (into hist_data->var_refs[]): 42084 type: char[16]2085 size: 2562086 is_signed: 02087 2088 field variables:2089 2090 hist_data->field_vars[0]:2091 2092 field_vars[0].var:2093 flags:2094 HIST_FIELD_FL_VAR2095 var.name: next_comm2096 var.idx (into tracing_map_elt.vars[]): 22097 2098 field_vars[0].val:2099 ftrace_event_field name: next_comm2100 type: char[16]2101 size: 2562102 is_signed: 02103 2104 action tracking variables (for onmax()/onchange()/onmatch()):2105 2106 hist_data->actions[0].match_data.event_system: sched2107 hist_data->actions[0].match_data.event: sched_waking2108 2109The commands below can be used to clean things up for the next test::2110 2111 # echo '!hist:keys=next_pid:woken_pid=$waking_pid:wakeup_lat=common_timestamp.usecs-$ts0:onmatch(sched.sched_waking).wakeup_latency($wakeup_lat,$woken_pid,next_comm)' >> events/sched/sched_switch/trigger2112 2113 # echo '!hist:keys=pid:ts0=common_timestamp.usecs' >> events/sched/sched_waking/trigger2114 2115 # echo '!wakeup_latency u64 lat; pid_t pid; char comm[16]' >> synthetic_events2116