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();
}

}  // namespace logging