diff options
Diffstat (limited to 'Documentation/trace/histogram.txt')
| -rw-r--r-- | Documentation/trace/histogram.txt | 570 |
1 files changed, 557 insertions, 13 deletions
diff --git a/Documentation/trace/histogram.txt b/Documentation/trace/histogram.txt index 6e05510afc28..7ffea6aa22e3 100644 --- a/Documentation/trace/histogram.txt +++ b/Documentation/trace/histogram.txt @@ -7,7 +7,7 @@ Histogram triggers are special event triggers that can be used to aggregate trace event data into histograms. For information on - trace events and event triggers, see Documentation/trace/events.txt. + trace events and event triggers, see Documentation/trace/events.rst. 2. Histogram Trigger Command @@ -1604,7 +1604,6 @@ Entries: 7 Dropped: 0 - 2.2 Inter-event hist triggers ----------------------------- @@ -1730,35 +1729,35 @@ If a variable isn't a key variable or prefixed with 'vals=', the associated event field will be saved in a variable but won't be summed as a value: - # echo 'hist:keys=next_pid:ts1=common_timestamp ... >> event/trigger + # echo 'hist:keys=next_pid:ts1=common_timestamp ...' >> event/trigger Multiple variables can be assigned at the same time. The below would result in both ts0 and b being created as variables, with both common_timestamp and field1 additionally being summed as values: - # echo 'hist:keys=pid:vals=$ts0,$b:ts0=common_timestamp,b=field1 ... >> \ + # echo 'hist:keys=pid:vals=$ts0,$b:ts0=common_timestamp,b=field1 ...' >> \ event/trigger Note that variable assignments can appear either preceding or following their use. The command below behaves identically to the command above: - # echo 'hist:keys=pid:ts0=common_timestamp,b=field1:vals=$ts0,$b ... >> \ + # echo 'hist:keys=pid:ts0=common_timestamp,b=field1:vals=$ts0,$b ...' >> \ event/trigger Any number of variables not bound to a 'vals=' prefix can also be assigned by simply separating them with colons. Below is the same thing but without the values being summed in the histogram: - # echo 'hist:keys=pid:ts0=common_timestamp:b=field1 ... >> event/trigger + # echo 'hist:keys=pid:ts0=common_timestamp:b=field1 ...' >> event/trigger Variables set as above can be referenced and used in expressions on another event. For example, here's how a latency can be calculated: - # echo 'hist:keys=pid,prio:ts0=common_timestamp ... >> event1/trigger - # echo 'hist:keys=next_pid:wakeup_lat=common_timestamp-$ts0 ... >> event2/trigger + # echo 'hist:keys=pid,prio:ts0=common_timestamp ...' >> event1/trigger + # echo 'hist:keys=next_pid:wakeup_lat=common_timestamp-$ts0 ...' >> event2/trigger In the first line above, the event's timetamp is saved into the variable ts0. In the next line, ts0 is subtracted from the second @@ -1767,7 +1766,7 @@ yet another variable, 'wakeup_lat'. The hist trigger below in turn makes use of the wakeup_lat variable to compute a combined latency using the same key and variable from yet another event: - # echo 'hist:key=pid:wakeupswitch_lat=$wakeup_lat+$switchtime_lat ... >> event3/trigger + # echo 'hist:key=pid:wakeupswitch_lat=$wakeup_lat+$switchtime_lat ...' >> event3/trigger 2.2.2 Synthetic Events ---------------------- @@ -1808,10 +1807,11 @@ the command that defined it with a '!': At this point, there isn't yet an actual 'wakeup_latency' event instantiated in the event subsytem - for this to happen, a 'hist trigger action' needs to be instantiated and bound to actual fields -and variables defined on other events (see Section 6.3.3 below). +and variables defined on other events (see Section 2.2.3 below on +how that is done using hist trigger 'onmatch' action). Once that is +done, the 'wakeup_latency' synthetic event instance is created. -Once that is done, an event instance is created, and a histogram can -be defined using it: +A histogram can now be defined for the new synthetic event: # echo 'hist:keys=pid,prio,lat.log2:sort=pid,lat' >> \ /sys/kernel/debug/tracing/events/synthetic/wakeup_latency/trigger @@ -1961,7 +1961,7 @@ hist trigger specification. back to that pid, the timestamp difference is calculated. If the resulting latency, stored in wakeup_lat, exceeds the current maximum latency, the values specified in the save() fields are - recoreded: + recorded: # echo 'hist:keys=pid:ts0=common_timestamp.usecs \ if comm=="cyclictest"' >> \ @@ -1993,3 +1993,547 @@ hist trigger specification. Hits: 12970 Entries: 2 Dropped: 0 + +3. User space creating a trigger +-------------------------------- + +Writing into /sys/kernel/tracing/trace_marker writes into the ftrace +ring buffer. This can also act like an event, by writing into the trigger +file located in /sys/kernel/tracing/events/ftrace/print/ + +Modifying cyclictest to write into the trace_marker file before it sleeps +and after it wakes up, something like this: + +static void traceputs(char *str) +{ + /* tracemark_fd is the trace_marker file descriptor */ + if (tracemark_fd < 0) + return; + /* write the tracemark message */ + write(tracemark_fd, str, strlen(str)); +} + +And later add something like: + + traceputs("start"); + clock_nanosleep(...); + traceputs("end"); + +We can make a histogram from this: + + # cd /sys/kernel/tracing + # echo 'latency u64 lat' > synthetic_events + # echo 'hist:keys=common_pid:ts0=common_timestamp.usecs if buf == "start"' > events/ftrace/print/trigger + # echo 'hist:keys=common_pid:lat=common_timestamp.usecs-$ts0:onmatch(ftrace.print).latency($lat) if buf == "end"' >> events/ftrace/print/trigger + # echo 'hist:keys=lat,common_pid:sort=lat' > events/synthetic/latency/trigger + +The above created a synthetic event called "latency" and two histograms +against the trace_marker, one gets triggered when "start" is written into the +trace_marker file and the other when "end" is written. If the pids match, then +it will call the "latency" synthetic event with the calculated latency as its +parameter. Finally, a histogram is added to the latency synthetic event to +record the calculated latency along with the pid. + +Now running cyclictest with: + + # ./cyclictest -p80 -d0 -i250 -n -a -t --tracemark -b 1000 + + -p80 : run threads at priority 80 + -d0 : have all threads run at the same interval + -i250 : start the interval at 250 microseconds (all threads will do this) + -n : sleep with nanosleep + -a : affine all threads to a separate CPU + -t : one thread per available CPU + --tracemark : enable trace mark writing + -b 1000 : stop if any latency is greater than 1000 microseconds + +Note, the -b 1000 is used just to make --tracemark available. + +Then we can see the histogram created by this with: + + # cat events/synthetic/latency/hist +# event histogram +# +# trigger info: hist:keys=lat,common_pid:vals=hitcount:sort=lat:size=2048 [active] +# + +{ lat: 107, common_pid: 2039 } hitcount: 1 +{ lat: 122, common_pid: 2041 } hitcount: 1 +{ lat: 166, common_pid: 2039 } hitcount: 1 +{ lat: 174, common_pid: 2039 } hitcount: 1 +{ lat: 194, common_pid: 2041 } hitcount: 1 +{ lat: 196, common_pid: 2036 } hitcount: 1 +{ lat: 197, common_pid: 2038 } hitcount: 1 +{ lat: 198, common_pid: 2039 } hitcount: 1 +{ lat: 199, common_pid: 2039 } hitcount: 1 +{ lat: 200, common_pid: 2041 } hitcount: 1 +{ lat: 201, common_pid: 2039 } hitcount: 2 +{ lat: 202, common_pid: 2038 } hitcount: 1 +{ lat: 202, common_pid: 2043 } hitcount: 1 +{ lat: 203, common_pid: 2039 } hitcount: 1 +{ lat: 203, common_pid: 2036 } hitcount: 1 +{ lat: 203, common_pid: 2041 } hitcount: 1 +{ lat: 206, common_pid: 2038 } hitcount: 2 +{ lat: 207, common_pid: 2039 } hitcount: 1 +{ lat: 207, common_pid: 2036 } hitcount: 1 +{ lat: 208, common_pid: 2040 } hitcount: 1 +{ lat: 209, common_pid: 2043 } hitcount: 1 +{ lat: 210, common_pid: 2039 } hitcount: 1 +{ lat: 211, common_pid: 2039 } hitcount: 4 +{ lat: 212, common_pid: 2043 } hitcount: 1 +{ lat: 212, common_pid: 2039 } hitcount: 2 +{ lat: 213, common_pid: 2039 } hitcount: 1 +{ lat: 214, common_pid: 2038 } hitcount: 1 +{ lat: 214, common_pid: 2039 } hitcount: 2 +{ lat: 214, common_pid: 2042 } hitcount: 1 +{ lat: 215, common_pid: 2039 } hitcount: 1 +{ lat: 217, common_pid: 2036 } hitcount: 1 +{ lat: 217, common_pid: 2040 } hitcount: 1 +{ lat: 217, common_pid: 2039 } hitcount: 1 +{ lat: 218, common_pid: 2039 } hitcount: 6 +{ lat: 219, common_pid: 2039 } hitcount: 9 +{ lat: 220, common_pid: 2039 } hitcount: 11 +{ lat: 221, common_pid: 2039 } hitcount: 5 +{ lat: 221, common_pid: 2042 } hitcount: 1 +{ lat: 222, common_pid: 2039 } hitcount: 7 +{ lat: 223, common_pid: 2036 } hitcount: 1 +{ lat: 223, common_pid: 2039 } hitcount: 3 +{ lat: 224, common_pid: 2039 } hitcount: 4 +{ lat: 224, common_pid: 2037 } hitcount: 1 +{ lat: 224, common_pid: 2036 } hitcount: 2 +{ lat: 225, common_pid: 2039 } hitcount: 5 +{ lat: 225, common_pid: 2042 } hitcount: 1 +{ lat: 226, common_pid: 2039 } hitcount: 7 +{ lat: 226, common_pid: 2036 } hitcount: 4 +{ lat: 227, common_pid: 2039 } hitcount: 6 +{ lat: 227, common_pid: 2036 } hitcount: 12 +{ lat: 227, common_pid: 2043 } hitcount: 1 +{ lat: 228, common_pid: 2039 } hitcount: 7 +{ lat: 228, common_pid: 2036 } hitcount: 14 +{ lat: 229, common_pid: 2039 } hitcount: 9 +{ lat: 229, common_pid: 2036 } hitcount: 8 +{ lat: 229, common_pid: 2038 } hitcount: 1 +{ lat: 230, common_pid: 2039 } hitcount: 11 +{ lat: 230, common_pid: 2036 } hitcount: 6 +{ lat: 230, common_pid: 2043 } hitcount: 1 +{ lat: 230, common_pid: 2042 } hitcount: 2 +{ lat: 231, common_pid: 2041 } hitcount: 1 +{ lat: 231, common_pid: 2036 } hitcount: 6 +{ lat: 231, common_pid: 2043 } hitcount: 1 +{ lat: 231, common_pid: 2039 } hitcount: 8 +{ lat: 232, common_pid: 2037 } hitcount: 1 +{ lat: 232, common_pid: 2039 } hitcount: 6 +{ lat: 232, common_pid: 2040 } hitcount: 2 +{ lat: 232, common_pid: 2036 } hitcount: 5 +{ lat: 232, common_pid: 2043 } hitcount: 1 +{ lat: 233, common_pid: 2036 } hitcount: 5 +{ lat: 233, common_pid: 2039 } hitcount: 11 +{ lat: 234, common_pid: 2039 } hitcount: 4 +{ lat: 234, common_pid: 2038 } hitcount: 2 +{ lat: 234, common_pid: 2043 } hitcount: 2 +{ lat: 234, common_pid: 2036 } hitcount: 11 +{ lat: 234, common_pid: 2040 } hitcount: 1 +{ lat: 235, common_pid: 2037 } hitcount: 2 +{ lat: 235, common_pid: 2036 } hitcount: 8 +{ lat: 235, common_pid: 2043 } hitcount: 2 +{ lat: 235, common_pid: 2039 } hitcount: 5 +{ lat: 235, common_pid: 2042 } hitcount: 2 +{ lat: 235, common_pid: 2040 } hitcount: 4 +{ lat: 235, common_pid: 2041 } hitcount: 1 +{ lat: 236, common_pid: 2036 } hitcount: 7 +{ lat: 236, common_pid: 2037 } hitcount: 1 +{ lat: 236, common_pid: 2041 } hitcount: 5 +{ lat: 236, common_pid: 2039 } hitcount: 3 +{ lat: 236, common_pid: 2043 } hitcount: 9 +{ lat: 236, common_pid: 2040 } hitcount: 7 +{ lat: 237, common_pid: 2037 } hitcount: 1 +{ lat: 237, common_pid: 2040 } hitcount: 1 +{ lat: 237, common_pid: 2036 } hitcount: 9 +{ lat: 237, common_pid: 2039 } hitcount: 3 +{ lat: 237, common_pid: 2043 } hitcount: 8 +{ lat: 237, common_pid: 2042 } hitcount: 2 +{ lat: 237, common_pid: 2041 } hitcount: 2 +{ lat: 238, common_pid: 2043 } hitcount: 10 +{ lat: 238, common_pid: 2040 } hitcount: 1 +{ lat: 238, common_pid: 2037 } hitcount: 9 +{ lat: 238, common_pid: 2038 } hitcount: 1 +{ lat: 238, common_pid: 2039 } hitcount: 1 +{ lat: 238, common_pid: 2042 } hitcount: 3 +{ lat: 238, common_pid: 2036 } hitcount: 7 +{ lat: 239, common_pid: 2041 } hitcount: 1 +{ lat: 239, common_pid: 2043 } hitcount: 11 +{ lat: 239, common_pid: 2037 } hitcount: 11 +{ lat: 239, common_pid: 2038 } hitcount: 6 +{ lat: 239, common_pid: 2036 } hitcount: 7 +{ lat: 239, common_pid: 2040 } hitcount: 1 +{ lat: 239, common_pid: 2042 } hitcount: 9 +{ lat: 240, common_pid: 2037 } hitcount: 29 +{ lat: 240, common_pid: 2043 } hitcount: 15 +{ lat: 240, common_pid: 2040 } hitcount: 44 +{ lat: 240, common_pid: 2039 } hitcount: 1 +{ lat: 240, common_pid: 2041 } hitcount: 2 +{ lat: 240, common_pid: 2038 } hitcount: 1 +{ lat: 240, common_pid: 2036 } hitcount: 10 +{ lat: 240, common_pid: 2042 } hitcount: 13 +{ lat: 241, common_pid: 2036 } hitcount: 21 +{ lat: 241, common_pid: 2041 } hitcount: 36 +{ lat: 241, common_pid: 2037 } hitcount: 34 +{ lat: 241, common_pid: 2042 } hitcount: 14 +{ lat: 241, common_pid: 2040 } hitcount: 94 +{ lat: 241, common_pid: 2039 } hitcount: 12 +{ lat: 241, common_pid: 2038 } hitcount: 2 +{ lat: 241, common_pid: 2043 } hitcount: 28 +{ lat: 242, common_pid: 2040 } hitcount: 109 +{ lat: 242, common_pid: 2041 } hitcount: 506 +{ lat: 242, common_pid: 2039 } hitcount: 155 +{ lat: 242, common_pid: 2042 } hitcount: 21 +{ lat: 242, common_pid: 2037 } hitcount: 52 +{ lat: 242, common_pid: 2043 } hitcount: 21 +{ lat: 242, common_pid: 2036 } hitcount: 16 +{ lat: 242, common_pid: 2038 } hitcount: 156 +{ lat: 243, common_pid: 2037 } hitcount: 46 +{ lat: 243, common_pid: 2039 } hitcount: 40 +{ lat: 243, common_pid: 2042 } hitcount: 119 +{ lat: 243, common_pid: 2041 } hitcount: 611 +{ lat: 243, common_pid: 2036 } hitcount: 69 +{ lat: 243, common_pid: 2038 } hitcount: 784 +{ lat: 243, common_pid: 2040 } hitcount: 323 +{ lat: 243, common_pid: 2043 } hitcount: 14 +{ lat: 244, common_pid: 2043 } hitcount: 35 +{ lat: 244, common_pid: 2042 } hitcount: 305 +{ lat: 244, common_pid: 2039 } hitcount: 8 +{ lat: 244, common_pid: 2040 } hitcount: 4515 +{ lat: 244, common_pid: 2038 } hitcount: 371 +{ lat: 244, common_pid: 2037 } hitcount: 31 +{ lat: 244, common_pid: 2036 } hitcount: 114 +{ lat: 244, common_pid: 2041 } hitcount: 3396 +{ lat: 245, common_pid: 2036 } hitcount: 700 +{ lat: 245, common_pid: 2041 } hitcount: 2772 +{ lat: 245, common_pid: 2037 } hitcount: 268 +{ lat: 245, common_pid: 2039 } hitcount: 472 +{ lat: 245, common_pid: 2038 } hitcount: 2758 +{ lat: 245, common_pid: 2042 } hitcount: 3833 +{ lat: 245, common_pid: 2040 } hitcount: 3105 +{ lat: 245, common_pid: 2043 } hitcount: 645 +{ lat: 246, common_pid: 2038 } hitcount: 3451 +{ lat: 246, common_pid: 2041 } hitcount: 142 +{ lat: 246, common_pid: 2037 } hitcount: 5101 +{ lat: 246, common_pid: 2040 } hitcount: 68 +{ lat: 246, common_pid: 2043 } hitcount: 5099 +{ lat: 246, common_pid: 2039 } hitcount: 5608 +{ lat: 246, common_pid: 2042 } hitcount: 3723 +{ lat: 246, common_pid: 2036 } hitcount: 4738 +{ lat: 247, common_pid: 2042 } hitcount: 312 +{ lat: 247, common_pid: 2043 } hitcount: 2385 +{ lat: 247, common_pid: 2041 } hitcount: 452 +{ lat: 247, common_pid: 2038 } hitcount: 792 +{ lat: 247, common_pid: 2040 } hitcount: 78 +{ lat: 247, common_pid: 2036 } hitcount: 2375 +{ lat: 247, common_pid: 2039 } hitcount: 1834 +{ lat: 247, common_pid: 2037 } hitcount: 2655 +{ lat: 248, common_pid: 2037 } hitcount: 36 +{ lat: 248, common_pid: 2042 } hitcount: 11 +{ lat: 248, common_pid: 2038 } hitcount: 122 +{ lat: 248, common_pid: 2036 } hitcount: 135 +{ lat: 248, common_pid: 2039 } hitcount: 26 +{ lat: 248, common_pid: 2041 } hitcount: 503 +{ lat: 248, common_pid: 2043 } hitcount: 66 +{ lat: 248, common_pid: 2040 } hitcount: 46 +{ lat: 249, common_pid: 2037 } hitcount: 29 +{ lat: 249, common_pid: 2038 } hitcount: 1 +{ lat: 249, common_pid: 2043 } hitcount: 29 +{ lat: 249, common_pid: 2039 } hitcount: 8 +{ lat: 249, common_pid: 2042 } hitcount: 56 +{ lat: 249, common_pid: 2040 } hitcount: 27 +{ lat: 249, common_pid: 2041 } hitcount: 11 +{ lat: 249, common_pid: 2036 } hitcount: 27 +{ lat: 250, common_pid: 2038 } hitcount: 1 +{ lat: 250, common_pid: 2036 } hitcount: 30 +{ lat: 250, common_pid: 2040 } hitcount: 19 +{ lat: 250, common_pid: 2043 } hitcount: 22 +{ lat: 250, common_pid: 2042 } hitcount: 20 +{ lat: 250, common_pid: 2041 } hitcount: 1 +{ lat: 250, common_pid: 2039 } hitcount: 6 +{ lat: 250, common_pid: 2037 } hitcount: 48 +{ lat: 251, common_pid: 2037 } hitcount: 43 +{ lat: 251, common_pid: 2039 } hitcount: 1 +{ lat: 251, common_pid: 2036 } hitcount: 12 +{ lat: 251, common_pid: 2042 } hitcount: 2 +{ lat: 251, common_pid: 2041 } hitcount: 1 +{ lat: 251, common_pid: 2043 } hitcount: 15 +{ lat: 251, common_pid: 2040 } hitcount: 3 +{ lat: 252, common_pid: 2040 } hitcount: 1 +{ lat: 252, common_pid: 2036 } hitcount: 12 +{ lat: 252, common_pid: 2037 } hitcount: 21 +{ lat: 252, common_pid: 2043 } hitcount: 14 +{ lat: 253, common_pid: 2037 } hitcount: 21 +{ lat: 253, common_pid: 2039 } hitcount: 2 +{ lat: 253, common_pid: 2036 } hitcount: 9 +{ lat: 253, common_pid: 2043 } hitcount: 6 +{ lat: 253, common_pid: 2040 } hitcount: 1 +{ lat: 254, common_pid: 2036 } hitcount: 8 +{ lat: 254, common_pid: 2043 } hitcount: 3 +{ lat: 254, common_pid: 2041 } hitcount: 1 +{ lat: 254, common_pid: 2042 } hitcount: 1 +{ lat: 254, common_pid: 2039 } hitcount: 1 +{ lat: 254, common_pid: 2037 } hitcount: 12 +{ lat: 255, common_pid: 2043 } hitcount: 1 +{ lat: 255, common_pid: 2037 } hitcount: 2 +{ lat: 255, common_pid: 2036 } hitcount: 2 +{ lat: 255, common_pid: 2039 } hitcount: 8 +{ lat: 256, common_pid: 2043 } hitcount: 1 +{ lat: 256, common_pid: 2036 } hitcount: 4 +{ lat: 256, common_pid: 2039 } hitcount: 6 +{ lat: 257, common_pid: 2039 } hitcount: 5 +{ lat: 257, common_pid: 2036 } hitcount: 4 +{ lat: 258, common_pid: 2039 } hitcount: 5 +{ lat: 258, common_pid: 2036 } hitcount: 2 +{ lat: 259, common_pid: 2036 } hitcount: 7 +{ lat: 259, common_pid: 2039 } hitcount: 7 +{ lat: 260, common_pid: 2036 } hitcount: 8 +{ lat: 260, common_pid: 2039 } hitcount: 6 +{ lat: 261, common_pid: 2036 } hitcount: 5 +{ lat: 261, common_pid: 2039 } hitcount: 7 +{ lat: 262, common_pid: 2039 } hitcount: 5 +{ lat: 262, common_pid: 2036 } hitcount: 5 +{ lat: 263, common_pid: 2039 } hitcount: 7 +{ lat: 263, common_pid: 2036 } hitcount: 7 +{ lat: 264, common_pid: 2039 } hitcount: 9 +{ lat: 264, common_pid: 2036 } hitcount: 9 +{ lat: 265, common_pid: 2036 } hitcount: 5 +{ lat: 265, common_pid: 2039 } hitcount: 1 +{ lat: 266, common_pid: 2036 } hitcount: 1 +{ lat: 266, common_pid: 2039 } hitcount: 3 +{ lat: 267, common_pid: 2036 } hitcount: 1 +{ lat: 267, common_pid: 2039 } hitcount: 3 +{ lat: 268, common_pid: 2036 } hitcount: 1 +{ lat: 268, common_pid: 2039 } hitcount: 6 +{ lat: 269, common_pid: 2036 } hitcount: 1 +{ lat: 269, common_pid: 2043 } hitcount: 1 +{ lat: 269, common_pid: 2039 } hitcount: 2 +{ lat: 270, common_pid: 2040 } hitcount: 1 +{ lat: 270, common_pid: 2039 } hitcount: 6 +{ lat: 271, common_pid: 2041 } hitcount: 1 +{ lat: 271, common_pid: 2039 } hitcount: 5 +{ lat: 272, common_pid: 2039 } hitcount: 10 +{ lat: 273, common_pid: 2039 } hitcount: 8 +{ lat: 274, common_pid: 2039 } hitcount: 2 +{ lat: 275, common_pid: 2039 } hitcount: 1 +{ lat: 276, common_pid: 2039 } hitcount: 2 +{ lat: 276, common_pid: 2037 } hitcount: 1 +{ lat: 276, common_pid: 2038 } hitcount: 1 +{ lat: 277, common_pid: 2039 } hitcount: 1 +{ lat: 277, common_pid: 2042 } hitcount: 1 +{ lat: 278, common_pid: 2039 } hitcount: 1 +{ lat: 279, common_pid: 2039 } hitcount: 4 +{ lat: 279, common_pid: 2043 } hitcount: 1 +{ lat: 280, common_pid: 2039 } hitcount: 3 +{ lat: 283, common_pid: 2036 } hitcount: 2 +{ lat: 284, common_pid: 2039 } hitcount: 1 +{ lat: 284, common_pid: 2043 } hitcount: 1 +{ lat: 288, common_pid: 2039 } hitcount: 1 +{ lat: 289, common_pid: 2039 } hitcount: 1 +{ lat: 300, common_pid: 2039 } hitcount: 1 +{ lat: 384, common_pid: 2039 } hitcount: 1 + +Totals: + Hits: 67625 + Entries: 278 + Dropped: 0 + +Note, the writes are around the sleep, so ideally they will all be of 250 +microseconds. If you are wondering how there are several that are under +250 microseconds, that is because the way cyclictest works, is if one +iteration comes in late, the next one will set the timer to wake up less that +250. That is, if an iteration came in 50 microseconds late, the next wake up +will be at 200 microseconds. + +But this could easily be done in userspace. To make this even more +interesting, we can mix the histogram between events that happened in the +kernel with trace_marker. + + # cd /sys/kernel/tracing + # echo 'latency u64 lat' > synthetic_events + # echo 'hist:keys=pid:ts0=common_timestamp.usecs' > events/sched/sched_waking/trigger + # echo 'hist:keys=common_pid:lat=common_timestamp.usecs-$ts0:onmatch(sched.sched_waking).latency($lat) if buf == "end"' > events/ftrace/print/trigger + # echo 'hist:keys=lat,common_pid:sort=lat' > events/synthetic/latency/trigger + +The difference this time is that instead of using the trace_marker to start +the latency, the sched_waking event is used, matching the common_pid for the +trace_marker write with the pid that is being woken by sched_waking. + +After running cyclictest again with the same parameters, we now have: + + # cat events/synthetic/latency/hist +# event histogram +# +# trigger info: hist:keys=lat,common_pid:vals=hitcount:sort=lat:size=2048 [active] +# + +{ lat: 7, common_pid: 2302 } hitcount: 640 +{ lat: 7, common_pid: 2299 } hitcount: 42 +{ lat: 7, common_pid: 2303 } hitcount: 18 +{ lat: 7, common_pid: 2305 } hitcount: 166 +{ lat: 7, common_pid: 2306 } hitcount: 1 +{ lat: 7, common_pid: 2301 } hitcount: 91 +{ lat: 7, common_pid: 2300 } hitcount: 17 +{ lat: 8, common_pid: 2303 } hitcount: 8296 +{ lat: 8, common_pid: 2304 } hitcount: 6864 +{ lat: 8, common_pid: 2305 } hitcount: 9464 +{ lat: 8, common_pid: 2301 } hitcount: 9213 +{ lat: 8, common_pid: 2306 } hitcount: 6246 +{ lat: 8, common_pid: 2302 } hitcount: 8797 +{ lat: 8, common_pid: 2299 } hitcount: 8771 +{ lat: 8, common_pid: 2300 } hitcount: 8119 +{ lat: 9, common_pid: 2305 } hitcount: 1519 +{ lat: 9, common_pid: 2299 } hitcount: 2346 +{ lat: 9, common_pid: 2303 } hitcount: 2841 +{ lat: 9, common_pid: 2301 } hitcount: 1846 +{ lat: 9, common_pid: 2304 } hitcount: 3861 +{ lat: 9, common_pid: 2302 } hitcount: 1210 +{ lat: 9, common_pid: 2300 } hitcount: 2762 +{ lat: 9, common_pid: 2306 } hitcount: 4247 +{ lat: 10, common_pid: 2299 } hitcount: 16 +{ lat: 10, common_pid: 2306 } hitcount: 333 +{ lat: 10, common_pid: 2303 } hitcount: 16 +{ lat: 10, common_pid: 2304 } hitcount: 168 +{ lat: 10, common_pid: 2302 } hitcount: 240 +{ lat: 10, common_pid: 2301 } hitcount: 28 +{ lat: 10, common_pid: 2300 } hitcount: 95 +{ lat: 10, common_pid: 2305 } hitcount: 18 +{ lat: 11, common_pid: 2303 } hitcount: 5 +{ lat: 11, common_pid: 2305 } hitcount: 8 +{ lat: 11, common_pid: 2306 } hitcount: 221 +{ lat: 11, common_pid: 2302 } hitcount: 76 +{ lat: 11, common_pid: 2304 } hitcount: 26 +{ lat: 11, common_pid: 2300 } hitcount: 125 +{ lat: 11, common_pid: 2299 } hitcount: 2 +{ lat: 12, common_pid: 2305 } hitcount: 3 +{ lat: 12, common_pid: 2300 } hitcount: 6 +{ lat: 12, common_pid: 2306 } hitcount: 90 +{ lat: 12, common_pid: 2302 } hitcount: 4 +{ lat: 12, common_pid: 2303 } hitcount: 1 +{ lat: 12, common_pid: 2304 } hitcount: 122 +{ lat: 13, common_pid: 2300 } hitcount: 12 +{ lat: 13, common_pid: 2301 } hitcount: 1 +{ lat: 13, common_pid: 2306 } hitcount: 32 +{ lat: 13, common_pid: 2302 } hitcount: 5 +{ lat: 13, common_pid: 2305 } hitcount: 1 +{ lat: 13, common_pid: 2303 } hitcount: 1 +{ lat: 13, common_pid: 2304 } hitcount: 61 +{ lat: 14, common_pid: 2303 } hitcount: 4 +{ lat: 14, common_pid: 2306 } hitcount: 5 +{ lat: 14, common_pid: 2305 } hitcount: 4 +{ lat: 14, common_pid: 2304 } hitcount: 62 +{ lat: 14, common_pid: 2302 } hitcount: 19 +{ lat: 14, common_pid: 2300 } hitcount: 33 +{ lat: 14, common_pid: 2299 } hitcount: 1 +{ lat: 14, common_pid: 2301 } hitcount: 4 +{ lat: 15, common_pid: 2305 } hitcount: 1 +{ lat: 15, common_pid: 2302 } hitcount: 25 +{ lat: 15, common_pid: 2300 } hitcount: 11 +{ lat: 15, common_pid: 2299 } hitcount: 5 +{ lat: 15, common_pid: 2301 } hitcount: 1 +{ lat: 15, common_pid: 2304 } hitcount: 8 +{ lat: 15, common_pid: 2303 } hitcount: 1 +{ lat: 15, common_pid: 2306 } hitcount: 6 +{ lat: 16, common_pid: 2302 } hitcount: 31 +{ lat: 16, common_pid: 2306 } hitcount: 3 +{ lat: 16, common_pid: 2300 } hitcount: 5 +{ lat: 17, common_pid: 2302 } hitcount: 6 +{ lat: 17, common_pid: 2303 } hitcount: 1 +{ lat: 18, common_pid: 2304 } hitcount: 1 +{ lat: 18, common_pid: 2302 } hitcount: 8 +{ lat: 18, common_pid: 2299 } hitcount: 1 +{ lat: 18, common_pid: 2301 } hitcount: 1 +{ lat: 19, common_pid: 2303 } hitcount: 4 +{ lat: 19, common_pid: 2304 } hitcount: 5 +{ lat: 19, common_pid: 2302 } hitcount: 4 +{ lat: 19, common_pid: 2299 } hitcount: 3 +{ lat: 19, common_pid: 2306 } hitcount: 1 +{ lat: 19, common_pid: 2300 } hitcount: 4 +{ lat: 19, common_pid: 2305 } hitcount: 5 +{ lat: 20, common_pid: 2299 } hitcount: 2 +{ lat: 20, common_pid: 2302 } hitcount: 3 +{ lat: 20, common_pid: 2305 } hitcount: 1 +{ lat: 20, common_pid: 2300 } hitcount: 2 +{ lat: 20, common_pid: 2301 } hitcount: 2 +{ lat: 20, common_pid: 2303 } hitcount: 3 +{ lat: 21, common_pid: 2305 } hitcount: 1 +{ lat: 21, common_pid: 2299 } hitcount: 5 +{ lat: 21, common_pid: 2303 } hitcount: 4 +{ lat: 21, common_pid: 2302 } hitcount: 7 +{ lat: 21, common_pid: 2300 } hitcount: 1 +{ lat: 21, common_pid: 2301 } hitcount: 5 +{ lat: 21, common_pid: 2304 } hitcount: 2 +{ lat: 22, common_pid: 2302 } hitcount: 5 +{ lat: 22, common_pid: 2303 } hitcount: 1 +{ lat: 22, common_pid: 2306 } hitcount: 3 +{ lat: 22, common_pid: 2301 } hitcount: 2 +{ lat: 22, common_pid: 2300 } hitcount: 1 +{ lat: 22, common_pid: 2299 } hitcount: 1 +{ lat: 22, common_pid: 2305 } hitcount: 1 +{ lat: 22, common_pid: 2304 } hitcount: 1 +{ lat: 23, common_pid: 2299 } hitcount: 1 +{ lat: 23, common_pid: 2306 } hitcount: 2 +{ lat: 23, common_pid: 2302 } hitcount: 6 +{ lat: 24, common_pid: 2302 } hitcount: 3 +{ lat: 24, common_pid: 2300 } hitcount: 1 +{ lat: 24, common_pid: 2306 } hitcount: 2 +{ lat: 24, common_pid: 2305 } hitcount: 1 +{ lat: 24, common_pid: 2299 } hitcount: 1 +{ lat: 25, common_pid: 2300 } hitcount: 1 +{ lat: 25, common_pid: 2302 } hitcount: 4 +{ lat: 26, common_pid: 2302 } hitcount: 2 +{ lat: 27, common_pid: 2305 } hitcount: 1 +{ lat: 27, common_pid: 2300 } hitcount: 1 +{ lat: 27, common_pid: 2302 } hitcount: 3 +{ lat: 28, common_pid: 2306 } hitcount: 1 +{ lat: 28, common_pid: 2302 } hitcount: 4 +{ lat: 29, common_pid: 2302 } hitcount: 1 +{ lat: 29, common_pid: 2300 } hitcount: 2 +{ lat: 29, common_pid: 2306 } hitcount: 1 +{ lat: 29, common_pid: 2304 } hitcount: 1 +{ lat: 30, common_pid: 2302 } hitcount: 4 +{ lat: 31, common_pid: 2302 } hitcount: 6 +{ lat: 32, common_pid: 2302 } hitcount: 1 +{ lat: 33, common_pid: 2299 } hitcount: 1 +{ lat: 33, common_pid: 2302 } hitcount: 3 +{ lat: 34, common_pid: 2302 } hitcount: 2 +{ lat: 35, common_pid: 2302 } hitcount: 1 +{ lat: 35, common_pid: 2304 } hitcount: 1 +{ lat: 36, common_pid: 2302 } hitcount: 4 +{ lat: 37, common_pid: 2302 } hitcount: 6 +{ lat: 38, common_pid: 2302 } hitcount: 2 +{ lat: 39, common_pid: 2302 } hitcount: 2 +{ lat: 39, common_pid: 2304 } hitcount: 1 +{ lat: 40, common_pid: 2304 } hitcount: 2 +{ lat: 40, common_pid: 2302 } hitcount: 5 +{ lat: 41, common_pid: 2304 } hitcount: 1 +{ lat: 41, common_pid: 2302 } hitcount: 8 +{ lat: 42, common_pid: 2302 } hitcount: 6 +{ lat: 42, common_pid: 2304 } hitcount: 1 +{ lat: 43, common_pid: 2302 } hitcount: 3 +{ lat: 43, common_pid: 2304 } hitcount: 4 +{ lat: 44, common_pid: 2302 } hitcount: 6 +{ lat: 45, common_pid: 2302 } hitcount: 5 +{ lat: 46, common_pid: 2302 } hitcount: 5 +{ lat: 47, common_pid: 2302 } hitcount: 7 +{ lat: 48, common_pid: 2301 } hitcount: 1 +{ lat: 48, common_pid: 2302 } hitcount: 9 +{ lat: 49, common_pid: 2302 } hitcount: 3 +{ lat: 50, common_pid: 2302 } hitcount: 1 +{ lat: 50, common_pid: 2301 } hitcount: 1 +{ lat: 51, common_pid: 2302 } hitcount: 2 +{ lat: 51, common_pid: 2301 } hitcount: 1 +{ lat: 61, common_pid: 2302 } hitcount: 1 +{ lat: 110, common_pid: 2302 } hitcount: 1 + +Totals: + Hits: 89565 + Entries: 158 + Dropped: 0 + +This doesn't tell us any information about how late cyclictest may have +woken up, but it does show us a nice histogram of how long it took from +the time that cyclictest was woken to the time it made it into user space. |