source: trunk/src/profiler.cc @ 306

// Copyright (C) 2012-2013 Kornel Kisielewicz
// This file is part of NV Libraries.
// For conditions of distribution and use, see copyright notice in nv.hh

#include "nv/profiler.hh"

#include <iomanip>
#include <ios>
#include "nv/time.hh"

using namespace nv;


profiler::profiler()
{
        m_root = new node( "root", nullptr );
        m_root->start();
        m_current = m_root;
}

profiler::~profiler()
{
        delete m_root;
}

void profiler::start_profile( const char* tag )
{
        if ( tag != m_current->m_tag )
        {
                m_current = m_current->request_child( tag );
        }
        m_current->start();
}

void profiler::stop_profile()
{
        if ( m_current->stop() )
        {
                m_current = m_current->get_parent();
        }
}

profiler::node::node( const char* tag, node* parent ) 
        : m_tag( tag )
        , m_parent( parent )
        , m_recusion( 0 )
        , m_calls( 0 )
        , m_start_time_us( 0 )
        , m_total_time_us( 0 )
{

}

profiler::node* profiler::node::request_child( const char* tag )
{
        auto it = m_children.find( tag );
        if ( it != m_children.end() ) 
                return it->second;
        else
        {
                node* result = new node( tag, this );
                m_children[ tag ] = result;
                return result;
        }
}

void profiler::node::start()
{
        m_calls++;
        m_recusion++;
        if ( m_recusion == 1 )
        {
                m_start_time_us = get_system_us();
        }
}

bool profiler::node::stop()
{
        m_recusion--;
        if ( m_recusion == 0 )
        {
                uint64 stop_time_us = get_system_us();
                uint64 elapsed_us   = stop_time_us - m_start_time_us;
                m_total_time_us     += elapsed_us;
                return true;
        }
        return false;
}


nv::profiler::node::~node()
{
        for ( const auto& pair : m_children )
        {
                delete pair.second;
        }
}


void profiler::log_report()
{
        m_root->stop();
        NV_LOG( LOG_INFO, "-- PROFILER REPORT -----------------------------------------" );
        NV_LOG( LOG_INFO, std::left << std::setw(24) << "TAG" 
                << std::setw(7) << "%PARNT" 
                << std::setw(7) << "CALLS" 
                << std::setw(10) << "TOTAL(ms)" 
                << std::setw(10) << "AVG(ms)" );
        log_node_children( "", m_root );
        NV_LOG( LOG_INFO, "-- PROFILER REPORT END -------------------------------------" );
        m_root->start();
}

void profiler::log_node_children( const std::string& ind, const node* n )
{
        for ( const auto& pair : n->m_children )
        {
                const node* c = pair.second;
                if ( c->m_calls > 0 )
                {
                        NV_LOG( LOG_INFO, std::left << std::setw(24) << ind + c->m_tag 
                                << std::setw(7) << std::setprecision(2) << std::fixed << ( (double)c->m_total_time_us / (double)c->m_parent->m_total_time_us ) * 100.0
                                << std::setw(7) << c->m_calls 
                                << std::setw(10) << std::setprecision(2) << std::fixed << c->m_total_time_us / 1000.f
                                << std::setw(10) << std::setprecision(2) << std::fixed << ( (double)c->m_total_time_us / (double)c->m_calls ) / 1000.f
                                );
                        if ( c->m_children.size() > 0 )
                        {
                                log_node_children( ind + "-", c );
                        }
                }
        }
}