Database is 11.2.0.3 running on Solaris SVR40-be-64bit 8.1.0, 32 CPU's.
The database is used by many connected libraries, to check books in and out, query for overdues etc.
On busy days, performance seems to be all over the map, some areas reporting 40 seconds for a form to update, some areas < 2 seconds. The transactions that seem to cause the bottlenecks seem to be queries checking if a patron has overdues, fines etc.
I've been tasked to try and find where the bottlenecks are, and find out if the long delays are caused by server contention, application code, network & internet issues, or within the database itself.
The server is a Solaris M5000 with about 16 other Oracle databases, 128GB RAM
I have run ADDM reports, trying to catch busy periods. One recommendation was increase the SGA size, which was at 1.8Gb to 2.5, so on the next database bounce SGA was increased to 3GB and AMM was implemented, but the SGA never seems to get above 1.9GB in size.
Here is a snapshot from instance viewer on a typical busy day.
Below is the output from ADDM for the hour immediately preceding the above.
================================================================================
ADDM Report for Task 'report feb 7'
-----------------------------------
Analysis Period
---------------
AWR snapshot range from 34564 to 34565.
Time period starts at 07-FEB-17 08.00.56 AM
Time period ends at 07-FEB-17 09.00.58 AM
Analysis Target
---------------
Database 'xxxx' with DB ID 2322079177.
Database version 11.2.0.3.0.
Analysis was requested for all instances, but ADDM analyzed instance SYMP,
numbered 1 and hosted at xxxx.
See the "Additional Information" section for more information on the requested
instances.
Activity During the Analysis Period
-----------------------------------
Total database time was 1931 seconds.
The average number of active sessions was .54.
ADDM analyzed 1 of the requested 1 instances.
Summary of Findings
-------------------
Description Active Sessions Recommendations
Percent of Activity
---------------------------------------- ------------------- ---------------
1 Virtual Memory Paging .54 | 100 1
2 Top SQL Statements .23 | 43.14 6
3 "User I/O" wait Class .23 | 43.06 0
4 Top Segments by "User I/O" and "Cluster" .14 | 26.16 5
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Findings and Recommendations
----------------------------
Finding 1: Virtual Memory Paging
Impact is .54 active sessions, 100% of total activity.
------------------------------------------------------
Significant virtual memory paging was detected on the host operating system.
Recommendation 1: Host Configuration
Estimated benefit is .54 active sessions, 100% of total activity.
-----------------------------------------------------------------
Action
Host operating system was experiencing significant paging but no
particular root cause could be detected. Investigate processes that do
not belong to this instance running on the host that are consuming
significant amount of virtual memory. Also consider adding more physical
memory to the host.
Finding 2: Top SQL Statements
Impact is .23 active sessions, 43.14% of total activity.
--------------------------------------------------------
SQL statements consuming significant database time were found. These
statements offer a good opportunity for performance improvement.
Recommendation 1: SQL Tuning
Estimated benefit is .07 active sessions, 12.42% of total activity.
-------------------------------------------------------------------
Action
Run SQL Tuning Advisor on the SELECT statement with SQL_ID
"2zky76mt3dtnz".
Related Object
SQL statement with SQL_ID 2zky76mt3dtnz.
select /*+ INDEX(item item_key) */ item.*, rowid from item where
catalog_key = :1 and call_sequence = :2 and copy_number = :3
Rationale
The SQL spent 100% of its database time on CPU, I/O and Cluster waits.
This part of database time may be improved by the SQL Tuning Advisor.
Rationale
Database time for this SQL was divided as follows: 100% for SQL
execution, 0% for parsing, 0% for PL/SQL execution and 0% for Java
execution.
Rationale
SQL statement with SQL_ID "2zky76mt3dtnz" was executed 1937344 times and
had an average elapsed time of 0.00012 seconds.
Rationale
I/O and Cluster wait for TABLE "SIRSI.ITEM" with object ID 59004
consumed 47% of the database time spent on this SQL statement.
Recommendation 2: SQL Tuning
Estimated benefit is .06 active sessions, 11.76% of total activity.
-------------------------------------------------------------------
Action
Run SQL Tuning Advisor on the SELECT statement with SQL_ID
"6khb1xv7us4r1".
Related Object
SQL statement with SQL_ID 6khb1xv7us4r1.
select /*+ INDEX(marc0 marc0_key) */ marc0.*, rowid from marc0 where
marc = :1
Rationale
The SQL spent 100% of its database time on CPU, I/O and Cluster waits.
This part of database time may be improved by the SQL Tuning Advisor.
Rationale
Database time for this SQL was divided as follows: 100% for SQL
execution, 0% for parsing, 0% for PL/SQL execution and 0% for Java
execution.
Rationale
SQL statement with SQL_ID "6khb1xv7us4r1" was executed 26069 times and
had an average elapsed time of 0.0066 seconds.
Rationale
I/O and Cluster wait for TABLE "SIRSI.MARC0" with object ID 59022
consumed 61% of the database time spent on this SQL statement.
Rationale
I/O and Cluster wait for INDEX "SIRSI.MARC0_KEY" with object ID 59023
consumed 33% of the database time spent on this SQL statement.
Recommendation 3: SQL Tuning
Estimated benefit is .04 active sessions, 6.54% of total activity.
------------------------------------------------------------------
Action
Run SQL Tuning Advisor on the SELECT statement with SQL_ID
"5gr56zs9taqs6".
Related Object
SQL statement with SQL_ID 5gr56zs9taqs6.
select
REDO_SIZE.value as REDO_SIZE
,REDO_WASTAGE.value as REDO_WASTAGE
,REDO_ENTRIES.value as REDO_ENTRIES
,REDO_BLOCKS_WRITTEN.value as REDO_BLOCKS_WRITTEN
,REDO_BLOCKS_CHECKSUMMED.value as REDO_BLOCKS_CHECKSUMMED
,REDO_WRITES.value as REDO_WRITES
,REDO_LOG_SPACE_REQUESTS.value as REDO_LOG_SPACE_REQUESTS
,REDO_BUFFER_ALLOC_RETRIES.value as REDO_BUFFER_ALLOC_RETRIES
,REDO_WRITE_TIME.value as REDO_WRITE_TIME
,REDO_KB_READ.value as REDO_KB_READ
,REDO_SYNCH_WRITES.value as REDO_SYNCH_WRITES
,REDO_BLKS_RD_FOR_RECOVERY.value as REDO_BLKS_RD_FOR_RECOVERY
,REDO_SYNCH_TIME.value as REDO_SYNCH_TIME
,REDO_K_BS_READ_FOR_RECOVERY.value as REDO_K_BS_READ_FOR_RECOVERY
,REDO_SIZE_FOR_DIRECT_WRITES.value as REDO_SIZE_FOR_DIRECT_WRITES
,REDO_LOG_SPACE_WAIT_TIME.value as REDO_LOG_SPACE_WAIT_TIME
,REDO_ORDERING_MARKS.value as REDO_ORDERING_MARKS
from
(select min(value) as value from v$sysstat where name = 'redo size')
REDO_SIZE
,(select min(value) as value from v$sysstat where name = 'redo
wastage') REDO_WASTAGE
,(select min(value) as value from v$sysstat where name = 'redo
entries') REDO_ENTRIES
,(select min(value) as value from v$sysstat where name = 'redo blocks
written') REDO_BLOCKS_WRITTEN
,(select min(value) as value from v$sysstat where name = 'redo blocks
checksummed by FG (exclusive)') REDO_BLOCKS_CHECKSUMMED
,(select min(value) as value from v$sysstat where name = 'redo
writes') REDO_WRITES
,(select min(value) as value from v$sysstat where name = 'redo log
space requests') REDO_LOG_SPACE_REQUESTS
,(select min(value) as value from v$sysstat where name = 'redo buffer
allocation retries') REDO_BUFFER_ALLOC_RETRIES
,(select min(value) as value from v$sysstat where name = 'redo write
time') REDO_WRITE_TIME
,(select min(value) as value from v$sysstat where name = 'redo KB
read') REDO_KB_READ
,(select min(value) as value from v$sysstat where name = 'redo synch
writes') REDO_SYNCH_WRITES
,(select min(value) as value from v$sysstat where name = 'redo blocks
read for recovery') REDO_BLKS_RD_FOR_RECOVERY
,(select min(value) as value from v$sysstat where name = 'redo synch
time') REDO_SYNCH_TIME
,(select min(value) as value from v$sysstat where name = 'redo
k-bytes read for recovery') REDO_K_BS_READ_FOR_RECOVERY
,(select min(value) as value from v$sysstat where name = 'redo size
for direct writes') REDO_SIZE_FOR_DIRECT_WRITES
,(select min(value) as value from v$sysstat where name = 'redo log
space wait time') REDO_LOG_SPACE_WAIT_TIME
,(select min(value) as value from v$sysstat where name = 'redo
ordering marks') REDO_ORDERING_MARKS
Rationale
The SQL spent 100% of its database time on CPU, I/O and Cluster waits.
This part of database time may be improved by the SQL Tuning Advisor.
Rationale
Database time for this SQL was divided as follows: 100% for SQL
execution, 0% for parsing, 0% for PL/SQL execution and 0% for Java
execution.
Rationale
SQL statement with SQL_ID "5gr56zs9taqs6" was executed 696 times and had
an average elapsed time of 0.17 seconds.
Recommendation 4: SQL Tuning
Estimated benefit is .03 active sessions, 5.88% of total activity.
------------------------------------------------------------------
Action
Run SQL Tuning Advisor on the SELECT statement with SQL_ID
"b2sy91m0k196m".
Related Object
SQL statement with SQL_ID b2sy91m0k196m.
select /*+ INDEX(callnum call_key) */ callnum.*, rowid from callnum
where catalog_key = :1 and call_sequence = :2
Rationale
The SQL spent 100% of its database time on CPU, I/O and Cluster waits.
This part of database time may be improved by the SQL Tuning Advisor.
Rationale
Database time for this SQL was divided as follows: 100% for SQL
execution, 0% for parsing, 0% for PL/SQL execution and 0% for Java
execution.
Rationale
SQL statement with SQL_ID "b2sy91m0k196m" was executed 63735 times and
had an average elapsed time of 0.001 seconds.
Rationale
I/O and Cluster wait for TABLE "SIRSI.CALLNUM" with object ID 58825
consumed 55% of the database time spent on this SQL statement.
Recommendation 5: SQL Tuning
Estimated benefit is .02 active sessions, 3.27% of total activity.
------------------------------------------------------------------
Action
Run SQL Tuning Advisor on the SELECT statement with SQL_ID
"9ajkb4xnr8czq".
Related Object
SQL statement with SQL_ID 9ajkb4xnr8czq.
select /*+ INDEX(ucat ucat_key) */ ucat.*, rowid from ucat where
user_key > :1
Rationale
The SQL spent 100% of its database time on CPU, I/O and Cluster waits.
This part of database time may be improved by the SQL Tuning Advisor.
Rationale
Database time for this SQL was divided as follows: 100% for SQL
execution, 0% for parsing, 0% for PL/SQL execution and 0% for Java
execution.
Rationale
SQL statement with SQL_ID "9ajkb4xnr8czq" was executed 1253012 times and
had an average elapsed time of 0.000042 seconds.
Recommendation 6: SQL Tuning
Estimated benefit is .02 active sessions, 3.27% of total activity.
------------------------------------------------------------------
Action
Run SQL Tuning Advisor on the SELECT statement with SQL_ID
"gxvqh9vbhvk4m".
Related Object
SQL statement with SQL_ID gxvqh9vbhvk4m.
select /*+ INDEX(item item_id) */ item.*, rowid from item where id =
:1
Rationale
The SQL spent 100% of its database time on CPU, I/O and Cluster waits.
This part of database time may be improved by the SQL Tuning Advisor.
Rationale
Database time for this SQL was divided as follows: 100% for SQL
execution, 0% for parsing, 0% for PL/SQL execution and 0% for Java
execution.
Rationale
SQL statement with SQL_ID "gxvqh9vbhvk4m" was executed 13083 times and
had an average elapsed time of 0.0024 seconds.
Rationale
I/O and Cluster wait for INDEX "SIRSI.ITEM_ID" with object ID 59315
consumed 100% of the database time spent on this SQL statement.
Finding 3: "User I/O" wait Class
Impact is .23 active sessions, 43.06% of total activity.
--------------------------------------------------------
Wait class "User I/O" was consuming significant database time.
The throughput of the I/O subsystem was not significantly lower than expected.
The Oracle instance memory (SGA and PGA) was adequately sized.
No recommendations are available.
Finding 4: Top Segments by "User I/O" and "Cluster"
Impact is .14 active sessions, 26.16% of total activity.
--------------------------------------------------------
Individual database segments responsible for significant "User I/O" and
"Cluster" waits were found.
Recommendation 1: Segment Tuning
Estimated benefit is .04 active sessions, 8.18% of total activity.
------------------------------------------------------------------
Action
Investigate application logic involving I/O on TABLE "SIRSI.ITEM" with
object ID 59004.
Related Object
Database object with ID 59004.
Action
Look at the "Top SQL Statements" finding for SQL statements consuming
significant I/O on this segment. For example, the SELECT statement with
SQL_ID "2zky76mt3dtnz" is responsible for 71% of "User I/O" and
"Cluster" waits for this segment.
Rationale
The I/O usage statistics for the object are: 0 full object scans, 32617
physical reads, 2870 physical writes and 0 direct reads.
Recommendation 2: Segment Tuning
Estimated benefit is .03 active sessions, 6% of total activity.
---------------------------------------------------------------
Action
Investigate application logic involving I/O on TABLE "SIRSI.CALLNUM"
with object ID 58825.
Related Object
Database object with ID 58825.
Action
Look at the "Top SQL Statements" finding for SQL statements consuming
significant I/O on this segment. For example, the SELECT statement with
SQL_ID "b2sy91m0k196m" is responsible for 54% of "User I/O" and
"Cluster" waits for this segment.
Rationale
The I/O usage statistics for the object are: 0 full object scans, 18214
physical reads, 2837 physical writes and 0 direct reads.
Recommendation 3: Segment Tuning
Estimated benefit is .03 active sessions, 6% of total activity.
---------------------------------------------------------------
Action
Investigate application logic involving I/O on TABLE "SIRSI.MARC0" with
object ID 59022.
Related Object
Database object with ID 59022.
Action
Look at the "Top SQL Statements" finding for SQL statements consuming
significant I/O on this segment. For example, the SELECT statement with
SQL_ID "6khb1xv7us4r1" is responsible for 100% of "User I/O" and
"Cluster" waits for this segment.
Rationale
The I/O usage statistics for the object are: 0 full object scans, 13053
physical reads, 6 physical writes and 0 direct reads.
Recommendation 4: Segment Tuning
Estimated benefit is .02 active sessions, 3.27% of total activity.
------------------------------------------------------------------
Action
Investigate application logic involving I/O on INDEX "SIRSI.MARC0_KEY"
with object ID 59023.
Related Object
Database object with ID 59023.
Action
Look at the "Top SQL Statements" finding for SQL statements consuming
significant I/O on this segment. For example, the SELECT statement with
SQL_ID "6khb1xv7us4r1" is responsible for 100% of "User I/O" and
"Cluster" waits for this segment.
Rationale
The I/O usage statistics for the object are: 0 full object scans, 5984
physical reads, 2 physical writes and 0 direct reads.
Recommendation 5: Segment Tuning
Estimated benefit is .01 active sessions, 2.73% of total activity.
------------------------------------------------------------------
Action
Investigate application logic involving I/O on INDEX "SIRSI.ITEM_ID"
with object ID 59315.
Related Object
Database object with ID 59315.
Action
Look at the "Top SQL Statements" finding for SQL statements consuming
significant I/O on this segment. For example, the SELECT statement with
SQL_ID "gxvqh9vbhvk4m" is responsible for 100% of "User I/O" and
"Cluster" waits for this segment.
Rationale
The I/O usage statistics for the object are: 0 full object scans, 2976
physical reads, 35 physical writes and 0 direct reads.
Symptoms That Led to the Finding:
---------------------------------
Wait class "User I/O" was consuming significant database time.
Impact is .23 active sessions, 43.06% of total activity.
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Additional Information
----------------------
Miscellaneous Information
-------------------------
Wait class "Application" was not consuming significant database time.
Wait class "Commit" was not consuming significant database time.
Wait class "Concurrency" was not consuming significant database time.
Wait class "Configuration" was not consuming significant database time.
CPU was not a bottleneck for the instance.
Wait class "Network" was not consuming significant database time.
Session connect and disconnect calls were not consuming significant database
time.
Hard parsing of SQL statements was not consuming significant database time.
======================================================================================
The same or similar queries seem to come up in all of these reports. When I run the SQL from a sqlplus prompt they run instantly.
I notice that logical reads are consistently high, there is a lot of IO in the database and that the temp tablespace in this database is pretty well unused.
Talking to the application administrator here she said that sometimes it seems to be just certain geographical areas reporting issues, but is unable to say if that's just coincidence or if some areas just don't report slowness or use the application during these times.
I notices all the queries reported in ADDM use index hints, and like I said the queries run very fast from a sql prompt.
I am wondering if it is application code that is queuing up reports and queries that are causing the delay, internet issues, database waits or a combination of all - but I would like to be able to point out where the problem "most likely" is coming from.
What and where else should I be looking for? Next steps?
thanks in advance.
(note: the SQL in sql 5gr56zs9taqs6 regarding redo is not usually in the ADDM report)