1 From 3686244e5446419fc92bb4b2bc154f776f3d0acb Mon Sep 17 00:00:00 2001
2 From: Steven Rostedt <rostedt@goodmis.org>
3 Date: Mon, 19 Aug 2013 17:33:25 -0400
4 Subject: [PATCH 025/366] hwlat-detector: Update hwlat_detector to add outer
7 The hwlat_detector reads two timestamps in a row, then reports any
8 gap between those calls. The problem is, it misses everything between
9 the second reading of the time stamp to the first reading of the time stamp
10 in the next loop. That's were most of the time is spent, which means,
11 chances are likely that it will miss all hardware latencies. This
14 By also testing the first time stamp from the previous loop second
15 time stamp (the outer loop), we are more likely to find a latency.
17 Setting the threshold to 1, here's what the report now looks like:
19 1347415723.0232202770 0 2
20 1347415725.0234202822 0 2
21 1347415727.0236202875 0 2
22 1347415729.0238202928 0 2
23 1347415731.0240202980 0 2
24 1347415734.0243203061 0 2
25 1347415736.0245203113 0 2
26 1347415738.0247203166 2 0
27 1347415740.0249203219 0 3
28 1347415742.0251203272 0 3
29 1347415743.0252203299 0 3
30 1347415745.0254203351 0 2
31 1347415747.0256203404 0 2
32 1347415749.0258203457 0 2
33 1347415751.0260203510 0 2
34 1347415754.0263203589 0 2
35 1347415756.0265203642 0 2
36 1347415758.0267203695 0 2
37 1347415760.0269203748 0 2
38 1347415762.0271203801 0 2
39 1347415764.0273203853 2 0
41 There's some hardware latency that takes 2 microseconds to run.
43 Signed-off-by: Steven Rostedt <srostedt@redhat.com>
44 Signed-off-by: Sebastian Andrzej Siewior <bigeasy@linutronix.de>
46 drivers/misc/hwlat_detector.c | 32 ++++++++++++++++++++++++++------
47 1 file changed, 26 insertions(+), 6 deletions(-)
49 diff --git a/drivers/misc/hwlat_detector.c b/drivers/misc/hwlat_detector.c
50 index 6864f3c..c07e859 100644
51 --- a/drivers/misc/hwlat_detector.c
52 +++ b/drivers/misc/hwlat_detector.c
53 @@ -143,6 +143,7 @@ static void detector_exit(void);
55 u64 seqnum; /* unique sequence */
56 u64 duration; /* ktime delta */
57 + u64 outer_duration; /* ktime delta (outer loop) */
58 struct timespec timestamp; /* wall time */
61 @@ -219,11 +220,13 @@ static struct sample *buffer_get_sample(struct sample *sample)
63 static int get_sample(void *unused)
65 - ktime_t start, t1, t2;
66 + ktime_t start, t1, t2, last_t2;
69 + u64 outer_sample = 0;
73 start = ktime_get(); /* start timestamp */
76 @@ -231,7 +234,22 @@ static int get_sample(void *unused)
77 t1 = ktime_get(); /* we'll look for a discontinuity */
81 + /* Check the delta from outer loop (t2 to next t1) */
82 + diff = ktime_to_us(ktime_sub(t1, last_t2));
83 + /* This shouldn't happen */
85 + pr_err(BANNER "time running backwards\n");
88 + if (diff > outer_sample)
89 + outer_sample = diff;
93 total = ktime_to_us(ktime_sub(t2, start)); /* sample width */
95 + /* This checks the inner loop (t1 to t2) */
96 diff = ktime_to_us(ktime_sub(t2, t1)); /* current diff */
98 /* This shouldn't happen */
99 @@ -246,12 +264,13 @@ static int get_sample(void *unused)
100 } while (total <= data.sample_width);
102 /* If we exceed the threshold value, we have found a hardware latency */
103 - if (sample > data.threshold) {
104 + if (sample > data.threshold || outer_sample > data.threshold) {
108 s.seqnum = data.count;
110 + s.outer_duration = outer_sample;
111 s.timestamp = CURRENT_TIME;
112 __buffer_add_sample(&s);
114 @@ -738,10 +757,11 @@ static ssize_t debug_sample_fread(struct file *filp, char __user *ubuf,
118 - len = snprintf(buf, sizeof(buf), "%010lu.%010lu\t%llu\n",
119 - sample->timestamp.tv_sec,
120 - sample->timestamp.tv_nsec,
122 + len = snprintf(buf, sizeof(buf), "%010lu.%010lu\t%llu\t%llu\n",
123 + sample->timestamp.tv_sec,
124 + sample->timestamp.tv_nsec,
126 + sample->outer_duration);
129 /* handling partial reads is more trouble than it's worth */