Исходные данные: три системы БД Oracle, которые активно обмениваются между собой данными через механизм распределенных транзакций Oracle. В один прекрасный момент на всех серверах админы стали наблюдать возникновение очередей при попытке приложения выполнить вставки/обновления данных. Тут же послали сигналы для немедленного завершения процессов, которые блокировали работу пользователей. После получаса разбирательств было принято решение перезагрузить все три системы. Далее запустили процедуры по очистке зависших распределенных транзакций, которые находились в статусах COLLECTING и PREPEARED. Подробности о том, что делать в этом случае, можно зачитать в документе: How To Resolve Stranded DBA_2PC_PENDING Entries [ID 401302.1]. После того, как системы привели в работоспособное состояние, начался разбор полетов.
Главный вопрос – что стало причиной сбоя системы? Да, во время инцидента была выявлена система (одна из трех), которая на этапе первичной диагностики работала с аномалиями (назовем ее система Х). Логин в ОС проходил, но подключиться к БД было невозможно. Причем данные системы оповещения health check фиксировали, что с системой Х полный порядок и во время зависания внимания на нее особо не обращали. Проблемы первоначально фиксировались в двух других системах (назовем их Y и Z), поэтому все внимание было на них.
Начали сбор диагностики. Что-то уже было сделано до и во время зависания. Забегая вперед, скажу, что очень помогли скриншоты профилей удаляемых процессов из системы мониторинга, как раз перед их удалением.
- На системах Y и Z из истории активных сессий выгрузили статистику удаленных в первую очередь процессов. Процессы до их удаления фигурировали в истории активных сессий, каждый из них ожидал SQL*Net message from dblink из удаленной системы X. И тут появилась первая аномалия. После отметки времени 12:32:08 строки истории активных сессий в столбцах статистик потребленного CPU, DB time (TM_DELTA_CPU_TIME, TM_DELTA_DB_TIME) показывали пустые данные.
- Анализ трассировочных файлов БД и listener системы X. В alert.log БД последняя временная метка до перезапуска системы — Time: 06-SEP-2017 12:27:18. В журнале listener — Wed Sep 06 12:27:18 2017. В директории с трассировочными файлами последнее изменение файла NMON было в 12:26.
- История активных сессий на системе X показывала, что последняя запись из диапазона 12:20 – 14:00 была сделана фоновыми процессами в 12.27.33. В нашем случае сервер Oracle перестал сохранять данные истории, начиная с 12:27:33.
- Очевидно, что-то произошло с БД на стороне системы X. Решили посмотреть детально статистику со стороны ОС (CPU, ввод-вывод и т.п.) сервера X.
Наблюдались значительные ожидания Wait % – когда пользовательские процессы ожидали возможности записи/чтения данных с диска (также наблюдалось полное отсутствие kernel write/read system calls, сетевого ввода-вывода и падение RunQueue). Время наступления событий ожидания – также 12:28. - С БД и ОС разобрались. Решили посмотреть на нижележащий уровень – файловую систему и СХД. На системе хранения ничего не обнаружили, а вот на Veritas вывод команды errpt показал такую картину (лишнее убрано):
BC3BE5A3 0906140317 P S SRC SOFTWARE PROGRAM ERROR
A6DF45AA 0906140317 I O RMCdaemon The daemon is started.
BC3BE5A3 0906140217 P S SRC SOFTWARE PROGRAM ERROR
D221BD55 0906140217 I O perftune RESTRICTED TUNABLES MODIFIED AT REBOOT
B258EF25 0906140117 T S VxDRV:vxdmp Messages reported by vxdmp driver
B258EF25 0906140117 T S VxDRV:vxdmp Messages reported by vxdmp driver
B258EF25 0906140117 T S VxDRV:vxdmp Messages reported by vxdmp driver
… удалено...<
B258EF25 0906122817 T S VxDRV:vxdmp Messages reported by vxdmp driver
B258EF25 0906122817 T S VxDRV:vxdmp Messages reported by vxdmp driver
Промежуточный итог
Основной причиной возникновения проблем явился отказ в обслуживании системы X в районе 12:27(28) местного серверного времени. Это прямо видно из журналов БД, слушателя, трассировочных файлов, данных истории активных сессий и журналов ФС Veritas. Также подтверждается отсутствием активности после отметки 12:32 на системах Y и Z при сетевых ожиданиях процессов во время вставки данных и фиксации распределенных транзакций. Данные процессы блокировали другие сессии, что приводило к формированию больших очередей процессов на сервере Y. Блокирующие сессии впоследствии были завершены аварийно.
Различие временных меток остановки обслуживания на Y, Z и X связано с отставанием сервера X на ~4 минуты от других систем. Если вычесть эту дельту из времени окончания активности процессов на Y и Z (см. выше п.1), получим 12:27 (28) – цифры последней активности, которые показывают журналы БД, слушателя и история активных сессий на системе X.
Если восстановить последовательность событий, то цепочка такая: недоступность системы X-> появление очередей на Y и Z –> потом — удаление администраторами блокирующих процессов и дальнейшее лавинообразное развитие ситуации с зависанием распределенных транзакций оставшихся компонентов системы.
Итак, похоже дело в файловой системе VxFS от Veritas (ФС) на которой располагались файлы БД, трассировочные файлы БД и слушателя. ФС впала в «спячку» и остальные процессы ожидали, пока операция ввода-вывода будет завершена. Решили воспроизвести проблему с помощью команды fsfreeze на тестовых системах – очень похожая картина. Поиском на сайте вендора Veritas обнаружили описание бага с похожими симптомами: Doc Id: 3898129 с симптомами: File system hang can be observed sometimes due to IO's hung in DRL.
Неожиданное
На следующий день открываю новостную ленту – а там сообщения о вспышках на Солнце 6 сентября. За 7 сентября заголовки новостей пестрили сообщениями о том, как эта аномалия повлияла на системы связи, людей и т.д.
06.09.2017 14:05, rg.ru, «Ученые: Мощнейшая вспышка на Солнце окажет воздействие на Землю»
06.09.2017 14:44, rbc.ru, «Астрономы зарегистрировали самую мощную за 12 лет вспышку на Солнце»
06.09.2017 15:34, rg.ru, «Видео: Из-за мощной вспышки на Солнце Москва увидит полярное сияние»
06.09.2017 23:54, rg.ru, «Ученые рассказали о последствиях мощнейшей вспышки на Солнце»
Некоторые считали, что необходимо наряду с багом в ФС Veritas рассматривать и эту версию как рабочую. Тогда я не придал этому особого значения.
На днях решил все-таки плотно разобраться с этим вопросом. В интернете вышел на сайт Лаборатории рентгеновской астрономии солнца (ФИАН), на котором публикуется статистика солнечной активности со спутника GOES-15. Открываю я страницу с данными за 6 сентября – и что же? На КДПВ всплеск активности по вспышке C2.7 как раз попадает на время начала проблем с работой сервера X, причем очень близко к максимуму вспышки – 12:34. Я проверил еще раз время – не UTC ли? Нет, время местное. Ну, не может такого быть. Совпадение?
Однако дополнительный поиск вывел на статью на Geektimes: Космическое излучение может влиять на системы.
Оказывается, такое редко, но бывает. Подобные события называются «нарушением в результате единичного события» (single-event upset, SEU). Чаще всего происходят на большой высоте или околоземной орбите, но случаются и на Земле. Цитата:
Хотя существуют довольно яркие примеры сбоев техники, SEU остаются исключительно редким феноменом. Но специалисты обращают внимание, что электронные микросхемы всё чаще используются в различных бытовых приборах. Плотность транзисторов на чипах возрастает, как и их количество. Из-за этого вероятность встречи с «космическим сбоем» растёт с каждым годом. Производители электротехники изучают проблему.
Похоже, солнечная активность вполне может влиять на стабильность и устойчивость информационных систем. Что будет с их надежностью при дальнейшей миниатюризации технических процессов и более плотной упаковке чипов? Вопрос.
На этом всё.
Берегите себя!
Александр Кардаполов, сервисный инженер компании «Инфосистемы Джет»