Skip to Main Content

Oracle Database Discussions

Announcement

For appeals, questions and feedback about Oracle Forums, please email oracle-forums-moderators_us@oracle.com. Technical questions should be asked in the appropriate category. Thank you!

Interested in getting your voice heard by members of the Developer Marketing team at Oracle? Check out this post for AppDev or this post for AI focus group information.

finding a performance bottleneck

GlenStromFeb 7 2017 — edited Feb 23 2017

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.

symp1.JPG

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)

Comments

Processing
Locked Post
New comments cannot be posted to this locked post.

Post Details

Locked on Mar 23 2017
Added on Feb 7 2017
25 comments
5,148 views