CTimeLogger.cpp

Go to the documentation of this file.

/* +------------------------------------------------------------------------+
   |                     Mobile Robot Programming Toolkit (MRPT)            |
   |                          http://www.mrpt.org/                          |
   |                                                                        |
   | Copyright (c) 2005-2017, Individual contributors, see AUTHORS file     |
   | See: http://www.mrpt.org/Authors - All rights reserved.                |
   | Released under BSD License. See details in http://www.mrpt.org/License |
   +------------------------------------------------------------------------+ */

#include "base-precomp.h"  // Precompiled headers

#include <mrpt/utils/CTimeLogger.h>
#include <mrpt/utils/CFileOutputStream.h>
#include <mrpt/system/string_utils.h>

#include <iostream>

using namespace mrpt;
using namespace mrpt::utils;
using namespace mrpt::system;
using namespace std;

struct MyGlobalProfiler : public mrpt::utils::CTimeLogger
{
        MyGlobalProfiler() : mrpt::utils::CTimeLogger("MRPT_global_profiler") {}
        ~MyGlobalProfiler()
        {
                if (!m_data.empty())
                {
                        const std::string sFil("mrpt-global-profiler.csv");
                        this->saveToCSVFile(sFil);
                        std::cout << "[MRPT global profiler] Write stats to: " << sFil
                                          << std::endl;
                }
        }
};
MyGlobalProfiler global_profiler;

namespace mrpt
{
namespace utils
{
CTimeLogger& global_profiler_getref() noexcept { return global_profiler; }
void global_profiler_enter(const char* func_name) noexcept
{
        global_profiler.enter(func_name);
}
void global_profiler_leave(const char* func_name) noexcept
{
        global_profiler.leave(func_name);
}
}
}

CTimeLogger::CTimeLogger(
        bool enabled /*=true*/, const std::string& name /*=""*/)
        : COutputLogger("CTimeLogger"), m_tictac(), m_enabled(enabled), m_name(name)
{
        m_tictac.Tic();
}

CTimeLogger::~CTimeLogger()
{
        // Dump all stats:
        if (!m_data.empty())  // If logging is disabled, do nothing...
                dumpAllStats();
}

CTimeLogger::CTimeLogger(const CTimeLogger& o)
        : COutputLogger(o),
          m_enabled(o.m_enabled),
          m_name(o.m_name),
          m_data(o.m_data)
{
}
CTimeLogger& CTimeLogger::operator=(const CTimeLogger& o)
{
        COutputLogger::operator=(o);
        m_enabled = o.m_enabled;
        m_name = o.m_name;
        m_data = o.m_data;
        return *this;
}
CTimeLogger::CTimeLogger(CTimeLogger&& o)
        : COutputLogger(o),
          m_enabled(o.m_enabled),
          m_name(o.m_name),
          m_data(o.m_data)
{
}
CTimeLogger& CTimeLogger::operator=(CTimeLogger&& o)
{
        COutputLogger::operator=(o);
        m_enabled = o.m_enabled;
        m_name = o.m_name;
        m_data = o.m_data;
        return *this;
}

void CTimeLogger::clear(bool deep_clear)
{
        if (deep_clear)
                m_data.clear();
        else
        {
                for (auto& e : m_data) e.second = TCallData();
        }
}

std::string aux_format_string_multilines(const std::string& s, const size_t len)
{
        std::string ret;

        for (size_t p = 0; p < s.size(); p += len)
        {
                ret += rightPad(s.c_str() + p, len, true);
                if (p + len < s.size()) ret += "\n";
        }
        return ret;
}

void CTimeLogger::getStats(std::map<std::string, TCallStats>& out_stats) const
{
        out_stats.clear();
        for (const auto e : m_data)
        {
                TCallStats& cs = out_stats[e.first];
                cs.min_t = e.second.min_t;
                cs.max_t = e.second.max_t;
                cs.total_t = e.second.mean_t;
                cs.mean_t = e.second.n_calls ? e.second.mean_t / e.second.n_calls : 0;
                cs.n_calls = e.second.n_calls;
                cs.last_t = e.second.last_t;
        }
}

std::string CTimeLogger::getStatsAsText(const size_t column_width) const
{
        std::string stats_text;
        std::string name_tmp = m_name.size() ? " " + m_name + ": " : " ";
        std::string mrpt_string = "MRPT CTimeLogger report ";

        std::string top_header(name_tmp + mrpt_string);
        // append dashes to the header to reach column_width
        {
                int space_to_fill = top_header.size() < column_width
                                                                ? (column_width - top_header.size()) / 2
                                                                : 2;
                std::string dashes_half(space_to_fill, '-');
                top_header = dashes_half + top_header + dashes_half;
                if (dashes_half.size() % 2)
                {  // what if column_width-top_header.size() is odd?
                        top_header += '-';
                }
        }

        std::string middle_header(
                "           FUNCTION                         #CALLS  MIN.T  MEAN.T "
                "MAX.T TOTAL ");
        std::string bottom_header(column_width, '-');

        stats_text += top_header + "\n";
        stats_text += middle_header + "\n";
        stats_text += bottom_header + "\n";

        // for all the timed sections
        for (const auto i : m_data)
        {
                const string sMinT = unitsFormat(i.second.min_t, 1, false);
                const string sMaxT = unitsFormat(i.second.max_t, 1, false);
                const string sTotalT = unitsFormat(i.second.mean_t, 1, false);
                const string sMeanT = unitsFormat(
                        i.second.n_calls ? i.second.mean_t / i.second.n_calls : 0, 1,
                        false);

                stats_text += format(
                        "%s %7u %6s%c %6s%c %6s%c %6s%c\n",
                        aux_format_string_multilines(i.first, 39).c_str(),
                        static_cast<unsigned int>(i.second.n_calls), sMinT.c_str(),
                        i.second.has_time_units ? 's' : ' ', sMeanT.c_str(),
                        i.second.has_time_units ? 's' : ' ', sMaxT.c_str(),
                        i.second.has_time_units ? 's' : ' ', sTotalT.c_str(),
                        i.second.has_time_units ? 's' : ' ');
        }

        std::string footer(top_header);
        stats_text += footer + "\n";

        return stats_text;
}

void CTimeLogger::saveToCSVFile(const std::string& csv_file) const
{
        std::string s;
        s += "FUNCTION, #CALLS, LAST.T, MIN.T, MEAN.T, MAX.T, TOTAL.T\n";
        for (const auto& i : m_data)
        {
                s += format(
                        "\"%s\",\"%7u\",\"%e\",\"%e\",\"%e\",\"%e\",\"%e\"\n",
                        i.first.c_str(), static_cast<unsigned int>(i.second.n_calls),
                        i.second.last_t, i.second.min_t,
                        i.second.n_calls ? i.second.mean_t / i.second.n_calls : 0,
                        i.second.max_t, i.second.mean_t);
        }
        CFileOutputStream(csv_file).printf("%s", s.c_str());
}

void CTimeLogger::dumpAllStats(const size_t column_width) const
{
        MRPT_LOG_INFO_STREAM("dumpAllStats:\n" << getStatsAsText(column_width));
}

void CTimeLogger::do_enter(const char* func_name)
{
        const string s = func_name;
        TCallData& d = m_data[s];

        d.n_calls++;
        d.open_calls.push(0);  // Dummy value, it'll be written below
        d.open_calls.top() = m_tictac.Tac();  // to avoid possible delays.
}

double CTimeLogger::do_leave(const char* func_name)
{
        const double tim = m_tictac.Tac();

        const string s = func_name;
        TCallData& d = m_data[s];

        if (!d.open_calls.empty())
        {
                const double At = tim - d.open_calls.top();
                d.open_calls.pop();

                d.last_t = At;
                d.mean_t += At;
                if (d.n_calls == 1)
                {
                        d.min_t = At;
                        d.max_t = At;
                }
                else
                {
                        mrpt::utils::keep_min(d.min_t, At);
                        mrpt::utils::keep_max(d.max_t, At);
                }
                return At;
        }
        else
                return 0;  // This shouldn't happen!
}

void CTimeLogger::registerUserMeasure(
        const char* event_name, const double value)
{
        if (!m_enabled) return;
        const string s = event_name;
        TCallData& d = m_data[s];

        d.has_time_units = false;
        d.last_t = value;
        d.mean_t += value;
        if (++d.n_calls == 1)
        {
                d.min_t = value;
                d.max_t = value;
        }
        else
        {
                mrpt::utils::keep_min(d.min_t, value);
                mrpt::utils::keep_max(d.max_t, value);
        }
}

CTimeLogger::TCallData::TCallData()
        : n_calls(0), min_t(0), max_t(0), mean_t(0), last_t(0), has_time_units(true)
{
}

double CTimeLogger::getMeanTime(const std::string& name) const
{
        TDataMap::const_iterator it = m_data.find(name);
        if (it == m_data.end())
                return 0;
        else
                return it->second.n_calls ? it->second.mean_t / it->second.n_calls : 0;
}
double CTimeLogger::getLastTime(const std::string& name) const
{
        TDataMap::const_iterator it = m_data.find(name);
        if (it == m_data.end())
                return 0;
        else
                return it->second.last_t;
}

CTimeLoggerEntry::CTimeLoggerEntry(
        const CTimeLogger& logger, const char* section_name)
        : m_logger(const_cast<CTimeLogger&>(logger)), m_section_name(section_name)
{
        m_logger.enter(m_section_name);
}
CTimeLoggerEntry::~CTimeLoggerEntry() { m_logger.leave(m_section_name); }