Re: Fwd: Potential deadlock in operf when using --pid

[大平怜 <rei.odaira@gm...>]

Thanks for reviewing the patches, Will,

I am trying to remember the code....  As far as I understand, the comm
pipes are used only for newly spawned processes.  I need to investigate
more to see if they can be removed.

It is less likely, but theoretically it is possible that the comm pipe gets
full first and as a result the sample output pipe gets full next.  In any
case, my patches should solve the issue.


Thanks,
Rei Odaira

2017-06-30 14:50 GMT-05:00 William Cohen <wcohen@...>:

> On 06/24/2016 08:06 PM, 大平怜 wrote:
> > I forgot to include oprofile-list.
> >
> >
> > Regards,
> > Rei Odaira
> >
> > ---------- Forwarded message ----------
> > From: *大平怜* <rei.odaira@... <mailto:rei.odaira@...>>
> > Date: 2016-06-24 19:04 GMT-05:00
> > Subject: Re: Potential deadlock in operf when using --pid
> > To: William Cohen <wcohen@... <mailto:wcohen@...>>
> >
> >
> > Hi,
> >
> > Now I come back to this problem.
> >
> > I am attaching two patches to solve it.  They apply to the latest master
> in the git repository.  Please apply oprofile_avoid_deadlock_1.patch
> first and then oprofile_avoid_deadlock_2.patch. The first patch is just
> for refactoring the code to make the second patch possible, and the second
> patch is for the actual problem solving.
> >
> > So, the problem is that the operf-record process is blocked on a write
> to the sample output pipe when the pipe is full, while the operf-read
> process, which is the consumer of the pipe, cannot read from the pipe
> because it is blocked on a read from the comm pipe, to which the
> operf-record process is supposed to write.  Please refer to the previous
> emails for the detailed problem description.
> >
> >             |<--sample output pipe--|
> > operf-read  |-------comm pipe------>|  operf-record
> >             |<------comm pipe-------|
> >
> > My solution is to make the sample output pipe non-blocking on the
> operf-record side.  When the sample output pipe is full, instead of waiting
> on it, the operf-record process polls both the sample output pipe and the
> (read-end of) comm pipe.  If there is a message in the comm pipe from the
> operf-read process, the operf-record process handles it and writes a
> response to the comm pipe, so that the operf-read process can finish being
> blocked on the read from the comm pipe and eventually can consume the
> sample output pipe.
> >
> > There are some other ways to solve this problem, so any comments are
> welcome.  With my patches, you can finish profiling
> oprofile_multithread_test by a single ctrl-c. They passed all the tests in
> oprofile-tests.
> >
> >
> > Regards,
> > Rei Odaira
> >
>
>
>
>
> Hi Da Rei,
>
> Sorry for missing the patches to address rapid thread
> creation/deletion deadlock issue.  I have been taking a look at them.
> As a sanity check I ran the testsuite before and after the patches and
> things look the same.
>
> Test results before the patches:
>
>                 === oprofile Summary ===
>
> # of expected passes            149
>
> kernel version: 4.11.5-200.fc25.x86_64
> userspace version: oprofile 1.2.0git compiled on Jun 29 2017 13:59:35
>
>
> Test results after the patches:
>
>                 === oprofile Summary ===
>
> # of expected passes            149
>
> kernel version: 4.11.5-200.fc25.x86_64
> userspace version: oprofile 1.2.0git compiled on Jun 29 2017 14:10:33
>
>
> The patches does appear to help with the issue demonstrated with the
> reporducer oprofile_mutithread_test with operations per thread of
> 1000000.  However, with smaller number of operations per thread
> settings (100000) operf has issue getting connected:
>
> $ operf --pid 7555
> !!!! No samples collected !!!
> The target program/command ended before profiling was started.
> operf record init failed
> usage: operf [ options ] [ --system-wide | --pid <pid> | [ command [ args
> ] ] ]
> Error running profiler
>
>
> Or if it is able to connect (the process was paused with cntl-z and
> then put back in the foreground after oprofile had attached):
>
> $ operf --pid 7555
> ...
> Unable to collect samples for forked process 17240. Process may have ended
> before recording could be started.
> Unable to collect samples for forked process 17241. Process may have ended
> before recording could be started.
> Unable to collect samples for forked process 17242. Process may have ended
> before recording could be started.
> Unable to collect samples for forked process 17243. Process may have ended
> before recording could be started.
> Failed to mmap kernel profile data.
> This issue may be caused by a non-root user running multiple operf
> sessions simultaneously. Try running as root or increasing the value of
> /proc/sys/kernel/perf_event_mlock_kb to resolve the problem.
>
> Unable to collect samples for forked process 17245. Process may have ended
> before recording could be started.
>
>
> Is is notable that perf has similar problems it is unable to attach to
> quickly spawning processes
>
> $ perf record --pid 7555
> Error:
> The sys_perf_event_open() syscall returned with 3 (No such process) for
> event (cycles).
> /bin/dmesg may provide additional information.
> No CONFIG_PERF_EVENTS=y kernel support configured?
> [wcohen@... oprofile]$ perf record --pid 7555
> ^C[ perf record: Woken up 81 times to write data ]
>
> However "perf record --pid 7555" is able to collect data without issue
> if the 7555 is paused when "perf record" starts up.  I have let the
> perf developers know about this issue.
>
>
> The portion of oprofile the patches affect is not easy to follow, so I
> am still trying to make sure I fully understand the issue and that the
> patches address the issue without introducing some other issue.
> Earlier email has the following diagram:
>
>
>             |<--sample output pipe--|
> operf-read  |-------comm pipe------>|  operf-record
>             |<------comm pipe-------|
>
>
> The data in the sample "sample output pipe" stream includes the
> PERF_RECORD_FORK events.  The operf-read processes the
> PERF_RECORD_FORK events in the stream and sends pid back up the comm
> pipe for operf-record add another thread.
>
> Is the comm pipe only being used to communicate the new processes to be
> monitored?
>
> Would it be possible to have operf-record just do that directly rather
> than having to make a round trip from operf-record to operf-read and
> back to operf-record?  Seems like there is a lot of overhead when
> starting to monitoring a new thread.
>
> The patches implement polling to avoid the opef-record getting hung
> and in turn causing operf-read getting stuck when sample output pipe
> gets full.  Is there any way that the comm pipe might similarly get
> full and cause a hang?
>
> -Will
>

Re: Operf and Opreport outputs

[Michael Petlan <mpetlan@re...>]

Hi Dhara,

On Thu, 6 Jul 2017, dhara buch wrote:
> Hello,
> I tried the perf-hello.c file and found the results as you explained. It is very helpful to me. Now, for
> PERF_COUNT_HW_BRANCH_MISSES, I am getting varying values every time unlike PERF_COUNT_HW_INSTRUCTIONS.  

Try to compare:

PERF_COUNT_HW_BRANCH_INSTRUCTIONS against PERF_COUNT_HW_BRANCH_MISSES.

The first one is how many branching instructions have been used, the second is
how many branch predictions were wrong. I am always getting almost the same
values of _BRANCH_INSTRUCTIONS, the values of _BRANCH_MISSES differ. That
makes sense, since from some constant number of branch instructions (these
are conditional jumps, loops, etc), some were mispredicted. The branch
prediction works pretty well, but it is not 100% successful. I am getting
around 6% of missed branches:

 	PERF_COUNT_HW_BRANCH_INSTRUCTIONS = 4541
 	PERF_COUNT_HW_BRANCH_MISSES = 272

but another run slightly differs in _BRANCH_MISSES while still having the
same number of branch instructions:

 	PERF_COUNT_HW_BRANCH_INSTRUCTIONS = 4541
 	PERF_COUNT_HW_BRANCH_MISSES = 248



It seems that the "more effective" factorial computation function not only
consumes slightly less instructions and cycles, but it also consumes
slightly less branch instructions and the branch prediction works slightly
better there:

My results look like this:

Ineffective method:
 	PERF_COUNT_HW_BRANCH_INSTRUCTIONS = 4541
 	PERF_COUNT_HW_BRANCH_MISSES = 258

More effective method:
 	PERF_COUNT_HW_BRANCH_INSTRUCTIONS = 4334
 	PERF_COUNT_HW_BRANCH_MISSES = 97

This is expectable and expected.

> 
> To get count for only defined process,

You are counting only the process and, also, in my example, you are counting
just the code between myperf_event_restart() and myperf_event_stop() functions.

The only dust you see in the measurements is that kernel might suspend your
process and schedule some other process in meanwhile, which may invalidate
the caches or spoil the branch guessing (I don't know how exactly this works)
--> so you cannot expect the metrics such as branch misses, cycles, etc. to
be 100% deterministic from your point of view.

> I am trying to set perf_event_attr structure variables sample_type
> as PERF_SAMPLE_BRANCH_STACK and branch_sample_type as PERF_SAMPLE_BRANCH_USER. By doing so, I am getting error no. 5 by
> perf_event_open. What may be the problem?

These variables are for something completely different. See the manpage for
"perf_event_open". The syscall returns error, because you misconfigured the
perf_event_attr structure to invalid values.

As I've already said: You don't need to tweak anything else, you already are
counting just the process you want.

> 
> Dhara Buch

Cheers,
Michael

> 
> On Mon, Jun 19, 2017 at 5:51 PM, Michael Petlan <mpetlan@...> wrote:
>       On Mon, 19 Jun 2017, dhara buch wrote:
>       > Hello,
>       > Thanks a lot for the detailed explanation. I could understand the working of operf and opreport.
>       > Unlike operf, ocount counts each occurrence of the monitored event. In such a case, why ocount also gives
>       varying values of CPU_CLK_UNHALTED even when the monitored code doesn't get
>       > changed. Is it because of background processes? If so, then can we get event count for only monitored
>       command?
>
>       Hi Dhara,
>
>       it is kind of because of the background processes, but not in the way that ocount
>       would count also their CPU consumption. If you don't use '-s' option, ocount will
>       count only what your command does.
>
>       However, it counts either kernelspace, userspace or both (default if you are root).
>       This can be configured by the event's flags:
>
>       Both:
>       -e CPU_CLK_UNHALTED:0:1:1
>
>       Only kernelspace (used by the command, i.e. syscalls, etc):
>       -e CPU_CLK_UNHALTED:0:1:0
>
>       Only userspace (i.e. syscalls are excluded):
>       -e CPU_CLK_UNHALTED:0:0:1
>
>       (the format is (ocount): event:umask:kernelspace:userspace,
>       for operf it is: event:umask:sample_rate:kernelspace:userspace)
>
>       The numbers are slightly different each run because the process does not live in
>       vacuum. It is usually dynamically linked, it calls libraries, kernel switches
>       contexts, etc. All these things cause the differences. Also, the CPU optimizes
>       the execution with floating success, depending on what else runs there with it.
>       If the process is interrupted many times, the CPU consumption will be higher.
>
>       I have a sample code which I linked dynamically and statically. While the dyn.
>       linked executable always takes around 670,260 cycles, the statically linked one
>       takes around 380,202 and seems to be more steady. Since it is very simple code,
>       you can see that the linker-related stuff took more than 40% of the CPU cycles).
>
>       Executing a binary is so complex problem that there is no surprise that those
>       measurements give different values every time.
>
>       ........
>
>       TIP:
>
>       You can use either papi library or the built-in kernel support for counting
>       just a particular part of code, e.g. a function. I have attached one example
>       which uses perfevents kernel background. I have two functions for factorial
>       counting, one is slightly less effective than the other. I count cycles and
>       instructions for both. When executing repeatedly, you can see, that the inst.
>       count is the same all the time (at least on my laptop), but the cycles count
>       differs even for just the stuff in the functions which are very simple.
>
>       cc -o perf-hello perf-hello.c myperf.c
>       ./perf-hello
>
>       Ineffective method:
>               PERF_COUNT_HW_CPU_CYCLES = 32192
>               PERF_COUNT_HW_INSTRUCTIONS = 20681
>
>       More effective method:
>               PERF_COUNT_HW_CPU_CYCLES = 15931
>               PERF_COUNT_HW_INSTRUCTIONS = 19103
>
>       ........
>
>       Cheers,
>       Michael
> 
>
>       >
>       > Thank you,
>       >
>       > On Fri, Jun 16, 2017 at 4:52 PM, Michael Petlan <mpetlan@...> wrote:
>       >       On Fri, 16 Jun 2017, dhara buch wrote:
>       >       > Hello,
>       >       >
>       >       > Many days ago you had helped me a lot in using Oprofile in Virtual Machine. That time, I also had a
>       query regarding
>       >       > getting information from 'opreport --symbols --debuginfo' command.
>       >
>       >       Hello,
>       >
>       >       yeah, I remember...
>       >
>       >       >
>       >       > Actually, I am profiling a file1.c file with the following commands...
>       >       >
>       >       > 1. gcc -g file1.c -o file1
>       >       >
>       >       > 2. operf ./file1 --events=CPU_CLK_UNHALTED
>       >       >
>       >       > 3. opreport --symbols --debuginfo
>       >       >
>       >       > the output contains various lines where one line look follows:
>       >       >
>       >       > samples  %        linenr info                 image name               symbol name
>       >       >
>       >       > 2       12.5000  rsaimp.c:16                 rsaimp                   MM
>       >       > 2        12.5000  rsaimp.c:34                 rsaimp                   main
>       >       >
>       >       > When I execute commands 2 and 3 multiple times, each time I gwt the output for symbole name MM
>       (which is UDF in the
>       >       > program) but I don't get output for main every time.
>       >       >
>       >       This is kind of random, see below.
>       >
>       >       > Additionally,'' the sample % also vary every time I file operf command. I do not understand the
>       working of operf that
>       >       > how it gives different outputs for the same program.
>       >       >
>       >
>       >       How _counting_ works:
>       >
>       >       Each time an event happens in CPU (in our case -- CPU_CLK_UNHALTED -- one
>       >       CPU tick), its counter is incremented by one. This way, you can get the
>       >       whole number of how many times the event happened:
>       >
>       >       $ ocount ls
>       >       Events were actively counted for 1863267 nanoseconds.
>       >       Event counts (actual) for /bin/ls:
>       >                 Event                    Count                    % time counted
>       >                 CPU_CLK_UNHALTED         2,672,309                100.00
>       >
>       >       This means that there were 2.672 million CPU ticks necessary to execute
>       >       `ls`.
>       >
>       >       The tool for counting is *ocount*.
>       >
>       >
>       >       How _profiling_ works:
>       >
>       >       For profiling, events are counted the same way as when counting, but only
>       >       once per N event occurrences a "sample" is taken. A sample is a piece of
>       >       information about where in the code it happened, what was the context and
>       >       potentially call-stack, etc. This sample is saved into the oprofile_data
>       >       dir structure. When you finish profiling, opreport generates some overview
>       >       from the samples recorded.
>       >
>       >       Of course, taking sample causes some overhead. Thus, you cannot take it
>       >       each time the event counter increments. For this purpose, there is "sample
>       >       rate" value which divides the event counter and takes a sample only once
>       >       per "sample rate" occurrences. Thus, it is pretty random, which event
>       >       occurrence is picked for a sample.
>       >
>       >       Of course, your main() consumes CPU ticks and the counter is incremented,
>       >       but sometimes, one of these incrementations produces sample, sometimes not,
>       >       thus the function is missing.
>       >
>       >       You have 2 samples on each of the line in the report. That is really a low
>       >       number, so it is very probable that sometimes the samples hit main() and
>       >       sometimes not.
>       >
>       >       $ operf ls
>       >       Profiling done.
>       >
>       >       $ opreport
>       >       Using /root/oprofile_data/samples/ for samples directory.
>       >       CPU: Core 2, speed 2267 MHz (estimated)
>       >       Counted CPU_CLK_UNHALTED events (Clock cycles when not halted) with a unit mask of 0x00 (Unhalted
>       core cycles) count 100000
>       >       CPU_CLK_UNHALT...|
>       >         samples|      %|
>       >       ------------------
>       >        -->   37 100.000 ls
>       >              CPU_CLK_UNHALT...|
>       >                samples|      %|
>       >                        ------------------
>       >                     27 72.9730 kallsyms
>       >                      5 13.5135 libc-2.19.so
>       >                      2  5.4054 ld-2.19.so
>       >                      1  2.7027 ls
>       >                      1  2.7027 ext4
>       >                      1  2.7027 libattr.so.1.1.0
>       >
>       >       You see that out of (estimated) 2.5-3.5 mil of event occurrences (which is
>       >       the scale `ls` usually needs on my PC), I got only 37 samples.
>       >
>       >       The sample rate for each event are in `ophelp` as "min count".
>       >
>       >       Why did I get 37 samples? My default setting of default event is:
>       >
>       >       $ ophelp -d
>       >       CPU_CLK_UNHALTED:100000:0:1:1
>       >       -------------------^^
>       >
>       >       This means that there is 1 sample per 100000 event occurrences.
>       >
>       >       You can tweak this value a bit, but note that oprofile won't let you set
>       >       the value to be too low, due to the overhead reasons.
>       >
>       >       Let's try 10000 (sampling 10 times more often):
>       >
>       >       $ operf -e CPU_CLK_UNHALTED:10000 ls
>       >       WARNING: Lost samples detected! See /root/oprofile_data/samples/operf.log for details.
>       >       Lowering the sampling rate may reduce or eliminate lost samples.
>       >       See the '--events' option description in the operf man page for help.
>       >       Profiling done.
>       >
>       >       $ opreport
>       >       Using /root/oprofile_data/samples/ for samples directory.
>       >       WARNING: Lost samples detected! See /root/oprofile_data/samples/operf.log for details.
>       >       CPU: Core 2, speed 2267 MHz (estimated)
>       >       Counted CPU_CLK_UNHALTED events (Clock cycles when not halted) with a unit mask of 0x00 (Unhalted
>       core cycles) count 10000
>       >       CPU_CLK_UNHALT...|
>       >         samples|      %|
>       >       ------------------
>       >             429 100.000 ls
>       >             CPU_CLK_UNHALT...|
>       >               samples|      %|
>       >               ------------------
>       >                     313 72.9604 kallsyms
>       >                      55 12.8205 ld-2.19.so
>       >                      34  7.9254 libc-2.19.so
>       >                      17  3.9627 ls
>       >                       8  1.8648 ext4
>       >                       2  0.4662 binfmt_misc
>       >
>       >       You see that both operf and opreport warned about lost samples which means
>       >       that the overhead in kernel was too high and some samples were lost. But
>       >       probably not that many, since you see that I got 429 samples instead of
>       >       37 which is very roughly 10 times more.
>       >
>       >
>       >       Profiling is not for exact measurement of how many CPU ticks happened in
>       >       a function, it is rather designed for relative comparison across your code.
>       >
>       >       If you are getting too few samples, try to decrease the sample rate as I
>       >       did in the example. Have a look at `ophelp` what is the lowest value for
>       >       your event.
>       >
>       >       Also please note that the min sample rates are rough and depend on the load,
>       >       so under low load, lower rates can be used without issues. When you profile
>       >       systemwide on all CPUs, it's very high chance that you'll run into an overhead
>       >       and lose many samples...
>       >
>       >       I hope I explained it a bit.
>       >
>       >       Cheers,
>       >       Michael
>       >
>       >       > Thanks,
>       >       >
>       >       > Dhara Buch
>       >       >
>       >       >
>       >
>       >
>       >
>       >
> 
> 
> 
>

OProfile-1.2.0-rc2

[William Cohen <wcohen@re...>]

Due to some fixes for "make check" made oprofile-1.2.0-rc2.tar.gz. Proposed fixes to address the rapid thread spawning  are not this release.

URL:
https://sourceforge.net/projects/oprofile/files/oprofile/oprofile-1.2.0rc2/oprofile-1.2.0rc2.tar.gz/download
 
RELEASE NOTES:


OProfile is a powerful system-wide profiler for Linux.
Read more at http://oprofile.sf.net

OProfile 1.2.0 has been released.

New features
------------

- New/updated Processor Support
    * ARM Cortex A17
    * IBM Power 9
    * IBM Power 8NV and NVL variants
    * IBM z13
    * Intel Goldmont
    * Intel Kabylake
    * Intel Xeon Phi (Knights Landing)
    * Achitecture specific events for Applied Micro X-Gene

Bug fixes
---------

Filed bug reports:
-------------------------------------------------------------------------
|  BUG ID   |  Summary 
|-----------|------------------------------------------------------------
|  286      | Compilation error: left shift of negative value
|  288      | oprofile fails to build with --enable-pch and gcc-6.2 
-------------------------------------------------------------------------

Other bug fixes and improvements without a filed report (e.g., posted to the lis
t):
---------------
   - Fixed compile warning and errors when using GCC 6 or GCC 7
   - Avoid using deprecated readdir_r function
   - Store samples in the archive and search the appropriate places
     for samples
   - Only start the application if the perf events setup was successful
   - Corrections in the code and i386 events so "make check" tests pass


Known problems and limitations
-------------------------

- When using operf to profile multiple events, the absolute number of
  events recorded may be substantially fewer than expected. This can
  be due to known bug in the Linux kernel's Performance Events
  Subsystem that was fixed sometime between Linux kernel version 3.1
  and 3.5.

- Monitoring processes that frequently create and destroy threads via
  the "--pid" option can be problematic.  The pipes used within operf
  and ocount may fill up can cause these programs to hang and require
  multiple cntl-C to exit rather than successfully collecting data on
  fast spawning processes and children.

Re: Operf and Opreport outputs

[dhara buch <dharabuchphd@gm...>]

Hello,

I tried the perf-hello.c file and found the results as you explained. It is
very helpful to me. Now, for PERF_COUNT_HW_BRANCH_MISSES, I am getting
varying values every time unlike PERF_COUNT_HW_INSTRUCTIONS.

To get count for only defined process, I am trying to set perf_event_attr
structure variables sample_type as PERF_SAMPLE_BRANCH_STACK and
branch_sample_type as PERF_SAMPLE_BRANCH_USER. By doing so, I am getting
error no. 5 by perf_event_open. What may be the problem?

Dhara Buch

On Mon, Jun 19, 2017 at 5:51 PM, Michael Petlan <mpetlan@...> wrote:

> On Mon, 19 Jun 2017, dhara buch wrote:
> > Hello,
> > Thanks a lot for the detailed explanation. I could understand the
> working of operf and opreport.
> > Unlike operf, ocount counts each occurrence of the monitored event. In
> such a case, why ocount also gives varying values of CPU_CLK_UNHALTED even
> when the monitored code doesn't get
> > changed. Is it because of background processes? If so, then can we get
> event count for only monitored command?
>
> Hi Dhara,
>
> it is kind of because of the background processes, but not in the way that
> ocount
> would count also their CPU consumption. If you don't use '-s' option,
> ocount will
> count only what your command does.
>
> However, it counts either kernelspace, userspace or both (default if you
> are root).
> This can be configured by the event's flags:
>
> Both:
> -e CPU_CLK_UNHALTED:0:1:1
>
> Only kernelspace (used by the command, i.e. syscalls, etc):
> -e CPU_CLK_UNHALTED:0:1:0
>
> Only userspace (i.e. syscalls are excluded):
> -e CPU_CLK_UNHALTED:0:0:1
>
> (the format is (ocount): event:umask:kernelspace:userspace,
> for operf it is: event:umask:sample_rate:kernelspace:userspace)
>
> The numbers are slightly different each run because the process does not
> live in
> vacuum. It is usually dynamically linked, it calls libraries, kernel
> switches
> contexts, etc. All these things cause the differences. Also, the CPU
> optimizes
> the execution with floating success, depending on what else runs there
> with it.
> If the process is interrupted many times, the CPU consumption will be
> higher.
>
> I have a sample code which I linked dynamically and statically. While the
> dyn.
> linked executable always takes around 670,260 cycles, the statically
> linked one
> takes around 380,202 and seems to be more steady. Since it is very simple
> code,
> you can see that the linker-related stuff took more than 40% of the CPU
> cycles).
>
> Executing a binary is so complex problem that there is no surprise that
> those
> measurements give different values every time.
>
> ........
>
> TIP:
>
> You can use either papi library or the built-in kernel support for counting
> just a particular part of code, e.g. a function. I have attached one
> example
> which uses perfevents kernel background. I have two functions for factorial
> counting, one is slightly less effective than the other. I count cycles and
> instructions for both. When executing repeatedly, you can see, that the
> inst.
> count is the same all the time (at least on my laptop), but the cycles
> count
> differs even for just the stuff in the functions which are very simple.
>
> cc -o perf-hello perf-hello.c myperf.c
> ./perf-hello
>
> Ineffective method:
>         PERF_COUNT_HW_CPU_CYCLES = 32192
>         PERF_COUNT_HW_INSTRUCTIONS = 20681
>
> More effective method:
>         PERF_COUNT_HW_CPU_CYCLES = 15931
>         PERF_COUNT_HW_INSTRUCTIONS = 19103
>
> ........
>
> Cheers,
> Michael
>
>
> >
> > Thank you,
> >
> > On Fri, Jun 16, 2017 at 4:52 PM, Michael Petlan <mpetlan@...>
> wrote:
> >       On Fri, 16 Jun 2017, dhara buch wrote:
> >       > Hello,
> >       >
> >       > Many days ago you had helped me a lot in using Oprofile in
> Virtual Machine. That time, I also had a query regarding
> >       > getting information from 'opreport --symbols --debuginfo'
> command.
> >
> >       Hello,
> >
> >       yeah, I remember...
> >
> >       >
> >       > Actually, I am profiling a file1.c file with the following
> commands...
> >       >
> >       > 1. gcc -g file1.c -o file1
> >       >
> >       > 2. operf ./file1 --events=CPU_CLK_UNHALTED
> >       >
> >       > 3. opreport --symbols --debuginfo
> >       >
> >       > the output contains various lines where one line look follows:
> >       >
> >       > samples  %        linenr info                 image
> name               symbol name
> >       >
> >       > 2       12.5000  rsaimp.c:16
> rsaimp                   MM
> >       > 2        12.5000  rsaimp.c:34
> rsaimp                   main
> >       >
> >       > When I execute commands 2 and 3 multiple times, each time I gwt
> the output for symbole name MM (which is UDF in the
> >       > program) but I don't get output for main every time.
> >       >
> >       This is kind of random, see below.
> >
> >       > Additionally,'' the sample % also vary every time I file operf
> command. I do not understand the working of operf that
> >       > how it gives different outputs for the same program.
> >       >
> >
> >       How _counting_ works:
> >
> >       Each time an event happens in CPU (in our case -- CPU_CLK_UNHALTED
> -- one
> >       CPU tick), its counter is incremented by one. This way, you can
> get the
> >       whole number of how many times the event happened:
> >
> >       $ ocount ls
> >       Events were actively counted for 1863267 nanoseconds.
> >       Event counts (actual) for /bin/ls:
> >                 Event                    Count                    % time
> counted
> >                 CPU_CLK_UNHALTED         2,672,309                100.00
> >
> >       This means that there were 2.672 million CPU ticks necessary to
> execute
> >       `ls`.
> >
> >       The tool for counting is *ocount*.
> >
> >
> >       How _profiling_ works:
> >
> >       For profiling, events are counted the same way as when counting,
> but only
> >       once per N event occurrences a "sample" is taken. A sample is a
> piece of
> >       information about where in the code it happened, what was the
> context and
> >       potentially call-stack, etc. This sample is saved into the
> oprofile_data
> >       dir structure. When you finish profiling, opreport generates some
> overview
> >       from the samples recorded.
> >
> >       Of course, taking sample causes some overhead. Thus, you cannot
> take it
> >       each time the event counter increments. For this purpose, there is
> "sample
> >       rate" value which divides the event counter and takes a sample
> only once
> >       per "sample rate" occurrences. Thus, it is pretty random, which
> event
> >       occurrence is picked for a sample.
> >
> >       Of course, your main() consumes CPU ticks and the counter is
> incremented,
> >       but sometimes, one of these incrementations produces sample,
> sometimes not,
> >       thus the function is missing.
> >
> >       You have 2 samples on each of the line in the report. That is
> really a low
> >       number, so it is very probable that sometimes the samples hit
> main() and
> >       sometimes not.
> >
> >       $ operf ls
> >       Profiling done.
> >
> >       $ opreport
> >       Using /root/oprofile_data/samples/ for samples directory.
> >       CPU: Core 2, speed 2267 MHz (estimated)
> >       Counted CPU_CLK_UNHALTED events (Clock cycles when not halted)
> with a unit mask of 0x00 (Unhalted core cycles) count 100000
> >       CPU_CLK_UNHALT...|
> >         samples|      %|
> >       ------------------
> >        -->   37 100.000 ls
> >              CPU_CLK_UNHALT...|
> >                samples|      %|
> >                        ------------------
> >                     27 72.9730 kallsyms
> >                      5 13.5135 libc-2.19.so
> >                      2  5.4054 ld-2.19.so
> >                      1  2.7027 ls
> >                      1  2.7027 ext4
> >                      1  2.7027 libattr.so.1.1.0
> >
> >       You see that out of (estimated) 2.5-3.5 mil of event occurrences
> (which is
> >       the scale `ls` usually needs on my PC), I got only 37 samples.
> >
> >       The sample rate for each event are in `ophelp` as "min count".
> >
> >       Why did I get 37 samples? My default setting of default event is:
> >
> >       $ ophelp -d
> >       CPU_CLK_UNHALTED:100000:0:1:1
> >       -------------------^^
> >
> >       This means that there is 1 sample per 100000 event occurrences.
> >
> >       You can tweak this value a bit, but note that oprofile won't let
> you set
> >       the value to be too low, due to the overhead reasons.
> >
> >       Let's try 10000 (sampling 10 times more often):
> >
> >       $ operf -e CPU_CLK_UNHALTED:10000 ls
> >       WARNING: Lost samples detected! See /root/oprofile_data/samples/operf.log
> for details.
> >       Lowering the sampling rate may reduce or eliminate lost samples.
> >       See the '--events' option description in the operf man page for
> help.
> >       Profiling done.
> >
> >       $ opreport
> >       Using /root/oprofile_data/samples/ for samples directory.
> >       WARNING: Lost samples detected! See /root/oprofile_data/samples/operf.log
> for details.
> >       CPU: Core 2, speed 2267 MHz (estimated)
> >       Counted CPU_CLK_UNHALTED events (Clock cycles when not halted)
> with a unit mask of 0x00 (Unhalted core cycles) count 10000
> >       CPU_CLK_UNHALT...|
> >         samples|      %|
> >       ------------------
> >             429 100.000 ls
> >             CPU_CLK_UNHALT...|
> >               samples|      %|
> >               ------------------
> >                     313 72.9604 kallsyms
> >                      55 12.8205 ld-2.19.so
> >                      34  7.9254 libc-2.19.so
> >                      17  3.9627 ls
> >                       8  1.8648 ext4
> >                       2  0.4662 binfmt_misc
> >
> >       You see that both operf and opreport warned about lost samples
> which means
> >       that the overhead in kernel was too high and some samples were
> lost. But
> >       probably not that many, since you see that I got 429 samples
> instead of
> >       37 which is very roughly 10 times more.
> >
> >
> >       Profiling is not for exact measurement of how many CPU ticks
> happened in
> >       a function, it is rather designed for relative comparison across
> your code.
> >
> >       If you are getting too few samples, try to decrease the sample
> rate as I
> >       did in the example. Have a look at `ophelp` what is the lowest
> value for
> >       your event.
> >
> >       Also please note that the min sample rates are rough and depend on
> the load,
> >       so under low load, lower rates can be used without issues. When
> you profile
> >       systemwide on all CPUs, it's very high chance that you'll run into
> an overhead
> >       and lose many samples...
> >
> >       I hope I explained it a bit.
> >
> >       Cheers,
> >       Michael
> >
> >       > Thanks,
> >       >
> >       > Dhara Buch
> >       >
> >       >
> >
> >
> >
> >
>

Re: Fwd: Potential deadlock in operf when using --pid

[William Cohen <wcohen@re...>]

On 06/24/2016 08:06 PM, 大平怜 wrote:
> I forgot to include oprofile-list.
> 
> 
> Regards,
> Rei Odaira
> 
> ---------- Forwarded message ----------
> From: *大平怜* <rei.odaira@... <mailto:rei.odaira@...>>
> Date: 2016-06-24 19:04 GMT-05:00
> Subject: Re: Potential deadlock in operf when using --pid
> To: William Cohen <wcohen@... <mailto:wcohen@...>>
> 
> 
> Hi,
> 
> Now I come back to this problem.
> 
> I am attaching two patches to solve it.  They apply to the latest master in the git repository.  Please apply oprofile_avoid_deadlock_1.patch first and then oprofile_avoid_deadlock_2.patch. The first patch is just for refactoring the code to make the second patch possible, and the second patch is for the actual problem solving.
> 
> So, the problem is that the operf-record process is blocked on a write to the sample output pipe when the pipe is full, while the operf-read process, which is the consumer of the pipe, cannot read from the pipe because it is blocked on a read from the comm pipe, to which the operf-record process is supposed to write.  Please refer to the previous emails for the detailed problem description.
> 
>             |<--sample output pipe--|
> operf-read  |-------comm pipe------>|  operf-record
>             |<------comm pipe-------|
> 
> My solution is to make the sample output pipe non-blocking on the operf-record side.  When the sample output pipe is full, instead of waiting on it, the operf-record process polls both the sample output pipe and the (read-end of) comm pipe.  If there is a message in the comm pipe from the operf-read process, the operf-record process handles it and writes a response to the comm pipe, so that the operf-read process can finish being blocked on the read from the comm pipe and eventually can consume the sample output pipe.
> 
> There are some other ways to solve this problem, so any comments are welcome.  With my patches, you can finish profiling oprofile_multithread_test by a single ctrl-c. They passed all the tests in oprofile-tests.
> 
> 
> Regards,
> Rei Odaira
> 




Hi Da Rei,

Sorry for missing the patches to address rapid thread
creation/deletion deadlock issue.  I have been taking a look at them.
As a sanity check I ran the testsuite before and after the patches and
things look the same.

Test results before the patches:

		=== oprofile Summary ===

# of expected passes		149

kernel version: 4.11.5-200.fc25.x86_64
userspace version: oprofile 1.2.0git compiled on Jun 29 2017 13:59:35


Test results after the patches:

		=== oprofile Summary ===

# of expected passes		149

kernel version: 4.11.5-200.fc25.x86_64
userspace version: oprofile 1.2.0git compiled on Jun 29 2017 14:10:33


The patches does appear to help with the issue demonstrated with the
reporducer oprofile_mutithread_test with operations per thread of
1000000.  However, with smaller number of operations per thread
settings (100000) operf has issue getting connected:

$ operf --pid 7555
!!!! No samples collected !!!
The target program/command ended before profiling was started.
operf record init failed
usage: operf [ options ] [ --system-wide | --pid <pid> | [ command [ args ] ] ]
Error running profiler


Or if it is able to connect (the process was paused with cntl-z and
then put back in the foreground after oprofile had attached):

$ operf --pid 7555
...
Unable to collect samples for forked process 17240. Process may have ended before recording could be started.
Unable to collect samples for forked process 17241. Process may have ended before recording could be started.
Unable to collect samples for forked process 17242. Process may have ended before recording could be started.
Unable to collect samples for forked process 17243. Process may have ended before recording could be started.
Failed to mmap kernel profile data.
This issue may be caused by a non-root user running multiple operf
sessions simultaneously. Try running as root or increasing the value of
/proc/sys/kernel/perf_event_mlock_kb to resolve the problem.

Unable to collect samples for forked process 17245. Process may have ended before recording could be started.


Is is notable that perf has similar problems it is unable to attach to quickly spawning processes

$ perf record --pid 7555
Error:
The sys_perf_event_open() syscall returned with 3 (No such process) for event (cycles).
/bin/dmesg may provide additional information.
No CONFIG_PERF_EVENTS=y kernel support configured?
[wcohen@... oprofile]$ perf record --pid 7555
^C[ perf record: Woken up 81 times to write data ]

However "perf record --pid 7555" is able to collect data without issue
if the 7555 is paused when "perf record" starts up.  I have let the
perf developers know about this issue.


The portion of oprofile the patches affect is not easy to follow, so I
am still trying to make sure I fully understand the issue and that the
patches address the issue without introducing some other issue.
Earlier email has the following diagram:


            |<--sample output pipe--|
operf-read  |-------comm pipe------>|  operf-record
            |<------comm pipe-------|


The data in the sample "sample output pipe" stream includes the
PERF_RECORD_FORK events.  The operf-read processes the
PERF_RECORD_FORK events in the stream and sends pid back up the comm
pipe for operf-record add another thread.

Is the comm pipe only being used to communicate the new processes to be monitored?

Would it be possible to have operf-record just do that directly rather
than having to make a round trip from operf-record to operf-read and
back to operf-record?  Seems like there is a lot of overhead when
starting to monitoring a new thread.

The patches implement polling to avoid the opef-record getting hung
and in turn causing operf-read getting stuck when sample output pipe
gets full.  Is there any way that the comm pipe might similarly get
full and cause a hang?

-Will

Re: OProfile-1.2.0-rc1

[Will Schmidt <will_schmidt@vn...>]

On Wed, 2017-06-28 at 12:08 -0400, William Cohen wrote:
> On 06/28/2017 11:53 AM, William Cohen wrote:
> > On 06/26/2017 10:42 AM, Will Schmidt wrote:
> >> On Mon, 2017-06-19 at 11:08 -0400, William Cohen wrote:
> >>> There have been a number of improvements checked into the OProfile git repo.  It would be good to have those into an official release.  I have made a release candidate and it would be good to test this out on various platforms.
> >>>
> >>> URL:
> >>> https://sourceforge.net/projects/oprofile/files/oprofile/oprofile-1.2.0rc1/oprofile-1.2.0rc1.tar.gz/download
> >>>
> >>
> >> I grabbed and did a build/run across a small assortment of power
> >> systems.   (power7,power8LE,power8BE), test suite runs clean. 
> >> (Also looks good on pre-ga P9)
> >> 			=== oprofile Summary ===
> >> 	
> >> 	# of expected passes		78
> >>
> >> One error in 'make check'.  (also see this on my x86 laptop).
> >> I suspect not a big deal, but in case... :-)
> >>
> >> 	FAIL: load_events_files_tests
> >>
> >> 	um zero is not used
> >>
> >> A quick peek via gdb suggests this is occurring when trying to parse the
> >> events files for CPU_CORE_I7, down the op_events(cpu_type) path.  If I
> >> force that test to pass via setting err=0 in gdb, it occurs again on
> >> CPU_NEHALEM.
> >>
> >> Breakpoint 1, op_events (cpu_type=CPU_CORE_I7) at op_events.c:724
> >> 724	{
> >> $60 = CPU_CORE_I7
> >> um zero is not used
> >>
> >> Breakpoint 1, op_events (cpu_type=CPU_NEHALEM) at op_events.c:724
> >> 724	{
> >> $63 = CPU_NEHALEM
> >> um zero is not used
> >>
> >>
> >> thanks
> >> -Will (Schmidt)
> > 
> > Hi Will,
> > 
> > I took a look at this failure from "make check".  This is due to the events/i386/arch_perfmon/unit_masks having the unit mask zero, but it not being used in nahelem for the events. i386/nehalem/events has:
> > 
> > #event:0x3c counters:0,1,2,3 um:zero minimum:6000 name:CPU_CLK_UNHALTED : Clock cycles when not halted
> > event:0x3c counters:0,1,2,3 um:one minimum:6000 name:UNHALTED_REFERENCE_CYCLES : Unhalted reference cycles
> > 
> > The nahelem events are included in the i386/core_i7 events. Thus, it also suffers from the same problem.  This appears to be relatively harmless.  However, it does cause the load_events_files_tests test to abort so processors after core_i7 (including nehalem) are not check for event sanity.  I manually set err=0 after each of the reports of the unused mask and didn't see any other problems.
> > 
> > -Will Cohen
> 
> The attached patch should address the test failure.  Does that seem like a reasonable fix?  -Will

Looks good to me.   fixes the problem, at least. :-)


PASS: cpu_type_tests
PASS: parse_event_tests
PASS: load_events_files_tests
PASS: alloc_counter_tests
PASS: mangle_tests
PASS: utf8_checker.sh
============================================================================
Testsuite summary for OProfile 1.2.0rc1
============================================================================
# TOTAL: 6
# PASS:  6
# SKIP:  0
# XFAIL: 0
# FAIL:  0
# XPASS: 0
# ERROR: 0

Re: OProfile-1.2.0-rc1

[William Cohen <wcohen@re...>]

On 06/28/2017 11:53 AM, William Cohen wrote:
> On 06/26/2017 10:42 AM, Will Schmidt wrote:
>> On Mon, 2017-06-19 at 11:08 -0400, William Cohen wrote:
>>> There have been a number of improvements checked into the OProfile git repo.  It would be good to have those into an official release.  I have made a release candidate and it would be good to test this out on various platforms.
>>>
>>> URL:
>>> https://sourceforge.net/projects/oprofile/files/oprofile/oprofile-1.2.0rc1/oprofile-1.2.0rc1.tar.gz/download
>>>
>>
>> I grabbed and did a build/run across a small assortment of power
>> systems.   (power7,power8LE,power8BE), test suite runs clean. 
>> (Also looks good on pre-ga P9)
>> 			=== oprofile Summary ===
>> 	
>> 	# of expected passes		78
>>
>> One error in 'make check'.  (also see this on my x86 laptop).
>> I suspect not a big deal, but in case... :-)
>>
>> 	FAIL: load_events_files_tests
>>
>> 	um zero is not used
>>
>> A quick peek via gdb suggests this is occurring when trying to parse the
>> events files for CPU_CORE_I7, down the op_events(cpu_type) path.  If I
>> force that test to pass via setting err=0 in gdb, it occurs again on
>> CPU_NEHALEM.
>>
>> Breakpoint 1, op_events (cpu_type=CPU_CORE_I7) at op_events.c:724
>> 724	{
>> $60 = CPU_CORE_I7
>> um zero is not used
>>
>> Breakpoint 1, op_events (cpu_type=CPU_NEHALEM) at op_events.c:724
>> 724	{
>> $63 = CPU_NEHALEM
>> um zero is not used
>>
>>
>> thanks
>> -Will (Schmidt)
> 
> Hi Will,
> 
> I took a look at this failure from "make check".  This is due to the events/i386/arch_perfmon/unit_masks having the unit mask zero, but it not being used in nahelem for the events. i386/nehalem/events has:
> 
> #event:0x3c counters:0,1,2,3 um:zero minimum:6000 name:CPU_CLK_UNHALTED : Clock cycles when not halted
> event:0x3c counters:0,1,2,3 um:one minimum:6000 name:UNHALTED_REFERENCE_CYCLES : Unhalted reference cycles
> 
> The nahelem events are included in the i386/core_i7 events. Thus, it also suffers from the same problem.  This appears to be relatively harmless.  However, it does cause the load_events_files_tests test to abort so processors after core_i7 (including nehalem) are not check for event sanity.  I manually set err=0 after each of the reports of the unused mask and didn't see any other problems.
> 
> -Will Cohen

The attached patch should address the test failure.  Does that seem like a reasonable fix?  -Will

Re: OProfile-1.2.0-rc1

[William Cohen <wcohen@re...>]

On 06/26/2017 10:42 AM, Will Schmidt wrote:
> On Mon, 2017-06-19 at 11:08 -0400, William Cohen wrote:
>> There have been a number of improvements checked into the OProfile git repo.  It would be good to have those into an official release.  I have made a release candidate and it would be good to test this out on various platforms.
>>
>> URL:
>> https://sourceforge.net/projects/oprofile/files/oprofile/oprofile-1.2.0rc1/oprofile-1.2.0rc1.tar.gz/download
>>
> 
> I grabbed and did a build/run across a small assortment of power
> systems.   (power7,power8LE,power8BE), test suite runs clean. 
> (Also looks good on pre-ga P9)
> 			=== oprofile Summary ===
> 	
> 	# of expected passes		78
> 
> One error in 'make check'.  (also see this on my x86 laptop).
> I suspect not a big deal, but in case... :-)
> 
> 	FAIL: load_events_files_tests
> 
> 	um zero is not used
> 
> A quick peek via gdb suggests this is occurring when trying to parse the
> events files for CPU_CORE_I7, down the op_events(cpu_type) path.  If I
> force that test to pass via setting err=0 in gdb, it occurs again on
> CPU_NEHALEM.
> 
> Breakpoint 1, op_events (cpu_type=CPU_CORE_I7) at op_events.c:724
> 724	{
> $60 = CPU_CORE_I7
> um zero is not used
> 
> Breakpoint 1, op_events (cpu_type=CPU_NEHALEM) at op_events.c:724
> 724	{
> $63 = CPU_NEHALEM
> um zero is not used
> 
> 
> thanks
> -Will (Schmidt)

Hi Will,

I took a look at this failure from "make check".  This is due to the events/i386/arch_perfmon/unit_masks having the unit mask zero, but it not being used in nahelem for the events. i386/nehalem/events has:

#event:0x3c counters:0,1,2,3 um:zero minimum:6000 name:CPU_CLK_UNHALTED : Clock cycles when not halted
event:0x3c counters:0,1,2,3 um:one minimum:6000 name:UNHALTED_REFERENCE_CYCLES : Unhalted reference cycles

The nahelem events are included in the i386/core_i7 events. Thus, it also suffers from the same problem.  This appears to be relatively harmless.  However, it does cause the load_events_files_tests test to abort so processors after core_i7 (including nehalem) are not check for event sanity.  I manually set err=0 after each of the reports of the unused mask and didn't see any other problems.

-Will Cohen

Re: OProfile-1.2.0-rc1

[Will Schmidt <will_schmidt@vn...>]

On Mon, 2017-06-19 at 11:08 -0400, William Cohen wrote:
> There have been a number of improvements checked into the OProfile git repo.  It would be good to have those into an official release.  I have made a release candidate and it would be good to test this out on various platforms.
> 
> URL:
> https://sourceforge.net/projects/oprofile/files/oprofile/oprofile-1.2.0rc1/oprofile-1.2.0rc1.tar.gz/download
> 

I grabbed and did a build/run across a small assortment of power
systems.   (power7,power8LE,power8BE), test suite runs clean. 
(Also looks good on pre-ga P9)
			=== oprofile Summary ===
	
	# of expected passes		78

One error in 'make check'.  (also see this on my x86 laptop).
I suspect not a big deal, but in case... :-)

	FAIL: load_events_files_tests

	um zero is not used

A quick peek via gdb suggests this is occurring when trying to parse the
events files for CPU_CORE_I7, down the op_events(cpu_type) path.  If I
force that test to pass via setting err=0 in gdb, it occurs again on
CPU_NEHALEM.

Breakpoint 1, op_events (cpu_type=CPU_CORE_I7) at op_events.c:724
724	{
$60 = CPU_CORE_I7
um zero is not used

Breakpoint 1, op_events (cpu_type=CPU_NEHALEM) at op_events.c:724
724	{
$63 = CPU_NEHALEM
um zero is not used


thanks
-Will (Schmidt)


> RELEASE NOTES:
> 
> New features
> ------------
> 
> - New/updated Processor Support
>     * ARM Cortex A17
>     * IBM Power 9
>     * IBM Power 8NV and NVL variants
>     * IBM z13
>     * Intel Goldmont
>     * Intel Kabylake
>     * Intel Xeon Phi (Knights Landing)
>     * Achitecture specific events for Applied Micro X-Gene
> 
> Bug fixes
> ---------
> 
> Filed bug reports:
> -------------------------------------------------------------------------
> |  BUG ID   |  Summary 
> |-----------|------------------------------------------------------------
> |  286      | Compilation error: left shift of negative value
> |  288      | oprofile fails to build with --enable-pch and gcc-6.2 
> -------------------------------------------------------------------------
> 
> Other bug fixes and improvements without a filed report (e.g., posted to the lis
> t):
> ---------------
>    - Fixed compile warning and errors when using GCC 6 or GCC 7
>    - Avoid using deprecated readdir_r function
>    - Store samples in the archive and search the appropriate places
>      for samples
>    - Only start the application if the perf events setup was successful
> 
> 
> Known problems and limitations
> -------------------------
> 
> - When using operf to profile multiple events, the absolute number of
>   events recorded may be substantially fewer than expected. This can
>   be due to known bug in the Linux kernel's Performance Events
>   Subsystem that was fixed sometime between Linux kernel version 3.1
>   and 3.5.
> 
> - Monitoring processes that frequently create and destroy threads via
>   the "--pid" option can be problematic.  The pipes used within operf
>   and ocount may fill up can cause these programs to hang and require
>   multiple cntl-C to exit rather than successfully collecting data on
>   fast spawning processes and children.
> 
> ------------------------------------------------------------------------------
> Check out the vibrant tech community on one of the world's most
> engaging tech sites, Slashdot.org! http://sdm.link/slashdot
> _______________________________________________
> oprofile-list mailing list
> oprofile-list@...
> https://lists.sourceforge.net/lists/listinfo/oprofile-list
> 

Re: OProfile-1.2.0-rc1

[大平怜 <rei.odaira@gm...>]

Hi,

FYI, I have submitted patches for this problem about a year ago. :-)
http://marc.info/?l=oprofile-list&m=146721380410945&w=2

>> - Monitoring processes that frequently create and destroy threads via
> >>   the "--pid" option can be problematic.  The pipes used within operf
> >>   and ocount may fill up can cause these programs to hang and require
> >>   multiple cntl-C to exit rather than successfully collecting data on
> >>   fast spawning processes and children.
>


Regards,
Rei Odaira

Re: OProfile-1.2.0-rc1

[William Cohen <wcohen@re...>]

On 06/20/2017 08:09 AM, Michael Petlan wrote:
> Hi William,
> 
> I have tested this tarball on a Knights Landing and everything looks good,
> except that the testsuite still does not contain my KNL patch I guess.

Hi Michael,

Thanks for testing.

Sorry about the missing Intel KNL oprofile-tests patch.  This should be in the upstream oprofile-tests now.

> 
> However, even when I applied the patch to the testsuite, I got:
> "Native configuration is x86_64-unknown-linux-gnu"
> Is it somehow connected to the testsuite or is that related to the build?
> It looks like the events I specified in the testsuite patch for KNL were
> used in the test, so I expect it works.

The "Native configuration is x86_64-unknown-linux-gnu" output appears to be coming from runtest rather than oprofile testing itself.  I am also seeing it in the systemtap testsuite output. It looks to be harmless.

> 
> I also ran selected Red Hat tests against it.
> 
> Cheers,
> Michael
> 
> On Mon, 19 Jun 2017, William Cohen wrote:
>> There have been a number of improvements checked into the OProfile git repo.  It would be good to have those into an official release.  I have made a release candidate and it would be good to test this out on various platforms.
>>
>> URL:
>> https://sourceforge.net/projects/oprofile/files/oprofile/oprofile-1.2.0rc1/oprofile-1.2.0rc1.tar.gz/download
>>
>> RELEASE NOTES:
>>
>> New features
>> ------------
>>
>> - New/updated Processor Support
>>     * ARM Cortex A17
>>     * IBM Power 9
>>     * IBM Power 8NV and NVL variants
>>     * IBM z13
>>     * Intel Goldmont
>>     * Intel Kabylake
>>     * Intel Xeon Phi (Knights Landing)
>>     * Achitecture specific events for Applied Micro X-Gene
>>
>> Bug fixes
>> ---------
>>
>> Filed bug reports:
>> -------------------------------------------------------------------------
>> |  BUG ID   |  Summary 
>> |-----------|------------------------------------------------------------
>> |  286      | Compilation error: left shift of negative value
>> |  288      | oprofile fails to build with --enable-pch and gcc-6.2 
>> -------------------------------------------------------------------------
>>
>> Other bug fixes and improvements without a filed report (e.g., posted to the lis
>> t):
>> ---------------
>>    - Fixed compile warning and errors when using GCC 6 or GCC 7
>>    - Avoid using deprecated readdir_r function
>>    - Store samples in the archive and search the appropriate places
>>      for samples
>>    - Only start the application if the perf events setup was successful
>>
>>
>> Known problems and limitations
>> -------------------------
>>
>> - When using operf to profile multiple events, the absolute number of
>>   events recorded may be substantially fewer than expected. This can
>>   be due to known bug in the Linux kernel's Performance Events
>>   Subsystem that was fixed sometime between Linux kernel version 3.1
>>   and 3.5.
>>
>> - Monitoring processes that frequently create and destroy threads via
>>   the "--pid" option can be problematic.  The pipes used within operf
>>   and ocount may fill up can cause these programs to hang and require
>>   multiple cntl-C to exit rather than successfully collecting data on
>>   fast spawning processes and children.
>>
>> ------------------------------------------------------------------------------
>> Check out the vibrant tech community on one of the world's most
>> engaging tech sites, Slashdot.org! http://sdm.link/slashdot
>> _______________________________________________
>> oprofile-list mailing list
>> oprofile-list@...
>> https://lists.sourceforge.net/lists/listinfo/oprofile-list
>>

Re: OProfile-1.2.0-rc1

[Michael Petlan <mpetlan@re...>]

Hi William,

I have tested this tarball on a Knights Landing and everything looks good,
except that the testsuite still does not contain my KNL patch I guess.

However, even when I applied the patch to the testsuite, I got:
"Native configuration is x86_64-unknown-linux-gnu"
Is it somehow connected to the testsuite or is that related to the build?
It looks like the events I specified in the testsuite patch for KNL were
used in the test, so I expect it works.

I also ran selected Red Hat tests against it.

Cheers,
Michael

On Mon, 19 Jun 2017, William Cohen wrote:
> There have been a number of improvements checked into the OProfile git repo.  It would be good to have those into an official release.  I have made a release candidate and it would be good to test this out on various platforms.
> 
> URL:
> https://sourceforge.net/projects/oprofile/files/oprofile/oprofile-1.2.0rc1/oprofile-1.2.0rc1.tar.gz/download
> 
> RELEASE NOTES:
> 
> New features
> ------------
> 
> - New/updated Processor Support
>     * ARM Cortex A17
>     * IBM Power 9
>     * IBM Power 8NV and NVL variants
>     * IBM z13
>     * Intel Goldmont
>     * Intel Kabylake
>     * Intel Xeon Phi (Knights Landing)
>     * Achitecture specific events for Applied Micro X-Gene
> 
> Bug fixes
> ---------
> 
> Filed bug reports:
> -------------------------------------------------------------------------
> |  BUG ID   |  Summary 
> |-----------|------------------------------------------------------------
> |  286      | Compilation error: left shift of negative value
> |  288      | oprofile fails to build with --enable-pch and gcc-6.2 
> -------------------------------------------------------------------------
> 
> Other bug fixes and improvements without a filed report (e.g., posted to the lis
> t):
> ---------------
>    - Fixed compile warning and errors when using GCC 6 or GCC 7
>    - Avoid using deprecated readdir_r function
>    - Store samples in the archive and search the appropriate places
>      for samples
>    - Only start the application if the perf events setup was successful
> 
> 
> Known problems and limitations
> -------------------------
> 
> - When using operf to profile multiple events, the absolute number of
>   events recorded may be substantially fewer than expected. This can
>   be due to known bug in the Linux kernel's Performance Events
>   Subsystem that was fixed sometime between Linux kernel version 3.1
>   and 3.5.
> 
> - Monitoring processes that frequently create and destroy threads via
>   the "--pid" option can be problematic.  The pipes used within operf
>   and ocount may fill up can cause these programs to hang and require
>   multiple cntl-C to exit rather than successfully collecting data on
>   fast spawning processes and children.
> 
> ------------------------------------------------------------------------------
> Check out the vibrant tech community on one of the world's most
> engaging tech sites, Slashdot.org! http://sdm.link/slashdot
> _______________________________________________
> oprofile-list mailing list
> oprofile-list@...
> https://lists.sourceforge.net/lists/listinfo/oprofile-list
> 

Re: OProfile-1.2.0-rc1

[Carl Love <cel@us...>]

Will:

I downloaded the RC1 tar ball and tested it on IBM Power 7, IBM Power8
big endian, IBM Power 8 little endian.  I did some manual tests of a
known workload.  I also downloaded and ran the OProfile test suite.
Everything looked fine.

                  Carl Love


On Mon, 2017-06-19 at 11:08 -0400, William Cohen wrote:
> There have been a number of improvements checked into the OProfile git repo.  It would be good to have those into an official release.  I have made a release candidate and it would be good to test this out on various platforms.
> 
> URL:
> https://sourceforge.net/projects/oprofile/files/oprofile/oprofile-1.2.0rc1/oprofile-1.2.0rc1.tar.gz/download
> 
> RELEASE NOTES:
> 
> New features
> ------------
> 
> - New/updated Processor Support
>     * ARM Cortex A17
>     * IBM Power 9
>     * IBM Power 8NV and NVL variants
>     * IBM z13
>     * Intel Goldmont
>     * Intel Kabylake
>     * Intel Xeon Phi (Knights Landing)
>     * Achitecture specific events for Applied Micro X-Gene
> 
> Bug fixes
> ---------
> 
> Filed bug reports:
> -------------------------------------------------------------------------
> |  BUG ID   |  Summary 
> |-----------|------------------------------------------------------------
> |  286      | Compilation error: left shift of negative value
> |  288      | oprofile fails to build with --enable-pch and gcc-6.2 
> -------------------------------------------------------------------------
> 
> Other bug fixes and improvements without a filed report (e.g., posted to the lis
> t):
> ---------------
>    - Fixed compile warning and errors when using GCC 6 or GCC 7
>    - Avoid using deprecated readdir_r function
>    - Store samples in the archive and search the appropriate places
>      for samples
>    - Only start the application if the perf events setup was successful
> 
> 
> Known problems and limitations
> -------------------------
> 
> - When using operf to profile multiple events, the absolute number of
>   events recorded may be substantially fewer than expected. This can
>   be due to known bug in the Linux kernel's Performance Events
>   Subsystem that was fixed sometime between Linux kernel version 3.1
>   and 3.5.
> 
> - Monitoring processes that frequently create and destroy threads via
>   the "--pid" option can be problematic.  The pipes used within operf
>   and ocount may fill up can cause these programs to hang and require
>   multiple cntl-C to exit rather than successfully collecting data on
>   fast spawning processes and children.
> 
> ------------------------------------------------------------------------------
> Check out the vibrant tech community on one of the world's most
> engaging tech sites, Slashdot.org! http://sdm.link/slashdot
> _______________________________________________
> oprofile-list mailing list
> oprofile-list@...
> https://lists.sourceforge.net/lists/listinfo/oprofile-list
> 

Re: OProfile-1.2.0-rc1

[William Cohen <wcohen@re...>]

On 06/19/2017 02:31 PM, Carl Love wrote:
> Will:
> 
> I downloaded the RC1 tar ball and tested it on IBM Power 7, IBM Power8
> big endian, IBM Power 8 little endian.  I did some manual tests of a
> known workload.  I also downloaded and ran the OProfile test suite.
> Everything looked fine.
> 
>                   Carl Love

Hi Carl,

Thanks so much testing on power.  I also created some fedora rawhide rpms, https://koji.fedoraproject.org/koji/taskinfo?taskID=20066548 
Going to try these out on various machine I have access to.

-Will
> 
> On Mon, 2017-06-19 at 11:08 -0400, William Cohen wrote:
>> There have been a number of improvements checked into the OProfile git repo.  It would be good to have those into an official release.  I have made a release candidate and it would be good to test this out on various platforms.
>>
>> URL:
>> https://sourceforge.net/projects/oprofile/files/oprofile/oprofile-1.2.0rc1/oprofile-1.2.0rc1.tar.gz/download
>>
>> RELEASE NOTES:
>>
>> New features
>> ------------
>>
>> - New/updated Processor Support
>>     * ARM Cortex A17
>>     * IBM Power 9
>>     * IBM Power 8NV and NVL variants
>>     * IBM z13
>>     * Intel Goldmont
>>     * Intel Kabylake
>>     * Intel Xeon Phi (Knights Landing)
>>     * Achitecture specific events for Applied Micro X-Gene
>>
>> Bug fixes
>> ---------
>>
>> Filed bug reports:
>> -------------------------------------------------------------------------
>> |  BUG ID   |  Summary 
>> |-----------|------------------------------------------------------------
>> |  286      | Compilation error: left shift of negative value
>> |  288      | oprofile fails to build with --enable-pch and gcc-6.2 
>> -------------------------------------------------------------------------
>>
>> Other bug fixes and improvements without a filed report (e.g., posted to the lis
>> t):
>> ---------------
>>    - Fixed compile warning and errors when using GCC 6 or GCC 7
>>    - Avoid using deprecated readdir_r function
>>    - Store samples in the archive and search the appropriate places
>>      for samples
>>    - Only start the application if the perf events setup was successful
>>
>>
>> Known problems and limitations
>> -------------------------
>>
>> - When using operf to profile multiple events, the absolute number of
>>   events recorded may be substantially fewer than expected. This can
>>   be due to known bug in the Linux kernel's Performance Events
>>   Subsystem that was fixed sometime between Linux kernel version 3.1
>>   and 3.5.
>>
>> - Monitoring processes that frequently create and destroy threads via
>>   the "--pid" option can be problematic.  The pipes used within operf
>>   and ocount may fill up can cause these programs to hang and require
>>   multiple cntl-C to exit rather than successfully collecting data on
>>   fast spawning processes and children.
>>
>> ------------------------------------------------------------------------------
>> Check out the vibrant tech community on one of the world's most
>> engaging tech sites, Slashdot.org! http://sdm.link/slashdot
>> _______________________________________________
>> oprofile-list mailing list
>> oprofile-list@...
>> https://lists.sourceforge.net/lists/listinfo/oprofile-list
>>
> 
> 

OProfile-1.2.0-rc1

[William Cohen <wcohen@re...>]

There have been a number of improvements checked into the OProfile git repo.  It would be good to have those into an official release.  I have made a release candidate and it would be good to test this out on various platforms.

URL:
https://sourceforge.net/projects/oprofile/files/oprofile/oprofile-1.2.0rc1/oprofile-1.2.0rc1.tar.gz/download

RELEASE NOTES:

New features
------------

- New/updated Processor Support
    * ARM Cortex A17
    * IBM Power 9
    * IBM Power 8NV and NVL variants
    * IBM z13
    * Intel Goldmont
    * Intel Kabylake
    * Intel Xeon Phi (Knights Landing)
    * Achitecture specific events for Applied Micro X-Gene

Bug fixes
---------

Filed bug reports:
-------------------------------------------------------------------------
|  BUG ID   |  Summary 
|-----------|------------------------------------------------------------
|  286      | Compilation error: left shift of negative value
|  288      | oprofile fails to build with --enable-pch and gcc-6.2 
-------------------------------------------------------------------------

Other bug fixes and improvements without a filed report (e.g., posted to the lis
t):
---------------
   - Fixed compile warning and errors when using GCC 6 or GCC 7
   - Avoid using deprecated readdir_r function
   - Store samples in the archive and search the appropriate places
     for samples
   - Only start the application if the perf events setup was successful


Known problems and limitations
-------------------------

- When using operf to profile multiple events, the absolute number of
  events recorded may be substantially fewer than expected. This can
  be due to known bug in the Linux kernel's Performance Events
  Subsystem that was fixed sometime between Linux kernel version 3.1
  and 3.5.

- Monitoring processes that frequently create and destroy threads via
  the "--pid" option can be problematic.  The pipes used within operf
  and ocount may fill up can cause these programs to hang and require
  multiple cntl-C to exit rather than successfully collecting data on
  fast spawning processes and children.

Re: Operf and Opreport outputs

[Michael Petlan <mpetlan@re...>]

On Mon, 19 Jun 2017, dhara buch wrote:
> Hello,
> Thanks a lot for the detailed explanation. I could understand the working of operf and opreport.
> Unlike operf, ocount counts each occurrence of the monitored event. In such a case, why ocount also gives varying values of CPU_CLK_UNHALTED even when the monitored code doesn't get
> changed. Is it because of background processes? If so, then can we get event count for only monitored command?

Hi Dhara,

it is kind of because of the background processes, but not in the way that ocount
would count also their CPU consumption. If you don't use '-s' option, ocount will
count only what your command does.

However, it counts either kernelspace, userspace or both (default if you are root).
This can be configured by the event's flags:

Both:
-e CPU_CLK_UNHALTED:0:1:1

Only kernelspace (used by the command, i.e. syscalls, etc):
-e CPU_CLK_UNHALTED:0:1:0

Only userspace (i.e. syscalls are excluded):
-e CPU_CLK_UNHALTED:0:0:1

(the format is (ocount): event:umask:kernelspace:userspace,
for operf it is: event:umask:sample_rate:kernelspace:userspace)

The numbers are slightly different each run because the process does not live in
vacuum. It is usually dynamically linked, it calls libraries, kernel switches
contexts, etc. All these things cause the differences. Also, the CPU optimizes
the execution with floating success, depending on what else runs there with it.
If the process is interrupted many times, the CPU consumption will be higher.

I have a sample code which I linked dynamically and statically. While the dyn.
linked executable always takes around 670,260 cycles, the statically linked one
takes around 380,202 and seems to be more steady. Since it is very simple code,
you can see that the linker-related stuff took more than 40% of the CPU cycles).

Executing a binary is so complex problem that there is no surprise that those
measurements give different values every time.

........

TIP:

You can use either papi library or the built-in kernel support for counting
just a particular part of code, e.g. a function. I have attached one example
which uses perfevents kernel background. I have two functions for factorial
counting, one is slightly less effective than the other. I count cycles and
instructions for both. When executing repeatedly, you can see, that the inst.
count is the same all the time (at least on my laptop), but the cycles count
differs even for just the stuff in the functions which are very simple.

cc -o perf-hello perf-hello.c myperf.c
./perf-hello

Ineffective method:
	PERF_COUNT_HW_CPU_CYCLES = 32192
	PERF_COUNT_HW_INSTRUCTIONS = 20681

More effective method:
	PERF_COUNT_HW_CPU_CYCLES = 15931
	PERF_COUNT_HW_INSTRUCTIONS = 19103

........

Cheers,
Michael


> 
> Thank you,
> 
> On Fri, Jun 16, 2017 at 4:52 PM, Michael Petlan <mpetlan@...> wrote:
>       On Fri, 16 Jun 2017, dhara buch wrote:
>       > Hello,
>       >
>       > Many days ago you had helped me a lot in using Oprofile in Virtual Machine. That time, I also had a query regarding
>       > getting information from 'opreport --symbols --debuginfo' command.
> 
>       Hello,
> 
>       yeah, I remember...
> 
>       >
>       > Actually, I am profiling a file1.c file with the following commands...
>       >
>       > 1. gcc -g file1.c -o file1
>       >
>       > 2. operf ./file1 --events=CPU_CLK_UNHALTED
>       >
>       > 3. opreport --symbols --debuginfo
>       >
>       > the output contains various lines where one line look follows:
>       >
>       > samples  %        linenr info                 image name               symbol name
>       >
>       > 2       12.5000  rsaimp.c:16                 rsaimp                   MM
>       > 2        12.5000  rsaimp.c:34                 rsaimp                   main
>       >
>       > When I execute commands 2 and 3 multiple times, each time I gwt the output for symbole name MM (which is UDF in the
>       > program) but I don't get output for main every time.
>       >
>       This is kind of random, see below.
> 
>       > Additionally,'' the sample % also vary every time I file operf command. I do not understand the working of operf that
>       > how it gives different outputs for the same program.
>       >
> 
>       How _counting_ works:
> 
>       Each time an event happens in CPU (in our case -- CPU_CLK_UNHALTED -- one
>       CPU tick), its counter is incremented by one. This way, you can get the
>       whole number of how many times the event happened:
> 
>       $ ocount ls
>       Events were actively counted for 1863267 nanoseconds.
>       Event counts (actual) for /bin/ls:
>                 Event                    Count                    % time counted
>                 CPU_CLK_UNHALTED         2,672,309                100.00
> 
>       This means that there were 2.672 million CPU ticks necessary to execute
>       `ls`.
> 
>       The tool for counting is *ocount*.
> 
> 
>       How _profiling_ works:
> 
>       For profiling, events are counted the same way as when counting, but only
>       once per N event occurrences a "sample" is taken. A sample is a piece of
>       information about where in the code it happened, what was the context and
>       potentially call-stack, etc. This sample is saved into the oprofile_data
>       dir structure. When you finish profiling, opreport generates some overview
>       from the samples recorded.
> 
>       Of course, taking sample causes some overhead. Thus, you cannot take it
>       each time the event counter increments. For this purpose, there is "sample
>       rate" value which divides the event counter and takes a sample only once
>       per "sample rate" occurrences. Thus, it is pretty random, which event
>       occurrence is picked for a sample.
> 
>       Of course, your main() consumes CPU ticks and the counter is incremented,
>       but sometimes, one of these incrementations produces sample, sometimes not,
>       thus the function is missing.
> 
>       You have 2 samples on each of the line in the report. That is really a low
>       number, so it is very probable that sometimes the samples hit main() and
>       sometimes not.
> 
>       $ operf ls
>       Profiling done.
> 
>       $ opreport
>       Using /root/oprofile_data/samples/ for samples directory.
>       CPU: Core 2, speed 2267 MHz (estimated)
>       Counted CPU_CLK_UNHALTED events (Clock cycles when not halted) with a unit mask of 0x00 (Unhalted core cycles) count 100000
>       CPU_CLK_UNHALT...|
>         samples|      %|
>       ------------------
>        -->   37 100.000 ls
>              CPU_CLK_UNHALT...|
>                samples|      %|
>                        ------------------
>                     27 72.9730 kallsyms
>                      5 13.5135 libc-2.19.so
>                      2  5.4054 ld-2.19.so
>                      1  2.7027 ls
>                      1  2.7027 ext4
>                      1  2.7027 libattr.so.1.1.0
> 
>       You see that out of (estimated) 2.5-3.5 mil of event occurrences (which is
>       the scale `ls` usually needs on my PC), I got only 37 samples.
> 
>       The sample rate for each event are in `ophelp` as "min count".
> 
>       Why did I get 37 samples? My default setting of default event is:
> 
>       $ ophelp -d
>       CPU_CLK_UNHALTED:100000:0:1:1
>       -------------------^^
> 
>       This means that there is 1 sample per 100000 event occurrences.
> 
>       You can tweak this value a bit, but note that oprofile won't let you set
>       the value to be too low, due to the overhead reasons.
> 
>       Let's try 10000 (sampling 10 times more often):
> 
>       $ operf -e CPU_CLK_UNHALTED:10000 ls
>       WARNING: Lost samples detected! See /root/oprofile_data/samples/operf.log for details.
>       Lowering the sampling rate may reduce or eliminate lost samples.
>       See the '--events' option description in the operf man page for help.
>       Profiling done.
> 
>       $ opreport
>       Using /root/oprofile_data/samples/ for samples directory.
>       WARNING: Lost samples detected! See /root/oprofile_data/samples/operf.log for details.
>       CPU: Core 2, speed 2267 MHz (estimated)
>       Counted CPU_CLK_UNHALTED events (Clock cycles when not halted) with a unit mask of 0x00 (Unhalted core cycles) count 10000
>       CPU_CLK_UNHALT...|
>         samples|      %|
>       ------------------
>             429 100.000 ls
>             CPU_CLK_UNHALT...|
>               samples|      %|
>               ------------------
>                     313 72.9604 kallsyms
>                      55 12.8205 ld-2.19.so
>                      34  7.9254 libc-2.19.so
>                      17  3.9627 ls
>                       8  1.8648 ext4
>                       2  0.4662 binfmt_misc
> 
>       You see that both operf and opreport warned about lost samples which means
>       that the overhead in kernel was too high and some samples were lost. But
>       probably not that many, since you see that I got 429 samples instead of
>       37 which is very roughly 10 times more.
> 
> 
>       Profiling is not for exact measurement of how many CPU ticks happened in
>       a function, it is rather designed for relative comparison across your code.
> 
>       If you are getting too few samples, try to decrease the sample rate as I
>       did in the example. Have a look at `ophelp` what is the lowest value for
>       your event.
> 
>       Also please note that the min sample rates are rough and depend on the load,
>       so under low load, lower rates can be used without issues. When you profile
>       systemwide on all CPUs, it's very high chance that you'll run into an overhead
>       and lose many samples...
> 
>       I hope I explained it a bit.
> 
>       Cheers,
>       Michael
> 
>       > Thanks,
>       >
>       > Dhara Buch
>       >
>       >
> 
> 
> 
> 

Re: Operf and Opreport outputs

[dhara buch <dharabuchphd@gm...>]

Hello,

Thanks a lot for the detailed explanation. I could understand the working
of operf and opreport.

Unlike operf, ocount counts each occurrence of the monitored event. In such
a case, why ocount also gives varying values of CPU_CLK_UNHALTED even when
the monitored code doesn't get changed. Is it because of background
processes? If so, then can we get event count for only monitored command?

Thank you,

On Fri, Jun 16, 2017 at 4:52 PM, Michael Petlan <mpetlan@...> wrote:

> On Fri, 16 Jun 2017, dhara buch wrote:
> > Hello,
> >
> > Many days ago you had helped me a lot in using Oprofile in Virtual
> Machine. That time, I also had a query regarding
> > getting information from 'opreport --symbols --debuginfo' command.
>
> Hello,
>
> yeah, I remember...
>
> >
> > Actually, I am profiling a file1.c file with the following commands...
> >
> > 1. gcc -g file1.c -o file1
> >
> > 2. operf ./file1 --events=CPU_CLK_UNHALTED
> >
> > 3. opreport --symbols --debuginfo
> >
> > the output contains various lines where one line look follows:
> >
> > samples  %        linenr info                 image name
> symbol name
> >
> > 2       12.5000  rsaimp.c:16                 rsaimp                   MM
> > 2        12.5000  rsaimp.c:34                 rsaimp
> main
> >
> > When I execute commands 2 and 3 multiple times, each time I gwt the
> output for symbole name MM (which is UDF in the
> > program) but I don't get output for main every time.
> >
> This is kind of random, see below.
>
> > Additionally,'' the sample % also vary every time I file operf command.
> I do not understand the working of operf that
> > how it gives different outputs for the same program.
> >
>
> How _counting_ works:
>
> Each time an event happens in CPU (in our case -- CPU_CLK_UNHALTED -- one
> CPU tick), its counter is incremented by one. This way, you can get the
> whole number of how many times the event happened:
>
> $ ocount ls
> Events were actively counted for 1863267 nanoseconds.
> Event counts (actual) for /bin/ls:
>           Event                    Count                    % time counted
>           CPU_CLK_UNHALTED         2,672,309                100.00
>
> This means that there were 2.672 million CPU ticks necessary to execute
> `ls`.
>
> The tool for counting is *ocount*.
>
>
> How _profiling_ works:
>
> For profiling, events are counted the same way as when counting, but only
> once per N event occurrences a "sample" is taken. A sample is a piece of
> information about where in the code it happened, what was the context and
> potentially call-stack, etc. This sample is saved into the oprofile_data
> dir structure. When you finish profiling, opreport generates some overview
> from the samples recorded.
>
> Of course, taking sample causes some overhead. Thus, you cannot take it
> each time the event counter increments. For this purpose, there is "sample
> rate" value which divides the event counter and takes a sample only once
> per "sample rate" occurrences. Thus, it is pretty random, which event
> occurrence is picked for a sample.
>
> Of course, your main() consumes CPU ticks and the counter is incremented,
> but sometimes, one of these incrementations produces sample, sometimes not,
> thus the function is missing.
>
> You have 2 samples on each of the line in the report. That is really a low
> number, so it is very probable that sometimes the samples hit main() and
> sometimes not.
>
> $ operf ls
> Profiling done.
>
> $ opreport
> Using /root/oprofile_data/samples/ for samples directory.
> CPU: Core 2, speed 2267 MHz (estimated)
> Counted CPU_CLK_UNHALTED events (Clock cycles when not halted) with a unit
> mask of 0x00 (Unhalted core cycles) count 100000
> CPU_CLK_UNHALT...|
>   samples|      %|
> ------------------
>  -->   37 100.000 ls
>        CPU_CLK_UNHALT...|
>          samples|      %|
>                  ------------------
>               27 72.9730 kallsyms
>                5 13.5135 libc-2.19.so
>                2  5.4054 ld-2.19.so
>                1  2.7027 ls
>                1  2.7027 ext4
>                1  2.7027 libattr.so.1.1.0
>
> You see that out of (estimated) 2.5-3.5 mil of event occurrences (which is
> the scale `ls` usually needs on my PC), I got only 37 samples.
>
> The sample rate for each event are in `ophelp` as "min count".
>
> Why did I get 37 samples? My default setting of default event is:
>
> $ ophelp -d
> CPU_CLK_UNHALTED:100000:0:1:1
> -------------------^^
>
> This means that there is 1 sample per 100000 event occurrences.
>
> You can tweak this value a bit, but note that oprofile won't let you set
> the value to be too low, due to the overhead reasons.
>
> Let's try 10000 (sampling 10 times more often):
>
> $ operf -e CPU_CLK_UNHALTED:10000 ls
> WARNING: Lost samples detected! See /root/oprofile_data/samples/operf.log
> for details.
> Lowering the sampling rate may reduce or eliminate lost samples.
> See the '--events' option description in the operf man page for help.
> Profiling done.
>
> $ opreport
> Using /root/oprofile_data/samples/ for samples directory.
> WARNING: Lost samples detected! See /root/oprofile_data/samples/operf.log
> for details.
> CPU: Core 2, speed 2267 MHz (estimated)
> Counted CPU_CLK_UNHALTED events (Clock cycles when not halted) with a unit
> mask of 0x00 (Unhalted core cycles) count 10000
> CPU_CLK_UNHALT...|
>   samples|      %|
> ------------------
>       429 100.000 ls
>       CPU_CLK_UNHALT...|
>         samples|      %|
>         ------------------
>               313 72.9604 kallsyms
>                55 12.8205 ld-2.19.so
>                34  7.9254 libc-2.19.so
>                17  3.9627 ls
>                 8  1.8648 ext4
>                 2  0.4662 binfmt_misc
>
> You see that both operf and opreport warned about lost samples which means
> that the overhead in kernel was too high and some samples were lost. But
> probably not that many, since you see that I got 429 samples instead of
> 37 which is very roughly 10 times more.
>
>
> Profiling is not for exact measurement of how many CPU ticks happened in
> a function, it is rather designed for relative comparison across your code.
>
> If you are getting too few samples, try to decrease the sample rate as I
> did in the example. Have a look at `ophelp` what is the lowest value for
> your event.
>
> Also please note that the min sample rates are rough and depend on the
> load,
> so under low load, lower rates can be used without issues. When you profile
> systemwide on all CPUs, it's very high chance that you'll run into an
> overhead
> and lose many samples...
>
> I hope I explained it a bit.
>
> Cheers,
> Michael
>
> > Thanks,
> >
> > Dhara Buch
> >
> >

Re: Operf and Opreport outputs

[Michael Petlan <mpetlan@re...>]

On Fri, 16 Jun 2017, dhara buch wrote:
> Hello,
> 
> Many days ago you had helped me a lot in using Oprofile in Virtual Machine. That time, I also had a query regarding
> getting information from 'opreport --symbols --debuginfo' command.

Hello,

yeah, I remember...

> 
> Actually, I am profiling a file1.c file with the following commands...
> 
> 1. gcc -g file1.c -o file1
> 
> 2. operf ./file1 --events=CPU_CLK_UNHALTED
> 
> 3. opreport --symbols --debuginfo
> 
> the output contains various lines where one line look follows:
> 
> samples  %        linenr info                 image name               symbol name
> 
> 2       12.5000  rsaimp.c:16                 rsaimp                   MM
> 2        12.5000  rsaimp.c:34                 rsaimp                   main
> 
> When I execute commands 2 and 3 multiple times, each time I gwt the output for symbole name MM (which is UDF in the
> program) but I don't get output for main every time.
> 
This is kind of random, see below.

> Additionally,'' the sample % also vary every time I file operf command. I do not understand the working of operf that
> how it gives different outputs for the same program.
> 

How _counting_ works:

Each time an event happens in CPU (in our case -- CPU_CLK_UNHALTED -- one
CPU tick), its counter is incremented by one. This way, you can get the
whole number of how many times the event happened:

$ ocount ls
Events were actively counted for 1863267 nanoseconds.
Event counts (actual) for /bin/ls:
	  Event                    Count                    % time counted
	  CPU_CLK_UNHALTED         2,672,309                100.00

This means that there were 2.672 million CPU ticks necessary to execute
`ls`.

The tool for counting is *ocount*.


How _profiling_ works:

For profiling, events are counted the same way as when counting, but only
once per N event occurrences a "sample" is taken. A sample is a piece of
information about where in the code it happened, what was the context and
potentially call-stack, etc. This sample is saved into the oprofile_data
dir structure. When you finish profiling, opreport generates some overview
from the samples recorded.

Of course, taking sample causes some overhead. Thus, you cannot take it
each time the event counter increments. For this purpose, there is "sample
rate" value which divides the event counter and takes a sample only once
per "sample rate" occurrences. Thus, it is pretty random, which event
occurrence is picked for a sample.

Of course, your main() consumes CPU ticks and the counter is incremented,
but sometimes, one of these incrementations produces sample, sometimes not,
thus the function is missing.

You have 2 samples on each of the line in the report. That is really a low
number, so it is very probable that sometimes the samples hit main() and
sometimes not.

$ operf ls
Profiling done.

$ opreport
Using /root/oprofile_data/samples/ for samples directory.
CPU: Core 2, speed 2267 MHz (estimated)
Counted CPU_CLK_UNHALTED events (Clock cycles when not halted) with a unit mask of 0x00 (Unhalted core cycles) count 100000
CPU_CLK_UNHALT...|
  samples|      %|
------------------
 -->   37 100.000 ls
       CPU_CLK_UNHALT...|
         samples|      %|
		 ------------------
              27 72.9730 kallsyms
               5 13.5135 libc-2.19.so
               2  5.4054 ld-2.19.so
               1  2.7027 ls
               1  2.7027 ext4
               1  2.7027 libattr.so.1.1.0

You see that out of (estimated) 2.5-3.5 mil of event occurrences (which is
the scale `ls` usually needs on my PC), I got only 37 samples.

The sample rate for each event are in `ophelp` as "min count".

Why did I get 37 samples? My default setting of default event is:

$ ophelp -d
CPU_CLK_UNHALTED:100000:0:1:1
-------------------^^

This means that there is 1 sample per 100000 event occurrences.

You can tweak this value a bit, but note that oprofile won't let you set
the value to be too low, due to the overhead reasons.

Let's try 10000 (sampling 10 times more often):

$ operf -e CPU_CLK_UNHALTED:10000 ls
WARNING: Lost samples detected! See /root/oprofile_data/samples/operf.log for details.
Lowering the sampling rate may reduce or eliminate lost samples.
See the '--events' option description in the operf man page for help.
Profiling done.

$ opreport
Using /root/oprofile_data/samples/ for samples directory.
WARNING: Lost samples detected! See /root/oprofile_data/samples/operf.log for details.
CPU: Core 2, speed 2267 MHz (estimated)
Counted CPU_CLK_UNHALTED events (Clock cycles when not halted) with a unit mask of 0x00 (Unhalted core cycles) count 10000
CPU_CLK_UNHALT...|
  samples|      %|
------------------
      429 100.000 ls
      CPU_CLK_UNHALT...|
        samples|      %|
        ------------------
              313 72.9604 kallsyms
               55 12.8205 ld-2.19.so
               34  7.9254 libc-2.19.so
               17  3.9627 ls
                8  1.8648 ext4
                2  0.4662 binfmt_misc

You see that both operf and opreport warned about lost samples which means
that the overhead in kernel was too high and some samples were lost. But
probably not that many, since you see that I got 429 samples instead of
37 which is very roughly 10 times more.


Profiling is not for exact measurement of how many CPU ticks happened in
a function, it is rather designed for relative comparison across your code.

If you are getting too few samples, try to decrease the sample rate as I
did in the example. Have a look at `ophelp` what is the lowest value for
your event.

Also please note that the min sample rates are rough and depend on the load,
so under low load, lower rates can be used without issues. When you profile
systemwide on all CPUs, it's very high chance that you'll run into an overhead
and lose many samples...

I hope I explained it a bit.

Cheers,
Michael

> Thanks,
> 
> Dhara Buch
> 
> 

Re: [PATCH] oprofile update pointers to documentation for Power

[William Cohen <wcohen@re...>]

On 06/09/2017 03:29 PM, Will Schmidt wrote:
> 
> Hi, 
> Update the documentation pointers to the current home
> for the Power ISA and P8 Users Manual.
> 
> Signed-off-by:  Will Schmidt <will_schmidt@...>
> 
> Thanks
> -Will

Thanks for the quick patch.  It has been merged into the upstream oprofile.

-Will

> 
> 
> --
> 
> diff --git a/utils/ophelp.c b/utils/ophelp.c
> index f76bf2a..ed278c2 100644
> --- a/utils/ophelp.c
> +++ b/utils/ophelp.c
> @@ -683,13 +683,17 @@ int main(int argc, char const * argv[])
>  	case CPU_PPC64_POWER8:
>  		event_doc =
>  			"This processor type is fully supported with operf.\n"
> -			"See Power ISA 2.07 at https://www.power.org/\n\n";;
> +			"See Power ISA 3.0B at "
> +			"https://openpowerfoundation.org/?submit=Search&s=ISA \n"
> +			"And the P8 Users Manual at "
> +			"https://www-355.ibm.com/systems/power/openpower \n\n";
>  		break;
>  
>  	case CPU_PPC64_POWER9:
>  		event_doc =
>  			"This processor type is fully supported with operf.\n"
> -			"See Power ISA 3.0 at https://www.power.org/\n\n";;
> +			"See Power ISA 3.0B at "
> +			"https://openpowerfoundation.org/?resource_lib=power-isa-version-3-0\n";;
>  		break;
>  
>  	case CPU_MIPS_20K:
> 
> 

[PATCH] oprofile update pointers to documentation for Power

[Will Schmidt <will_schmidt@vn...>]

Hi, 
Update the documentation pointers to the current home
for the Power ISA and P8 Users Manual.

Signed-off-by:  Will Schmidt <will_schmidt@...>

Thanks
-Will


--

diff --git a/utils/ophelp.c b/utils/ophelp.c
index f76bf2a..ed278c2 100644
--- a/utils/ophelp.c
+++ b/utils/ophelp.c
@@ -683,13 +683,17 @@ int main(int argc, char const * argv[])
 	case CPU_PPC64_POWER8:
 		event_doc =
 			"This processor type is fully supported with operf.\n"
-			"See Power ISA 2.07 at https://www.power.org/\n\n";;
+			"See Power ISA 3.0B at "
+			"https://openpowerfoundation.org/?submit=Search&s=ISA \n"
+			"And the P8 Users Manual at "
+			"https://www-355.ibm.com/systems/power/openpower \n\n";
 		break;
 
 	case CPU_PPC64_POWER9:
 		event_doc =
 			"This processor type is fully supported with operf.\n"
-			"See Power ISA 3.0 at https://www.power.org/\n\n";;
+			"See Power ISA 3.0B at "
+			"https://openpowerfoundation.org/?resource_lib=power-isa-version-3-0\n";;
 		break;
 
 	case CPU_MIPS_20K:

Re: [PATCH] 1/2 Oprofile support for Power9

[Will Schmidt <will_schmidt@vn...>]

On Wed, 2017-06-07 at 14:30 -0500, Will Schmidt wrote:
> On Wed, 2017-06-07 at 14:56 -0400, William Cohen wrote:
> > On 06/06/2017 11:52 AM, Will Schmidt wrote:
> > > Hi, 
> > >  
> > > +	case CPU_PPC64_POWER9:
> > > +		event_doc =
> > > +			"This processor type is fully supported with operf.\n"
> > > +			"See Power ISA 3.0 at https://www.power.org/\n\n";;
> > > +		break;
> > 
> > https://www.power.org/ seems to be unreachable.  It that site still the correct site for this information?
> > 
> > -Will
> 
> Hmm, same thing for me here.   I'm not sure what is going on with
> power.org.   I'll have to get back to you on this one.

The power.org references are no longer valid.  
Openpowerfoundation.org is the current home for the P8 and newer
documents.
I'll have an update for the power8/power9 references from ophelp posted
here momentarily.

Thanks,
-Will

> 
> -Will
> 
> 
> 

[PATCH] oprofile-tests power9 support

[Will Schmidt <will_schmidt@vn...>]

Hi, 

Add Power9 support to oprofile-tests.
Sniff tested on an early P9.

Signed-off-by:  Will Schmidt <will_schmidt@...>

--


diff --git a/testsuite/lib/op_events.exp b/testsuite/lib/op_events.exp
index ec804d2..4b7a437 100644
--- a/testsuite/lib/op_events.exp
+++ b/testsuite/lib/op_events.exp
@@ -456,6 +456,20 @@ set op_event_table(power8)                          \
 	}                                           \
     }
 
+set op_event_table(power9)                          \
+    {                                               \
+	{                                           \
+	    {0 CYCLES 0 500000}                     \
+	}                                           \
+	{                                           \
+	    {0 PM_BR_CMPL 0 100000}                 \
+	    {1 PM_BR_TAKEN_CMPL 0 100000}           \
+	    {3 PM_INST_DISP 0 100000}               \
+	    {4 PM_RUN_INST_CMPL 0 500000}           \
+	    {5 PM_RUN_CYC  0 500000}                \
+	}                                           \
+    }
+
 set op_event_table(ibm_power_architected_v1)                          \
     {                                               \
 	{                                           \
@@ -816,6 +830,9 @@ proc select_cpu_events {cpu_name} {
 	Intel_Broadwell_microarchitecture {set type arch_perf}
 	i386/skylake {set type skylake}
 	Intel_Skylake_microarchitecture {set type skylake}
+	ppc64/power9 {set type power9}
+	ppc64_POWER9 {set type power9}
+
     }
 
     verbose "cpu type is $type"

Re: [PATCH] 1/2 Oprofile support for Power9

[Will Schmidt <will_schmidt@vn...>]

On Thu, 2017-06-08 at 09:45 -0400, William Cohen wrote:
> On 06/07/2017 02:51 PM, Will Schmidt wrote:
> > On Wed, 2017-06-07 at 13:17 -0400, William Cohen wrote:
> >> On 06/06/2017 11:52 AM, Will Schmidt wrote:
> >>> Hi, 
> >>>
> >>> Add initial support for PPC64/Power9 to oprofile.
> >>> This includes the documentation updates to indicate "power9",
> >>> the PVR values, and all the other updates that will be necessary.
> >>> (This is based on a review of changes made when Power8 support
> >>> was initially added).
> >>> The long-ish event list follows as a subsequent patch.
> >>>     
> >>> Signed-off-by:  Will Schmidt <will_schmidt@...>
> >>>
> >>> --
> >>>
> >>
> >> Hi Will,
> >>
> >> I have started to review the power9 patches.  IIRC OProfile uses libpfm
> >>  for some of the event mapping for power processors.  Is that the case
> >>  for power9 also?  Are there similar power9 patches coming for libpfm?
> > 
> > Yes.  They've been sent (yesterday), and I believe are now in the
> > moderator queue awaiting approval, due to their size. 
> > 
> >>
> >> -Will
> >>
> > 
> > 
> 
> Hi Will,
> 
> The patches looked reasonable, so they have been checked into the main oprofile git repository.  Thanks for the patches.
> 
> Do you have some patches to add to the oprofile-testsuite to allow testing oprofile on power9?

I had spaced this part, my bad.  Thanks for the reminder... :-) 

Patch to add p9 to the testsuite will be following momentarily. 


> 
> -Will
> 

Re: [PATCH] 1/2 Oprofile support for Power9

[William Cohen <wcohen@re...>]

On 06/07/2017 02:51 PM, Will Schmidt wrote:
> On Wed, 2017-06-07 at 13:17 -0400, William Cohen wrote:
>> On 06/06/2017 11:52 AM, Will Schmidt wrote:
>>> Hi, 
>>>
>>> Add initial support for PPC64/Power9 to oprofile.
>>> This includes the documentation updates to indicate "power9",
>>> the PVR values, and all the other updates that will be necessary.
>>> (This is based on a review of changes made when Power8 support
>>> was initially added).
>>> The long-ish event list follows as a subsequent patch.
>>>     
>>> Signed-off-by:  Will Schmidt <will_schmidt@...>
>>>
>>> --
>>>
>>
>> Hi Will,
>>
>> I have started to review the power9 patches.  IIRC OProfile uses libpfm
>>  for some of the event mapping for power processors.  Is that the case
>>  for power9 also?  Are there similar power9 patches coming for libpfm?
> 
> Yes.  They've been sent (yesterday), and I believe are now in the
> moderator queue awaiting approval, due to their size. 
> 
>>
>> -Will
>>
> 
> 

Hi Will,

The patches looked reasonable, so they have been checked into the main oprofile git repository.  Thanks for the patches.

Do you have some patches to add to the oprofile-testsuite to allow testing oprofile on power9?

-Will

Re: [PATCH] 1/2 Oprofile support for Power9

[Will Schmidt <will_schmidt@vn...>]

On Wed, 2017-06-07 at 14:56 -0400, William Cohen wrote:
> On 06/06/2017 11:52 AM, Will Schmidt wrote:
> > Hi, 
> >  
> > +	case CPU_PPC64_POWER9:
> > +		event_doc =
> > +			"This processor type is fully supported with operf.\n"
> > +			"See Power ISA 3.0 at https://www.power.org/\n\n";;
> > +		break;
> 
> https://www.power.org/ seems to be unreachable.  It that site still the correct site for this information?
> 
> -Will

Hmm, same thing for me here.   I'm not sure what is going on with
power.org.   I'll have to get back to you on this one.

-Will