Changeset 365 for trunk/src/core

Timestamp:

05/16/15 17:40:16 (10 years ago)

Author:

epyon

Message:

• overhaul of logging: no longer stream operated no longer using STL no memory allocation shorthand macros fast file and console I/O

Location:

trunk

Files:

• . (modified) (1 prop)
• src/core/io_event.cc (modified) (1 diff)
• src/core/library.cc (modified) (3 diffs)
• src/core/logger.cc (modified) (6 diffs)
• src/core/profiler.cc (modified) (4 diffs)
• src/core/string.cc (added)

trunk/src/core/io_event.cc

@@ -46 +46 @@
 void nv::log_event( const io_event& e )
 {
-        NV_LOG( LOG_INFO, "Event: " << get_io_event_name( e.type ) );
+        NV_LOG_INFO( "Event: ", get_io_event_name( e.type ) );
 }
 

trunk/src/core/library.cc

@@ -71 +71 @@
         return true;
     }
-    NV_LOG( LOG_NOTICE, "library : loading '" + m_name + "'..." );
+    NV_LOG_NOTICE( "library : loading '", m_name, "'..." );
 
     string name = m_name;
@@ -86 +86 @@
     if ( m_handle == NULL )
     {
-                NV_LOG( LOG_NOTICE, "library : '" + name + "' failed to open." );
+                NV_LOG_NOTICE( "library : '", name, "' failed to open." );
                 return false;
     }
-    NV_LOG( LOG_NOTICE, "library : '" + name + "' loaded." );
+    NV_LOG_NOTICE( "library : '", name, "' loaded." );
         return true;
 }
@@ -117 +117 @@
     if ( NV_LIB_CLOSE( (NV_LIB_HANDLE)m_handle ) )
     {
-        NV_LOG( LOG_ERROR, "library : can't close library '" + m_name + "'!" );
+        NV_LOG_ERROR( "library : can't close library '", m_name, "'!" );
     }
     m_handle = NULL;

trunk/src/core/logger.cc

@@ -6 +6 @@
 
 #include "nv/core/common.hh"
-#include <iostream>
-#include <utility>
-#include <algorithm>
-#include <fstream>
-#include <ctime>
+#include "nv/core/time.hh"
 #include <cstdio>
-#include "nv/core/exception.hh"
 #if NV_PLATFORM == NV_WINDOWS
 #define WIN32_LEAN_AND_MEAN
@@ -89 +84 @@
 
 // log function
-void logger::log( log_level level, const std::string& message )
-{
-        // get the iterator to the beginning of the log_sink list
-        log_sink_list::reverse_iterator it = m_log_sinks.rbegin();
-
-        // iterate
-        while ( it != m_log_sinks.rend() )
-        {
-                // if we have a log sink with high enough level...
-                if ( it->first >= level )
+void logger::log( log_level level, const string_ref& message )
+{
+        for ( auto& sink_info : m_log_sinks )
+        {
+                if ( sink_info.sink && (sink_info.level >= (uint32)level) )
                 {
                         // log and iterate
-                        it->second->log( level, message );
+                        sink_info.sink->log( level, message );
                 }
-                else 
+        }
+}
+
+// add a new sink
+void logger::add_sink( log_sink* sink, int level )
+{
+        // add a sink
+        for ( auto& sink_info : m_log_sinks )
+        {
+                if ( sink_info.sink == nullptr )
                 {
-                        // otherwise return, the list is sorted by log level
+                        sink_info.sink  = sink;
+                        sink_info.level = (uint32)level;
                         return;
                 }
-                ++it;
-        }
-}
-
-// add a new sink
-void logger::add_sink( log_sink* sink, int level )
-{
-        // add a sink
-        m_log_sinks.push_back( std::make_pair( log_level(level), sink ) );
-        // and sort the list (default sort of pairs is by first element)
-        m_log_sinks.sort();
+        }
+        NV_ASSERT( false, "ran out of log sink space!" );
 }
 
@@ -124 +115 @@
 bool logger::remove_sink( log_sink* sink )
 {
-        // get the iterator to the beginning of the log_sink list
-        log_sink_list::iterator it = m_log_sinks.begin();
-
-        // iterate
-        while ( it != m_log_sinks.end() )
-        {
-                // found?
-                if ( it->second == sink ) 
+        for ( auto& sink_info : m_log_sinks )
+        {
+                if ( sink_info.sink == sink )
                 {
-                        // erase and return true to report success
-                        m_log_sinks.erase(it);
+                        delete sink_info.sink;
+                        sink_info.sink = nullptr;
                         return true;
                 }
-                ++it;
-        }
-
+        }
         // not found, return false
         return false;
@@ -147 +131 @@
 logger::~logger()
 {
-        // while we have sinks
-        while ( !m_log_sinks.empty() )
-        {
-                // delete the last one
-                delete m_log_sinks.back().second;
-                // and pop it
-                m_log_sinks.pop_back();
+        // delete all sinks
+        for ( auto& sink_info : m_log_sinks )
+        {
+                delete sink_info.sink;
         }
 }
@@ -159 +140 @@
 
 // console logging
-void log_console_sink::log( log_level level, const std::string& message )
-{
-        if (m_color) 
-        {
-#if NV_PLATFORM == NV_WINDOWS 
-                SetConsoleTextAttribute( m_handle, FOREGROUND_INTENSITY );
-                std::cout << timestamp() << " [";
-                SetConsoleTextAttribute( m_handle, log_color[ (level) / 10 ] );
-                std::cout << NV_LOG_LEVEL_NAME_PAD(level);
-                SetConsoleTextAttribute( m_handle, FOREGROUND_INTENSITY );
-                std::cout << "] ";
-                SetConsoleTextAttribute( m_handle, FOREGROUND_INTENSITY | FOREGROUND_RED | FOREGROUND_GREEN | FOREGROUND_BLUE );
-                std::cout << message << std::endl;
-#else
-                std::cout << "\33[30;1m" << timestamp() << " [" << log_color[ (level) / 10 ] << NV_LOG_LEVEL_NAME_PAD(level) << "\33[30;1m] \33[37;1m" << message << std::endl;
-#endif
-        }
+void log_console_sink::log( log_level level, const string_ref& message )
+{
+#if NV_PLATFORM == NV_WINDOWS 
+        if ( m_color ) SetConsoleTextAttribute( m_handle, FOREGROUND_INTENSITY );
+        string_ref stamp( timestamp() );
+        WriteConsole( m_handle, stamp.data(), stamp.size(), nullptr, nullptr );
+        WriteConsole( m_handle, " [", 2, nullptr, nullptr );
+        if (m_color) SetConsoleTextAttribute( m_handle, log_color[( level ) / 10] );
+        WriteConsole( m_handle, NV_LOG_LEVEL_NAME_PAD( level ), 8, nullptr, nullptr );
+        if ( m_color ) SetConsoleTextAttribute( m_handle, FOREGROUND_INTENSITY );
+        WriteConsole( m_handle, "] ", 2, nullptr, nullptr );
+        if ( m_color ) SetConsoleTextAttribute( m_handle, FOREGROUND_INTENSITY | FOREGROUND_RED | FOREGROUND_GREEN | FOREGROUND_BLUE );
+        WriteConsole( m_handle, message.data(), message.size(), nullptr, nullptr );
+        WriteConsole( m_handle, "\n", 1, nullptr, nullptr );
+#else
+        if ( m_color ) fwrite( "\33[30;1m", 7, 1, stdout );
+        fwrite( stamp.data(), stamp.size(), 1, stdout );
+        fwrite( " [", 2, 1, stdout );
+        if ( m_color )
+        {
+                const char* lcolor = log_color[( level ) / 10];
+                fwrite( lcolor, strlen(lcolor), 1, stdout );
+        }
+        fwrite( NV_LOG_LEVEL_NAME_PAD( level ), 8, 1, stdout );
+        if ( m_color )
+                fwrite( "\33[30;1m] \33[37;1m", 16, 1, stdout );
         else
-        {
-        std::cout << timestamp() << " [" << NV_LOG_LEVEL_NAME_PAD(level) << "] " << message << std::endl;
-        }
-}
-
-// stream logging
-void log_stream_sink::log( log_level level, const std::string& message )
-{
-        // if flushing is enabled
-        if ( m_flush )
-        {
-                // write and flush using std::endl
-                *m_stream << timestamp() << " [" << NV_LOG_LEVEL_NAME(level) << "] " << message << std::endl;
-        }
-        else
-        {
-                // write and end with "\n" (no flush)
-                *m_stream << timestamp() << " [" << NV_LOG_LEVEL_NAME(level) << "] " << message << "\n";
-        }
-}
-
-// file logging
-log_file_sink::log_file_sink( const std::string file_name, bool flush_always /*= true */ )
-        : log_stream_sink( nullptr, flush_always )
-{
-        // create the stream manually
-        std::ofstream* fstream = new std::ofstream( file_name );
-
-        // check if it's open
-        if ( !fstream->is_open() )
-        {
-                // throw if not open
-                NV_THROW( runtime_error, "Could not open file \""+file_name+"\" for logging!" );
-        }
-
-        m_stream = fstream;
-}
-
-// file logger destructor
-log_file_sink::~log_file_sink()
-{
-        // close the file
-        dynamic_cast< std::ofstream* >(m_stream)->close();
-        // dispose of the stream
-        delete m_stream;
-}
+                fwrite( "] ", 2, 1, stdout );
+        fwrite( stamp.data(), stamp.size(), 1, stdout );
+        fwrite( "\n", 1, 1, stdout );
+#endif
+}
+
+// handle logging
+void log_handle_sink::log( log_level level, const string_ref& message )
+{
+        string_ref stamp( timestamp() );
+#if 0 // NV_PLATFORM == NV_WINDOWS
+        // Turns out WriteFile on Windows is unbuffered and quite slower than fwrite 
+        // due to this fact -- especially UNUSABLE with manual FlushFileBuffers
+        // If we want to get rid of C runtime, this would need a buffered I/O layer.
+        DWORD unused = 0;
+        WriteFile( m_handle, stamp.data(), stamp.size(), &unused, nullptr );
+        WriteFile( m_handle, " [", 2, &unused, nullptr );
+        WriteFile( m_handle, NV_LOG_LEVEL_NAME_PAD( level ), 8, &unused, nullptr );
+        WriteFile( m_handle, "] ", 2, &unused, nullptr );
+        WriteFile( m_handle, message.data(), message.size(), &unused, nullptr );
+        WriteFile( m_handle, "\n", 1, &unused, nullptr );
+        //if ( m_flush ) FlushFileBuffers( m_handle );
+#else
+        fwrite( stamp.data(), stamp.size(), 1, (FILE*)m_handle );
+        fwrite( " [", 2, 1, (FILE*)m_handle );
+        fwrite( NV_LOG_LEVEL_NAME_PAD( level ), 8, 1, (FILE*)m_handle );
+        fwrite( "] ", 2, 1, (FILE*)m_handle );
+        fwrite( message.data(), message.size(), 1, (FILE*)m_handle );
+        fwrite( "\n", 1, 1, (FILE*)m_handle );
+        if ( m_flush ) fflush( (FILE*)m_handle );
+#endif
+}
+
+nv::log_file_sink::log_file_sink( const string_ref& file_name, bool flush_always /*= true */ )
+        : log_handle_sink( nullptr, flush_always )
+{
+#if 0 // NV_PLATFORM == NV_WINDOWS
+        // See comments in log_handle_sink
+        HANDLE handle = CreateFile( file_name.data(), GENERIC_WRITE, 0, nullptr, CREATE_ALWAYS, FILE_ATTRIBUTE_NORMAL, nullptr );
+        if ( INVALID_HANDLE_VALUE == handle )
+        {
+                NV_ASSERT( false, "invalid log handle" );
+        }
+        m_handle = handle;
+#else
+        m_handle = fopen( file_name.data(), "w" );
+#endif
+}
+
+nv::log_file_sink::~log_file_sink()
+{
+#if 0 // NV_PLATFORM == NV_WINDOWS
+        // See comments in log_handle_sink
+        CloseHandle( m_handle );
+#else
+        fclose( (FILE*) m_handle );
+#endif
+}
+
 
 nv::log_console_sink::log_console_sink( bool coloring )
@@ -234 +237 @@
 }
 
-const char* nv::log_sink::timestamp() const
-{
-        std::clock_t time = std::clock();
-        unsigned int secs = (unsigned int)(time / CLOCKS_PER_SEC);
-        unsigned int mm   = (unsigned int)(time*100 / CLOCKS_PER_SEC) % 100;
+string_ref nv::log_sink::timestamp() const
+{
+        uint32 ms = get_system_ms();
+        unsigned int secs = (unsigned int)(ms / 1000);
+        unsigned int mm   = (unsigned int)( ms * 100 / 1000 ) % 100;
         unsigned int h    = (unsigned int)(secs / (60*60));
         unsigned int m    = (unsigned int)(secs / 60) % 60;
         unsigned int s    = secs % 60;
-        static char buffer[128];
-#if NV_PLATFORM == NV_WINDOWS 
-        sprintf_s( buffer, 128, "%02d:%02d:%02d.%02d", h, m, s, mm );
-#else
-        sprintf( buffer, "%02d:%02d:%02d.%02d", h, m, s, mm );
+        static char buffer[16];
+#if NV_PLATFORM == NV_WINDOWS 
+        sprintf_s( buffer, 16, "%02d:%02d:%02d.%02d", h, m, s, mm );
+#else
+        snprintf( buffer, 16, "%02d:%02d:%02d.%02d", h, m, s, mm );
 #endif
         buffer[11] = '\0';
-        return buffer;
-}
-
-const char* nv::log_sink::level_name( log_level level ) const
+        return string_ref( buffer, 10 );
+}
+
+string_ref nv::log_sink::level_name( log_level level ) const
 {
         return NV_LOG_LEVEL_NAME( level );
 }
 
-const char* nv::log_sink::padded_level_name( log_level level ) const
-{
-        return NV_LOG_LEVEL_NAME_PAD( level );
-}
+string_ref nv::log_sink::padded_level_name( log_level level ) const
+{
+        return string_ref( NV_LOG_LEVEL_NAME_PAD( level ), 8 );
+}
+

trunk/src/core/profiler.cc

@@ -8 +8 @@
 #include <ios>
 #include "nv/core/time.hh"
+#include "nv/core/logging.hh"
 
 using namespace nv;
@@ -97 +98 @@
 }
 
-
 void profiler::log_report()
 {
         m_root->stop();
-        NV_LOG( LOG_INFO, "-- PROFILER REPORT -----------------------------------------" );
-        NV_LOG( LOG_INFO, std::left << std::setw(24) << "TAG" 
+        NV_LOG_INFO( "-- PROFILER REPORT -----------------------------------------" );
+        NV_LOG_STREAM( LOG_INFO, std::left << std::setw(24) << "TAG" 
                 << std::setw(7) << "%PARNT" 
                 << std::setw(7) << "CALLS" 
@@ -108 +108 @@
                 << std::setw(10) << "AVG(ms)" );
         log_node_children( "", m_root );
-        NV_LOG( LOG_INFO, "-- PROFILER REPORT END -------------------------------------" );
+        NV_LOG_INFO( "-- PROFILER REPORT END -------------------------------------" );
         m_root->start();
 }
@@ -119 +119 @@
                 if ( c->m_calls > 0 )
                 {
-                        NV_LOG( LOG_INFO, std::left << std::setw(24) << ind + c->m_tag 
+                        NV_LOG_STREAM( 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