Thank you for your precious time in looking at my stats.

<quote>
I would say your shared pool looks sized OK, block buffers might be smallish at 78m but that is hard to say. One would have to see the top 5 waits to see if your log buffer is too small (probable). We would be looking for log related waits there.
</quote>

It's hard understanding this part (please bear with me..)
Below additional info from the same 2 statspack report above:
SNAP1
============================================================
Top 5 Wait Events
~~~~~~~~~~~~~~~~~ Wait % Total
Event Waits Time (cs) Wt Time
---------------------------- ------ ------------ -------
db file scattered read 56,100 0 .00
db file sequential read 38,457 0 .00
SQL*Net message to dblink 19,606 0 .00
SQL*Net message from dblink 19,600 0 .00
direct path read 11,006 0 .00
============================================================
SNAP2
============================================================
Top 5 Wait Events
~~~~~~~~~~~~~~~~~ Wait % Total
Event Waits Time (cs) Wt Time
--------------------------- ------ --------- -------
db file sequential read 38,542 0 .00
direct path read 26,445 0 .00
SQL*Net message to dblink 20,709 0 .00
SQL*Net message from dblink 20,701 0 .00
db file scattered read 13,592 0 .00
============================================================

Also, i extracted all "log related waits" information:
SNAP1
============================================================
Wait Events:
Avg
Total Wait wait Waits
Event Waits Timeouts Time (cs) (ms) /txn
---------------------------- ------------ ---------- ----------- ------ ------
log file parallel write 1,355 0 0 0 0.6
log file sync 862 0 0 0 0.4
log file sequential read 322 0 0 0 0.1
log buffer space 18 0 0 0 0.0
log file single write 2 0 0 0 0.0
log file switch completion 2 0 0 0 0.0

Background Wait Events:
log file parallel write 1,355 0 0 0 0.6
log file sequential read 322 0 0 0 0.1
log file single write 2 0 0 0 0.0
============================================================

SNAP2
============================================================
Wait Events:

log file parallel write 723 0 0 0 0.6
log file sync 520 0 0 0 0.4
log file sequential read 322 0 0 0 0.3
log buffer space 12 0 0 0 0.0
log file single write 2 0 0 0 0.0
log file switch completion 1 0 0 0 0.0

Background Wait Events:
log file parallel write 722 0 0 0 0.6
log file sequential read 322 0 0 0 0.3
log file single write 2 0 0 0 0.0

============================================================

Another 2 questions:
a. If with the same setup, we add 10% more users. What will we observe in the Load Profile?

b. If i was to add another application to my system (mainly batch processing oriented and which would normally ocurr between 8:00 a.m to 10:30 a.m.), how would i go about my analysis? How can i forecast the amount of performance degradation (if any) and what are the values that i would eye so as to take corrective measures? Assuming the new application have the same flaws as my current one.

Thank you again for your precious guidance.

Best Regards
Yogeeraj
PS. I did not get any notification message about your reply. Do i assume a problem with my mail server?

thank you very much for the reply.

I will have to spend more time evaluating the impact of the new application going live and take appropriate pro-active measures.

regards
Yogeeraj
PS. still sorting out the email problem with my mail server admin.

I am seeing a negative value in the Execute to Parse %.

Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Buffer Nowait %: 99.92 Redo NoWait %: 100.00
Buffer Hit %: 97.15 In-memory Sort %: 96.11
Library Hit %: 99.89 Soft Parse %: 99.92
Execute to Parse %: -63.17 Latch Hit %: 99.95
Parse CPU to Parse Elapsd %: 62.72 % Non-Parse CPU: 100.00

What is wrong?

Tom
May be this is not in line of discussion, but how to install this Statpack( ver. 8.1.6 on NT)?
Thanks

Tom,
What is the meaning of the timeouts column in the Wait Events section of the statspack report?

From the SQL report:
CPU Elapsd
Buffer Gets Executions Gets per Exec %Total Time (s) Time (s) Hash Value
--------------- ------------ -------------- ------ -------- --------- ----------
9,192,936 22,045 417.0 2.5 946.15 1062.41 238087931
select t.schema, t.name, t.flags, q.name from system.aq$_queue_tables t, sys.aq$_queue_table_affinities aft, system.aq$_que
ues q where aft.table_objno = t.objno and aft.owner_instance = :
1 and q.table_objno = t.objno and q.usage = 0 and b
itand(t.flags, 4+16+32+64+128+256) = 0 for update of t.name, aft

...

3,406,887 484,990 7.0 0.9 235.18 291.73 3460529092
select t.name, (select owner_instance from sys.aq$_queue_table_
affinities where table_objno = t.objno) from system.aq$_queue
_tables t where t.name = :1 and t.schema = :2 for update skip lo
cked


This report is for the interval between a couple of days. 3 questions:

1. Why is it reporting on AQ ? I don't use it, as far as I know.

2. Why do they have so high buffer gets ?

3. Since the report spans the time between the snaps, to what period do the sql commands belong ? Are they only those sql commands that persisted across the snaps ?

Thanks, Tom

show parameter aq_tm_processes
NAME TYPE VALUE
------------------------------------ ----------- ------------------------------
aq_tm_processes integer 1

I have the default install of 9i R1, and I did not set up AQ. Why does it come out as default?

Thanks

Hi,

I am used to analyse my STATSPACK report once every week (especially when my users starts complaining about "performance" problems - well, fortunately most of the time, it has been network problem over our Frame Relay WAN.

Currently, there is one SQL in the "SQL ordered by Gets for DB: " section of the reports that keeps giving me the same SQL on top, namely:
================================================================
select parent_owner,parent_name,parent_link_name,parent_type,par
ent_timestamp,property from ora_kglr7_dependencies where owner=:
1 and name=:2 and type=:3 and obj#=:4 order by order_number
================================================================

For example:

Day 1 at 09:06:59: [Elapsed: 15.67 (mins)]
Buffer Gets Executions Gets per Exec % Total Hash Value
--------------- ------------ -------------- ------- ------------
1,355,159 719 1,884.8 7.4 2838017588
select parent_owner,parent_name,parent_link_name,parent_type,par
ent_timestamp,property from ora_kglr7_dependencies where owner=:
1 and name=:2 and type=:3 and obj#=:4 order by order_number


Day 2 at 12:29:36: [Elapsed:15.18 (mins) - a batch job was running at that time]
6,908,475 1 6,908,475.0 48.0 2924315239
UPDATE OPT320 SET ( CRTQTY,EXPQTY )=(SELECT NVL(SUM(DECODE(CRT2
00V_2.TRNCODE,'IN',CRT200V_2.PCECRT)),0),NVL(SUM(DECODE(CRT200V_
2.TRNCODE,'OUT',CRT200V_2.PCECRT)),0) FROM SWPROD.CRT200V_2 W
HERE ORDNUM = OPT320.ORDNUM AND CLRSEQ = OPT320.CLRSEQG AND SZ
ESEQ = OPT320.SZESEQ AND GMTSEQ = OPT320.GMTSEQ ),( RBPQTY,RAPQ

2,017,958 1,062 1,900.1 14.0 2838017588
select parent_owner,parent_name,parent_link_name,parent_type,par
ent_timestamp,property from ora_kglr7_dependencies where owner=:
1 and name=:2 and type=:3 and obj#=:4 order by order_number


Day 2 at 13:42:26: [Elapsed: 15.28 (mins)]
Buffer Gets Executions Gets per Exec % Total Hash Value
--------------- ------------ -------------- ------- ------------
1,749,879 924 1,893.8 15.4 2838017588
select parent_owner,parent_name,parent_link_name,parent_type,par
ent_timestamp,property from ora_kglr7_dependencies where owner=:
1 and name=:2 and type=:3 and obj#=:4 order by order_number


Day 3 (today): [Elapsed: 38.93 (mins)]
Buffer Gets Executions Gets per Exec % Total Hash Value
--------------- ------------ -------------- ------- ------------
4,578,962 2,420 1,892.1 14.1 2838017588
select parent_owner,parent_name,parent_link_name,parent_type,par
ent_timestamp,property from ora_kglr7_dependencies where owner=:
1 and name=:2 and type=:3 and obj#=:4 order by order_number


Does this "smell" any problem?

thank you in advance for your time and reply

regards
Yogeeraj

Hi Tom,

I have lots of timeouts on log file parallel write wait event. Is it because my log files are in the same RAID5 diskset?

What can I do in the database to make the situation better on this existing hardware? Hardware configuration:

Disk #1, #2: RAID 1+0 for OS (Win2K)
Disk #3,#4,#5: RAID 5 for Oracle database (including software)
2G Memoery with 1.8Ghz Xeon processor

Thanks.


STATSPACK report for

DB Name DB Id Instance Inst Num Release Cluster Host
------------ ----------- ------------ -------- ----------- ------- ------------
PAGO04 1502736998 pago04 1 9.2.0.3.0 NO KTCSRV005

Snap Id Snap Time Sessions Curs/Sess Comment
------- ------------------ -------- --------- -------------------
Begin Snap: 781 07-Jul-03 14:38:03 30 4.0
End Snap: 782 07-Jul-03 15:03:16 39 5.5
Elapsed: 25.22 (mins)

Cache Sizes (end)
~~~~~~~~~~~~~~~~~
Buffer Cache: 120M Std Block Size: 8K
Shared Pool Size: 56M Log Buffer: 512K

Load Profile
~~~~~~~~~~~~ Per Second Per Transaction
--------------- ---------------
Redo size: 1,284.15 176,628.36
Logical reads: 213.57 29,375.00
Block changes: 7.50 1,031.09
Physical reads: 0.15 21.09
Physical writes: 0.65 89.00
User calls: 1.04 143.36
Parses: 1.95 268.09
Hard parses: 0.02 2.55
Sorts: 0.69 94.27
Logons: 0.04 5.45
Executes: 3.30 453.27
Transactions: 0.01

% Blocks changed per Read: 3.51 Recursive Call %: 90.43
Rollback per transaction %: 0.00 Rows per Sort: 16.53

Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Buffer Nowait %: 100.00 Redo NoWait %: 100.00
Buffer Hit %: 99.93 In-memory Sort %: 100.00
Library Hit %: 97.79 Soft Parse %: 99.05
Execute to Parse %: 40.85 Latch Hit %: 99.98
Parse CPU to Parse Elapsd %: 94.20 % Non-Parse CPU: 83.20

Shared Pool Statistics Begin End
------ ------
Memory Usage %: 95.66 95.81
% SQL with executions>1: 81.51 82.97
% Memory for SQL w/exec>1: 77.44 79.50

Top 5 Timed Events
~~~~~~~~~~~~~~~~~~ % Total
Event Waits Time (s) Ela Time
-------------------------------------------- ------------ ----------- --------
CPU time 4 59.02
db file sequential read 240 1 13.38
log file parallel write 1,829 1 8.92
control file parallel write 492 1 8.36
db file parallel write 66 0 5.15
-------------------------------------------------------------
Wait Events for DB: PAGO04 Instance: pago04 Snaps: 781 -782
-> s - second
-> cs - centisecond - 100th of a second
-> ms - millisecond - 1000th of a second
-> us - microsecond - 1000000th of a second
-> ordered by wait time desc, waits desc (idle events last)

Avg
Total Wait wait Waits
Event Waits Timeouts Time (s) (ms) /txn
---------------------------- ------------ ---------- ---------- ------ --------
db file sequential read 240 0 1 4 21.8
log file parallel write 1,829 1,705 1 0 166.3
control file parallel write 492 0 1 1 44.7
db file parallel write 66 0 0 5 6.0
control file sequential read 371 0 0 0 33.7
latch free 15 0 0 8 1.4
log file sync 66 0 0 0 6.0
SQL*Net break/reset to clien 4 0 0 0 0.4
SQL*Net more data to client 6 0 0 0 0.5
LGWR wait for redo copy 1 0 0 0 0.1
SQL*Net message from client 1,676 0 16,047 9575 152.4
virtual circuit status 51 51 1,524 29886 4.6
wakeup time manager 48 48 1,465 30528 4.4
SQL*Net message to client 1,685 0 0 0 153.2
-------------------------------------------------------------
Background Wait Events for DB: PAGO04 Instance: pago04 Snaps: 781 -782
-> ordered by wait time desc, waits desc (idle events last)

Avg
Total Wait wait Waits
Event Waits Timeouts Time (s) (ms) /txn
---------------------------- ------------ ---------- ---------- ------ --------
log file parallel write 1,829 1,705 1 0 166.3
control file parallel write 492 0 1 1 44.7
db file parallel write 66 0 0 5 6.0
control file sequential read 321 0 0 0 29.2
db file sequential read 2 0 0 6 0.2
LGWR wait for redo copy 1 0 0 0 0.1
rdbms ipc message 4,988 3,213 7,564 1516 453.5
pmon timer 514 514 1,511 2940 46.7
smon timer 5 5 1,279 ###### 0.5
-------------------------------------------------------------
SQL ordered by Gets for DB: PAGO04 Instance: pago04 Snaps: 781 -782
-> End Buffer Gets Threshold: 10000
-> Note that resources reported for PL/SQL includes the resources used by
all SQL statements called within the PL/SQL code. As individual SQL
statements are also reported, it is possible and valid for the summed
total % to exceed 100

CPU Elapsd

Tom, If time permits, could you please explain the meaning of the following terminology to understand the information in statspack.

db file parallel write
control file parallel write
db file sequential read
db file scattered read
log file parallel write.

Hi Tom
I know you advocate a window of 30 minutes max. One thought
is - if the reported SQL accounts for a large % of
the reported time then it is ok to go for a longer
period - an hour, 2, 5 hours even may be. This does not
seem correct to me (esp. after reading Cary's book:)).

What are your thoughts?

Love your site and books!

what you say makes sense - I guess what they mean is
that if the top sql of statspack points to a query that has been running for say 2 hours or so then may be the
statspack window time is ok (even if it is 2 hours)

Anyways, intuitively it does not make sense to me!

Tom,
I have very high Pct miss in library cache and dictionary cache. I have looked at the statspack reports for the same period for last two months for this database. The Pct miss for SQL AREA is always more that 50%. Does this mean the shared pool size it too low?

Library Cache Activity for DB: MCIP Instance: MCIP Snaps: 1640 -1641
->"Pct Misses" should be very low

Get Pct Pin Pct Invali-
Namespace Requests Miss Requests Miss Reloads dations
--------------- ------------ ------ -------------- ------ ---------- --------
BODY 1,869 0.1 1,869 0.1 0 0
CLUSTER 57 0.0 61 0.0 0 0
INDEX 6 50.0 6 50.0 0 0
SQL AREA 8,895 49.6 342,260 2.7 212 0
TABLE/PROCEDURE 47,221 0.2 116,099 0.5 395 0
-------------------------------------------------------------

Hi

in statspack reports I see many time values such as

smon timer 5 5 1,279 ###### 0.5


can we modify the spreport.sql to change that?

Hi

following note 223117.1 from Metalink, tuning I/O related waits I found my response time is bigger than the snap interval... Is this possible?!

The report is below:

Snap Id Snap Time Sessions
------- ------------------ --------
Begin Snap: 2551 10-Nov-03 13:13:52 514
End Snap: 2552 10-Nov-03 13:35:58 514

Top 5 Wait Events
~~~~~~~~~~~~~~~~~ Wait % Total
Event Waits Time (cs) Wt Time
-------------------------------------------- ------------ ------------ -------
latch free 51,692 52,872 22.82
direct path write (lob) 59,228 47,489 20.50
direct path read (lob) 62,323 47,076 20.32
db file sequential read 36,120 25,951 11.20
buffer busy waits 8,496 20,879 9.01


Statistic Total per Second per Trans
--------------------------------- ---------------- ------------ ------------
CPU used by this session 215,903 162.8 2.9


according to the note:

Wait time = 52,872 x 100% / 22.82% = 231,691.40 cs
Service time = 215,903 cs
Response time = 215,903 + 231,691.40 = 447,594.40 cs = 4475 seconds aprox

Is this possible...?

Hi

So how can we find the service time in a multi-user environment? I guess the note's approach only works for single processes.... huh

Tom,
How can i make effective use of statspack in a Apps 11i environment when users complain that there is total system slowdown and CPU pegged at 100%?

Can you please take a look at my statspack report and let me know if there are any obvious issues?

Thanks,
Sriram


STATSPACK report for

DB Name DB Id Instance Inst Num Release OPS Host
------------ ----------- ------------ -------- ----------- --- ------------
xxx 785005184 prod 1 8.1.7.4.1 NO xxx

Snap Id Snap Time Sessions
------- ------------------ --------
Begin Snap: 1084 18-Nov-03 14:26:43 196
End Snap: 1086 18-Nov-03 14:42:53 196
Elapsed: 16.17 (mins)

Cache Sizes
~~~~~~~~~~~
db_block_buffers: 30000 log_buffer: 1048576
db_block_size: 8192 shared_pool_size: 300000000

Load Profile
~~~~~~~~~~~~ Per Second Per Transaction
--------------- ---------------
Redo size: 78,822.39 41,871.70
Logical reads: 30,263.57 16,076.48
Block changes: 527.92 280.44
Physical reads: 799.79 424.86
Physical writes: 35.61 18.92
User calls: 163.00 86.59
Parses: 42.68 22.67
Hard parses: 1.27 0.67
Sorts: 284.89 151.34
Logons: 0.17 0.09
Executes: 852.63 452.93
Transactions: 1.88

% Blocks changed per Read: 1.74 Recursive Call %: 91.06
Rollback per transaction %: 4.22 Rows per Sort: 11.75

Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Buffer Nowait %: 99.99 Redo NoWait %: 100.00
Buffer Hit %: 97.36 In-memory Sort %: 99.97
Library Hit %: 99.75 Soft Parse %: 97.03
Execute to Parse %: 94.99 Latch Hit %: 99.97
Parse CPU to Parse Elapsd %: 27.82 % Non-Parse CPU: 99.07

Shared Pool Statistics Begin End
------ ------
Memory Usage %: 91.15 91.62
% SQL with executions>1: 80.94 75.94
% Memory for SQL w/exec>1: 66.93 74.37

Top 5 Wait Events
~~~~~~~~~~~~~~~~~ Wait % Total
Event Waits Time (cs) Wt Time
-------------------------------------------- ------------ ------------ -------
db file sequential read 208,439 476,250 58.84
db file scattered read 79,090 285,145 35.23
pipe put 79 8,075 1.00
log file sequential read 4,804 7,504 .93
latch free 3,192 7,410 .92
-------------------------------------------------------------
Wait Events for DB: PROD Instance: prod Snaps: 1084 -1086
-> cs - centisecond - 100th of a second
-> ms - millisecond - 1000th of a second
-> ordered by wait time desc, waits desc (idle events last)

Avg
Total Wait wait Waits
Event Waits Timeouts Time (cs) (ms) /txn
---------------------------- ------------ ---------- ----------- ------ ------
db file sequential read 208,439 0 476,250 23 114.2
db file scattered read 79,090 0 285,145 36 43.3
pipe put 79 76 8,075 1022 0.0
log file sequential read 4,804 0 7,504 16 2.6
latch free 3,192 2,869 7,410 23 1.7
enqueue 20 18 5,586 2793 0.0
log file sync 1,740 0 5,169 30 1.0
file open 930 0 5,023 54 0.5
buffer busy waits 3,933 1 4,314 11 2.2
queue messages 19 19 2,015 1061 0.0
log file parallel write 2,237 0 1,340 6 1.2
control file sequential read 328 0 489 15 0.2
direct path read 418 0 358 9 0.2
log file switch completion 3 0 164 547 0.0
SQL*Net more data to client 7,499 0 136 0 4.1
direct path write 254 0 99 4 0.1
db file parallel write 216 0 91 4 0.1
control file parallel write 325 0 86 3 0.2
refresh controlfile command 20 0 56 28 0.0
file identify 8 0 26 33 0.0
SQL*Net break/reset to clien 252 0 21 1 0.1
log buffer space 8 0 20 25 0.0
library cache pin 5 0 16 32 0.0
LGWR wait for redo copy 48 4 8 2 0.0
log file single write 4 0 0 0 0.0
buffer deadlock 1 1 0 0 0.0
SQL*Net message from client 160,226 0 9,678,556 604 87.7
wakeup time manager 33 31 94,933 28768 0.0
SQL*Net more data from clien 2,323 0 98 0 1.3
SQL*Net message to client 160,221 0 20 0 87.7
-------------------------------------------------------------
Background Wait Events for DB: PROD Instance: prod Snaps: 1084 -1086
-> ordered by wait time desc, waits desc (idle events last)

Avg
Total Wait wait Waits
Event Waits Timeouts Time (cs) (ms) /txn
---------------------------- ------------ ---------- ----------- ------ ------
log file sequential read 4,804 0 7,504 16 2.6
log file parallel write 2,237 0 1,340 6 1.2
db file scattered read 333 0 583 18 0.2
db file parallel write 216 0 91 4 0.1
control file sequential read 91 0 89 10 0.0
control file parallel write 325 0 86 3 0.2
db file sequential read 19 0 49 26 0.0
file identify 8 0 26 33 0.0
latch free 3 3 16 53 0.0
LGWR wait for redo copy 48 4 8 2 0.0
file open 7 0 8 11 0.0
rdbms ipc reply 10 0 2 2 0.0
log file single write 4 0 0 0 0.0
rdbms ipc message 7,469 917 549,679 736 4.1
smon timer 4 3 100,292 ###### 0.0
pmon timer 312 312 97,124 3113 0.2
-------------------------------------------------------------
SQL ordered by Gets for DB: PROD Instance: prod Snaps: 1084 -1086
-> End Buffer Gets Threshold: 10000
-> Note that resources reported for PL/SQL includes the resources used by
all SQL statements called within the PL/SQL code. As individual SQL
statements are also reported, it is possible and valid for the summed
total % to exceed 100

Buffer Gets Executions Gets per Exec % Total Hash Value
--------------- ------------ -------------- ------- ------------
12,404,196 25,943 478.1 42.3 470331148
SELECT 'Y' FROM FND_ATTACHED_DOCUMENTS T1,FND_DOCUMENTS_TL T2,
FND_DOCUMENTS T3 WHERE T1.ENTITY_NAME = :b1 AND T1.PK1_VALUE =
:b2 AND T1.DOCUMENT_ID = T2.DOCUMENT_ID AND T2.DOCUMENT_ID =
T3.DOCUMENT_ID AND T3.DATATYPE_ID = 100

5,745,997 2 2,872,998.5 19.6 1162758779
declare rc__ number; begin owa.init_cgi_env(:n__,:nm__,:v__);
htp.HTBUF_LEN := 255; null; arw_pages.invoice_table; if (wpg
_docload.is_file_download) then rc__ := 1; wpg_docload.get_d
ownload_file(:doc_info); null; commit; else rc__ := 0; nu
ll; commit; owa.get_page(:data__,:ndata__); end if; :rc__

4,376,840 3 1,458,946.7 14.9 328885768
SELECT CONCURRENT_PROGRAM_ID,PROGRAM_APPLICATION_ID,PRINTER,PROG
RAM_SHORT_NAME,ARGUMENT_TEXT,PRINT_STYLE,USER_PRINT_STYLE,SAVE_O
UTPUT_FLAG,ROW_ID,ACTUAL_COMPLETION_DATE,COMPLETION_TEXT,PARENT_
REQUEST_ID,REQUEST_TYPE,FCP_PRINTER,FCP_PRINT_STYLE,FCP_REQUIRED
_STYLE,LAST_UPDATE_DATE,LAST_UPDATED_BY,REQUESTED_BY,HAS_SUB_REQ

2,039,585 7,587 268.8 6.9 3873667830
begin AP_APPROVAL_PKG.APPROVE(:P_RUN_OPTION, :P_INVOICE_BATCH_ID
, :P_BEGIN_INVOICE_DATE, :P_END_INVOICE_DATE, :P_VENDOR_ID, :P_P
AY_GROUP, :P_INVOICE_ID, :P_ENTERED_BY, :P_SET_OF_BOOKS_ID, :P_T
RACE_OPTION, :P_CONC_FLAG, :P_HOLDS_COUNT, :P_APPROVAL_STATUS, :
P_CALLING_SEQUENCE); end;

1,587,220 1 1,587,220.0 5.4 4160269578
SELECT SUBSTR(akq.AL_CLASS_MEANING,1,4000), SUBSTR(akq.TRX_NUMBE
R,1,4000), SUBSTR(akq.AL_STATUS_MEANING,1,4000), SUBSTR(akq.TRX_
DATE,1,4000), SUBSTR(akq.RAC_CUSTOMER_NAME,1,4000), SUBSTR(akq.C
T_PURCHASE_ORDER,1,4000), SUBSTR(akq.AMOUNT_DUE_ORIGINAL,1,4000)
, SUBSTR(akq.AMOUNT_DUE_REMAINING,1,4000), SUBSTR(akq.CUSTOMER_T

1,284,729 14 91,766.4 4.4 2586771312
declare x_message_code varchar2 ( 100 ) ; BEGIN x_message_code :
= null ; pa_billing . bill_ext_driver ( :par_project_id , :par_c
alling_process , :par_calling_place , :par_acc_thru_dt , :par_re
quest_id , x_message_code ) ; :message:i_message := x_message_co
de ; END ;

1,241,280 6 206,880.0 4.2 1696222480
UPDATE PA_EVENTS PE SET REVENUE_DISTRIBUTED_FLAG='Y' WHERE EXIST
S (SELECT 1 FROM GSI_COST_OF_SALES COS WHERE LINE_NUM IS NUL
L AND COS.EVENT_ID = :b1 AND COS.MANUAL_EVENT_ID = PE.EVENT_ID
)

1,085,511 1 1,085,511.0 3.7 362512440
SELECT scope, project_num, sum(currev) Sales
, (sum(currev) - sum(curcost)) CV, decode(sum(currev),0,
0,(sum(currev) - sum(curcost))*100/sum(currev)) CV_percent,
SQL ordered by Gets for DB: PROD Instance: prod Snaps: 1084 -1086
-> End Buffer Gets Threshold: 10000
-> Note that resources reported for PL/SQL includes the resources used by
all SQL statements called within the PL/SQL code. As individual SQL
statements are also reported, it is possible and valid for the summed
total % to exceed 100

Buffer Gets Executions Gets per Exec % Total Hash Value
--------------- ------------ -------------- ------- ------------
sum(reg_amt) reg_amt, sum(ovt_amt) ovt_amt, sum(dot_amt)
dot_amt, location, project_id, address_id FROM

834,434 14 59,602.4 2.8 1255574089
declare rc__ number; begin owa.init_cgi_env(:n__,:nm__,:v__);
htp.HTBUF_LEN := 255; null; OracleSSWA.Execute(E=>:E); if (w
pg_docload.is_file_download) then rc__ := 1; wpg_docload.get
_download_file(:doc_info); null; commit; else rc__ := 0;
null; commit; owa.get_page(:data__,:ndata__); end if; :rc_

796,528 10 79,652.8 2.7 423950914
BEGIN WF_ENGINE.BACKGROUNDCONCURRENT( :errbuf, :rc,:A0,:A1,:A2,:
A3,:A4,:A5); END;

775,604 12 64,633.7 2.6 1335613946
SELECT /*+ ORDERED USE_NL (WIASP WI WPAP WAP) INDEX
(WIASP WF_ITEM_ACTIVITY_STATUSES_N1) */WIASP.ROWID ROW_ID FRO
M WF_ITEM_ACTIVITY_STATUSES WIASP,WF_ITEMS WI,WF_PROCESS_ACTIVIT
IES WPAP,WF_ACTIVITIES WAP WHERE WIASP.ITEM_TYPE = :b1 AND WIA
SP.PROCESS_ACTIVITY = WPAP.INSTANCE_ID AND WPAP.ACTIVITY_ITEM_T

752,819 407 1,849.7 2.6 1857750303
SELECT NVL(SUM(DECODE(ITEM.EXPENDITURE_TYPE,'REGULAR TIME',ITEM.
QUANTITY,0.00)),0) REG_AMT,NVL(SUM(DECODE(ITEM.EXPENDITURE_TYPE,
'OVERTIME',ITEM.QUANTITY,0.00)),0) OVT_AMT,NVL(SUM(DECODE(ITEM.E
XPENDITURE_TYPE,'DOUBLE TIME',ITEM.QUANTITY,0.00)),0) DOT_AMT
FROM PA_TASKS PAT,PA_EXPENDITURE_ITEMS ITEM,PA_PROJECT_CLASSES P

731,939 56,303 13.0 2.5 885722162
(SELECT STATUS_FLAG FROM IGI_GCC_INSTALLED_OPTIONS WHERE UPPE
R(OPTION_NAME) = UPPER(:b1) ) UNION (SELECT STATUS_FLAG FROM I
GI_GCC_GL_FA_INST_OPS WHERE UPPER(OPTION_NAME) = UPPER(:b1) )

548,295 3 182,765.0 1.9 3495154319
begin PA_SELF_SERVICE_HANDLER_PVT.CREATENEWTIMECARD; end;

410,188 211 1,944.0 1.4 2838017588
select parent_owner,parent_name,parent_link_name,parent_type,par
ent_timestamp,property from ora_kglr7_dependencies where owner=:
1 and name=:2 and type=:3 and obj#=:4 order by order_number

371,733 5 74,346.6 1.3 132022523
SELECT ET.EXPENDITURE_TYPE EXPENDITURE_TYPE,ET.SYSTEM_LINKAGE_FU
NCTION SYS_LINKAGE_CODE,GREATEST(ET.EXPND_TYP_START_DATE_ACTIVE,

-------------------------------------------------------------
SQL ordered by Reads for DB: PROD Instance: prod Snaps: 1084 -1086
-> End Disk Reads Threshold: 1000

Physical Reads Executions Reads per Exec % Total Hash Value
--------------- ------------ -------------- ------- ------------
169,260 51 3,318.8 21.8 1233221062
SELECT T2.FILE_NAME FROM FND_ATTACHED_DOCUMENTS T1,FND_DOCUMEN
TS_TL T2 WHERE T1.PK1_VALUE = :b1 AND T1.DOCUMENT_ID = T2.DOCU
MENT_ID AND ROWNUM <= 1

61,930 2 30,965.0 8.0 1855731242
select decode ( : p_show_country , 'Y' , fnd . territory_short_n
ame , 'Dummy_Country' ) country , party . category_code category
, cust_acct . attribute1 dr4code , substrb ( party . party_name
, 1 , 50 ) cust_name , cust_acct . account_number cust_no , nvl
( proj . segment1 , '~' ) project_number , nvl ( task . task_nu

55,413 53 1,045.5 7.1 1441530861
begin WF_XML.GetShortMessage(:q, :n, :r, :s, :t, :er); end;

55,401 22 2,518.2 7.1 633115946
select /*+ FIRST_ROWS */ qt.rowid, qt.msgid, qt.corrid, qt.prio
rity, qt.delay, qt.expiration, qt.retry_count, qt.except
ion_qschema, qt.exception_queue, qt.chain_no, qt.local_or
der_no, qt.enq_time, qt.time_manager_info, qt.state, qt.
enq_tid, qt.step_no, qt.sender_name, qt.sender_address, qt.send

41,349 407 101.6 5.3 1857750303
SELECT NVL(SUM(DECODE(ITEM.EXPENDITURE_TYPE,'REGULAR TIME',ITEM.
QUANTITY,0.00)),0) REG_AMT,NVL(SUM(DECODE(ITEM.EXPENDITURE_TYPE,
'OVERTIME',ITEM.QUANTITY,0.00)),0) OVT_AMT,NVL(SUM(DECODE(ITEM.E
XPENDITURE_TYPE,'DOUBLE TIME',ITEM.QUANTITY,0.00)),0) DOT_AMT
FROM PA_TASKS PAT,PA_EXPENDITURE_ITEMS ITEM,PA_PROJECT_CLASSES P

41,005 14 2,928.9 5.3 2586771312
declare x_message_code varchar2 ( 100 ) ; BEGIN x_message_code :
= null ; pa_billing . bill_ext_driver ( :par_project_id , :par_c
alling_process , :par_calling_place , :par_acc_thru_dt , :par_re
quest_id , x_message_code ) ; :message:i_message := x_message_co
de ; END ;

38,427 6 6,404.5 5.0 1696222480
UPDATE PA_EVENTS PE SET REVENUE_DISTRIBUTED_FLAG='Y' WHERE EXIST
S (SELECT 1 FROM GSI_COST_OF_SALES COS WHERE LINE_NUM IS NUL
L AND COS.EVENT_ID = :b1 AND COS.MANUAL_EVENT_ID = PE.EVENT_ID
)

27,033 192 140.8 3.5 1542130467
declare event_info SF_Mgr.EventInfo_T; e_prop_types
SF_Mgr.EventPropertyTypeList_T; e_prop_values SF_Mgr.E
ventPropertyValueList_T; triggered_rules SF_Mgr.TriggeredRuleLis
t_T; i Number; rule_inst_id Number; res
ult Number; begin :EVENT_COUNT := 0; :TRIG_MSG := '

23,204 1 23,204.0 3.0 362512440
SELECT scope, project_num, sum(currev) Sales
, (sum(currev) - sum(curcost)) CV, decode(sum(currev),0,
0,(sum(currev) - sum(curcost))*100/sum(currev)) CV_percent,
sum(reg_amt) reg_amt, sum(ovt_amt) ovt_amt, sum(dot_amt)
dot_amt, location, project_id, address_id FROM
SQL ordered by Reads for DB: PROD Instance: prod Snaps: 1084 -1086
-> End Disk Reads Threshold: 1000

Physical Reads Executions Reads per Exec % Total Hash Value
--------------- ------------ -------------- ------- ------------

22,652 45 503.4 2.9 3220411513
select NODE_NAME ,CHILD_PROCESS_ID ,CHILD_THREAD_ID ,CHILD_EXE_N
AME ,TO_CHAR(CHILD_START_TIME,'YYYYDDMM HH24MISS') into :b0,:b1,
:b2,:b3,:b4 from FND_CONC_NT_PROCESSES where (CHILD_PROCESS_ID=
:b5 and PARENT_PROCESS_ID=:b6)

22,109 2 11,054.5 2.8 2031957757
/*03 Aug 2001 14:44*/ SELECT lpad(rta.trx_number,15) so
rt_invoice, rta.org_id org_id, rta.customer_trx_id
customer_trx_id, pdi.project_id project_id, pdi.d
raft_invoice_num draft_invoice_num, ppa.name project_name
, rac.customer_id customer_id, rta.trx_number invo

19,991 3 6,663.7 2.6 3836499246
SELECT DISTINCT AERHV.FULL_NAME FULL_NAME, AERHV.EMPLOYEE_ID E
MPLOYEE_ID, AERHV.INVOICE_NUM REPORT_NUMBER, AERHV.REPORT_HE
ADER_ID REPORT_HEADER_ID, AERHV.INVOICE_DATE REPORT_DATE, AE
RHV.STATUS STATUS, AERHV.GR

Tom,

Excellent as always! Below is a statspack report for a about 10 snaps taken over about a 2 hour period.

Can you comment on the wait times, memory usage and parsing?

I see an issue with the redo/transaction being high here. Comments?

Thanks!

STATSPACK report for

DB Name DB Id Instance Inst Num Release Cluster Host
------------ ----------- ------------ -------- ----------- ------- ------------
IDWPROD1 2334540272 idwprod1 1 9.2.0.4.0 NO slkux1

Snap Id Snap Time Sessions Curs/Sess Comment
------- ------------------ -------- --------- -------------------
Begin Snap: 3 11-Mar-04 13:30:33 399 64.8
End Snap: 21 11-Mar-04 14:20:03 404 64.7
Elapsed: 49.50 (mins)

Cache Sizes (end)
~~~~~~~~~~~~~~~~~
Buffer Cache: 1,024M Std Block Size: 16K
Shared Pool Size: 128M Log Buffer: 768K

Load Profile
~~~~~~~~~~~~ Per Second Per Transaction
--------------- ---------------
Redo size: 10,108.84 24,251.42
Logical reads: 10,701.67 25,673.65
Block changes: 74.08 177.73
Physical reads: 210.80 505.71
Physical writes: 25.14 60.30
User calls: 100.74 241.68
Parses: 43.72 104.89
Hard parses: 1.83 4.40
Sorts: 116.08 278.48
Logons: 0.10 0.25
Executes: 153.23 367.60
Transactions: 0.42

% Blocks changed per Read: 0.69 Recursive Call %: 86.73
Rollback per transaction %: 9.69 Rows per Sort: 116.19

Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Buffer Nowait %: 100.00 Redo NoWait %: 99.99
Buffer Hit %: 98.69 In-memory Sort %: 99.99
Library Hit %: 97.25 Soft Parse %: 95.81
Execute to Parse %: 71.47 Latch Hit %: 99.98
Parse CPU to Parse Elapsd %: 45.61 % Non-Parse CPU: 92.83

Shared Pool Statistics Begin End
------ ------
Memory Usage %: 73.01 84.05
% SQL with executions>1: 84.91 78.35
% Memory for SQL w/exec>1: 80.99 77.01

Top 5 Timed Events
~~~~~~~~~~~~~~~~~~ % Total
Event Waits Time (s) Ela Time
-------------------------------------------- ------------ ----------- --------
db file sequential read 231,339 2,023 50.23
CPU time 1,383 34.34
db file scattered read 45,995 224 5.56
direct path write 11,329 104 2.58
direct path read 70,161 102 2.54
-------------------------------------------------------------
Wait Events for DB: IDWPROD1 Instance: idwprod1 Snaps: 3 -21
-> s - second
-> cs - centisecond - 100th of a second
-> ms - millisecond - 1000th of a second
-> us - microsecond - 1000000th of a second
-> ordered by wait time desc, waits desc (idle events last)

Avg
Total Wait wait Waits
Event Waits Timeouts Time (s) (ms) /txn
---------------------------- ------------ ---------- ---------- ------ --------
db file sequential read 231,339 0 2,023 9 186.9
db file scattered read 45,995 0 224 5 37.2
direct path write 11,329 0 104 9 9.2
direct path read 70,161 0 102 1 56.7
library cache pin 20 9 30 1507 0.0
SQL*Net more data to client 1,079,452 0 27 0 871.9
SQL*Net message from dblink 26,136 0 22 1 21.1
log file sync 1,627 7 20 12 1.3
log file parallel write 3,837 3,774 19 5 3.1
library cache load lock 24 5 19 778 0.0
db file parallel write 265 0 12 47 0.2
control file parallel write 1,539 0 12 8 1.2
async disk IO 251 0 7 27 0.2
process startup 42 0 3 64 0.0
latch free 589 79 2 4 0.5
db file single write 613 0 2 2 0.5
control file sequential read 6,406 0 1 0 5.2
direct path read (lob) 122 0 1 7 0.1
log file sequential read 46 0 1 15 0.0
buffer busy waits 51 0 1 11 0.0
db file parallel read 2 0 0 168 0.0
enqueue 13 0 0 25 0.0
log file switch completion 6 0 0 50 0.0
log buffer space 3 0 0 98 0.0
SQL*Net message to dblink 26,136 0 0 0 21.1
SQL*Net break/reset to clien 454 0 0 0 0.4
row cache lock 21 0 0 3 0.0
log file single write 4 0 0 4 0.0
SQL*Net more data from dblin 350 0 0 0 0.3
LGWR wait for redo copy 46 0 0 0 0.0
SQL*Net message from client 227,022 0 215,823 951 183.4
virtual circuit status 99 99 2,874 29029 0.1
wakeup time manager 94 94 2,807 29859 0.1
jobq slave wait 900 870 2,674 2971 0.7
SQL*Net more data from clien 2,492 0 1 1 2.0
SQL*Net message to client 227,027 0 0 0 183.4
-------------------------------------------------------------
Background Wait Events for DB: IDWPROD1 Instance: idwprod1 Snaps: 3 -21
-> ordered by wait time desc, waits desc (idle events last)

Avg
Total Wait wait Waits
Event Waits Timeouts Time (s) (ms) /txn
---------------------------- ------------ ---------- ---------- ------ --------
log file parallel write 3,837 3,774 19 5 3.1
db file parallel write 265 0 12 47 0.2
control file parallel write 1,067 0 10 10 0.9
db file sequential read 282 0 3 12 0.2
direct path read 1,584 0 2 2 1.3
db file scattered read 78 0 1 19 0.1
direct path write 442 0 1 2 0.4
log file sequential read 46 0 1 15 0.0
async disk IO 66 0 0 6 0.1
enqueue 2 0 0 158 0.0
control file sequential read 945 0 0 0 0.8
log file single write 4 0 0 4 0.0
LGWR wait for redo copy 46 0 0 0 0.0
rdbms ipc reply 30 0 0 0 0.0
log file sync 1 0 0 1 0.0
latch free 2 1 0 0 0.0
rdbms ipc message 13,562 6,727 17,454 1287 11.0
smon timer 10 9 2,947 ###### 0.0
pmon timer 993 993 2,898 2918 0.8

<quote>your soft parse is too low unless you are a data warehouse/mostly reporting system <quote>

Why do you say soft parse is too low? I see from the above report, Soft Parse %: 95.81. Soft parse ratio of 96% is not good for OLTP? Should it be close to 100%?

Also, Execute to Parse %: 71.47 . Should it also be close to 100%?

What is ROT for these stats related to parsing and executions? Thanks.

<quote src=reference manual>
Reviewer: Todd Laubach from Bloomington, MN

Tom,
What is the meaning of the timeouts column in the Wait Events section of the
statspack report?


Followup:
some things try to do something and wait for a fixed amount of time. If no joy
in that time, they "timeout" and perhaps try again or fail. So, for example:


Avg
Total Wait wait Waits
Event Waits Timeouts Time (cs) (ms) /txn
---------------------------- ------------ ---------- ----------- ------ ------
...
rdbms ipc message 215 199 61,260 2849 107.5
...


<quote src=reference manual>
rdbms ipc message

The background processes (LGWR, DBWR, LCK0) use this event to indicate that they
are idle and are waiting for the foreground processes to send them an IPC
message to do some work.

Wait Time: Up to 3 seconds. The parameter timeout shows the true sleep time.
</quote>

so, that just shows the rdbms ipc message wait event happened 215 times during
my statspack -- 199 of them "timed out" (eg: DBWR or someone waited for 3
seconds for something to happen, nothing did so they timed out -- looked around
and seeing nothing important to do, went back and waited again (or did
something) )

<quote src=reference manual>

Then, what does it mean for the other wait events,especially for latch free?

<quote>
Followup:
same thing. same exact thing.
<quote>

something more, more detail

I pray you will not hate me for pasting a big file here.


STATSPACK report for

DB Name DB Id Instance Inst Num Release Cluster Host
------------ ----------- ------------ -------- ----------- ------- ------------
GFWT3 4294401998 gfwt3 1 9.2.0.1.0 NO GEASSM5

Snap Id Snap Time Sessions Curs/Sess Comment
------- ------------------ -------- --------- -------------------
Begin Snap: 12 27-Apr-04 18:14:04 18 6.2
End Snap: 13 27-Apr-04 18:21:32 18 6.2
Elapsed: 7.47 (mins)

Cache Sizes (end)
~~~~~~~~~~~~~~~~~
Buffer Cache: 24M Std Block Size: 8K
Shared Pool Size: 48M Log Buffer: 512K

Load Profile
~~~~~~~~~~~~ Per Second Per Transaction
--------------- ---------------
Redo size: 3,370.18 20,682.74
Logical reads: 159.48 978.71
Block changes: 15.64 95.99
Physical reads: 13.90 85.27
Physical writes: 0.04 0.22
User calls: 5.52 33.86
Parses: 4.30 26.41
Hard parses: 0.12 0.75
Sorts: 1.33 8.15
Logons: 0.00 0.03
Executes: 11.00 67.53
Transactions: 0.16

% Blocks changed per Read: 9.81 Recursive Call %: 92.97
Rollback per transaction %: 20.55 Rows per Sort: 24.31

Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Buffer Nowait %: 100.00 Redo NoWait %: 100.00
Buffer Hit %: 91.29 In-memory Sort %: 100.00
Library Hit %: 97.60 Soft Parse %: 97.15
Execute to Parse %: 60.89 Latch Hit %: 100.00
Parse CPU to Parse Elapsd %: 73.31 % Non-Parse CPU: 82.96

Shared Pool Statistics Begin End
------ ------
Memory Usage %: 49.67 61.13
% SQL with executions>1: 76.87 76.58
% Memory for SQL w/exec>1: 83.38 84.09

Top 5 Timed Events
~~~~~~~~~~~~~~~~~~ % Total
Event Waits Time (s) Ela Time
-------------------------------------------- ------------ ----------- --------
CPU time 78 79.47
db file sequential read 457 7 6.73
db file scattered read 412 6 5.88
log file sync 56 2 2.39
control file sequential read 140 2 1.59
-------------------------------------------------------------
Wait Events for DB: GFWT3 Instance: gfwt3 Snaps: 12 -13
-> s - second
-> cs - centisecond - 100th of a second
-> ms - millisecond - 1000th of a second
-> us - microsecond - 1000000th of a second
-> ordered by wait time desc, waits desc (idle events last)

Avg
Total Wait wait Waits
Event Waits Timeouts Time (s) (ms) /txn
---------------------------- ------------ ---------- ---------- ------ --------
db file sequential read 457 0 7 15 6.3
db file scattered read 412 0 6 14 5.6
log file sync 56 2 2 42 0.8
control file sequential read 140 0 2 11 1.9
enqueue 4 0 2 387 0.1
log file parallel write 679 668 1 2 9.3
control file parallel write 150 0 1 5 2.1
db file parallel write 18 9 0 12 0.2
SQL*Net more data to client 297 0 0 0 4.1
db file single write 2 0 0 1 0.0
latch free 4 0 0 0 0.1
async disk IO 2 0 0 0 0.0
SQL*Net message from client 2,466 0 2,387 968 33.8
virtual circuit status 21 20 601 28606 0.3
wakeup time manager 14 14 387 27651 0.2
SQL*Net message to client 2,466 0 0 0 33.8
-------------------------------------------------------------
Background Wait Events for DB: GFWT3 Instance: gfwt3 Snaps: 12 -13
-> ordered by wait time desc, waits desc (idle events last)

Avg
Total Wait wait Waits
Event Waits Timeouts Time (s) (ms) /txn
---------------------------- ------------ ---------- ---------- ------ --------
log file parallel write 679 668 1 2 9.3
control file sequential read 66 0 1 15 0.9
control file parallel write 146 0 1 5 2.0
db file parallel write 18 9 0 12 0.2
db file scattered read 3 0 0 11 0.0
db file sequential read 1 0 0 9 0.0
rdbms ipc message 1,912 1,201 1,784 933 26.2
smon timer 2 2 614 ###### 0.0
-------------------------------------------------------------
SQL ordered by Gets for DB: GFWT3 Instance: gfwt3 Snaps: 12 -13
-> End Buffer Gets Threshold: 10000
-> Note that resources reported for PL/SQL includes the resources used by
all SQL statements called within the PL/SQL code. As individual SQL
statements are also reported, it is possible and valid for the summed
total % to exceed 100

CPU Elapsd
Buffer Gets Executions Gets per Exec %Total Time (s) Time (s) Hash Value
--------------- ------------ -------------- ------ -------- --------- ----------
20,756 108 192.2 29.1 2.59 4.53 1178035321
select value(p$) from "XDB"."XDB$ELEMENT" as of
snapshot(:2) p$ where SYS_NC_OID$ = :1

10,823 46 235.3 15.1 0.65 0.78 3409793550
select replace(a.name, '"', ''), (case when (c.type# = 123 and
bitand(c.property, 8) = 8 ) then c1.segcol# else c.segcol# end)
from attrcol$ a, obj$ o, col$ c, col$ c1, user$ u where o.obj
# = a.obj# and o.name = :1 and o.obj# = c.obj# and c.intcol# =
a.intcol# and c1.obj#(+) = c.obj# and c1.intcol#(+) = c.intcol#

5,862 2 2,931.0 8.2 1.18 6.62 1794331506
select t.* from lxBO_8f60d65c t where t.lxLocker in (-32220192)

5,836 14 416.9 8.2 21.46 36.18 238087931
select t.schema, t.name, t.flags, q.name from system.aq$_queue_t
ables t, sys.aq$_queue_table_affinities aft, system.aq$_que
ues q where aft.table_objno = t.objno and aft.owner_instance = :
1 and q.table_objno = t.objno and q.usage = 0 and b
itand(t.flags, 4+16+32+64+128+256) = 0 for update of t.name, aft

3,215 1 3,215.0 4.5 2.93 5.52 3376831664
Module: SQL*Plus
BEGIN statspack.snap; END;

2,719 209 13.0 3.8 0.36 0.76 1819073277
select owner#,name,namespace,remoteowner,linkname,p_timestamp,p_
obj#, d_owner#, nvl(property,0),subname from dependency$,obj$ wh
ere d_obj#=:1 and p_obj#=obj#(+) order by order#

2,159 308 7.0 3.0 0.47 0.42 3460529092
select t.name, (select owner_instance from sys.aq$_queue_table_
affinities where table_objno = t.objno) from system.aq$_queue
_tables t where t.name = :1 and t.schema = :2 for update skip lo
cked

2,026 1,013 2.0 2.8 0.43 0.49 2240905169
select * from mxVer6 where mxOid = :va

1,524 209 7.3 2.1 0.26 0.69 4049165760
select order#,columns,types from access$ where d_obj#=:1

1,453 210 6.9 2.0 1.07 4.04 2049294136
select lxType,lxVal from lxString_8f60d65c where lxOid = :va

1,266 422 3.0 1.8 0.22 0.55 4059714361
select type#,blocks,extents,minexts,maxexts,extsize,extpct,user#
,iniexts,NVL(lists,65535),NVL(groups,65535),cachehint,hwmincr, N
VL(spare1,0) from seg$ where ts#=:1 and file#=:2 and block#=:3

SQL ordered by Gets for DB: GFWT3 Instance: gfwt3 Snaps: 12 -13
-> End Buffer Gets Threshold: 10000
-> Note that resources reported for PL/SQL includes the resources used by
all SQL statements called within the PL/SQL code. As individual SQL
statements are also reported, it is possible and valid for the summed
total % to exceed 100

CPU Elapsd
Buffer Gets Executions Gets per Exec %Total Time (s) Time (s) Hash Value
--------------- ------------ -------------- ------ -------- --------- ----------
1,209 403 3.0 1.7 0.16 0.23 189272129
select o.owner#,o.name,o.namespace,o.remoteowner,o.linkname,o.su
bname,o.dataobj#,o.flags from obj$ o where o.obj#=:1

1,017 307 3.3 1.4 0.19 0.49 589648873
select * from lxBO_8f60d65c where lxOid = :va

450 141 3.2 0.6 0.22 0.29 1604978152
select value(p$) from "XDB"."XDB$ATTRIBUTE" as o
f snapshot(:2) p$ where SYS_NC_OID$ = :1

426 191 2.2 0.6 0.08 0.07 1930240031
select pos#,intcol#,col#,spare1,bo#,spare2 from icol$ where obj#
=:1

381 127 3.0 0.5 0.00 0.11 2591785020
select obj#,type#,ctime,mtime,stime,status,dataobj#,flags,oid$,
spare1, spare2 from obj$ where owner#=:1 and name=:2 and namespa
ce=:3 and(remoteowner=:4 or remoteowner is null and :4 is null)a
nd(linkname=:5 or linkname is null and :5 is null)and(subname=:6
or subname is null and :6 is null)

189 70 2.7 0.3 0.01 0.05 787810128
select /*+ rule */ bucket_cnt, row_cnt, cache_cnt, null_cnt, tim
estamp#, sample_size, minimum, maximum, distcnt, lowval, hival,
density, col#, spare1, spare2, avgcln from hist_head$ where obj#
=:1 and intcol#=:2

172 86 2.0 0.2 0.03 0.06 2963598673
select job, nvl2(last_date, 1, 0) from sys.job$ where (((:1 <= n
ext_date) and (next_date < :2)) or ((last_date is null) and
(next_date < :3))) and (field1 = :4 or (field1 = 0 and 'Y' = :5)
) and (this_date is null) order by next_date, job

115 19 6.1 0.2 0.08 0.08 3844343967
select i.obj#,i.ts#,i.file#,i.block#,i.intcols,i.type#,i.flags,
i.property,i.pctfree$,i.initrans,i.maxtrans,i.blevel,i.leafcnt,i
.distkey, i.lblkkey,i.dblkkey,i.clufac,i.cols,i.analyzetime,i.sa
mplesize,i.dataobj#, nvl(i.degree,1),nvl(i.instances,1),i.rowcnt
,mod(i.pctthres$,256),i.indmethod#,i.trunccnt,nvl(c.unicols,0),n

88 22 4.0 0.1 0.00 0.04 2085632044
select intcol#,nvl(pos#,0),col# from ccol$ where con#=:1

86 86 1.0 0.1 0.00 0.03 2964743345
select count(*) from sys.job$ where (next_date > sysdate) and (n
ext_date < (sysdate+5/86400))

85 25 3.4 0.1 0.02 0.09 3680293972
select ts#,file#,block#,nvl(bobj#,0),nvl(tab#,0),intcols,nvl(clu
SQL ordered by Gets for DB: GFWT3 Instance: gfwt3 Snaps: 12 -13
-> End Buffer Gets Threshold: 10000
-> Note that resources reported for PL/SQL includes the resources used by
all SQL statements called within the PL/SQL code. As individual SQL
statements are also reported, it is possible and valid for the summed
total % to exceed 100

CPU Elapsd
Buffer Gets Executions Gets per Exec %Total Time (s) Time (s) Hash Value
--------------- ------------ -------------- ------ -------- --------- ----------
cols,0),audit$,flags,pctfree$,pctused$,initrans,maxtrans,rowcnt,
blkcnt,empcnt,avgspc,chncnt,avgrln,analyzetime, samplesize,cols,
property,nvl(degree,1),nvl(instances,1),avgspc_flb,flbcnt,kernel
cols,nvl(trigflag, 0),nvl(spare1,0),nvl(spare2,0),spare4,spare6

81 19 4.3 0.1 0.04 0.07 2385919346
select name,intcol#,segcol#,type#,length,nvl(precision#,0),decod
e(type#,2,nvl(scale,-127/*MAXSB1MINAL*/),178,scale,179,scale,180
,scale,181,scale,182,scale,183,scale,231,scale,0),null$,fixedsto
rage,nvl(deflength,0),default$,rowid,col#,property, nvl(charseti

-------------------------------------------------------------
SQL ordered by Reads for DB: GFWT3 Instance: gfwt3 Snaps: 12 -13
-> End Disk Reads Threshold: 1000

CPU Elapsd
Physical Reads Executions Reads per Exec %Total Time (s) Time (s) Hash Value
--------------- ------------ -------------- ------ -------- --------- ----------
5,766 2 2,883.0 92.6 1.18 6.62 1794331506
select t.* from lxBO_8f60d65c t where t.lxLocker in (-32220192)

41 209 0.2 0.7 0.36 0.76 1819073277
select owner#,name,namespace,remoteowner,linkname,p_timestamp,p_
obj#, d_owner#, nvl(property,0),subname from dependency$,obj$ wh
ere d_obj#=:1 and p_obj#=obj#(+) order by order#

41 209 0.2 0.7 0.26 0.69 4049165760
select order#,columns,types from access$ where d_obj#=:1

33 210 0.2 0.5 1.07 4.04 2049294136
select lxType,lxVal from lxString_8f60d65c where lxOid = :va

28 1 28.0 0.4 2.93 5.52 3376831664
Module: SQL*Plus
BEGIN statspack.snap; END;

22 422 0.1 0.4 0.22 0.55 4059714361
select type#,blocks,extents,minexts,maxexts,extsize,extpct,user#
,iniexts,NVL(lists,65535),NVL(groups,65535),cachehint,hwmincr, N
VL(spare1,0) from seg$ where ts#=:1 and file#=:2 and block#=:3

14 307 0.0 0.2 0.19 0.49 589648873
select * from lxBO_8f60d65c where lxOid = :va

12 108 0.1 0.2 2.59 4.53 1178035321
select value(p$) from "XDB"."XDB$ELEMENT" as of
snapshot(:2) p$ where SYS_NC_OID$ = :1

11 46 0.2 0.2 0.65 0.78 3409793550
select replace(a.name, '"', ''), (case when (c.type# = 123 and
bitand(c.property, 8) = 8 ) then c1.segcol# else c.segcol# end)
from attrcol$ a, obj$ o, col$ c, col$ c1, user$ u where o.obj
# = a.obj# and o.name = :1 and o.obj# = c.obj# and c.intcol# =
a.intcol# and c1.obj#(+) = c.obj# and c1.intcol#(+) = c.intcol#

7 403 0.0 0.1 0.16 0.23 189272129
select o.owner#,o.name,o.namespace,o.remoteowner,o.linkname,o.su
bname,o.dataobj#,o.flags from obj$ o where o.obj#=:1

7 25 0.3 0.1 0.02 0.09 3680293972
select ts#,file#,block#,nvl(bobj#,0),nvl(tab#,0),intcols,nvl(clu
cols,0),audit$,flags,pctfree$,pctused$,initrans,maxtrans,rowcnt,
blkcnt,empcnt,avgspc,chncnt,avgrln,analyzetime, samplesize,cols,
property,nvl(degree,1),nvl(instances,1),avgspc_flb,flbcnt,kernel
cols,nvl(trigflag, 0),nvl(spare1,0),nvl(spare2,0),spare4,spare6

6 127 0.0 0.1 0.00 0.11 2591785020
select obj#,type#,ctime,mtime,stime,status,dataobj#,flags,oid$,
spare1, spare2 from obj$ where owner#=:1 and name=:2 and namespa
ce=:3 and(remoteowner=:4 or remoteowner is null and :4 is null)a
nd(linkname=:5 or linkname is null and :5 is null)and(subname=:6
or subname is null and :6 is null)
SQL ordered by Reads for DB: GFWT3 Instance: gfwt3 Snaps: 12 -13
-> End Disk Reads Threshold: 1000

CPU Elapsd
Physical Reads Executions Reads per Exec %Total Time (s) Time (s) Hash Value
--------------- ------------ -------------- ------ -------- --------- ----------

5 14 0.4 0.1 0.04 0.07 1453445442
select col#, grantee#, privilege#,max(mod(nvl(option$,0),2)) fro
m objauth$ where obj#=:1 and col# is not null group by privilege
#, col#, grantee# order by col#, grantee#

4 141 0.0 0.1 0.22 0.29 1604978152
select value(p$) from "XDB"."XDB$ATTRIBUTE" as o
f snapshot(:2) p$ where SYS_NC_OID$ = :1

3 19 0.2 0.0 0.08 0.08 3844343967
select i.obj#,i.ts#,i.file#,i.block#,i.intcols,i.type#,i.flags,
i.property,i.pctfree$,i.initrans,i.maxtrans,i.blevel,i.leafcnt,i
.distkey, i.lblkkey,i.dblkkey,i.clufac,i.cols,i.analyzetime,i.sa
mplesize,i.dataobj#, nvl(i.degree,1),nvl(i.instances,1),i.rowcnt
,mod(i.pctthres$,256),i.indmethod#,i.trunccnt,nvl(c.unicols,0),n

2 16 0.1 0.0 0.02 0.03 931956286
s

contd ...

looking at the above, ones - please let me know where i need to tune.

thanks for you time

Tom,

Can you tell me, how to read this advisory part from statspack.

Shared Pool Advisory for DB: GFWT3 Instance: gfwt3 End Snap: 20
-> Note there is often a 1:Many correlation between a single logical object
in the Library Cache, and the physical number of memory objects associated
with it. Therefore comparing the number of Lib Cache objects (e.g. in
v$librarycache), with the number of Lib Cache Memory Objects is invalid

Estd
Shared Pool SP Estd Estd Estd Lib LC Time
Size for Size Lib Cache Lib Cache Cache Time Saved Estd Lib Cache
Estim (M) Factr Size (M) Mem Obj Saved (s) Factr Mem Obj Hits
----------- ----- ---------- ------------ ------------ ------- ---------------
24 .5 24 4,376 259,196 1.0 274,257
32 .7 31 5,218 259,425 1.0 274,682
40 .8 38 6,441 259,494 1.0 274,885
48 1.0 45 7,892 259,516 1.0 275,016
56 1.2 52 9,245 259,566 1.0 275,103
64 1.3 59 10,309 259,574 1.0 275,142
72 1.5 66 11,385 259,587 1.0 275,167
80 1.7 73 12,471 259,594 1.0 275,234
88 1.8 80 13,500 259,670 1.0 275,283
96 2.0 87 14,094 259,748 1.0 275,377
-------------------------------------------------------------


PGA Memory Advisory for DB: GFWT3 Instance: gfwt3 End Snap: 20
-> When using Auto Memory Mgmt, minimally choose a pga_aggregate_target value
where Estd PGA Overalloc Count is 0

Estd Extra Estd PGA Estd PGA
PGA Target Size W/A MB W/A MB Read/ Cache Overalloc
Est (MB) Factr Processed Written to Disk Hit % Count
---------- ------- ---------------- ---------------- -------- ----------
12 0.5 4,197.1 5,993.0 41.0 1,311
18 0.8 4,197.1 2,352.2 64.0 2
24 1.0 4,197.1 151.4 97.0 2
29 1.2 4,197.1 95.2 98.0 0
34 1.4 4,197.1 90.7 98.0 0
38 1.6 4,197.1 90.7 98.0 0
43 1.8 4,197.1 75.9 98.0 0
48 2.0 4,197.1 73.8 98.0 0
72 3.0 4,197.1 37.2 99.0 0
96 4.0 4,197.1 25.3 99.0 0
144 6.0 4,197.1 20.2 100.0 0
192 8.0 4,197.1 12.2 100.0 0
-------------------------------------------------------------


Buffer Pool Advisory for DB: GFWT3 Instance: gfwt3 End Snap: 20
-> Only rows with estimated physical reads >0 are displayed
-> ordered by Block Size, Buffers For Estimate

Size for Size Buffers for Est Physical Estimated
P Estimate (M) Factr Estimate Read Factor Physical Reads
--- ------------ ----- ---------------- ------------- ------------------
D 4 .2 500 1.18 523,162
D 8 .3 1,000 1.09 485,603
D 12 .5 1,500 1.06 468,257
D 16 .7 2,000 1.02 454,343
D 20 .8 2,500 1.01 446,228
D 24 1.0 3,000 1.00 443,495
D 28 1.2 3,500 0.81 358,229
D 32 1.3 4,000 0.77 339,266
D 36 1.5 4,500 0.75 330,418
D 40 1.7 5,000 0.74 327,035
D 44 1.8 5,500 0.72 318,953
D 48 2.0 6,000 0.69 306,306
D 52 2.2 6,500 0.67 297,307
D 56 2.3 7,000 0.66 292,508
D 60 2.5 7,500 0.66 291,009
D 64 2.7 8,000 0.65 287,243
D 68 2.8 8,500 0.65 286,076
D 72 3.0 9,000 0.64 285,943
D 76 3.2 9,500 0.64 285,810
D 80 3.3 10,000 0.64 284,810
-------------------------------------------------------------



I understood the pga advisory from the below link
</code> http://asktom.oracle.com/pls/asktom/f?p=100:11:::::P11_QUESTION_ID:8759826405304, <code>

PGA Memory Advisory for DB says that setting for 144mb, would be a good value at present - am i correct?

Please let me know, how to interpret the other two.

Thanks a lot

Dear Tom,

Oracle Documentation says that "If an Oracle user process searches the threshold limit of buffers without finding a free buffer, the process stops searching the LRU list and signals the DBW0 background process to write some of the dirty buffers to disk."

In this scenario, what will the wait event user will wait for ? Will the User wait for "FREE BUFFER WAIT" wait event ?
If yes, then can there be any more wait events in such scenario.

Please let me know.

Regards
Vivek

Tom

what is the significance of this section of the statspack report ? I have a particular set of queries, that dont use bind variables (yet), and which get repeated many times.
However, the queries only really show up under this section of the statspack report with a Sharable Mem (b) of something like 2,615,365 - what is it telling me ?

Thanks

Hi Tom,

Here is a part of a statspack report.

Top 10 Timed Events
~~~~~~~~~~~~~~~~~~ % Total
Event Waits Time (s) Ela Time
-------------------------------------------- ------------ ----------- --------
CPU time 105,258 53.35
db file sequential read 5,191,346 49,021 24.84
db file scattered read 529,410 16,307 8.26
PX Deq: Execute Reply 8,762 6,811 3.45
rdbms ipc reply 5,024 4,009 2.03
buffer busy waits 400,272 3,528 1.79
db file parallel write 66,689 3,257 1.65
direct path write 48,098 1,545 .78
log file sync 73,772 1,499 .76
log file parallel write 181,864 1,377 .70
-------------------------------------------------------------

How should I interpret the event "CPU time"?

Thanks,

Sven

There is a production database implemented with statspack, which is scheduled every 30 minutes to take snapshot. It is just there no matter whether there is any performance issue or not. Yes, they do data purge on data under perfstat schema. But still, I don't think it is the right way to use statspack, as it is really geared towards for performance tunning. Tom, What is your thought about this?

Thanks, as always.

Yes you are right that STATSPACK need point to compare from 'bad' to 'good'. I am just wondering why not keep one or two or more, say about 10 snapshots during normal working day under regular circumstances (refresh those baseline at somepoint, of course), then stop it, and recollect if there is any issues raised.

I come from the overall picture about the performance burden on the database for this snapshot taken so frequently. For 200GB database, it may not be a big problem. What if I have terabytes database and consistently have data loads around 24 hours with daily volumn about 17mm records ( we do have one like that)?

What I try to seek is how to use it wisely instead of just schedule it every 15 or 30 minutes all the time.

It will be curious to know how 10G absorbs the performance burden itself. 10G OEM shows those statistics so I assume it is collected automatically.

Thanks!

Hi Tom,
Is it OK for me to have timed_statistics = true all the
time at the system level in my production database server?
Can I just set timed_statistics = true in my init.ora file
and is there any overhead incurred as such by this.
Or should I just do alter system set timed_statistics = true.
Actuall I wany the miniotim, maxiowtm etc from v$filestat
but I,m getting all 0 because of timing being off.
Please suggest..
Regards,
RD.

You mean through
alter system set timed_statistics= true;

or

timed_statistics=true in the init.ora.

The database is oracle8i.

Thanks lots,
RD.

Hi tom,
In my 9.2.0.1.0 dbms_jobs running very slow.
Moreover job wokq parent latch misses reached 100% and system has very poor response.pls check this report..
Cache Sizes (end)
~~~~~~~~~~~~~~~~~
Buffer Cache: 704M Std Block Size: 8K
Shared Pool Size: 704M Log Buffer: 512K

Load Profile
~~~~~~~~~~~~ Per Second Per Transaction
--------------- ---------------
Redo size: 6,965.56 7,300.12
Logical reads: 33,096.49 34,686.13
Block changes: 41.93 43.94
Physical reads: 1,627.23 1,705.39
Physical writes: 2.89 3.03
User calls: 65.60 68.75
Parses: 8.88 9.31
Hard parses: 2.68 2.81
Sorts: 5.36 5.61
Logons: 0.03 0.03
Executes: 17.46 18.30
Transactions: 0.95

% Blocks changed per Read: 0.13 Recursive Call %: 35.23
Rollback per transaction %: 0.05 Rows per Sort: 2045.55


Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Buffer Nowait %: 100.00 Redo NoWait %: 100.00
Buffer Hit %: 95.09 In-memory Sort %: 99.98
Library Hit %: 91.04 Soft Parse %: 69.80
Execute to Parse %: 49.13 Latch Hit %: 99.96
Parse CPU to Parse Elapsd %: 96.32 % Non-Parse CPU: 97.84

Shared Pool Statistics Begin End
------ ------
Memory Usage %: 7.63 21.35
% SQL with executions>1: 54.34 30.13
% Memory for SQL w/exec>1: 49.47 36.91

Top 5 Timed Events
~~~~~~~~~~~~~~~~~~ % Total
Event Waits Time (s) Ela Time
-------------------------------------------- ------------ ----------- --------
CPU time 631 60.10
db file sequential read 713,317 338 32.16
db file scattered read 540,932 37 3.50
log file sync 1,361 30 2.83
buffer busy waits 2,736 8 .78
-------------------------------------------------------------
Event Waits Timeouts Time (s) (ms) /txn
---------------------------- ------------ ---------- ---------- ------ --------
db file sequential read 713,317 0 338 0 385.0
db file scattered read 540,932 0 37 0 291.9
log file sync 1,361 13 30 22 0.7
buffer busy waits 2,736 0 8 3 1.5
enqueue 1 0 3 2549 0.0
control file parallel write 632 0 2 4 0.3
process startup 27 0 1 31 0.0
latch free 45 36 1 16 0.0
SQL*Net break/reset to clien 368 0 0 0 0.2
log file parallel write 1,826 1,826 0 0 1.0
control file sequential read 468 0 0 0 0.3
db file parallel read 17 0 0 0 0.0
SQL*Net more data to client 48 0 0 0 0.0
db file parallel write 212 105 0 0 0.1
direct path read 88 0 0 0 0.0
LGWR wait for redo copy 10 0 0 0 0.0
direct path write 8 0 0 0 0.0
SQL*Net message from client 127,586 0 49,108 385 68.9
virtual circuit status 65 65 1,912 29413 0.0
wakeup time manager 62 62 1,860 30000 0.0
jobq slave wait 615 588 1,813 2948 0.3
SQL*Net message to client 127,595 0 0 0 68.9
SQL*Net more data from clien 29 0 0 0 0.0
-------------------------------------------------------------

-----------

Latch Activity for DB: RFES Instance: RFES Snaps: 23 -24
->"Get Requests", "Pct Get Miss" and "Avg Slps/Miss" are statistics for
willing-to-wait latch get requests
->"NoWait Requests", "Pct NoWait Miss" are for no-wait latch get requests
->"Pct Misses" for both should be very close to 0.0

Pct Avg Wait Pct
Get Get Slps Time NoWait NoWait
Latch Requests Miss /Miss (s) Requests Miss
------------------------ -------------- ------ ------ ------ ------------ ------
Consistent RBA 1,826 0.0 0 0
FIB s.o chain latch 12 0.0 0 0
FOB s.o list latch 435 0.0 0 0
SQL memory manager latch 1 0.0 0 632 0.0
SQL memory manager worka 45,087 0.0 0 0
active checkpoint queue 1,433 0.0 0 0
archive control 65 0.0 0 0
archive process latch 38 0.0 0 0
cache buffer handles 2,449 0.0 0 0
cache buffers chains 80,404,966 0.0 0.0 0 6,196,228 0.0
cache buffers lru chain 11,647,997 0.3 0.0 0 3,157,442 0.5
channel handle pool latc 67 0.0 0 0
channel operations paren 1,433 0.0 0 0
checkpoint queue latch 68,620 0.0 0 7,511 0.0
child cursor hash table 37,405 0.0 0 0
commit callback allocati 118 0.0 0 0
dml lock allocation 11,485 0.0 0 0
dummy allocation 85 0.0 0 0
enqueue hash chains 23,953 0.0 0.0 0 0
enqueues 15,427 0.0 0 0
event group latch 40 0.0 0 0
file number translation 28,807 0.0 0 0
hash table column usage 88 0.0 0 325,734 0.0
job workq parent latch 3 100.0 0.0 0 18 66.7
job_queue_processes para 59 0.0 0 0
ktm global data 9 0.0 0 0
kwqit: protect wakeup ti 62 0.0 0 0
lgwr LWN SCN 1,916 0.0 0 0
library cache 372,133 0.0 0.0 0 0
library cache load lock 334 0.0 0 0
library cache pin 197,767 0.0 0.0 0 0
library cache pin alloca 90,828 0.0 0 0
list of block allocation 584 0.0 0 0
loader state object free 12 0.0 0 0
messages 19,776 0.0 0 0
mostly latch-free SCN 1,913 0.0 0 0
multiblock read objects 2,359,404 0.2 0.0 0 0
ncodef allocation latch 31 0.0 0 0
object stats modificatio 41 0.0 0 0
post/wait queue 3,675 0.0 0 1,360 0.0
process allocation 40 0.0 0 40 0.0
process group creation 67 0.0 0 0
redo allocation 44,631 0.0 0.3 0 0
redo copy 0 0 40,896 0.0
redo writing 6,413 0.0 0 0
row cache enqueue latch 362,648 0.0 0.0 0 0
row cache objects 371,816 0.0 0.0 0 0
sequence cache 24,545 0.0 0 0
session allocation 41,066 0.0 0 0
session idle bit 265,263 0.0 0.0 0 0

Latch Activity for DB: RFES Instance: RFES Snaps: 23 -24
->"Get Requests", "Pct Get Miss" and "Avg Slps/Miss" are statistics for
willing-to-wait latch get requests
->"NoWait Requests", "Pct NoWait Miss" are for no-wait latch get requests
->"Pct Misses" for both should be very close to 0.0

Pct Avg Wait Pct
Get Get Slps Time NoWait NoWait
Latch Requests Miss /Miss (s) Requests Miss
------------------------ -------------- ------ ------ ------ ------------ ------
session switching 31 0.0 0 0
session timer 653 0.0 0 0
shared pool 261,370 0.0 0.0 0 0
sim partition latch 0 0 391 0.0
simulator hash latch 4,329,281 0.0 0.0 0 0
simulator lru latch 271,705 0.0 0.0 0 27,173 0.3
sort extent pool 432 0.0 0 0
temporary table state ob 17 0.0 0 0
trace latch 11 0.0 0 0
transaction allocation 2,146,577 0.0 0 0
transaction branch alloc 31 0.0 0 0
undo global data 30,624 0.0 0 0
user lock 44 0.0 0 0
-------------------------------------------------------------

Thanks in advance for your great suggestion.

Tom,
There were top 2 sql statements show in the statspack shown as following.

The first one (hash value 2648878192) is an anonymous block,
which has the sql shown in the second one (hash value 4159474552).

My question is that does the stats shown for the first one include the second one?
the 98 million logical reads includes the 44 million logical reads?

Thank you

Sean


Buffer Gets Executions Gets per Exec % Total Hash Value
--------------- ------------ -------------- ------- ------------
98,382,897 35 2,810,939.9 51.0 2648878192
DECLARE g_error_rows number; CURSOR project_stg_cur IS
select distinct project_id, p
roject_number, work_item_name, wi_de
scription, wi_resp_emp_no, wi_receiv
e_by_org, wi_start_date, wi_end_date

44,061,595 4,898,479 9.0 22.9 4159474552
SELECT PT.TASK_ID,PT.PROJECT_ID,PT.TASK_NUMBER,PT.TASK_NAME,SUBS
TR(PT.TASK_NUMBER || '-' || PT.DESCRIPTION ,1,50) || ' [' || P
A.SEGMENT1 || ']' WI_NAME,NVL(PT.DESCRIPTION,PT.TASK_NAME) DES
CRIPTION,NVL(PT.START_DATE,PA.START_DATE) START_DATE,DECODE(PA.P
ROJECT_STATUS_CODE,'CLOSED',NVL(PA.CLOSED_DATE,NVL(PA.COMPLETION

Tom,
it's 8.1.7.4.
I knew it's not the query performing bad , rather than the code algorithm. But I had the question for statspack. Can you help to anwser it?
thanks,

Sean

i wnat to know the what is the begin snap and end snap regarding STATSPACK

In the statspack report, when I read "SQL ordered by Gets" and "SQL ordered by Reads" part, I found that there is one sql statement which appeared in both these two parts (4 in gets, 4 in reads), and they have four different hash values:
SQL ordered by Gets for DB:

Buffer Gets Executes per Exec Total Hash Value
-------------- ------------ ------------ ------ ------------
SQL statement
------------------------------------------------------------------------------
4,462,687 4 1,115,671.8 8.4 3694596621
select cust.cust_id,cust.cust_name,e_order.col_date,e_order.order_id,e_order

2,295,324 2 1,147,662.0 4.3 814329019
select cust.cust_id,cust.cust_name,e_order.col_date,e_order.order_id,e_order

2,238,365 2 1,119,182.5 4.2 3426503349
select cust.cust_id,cust.cust_name,e_order.col_date,e_order.order_id,e_order

2,237,595 2 1,118,797.5 4.2 2206546509
select cust.cust_id,cust.cust_name,e_order.col_date,e_order.order_id,e_order

SQL ordered by Reads for DB:

Physical Reads % of
Reads Executes per Exec Total Hash Value
-------------- ------------ ------------ ------ ------------
SQL statement
------------------------------------------------------------------------------
188,199 4 47,049.8 10.4 3694596621
select cust.cust_id,cust.cust_name,e_order.col_date,e_order.order_id,e_order

96,641 2 48,320.5 5.3 814329019
select cust.cust_id,cust.cust_name,e_order.col_date,e_order.order_id,e_order

94,955 2 47,477.5 5.2 2206546509
select cust.cust_id,cust.cust_name,e_order.col_date,e_order.order_id,e_order

94,615 2 47,307.5 5.2 3426503349
select cust.cust_id,cust.cust_name,e_order.col_date,e_order.order_id,e_order

My time interval for two snaps is 15 minutes.

Does this mean that this sql statement was age-out from shared pool, so that Oracle "think" that these are four different statements?

Thanks a lot!

you are only seeing a bit of the sql statement, it differs out further.  these are 4 unique sql statements.

peek at the other v$sql* tables to see the entire sql statement.

for example, i use this (you can use hash instead)

 37          for y in ( select sql_text
 38                       from v$sqltext_with_newlines
 39                      where address = x.sql_address
 40                                       order by piece )
 41          loop
 42                     p( y.sql_text );
 43          end loop;
 44
 45      end loop;
 46* end;
ops$ora9ir2@ORA9IR2> desc v$sqltext_with_newlines
 Name                                     Null?    Type
 ---------------------------------------- -------- ----------------------------
 ADDRESS                                           RAW(4)
 HASH_VALUE                                        NUMBER
 COMMAND_TYPE                                      NUMBER
 PIECE                                             NUMBER
 SQL_TEXT                                          VARCHAR2(64)
 

hi tom

this is statspack output my clients db is having

Top 5 Wait Events
~~~~~~~~~~~~~~~~~ Wait % Total
Event Waits Time (cs) Wt Time
-------------------------------------------- ------------ ------------ -------
queue messages 1,807 1,626,378 77.74
SQL*Net message from dblink 23,905 221,286 10.58
PL/SQL lock timer 162 82,607 3.95
direct path write 33,682 44,383 2.12
db file scattered read 1,092,520 39,003 1.86
-------------------------------------------------------------
Wait Events for DB: PROD Instance: PROD Snaps: 1456 -1457
-> cs - centisecond - 100th of a second
-> ms - millisecond - 1000th of a second
-> ordered by wait time desc, waits desc (idle events last)

Avg
Total Wait wait Waits
Event Waits Timeouts Time (cs) (ms) /txn
---------------------------- ------------ ---------- ----------- ------ ------
queue messages 1,807 1,794 1,626,378 9000 0.4
SQL*Net message from dblink 23,905 0 221,286 93 5.5
direct path write 33,682 0 44,383 13 7.8
db file scattered read 1,092,520 0 39,003 0 252.0
pipe put 241 232 23,871 990 0.1

this is db vesion and they are running apps db on it
Oracle8i Enterprise Edition Release 8.1.7.4.0 - Production
With the Partitioning option
JServer Release 8.1.7.4.0 - Production

how can i made queue messaging less in db

87082 0 0 0 0 0
87081 0 0 0 0 0
165704 0 0 0 0 0
165709 0 0 0 0 0
87094 0 0 0 0 0
165711 0 0 0 0 0
87097 0 0 0 0 0
87096 0 0 0 0 0
95118 0 0 132040 2.3954E+12 18141623.2
95120 0 0 0 0 0
108816 0 0 0 0 0
108817 0 0 0 0 0
172875 0 0 0 0 0
172877 0 0 0 0 0
172889 0 0 0 0 0
172891 0 0 0 0 0
173143 0 0 0 0 0
173145 0 0 0 0 0
173278 0 0 0 0 0
173280 0 0 0 0 0
173296 0 0 0 0 0
173298 0 140564 0 1.7415E+11 1238943.83
173581 0 0 0 0 0
173583 0 0 0 0 0
173595 0 0 0 0 0
173597 0 0 0 0 0
173609 0 0 0 0 0
173613 0 0 0 0 0
173627 0 0 0 0 0
173629 0 0 0 0 0
173641 0 0 0 0 0
173643 0 571185 0 1.4772E+13 25862216.2
173660 0 0 0 0 0
173662 0 0 0 0 0
187898 0 0 0 0 0
187906 0 0 0 0 0
187908 0 0 0 0 0
187909 0 0 0 0 0
195799 0 0 29 1414615215 48779835
195815 0 0 40 2023980895 50599522.4
195820 0 0 0 0 0
195821 0 0 0 0 0
222708 0 0 0 0 0
222710 0 0 0 0 0
105 rows selected.

Well, on the version 8.1.6, there is no v$sql_with_newlines view. :(

I've checked v$sql with these different hash values, and I got the same sql text... that's why I'm confuse about it.

Any idea about "different hash value with the same sql statement"? Or, if I got different hash value, it means different sql statements for sure?

Thanks.

ops$tkyte@ORA815> desc v$sqltext_with_newlines;
 Name                                     Null?    Type
 ---------------------------------------- -------- ----------------------------
 ADDRESS                                           RAW(4)
 HASH_VALUE                                        NUMBER
 COMMAND_TYPE                                      NUMBER
 PIECE                                             NUMBER
 SQL_TEXT                                          VARCHAR2(64)
 


v$sqlTEXT_with_newlines

it is there.  the different hashes are for DIFFERENT sql 

Cindy, there is a typo in the view name.

I got it.
Thanks a lot! :)

I see negative value for Buffer Hit in statspack. What does this indicate. Is bufferpool too low. The buffer cache size is 700M now.

Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Buffer Nowait %: 100.00 Redo NoWait %: 100.00
Buffer Hit %: -23.76 In-memory Sort %: 99.87
Library Hit %: 95.46 Soft Parse %: 63.60
Execute to Parse %: 9.53 Latch Hit %: 99.97
Parse CPU to Parse Elapsd %: 97.15 % Non-Parse CPU: 99.91

hi again,

it has been almost 2 months that our team has been daily running statspack reports and rewriting queries topping at each of the sections:
SQL ordered by Gets
SQL ordered by Reads
and
SQL ordered by Executions


but still, the Efficiency percentages are still "alarming", below an extract from an 15 mins snap at a peak hour!
========================================================

STATSPACK report for

DB Name DB Id Instance Inst Num Release OPS Host
____________ ___________ ____________ ________ ___________ ___ ____________
MYDB 2076546630 mydb 1 8.1.7.4.0 NO slx1

Snap Id Snap Time Sessions
------- ------------------ --------
Begin Snap: 1451 20-Jul-05 08:44:19 997
End Snap: 1452 20-Jul-05 08:59:13 997
Elapsed: 14.90 (mins)

Cache Sizes
~~~~~~~~~~~
db_block_buffers: 100000 log_buffer: 2097152
db_block_size: 8192 shared_pool_size: 419430400

Load Profile
~~~~~~~~~~~~ Per Second Per Transaction
--------------- ---------------
Redo size: 23,555.16 7,194.50
Logical reads: 26,067.36 7,961.81
Block changes: 148.90 45.48
Physical reads: 398.95 121.85
Physical writes: 43.89 13.41
User calls: 1,518.13 463.69
Parses: 184.76 56.43
Hard parses: 2.71 0.83
Sorts: 129.84 39.66
Logons: 0.86 0.26
Executes: 530.77 162.11
Transactions: 3.27

% Blocks changed per Read: 0.57 Recursive Call %: 28.30
Rollback per transaction %: 28.83 Rows per Sort: 42.58

Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Buffer Nowait %: 100.00 Redo NoWait %: 100.00
Buffer Hit %: 98.47 In-memory Sort %: 99.99
Library Hit %: 99.22 Soft Parse %: 98.53
Execute to Parse %: 65.19 Latch Hit %: 99.98
Parse CPU to Parse Elapsd %: 3.39 % Non-Parse CPU: 97.72

Shared Pool Statistics Begin End
------ ------
Memory Usage %: 81.97 88.43
% SQL with executions>1: 86.31 84.22
% Memory for SQL w/exec>1: 69.93 67.78

Top 5 Wait Events
~~~~~~~~~~~~~~~~~ Wait % Total
Event Waits Time (cs) Wt Time
____________________________________________ ____________ ____________ _______
latch free 21,955 113,772 72.61
db file sequential read 45,861 19,250 12.28
db file scattered read 13,667 11,588 7.40
PX Deq: Execute Reply 502 3,343 2.13
log file sync 2,085 1,876 1.20
-------------------------------------------------------------
...

what are the best practices in this tool to pinpoint potential bottlenecks?

regards
yogeeraj

Hi again!

thank you for your invaluable reply.

<quote>
Only the application can parse less often
</quote>

Do you mean that i should review my priority which was to first,

run statspack at different peak periods during the day and analyse and fine-tune the SQLs...

to

to review of applications (mainly forms 6i and reports 6i) and reduce the contentions due to "latches" then focus on the SQL fine-tuning...

thanks
yogeeraj

Tom, above you stated that the cause of a Negative Buffer Cache ratio was that developers were parsing more sql than executions. I don't understand what you mean. Isn't the buffer cache ratio strictly logical vs physical reads?

I'm confused.

Just to be clear:
Developers were parsing more sql than execution causes a negative parse ratio (makes sense).

But could you answer "What causes a negative buffer cache ratio?" (I would assume a flush or database shutdown in between snapshots).

Could you link to a better discussion with the answer?

In response to my own question I found out that a negative buffer cache for my version of the database. I found this on metalink

Note:207708.1
Statspack calculates wrong values for the buffer cache hit ratio in Oracle 8i
(see Note 33883.1). It can result in wrong and even negative values.
This problem has not been backported for any O8.1.x releases since the
correction can be done easily by updating the statspack files.

Hi,

My statspack report shows following execute to parse.

++++++++++++++
Begin Snap: 75 05-Sep-05 08:50:01 19 3.0
End Snap: 77 05-Sep-05 09:07:01 19 3.6
Elapsed: 17.00 (mins)

Cache Sizes (end)
~~~~~~~~~~~~~~~~~
Buffer Cache: 304M Std Block Size: 8K
Shared Pool Size: 464M Log Buffer: 512K

Load Profile
~~~~~~~~~~~~ Per Second Per Transaction
--------------- ---------------
Redo size: 28,962.47 2,873.71
Logical reads: 48,149.56 4,777.49
Block changes: 166.80 16.55
Physical reads: 6.20 0.62
Physical writes: 8.30 0.82
User calls: 92.32 9.16
Parses: 94.15 9.34
Hard parses: 0.01 0.00
Sorts: 16.35 1.62
Logons: 0.03 0.00
Executes: 117.36 11.65
Transactions: 10.08

% Blocks changed per Read: 0.35 Recursive Call %: 75.26
Rollback per transaction %: 0.06 Rows per Sort: 8.85

Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Buffer Nowait %: 100.00 Redo NoWait %: 100.00
Buffer Hit %: 100.00 In-memory Sort %: 100.00
Library Hit %: 99.99 Soft Parse %: 99.99
Execute to Parse %: 19.78 Latch Hit %: 99.98
Parse CPU to Parse Elapsd %: 80.60 % Non-Parse CPU: 98.82

Shared Pool Statistics Begin End
------ ------
Memory Usage %: 6.74 6.88
% SQL with executions>1: 76.16 77.45
% Memory for SQL w/exec>1: 69.66 68.62

++++++++++++++++++++

Is such a low " Execute to Parse %: 19.78" is OK.
If not,why it is causing?

How to interpreet "% SQL with executions>1" and "% Memory for SQL w/exec>1".


Thanks,
Atul

Hi,

On my statspack report i could see 2 top wait events
1)log file sync
2)log file parallel write

Could you kindly help us to reduce these wait events?
I know 1st one is because of commits.
but we can't avoid that as our application has to do commit when one record inserts.
its tibco application


STATSPACK report for

DB Name DB Id Instance Inst Num Release Cluster Host
------------ ----------- ------------ -------- ----------- ------- ------------
VTIBD 1645481651 vtibd 1 9.2.0.6.0 NO svltibd1

Snap Id Snap Time Sessions Curs/Sess Comment
--------- ------------------ -------- --------- -------------------
Begin Snap: 229 08-Sep-05 02:40:01 26 5.0
End Snap: 231 08-Sep-05 03:00:01 36 5.8
Elapsed: 20.00 (mins)

Cache Sizes (end)
~~~~~~~~~~~~~~~~~
Buffer Cache: 160M Std Block Size: 8K
Shared Pool Size: 464M Log Buffer: 512K

Load Profile
~~~~~~~~~~~~ Per Second Per Transaction
--------------- ---------------
Redo size: 55,980.22 3,229.32
Logical reads: 1,221.71 70.48
Block changes: 322.70 18.62
Physical reads: 39.91 2.30
Physical writes: 14.40 0.83
User calls: 166.68 9.62
Parses: 171.53 9.89
Hard parses: 0.01 0.00
Sorts: 29.56 1.70
Logons: 0.04 0.00
Executes: 219.27 12.65
Transactions: 17.34

% Blocks changed per Read: 26.41 Recursive Call %: 75.63
Rollback per transaction %: 0.06 Rows per Sort: 9.20

Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Buffer Nowait %: 99.96 Redo NoWait %: 100.00
Buffer Hit %: 97.55 In-memory Sort %: 100.00
Library Hit %: 100.00 Soft Parse %: 99.99
Execute to Parse %: 21.77 Latch Hit %: 99.79
Parse CPU to Parse Elapsd %: 90.97 % Non-Parse CPU: 90.73

Shared Pool Statistics Begin End
------ ------
Memory Usage %: 13.74 13.91
% SQL with executions>1: 92.24 91.95
% Memory for SQL w/exec>1: 67.04 65.70

Top 5 Timed Events
~~~~~~~~~~~~~~~~~~ % Total
Event Waits Time (s) Ela Time
-------------------------------------------- ------------ ----------- --------
log file sync 24,646 260 31.96
CPU time 225 27.65
log file parallel write 70,227 139 17.12
enqueue 345 88 10.87
direct path write 12,033 56 6.89
-------------------------------------------------------------
^LWait Events for DB: VTIBD Instance: vtibd Snaps: 229 -231
-> s - second
-> cs - centisecond - 100th of a second
-> ms - millisecond - 1000th of a second
-> us - microsecond - 1000000th of a second
-> ordered by wait time desc, waits desc (idle events last)

Avg
Total Wait wait Waits
Event Waits Timeouts Time (s) (ms) /txn
---------------------------- ------------ ---------- ---------- ------ --------
log file sync 24,646 24 260 11 1.2
log file parallel write 70,227 0 139 2 3.4
enqueue 345 4 88 256 0.0
direct path write 12,033 0 56 5 0.6
db file parallel write 538 0 12 23 0.0
db file sequential read 716 0 7 10 0.0
control file parallel write 430 0 6 13 0.0
log file sequential read 112 0 5 45 0.0
direct path read (lob) 11,982 0 5 0 0.6
buffer busy waits 535 0 5 9 0.0
SQL*Net break/reset to clien 14 0 2 110 0.0
local write wait 120 0 1 9 0.0


Thanks,
Atul

Tom,

I have been reading your book to understand statspack report. I read most of your articles on statspack. Unable to figure out how excatly to read the report. Users are reporting the system is very slow at the month end. This report has taken at non peak time. Would you please throgh some light on to understand where and what to look for inorder to identify the problem.

With regards
Prasad.
STATSPACK report for

DB Name DB Id Instance Inst Num Release Cluster Host
------------ ----------- ------------ -------- ----------- ------- ------------
XXX 456268352 XXX 1 9.2.0.5.0 NO XXXXX

Snap Id Snap Time Sessions Curs/Sess Comment
------- ------------------ -------- --------- -------------------
Begin Snap: 22 07-Oct-05 06:26:05 60 125.0
End Snap: 23 07-Oct-05 07:06:23 60 124.9
Elapsed: 40.30 (mins)

Cache Sizes (end)
~~~~~~~~~~~~~~~~~
Buffer Cache: 1,184M Std Block Size: 8K
Shared Pool Size: 768M Log Buffer: 1,024K

Load Profile
~~~~~~~~~~~~ Per Second Per Transaction
--------------- ---------------
Redo size: 5,020.19 8,726.69
Logical reads: 278.69 484.45
Block changes: 15.92 27.67
Physical reads: 40.79 70.90
Physical writes: 2.18 3.79
User calls: 18.50 32.17
Parses: 0.42 0.73
Hard parses: 0.00 0.00
Sorts: 0.24 0.41
Logons: 0.00 0.01
Executes: 17.86 31.04
Transactions: 0.58

% Blocks changed per Read: 5.71 Recursive Call %: 7.10
Rollback per transaction %: 2.30 Rows per Sort: 119.89

Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Buffer Nowait %: 100.00 Redo NoWait %: 99.99
Buffer Hit %: 85.63 In-memory Sort %: 99.83
Library Hit %: 100.00 Soft Parse %: 100.00
Execute to Parse %: 97.66 Latch Hit %: 99.98
Parse CPU to Parse Elapsd %: 130.00 % Non-Parse CPU: 99.59

Shared Pool Statistics Begin End
------ ------
Memory Usage %: 87.91 87.91
% SQL with executions>1: 77.33 77.33
% Memory for SQL w/exec>1: 60.00 60.00

Top 5 Timed Events
~~~~~~~~~~~~~~~~~~ % Total
Event Waits Time (s) Ela Time
-------------------------------------------- ------------ ----------- --------
db file scattered read 12,831 34 26.83
CPU time 32 25.05
db file sequential read 8,222 18 14.42
log file sync 1,392 18 14.24
db file parallel write 115 11 8.61
-------------------------------------------------------------
Wait Events for DB: PR1 Instance: PR1 Snaps: 22 -23
-> s - second
-> cs - centisecond - 100th of a second
-> ms - millisecond - 1000th of a second
-> us - microsecond - 1000000th of a second
-> ordered by wait time desc, waits desc (idle events last)

Avg
Total Wait wait Waits
Event Waits Timeouts Time (s) (ms) /txn
---------------------------- ------------ ---------- ---------- ------ --------
db file scattered read 12,831 0 34 3 9.2
db file sequential read 8,222 0 18 2 5.9
log file sync 1,392 0 18 13 1.0
db file parallel write 115 0 11 96 0.1
control file parallel write 824 0 10 12 0.6
latch free 100 5 2 22 0.1
db file parallel read 10 0 0 33 0.0
SQL*Net more data to client 8,928 0 0 0 6.4
control file sequential read 7,388 0 0 0 5.3
async disk IO 33 0 0 8 0.0
log file switch completion 3 0 0 47 0.0
direct path write 114 0 0 1 0.1
direct path read 344 0 0 0 0.2
SQL*Net break/reset to clien 104 0 0 0 0.1
log file sequential read 26 0 0 2 0.0
log file parallel write 1,429 1,425 0 0 1.0
log file single write 4 0 0 4 0.0
enqueue 4 0 0 4 0.0
buffer busy waits 3 0 0 1 0.0
direct path read (lob) 2 0 0 0 0.0
LGWR wait for redo copy 2 0 0 0 0.0
SQL*Net message from client 44,725 0 31,956 715 32.2
SQL*Net message to client 44,725 0 0 0 32.2
SQL*Net more data from clien 1,021 0 0 0 0.7
-------------------------------------------------------------
Background Wait Events for DB: PR1 Instance: PR1 Snaps: 22 -23
-> ordered by wait time desc, waits desc (idle events last)

Avg
Total Wait wait Waits
Event Waits Timeouts Time (s) (ms) /txn
---------------------------- ------------ ---------- ---------- ------ --------
db file parallel write 115 0 11 96 0.1
control file parallel write 824 0 10 12 0.6
db file scattered read 967 0 1 1 0.7
async disk IO 33 0 0 8 0.0
direct path write 112 0 0 1 0.1
log file sequential read 26 0 0 2 0.0
direct path read 312 0 0 0 0.2
log file parallel write 1,429 1,425 0 0 1.0
log file single write 4 0 0 4 0.0
control file sequential read 638 0 0 0 0.5
db file sequential read 4 0 0 0 0.0
LGWR wait for redo copy 2 0 0 0 0.0
rdbms ipc message 6,351 4,978 13,594 2140 4.6
smon timer 8 8 2,400 ###### 0.0
pmon timer 806 806 2,361 2930 0.6
-------------------------------------------------------------
SQL ordered by Gets for DB: PR1 Instance: PR1 Snaps: 22 -23
-> End Buffer Gets Threshold: 10000
-> Note that resources reported for PL/SQL includes the resources used by
all SQL statements called within the PL/SQL code. As individual SQL
statements are also reported, it is possible and valid for the summed
total % to exceed 100

CPU Elapsd
Buffer Gets Executions Gets per Exec %Total Time (s) Time (s) Hash Value
--------------- ------------ -------------- ------ -------- --------- ----------
129,823 1 129,823.0 19.3 4.41 18.78 2522684317
Module: SQL*Plus
BEGIN statspack.snap; END;

127,584 1 127,584.0 18.9 2.37 2.65 1116368370
Module: SQL*Plus
INSERT INTO STATS$SQLTEXT ( HASH_VALUE , TEXT_SUBSET , PIECE , S
QL_TEXT , ADDRESS , COMMAND_TYPE , LAST_SNAP_ID ) SELECT ST1.HAS
H_VALUE , SS.TEXT_SUBSET , ST1.PIECE , ST1.SQL_TEXT , ST1.ADDRES
S , ST1.COMMAND_TYPE , SS.SNAP_ID FROM V$SQLTEXT ST1 , STATS$SQL
_SUMMARY SS WHERE SS.SNAP_ID = :B3 AND SS.DBID = :B2 AND SS.INST

120,417 3 40,139.0 17.9 0.71 0.69 1940645024
Module: SAPLSDO0
select file_id, sum ( bytes ) from sys.dba_free_space exts group
by file_id

68,070 15 4,538.0 10.1 3.05 3.49 348738309
Module: SAPLARFC
SELECT * FROM "ARFCRSTATE" WHERE "ARFCSTATE" = :A0 OR "ARFCSTATE
" = :A1

37,623 8,313 4.5 5.6 2.00 3.15 2003785878
Module: ZVSOM001
SELECT * FROM "LIPS" WHERE "MANDT" = :A0 AND "VBELN" = :A1

35,065 5 7,013.0 5.2 0.19 0.23 4174032697
Module: SAPLSDH3
SELECT /*+ first_rows */ * FROM "M_ZCDL1" WHERE "MANDT" = :A0 A
ND "ZCDLLNAME" = :A1

Tom, Thank you for your response.

Here is a 4 cpu system with very poor performance, most of the time cpus are 90% busy. I am doubts, could you comment on this:
1. there are too many sof parse due to jdbc calls
2. too many physical reads caused by full table scan(some of the tables don't have primary key, but do have indexes)
3. high rollback per transaction
4. too many latch free waits caused by parse
5. network traffic to client too high

what should I do to tune this system?
Use plsql packages instead of write sql in java to reduce network traffic?

Snap Id Snap Time Sessions Curs/Sess Comment
------- ------------------ -------- --------- -------------------
Begin Snap: 1285 27-Oct-05 14:31:35 141 2.7

End Snap: 1286 27-Oct-05 14:46:31 132 2.8

Elapsed: 14.93 (mins)

Cache Sizes (end)
~~~~~~~~~~~~~~~~~
Buffer Cache: 912M Std Block Size: 8K
Shared Pool Size: 368M Log Buffer: 16,384K

Load Profile
~~~~~~~~~~~~ Per Second Per Transaction
--------------- ---------------
Redo size: 32,904.15 606.19
Logical reads: 54,397.30 1,002.16
Block changes: 150.85 2.78
Physical reads: 1,101.87 20.30
Physical writes: 47.10 0.87
User calls: 1,683.06 31.01
Parses: 268.54 4.95
Hard parses: 0.02 0.00
Sorts: 118.95 2.19
Logons: 1.36 0.03
Executes: 272.16 5.01
Transactions: 54.28

% Blocks changed per Read: 0.28 Recursive Call %: 4.41
Rollback per transaction %: 73.50 Rows per Sort: 172.04

Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Buffer Nowait %: 100.00 Redo NoWait %: 100.00
Buffer Hit %: 98.08 In-memory Sort %: 99.98
Library Hit %: 100.00 Soft Parse %: 99.99
Execute to Parse %: 1.33 Latch Hit %: 99.88
Parse CPU to Parse Elapsd %: 6.10 % Non-Parse CPU: 99.64

Shared Pool Statistics Begin End
------ ------
Memory Usage %: 93.54 93.50
% SQL with executions>1: 94.86 94.83
% Memory for SQL w/exec>1: 93.72 93.69

Top 5 Timed Events
~~~~~~~~~~~~~~~~~~ % Total
Event Waits Time (s) Ela Time
-------------------------------------------- ------------ ----------- --------
CPU time 2,821 37.84
latch free 22,351 1,993 26.73
log file sync 14,464 1,437 19.27
db file sequential read 582,024 1,108 14.86
buffer busy waits 386 28 .38
-------------------------------------------------------------
Avg
Total Wait wait Waits
Event Waits Timeouts Time (s) (ms) /txn
---------------------------- ------------ ---------- ---------- ------ --------
latch free 22,351 15,296 1,993 89 0.5
log file sync 14,464 443 1,437 99 0.3
db file sequential read 582,024 0 1,108 2 12.0
buffer busy waits 386 8 28 73 0.0
SQL*Net more data to client 31,577 0 28 1 0.6
control file parallel write 297 0 16 54 0.0
db file scattered read 119,062 0 14 0 2.4
process startup 30 5 7 226 0.0
log file parallel write 12,306 10,214 2 0 0.3
LGWR wait for redo copy 215 157 2 7 0.0
enqueue 20 0 1 64 0.0
SQL*Net break/reset to clien 8 0 0 27 0.0
direct path read (lob) 22,830 0 0 0 0.5
log file sequential read 23 0 0 2 0.0
control file sequential read 251 0 0 0 0.0
db file parallel write 1,901 0 0 0 0.0
log file switch completion 2 0 0 4 0.0
direct path read 1,049 0 0 0 0.0
slave TJ process wait 1 1 0 4 0.0
log file single write 2 0 0 0 0.0
direct path write (lob) 20 0 0 0 0.0
direct path write 47 0 0 0 0.0
async disk IO 33 0 0 0 0.0
db file parallel read 1 0 0 0 0.0
buffer deadlock 1 1 0 0 0.0
virtual circuit status 589,495 105 12,562 21 12.1
jobq slave wait 44 42 127 2892 0.0
SQL*Net message from client 1,509,001 0 71 0 31.0
SQL*Net message to client 1,509,035 0 10 0 31.0
SQL*Net more data from clien 40 0 0 0 0.0
-------------------------------------------------------------

Execute to Parse %:    1.33 


that is very low. the formula used is:

round(100*(1-:prse/:exe),2) 

that indicates there is no cursor reuse going on AT ALL - like the values are:

ops$tkyte@ORA10GR2> print :exe

       EXE
----------
   1000000

ops$tkyte@ORA10GR2> print :prse

      PRSE
----------
    990000


You can ask the developers to look at:

a lot of your latch frees are likely parse related. 
 

Dear Tom,

Thaks for your last reply. Since last time I have taken the report at non peak time that was no use. Now this report is from peak hours. Trying to learn where and what to look. Please help me out. This will help me a lot in reading these reports in future for me TOM. Your help is greatly appreciated. Last time you mentioned that soft parse 100% that is cool. Now it is 99.01%. Please guide me.

Other question TOM, I was reading your book on performance tuning. Trying to understand when exatly we use autotrace and when do we use tkprof? Because both gives the statistics but tkprof gives timing also is that right?
STATSPACK report for

DB Name DB Id Instance Inst Num Release Cluster Host
------------ ----------- ------------ -------- ----------- ------- ------------
MVA 3433455 MVA 1 9.2.0.5.0 NO mva1

Snap Id Snap Time Sessions Curs/Sess Comment
------- ------------------ -------- --------- -------------------
Begin Snap: 24 02-Nov-05 09:05:32 64 110.8
End Snap: 25 02-Nov-05 09:32:58 65 112.1
Elapsed: 27.43 (mins)

Cache Sizes (end)
~~~~~~~~~~~~~~~~~
Buffer Cache: 1,184M Std Block Size: 8K
Shared Pool Size: 768M Log Buffer: 1,024K

Load Profile
~~~~~~~~~~~~ Per Second Per Transaction
--------------- ---------------
Redo size: 32,742.10 14,360.11
Logical reads: 3,942.13 1,728.95
Block changes: 103.51 45.40
Physical reads: 192.99 84.64
Physical writes: 9.52 4.17
User calls: 120.63 52.90
Parses: 5.48 2.40
Hard parses: 0.05 0.02
Sorts: 1.44 0.63
Logons: 0.02 0.01
Executes: 109.89 48.20
Transactions: 2.28

% Blocks changed per Read: 2.63 Recursive Call %: 8.21
Rollback per transaction %: 0.99 Rows per Sort: 117.02

Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Buffer Nowait %: 100.00 Redo NoWait %: 99.99
Buffer Hit %: 95.18 In-memory Sort %: 99.79
Library Hit %: 99.76 Soft Parse %: 99.01
Execute to Parse %: 95.01 Latch Hit %: 99.89
Parse CPU to Parse Elapsd %: 3.77 % Non-Parse CPU: 95.57

Shared Pool Statistics Begin End
------ ------
Memory Usage %: 68.02 69.94
% SQL with executions>1: 74.40 74.77
% Memory for SQL w/exec>1: 66.44 66.94

Top 5 Timed Events
~~~~~~~~~~~~~~~~~~ % Total
Event Waits Time (s) Ela Time
-------------------------------------------- ------------ ----------- --------
latch free 19,132 2,155 57.48
db file sequential read 114,574 1,114 29.70
CPU time 207 5.51
log file sync 3,753 77 2.05
db file scattered read 29,084 61 1.62
-------------------------------------------------------------
Wait Events for DB: mva Instance: mva Snaps: 24 -25
-> s - second
-> cs - centisecond - 100th of a second
-> ms - millisecond - 1000th of a second
-> us - microsecond - 1000000th of a second
-> ordered by wait time desc, waits desc (idle events last)

Yes your are right TOM. Batch processes runs in the last week of every month. When I chekced these batch processes duration about 20 to 25 minutes. Do you see any problem with wait events or resources? or the batch processes need to be fine tune? Thanks TOM.
Avg
Total Wait wait Waits
Event Waits Timeouts Time (s) (ms) /txn
---------------------------- ------------ ---------- ---------- ------ --------
latch free 19,132 23 2,155 113 5.1
db file sequential read 114,574 0 1,114 10 30.5
log file sync 3,753 10 77 20 1.0
db file scattered read 29,084 0 61 2 7.7
db file parallel write 325 0 43 132 0.1
direct path read (lob) 912 0 23 25 0.2
control file parallel write 640 0 21 34 0.2
enqueue 11 4 19 1712 0.0
SQL*Net more data to client 44,798 0 16 0 11.9
db file parallel read 80 0 5 64 0.0
log file sequential read 78 0 4 52 0.0
log file switch completion 13 0 2 175 0.0
direct path read 717 0 1 2 0.2
direct path write 306 0 0 2 0.1
control file sequential read 2,136 0 0 0 0.6
async disk IO 99 0 0 2 0.0
log file single write 12 0 0 17 0.0
SQL*Net break/reset to clien 274 0 0 1 0.1
log buffer space 3 0 0 38 0.0
log file parallel write 3,815 3,809 0 0 1.0
buffer busy waits 15 0 0 7 0.0
LGWR wait for redo copy 13 4 0 5 0.0
SQL*Net message from client 198,295 0 37,135 187 52.8
SQL*Net more data from clien 8,146 0 0 0 2.2
SQL*Net message to client 198,294 0 0 0 52.8
-------------------------------------------------------------
Background Wait Events for DB: mva Instance: mva Snaps: 24 -25
-> ordered by wait time desc, waits desc (idle events last)

Avg
Total Wait wait Waits
Event Waits Timeouts Time (s) (ms) /txn
---------------------------- ------------ ---------- ---------- ------ --------
db file parallel write 325 0 43 132 0.1
control file parallel write 639 0 21 34 0.2
log file sequential read 78 0 4 52 0.0
db file scattered read 193 0 3 16 0.1
direct path read 672 0 1 2 0.2
direct path write 296 0 0 1 0.1
async disk IO 99 0 0 2 0.0
log file single write 12 0 0 17 0.0
db file sequential read 86 0 0 2 0.0
control file sequential read 630 0 0 0 0.2
log file parallel write 3,815 3,809 0 0 1.0
latch free 4 1 0 23 0.0
enqueue 1 0 0 90 0.0
LGWR wait for redo copy 13 4 0 5 0.0
rdbms ipc message 12,748 8,819 8,069 633 3.4
pmon timer 548 548 1,600 2919 0.1
smon timer 5 5 1,451 ###### 0.0
-------------------------------------------------------------
SQL ordered by Gets for DB: mva Instance: mva Snaps: 24 -25
-> End Buffer Gets Threshold: 10000
-> Note that resources reported for PL/SQL includes the resources used by
all SQL statements called within the PL/SQL code. As individual SQL
statements are also reported, it is possible and valid for the summed
total % to exceed 100

CPU Elapsd
Buffer Gets Executions Gets per Exec %Total Time (s) Time (s) Hash Value
--------------- ------------ -------------- ------ -------- --------- ----------
391,410 5 78,282.0 6.0 5.16 7.69 3901616721
Module: SAPLARCIS_DB_INTERFACE
SELECT * FROM "ZARIXFI002" WHERE "MANDT" = :A0 AND "BUKRS" = :A1
AND "AWTYP" = :A2 AND "AWKEY" = :A3 AND "AWSYS" = :A4

345,786 1 345,786.0 5.3 6.32 6.33 632193686
Module: ImpAdmin.exe
select "c318" "c0" , "c206" "c1" , "c204" "c2" , "c200" "c3" , "
c317" "c4" , "c198" "c5" , "c205" "c6" , "c203" "c7" , "c202" "c
8" , "c201" "c9" , "c199" "c10" , "c193" "c11" , "c178" "c12" ,
"c196" "c13" , "c197" "c14" , "c192" "c15" , "c316" "c16" , "c19
5" "c17" , "c315" "c18" , "c314" "c19" , "c313" "c20" , "c312" "

345,786 1 345,786.0 5.3 6.16 6.16 1179063173
Module: ImpAdmin.exe
select "c311" "c0" , "c199" "c1" , "c197" "c2" , "c193" "c3" , "
c310" "c4" , "c191" "c5" , "c198" "c6" , "c196" "c7" , "c195" "c
8" , "c194" "c9" , "c192" "c10" , "c186" "c11" , "c171" "c12" ,
"c189" "c13" , "c190" "c14" , "c185" "c15" , "c309" "c16" , "c18
8" "c17" , "c308" "c18" , "c307" "c19" , "c306" "c20" , "c305" "

341,266 1 341,266.0 5.3 4.95 5.20 1769707217
Module: ImpAdmin.exe
select "c298" "c0" , "c190" "c1" , "c189" "c2" , "c185" "c3" , "
c297" "c4" , "c183" "c5" , "c188" "c6" , "c187" "c7" , "c186" "c
8" , "c184" "c9" , "c178" "c10" , "c164" "c11" , "c181" "c12" ,
"c182" "c13" , "c177" "c14" , "c296" "c15" , "c180" "c16" , "c29
5" "c17" , "c294" "c18" , "c293" "c19" , "c292" "c20" , "c291" "

160,078 34 4,708.2 2.5 6.38 16.17 348738309
Module: SAPLARFC
SELECT * FROM "ARFCRSTATE" WHERE "ARFCSTATE" = :A0 OR "ARFCSTATE
" = :A1

107,409 3 35,803.0 1.7 5.36 32.47 2519557479
Module: SAPLVKMP
SELECT "WAERK" , "NETWR" , "ERDAT" FROM "VBRKUK" WHERE "MANDT" =
:A0 AND "BUKRS" = :A1 AND "KUNAG" = :A2 AND ( "BUCHK" = :A3 OR
"BUCHK" = :A4 )

99,673 4,981 20.0 1.5 1.19 1.30 1337134973
Module: RADBTDDF
SELECT * FROM "DD04L" WHERE "ROLLNAME" IN ( :A0 , :A1 , :A2 , :A
3 , :A4 ) AND "AS4LOCAL" = :A5

81,620 4,081 20.0 1.3 0.94 0.88 1662467684
Module: RADBTDDF
SELECT * FROM "DD04T" WHERE "ROLLNAME" IN ( :A0 , :A1 , :A2 , :A
3 , :A4 ) AND "DDLANGUAGE" = :A5 AND "AS4LOCAL" = :A6

SQL ordered by Gets for DB: mva Instance: mva Snaps: 24 -25
-> End Buffer Gets Threshold: 10000
-> Note that resources reported for PL/SQL includes the resources used by
all SQL statements called within the PL/SQL code. As individual SQL
statements are also reported, it is possible and valid for the summed
total % to exceed 100

CPU Elapsd
Buffer Gets Executions Gets per Exec %Total Time (s) Time (s) Hash Value
--------------- ------------ -------------- ------ -------- --------- ----------
76,373 1 76,373.0 1.2 5.73 629.78 2522684317
Module: SQL*Plus
BEGIN statspack.snap; END;

68,076 1 68,076.0 1.0 1.26 2.82 1116368370
Module: SQL*Plus
INSERT INTO STATS$SQLTEXT ( HASH_VALUE , TEXT_SUBSET , PIECE , S
QL_TEXT , ADDRESS , COMMAND_TYPE , LAST_SNAP_ID ) SELECT ST1.HAS
H_VALUE , SS.TEXT_SUBSET , ST1.PIECE , ST1.SQL_TEXT , ST1.ADDRES
S , ST1.COMMAND_TYPE , SS.SNAP_ID FROM V$SQLTEXT ST1 , STATS$SQL
_SUMMARY SS WHERE SS.SNAP_ID = :B3 AND SS.DBID = :B2 AND SS.INST

66,818 2 33,409.0 1.0 1.63 143.24 3000445581
Module: ZLSRR015
SELECT "MBLNR" , "MJAHR" , "ZEILE_I" , "BWART_I" , "MATNR_I" , "
WERKS_I" , "LGORT_I" , "CHARG_I" , "SOBKZ_I" , "LIFNR_I" , "KUNN
R_I" , "KDAUF_I" , "SHKZG_I" , "WAERS_I" , "DMBTR_I" , "MENGE_I"
, "MEINS_I" , "ERFMG_I" , "ERFME_I" , "EBELN_I" , "EBELP_I" , "
KOSTL_I" , "AUFNR_I" , "ANLN1_I" , "ANLN2_I" , "BUKRS_I" , "UMWR

64,297 1 64,297.0 1.0 0.45 2.89 2422616607
Module: ZLSRR015
SELECT "MBLNR" , "MJAHR" , "ZEILE_I" , "BWART_I" , "MATNR_I" , "
WERKS_I" , "LGORT_I" , "CHARG_I" , "SOBKZ_I" , "LIFNR_I" , "KUNN
R_I" , "KDAUF_I" , "SHKZG_I" , "WAERS_I" , "DMBTR_I" , "MENGE_I"
, "MEINS_I" , "ERFMG_I" , "ERFME_I" , "EBELN_I" , "EBELP_I" , "
KOSTL_I" , "AUFNR_I" , "ANLN1_I" , "ANLN2_I" , "BUKRS_I" , "UMWR

63,492 3 21,164.0 1.0 0.68 31.80 775574771
Module: ZAPMV50L
SELECT "VBELN" FROM "LIKPUK" WHERE "MANDT" = :A0 AND "VSTEL" = :
A1 AND "WADAT" BETWEEN :A2 AND :A3 AND ( "WBSTK" = :A4 OR "WBSTK
" = :A5 ) AND "VBOBJ" = :A6

45,024 2,991 15.1 0.7 0.56 0.75 3376212751
Module: RADBTDDF
SELECT * FROM "DD01L" WHERE "DOMNAME" IN ( :A0 , :A1 , :A2 , :A3
, :A4 ) AND "AS4LOCAL" = :A5

39,941 1 39,941.0 0.6 0.24 0.24 1940645024
Module: SAPLSDO0
select file_id, sum ( bytes ) from sys.dba_free_space exts group
by file_id

37,218 3 12,406.0 0.6 1.72 10.60 1246726702
Module: SAPLVKMP
SELECT T_00 . "ERDAT" , T_00 . "NETWR" , T_00 . "WAERK" FROM "VB
AK" T_00 , "VBUK" T_01 WHERE ( T_01 . "MANDT" = :A0 AND T_00 . "
VBELN" = T_01 . "VBELN" ) AND T_00 . "MANDT" = :A1 AND T_00 . "V
BTYP" = :A2 AND T_00 . "AUART" = :A3 AND T_00 . "BUKRS_VF" = :A4
SQL ordered by Gets for DB: mva Instance: mva Snaps: 24 -25
-> End Buffer Gets Threshold: 10000
-> Note that resources reported for PL/SQL includes the resources used by
all SQL statements called within the PL/SQL code. As individual SQL
statements are also reported, it is possible and valid for the summed
total % to exceed 100

CPU Elapsd
Buffer Gets Executions Gets per Exec %Total Time (s) Time (s) Hash Value
--------------- ------------ -------------- ------ -------- --------- ----------
AND T_00 . "KUNNR" = :A5 AND ( T_01 . "FKSAK" = :A6 OR T_01 . "

35,890 598 60.0 0.6 0.63 2.51 1235747925
Module: SAPLABRA
SELECT "MANDT" , "BUKRS" , "ANLN1" , "ANLN2" , "AFABE" , "BDATU"
, "ADATU" , "ERNAM" , "ERDAT" , "AENAM" , "AEDAT" , "XLOEV" , "
XSPEB" , "FELEI" , "XNEGA" , "XGWGK" , "XUNTA" , "AFABG" , "ZINB
G" , "SAFBG" , "INVSL" , "AFASL" , "NDJAR" , "NDPER" , "NAPRZ" ,
"SAPRZ" , "WBIND" , "ALIND" , "APROP" , "UMJAR" , "NDURJ" , "ND

35,091 40 877.3 0.5 4.67 13.91 3901340661
Module: SAPLF035
SELECT * FROM "BSID" WHERE "MANDT" = :A0 AND "BUKRS" = :A1 AND "
KUNNR" = :A2 AND "SHKZG" = :A3

28,678 598 48.0 0.4 0.40 2.50 3895264742
Module: SAPLABRA
SELECT * FROM "ANEA" WHERE "MANDT" = :A0 AND "BUKRS" = :A1 AND "
ANLN1" = :A2 AND "ANLN2" = :A3 AND "AFABE" = :A4 AND "GJAHR" = :
A5 OR "MANDT" = :A6 AND "BUKRS" = :A7 AND "ANLN1" = :A8 AND "ANL

-------------------------------------------------------------
SQL ordered by Reads for DB: mva Instance: mva Snaps: 24 -25
-> End Disk Reads Threshold: 1000

CPU Elapsd
Physical Reads Executions Reads per Exec %Total Time (s) Time (s) Hash Value
--------------- ------------ -------------- ------ -------- --------- ----------
106,286 34 3,126.1 33.5 6.38 16.17 348738309
Module: SAPLARFC
SELECT * FROM "ARFCRSTATE" WHERE "ARFCSTATE" = :A0 OR "ARFCSTATE
" = :A1

20,513 2 10,256.5 6.5 1.63 143.24 3000445581
Module: ZLSRR015
SELECT "MBLNR" , "MJAHR" , "ZEILE_I" , "BWART_I" , "MATNR_I" , "
WERKS_I" , "LGORT_I" , "CHARG_I" , "SOBKZ_I" , "LIFNR_I" , "KUNN
R_I" , "KDAUF_I" , "SHKZG_I" , "WAERS_I" , "DMBTR_I" , "MENGE_I"
, "MEINS_I" , "ERFMG_I" , "ERFME_I" , "EBELN_I" , "EBELP_I" , "
KOSTL_I" , "AUFNR_I" , "ANLN1_I" , "ANLN2_I" , "BUKRS_I" , "UMWR

Thanks for your reply. I understand you. But how do we take snapshots then, since we don't know when these jobs are exaclty is going to be done. Can we take one before we start batch jobs and one after completing our batch jobs?

Based on the existing report can you suggest on any waits or anything regarding the tuning resources apart from cpu statistics? or the present report is not useful at all.
Thanks Tom.

Thanks a lot Tom. I will work on SQL_TRACE for individual BATCH per your recommendation. Really appreciated your help and time.

"I would sql_trace (using 10046 level 12 trace) an individual BATCH to see what
that batch is being affected most by."

Tom,

What should be the best method to archive and purge statspack data?

How to run sppurge in batch mode

#!/bin/ksh

# First, we must set the environment . . . .
ORACLE_SID=REPD
export ORACLE_SID
ORACLE_HOME=/apps/orarepd/db/920
export ORACLE_HOME
PATH=$ORACLE_HOME/bin:$PATH
export PATH
date
$ORACLE_HOME/bin/sqlplus system/n1ners <<!

define losnapid=1
define hisnapid=6503
@$ORACLE_HOME/rdbms/admin/sppurge
exit
!

Above code is not working

Tom,
What is the main reason for this wait. Why the background processes(LGWR,DBWR,ARC Etc..) needs to wait for the foreground process even the system is busy?

Thanks

Hi Tom,
I would like to ask for your advice regard to this strange statspack:

How can Transaction be equal to zero while there are huge number of blocks per
transaction in the Redo size, Logical reads and block changes ?

STATSPACK report for

DB Name DB Id Instance Inst Num Release Cluster Host
------------ ----------- ------------ -------- ----------- ------- ------------
xxxxx yyyyyyyyyyy xxxxx 1 9.2.0.7.0 NO xxxxx

Snap Id Snap Time Sessions Curs/Sess Comment
--------- ------------------ -------- --------- -------------------
Begin Snap: 911 07-May-06 21:13:13 12 3.2
End Snap: 912 07-May-06 22:00:02 37 3.3
Elapsed: 46.82 (mins)

Cache Sizes (end)
~~~~~~~~~~~~~~~~~
Buffer Cache: 1,504M Std Block Size: 8K
Shared Pool Size: 152M Log Buffer: 1,600K

Load Profile
~~~~~~~~~~~~ Per Second Per Transaction
--------------- ---------------
Redo size: 639,824.96 599,089,441.33
Logical reads: 4,006.08 3,751,022.00
Block changes: 2,944.99 2,757,490.33
Physical reads: 17.12 16,031.33
Physical writes: 87.69 82,108.33
User calls: 60.00 56,178.67
Parses: 30.81 28,851.00
Hard parses: 4.77 4,463.33
Sorts: 0.83 778.00
Logons: 0.01 12.67
Executes: 31.97 29,933.33
Transactions: 0.00

% Blocks changed per Read: 73.51 Recursive Call %: 46.60
Rollback per transaction %: 0.00 Rows per Sort: 98.91

Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Buffer Nowait %: 100.00 Redo NoWait %: 100.00
Buffer Hit %: 99.68 In-memory Sort %: 99.96
Library Hit %: 92.45 Soft Parse %: 84.53
Execute to Parse %: 3.62 Latch Hit %: 100.00
Parse CPU to Parse Elapsd %: 76.91 % Non-Parse CPU: 96.01

Shared Pool Statistics Begin End
------ ------
Memory Usage %: 16.77 65.33
% SQL with executions>1: 49.24 1.44
% Memory for SQL w/exec>1: 31.28 4.58

Top 5 Timed Events
~~~~~~~~~~~~~~~~~~ % Total
Event Waits Time (s) Ela Time
-------------------------------------------- ------------ ----------- --------
CPU time 180 65.53
db file sequential read 29,796 62 22.65
log file sequential read 1,751 16 6.00
db file parallel write 1,208 9 3.40
log file switch completion 35 2 .66
-------------------------------------------------------------

Hi Tom
Thanks for your previous input.
I have few question:

1. Its look like those long transaction are producing huge amount of redo per second (~625MB).
But it had almost no affect on the performance (based on : "Top 5 Timed Events").

Top 5 Timed Events
~~~~~~~~~~~~~~~~~~ % Total
Event Waits Time (s) Ela Time
-------------------------------------------- ------------ ----------- --------
CPU time 180 65.53
db file sequential read 29,796 62 22.65
log file sequential read 1,751 16 6.00
db file parallel write 1,208 9 3.40
log file switch completion 35 2 .66
-------------------------------------------------------------

A. Is that True?
B. Is that mean that the log file size is set correctly for this load ?

2. We are using :
undo_management AUTO
undo_retention 10800
undo_tablespace undotbs
Why the Rollback Segment storage appear in the statpack ?

Rollback Segment Storage for DB: xxxx Instance: xxxx Snaps: 911 -912
->Optimal Size should be larger than Avg Active

RBS No Segment Size Avg Active Optimal Size Maximum Size
------ --------------- --------------- --------------- ---------------
0 401,408 0 401,408
1 67,231,744 0 67,231,744
2 42,065,920 0 42,065,920
3 67,231,744 0 67,231,744
4 8,511,488 0 8,511,488
5 67,231,744 0 67,231,744
6 67,231,744 0 67,231,744
7 10,608,640 0 10,608,640
8 738,320,384 612,381,924 738,320,384
9 42,065,920 0 42,065,920
10 67,231,744 0 67,231,744
-------------------------------------------------------------
Undo Segment Summary for DB: XXXXX Instance: xxxx Snaps: 911 -912
-> Undo segment block stats:
-> uS - unexpired Stolen, uR - unexpired Released, uU - unexpired reUsed
-> eS - expired Stolen, eR - expired Released, eU - expired reUsed

Undo Undo Num Max Qry Max Tx Snapshot Out of uS/uR/uU/
TS# Blocks Trans Len (s) Concurcy Too Old Space eS/eR/eU
---- -------------- ---------- -------- ---------- -------- ------ -------------
1 104,024 61,077 30 2 0 0 0/0/0/0/0/0
-------------------------------------------------------------

3. what is the mining of User calls in "Load Profile" section

Thanks.

Hi Tom,

I didnt understand what you mean by :

"or they might be producing little redo per second ~625KB!"

Thanks again

Dear Tom,

I am very sorry for posting the SPR for the same old points but please bear once for me...

-----

STATSPACK report for

DB Name DB Id Instance Inst Num Release Cluster Host
------------ ----------- ------------ -------- ----------- ------- ------------
STAR 3333099603 2 9.2.0.7.0 YES

Snap Id Snap Time Sessions Curs/Sess Comment
--------- ------------------ -------- --------- -------------------
Begin Snap: 993 09-Dec-06 09:30:00 1,606 10.8
End Snap: 1021 09-Dec-06 10:00:03 2,585 12.9
Elapsed: 30.05 (mins)

Cache Sizes (end)
~~~~~~~~~~~~~~~~~
Buffer Cache: 4,096M Std Block Size: 8K
Shared Pool Size: 1,440M Log Buffer: 2,048K

Load Profile
~~~~~~~~~~~~ Per Second Per Transaction
--------------- ---------------
Redo size: 74,690.00 9,992.29
Logical reads: 252,322.63 33,756.60
Block changes: 507.26 67.86
Physical reads: 2,377.87 318.12
Physical writes: 25.76 3.45
User calls: 1,131.86 151.42
Parses: 217.55 29.10
Hard parses: 28.32 3.79
Sorts: 84.72 11.33
Logons: 1.38 0.18
Executes: 643.82 86.13
Transactions: 7.47

% Blocks changed per Read: 0.20 Recursive Call %: 44.73
Rollback per transaction %: 45.54 Rows per Sort: 43.79

Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Buffer Nowait %: 99.96 Redo NoWait %: 100.00
Buffer Hit %: 99.06 In-memory Sort %: 100.00
Library Hit %: 96.12 Soft Parse %: 86.98
Execute to Parse %: 66.21 Latch Hit %: 99.93
Parse CPU to Parse Elapsd %: 31.41 % Non-Parse CPU: 99.24

Shared Pool Statistics Begin End
------ ------
Memory Usage %: 95.80 61.99
% SQL with executions>1: 41.23 59.00
% Memory for SQL w/exec>1: 40.52 54.71

Top 5 Timed Events
~~~~~~~~~~~~~~~~~~ % Total
Event Waits Time (s) Ela Time
-------------------------------------------- ------------ ----------- --------
db file sequential read 2,934,791 55,409 81.34
CPU time 5,313 7.80
buffer busy waits 97,153 2,910 4.27
db file scattered read 112,653 1,458 2.14
global cache cr request 1,986,534 1,317 1.93
-------------------------------------------------------------
Cluster Statistics for DB: Snaps: 993 -1021

******************************
QUESTIONS:
1) In the above Statspack Report (SPR), what do you think tobe culprit for the slowness, customers are shouting on us and complaining frequently for slowness.
2) In OEM, Block/waiting locks (Under Instance) are there, how to find manually...? (Pls. share the script).
3) Execute to parse is not even crossing 70%... ? Does it responsible for the slowness...? How to improve that ?
4) CPU time is not displaying, what would be the cause ?
5) DB sequencial read is a top event, so do we need to change the storage prameter...? How to come out from this event because, i believe that it is also responsible for slowness...
6) shared pool 4,542,645 0.2 0.1 1 0
is it ok............?
7) simulator hash latch 28,679,856 0.0 0.0 0 0
what is this meant for sir.....?
8) Open cursors are only 400 set so is it responsible for slowness...?
9) I am failed to understand SGA breakdown...

*******
Pool Name Begin value End value % Diff
------ ------------------------------ ---------------- ---------------- -------
java free memory 134,217,728 134,217,728 0.00
large free memory 83,886,080 83,886,080 0.00
shared 1M buffer 528,384 528,384 0.00
shared Checkpoint queue 1,026,560 1,026,560 0.00
shared DML lock 5,085,656 5,085,656 0.00
shared FileOpenBlock 16,104,056 16,104,056 0.00
shared KCL name table 2,938,632 2,938,632 0.00
shared KGK heap 7,000 7,000 0.00
shared KGLS heap 7,565,664 4,674,488 -38.21
shared KQR L PO 2,513,064 1,874,832 -25.40
shared KQR L SO 1,998,216 1,762,208 -11.81
shared KQR M PO 5,098,440 3,021,776 -40.73
shared KQR M SO 3,861,008 3,007,520 -22.11
shared KQR S SO 6,400 6,400 0.00
shared KSXR pending messages que 853,952 853,952 0.00
shared PL/SQL DIANA 6,236,904 5,726,512 -8.18
shared PL/SQL MPCODE 36,803,296 23,894,424 -35.08
shared PL/SQL PPCODE 55,728 26,872 -51.78
shared PLS non-lib hp 2,088 2,088 0.00
shared PX subheap 20,048 20,048 0.00
shared Temporary Tables State Ob 1,288,576 1,288,576 0.00
shared UNDO INFO SEGMENTED ARRAY 1,080,072 1,080,072 0.00
shared branch 1,963,256 1,963,256 0.00
shared constraints 1,371,144 1,371,144 0.00
shared db_block_hash_buckets 16,883,152 16,883,152 0.00
shared dictionary cache 4,274,432 4,274,432 0.00
shared enqueue 9,281,504 9,281,504 0.00
shared enqueue resources 3,178,144 3,178,144 0.00
shared errors 45,328 33,104 -26.97
shared event statistics per sess 62,392,000 62,392,000 0.00
shared fixed allocation callback 1,088 1,088 0.00
shared free memory 80,419,800 726,960,344 803.96
shared gcs resource hash table 1,048,576 1,048,576 0.00
shared gcs resources 78,660,704 78,660,704 0.00
shared gcs shadows 52,262,448 52,262,448 0.00
shared ges big msg buffers 10,962,088 10,962,088 0.00
shared ges enqueues 58,882,176 58,882,176 0.00
shared ges process array 3,201,280 3,201,280 0.00
shared ges regular msg buffers 2,552,248 2,552,248 0.00
shared ges resource hash table 8,650,752 8,650,752 0.00
shared ges resources 36,085,304 36,085,304 0.00
shared joxs heap init 624 624 0.00
shared ksm_file2sga region 370,496 370,496 0.00
shared ktlbk state objects 3,242,800 3,242,800 0.00
shared library cache 502,555,312 309,454,656 -38.42
shared miscellaneous 191,993,544 219,164,976 14.15
shared parameters 4,124,968 3,032,648 -26.48
shared partitioning d 85,256 86,736 1.74
shared processes 3,280,000 3,280,000 0.00
shared qmps connections 2,420,000 2,420,000 0.00
shared sessions 14,872,000 14,872,000 0.00
shared sim memory hea 1,380,480 1,380,480 0.00
shared sql area 652,618,392 193,249,168 -70.39
shared table definiti 26,248 8,976 -65.80

Pool Name Begin value End value % Diff
------ ------------------------------ ---------------- ---------------- -------
shared temporary tabl 17,632 50,288 185.21
shared transaction 10,078,144 10,078,144 0.00
shared trigger defini 22,704 12,040 -46.97
shared trigger inform 736 672 -8.70
shared trigger source 120 120 0.00
shared txncallback 324,000 324,000 0.00
buffer_cache 4,294,967,296 4,294,967,296 0.00
fixed_sga 753,216 753,216 0.00
log_buffer 2,360,320 2,360,320 0.00
-------------------------------------------------------------
Resource Limit Stats for DB: DMS Instance: DMS2 End Snap: 1021
-> only rows with Current or Maximum Utilization > 80% of Limit are shown
-> ordered by resource name


end of the SP report...

Pls. tell me where I need to check because reduce the contention is now challenge for us...

Hope your explanation would help me in the very broad manner. Also in your first thread, you have mentioned that you send email once you update this thread. Sorry to say but I have never got any email from your side. can you check from your end please...? I will also confirm from my admin team.

Regards,
Star Nirav

Tom,

You did not point to

Parses: 217.55 29.10
Hard parses: 28.32 3.79

is it because of RAC?

TIA.

HI,

I have to take statspack report on only in particular area
how to take the report.

Hi,

QUESTIONS:
1) In the above Statspack Report (SPR), what do you think tobe culprit for the slowness, customers
are shouting on us and complaining frequently for slowness.
2) In OEM, Block/waiting locks (Under Instance) are there, how to find manually...? (Pls. share the
script).
3) Execute to parse is not even crossing 70%... ? Does it responsible for the slowness...? How to
improve that ?
4) CPU time is not displaying, what would be the cause ?
5) DB sequencial read is a top event, so do we need to change the storage prameter...? How to come
out from this event because, i believe that it is also responsible for slowness...
6) shared pool 4,542,645 0.2 0.1 1 0
is it ok............?
7) simulator hash latch 28,679,856 0.0 0.0 0 0
what is this meant for sir.....?
8) Open cursors are only 400 set so is it responsible for slowness...?
9) I am failed to understand SGA breakdown...


Can you pls. respond for the above said questions...?

Sorry... SPR term has been used for StatsPack Report. Anyways, pls. respond for the above questions.

Regards,

Using statspack how can we get :
Version(9.2.0.7)
1. How many sessions got connected for the snapshot interval
2. How many sessions were closed for the snapshot interval
3. How many sessions were using MTS (shared server)
4. How many sessions were using dedicated server

Hi Tom,
Our DB gave an error saying SGA was full and we had to restart the DB. We do not know what really caused the 'SGA full issue'. Is there a way to use statspack or any tables or views (such as the one used by statspack) to find out what happend immediately before the DB went down? Which processes were consuming most of the SGA during that time period?

Hi Tom,

the following statspack snippet tells, that 3000s CPU time were needed but also that average CPU load was < 3%.
As i interpet this result the os is not giving oracle the cpu ressources it would need to shorten the overall execution time. Am i wrong with that ?

(The monitored activity is 1 stored procedure with 1 big update statement.)


Top 5 Timed Events Avg %Total
~~~~~~~~~~~~~~~~~~ wait Call
Event Waits Time (s) (ms) Time
----------------------------------------- ------------ ----------- ------ ------
CPU time 3,102 82.8
db file sequential read 5,492,078 444 0 11.8
Backup: sbtwrite2 886 59 67 1.6
db file parallel write 8,192 59 7 1.6
log file parallel write 1,960 30 15 .8
--------------------------------------------------------------------------------

Host CPU (CPUs: 16)
~~~~~~~~ Load Average
Begin End User System Idle WIO WCPU
------- ------- ------- ------- ------- ------- --------
2.34 2.28 16.61 4.61 78.78 0.00 0.85

rdbms 10gr2

found in statspack report
Gets per Exec was 9 millions for
BEGIN POPULATE_RR_INVENTORY(:1,:2,:3,:4) ; END;

Question, will the queries in POPULATE_RR_INVENTORY also be shown in the report?

In my report, I see high avg wait for enq:CF -contention.
I could not find much info about. Please comment.
Thanks.
Avg
%Time Total Wait wait Waits
Event Waits -outs Time (s) (ms) /txn
---------------------------- -------------- ------ ----------- ------- ---------
db file sequential read 877,944 .0 54,556 62 118.8
read by other session 681,355 .0 33,817 50 92.2
enq: TM - contention 5,134 96.0 14,623 2848 0.7
db file scattered read 92,265 .0 6,491 70 12.5
db file parallel write 335,784 .0 4,918 15 45.4
Log archive I/O 16,005 .0 2,255 141 2.2
log file parallel write 14,133 .0 1,742 123 1.9
log file sequential read 14,031 .0 1,237 88 1.9
control file sequential read 24,981 .0 896 36 3.4
log file sync 5,677 .4 801 141 0.8
log file switch completion 942 36.7 546 580 0.1
control file parallel write 2,990 .0 279 93 0.4
enq: CF - contention 30 .0 33 1087 0.0
direct path write 3,568 .0 24 7 0.5
SQL*Net message to client 9,568,326 .0 22 0 1,295.1
latch free 6,697 .0 21 3 0.9
log buffer space 134 .0 17 125 0.0
latch: cache buffers chains 11,873 .0 13 1 1.6
direct path read 6,729 .0 12 2 0.9
buffer busy waits 72 8.3 9 131 0.0
log file single write 228 .0 7 29 0.0
enq: TX - index contention 21 .0 6 262 0.0
cursor: pin S wait on X 483 98.8 5 11 0.1

Tom

I'm sorry but I'd like to see the full text to your last response. I'm also having a problems with 'enq: CF - contention' and can't for the life of me work out what (other than the checkpointer and rman) could be competing for a controlfile latch

Regs
John Davey

Tom

Thanks for responding. I may well have been focussing on CF contention at the expense of other candidates. Besides it would appear that the regular RMAN job is suffering most.

There are, I think, definitely issues on other areas that you highlighted.

If I check v$active session_history using the following query

select active_session_history.event,
sum(active_session_history.wait_time +
active_session_history.time_waited) ttl_wait_time
from v$active_session_history active_session_history
where active_session_history.sample_time between sysdate - 60/2880 and sysdate
group by active_session_history.event
order by 2

For the last half hour I've had these as the worst offenders :-

enq: CF - contention 100219916
log file sequential read 118184573

control file parallel write 121005700

log file switch completion 146526292
log file sync 208731972
db file sequential read 236192222
303941275
log file parallel write 355215888


Now I understand that the wait times are recorded in Microseconds. So 355 seconds for a log file parallel write in 30 minutes, albeit of real time, must be on the high side ?

We have had a problem in the last hour with a query doing a huge "hashed group by" - a temp segment of 8Gigs was eventually created. However seeing high values for log file parallel writes is fairly typical as far as I'm concerned.

We are using an ASM instance for our storage and I know we have only one disk group - is this likely to create logfile contention issues ?

Hi Tom

I thing there is a problem with the shared memory
do you agree?

thanks and
best regards

STATSPACK report for

DB Name DB Id Instance Inst Num Release Cluster Host
------------ ----------- ------------ -------- ----------- ------- ------------
CRM 3401395366 CRM1 1 9.2.0.7.0 YES p595a-p4

Snap Id Snap Time Sessions Curs/Sess Comment
--------- ------------------ -------- --------- -------------------
Begin Snap: 16723 13-Ago-09 09:00:02 285 #########
End Snap: 16724 13-Ago-09 10:00:07 291 #########
Elapsed: 60.08 (mins)

Cache Sizes (end)
~~~~~~~~~~~~~~~~~
Buffer Cache: 1,024M Std Block Size: 8K
Shared Pool Size: 512M Log Buffer: 3,072K

Load Profile
~~~~~~~~~~~~ Per Second Per Transaction
--------------- ---------------
Redo size: 111,621.06 6,016.66
Logical reads: 18,093.76 975.30
Block changes: 613.09 33.05
Physical reads: 709.94 38.27
Physical writes: 75.16 4.05
User calls: 506.13 27.28
Parses: 313.40 16.89
Hard parses: 1.63 0.09
Sorts: 38.03 2.05
Logons: 0.34 0.02
Executes: 512.99 27.65
Transactions: 18.55

% Blocks changed per Read: 3.39 Recursive Call %: 43.32
Rollback per transaction %: 0.06 Rows per Sort: 112.70

Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Buffer Nowait %: 99.99 Redo NoWait %: 100.00
Buffer Hit %: 96.24 In-memory Sort %: 100.00
Library Hit %: 99.79 Soft Parse %: 99.48
Execute to Parse %: 38.91 Latch Hit %: 99.93
Parse CPU to Parse Elapsd %: 9.59 % Non-Parse CPU: 98.64

Shared Pool Statistics Begin End
------ ------
Memory Usage %: 100.00 100.00
% SQL with executions>1: 88.20 87.22
% Memory for SQL w/exec>1: 99.25 99.23

Top 5 Timed Events
~~~~~~~~~~~~~~~~~~ % Total
Event Waits Time (s) Ela Time
-------------------------------------------- ------------ ----------- --------
db file sequential read 979,354 2,992 60.00
CPU time 861 17.26
global cache cr request 731,893 443 8.89
db file scattered read 105,694 197 3.95
PL/SQL lock timer 23 112 2.25
-------------------------------------------------------------

Hi Tom

in my statpack I see

Shared Pool Statistics Begin End
------ ------
Memory Usage %: 100.00 100.00

so it could be a small shared memory...perhaps...

Hi Tom,

my Oracle has performance problem, i notice
many wait event 'latch free'

please help me to interpret the Shared Pool Advisor

many thanks

Mauro



Library Cache Activity for DB: CRM Instance: CRM1 Snaps: 15772 -15773
->"Pct Misses" should be very low

Get Pct Pin Pct Invali-
Namespace Requests Miss Requests Miss Reloads dations
--------------- ------------ ------ -------------- ------ ---------- --------
BODY 4,601 0.0 4,601 0.1 2 0
CLUSTER 773 0.4 780 0.8 0 0
INDEX 234 0.0 234 0.0 0 0
JAVA DATA 90 0.0 2,116 0.0 0 0
SQL AREA 221,714 0.4 6,450,463 0.1 2,509 0
TABLE/PROCEDURE 145,866 0.3 522,116 0.7 1,494 0
TRIGGER 1,685 0.0 1,685 0.2 3 0
-------------------------------------------------------------


GES Lock GES Pin GES Pin GES Inval GES Invali-
Namespace Requests Requests Releases Requests dations
--------------- ------------ ------------ ------------ ----------- -----------
BODY 1 2 1 2 0
CLUSTER 528 3 3 3 0
INDEX 234 0 0 0 0
JAVA DATA 0 0 0 0 0
SQL AREA 0 0 0 0 0
TABLE/PROCEDURE 38,965 449 378 253 0
TRIGGER 0 0 0 0 0
-------------------------------------------------------------
Shared Pool Advisory for DB: CRM Instance: CRM1 End Snap: 15773
-> Note there is often a 1:Many correlation between a single logical object
in the Library Cache, and the physical number of memory objects associated
with it. Therefore comparing the number of Lib Cache objects (e.g. in
v$librarycache), with the number of Lib Cache Memory Objects is invalid

Estd
Shared Pool SP Estd Estd Estd Lib LC Time
Size for Size Lib Cache Lib Cache Cache Time Saved Estd Lib Cache
Estim (M) Factr Size (M) Mem Obj Saved (s) Factr Mem Obj Hits
----------- ----- ---------- ------------ ------------ ------- ---------------
256 .5 262 27,854 17,653,191 1.0 2,347,022,464
320 .6 325 36,445 17,655,218 1.0 2,347,777,030
384 .8 388 44,341 17,656,335 1.0 2,348,163,591
448 .9 451 51,617 17,657,045 1.0 2,348,419,271
512 1.0 514 57,838 17,657,579 1.0 2,348,608,500
576 1.1 577 64,057 17,657,939 1.0 2,348,748,206
640 1.3 640 70,420 17,658,226 1.0 2,348,869,508
704 1.4 703 76,165 17,658,506 1.0 2,348,992,191
768 1.5 766 82,129 17,658,768 1.0 2,349,133,385
832 1.6 829 88,833 17,659,106 1.0 2,349,331,667
896 1.8 894 98,028 17,659,447 1.0 2,349,548,084
960 1.9 957 105,980 17,659,644 1.0 2,349,664,174
1,024 2.0 1,022 115,273 17,659,790 1.0 2,349,754,104
-------------------------------------------------------------
SGA Memory Summary for DB: CRM Instance: CRM1 Snaps: 15772 -15773

SGA regions Size in Bytes
------------------------------ ----------------
Database Buffers 1,073,741,824
Fixed Size 744,648
Redo Buffers 3,420,160
Variable Size 973,078,528
----------------
sum 2,050,985,160

Thank you Tom

WORKLOAD REPOSITORY report for

DB Name DB Id Instance Inst Num Release RAC Host
------------ ----------- ------------ -------- ----------- --- ------------
Snap1 2270086637 snap2 2 10.2.0.3.0 YES prs-lin-306-

Snap Id Snap Time Sessions Curs/Sess
--------- ------------------- -------- ---------
Begin Snap: 25251 16-Aug-11 16:00:35 37 5.8
End Snap: 25252 16-Aug-11 17:00:04 36 5.9
Elapsed: 59.48 (mins)
DB Time: 177.18 (mins)

Cache Sizes
~~~~~~~~~~~ Begin End
---------- ----------
Buffer Cache: 1,008M 1,008M Std Block Size: 8K
Shared Pool Size: 1,504M 1,504M Log Buffer: 14,356K

Load Profile
~~~~~~~~~~~~ Per Second Per Transaction
--------------- ---------------
Redo size: 45,892.52 2,441.03
Logical reads: 58,560.95 3,114.86
Block changes: 244.41 13.00
Physical reads: 768.53 40.88
Physical writes: 5.34 0.28
User calls: 9.12 0.49
Parses: 171.99 9.15
Hard parses: 22.80 1.21
Sorts: 38.32 2.04
Logons: 0.05 0.00
Executes: 166.55 8.86
Transactions: 18.80

% Blocks changed per Read: 0.42 Recursive Call %: 98.67
Rollback per transaction %: 5.40 Rows per Sort: 1.29

Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Buffer Nowait %: 99.91 Redo NoWait %: 100.00
Buffer Hit %: 98.70 In-memory Sort %: 100.00
Library Hit %: 92.80 Soft Parse %: 86.74
Execute to Parse %: -3.27 Latch Hit %: 99.86
Parse CPU to Parse Elapsd %: 32.38 % Non-Parse CPU: 97.55

Shared Pool Statistics Begin End
------ ------
Memory Usage %: 86.16 85.73
% SQL with executions>1: 91.05 70.68
% Memory for SQL w/exec>1: 91.05 71.96

Top 5 Timed Events Avg %Total
~~~~~~~~~~~~~~~~~~ wait Call
Event Waits Time (s) (ms) Time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
CPU time 4,154 39.1
enq: TM - contention 24,546 3,685 150 34.7 Applicatio
gc buffer busy 189,530 1,082 6 10.2 Cluster
gc cr multi block request 5,411,933 593 0 5.6 Cluster
db file parallel read 7,320 455 62 4.3 User I/O
-------------------------------------------------------------
RAC Statistics DB/Inst: Snap1/snap2 Snaps: 25251-25252

Begin End
----- -----
Number of Instances: 2 2


Global Cache Load Profile
~~~~~~~~~~~~~~~~~~~~~~~~~ Per Second Per Transaction
--------------- ---------------
Global Cache blocks received: 1,807.60 96.15
Global Cache blocks served: 467.40 24.86
GCS/GES messages received: 1,730.41 92.04
GCS/GES messages sent: 3,857.07 205.16
DBWR Fusion writes: 0.51 0.03
Estd Interconnect traffic (KB) 19,291.27


Global Cache Efficiency Percentages (Target local+remote 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Buffer access - local cache %: 95.61
Buffer access - remote cache %: 3.09
Buffer access - disk %: 1.30


Global Cache and Enqueue Services - Workload Characteristics
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Avg global enqueue get time (ms): 3.1

Avg global cache cr block receive time (ms): 0.6
Avg global cache current block receive time (ms): 0.9

Avg global cache cr block build time (ms): 0.0
Avg global cache cr block send time (ms): 0.0
Global cache log flushes for cr blocks served %: 2.6
Avg global cache cr block flush time (ms): 6.8

Avg global cache current block pin time (ms): 0.0
Avg global cache current block send time (ms): 0.0
Global cache log flushes for current blocks served %: 0.1
Avg global cache current block flush time (ms): 2.8

Global Cache and Enqueue Services - Messaging Statistics
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Avg message sent queue time (ms): 0.1
Avg message sent queue time on ksxp (ms): 0.3
Avg message received queue time (ms): 0.0
Avg GCS message process time (ms): 0.0
Avg GES message process time (ms): 0.0

% of direct sent messages: 3.23
% of indirect sent messages: 95.13
% of flow controlled messages: 1.65
-------------------------------------------------------------

Time Model Statistics DB/Inst: Snap1/snap2 Snaps: 25251-25252
-> Total time in database user-calls (DB Time): 10631s
-> Statistics including the word "background" measure background process
time, and so do not contribute to the DB time statistic
-> Ordered by % or DB time desc, Statistic name

Statistic Name Time (s) % of DB Time
------------------------------------------ ------------------ ------------
sql execute elapsed time 10,608.1 99.8
DB CPU 4,154.2 39.1
parse time elapsed 628.0 5.9
PL/SQL execution elapsed time 473.7 4.5
hard parse elapsed time 432.0 4.1
failed parse elapsed time 354.4 3.3
PL/SQL compilation elapsed time 43.7 .4
connection management call elapsed time 1.8 .0
hard parse (sharing criteria) elapsed time 0.7 .0
repeated bind elapsed time 0.3 .0
hard parse (bind mismatch) elapsed time 0.3 .0
sequence load elapsed time 0.2 .0
DB time 10,631.0 N/A
background elapsed time 332.1 N/A
background cpu time 154.8 N/A
-------------------------------------------------------------

Wait Class DB/Inst: Snap1/snap2 Snaps: 25251-25252
-> s - second
-> cs - centisecond - 100th of a second
-> ms - millisecond - 1000th of a second
-> us - microsecond - 1000000th of a second
-> ordered by wait time desc, waits desc

Avg
%Time Total Wait wait Waits
Wait Class Waits -outs Time (s) (ms) /txn
-------------------- ---------------- ------ ---------------- ------- ---------
Application 24,557 21.9 3,685 150 0.4
Cluster 5,670,075 .0 1,700 0 84.5
User I/O 74,300 .0 843 11 1.1
Concurrency 152,352 10.6 212 1 2.3
System I/O 74,099 .0 138 2 1.1
Commit 12,687 .0 38 3 0.2
Other 468,014 76.8 30 0 7.0
Configuration 38 .0 0 4 0.0
Network 23,311 .0 0 0 0.3
-------------------------------------------------------------

Wait Events DB/Inst: Snap1/snap2 Snaps: 25251-25252
-> s - second
-> cs - centisecond - 100th of a second
-> ms - millisecond - 1000th of a second
-> us - microsecond - 1000000th of a second
-> ordered by wait time desc, waits desc (idle events last)

Avg
%Time Total Wait wait Waits
Event Waits -outs Time (s) (ms) /txn
---------------------------- -------------- ------ ----------- ------- ---------
enq: TM - contention 24,546 21.9 3,685 150 0.4
gc buffer busy 189,530 .0 1,082 6 2.8
gc cr multi block request 5,411,933 .0 593 0 80.7
db file parallel read 7,320 .0 455 62 0.1
db file scattered read 38,843 .0 308 8 0.6
cursor: pin S wait on X 16,269 98.9 174 11 0.2
log file parallel write 64,200 .0 117 2 1.0
db file sequential read 11,144 .0 45 4 0.2
log file sync 12,687 .0 38 3 0.2
read by other session 6,212 .0 35 6 0.1
library cache lock 83,094 .0 20 0 1.2
control file sequential read 8,411 .0 17 2 0.1
gc current block 2-way 40,706 .0 11 0 0.6
wait for scn ack 45,051 .0 9 0 0.7
library cache pin 19,468 .0 7 0 0.3
row cache lock 20,872 .0 6 0 0.3
gcs log flush sync 2,907 14.4 5 2 0.0
control file parallel write 1,488 .0 4 3 0.0
kksfbc child completion 80 98.8 4 49 0.0
gc cr block 2-way 13,907 .0 4 0 0.2
gc current block busy 697 .0 3 5 0.0
gc cr block busy 589 .0 3 6 0.0
enq: WF - contention 9 33.3 2 233 0.0
enq: US - contention 7,585 .0 2 0 0.1
enq: TX - index contention 179 .0 2 10 0.0
latch: ges resource hash lis 2,613 .0 2 1 0.0
gc current grant busy 5,024 .0 1 0 0.1
DFS lock handle 2,846 .0 1 0 0.0
latch: shared pool 6,330 .0 1 0 0.1
name-service call wait 17 .0 1 70 0.0
CGS wait for IPC msg 331,948 100.0 1 0 4.9
gc cr grant 2-way 5,164 .0 1 0 0.1
os thread startup 7 .0 1 85 0.0
gcs drm freeze in enter serv 8 .0 0 60 0.0
Data file init write 49 .0 0 8 0.0
ksxr poll remote instances 68,319 36.1 0 0 1.0
enq: TX - contention 4 .0 0 84 0.0
gc remaster 17 .0 0 18 0.0
gc current grant 2-way 1,248 .0 0 0 0.0
buffer busy waits 449 .0 0 1 0.0
latch: cache buffers chains 5,012 .0 0 0 0.1
enq: HW - contention 26 .0 0 5 0.0
enq: JI - contention 325 .0 0 0 0.0
latch free 695 .0 0 0 0.0
enq: MS - contention 293 .0 0 0 0.0
rdbms ipc reply 463 .0 0 0 0.0
ges global resource director 8 100.0 0 11 0.0
gc current multi block reque 1,187 .0 0 0 0.0
direct path read 10,668 .0 0 0 0.2
cursor: pin X 7 100.0 0 11 0.0
latch: library cache 576 .0 0 0 0.0
kjbdrmcvtq lmon drm quiesce: 8 .0 0 8 0.0
enq: FB - contention 146 .0 0 0 0.0
global enqueue expand wait 5 100.0 0 11 0.0
SQL*Net message to client 23,054 .0 0 0 0.3
enq: JQ - contention 93 .0 0 0 0.0
enq: TT - contention 95 .0 0 0 0.0
enq: TX - row lock contentio 10 .0 0 4 0.0
LGWR wait for redo copy 536 .0 0 0 0.0
enq: CF - contention 83 .0 0 0 0.0
Wait Events DB/Inst: Snap1/snap2 Snaps: 25251-25252
-> s - second
-> cs - centisecond - 100th of a second
-> ms - millisecond - 1000th of a second
-> us - microsecond - 1000000th of a second
-> ordered by wait time desc, waits desc (idle events last)

%Time Total Wait wait Waits
Event Waits -outs Time (s) (ms) /txn
---------------------------- -------------- ------ ----------- ------- ---------
log file parallel write 64,197 .0 117 2 1.0
events in waitclass Other 458,769 77.9 18 0 6.8
control file sequential read 6,903 .0 14 2 0.1
control file parallel write 1,443 .0 4 3 0.0
library cache lock 787 .0 0 0 0.0
gc cr multi block request 1,167 .0 0 0 0.0
os thread startup 2 .0 0 46 0.0
gc current block 2-way 100 .0 0 0 0.0
gc cr block 2-way 89 .0 0 0 0.0
enq: HW - contention 4 .0 0 1 0.0
latch: cache buffers chains 10 .0 0 0 0.0
gc current grant busy 3 .0 0 0 0.0
latch: row cache objects 3 .0 0 0 0.0
latch: library cache 1 .0 0 0 0.0
buffer busy waits 1 .0 0 0 0.0
rdbms ipc message 193,331 24.7 37,712 195 2.9
gcs remote message 826,092 93.5 6,846 8 12.3
pmon timer 1,243 100.0 3,483 2802 0.0
DIAG idle wait 17,689 .0 3,483 197 0.3
ges remote message 389,773 88.4 3,465 9 5.8
Streams AQ: qmn slave idle w 126 .0 3,464 27493 0.0
Streams AQ: qmn coordinator 254 50.4 3,464 13638 0.0
Streams AQ: waiting for time 14 14.3 3,315 236795 0.0
smon timer 48 .0 3,302 68781 0.0
PX Deq: Join ACK 29 41.4 0 1 0.0
PX Deq: Parse Reply 27 44.4 0 0 0.0
PX Deq: Execute Reply 28 39.3 0 0 0.0
Streams AQ: RAC qmn coordina 254 100.0 0 0 0.0
-------------------------------------------------------------

Operating System Statistics DB/Inst: Snap1/Snap2 Snaps: 25251-25252

Statistic Total
-------------------------------- --------------------
BUSY_TIME 517,928
IDLE_TIME 2,333,872
IOWAIT_TIME 102,175
NICE_TIME 971
SYS_TIME 65,909
USER_TIME 433,663
LOAD 3
RSRC_MGR_CPU_WAIT_TIME 0
PHYSICAL_MEMORY_BYTES 52,112
NUM_CPUS 8
NUM_CPU_SOCKETS 2
-------------------------------------------------------------



Its seem to be a memory problem please help me in this regard.
Thanks
Ajit

I have run a the following select in RAC and non RAC environment and i am getting different response time can you explain me the logic and reason behind it.

in RAC environment:-->
Select count(*) from t1;

Total count = 23000000
Total elapsed time : 00:00:44.11

In non RAC:-->

Select count(*) from t1;

Total count = 22500690
Total elapsed time : 00:00:09.05

With Regards
Ajit

Hi Tom,

Thanks for your suggession. is there any problem to assign same tablespace to table and indexes in OLTP environment, when we try to load (merging) the same sets tables concurrently through 6 session? will performance decrease or serialization increase? Please advice.

Hi Tom,
Our production database started crawling a few days ago. It is at the client site and we don't have access. I requested for the AWR and ADDM reports during the 'slowdown' period and there were a few queries which took a few minutes, and got executed a few hundred times, so total time for these queries ran into many hours. Some curious parts of the queries are pasted here.
1) AND "A1"."FLT_DT_UTC" =TRIM(TO_CHAR(SYSDATE@!))
2) TRUNC("A2"."EFF_TO_DTM_UTC")=TO_DATE(' 2075-12-31 00:00:00', 'syyyy-mm-dd hh24:mi:ss')
See the '@!' in the first query and 'syyyy' in the next. None of our developers would have written these conditions. We went through the application code and did not find these queries. The tables in these queries are from our application.
Our application does use materialized views. We also moved an archival job into production recently (but it has not been scheduled yet).
Is there any Oracle batch or background job which is likely to generate such queries, like changing data in base tables for a materialized view, or MV refresh, generate such queries?
Regards,
Jay

ops$tkyte%ORA11GR2> select* from dual where sysdate = to_date(null);

no rows selected


Execution Plan
----------------------------------------------------------
Plan hash value: 3752461848

---------------------------------------------------------------------------
| Id  | Operation          | Name | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------
|   0 | SELECT STATEMENT   |      |     1 |     2 |     2   (0)| 00:00:01 |
|*  1 |  FILTER            |      |       |       |            |          |
|   2 |   TABLE ACCESS FULL| DUAL |     1 |     2 |     2   (0)| 00:00:01 |
---------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   1 - filter(SYSDATE@!=TO_DATE(NULL))

Elapsed: 59.60 (mins)
DB Time: 5,159.14 (mins)

FROM OUR awr report above, run for a 1 hr window, why is elapsed time <> db time ?

64 cores or more ... - you mean 64 CPUs ?

Our server is having 64 CPUs

Bobby

Hi Tom,

How to simulate/replicate the following wait event

enq: TS - contention

in database 11g

many thanks.

Hi Tom,

On 11.2.0.3 version AWR report Instance Efficiency is showing negative library hit ratio as low as -3,321.23, it was above +95 % till previous day, like to know the reasons for the change & sudden change

Buffer Nowait %: 99.87 Redo NoWait %: 99.99
Buffer Hit %: 92.17 In-memory Sort %: 100.00
Library Hit %: -3,321.23 Soft Parse %: 81.95
Execute to Parse %: 92.88 Latch Hit %: 95.11
Parse CPU to Parse Elapsd %: 87.25 % Non-Parse CPU: 81.39

Its on 64 bit. From next day hit ratio was normal at >90%, without restarting the instance.