perf: h/w counters not counted and no error/info reported to user

perf: h/w counters not counted and no error/info reported to user

[David Ahern]

By default (tip-perf-core) perf-stat enables a number of H/W counters:

perf stat  -- sleep 1

Performance counter stats for 'sleep 1':

     1.346889 task-clock
            1 context-switches
            0 CPU-migrations
          157 page-faults
<not counted> cycles
<not counted> stalled-cycles-frontend
<not counted> stalled-cycles-backend
      493,740 instructions
      137,062 branches
        6,773 branch-misses

In this case 3 of them are not counted and perf does not tell me why.
I'm guessing that my processor (Core2 Duo T9550) does not support the
stalled cycles counters. Should perf not emit a message telling me that?

However, cycles is supported by the processor:

perf stat -e cycles -- sleep 1

Performance counter stats for 'sleep 1':

         1,091,102 cycles

Based on that I am guessing that only the last N requested events are
counted where N is processor specific. In my case N is apparently 3 as
this works:

perf stat -e cycles -e instructions -e branches -- sleep 1

 Performance counter stats for 'sleep 1':

    1,028,331 cycles
      634,101 instructions
      130,253 branches

but adding a fourth causes the first one to roll off -- again without
any message from perf:

perf stat -e cycles -e instructions -e branches -e branch-misses -v --
sleep 1
Performance counter stats for 'sleep 1':

<not counted> cycles
      219,727 instructions
      128,071 branches
        6,625 branch-misses

Which is confusing -- cycles are not counted, yet it should be given
that it is supported.

David

Re: perf: h/w counters not counted and no error/info reported to user

[Corey Ashford]

On 05/26/2011 03:10 PM, David Ahern wrote:
>
> By default (tip-perf-core) perf-stat enables a number of H/W counters:
>
> perf stat  -- sleep 1
>
> Performance counter stats for 'sleep 1':
>
>       1.346889 task-clock
>              1 context-switches
>              0 CPU-migrations
>            157 page-faults
> <not counted>  cycles
> <not counted>  stalled-cycles-frontend
> <not counted>  stalled-cycles-backend
>        493,740 instructions
>        137,062 branches
>          6,773 branch-misses
>
> In this case 3 of them are not counted and perf does not tell me why.
> I'm guessing that my processor (Core2 Duo T9550) does not support the
> stalled cycles counters. Should perf not emit a message telling me that?
>
> However, cycles is supported by the processor:
>
> perf stat -e cycles -- sleep 1
>
> Performance counter stats for 'sleep 1':
>
>           1,091,102 cycles

I suspect that what's happening is that "sleep 1" is not a very good 
test case, because it's sleeping most of the time.  The result is that 
some of the events don't have time enough to get counted because not 
enough system ticks occur while the "sleep 1" is running to get all of 
the events to be scheduled onto the PMU.

Try a simple problem which spins, or otherwise chews up cycles, for a 
second or so instead of sleeps.  I think you will get more events counted.

- Corey

Re: perf: h/w counters not counted and no error/info reported to user

[Ingo Molnar]

* David Ahern <dsahern@gmail.com> wrote:

> By default (tip-perf-core) perf-stat enables a number of H/W counters:
> 
> perf stat  -- sleep 1

did you mean to do 'perf stat -a sleep 1' ?

'perf stat sleep 1' in itself will only measure that very simple 
command - which does not do much.

Thanks,

	Ingo

Re: perf: h/w counters not counted and no error/info reported to user

[David Ahern]

On 05/27/2011 03:50 AM, Ingo Molnar wrote:
> 
> * David Ahern <dsahern@gmail.com> wrote:
> 
>> By default (tip-perf-core) perf-stat enables a number of H/W counters:
>>
>> perf stat  -- sleep 1
> 
> did you mean to do 'perf stat -a sleep 1' ?

Adding the -a has its own problems. It blocks reading from fd=0 (stdin);
I have to type Ctrl-D to see the results. The FD array gets initialized
to 0 and some case is not erroring out or setting the fd.

perf stat -a -- sleep 1

 Performance counter stats for 'sleep 1':

       2008.600377 task-clock
               545 context-switches
                31 CPU-migrations
               198 page-faults
       101,938,898 cycles
140,734,186,560,480 stalled-cycles-frontend
                 0 stalled-cycles-backend
       115,406,129 instructions

        26,361,321 branches
         1,068,804 branch-misses

       1.003842524 seconds time elapsed

The stalled-cycles-frontend is off the chats, but shows a value.
Similarly, backed shows 0 versus <not counted>.


> 
> 'perf stat sleep 1' in itself will only measure that very simple 
> command - which does not do much.

Simple program for a simple test. I just wanted to know which counters
are available for a given processor.

Per your comment and Corey's I tried a program that does some work:

perf stat -- openssl speed aes

Performance counter stats for 'openssl speed aes':

      44964.148608 task-clock
             4,593 context-switches
                48 CPU-migrations
               487 page-faults
   124,134,470,217 cycles
     <not counted> stalled-cycles-frontend
     <not counted> stalled-cycles-backend
   319,440,401,206 instructions
     6,710,107,937 branches
         1,638,412 branch-misses

      45.012092601 seconds time elapsed
This time I get data for 4 events -- which I did not get with sleep --
but I get <not counted> for the stalled cycles.

How is the <not counted> supposed to be interpreted?

Also, back to the 'perf stat -- sleep 1' example: If I run it with
individual -e <event> args I get values -- up to 3. Sure sleep is a
simple program, but some counter value comes out. What's magical about 3?

David


> 
> Thanks,
> 
> 	Ingo

Re: perf: h/w counters not counted and no error/info reported to user

[David Ahern]

On 05/27/2011 09:04 AM, David Ahern wrote:
> How is the <not counted> supposed to be interpreted?
> 
> Also, back to the 'perf stat -- sleep 1' example: If I run it with
> individual -e <event> args I get values -- up to 3. Sure sleep is a
> simple program, but some counter value comes out. What's magical about 3?

Ok, I got it now. On some occasions for simple programs -- like sleep 1
-- the counter reads show:

cycles: 0 1066485 0

While the counter value is non-0, the time enabled and running values
are 0 and those latter two are used by stat to say "not-counted".

Unsupported events have 0's across the board. I'm working on a patch to
change <not counted> to <not supported> for events marked as unsupported.

David

Re: perf: h/w counters not counted and no error/info reported to user

[Ingo Molnar]

* David Ahern <dsahern@gmail.com> wrote:

> 
> 
> On 05/27/2011 03:50 AM, Ingo Molnar wrote:
> > 
> > * David Ahern <dsahern@gmail.com> wrote:
> > 
> >> By default (tip-perf-core) perf-stat enables a number of H/W counters:
> >>
> >> perf stat  -- sleep 1
> > 
> > did you mean to do 'perf stat -a sleep 1' ?
> 
> Adding the -a has its own problems. It blocks reading from fd=0 
> (stdin); I have to type Ctrl-D to see the results. The FD array 
> gets initialized to 0 and some case is not erroring out or setting 
> the fd.

Ok, that's a bug (and you sent the fix for it already) - weird that i 
havent seen this before, i use perf stat -a sleep 1 type of analysis 
all the time.

Thanks,

	Ingo

Re: perf: h/w counters not counted and no error/info reported to user

[Ashwin Chaugule]

Hi David,

On Fri, May 27, 2011 at 12:36 PM, David Ahern <dsahern@gmail.com> wrote:
>
> Ok, I got it now. On some occasions for simple programs -- like sleep 1
> -- the counter reads show:
>
> cycles: 0 1066485 0
>
> While the counter value is non-0, the time enabled and running values
> are 0 and those latter two are used by stat to say "not-counted".

I've seen time-enabled = 0 too, but I suspected that's because on my
kernel the sched_clock implementation was missing. (defaults to a
jiffies based timer)
I saw your patch for initializing the fd's to -1's, but I'm unable to
see how that makes the value of time-enabled non zero ?

Cheers,
Ashwin

Re: perf: h/w counters not counted and no error/info reported to user

[David Ahern]

On 05/30/2011 03:04 PM, Ashwin Chaugule wrote:
> Hi David,
> 
> On Fri, May 27, 2011 at 12:36 PM, David Ahern <dsahern@gmail.com> wrote:
>>
>> Ok, I got it now. On some occasions for simple programs -- like sleep 1
>> -- the counter reads show:
>>
>> cycles: 0 1066485 0
>>
>> While the counter value is non-0, the time enabled and running values
>> are 0 and those latter two are used by stat to say "not-counted".
> 
> I've seen time-enabled = 0 too, but I suspected that's because on my
> kernel the sched_clock implementation was missing. (defaults to a
> jiffies based timer)

I think in the case of 'perf stat -- sleep 1' it runs so quickly that
sometimes it does not cross timer ticks and the time_enabled comes out 0.

> I saw your patch for initializing the fd's to -1's, but I'm unable to
> see how that makes the value of time-enabled non zero ?

It doesn't. That patch addresses unsupported counters in the default
list (e.g., -ddd on a T9550 Core2Duo). The first open fails (cpu 0,
thread 0) and the entire FD array is not reset to -1 (from its
initialization to 0).

David

> 
> Cheers,
> Ashwin