Dev team complains about performance of a complex query which join a dozen of tables, they insist that the row count of the tables in the join remain same, but the query elapse time various from 1 hour to 5 hours.
I use AWR to analyze the overall query performance, but down to the fact tables and lookup tables, I use the following DBA query to prove that the logical_read various, which caused the variation of query elapsed time, and most importantly, Tune the query to reduce the elapsed time from hours to only a few minutes!
DBA query 1:
On table snapshot level: this query help to compare visiting blocks of involved tables on snapshot id level. we have snapshot every 10 minutes.
col BEGIN_INTERVAL_TIME format a25
col object_name format a20
col start_time format a15
select object_name,
to_char(BEGIN_INTERVAL_TIME,'hh24:mi-dd-mon') start_time,
LOGICAL_READS_TOTAL logical_total,
LOGICAL_READS_DELTA logical_delta,
SPACE_USED_TOTAL space_total,
SPACE_USED_DELTA space_delta,
TABLE_SCANS_TOTAL tscan_total,
TABLE_SCANS_DELTA tscan_del,
CHAIN_ROW_EXCESS_TOTAL chain_row,
PHYSICAL_READS_TOTAL phy_total,
PHYSICAL_READS_DELTA phy_delta
from
dba_hist_seg_stat a,
DBA_HIST_SNAPSHOT b,
dba_objects c
where trunc(BEGIN_INTERVAL_TIME) in (trunc(sysdate-&firstdays), trunc(sysdate-&seconddays))
and obj#=c.object_id
and a.snap_id=b.snap_id
and object_name in
(
'RADIOSTATIONGROUP',
'DATASOURCE',
'LOAD_COMPANY',
'INCOMETYPE_XREF',
'INDUSTRYPRODUCT',
'CUSTOMER',
'SALES_CHANNEL_XREF',
'DAYPARTSALETYPE',
'INCOMETYPE',
'REVENUESTREAM',
'REVENUESTREAMEXPORT',
'REVENUETYPE',
'SALES_PERSON_REP',
'CONTRACTHEADER',
'CONTRACT_ITEM_B'
)
order by object_name,BEGIN_INTERVAL_TIME
DBA Query 2: On table summary level, compare the maximum numbers of logical_reads_total between the ok day and trouble day.
select object_name, to_char(BEGIN_INTERVAL_TIME,'yyyymmdd') ddate,
max(to_char(BEGIN_INTERVAL_TIME,'hh24:mi-dd-mon')) start_time,
max(LOGICAL_READS_TOTAL) logical_total,
max(SPACE_USED_TOTAL) space_total,
max(TABLE_SCANS_TOTAL) tscan_total,
max(PHYSICAL_READS_TOTAL) phy_total
from
dba_hist_seg_stat a,
DBA_HIST_SNAPSHOT b,
dba_objects c
where trunc(BEGIN_INTERVAL_TIME) in (trunc(sysdate-&firstdays), trunc(sysdate-&seconddays))
and obj#=c.object_id
and a.snap_id=b.snap_id
and object_name in
(
'RADIOSTATIONGROUP',
'DATASOURCE',
'LOAD_COMPANY',
'INCOMETYPE_XREF',
'INDUSTRYPRODUCT',
'CUSTOMER',
'SALES_CHANNEL_XREF',
'DAYPARTSALETYPE',
'INCOMETYPE',
'REVENUESTREAM',
'REVENUESTREAMEXPORT',
'REVENUETYPE',
'SALES_PERSON_REP',
'CONTRACTHEADER',
'CONTRACT_ITEM_B'
)
group by object_name,to_char(BEGIN_INTERVAL_TIME, 'yyyymmdd')
order by object_name,max(to_char(BEGIN_INTERVAL_TIME,'hh24:mi-dd-mon'))
an sample result is shown below.
Enter value for firstdays: 0
Enter value for secibddays: 4
OBJECT_NAME DDATE START_TIME LOGICAL_TOTAL SPACE_TOTAL TSCAN_TOTAL PHY_TOTAL
------------------------------ -------- --------------------- ------------- ----------- ----------- ----------
CONTRACTHEADER 20140918 04:40-18-sep 66704 43163396 0 6139
CONTRACTHEADER 20140922 05:10-22-sep 66048 43191167 0 6138
CONTRACT_ITEM_B 20140918 09:50-18-sep 418848 278825606 0 38692
CONTRACT_ITEM_B 20140922 11:40-22-sep 397088 280241601 123 117427
CUSTOMER 20140918 04:40-18-sep 5616 2969043 0 485
CUSTOMER 20140922 05:10-22-sep 10240 2967978 0 926
DATASOURCE 20140922 05:50-22-sep 111632 2048 0 6
DATASOURCE 20140918 10:00-18-sep 184224 4096 0 7
DAYPARTSALETYPE 20140922 06:10-22-sep 753616 1025726 0 262
DAYPARTSALETYPE 20140918 10:10-18-sep 746480 1032935 0 74
INCOMETYPE 20140922 06:10-22-sep 194224 19579 0 12
INCOMETYPE 20140918 10:10-18-sep 71456 19579 0 17
INCOMETYPE_XREF 20140918 10:10-18-sep 159442624 0 0 1231
INCOMETYPE_XREF 20140922 14:40-22-sep 86938832 0 0 4108
INDUSTRYPRODUCT 20140922 06:10-22-sep 25944784 64881 0 14
INDUSTRYPRODUCT 20140918 10:00-18-sep 27159040 72090 0 66
LOAD_COMPANY 20140922 05:50-22-sep 4385088 9366539 0 3615
LOAD_COMPANY 20140918 10:00-18-sep 4743376 9364491 0 7722
RADIOSTATIONGROUP 20140922 05:50-22-sep 1193168 0 0 6
RADIOSTATIONGROUP 20140918 10:00-18-sep 4281488 0 0 36
SALES_PERSON_REP 20140922 04:10-22-sep 848 86508 0 2
SALES_PERSON_REP 20140918 04:40-18-sep 896 92652 0 24
DBA query 3: This one shows overall of the query buffer_get_total during the run of problematic query. compare the ok day and problematic day.
col buffer_gets_DELTA for 999,999,999
col buffer_gets_total for 999,999,999,999
col start_time for a12
col end_time for a12
col executions_total for 999999999
col executions_delta for 999999999
select snap_id,begin_interval_time from (select * from DBA_HIST_SNAPSHOT where BEGIN_INTERVAL_TIME > sysdate-2 order by BEGIN_INTERVAL_TIME desc) where rownum < 100;
select distinct sql_id,PLAN_HASH_VALUE,to_char(BEGIN_INTERVAL_TIME,'hh24:mi-dd-mon') start_time,to_char(end_intervAL_TIME,'hh24:mi-dd-mon') end_time,
executions_total,executions_delta,
BUFFER_GETS_DELTA,buffer_gets_total,
--round(buffer_gets_delta/EXECUTIONS_DELTA) "gets/exec",
round(cpu_time_delta/1000000) "cpu_del(s)",round(ELAPSED_TIME_DELTA/1000000) "ele_del(s)"
from dba_hist_sqlstat st, DBA_HIST_SNAPSHOT sn
where st.snap_id between &begin_snap_id and &end_snap_id
and st.snap_id=sn.snap_id
and sql_id='&sql_id'
order by to_char(BEGIN_INTERVAL_TIME,'hh24:mi-dd-mon');
--order by ELAPSED_TIME_DELTA desc;
undefine snap_id
undefine sql_id
sample query result is:
SQL_ID PLAN_HASH_VALUE START_TIME END_TIME EXECUTIONS_TOTAL EXECUTIONS_DELTA BUFFER_GETS_DELTA BUFFER_GETS_TOTAL cpu_del(s) ele_del(s)
------------- --------------- ------------ ------------ ---------------- ---------------- ----------------- ----------------- ---------- ----------
0fcvv8rsqyh59 3589643954 05:20-05-sep 05:30-05-sep 1 1 13,633,017 13,633,017 108 185
0fcvv8rsqyh59 3589643954 05:30-05-sep 05:40-05-sep 1 0 19,366,362 32,999,379 357 596
0fcvv8rsqyh59 3589643954 05:40-05-sep 05:50-05-sep 1 0 12,337,385 45,345,660 355 591
0fcvv8rsqyh59 3589643954 05:50-05-sep 06:00-05-sep 1 0 10,171,499 55,517,159 365 595
0fcvv8rsqyh59 3589643954 06:00-05-sep 06:10-05-sep 1 0 8,503,090 64,050,934 370 598
0fcvv8rsqyh59 3589643954 06:10-05-sep 06:20-05-sep 1 0 7,752,640 71,803,574 371 598
0fcvv8rsqyh59 3589643954 06:20-05-sep 06:30-05-sep 1 0 913,075 72,716,649 46 73
long story short, I find out that there is one table that account for 80% of logical_total, the table has only 4k rows in it. checking the query plan, I am able to remove the "distinct" keyword from the query, creating index on the join column, then the logical_total on this table is reduced significantly, hence the query elapsed time is reduced to 8 minutes!
For security reason, I will not post the query detail etc in this post, but the key is to find out which table has the most of logical read, from dba_hist_seg_stat!
Further more, I use the following query to link sql_id and segment to see segment logical read used by specific sql_id.
col BEGIN_INTERVAL_TIME format a25
col object_name format a25
col start_time format a15
select distinct object_name,
to_char(BEGIN_INTERVAL_TIME,'hh24:mi-dd-mon') start_time,
LOGICAL_READS_DELTA lgcl_delta,
LOGICAL_READS_TOTAL lgcl_totl,
PHYSICAL_READS_TOTAL phy_totl,
PHYSICAL_READS_DELTA phy_delta,
SPACE_USED_TOTAL space_total,
SPACE_USED_DELTA space_delta,
TABLE_SCANS_TOTAL tscan_totl,
TABLE_SCANS_DELTA tscan_del,
CHAIN_ROW_EXCESS_TOTAL chain_row
from
dba_hist_seg_stat a,
DBA_HIST_SNAPSHOT b,
DBA_HIST_SQL_PLAN c
where sql_id='&sqlid'
and trunc(BEGIN_INTERVAL_TIME) in (trunc(sysdate-&firstdays), trunc(sysdate-&seconddays))
and obj#=c.object#
and a.snap_id=b.snap_id
order by object_name,
to_char(BEGIN_INTERVAL_TIME,'hh24:mi-dd-mon')
/
I use AWR to analyze the overall query performance, but down to the fact tables and lookup tables, I use the following DBA query to prove that the logical_read various, which caused the variation of query elapsed time, and most importantly, Tune the query to reduce the elapsed time from hours to only a few minutes!
DBA query 1:
On table snapshot level: this query help to compare visiting blocks of involved tables on snapshot id level. we have snapshot every 10 minutes.
col BEGIN_INTERVAL_TIME format a25
col object_name format a20
col start_time format a15
select object_name,
to_char(BEGIN_INTERVAL_TIME,'hh24:mi-dd-mon') start_time,
LOGICAL_READS_TOTAL logical_total,
LOGICAL_READS_DELTA logical_delta,
SPACE_USED_TOTAL space_total,
SPACE_USED_DELTA space_delta,
TABLE_SCANS_TOTAL tscan_total,
TABLE_SCANS_DELTA tscan_del,
CHAIN_ROW_EXCESS_TOTAL chain_row,
PHYSICAL_READS_TOTAL phy_total,
PHYSICAL_READS_DELTA phy_delta
from
dba_hist_seg_stat a,
DBA_HIST_SNAPSHOT b,
dba_objects c
where trunc(BEGIN_INTERVAL_TIME) in (trunc(sysdate-&firstdays), trunc(sysdate-&seconddays))
and obj#=c.object_id
and a.snap_id=b.snap_id
and object_name in
(
'RADIOSTATIONGROUP',
'DATASOURCE',
'LOAD_COMPANY',
'INCOMETYPE_XREF',
'INDUSTRYPRODUCT',
'CUSTOMER',
'SALES_CHANNEL_XREF',
'DAYPARTSALETYPE',
'INCOMETYPE',
'REVENUESTREAM',
'REVENUESTREAMEXPORT',
'REVENUETYPE',
'SALES_PERSON_REP',
'CONTRACTHEADER',
'CONTRACT_ITEM_B'
)
order by object_name,BEGIN_INTERVAL_TIME
DBA Query 2: On table summary level, compare the maximum numbers of logical_reads_total between the ok day and trouble day.
select object_name, to_char(BEGIN_INTERVAL_TIME,'yyyymmdd') ddate,
max(to_char(BEGIN_INTERVAL_TIME,'hh24:mi-dd-mon')) start_time,
max(LOGICAL_READS_TOTAL) logical_total,
max(SPACE_USED_TOTAL) space_total,
max(TABLE_SCANS_TOTAL) tscan_total,
max(PHYSICAL_READS_TOTAL) phy_total
from
dba_hist_seg_stat a,
DBA_HIST_SNAPSHOT b,
dba_objects c
where trunc(BEGIN_INTERVAL_TIME) in (trunc(sysdate-&firstdays), trunc(sysdate-&seconddays))
and obj#=c.object_id
and a.snap_id=b.snap_id
and object_name in
(
'RADIOSTATIONGROUP',
'DATASOURCE',
'LOAD_COMPANY',
'INCOMETYPE_XREF',
'INDUSTRYPRODUCT',
'CUSTOMER',
'SALES_CHANNEL_XREF',
'DAYPARTSALETYPE',
'INCOMETYPE',
'REVENUESTREAM',
'REVENUESTREAMEXPORT',
'REVENUETYPE',
'SALES_PERSON_REP',
'CONTRACTHEADER',
'CONTRACT_ITEM_B'
)
group by object_name,to_char(BEGIN_INTERVAL_TIME, 'yyyymmdd')
order by object_name,max(to_char(BEGIN_INTERVAL_TIME,'hh24:mi-dd-mon'))
an sample result is shown below.
Enter value for firstdays: 0
Enter value for secibddays: 4
OBJECT_NAME DDATE START_TIME LOGICAL_TOTAL SPACE_TOTAL TSCAN_TOTAL PHY_TOTAL
------------------------------ -------- --------------------- ------------- ----------- ----------- ----------
CONTRACTHEADER 20140918 04:40-18-sep 66704 43163396 0 6139
CONTRACTHEADER 20140922 05:10-22-sep 66048 43191167 0 6138
CONTRACT_ITEM_B 20140918 09:50-18-sep 418848 278825606 0 38692
CONTRACT_ITEM_B 20140922 11:40-22-sep 397088 280241601 123 117427
CUSTOMER 20140918 04:40-18-sep 5616 2969043 0 485
CUSTOMER 20140922 05:10-22-sep 10240 2967978 0 926
DATASOURCE 20140922 05:50-22-sep 111632 2048 0 6
DATASOURCE 20140918 10:00-18-sep 184224 4096 0 7
DAYPARTSALETYPE 20140922 06:10-22-sep 753616 1025726 0 262
DAYPARTSALETYPE 20140918 10:10-18-sep 746480 1032935 0 74
INCOMETYPE 20140922 06:10-22-sep 194224 19579 0 12
INCOMETYPE 20140918 10:10-18-sep 71456 19579 0 17
INCOMETYPE_XREF 20140918 10:10-18-sep 159442624 0 0 1231
INCOMETYPE_XREF 20140922 14:40-22-sep 86938832 0 0 4108
INDUSTRYPRODUCT 20140922 06:10-22-sep 25944784 64881 0 14
INDUSTRYPRODUCT 20140918 10:00-18-sep 27159040 72090 0 66
LOAD_COMPANY 20140922 05:50-22-sep 4385088 9366539 0 3615
LOAD_COMPANY 20140918 10:00-18-sep 4743376 9364491 0 7722
RADIOSTATIONGROUP 20140922 05:50-22-sep 1193168 0 0 6
RADIOSTATIONGROUP 20140918 10:00-18-sep 4281488 0 0 36
SALES_PERSON_REP 20140922 04:10-22-sep 848 86508 0 2
SALES_PERSON_REP 20140918 04:40-18-sep 896 92652 0 24
DBA query 3: This one shows overall of the query buffer_get_total during the run of problematic query. compare the ok day and problematic day.
col buffer_gets_DELTA for 999,999,999
col buffer_gets_total for 999,999,999,999
col start_time for a12
col end_time for a12
col executions_total for 999999999
col executions_delta for 999999999
select snap_id,begin_interval_time from (select * from DBA_HIST_SNAPSHOT where BEGIN_INTERVAL_TIME > sysdate-2 order by BEGIN_INTERVAL_TIME desc) where rownum < 100;
select distinct sql_id,PLAN_HASH_VALUE,to_char(BEGIN_INTERVAL_TIME,'hh24:mi-dd-mon') start_time,to_char(end_intervAL_TIME,'hh24:mi-dd-mon') end_time,
executions_total,executions_delta,
BUFFER_GETS_DELTA,buffer_gets_total,
--round(buffer_gets_delta/EXECUTIONS_DELTA) "gets/exec",
round(cpu_time_delta/1000000) "cpu_del(s)",round(ELAPSED_TIME_DELTA/1000000) "ele_del(s)"
from dba_hist_sqlstat st, DBA_HIST_SNAPSHOT sn
where st.snap_id between &begin_snap_id and &end_snap_id
and st.snap_id=sn.snap_id
and sql_id='&sql_id'
order by to_char(BEGIN_INTERVAL_TIME,'hh24:mi-dd-mon');
--order by ELAPSED_TIME_DELTA desc;
undefine snap_id
undefine sql_id
sample query result is:
SQL_ID PLAN_HASH_VALUE START_TIME END_TIME EXECUTIONS_TOTAL EXECUTIONS_DELTA BUFFER_GETS_DELTA BUFFER_GETS_TOTAL cpu_del(s) ele_del(s)
------------- --------------- ------------ ------------ ---------------- ---------------- ----------------- ----------------- ---------- ----------
0fcvv8rsqyh59 3589643954 05:20-05-sep 05:30-05-sep 1 1 13,633,017 13,633,017 108 185
0fcvv8rsqyh59 3589643954 05:30-05-sep 05:40-05-sep 1 0 19,366,362 32,999,379 357 596
0fcvv8rsqyh59 3589643954 05:40-05-sep 05:50-05-sep 1 0 12,337,385 45,345,660 355 591
0fcvv8rsqyh59 3589643954 05:50-05-sep 06:00-05-sep 1 0 10,171,499 55,517,159 365 595
0fcvv8rsqyh59 3589643954 06:00-05-sep 06:10-05-sep 1 0 8,503,090 64,050,934 370 598
0fcvv8rsqyh59 3589643954 06:10-05-sep 06:20-05-sep 1 0 7,752,640 71,803,574 371 598
0fcvv8rsqyh59 3589643954 06:20-05-sep 06:30-05-sep 1 0 913,075 72,716,649 46 73
long story short, I find out that there is one table that account for 80% of logical_total, the table has only 4k rows in it. checking the query plan, I am able to remove the "distinct" keyword from the query, creating index on the join column, then the logical_total on this table is reduced significantly, hence the query elapsed time is reduced to 8 minutes!
For security reason, I will not post the query detail etc in this post, but the key is to find out which table has the most of logical read, from dba_hist_seg_stat!
Further more, I use the following query to link sql_id and segment to see segment logical read used by specific sql_id.
col BEGIN_INTERVAL_TIME format a25
col object_name format a25
col start_time format a15
select distinct object_name,
to_char(BEGIN_INTERVAL_TIME,'hh24:mi-dd-mon') start_time,
LOGICAL_READS_DELTA lgcl_delta,
LOGICAL_READS_TOTAL lgcl_totl,
PHYSICAL_READS_TOTAL phy_totl,
PHYSICAL_READS_DELTA phy_delta,
SPACE_USED_TOTAL space_total,
SPACE_USED_DELTA space_delta,
TABLE_SCANS_TOTAL tscan_totl,
TABLE_SCANS_DELTA tscan_del,
CHAIN_ROW_EXCESS_TOTAL chain_row
from
dba_hist_seg_stat a,
DBA_HIST_SNAPSHOT b,
DBA_HIST_SQL_PLAN c
where sql_id='&sqlid'
and trunc(BEGIN_INTERVAL_TIME) in (trunc(sysdate-&firstdays), trunc(sysdate-&seconddays))
and obj#=c.object#
and a.snap_id=b.snap_id
order by object_name,
to_char(BEGIN_INTERVAL_TIME,'hh24:mi-dd-mon')
/
Comments
Post a Comment