Когда Вы замечаете, что Ваш сервер приложений на z/OS очень сильно потребляет CPU, то возникает вопрос – как найти источник (причину) такого поведения сервера? В этой статье будет рассмотрен подход, позволяющий определить источник чрезмерного потребления процессора с помощью возможностей z/OS, WebSphere Application Server и Java SDK.
Введение: в чем суть?
Первое с чего стоит начать, это понять, действительно ли сервер приложений стал чрезмерно “кушать” CPU или нет? Для этого следует обратиться к статистике по использованию CPU, собираемой такими инструментами z/OS как RMF или SMF. Проанализировав статистику, необходимо понять, связано ли увеличение использования CPU с ростом рабочей нагрузки, а так же сравнить потребление процессора за нужный временной интервал с показателями статистики за этот же интервал в прошлом. Важно убедиться, что проблемы действительно существуют, а не являются надуманными, особенно если Вы не знаете изменялся ли характер или объем нагрузки, изменялась ли среда окружения.
Если установлено, что проблемы с чрезмерным потреблением процессора сервером приложений действительно существуют, то далее необходимо воспользоваться методикой, которая состоит из двух основных этапов:
- С помощью средств z/OS определить потоки (треды, threads) сервера приложений, которые сильно используют CPU.
- Снять javacore дамп, в котором можно будет найти поток, выявленный на первом шаге, и увидеть какой код он исполняет.
Обычно этого достаточно, что бы узнать причину чрезмерного потребления CPU и понять проблема в “системе” или в “приложении“.
Часть1. Разложение сервера приложений на потоки
В среде z/OS код приложений исполняется в серванте (Servant Region) сервера приложений, поэтому необходимо получить информацию о нитках серванта. Для этого необходимо воспользоваться возможностями SDSF (System Display and Search Facility). В меню SDSF выберите PS (Processes), найдите интересующий Вас процесс серванта (того, который чрезмерно потребляет CPU) и выдайте напротив него строчную команду ‘d’. Обратите внимание, что процессов серванта несколько, даже если у Вас выделен всего один сервант для сервера приложений, то ему соответствуют два процесса в системе. Необходимо выдать команду ‘d’ напротив того процесса, который находится в статусе ‘Running‘ и имеет значение PPID отличное от ‘1‘. Это показано на рисунке ниже (кликните для увеличения).
Что же делает строчная команда ‘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= приведен ниже.
|
1 2 3 4 5 6 7 |
D OMVS,ASID=0088 BPXO040I 15.08.59 DISPLAY OMVS 517 OMVS 000E ACTIVE OMVS=(00,F1,WS,50,CA,08,58) USER JOBNAME ASID PID PPID STATE START CT_SECS EDDMS ED1SR03S 0088 67108981 1 1W---- 10.52.15 50658.023 LATCHWAITPID= 0 CMD=BPXBATSL EDDMS ED1SR03S 0088 121 67108981 HR---- 10.52.15 50658.023 |
Скопируйте значение PID того процесса, PPID которого не равен ‘1’. И в строке ввода команд введите D OMVS,PID=XXXXXX , где XXXXXX – process id интересующего нас серванта, точнее скопированный PID. Результат команды не поместиться целиком на экране, поэтому для его просмотра можно перейти либо в журнал пользователя (user log), либо в syslog (введите ‘LOG‘ в строке ввода команд).
Если у вас нет возможности или желания работать в SDSF, то есть другой вариант. В телнет-сессии используйте Unix команду ‘ps‘, синтаксис которой приведен ниже:
|
1 |
ps -p -m -o xtid,xtcbaddr,state=STATE -o atime=CPUTIME -o syscall |
Пример выполнения этой команды:
|
1 2 3 4 5 6 7 |
TID TCBADDR STATE CPUTIME SYSC - - HR 14:12 - 1e4e300000000000 8d0e00 YU 0:20 1e4e400000000001 8d07a8 YJV 0:00 1e4e500000000002 8d0588 YNJV 0:00 1e4e600000000003 8d0368 YJV 1:35 1e4e700000000004 8d0148 YJV 0:25 |
Другие полезные команды для Unix, на эту тему, которые Вы можете попробовать:
|
1 2 |
ps -p -o pid,ppid,xasid,thdcnt,vsz=VIRTUAL -o atime,jobname,ruser,etime -o args ps -p -o pid,xasid,xstid,xtcbaddr,wtime,semnum,lpid,lsyscall,syscall,atime,state -o THREAD -o comm=CMD |
Помните, что необходимо выполнять команды из под superuser‘a, что бы работать с процессами, не принадлежащими Вашему userid.
Еще один вариант это получить информацию о потоках серванта из java программы. Т.е. выполнить команду ‘ps’, а так же снять javacore дамп прямо из программы. Ниже приведены фрагменты кода, показывающие как это сделать.
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 |
/* Now get the ps and javacore doc ourselves */ String getDoc = System.getProperty("mcc.get.doc"); if (getDoc != null) { System.out.println("\nCapturing documentation"); String pidString = java.lang.Integer.toString(pid); String cmd = "ps -m -o xtid,xtcbaddr,state=STATE -o atime=CPUTIME -o syscall -p " + pidString + " "; command(cmd); com.ibm.jvm.Dump.JavaDump(); } System.out.println("Done..."); . . . . public static void command( String cmd) { try { System.out.println("\nExecuting command: \n" + cmd + " "); Process commandProcess = Runtime.getRuntime().exec(cmd); int status = 0; try { status = commandProcess.waitFor(); } catch (InterruptedException e) { status = -1; } if (status == 0) { System.out.println("\nCommand process completed successfully, results follow.\n"); InputStreamReader in = new InputStreamReader(commandProcess.getInputStream(),"cp1047"); int = 0; c while ((c = in.read()) != -1) { System.out.print((char)c); } } else { System.out.println("\n\nCommand process exited with " + status); } } catch (IOException eio) { System.err.println(eio); } } |
Часть 2. Анализ тредов серванта
Вернемся к полученному представлению потоков серванта, т.е. результату выполнения команды D OMVS,PID=XXXXXX, и рассмотрим его подробнее. Ниже приведена информация по серванту WAS V7. Обратите внимание на цифры справа – это сноски, которые будут разъяснены далее.
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100 101 102 103 104 105 106 107 108 109 110 111 112 113 114 115 116 117 118 119 120 121 122 123 124 125 126 127 128 129 130 131 132 133 134 135 136 137 138 139 140 141 142 143 144 145 146 147 148 149 150 151 152 153 154 155 156 157 158 159 160 161 162 163 164 165 166 167 |
D OMVS,PID=121 BPXO040I 15.12.37 DISPLAY OMVS 528 OMVS 000E ACTIVE OMVS=(00,F1,WS,50,CA,08,58) USER JOBNAME ASID PID PPID STATE START CT_SECS //1 EDDMS ED1SR03S 0088 121 67108981 HR---- 10.52.15 50680.341 //1 THREAD_ID TCB@ PRI_JOB USERNAME ACC_TIME SC STATE 17829A9000000000 009F1CF0 221.977 IPT YU //2 17837C8000000001 009F1A60 9.507 PTX JY V 1783A9B000000002 009F1840 .001 PTX JYNV 1783C7D000000003 009F1528 133.179 SOP JY V //3 1784041000000004 009F1298 764.534 STE JY V 1784132000000005 009F1100 .001 PTX JY V 1784405000000006 009E8E88 .345 PTC JY V 17844F6000000007 009E8C68 504.472 PTX JY V //4 --> 17845E7000000008 009E8A48 503.243 PTX JY V 17848BA000000009 009E8828 504.798 PTX JY V 1784A9C00000000A 009E8608 505.950 PTX JY V 1784D6F00000000B 009E83E8 504.550 PTX JY V 178504200000000C 009E81C8 504.235 PTX JY V 178540600000000D 009DDE88 502.751 PTX JY V 17858BB00000000E 009DDCF0 503.824 PTX JY V 1785C7F00000000F 009DD658 502.218 PTX JY V //--> 4 178D4FF000000012 009DD218 37.948 STE JY V 178DC87000000016 009DD438 .001 LST JY V 178DF5A000000017 009DCB58 .902 SOP JY V 178E22D000000018 009DC938 1.207 STE JY V 178E40F000000019 009DC718 43.430 CLO JY V //5 178E7D300000001B 009DC2D8 1.704 STE JY V 178E9B500000001C 009DC0B8 1.747 STE JY V 178EAA600000001D 009DBE88 210.206 STE JY V 178EC8800000001E 009DBC68 179.955 STE JY V 178F50100000001F 009DBA48 .001 PTX JY V 178F8C5000000020 009DB828 .001 PTX JY V 178FB98000000021 009DB608 .001 PTX JY V 179013E000000022 009DB3E8 .001 PTX JY V 179022F000000023 009DB1C8 .001 PTX JY V 1790502000000024 009C9E88 .001 PTX JY V 17908C6000000025 009C9CF0 .001 PTX JY V 1790B99000000026 009C9658 2.827 STE JY V 1790C8A000000027 009C9438 22.965 STE JY V 17916E5000000028 009C9218 1.453 STE JY V 1791E6D000000029 009C8E88 .001 PTX JY V 179204F00000002A 009C8CF0 .001 PTX JY V 179223100000002B 009C8B58 .001 PTX JY V 179250400000002C 009C8938 .001 PTX JY V 17929B9000000030 009C8718 36.297 STE JY V 1792B9B000000031 009C84F8 20.869 STE JY V 1792E6E000000034 009C5E88 24.291 STE JY V 17938C9000000035 009C5C68 22.158 STE JY V 179541600000003B 009C5828 7.382 STE JY V 179550700000003C 009C5608 .766 STE JY V 17955F800000003D 009C53E8 13.666 STE JY V 17956E900000003E 009C51C8 4.220 STE JY V 17957DA00000003F 009C4E88 22.051 STE JY V 1795B9E000000040 009C4438 .001 SOP JR V 1795C8F000000041 009C4658 2.410 LST JR V 1795D80000000042 009C4CF0 .586 LST JR V 1795E71000000043 009C5A48 .555 LST JR V 1795F62000000044 009C4218 WLM 1815.670 WRT JR V //6 --> 1796053000000045 009C2E88 WLM .001 LST JR V 1796144000000046 009C2CF0 WLM .001 LST JR V 1796235000000047 009C2B58 WLM .001 LST JR V 1796326000000048 009C2938 WLM 2145.880 WRT JR V 1796417000000049 009C2718 WLM .001 LST JR V 179650800000004A 009C24F8 WLM .001 LST JR V 17965F900000004B 009C22D8 WLM 1897.645 WRT JR V 17966EA00000004C 009C20B8 WLM 2033.014 WRT JR V 17967DB00000004D 009C1E88 WLM 51.952 CLO JR V 17968CC00000004E 009C1C68 WLM .006 LST JR V 17969BD00000004F 009C1A48 WLM .002 SOP JR V 1796AAE000000050 009C1828 WLM 508.080 WRT JR V 1796B9F000000051 009C1608 WLM 136.402 WRT JR V 1796C90000000052 009C13E8 WLM 883.680 WRT JR V 1796D81000000053 009C11C8 WLM .001 SOP JR V 1796E72000000054 009BDE88 WLM 370.848 WRT JR V 1796F63000000055 009BDCF0 WLM 463.358 IOC JR V 1797054000000056 009BD658 WLM .001 PTX JR V 1797145000000057 009BD438 WLM .004 PTX JR V 1797236000000058 009BD218 WLM .001 PTX JR V 1797327000000059 009BC7C0 WLM 176.782 WRT JR V 179741800000005A 009BC628 WLM .001 PTX JR V 179750900000005B 009BC490 WLM .001 PTX JR V 17975FA00000005C 009BC050 WLM .001 PTX JR V 17976EB00000005D 009BC270 WLM .001 PTX JR V 17977DC00000005E 009BBE00 WLM .001 PTX JR V 17979BE00000005F 009BBBE0 WLM .001 PTX JR V 1797AAF000000060 009BB9C0 WLM .001 PTX JR V 1797BA0000000061 009BB580 WLM .001 PTX JR V 1797C91000000062 009BB7A0 WLM .001 PTX JR V 1797D82000000063 009BB360 WLM .001 PTX JR V 1797E73000000064 009BB140 WLM .001 PTX JR V 1797F64000000065 009B9E88 WLM .001 PTX JR V 1798055000000066 009B9CF0 WLM .001 PTX JR V 1798146000000067 009B9AD0 WLM .001 PTX JR V 1798237000000068 009B98B0 WLM .001 PTX JR V 1798328000000069 009B9690 WLM .001 PTX JR V 179841900000006A 009B8E88 WLM 306.837 WRT JR V 179850A00000006B 009B8CF0 WLM .029 IOC JR V 17985FB00000006C 009B8AD0 WLM 489.609 IOC JR V 17986EC00000006D 009B88B0 WLM .005 PTX JR V 17987DD00000006E 009B8470 WLM 309.472 WRT JR V 17988CE00000006F 009B8690 WLM .005 PTX JR V 17989BF000000070 009B8250 WLM 449.578 WRT JR V 1798AB0000000071 009B8030 WLM 202.180 IOC JR V 1798BA1000000072 009B5E00 WLM 280.277 IOC JR V 1798C92000000073 009B5BE0 WLM 428.668 WRT JR V 1798D83000000074 009B59C0 WLM 579.462 IOC JR V 1798E74000000075 009B57A0 WLM 306.377 IOC JR V 1798F65000000076 009B5580 WLM .279 CLO JR V 1799056000000077 009B5360 WLM 1695.113 WRT JR V 1799147000000078 009B5140 WLM 412.126 WRT JR V 1799238000000079 009B3E88 WLM .031 IOC JR V 179932900000007A 009B3CF0 WLM .005 PTX JR V 179941A00000007B 009B3AD0 WLM 276.379 IOC JR V 179950B00000007C 009B38B0 WLM .004 PTX JR V 17995FC00000007D 009B3690 WLM 1496.770 IOC JR V 17996ED00000007E 009B1E88 WLM .005 PTX JR V 17997DE00000007F 009B1840 WLM 2105.242 WRT JR V 17998CF000000080 009B1A60 WLM 176.834 WRT JR V 17999C0000000081 009B1CF0 WLM .005 PTX JR V 1799AB1000000082 009B1620 WLM 2374.752 WRT JR V 1799BA2000000083 009B1400 WLM 357.555 WRT JR V 1799C93000000084 009B11E0 WLM 2283.387 WRT JR V 1799D84000000085 009B0E88 WLM .007 WRT JR V 1799E75000000086 009B0CF0 WLM .004 PTX JR V 1799F66000000087 009B0B58 WLM 2074.216 WRT JR V 179A057000000088 009B0938 WLM .005 PTX JR V 179A148000000089 009B0718 WLM 243.413 WRT JR V 179A23900000008A 009B04F8 WLM 399.193 CLO JR V 179A32A00000008B 009B02D8 WLM .005 PTX JR V 179A41B00000008C 009B00B8 WLM 401.051 WRT JR V 179A50C00000008D 009AEE88 WLM 264.189 IOC JR V 179A5FD00000008E 009AEC68 WLM 151.023 WRT JR V 179A6EE00000008F 009AEA48 WLM 1163.551 WRT JR V 179A7DF000000090 009AE828 WLM 413.173 WRT JR V 179A8D0000000091 009AE608 WLM 183.402 WRT JR V 179A9C1000000092 009ABC68 WLM 1.292 CLO JR V 179AAB2000000093 009ABE88 WLM 110.658 WRT JR V 179ABA3000000094 009ABA48 WLM .203 LST JR V 179AC94000000095 009AB828 WLM 279.691 IOC JR V 179AD85000000096 009AB608 WLM .560 STE JR V 179AE76000000097 009AB3E8 WLM 248.352 WRT JR V 179AF67000000098 009AAE88 WLM 388.296 CLO JR V 179B058000000099 009AB1C8 WLM 495.073 WRT JR V 179B14900000009A 009AACF0 WLM 159.150 WRT JR V 179B23A00000009B 009AAB58 WLM 1180.649 WRT JR V 179B32B00000009C 009AA488 WLM .957 IOC JR V 179B41C00000009D 009AA718 WLM 232.028 WRT JR V //--> 6 179B50D00000009E 009AA938 .151 LST JR V 179B5FE00000009F 009AA048 37.487 WRT JR V 179B6EF0000000A0 009AA268 156.410 LST JR V 17A25140000000A3 009A8BD0 1303.158 STE JY V //7 --> 17A29C90000000A4 009A89B0 1308.763 STE JY V 17A2ABA0000000A5 009A8790 1305.459 STE JY V 17A2BAB0000000A6 009A8570 1306.239 STE JY V //--> 7 17A30600000000A8 009DC4F8 47.058 STE JY V 17A31510000000A9 009A8130 33.776 STE JY V 17A32420000000AA 009A6988 35.594 STE JY V 17A66090000000AC 009A67F0 .318 STE JY V 17C48090000000B1 009A4CF0 .001 SOP JY V 17D6EB200000011B 009C82D8 .001 PTX JY V 17E591B000000590 009C80B8 2.251 STE JY V 17C42630000BFFFB 009A4E88 221.393 CPO JY V 17C55370000BFFFC 009A82C8 62.370 SND JY V 17C56280000BFFFD 009A2070 OMVS 96.606 RCV JF V 17CFEAB0000C0002 009A3070 .043 STE JY V 17D0360000546910 009DCE88 93.958 LSK JY V |
Подробное описание результата команды 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:
|
1 2 |
3XMTHREADINFO "JIT Compilation Thread" J9VMThread:0x0000000018B98A00, j9thread_t:0x0000000808445CF0, java/lang/Thread:0x000000008004A950, state:CW, prio=10 3XMTHREADINFO1 (native thread ID:0x1783C7D0, native priority:0xB, native policy:UNKNOWN) |
//4 – Группа тредов, с примерно одинаковыми значениями использования CPU, это потоки сборщика мусора (garbage collection (GC) slave threads). В javacore они представлены следующим образом:
|
1 2 3 4 5 6 7 8 9 10 |
3XMTHREADINFO "Gc Slave Thread" J9VMThread:0x0000000018C3B200, j9thread_t:0x00000008085E3BD0, java/lang/Thread:0x000000008004F650, state:CW, prio=5 3XMTHREADINFO1 (native thread ID:0x1785C7F0, native priority:0x5, native policy:UNKNOWN) 3XMTHREADINFO3 No Java callstack associated with this thread 3XMTHREADINFO3 No native callstack available on this platform NULL NULL 3XMTHREADINFO "Gc Slave Thread" J9VMThread:0x0000000018C3A200, j9thread_t:0x00000008085E3730, java/lang/Thread:0x000000008004F428, state:CW, prio=5 3XMTHREADINFO1 (native thread ID:0x17858BB0, native priority:0x5, native policy:UNKNOWN) 3XMTHREADINFO3 No Java callstack associated with this thread 3XMTHREADINFO3 No native callstack available on this platform |
Число тредов сборщика мусора зависит от числа доступных процессоров. Эта зависимость выражается формулой: Число_нитей_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%.
|
1 2 3 4 |
Хозяйке на заметку: Можно определить необходимое число нитей сборщика мусора, используя JVM ключ -XgcthreadsY, где Y - число нитей. Например, -Xgcthreads6 - означает, что для сборки мусора будет использоваться 6 нитей. |
//5 – Это поток завершения, Finalizer thread. В javacore он представлен следующим образом:
|
1 2 |
3XMTHREADINFO "Finalizer thread" J9VMThread:0x00000000191BA700, j9thread_t:0x00000008086FC8D0, java/lang/Thread:0x00000000800055F8, state:CW, prio=5 3XMTHREADINFO1 (native thread ID:0x178E40F0, native priority:0x5, native policy:UNKNOWN) |
Обычно этото тред не использует много CPU, но когда приложения используют очень много finalizer methods, то это приводит к задержке удаления неиспользуемых объектов в процессе сборки мусора, что может привести к увеличению числа циклов сборки мусора и фрагментации кучи JVM, что в свою очередь может являться причиной чрезмерного использования CPU. В таком случае необходимо воспользоваться рекомендациями по уменьшению использования финализатора, “Reduce finalizer usage”, содержащимися в IBM SDK for Java Information Center.
//6 – Группа потоков, напротив которых стоит обозначение “WLM“, это треды ORB пула (ORB thread pool). Это непосредственно рабочие потоки, исполняющие код приложения, а точнее обрабатывающие анклавы.
|
1 2 3 |
Хозяйке на заметку: Анклав - это транзакция, которая может быть распределена между несколькими управляемыми [диспетчерезуемыми] единицами работ (TCB, SRB) в рамках одного или нескольких адресных пространств. Анклаву сопоставляется соответствующий Service Class (SC) и Report Class (RC) WLM. |
В javacore они выглядят следующим образом:
|
1 2 3 4 5 6 7 |
3XMTHREADINFO "WebSphere:ORB.thread.pool t=009b8470" J9VMThread:0x000000001A73A300, j9thread_t:0x00000008088EC9F0, java/lang/Thread:0x00000000895999F0, state:CW, prio=5 3XMTHREADINFO1 (native thread ID:0x17987DD0, native priority:0x5, native policy:UNKNOWN) 3XMTHREADINFO3 Java callstack: 4XESTACKTRACE at com/ibm/ws390/orb/CommonBridge.nativeRunApplicationThread(Native Method) 4XESTACKTRACE at com/ibm/ws390/orb/CommonBridge.runApplicationThread(CommonBridge.java:472) 4XESTACKTRACE at com/ibm/ws/util/ThreadPool$ZOSWorker.run(ThreadPool.java:1846) 3XMTHREADINFO3 No native callstack available on this platform |
Количество рабочих потоков (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 выглядят так:
|
1 2 3 4 5 6 7 8 9 10 |
3XMTHREADINFO "Deferrable Alarm : 0" J9VMThread:0x000000001A852B00, j9thread_t:0x000000080895D360, java/lang/Thread:0x000000008B136B10, state:CW, prio=5 3XMTHREADINFO1 (native thread ID:0x17A25140, native priority:0x5, native policy:UNKNOWN) 3XMTHREADINFO3 Java callstack: 4XESTACKTRACE at java/lang/Object.wait(Native Method) 4XESTACKTRACE at java/lang/Object.wait(Object.java:196(Compiled Code)) 4XESTACKTRACE at com/ibm/ws/util/BoundedBuffer.waitGet_(BoundedBuffer.java:187(Compiled Code)) 4XESTACKTRACE at com/ibm/ws/util/BoundedBuffer.poll(BoundedBuffer.java:609(Compiled Code)) 4XESTACKTRACE at com/ibm/ws/util/ThreadPool.getTask(ThreadPool.java:899(Compiled Code)) 4XESTACKTRACE at com/ibm/ws/util/ThreadPool$Worker.run(ThreadPool.java:1653(Compiled Code)) 3XMTHREADINFO3 No native callstack available on this platform |
Мы рассмотрели основные потоки в серванте сервера приложений. Остальные – это треды мониторинга (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:
|
1 2 3 4 5 6 7 8 9 10 |
F ED1SR03,JAVACORE BPXM023I (EDDMC) 530 JVMDUMP034I User requested Java dump using '/u/ED/EDCFG/javacore.20131 125.151242.67108928.0001.txt' through JVMRI BPXM023I (EDDMS) 532 JVMDUMP034I User requested Java dump using '/u/ED/EDCFG/javacore.20131 125.151252.121.0001.txt' through JVMRI BBOO0211I MODIFY COMMAND JAVACORE COMPLETED SUCCESSFULLY |
После выдачи команды, появляется сообщение, в котором отображено размещение формируемых 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:
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 |
3XMTHREADINFO "WebSphere:ORB.thread.pool t=009c2938" J9VMThread:0x000000001A70A600, j9thread_t:0x00000008088B0E90, java/lang/Thread:0x00000000893F81F0, state:CW, prio=5 3XMTHREADINFO1 (native thread ID:0x17963260, native priority:0x5, native policy:UNKNOWN) 3XMTHREADINFO3 Java callstack: 4XESTACKTRACE at java/net/SocketInputStream.socketRead0(Native Method) 4XESTACKTRACE at java/net/SocketInputStream.read(SocketInputStream.java:140(Compiled Code)) 4XESTACKTRACE at java/io/BufferedInputStream.fill(BufferedInputStream.java:229(Compiled Code)) 4XESTACKTRACE at java/io/BufferedInputStream.read(BufferedInputStream.java:248(Compiled Code)) 4XESTACKTRACE at org/apache/commons/httpclient/HttpParser.readRawLine(HttpParser.java:78(Compiled Code)) 4XESTACKTRACE at org/apache/commons/httpclient/HttpParser.readLine(HttpParser.java:106(Compiled Code)) 4XESTACKTRACE at org/apache/commons/httpclient/HttpConnection.readLine(HttpConnection.java:1116(Compiled Code)) 4XESTACKTRACE at org/apache/commons/httpclient/MultiThreadedHttpConnectionManager$HttpConnectionAdapter.readLine(MultiThreadedHttpConnectionManager.java:1413(Compiled Code)) 4XESTACKTRACE at org/apache/commons/httpclient/HttpMethodBase.readStatusLine(HttpMethodBase.java:1973(Compiled Code)) 4XESTACKTRACE at org/apache/commons/httpclient/HttpMethodBase.readResponse(HttpMethodBase.java:1735(Compiled Code)) 4XESTACKTRACE at org/apache/commons/httpclient/HttpMethodBase.execute(HttpMethodBase.java:1098(Compiled Code)) 4XESTACKTRACE at org/apache/commons/httpclient/HttpMethodDirector.executeWithRetry(HttpMethodDirector.java:398(Compiled Code)) 4XESTACKTRACE at org/apache/commons/httpclient/HttpMethodDirector.executeMethod(HttpMethodDirector.java:171(Compiled Code)) 4XESTACKTRACE at org/apache/commons/httpclient/HttpClient.executeMethod(HttpClient.java:397(Compiled Code)) 4XESTACKTRACE at org/apache/commons/httpclient/HttpClient.executeMethod(HttpClient.java:346(Compiled Code)) 4XESTACKTRACE at org/apache/axis2/transport/http/AbstractHTTPSender.executeMethod(AbstractHTTPSender.java:542(Compiled Code)) 4XESTACKTRACE at org/apache/axis2/transport/http/HTTPSender.sendViaPost(HTTPSender.java:189(Compiled Code)) 4XESTACKTRACE at org/apache/axis2/transport/http/HTTPSender.send(HTTPSender.java:75(Compiled Code)) 4XESTACKTRACE at org/apache/axis2/transport/http/CommonsHTTPTransportSender.writeMessageWithCommons(CommonsHTTPTransportSender.java:371(Compiled Code)) 4XESTACKTRACE at org/apache/axis2/transport/http/CommonsHTTPTransportSender.invoke(CommonsHTTPTransportSender.java:210(Compiled Code)) 4XESTACKTRACE at org/apache/axis2/engine/AxisEngine.send(AxisEngine.java:544(Compiled Code)) 4XESTACKTRACE at org/apache/axis2/description/OutInAxisOperationClient.send(OutInAxisOperation.java:401(Compiled Code)) 4XESTACKTRACE at org/apache/axis2/description/OutInAxisOperationClient.executeImpl(OutInAxisOperation.java:228(Compiled Code)) 4XESTACKTRACE at org/apache/axis2/client/OperationClient.execute(OperationClient.java:163(Compiled Code)) 4XESTACKTRACE at rzd/gvc/etd/was/etd/mmfinalize/MmFinalizeSrcStub.mmFinalize(MmFinalizeSrcStub.java:181(Compiled Code)) 4XESTACKTRACE at ru/transinfocom/asut/services/impl/Impl.mmFinalize(Impl.java:129(Compiled Code)) 4XESTACKTRACE at sun/reflect/GeneratedMethodAccessor358.invoke(Bytecode PC:40(Compiled Code)) 4XESTACKTRACE at sun/reflect/DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:37(Compiled Code)) 4XESTACKTRACE at java/lang/reflect/Method.invoke(Method.java:611(Compiled Code)) 4XESTACKTRACE at com/ibm/ws/webservices/engine/dispatchers/java/JavaDispatcher.invokeMethod(JavaDispatcher.java:178(Compiled Code)) 4XESTACKTRACE at com/ibm/ws/webservices/engine/dispatchers/java/JavaDispatcher.invokeOperation(JavaDispatcher.java:141(Compiled Code)) 4XESTACKTRACE at com/ibm/ws/webservices/engine/dispatchers/SoapRPCProcessor.processRequestResponse(SoapRPCProcessor.java:490(Compiled Code)) 4XESTACKTRACE at com/ibm/ws/webservices/engine/dispatchers/SoapRPCProcessor.processMessage(SoapRPCProcessor.java:433(Compiled Code)) 4XESTACKTRACE at com/ibm/ws/webservices/engine/dispatchers/BasicDispatcher.processMessage(BasicDispatcher.java:134(Compiled Code)) 4XESTACKTRACE at com/ibm/ws/webservices/engine/dispatchers/java/SessionDispatcher.invoke(SessionDispatcher.java:204(Compiled Code)) 4XESTACKTRACE at com/ibm/ws/webservices/engine/PivotHandlerWrapper.invoke(PivotHandlerWrapper.java:263(Compiled Code)) 4XESTACKTRACE at com/ibm/ws/webservices/engine/handlers/jaxrpc/JAXRPCHandler.invoke(JAXRPCHandler.java:153(Compiled Code)) 4XESTACKTRACE at com/ibm/ws/webservices/engine/handlers/WrappedHandler.invoke(WrappedHandler.java:64(Compiled Code)) 4XESTACKTRACE at com/ibm/ws/webservices/engine/PivotHandlerWrapper.invoke(PivotHandlerWrapper.java:263(Compiled Code)) 4XESTACKTRACE at com/ibm/ws/webservices/engine/PivotHandlerWrapper.invoke(PivotHandlerWrapper.java:263(Compiled Code)) 4XESTACKTRACE at com/ibm/ws/webservices/engine/WebServicesEngine.invoke(WebServicesEngine.java:336(Compiled Code)) 4XESTACKTRACE at com/ibm/ws/webservices/engine/transport/http/WebServicesServlet.doPost(WebServicesServlet.java:1131(Compiled Code)) 4XESTACKTRACE at javax/servlet/http/HttpServlet.service(HttpServlet.java:738(Compiled Code)) 4XESTACKTRACE at com/ibm/ws/webservices/engine/transport/http/WebServicesServletBase.service(WebServicesServletBase.java:344(Compiled Code)) 4XESTACKTRACE at javax/servlet/http/HttpServlet.service(HttpServlet.java:831(Compiled Code)) 4XESTACKTRACE at com/ibm/ws/webcontainer/servlet/ServletWrapper.service(ServletWrapper.java:1657(Compiled Code)) 4XESTACKTRACE at com/ibm/ws/webcontainer/servlet/ServletWrapper.service(ServletWrapper.java:1597(Compiled Code)) 4XESTACKTRACE at com/ibm/ws/webcontainer/filter/WebAppFilterChain.doFilter(WebAppFilterChain.java:131(Compiled Code)) 4XESTACKTRACE at ru/transinfocom/asut/services/impl/logfilter/LogFilter.doFilter(LogFilter.java:44(Compiled Code)) 4XESTACKTRACE at com/ibm/ws/webcontainer/filter/FilterInstanceWrapper.doFilter(FilterInstanceWrapper.java:188(Compiled Code)) 4XESTACKTRACE at com/ibm/ws/webcontainer/filter/WebAppFilterChain.doFilter(WebAppFilterChain.java:116(Compiled Code)) 4XESTACKTRACE at com/ibm/ws/webcontainer/filter/WebAppFilterChain._doFilter(WebAppFilterChain.java:77(Compiled Code)) 4XESTACKTRACE at com/ibm/ws/webcontainer/filter/WebAppFilterManager.doFilter(WebAppFilterManager.java:908(Compiled Code)) 4XESTACKTRACE at com/ibm/ws/webcontainer/servlet/ServletWrapper.handleRequest(ServletWrapper.java:934(Compiled Code)) 4XESTACKTRACE at com/ibm/ws/webcontainer/servlet/ServletWrapper.handleRequest(ServletWrapper.java:502(Compiled Code)) 4XESTACKTRACE at com/ibm/ws/webcontainer/servlet/ServletWrapperImpl.handleRequest(ServletWrapperImpl.java:181(Compiled Code)) 4XESTACKTRACE at com/ibm/ws/webcontainer/servlet/CacheServletWrapper.handleRequest(CacheServletWrapper.java:91(Compiled Code)) 4XESTACKTRACE at com/ibm/ws/webcontainer/WebContainer.handleRequest(WebContainer.java:864(Compiled Code)) 4XESTACKTRACE at com/ibm/ws/webcontainer/WSWebContainer.handleRequest(WSWebContainer.java:1592(Compiled Code)) 4XESTACKTRACE at com/ibm/ws/webcontainer/channel/WCChannelLink.ready(WCChannelLink.java:186(Compiled Code)) 4XESTACKTRACE at com/ibm/ws/http/channel/inbound/impl/HttpInboundLink.handleDiscrimination(HttpInboundLink.java:452(Compiled Code)) 4XESTACKTRACE at com/ibm/ws/http/channel/inbound/impl/HttpInboundLink.handleNewRequest(HttpInboundLink.java:511(Compiled Code)) 4XESTACKTRACE at com/ibm/ws/http/channel/inbound/impl/HttpInboundLink.processRequest(HttpInboundLink.java:305(Compiled Code)) 4XESTACKTRACE at com/ibm/ws/http/channel/inbound/impl/HttpInboundLink.ready(HttpInboundLink.java:276(Compiled Code)) 4XESTACKTRACE at com/ibm/ws390/channel/xmem/XMemConnLink.ready(XMemConnLink.java:858(Compiled Code)) 4XESTACKTRACE at com/ibm/ws390/channel/xmem/XMemInboundChannel.handleRequest(XMemInboundChannel.java:340(Compiled Code)) 4XESTACKTRACE at com/ibm/ws390/xmem/XMemSRBridgeImpl.httpinvoke(XMemSRBridgeImpl.java:104(Compiled Code)) 4XESTACKTRACE at com/ibm/ws390/xmem/XMemSRCppUtilities.httpinvoke(XMemSRCppUtilities.java:74(Compiled Code)) 4XESTACKTRACE at com/ibm/ws390/orb/ServerRegionBridge.httpinvoke(ServerRegionBridge.java:215(Compiled Code)) 4XESTACKTRACE at com/ibm/ws390/orb/ORBEJSBridge.httpinvoke(ORBEJSBridge.java:281(Compiled Code)) 4XESTACKTRACE at sun/reflect/GeneratedMethodAccessor114.invoke(Bytecode PC:24(Compiled Code)) 4XESTACKTRACE at sun/reflect/DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:37(Compiled Code)) 4XESTACKTRACE at java/lang/reflect/Method.invoke(Method.java:611(Compiled Code)) 4XESTACKTRACE at com/ibm/ws390/orb/parameters/HTTPInvoke.HTTPInvokeParmSetter(HTTPInvoke.java:101(Compiled Code)) 4XESTACKTRACE at com/ibm/ws390/orb/CommonBridge.nativeRunApplicationThread(Native Method) 4XESTACKTRACE at com/ibm/ws390/orb/CommonBridge.runApplicationThread(CommonBridge.java:472) 4XESTACKTRACE at com/ibm/ws/util/ThreadPool$ZOSWorker.run(ThreadPool.java:1846) 3XMTHREADINFO3 No native callstack available on this platform |
Как видно из фрагмента javacore, первые 8 байт THREAD_ID соответствуют значению “native thread ID” в javacore. Из stack trace мы узнаем, что выбранный поток исполняет код приложения, которое делает вызов другого приложения с помощью web сервиса, и передает ему данные.
Заключение
В заключении резюмируем все описанное выше, т.е. составим подробную последовательность действий для выявления “сбойного” треда:
- В режиме реального времени мы видим, что сервант сервера приложений чрезмерно использует CPU.
- Выполняем команду D OMVS,PID=XXXXXX , где XXXXXX – process id (PID) интересующего нас серванта. (Строчная команда ‘d’).
- Выполняем команду F ,JAVACORE , где – имя сервера (Control Region).
- Переходим в журнал пользователя (user log), для этого в строке ввода команд введите ‘ULOG‘.
- Ищем поток (потоки) которые больше остальных используют CPU (смотрим по столбцу ACC_TIME).
- У выбранных потоков копируем первые 8 байт THREAD_ID.
- В полученном javacore серванта ищем выбранные потоки по первым 8 байтам THREAD_ID.
- У найденных тредов смотрим stack trace, показывающий исполняемый ими код.
- Анализируем полученный код. Какие классы исполняются? Проблема в сервере или в приложении?
- В зависимости от результатов анализа, связываемся с разработчиками для изменения кода приложения или оптимизируем параметры системы.
P.S.: статья основана на
WP101474 Threads And Excessive CPU Consumption In WAS ZOS (162.3 KB)
Leave a Reply