Key Performance Indicators in the Alpha Framework

Published on 2011-06-13 by John Collins. Socials: YouTube - X - Spotify - Amazon Music - Apple Podcast

Introduction

In the context of web applications, a Key Performance Indicator (KPI) is a benchmark that attempts to answer common business questions about the performance of a live application, for example:

How long does it take to login?
How long does it take to open the profile for a user?
How long does a search take?

The answers to these questions enable the owner of the application to determine where any performance issues reside, enabling corrective action to be taken and the subsequent monitoring for the success or otherwise of the action taken.

“It is much better for the site owner to have a clear understanding of what parts of the application are slow from a user perspective”

The accurate collection of KPIs also allow for an assessment of the typical user experience. It is much better for the site owner to have a clear understanding of what parts of the application are slow from a user perspective, rather than waiting for the user to complain, or worst still not complain but just leave the site and never return.

A simple KPI framework for Alpha

As part of the Alpha Framework roadmap, I wanted to add a simple but effective KPI solution to the framework. I had a number of design goals:

It should be easy to reuse (always a good design goal!).
It should support the logging if steps in a KPI as well as the overall performance metric.
It should log KPIs into seperate .csv files, which I felt would make it easier for generating reports.

The actual fields that the KPI framework will capture are as follows:

Timestamp: the date/time when the KPI was logged.
Name: the name of the KPI for identification, also used as part of the KPI filename. When logging a step, the logged entry will be in the format "KPI name [step name]".
SessionID: the unique session identifier from PHP, useful for when you want to correlate multiple separate KPIs to the same user in a report.
StartTime: the start time of the KPI, in the form of a UNIX timestamp.
EndTime: the end time of the KPI, in the form of a UNIX timestamp.
Duration: the duration of the KPI in seconds (with decimal precision).

A typical log entry will look something like this:

2011-06-13 22:03:12,search [log search query],698crr1htlf22g87inuc47gm47,1307998992.0963,1307998992.1088,0.012527942657471
2011-06-13 22:03:12,search [loaded matching tags],698crr1htlf22g87inuc47gm47,1307998992.0963,1307998992.1649,0.068588018417358
2011-06-13 22:03:12,search [built array of matching OIDs],698crr1htlf22g87inuc47gm47,1307998992.0963,1307998992.1654,0.069087982177734
2011-06-13 22:03:12,search,698crr1htlf22g87inuc47gm47,1307998992.0963,1307998992.2692,0.17289686203003

Implementation and usage

I have added a new class into the utils package of Alpha with the following source code:

<?php
 
require_once $config->get('sysRoot').'alpha/util/helpers/AlphaValidator.inc';
require_once $config->get('sysRoot').'alpha/model/types/Timestamp.inc';
require_once $config->get('sysRoot').'alpha/model/types/String.inc';
 
/**
 *
 * A Key Performance Indicator (KPI) logging class
 * 
 * @package alpha::util
 * @since 1.1
 * @author John Collins
 * @version $Id: AlphaKPI.inc 1403 2011-05-25 19:37:35Z johnc $
 * @license http://www.opensource.org/licenses/bsd-license.php The BSD License
 * @copyright Copyright (c) 2011, John Collins (founder of Alpha Framework).  
 * All rights reserved.
 * 
 * <pre>
 * Redistribution and use in source and binary forms, with or 
 * without modification, are permitted provided that the 
 * following conditions are met:
 * 
 * * Redistributions of source code must retain the above 
 *   copyright notice, this list of conditions and the 
 *   following disclaimer.
 * * Redistributions in binary form must reproduce the above 
 *   copyright notice, this list of conditions and the 
 *   following disclaimer in the documentation and/or other 
 *   materials provided with the distribution.
 * * Neither the name of the Alpha Framework nor the names 
 *   of its contributors may be used to endorse or promote 
 *   products derived from this software without specific 
 *   prior written permission.
 *   
 * THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND 
 * CONTRIBUTORS "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, 
 * INCLUDING, BUT NOT LIMITED TO, THE IMPLIED WARRANTIES OF 
 * MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE ARE 
 * DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT HOLDER OR 
 * CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL, 
 * SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT 
 * NOT LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; 
 * LOSS OF USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION) 
 * HOWEVER CAUSED AND ON ANY THEORY OF LIABILITY, WHETHER IN 
 * CONTRACT, STRICT LIABILITY, OR TORT (INCLUDING NEGLIGENCE 
 * OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE OF THIS 
 * SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
 * </pre>
 *  
 */
class AlphaKPI {
    /**
     * The date/time of the KPI event
     * 
     * @var Timestamp
     * @since 1.1
     */
    private $timeStamp;
 
    /**
     * The name of the KPI
     * 
     * @var String
     * @since 1.1
     */
    private $name;
 
    /**
     * The session ID of the current HTTP session
     * 
     * @var string
     * @since 1.1
     */
    private $sessionID;
 
    /**
     * The start time of the KPI event (UNIX timestamp in seconds)
     * 
     * @var float
     * @since 1.1
     */
    private $startTime;
 
    /**
     * The end time of the KPI event (UNIX timestamp in seconds)
     * 
     * @var float
     * @since 1.1
     */
    private $endTime;
 
    /**
     * The duration in seconds
     * 
     * @var float
     * @since 1.1
     */
    private $duration;
 
    /**
     * Constructor
     * 
     * @param string $name The name of the KPI which is used in the log files, must only
     *  be letters and/or numbers.
     * @throws IllegalArguementException
     * @since 1.1
     */
    public function __construct($name) {
        $this->name = new String();
        $this->name->setRule(AlphaValidator::REQUIRED_ALPHA_NUMBEIC);
        $this->name->setHelper('The KPI name can only contain letters and numbers');
 
        $this->name->setValue($name);
 
        $this->timeStamp = new Timestamp(date('Y-m-d H:i:s'));
 
        $this->startTime = microtime(true);
 
        if(!isset($_SESSION))
            session_start();
 
        // a startTime value may have been passed from a previous request
        if(isset($_SESSION[$name.'-startTime'])) {
            $this->startTime = $_SESSION[$name.'-startTime'];
            $_SESSION[$name.'-startTime'] = null;
        }
 
        $this->sessionID = session_id();
    }
 
    /**
     * Stores the current startTime for the KPI in the session, useful for multi-request
     * KPI tracking.
     * 
     * @since 1.0
     */
    public function storeStartTimeInSession() {
        $_SESSION[$this->name->getValue().'-startTime'] = $this->startTime;
    }
 
    /**
     * Writes the KPI event to a log file named logs/kpi-'.$this->name->getValue().'.csv,
     * which will be created if it does not exist.
     * 
     * @since 1.1
     */
    public function log() {
        global $config;
 
        $this->endTime = microtime(true);
 
        $this->duration = $this->endTime - $this->startTime;
 
        $logfile = new LogFile($config->get('sysRoot').'logs/kpi-'.
           $this->name->getValue().'.csv');
 
        $logfile->setMaxSize($config->get('sysLogFileMaxSize'));
        $logfile->setSeperator(',');
 
        $logfile->writeLine(array($this->timeStamp, $this->name->getValue(), 
           $this->sessionID, $this->startTime, $this->endTime, $this->duration));
    }
 
    /**
     * Writes a step in the KPI event to a log file named logs/kpi-'.$this->name->
     * getValue().'.csv, which will be created if it does not exist.
     * 
     * @since 1.1
     */
    public function logStep($stepName) {
        global $config;
 
        $this->endTime = microtime(true);
 
        $this->duration = $this->endTime - $this->startTime;
 
        $logfile = new LogFile($config->get('sysRoot').'logs/kpi-'.$this->name->getValue()
            .'.csv');
 
        $logfile->setMaxSize($config->get('sysLogFileMaxSize'));
        $logfile->setSeperator(',');
 
        $logfile->writeLine(array($this->timeStamp, $this->name->getValue().' ['.
            $stepName.']', $this->sessionID, $this->startTime, $this->endTime,
            $this->duration));
    }
}
 
?>

To use this class, you simply include the class and invoke it, then begin logging:

<?php
 
//...
 
require_once $config->get('sysRoot').'alpha/util/AlphaKPI.inc';
 
//...
 
$KPI = new AlphaKPI('search');
 
//...
 
$KPI->logStep('log search query');
 
//...
 
$KPI->logStep('loaded matching tags');
 
//...
 
$KPI->logStep('built array of matching OIDs');
 
//...
 
$KPI->log();
 
//...
 
?>

Remember that as the class is using the session to temporally store the named KPI start time, you can invoke a KPI object from one controller or view and close it from another controller or view, and a single KPI entry will be logged.

The generated log files are stored in the [sysRoot]/logs directory of your application. Here is an example listing containing several KPI log files:

[root@redhat ~]# cd /var/www/html/TestApp/logs/
[root@redhat logs]# ls -l
total 640
-rw-r--r-- 1 apache apache 588374 2011-06-05 10:19 alpha.log
-rw-r--r-- 1 apache apache    309 2011-05-26 21:40 kpi-search.csv
-rw-r--r-- 1 apache apache    109 2011-05-26 21:40 kpi-viewarticle.csv
-rw-r--r-- 1 apache apache  35619 2011-05-26 21:40 search.log
-rw-r--r-- 1 apache apache  16268 2011-05-21 17:24 tasks.log

The observer effect

By adding additional disc usage on the server due to increased logging, we are adding to the overhead of the KPIs we would like to monitor. This is referred to as “the observer effect”:

Observer effect (information technology)

We always need to keep in mind that as we are observing, we are also having an impact to performance. Therefore we should be extremely selective about where we place KPIs to ensure they are not service impacting, i.e. keep their usage to a minimum.

Future plans

The KPI features that will be added to the Alpha Framework version 1.1 will be kept simple to begin with, but there are plans to increase their functionality at some point in the future, notably to add support for maximum performance thresholds and alarming (e-mail alerts) for when those thresholds are exceeded. A reporting frontend may also be added at some point, but it is not a priority given the amount of existing reporting tools like Jasper Reports which can easily generate professional looking reports from .csv files.

Updated 2022 : note that the above post was originally published in 2011, but is left here for archival purposes. I have fixed some external links above.