OProfile manual

The --event option to opcontrol takes a specification that indicates how the details of each hardware performance counter should be setup. If you want to revert to OProfile's default setting (--event is strictly optional), use --event=default.

You can pass multiple event specifications. OProfile will allocate hardware counters as necessary. Note that some combinations are not allowed by the CPU; running opcontrol --list-events gives the details of each event. The event specification is a colon-separated string of the form name:count:unitmask:kernel:user as described in this table:

The last three values are optional, if you omit them (e.g. --event=DATA_MEM_REFS:30000), they will be set to the default values (a unit mask of 0, and profiling both kernel and userspace code). Note that some events require a unit mask.

If OProfile is using RTC mode, and you want to alter the default counter value, you can use something like --event=RTC_INTERRUPTS:2048. Note the last three values here are ignored. If OProfile is using timer-interrupt mode, there is no configuration possible.

The table below lists the events selected by default (--event=default) for the various computer architectures:

Some CPU types do not provide the needed hardware support to use the hardware performance counters. This includes some laptops, classic Pentiums, and other CPU types not yet supported by OProfile (such as Cyrix). On these machines, OProfile falls back to using the real-time clock interrupt to collect samples. This interrupt is also used by the rtc module: you cannot have both the OProfile and rtc modules loaded nor the rtc support compiled in the kernel.

RTC mode is less capable than the hardware counters mode; in particular, it is unable to profile sections of the kernel where interrupts are disabled. There is just one available event, "RTC interrupts", and its value corresponds to the number of interrupts generated per second (that is, a higher number means a better profiling resolution, and higher overhead). The current implementation of the real-time clock supports only power-of-two sampling rates from 2 to 4096 per second. Other values within this range are rounded to the nearest power of two.

You can force use of the RTC interrupt with the force_rtc=1 module parameter.

Setting the value from the GUI should be straightforward. On the command line, you need to specify the event to opcontrol, e.g. :

opcontrol --event=RTC_INTERRUPTS:256

In 2.6 kernels on CPUs without OProfile support for the hardware performance counters, the driver falls back to using the timer interrupt for profiling. Like the RTC mode in 2.4 kernels, this is not able to profile code that has interrupts disabled. Note that there are no configuration parameters for setting this, unlike the RTC and hardware performance counter setup.

You can force use of the timer interrupt by using the timer=1 module parameter (or oprofile.timer=1 on the boot command line if OProfile is built-in).

The Pentium 4 / Xeon performance counters are organized around 3 types of model specific registers (MSRs): 45 event selection control registers (ESCRs), 18 counter configuration control registers (CCCRs) and 18 counters. ESCRs describe a particular set of events which are to be recorded, and CCCRs bind ESCRs to counters and configure their operation. Unfortunately the relationship between these registers is quite complex; they cannot all be used with one another at any time. There is, however, a subset of 8 counters, 8 ESCRs, and 8 CCCRs which can be used independently of one another, so OProfile only accesses those registers, treating them as a bank of 8 "normal" counters, similar to those in the P6 or Athlon families of CPU.

There is currently no support for Precision Event-Based Sampling (PEBS), nor any advanced uses of the Debug Store (DS). Current support is limited to the conservative extension of OProfile's existing interrupt-based model described above. Performance monitoring hardware on Pentium 4 / Xeon processors with Hyperthreading enabled (multiple logical processors on a single die) is not supported in 2.4 kernels (you can use OProfile if you disable hyper-threading, though).

The Itanium 2 performance monitoring unit (PMU) organizes the counters as four pairs of performance event monitoring registers. Each pair is composed of a Performance Monitoring Configuration (PMC) register and Performance Monitoring Data (PMD) register. The PMC selects the performance event being monitored and the PMD determines the sampling interval. The IA64 Performance Monitoring Unit (PMU) triggers sampling with maskable interrupts. Thus, samples will not occur in sections of the IA64 kernel where interrupts are disabled.

None of the advance features of the Itanium 2 performance monitoring unit such as opcode matching, address range matching, or precise event sampling are supported by this version of OProfile. The Itanium 2 support only maps OProfile's existing interrupt-based model to the PMU hardware.

The performance monitoring unit (PMU) for the PowerPC 64-bit processors consists of between 6 and 8 counters (depending on the model), plus three special purpose registers used for programming the counters -- MMCR0, MMCR1, and MMCRA. Advanced features such as instruction matching and thresholding are not supported by this version of OProfile.

OProfile is a low-level profiler which allow continuous profiling with a low-overhead cost. If too low a count reset value is set for a counter, the system can become overloaded with counter interrupts, and seem as if the system has frozen. Whilst some validation is done, it is not foolproof.

If this happens, it will be impossible to bring the system back to a workable state. There is no way to provide real security against this happening, other than making sure to use a reasonable value for the counter reset. For example, setting CPU_CLK_UNHALTED event type with a ridiculously low reset count (e.g. 500) is likely to freeze the system.

In short : Don't try a foolish sample count value. Unfortunately the definition of a foolish value is really dependent on the event type - if ever in doubt, e-mail

Image summaries for all profiles with DATA_MEM_REFS samples in the saved session called "stresstest" :

# opreport session:stresstest event:DATA_MEM_REFS

Symbol summary for the application called "test_sym53c8xx,9xx". Note the escaping is necessary as image: takes a comma-separated list.

# opreport -l ./test/test_sym53c8xx\,9xx

Image summaries for all binaries in the test directory, excepting boring-test :

# opreport image:./test/\* image-exclude:./test/boring-test

Differential profile of a binary stored in two archives :

# opreport -l /bin/bash { archive:./orig } { archive:./new }

Differential profile of an archived binary with the current session :

# opreport -l /bin/bash { archive:./orig } { }

Each session's sample files can be found in the /var/lib/oprofile/samples/ directory. These are used, along with the binary image files, to produce human-readable data. In some circumstances (kernel modules in an initrd, or modules on 2.6 kernels), OProfile will not be able to find the binary images. All the tools have an --image-path option to which you can pass a comma-separated list of alternate paths to search. For example, I can let OProfile find my 2.6 modules by using --image-path /lib/modules/2.6.0/kernel/. It is your responsibility to ensure that the correct images are found when using this option.

Note that if a binary image changes after the sample file was created, you won't be able to get useful symbol-based data out. This situation is detected for you. If you replace a binary, you should make sure to save the old binary if you need to do comparative profiles.

When attempting to get output, you may see the error :

error: no sample files found: profile specification too strict ?

What this is saying is that the profile specification you passed in, when matched against the available sample files, resulted in no matches. There are a number of reasons this might happen:

When using the opcontrol --callgraph option, you can see what functions are calling other functions in the output. Consider the following program:

#include <string.h>
#include <stdlib.h>
#include <stdio.h>

#define SIZE 500000

static int compare(const void *s1, const void *s2)
{
        return strcmp(s1, s2);
}

static void repeat(void)
{
        int i;
        char *strings[SIZE];
        char str[] = "abcdefghijklmnopqrstuvwxyz";

        for (i = 0; i < SIZE; ++i) {
                strings[i] = strdup(str);
                strfry(strings[i]);
        }

        qsort(strings, SIZE, sizeof(char *), compare);
}

int main()
{
        while (1)
                repeat();
}

When running with the call-graph option, OProfile will record the function stack every time it takes a sample. opreport --callgraph outputs an entry for each function, where each entry looks similar to:

samples  %        image name               symbol name
  197       0.1548  cg                       main
  127036   99.8452  cg                       repeat
84590    42.5084  libc-2.3.2.so            strfry
  84590    66.4838  libc-2.3.2.so            strfry [self]
  39169    30.7850  libc-2.3.2.so            random_r
  3475      2.7312  libc-2.3.2.so            __i686.get_pc_thunk.bx
-------------------------------------------------------------------------------

Here the non-indented line is the function we're focussing upon (strfry()). This line is the same as you'd get from a normal opreport output.

Above the non-indented line we find the functions that called this function (for example, repeat() calls strfry()). The samples and percentage values here refer to the number of times we took a sample where this call was found in the stack; the percentage is relative to all other callers of the function we're focussing on. Note that these values are not call counts; they only reflect the call stack every time a sample is taken; that is, if a call is found in the stack at the time of a sample, it is recorded in this count.

Below the line are functions that are called by strfry() (called callees). It's clear here that strfry() calls random_r(). We also see a special entry with a "[self]" marker. This records the normal samples for the function, but the percentage becomes relative to all callees. This allows you to compare time spent in the function itself compared to functions it calls. Note that if a function calls itself, then it will appear in the list of callees of itself, but without the "[self]" marker; so recursive calls are still clearly separable.

Often, we'd like to be able to compare two profiles. For example, when analysing the performance of an application, we'd like to make code changes and examine the effect of the change. This is supported in opreport by giving a profile specification that identifies two different profiles. The general form is of:

$ opreport <shared-spec> { <first-profile> } { <second-profile> }

For each of the profiles, the shared section is prefixed, and then the specification is analysed. The usual parameters work both within the shared section, and in the sub-specification within the curly braces.

A typical way to use this feature is with archives created with oparchive. Let's look at an example:

$ ./a
$ oparchive -o orig ./a
$ opcontrol --reset
  # edit and recompile a
$ ./a
  # now compare the current profile of a with the archived profile
$ opreport -xl ./a { archive:./orig } { }
CPU: PIII, speed 863.233 MHz (estimated)
Counted CPU_CLK_UNHALTED events (clocks processor is not halted) with a
unit mask of 0x00 (No unit mask) count 100000
samples  %        diff %    symbol name
92435    48.5366  +0.4999   a
54226    ---      ---       c
49222    25.8459  +++       d
48787    25.6175  -2.2e-01  b

Note that we specified an empty second profile in the curly braces, as we wanted to use the current session; alternatively, we could have specified another archive, or a tgid etc. We specified the binary a in the shared section, so we matched that in both the profiles we're diffing.

As in the normal output, the results are sorted by the number of samples, and the percentage field represents the relative percentage of the symbol's samples in the second profile.

Notice the new column in the output. This value represents the percentage change of the relative percent between the first and the second profile: roughly, "how much more important this symbol is". Looking at the symbol a(), we can see that it took roughly the same amount of the total profile in both the first and the second profile. The function c() was not in the new profile, so has been marked with ---. Note that the sample value is the number of samples in the first profile; since we're displaying results for the second profile, we don't list a percentage value for it, as it would be meaningless. d() is new in the second profile, and consequently marked with +++.

When comparing profiles between different binaries, it should be clear that functions can change in terms of VMA and size. To avoid this problem, opreport considers a symbol to be the same if the symbol name, image name, and owning application name all match; any other factors are ignored. Note that the check for application name means that trying to compare library profiles between two different applications will not work as you might expect: each symbol will be considered different.

Many applications, typically ones involving dynamic compilation into machine code, have executable mappings that are not backed by an ELF file. opreport has basic support for showing the samples taken in these regions; for example:

$ opreport /usr/jre1.5.0/bin/java
CPU: PIII, speed 863.195 MHz (estimated)
Counted CPU_CLK_UNHALTED events (clocks processor is not halted) with a unit mask of 0x00 (No unit mask) count 100000
CPU_CLK_UNHALT...|
  samples|      %|
------------------
    27344 100.000 java
        CPU_CLK_UNHALT...|
          samples|      %|
        ------------------
            27236  99.605 anon (tgid:12135 range:0xb2cb8000-0xb2e80000)
              108  0.3949 java

Currently, there is no support for getting symbol-based summaries for such regions. Note that, since such mappings are dependent upon individual invocations of a binary, these mappings are always listed as a dependent image, even when using --separate=none. Equally, the results are not affected by the --merge option.

Of course, opannotate needs to be able to locate the source files for the binary image(s) in order to produce output. Some binary images have debug information where the given source file paths are relative, not absolute. You can specify search paths to look for these files (similar to gdb's dir command) with the --search-dirs option.

Sometimes you may have a binary image which gives absolute paths for the source files, but you have the actual sources elsewhere (commonly, you've installed an SRPM for a binary on your system and you want annotation from an existing profile). You can use the --base-dirs option to redirect OProfile to look somewhere else for source files. For example, imagine we have a binary generated from a source file that is given in the debug information as /tmp/build/libfoo/foo.c, and you have the source tree matching that binary installed in /home/user/libfoo/. You can redirect OProfile to find foo.c correctly like this :

$ opannotate --source --base-dirs=/tmp/build/libfoo/ --search-dirs=/home/user/libfoo/ --output-dir=annotated/ /lib/libfoo.so

You can specify multiple (comma-separated) paths to both options.

OProfile uses non-maskable interrupts (NMI) on the P6 generation, Pentium 4, Athlon and Duron processors. These interrupts can occur even in section of the Linux where interrupts are disabled, allowing collection of samples in virtually all executable code. The RTC, timer interrupt mode, and Itanium 2 collection mechanisms use maskable interrupts. Thus, the RTC and Itanium 2 data collection mechanism have "sample shadows", or blind spots: regions where no samples will be collected. Typically, the samples will be attributed to the code immediately after the interrupts are re-enabled.

Your kernel is likely to support halting the processor when a CPU is idle. As the typical hardware events like CPU_CLK_UNHALTED do not count when the CPU is halted, the kernel profile will not reflect the actual amount of time spent idle. You can change this behaviour by booting with the idle=poll option, which uses a different idle routine. This will appear as poll_idle() in your kernel profile.

OProfile profiles kernel modules by default. However, there are a couple of problems you may have when trying to get results. First, you may have booted via an initrd; this means that the actual path for the module binaries cannot be determined automatically. To get around this, you can use the -p option to the profiling tools to specify where to look for the kernel modules.

In 2.6, the information on where kernel module binaries are located has been removed. This means OProfile needs guiding with the -p option to find your modules. Normally, you can just use your standard module top-level directory for this. Note that due to this problem, OProfile cannot check that the modification times match; it is your responsibility to make sure you do not modify a binary after a profile has been created.

If you have run insmod or modprobe to insert a module in a particular directory, it is important that you specify this directory with the -p option first, so that it over-rides an older module binary that might exist in other directories you've specified with -p. It is up to you to make sure that these values are correct: 2.6 kernels simply do not provide enough information for OProfile to get this information.

The compiler can introduce some pitfalls in the annotated source output. The optimizer can move pieces of code in such manner that two line of codes are interlaced (instruction scheduling). Also debug info generated by the compiler can show strange behavior. This is especially true for complex expressions e.g. inside an if statement:

	if (a && ..
	    b && ..
	    c &&)

here the problem come from the position of line number. The available debug info does not give enough details for the if condition, so all samples are accumulated at the position of the right brace of the expression. Using opannotate -a can help to show the real samples at an assembly level.

The compiler generally needs to generate "glue" code across function calls, dependent on the particular function call conventions used. Additionally other things need to happen, like stack pointer adjustment for the local variables; this code is known as the function prologue. Similar code is needed at function return, and is known as the function epilogue. This will show up in annotations as samples at the very start and end of a function, where there is no apparent executable code in the source.

You may see that a function is credited with a certain number of samples, but the listing does not add up to the correct total. To pick a real example :

               :internal_sk_buff_alloc_security(struct sk_buff *skb)
 353 2.342%    :{ /* internal_sk_buff_alloc_security total: 1882 12.48% */
               :
               :        sk_buff_security_t *sksec;
  15 0.0995%   :        int rc = 0;
               :
  10 0.06633%  :        sksec = skb->lsm_security;
 468 3.104%    :        if (sksec && sksec->magic == DSI_MAGIC) {
               :                goto out;
               :        }
               :
               :        sksec = (sk_buff_security_t *) get_sk_buff_memory(skb);
   3 0.0199%   :        if (!sksec) {
  38 0.2521%   :                rc = -ENOMEM;
               :                goto out;
  10 0.06633%  :        }
               :        memset(sksec, 0, sizeof (sk_buff_security_t));
  44 0.2919%   :        sksec->magic = DSI_MAGIC;
  32 0.2123%   :        sksec->skb = skb;
  45 0.2985%   :        sksec->sid = DSI_SID_NORMAL;
  31 0.2056%   :        skb->lsm_security = sksec;
               :
               :      out:
               :
 146 0.9685%   :        return rc;
               :
  98 0.6501%   :}

Here, the function is credited with 1,882 samples, but the annotations below do not account for this. This is usually because of inline functions - the compiler marks such code with debug entries for the inline function definition, and this is where opannotate annotates such samples. In the case above, memset is the most likely candidate for this problem. Examining the mixed source/assembly output can help identify such results.

This problem is more visible when there is no source file available, in the following example it's trivially visible the sums of symbols samples is less than the number of the samples for this file. The difference must be accounted to inline functions.

/*
 * Total samples for file : "arch/i386/kernel/process.c"
 *
 *    109  2.4616
 */

 /* default_idle total:     84  1.8970 */
 /* cpu_idle total:         21  0.4743 */
 /* flush_thread total:      1  0.0226 */
 /* prepare_to_copy total:   1  0.0226 */
 /* __switch_to total:      18  0.4065 */

The missing samples are not lost, they will be credited to another source location where the inlined function is defined. The inlined function will be credited from multiple call site and merged in one place in the annotated source file so there is no way to see from what call site are coming the samples for an inlined function.

When running opannotate, you may get a warning "some functions compiled without debug information may have incorrect source line attributions". In some rare cases, OProfile is not able to verify that the derived source line is correct (when some parts of the binary image are compiled without debugging information). Be wary of results if this warning appears.

Furthermore, for some languages the compiler can implicitly generate functions, such as default copy constructors. Such functions are labelled by the compiler as having a line number of 0, which means the source annotation can be confusing.

Depending on your compiler you can fall into the following problem:

struct big_object { int a[500]; };

int main()
{
	big_object a, b;
	for (int i = 0 ; i != 1000 * 1000; ++i)
		b = a;
	return 0;
}

Compiled with gcc 3.0.4 the annotated source is clearly inaccurate:

               :int main()
               :{  /* main total: 7871 100% */
               :        big_object a, b;
               :        for (int i = 0 ; i != 1000 * 1000; ++i)
               :                b = a;
 7871 100%     :        return 0;
               :}

The problem here is distinct from the IRQ latency problem; the debug line number information is not precise enough; again, looking at output of opannoatate -as can help.

               :int main()
               :{
               :        big_object a, b;
               :        for (int i = 0 ; i != 1000 * 1000; ++i)
               : 80484c0:       push   %ebp
               : 80484c1:       mov    %esp,%ebp
               : 80484c3:       sub    $0xfac,%esp
               : 80484c9:       push   %edi
               : 80484ca:       push   %esi
               : 80484cb:       push   %ebx
               :                b = a;
               : 80484cc:       lea    0xfffff060(%ebp),%edx
               : 80484d2:       lea    0xfffff830(%ebp),%eax
               : 80484d8:       mov    $0xf423f,%ebx
               : 80484dd:       lea    0x0(%esi),%esi
               :        return 0;
    3 0.03811% : 80484e0:       mov    %edx,%edi
               : 80484e2:       mov    %eax,%esi
    1 0.0127%  : 80484e4:       cld
    8 0.1016%  : 80484e5:       mov    $0x1f4,%ecx
 7850 99.73%   : 80484ea:       repz movsl %ds:(%esi),%es:(%edi)
    9 0.1143%  : 80484ec:       dec    %ebx
               : 80484ed:       jns    80484e0
               : 80484ef:       xor    %eax,%eax
               : 80484f1:       pop    %ebx
               : 80484f2:       pop    %esi
               : 80484f3:       pop    %edi
               : 80484f4:       leave
               : 80484f5:       ret

So here it's clear that copying is correctly credited with of all the samples, but the line number information is misplaced. objdump -dS exposes the same problem. Note that maintaining accurate debug information for compilers when optimizing is difficult, so this problem is not suprising. The problem of debug information accuracy is also dependent on the binutils version used; some BFD library versions contain a work-around for known problems of gcc, some others do not. This is unfortunate but we must live with that, since profiling is pointless when you disable optimisation (which would give better debugging entries).