writing a build logger: all the news fit to print - jeffcal's blogland - Site Home

We have an internal discussion list for users of MSBuild to share their thoughts and experiences with each other and bring questions they have about MSBuild. Last week, one of our internal users wrote the list to talk about some performance issues he was noticing as his build projects grew larger and larger, but he needed to extract timing info for the build in order to drill down on the problem. MSBuild won't give you this for free, but it offers an even better solution: loggers. By writing a custom logger, which is really just a .NET class implementing a public MSBuild interface, users can receive the events they're interested in receiving and record them in the ways they're interested in viewing them.

So I set out to write a logger which computes and records timing info for each segment of the build. I pasted the outcome of this effort below. Essentially I started off maintaining an open xml document and writing the data to the file as it became available (i.e., when the MSBuild engine fired a StatusEvent). This was quite efficient but the logs were just flat out ugly because every single “build“ element had to have a child “time“ element. So at the expense of my RAM, I cached all of the events for the entire build and processed the data once the build was complete. Here's what I came up with:

using System; using System.Xml; using System.Collections; using Microsoft.Build.Framework; namespace BuildTimer { /// <summary> /// This logger computes and records the timing info for each interesting segment /// of the build, i.e., the time spent in each task, target, and project along /// with the total time for the entire build. /// </summary> public class BuildTimer : ILogger { private Queue events; //where we cache all of the events private string parameters; //storage for Parameters property private LoggerVerbosity verbosity; //storage for Verbosity property /// <summary> /// From ILogger. This value is specified on the command line along with the logger spec. /// Should be a valid path to a writable location or the logger will throw during Shutdown() /// when it tries to write the XML log. /// </summary> /// <value>The value the engine provided from the logger's command line spec.</value> public string Parameters { set { parameters = value; } get { return parameters; } } /// <summary> /// From ILogger. This value is either specified on the command line, or the engine will /// set it to the default value LoggerVerbosity.Normal. All loggers receive the same value /// for a particular build and it is their choice/responsibility to use Verbosity as they /// see fit. In particular, the set of events a logger receives from the engine is the /// same no matter what Verbosity is specified. /// </summary> /// <value>The value specified on the command line, or the default if none was specified.</value> public LoggerVerbosity Verbosity { set { verbosity = value; } get { return verbosity; } } /// <summary> /// From ILogger. This method is called by the engine before any events are fired /// so the logger can register for events it's interested in. In our case, we're /// only interested in StatusEvents. /// </summary> /// <param name="eventSource">IEventSource provided by the engine for event registration.</param> public void Initialize(IEventSource eventSource) { events = new Queue(); eventSource.StatusEvent += new BuildEventHandler(StatusHandler); //register for StatusEvents } /// <summary> /// From ILogger. This method is called by the engine once all events have been fired. /// The logger should perform any final work here. We create an Xml file and log all /// event info including times to the file. /// </summary> public void Shutdown() { XmlTextWriter log = new XmlTextWriter(Parameters, System.Text.Encoding.Unicode); log.Formatting = Formatting.Indented; log.IndentChar = '\t'; Stack timingInfo = ComputeTimingInfo(); //contains one BuildInterval per Started/Finished pair while (events.Count > 0) { BuildStatusEventArgs statusEvent = (BuildStatusEventArgs)events.Dequeue(); if (!IsStartedStage(statusEvent.Stage)) //finish event - close the element and carry on { log.WriteEndElement(); continue; } log.WriteStartElement(GetStageElementName(statusEvent.Stage)); if (statusEvent.Stage != BuildStage.BuildStarted) //StageName is blank for BuildStarted { log.WriteAttributeString("Name", statusEvent.StageName); } BuildInterval interval = (BuildInterval) timingInfo.Pop(); log.WriteAttributeString("Time", (interval.Finish - interval.Start).ToString()); if (Verbosity == LoggerVerbosity.Detailed || Verbosity == LoggerVerbosity.Diagnostic) { log.WriteAttributeString("Message", statusEvent.Message); log.WriteAttributeString("Start", interval.Start.ToString()); log.WriteAttributeString("Finish", interval.Finish.ToString()); } } log.Close(); } /// <summary> /// The registered BuildEventHandler which will receive all StatusEvents /// from the engine. We simply cache the event and save the work for /// Shutdown() when we know we've received all events. /// </summary> /// <param name="sender">Ignored.</param> /// <param name="args">BuildStatusEventArgs object we cache for later use.</param> public void StatusHandler(object sender, BuildEventArgs args) { events.Enqueue(args); } /// <summary> /// Walks the event cache and populates a stack with BuildIntervals for each /// Started/Finished pair of StatusEvents. /// </summary> private Stack ComputeTimingInfo() { Stack remaining = new Stack(events); //the constructor effectively reverses the order we'll see events Stack finishedEvents = new Stack(); Stack timingInfo = new Stack(); while (remaining.Count > 0) { BuildStatusEventArgs currentEvent = (BuildStatusEventArgs) remaining.Pop(); if (IsStartedStage(currentEvent.Stage)) { BuildInterval interval = new BuildInterval(); interval.Start = currentEvent.TimeStamp; interval.Finish = ((BuildStatusEventArgs)finishedEvents.Pop()).TimeStamp; timingInfo.Push(interval); } else { finishedEvents.Push(currentEvent); } } return timingInfo; } /// <summary> /// Simple test to see if a particular BuildStage was one of the "Started" stages. /// </summary> /// <param name="stage">The stage to be checked.</param> private bool IsStartedStage(BuildStage stage) { return ((stage == BuildStage.TaskStarted) || (stage == BuildStage.TargetStarted) || (stage == BuildStage.ProjectStarted) || (stage == BuildStage.BuildStarted)); } /// <summary> /// This exists purely for performance, to avoid repeated calls of the form /// /// stage.ToString().Replace("Started", "") /// </summary> /// <param name="stage">The stage we're getting the element name for.</param> private string GetStageElementName(BuildStage stage) { string name = String.Empty; switch (stage) { case BuildStage.TaskStarted: name = "Task"; break; case BuildStage.TargetStarted: name = "Target"; break; case BuildStage.ProjectStarted: name = "Project"; break; case BuildStage.BuildStarted: name = "Build"; break; } return name; } } /// <summary> /// Use this to conveniently pair the timing info for a Started/Finished event pair /// so we can later output it to the log. /// </summary> internal struct BuildInterval { public DateTime Start; public DateTime Finish; } }

I like the output of this logger much better now even if it chews up memory on order of the number of status events (I've always been a sucker for form over function). With a sufficiently large project, it'd probably be necessary to go back to the uglier logs or risk the logger becoming its own bottleneck in the build's perf. Finally, here's an example of the logger's output when logging a build of itself with default verbosity:

With a command line switch, I can increase the verbosity to include the Message, Start time, and Finish time for each build segment.

jeff.