Understanding timestamps in perf.data

Understanding timestamps in perf.data

[Dennis Gnad]

Hi,

I am interested in timestamped performance counter data (with a 
specified sampling rate) as there is supposed to be saved in perf.data 
when I use "perf record -T".

However, I don't understand the complete output of "perf report -D", and 
can't figure out which parts of it are the timestamps. Is there any 
documentation that I overlooked?

Actually if it helps, I am only interested in the name/raw event, value, 
and timestamp, without any code/library information. Maybe the 
information on which CPU it is from (on a multicore) could be 
interesting as well.

Do I need to start looking into the code? Any good place to start? I 
probably need to do this anyway, instead of parsing the really large 
perf report -D output.

Thanks for your help and best regards,
Dennis

Re: Understanding timestamps in perf.data

[David Ahern]

On 9/2/15 3:28 AM, Dennis Gnad wrote:
> Hi,
>
> I am interested in timestamped performance counter data (with a
> specified sampling rate) as there is supposed to be saved in perf.data
> when I use "perf record -T".
>
> However, I don't understand the complete output of "perf report -D", and
> can't figure out which parts of it are the timestamps. Is there any
> documentation that I overlooked?
>
> Actually if it helps, I am only interested in the name/raw event, value,
> and timestamp, without any code/library information. Maybe the
> information on which CPU it is from (on a multicore) could be
> interesting as well.
>
> Do I need to start looking into the code? Any good place to start? I
> probably need to do this anyway, instead of parsing the really large
> perf report -D output.
>

Use 'perf script' instead of 'perf report -D' to dump the samples.

Re: Understanding timestamps in perf.data

[Dennis Gnad]

On 02.09.2015 15:43, David Ahern wrote:
> On 9/2/15 3:28 AM, Dennis Gnad wrote:
>> Hi,
>>
>> I am interested in timestamped performance counter data (with a
>> specified sampling rate) as there is supposed to be saved in perf.data
>> when I use "perf record -T".
>>
>> However, I don't understand the complete output of "perf report -D", and
>> can't figure out which parts of it are the timestamps. Is there any
>> documentation that I overlooked?
>>
>> Actually if it helps, I am only interested in the name/raw event, value,
>> and timestamp, without any code/library information. Maybe the
>> information on which CPU it is from (on a multicore) could be
>> interesting as well.
>>
>> Do I need to start looking into the code? Any good place to start? I
>> probably need to do this anyway, instead of parsing the really large
>> perf report -D output.
>>
>
> Use 'perf script' instead of 'perf report -D' to dump the samples.

OK, I really overlooked this. Thank you!

But now I am confused by that output. If I run for example:

$ perf record -F 100 -T -e cycles,cache-misses ./my_code

my understanding is, that at 100Hz, the values of the specified 
performance counters are read. But when I run:

$ perf script -f time,event
2001301.016880: cycles:
2001301.016883: cycles:
2001301.016885: cycles:
2001301.016886: cache-misses:
2001301.016887: cache-misses:
2001301.016889: cache-misses:
2001301.016890: cycles:
2001301.016925: cache-misses:
2001301.017000: cycles:
2001301.031339: cycles:
[..]

I don't get the values of the events, only that they "happened", which 
isn't that helpful if it is only sampled at a certain frequency. I also 
tried other options, but don't seem to be able to get the actually 
sampled values of the counters.

Any idea what am I missing? Much thanks in advance!

Re: Understanding timestamps in perf.data

[David Ahern]

On 9/2/15 9:18 AM, Dennis Gnad wrote:
> On 02.09.2015 15:43, David Ahern wrote:
>> On 9/2/15 3:28 AM, Dennis Gnad wrote:
>>> Hi,
>>>
>>> I am interested in timestamped performance counter data (with a
>>> specified sampling rate) as there is supposed to be saved in perf.data
>>> when I use "perf record -T".
>>>
>>> However, I don't understand the complete output of "perf report -D", and
>>> can't figure out which parts of it are the timestamps. Is there any
>>> documentation that I overlooked?
>>>
>>> Actually if it helps, I am only interested in the name/raw event, value,
>>> and timestamp, without any code/library information. Maybe the
>>> information on which CPU it is from (on a multicore) could be
>>> interesting as well.
>>>
>>> Do I need to start looking into the code? Any good place to start? I
>>> probably need to do this anyway, instead of parsing the really large
>>> perf report -D output.
>>>
>>
>> Use 'perf script' instead of 'perf report -D' to dump the samples.
>
> OK, I really overlooked this. Thank you!
>
> But now I am confused by that output. If I run for example:
>
> $ perf record -F 100 -T -e cycles,cache-misses ./my_code
>
> my understanding is, that at 100Hz, the values of the specified
> performance counters are read. But when I run:
>
> $ perf script -f time,event
> 2001301.016880: cycles:
> 2001301.016883: cycles:
> 2001301.016885: cycles:
> 2001301.016886: cache-misses:
> 2001301.016887: cache-misses:
> 2001301.016889: cache-misses:
> 2001301.016890: cycles:
> 2001301.016925: cache-misses:
> 2001301.017000: cycles:
> 2001301.031339: cycles:
> [..]
>
> I don't get the values of the events, only that they "happened", which
> isn't that helpful if it is only sampled at a certain frequency. I also
> tried other options, but don't seem to be able to get the actually
> sampled values of the counters.
>
> Any idea what am I missing? Much thanks in advance!

The counter values are not relevant for profiling. They are programmed 
to rollover and generate an NMI which causes the sample to be taken.

David

Re: Understanding timestamps in perf.data

[David Ahern]

On 9/2/15 11:00 AM, Vince Weaver wrote:
> On Wed, 2 Sep 2015, David Ahern wrote:
>> The counter values are not relevant for profiling. They are programmed to
>> rollover and generate an NMI which causes the sample to be taken.
>
> They might not be relevant for profiling, but some people use the perf
> counters for other tasks.

Dennis was asking about profiling.

Re: Understanding timestamps in perf.data

[Vince Weaver]

On Wed, 2 Sep 2015, David Ahern wrote:
> The counter values are not relevant for profiling. They are programmed to
> rollover and generate an NMI which causes the sample to be taken.

They might not be relevant for profiling, but some people use the perf 
counters for other tasks.

For example, when measuring phase plot behavior for a system, it would be 
great if you'd be able to say I want a snapshot sample of the cycle and 
instruction counters every 10ms, and then you can plot the CPI behavior of 
the system.

as far as I can tell you can't really do this with perf (the -I option 
only lets you get down to 100ms).

I ended up trying to write a custom program to do this, but it turns out 
the perf sampling interface has really high overhead when doing this, and 
the interrupt throttle kicks in which makes it useless.

It's a shame, as the old "pfmon" tool that came with perfmon2 could do 
this kind of measurement very easily.

Vince

Re: Understanding timestamps in perf.data

[Andi Kleen]

David Ahern <dsahern@gmail.com> writes:
>
> The counter values are not relevant for profiling. They are programmed
> to rollover and generate an NMI which causes the sample to be taken.

Actually it's relevent if you use adaptive frequency mode
(-F or default, not using -c) because it varies then.

The count values are reported by default in perf script.

-Andi

Re: Understanding timestamps in perf.data

[David Ahern]

On 9/2/15 1:23 PM, Andi Kleen wrote:
> David Ahern <dsahern@gmail.com> writes:
>>
>> The counter values are not relevant for profiling. They are programmed
>> to rollover and generate an NMI which causes the sample to be taken.
>
> Actually it's relevent if you use adaptive frequency mode
> (-F or default, not using -c) because it varies then.

In all cases the counters are set to rollover for profiling mode.

Re: Understanding timestamps in perf.data

[Dennis Gnad]

On 02.09.2015 19:00, Vince Weaver wrote:
> They might not be relevant for profiling, but some people use the perf
> counters for other tasks.
>
> For example, when measuring phase plot behavior for a system, it would be
> great if you'd be able to say I want a snapshot sample of the cycle and
> instruction counters every 10ms, and then you can plot the CPI behavior of
> the system.

Yeah, actually I wasn't asking about profiling, sorry if this was 
misunderstood for some reason. I am looking into something you could 
call 'workload characterization' and really need the absolute 
performance counter values, as they could for example correlate with the 
resulting temperature or energy-optimal frequency of the cpu/system, 
depending on its specific workload.

> as far as I can tell you can't really do this with perf (the -I option
> only lets you get down to 100ms).

Which -I option do you mean? At least it's not available for my perf 
record (kernel 3.16).

> I ended up trying to write a custom program to do this, but it turns out
> the perf sampling interface has really high overhead when doing this, and
> the interrupt throttle kicks in which makes it useless.

Are you talking about the kernel interface or some interface of the perf 
tool? I think I need a minimum of 100Hz or 1000Hz, but it wouldn't be a 
problem if this is just collected in some kernel shared memory and in 
the end copied to userspace, or at a lower frequency.

> It's a shame, as the old "pfmon" tool that came with perfmon2 could do
> this kind of measurement very easily.
>
> Vince
>

This can not be used with current kernels, I guess? I tried "oprofile" 
before, which can show absolute counts, but instead doesn't support any 
timestamps.

So, it seems there is nothing available that can do what I need. Maybe 
some of you can still recommend where I could start looking next or go 
into more detail? Kernel, perf, oprofile, libpapi are the things that 
come to my mind. If the kernel interface is really the bottleneck, it 
probably has to be there.

Thanks for your help so far,
Dennis

Re: Understanding timestamps in perf.data

[Dennis Gnad]

On 02.09.2015 21:23, Andi Kleen wrote:
> David Ahern <dsahern@gmail.com> writes:
>> The counter values are not relevant for profiling. They are programmed
>> to rollover and generate an NMI which causes the sample to be taken.
> Actually it's relevent if you use adaptive frequency mode
> (-F or default, not using -c) because it varies then.
>
> The count values are reported by default in perf script.
>
> -Andi
Was this only more recently added to perf? I can't see it for kernel 3.16.

Re: Understanding timestamps in perf.data

[Vince Weaver]

On Thu, 3 Sep 2015, Dennis Gnad wrote:
> 
> > as far as I can tell you can't really do this with perf (the -I option
> > only lets you get down to 100ms).
> 
> Which -I option do you mean? At least it's not available for my perf record
> (kernel 3.16).

The -I option is for "perf stat".  It lets you print the counters at a 
regular time interval.

Something like
	perf_3.16 stat -e cycles,instructions -I 100 sleep 1

> 
> > I ended up trying to write a custom program to do this, but it turns out
> > the perf sampling interface has really high overhead when doing this, and
> > the interrupt throttle kicks in which makes it useless.
> 
> Are you talking about the kernel interface or some interface of the perf tool?
> I think I need a minimum of 100Hz or 1000Hz, but it wouldn't be a problem if
> this is just collected in some kernel shared memory and in the end copied to
> userspace, or at a lower frequency.

The kernel itself has trouble going to 100Hz without causing a lot of 
overhead and at 1kHz the NMI overhead gets high enough that the kernel 
throttles things down.  I haven't investigated why that is, it might be a 
problem with how my tool is coded.  For now I just gave up and am making 
masurements at 10Hz.

Vince

Re: Understanding timestamps in perf.data

[Dennis Gnad]

On 03.09.2015 14:52, Vince Weaver wrote
>
> The kernel itself has trouble going to 100Hz without causing a lot of
> overhead and at 1kHz the NMI overhead gets high enough that the kernel
> throttles things down.  I haven't investigated why that is, it might be a
> problem with how my tool is coded.  For now I just gave up and am making
> masurements at 10Hz.
OK thanks for this information. I can probably now exclude the current 
perf-interface of the kernel.

Maybe this is also interesting for you then:

In the meantime I got some information for the x86 architecture. There, 
the performance counters can be read directly in userspace by the 
interface over MSR's similar to readmsr/msrtool, where a reliable 
interval of <10ms can be achieved. [1]

For ARM, there seems to exist some specialized driver "gator" which I 
didn't take a closer look.

Anyhow, I am currently looking at a Power7 system, and don't know of any 
other interfaces there than perf/oprofile. I will continue to try to 
find some more information about that.

Best regards,
Dennis


[1] *F. Oboril*, J. Ewert, and M. B. Tahoori, "High-Resolution Online 
Power Monitoring for Modern Microprocessors," in Proceedings of Design, 
Automation & Test in Europe (*DATE*), 2015, France. Online available: 
*http://cdnc.itec.kit.edu/downloads/Papers/Oboril15DATE.pdf
*

Re: Understanding timestamps in perf.data

[Vince Weaver]

On Thu, 3 Sep 2015, Dennis Gnad wrote:

> In the meantime I got some information for the x86 architecture. There, the
> performance counters can be read directly in userspace by the interface over
> MSR's similar to readmsr/msrtool, where a reliable interval of <10ms can be
> achieved. [1]

this is probably getting a bit off topic for linux-perf-users, but yes, I 
was doing similar work recently.  I was trying to validate the RAPL 
values (which are only estimates, not actual sensor results, on most 
CPUs).  This involved trying to read the RAPL and perf counters at a high 
rate of speed.

And yes, it seems that reading the MSRs directly from userspace has a lot 
less overhead than trying to use the perf_event sampling interface.  I had 
hoped that having an in-kernel ring buffer would be faster than just 
manually dumping the results to disk continually from userspace, but maybe 
NMI overhead is just too high.

Vince