Elapsed time per exec of a SQL - AWR report puzzle!

I recently faced an issue when the user was complaining that a particular SQL was taking more time than expected. It usually runs for 40-50 minutes but on an unfortunate day it took more time.

AWR reports have always been my savior but when I generated one I was mildly surprised. Read on.

AWR reports:
                  Snap Time
Begin snap      1:00
End snap         2:00

SQL ordered by Elapsed Time
Elapsed Time (s) Executions    Elapsed Time per Exec (s) %Total  %CPU     %IO SQL Id
2,900.00                          0                                             74.04        6.07     94.19     acbcdefg

I see that the SQL was still executing (obvious due to the face that the executions still showed zero) at the end of 2:00 am.

              Snap Time

Begin snap     2:00

End snap        3:00

SQL ordered by Elapsed Time

Elapsed Time (s) Executions   Elapsed Time per Exec (s)       %Total   %CPU    %IO SQL Id 

2,800.00                        1                  2,800.00                68.03      5.38    96.15      acbcdefg

I generated another one during the interval 2:00-3:00 expecting I would have the SQL completed in this duration.

There it is , as expected Executions = 1, which means the SQL has completed by the end of snapshot at 3:00 am. 

As Elapsed Time per Exec showed 2,800 seconds without checking further informed my user saying the SQL has completed in 2,800 seconds as it was earlier feeling relieved that there was nothing wrong with the SQL and I could get a good night's sleep.

Soon after I told the user he immediately called me at 3.30 am stating that the AWR isn't showing  accurate results and that the SQL took about 90 minutes to complete.

Woken up from my sleep, rubbing my ever so drooping eyes I had to login and had to check what exactly was going on.

So, I generated another AWR , this time for snapshots between 1:00 - 3:00 am , I saw that the SQL had taken 5,700 seconds which shook me up and I was wide awake!.

             Snap Time

Begin snap     1:00

End snap        3:00

SQL ordered by Elapsed Time

Elapsed Time (s) Executions   Elapsed Time per Exec (s)       %Total   %CPU    %IO SQL Id 

5,700.00                        1                  5,700.00                                71.09      5.73     95.12      acbcdefg

How could this be? why was the AWR I had taken earlier lying to me? My assumptions were in for a rude shock!

Moments later realized that AWR only picks information for that particular snapshot and doesn't show the whole truth. My mistake really.

To confirm the same, I joined DBA_HIST_SQLSTAT DBA_HIST_SNAPSHOT for a couple of snapshots and voila! , AWR wasn't lying after all !.

I immediately fixed the query with an SQL plan baseline and it ran fine there after.

The solution was quite simple. 

The main idea of this post was to emphasize on a minor detail that we often skip when your mind starts making assumptions. 

Assumptions are good but then again they can go horribly wrong and wake up at 3.30 in the morning! :)

I shared this information on OTN as well which is one of my favorite forums. Here is the link 

Testing the Oracle database - Its significance and much more

I recently had an opportunity to write couple of articles as a guest author for a website http://www.softwaretestinghelp.com/

These posts gives you an insight on definition of a database, how to test them , the different utilities/tools that could be used to test them.

The topics covered are related to Oracle Database Testing and has been broken down into 3 parts.

How to Test Oracle Database
http://www.softwaretestinghelp.com/how-to-test-oracle-database/

Systematic Ways of Testing Oracle Database for Memory, Space and CPU Processing
http://www.softwaretestinghelp.com/testing-oracle-database-for-memory-space-and-cpu/

Oracle Real Application Testing – Solution to Test Oracle DB Before Moving to Production
http://www.softwaretestinghelp.com/oracle-real-application-testing/

Any comments are most welcome.

Dynamic Performance Views - What are they?

While reading the 12.1 Documentation regarding Dynamic Performance views and Data Dictionary views after pondering for a while, I decided to write a little bit about how exactly Oracle retrieves the information from these views.

Before we get to this, Let us understand what these views are:

Every DBA makes use of these views to pull information to know what exactly goes on in the database and know a little more detail about the database.

Dynamic Performance views provide data on internal disk structures and memory structures. We can select from these views, but we can never update or alter them.
Data dictionary views provide information regarding metadata of the database. They are available only after database is created, open and data dictionary tables become accessible.

Things to remember:
1) Dynamic performance views (or) V$ views are available since our instance startup even at NO MOUNT stage.
2) Data Dictionary views are identified by DBA_, ALL_, USER_ views

SQL> startup nomount;
ORACLE instance started.

Total System Global Area  521936896 bytes
Fixed Size                               2177328 bytes
Variable Size                      373294800 bytes
Database Buffers                138412032 bytes
Redo Buffers                          8052736 bytes

SQL> select count(*) from dba_users;
select count(*) from dba_users
                     *
ERROR at line 1:
ORA-01219: database not open: queries allowed on fixed tables/views only   (dictionary views are inaccessible in NO MOUNT)

SQL> select instance_name from v$instance;

INSTANCE_NAME
----------------
orcl

3) The V$FIXED_TABLE view contains information about all of the dynamic performance tables and views. These tables and views are created and populated automatically during instance startup and destroyed during shutdown.

Let's define the basic structure of a dynamic performance view. Consider V$INSTANCE.

v$instance     ==> v_$instance  ==> v$instance  ==> gv$instance  ==> x$table(s)
public synonym      view                      fixed view           fixed view

SQL> select synonym_name,table_name from dba_synonyms where synonym_name ='V$INSTANCE';

SYNONYM_NAME                   TABLE_NAME
------------------------------ ------------------------------
V$INSTANCE                     V_$INSTANCE

SQL> select view_name from dba_views where view_name ='V_$INSTANCE';

VIEW_NAME
------------------------------
V_$INSTANCE

SQL> set long 3000
SQL> select text from dba_views where view_name ='V_$INSTANCE';

TEXT
--------------------------------------------------------------------------------
select "INSTANCE_NUMBER","INSTANCE_NAME","HOST_NAME","VERSION","STARTUP_TIME","S
TATUS","PARALLEL","THREAD#","ARCHIVER","LOG_SWITCH_WAIT","LOGINS","SHUTDOWN_PEND
ING","DATABASE_STATUS","INSTANCE_ROLE","ACTIVE_STATE","BLOCKED" from v$instance

Now, to get the definition of the view.

SQL> select view_definition from v$fixed_view_definition where view_name ='V$INSTANCE';

VIEW_DEFINITION
--------------------------------------------------------------------------------
select  INSTANCE_NUMBER , INSTANCE_NAME , HOST_NAME , VERSION , STARTUP_TIME , S
TATUS , PARALLEL , THREAD# , ARCHIVER , LOG_SWITCH_WAIT , LOGINS , SHUTDOWN_PEND
ING, DATABASE_STATUS, INSTANCE_ROLE, ACTIVE_STATE, BLOCKED from GV$INSTANCE wher
e inst_id = USERENV('Instance')

Ah, We query the GV$INSTANCE.

SQL> select view_definition from v$fixed_view_definition where view_name ='GV$INSTANCE';

VIEW_DEFINITION
--------------------------------------------------------------------------------
select ks.inst_id,ksuxsins,ksuxssid,ksuxshst,ksuxsver,ksuxstim,decode(ksuxssts,0
,'STARTED',1,'MOUNTED',2,'OPEN',3,'OPEN MIGRATE','UNKNOWN'),decode(ksuxsshr,0,'N
O',1,'YES',2,NULL),ksuxsthr,decode(ksuxsarc,0,'STOPPED',1,'STARTED','FAILED'),de
code(ksuxslsw,0,NULL,2,'ARCHIVE LOG',3,'CLEAR LOG',4,'CHECKPOINT',       5,'REDO
 GENERATION'),decode(ksuxsdba,0,'ALLOWED','RESTRICTED'),decode(ksuxsshp,0,'NO','
YES'),decode(kvitval,0,'ACTIVE',2147483647,'SUSPENDED','INSTANCE RECOVERY'),deco
de(ksuxsrol,1,'PRIMARY_INSTANCE',2,'SECONDARY_INSTANCE','UNKNOWN'), decode(qui_s
tate,0,'NORMAL',1,'QUIESCING',2,'QUIESCED','UNKNOWN'), decode(bitand(ksuxsdst, 1
), 0, 'NO', 1, 'YES', 'NO') from x$ksuxsinst ks, x$kvit kv, x$quiesce qu where k
vittag = 'kcbwst'

These views are built on the X$ tables.

These x$ tables can be viewed when our database is up (atleast at Mount). They are just memory based structures. As indicated earlier, They are destroyed at shutdown and created each time at instance startup. x$tables are not real tables. They represent internal structures. The information is pulled from memory.