21 August, 2011

Reading an AWR Report -- 3

Continuing the Reading an AWR report series ....

I run these statements :
SQL> exec dbms_workload_repository.create_snapshot;


PL/SQL procedure successfully completed.

Elapsed: 00:00:01.15
SQL> set serveroutput on
SQL> declare
2 cnt number;
3 begin
4 select sum(sale_qty) into cnt
5 from very_large_fact_table
6 where prod_id = 5;
7 dbms_output.put_line('Sales for Prod 5 : ' || cnt);
8 select sum(sale_qty) into cnt
9 from very_large_fact_table
10 where prod_id in (4,11);
11 dbms_output.put_line('Sales for Prods 4,11 : ' || cnt);
12 select sum(sale_qty) into cnt
13 from very_large_fact_table
14 where prod_id = 10
15 and cust_id = 10;
16 dbms_output.put_line('Sales for Prod 10 to Cust 10 : ' || cnt);
17 end;
18 /
Sales for Prod 5 : 4012173200
Sales for Prods 4,11 : 8004026720
Sales for Prod 10 to Cust 10 : 2017249360

PL/SQL procedure successfully completed.

Elapsed: 00:01:34.05
SQL> exec dbms_workload_repository.create_snapshot;


The AWR report indicates that the whole PLSQL block took 57.47 seconds but that the individual SQLs in the block took 70.52 to 112.95 seconds (Note :The client reported a total elapsed time of 94.05seconds, including parsing and SQLNet time !).

SQL ordered by Elapsed Time              DB/Inst: ORCL/orcl  Snaps: 1320-1321

-> Resources reported for PL/SQL code includes the resources used by all SQL
statements called by the code.
-> % Total DB Time is the Elapsed Time of the SQL statement divided
into the Total Database Time multiplied by 100
-> %Total - Elapsed Time as a percentage of Total DB time
-> %CPU - CPU Time as a percentage of Elapsed Time
-> %IO - User I/O Time as a percentage of Elapsed Time
-> Captured SQL account for 99.7% of Total DB Time (s): 284
-> Captured PL/SQL account for 20.7% of Total DB Time (s): 284

Elapsed Elapsed Time
Time (s) Executions per Exec (s) %Total %CPU %IO SQL Id
---------------- -------------- ------------- ------ ------ ------ -------------
112.9 1 112.95 39.8 23.5 .4 cc8khw75jw0ha
Module: SQL*Plus
SELECT SUM(SALE_QTY) FROM VERY_LARGE_FACT_TABLE WHERE PROD_ID = 10 AND CUST_ID =
10

97.2 1 97.22 34.3 34.7 1.1 dwm8pq8awt96v
Module: SQL*Plus
SELECT SUM(SALE_QTY) FROM VERY_LARGE_FACT_TABLE WHERE PROD_ID IN (4,11)

70.5 1 70.52 24.9 37.2 .6 gscvdz32smtgr
Module: SQL*Plus
SELECT SUM(SALE_QTY) FROM VERY_LARGE_FACT_TABLE WHERE PROD_ID = 5

57.5 1 57.47 20.3 .3 .0 1dh6uf6hyr3us
Module: SQL*Plus
declare cnt number; begin select sum(sale_qty) into cnt from very_large_fact_t
able where prod_id = 5; dbms_output.put_line('Sales for Prod 5 : ' || cnt); sel
ect sum(sale_qty) into cnt from very_large_fact_table where prod_id in (4,11);
dbms_output.put_line('Sales for Prods 4,11 : ' || cnt); select sum(sale_qty) int

1.1 1 1.14 .4 88.2 10.6 1uk5m5qbzj1vt
Module: SQL*Plus
BEGIN dbms_workload_repository.create_snapshot; END;


The table has a PARALLEL DEGREE of 4 defined so each of the three queries, doing a FullTableScan actually used 4 PQ slaves.

What are the time model statistics ?
Time Model Statistics                    DB/Inst: ORCL/orcl  Snaps: 1320-1321

-> Total time in database user-calls (DB Time): 283.5s
-> Statistics including the word "background" measure background process
time, and so do not contribute to the DB time statistic
-> Ordered by % or DB time desc, Statistic name

Statistic Name Time (s) % of DB Time
------------------------------------------ ------------------ ------------
sql execute elapsed time 281.8 99.4
DB CPU 88.2 31.1
parse time elapsed 0.4 .1
PL/SQL execution elapsed time 0.2 .1
hard parse elapsed time 0.2 .1
hard parse (sharing criteria) elapsed time 0.1 .0
PL/SQL compilation elapsed time 0.0 .0
repeated bind elapsed time 0.0 .0


The Time Model Statistics indicates that the summed elapsed time for all sessions (including PQ slaves) is 281.8seconds and the summed DB CPU t ime is 88.2seconds.

The Timed Foreground Events shows :
                                                          Avg

wait % DB
Event Waits Time(s) (ms) time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
DB CPU 88 31.1
direct path read 61 2 31 .7 User I/O
cursor: pin S wait on X 3 0 67 .1 Concurrenc
PX Deq: Signal ACK RSG 2 0 89 .1 Other
db file sequential read 50 0 4 .1 User I/O


If Database CPU time was 88.2seconds and total Database SQL Elapsed Time was 281.8seconds, how do we account for the large discrepancy ? All the other wait event hardly add up to a few seconds.

.
.
UPDATE 22-Aug-11 :
What if the table is set to NOPARALLEL so that the the three SQL executions do not use Parallel Query slaves ?
SQL> select degree from user_tables where table_name = 'VERY_LARGE_FACT_TABLE';


DEGREE
----------------------------------------
4

Elapsed: 00:00:00.18
SQL> alter table very_large_fact_table noparallel;

Table altered.

Elapsed: 00:00:00.73
SQL> select degree from user_tables where table_name = 'VERY_LARGE_FACT_TABLE';

DEGREE
----------------------------------------
1

Elapsed: 00:00:00.01
SQL>
SQL> exec dbms_workload_repository.create_snapshot;

PL/SQL procedure successfully completed.

Elapsed: 00:00:03.13
SQL> set serveroutput on
SQL> declare
2 cnt number;
3 begin
4 select sum(sale_qty) into cnt
5 from very_large_fact_table
6 where prod_id = 5;
7 dbms_output.put_line('Sales for Prod 5 : ' || cnt);
8 select sum(sale_qty) into cnt
9 from very_large_fact_table
10 where prod_id in (4,11);
11 dbms_output.put_line('Sales for Prods 4,11 : ' || cnt);
12 select sum(sale_qty) into cnt
13 from very_large_fact_table
14 where prod_id = 10
15 and cust_id = 10;
16 dbms_output.put_line('Sales for Prod 10 to Cust 10 : ' || cnt);
17 end;
18 /
Sales for Prod 5 : 4012173200
Sales for Prods 4,11 : 8004026720
Sales for Prod 10 to Cust 10 : 2017249360

PL/SQL procedure successfully completed.

Elapsed: 00:02:31.73
SQL> exec dbms_workload_repository.create_snapshot;

PL/SQL procedure successfully completed.

Elapsed: 00:00:01.43
SQL>


So, the entire block completed in 151.73seconds.

What does the AWR report show ?

SQL ordered by Elapsed Time              DB/Inst: ORCL/orcl  Snaps: 1325-1326

-> Resources reported for PL/SQL code includes the resources used by all SQL
statements called by the code.
-> % Total DB Time is the Elapsed Time of the SQL statement divided
into the Total Database Time multiplied by 100
-> %Total - Elapsed Time as a percentage of Total DB time
-> %CPU - CPU Time as a percentage of Elapsed Time
-> %IO - User I/O Time as a percentage of Elapsed Time
-> Captured SQL account for 94.2% of Total DB Time (s): 167
-> Captured PL/SQL account for 94.0% of Total DB Time (s): 167

Elapsed Elapsed Time
Time (s) Executions per Exec (s) %Total %CPU %IO SQL Id
---------------- -------------- ------------- ------ ------ ------ -------------
151.7 1 151.70 91.1 62.6 19.1 1dh6uf6hyr3us
Module: SQL*Plus
declare cnt number; begin select sum(sale_qty) into cnt from very_large_fact_t
able where prod_id = 5; dbms_output.put_line('Sales for Prod 5 : ' || cnt); sel
ect sum(sale_qty) into cnt from very_large_fact_table where prod_id in (4,11);
dbms_output.put_line('Sales for Prods 4,11 : ' || cnt); select sum(sale_qty) int

58.9 1 58.87 35.3 64.2 17.0 dwm8pq8awt96v
Module: SQL*Plus
SELECT SUM(SALE_QTY) FROM VERY_LARGE_FACT_TABLE WHERE PROD_ID IN (4,11)

46.8 1 46.79 28.1 61.6 26.1 cc8khw75jw0ha
Module: SQL*Plus
SELECT SUM(SALE_QTY) FROM VERY_LARGE_FACT_TABLE WHERE PROD_ID = 10 AND CUST_ID =
10

46.0 1 45.99 27.6 61.6 14.5 gscvdz32smtgr
Module: SQL*Plus
SELECT SUM(SALE_QTY) FROM VERY_LARGE_FACT_TABLE WHERE PROD_ID = 5


Isn't that a very interesting difference from yesterday's report ? Now we have the real execution time for each of the three SQLs which add up to the time for the PLSQL block.

Is there a discrepancy in the Time Model Statistics now ?
Time Model Statistics                    DB/Inst: ORCL/orcl  Snaps: 1325-1326

-> Total time in database user-calls (DB Time): 166.6s
-> Statistics including the word "background" measure background process
time, and so do not contribute to the DB time statistic
-> Ordered by % or DB time desc, Statistic name

Statistic Name Time (s) % of DB Time
------------------------------------------ ------------------ ------------
sql execute elapsed time 161.7 97.1
DB CPU 99.4 59.7
parse time elapsed 2.8 1.7
PL/SQL execution elapsed time 2.6 1.6
hard parse elapsed time 2.2 1.3
hard parse (sharing criteria) elapsed time 0.2 .1
PL/SQL compilation elapsed time 0.0 .0
repeated bind elapsed time 0.0 .0
sequence load elapsed time 0.0 .0


Top 5 Timed Foreground Events
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Avg
wait % DB
Event Waits Time(s) (ms) time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
DB CPU 99 59.7
direct path read 4,648 27 6 16.5 User I/O
db file sequential read 388 1 4 .9 User I/O
db file scattered read 18 1 36 .4 User I/O
enq: KO - fast object checkpoi 1 0 53 .0 Applicatio



What are your comments / observations ?
.
.
.



2 comments:

Oracle DBA said...

here is an STEP BY STEP procedure to generate AWR report :

http://chandu208.blogspot.com/2011/04/steps-to-generate-awr-report.html

BISWAJIT said...

is not upto mark