Jó napot, jó kódolást!
„Bizony mondom néktek, boldogok a debugtalanok, mert övék a performancia országa...”
Történt a minap, hogy megkérdeztem Főnöktörpöt, mi a szerinte elfogadható idő egy Logon hívásra. Valahogy így:
-Szerinted mennyi idő az elfogadható egy SessionService.Logon esetén?
-Tíz. Köbö tíz miliszek.
-Hmm... Most olyan 30-40 körül van. Na, majd megnézem.
Azzal megnéztem. Release mód, log level ERROR, hoster.exe a profiler-be, adjunk neki.
Logon. Nem jó. Egy adat nem fog pontos eredményt adni. Logoff.
Némi molyolás után összedobtam egy szokásos T01 commandot a DAMCON-ban, valahogy így:
public static class TestMethods
[CommandMethod("Test", RequiresAuthentication = false, SysCommand = true)]
public static void T01()
{
for (int i = 0; i < 100; i++)
{
Session session = Session.Logon("admin", "admin");
session.Close();
}
}
}
Egyszerű, mint a kalapács, dehát ezt szeretnénk mérni. Nosza. Adatbázis újrahúz, profiler újraindít, perceg a diszk (na jó, másodperceg), jön a feketeleves.
Bizony, a logon ideje 500 hívásra átlagolva ~12-15 ms között alakul. Meg is néztem, miért. Nos, kód kódot követett, és eljutottam egy általam írt SqlCommandHelper metódusig:
/// <summary>
/// Logs the parameters of an SqlCommand to the provided logger.
/// </summary>
/// <param name="sqlCmd">The SqlCommand to log.</param>
/// <param name="logger">Logger to log to.</param>
private static void LogCommandParameters(SqlCommand sqlCmd, ILog logger)
{
//#if DEBUG
if (null != logger && logger.IsDebugEnabled)
{
string pref =
"==================================================================================================";
string query = GetQueryText(sqlCmd);
logger.Debug("\n" + pref + "\nExecuting SqlCommand:\n" + pref + "\n" + query + "\n" + pref);
}
//#endif
}
Akár hiszitek, akár nem, ERROR szintű logolás mellett a fenti kód rendre meghívódott. Néhány ezer alkalommal. Aucs.
Nézzük figyelmesen, mit vizsgálunk:
- Van-e logger insztanszunk? – Check
- Debug mód van bekapcsolva? – Nope!
Hoppá! Vagyis a mérések szerint kb. 50%-át az teszi ki egy-egy SQL query futtatásának, hogy elkészítjük, majd ignoráljuk a lognak szánt információkat.
Mert ugye a fentiek ellenére a logger.Debug("\n" + pref + "\nExecuting SqlCommand:\n" + pref + "\n" + query + "\n" + pref) utasítás nem írt a logba egy kanyi bájt se.
Az idő jó részét tehát kidobtuk, hiszen a szerver hívások entry-point-ján hasonló mechanizmus ellenőriz/logol szükséges esetben.
Hogy is van ez? Debug enabled, de mégsem?
Erre már megremegett a kezem a refaktor gomb fölött, aztán mást gondolva összeraktam a LoggerHelper-ben egy metódust, ami egzaktul arra vizsgál, hogy a config szerint DEBUG level-t állítottunk-e, vagy sem.
Át is írtam erre a kódot, amit demonstráció céljából ERROR loglevel mellett debugoltam azon melegében.
Valahogy így nézett a képernyő megrökönyödött arcomra:
Igen, a logger szerint mi most itten DebugEnabled környezet vagyunk, pedig nem. Nos, valami erősen sanda gyanú fogalmazódott meg bennem. Tudniillik a log appender példányokat a LoggerHelper explicite beállítja a config fájlban található LogThreshold szerint, ami esetünkben ERROR. Mi történik akkor itt? Nem számít, hogy milyen szintet állítunk be az appendereknek?
Clickety-click, már jön is fel a debug watch window, nézem a logger-t, a repository-ját, és mit látok? Threshold = ALL. Hmm...
Innen persze már könnyű volt megtalálni a probléma forrását, konkrétan az ILoggerRepository példány létrehozásakor explicite nem mondtunk Thresholdot, ezért ő úgy gondolta, hogy minden érdekes nekünk.
Viszont az appenderek tették a dolgukat, és a Repository-ból áramló üzeneteket szépen ignorálták. Nade ugye azokat a log üzeneteket előállítani sokszor nem kevés idő!
Pótoltam hát a Repository beállítás hiányosságát, alapos alázattal átnéztem még a Logon implementációt, és némi kulturált default használat beiktatásával, illetve statikus elemek megtartásával végül az alábbi mérési eredmény született:
A képről jól látható, hogy a LogonInternal hívás (a tényleges munkavégzés) effektíve ~3.5ms környékére csökkent. No, ezért megérte belevágni.
Tanulság
Röviden összefoglalva:
· A log4net futási időben történő konfigurálásakor nem csak az appenderek Threshold-ját, de az őket használó repository Threshold-ját is be kell állítani.
· A kvázi-statikus, nagyon ritkán változó dolgokat célszerű nem eldobálgatni (pl. Server-ek nyilvántartása az Invenio-ban).
· Rengeteget számít, hogyan, mit és mennyit logolunk.
