http://www.db2china.net/club/thread-18522-1-3.html

客户环境：db2 v82 fp13, aix 5.3一个采购管理系统，

问题描述：某些页面响应时间很慢，系统管理员通过系统监控，发现 CPU、I/O资源使用率高。


问题分析：这是典型的性能问题，分析的思路自然从database snapshot入手，发现rows read/rows selected过高，达到600左右，观察bufferpool同步读I/O，发现很低。这说明database有性能瓶颈。接着抓取sql snapshot快照，发现很多语句有问题。以下是找到的比较有意思的一条。

通过sql快照：



Number of executions               = 3

Number of compilations             = 1

Worst preparation time (ms)        = 18

Best preparation time (ms)         = 18

Internal rows deleted              = 0

Internal rows inserted             = 0

Rows read                          = 225976098

Internal rows updated              = 0

Rows written                       = 77448

Statement sorts                    = 5520

Statement sort overflows           = 6

Total sort time                    = 108

Buffer pool data logical reads     = 166248

Buffer pool data physical reads    = 0

Buffer pool temporary data logical reads   = 3391188

Buffer pool temporary data physical reads  = 0

Buffer pool index logical reads    = 404475

Buffer pool index physical reads   = 3467

Buffer pool temporary index logical reads  = 0

Buffer pool temporary index physical reads = 0

Total execution time (sec.ms)      = 134.657283

Total user cpu time (sec.ms)       = 96.790617

Total system cpu time (sec.ms)     = 1.878419

Statement text                     = select sum(a.zctamount) amount,aa.invoicecode code,aa.status from invoicedetail a,invoice aa,billing b,deliverydetail c,orderdetail d, ord dd,ordertype e   WHERE 1=1   and a.invoiceid=aa.invoiceid and a.billingid=b.billingid and b.relatedtrandetailid=c.deliverydetailid and c.orderdetailid=d.orderdetailid   and dd.ordertypeid=e.ordertypeid and dd.orderid=d.orderid and e.saleflag>0   and aa.partnerid=dd.billto and aa.orgid=dd.sellerid and b.billto=dd.billto and a.relatedtrantype=10 and aa.status=80   and dd.sellerid=100000001      and dd.billto=100002441   and dd.status in ( 50, 60, 70)      and dd.ordertypeid in (100000242,100000000,100000001,100000002,100000003,100000004,100000011,100000005,100000170,100000006,100000007,100000008,100000151,100000155,100000156,100000157,100000158,100000070,100000163,100000165,100000194,100000202,100000203,100000159,100000132)   GROUP BY  aa.invoicecode ,aa.status
复制代码


发现该语句每次执行大概需要45秒，每次读的行数7100万行，发生排序1800次，根据这些指标，说明该SQL存在严重的性能问题。Rows_read对系统的性能影响很大，通常是由于过多的表扫描引起。


找到了语句，接下来很自然的看它的执行计划。通过explain + db2exfmt，发现语句的cost为537.262，也不算高啊。


继续分析，发现很多连接操作符是MSJOIN和NLJOIN，根据经验，这些操作符有可能是出问题的地方。我们找到比较可疑的一个NLJOIN（21）。（篇幅所限，只粘贴了最关键的部分）







这个NLJOIN的预测rows只有0.0529，继续定位它的左子树，Fetch的cost达到165，而IXSCAN 25）的估计返回值是83行，以下是25)操作符的详细解释：







    25) IXSCAN: (Index Scan)

         Cumulative Total Cost:         25.7581

         Cumulative CPU Cost:      210702

         Cumulative I/O Cost:      2

         Cumulative Re-Total Cost: 0.0427741

         Cumulative Re-CPU Cost:   155241

         Cumulative Re-I/O Cost:   0

         Cumulative First Row Cost:     25.7183

         Estimated Bufferpool Buffers: 3



         Arguments:

         ---------

         MAXPAGES: (Maximum pages for prefetch)

             1

         PREFETCH: (Type of Prefetch)

             NONE

         ROWLOCK : (Row Lock intent)

             NONE

         SCANDIR : (Scan Direction)

             FORWARD

         TABLOCK : (Table Lock intent)

             INTENT NONE

         TBISOLVL: (Table access Isolation Level)

             CURSOR STABILITY



         Predicates:

         ----------

         7) Start Key Predicate

             Relational Operator:      Equal (=)

             Subquery Input Required: No

             Filter Factor:            0.000172325



             Predicate Text:

             --------------

             (Q2."BILLTO" = 100002441)



         7) Stop Key Predicate

             Relational Operator:      Equal (=)

             Subquery Input Required: No

             Filter Factor:            0.000172325



             Predicate Text:

             --------------

             (Q2."BILLTO" = 100002441)





         Input Streams:

         -------------

             24) From Object DB2ADMIN.ORD_IDX9



                  Estimated number of rows: 486884

                  Number of columns:        2

                  Subquery predicate ID:         Not Applicable



                  Column Names:

                  ------------

                  +Q2.$RID$+Q2."BILLTO"





         Output Streams:

         --------------

             25) To Operator #24



                  Estimated number of rows: 83.9021

                  Number of columns:        1

                  Subquery predicate ID:         Not Applicable



                  Column Names:

                  ------------

                  +Q2."BILLTO"
复制代码

附件: 您需要登录才可以下载或查看附件。没有帐号？注册
本主题由 System 于 2012-5-15 05:00 撤销鉴定



 

发短消息
加为好友
飞天 当前离线

UID6761 帖子185 主题11 金钱1333 米 阅读权限50 注册时间2009-9-15  
2#
五星级会员 飞天发表于 2011-6-20 18:20 | 只看该作者
本帖最后由 飞天 于 2011-6-20 18:28 编辑

回复 1# 飞天


观察到该操作符执行的过滤条件为Q2."BILLTO" = 100002441，那么我们要看一下该条件的返回行数是多少，结果是2580，而估计的值是83.9，差了几十倍。


db2 “select count(*) from ord where BILLTO=100002441”

2957



这是典型的优化器低估问题，那么为什么会出现这种情况呢？统计信息，没错，就是统计信息，如果统计信息不准确，就会误导优化器选择错误的路径。


这时，检查syscat.tables的stats_time统计时间，发现该表最近做过统计信息收集。那么为什么造成这种情况呢？继续通过以下语句查看数据分布情况，

db2 “select billto, count(*) from ord group by billto order by desc”


发现数据及其不均匀，这时可以怀疑分布统计信息问题。查看sysstat.coldist系统表，果然不出所料，该表并没有做分布统计信息。这时，执行 runstats with distribution。但奇怪的是，执行后，访问计划没有变，时间仍然为45秒。




继续查sysstat.coldist，发现收集了10个frequency value，但查询条件100002441并没有出现在该表中，也就是并没有为该值收集统计信息。



TABNAME    COLNAME    TYPE SEQNO  COLVALUE      VALCOUNT   DISTCOUNT          

---------- ---------- ---- ------ ------------ --------- ----------

ORD        BILLTO     F         1 100000002         5145          -

ORD        BILLTO     F         2 100004319         4533          -

ORD        BILLTO     F         3 100008682         4129          -

ORD        BILLTO     F         4 100000003         4001          -

ORD        BILLTO     F         5 100004037         3696          -

ORD        BILLTO     F         6 100017876         3435          -

ORD        BILLTO     F         7 100005877         3309          -

ORD        BILLTO     F         8 100000001         3195          -

ORD        BILLTO     F         9 100004046         3071          -

ORD        BILLTO     F        10 100004030         3008          -

ORD        BILLTO     Q         1 100000001         3195          1

ORD        BILLTO     Q         2 100001808        26186         85

ORD        BILLTO     Q         3 100002389        51546        179

ORD        BILLTO     Q         4 100003137        76945        276

ORD        BILLTO     Q         5 100003272       102535        355

ORD        BILLTO     Q         6 100003993       128771        513

ORD        BILLTO     Q         7 100004078       154800        559

ORD        BILLTO     Q         8 100004558       179535        706

ORD        BILLTO     Q         9 100005661       205113        964

ORD        BILLTO     Q        10 100006660       231133       1192

ORD        BILLTO     Q        11 100007976       256415       1489

ORD        BILLTO     Q        12 100008682       282549       1695

ORD        BILLTO     Q        13 100009725       307643       1923

ORD        BILLTO     Q        14 100011096       333224       2257

ORD        BILLTO     Q        15 100011827       359223       2592

ORD        BILLTO     Q        16 100013373       384522       2923

ORD        BILLTO     Q        17 100015551       410143       3295

ORD        BILLTO     Q        18 100016969       436002       3806

ORD        BILLTO     Q        19 100018193       461560       4293

ORD        BILLTO     Q        20 100024510       487015       5827
复制代码
这时更改数据库参数NUM_FREQVALUES到25，观察sysstat.coldist，发现已经为100002441 值收集了统计信息。
TABNAME COLNAME TYPE SEQNO COLVALUE VALCOUNT DISTCOUNT

---------- ---------- ---- ------ ------------ --------- ----------

ORD BILLTO F 1 100000002 5145 -

ORD BILLTO F 2 100004319 4533 -

ORD BILLTO F 3 100008682 4129 -

ORD BILLTO F 4 100000003 4001 -

ORD BILLTO F 5 100004037 3696 -

ORD BILLTO F 6 100017876 3435 -

ORD BILLTO F 7 100005877 3309 -

ORD BILLTO F 8 100000001 3195 -

ORD BILLTO F 9 100004046 3071 -

ORD BILLTO F 10 100004030 3008 -

ORD BILLTO F 11 100002441 2957 -

ORD BILLTO F 12 100011195 2690 -

ORD BILLTO F 13 100002354 2383 -

ORD BILLTO F 14 100004078 2311 -

ORD BILLTO F 15 100003218 2300 -

ORD BILLTO F 16 100002402 2252 -

ORD BILLTO F 17 100004087 2094 -

ORD BILLTO F 18 100004127 1950 -

ORD BILLTO F 19 100010910 1934 -

ORD BILLTO F 20 100003300 1894 -

ORD BILLTO F 21 100004006 1877 -

ORD BILLTO F 22 100003932 1835 -

ORD BILLTO F 23 100001852 1830 -

ORD BILLTO F 24 100002367 1796 -

ORD BILLTO F 25 100002342 1710 -

ORD BILLTO Q 1 100000001 3195 1

ORD BILLTO Q 2 100001808 26186 85

ORD BILLTO Q 3 100002389 51546 179

ORD BILLTO Q 4 100003137 76945 276

ORD BILLTO Q 5 100003272 102535 355

ORD BILLTO Q 6 100003993 128771 513

ORD BILLTO Q 7 100004078 154800 559

ORD BILLTO Q 8 100004558 179535 706

ORD BILLTO Q 9 100005661 205113 964

ORD BILLTO Q 10 100006660 231133 1192

ORD BILLTO Q 11 100007976 256415 1489

ORD BILLTO Q 12 100008682 282549 1695

ORD BILLTO Q 13 100009725 307643 1923

ORD BILLTO Q 14 100011096 333224 2257

ORD BILLTO Q 15 100011827 359223 2592

ORD BILLTO Q 16 100013373 384522 2923

ORD BILLTO Q 17 100015551 410143 3295

ORD BILLTO Q 18 100016969 436002 3806

ORD BILLTO Q 19 100018193 461560 4293

ORD BILLTO Q 20 100024510 487015 5827
复制代码

这时，再次执行该sql，响应时间降为1秒，返回的行数为90850。


Rows selected = 1317

Rows read = 90850

Rows written = 13183



Total User CPU Time used by agent (s) = 1.077983

Total System CPU Time used by agent (s) = 0.000324

Host execution elapsed time = 0.000023
复制代码

总结：

当数据分别不均匀时，需要收集分布式统计信息，否则可能会误导优化器选择错误的路径。当发现cost很低，并出现MSJOIN和NLJOIN操作符时，很大的可能是优化器低估。这时需要找到哪个操作符发生的问题，并一步一步地验证优化器估计值与实际值的偏差。