2011. augusztus 19., péntek

CPU usage monitoring by processes

Kaptam egy érdekes feladatot mostanság: Kéne valahogy monitorozni a gépen futó alkalmazások által használt CPU időt, de mindezt úgy, hogy az adatokat később diagram-ban ábrázolni lehessen processekre lebontva.
Első gondolatom az nmon volt, de sajna az nem képes a processenkénti lebontásra ahogy néztem.. topasrec detto nem.
Aztán próbáltam a ps listából kiszedni az adatokat ('ps -o ruser,pid,ppid,pcpu,args') de ott is bajba ütköztem, mivel sokszor a ps által reportolt eredmény durván eltért a topas/nmon által visszaadottól.
Aztán jó kis kutatás után kikötöttem a tprof-nál.. Ennek azonban alapvetően 1 nagy baja van: eredetileg csak arra készítették fel, hogy egy alatta futó alkalmazást monitorozzon és annak minden kis forkolását és mozgását kövesse, majd a végén reportot generáljon belőle. Viszont mint kiderült a tprof tud offline módban is dolgozni, bár elég hülye megkötésekkel.
A módszer kb így néz ki:
- Generáljunk a trace parancsal egy tracefile-t
- Hagyjuk kicsit futni a trace-t, majd állítsuk le (nálam ez 30 sec volt)
- Ez után a gensyms-el generáljuk le az address mappingot
- Majd futtassuk a kinyert adatokra a tprof-ot offline módban

Ez nálam a script-ben így nézett ki:

#!/usr/bin/ksh
mkdir /tmp/cpucheck 2>/dev/null
cd /tmp/cpucheck
DATE=$(date +"%Y.%m.%d. %H:%M:%S")
echo $DATE >> cpu_check_output_total
echo $DATE >> cpu_check_output
trace -af -T 1000000 -L 10000000 -o trace1.trc -j 000,001,002,003,005,006,234,106,10C,134,139,00A,465
sleep 30
trcoff
gensyms > trace1.syms
trcstop
tprof -skjue -R -P all -r trace1
grep -p Freq trace1.prof >> cpu_check_output_total
grep -p TID trace1.prof >> cpu_check_output
rm trace1*

Nem mondom, hogy szép megoldás, viszont a célnak bőven megtette. Annyi extrát adtam hozzá, hogy mivel a trace1.[trc|sysms] file-ok sok helyet igényeltek, így azokat a ciklus végén töröltem, miután kinyertem belőlük a számomra szükséges adatokat.
A scriptet crontabba belerakva és 10 percenként futtatva már egy egész szép kis kimutatást lehetett kapni arról, hogy mikor mi is folyik a rendszeren.
Valami ilyesfélét:

2011.08.14. 02:20:00
Process                          Freq  Total Kernel   User Shared  Other   Java
=======                          ====  ===== ======   ==== ======  =====   ====
dsapi_slave                         4  50.69  10.17  27.66  12.86   0.00   0.00
kuxagent                            2  22.34   0.06   0.00  22.28   0.00   0.00
/usr/bin/sh                       150   7.72   6.28   0.70   0.75   0.00   0.00
/usr/bin/echo                     129   5.24   5.16   0.00   0.08   0.00   0.00
/usr/bin/awk                      116   5.04   4.45   0.46   0.13   0.00   0.00
/usr/bin/sed                      106   4.37   4.25   0.00   0.13   0.00   0.00
wait                                4   2.39   2.39   0.00   0.00   0.00   0.00
dscs                                2   1.01   0.84   0.00   0.17   0.00   0.00
/usr/sbin/syncd                     1   0.35   0.35   0.00   0.00   0.00   0.00
l/DataStage/DSEngine/bin/dsjob      2   0.35   0.19   0.00   0.16   0.00   0.00
/db2gpsp1/sqllib/bin/db2usrinf      3   0.13   0.13   0.00   0.00   0.00   0.00
/bin/sh                             3   0.12   0.12   0.00   0.00   0.00   0.00
xmgc                                1   0.09   0.09   0.00   0.00   0.00   0.00
kulagent                            2   0.07   0.00   0.00   0.07   0.00   0.00
/usr/bin/vmstat                     1   0.03   0.03   0.00   0.00   0.00   0.00
/usr/bin/ksh                        1   0.03   0.03   0.00   0.00   0.00   0.00
/usr/bin/lparstat                   1   0.02   0.02   0.00   0.00   0.00   0.00
=======                          ====  ===== ======   ==== ======  =====   ====
Total                             528 100.00  34.57  28.83  36.61   0.00   0.00

Amit erről az ábráról le lehetett olvasni:
- A gépet a különböző scriptek elég durván meghajtják (jelen esetben a gépnek van 0.3 EC-je :))
- A legtöbb CPU időt a dsapi_slave nevű bináris viszi (mellesleg ez hívogatja a scripteket is)
- Szépen processekre lehet nézni, hogy a 30 sec-es mérésen belül mi és mennyiszer hívódott meg, az CPU kihasználtság viszont összesítve (Kernel, User,Shared-re lebontva) látható, ami nekem most nagyon is kapóra jött

Egy dologra viszont mindenképp felhívnám a figyelmet: Ez a report nem azt mutatja, hogy a gép 100%-ban ki volt hajtva, ahogy a Total mutatja! Csupán annyit mutat, hogy a felhasznált CPU mennyiség (!) mekkora része mely processek által lett kihasználva! Ergo ha valaki szeretne ez alapján egy átfogó képet készíteni, annak szüksége lesz egy külön log-ra, amely a global CPU usage-et nézi! Erre viszont már könnyű szerrel használhatóak a normal toolok (nmon/topasrec/sar). Ezt a kis "apróságot" leszámítva viszont szerintem nagyon is jól használható ez a kis módszer az esetleges bottleneck-ek kiderítésére (jelen esetben, hogy a gépen futó applikáció iszonyat sokat forkol (szerintem feleslegesen)

2 megjegyzés: