cyclictest: new command line switch for histogram overflow instance tracking

From: Bhavesh Davda <[email protected]>

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

Signed-off-by Bhavesh Davda <[email protected]>

---
Here's my attempt at addressing Frank's suggestions. Please correct me if I've misunderstood what you were suggesting.

checkpatch.pl reported:

total: 2 errors, 5 warnings, 76 lines checked

but the warnings and errors seem consistent with existing cyclictest practice.

---
 src/cyclictest/cyclictest.c |   24 +++++++++++++++++-------
 1 files changed, 17 insertions(+), 7 deletions(-)

src/cyclictest/cyclictest.c +3 -1

index 824544f..a728c14 100644
@@ -171,6 +171,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;

@@ -854,7 +855,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

@@ -930,6 +931,7 @@ static void display_help(int error)
 	       "                           to modify value to minutes, hours or days\n"
 	       "-E       --event           event tracing (used with -b)\n"
 	       "-f       --ftrace          function trace (when -b is active)\n"
+	       "-g MAX   --of_max=MAX      Report cycle instances (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"

src/cyclictest/cyclictest.c +9 -4

@@ -1563,13 +1568,18 @@ int main(int argc, char **argv)
 		/* allocate the histogram if requested */
 		if (histogram) {
 			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);
 		}
 

@@ -1688,7 +1698,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);
 		}
 	}
 

Quoted 2 lines

Here's my attempt at addressing Frank's suggestions. Please correct me if I've misunderstood what you were suggesting.

It addresses the issues related to the size of stat->outliers. But does
not address my other suggestions.

If you want to ignore my other suggestions, that is ok.

More comments inline below.

Patch is not against the current git repository, so fails:

patching file src/cyclictest/cyclictest.c
Hunk #2 succeeded at 888 (offset 33 lines). Hunk #3 succeeded at 965 with fuzz 2 (offset 34 lines). Hunk #4 FAILED at 1061.
Hunk #5 FAILED at 1092.
Hunk #6 succeeded at 1168 with fuzz 1 (offset 50 lines). Hunk #7 succeeded at 1707 (offset 141 lines). Hunk #8 succeeded at 1837 (offset 141 lines).

Review

Quoted 2 lines

(quoted diff) +1 -0

 			{"ftrace", no_argument, NULL, 'f'},
+			{"ftrace", no_argument, NULL, 'f'},

ftrace already exists in previous line.

Review

Quoted 3 lines

(quoted diff) +1 -0

+		int c = getopt_long(argc, argv,

"a::b:Bc:Cd:Efg:h:H:i:Il:MnNo:O:p:PmqQrsS"

(quoted diff) +1 -0

+				    "t::uUvD:wWT:y:e:", long_options, &option_index);

nit: I don't see the point of splitting the constant string. The line is over long both before
and after the change. If adding one character makes the string too long, I would suggest
moving it to a new line, indented to match "long_options, &option_index);".

Should ensure that of_max is not negative.

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

policy: fifo: loadavg: 0.04 0.05 0.01 1/422 13994

T: 0 (13938) P:99 I:1000 C: 29996 Min: 2 Act: 3 Avg: 2 Max: 75
T: 1 (13939) P:99 I:1000 C: 29994 Min: 2 Act: 5 Avg: 3 Max: 12
T: 2 (13940) P:99 I:1000 C: 29991 Min: 2 Act: 4 Avg: 3 Max: 8
T: 3 (13941) P:99 I:1000 C: 29989 Min: 2 Act: 4 Avg: 3 Max: 8
Histogram

000000 000000   000000  000000  000000
000001 000000   000000  000000  000000
000002 010425   000019  000012  000029
000003 017252   005100  008867  018353
000004 002277   021146  021048  011549

Total: 000029954 000026265 000029927 000029931
Min Latencies: 00002 00002 00002 00002
Avg Latencies: 00002 00003 00003 00003
Max Latencies: 00075 00012 00008 00008
Histogram Overflows: 00046 03733 00069 00063
Histogram Overflow at cycle number:
Thread 0: 00475 00476 01311 01818 03183 03311 05569 08003 08741 08743 08745 08760 08761 09311 13922 14890 15476 15562 15563 17243 17250 17253 17254 17255 17256 17257 17258 17259 17270 17271 17272 18026 18752 19115 19700 20668 21031 21311 21813 22311 24782 26234 26960 28291 29259 29622 Thread 1: 00000 00001 00002 00003 00004 00014 00024 00034 00035 00044 00045 00054 00055 00064 00065 00074 00075 00084 00085 00095 00105 00115 00125 00135 00145 00146 00149 00155 00156 00165 00166 00175 00176 00185 00186 00188 00195 00196 00206 00216 00226 00233 00236 00246 00256 00257 00266 00267 00276 00277 # 03683 others Thread 2: 00000 00001 00002 00228 00471 01301 02471 02472 02912 03301 03472 05301 05307 05314 05565 06472 07301 07472 08472 08711 08737 08738 08740 08757 09301 10228 11301 13301 14472 15301 15472 15566 17241 17247 17249 17250 17251 17252 17253 17254 17255 17256 17257 17262 17266 17267 17268 17301 17472 18472 # 00019 others Thread 3: 00000 00469 01296 02469 02470 03296 05296 05562 06554 06555 07296 07308 08736 08737 08738 08739 08740 08741 08742 08743 08744 08745 08746 08747 08748 08749 08750 08751 08752 08753 08754 09296 09308 11296 13296 14470 15296 15308 15470 15564 16554 16555 17245 17246 17248 17249 17253 17254 17265 17296 # 00013 others

Signed-off-by Bhavesh Davda <[email protected]>

---

Quoted 3 lines

Quoted 2 lines

Here's my attempt at addressing Frank's suggestions. Please correct me if I've misunderstood what you were suggesting.

Quoted 5 lines

It addresses the issues related to the size of stat->outliers. But does
not address my other suggestions.

If you want to ignore my other suggestions, that is ok.

I would like to address all your suggestions. Which ones did I miss?

Quoted 1 line

More comments inline below.

| Add a line to the histogram overflow cycle report that merges all
| threads into a single time line.  This is controlled by the -H
| option which already serves a similar purpose for histograms.

The merged data line is an enhancement. If there is no strong request
from anyone for the feature then no need to include. But it seems useful to me.

| Removed leading zeros from cycle values reported in the histogram | overflow cycle report to make the values more readable.

I should have also mentioned that many programs interpret numbers with leading zeros as octal.

| Removed extra blank line printed at end of Histogram output.

Some graphing programs are sensitive to extraneous blank lines, so I try to avoid adding additional blank lines.

| One further thought...  The histogram overflow cycle report shows
| what cycle the overflow occurred in, not the actual time.  Adding
| the merged for all threads cycle times works because the histogram
| turns off the "different intervals for different threads" option:
| 
|                 if (!histogram) /* same interval on CPUs */
|                         interval += distance;
| 
| but if that ever changes then cycle is not a useful value to be
| reporting.
| 
| So it seems like it would be useful to convert cycle to a time
| in the report.  This is something that would have to be done
| anyway in post processing when trying to make use of the report.

This was probably the most important comment.

This version of the patch addressed all of my inline comments.

But this version of the patch seems to have tabs converted to spaces, so
it doesn't apply. My email servers sometimes alter white space in patches
so I double checked the patch on a list server at:

From: Bhavesh Davda <[email protected]>

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

---

Quoted 4 lines

| Add a line to the histogram overflow cycle report that merges all | threads into a single time line. This is controlled by the -H | option which already serves a similar purpose for histograms.

Quoted 3 lines

The merged data line is an enhancement. If there is no strong request from anyone for the feature then no need to include. But it seems useful to me.

I agree this is a useful feature request, but harder to implement, since I'll have to merge sort from the per-thread outliers to produce a single line merged outlier output. I hope it's okay if I punt on this one.

I graphed the results with the msec data and with the nanosecond timestamps for an artificial test (two test runs for each case):

  nanosecond:  junk7.gif    junk10.gif
  msec:        junk8_d.gif  junk9_d.gif

The cyclictest latency disruptions seem more visible to me in the nanosecond data graphs. But that is just a first impression without playing around with a lot of different data sets.

On 11/16/12 18:31, Frank Rowand wrote:

< snip >

Quoted 6 lines

I graphed the results with the msec data and with the nanosecond timestamps for an artificial test (two test runs for each case):

  nanosecond:  junk7.gif    junk10.gif
  msec:        junk8_d.gif  junk9_d.gif

Quoted 3 lines

The cyclictest latency disruptions seem more visible to me in the nanosecond data graphs. But that is just a first impression without playing around with a lot of different data sets.

John, Bhavesh,

OK, so after all of that, I'm going on vacation for a week. I hope the rest of you are taking some time off too.

My conclusion after my data creation and graphing exercise is that it might be good if people could play around with collecting and analyzing real histogram overflow data and see what data formats provide useful information.

I think we should not rush the patch into John's tree so that we aren't stuck with a format or type of data that is not optimal.

Bhavesh, if you created this feature based on a real world need (instead of just a brilliant mind exercise), it would be great if you could apply the latest iteration (or iterations in the near future) to your actual data collection and provide a real world example of how this feature makes cyclictest better.

Thanks,

Frank

Quoted 14 lines · Frank Rowand

< snip >

Quoted 9 lines

I graphed the results with the msec data and with the nanosecond timestamps for an artificial test (two test runs for each case):

  nanosecond:  junk7.gif    junk10.gif
  msec:        junk8_d.gif  junk9_d.gif

The cyclictest latency disruptions seem more visible to me in the nanosecond data graphs. But that is just a first impression without playing around with a lot of different data sets.

Quoted 4 lines

John, Bhavesh,

OK, so after all of that, I'm going on vacation for a week. I hope the rest of you are taking some time off too.

I'm back... Bhavesh, have you had a chance to think about my last several emails (my comments on your latest patch, my proposed patch, and the email I'm responding to)? Any comments?

Quoted 19 lines

My conclusion after my data creation and graphing exercise is that it might be good if people could play around with collecting and analyzing real histogram overflow data and see what data formats provide useful information.

I think we should not rush the patch into John's tree so that we aren't stuck with a format or type of data that is not optimal.

Bhavesh, if you created this feature based on a real world need (instead of just a brilliant mind exercise), it would be great if you could apply the latest iteration (or iterations in the near future) to your actual data collection and provide a real world example of how this feature makes cyclictest better.

Thanks,

Frank

Quoted 4 lines

I'm back... Bhavesh, have you had a chance to think about my last several emails (my comments on your latest patch, my proposed patch,
and the email I'm responding to)? Any comments?

Hello Frank. Welcome back. I was out for the long weekend and am just getting back in the swing of things too, so sorry about the delay.

I do have real use cases for this "outlier" mode, that I've used effectively to identify sources of high latencies of cyclictest

I'm hoping that others in the community find similar uses of this "outlier" feature of cyclictest.

I'm going to respond to your proposed patch next.

Quoted 10 lines

Quoted 4 lines

I'm back... Bhavesh, have you had a chance to think about my last several emails (my comments on your latest patch, my proposed patch,
and the email I'm responding to)? Any comments?

Hello Frank. Welcome back. I was out for the long weekend and am just getting back in the swing of things too, so sorry about the delay.

I do have real use cases for this "outlier" mode, that I've used effectively to identify sources of high latencies of cyclictest

<snip>

Quoted 3 lines

I'm hoping that others in the community find similar uses of this "outlier" feature of cyclictest.

<snip>

Quoted 1 line

I'm going to respond to your proposed patch next.

Hello Frank,

I'm sorry I can't find your e-mail with a proposed patch on top of my patch posted on

Date: 2012-11-16 2:04:07

with

Message-ID: 1465858638.1880820.1353031447623.JavaMail.root () vmware ! com

Can you please tell me which e-mail contained your proposed patch on top of this patch?

Thanks

- Bhavesh

Quoted 17 lines · Frank Rowand

Quoted 16 lines · Frank Rowand

< snip >

Quoted 11 lines

I graphed the results with the msec data and with the nanosecond timestamps for an artificial test (two test runs for each case):

nanosecond: junk7.gif junk10.gif msec: junk8_d.gif
junk9_d.gif

The cyclictest latency disruptions seem more visible to me in the nanosecond data graphs. But that is just a first impression without playing around with a lot of different data sets.

Quoted 8 lines

Quoted 4 lines

John, Bhavesh,

OK, so after all of that, I'm going on vacation for a week. I hope the rest of you are taking some time off too.

I'm back... Bhavesh, have you had a chance to think about my last several emails (my comments on your latest patch, my proposed patch, and the email I'm responding to)? Any comments?

Hello Frank. Welcome back. I was out for the long weekend and am just getting back in the swing of things too, so sorry about the delay.

I do have real use cases for this "outlier" mode, that I've used effectively to identify sources of high latencies of cyclictest running in a Linux-rt kernel based VM on our VMware ESXi hypervisor. The patterns in the outliers, for various thresholds (e.g. 50 us) have helped me identify timers and callbacks in the hypervisor kernel (vmkernel) which have caused time to be "stolen" away from scheduling the virtual CPUs of the VM to do various housekeeping tasks, and to either move those timers out to other physical CPUs or to limit the time spend in those timers and callbacks to have a smaller impact on the cyclictest latencies.

I'm hoping that others in the community find similar uses of this "outlier" feature of cyclictest.

That said, I realize that not every use cases might fit my exact mould and might require either different formatting, or different granularities of the "outliers" output. So I'm open to suggestions in that regard.

I'm going to respond to your proposed patch next.

Thanks

- Bhavesh

Quoted 5 lines

I'm going to respond to your proposed patch next.

Thanks

- Bhavesh

ping....

Thanks,

Frank

Quoted 8 lines

Quoted 5 lines

I'm going to respond to your proposed patch next.

Thanks

- Bhavesh

ping....

Quoted 3 lines

Thanks,

Frank

Hello Frank,

Extremely sorry about the tardiness in reviewing your proposed change!

Your change looks good to me. Again, did you want me to fold your proposed change into my original patch, or were you proposing applying your patch (of course without the #if 0's) on top of mine?

Thanks for spending so much time reviewing my patches, trying them out, and suggesting ways to make it better!

It would be great if you could add my changes on top of your original patch
since John hasn't committed your original patch yet. That way everything
will be coordinated from one person. And yes, without the "#if 0's".

It would probably be good to submit it to John as a series of two patches,
your original patch, followed by my additions.

For my patch, you can add: Signed-off-by: Frank Rowand <[email protected]>

My patch did not address one other comment I made, which is:

default of -g to zero means histogram overflows will be printed even
if "-g" not specified (same as "-g 0"). The output of histogram overflows should only occur if of_max > 0.

Quoted 14 lines

It would be great if you could add my changes on top of your original patch
since John hasn't committed your original patch yet. That way everything
will be coordinated from one person. And yes, without the "#if 0's".

It would probably be good to submit it to John as a series of two patches,
your original patch, followed by my additions.

For my patch, you can add: Signed-off-by: Frank Rowand <[email protected]>

Quoted 6 lines

My patch did not address one other comment I made, which is:

default of -g to zero means histogram overflows will be printed even
if "-g" not specified (same as "-g 0"). The output of histogram overflows should only occur if of_max > 0.

I'll see if I can address that in a potentially 3rd part of a 3 patch series.

One thing I noticed when actually creating the 2nd patch, in your change:

(quoted diff) +1 -1

@@ -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]++;

Should that be:
+ stat->outliers[stat->num_outliers++] = now;

instead?

And finally, as far as output format for the outliers is concerned, I'm slightly worried it takes too much screen real estate by printing one line per outlier per thread. But that's quite subjective and I wouldn't be opposed to living with it for a while and seeing if it starts to get annoying :)

Quoted 1 line

I would like to address all your suggestions. Which ones did I miss?

| Add a line to the histogram overflow cycle report that merges all
| threads into a single time line.  This is controlled by the -H
| option which already serves a similar purpose for histograms.

The merged data line is an enhancement. If there is no strong request from anyone for the feature then no need to include. But it seems useful to me.