Oracle mechanics

24.11.2014

ASM bug / таймауты типа Waited 15 secs for write IO to PST

Filed under: Диагностика системы (instance),Oracle,Standby — Игорь Усольцев @ 23:08
Tags: ,

Недавно с Наташей Егоровой разбирали проблемы standby бд, которые отражались в alert.log следующего типа жалобами процессов ARC и RFS:

Errors in file /opt/oracle/admin/diag/rdbms/orcl/orcl1/trace/orcl1_arc2_9237.trc:
ORA-00235: control file read without a lock inconsistent due to concurrent update
...
RFS[147]: Controlfile enqueue unavailable
Errors in file /opt/oracle/admin/diag/rdbms/orcl/orcl1/trace/orcl1_rfs_32434.trc:
ORA-16146: standby control file enqueue unavailable

И если первая ошибка може быть игнорирована согласно ORA-235 Reported in standby alert log (Doc ID 1104343.1), то ORA-16146 в версии 11.2 из трейса RFS:

RFS[77]: Assigned to RFS process 26484
Failed to start CFTXN 0x7ffff7ac2898 (last PID:26662) [krsr.c:10727] IX0
Possible invalid cross-instance archival configuration
Raising exception 16146 [krsa.c:1511] (1 parameters)
Resignalling exception 16146 [krsr.c:10818]
ORA-16146: standby control file enqueue unavailable
...

— вероятно свидетельствует о реальных проблемах с доступом к controlfile (CF), например, из-за проблем с вводом/выводом, которые логично поискать в ASM, alert.log которого:

WARNING: Waited 15 secs for write IO to PST disk 26 in group 1.
WARNING: Waited 15 secs for write IO to PST disk 26 in group 1.
NOTE: process _b000_+asm1 (9442) initiating offline of disk 26.3915927445 (DISK2D06A) with mask 0x7e in group 1
NOTE: checking PST: grp = 1
GMON checking disk modes for group 1 at 36 for pid 61, osid 9442
NOTE: group DATA: updated PST location: disk 0000 (PST copy 0)
NOTE: group DATA: updated PST location: disk 0020 (PST copy 1)
NOTE: checking PST for grp 1 done.
NOTE: sending set offline flag message 2171504456 to 1 disk(s) in group 1
WARNING: Disk DISK2D06A in mode 0x7f is now being offlined
NOTE: initiating PST update: grp = 1, dsk = 26/0xe9684f95, mask = 0x6a, op = clear

— стабильно сигнализировал о безсистемных случаях offline отдельных дисков, причины коих подробно расшифрованы в логах пишущих / контролирующих ASM процессов LGWR, DBW, GMON:

WARNING: Write Failed. group:1 disk:26 AU:0 offset:176128 size:4096
path:ORCL:DISK2D06A
         incarnation:0xebdc56be asynchronous result:'I/O error'
         subsys:/opt/oracle/extapi/64/asm/orcl/1/libasm.so iop:0x7f7b74b5d368 bufp:0x639f3000 osderr:0x534b4950 osderr1:0x0
WARNING: disk offlining resulting in I/O error

— где действительно имелись сообщения об I/O error, в рез-те которых в offline отправлялись вполне исправные ASM диски с одного из таргетов:

[oracle@db_host ~]$ oracleasm querydisk -d DISK2D06A
Disk "DISK2D06A" is a valid ASM disk on device [67, 229]

[oracle@db_host ~]$ ls -l /dev/ | grep 67, | grep 229
brw-rw----  1 oracle dba    67, 229 Nov 13 21:06 /dev/sdbk5

[oracle@db_host ~]$ ls -l /dev/disk/by-path/ | grep sdbk
lrwxrwxrwx 1 root root 10 Nov 13 21:06 ip-192.168.127.2:3260-iscsi-iqn.1987-05.com.cisco:target2.com.ru-lun-206 -> ../../sdbk
lrwxrwxrwx 1 root root 11 Nov 13 21:06 ip-192.168.127.2:3260-iscsi-iqn.1987-05.com.cisco:target2.com.ru-lun-206-part1 -> ../../sdbk1
lrwxrwxrwx 1 root root 11 Nov 13 21:06 ip-192.168.127.2:3260-iscsi-iqn.1987-05.com.cisco:target2.com.ru-lun-206-part5 -> ../../sdbk5

[root@target2 ~]# cat /etc/iet/ietd.conf | grep "Lun 206"
        Lun 206 Path=/dev/disk/by-path/pci-0000:0a:00.0-sas-0x50022a10e0e9413f:1:14-0x50022a10e0e9410e:0,Type=blockio,ScsiId=T02hD006,IOMode=wb

[root@target2 ~]# ls -l /dev/disk/by-path/ | grep 50022a10e0e9410e
lrwxrwxrwx 1 root root  9 Nov 13 00:41 pci-0000:0a:00.0-sas-0x50022a10e0e9413f:1:14-0x50022a10e0e9410e:0 -> ../../sds
lrwxrwxrwx 1 root root 10 Nov 13 00:45 pci-0000:0a:00.0-sas-0x50022a10e0e9413f:1:14-0x50022a10e0e9410e:0-part1 -> ../../sds1
lrwxrwxrwx 1 root root 10 Nov 13 00:45 pci-0000:0a:00.0-sas-0x50022a10e0e9413f:1:14-0x50022a10e0e9410e:0-part5 -> ../../sds5

[root@target2 ~]# smartctl -a /dev/sds | grep Erro
Error logging capability:        (0x01) Error logging supported.
                                        SCT Error Recovery Control supported.
  1 Raw_Read_Error_Rate     0x000b   100   100   016    Pre-fail  Always       -       0
  7 Seek_Error_Rate         0x000b   100   100   067    Pre-fail  Always       -       0
199 UDMA_CRC_Error_Count    0x000a   200   200   000    Old_age   Always       -       0
SMART Error Log Version: 1
No Errors Logged

В то же время по данным iostat и smartctl на том же target2 присутствовал очевидно нездоровый диск:

[root@target2 ~]# iostat -xm /dev/sd*5 1
...
Device:         rrqm/s   wrqm/s   r/s   w/s    rMB/s    wMB/s avgrq-sz avgqu-sz   await  svctm  %util
sdc5              0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00
sdd5              0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00
sds5              0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00
sdv5              0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00
sdo5              0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00
sdw5              0.00     0.00  5.00  0.00     0.00     0.00     1.00     0.06   11.20   9.00   4.50
sdz5              0.00     0.00  4.00  0.00     0.00     0.00     1.00     0.07   13.75  10.75   4.30
sdj5              0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00
sdm5              0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00
sdi5              0.00     0.00  4.00  0.00     0.00     0.00     1.00     0.05   11.75  10.50   4.20
sdab5             0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00
sdr5              0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00
sdu5              0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00
sdx5              0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00
sdy5              0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00
sdq5              0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00
sdh5              0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00
sdk5              0.00     0.00  5.00  0.00     0.00     0.00     1.00     0.03    4.40   5.00   2.50
sdg5              0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00
sdaa5             0.00     0.00  0.00  4.00     0.00     0.25   126.00    60.83 6788.25 250.00 100.00 -- here be dragonz
sdl5              0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00
sdf5              0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00
sdt5              0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00
sdn5              0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00
sdp5              0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00
sde5              0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00

[root@target2 ~]# smartctl -a /dev/sdaa | grep Error
Error logging capability:        (0x01) Error logging supported.
                                        SCT Error Recovery Control supported.
  1 Raw_Read_Error_Rate     0x000b   095   095   016    Pre-fail  Always       -       196618
  7 Seek_Error_Rate         0x000b   100   100   067    Pre-fail  Always       -       0
199 UDMA_CRC_Error_Count    0x000a   200   200   000    Old_age   Always       -       0
SMART Error Log Version: 1
ATA Error Count: 10617 (device log contains only the most recent five errors)
Error 10617 occurred at disk power-on lifetime: 10835 hours (451 days + 11 hours)
  40 51 00 7e a8 7e 01  Error: WP at LBA = 0x017ea87e = 25077886
Error 10616 occurred at disk power-on lifetime: 10835 hours (451 days + 11 hours)
  40 51 ff 7f a0 7e 01  Error: UNC at LBA = 0x017ea07f = 25075839
Error 10615 occurred at disk power-on lifetime: 10835 hours (451 days + 11 hours)
  40 51 00 7e 40 a5 00  Error: UNC at LBA = 0x00a5407e = 10829950
Error 10614 occurred at disk power-on lifetime: 10567 hours (440 days + 7 hours)
  40 51 08 fe 01 c8 0b  Error: UNC at LBA = 0x0bc801fe = 197657086
Error 10613 occurred at disk power-on lifetime: 10567 hours (440 days + 7 hours)
  40 51 08 fe 01 c8 0b  Error: UNC at LBA = 0x0bc801fe = 197657086

, в отношении которого ASM проблем не фиксировал и, соответственно, никаких действий не предпринимал!

Оказалось, наш товарищ и коллега Руслан Бикбаев ранее встречался с сообщением Waited 15 secs for write IO to PST и похожим поведением ASM при высоком I/O трафике, и успешно решал проблему увеличением ASM-таймаута:

alter system set "_asm_hbeatiowait"=120 scope=spfile sid='*';

, что в качестве рекомендации можно найти в документах техподдержки типа ASM diskgroup dismount with «Waited 15 secs for write IO to PST» (Doc ID 1581684.1), с обещанием исправить поведение или же этот таймаут к версии 12.2, вестимо

В нашем случае для решения проблемы в отсутствии тяжёлой I/O нагрузки прежде увеличения таймаута (на всякий случай) логично требовалось превентивно отключить очевидно проблемный диск /dev/sdaa, и после ребалансировки дисковой группы всё заработало штатно:

[oracle@db_host trace]$ tail alert_+ASM1.log
GMON querying group 1 at 16 for pid 18, osid 26939
NOTE: Disk _DROPPED_0035_DATA in mode 0x0 marked for de-assignment
SUCCESS: refreshed membership for 1/0xe3b13ba9 (DATA)
NOTE: Attempting voting file refresh on diskgroup DATA
NOTE: Refresh completed on diskgroup DATA. No voting file found.
Thu Nov 20 17:40:29 2014
NOTE: stopping process ARB0
SUCCESS: rebalance completed for group 1/0xe3b13ba9 (DATA)
Fri Nov 21 14:39:45 2014
NOTE: client orcl1:orcl registered, osid 9098, mbr 0x1

Добавить комментарий »

Комментариев нет.

RSS feed for comments on this post. TrackBack URI

Добавить комментарий

Заполните поля или щелкните по значку, чтобы оставить свой комментарий:

Логотип WordPress.com

Для комментария используется ваша учётная запись WordPress.com. Выход / Изменить )

Фотография Twitter

Для комментария используется ваша учётная запись Twitter. Выход / Изменить )

Фотография Facebook

Для комментария используется ваша учётная запись Facebook. Выход / Изменить )

Google+ photo

Для комментария используется ваша учётная запись Google+. Выход / Изменить )

Connecting to %s

Создайте бесплатный сайт или блог на WordPress.com.

%d такие блоггеры, как: