性能优化 ---- db file sequential read

今天遇到了一个比较奇怪的问题，客户说把一个表分区后SELECT处理变慢了。本来SELECT处理变慢是很常见的问题，可是我看了10046Trace后还是感觉有些地方值得深究一下。

我们先来看看Tkprof之后的10046Trace。

◆分区前

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0         40          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        1      2.41       2.58      15177      15177          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3      2.42       2.59      15177      15217          0           1

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 78  
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         1          1          1  SORT AGGREGATE (cr=15177 pr=15177 pw=0 time=2583401 us)
         0          0          0   FIRST ROW  (cr=15177 pr=15177 pw=0 time=2583388 us cost=5601 size=14 card=1)
         0          0          0    INDEX RANGE SCAN (MIN/MAX) XXXX_IX03 (cr=15177 pr=15177 pw=0 time=2583385 us cost=5601 size=14 card=1)(object id 254189)

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  db file sequential read                     15177        0.00          0.36

◆分区后

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        1      2.46       4.10      14828      14828          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3      2.46       4.10      14828      14828          0           1

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 78  
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         1          1          1  SORT AGGREGATE (cr=14828 pr=14828 pw=0 time=4103521 us)
         0          0          0   FIRST ROW  (cr=14828 pr=14828 pw=0 time=4103511 us cost=4508 size=14 card=1)
         0          0          0    INDEX RANGE SCAN (MIN/MAX) XXXX_IX15 (cr=14828 pr=14828 pw=0 time=4103509 us cost=4508 size=14 card=1)(object id 352194)

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  db file sequential read                     14828        0.00          1.85

从上面的数据来看，我们发现执行时间的差异主要来自索引的I/O待机“db file sequential read”。为了看看具体有啥区别，我们再来看看Tkprof之前的10046Trace文件。

◆分区前

**-----------------------------------------------
WAIT #139891128650264: nam='db file sequential read' ela= 12 file#=15 block#=702838 blocks=1 obj#=254189 tim=45007446902
WAIT #139891128650264: nam='db file sequential read' ela= 11 file#=15 block#=702839 blocks=1 obj#=254189 tim=45007447264
WAIT #139891128650264: nam='db file sequential read' ela= 11 file#=15 block#=702840 blocks=1 obj#=254189 tim=45007447457
WAIT #139891128650264: nam='db file sequential read' ela= 75 file#=15 block#=702841 blocks=1 obj#=254189 tim=45007447706
WAIT #139891128650264: nam='db file sequential read' ela= 12 file#=15 block#=702842 blocks=1 obj#=254189 tim=45007447908
WAIT #139891128650264: nam='db file sequential read' ela= 10 file#=15 block#=702843 blocks=1 obj#=254189 tim=45007448123
WAIT #139891128650264: nam='db file sequential read' ela= 11 file#=15 block#=702844 blocks=1 obj#=254189 tim=45007448314
WAIT #139891128650264: nam='db file sequential read' ela= 15 file#=15 block#=702845 blocks=1 obj#=254189 tim=45007448503
WAIT #139891128650264: nam='db file sequential read' ela= 10 file#=15 block#=702846 blocks=1 obj#=254189 tim=45007448804
WAIT #139891128650264: nam='db file sequential read' ela= 11 file#=15 block#=702847 blocks=1 obj#=254189 tim=45007449000
-----------------------------------------------**

◆分区后

-----------------------------------------------
WAIT #139891129837744: nam='db file sequential read' ela= 1535 file#=15 block#=5593761 blocks=1 obj#=352194 tim=45021020310
WAIT #139891129837744: nam='db file sequential read' ela= 1642 file#=15 block#=5593777 blocks=1 obj#=352194 tim=45021022129
WAIT #139891129837744: nam='db file sequential read' ela= 1037 file#=15 block#=5593538 blocks=1 obj#=352194 tim=45021023332
WAIT #139891129837744: nam='db file sequential read' ela= 947 file#=15 block#=5593554 blocks=1 obj#=352194 tim=45021024455
WAIT #139891129837744: nam='db file sequential read' ela= 1220 file#=15 block#=5593570 blocks=1 obj#=352194 tim=45021025868
WAIT #139891129837744: nam='db file sequential read' ela= 998 file#=15 block#=5593586 blocks=1 obj#=352194 tim=45021027237
WAIT #139891129837744: nam='db file sequential read' ela= 1109 file#=15 block#=5593602 blocks=1 obj#=352194 tim=45021028638
WAIT #139891129837744: nam='db file sequential read' ela= 1138 file#=15 block#=5593618 blocks=1 obj#=352194 tim=45021030019
WAIT #139891129837744: nam='db file sequential read' ela= 1251 file#=15 block#=5593634 blocks=1 obj#=352194 tim=45021031509
WAIT #139891129837744: nam='db file sequential read' ela= 1518 file#=15 block#=5593650 blocks=1 obj#=352194 tim=45021033196

…略…

WAIT #139891129837744: nam='db file sequential read' ela= 11 file#=15 block#=5593539 blocks=1 obj#=352194 tim=45021040872
WAIT #139891129837744: nam='db file sequential read' ela= 10 file#=15 block#=5593555 blocks=1 obj#=352194 tim=45021041034
WAIT #139891129837744: nam='db file sequential read' ela= 10 file#=15 block#=5593571 blocks=1 obj#=352194 tim=45021041198
WAIT #139891129837744: nam='db file sequential read' ela= 10 file#=15 block#=5593587 blocks=1 obj#=352194 tim=45021041350
WAIT #139891129837744: nam='db file sequential read' ela= 11 file#=15 block#=5593603 blocks=1 obj#=352194 tim=45021041498
WAIT #139891129837744: nam='db file sequential read' ela= 10 file#=15 block#=5593619 blocks=1 obj#=352194 tim=45021041661
WAIT #139891129837744: nam='db file sequential read' ela= 11 file#=15 block#=5593635 blocks=1 obj#=352194 tim=45021041813
WAIT #139891129837744: nam='db file sequential read' ela= 26 file#=15 block#=5593651 blocks=1 obj#=352194 tim=45021041980
WAIT #139891129837744: nam='db file sequential read' ela= 10 file#=15 block#=5593667 blocks=1 obj#=352194 tim=45021042177

…略…

WAIT #139891129837744: nam='db file sequential read' ela= 1007 file#=15 block#=5593882 blocks=1 obj#=352194 tim=45021070164
WAIT #139891129837744: nam='db file sequential read' ela= 1437 file#=15 block#=5593898 blocks=1 obj#=352194 tim=45021071788
WAIT #139891129837744: nam='db file sequential read' ela= 1158 file#=15 block#=5593914 blocks=1 obj#=352194 tim=45021073104
WAIT #139891129837744: nam='db file sequential read' ela= 1040 file#=15 block#=5593930 blocks=1 obj#=352194 tim=45021074307
WAIT #139891129837744: nam='db file sequential read' ela= 958 file#=15 block#=5593946 blocks=1 obj#=352194 tim=45021075424
WAIT #139891129837744: nam='db file sequential read' ela= 1145 file#=15 block#=5593962 blocks=1 obj#=352194 tim=45021076743
WAIT #139891129837744: nam='db file sequential read' ela= 997 file#=15 block#=5593978 blocks=1 obj#=352194 tim=45021077917
WAIT #139891129837744: nam='db file sequential read' ela= 1011 file#=15 block#=5593994 blocks=1 obj#=352194 tim=45021079129
WAIT #139891129837744: nam='db file sequential read' ela= 898 file#=15 block#=5594010 blocks=1 obj#=352194 tim=45021080218
WAIT #139891129837744: nam='db file sequential read' ela= 1450 file#=15 block#=5594026 blocks=1 obj#=352194 tim=45021081838
WAIT #139891129837744: nam='db file sequential read' ela= 1266 file#=15 block#=5594042 blocks=1 obj#=352194 tim=45021083270

…略…

WAIT #139891129837744: nam='db file sequential read' ela= 11 file#=15 block#=5593867 blocks=1 obj#=352194 tim=45021088206
WAIT #139891129837744: nam='db file sequential read' ela= 11 file#=15 block#=5593883 blocks=1 obj#=352194 tim=45021088362
WAIT #139891129837744: nam='db file sequential read' ela= 10 file#=15 block#=5593899 blocks=1 obj#=352194 tim=45021088494
WAIT #139891129837744: nam='db file sequential read' ela= 10 file#=15 block#=5593915 blocks=1 obj#=352194 tim=45021088628
WAIT #139891129837744: nam='db file sequential read' ela= 10 file#=15 block#=5593931 blocks=1 obj#=352194 tim=45021088764
WAIT #139891129837744: nam='db file sequential read' ela= 9 file#=15 block#=5593947 blocks=1 obj#=352194 tim=45021088899
WAIT #139891129837744: nam='db file sequential read' ela= 10 file#=15 block#=5593963 blocks=1 obj#=352194 tim=45021089031
WAIT #139891129837744: nam='db file sequential read' ela= 11 file#=15 block#=5593979 blocks=1 obj#=352194 tim=45021089205
WAIT #139891129837744: nam='db file sequential read' ela= 10 file#=15 block#=5593995 blocks=1 obj#=352194 tim=45021089339
WAIT #139891129837744: nam='db file sequential read' ela= 10 file#=15 block#=5594011 blocks=1 obj#=352194 tim=45021089485

…略…

WAIT #139891129837744: nam='db file sequential read' ela= 1412 file#=15 block#=5597225 blocks=1 obj#=352194 tim=45021203277
WAIT #139891129837744: nam='db file sequential read' ela= 1238 file#=15 block#=5597240 blocks=1 obj#=352194 tim=45021204680
WAIT #139891129837744: nam='db file sequential read' ela= 1027 file#=15 block#=5597255 blocks=1 obj#=352194 tim=45021205889
WAIT #139891129837744: nam='db file sequential read' ela= 1084 file#=15 block#=5597270 blocks=1 obj#=352194 tim=45021207169
WAIT #139891129837744: nam='db file sequential read' ela= 1263 file#=15 block#=5597285 blocks=1 obj#=352194 tim=45021208594
WAIT #139891129837744: nam='db file sequential read' ela= 1265 file#=15 block#=5597300 blocks=1 obj#=352194 tim=45021210019

…略…

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

通过上面的原始Trace,我们可以看到分区前的“db file sequential read”都是比较平均的10几个微秒，而分区后则出现间歇性的高达数千微秒的长待机。

关于具体的原因，现在还在调查，先说说我的几个猜测吧。

1.访问对象数据块的位置和随机I/O的影响。表被分区后，索引的“CLUSTERING_FACTOR”受到分区Key的影响，聚簇情况发生变化。

2.单纯的I/O性能的变化影响。

等调查结果出来后我再更新。

2021/01/18 9：00AM
客户给了测试结果，原因就是单纯的I/O问题。