histogram-design.rst 87 KB

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