The linux ‘perf’ utility with EL 6

Some of you might have experimented with, or used Oprofile, ltrace/strace, Systemtap, and wished you could look further into the userland process, like dtrace does, because dtrace allows you to profile and look into a process’ function calls.

If you’ve used oprofile/strace/systemtap/etc., you probably found out you can see all the kernel functions which are processed, but it does not get into userspace, or with very limited information. Perhaps the only tool which is different is gdb, which enables you to see userspace function names, but gdb is not a profiler, it’s a debugger. And it works best with (I assume it made for) debugging symbols in the executable. Most (all I presume) commercial executables, like the oracle database executable, do not have debugging symbols.

Some time ago, a tweet from Kevin Closson caught my attention, which showed a profile of a Linux system running Oracle, which showed the functions inside Oracle. This totally shocked me! That is something I want to be able to do on Linux too!!

It was done using the perf utility. The perf utility is delivered with the kernel (rpm) package on EL Linuxes, and the since I am using Oracle Linux, I can tell you it’s delivered with the ‘UEK’ kernels (the 2.6.32+ ones). I’ve eventually used the latest version of the UEK kernel (2.6.39-200.24.1.el6uek.x86_64), which you get when you subscribe to the ol6_UEK_latest yum channel. Newer versions of the kernel have more perf functions.

The ‘perf top’ sub-utility shows the kernel and userland functions which are active (by sampling active processes). It can be used in a variety of ways, some of them are: system-wide, per processor or per process. This allows you to do look beyond the Oracle wait interface. As Tanel Poder often states in his performance classes: the Oracle wait interface is a good starting point for performance investigation, but sometimes you need to look deeper. You always need to use the appropriate layer to look at when investigating issues.

Note when using virtualization: virtualization does not allow direct access to the performance monitoring hardware. So if you try to use perf on that (or oprofile for that matter), you get no output. You can get around that with perf by using a software event. I use the software event cpu-clock. This means I invoke perf with the option ‘-e cpu-clock’

For example: this statement uses a lot of CPU, and might (depending on Oracle version, operating system type and version) never return an answer. But it is perfect to have a statement that consumes approximately 1 CPU, and keeps doing that for some time:

select count(*) from dba_extents, dba_extents, dba_extents

A quick glimpse on the statistics profile using sql_monitor reveals:

Global Stats
=========================================
| Elapsed |   Cpu   |  Other   | Buffer |
| Time(s) | Time(s) | Waits(s) |  Gets	|
=========================================
|     109 |	103 |	  6.23 |   9755 |
=========================================

Of course I could look in the sql monitoring plan details, which would reveal what row sources are active at the moment, but let’s see what ‘perf top -e cpu-clock -p shows:

   PerfTop:     108 irqs/sec  kernel: 0.9%  exact:  0.0% [1000Hz cpu-clock],  (target_pid: 12727)
--------------------------------------------------------------------------------------------------------------------

             samples  pcnt function                  DSO
             _______ _____ _________________________ ____________________________________________________

             1414.00 58.8% kxhrHash                  /u01/app/oracle/product/11.2.0.3/dbhome_1/bin/oracle
              389.00 16.2% qerhjSplitProbe           /u01/app/oracle/product/11.2.0.3/dbhome_1/bin/oracle
              263.00 10.9% rworofprVeryFastUnpackRow /u01/app/oracle/product/11.2.0.3/dbhome_1/bin/oracle
              122.00  5.1% smbget                    /u01/app/oracle/product/11.2.0.3/dbhome_1/bin/oracle
               93.00  3.9% sorgetqbf                 /u01/app/oracle/product/11.2.0.3/dbhome_1/bin/oracle
               86.00  3.6% qersoFetch                /u01/app/oracle/product/11.2.0.3/dbhome_1/bin/oracle
               31.00  1.3% qerhjInnerProbeHashTable  /u01/app/oracle/product/11.2.0.3/dbhome_1/bin/oracle

This shows 58.8% of the samples takes of this process are busy in the function ‘kxhrHash’. So it’s the hashing which this process is busy with. Another important and interesting aspect is: there is very little time spend in kernel mode: (kernel: 0.9%). But…the information about where the time is spend could have been read in the sql monitoring report: it reports CPU and waits per row source.

Where perf comes in to fulfill something which could not be done different, is when you got multiple processes, and you cannot setup perf for every distinct process, or you want to understand system-wide performance. To mimic a system doing OLTP, I’ve setup Kevin Closson’s SLOB in PIO mode, and use perf top -e cpu-clock without specifying a process ID, so I measure the entire system. I get the following profile:

  PerfTop:     984 irqs/sec  kernel:92.4%  exact:  0.0% [1000Hz cpu-clock],  (all, 1 CPU)
--------------------------------------------------------------------------------------------------------------------------------------------------------------

             samples  pcnt function                           DSO
             _______ _____ __________________________________ ______________________________________________________________________

            13102.00 88.3% _raw_spin_unlock_irqrestore        [kernel.kallsyms]                                                     
              772.00  5.2% copy_page                          [kernel.kallsyms]                                                     
              298.00  2.0% __do_softirq                       [kernel.kallsyms]                                                     
              114.00  0.8% scsi_request_fn                    [kernel.kallsyms]                                                     
               29.00  0.2% kcbgtcr                            /u01/app/oracle/product/11.2.0.3/dbhome_1/bin/oracle                  
               25.00  0.2% kmem_cache_alloc                   [kernel.kallsyms]                                                     
               25.00  0.2% finish_task_switch                 [kernel.kallsyms]                                                     
               22.00  0.1% kcbzib                             /u01/app/oracle/product/11.2.0.3/dbhome_1/bin/oracle                  
               17.00  0.1% sxorchk                            /u01/app/oracle/product/11.2.0.3/dbhome_1/bin/oracle

Conclusion: the majority of the processes spend time in kernel calls (kernel.kallsyms). This is not too surprising: I've setup SLOB in 'PIO mode', which means I've reduced the Oracle database buffer cache as much as possible. With Oracle version 11.2.0.3, the smallest buffer cache I can create is 4MB. Next I've let 10 readers do index range scans (that is one of the functions of SLOB: swamping your system with single block (8KB) IO's). The majority of the processes are spending time in the kernel function _raw_spin_unlock_irqrestore. This is how a system which is swamped with physical IO looks like with perf.

This all changes when I revert SLOB to LIO mode, and issue the same test (SLOB run with 10 readers):

   PerfTop:    1004 irqs/sec  kernel: 3.1%  exact:  0.0% [1000Hz cpu-clock],  (all, 1 CPU)
---------------------------------------------------------------------------------------------------------------------------------------------------------------

             samples  pcnt function                    DSO
             _______ _____ ___________________________ ____________________________________________________

              478.00 23.9% kcbgtcr                     /u01/app/oracle/product/11.2.0.3/dbhome_1/bin/oracle
              154.00  7.7% qetlbr                      /u01/app/oracle/product/11.2.0.3/dbhome_1/bin/oracle
              149.00  7.4% kcbz_fp_buf                 /u01/app/oracle/product/11.2.0.3/dbhome_1/bin/oracle
              133.00  6.6% kdsgrp                      /u01/app/oracle/product/11.2.0.3/dbhome_1/bin/oracle
              104.00  5.2% kafger                      /u01/app/oracle/product/11.2.0.3/dbhome_1/bin/oracle
               94.00  4.7% kcbrls                      /u01/app/oracle/product/11.2.0.3/dbhome_1/bin/oracle
               60.00  3.0% ktrgcm                      /u01/app/oracle/product/11.2.0.3/dbhome_1/bin/oracle
               60.00  3.0% ktrget3                     /u01/app/oracle/product/11.2.0.3/dbhome_1/bin/oracle

Ah, we now spend only 3.1% in kernel mode, and the majority of the time is spend in kcbgtcr (quite probably meaning 'kernel cache buffer get consistent read')! I've modified the buffer cache to be able to contain all blocks (also known as SLOB 'LIO mode'), so once they are read, only a logical IO is needed to fetch the block.

About these ads
7 comments
  1. Frank Ch. Eigler said:

    Correction: systemtap has had kernel+userspace profiling (sampled-pc to symbol resolution) for years, and userspace probing (dtrace fbt style, and then some) for almost as many years.

    • Hi Frits
      I have been experimenting with systemtap and I was able to display functions name but for OS tools (like ls). I don’t remember exactly if I needed debug version of ls package but probably I did. Anyway perf is very cool and easier to use – I just did simple check but want to spend more time on it for sure.

      regards,
      Marcin

  2. Thanks for reading Frank!
    Could you elaborate on using systemtap in userspace? I know the function names are in the symbol table, which is present, but never succeeded in getting userspace function names myself.
    Please mind using Oracle means the distribution is pretty much bound to oracle Linux, redhat Linux or suse Linux.

    • Frank Ch. Eigler said:

      Hi, Frits. The stap tapset library includes functions to resolve addresses to userspace symbols, e.g., usymdata(). This can be used to generate “perf top” style output (on rhel5 etc. too). You may need to add “-d /bin/foo -d /lib/libbar.so” type options to stap for this undirected sort of profiling (since stap needs to know which processes to gather symbol data for, by startup time).

      http://sourceware.org/systemtap/examples/#profiling/pf3.stp

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

Follow

Get every new post delivered to your Inbox.

Join 2,058 other followers

%d bloggers like this: