Oracle redo file on SSD wait event log file sync 、opiodr aborting process unknown ospid (29942) as a

Oracle redo file on SSD wait event log file sync

最近某客户一套Oracle19c RAC 环境，在负载相对空闲时也面临一个常见的问题”log file sync”， 数据库存储已经是较快的SSD设备， 下面记录一下容易忽略的RAID配置，居然对数据库的影响如此之大的案例。

AWR 现象

Top 10 Foreground Events by Total Wait Time

Wait Classes by Total Wait Time

Host CPU

IO Profile

Note:

可见数据库的LOG FILE SYNC达500ms以上，并且CPU 负载相对空闲，IO吞吐量并不大，top event还有其它数据文件相关的I/O class wait event, 并且都是ms级别，这样的负载对于SSD存储通常应该就是在us级。

查看LOG FILE PARALLEL WRITE

Wait Event Histogram (up to 32 ms)

Units for Total Waits column: K is 1000, M is 1000000, G is 1000000000
Units for % of Total Waits: us is microseconds, ms is 1024 microseconds (approximately 1 millisecond)
% of Total Waits: total waits for all wait classes, including Idle
% of Total Waits: value of .0 indicates value was <.05%; value of null is truly 0
Ordered by Event (only non-idle events are displayed)

查看当时的OSW IOSTAT信息

zzz ***Mon Jul 25 05:00:01 CST 2022
avg-cpu:  %user   %nice %system %iowait  %steal   %idle
           2.55    0.00    2.64   25.02    0.00   69.79

Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
sda               0.00     0.00    0.00   64.00     0.00   544.00    17.00     0.00    0.00    0.00    0.00   0.00   0.00
dm-0              0.00     0.00    0.00   13.00     0.00    64.00     9.85     0.00    0.00    0.00    0.00   0.00   0.00
dm-1              0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00    0.00    0.00   0.00   0.00
dm-2              0.00     0.00    0.00   51.00     0.00   480.00    18.82     0.00    0.00    0.00    0.00   0.00   0.00
sdb               0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00    0.00    0.00   0.00   0.00
sdc               0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00    0.00    0.00   0.00   0.00
dm-3              0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00    0.00    0.00   0.00   0.00
sdj               0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00    0.00    0.00   0.00   0.00
sdk               0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00    0.00    0.00   0.00   0.00
sdl               0.00     0.00    0.00    1.00     0.00    16.00    32.00     0.00    1.00    0.00    1.00   1.00   0.10
dm-7              0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00    0.00    0.00   0.00   0.00
sdm               0.00     0.00    0.00    2.00     0.00     4.50     4.50     0.00    0.00    0.00    0.00   0.00   0.00
dm-8              0.00     0.00    0.00    3.00     0.00    20.50    13.67     0.00    0.33    0.00    0.33   0.33   0.10
sdn               0.00     0.00    0.00    0.00     0.00     0.00     0.00     1.16    0.00    0.00    0.00   0.00  68.50
sdo               0.00     0.00    1.00    1.00     0.50     4.00     4.50     0.93  288.50  338.00  239.00 346.00  69.20
dm-9              0.00     0.00    0.00    0.00     0.00     0.00     0.00     1.83    0.00    0.00    0.00   0.00  68.50
sdp               0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.67    0.00    0.00    0.00   0.00  67.10
dm-10             0.00     0.00    2.00    1.00     4.50     4.00     5.67     2.17  293.00  320.00  239.00 230.67  69.20
sdr               0.00     0.00    1.00    0.00     4.00     0.00     8.00     1.24  302.00  302.00    0.00 656.00  65.60
sdw               0.00     0.00    0.00    2.00     0.00     9.00     9.00     1.39  522.00    0.00  522.00 500.00 100.00
dm-14             0.00     0.00    0.00    4.00     0.00    13.50     6.75     3.37  558.00    0.00  558.00 250.00 100.00
sdz               0.00     0.00    0.00    2.00     0.00     4.50     4.50     1.98  593.00    0.00  593.00 500.00 100.00
dm-15             0.00     0.00    1.00    1.00     8.00     4.00    12.00     1.94  523.00  787.00  259.00 500.00 100.00
sdaa              0.00     0.00    1.00    1.00     8.00     4.00    12.00     1.26  523.00  787.00  259.00 499.50  99.90
sdab              0.00     0.00    3.00    2.00    96.50     4.50    40.40     1.24  759.00 1000.00  397.50  62.00  31.00
sdac              0.00     0.00   34.00    1.00   352.00     4.00    20.34     0.94   71.83   73.94    0.00   9.00  31.50
dm-16             0.00     0.00    7.00    2.00   257.00     4.50    58.11     2.17  754.89  857.00  397.50  34.44  31.00
sdad              0.00     0.00    4.00    0.00   160.50     0.00    80.25     0.93  749.75  749.75    0.00  77.50  31.00
dm-17             0.00     0.00   69.00    1.00   768.00     4.00    22.06     1.87   78.81   79.96    0.00   4.57  32.00
sdaf              0.00     0.00   35.00    0.00   416.00     0.00    23.77     0.94   85.80   85.80    0.00   9.00  31.50
sdak              0.00     0.00   77.00    1.00   676.00     1.00    17.36     1.26   44.74   45.31    1.00   4.21  32.80
sdam              0.00     0.00   77.00    2.00   724.00    17.00    18.76     1.49   50.19   48.45  117.00   4.14  32.70
sdan              0.00     0.00    2.00    0.00    96.00     0.00    96.00     0.62  998.50  998.50    0.00 154.50  30.90
dm-21             0.00     0.00  154.00    3.00  1400.00    18.00    18.06     2.74   47.50   46.90   78.33   2.14  33.60
sdao              0.00     0.00    3.00    0.00   160.00     0.00   106.67     0.93  999.33  999.33    0.00 103.00  30.90
dm-22             0.00     0.00    5.00    0.00   256.00     0.00   102.40     1.54  999.00  999.00    0.00  61.80  30.90

Note:

可见I/O设备在R/W很小的情况下，await svctm %util相对比较高，问题应该是在OS下层存储端。

Megacli

在操作系统上可以安装使用megacli工具查看和配置RAID, 这里附几个常用命令，更多可查看wiki

Before we go through megacli commands we need to follow megacli concepts.

Adapter - The physical controller which we are going to use, represented by id (usually 0).
Enclosure - The physical chassis the physical drives attached to, represented by id, such as 254,252 etc.
Physical Drives - Physical Hard Disks attached to controller, represented by id, 0,1,2,3 etc.
Virtual Drives - Those drives contains Physical Drives and equal to Raid Devices, represented by id, 0,1,2,3 etc.

Gather info about raid controller

Make sure you have raid controller attached to your server, using lspci.

# lspci | grep -i raid
Output example:

81:00.0 RAID bus controller: LSI Logic / Symbios Logic MegaRAID SAS 2208 [Thunderbolt] (rev 05)

Gather info about raid adapters:

# megacli -AdpGetPciInfo -aAll
Output example:

PCI information for Controller 0
--------------------------------
Bus Number : 5
Device Number : 0
Function Number : 0
Exit Code: 0x00

We can see here the adapters information, we will use the adapter id later on, adapter id is 0.

Gather info about the enclosure

# megacli -EncInfo -a0

Gather info about physical drives
Adapter id is 0.

# megacli -LdPdInfo -a0

Gather info about Virtual drives

# megacli -LDInfo -Lall -a0

Gather info about raid level

# megacli -LDInfo -L2 -a0 | grep -i raid
Output example:
RAID Level : Primary-1, Secondary-0, RAID Level Qualifier-0

We can see here Primary raid level 1 and secondary 0. It means actually raid 0 over raid 1 that is RAID 10.

Cache Policy
Cache Policy’s are how the raid card uses on board RAM to collect data before writing out to disk or to read data before the system asks for it.

WriteBack uses the card’s cache to collect enough data to make a series of long sequential writes out to disk. This is the fastest write method.
WriteThrough tells the card to write all data directly to disk without cache. This method is quite slow by about 1/10 the speed of WriteBack, but is safer as no data can be lost that was in cache when the machine’s power fails.
ReadAdaptive uses an algorithm to see if when the OS asks for a bunch of data blocks sequentially, if we should read a few more sequential blocks because the OS might ask for those too. This method can lead to good speed increases.
ReadAheadNone tells the raid card to only read the data off the raid disk if it was actually asked for. No more, no less.
Cached allows the general use of the cards cache for any data which is read or written. Very efficient if the same data is accessed over and over again.
Direct is straight access to the disk without ever storing data in the cache. This can be slow as any I/O has to touch the disk platters.

# megacli -LDInfo -Lall -aALL

Adapter 0 -- Virtual Drive Information:
Virtual Drive: 0 (Target Id: 0)
Name                :
RAID Level          : Primary-1, Secondary-0, RAID Level Qualifier-0
Size                : 1.090 TB
Sector Size         : 512
Is VD emulated      : No
Mirror Data         : 1.090 TB
State               : Optimal
Strip Size          : 64 KB
Number Of Drives    : 2
Span Depth          : 1
Default Cache Policy: WriteBack, ReadAhead, Direct, No Write Cache if Bad BBU
Current Cache Policy: WriteBack, ReadAhead, Direct, No Write Cache if Bad BBU
Default Access Policy: Read/Write
Current Access Policy: Read/Write
Disk Cache Policy   : Disk's Default
Encryption Type     : None
Default Power Savings Policy: Controller Defined
Current Power Savings Policy: None
Can spin up in 1 minute: Yes
LD has drives that support T10 power conditions: Yes
LD's IO profile supports MAX power savings with cached writes: No
Bad Blocks Exist: No
Is VD Cached: No

Exit Code: 0x00

对于SSD 存储的RAID配置时建议使用Writethrough, ReadAheadNone, Direct, nocache. 因为SSD已经性能远优于HDD，默认的RAID更适用于HDD， 不用预读到RAID 控制器的CACHE, 因为SSD内部CACHE已足够强大，并且是iops也并非瓶颈，使用预读是按strip size预读，以于Oracle DB随机IO 和多会话，这种情况readahead一般不会有什么性能改善，我认为还可能会有读放大。

我们看一下这套数据库的RAID配置

Configure RAID set:

./MegaCli -cfgLdAdd -r0 [32:2] [WT] [NORA] [DIRECT] -a0
Where:

r0 = RAID type (r0, r1, r5, etc)
32:2 = HBD ID 32 (Default) and after colon is actual disk# as installed in the backplane.
WT = Write through (can also be WB for Write Back)
NORA = No Read Ahead (can also be Read Ahead (RA) or Adapative Read Ahead (ADRA))
DIRECT = Disk Cache Policy of Disabled (can also be Cached to enable Disk Cache Policy)
a0 = Controller ID

Configure Virtual Disk name:

./MegaCli -LDSetProp -Name SSD_Cache_Disk1 -L1 -a0
Where:

SSD_Cache_Disk1 = Name of the virtual disk, cannot have spaces or quotes
L1 = Virtual Disk volume that is going to be labeled.
a0 = Controller ID

禁用了ReadAhead功能后效果

$ megacli -LDSetProp NORA -L 1，2，3 -aall

Note:

log file parallel write恢复到us级正常水平， 一切IO都有所改善，I/O性能问题消失。

References

Megacli wiki

https://raid.wiki.kernel.org/index.php/Hardware_Raid_Setup_using_MegaCli

AID Stripe Size and filesystem Readahead

Oracle 11g alert log 新增消息 opiodr aborting process unknown ospid (1951) as a result of ORA-28 说明

在Oracle 11.2.0.2 的数据库中alert log发现大量如下log：

Fatal NI connect error 12537, connectingto:
 (LOCAL=NO)
 
VERSION INFORMATION:
       TNS for HPUX: Version 11.2.0.2.0 - Production
       Oracle Bequeath NT Protocol Adapter for HPUX: Version 11.2.0.2.0 -Production
       TCP/IP NT Protocol Adapter for HPUX: Version 11.2.0.2.0 - Production
 Time: 11-SEP-2011 17:03:56
 Tracing not turned on.
  Tnserror struct:
  nsmain err code: 12537
   
TNS-12537: TNS:connection closed
   ns secondary err code: 12560
   nt main err code: 0
   nt secondary err code: 0
   nt OS err code: 0
opiodr aborting process unknown ospid (29942) as a result of ORA-609
Sun Sep 11 17:05:23 2011
 
 
Tue Sep 13 17:56:37 2011
opiodr aborting processunknown ospid (924) as a result of ORA-28
Tue Sep 13 17:56:38 2011
opiodr aborting process unknownospid (1951) as a result of ORA-28
Tue Sep 13 17:56:40 2011
opiodr aborting process unknown ospid(1983) as a result of ORA-28
Tue Sep 13 17:56:42 2011
opiodr aborting process unknown ospid(11149) as a result of ORA-28
Tue Sep 13 17:56:43 2011
opiodr aborting process unknown ospid(17662) as a result of ORA-28
Tue Sep 13 17:58:06 2011
 
 
opidcl aborting process unknown ospid(9702) as a result of ORA-604

问题分析

opiodr aborting process unknown ospid (924) as a resultof ORA-28

在Oracle 11.1.0.6 和 11.1.0.7 的版本中，存在一个bug：6377339。 其会在alert log 显示如下信息：

ORA-28 : opiodr aborting process unknown ospid (21016_3086862016)

这样的提示信息会让我们产生疑惑. 所以在Oracle 11.2 版本中对这个bug进行修复，修复之后的提示信息变成了：

opidcl abortingprocess unknown ospid (32110) as a result of ORA-28

opiodr aborting process信息仅仅是一个消息，它是Oracle 11g里新添加的一个消息，用来记录进程的异常退出。

该消息一般用来记录有权限的用户kill 的session信息。

示例：

"opiodr aborting process unknown ospid(28342) as a result of ORA-28"

解释

• “unknown” => means it is not a background or shadow process that is killed
• “ospid (28342)” => this is the OS pid of the process which opiodris aborting
• “as a result of” => this precedes the error message which is thereason for opiodr to kill the process
• “ORA-28” => this is the reason that opiodr killed the process. In this case, it is ora-28.

参考：

“opiodr abortingprocess” Messages in Alert.Log [ID 1230858.1]

Bug 6377339 - Misleading alertlog message for “opiodr aborting” [ID 6377339.8]

opiodr aborting process unknown ospid (29942) as a resultof ORA-609

这里表示进程ospid (29942) 因为ORA-609的错误而被kill。导致这个错误的原因有2种：

• Bug9856585 - “audit network by access does not audit ora-12650”

  该bug 存在Oracle 11.1 到 11.2 的版本中，官网对这个bug的说明如下：

  The Bug9856585 is going to be fix by the Oracle RDBMS Development team, it is currently in Work in Progress Status.

• 在启动 EM Console后报该错误，该问题存在Oracle 10.1到11.2.可能是nscd 进程引起。解决方法是重启这个进程。

用超级用户（root）用户执行以下步骤进行重启：

1. Stop nscd daemon:
# service nscd stop 

2. Verify if any rogue processes is still running:
# ps -ef|grep nscd 


If any process is found, kill the roguenscd process
# kill -9 <nscd_pid> 


3. Start nscd daemon:
# service nscd start 

4. As the OS user who has installed theAgent, start the Agent:
cd <AGENT_HOME>/bin
emctl start agent

参考：

Audit Network Does Not Work When notSuccessful in Oracle 11gR2 [ID 1241325.1]

Grid Control Agent 10.2 Crashes with CoreDump if ‘nscd’ daemon is Hung on Linux OS [ID 430200.1]

Lsnrctl Status is Failing and Alert.logShows TNS-12537 and ORA-609 [ID 950135.1]

opidcl aborting process unknown ospid (9702) asa result of ORA-604

根据ORA-28中的说明，这里的信息时记录了ospid(9702) 进程因为ORA-604的错误而被中断了。 该消息仅用来记录进程异常退出的信息，是Oracle 11g中新增加的消息。

总结：

Alert log中的"opiodr aborting processunknown ospid (28342) as a result of ORA-28"消息仅仅是一个记录信息。最后的ORA-XX的信息代表导致进程异常退出的原因。

参考资料

https://www.cnblogs.com/tianlesoftware/archive/2012/08/04/3609196.html