Blog

Database IO Performance Troubleshooting

We often stumble upon database performance issues and we soon jump into AWR report to check if any of the top wait events are slowing down the system.

To our surprise we see something like below. The top wait event is the DB file sequential read which says that the most of the waits are due to index access.

                                  Top 5 Timed Foreground Events

Now, what are the various index access that optimizer can choose:

• Index Unique Scan
• Index Range Scan
• Index Full Scan
• Index Fast Full Scan

So, our immediate guess is “Index Full Scan” if there are unusual increase in amount of wait on DB file sequential read in AWR report. Now, we need to see if any of the query plans have changed and are causing this high amount of index read. The index full scan are single block IO and would impact the query performance.

We will take the top IO query’s SQL_ID and check if their execution plan has changed recently. Use the below query to verify the same.

SELECT sql_id, plan_hash_value, timestamp

FROM dba_hist_sql_pan

WHERE sql_id in (‘<sql_id1>’,’<sql_id2>’);

If there is a new plan hash value present on a recent date, that means that there is a change in the execution plan. Then our troubleshooting is easy and straight forward. We need to compare the older and the current (CURSOR) plan and correct the execution plan either by gathering the statistics or using SQL plan baselines. The quickest fix is to use the baseline. Please evaluate the baseline option as it has its own advantages and disadvantages.

In this case, we did not find any change in the execution plan, now what next? Started comparing the elapsed time of the queries with past AWR report and found that the elapsed time has increased by 3 times for some of the queries. This system was a OLTP system and the number of queries executed as high as ~5M executions in 60 minutes. Elapsed time of this query was about 0.01 seconds when the system was performing optimally. Now, the elapsed time has increased to 0.03 seconds per execution and was slowing down the transactions.

So, it was evident that there is some issue with IO sub system. So, drilling down to disk IO was required. Below is the “iostat -D 5 50” output and some of the disks are consistently having more than 50ms service time. For OLTP systems, the average service time should be less than 10ms.

The highlighted  report shows very high service time for some of the disks. It was evident that there was IO issue from storage. Further investigation on storage lead to some multi path errors. Post upgrading storage software the IO response time improved and automatically reduced the query elapsed time.

There are several other factors that cause the IO bottleneck such as:

• High number of disk sorts
• Conventional Data loads on indexed table
• Increase in height of index
• Export/RMAN Backup

So, it is important to look from all angles of database before zeroing down on to the route cause.

Troubleshooting a Batch Job on Oracle Database

Troubleshooting a Batch Job on Oracle Database

The customer reported us problem of a batch job taking 3x more time than its normal execution time. The batch contains mainly data loading using SQLLDR and then a set of 20-25 queries on a set of 2-3 tables. The queries are more of FTS in nature.

Our application team approached us saying that queries are taking 4-6 hours instead of completing in an hour.  They sent me the AWR report showing the queries running for long and wanted me find out the problem SQL. Below is the AWR report showing the queries running for long.

AWR Report of 8 hours period

The above AWR was taken for the 8 hour window and hence I could not make out what was happening from the beginning of the batch job. So I generated the reports for every one hour from the beginning to end of the batch job execution.  We had OS level statistics such as iostat, vmstat and prstat utility output.

Looking at the first few reports I found out that the data loading had taken up the first 3 hours of time. Ideally this should have been completed in 45 minutes (Timing from the past run). When looked into AWR report the DB was waiting for “Log file sync” wait event.  I needed to conclude now if the commit or slow IO is causing the log file synch wait at the DB.  So, I first checked the vmstat and iostat outputs, both were showing IO waits. Below is the snippet of the AWR top waits, vmstat and sar output.

AWR Top 5 Wait Events

Sar –d Output

The “b” column of the vmstat output indicates that the some processes are blocked for the IO operation.  In order to confirm if the device where redo are placed is slow I had to check the iostat report. But the problem with iostat report is that it provides only the device name. We had to map the device name to the mount point name using the command “pvdisplay -l /dev/dsk/c2t0d0”. Below is the iostat output, the highlighted is the mount point where the redo logs were placed. The highlighted line shows very high average service time and also 100% busy.  This shows that the disk where the redo logs were placed was slow and causing the “Log file sync” DB wait.

Vmstat output

I could confirm the redo log taking time to write data by looking at the following section in AWR report. Typically this should have been less than 20ms.

We had other factors which were also impacting data loads such RMAN backup and a slow mount point where the data file was placed. RMAN was also consuming certain amount IO and CPU and was slowing down the data load.

AWR Top 5 Wait Events

The next step was to examine the queries. The queries were run from 3^rd hour of start of batch job execution and lasted till 8^th hour.

I looked at the hourly AWR report from 3^rd hour and found that most of the queries had executed but were still running because the batch job was spooling to a file.  The query output was in the range of 25-40M rows and that is the reason for taking huge spooling time.  This is the classic example of query being executed but run for long time just because the output was spooled by the Java based application. Below are the various examples showing query execution being completed but elapsed for more than 2 hours.

AWR Report for 1 Hour Period 

It was the same disk where both SQLLDR data file and the spool output file was placed.  The LUN from where this disk was presented was exhausted the IO bandwidth and hence it was impacting the spooling.

We presented my analysis to the customer but customer point was why the IO issue now when there was no change from DB, App Server and Storage. We asked the customer’s storage engineer to check the IO reports and it was evident from the storage level IO report of IO bandwidth was saturated.

On further analysis it was learnt that the customer had moved some application from another Data Centre and that application was allocated storage on the same SAN storage where our application was allocated the storage. The new application was sucking huge amount of IO and that was impacting the batch job.

OLTP Oracle Database Performance Tuning

Performance Trouble Shooting of OLTP Oracle Database

Background About The System:

Little bit of back ground on the processing logic of the system here. The system processes events that are generated for every end user activity in the system. In a typical system there will be 20-30 million users and they generate at least 5-10 events per day.  The total number of events that the system needs to process in a day is anything between 300 to 350 million events. That means around 4000 events/sec when distributed equally over 24 hours.

Read More “OLTP Oracle Database Performance Tuning”