Linux kernel mirror (for testing)
git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git
kernel
os
linux
tracing: Have hwlat ts be first instance and record count of instances
The hwlat tracer runs a loop of width time during a given window. It then
reports the max latency over a given threshold and records a timestamp. But
this timestamp is the time after the width has finished, and not the time it
actually triggered.
Record the actual time when the latency was greater than the threshold as
well as the number of times it was greater in a given width per window.
Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
+44
-20
+22
-10
Documentation/trace/ftrace.rst
+22
-10
Documentation/trace/ftrace.rst
···
2126
2126
# cat trace
2127
2127
# tracer: hwlat
2128
2128
#
2129
+
# entries-in-buffer/entries-written: 13/13 #P:8
2130
+
#
2129
2131
# _-----=> irqs-off
2130
2132
# / _----=> need-resched
2131
2133
# | / _---=> hardirq/softirq
···
2135
2133
# ||| / delay
2136
2134
# TASK-PID CPU# |||| TIMESTAMP FUNCTION
2137
2135
# | | | |||| | |
2138
-
<...>-3638 [001] d... 19452.055471: #1 inner/outer(us): 12/14 ts:1499801089.066141940
2139
-
<...>-3638 [003] d... 19454.071354: #2 inner/outer(us): 11/9 ts:1499801091.082164365
2140
-
<...>-3638 [002] dn.. 19461.126852: #3 inner/outer(us): 12/9 ts:1499801098.138150062
2141
-
<...>-3638 [001] d... 19488.340960: #4 inner/outer(us): 8/12 ts:1499801125.354139633
2142
-
<...>-3638 [003] d... 19494.388553: #5 inner/outer(us): 8/12 ts:1499801131.402150961
2143
-
<...>-3638 [003] d... 19501.283419: #6 inner/outer(us): 0/12 ts:1499801138.297435289 nmi-total:4 nmi-count:1
2136
+
<...>-1729 [001] d... 678.473449: #1 inner/outer(us): 11/12 ts:1581527483.343962693 count:6
2137
+
<...>-1729 [004] d... 689.556542: #2 inner/outer(us): 16/9 ts:1581527494.889008092 count:1
2138
+
<...>-1729 [005] d... 714.756290: #3 inner/outer(us): 16/16 ts:1581527519.678961629 count:5
2139
+
<...>-1729 [001] d... 718.788247: #4 inner/outer(us): 9/17 ts:1581527523.889012713 count:1
2140
+
<...>-1729 [002] d... 719.796341: #5 inner/outer(us): 13/9 ts:1581527524.912872606 count:1
2141
+
<...>-1729 [006] d... 844.787091: #6 inner/outer(us): 9/12 ts:1581527649.889048502 count:2
2142
+
<...>-1729 [003] d... 849.827033: #7 inner/outer(us): 18/9 ts:1581527654.889013793 count:1
2143
+
<...>-1729 [007] d... 853.859002: #8 inner/outer(us): 9/12 ts:1581527658.889065736 count:1
2144
+
<...>-1729 [001] d... 855.874978: #9 inner/outer(us): 9/11 ts:1581527660.861991877 count:1
2145
+
<...>-1729 [001] d... 863.938932: #10 inner/outer(us): 9/11 ts:1581527668.970010500 count:1 nmi-total:7 nmi-count:1
2146
+
<...>-1729 [007] d... 878.050780: #11 inner/outer(us): 9/12 ts:1581527683.385002600 count:1 nmi-total:5 nmi-count:1
2147
+
<...>-1729 [007] d... 886.114702: #12 inner/outer(us): 9/12 ts:1581527691.385001600 count:1
2144
2148
2145
2149
2146
2150
The above output is somewhat the same in the header. All events will have
···
2156
2148
This is the count of events recorded that were greater than the
2157
2149
tracing_threshold (See below).
2158
2150
2159
-
inner/outer(us): 12/14
2151
+
inner/outer(us): 11/11
2160
2152
2161
2153
This shows two numbers as "inner latency" and "outer latency". The test
2162
2154
runs in a loop checking a timestamp twice. The latency detected within
···
2164
2156
after the previous timestamp and the next timestamp in the loop is
2165
2157
the "outer latency".
2166
2158
2167
-
ts:1499801089.066141940
2159
+
ts:1581527483.343962693
2168
2160
2169
-
The absolute timestamp that the event happened.
2161
+
The absolute timestamp that the first latency was recorded in the window.
2170
2162
2171
-
nmi-total:4 nmi-count:1
2163
+
count:6
2164
+
2165
+
The number of times a latency was detected during the window.
2166
+
2167
+
nmi-total:7 nmi-count:1
2172
2168
2173
2169
On architectures that support it, if an NMI comes in during the
2174
2170
test, the time spent in NMI is reported in "nmi-total" (in
+3
-1
kernel/trace/trace_entries.h
+3
-1
kernel/trace/trace_entries.h
···
325
325
__field_desc( long, timestamp, tv_nsec )
326
326
__field( unsigned int, nmi_count )
327
327
__field( unsigned int, seqnum )
328
+
__field( unsigned int, count )
328
329
),
329
330
330
-
F_printk("cnt:%u\tts:%010llu.%010lu\tinner:%llu\touter:%llu\tnmi-ts:%llu\tnmi-count:%u\n",
331
+
F_printk("cnt:%u\tts:%010llu.%010lu\tinner:%llu\touter:%llu\tcount:%d\tnmi-ts:%llu\tnmi-count:%u\n",
331
332
__entry->seqnum,
332
333
__entry->tv_sec,
333
334
__entry->tv_nsec,
334
335
__entry->duration,
335
336
__entry->outer_duration,
337
+
__entry->count,
336
338
__entry->nmi_total_ts,
337
339
__entry->nmi_count)
338
340
);
+17
-7
kernel/trace/trace_hwlat.c
+17
-7
kernel/trace/trace_hwlat.c
···
83
83
u64 nmi_total_ts; /* Total time spent in NMIs */
84
84
struct timespec64 timestamp; /* wall time */
85
85
int nmi_count; /* # NMIs during this sample */
86
+
int count; /* # of iteratons over threash */
86
87
};
87
88
88
89
/* keep the global state somewhere. */
···
125
124
entry->timestamp = sample->timestamp;
126
125
entry->nmi_total_ts = sample->nmi_total_ts;
127
126
entry->nmi_count = sample->nmi_count;
127
+
entry->count = sample->count;
128
128
129
129
if (!call_filter_check_discard(call, entry, buffer, event))
130
130
trace_buffer_unlock_commit_nostack(buffer, event);
···
169
167
static int get_sample(void)
170
168
{
171
169
struct trace_array *tr = hwlat_trace;
170
+
struct hwlat_sample s;
172
171
time_type start, t1, t2, last_t2;
173
-
s64 diff, total, last_total = 0;
172
+
s64 diff, outer_diff, total, last_total = 0;
174
173
u64 sample = 0;
175
174
u64 thresh = tracing_thresh;
176
175
u64 outer_sample = 0;
177
176
int ret = -1;
177
+
unsigned int count = 0;
178
178
179
179
do_div(thresh, NSEC_PER_USEC); /* modifies interval value */
180
180
···
190
186
191
187
init_time(last_t2, 0);
192
188
start = time_get(); /* start timestamp */
189
+
outer_diff = 0;
193
190
194
191
do {
195
192
···
199
194
200
195
if (time_u64(last_t2)) {
201
196
/* Check the delta from outer loop (t2 to next t1) */
202
-
diff = time_to_us(time_sub(t1, last_t2));
197
+
outer_diff = time_to_us(time_sub(t1, last_t2));
203
198
/* This shouldn't happen */
204
-
if (diff < 0) {
199
+
if (outer_diff < 0) {
205
200
pr_err(BANNER "time running backwards\n");
206
201
goto out;
207
202
}
208
-
if (diff > outer_sample)
209
-
outer_sample = diff;
203
+
if (outer_diff > outer_sample)
204
+
outer_sample = outer_diff;
210
205
}
211
206
last_t2 = t2;
212
207
···
221
216
222
217
/* This checks the inner loop (t1 to t2) */
223
218
diff = time_to_us(time_sub(t2, t1)); /* current diff */
219
+
220
+
if (diff > thresh || outer_diff > thresh) {
221
+
if (!count)
222
+
ktime_get_real_ts64(&s.timestamp);
223
+
count++;
224
+
}
224
225
225
226
/* This shouldn't happen */
226
227
if (diff < 0) {
···
247
236
248
237
/* If we exceed the threshold value, we have found a hardware latency */
249
238
if (sample > thresh || outer_sample > thresh) {
250
-
struct hwlat_sample s;
251
239
u64 latency;
252
240
253
241
ret = 1;
···
259
249
s.seqnum = hwlat_data.count;
260
250
s.duration = sample;
261
251
s.outer_duration = outer_sample;
262
-
ktime_get_real_ts64(&s.timestamp);
263
252
s.nmi_total_ts = nmi_total_ts;
264
253
s.nmi_count = nmi_count;
254
+
s.count = count;
265
255
trace_hwlat_sample(&s);
266
256
267
257
latency = max(sample, outer_sample);
+2
-2
kernel/trace/trace_output.c
+2
-2
kernel/trace/trace_output.c
···
1158
1158
1159
1159
trace_assign_type(field, entry);
1160
1160
1161
-
trace_seq_printf(s, "#%-5u inner/outer(us): %4llu/%-5llu ts:%lld.%09ld",
1161
+
trace_seq_printf(s, "#%-5u inner/outer(us): %4llu/%-5llu ts:%lld.%09ld count:%d",
1162
1162
field->seqnum,
1163
1163
field->duration,
1164
1164
field->outer_duration,
1165
1165
(long long)field->timestamp.tv_sec,
1166
-
field->timestamp.tv_nsec);
1166
+
field->timestamp.tv_nsec, field->count);
1167
1167
1168
1168
if (field->nmi_count) {
1169
1169
/*