Skip to contentSkip to conversation

rt-tests: incorrect first latency value for --verbose option

PATCH In review Frank Rowand 2 participants 5 messages May 3, 2012 – May 7, 2012

lore
Share & tools
lore

Frank Rowand

author
#0 lore raw

PATCH 1/1 rt-tests: incorrect first latency value for --verbose option

When the --verbose option is selected, the first value for each thread is incorrectly reported as zero.

This is because when collecting the first value, the index into stat->values is incremented from zero to one before storing the value. But when printing the values, the first value printed is stat->values[0], which has been initialized to zero.

Signed-off-by Frank Rowand <[email protected]>

---
src/cyclictest/cyclictest.c | 3 2 + 1 - 0 !

 1 file changed, 2 insertions(+), 1 deletion(-)
src/cyclictest/cyclictest.c +2 -1
Index: b/src/cyclictest/cyclictest.c
===================================================================
@@ -756,7 +756,6 @@ void *timerthread(void *param)
 			pthread_mutex_unlock(&break_thread_id_lock);
 		}
 		stat->act = diff;
-		stat->cycles++;
 
 		if (par->bufmsk)
 			stat->values[stat->cycles & par->bufmsk] = diff;

@@ -769,6 +768,8 @@ void *timerthread(void *param)
 				stat->hist_array[diff]++;
 		}
 
+		stat->cycles++;
+
 		next.tv_sec += interval.tv_sec;
 		next.tv_nsec += interval.tv_nsec;
 		if (par->mode == MODE_CYCLIC) {
#1 lore raw
Quoted 8 lines · Frank Rowand

When the --verbose option is selected, the first value for each thread is incorrectly reported as zero.

This is because when collecting the first value, the index into stat->values is incremented from zero to one before storing the value. But when printing the values, the first value printed is stat->values[0], which has been initialized to zero.

Hi Frank

Ok, no more posting from me after winning a bottle of whiskey at the Irish Pub on quiz night. :)

I've been looking at this one, and I'm not sure about it. According to the help output,

"-v --verbose output values on stdout for statistics
format: n:c:v n=tasknum c=count v=value in us"

./cyclictest --verbose -p99 -t | awk '$2~/^0/{ print }'

       0:       0:       0
       1:       0:       0
       2:       0:       0
       3:       0:       0
       4:       0:       0
       5:       0:       0
       6:       0:       0
       7:       0:       0

So, it looks like the values are 0 at count 0, doesn't that make sense?

Thanks

John Kacur

author
#2 lore raw
Quoted 13 lines · John Kacur
Quoted 8 lines · Frank Rowand

When the --verbose option is selected, the first value for each thread is incorrectly reported as zero.

This is because when collecting the first value, the index into stat->values is incremented from zero to one before storing the value. But when printing the values, the first value printed is stat->values[0], which has been initialized to zero.

Quoted 4 lines

Hi Frank

Ok, no more posting from me after winning a bottle of whiskey at the Irish Pub on quiz night. :)

Or if you do, you should share a bit of the whiskey with me.

Quoted 18 lines

I've been looking at this one, and I'm not sure about it. According to the help output,

"-v --verbose output values on stdout for statistics
format: n:c:v n=tasknum c=count v=value in us"

./cyclictest --verbose -p99 -t | awk '$2~/^0/{ print }'

       0:       0:       0
       1:       0:       0
       2:       0:       0
       3:       0:       0
       4:       0:       0
       5:       0:       0
       6:       0:       0
       7:       0:       0
Quoted 1 line

So, it looks like the values are 0 at count 0, doesn't that make sense?

Nope. The event for count == 0 is the first event. And the first event has an actual latency that is not zero on the system I tested it on.

-Frank

#3 lore raw
Quoted 14 lines · Frank Rowand
Quoted 13 lines · John Kacur
Quoted 8 lines · Frank Rowand

When the --verbose option is selected, the first value for each thread is incorrectly reported as zero.

This is because when collecting the first value, the index into stat->values is incremented from zero to one before storing the value. But when printing the values, the first value printed is stat->values[0], which has been initialized to zero.

Quoted 6 lines
Quoted 4 lines

Hi Frank

Ok, no more posting from me after winning a bottle of whiskey at the Irish Pub on quiz night. :)

Or if you do, you should share a bit of the whiskey with me.

You get the bottle and 30 shot glasses and share it with everyone at the pub, so if you want some you have to come, and then help my team win too :)

Quoted 19 lines
Quoted 19 lines

I've been looking at this one, and I'm not sure about it. According to the help output,

"-v --verbose output values on stdout for statistics
format: n:c:v n=tasknum c=count v=value in us"

./cyclictest --verbose -p99 -t | awk '$2~/^0/{ print }'

       0:       0:       0
       1:       0:       0
       2:       0:       0
       3:       0:       0
       4:       0:       0
       5:       0:       0
       6:       0:       0
       7:       0:       0
Quoted 5 lines
Quoted 1 line

So, it looks like the values are 0 at count 0, doesn't that make sense?

Nope. The event for count == 0 is the first event. And the first event has an actual latency that is not zero on the system I tested it on.

Hmmm, this may be a quibble about definitions. I know that in the c-world we're used to start counting at 0, but to me, count == 0 is before the first event. You're not losing any data here, it's just that the first event is stored in the first count. Or am I still missing something here?

It looks like it was very deliberately programmed this way, unless Thomas tells us otherwise.

Thanks

John

author
#4 lore raw
Quoted 20 lines · John Kacur
Quoted 16 lines · Frank Rowand
Quoted 15 lines · John Kacur
Quoted 8 lines · Frank Rowand

When the --verbose option is selected, the first value for each thread is incorrectly reported as zero.

This is because when collecting the first value, the index into stat->values is incremented from zero to one before storing the value. But when printing the values, the first value printed is stat->values[0], which has been initialized to zero.

Hi Frank

Quoted 8 lines
Quoted 4 lines
Quoted 2 lines

Ok, no more posting from me after winning a bottle of whiskey at the Irish Pub on quiz night. :)

Or if you do, you should share a bit of the whiskey with me.

You get the bottle and 30 shot glasses and share it with everyone at the pub, so if you want some you have to come, and then help my team win too :)

Hmmm, that's a long way to go for a shot.

Quoted 22 lines
Quoted 22 lines
Quoted 21 lines

I've been looking at this one, and I'm not sure about it. According to the help output,

"-v --verbose output values on stdout for statistics
format: n:c:v n=tasknum c=count v=value in us"

./cyclictest --verbose -p99 -t | awk '$2~/^0/{ print }'

       0:       0:       0
       1:       0:       0
       2:       0:       0
       3:       0:       0
       4:       0:       0
       5:       0:       0
       6:       0:       0
       7:       0:       0

So, it looks like the values are 0 at count 0, doesn't that make sense?

Quoted 8 lines
Quoted 3 lines

Nope. The event for count == 0 is the first event. And the first event has an actual latency that is not zero on the system I tested it on.

Hmmm, this may be a quibble about definitions. I know that in the c-world we're used to start counting at 0, but to me, count == 0 is before the first event. You're not losing any data here, it's just that the first event is stored in the first count. Or am I still missing something here?

In that case, there is no value in reporting event zero for each thread,
because it will always be: 0: 0: 0

Another thing that points to reporting latency == 0 is not intended is that the summary does not report a 'Min' of zero, even when the trace shows the first event having a latency of zero:

  # cyclictest -q --verbose -p99 -t -l 3
  Thread 0 Interval: 1500
  Thread 1 Interval: 2000
         0:       0:       0
         0:       1:     190
         0:       2:     166
         1:       0:       0
         1:       1:     178
         1:       2:     173
  T: 0 (  633) P:99 I:1000 C:      3 Min:    166 Act:  173 Avg:  176 Max:     190
  T: 1 (  634) P:98 I:1500 C:      3 Min:    138 Act:  138 Avg:  163 Max:     178