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

Event Waits Time(S) Avg wait(ms) % DB time Wait class
db file sequential  read 21,407,957 240,686 11 81.24 User I/O
DB CPU   30,996   10.46  
Control file sequential read 1,643,451 2,186 1 0.74 System I/O
SQL*Net more data to client 16,900,143 2,162 0 0.73 Network
Direct path read 70,251 1,719 24 0.58 User I/O

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.

Hdisk177     xfer:   %tm_act        bps                tps         bread        bwetn

84.0            3.5M           142.3      3.0M         507.9k

Read:       rps            avgserv         minserv   maxserv   timeout      fail

117                  23.5                 0.3            1.6S              0         0

Write:      wps          avgserv         minserv   maxserv   timeout      fail

24.6           52.7               0.5             1.3S            0              0

Queue:     avgtime      mintime         maxtime     avgwqsz    avgsqsz     sqlful

2.2            0.0                133.3          0.0              5.0            10.3

Hdisk173      xfer:    %tm_act          bps             tps         bread        bwetn

66.0              2.9M            125.0       2.5M        316.0

Read:       rps            avgserv         minserv   maxserv   timeout      fail

107.0             15.8                    0.3          650.3        0           0

Write:      wps          avgserv         minserv   maxserv   timeout      fail

18.0           39.6                 0.6        231.7            0               0

Queue:     avgtime      mintime         maxtime     avgwqsz    avgsqsz   sqlful

1.5                0.0                 156.4          0.0              2.0           2.3

Hdisk178      xfer:    %tm_act          bps             tps         bread        bwetn

69.8                3.6M        130.9      3.1M         414.3K

Read:       rps            avgserv         minserv   maxserv   timeout      fail

110.7                 13.7              0.3        483.5             0             0

Write:      wps          avgserv         minserv   maxserv   timeout      fail

20.1          42.2                 1.1           150.9             0              0

Queue:     avgtime      mintime         maxtime     avgwqsz    avgsqsz   sqlful

0.7               0.0                    111.3           0.0               2.0       1.4

Hdisk179      xfer:    %tm_act          bps             tps         bread        bwetn

68.1            3.2M           131.3      2.8M         423.6K

Read:       rps            avgserv         minserv   maxserv   timeout      fail

109.3          15.4               0.2           429.6           0               0

Write:      wps          avgserv         minserv   maxserv   timeout      fail

22.0            46.5               0.6           147.4             0            0

Queue:     avgtime      mintime         maxtime     avgwqsz    avgsqsz   sqlful

1.2                0.0                   124.9           0.0            3.0          2.4

 

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.

Password file authentication

PASSWORD FILE  (Remote authentication using PASSWORD FILE)

 

Set the environment variables i.e.

export ORACLE_BASE=/u01/app/oracle

export ORACLE_HOME=$ORACLE_BASE/product/11.2.0/dbhome_1

export PATH=$PATH:$ORACLE_HOME/bin

export ORACLE_SID=<your database sid>

 

sqlplus / as sysdba

 

  1. Create a new user as below

create user  <username>  identified by  <password>;

  1. grant sysdba to <USERNAME>;

 

Repeat the step 1 and 2 until you receive an error as ‘PASSWORD FILE FULL’

I step

create the password file as below

orapwd file=$ORACLE_HOME/dbs/orapw<db_name> entires=<number bigger than earlier> force=y

All the users with SYSDBA privilege you can find in the view called v$pwfile_users

  1. connect to the database AS SYSDBA
  2. say

SQL>show parameter remote;

NAME                                                          TYPE                         VALUE

Remote_dependencies_mode                String                     TIMESTAMP

Remote_listener                                        String

Remote_login_passwordfile                   String                       EXCLUSIVE

 

  1. if remote_login_passwordfile=EXCLUSIVE THEN

a.CREATE USER1 IDENTIFIED BY USER1;

  1. GRANT SYSDBA TO USER1;
  2. same as step a and b with different users until you get an error.
  3. Once you get the error, which means you want to add more users than expected earlier then,

your password file needs to be recreated as it has lasted maximum no. of sysdba connections

specified using parameter ‘entries’ in ‘orapwd’ utility;

  1. You will have to recreate password file with more no. of entries using below command.

 

At command prompt –

orapwd file=$ORACLE_HOME/dbs/orapw<dbname> entries=<number bigger than earlier> force=y

This will prompt for sys user password

Enter the password

 

Now regrant sysdba privilage to all the existing user and to the new user too.

 

 

II step

 

change the value in init.ora for remote_login_passwordfile=NONE

This behaves as if password file doesn’t exist on the db i.e. no remote sysdba authentication is possible.

 

shutdown and startup db using pfile=<path> option.

now try to create some user and give sysdba privileges and see what happens

 

 

 

Shutdown the DB

  1. change the parameter remote_login_passwordfile=EXCLUSIVE in init.ora
  2. bounce the db using startup pfile=/u01/app/oracle/product/11.2.0/dbs/init<dbname>.ora

CONTROL FILE MANAGEMENT

We have to recreate the control file for the below mentioned reasons.

1  All copies of control files present in database are lost or corrupted.

2 We are restoring a backup in which control file is corrupted or missing.

3 We need to change a hard limit database parameter in the control file.

  1. Generating the trace of the controlfile
    1. Sql>alter database backup controlfile to trace;
    2. Get control file creation script from backup trace file :-
      1. Go to this directory find the trace with the below content. $ORACLE_BASE/diag/rdbms/orcl/orcl/trace/

open the trace file named like _orc_1234.trc. It appears like an ordinary trace file but we are interested in the part having create control file script. Modify the trace file, delete every thing above the “CREATE CONTROLFILE” and after the “CHARACTER SET” option.

2. Shut down your database with immediate option.

SQL> startup nomount;

ORACLE instance started.

Total System Global Area 1025298432 bytes

Fixed Size                  1341000 bytes

Variable Size             322963896 bytes

Database Buffers          696254464 bytes

Redo Buffers                4739072 bytes

3. Startup the database in nomount mode.

SQL> startup nomount;

ORACLE instance started.

Total System Global Area 1025298432 bytes

Fixed Size                  1341000 bytes

Variable Size             322963896 bytes

Database Buffers          696254464 bytes

Redo Buffers                4739072 bytes

4. Take the control file script and use it to create the control file of the database.

SQL> CREATE CONTROLFILE  REUSE DATABASE “ORCL” RESETLOGS  NOARCHIVELOG

MAXLOGFILES 16

MAXLOGMEMBERS 3

MAXDATAFILES 100

MAXINSTANCES 8

MAXLOGHISTORY 292

LOGFILE

GROUP 1 (

‘/u01/oradata/orcl/onlinelog/group_1.log’,

‘/u01/oradata/orcl/onlinelog/group_1.log’

) SIZE 50M BLOCKSIZE 512,

GROUP 2 (

‘/u01/oradata/orcl/onlinelog/group_2.log’,

‘/u01/oradata/orcl/onlinelog/group_2.log’

) SIZE 50M BLOCKSIZE 512,

GROUP 3 (

‘/u01/oradata/orcl/onlinelog/group_3.log’,

‘/u01/oradata/orcl/onlinelog/group_3.log’

) SIZE 50M BLOCKSIZE 512

— STANDBY LOGFILE

DATAFILE

‘/u01/oradata/orcl/datafile/system.dbf’,

‘/u01/oradata/orcl/datafile/sysaux.dbf’,

‘/u01/oradata/orcl/datafile/undotbs1.dbf’,

‘/u01/oradata/orcl/datafile/users.dbf’,

‘/u01/oradata/orcl/datafile/example.dbf’,

‘/u01/oradata/orcl/datafile/amit.dbf’

CHARACTER SET AL32UTF8

;

Control file created.

5. Once the control file successfully created database is automatically mounted.

SQL> select open_mode from v$database;

 

OPEN_MODE

——————–

MOUNTED

 

  1. Once the database is mounted open the database with reset logs option.

 

SQL> alter database open resetlogs;

 

Database altered.

 

We have started the database with resetlogs so it’s important to take a backup immediately.

 

  1. After the database is open add the existing temp file

 

SQL> ALTER TABLESPACE TEMP ADD TEMPFILE ‘/u01/oradata/orcl/tempfile/temp01.dbf’ size 200M REUSE;

 

Tablespace altered.

 

SQL JOINS

Joins are used to retrieve the data from multiple tables.

There are four types of SQL Joins:

1.SQL INNER Join ( called simple join)

2.SQL LEFT Join (called Left Join)

3.SQL RIGHT Join(called right join)

4.SQL FULL Join(called Full join)

 

INNER JOIN : Retrieves all rows from multiple tables where the join condition is met.

 Syntax : select columns

From table1

INNER JOIN table2

ON table1.column=table2.column;

 Example : consider two table

1. employees (emp_id,e_name,dept_id) and     2. department(dept_id,emp_id,join_date)

Employees

Emp_id E_name Dept_id
100 Aadhya 50020
200 Anup 50030
500 Ankit 50050

Deparments

Dept_id Emp_id Join_date
50020 100 2011/01/20
50040 400 2012/03/14
50050 500 2012/05/19

Select e.emp_id,e.e_name ,d.join_date

From employees e

INNER JOIN department d

ON e.emp_id=d.emp_id;

OUTPUT:

Emp_id E_name Join_date
100 Aadhya 2011/01/20
500 Ankit 2012/05/19

2.SQL LEFT OUTER JOIN:

Returns all rows from the left hand table specified in the ON condition and only those rows from the other table where the condition met.

 Syntax : Select columns

From table1

LEFT OUTER JOIN table2

ON table1.column=table2.column;

Example : consider two table

1. employees (emp_id,e_name,dept_id)        2. department(dept_id,emp_id,join_date)

Employees

Emp_id E_name Dept_id
100 Aadhya 50020
200 Anup 50030
500 Ankit 50050

Departments

Dept_id Emp_id Join_date
50020 100 2011/01/20
50040 400 2012/03/14
50050 500 2012/05/19

Select e.emp_id,e.e_name ,d.join_date

From employees e

LEFT OUTER JOIN department d

ON e.emp_id=d.emp_id;

OUTPUT :

Emp_id E_name Join_date
100 Aadhya 2011/01/20
200 Anup <NULL>
500 Ankit 2012/05/19

3.RIGHT OUTER JOIN:

Returns all rows from the right hand table specified in the ON condition and only those rows from the other table where the join condition met.

 Syntax : Select columns

From table1

RIGHT OUTER JOIN table2

ON table1.column=table2.column;

 

 Example : consider two table

1. employees (emp_id,e_name,dept_id)      2. department(dept_id,emp_id,join_date)

Employees

Emp_id E_name Dept_id
100 Aadhya 50020
200 Anup 50030
500 Ankit 50050

Department

Dept_id Emp_id Join_date
50020 100 2011/01/20
50040 400 2012/03/14
50050 500 2012/05/19

Select d.dept_id,e.e_name,d.join_date

From employees e

RIGHT OUTER JOIN department d

ON e.dept_id=d.dept_id;

OUTPUT :

Dept_id E_name Join_date
50020 Aadhya 2011/01/20
50040 <NULL> 2012/03/14
50050 Ankit 2012/05/19

4.SQL FULL OUTER JOIN :

Returns all rows from the left hand table and right hand table with nulls in place where the condition is not met.

 Syntax :  Select columns

From table1

FULL OUTER JOIN table2

ON table1.column=table2.column;

 

 Example : consider two table

1. employees (emp_id,e_name,dept_id)   2.department(dept_id,emp_id,join_date)

Employees

Emp_id E_name Dept_id
100 Aadhya 50020
200 Anup 50030
500 Ankit 50050

Department

Dept_id Emp_id Join_date
50020 100 2011/01/20
50040 400 2012/03/14
50050 500 2012/05/19

Select e.emp_id,e.e_name ,d.join_date

From employees e

FULL OUTER JOIN department d

ON e.emp_id=d.emp_id;

OUTPUT :

Emp_id E_name Join_date
100 Aadhya 2011/01/20
200 Anup <NULL>
400 <NULL> 2012/03/14
500 Ankit 2012/05/19

 

 

 

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

Elapsed Time (s) CPU Time (s) Executions Elap per Exec (s) % Total DB Time SQL Id SQL Module SQL Text
44,871 2,149 1 44871.25 12.63 0txpt874y7ftw JDBC Thin Client SELECT DISTINCT mtr.cesi_sim_i…
21,797 20,202 1 21797.28 6.14 b6jbg5fcqzkkp JDBC Thin Client SELECT COUNT( caa.cat_id ), ca…
16,747 681 1 16747.36 4.72 bm0wf6jj3d8yu JDBC Thin Client SELECT DISTINCT COUNT( caa.cat…
11,612 827 1 11612.08 3.27 59d06psb76bt2 JDBC Thin Client SELECT DISTINCT caa.cpk_clu_ce…
11,453 2,695 0 3.22 87j0p1z91vhgq SQL*Plus CREATE TABLE ETA.R_CATALOG_…
10,838 3,990 1 10837.99 3.05 3j24aax576t3q JDBC Thin Client SELECT mer.cesi_sim_imsi, mer….

 

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

Event Waits Time(s) Avg Wait(ms) % Total Call Time Wait Class
log file sync 3,276,150 316,938 97 95 Commit
log file parallel write 9,601 18,585 1,936 5.6 System I/O
RMAN backup & recovery I/O 3,418,459 11,639 3 3.5 System I/O
CPU time 10,666 3.2
rdbms ipc reply 2,712 1,718 634 0.5 Other

Sar –d Output

device   %busy   avque   r+w/s  blks/s  avwait  Avserv
c62t4d2 100.00 0.50 23  1494 0.00 105.51
c63t3d5 100.00 0.51 20 1773    0.01 121.16
c63t4d0 38.92 0.50 23 2299 0.00 106.42
c63t3d5 100.00 0.50 31 3277 0.00 77.73
c62t4d6 100.00 0.50 64 6195 0.00 38.67
c62t2d7 80.20 0.50 22 1206 0.00 109.94
c62t4d2 100.00 0.50 32 1926 0.00 75.1
c63t4d0 100.00 0.50 3 358 0 1419.02
c62t4d7 100.00 0.50 20 2176 0.00 119.15
c62t2d7 100.00 0.50 1 83  0.00 2397.55
c62t4d7 97.20 0.50 4 410 0.00 603.12
c63t0d1 51.70 0.50 0 26 0 6015.15
c63t0d1 89.62 0.50 12 626 0.00 207.88
c62t2d7 76.60 0.56 10 413 0.04 245.51

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

 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
 1 1 10598320 127932 5764 7968032 2702 0 3,659 79457 4,162 15588 31 1 49 19 0
 3 5 10589176 104076 5796 7977540 2961 0 5691 39878 4,754 15443 42 2 40 16 0
 2 6 10591824 67704 5704 7974848 2001 2109 3180 2816 4371 13900 34 2 47 17 0
 5 5 10592088 90484 6072 7982792 1696 1117 3,891 34984 4479 14651 24 3 50 24 0
 5 4 10593412 74124 5868 7980792 2015 1413 7018 75822 5788 18021 40 2 32 25 0
 5 5 10599220 71796 5260 7978036 1678 2,310 11,058 65867 5222 18994 40 3 33 24 0

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.

Event Waits %Time -outs Total Wait Time (s) Avg wait (ms) Waits /txn
log file sync 676,235 99 65,708 97 68.85
log file parallel write 959 3,596 3750 0.1

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

Event Waits Time(s) Avg Wait(ms) % Total Call Time Wait Class
log file sync 61,493 5,810 94 77.9 Commit
RMAN backup & recovery I/O 745,314 2,802 4 37.6 System I/O
CPU time 1,611 21.6

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

I looked at the hourly AWR report from 3rd 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 

Elapsed Time (s) CPU Time (s) Executions Elap per Exec (s) % Total DB Time SQL Id SQL Module SQL Text
6,502 231 1 6501.92 9.01 0txpt874y7ftw JDBC Thin Client SELECT DISTINCT mtr.cesi_sim_i…
5,870 652 1 5869.95 8.13 513wrv8ak6c0t JDBC Thin Client SELECT COUNT( caa.cat_id ), ca…
5,737 480 1 5736.9 7.95 59d06psb76bt2 JDBC Thin Client SELECT DISTINCT caa.cpk_clu_ce…
5,291 4,201 1 5291.47 7.33 b6jbg5fcqzkkp JDBC Thin Client SELECT COUNT( caa.cat_id ), ca…
4,694 394 1 4694.13 6.51 bm0wf6jj3d8yu JDBC Thin Client SELECT DISTINCT COUNT( caa.cat…
3,937 2,801 1 3936.76 5.46 dvf91g0uf6qbc JDBC Thin Client SELECT DISTINCT caa.cpk_clu_ce…
2,255 403 3 751.72 3.13 9181pwqnrss3q JDBC Thin Client SELECT DISTINCT mer.imsi, mer….

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”