暂无图片
暂无图片
1
暂无图片
暂无图片
暂无图片

一个IO性能问题的分析与解决

白鳝的洞穴 2020-04-17
1031


问题描述客户反馈存储性能不足导致Oracle数据库经常HANG,因此换了一个新存储,新更换的存储是华为S5600T,换上去后,不会出现系统HANG的问题了,但是还是觉得比较慢。出问题时候的AWR报告的片段如下



BeginSnap: 243 24-Nov-13 18:00:03 106 4.1

End Snap: 244 24-Nov-13 19:00:46 101 4.0

Elapsed: 60.73 (mins)

DB Time: 1,459.39 (mins)

CacheSizes

~~~~~~~~~~~ Begin End

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

BufferCache: 61,440M 61,440M Std Block Size: 8K

SharedPool Size: 4,096M 4,096M Log Buffer: 96,128K

LoadProfile

~ Per Second Per Transaction

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

Redo size: 37,803,799.36 15,612,039.36

Logical reads: 218,083.70 90,063.20

Block changes: 154,377.24 63,754.00

Physical reads: 2,832.10 1,169.59

Physical writes: 10,388.01 4,289.99

User calls: 1,781.62 735.77

Parses: 26.39 10.90

Hard parses: 0.68 0.28

Sorts: 7.01 2.89

Logons: 0.50 0.21

Executes: 36.30 14.99

Transactions: 2.42


% Blocks changed per Read: 70.79 Recursive Call %: 15.74

Rollbackper transaction %: 0.05 Rows per Sort: ########


InstanceEfficiency Percentages (Target 100%)

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

Buffer Nowait %: 100.00 Redo NoWait %: 99.99

Buffer Hit %: 99.24 In-memory Sort %: 99.91

Library Hit %: 98.01 Soft Parse %: 97.41

Execute to Parse %: 27.30 Latch Hit %: 99.82

ParseCPU to Parse %: 1.69 % Non-Parse CPU: 99.98


SharedPool Statistics Begin End

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

Memory Usage %: 87.20 87.50

% SQL with executions>1: 95.92 98.04

% Memory for SQL w/exec>1: 98.59 99.36


Top5 Timed Events Avg%Total

~~~~~~~~~~~~~~~~~~ wait Call

Event Waits Time (s) (ms) Time Wait Class

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

dbfile scattered read 364,722 31,340 86 35.8 User I/O

dbfile sequential read 250,654 15,419 62 17.6 User I/O

CPUtime 12,738 14.5

dbfile parallel write 158,850 9,728 61 11.1 System I/O

directpath read 161,876 8,024 50 9.2 User I/O

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


StatisticName Time(s) % of DB Time

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

sqlexecute elapsed time 86,529.2 98.8

DBCPU 12,737.9 14.5

parsetime elapsed 130.9 .1

hardparse elapsed time 128.0 .1

PL/SQLexecution elapsed time 22.0 .0

sequenceload elapsed time 5.8 .0

connectionmanagement call elapsed time 3.0 .0

failedparse elapsed time 0.1 .0

repeatedbind elapsed time 0.0 .0

PL/SQLcompilation elapsed time 0.0 .0

hardparse (sharing criteria) elapsed time 0.0 .0

DBtime 87,563.3 N/A

backgroundelapsed time 15,334.9 N/A

backgroundcpu time 1,676.7 N/A

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


%Time Total Wait wait Call

WaitClass Waits -outs Time (s) (ms) Time

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

UserI/O 1,065,631 0 62,993 59 71.9

CPUtime N/A N/A 12,738 N/A 14.5

SystemI/O 273,446 N/A 10,872 40 12.4

Configuration 5,893 46 3,220 546 3.7

Network 27,779,109 N/A 3,171 0 3.6

Other 1,509,280 17 1,238 1 1.4

Application 854 11 464 543 0.5

Commit 7,653 8 145 19 0.2

Concurrency 2,159 1 34 16 0.0

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

AWR数据上看,很明显,本系统是一个写IO很大的系统,每秒REDO的量达到了 36M/秒以上,每秒的物理写超过1万,这在普通的Oracle数据库系统中是比较少见的。从主要等待事件上看,也主要集中在IO上,从WAIT CLASS分类看,USER I/O也排在第一位,平均等待时间为59MSSYSTEMI/O的平均等待也达到40MS,从这些指标上看IO是明显存在问题的。 既然IO存在明显的问题,那么我们就需要马上采集下操作系统IO的情况:


APE:/ # sar -d 3 2
AIX APE 3 5 00CD36454C00 11/25/13
System configuration: lcpu=32 drives=111 mode=Capped
14:52:11 device %busy avque r+w/s Kbs/s avwait avserv
14:52:14 hdisk1 0 0.0 0 0 0.0 0.0
hdisk0 0 0.0 0 0 0.0 0.0
hdisk2 3 0.0 13 1403 0.0 11.6
hdisk3 4 0.0 17 1411 0.0 9.5
hdisk44 49 0.0 85 4096 10.0 6.0
hdisk43 65 0.1 138 7329 15.2 4.6
hdisk39 99 0.2 149 8589 40.6 6.7
hdisk38 30 0.8 303 3081 86.5 1.0
hdisk40 99 0.5 210 11196 60.9 4.7
hdisk42 99 0.9 346 13998 76.2 2.9
hdisk41 61 0.3 246 9734 45.3 2.5
hdisk47 0 0.0 11 149 0.8 0.5
hdisk45 0 0.0 0 0 0.0 0.0

14:52:17 hdisk1 0 0.0 0 0 0.0 0.0
hdisk0 0 0.0 0 0 0.0 0.0
hdisk2 3 0.0 13 1067 0.0 10.8
hdisk3 2 0.0 11 1057 0.0 8.9
hdisk44 79 0.0 107 10475 4.9 7.5
hdisk43 98 0.1 188 14820 12.1 5.1
hdisk39 99 0.2 150 5531 41.9 6.6
hdisk38 23 0.4 288 2921 43.0 0.8
hdisk40 99 0.6 336 11877 52.6 3.0
hdisk42 99 0.2 201 13383 29.0 5.0
hdisk41 60 0.2 222 8487 28.9 2.7
hdisk47 0 0.0 9 202 1.6 0.5
Average hdisk1 0 0.0 0 0 0.0 0.0
hdisk0 0 0.0 0 0 0.0 0.0
hdisk2 3 0.0 13 1235 0.0 11.2
hdisk3 3 0.0 14 1234 0.0 9.2
cd0 0 0.0 0 0 0.0 0.0
hdisk44 64 0.0 96 7285 7.5 6.8
hdisk43 81 0.1 163 11074 13.6 4.9
hdisk39 99 0.2 149 7060 41.3 6.7
hdisk38 26 0.6 295 3001 64.8 0.9
hdisk40 99 0.5 273 11536 56.8 3.8
hdisk42 99 0.5 273 13690 52.6 3.9
hdisk41 60 0.3 234 9110 37.1 2.6
hdisk47 0 0.0 10 175 1.2 0.5
hdisk45 0 0.0 0 21 0.0 0.4


System configuration: lcpu=32drives=111 mode=Capped
14:52:11 device %busy avque r+w/s Kbs/s avwait avserv
Average hdisk1 0 0.0 0 0 0.0 0.0
hdisk0 0 0.0 0 0 0.0 0.0
hdisk2 3 0.0 13 1235 0.0 11.2
hdisk3 3 0.0 14 1234 0.0 9.2
cd0 0 0.0 0 0 0.0 0.0
hdisk44 64 0.0 96 7285 7.5 6.8
hdisk43 81 0.1 163 11074 13.6 4.9
hdisk39 99 0.2 149 7060 41.3 6.7
hdisk38 26 0.6 295 3001 64.8 0.9
hdisk40 99 0.5 273 11536 56.8 3.8
hdisk42 99 0.5 273 13690 52.6 3.9
hdisk41 60 0.3 234 9110 37.1 2.6
hdisk47 0 0.0 10 175 1.2 0.5
hdisk45 0 0.0 0 21 0.0 0.4

从上述指标上看,IOPS和吞吐量都不算太高,但是平均响应时间(avwait+avserv)确实很高,达到几十毫秒。这和我们从AWR报告看到的数据是吻合的。找存储工程师问了问,他认为存储没问题,负载很轻,从存储监控上看到的响应时间也很正常,在几个毫秒。

这恐怕是DBA经常遇到的问题了,到底是存储工程师在推诿呢还是实际情况就是这样的,存储没问题,但是OS层面表现出慢呢?

对于sar的数据,很多DBA总是先去看busy%这个指标,一看很多盘都已经是99% busy了,那可不得了了,存储出现瓶颈了。实际上对于现在的系统而言,busy%这个指标的可参考性并不大,后面的指标更能看出问题。Avque指的是平均队列的长度,有多少IO在队列中等待。再后面一列是IOPS,再后面是吞吐量,最后两列一列是平均等待时间,也就是在队列中等待IO的时间,和平均服务时间,也就是IO请求发出后,从后端返回的时间。

我们通过这些指标实际上是可以区分IO等待是在前端系统端还是后端存储端的。AVSERV是存储到OS之间的端到端服务时间,从上面的指标上看,确实也不大,只有几个毫秒,所以说存储工程师的说法可能是对的,存储端并不慢。而avwaitIO在前端的等待时间,这个指标是相当高的,这说明很可能IO并没有下到存储上,而是在前端OS层面出现了等待。对于AIX系统而言,这个等待很大可能是和QUEUE_DEPTH参数设置不当有关的。

为了进一步确认是否QUEUE_DEPTH不足引起了问题,在AIX系统上,可以用iostat–D去分析:

APE:/ # iostat -D
System configuration: lcpu=32 drives=111 paths=4 vdisks=0
hdisk44 xfer: %tm_act bps tps bread bwrtn
21.9 4.1M 160.3 2.1M 2.0M
read: rps avgserv minserv maxserv timeouts fails
28.8 5.6 0.1 1.2S 0 0
write: wps avgserv minserv maxserv timeouts fails
131.5 0.4 0.2 1.7S 0 0
queue: avgtime mintime maxtime avgwqsz avgsqsz sqfull
68.1 0.0 9.2S 12.0 0.0 160.3
hdisk43 xfer: %tm_act bps tps bread bwrtn
24.0 4.6M 198.9 1.9M 2.7M
read: rps avgserv minserv maxserv timeouts fails
29.4 5.6 0.1 748.9 0 0
write: wps avgserv minserv maxserv timeouts fails
169.4 0.4 0.2 1.2S 0 0
queue: avgtime mintime maxtime avgwqsz avgsqsz sqfull
107.4 0.0 11.6S 25.0 0.0 198.9
hdisk39 xfer: %tm_act bps tps bread bwrtn
27.5 5.3M 192.9 2.6M 2.6M
read: rps avgserv minserv maxserv timeouts fails
38.8 5.3 0.1 791.8 0 0
write: wps avgserv minserv maxserv timeouts fails
154.0 0.4 0.2 1.4S 0 0
queue: avgtime mintime maxtime avgwqsz avgsqsz sqfull
100.2 0.0 11.0S 21.0 0.0 192.9
hdisk38 xfer: %tm_act bps tps bread bwrtn
17.1 3.5M 145.8 1.4M 2.1M
read: rps avgserv minserv maxserv timeouts fails
19.9 5.7 0.1 967.4 0 0
write: wps avgserv minserv maxserv timeouts fails
125.9 0.4 0.2 2.3S 0 0
queue: avgtime mintime maxtime avgwqsz avgsqsz sqfull
282.0 0.0 11.4S 44.0 0.0 145.8
hdisk40 xfer: %tm_act bps tps bread bwrtn
25.0 5.3M 178.7 2.7M 2.6M
read: rps avgserv minserv maxserv timeouts fails
36.5 5.1 0.1 793.6 0 0
write: wps avgserv minserv maxserv timeouts fails
142.2 0.4 0.3 845.6 0 0
queue: avgtime mintime maxtime avgwqsz avgsqsz sqfull
89.7 0.0 10.3S 17.0 0.0 178.7
hdisk42 xfer: %tm_act bps tps bread bwrtn
30.0 6.3M 299.6 2.9M 3.4M
read: rps avgserv minserv maxserv timeouts fails
40.2 4.8 0.1 691.9 0 0
write: wps avgserv minserv maxserv timeouts fails
259.4 0.4 0.2 1.1S 0 0
queue: avgtime mintime maxtime avgwqsz avgsqsz sqfull
3.2S 0.0 11.1S 957.0 0.0 299.6
hdisk41 xfer: %tm_act bps tps bread bwrtn
18.6 4.3M 174.9 1.8M 2.5M
read: rps avgserv minserv maxserv timeouts fails
23.9 5.0 0.1 747.2 0 0
write: wps avgserv minserv maxserv timeouts fails
151.0 0.4 0.2 1.0S 0 0
queue: avgtime mintime maxtime avgwqsz avgsqsz sqfull
82.2 0.0 6.6S 16.0 0.0 174.9

大家可以关注最后一个指标sqfull的指标值,如果这个指标大于0,说明QUEUE_DEPTH参数的设置是不足的,出现了大量IO队列满的情况。从上述数据我们可以比较肯定队列等待可能是问题的主要原因了。下面我们来看看实际上HDISK的设置是什么样的:

APE:/ # lsattr -El hdisk42
clr_q no Device CLEARS its Queue on error
True
location Location Label
True
lun_id 0x4000000000000 Logical Unit Number ID
False
max_transfer 0x40000 Maximum TRANSFER Size
True
node_name 0x2100f84abf591cca FC Node Name
False
pvid 00cd36456aecb23e0000000000000000 Physical volume identifier
False
q_err yes Use QERR bit
True
q_type simple Queuing TYPE
True
queue_depth 1 Queue DEPTH
True
reassign_to 120 REASSIGN time out value
True
rw_timeout 30 READ/WRITE time out value
True
scsi_id 0xe0 SCSI ID
False
start_timeout 60 START unit time out value
True
ww_name 0x2008f84abf591cca FC World Wide Name
False

什么?QUEUE_DEPTH居然是1?其实也没啥大惊小怪的,在AIX系统下,华为存储的缺省QUEUE_DEPTH就是1,也就是说存储工程师并没有帮助用户设置合理的值。其实HDS存储在AIX上的QUEUE_DEPTH缺省值是2,类似的情况还有很多。那么这个参数设置为多少合适呢?根据老白的经验,如果跑Oracle这个参数至少设置为8,高负载的系统可以设置为更大的值,甚至32或者更高(LINUX上缺省是128,不过也不是越高越好,要看你的存储的能力,如果这个参数很大,存储没那么强的能力,也是没用的,需要一个匹配。

既然发现了问题,那么果断的将参数调整为24,我们来看看优化后的效果:

QUEUE_DEPTH加大到24,再看AWR数据:

Load Profile
~~~~~~~~~~~~ Per Second Per Transaction
--------------- ---------------
Redosize: 58,379,378.01 11,838,984.49
Logical reads: 297,113.02 60,252.72
Block changes: 206,017.48 41,779.10
Physical reads: 2,117.52 429.42
Physical writes: 27,976.85 5,673.54

User calls: 51.61 10.47

Parses: 26.49 5.37
Hard parses: 1.00 0.20
Sorts: 2.88 0.58
Logons: 0.80 0.16
Executes: 30.86 6.26
Transactions: 4.93

% Blocks changed per Read: 69.34 RecursiveCall %: 83.58
Rollback per transaction %: 0.20 Rowsper Sort: ########

Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Buffer Nowait %: 100.00 Redo NoWait %: 100.00
Buffer Hit %: 99.30 In-memory Sort %: 99.99
Library Hit %: 96.63 Soft Parse %: 96.23
Execute to Parse %: 14.17 Latch Hit %: 99.84
Parse CPU to Parse Elapsd %: 4.47 % Non-Parse CPU: 99.99

Shared Pool Statistics Begin End
------ ------
Memory Usage %: 42.26 43.94
% SQL with executions>1: 98.99 95.63
% Memory for SQL w/exec>1: 97.78 93.54

Top 5 Timed Events Avg %Total
~~~~~~~~~~~~~~~~~~ wait Call
Event Waits Time (s) (ms) Time Wait Class
------------------------------ ------------ ----------- ------ ----------------
CPU time 18,629 29.7
db file scattered read 463,322 17,063 37 27.2 User I/O
db file sequential read 336,204 10,451 31 16.7 User I/O
db file parallel write 300,543 7,727 26 12.3 System I/O
SQL*Net more data from dblink 8,196,651 5,149 1 8.2 Network

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


是不是好了很多。其实这时候IO还是有问题,现在压力下放到存储上,存储上看到明显的性能问题了。下面可以进一步优化,比如QUEUE DEPTH是不是还可以再加大。另外数据能否存放到更多的盘上。给客户的建议是再多分配2-3RAID 组,把部分数据分散到多个RAID 组上。


最后修改时间:2020-04-17 08:03:30
文章转载自 白鳝的洞穴,如果涉嫌侵权,请发送邮件至:contact@modb.pro进行举报,并提供相关证据,一经查实,墨天轮将立刻删除相关内容。

评论