Un paio di assiomi ;-):
  • Il Tracing è necessario;
  • Il Tracing è di una noia mortale;
Però… ci sono due macro categorie di Tracing in realtà, io divido tra:
  • Tracing: quello che fa il codice: il metodo tal dei tali è stato invocato con la lista di parametrei xyz;
  • Logging: quello che fa l’utente: l’utente ‘mauro’ alla tal ora del tal giorno ha salvato la tal anagrafica cliente;
Quello che più mi pesa è la prima categoria, facendo un esempio decisamente triviale di quello che siamo abituati a scrivere:
class Program
{
    static TraceSource tracer = new TraceSource( "Program" );

    static void Main( string[] args )
    {
        try
        {
            tracer.TraceEvent( TraceEventType.Verbose, 0, "Entering method..." );

            var p = new Person();
            p.FirstName = "Mauro";
            p.LastName = "Servienti";

            var x = p.Echo( p );

            Console.WriteLine( x );
        }
        catch( Exception e )
        {
            tracer.TraceEvent( TraceEventType.Critical, 0, "Unhandled Exception: {0}", e );

            throw;
        }
        finally
        {
            tracer.TraceEvent( TraceEventType.Verbose, 0, "Exiting method..." );
        }
    }
}
se pensiamo a quanto tempo investiamo nella scrittura, e manutenzione, di quel codice mi viene male, questo in generale a prescindere dallo strumento di Tracing che usiamo.
Introducing AOP with PostSharp
Il tracing è uno di quegli aspetti della programmazione in cui AOP potrebbe fare da padrone, alla fine della fiera quel codice è generalizzabilissimo e varrebbe proprio la pena di farlo.
Ho già parlato più di una volta di PostSharp: qui, qui, qui e qui. Oggi voglio approfondire alcuni concetti e far vedere come lo sto usando con soddisfazione, molta soddisfazione.
AOP: Compile Time Code Injection
PostSharp ragiona in maniera completamente diversa rispetto a tutti i framework che fanno policy/behavior injection, in generale siamo abituati ad un qualcosa fatto a runtime utilizzando il concetto di transparent proxy, viene cioè creato a runtime un proxy che wrappa il vostro tipo e inietta codice e comportamento, è evidente che questo ha un costo in termini di performance; ha anche interessanti vantaggi sia chiaro.
PostSharp invece interviene a compile time, PostSharp incorpora un post-compilatore che interviene dopo la compilazione fatta da MSBuild, disassembla il vostro compilato, inietta il codice e ricompila. Vediamo un esempio proprio in materia di Tracing:
[Serializable]
public class TraceAttribute : OnMethodBoundaryAspect
{
    public override void OnEntry( MethodExecutionEventArgs eventArgs )
    {
        eventArgs.MethodExecutionTag = Guid.NewGuid();
        Console.WriteLine( "--> ctx: {1} - {0}", eventArgs.Method.Name, eventArgs.MethodExecutionTag );
    }

    public override void OnExit( MethodExecutionEventArgs eventArgs )
    {
        Console.WriteLine( "<-- ctx: {1} - {0}", eventArgs.Method.Name, eventArgs.MethodExecutionTag );
    }

    public override void OnException( MethodExecutionEventArgs eventArgs )
    {
        Console.WriteLine( "--- Exception at" );
        Console.WriteLine( "--- ctx: {1} - {0}", eventArgs.Method.Name, eventArgs.MethodExecutionTag );
        Console.WriteLine( "--- Begin of Stack Trace" );
        Console.WriteLine( eventArgs.Exception.StackTrace );
        Console.WriteLine( "--- End of Stack Trace" );
    }
}
Creiamo una classe che deriva da una classe base del framework di PostSharp, in questo caso OnMethodBoundaryAspect che, come lascia intuire il nome, è una sorta di wrapper intorno al codice di un metodo (ove per metodo vengono intesi anche costruttori, proprietà ed eventi).
Torniamo al codice di esempio da cui siamo partiti e trasformiamolo così:
[assembly: TraceAttribute( AttributeTargetMembers = "*", 
                           AttributeTargetAssemblies = "PostSharp Tracing" )]

namespace PostSharp_Tracing
{
    class Program
    {
        static void Main( string[] args )
        {
            var p = new Person();
            p.FirstName = "Mauro";
            p.LastName = "Servienti";

            var x = p.Echo( p );

            Console.WriteLine( x );
            Console.Read();
        }
    }
}
Se lo compiliamo e manidamo in esecuzione l’output è questo:
image
Urka :-) praticamente abbiamo “gratis” un trace di tutto quello che è successo nel codice, ma cosa è successo? Apriamo con Reflector l’assembly generato:
image
Il metodo Main() del nostro programma è diventato qualcosa di decisamente diverso, e così tutto il resto. PostSharp ha infatti iniettato una montagna di codice per far si che vengano effettuate le chiamate al codice del nostro attributo.
Non mi dilungo oltre perchè ho parlato a lungo di come funziona, tutto bello però c’è un problema. Se osserviamo bene il codice generato c’è un sacco di overhead che per quello che vogliamo fare è pressochè inutile (per altri usi di PostSharp è una manna ma per il tracing non serve proprio a nulla). L’overhead è in soldoni questo:
  • MSBuild compila il vostro codice;
  • PostSharp disassembla e deve iniettare le chiamate;
  • Quello che però deve fare non è chiamare il vostro codice perchè non ha idea di come farlo non conoscendolo… deve quindi creare un generico e flessibile ponte: programma –> infrastruttura di PostSharp –> codice di tracing –> infrastruttura di PostSharp –> programma;
E’ evidente che questo costa…
Ma non tutto è perso, anzi. PostSharp mette a disposizione anche un livello di intervento decisamente più basso, chiamato Weaver, che vi consete di inserirvi direttamente nel processo di Post-Compilazione al fine di emettere direttamente codice… IL…
Naturalmente lungi da me intraprendere questa impervia ed ardua strada, soprattutto se altri lo hanno già fatto ;-)
Log4PostSharp
Dopo aver seguito i passi per il setup di tutto l’ambaradan possiamo cambiare il nostro codice in questo modo:
[assembly: XmlConfigurator( Watch = true )]
[assembly: Log( AttributeTargetMembers = "*",
    AttributeTargetAssemblies = "PostSharp Tracing",
    EntryLevel = LogLevel.Debug,
    ExitLevel = LogLevel.Debug )]

namespace PostSharp_Tracing
{
    class Program
    {
        static void Main( string[] args )
        {
            var p = new Person();
            p.FirstName = "Mauro";
            p.LastName = "Servienti";

            var x = p.Echo( p );

            Console.WriteLine( x );
            Console.Read();
        }
    }
}
L’unica differenza evidente sono le dichiarazioni in testa, aggiungiamo l’attributo XmlConfiguration che istruisce log4net (utilizzato come framework di logging da Log4PostSharp) su come gestire la configurazione e rimpiazziamo il nostro attributo TraceAttribute con LogAttribute incluso nella librearia Log4PostSharp, ricordiamoci anche di aggiungere la configurazione di log4net nel file app.config:
<configSections>
  <section name="log4net" type="log4net.Config.Log4NetConfigurationSectionHandler, log4net" />
configSections>

<log4net>
  <appender name="consoleAppender" type="log4net.Appender.ConsoleAppender">
    <layout type="log4net.Layout.PatternLayout">
      <conversionPattern value="%date [%thread] %-5level %logger %ndc - %message%newline" />
    layout>
  appender>

  <root>
    <level value="ALL" />
    <appender-ref ref="consoleAppender" />
  root>
  
log4net>
Ecco il nuovo metodo Main dopo la Post-Compilazione:
image
Le differenze sono evidenti, non c’è più traccia di tutta l’infrastruttura di PostSharp (che infatti non è più una dipendenza a runtime per il nostro programma) ma troviamo solo del sano codice di tracing molto simle (naming a parte) a quello che potremmo scrivere noi. Ed ecco il risultato a runtime con la configurazione di log4net di cui sopra:
image
Di nuovo urka ;-)
Un paio di note:
  1. il codice iniettato non interferisce in alcun modo con la debug-experience;
  2. Il codice di tracing dipende da log4net e vi obbliga all’uso di log4net; utilizzando la prima tecnica che abbiamo visto sarebbe abbastanza facile utilizzare IoC/DI nel TraceAttribute per iniettare a runtime il motore di tracing ma:
    1. IMVHO: non ne vale la pena neanche dipinti sui muri ;-)
    2. Generalizzare il sistema di Tracing vi porterebbe ad avere un’infrastruttura di Tracing veramente povera, vedasi come esempio quella di Castle Windsor, perchè le uniche feature che potreste esporre sono il minimo comun denominatore delle feature messe a disposizione dai motori di tracing che volete supportare;
    3. Generalizzare/cambiare il motore di tracing con la seconda tecnica ha invece un costo altissimo perchè dovete essere dei mezzi guru di IL e della generazione di codice a compile-time… quindi viva log4net ;-)
Quali sono i side effects, sempre che ce ne siano? in generale io per ora ne ho trovato uno solo: i tempi di build si allungano sensibilmente perchè la post-compilazione costa, ma se lo paragono ai benefici il caffè che mi bevo tra una build è l’altra è tempo molto ben speso ;-)
Una cosa che ho fatto è stata però ricompilare il plugin Log4PostSharp per la versione 1.5 di PostSharp, la versione originale è per la 1.0, perchè il post-compiler della 1.5 è mostruosamente più veloce.
Per quello che rigarda il Logging continuo a farlo a mano, ma quello ha anche aspetti interessanti e problematiche curiose che val la pena affrontare.
.m