perf_log.h

Go to the documentation of this file.

// The libMesh Finite Element Library.
// Copyright (C) 2002-2018 Benjamin S. Kirk, John W. Peterson, Roy H. Stogner

// This library is free software; you can redistribute it and/or
// modify it under the terms of the GNU Lesser General Public
// License as published by the Free Software Foundation; either
// version 2.1 of the License, or (at your option) any later version.

// This library 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
// Lesser General Public License for more details.

// You should have received a copy of the GNU Lesser General Public
// License along with this library; if not, write to the Free Software
// Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA  02111-1307  USA



#ifndef LIBMESH_PERFLOG_H
#define LIBMESH_PERFLOG_H


// Local includes
#include "libmesh/libmesh_common.h"

// C++ includes
#include <cstddef>
#include <map>
#include <stack>
#include <string>
#include <vector>
#include <sys/time.h>

namespace libMesh
{

class PerfData
{
public:

  PerfData () :
    tot_time(0.),
    tot_time_incl_sub(0.),
    tstart(),
    tstart_incl_sub(),
    count(0),
    open(false),
    called_recursively(0)
  {}


  double tot_time;

  double tot_time_incl_sub;

  struct timeval tstart;

  struct timeval tstart_incl_sub;

  unsigned int count;

  bool open;

  void   start ();
  void   restart ();
  double pause ();
  double pause_for(PerfData & other);
  double stopit ();

  int called_recursively;

protected:
  double stop_or_pause(const bool do_stop);
};




class PerfLog
{
public:

  PerfLog(const std::string & label_name="",
          const bool log_events=true);

  ~PerfLog();

  void clear();

  void disable_logging() { log_events = false; }

  void enable_logging() { log_events = true; }

  bool logging_enabled() const { return log_events; }

  void fast_push (const char * label,
                  const char * header="");

  void push (const char * label,
             const char * header="");

  void push (const std::string & label,
             const std::string & header="");

  void fast_pop (const char * label,
                 const char * header="");

  void pop (const char * label,
            const char * header="");

  void pop (const std::string & label,
            const std::string & header="");

  void start_event(const std::string & label,
                   const std::string & header="");

  void stop_event(const std::string & label,
                  const std::string & header="");

  void pause_event(const std::string & label,
                   const std::string & header="");

  void restart_event(const std::string & label,
                     const std::string & header="");

  std::string get_log() const;

  std::string get_info_header() const;

  std::string get_perf_info() const;

  void print_log() const;

  double get_elapsed_time() const;

  double get_active_time() const;

  PerfData get_perf_data(const std::string & label, const std::string & header="");

  typedef std::map<std::pair<const char *,
                             const char *>,
                   PerfData> log_type;
#ifdef LIBMESH_ENABLE_DEPRECATED
  const log_type & get_log_raw() const
  {
    libmesh_deprecated();
    return log;
  }
#endif

private:


  const std::string label_name;

  bool log_events;

  double total_time;

  struct timeval tstart;

  log_type log;

  std::stack<PerfData*> log_stack;

  static bool called;

  void split_on_whitespace(const std::string & input,
                           std::vector<std::string> & output) const;

  std::map<std::string, const char *> non_temporary_strings;
};



// ------------------------------------------------------------
// PerfData class member functions
inline
void PerfData::start ()
{
  this->count++;
  this->called_recursively++;
  gettimeofday (&(this->tstart), nullptr);
  this->tstart_incl_sub = this->tstart;
}



inline
void PerfData::restart ()
{
  gettimeofday (&(this->tstart), nullptr);
}



inline
double PerfData::pause ()
{
  return this->stop_or_pause(false);
}


inline
double PerfData::stop_or_pause(const bool do_stop)
{
  // save the start times, reuse the structure we have rather than create
  // a new one.
  const time_t
    tstart_tv_sec  = this->tstart.tv_sec,
    tstart_tv_usec = this->tstart.tv_usec;

  gettimeofday (&(this->tstart), nullptr);

  const double elapsed_time = (static_cast<double>(this->tstart.tv_sec  - tstart_tv_sec) +
                               static_cast<double>(this->tstart.tv_usec - tstart_tv_usec)*1.e-6);

  this->tot_time += elapsed_time;

  if (do_stop)
    {
      const double elapsed_time_incl_sub = (static_cast<double>(this->tstart.tv_sec  - this->tstart_incl_sub.tv_sec) +
                                            static_cast<double>(this->tstart.tv_usec - this->tstart_incl_sub.tv_usec)*1.e-6);

      this->tot_time_incl_sub += elapsed_time_incl_sub;
    }

  return elapsed_time;
}



inline
double PerfData::pause_for(PerfData & other)
{
  gettimeofday (&(other.tstart), nullptr);

  const double elapsed_time = (static_cast<double>(other.tstart.tv_sec  - this->tstart.tv_sec) +
                               static_cast<double>(other.tstart.tv_usec - this->tstart.tv_usec)*1.e-6);
  this->tot_time += elapsed_time;

  other.count++;
  other.called_recursively++;
  other.tstart_incl_sub = other.tstart;

  return elapsed_time;
}



inline
double PerfData::stopit ()
{
  // stopit is just similar to pause except that it decrements the
  // recursive call counter

  this->called_recursively--;
  return this->stop_or_pause(true);
}



// ------------------------------------------------------------
// PerfLog class inline member functions
inline
void PerfLog::fast_push (const char * label,
                         const char * header)
{
  if (this->log_events)
    {
      // Get a reference to the event data to avoid
      // repeated map lookups
      PerfData * perf_data = &(log[std::make_pair(header,label)]);

      if (!log_stack.empty())
        total_time += log_stack.top()->pause_for(*perf_data);
      else
        perf_data->start();
      log_stack.push(perf_data);
    }
}



inline
void PerfLog::fast_pop(const char * libmesh_dbg_var(label),
                       const char * libmesh_dbg_var(header))
{
  if (this->log_events)
    {
      libmesh_assert (!log_stack.empty());

#ifndef NDEBUG
      PerfData * perf_data = &(log[std::make_pair(header,label)]);
      if (perf_data != log_stack.top())
        {
          libMesh::err << "PerfLog can't pop (" << header << ',' << label << ')' << std::endl;
          libMesh::err << "From top of stack of running logs:" << std::endl;
          for (auto i : log)
            if (&(i.second) == log_stack.top())
              libMesh::err << '(' << i.first.first << ',' << i.first.second << ')' << std::endl;

          libmesh_assert_equal_to (perf_data, log_stack.top());
        }
#endif

      total_time += log_stack.top()->stopit();

      log_stack.pop();

      if (!log_stack.empty())
        log_stack.top()->restart();
    }
}



inline
double PerfLog::get_elapsed_time () const
{
  struct timeval tnow;

  gettimeofday (&tnow, nullptr);

  const double elapsed_time = (static_cast<double>(tnow.tv_sec  - tstart.tv_sec) +
                               static_cast<double>(tnow.tv_usec - tstart.tv_usec)*1.e-6);
  return elapsed_time;
}

inline
double PerfLog::get_active_time() const
{
  return total_time;
}

} // namespace libMesh



#endif // LIBMESH_PERFLOG_H