Пул ZFS в Open Indiana используется на 100% каждый час
У меня проблемы с пулом, который используется на 100% каждый час примерно в течение 3 минут. Хотя это звучит как cron, на самом деле это 1 час после остановки замораживания, так, например, замораживание начинается в 12:00, длится около 3 минут, следующее замораживание начнется в 13:03, ровно через 1 час после прекращения предыдущего замораживания с почти тактовая точность с разницей в несколько секунд. Пул представляет собой полный SSD-накопитель и действует как общее хранилище NFS для облачной платформы, на которой работает около 300 виртуальных машин. SSD-накопители - Samsung PM863, контроллер - LSI3008 IT.
prtconf -vvv | grep -i sas
value='LSISAS3008ALLLSI3008-IT'
value='LSISAS3008'
value='MPTSAS HBA Driver 00.00.00.24'
value='NAME=mptsas0' + '0=Off (PCI D3 State)' + '3=On (PCI D0 State)'
value='SAS3008 PCI-Express Fusion-MPT SAS-3'
name='firmware-version' type=string items=1 dev=none
value='16.0.1.0'
Коробка - это супермикро с 64 ГБ оперативной памяти, общий объем памяти составляет около 12 ТБ. Состояние zpool в порядке, очистка zpool завершается без ошибок.
ОС - это OpenIndiana с последними обновлениями
OpenIndiana Hipster 2019.10 (powered by illumos)
OpenIndiana Project, part of The Illumos Foundation (C) 2010-2019
Use is subject to license terms.
Assembled 30 March 2020
В системе есть rpool и пул данных, когда происходит замораживание, оба переходят на 100%. Зависание происходит с включенными виртуальными машинами или без них.
"fmadm faulty" не показывает ошибок. "fmdump -eV" выдаст довольно длинный список дисковых ошибок и ошибок передачи во время 3-минутного шторма. В пуле уже несколько лет используется несколько SSD, а недавно были добавлены некоторые SSD. Ошибки в большинстве случаев бывают на всех старых SSD, очень редко на новых. Я поменял несколько ssd-накопителей, которые показывают эти ошибки, и провел короткие и длинные тесты smartcl без ошибок. Вот пример пары таких штормовых циклов
Apr 16 23:51:41.1642 ereport.io.scsi.cmd.disk.recovered
--------calm period----------
Apr 17 00:52:05.6950 ereport.io.scsi.cmd.disk.dev.rqs.derr
Apr 17 00:52:05.6950 ereport.io.scsi.cmd.disk.recovered
Apr 17 00:52:09.9469 ereport.io.scsi.cmd.disk.tran
Apr 17 00:52:09.9469 ereport.io.scsi.cmd.disk.tran
--------storm period period, about 200 error + recovered messages----------
Apr 17 00:55:00.4031 ereport.io.scsi.cmd.disk.dev.rqs.derr
Apr 17 00:55:00.4031 ereport.io.scsi.cmd.disk.recovered
Apr 17 00:55:04.4489 ereport.io.scsi.cmd.disk.tran
Apr 17 00:55:04.4488 ereport.io.scsi.cmd.disk.recovered
--------calm period----------
Apr 17 2020 01:55:28.979494132 ereport.io.scsi.cmd.disk.dev.rqs.derr
--------storm period period-----
Несколько подробных ошибок из "fmdump -eV":
Apr 17 2020 01:58:10.232937209 ereport.io.scsi.cmd.disk.tran
nvlist version: 0
class = ereport.io.scsi.cmd.disk.tran
ena = 0xf880bff57e800801
detector = (embedded nvlist)
nvlist version: 0
version = 0x0
scheme = dev
device-path = /pci@0,0/pci8086,2f06@2,2/pci15d9,808@0/iport@ff/disk@w5002538c40391ea7,0
(end detector)
devid = id1,sd@n5002538c40391ea7
driver-assessment = retry
op-code = 0x2a
cdb = 0x2a 0x0 0x2d 0x1a 0x4b 0x42 0x0 0x0 0x5a 0x0
pkt-reason = 0x4
pkt-state = 0x0
pkt-stats = 0x10
__ttl = 0x1
__tod = 0x5e98e302 0xde256f9
Apr 17 2020 01:58:06.982636932 ereport.io.scsi.cmd.disk.recovered
nvlist version: 0
class = ereport.io.scsi.cmd.disk.recovered
ena = 0xf874a44868e01001
detector = (embedded nvlist)
nvlist version: 0
version = 0x0
scheme = dev
device-path = /pci@0,0/pci8086,2f06@2,2/pci15d9,808@0/iport@ff/disk@w5002538c40392191,0
devid = id1,sd@n5002538c40392191
(end detector)
devid = id1,sd@n5002538c40392191
driver-assessment = recovered
op-code = 0x2a
cdb = 0x2a 0x0 0x0 0x6a 0xa0 0xb1 0x0 0x1 0x0 0x0
pkt-reason = 0x0
pkt-state = 0x1f
pkt-stats = 0x0
__ttl = 0x1
__tod = 0x5e98e2fe 0x3a91d984
Apr 17 2020 01:58:10.232762449 ereport.io.scsi.cmd.disk.dev.rqs.derr
nvlist version: 0
class = ereport.io.scsi.cmd.disk.dev.rqs.derr
ena = 0xf880bff57e800801
detector = (embedded nvlist)
nvlist version: 0
version = 0x0
scheme = dev
device-path = /pci@0,0/pci8086,2f06@2,2/pci15d9,808@0/iport@ff/disk@w5002538c40391ea7,0
devid = id1,sd@n5002538c40391ea7
(end detector)
devid = id1,sd@n5002538c40391ea7
driver-assessment = retry
op-code = 0x2a
cdb = 0x2a 0x0 0x2d 0x1a 0x4b 0x42 0x0 0x0 0x5a 0x0
pkt-reason = 0x0
pkt-state = 0x3f
pkt-stats = 0x0
stat-code = 0x2
key = 0x6
asc = 0x29
ascq = 0x0
sense-data = 0x70 0x0 0x6 0x0 0x0 0x0 0x0 0xa 0x0 0x0 0x0 0x0 0x29 0x0 0x0 0x0 0x0 0x0 0x0 0x0
__ttl = 0x1
__tod = 0x5e98e302 0xddfac51
Apr 17 2020 01:58:10.232706429 ereport.io.scsi.cmd.disk.recovered
nvlist version: 0
class = ereport.io.scsi.cmd.disk.recovered
ena = 0xf880bff57e800801
detector = (embedded nvlist)
nvlist version: 0
version = 0x0
scheme = dev
device-path = /pci@0,0/pci8086,2f06@2,2/pci15d9,808@0/iport@ff/disk@w5002538c40391ea7,0
devid = id1,sd@n5002538c40391ea7
(end detector)
devid = id1,sd@n5002538c40391ea7
driver-assessment = recovered
op-code = 0x2a
cdb = 0x2a 0x0 0x2d 0x1a 0x4b 0x42 0x0 0x0 0x5a 0x0
pkt-reason = 0x0
pkt-state = 0x1f
pkt-stats = 0x0
__ttl = 0x1
__tod = 0x5e98e302 0xdded17d
В /var/adm/messages я вижу такие вещи
Apr 17 01:57:32 storage scsi: [ID 365881 kern.info] /pci@0,0/pci8086,2f06@2,2/pci15d9,808@0 (mpt_sas0):
Apr 17 01:57:32 storage Log info 0x31130000 received for target 24 w5002538c4015bc59.
Apr 17 01:57:32 storage scsi_status=0x0, ioc_status=0x804b, scsi_state=0xc
Apr 17 01:57:35 storage scsi_vhci: [ID 734749 kern.warning] WARNING: vhci_scsi_reset 0x1
Apr 17 01:57:42 storage last message repeated 2 times
Apr 17 01:57:42 storage scsi: [ID 365881 kern.info] /pci@0,0/pci8086,2f06@2,2/pci15d9,808@0 (mpt_sas0):
Apr 17 01:57:42 storage Log info 0x31140000 received for target 25 w5002538c400a3ea2.
Apr 17 01:57:42 storage scsi_status=0x0, ioc_status=0x804b, scsi_state=0xc
Apr 17 01:57:46 storage scsi_vhci: [ID 734749 kern.warning] WARNING: vhci_scsi_reset 0x1
Apr 17 01:57:46 storage scsi: [ID 365881 kern.info] /pci@0,0/pci8086,2f06@2,2/pci15d9,808@0 (mpt_sas0):
Apr 17 01:57:46 storage Log info 0x31130000 received for target 25 w5002538c400a3ea2.
Apr 17 01:57:46 storage scsi_status=0x0, ioc_status=0x804b, scsi_state=0xc
Apr 17 01:57:49 storage scsi_vhci: [ID 734749 kern.warning] WARNING: vhci_scsi_reset 0x1
Apr 17 01:57:52 storage last message repeated 2 times
Apr 17 01:57:53 storage scsi: [ID 365881 kern.info] /pci@0,0/pci8086,2f06@2,2/pci15d9,808@0 (mpt_sas0):
Apr 17 01:57:53 storage Log info 0x31130000 received for target 26 w5002538c400a3ea9.
Apr 17 01:57:53 storage scsi_status=0x0, ioc_status=0x804b, scsi_state=0xc
Apr 17 01:57:56 storage scsi_vhci: [ID 734749 kern.warning] WARNING: vhci_scsi_reset 0x1
Apr 17 01:57:59 storage last message repeated 1 time
Apr 17 01:57:59 storage scsi: [ID 365881 kern.info] /pci@0,0/pci8086,2f06@2,2/pci15d9,808@0 (mpt_sas0):
Apr 17 01:57:59 storage Log info 0x31130000 received for target 27 w5002538c40392191.
Apr 17 01:57:59 storage scsi_status=0x0, ioc_status=0x804b, scsi_state=0xc
Apr 17 01:58:03 storage scsi_vhci: [ID 734749 kern.warning] WARNING: vhci_scsi_reset 0x1
Apr 17 01:58:03 storage scsi: [ID 365881 kern.info] /pci@0,0/pci8086,2f06@2,2/pci15d9,808@0 (mpt_sas0):
Apr 17 01:58:03 storage Log info 0x31130000 received for target 27 w5002538c40392191.
Apr 17 01:58:03 storage scsi_status=0x0, ioc_status=0x804b, scsi_state=0xc
Apr 17 01:58:03 storage scsi: [ID 365881 kern.info] /pci@0,0/pci8086,2f06@2,2/pci15d9,808@0 (mpt_sas0):
Apr 17 01:58:03 storage Log info 0x31130000 received for target 27 w5002538c40392191.
Apr 17 01:58:03 storage scsi_status=0x0, ioc_status=0x804b, scsi_state=0xc
Apr 17 01:58:06 storage scsi_vhci: [ID 734749 kern.warning] WARNING: vhci_scsi_reset 0x1
Apr 17 01:58:13 storage last message repeated 2 times
Apr 17 01:58:13 storage scsi: [ID 365881 kern.info] /pci@0,0/pci8086,2f06@2,2/pci15d9,808@0 (mpt_sas0):
Apr 17 01:58:13 storage Log info 0x31130000 received for target 28 w5002538c40391ea7.
Apr 17 01:58:13 storage scsi_status=0x0, ioc_status=0x804b, scsi_state=0xc
Apr 17 01:58:16 storage scsi_vhci: [ID 734749 kern.warning] WARNING: vhci_scsi_reset 0x1
Apr 17 01:58:27 storage last message repeated 3 times
Apr 17 01:58:27 storage scsi: [ID 365881 kern.info] /pci@0,0/pci8086,2f06@2,2/pci15d9,808@0 (mpt_sas0):
Apr 17 01:58:27 storage Log info 0x31140000 received for target 30 w5002538c4039218d.
Apr 17 01:58:27 storage scsi_status=0x0, ioc_status=0x804b, scsi_state=0xc
Apr 17 01:58:30 storage scsi_vhci: [ID 734749 kern.warning] WARNING: vhci_scsi_reset 0x1
Иостат во время шторма
tin tout us sy dt id
0 2854 2 1 0 97
extended device statistics
r/s w/s Mr/s Mw/s wait actv wsvc_t asvc_t %w %b device
0.0 0.0 0.0 0.0 62.0 108.0 0.0 0.0 100 100 datetest
0.0 0.0 0.0 0.0 0.0 6.0 0.0 0.0 0 100 rpool1
0.0 0.0 0.0 0.0 0.0 3.0 0.0 0.0 0 100 c0t5002538C40057CB0d0
0.0 0.0 0.0 0.0 0.0 3.0 0.0 0.0 0 100 c0t5002538C40057CB2d0
0.0 0.0 0.0 0.0 0.0 1.0 0.0 0.0 0 100 c0t5002538C4007F3CAd0
0.0 0.0 0.0 0.0 0.0 1.0 0.0 0.0 0 100 c0t5002538C4007F3DAd0
0.0 0.0 0.0 0.0 0.0 1.0 0.0 0.0 0 100 c0t5002538C4007F3F8d0
0.0 0.0 0.0 0.0 0.0 2.0 0.0 0.0 0 100 c0t5002538C4007F3BCd0
0.0 0.0 0.0 0.0 0.0 1.0 0.0 0.0 0 100 c0t5002538C4007F3C9d0
0.0 0.0 0.0 0.0 0.0 1.0 0.0 0.0 0 100 c0t5002538C4007F32Dd0
0.0 0.0 0.0 0.0 0.0 1.0 0.0 0.0 0 100 c0t5002538C4007F3CDd0
0.0 0.0 0.0 0.0 0.0 11.0 0.0 0.0 0 100 c0t5002538C4007F334d0
0.0 0.0 0.0 0.0 0.0 2.0 0.0 0.0 0 100 c0t5002538C4007F3C1d0
0.0 0.0 0.0 0.0 0.0 10.0 0.0 0.0 0 100 c0t5002538C40BD2AE2d0
0.0 0.0 0.0 0.0 0.0 2.0 0.0 0.0 0 100 c0t5002538C400A3EA7d0
0.0 0.0 0.0 0.0 0.0 1.0 0.0 0.0 0 100 c0t5002538C4015BC59d0
0.0 0.0 0.0 0.0 0.0 3.0 0.0 0.0 0 100 c0t5002538C400A3EA2d0
0.0 0.0 0.0 0.0 0.0 3.0 0.0 0.0 0 100 c0t5002538C400A3EA9d0
0.0 0.0 0.0 0.0 3.0 1.0 0.0 0.0 100 100 c0t5002538C40392191d0
0.0 0.0 0.0 0.0 0.0 4.0 0.0 0.0 0 100 c0t5002538C40391EA7d0
0.0 0.0 0.0 0.0 0.0 11.0 0.0 0.0 0 100 c0t5002538C4039218Dd0
0.0 0.0 0.0 0.0 0.0 10.0 0.0 0.0 0 100 c0t5002538C4058618Fd0
0.0 0.0 0.0 0.0 0.0 10.0 0.0 0.0 0 100 c0t5002538C40586190d0
0.0 0.0 0.0 0.0 0.0 3.0 0.0 0.0 0 100 c0t5002538C4058617Fd0
0.0 0.0 0.0 0.0 0.0 3.0 0.0 0.0 0 100 c0t5002538C40586181d0
0.0 0.0 0.0 0.0 0.0 2.0 0.0 0.0 0 100 c0t5002538E40FAFF79d0
0.0 0.0 0.0 0.0 0.0 3.0 0.0 0.0 0 100 c0t5002538E40FAFF76d0
0.0 0.0 0.0 0.0 0.0 2.0 0.0 0.0 0 100 c0t5002538E40FAFF83d0
0.0 0.0 0.0 0.0 0.0 2.0 0.0 0.0 0 100 c0t5002538E40FAFF6Fd0
0.0 0.0 0.0 0.0 0.0 1.0 0.0 0.0 0 100 c0t5002538E40FAFF7Ad0
0.0 0.0 0.0 0.0 0.0 1.0 0.0 0.0 0 100 c0t5002538E40FAFF86d0
0.0 0.0 0.0 0.0 0.0 12.0 0.0 0.0 0 100 c0t5002538C40BD2AE3d0
И в нормальный период
tty cpu
tin tout us sy dt id
1 2866 2 7 0 90
extended device statistics
r/s w/s Mr/s Mw/s wait actv wsvc_t asvc_t %w %b device
164.8 990.7 18.7 18.0 0.0 0.3 0.0 0.3 0 9 datetest
2.0 0.0 0.0 0.0 0.0 0.0 0.0 0.2 0 0 rpool1
2.0 0.0 0.0 0.0 0.0 0.0 0.0 0.1 0 0 c0t5002538C40057CB0d0
9.0 72.9 0.9 0.7 0.0 0.0 0.0 0.1 0 1 c0t5002538C4007F3CAd0
7.0 66.9 0.8 0.7 0.0 0.0 0.0 0.1 0 1 c0t5002538C4007F3DAd0
10.0 72.9 0.9 0.7 0.0 0.0 0.0 0.1 0 1 c0t5002538C4007F3F8d0
6.0 84.9 0.7 0.7 0.0 0.0 0.0 0.1 0 1 c0t5002538C4007F3BCd0
1.0 76.9 0.1 0.8 0.0 0.0 0.0 0.1 0 1 c0t5002538C4007F3C9d0
3.0 66.9 0.4 0.7 0.0 0.0 0.0 0.1 0 1 c0t5002538C4007F32Dd0
6.0 84.9 0.7 0.7 0.0 0.0 0.0 0.1 0 1 c0t5002538C4007F3CDd0
3.0 72.9 0.3 0.6 0.0 0.0 0.0 0.1 0 1 c0t5002538C4007F334d0
4.0 76.9 0.5 0.8 0.0 0.0 0.0 0.1 0 1 c0t5002538C4007F3C1d0
3.0 72.9 0.4 0.6 0.0 0.0 0.0 0.1 0 1 c0t5002538C40BD2AE2d0
5.0 65.9 0.5 0.6 0.0 0.0 0.0 0.1 0 1 c0t5002538C400A3EA7d0
8.0 65.9 0.8 0.6 0.0 0.0 0.0 0.1 0 1 c0t5002538C4015BC59d0
7.0 65.9 0.7 0.7 0.0 0.0 0.0 0.1 0 1 c0t5002538C400A3EA2d0
4.0 65.9 0.5 0.7 0.0 0.0 0.0 0.1 0 1 c0t5002538C400A3EA9d0
8.0 69.9 1.0 0.6 0.0 0.0 0.0 0.2 0 1 c0t5002538C40392191d0
5.0 69.9 0.5 0.6 0.0 0.0 0.0 0.1 0 1 c0t5002538C40391EA7d0
7.0 62.9 0.7 0.6 0.0 0.0 0.0 0.1 0 1 c0t5002538C4039218Dd0
7.0 73.9 0.7 0.8 0.0 0.0 0.0 0.1 0 1 c0t5002538C4058618Fd0
7.0 73.9 0.7 0.8 0.0 0.0 0.0 0.1 0 1 c0t5002538C40586190d0
4.0 65.9 0.5 0.6 0.0 0.0 0.0 0.1 0 1 c0t5002538C4058617Fd0
7.0 65.9 0.8 0.6 0.0 0.0 0.0 0.1 0 1 c0t5002538C40586181d0
0.0 67.9 0.0 0.6 0.0 0.0 0.0 0.1 0 0 c0t5002538E40FAFF79d0
12.0 67.9 1.5 0.6 0.0 0.0 0.0 0.2 0 1 c0t5002538E40FAFF76d0
8.0 63.9 0.9 0.6 0.0 0.0 0.0 0.2 0 1 c0t5002538E40FAFF83d0
5.0 63.9 0.6 0.6 0.0 0.0 0.0 0.1 0 1 c0t5002538E40FAFF6Fd0
6.0 63.9 0.7 0.5 0.0 0.0 0.0 0.1 0 1 c0t5002538E40FAFF7Ad0
6.0 63.9 0.9 0.5 0.0 0.0 0.0 0.1 0 1 c0t5002538E40FAFF86d0
7.0 62.9 0.9 0.6 0.0 0.0 0.0 0.1 0 1 c0t5002538C40BD2AE3d0
В системе был LSI3108 с дисками в режиме JBOD, когда проблема началась, она была намного серьезнее, вероятно, из-за драйвера, так как mr_sas застревал в инструкции по сбросу (вот как я могу описать, что я помню, наблюдая за экраном консоли прокрутка с ошибками). Заменив LSI3008 на IT-прошивку, теперь переживает период, ошибок на консоли нет, но все равно сильно лагает.
Может ли кто-нибудь помочь с идеями о том, как выяснить причину этой проблемы? Я пытался наблюдать за процессами, которые запускаются, отслеживая с помощью dtrace_toolkit iotop, но я не могу точно определить какое-то очевидное событие.
Большое спасибо за любые предложения.