Measuring & displaying Phing build times with buildhawk

Recently I installed a Ruby gem called buildhawk which allows to measure and display the build times of Rake driven builds. As I like the idea behind this tool a lot but mostly use Phing for build orchestration, it was time to explore the possibility to interconnect them both. In this blog post I'll show an implementation of an apposite Phing Logger gathering the buildhawk compatible build times via git note(s) and how to put the interplay between those two tools to work.

Logging on

As mentioned above the build time of each build is stored as a git note and associated to the repository's HEAD, reflecting the current state of the system under build (SUB), which assumes that the SUB is versioned via Git. The next shown Phing Logger (i.e. BuildhawkLogger) grabs the overall build time by hooking into the buildFinished method of the extended DefaultLogger class, transforms it into a buildhawk specific format and finally adds it as a git note.

<?php

require_once 'phing/listener/DefaultLogger.php';

/**
 *  Writes a build event to the console and store the build time as a git notes in the   
 *  project's repository HEAD.
 *
 *  @author    Raphael Stolt <raphael.stolt@gmail.com>
 *  @see       BuildEvent
 *  @link      https://github.com/xaviershay/buildhawk Buildhawk on GitHub
 *  @package   phing.listener
 */
class BuildhawkLogger extends DefaultLogger {
    
    /**
     *  @var string
     */
    private $_gitNotesCommandResponse = null;

    /**
     *  Behaves like the original DefaultLogger, plus adds the total build time 
     *  as a git note to current repository HEAD.
     *
     *  @param  BuildEvent $event
     *  @see    BuildEvent::getException()
     *  @see    DefaultLogger::buildFinished
     *  @link   http://www.kernel.org/pub/software/scm/git/docs/git-notes.html
     */
    public function buildFinished(BuildEvent $event) {
        parent::buildFinished($event);
        if ($this->_isProjectGitDriven($event)) {
            $error = $event->getException();
            if ($error === null) {
                $buildtimeForBuildhawk = $this->_formatBuildhawkTime(
                    Phing::currentTimeMillis() - $this->startTime
                );
                if (!$this->_addBuildTimeAsGitNote($buildtimeForBuildhawk)) {
                    $message = sprintf(
                        "Failed to add git note due to '%s'",
                        $this->_gitNotesCommandResponse
                    );
                    $this->printMessage($message, $this->err, Project::MSG_ERR);
                }
            }
        }
    }
    
    /**
     * Checks (rudimentary) if the project is Git driven
     *
     *  @param  BuildEvent $event
     *  @return boolean
     */
    private function _isProjectGitDriven(BuildEvent $event)
    {
        $project = $event->getProject();
        $projectRelativeGitDir = sprintf(
            '%s/.git', $project->getBasedir()->getPath()
        );
        return file_exists($projectRelativeGitDir) && is_dir($projectRelativeGitDir);
    }
    
    /**
     *  Formats a time micro integer to buildhawk readable format.
     *
     *  @param  integer The time stamp
     */
    private function _formatBuildhawkTime($micros) {
        return sprintf("%0.3f", $micros);
    }
    
    /**
     *  Adds the build time as a git note to the current repository HEAD
     *
     *  @param  string  $buildTime The build time of the build
     *  @return mixed   True on sucess otherwise the command failure response
     */
    private function _addBuildTimeAsGitNote($buildTime) {
        $gitNotesCommand = sprintf(
            "git notes --ref=buildtime add -f -m '%s' HEAD 2>&1",
            $buildTime
        );
        $gitNotesCommandResponse = exec($gitNotesCommand, $output, $return);
        if ($return !== 0) {
            $this->_gitNotesCommandResponse = $gitNotesCommandResponse;
            return false;
        }
        return true;
    }
}

Putting the Logger to work

As the buildhawk logger is available via GitHub you can easily grab it by issuing sudo curl -s http://gist.github.com/raw/707868/BuildhawkLogger.php -o $PHING_HOME/listener/BuildhawkLogger.php. The next step, making the build times loggable, is achieved by using the -logger command line argument of the Phing Cli and specifying the buildhawk logger name or the path to it. In case you want the buildhawk logger to be used per default (it behaves like the default logger if the SUB isn't Git driven/managed) you can also add it to the Phing shell script.

The next console command issued in the directory of the SUB shows a Phing call utilizing the BuildhawkLogger, assumed it has been installed at $PHING_HOME/listener/BuildhawkLogger.php and not been made the default logger.

phing -logger phing.listener.BuildhawkLogger

Looking at them Phing build times

Now it's time to switch to buildhawk and let it finally perform it's designated task, rendering an with the commit SHAs, commit messages, and build times fed Erb template into an informative, viewable HTML page. To install it you simply have to run sudo gem install buildhawk and you're good to go.

The next console command shows the buildhawk call issued in the SUB's directory to produce it's build time report page.

buildhawk --title 'Examplr' > examplr-build-times.html

The outro screenshot below gives you a peek at a rendered build time report.