2.5.5.2. A Sample OProfile Session

This section shows an OProfile monitoring and data analysis session from initial configuration to final data analysis. It is only an introductory overview; for more detailed information, consult the System Administrators Guide.
Use opcontrol to configure the type of data to be collected with the following command: 
opcontrol \ --vmlinux=/boot/vmlinux-`uname -r` \ --ctr0-event=CPU_CLK_UNHALTED \ --ctr0-count=6000
The options used here direct opcontrol to:
  • Direct OProfile to a copy of the currently running kernel (--vmlinux=/boot/vmlinux-`uname -r`)
  • Specify that the processor's counter 0 is to be used and that the event to be monitored is the time when the CPU is executing instructions (--ctr0-event=CPU_CLK_UNHALTED)
  • Specify that OProfile is to collect samples every 6000th time the specified event occurs (--ctr0-count=6000)
Next, check that the oprofile kernel module is loaded by using the lsmod command: 
 Module Size Used by Not tainted oprofile 75616 1 …
Confirm that the OProfile file system (located in /dev/oprofile/) is mounted with the ls /dev/oprofile/ command: 
 0 buffer buffer_watershed cpu_type enable stats 1 buffer_size cpu_buffer_size dump kernel_only
(The exact number of files varies according to processor type.)
At this point, the /root/.oprofile/daemonrc file contains the settings required by the data collection software: 
 CTR_EVENT[0]=CPU_CLK_UNHALTED CTR_COUNT[0]=6000 CTR_KERNEL[0]=1 CTR_USER[0]=1 CTR_UM[0]=0 CTR_EVENT_VAL[0]=121 CTR_EVENT[1]= CTR_COUNT[1]= CTR_KERNEL[1]=1 CTR_USER[1]=1 CTR_UM[1]=0 CTR_EVENT_VAL[1]= one_enabled=1 SEPARATE_LIB_SAMPLES=0 SEPARATE_KERNEL_SAMPLES=0 VMLINUX=/boot/vmlinux-2.4.21-1.1931.2.349.2.2.entsmp
Next, use opcontrol to actually start data collection with the opcontrol --start command: 
 Using log file /var/lib/oprofile/oprofiled.log Daemon started. Profiler running.
Verify that the oprofiled daemon is running with the command ps x | grep -i oprofiled: 
 32019 ? S 0:00 /usr/bin/oprofiled --separate-lib-samples=0 … 32021 pts/0 S 0:00 grep -i oprofiled
(The actual oprofiled command line displayed by ps is much longer; however, it has been truncated here for formatting purposes.)
The system is now being monitored, with the data collected for all executables present on the system. The data is stored in the /var/lib/oprofile/samples/ directory. The files in this directory follow a somewhat unusual naming convention. Here is an example: 
 }usr}bin}less#0
The naming convention uses the absolute path of each file containing executable code, with the slash (/) characters replaced by right curly brackets (}), and ending with a pound sign (#) followed by a number (in this case, 0.) Therefore, the file used in this example represents data collected while /usr/bin/less was running.
Once data has been collected, use one of the analysis tools to display it. One nice feature of OProfile is that it is not necessary to stop data collection before performing a data analysis. However, you must wait for at least one set of samples to be written to disk, or use the opcontrol --dump command to force the samples to disk.
In the following example, op_time is used to display (in reverse order -- from highest number of samples to lowest) the samples that have been collected: 
 3321080 48.8021 0.0000 /boot/vmlinux-2.4.21-1.1931.2.349.2.2.entsmp 761776 11.1940 0.0000 /usr/bin/oprofiled 368933 5.4213 0.0000 /lib/tls/libc-2.3.2.so 293570 4.3139 0.0000 /usr/lib/libgobject-2.0.so.0.200.2 205231 3.0158 0.0000 /usr/lib/libgdk-x11-2.0.so.0.200.2 167575 2.4625 0.0000 /usr/lib/libglib-2.0.so.0.200.2 123095 1.8088 0.0000 /lib/libcrypto.so.0.9.7a 105677 1.5529 0.0000 /usr/X11R6/bin/XFree86 …
Using less is a good idea when producing a report interactively, as the reports can be hundreds of lines long. The example given here has been truncated for that reason.
The format for this particular report is that one line is produced for each executable file for which samples were taken. Each line follows this format: 
<sample-count> <sample-percent> <unused-field> <executable-name>
Where:
  • <sample-count> represents the number of samples collected
  • <sample-percent> represents the percentage of all samples collected for this specific executable
  • <unused-field> is a field that is not used
  • <executable-name> represents the name of the file containing executable code for which samples were collected.
This report (produced on a mostly-idle system) shows that nearly half of all samples were taken while the CPU was running code within the kernel itself. Next in line was the OProfile data collection daemon, followed by a variety of libraries and the X Window System server, XFree86. It is worth noting that for the system running this sample session, the counter value of 6000 used represents the minimum value recommended by opcontrol --list-events. This means that -- at least for this particular system -- OProfile overhead at its highest consumes roughly 11% of the CPU.