在调查一个逻辑从库(数据库版本10.2.0.4)的性能问题时,发现的一个sql语句:
当然,这里逻辑IO偏高,主要是因为步骤8,9循环的次数太多了,主要的时间消耗也是发生在步骤8,9上了.当然,一开始我认为这里的问题和这个系统中Optimizer_Index_Caching=60有关,我在另一个系统中遇到过类似的问题,我在这篇文章http://blog.csdn.net/zhaosj1726/archive/2010/12/04/6054650.aspx中论及过(Optimizer_Index_Caching<>0,并且nl连接的内表使用唯一索引扫描的时候,索引访问的cost可能就会变成0,也就是说不管外表返回的card有多大,内表访问是完全免费的,导致优化器选择了性能很差的执行计划),一开始我没想细到:Optimizer_Index_Caching=60时,索引的访问代价确实可能按0计算了,可回访表的代价1还是有的呀,这里51942次,optimizer_index_cost_adj=50的情况下,访问内表的代价也有25971呢,这样和执行计划显示的cost相差很大的,不过一开始我没有细想这些,其实也是这里的执行计划的显示误导了我.
一开始我关注的是步骤4实际返回了970行数据,而估算却是返回1行数据,注意这里的1很可能是代表0的,所以这个问题需要调查一下.
明显,这里的逻辑IO和执行时间都大幅的下降了.我们不去论及为什么作为一个sql的一部分时选择了nl + INDEX UNIQUE SCAN,而作为一个单独的sql时却选择了hash_sj.我们关注的是这里card估算是1524,而不是上面的1了.
这里是几乎相同的执行计划了(当然还是有些不同的,比如这里多了一个view行,这里是hash unique,而不是sort unique),这里的card估算是1601,也不是上面的1.
其实,这里还有一件事情挺有意思的:同一个sql,不同的执行计划,card估算居然是不同的?
看来还是需要做一个10053事件:
我把sql稍微改写了一下,就是不同部分的同样对象名给了不同的别名,这样便于区分,因为10053 trace文件中都在论及某个对象时给出了别名的。
从后往前推(因为我们这里主要是关注这里为什么得到了1这个card,而不是这个执行计划是不是最优的)
我们往上找连接顺序7:
Join order[7]: CMS_ARTICLE_KEYWORDS[CMS_ARTICLE_KEYWORDS]#3 CMS_ARTICLE_COMPOSE[A6]#0 CMS_BLOCK_ARTICLE[B1]#1 VW_NSO_1[VW_NSO_1]#2
SORT resource Sort statistics
Sort width: 2455 Area size: 1048576 Max Area size: 429496320
Degree: 1
Blocks to Sort: 159 Row size: 25 Total Rows: 51942 --这个是排序的行数
Initial runs: 2 Merge passes: 1 IO Cost / pass: 88
Total IO sort cost: 247 Total CPU sort cost: 49141986
Total Temp space used: 2515000
***************
Now joining: CMS_ARTICLE_COMPOSE[A6]#0
***************
NL Join
Outer table: Card: 1.00 Cost: 304.35 Resp: 304.35 Degree: 1 Bytes: 13
Inner table: CMS_ARTICLE_COMPOSE Alias: A6
Join Card: 0.03 = outer (1.00) * inner (1601.23) * sel (1.9415e-05)
Best:: JoinMethod: NestedLoop
Cost: 305.35 Degree: 1 Resp: 305.35 Card: 0.03 Bytes: 41
Best so far: Table#: 3 cost: 304.3459 card: 1.0000 bytes: 13
Table#: 0 cost: 305.3465 card: 0.0311 bytes: 41
Table#: 1 cost: 307.3506 card: 0.0311 bytes: 79
Table#: 2 cost: 312.3564 card: 0.0310 bytes: 92
这里的顺序和执行计划中的顺序是一致的,而且代价也是一致的,注意这里第一次连接的时候,外表也就是CMS_ARTICLE_KEYWORDS表估算的card是1.
再往前看单表访问路径处CMS_ARTICLE_KEYWORDS的card的估算:
Table: CMS_ARTICLE_KEYWORDS Alias: CMS_ARTICLE_KEYWORDS
Card: Original: 6592549 Rounded: 51942 Computed: 51942.02 Non Adjusted: 51942.02
Best:: AccessPath: IndexRange Index: UK_CMS_ARTICLE_KEYWORDS
Cost: 51.61 Degree: 1 Resp: 51.61 Card: 51942.02 Bytes: 0
注意这里,card还是对的:51942,这一点在上面的排序行数:51942处也可以得到佐证.可经过一个sort操作(sort unique)忽然就变为1了,为什么呢?感觉bug的可能性还是很大的.
其实,这里无论是10053文件里的执行计划还是display_cursor显示的执行计划,它们的显示似乎都是有问题的,它们都是显示:sort unique后,card还是51942,cost还是52,似乎是nl后card变为了1,cost变成了305似的.但从10053文件看来,似乎不是这样的,应该是sort unique后:card=1,cost=304.35,它这里的304.35是如何计算出来的呢?就是cost(IndexRange UK_CMS_ARTICLE_KEYWORDS)+排序的io代价+排序的cpu代价: 51.61 + 247 + 49141986000/714000000/(10+ 8192/4096) = 304.3455
(
Using NOWORKLOAD Stats
CPUSPEED: 714 millions instruction/sec
IOTFRSPEED: 4096 bytes per millisecond (default is 4096)
IOSEEKTIM: 10 milliseconds (default is 10)
使用8k大小的数据块
)
因为nl的外表返回1行,内表的访问成本是:
OPTIMIZER PERCENT INDEX CACHING = 60
Access Path: index (UniqueScan)
Index: PK_ID
resc_io: 1.00 resc_cpu: 9339
ix_sel: 4.1692e-07 ix_sel_with_filters: 4.1692e-07
NL Join: Cost: 305.35 Resp: 305.35 Degree: 1
所以nl连接后的总成本cost=304.35 + 1*1 = 305.35,nl连接后的card是0.03,显示为1.
总结一下:总的来说,就是sort unique后,card的估算忽然变成了1,实际却大得多,导致了随后的一系列问题.当然,这里执行计划的显示也存在一些问题,似乎没有正确的显示实际的估算情况.至于sort unique后为什么card的估算就变成1了,10053 trace文件没有给出任何的信息,也不清楚,我觉得bug的可能性还是有的.