mariadb-columnstore-engine/utils/loggingcpp/stopwatch.cpp

/* Copyright (C) 2014 InfiniDB, Inc.

   This program is free software; you can redistribute it and/or
   modify it under the terms of the GNU General Public License
   as published by the Free Software Foundation; version 2 of
   the License.

   This program is distributed in the hope that it will be useful,
   but WITHOUT ANY WARRANTY; without even the implied warranty of
   MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
   GNU General Public License for more details.

   You should have received a copy of the GNU General Public License
   along with this program; if not, write to the Free Software
   Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston,
   MA 02110-1301, USA. */

//
// $Id$
//
// Timer class used to spit out times and percentages.  Temporarily lives in joblist.
// This is strictly a debugging utility class that accumulates times between .start() and
// .stop() calls for a particular string.  It can be useful in tdrivers.
//
// It outputs a report when finish() is called with
// the total times by string and their percentage of the total.  The total is tracked from
// the first time start() is called until finish() is called.  You should always match your
// start and stop calls up.
//
// This works fine as long as you don't use it with huge numbers of calls.  If you call start
// and stop too many times the overhead of the StopWatch class will start factoring in to your
// results.
//
// How to use:
//
// 	StopWatch timer;
// 	timer.start("Loop only");
// 	for(int i = 0; i < 6999075; i++)
// 	{
// 	}
// 	timer.stop("Loop only");
//
// 	timer.start("Loop Plus");
// 	for(int i = 0; i < 100000; i++)
// 	{
// 		timer.start("Inside loop");
// 		timer.stop("Inside loop");
// 	}
// 	timer.stop("Loop Plus");
// 	timer.finish();
//
// Produces this:
//
// Seconds  Percentage  Calls      Description
// 0.02865  9.377%      1          Loop only
// 0.27680  90.59%      1          Loop Plus
// 0.12138  39.72%      100000     Inside loop
//
// 0.30553  100  %      1          Total
//
// Note that you can have overlapping timers which will make your percentages add up to more than 100%.
#include <iostream>
#include <fstream>
#include <list>
#include <sstream>
#include <time.h>
#include <sys/time.h>
#include <vector>
#include <stdexcept>
#include <sys/types.h>
#include <cstring>
#include <stdint.h>
#include "stopwatch.h"
using namespace std;

namespace logging
{

void StopWatch::stop(const string& message)
{
    stop(message, 1);
}

bool StopWatch::stop(const string& message, const int limit)
{
    gettimeofday(&fTvLast, 0);
    fOpenCalls--;
    bool found = false;
    uint32_t idx = 0;

    for (uint32_t i = 0; i < fProcessStats.size(); i++)
    {
        if (fProcessStats[i].fProcess == message)
        {
            idx = i;
            found = true;
            break;
        }
    }

    if (!found)
    {
        //throw std::runtime_error("StopWatch::stop " + message + " called without calling start first.");
        std::cerr << "StopWatch receiving STOP for unknown event: " << message << std::endl;
        return false;
    }

    fProcessStats[idx].processStop();

    if (fProcessStats[idx].fStopCount >= limit)
        return true;

    return false;
}

void StopWatch::start(const string& message)
{
    fOpenCalls++;
    gettimeofday(&fTvLast, 0);
    bool found = false;
    uint32_t idx = 0;
    ProcessStats processStats;

    if (!fStarted)
    {
        fStarted = true;
        gettimeofday(&fTvStart, 0);
    }

    for (uint32_t i = 0; i < fProcessStats.size(); i++)
    {
        if (fProcessStats[i].fProcess == message)
        {
            idx = i;
            found = true;
            break;
        }
    }

    if (!found)
    {
        fProcessStats.push_back(processStats);
        idx = fProcessStats.size() - 1;
    }

    fProcessStats[idx].fProcess = message;
    fProcessStats[idx].processStart();
}

void StopWatch::finish()
{
    ostringstream oss;

    oss << endl;
    oss << "Seconds      Percentage        Calls      Description" << endl;

    // total seconds elapsed
    double totalSeconds = 1.0;

    // Add a last entry into the vector for total.
    ProcessStats total;
    total.fProcess = "Total";

    if (fProcessStats.size() > 0)
    {
        // Calculate the total seconds elapsed.
        totalSeconds =
            (fTvLast.tv_sec + (fTvLast.tv_usec / 1000000.0)) -
            (fTvStart.tv_sec + (fTvStart.tv_usec / 1000000.0));
        total.fTotalSeconds = totalSeconds;
        total.fStartCount   = 1;
    }
    else
    {
        total.fTotalSeconds = 0.0;
        total.fStartCount   = 0;
    }

    fProcessStats.push_back(total);

    for (uint32_t i = 0; i < fProcessStats.size(); i++)
    {

        if (i == (fProcessStats.size() - 1))
        {
            oss << endl;
        }

        // Seconds.
        string seconds;
        ostringstream ossTemp;
        ossTemp << fProcessStats[i].fTotalSeconds;
        seconds = ossTemp.str();
        seconds.resize(11, ' ');
        oss << seconds << "  ";

        // Percentage.
        string percentage;
        ossTemp.str(""); // clear the stream.
        ossTemp << (fProcessStats[i].fTotalSeconds / totalSeconds) * 100.0;
        percentage = ossTemp.str();
        percentage.resize(11, ' ');
        oss << percentage << "%      ";

        // Times Initiated.
        ossTemp.str(""); // clear the stream.
        ossTemp << fProcessStats[i].fStartCount;
        string timesInitiated = ossTemp.str();
        timesInitiated.resize(10, ' ');
        oss << timesInitiated << " ";

        // Description.
        if (fId >= 0)
            oss << fId << ": " << fProcessStats[i].fProcess << endl;
        else
            oss << fProcessStats[i].fProcess << endl;
    }

    if (fOutputToFile)
    {

        ofstream profLog;
        profLog.open(fLogFile.c_str(), std::ios::app);

        // Output the date and time.
        time_t t = time(0);
        char timeString[50];
        ctime_r(&t, timeString);
        timeString[ strlen(timeString) - 1 ] = '\0';
        profLog << endl << timeString;

        // Output the stopwatch info.
        profLog << oss.str();
    }
    else
    {
        cout << oss.str();
    }

    // Clear everything out.
    fStarted = false;
    fProcessStats.clear();

}

} // end of logging namespace