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

Configure Feed

Select the types of activity you want to include in your feed.

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