iSCSI отваливается под нагрузкой

[av_spb]

Добрый день!
Использую iscsi от freenas. В качестве источника используется zvol, размер блока которого 4k, размер логического блока так же 4к (logical block size).
Цепляю с клиента (Ubuntu) диск, форматирую его в ext4, монтирую. Все нормально работает (все видится, файлы копируются). Сеть 1Gbit.
Начинаю давать нагрузку на диск (плоская база данных). В какой-то момент в логах клиента вываливается дисковая ошибка, после которой диск переходит в статус read only.
Не подскажите в чем может быть проблема и можно ли ее победить?
Спасибо!
Ошибка:

Code:

root@solr512:/# cat /var/log/syslog |grep sdc
Oct 23 13:04:25 kernel: [602383.745642] sd 3:0:0:0: [sdc] tag#0 FAILED Result: hostbyte=DID_ABORT driverbyte=DRIVER_OK
Oct 23 13:04:25 kernel: [602383.745653] sd 3:0:0:0: [sdc] tag#0 CDB: Write(10) 2a 08 07 f8 b6 3b 00 00 01 00
Oct 23 13:04:25 kernel: [602383.745658] blk_update_request: I/O error, dev sdc, sector 1069920728
Oct 23 13:04:25 kernel: [602383.747832] blk_update_request: I/O error, dev sdc, sector 1069920728
Oct 23 13:04:25 kernel: [602383.749563] Aborting journal on device sdc1-8.
Oct 23 13:07:23 kernel: [602562.123871] EXT4-fs error (device sdc1): ext4_journal_check_start:56:
Oct 23 13:07:23 kernel: [602562.123883] EXT4-fs error (device sdc1): ext4_journal_check_start:56: Detected aborted journal
Oct 23 13:07:23 kernel: [602562.123888] EXT4-fs (sdc1): Remounting filesystem read-only
Oct 23 13:17:27 kernel: [603165.377827] EXT4-fs warning (device sdc1): ext4_clear_journal_err:4516: Filesystem error recorded from previous mount: IO failure
Oct 23 13:17:27 kernel: [603165.377830] EXT4-fs warning (device sdc1): ext4_clear_journal_err:4517: Marking fs in need of filesystem check.
Oct 23 13:17:27 kernel: [603165.382854] EXT4-fs (sdc1): warning: mounting fs with errors, running e2fsck is recommended
Oct 23 13:17:27 kernel: [603165.389588] EXT4-fs (sdc1): recovery complete
Oct 23 13:17:27 kernel: [603165.390205] EXT4-fs (sdc1): mounted filesystem with ordered data mode. Opts: (null)
Oct 23 13:18:30 kernel: [603228.659709] EXT4-fs (sdc1): warning: mounting fs with errors, running e2fsck is recommended
Oct 23 13:18:30 kernel: [603228.675559] EXT4-fs (sdc1): mounted filesystem with ordered data mode. Opts: (null)
Oct 23 13:23:30 kernel: [603529.210137] EXT4-fs (sdc1): error count since last fsck: 26
Oct 23 13:23:30 kernel: [603529.210175] EXT4-fs (sdc1): initial error at time 1508153975: ext4_journal_check_start:56
Oct 23 13:23:30 kernel: [603529.210184] EXT4-fs (sdc1): last error at time 1508753243: ext4_journal_check_start:56

Параметры iscsi

 

[mav@]

Не факт что в этом проблема, но вообще 4К блок zvol это прямая просьба о низкой скорости линейный операций. Возможно в этом есть какой-то смысл (например, там очень много рандомной перезаписи блоками по 4К), но в других случаях это может быть очень медленно.

 

[av_spb]

Не факт что в этом проблема, но вообще 4К блок zvol это прямая просьба о низкой скорости линейный операций. Возможно в этом есть какой-то смысл (например, там очень много рандомной перезаписи блоками по 4К), но в других случаях это может быть очень медленно.

Честно говоря, запутался в размерах, поэтому исходил из того, что конечная файловая система на клиенте (ubuntu, ext4) имеет размер кластера 4k. Поэтому все к одному виду привел (zvol block size (4k), iscsi logical block size(4k), ext4 cluster size (4k)).
Может посоветуете с какими значения стоит поэксперементировать?

 

[mav@]

В вашей логике есть смысл, но в основном, как я сказал, в условиях активной рандомной перезаписи, где более крупные блоки ZVOL могут вызвать циклы чтение-модификация-запись, что может сильно снизить производительность. С другой стороны мелкие блоки повышают нагрузку на просессор, увеличивают объем метаданных, фрагментацию данных на дисках, делают бесполезной компрессию и т.д.

FreeNAS автоматически подбирает размер блока в зависимости от конфигурации пула. Для mirror пула компромисом и значением по умолчанию сейчас считается 16КБ, для RAIDZ -- больше, в зависимости от числа дисков в каждом top-level vdev.

 

[chs]

А смотрели нагрузку на сеть ? Пакетики не теряются ?

 

[mav@]

Какая вообще конфигурация пула? Для баз данных с активным случайным параллельным доступом mirror должен быть много быстрее чем RAIDZ.

 

[av_spb]

Какая вообще конфигурация пула? Для баз данных с активным случайным параллельным доступом mirror должен быть много быстрее чем RAIDZ.

Конфигурация такая. Три диска напилены через аппаратный raid. Два диска на ssd, третий на sas (большой). Система на одном ssd, лог на втором ssd, sas для данных (картинка ниже). Везде stripe т.к. один диск.

 

[mav@]

Этот da4 это и правда один диск или там аппаратный RAID массив? Если и правда один, то надеюсь у тебя есть бакап. Если это массив, то ZFS может быть можно немного потюнить чтобы он слал на него больше одновременных запросов, так как настройки по умолчанию заточены на физические диски. Кроме того, в зависимости от объема SSD под кеш, надеюсь в сервере достаточно оперативной памяти для его обслуживания.

 

[av_spb]

А смотрели нагрузку на сеть ? Пакетики не теряются ?

Нагрузка на сеть не большая, судя по графикам freenas (до 300Mbit, при доступных 1Gbit). Эти машины на отдельном, полупустом свитче.

 

[av_spb]

Этот da4 это и правда один диск или там аппаратный RAID массив? Если и правда один, то надеюсь у тебя есть бакап. Если это массив, то ZFS может быть можно немного потюнить чтобы он слал на него больше одновременных запросов, так как настройки по умолчанию заточены на физические диски. Кроме того, в зависимости от объема SSD под кеш, надеюсь в сервере достаточно оперативной памяти для его обслуживания.

Все диски на аппаратном raid. da4 - это один raid-диск (raid 5) на sas-дисках.
Памяти достаточно - 40G, из которой 10G не используются.

 

[chs]

А свитч на портах iscsi не показывает битых пакетов ?

 

[av_spb]

А свитч на портах iscsi не показывает битых пакетов ?

Сделал немного не так. соединил эти машину напрямую, дал нагрузку. Полчаса было все хорошо, а потом бах!

Oct 24 17:58:19 solr512 kernel: [22094.789270] ------------[ cut here ]------------
Oct 24 17:58:19 solr512 kernel: [22094.789279] WARNING: CPU: 6 PID: 2386 at /build/linux-5EyXrQ/linux-4.4.0/kernel/softirq.c:150 __local_bh_enable_ip+0x64/0x80()
Oct 24 17:58:19 solr512 kernel: [22094.789280] Modules linked in: ebtable_filter ebtables ip6table_filter ip6_tables iptable_filter ip_tables x_tables binfmt_misc vmw_vsock_vmci_transport vsock ppdev vmw_balloon input_leds joydev serio_raw coretemp shpchp parport_pc parport 8250_fintek i2c_piix4 vmw_vmci mac_hid ib_iser rdma_cm iw_cm ib_cm ib_sa ib_mad ib_core ib_addr iscsi_tcp libiscsi_tcp libiscsi scsi_transport_iscsi autofs4 btrfs raid10 raid456 async_raid6_recov async_memcpy async_pq async_xor async_tx xor raid6_pq libcrc32c raid1 raid0 multipath linear crct10dif_pclmul vmwgfx crc32_pclmul ghash_clmulni_intel ttm aesni_intel drm_kms_helper aes_x86_64 lrw syscopyarea gf128mul sysfillrect glue_helper sysimgblt ablk_helper fb_sys_fops cryptd psmouse drm vmxnet3 vmw_pvscsi pata_acpi floppy fjes
Oct 24 17:58:19 solr512 kernel: [22094.789395] CPU: 6 PID: 2386 Comm: kworker/6:1H Not tainted 4.4.0-87-generic #110-Ubuntu
Oct 24 17:58:19 solr512 kernel: [22094.789396] Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 09/21/2015
Oct 24 17:58:19 kernel: [22094.789401] Workqueue: kblockd blk_timeout_work
Oct 24 17:58:19 kernel: [22094.789402] 0000000000000086 ef047d370033f5ce ffff8833150dfc50 ffffffff813f9903
Oct 24 17:58:19 kernel: [22094.789404] 0000000000000000 ffffffff81cba920 ffff8833150dfc88 ffffffff81081332
Oct 24 17:58:19 kernel: [22094.789405] 0000000000000200 ffff886360f1b3e8 ffff884eb6dc8000 ffff886360f1d420
Oct 24 17:58:19 kernel: [22094.789407] Call Trace:
Oct 24 17:58:19 kernel: [22094.789411] [<ffffffff813f9903>] dump_stack+0x63/0x90
Oct 24 17:58:19 kernel: [22094.789413] [<ffffffff81081332>] warn_slowpath_common+0x82/0xc0
Oct 24 17:58:19 kernel: [22094.789414] [<ffffffff8108147a>] warn_slowpath_null+0x1a/0x20
Oct 24 17:58:19 kernel: [22094.789416] [<ffffffff810858c4>] __local_bh_enable_ip+0x64/0x80
Oct 24 17:58:19 kernel: [22094.789419] [<ffffffff81841a0e>] _raw_spin_unlock_bh+0x1e/0x20
Oct 24 17:58:19 kernel: [22094.789434] [<ffffffffc0368cb6>] __iscsi_conn_send_pdu+0x1c6/0x3e0 [libiscsi]
Oct 24 17:58:19 kernel: [22094.789437] [<ffffffffc036b6ce>] iscsi_send_nopout+0xbe/0x100 [libiscsi]
Oct 24 17:58:19 kernel: [22094.789439] [<ffffffffc036b9a7>] iscsi_eh_cmd_timed_out+0x297/0x2a0 [libiscsi]
Oct 24 17:58:19 kernel: [22094.789441] [<ffffffff815c21c2>] scsi_times_out+0x62/0x250
Oct 24 17:58:19 kernel: [22094.789443] [<ffffffff813d21af>] blk_rq_timed_out+0x1f/0x60
Oct 24 17:58:19 kernel: [22094.789445] [<ffffffff813d229e>] blk_timeout_work+0xae/0x150
Oct 24 17:58:19 kernel: [22094.789448] [<ffffffff8109a5e5>] process_one_work+0x165/0x480
Oct 24 17:58:19 kernel: [22094.789450] [<ffffffff8109a94b>] worker_thread+0x4b/0x4c0
Oct 24 17:58:19 kernel: [22094.789451] [<ffffffff8109a900>] ? process_one_work+0x480/0x480
Oct 24 17:58:19 kernel: [22094.789453] [<ffffffff810a0c85>] kthread+0xe5/0x100
Oct 24 17:58:19 kernel: [22094.789454] [<ffffffff810a0ba0>] ? kthread_create_on_node+0x1e0/0x1e0
Oct 24 17:58:19 kernel: [22094.789457] [<ffffffff8184224f>] ret_from_fork+0x3f/0x70
Oct 24 17:58:19 kernel: [22094.789458] [<ffffffff810a0ba0>] ? kthread_create_on_node+0x1e0/0x1e0
Oct 24 17:58:19 kernel: [22094.789459] ---[ end trace 46e103b7fe149454 ]---
Oct 24 18:00:05 kernel: [22200.553412] INFO: task jbd2/sdc1-8:4585 blocked for more than 120 seconds.

 

[av_spb]

но правда диск не отвалился и после 2-х минутных ошибок, база поехала обрабатываться дальше.

 

[chs]

Хм ... А в логах FreeNAS ничего нет ?
"blk_timeout_work" - прозрачно намекает, что напрасно ожидали блок.
Теперь осталось выяснить - почему ?

 

[av_spb]

Хм ... А в логах FreeNAS ничего нет ?
"blk_timeout_work" - прозрачно намекает, что напрасно ожидали блок.
Теперь осталось выяснить - почему ?

Ничего криминального не вижу. Вот все данные в этот период (17:00-17:59)


cat /var/log/messages | grep "Oct 24 17"
Oct 24 17:59:58 freenas (3:3:0/1): SYNCHRONIZE CACHE(10). CDB: 35 00 00 00 00 00 00 00 00 00
Oct 24 17:59:58 freenas (3:3:0/1): Tag: 0x2000001e, type 1
Oct 24 17:59:58 freenas (3:3:0/1): ctl_process_done: 217 seconds

 

[chs]

А подправить /usr/local/etc/syslog-ng.conf (создать /var/log/all.log, дать ему права 600 и раскомментарить строчку

Code:

log { source(src); destination(all); };

Перезапустить syslog-ng
# service syslog-ng restart

И повторить эксперимент - посмотреть в /var/log/all.log ?

 

[CrashX]

линк по одному порту или нет у меня было линк падал из-за неверно настроенного MPIO

 

[av_spb]

Похоже проблема была в клиенте. Клиент на виртуалке и ему похоже не хватало ресурсов. Добавил мощности, пока живет.