Loggolás alatt egy alkalmazás működése közben zajló események, keletkező adatok háttértáron való rögzítését értem.
Az adatok rögzítése történhet állományba, valamint adatbázisba. (Most főleg a fileba való loggolást tárgyalom, csak érintem az adatbázisba való loggolást.)
A cél, hogy a loggolt adatokat fel tudjuk használni:
- hibás működés felderítéséhez,
- helyes működés bizonyításához,
- statisztikai adatok kinyeréséhez,
- stb.
A loggolás amúgy az alkalmazás haszontalan része, mivel a loggolt adatokat az üzemszerű működés során nem használjuk fel, hacsak nem része az üzleti logikának (mint a fenti esetekben a statisztika).
A log keletkezése és felhasználása
A loggolással kapcsolatosan két fő tevékenységet különíthetünk el. Mindkettőnél követelmény, hogy gyorsan végrehajtható legyen.
1. az adat loggolása: nagyon gyakori esemény, ezért egy-egy adat rögzítését nagyon gyorsan kell elvégezni, hogy az alkalmazás üzleti logikával kapcsolatos folyamatait ne lassítsuk. (Adatbázisba való loggolás során a logot tartalmazó táblát – a kulcstól eltekintve – nem is indexeljük, mivel az egyes mezők újraindexelése sok időt vesz igénybe, így maga a log rögzítése blokkolhatja az alkalmazást.)
2. adat visszakeresése: szerencsés esetben erre ritkán van szükség, de akkor általában sürgősen, vagyis az érintett logot gyorsan meg kell találnunk.
A log „formátuma”
A fenti 2. pont miatt a log tartalmát megfelelően kell szerveznünk:
- a log bejegyzés legyen áttekinthető,
- tartalmazza az összes szükséges adatot,
- könnyen, költséghatékonyan legyen kereshető,
- rögzítse világosan az adat keletkezésének „körülményeit”.
A logállományok szervezése
- a log állományokat logikusan nevezzük el,
- ezeket csoportosítsuk megfelelően strukturált és elnevezett (al)könyvtárakba.
A legjobb struktúra felépítése nagymértékben függ az üzleti logikától, ezért konkrét javaslatot nem tudok adni. (A post végén található példák viszont támpontot nyújthatnak.)
(A log nevében időnként érdemes rögzíteni olyan információt, ami amúgy magában a logban is szerepel. Előfordulhat ugyanis, hogy a teljes logot el kell küldeni pl. e-mailben, így nem kell bajlódni az átnevezgetéssel, de ez egy adott logállomány megtalálásában is segíthet.)
Az adatok rögzítése
Törekednünk kell arra, hogy a loggolandó adatokon ne végezzünk átalakításokat, hanem közvetlenül kerüljenek loggolásra. Ennek biztosítása érdekében az adatokat azok keletkezési helyéhez minél „közelebb” loggoljuk le.
Minden, a loggolandó adatokon végzett művelet növeli a hibázás lehetőségét. (Ha az adatokon valamilyen műveletet végzünk, és csak azután loggoljuk, akkor valójában a "műveletet" loggoljuk, s nem az eredeti adatokat.)
Rendellenes működés kiszűrése
Üzemszerű működés során – vagyis, amikor nincs probléma -, a logot nem szoktuk vizsgálni: felesleges erőforrás-felhasználás.
A rendellenes működésről viszont azonnal szeretnénk értesülni. Ennek érdekében egy daemonnal figyeljük a hibás eseményeket rögzítő logot (logcheck), és változás esetén pl. e-mailben kérjünk értesítést. (A log változását érdemes pl. 1 órás időközönként figyelni, igaz, így a hibákról csak óránként értesülhetünk.)
A log élettartama
Az alkalmazás működése során, a loggolt adatok mennyisége folyamatosan növekszik, aminek a rendelkezésre álló háttértár szab csak határt. Ennek elkerülése érdekében, az üzleti logikát figyelembe véve határozzunk meg, mennyi időre visszamenőlegesen van értelme megtartani a logokat. Az ennél régebbieket töröljük.
Mivel az elérhető logokat is érdemes kordában tartani, ezért szintén az üzleti logikától függően határozzuk meg, mennyi időre visszamenőleg kell a logok azonnali hozzáférhetőségét biztosítani. Az ennél régebbieket tömörítsük be.
A log felhasználása
Loggolást többféle célból készítünk, pl.:
- fejlesztés során ellenőrizzük az elkészült algoritmus helyességét, megfelelőségét,
- éles működés során a rendellenes működést követjük nyomon,
- statisztikai adatok kinyerése (általában a statisztikák esetében nem is a konkrét logot, hanem az abból vett, feldolgozott adathalmazt vizsgálunk),
- stb.
Fejlesztés
- a fejlesztésnél keletkező log állományokat ne tegyük fel a verziókezelőbe,
- mivel az éles működés során nem feltétlenül van szükség a loggolásra, azt úgy kell elkészíteni, hogy könnyen ki/bekapcsolható legyen,
- érdemes logszinteket is kialakítani, pl.: információ, hiba, figyelmeztetés, kritikus, stb, majd az éles működés során beállítani, hogy milyen kritikusságú eseményeket rögzítsünk a logban. (Pl. az információknak csak fejlesztés alatt van jelentősége.)
Éles működés
Éles működés során a loggolással kapcsolatban nem szabad, hogy felesleges erőforrásokat használjunk fel. Ha nincs probléma az alkalmazás működése során, nem szükséges e-mail értesítést küldeni. A levelek feldolgozása plusz időt és energiát igényel.
A logok archiválását és törlését is automatizáljuk.
Kritikus fontosságú alkalmazások loggolása
Bizonyos alkalmazásoknál a loggolás az üzleti folyamattal együtt kritikus fontosságú. Így, ha a loggolás nem működik, az egész alkalmazás működése leáll.
Példák
(Az alábbi események a valóságban nem történtek meg, a téma tárgyalása érdekében találtam ki őket.)
1. Péda
Tekintsünk egy könyvtári alkalmazást, azon belül is a kölcsönzést.
Nagyobb látogatottság esetén – pl. vizsgaidőszakban – azt tapasztalták az üzemeltetők, hogy egy kölcsönzés adminisztrációjának időtartama megnövekszik; némely művelet akár 20-30 mp is lehet. (Ez azzal is jár, hogy sorok állnak a pultok előtt, és növekszik a könyvtári tagok elégedetlensége is.)
Az üzemeltetést végzők az adatbázis, illetve a lekérdezések lassúságára gyanakodnak, mivel záróra után a rendszer válaszideje 3-5mp-re csökken, ami a 30mp-et tekintve, már jónak lenne mondható.
Az alkalmazás fejlesztői ezen információ alapján határozzák meg a célokat.
Cél: szeretnék kiszűrni a lassú lekérdezéseket, s így kideríteni, hogy melyik tábla, vagy kapcsolat okozza a lassúságot.
A logbejegyzés felépítésének első változata:
SQL_parancs végrehajtási_idő
A loggolás elkészítése után az első logbejegyzéseket áttekinve a végrehajtási idő értéke – az SQL parancsok hosszának „ingadozása” miatt – gyakorlatilag követhetetlen lett.
Második változat; fordítsuk meg a két adat sorrendjét:
végrehajtási_idő SQL_parancs
Most már a végrehajtási idők jól áttekinthetőek.
Mivel a rendszerünk több, másik – hasonló rendszerrel is kapcsolatban áll -, fontos lehet, hogy mikor keletkeztek az adott bejegyzések.
Harmadik változat:
éé-hh-nn óó:pp:mm végrehajtási_idő SQL_parancs
(Itt még annyi finomítást érdemes tennünk, hogy a végrehajtási idő értékét 2 karakter hosszan, „jobbra igazítva” jelenítsük meg: így gyorsan ki tudjuk keresni a hosszabb lekérdezéseket.)
A logok alapján a fejlesztők a könyvtár szakembereivel egyeztetve abban állapodnak meg, hogy elsődleges feladatként a kb. 10mp-nél lassabb lekérdezéseket kell kiemelt prioritással megoldani, de további két „sávot” határoznak meg, amiket kisebb prioritással fognak kezelni.
A logokat így három állományba gyűjtik:
- 20 mp-et meghaladó lekérdezések,
- 10-20mp-et igénylő lekérdezések,
- 10mp alatt végrehajtódó lekérdezések.
A fenti logokat rendre a következő logállományok tartalmazzák:
SQL_20s.log
SQL_10-20s.log
SQL_0-10s.log
Becslésük szerint napi szintű logokat előállítva hatalmas mennyiségű adattal kellene dolgozniuk, így órás bontásban fogják tárolni az adatokat, vagyis módosulnak az eredeti állománynevek:
SQL_óó_20s.log
SQL_óó_10-20s.log
SQL_óó_0-10s.log
Mivel így naponta 3 * 24 log állomány keletkezik, a logokat napi szinten, könyvtárakba gyűjtik: éééé-hh-nn
2010-08-10/
SQL_óó_20s.log
SQL_óó_10-20s.log
SQL_óó_0-10s.log
2010-08-11/
SQL_óó_20s.log
SQL_óó_10-20s.log
SQL_óó_0-10s.log
2. Példa: Külső rendszerrel való kommunikáció loggolása
Az 1. példa eredményeit felhasználva, a fejlesztőknek sikerült az összes lekérdezés futási idejét 1-2mp-re csökkenteni. (Ezért a loggolást úgy módosították, hogy a 3mp-en felüli lekérdezések kerüljenek csak a logba, és ezekről e-mail értesítést is kértek.)
Egy idő után az üzemeltetők – hozzászokva a felgyorsult rendszerhez – ismét lassúságra panaszkodtak, bár a fejlesztők nem kaptak értesítést, hogy valamely lekérdezés hossza meghaladta volna a 3mp-et.
Így ismét megvizsgálták a rendszert, most már a kölcsönzés teljes folyamatát áttekintve.
Az üzemeltetési paramétereket módosítva egyszer csak „eltűnt” a rendszerből a lassúság, és azonnali rugalmas működés volt tapasztalható.
A könyvtári rendszer számos, kisebb fiókkönyvtárral állt kapcsolatban. Ha valaki keresett egy könyvet, az alkalmazás először a könyvtár saját adatbázisában kereste, majd – opcionáisan - a fiókkönyvtárak adatbázisaiban. (A rendszerek közötti adatcserét XML formátumú adatcsomagok biztosították.)
A fejlesztők ezt a funkciót kapcsolták ki. Most már csak ki kellett deríteni, hogy melyik fiókkönyvtárral való kapcsolódás tart hosszú ideig.
Ennek érdekében újabb logot építettek be a rendszerbe, ami a könyvtár, és a fiókkönyvtárak kapcsolatát loggolja.
Mivel sok kommunikáció volt várható, ezért a logokat fiókkönyvtáranként egy-egy mappába helyezték.
Első változat; a logfile neve: fiókkönyvtárneve/éé-hh-nn-könyvtár_neve.log
éé-hh-nn óó:pp:mp kommunikáció_ideje
Annak érdekében, hogy pontosabb adatokat kapjanak a kommunikációról, több módosítást tettek:
- loggolják a cél rendszer IP címét,
- a kommunikáció során használt portot,
- illetve zárójelben a timeout értékét is,
- valamint a küldött, és a fogadott XML-eket. (Mivel a kommunikáció során nem TAB-al, vagy szóközzel "formázott" XML-ek érkeznek, ezeket nem is formázzák be, hanem átalakítás nélkül kerülnek a logba.),
- a logban továbbá külön jelölik a küldött „>>”, valamint a fogadott „<<” adatokat is. Ha a fiókkönyvtártól nem jön válasz, azt „|<” jellel jelölték.
Második változat (sikeres kommunikáció):
éééé-hh-nn óó:pp:mp (15s) >> xxx.yyy.zzz.www:abcd
<adatok><adat1></adat1>...<adatn>...<adatn></adatok>
éééé-hh-nn óó:pp:mp (15s) << 3.14
<adat>...</adat>
Mivel a kommunikációk most már rendben loggolódnak, ezért a fejlesztők első lépésként a 10mp-nél hosszabban tartó kommunikációkat kívánják loggolni, illetve mivel így lényegesen kevesebb log várható, egy állományba irányították a logot.
Ezek alapján már könnyű volt kiszűrni a lassú kapcsolatú fiókkönyvtárat, az alábbi log segítségével.
2010-08-09 23:30:42 (15s) >> 111.111.222.222:1234
<adatok><adat1></adat1>...<adatn>...<adatn></adatok>
2010-08-09 23:30:57 (15s) |<
A fenti logból ugyanis egyértelműen kiderült, hogy az 111.111.222.222 IP-n lévő fiókkönyvtár az esetek nagy részében nem válaszolt 15mp-en belül.
Mivel a fiókkönyvtár üzemeltetői a hálózati problémákat hamar kiszűrték, így most már rendben zajlanak a kommunikációk.
A normál, üzemszerű működés figyelése érdekében azonban további módosításokat eszközöltek:
- a timeout értékét csökkentették 5mp-re; így egy lassú kommunikáció nem "tartotta" fel a többi kommunikációt,
- a logokba csak azok a bejegyzések kerültek, amiknek a válaszideje több, mint 4mp,
- az egyes fiókkönyvtárak logjaira logcheck-et állítottak be, és a log változásairól értesítést küldenek az egyes fiókkönyvtáraknak.
