[PATCH] rt-tests: incorrect first latency value for --verbose option

[PATCH] rt-tests: incorrect first latency value for --verbose option

[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.

Signed-off-by: Frank Rowand <frank.rowand@am.sony.com>
---
 src/cyclictest/cyclictest.c |    3 	2 +	1 -	0 !
 1 file changed, 2 insertions(+), 1 deletion(-)

Index: b/src/cyclictest/cyclictest.c
===================================================================
--- a/src/cyclictest/cyclictest.c
+++ 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) {

Re: [PATCH] rt-tests: incorrect first latency value for --verbose option

[John Kacur]

On Wed, 2 May 2012, Frank Rowand wrote:

> 
> 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

Re: [PATCH] rt-tests: incorrect first latency value for --verbose option

[Frank Rowand]

On 05/07/12 14:41, John Kacur wrote:
> 
> 
> On Wed, 2 May 2012, Frank Rowand wrote:
> 
>>
>> 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. :)

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

> 
> 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?

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

Re: [PATCH] rt-tests: incorrect first latency value for --verbose option

[John Kacur]

On Mon, 7 May 2012, Frank Rowand wrote:

> On 05/07/12 14:41, John Kacur wrote:
> > 
> > 
> > On Wed, 2 May 2012, Frank Rowand wrote:
> > 
> >>
> >> 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. :)
> 
> 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 
:)

 > 
> > 
> > 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?
> 
> 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 

Re: [PATCH] rt-tests: incorrect first latency value for --verbose option

[Frank Rowand]

On 05/07/12 15:03, John Kacur wrote:
> 
> 
> On Mon, 7 May 2012, Frank Rowand wrote:
> 
>> On 05/07/12 14:41, John Kacur wrote:
>>>
>>>
>>> On Wed, 2 May 2012, Frank Rowand wrote:
>>>
>>>>
>>>> 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. :)
>>
>> 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.

> 
>  > 
>>>
>>> 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?
>>
>> 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