perf_log.h

Go to the documentation of this file.

// The libMesh Finite Element Library.
// Copyright (C) 2002-2025 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 <deque>
#include <memory>
#ifdef LIBMESH_HAVE_SYS_TIME_H
#include <sys/time.h> // gettimeofday() on Unix
#endif
#ifndef LIBMESH_HAVE_GETTIMEOFDAY
#include "libmesh/win_gettimeofday.h" // gettimeofday() on Windows
#endif

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

  PerfData & operator += (const PerfData & other)
  {
    libmesh_assert(!open);
    tot_time += other.tot_time;
    tot_time_incl_sub += other.tot_time_incl_sub;
    count += other.count;

    return *this;
  }

  int called_recursively;

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




class PerfLog
{
public:

  PerfLog(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 enable_summarized_logs() { summarize_logs = true; }

  void disable_summarized_logs() { summarize_logs = false; }

  bool summarized_logs_enabled() { return summarize_logs; }

  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="") noexcept;

  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;

private:


  const std::string label_name;

  bool log_events;

  bool summarize_logs;

  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, std::unique_ptr<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)) noexcept
{
  if (this->log_events)
    {
      // If there's nothing on the stack, then we can't pop anything. Previously we
      // asserted that the log_stack was not empty, but we should not throw from
      // this function, so instead just return in that case.
      if (log_stack.empty())
        return;

#ifndef NDEBUG
      // In debug mode, we carefully check that before popping the stack,
      // we have the correct event.

      // Get pointer to corresponding PerfData, or nullptr if it does not exist.
      auto it = log.find(std::make_pair(header, label));
      PerfData * perf_data = (it == log.end()) ? nullptr : &(it->second);

      // If this event is not found in the log, then it could indicate
      // that you have a STOP_LOG(a,b) without a corresponding
      // START_LOG(a,b) call. We don't pop anything from the log_stack
      // in this case.
      if (!perf_data)
        {
          libMesh::err << "PerfLog can't pop (" << header << ',' << label << ')' << std::endl;
          libMesh::err << "No such event was found in the log, you may have a mismatched START/STOP_LOG statement." << std::endl;
          return;
        }

      if (perf_data != log_stack.top())
        {
          // We've been asked to pop an event which is not at the
          // top() of the log_stack. The event may be deeper in the
          // stack instead, so search for it now. If we find it, we'll
          // pop all intermediate items off the stack (abandoning any
          // attempt to time them accurately) and let the optimized
          // code path take over from there.
          std::deque<PerfData*> tmp_stack;

          while (!log_stack.empty() && perf_data != log_stack.top())
            {
              tmp_stack.push_front(log_stack.top());
              log_stack.pop();
            }

          // If we exhaustively searched the log_stack without finding
          // the event, we can't do anything else so just put
          // everything back and return, not doing anything for this
          // event.
          if (log_stack.empty())
            {
              while (!tmp_stack.empty())
                {
                  log_stack.push(tmp_stack.back());
                  tmp_stack.pop_back();
                }

              return;
            }
        }
#endif

      // In optimized mode, we just pop from the top of the stack and
      // resume timing the next entry.
      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