Bij mijn huidige project werd de vraag gesteld of één van onze websites
geïnstrumenteerd kon worden met debug meldingen zodat de werking, de flow door de code, gecontroleerd kon worden.
Daar we al aardig op weg waren naar de oplevering van een nieuwe release
was het introduceren van injectie frameworks geen optie. De gemakkelijkste
oplossing leek het ons om meldingen in de eventlog te schrijven. Natuurlijk
geeft dit een aardige belasting op die Application eventlog dus waren we wel zo
slim (..) om dit alleen te doen als onze projecten in debug mode gecompileerd
werden.
We wilden dus aan het begin en einde van een aantal methodes even loggen
dat we hier langsgekomen waren. Ook enkele try-catches moesten opgefleurd
worden.
Het gebruik van #if DEBUG #endif had als neveneffect dat de code lekker
onleesbaar en minder onderhoudbaar werd. Gelukkig kwam ConditionalAttribute tot de redding:
using System.Diagnostics;
namespace Logging
{
/// <summary>
/// Log a message to the eventlog.
/// This code is only available when the project is
/// compiled in Debug mode
/// </summary>
public class LogToDebugEventLog
{
/// <summary>
/// Logs the specified text only when the project is
/// compiled as Debug.
/// </summary>
/// <param name="text">The text to log.</param>
[Conditional("DEBUG")]
public static void Log(string text)
{
EventLog.WriteEntry("Application", text);
}
}
}
Dit gaf lucht. Bovenstaande code geeft een compact statement om een tekst
te loggen. En het mooie is dat deze code verdwijnt als deze NIET in debug mode
wordt gecompileerd (vandaar dat het een static void is en dat in combinatie met
die “DEBUG”).
Vervolgens was er de vervolg-wens om de tijdsduur te loggen die verstreek
als een bepaalde actie uitgevoerd werd. Hiervoor is de StopWatch class prima te
gebruiken, maar ook die geeft nogal wat verstoring aan de huidige code. De
stopwatch moet in het geheugen aangemaakt worden, het moet gestart worden, het wordt hopelijk ook ooit gestopt en dan moet de tijdsduur afgedrukt worden. En een exception mag de werking niet verstoren…
Door handig met IDisposible te werken kan deze “code verstoring” sterk
teruggebracht worden:
using System.Diagnostics;using System;
namespace Logging
{
/// <summary>
/// Use this class in a Using to count the number of
/// milliseconds an action takes
/// </summary>
public class DebugStopwatch : Stopwatch, IDisposable
{
/// <summary>
/// Gets or sets the text to show when the stopwatch is stopped.
/// </summary>
/// <value>
/// The text.
/// </value>
public string Text { get; set; }
/// <summary>
/// Initializes a new instance of the
/// <see cref="DebugStopwatch"/> class.
/// </summary>
/// <param name="text">the stopwatch is stopped.</param>
public DebugStopwatch(string text)
{
Text = text;
Start();
}
/// <summary>
/// Performs application-defined tasks associated with freeing,
/// releasing, or resetting unmanaged resources.
/// </summary>
public void Dispose()
{
Close();
}
/// <summary>
/// Closes this instance.
/// </summary>
public void Close()
{
if (this.IsRunning)
{
Stop();
LogToDebugEventLog.Log(
String.Format("{0} - Elapsed time: {1}ms",
Text,
ElapsedMilliseconds));
}
}
}
}
Bovenstaande class kan nu aangeroepen worden met slechts één
using:
using (var debugStopwatch = new DebugStopwatch("Method X"))
{
// do some stuff here...
}
De stopwatch wordt gestart in de constructor (zegmaar: bij de eerste
accolade)en gestopt bij de dispose (de tweede accolade). De tekst die aan de
constructor meegegeven wordt, zal ook afgedrukt worden, tesamen met de
verstreken tijd in milliseconden.
De Close actie krijg je kado om eventueel met code de stopwatch te
stoppen.
Helaas wordt de timer ook aangemaakt, gestart en gestopt als de
applicatie niet als DEBUG versie wordt opgeleverd. Alleen de tekst wordt dan
niet getoond. Dit kan nog wel met een #if #endif opgelost worden want dit speelt
zich binnen de DebugStopwatch af. Maar wat er nog meer knaagde, was het feit dat we nog steeds de eventlog aan het vullen waren. Eigenlijk iedere vorm van loggen naar een permanente vorm (file/database) was niet wenselijk.
Toen moest ik denken aan een verwijzing naar een blog in de Morning
Brew. Ik kan iedere Microsoft ontwikkelaar aanraden om zeker deze blog te
volgen. Sterker nog, als je dagelijks maar één blog wilt lezen, lees dan deze.
Het geeft simpele maar uitstekende opsomming van wat er momenteel aan
ontwikkelingen zijn rond Microsoft development. Ik laat het uittreksel dagelijk
in Outlook landen want die heb ik altijd openstaan en dan heb ik geen extra
feedreader nodig.
DebugView
In de Moringbrew had ik enkele weken geleden iets gelezen over debuggen
zonder debugger. Gelukkig vond ik het item snel terug en het bleek over DebugView te gaan, onderdeel van de onvolprezen SysInternals.
In deze gave verzamling van diagnose tooling zit ook een simpele
executable die kan luisteren naar Debug.Write en Trace.Write. Dus ik heb de betreffende blogpost doorgenomen en dit is een heel aardig stuk gereedschap. Het is namelijk erg lastig als op bepaalde machines (lees de test- of productieserver) de bestaande logging onvoldoende inzicht geeft over de
interne werking. En in die situatie zatten wij ook. Met deze tool kan gewoon
meegeluisterd worden zolang het een debug build betreft. Het is ook een ideale
tool naast Visual Studio om te werking te controleren zonder dat je met de
VS2010 debugger door de code moet steppen. Het kleine debugger schermpje binnen VS2010 loopt niet zo handig mee en DebugView heeft een keur van opties om de output inzichtelijk te maken (zoals always-on-top, filteren en zoeken).
Het tooltje is al enkele jaren oud maar het functioneert nog prima. Het
werkt zowel op XP als op nieuwere OS-en zoals Windows 7. Ik heb het werkend
getest met IIS en met IIS Express. Trace messages werken pas als “Capture Global Win32” wordt aangezet, maar die optie is niet beschikbaar onder XP. Onderstaande schermafdruk is in XP gemaakt. Hier wordt dus alleen de debug melding getoond (de breakpoint werd niet actief doordat ik draaide zonder debugger; opstarten met CTRL-F5):
DebugView draait als executable dus hoeft niet geinstalleerd te worden op de
server. Wellicht draait het zelf vanaf een memorystick. Er is ook een Remote
Monitoring optie voor het debuggen van servers over het netwerk maar dit lijkt
mij lastig uit te leggen aan systeembeheerders…
Conclusie
Als nu de DebugStopWatch gecombineerd wordt met het gebruik van
Debug.WriteLine() voor DebugView, dan kan dit leiden tot een tijdelijke log die
prima inzicht geeft in de werking van een applicatie. Er is ook alleen maar een
afhankelijkheid met System.Diagnostics. De gecontroleerde code hoeft niet extra
geinstrumenteerd te worden met 3e partij frameworks.
Sander van de Velde 