This page has been permanently moved. Please
CLICK HERE to be redirected.
Thanks, Craig.
Detailing an Oracle Database process's CPU consumption is amazing, a lot
of fun, and can lead to some “ah ha” moments. To make this posting
daily digestible, I’m breaking it up into a multi-part series. Today I’m
posting the second part entitle, Tools Options. Here we go…Tool Options
As I mentioned in my previous post entitled, The Situation, there is bad news and there is good news. The bad news, to my knowledge, Oracle does not collect process CPU consumption at the Oracle kernel level. For sure, Oracle collects Oracle process CPU consumption, but it is the total CPU consumption, with the key word being total. What I want is process CPU consumption at the Oracle kernel function level.
When I started my quest I knew there had to be some good news! With all the OS tools out there, there must be one that will meet my requirements. There were four tools that caught my attention: strace/truss, dtrace, gdb, and perf. Here is what I learned in my quest.
System Call Tracing Using STRACE/TRUSS
I started with strace because I am very familiar with it. For many years I have traced Oracle processes at the operating system level using strace. (If you are on Solaris, the command is truss.) It's a fantastic way to learn how Oracle really works. And it's a great teaching tool (which I'm always looking for).
Here is an example of what you can do with strace. Suppose I wanted to know how long it takes an Oracle server process to read a single block from disk. Through Oracle wait interface we would see this as a db file sequential read. To do an Operating system trace on the Oracle server process 2518, I could issue this command:
$ strace –rp 2518
...
0.000324 clock_gettime(CLOCK_MONOTONIC, {504, 52586559}) = 0
0.000040 clock_gettime(CLOCK_MONOTONIC, {504, 52625324}) = 0
0.000040 pread(257, "\6\242\0\f\0"..., 8192, 427270144) = 8192
0.000047 clock_gettime(CLOCK_MONOTONIC, {504, 52712996}) = 0
0.000044 clock_gettime(CLOCK_MONOTONIC, {504, 52757393}) = 0
0.000329 clock_gettime(CLOCK_MONOTONIC, {504, 53086771}) = 0
0.000040 clock_gettime(CLOCK_MONOTONIC, {504, 53125505}) = 0
0.000040 pread(257, "\6\76 [y\f\0"..., 8192, 427278336) = 8192
0.000047 clock_gettime(CLOCK_MONOTONIC, {504, 53213583}) = 0
0.000040 clock_gettime(CLOCK_MONOTONIC, {504, 53253021}) = 0
0.000327 clock_gettime(CLOCK_MONOTONIC, {504, 53580561}) = 0
0.000040 clock_gettime(CLOCK_MONOTONIC, {504, 53619199}) = 0
0.000040 pread(257, "\6\273\f\0"..., 8192, 427286528) = 8192
0.000047 clock_gettime(CLOCK_MONOTONIC, {504, 53706779}) = 0
0.000040 clock_gettime(CLOCK_MONOTONIC, {504, 53752611}) = 0
What did I learn from the above? I observed that Oracle is instrumenting a single block read using the clock_gettime call, the server processes is requesting a single 8K block using the pread call, and the first pread shown above took about 0.047 ms (not 0.040 ms).
While that's great, notice there is no reference to CPU consumption and there is no mention of Oracle kernel functions either. In fact, only the "system calls" are shown. Also, based on what the contents of the Linux /proc/sys/kernel/vsyscall64 file is set to, I may not see all the system calls!
So clearly, strace is not going to work.
Detailed Tracing Using DTRACE
If you are a developer on Solaris, you probably have used dtrace. DTrace is a framework for troubleshooting processes as they are running...and in production! DTrace can be used to capture CPU consumption, IO read times, IO write times, network activity, and many other things. It is amazing!
DTrace programs resemble awk programs in structure; they consist of a list of one or more probes (instrumentation points), and each probe is associated with an action. These probes are comparable to a pointcut in aspect-oriented programming. Whenever the condition for the probe is met, the associated action is executed (the probe "fires"). A typical probe might fire when a certain file is opened, or a process is started, or a certain line of code is executed. The probe may result in some information being displayed.
The good news is, DTrace is very powerful. I think any DBA could see the value in learning how Oracle works by using DTrace. Have you ever wondered how Tanel Poder finds out so much about the Oracle kernel? Tanel is a super big fan of DTrace and you quickly see this when reading his work.
There is a down side though. There is a considerable learning curve. True this rarely stops the performance researcher... but it sure can slows them down. While DTrace is standard for Solaris, it's a little trickier on Linux. The DTrace package and the Unbreakable Enterprise Kernel (UEK) package are available on the Unbreakable Linux Network (ULN), but not on the public yum server. You must register your system with ULN before you can download the required packages. The Oracle Linux Administrator's Solutions Guide for Release 6 lists the packages you need to download from ULN and shows how to install them. ...bummer.
Hmm... So dtrace is not installed and not working by default. That's a problem for me and especially in this quest. Whenever I do my research, I want others to be able to duplicate it. I also usually don't want someone to have to install, configure, and learn about another tool in the process. This combined with the learning curve, put the kibosh on DTrace for this endeavor.
Using the GNU Debugger: GDB
The purpose of a debugger such as GDB is to allow you to see what is going on ‘‘inside’’ another program while it executes—or what another program was doing at the moment it crashed.
I have spoken to Frits Hoogland about gdb before and was really impressed with what one can do with it. Frits uses gdb quite a bit, so his blog postings have many great examples. Here is just one good example. At this years IOUG/Collaborate conference in Las Vegas, Frits is going to present a 30 minute Quick Tip on using how DBAs can use gdb. I hope the room is full!
The word "debugger" is a clue that gdb is not going to meet my objective. GDB is great for stepping through Oracle's kernel code (and even interrupting or stopping it!), but it wasn't clear how I could capture an Oracle process's CPU consumption by Oracle kernel function.
As with strace and dtrace, gdb isn't what I'm looking for.
Using the Linux Profiler: Perf
First of all, Perf is a free Linux process profiling tool. When I checked on my pretty-much default OEL 6.2 and Oracle Database 12c box, the perf tools where already there!
On your Linux box, just do:
$ which perf
/usr/sbin/perf
Oh yeah... one other thing. Perf keeps track of the "count" at the function level. This means I can determine how much CPU time (more correctly the counts) each Oracle kernel function "consumes." Therefore, it appears Perf will do exactly what I need; keep track of an Oracle's process's CPU consumption down to the Oracle kernel function. Perf-ect! (sorry about that)
To help make this crystal clear, now I can get something like this:
Count Kernel Function
-------- ---------------
1500 abc124
900 td8tr
200 kcbte
12 kbce8
------
2612 counts over a 5 second interval
perf stat is used to obtain, that is collect, the event counts.
perf record is used to record the event counts for later reporting.
perf report is used to break down and report on the events process, function, etc.
perf top is like the standard "top" command but provides function level detail for a specific process.
Here is a quick example of "perf stat" collecting the default events for process 28497 for five seconds. Notice the "sleep 5"? The execution duration of the command "sleep 5" is the collection period duration. I could have used another command like, "ls -1" but "sleep 5" is an obvious way to sleep for five seconds.
$ ps -eaf | grep oracleprod35
oracle 28497 28496 8 09:58 ? 00:31:36 oracleprod35 (DESCRIPTION=(LOCAL=YES)...
oracle 42265 28425 0 15:51 pts/1 00:00:00 grep oracleprod35
$ perf stat -p 28497 sleep 5
Performance counter stats for process id '28497':
560.686866 task-clock # 0.112 CPUs utilized
32 context-switches # 0.000 M/sec
1 CPU-migrations # 0.000 M/sec
0 page-faults # 0.000 M/sec
1,522,513,670 cycles # 2.715 GHz [83.11%]
952,309,947 stalled-cycles-frontend # 62.55% frontend cycles idle [83.65%]
568,827,423 stalled-cycles-backend # 37.36% backend cycles idle [66.93%]
1,333,413,297 instructions # 0.88 insns per cycle
# 0.71 stalled cycles per insn[83.54%]
249,397,610 branches # 444.807 M/sec [82.99%]
4,478,117 branch-misses # 1.80% of all branches [83.40%]
5.000696361 seconds time elapsed
$ perf top -p 28497 -d 30
PerfTop: 89 irqs/sec kernel: 5.6% exact: 0.0% [1000Hz cycles],(target_pid: 28497)
---------------------------------------------------------------------------
samples pcnt function DSO
_______ _____ __________________________ __________________________
205.00 7.6% kcbchg1_main product/12.1.0/bin/oracle
148.00 5.5% kcbget product/12.1.0/bin/oracle
124.00 4.6% kcrfw_redo_gen_ext product/12.1.0/bin/oracle
114.00 4.2% kdkcmp1 product/12.1.0/bin/oracle
100.00 3.7% __intel_ssse3_rep_memcpy product/12.1.0/bin/oracle
99.00 3.7% kcrfw_copy_cv product/12.1.0/bin/oracle
89.00 3.3% kcoapl product/12.1.0/bin/oracle
84.00 3.1% kcbgcur product/12.1.0/bin/oracle
77.00 2.9% kdiins1 product/12.1.0/bin/oracle
62.00 2.3% kduovw product/12.1.0/bin/oracle
56.00 2.1% ktuchg2 product/12.1.0/bin/oracle
52.00 1.9% ktugur product/12.1.0/bin/oracle
51.00 1.9% kdimod0 product/12.1.0/bin/oracle
50.00 1.9% updrow product/12.1.0/bin/oracle
46.00 1.7% kauupd product/12.1.0/bin/oracle
42.00 1.6% qertbFetch product/12.1.0/bin/oracle
38.00 1.4% kdudcp product/12.1.0/bin/oracle
$ perf record -e cycles -p 28497 sleep 30
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.093 MB perf.data (~4057 samples) ]
$ perf report
# Events: 2K cycles
#
# Overhead Command Shared Object Symbol
# ........ ............... ................. ...........................
#
7.91% oracle_28497_pr oracle [.] kcbchg1_main
4.87% oracle_28497_pr oracle [.] kcbget
4.07% oracle_28497_pr oracle [.] kcrfw_redo_gen_ext
3.86% oracle_28497_pr oracle [.] kdkcmp1
3.42% oracle_28497_pr oracle [.] __intel_ssse3_rep_memcpy
3.37% oracle_28497_pr oracle [.] kcoapl
3.23% oracle_28497_pr oracle [.] kcrfw_copy_cv
3.08% oracle_28497_pr oracle [.] kcbgcur
2.56% oracle_28497_pr oracle [.] kdiins1
2.22% oracle_28497_pr oracle [.] ktuchg2
2.03% oracle_28497_pr oracle [.] ktbgwl
2.00% oracle_28497_pr oracle [.] kauupd
1.88% oracle_28497_pr oracle [.] kduovw
1.78% oracle_28497_pr oracle [.] kdimod0
1.56% oracle_28497_pr oracle [.] kdudcp
Can We Go From Count To Time?
This is actually a very serious issue. Most DBAs will and should pause and consider the situation when jumping from sample counts to time.
Here is an example situation. Suppose over a 30 second interval the Oracle view v$sess_time_model (stat: db cpu) shows a server process consumed 10 seconds of CPU. Also, according to Perf, the Oracle kernel function kcb1 accounts for 60% of the CPU counts and kcb2 accounts for the remaining 40%.
Now the question is, can we attribute 60% of the 10 seconds of CPU time to the Oracle kernel function kcb1 and 40% of the 10 seconds of CPU to kcb2? If so, then kcb1 would be assigned 6 seconds and kcb2 4 seconds.
Using the count-to-seconds math above combined with Perf's default sample rate of 1000/sec, (i.e., 1/ms), then each CPU count is equivalent to 1 ms of CPU consumption. I suspect it is likely either less than 1ms or greater than 1ms. Assuming either direction is just as likely to occur (and I can't prove this to you), then I suspect assessing one count to 1ms of CPU is OK.
Based on the above, I am comfortable jumping from Perf counts to time.
So Where Are We In This Quest?
At this point, in terms of CPU consumption I'd say we are here:
Time Component secs %
------------------------------------------------------- ---------- -------
cpu : [.] kcbgtcr 29.714 66.87
cpu : [.] kdstf000010100001km 3.716 8.36
cpu : [.] lnxsum 3.541 7.97
cpu : [?] sum of funcs consuming less than 2% of CPU ti 2.393 5.38
cpu : [.] kaf4reasrp0km 2.180 4.91
Time Component secs %
------------------------------------------------------- ---------- -------
cpu : [.] kcbgtcr 29.714 66.87
cpu : [.] kdstf000010100001km 3.716 8.36
cpu : [.] lnxsum 3.541 7.97
cpu : [?] sum of funcs consuming less than 2% of CPU ti 2.393 5.38
cpu : [.] kaf4reasrp0km 2.180 4.91
wait: latch: cache buffers chains 2.100 4.73
But until then, log into your non-production yet active Linux box and some a few "perf top" and a few "perf record" and then "perf report" commands. If it's not production, profile the Oracle log writer or database writer background process or perhaps an active server process!
Feeling dangerous yet?
If you can’t wait until the next posting (or you have lots of time), here are some resources.
1. Presentation: Detailing Oracle CPU Consumption. Download here.
2. Tool: Oracle wait time and kernel function CPU monitor. Download the fulltime.sh script.
Thanks for reading,
Craig.
