This page has been permanently moved. Please
CLICK HERE to be redirected.
Thanks, Craig.
What? Fixed? Problem? Huh?
While going through and checking and updating my Oracle Performance Firefighting course for Oracle Database 12c, I once again compared session level CPU consumption from v$session and v$sess_time_model. In the past v$sesstat server process CPU consumption could be significantly less than what is shown in v$sess_time_model. Also, many background processes showed zero CPU consumption in v$sesstat while v$sess_time_model clearly showed CPU consumption. The lesson was to always use v$sess_time_model for CPU consumption.Though I have not tested this in 12c yet, in pre-12c releases this difference is very apparent when comparing values from v$sysstat and v$sys_time_model. To check this out for yourself, look at one of your Statspack or AWR reports. You will notice the Instance Statistic CPU used by this session usually to be shockingly less then the Time Model statistic DB CPU.
Should I Care?
If your Oracle performance analysis is highly quantitative driven (which I hope it is) you need accurate CPU consumption values. ... you should care.This also has been an issue for those developing performance tuning products! OraPub's Stori product (which helps you find, understand and solve Oracle performance problems) is based highly on quantitative analysis and therefore understanding the raw statistics reliability is extremely important.
This posting will take a quick stroll though Oracle foreground and background process CPU consumption reporting, how 11g and 12c reporting compare, and how you can easily check out the situation on your system. Read on...
So Much To Write About 12c!
I have so much to write about. There are a number of very interesting changes in the Oracle Database 12c release. If you have downloaded my recent NOUG presentation containing some of my initial 12c research, you'll know what I mean. What I presented was raw and not thoroughly tested...but I told you that. It will take me months before I get to the bottom of all of changes and post the results here, convert that into conference presentations and merge into my Oracle performance classes!Note: When you attend my Oracle Performance classes you will get the most recent results of my research. Even material that I have not brought to conclusion I will talk about... but I'll tell you my "confidence level" and why.
Experiment Setup
My test is simple. So simple you can copy and paste the below script into your system, as long as it is Oracle Database 10g or higher. You can download the script HERE and it shown below.$ cat cpu_compare.sql
rem Session CPU consumption statistic compare
rem Craig Shallahamer, craig@orapub.com
set tab off
col sid format 99990
col ss_sec format 99990.00
col program format a22 trunc
col db_cpu_sec format 99990.00
col bg_cpu_sec format 99990.00
select ss.sid, se.program, ss.value/100 ss_sec,
stmfg.value/1000000 db_cpu, stmbg.value/1000000 bg_cpu
from v$session se,
v$sesstat ss,
v$statname sn,
v$sess_time_model stmbg,
v$sess_time_model stmfg
where se.sid = ss.sid
and se.sid = stmfg.sid
and se.sid = stmbg.sid
and stmfg.stat_name = 'DB CPU'
and stmbg.stat_name = 'background cpu time'
and ss.statistic# = sn.statistic#
and sn.name = 'CPU used by this session'
order by 3 desc, 5 desc, 1
/
Using my free "opload" toolkit (which you can download HERE), I placed a number of different loads on my Oracle Database 12c (12.1.0.1) system. It's a 64 bit six core Linux (2.6.32-300.3.1.el6uek.x86_64) box.
It is important to know when looking at the experimental results that I only recycled the instance before the first test. However, between each load change, I killed all the server/foreground processes. Why is this important? Because you may notice some of the background processes having a shockingly large percentage of CPU consumption... this is because they have been running much longer than the server processes.
After killing the server processes and restarting a new and different load, I let the system stabilize for a minute and then waited (patiently) at least three minutes (usually 5+) before running the above script.
The CPU Statistics
A little background on what the statistics mean. Each statistic shown represents the CPU consumption since the session has connected. What is unique about the time model view is there is a statistic for both foreground/server processes and also for background processes. Since the time model view was introduced in 10g, I have always seen the values placed in the correct bucket. The raw CPU time model values are in microseconds. If you look at my script above, you may have noticed I divided the raw statistic value by 1000000 to convert its value into seconds. In contract, the v$sesstat values are in hundredths of a second, that is centi-seconds and therefore I divided by 100.In the early 10g years, I did quite a bit of research on the trustworthiness of the time model CPU consumption values. The results showed time model CPU values matches the operating system. This is documented in my book, Oracle Performance Firefighting. (Which is still a powerful performance book for 12c by the way...)
In each of the loads below, I ran the above cpu_compare.sql script. In every situation, you can easily see there is a near perfect match...unless the CPU time is simply not reported!
Experimental Results
I ran a number of different loads; light buffer get, intense buffer get, free buffer wait load (physical reads, dml, small buffer cache), physical read (small buffer cache with some IO read related wait time), and an intense DML load to stress the redo mechanism. I figure if the CPU consumption results are consistent for all these workloads, the conclusions will be solid.The order I present the results below is the same order in which I changed the load and collected the data. It is good know because, after the first experiment, you can see the influence of the load on the background process CPU consumption change.
The "load" sessions are the "sqlplus@sixcore (TNS..." sessions, but one of them is the reporting script being run. For example, for the first load (see directly below) there are three sessions. The first two shown are the load sessions and further the other is the session that runs the cpu_compare.sql script.
Load: Light Buffer Get (LIO) Load
I created a buffer cache large enough to cache all the data, started two Oracle sessions, the CPU utilization was around 5% with a CPU run queue between 0 and 2 (6 core box), and there was virtually no IO reported at the OS level (vmstat "wait for IO" statistic was 0).SQL> @cpu_compare.sql
SID PROGRAM SS_SEC DB_CPU_SEC BG_CPU_SEC
------ ---------------------- --------- ---------- ----------
403 sqlplus@sixcore (TNS V 7089.64 7089.65 0.00
167 sqlplus@sixcore (TNS V 385.94 385.96 0.00
162 oracle@sixcore (MMNL) 30.52 0.00 30.96
320 oracle@sixcore (CJQ0) 13.20 0.00 13.20
82 oracle@sixcore (MMON) 4.67 0.00 4.67
319 oracle@sixcore (SMON) 1.55 0.00 1.55
7 sqlplus@sixcore (TNS V 1.32 1.33 0.00
86 oracle@sixcore (W000) 0.94 0.00 0.97
5 oracle@sixcore (W001) 0.90 0.00 0.93
324 oracle@sixcore (W002) 0.70 0.00 0.71
322 oracle@sixcore (W003) 0.61 0.00 0.64
239 oracle@sixcore (DBRM) 0.52 0.00 1.79
163 oracle@sixcore (FBDA) 0.51 0.00 0.51
80 oracle@sixcore (Q002) 0.46 0.00 0.46
399 oracle@sixcore (RECO) 0.32 0.00 0.32
318 oracle@sixcore (DIA0) 0.00 0.00 24.29
81 oracle@sixcore (CKPT) 0.00 0.00 10.03
398 oracle@sixcore (DBW0) 0.00 0.00 5.87
238 oracle@sixcore (PSP0) 0.00 0.00 5.80
159 oracle@sixcore (PMON) 0.00 0.00 5.44
397 oracle@sixcore (GEN0) 0.00 0.00 1.77
160 oracle@sixcore (DIAG) 0.00 0.00 1.43
2 oracle@sixcore (LGWR) 0.00 0.00 1.31
85 oracle@sixcore (SMCO) 0.00 0.00 1.17
3 oracle@sixcore (LREG) 0.00 0.00 1.12
4 oracle@sixcore (TT00) 0.00 0.00 0.95
1 oracle@sixcore (MMAN) 0.00 0.00 0.91
400 oracle@sixcore (QM02) 0.00 0.00 0.43
396 oracle@sixcore (TMON) 0.00 0.00 0.39
242 oracle@sixcore (AQPC) 0.00 0.00 0.32
161 oracle@sixcore (LG00) 0.00 0.00 0.00
166 oracle@sixcore (Q003) 0.00 0.00 0.00
240 oracle@sixcore (LG01) 0.00 0.00 0.00
244 oracle@sixcore (VKRM) 0.00 0.00 0.00
317 oracle@sixcore (VKTM) 0.00 0.00 0.00
35 rows selected.Load: Significant Buffer Get (LIO) Load, Minimal Contention
I created a buffer cache large enough to cache all the data, started four Oracle sessions, the CPU utilization was around 30% with a CPU run queue between 1 and 4 (6 core box), and there was virtually no IO reported at the OS level (vmstat "wait for IO" statistic was 0)..SQL> @cpu_compare
SID PROGRAM SS_SEC DB_CPU_SEC BG_CPU_SEC
------ ---------------------- --------- ---------- ----------
8 sqlplus@sixcore (TNS V 1111.14 1111.16 0.00
90 sqlplus@sixcore (TNS V 1110.99 1111.00 0.00
246 sqlplus@sixcore (TNS V 187.39 187.24 0.00
405 sqlplus@sixcore (TNS V 179.85 179.72 0.00
162 oracle@sixcore (MMNL) 31.38 0.00 31.86
320 oracle@sixcore (CJQ0) 13.68 0.00 13.69
82 oracle@sixcore (MMON) 4.79 0.00 4.79
319 oracle@sixcore (SMON) 1.59 0.00 1.59
86 oracle@sixcore (W000) 0.99 0.00 0.99
5 oracle@sixcore (W001) 0.94 0.00 0.95
324 oracle@sixcore (W002) 0.72 0.00 0.73
322 oracle@sixcore (W003) 0.66 0.00 0.66
239 oracle@sixcore (DBRM) 0.52 0.00 1.86
163 oracle@sixcore (FBDA) 0.52 0.00 0.52
80 oracle@sixcore (Q002) 0.46 0.00 0.47
399 oracle@sixcore (RECO) 0.32 0.00 0.32
403 sqlplus@sixcore (TNS V 0.03 0.02 0.00
318 oracle@sixcore (DIA0) 0.00 0.00 25.00
81 oracle@sixcore (CKPT) 0.00 0.00 10.33
238 oracle@sixcore (PSP0) 0.00 0.00 5.96
398 oracle@sixcore (DBW0) 0.00 0.00 5.93
159 oracle@sixcore (PMON) 0.00 0.00 5.57
397 oracle@sixcore (GEN0) 0.00 0.00 1.87
160 oracle@sixcore (DIAG) 0.00 0.00 1.48
2 oracle@sixcore (LGWR) 0.00 0.00 1.36
85 oracle@sixcore (SMCO) 0.00 0.00 1.22
3 oracle@sixcore (LREG) 0.00 0.00 1.15
4 oracle@sixcore (TT00) 0.00 0.00 0.98
1 oracle@sixcore (MMAN) 0.00 0.00 0.93
400 oracle@sixcore (QM02) 0.00 0.00 0.44
396 oracle@sixcore (TMON) 0.00 0.00 0.40
242 oracle@sixcore (AQPC) 0.00 0.00 0.33
161 oracle@sixcore (LG00) 0.00 0.00 0.00
166 oracle@sixcore (Q003) 0.00 0.00 0.00
240 oracle@sixcore (LG01) 0.00 0.00 0.00
244 oracle@sixcore (VKRM) 0.00 0.00 0.00
317 oracle@sixcore (VKTM) 0.00 0.00 0.00
37 rows selected.Load: Significant Buffer Get (LIO) Load, Significant Contention
I created a buffer cache large enough to cache all the data, started twelve Oracle sessions, the CPU utilization was between 85% to 96% with a CPU run queue between 4 and 8 (6 core box), and there was virtually no IO reported at the OS level (vmstat "wait for IO" statistic was 0).SQL> @cpu_compare
SID PROGRAM SS_SEC DB_CPU_SEC BG_CPU_SEC
------ ---------------------- --------- ---------- ----------
90 sqlplus@sixcore (TNS V 1643.65 1643.66 0.00
8 sqlplus@sixcore (TNS V 1642.70 1642.72 0.00
167 sqlplus@sixcore (TNS V 470.41 472.35 0.00
404 sqlplus@sixcore (TNS V 469.40 471.35 0.00
168 sqlplus@sixcore (TNS V 466.80 466.82 0.00
9 sqlplus@sixcore (TNS V 461.92 464.99 0.00
246 sqlplus@sixcore (TNS V 281.84 281.68 0.00
405 sqlplus@sixcore (TNS V 275.22 275.23 0.00
88 sqlplus@sixcore (TNS V 89.71 89.55 0.00
7 sqlplus@sixcore (TNS V 88.16 88.16 0.00
245 sqlplus@sixcore (TNS V 86.97 86.97 0.00
326 sqlplus@sixcore (TNS V 86.58 86.40 0.00
162 oracle@sixcore (MMNL) 31.83 0.00 32.33
320 oracle@sixcore (CJQ0) 13.82 0.00 13.82
82 oracle@sixcore (MMON) 4.85 0.00 4.85
319 oracle@sixcore (SMON) 1.60 0.00 1.60
86 oracle@sixcore (W000) 1.00 0.00 1.01
5 oracle@sixcore (W001) 0.95 0.00 0.96
324 oracle@sixcore (W002) 0.72 0.00 0.74
322 oracle@sixcore (W003) 0.66 0.00 0.67
163 oracle@sixcore (FBDA) 0.53 0.00 0.53
239 oracle@sixcore (DBRM) 0.52 0.00 1.87
80 oracle@sixcore (Q002) 0.46 0.00 0.47
403 sqlplus@sixcore (TNS V 0.36 0.35 0.00
399 oracle@sixcore (RECO) 0.33 0.00 0.33
318 oracle@sixcore (DIA0) 0.00 0.00 25.41
81 oracle@sixcore (CKPT) 0.00 0.00 10.48
238 oracle@sixcore (PSP0) 0.00 0.00 6.04
398 oracle@sixcore (DBW0) 0.00 0.00 5.96
159 oracle@sixcore (PMON) 0.00 0.00 5.64
397 oracle@sixcore (GEN0) 0.00 0.00 1.90
160 oracle@sixcore (DIAG) 0.00 0.00 1.51
2 oracle@sixcore (LGWR) 0.00 0.00 1.40
85 oracle@sixcore (SMCO) 0.00 0.00 1.25
3 oracle@sixcore (LREG) 0.00 0.00 1.16
4 oracle@sixcore (TT00) 0.00 0.00 0.99
1 oracle@sixcore (MMAN) 0.00 0.00 0.95
400 oracle@sixcore (QM02) 0.00 0.00 0.45
396 oracle@sixcore (TMON) 0.00 0.00 0.41
242 oracle@sixcore (AQPC) 0.00 0.00 0.33
161 oracle@sixcore (LG00) 0.00 0.00 0.00
166 oracle@sixcore (Q003) 0.00 0.00 0.00
240 oracle@sixcore (LG01) 0.00 0.00 0.00
244 oracle@sixcore (VKRM) 0.00 0.00 0.00
317 oracle@sixcore (VKTM) 0.00 0.00 0.00
45 rows selected.Load: Significant Physical Read IO (PIOR) Load, Significant IO Contention
I created a very small buffer cache to force lots of physical IO reads plus some DML activity, started six Oracle sessions, the CPU utilization was between 50% to 75% with a CPU run queue between 2 and 6 (6 core box), and the vmstat "wait for IO" statistic was between 4 and 15.SQL> @cpu_compare
SID PROGRAM SS_SEC DB_CPU_SEC BG_CPU_SEC
------ ---------------------- --------- ---------- ----------
88 sqlplus@sixcore (TNS V 781.91 781.91 0.00
91 sqlplus@sixcore (TNS V 775.41 775.43 0.00
167 sqlplus@sixcore (TNS V 774.11 773.95 0.00
404 sqlplus@sixcore (TNS V 774.07 774.63 0.00
10 sqlplus@sixcore (TNS V 772.18 772.18 0.00
162 oracle@sixcore (MMNL) 33.40 0.00 33.96
247 sqlplus@sixcore (TNS V 24.38 24.38 0.00
407 sqlplus@sixcore (TNS V 22.15 22.10 0.00
7 sqlplus@sixcore (TNS V 20.74 20.64 0.00
320 oracle@sixcore (CJQ0) 14.80 0.00 14.81
82 oracle@sixcore (MMON) 5.07 0.00 5.08
319 oracle@sixcore (SMON) 1.66 0.00 1.67
5 oracle@sixcore (W001) 1.31 0.00 1.32
86 oracle@sixcore (W000) 1.30 0.00 1.31
322 oracle@sixcore (W003) 0.94 0.00 0.94
324 oracle@sixcore (W002) 0.90 0.00 0.90
163 oracle@sixcore (FBDA) 0.55 0.00 0.56
239 oracle@sixcore (DBRM) 0.52 0.00 1.97
80 oracle@sixcore (Q002) 0.48 0.00 0.49
399 oracle@sixcore (RECO) 0.34 0.00 0.34
245 oracle@sixcore (W004) 0.04 0.00 0.04
169 sqlplus@sixcore (TNS V 0.01 0.02 0.00
81 oracle@sixcore (CKPT) 0.00 0.00 212.42
318 oracle@sixcore (DIA0) 0.00 0.00 26.89
398 oracle@sixcore (DBW0) 0.00 0.00 15.20
238 oracle@sixcore (PSP0) 0.00 0.00 6.31
159 oracle@sixcore (PMON) 0.00 0.00 5.88
2 oracle@sixcore (LGWR) 0.00 0.00 2.75
397 oracle@sixcore (GEN0) 0.00 0.00 2.05
160 oracle@sixcore (DIAG) 0.00 0.00 1.57
85 oracle@sixcore (SMCO) 0.00 0.00 1.35
3 oracle@sixcore (LREG) 0.00 0.00 1.22
4 oracle@sixcore (TT00) 0.00 0.00 1.03
1 oracle@sixcore (MMAN) 0.00 0.00 1.00
400 oracle@sixcore (QM02) 0.00 0.00 0.46
396 oracle@sixcore (TMON) 0.00 0.00 0.44
242 oracle@sixcore (AQPC) 0.00 0.00 0.35
161 oracle@sixcore (LG00) 0.00 0.00 0.00
166 oracle@sixcore (Q003) 0.00 0.00 0.00
240 oracle@sixcore (LG01) 0.00 0.00 0.00
244 oracle@sixcore (VKRM) 0.00 0.00 0.00
317 oracle@sixcore (VKTM) 0.00 0.00 0.00
42 rows selected.Load: Significant DML Load Resulting In Significant Redo Related Contention
I created a very small buffer cache to encourage physical IO reads plus significant DML activity, started three Oracle sessions, the CPU utilization was around 5% with a CPU run queue between 1 and 2 (6 core box), and the vmstat "wait for IO" statistic was between 15 and 20.SQL> @cpu_compare
SID PROGRAM SS_SEC DB_CPU_SEC BG_CPU_SEC
------ ---------------------- --------- ---------- ----------
7 sqlplus@sixcore (TNS V 136.11 136.13 0.00
162 oracle@sixcore (MMNL) 34.02 0.00 34.44
320 oracle@sixcore (CJQ0) 15.20 0.00 15.20
404 sqlplus@sixcore (TNS V 7.91 7.90 0.00
82 oracle@sixcore (MMON) 5.15 0.00 5.15
88 sqlplus@sixcore (TNS V 5.07 5.07 0.00
319 oracle@sixcore (SMON) 1.69 0.00 1.71
86 oracle@sixcore (W000) 1.32 0.00 1.33
5 oracle@sixcore (W001) 1.32 0.00 1.32
322 oracle@sixcore (W003) 0.95 0.00 0.96
324 oracle@sixcore (W002) 0.91 0.00 0.92
163 oracle@sixcore (FBDA) 0.57 0.00 0.56
239 oracle@sixcore (DBRM) 0.52 0.00 2.00
80 oracle@sixcore (Q002) 0.50 0.00 0.50
399 oracle@sixcore (RECO) 0.35 0.00 0.36
245 oracle@sixcore (W004) 0.05 0.00 0.05
81 oracle@sixcore (CKPT) 0.00 0.00 214.92
318 oracle@sixcore (DIA0) 0.00 0.00 27.26
398 oracle@sixcore (DBW0) 0.00 0.00 21.77
159 oracle@sixcore (PMON) 0.00 0.00 6.46
238 oracle@sixcore (PSP0) 0.00 0.00 6.40
2 oracle@sixcore (LGWR) 0.00 0.00 4.27
397 oracle@sixcore (GEN0) 0.00 0.00 2.05
160 oracle@sixcore (DIAG) 0.00 0.00 1.59
85 oracle@sixcore (SMCO) 0.00 0.00 1.37
3 oracle@sixcore (LREG) 0.00 0.00 1.23
4 oracle@sixcore (TT00) 0.00 0.00 1.05
1 oracle@sixcore (MMAN) 0.00 0.00 1.02
400 oracle@sixcore (QM02) 0.00 0.00 0.47
396 oracle@sixcore (TMON) 0.00 0.00 0.44
242 oracle@sixcore (AQPC) 0.00 0.00 0.35
161 oracle@sixcore (LG00) 0.00 0.00 0.00
166 oracle@sixcore (Q003) 0.00 0.00 0.00
167 sqlplus@sixcore (TNS V 0.00 0.02 0.00
240 oracle@sixcore (LG01) 0.00 0.00 0.00
244 oracle@sixcore (VKRM) 0.00 0.00 0.00
317 oracle@sixcore (VKTM) 0.00 0.00 0.00
37 rows selected.
What Does This Mean?
There are a number of "take aways" from this experiment.- Foreground/Server process CPU consumption values match for both v$sesstat and v$sess_time_model. This is not always the case in Oracle Database 10g and 11g.
- Foreground/Server and background process CPU consumption continue to be placed in their proper statistical bucket. Foreground/Server process CPU time into DB CPU and the background processes into background cpu time. This was the same in both Oracle Database 10g and 11g.
- Some background process's CPU consumption continues to NOT be reported in the instance statistic view v$sesstat. From my perspective this continues to be a bug. But we can deal with this from two perspectives. First, we have the time model view which looks to report correctly for all background processes. Second, background process CPU consumption is usually very small compared to foreground/server process CPU and if it is significant you can easily see this on an operating system monitor, like top.
Craig.
If you enjoy my blog, I suspect you'll get a lot out of my courses; Oracle Performance Firefighting, Advanced Oracle Performance Analysis, and my One-Day Oracle Performance Research Seminar. I teach these classes around the world multiple times each year. For the latest schedule, go to www.orapub.com . I also offer on-site training and consulting services.
P.S. If you want me to respond to a comment or you have a question, please feel free to email me directly at craig@orapub .com. Another option is to send an email to OraPub's general email address, which is currently info@ orapub. com.
Just noticed on one of my 12c systems the child log writer background process LG01 shows over 2 minutes of CPU at the OS (ps command) but zero in v$sess_time_model!! Hopefully Oracle fixes that.
ReplyDeleteCraig.
Craig.
Những điều cần biết về chăm sóc trẻ dưới 1 tuổi http://treduoi1tuoiconen.blogspot.com/
ReplyDeleteMột số công dụng của lá http://congdungcuala.blogspot.com/
Đau đầu có nên http://daudauconen.blogspot.com/
Chăm sóc trẻ 6 tháng tuổi http://tre6thangtuoiconen.blogspot.com/
Chuyển hàng đi như thế nào http://chuyenthenao.blogspot.com/
Một số tác dụng của trái http://tacdungcuatrai.blogspot.com/
Công dụng của quả cây nhà vườn http://congdungcuaqua.blogspot.com/
Bao lâu thì hàng về Việt Nam http://baolauthi.blogspot.com/
Có nên gửi tiết kiệm không http://conengui.blogspot.com/
Thanks for sharing these information. It’s a very nice topic. We are providing online training classes
ReplyDeleteBest bca college in noida
Top bca colleges in noida
ust noticed on one of my 12c systems the child log writer background process LG01 shows over 2 minutes of CPU at the OS (ps command) but zero in v$sess_time_model!! Hopefully Oracle fixes that.
ReplyDeleteblood concentration
Thank you for excellent article.You made an article that is interesting.
ReplyDeleteAWS Solutions Architect courses in Bangalore with certifications.
https://onlineidealab.com/aws-training-in-bangalore/