The linux ‘perf’ utility with EL 6 – part 2

In my previous post about perf I showed how it can be used to determine the function which is used the most systemwide.

One thing it helped me with, is determining the impact of swapping on a system. The testcase I build for that is kind of a no-brainer (setting up a 3GB SGA with 2GB of physical memory in a test VM), but think about a few things: I regularly encounter systems who have an amount of swap allocated. This can mean memory is simply plain over allocated, but can also be older pages are just swapped out by Linux “just in case”. This probably will happen more with the new oracle recommendation for “swappiness” (the eagerness of Linux to swap) to set it to 100 (used to be 60). The amount of swap transfers can be measured, but the regular tools cannot measure the impact. With perf, this is possible.

I ran another SLOB run (10 readers) against the 3GB SGA/2GB physical memory system, and collected perf data with ‘perf record -e cpu-clock -g -a’. After the run, I printed a summary of the collected data using ‘perf report -g none':

# Events: 33K cpu-clock
#
# Overhead          Command                       Shared Object                                                                                                                     
# ........  ...............  ..................................  
#
    24.65%          swapper  [kernel.kallsyms]                   [k] native_safe_halt
    17.99%           oracle  [kernel.kallsyms]                   [k] _raw_spin_unlock_irqrestore
    10.82%           oracle  oracle                              [.] kcbgtcr
     2.94%           oracle  oracle                              [.] qetlbr
     2.66%           oracle  oracle                              [.] kcbz_fp_buf
     2.22%           oracle  oracle                              [.] kdsgrp
     1.98%           oracle  oracle                              [.] kafger

I guess this speaks for itself. The highest number of measurements of a function (24.65%) was a kernel-mode function ([k]) ‘native_safe_halt’, which was issued by ‘swapper’. The next most active function (17.99%) was a kernel-mode function ([k]) ‘_raw_spin_unlock_irqrestore’ which was issued by oracle. This function represent waiting for I/O (read on if you want to be able to determine that). Next functions are user land functions ([.]). These are issued by oracle, with the executable oracle. Because we are using SLOB, which is made to issue 8KB block reads, it makes sense the user land function with the most impact is the ‘kcbgtcr’ function (kernel cache buffer get consistent read).

Above example shows the summary of the perf recording. The “normal” report shows the complete stack from the active function down to main. Here is an example with the data from which the summary above has been made:

# Events: 33K cpu-clock
#
# Overhead          Command                       Shared Object                                                                                                                     
# ........  ...............  ..................................  ...................................................................................................................
#
    24.65%          swapper  [kernel.kallsyms]                   [k] native_safe_halt
                    |
                    --- native_safe_halt
                        cpu_idle
                        rest_init
                        start_kernel
                        x86_64_start_reservations
                        x86_64_start_kernel

    17.99%           oracle  [kernel.kallsyms]                   [k] _raw_spin_unlock_irqrestore
                    |
                    --- _raw_spin_unlock_irqrestore
                       |          
                       |--97.51%-- scsi_dispatch_cmd
                       |          scsi_request_fn
                       |          __blk_run_queue
                       |          |          
                       |          |--99.69%-- queue_unplugged
                       |          |          blk_flush_plug_list
                       |          |          |          
                       |          |          |--94.22%-- blk_finish_plug
                       |          |          |          |          
                       |          |          |          |--99.85%-- generic_file_read_iter
                       |          |          |          |          generic_file_aio_read
                       |          |          |          |          aio_rw_vect_retry
                       |          |          |          |          aio_run_iocb
                       |          |          |          |          io_submit_one
                       |          |          |          |          do_io_submit
                       |          |          |          |          sys_io_submit
                       |          |          |          |          system_call_fastpath
                       |          |          |          |          io_submit
                       |          |          |          |          |          
                       |          |          |          |           --100.00%-- skgfqio
                       |          |          |          |                     ksfd_skgfqio

Here you see the stack of the swapper, and the different stacks, as a tree, which lead to _raw_spin_unlock_irqrestore, with percentages of functions from the differences which lead the same executable/function combination.

Using the percentages, the function calls can be investigated which happen on the system. Above sample shows the last two oracle database functions prior to the io_submit call (io_submit is the function to issue an asynchronous IO call), ksfd_skgfqio and skgfqio. Next we see the io_submit call, and everything which is called by the kernel.

The report contains all the stacks, not a partial one like my example.

About these ads
3 comments

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,060 other followers

%d bloggers like this: