Threads and Excessive CPU Consumption in WAS for z/OS

      Когда Вы замечаете, что Ваш сервер приложений на z/OS очень сильно потребляет CPU, то возникает вопрос – как найти источник (причину) такого поведения сервера? В этой статье будет рассмотрен подход, позволяющий определить источник чрезмерного потребления процессора с помощью возможностей z/OS, WebSphere Application Server и Java SDK.

Введение: в чем суть?

     Первое с чего стоит начать, это понять, действительно ли сервер приложений стал чрезмерно “кушать” CPU или нет? Для этого следует обратиться к статистике по использованию CPU, собираемой такими инструментами z/OS как RMF или SMF. Проанализировав статистику, необходимо понять, связано ли увеличение использования CPU с ростом рабочей нагрузки, а так же сравнить потребление процессора за нужный временной интервал с показателями статистики за этот же интервал в прошлом. Важно убедиться, что проблемы действительно существуют, а не являются надуманными, особенно если Вы не знаете изменялся ли характер или объем нагрузки, изменялась ли среда окружения.

     Если установлено, что проблемы с чрезмерным потреблением процессора сервером приложений действительно существуют, то далее необходимо воспользоваться методикой, которая состоит из двух основных этапов:

  1. С помощью средств z/OS определить потоки (треды, threads) сервера приложений, которые сильно используют CPU.
  2. Снять javacore дамп, в котором можно будет найти поток, выявленный на первом шаге, и увидеть какой код он исполняет.

      Обычно этого достаточно, что бы узнать причину чрезмерного потребления CPU и понять проблема в “системе” или в “приложении“.

Часть1. Разложение сервера приложений на потоки

   В среде z/OS код приложений исполняется в серванте (Servant Region) сервера приложений, поэтому необходимо получить информацию о нитках серванта. Для этого необходимо воспользоваться возможностями SDSF (System Display and Search Facility). В меню SDSF выберите PS (Processes), найдите интересующий Вас процесс серванта (того, который чрезмерно потребляет CPU) и выдайте напротив него строчную команду ‘d’. Обратите внимание, что процессов серванта несколько, даже если у Вас выделен всего один сервант для сервера приложений, то ему соответствуют два процесса в системе. Необходимо выдать команду ‘d’ напротив того процесса, который находится в статусе ‘Running‘ и имеет значение PPID отличное от ‘1‘. Это показано на рисунке ниже (кликните для увеличения).

SDSF-PS-d-linecommand

  Что же делает строчная команда ‘d’? Она выполняет SDSF команду D OMVS,PID=XXXXXX , где XXXXXX – process id (PID) интересующего нас серванта. То есть, зная PID серванта можно самостоятельно выполнить команду D OMVS,PID= и получить информацию о потоках серванта. Удобство в том что, что вам не нужно искать PID серванта и вставлять его в команду, SDSF сделает это за Вас. Результат команды не поместится на экране целиком, о чем свидетельствует сообщение в правом верхнем углу “XX RESPONSES NOT SHOWN”. Поэтому, для его просмотра, перейдите в журнал пользователя (user log), для этого в строке ввода команд введите ‘ULOG‘. Там Вы сможете полностью увидеть информацию о потоках серванта, которую мы проанализируем позже.

     Хочу обратить внимание, что не всегда удобно оценивать использование процессора в SDSF PS, по столбцу CPU-Time, особенно когда сервер приложений имеет несколько сервантов. Для этого удобнее использовать SDSF DA, и анализировать столбец CPU%, который нагляднее показывает использование процессора.  Поэтому, приведу еще один способ как получить информацию о потоках серванта без использования строчной команды ‘d’ в SDSF PS, но требующий больше действий руками.

      Для этого в меню SDSF выберите DA (Active users), найдите интересующее Вас адресное пространство серванта (того, который чрезмерно потребляет CPU) и узнайте его ASIDX. После этого выдайте команду: D OMVS,ASID=XXXX , где XXXX – значение ASIDX серванта. Пример ответа команды D OMVS,ASID= приведен ниже.

     Скопируйте значение PID того процесса, PPID которого не равен ‘1’. И в строке ввода команд введите D OMVS,PID=XXXXXX , где XXXXXX –  process id интересующего нас серванта, точнее скопированный PID. Результат команды не поместиться целиком на экране, поэтому для его просмотра можно перейти либо в журнал пользователя (user log), либо в syslog (введите ‘LOG‘ в строке ввода команд).

     Если у вас нет возможности или желания работать в SDSF, то есть другой вариант. В телнет-сессии используйте Unix команду ‘ps‘, синтаксис которой приведен ниже:

Пример выполнения этой команды:

Другие полезные команды для Unix, на эту тему, которые Вы можете попробовать:

     Помните, что необходимо выполнять команды из под superuser‘a, что бы работать с процессами, не принадлежащими Вашему userid.

     Еще один вариант это получить информацию о потоках серванта из java программы. Т.е. выполнить команду ‘ps’, а так же снять javacore дамп прямо из программы. Ниже приведены фрагменты кода, показывающие как это сделать.

Часть 2. Анализ тредов серванта

      Вернемся к полученному представлению потоков серванта, т.е. результату выполнения команды D OMVS,PID=XXXXXX, и рассмотрим его подробнее. Ниже приведена информация по серванту WAS V7. Обратите внимание на цифры справа – это сноски, которые будут разъяснены далее.

    Подробное описание результата команды D OMVS,PID= содержится в сообщении BPXO040I, с которым можно ознакомиться здесь или в соответствующем разделе IBM InfoCenter для z/OS.

//1 – Значение поля CT_SECS – это суммарное время использования CPU процессом серванта с момента его запуска. Измеряется в секундах, в формате ssssss.hhh. Когда сервант работает более 11,5 дней, то CT_SECS переполняется и вместо значения будут отображаться “звездочки”: ******.***

   Столбец  ACC_TIME – показывает использование процессора (CPU time) каждым потоком серванта. Измеряется в секундах, в формате ssssss.hhh. Когда сервант работает более 11,5 дней, то ACC_TIME переполняется и вместо значений будут отображаться “звездочки”: ******.**, а если данных для отображения нету, то и вовсе **********. По идее CT_SECS  – это сумма всех ACC_TIME, но фактически это не так, потому что некоторые потоки завершаются. Например, потоки в пуле соединений (connection pool) завершаются, если долго находятся в ожидании и срабатывает тайм-аут неиспользования (unused timeout). Это можно увидеть, когда номера (последние 8 символов THREAD_ID) двух соседних потоков идут не по порядку, т.е. между ними есть пробелы. Например, между тредами 178D4FF000000012 и 178DC87000000016 отсутствуют еще 3 потока.

//2 – Это поток инициализации, “главный” тред.

//3 – Обычно этот поток, или следующий за ним, это JIT компилятор. Вот как он выглядит в дампе javacore:

//4 – Группа тредов, с примерно одинаковыми значениями использования CPU, это потоки сборщика мусора (garbage collection (GC) slave threads). В javacore они представлены следующим образом:

   Число тредов сборщика мусора зависит от числа доступных процессоров. Эта зависимость выражается формулой: Число_нитей_GC = число_CPU – 1. При этом число_CPU, это общее число процессоров, находящихся в online на момент запуска адресного пространства, которое включает в себя процессоры общего пользования (CP), zIIP и zAAP процессоры. Так, из приведенного выше примера, видно, что мы имеем 9 потоков сборщика мусора, а значит в нашей системе 10 процессоров.

    Анализировать работу сборщика мусора можно по использованию процессора его потоками. Для этого необходимо суммировать значения ACC_TIME всех тредов GC, и посмотреть какой процент от CT_SECS они составляют. Полученное значение не должно превышать 10%. Это свидетельствует о том, что выбрана правильная политика работы сборщика мусора. Если полученное значение превышает 10%, то необходимо подумать о смене политики сборщика мусора.

     Давайте сделаем это на нашем примере. Среднее значение использования CPU нашими потоками GC равно 504, 504*9=4536. Посчитаем какой процент это составляет от 50680, для этого 4536/50680*100=8,95%=9%.

//5 – Это поток завершения, Finalizer thread. В javacore он представлен следующим образом:

    Обычно этото тред не использует много CPU, но когда приложения используют очень много finalizer methods, то это приводит к задержке удаления неиспользуемых объектов в процессе сборки мусора, что может привести к увеличению числа циклов сборки мусора и фрагментации кучи JVM, что в свою очередь может являться причиной чрезмерного использования CPU. В таком случае необходимо воспользоваться рекомендациями по уменьшению использования финализатора, “Reduce finalizer usage”, содержащимися в IBM SDK for Java Information Center.

//6 – Группа потоков, напротив которых стоит обозначение “WLM“, это треды ORB пула (ORB thread pool). Это непосредственно рабочие потоки, исполняющие код приложения, а точнее обрабатывающие анклавы.

В javacore они выглядят следующим образом:

    Количество рабочих потоков (ORB threads) зависит от выбранного профиля рабочей нагрузки (Workload profile). Профиль рабочей нагрузки, это параметр, определяющий количество рабочих потоков в серванте сервера приложений в зависимости от типа обрабатываемой нагрузки. Он обеспечивает дополнительную масштабируемость сервера приложений и помогает оптимизировать использование системных ресурсов. Параметр workload profile устанавливается в административной консоли WAS:

      Servers > Application servers > server_name > Container services > ORB service > z/OS additional settings

Подробнее о настройке workload profile смотрите здесь.

   В нашем примере используется WAS V7, workload profile установлен в значение CUSTOM, а переменная, servant_region_custom_thread_count, определяющая количество рабочих тредов в серванте, установлена в значение 90. То есть сервант имеет 90 рабочих потоков.

    При анализе тредов серванта важно обратить внимание на использование CPU всеми рабочими потоками. Если замер делался в период пиковых нагрузок, а при анализе видно, что есть большое число потоков, которые не ведут никакой работы, то есть не используют CPU (значение ACC_TIME равно .001), то необходимо изменить workload profile, т.е. уменьшить количество рабочих потоков в серванте. При этом следует основываться на числе рабочих тредов, которые реально осуществляю работу в моменты пиковых нагрузок, т.е. ACC_TIME которых значительно превосходит .001. Слишком большое количество тредов, которые не ведут никакой работы, может привести к ухудшению производительности системы в целом. Это связано с работой back-end’а. Например, возникают проблемы в DB2, замедление работы, при этом начинает накапливаться количество рабочих потоков серванта, пытающихся выполнить работу. Это может привести к тому, что сервант увеличит использование кучи JVM, в свою очередь активнее начнет работать сборщик мусора, все это сказывается на увеличении использования CPU, а если размер кучи JVM будет приближаться к максимальному, то система начнет использовать подкачку (paging). Ситуация усугубляется, если сервер приложений имеет несколько сервантов. Помните, что оптимизация и тюнинг – это не всегда бездумное увеличение значений параметров.

    В нашем примере сервер приложений имеет один сервант с 90 рабочими тредами, посмотрев на которые видно, что 39 из них не участвуют в реальной работе. И если допустить, что замеры сделаны в период пиковых нагрузок, то необходимо сократить количество потоков с 90 до 51, после чего повторить замер и анализ.

//7 – 4 потока, которые следуют после рабочих (WLM) тредов, имеющие примерно одинаковые значения использования CPU – это треды “Deferrable Alarm“. Они нужны для управления потоками пула соединений. В javacore выглядят так:

      Мы рассмотрели основные потоки в серванте сервера приложений. Остальные – это треды мониторинга (ITCAM), пул тредов Work Manager’a, которые исполняют асинхронные бины (Async Beans), вспомогательные потоки, которые обеспечивают выполнение работы тредами ORB. Некоторые из них запускаются WebSphere, некоторые запускаются коннекторами, которые используют приложения для соединения, например, с MQ или LDAP, а некоторые – самой JVM. В любом случае, что бы понять, что делает тот или иной поток, необходимо посмотреть на него в дампе javacore.

     ! На этом этапе важно выделить тот поток (или потоки), который намного больше других потребляет CPU (по столбцу ACC_TIME). Скопируйте THREAD_ID выбранного треда.

Часть 3. Работа с javacore

     Заключительная часть статьи посвящена вопросам получения и анализа дампа javacore. Javacore – это небольшой дамп, определенного формата, легкий для понимания, который может быть проанализирован даже не специалистом. Для формирования дампа javacore, в DA или в LOG (меню SDSF) выполните команду:

F ,JAVACORE

     Вместо необходимо подставить имя сервера приложений (Control Region). Эта команда сформирует дампы javacore для всех адресных пространств сервера (Control Region, Servant Region, Adjunct Region [если запущен]). Javacore будут сформированы в директорию, определенную переменной среды IBM_JAVACOREDIR. Если эта переменная не определена, то javacore будут сформированы в домашние директории пользователей из-под которых работают адресные пространства сервера. Ниже приведен пример выполнения команды F ,JAVACORE, для сервера приложений ED1SR03:

    После выдачи команды, появляется сообщение, в котором отображено размещение формируемых javacore. В журнале сервера приложений так же фиксируется формирование дампа javacore, с указанием файлов. Когда javacore успешно сформирован, с помощью FTP клиента, копируем его к себе на ПК для дальнейшего анализа.

     В полученном javacore серванта будем искать потоки, которые были отобраны в процессе анализа результатов команды D OMVS,PID=. Для этого из THREAD_ID отобранного треда копируем первые 8 байт и ищем эту последовательность в дампе javacore. Когда поиск будет завершен, мы увидим stack trace, из которого узнаем, какой код исполняет поток, а значит, который сильно потребляет CPU.

Например, в полученном выше результате команды D OMVS,PID=, нам интересен поток:

1796326000000048 009C2938 WLM         2145.880 WRT JR V

По последовательности 17963260 найдем этот тред в javacore:

     Как видно из фрагмента javacore, первые 8 байт THREAD_ID соответствуют значению “native thread ID” в javacore. Из stack trace мы узнаем, что выбранный поток исполняет код приложения, которое делает вызов другого приложения с помощью web сервиса, и передает ему данные.

Заключение

  В заключении резюмируем все описанное выше, т.е. составим подробную последовательность действий для выявления “сбойного” треда:

  1. В режиме реального времени мы видим, что сервант сервера приложений чрезмерно использует CPU.
  2. Выполняем команду D OMVS,PID=XXXXXX , где XXXXXX – process id (PID) интересующего нас серванта. (Строчная команда ‘d’).
  3. Выполняем команду F ,JAVACORE , где  – имя сервера (Control Region).
  4. Переходим в журнал пользователя (user log), для этого в строке ввода команд введите ‘ULOG‘.
  5. Ищем поток (потоки) которые больше остальных используют CPU (смотрим по столбцу ACC_TIME).
  6. У выбранных потоков копируем первые 8 байт THREAD_ID.
  7. В полученном javacore серванта ищем выбранные потоки по первым 8 байтам THREAD_ID.
  8. У найденных тредов смотрим stack trace, показывающий исполняемый ими код.
  9. Анализируем полученный код. Какие классы исполняются? Проблема в сервере или в приложении?
  10. В зависимости от результатов анализа, связываемся с разработчиками для изменения кода приложения или оптимизируем параметры системы.

P.S.: статья основана на
Icon of Troubleshooting WP101474 Threads And Excessive CPU Consumption In WAS ZOS (162.3 KB)

VN:F [1.9.22_1171]
Rating: 5.0/5 (4 votes cast)
Tagged with: , , , , ,
Posted in WebSphere Application Server, Troubleshooting

Leave a Reply

Your email address will not be published. Required fields are marked *

*

You may use these HTML tags and attributes: <a href="" title=""> <abbr title=""> <acronym title=""> <b> <blockquote cite=""> <cite> <code class="" title="" data-url=""> <del datetime=""> <em> <i> <q cite=""> <s> <strike> <strong> <pre class="" title="" data-url=""> <span class="" title="" data-url="">

Language: