Hi Tom !

I am using 8.1.7.2.1.

Consider the following:

Snap Id Snap Time Sessions
------- ------------------ --------
Begin Snap: 63 23-Jun-03 13:59:09 24
End Snap: 64 23-Jun-03 14:06:15 24
Elapsed: 7.10 (mins)


Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Buffer Nowait %: 100.00 Redo NoWait %: 99.84
Buffer Hit %: 94.72 In-memory Sort %: 97.98
Library Hit %: 94.13 Soft Parse %: 89.66
Execute to Parse %:65.24 Latch Hit %: 100.00
Parse CPU to Parse Elapsd %: 0.12
% Non-ParseCPU: 99.98


Background Wait Events for DB: STARR Instance: starr Snaps: 63 -64
a-> ordered by wait time desc, waits desc (idle events last)

Event Waits Timeouts Total Wait Avg Wait
Time(cs) Wait /txn
================= ===== ======== ========== ==== =====
rdbms ipc message 829 414 136,992 1652 15.9
pmon timer 139 138 42,478 3056 2.7
smon timer 3 1 15,134 50447 0.1

I am receving the following error very much frequenctly:
ORA-02049,timeout: distributed transaction waiting for lock

What may be a possible cause and solution.

Waiting for your advice....

Riaz

Hi Tom,
I have a db say X and a repository OEMREP created for this db x. I installed statspack and tried to generate report but the report generats for OEMREP. What changes do i make so that i get statspack report for X.
I tried using sprepins and manually feeding dbid,inst_num and other details to point to X instead of OEMREP. This is what I get



ERROR: Database/Instance does not exist in STATS$DATABASE_INSTANCE

ERROR: Begin Snapshot Id specified does not exist for this database/instance

ERROR: End Snapshot Id specified does not exist for this database/instance

WARNING: timed_statitics setting changed between begin/end snaps: TIMINGS ARE IN
VALID

ERROR: Snapshots chosen span an instance shutdown: RESULTS ARE INVALID

ERROR: Session statistics are for different sessions: RESULTS NOT PRINTED
begin
*
ERROR at line 1:
ORA-20100: Missing Init.ora parameter db_block_size
ORA-06512: at "PERFSTAT.STATSPACK", line 727
ORA-06512: at "PERFSTAT.STATSPACK", line 1126
ORA-06512: at line 2


STATSPACK report for

DB Name DB Id Instance Inst Num Release Cluster Host
------------ ----------- ------------ -------- ----------- ------- ------------
OEMREP 893333440 oemrep 1 9.2.0.1.0 NO Wx07044464

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

Load Profile
~~~~~~~~~~~~ Per Second Per Transaction
--------------- ---------------
Redo size:
Logical reads:
Block changes:
Physical reads:
Physical writes:
User calls:
Parses:
Hard parses:
Sorts:
Logons:
Executes:
Transactions:

% Blocks changed per Read: Recursive Call %:
Rollback per transaction %: Rows per Sort:

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

SGA Memory Summary for DB: OEMREP Instance: oemrep Snaps: 2 -4

SGA regions Size in Bytes
------------------------------ ----------------
----------------
sum
-------------------------------------------------------------

End of Report


Can you let me know how do I handle this??

Thanks again.

Tom,
What was happening was when i connected as sysdba through sqlplus I was on "X" instance. When I ran spcreate from here midway through the script somewhere around where it creates the pkg for some reason it started pointing to OEMREP (Queried V$instance before and after running the script) So errored towards the end of the script because it could not find tables or synonyms on OEMREP for the pkg it was trying to create. Anyways...
The work around I used for this was I stopped OEMREP through services/control panel. Then set environment local variable as "X" and started sqlplus and ran spcreate(ofcourse after spdrop). Statspack installed without any errors. Any better way or better suggestions from you when there are two instances on the same server??
Thanks again really appreciate it!!

Hi Tom,

According to the statspack doc, I can use dbms_job to generate snapshot. (Oracle 902)

Assume I use dbms_job to generate snapshot every 15 min, I think that I can use these data in two ways:
(1) If system is slow, I can run snapshot and use this snapshot and latest one generated by dbms_job to generate report. I can get last snapshot id by running snapshot function. But how can I get the snapshot id generated by dbms_job? Because there is gap between snapshot id, I can not simply use currrent snapshot_id minus one as the second snapshot id.

(2) At the end of day, I can analyze db in certain period of time by statspack report. If I want to get the report between 11 AM to 11:15 AM, I know that I have snapshots around that time. But how can I get those two snapshot id generated by dbms_job?

Thanks so much for your help.

Hi Tom,

In Top SQL report of Statspack, how do I know where these SQL are called ( from VB code or stored procedures)?

How do I know from which stored procedures the top SQL are called if these SQL are called from stored procedures?

Thanks so much for your help.

Hi Tom,

I understand that by using different level of i_snap_level or other parameters, I can collect data in different level of detail. But what I want is to collect data in details, but generating report in different levels for different people. Here are a few questions related to this task:

(1) Should I just modify the script sprepints.sql or write my own script to generate report?
(2) Do people write own script for statspack to generate report?

Thanks so much for your help.

Tom,

When I "execute statspack.snap;" it displays "not spooling currently" How can I create .lst spool file to view?

Tom in your first response in this thread you stated "....blew out rows per sort...."

I have never used statspack, what does rows per sort tell you?

What specifically does all the pound signs mean?

Thank you for your response.

So can I assume that your concern for that metric was that the high number MAYBE meant that:

- some tables could have been indexed more properly
- maybe some tables could have been physicall stored
differently (cluster, partitions)
- maybe some tables and indexes should be analyzed????

Hi Tom,

I was trying to automate the automation of Statspack,using dbms_job to gather stats for 30 mins every hr on our production database.

I have done this, but further need to automate that whenever the staspack finishes, the spreport can get executed and the report can be created under the specified utl_file_dir destination.

Once the report gets generated the snaps can be deleted using the sppurge utility.

How all this can be automated, so that we never have more than perhaps 10 snapshots in our perfstat schema.

Please let us know how to do this trick!

Hi tom,

The point was not to keep stats beyond a certain timeframe as it becomes too old to quantify, with day to day optimizations happening.

Moreover, we don't need to autogrow this tablespace where performance statistics are collected. Thus the job getting broken because there is no space in the perfstat tablespace doesn't seem good.

Anyways, we have automated to

- generate snaps on an hourly basis for 30 mins
- SPREPORT is the only automation, left.
- Purge the stats which are older than 5 days.

Looking to see how can we run something outside database. Always used dbms_job to submit the jobs inside the database.

Can you throw some light, how to connect to perfstat user and generate report via cron job, as I have never used this functionality.

This would be blessing in disguise to learn some functionality (executing a SQL script) outside database.

Thanks,
Vikas Khanna

A very clear, concise piece of work that goes a long way towards demystifying statspack reports.

Tom,

Does this statspack report look ok? Are there any issues? I shortened the timed, wait events just to show the top items. Thanks for your time.


Load Profile
~~~~~~~~~~~~ Per Second Per Transaction
--------------- ---------------
Redo size: 1,801.36 3,622.92
Logical reads: 968.69 1,948.25
Block changes: 7.62 15.32
Physical reads: 89.42 179.85
Physical writes: 1.10 2.21
User calls: 21.14 42.51
Parses: 13.69 27.53
Hard parses: 0.36 0.72
Sorts: 10.88 21.88
Logons: 0.02 0.04
Executes: 80.52 161.94
Transactions: 0.50

% Blocks changed per Read: 0.79 Recursive Call %: 87.37
Rollback per transaction %: 0.00 Rows per Sort: 9.43

Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Buffer Nowait %: 100.00 Redo NoWait %: 100.00
Buffer Hit %: 90.85 In-memory Sort %: 99.99
Library Hit %: 99.45 Soft Parse %: 97.39
Execute to Parse %: 83.00 Latch Hit %: 99.99
Parse CPU to Parse Elapsd %: 105.66 % Non-Parse CPU: 96.24

Shared Pool Statistics Begin End
------ ------
Memory Usage %: 94.36 94.33
% SQL with executions>1: 46.37 45.28
% Memory for SQL w/exec>1: 51.57 50.47




Top 5 Timed Events
~~~~~~~~~~~~~~~~~~ % Total
Event Waits Time (s) Ela Time
-------------------------------------------- ------------ ----------- --------
CPU time 45 55.54
db file scattered read 22,832 18 22.77
control file parallel write 295 11 14.18


Wait Events
~~~~~~~~~~~ Avg
Total Wait wait Waits
Event Waits Timeouts Time (s) (ms) /txn
---------------------------- ------------ ---------- ---------- ------ --------
db file scattered read 22,832 0 18 1 51.2
control file parallel write 295 0 11 39 0.7



Buffer Gets Executions Gets per Exec %Total Time (s) Time (s) Hash Value
--------------- ------------ -------------- ------ -------- --------- ----------
357,115 61 5,854.3 41.1 22.97 39.98 1398470370
Module: JDBC Thin Client

CPU Elapsd
Physical Reads Executions Reads per Exec %Total Time (s) Time (s) Hash Value
--------------- ------------ -------------- ------ -------- --------- ----------
75,162 61 1,232.2 93.7 22.97 39.98 1398470370
Module: JDBC Thin Client

Statspack is much better than the Utlbstat etc. Howvere, I have a minor problem in generating a report using a batch file. I use the following sql to get the snaps I want to run on report between:-

select max(snap_id)-2, max(snap_id) into :snap1, :snap2 from stats$snapshot;
producing the following output:-

MAX(SNAP_ID)-2 MAX(SNAP_ID)
-------------- ------------
0 2

Howvere when I try to pass the variables to the amended spreport.sql as follows:
set termout on;
variable bid number;
variable eid number;
variable versn varchar2(10);
variable para varchar2(9);
variable host_name varchar2(64);
begin
:bid := :snap1;
:eid := :snap2;
:versn := '&versn';
:para := '&para';
:host_name := '&host_name';
end;
/

They have become undefined. Any ideas ?

Thanks.

Hi Tom,
I have two questions regard to statspack:
1. I would like two keep only the last two weeks of
history information how can i do that ?
2. Suppose I have a process that run every day between
10:00 to 10:30.
Is there any way i can compare "automaticaly" the
statspack results between dates ?
Thanks.

I am planning to use statspack to measure the performance of database load. (I am new to RAC)

Which approach should I follow
Option 1:
---------
a) Take a snap(begin snap) for each RAC node
b) Perform the load test
c) Take a snap (end snap) for each RAC node
d) generate report for node specific (begin to end) snaps


Option2:
--------
a) Take a snap on any node (begin snap)
b) perform the load test
c) Take a snap (end snap) on the same node as a)
d) generate report once

(I remember reading somewhere that statspack is RAC-aware..)

Also , if there an easy way to see (in a statspack report) how the RAC balanced the load amongst its nodes (say 250 transactions --> distributed in the fashion of 100 to nodeA ; 100 to nodeB and 50 to nodeC )?


Thanks.

Thanks Tom. 

I just noticed that when I use AWR's API to create a snap, it actually goes across all nodes in the RAC cluster. That means I dont have to run begin snap & end snap in each node (as listed above in my prev question)

SQL> select instance_number,max(snap_id) from dba_hist_snapshot
  2  group by instance_number
  3  /

INSTANCE_NUMBER MAX(SNAP_ID)
--------------- ------------
              1         1542
              2         1542
              3         1542

SQL> exec dbms_workload_repository.create_snapshot;

PL/SQL procedure successfully completed.

SQL> select instance_number,max(snap_id) from dba_hist_snapshot
  2  group by instance_number
  3  /

INSTANCE_NUMBER MAX(SNAP_ID)
--------------- ------------
              1         1543
              2         1543
              3         1543

 

Sorry ,my bad!! I knew that sticking on to old term while using new features always bite back - but never thought it would happen so soon ;)

I should learn to forget "statspack" soon as its gone with 9i and start saying AWR atleast from here on.

Thanks!

Hi Tom,

Here I am putting the statspack Report.

Most the program are running in backend as pl/sql jobs.

Could you please explain what could be the reason of High CPU utilization, by looking at result.

What I can see here Execute to Parse % is too low that could be the possible reason.




Snap Id Snap Time Sessions
------- ------------------ --------
Begin Snap: 11524 18-Jul-06 00:00:03 48
End Snap: 11548 19-Jul-06 00:00:04 48
Elapsed: 1,440.02 (mins)

Cache Sizes
~~~~~~~~~~~
db_block_buffers: 32000 log_buffer: 1048576
db_block_size: 4096 shared_pool_size: 42000000

Load Profile
~~~~~~~~~~~~ Per Second Per Transaction
--------------- ---------------
Redo size: 13,280.13 8,463.71
Logical reads: 10,340.77 6,590.39
Block changes: 93.01 59.28
Physical reads: 518.61 330.52
Physical writes: 8.97 5.72
User calls: 46.76 29.80
Parses: 16.06 10.24
Hard parses: 3.57 2.28
Sorts: 0.79 0.50
Logons: 0.60 0.38
Executes: 16.72 10.65
Transactions: 1.57

% Blocks changed per Read: 0.90 Recursive Call %: 50.39
Rollback per transaction %: 0.52 Rows per Sort: 119.12

Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Buffer Nowait %: 100.00 Redo NoWait %: 100.00
Buffer Hit %: 94.98 In-memory Sort %: 99.50
Library Hit %: 94.24 Soft Parse %: 77.76
Execute to Parse %: 3.92 Latch Hit %: 99.98
Parse CPU to Parse Elapsd %: % Non-Parse CPU:

Shared Pool Statistics Begin End
------ ------
Memory Usage %: 82.92 95.33
% SQL with executions>1: 64.24 54.55
% Memory for SQL w/exec>1: 33.10 27.35

Top 5 Wait Events
~~~~~~~~~~~~~~~~~ Wait % Total
Event Waits Time (cs) Wt Time
-------------------------------------------- ------------ ------------ -------
db file sequential read 35,465,422 0 .00
db file scattered read 600,684 0 .00
undo segment extension 548,300 0 .00
SQL*Net more data to client 219,673 0 .00
log file parallel write 141,584 0 .00
-------------------------------------------------------------


-> cs - centisecond - 100th of a second
-> ms - millisecond - 1000th of a second
-> ordered by wait time desc, waits desc (idle events last)

Avg
Total Wait wait Waits
Event Waits Timeouts Time (cs) (ms) /txn
---------------------------- ------------ ---------- ----------- ------ ------
db file sequential read 35,465,422 0 0 0 261.6
db file scattered read 600,684 0 0 0 4.4
undo segment extension 548,300 548,298 0 0 4.0
SQL*Net more data to client 219,673 0 0 0 1.6
log file parallel write 141,584 0 0 0 1.0
log file sync 80,562 2 0 0 0.6
log file sequential read 37,941 0 0 0 0.3
control file parallel write 29,612 0 0 0 0.2
PX Deq: Execution Msg 29,107 4 0 0 0.2
direct path write 26,078 0 0 0 0.2
SQL*Net break/reset to clien 25,880 0 0 0 0.2
db file parallel write 19,693 0 0 0 0.1
direct path read 19,462 0 0 0 0.1
file open 16,937 0 0 0 0.1
control file sequential read 12,873 0 0 0 0.1
latch free 9,902 7,847 0 0 0.1
PX Deq: Execute Reply 9,666 8 0 0 0.1
PX Deq: Signal ACK 5,544 1,929 0 0 0.0
enqueue 4,541 19 0 0 0.0
PX Deq: Parse Reply 3,939 0 0 0 0.0
PX Deq: Join ACK 3,675 0 0 0 0.0
library cache pin 2,548 0 0 0 0.0
buffer busy waits 2,097 175 0 0 0.0
PX Deq: Table Q Sample 1,749 41 0 0 0.0
PX Deq Credit: send blkd 1,680 0 0 0 0.0
PX Deq: Table Q qref 1,313 0 0 0 0.0
file identify 1,039 0 0 0 0.0
refresh controlfile command 814 0 0 0 0.0
log file single write 516 0 0 0 0.0
LGWR wait for redo copy 484 4 0 0 0.0
db file parallel read 365 0 0 0 0.0
log file switch completion 171 20 0 0 0.0
db file single write 160 0 0 0 0.0
SQL*Net message from dblink 86 0 0 0 0.0
SQL*Net message to dblink 86 0 0 0 0.0
process startup 83 0 0 0 0.0
row cache lock 79 0 0 0 0.0
switch logfile command 26 0 0 0 0.0
single-task message 18 0 0 0 0.0
control file single write 10 0 0 0 0.0
PX Deq: Table Q Normal 8 0 0 0 0.0
PX Deq Credit: need buffer 6 0 0 0 0.0
buffer deadlock 6 6 0 0 0.0
free buffer waits 2 0 0 0 0.0
PX qref latch 1 1 0 0 0.0
SQL*Net message from client 3,903,694 0 0 0 28.8
SQL*Net message to client 3,903,683 0 0 0 28.8
PX Idle Wait 120,457 114,313 0 0 0.9
SQL*Net more data from clien 1,539 0 0 0 0.0
-------------------------------------------------------------

Avg
Total Wait wait Waits
Event Waits Timeouts Time (cs) (ms) /txn
---------------------------- ------------ ---------- ----------- ------ ------
log file parallel write 141,584 0 0 0 1.0
log file sequential read 34,125 0 0 0 0.3
control file parallel write 29,373 0 0 0 0.2
db file parallel write 19,693 0 0 0 0.1
file open 11,077 0 0 0 0.1
control file sequential read 7,173 0 0 0 0.1
direct path read 2,560 0 0 0 0.0
direct path write 2,560 0 0 0 0.0
db file sequential read 2,344 0 0 0 0.0
db file scattered read 1,235 0 0 0 0.0
file identify 944 0 0 0 0.0

Note: of AWR requires a license.
</code> http://download-east.oracle.com/docs/cd/B19306_01/license.102/b14199/options.htm#sthref75 <code>

Tom,

My sysaux tablespace has grown huge and i would like to purge all the information related to workload as i have saved it (and dont need it) can you please tell me what syntax should I be using.

Thanks.

Tom,

Can you please give me some pointers about the wait events in my statspack report ? I am working to improve the performance.

STATSPACK report for

DB Name DB Id Instance Inst Num Release OPS Host
------------ ----------- ------------ -------- ----------- --- ------------
OPS 255777838 OPS1 1 8.1.7.3.0 YES node1

Snap Id Snap Time Sessions
------- ------------------ --------
Begin Snap: 25 07-Aug-06 10:00:12 18
End Snap: 26 07-Aug-06 10:28:47 18
Elapsed: 28.58 (mins)

Cache Sizes
~~~~~~~~~~~
db_block_buffers: 9000 log_buffer: 262144
db_block_size: 8192 shared_pool_size: 64000000

Load Profile
~~~~~~~~~~~~ Per Second Per Transaction
--------------- ---------------
Redo size: 1,420.83 143,337.18
Logical reads: 4,169.87 420,666.53
Block changes: 10.41 1,050.47
Physical reads: 74.95 7,561.18
Physical writes: 73.66 7,430.94
User calls: 6.80 686.12
Parses: 6.96 702.18
Hard parses: 0.10 9.71
Sorts: 0.89 89.47
Logons: 0.16 16.41
Executes: 12.15 1,226.18
Transactions: 0.01

% Blocks changed per Read: 0.25 Recursive Call %: 90.77
Rollback per transaction %: 29.41 Rows per Sort: #######

Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Buffer Nowait %: 100.00 Redo NoWait %: 100.00
Buffer Hit %: 98.20 In-memory Sort %: 70.22
Library Hit %: 98.80 Soft Parse %: 98.62
Execute to Parse %: 42.73 Latch Hit %: 100.00
Parse CPU to Parse Elapsd %: 100.00 % Non-Parse CPU: 99.50

Shared Pool Statistics Begin End
------ ------
Memory Usage %: 30.66 34.42
% SQL with executions>1: 70.99 81.94
% Memory for SQL w/exec>1: 76.29 89.55

Top 5 Wait Events
~~~~~~~~~~~~~~~~~ Wait % Total
Event Waits Time (cs) Wt Time
-------------------------------------------- ------------ ------------ -------
global cache lock s to x 65 8 72.73
enqueue 1,327 1 9.09
control file sequential read 37 1 9.09
refresh controlfile command 6 1 9.09
latch free 67,133 0 .00
-------------------------------------------------------------
Wait Events for DB: OPS Instance: OPS1 Snaps: 25 -26
-> cs - centisecond - 100th of a second
-> ms - millisecond - 1000th of a second
-> ordered by wait time desc, waits desc (idle events last)

Avg
Total Wait wait Waits
Event Waits Timeouts Time (cs) (ms) /txn
---------------------------- ------------ ---------- ----------- ------ ------
global cache lock s to x 65 0 8 1 3.8
enqueue 1,327 0 1 0 78.1
control file sequential read 37 0 1 0 2.2
refresh controlfile command 6 0 1 2 0.4
latch free 67,133 36 0 0 ######
direct path read 51,561 0 0 0 ######
db file sequential read 1,768 0 0 0 104.0


It seems, I have to see gc_releasable_locks parameter.

Please Let me know, if you could point some other pointers ??

Regards, Ritesh

Tom,

After I increased the gc_releasable_locks from 0 to 1000. I can see the new sets of wait events :

STATSPACK report for

DB Name DB Id Instance Inst Num Release OPS Host
------------ ----------- ------------ -------- ----------- --- ------------
OPS 255777838 OPS1 1 8.1.7.3.0 YES node1

Snap Id Snap Time Sessions
------- ------------------ --------
Begin Snap: 36 08-Aug-06 11:31:01 12
End Snap: 37 08-Aug-06 11:45:31 12
Elapsed: 14.50 (mins)

Cache Sizes
~~~~~~~~~~~
db_block_buffers: 9000 log_buffer: 262144
db_block_size: 8192 shared_pool_size: 64000000

Load Profile
~~~~~~~~~~~~ Per Second Per Transaction
--------------- ---------------
Redo size: 731.98 159,205.00
Logical reads: 943.56 205,224.75
Block changes: 4.02 874.00
Physical reads: 32.35 7,035.50
Physical writes: 30.28 6,586.50
User calls: 3.25 706.00
Parses: 3.73 810.50
Hard parses: 0.13 29.25
Sorts: 0.70 151.25
Logons: 0.15 33.00
Executes: 5.78 1,256.75
Transactions: 0.00

% Blocks changed per Read: 0.43 Recursive Call %: 92.94
Rollback per transaction %: 25.00 Rows per Sort: #######

Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Buffer Nowait %: 100.00 Redo NoWait %: 100.00
Buffer Hit %: 96.57 In-memory Sort %: 86.61
Library Hit %: 95.15 Soft Parse %: 96.39
Execute to Parse %: 35.51 Latch Hit %: 100.00
Parse CPU to Parse Elapsd %: % Non-Parse CPU:

Shared Pool Statistics Begin End
------ ------
Memory Usage %: 30.14 33.55
% SQL with executions>1: 45.95 60.95
% Memory for SQL w/exec>1: 36.14 57.37

Top 5 Wait Events
~~~~~~~~~~~~~~~~~ Wait % Total
Event Waits Time (cs) Wt Time
-------------------------------------------- ------------ ------------ -------
direct path read 10,923 0 .00
db file sequential read 1,647 0 .00
row cache lock 471 0 .00
global cache cr request 397 0 .00
library cache lock 365 0 .00
-------------------------------------------------------------
^LWait Events for DB: OPS Instance: OPS1 Snaps: 36 -37
-> cs - centisecond - 100th of a second
-> ms - millisecond - 1000th of a second
-> ordered by wait time desc, waits desc (idle events last)

Avg
Total Wait wait Waits
Event Waits Timeouts Time (cs) (ms) /txn
---------------------------- ------------ ---------- ----------- ------ ------
direct path read 10,923 0 0 0 ######
db file sequential read 1,647 0 0 0 411.8
row cache lock 471 0 0 0 117.8
global cache cr request 397 0 0 0 99.3
library cache lock 365 0 0 0 91.3
enqueue 300 0 0 0 75.0

suggestions please ?? Users are using forms 6i.

Regards, Ritesh

Tom,

This is a test machine. Developers do testing here...they use forms 6i. When they try to save the data it takes around 2 minutes and 30 seconds. So why is this delay ??

I noticed one more thing, startup of the database is taking 2 minutes and 30 seconds.

1. startup nomount is fine
2. alter datbase mount is taking 2 minutes and 25 seconds.
3. alter database open is also fine.

Please let me know what could be the reason that "alter database mount" is taking so long time. As I understand "alter database mount" Checks the existence of Datafile,logfiles ,consitency of files,database (properly shutdown or not) etc...!!!

It seems the problem lies here.

Please let me know your expert comments.

Regards, Ritesh

Tom,

Thanks for the reply.

I will do as per your suggestion. But I am wondering why this database startup is taking so much time ?? When I try to mount, it is taking around 3 minutes of time.

I have checked every single thing I can think off...but could not get solution for slow startup.

Can you suggest some thing to start looking with a new angle.

Thanking in anticipation.

Regards, Ritesh

Hi Tom,

Thanks for your reply once again.

I have below mentioned datafiles:

SQL> select name from v$datafile;

NAME
--------------------------------------------------------------------------------
/dbfile/system
/dbfile/rbs_1_file_01
/dbfile/rbs_2_file_01
/dbfile/temp_1_file_01
/dbfile/temp_2_file_01
/dbfile/zpddb
/dbfile/zpdbz

And Below is the Tablespace information :

Tablesapce                       Size_Mb   Used_Mb   Free_Mb    Used_%
------------------------------ --------- --------- --------- ---------
TS_RBS_1                           256.0     128.8     127.2      50.3
TS_RBS_2                           256.0     128.8     127.2      50.3
ZPDDB_TS1                           300.0     121.3     178.7      40.4
SYSTEM                             256.0      55.4     200.6      21.6
ZPDBZ                              1000.0      65.9     934.1       6.6
TS_TEMP_1                          256.0        .0     256.0        .0
TS_TEMP_2                          256.0        .0     256.0        .0


Also, I am working on a parallel server and using forms.

Please let me know your comments. 

Regards, Ritesh 

Tom,

Thanks for prompt response.

I understand what you are saying. But client is adament that I should improve the performance..:-(

I saw redo log file size 100 MB and resized it to 4 MB. Just to give it a try, because i found on internet that sometimes redo log files of big size also gives slow response. But still no luck.

Also, I noticed one more thing when I open forms window to save some data....most of the times it is getting killed automatically....and then again I am restarting with scratch.

Do you have any clue at this point ??

Regards, Ritesh

Also, I can see the below pasted message in alert log, corresponding to every kill of forms window :

Instance recovery: looking for dead threads
Instance recovery: lock domain invalid but no dead threads

And , when i restart the database following message I can see in one of the *.trc file:

Instance name: OPS1
Redo thread mounted by this instance: 0 <none>
Oracle process number: 3
Unix process pid: 20843, image: oracle@node1 (LMON)

*** SESSION ID:(2.1) 2006-08-10 16:15:29.237
kjxggin: receive buffer size = 32768
kgxggin: SKGXN ver (2 0 Oracle 8.1 Reference CM)
kgxggcs: Setting state to 0 0.
*** 2006-08-10 16:15:29.257
Name Service recovery started
Service frozen
kgxggcs: Setting state to 1 1.
*** 2006-08-10 16:17:40.387
kgxggcs: Setting state to 82 2.
Deleted all non-local name entries
kgxggps: proposing substate 3
kgxggcs: Setting state to 82 3.
Broadcasted all local name entries for publish
Replayed all pending requests
kgxggps: proposing substate 4
kgxggcs: Setting state to 82 4.
Service normal
Name Service recovery done
*** 2006-08-10 16:17:40.407
kgxggps: proposing substate 5
kgxggcs: Setting state to 82 5.
*** 2006-08-10 16:17:43.406
Reconfiguration started
Synchronization timeout: 600 sec
List of nodes: 0,1,
Lock DB frozen
Non-local Process blocks cleaned out
Non-local Group blocks cleaned out
Resources and locks cleaned out
Resources remastered 0
Active sendback threshold = 8180 (tkts)
Traffic controller Initialized
Communication channels reestablished
Submitted all rdomain info
Submitted all remote-lock requests
*** 2006-08-10 16:18:11.706
Update rdomain variables
Dwn-cvts replayed, VALBLKs dubious
All grantable locks granted
*** 2006-08-10 16:18:21.639
Reconfiguration complete

I am looking for solution at all possible places, also thought of informing you....may be you can throw some light out of genius.

Regards, Ritesh

Tom, I am not too worried about startup time ...I am worried about the above mentioned messages I am getting with every startup and every kill of forms window.

Could you please say something about those messages and errors..??

Thanks, Ritesh

Tom,

can you just confirm something (or not) for me please. in the following extract from one of our stats reports some queries are shown as being executed more than 25,000 times during the 12minute period the report covers.

i am reading this correctly, or does the 25,000 figure relate to something other than the number of times a query was run?

any help you can give would be much appreciated.


STATSPACK report for

DB Name DB Id Instance Inst Num Release RAC Host
------------ ----------- ------------ -------- ----------- --- ----------------
APGATE 621650022 apgate 1 10.1.0.3.0 NO krumble2

Snap Id Snap Time Sessions Curs/Sess Comment
--------- ------------------ -------- --------- -------------------
Begin Snap: 4 11-Aug-06 11:01:12 28 7.9
End Snap: 5 11-Aug-06 11:12:50 30 12.5
Elapsed: 11.63 (mins)

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

Load Profile
~~~~~~~~~~~~ Per Second Per Transaction
--------------- ---------------
Redo size: 8,479.63 1,849.04
Logical reads: 11,051.16 2,409.78
Block changes: 108.00 23.55
Physical reads: 3.50 0.76
Physical writes: 1.33 0.29
User calls: 62.44 13.62
Parses: 29.60 6.45
Hard parses: 0.15 0.03
Sorts: 10.13 2.21
Logons: 0.06 0.01
Executes: 265.58 57.91
Transactions: 4.59

% Blocks changed per Read: 0.98 Recursive Call %: 87.89
Rollback per transaction %: 89.97 Rows per Sort: 83.79

Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Buffer Nowait %: 100.00 Redo NoWait %: 100.00
Buffer Hit %: 99.97 In-memory Sort %: 100.00
Library Hit %: 99.92 Soft Parse %: 99.51
Execute to Parse %: 88.85 Latch Hit %: 100.00
Parse CPU to Parse Elapsd %: 96.63 % Non-Parse CPU: 99.11

Shared Pool Statistics Begin End
------ ------
Memory Usage %: 51.06 51.40
% SQL with executions>1: 77.80 77.53
% Memory for SQL w/exec>1: 80.94 80.86

Top 5 Timed Events
~~~~~~~~~~~~~~~~~~ % Total
Event Waits Time (s) Call Time
-------------------------------------------- ------------ ----------- ---------
CPU time 96 91.03
db file sequential read 411 3 2.63
log file parallel write 343 2 2.25
db file scattered read 435 2 2.18
log file sync 149 1 1.12
-------------------------------------------------------------
.
.
.

.SQL ordered by Gets DB/Inst: APGATE/apgate Snaps: 4-5
-> Resources reported for PL/SQL code includes the resources used by all SQL
statements called by the code.
-> End Buffer Gets Threshold: 10000 Total Buffer Gets: 7,713,710
-> Captured SQL accounts for 118.9% of Total Buffer Gets
-> SQL reported below exceeded 1.0% of Total Buffer Gets

CPU Elapsd Old
Buffer Gets Executions Gets per Exec %Total Time (s) Time (s) Hash Value
--------------- ------------ -------------- ------ -------- --------- ----------
2,723,751 6 453,958.5 35.3 8.15 8.15 278025211
Module: JDBC Thin Client
SELECT * FROM ( SELECT TRUNC((SYSDATE-duedate)*24*60
) FROM contactinformation WHERE userid=:1 AND iscomp
lete=0 AND SYSDATE>(duedate) ORDER BY duedate ) WHER
E ROWNUM=1

1,565,180 58 26,985.9 20.3 14.36 14.40 3898815545
Module: JDBC Thin Client
SELECT CON.PRIORITY, CON.DETAILS, PKG_GENERAL.FN_CONVERT_TO_STRI
NG(CON.DUEDATE), CON.PERSONID CONTACTNAME, CON.POSITION, COMPANY
.NAME, CON.COMPANYID, CON.TODOID, CASE WHEN CON.DUEDATE <= SYSDA
TE THEN 0 WHEN CON.DUEDATE > SYSDATE THEN 1 ELSE 0 END FROM CONT
ACTINFORMATION CON, COMPANY COMPANY WHERE CON.COMPANYID=COMPANY.

717,651 819 876.3 9.3 18.10 18.24 2091003404
Module: JDBC Thin Client
BEGIN :1 := pkg_advertising.fn_calc_dis_for_advt(:2,:3,:4); END;


714,066 825 865.5 9.3 17.78 17.92 125011071
Module: JDBC Thin Client
SELECT COUNT(*) FROM ORDERLINEITEMS OLI, ORDERS O WHERE OLI.ADVE
RTISEMENTTYPEID = :B2 AND OLI.SECTIONID = :B1 AND OLI.ORDERID =
O.ORDERID AND OLI.ISHIDDEN = 0 AND OLI.EXPIRYDATE > SYSDATE - (P
KG_CONFIGURATION.FN_GETRENEWALGRACEPERIOD()) AND NVL (O.STATUS,
'-') NOT IN ('CANCELLED') AND NVL (OLI.STATUS, '-') NOT IN ('REP

431,877 56 7,712.1 5.6 4.64 5.20 3535957569
Module: JDBC Thin Client
BEGIN pkg_todo.pr_update_todo(:1,:2,:3,:4,:5,:6,:7,:8,:9,:10,:11
); END;

425,722 1 425,722.0 5.5 18.05 18.05 1603677759
DECLARE job BINARY_INTEGER := :job; next_date DATE := :mydate;
broken BOOLEAN := FALSE; BEGIN dbms_refresh.refresh('"APPLEGATE"
."MV_MGMTPOOLSTATUS"'); :mydate := next_date; IF broken THEN :b
:= 1; ELSE :b := 0; END IF; END;

424,842 1 424,842.0 5.5 18.00 18.00 3556075414
INSERT /*+ BYPASS_RECURSIVE_CHECK */ INTO "APPLEGATE"."MV_MGMTPO
OLSTATUS" SELECT DISTINCT userid, isactive, noofclients, noofite
ms, currentpoolvalue, allocatedvalue, discountcurrent, valueowed
FROM( SELECT a.userid, isactive, NVL (pkg_user.fn
_get_no_clients (a.userid), 0) AS noofclients, NVL (b.

340,252 46 7,396.8 4.4 1.11 1.14 4239780084
Module: JDBC Thin Client
SELECT /*+ FIRST_ROWS ORDERED */ CON.PRIORITY, CON.DETAILS, TO_C
HAR (CON.DUEDATE, 'DD-MON-YYYY HH24:MI:SS'), CON.PERSONID CONTAC
.SQL ordered by Gets DB/Inst: APGATE/apgate Snaps: 4-5
-> Resources reported for PL/SQL code includes the resources used by all SQL
statements called by the code.
-> End Buffer Gets Threshold: 10000 Total Buffer Gets: 7,713,710
-> Captured SQL accounts for 118.9% of Total Buffer Gets
-> SQL reported below exceeded 1.0% of Total Buffer Gets

CPU Elapsd Old
Buffer Gets Executions Gets per Exec %Total Time (s) Time (s) Hash Value
--------------- ------------ -------------- ------ -------- --------- ----------
TNAME, CON.POSITION, COM.NAME, CON.COMPANYID, CON.TODOID FROM CO
NTACTINFORMATION CON, USERS U, COMPANY COM WHERE COM.COMPANYID =
CON.COMPANYID AND U.USERID = CON.USERID AND CON.USERID = :B1 AN

329,821 56 5,889.7 4.3 1.52 1.63 1055230874
Module: JDBC Thin Client
SELECT * FROM CONTACTINFORMATION C WHERE C.USERID = :B2 AND C.US
ERID = C.CREATEDBY AND TRUNC(C.DUEDATE) = TRUNC(TO_DATE(:B1 ,'DD
/MM/YYYY HH24:MI:SS')) AND (C.COMPLETEDDATE IS NULL OR TRUNC(C.C
OMPLETEDDATE) = TRUNC(C.DUEDATE))

283,624 25,784 11.0 3.7 4.66 4.66 110479646
Module: JDBC Thin Client
SELECT COUNT(*) FROM WORKINGSHIFTS WS, WORKINGDAYSINSHIFT WDIS,
WORKINGPERIODSINDAY WPID WHERE WPID.WORKINGDAYID = WDIS.WORKINGD
AYID AND WDIS.SHIFTID = WS.SHIFTID AND UPPER(WDIS.WORKINGDAYNAME
) = RTRIM(UPPER(TO_CHAR(:B1 ,'DAY'))) AND WS.SHIFTID = :B2 AND :
B1 BETWEEN TO_DATE( (TO_CHAR(:B1 ,'DD/MM/YYYY')) || ' '|| WPID.W

280,241 50 5,604.8 3.6 0.75 0.87 2471348282
Module: JDBC Thin Client
SELECT /*+ FIRST_ROWS */ con.priority
, con.details, TO_CHAR (con.duedate, 'D
D-MON-YYYY HH24:MI:SS'), con.personid c
ontactname, con.POSITION, com.NAME, con.companyid,
con.todoid FROM contactinformati

227,951 8 28,493.9 3.0 3.90 3.90 1569749176
Module: JDBC Thin Client
SELECT QUERYA.USERNAME, QUERYA.USERPOINTS, QUERYA.USERPRICE, QUE
RYA.TEAMNAME, QUERYB.TEAMPOINTS, QUERYB.TEAMPRICE FROM (SELECT S
UM (NVL (OLI.POINTS, 0)) USERPOINTS, NVL (U.NAME, 'Unknown') USE
RNAME, NVL (T.NAME, 'No Team') TEAMNAME, SUM (NVL (OLI.PRICE, 0)
) USERPRICE, NVL(T.TEAMID,-1) TEAMID FROM ORDERLINEITEMS OLI, US

182,007 26,001 7.0 2.4 3.13 3.13 4223936558
Module: JDBC Thin Client
SELECT COUNT(*) FROM NONWORKINGDAYS NWD, WORKINGSHIFTS WS WHERE
(WS.SHIFTID = NWD.SHIFTID AND NWD.SHIFTID = :B2 AND TRUNC(:B1 )
= TRUNC(NWD.NONWORKINGDATE)) OR (TRIM(UPPER(TO_CHAR(:B1 ,'DAY'))
) NOT IN((SELECT UPPER(WDIS.WORKINGDAYNAME) FROM WORKINGDAYSINSH
IFT WDIS WHERE WDIS.SHIFTID = :B2 )))

Some Serious, with a Capital S, issue there. The rollback per Transaction % is 89.97 :O. wow man seems a lot to me. Guess most of the users have forgotten to commit.

Cheers

our problem is that we had a nice stable java application, then a change was made on tuesday that led to the system colapsing 10 minutes into the day. we backed out the change, and the only difference i can see is the number of times some new queries are being executed.

the development team has now moved on to other things, leaving the dba (me) to sort out the problem

dave

This is a snapshot of 60 min time interval. We are using Oracle 9i. There are lots of tables accessed remotely. Are the top 5 timed events could be because of that? We are trying to convert frequnetly accessed tables into materialized views.

Begin Snap: 28100 04-Apr-07 10:00:02 102 3,978.1
End Snap: 28101 04-Apr-07 11:00:02 103 3,944.2
Elapsed: 60.00 (mins)

Top 5 Timed Events
~~~~~~~~~~~~~~~~~~ % Total
Event Waits Time (s) Ela Time
-------------------------------------------- ------------ ----------- --------
CPU time 20,643 53.15
SQL*Net message from dblink 299,160 15,424 39.71
HS message to agent 719 821 2.11
db file scattered read 133,594 523 1.35
db file sequential read 182,102 375 .97
-------------------------------------------------------------

~~~~~~~~~~~~~~~~~~                                                      % Total
Event                                               Waits  Time (s) Ela Time
-------------------------------------------- ------------ ----------- --------
CPU time                                                    20,643    53.15
SQL*Net message from dblink                       299,160   15,424    39.71
HS message to agent                                   719      821     2.11
db file scattered read                            133,594      523     1.35
db file sequential read                           182,102      375      .97

Tom,

I have a 10g Database,I am using AWR report to check health of my database.

I could find below:

=====
Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Buffer Nowait %: 99.97 Redo NoWait %: 100.00
Buffer Hit %: 98.79 In-memory Sort %: 100.00
Library Hit %: 100.35 Soft Parse %: 98.72
Execute to Parse %: 94.15 Latch Hit %: 99.92

OUTPUT
--------------------------------------------------------------------------------
Parse CPU to Parse Elapsd %: 24.21 % Non-Parse CPU: 98.43

Shared Pool Statistics Begin End
------ ------
Memory Usage %: 64.49 68.65
% SQL with executions>1: 88.48 91.53
% Memory for SQL w/exec>1: 85.72 85.14

Top 5 Timed Events Avg %Total
~~~~~~~~~~~~~~~~~~ wait Call
Event Waits Time (s) (ms) Time Wait Class

OUTPUT
--------------------------------------------------------------------------------
------------------------------ ------------ ----------- ------ ------ ----------
db file sequential read 7,870,297 53,396 7 44.2 User I/O
CPU time 10,777 8.9
db file scattered read 1,273,119 10,711 8 8.9 User I/O
gc cr grant 2-way 3,551,732 2,005 1 1.7 Cluster
direct path read 389,349 1,935 5 1.6 User I/O
=========


If this is a case then in which section of TOP sql's i need to concentrate,Ie TOP sql bu cpu,reads,gets?

2)Also in segment Advisory section

-> Total Logical Reads: 1,332,326,081
-> Captured Segments account for 93.7% of Total

Tablespace Subobject Obj. Logical
Owner Name Object Name Name Type Reads %Total
---------- ---------- -------------------- ---------- ----- ------------ -------
APPLSYS WFLD SYS_IOT_TOP_846194 INDEX 647,931,808 48.63
AR ARD1 HZ_CUSTOMER_PROFILES TABLE 115,904,336 8.70
JTF JTFX JTF_TASK_ASSIGNMENTS INDEX 27,128,752 2.04
APPLSYS WFLD SYS_IOT_TOP_846114 INDEX 26,974,400 2.02

OUTPUT
--------------------------------------------------------------------------------
JTF JTFD JTF_TASKS_B TABLE 22,368,880 1.68
-------------------------------------------------------------

Segments by Physical Reads DB/Inst: DBAD/dbad1 Snaps: 895-906
-> Total Physical Reads: 19,289,894
-> Captured Segments account for 71.2% of Total

Tablespace Subobject Obj. Physical
Owner Name Object Name Name Type Reads %Total
---------- ---------- -------------------- ---------- ----- ------------ -------
PO POD PO_REQUISITION_LINES TABLE 3,578,485 18.55

OUTPUT
--------------------------------------------------------------------------------
OKC OKCD1 OKC_K_LINES_B TABLE 1,648,539 8.55
AR ARD HZ_PARTY_SITES TABLE 707,164 3.67
JTF JTFD JTF_TAE_1001_ACCOUNT TABLE 479,303 2.48
OKC OKCD1 OKC_RULES_B TABLE 378,466 1.96
-------------------------------------------------------------

^LSegments by Row Lock Waits DB/Inst: DBAD/dbad1 Snaps: 895-906
-> % of Capture shows % of row lock waits for each top segment compared
-> with total row lock waits for all segments captured by the Snapshot

Row

OUTPUT
--------------------------------------------------------------------------------
Tablespace Subobject Obj. Lock % of
Owner Name Object Name Name Type Waits Capture
---------- ---------- -------------------- ---------- ----- ------------ -------
APPLSYS FNDD FND_CONCURRENT_REQUE TABLE 7,008 87.11
APPLSYS APPLSYSD SYS_IOT_TOP_3063485 INDEX 598 7.43
APPLSYS FNDD FND_CONCURRENT_QUEUE TABLE 92 1.14
APPLSYS APPLSYSD FND_CONC_PROG_ONSITE TABLE 76 .94
APPLSYS FNDD FND_CONCURRENT_PROCE TABLE 24 .30


What could be my next course of action to reduce this?


Thanks,
Atul

Hi Tom,
We are running 10.1.0.5 on windows 2000 server. There is lot of paging and the server dies when there are only 30 Active sessions. The AWR report looks like:

WORKLOAD REPOSITORY report for

DB Name DB Id Instance Inst num Release Cluster Host
PRODORCL 2042967257 prodorcl 1 10.1.0.5.0 NO ORACLE1

Snap Id Snap Time Sessions Cursors/Session
Begin Snap: 17072 28-Feb-08 11:00:52 158 51.9
End Snap: 17073 28-Feb-08 12:00:10 113 29.2
Elapsed: 59.29 (mins)
DB Time: 488.46 (mins)

Report Summary

Cache Sizes (end)

Buffer Cache: 1,563M Std Block Size: 8K
Shared Pool Size:391M Log Buffer: 8,192K

Load Profile

Per Second Per Transaction
Redo size: 197,290.19 26,054.23
Logical reads: 16,778.28 2,215.75
Block changes: 910.74 120.27
Physical reads: 1,664.86 219.86
Physical writes:246.46 32.55
User calls: 269.97 35.65
Parses: 353.38 46.67
Hard parses: 34.44 4.55
Sorts: 164.36 21.71
Logons: 0.15 0.02
Executes: 803.92 106.17
Transactions: 7.57

% Blocks changed per Read:5.43 Recursive Call %:96.74
Rollback per transaction %:4.68 Rows per Sort: 592.71

Instance Efficiency Percentages (Target 100%)

Buffer Nowait %: 99.81 Redo NoWait %: 100.00
Buffer Hit %: 91.36 In-memory Sort %: 99.99
Library Hit %: 94.34 Soft Parse %: 90.25
Execute to Parse %: 56.04 Latch Hit %: 96.42
Parse CPU to Parse Elapsd %:58.59 % Non-Parse CPU:83.49

Shared Pool Statistics

Begin End
Memory Usage %: 71.99 73.29
% SQL with executions>1: 91.34 86.52
% Memory for SQL w/exec>1: 98.18 89.67

Top 5 Timed Events

Event Waits Time(s) Percent Total DB Time Wait Class
CPU time 12,107 41.31
db file sequential read 1,409,700 8,913 30.41 User I/O
db file scattered read 247,493 1,562 5.33 User I/O
SQL*Net more data from client 55,540 1,175 4.01 Network
library cache pin 11,367 756 2.58 Concurrency

Event Waits Timeouts Total Wait Time (s) Avg wait (ms) Waits /txn
db file sequential read 1,409,700 0 8,913 6 52.33
db file scattered read 247,493 0 1,562 6 9.19
SQL*Net more data from client 55,540 0 1,175 21 2.06
library cache pin 11,367 8 756 67 0.42
read by other session 112,845 0 395 3 4.19
db file parallel read 12,527 0 228 18 0.47
library cache load lock 5,891 2 215 37 0.22
latch: shared pool 118,090 0 199 2 4.38
direct path read temp 89,419 0 130 1 3.32
direct path read 50,395 0 125 2 1.87
enq: TX - row lock contention 127 36 124 978 0.00
log file sync 31,514 0 118 4 1.17
log file parallel write 94,449 0 81 1 3.51
latch: row cache objects 23,148 0 63 3 0.86
SQL*Net more data to client 182,757 0 58 0 6.78
latch: library cache 29,969 0 55 2 1.11
kksfbc child completion 971 963 54 55 0.04
latch: cache buffers chains 10,655 10,655 36 3 0.40
latch: session allocation 16,870 0 21 1 0.63
db file parallel write 15,290 0 16 1 0.57
Queue Monitor Task Wait 3 2 15 4,992 0.00
log file sequential read 499 0 12 24 0.02
row cache lock 1,808 0 7 4 0.07
library cache lock 118 0 6 50 0.00
buffer busy waits 204 0 6 28 0.01
SQL*Net break/reset to client 6,748 0 5 1 0.25
control file parallel write 1,554 0 5 3 0.06
SQL*Net more data from dblink 29,420 0 4 0 1.09
SQL*Net message to client 614,862 0 3 0 22.83
enq: SQ - contention 435 0 3 6 0.02
control file sequential read 1,046 0 2 2 0.04
inactive session 2 2 2 994 0.00
latch free 816 13 2 2 0.03
enq: HW - contention 128 0 1 11 0.00
process startup 37 0 1 30 0.00
enq: CU - contention 40 0 1 22 0.00
LGWR wait for redo copy 1,080 29 1 1 0.04
latch: library cache pin 304 0 1 2 0.01
direct path write temp 31,887 0 1 0 1.18
direct path write 61,145 0 0 0 2.27
wait list latch free 29 0 0 12 0.00
latch: library cache lock 80 0 0 4 0.00
control file single write 122 0 0 2 0.00
latch: cache buffers lru chain 178 0 0 1 0.01
log file switch completion 3 0 0 43 0.00
latch: object queue header operation 20 0 0 6 0.00
rdbms ipc reply 150 0 0 1 0.01
latch: In memory undo latch 12 0 0 5 0.00
latch: enqueue hash chains 7 0 0 6 0.00
enq: TX - index contention 2 0 0 19 0.00
SQL*Net message to dblink 3,789 0 0 0 0.14
latch: messages 7 0 0 4 0.00
ksfd: async disk IO 245 0 0 0 0.01
latch: checkpoint queue latch 1 0 0 14 0.00
latch: redo allocation 8 0 0 1 0.00
log file single write 4 0 0 1 0.00
enq: CF - contention 1 0 0 3 0.00
undo segment extension 27 23 0 0 0.00
latch: redo writing 1 0 0 0 0.00
latch: undo global data 1 0 0 0 0.00
SQL*Net message from client 614,904 0 287,862 468 22.83
Queue Monitor Slave Wait 692 0 3,840 5,549 0.03
wakeup time manager 24 12 3,590 149,603 0.00
Queue Monitor Wait 1,442 521 3,538 2,453 0.05
jobq slave wait 1,135 1,108 3,365 2,965 0.04
HS message to agent 22,992 0 105 5 0.85
single-task message 88 0 27 303 0.00
class slave wait 5 5 25 4,992 0.00
SQL*Net message from dblink 3,789 0 14 4 0.14

According to me there looks to be lot of DISK I/O contention and Network contention. Seeing the above report please suggest some tips to accomplish good performance.

Thanks.

We are on Windows 2000 service pack 4 and it is X86 family and having 6Gig Ram. Users generally select from different tables and insert into an temp table (cart)

A sample Query looks like this:

INSERT INTO falcon.container_items
(pk_container_item, pk_container, item_type, created_ts, pk_item,isbn_13, title_link_number, pk_binding_code, is_temporary)
SELECT falcon.container_item_seq.NEXTVAL, 1141681, 1, SYSDATE, x.pk_item,x.isbn_13, x.titlelink_number, x.pk_binding_code, 1
FROM (SELECT DISTINCT i.pk_item, i.isbn_13, i.titlelink_number,i.pk_binding_code FROM ybp.item_vendor iv,ybp.items i, ybp.status_codes sc WHERE iv.pk_item = i.pk_item
AND iv.pk_status_code = sc.pk_status_code
AND (iv.transaction_date BETWEEN TO_DATE ('01012000',
'MMDDYYYY' )AND TO_DATE ('03052008', 'MMDDYYYY' ))
AND iv.record_code = 'NT'
AND iv.active_record_code = 'S'
AND i.date_created < TRUNC (SYSDATE)
AND NVL (i.invalid_code, 0) IN (0, 2)
AND iv.pk_vendor != 140
AND sc.status_code NOT IN
('1', '3', '4', '13', '15', '17', '19')
AND i.bib_level IN
('JUV', 'POP', 'BASIC', 'GEN-AC', 'ADV-AC', 'PROF')
AND (NOT EXISTS (SELECT 1 FROM ybp.gobicustomer_activity gca
WHERE gca.title_link_number = i.titlelink_number AND gca.customer_base = 1320
AND ( gca.quantity_order > 0
OR gca.quantity_ship > 0 ))) /*End Scope*/) x
WHERE ROWNUM <= 1000 + 1

Regards,
aaa

Hey Tom:

I have questions about the awr report:

1. in the "SQL ordered by Elapsed Time" area:

Elapsed Time (s), CPU Time (s), Executions,  Elap per Exec (s),  I know these are the corresponding delta value got from dba_hist_sqlstat. what are the meaning of these:

Elapsed Time: total elapsed time in this snapshot

Executions: total execution time in this snapshot

Elap per Exec: Elapsed Time / Executions

are my explanation correct?

so we suppose the "Elap per Exec" should be less than or equal to one hour, since our snapshot interval is one hour, right? but i found some queries with "Elap per Exec" greater than 1 hour in awr, and here is the query to get it from dba_hist_sqlstat:

SQL> select sql.sql_id, sql.snap_id, snap.BEGIN_INTERVAL_TIME,
  2  snap.END_INTERVAL_TIME , sql.ELAPSED_TIME_DELTA/1000000/EXECUTIONS_DELTA Elap_per_Exec,
sql.ELAPSED_TIME_DELTA/1000000 delta_time,
  3    4  sql.EXECUTIONS_DELTA delta_exe
from hist_temp sql,DBA_HIST_SNAPSHOT snap
  5    6  where  sql.snap_id= snap.snap_id
  7  and sql.ELAPSED_TIME_DELTA/1000000/EXECUTIONS_DELTA> 3600                                                                                               
order by sql_id;  8

SQL_ID           SNAP_ID BEGIN_INTERVAL_TIME                 END_INTERVAL_TIME                   ELAP_PER_EXEC DELTA_TIME  DELTA_EXE
------------- ---------- ----------------------------------- ----------------------------------- ------------- ---------- ----------
dh2gn2b5urfy1       4486 03-MAR-08 04.00.33.503 PM           03-MAR-08 05.00.47.197 PM               4734.3509  4734.3509          1
dh2gn2b5urfy1       4503 04-MAR-08 09.00.14.601 AM           04-MAR-08 10.00.27.741 AM              3814.12127 3814.12127          1


why did this happen?

and I got a longest runing query with id "2auf1cnb492xy" with this:

SQL> select snap_id,
  2   to_char(begin_time,'yyyy-mm-dd hh24:mi:ss')
  3   starttime,
 to_char(end_time,'yyyy-mm-dd hh24:mi:ss')
  4    5   endtime,
  6  undoblks,
  7   maxquerylen/60 maxqrylen,
  8   MAXQUERYSQLID
  9   from dba_hist_undostat
 10   where maxquerylen = (select max(maxquerylen) from dba_hist_undostat);

SNAP_ID STARTTIME                           ENDTIME                               UNDOBLKS  MAXQRYLEN MAXQUERYSQLID
---------- ----------------------------------- ----------------------------------- ---------- ---------- -------------
      4512 2008-03-04 18:40:37                 2008-03-04 18:50:37                      30289     2507.2 2auf1cnb492xy


so if this was the longest runing query, it should show up in the dba_hist_sqlstat, but why it is not there:

SQL> select * from dba_hist_sqlstat where sql_id='2auf1cnb492xy';

no rows selected


how come!?


since we want to set the database undo retention as 30mins, so how can find the query which has the runing time >=30 mins in the history? We want to find them out and tuning them to prevent 01555 error.

Hey Tom, thank you for your response.

still have questions about this topic:

1. I have calculated, Elap per Exec: Elapsed Time delta / Executions delta for a specific snapshot. what I am confused is: this is elapsed time per execution, if 1000 people run a query at the same minute, then should this be counted as one execution or 1000 execution? do you mean since 1000 people will share one cursor, so this just accout as 1 execution?

2. still confused why the query in the dba_hist_undostat is not in the dba_hist_sqlstat. does dba_hist_sqlstat and dba_hist_sqltext include all the history queries, or some queries got filtered out, if yes, what is the criteria?

3. so if the elapsed time is not the serial time, then how can we find a long running query? like how can I find a query that run more than 30mins. is it possible to find out this in the Oracle?

4 and the reason why I want to find out these querise is we want to switch to a smaller undo tablespace, but we want to know if there is any query having the running time over our expected undo retention.
the last question is what happens to a cursor during undo swtich?

I know undo switch can happen during database is online,and I also did some test and see the pending offline old undotbs. but just curious if cursor is affected by undo switch and how can it continue to move on.


thank you very much!!

Hello Tom,
We are using an application, that imports data as a part from flat files of its functionality. The application connects to a 10g database. The first import of 2.5 million records took almost about 3 days.
While trying to determine the bottleneck our DBA produced an AWR. I'm trying to make sense of the information on AWR and connect the dots.
The snap was for a duration of 7 hours during which the process was running.

The top 5 timed events are as follows:

Event              Waits Time(s) Avg Wait(ms)  % Total Call Time  Wait Class 
CPU time                    14,913                   99.8   
log file parallel write  59,269  343    6   2.3   System I/O 
db file parallel write   118,397 260   2   1.7   System I/O 
log file sync    30,626  49   2   .3   Commit 
enq: TX - row lock contention  5,653  21   4   .1   Application

Here is the wait events table :

Event     Waits  %Time -outs  Total    Avg wait (ms)  Waits /txn
           Wait Time (s) 
log file parallel write  59,269  0.00   343    6  1.94 
db file parallel write   118,397 0.00   260    2  3.87 
log file sync    30,626  0.00   49    2  1.00 
enq: TX - row lock contention  5,653  0.00   21    4  0.18 
control file parallel write  14,133  0.00   19    1  0.46 
control file sequential read  39,195  0.00   18    0  1.28 
db file sequential read  1,414  0.00   10    7  0.05 
SQL*Net message to client  13,834,658 0.00  8    0  452.22 
log file switch completion  345  0.00   7    19  0.01 
SQL*Net more data from client  31,811  0.00   4    0  1.04 
os thread startup   15  0.00   1    77  0.00 
direct path write   983  0.00   1    1  0.03 
db file scattered read   31  0.00   1    19  0.00 
log file sequential read  648  0.00   1    1 0.02 
latch free    7  0.00   0    69  0.00 
rdbms ipc reply   286  0.00   0    1  0.01 
log file single write   648  0.00   0    1  0.02 
direct path read   972  0.00   0    0 0.03 
SQL*Net break/reset to client  2  0.00   0    30 0.00 
SQL*Net more data to client  823  0.00   0    0  0.03 
LGWR wait for redo copy  1,497  0.00   0    0  0.05 
buffer busy waits   104  0.00   0    0  0.00 
enq: TX - index contention  4  0.00   0    2  0.00 
latch: cache buffers lru chain  4  0.00   0    1  0.00 
latch: In memory undo latch  39  0.00   0    0  0.00 
SQL*Net message from client 13,834,657  0.00   114,915   8  452.22 
Streams AQ: qmn slave idle wait 895  0.00   24,528    27405  0.03 
Streams AQ: qmn coordinator idle wait 1,840 51.36  24,527    13330  0.06 
Streams AQ: waiting for time management or cleanup tasks 6 100.00 12,800  2133382 0.00 
jobq slave wait   20  100.00   59    2939  0.00 
class slave wait   14  0.00   0    0  0.00

If you notice the event, SQL*Net message from client, it had a total of 13,834,657 waits with a total wait time of 114,915 seconds - meaning that the database was in an idle state.

The SQL statistics are as follows :

SQL ordered by Elapsed Time
Resources reported for PL/SQL code includes the resources used by all SQL statements called by the code.
% Total DB Time is the Elapsed Time of the SQL statement divided into the Total Database Time multiplied by 100

Elapsed Time(s)  CPU Time(s) Executions Elap per Exec(s)  % Total DB Time SQL Module SQL Text 
 12,263   12,263   20,677    0.59   82.07     SELECT * FROM ACCOUNTS WHERE N... 
 797   795   5,571,811   0.00   5.33    INSERT INTO ACCT_ATTR_HIER_NOD... 
 683   680   5,568,568   0.00   4.57 INSERT INTO ACCOUNT_ATTRIBUTES... 
....................

The SQL that is hogging the CPU time is a select statement : SELECT * FROM ACCOUNTS WHERE NAMESPACEKEY = :1 AND ENDPOINT_NAME = :2 AND NAME IN ( :3 , :4 , :5 , :6 , :7 , :8 , :9 , :10 , :11 , :12 , :13 , :14 , :15 , :16 , :17 , :18 , :19 , :20 , :21 , :22 , :23 , :24 , :25 , :26 , :27 , :28 , :29 , :30 , :31 , :32 , :33 , :34 , :35 , :36 , :37 , :38 , :39 , :40 )

So the above select statement is taking up 82% of the CPU time which also equals the elapsed time (or the wall clock time). And CPU time is one of the top 5 timed events.

But the events indicate that SQL*Net message from client had a total of 13,834,657 waits with a total wait time of 114,915.

a)How do the SQL statistics and the Wait Events relate, if at all?
b)Which event would capture the SQL statement that is taking up most of the time? I'm not even sure if the above question is correct or makes sense.
Our team seems to think that the SQL statement that is taking up 82% of the time is the bottleneck while altogether ignoring the event of SQL*Net message from client. The SQL*Net message from client event is almost 10 times more than the time taken by the select statement.
To me, the event SQL*Net message from client seems to be the bottleneck and on looking up the session_wait view to determine the object of the wait, the P1text shows that a driver is the object of the wait. Also, I don't understand what it means when the object of the wait is a driver.
c)What kind of a driver is it referring to?
d)Are we targetting the right areas?
e)What else should we concentrate on?
I do realize that the information I provided is insufficient. Let me know if there is more information that i need to provide.

Thanks a lot in advacne,
Rish G.

ops$tkyte%ORA10GR2> select 5000000 * (1/1000) / 60 /60 from dual;

5000000*(1/1000)/60/60
----------------------
            1.38888889

Tom,
Thanks for the response. I apologize for the bad formatting above. That was my fault. I thought that formatting in notepad would work. We were given a nicely formatted report in html.

I understand and agree what you say about row by row processing. Apparently, the application that we are using does bulk processing(the defualt was 100; we're going to try and set different numbers to test)
For my understanding , so does the 'SQL*Net Message from Client' event have any impact on the slow processing times in the above case? It is not a idle event where a user logs in and then uses the client to submit queries intermittently. This connection is opened by the application and all it does is import data from a flat file. What do you think could be the cause of the enormous waits with total of 13,834,657 waits and a total wait time of 114,915? I realize that its totally a short in the dark for you and there could be many many reasons, but when you see an such long wait times from an application (where no user interaction is involved) what do you think about it?
Is the long wait caused because of the row by row processing and cascading inserts?

ops$tkyte%ORA10GR2> select 5000000 * (1/1000) * 50 / 60 / 60 /24 from dual;

5000000*(1/1000)*50/60/60/24
----------------------------
                  2.89351852

for i in 1 .. 5,000,000
loop
   <sqlnet message from client wait here>
   insert
   <sqlnet message from client wait here>
   update
   <sqlnet message from client wait here>
   delete
end loop

Thank you so much for the wonderful explanation. As per the application team, the sql is batch processed - 100 at a time. That is the default batch size. This number can be changed for optimum performance. But, is there a way to prove/disprove that the sql is not batch processed, apart from looking at the code. We don't have access to the code as this is a 3rd party application.

Is there a way to interpret the dynamic views or some tables that the sql was batch processed?

See the following from a statspack report in a 10g R2 database. Why do control file sequential read waits appear in both Wait Events and Background Wait Events and why such different values:

^LWait Events DB/Inst: BOS/BOS Snaps: 34-35
-> s - second, cs - centisecond, ms - millisecond, us - microsecond
-> %Timeouts: value of 0 indicates value was < .5%. Value of null is truly 0
-> Only events with Total Wait Time (s) >= .001 are shown
-> ordered by Total Wait Time desc, Waits desc (idle events last)

Avg
%Time Total Wait wait Waits
Event Waits -outs Time (s) (ms) /txn
--------------------------------- ------------ ------ ---------- ------ --------
log file parallel write 3,372 0 2 1 0.9
log file sync 2,358 0 2 1 0.6
control file sequential read 6,268 0 1 0 1.6
db file sequential read 186 0 0 2 0.0
db file parallel write 511 0 0 1 0.1
os thread startup 2 0 0 70 0.0
db file scattered read 6 0 0 17 0.0
SQL*Net more data to client 2,978 0 0 0 0.8
control file parallel write 136 0 0 1 0.0
latch free 1 0 0 68 0.0
SQL*Net break/reset to client 36 0 0 0 0.0
LGWR wait for redo copy 209 0 0 0 0.1
direct path write 19 0 0 0 0.0
buffer busy waits 46 0 0 0 0.0
SQL*Net message from client 62,356 0 14,053 225 16.0
jobq slave wait 413 87 1,168 2829 0.1
Streams AQ: waiting for messages 60 100 294 4892 0.0
wait for unread message on broadc 297 100 293 986 0.1
SQL*Net more data from client 2,693 0 0 0 0.7
SQL*Net message to client 62,357 0 0 0 16.0
-------------------------------------------------------------
^LBackground Wait Events DB/Inst: BOS/BOS Snaps: 34-35
-> %Timeouts: value of 0 indicates value was < .5%. Value of null is truly 0
-> Only events with Total Wait Time (s) >= .001 are shown
-> ordered by Total Wait Time desc, Waits desc (idle events last)

Avg
%Time Total Wait wait Waits
Event Waits -outs Time (s) (ms) /txn
--------------------------------- ------------ ------ ---------- ------ --------
log file parallel write 3,371 0 2 1 0.9
db file parallel write 511 0 0 1 0.1
os thread startup 2 0 0 70 0.0
control file parallel write 135 0 0 1 0.0
control file sequential read 130 0 0 0 0.0
events in waitclass Other 209 0 0 0 0.1
rdbms ipc message 4,537 32 4,389 967 1.2
smon timer 3 33 399 ###### 0.0
pmon timer 100 100 294 2937 0.0
-------------------------------------------------------------

Whereas many of the stats that appear in both places are very similar, the control file sequential read stats are hugely different. Here is another example from the same database, when under a different load.
control file sequential reads=35,040 wait time=6 secs
and in background waits
control file sequential reads=209 wait time=0 secs
That's a massive difference - one figure would indicate a potential problem with control file reads, but the other would not. I think that there probably is a problem here, what do you think?
Have a look at this:

Avg
%Time Total Wait wait Waits
Event Waits -outs Time (s) (ms) /txn
--------------------------------- ------------ ------ ---------- ------ --------
log file sync 28,284 0 36 1 0.2
log file parallel write 26,995 0 19 1 0.2
db file parallel write 7,623 0 10 1 0.0
db file sequential read 1,745 0 8 4 0.0
control file sequential read 35,040 0 6 0 0.2
log file sequential read 254 0 4 14 0.0
db file scattered read 110 0 2 16 0.0
SQL*Net break/reset to client 526 0 1 3 0.0
Log archive I/O 731 0 0 1 0.0
SQL*Net more data to client 10,009 0 0 0 0.1
enq: TX - index contention 64 0 0 6 0.0
read by other session 26 0 0 9 0.0
control file parallel write 181 0 0 1 0.0
buffer busy waits 1,274 0 0 0 0.0
log file switch completion 4 0 0 8 0.0
enq: TX - row lock contention 37 0 0 1 0.0
LGWR wait for redo copy 654 0 0 0 0.0
direct path write 89 0 0 0 0.0
latch: cache buffers chains 89 0 0 0 0.0
enq: SQ - contention 7 0 0 0 0.0
enq: TX - contention 1 0 0 2 0.0
direct path read 179 0 0 0 0.0
SQL*Net message from client 538,583 0 16,330 30 3.4
jobq slave wait 413 87 1,167 2826 0.0
wait for unread message on broadc 298 100 294 986 0.0
Streams AQ: waiting for messages 60 100 294 4892 0.0
SQL*Net more data from client 9,478 0 2 0 0.1
SQL*Net message to client 538,607 0 0 0 3.4
-------------------------------------------------------------
^LBackground Wait Events DB/Inst: BOS/BOS Snaps: 15-16
-> %Timeouts: value of 0 indicates value was < .5%. Value of null is truly 0
-> Only events with Total Wait Time (s) >= .001 are shown
-> ordered by Total Wait Time desc, Waits desc (idle events last)

Avg
%Time Total Wait wait Waits
Event Waits -outs Time (s) (ms) /txn
--------------------------------- ------------ ------ ---------- ------ --------
log file parallel write 27,004 0 19 1 0.2
db file parallel write 7,646 0 10 1 0.0
log file sequential read 254 0 4 14 0.0
Log archive I/O 731 0 0 1 0.0
control file parallel write 181 0 0 1 0.0
control file sequential read 209 0 0 0 0.0
events in waitclass Other 654 0 0 0 0.0
direct path write 89 0 0 0 0.0

"reads are done by things other than just backgrounds, your dedicated server can read the control file. your dedicated server is not a background process."

Yep, good point - I hadn't thought of it in that way.

Thanks

Hello,
I don't know if it's appropiate to write here and since it's the first time i do it, you have every right to delete this.
This system doesn't perform well it's quite slow and I have seen that db file scattered read is very high
but the soft parse ratio is pretty good.
From what i have read this indicates that the database is undergoing a lot of full table scans or index fast full scans which will slow down the database, but somewhere else they say that maybe it's not the reason for wait and maybe the full table scan are better for performance.
What's your opinion?

Thank you very much for your time!

STATSPACK report for

DB Name DB Id Instance Inst Num Release OPS Host
------------ ----------- ------------ -------- ----------- --- ------------
1 8.1.7.4.0

Snap Id Snap Time Sessions
------- ------------------ --------
Begin Snap: 31 02-May-08 10:45:32 54
End Snap: 32 02-May-08 11:26:30 54
Elapsed: 40.97 (mins)

Cache Sizes
~~~~~~~~~~~
db_block_buffers: 10240 log_buffer: 163840
db_block_size: 8192 shared_pool_size: 52428800

Load Profile
~~~~~~~~~~~~ Per Second Per Transaction
--------------- ---------------
Redo size: 1,497.67 2,512.81
Logical reads: 1,344.71 2,256.17
Block changes: 5.25 8.80
Physical reads: 807.52 1,354.87
Physical writes: 1.74 2.92
User calls: 13.29 22.30
Parses: 4.02 6.75
Hard parses: 0.02 0.03
Sorts: 0.18 0.30
Logons: 0.16 0.26
Executes: 4.02 6.74
Transactions: 0.60

% Blocks changed per Read: 0.39 Recursive Call %: 38.06
Rollback per transaction %: 0.00 Rows per Sort: 571.81

Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Buffer Nowait %: 99.19 Redo NoWait %: 99.76
Buffer Hit %: 39.95 In-memory Sort %: 98.88
Library Hit %: 99.27 Soft Parse %: 99.61
Execute to Parse %: -0.07 Latch Hit %: 99.68
Parse CPU to Parse Elapsd %: % Non-Parse CPU:

Shared Pool Statistics Begin End
------ ------
Memory Usage %: 90.75 87.96
% SQL with executions>1: 83.86 86.26
% Memory for SQL w/exec>1: 58.97 63.26

Top 5 Wait Events
~~~~~~~~~~~~~~~~~ Wait % Total
Event Waits Time (cs) Wt Time
-------------------------------------------- ------------ ------------ -------
db file scattered read 276,389 0 .00
buffer busy waits 26,680 0 .00
db file sequential read 10,443 0 .00
log file parallel write 1,507 0 .00
log file sync 1,489 0 .00
-------------------------------------------------------------

End value
Parameter Name Begin value (if different)
----------------------------- --------------------------------- --------------
background_dump_dest
compatible 8.1.0
control_files
core_dump_dest
db_block_buffers 10240
db_block_size 8192
db_domain
db_name
distributed_transactions 10
global_names FALSE
instance_name
java_pool_size 20971520
job_queue_interval 60
job_queue_processes 4
large_pool_size 614400
log_archive_dest_1
log_archive_format arch_%t_%s.arc
log_archive_start TRUE
log_buffer 163840
log_checkpoint_interval 10000
log_checkpoint_timeout 1800
max_enabled_roles 30
open_cursors 300
open_links 4
os_authent_prefix
processes 150
remote_login_passwordfile NONE
service_names
shared_pool_size 52428800
sort_area_retained_size 65536
sort_area_size 65536
user_dump_dest
-------------------------------------------------------------

Tom,
The instance activity section of awr report shows buffer is not pinned count and buffer is pinned count are 40,706,928 and 2,346,447,160 respectively for a duration of 2hrs.

What does these statistics indicate ?

Hi Tom,

Clients who run our software leave the snapshot frequency at 1 hour (10g out of the box). Some of the processes run in a "tighter" timeframe. To determine bottlenecks I purpose that we switch to every 30 minutes (via MODIFY_SNAPSHOT_SETTINGS). Do you see any problems with a 30 minute setting? If so, what are the trade offs?

Thanks in advance!

Hi Tom,

I know you don't like to generalize, but, do you think snapshots every 30 minutes is reasonable?

Thanks again.

Hi Tom,
Thanks for your time.

I have the Top 5 wait events from Statspack report as follows.

Event Waits Wait Time (s) % Total Wt Time
db file scattered read 768,539 5,846 85.08
db file sequential read 315,641 517 7.53
buffer busy waits 39,347 138 2.01
log file sync 39,858 114 1.66
log file parallel write 78,903 82 1.19


Further File IO Statistics


Tablespace Filename Read% Reads Av Reads/s Av Rd(ms) Av Blks/Rd Write% Writes Av Writes/s Buffer Waits Av Buf Wt(ms)
DATA /oradata02/data-01.dbf 71.00 774,887 430.49 6.96 14.40 5.78 4,181 2.32 20,158 5.09
DATA07 /oradata02/data07-01.dbf 28.08 306,442 170.25 1.85 1.46 0.18 127 0.07 20,905 1.82
DATA06 /oradata03/data06-01.dbf 0.21 2,282 1.27 8.98 1.35 15.41 11,147 6.19 155 0.65
.....
.....
for rest tablespaces % read is very low <1% there are Total 22 Tablespaces , but 90% of the objects are created in DATA tablespace.



Your comment on the Top 5 events and File IO statistics please.

Regards

useful for fixed width stuff

Tom:

what is the difference between STATSPACK and AWR? I used AWR a lot, but never use STATSPACK, which one is better for performance tuning?

Hi Tom,

Many Thanks for your time.
I just want to understand the basics about statspack. Please corect me if my understanding is wrong.

Scenario:
1st Statspack run at T1 and 2nd Statspack is run at T2. say T2-T1 is 15 mins. Then I generate the Statspack report for snapshots IDs created at T1 & T2.

Now.
Question. My Statspack report will give me the differnce ( and % change) in the Database events/waits?

My question above is basically how Oracle generates Statspack report. If you could please explain with some example( as you always do) by taking any one event( say "db file scattered read" ) and showing the waits , wait time of that event at T1 and T2 and Finally in statspack report showing the waits, wait time.

Tom, if you feel that I should walk thro some documentation, please point me to that.

Cheers.

¿table1¿ has a column called city. The records with city='Delhi' are to be updated with city='Mumbai' and records with city='Mumbai' are to be updated with city='Delhi'. Write a single SQL statement to do this.

Many Thanks Tom.

Cheers.

Hi Tom,

Many thanks for your time as I am aware that you have busy schedule during this week.

I have the followings findings/questions.

a. "db file scattered read" too high. whether
reorganising tables in other tablespaces will help? and how to hit the "poor" sql?
b. "buffer busy wait" too high?
c. Your opinion on "SQL ordered by Gets"?
d. "Keep Buffer Pool" is not being utilised? as "table scans (short tables)" is too high?
e. Too bad "Execute to Parse ratio"?
f. Buffer hit ratio low ? "db_cache_size" is 512M shall
we try increasing it ( v$db_cache_advice suggest to double it)?

g. Where you can see the "bottleneck" in db?

Some background - we are using RAC but with no load balancing and also connections are directed to second instance.

STATSPACK report for

DB Name DB Id Instance Inst Num Release Cluster Host
------------ ----------- ------------ -------- ----------- ------- ------------
db04C 2932903571 db04c02 2 9.2.0.6.0 YES hostd02

Snap Id Snap Time Sessions Curs/Sess Comment
--------- ------------------ -------- --------- -------------------
Begin Snap: 2270 22-Sep-08 23:17:02 ####### .0
End Snap: 2271 22-Sep-08 23:43:02 ####### .0
Elapsed: 26.00 (mins)

Cache Sizes (end)
~~~~~~~~~~~~~~~~~
Buffer Cache: 896M Std Block Size: 8K
Shared Pool Size: 720M Log Buffer: 2,048K

Load Profile
~~~~~~~~~~~~ Per Second Per Transaction
--------------- ---------------
Redo size: 750,021.63 19,686.60
Logical reads: 46,805.63 1,228.56
Block changes: 1,929.83 50.65
Physical reads: 10,510.84 275.89
Physical writes: 93.06 2.44
User calls: 1,906.09 50.03
Parses: 754.47 19.80
Hard parses: 0.01 0.00
Sorts: 20.31 0.53
Logons: 0.02 0.00
Executes: 754.93 19.82
Transactions: 38.10

% Blocks changed per Read: 4.12 Recursive Call %: 22.11
Rollback per transaction %: 0.00 Rows per Sort: 5.27

Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Buffer Nowait %: 95.72 Redo NoWait %: 100.00
Buffer Hit %: 77.60 In-memory Sort %: 100.00
Library Hit %: 100.01 Soft Parse %: 100.00
Execute to Parse %: 0.06 Latch Hit %: 99.15
Parse CPU to Parse Elapsd %: 41.55 % Non-Parse CPU: 99.33

Shared Pool Statistics Begin End
------ ------
Memory Usage %: 100.00 100.00
% SQL with executions>1: 84.37 84.07
% Memory for SQL w/exec>1: 77.11 75.98

Top 5 Timed Events
~~~~~~~~~~~~~~~~~~ % Total
Event Waits Time (s) Ela Time
-------------------------------------------- ------------ ----------- --------
db file scattered read 2,708,910 54,664 51.28
buffer busy waits 2,954,810 22,520 21.13
db file sequential read 4,349,792 15,765 14.79
latch free 788,738 5,979 5.61
CPU time 5,421 5.09
-------------------------------------------------------------
Wait Events for DB: db04C Instance: db04c02 Snaps: 2270 -2271
-> s - second
-> cs - centisecond - 100th of a second
-> ms - millisecond - 1000th of a second
-> us - microsecond - 1000000th of a second
-> ordered by wait time desc, waits desc (idle events last)

Avg
Total Wait wait Waits
Event Waits Timeouts Time (s) (ms) /txn
---------------------------- ------------ ---------- ---------- ------ --------
db file scattered read 2,708,910 0 54,664 20 45.6
buffer busy waits 2,954,810 72 22,520 8 49.7
db file sequential read 4,349,792 0 15,765 4 73.2
latch free 788,738 617,049 5,979 8 13.3
buffer busy global CR 180,811 1 1,604 9 3.0
log file sync 60,298 0 215 4 1.0
log file parallel write 113,500 0 130 1 1.9
global cache busy 162 74 90 554 0.0
direct path write (lob) 61,765 0 80 1 1.0
direct path read (lob) 31,377 0 42 1 0.5
db file parallel write 3,675 0 22 6 0.1
enqueue 3,938 4 14 4 0.1
control file sequential read 2,167 0 13 6 0.0
wait list latch free 581 0 11 19 0.0
SQL*Net more data to client 171,867 0 9 0 2.9
control file parallel write 537 0 7 13 0.0
buffer busy global cache 641 0 3 5 0.0
SQL*Net break/reset to clien 4,716 0 1 0 0.1
LGWR wait for redo copy 731 32 1 2 0.0
log file switch completion 6 0 0 67 0.0
CGS wait for IPC msg 15,452 15,452 0 0 0.3
row cache lock 67 0 0 2 0.0
name-service call wait 2 0 0 19 0.0
DFS lock handle 110 0 0 0 0.0
ksxr poll remote instances 1,216 1,141 0 0 0.0
library cache pin 1 0 0 17 0.0
global cache s to x 21 0 0 1 0.0
log file single write 8 0 0 1 0.0
log file sequential read 8 0 0 1 0.0
global cache open x 6 2 0 1 0.0
PX Deq: reap credit 88 88 0 0 0.0
buffer deadlock 9 9 0 0 0.0
SQL*Net message from client 2,092,362 0 196,122 94 35.2
gcs remote message 77,027 76,911 5,921 77 1.3
virtual circuit status 52 52 1,523 29297 0.0
ges remote message 42,770 38,189 1,521 36 0.7
wakeup time manager 50 50 1,462 29231 0.0
PX Idle Wait 89 89 217 2442 0.0
SQL*Net more data from clien 383,624 0 27 0 6.5
SQL*Net message to client 2,092,351 0 3 0 35.2
-------------------------------------------------------------
Background Wait Events for DB: db04C Instance: db04c02 Snaps: 2270 -2271
-> 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 113,502 0 130 1 1.9
latch free 13,413 8,178 60 5 0.2
db file parallel write 3,675 0 22 6 0.1
control file sequential read 2,080 0 13 6 0.0
control file parallel write 537 0 7 13 0.0
LGWR wait for redo copy 731 32 1 2 0.0
enqueue 3,006 0 1 0 0.1
CGS wait for IPC msg 15,451 15,451 0 0 0.3
wait list latch free 5 0 0 17 0.0
db file sequential read 34 0 0 2 0.0
DFS lock handle 110 0 0 0 0.0
ksxr poll remote instances 1,216 1,141 0 0 0.0
log file single write 8 0 0 1 0.0
log file sequential read 8 0 0 1 0.0
rdbms ipc message 85,560 17,809 10,672 125 1.4
gcs remote message 77,027 76,911 5,921 77 1.3
ges remote message 42,770 38,189 1,521 36 0.7
pmon timer 552 512 1,520 2754 0.0
smon timer 5 5 1,465 ###### 0.0
-------------------------------------------------------------
SQL ordered by Gets for DB: db04C Instance: db04c02 Snaps: 2270 -2271
-> 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
--------------- ------------ -------------- ------ -------- --------- ----------
12,669,563 1,657 7,646.1 17.4 1229.82 41174.98 4071151282
Module: java@hosta01 (TNS V1-V3)
SELECT T1.objid,T1.dev,T1.x_e2edata,T1.x_create_timestamp,T1.x_u
pdate_timestamp,T1.x_e2edata2proc_inst FROM table_x_e2e_data T1
INNER JOIN table_proc_inst T2 ON T1.x_e2edata2proc_inst = T2.ob
jid WHERE ( T2.objid = :P16 )

11,253,264 1,258 8,945.4 15.4 1688.93 38571.07 1099683404
Module: java@hosta01 (TNS V1-V3)
SELECT T1.objid,T1.dev,T1.slm_code,T1.event_time,T1.is_suspended
,T1.period_elapsed,T1.period_business,T1.period_clock,T1.total_e
lapsed,T1.total_business,T1.total_clock,T1.current_milestone,T1.
current_remaining,T1.fix_milestone,T1.fix_remaining,T1.err_code,
T1.event_milestone,T1.update_time,T1.x_clk_chg_reason,T1.x_reaso

10,047,335 21 478,444.5 13.8 630.66 3268.64 1771214746
Module: java@hosta02 (TNS V1-V3)
SELECT rqst_inst_objid,rqst_inst_start_time,rqst_inst_end_time,r
qst_inst_status,rqst_inst_focus_type,rqst_inst_focus_lowid,rqst_
inst_retry_count,rqst_inst_err_code,rqst_inst_err_mess,rqst_inst
_busy,rqst_inst_focus_object,rqst_inst_error_status,rqst_inst_er
r_type,rqst_inst_err_info,rqst_inst_resume_focus_type,rqst_inst_

8,753,130 16,241 539.0 12.0 334.55 542.48 3629242874
Module: java@hosta02 (TNS V1-V3)
SELECT T101.name,T101.objid FROM table_site_part T100,table_orde
r_action T101 WHERE( T100.objid = :P1)AND(T101.order_action_svc
2site_part=T100.objid)

21,713 16,241 1.3 0.1 334.55 542.48 3629242874
Module: java@hosta02 (TNS V1-V3)
SELECT T101.name,T101.objid FROM table_site_part T100,table_orde
r_action T101 WHERE( T100.objid = :P1)AND(T101.order_action_svc
2site_part=T100.objid)

SQL ordered by Reads for DB: db04C Instance: db04c02 Snaps: 2270 -2271
-> End Disk Reads Threshold: 1000

CPU Elapsd
Physical Reads Executions Reads per Exec %Total Time (s) Time (s) Hash Value
--------------- ------------ -------------- ------ -------- --------- ----------
Module: java@hosta01 (TNS V1-V3)
SELECT T103.attribute_value,T103.attribute_datatype,T103.objid F
ROM table_order_action T100,table_contract T101,table_contract T
102,table_fa_contract T103 WHERE ( T103.attribute_name = :P1) A
ND ( T100.objid = :P2)AND (T102.objid=T103.fa_contract2contract
) AND (T100.order_action2contract=T101.objid) AND (T102.x_contra

-------------------------------------------------------------
SQL ordered by Parse Calls for DB: db04C Instance: db04c02 Snaps: 2270 -2271
-> End Parse Calls Threshold: 1000

% Total
Parse Calls Executions Parses Hash Value
------------ ------------ -------- ----------
143,944 143,943 12.23 982153273
Module: java@hosta02 (TNS V1-V3)
SELECT T101.attribute_value,T101.attribute_datatype,T101.objid F
ROM table_site_part T100,table_fa_site_part T101 WHERE ( T101.at
tribute_name = :P1) AND ( T100.objid = :P2)AND (T100.objid=T10
1.fa_site_part2site_part)

...

-------------------------------------------------------------
Instance Activity Stats for DB: db04C Instance: db04c02 Snaps: 2270 -2271

Statistic Total per Second per Trans
--------------------------------- ------------------ -------------- ------------
CPU used by this session 542,144 347.5 9.1
CPU used when call started 542,109 347.5 9.1
CR blocks created 95,683 61.3 1.6
Cached Commit SCN referenced 0 0.0 0.0
Commit SCN cached 0 0.0 0.0
DBWR buffers scanned 2,522,827 1,617.2 42.5
DBWR checkpoint buffers written 26,536 17.0 0.5
DBWR checkpoints 2 0.0 0.0
DBWR free buffers found 2,491,932 1,597.4 41.9
DBWR fusion writes 0 0.0 0.0
DBWR lru scans 2,921 1.9 0.1
DBWR make free requests 3,283 2.1 0.1
DBWR revisited being-written buff 0 0.0 0.0
DBWR summed scan depth 2,522,827 1,617.2 42.5
DBWR transaction table writes 94 0.1 0.0
DBWR undo block writes 21,795 14.0 0.4
.....
.....
RowCR - row contention 22 0.0 0.0
RowCR attempts 2,907 1.9 0.1
RowCR hits 2,883 1.9 0.1
SQL*Net roundtrips to/from client 2,092,994 1,341.7 35.2
active txn count during cleanout 31,584 20.3 0.5
background checkpoints completed 2 0.0 0.0
background checkpoints started 2 0.0 0.0
background timeouts 2,897 1.9 0.1
branch node splits 9 0.0 0.0
buffer is not pinned count 63,261,145 40,552.0 1,064.4
buffer is pinned count 311,617,437 199,754.8 5,243.2
bytes received via SQL*Net from c 1,279,547,376 820,222.7 21,529.2
bytes sent via SQL*Net to client 974,859,845 624,910.2 16,402.7
.....

Instance Activity Stats for DB: db04C Instance: db04c02 Snaps: 2270 -2271

Statistic Total per Second per Trans
--------------------------------- ------------------ -------------- ------------
table scan blocks gotten 48,090,112 30,827.0 809.2
table scan rows gotten 1,894,952,873 1,214,713.4 31,883.9
table scans (cache partitions) 0 0.0 0.0
....
user calls 2,973,503 1,906.1 50.0
user commits 59,432 38.1 1.0
user rollbacks 1 0.0 0.0
....
-------------------------------------------------------------
Tablespace IO Stats for DB: db04C Instance: db04c02 Snaps: 2270 -2271
->ordered by IOs (Reads + Writes) desc

Tablespace
------------------------------
Av Av Av Av Buffer Av Buf
Reads Reads/s Rd(ms) Blks/Rd Writes Writes/s Waits Wt(ms)
-------------- ------- ------ ------- ------------ -------- ---------- ------
DATA
4,655,800 2,984 15.0 2.9 6,825 4 2,598,248 9.4
DATA18
1,821,555 1,168 0.8 1.0 1,126 1 445,491 0.8
INDEX18
348,167 223 0.8 1.0 5,831 4 81,058 0.8
DATA07
191,647 123 2.9 4.3 160 0 3,264 2.4
DATA06
30,914 20 15.8 1.4 62,254 40 3,364 1.5

....
.....
File IO Stats for DB: db04C Instance: db04c02 Snaps: 2270 -2271
->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)
-------------- ------- ------ ------- ------------ -------- ---------- ------
DATA /dborafiles/mydb/db04c/oradata02/data-01.dbf
4,655,800 2,984 15.0 2.9 6,825 4 2,598,248 9.4

....

File IO Stats for DB: db04C Instance: db04c02 Snaps: 2270 -2271
->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)
-------------- ------- ------ ------- ------------ -------- ---------- ------

DATA17 /dborafiles/mydb/db04c/oradata02/data17-01.dbf
254 0 1.7 1.0 58 0 0

DATA18 /dborafiles/mydb/db04c/oradata03/data18-01.dbf
1,821,555 1,168 0.8 1.0 1,126 1 445,491 0.8

....
...
Buffer Pool Statistics for DB: db04C Instance: db04c02 Snaps: 2270 -2271
-> 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 61,216 77.6 73,001,510 16,356,493 58,863 0 0########
K 30,608 0 0 0 0 0 0
R 15,304 100.0 4,285 0 0 0 0 0
-------------------------------------------------------------

Buffer wait Statistics for DB: db04C Instance: db04c02 Snaps: 2270 -2271
-> ordered by wait time desc, waits desc

Tot Wait Avg
Class Waits Time (s) Time (ms)
------------------ ----------- ---------- ---------
data block 3,118,888 24,533 8
bitmap block 2,592 4 2
undo block 570 1 1
undo header 164 0 3
segment header 370 0 1
bitmap index block 317 0 1
1st level bmb 2 0 0
-------------------------------------------------------------
Top 5 Logical Reads per Segment for DB: db04C Instance: db04c02 Snaps: 2270 -2
-> End Segment Logical Reads Threshold: 10000

Subobject Obj. Logical
Owner Tablespace Object Name Name Type Reads %Total
---------- ---------- -------------------- ---------- ----- ------------ -------
XX DATA TABLE_X_E2E_DATA TABLE 18,399,824 25.44
XX DATA12 TABLE_ORDER_ACTION TABLE 16,254,816 22.47
XX DATA TABLE_SLM_LOG TABLE 11,297,456 15.62
XX DATA18 TABLE_RQST_INST TABLE 9,988,832 13.81
XX DATA06 SYS_LOB0000061891C00 LOB 1,999,104 2.76
-------------------------------------------------------------


Top 5 Physical Reads per Segment for DB: db04C Instance: db04c02 Snaps: 2270 -
-> End Segment Physical Reads Threshold: 1000

Subobject Obj. Physical
Owner Tablespace Object Name Name Type Reads %Total
---------- ---------- -------------------- ---------- ----- ------------ -------
XX DATA TABLE_X_E2E_DATA TABLE 7,469,916 45.58
XX DATA TABLE_SLM_LOG TABLE 5,788,602 35.32
XX DATA18 TABLE_RQST_INST TABLE 1,821,308 11.11
XX DATA07 TABLE_CONTRACT TABLE 824,884 5.03
XX INDEX18 SYS_C0010450 INDEX 345,099 2.11
-------------------------------------------------------------
Top 5 Buf. Busy Waits per Segment for DB: db04C Instance: db04c02 Snaps: 2270
-> End Segment Buffer Busy Waits Threshold: 100
Buffer
Subobject Obj. Busy
Owner Tablespace Object Name Name Type Waits %Total
---------- ---------- -------------------- ---------- ----- ------------ -------
XX DATA TABLE_X_E2E_DATA TABLE 1,825,204 61.74
XX DATA TABLE_SLM_LOG TABLE 644,052 21.79
XX DATA18 TABLE_RQST_INST TABLE 399,604 13.52
XX INDEX18 SYS_C0010450 INDEX 72,952 2.47
XX DATA TABLE_SLM_SUMMARY TABLE 4,093 .14
-------------------------------------------------------------
Top 5 Row Lock Waits per Segment for DB: db04C Instance: db04c02 Snaps: 2270 -
-> End Segment Row Lock Waits Threshold: 100

Row
Subobject Obj. Lock
Owner Tablespace Object Name Name Type Waits %Total
---------- ---------- -------------------- ---------- ----- ------------ -------
XX DATA TABLE_CONFIG_ITM TABLE 82 36.12
XX DATA ADP_TBL_OID TABLE 13 5.73
XX INDEX01 IND_ACT_CODE INDEX 7 3.08
XX INDEX15 SYS_C0010341 INDEX 7 3.08
-------------------------------------------------------------

SGA Memory Summary for DB: db04C Instance: db04c02 Snaps: 2270 -2271

SGA regions Size in Bytes
------------------------------ ----------------
Database Buffers 939,524,096
Fixed Size 730,424
Redo Buffers 2,371,584
Variable Size 1,577,058,304
----------------
sum 2,519,684,408
-------------------------------------------------------------


End of Report

HI Tom,

Could you plase help me in analyzing the above staspack report mentioned under title "Statspack Analysis..."

Thanks a lot.

t

d. "Keep Buffer Pool" is not being utilised? as "table scans (short tables)" is too high?

Hi Tom,
Many thanks for enlighting me.

>>e. Too bad "Execute to Parse ratio"?
that I would agree with, your java programmers need to look at their code and ask themselves "why are we doing this so inefficiently". They do not need to parse every single time they execute - they only need to parse ONCE and then bind/execute over and over and over.

Our java programmers says they are using bind variables. So, the statement should not get parsed again and again.

parse stats :
Load Profile
~~~~~~~~~~~~ Per Second Per Transaction
--------------- ---------------
User calls: 1,906.09 50.03
Parses: 754.47 19.80
Hard parses: 0.01 0.00

>>SQL ordered by Parse Calls for DB: db04C Instance: db04c02 Snaps: 2270 -2271
-> End Parse Calls Threshold: 1000

% Total
Parse Calls Executions Parses Hash Value
------------ ------------ -------- ----------
143,944 143,943 12.23 982153273
Module: java@hosta02 (TNS V1-V3)
SELECT T101.attribute_value,T101.attribute_datatype,T101.objid F
ROM table_site_part T100,table_fa_site_part T101 WHERE ( T101.at
tribute_name = :P1) AND ( T100.objid = :P2)AND (T100.objid=T10
1.fa_site_part2site_part)

So what is wrong with above query which is making it to for parsing almost every time.

Many Many Thanks Tom, for your prompt & perfect reply. As always!

How to check the complete sqltext for sqls which are partially shown ( limit on char) in the statspack report?

I have digged it using hash value shown in statspack report but no sql exist there.

Cheers.

Hi tom,
I appriciate the response given by you in previous thread but it doesnot explain much about "os thread startup" wait event.

On few of our AIX servers with Oracle 10gR2 we are experencing that new connection to Db hangs as long as disk activity are high on the server, like when we simply try to copy a big file (>20gb)to and from the server it hangs new connection to one of the DB and a delay in connection is noticed on another DB, but at the same time existing connection to both the DB face NO performace problem while executing any transaction or selection.

AWR reoport during that time period shows high waits for "os thread startup". Can you explain what this wait event means and what could be the possible cause of hang situation during new connection
Top 5 Wait Events
-----------------
os thread startup 269.0%
latch free 109.7%
Data file init write 59.4%
control file parallel write 29.7%
CPU time 2.1%

Any response on this is highly appreciated. Let me know if the information given is not sufficent enough.

Regards
Monica

Some more info on the previous review

Top 5 Timed Events Avg %Total
~~~~~~~~~~~~~~~~~~ wait Call
Event Waits Time (s) (ms) Time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
db file parallel write 395 57 144 152.0 System I/O
control file parallel write 559 38 69 102.7 System I/O
os thread startup 28 21 741 55.5 Concurrenc
LGWR wait for redo copy 1,569 15 10 40.6 Other
Streams AQ: qmn coordinator wa 1 5 4883 13.1 Other
-------------------------------------------------------------



Event Waits -outs Time (s) (ms) /txn
---------------------------- -------------- ------ ----------- ------- ---------
db file parallel write 395 .0 57 144 2.3
control file parallel write 559 .0 38 69 3.2
os thread startup 28 71.4 21 741 0.2
LGWR wait for redo copy 1,569 98.3 15 10 9.0
Streams AQ: qmn coordinator 1 100.0 5 4883 0.0
log file parallel write 302 .0 1 3 1.7
latch free 2 .0 0 67 0.0
control file sequential read 682 .0 0 0 3.9
latch: redo writing 1 .0 0 60 0.0
log file sync 42 .0 0 1 0.2
latch: redo allocation 23 .0 0 1 0.1
latch: messages 1 .0 0 11 0.0
db file sequential read 7 .0 0 1 0.0
latch: undo global data 1 .0 0 5 0.0
latch: library cache 1 .0 0 3 0.0
latch: shared pool 4 .0 0 0 0.0
latch: enqueue hash chains 1 .0 0 1 0.0
SQL*Net message to client 138 .0 0 0 0.8
SQL*Net break/reset to clien 2 .0 0 0 0.0
Streams AQ: qmn slave idle w 87 .0 2,388 27451 0.5
Streams AQ: waiting for time 40 60.0 1,771 44274 0.2
Streams AQ: qmn coordinator 125 52.0 1,658 13268 0.7
jobq slave wait 567 96.3 1,653 2916 3.3
virtual circuit status 57 100.0 1,652 28982 0.3
SQL*Net message from client 138 .0 1,287 9326 0.8
-------------------------------------------------------------

Background Wait Events DB/Inst: PRODTEST/prodtest Snaps: 958-959
-> ordered by wait time desc, waits desc (idle events last)

Avg
%Time Total Wait wait Waits
Event Waits -outs Time (s) (ms) /txn
---------------------------- -------------- ------ ----------- ------- ---------
db file parallel write 395 .0 57 144 2.3
control file parallel write 559 .0 38 69 3.2
os thread startup 28 71.4 21 741 0.2
events in waitclass Other 1,595 96.8 20 13 9.2
log file parallel write 301 .0 1 3 1.7
control file sequential read 28 .0 0 2 0.2
latch: redo writing 1 .0 0 60 0.0
rdbms ipc message 6,254 96.3 14,998 2398 35.9
Streams AQ: qmn slave idle w 87 .0 2,388 27451 0.5
Streams AQ: waiting for time 40 60.0 1,771 44274 0.2
pmon timer 572 100.0 1,675 2928 3.3
Streams AQ: qmn coordinator 125 52.0 1,658 13268 0.7
smon timer 5 100.0 1,225 244959 0.0
-------------------------------------------------------------

- I'm trying to connect to Oracle DB via SQLPLUS thru telnet (by passing the listener) also thru TNS names. 
With both the ways it is hanging.
SQL> conn system/prod123
*HANGING*


- It is quite a big system with 100Gb RAM and with good enough Swap space.

- file listing is working fine with no delay is response under Such situation.  

$:>ls
arcinfo           etc               proc              tmp
audit             home              sbin              u
bin               lib               smit.log          unix
core              lost+found        smit.script       usr
data              lpp               smit.transaction  var
data1             mnt               softwares
dev               opt               tftpboot
$:>

Some more information

It has been noticed that during such sitaution our Root hard disk get busy and stay above 50% value as shown below.
*******************************
Disk    Busy%     KBPS     TPS KB-Read KB-Writ
hdisk0  100.0    13.9K    2.4K    7.5K    6.4K
hdisk1   12.5    21.5K  144.0    19.5K    2.0K

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

The moment it drops to normal we are able to connect. 

Please suggest further

The following is from the AWRs .
In the first example , the difference between these snapshots are around 8 minutes ; but the AWR shows DB time as 40.73 mins and elasped time is 6.41 mins.
Please explain .

Example 1


Begin Snap: 2606 05-May-09 17:03:37 98 36.0
End Snap: 2607 05-May-09 17:10:01 98 39.4

Elapsed: 6.41 (mins)
DB Time: 40.73 (mins)


Example 2:

Snap Id Snap Time Sessions Cursors/Session
Begin Snap: 2629 06-May-09 09:34:36 101 8.3
End Snap: 2630 06-May-09 09:47:42 110 39.2

Elapsed: 13.10 (mins)
DB Time: 231.04 (mins)

Hi Tom,

Could you help in reading the share pool advice view. What are the columns we need to compare for considering for increasing in share pool size?
Est Est
Time Parse
Pool Size Est Est LC Saved Saved Est
Size(M) Factor LC(M) Mem. Obj. (sec) Factor Object Hits
---------- ---------- ---------- ---------- ---------- ---------- ----------------
3200 .5814 676 24447 134435772 .9713 3,835,851,647
3776 .686 1172 37529 136329354 .985 3,859,828,992
4352 .7907 1751 52553 136867685 .9889 3,862,303,623
4928 .8953 2324 74090 137770415 .9954 3,863,257,778
5504 1 2894 90751 138408244 1 3,863,705,843
6080 1.1047 3464 109142 138571521 1.0012 3,863,985,663
6656 1.2093 4039 133307 138771172 1.0026 3,864,239,606
7232 1.314 4610 156137 138891737 1.0035 3,864,463,978
7808 1.4186 5185 181478 138958625 1.004 3,864,641,055
8384 1.5233 5760 207151 139018669 1.0044 3,864,808,442
8960 1.6279 6337 235530 139084187 1.0049 3,864,956,556
9536 1.7326 6913 266053 139122803 1.0052 3,865,089,265
10112 1.8372 7497 297764 139168567 1.0055 3,865,200,669
10688 1.9419 8067 323693 139204227 1.0058 3,865,309,013
11264 2.0465 8642 351416 139242252 1.006 3,865,413,122

Hi,

Could one of you suggest me should I go for increaseing the share pool, if so why and how much?


Shared sp size Est LC Est LC Est LC Time Est LC time Est LC Load Est Lc Load Est Mem Obj
Pool Factr Size (M)Mem Obj Saved (s) Saved Factr Time (s) Time Factr Hits
Size(M)
976 0.19 645 13,436 77,987,167 0.94 5,973,438 8.18 4,056,869,761
1,504 0.29 1,076 17,824 79,895,033 0.96 4,065,572 5.57 4,114,914,600
2,032 0.39 1,595 26,954 80,598,957 0.97 3,361,648 4.60 4,120,681,568
2,560 0.49 2,104 32,592 81,082,445 0.97 2,878,160 3.94 4,122,667,679
3,088 0.59 2,631 44,535 81,430,942 0.98 2,529,663 3.46 4,123,518,341
3,616 0.70 3,160 53,350 81,642,439 0.98 2,318,166 3.17 4,123,958,677
4,144 0.80 3,691 62,488 82,005,113 0.99 1,955,492 2.68 4,124,270,138
4,672 0.90 4,219 74,611 82,689,574 0.99 1,271,031 1.74 4,124,555,047
5,200 1.00 4,741 85,180 83,230,233 1.00 730,372 1.00 4,124,800,530
5,728 1.10 5,268 94,239 83,472,403 1.00 488,202 0.67 4,124,990,932
6,256 1.20 5,795 102,863 83,607,179 1.00 353,426 0.48 4,125,155,118
6,784 1.30 6,317 114,432 83,730,384 1.01 230,221 0.32 4,125,306,001
7,312 1.41 6,845 133,734 83,872,340 1.01 88,265 0.12 4,125,445,481
7,840 1.51 7,385 154,328 83,981,950 1.01 1 0.00 4,125,575,630
8,368 1.61 7,912 171,818 84,038,373 1.01 1 0.00 4,125,697,466
8,896 1.71 8,433 190,334 84,107,795 1.01 1 0.00 4,125,809,379
9,424 1.81 8,961 204,465 84,147,762 1.01 1 0.00 4,125,914,745
9,952 1.91 9,494 225,249 84,187,361 1.01 1 0.00 4,126,013,106
10,480 2.02 10,178 258,033 84,218,105 1.01 1 0.00 4,126,091,431

Hi,

What are the value you are comparing.

Please explain me with an example.

Thanks in advance!

Hi,

My database base as performance issue.

We are thinking to increasing the cacahe size. Below is my buffer cache advisory value. Could you help me in understanding this, will inceasing the db buffer helps me.


P Size for Size Buffers Est Phys Estimated
Est (M) Factor for Read Physical Reads
Estimate Factor
D 3,072 0.10 368,448 7.92 91,430,128,087
D 6,144 0.20 736,896 5.69 65,710,257,507
D 9,216 0.30 1,105,344 3.96 45,746,700,028
D 12,288 0.40 1,473,792 2.60 30,052,073,812
D 15,360 0.50 1,842,240 1.96 22,608,624,882
D 18,432 0.60 2,210,688 1.60 18,482,350,959
D 21,504 0.70 2,579,136 1.37 15,782,246,291
D 24,576 0.80 2,947,584 1.21 13,926,024,638
D 27,648 0.90 3,316,032 1.09 12,588,309,843
D 30,720 1.00 3,684,480 1.00 11,538,454,474
D 33,792 1.10 4,052,928 0.93 10,693,974,320
D 36,864 1.20 4,421,376 0.87 9,991,602,544
D 39,936 1.30 4,789,824 0.81 9,390,853,471
D 43,008 1.40 5,158,272 0.77 8,864,683,205
D 46,080 1.50 5,526,720 0.73 8,398,528,906
D 49,152 1.60 5,895,168 0.69 7,980,572,824
D 52,224 1.70 6,263,616 0.66 7,604,964,472
D 55,296 1.80 6,632,064 0.63 7,271,144,198
D 58,368 1.90 7,000,512 0.60 6,953,278,135
D 61,440 2.00 7,368,960 0.58 6,650,483,256

D    30,720    1.00    3,684,480    1.00    11,538,454,474

Hi,

Thanks for making me more understanding. I agree will what you told me.

Here is sample of my AWR report. Please suggest me the area which I should consider.



WORKLOAD REPOSITORY report for

DB Name DB Id Instance Inst Num Release RAC Host
------------ ----------- ------------ -------- ----------- --- ------------
inst1 51107971 inst1 1 10.2.0.3.0 YES Node1

Snap Id Snap Time Sessions Curs/Sess
--------- ------------------- -------- ---------
Begin Snap: 13940 12-Jun-09 09:00:31 1,356 5.9
End Snap: 13942 12-Jun-09 11:00:19 1,379 6.0
Elapsed: 119.81 (mins)
DB Time: 3,476.41 (mins)

Cache Sizes
~~~~~~~~~~~ Begin End
---------- ----------
Buffer Cache: 30,720M 30,720M Std Block Size: 8K
Shared Pool Size: 5,200M 5,200M Log Buffer: 30,672K

Load Profile
~~~~~~~~~~~~ Per Second Per Transaction
--------------- ---------------
Redo size: 1,387,324.85 8,153.17
Logical reads: 496,500.28 2,917.88
Block changes: 7,716.48 45.35
Physical reads: 5,219.26 30.67
Physical writes: 362.19 2.13
User calls: 8,564.61 50.33
Parses: 3,317.79 19.50
Hard parses: 18.16 0.11
Sorts: 508.98 2.99
Logons: 0.15 0.00
Executes: 5,566.75 32.72
Transactions: 170.16

% Blocks changed per Read: 1.55 Recursive Call %: 14.62
Rollback per transaction %: 0.74 Rows per Sort: 66.49

Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Buffer Nowait %: 99.70 Redo NoWait %: 100.00
Buffer Hit %: 98.95 In-memory Sort %: 100.00
Library Hit %: 99.24 Soft Parse %: 99.45
Execute to Parse %: 40.40 Latch Hit %: 99.75
Parse CPU to Parse Elapsd %: 28.83 % Non-Parse CPU: 99.47

Shared Pool Statistics Begin End
------ ------
Memory Usage %: 84.31 85.67
% SQL with executions>1: 78.68 56.19
% Memory for SQL w/exec>1: 80.77 75.22

Top 5 Timed Events Avg %Total
~~~~~~~~~~~~~~~~~~ wait Call
Event Waits Time (s) (ms) Time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
db file sequential read 37,137,954 143,521 4 68.8 User I/O
CPU time 40,853 19.6
read by other session 9,374,632 12,456 1 6.0 User I/O
enq: TX - row lock contention 20,766 9,808 472 4.7 Applicatio
gc buffer busy 1,495,447 2,456 2 1.2 Cluster
-------------------------------------------------------------

RAC Statistics DB/Inst: inst1/inst11 Snaps: 13940-13942

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


Global Cache Load Profile
~~~~~~~~~~~~~~~~~~~~~~~~~ Per Second Per Transaction
--------------- ---------------
Global Cache blocks received: 438.78 2.58
Global Cache blocks served: 22.42 0.13
GCS/GES messages received: 269.45 1.58
GCS/GES messages sent: 1,633.63 9.60
DBWR Fusion writes: 0.22 0.00
Estd Interconnect traffic (KB) 4,061.27


Global Cache Efficiency Percentages (Target local+remote 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Buffer access - local cache %: 98.86
Buffer access - remote cache %: 0.09
Buffer access - disk %: 1.05


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

Avg global cache cr block receive time (ms): 0.7
Avg global cache current block receive time (ms): 0.5


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

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

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

% of direct sent messages: 49.00
% of indirect sent messages: 39.81
% of flow controlled messages: 11.20
-------------------------------------------------------------

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

Statistic Name Time (s) % of DB Time
------------------------------------------ ------------------ ------------
sql execute elapsed time 205,138.4 98.3
DB CPU 40,853.1 19.6
parse time elapsed 2,898.3 1.4
hard parse elapsed time 2,401.8 1.2
PL/SQL execution elapsed time 107.1 .1
sequence load elapsed time 8.2 .0
repeated bind elapsed time 6.8 .0
PL/SQL compilation elapsed time 5.9 .0
connection management call elapsed time 3.7 .0
hard parse (sharing criteria) elapsed time 2.2 .0
hard parse (bind mismatch) elapsed time 2.1 .0
failed parse elapsed time 0.0 .0
DB time 208,584.3 N/A
background elapsed time 2,324.5 N/A
background cpu time 891.2 N/A
-------------------------------------------------------------

Wait Class DB/Inst: inst1/inst11 Snaps: 13940-13942
-> s - second
-> cs - centisecond - 100th of a second
-> ms - millisecond - 1000th of a second
-> us - microsecond - 1000000th of a second
-> ordered by wait time desc, waits desc

Avg
%Time Total Wait wait Waits
Wait Class Waits -outs Time (s) (ms) /txn
-------------------- ---------------- ------ ---------------- ------- ---------
User I/O 46,587,857 .0 156,091 3 38.1
Application 27,681 71.9 9,809 354 0.0
Cluster 7,296,437 .0 4,453 1 6.0
Commit 1,228,658 .0 1,309 1 1.0
System I/O 2,087,467 .0 1,113 1 1.7
Network 71,091,652 .0 481 0 58.1
Other 2,295,636 56.2 373 0 1.9
Concurrency 2,349,247 .0 157 0 1.9
Configuration 2,342 88.6 3 1 0.0
-------------------------------------------------------------

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

Avg
%Time Total Wait wait Waits
Event Waits -outs Time (s) (ms) /txn
---------------------------- -------------- ------ ----------- ------- ---------
db file sequential read 37,137,954 .0 143,521 4 30.4
read by other session 9,374,632 .0 12,456 1 7.7
enq: TX - row lock contentio 20,766 95.9 9,808 472 0.0
gc buffer busy 1,495,447 .0 2,456 2 1.2
log file sync 1,228,658 .0 1,309 1 1.0
gc current block 2-way 2,592,154 .0 1,033 0 2.1
gc cr grant 2-way 2,291,704 .0 697 0 1.9
log file parallel write 1,192,369 .0 586 0 1.0
db file parallel write 796,433 .0 405 1 0.7
SQL*Net more data from clien 4,387,048 .0 356 0 3.6
wait for scn ack 815,865 .0 165 0 0.7
gc current grant 2-way 478,743 .0 142 0 0.4
gcs drm freeze in enter serv 324 55.9 127 391 0.0
db file scattered read 51,554 .0 110 2 0.0
SQL*Net more data to client 5,465,626 .0 84 0 4.5
latch: cache buffers chains 2,225,972 .0 78 0 1.8
gc cr multi block request 414,802 .0 61 0 0.3
gc remaster 179 1.7 57 320 0.0
Log archive I/O 12,146 .0 46 4 0.0
log file sequential read 10,196 .0 45 4 0.0
SQL*Net message to client 61,238,646 .0 42 0 50.1
enq: TX - index contention 3,850 .1 29 8 0.0
control file sequential read 72,005 .0 28 0 0.1
Streams AQ: qmn coordinator 4 100.0 23 5790 0.0
library cache lock 53,804 .0 22 0 0.0
row cache lock 48,685 .0 17 0 0.0
reliable message 546 .7 13 24 0.0
CGS wait for IPC msg 1,125,241 100.0 6 0 0.9
ges LMD suspend for testing 38 86.8 6 147 0.0
enq: WF - contention 23 43.5 6 243 0.0
enq: US - contention 16,762 .0 5 0 0.0
kjbdrmcvtq lmon drm quiesce: 53 50.9 5 98 0.0
latch: shared pool 4,061 .0 5 1 0.0
latch: object queue header o 19,179 .0 4 0 0.0
control file parallel write 4,278 .0 4 1 0.0
gc current grant busy 8,427 .0 4 0 0.0
direct path read 16,630 .0 4 0 0.0
cursor: pin S wait on X 325 99.1 3 10 0.0
log file switch completion 127 .0 3 22 0.0
enq: TT - contention 6,087 .0 2 0 0.0
gcs log flush sync 604 15.6 2 3 0.0
PX Deq: reap credit 153,629 73.6 2 0 0.1
enq: FB - contention 3,467 .0 1 0 0.0
gc current multi block reque 12,362 .0 1 0 0.0
SQL*Net break/reset to clien 6,870 .0 1 0 0.0
buffer busy waits 10,668 .0 1 0 0.0
ksxr poll remote instances 104,805 42.7 1 0 0.1
latch free 3,965 .0 1 0 0.0
latch: gcs resource hash 5,143 .0 1 0 0.0
PX Deq Credit: send blkd 5,213 1.4 1 0 0.0
latch: library cache 419 .0 1 2 0.0
gc cr disk read 1,266 .0 1 0 0.0
LGWR wait for redo copy 20,100 .0 1 0 0.0
library cache pin 1,421 .0 1 0 0.0
ges global resource director 53 98.1 1 10 0.0
gc cr block 2-way 1,230 .0 1 0 0.0
DFS lock handle 1,210 .0 0 0 0.0
wait list latch free 41 .0 0 10 0.0
gc cr block busy 24 .0 0 15 0.0
os thread startup 13 .0 0 27 0.0
Wait Events DB/Inst: inst1/inst11 Snaps: 13940-13942
-> s - second
-> cs - centisecond - 100th of a second
-> ms - millisecond - 1000th of a second
-> us - microsecond - 1000000th of a second
-> ordered by wait time desc, waits desc (idle events last)

Avg
%Time Total Wait wait Waits
Event Waits -outs Time (s) (ms) /txn
---------------------------- -------------- ------ ----------- ------- ---------
rdbms ipc reply 1,243 .0 0 0 0.0
enq: TO - contention 937 .0 0 0 0.0
latch: cache buffers lru cha 2,488 .0 0 0 0.0
direct path write 7,034 .0 0 0 0.0
db file parallel read 15 .0 0 13 0.0
gc cr grant congested 50 .0 0 3 0.0
IPC send completion sync 325 100.0 0 0 0.0
enq: CF - contention 297 .0 0 0 0.0
kksfbc child completion 2 100.0 0 49 0.0
enq: RO - fast object reuse 33 .0 0 3 0.0
gc current grant congested 15 .0 0 5 0.0
global enqueue expand wait 10 80.0 0 8 0.0
enq: HW - contention 80 .0 0 1 0.0
enq: PS - contention 164 .0 0 0 0.0
gc current block congested 20 .0 0 3 0.0
latch: KCL gc element parent 252 .0 0 0 0.0
PX qref latch 6,434 86.2 0 0 0.0
local write wait 24 .0 0 2 0.0
enq: SQ - contention 51 .0 0 1 0.0
library cache load lock 7 .0 0 4 0.0
latch: ges resource hash lis 427 .0 0 0 0.0
enq: TA - contention 56 .0 0 0 0.0
gc current block busy 9 .0 0 2 0.0
latch: session allocation 45 .0 0 0 0.0
PX Deq: Signal ACK 61 26.2 0 0 0.0
log file single write 40 .0 0 0 0.0
ges inquiry response 16 .0 0 1 0.0
enq: TX - allocate ITL entry 4 .0 0 1 0.0
enq: TM - contention 10 .0 0 1 0.0
db file single write 14 .0 0 0 0.0
undo segment extension 2,076 100.0 0 0 0.0
buffer deadlock 406 99.8 0 0 0.0
latch: redo allocation 29 .0 0 0 0.0
latch: library cache lock 8 .0 0 0 0.0
KJC: Wait for msg sends to c 17 .0 0 0 0.0
enq: WL - contention 5 .0 0 0 0.0
enq: DR - contention 4 .0 0 0 0.0
latch: row cache objects 12 .0 0 0 0.0
enq: AF - task serialization 2 .0 0 0 0.0
latch: undo global data 9 .0 0 0 0.0
enq: PW - flush prewarm buff 2 .0 0 0 0.0
latch: messages 13 .0 0 0 0.0
latch: library cache pin 2 .0 0 0 0.0
SQL*Net more data from dblin 24 .0 0 0 0.0
gc current split 1 .0 0 0 0.0
gc quiesce wait 4 .0 0 0 0.0
latch: cache buffer handles 6 .0 0 0 0.0
ges2 LMON to wake up LMD - m 3 .0 0 0 0.0
latch: redo writing 4 .0 0 0 0.0
SQL*Net message to dblink 308 .0 0 0 0.0
cursor: pin S 31 .0 0 0 0.0
latch: enqueue hash chains 1 .0 0 0 0.0
latch: checkpoint queue latc 1 .0 0 0 0.0
SQL*Net message from client 61,238,606 .0 6,259,882 102 50.1
gcs remote message 4,401,498 71.9 55,842 13 3.6
PX Idle Wait 5,795 97.1 13,913 2401 0.0
Streams AQ: qmn slave idle w 270 1.5 7,220 26741 0.0
Streams AQ: waiting for mess 1,462 99.7 7,012 4796 0.0
ges remote message 251,746 76.1 7,005 28 0.2
Streams AQ: qmn coordinator 511 49.5 6,962 13625 0.0
Wait Events DB/Inst: inst1/inst11 Snaps: 13940-13942
-> s - second
-> cs - centisecond - 100th of a second
-> ms - millisecond - 1000th of a second
-> us - microsecond - 1000000th of a second
-> ordered by wait time desc, waits desc (idle events last)

Avg
%Time Total Wait wait Waits
Event Waits -outs Time (s) (ms) /txn
---------------------------- -------------- ------ ----------- ------- ---------
DIAG idle wait 35,484 .0 6,934 195 0.0
Streams AQ: waiting for time 44 90.9 6,592 149824 0.0
jobq slave wait 102 99.0 298 2920 0.0
PX Deq: Execution Msg 704 32.1 114 162 0.0
PX Deq: Execute Reply 56,886 27.6 9 0 0.0
SQL*Net message from dblink 308 .0 1 4 0.0
PX Deq Credit: need buffer 12,005 .0 1 0 0.0
single-task message 6 .0 0 36 0.0
PX Deq: Parse Reply 69 40.6 0 1 0.0
PX Deq: Join ACK 71 39.4 0 1 0.0
PX Deq: Msg Fragment 263 39.5 0 0 0.0
Streams AQ: RAC qmn coordina 511 100.0 0 0 0.0
class slave wait 8 .0 0 0 0.0
-------------------------------------------------------------

Background Wait Events DB/Inst: inst1/inst11 Snaps: 13940-13942
-> ordered by wait time desc, waits desc (idle events last)

Avg
%Time Total Wait wait Waits
Event Waits -outs Time (s) (ms) /txn
---------------------------- -------------- ------ ----------- ------- ---------
log file parallel write 1,192,379 .0 586 0 1.0
db file parallel write 796,433 .0 405 1 0.7
events in waitclass Other 2,105,382 55.6 235 0 1.7
Log archive I/O 12,146 .0 46 4 0.0
log file sequential read 10,196 .0 45 4 0.0
db file sequential read 3,666 .0 20 5 0.0
control file sequential read 19,722 .0 13 1 0.0
row cache lock 7,266 .0 4 1 0.0
control file parallel write 4,278 .0 4 1 0.0
direct path read 16,198 .0 3 0 0.0
gc current block 2-way 6,926 .1 3 0 0.0
library cache lock 1,663 .0 1 0 0.0
os thread startup 13 .0 0 27 0.0
gc current grant 2-way 939 .0 0 0 0.0
direct path write 6,860 .0 0 0 0.0
gc cr multi block request 857 .0 0 0 0.0
gc cr block 2-way 251 .0 0 0 0.0
gc cr grant 2-way 197 .0 0 0 0.0
latch: cache buffers chains 106 .0 0 0 0.0
db file scattered read 1 .0 0 17 0.0
library cache pin 37 .0 0 0 0.0
latch: shared pool 34 .0 0 0 0.0
log file single write 40 .0 0 0 0.0
gc current grant busy 43 .0 0 0 0.0
enq: RO - fast object reuse 17 .0 0 0 0.0
db file single write 14 .0 0 0 0.0
enq: TM - contention 8 .0 0 1 0.0
gc current multi block reque 41 .0 0 0 0.0
buffer busy waits 16 .0 0 0 0.0
gc cr block busy 1 .0 0 3 0.0
enq: HW - contention 9 .0 0 0 0.0
latch: row cache objects 9 .0 0 0 0.0
latch: redo writing 4 .0 0 0 0.0
latch: library cache 1 .0 0 0 0.0
rdbms ipc message 2,476,868 4.8 109,918 44 2.0
gcs remote message 4,401,521 71.9 55,842 13 3.6
pmon timer 2,947 99.1 7,012 2379 0.0
ges remote message 251,756 76.1 7,005 28 0.2
smon timer 3,889 37.6 7,002 1801 0.0
Streams AQ: qmn coordinator 511 49.5 6,962 13625 0.0
DIAG idle wait 35,482 .0 6,932 195 0.0
Streams AQ: waiting for time 44 90.9 6,592 149824 0.0
PX Deq: Join ACK 60 40.0 0 1 0.0
PX Deq: Parse Reply 57 42.1 0 0 0.0
PX Deq: Execute Reply 44 29.5 0 0 0.0
Streams AQ: RAC qmn coordina 511 100.0 0 0 0.0
-------------------------------------------------------------

Operating System Statistics DB/Inst: inst1/inst11 Snaps: 13940-13942

Statistic Total
-------------------------------- --------------------
NUM_LCPUS 0
NUM_VCPUS 0
AVG_BUSY_TIME 153,143
AVG_IDLE_TIME 564,890
AVG_IOWAIT_TIME 220,947
AVG_SYS_TIME 29,483
AVG_USER_TIME 123,423
BUSY_TIME 4,908,054
IDLE_TIME 18,083,594
IOWAIT_TIME 7,077,713
SYS_TIME 950,774
USER_TIME 3,957,280
LOAD 0
OS_CPU_WAIT_TIME 5,025,200
RSRC_MGR_CPU_WAIT_TIME 0
PHYSICAL_MEMORY_BYTES 65,497,726,976
NUM_CPUS 32
NUM_CPU_CORES 16
-------------------------------------------------------------

Tom,

Thanks for your suggestion to run ADDM report, it gave some usefull information.

I still need to get more information about this report, here is AWR report when we had performance issuse.

Could you please explain/suggest me on the following

1. How is the TOP 5 Timed events looks, what is "log file sync" and "db file parallel write" is this something I should think off?
2. How is my Load Profile looks?
3. In wait Events, please look at the following waits which as more than 90% time outs.
a) cursor: pin S wait on X
b) buffer deadlock
C) CGS wait for IPC msg

Top 5 Timed Events

Event Waits Time(s) Avg Wait(ms) % Total Wait Class
Call Time
db file sequential read 3,010,920 86,228 29 57.4 User I/O
log file sync 262,361 24,701 94 16.4 Commit
read by other session 932,655 20,400 22 13.6 User I/O
db file parallel write 311,771 13,577 44 9.0 System I/O
gc buffer busy 490,355 6,677 14 4.4 Cluster



Load Profile
Per Second Per Transaction
Redo size: 583,101.24 8,145.51
Logical reads: 184,894.79 2,582.85
Block changes: 3,338.74 46.64
Physical reads: 1,195.27 16.70
Physical writes: 168.45 2.35
User calls: 3,457.06 48.29
Parses: 1,287.04 17.98
Hard parses: 1.75 0.02
Sorts: 241.27 3.37
Logons: 0.20 0.00
Executes: 2,256.21 31.52
Transactions: 71.59



Wait Events
" 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)

Event Waits %Time Total Wait Avgwait Waits /txn
-outs Time (s) (ms)
db file sequential read 3,010,920 0.00 86,228 29 11.56
log file sync 262,361 0.15 24,701 94 1.01
read by other session 932,655 0.02 20,400 22 3.58
db file parallel write 311,771 0.00 13,577 44 1.20
gc buffer busy 490,355 0.03 6,677 14 1.88
db file scattered read 139,907 0.00 4,097 29 0.54
log file parallel write 72,768 0.00 3,437 47 0.28
log file switch completion 118 20.34 54 454 0.00
enq: TX - allocate ITL entry 29 65.52 10 342 0.00
cursor: pin S wait on X 325 99.38 3 10 0.00
CGS wait for IPC msg 475,910 99.99 2 0 1.83
buffer deadlock 211 98.10 0 0 0.00

In the AWR comparison report , under the section "Global Cache and Enqueue Services - Messaging Statistics " ,
I see a negative value in the "Avg message sent queue time (ms)" . Why AWR reports a negative value ?


Avg message sent queue time (ms): -4,409.01 256.56 -105.82
Avg message sent queue time on ksxp (ms): 0.25 0.25 0.00
Avg message received queue time (ms): 0.01 0.01 0.00
Avg GCS message process time (ms): 0.04 0.04 0.00
Avg GES message process time (ms): 0.02 0.02 0.00

We are 10g R2 on 2 node RAC in linux.

We ran two tests of the similar app on the same server different times ( with no /little changes to the underlying data )
The test 2 had performance degradation of 12 % in terms of elasped time / over all response .

When I looked at the AWR , I see the following are different ( esp dc_histogram_data , dc_histogram_defs) .
We have the daily stats job enabled

Please advise .

Why would it be so different ?
what is the explanaton of application wait time ( Is it the time waiting for foreground process ) ?


Test 1


Dictionary Cache Stats (RAC)

dc_awr_control 2 2 0
dc_histogram_defs 27 0 0
dc_object_ids 96 0 0
dc_objects 75 0 0
dc_segments 180 39 0
dc_sequences 1,354 359 0
dc_tablespace_quotas 158 42 0
outstanding_alerts 132 54 0

Test 2

Dictionary Cache Stats (RAC)

dc_awr_control 5 0 1
dc_global_oids 18 0 18
dc_histogram_defs 4,459 0 3,896
dc_object_ids 688 0 958
dc_objects 408 0 522
dc_profiles 2 0 2
dc_segments 22,159 30 22,085
dc_sequences 1,109 345 1
dc_tablespace_quotas 164 41 0
dc_tablespaces 8 0 10
dc_usernames 37 0 5
dc_users 15 0 15
outstanding_alerts 137 54 1


Test 1

Dictionary Cache Stats


dc_awr_control 32 6.25 0 0 1
dc_database_links 53 0.00 0 0 1
dc_global_oids 239,684 0.00 0 0 70
dc_histogram_data 274 1.09 0 0 12,848
dc_histogram_defs 133 20.30 0 0 7,674
dc_object_ids 250,846 0.04 0 0 1,946
dc_objects 402,027 0.02 0 0 1,642
dc_profiles 65 0.00 0 0 2
dc_rollback_segments 12,818 0.00 0 0 216
dc_segments 2,203 3.18 0 90 13,265
dc_sequences 677 53.32 0 677 5
dc_tablespace_quotas 79 51.90 0 79 1
dc_tablespaces 2,216,077 0.00 0 0 11
dc_usernames 1,180 0.00 0 0 45
dc_users 1,740,338 0.00 0 0 73
outstanding_alerts 71 76.06 0 0 22



Test 2


dc_awr_control 36 2.78 0 2 1
dc_database_links 53 0.00 0 0 1
dc_global_oids 633,793 0.00 0 0 31
dc_histogram_data 143,604 6.29 0 0 9,959
dc_histogram_defs 67,054 6.65 0 0 4,164
dc_object_grants 19 5.26 0 0 90
dc_object_ids 673,084 0.10 0 0 838
dc_objects 447,115 0.09 0 4 804
dc_profiles 36 5.56 0 0 2
dc_rollback_segments 18,813 0.00 0 0 304
dc_segments 27,417 80.44 0 86 1,726
dc_sequences 555 61.98 0 555 4
dc_tablespace_quotas 82 51.22 0 82 3
dc_tablespaces 2,462,926 0.00 0 0 9
dc_usernames 807 4.58 0 0 41
dc_users 2,224,141 0.00 0 0 63
outstanding_alerts 72 76.39 0 2 3


Test 1

application wait time 806 0.45 0.00


Test 2

application wait time 2,030 1.13 0.01

in a RAC load test..I see lot of 54% wait as gc buffer busy , i can see the sql also which is causing this and this is a simple select statement beging executed too many times.
as a concept question - why this select would cause the gc buffer busy wait - is it due to

1. the table which this select query is using,might be getting updated by other nodes..
or
2.due to hot block issue.

in both the cases..what could be a potential solution.
database version 10.2.0.4.

Thanks

Tom ,

Are you saying the metrics related to dc_* are meaningless.

Tom,

Thanks for the help in making Oracle easy to every user.


Giving below excerpts from Statspack.



Oracle 9.2.0.8 (RAC)

Snap Id Snap Time Sessions Curs/Sess Comment
--------- ------------------ -------- --------- -------------------
Begin Snap: 12243 26-Aug-09 10:50:01 129 10.7
End Snap: 12244 26-Aug-09 11:10:02 130 10.9
Elapsed: 20.02 (mins)



Load Profile
~~~~~~~~~~~~ Per Second Per Transaction
--------------- ---------------
Redo size: 26,848.13 8,344.88
Logical reads: 40,018.33 12,438.41
Block changes: 133.11 41.37
Physical reads: 27,484.03 8,542.53
Physical writes: 18.91 5.88
User calls: 532.84 165.62
Parses: 262.09 81.46
Hard parses: 0.63 0.20
Sorts: 3.49 1.09
Logons: 0.10 0.03
Executes: 262.73 81.66
Transactions: 3.22

% Blocks changed per Read: 0.33 Recursive Call %: 7.84
Rollback per transaction %: 0.00 Rows per Sort: 39.05

Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Buffer Nowait %: 99.84 Redo NoWait %: 100.00
Buffer Hit %: 31.33 In-memory Sort %: 99.95
Library Hit %: 99.84 Soft Parse %: 99.76
Execute to Parse %: 0.25 Latch Hit %: 98.09
Parse CPU to Parse Elapsd %: 50.79 % Non-Parse CPU: 99.71


Top 5 Timed Events
~~~~~~~~~~~~~~~~~~ % Total
Event Waits Time (s) Ela Time
-------------------------------------------- ------------ ----------- --------
CPU time 3,963 55.44
db file sequential read 32,113,320 2,458 34.39
global cache freelist wait 49,517 245 3.42
db file scattered read 38,749 176 2.47
latch free 103,945 175 2.45
-------------------------------------------------------------



....

CPU Elapsd
Buffer Gets Executions Gets per Exec %Total Time (s) Time (s) Hash Value
--------------- ------------ -------------- ------ -------- --------- ----------
781,238 12 65,103.2 1.6 66.71 85.55 1804438004
Module: java_q4p@App-host-A (TNS V1-V3)
SELECT objid FROM table_t1 WHERE group2function = :P10
416 AND child2group_inst = :P10417 AND iter_seqno = :P10418
FOR UPDATE

742,736 43 17,272.9 1.5 61.49 76.15 3909554356
Module: java_q4p@App-host-A (TNS V1-V3)
SELECT objid FROM table_t1 WHERE group2function = :P61
6 AND child2group_inst = :P617 AND iter_seqno = :P618 FOR UP
DATE

742,681 44 16,879.1 1.5 62.21 76.33 3711122495
Module: java_q4p@App-host-A (TNS V1-V3)
SELECT objid FROM table_t1 WHERE group2function = :P41
6 AND child2group_inst = :P417 AND iter_seqno = :P418 FOR UP
DATE

742,535 12 61,877.9 1.5 61.96 77.54 4162730032
Module: java_q4p@App-host-A (TNS V1-V3)
SELECT objid FROM table_t1 WHERE group2function = :P78
16 AND child2group_inst = :P7817 AND iter_seqno = :P7818 FOR
UPDATE


...
Physical Reads Executions Reads per Exec %Total Time (s) Time (s) Hash Value
--------------- ------------ -------------- ------ -------- --------- ----------
577,596 12 48,133.0 1.7 66.71 85.55 1804438004
Module: java_q4p@App-Host-A (TNS V1-V3)
SELECT objid FROM table_t1 WHERE group2function = :P10
416 AND child2group_inst = :P10417 AND iter_seqno = :P10418
FOR UPDATE

551,188 43 12,818.3 1.7 61.49 76.15 3909554356
Module: java_q4p@App-Host-A (TNS V1-V3)
SELECT objid FROM table_t1 WHERE group2function = :P61
6 AND child2group_inst = :P617 AND iter_seqno = :P618 FOR UP
DATE

545,948 12 45,495.7 1.6 63.26 77.21 2226722238
Module: java_q4p@App-Host-A (TNS V1-V3)
SELECT objid FROM table_t1 WHERE group2function = :P60
16 AND child2group_inst = :P6017 AND iter_seqno = :P6018 FOR
UPDATE

545,875 12 45,489.6 1.6 62.13 76.72 3371167837
Module: java_q4p@App-Host-A (TNS V1-V3)
SELECT objid FROM table_t1 WHERE group2function = :P54
16 AND child2group_inst = :P5417 AND iter_seqno = :P5418 FOR
UPDATE
..



Top 5 Physical Reads per Segment for DB: DB3 Instance: Instance-A Snaps: 12244
-> End Segment Physical Reads Threshold: 1000
Subobject Obj. Physical
Owner Tablespace Object Name Name Type Reads %Total
---------- ---------- -------------------- ---------- ----- ------------ -------
User DATA11 table_t1 TABLE 30,241,496 91.19


...
^LTop 5 Buf. Busy Waits per Segment for DB: DB3 Instance: Instance-A Snaps: 12244
-> End Segment Buffer Busy Waits Threshold: 100

Subobject Obj. Busy
Owner Tablespace Object Name Name Type Waits %Total
---------- ---------- -------------------- ---------- ----- ------------ -------
User DATA11 table_t1 TABLE 48,928 99.35
...


Further details.
a)
select count(*) from table_t1 ;
29367305

b) there are :
NONUNIQUE index C2GI9757 on table_t1(child2group_inst)
and another nonunique index G2F9757 on table_t1(GROUP2FUNCTION )
and
UNIQUE index SYS_C002589 on table_t1(objid) .




c) explain plan for

SELECT objid FROM table_t1 WHERE group2function = :P10416
AND child2group_inst = :P10417 AND iter_seqno = :P10418

Operation Object Name Rows Bytes Cost Object Node In/Out PStart PStop
SELECT STATEMENT Optimizer Mode=FIRST_ROWS 1 4
TABLE ACCESS BY INDEX ROWID USER.table_t1 1 19 4
INDEX RANGE SCAN USER.C2GI9757 1 3

d) chain_cnt is 0 for table_t1

e) There are 16 cpu per RAC host


Question/s:
1.Where does this huge PIO comes in? (from explain plan it looks query cost is very less and it is not performing lots of IO.)
2. How to reduce IO in the mentioned query?


Regards

 Physical Reads  Executions  Reads per Exec %Total Time (s)  Time (s) Hash 
Value
--------------- ------------ -------------- ------ -------- --------- 
----------
        577,596           12       48,133.0    1.7    66.71     85.55 
1804438004
Module: java_q4p@App-Host-A (TNS V1-V3)
SELECT objid FROM table_t1 WHERE  group2function =  :P10
416 AND  child2group_inst =  :P10417 AND  iter_seqno =  :P10418
FOR UPDATE

Tom,
further details for the above question.

f)select count(distinct(group2function)) from table_T1
890

select count(distinct(child2group_inst)) from table_T1
20770108

select distinct(iter_seqno) from table_T1
780998

g) Tablespace IO Stats
Tablespace
-------
Av Av Av Av Buffer Av Buf
Reads Reads/s Rd(ms) Blks/Rd Writes Writes/s Waits Wt(ms)
-------------- ------- ------ ------- ------------ -------- ---------- ------
DATA11
31,048,531 25,831 0.1 1.0 462 0 97,194 0.1


Regards

Many thanks Tom for your help.


.....So, I'm guessing you do not have an index on those three columns and we are forced to go to the table over and over and over and over to find out the other columns do not match the where clause.

03 columns in where clause with index(Y/N) are as follows:

child2group_inst - has nonunique index
GROUP2FUNCTION - has nonunique index
iter_seqno - NO Index


....If the three columns where indexed in a concatenated index - the MAX IO's it should do would be the number of rows returned plus a small number of index reads (very small)

Datatype of all above 03 columns in table_T1 is NUMBER.

and

select count(*) from table_t1 ;
29367305

select count(distinct(group2function)) from table_T1
890

select count(distinct(child2group_inst)) from table_T1
20770108

select distinct(iter_seqno) from table_T1
780998

Question.
1. So composite index on table_T1(group2function,child2group_inst,iter_seqno) would reduce in IO?


Regards

In the AWR report I see row lock waits on indexes:

                                                                     Row
           Tablespace                      Subobject  Obj.          Lock    % of
Owner         Name    Object Name            Name     Type         Waits Capture
---------- ---------- -------------------- ---------- ----- ------------ -------
ECP_3229   ECP_INDEX_ IF414_CPBALANCESHEET            INDEX           33    4.78
ECP_3229   ECP_INDEX_ PK_CPCASECOLLATERAL             INDEX           33    4.78
ECP_3229   ECP_INDEX_ PK_CPCASECUSTOMERCOM            INDEX           31    4.49
ECP_3229   ECP_INDEX_ PK_CPCASEROLE                   INDEX           28    4.06
ECP_3229   ECP_INDEX_ PK_CPCASECOLLATERALI            INDEX           26    3.77
          -------------------------------------------------------------

This I can - maybe -understand on the PK_-indexes (being primary keys). But definitly not for the IF414_CPBALANCESHEET index. The column in this index is a foreign key in a reference constraint and is a non-unique index. I've googled on the topic, but can only find information related to the topic of indexing foreign keys, and generally about locking mechanismen. Nothing that really explains how and when you can get a "row lock wait" on a index object.

Do you have any comment about this, or suggestions about any reading that will explain this?

ops$tkyte%ORA10GR2> create table p( x int primary key );

Table created.

ops$tkyte%ORA10GR2> create table c( x int references p, y int );

Table created.

ops$tkyte%ORA10GR2> create index c_idx on c(x);

Index created.

ops$tkyte%ORA10GR2> insert into p values ( 1 );

1 row created.

ops$tkyte%ORA10GR2> commit;

Commit complete.

ops$tkyte%ORA10GR2>
ops$tkyte%ORA10GR2>
ops$tkyte%ORA10GR2> select object_name, statistic_name, value from v$segment_statistics where object_name in ( 'P', 'C', 'C_IDX' ) and statistic_name like '%wait%' order by 1,2;

OBJEC STATISTIC_NAME            VALUE
----- -------------------- ----------
C     ITL waits                     0
C     buffer busy waits             0
C     row lock waits                0
C_IDX ITL waits                     0
C_IDX buffer busy waits             0
C_IDX row lock waits                0
P     ITL waits                     0
P     buffer busy waits             0
P     row lock waits                0

9 rows selected.

ops$tkyte%ORA10GR2>
ops$tkyte%ORA10GR2> insert into c values (1,1);

1 row created.

ops$tkyte%ORA10GR2> declare
  2          pragma autonomous_transaction;
  3  begin
  4          delete from p where x = 1;
  5          commit;
  6  end;
  7  /
declare
*
ERROR at line 1:
ORA-00060: deadlock detected while waiting for resource
ORA-06512: at line 4


ops$tkyte%ORA10GR2>
ops$tkyte%ORA10GR2> select object_name, statistic_name, value from v$segment_statistics where object_name in ( 'P', 'C', 'C_IDX' ) and statistic_name like '%wait%' order by 1,2;

OBJEC STATISTIC_NAME            VALUE
----- -------------------- ----------
C     ITL waits                     0
C     buffer busy waits             0
C     row lock waits                0
C_IDX ITL waits                     0
C_IDX buffer busy waits             0
C_IDX row lock waits                1
P     ITL waits                     0
P     buffer busy waits             0
P     row lock waits                0

9 rows selected.

.... continue from last review (look above) ....

Another example from AWR report:

Top 5 Timed Events                                         Avg %Total
~~~~~~~~~~~~~~~~~~                                        wait   Call
Event                                 Waits    Time (s)   (ms)   Time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
enq: TX - row lock contention           181         521   2879   31.8 Applicatio
db file sequential read              77,499         515      7   31.4   User I/O
CPU time                                            450          27.4
log file sync                         7,303         123     17    7.5     Commit
log file parallel write              10,115         109     11    6.7 System I/O
          -------------------------------------------------------------

From the AWR report it looks like the row lock waits come from "enq: TX - row lock contention".

As far as I know this is related to:
- Waits for TX in mode 6 (one user is updating or deleting a row, which another user wants to update or delete)
- Waits for TX in mode 4 (waiting because of possible duplicate in unique index, as most PK indexes). Question: How does this lock actually appear? The mode 6 lock is held by changing the "lock byte" on the row? What about the mode 4 blocks?

Is the row wait lock on no-unique index related to another wait event?

If so, my number don't seem to fit in:

Segments by Row Lock Waits:

                                                                     Row
           Tablespace                      Subobject  Obj.          Lock    % of
Owner         Name    Object Name            Name     Type         Waits Capture
---------- ---------- -------------------- ---------- ----- ------------ -------
ECP_3229   ECP_INDEX_ PK_CPCASECUSTOMERCOM            INDEX           20    5.06
ECP_3229   ECP_INDEX_ PK_CPCASEADJUSTMENTC            INDEX           18    4.56
ECP_3229   ECP_INDEX_ PK_CPCASECOLLATERAL             INDEX           18    4.56
ECP_4210   ECP_INDEX_ IF422_CPCASEBALANCES            INDEX           17    4.30
ECP_3229   ECP_INDEX_ PK_CPCASEADJUSTMENTR            INDEX           17    4.30
          -------------------------------------------------------------

Event statistics:

                                                                   Avg
                                             %Time  Total Wait    wait     Waits
Event                                 Waits  -outs    Time (s)    (ms)      /txn
---------------------------- -------------- ------ ----------- ------- ---------
enq: TX - row lock contentio            181   97.8         521    2879       0.0
enq: CF - contention                      2     .0           0     120       0.0

Enqueue Activity:

Enqueue Type (Request Reason)
------------------------------------------------------------------------------
    Requests    Succ Gets Failed Gets       Waits  Wt Time (s) Av Wt Time(ms)
------------ ------------ ----------- ----------- ------------ --------------
TX-Transaction (row lock contention)
           4            4           0           4          534     133,403.25
CF-Controlfile Transaction
       1,322        1,322           0           2            0         122.50
          -------------------------------------------------------------

Here the TX-Transaction seems to be related to the "enq: TX - row contention". The wait time just about fits 534 s vs 521 s. But the number of waits does not match at all - 181 and 4.

Must admitt that I'm getting a little confused here.
What is the exact meaning of "TX-Transaction" here? And how can I investigate this problem further (if it is a problem)? Application people is complaining about average request times is rising suddenly, and to me it definitly seems like we're having a locking issue.

Sorry ... forgot to tell:
- AWR report is from 30 minutt snapshot (AWR)
- 4 cpu's on the database node

Hi Sir;
What is the side effect of taking snapshot in 30 minutes interval at all time ?

Hi Tom,

CPU core is one basic information we look for when looking into the DB time. Why AWR report does not display this information.

I know it's just a matter of executing small command to get number of cpu cores speed etc, but would it not be nice to keep these info in AWR report?

Hi Tom,

I have a statspack report from our test environment which was taken for 2 hour period. It shows that DP CPU time was 20.5 seconds. But in the SQLs ordered by CPU section, the first SQL shown itself taken 85.36 seconds. For your information, this statistic was gather at the time when a long running (9 hours) was running.

1) How is this possible?
2) Is there any other problem that you can find out in the statspack report?

STATSPACK report for

Database    DB Id    Instance     Inst Num Startup Time    Release     RAC
~~~~~~~~ ----------- ------------ -------- --------------- ----------- ---
           681387821 TDOLPHIN            1 20-Jun-10 12:16 10.2.0.4.0  NO

Host  Name:   dl0dbsbhg117     Num CPUs:   12        Phys Memory (MB):   80,422
~~~~

Snapshot       Snap Id     Snap Time      Sessions Curs/Sess Comment
~~~~~~~~    ---------- ------------------ -------- --------- -------------------
Begin Snap:       3202 09-Aug-10 19:25:00       69      45.8
  End Snap:       3212 09-Aug-10 21:25:02       69      45.8
   Elapsed:              120.03 (mins)

Cache Sizes                       Begin        End
~~~~~~~~~~~                  ---------- ----------
               Buffer Cache:     1,056M             Std Block Size:         8K
           Shared Pool Size:       432M                 Log Buffer:     4,096K

Load Profile                            Per Second       Per Transaction
~~~~~~~~~~~~                       ---------------       ---------------
                  Redo size:              9,481.38             95,104.32
              Logical reads:              6,487.38             65,072.54
              Block changes:                 43.36                434.91
             Physical reads:              4,363.54             43,769.08
            Physical writes:                  1.95                 19.58
                 User calls:                 19.41                194.67
                     Parses:                  9.54                 95.65
                Hard parses:                  0.58                  5.85
                      Sorts:                 11.29                113.20
                     Logons:                  2.82                 28.27
                   Executes:                 69.25                694.63
               Transactions:                  0.10

  % Blocks changed per Read:    0.67    Recursive Call %:    93.27
 Rollback per transaction %:    0.00       Rows per Sort:    13.35

Instance Efficiency Percentages
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
            Buffer Nowait %:  100.00       Redo NoWait %:  100.00
            Buffer  Hit   %:   52.99    In-memory Sort %:  100.00
            Library Hit   %:   91.86        Soft Parse %:   93.89
         Execute to Parse %:   86.23         Latch Hit %:   99.47
Parse CPU to Parse Elapsd %:             % Non-Parse CPU:

 Shared Pool Statistics        Begin   End
                               ------  ------
             Memory Usage %:   67.74   68.56
    % SQL with executions>1:   56.67   54.13
  % Memory for SQL w/exec>1:   38.07   36.61

Top 5 Timed Events                                                    Avg %Total
~~~~~~~~~~~~~~~~~~                                                   wait   Call
Event                                            Waits    Time (s)   (ms)   Time
----------------------------------------- ------------ ----------- ------ ------
latch: session allocation                        8,995           3      0   60.4
latch free                                       7,379           1      0   22.3
latch: cache buffers chains                      2,448           1      0   14.5
wait list latch free                                 9           0     10    2.1
latch: shared pool                                 252           0      0     .6
          -------------------------------------------------------------
Host CPU  (CPUs: 12)
~~~~~~~~              Load Average
                      Begin     End      User  System    Idle     WIO     WCPU
                    ------- -------   ------- ------- ------- ------- --------
                       4.21    4.49     32.52    6.91   60.57    0.00   12.59

Instance CPU
~~~~~~~~~~~~
              % of total CPU for Instance:    0.02
              % of busy  CPU for Instance:    0.06
  %DB time waiting for CPU - Resource Mgr:

Memory Statistics                       Begin          End
~~~~~~~~~~~~~~~~~                ------------ ------------
                  Host Mem (MB):     80,421.8     80,421.8
                   SGA use (MB):      1,600.0      1,600.0
                   PGA use (MB):        426.8        441.4
    % Host Mem used for SGA+PGA:          2.5          2.5
          -------------------------------------------------------------

Time Model System Stats  DB/Inst: TDOLPHIN/TDOLPHIN  Snaps: 3202-3212
-> Ordered by % of DB time desc, Statistic name

Statistic                                       Time (s) % of DB time
----------------------------------- -------------------- ------------
sql execute elapsed time                        79,385.0        100.0
PL/SQL execution elapsed time                      464.9           .6
parse time elapsed                                  49.9           .1
hard parse elapsed time                             45.1           .1
DB CPU                                              20.5           .0
repeated bind elapsed time                           0.1           .0
connection management call elapsed                   0.1           .0
PL/SQL compilation elapsed time                      0.0           .0
sequence load elapsed time                           0.0           .0
DB time                                         79,404.8
background elapsed time                         18,414.7
background cpu time                                  0.0
          -------------------------------------------------------------
Wait Events  DB/Inst: TDOLPHIN/TDOLPHIN  Snaps: 3202-3212
-> s - second, cs - centisecond,  ms - millisecond, us - microsecond
-> %Timeouts:  value of 0 indicates value was < .5%.  Value of null is truly 0
-> Only events with Total Wait Time (s) >= .001 are shown
-> ordered by Total Wait Time desc, Waits desc (idle events last)

                                                                    Avg
                                                %Time Total Wait   wait    Waits
Event                                    Waits  -outs   Time (s)   (ms)     /txn
--------------------------------- ------------ ------ ---------- ------ --------
latch: session allocation                8,995      0          3      0     12.5
latch free                               7,379      0          1      0     10.3
latch: cache buffers chains              2,448      0          1      0      3.4
wait list latch free                         9      0          0     10      0.0
latch: shared pool                         252      0          0      0      0.4
latch: library cache                        11      0          0      0      0.0
db file sequential read             13,561,704      0          0      0 ########
direct path read                     1,471,016      0          0      0  2,048.8
control file sequential read            25,656      0          0      0     35.7
PX Deq: Join ACK                        14,368      0          0      0     20.0
PX Deq: Parse Reply                     13,923      0          0      0     19.4
db file parallel write                   7,510      0          0      0     10.5
control file parallel write              6,080      0          0      0      8.5
reliable message                         2,796      0          0      0      3.9
log file parallel write                  2,655      0          0      0      3.7
enq: PS - contention                     1,978      0          0      0      2.8
enq: KO - fast object checkpoint         1,834      0          0      0      2.6
PX Deq: Msg Fragment                     1,676      0          0      0      2.3
PX qref latch                            1,236     85          0      0      1.7
log file sync                              693      0          0      0      1.0
db file scattered read                     480      0          0      0      0.7
LGWR wait for redo copy                    167      0          0      0      0.2
SQL*Net more data to client                151      0          0      0      0.2
direct path write                          144      0          0      0      0.2
cursor: pin S                               83      0          0      0      0.1
log file single write                        8      0          0      0      0.0
log file sequential read                     8      0          0      0      0.0
direct path read temp                        7      0          0      0      0.0
direct path write temp                       7      0          0      0      0.0
os thread startup                            6      0          0      0      0.0
buffer busy waits                            1      0          0      0      0.0
PX Deq: Execution Msg                  402,681      9     71,666    178    560.8
PX Deq Credit: send blkd                35,843    100     71,642   1999     49.9
PX Idle Wait                            52,644     61     64,256   1221     73.3
Streams AQ: waiting for time mana           26     92      8,710 ######      0.0
Streams AQ: qmn coordinator idle           694     38      7,212  10392      1.0
jobq slave wait                             20    100         60   3000      0.0
PX Deq: Execute Reply                  246,467      0          0      0    343.3
SQL*Net message to client               35,255      0          0      0     49.1
SQL*Net message from client             35,255      0          0      0     49.1
PX Deq: Signal ACK                      11,024      1          0      0     15.4
Streams AQ: qmn slave idle wait            994      0          0      0      1.4
SQL*Net more data from client               31      0          0      0      0.0
class slave wait                             4      0          0      0      0.0
          -------------------------------------------------------------
Background Wait Events  DB/Inst: TDOLPHIN/TDOLPHIN  Snaps: 3202-3212
-> %Timeouts:  value of 0 indicates value was < .5%.  Value of null is truly 0
-> Only events with Total Wait Time (s) >= .001 are shown
-> ordered by Total Wait Time desc, Waits desc (idle events last)

                                                                    Avg
                                                %Time Total Wait   wait    Waits
Event                                    Waits  -outs   Time (s)   (ms)     /txn
--------------------------------- ------------ ------ ---------- ------ --------
events in waitclass Other                  173      1          0      0      0.2
control file sequential read            20,456      0          0      0     28.5
db file parallel write                   7,513      0          0      0     10.5
control file parallel write              6,080      0          0      0      8.5
db file sequential read                  5,296      0          0      0      7.4
log file parallel write                  2,655      0          0      0      3.7
direct path read                           140      0          0      0      0.2
direct path write                          140      0          0      0      0.2
log file single write                        8      0          0      0      0.0
log file sequential read                     8      0          0      0      0.0
os thread startup                            6      0          0      0      0.0
rdbms ipc message                       47,153     59     75,293   1597     65.7
Streams AQ: waiting for time mana           26     92      8,710 ######      0.0
pmon timer                               2,695    100      8,076   2997      3.8
Streams AQ: qmn coordinator idle           694     38      7,212  10392      1.0
smon timer                                  28     75      6,300 ######      0.0
Streams AQ: qmn slave idle wait            994      0          0      0      1.4
          -------------------------------------------------------------
Wait Event Histogram  DB/Inst: TDOLPHIN/TDOLPHIN  Snaps: 3202-3212
-> Total Waits - units: K is 1000, M is 1000000, G is 1000000000
-> % of Waits - column heading: <=1s is truly <1024ms, >1s is truly >=1024ms
-> % of Waits - value: .0 indicates value was <.05%, null is truly 0
-> Ordered by Event (idle events last)

                           Total ----------------- % of Waits ------------------
Event                      Waits  <1ms  <2ms  <4ms  <8ms <16ms <32ms  <=1s   >1s
-------------------------- ----- ----- ----- ----- ----- ----- ----- ----- -----
latch free                 5477   99.7    .2    .1                      .0
latch: cache buffers chain 2380   96.9   1.7    .5    .4    .4
latch: library cache         11  100.0
latch: session allocation  7874   99.6    .3    .1
latch: shared pool          252  100.0
wait list latch free         10                          100.0
          -------------------------------------------------------------

SQL ordered by CPU  DB/Inst: TDOLPHIN/TDOLPHIN  Snaps: 3202-3212
-> Resources reported for PL/SQL code includes the resources used by all SQL
   statements called by the code.
-> Total DB CPU (s):              21
-> Captured SQL accounts for ######% of Total DB CPU
-> SQL reported below exceeded  1.0% of Total DB CPU

    CPU                  CPU per             Elapsd                     Old
  Time (s)   Executions  Exec (s)  %Total   Time (s)    Buffer Gets  Hash Value
---------- ------------ ---------- ------ ---------- --------------- ----------
     85.36       25,837       0.00  416.2      89.61         165,829 3087861205
Module: JDBC Thin Client
INSERT INTO VA_TEMP_HISTORIE( LOG_ID, BUCHUNG_ID, SCHULDNERNR, M
AHNAKTENNR, MAHNTANR, GLAEUBIGERNR, FORDNR, FORDERGNR, BETRAG, U
RSPRUNGSBETRAG, WMM, ZINSSATZ, VALUTADATUM, ERFASSDATUM, ERFASSD
ATUMINTERN, ERFASS_REF, ERFASS_REFINTERN, ERFASSSBNR, BUCHUNGSGR
UPPE, LFDNR, STORNOMM, ZUSATZTEXT, TITELMM, TITELAKTE, BELEGNR,

start1 = get_cpu
loop a lot
     start2 = get_cpu
     do something 
     total2 = total2 + (get_cpu-start2)
end loop
total1 = get_cpu - start1

Sir,

I have read from your site/books that "execute to parse should be near to 100%", one thing that I am not clear is that every query that has to be executed in a Database has first to be parsed for syntax and semantic check if so this will always increase the parse count which makes difficult for the execute to parse % reach 100. In some of your posting you have mentioned that PL/SQL will be helpful to get a higer execute to parse count. ie if I have a stored procedure with some select and insert commands and executing it multiple times would only execute the stored procedure rather than parse it, here i am not clear I assume that the Database has to check whether the user has execute privileges on the stored procedure or not which i think is parsing is this is the case how can I increase the execute to parse ratio using PL/SQL. How can we achieve a good execute to parse % without PL/SQL.

Thanks in advance for your valuable time and your expert suggestions.

This is from our production box, oracle EE 10.2.0.4.0 on solaris 5.9, 28 cpu machine, hosts content management (packaged) application stellent. The issue apparently is very high number of sql executions and equal number of parses (which is also showing up in low execute to parse ratio) which is consuming almost 50 to 60% of cpu of the box.

The cursor sharing is similar:



Snap Id Snap Time Sessions Curs/Sess
--------- ------------------- -------- ---------
Begin Snap: 31273 14-Apr-11 12:00:03 333 16.8
End Snap: 31274 14-Apr-11 13:00:19 333 16.8
Elapsed: 60.26 (mins)
DB Time: 793.69 (mins)

Cache Sizes
~~~~~~~~~~~ Begin End
---------- ----------
Buffer Cache: 448M 448M Std Block Size: 8K
Shared Pool Size: 1,104M 1,104M Log Buffer: 14,384K

Load Profile
~~~~~~~~~~~~ Per Second Per Transaction
--------------- ---------------
Redo size: 3,760.73 6,105.85
Logical reads: 714,366.66 1,159,833.45
Block changes: 22.30 36.20
Physical reads: 92.30 149.86
Physical writes: 91.16 148.01
User calls: 141.09 229.07
Parses: 70.72 114.82
Hard parses: 7.99 12.97
Sorts: 10.60 17.21
Logons: 0.02 0.04
Executes: 74.29 120.61
Transactions: 0.62

% Blocks changed per Read: 0.00 Recursive Call %: 53.51
Rollback per transaction %: 0.94 Rows per Sort: 75.77

Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Buffer Nowait %: 100.00 Redo NoWait %: 100.00
Buffer Hit %: 100.00 In-memory Sort %: 99.99
Library Hit %: 86.81 Soft Parse %: 88.70
Execute to Parse %: 4.80 Latch Hit %: 96.50
Parse CPU to Parse Elapsd %: 89.36 % Non-Parse CPU: 99.00

Shared Pool Statistics Begin End
------ ------
Memory Usage %: 60.69 86.98
% SQL with executions>1: 53.09 83.93
% Memory for SQL w/exec>1: 72.12 86.62

Top 5 Timed Events Avg %Total
~~~~~~~~~~~~~~~~~~ wait Call
Event Waits Time (s) (ms) Time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
CPU time 45,975 96.5
Backup: sbtwrite2 33,297 4,434 133 9.3 Administra
db file sequential read 8,567 122 14 0.3 User I/O
Backup: sbtbackup 9 79 8805 0.2 Administra
enq: TX - row lock contention 262 54 206 0.1 Applicatio
-------------------------------------------------------------
^LTime Model Statistics DB/Inst: WCMP02/WCMP02 Snaps: 31273-31274
-> Total time in database user-calls (DB Time): 47621.1s
-> Statistics including the word "background" measure background process
time, and so do not contribute to the DB time statistic
-> Ordered by % or DB time desc, Statistic name

Statistic Name Time (s) % of DB Time
------------------------------------------ ------------------ ------------
sql execute elapsed time 46,716.6 98.1
DB CPU 45,975.3 96.5
parse time elapsed 534.9 1.1
hard parse elapsed time 418.0 .9
RMAN cpu time (backup/restore) 107.9 .2
hard parse (sharing criteria) elapsed time 22.8 .0
hard parse (bind mismatch) elapsed time 19.0 .0
PL/SQL execution elapsed time 10.9 .0
connection management call elapsed time 4.6 .0
PL/SQL compilation elapsed time 3.4 .0
repeated bind elapsed time 0.1 .0
inbound PL/SQL rpc elapsed time 0.0 .0
failed parse elapsed time 0.0 .0
sequence load elapsed time 0.0 .0
DB time 47,621.1 N/A
background elapsed time 5,564.8 N/A





SQL section


-> Resources reported for PL/SQL code includes the resources used by all SQL
statements called by the code.
-> % Total DB Time is the Elapsed Time of the SQL statement divided
into the Total Database Time multiplied by 100

Elapsed CPU Elap per % Total
Time (s) Time (s) Executions Exec (s) DB Time SQL Id
---------- ---------- ------------ ---------- ------- -------------
2,656 2,575 847 3.1 5.6 0j06hs4gysj7q
Module: JDBC Thin Client
SELECT Revisions.*, DocumentsP.*, DocMeta.*, DocTypes.dGif, DocumentsW.dFi
leSize as WebFileSize, DocumentsW.dFormat as WebFormat, DocumentsA.dFileSize
as AlternateFileSize, DocumentsA.dFormat as AlternateFormat FROM Revisions I
NNER JOIN Documents DocumentsP ON (Revisions.dID = DocumentsP.dID AND Docum

2,530 2,456 1,715 1.5 5.3 80p73zwqhyuqy
Module: JDBC Thin Client
SELECT Revisions.*, DocumentsP.*, DocMeta.*, DocTypes.dGif, DocumentsW.dFi
leSize as WebFileSize, DocumentsW.dFormat as WebFormat, DocumentsA.dFileSize
as AlternateFileSize, DocumentsA.dFormat as AlternateFormat FROM Revisions I
NNER JOIN Documents DocumentsP ON (Revisions.dID = DocumentsP.dID AND Docum

2,437 2,394 1,541 1.6 5.1 dh2vbmtxpcw8s
Module: JDBC Thin Client
SELECT Revisions.*, DocumentsP.*, DocMeta.*, DocTypes.dGif, DocumentsW.dFi
leSize as WebFileSize, DocumentsW.dFormat as WebFormat, DocumentsA.dFileSize
as AlternateFileSize, DocumentsA.dFormat as AlternateFormat FROM Revisions I
NNER JOIN Documents DocumentsP ON (Revisions.dID = DocumentsP.dID AND Docum




^LSQL ordered by Parse Calls DB/Inst: Stellant Snaps: 31273-31274
-> Total Parse Calls: 255,694
-> Captured SQL account for 59.5% of Total

% Total
Parse Calls Executions Parses SQL Id
------------ ------------ --------- -------------
36,409 36,410 14.24 ftj9uawt4wwzb
select condition from cdef$ where rowid=:1

19,140 19,140 7.49 736z4pq1ggssb
Module: JDBC Thin Client
SELECT/*+ USE_NL (Revisions Documents DocMeta) LEADING(Revisions)INDEX (Revision
s PK_Revisions)*/ Revisions.*, Documents.*, DocMeta.* FROM Revisions, Document
s, DocMeta WHERE Revisions.dID=:"SYS_B_0" AND Revisions.dID=Documents.dID AND
DocMeta.dID = Documents.dID AND Revisions.dStatus<>:"SYS_B_1" AND Documents.dI

18,641 18,641 7.29 1fha9wm4h1kjf
Module: JDBC Thin Client
SELECT/*+ INDEX (Revisions dDocName)*/ Max(Revisions.dID) AS dID FROM Revision
s WHERE (Revisions.dDocName=:"SYS_B_0" AND Revisions.dStatus<>:"SYS_B_1") AN
D (Revisions.dStatus=:"SYS_B_2" OR Revisions.dReleaseState in (:"SYS_B_3", :"SYS
_B_4"))


We've upgraded this DB in dev to 11.1.0.7 RAC on linux and the executions of course are same but with very small elapsed per execution seconds.

Question (these are my thoughts):

1. We have asked the application team to investigate the cause of such high executions (and parses) but want to know if going to cursor_sharing=similar on 11g will kick in adaptive cursor sharing and benefit by reducing the parsing.

2. If 'parsed time elapsed' and 'hard prse time elapsed' showing low/insignificant values, should we consider that parsing is not consuming that much of CPU/time as compared to executions by these SQL's.

Any other clues?

Hi Tom

Sorry I forgot the code button in hurry.

This is from our production box, oracle EE 10.2.0.4.0 on solaris 5.9, 28 cpu machine, hosts content management (packaged) application stellent. The issue apparently is very high number of sql executions and equal number of parses (which is also showing up in low execute to parse ratio) which is consuming almost 50 to 60% of cpu of the box.

The cursor sharing is similar:

              Snap Id      Snap Time      Sessions Curs/Sess
            --------- ------------------- -------- ---------
Begin Snap:     31273 14-Apr-11 12:00:03       333      16.8
  End Snap:     31274 14-Apr-11 13:00:19       333      16.8
   Elapsed:               60.26 (mins)
   DB Time:              793.69 (mins)

Cache Sizes
~~~~~~~~~~~                       Begin        End
                             ---------- ----------
               Buffer Cache:       448M       448M  Std Block Size:         8K
           Shared Pool Size:     1,104M     1,104M      Log Buffer:    14,384K

Load Profile
~~~~~~~~~~~~                            Per Second       Per Transaction
                                   ---------------       ---------------
                  Redo size:              3,760.73              6,105.85
              Logical reads:            714,366.66          1,159,833.45
              Block changes:                 22.30                 36.20
             Physical reads:                 92.30                149.86
            Physical writes:                 91.16                148.01
                 User calls:                141.09                229.07
                     Parses:                 70.72                114.82
                Hard parses:                  7.99                 12.97
                      Sorts:                 10.60                 17.21
                     Logons:                  0.02                  0.04
                   Executes:                 74.29                120.61
               Transactions:                  0.62

  % Blocks changed per Read:    0.00    Recursive Call %:    53.51
 Rollback per transaction %:    0.94       Rows per Sort:    75.77

Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
            Buffer Nowait %:  100.00       Redo NoWait %:  100.00
            Buffer  Hit   %:  100.00    In-memory Sort %:   99.99
            Library Hit   %:   86.81        Soft Parse %:   88.70
         Execute to Parse %:    4.80         Latch Hit %:   96.50
Parse CPU to Parse Elapsd %:   89.36     % Non-Parse CPU:   99.00

 Shared Pool Statistics        Begin    End
                              ------  ------
             Memory Usage %:   60.69   86.98
    % SQL with executions>1:   53.09   83.93
  % Memory for SQL w/exec>1:   72.12   86.62



Top 5 Timed Events                                         Avg %Total
~~~~~~~~~~~~~~~~~~                                        wait   Call
Event                                 Waits    Time (s)   (ms)   Time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
CPU time                                         45,975          96.5
Backup: sbtwrite2                    33,297       4,434    133    9.3 Administra
db file sequential read               8,567         122     14    0.3   User I/O
Backup: sbtbackup                         9          79   8805    0.2 Administra
enq: TX - row lock contention           262          54    206    0.1 Applicatio
          -------------------------------------------------------------
^LTime Model Statistics              DB/Inst: WCMP02/WCMP02  Snaps: 31273-31274
-> Total time in database user-calls (DB Time): 47621.1s
-> Statistics including the word "background" measure background process
   time, and so do not contribute to the DB time statistic
-> Ordered by % or DB time desc, Statistic name

Statistic Name                                       Time (s) % of DB Time
------------------------------------------ ------------------ ------------
sql execute elapsed time                             46,716.6         98.1
DB CPU                                               45,975.3         96.5
parse time elapsed                                      534.9          1.1
hard parse elapsed time                                 418.0           .9
RMAN cpu time (backup/restore)                          107.9           .2
hard parse (sharing criteria) elapsed time               22.8           .0
hard parse (bind mismatch) elapsed time                  19.0           .0
PL/SQL execution elapsed time                            10.9           .0
connection management call elapsed time                   4.6           .0
PL/SQL compilation elapsed time                           3.4           .0
repeated bind elapsed time                                0.1           .0
inbound PL/SQL rpc elapsed time                           0.0           .0
failed parse elapsed time                                 0.0           .0
sequence load elapsed time                                0.0           .0
DB time                                              47,621.1          N/A
background elapsed time                               5,564.8          N/A
background cpu time                                     626.7          N/A
          -------------------------------------------------------------





SQL section 


-> Resources reported for PL/SQL code includes the resources used by all SQL 
  statements called by the code. 
-> % Total DB Time is the Elapsed Time of the SQL statement divided 
  into the Total Database Time multiplied by 100 

Elapsed    CPU            Elap per % Total 
Time (s)  Time (s) Executions  Exec (s) DB Time  SQL Id 
---------- ---------- ------------ ---------- ------- ------------- 
  2,656    2,575      847    3.1  5.6 0j06hs4gysj7q 
Module: JDBC Thin Client 
SELECT Revisions.*, DocumentsP.*, DocMeta.*, DocTypes.dGif, DocumentsW.dFi 
leSize as WebFileSize, DocumentsW.dFormat as WebFormat, DocumentsA.dFileSize 
as AlternateFileSize, DocumentsA.dFormat as AlternateFormat FROM Revisions I 
NNER JOIN Documents DocumentsP ON (Revisions.dID = DocumentsP.dID AND Docum 

  2,530    2,456    1,715    1.5  5.3 80p73zwqhyuqy 
Module: JDBC Thin Client 
SELECT Revisions.*, DocumentsP.*, DocMeta.*, DocTypes.dGif, DocumentsW.dFi 
leSize as WebFileSize, DocumentsW.dFormat as WebFormat, DocumentsA.dFileSize 
as AlternateFileSize, DocumentsA.dFormat as AlternateFormat FROM Revisions I 
NNER JOIN Documents DocumentsP ON (Revisions.dID = DocumentsP.dID AND Docum 

  2,437    2,394    1,541    1.6  5.1 dh2vbmtxpcw8s 
Module: JDBC Thin Client 
SELECT Revisions.*, DocumentsP.*, DocMeta.*, DocTypes.dGif, DocumentsW.dFi 
leSize as WebFileSize, DocumentsW.dFormat as WebFormat, DocumentsA.dFileSize 
as AlternateFileSize, DocumentsA.dFormat as AlternateFormat FROM Revisions I 
NNER JOIN Documents DocumentsP ON (Revisions.dID = DocumentsP.dID AND Docum 




^LSQL ordered by Parse Calls      DB/Inst: Stellant Snaps: 31273-31274 
-> Total Parse Calls:      255,694 
-> Captured SQL account for    59.5% of Total 

                  % Total 
Parse Calls Executions  Parses  SQL Id 
------------ ------------ --------- ------------- 
    36,409    36,410  14.24 ftj9uawt4wwzb 
select condition from cdef$ where rowid=:1 

    19,140    19,140    7.49 736z4pq1ggssb 
Module: JDBC Thin Client 
SELECT/*+ USE_NL (Revisions Documents DocMeta) LEADING(Revisions)INDEX (Revision 
s PK_Revisions)*/ Revisions.*, Documents.*, DocMeta.* FROM Revisions, Document 
s, DocMeta WHERE Revisions.dID=:"SYS_B_0" AND Revisions.dID=Documents.dID AND 
DocMeta.dID = Documents.dID AND Revisions.dStatus<>:"SYS_B_1" AND Documents.dI 

    18,641    18,641    7.29 1fha9wm4h1kjf 
Module: JDBC Thin Client 
SELECT/*+ INDEX (Revisions dDocName)*/ Max(Revisions.dID) AS dID FROM Revision 
s WHERE (Revisions.dDocName=:"SYS_B_0" AND Revisions.dStatus<>:"SYS_B_1") AN 
D (Revisions.dStatus=:"SYS_B_2" OR Revisions.dReleaseState in (:"SYS_B_3", :"SYS 
_B_4"))

We've upgraded this DB in dev to 11.1.0.7 RAC on linux and the executions of course are same but with very small elapsed per execution seconds.

Question (these are my thoughts):

1. We have asked the application team to investigate the cause of such high executions (and parses) but want to know if going to cursor_sharing=similar on 11g will kick in adaptive cursor sharing and benefit by reducing the parsing.

2. If 'parsed time elapsed' and 'hard prse time elapsed' showing low/insignificant values, should we consider that parsing is not consuming that much of CPU/time as compared to executions by these SQL's.

Any other clues?

There is no way to edit the posts :)

The cursor sharing is EXACT on this database, sorry.

NOt sure why it gives:

SQL> show parameter cursor_sh

NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
cursor_sharing                       string      EXACT

Also, in a packaged app, don't we try to put 'external' fixes as code changes are not always feasible in a short time in a real world.

These are two 30 minutes statspack reports from a 10g database (240 GB) on a 16 GB RAM 2 physical, 4 virtual CPUs on a SUN OS .. these are during the two main time intervals slowness is being reported by the end users.

Can you help us drill down the problem areas please.

Snapshot       Snap Id     Snap Time      Sessions Curs/Sess Comment
~~~~~~~~    ---------- ------------------ -------- --------- -------------------
Begin Snap:       9861 26-Jul-12 08:02:34      281      92.4
  End Snap:       9871 26-Jul-12 08:32:34      288      91.9
   Elapsed:               30.00 (mins)

Cache Sizes                       Begin        End
~~~~~~~~~~~                  ---------- ----------
               Buffer Cache:       432M       592M  Std Block Size:         8K
           Shared Pool Size:       704M       544M      Log Buffer:    13,940K

Load Profile                            Per Second       Per Transaction
~~~~~~~~~~~~                       ---------------       ---------------
                  Redo size:            104,018.22             22,607.20
              Logical reads:             35,511.32              7,717.99
              Block changes:                424.68                 92.30
             Physical reads:              8,762.13              1,904.35
            Physical writes:                391.14                 85.01
                 User calls:              1,787.96                388.59
                     Parses:                168.60                 36.64
                Hard parses:                 46.23                 10.05
                      Sorts:                 59.06                 12.84
                     Logons:                  0.10                  0.02
                   Executes:              1,362.07                296.03
               Transactions:                  4.60

  % Blocks changed per Read:    1.20    Recursive Call %:    60.30
 Rollback per transaction %:    0.01       Rows per Sort:   374.04

Instance Efficiency Percentages
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
            Buffer Nowait %:   99.44       Redo NoWait %:  100.00
            Buffer  Hit   %:   76.35    In-memory Sort %:   99.96
            Library Hit   %:   92.11        Soft Parse %:   72.58
         Execute to Parse %:   87.62         Latch Hit %:   99.76
Parse CPU to Parse Elapsd %:   90.51     % Non-Parse CPU:   86.08

 Shared Pool Statistics        Begin   End
                               ------  ------
             Memory Usage %:   66.86   40.68
    % SQL with executions>1:   74.54   79.83
  % Memory for SQL w/exec>1:   68.30   79.16

Top 5 Timed Events                                                    Avg %Total
~~~~~~~~~~~~~~~~~~                                                   wait   Call
Event                                            Waits    Time (s)   (ms)   Time
----------------------------------------- ------------ ----------- ------ ------
CPU time                                                     3,234          61.4
direct path sync                                 4,974         537    108   10.2
db file sequential read                      2,189,322         398      0    7.6
db file scattered read                       2,507,932         342      0    6.5
ARCH wait on SENDREQ                               167         273   1637    5.2
          -------------------------------------------------------------
^LHost CPU  (CPUs: 4)
~~~~~~~~              Load Average
                      Begin     End      User  System    Idle     WIO     WCPU
                    ------- -------   ------- ------- ------- ------- --------
                       2.18    1.29     36.60   17.69   45.70    3.87   22.55

Instance CPU
~~~~~~~~~~~~
              % of total CPU for Instance:   47.73
              % of busy  CPU for Instance:   87.90
  %DB time waiting for CPU - Resource Mgr:

Memory Statistics                       Begin          End
~~~~~~~~~~~~~~~~~                ------------ ------------
                  Host Mem (MB):     16,384.0     16,384.0
                   SGA use (MB):      1,200.0      1,200.0
                   PGA use (MB):        528.0        567.1
    % Host Mem used for SGA+PGA:         10.5         10.8
          -------------------------------------------------------------

Time Model System Stats  DB/Inst: MESGAL/mesgal  Snaps: 9861-9871
-> Ordered by % of DB time desc, Statistic name

Statistic                                       Time (s) % of DB time
----------------------------------- -------------------- ------------
DB CPU                                           3,408.5         82.9
sql execute elapsed time                         3,337.1         81.2
parse time elapsed                                 499.7         12.2
hard parse elapsed time                            462.7         11.3
sequence load elapsed time                           5.8           .1
hard parse (sharing criteria) elaps                  4.5           .1
hard parse (bind mismatch) elapsed                   4.4           .1
connection management call elapsed                   3.0           .1
PL/SQL compilation elapsed time                      2.3           .1
PL/SQL execution elapsed time                        2.2           .1
repeated bind elapsed time                           0.2           .0
DB time                                          4,109.6
background elapsed time                            413.0
background cpu time                                 26.4
          -------------------------------------------------------------

                                                                    Avg
                                                %Time Total Wait   wait    Waits
Event                                    Waits  -outs   Time (s)   (ms)     /txn
--------------------------------- ------------ ------ ---------- ------ --------
direct path sync                         4,974      0        537    108      0.6
db file sequential read              2,189,322      0        398      0    264.3
db file scattered read               2,507,932      0        342      0    302.8
ARCH wait on SENDREQ                       167      0        273   1637      0.0
direct path write temp                  78,501      0        173      2      9.5
log file sync                           14,060      0         83      6      1.7
read by other session                  357,353      0         73      0     43.1
log file parallel write                 14,250      0         68      5      1.7
direct path read temp                   84,170      0         30      0     10.2
direct path read                         5,697      0         14      2      0.7
direct path write                        4,789      0          9      2      0.6
control file parallel write              1,754      0          7      4      0.2
db file parallel read                    1,388      0          6      4      0.2
SQL*Net more data to client            133,399      0          4      0     16.1
latch: shared pool                       3,247      0          3      1      0.4
latch: library cache                       915      0          2      3      0.1
log file sequential read                   174      0          1      8      0.0
cursor: pin S wait on X                     45     89          1     16      0.0
latch free                                 591      0          1      1      0.1
control file sequential read            15,907      0          1      0      1.9
library cache load lock                     53      0          1     11      0.0
latch: cache buffers chains              3,750      0          0      0      0.5
enq: HW - contention                        23      0          0     21      0.0
enq: TX - index contention                  21      0          0     16      0.0
os thread startup                            4      0          0     80      0.0
latch: session allocation                  497      0          0      0      0.1
latch: cache buffers lru chain             185      0          0      1      0.0
latch: library cache lock                  111      0          0      1      0.0
latch: row cache objects                    58      0          0      2      0.0
SGA: MMAN sleep for component shr           78      0          0      1      0.0
local write wait                            12      0          0      6      0.0
buffer busy waits                           57      0          0      1      0.0
...
...
                                                                    Avg
                                                %Time Total Wait   wait    Waits
Event                                    Waits  -outs   Time (s)   (ms)     /txn
--------------------------------- ------------ ------ ---------- ------ --------
ARCH wait on SENDREQ                       167      0        273   1637      0.0
log file parallel write                 14,247      0         68      5      1.7
control file parallel write              1,754      0          7      4      0.2
log file sequential read                   174      0          1      8      0.0
os thread startup                            4      0          0     80      0.0
control file sequential read             6,638      0          0      0      0.8
db file sequential read                  2,559      0          0      0      0.3
SGA: MMAN sleep for component shr           78      0          0      1      0.0
events in waitclass Other                  223      0          0      0      0.0
direct path write                           19      0          0      3      0.0
direct path read                            19      0          0      3      0.0
db file scattered read                     114      0          0      0      0.0
latch: shared pool                          14      0          0      1      0.0
log file single write                        4      0          0      1      0.0
Log archive I/O                            165      0          0      0      0.0
latch: library cache                         1      0          0      3      0.0
latch: cache buffers chains                  3      0          0      1      0.0
rdbms ipc message                       19,920     28     17,718    889      2.4
pmon timer                                 597    100      1,752   2934      0.1
Streams AQ: qmn slave idle wait             65      0      1,745  26848      0.0
Streams AQ: qmn coordinator idle           169     38      1,745  10326      0.0
smon timer                                   6    100      1,625 ######      0.0
Streams AQ: waiting for time mana            1    100         44  43896      0.0
...
...
^LSQL ordered by CPU  DB/Inst: MESGAL/mesgal  Snaps: 9861-9871
-> Resources reported for PL/SQL code includes the resources used by all SQL
   statements called by the code.
-> Total DB CPU (s):           3,408
-> Captured SQL accounts for   21.2% of Total DB CPU
-> SQL reported below exceeded  1.0% of Total DB CPU

    CPU                  CPU per             Elapsd                     Old
  Time (s)   Executions  Exec (s)  %Total   Time (s)    Buffer Gets  Hash Value
---------- ------------ ---------- ------ ---------- --------------- ----------
    253.90        1,722       0.15    7.4     287.50          98,718 1533742463
INSERT INTO MESGALX.DataStoreInserts1 (TxnID, TxnType, Sequence,
 SqlStmt) VALUES (:V1, :V2, :V3, :V4)

     58.40        3,433       0.02    1.7      66.16          86,554 3886788168
INSERT INTO MESGALX.DataStoreUpdates (TxnID, TxnType, Sequence,
SqlStmt) VALUES (:V1, :V2, :V3, :V4)

     39.94          827       0.05    1.2      41.63       2,076,359  494409777
Module: oracle@montoya (TNS V1-V3)
SELECT "A1"."ID","A1"."TXNID" FROM "DATASTOREUPDATESMASTER" "A1"
 ORDER BY "A1"."ID"

          -------------------------------------------------------------
^LSQL ordered by Elapsed  DB/Inst: MESGAL/mesgal  Snaps: 9861-9871
-> Resources reported for PL/SQL code includes the resources used by all SQL
   statements called by the code.
-> Total DB Time (s):           4,110
-> Captured SQL accounts for   24.2% of Total DB Time
-> SQL reported below exceeded  1.0% of Total DB Time

  Elapsed                Elap per            CPU                        Old
  Time (s)   Executions  Exec (s)  %Total   Time (s)  Physical Reads Hash Value
---------- ------------ ---------- ------ ---------- --------------- ----------
    287.50        1,722       0.17    7.0     253.90           6,492 1533742463
INSERT INTO MESGALX.DataStoreInserts1 (TxnID, TxnType, Sequence,
 SqlStmt) VALUES (:V1, :V2, :V3, :V4)
..
..



and



Snapshot       Snap Id     Snap Time      Sessions Curs/Sess Comment
~~~~~~~~    ---------- ------------------ -------- --------- -------------------
Begin Snap:       9971 26-Jul-12 13:32:58      275     101.3
  End Snap:       9981 26-Jul-12 14:03:03      279     100.6
   Elapsed:               30.08 (mins)

Cache Sizes                       Begin        End
~~~~~~~~~~~                  ---------- ----------
               Buffer Cache:       576M       560M  Std Block Size:         8K
           Shared Pool Size:       560M       576M      Log Buffer:    13,940K

Load Profile                            Per Second       Per Transaction
~~~~~~~~~~~~                       ---------------       ---------------
                  Redo size:             80,209.18             22,792.44
              Logical reads:             31,788.12              9,032.99
              Block changes:                324.33                 92.16
             Physical reads:              8,772.12              2,492.71
            Physical writes:                419.36                119.17
                 User calls:              1,465.05                416.31
                     Parses:                124.84                 35.47
                Hard parses:                 35.23                 10.01
                      Sorts:                 41.09                 11.68
                     Logons:                  0.11                  0.03
                   Executes:              1,048.82                298.04
               Transactions:                  3.52

  % Blocks changed per Read:    1.02    Recursive Call %:    50.19
 Rollback per transaction %:    0.14       Rows per Sort:   507.38

Instance Efficiency Percentages
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
            Buffer Nowait %:   99.75       Redo NoWait %:  100.00
            Buffer  Hit   %:   73.72    In-memory Sort %:   99.90
            Library Hit   %:   92.70        Soft Parse %:   71.78
         Execute to Parse %:   88.10         Latch Hit %:   99.88
Parse CPU to Parse Elapsd %:   93.63     % Non-Parse CPU:   88.03

 Shared Pool Statistics        Begin   End
                               ------  ------
             Memory Usage %:   43.97   46.25
    % SQL with executions>1:   69.16   78.65
  % Memory for SQL w/exec>1:   68.97   78.79

Top 5 Timed Events                                                    Avg %Total
~~~~~~~~~~~~~~~~~~                                                   wait   Call
Event                                            Waits    Time (s)   (ms)   Time
----------------------------------------- ------------ ----------- ------ ------
CPU time                                                     2,886          61.9
direct path sync                                 4,069         482    119   10.3
db file sequential read                      1,918,966         406      0    8.7
db file scattered read                       2,219,525         405      0    8.7
direct path write temp                          89,011         185      2    4.0
          -------------------------------------------------------------
^LHost CPU  (CPUs: 4)
~~~~~~~~              Load Average
                      Begin     End      User  System    Idle     WIO     WCPU
                    ------- -------   ------- ------- ------- ------- --------
                       1.52    1.85     31.94   16.78   51.27    4.44   13.90

Instance CPU
~~~~~~~~~~~~
              % of total CPU for Instance:   42.21
              % of busy  CPU for Instance:   86.62
  %DB time waiting for CPU - Resource Mgr:

Memory Statistics                       Begin          End
~~~~~~~~~~~~~~~~~                ------------ ------------
                  Host Mem (MB):     16,384.0     16,384.0
                   SGA use (MB):      1,200.0      1,200.0
                   PGA use (MB):        554.1        558.5
    % Host Mem used for SGA+PGA:         10.7         10.7
          -------------------------------------------------------------

Time Model System Stats  DB/Inst: MESGAL/mesgal  Snaps: 9971-9981
-> Ordered by % of DB time desc, Statistic name

Statistic                                       Time (s) % of DB time
----------------------------------- -------------------- ------------
sql execute elapsed time                         3,046.9         83.5
DB CPU                                           3,023.2         82.9
parse time elapsed                                 364.4         10.0
hard parse elapsed time                            335.6          9.2
sequence load elapsed time                           3.8           .1
PL/SQL execution elapsed time                        1.5           .0
connection management call elapsed                   1.4           .0
hard parse (sharing criteria) elaps                  1.3           .0
hard parse (bind mismatch) elapsed                   1.3           .0
PL/SQL compilation elapsed time                      0.3           .0
repeated bind elapsed time                           0.1           .0
DB time                                          3,648.1
background elapsed time                            154.1
background cpu time                                 24.9
          -------------------------------------------------------------
^LWait Events  DB/Inst: MESGAL/mesgal  Snaps: 9971-9981
-> s - second, cs - centisecond,  ms - millisecond, us - microsecond
-> %Timeouts:  value of 0 indicates value was < .5%.  Value of null is truly 0
-> Only events with Total Wait Time (s) >= .001 are shown
-> ordered by Total Wait Time desc, Waits desc (idle events last)


                                                                    Avg
                                                %Time Total Wait   wait    Waits
Event                                    Waits  -outs   Time (s)   (ms)     /txn
--------------------------------- ------------ ------ ---------- ------ --------
direct path sync                         4,069      0        482    119      0.6
db file sequential read              1,918,966      0        406      0    302.1
db file scattered read               2,219,525      0        405      0    349.4
direct path write temp                  89,011      0        185      2     14.0
ARCH wait on SENDREQ                        69      0        106   1533      0.0
log file sync                           10,701      0         51      5      1.7
log file parallel write                 10,889      0         43      4      1.7
read by other session                  143,454      0         32      0     22.6
direct path read temp                  102,016      0         30      0     16.1
direct path read                         4,597      0         10      2      0.7
SQL*Net more data to client            192,119      0          6      0     30.2
direct path write                        3,866      0          5      1      0.6
db file parallel read                      903      0          3      4      0.1
control file parallel write                888      0          3      3      0.1
latch: shared pool                       1,789      0          2      1      0.3
log file sequential read                   153      0          1      8      0.0
latch: library cache                       467      0          1      2      0.1
os thread startup                            7      0          1     77      0.0
control file sequential read            15,891      0          1      0      2.5
SGA: MMAN sleep for component shr          209      3          0      2      0.0
latch: session allocation                  253      0          0      1      0.0
latch free                                 322      0          0      1      0.1
latch: cache buffers chains              1,690      0          0      0      0.3
enq: TX - row lock contention                1      0          0    248      0.0
latch: cache buffers lru chain             124      0          0      2      0.0
enq: HW - contention                        10      0          0     13      0.0
buffer busy waits                           30      0          0      4      0.0
latch: library cache lock                   58      0          0      2      0.0
latch: row cache objects                    34      0          0      2      0.0
library cache load lock                      2      0          0     22      0.0
buffer exterminate                           3     67          0     12      0.0
cursor: pin S wait on X                      2    100          0     16      0.0
...
...
                                                                    Avg
                                                %Time Total Wait   wait    Waits
Event                                    Waits  -outs   Time (s)   (ms)     /txn
--------------------------------- ------------ ------ ---------- ------ --------
ARCH wait on SENDREQ                        61      0         90   1480      0.0
log file parallel write                 10,889      0         43      4      1.7
control file parallel write                889      0          3      4      0.1
log file sequential read                   153      0          1      8      0.0
os thread startup                            7      0          1     77      0.0
SGA: MMAN sleep for component shr          209      3          0      2      0.0
control file sequential read             6,404      0          0      0      1.0
db file sequential read                  2,671      0          0      0      0.4
events in waitclass Other                  175      0          0      0      0.0
log file single write                        4      0          0      4      0.0
db file scattered read                      90      0          0      0      0.0
direct path write                           19      0          0      0      0.0
Log archive I/O                            144      0          0      0      0.0
latch: shared pool                           6      0          0      0      0.0
rdbms ipc message                       16,700     34     19,183   1149      2.6
pmon timer                                 599    100      1,760   2938      0.1
smon timer                                   6    100      1,758 ######      0.0
Streams AQ: qmn slave idle wait             64      0      1,751  27353      0.0
Streams AQ: qmn coordinator idle           174     37      1,751  10061      0.0
          -------------------------------------------------------------
..
...
...
> SQL reported below exceeded  1.0% of Total DB CPU

    CPU                  CPU per             Elapsd                     Old
  Time (s)   Executions  Exec (s)  %Total   Time (s)    Buffer Gets  Hash Value
---------- ------------ ---------- ------ ---------- --------------- ----------
    263.60           46       5.73    8.7     286.99       2,715,310 1933345649
SELECT Container.ContainerId ,Container.ContainerName  as "Conta
iner",ContainerLevel.ContainerLevelName  as "Level",WorkflowStep
.WorkflowStepName  as "Step",PriorityCode.PriorityCodeName  as "
Priority",Product.ProductName AS "Product",Product.ProductRevisi
on AS "Revision",Container.Qty ,Operation.OperationName  as "Ope

    190.32        1,112       0.17    6.3     214.36          70,910 2267369128
INSERT INTO MESGALX.DataStoreInserts2 (TxnID, TxnType, Sequence,
 SqlStmt) VALUES (:V1, :V2, :V3, :V4)

    188.82        1,116       0.17    6.2     215.47          70,398 1533742463
INSERT INTO MESGALX.DataStoreInserts1 (TxnID, TxnType, Sequence,
 SqlStmt) VALUES (:V1, :V2, :V3, :V4)

     73.47        2,211       0.03    2.4      84.78          62,009 3886788168
INSERT INTO MESGALX.DataStoreUpdates (TxnID, TxnType, Sequence,
SqlStmt) VALUES (:V1, :V2, :V3, :V4)

     55.89            1      55.89    1.8     106.30         775,352 2538744661
Module: fcproc.exe
SELECT DISTINCT    Container.ContainerName,    HistoryMainline.T
XNDATE,    TranProductBase.ProductName,    TranProduct.DESCRIPTI
ON,    BSCPRODUCTINFOTrans.DESCRIPTION,    MfgOrder.MFGORDERNAME
,    DHRRESOURCES.RESOURCENAME,    DHRRESOURCES.RESOURCEDESCRIPT
ION,    TASKDATAHISTORYSUMMARY.BSCSTATIONNAME  FROM    ProductBa

     50.56           52       0.97    1.7      57.01         157,362 2344813299
SELECT  ProductBase.ProductName , Product.ProductRevision , Prod
uctBase.RevOfRcdId ,          Product.IsFrozen , Product.Product
Id , Product.Description ,          Product.Status  FROM    Prod
uct , ProductBase WHERE   Product.ProductBaseId = ProductBase.Pr
oductBaseId AND     (Product.CDOTypeId = 1580 or 0 <> 1)  AND