Step by Step: How to troubleshoot a slow running query in Oracle

This is a day to day task of a DBA. Someone from application team comes to our desk and simply says a query is running slow. We may question him on many things but ultimately a DBA has to tune the query at the end.

This is also very popular and known question for the DBA's who are attending interviews. This question is simply asked again and again. I have also been asked this question multiple times. After a pause, interviewer simply asks...so suppose a user comes and reports that his query is running slow, what will be your approach to tune this.

There is no absolute or concrete answer to this question because there might be multiple way to tune a slow running query. Everyone can have a different approach.

So here is my approach:

Very first thing we have to find which type of query is running slow. Whether it is SELECT query of DML statements(insert, update, delete and merge).

So first we will see how to tune a SELECT query

Step 1 – Find the SQL_ID of the slow running query

There could be two possibilities:

 1) Query is still running: If the slow query is still running then we can find the sql_id of the query by using v$session view.

SQL>select sql_id

from v$session

where sid = 3089;

Output:

SQL_ID

—————————————————

g0uubmuvk4uax

2)  Query is completed: It might be query is completed but application team got to know it later that the query was slow and it did not finish in its usual time. Since this query is not running right now, we can’t query v$session to get its information.

So for this we use AWR/ASH report. We ask application team that at what time the query was running and for that duration we generate the AWR. In ASH report we find all kind of information regarding the top SQL’s. Basically we see SQL STATISTIS section of the AWR report. In this section there is SQL ORDERED BY ELAPSED TIME which matters most to us. If the query which is reported by application team is present in this section then we note down the sql_id of the query. Otherwise we generate ASH report for that particular time and get the sql_id.

  

Step 2 – Run the SQL Tuning advisor for that SQL_ID

After finding the sql_id we can run sql tuning advisor on this sql_id.

Use below steps to run the sql tuning advisor and display its output:

1. Create tuning task for specific Sql id:

SET SERVEROUTPUT ON

DECLARE

  l_sql_tune_task_id  VARCHAR2(100);

BEGIN

  l_sql_tune_task_id := DBMS_SQLTUNE.create_tuning_task (

                          sql_id      => 'g0uubmuvk4uax',

                          scope       => DBMS_SQLTUNE.scope_comprehensive,

                          time_limit  => 60,

                          task_name   => 'g0uubmuvk4uax_tuning_task',

                          description => 'Tuning task for statement g0uubmuvk4uax.');

  DBMS_OUTPUT.put_line('l_sql_tune_task_id: ' || l_sql_tune_task_id);

END;

/

2. Execute the tuning task:

EXEC DBMS_SQLTUNE.execute_tuning_task(task_name => 'g0uubmuvk4uax_tuning_task');

3. Display the recommendations:

Once the tuning task has executed successfully the recommendations can be displayed using the REPORT_TUNING_TASK function.

SET LONG 10000;

SET PAGESIZE 1000

SET LINESIZE 200

SELECT DBMS_SQLTUNE.report_tuning_task('g0uubmuvk4uax_tuning_task') AS recommendations FROM dual;

SET PAGESIZE 24

Based on the tuning advisor recommendation we have to take corrective actions. These recommendation could be and many more:

1) Gather Statistics

2) Create Index

3) Drop Index

4) Join orders

5) Accept sql profile

6) Create baseline and many more recommnendations

Before applying any corrective action on production, we need to test that in DEV/QA/UAT/TEST environment or we can ask an tuning expert that this is the recommendation. After all the analysis we should apply in the production database.

After corrective action from tuning advisor run the SQL again and see the improvement.

Step 3 - Check the sql plan hash value and pin the good plan:

Sometime SQL tuning advisor does not recommend anything, in that case we have to go for a different approach.

check if there is any change in the sql plan.

set lines 500

set pages 500

col Snap for a25

col SQL_PROFILE for a40

select distinct b.BEGIN_INTERVAL_TIME as Snap, a.PLAN_HASH_VALUE as plan, a.EXECUTIONS_DELTA as EXECUTIONS, a.ELAPSED_TIME_DELTA/1000000 as ELAPSED_SEC, ROWS_PROCESSED_DELTA as "ROWS" , a.ROWS_PROCESSED_DELTA/CASE WHEN a.EXECUTION_DELTA = 0 THEN -1 ELSE a.EXECUTIONS_DELTA END "Avg Rows", a.ELAPSED_TIME_DELTA/1000000/CASE WHEN a. EXECUTION_DELTA = 0 THEN -1 ELSE a.EXECUTION_DELTA END "Avg Elapsed", a.optimizer_cost, a.SQL_PROFILE from DBA_HIST_SQLSTAT a, DBA_HIST_SNAPHOT b where a.SQL_ID = '&sqlid' and a.snap_id = b.snap_id order by b.BEGIN_INTERVAL_TIME

We can also use below query to to find out the sql plan for n number of days:

(Show the plan has value for a given sqlid over a given period)

SET PAUSE ON

SET PAUSE 'Press Return to Continue'

SET PAGESIZE 60

SET LINESIZE 300

SELECT DISTINCT sql_id, plan_hash_value

FROM dba_hist_sqlstat q,

    (

    SELECT /*+ NO_MERGE */ MIN(snap_id) min_snap, MAX(snap_id) max_snap

    FROM dba_hist_snapshot ss

    WHERE ss.begin_interval_time BETWEEN (SYSDATE - &No_Days) AND SYSDATE

    ) s

WHERE q.snap_id BETWEEN s.min_snap AND s.max_snap

  AND q.sql_id IN ( '&SQLID')

/

here we have to supply the value for number of days.

We can see the entire plan for n number of days the query has used. It is not mandatory that plan is changed. Here it also displays which plan takes how much time executes. So if there is change in plan, we should find best plan and pin it. Plan could be changed due to several reasons like change in the sql, due to stats gathering and many more.

Step 4 - Use TOP command to check the CPU usages by various processes:

TOP command is also useful for performance tuning. Many times, in a single server multiple databases are running. It may happen that one database is consuming more server resources than others. So we have to find out which oracle process is consuming more resources and it is related to which database. For this we use  TOP command. If we see there is CPU used by an oracle process is very high then this a matter of subject to worry about.

$top

Output of the top command 

top - 10:56:49 up 18 days, 18:48,  4 users,  load average: 1.02, 0.92, 0.48

Tasks: 180 total,   2 running, 178 sleeping,   0 stopped,   0 zombie

Cpu(s): 49.8%us,  0.5%sy,  0.0%ni, 49.2%id,  0.5%wa,  0.0%hi,  0.0%si,  0.0%st

Mem:   1815256k total,  1771772k used,    43484k free,    66120k buffers

Swap:  2031608k total,   734380k used,  1297228k free,   747740k cached

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND

 5946 oracle    25   0  706m 177m 159m R  100 10.0   9:20.26 oracle

 6104 oracle    15   0  2324 1060  800 R    1  0.1   0:00.12 top

31446 oracle    15   0  688m 135m 129m S    0  7.7   0:08.24 oracle

… output truncated …

In the output, we can see that the process with ID 5946 consumes the most CPU (100 percent) and memory (10 percent) and therefore should be the focus of our attention. To find out more about the process, enter the following command at the UNIX prompt: 

$ ps -aef|grep 5946

oracle    5946  5945 63 10:59 ?

00:01:52 oracleD112D2 (DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq)))

The output shows the entire description of the process, which is clearly an Oracle “server process”—a process that is created by Oracle Database when a session is established—and that the process has been running for 1 minute and 52 seconds. The next question, then, is which Oracle Database session this process was created for. For that, we should look into another view—V$PROCESS—where the SPID column shows the server process ID. However, this view does not show the session information, so we need to join this view with the familiar V$SESSION view, as follows: 

select sid

from v$session s, v$process p

where p.spid = 5946

and s.paddr = p.addr;

SID

———

37

Once we know the SID, we can get everything we need to know about the session—the user who established the session, the machine it came from, the operating system user, the SQL it is executing, and so on—from the V$SESSION view. To find the SQL being run by session 37, use this query: 

select sql_fulltext

from v$sql l, v$session s

where s.sid = 37

and l.sql_id = s.sql_id;

Here is the output: 

select max(test1.owner)

from test1, test2, test2, test2,

     test2, test2, test2, test2,

     test2, test2, test2, test2,

     test2, test2, test2, test2,

     test2, test2, test2, test2,

     test2, test2, test2, test2;

This SQL is performing multiple Cartesian joins, so it’s no wonder it’s consuming so much CPU and memory. 

Since this session is using most of the CPU, other sessions on the database might be waiting for the CPU to get their job done. But until or unless this session releases the CPU others won't be able to complete their job. So we can kill this high CPU consuming session so that others can complete their execution. And later on we can investigate why this is consuming so much of CPU.

If it is a DML statement then we have check the locking in the database

Step 5 - Find the locking in the database:

The very first step is to find out if there is any locking in the database. Sometime due to locking a session does not get the required resources and the session gets slow.

We can find below command to check locking in the database:

In Standalone:

sql>select s1.username || '@' || s1.machine || ' ( SID=' || s1.sid || ') is blocking'

       || s2.username || '@' || s2.machine || '( SID=' || s2.sid || ')' from

       v$lock l1, v$session s1, v$lock l2, v$session s2

       where s1.sid=l1.sid and s2.sid=l2.sid

       and l1.block=1 and l2.request > 0

       and l1.id1=l2.id1

       and l2.id2=l2.id2;

In RAC:

sql> select s1.username || '@' || s1.machine || ' ( SID=' || s1.sid || ') is blocking'

        || s2.username || '@' || s2.machine || '( SID=' || s2.sid || ')' from

       gv$lock l1, gv$session s1, gv$lock l2, gv$session s2

       where s1.sid=l1.sid and s2.sid=l2.sid

       and l1.block=1 and l2.request > 0

       and l1.id1=l2.id1

       and l2.id2=l2.id2;

Query Output:

S1.USERNAME||'@'||S1.MACHINE||'(SID='||S1.SID||')ISBLOCKING'||S2.USERNAME||'@'||

----------------------------------------------------------------------------------------

SYS@host1.abc.com ( SID=229) is blockingSYS@host1.abc.com( SID=226)

If we see the locking from above query then we can simply inform to user/application. And if they suggest to kill this blocking session then after killing we can get rid of this slowness.

Step 6 - Check for the wait events:

There could be some wait events on the database. Check for the particular user and session.

Query for displaying sessions, session state, and wait details

col "Description" format a50

select sid,

        decode(state, 'WAITING','Waiting',

                'Working') state,

        decode(state,

                'WAITING',

                'So far '||seconds_in_wait,

                'Last waited '||

                wait_time/100)||

        ' secs for '||event

        "Description"

from v$session

where username = 'ARUP';

Output:

SID   STATE       Description

————— ——————————  ———————————————————————————————————————————————————————

2832  Working     Last waited 2029 secs for SQL*Net message from client

3346  Waiting     So far 743 secs for enq: TX - row lock contention

4208  Waiting     So far 5498 secs for SQL*Net message from client

It clearly shows the state of the sessions: whether they are working or waiting; if they are working, what they were waiting for earlier and for how long; and if they are waiting, what for and for how long.

In many troubleshooting situations, just knowing the SID of each session is not enough. We may need to know other details, such as the client machine the session is connecting from, the user (of both the database and the operating system), and the service name. All of this information is also readily available in the same V$SESSION view we have been using. Let’s briefly examine the columns that provide that information, by running the below query

select SID, osuser, machine, terminal, service_name,

       logon_time, last_call_et

from v$session

where username = 'ARUP';

SID   OSUSER  MACHINE   TERMINAL  SERVICE_NAME  LOGON_TIME LAST_CALL_ET

————— ——————  ———————   ————————  ————————————  —————————— ————————————

3346  oradb   prodb1    pts/5     SYS$USERS     05-FEB-12          6848

2832  oradb   prodb1    pts/6     SERV1         05-FEB-12          7616

4408  ANANDA  ANLAP     ANLAP     ADHOC         05-FEB-12             0

OSUSER. The operating system user as which the client is connected. The output indicates that session 4408 is connected from the ANLAP machine, where a Windows user, ANANDA, has logged in.

MACHINE. The name of the machine where the client is running. This could be the database server itself. For two of the sessions, the machine name shows up as “prodb1.” Session 4408 runs on a different machine—ANLAP—presumably a laptop.

TERMINAL. If the session is connected from a UNIX server, this is the terminal where it runs.

LOGON_TIME. This shows when the session was first connected to the Oracle Database instance.

Using the columns shown in Listing 5, you can get very detailed information on a user’s sessions.

Suppose you receive a complaint that the applications running on the application server named appsvr1 are experiencing performance issues. Listing 6 shows a query against the V$SESSION view—including columns you’ve used in previous queries in this article—for the sessions connected from that machine and the output.

Code Listing 6: Session waits for a specific machine

col username format a5

col program format a10

col state format a10

col last_call_et head 'Called|secs ago' format 999999

col seconds_in_wait head 'Waiting|for secs' format 999999

col event format a50

select sid, username, program,

        decode(state, 'WAITING', 'Waiting',

                'Working') state,

last_call_et, seconds_in_wait, event

from v$session

where machine = 'appsvr1'

/

                                       Called      Waiting

SID   USERNAME  PROGRAM       STATE    secs ago    for secs   EVENT

————— ———————   ———————————   ———————  —————————   ————————   ——————————————————

2832  ARUP      sqlplus.exe   Waiting       152         151   SQL*Net message

                                                              from client

3089  ARUP      sqlplus.exe   Waiting       146         146   enq: TX - row lock

                                                              contention

3346  ARUP      sqlplus.exe   Working        18          49   SQL*Net message

                                                              from clie

History of wait events in a specific session 

set lines 120 trimspool on

col event head "Waited for" format a30

col total_waits head "Total|Waits" format 999,999

col tw_ms head "Waited|for (ms)" format 999,999.99

col aw_ms head "Average|Wait (ms)" format 999,999.99

col mw_ms head "Max|Wait (ms)" format 999,999.99

select event, total_waits, time_waited*10 tw_ms,

       average_wait*10 aw_ms, max_wait*10 mw_ms

from v$session_event

where sid = 37

/

                                  Total      Waited     Average         Max

Waited for                        Waits    for (ms)   Wait (ms)   Wait (ms)

—————————————————————————— ————————————  ———————————  ——————————  —————————

Disk file operations I/O              8         .00         .10         .00

KSV master wait                       2      350.00      173.20      340.00

os thread startup                     1       20.00       19.30       20.00

db file sequential read               5      160.00       32.10       70.00

direct path read                  1,521   51,010.00       33.50      120.00

direct path read temp           463,035  513,810.00        1.10      120.00

direct path write temp               20      370.00       18.70       50.00

resmgr:cpu quantum                   21      520.00       24.60      110.00

utl_file I/O                          8         .00         .00         .00

SQL*Net message to client            20         .00         .00         .00

SQL*Net message from client          20    9,620.00      481.20    9,619.00

kfk: async disk IO              904,818    3,050.00         .00         .00

events in waitclass Other            35       20.00         .70       20.00

Step 7 - Getting the SQL:

Another key piece of performance tuning information is the SQL statement a session is executing, which will provide more insights into the workings of the session. The same V$SESSION view also shows the SQL statement information. The SQL_ID column in the V$SESSION view shows the ID of the last SQL statement executed. W can get the text of that SQL statement from the V$SQL view, using the SQL_ID value. Here is an example of how I have identified the SQL statement executed by the session that appears slow to the user.

select sql_id

from v$session

where sid = 3089;

SQL_ID

—————————————————

g0uubmuvk4uax

set long 99999

select sql_fulltext

from v$sql

where sql_id = 'g0uubmuvk4uax';

SQL_FULLTEXT

————————————————————————————————————————

update t1 set col2 = 'y' where col1 = 1

Step 8 - Data Access issue:

Although locking-related contention is a very common cause, it is not the only cause of performance problems. Another major cause of contention is disk I/O. When a session retrieves data from the database data files on disk to the buffer cache, it has to wait until the disk sends the data. This wait shows up for that session as “db file sequential read” (for index scans) or “db file scattered read” (for full-table scans) in the EVENT column, as shown below:

select event

from v$session

where sid = 3011;

EVENT

—————————————————————————

db file sequential read

When we see this event, we know that the session is waiting for I/O from the disk to complete. To make the session go faster, we have to reduce that waiting period. There are several ways to reduce the wait:

Reduce the number of blocks retrieved by the SQL statement. Examine the SQL statement to see if it is doing a full-table scan when it should be using an index, if it is using a wrong index, or if it can be rewritten to reduce the amount of data it retrieves.

 Place the tables used in the SQL statement on a faster part of the disk. 

Consider increasing the buffer cache to see if the expanded size will accommodate the additional blocks, therefore reducing the I/O and the wait.  

 Tune the I/O subsystem to return data faster.

To find the table causing a wait, we will again use the V$SESSION view. The view’s P1 and P2 columns provide information about the segment the session is waiting for. Below shows a query of P1 and P2, and the output.There are other options as well, but the preceding ones are the most common remediation techniques. The exact activity we undertake depends on our specific situation, but the first technique—reducing the number of blocks retrieved by a SQL statement—almost always works.  When we think about tuning to reduce the number of blocks, we can look at the SQL statement to see which table is being selected from. But what if you see two or more tables in the statement? How do we determine which table is causing the wait?

To find the table causing a wait, we will again use the V$SESSION view. The view’s P1 and P2 columns provide information about the segment the session is waiting for. below query shows a query of P1 and P2, and the output.

Query to  Check data access waits:

select SID, state, event, p1, p2

from v$session

where username = 'ARUP';

SID  STATE     EVENT                   P1 P2

———— ———————   ——————————————————————— —— ————

2201 WAITING   db file sequential read  5 3011

The P1 column shows the file ID, and the P2 column shows the block ID. From that information in the above result, we can get the segment name from the extent information in DBA_EXTENTS, as shown below:

select owner, segment_name

from dba_extents

where file_id = 5

and 3011 between block_id

and block_id + blocks;

OWNER  SEGMENT_NAME

—————— —————————————

ARUP   T1

This shows that the T1 table, owned by ARUP, is being selected from by the disk in the session. We should direct our attention to this table for tuning. We can move the table to a high-speed disk for faster I/O, or, alternatively, We can focus on making I/O in this table faster by making changes that affect this table, such as creating new indexes, creating materialized views, or building a result cache.

These are the just few general guideline. We can enjoy it most when we really face this situation... :)

Suggestions are most welcome!!!