oracle db file sequential read,性能优化 ---- 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问题。