^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1) .. SPDX-License-Identifier: GPL-2.0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 3) ======================
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 4) Histogram Design Notes
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 5) ======================
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 6)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 7) :Author: Tom Zanussi <zanussi@kernel.org>
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 8)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 9) This document attempts to provide a description of how the ftrace
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 10) histograms work and how the individual pieces map to the data
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 11) structures used to implement them in trace_events_hist.c and
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 12) tracing_map.c.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 13)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 14) Note: All the ftrace histogram command examples assume the working
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 15) directory is the ftrace /tracing directory. For example::
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 16)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 17) # cd /sys/kernel/debug/tracing
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 18)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 19) Also, the histogram output displayed for those commands will be
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 20) generally be truncated - only enough to make the point is displayed.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 21)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 22) 'hist_debug' trace event files
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 23) ==============================
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 24)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 25) If the kernel is compiled with CONFIG_HIST_TRIGGERS_DEBUG set, an
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 26) event file named 'hist_debug' will appear in each event's
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 27) subdirectory. This file can be read at any time and will display some
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 28) of the hist trigger internals described in this document. Specific
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 29) examples and output will be described in test cases below.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 30)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 31) Basic histograms
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 32) ================
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 33)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 34) First, basic histograms. Below is pretty much the simplest thing you
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 35) can do with histograms - create one with a single key on a single
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 36) event and cat the output::
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 37)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 38) # echo 'hist:keys=pid' >> events/sched/sched_waking/trigger
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 39)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 40) # cat events/sched/sched_waking/hist
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 41)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 42) { pid: 18249 } hitcount: 1
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 43) { pid: 13399 } hitcount: 1
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 44) { pid: 17973 } hitcount: 1
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 45) { pid: 12572 } hitcount: 1
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 46) ...
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 47) { pid: 10 } hitcount: 921
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 48) { pid: 18255 } hitcount: 1444
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 49) { pid: 25526 } hitcount: 2055
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 50) { pid: 5257 } hitcount: 2055
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 51) { pid: 27367 } hitcount: 2055
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 52) { pid: 1728 } hitcount: 2161
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 53)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 54) Totals:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 55) Hits: 21305
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 56) Entries: 183
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 57) Dropped: 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 58)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 59) What this does is create a histogram on the sched_waking event using
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 60) pid as a key and with a single value, hitcount, which even if not
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 61) explicitly specified, exists for every histogram regardless.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 62)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 63) The hitcount value is a per-bucket value that's automatically
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 64) incremented on every hit for the given key, which in this case is the
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 65) pid.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 66)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 67) So in this histogram, there's a separate bucket for each pid, and each
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 68) bucket contains a value for that bucket, counting the number of times
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 69) sched_waking was called for that pid.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 70)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 71) Each histogram is represented by a hist_data struct.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 72)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 73) To keep track of each key and value field in the histogram, hist_data
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 74) keeps an array of these fields named fields[]. The fields[] array is
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 75) an array containing struct hist_field representations of each
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 76) histogram val and key in the histogram (variables are also included
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 77) here, but are discussed later). So for the above histogram we have one
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 78) key and one value; in this case the one value is the hitcount value,
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 79) which all histograms have, regardless of whether they define that
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 80) value or not, which the above histogram does not.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 81)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 82) Each struct hist_field contains a pointer to the ftrace_event_field
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 83) from the event's trace_event_file along with various bits related to
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 84) that such as the size, offset, type, and a hist_field_fn_t function,
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 85) which is used to grab the field's data from the ftrace event buffer
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 86) (in most cases - some hist_fields such as hitcount don't directly map
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 87) to an event field in the trace buffer - in these cases the function
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 88) implementation gets its value from somewhere else). The flags field
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 89) indicates which type of field it is - key, value, variable, variable
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 90) reference, etc., with value being the default.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 91)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 92) The other important hist_data data structure in addition to the
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 93) fields[] array is the tracing_map instance created for the histogram,
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 94) which is held in the .map member. The tracing_map implements the
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 95) lock-free hash table used to implement histograms (see
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 96) kernel/trace/tracing_map.h for much more discussion about the
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 97) low-level data structures implementing the tracing_map). For the
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 98) purposes of this discussion, the tracing_map contains a number of
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 99) buckets, each bucket corresponding to a particular tracing_map_elt
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 100) object hashed by a given histogram key.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 101)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 102) Below is a diagram the first part of which describes the hist_data and
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 103) associated key and value fields for the histogram described above. As
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 104) you can see, there are two fields in the fields array, one val field
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 105) for the hitcount and one key field for the pid key.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 106)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 107) Below that is a diagram of a run-time snapshot of what the tracing_map
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 108) might look like for a given run. It attempts to show the
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 109) relationships between the hist_data fields and the tracing_map
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 110) elements for a couple hypothetical keys and values.::
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 111)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 112) +------------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 113) | hist_data |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 114) +------------------+ +----------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 115) | .fields[] |---->| val = hitcount |----------------------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 116) +----------------+ +----------------+ |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 117) | .map | | .size | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 118) +----------------+ +--------------+ |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 119) | .offset | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 120) +--------------+ |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 121) | .fn() | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 122) +--------------+ |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 123) . |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 124) . |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 125) . |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 126) +----------------+ <--- n_vals |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 127) | key = pid |----------------------------|--+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 128) +----------------+ | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 129) | .size | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 130) +--------------+ | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 131) | .offset | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 132) +--------------+ | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 133) | .fn() | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 134) +----------------+ <--- n_fields | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 135) | unused | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 136) +----------------+ | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 137) | | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 138) +--------------+ | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 139) | | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 140) +--------------+ | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 141) | | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 142) +--------------+ | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 143) n_keys = n_fields - n_vals | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 144)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 145) The hist_data n_vals and n_fields delineate the extent of the fields[] | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 146) array and separate keys from values for the rest of the code. | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 147)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 148) Below is a run-time representation of the tracing_map part of the | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 149) histogram, with pointers from various parts of the fields[] array | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 150) to corresponding parts of the tracing_map. | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 151)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 152) The tracing_map consists of an array of tracing_map_entrys and a set | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 153) of preallocated tracing_map_elts (abbreviated below as map_entry and | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 154) map_elt). The total number of map_entrys in the hist_data.map array = | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 155) map->max_elts (actually map->map_size but only max_elts of those are | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 156) used. This is a property required by the map_insert() algorithm). | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 157)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 158) If a map_entry is unused, meaning no key has yet hashed into it, its | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 159) .key value is 0 and its .val pointer is NULL. Once a map_entry has | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 160) been claimed, the .key value contains the key's hash value and the | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 161) .val member points to a map_elt containing the full key and an entry | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 162) for each key or value in the map_elt.fields[] array. There is an | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 163) entry in the map_elt.fields[] array corresponding to each hist_field | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 164) in the histogram, and this is where the continually aggregated sums | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 165) corresponding to each histogram value are kept. | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 166)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 167) The diagram attempts to show the relationship between the | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 168) hist_data.fields[] and the map_elt.fields[] with the links drawn | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 169) between diagrams::
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 170)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 171) +-----------+ | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 172) | hist_data | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 173) +-----------+ | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 174) | .fields | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 175) +---------+ +-----------+ | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 176) | .map |---->| map_entry | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 177) +---------+ +-----------+ | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 178) | .key |---> 0 | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 179) +---------+ | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 180) | .val |---> NULL | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 181) +-----------+ | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 182) | map_entry | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 183) +-----------+ | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 184) | .key |---> pid = 999 | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 185) +---------+ +-----------+ | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 186) | .val |--->| map_elt | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 187) +---------+ +-----------+ | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 188) . | .key |---> full key * | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 189) . +---------+ +---------------+ | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 190) . | .fields |--->| .sum (val) |<-+ |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 191) +-----------+ +---------+ | 2345 | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 192) | map_entry | +---------------+ | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 193) +-----------+ | .offset (key) |<----+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 194) | .key |---> 0 | 0 | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 195) +---------+ +---------------+ | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 196) | .val |---> NULL . | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 197) +-----------+ . | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 198) | map_entry | . | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 199) +-----------+ +---------------+ | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 200) | .key | | .sum (val) or | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 201) +---------+ +---------+ | .offset (key) | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 202) | .val |--->| map_elt | +---------------+ | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 203) +-----------+ +---------+ | .sum (val) or | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 204) | map_entry | | .offset (key) | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 205) +-----------+ +---------------+ | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 206) | .key |---> pid = 4444 | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 207) +---------+ +-----------+ | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 208) | .val | | map_elt | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 209) +---------+ +-----------+ | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 210) | .key |---> full key * | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 211) +---------+ +---------------+ | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 212) | .fields |--->| .sum (val) |<-+ |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 213) +---------+ | 65523 | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 214) +---------------+ |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 215) | .offset (key) |<----+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 216) | 0 |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 217) +---------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 218) .
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 219) .
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 220) .
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 221) +---------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 222) | .sum (val) or |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 223) | .offset (key) |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 224) +---------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 225) | .sum (val) or |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 226) | .offset (key) |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 227) +---------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 228)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 229) Abbreviations used in the diagrams::
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 230)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 231) hist_data = struct hist_trigger_data
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 232) hist_data.fields = struct hist_field
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 233) fn = hist_field_fn_t
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 234) map_entry = struct tracing_map_entry
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 235) map_elt = struct tracing_map_elt
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 236) map_elt.fields = struct tracing_map_field
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 237)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 238) Whenever a new event occurs and it has a hist trigger associated with
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 239) it, event_hist_trigger() is called. event_hist_trigger() first deals
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 240) with the key: for each subkey in the key (in the above example, there
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 241) is just one subkey corresponding to pid), the hist_field that
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 242) represents that subkey is retrieved from hist_data.fields[] and the
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 243) hist_field_fn_t fn() associated with that field, along with the
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 244) field's size and offset, is used to grab that subkey's data from the
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 245) current trace record.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 246)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 247) Once the complete key has been retrieved, it's used to look that key
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 248) up in the tracing_map. If there's no tracing_map_elt associated with
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 249) that key, an empty one is claimed and inserted in the map for the new
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 250) key. In either case, the tracing_map_elt associated with that key is
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 251) returned.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 252)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 253) Once a tracing_map_elt available, hist_trigger_elt_update() is called.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 254) As the name implies, this updates the element, which basically means
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 255) updating the element's fields. There's a tracing_map_field associated
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 256) with each key and value in the histogram, and each of these correspond
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 257) to the key and value hist_fields created when the histogram was
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 258) created. hist_trigger_elt_update() goes through each value hist_field
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 259) and, as for the keys, uses the hist_field's fn() and size and offset
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 260) to grab the field's value from the current trace record. Once it has
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 261) that value, it simply adds that value to that field's
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 262) continually-updated tracing_map_field.sum member. Some hist_field
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 263) fn()s, such as for the hitcount, don't actually grab anything from the
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 264) trace record (the hitcount fn() just increments the counter sum by 1),
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 265) but the idea is the same.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 266)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 267) Once all the values have been updated, hist_trigger_elt_update() is
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 268) done and returns. Note that there are also tracing_map_fields for
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 269) each subkey in the key, but hist_trigger_elt_update() doesn't look at
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 270) them or update anything - those exist only for sorting, which can
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 271) happen later.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 272)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 273) Basic histogram test
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 274) --------------------
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 275)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 276) This is a good example to try. It produces 3 value fields and 2 key
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 277) fields in the output::
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 278)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 279) # echo 'hist:keys=common_pid,call_site.sym:values=bytes_req,bytes_alloc,hitcount' >> events/kmem/kmalloc/trigger
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 280)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 281) To see the debug data, cat the kmem/kmalloc's 'hist_debug' file. It
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 282) will show the trigger info of the histogram it corresponds to, along
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 283) with the address of the hist_data associated with the histogram, which
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 284) will become useful in later examples. It then displays the number of
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 285) total hist_fields associated with the histogram along with a count of
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 286) how many of those correspond to keys and how many correspond to values.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 287)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 288) It then goes on to display details for each field, including the
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 289) field's flags and the position of each field in the hist_data's
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 290) fields[] array, which is useful information for verifying that things
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 291) internally appear correct or not, and which again will become even
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 292) more useful in further examples::
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 293)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 294) # cat events/kmem/kmalloc/hist_debug
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 295)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 296) # event histogram
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 297) #
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 298) # trigger info: hist:keys=common_pid,call_site.sym:vals=hitcount,bytes_req,bytes_alloc:sort=hitcount:size=2048 [active]
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 299) #
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 300)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 301) hist_data: 000000005e48c9a5
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 302)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 303) n_vals: 3
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 304) n_keys: 2
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 305) n_fields: 5
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 306)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 307) val fields:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 308)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 309) hist_data->fields[0]:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 310) flags:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 311) VAL: HIST_FIELD_FL_HITCOUNT
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 312) type: u64
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 313) size: 8
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 314) is_signed: 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 315)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 316) hist_data->fields[1]:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 317) flags:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 318) VAL: normal u64 value
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 319) ftrace_event_field name: bytes_req
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 320) type: size_t
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 321) size: 8
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 322) is_signed: 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 323)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 324) hist_data->fields[2]:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 325) flags:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 326) VAL: normal u64 value
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 327) ftrace_event_field name: bytes_alloc
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 328) type: size_t
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 329) size: 8
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 330) is_signed: 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 331)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 332) key fields:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 333)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 334) hist_data->fields[3]:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 335) flags:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 336) HIST_FIELD_FL_KEY
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 337) ftrace_event_field name: common_pid
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 338) type: int
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 339) size: 8
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 340) is_signed: 1
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 341)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 342) hist_data->fields[4]:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 343) flags:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 344) HIST_FIELD_FL_KEY
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 345) ftrace_event_field name: call_site
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 346) type: unsigned long
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 347) size: 8
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 348) is_signed: 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 349)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 350) The commands below can be used to clean things up for the next test::
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 351)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 352) # echo '!hist:keys=common_pid,call_site.sym:values=bytes_req,bytes_alloc,hitcount' >> events/kmem/kmalloc/trigger
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 353)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 354) Variables
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 355) =========
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 356)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 357) Variables allow data from one hist trigger to be saved by one hist
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 358) trigger and retrieved by another hist trigger. For example, a trigger
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 359) on the sched_waking event can capture a timestamp for a particular
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 360) pid, and later a sched_switch event that switches to that pid event
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 361) can grab the timestamp and use it to calculate a time delta between
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 362) the two events::
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 363)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 364) # echo 'hist:keys=pid:ts0=common_timestamp.usecs' >>
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 365) events/sched/sched_waking/trigger
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 366)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 367) # echo 'hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0' >>
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 368) events/sched/sched_switch/trigger
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 369)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 370) In terms of the histogram data structures, variables are implemented
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 371) as another type of hist_field and for a given hist trigger are added
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 372) to the hist_data.fields[] array just after all the val fields. To
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 373) distinguish them from the existing key and val fields, they're given a
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 374) new flag type, HIST_FIELD_FL_VAR (abbreviated FL_VAR) and they also
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 375) make use of a new .var.idx field member in struct hist_field, which
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 376) maps them to an index in a new map_elt.vars[] array added to the
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 377) map_elt specifically designed to store and retrieve variable values.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 378) The diagram below shows those new elements and adds a new variable
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 379) entry, ts0, corresponding to the ts0 variable in the sched_waking
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 380) trigger above.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 381)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 382) sched_waking histogram
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 383) ----------------------::
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 384)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 385) +------------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 386) | hist_data |<-------------------------------------------------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 387) +------------------+ +-------------------+ |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 388) | .fields[] |-->| val = hitcount | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 389) +----------------+ +-------------------+ |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 390) | .map | | .size | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 391) +----------------+ +-----------------+ |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 392) | .offset | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 393) +-----------------+ |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 394) | .fn() | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 395) +-----------------+ |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 396) | .flags | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 397) +-----------------+ |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 398) | .var.idx | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 399) +-------------------+ |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 400) | var = ts0 | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 401) +-------------------+ |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 402) | .size | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 403) +-----------------+ |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 404) | .offset | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 405) +-----------------+ |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 406) | .fn() | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 407) +-----------------+ |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 408) | .flags & FL_VAR | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 409) +-----------------+ |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 410) | .var.idx |----------------------------+-+ |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 411) +-----------------+ | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 412) . | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 413) . | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 414) . | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 415) +-------------------+ <--- n_vals | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 416) | key = pid | | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 417) +-------------------+ | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 418) | .size | | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 419) +-----------------+ | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 420) | .offset | | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 421) +-----------------+ | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 422) | .fn() | | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 423) +-----------------+ | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 424) | .flags & FL_KEY | | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 425) +-----------------+ | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 426) | .var.idx | | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 427) +-------------------+ <--- n_fields | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 428) | unused | | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 429) +-------------------+ | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 430) | | | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 431) +-----------------+ | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 432) | | | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 433) +-----------------+ | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 434) | | | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 435) +-----------------+ | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 436) | | | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 437) +-----------------+ | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 438) | | | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 439) +-----------------+ | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 440) n_keys = n_fields - n_vals | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 441) | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 442)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 443) This is very similar to the basic case. In the above diagram, we can | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 444) see a new .flags member has been added to the struct hist_field | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 445) struct, and a new entry added to hist_data.fields representing the ts0 | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 446) variable. For a normal val hist_field, .flags is just 0 (modulo | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 447) modifier flags), but if the value is defined as a variable, the .flags | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 448) contains a set FL_VAR bit. | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 449)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 450) As you can see, the ts0 entry's .var.idx member contains the index | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 451) into the tracing_map_elts' .vars[] array containing variable values. | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 452) This idx is used whenever the value of the variable is set or read. | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 453) The map_elt.vars idx assigned to the given variable is assigned and | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 454) saved in .var.idx by create_tracing_map_fields() after it calls | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 455) tracing_map_add_var(). | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 456)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 457) Below is a representation of the histogram at run-time, which | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 458) populates the map, along with correspondence to the above hist_data and | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 459) hist_field data structures. | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 460)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 461) The diagram attempts to show the relationship between the | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 462) hist_data.fields[] and the map_elt.fields[] and map_elt.vars[] with | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 463) the links drawn between diagrams. For each of the map_elts, you can | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 464) see that the .fields[] members point to the .sum or .offset of a key | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 465) or val and the .vars[] members point to the value of a variable. The | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 466) arrows between the two diagrams show the linkages between those | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 467) tracing_map members and the field definitions in the corresponding | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 468) hist_data fields[] members.::
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 469)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 470) +-----------+ | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 471) | hist_data | | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 472) +-----------+ | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 473) | .fields | | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 474) +---------+ +-----------+ | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 475) | .map |---->| map_entry | | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 476) +---------+ +-----------+ | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 477) | .key |---> 0 | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 478) +---------+ | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 479) | .val |---> NULL | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 480) +-----------+ | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 481) | map_entry | | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 482) +-----------+ | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 483) | .key |---> pid = 999 | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 484) +---------+ +-----------+ | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 485) | .val |--->| map_elt | | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 486) +---------+ +-----------+ | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 487) . | .key |---> full key * | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 488) . +---------+ +---------------+ | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 489) . | .fields |--->| .sum (val) | | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 490) . +---------+ | 2345 | | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 491) . +--| .vars | +---------------+ | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 492) . | +---------+ | .offset (key) | | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 493) . | | 0 | | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 494) . | +---------------+ | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 495) . | . | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 496) . | . | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 497) . | . | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 498) . | +---------------+ | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 499) . | | .sum (val) or | | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 500) . | | .offset (key) | | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 501) . | +---------------+ | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 502) . | | .sum (val) or | | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 503) . | | .offset (key) | | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 504) . | +---------------+ | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 505) . | | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 506) . +---------------->+---------------+ | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 507) . | ts0 |<--+ | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 508) . | 113345679876 | | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 509) . +---------------+ | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 510) . | unused | | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 511) . | | | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 512) . +---------------+ | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 513) . . | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 514) . . | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 515) . . | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 516) . +---------------+ | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 517) . | unused | | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 518) . | | | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 519) . +---------------+ | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 520) . | unused | | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 521) . | | | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 522) . +---------------+ | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 523) . | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 524) +-----------+ | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 525) | map_entry | | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 526) +-----------+ | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 527) | .key |---> pid = 4444 | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 528) +---------+ +-----------+ | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 529) | .val |--->| map_elt | | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 530) +---------+ +-----------+ | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 531) . | .key |---> full key * | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 532) . +---------+ +---------------+ | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 533) . | .fields |--->| .sum (val) | | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 534) +---------+ | 2345 | | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 535) +--| .vars | +---------------+ | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 536) | +---------+ | .offset (key) | | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 537) | | 0 | | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 538) | +---------------+ | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 539) | . | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 540) | . | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 541) | . | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 542) | +---------------+ | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 543) | | .sum (val) or | | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 544) | | .offset (key) | | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 545) | +---------------+ | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 546) | | .sum (val) or | | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 547) | | .offset (key) | | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 548) | +---------------+ | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 549) | | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 550) | +---------------+ | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 551) +---------------->| ts0 |<--+ | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 552) | 213499240729 | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 553) +---------------+ | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 554) | unused | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 555) | | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 556) +---------------+ | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 557) . | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 558) . | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 559) . | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 560) +---------------+ | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 561) | unused | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 562) | | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 563) +---------------+ | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 564) | unused | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 565) | | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 566) +---------------+ | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 567)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 568) For each used map entry, there's a map_elt pointing to an array of | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 569) .vars containing the current value of the variables associated with | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 570) that histogram entry. So in the above, the timestamp associated with | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 571) pid 999 is 113345679876, and the timestamp variable in the same | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 572) .var.idx for pid 4444 is 213499240729. | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 573)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 574) sched_switch histogram | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 575) ---------------------- | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 576)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 577) The sched_switch histogram paired with the above sched_waking | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 578) histogram is shown below. The most important aspect of the | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 579) sched_switch histogram is that it references a variable on the | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 580) sched_waking histogram above. | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 581)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 582) The histogram diagram is very similar to the others so far displayed, | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 583) but it adds variable references. You can see the normal hitcount and | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 584) key fields along with a new wakeup_lat variable implemented in the | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 585) same way as the sched_waking ts0 variable, but in addition there's an | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 586) entry with the new FL_VAR_REF (short for HIST_FIELD_FL_VAR_REF) flag. | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 587)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 588) Associated with the new var ref field are a couple of new hist_field | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 589) members, var.hist_data and var_ref_idx. For a variable reference, the | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 590) var.hist_data goes with the var.idx, which together uniquely identify | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 591) a particular variable on a particular histogram. The var_ref_idx is | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 592) just the index into the var_ref_vals[] array that caches the values of | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 593) each variable whenever a hist trigger is updated. Those resulting | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 594) values are then finally accessed by other code such as trace action | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 595) code that uses the var_ref_idx values to assign param values. | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 596)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 597) The diagram below describes the situation for the sched_switch | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 598) histogram referred to before::
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 599)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 600) # echo 'hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0' >> | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 601) events/sched/sched_switch/trigger | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 602) | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 603) +------------------+ | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 604) | hist_data | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 605) +------------------+ +-----------------------+ | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 606) | .fields[] |-->| val = hitcount | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 607) +----------------+ +-----------------------+ | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 608) | .map | | .size | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 609) +----------------+ +---------------------+ | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 610) +--| .var_refs[] | | .offset | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 611) | +----------------+ +---------------------+ | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 612) | | .fn() | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 613) | var_ref_vals[] +---------------------+ | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 614) | +-------------+ | .flags | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 615) | | $ts0 |<---+ +---------------------+ | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 616) | +-------------+ | | .var.idx | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 617) | | | | +---------------------+ | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 618) | +-------------+ | | .var.hist_data | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 619) | | | | +---------------------+ | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 620) | +-------------+ | | .var_ref_idx | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 621) | | | | +-----------------------+ | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 622) | +-------------+ | | var = wakeup_lat | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 623) | . | +-----------------------+ | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 624) | . | | .size | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 625) | . | +---------------------+ | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 626) | +-------------+ | | .offset | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 627) | | | | +---------------------+ | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 628) | +-------------+ | | .fn() | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 629) | | | | +---------------------+ | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 630) | +-------------+ | | .flags & FL_VAR | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 631) | | +---------------------+ | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 632) | | | .var.idx | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 633) | | +---------------------+ | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 634) | | | .var.hist_data | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 635) | | +---------------------+ | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 636) | | | .var_ref_idx | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 637) | | +---------------------+ | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 638) | | . | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 639) | | . | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 640) | | . | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 641) | | +-----------------------+ <--- n_vals | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 642) | | | key = pid | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 643) | | +-----------------------+ | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 644) | | | .size | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 645) | | +---------------------+ | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 646) | | | .offset | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 647) | | +---------------------+ | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 648) | | | .fn() | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 649) | | +---------------------+ | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 650) | | | .flags | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 651) | | +---------------------+ | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 652) | | | .var.idx | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 653) | | +-----------------------+ <--- n_fields | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 654) | | | unused | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 655) | | +-----------------------+ | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 656) | | | | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 657) | | +---------------------+ | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 658) | | | | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 659) | | +---------------------+ | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 660) | | | | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 661) | | +---------------------+ | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 662) | | | | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 663) | | +---------------------+ | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 664) | | | | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 665) | | +---------------------+ | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 666) | | n_keys = n_fields - n_vals | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 667) | | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 668) | | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 669) | | +-----------------------+ | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 670) +---------------------->| var_ref = $ts0 | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 671) | +-----------------------+ | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 672) | | .size | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 673) | +---------------------+ | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 674) | | .offset | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 675) | +---------------------+ | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 676) | | .fn() | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 677) | +---------------------+ | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 678) | | .flags & FL_VAR_REF | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 679) | +---------------------+ | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 680) | | .var.idx |--------------------------+ |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 681) | +---------------------+ |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 682) | | .var.hist_data |----------------------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 683) | +---------------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 684) +---| .var_ref_idx |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 685) +---------------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 686)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 687) Abbreviations used in the diagrams::
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 688)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 689) hist_data = struct hist_trigger_data
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 690) hist_data.fields = struct hist_field
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 691) fn = hist_field_fn_t
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 692) FL_KEY = HIST_FIELD_FL_KEY
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 693) FL_VAR = HIST_FIELD_FL_VAR
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 694) FL_VAR_REF = HIST_FIELD_FL_VAR_REF
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 695)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 696) When a hist trigger makes use of a variable, a new hist_field is
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 697) created with flag HIST_FIELD_FL_VAR_REF. For a VAR_REF field, the
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 698) var.idx and var.hist_data take the same values as the referenced
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 699) variable, as well as the referenced variable's size, type, and
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 700) is_signed values. The VAR_REF field's .name is set to the name of the
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 701) variable it references. If a variable reference was created using the
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 702) explicit system.event.$var_ref notation, the hist_field's system and
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 703) event_name variables are also set.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 704)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 705) So, in order to handle an event for the sched_switch histogram,
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 706) because we have a reference to a variable on another histogram, we
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 707) need to resolve all variable references first. This is done via the
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 708) resolve_var_refs() calls made from event_hist_trigger(). What this
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 709) does is grabs the var_refs[] array from the hist_data representing the
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 710) sched_switch histogram. For each one of those, the referenced
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 711) variable's var.hist_data along with the current key is used to look up
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 712) the corresponding tracing_map_elt in that histogram. Once found, the
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 713) referenced variable's var.idx is used to look up the variable's value
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 714) using tracing_map_read_var(elt, var.idx), which yields the value of
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 715) the variable for that element, ts0 in the case above. Note that both
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 716) the hist_fields representing both the variable and the variable
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 717) reference have the same var.idx, so this is straightforward.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 718)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 719) Variable and variable reference test
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 720) ------------------------------------
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 721)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 722) This example creates a variable on the sched_waking event, ts0, and
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 723) uses it in the sched_switch trigger. The sched_switch trigger also
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 724) creates its own variable, wakeup_lat, but nothing yet uses it::
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 725)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 726) # echo 'hist:keys=pid:ts0=common_timestamp.usecs' >> events/sched/sched_waking/trigger
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 727)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 728) # echo 'hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0' >> events/sched/sched_switch/trigger
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 729)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 730) Looking at the sched_waking 'hist_debug' output, in addition to the
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 731) normal key and value hist_fields, in the val fields section we see a
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 732) field with the HIST_FIELD_FL_VAR flag, which indicates that that field
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 733) represents a variable. Note that in addition to the variable name,
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 734) contained in the var.name field, it includes the var.idx, which is the
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 735) index into the tracing_map_elt.vars[] array of the actual variable
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 736) location. Note also that the output shows that variables live in the
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 737) same part of the hist_data->fields[] array as normal values::
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 738)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 739) # cat events/sched/sched_waking/hist_debug
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 740)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 741) # event histogram
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 742) #
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 743) # trigger info: hist:keys=pid:vals=hitcount:ts0=common_timestamp.usecs:sort=hitcount:size=2048:clock=global [active]
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 744) #
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 745)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 746) hist_data: 000000009536f554
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 747)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 748) n_vals: 2
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 749) n_keys: 1
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 750) n_fields: 3
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 751)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 752) val fields:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 753)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 754) hist_data->fields[0]:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 755) flags:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 756) VAL: HIST_FIELD_FL_HITCOUNT
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 757) type: u64
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 758) size: 8
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 759) is_signed: 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 760)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 761) hist_data->fields[1]:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 762) flags:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 763) HIST_FIELD_FL_VAR
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 764) var.name: ts0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 765) var.idx (into tracing_map_elt.vars[]): 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 766) type: u64
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 767) size: 8
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 768) is_signed: 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 769)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 770) key fields:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 771)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 772) hist_data->fields[2]:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 773) flags:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 774) HIST_FIELD_FL_KEY
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 775) ftrace_event_field name: pid
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 776) type: pid_t
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 777) size: 8
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 778) is_signed: 1
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 779)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 780) Moving on to the sched_switch trigger hist_debug output, in addition
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 781) to the unused wakeup_lat variable, we see a new section displaying
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 782) variable references. Variable references are displayed in a separate
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 783) section because in addition to being logically separate from
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 784) variables and values, they actually live in a separate hist_data
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 785) array, var_refs[].
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 786)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 787) In this example, the sched_switch trigger has a reference to a
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 788) variable on the sched_waking trigger, $ts0. Looking at the details,
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 789) we can see that the var.hist_data value of the referenced variable
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 790) matches the previously displayed sched_waking trigger, and the var.idx
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 791) value matches the previously displayed var.idx value for that
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 792) variable. Also displayed is the var_ref_idx value for that variable
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 793) reference, which is where the value for that variable is cached for
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 794) use when the trigger is invoked::
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 795)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 796) # cat events/sched/sched_switch/hist_debug
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 797)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 798) # event histogram
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 799) #
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 800) # trigger info: hist:keys=next_pid:vals=hitcount:wakeup_lat=common_timestamp.usecs-$ts0:sort=hitcount:size=2048:clock=global [active]
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 801) #
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 802)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 803) hist_data: 00000000f4ee8006
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 804)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 805) n_vals: 2
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 806) n_keys: 1
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 807) n_fields: 3
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 808)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 809) val fields:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 810)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 811) hist_data->fields[0]:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 812) flags:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 813) VAL: HIST_FIELD_FL_HITCOUNT
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 814) type: u64
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 815) size: 8
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 816) is_signed: 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 817)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 818) hist_data->fields[1]:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 819) flags:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 820) HIST_FIELD_FL_VAR
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 821) var.name: wakeup_lat
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 822) var.idx (into tracing_map_elt.vars[]): 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 823) type: u64
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 824) size: 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 825) is_signed: 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 826)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 827) key fields:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 828)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 829) hist_data->fields[2]:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 830) flags:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 831) HIST_FIELD_FL_KEY
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 832) ftrace_event_field name: next_pid
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 833) type: pid_t
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 834) size: 8
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 835) is_signed: 1
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 836)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 837) variable reference fields:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 838)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 839) hist_data->var_refs[0]:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 840) flags:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 841) HIST_FIELD_FL_VAR_REF
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 842) name: ts0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 843) var.idx (into tracing_map_elt.vars[]): 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 844) var.hist_data: 000000009536f554
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 845) var_ref_idx (into hist_data->var_refs[]): 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 846) type: u64
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 847) size: 8
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 848) is_signed: 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 849)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 850) The commands below can be used to clean things up for the next test::
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 851)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 852) # echo '!hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0' >> events/sched/sched_switch/trigger
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 853)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 854) # echo '!hist:keys=pid:ts0=common_timestamp.usecs' >> events/sched/sched_waking/trigger
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 855)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 856) Actions and Handlers
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 857) ====================
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 858)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 859) Adding onto the previous example, we will now do something with that
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 860) wakeup_lat variable, namely send it and another field as a synthetic
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 861) event.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 862)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 863) The onmatch() action below basically says that whenever we have a
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 864) sched_switch event, if we have a matching sched_waking event, in this
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 865) case if we have a pid in the sched_waking histogram that matches the
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 866) next_pid field on this sched_switch event, we retrieve the
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 867) variables specified in the wakeup_latency() trace action, and use
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 868) them to generate a new wakeup_latency event into the trace stream.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 869)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 870) Note that the way the trace handlers such as wakeup_latency() (which
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 871) could equivalently be written trace(wakeup_latency,$wakeup_lat,next_pid)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 872) are implemented, the parameters specified to the trace handler must be
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 873) variables. In this case, $wakeup_lat is obviously a variable, but
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 874) next_pid isn't, since it's just naming a field in the sched_switch
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 875) trace event. Since this is something that almost every trace() and
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 876) save() action does, a special shortcut is implemented to allow field
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 877) names to be used directly in those cases. How it works is that under
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 878) the covers, a temporary variable is created for the named field, and
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 879) this variable is what is actually passed to the trace handler. In the
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 880) code and documentation, this type of variable is called a 'field
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 881) variable'.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 882)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 883) Fields on other trace event's histograms can be used as well. In that
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 884) case we have to generate a new histogram and an unfortunately named
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 885) 'synthetic_field' (the use of synthetic here has nothing to do with
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 886) synthetic events) and use that special histogram field as a variable.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 887)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 888) The diagram below illustrates the new elements described above in the
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 889) context of the sched_switch histogram using the onmatch() handler and
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 890) the trace() action.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 891)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 892) First, we define the wakeup_latency synthetic event::
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 893)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 894) # echo 'wakeup_latency u64 lat; pid_t pid' >> synthetic_events
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 895)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 896) Next, the sched_waking hist trigger as before::
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 897)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 898) # echo 'hist:keys=pid:ts0=common_timestamp.usecs' >>
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 899) events/sched/sched_waking/trigger
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 900)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 901) Finally, we create a hist trigger on the sched_switch event that
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 902) generates a wakeup_latency() trace event. In this case we pass
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 903) next_pid into the wakeup_latency synthetic event invocation, which
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 904) means it will be automatically converted into a field variable::
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 905)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 906) # echo 'hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0: \
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 907) onmatch(sched.sched_waking).wakeup_latency($wakeup_lat,next_pid)' >>
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 908) /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 909)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 910) The diagram for the sched_switch event is similar to previous examples
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 911) but shows the additional field_vars[] array for hist_data and shows
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 912) the linkages between the field_vars and the variables and references
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 913) created to implement the field variables. The details are discussed
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 914) below::
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 915)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 916) +------------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 917) | hist_data |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 918) +------------------+ +-----------------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 919) | .fields[] |-->| val = hitcount |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 920) +----------------+ +-----------------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 921) | .map | | .size |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 922) +----------------+ +---------------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 923) +---| .field_vars[] | | .offset |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 924) | +----------------+ +---------------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 925) |+--| .var_refs[] | | .offset |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 926) || +----------------+ +---------------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 927) || | .fn() |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 928) || var_ref_vals[] +---------------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 929) || +-------------+ | .flags |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 930) || | $ts0 |<---+ +---------------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 931) || +-------------+ | | .var.idx |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 932) || | $next_pid |<-+ | +---------------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 933) || +-------------+ | | | .var.hist_data |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 934) ||+>| $wakeup_lat | | | +---------------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 935) ||| +-------------+ | | | .var_ref_idx |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 936) ||| | | | | +-----------------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 937) ||| +-------------+ | | | var = wakeup_lat |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 938) ||| . | | +-----------------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 939) ||| . | | | .size |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 940) ||| . | | +---------------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 941) ||| +-------------+ | | | .offset |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 942) ||| | | | | +---------------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 943) ||| +-------------+ | | | .fn() |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 944) ||| | | | | +---------------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 945) ||| +-------------+ | | | .flags & FL_VAR |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 946) ||| | | +---------------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 947) ||| | | | .var.idx |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 948) ||| | | +---------------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 949) ||| | | | .var.hist_data |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 950) ||| | | +---------------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 951) ||| | | | .var_ref_idx |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 952) ||| | | +---------------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 953) ||| | | .
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 954) ||| | | .
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 955) ||| | | .
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 956) ||| | | .
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 957) ||| +--------------+ | | .
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 958) +-->| field_var | | | .
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 959) || +--------------+ | | .
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 960) || | var | | | .
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 961) || +------------+ | | .
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 962) || | val | | | .
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 963) || +--------------+ | | .
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 964) || | field_var | | | .
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 965) || +--------------+ | | .
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 966) || | var | | | .
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 967) || +------------+ | | .
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 968) || | val | | | .
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 969) || +------------+ | | .
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 970) || . | | .
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 971) || . | | .
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 972) || . | | +-----------------------+ <--- n_vals
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 973) || +--------------+ | | | key = pid |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 974) || | field_var | | | +-----------------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 975) || +--------------+ | | | .size |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 976) || | var |--+| +---------------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 977) || +------------+ ||| | .offset |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 978) || | val |-+|| +---------------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 979) || +------------+ ||| | .fn() |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 980) || ||| +---------------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 981) || ||| | .flags |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 982) || ||| +---------------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 983) || ||| | .var.idx |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 984) || ||| +---------------------+ <--- n_fields
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 985) || |||
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 986) || ||| n_keys = n_fields - n_vals
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 987) || ||| +-----------------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 988) || |+->| var = next_pid |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 989) || | | +-----------------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 990) || | | | .size |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 991) || | | +---------------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 992) || | | | .offset |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 993) || | | +---------------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 994) || | | | .flags & FL_VAR |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 995) || | | +---------------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 996) || | | | .var.idx |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 997) || | | +---------------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 998) || | | | .var.hist_data |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 999) || | | +-----------------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1000) || +-->| val for next_pid |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1001) || | | +-----------------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1002) || | | | .size |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1003) || | | +---------------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1004) || | | | .offset |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1005) || | | +---------------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1006) || | | | .fn() |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1007) || | | +---------------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1008) || | | | .flags |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1009) || | | +---------------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1010) || | | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1011) || | | +---------------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1012) || | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1013) || | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1014) || | | +-----------------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1015) +|------------------|-|>| var_ref = $ts0 |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1016) | | | +-----------------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1017) | | | | .size |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1018) | | | +---------------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1019) | | | | .offset |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1020) | | | +---------------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1021) | | | | .fn() |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1022) | | | +---------------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1023) | | | | .flags & FL_VAR_REF |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1024) | | | +---------------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1025) | | +---| .var_ref_idx |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1026) | | +-----------------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1027) | | | var_ref = $next_pid |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1028) | | +-----------------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1029) | | | .size |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1030) | | +---------------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1031) | | | .offset |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1032) | | +---------------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1033) | | | .fn() |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1034) | | +---------------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1035) | | | .flags & FL_VAR_REF |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1036) | | +---------------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1037) | +-----| .var_ref_idx |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1038) | +-----------------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1039) | | var_ref = $wakeup_lat |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1040) | +-----------------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1041) | | .size |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1042) | +---------------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1043) | | .offset |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1044) | +---------------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1045) | | .fn() |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1046) | +---------------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1047) | | .flags & FL_VAR_REF |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1048) | +---------------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1049) +------------------------| .var_ref_idx |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1050) +---------------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1051)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1052) As you can see, for a field variable, two hist_fields are created: one
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1053) representing the variable, in this case next_pid, and one to actually
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1054) get the value of the field from the trace stream, like a normal val
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1055) field does. These are created separately from normal variable
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1056) creation and are saved in the hist_data->field_vars[] array. See
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1057) below for how these are used. In addition, a reference hist_field is
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1058) also created, which is needed to reference the field variables such as
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1059) $next_pid variable in the trace() action.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1060)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1061) Note that $wakeup_lat is also a variable reference, referencing the
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1062) value of the expression common_timestamp-$ts0, and so also needs to
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1063) have a hist field entry representing that reference created.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1064)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1065) When hist_trigger_elt_update() is called to get the normal key and
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1066) value fields, it also calls update_field_vars(), which goes through
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1067) each field_var created for the histogram, and available from
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1068) hist_data->field_vars and calls val->fn() to get the data from the
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1069) current trace record, and then uses the var's var.idx to set the
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1070) variable at the var.idx offset in the appropriate tracing_map_elt's
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1071) variable at elt->vars[var.idx].
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1072)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1073) Once all the variables have been updated, resolve_var_refs() can be
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1074) called from event_hist_trigger(), and not only can our $ts0 and
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1075) $next_pid references be resolved but the $wakeup_lat reference as
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1076) well. At this point, the trace() action can simply access the values
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1077) assembled in the var_ref_vals[] array and generate the trace event.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1078)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1079) The same process occurs for the field variables associated with the
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1080) save() action.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1081)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1082) Abbreviations used in the diagram::
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1083)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1084) hist_data = struct hist_trigger_data
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1085) hist_data.fields = struct hist_field
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1086) field_var = struct field_var
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1087) fn = hist_field_fn_t
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1088) FL_KEY = HIST_FIELD_FL_KEY
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1089) FL_VAR = HIST_FIELD_FL_VAR
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1090) FL_VAR_REF = HIST_FIELD_FL_VAR_REF
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1091)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1092) trace() action field variable test
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1093) ----------------------------------
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1094)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1095) This example adds to the previous test example by finally making use
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1096) of the wakeup_lat variable, but in addition also creates a couple of
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1097) field variables that then are all passed to the wakeup_latency() trace
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1098) action via the onmatch() handler.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1099)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1100) First, we create the wakeup_latency synthetic event::
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1101)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1102) # echo 'wakeup_latency u64 lat; pid_t pid; char comm[16]' >> synthetic_events
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1103)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1104) Next, the sched_waking trigger from previous examples::
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1105)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1106) # echo 'hist:keys=pid:ts0=common_timestamp.usecs' >> events/sched/sched_waking/trigger
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1107)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1108) Finally, as in the previous test example, we calculate and assign the
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1109) wakeup latency using the $ts0 reference from the sched_waking trigger
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1110) to the wakeup_lat variable, and finally use it along with a couple
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1111) sched_switch event fields, next_pid and next_comm, to generate a
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1112) wakeup_latency trace event. The next_pid and next_comm event fields
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1113) are automatically converted into field variables for this purpose::
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1114)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 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/debug/tracing/events/sched/sched_switch/trigger
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1116)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1117) The sched_waking hist_debug output shows the same data as in the
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1118) previous test example::
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1119)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1120) # cat events/sched/sched_waking/hist_debug
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1121)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1122) # event histogram
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1123) #
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1124) # trigger info: hist:keys=pid:vals=hitcount:ts0=common_timestamp.usecs:sort=hitcount:size=2048:clock=global [active]
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1125) #
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1126)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1127) hist_data: 00000000d60ff61f
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1128)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1129) n_vals: 2
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1130) n_keys: 1
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1131) n_fields: 3
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1132)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1133) val fields:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1134)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1135) hist_data->fields[0]:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1136) flags:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1137) VAL: HIST_FIELD_FL_HITCOUNT
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1138) type: u64
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1139) size: 8
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1140) is_signed: 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1141)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1142) hist_data->fields[1]:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1143) flags:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1144) HIST_FIELD_FL_VAR
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1145) var.name: ts0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1146) var.idx (into tracing_map_elt.vars[]): 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1147) type: u64
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1148) size: 8
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1149) is_signed: 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1150)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1151) key fields:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1152)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1153) hist_data->fields[2]:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1154) flags:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1155) HIST_FIELD_FL_KEY
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1156) ftrace_event_field name: pid
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1157) type: pid_t
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1158) size: 8
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1159) is_signed: 1
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1160)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1161) The sched_switch hist_debug output shows the same key and value fields
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1162) as in the previous test example - note that wakeup_lat is still in the
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1163) val fields section, but that the new field variables are not there -
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1164) although the field variables are variables, they're held separately in
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1165) the hist_data's field_vars[] array. Although the field variables and
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1166) the normal variables are located in separate places, you can see that
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1167) the actual variable locations for those variables in the
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1168) tracing_map_elt.vars[] do have increasing indices as expected:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1169) wakeup_lat takes the var.idx = 0 slot, while the field variables for
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1170) next_pid and next_comm have values var.idx = 1, and var.idx = 2. Note
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1171) also that those are the same values displayed for the variable
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1172) references corresponding to those variables in the variable reference
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1173) fields section. Since there are two triggers and thus two hist_data
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1174) addresses, those addresses also need to be accounted for when doing
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1175) the matching - you can see that the first variable refers to the 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1176) var.idx on the previous hist trigger (see the hist_data address
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1177) associated with that trigger), while the second variable refers to the
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1178) 0 var.idx on the sched_switch hist trigger, as do all the remaining
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1179) variable references.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1180)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1181) Finally, the action tracking variables section just shows the system
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1182) and event name for the onmatch() handler::
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1183)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1184) # cat events/sched/sched_switch/hist_debug
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1185)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1186) # event histogram
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1187) #
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 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]
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1189) #
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1190)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1191) hist_data: 0000000008f551b7
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1192)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1193) n_vals: 2
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1194) n_keys: 1
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1195) n_fields: 3
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1196)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1197) val fields:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1198)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1199) hist_data->fields[0]:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1200) flags:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1201) VAL: HIST_FIELD_FL_HITCOUNT
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1202) type: u64
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1203) size: 8
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1204) is_signed: 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1205)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1206) hist_data->fields[1]:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1207) flags:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1208) HIST_FIELD_FL_VAR
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1209) var.name: wakeup_lat
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1210) var.idx (into tracing_map_elt.vars[]): 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1211) type: u64
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1212) size: 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1213) is_signed: 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1214)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1215) key fields:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1216)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1217) hist_data->fields[2]:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1218) flags:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1219) HIST_FIELD_FL_KEY
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1220) ftrace_event_field name: next_pid
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1221) type: pid_t
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1222) size: 8
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1223) is_signed: 1
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1224)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1225) variable reference fields:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1226)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1227) hist_data->var_refs[0]:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1228) flags:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1229) HIST_FIELD_FL_VAR_REF
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1230) name: ts0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1231) var.idx (into tracing_map_elt.vars[]): 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1232) var.hist_data: 00000000d60ff61f
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1233) var_ref_idx (into hist_data->var_refs[]): 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1234) type: u64
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1235) size: 8
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1236) is_signed: 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1237)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1238) hist_data->var_refs[1]:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1239) flags:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1240) HIST_FIELD_FL_VAR_REF
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1241) name: wakeup_lat
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1242) var.idx (into tracing_map_elt.vars[]): 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1243) var.hist_data: 0000000008f551b7
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1244) var_ref_idx (into hist_data->var_refs[]): 1
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1245) type: u64
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1246) size: 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1247) is_signed: 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1248)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1249) hist_data->var_refs[2]:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1250) flags:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1251) HIST_FIELD_FL_VAR_REF
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1252) name: next_pid
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1253) var.idx (into tracing_map_elt.vars[]): 1
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1254) var.hist_data: 0000000008f551b7
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1255) var_ref_idx (into hist_data->var_refs[]): 2
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1256) type: pid_t
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1257) size: 4
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1258) is_signed: 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1259)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1260) hist_data->var_refs[3]:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1261) flags:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1262) HIST_FIELD_FL_VAR_REF
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1263) name: next_comm
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1264) var.idx (into tracing_map_elt.vars[]): 2
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1265) var.hist_data: 0000000008f551b7
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1266) var_ref_idx (into hist_data->var_refs[]): 3
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1267) type: char[16]
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1268) size: 256
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1269) is_signed: 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1270)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1271) field variables:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1272)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1273) hist_data->field_vars[0]:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1274)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1275) field_vars[0].var:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1276) flags:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1277) HIST_FIELD_FL_VAR
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1278) var.name: next_pid
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1279) var.idx (into tracing_map_elt.vars[]): 1
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1280)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1281) field_vars[0].val:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1282) ftrace_event_field name: next_pid
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1283) type: pid_t
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1284) size: 4
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1285) is_signed: 1
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1286)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1287) hist_data->field_vars[1]:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1288)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1289) field_vars[1].var:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1290) flags:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1291) HIST_FIELD_FL_VAR
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1292) var.name: next_comm
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1293) var.idx (into tracing_map_elt.vars[]): 2
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1294)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1295) field_vars[1].val:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1296) ftrace_event_field name: next_comm
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1297) type: char[16]
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1298) size: 256
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1299) is_signed: 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1300)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1301) action tracking variables (for onmax()/onchange()/onmatch()):
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1302)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1303) hist_data->actions[0].match_data.event_system: sched
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1304) hist_data->actions[0].match_data.event: sched_waking
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1305)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1306) The commands below can be used to clean things up for the next test::
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1307)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 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/debug/tracing/events/sched/sched_switch/trigger
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1309)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1310) # echo '!hist:keys=pid:ts0=common_timestamp.usecs' >> events/sched/sched_waking/trigger
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1311)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1312) # echo '!wakeup_latency u64 lat; pid_t pid; char comm[16]' >> synthetic_events
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1313)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1314) action_data and the trace() action
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1315) ----------------------------------
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1316)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1317) As mentioned above, when the trace() action generates a synthetic
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1318) event, all the parameters to the synthetic event either already are
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1319) variables or are converted into variables (via field variables), and
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1320) finally all those variable values are collected via references to them
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1321) into a var_ref_vals[] array.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1322)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1323) The values in the var_ref_vals[] array, however, don't necessarily
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1324) follow the same ordering as the synthetic event params. To address
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1325) that, struct action_data contains another array, var_ref_idx[] that
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1326) maps the trace action params to the var_ref_vals[] values. Below is a
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1327) diagram illustrating that for the wakeup_latency() synthetic event::
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1328)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1329) +------------------+ wakeup_latency()
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1330) | action_data | event params var_ref_vals[]
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1331) +------------------+ +-----------------+ +-----------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1332) | .var_ref_idx[] |--->| $wakeup_lat idx |---+ | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1333) +----------------+ +-----------------+ | +-----------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1334) | .synth_event | | $next_pid idx |---|-+ | $wakeup_lat val |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1335) +----------------+ +-----------------+ | | +-----------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1336) . | +->| $next_pid val |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1337) . | +-----------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1338) . | .
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1339) +-----------------+ | .
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1340) | | | .
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1341) +-----------------+ | +-----------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1342) +--->| $wakeup_lat val |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1343) +-----------------+
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1344)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1345) Basically, how this ends up getting used in the synthetic event probe
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1346) function, trace_event_raw_event_synth(), is as follows::
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1347)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1348) for each field i in .synth_event
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1349) val_idx = .var_ref_idx[i]
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1350) val = var_ref_vals[val_idx]
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1351)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1352) action_data and the onXXX() handlers
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1353) ------------------------------------
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1354)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1355) The hist trigger onXXX() actions other than onmatch(), such as onmax()
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1356) and onchange(), also make use of and internally create hidden
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1357) variables. This information is contained in the
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1358) action_data.track_data struct, and is also visible in the hist_debug
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1359) output as will be described in the example below.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1360)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1361) Typically, the onmax() or onchange() handlers are used in conjunction
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1362) with the save() and snapshot() actions. For example::
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1363)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1364) # echo 'hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0: \
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1365) onmax($wakeup_lat).save(next_comm,prev_pid,prev_prio,prev_comm)' >>
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1366) /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1367)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1368) or::
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1369)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1370) # echo 'hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0: \
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1371) onmax($wakeup_lat).snapshot()' >>
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1372) /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1373)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1374) save() action field variable test
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1375) ---------------------------------
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1376)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1377) For this example, instead of generating a synthetic event, the save()
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1378) action is used to save field values whenever an onmax() handler
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1379) detects that a new max latency has been hit. As in the previous
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1380) example, the values being saved are also field values, but in this
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1381) case, are kept in a separate hist_data array named save_vars[].
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1382)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1383) As in previous test examples, we set up the sched_waking trigger::
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1384)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1385) # echo 'hist:keys=pid:ts0=common_timestamp.usecs' >> events/sched/sched_waking/trigger
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1386)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1387) In this case, however, we set up the sched_switch trigger to save some
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1388) sched_switch field values whenever we hit a new maximum latency. For
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1389) both the onmax() handler and save() action, variables will be created,
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1390) which we can use the hist_debug files to examine::
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1391)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 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/trigger
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1393)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1394) The sched_waking hist_debug output shows the same data as in the
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1395) previous test examples::
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1396)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1397) # cat events/sched/sched_waking/hist_debug
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1398)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1399) #
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1400) # trigger info: hist:keys=pid:vals=hitcount:ts0=common_timestamp.usecs:sort=hitcount:size=2048:clock=global [active]
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1401) #
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1402)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1403) hist_data: 00000000e6290f48
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1404)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1405) n_vals: 2
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1406) n_keys: 1
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1407) n_fields: 3
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1408)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1409) val fields:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1410)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1411) hist_data->fields[0]:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1412) flags:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1413) VAL: HIST_FIELD_FL_HITCOUNT
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1414) type: u64
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1415) size: 8
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1416) is_signed: 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1417)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1418) hist_data->fields[1]:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1419) flags:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1420) HIST_FIELD_FL_VAR
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1421) var.name: ts0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1422) var.idx (into tracing_map_elt.vars[]): 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1423) type: u64
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1424) size: 8
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1425) is_signed: 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1426)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1427) key fields:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1428)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1429) hist_data->fields[2]:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1430) flags:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1431) HIST_FIELD_FL_KEY
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1432) ftrace_event_field name: pid
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1433) type: pid_t
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1434) size: 8
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1435) is_signed: 1
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1436)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1437) The output of the sched_switch trigger shows the same val and key
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1438) values as before, but also shows a couple new sections.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1439)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1440) First, the action tracking variables section now shows the
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1441) actions[].track_data information describing the special tracking
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1442) variables and references used to track, in this case, the running
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1443) maximum value. The actions[].track_data.var_ref member contains the
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1444) reference to the variable being tracked, in this case the $wakeup_lat
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1445) variable. In order to perform the onmax() handler function, there
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1446) also needs to be a variable that tracks the current maximum by getting
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1447) updated whenever a new maximum is hit. In this case, we can see that
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1448) an auto-generated variable named ' __max' has been created and is
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1449) visible in the actions[].track_data.track_var variable.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1450)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1451) Finally, in the new 'save action variables' section, we can see that
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1452) the 4 params to the save() function have resulted in 4 field variables
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1453) being created for the purposes of saving the values of the named
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1454) fields when the max is hit. These variables are kept in a separate
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1455) save_vars[] array off of hist_data, so are displayed in a separate
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1456) section::
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1457)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1458) # cat events/sched/sched_switch/hist_debug
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1459)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1460) # event histogram
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1461) #
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 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]
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1463) #
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1464)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1465) hist_data: 0000000057bcd28d
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1466)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1467) n_vals: 2
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1468) n_keys: 1
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1469) n_fields: 3
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1470)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1471) val fields:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1472)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1473) hist_data->fields[0]:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1474) flags:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1475) VAL: HIST_FIELD_FL_HITCOUNT
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1476) type: u64
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1477) size: 8
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1478) is_signed: 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1479)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1480) hist_data->fields[1]:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1481) flags:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1482) HIST_FIELD_FL_VAR
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1483) var.name: wakeup_lat
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1484) var.idx (into tracing_map_elt.vars[]): 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1485) type: u64
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1486) size: 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1487) is_signed: 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1488)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1489) key fields:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1490)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1491) hist_data->fields[2]:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1492) flags:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1493) HIST_FIELD_FL_KEY
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1494) ftrace_event_field name: next_pid
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1495) type: pid_t
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1496) size: 8
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1497) is_signed: 1
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1498)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1499) variable reference fields:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1500)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1501) hist_data->var_refs[0]:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1502) flags:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1503) HIST_FIELD_FL_VAR_REF
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1504) name: ts0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1505) var.idx (into tracing_map_elt.vars[]): 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1506) var.hist_data: 00000000e6290f48
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1507) var_ref_idx (into hist_data->var_refs[]): 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1508) type: u64
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1509) size: 8
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1510) is_signed: 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1511)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1512) hist_data->var_refs[1]:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1513) flags:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1514) HIST_FIELD_FL_VAR_REF
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1515) name: wakeup_lat
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1516) var.idx (into tracing_map_elt.vars[]): 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1517) var.hist_data: 0000000057bcd28d
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1518) var_ref_idx (into hist_data->var_refs[]): 1
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1519) type: u64
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1520) size: 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1521) is_signed: 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1522)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1523) action tracking variables (for onmax()/onchange()/onmatch()):
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1524)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1525) hist_data->actions[0].track_data.var_ref:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1526) flags:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1527) HIST_FIELD_FL_VAR_REF
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1528) name: wakeup_lat
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1529) var.idx (into tracing_map_elt.vars[]): 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1530) var.hist_data: 0000000057bcd28d
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1531) var_ref_idx (into hist_data->var_refs[]): 1
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1532) type: u64
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1533) size: 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1534) is_signed: 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1535)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1536) hist_data->actions[0].track_data.track_var:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1537) flags:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1538) HIST_FIELD_FL_VAR
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1539) var.name: __max
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1540) var.idx (into tracing_map_elt.vars[]): 1
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1541) type: u64
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1542) size: 8
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1543) is_signed: 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1544)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1545) save action variables (save() params):
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1546)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1547) hist_data->save_vars[0]:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1548)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1549) save_vars[0].var:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1550) flags:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1551) HIST_FIELD_FL_VAR
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1552) var.name: next_comm
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1553) var.idx (into tracing_map_elt.vars[]): 2
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1554)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1555) save_vars[0].val:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1556) ftrace_event_field name: next_comm
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1557) type: char[16]
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1558) size: 256
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1559) is_signed: 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1560)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1561) hist_data->save_vars[1]:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1562)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1563) save_vars[1].var:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1564) flags:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1565) HIST_FIELD_FL_VAR
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1566) var.name: prev_pid
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1567) var.idx (into tracing_map_elt.vars[]): 3
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1568)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1569) save_vars[1].val:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1570) ftrace_event_field name: prev_pid
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1571) type: pid_t
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1572) size: 4
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1573) is_signed: 1
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1574)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1575) hist_data->save_vars[2]:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1576)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1577) save_vars[2].var:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1578) flags:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1579) HIST_FIELD_FL_VAR
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1580) var.name: prev_prio
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1581) var.idx (into tracing_map_elt.vars[]): 4
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1582)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1583) save_vars[2].val:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1584) ftrace_event_field name: prev_prio
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1585) type: int
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1586) size: 4
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1587) is_signed: 1
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1588)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1589) hist_data->save_vars[3]:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1590)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1591) save_vars[3].var:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1592) flags:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1593) HIST_FIELD_FL_VAR
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1594) var.name: prev_comm
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1595) var.idx (into tracing_map_elt.vars[]): 5
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1596)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1597) save_vars[3].val:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1598) ftrace_event_field name: prev_comm
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1599) type: char[16]
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1600) size: 256
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1601) is_signed: 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1602)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1603) The commands below can be used to clean things up for the next test::
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1604)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 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/trigger
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1606)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1607) # echo '!hist:keys=pid:ts0=common_timestamp.usecs' >> events/sched/sched_waking/trigger
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1608)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1609) A couple special cases
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1610) ======================
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1611)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1612) While the above covers the basics of the histogram internals, there
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1613) are a couple of special cases that should be discussed, since they
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1614) tend to create even more confusion. Those are field variables on other
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1615) histograms, and aliases, both described below through example tests
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1616) using the hist_debug files.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1617)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1618) Test of field variables on other histograms
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1619) -------------------------------------------
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1620)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1621) This example is similar to the previous examples, but in this case,
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1622) the sched_switch trigger references a hist trigger field on another
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1623) event, namely the sched_waking event. In order to accomplish this, a
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1624) field variable is created for the other event, but since an existing
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1625) histogram can't be used, as existing histograms are immutable, a new
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1626) histogram with a matching variable is created and used, and we'll see
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1627) that reflected in the hist_debug output shown below.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1628)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1629) First, we create the wakeup_latency synthetic event. Note the
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1630) addition of the prio field::
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1631)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1632) # echo 'wakeup_latency u64 lat; pid_t pid; int prio' >> synthetic_events
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1633)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1634) As in previous test examples, we set up the sched_waking trigger::
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1635)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1636) # echo 'hist:keys=pid:ts0=common_timestamp.usecs' >> events/sched/sched_waking/trigger
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1637)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1638) Here we set up a hist trigger on sched_switch to send a wakeup_latency
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1639) event using an onmatch handler naming the sched_waking event. Note
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1640) that the third param being passed to the wakeup_latency() is prio,
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1641) which is a field name that needs to have a field variable created for
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1642) it. There isn't however any prio field on the sched_switch event so
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1643) it would seem that it wouldn't be possible to create a field variable
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1644) for it. The matching sched_waking event does have a prio field, so it
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1645) should be possible to make use of it for this purpose. The problem
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1646) with that is that it's not currently possible to define a new variable
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1647) on an existing histogram, so it's not possible to add a new prio field
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1648) variable to the existing sched_waking histogram. It is however
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1649) possible to create an additional new 'matching' sched_waking histogram
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1650) for the same event, meaning that it uses the same key and filters, and
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1651) define the new prio field variable on that.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1652)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1653) Here's the sched_switch trigger::
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1654)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 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/trigger
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1656)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1657) And here's the output of the hist_debug information for the
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1658) sched_waking hist trigger. Note that there are two histograms
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1659) displayed in the output: the first is the normal sched_waking
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1660) histogram we've seen in the previous examples, and the second is the
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1661) special histogram we created to provide the prio field variable.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1662)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1663) Looking at the second histogram below, we see a variable with the name
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1664) synthetic_prio. This is the field variable created for the prio field
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1665) on that sched_waking histogram::
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1666)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1667) # cat events/sched/sched_waking/hist_debug
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1668)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1669) # event histogram
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1670) #
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1671) # trigger info: hist:keys=pid:vals=hitcount:ts0=common_timestamp.usecs:sort=hitcount:size=2048:clock=global [active]
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1672) #
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1673)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1674) hist_data: 00000000349570e4
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1675)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1676) n_vals: 2
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1677) n_keys: 1
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1678) n_fields: 3
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1679)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1680) val fields:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1681)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1682) hist_data->fields[0]:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1683) flags:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1684) VAL: HIST_FIELD_FL_HITCOUNT
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1685) type: u64
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1686) size: 8
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1687) is_signed: 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1688)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1689) hist_data->fields[1]:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1690) flags:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1691) HIST_FIELD_FL_VAR
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1692) var.name: ts0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1693) var.idx (into tracing_map_elt.vars[]): 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1694) type: u64
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1695) size: 8
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1696) is_signed: 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1697)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1698) key fields:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1699)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1700) hist_data->fields[2]:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1701) flags:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1702) HIST_FIELD_FL_KEY
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1703) ftrace_event_field name: pid
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1704) type: pid_t
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1705) size: 8
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1706) is_signed: 1
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1707)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1708)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1709) # event histogram
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1710) #
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1711) # trigger info: hist:keys=pid:vals=hitcount:synthetic_prio=prio:sort=hitcount:size=2048 [active]
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1712) #
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1713)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1714) hist_data: 000000006920cf38
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1715)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1716) n_vals: 2
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1717) n_keys: 1
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1718) n_fields: 3
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1719)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1720) val fields:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1721)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1722) hist_data->fields[0]:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1723) flags:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1724) VAL: HIST_FIELD_FL_HITCOUNT
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1725) type: u64
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1726) size: 8
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1727) is_signed: 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1728)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1729) hist_data->fields[1]:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1730) flags:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1731) HIST_FIELD_FL_VAR
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1732) ftrace_event_field name: prio
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1733) var.name: synthetic_prio
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1734) var.idx (into tracing_map_elt.vars[]): 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1735) type: int
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1736) size: 4
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1737) is_signed: 1
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1738)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1739) key fields:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1740)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1741) hist_data->fields[2]:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1742) flags:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1743) HIST_FIELD_FL_KEY
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1744) ftrace_event_field name: pid
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1745) type: pid_t
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1746) size: 8
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1747) is_signed: 1
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1748)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1749) Looking at the sched_switch histogram below, we can see a reference to
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1750) the synthetic_prio variable on sched_waking, and looking at the
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1751) associated hist_data address we see that it is indeed associated with
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1752) the new histogram. Note also that the other references are to a
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1753) normal variable, wakeup_lat, and to a normal field variable, next_pid,
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1754) the details of which are in the field variables section::
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1755)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1756) # cat events/sched/sched_switch/hist_debug
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1757)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1758) # event histogram
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1759) #
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 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]
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1761) #
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1762)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1763) hist_data: 00000000a73b67df
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1764)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1765) n_vals: 2
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1766) n_keys: 1
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1767) n_fields: 3
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1768)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1769) val fields:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1770)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1771) hist_data->fields[0]:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1772) flags:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1773) VAL: HIST_FIELD_FL_HITCOUNT
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1774) type: u64
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1775) size: 8
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1776) is_signed: 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1777)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1778) hist_data->fields[1]:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1779) flags:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1780) HIST_FIELD_FL_VAR
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1781) var.name: wakeup_lat
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1782) var.idx (into tracing_map_elt.vars[]): 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1783) type: u64
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1784) size: 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1785) is_signed: 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1786)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1787) key fields:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1788)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1789) hist_data->fields[2]:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1790) flags:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1791) HIST_FIELD_FL_KEY
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1792) ftrace_event_field name: next_pid
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1793) type: pid_t
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1794) size: 8
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1795) is_signed: 1
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1796)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1797) variable reference fields:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1798)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1799) hist_data->var_refs[0]:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1800) flags:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1801) HIST_FIELD_FL_VAR_REF
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1802) name: ts0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1803) var.idx (into tracing_map_elt.vars[]): 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1804) var.hist_data: 00000000349570e4
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1805) var_ref_idx (into hist_data->var_refs[]): 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1806) type: u64
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1807) size: 8
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1808) is_signed: 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1809)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1810) hist_data->var_refs[1]:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1811) flags:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1812) HIST_FIELD_FL_VAR_REF
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1813) name: wakeup_lat
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1814) var.idx (into tracing_map_elt.vars[]): 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1815) var.hist_data: 00000000a73b67df
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1816) var_ref_idx (into hist_data->var_refs[]): 1
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1817) type: u64
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1818) size: 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1819) is_signed: 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1820)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1821) hist_data->var_refs[2]:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1822) flags:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1823) HIST_FIELD_FL_VAR_REF
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1824) name: next_pid
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1825) var.idx (into tracing_map_elt.vars[]): 1
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1826) var.hist_data: 00000000a73b67df
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1827) var_ref_idx (into hist_data->var_refs[]): 2
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1828) type: pid_t
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1829) size: 4
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1830) is_signed: 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1831)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1832) hist_data->var_refs[3]:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1833) flags:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1834) HIST_FIELD_FL_VAR_REF
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1835) name: synthetic_prio
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1836) var.idx (into tracing_map_elt.vars[]): 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1837) var.hist_data: 000000006920cf38
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1838) var_ref_idx (into hist_data->var_refs[]): 3
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1839) type: int
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1840) size: 4
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1841) is_signed: 1
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1842)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1843) field variables:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1844)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1845) hist_data->field_vars[0]:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1846)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1847) field_vars[0].var:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1848) flags:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1849) HIST_FIELD_FL_VAR
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1850) var.name: next_pid
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1851) var.idx (into tracing_map_elt.vars[]): 1
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1852)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1853) field_vars[0].val:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1854) ftrace_event_field name: next_pid
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1855) type: pid_t
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1856) size: 4
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1857) is_signed: 1
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1858)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1859) action tracking variables (for onmax()/onchange()/onmatch()):
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1860)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1861) hist_data->actions[0].match_data.event_system: sched
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1862) hist_data->actions[0].match_data.event: sched_waking
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1863)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1864) The commands below can be used to clean things up for the next test::
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1865)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 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/trigger
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1867)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1868) # echo '!hist:keys=pid:ts0=common_timestamp.usecs' >> events/sched/sched_waking/trigger
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1869)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1870) # echo '!wakeup_latency u64 lat; pid_t pid; int prio' >> synthetic_events
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1871)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1872) Alias test
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1873) ----------
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1874)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1875) This example is very similar to previous examples, but demonstrates
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1876) the alias flag.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1877)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1878) First, we create the wakeup_latency synthetic event::
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1879)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1880) # echo 'wakeup_latency u64 lat; pid_t pid; char comm[16]' >> synthetic_events
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1881)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1882) Next, we create a sched_waking trigger similar to previous examples,
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1883) but in this case we save the pid in the waking_pid variable::
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1884)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1885) # echo 'hist:keys=pid:waking_pid=pid:ts0=common_timestamp.usecs' >> events/sched/sched_waking/trigger
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1886)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1887) For the sched_switch trigger, instead of using $waking_pid directly in
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1888) the wakeup_latency synthetic event invocation, we create an alias of
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1889) $waking_pid named $woken_pid, and use that in the synthetic event
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1890) invocation instead::
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1891)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 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/trigger
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1893)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1894) Looking at the sched_waking hist_debug output, in addition to the
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1895) normal fields, we can see the waking_pid variable::
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1896)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1897) # cat events/sched/sched_waking/hist_debug
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1898)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1899) # event histogram
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1900) #
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1901) # trigger info: hist:keys=pid:vals=hitcount:waking_pid=pid,ts0=common_timestamp.usecs:sort=hitcount:size=2048:clock=global [active]
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1902) #
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1903)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1904) hist_data: 00000000a250528c
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1905)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1906) n_vals: 3
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1907) n_keys: 1
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1908) n_fields: 4
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1909)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1910) val fields:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1911)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1912) hist_data->fields[0]:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1913) flags:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1914) VAL: HIST_FIELD_FL_HITCOUNT
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1915) type: u64
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1916) size: 8
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1917) is_signed: 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1918)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1919) hist_data->fields[1]:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1920) flags:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1921) HIST_FIELD_FL_VAR
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1922) ftrace_event_field name: pid
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1923) var.name: waking_pid
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1924) var.idx (into tracing_map_elt.vars[]): 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1925) type: pid_t
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1926) size: 4
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1927) is_signed: 1
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1928)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1929) hist_data->fields[2]:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1930) flags:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1931) HIST_FIELD_FL_VAR
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1932) var.name: ts0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1933) var.idx (into tracing_map_elt.vars[]): 1
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1934) type: u64
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1935) size: 8
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1936) is_signed: 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1937)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1938) key fields:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1939)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1940) hist_data->fields[3]:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1941) flags:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1942) HIST_FIELD_FL_KEY
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1943) ftrace_event_field name: pid
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1944) type: pid_t
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1945) size: 8
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1946) is_signed: 1
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1947)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1948) The sched_switch hist_debug output shows that a variable named
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1949) woken_pid has been created but that it also has the
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1950) HIST_FIELD_FL_ALIAS flag set. It also has the HIST_FIELD_FL_VAR flag
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1951) set, which is why it appears in the val field section.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1952)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1953) Despite that implementation detail, an alias variable is actually more
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1954) like a variable reference; in fact it can be thought of as a reference
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1955) to a reference. The implementation copies the var_ref->fn() from the
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1956) variable reference being referenced, in this case, the waking_pid
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1957) fn(), which is hist_field_var_ref() and makes that the fn() of the
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1958) alias. The hist_field_var_ref() fn() requires the var_ref_idx of the
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1959) variable reference it's using, so waking_pid's var_ref_idx is also
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1960) copied to the alias. The end result is that when the value of alias
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1961) is retrieved, in the end it just does the same thing the original
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1962) reference would have done and retrieves the same value from the
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1963) var_ref_vals[] array. You can verify this in the output by noting
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1964) that the var_ref_idx of the alias, in this case woken_pid, is the same
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1965) as the var_ref_idx of the reference, waking_pid, in the variable
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1966) reference fields section.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1967)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1968) Additionally, once it gets that value, since it is also a variable, it
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1969) then saves that value into its var.idx. So the var.idx of the
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1970) woken_pid alias is 0, which it fills with the value from var_ref_idx 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1971) when its fn() is called to update itself. You'll also notice that
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1972) there's a woken_pid var_ref in the variable refs section. That is the
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1973) reference to the woken_pid alias variable, and you can see that it
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1974) retrieves the value from the same var.idx as the woken_pid alias, 0,
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1975) and then in turn saves that value in its own var_ref_idx slot, 3, and
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1976) the value at this position is finally what gets assigned to the
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1977) $woken_pid slot in the trace event invocation::
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1978)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1979) # cat events/sched/sched_switch/hist_debug
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1980)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1981) # event histogram
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1982) #
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 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]
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1984) #
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1985)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1986) hist_data: 0000000055d65ed0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1987)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1988) n_vals: 3
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1989) n_keys: 1
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1990) n_fields: 4
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1991)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1992) val fields:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1993)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1994) hist_data->fields[0]:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1995) flags:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1996) VAL: HIST_FIELD_FL_HITCOUNT
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1997) type: u64
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1998) size: 8
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1999) is_signed: 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2000)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2001) hist_data->fields[1]:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2002) flags:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2003) HIST_FIELD_FL_VAR
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2004) HIST_FIELD_FL_ALIAS
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2005) var.name: woken_pid
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2006) var.idx (into tracing_map_elt.vars[]): 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2007) var_ref_idx (into hist_data->var_refs[]): 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2008) type: pid_t
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2009) size: 4
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2010) is_signed: 1
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2011)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2012) hist_data->fields[2]:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2013) flags:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2014) HIST_FIELD_FL_VAR
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2015) var.name: wakeup_lat
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2016) var.idx (into tracing_map_elt.vars[]): 1
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2017) type: u64
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2018) size: 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2019) is_signed: 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2020)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2021) key fields:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2022)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2023) hist_data->fields[3]:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2024) flags:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2025) HIST_FIELD_FL_KEY
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2026) ftrace_event_field name: next_pid
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2027) type: pid_t
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2028) size: 8
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2029) is_signed: 1
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2030)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2031) variable reference fields:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2032)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2033) hist_data->var_refs[0]:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2034) flags:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2035) HIST_FIELD_FL_VAR_REF
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2036) name: waking_pid
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2037) var.idx (into tracing_map_elt.vars[]): 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2038) var.hist_data: 00000000a250528c
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2039) var_ref_idx (into hist_data->var_refs[]): 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2040) type: pid_t
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2041) size: 4
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2042) is_signed: 1
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2043)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2044) hist_data->var_refs[1]:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2045) flags:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2046) HIST_FIELD_FL_VAR_REF
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2047) name: ts0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2048) var.idx (into tracing_map_elt.vars[]): 1
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2049) var.hist_data: 00000000a250528c
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2050) var_ref_idx (into hist_data->var_refs[]): 1
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2051) type: u64
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2052) size: 8
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2053) is_signed: 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2054)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2055) hist_data->var_refs[2]:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2056) flags:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2057) HIST_FIELD_FL_VAR_REF
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2058) name: wakeup_lat
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2059) var.idx (into tracing_map_elt.vars[]): 1
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2060) var.hist_data: 0000000055d65ed0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2061) var_ref_idx (into hist_data->var_refs[]): 2
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2062) type: u64
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2063) size: 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2064) is_signed: 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2065)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2066) hist_data->var_refs[3]:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2067) flags:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2068) HIST_FIELD_FL_VAR_REF
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2069) name: woken_pid
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2070) var.idx (into tracing_map_elt.vars[]): 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2071) var.hist_data: 0000000055d65ed0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2072) var_ref_idx (into hist_data->var_refs[]): 3
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2073) type: pid_t
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2074) size: 4
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2075) is_signed: 1
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2076)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2077) hist_data->var_refs[4]:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2078) flags:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2079) HIST_FIELD_FL_VAR_REF
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2080) name: next_comm
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2081) var.idx (into tracing_map_elt.vars[]): 2
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2082) var.hist_data: 0000000055d65ed0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2083) var_ref_idx (into hist_data->var_refs[]): 4
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2084) type: char[16]
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2085) size: 256
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2086) is_signed: 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2087)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2088) field variables:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2089)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2090) hist_data->field_vars[0]:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2091)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2092) field_vars[0].var:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2093) flags:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2094) HIST_FIELD_FL_VAR
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2095) var.name: next_comm
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2096) var.idx (into tracing_map_elt.vars[]): 2
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2097)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2098) field_vars[0].val:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2099) ftrace_event_field name: next_comm
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2100) type: char[16]
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2101) size: 256
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2102) is_signed: 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2103)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2104) action tracking variables (for onmax()/onchange()/onmatch()):
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2105)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2106) hist_data->actions[0].match_data.event_system: sched
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2107) hist_data->actions[0].match_data.event: sched_waking
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2108)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2109) The commands below can be used to clean things up for the next test::
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2110)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 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/trigger
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2112)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2113) # echo '!hist:keys=pid:ts0=common_timestamp.usecs' >> events/sched/sched_waking/trigger
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2114)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2115) # echo '!wakeup_latency u64 lat; pid_t pid; char comm[16]' >> synthetic_events
Orange Pi5 kernel
Deprecated Linux kernel 5.10.110 for OrangePi 5/5B/5+ boards
3 Commits
0 Branches
0 Tags