Skip to Main Content

Oracle Database Discussions

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
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
3,813 views