A következő címkéjű bejegyzések mutatása: trace. Összes bejegyzés megjelenítése
A következő címkéjű bejegyzések mutatása: trace. Összes bejegyzés megjelenítése

2014. június 10., kedd

Amikor RAMBO kifogy a RAMbó..

Egy újabb nap, egy újabb kihívás.. Legalább is ezt mondják a hangok odafent. Gyakorlatilag az irodába beérkezve az alábbi "köszöntő" fogad: "A szerver nem elérhető, csinálj valamit!". Jaj de jó, ismét valami ami elé hulla fáradtan le lehet ülni, hogy aztán még jobban lefárasszam magam. Na mindegy, nézzük miből élünk..

Ránézek a szerverre: pingelni lehet, barmiféle kapcsolatot nyitni viszont nem.
HMC-ről nyitott virtual konzolról megvizsgálva a kérdést se jobb a helyzet, csupán a temérdek "unable to fork" hibaüzenet igazolja az eddigi teóriát, hogy bizony itt elfogyott a gép alól a fizikai memória, és még csak azért van életben, mert a paging space-ből még maradt valami ahova ki lehet lapozni azt a kevés memória területet amit a rendszer képes volt felszabadítani.

Mit lehet ilyenkor tenni? A lehetőségeink lényegében az alábbi 3 opcióra korlátozódnak:
- Imádkozunk, hogy a terhelés egy idő után megszűnik, és felszabadul annyi memória, hogy a szervert ismét életképes állapotba lehessen hozni
- Várni hogy az OOM killer végre működésbe lépjen, vagy hogy a rendszer összeessen magától
- Manuálisan újraindítani az egész mindenséget és behúzni +1 strigulát a service outage rubrika mellé

A kérdés már csak az, hogy a 3 opció közül melyik az, amelyik számunkra ÉS a customer számára is elfogadható. Jó, beszélgessünk el a customerrel, hogy akkor mi és hogyan, illetve próbáljunk meg rájönni, hogy melyik opciót is érdemes választani. Valami ilyesmit képzeljetek el:
- A szerviz számára fontos a szerver?
- Naná hogy az, production szerver, 7x24ben elérhetőnek kéne lennie
- A fontosabb szolgáltatás(ok) elérhető(ek)?
- Hááát ami azt illeti igen, csak épp lassú mint a fene.
/* tehát nincs szerviz kiesés, ami azt jelenti, hogy a fontosabb programok még a memóriában elvannak valahogy és onnan még tudnak úgy-ahogy működni is*/
A fontosabb dolgok hála az égnek mennek, de például az utóbbi 4 beütemezett job failed-re futott /* naná, valószínű el se tudott indulni */
- A nem elérhető részek mennyire business kritikusak?
- Hát.. Kis kiesés még belefér, de hosszútávon már komoly problémákat okoz ha a jobok nem futnak le.
- Tudnak e olyan jobról ami ebbe az idő-ablakba lett ütemezve, és esetleg erősen erőforrás igényes lehet?
- Nem, azok a hétvégére vannak csak beütemezve
- Jó. Tehát a szerviz még elérhető, bár funkcionálisan korlatozott. Mivel jelenleg nem tudunk a rendszerről barmit lekérni, így sajna megbecsülni se tudjuk hogy ez a hibajelenség tartós avagy ideiglenes e. A rendszer teljes újraindításával biztosan vissza tudjuk állítani a rendet, viszont az a szolgáltatás ideiglenes, ám teljes kiesésével is jár. Kérdés hogy ez a szerviz szempontjából elfogadható e, vagy inkább várjunk még egy kis időt, hogy hátha magától megszűnik a magas memória terhelés?
- Hát.. A szolgáltatás szempontjából a helyzet nem kritikus, viszont így nem is lehet a rendszert adminisztrálni. A következő fontos job kb 2 óra múlva indulna. Ha az se tud lefutni, az már komoly pénzbeli veszteség lenne a cégnek. Kb mennyi időt vesz igénybe a teljes rendszer újraindítása?
- Az újraindítás viszonylag gyorsan megvan, a visszaellenőrzések viszont eltartanak egy minimum 20 percig. Számoljunk 30 percet mindenre biztos ami biztos.
- Rendben. Akkor még kb 1 órát tudunk várni, és akkor még lesz 30 percünk az esetleges hibaelhárításra. Ha addig se jön helyre a szerver, akkor indítsák újra.

Ok.. Kapott a szerver 1 óra haladékot, hogy bebizonyítsa milyen fából is faragták. Közben azért érdemes elgondolkodni, hogy mi is mehet épp végbe az AIX mélyebb bugyraiban (kernel szinten):
- A rendszer már kidobált minden nem szükséges adatot a fizikai memóriából (temporary cache már tuti nincs, ami még kell és kilapozható az meg már biztosan a paging space-en található)
- Ettől függetlenül a fizikai memóriában nincs szabad hely, ergo új process-t se lehet nyitni/forkolni. /* épp ezért nem is lehet belépni a gépre, mivel ott is minimum egy új shell-t kéne forkolnia a rendszernek */
- Azok a processek amik már a memóriában vannak még képesek funkcionálni /* ezért is képes a szolgáltatás még úgy ahogy életben maradni */
- A rendszer folyamatosan törekszik kiszolgálni a bejövő memória igényeket, illetve fizikai memóriát felszabadítani további page-ek kilapozásával.
- Amennyiben az egységnyi idő alatt bejövő memória kérések száma magasabb mint amit a rendszer adott idő alatt fel tud szabadítani, akkor lényegében egy meglehetősen kellemetlen hógolyó effektus következik be, mivel a futó program által kért memória terület biztosan valami adat számára lett kikérve, - amit a rendszer viszont ilyen esetekben hajlamos gyorsan ki is lapozni - ami viszont csak tovább rontja a helyzetet, mivel a diszken lévő paging sebessége kb egy kerékbilincses csigáéhoz hasonlítható a fizikai memóriához képest => ilyen helyzetben a nagy paging space csak a haláltusát hosszabbítja meg, de ténylegesen nem segít semmit /* főleg ha a process még később vissza is akar olvasni valamit amit a rendszer ma előzőleg kilapozott */
- Ez az állapot addig fennáll amíg az elérhető virtuális (!) memória le nem csökken egy bizonyos szintig: Amikor az elérhető virtualis memory page-ek száma eléri az VMO npswarn értékét (4k-ban tessek számolni), akkor a rendszer kiküld mindenkinek egy SIGDANGER signalt, hogy lehetőséget adjon a processeknek konzisztensen leállni (már ha fel vannak készítve arra hogy az ilyen signal-al kezdjenek valamit). Amennyiben a memória kihasználtság ez után eléri a VMO npskill értékét (vagy mert a programok ignorálták a signalt, vagy mert nem bírtak időben leállni), akkor a kernel szisztematikusan elkezdi legyilkolászni a legfiatalabb processeket amikre "engedélyé van": Ez kb annyit jelent, hogy a process owner UID-ja nincs felsorolva a VMO nokilluid listáján /* alapból pl a 0as UID van ott, ami annyit jelent, hogy a root neve alatt futó processeket a rendszer nem fogja legyilkolni */
- Amennyiben a rendszer nem képes ezzel a módszerrel se memóriát felszabadítani akkor a paging space teljes felhasználása után egy garantált system crash következik, amit aztán egy automatikus restart követ.

A fenti példából azért látszik, hogy van olyan forgatókönyv is, amikor a szerviz számára fontos programot a rendszer nemes egyszerűséggel legyilkolja (már ha a hozza köthető UID nincs rajta a nokilluid listán), ami kb csak 1 fokkal jobb csak a teljes újraindításnál :)
#Megjegyzés - ez azt is jelenti, hogy a fenti VMO paraméterek finomhangolásával amúgy simán életben is lehet tartani egy gépet restart nélkül, csak akkor készüljünk fel arra, hogy időnként 1-2 programot lehet újra kell majd indítgatni.

Eltelt 1 óra.. Sajnos a rendszer nem volt képes visszarángatni magát a valóságba, így az ügyfél kérésére azt újra kellett indítani. Na jó.. de hogyan? Ne tessek félre érteni, nem az a kérdés, hogy milyen paranccsal, vagy min keresztül (HMC azért jó ha van :)). A kérdés inkább arra irányul, hogy azonnal újra kell e indítani mindent, vagy esetleg adunk a rendszernek még 1-2 percet hogy ha már eddig eljutott akkor dobjon már egy system dumpot is, amiből esetleg később még tudunk vizsgálódni. Ismerve a managementet, az utóbbi garantáltan megfontolandó (még akkor is ha nem azonnal indul újra az LPAR), tekintve, hogy biztosan el fog hangzani az a kérdés, hogy "Jó, de mi tömte tele a memóriát?"

# Jó tanács: Mielőtt a Windows-on nevelkedett adminok nekiállnának azonnal újraindítani 1-1 gépet, inkább tanulják meg az alábbi parancsot használni HMC-ről:
chsysstate -m $MACHINE -r lpar -o dumprestart -n $PARTITION

Kb 5-10 percbe telt mire a gép mindent kidumpolt a memóriából, majd elkezdte szépen újraindítani a rendszert, amit gyors program indítgatások és visszaellenőrzések követtek, így a szerviz ismét teljesen elérhető lett és a customer számára kritikus job is le tudott futni minden gond nélkül.. Éljen.. An other success story, good job, well done, champaign.. Na jó, nem egészen..
További kb 1-1,5 órán át még ment a beszélgetés illetve az összefoglalók írása, miután elhangzott customer oldalról az a kérdés amire előzőleg egy meglehetősen nagy fogadást mertem volna kötni: "Ki tudjuk deríteni, hogy mi okozta ezt? Vagy van valami módszer arra, hogy ezt megelőzzük?"
Látjátok, mondtam én :)

Mázlira a dump device-al, és annak beállításaival semmi gond nem volt (dump compression bekapcsolva, dump device mérete megfelelő) és volt is elég hely ahhoz, hogy a dumpot kimásolva egy fájlrendszerre, majd kitömörítve el lehessen kezdeni analizálni, hogy végül is mi a franc volt a géppel.
Persze ahhoz hogy ezt megválaszoljuk azért nem árt tudni, hogy mi is helyezkedik el a memóriában. A teljesség igénye nélkül itt egy kis összefoglaló:
- A kernel számára lefoglalt memória terület (erre szoktak még System occupied memory néven is hivatkozni, ami magában foglalja magát a kernelt (és annak moduljait), a kernel heap-et, a shared memory szegmenseket, memory buffert, kernel cache-t, és a shared library-knak fenntartott memória területet)
- Fájlrendszer cache /* AIX esetében ez JFS, JFS2, NFS cache-t jelent */
- Különböző HW-ek számára fenntartott caching area
- Processek indító binárisainak (futó process binárisa kötelezően a fizikai memóriában helyezkedik el) és esetleges privát library-knek fenntartott memória terület
- A processek számára fenntartott privát memória területek (minden processnek saját memória terület, saját virtuális memória címzéssel)

Kezdjük is azzal ami a legtöbb problémát szokta okozni: Azok a fránya programok. Csak hogy szemléltessem hogy mennyire (nem)vicces tud egy ilyen nyomozás lenni, már itt leszegezem hogy ennek vizsgálatára nyomban 3 különböző módszer van, amik mind mást-mást néznek (ergo más-más eredményt is produkálnak) ... csak hogy az ember élete egyszerű legyen ...
- a kdb-nek van beépített svmon parancsa, ami meglehetősen jól visszaadja az aktuális állapotot, viszont bizonyos helyzetekben hajlamos nem működni. Naná hogy ez is pont egy olyan helyzet:
(0)> svmon * Pid Command Inuse Pin Pgsp Virtual 64-bit Mthrd LPage [kdb_read_mem] no real storage @ F10013AE4747FF70

- Minden process-től ki lehet kérni az éppen lefoglalt fizikai és paging lapokat (nvpages és npsblks értékek) a proc alparancs segítségével, viszont összehasonlítva egy (működő) svmon kimenetével egyértelműen látható, hogy ez nem a ténylegesen lefoglalt összes virtuális memóriát adja vissza, hanem annak csak egy részét (az svmon kimenetéből csupán a working storage és shared library data összegét vagyunk képesek így megállapítani; a heapet, illetve a kernel segment-eket nem). További kellemetlenség, hogy ezt minden egyes processre meg kell vizsgálni, ami vagy egy script formájában történhet meg, vagy sok, türelmesen beírogatott proc es grep parancsok kombinációjával /* a script lassú, kézzel meg még lassabb - marad a script */
# for i in $(echo 'proc *' |kdb dump_file_copy|awk '{print $1}') > do > echo "proc $i" |kdb dump_file_copy |awk '/ nvpages/ || /^pvproc/ {print $3}' | \ > awk 'NR == 1 { printf("%s", $0); } NR != 1 { printf(" %s", $0); } END { printf("\n") }' > done |sort -r -k2 |sed "s/://g" |head -10 java 000000000001F7FC -> ~ 503.9 MB java 000000000001545D -> ~ 340.3 MB java 0000000000007A43 -> ~ 122.2 MB java 00000000000065F0 -> ~ 101.9 MB kuxagent 00000000000024A1 -> ~ 36.6 MB java 0000000000001951 -> ~ 25.3 MB k07agent 000000000000140F -> ~ 20 MB cimserve 0000000000001088 -> ~ 16.5 MB kulagent 0000000000000C37 -> ~ 12.2 MB aixdp_da 0000000000000C02 -> ~ 12 MB
# Megjegyzés - már itt látható, hogy még így is lesznek később problémáink a processek pontos behatárolásával, tekintve, hogy a "java" process rohadtul nem mondja meg, hogy a JVM-en belül mi futott. Erre később még visszatérünk.

- az scb alparancs segítségével is ki lehet kérni az nvpage-eket (process azonosítóra szűrve), itt viszont már a rendszerhez rendelt page-ek is listázva lesznek, ergo szerintem ez a leghasználhatóbb módszer (már ha az svmon valamiért nem működne), plusz az előzőhöz képest jóval gyorsabb is az alap vizsgalat (mivel a page-eket egy körben le tudjuk kérni), viszont itt az is bejön, hogy 1 process több page-et is használhat (már ha többszálusított programról beszélünk), így ezt a vizsgálat során külön figyelembe kell venni. Ezen felül a szűrt processekre (mondjuk top10) így is kell egy extra fork a proc alparanccsal, szóval hiába gyorsabb, attól még azért eléggé macerás így is:
# PVPROC_=""; VPGS_="0" # echo "scb -c 6 0" |kdb dump_file_copy |grep -v 0000000000000000 |grep -w W |awk '{print $10,$7}' |sort | \ > awk '{gsub ("MB","")}{if ($2 ~ "GB") {sub ("GB","");print $1,$2*1024,$3} else {print}}' | while read PVPROC VPGS > do > if [ "${PVPROC}" == "${PVPROC_}" ] > then > VPGS="$(echo ${VPGS_}+${VPGS} |bc)" > else > echo "${PVPROC_} ${VPGS_} ${PGSP_}" > fi > PVPROC_="${PVPROC}" > VPGS_="${VPGS}" > done| sort -rn -k2 |head -10|while read PROC VPGS PGSP > do > printf "%-15s %-15s %-15s\n" \ > $(echo "proc $PROC"|kdb dump_file_copy |awk '/^pvproc/ {printf ("%d %s", "0x"$5, $3)}') "${VPGS} MB" > done 15597570 java 571.6 MB 7274716 java 374.1 MB 4653250 java 271.1 MB 14745724 java 102.9 MB 0 swapper 83.7 MB 3866808 rmcd 61.6 MB 6094860 java 50.3 MB 10354744 kuxagent 38.0 MB 8192024 cimserve 31.5 MB 6946818 k07agent 22.5 MB

Szupi.. akkor most már van valami hozzávetőleges fogalmunk is arról, hogy mi mennyit zabált. nézzük mennyi memória is alt rendelkezésre:
(0)> vmstat |grep "total lru frames" total lru frames (4K units) : 00000000000E53E0 3.6GB
Őőőőőő.. Állj.. A számok valahogy nem stimmelnek: Ha megnézzük, akkor az top10 process is csak kb 1.6 GB-ot volt képes lefoglalni, ami közel sincs a teljes 3.6 GB-hoz (HW cache nélkül). Ami azt jelenti, hogy valamit vagy nagyon sikerült benézni, vagy máshol van Lessie elásva. 1 lépés előre, 3 lépés vissza, kezdjük elölről, de most inkább kezdjük a vizsgálódást magasabb szintről és csak utána menjünk alacsonyabb szintekre:

Fizikai memória (poolonként lebontva - mázlira itt csak 1 pool volt)
(0)> memp * VMP MEMP NB_PAGES FRAMESETS NUMFRB F1000F0009540000 00 000 000E7440 000 001 002 003 000008D4 ^^^^^^^^ ^^^^^^^^ 3700.25 MB 8.8 MB
3700 MB (3.6 GB) fizikai memória összesen, ebből 8,8 MB szabad a dump pillanatában. Eddig stimmt. Nézzük a paginget
(0)> vmker |grep pgsp |egrep "^total|^free" total pgsp blks (numpsblks) : 001A8000 -> 6784 MB free pgsp blks (psfreeblks) : 0010DDE4 -> 4317.8 MB
6.625 GB paging, ebből közel 4.2 GB szabad. Eddig is klappol a történet.
(0)> vmstat |egrep "total perm frames|wlm_hw_pages|vm_nonsys|total perm frames|vm_syspgs" # 'system' pages (vm_syspgs) : 00000000000E2844 3.5GB # non-'system' pages (vm_nonsys) : 00000000000041F8 66.0MB total perm frames (4K units) : 0000000000000187 1.5MB Total unmanaged mem (wlm_hw_pages): 00018BC0 395.8MB
Na jó, itt kicsit sok dolog van, beismerem. Nézzük őket szépen sorjában
- 'system' pages / vm_syspgs - Emlékeztek még a fent említett "kernel-számára fenntartott memória terület"-re? Na ez az :)
- non-'system' pages / vm_nonsys - Fizikai memórián belül azon processekhez tartozó lapok mennyisége amik nem lettek kilapozva a paging space-re
- total perm frames - fájlrendszer cache (JFS, JFS2, NFS)
- Total unmanaged mem / wlm_hw_pages - A szinten fent emlegetett HW cache area.

Na itt már látszik, hogy nem mi vagyunk a hülyék, hanem a rendszer tényleg nagyon élszált, tekintve hogy a fizikai memóriában szinte csak system lapok voltak, a többi meg vagy HW cache, vagy applikáció, egy nagyon kevés FS cache, illetve 1 kis rész ami ezen a query-n nem látszik. Továbbá az is simán látszik, hogy a fenti svmon/proc/scb mérésünk semmit nem ér, ha nem látjuk, hogy mennyi memória terület is lett kilapozva abból amit az applikáció tényleg lefoglalt. Az viszont tuti, hogy a kernelnek nem kéne ennyit lefoglalnia, szóval nézzünk már rá, hogy mi a franc is zabált annyit:
(0)> scb -c 6 100 |grep 0000000000000000 |sort -rn -k4 |head -15 00A14A W 64K 256.0MB 256.0MB 0.0MB 256.0MB 0.0MB 0000 0000000000000000 KHEAP SYS 00A148 W 64K 256.0MB 256.0MB 0.0MB 256.0MB 0.0MB 0000 0000000000000000 KHEAP SYS 00A147 W 64K 256.0MB 256.0MB 0.0MB 256.0MB 0.0MB 0000 0000000000000000 KHEAP SYS 00A146 W 64K 256.0MB 256.0MB 0.0MB 256.0MB 0.0MB 0000 0000000000000000 KHEAP SYS 00A145 W 64K 256.0MB 256.0MB 0.0MB 256.0MB 0.0MB 0000 0000000000000000 KHEAP SYS 00A144 W 64K 256.0MB 256.0MB 0.0MB 256.0MB 0.0MB 0000 0000000000000000 KHEAP SYS 00A143 W 64K 256.0MB 256.0MB 0.0MB 256.0MB 0.0MB 0000 0000000000000000 KHEAP SYS 00A142 W 64K 256.0MB 256.0MB 0.0MB 256.0MB 0.0MB 0000 0000000000000000 KHEAP SYS 00A149 W 64K 255.8MB 255.7MB 0.0MB 255.8MB 0.0MB 0000 0000000000000000 KHEAP SYS 00A023 W 64K 206.7MB 203.4MB 0.0MB 206.8MB 0.1MB 0000 0000000000000000 KHEAP SYS 00A00E W 64K 187.8MB 53.8MB 0.0MB 188.0MB 0.2MB 0000 0000000000000000 KHEAP SYS 00A14B W 64K 154.1MB 153.9MB 0.0MB 154.1MB 0.0MB 0000 0000000000000000 KHEAP SYS 00E000 W 64K 130.0MB 130.0MB 0.0MB 130.0MB 0.0MB 0000 0000000000000000 MBUF SYS 00A111 W 64K 122.8MB 0.8MB 0.0MB 122.9MB 0.1MB 0000 0000000000000000 KHEAP SYS 00A01C W 64K 87.3MB 86.9MB 0.0MB 87.3MB 0.1MB 0000 0000000000000000 KHEAP SYS
Hat én itt 2 dolgot latok: Rohadt sok Kernel heap-et, meg egy kevéske memory buffert.. Ami azt jelenti, hogy az elején valóban nem benézés esete forgott fent, hanem a rendszer tényleg "Mind megette" játékot játszott, ami viszont némi kis keresgélés után nyomban ki is derül miért:
IV53587: XMGC NOT TRAVERSING ALL KERNEL HEAPS. APPLIES TO AIX 7100-03 14/04/17 PTF PECHANGE

És igen... Persze hogy a rendszer pont ezen az szinten fut:
# oslevel -s 7100-03-01-1341
Customer értesít, állapot elmagyaráz (csak amolyan konyhanyelven, mert az halál biztos, hogy nem akarok 2 órán keresztül arról magyarázkodni -egy jó esetben félig technikus emberkének - hogy az AIX hogyan is manageli a memóriát a motorháztető alatt), következő maintenance window lefoglal, change előkészít, rendszer frissítés a hétvégére beütemez, hátradől, virtuális vállveregetés, a rendszergazda megpihen.
Megpihenne.. Legalább is ha nem baxná az ideg, hogy mi a jó büdös francért kellett kb 2-3 órán át a kernel dumpot túrnia és a fejét vakarnia amikor különböző okoknál fogva valami vagy nem működött, vagy nem azt az eredményt adta amit az ember várna tőle. Mit csinál ilyenkor a (jó)rendszer gazda? Füles be, elkezd valami kódolós zenét hallgatni majd elkezdi az egész francos memória checket lescriptelni, hogy legközelebb már 5 perc alatt meglegyen az, amivel most órákat szívott.
És mivel jófej rendszergazda tudja milyen xar amikor mások is ilyenekkel szívnak, így inkább úgy dönt, hogy szabadon elérhetővé teszi az egészet, szóval ha ne adj isten más is hasonló aljasságokra adná a fejet, az használja szeretettel az alábbi kis scriptecskét arra hogy valami támpontot kapjon a rendszer állapotáról egy sikeres dump után:
https://drive.google.com/file/d/0BzMqRqSWTAToNjdCbUNXd1ZGeVU

A gyengébbek kedvéért azért azt kiemelném hogy az ilyen jellegű outputot is a helyén kell kezelni, ergo akinek nincs tapasztalata ilyen jellegű debugolásokban, annak inkább azt ajánlom, hogy max a scriptet olvasgassa, és próbálja meg megérteni hogy mi és hogy működik mielőtt teljesen vakon megbízna egy netről letöltött scriptben/parancsban :D

Csak úgy a hova tartás végett: a script jelenlegi verziója ilyen outputot generált a fent említett dumpból:
# kdb_memory_check.sh -d dump_file_copy -t 10 Available physical memory: 0.215% (8.828 from 4096 MB ) HW pages: 395.750 MB (9.661% of total memory) FS cache: 1.527 MB (.037% of total memory) Processes occupied memory: 64.441 MB (1.573% of total memory) System occupied memory: 3624.265 MB (88.483% of total memory) Kernel Heap: 3320 MB (91.606% of system memory) Available paging space: 63.648% (4317.890 from 6784 MB) Additional details: SIGDANGER level: 54272 SIGKILL level: 13568 minperm percent: 3.0% maxperm percent: 90.0% maxclient percent: 90.0% Top 10 memory consumer(s) (based on nvpages) Process Name PID Virtual Pages Paged pages java 15597570 571.6 569.9 java 7274716 374.1 372.2 java 4653250 271.1 270.7 java 14745724 102.9 102.3 swapper 0 83.7 24.8 rmcd 3866808 61.6 61.1 java 6094860 50.3 49.8 kuxagent 10354744 38.0 36.8 cimserve 8192024 31.5 31.3 k07agent 6946818 22.5 20.6
Ami a process neveket illeti.. Hát az tényleg a szívás kategóriába tartozik: logikus lenne, hogy a parancs argumentumait is megtaláljuk a memóriában (hisz itt van a /proc alatt, ami meg teljesen memória rezidens), a probléma viszont az, hogy ezt minden process saját maga manageli a saját kis memória területen belül (pontosabban mondva a process-nek fenntartott Guardpage-en belül; a procfs-en belül a psargs meg erre a memória címre mutat), így azt a kernel dumpból nem fogjuk tudni kinyerni direktben...
Viszont ha mázlink van és megmaradt a process név+PID páros valamelyik bufferban/cache-benm akkor simán megpróbálhatunk ezekre rá-greppelni a dumpon belül és megszerezni a teljes process nevet, annak minden argumentumával együtt :)

Na és ezzel tényleg ennyi.. It's Now Safe to Turn Off Your Computer. Legalább is amíg a következő nagy "kihívás" nem köszön be..

2012. március 3., szombat

Élménybeszámoló - Molylepke vadászat.

Noh. Eljött ez a nap is.. Végre ez a bug vadászat is lezárult, és hivatalos ticket is nyílt róla, így most már írhatok kicsit a részletekről..

A történet ott kezdődött amikor is az egyik HACMP clusterünk failover közben mondhatni "totál beakadt" -> A Resource group-ban (RG) definiált összes resource-t leadta a primary node, a secondary is elkezdte szépen átvenni, illetve az RG is szépen átment, de a folyamat során egy nem várt esemény is előjött: A primary node ez után teljesen elérhetetlen lett. Nézzük hirtelen mit is próbál az ember amikor ilyennel találkozik:
- Nyissunk újabb SSH kapcsolatot a gépre, hátha az előző megszakadt - No response...
- Oks.. elérhető a gép? Nézzünk rá egy ping tesztet - no ping reply.. (előtte volt)
- Jó.. Nézzünk be HMC-re. Az LPAR állapota "running". Tehát elvileg az LPAR megy.. De akkor meg mi a fene?
- Hátha csak a hálózat nyekkent meg. Menjünk be soros terminálról (vterm) - Semmi nem történik.

Ilyenkor ül ki az ember a kertbe, és elkezdi nagy, kikerekedett szemmel nézni a wattafákat, és azon filózni, hogy mikor szüretelheti le majd a fáról a vattát..

Összefoglalva: Az OS se előre, se hátra, az LPAR fut.. Nincs mit tenni.. Indítsuk újra a teljes LPAR-t.
Gép újraindul, log túrás.. Semmi, ami alapján el lehetne indulni.. Jó.. Akkor nézzük meg, hogy egyáltalán tudom e reprodukálni az esetet..
RG visszarak a primary node-ra (szépen visszamegy), majd újabb failover a primary-ról a secondary-re.. Ugyan az.. De legalább tudom, hogy reprodukálható az issue, ami azért sokkal jobb, mintha valami szellemet kéne kergetnem. Mázlimra a gépen szabadon lehetett egy ideig garázdálkodni, így kedvem szerint tesztelgethettem.

Kezdés képen szerettem volna kideríteni, hogy az RG-ben lévő applikációk okozzák e a problémát, vagy mélyebben kell keresgélni. Így fogtam magam, és a HACMP-ben definiált start/stop scripteket ideiglenesen kisöpörtem a színről (így csak a diszkek, LV-k, FS-ek, mount pointok, meg a service IP maradt) és megnéztem így is összeszakad e a gép.. Hát össze..

Jó, akkor nézzük tovább.. Következő ötletem az volt, hogy akkor ráengedek egy trace-t a gépre, úgy futtatok egy ilyen lecsupaszított failover-t, és akkor hátha észreveszem, hogy hol akad meg.. Sajna ez se nyert, mert amint a gép összerogyott a memóriában lévő trace bejegyzések se kerültek kiírásra, így a trace-em teljesen hiányos volt, és csak a standard folyamatok voltak benne, amit amúgy is vár az ember.

1-2 felesleges kísérlet után eljutottam addig, hogy mivel a hálózatom egy idő után úgy is elmegy, így azon keresztül felesleges bármit nézzek, mert simán előfordulhat, hogy a hálózat megszűnése után még a gép csinál valamit a háttérben. Tehát bejelentkeztem virtuális terminálon keresztül (mondván, hogy ami ott van azt csak látnom kell), és úgy elkezdtem monitorozni, hogy a gép meddig jut.. Furcsa mód a HA (illetve az OS) az alábbi parancs után dőlt le:

ifconfig en2 delete ${HACMP_MANAGED_SERVICE_IP_ADDRESS}

Kicsit furcsálltam a dolgot, de gondoltam üsse kutya, mit veszíthetek, ha ezt a lehetőséget is megnézem. Gép újraindul, HA RG ismét a helyére, majd csodálkozva konstatáltam, hogy a fenti parancs futtatásával a gép tényleg ugyan úgy bedől, annak rendje és módja szerint..

Ez egy részről jót jelentett, mert innentől tudtam, hogy a HACMP-nek köze nincs az issue-hoz, más részről viszont bajban voltam, mert az ifconfig-nak ilyet elméletileg még véletlenül se kéne okoznia (az tuti, hogy ezt semmiféle dokumentációban nem említik :))

Ez volt az a pont amikor ez már software call-ért kiáltott.. Tehát hivatalosan is jelentettem a hibát az IBM-es fejlesztők felé, hogy akkor kérem ennek tessék utánanézni. A kezdeti adminisztrációs útvesztőkön, és issue leírás+hiba bizonyítás után aztán a hivatalos IBM supportal eljutottunk addig, hogy itt valami tényleg nem kóser. Első körben ők már egy full system dump-ot kértek tőlem -az után, hogy a gép összecsuklott- hogy megnézzék, hogy a memóriában mi van. Azt analizálva aztán kijött, hogy az összes LPAR-hoz assignolt processzor szál LOCK állapotban van, tehát nem mozdul senki semerre..

Ez persze megmagyarázza, hogy a gép ez után miért nem csinált semmit, de azt nem, hogy hogy jutott el eddig az állapotig. A következő lépésként a fejlesztők küldtek nekem egy kissé átberhelt kernelt, amiben az elérhető összes debug opciót bekapcsolták, hogy aztán az a memóriában (és így a dumpban) is könnyebben követhető legyen.

Az új kernelt életbe léptetve (majd a gépet ismételten megakasztva) immár látható volt, hogy routing lock ált be, tehát kernel szinten volt valami megkergülve. Ez már elég volt a fejlesztőknek, hogy megfelelően e tudják szűkíteni a lehetséges problémák forrását, és ki tudják ténylegesen debugolni, hogy honnan is ered a hiba.

Rövidesen meg is született az eredmény - "A" patch. Megkaptam, telepítettem, és csodák csodájára működött.. Öröm és bóduttá.. Na jó.. Nem teljesen.. Volt még 1-2 dolog amit meg kellett oldani.
-> A patch csak AIX 5.3 TL12 SP04 alá készült el. Sajna a latest SP 05ön állt, és ezen a rendszeren is hamarosan telepíteni kellett, ám mint kiderült az SP05 is érintett volt az issue kapcsán. Sőt mi több, a 6.1es AIX is (TL07,SP2 a latest). Így arra kértem a fejlesztőket, hogy a hivatalos úton olvasszák be ezt a patch-et az érintett AIX verziókba, hogy aztán a következő TL/SP-kben már benne is lehessen.

Így született aztán meg a IV16037-es patch (IBM ID szükséges a megtekintéséhez)

Ha ne adj isten valaki más is hasonló problémákba ütközik a közeljövőben (amíg a fix nem lesz elérhető hivatalosan), akkor némi kis segítség a gyors probléma megoldáshoz:
- teljes system dump force-olása a HMC-ről restartal egybekötve
- Dump analízis kdb-vel. A stack nálam így nézett ki:
pvthread+031300 STACK:
[0000932C].unlock_enable_mem+000020 ()
[00204F50]rt_setgate+0001F8 (??, ??, ??)
[043D6A08]in_ifscrub+000488 (??, ??)
[043D8050]in_control+0009A8 (??, ??, ??, ??)
[04436B38]udp_usrreq+000214 (??, ??, ??, ??, ??)
[0020E7F4]ifioctl+00075C (??, ??, ??)
[0025FDFC]soo_ioctl+000494 (??, ??, ??)
[004A8968]common_ioctl+0000C0 (??, ??, ??, ??)
[00003810].svc_instr+000110 ()
[kdb_get_memory] no real storage @ 2FF22390
[D03B1D14]D03B1D14 ()
- Ha ilyesmi, vagy a ticketben leírthoz hasonló stack-el találkozol, nyiss egy SW call-t az IBM felé, és hivatkozz a fenti fix-re.
- Ők persze ugyan úgy el fogják kérni a dump-ot, hogy megbizonyosodjanak róla, hogy a 2 eset valóban 1 tőről származik e. Ha úgy találják, hogy igen, akkor elérhetővé teszik számodra a patch-et.

2011. október 16., vasárnap

Elvitte a cica.. De hova bújt???

Pénteken olyan hibába botlottam bele, hogy azt hittem ilyen nem is létezhet.. Így hát amikor sikerült megtalálnom mi és hogy is történ(hetet)t persze, hogy úgy gondoltam, hogy ezt le kell blogoljam.. Íme egy némileg összeszedett beszámoló arról, hogy mi és hogy történt a probléma felderítése során:

Nos hát.. Alap probléma: Restart után a szerveren nem használható a /dev/null...
Nézek ki a fejemből, hogy ez miért és hogy, de a hibaüzenet egyértelműen fogalmaz:
server@user:/home/user $ ls > /dev/null
Permission denied
ksh: /dev/null: cannot create
Gyorsan átmásztam root-ba, megnéztem mi a helyzet a környéken:
server@root:/home/root # ls -ld /dev/null
crw-rw-rw-    1 root     system        2,  2 Oct 15 16:29 /dev/null
server@root:/home/root # ls -ld /dev
drw-------    5 root     system       356352 Oct 15 15:00 /dev
Aham.. hogy csak a root-nak van valami joga a mappára.. Ki lehetett az a hülye, aki átlőtte??? Na mind1, rakjuk helyére..
server@root:/home/root # chmod 775 /dev
server@root:/home/root # ls -ld /dev
drwxrwxr-x    5 root     system       356352 Oct 15 15:00 /dev
Kicsit matattam még a gépen, tettem-vettem, amikor is egy újabb parancs kiadásakor ismét ugyan ebbe a hibába botlottam (Permission denied).. Nézem ismét a /dev jogait.. megint 600... Hát mondom ilyen nincs.. valaki ilyen hülye, és még aktívan a gépen is van? Ha megtalálom nem hogy a root jogot veszem el tőle, hanem még a kezét is letöröm.. Ez a kis "lelkesedés" addig tartott, amíg észre nem vettem, hogy rajtam kívül nincs senki a gépen.. Feltételezve, hogy én nem műveltem ilyen hülyeséget néztem hogy akkor ez most WTF.. Valaki távolról, vagy hogy??? Hát mondom akkor játsszuk ezt..

Visszaállítottam a /dev jogait 775-re, majd kb 5-10 mp-enként visszaellenőriztem 'ls -ld /dev'-el, hogy mi is lehet itt.. Kb ezt kaptam:
server@root:/home/root # ls -ld /dev
drwxrwxr-x    5 root     system       356352 Oct 14 15:10 /dev
server@root:/home/root # ls -ld /dev
drwxrwxr-x    5 root     system       356352 Oct 14 15:10 /dev
server@root:/home/root # ls -ld /dev
drwxrwxr-x    5 root     system       356352 Oct 14 15:10 /dev
server@root:/home/root # ls -ld /dev
drw-------    5 root     system       356352 Oct 14 15:10 /dev
Hát mondom ilyen nincs.. valaki garázdálkodik itt, vagy mifene?? Hát a jó nénikéjét.. Fogjuk már meg..
Első gondolatom az volt, hogy az audit subsystem tökéletesen megfelel ennek kiderítésére.. De nézzük hogy is lehet ezt kivitelezni?
- /etc/security/audit/objects alá fel lehet ugyan venni a /dev-et, de az objects alatt csak read/write/execute event-eket lehet vizsgálni.. Itt meg látható, hogy az nem segítene, ergo ez nem nyert hangszórót
- Gondoltam, hogy ha valami itt a /dev jogait piszkálja, akkor a chmod-ot kell hívnia kötelezően.. Hát akkor induljunk el ebbe az irányba: Vegyünk fel a chmod parancsot az objects alá az alábbi módon:
/usr/bin/chmod:
 x = "CHMOD_USE"
Illetve a /etc/security/audit/events alá az új eventünket:
* chmod execution
  CHMOD_USE = printf "pid: %d, command: %s"
Amint ezzel kész vagyunk indítsuk újra az audit subsystem-et:
server@root:/ # audit shutdown
auditing reset
server@root:/ # audit start
server@root:/ # audit query |grep auditing
auditing on
server@root:/ # audit query |tail -2
 /usr/bin/chmod:
  x = "CHMOD_USE"
Oksa.. Tehát akkor elvileg ez is a helyén van.. akkor már csak az kell, hogy realtime nézhessük mi is folyik a gépen. Ezt az alábbi módon oldottam meg:
server@root:/ # /usr/sbin/auditstream | /usr/sbin/auditpr -t0 -heRltc |grep CHMOD
Ezzel a paranccsal lényegében direktbe szűrhetek arra, amire szeretnék.. Ergo fogtam magam, nyitottam egy újabb terminált, majd ott követtem a /dev változásait, miközben ez a stream az 'egyes" terminálon szépen futott. Direkt átírtam a chmod jogait ismét 775-re (megint 600on volt), és konstatáltam, hogy az audit igen is látja a módosításom:
CHMOD_USE       OK          root  Fri Oct 14 17:06:52 2011 chmod
Ezt követően csak vártam, és a másodlagos terminálon követtem a /dev esetleges változásait.. Egészen addig amíg a terminálon láttam, hogy a jogok megváltoztak, de az audit ebből semmit nem vett észre... WTF!? Audit stop, mit szúrtam el?? Lehet van máshol is chmod a rendszeren???
server@root:/ # find / -name chmod -type f -ls
 1057    9 -r-xr-xr-x  1 bin       bin           9216 Jul  9  2009 /usr/bin/chmod
Nincs, csak ez az egy.. Akkor meg hogy a fenébe??? Na jó, mind1.. Az auditról tudni illik, hogy azért nem csak az objects file-ja használható, hanem alapértelmezetten az events-ek között jó pár más event is előre van definálva, mint például ezek:
*       chmod()
        FILE_Mode = printf "mode: %o filename %s"

*       fchmod()
        FILE_Fchmod = printf "mode: %o file descriptor %d"
A rendszer alaptelepítés esetén ezeket nem használja (tekintve, hogy iszonyat sok adatot is generálnának), de nekem most ideiglenesen ezek pont jónak tűntek.. Meg is néztem, hogy a configon belül ezek hol vannak definiálva, és a classes alatt gyönyörűen ott sorakozott az alábbi sor:
files = FILE_Open,FILE_Read,FILE_Write,FILE_Close,FILE_Link,FILE_Unlink,FILE_Rename,FILE_Owner,FILE_Mode,FILE_Acl,FILE_Privilege,DEV_Create
A FILE_Mode alapból ott volt a files class-ban, viszont a FILE_Fchmod nem, így azt is felvettem (biztosra megyek, úgy voltam vele), így kaptam ezt a sort:
files = FILE_Open,FILE_Read,FILE_Write,FILE_Close,FILE_Link,FILE_Unlink,FILE_Rename,FILE_Owner,FILE_Mode,FILE_Acl,FILE_Privilege,DEV_Create,FILE_Fchmod
Ez után már csak az kellett, hogy ezt a class-t felvegyem a users szekció alatt a root-hoz az alábbi módon:
users:
        root = general,files
        default = objects
Rendicsek.. Akkor ez is megvan.. Biztos ami biztos kiszedtem az objests-ből előzőleg definiált chmod figyelést is, majd újraindítottam az auditot, és eljátszottam pontosan ugyan azt mint előzőleg -> egyik konzolon futott az auditing stream-je (immár grep -E "FILE_Mode|FILE_Fchmod" szűréssel), a másikon meg a /dev vizsgálata. Átállítottam ismét a /dev jogait 775-re (ekkor már kifejezetten idegesített az issue), majd örömmel konstatáltam, hogy az audit észrevette ezt a súlyos cselekményt:
FILE_Mode       OK          root  Fri Oct 14 18:05:25 2011 chmod
Újabb 1-2 percnyi várakozás, és minden elvárás ellenére ugyan az az eredmény!!! -> Az audit nem veszi észre azt ami ezt csinálja, csak azt amit én manuálisan ráengedek.. Ekkor sejtettem, hogy ez valószínű nem valami user hülyesége, hanem lehet valami bug, mert a forkot az audit tuti észrevenné.

Innentől viszont nyilvánvalóvá vált, hogy az audit e célra itt nem fog bejönni.. Kénytelen voltam elővenni a nagyágyút: trace
Szerencsémre a trace azért meglehetősen jól használható AIX alatt, feltéve ha az ember tudja hogy is használja.. Az már csak hab a tortán, hogy van egy csomó előre definiált trace event group, amik közül az alábbiak közül választhattam (A / JFS2 típusú)
server@root:/ # trcrpt -G |grep jfs2
jfs2 - JFS2: all JFS2 operations (reserved)
jfs2meta - JFS2: metadata operations (reserved)
jfs2user - JFS2: userdata operations (reserved)
jfs2snap - JFS2: snapshot operations (reserved)
Megvan azért annak az előnye, ha nem kell az embernek fejből tudnia az összes hookot :)) Ami viszont engem illetett - úgy voltam vele, hogy ennyi szívás után nem szórakozok: minden JFS2 módosításról tudni akarok!!! Ergo fogtam magam, és az alábbi módon jártam el:
server@root:/ # chmod 775 /dev
server@root:/ # ls -ld /dev
drwxrwxr-x    5 root     system       356352 Oct 15 15:00 /dev
server@root:/ # trace -a -J jfs2 -o /tmp/trc_raw 
server@root:/ # trcon
A másik konzolon meg az alábbi kis while ciklussal vártam, hogy mikor is történik pontosan (!) a váltás:
server@root:/ # while true;do echo "$(date +"%Y.%m.%d %H:%M:%S") $(ls -ld /dev)";sleep 1;done
2011.10.14 18:42:00 drwxrwxr-x    5 root     system       356352 Oct 14 18:30 /dev
2011.10.14 18:42:01 drwxrwxr-x    5 root     system       356352 Oct 14 18:30 /dev
2011.10.14 18:42:02 drwxrwxr-x    5 root     system       356352 Oct 14 18:30 /dev
2011.10.14 18:42:03 drwxrwxr-x    5 root     system       356352 Oct 14 18:30 /dev
2011.10.14 18:42:04 drwxrwxr-x    5 root     system       356352 Oct 14 18:30 /dev
2011.10.14 18:42:05 drwxrwxr-x    5 root     system       356352 Oct 14 18:30 /dev
2011.10.14 18:42:06 drwxrwxr-x    5 root     system       356352 Oct 14 18:30 /dev
2011.10.14 18:42:07 drwxrwxr-x    5 root     system       356352 Oct 14 18:30 /dev
2011.10.14 18:42:08 drwxrwxr-x    5 root     system       356352 Oct 14 18:30 /dev
2011.10.14 18:42:09 drwxrwxr-x    5 root     system       356352 Oct 14 18:30 /dev
2011.10.14 18:42:10 drwxrwxr-x    5 root     system       356352 Oct 14 18:30 /dev
2011.10.14 18:42:11 drwxrwxr-x    5 root     system       356352 Oct 14 18:30 /dev
2011.10.14 18:42:12 drw-------    5 root     system       356352 Oct 14 18:30 /dev
2011.10.14 18:42:13 drw-------    5 root     system       356352 Oct 14 18:30 /dev
2011.10.14 18:42:14 drw-------    5 root     system       356352 Oct 14 18:30 /dev
Amint erre a pontra jutottam nyomban le is állítottam a trace-t, majd amikor állítottam volna le ezt a while ciklust konstatálhattam, hogy a CTRL+C nem működik!! -> Mint kiderült: Ha belépéskor nincs a /dev-nek elég joga, akkor a CTRL+C nem fog menni, hiába van jól belőve az 'intr' érték az stty alatt:
server@root:/ # stty -a |grep intr
intr = ^C; quit = ^\; erase = ^?; kill = ^U; eof = ^D; eol = 
Amint átállítottam a /dev jogait, és nyitottam egy új shell-t nyomban visszaállt minden a régibe az adott shellen belül.. A másikon meg killelhettem a ciklust.

Na mind1.. Nézzük azt a trace-t
server@root:/ # trcoff
server@root:/ # trcrpt -O "exec=on,pid=on" /tmp/trc_raw > /tmp/trc_raw.out
server@root:/ # ls -l /tmp/trc_raw.out
-rw-------    1 root     system      7213429 Oct 14 18:26 /tmp/trc_raw.out
Kb sejthetitek miért is nem olyan gyakori a trace használata ebből már: kevesebb mint fél perc alatt majd 7 MB adat generálódott a riportban! Na de, ha már megvannak az adatok, akkor igen is nézzük át mi és hogy lehetett.. A probléma csupán az, hogy ~7 MB-ot átnyálazni kicsit sokáig tart, meg jelen esetben amúgy se célravezető.. Jobb volt inkább megnézni, hogy mely processek használták a /dev-et..

Ehhez első körben tudni kell a /dev inode számát, hogy legalább legyen mire szűrnünk:
server@root:/tmp # istat /dev
Inode 12289 on device 10/5      Directory
Protection: rw-------   
Owner: 0(root)          Group: 0(system)
Link count:   5         Length 356352 bytes

Last updated:   Fri Oct 14 18:30:10 2011
Last modified:  Fri Oct 14 18:30:10 2011
Last accessed:  Fri Oct 14 18:30:27 2011
Oks.. Tehát 12289.. Ezt nyomban át is kell váltanunk hexába, ami meg 3001.. Ezt a számot használva meg könnyen szűrhetünk is. Ha viszont csak így magában tesszük, akkor ilyen hosszú rettentő sorokat kapunk:
server@root:/ # grep -w 3001 /tmp/trc_raw.out |head -5
4DF --1-           -1            0.003434251       0.001326                   JFS2 iget: vp = F100011010C3B3E8, count = 0001, ino = 3001, dev = 8000000A00000005, getcaller = 2CF754
4DF --1-           -1            0.003444816       0.005402                   JFS2 iput: vp = F100011010C3B3E8, count = 0000, ino = 3001, nlink = 0005, getcaller = 2CF9DC
4DF --1-           -1            0.003447171       0.000623                   JFS2 iget: vp = F100011010C3B3E8, count = 0001, ino = 3001, dev = 8000000A00000005, getcaller = 2CF754
4DF --1-           -1            0.003452763       0.003297                   JFS2 iput: vp = F100011010C3B3E8, count = 0000, ino = 3001, nlink = 0005, getcaller = 2CF9DC
4DF --1-           -1            0.003455013       0.000683                   JFS2 iget: vp = F100011010C3B3E8, count = 0001, ino = 3001, dev = 8000000A00000005, getcaller = 2CF754
Ergo lehet jobban járunk ha inkább a statisztikára vagyunk kíváncsiak:
server@root:/ #  grep -w 3001 /tmp/trc_raw.out |awk '{print $2}'|sort|uniq -c
   761 --1-
   2 cdromd
   36 init
Mindjárt jobb.. Tehát.. 761 hozzáférés a kernel részéről, 2 hozzáférés a cdromd-től, 36 az inittől.. A kernellel ugye nem sokat tudok kezdeni (az meg csak nem vetemedik ilyenre!), ergo maradt a másik 2 - cdromd, meg init.. Első körben így hát fogtam magam, 'stopsrc -s cdromd'-vel leállítottam a daemon-t, visszalőttem a /dev-et 775-re, majd vártam, hogy változik e a jogosultsága.. Változott.. Ergo akkor nem a cdromd.. Vissza is kapcsoltam.

A másik lehetőség az init volt.. Erről ugye annyit illik tudni, hogy a /etc/inittab file-ban tárolt bejegyzések alapján ténykedik. Amennyiben egy program/script respawn-ra van állítva, akkor az időről időre meg is hívódik, ami meg is magyarázná, hogy hogy lehet az, hogy user interakció nélkül változzon a /dev jogosultsága.. Nade a baj az, hogy az inittab-ban azért csak úgy nem turkálunk, a cdromd-hez hasonló teszteléseket (állítsuk le, aztán nézzük meg jó lesz e úgy) meg itt már nem biztos hogy jó ötletnek tartanám..

Azt viszont tudnunk kell, hogy amennyiben az inittab indít valamit, úgy annak a bejegyzése beleíródik a wtmp-be is.. Én meg az előző mérésemből tudtam a pontos időpontot (18:42:12), így az alapján már könnyen el lehetett indulni:
server@root:/ # cat /var/adm/wtmp |/usr/sbin/acct/fwtmp |grep "Fri Oct 14 18:42:1[012]"
         cons                         8 155664 0000 0001 1318614131                                  Fri Oct 14 18:42:11 2011
cons     cons                         5 58206 0000 0000 1318614131                                  Fri Oct 14 18:42:11 2011
         cons                         8 58206 0000 0001 1318614131                                  Fri Oct 14 18:42:11 2011
cons     cons                         5 58208 0000 0000 1318614131                                  Fri Oct 14 18:42:11 2011
         cons                         8 58208 0000 0001 1318614131                                  Fri Oct 14 18:42:11 2011
cons     cons                         5 221186 0000 0000 1318614131                                  Fri Oct 14 18:42:11 2011
         cons                         8 221186 0000 0001 1318614132                                  Fri Oct 14 18:42:12 2011
cons     cons                         5 57910 0000 0000 1318614132                                  Fri Oct 14 18:42:12 2011
         cons                         8 57910 0000 0001 1318614132                                  Fri Oct 14 18:42:12 2011
cons     cons                         5 221188 0000 0000 1318614132                                  Fri Oct 14 18:42:12 2011
         cons                         8 221188 0000 0001 1318614132                                  Fri Oct 14 18:42:12 2011
cons     cons                         5 221190 0000 0000 1318614132                                  Fri Oct 14 18:42:12 2011
Aham.. Tehát a cons bejegyzés a ludas.. Az meg a getty-t hívogatja..
server@root:/ # lsitab cons
cons:0123456789:respawn:/usr/sbin/getty /dev/console
Respawn is ahogy vártam, de most komolyan a getty okozna nekem ilyen gondokat? Hát nézzük meg:
server@root:/tmp # ls -ld /dev; /usr/sbin/getty /dev/console;ls -ld /dev
drwxrwxr-x    5 root     system       356352 Oct 14 18:30 /dev
/dev/: TSM was unable to open port "/dev/"
drw-------    5 root     system       356352 Oct 14 18:30 /dev
Aham.. Hát most vagy én vagyok nagyon balszerencsés, és pont abban az időben történt más is, vagy a getty tényleg ilyen problémákkal küszködik.. (A TSM-es hibára még visszatérek). Tekintve, hogy a 'getty /dev/console'-t manapság inkább csak virtual console-okhoz használják, így szívfájdalom nélkül kikapcsoltam, majd vártam, hogy történjen valami:
server@root:/tmp # chitab cons:0123456789:off:"/usr/sbin/getty /dev/console"
server@root:/tmp # chmod 755 /dev
server@root:/ # while true;do echo "$(date +"%Y.%m.%d %H:%M:%S") $(ls -ld /dev)";sleep 1;done
2011.10.14 18:46:11 drwxrwxr-x    5 root     system       356352 Oct 14 18:30 /dev
......
2011.10.14 18:46:40 drwxrwxr-x    5 root     system       356352 Oct 14 18:30 /dev
...
2011.10.14 18:46:57 drwxrwxr-x    5 root     system       356352 Oct 14 18:30 /dev
...
2011.10.14 18:47:22 drwxrwxr-x    5 root     system       356352 Oct 14 18:30 /dev
...
2011.10.14 18:47:38 drwxrwxr-x    5 root     system       356352 Oct 14 18:30 /dev
...
2011.10.14 18:47:58 drwxrwxr-x    5 root     system       356352 Oct 14 18:30 /dev
...
2011.10.14 18:48:20 drwxrwxr-x    5 root     system       356352 Oct 14 18:30 /dev
2011.10.14 18:48:21 drwxrwxr-x    5 root     system       356352 Oct 14 18:30 /dev
2011.10.14 18:48:22 drwxrwxr-x    5 root     system       356352 Oct 14 18:30 /dev
2011.10.14 18:48:23 drwxrwxr-x    5 root     system       356352 Oct 14 18:30 /dev
2011.10.14 18:48:24 drwxrwxr-x    5 root     system       356352 Oct 14 18:30 /dev
2011.10.14 18:48:25 drwxrwxr-x    5 root     system       356352 Oct 14 18:30 /dev
2011.10.14 18:48:26 drwxrwxr-x    5 root     system       356352 Oct 14 18:30 /dev
2011.10.14 18:48:27 drwxrwxr-x    5 root     system       356352 Oct 14 18:30 /dev
2011.10.14 18:48:28 drwxrwxr-x    5 root     system       356352 Oct 14 18:30 /dev
2011.10.14 18:48:29 drwxrwxr-x    5 root     system       356352 Oct 14 18:30 /dev
Ctrl+C.. Őszinte leszek.. Még mindig nem értettem a dolgot.. Ezek szerint tényleg a getty okozza a problémát.. De miért?? Nézzük a konzol beállításokat:
server@root:/tmp # lscons -a
 current = NULL
 console_logname = /var/adm/ras/conslog
 console_logsize = 32768
 console_logverb = 1
 console_tagverb = 0
Na jó.. Beismerem.. Ez tényleg nem egészséges.. Ezt azonnal orvosolni kell:
server@root:/tmp # chcons -a login=enable /dev/vty0
chcons: Console login cannot be enabled because the console device
        is not an available lft, tty, or vty.
Hö??? WTF??? Mi van a vty0-val?
server@root:/tmp # lsdev -Cctty
vty0 Defined  Asynchronous Terminal
Jah hogy úgy.. Na ezt rántsuk már be akkor:
server@root:/tmp # cfgmgr -l vty0
Method error (/etc/methods/cfgtty -l vty0 ):
        0514-040 Error initializing a device into the kernel.
Na menj a tudod hova... Van más is amiről tudnom kéne??
server@root:/ # lsdev |grep vs
vsa0        Defined            LPAR Virtual Serial Adapter
vsa1        Defined            LPAR Virtual Serial Adapter
vsa2        Available          LPAR Virtual Serial Adapter
server@root:/ # lsdev |grep vty
vty0        Defined            Asynchronous Terminal
Aham.. LPAR profil alapján csak 1 Virtual Serial Adapter van (ezek szerint az lesz a vsa2), de akkor ez miért lát 3at?? Na mind.. Gyomláljunk, mert ez így gázos:
server@root:/ # for i in vty0 vsa2 vsa1 vsa0;do rmdev -dl $i;done
vty0 deleted
vsa2 deleted
vsa1 deleted
vsa0 deleted
server@root:/ # cfgmgr
server@root:/ # lsdev |egrep "vty|vsa"
vty0        Available          Asynchronous Terminal
vsa0        Available          LPAR Virtual Serial Adapter
server@root:/ # chcons -a login=enable /dev/vty0
chcons: console login enabled, effective on next system boot
chcons: console assigned to: /dev/vty0, effective on next system boot
Oks.. Mindjárt jobb.. Console-al mi van?
server@root:/ # pstart
console DISABLE
vty0 ENABLE
Na ez még gázos lehet.. Akkor ezt is rakjuk helyre:
server@root:/ # penable console
server@root:/ # pstart
console ENABLE
vty0 ENABLE
Ez után ismét megnéztem mi és hogy áll.. Sajna azt kellett tapasztaljam, hogy a penable igaz, hogy helyére rakta a console-t, viszont az inittab-ban is újra engedélyezte a cons bejegyzést.. Ez miatt ismét rakhattam off-ba, illetve lőhettem vissza a /dev-et 775-re.. Viszont sajna a jelek szerint a getty még mindig nem ment normálisan:
server@root:/tmp # ls -ld /dev; /usr/sbin/getty /dev/console;ls -ld /dev
drwxrwxr-x    5 root     system       356352 Oct 14 18:30 /dev
/dev/: TSM was unable to open port "/dev/"
drw-------    5 root     system       356352 Oct 14 18:30 /dev
Hát jó.. akkor nem maradt más restart.. Ami láss csodát.. Megoldotta a problémát!
server@root:/tmp # ls -ld /dev; /usr/sbin/getty /dev/console;ls -ld /dev
drwxrwxr-x    5 root     system       356352 Oct 14 19:10 /dev
drwxrwxr-x    5 root     system       356352 Oct 14 19:10 /dev

Éljen.. akkor problem solved.. Na de azért bennem felmerült 1-2 dolog.. Az első, hogy mint látható, most a TSM nem dobott hibát. Tekintve, hogy a TSM-es hiba direktben a /dev-re hivatkozott, így erősen esélyesnek tartom, hogy a problémának ehhez is köze lehet.. Tekintve, hogy ez egy TSM szerver, így nem csodálkoznék, ha ez egy TSM bug lenne, viszont a neten körbeszaglászva ilyen, vagy ehhez hasonló hibaleírást véletlenül se sikerült találnom.. A gyanúmat még jobban alátámasztja az, hogy a getty által piszkált file-ok a /dev alatt default 622-es jogot kapnak (hacsak ezt az ODM-ben nem bíráljuk felül, de ilyen itt nem volt)
Az viszont a probléma ellen szól, hogy a TSM-nek semmi köze nem szabadna legyen ezen a szinten a rendszerhez, pláne nem a getty futtatásakor. Így az is elképzelhető, hogy ez is csak egy a sok side affect közül (mint pl a CTRL+C-s hiba) ami amúgy egy getty-os bug.
Mindazonáltal a hiba meglehetősen furcsa volta, illetve a hiba keresési mód miatt úgy gondoltam, hogy ez az írás megér egy blog bejegyzés (tudom - jó hosszú lett)

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)