[PATCH 0/3] cyclictest: improvements to histogram overflow instance mode

[PATCH 0/3] cyclictest: improvements to histogram overflow instance mode

[Bhavesh Davda]

This patch series makes usability improvements to the histogram overflow
instance tracking mode, as suggested by Frank Rowland.

Bhavesh Davda (3):
  cyclictest: new command line switch for histogram overflow instance
    tracking
  cyclictest: Report histogram overflow instances in seconds since
    start
  cyclictest: Print histogram overflow instances only if asked for

 src/cyclictest/cyclictest.c |   72 +++++++++++++++++++++++++++++++++---------
 1 files changed, 56 insertions(+), 16 deletions(-)

-- 
1.7.4.1

[PATCH 1/3] cyclictest: new command line switch for histogram overflow instance tracking

[Bhavesh Davda]

Add a new command line option '-g' (long option '--of_max') to cap how many
outliers are tracked per thread.

$ sudo ./cyclictest -p 99 -m -n -a -h 5 -g 50 -t4 -D 30
  /dev/cpu_dma_latency set to 0us
policy: fifo: loadavg: 0.14 0.15 0.09 1/396 11018

T: 0 (10978) P:99 I:1000 C:  29997 Min:      2 Act:    4 Avg:    3 Max:       7
T: 1 (10979) P:99 I:1000 C:  29995 Min:      2 Act:    4 Avg:    3 Max:      54
T: 2 (10980) P:99 I:1000 C:  29993 Min:      2 Act:    3 Avg:    3 Max:      10
T: 3 (10981) P:99 I:1000 C:  29991 Min:      2 Act:    3 Avg:    3 Max:       8
  Histogram
000000 000000	000000	000000	000000
000001 000000	000000	000000	000000
000002 000050	000031	000009	000037
000003 015205	016327	014673	018062
000004 014619	010466	012414	011863
  Total: 000029874 000026824 000027096 000029962
  Min Latencies: 00002 00002 00002 00002
  Avg Latencies: 00003 00003 00003 00003
  Max Latencies: 00007 00054 00010 00008
  Histogram Overflows: 00126 03174 02900 00032
  Histogram Overflow at time (ms):
  Thread 0: 1152 1653 3027 3152 3650 5152 5653 7027 7037 7047 7058 7068 7078 7088 7098 7108 7118 7128 7138 7148 7152 7158 7169 7179 7189 7199 7209 7219 7229 7239 7249 7259 7269 7279 7290 7300 7310 7320 7330 7340 7350 7360 7370 7380 7390 7401 7403 7404 7411 7412 # 76 others
  Thread 1: 0 1 2 4 14 24 34 45 55 56 65 75 85 95 105 115 125 126 135 145 153 155 166 176 186 196 206 216 226 236 246 256 266 277 287 297 307 317 327 337 347 357 367 377 388 398 408 418 428 438 # 3124 others
  Thread 2: 0 1 2 12 22 32 42 52 62 72 82 92 102 113 123 133 143 153 173 183 193 203 224 234 244 254 264 284 294 304 314 324 334 345 355 365 375 395 405 415 425 435 445 456 466 476 486 496 516 526 # 2850 others
  Thread 3: 0 1137 1149 3137 5137 7137 7405 8395 8396 8397 9137 11137 12643 12644 13137 15137 17137 17406 18395 18396 19137 21137 21227 21228 21229 23137 25137 27137 27406 28395 28396 29137

Signed-off-by: Bhavesh Davda <bhavesh@vmware.com>
---
 src/cyclictest/cyclictest.c |   34 +++++++++++++++++++++++++---------
 1 files changed, 25 insertions(+), 9 deletions(-)

diff --git a/src/cyclictest/cyclictest.c b/src/cyclictest/cyclictest.c
index abf3e8b..141e79f 100644
--- a/src/cyclictest/cyclictest.c
+++ b/src/cyclictest/cyclictest.c
@@ -91,6 +91,7 @@ extern int clock_nanosleep(clockid_t __clock_id, int __flags,
 #define NSEC_PER_SEC		1000000000
 
 #define HIST_MAX		1000000
+#define OF_MAX                  1000000
 
 #define MODE_CYCLIC		0
 #define MODE_CLOCK_NANOSLEEP	1
@@ -171,6 +172,7 @@ static int lockall = 0;
 static int tracetype = NOTRACE;
 static int histogram = 0;
 static int histofall = 0;
+static int of_max = 0;
 static int duration = 0;
 static int use_nsecs = 0;
 static int refresh_on_max;
@@ -887,7 +889,7 @@ void *timerthread(void *param)
 		if (histogram) {
 			if (diff >= histogram) {
 				stat->hist_overflow++;
-                                if (stat->num_outliers < histogram)
+				if (stat->num_outliers < of_max)
 					stat->outliers[stat->num_outliers++] = stat->cycles;
 			}
 			else
@@ -964,6 +966,7 @@ static void display_help(int error)
 	       "-e       --latency=PM_QOS  write PM_QOS to /dev/cpu_dma_latency\n"
 	       "-E       --event           event tracing (used with -b)\n"
 	       "-f       --ftrace          function trace (when -b is active)\n"
+	       "-g MAX   --of_max=MAX      Report time in ms (up to MAX) for histogram overflows\n"
 	       "-h       --histogram=US    dump a latency histogram to stdout after the run\n"
 	       "                           (with same priority about many threads)\n"
 	       "                           US is the max time to be be tracked in microseconds\n"
@@ -1102,6 +1105,7 @@ static void process_options (int argc, char *argv[])
 			{"latency",          required_argument, NULL, 'e'},
 			{"event",            no_argument,       NULL, 'E'},
 			{"ftrace",           no_argument,       NULL, 'f'},
+			{"of_max",           required_argument, NULL, 'g'},
 			{"histogram",        required_argument, NULL, 'h'},
 			{"histofall",        required_argument, NULL, 'H'},
 			{"interval",         required_argument, NULL, 'i'},
@@ -1133,7 +1137,7 @@ static void process_options (int argc, char *argv[])
 			{"help",             no_argument,       NULL, '?'},
 			{NULL, 0, NULL, 0}
 		};
-		int c = getopt_long(argc, argv, "a::b:Bc:Cd:D:e:Efh:H:i:Il:MnNo:O:p:PmqQrRsSt::uUvD:wWXT:y:",
+		int c = getopt_long(argc, argv, "a::b:Bc:Cd:D:e:Efg:h:H:i:Il:MnNo:O:p:PmqQrRsSt::uUvD:wWXT:y:",
 				    long_options, &option_index);
 		if (c == -1)
 			break;
@@ -1166,6 +1170,7 @@ static void process_options (int argc, char *argv[])
 			break;
 		case 'E': enable_events = 1; break;
 		case 'f': tracetype = FUNCTION; ftrace = 1; break;
+		case 'g': of_max = atoi(optarg); break;
 		case 'H': histofall = 1; /* fall through */
 		case 'h': histogram = atoi(optarg); break;
 		case 'i': interval = atoi(optarg); break;
@@ -1290,6 +1295,12 @@ static void process_options (int argc, char *argv[])
 	if (histogram > HIST_MAX)
 		histogram = HIST_MAX;
 
+	if (of_max < 0)
+		error = 1;
+
+	if (of_max > OF_MAX)
+		of_max = OF_MAX;
+
 	if (histogram && distance != -1)
 		warn("distance is ignored and set to 0, if histogram enabled\n");
 	if (distance == -1)
@@ -1451,16 +1462,15 @@ static void print_hist(struct thread_param *par[], int nthreads)
 		printf(" %05lu", alloverflows);
 	printf("\n");
 
-	printf("# Histogram Overflow at cycle number:\n");
+	printf("# Histogram Overflow at time (ms):\n");
 	for (i = 0; i < nthreads; i++) {
 		printf("# Thread %d:", i);
 		for (j = 0; j < par[i]->stats->num_outliers; j++)
-			printf(" %05lu", par[i]->stats->outliers[j]);
+			printf(" %lu", par[i]->stats->outliers[j] * par[i]->interval / 1000);
 		if (par[i]->stats->num_outliers < par[i]->stats->hist_overflow)
-			printf(" # %05lu others", par[i]->stats->hist_overflow - par[i]->stats->num_outliers);
+			printf(" # %lu others", par[i]->stats->hist_overflow - par[i]->stats->num_outliers);
 		printf("\n");
 	}
-	printf("\n");
 }
 
 static void print_stat(struct thread_param *par, int index, int verbose)
@@ -1706,11 +1716,17 @@ int main(int argc, char **argv)
 			int bufsize = histogram * sizeof(long);
 
 			stat->hist_array = threadalloc(bufsize, node);
-			stat->outliers = threadalloc(bufsize, node);
-			if (stat->hist_array == NULL || stat->outliers == NULL)
+			if (stat->hist_array == NULL)
 				fatal("failed to allocate histogram of size %d on node %d\n",
 				      histogram, i);
 			memset(stat->hist_array, 0, bufsize);
+		}
+		if (of_max) {
+			int bufsize = of_max * sizeof(long);
+			stat->outliers = threadalloc(bufsize, node);
+			if (stat->outliers == NULL)
+				fatal("failed to allocate outliers of size %d on node %d\n",
+				      histogram, i);
 			memset(stat->outliers, 0, bufsize);
 		}
 
@@ -1829,7 +1845,7 @@ int main(int argc, char **argv)
 		print_hist(parameters, num_threads);
 		for (i = 0; i < num_threads; i++) {
 			threadfree(statistics[i]->hist_array, histogram*sizeof(long), parameters[i]->node);
-			threadfree(statistics[i]->outliers, histogram*sizeof(long), parameters[i]->node);
+			threadfree(statistics[i]->outliers, of_max*sizeof(long), parameters[i]->node);
 		}
 	}
 
-- 
1.7.4.1

[PATCH 2/3] cyclictest: Report histogram overflow instances in seconds since start

[Bhavesh Davda]

This enhancement comes courtesy of Frank Rowand. It simplifies post-processing
of the outliers output. Note that the time reported is the "expected" wake-up
time for the outlier, not the "actual" wake-up time.

$ sudo ./cyclictest -p 99 -m -n -a -h 5 -g 50 -t4 -D 30
  /dev/cpu_dma_latency set to 0us
policy: fifo: loadavg: 0.14 0.07 0.02 1/392 17548

T: 0 (17514) P:99 I:1000 C:  29994 Min:      2 Act:    4 Avg:    3 Max:      25
T: 1 (17515) P:99 I:1000 C:  29992 Min:      2 Act:    4 Avg:  158 Max:   53753
T: 2 (17516) P:99 I:1000 C:  29990 Min:      2 Act:    3 Avg:    3 Max:       8
T: 3 (17517) P:99 I:1000 C:  29988 Min:      2 Act:    3 Avg:    4 Max:    5217
  Histogram
000000 000000	000000	000000	000000
000001 000000	000000	000000	000000
000002 000270	000026	000059	001742
000003 018558	002344	010656	007578
000004 011044	023196	019209	018014
  Total: 000029872 000025566 000029924 000027334
  Min Latencies: 00002 00002 00002 00002
  Avg Latencies: 00003 00158 00003 00004
  Max Latencies: 00025 53753 00008 05217
  Histogram Overflows: 00128 04432 00072 02660
  Histogram Overflow: time (sec), thread
0.003019264 0
0.004019264 0
...
0.005076667 1
0.006076667 1
...
0.007151408 2
0.008151408 2
...
0.009228138 3
0.019228138 3
...

Signed-off-by: Frank Rowand <frank.rowand@am.sony.com>
Signed-off-by: Bhavesh Davda <bhavesh@vmware.com>
---
 src/cyclictest/cyclictest.c |   42 ++++++++++++++++++++++++++++++++----------
 1 files changed, 32 insertions(+), 10 deletions(-)

diff --git a/src/cyclictest/cyclictest.c b/src/cyclictest/cyclictest.c
index 141e79f..b27f7dc 100644
--- a/src/cyclictest/cyclictest.c
+++ b/src/cyclictest/cyclictest.c
@@ -110,6 +110,8 @@ extern int clock_nanosleep(clockid_t __clock_id, int __flags,
 
 int enable_events;
 
+struct timespec test_start;
+
 static char *policyname(int policy);
 
 enum {
@@ -151,7 +153,7 @@ struct thread_stat {
 	double avg;
 	long *values;
 	long *hist_array;
-        long *outliers;
+	struct timespec *outliers;
 	pthread_t thread;
 	int threadstarted;
 	int tid;
@@ -337,6 +339,18 @@ static inline void tsnorm(struct timespec *ts)
 	}
 }
 
+static inline void tsnorm2(struct timespec *ts)
+{
+	while (ts->tv_nsec < 0) {
+		ts->tv_nsec += NSEC_PER_SEC;
+		ts->tv_sec--;
+	}
+	while (ts->tv_nsec >= NSEC_PER_SEC) {
+		ts->tv_nsec -= NSEC_PER_SEC;
+		ts->tv_sec++;
+	}
+}
+
 static inline int64_t calcdiff(struct timespec t1, struct timespec t2)
 {
 	int64_t diff;
@@ -890,7 +904,7 @@ void *timerthread(void *param)
 			if (diff >= histogram) {
 				stat->hist_overflow++;
 				if (stat->num_outliers < of_max)
-					stat->outliers[stat->num_outliers++] = stat->cycles;
+					stat->outliers[stat->num_outliers++] = next;
 			}
 			else
 				stat->hist_array[diff]++;
@@ -1462,14 +1476,15 @@ static void print_hist(struct thread_param *par[], int nthreads)
 		printf(" %05lu", alloverflows);
 	printf("\n");
 
-	printf("# Histogram Overflow at time (ms):\n");
+	printf("# Histogram Overflow: time (sec), thread\n");
 	for (i = 0; i < nthreads; i++) {
-		printf("# Thread %d:", i);
-		for (j = 0; j < par[i]->stats->num_outliers; j++)
-			printf(" %lu", par[i]->stats->outliers[j] * par[i]->interval / 1000);
-		if (par[i]->stats->num_outliers < par[i]->stats->hist_overflow)
-			printf(" # %lu others", par[i]->stats->hist_overflow - par[i]->stats->num_outliers);
-		printf("\n");
+		for (j = 0; j < par[i]->stats->num_outliers; j++) {
+			struct timespec diff;
+			diff.tv_sec  = par[i]->stats->outliers[j].tv_sec  - test_start.tv_sec;
+			diff.tv_nsec = par[i]->stats->outliers[j].tv_nsec - test_start.tv_nsec;
+			tsnorm2(&diff);
+			printf("%ld.%09ld %d\n", diff.tv_sec, diff.tv_nsec, i);
+		}
 	}
 }
 
@@ -1663,6 +1678,13 @@ int main(int argc, char **argv)
 	if (!statistics)
 		goto outpar;
 
+	/*
+	 * test_start does not need to be precise.  For some types of output,
+	 * it will be subtracted from a time value so that the result is
+	 * relative to the start of test.
+	 */
+	clock_gettime(clocksources[clocksel], &test_start);
+
 	for (i = 0; i < num_threads; i++) {
 		pthread_attr_t attr;
 		int node;
@@ -1722,7 +1744,7 @@ int main(int argc, char **argv)
 			memset(stat->hist_array, 0, bufsize);
 		}
 		if (of_max) {
-			int bufsize = of_max * sizeof(long);
+			int bufsize = of_max * sizeof(*stat->outliers);
 			stat->outliers = threadalloc(bufsize, node);
 			if (stat->outliers == NULL)
 				fatal("failed to allocate outliers of size %d on node %d\n",
-- 
1.7.4.1

[PATCH 3/3] cyclictest: Print histogram overflow instances only if asked for

[Bhavesh Davda]

By default (if -g is not specified), of_max is zero. Don't print histogram
overflow instances in that case.

Signed-off-by: Bhavesh Davda <bhavesh@vmware.com>
---
 src/cyclictest/cyclictest.c |   18 ++++++++++--------
 1 files changed, 10 insertions(+), 8 deletions(-)

diff --git a/src/cyclictest/cyclictest.c b/src/cyclictest/cyclictest.c
index b27f7dc..74c56a6 100644
--- a/src/cyclictest/cyclictest.c
+++ b/src/cyclictest/cyclictest.c
@@ -1476,14 +1476,16 @@ static void print_hist(struct thread_param *par[], int nthreads)
 		printf(" %05lu", alloverflows);
 	printf("\n");
 
-	printf("# Histogram Overflow: time (sec), thread\n");
-	for (i = 0; i < nthreads; i++) {
-		for (j = 0; j < par[i]->stats->num_outliers; j++) {
-			struct timespec diff;
-			diff.tv_sec  = par[i]->stats->outliers[j].tv_sec  - test_start.tv_sec;
-			diff.tv_nsec = par[i]->stats->outliers[j].tv_nsec - test_start.tv_nsec;
-			tsnorm2(&diff);
-			printf("%ld.%09ld %d\n", diff.tv_sec, diff.tv_nsec, i);
+	if (of_max > 0) {
+		printf("# Histogram Overflow: time (sec), thread\n");
+		for (i = 0; i < nthreads; i++) {
+			for (j = 0; j < par[i]->stats->num_outliers; j++) {
+				struct timespec diff;
+				diff.tv_sec  = par[i]->stats->outliers[j].tv_sec  - test_start.tv_sec;
+				diff.tv_nsec = par[i]->stats->outliers[j].tv_nsec - test_start.tv_nsec;
+				tsnorm2(&diff);
+				printf("%ld.%09ld %d\n", diff.tv_sec, diff.tv_nsec, i);
+			}
 		}
 	}
 }
-- 
1.7.4.1

Re: [PATCH 0/3] cyclictest: improvements to histogram overflow instance mode

[Frank Rowand]

On 12/19/12 12:00, Bhavesh Davda wrote:
> This patch series makes usability improvements to the histogram overflow
> instance tracking mode, as suggested by Frank Rowland.
                                                ^^^^^^^
                                                Rowand

It happens all the time....

> 
> Bhavesh Davda (3):
>   cyclictest: new command line switch for histogram overflow instance
>     tracking
>   cyclictest: Report histogram overflow instances in seconds since
>     start
>   cyclictest: Print histogram overflow instances only if asked for
> 
>  src/cyclictest/cyclictest.c |   72 +++++++++++++++++++++++++++++++++---------
>  1 files changed, 56 insertions(+), 16 deletions(-)
> 

For patches 1 - 3:


Reviewed-by: Frank Rowand <frank.rowand@am.sony.com>
Tested-by: Frank Rowand <frank.rowand@am.sony.com>


Thanks for improving cyclictest Bhavesh!

John, all good for you to commit?

-Frank

Re: [PATCH 0/3] cyclictest: improvements to histogram overflow instance mode

[Frank Rowand]

John,

Ping... (did this go into the git repository?)

-Frank

On 12/19/12 15:17, Frank Rowand wrote:
> On 12/19/12 12:00, Bhavesh Davda wrote:
>> This patch series makes usability improvements to the histogram overflow
>> instance tracking mode, as suggested by Frank Rowland.
>                                                 ^^^^^^^
>                                                 Rowand
> 
> It happens all the time....
> 
>>
>> Bhavesh Davda (3):
>>   cyclictest: new command line switch for histogram overflow instance
>>     tracking
>>   cyclictest: Report histogram overflow instances in seconds since
>>     start
>>   cyclictest: Print histogram overflow instances only if asked for
>>
>>  src/cyclictest/cyclictest.c |   72 +++++++++++++++++++++++++++++++++---------
>>  1 files changed, 56 insertions(+), 16 deletions(-)
>>
> 
> For patches 1 - 3:
> 
> 
> Reviewed-by: Frank Rowand <frank.rowand@am.sony.com>
> Tested-by: Frank Rowand <frank.rowand@am.sony.com>
> 
> 
> Thanks for improving cyclictest Bhavesh!
> 
> John, all good for you to commit?
> 
> -Frank
> .
> 

Re: [PATCH 0/3] cyclictest: improvements to histogram overflow instance mode

[John Kacur]

On Wed, 19 Dec 2012, Bhavesh Davda wrote:

> This patch series makes usability improvements to the histogram overflow
> instance tracking mode, as suggested by Frank Rowland.
> 
> Bhavesh Davda (3):
>   cyclictest: new command line switch for histogram overflow instance
>     tracking
>   cyclictest: Report histogram overflow instances in seconds since
>     start
>   cyclictest: Print histogram overflow instances only if asked for
> 
>  src/cyclictest/cyclictest.c |   72 +++++++++++++++++++++++++++++++++---------
>  1 files changed, 56 insertions(+), 16 deletions(-)
> 

Thanks for submitting these patches - I'm afraid I either missed them or 
forgot about them since they were submitted so close to Christmas. Review 
pending.

John

Re: [PATCH 0/3] cyclictest: improvements to histogram overflow instance mode

[Bhavesh Davda]

> On Wed, 19 Dec 2012, Bhavesh Davda wrote:
> 
> > This patch series makes usability improvements to the histogram
> > overflow
> > instance tracking mode, as suggested by Frank Rowland.
> > 
> > Bhavesh Davda (3):
> >   cyclictest: new command line switch for histogram overflow
> >   instance
> >     tracking
> >   cyclictest: Report histogram overflow instances in seconds since
> >     start
> >   cyclictest: Print histogram overflow instances only if asked for
> > 
> >  src/cyclictest/cyclictest.c |   72
> >  +++++++++++++++++++++++++++++++++---------
> >  1 files changed, 56 insertions(+), 16 deletions(-)
> > 
> 
> Thanks for submitting these patches - I'm afraid I either missed them
> or
> forgot about them since they were submitted so close to Christmas.
> Review
> pending.
> 
> John


Thank you John,

As you might have noticed, Frank has already signed off on this patch set.

- Bhavesh