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