source: trunk/src/core/profiler.cc @ 371

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

#include "nv/core/profiler.hh"

#include "nv/core/time.hh"
#include "nv/core/logging.hh"
#include <cstdio>
#include <cstdlib>

using namespace nv;

#ifdef NV_MSVC
#define snprintf sprintf_s
#endif

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 string_ref& 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 string_ref& tag, node* parent )
        : m_tag( tag.to_string() )
        , 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 string_ref& tag )
{
        std::string stag( tag.to_string() );
        auto it = m_children.find( stag );
        if ( it != m_children.end() ) 
                return it->second;
        else
        {
                node* result = new node( tag, this );
                m_children[ stag ] = 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_INFO( "-- PROFILER REPORT -------------------------------------" );
        char buffer[128];
        snprintf( buffer, 128, "%-23s %6s %6s %9s %6s", "TAG", "%PARNT", "CALLS", "TOTAL(ms)", "AVG(ms)" );
        NV_LOG_INFO( string_ref( buffer, strlen(buffer) ) );
        log_node_children( 0, m_root );
        NV_LOG_INFO( "-- PROFILER REPORT END ---------------------------------" );
        m_root->start();
}

void profiler::log_node_children( uint32 indent, const node* n )
{
        char buffer[128];
        for ( const auto& pair : n->m_children )
        {
                const node* c = pair.second;
                if ( c->m_calls > 0 )
                {
                        double pparent  = ( (double)c->m_total_time_us / (double)c->m_parent->m_total_time_us ) * 100.f;
                        int calls       = c->m_calls;
                        double total_ms = c->m_total_time_us / 1000.f;
                        double avg_ms   = ( (double)c->m_total_time_us / (double)c->m_calls ) / 1000.f;
                        if ( indent > 0 ) memset( buffer, '-', indent );
                        snprintf( buffer + indent, 128 - indent, "%*.*s %6.2f %6d %9.2f %6.2f", indent - 23, 23 - indent,
                                c->m_tag.c_str(), pparent, calls, total_ms, avg_ms );
                        NV_LOG_INFO( string_ref( buffer, strlen( buffer ) ) );
                        if ( c->m_children.size() > 0 )
                        {
                                log_node_children( indent + 1, c );
                        }
                }
        }
}