При эксплуатации систем АСУ ТП возникают ситуации, когда написанная подрядчиком диагностика АРМа формирует аварийные сообщения в исторический журнал, после которых и начинаются данные расследования. Так как системы написаны и сделаны очень давно, то о никаких Grafana/Prometheus/Zabbix речь идти не может, плюс всё это работает на серверах/АРМах времён ввода в эксплуатацию. А чем старее оборудование, тем за каждый мегабайт оперативной памяти и процент нагрузки процессора идёт жёсткая борьба.
Без логирования для расследования отказов никуда не деться, но и сами логи могут быть причиной аварийных сообщений. Поэтому вот 3 истории, когда логи сделали не лучше, а хуже.
Случай №1 - частая загрузка процессора
Мониторинг стал показывать и генерировать сообщения, что периодически возрастает общая загрузка процессора больше 70% на 5-10 секунд. Данное поведение происходило не часто, поэтому местный персонал не обращал внимания на данную проблему. Но приехала проверка из филиала повыше, просмотрела исторические сообщения и выписала замечание - мол, нештатное поведение, разбирайтесь. Ну раз есть проблема, значит надо решать.
На объекте эксплуатируется HP ProLiant DL 120 G6 с процессором Intel Pentium G6950 (2.80Ghz). Сразу отмету вопросы об апгрейде - нет, пока не время и апгрейд будет позже, а пока что есть, то и используем, но пока запомните - здесь стоит двухъядерный процессор.
По имеющемуся мониторингу всплески видны были, но к формированию сообщения они не приводили, так как по продолжительности были меньше 2 секунд. При этом видно, что нагрузка на ЦП держится в районе 20-30%. Это не очень хорошо, так как обычно она находится в районе 10-15%.
Приступаю к сбору данных. Для начала просто запускаю диспетчер задач и мониторю глазами в режиме реального времени, кто виноват:
Вот наш виновник:
Исходя из названия становится понятно, что виноват WMI. Но почему? Так как проблема часто встречаемая, Microsoft выпустила целую статью, из которой подчерпнём пару моментов.
На данном этапе мне надо выяснить PID процессов, которые дают данную нагрузку. Воспользуюсь встроенными счетчиками производительности Windows: нажимаю Win+R и в окне «Выполнить» выполняю команду perfmon.msc. Перехожу в "Группы сборщиков данных" -> "Особые", нажимаю правой кнопкой и создаю новую группу сборщиков данных:
Записав пару минут, я понял, что ничего интересного из этой информации я не извлеку. Поэтому перевожу службу WMI на собственный процесс svchost.exe через команду sc config Winmgmt type= own, не забывая после данной команды перезапустить службу "Инструментарий управления Windows". После перезапуска службы можно выполнить команду Tasklist /svc , чтобы проверить, что служба Winmgmt работает в отдельном процессе svchost.exe .
После этого подозреваемых стало меньше - теперь отдельный svchost.exe дает нагрузку, а WmiPrvSe показывает стабильно 0%. Да и по графикам стала видна четкая "пила", то есть нагрузка не размылась, а стала пиками от 0 до 50%. Возникает логичный вопрос - а что на этот раз не так?
Для продолжения расследования воспользуюсь уже другой утилитой от Sysinternals -Process Explorer. Ищу PID процесса необходимого нам svchost.exe любым способом - либо через счетчики аналогично выше (только выбираем все процессы svchost), либо глазами ловим момент нагрузки через Process Explorer и выделяем нужный нам PID. Открываю в Process Explorer подробности нашего процесса и вкладке Threads смотрю текущие потоки. И вот в момент нагрузки у меня получается такая картина:
Eventlog, она же служба «Журнал событий Windows». Открываю логи приложений, сравниваю время с нагрузкой и вижу, что одна из программ просто очень часто пишет диагностические логи. Перевожу в настройках программы запись логов с отладки на информационные сообщения и основной источник повторяемой нагрузки (раз в 30 секунд где-то) уходит. Казалось бы - начинали с одного процесса, а закончилось вообще другим.
Почему первоначально была нагрузка на WmiPrvSE? Приложение, которое писало логи, написано на Net и видимо использует класс с логичным названием EventLog. А запись данных событий происходит через WMI и конкретно службу Eventlog.
Почему я упомянул про двухъядерный процессор? Так как если на одном объекте была такая же проблема, то и на других должна быть? Оказалось, что не совсем. На других объектах такая же система собрана на таких же серверах, но конфигурация там четырёхъядерная на базе X3430 и нагрузка равномерно "размазывалась" по ядрам. Исходя из этого, нагрузка даже в простое не превышала 10% по каждому из ядер (соответственно и общая нагрузка ЦПУ была в этих же пределах). Но такой уровень логирования нам на данный момент не требовался, поэтому тоже везде поменяли на уровень ниже - да и журнал меньше забивать стало.
Случай №2 - эпизодическая загрузка процессора
А вот тут случай был плавающий. В один месяц, в течение двух минут, в определенные дни появлялась общая нагрузка на процессор, резко исчезала и снова тишина. Через определенный промежуток времени вновь на два дня проявлялась и уходила. А раз есть повторение, значит это не случайность, а системность.
На этот раз у нас встраиваемый компьютер (панель с сенсорным экраном) на базе Intel с процессором серии N3000 или что-то в этом духе, с 4 Гбайтами оперативной памяти.
Первым делом по историческим сообщениям решил проследить, а как часто это было и через какой промежуток повторялось. Самое интересное - это промежуток: ровно через определенное число дней в примерно плюс минус 1-2 часа повторяются сообщения по загрузке. Расчеты показали, что исходя из последнего события в ближайшее время (тогда конец августа был) в 14 по Мск будет похожий всплеск. Ставлю запись счетчиков на запись, дожидаюсь дня икс - и нагрузка плюс/минус в 5 минут выстреливает. На следующий день (мы на ДВ живем, поэтому в 2 по Мск следующего дня) смотрю в историческом режиме, а там наш знакомый - WmiPrvSE.exe.
Ну, я уже умный (после прошлого случая) - иду смотреть логи за это время. А там тишина - ничего вообще в этот момент. Смотрю опять счетчики - в этот момент идет нагрузка на жесткий диск, то есть кто-то что-то пишет. Но как узнать, что за процесс в этот момент работает? Благо у меня в этот день есть ещё шанс - по статистике должно стрельнуть ещё раз, но чуть позже. Но это будет под ночь уже по нашему времени, никто сидеть дежурить на объекте не будет, надо это дело как-то автоматизировать.
Из всех программ, которые показывают, кто в режиме реально времени пишет в файлы и реестр, я знаю только Process Monitor от тех же Sysinternals (Руссинович молодец конечно). И как раз её можно запустить через консоль, записать нужное нам по времени количество логи доступа и закрыть программу, а на утро уже посмотреть записанное и разобраться что к чему.
Вот тут для меня оказалось откровением, как стандартными средствами посмотреть загрузку процессора. Всеми предлагаемая команда wmic cpu get LoadPercentage дает значение близкое к нагрузке на 1ое ядро, чем на весь процессор. Я делал простой бесконечный цикл в vba и крутил его - если вывести в консоль данную команду, открыть диспетчер задач, то полученное значение будет как я говорил выше. Вопрос почему так - а потому что значение, которое отображается в диспетчере задач, пересчитывается от всех ядер. Плюс ещё от системы зависит, как правильно сформировать запрос в консоли - вот пример с stackoverflow. Для понимания, как это делает диспетчер задач гуглить фразу NtQuerySystemInformation. Добавлю пару ссылок - раз, два, три (тут больше про счетчики производительности, но для понимания нужно). Если кто разбирается в этом более подробно, то вот вам идея для статьи - пишем правильный счетчик нагрузки многоядерного процессора. Ну отвлеклись, продолжу.
Из-за того, что нагрузка смотрится на ядро, можно словить неприятный момент. Я запускаю скрипт под Администратором, не выхожу из пользователя, а сменяю его на учетную запись пользователя и в этот момент я могу словить нагрузку на ядро. Как вы помните, процессор на данной панели очень слабый и любая нагрузка пролетает. Поэтому я пишу следующий скрипт, запускаю его и тестирую.
Batник со следующим содержимым
@chcp 1251
@echo OFF
setlocal enabledelayedexpansion
set /a cpuload=81
:proverka
rem Цикл нагрузки ЦПУ
echo Выбраная для сравнения нагрузка на CPU = %cpuload%
for /f "skip=1" %%i in ('wmic cpu get LoadPercentage') do (
set Times=%%i
echo !Times!
IF !Times! GEQ %cpuload% goto processmonitor
rem @echo Нагрузка больше или равна %cpuload%
)
goto proverka
:processmonitor
set PM=C:\ProcessMonitor\procmon.exe
start %PM% /quiet /minimized /backingfile C:\ProcessMonitor\temp\hishload.pml
%PM% /waitforidle
TIMEOUT /T 10 /NOBREAK
%PM% /terminate
goto ENDS
:ENDS
@echo Tyt stopНаписано на bat, а не Powershell, потому что в поставке Win7 то ли его не было, то ли были какие-то проблемы с ним.
cpuload я вывел в отдельную переменную, так как приходилось играться со значением нагрузки. Подобрав опытным путем значение, я, после смены пользователя, не вызывал сработку скрипта и со спокойной душой ушел спать. На следующий день сообщение по нагрузке сформировалось в нужный момент - как и было запланировано.
Открываю логи и убийцей оказался кто вы могли бы подумать? Acronis Backup. Нет, бэкап в этот момент не создавался. Просто программа собирала логи системы для системного отчета в компанию для отправки по интернету. Это пункт в настройках зовется Программа улучшения качества программного обеспечения Acronis. По WMI она собирает статистику о системе, делает свой файл с логами и пытается их отправить. Но так как у нас изолированная система, то логи никуда не уходят, и Acronis на следующий день пытается это сделать ещё раз. После всех попыток, она через какое-то время пытается сделать тоже самое и так по кругу. Как ловить такие моменты в системе - я пока, кроме данного способа не придумал. Галочку в настройках сняли, службу на всякий случай перезапустили - проблем с тех пор не было.
Случай №3 - утечка памяти
Когда я работал с этим случаем, то все статьи в интернете только и пестрят - утечки в Java/Net/JS и другой язык программирования, но нигде нет простого объяснения, что делать, если ты не разработчик и программа не твоя (если есть годное - кидайте ссылки в комментариях, обязательно посмотрю). А пока расскажу, как я анализировал утечку.
Опять у нас панель с примерно таким же железом, но на этот раз другая софтовая часть. В какой-то момент происходит утечка памяти процесса KEPServer EX - OPC сервер производителя Kepware. Процесс c 40 Мбайт разрастается до 500 Мбайт. Перезапускать службы у нас нельзя для решения проблемы, поэтому начинаем разбираться.
Первым делом, чтобы выяснить, что не так с процессом, нам необходимо снять дамп памяти. Это можно сделать стандартной утилитой из поставляемой в комплекте для сбора логов KEPServer Report Tool, либо через диспетчер задач, либо утилитами от Sysinternals. Мы для определения использования всей памяти всегда используем RAMMap - полезная утилита, но в данном случае именно для процесса используем уже другую утилиту - VMMap.
Открываем VMMap, выбираем процесс, смотрим (я вам для примера покажу на другом процессе, но суть действий такая же):
Так вот, heap (куча) занимаемая процессом занимала под 500 Мбайт, остальное незначительное. И таких heap строк в программе я насчитал около 41 штуки - такое количество, сколько дней у нас работает приложение. Как говорится - "Совпадение? Не думаю". Каждый адрес памяти можно посмотреть - что там за строки хранятся. Для этого выбираем адрес, в меню выбираем "View -> Strings":
Я прощелкал почти каждую область памяти и увидел, что они забиты логами из программы. Тот же самый результат можно увидеть и через дамп, который мы сняли. Для этого нам понадобится WinDBG (чтобы не качать весь WDK, есть на гитхабе скаченные установщики - ссылка). Скачиваем, устанавливаем, открываем наш дамп файл через "File -> Open Crash Dump". Через пункт меню "View -> Memory" можно так же по адресам посмотреть содержимое памяти.
Скриншоты
Я посмотрел через WinDbg и там так же в тех же областях памяти были строки с логами, которые пишет программа. В настройках программы есть пункт меню, в котором можно настроить логирование:
Для всех типов диагностики был выбран тип записи логов в файл (количество событий тоже уменьшено для уменьшения нагрузки), служба для применения настроек перезапущена - после данных действий проблем не возникало. Так же с помощью VMMap можно чистить Working Set - иногда помогает, но в моём случае это была бы полумера - процесс вновь бы занял всю память.
Итог
Исходя из этого можно сделать несколько выводов.
Думайте, какой уровень логирования вам нужен и нужно ли это вообще.
Безвыходных ситуаций почти нет - нужно только найти правильный инструмент.
Иногда неочевидные вещи могут влиять на всю систему в целом.
В комментариях предлагаю обсудить, как бы вы решали данные проблемы и что можете посоветовать для таких случаев.
И, пока не кончился отпуск, постараюсь написать хотя бы первую часть про реверс-инжиниринг одной программы в области АСУ от любимого уже мне производителя Schneider Electric.
