'
Hi all,
I have just run Statspack for 2 hours while a [url http://hammerora.sourceforge.net/]HammerOra session was running.
I'm pretty sure I understand what's going on, but I would be grateful if any experts
could just glance at my interpretation and correct any errors I may have.
I'm using an Oracle 10 XE instance with 1GB of RAM, 2GB of swap running Linux Ubuntu 10.10
with 1 HDD of 120 GB.
I believe that there is contention for the Hard Disk which is causing problems - I have
inserted questions between the code blocks below where I am puzzled.
Redo excessive here?
STATSPACK report for
Database DB Id Instance Inst Num Startup Time Release RAC
~~~~~~~~ ----------- ------------ -------- --------------- ----------- ---
2639426735 XE 1 18-Aug-11 11:01 10.2.0.1.0 NO
Host Name: pol-laptop Num CPUs: 2 Phys Memory (MB): 0
~~~~
Snapshot Snap Id Snap Time Sessions Curs/Sess Comment
~~~~~~~~ ---------- ------------------ -------- --------- -------------------
Begin Snap: 21 18-Aug-11 12:23:49 20 9.7 A first test of ham
End Snap: 22 18-Aug-11 14:23:13 22 10.0 A first test of ham
Elapsed: 119.40 (mins)
Cache Sizes Begin End
~~~~~~~~~~~ ---------- ----------
Buffer Cache: 176M Std Block Size: 8K
Shared Pool Size: 80M Log Buffer: 2,820K
Load Profile Per Second Per Transaction
~~~~~~~~~~~~ --------------- ---------------
Redo size: 221,424.24 5,137.09 <=Something wrong here?
Logical reads: 4,089.12 94.87
Block changes: 1,379.16 32.00
Physical reads: 29.34 0.68
Physical writes: 71.13 1.65
User calls: 33.65 0.78
Parses: 0.88 0.02
Hard parses: 0.05 0.00
Sorts: 2.09 0.05
Logons: 0.00 0.00
Executes: 894.54 20.75
Transactions: 43.10
% Blocks changed per Read: 33.73 Recursive Call %: 97.06
Rollback per transaction %: 0.17 Rows per Sort: 22.85
I read [url http://dbaspot.com/oracle-server/14914-need-help-statspack-report-parse-cpu-parse-elapsd.html]here that a low value of CPU to Parse Elapsd means that
========================================================
during parsing, the server process is waiting for something, most likely
contending for a latch (shared pool and library cache latches).
But in your case this is not much of a disadvantage as you have a high
% Non-Parse CPU (98.94 %).
========================================================
This appears to agree with the excessive waits for log files that occur later.
But in the examples that I am studying (from Kyte and Lawson) this percentage
never goes below 40%, whereas for me, it is very low ~ 4.3%.
Instance Efficiency Percentages
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Buffer Nowait %: 99.98 Redo NoWait %: 99.80
Buffer Hit %: 99.28 In-memory Sort %: 100.00
Library Hit %: 99.98 Soft Parse %: 94.41
Execute to Parse %: 99.90 Latch Hit %: 99.83
Parse CPU to Parse Elapsd %: 4.35 % Non-Parse CPU: 99.88
Below seems reasonable.
Shared Pool Statistics Begin End
------ ------
Memory Usage %: 84.05 85.41
% SQL with executions>1: 64.83 89.95
% Memory for SQL w/exec>1: 77.94 96.43
Now
here* is where it gets interesting. Do I really wait 13000 seconds out of the
14400 seconds of the session (2 (CPU) X 120 (mins) X 60 (seconds)? Surely this
is a problem? I know that I only have one disk, but even so, this appears and
excessive amount of time to have to wait for log files?
Also, why is the sum of the time of the waits greater than the time taken for the entire
Statspack session - i.e. the sum of the waits is greater than 14400 -
why?*
Top 5 Timed Events Avg %Total
~~~~~~~~~~~~~~~~~~ wait Call
Event Waits Time (s) (ms) Time
----------------------------------------- ------------ ----------- ------ ------
log file sync 217,470 13,750 63 50.9
log file parallel write 155,901 5,935 38 22.0
db file sequential read 208,369 3,364 16 12.5
log file switch (checkpoint incomplete) 2,267 2,135 942 7.9
CPU time 755 2.8
-------------------------------------------------------------
Load on system not exactly high - %idle = 70%
^LHost CPU (CPUs: 2)
~~~~~~~~ Load Average
Begin End User System Idle WIO WCPU
------- ------- ------- ------- ------- ------- --------
2.84 3.17 21.72 6.85 71.43
I'm very puzzled by what's below.
The instance has used 10279 seconds out of the 14328 seconds of the
Statspack run. That's fine - I understand what's going on (I think) - the Oracle
instance doesn't have complete control over the machine and relinquishes
control for some of the time - OS housekeeping functions &c.
Where I
am* confused is the DB time of 20,836.7, which is significantly
longer* than the entire Statspack session of 14K seconds. Could somebody
explain this to me please? Related to my question about wait events above?
Even the background elapsed time is very large compared to the time
overall - more confusion.
Note: There is a 28% discrepancy between the OS Stat total CPU time and
the total CPU time estimated by Statspack
OS Stat CPU time: 10279(s) (BUSY_TIME + IDLE_TIME)
Statspack CPU time: 14328(s) (Elapsed time * num CPUs in end snap)
Instance CPU
~~~~~~~~~~~~
% of total CPU for Instance: 8.96
% of busy CPU for Instance: 31.36
%DB time waiting for CPU - Resource Mgr: 0.00
Memory Statistics Begin End
~~~~~~~~~~~~~~~~~ ------------ ------------
Host Mem (MB): .0 .0
SGA use (MB): 272.0 272.0
PGA use (MB): 61.0 79.1
% Host Mem used for SGA+PGA: 1947444.5 842052.4
-------------------------------------------------------------
Time Model System Stats DB/Inst: XE/XE Snaps: 21-22
-> Ordered by % of DB time desc, Statistic name
Statistic Time (s) % of DB time
----------------------------------- -------------------- ------------
sql execute elapsed time 7,059.6 33.9
DB CPU 758.8 3.6
PL/SQL execution elapsed time 100.5 .5
parse time elapsed 14.9 .1
hard parse elapsed time 13.7 .1
PL/SQL compilation elapsed time 5.3 .0
connection management call elapsed 3.4 .0
repeated bind elapsed time 0.7 .0
hard parse (sharing criteria) elaps 0.7 .0
DB time 20,836.7
background elapsed time 13,194.8
background cpu time 162.1
-------------------------------------------------------------
Thanks for having got this far - there's a drink waiting for you if you're ever
in Dublin -
Paul...