Reading an AWR -- 2

I have extracted this from an AWR report :

    

    Elapsed                  Elapsed Time

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

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

       277.8              1        277.85   97.6   14.9   59.4 8madvr3cvp929

Module: SQL*Plus

select count(*), sum(sale_qty), sum(discount_rate) from very_large_fact_table





 CPU                   CPU per           Elapsed

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

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

   41.5            1      41.49   91.4      277.8   14.9   59.4 8madvr3cvp929

Module: SQL*Plus

select count(*), sum(sale_qty), sum(discount_rate) from very_large_fact_table





User I/O                UIO per           Elapsed

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

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

  164.9            1     164.94   99.4      277.8   14.9   59.4 8madvr3cvp929

Module: SQL*Plus

select count(*), sum(sale_qty), sum(discount_rate) from very_large_fact_table





  Buffer                 Gets              Elapsed

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

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

 530,607           1    530,607.0   98.0      277.8   14.9   59.4 8madvr3cvp9

Module: SQL*Plus

select count(*), sum(sale_qty), sum(discount_rate) from very_large_fact_table





Physical              Reads              Elapsed

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

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

 530,326           1  530,326.0   99.9      277.8   14.9   59.4 8madvr3cvp929

Module: SQL*Plus

select count(*), sum(sale_qty), sum(discount_rate) from very_large_fact_table

How long did the query really take to execute ? Did it take approximately 278seconds ? We know that the query returns only 1 row so we don't have to factor SQL*Net round-trips or ARRAYSIZE. This is the output of the query :

SQL> select count(*), sum(sale_qty), sum(discount_rate)

2  from very_large_fact_table

3  /



COUNT(*) SUM(SALE_QTY) SUM(DISCOUNT_RATE)

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

80000000    1.0044E+11         1280636517

A query on 80million rows and about 530thousand blocks (slightly over 4GB). Did it take about 278seconds to execute ?

??
.
.

UPDATE : 13-Aug :

Here is the actual execution of the query (with elapsed time included) :

SQL> select count(*), sum(sale_qty), sum(discount_rate)

 2  from very_large_fact_table

 3  /



 COUNT(*) SUM(SALE_QTY) SUM(DISCOUNT_RATE)

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

 80000000    1.0044E+11         1280636517



Elapsed: 00:01:11.95

SQL>

So, the actual elapsed time was about 72seconds.
How did the query really execute ?

SQL> select * from table(dbms_xplan.display_cursor);



PLAN_TABLE_OUTPUT

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

SQL_ID  8madvr3cvp929, child number 0

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

select count(*), sum(sale_qty), sum(discount_rate) from

very_large_fact_table



Plan hash value: 3187774711



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

| Id  | Operation              | Name                  | Rows  | Bytes | Cost (%CPU)| Time     |    TQ  |IN-OUT| PQ Distrib |

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

|   0 | SELECT STATEMENT       |                       |       |       | 40148 (100)|          |        |      |            |

|   1 |  SORT AGGREGATE        |                       |     1 |    26 |            |          |        |      |            |

|   2 |   PX COORDINATOR       |                       |       |       |            |          |        |      |            |

|   3 |    PX SEND QC (RANDOM) | :TQ10000              |     1 |    26 |            |          |  Q1,00 | P->S | QC (RAND)  |

|   4 |     SORT AGGREGATE     |                       |     1 |    26 |            |          |  Q1,00 | PCWP |            |

|   5 |      PX BLOCK ITERATOR |                       |    87M|  2176M| 40148   (1)| 00:08:02 |  Q1,00 | PCWC |            |

|*  6 |       TABLE ACCESS FULL| VERY_LARGE_FACT_TABLE |    87M|  2176M| 40148   (1)| 00:08:02 |  Q1,00 | PCWP |            |

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



Predicate Information (identified by operation id):

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



  6 - access(:Z>=:Z AND :Z<=:Z)  

Note -----    

- dynamic sampling used for this statement (level=5)    

(The "dynamic sampling level 5 is new "automatic" behaviour in 11gR2. I will talk about that in a later blog post).
Also note that the elapsed time includes time for dynamic sampling -- which is executed as recursive SQL.

More information about the execution statistics :

SQL> select executions, disk_reads, buffer_gets, elapsed_time/1000, px_servers_executions

 2  from v$sqlstats where sql_id = '&myqry'

 3  /

Enter value for myqry: 8madvr3cvp929

old   2: from v$sqlstats where sql_id = '&myqry'

new   2: from v$sqlstats where sql_id = '8madvr3cvp929'



EXECUTIONS DISK_READS BUFFER_GETS ELAPSED_TIME/1000 PX_SERVERS_EXECUTIONS

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

        1     530326      530607        277849.818                     4

Conclusive evidence that the query actually used 4 PQ slaves. There is no PARALLEL Hint in the query but a Parallel DEGREE of 4 has been defined on the table.

The table is about 4GB in size :

SQL> select blocks from user_tables where table_name = 'VERY_LARGE_FACT_TABLE';



   BLOCKS

----------





SQL> select blocks from user_segments where segment_name = 'VERY_LARGE_FACT_TABLE';



   BLOCKS

----------

   533504



SQL>

SQL> select table_name, degree from user_tables    

  2  where table_name = 'VERY_LARGE_FACT_TABLE';



TABLE_NAME                     DEGREE

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

VERY_LARGE_FACT_TABLE                   4



SQL> 

So, the Buffer Gets and Physical Reads statistics (530thousand) reported by AWR are for the SQL but the Total Elapsed Time is the summation of time for the 4 PQ slaves !
Here are some statistics from the AWR :

Statistic                                     Total

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

consistent gets                             539,810

consistent gets direct                      530,138

physical read IO requests                     4,747

physical read bytes                   4,348,256,256

physical read total IO requests               5,008

physical read total bytes             4,352,385,024

physical read total multi block               4,190

physical reads                              530,793

physical reads direct                       530,138

table scan blocks gotten                    530,228

table scan rows gotten                   80,010,539

PX local messages recv'd                        120

PX local messages sent                          120

About 530thousand table blocks holding 80million rows were fetched using 4thousand multi block read calls to read 4GB. Those multiblock read calls were made by PX operators (what I call PQ slaves).

Therefore, although the AWR statistics about I/O by the SQL are correct, the information about elapsed time is wrong !

The next time you look at Elapsed Time for a query in an AWR report, you might want to confirm if the query did or did not use Parallel Slaves !

.
.
.