09 August, 2011

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 !

.
.
.

4 comments:

Narendra said...

I would have to say yes, it did take 278 seconds to execute unless I am missing something obvious

Hemant K Chitale said...

Narendra,
I will be updating the post tomorrow (hopefullly) with an extract from the actual SQL run file and more information from the AWR.

However, as you would have expected : This was a trick question. The actual execution and elapsed time of the query was not 278seconds.

Hemant

Franck Pachot said...

Hi,

In AWR, most of 'elapsed time' are more like 'DB time'. It is the sum of time that has been passed in the database. Something like 'DB time' that is the sum of elapsed time of user calls. Each concurrent process can measure their own elapsed time, but once added, the term 'elapsed' is not accurate anymore.

There are a lot of 'elapsed' time in the Time Model Statistics section that are summed over several sessions...

The only real 'elapsed time' is the Elapsed that is calculated from the Snapshot clock time. All others are summed over several sessions.

Regards,
Franck.

Hemant K Chitale said...

Franck,
True. However, I have not presented Instance Statistics. What I show is an extract from AWR that purports to list a *single* execution of an SQL.