一。问题由来：
xxx数据库上一个sql性能突然下降，从原来的耗时不到1秒，降低到8秒左右，而涉及到的表数据量并没有发生大的变化，将数据导入到测试环境中执行，耗时35秒之多
二。初步分析
通过10046事件，可以跟踪到执行计划每一步的具体耗时及逻辑读情况：
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.01 166 253 0 0
Fetch 1 34.45 33.90 2 517451 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 34.47 33.92 168 517704 0 0
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 30
Rows Row Source Operation
------- ---------------------------------------------------
0 COUNT STOPKEY (cr=517704 pr=168 pw=0 time=33922798 us)
0 FILTER (cr=517704 pr=168 pw=0 time=33922786 us)
10048 FILTER (cr=10809 pr=168 pw=0 time=840754 us)
10048 NESTED LOOPS (cr=10556 pr=2 pw=0 time=757217 us)
10048 HASH JOIN RIGHT ANTI (cr=506 pr=2 pw=0 time=284828 us)
0 TABLE ACCESS FULL xxxxxxxx (cr=253 pr=2 pw=0 time=1615 us)
10048 TABLE ACCESS FULL xxxxxxxx (cr=253 pr=0 pw=0 time=114843 us)
10048 TABLE ACCESS BY INDEX ROWID xxxxxxxx (cr=10050 pr=0 pw=0 time=329470 us)
10048 INDEX UNIQUE SCAN SYS_C003109 (cr=2 pr=0 pw=0 time=123416 us)(object id 11094)
0 TABLE ACCESS FULL xxxxxxxx (cr=253 pr=166 pw=0 time=13187 us)
48 SORT AGGREGATE (cr=506895 pr=0 pw=0 time=33057678 us)
482352 FILTER (cr=506895 pr=0 pw=0 time=31909446 us)
482352 NESTED LOOPS (cr=506642 pr=0 pw=0 time=29978641 us)
482352 HASH JOIN RIGHT ANTI (cr=24288 pr=0 pw=0 time=12130773 us)
0 TABLE ACCESS FULL xxxxxxxx (cr=12144 pr=0 pw=0 time=56060 us)
482352 TABLE ACCESS FULL xxxxxxxx (cr=12144 pr=0 pw=0 time=4878205 us)
482352 TABLE ACCESS BY INDEX ROWID xxxxxxxx (cr=482354 pr=0 pw=0 time=13310230 us)
482352 INDEX UNIQUE SCAN SYS_C003109 (cr=2 pr=0 pw=0 time=5419992 us)(object id 11094)
0 TABLE ACCESS FULL xxxxxxxx (cr=253 pr=0 pw=0 time=1032 us)
实际上，从10046的结果来看，可以看出主要的耗时及逻辑读消耗在一个子查询上面：
AND a.last_time =
(SELECT MIN (c.last_time)
FROM xxxxxxxx c, xxxxxxxx d
WHERE c.branch_code = d.branch_code
AND d.status = 'Y'
AND d.status1 = 'Y'
AND ( ( c.op_time <= '153316'
AND TO_CHAR (c.work_day, 'yyyymmdd') = '20110314' )
OR TO_CHAR (c.work_day, 'yyyymmdd') < '20110314' )
AND c.status = '0'
AND c.cust_id NOT IN (
SELECT cust_id
FROM xxxxxxxx
WHERE status = '2'
AND last_time > (to_date('20110316','yyyymmdd') - 5 / 24 / 60))
AND ( a.branch_code not in('610000000','371000000','460000000','540000000' ) or a.product_type='03')
AND not exists
(select * from xxxxxxxx where product_type = '03'
and status= '2'
and last_time > TO_DATE ('20110314153316', 'yyyymmddhh24miss') - (1/24/60)*10
)
)
执行这个子查询时， 由于条件AND ( a.branch_code not in('610000000','371000000','460000000','540000000' ) or a.product_type='03') 的存在，需要执行一个filter的操作，
初步来看，这个filter操作的效率的高低，决定了这条sql执行总体耗时和逻辑读的高低。
三。变化无常的filter操作
为了抓住问题的根本所在，在初步推测filter操作可能是元凶之后，我们可以将sql简化，只保留一个filter操作，然后针对这个简化的sql进行分析
xxxxxx@xxxxxx>set timing on
xxxxxx@xxxxxx>SELECT /*+ gather_plan_statistics */ a.branch_code
2 FROM xxxxxxxx a
3 WHERE
4 a.last_time =
5 (SELECT MIN (c.last_time)
6 FROM xxxxxxxx c
7 WHERE
8 a.branch_code not in('6' )
9 )
10 AND ROWNUM <= 1 ;
BRANCH_CO
---------
510000000
Elapsed: 00:00:08.29
-----------------------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows |E-Bytes| Cost (%CPU)| E-Time | A-Rows | A-Time | Buffers |
-----------------------------------------------------------------------------------------------------------------------------------
|* 1 | COUNT STOPKEY | | 1 | | | | | 1 |00:00:08.09 | 15208 |
|* 2 | FILTER | | 1 | | | | | 1 |00:00:08.09 | 15208 |
| 3 | TABLE ACCESS FULL | xxxxxxxx | 1 | 14526 | 255K| 69 (0)| 00:00:01 | 1472 |00:00:00.01 | 28 |
| 4 | SORT AGGREGATE | | 60 | 1 | 8 | | | 60 |00:00:08.07 | 15180 |
|* 5 | FILTER | | 60 | | | | | 871K|00:00:06.11 | 15180 |
| 6 | TABLE ACCESS FULL| xxxxxxxx | 60 | 14526 | 113K| 69 (0)| 00:00:01 | 871K|00:00:02.62 | 15180 |
-----------------------------------------------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
1 - filter(ROWNUM<=1)
2 - filter("A"."LAST_TIME"=)
5 - filter(:B1<>'6')
显然，从执行计划的结果来看，子查询共执行了60次，耗时达到了8秒，逻辑读高达15208，此时查看branch_code的唯一值数量：
xxxxxx@xxxxxx>select count(distinct(branch_code)) from xxxxxxxx;
COUNT(DISTINCT(BRANCH_CODE))
----------------------------
35
Elapsed: 00:00:00.10
然后将修改branch_code的值，将所有记录的branch_code改成同一个值。
xxxxxx@xxxxxx>update xxxxxxxx set branch_code='420000000';
14526 rows updated.
Elapsed: 00:00:00.75
xxxxxx@xxxxxx>commit;
Commit complete.
Elapsed: 00:00:00.06
xxxxxx@xxxxxx>select count(distinct(branch_code)) from xxxxxxxx;
COUNT(DISTINCT(BRANCH_CODE))
----------------------------
1
Elapsed: 00:00:00.07
xxxxxx@xxxxxx>SELECT /*+ gather_plan_statistics */ a.branch_code
2 FROM xxxxxxxx a
3 WHERE
4 a.last_time =
5 (SELECT MIN (c.last_time)
6 FROM xxxxxxxx c
7 WHERE
8 a.branch_code not in('6' )
9 )
10 AND ROWNUM <= 1 ;
BRANCH_CO
---------
420000000
Elapsed: 00:00:00.14
Plan hash value: 188740468
-----------------------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows |E-Bytes| Cost (%CPU)| E-Time | A-Rows | A-Time | Buffers |
-----------------------------------------------------------------------------------------------------------------------------------
|* 1 | COUNT STOPKEY | | 1 | | | | | 1 |00:00:00.13 | 281 |
|* 2 | FILTER | | 1 | | | | | 1 |00:00:00.13 | 281 |
| 3 | TABLE ACCESS FULL | xxxxxxxx | 1 | 14526 | 255K| 69 (0)| 00:00:01 | 1472 |00:00:00.01 | 28 |
| 4 | SORT AGGREGATE | | 1 | 1 | 8 | | | 1 |00:00:00.12 | 253 |
|* 5 | FILTER | | 1 | | | | | 14526 |00:00:00.09 | 253 |
| 6 | TABLE ACCESS FULL| xxxxxxxx | 1 | 14526 | 113K| 69 (0)| 00:00:01 | 14526 |00:00:00.03 | 253 |
-----------------------------------------------------------------------------------------------------------------------------------
这一次，仅仅是对branch_code的值做了修改，filter操作时子查询之执行了一次，逻辑读只有281，耗时也大幅降低。为了进一步证明branch唯一值的多少对执行效率的影响，
将其唯一值数量增加到与记录数相同:
xxxxxx@xxxxxx>update xxxxxxxx set branch_code=lpad(to_char(rownum),9,'0');
14526 rows updated.
Elapsed: 00:00:01.06
xxxxxx@xxxxxx>commit;
Commit complete.
Elapsed: 00:00:00.02
xxxxxx@xxxxxx>select count(distinct(branch_code)) from xxxxxxxx;
COUNT(DISTINCT(BRANCH_CODE))
----------------------------
14526
Elapsed: 00:00:00.09
xxxxxx@xxxxxx>SELECT /*+ gather_plan_statistics */ a.branch_code
2 FROM xxxxxxxx a
3 WHERE
4 a.last_time =
5 (SELECT MIN (c.last_time)
6 FROM xxxxxxxx c
7 WHERE
8 a.branch_code not in('6' )
9 )
10 AND ROWNUM <= 1 ;
BRANCH_CO
---------
000001472
Elapsed: 00:02:54.92
Plan hash value: 188740468
-----------------------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows |E-Bytes| Cost (%CPU)| E-Time | A-Rows | A-Time | Buffers |
-----------------------------------------------------------------------------------------------------------------------------------
|* 1 | COUNT STOPKEY | | 1 | | | | | 1 |00:02:50.80 | 372K|
|* 2 | FILTER | | 1 | | | | | 1 |00:02:50.80 | 372K|
| 3 | TABLE ACCESS FULL | xxxxxxxx | 1 | 14526 | 255K| 69 (0)| 00:00:01 | 1472 |00:00:00.01 | 28 |
| 4 | SORT AGGREGATE | | 1472 | 1 | 8 | | | 1472 |00:02:50.77 | 372K|
|* 5 | FILTER | | 1472 | | | | | 21M|00:02:08.38 | 372K|
| 6 | TABLE ACCESS FULL| xxxxxxxx | 1472 | 14526 | 113K| 69 (0)| 00:00:01 | 21M|00:00:42.84 | 372K|
-----------------------------------------------------------------------------------------------------------------------------------
1 - filter(ROWNUM<=1)
2 - filter("A"."LAST_TIME"=)
5 - filter(:B1<>'6')
推测得到了验证，这一次执行耗时高达2分钟54秒，子查询执行次数高达1472次，而逻辑读高达37万之多。
四。filter操作的由来
关于filter操作，请阅读《Cost-Based Oracle Fundamentals》一书中的相关章节，以下摘录部分：
if the new driving value is in the hash table
retrieve the stored return value from the in-memory hash table
retain these values as the 'current values'
set the 'current values' status to 'previously stored'
else
execute the subquery with the new driving value
retain the driving and return (output) values as 'current values'
set the 'current values' status to 'not yet stored'.
end if
由于本人水平所限，粗浅的认为，oracle在执行这个filter操作时，会对每个不同的branch_code值进行hash运算，并将其hash值保存在一个hash table中,每次检索到一个
branch_code值时，在hash table中搜索是否有相同hash值，如果存在且没有发生hash 碰撞，就不需要再执行子查询，直接返回结果，如果找不到相同的hash值，则执行子查询，
并将该branch_code的hash值保存在hash table中。 可以大致认为，branch_code的唯一值数量，hash table的大小以及所能存放的记录数多少，决定了oracle执行子查询的次数多少，也决定了sql执行的效率高低。
当然，对于filter操作，随着oracle版本的不同，即使是同样的执行计划，其执行效率相差甚大。简单测试了一下9i下的情况，查询涉及到的表与10g中的是完全一样的：
xxxxxx@xxxxxx>select count(distinct(branch_code)) from xxxxxxxx;
COUNT(DISTINCT(BRANCH_CODE))
----------------------------
35
xxxxxx@TEST>set autot on
xxxxxx@TEST>SELECT a.branch_code
2 FROM xxxxxxxx a
3 WHERE
4 a.last_time =
5 (SELECT MIN (c.last_time)
6 FROM xxxxxxxx c
7 WHERE
8 a.branch_code not in('6' )
9 )
10 AND ROWNUM <= 1 ;
BRANCH_CO
---------
510000000
Elapsed: 00:00:00.14
Execution Plan
----------------------------------------------------------
0 SELECT STATEMENT ptimizer=CHOOSE (Cost=76 Card=1 Bytes=18)
1 0 COUNT (STOPKEY)
2 1 FILTER
3 2 TABLE ACCESS (FULL) OF 'xxxxxxxx' (Cost=38 Card
=5 Bytes=90)
4 2 SORT (AGGREGATE)
5 4 FILTER
6 5 TABLE ACCESS (FULL) OF 'xxxxxxxx' (Cost=38
Card=14526 Bytes=116208)
Statistics
----------------------------------------------------------
0 recursive calls
0 db block gets
15951 consistent gets
0 physical reads
0 redo size
389 bytes sent via SQL*Net to client
499 bytes received via SQL*Net from client
2 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
1 rows processed
耗时不到一秒，再将branch_code值进行修改，与10g中的修改是一样的：
xxxxxx@TEST>update xxxxxxxx set branch_code=lpad(rownum,9,'0');
14526 rows updated.
Elapsed: 00:00:00.45
xxxxxx@TEST>commit;
Commit complete.
Elapsed: 00:00:00.02
xxxxxx@TEST>select count(distinct(branch_code)) from xxxxxxxx;
COUNT(DISTINCT(BRANCH_CODE))
----------------------------
14526
Elapsed: 00:00:00.01
xxxxxx@TEST>set autot on
xxxxxx@TEST>SELECT a.branch_code
2 FROM xxxxxxxx a
3 WHERE
4 a.last_time =
5 (SELECT MIN (c.last_time)
6 FROM xxxxxxxx c
7 WHERE
8 a.branch_code not in('6' )
9 )
10 AND ROWNUM <= 1 ;
BRANCH_CO
---------
000001350
Elapsed: 00:00:01.91
Execution Plan
----------------------------------------------------------
0 SELECT STATEMENT ptimizer=CHOOSE (Cost=76 Card=1 Bytes=18)
1 0 COUNT (STOPKEY)
2 1 FILTER
3 2 TABLE ACCESS (FULL) OF 'xxxxxxxx' (Cost=38 Card
=5 Bytes=90)
4 2 SORT (AGGREGATE)
5 4 FILTER
6 5 TABLE ACCESS (FULL) OF 'xxxxxxxx' (Cost=38
Card=14526 Bytes=116208)
Statistics
----------------------------------------------------------
0 recursive calls
0 db block gets
330776 consistent gets
0 physical reads
0 redo size
389 bytes sent via SQL*Net to client
499 bytes received via SQL*Net from client
2 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
1 rows processed
xxxxxx@TEST>set autot off
耗时变为不到2秒，逻辑读也增加到30多万，在同样的情况下，9i的效率要远远高于10g！！！
来自 “ ITPUB博客 ” ，链接：https://blog.itpub.net/10972173/viewspace-706322/ ，如需转载，请注明出处，否则将追究法律责任。
上一篇：
listener挂起时的诊断步骤
请登录后发表评论
登录
全部评论
