AIX at its best #1

Bevezeto: Az AIX device-kezelese

Az AIX statikusan kezeli az eszkozoket. Csak bootkor van egy automatikus hardverfelismeresi folyamat, amely ugyanazt a cfgmgr nevezetu utility-t es az azon keresztul a /usr/lib/methods alatti rutinokat hivja meg, mint amit manualis konfiguraciokor vegzunk. A cfgmgr az installp-t (AIX package manager) meghivva tud drivert is telepiteni, ha megadjuk neki az eleresi utvonalat, illetve - korlatozott mertekben - kepes azt is megallapitani, hogy milyen driver hianyzik.

Az AIX idestova kb 25 eve egy file-alapu leiro adatbazist hasznal szinte az osszes rendszerinformacio tarolasara (kiveve pl a usereket vagy a security informaciokat), legjellemzobben a device-ok es a szoftverek adatai vannak itt. Ezt kulonfele utility-kkel lehet nezegetni es kezelni. Az ODM egy resze a boot LV-n is megtalalhato. A futo rendszeren pedig az ODM a kernel es a file alapu registry (/etc/objrepos/* - root part, /usr/lib/objrepos/* - usr part) kozott szinkronizalodik.

Elozmenyek

Van egy rendszer, amin AIX 5.3 TL8 futott Oracle-lel es nehany sulyos szoftverrel (permanens 4-5 koruli load 4 db POWER6 fizikai CPU core-ral 16 threaden, 24GB RAM-mal). 2 darab 2portos FC adapteren log rajta egy csomo diszk FC multipathing-gal (MPIO), ket kulonfele storage-bol (termeszetesen azok kulon VG-ben is vannak). A scalable VG formatum miatt eszetlenul sok, tobb mint 1.1 millio PP (physical partition = physical extent) van egyes VG-kben.

Oktoberben egyszer eszrevettuk, hogy az MPIO egyik utvonala nem stimmel, Missing statuszban van, igy a megfelelo AIX utility-vel megprobaltuk helyretenni (rmpath, cfgmgr), de a diszkeket nagyon lassan szedte vissza, am vegul sikerult.

Masnap megis ugy tunt, hogy valami permanens problema van, igy jobb hijan rebootoltuk a rendszert. 3 honapig futott ezutan, es talan a tobbi problema rejtve is maradt volna, ha a mult heten nem akartunk volna egy *harmadik* fajta storage-rol uj LUN-okat csapni ehhez az LPAR-hoz is. Mivel azonban ehhez vagy egy uj driver, vagy a megfelelo fixpack kellett volna, a gyors upgrade mellett dontottunk, es upgrade-eltem a gepet TL11 SP1-re (ez a tavaly decemberi, legfrissebb szint). Commit nem volt, vissza tudnek allni az elozo TL-re, de szerintem jelen esetben az nem segitene.

A hiba

Reboot utan jo szokasomnak megfeleloen ;-) konzolban neztem a boot folyamatot, es ezt lattam:

/etc/rc[46]: 184572 Segmentation fault(coredump)


o_O, na ez mi lehet? Az AIX-en a legtobb, rendszerrel osszefuggo problemara egy univerzalis log, az errlog all rendelkezesre, amit nem a syslogd, hanem az errdemon nevu processz kezel a /dev/error specialis file-on, illetve ODM stanza-kon keresztul. Ez tobbek kozott a segfault-okat is szamon tartja, itt a fenti is:

# errpt -Aj C69F5C9B
...
LABEL: CORE_DUMP
Date/Time: Fri Jan 29 12:04:28 CET 2010
Type: PERM
Resource Name: SYSPROC
Description
SOFTWARE PROGRAM ABNORMALLY TERMINATED
Detail Data
SIGNAL NUMBER
11
USER'S PROCESS ID:
184572
FILE SYSTEM SERIAL NUMBER
1
INODE NUMBER
2
CORE FILE NAME
//core
PROGRAM NAME
swapon
STACK EXECUTION DISABLED
0
COME FROM ADDRESS REGISTER
extend_br 170


PROCESSOR ID
hw_fru_id: 0
hw_cpu_id: 0

ADDITIONAL INFORMATION
extend_br 20C
extend_br 170
Unable to generate symptom string.

Mi a helyzet a paging space-szel, talan nincs is fenn a swap? De igen...
Az AIX paging space aktivalasa ket lepesben tortenik, eloszor meg a boot legelejen, akkor csak az elsodleges aktivalodik, majd multiuser-ben az osszes. Az elso sikeres volt, az utobbi (swapon -a) dobta a dumpot.

Mivel ezt shellben is tudtam reprodukalni, megneztem truss-szal (strace AIX-es megfeleloje), mi a gondja.


Trace Started at: Fri Jan 29 12:16:42 2010
413944: 0.0011: execve("/usr/sbin/swapon", 0x2FF22C3C, 0x2000FBB8) argc: 2
413944: 0.0145: __loadx(0x03480000, 0x2FF22A50, 0x00000118, 0x10000000, 0x20000594) = 0x00000000
413944: 0.0149: __loadx(0x0A040000, 0xD059652C, 0x0000000A, 0x00000000, 0x00000000) = 0x00000000
413944: 0.0152: _sigaction(33, 0x200025C8, 0x00000000) = 0
413944: 0.0158: vmgetinfo(0x2FF1F5E0, 7, 16) = 0
/* snip */
413944: 0.0222: access("/usr/lib/nls/msg/en_US/cmdps.cat", 0) = 0
413944: 0.0224: _getpid() = 413944
413944: 0.0226: open("/etc/swapspaces", O_RDONLY) = 3
413944: 0.0227: kioctl(3, 22528, 0x00000000, 0x00000000) Err#25 ENOTTY
413944: 0.0229: kioctl(3, 22528, 0x00000000, 0x00000000) Err#25 ENOTTY
413944: kread(3, " * / e t c / s w a p s".., 4096) = 408
413944: kread(3, " * / e t c / s w a p s".., 4096) = 0
413944: kread(3, " * / e t c / s w a p s".., 4096) = 0
413944: 0.0236: close(3) = 0
413944: 0.0238: sysconfig(3, 0x2FF20130, 12) = 0
413944: 0.0243: sysconfig(3, 0x2FF1FC70, 12) = 0
413944: 0.0244: hd_cfg(0x00000000, 0x00000000, 0x0000001F, 0x20017D88, 0x00000000, 0x000002C0, 0x00000000, 0x00000000) = 0x00000000
413944: 0.0247: _getpid() = 413944
413944: 0.0248: _getppid() = 360648
413944: 0.0249: open("/etc/lvmtlog.cfg", O_RDONLY) Err#2 ENOENT
413944: 0.0254: sysconfig(3, 0x2FF1E580, 12) = 0
413944: 0.0255: hd_cfg(0x00000000, 0x00000000, 0x0000001F, 0x2002BD88, 0x00000000, 0x00000280, 0x00000000, 0x00000000) = 0x00000000
413944: 0.0257: open("/etc/vg/vg00C91F5B00004C0000000112537093C9", O_RDONLY|O_RSHARE|O_DELAY) = 3
413944: 0.0258: sysconfig(3, 0x2FF1E5D0, 12) = 0
413944: 0.0260: hd_cfg(0x00000014, 0x00000000, 0x00000093, 0x2FF1EEA0, 0x00000000, 0x000002D0, 0x00000000, 0x00000000) = 0x00000000
413944: 0.0261: sysconfig(3, 0x2FF1E5D0, 12) = 0
413944: 0.0262: hd_cfg(0x00000014, 0x00000000, 0x00000027, 0x2FF1EEA0, 0x00000000, 0x00000290, 0x00000000, 0x00000000) = 0x00000000
413944: 0.0265: _getpid() = 413944
413944: 0.0266: mknod("/dev/__pv15.14.413944", 8576, 0x000F000E) = 0
413944: 0.0305: statx("/dev/__pv15.14.413944", 0x20023D98, 76, 0) = 0
413944: 0.0306: openx("/dev/__pv15.14.413944", O_RDONLY, , 8) = 4
413944: 0.0308: lseek(4, 3584, 0) = 3584
413944: kread(4, " _ L V M\0 É1F [\0\0 L\0".., 512) = 512
413944: 0.0313: klseek(4, 0, 4096, 0x00000000) = 0
413944: kread(4, " D E F E C T\0\0\0\0\0\0".., 512) = 512
413944: kpread(4, 0x20023D98, 512, 0x00000000, 0x00051400) = 512
413944: kpread(4, 0x20023FA8, 123392, 0x00000000, 0x00051600) = 123392
413944: kpread(4, 0x200421B8, 96768, 0x00000000, 0x0006F800) = 96768
413944: kpread(4, 0x20059BC8, 25088, 0x00000000, 0x001E7A00) = 25088
413944: kpread(4, 0x2005FDD8, 33554944, 0x00000000, 0x00247C00) = 33554944
413944: Received signal #11, SIGSEGV [default]
413944: *** process killed ***


Elemzes

Valamilyen oknal fogva az tortenik, hogy nem a megfelelo diszken keresi a paging LV-t (/dev/hd6), hanem, ahogy a VGID es a diszk major/minor (/dev/__pv15.14*) alapjan azonosithato, egy masik VG-n. A kread sorokban olvashato adatokat meg is lehet talalni a hdisk2 elejen.

Azt gondolom, mivel /etc/swapspaces alapjan csak egy LV nevet ismer a swapon, innentol elvileg az ODM-tol kellene hamis adatokat kapnia, ennek csak az mond ellent, hogy:

- nincs a truss kimeneteben hivatkozas ODM class-ra
- nem talaltam rossz informaciokat az ODM-ben
- a korai boot fazisaban meg mukodik a swapon...
- a readvgda es a getlvcb sem mutat rendellenes adatokat

Terjunk vissza a mult heti esemenyekhez. Mikor truss-oltam a swapon-t, feltunt, hogy letrehozza a /dev/__pv15.14.$pid file-okat. De az 'ls -l /dev/__pv*' -ra 'The argument list is too long'-ot kaptam... A find segitsegevel kiderult, hogy nem kevesebb, mint 27612 'kamu' inode van ilyen nevvel...! Tuzetesebben megnezve oket, az alabbiak tuntek fel:

- csak az oktoberi reboot ota generalodnak
- nagy reszuk 'dba' group ownership alatt van, az egyetlen potencialis ilyen user pedig az oracle...
- mas file-ok nincsenek 'dba' group alatt
- a nap folyaman altalaban egyenletesen, 5 perccel oszthato valtozo idotartamokban jonnek letre
- a mult heti reboot ota nem keletkeznek ujak, holott a szerver uzemben van
- csak erre az egy diszk major/minorra jonnek letre

Az is nyilvanvalova valt, hogy ilyen atmeneti __pv* device node-ok uzemszeruen is letrejonnek minden AIX-en, de korantsem ilyen tomegben; jellemzoen csak 1-2 van, es 'valami' elvileg le is takaritja oket (nem a shutdown, sem az rc.boot).

Mivel egyertelmuen semmi hasznuk nem volt ezeknek, mind le is lett torolve, ami a 15:14 major:minor diszkhez tartozott. Mondanom sem kell, ettol a swapon nem kezdett el mukodni...

Megjegyzesek

Egyeb: Van meg nehany hasonlo rendszer (azonos TL/funkcio), de ez az inode problema mashol meg nem fordult elo.

Legrosszabb esetben nyitok egy PMR-t az IBM-nek, de egyelore jo lenne 'haznon belul' rajonni valamire, hiszen nekik sem lenne egyszeru korbejarni a problemat a rengeteg homalyos resz, illetve valtozas miatt (TL upgrade, 3 kulonbozo storage, Oracle, device-ok dba group-ban...). Meg vegul is support ide, support oda, nehogy mar azt higgyek, hogy impotensek vagyunk ;-)

Mivel a 8GB-os paging space aktiv, es kicsi az eselye annak, hogy kifussunk belole, illetve a rendszerrel jelenleg amugy sem tudunk leallni, most biztosan nem tudunk egyeb muveleteket vegrehajtani (pl oracle VG-k leallitasa). Swapoff vagy uj paging space swapon szinten nem mukodik.

To be continued...