Tom, even with three statspack snapshots a day, what if someone calls somewhere inbetween and says "things are slow", and you also know that someone could have kicked off an ad hoc query that could be slowing things down. How would you go about identifying it?

Thanks Tom for your quich and very useful response.
The script showsql is really good and I was looking
for a script like this only.

But you have also mentioned to make use of statspack
to further analyse the problem.I ' am sorry as I should
have mentioned this before,my Production database version
is 7.3.3 and I think statspack will not work.

Could you please suggest any other alternative please.

hello
may I know what is meant by production database.

Hi Tom,

We have about 10 datbases (3 of them really large with large number of users and heavy weight sqls) on a large SUN E10K (16 cpus, 24GB ram and fast disks). There are frequent occasions where users complain of slowness and the "top/mpstat" shows some cpus loaded heavily. I suspect some heavy processes on specific cpu's (background and/or client connections) could be a factor.
I would like to know if there is an easy way I could determine which processes run on which cpu's.
Forgive me my question is aimed at OS rather than Oracle.

Hi TOm,

Hope u dont mind. I have a problem with one of our production databases. I dont have that extensive knowledge on interpreting the report of statspack. Can u give me a nice document.

And another one. Our production database is experiencing some problems where the users are waiting too long for login. Even I am waiting too long when logging in via sqlplus for windows or via telnet then sqlplus. It's only fast when I use svrmgrl. It takes about 2 to 5 minutes for a login. My db is 8.1.7 and my server is IBM AIX. No prob with the server as I used TOPAS. But after one long waiting for login, my next login would only be for 5 secs. Also thru sqlplus. I'm going to paste my statspack report during that time. I have a prior report that's run when there's no prob. I'll paste it if u'd like. SOrry for this. Hope you have the time.

STATSPACK report for

DB Name DB Id Instance Inst Num Release OPS Host
---------- ----------- ---------- -------- ---------- ---- ----------
POINT 947966058 POINT 1 8.1.7.0.0 NO CRM_PROD

Snap Length
Start Id End Id Start Time End Time (Minutes)
-------- -------- -------------------- -------------------- -----------
98 99 12-Mar-03 10:51:13 12-Mar-03 11:37:39 46.43


Cache Sizes
~~~~~~~~~~~
db_block_buffers: 250000
db_block_size: 4096
log_buffer: 524288
shared_pool_size: 800000000


Load Profile
~~~~~~~~~~~~
Per Second Per Transaction
--------------- ---------------
Redo size: 2,903.21 2,501.03
Logical reads: 2,938.21 2,531.18
Block changes: 15.64 13.47
Physical reads: 655.77 564.93
Physical writes: 11.47 9.88
User calls: 74.02 63.77
Parses: 12.58 10.83
Hard parses: 0.15 0.13
Sorts: 2.69 2.31
Transactions: 1.16

Rows per Sort: 104.55
Pct Blocks changed / Read: 0.53
Recursive Call Pct: 5.49
Rollback / transaction Pct: 1.89


Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Buffer Nowait Ratio: 96.13
Buffer Hit Ratio: 77.68
Library Hit Ratio: 99.23
Redo NoWait Ratio: 100.00
In-memory Sort Ratio: 99.96
Soft Parse Ratio: 98.78
Latch Hit Ratio: 98.65


Top 5 Wait Events
~~~~~~~~~~~~~~~~~ Wait % Total
Event Waits Time (cs) Wt Time
-------------------------------------------- ------------ ------------ -------
db file sequential read 1,547,030 167,785 68.61
buffer busy waits 316,992 40,103 16.40
latch free 17,757 17,784 7.27
db file parallel read 6,995 8,257 3.38
db file scattered read 9,969 4,945 2.02
-------------------------------------------------------------
^LWait Events for DB: POINT Instance: POINT Snaps: 98 - 99
->cs - centisecond - 100th of a second
->ms - millisecond - 1000th of a second (unit often used for disk IO timings)

Avg
Total Wait wait Waits
Event Waits Timeouts Time (cs) (ms) /txn
---------------------------- ------------ ---------- ----------- ----- ------
db file sequential read 1,547,030 0 167,785 1 478.4
buffer busy waits 316,992 0 40,103 1 98.0
latch free 17,757 11,226 17,784 10 5.5
db file parallel read 6,995 0 8,257 12 2.2
db file scattered read 9,969 0 4,945 5 3.1
log file sync 3,237 0 2,058 6 1.0
log file parallel write 3,253 0 980 3 1.0
db file parallel write 1,097 0 659 6 0.3
PX Deq: Execute Reply 84 0 387 46 0.0
control file parallel write 904 0 339 4 0.3
enqueue 25 0 279 112 0.0
process startup 5 1 221 442 0.0
file open 162 0 207 13 0.1
PX Deq: Parse Reply 3 0 142 473 0.0
library cache pin 3 0 135 450 0.0
PX Deq: Execution Msg 100 0 129 13 0.0
direct path read 663 0 48 1 0.2
PX Deq: Signal ACK 9 6 35 39 0.0
PX Deq: Join ACK 5 0 22 44 0.0
SQL*Net more data to client 1,859 0 16 0 0.6
refresh controlfile command 5 0 4 8 0.0
control file sequential read 57 0 3 1 0.0
direct path write 6 0 2 3 0.0
file identify 2 0 2 10 0.0
SQL*Net break/reset to clien 2 0 1 5 0.0
db file single write 1 0 0 0 0.0
SQL*Net message from client 205,557 0 14,238,554 693 63.6
virtual circuit status 90 90 276,477 ##### 0.0
PX Idle Wait 836 830 170,455 2039 0.3
SQL*Net message to client 205,556 0 52 0 63.6
SQL*Net more data from clien 103 0 2 0 0.0
-------------------------------------------------------------
^LBackground Wait Events for DB: POINT Instance: POINT Snaps: 98 - 99

Avg
Total Wait wait Waits
Event Waits Timeouts Time (cs) (ms) /txn
---------------------------- ------------ ---------- ----------- ----- ------
log file parallel write 3,251 0 980 3 1.0
db file parallel write 1,097 0 659 6 0.3
control file parallel write 903 0 339 4 0.3
db file scattered read 74 0 59 8 0.0
latch free 14 11 19 14 0.0
db file sequential read 18 0 16 9 0.0
control file sequential read 19 0 2 1 0.0
rdbms ipc message 25,995 5,382 2,126,644 818 8.0
pmon timer 1,003 868 277,734 2769 0.3
smon timer 9 9 276,458 ##### 0.0
-------------------------------------------------------------
^LSQL ordered by Gets for DB: POINT Instance: POINT Snaps: 98 - 99

Gets % of
Buffer Gets Executes per Exec Total Hash Value
-------------- ------------ ------------ ------ ------------
SQL statement
------------------------------------------------------------------------------
2,529,602 4 632,400.5 30.9 1132031452
SELECT /*+ FIRST_ROWS */ Whendate__,PRIMARYKEY,Status,Priority,ForeignKey,When

1,264,899 1 1,264,899.0 15.5 2069064965
SELECT /*+ FIRST_ROWS */ Whendate__,PRIMARYKEY,Status,Priority,ForeignKey,Type

673,170 5 134,634.0 8.2 2251869451
SELECT /*+ FIRST_ROWS */ LINENUMBER,ACCTNUMBER,CUSTNUMBER,SERVCODE,ACTIVEDATE,

578,968 8 72,371.0 7.1 2488240846
SELECT /*+ FIRST_ROWS */ CUS.RECORDTYPE,CUS.CUSTNUMBER,CUS.NAME,CUS.TYPE,CUS.C

217,301 134 1,621.6 2.7 333582979
SELECT /*+ FIRST_ROWS */ Whendate__,PRIMARYKEY,Status,Priority,Type,Why,Whenda

194,240 2,013 96.5 2.4 1371574077
SELECT /*+ FIRST_ROWS */ * FROM PCR_SYSDDB SDB WHERE FETCHID=(SELECT /*+ FIRST

129,058 1 129,058.0 1.6 3507863592
SELECT /*+ FIRST_ROWS */ ACCTNUMBER,CUSTNUMBER,LINENUMBER,SERVCODE,ACTIVEDATE,

123,911 27 4,589.3 1.5 2344561510
SELECT /*+ FIRST_ROWS */ CUS.RECORDTYPE,CUS.CUSTNUMBER,CUS.NAME,CUS.TYPE,CUS.C

107,550 2 53,775.0 1.3 303765711
SELECT /*+ FIRST_ROWS */ Whendate__,PRIMARYKEY,Status,Priority,Type,Why,Whenda

71,892 1 71,892.0 .9 1541492399
SELECT /*+ FIRST_ROWS */ * FROM TP_CUSTOMER CUS WHERE (UPPER(LASTNAME)=:1) AND

53,794 2 26,897.0 .7 4274864533
SELECT /*+ FIRST_ROWS */ Whendate__,PRIMARYKEY,Status,Priority,Type,Why,Whenda

53,775 1 53,775.0 .7 463364931
SELECT /*+ FIRST_ROWS */ Whendate__,PRIMARYKEY,Status,Priority,Type,Why,Whenda

Hi TOm,

Sorry for this, but I dont understand what you meant. Did you mean that the buffer gets of the queries in my database are "BAD". Are they that high? If i do get a low cost from them using explain plan, would that be enough? Thanks for your valuable time. And if you can direct me to a nice doc on statspack and buffer gets. did u discuss them in your book? thanks.

Hi Tom,

If I'd like to see the plan of a query without really executing it, all I need is to "explain plan" it. Is there a tool I can use to view the statistics like consistent gets, physical reads, executions,etc, the information we see when we set autotrace on for statistics without actually executing the sql statement?

Thanks.

I took a 75 min snap of statspack and found the most expensive
query:
Buffer Gets Executions Gets per Exec % Total Hash Value
--------------- ------------ -------------- ------- ------------
259,672,818 25,108 10,342.2 55.5 2531437174
SELECT COUNT(*) FROM MTL_ITEM_REVISIONS_INTERFACE WHERE ((ORG
ANIZATION_ID = :b1 AND INVENTORY_ITEM_ID = :b2 ) OR (ORGANIZATI
ON_ID = :b1 AND ITEM_NUMBER = :b4 )) AND REVISION = :b5 AND SE
T_PROCESS_ID = :b6

apps@prod1> @plan
QUERY_PLAN
------------------------------------------------------------
SORT AGGREGATE
CONCATENATION
TABLE ACCESS BY INDEX ROWID MTL_ITEM_REVISIONS_INTERFACE
INDEX RANGE SCAN MTL_ITEM_REVS_INTERFACE_N4
TABLE ACCESS BY INDEX ROWID MTL_ITEM_REVISIONS_INTERFACE
INDEX RANGE SCAN MTL_ITEM_REVS_INTERFACE_N2

6 rows selected.

Do you think the Gets per Exec = 10,342.2?

Thanks

"
tell me -- what does the code that invoke this count do with the results??

yes, 10k gets / query for a query that is executed over 5 times a SECOND is
horrible.
"
It's Oracle APPS 11.5.7 and I am new to the site. Do not know what's code has the query. I may find that later

"
it looks like a query from PLSQL given the name of the binds -- you might try
looking in ALL_SOURCE for the code
"
What's effective method to find the code name, I used

select distinct name from dba_source where text like
'%SELECT COUNT(*) FROM MTL_ITEM_REVISIONS_INTERFACE%'
/
It has not come back yet.

Hi Tom,

How can I reduce LIO's. I mean, you can give me an example of a query that has so much LIO then reduce it. Hope you can help me on this. This would help me in resolving those
queries that could possibly have to much LIO's in our system. Thanks a lot.

Hi again Tom,

I forgot too. Is there a way of determining the LIO'S of sql statements that have been executed in the database. Can v$sqlarea show this (buffer_gets column). Thanks.

To Rory:
If only the first login is slow, then it could be a network problem. We had a similar problem, where the server was trying to find the hostname via DNS, and there was none. It takes the server a few minutes to give up, and look at the hosts file.

Hope it helps.
Chris

To Chris:

Thanks for the advise. The problem is like this. There are times when the users will complain that they can't login or database has simply hang. Now if that happened when I am logged in (even as sys in sqlplus or svrmgrl), I would hang too when I would execute a query. If I'm not logged in, I would not be able to login and appear to hang. I checked the os for top processes and saw two belonging to Oracle. I found out that they were p000 processes, meaning they're for parallel query right? So I thought this might be the problem. Somebody might be executing queries in parallel. But after 10 mins of hang and everything is smooth again, I saw that the two oracle processes were still at the top of the processes as seen in the os and still the same percentage playing from 95-102%. Were could the problem be? Cant run statspack since I cant log in. Thanks for anybody's help. Thanks Tom for the answers and they're really a big help.

Hi Tom,


Our database is configured only for dedicated connection. Shared server connection or MTS is not configured for this specific database. I was also thinking that there might be LIO's or waits... but why affect log in too? Cant think of anything yet. My database is 8.1.7 running on IBM AIX. There are abt 200 users logged in with just a create session privilege and all the objects they need to access have public synonyms. Security is done in the front end. Still curious why it could affect even svrmgrl. By the way, I can log in via server manager and the hang will take place when I query. Thanks a lot Tom for the help.

Hi Tom,

It happened again this afternoon. Seems like the whole system is waiting for something to finish. Just dont know how I could get that wait after the hang. But what could that wait be that could cause even a query in server manager to halt. Is iit possible for everyone to be locked out whenever a query is executed by a certain user that could perhaps have heavy LIO. Reflecting on the knowledge I have learned here, whenver a query is executed, it's looked at in the shared_pool for shared resources then when it's ready, the data is searched buffer cache using some function. I'm really curious on this one. It happens at different times. It lasted for 15 minutes.
Here are some of the data I was able to gather after the hang. Dont know if they are meaningful.

SVRMGR> select * from v$waitstat
2> order by count asc;
CLASS COUNT TIME
------------------ ---------- ----------
sort block 0 0
save undo block 0 0
save undo header 0 0
free list 0 0
bitmap block 0 0
extent map 0 0
system undo block 0 0
system undo header 0 0
bitmap index block 1 0
unused 10 42
segment header 83 295
undo header 244 1572
undo block 1257 281
data block 54918547 8721332
14 rows selected.

I spooled the content of v$sesstat after the hang but did not paste it here. Tell me if u need to see it and what particular statistic is need. I spooled by individual sid. I didnt do any summing. I'm really curious on this one. Thanks a lot.

P.S.
It's Saturday tomorrow so I may be able to see your response on Monday. But I'll try to surf tomorrow. The machine after all is a production one. And I need to solve this quickly.

Hi Tom,

Yes I am in a supported version, 8.1.7. I'll try to get a statspack every 30 mins. That'll be continuous until I'm able to catch the problem. THen I'll post here again. I'll try to post the statspack report here of when the problem occured. Million thanks for your help.

Hi

quoting one of your answers

"that would be neat -- "without actually running the query -- tell me how many blocks it'll get from the cache, read from disk, recursive sql calls it'll make"

How do we know how many blocks Oracle will get from cache/buffer and disk??? Consistent gets seems out of question since it´s not the number of blocks.

Cheers

Hi

but everytime I change my array size consistent gets changes, does that mean Oracle reads different number of blocks.... everytime?

Hi

I have a table with around 1 million rows, I ran your show_space proc and had this result

exec show_space('CLDOM_DOMICILIOS', 'TGCGCT10')

Free Blocks.............................
Total Blocks............................18688
Total Bytes.............................153092096
Total MBytes............................146
Unused Blocks...........................256
Unused Bytes............................2097152
Last Used Ext FileId....................7
Last Used Ext BlockId...................41096
Last Used Block.........................768

I have 16MB DB Cache, I tried first ararysize of 15 then 200

tgcgct10@LNX920>select * from CLDOM_DOMICILIOS where CLENT_COD_CLIENTE = 2796;

100304 rows selected.


Execution Plan
----------------------------------------------------------
0 SELECT STATEMENT Optimizer=CHOOSE (Cost=2 Card=276 Bytes=28152)

1 0 TABLE ACCESS (BY INDEX ROWID) OF 'CLDOM_DOMICILIOS' (Cost=2 Card=276 Bytes=28152)

2 1 INDEX (RANGE SCAN) OF 'CLDOM_DOMICILIOS_IDX1' (NON-UNIQUE) (Cost=1 Card=276)

Statistics
----------------------------------------------------------
0 recursive calls
0 db block gets
15701 consistent gets
2501 physical reads
0 redo size
12747329 bytes sent via SQL*Net to client
74045 bytes received via SQL*Net from client
6688 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
100304 rows processed

tgcgct10@LNX920>set arraysize 200
tgcgct10@LNX920>select * from CLDOM_DOMICILIOS where CLENT_COD_CLIENTE = 2796;

100304 rows selected.


Execution Plan
----------------------------------------------------------
0 SELECT STATEMENT Optimizer=CHOOSE (Cost=2 Card=276 Bytes=28152)

1 0 TABLE ACCESS (BY INDEX ROWID) OF 'CLDOM_DOMICILIOS' (Cost=2 Card=276 Bytes=28152)

2 1 INDEX (RANGE SCAN) OF 'CLDOM_DOMICILIOS_IDX1' (NON-UNIQUE) (Cost=1 Card=276)

Statistics
----------------------------------------------------------
0 recursive calls
0 db block gets
3493 consistent gets
2495 physical reads
0 redo size
11998944 bytes sent via SQL*Net to client
6010 bytes received via SQL*Net from client
503 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
100304 rows processed


as you can see I have different consistent gets (15701 vs 3493), from these results how can I know how many blocks my query actually read in the buffer....?

Thank you a lot for you advices :-D

Hi again

First thanks for your patience and replies.

Secondly, I am 100% confused now. In your previous reply you said

"consistent gets IS the number of blocks Oracle will get from the cache. that is exactly what consistent gets is"

Number of blocks == Consistent gets

So how come a query needs to read different number of blocks in the buffer even the execution plan is exact....? I can see they read same number of blocks from disk but from the buffer it does not.

Thirdly, i did a TKPROF and two questions came up (look the TKPROF paste)

select *
from
CLDOM_DOMICILIOS where CLENT_COD_CLIENTE = 2796


call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 10032 1.68 2.63 1845 22272 0 100304
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 10034 1.68 2.63 1845 22272 0 100304

Misses in library cache during parse: 0
Optimizer goal: CHOOSE
Parsing user id: 58

Rows Row Source Operation
------- ---------------------------------------------------
100304 TABLE ACCESS BY INDEX ROWID CLDOM_DOMICILIOS
100304 INDEX RANGE SCAN CLDOM_DOMICILIOS_IDX1 (object id 29805)

********************************************************************************

select *
from
TGCGCT10.CLDOM_DOMICILIOS where CLENT_COD_CLIENTE = 2796


call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1005 2.031026955720.17 1838 4479 0 100304
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 1007 2.031026955720.17 1838 4479 0 100304

Misses in library cache during parse: 0
Optimizer goal: CHOOSE
Parsing user id: 58

My first concern is why in the second query TKPROF does not show

Rows Row Source Operation
------- -----------------------------------------------

like the first one

The second concern is what is the funny elapsed number 1026955720.17 in the second query....?

I am using Oracle EE 9.2.0.1

Cheers

Well, I cannot address the "funny number" -- other then to say either

o your trace file is truncated and those results are suspect (this would answer the "why there is not query plan for the second query" -- it is written last, after the cursor is closed

o there is an issue on your platform with tracing that I'm not aware of...


The reasons you don't have a query plan for the second query are either

o see above -- trace file truncated
o or you did this in sqlplus or some other environment and you did not EXIT that environment.  The stat records are written at the end.



The differnce (as seen right above in your other exmaple) is the array fetch size.


Lets take a simplier exmaple.  A full scan.  Say you have a table with 100 blocks in it.  You have 50 rows per block as follows:

ops$tkyte@ORA817DEV> create table t ( x int );
Table created.

ops$tkyte@ORA817DEV> insert into t select 1 from all_objects where rownum <= 50;
50 rows created.


ops$tkyte@ORA817DEV> alter table t minimize records_per_block;
Table altered.

ops$tkyte@ORA817DEV> insert into t select 1 from all_objects where rownum <= 50*99;
4950 rows created.

ops$tkyte@ORA817DEV> select min(count(*)), max(count(*)), avg(count(*))
  2    from t
  3   group by dbms_rowid.rowid_block_number(rowid)
  4  /

MIN(COUNT(*)) MAX(COUNT(*)) AVG(COUNT(*))
------------- ------------- -------------
           50            50            50

ops$tkyte@ORA817DEV> select count(distinct dbms_rowid.rowid_block_number(rowid) )
  2    from t
  3  /

COUNT(DISTINCTDBMS_ROWID.ROWID_BLOCK_NUMBER(ROWID))
---------------------------------------------------
                                                100

<b>so, 100 blocks, 50 rows per block.  Let's select * from this table -- but fetch 10 rows at a time:</b>

ops$tkyte@ORA817DEV> set autotrace traceonly
ops$tkyte@ORA817DEV> set arraysize 10
ops$tkyte@ORA817DEV> select * from t;

5000 rows selected.


Execution Plan
----------------------------------------------------------
   0      SELECT STATEMENT Optimizer=CHOOSE
   1    0   TABLE ACCESS (FULL) OF 'T'


Statistics
----------------------------------------------------------
          0  recursive calls
          4  db block gets
        603  consistent gets
...
       5000  rows processed

<b>Ok, so what happened?  600 logical IO's.  600 reads from the buffer cache... how could that be?  well, this is what happened:

you asked for rows 1..10
server got block 1 from cache (latched it), copied it (unlatched it)
server gave you rows 1..10
you asked for rows 11..20
server got block 1 from cache AGAIN (2 logical ios now)...
you asked for rows 21..30
server got block 1 from cache AGAIN (3)
you asked for rows 31..40
server got block 1 from cache AGAIN (4)
you asked for rows 41..50
server got block 1 from cache AGAIN (5)
you asked for rows 51..60
server got block 1 from cache AGAIN (6)
found no data, got block 2          (7)
......


you read each and every block about 6 times.  6*100 = 600.  </b>


ops$tkyte@ORA817DEV> set arraysize 50
ops$tkyte@ORA817DEV> select * from t;

5000 rows selected.


Statistics
----------------------------------------------------------
          0  recursive calls
          4  db block gets
        203  consistent gets
...
       5000  rows processed


<b>Now, you can see what happened here -- rows 1..50 = block 1, 51..100 = block1+block2 and so on...</b>


ops$tkyte@ORA817DEV> set arraysize 100
ops$tkyte@ORA817DEV> select * from t;

5000 rows selected.


Statistics
----------------------------------------------------------
          0  recursive calls
          4  db block gets
        153  consistent gets
....
       5000  rows processed

ops$tkyte@ORA817DEV> set autotrace off
ops$tkyte@ORA817DEV>

<b>and so on.  So, the larger the array size, the less consistent gets we needed to perform in order to answer your question.  The less logical IO's we did.  The less latching we did

The main difference between your two queries above is the array size.  In one example, you used an array size of 10.  You got and re-got the same block(s) over and over.  In the second case, you used 100 -- you got a block once and read the entire thing and never needed to get it again.</b>



 

the first query used arraysize 10 and the second arraysize 100

Hi

I fixed the first issue regarding

Rows Row Source Operation

I had to quit my session in order to get that part generated in my trace file, or simply I had to issue another SQL stmt.

Cheers

So I conclude

Number of blocks != Consistent gets

Guess we have to query v$bh to find the number of blocks read from buffer for a query!

Cheers

Tom, where is this script located - I can't find it in $ORACLE_HOME\rdbms\admin?

Many thanks in advance

Thanks, prima!

Tom,

What do you recommend(size) for arraysize, should we keep 10 or 15 or 50 or 100 or depending on how many records we want to grab.

Thanks

Hi Tom,

You mentioned:

"that stinks -- I hope the code isn't something silly like:


select count(*) into l_cnt .....

if ( l_cnt != 0 ) then...."

If it happens to be that way, then how would you suggest changing it? I have some procedures doing the same thing. Thanks in advance.

Kashif

Unless you actually need to no the number of
rows then there iwhy count them all?

The code Tom says stinks is quite common
when people want to check for existence of
any rows, they really aren't interested in how many
rows in total there are

Heres a quick example I found on tom's Site

select count(*)
from dual
where exists ( select NULL
from emp
where sal = 5000 );

that'll return 0 or 1. It'll stop looking at the emp table the instant it finds
one row.

Hi Tom,
Would you still recommend the use of "SELECT Count(*) FROM DUAL ..." syntax if you know that the query that you have will return no more than one row?
In such a case, should we use the "SELECT Count(*) FROM <table> WHERE <condition>" syntax or still use the DUAL construct?
Or maybe, there is another alternative to figuring out if the given input matches a row (The case I'm talking about is when the Input will match either one row or not match at all).

Hi Tom,

In the case that we want just to check whether there is any record in the Table or not. I mean we are just looking for "YES" or "NO" answer not the number of records in the table. You recommended useing of the following syntax:

SELECT count(*)
FROM table_name
WHERE condition
AND rownum = 1;

I was wondering is there any other way to do it? Because our Software should work on MSSQL & SQLAnywhere databases as well and these databases doesn't have rownum ! I need a synatx which works for all three vendors.

Thanks in advance,
Arash Zaryoun

Thank you so much. I got it.

hi

in one of recent responses you said

select count(*) into l_cnt from t where user = :x;
if ( l_cnt != 0 )
then
for x in ( select *from t where user = :x )
loop
...

should just be the loop;

How do you change that code into a FOR loop...? I mean how do you put the count part into the cursor?

Hi Tom,

One the guys in our group said that in Oracle 8.0.5 to use utlbstat/utlestat we have to buy license for that..

How far is that true??

Tom,

I got two databases on UAT and one PROD both the same size. In fact the UAT was created from the Prod last week using Exp/Imp.

I got a query that goes against two tables, one about 20 Mil rows and the other 120 Mil rows. When I do a explain plan or a Autotrace or a Sql Trace, it shows the exact same exact plan and cost for both.

But when I execute the query, one shows a lot higher consistent gets. Mind it is the same no. of rows. Any idea what is going on?


Thanks,

John.


Prod Output...

xecution Plan
----------------------------------------------------------
0 SELECT STATEMENT Optimizer=CHOOSE (Cost=26705 Card=1 Bytes=1
74)

1 0 FILTER* :Q360080
01

2 1 SORT* (GROUP BY) (Cost=26705 Card=1 Bytes=174) :Q360080
01

3 2 NESTED LOOPS* (Cost=26696 Card=1 Bytes=174) :Q360080
00

4 3 NESTED LOOPS* (Cost=26693 Card=1 Bytes=141) :Q360080
00

5 4 NESTED LOOPS* (Cost=26691 Card=2 Bytes=238) :Q360080
00

6 5 NESTED LOOPS* (Cost=26690 Card=1 Bytes=108) :Q360080
00

7 6 NESTED LOOPS* (Cost=26687 Card=3 Bytes=258) :Q360080
00

8 7 TABLE ACCESS* (FULL) OF 'DSTS2_ORDER_HEADER' :Q360080
(Cost=26678 Card=3 Bytes=198) 00

9 7 INDEX* (RANGE SCAN) OF 'ORDEA_PK' (UNIQUE) ( :Q360080
Cost=3 Card=21259213 Bytes=425184260) 00

10 6 TABLE ACCESS* (FULL) OF 'DSTS2_CBPF_FEATURE' ( :Q360080
Cost=1 Card=95 Bytes=2090) 00

11 5 INDEX* (FAST FULL SCAN) OF 'USOC_PK' (UNIQUE) (C :Q360080
ost=1 Card=3253 Bytes=35783) 00

12 4 TABLE ACCESS* (BY INDEX ROWID) OF 'DSTS2_CBPF' (Co :Q360080
st=1 Card=6 Bytes=132) 00

13 12 INDEX* (UNIQUE SCAN) OF 'XPKDSTS2_CBPF' (UNIQUE) :Q360080
00

14 3 TABLE ACCESS* (BY INDEX ROWID) OF 'DSTS2_ORDER_DETAI :Q360080
L' (Cost=3 Card=108011197 Bytes=3564369501) 00

15 14 INDEX* (UNIQUE SCAN) OF 'ORDED_PK' (UNIQUE) (Cost= :Q360080
2 Card=108011197) 00



1 PARALLEL_COMBINED_WITH_CHILD
2 PARALLEL_TO_SERIAL SELECT A1.C0,A1.C1,A1.C2,A1.C3,A1.C4,A1.C5,A
1.C6,A1.C7,A1.C8,A1.C9,A1.C10,A1.C11

3 PARALLEL_TO_PARALLEL SELECT /*+ ORDERED NO_EXPAND USE_NL(A2) INDE
X(A2 "ORDED_PK") */ A1.C0 C0,A1.C13

4 PARALLEL_COMBINED_WITH_PARENT
5 PARALLEL_COMBINED_WITH_PARENT
6 PARALLEL_COMBINED_WITH_PARENT
7 PARALLEL_COMBINED_WITH_PARENT
8 PARALLEL_COMBINED_WITH_PARENT
9 PARALLEL_COMBINED_WITH_PARENT
10 PARALLEL_COMBINED_WITH_PARENT
11 PARALLEL_COMBINED_WITH_PARENT
12 PARALLEL_COMBINED_WITH_PARENT
13 PARALLEL_COMBINED_WITH_PARENT
14 PARALLEL_COMBINED_WITH_PARENT
15 PARALLEL_COMBINED_WITH_PARENT


Statistics
----------------------------------------------------------
35 recursive calls
4112372 db block gets
23209109 consistent gets
438179 physical reads
692 redo size
54709 bytes sent via SQL*Net to client
3200 bytes received via SQL*Net from client
27 SQL*Net roundtrips to/from client
17 sorts (memory)
0 sorts (disk)
380 rows processed





UAT output......



Execution Plan
----------------------------------------------------------
0 SELECT STATEMENT Optimizer=CHOOSE (Cost=13489 Card=1 Bytes=2
25)

1 0 FILTER* :Q268001
2 1 SORT* (GROUP BY) (Cost=13489 Card=1 Bytes=225) :Q268001
3 2 SORT* (GROUP BY) (Cost=13489 Card=1 Bytes=225) :Q268000
4 3 NESTED LOOPS* (Cost=13464 Card=1 Bytes=225) :Q268000
5 4 NESTED LOOPS* (Cost=13462 Card=1 Bytes=192) :Q268000
6 5 NESTED LOOPS* (Cost=13461 Card=1 Bytes=181) :Q268000
7 6 NESTED LOOPS* (Cost=13460 Card=1 Bytes=142) :Q268000
8 7 NESTED LOOPS* (Cost=13458 Card=3 Bytes=255) :Q268000
9 8 TABLE ACCESS* (FULL) OF 'DSTS2_ORDER_HEADE :Q268000
R' (Cost=13452 Card=3 Bytes=198)

10 8 INDEX* (RANGE SCAN) OF 'ORDEA_PK' (UNIQUE) :Q268000
(Cost=3 Card=20635299 Bytes=392070681)

11 7 TABLE ACCESS* (FULL) OF 'DSTS2_CBPF_FEATURE' :Q268000
(Cost=1 Card=164 Bytes=9348)

12 6 TABLE ACCESS* (BY INDEX ROWID) OF 'DSTS2_CBPF' :Q268000
(Cost=1 Card=164 Bytes=6396)

13 12 INDEX* (UNIQUE SCAN) OF 'XPKDSTS2_CBPF' (UNI :Q268000
QUE)

14 5 INDEX* (RANGE SCAN) OF 'USOC_PK' (UNIQUE) (Cost= :Q268000
2 Card=3235 Bytes=35585)

15 4 TABLE ACCESS* (BY INDEX ROWID) OF 'DSTS2_ORDER_DET :Q268000
AIL' (Cost=3 Card=105300331 Bytes=3474910923)

16 15 INDEX* (UNIQUE SCAN) OF 'ORDED_PK' (UNIQUE) (Cos :Q268000
t=2 Card=105300331)



1 PARALLEL_COMBINED_WITH_CHILD
2 PARALLEL_TO_SERIAL SELECT /*+ CIV_GB */ A1.C0,A1.C1,A1.C2,A1.C3
,A1.C4,A1.C5,A1.C6,A1.C7,A1.C8,A1.C9

3 PARALLEL_TO_PARALLEL SELECT /*+ PIV_GB */ A1.C0 C0,A1.C13 C1,A1.C
22 C2,A1.C1 C3,A1.C9 C4,A1.C10 C5,A1

4 PARALLEL_COMBINED_WITH_PARENT
5 PARALLEL_COMBINED_WITH_PARENT
6 PARALLEL_COMBINED_WITH_PARENT
7 PARALLEL_COMBINED_WITH_PARENT
8 PARALLEL_COMBINED_WITH_PARENT
9 PARALLEL_COMBINED_WITH_PARENT
10 PARALLEL_COMBINED_WITH_PARENT
11 PARALLEL_COMBINED_WITH_PARENT
12 PARALLEL_COMBINED_WITH_PARENT
13 PARALLEL_COMBINED_WITH_PARENT
14 PARALLEL_COMBINED_WITH_PARENT
15 PARALLEL_COMBINED_WITH_PARENT
16 PARALLEL_COMBINED_WITH_PARENT


Statistics
----------------------------------------------------------
45 recursive calls
125 db block gets
218665 consistent gets
212231 physical reads
692 redo size
1167 bytes sent via SQL*Net to client
314 bytes received via SQL*Net from client
1 SQL*Net roundtrips to/from client
27 sorts (memory)
0 sorts (disk)
0 rows processed

Also the Block Size in UAT is twice of Prodcution. Hence the difference in Physical reads.

John.

Temp is setup temporary on UAT and regular permenant Files on Prod. But all Sorts are in Memory as the stats show. The time difference and consistent gets is probably in the nested loop join as longops goes idle after 2 - 3 mins. No Table or Index scans after that.

THANKS!!!

John.

Tom,

The Queries are different in one table being different
along the nested loop heirarchy.

Anyway I managed to tweak the order of the Join using " ORDERED " Hint and found alteast 3 combinations a lot faster than the Oracle decided way. I might be able to find several more if I test all combinations. Mind all the tables used in this query have been analyzed compute with all indexes and indexed columns.

My question is why is Oracle not even choosing one of the better patha from say the top 5 out of 20 - 30 possible combinations. Is The Optimizer not as efficient as Oracle markets?

John.

tom,

Version : 9i Release 2 on Win-2k(this query is fired on the bean to get the data)

recently we wrote a view that has link with 10 tables..from the tx screen we got to show most of the information for the master, so we require desc for each code..

our query return such a plan below...i require some understanding on why so many nested loops there ?? This query takes long time to come!!! Why ? ..below the plan i have pasted the query too..


PLAN_TABLE_OUTPUT

---------------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost |
---------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | |
|* 1 | TABLE ACCESS BY INDEX ROWID | T_POTENTIAL_AGENT | | | |
| 2 | NESTED LOOPS | | | | |
| 3 | NESTED LOOPS | | | | |
| 4 | NESTED LOOPS | | | | |
| 5 | NESTED LOOPS | | | | |
| 6 | NESTED LOOPS | | | | |
| 7 | NESTED LOOPS | | | | |
| 8 | NESTED LOOPS | | | | |
| 9 | NESTED LOOPS | | | | |
| 10 | NESTED LOOPS | | | | |
| 11 | NESTED LOOPS | | | | |
| 12 | NESTED LOOPS | | | | |
| 13 | NESTED LOOPS | | | | |
| 14 | NESTED LOOPS | | | | |
| 15 | NESTED LOOPS | | | | |
| 16 | NESTED LOOPS | | | | |
| 17 | TABLE ACCESS FULL | T_EXAMSETTINGS | | | |
|* 18 | TABLE ACCESS BY INDEX ROWID| T_AGENT_RANK | | | |
|* 19 | INDEX RANGE SCAN | PK_AGENT_RANK | | | |
| 20 | TABLE ACCESS BY INDEX ROWID | T_AGENT_RANK | | | |
|* 21 | INDEX RANGE SCAN | PK_AGENT_RANK | | | |
| 22 | TABLE ACCESS BY INDEX ROWID | T_AGENT_TIER | | | |
|* 23 | INDEX RANGE SCAN | PK_AGENT_TIER | | | |
| 24 | TABLE ACCESS BY INDEX ROWID | T_TITLE | | | |
|* 25 | INDEX RANGE SCAN | PK_TITLE | | | |
| 26 | TABLE ACCESS BY INDEX ROWID | T_EXAM_TIMETABLE | | | |
|* 27 | INDEX RANGE SCAN | PK_EXAM_TIMETABLE | | | |
| 28 | TABLE ACCESS BY INDEX ROWID | T_LANGUAGE | | | |
|* 29 | INDEX RANGE SCAN | PK_LANGUAGE | | | |
| 30 | TABLE ACCESS BY INDEX ROWID | T_SERVICE_CENTRE | | | |
|* 31 | INDEX RANGE SCAN | PK_SERVICE_CENTRE | | | |
|* 32 | TABLE ACCESS BY INDEX ROWID | T_REG_AGENT | | | |
|* 33 | INDEX RANGE SCAN | PK_REG_AGENT | | | |
| 34 | TABLE ACCESS BY INDEX ROWID | T_DEPARTMENT | | | |
|* 35 | INDEX RANGE SCAN | PK_DEPARTMENT | | | |
| 36 | TABLE ACCESS BY INDEX ROWID | T_BANKBRANCH | | | |
|* 37 | INDEX RANGE SCAN | PK_BANKBRANCH | | | |
| 38 | TABLE ACCESS BY INDEX ROWID | T_AGENT_CATEGORY | | | |
|* 39 | INDEX RANGE SCAN | PK_AGENT_CATEGORY | | | |
| 40 | TABLE ACCESS BY INDEX ROWID | T_RELIGION | | | |
|* 41 | INDEX RANGE SCAN | PK_RELIGION | | | |
| 42 | TABLE ACCESS BY INDEX ROWID | T_QUALIFICATION | | | |
|* 43 | INDEX RANGE SCAN | PK_QUALIFICATION | | | |
| 44 | TABLE ACCESS BY INDEX ROWID | T_NATIONALITY | | | |
|* 45 | INDEX RANGE SCAN | PK_NATIONALITY | | | |
|* 46 | INDEX RANGE SCAN | PK_POTENTIAL_AGENT | | | |
---------------------------------------------------------------------------------------------------

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

1 - filter("A"."AGENT_CENTER_CODE"="L"."CENTRE_CODE" AND "A"."RECRUITED_BY"="A"."AGENT_CODE"
AND "A"."DEPT_CODE"="J"."DEPT_CODE" AND "A"."BRANCH_CODE"="I"."BRANCH_CODE" AND "A
"."AGENT_CAT"="H"."AGENT_CAT" AND "A"."AGENT_LEVEL"="A"."AGENT_LEVEL" AND "A"."AGE
NT_RANK"="A"."AGENT_RANK" AND "A"."RELIGION_CODE"="E"."RELIGION_CODE" AND "A"."QUA
LIFICATION_CODE"="D"."QUALIFICATION_CODE" AND "A"."RACE_CODE"="C"."RACE_CODE" AND
"A"."TITLE_CODE"="B"."TITLE_CODE")
18 - filter("B"."RECDL_YN"='Y')
19 - access("B"."RECTYPE"='L')
21 - access("A"."RECTYPE"='L')
23 - access("A"."RECTYPE"="B"."RECTYPE" AND "A"."AGENT_TIER"="B"."AGENT_TIER")
filter("A"."AGENT_TIER"="B"."AGENT_TIER")
25 - access("B"."RECTYPE"='L')
filter("B"."RECTYPE"="A"."RECTYPE")
27 - access("P"."RECTYPE"="B"."RECTYPE" AND "M"."EXAM_DATE"="P"."EXAM_DATE")
filter("M"."EXAM_DATE"="P"."EXAM_DATE")
29 - access("B"."RECTYPE"="O"."RECTYPE" AND "M"."LANG_CODE"="O"."LANG_CODE")
filter("M"."LANG_CODE"="O"."LANG_CODE")
31 - access("B"."RECTYPE"="L"."RECTYPE")
32 - filter("A"."AGENT_RANK"="B"."AGENT_RANK")
33 - access("B"."RECTYPE"="A"."RECTYPE")
35 - access("B"."RECTYPE"="J"."RECTYPE")
37 - access("B"."RECTYPE"="I"."RECTYPE")
39 - access("B"."RECTYPE"="H"."RECTYPE")
41 - access("B"."RECTYPE"="E"."RECTYPE")
43 - access("B"."RECTYPE"="D"."RECTYPE")
45 - access("B"."RECTYPE"="C"."RECTYPE")
46 - access("A"."RECTYPE"="M"."RECTYPE" AND "A"."AGENT_CODE"="M"."AGENT_CODE")
filter("A"."AGENT_CODE"="M"."AGENT_CODE" AND "A"."RECTYPE"<>'H')

Note: rule based optimization


SELECT
A.*,
M.EXAM_DATE,
M.EXAM_NUMBER,
M.FEE_AMOUNT,
M.LANG_CODE AS EXAM_LANG_CODE,
M.LOCATION,
M.PAY_REF AS EXAM_PAY_REF,
M.RESIT_DATE,
M.RESULT,
B.TITLE_DESC,
C.RACE_DESC,
D.QUALIFICATION_DESC,
E.RELIGION_DESC
--,F.COUNTRY_DESC,F.STATE_DESC,F.REGION_DESC
,G.AGENT_DESC,
G.TIER_DESC,
H.CAT_DESC,
I.BRANCH_DESC,
J.DEPT_DESC,
K.AGENT_NAME AS RECRUITER_NAME,
K.RANK_DESC AS RECRUITER_RANK_NAME
,L.CENTRE_DESC,
O.LANG_DESC,
P.RESULT_DATE,'' AS AGE
--N.CITY_DESC AS EXAM_CITY_DESC,
FROM
T_POTENTIAL_AGENT A,
T_TITLE B,
T_NATIONALITY C,
T_QUALIFICATION D,
T_RELIGION E,
VW_RANK_TIER G,
T_AGENT_CATEGORY H,
T_BANKBRANCH I,
T_DEPARTMENT J,
VW_AGENT_RANK K,
T_SERVICE_CENTRE L,
T_EXAMSETTINGS M,
T_LANGUAGE O,
T_EXAM_TIMETABLE P
--,T_POSTCODE N,
--,VW_LIVE_POSTCODE F
WHERE
-- A TO M CONDITION
A.AGENT_CODE=M.AGENT_CODE
AND A.RECTYPE <> 'H'
AND A.RECTYPE=M.RECTYPE
-- A TO B CONDITION
AND A.TITLE_CODE=B.TITLE_CODE
AND B.RECTYPE='L'
-- A TO C CONDITION
AND A.RACE_CODE=C.RACE_CODE
AND B.RECTYPE=C.RECTYPE
-- A TO D CONDITION
AND A.QUALIFICATION_CODE=D.QUALIFICATION_CODE
AND B.RECTYPE=D.RECTYPE
-- A TO E CONDITION
AND A.RELIGION_CODE=E.RELIGION_CODE
AND B.RECTYPE=E.RECTYPE
-- A TO F CONDITION
--AND A.POST_CODE=F.POST_CODE
--AND A.COUNTRY_CODE=F.COUNTRY_CODE
--AND F.RECTYPE=B.RECTYPE
-- A TO G CONDITION
AND A.AGENT_RANK=G.AGENT_RANK
AND A.AGENT_LEVEL=G.AGENT_LEVEL
AND B.RECTYPE=G.RECTYPE
-- A TO H CONDITION
AND A.AGENT_CAT=H.AGENT_CAT
AND B.RECTYPE=H.RECTYPE
-- A TO I CONDITION
AND A.BRANCH_CODE=I.BRANCH_CODE
AND B.RECTYPE=I.RECTYPE
-- A TO J CONDITION
AND A.DEPT_CODE=J.DEPT_CODE
AND B.RECTYPE=J.RECTYPE
-- A TO K CONDITION
AND A.RECRUITED_BY=K.AGENT_CODE
AND B.RECTYPE=K.RECTYPE
-- A TO N CONDITION
--AND N.RECTYPE=B.RECTYPE
--AND M.LOCATION=N.POST_CODE
-- A TO L CONDITION
AND A.AGENT_CENTER_CODE=L.CENTRE_CODE
AND B.RECTYPE=L.RECTYPE
-- M TO O CONDITION
AND M.LANG_CODE=O.LANG_CODE
AND B.RECTYPE=O.RECTYPE
-- A TO P CONDITION
AND M.EXAM_DATE=P.EXAM_DATE
AND P.RECTYPE=B.RECTYPE

Rgds

should be less than 5000 Rows TOM...

Hi, Tom,

what parse/execute ratio is considered high ?


BT

Hi

Read some of your replies above about set arraysize and reducing consistent gets. I wonder, can this use to improve batch processes?

For example if I have a query using 10 table-join which returns 2 million of rows and spooled to text file will it run faster if I use a larger arraysize?

Would it work for Materialized View refresh??

Hi Tom,

We are trying to run multiple inserts on a table from different sessions and it is going very slow. I have read some articles about v$waitstat but I am still not clear on how to use it to solve my problems. Can you please provide some help with this?

Thanks.

can you please detail on array processing and freelists? i am new to performance tuning and i do not know about these concepts.
the insert time is 2 mins when compared to milliseconds, which is what it shud normally take (this is in comparison to other projects where we have similar tables.

Thanks.

Tom,

How would one implement arraysize if the java programs are calling stored procedures?

Thanks.

Opps..I was thinking in terms of set arraysize N :-)

Thanks..

hi Tom,

this is reg the slow inserts to the table which was taking about 2 mins. after i altered the table to have multiple freelists, now it has reduced to about 50 secs to 1 min. now i have sql_trace and timed_statistics on and it has generated some trace files. i did a tkprof and i have the text file. how do i interpret this output. can u give a detailed explanation please?

thanks.

what does the elapsed field in the tkprof output mean? b'cos in the trace file total is like 3 but elapsed is anywhere between 7 - 11. do you want me to post some output with such high elapsed values???

thanks.

i am sorry i guess i just misunderstood something. please see below a part of the tkprof output which has the sql query and the most time taken in the total line.

SELECT (SELECT count(*)
from
t where tid = t1.col1 and col2 = 'S') FROM t1
WHERE numcol = 1

call count cpu elapsed disk query current rows

Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1 1.81 7.06 9397 23645 0 1

total 3 1.81 7.07 9397 23645 0 1

is there anyway this query can be rewritten? Thanks.

you said that "elapsed is more than cpu time". that will always be the case isnt it?? since elapsed time = cpu tim + wait time

Hi,

I was expecting a similar problem but after I analyzed the tables involved the results were extremely fast (in milliseconds contrary to minutes). So is it a good practise that we analyze tables often? what is the recommended practise ?

Thanks.

so what are the effects of
alter table <tablename> monitoring.

what does it do and are there any negative effects I should be aware of.

I have a query which took hours to run

select
l.loan_blk_no,
l.loan_lot_no,
' '||c.cust_lname||', '||c.cust_fname||' '||extract_mi(c.cust_mname)||'.' cust_name,
ag.group_code,
l.loan_selling_price,
decode(lt.loan_description,'CASH',l.loan_selling_price,l.loan_value) loan_value,
lt.loan_description,
l.loan_reservation_fee,
l.loan_proc_date,
reservation_paid(l.loan_acct_no,:p_date) reservation_amount,
nvl(l.loan_reservation_fee,0)-nvl(reservation_paid(l.loan_acct_no,:p_date),0) res_balance,
NVL(l.loan_equity,0)-nvl(l.loan_reservation_fee,0)-nvl(l.loan_downpayment,0) loan_equity,
equity_paid(l.loan_acct_no,:p_date) equity_amount,
nvl(l.loan_equity,0)-nvl(l.loan_reservation_fee,0)-nvl(l.loan_downpayment,0)-nvl(equity_paid(l.loan_acct_no,:p_date),0) balance,
decode(decode(sign(nvl(l.loan_equity,0)-
nvl(l.loan_reservation_fee,0)-
nvl(l.loan_downpayment,0)-
nvl(equity_paid(l.loan_acct_no,:p_date),0)),0,0,-1,0,1,1)+
decode(sign(months_in_debt(:p_date,l.loan_acct_no)),-1,0,0,0,1,1),0,'Paid',1,'Updated',2,to_char(months_in_debt(:p_date,l.loan_acct_no),'999')||' mos. in arrears')||' '
||decode(submitted_pdc(l.loan_acct_no),'Y','w/PDC','N','w/o PDC') remarks
from loans l,
customers c,
loan_types lt,
brokers b,
agency_group ag
where l.loan_cust_no=c.cust_cust_no
and l.loan_type=lt.loan_type
and l.loan_broker=b.broker_code
and b.broker_group=ag.group_name
and upper(l.loan_units_status)='SOLD'
and nvl(lt.in_house_tag,'N')='N'
and nvl(lt.cash_tag,'N')='N'
and l.loan_proc_date<=:p_date
and l.loan_proj_code=:p_proj_code
order by to_number(l.loan_blk_no),lpad(l.loan_lot_no,15,'0')

equity_paid, months_in_debt and submitted_pdc are database functions.

function equity_paid(p_loan_acct_no in number,p_date in date) return number is
n_paid number;
begin
select nvl(sum(pay_amount),0)
into n_paid
from equity_payments
where nvl(pay_tag,'N')='Y'
and pay_date_applied<=p_date
and pay_fee_code in
(select fee_code
from other_charges
where nvl(equity_tag,'N')='Y')
and pay_loan_no=p_loan_acct_no;
RETURN(N_PAID);
exception
when no_data_found then return(0);
END;

FUNCTION MONTHS_IN_DEBT(P_DATE IN DATE,P_LOAN IN LOANS.LOAN_ACCT_NO%TYPE) RETURN NUMBER IS
v_months number;
v_running_principal number:=0;
v_total_payments number;
v_total_amort_payments number;
v_pay_date date;
v_date date;
cursor c_equity_schedule is
select equity_sched_due_date,
NVL(equity_sched_prin,0)+NVL(equity_sched_int,0) total_principal
from equity_amort_sched
where equity_sched_loan_no=p_loan
order by equity_sched_due_date;
rt_equity_schedule c_equity_schedule%rowtype;
begin
select sum(nvl(equity_sched_prin,0)+nvl(equity_sched_int,0))
into v_total_amort_payments
from equity_amort_sched
where equity_sched_loan_no=p_loan;

select NVL(sum(pay_amount),0)
into v_total_payments
from equity_payments
where pay_tag='Y'
and downpayment='Y';
and pay_loan_no=p_loan

dbms_output.put_line(to_char(v_pay_date)||' '||to_char(v_total_payments));
open c_equity_schedule;
fetch c_equity_schedule into rt_equity_schedule;
v_running_principal:=v_running_principal+rt_equity_schedule.total_principal;
v_date:=rt_equity_schedule.equity_sched_due_date;
if v_total_amort_payments = 0 then
return(0);
else
while v_running_principal <= v_total_payments loop
fetch c_equity_schedule into rt_equity_schedule;
v_running_principal:=v_running_principal+rt_equity_schedule.total_principal;
v_date:=rt_equity_schedule.equity_sched_due_date;
end loop;
end if;
close c_equity_schedule;
if p_date > v_date then
return(ceil(months_between(trunc(p_date),trunc(v_date))));
-- return(trunc(greatest(sysdate,v_pay_date)-trunc(v_date)));
else
return(0);
end if;
end;

FUNCTION SUBMITTED_PDC(loan_acct_no in number) return varchar is
cursor c_equity_payments is
select 'x'
from equity_payments
where pay_pdc_generated_date is not null
and pay_loan_no=loan_acct_no;
v_submitted_pdc varchar2(1):='N';
begin
for a in c_equity_payments loop
v_submitted_pdc:='Y';
exit;
end loop;
return(v_submitted_pdc);
end;

v_ledger_w_equity_payments view
(select p.pay_no pay_no,
ps.equity_sched_due_date due_date,
p.pay_date date_paid,
p.pay_amount paid_amount,
p.pay_type pay_type,
p.pay_check_no check_no,
p.pay_check_date check_date,
p.pay_bank_name bank_name,
p.pay_or_no or_no,
p.pay_or_date or_date,
l.equity_ledger_principal applied_prin,
l.equity_ledger_interest applied_int,
l.equity_ledger_penalty applied_penalty,
l.equity_ledger_days_late days_late,
nvl(l.equity_ledger_principal,0) +
nvl(l.equity_ledger_interest,0) +
nvl(l.equity_ledger_penalty,0) applied_total,
l.equity_ledger_amortno_applied amort_no_applied,
l.equity_ledger_pay_sched_no pay_sched_no,
p.pay_loan_no loan_no
from equity_payments p,
equity_amort_sched ps,
equity_ledger l
where l.equity_ledger_pay_no = p.pay_no
and l.equity_ledger_pay_sched_no = ps.equity_sched_no(+)
and nvl(p.pay_tag,'N')='Y'
and nvl(p.downpayment,'N')='Y')

Can you help me on how I could tune this query??? Many thanks

I have a query which took hours to run

select
l.loan_blk_no,
l.loan_lot_no,
' '||c.cust_lname||', '||c.cust_fname||' '||extract_mi(c.cust_mname)||'.' cust_name,
ag.group_code,
l.loan_selling_price,
decode(lt.loan_description,'CASH',l.loan_selling_price,l.loan_value) loan_value,
lt.loan_description,
l.loan_reservation_fee,
l.loan_proc_date,
reservation_paid(l.loan_acct_no,:p_date) reservation_amount,
nvl(l.loan_reservation_fee,0)-nvl(reservation_paid(l.loan_acct_no,:p_date),0) res_balance,
NVL(l.loan_equity,0)-nvl(l.loan_reservation_fee,0)-nvl(l.loan_downpayment,0) loan_equity,
equity_paid(l.loan_acct_no,:p_date) equity_amount,
nvl(l.loan_equity,0)-nvl(l.loan_reservation_fee,0)-nvl(l.loan_downpayment,0)-nvl(equity_paid(l.loan_acct_no,:p_date),0) balance,
decode(decode(sign(nvl(l.loan_equity,0)-
nvl(l.loan_reservation_fee,0)-
nvl(l.loan_downpayment,0)-
nvl(equity_paid(l.loan_acct_no,:p_date),0)),0,0,-1,0,1,1)+
decode(sign(months_in_debt(:p_date,l.loan_acct_no)),-1,0,0,0,1,1),0,'Paid',1,'Updated',2,to_char(months_in_debt(:p_date,l.loan_acct_no),'999')||' mos. in arrears')||' '
||decode(submitted_pdc(l.loan_acct_no),'Y','w/PDC','N','w/o PDC') remarks
from loans l,
customers c,
loan_types lt,
brokers b,
agency_group ag
where l.loan_cust_no=c.cust_cust_no
and l.loan_type=lt.loan_type
and l.loan_broker=b.broker_code
and b.broker_group=ag.group_name
and upper(l.loan_units_status)='SOLD'
and nvl(lt.in_house_tag,'N')='N'
and nvl(lt.cash_tag,'N')='N'
and l.loan_proc_date<=:p_date
and l.loan_proj_code=:p_proj_code
order by to_number(l.loan_blk_no),lpad(l.loan_lot_no,15,'0')

equity_paid, months_in_debt and submitted_pdc are database functions.

function equity_paid(p_loan_acct_no in number,p_date in date) return number is
n_paid number;
begin
select nvl(sum(pay_amount),0)
into n_paid
from equity_payments
where nvl(pay_tag,'N')='Y'
and pay_date_applied<=p_date
and pay_fee_code in
(select fee_code
from other_charges
where nvl(equity_tag,'N')='Y')
and pay_loan_no=p_loan_acct_no;
RETURN(N_PAID);
exception
when no_data_found then return(0);
END;

FUNCTION MONTHS_IN_DEBT(P_DATE IN DATE,P_LOAN IN LOANS.LOAN_ACCT_NO%TYPE) RETURN NUMBER IS
v_months number;
v_running_principal number:=0;
v_total_payments number;
v_total_amort_payments number;
v_pay_date date;
v_date date;
cursor c_equity_schedule is
select equity_sched_due_date,
NVL(equity_sched_prin,0)+NVL(equity_sched_int,0) total_principal
from equity_amort_sched
where equity_sched_loan_no=p_loan
order by equity_sched_due_date;
rt_equity_schedule c_equity_schedule%rowtype;
begin
select sum(nvl(equity_sched_prin,0)+nvl(equity_sched_int,0))
into v_total_amort_payments
from equity_amort_sched
where equity_sched_loan_no=p_loan;

select NVL(sum(pay_amount),0)
into v_total_payments
from equity_payments
where pay_tag='Y'
and downpayment='Y';
and pay_loan_no=p_loan

dbms_output.put_line(to_char(v_pay_date)||' '||to_char(v_total_payments));
open c_equity_schedule;
fetch c_equity_schedule into rt_equity_schedule;
v_running_principal:=v_running_principal+rt_equity_schedule.total_principal;
v_date:=rt_equity_schedule.equity_sched_due_date;
if v_total_amort_payments = 0 then
return(0);
else
while v_running_principal <= v_total_payments loop
fetch c_equity_schedule into rt_equity_schedule;
v_running_principal:=v_running_principal+rt_equity_schedule.total_principal;
v_date:=rt_equity_schedule.equity_sched_due_date;
end loop;
end if;
close c_equity_schedule;
if p_date > v_date then
return(ceil(months_between(trunc(p_date),trunc(v_date))));
-- return(trunc(greatest(sysdate,v_pay_date)-trunc(v_date)));
else
return(0);
end if;
end;

FUNCTION SUBMITTED_PDC(loan_acct_no in number) return varchar is
cursor c_equity_payments is
select 'x'
from equity_payments
where pay_pdc_generated_date is not null
and pay_loan_no=loan_acct_no;
v_submitted_pdc varchar2(1):='N';
begin
for a in c_equity_payments loop
v_submitted_pdc:='Y';
exit;
end loop;
return(v_submitted_pdc);
end;

v_ledger_w_equity_payments view
(select p.pay_no pay_no,
ps.equity_sched_due_date due_date,
p.pay_date date_paid,
p.pay_amount paid_amount,
p.pay_type pay_type,
p.pay_check_no check_no,
p.pay_check_date check_date,
p.pay_bank_name bank_name,
p.pay_or_no or_no,
p.pay_or_date or_date,
l.equity_ledger_principal applied_prin,
l.equity_ledger_interest applied_int,
l.equity_ledger_penalty applied_penalty,
l.equity_ledger_days_late days_late,
nvl(l.equity_ledger_principal,0) +
nvl(l.equity_ledger_interest,0) +
nvl(l.equity_ledger_penalty,0) applied_total,
l.equity_ledger_amortno_applied amort_no_applied,
l.equity_ledger_pay_sched_no pay_sched_no,
p.pay_loan_no loan_no
from equity_payments p,
equity_amort_sched ps,
equity_ledger l
where l.equity_ledger_pay_no = p.pay_no
and l.equity_ledger_pay_sched_no = ps.equity_sched_no(+)
and nvl(p.pay_tag,'N')='Y'
and nvl(p.downpayment,'N')='Y')

The last column in the query took most of the time to execute.

Can you help me on how I could tune this query??? Many thanks

Hi Tom,

My company has been using 3rd party tools in order to check Oracle performance and health.

I emphisized the need and ease of using Statspack, when compared to other products. You and me know how inadequate and awkward they can be :)

This is a mission-critical environment, with terabytes of storage and what.

They want some "proof" (as you say) that stastpack will not affect peformance.

**You** and **I** know that's not an issue. But they're ignorant, they don't. I'm afraid Statspack may become a "scapegoat" if something that's been running for years stops.

How could I "prove" to them that statspack is not so "dangerous" ?

In sum, where do you think I could get info on the workload involved in its execution ?

Besides my personal stress tests (yep, it's really stressing !), I'd like to have some documented feedback. Where could I get that ?

Thank you, pal.

Can you please help me figure out what could be causing the same process to run longer in a seemingly faster server?

Here are the details.

Test database instance: HKRS. Database server Sun Fire 6800, 12 CPUs @1.2GHz, 32 GB RAM
Production database instance: HKRP. Database server Sun Fire 15K, 16 CPUs @1.2GHz, 56 GB RAM

I run a daily batch composed of many tasks and noticed one task running too slow in Production.
This application is a third party product so I do not own nor have access to the code.

I imported the production database into the test instance and the same application runs much faster in test. The task that runs in 2.5 hours in production takes 1 hour in test. The Production server is not heavily loaded, "top" reports CPU states at an average of 50% idle. Both test and prod are using ASSM.

Included below are Statspack reports for both instances. The difference in snapshot times is due to the fact that test runs faster than PROD and test gets to the slow running task earlier than PROD.

Can you please give me some idea as to why the Insert in the top SQL on HKRP (production) has so many more Buffer Gets and Gets Per Exec than the same statement on HKRS (Test)?

I trimmed out some parts of the statspack reports to make this message a bit more readable. Please let me know if I removed anything that you may need to get a better picture of what's happening.

Thank you for your time.

=====================================================================
STATSPACK REPORT FOR TEST INSTANCE:
=====================================================================


STATSPACK report for

DB Name DB Id Instance Inst Num Release Cluster Host
------------ ----------- ------------ -------- ----------- ------- ------------
HKRS 250250253 hkrs 1 9.2.0.7.0 NO testdb

Snap Id Snap Time Sessions Curs/Sess Comment
--------- ------------------ -------- --------- -------------------
Begin Snap: 94 23-Jan-06 14:45:03 35 1.2
End Snap: 95 23-Jan-06 15:00:04 35 1.2
Elapsed: 15.02 (mins)

Cache Sizes (end)
~~~~~~~~~~~~~~~~~
Buffer Cache: 128M Std Block Size: 8K
Shared Pool Size: 64M Log Buffer: 10,240K

Load Profile
~~~~~~~~~~~~ Per Second Per Transaction
--------------- ---------------
Redo size: 2,404,860.06 169,306.06
Logical reads: 22,475.01 1,582.28
Block changes: 10,911.62 768.20
Physical reads: 623.42 43.89
Physical writes: 725.26 51.06
User calls: 36.34 2.56
Parses: 14.90 1.05
Hard parses: 0.00 0.00
Sorts: 3,944.03 277.67
Logons: 0.01 0.00
Executes: 15.37 1.08
Transactions: 14.20

% Blocks changed per Read: 48.55 Recursive Call %: 31.68
Rollback per transaction %: 0.01 Rows per Sort: 1.33

Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Buffer Nowait %: 99.70 Redo NoWait %: 99.99
Buffer Hit %: 97.30 In-memory Sort %: 100.00
Library Hit %: 99.98 Soft Parse %: 99.97
Execute to Parse %: 3.09 Latch Hit %: 99.01
Parse CPU to Parse Elapsd %: 72.67 % Non-Parse CPU: 99.86

Shared Pool Statistics Begin End
------ ------
Memory Usage %: 91.36 91.46
% SQL with executions>1: 71.53 71.31
% Memory for SQL w/exec>1: 61.40 61.33

Top 5 Timed Events
~~~~~~~~~~~~~~~~~~ % Total
Event Waits Time (s) Ela Time
-------------------------------------------- ------------ ----------- --------
free buffer waits 5,493 3,161 41.95
db file sequential read 539,508 1,229 16.31
io done 51,607 915 12.15
CPU time 811 10.77
write complete waits 950 673 8.92
-------------------------------------------------------------
Wait Events for DB: HKRS Instance: hkrs Snaps: 94 -95
-> 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
---------------------------- ------------ ---------- ---------- ------ --------
free buffer waits 5,493 1,654 3,161 575 0.4
db file sequential read 539,508 0 1,229 2 42.2
io done 51,607 0 915 18 4.0
write complete waits 950 459 673 708 0.1
buffer busy waits 61,011 38 274 4 4.8
log file sync 12,923 14 246 19 1.0
db file parallel write 1,669 0 100 60 0.1
latch free 15,552 11,869 81 5 1.2
direct path write 756 0 11 14 0.1
log file switch completion 338 0 10 29 0.0
enqueue 263 0 10 37 0.0
db file parallel read 2,392 0 7 3 0.2
SQL*Net more data to client 62,271 0 5 0 4.9
control file parallel write 550 0 2 3 0.0
log file parallel write 11,503 0 1 0 0.9
direct path read 804 0 1 1 0.1
LGWR wait for redo copy 1,238 0 0 0 0.1
log file single write 42 0 0 2 0.0
db file scattered read 32 0 0 3 0.0
control file sequential read 523 0 0 0 0.0
log file sequential read 42 0 0 0 0.0
imm op 34 0 0 0 0.0
SQL*Net break/reset to clien 2 0 0 0 0.0
buffer deadlock 70 68 0 0 0.0
SQL*Net message from client 32,692 0 5,077 155 2.6
i/o slave wait 23,549 1,053 3,543 150 1.8
PX Idle Wait 1,791 1,791 3,510 1960 0.1
SQL*Net more data from clien 112,019 0 15 0 8.8
SQL*Net message to client 32,691 0 0 0 2.6
-------------------------------------------------------------
Background Wait Events for DB: HKRS Instance: hkrs Snaps: 94 -95
-> ordered by wait time desc, waits desc (idle events last)

Avg
Total Wait wait Waits
Event Waits Timeouts Time (s) (ms) /txn
---------------------------- ------------ ---------- ---------- ------ --------
io done 51,606 0 916 18 4.0
db file parallel write 1,669 0 100 60 0.1
direct path write 399 0 8 20 0.0
buffer busy waits 9 1 2 256 0.0
control file parallel write 550 0 2 3 0.0
log file parallel write 11,503 0 1 0 0.9
latch free 269 47 1 3 0.0
LGWR wait for redo copy 1,238 0 0 0 0.1
enqueue 14 0 0 26 0.0
direct path read 399 0 0 0 0.0
log file single write 42 0 0 2 0.0
control file sequential read 465 0 0 0 0.0
log file sequential read 42 0 0 0 0.0
db file sequential read 42 0 0 0 0.0
imm op 34 0 0 0 0.0
i/o slave wait 23,548 1,053 3,543 150 1.8
rdbms ipc message 7,837 522 3,383 432 0.6
smon timer 40 0 901 22517 0.0
pmon timer 298 298 875 2937 0.0
-------------------------------------------------------------
SQL ordered by Gets for DB: HKRS Instance: hkrs Snaps: 94 -95
-> 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
--------------- ------------ -------------- ------ -------- --------- ----------
9,795,541 5,490 1,784.3 48.4 357.16 2252.86 516601529
Module: JDBC Thin Client
DELETE FROM RM_FRCST_WS_BKNG_CNCL
WHERE PRPRTY_CODE = :1 AND ROOM_T
YPE_CODE = :2 AND RATE_TYPE_CODE = :3
AND DOW = :4 AND BKNG_REGION_C
ODE = :5 AND SRVC_DATE = :6

5,854,624 6,161 950.3 28.9 175.58 1885.69 1951372070
Module: JDBC Thin Client
INSERT INTO RM_FRCST_WS_BKNG_CNCL ( DIME
NSION_KEY, PRPRTY_CODE,
ROOM_TYPE_CODE, RATE_TYPE_CODE,
DOW, BKNG_REGION
_CODE, SRVC_DATE,

1,780,189 45 39,559.8 8.8 112.18 855.89 1286824502
Module: JDBC Thin Client
select DIMENSION_KEY, PRPRTY_CODE,
ROOM_TYPE_CODE, RATE_
TYPE_CODE, DOW,
BKNG_REGION_CODE, SRVC_DATE,
FRCST_DATE, DCP,

SQL ordered by Reads for DB: HKRS Instance: hkrs Snaps: 94 -95
Top 5 Logical Reads per Segment for DB: HKRS Instance: hkrs Snaps: 94 -95
-> End Segment Logical Reads Threshold: 10000

Subobject Obj. Logical
Owner Tablespace Object Name Name Type Reads %Total
---------- ---------- -------------------- ---------- ----- ------------ -------
HRMS HRMS_LRG_I RM_FRCST_WS_BKNG_CNC INDEX 9,316,288 47.91
HRMS HRMS_LRG_I RM_FRCST_WS_SHWP_PK HWP_PK_MAX INDEX 455,664 2.34
HRMS HRMS_LRG_I RM_FRCST_WS_BKNG_CNC INDEX 372,480 1.92
HRMS HRMS_LRG_I RM_FRCST_WS_SHWP_IX2 INDEX 322,176 1.66
HRMS HRMS_LRG_I RM_FRCST_WS_SHWP_IX1 INDEX 307,760 1.58
-------------------------------------------------------------


Top 5 Physical Reads per Segment for DB: HKRS Instance: hkrs Snaps: 94 -95
-> End Segment Physical Reads Threshold: 1000

Subobject Obj. Physical
Owner Tablespace Object Name Name Type Reads %Total
---------- ---------- -------------------- ---------- ----- ------------ -------
HRMS HRMS_LRG_I RM_FRCST_WS_BKNG_CNC INDEX 61,380 11.34
HRMS HRMS_LRG_I RM_FRCST_WS_SHWP_PK HWP_PK_MAX INDEX 25,237 4.66
HRMS HRMS_LRG_I RM_BLEND_WS_PK _WS_PK_MAX INDEX 15,411 2.85
HRMS HRMS_LRG_I RM_FRCST_WS_BKNG_CNC INDEX 15,213 2.81
HRMS HRMS_LRG_D RM_FRCST_WS_BKNG_CNC NCL_200701 TABLE 14,556 2.69
-------------------------------------------------------------
Top 5 Buf. Busy Waits per Segment for DB: HKRS Instance: hkrs Snaps: 94 -95
-> End Segment Buffer Busy Waits Threshold: 100

Buffer
Subobject Obj. Busy
Owner Tablespace Object Name Name Type Waits %Total
---------- ---------- -------------------- ---------- ----- ------------ -------
HRMS HRMS_LRG_I RM_FRCST_WS_BKNG_CNC INDEX 7,798 12.96
HRMS HRMS_LRG_D RM_FRCST_WS_BKNG_CNC NCL_200701 TABLE 2,961 4.92
HRMS HRMS_LRG_D RM_FRCST_WS_BKNG_CNC NCL_200607 TABLE 2,231 3.71
HRMS HRMS_LRG_D RM_FRCST_WS_BKNG_CNC NCL_200608 TABLE 2,183 3.63
HRMS HRMS_LRG_D RM_FRCST_WS_BKNG_CNC NCL_200707 TABLE 2,126 3.53
-------------------------------------------------------------


Top 5 Row Lock Waits per Segment for DB: HKRS Instance: hkrs Snaps: 94 -95
-> End Segment Row Lock Waits Threshold: 100

Row
Subobject Obj. Lock
Owner Tablespace Object Name Name Type Waits %Total
---------- ---------- -------------------- ---------- ----- ------------ -------
HRMS HRMS_LRG_I RM_BLEND_WS_PK _WS_PK_MAX INDEX 231 18.73
HRMS HRMS_LRG_I RM_BLEND_WS_IX1 INDEX 168 13.63
HRMS HRMS_LRG_I RM_BLEND_WS_PK _PK_200607 INDEX 100 8.11
HRMS HRMS_LRG_I RM_BLEND_WS_PK _PK_200606 INDEX 99 8.03
HRMS HRMS_LRG_I RM_BLEND_WS_PK _PK_200603 INDEX 87 7.06
-------------------------------------------------------------


Top 5 ITL Waits per Segment for DB: HKRS Instance: hkrs Snaps: 94 -95
-> End Segment ITL Waits Threshold: 100

Subobject Obj. ITL
Owner Tablespace Object Name Name Type Waits %Total
---------- ---------- -------------------- ---------- ----- ------------ -------
HRMS HRMS_LRG_I RM_BLEND_WS_IX1 INDEX 4 50.00
HRMS HRMS_LRG_I RM_FRCST_WS_BKNG_CNC INDEX 2 25.00
HRMS HRMS_LRG_I RM_BLEND_WS_PK RM_BLEND_W INDEX 1 12.50
HRMS HRMS_LRG_I RM_BLEND_WS_PK RM_BLEND_W INDEX 1 12.50
-------------------------------------------------------------
End of Report


=====================================================================
STATSPACK REPORT FOR PRODUCTION INSTANCE
=====================================================================

STATSPACK report for

DB Name DB Id Instance Inst Num Release Cluster Host
------------ ----------- ------------ -------- ----------- ------- ------------
HKRP 2819810203 hkrp 1 9.2.0.5.0 NO proddb

Snap Id Snap Time Sessions Curs/Sess Comment
------- ------------------ -------- --------- -------------------
Begin Snap: 536 23-Jan-06 16:45:22 30 1.7
End Snap: 537 23-Jan-06 17:00:14 29 1.6

Elapsed: 14.87 (mins)

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

Load Profile
~~~~~~~~~~~~ Per Second Per Transaction
--------------- ---------------
Redo size: 1,168,291.47 169,449.75
Logical reads: 57,390.33 8,323.93
Block changes: 5,359.45 777.34
Physical reads: 128.87 18.69
Physical writes: 199.39 28.92
User calls: 17.97 2.61
Parses: 7.47 1.08
Hard parses: 0.02 0.00
Sorts: 2,050.24 297.37
Logons: 0.01 0.00
Executes: 7.94 1.15
Transactions: 6.89

% Blocks changed per Read: 9.34 Recursive Call %: 35.98
Rollback per transaction %: 0.02 Rows per Sort: 1.32

Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Buffer Nowait %: 99.94 Redo NoWait %: 100.00
Buffer Hit %: 99.78 In-memory Sort %: 100.00
Library Hit %: 99.81 Soft Parse %: 99.68
Execute to Parse %: 5.90 Latch Hit %: 99.76
Parse CPU to Parse Elapsd %: 64.41 % Non-Parse CPU: 99.93

Shared Pool Statistics Begin End
------ ------
Memory Usage %: 93.58 93.82
% SQL with executions>1: 92.09 91.54
% Memory for SQL w/exec>1: 93.48 92.98

Top 5 Timed Events
~~~~~~~~~~~~~~~~~~ % Total
Event Waits Time (s) Ela Time
-------------------------------------------- ------------ ----------- --------
db file sequential read 114,101 3,018 39.36
CPU time 1,608 20.97
free buffer waits 1,570 1,513 19.72
buffer busy waits 30,115 625 8.15
log file sync 6,208 267 3.49
-------------------------------------------------------------
Wait Events for DB: HKRP Instance: hkrp Snaps: 536 -537
-> 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 114,101 0 3,018 26 18.6
free buffer waits 1,570 1,472 1,513 963 0.3
buffer busy waits 30,115 64 625 21 4.9
log file sync 6,208 0 267 43 1.0
write complete waits 232 222 226 976 0.0
enqueue 100 33 104 1043 0.0
latch free 17,025 16,234 79 5 2.8
db file parallel write 436 0 62 142 0.1
log file parallel write 6,274 5,057 28 4 1.0
log file sequential read 1,008 0 25 25 0.2
control file parallel write 351 0 13 37 0.1
db file parallel read 193 0 12 65 0.0
log file switch completion 56 0 6 116 0.0
async disk IO 1,964 0 4 2 0.3
log buffer space 112 0 3 27 0.0
SQL*Net more data to client 29,701 0 3 0 4.8
undo segment extension 1,066,335 1,066,334 1 0 173.4
db file scattered read 42 0 0 5 0.0
LGWR wait for redo copy 192 0 0 0 0.0
control file sequential read 402 0 0 0 0.1
direct path read 96 0 0 0 0.0
direct path write 96 0 0 0 0.0
log file single write 8 0 0 1 0.0
SQL*Net break/reset to clien 4 0 0 0 0.0
buffer deadlock 37 37 0 0 0.0
PX Idle Wait 2,595 2,600 5,229 2015 0.4
SQL*Net message from client 15,945 0 1,038 65 2.6
SQL*Net more data from clien 51,750 0 5 0 8.4
SQL*Net message to client 15,946 0 0 0 2.6
-------------------------------------------------------------
Background Wait Events for DB: HKRP Instance: hkrp Snaps: 536 -537
-> ordered by wait time desc, waits desc (idle events last)

Avg
Total Wait wait Waits
Event Waits Timeouts Time (s) (ms) /txn
---------------------------- ------------ ---------- ---------- ------ --------
enqueue 22 21 65 2949 0.0
db file parallel write 436 0 62 142 0.1
log file parallel write 6,274 5,057 28 4 1.0
log file sequential read 1,008 0 25 25 0.2
control file parallel write 351 0 13 37 0.1
async disk IO 1,964 0 4 2 0.3
db file sequential read 33 0 1 26 0.0
buffer busy waits 11 0 0 28 0.0
latch free 41 17 0 5 0.0
rdbms ipc reply 14 0 0 9 0.0
LGWR wait for redo copy 192 0 0 0 0.0
direct path read 96 0 0 0 0.0
control file sequential read 319 0 0 0 0.1
direct path write 96 0 0 0 0.0
log file single write 8 0 0 1 0.0
rdbms ipc message 13,252 6,028 5,225 394 2.2
smon timer 12 0 888 73998 0.0
pmon timer 297 297 873 2938 0.0
-------------------------------------------------------------
SQL ordered by Gets for DB: HKRP Instance: hkrp Snaps: 536 -537
-> 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
--------------- ------------ -------------- ------ -------- --------- ----------
44,016,528 2,755 15,977.0 86.0 840.79 2896.45 1951372070
Module: JDBC Thin Client
INSERT INTO RM_FRCST_WS_BKNG_CNCL ( DIME
NSION_KEY, PRPRTY_CODE,
ROOM_TYPE_CODE, RATE_TYPE_CODE,
DOW, BKNG_REGION
_CODE, SRVC_DATE,

5,091,213 2,870 1,773.9 9.9 353.11 1357.61 516601529
Module: JDBC Thin Client
DELETE FROM RM_FRCST_WS_BKNG_CNCL
WHERE PRPRTY_CODE =

"before I even read it - on test are you modeling reality."

Test is an exact copy of the production database.

"In production, you are using 100% of 8 cpus. That would be "a couple of users" probably. In test, are you having the same sort of workload??"

There are no "users" here. This is purely a batch job. The same version of the application is installed in test and prod. The test database is a copy of PROD. The only difference is the hardware.


"Ok, so I peeked.
prod <> test version, that is not a really good idea."

What version are you referring to? The application is the same in PROD and test.

"prod time = test time? you said they would not???"

The are both 15 minute snaps but the test snapshot is from 2:45 to 3:00 PM, the PROD snap is from 4:45 to 5:00 PM.
Both batch jobs started at 1:00 PM. The test instance runs faster and runs the slow task from 2:00 to 3:00, the PROD instance runs the slow task from 2:00 to 5:00.


"but - are the concurrency rates even close here - same sort of mix of transactions happening?"

Yes, they are the same apps.

PROD database imported into TEST.
Both batch jobs started at 1:00 using same input so I would expect to see similar timings (or better timings in PROD since the PROD DB server is bigger).

What could be causing the huge difference in Buffer gets and Gets per exec? How can an insert generate such gets??

Thanks.

Hi Tom,

I have setup the second database from Production database. Then gathere statistics.

Execpt one schema, all other schema are working fine with correct time.

But on one schema=> I got following problem:

(1).when I analyse execution plan. It is same as production.

(2). But when execution it takes very long time than production.

Here I paste the statspack output. Could you please give me a clue, about the reason could be?

Note: SGA components and other related files sizes are same as production.


DB Name DB Id Instance Inst Num Release Cluster Host
------------ ----------- ------------ -------- ----------- ------- ------------
VIPR 1863601913 vipr 1 9.2.0.1.0 NO TKAESB24

Snap Id Snap Time Sessions Curs/Sess Comment
------- ------------------ -------- --------- -------------------
Begin Snap: 220 25-Jan-06 17:09:09 13 5.4
End Snap: 221 25-Jan-06 17:13:04 13 5.4
Elapsed: 3.92 (mins)

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

Load Profile
~~~~~~~~~~~~ Per Second Per Transaction
--------------- ---------------
Redo size: 3,778.13 6,165.69
Logical reads: 1,699.89 2,774.13
Block changes: 6.37 10.40
Physical reads: 9.71 15.85
Physical writes: 12.17 19.87
User calls: 7.39 12.06
Parses: 1.91 3.11
Hard parses: 0.00 0.00
Sorts: 1.55 2.53
Logons: 0.00 0.00
Executes: 2.57 4.19
Transactions: 0.61

% Blocks changed per Read: 0.37 Recursive Call %: 33.45
Rollback per transaction %: 99.31 Rows per Sort: ########

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

Shared Pool Statistics Begin End
------ ------
Memory Usage %: 47.24 47.25
% SQL with executions>1: 58.42 58.73
% Memory for SQL w/exec>1: 67.17 67.62

Top 5 Timed Events
~~~~~~~~~~~~~~~~~~ % Total
Event Waits Time (s) Ela Time
-------------------------------------------- ------------ ----------- --------
CPU time 297 99.77
db file sequential read 61 0 .14
control file parallel write 76 0 .03
direct path read 136 0 .03
log file parallel write 25 0 .01
-------------------------------------------------------------
Wait Events for DB: VIPR Instance: vipr Snaps: 220 -221
-> 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 61 0 0 7 0.4
control file parallel write 76 0 0 1 0.5
direct path read 136 0 0 1 0.9
log file parallel write 25 25 0 1 0.2
direct path write 111 0 0 0 0.8
control file sequential read 90 0 0 0 0.6
db file parallel write 12 6 0 1 0.1
log file sync 1 0 0 2 0.0
SQL*Net more data to client 2 0 0 0 0.0
SQL*Net message from client 1,018 0 776 763 7.1
wakeup time manager 8 8 246 30735 0.1
SQL*Net message to client 1,018 0 0 0 7.1
-------------------------------------------------------------
Background Wait Events for DB: VIPR Instance: vipr Snaps: 220 -221
-> ordered by wait time desc, waits desc (idle events last)

Avg
Total Wait wait Waits
Event Waits Timeouts Time (s) (ms) /txn
---------------------------- ------------ ---------- ---------- ------ --------
control file parallel write 76 0 0 1 0.5
log file parallel write 25 25 0 1 0.2
db file parallel write 12 6 0 1 0.1
control file sequential read 28 0 0 0 0.2
rdbms ipc message 339 321 2,783 8209 2.4
smon timer 1 1 307 ###### 0.0
-------------------------------------------------------------
SQL ordered by Gets for DB: VIPR Instance: vipr Snaps: 220 -221
-> 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
--------------- ------------ -------------- ------ -------- --------- ----------
719,546 1 719,546.0 180.1 0.02 296.93 1426524036
Module: SQL*Plus
SELECT t8.idx_cus, t8.idx_from, t8.asof_all, t8.idx_nam, t8.wgh,
t8.fx_cur, t8.asof_last, t9.val, t10.rate FROM (SELECT
ht1.idx_cus, ht1.idx_from, ht1.asof_all, ht1.idx_nam, ht1.wgh,
ht1.fx_cur, CASE
WHEN ht1.asof_part IS NULL THEN ht1.max_asof

.....

Instance Activity Stats for DB: VIPR Instance: vipr Snaps: 220 -221

Statistic Total per Second per Trans
--------------------------------- ------------------ -------------- ------------
CPU used by this session 29,700 126.4 206.3
CPU used when call started 29,700 126.4 206.3
CR blocks created 1 0.0 0.0
Commit SCN cached 0 0.0 0.0
DBWR checkpoint buffers written 70 0.3 0.5
DBWR checkpoints 0 0.0 0.0
DBWR transaction table writes 11 0.1 0.1
DBWR undo block writes 15 0.1 0.1
SQL*Net roundtrips to/from client 1,019 4.3 7.1
active txn count during cleanout 50 0.2 0.4
background checkpoints started 0 0.0 0.0
background timeouts 275 1.2 1.9
branch node splits 0 0.0 0.0
buffer is not pinned count 2,082 8.9 14.5
buffer is pinned count 83,099 353.6 577.1
bytes received via SQL*Net from c 258,987 1,102.1 1,798.5
bytes sent via SQL*Net to client 408,675 1,739.0 2,838.0
calls to get snapshot scn: kcmgss 1,204 5.1 8.4
calls to kcmgas 132 0.6 0.9
calls to kcmgcs 22 0.1 0.2
change write time 1 0.0 0.0
cleanout - number of ktugct calls 56 0.2 0.4
cleanouts and rollbacks - consist 0 0.0 0.0
cleanouts only - consistent read 0 0.0 0.0
cluster key scan block gets 58 0.3 0.4
cluster key scans 24 0.1 0.2
commit cleanout failures: callbac 4 0.0 0.0
commit cleanouts 267 1.1 1.9
commit cleanouts successfully com 263 1.1 1.8
commit txn count during cleanout 30 0.1 0.2
consistent changes 1 0.0 0.0
consistent gets 397,852 1,693.0 2,762.9
consistent gets - examination 117,769 501.1 817.8
cursor authentications 2 0.0 0.0
data blocks consistent reads - un 1 0.0 0.0
db block changes 1,498 6.4 10.4
db block gets 1,622 6.9 11.3
deferred (CURRENT) block cleanout 121 0.5 0.8
enqueue conversions 29 0.1 0.2
enqueue releases 417 1.8 2.9
enqueue requests 417 1.8 2.9
execute count 603 2.6 4.2
free buffer requested 224 1.0 1.6
immediate (CR) block cleanout app 0 0.0 0.0
immediate (CURRENT) block cleanou 57 0.2 0.4
index fast full scans (full) 0 0.0 0.0
index fetch by key 39,448 167.9 273.9
index scans kdiixs1 43,176 183.7 299.8
leaf node 90-10 splits 3 0.0 0.0
leaf node splits 24 0.1 0.2
logons cumulative 0 0.0 0.0
messages received 25 0.1 0.2
messages sent 25 0.1 0.2
no buffer to keep pinned count 0 0.0 0.0
no work - consistent read gets 236,496 1,006.4 1,642.3
opened cursors cumulative 448 1.9 3.1
Instance Activity Stats for DB: VIPR Instance: vipr Snaps: 220 -221

Statistic Total per Second per Trans
--------------------------------- ------------------ -------------- ------------
parse count (failures) 0 0.0 0.0
parse count (hard) 0 0.0 0.0
parse count (total) 448 1.9 3.1
parse time cpu 2 0.0 0.0
parse time elapsed 1 0.0 0.0
physical reads 2,282 9.7 15.9
physical reads direct 2,221 9.5 15.4
physical writes 2,861 12.2 19.9
physical writes direct 2,791 11.9 19.4
physical writes non checkpoint 2,861 12.2 19.9
prefetched blocks 0 0.0 0.0
process last non-idle time 0 0.0 0.0
recursive calls 873 3.7 6.1
recursive cpu usage 40 0.2 0.3
redo blocks written 1,806 7.7 12.5
redo buffer allocation retries 0 0.0 0.0
redo entries 825 3.5 5.7
redo log space requests 0 0.0 0.0
redo log space wait time 0 0.0 0.0
redo size 887,860 3,778.1 6,165.7
redo synch writes 1 0.0 0.0
redo wastage 7,648 32.5 53.1
redo write time 13 0.1 0.1
redo writes 25 0.1 0.2
rollback changes - undo records a 0 0.0 0.0
rollbacks only - consistent read 1 0.0 0.0
rows fetched via callback 183 0.8 1.3
session connect time 0 0.0 0.0
session logical reads 399,474 1,699.9 2,774.1
session pga memory 589,824 2,509.9 4,096.0
session pga memory max 3,276,800 13,943.8 22,755.6
session uga memory 440,816 1,875.8 3,061.2
session uga memory max 2,982,808 12,692.8 20,713.9
shared hash latch upgrades - no w 43,181 183.8 299.9
sorts (disk) 1 0.0 0.0
sorts (memory) 363 1.5 2.5
sorts (rows) 128,624,848 547,339.8 893,228.1
switch current to new buffer 32 0.1 0.2
table fetch by rowid 579 2.5 4.0
table fetch continued row 0 0.0 0.0
table scan blocks gotten 1,526 6.5 10.6
table scan rows gotten 239,398 1,018.7 1,662.5
table scans (long tables) 1 0.0 0.0
table scans (short tables) 162 0.7 1.1
transaction rollbacks 0 0.0 0.0
user calls 1,737 7.4 12.1
user commits 1 0.0 0.0
user rollbacks 143 0.6 1.0
workarea executions - onepass 1 0.0 0.0
workarea executions - optimal 455 1.9 3.2

File IO Stats for DB: VIPR Instance: vipr Snaps: 220 -221
->ordered by Tablespace, File

Tablespace Filename
------------------------ ----------------------------------------------------
Av Av Av Av Buffer Av Buf
Reads Reads/s Rd(ms) Blks/Rd Writes Writes/s Waits Wt(ms)
-------------- ------- ------ ------- ------------ -------- ---------- ------
UNDOTBS01 D:\ORACLE\VIPR\UNDO01_06.DBF
0 0 2 0 0

-------------------------------------------------------------
Buffer Pool Statistics for DB: VIPR Instance: vipr Snaps: 220 -221
-> Standard block size Pools D: default, K: keep, R: recycle
-> Default Pools for other block sizes: 2k, 4k, 8k, 16k, 32k

Free Write Buffer
Number of Cache Buffer Physical Physical Buffer Complete Busy
P Buffers Hit % Gets Reads Writes Waits Waits Waits
--- ---------- ----- ----------- ----------- ---------- ------- -------- ------
D 14,014 100.0 561,864 54 70 0 0 0
-------------------------------------------------------------

Instance Recovery Stats for DB: VIPR Instance: vipr Snaps: 220 -221
-> B: Begin snapshot, E: End snapshot

Targt Estd Log File Log Ckpt Log Ckpt
MTTR MTTR Recovery Actual Target Size Timeout Interval
(s) (s) Estd IOs Redo Blks Redo Blks Redo Blks Redo Blks Redo Blks
- ----- ----- ---------- ---------- ---------- ---------- ---------- ----------
B 22 12 673 5656 14742 14742 18307
E 22 12 770 7153 6744 14742 6744
-------------------------------------------------------------
PGA Aggr Target Histogram for DB: VIPR Instance: vipr Snaps: 220 -221
-> Optimal Executions are purely in-memory operations

Low High
Optimal Optimal Total Execs Optimal Execs 1-Pass Execs M-Pass Execs
------- ------- -------------- ------------- ------------ ------------
8K 16K 393 393 0 0
16K 32K 8 8 0 0
32K 64K 1 1 0 0
64K 128K 2 2 0 0
128K 256K 34 34 0 0
256K 512K 2 2 0 0
512K 1024K 15 15 0 0
4M 8M 1 0 1 0
-------------------------------------------------------------

PGA Memory Advisory for DB: VIPR Instance: vipr End Snap: 221
-> 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
---------- ------- ---------------- ---------------- -------- ----------
14 0.3 219.4 138.9 61.0 4
27 0.5 219.4 115.4 66.0 3
41 0.8 219.4 26.6 89.0 0
54 1.0 219.4 26.6 89.0 0
65 1.2 219.4 26.6 89.0 0
76 1.4 219.4 26.6 89.0 0
86 1.6 219.4 26.6 89.0 0
97 1.8 219.4 26.6 89.0 0
108 2.0 219.4 6.7 97.0 0
162 3.0 219.4 0.0 100.0 0
216 4.0 219.4 0.0 100.0 0
324 6.0 219.4 0.0 100.0 0
432 8.0 219.4 0.0 100.0 0
-------------------------------------------------------------

Hello Tom,

Thanks a lot for helping me so far on different questions.  At times my system goes very slow (9.2.0.6) during that period my login it self takes long time.  During that time I have ran a simple select query on a table and I am pasting the same.  Please give me your valueble suggestion to trouble shoot this and where to look for finding the issue and tuning.

 1* select * from MY_TABLEwhere rownum < 10
SQL> /

9 rows selected.

Elapsed: 00:00:02.68

Execution Plan
----------------------------------------------------------
   0      SELECT STATEMENT Optimizer=CHOOSE
   1    0   COUNT (STOPKEY)
   2    1     TABLE ACCESS (FULL) OF 'MY_TABLE'




Statistics
----------------------------------------------------------
          0  recursive calls
          0  db block gets
       3690  consistent gets
       1064  physical reads
          0  redo size
       4309  bytes sent via SQL*Net to client
        499  bytes received via SQL*Net from client
          2  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
          9  rows processed

SQL> /

9 rows selected.

Elapsed: 00:00:31.22

Execution Plan
----------------------------------------------------------
   0      SELECT STATEMENT Optimizer=CHOOSE
   1    0   COUNT (STOPKEY)
   2    1     TABLE ACCESS (FULL) OF 'MY_TABLE'




Statistics
----------------------------------------------------------
          0  recursive calls
          0  db block gets
       3690  consistent gets
       1134  physical reads
          0  redo size
       4309  bytes sent via SQL*Net to client
        499  bytes received via SQL*Net from client
          2  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
          9  rows processed

SQL> /

9 rows selected.

Elapsed: 00:00:00.89

Execution Plan
----------------------------------------------------------
   0      SELECT STATEMENT Optimizer=CHOOSE
   1    0   COUNT (STOPKEY)
   2    1     TABLE ACCESS (FULL) OF 'MY_TABLE'




Statistics
----------------------------------------------------------
          0  recursive calls
          0  db block gets
       3690  consistent gets
         38  physical reads
          0  redo size
       4309  bytes sent via SQL*Net to client
        499  bytes received via SQL*Net from client
          2  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
          9  rows processed

SQL> /

9 rows selected.

Elapsed: 00:00:01.08

Execution Plan
----------------------------------------------------------
   0      SELECT STATEMENT Optimizer=CHOOSE
   1    0   COUNT (STOPKEY)
   2    1     TABLE ACCESS (FULL) OF 'MY_TABLE'




Statistics
----------------------------------------------------------
          0  recursive calls
          0  db block gets
       3690  consistent gets
         20  physical reads
          0  redo size
       4309  bytes sent via SQL*Net to client
        499  bytes received via SQL*Net from client
          2  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
          9  rows processed

SQL> /

9 rows selected.

Elapsed: 00:00:00.68

Execution Plan
----------------------------------------------------------
   0      SELECT STATEMENT Optimizer=CHOOSE
   1    0   COUNT (STOPKEY)
   2    1     TABLE ACCESS (FULL) OF 'MY_TABLE'




Statistics
----------------------------------------------------------
          0  recursive calls
          0  db block gets
       3690  consistent gets
          0  physical reads
          0  redo size
       4309  bytes sent via SQL*Net to client
        499  bytes received via SQL*Net from client
          2  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
          9  rows processed


***********************************************
After the weekend it show as follows


SQL> /

9 rows selected.

Elapsed: 00:00:00.47

Execution Plan
----------------------------------------------------------
   0      SELECT STATEMENT Optimizer=CHOOSE
   1    0   COUNT (STOPKEY)
   2    1     TABLE ACCESS (FULL) OF 'MY_TABLE'




Statistics
----------------------------------------------------------
          0  recursive calls
          0  db block gets
          5  consistent gets
          0  physical reads
          0  redo size
       4312  bytes sent via SQL*Net to client
        499  bytes received via SQL*Net from client
          2  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
          9  rows processed

With lot less time and very few LILO's.
Please throw some light on this issue.  We have obseverd the system very slow when we had more logical I/O's along with some physical I/O's.
I am not sure why system become very slow some times it took so much time to even to login to ORACLE db.  What could be the problem.
What can cause to go up on LILO's and PIO's in the first few exetuions of the same query?

Thanks for your help.
Prasad.
 

Thanks for your reply. I have checked the CPU utilisation during that period it was not more than 50%. What I am unable to understand is why would this query does so many LIO's along with many physical IO's(under which state of SGA or any db components) where as it is able to get with only 5 Logical IO's when system is responding properly? What could cause to do so much Physical and Logical IO's?

May be too much buffer cache is the problem, becuase it can hold too many datablocks and causes more Logical IO's?
I am confused with this Logical IO thing. I understand that Logical IO's are not good : Please suggest me to resolve this issue.

well, this is easy to reproduce.  You fill up table, empty table, fill up table, empty table (you did a DO IT YOURSELF QUEUE, didn't you...)


consider:

ops$tkyte@ORA10GR2> create table t tablespace mssm as select * from all_objects;
 
Table created.
 
ops$tkyte@ORA10GR2>
ops$tkyte@ORA10GR2>
ops$tkyte@ORA10GR2> set autotrace traceonly statistics;
ops$tkyte@ORA10GR2> select * from t where rownum < 10;
 
9 rows selected.
 
 
Statistics
----------------------------------------------------------
        291  recursive calls
          0  db block gets
        193  consistent gets
        420  physical reads
          0  redo size
       1863  bytes sent via SQL*Net to client
        381  bytes received via SQL*Net from client
          2  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
          9  rows processed

<b>ignore that one, hard parse.... but:</b>
 
ops$tkyte@ORA10GR2> select * from t where rownum < 10;
 
9 rows selected.
 
 
Statistics
----------------------------------------------------------
          0  recursive calls
          0  db block gets
          5  consistent gets
          0  physical reads
          0  redo size
       1863  bytes sent via SQL*Net to client
        381  bytes received via SQL*Net from client
          2  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
          9  rows processed
 
<b>we stop full scanning as soon as we find 9 rows - since the table is "packed", it stops very soon - but now we process lots of records:</b>

ops$tkyte@ORA10GR2> set autotrace off
ops$tkyte@ORA10GR2> delete from t where rownum < (select count(*)-10 from t );
 
50036 rows deleted.
 
ops$tkyte@ORA10GR2> connect /
Connected.

<b>and now to find the first 9, we have to read over lots and lots of EMPTY blocks (full scans start at the "beginning" and go to the "end" - the high water mark "stops" us, we read up to the high water mark and then stop.  Since the "front" of the table is empty - we read lots of empty blocks:</b>

ops$tkyte@ORA10GR2> set autotrace traceonly statistics;
ops$tkyte@ORA10GR2> select * from t where rownum < 10;
 
9 rows selected.
 
 
Statistics
----------------------------------------------------------
          0  recursive calls
          0  db block gets
        693  consistent gets
          0  physical reads
          0  redo size
       1894  bytes sent via SQL*Net to client
        381  bytes received via SQL*Net from client
          2  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
          9  rows processed
 
ops$tkyte@ORA10GR2> select * from t where rownum < 10;
 
9 rows selected.
 
 
Statistics
----------------------------------------------------------
          0  recursive calls
          0  db block gets
        693  consistent gets
          0  physical reads
          0  redo size
       1894  bytes sent via SQL*Net to client
        381  bytes received via SQL*Net from client
          2  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
          9  rows processed
 
ops$tkyte@ORA10GR2> set autotrace off

<b>but now over the weekend, we queue up lots more work to do again:</b>

ops$tkyte@ORA10GR2> insert into t select * from all_objects;
 
50046 rows created.
 
ops$tkyte@ORA10GR2> connect /
Connected.
ops$tkyte@ORA10GR2> set autotrace traceonly statistics;
ops$tkyte@ORA10GR2> select * from t where rownum < 10;
 
9 rows selected.
 
 
Statistics
----------------------------------------------------------
          0  recursive calls
          0  db block gets
          5  consistent gets
          0  physical reads
          0  redo size
       2113  bytes sent via SQL*Net to client
        381  bytes received via SQL*Net from client
          2  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
          9  rows processed
 
ops$tkyte@ORA10GR2> select * from t where rownum < 10;
 
9 rows selected.
 
 
Statistics
----------------------------------------------------------
          0  recursive calls
          0  db block gets
          5  consistent gets
          0  physical reads
          0  redo size
       2113  bytes sent via SQL*Net to client
        381  bytes received via SQL*Net from client
          2  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
          9  rows processed
 
ops$tkyte@ORA10GR2> set autotrace off
ops$tkyte@ORA10GR2>

<b>back down to small full scan - but as we remove rows - it'll take "longer and longer" to retrieve them.
</b> 

Hello Tom,

Continue from previous reply....
Sorry for forgetting to mention that no one truncates this table and irrespective of this table entire database response is slow (really very slow –login it self will take more time.

Thanks
Prasad.

That is great example TOM, as usual. Now I understand why logical IO's are more at one time and got down later. In my example it was doing Physical IO's even after executing couple of time, But in your example it did only once later only logical IO's only this is because when I was executing still it is reading from disk rather reading from buffer?

When the server is performing poorly I check the CPU utilization it was not much, less under 60%. In order to know what is causing slowness you think statspack is the way to find out what is going on the server? along with Disk I/O and netstat.


Thanks Tom
With Regards
Prasad.

Hi Tom,

Statpack is installed and configured to coolect the stats on 30 Mins interval through OS cronjobs.
Noticed jump in the snap id when executing spreport as below.
Instance DB Name Id Snap Started Level
------------ ------------ --------- ----------------- -----
autrnp AUTRNP 1 10 Jul 2006 18:10 5
33 11 Jul 2006 09:45 5
34 11 Jul 2006 10:15 5
35 11 Jul 2006 10:45 5
43 11 Jul 2006 11:15 5

pls. see the jump 35,43. Please explain why the jump happend & Any impact associated?

Thanks & Regards,
Prashanth

What's the timeout for pages on ApEx? Because I can click the above link and I get the 'update' screen.

Hi Tom.
Comment, please this advice from "Oracle9i Administrator's Reference" (Oracle)
"Using Write Behind
The write behind feature enables the operating system to group write I/O s together...The
pages of a particular partition are not written to disk until the program
writes the first byte of the next 16 KB partition"
Will this optimization decrease the database safety ?
(if OS crash before next data chunk writing) ?

But "The file system divides
each file into 16 KB partitions to increase write performance, limit the
number of dirty pages in memory, and minimize disk fragmentation. The
pages of a particular partition are not written to disk until the program
writes the first byte of the next 16 KB partition" - ?

time event
t1 oracle calls write two blocks (2x8kb)
t2 ?os dosn't really write to disk ?
If i think wronk, then
what does the phrase mean "until the program writes the first byte of the next 16 KB" ?
Could you illustrate this ?

You said "
it does the right thing - we wait for confirmation from the OS that the data is
ON DISK before doing anything that assumes the data is on disk." I think as well.
But why oracle documentation recomeds tuning method, that is not useful ?
from ixora:
"Because delayed writes involve a risk of data loss, Oracle never uses them.Oracle insists on the synchronous completion of writes for all buffered I/O to database files"
I'm very confused.

Tom:

Would you be able to exaplin why I am having issues with newly created 9i database in calling some links. The links takes about 2 seconds in 8i versus 70 seconds in 9iR2. I copied the same procedure into another instance of 9i and it ran in 2 seconds.

I did a comparison on the parameter values between the two 9i databases and founf these to be different. Do you see anything that might cause this slowiness. Can it be the archive option?

Parameter 9i DB1 (Slow) 9i DB2 (Fast)
1. 07_DICTIONARY_ACCESSIBILITY TRUE FALSE
2. Db_domain Loc.gov
3. Db_writer_processes 1 2
4. Java_pool_size 167,772,160 117,440,512
5. Log_archive_dest_1 Location=/ora920/oradata/imsp/arch
6. Log_archive_start TRUE FALSE
7. Log_buffer 524,288 1,310,720
8. Sga_max_size 454,525,104 321,093,616
9. Shared_pool_reserved_size 10,905,190 5,872,025
10. Shared_pool_size 218,103,808 117,440,512


DB-SLOW> show sga;

Total System Global Area 454525104 bytes
Fixed Size 741552 bytes
Variable Size 419430400 bytes
Database Buffers 33554432 bytes
Redo Buffers 798720 bytes


DB-FAST> show sga

Total System Global Area 321093616 bytes
Fixed Size 741360 bytes
Variable Size 285212672 bytes
Database Buffers 33554432 bytes
Redo Buffers 1585152 bytes

DB-SLOW> show parameters

NAME TYPE VALUE
------------------------------------ ----------- ------------------------------
O7_DICTIONARY_ACCESSIBILITY boolean TRUE
active_instance_count integer
aq_tm_processes integer 0
archive_lag_target integer 0
audit_file_dest string ?/rdbms/audit
audit_sys_operations boolean FALSE
audit_trail string NONE
background_core_dump string partial
background_dump_dest string /ora920/admin/inpp/bdump
backup_tape_io_slaves boolean FALSE
bitmap_merge_area_size integer 1048576
blank_trimming boolean FALSE
buffer_pool_keep string
buffer_pool_recycle string
circuits integer 170
cluster_database boolean FALSE
cluster_database_instances integer 1
cluster_interconnects string
commit_point_strength integer 1
compatible string 9.2.0.0.0
control_file_record_keep_time integer 7
control_files string /ora920/oradata/inpp/control01

NAME TYPE VALUE
------------------------------------ ----------- ------------------------------
.ctl, /ora920/oradata/inpp/con
trol02.ctl, /ora920/oradata/in
pp/control03.ctl
core_dump_dest string /ora920/admin/inpp/cdump
cpu_count integer 1
create_bitmap_area_size integer 8388608
cursor_sharing string EXACT
cursor_space_for_time boolean FALSE
db_16k_cache_size big integer 0
db_2k_cache_size big integer 0
db_32k_cache_size big integer 0
db_4k_cache_size big integer 0
db_8k_cache_size big integer 0
db_block_buffers integer 0
db_block_checking boolean FALSE
db_block_checksum boolean TRUE
db_block_size integer 8192
db_cache_advice string ON
db_cache_size big integer 33554432
db_create_file_dest string
db_create_online_log_dest_1 string
db_create_online_log_dest_2 string

NAME TYPE VALUE
------------------------------------ ----------- ------------------------------
db_create_online_log_dest_3 string
db_create_online_log_dest_4 string
db_create_online_log_dest_5 string
db_domain string
db_file_multiblock_read_count integer 16
db_file_name_convert string
db_files integer 200
db_keep_cache_size big integer 0
db_name string inpp
db_recycle_cache_size big integer 0
db_writer_processes integer 1
dblink_encrypt_login boolean FALSE
dbwr_io_slaves integer 0
dg_broker_config_file1 string ?/dbs/dr1@.dat
dg_broker_config_file2 string ?/dbs/dr2@.dat
dg_broker_start boolean FALSE
disk_asynch_io boolean TRUE
dispatchers string (PROTOCOL=TCP) (SERVICE=inppXD
B)
distributed_lock_timeout integer 60
dml_locks integer 748
drs_start boolean FALSE

NAME TYPE VALUE
------------------------------------ ----------- ------------------------------
enqueue_resources integer 968
event string
fal_client string
fal_server string
fast_start_io_target integer 0
fast_start_mttr_target integer 300
fast_start_parallel_rollback string LOW
file_mapping boolean FALSE
filesystemio_options string none
fixed_date string
gc_files_to_locks string
global_context_pool_size string
global_names boolean FALSE
hash_area_size integer 1048576
hash_join_enabled boolean TRUE
hi_shared_memory_address integer 0
hs_autoregister boolean TRUE
ifile file
instance_groups string
instance_name string inpp
instance_number integer 0
java_max_sessionspace_size integer 0

NAME TYPE VALUE
------------------------------------ ----------- ------------------------------
java_pool_size big integer 167772160
java_soft_sessionspace_limit integer 0
job_queue_processes integer 0
large_pool_size big integer 16777216
license_max_sessions integer 0
license_max_users integer 0
license_sessions_warning integer 0
local_listener string
lock_name_space string
lock_sga boolean FALSE
log_archive_dest string
log_archive_dest_1 string LOCATION=/ora920/oradata/inpp/
arch
log_archive_dest_10 string
log_archive_dest_2 string
log_archive_dest_3 string
log_archive_dest_4 string
log_archive_dest_5 string
log_archive_dest_6 string
log_archive_dest_7 string
log_archive_dest_8 string
log_archive_dest_9 string

NAME TYPE VALUE
------------------------------------ ----------- ------------------------------
log_archive_dest_state_1 string enable
log_archive_dest_state_10 string enable
log_archive_dest_state_2 string enable
log_archive_dest_state_3 string enable
log_archive_dest_state_4 string enable
log_archive_dest_state_5 string enable
log_archive_dest_state_6 string enable
log_archive_dest_state_7 string enable
log_archive_dest_state_8 string enable
log_archive_dest_state_9 string enable
log_archive_duplex_dest string
log_archive_format string %t_%s.dbf
log_archive_max_processes integer 2
log_archive_min_succeed_dest integer 1
log_archive_start boolean TRUE
log_archive_trace integer 0
log_buffer integer 524288
log_checkpoint_interval integer 0
log_checkpoint_timeout integer 1800
log_checkpoints_to_alert boolean FALSE
log_file_name_convert string
log_parallelism integer 1

NAME TYPE VALUE
------------------------------------ ----------- ------------------------------
logmnr_max_persistent_sessions integer 1
max_commit_propagation_delay integer 700
max_dispatchers integer 5
max_dump_file_size string UNLIMITED
max_enabled_roles integer 30
max_rollback_segments integer 37
max_shared_servers integer 20
mts_circuits integer 170
mts_dispatchers string (PROTOCOL=TCP) (SERVICE=inppXD
B)
mts_listener_address string
mts_max_dispatchers integer 5
mts_max_servers integer 20
mts_multiple_listeners boolean FALSE
mts_servers integer 1
mts_service string inpp
mts_sessions integer 165
nls_calendar string
nls_comp string
nls_currency string
nls_date_format string
nls_date_language string

NAME TYPE VALUE
------------------------------------ ----------- ------------------------------
nls_dual_currency string
nls_iso_currency string
nls_language string AMERICAN
nls_length_semantics string BYTE
nls_nchar_conv_excp string FALSE
nls_numeric_characters string
nls_sort string
nls_territory string AMERICA
nls_time_format string
nls_time_tz_format string
nls_timestamp_format string
nls_timestamp_tz_format string
object_cache_max_size_percent integer 10
object_cache_optimal_size integer 102400
olap_page_pool_size integer 33554432
open_cursors integer 300
open_links integer 4
open_links_per_instance integer 4
optimizer_dynamic_sampling integer 1
optimizer_features_enable string 9.2.0
optimizer_index_caching integer 0
optimizer_index_cost_adj integer 100

NAME TYPE VALUE
------------------------------------ ----------- ------------------------------
optimizer_max_permutations integer 2000
optimizer_mode string CHOOSE
oracle_trace_collection_name string
oracle_trace_collection_path string ?/otrace/admin/cdf
oracle_trace_collection_size integer 5242880
oracle_trace_enable boolean FALSE
oracle_trace_facility_name string oracled
oracle_trace_facility_path string ?/otrace/admin/fdf
os_authent_prefix string ops$
os_roles boolean FALSE
parallel_adaptive_multi_user boolean FALSE
parallel_automatic_tuning boolean FALSE
parallel_execution_message_size integer 2152
parallel_instance_group string
parallel_max_servers integer 5
parallel_min_percent integer 0
parallel_min_servers integer 0
parallel_server boolean FALSE
parallel_server_instances integer 1
parallel_threads_per_cpu integer 2
partition_view_enabled boolean FALSE
pga_aggregate_target big integer 25165824

NAME TYPE VALUE
------------------------------------ ----------- ------------------------------
plsql_compiler_flags string INTERPRETED
plsql_native_c_compiler string
plsql_native_library_dir string
plsql_native_library_subdir_count integer 0
plsql_native_linker string
plsql_native_make_file_name string
plsql_native_make_utility string
plsql_v2_compatibility boolean FALSE
pre_page_sga boolean FALSE
processes integer 150
query_rewrite_enabled string FALSE
query_rewrite_integrity string enforced
rdbms_server_dn string
read_only_open_delayed boolean FALSE
recovery_parallelism integer 0
remote_archive_enable string true
remote_dependencies_mode string TIMESTAMP
remote_listener string
remote_login_passwordfile string EXCLUSIVE
remote_os_authent boolean FALSE
remote_os_roles boolean FALSE
replication_dependency_tracking boolean TRUE

NAME TYPE VALUE
------------------------------------ ----------- ------------------------------
resource_limit boolean FALSE
resource_manager_plan string
rollback_segments string
row_locking string always
serial_reuse string DISABLE
serializable boolean FALSE
service_names string inpp
session_cached_cursors integer 0
session_max_open_files integer 10
sessions integer 170
sga_max_size big integer 454525104
shadow_core_dump string partial
shared_memory_address integer 0
shared_pool_reserved_size big integer 10905190
shared_pool_size big integer 218103808
shared_server_sessions integer 165
shared_servers integer 1
sort_area_retained_size integer 0
sort_area_size integer 524288
spfile string ?/dbs/spfile@.ora
sql92_security boolean FALSE
sql_trace boolean FALSE

NAME TYPE VALUE
------------------------------------ ----------- ------------------------------
sql_version string NATIVE
standby_archive_dest string ?/dbs/arch
standby_file_management string MANUAL
star_transformation_enabled string FALSE
statistics_level string TYPICAL
tape_asynch_io boolean TRUE
thread integer 0
timed_os_statistics integer 0
timed_statistics boolean TRUE
trace_enabled boolean TRUE
tracefile_identifier string
transaction_auditing boolean TRUE
transactions integer 187
transactions_per_rollback_segment integer 5
undo_management string AUTO
undo_retention integer 10800
undo_suppress_errors boolean FALSE
undo_tablespace string UNDOTBS1
use_indirect_data_buffers boolean FALSE
use_sigio boolean TRUE
user_dump_dest string /ora920/admin/inpp/udump
utl_file_dir string

NAME TYPE VALUE
------------------------------------ ----------- ------------------------------
workarea_size_policy string AUTO

Tom:

Forgot to say that "links" are URLs in a mod_plsql application above and not db links.

Tom:

Don't you have any hint or suggestion for checking why would same procedure take 2 seconds in one 9i instance and 8i instance while 70 seconds for another 9i instance. They all have same number of records?

do you need to see the code for the procedure.

Tom:

sorry for the list. I did not realize that. at least now i know one thing you do not like.

I will look into tkprof even though it is an application tuning tool and I di not think it is an application issue. The code works fine in other instances which tells me it is something in the DB configuration. does it not make sense.

Hello Tom,

First of all thanks for teaching us.I am a regule vistior to your site and learn a lot.

Now i have this prlm...

Last 3 days back we had a terible prlm in the prod database where it suddenly got very slow...and finally we had to reboot the server to get it back to normal.

This is not the first time this happened..this we had a couple of months back and the same thing we did...

Lats as well as this time we have generated the stats report and these are the finding..we are unable to see where to start from...as of now we are seeing we should increase the memory and allocate more shared poll...

Here are some details :

Server : Sunos
CPU = 4
Memory =12gb
Database : 9.2.0.4
Oracle apps 11.5.9 running

StatsPack Report :

STATSPACK report for

DB Name DB Id Instance Inst Num Release Cluster Host
------------ ----------- ------------ -------- ----------- ------- ------------
PROD XXXXXXXXXX PROD 1 9.2.0.4.0 NO XXXXXXX

Snap Id Snap Time Sessions Curs/Sess Comment
------- ------------------ -------- --------- -------------------
Begin Snap: 41132 14-Apr-07 13:00:05 279 95.7
End Snap: 41366 17-Apr-07 13:00:06 155 122.1
Elapsed: 4,320.02 (mins)

Cache Sizes (end)
~~~~~~~~~~~~~~~~
Buffer Cache: 512M Std Block Size: 8K
Shared Pool Size: 592M Log Buffer: 10,240K

Load Profile
~~~~~~~~~~~ Per Second Per Transaction
--------------- ---------------
Redo size: 270,435.03 4,123.70
Logical reads: 32,791.04 500.01
Block changes: 1,888.71 28.80
Physical reads: 1,672.55 25.50
Physical writes: 46.99 0.72
User calls: 131.09 2.00
Parses: 81.52 1.24
Hard parses: 1.99 0.03
Sorts: 71.46 1.09
Logons: 0.70 0.01
Executes: 1,320.68 20.14
Transactions: 65.58

% Blocks changed per Read: 5.76 Recursive Call %: 96.31
Rollback per transaction %: 5.57 Rows per Sort: 229.06

Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Buffer Nowait %: 99.99 Redo NoWait %: 100.00
Buffer Hit %: 95.16 In-memory Sort %: 100.00
Library Hit %: 99.64 Soft Parse %: 97.56
Execute to Parse %: 93.83 Latch Hit %: 99.87
Parse CPU to Parse Elapsd %: 16.63 % Non-Parse CPU: 93.77

Shared Pool Statistics Begin End
------ ------
Memory Usage %: 94.45 95.24
% SQL with executions>1: 84.67 88.58
% Memory for SQL w/exec>1: 71.48 88.17

Top 5 Timed Events
~~~~~~~~~~~~~~~~~ % Total
Event Waits Time (s) Ela Time
-------------------------------------------- ------------ ----------- --------
library cache pin 595,941 1,683,567 40.06
PL/SQL lock timer 125,933 1,259,119 29.96
CPU time 434,852 10.35
db file sequential read 106,876,550 237,360 5.65
latch free 2,822,077 164,094 3.90
-------------------------------------------------------------
Wait Events for DB: PROD Instance: PROD Snaps: 41132 -41366
-> 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
---------------------------- ------------ ---------- ---------- ------ --------
library cache pin 595,941 558,420 1,683,567 2825 0.0
PL/SQL lock timer 125,933 125,921 1,259,119 9998 0.0
db file sequential read 106,876,550 0 237,360 2 6.3
latch free 2,822,077 269,830 164,094 58 0.2
library cache load lock 34,209 29,685 90,794 2654 0.0
db file scattered read 57,285,336 0 84,755 1 3.4
enqueue 62,346 16,688 56,628 908 0.0
SQL*Net message from dblink 4,030,526 0 30,515 8 0.2
PX Deq: Execute Reply 434,806 9,228 29,009 67 0.0
PX Deq Credit: send blkd 4,840,159 63 17,160 4 0.3
log file sync 383,468 3,754 17,033 44 0.0
buffer busy waits 689,524 126 16,669 24 0.0
direct path read 3,789,583 0 15,594 4 0.2
log file parallel write 6,895,601 6,810,139 13,419 2 0.4
db file parallel write 368,102 0 12,921 35 0.0
PX qref latch 15,483 8,302 8,497 549 0.0
PX Deq: Parse Reply 24,551 2,123 6,639 270 0.0
sbtpcstatus 1,962 0 3,575 1822 0.0
PX Deq Credit: need buffer 2,140,465 2 2,974 1 0.1
log file sequential read 78,884 0 2,868 36 0.0
async disk IO 204,826 0 1,874 9 0.0
control file parallel write 156,842 0 1,376 9 0.0
sbtpcbackup 654 0 1,099 1680 0.0
SQL*Net break/reset to clien 1,320,328 0 1,094 1 0.1
log file switch completion 8,776 105 915 104 0.0
PX Deq: Msg Fragment 311,000 291 898 3 0.0
PX Deq: Join ACK 23,370 313 893 38 0.0
SQL*Net more data to client 2,001,532 0 892 0 0.1
library cache lock 504 200 773 1534 0.0
PX Deq: Signal ACK 45,817 11,646 739 16 0.0
sbtbackup 6 0 696 ###### 0.0
direct path write 421,896 0 682 2 0.0
process startup 738 263 323 437 0.0
sbtpcquerybackup 654 0 219 335 0.0
direct path read (lob) 69,229 0 142 2 0.0
PX Deq: Table Q qref 45,740 329 110 2 0.0
direct path write (lob) 24,144 0 107 4 0.0
control file sequential read 323,165 0 94 0 0.0
sbtclose2 6 0 74 12320 0.0
SQL*Net message to dblink 4,030,526 0 67 0 0.2
SQL*Net more data from dblin 455,566 0 64 0 0.0
row cache lock 1,565 0 47 30 0.0
LGWR wait for redo copy 45,221 200 36 1 0.0
local write wait 1,203 3 35 29 0.0
log file single write 5,648 0 16 3 0.0
PX Deq: Table Q Sample 447 4 13 29 0.0
sbtwrite2 426 0 11 25 0.0
inactive session 10 10 10 1010 0.0
db file single write 4,442 0 10 2 0.0
Wait Events for DB: PROD Instance: PROD Snaps: 41132 -41366
-> 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
---------------------------- ------------ ---------- ---------- ------ --------
write complete waits 9 9 9 1006 0.0
PX Deq: Table Q Get Keys 1,164 0 7 6 0.0
kksfbc child completion 316 310 7 21 0.0
control file single write 210 0 5 22 0.0
log buffer space 6 1 3 517 0.0
wait list latch free 144 0 3 20 0.0
sbtpcvalidate 3 0 3 857 0.0
sbtinfo2 660 0 2 3 0.0
SQL*Net more data to dblink 4,545 0 2 0 0.0
sbtinit 21 0 1 28 0.0
switch logfile command 14 0 1 37 0.0
undo segment extension 106,087 106,078 0 0 0.0
sbtpcstart 654 0 0 0 0.0
kkdlgon 4 0 0 31 0.0
slave TJ process wait 4 4 0 19 0.0
sbtpccommit 654 0 0 0 0.0
sbtcommand 90 0 0 0 0.0
sbtend 21 0 0 0 0.0
buffer deadlock 2,527 2,524 0 0 0.0
SQL*Net break/reset to dblin 3 0 0 0 0.0
sbtpcend 3 0 0 0 0.0
sbtinit2 21 0 0 0 0.0
SQL*Net message from client 34,879,098 0 ########## 710 2.1
queue messages 489,292 486,757 4,512,075 9222 0.0
pipe get 412,288 410,919 1,764,625 4280 0.0
jobq slave wait 407,858 206,406 1,024,188 2511 0.0
PX Idle Wait 331,324 281,644 603,330 1821 0.0
wakeup time manager 20,352 20,228 470,646 23125 0.0
PX Deq: Execution Msg 684,341 48,131 139,734 204 0.0
PX Deq: Table Q Normal 7,365,784 237 30,985 4 0.4
SQL*Net more data from clien 324,649 0 4,636 14 0.0
SQL*Net message to client 34,878,937 0 162 0 2.1
-------------------------------------------------------------
Background Wait Events for DB: PROD Instance: PROD Snaps: 41132 -41366
-> 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 6,895,585 6,810,123 13,419 2 0.4
db file parallel write 368,101 0 12,921 35 0.0
log file sequential read 78,803 0 2,866 36 0.0
async disk IO 198,914 0 1,837 9 0.0
control file parallel write 150,059 0 1,336 9 0.0
db file scattered read 318,649 0 740 2 0.0
db file sequential read 131,718 0 328 2 0.0
latch free 5,707 1,636 242 42 0.0
direct path read 1,075,238 0 235 0 0.1
direct path write 252,936 0 217 1 0.0
rdbms ipc reply 8,142 0 161 20 0.0
LGWR wait for redo copy 45,221 200 36 1 0.0
buffer busy waits 1,295 0 31 24 0.0
control file sequential read 202,868 0 26 0 0.0
log file single write 5,648 0 16 3 0.0
enqueue 90 0 8 86 0.0
log buffer space 2 0 0 238 0.0
log file switch completion 6 0 0 62 0.0
db file single write 80 0 0 1 0.0
log file sync 3 0 0 5 0.0
rdbms ipc message 28,720,517 ########## 2,190,868 76 1.7
pmon timer 93,271 87,210 252,944 2712 0.0
smon timer 3,071 376 243,958 79439 0.0
-------------------------------------------------------------



My Comments:
We see library cache pin to be in the top 5 times event...what we feel it has a smaller shared pool and we should increase the same.
Also in the alert file we see the log switch happens too frequently...for that we are increasing the size of the log file and log buffer.

What other areas we can look into...this db is running on a filler..and we have run iostat and we dont see any bottleneck fromio part...memory usage and cpu usage is too high...we have allocate 3gb sga..with 900mb as shared pool

Thanks
Sk

Hello Tom,
Apologies for not looking at the elapsed time.Always thought the more the amount of time elasped it gives better report.Lesson learned...

Also prlm is Problem...short form...sorry for that too...

I have taken now the report of 2 hours..when the problem was there...

DB Name DB Id Instance Inst Num Release Cluster Host
------------ ----------- ------------ -------- ----------- ------- ------------
xxxx xxxxxxxxxx PROD 1 9.2.0.4.0 NO xxxxxxxx

Snap Id Snap Time Sessions Curs/Sess Comment
------- ------------------ -------- --------- -------------------
Begin Snap: 41342 17-Apr-07 06:00:10 418 96.9
End Snap: 41353 17-Apr-07 08:00:14 471 99.5
Elapsed: 120.07 (mins)

Cache Sizes (end)
~~~~~~~~~~~~~~~~~
Buffer Cache: 512M Std Block Size: 8K
Shared Pool Size: 592M Log Buffer: 10,240K

Load Profile
~~~~~~~~~~~~ Per Second Per Transaction
--------------- ---------------
Redo size: 469,560.06 7,037.80
Logical reads: 28,382.08 425.39
Block changes: 3,599.78 53.95
Physical reads: 2,007.82 30.09
Physical writes: 53.78 0.81
User calls: 121.32 1.82
Parses: 130.77 1.96
Hard parses: 6.19 0.09
Sorts: 85.90 1.29
Logons: 0.71 0.01
Executes: 1,159.66 17.38
Transactions: 66.72

% Blocks changed per Read: 12.68 Recursive Call %: 97.14
Rollback per transaction %: 5.78 Rows per Sort: 14.10

Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Buffer Nowait %: 99.99 Redo NoWait %: 100.00
Buffer Hit %: 92.95 In-memory Sort %: 100.00
Library Hit %: 98.66 Soft Parse %: 95.27
Execute to Parse %: 88.72 Latch Hit %: 99.84
Parse CPU to Parse Elapsd %: 17.12 % Non-Parse CPU: 94.06

Shared Pool Statistics Begin End
------ ------
Memory Usage %: 40.33 95.66
% SQL with executions>1: 94.10 90.25
% Memory for SQL w/exec>1: 87.45 78.80

Top 5 Timed Events
~~~~~~~~~~~~~~~~~~ % Total
Event Waits Time (s) Ela Time
-------------------------------------------- ------------ ----------- --------
library cache pin 60,378 180,582 72.03
PL/SQL lock timer 3,510 35,118 14.01
CPU time 11,639 4.64
latch free 182,551 6,831 2.72
db file sequential read 3,179,872 6,618 2.64
-------------------------------------------------------------
Wait Events for DB: PROD Instance: PROD Snaps: 41342 -41353
-> 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
---------------------------- ------------ ---------- ---------- ------ --------
library cache pin 60,378 59,945 180,582 2991 0.1
PL/SQL lock timer 3,510 3,510 35,118 10005 0.0
latch free 182,551 5,347 6,831 37 0.4
db file sequential read 3,179,872 0 6,618 2 6.6
library cache load lock 1,557 1,172 3,597 2310 0.0
db file scattered read 2,318,881 0 2,084 1 4.8
SQL*Net message from dblink 98,121 0 1,283 13 0.2
log file sync 14,152 207 895 63 0.0
db file parallel write 9,953 0 523 53 0.0
log file parallel write 165,783 163,607 423 3 0.3
buffer busy waits 18,079 1 392 22 0.0
enqueue 1,103 51 319 289 0.0
log file sequential read 3,752 0 131 35 0.0
log file switch completion 447 28 79 176 0.0
async disk IO 9,476 0 70 7 0.0
control file parallel write 4,905 0 59 12 0.0
SQL*Net break/reset to clien 20,810 0 21 1 0.0
direct path write 11,946 0 20 2 0.0
direct path read 42,377 0 11 0 0.1
row cache lock 143 0 5 33 0.0
SQL*Net more data to client 33,864 0 5 0 0.1
direct path read (lob) 906 0 3 3 0.0
control file sequential read 9,027 0 2 0 0.0
direct path write (lob) 515 0 2 3 0.0
SQL*Net message to dblink 98,121 0 1 0 0.2
wait list latch free 64 0 1 20 0.0
LGWR wait for redo copy 1,129 7 1 1 0.0
kksfbc child completion 37 36 1 19 0.0
process startup 5 0 1 126 0.0
SQL*Net more data from dblin 375 0 1 1 0.0
log file single write 268 0 1 2 0.0
SQL*Net more data to dblink 127 0 0 0 0.0
db file single write 8 0 0 1 0.0
buffer deadlock 67 67 0 0 0.0
undo segment extension 72 72 0 0 0.0
SQL*Net message from client 909,431 0 905,417 996 1.9
queue messages 13,779 13,679 126,929 9212 0.0
pipe get 11,540 11,442 49,201 4263 0.0
jobq slave wait 11,305 5,699 28,377 2510 0.0
wakeup time manager 660 653 12,520 18970 0.0
SQL*Net more data from clien 17,409 0 189 11 0.0
SQL*Net message to client 909,444 0 4 0 1.9
-------------------------------------------------------------
Background Wait Events for DB: PROD Instance: PROD Snaps: 41342 -41353
-> 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 9,954 0 523 53 0.0
log file parallel write 165,780 163,605 423 3 0.3
log file sequential read 3,752 0 131 35 0.0
async disk IO 9,476 0 70 7 0.0
control file parallel write 4,905 0 59 12 0.0
db file scattered read 9,541 0 17 2 0.0
db file sequential read 3,875 0 15 4 0.0
latch free 425 36 11 26 0.0
direct path read 39,386 0 11 0 0.1
direct path write 8,932 0 10 1 0.0
LGWR wait for redo copy 1,129 7 1 1 0.0
control file sequential read 7,499 0 1 0 0.0
log file single write 268 0 1 2 0.0
rdbms ipc reply 119 0 0 3 0.0
buffer busy waits 5 0 0 16 0.0
db file single write 8 0 0 1 0.0
rdbms ipc message 811,265 341,136 60,975 75 1.7
pmon timer 2,541 2,431 7,030 2767 0.0
smon timer 43 13 6,816 ###### 0.0
-------------------------------------------------------------

Thanks
Saurabh

STATSPACK report for

DB Name DB Id Instance Inst Num Release Cluster Host
------------ ----------- ------------ -------- ----------- ------- ------------
prod1 377438063 prod 1 9.2.0.7.0 NO my_machine
x

Snap Id Snap Time Sessions Curs/Sess Comment
--------- ------------------ -------- --------- -------------------
Begin Snap: 3588 13-Sep-07 04:00:04 65 44.1
End Snap: 3625 14-Sep-07 11:18:10 96 124.2
Elapsed: 1,878.10 (mins)

Wait Events for DB: PROD1 Instance: prod1 Snaps: 3588 -3625
-> 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
---------------------------- ------------ ---------- ---------- ------ --------
SQL*Net message from client 8,414,699 0 1,795,663 213 126.1
PX Idle Wait 258,496 247,511 489,473 1894 3.9
pipe get 44,357 44,336 216,688 4885 0.7
jobq slave wait 46,829 45,638 136,399 2913 0.7
PX Deq: Execution Msg 159,097 37,323 76,314 480 2.4
ARCH wait on SENDREQ 17,755 0 39,436 2221 0.3
log file switch (archiving n 29,111 28,485 28,344 974 0.4
db file sequential read 15,106,219 0 19,580 1 226.4
db file scattered read 7,059,518 0 13,755 2 105.8
SQL*Net message from dblink 951,053 0 13,234 14 14.3
enqueue 6,906 2,011 6,088 882 0.1
buffer busy waits 138,257 2,034 3,551 26 2.1
PX Deq: Execute Reply 68,957 390 2,924 42 1.0
SQL*Net more data to client 7,245,559 0 2,238 0 108.6
log file parallel write 427,104 0 1,544 4 6.4
direct path read 709,507 0 1,383 2 10.6
PX Deq Credi



My question on above report is
PX Idle Wait
pipe get
jobq slave wait
PX Deq: Execution Msg
ARCH wait on SENDREQ
log file switch (archiving

Are these top wait events are related ?
I am also seeing message in archive
Fri Sep 14 13:19:05 2007
ARC1: Evaluating archive log 3 thread 1 sequence 94409
ARC1: Unable to archive log 3 thread 1 sequence 94409
Log actively being archived by another process
Fri Sep 14 13:19:13 2007

is it system level issue?
What is suggestion for tuning the SQL i got which is poorly performing

STATSPACK report for

DB Name DB Id Instance Inst Num Release Cluster Host
------------ ----------- ------------ -------- ----------- ------- ------------
prod1 377438063 prod 1 9.2.0.7.0 NO my_machine
x


Snap Id Snap Time Sessions Curs/Sess Comment
--------- ------------------ -------- --------- -------------------
Begin Snap: 3627 14-Sep-07 12:08:45 99 123.7
End Snap: 3628 14-Sep-07 12:35:31 104 121.0
Elapsed: 26.77 (mins)

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

Load Profile
~~~~~~~~~~~~ Per Second Per Transaction
--------------- ---------------
Redo size: 5,469.17 5,887.05
Logical reads: 10,729.24 11,549.03
Block changes: 37.68 40.56
Physical reads: 4,624.52 4,977.87
Physical writes: 67.02 72.14
User calls: 37.64 40.51
Parses: 6.33 6.81
Hard parses: 0.48 0.51
Sorts: 8.69 9.36
Logons: 0.44 0.47
Executes: 60.34 64.95
Transactions: 0.93

% Blocks changed per Read: 0.35 Recursive Call %: 79.42
Rollback per transaction %: 0.20 Rows per Sort: ########

Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Buffer Nowait %: 100.00 Redo NoWait %: 99.99
Buffer Hit %: 61.52 In-memory Sort %: 99.95
Library Hit %: 98.53 Soft Parse %: 92.48
Execute to Parse %: 89.52 Latch Hit %: 99.93
Parse CPU to Parse Elapsd %: 60.52 % Non-Parse CPU: 99.74

Shared Pool Statistics Begin End
------ ------
Memory Usage %: 96.18 91.08
% SQL with executions>1: 44.71 53.87
% Memory for SQL w/exec>1: 20.17 19.67

Top 5 Timed Events
~~~~~~~~~~~~~~~~~~ % Total
Event Waits Time (s) Ela Time
-------------------------------------------- ------------ ----------- --------
SQL*Net message from client 43,284 35,758 40.76
PX Idle Wait 5,933 10,825 12.34
rdbms ipc message 4,605 10,740 12.24
CPU time 10,194 11.62
PX Deq: Execution Msg 10,258 7,274 8.29
-------------------------------------------------------------
Wait Events for DB: prod1 Instance: prod1 Snaps: 3627 -3628
-> 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
---------------------------- ------------ ---------- ---------- ------ --------
SQL*Net message from client 43,284 0 35,758 826 29.0
PX Idle Wait 5,933 5,410 10,825 1824 4.0
PX Deq: Execution Msg 10,258 3,406 7,274 709 6.9
pipe get 641 641 3,136 4892 0.4
jobq slave wait 695 676 2,025 2913 0.5
SQL*Net message from dblink 35,467 0 1,347 38 23.8
PX Deq: Execute Reply 4,670 127 1,062 227 3.1
db file scattered read 964,986 0 598 1 646.8
db file sequential read 890,379 0 363 0 596.8
PX Deq Credit: send blkd 67,021 0 327 5 44.9
ARCH wait on SENDREQ 105 0 289 2756 0.1
PX Deq: Table Q Normal 125,733 0 238 2 84.3
direct path read 35,847 0 220 6 24.0
PX Deq Credit: need buffer 12,609 0 30 2 8.5
direct path write 8,794 0 18 2 5.9
SQL*Net more data to client 59,201 0 13 0 39.7
log file parallel write 4,638 0 10 2 3.1
process startup 45 0 6 144 0.0
db file parallel write 196 0 6 33 0.1
SQL*Net more data from dblin 6,901 0 5 1 4.6
PX Deq: Signal ACK 234 92 4 18 0.2
library cache pin 597 0 4 7 0.4
log file sync 437 0 4 9 0.3
control file parallel write 544 0 3 6 0.4
PX Deq: Join ACK 353 0 3 9 0.2
latch free 533 316 3 5 0.4
single-task message 18 0 3 158 0.0
log file sequential read 86 0 2 29 0.1
buffer busy waits 57 0 1 15 0.0
PX Deq: Parse Reply 380 0 1 2 0.3
SQL*Net message to client 43,286 0 0 0 29.0
db file parallel read 4 0 0 77 0.0
kksfbc child completion 21 16 0 12 0.0
SQL*Net message to dblink 35,467 0 0 0 23.8
PX Deq: Msg Fragment 357 0 0 1 0.2
SQL*Net break/reset to clien 10 0 0 16 0.0
control file sequential read 1,161 0 0 0 0.8
enqueue 49 0 0 3 0.0
log file switch completion 2 0 0 44 0.0
SQL*Net more data from clien 26 0 0 3 0.0
log file single write 4 0 0 10 0.0
async disk IO 153 0 0 0 0.1
LGWR wait for redo copy 39 0 0 0 0.0
PX Deq: Table Q Sample 7 0 0 1 0.0
PX Deq: Table Q qref 5 0 0 0 0.0
PX qref latch 1 0 0 0 0.0
-------------------------------------------------------------
Background Wait Events for DB: prod1 Instance: prod1 Snaps: 3627 -3628
-> ordered by wait time desc, waits desc (idle events last)

Avg
Total Wait wait Waits
Event Waits Timeouts Time (s) (ms) /txn
---------------------------- ------------ ---------- ---------- ------ --------
rdbms ipc message 4,286 1,614 9,180 2142 2.9
smon timer 32 1 1,653 51648 0.0
pmon timer 557 557 1,566 2812 0.4
ARCH wait on SENDREQ 105 0 289 2756 0.1
log file parallel write 4,638 0 10 2 3.1
db file parallel write 196 0 6 33 0.1
control file parallel write 544 0 3 6 0.4
log file sequential read 86 0 2 29 0.1
db file sequential read 28 0 0 5 0.0
control file sequential read 612 0 0 0 0.4
db file scattered read 10 0 0 6 0.0
log file single write 4 0 0 10 0.0
async disk IO 153 0 0 0 0.1
rdbms ipc reply 3 0 0 3 0.0
LGWR wait for redo copy 39 0 0 0 0.0
-------------------------------------------------------------
SQL ordered by Gets for DB: prod1 Instance: prod1 Snaps: 3627 -3628
-> 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
--------------- ------------ -------------- ------ -------- --------- ----------
9,942,693 734 13,545.9 57.7 955.46 1121.94 2922327753


Can you help in this ?
I took report before running my query and after running my query

Can you suggest anything here
********************************************************************************

SELECT T1.EFF_FROM_D,T1.EFF_THRU_D,T1.TRUST_INSTN_ID_N,
T1.INVST_INSTN_ID_N,T1.INVST_NM_C,T1.STD_MEAS_TYPE_C,
T1.STD_MEAS_SET_NM_C,T1.PRNT_STD_MEAS_TYPE_C,
T1.STD_PRSNT_ORD_N,T1.STD_MEANING_LNG_C,T1.DB_TRST_IND_C,
T2.STD_MEAS_TYPE_C,T2.YR_N,T2.MO_N,T2.MEAS_V_N
FROM
PAS.V_INSTANCE_TREE_NM_MEASURES T1,
PAS.V_PNOR004_INVSTM_MA1 T2
WHERE (T2.STD_MEAS_TYPE_C (+) = T1.STD_MEAS_TYPE_C AND
T2.INVSTM_INSTN_ID_N (+) = T1.INVST_INSTN_ID_N) AND
(T1.INVST_NM_C <> ' ' AND
T1.STD_MEAS_SET_NM_C = 'PNOR004' AND
T1.DB_TRST_IND_C = 'Y' AND
T1.EFF_THRU_D >= TO_DATE('200706','YYYYMM') AND
T1.TRUST_INSTN_ID_N = 167 AND
T2.YR_MO_C(+) = TO_NUMBER('200706') )

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 6.66 6.56 0 8 0 0
Execute 1 0.03 0.03 0 0 0 0
Fetch 4 213.05 252.87 100710 348416 0 46
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 6 219.74 259.47 100710 348424 0 46

Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: SYS

Rows Row Source Operation
------- ---------------------------------------------------
46 HASH JOIN OUTER
124 VIEW
3937 MERGE JOIN CARTESIAN
127 HASH JOIN
127 NESTED LOOPS
127 NESTED LOOPS
127 HASH JOIN
127 HASH JOIN
127 NESTED LOOPS
127 NESTED LOOPS
127 HASH JOIN
127 NESTED LOOPS
127 HASH JOIN
127 HASH JOIN
304 HASH JOIN
317 VIEW
317 SORT UNIQUE
317 UNION-ALL
317 NESTED LOOPS
1 TABLE ACCESS BY INDEX ROWID OBJ#(39351)
1 INDEX UNIQUE SCAN OBJ#(70968) (object id 70968)
317 INDEX RANGE SCAN OBJ#(114681) (object id 114681)
0 NESTED LOOPS
0 TABLE ACCESS BY INDEX ROWID OBJ#(39351)
1 INDEX UNIQUE SCAN OBJ#(70968) (object id 70968)
0 INDEX FULL SCAN OBJ#(117285) (object id 117285)
304 HASH JOIN
317 VIEW
317 SORT UNIQUE
317 UNION-ALL
317 NESTED LOOPS
1 TABLE ACCESS BY INDEX ROWID OBJ#(39351)
1 INDEX UNIQUE SCAN OBJ#(70968) (object id 70968)
317 INDEX RANGE SCAN OBJ#(114681) (object id 114681)
0 NESTED LOOPS
0 TABLE ACCESS BY INDEX ROWID OBJ#(39351)
1 INDEX UNIQUE SCAN OBJ#(70968) (object id 70968)
0 INDEX FULL SCAN OBJ#(117285) (object id 117285)
10487 TABLE ACCESS FULL OBJ#(114534)
2772 VIEW
28808 CONNECT BY WITH FILTERING
1554 FILTER
9344 COUNT
9344 HASH JOIN
54 TABLE ACCESS FULL OBJ#(114637)
9344 HASH JOIN
54 TABLE ACCESS FULL OBJ#(114637)
9344 HASH JOIN
10839 INDEX FAST FULL SCAN OBJ#(114538) (object id 114538)
9344 HASH JOIN
10839 INDEX FAST FULL SCAN OBJ#(114538) (object id 114538)
9344 VIEW
9344 UNION-ALL
5782 HASH JOIN SEMI
9344 TABLE ACCESS FULL OBJ#(114558)
9344 VIEW
9344 TABLE ACCESS FULL OBJ#(114558)
3562 HASH JOIN ANTI
9344 TABLE ACCESS FULL OBJ#(114558)
9344 TABLE ACCESS FULL OBJ#(114558)
1 NESTED LOOPS
2537 NESTED LOOPS
2537 VIEW
2537 SORT UNIQUE
2853 UNION-ALL
2853 NESTED LOOPS
9 TABLE ACCESS BY INDEX ROWID OBJ#(39351)
9 INDEX UNIQUE SCAN OBJ#(70968) (object id 70968)
2853 INDEX RANGE SCAN OBJ#(114681) (object id 114681)
0 NESTED LOOPS
9 TABLE ACCESS BY INDEX ROWID OBJ#(39351)
9 INDEX UNIQUE SCAN OBJ#(70968) (object id 70968)
0 INDEX FULL SCAN OBJ#(117285) (object id 117285)
2537 TABLE ACCESS BY INDEX ROWID OBJ#(114670)
2537 INDEX UNIQUE SCAN OBJ#(114671) (object id 114671)
1 TABLE ACCESS BY INDEX ROWID OBJ#(114637)
2537 INDEX UNIQUE SCAN OBJ#(114640) (object id 114640)
9781 HASH JOIN
7620 CONNECT BY PUMP
65408 COUNT
65408 HASH JOIN
378 TABLE ACCESS FULL OBJ#(114637)
65408 HASH JOIN
378 TABLE ACCESS FULL OBJ#(114637)
65408 HASH JOIN
75873 INDEX FAST FULL SCAN OBJ#(114538) (object id 114538)
65408 HASH JOIN
75873 INDEX FAST FULL SCAN OBJ#(114538) (object id 114538)
65408 VIEW
65408 UNION-ALL
40474 HASH JOIN SEMI
65408 TABLE ACCESS FULL OBJ#(114558)
65408 VIEW
65408 TABLE ACCESS FULL OBJ#(114558)
24934 HASH JOIN ANTI
65408 TABLE ACCESS FULL OBJ#(114558)
65408 TABLE ACCESS FULL OBJ#(114558)
0 COUNT
0 HASH JOIN
0 TABLE ACCESS FULL OBJ#(114637)
0 HASH JOIN
0 TABLE ACCESS FULL OBJ#(114637)
0 HASH JOIN
0 INDEX FAST FULL SCAN OBJ#(114538) (object id 114538)
0 HASH JOIN
0 INDEX FAST FULL SCAN OBJ#(114538) (object id 114538)
0 VIEW
0 UNION-ALL
0 HASH JOIN SEMI
0 TABLE ACCESS FULL OBJ#(114558)
0 VIEW
0 TABLE ACCESS FULL OBJ#(114558)
0 HASH JOIN ANTI
0 TABLE ACCESS FULL OBJ#(114558)
0 TABLE ACCESS FULL OBJ#(114558)
1 NESTED LOOPS
2537 NESTED LOOPS
2537 VIEW
2537 SORT UNIQUE
2853 UNION-ALL
2853 NESTED LOOPS
9 TABLE ACCESS BY INDEX ROWID OBJ#(39351)
9 INDEX UNIQUE SCAN OBJ#(70968) (object id 70968)
2853 INDEX RANGE SCAN OBJ#(114681) (object id 114681)
0 NESTED LOOPS
9 TABLE ACCESS BY INDEX ROWID OBJ#(39351)
9 INDEX UNIQUE SCAN OBJ#(70968) (object id 70968)
0 INDEX FULL SCAN OBJ#(117285) (object id 117285)
2537 TABLE ACCESS BY INDEX ROWID OBJ#(114670)
2537 INDEX UNIQUE SCAN OBJ#(114671) (object id 114671)
1 TABLE ACCESS BY INDEX ROWID OBJ#(114637)
2537 INDEX UNIQUE SCAN OBJ#(114640) (object id 114640)
317 VIEW
317 SORT UNIQUE
317 UNION-ALL
317 NESTED LOOPS
1 TABLE ACCESS BY INDEX ROWID OBJ#(39351)
1 INDEX UNIQUE SCAN OBJ#(70968) (object id 70968)
317 INDEX RANGE SCAN OBJ#(114681) (object id 114681)
0 NESTED LOOPS
0 TABLE ACCESS BY INDEX ROWID OBJ#(39351)
1 INDEX UNIQUE SCAN OBJ#(70968) (object id 70968)
0 INDEX FULL SCAN OBJ#(117285) (object id 117285)
127 TABLE ACCESS BY INDEX ROWID OBJ#(114534)
127 INDEX UNIQUE SCAN OBJ#(114537) (object id 114537)
317 VIEW
317 SORT UNIQUE
317 UNION-ALL
317 NESTED LOOPS
1 TABLE ACCESS BY INDEX ROWID OBJ#(39351)
1 INDEX UNIQUE SCAN OBJ#(70968) (object id 70968)
317 INDEX RANGE SCAN OBJ#(114681) (object id 114681)
0 NESTED LOOPS
0 TABLE ACCESS BY INDEX ROWID OBJ#(39351)
1 INDEX UNIQUE SCAN OBJ#(70968) (object id 70968)
0 INDEX FULL SCAN OBJ#(117285) (object id 117285)
127 TABLE ACCESS BY INDEX ROWID OBJ#(114637)
127 INDEX UNIQUE SCAN OBJ#(114640) (object id 114640)
127 TABLE ACCESS BY INDEX ROWID OBJ#(114534)
127 INDEX UNIQUE SCAN OBJ#(114537) (object id 114537)
317 VIEW
317 SORT UNIQUE
317 UNION-ALL
317 NESTED LOOPS
1 TABLE ACCESS BY INDEX ROWID OBJ#(39351)
1 INDEX UNIQUE SCAN OBJ#(70968) (object id 70968)
317 INDEX RANGE SCAN OBJ#(114681) (object id 114681)
0 NESTED LOOPS
0 TABLE ACCESS BY INDEX ROWID OBJ#(39351)
1 INDEX UNIQUE SCAN OBJ#(70968) (object id 70968)
0 INDEX FULL SCAN OBJ#(117285) (object id 117285)
317 VIEW
317 SORT UNIQUE
317 UNION-ALL
317 NESTED LOOPS
1 TABLE ACCESS BY INDEX ROWID OBJ#(39351)
1 INDEX UNIQUE SCAN OBJ#(70968) (object id 70968)
317 INDEX RANGE SCAN OBJ#(114681) (object id 114681)
0 NESTED LOOPS
0 TABLE ACCESS BY INDEX ROWID OBJ#(39351)
1 INDEX UNIQUE SCAN OBJ#(70968) (object id 70968)
0 INDEX FULL SCAN OBJ#(117285) (object id 117285)
127 TABLE ACCESS BY INDEX ROWID OBJ#(114637)
127 INDEX UNIQUE SCAN OBJ#(114640) (object id 114640)
127 TABLE ACCESS BY INDEX ROWID OBJ#(114637)
127 INDEX UNIQUE SCAN OBJ#(114640) (object id 114640)
317 VIEW
317 SORT UNIQUE
317 UNION-ALL
317 NESTED LOOPS
1 TABLE ACCESS BY INDEX ROWID OBJ#(39351)
1 INDEX UNIQUE SCAN OBJ#(70968) (object id 70968)
317 INDEX RANGE SCAN OBJ#(114681) (object id 114681)
0 NESTED LOOPS
0 TABLE ACCESS BY INDEX ROWID OBJ#(39351)
1 INDEX UNIQUE SCAN OBJ#(70968) (object id 70968)
0 INDEX FULL SCAN OBJ#(117285) (object id 117285)
3937 BUFFER SORT
31 VIEW
31 SORT ORDER BY
31 NESTED LOOPS
31 TABLE ACCESS FULL OBJ#(42642)
31 TABLE ACCESS BY INDEX ROWID OBJ#(39519)
31 INDEX UNIQUE SCAN OBJ#(39520) (object id 39520)
814 VIEW
814 SORT UNIQUE
838 UNION-ALL
31 SORT GROUP BY
99 NESTED LOOPS
99 NESTED LOOPS
1 TABLE ACCESS BY INDEX ROWID OBJ#(39519)
1 INDEX UNIQUE SCAN OBJ#(39520) (object id 39520)
99 TABLE ACCESS BY INDEX ROWID OBJ#(39527)
99 INDEX RANGE SCAN OBJ#(39528) (object id 39528)
99 TABLE ACCESS BY INDEX ROWID OBJ#(3714)
99 INDEX UNIQUE SCAN OBJ#(3716) (object id 3716)
31 SORT GROUP BY
99 HASH JOIN
373 NESTED LOOPS
1 TABLE ACCESS BY INDEX ROWID OBJ#(39519)
1 INDEX UNIQUE SCAN OBJ#(39520) (object id 39520)
373 TABLE ACCESS FULL OBJ#(3714)
2970 TABLE ACCESS FULL OBJ#(39527)
268 SORT GROUP BY
500 VIEW
500 SORT GROUP BY
5901 HASH JOIN
5901 TABLE ACCESS BY INDEX ROWID OBJ#(114549)
11803 NESTED LOOPS
5901 HASH JOIN
6275 VIEW
6275 SORT GROUP BY
40083 NESTED LOOPS
40083 VIEW
40083 SORT UNIQUE
42826 UNION-ALL
42748 HASH JOIN
42748 NESTED LOOPS OUTER
42748 NESTED LOOPS
40005 HASH JOIN
40005 HASH JOIN
1346 TABLE ACCESS FULL OBJ#(114549)
40005 HASH JOIN
2054 TABLE ACCESS FULL OBJ#(39471)
40005 TABLE ACCESS FULL OBJ#(61705)
317 VIEW
317 SORT UNIQUE
317 UNION-ALL
317 NESTED LOOPS
1 TABLE ACCESS BY INDEX ROWID OBJ#(39351)
1 INDEX UNIQUE SCAN OBJ#(70968) (object id 70968)
317 INDEX RANGE SCAN OBJ#(114681) (object id 114681)
0 NESTED LOOPS
0 TABLE ACCESS BY INDEX ROWID OBJ#(39351)
1 INDEX UNIQUE SCAN OBJ#(70968) (object id 70968)
0 INDEX FULL SCAN OBJ#(117285) (object id 117285)
42748 TABLE ACCESS BY INDEX ROWID OBJ#(114549)
42748 INDEX RANGE SCAN OBJ#(116086) (object id 116086)
0 VIEW PUSHED PREDICATE
0 FILTER
0 HASH JOIN
0 TABLE ACCESS BY INDEX ROWID OBJ#(43008)
0 INDEX RANGE SCAN OBJ#(43009) (object id 43009)
0 VIEW
0 SORT GROUP BY
0 TABLE ACCESS FULL OBJ#(43008)
317 VIEW
317 SORT UNIQUE
317 UNION-ALL
317 NESTED LOOPS
1 TABLE ACCESS BY INDEX ROWID OBJ#(39351)
1 INDEX UNIQUE SCAN OBJ#(70968) (object id 70968)
317 INDEX RANGE SCAN OBJ#(114681) (object id 114681)
0 NESTED LOOPS
0 TABLE ACCESS BY INDEX ROWID OBJ#(39351)
1 INDEX UNIQUE SCAN OBJ#(70968) (object id 70968)
0 INDEX FULL SCAN OBJ#(117285) (object id 117285)
78 FILTER
115 TABLE ACCESS FULL OBJ#(43008)
81 SORT AGGREGATE
121 FILTER
121 TABLE ACCESS BY INDEX ROWID OBJ#(43008)
121 INDEX RANGE SCAN OBJ#(43009) (object id 43009)
40083 TABLE ACCESS BY INDEX ROWID OBJ#(39519)
40083 INDEX UNIQUE SCAN OBJ#(39520) (object id 39520)
2204 MERGE JOIN CARTESIAN
58 HASH JOIN
1346 TABLE ACCESS FULL OBJ#(114549)
317 VIEW
317 SORT UNIQUE
317 UNION-ALL
317 NESTED LOOPS
1 TABLE ACCESS BY INDEX ROWID OBJ#(39351)
1 INDEX UNIQUE SCAN OBJ#(70968) (object id 70968)
317 INDEX RANGE SCAN OBJ#(114681) (object id 114681)
0 NESTED LOOPS
0 TABLE ACCESS BY INDEX ROWID OBJ#(39351)
1 INDEX UNIQUE SCAN OBJ#(70968) (object id 70968)
0 INDEX FULL SCAN OBJ#(117285) (object id 117285)
2204 BUFFER SORT
38 TABLE ACCESS FULL OBJ#(39519)
5901 INDEX RANGE SCAN OBJ#(116086) (object id 116086)
317 VIEW
317 SORT UNIQUE
317 UNION-ALL
317 NESTED LOOPS
1 TABLE ACCESS BY INDEX ROWID OBJ#(39351)
1 INDEX UNIQUE SCAN OBJ#(70968) (object id 70968)
317 INDEX RANGE SCAN OBJ#(114681) (object id 114681)
0 NESTED LOOPS
0 TABLE ACCESS BY INDEX ROWID OBJ#(39351)
1 INDEX UNIQUE SCAN OBJ#(70968) (object id 70968)
0 INDEX FULL SCAN OBJ#(117285) (object id 117285)
322 SORT GROUP BY
322 VIEW
322 SORT GROUP BY
3671 VIEW
3671 SORT GROUP BY
6877 NESTED LOOPS
6877 NESTED LOOPS
6877 NESTED LOOPS
6877 NESTED LOOPS
7350 NESTED LOOPS
20233 NESTED LOOPS
68 NESTED LOOPS
68 HASH JOIN
317 VIEW
317 SORT UNIQUE
317 UNION-ALL
317 NESTED LOOPS
1 TABLE ACCESS BY INDEX ROWID OBJ#(39351)
1 INDEX UNIQUE SCAN OBJ#(70968) (object id 70968)
317 INDEX RANGE SCAN OBJ#(114681) (object id 114681)
0 NESTED LOOPS
0 TABLE ACCESS BY INDEX ROWID OBJ#(39351)
1 INDEX UNIQUE SCAN OBJ#(70968) (object id 70968)
0 INDEX FULL SCAN OBJ#(117285) (object id 117285)
2054 TABLE ACCESS FULL OBJ#(114549)
68 TABLE ACCESS BY INDEX ROWID OBJ#(23243)
68 INDEX RANGE SCAN OBJ#(30709) (object id 30709)
20233 TABLE ACCESS BY GLOBAL INDEX ROWID OBJ#(4956) PARTITION: ROW LOCATION ROW LOCATION
20319 INDEX RANGE SCAN OBJ#(60106) (object id 60106)
7350 TABLE ACCESS BY INDEX ROWID OBJ#(39497)
20233 INDEX UNIQUE SCAN OBJ#(39498) (object id 39498)
6877 TABLE ACCESS BY INDEX ROWID OBJ#(39519)
7350 INDEX UNIQUE SCAN OBJ#(39520) (object id 39520)
6877 TABLE ACCESS BY INDEX ROWID OBJ#(20497)
6877 INDEX UNIQUE SCAN OBJ#(20503) (object id 20503)
6877 INDEX UNIQUE SCAN OBJ#(22148) (object id 22148)
6877 INDEX UNIQUE SCAN OBJ#(22148) (object id 22148)
186 SORT GROUP BY
594 VIEW
594 SORT GROUP BY
17822 HASH JOIN
17822 HASH JOIN
82 TABLE ACCESS FULL OBJ#(39519)
23861 TABLE ACCESS FULL OBJ#(39527)
7818 TABLE ACCESS FULL OBJ#(3714)


Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 4 0.00 0.00
db file sequential read 7308 0.09 45.17
db file scattered read 5914 0.05 13.33
latch free 3 0.00 0.00
SQL*Net message from client 4 85.22 161.21
********************************************************************************

select o.owner#,o.name,o.namespace,o.remoteowner,o.linkname,o.subname,
o.dataobj#,o.flags
from
obj$ o where o.obj#=:1


call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 2 0.01 0.00 0 0 0 0
Execute 5 0.00 0.00 0 0 0 0
Fetch 5 0.00 0.00 0 15 0 5
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 12 0.01 0.00 0 15 0 5

Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: SYS (recursive depth: 2)



********************************************************************************

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 2 6.69 6.59 0 8 0 0
Execute 2 0.03 0.03 0 0 0 1
Fetch 4 213.05 252.87 100710 348416 0 46
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 8 219.77 259.50 100710 348424 0 47

Misses in library cache during parse: 2

Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
db file scattered read 5914 0.05 13.33
log file sync 2 0.00 0.00
SQL*Net message to client 5 0.00 0.00
SQL*Net message from client 5 85.22 167.35
db file sequential read 7308 0.09 45.17
latch free 3 0.00 0.00


OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 145 0.14 0.13 1 16 0 0
Execute 158 0.36 0.39 378 389 3 1
Fetch 225 0.03 0.11 12 410 0 202
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 528 0.53 0.64 391 815 3 203

Misses in library cache during parse: 22

Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
db file scattered read 13 0.03 0.11
db file sequential read 13 0.01 0.09

4 user SQL statements in session.
143 internal SQL statements in session.
147 SQL statements in session.
********************************************************************************
Trace file: prod1_ora_3553.trc
Trace file compatibility: 9.02.00
Sort options: default

1 session in tracefile.
4 user SQL statements in trace file.
143 internal SQL statements in trace file.
147 SQL statements in trace file.
24 unique SQL statements in trace file.
14946 lines in trace file.

When I compare this with test, it is using LOOPS instead of hash joins

Hi Tom,

Do you recommend some book which covers most of the statspack topics or we should stick with the documentation?

Thanks

Dear Tom,

I find myself quite new to performance tuning area (always..).. so please help me out here a bit..

I am staring at a statspack report for some HRMS database, users for which are complaining a lot about its performance (thanks to then it's not produntion ;))

I am pasting the output below (snippets which look relevat to me). It looks evident that there are wait events .. but I am not confident how to proceed with the same .. (please don't tell me to consult some dba.. as I am the one here).

Kindly advise..

fyi, it is a data gathered in 2 hrs problem interval...

STATSPACK report for

DB Name DB Id Instance Inst Num Release Cluster Host
------------ ----------- ------------ -------- ----------- ------- ------------
HRQA 1158705682 hrqa 1 9.2.0.4.0 NO nmx005

Snap Id Snap Time Sessions Curs/Sess Comment
------- ------------------ -------- --------- -------------------
Begin Snap: 1561 15-Apr-09 11:24:22 44 3.8
End Snap: 1563 15-Apr-09 13:24:29 51 3.8
Elapsed: 120.12 (mins)

Cache Sizes (end)
~~~~~~~~~~~~~~~~~
Buffer Cache: 704M Std Block Size: 8K
Shared Pool Size: 256M Log Buffer: 10,240K

Load Profile
~~~~~~~~~~~~ Per Second Per Transaction
--------------- ---------------
Redo size: 2,637.23 4,277.86
Logical reads: 1,464.33 2,375.29
Block changes: 17.58 28.52
Physical reads: 11.79 19.12
Physical writes: 0.55 0.90
User calls: 64.72 104.99
Parses: 52.22 84.71
Hard parses: 0.06 0.10
Sorts: 1.64 2.65
Logons: 0.01 0.02
Executes: 53.03 86.01
Transactions: 0.62

% Blocks changed per Read: 1.20 Recursive Call %: 19.19
Rollback per transaction %: 0.02 Rows per Sort: 931.11

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

Shared Pool Statistics Begin End
------ ------
Memory Usage %: 81.71 84.06
% SQL with executions>1: 70.22 68.02
% Memory for SQL w/exec>1: 56.01 53.48

Top 5 Timed Events
~~~~~~~~~~~~~~~~~~ % Total
Event Waits Time (s) Ela Time
-------------------------------------------- ------------ ----------- --------
enqueue 6,386 19,267 97.75
SQL*Net break/reset to client 7,849 416 2.11
log file parallel write 6,241 8 .04
log file sync 5,056 7 .04
control file parallel write 2,347 5 .02
-------------------------------------------------------------
^LWait Events for DB: HRQA Instance: hrqa Snaps: 1561 -1563
-> 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
---------------------------- ------------ ---------- ---------- ------ --------
enqueue 6,386 6,376 19,267 3017 1.4
SQL*Net break/reset to clien 7,849 0 416 53 1.8
log file parallel write 6,241 0 8 1 1.4
log file sync 5,056 0 7 1 1.1
control file parallel write 2,347 0 5 2 0.5
db file sequential read 1,584 0 4 3 0.4
db file scattered read 5,949 0 3 0 1.3
process startup 6 0 0 24 0.0
SQL*Net more data to client 6,413 0 0 0 1.4
control file sequential read 1,906 0 0 0 0.4
latch free 55 0 0 0 0.0
buffer busy waits 77 0 0 0 0.0
LGWR wait for redo copy 75 0 0 0 0.0
direct path write 10 0 0 0 0.0
SQL*Net message from client 435,567 0 95,246 219 98.0
jobq slave wait 132 126 393 2976 0.0
SQL*Net more data from clien 565 0 2 4 0.1
SQL*Net message to client 435,565 0 0 0 98.0
-------------------------------------------------------------
^LBackground Wait Events for DB: HRQA Instance: hrqa Snaps: 1561 -1563
-> 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 6,241 0 8 1 1.4
control file parallel write 2,323 0 5 2 0.5
control file sequential read 1,630 0 0 0 0.4
db file sequential read 482 0 0 0 0.1
LGWR wait for redo copy 75 0 0 0 0.0
db file scattered read 104 0 0 0 0.0
rdbms ipc message 18,488 9,426 47,648 2577 4.2
pmon timer 2,396 2,396 7,033 2935 0.5
smon timer 44 20 6,821 ###### 0.0

...
Event                                               Waits    Time (s) Ela Time
-------------------------------------------- ------------ ----------- --------
enqueue                                             6,386      19,267    97.75

.....

I had made your original suggestion to our DBA, here are his comments :

Stackpack is a extension of Analyze. In prod Analyze takes 5 / 6 hrs to finish and stackpack takes around 12/15 hrs. Definitely we can't run when regular users are in the system specially in this complicated setup.