diff --git a/src/libs/CMakeLists.txt b/src/libs/CMakeLists.txt index 26177be3f..49be02e31 100644 --- a/src/libs/CMakeLists.txt +++ b/src/libs/CMakeLists.txt @@ -2,13 +2,9 @@ # Project developers. See top-level LICENSE AND COPYRIGHT files for dates and # other details. No copyright assignment is required to contribute to Ascent. - -################################ -# Add flow -################################ -add_subdirectory(flow) - +####################################### # display info about optional features +####################################### if(ENABLE_APCOMP) message(STATUS "Building APComp (ENABLE_APCOMP=ON)") else() @@ -40,6 +36,11 @@ add_subdirectory(png_utils) ################################ add_subdirectory(logging) +################################ +# Add flow +################################ +add_subdirectory(flow) + ################################ # Add ap comp ################################ diff --git a/src/libs/logging/CMakeLists.txt b/src/libs/logging/CMakeLists.txt index d68127729..0d93cd9d1 100644 --- a/src/libs/logging/CMakeLists.txt +++ b/src/libs/logging/CMakeLists.txt @@ -4,12 +4,14 @@ set(ascent_logging_headers ascent_logging.hpp + ascent_logging_timer.hpp ascent_annotations.hpp ascent_logging_exports.h ) set(ascent_logging_sources ascent_logging.cpp + ascent_logging_timer.cpp ascent_annotations.cpp ) diff --git a/src/libs/logging/ascent_logging.cpp b/src/libs/logging/ascent_logging.cpp index 3cd942ffe..d16cf1613 100644 --- a/src/libs/logging/ascent_logging.cpp +++ b/src/libs/logging/ascent_logging.cpp @@ -31,8 +31,8 @@ using namespace conduit; namespace ascent { -Logger *Logger::m_active_logger = nullptr; -std::map Logger::m_loggers; +Logger Logger::m_instance; +Logger *Logger::m_active_instance = nullptr; std::vector Logger::m_level_strings = {"unset", "debug", "info", @@ -60,14 +60,15 @@ Logger::Scope::~Scope() } } - //----------------------------------------------------------------------------- Logger::Logger() : m_indent_level(0), m_rank(-1), m_level_threshold(INFO), m_echo_level_threshold(LEGENDARY) -{} +{ + m_key_counters.push(std::map()); +} //----------------------------------------------------------------------------- Logger::~Logger() @@ -84,7 +85,7 @@ Logger::open(const std::string &ofpattern) if(rank() > -1) { ofname = conduit_fmt::format(ofpattern, - conduit_fmt::arg("rank",rank())); + conduit_fmt::arg("rank",rank())); } else { @@ -99,6 +100,12 @@ Logger::open(const std::string &ofpattern) } } +//----------------------------------------------------------------------------- +bool +Logger::is_open() +{ + return m_ofstream.is_open(); +} //----------------------------------------------------------------------------- void @@ -121,15 +128,37 @@ Logger::flush() void Logger::log_block_begin(const std::string &name) { - stream() << m_indent_string << name << ":\n"; + // make sure we have a unique key name + + int key_count = m_key_counters.top()[name]++; + + stream() << m_indent_string <<"-\n"; + set_indent_level(indent_level()+1); + + if(key_count == 0) + { + stream() << m_indent_string << name << ":\n"; + } + else + { + stream() << m_indent_string << name << "_" << key_count <<":\n"; + } set_indent_level(indent_level()+1); + // add timer for new level + m_timers.push(Timer()); + // add key counter for new level + m_key_counters.push(std::map()); } //----------------------------------------------------------------------------- void Logger::log_block_end(const std::string &name) { - set_indent_level(indent_level()-1); + stream() << m_indent_string <<"-\n"; + stream() << m_indent_string << " time_elapsed: " << m_timers.top().elapsed() << "\n"; + set_indent_level(indent_level()-2); + m_key_counters.pop(); + m_timers.pop(); } //----------------------------------------------------------------------------- @@ -138,6 +167,29 @@ Logger::log_message(int level, const std::string &msg, const std::string &file, int line) +{ + // log if equal or above logging threshold + if(level >= log_threshold()) + { + log_message(level, msg, file, line, stream(), true); + } + + // echo if equal or above echo threshold + if(level >= echo_threshold()) + { + log_message(level, msg, file, line, std::cout, false); + } +} + + +//----------------------------------------------------------------------------- +void +Logger::log_message(int level, + const std::string &msg, + const std::string &file, + int line, + std::ostream &os, + bool detailed) { /* {parent_indent}- @@ -146,32 +198,61 @@ Logger::log_message(int level, {parent_indent}{indent}line: ... msg txt */ - stream() << m_indent_string <<"-\n"; - stream() << m_indent_string << " level: " << level_string(level) << "\n"; - stream() << m_indent_string << " file: " << file << "\n"; - stream() << m_indent_string << " line: " << line << "\n"; - log_message_inner(msg); + os << m_indent_string <<"-\n"; + os << m_indent_string << " level: " << level_string(level) << "\n"; + if(detailed) + { + os << m_indent_string << " file: " << file << "\n"; + os << m_indent_string << " line: " << line << "\n"; + os << m_indent_string << " timestamp: \"" << timestamp() << "\"\n"; + } + log_message_inner(msg, os); } //----------------------------------------------------------------------------- void Logger::log_message(int level, const std::string &msg) +{ + // log if equal or above logging threshold + if(level >= log_threshold()) + { + log_message(level, msg, stream(), true); + } + + // echo if equal or above echo threshold + if(level >= echo_threshold()) + { + log_message(level, msg, std::cout, false); + } +} + +//----------------------------------------------------------------------------- +void +Logger::log_message(int level, + const std::string &msg, + std::ostream &os, + bool detailed) { /* {parent_indent}- {parent_indent}{indent}level: ... msg txt */ - stream() << m_indent_string <<"-\n"; - stream() << m_indent_string << " level: " << level_string(level) << "\n"; - log_message_inner(msg); + os << m_indent_string <<"-\n"; + os << m_indent_string << " level: " << level_string(level) << "\n"; + if(detailed) + { + os << m_indent_string << " timestamp: \"" << timestamp() << "\"\n"; + } + log_message_inner(msg, os); } //----------------------------------------------------------------------------- void -Logger::log_message_inner(const std::string &msg) +Logger::log_message_inner(const std::string &msg, + std::ostream &os) { /* {parent_indent}{indent}msg: | @@ -179,12 +260,12 @@ Logger::log_message_inner(const std::string &msg) ... {parent_indent}{indent}{indent} msg line */ - stream() << m_indent_string << " msg: |\n"; + os << m_indent_string << " msg: |\n"; std::istringstream input; input.str(msg); for (std::string line; std::getline(input, line);) { - stream() << m_indent_string << " " << line << "\n"; + os << m_indent_string << " " << line << "\n"; } } @@ -212,28 +293,35 @@ Logger::rank() const //----------------------------------------------------------------------------- void -Logger::set_level_threshold(int level) +Logger::set_rank(int rank) +{ + m_rank = rank; +} + +//----------------------------------------------------------------------------- +void +Logger::set_log_threshold(int level) { m_level_threshold = level; } //----------------------------------------------------------------------------- int -Logger::level_threshold() const +Logger::log_threshold() const { return m_level_threshold; } //----------------------------------------------------------------------------- void -Logger::set_echo_level_threshold(int level) +Logger::set_echo_threshold(int level) { m_echo_level_threshold = level; } //----------------------------------------------------------------------------- int -Logger::echo_level_threshold() const +Logger::echo_threshold() const { return m_echo_level_threshold; } @@ -247,17 +335,23 @@ Logger::stream() //----------------------------------------------------------------------------- Logger * -Logger::active_instance() +Logger::instance() { - return m_active_logger; + return m_active_instance; } //----------------------------------------------------------------------------- -Logger * -Logger::activate_instance(const std::string &ofile_pattern) +void +Logger::activate() { - m_active_logger = &m_loggers[ofile_pattern]; - return m_active_logger; + m_active_instance = &m_instance; +} + +//----------------------------------------------------------------------------- +void +Logger::deactivate() +{ + m_active_instance = nullptr; } //----------------------------------------------------------------------------- @@ -275,7 +369,16 @@ Logger::level_string(int level) return m_level_strings[level]; } - +//----------------------------------------------------------------------------- +std::string +Logger::timestamp() +{ + std::time_t time = std::time(nullptr); + auto tm = *std::localtime(&time); + std::ostringstream oss; + oss << std::put_time(&tm, "%Y-%m-%d %H:%M:%S"); + return oss.str(); +} //----------------------------------------------------------------------------- }; diff --git a/src/libs/logging/ascent_logging.hpp b/src/libs/logging/ascent_logging.hpp index f1d55dc87..b3f61f3de 100644 --- a/src/libs/logging/ascent_logging.hpp +++ b/src/libs/logging/ascent_logging.hpp @@ -14,8 +14,10 @@ #include #include +#include #include +#include #include /* @@ -38,28 +40,24 @@ ASCENT_LOG_FLUSH() //----------------------------------------------------------------------------- #define ASCENT_LOG_OPEN( ofname_pattern ) \ { \ - ascent::Logger *lgr = ascent::Logger::activate_instance(ofname_pattern); \ + ascent::Logger::activate(); \ + ascent::Logger *lgr = ascent::Logger::instance(); \ lgr->open(ofname_pattern); \ } //----------------------------------------------------------------------------- #define ASCENT_LOG_OPEN_RANK( ofname_pattern , rank ) \ { \ - ascent::Logger *lgr = ascent::Logger::activate_instance(ofname_pattern); \ + ascent::Logger::activate(); \ + ascent::Logger *lgr = ascent::Logger::instance(); \ lgr->set_rank(rank); \ lgr->open(ofname_pattern); \ } -//----------------------------------------------------------------------------- -#define ASCENT_LOG_ACTIVATE( ofname_pattern ) \ -{ \ - Logger::activate_instance(ofname_pattern); \ -} - //----------------------------------------------------------------------------- #define ASCENT_LOG_DEBUG( msg ) \ { \ - ascent::Logger *_ascent_lgr = Logger::active_instance(); \ + ascent::Logger *_ascent_lgr = ascent::Logger::instance(); \ if(_ascent_lgr != nullptr) \ { \ std::ostringstream _ascent_oss_info; \ @@ -74,7 +72,7 @@ ASCENT_LOG_FLUSH() //----------------------------------------------------------------------------- #define ASCENT_LOG_INFO( msg ) \ { \ - ascent::Logger *_ascent_lgr = Logger::active_instance(); \ + ascent::Logger *_ascent_lgr = ascent::Logger::instance(); \ if(_ascent_lgr != nullptr) \ { \ std::ostringstream _ascent_oss_info; \ @@ -89,7 +87,7 @@ ASCENT_LOG_FLUSH() //----------------------------------------------------------------------------- #define ASCENT_LOG_WARN( msg ) \ { \ - ascent::Logger *_ascent_lgr = Logger::active_instance(); \ + ascent::Logger *_ascent_lgr = ascent::Logger::instance(); \ if(_ascent_lgr != nullptr) \ { \ std::ostringstream _ascent_oss_info; \ @@ -104,7 +102,7 @@ ASCENT_LOG_FLUSH() //----------------------------------------------------------------------------- #define ASCENT_LOG_ERROR( msg ) \ { \ - ascent::Logger *_ascent_lgr = ascent::Logger::active_instance(); \ + ascent::Logger *_ascent_lgr = ascent::Logger::instance(); \ if(_ascent_lgr != nullptr) \ { \ std::ostringstream _ascent_oss_info; \ @@ -117,9 +115,9 @@ ASCENT_LOG_FLUSH() }// TODO EXCEPTION! //----------------------------------------------------------------------------- -#define ASCENT_FLUSH () \ +#define ASCENT_LOG_FLUSH() \ { \ - ascent::Logger *_ascent_lgr = ascent::Logger::active_instance(); \ + ascent::Logger *_ascent_lgr = ascent::Logger::instance(); \ if(_ascent_lgr != nullptr) \ { \ _ascent_lgr->flush(); \ @@ -127,15 +125,26 @@ ASCENT_LOG_FLUSH() } //----------------------------------------------------------------------------- -#define ASCENT_MARK_SCOPE( name ) ASCENT_ANNOTATE_MARK_SCOPE; ascent::Logger::Scope _ascent_lgr_scope(ascent::Logger::active_instance(), name ); +#define ASCENT_LOG_CLOSE() \ +{ \ + ascent::Logger *_ascent_lgr = ascent::Logger::instance(); \ + if(_ascent_lgr != nullptr) \ + { \ + _ascent_lgr->close(); \ + ascent::Logger::deactivate(); \ + } \ +} + +//----------------------------------------------------------------------------- +#define ASCENT_MARK_SCOPE( name ) ASCENT_ANNOTATE_MARK_SCOPE; ascent::Logger::Scope _ascent_lgr_scope(ascent::Logger::instance(), name ); //----------------------------------------------------------------------------- -#define ASCENT_MARK_FUNCTION( name ) ASCENT_ANNOTATE_MARK_FUNCTION; ascent::Logger::Scope _ascent_lgr_func(ascent::Logger::active_instance(), std::string(__func__)); +#define ASCENT_MARK_FUNCTION( name ) ASCENT_ANNOTATE_MARK_FUNCTION; ascent::Logger::Scope _ascent_lgr_func(ascent::Logger::instance(), std::string(__func__)); //----------------------------------------------------------------------------- #define ASCENT_MARK_BEGIN( name ) ASCENT_ANNOTATE_MARK_BEGIN( name ); \ { \ - ascent::Logger *_ascent_lgr = ascent::Logger::active_instance(); \ + ascent::Logger *_ascent_lgr = ascent::Logger::instance(); \ if(_ascent_lgr != nullptr) \ { \ _ascent_lgr->log_block_begin(name); \ @@ -145,7 +154,7 @@ ASCENT_LOG_FLUSH() //----------------------------------------------------------------------------- #define ASCENT_MARK_END( name ) ASCENT_ANNOTATE_MARK_END( name ); \ { \ - ascent::Logger *_ascent_lgr = ascent::Logger::active_instance(); \ + ascent::Logger *_ascent_lgr = ascent::Logger::instance(); \ if(_ascent_lgr != nullptr) \ { \ _ascent_lgr->log_block_end(name); \ @@ -186,10 +195,6 @@ class ASCENT_API Logger std::string m_name; }; - //------------------------------------------------------------------------- - Logger(); - ~Logger(); - // // "ascent_log_out.yaml" // "ascent_log_out_{rank}.yaml" @@ -197,7 +202,7 @@ class ASCENT_API Logger // void open(const std::string &ofile_pattern); - + bool is_open(); void close(); void flush(); @@ -208,6 +213,7 @@ class ASCENT_API Logger void log_message(int level, const std::string &msg); + void log_block_begin(const std::string &name); void log_block_end(const std::string &name); @@ -217,37 +223,67 @@ class ASCENT_API Logger int indent_level() const; void set_indent_level(int level); - // any msgs >= level_threshold will be logged - void set_level_threshold(int level); - int level_threshold() const; - - // any msgs >= echo_level_threshold will sent to std out as well as log - void set_echo_level_threshold(int level); - int echo_level_threshold() const; + // any msgs >= log_threshold will be logged + void set_log_threshold(int level); + int log_threshold() const; + // any msgs >= echo_threshold will sent to std out as well as log + void set_echo_threshold(int level); + int echo_threshold() const; std::ostream &stream(); - static Logger *active_instance(); - static Logger *activate_instance(const std::string &ofile_pattern); + static Logger *instance(); + static void activate(); + static void deactivate(); private: + //------------------------------------------------------------------------- + Logger(); + ~Logger(); + static const std::string &level_string(int level); + std::string timestamp(); - void log_message_inner(const std::string &msg); + void log_message(int level, + const std::string &msg, + const std::string &file, + int line, + std::ostream &os, + bool detailed); + + void log_message(int level, + const std::string &msg, + std::ostream &os, + bool detailed); + + void log_message_inner(const std::string &msg, + std::ostream &os); + + void log_block_begin(const std::string &name, + std::ostream &os); + + void log_block_end(const std::string &name, + std::ostream &os); std::ofstream m_ofstream; - int m_indent_level; // default = 0 + int m_indent_level; // default = 0 int m_indent_spaces; // default = 4 int m_rank; // default = -1 int m_level_threshold; // default = INFO int m_echo_level_threshold; // default = LEGENDARY std::string m_indent_string; // current indent string - - static Logger *m_active_logger; // default = nullptr - static std::map m_loggers; + + // stack of timers + std::stack m_timers; + // stack of block name counters + // used to make sure we have unique keys in our yaml output + std::stack> m_key_counters; + + static Logger m_instance; + static Logger *m_active_instance; // default = nullptr static std::vector m_level_strings; }; diff --git a/src/libs/logging/ascent_logging_timer.cpp b/src/libs/logging/ascent_logging_timer.cpp new file mode 100644 index 000000000..e67959249 --- /dev/null +++ b/src/libs/logging/ascent_logging_timer.cpp @@ -0,0 +1,61 @@ +//~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~// +// Copyright (c) Lawrence Livermore National Security, LLC and other Ascent +// Project developers. See top-level LICENSE AND COPYRIGHT files for dates and +// other details. No copyright assignment is required to contribute to Ascent. +//~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~// + + +//----------------------------------------------------------------------------- +/// +/// file: ascent_logging_timer.cpp +/// +//----------------------------------------------------------------------------- + +#include "ascent_logging_timer.hpp" + + +using namespace std::chrono; + +//----------------------------------------------------------------------------- +// -- begin ascent:: -- +//----------------------------------------------------------------------------- +namespace ascent +{ + + +//----------------------------------------------------------------------------- +Timer::Timer() +{ + reset(); +} + +//----------------------------------------------------------------------------- +Timer::~Timer() +{ + +} + +//----------------------------------------------------------------------------- +void +Timer::reset() +{ + m_start = high_resolution_clock::now(); +} + +//----------------------------------------------------------------------------- +float +Timer::elapsed() const +{ + return duration_cast>(high_resolution_clock::now() - m_start).count(); +} + + + +//----------------------------------------------------------------------------- +}; +//----------------------------------------------------------------------------- +// -- end ascent:: -- +//----------------------------------------------------------------------------- + + + diff --git a/src/libs/logging/ascent_logging_timer.hpp b/src/libs/logging/ascent_logging_timer.hpp new file mode 100644 index 000000000..b0e348371 --- /dev/null +++ b/src/libs/logging/ascent_logging_timer.hpp @@ -0,0 +1,56 @@ +//~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~// +// Copyright (c) Lawrence Livermore National Security, LLC and other Ascent +// Project developers. See top-level LICENSE AND COPYRIGHT files for dates and +// other details. No copyright assignment is required to contribute to Ascent. +//~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~// + + +//----------------------------------------------------------------------------- +/// +/// file: ascent_logging_timer.hpp +/// +//----------------------------------------------------------------------------- + +#ifndef ASCENT_LOGGING_TIMER_HPP +#define ASCENT_LOGGING_TIMER_HPP + +#include +#include + +//----------------------------------------------------------------------------- +// -- begin ascent:: -- +//----------------------------------------------------------------------------- +namespace ascent +{ + + +//----------------------------------------------------------------------------- +class ASCENT_API Timer +{ + +public: + + explicit Timer(); + ~Timer(); + void reset(); + float elapsed() const; + +private: + std::chrono::high_resolution_clock::time_point m_start; +}; + + +//----------------------------------------------------------------------------- +}; +//----------------------------------------------------------------------------- +// -- end ascent:: -- +//----------------------------------------------------------------------------- + + + +#endif +//----------------------------------------------------------------------------- +// -- end header ifdef guard +//----------------------------------------------------------------------------- + + diff --git a/src/tests/logging/t_ascent_logger_basic.cpp b/src/tests/logging/t_ascent_logger_basic.cpp index 85791e01f..c4207ce4a 100644 --- a/src/tests/logging/t_ascent_logger_basic.cpp +++ b/src/tests/logging/t_ascent_logger_basic.cpp @@ -23,6 +23,30 @@ using namespace std; using namespace conduit; using namespace ascent; + +//----------------------------------------------------------------------------- +void my_func_nest_2() +{ + ASCENT_MARK_FUNCTION(); + ASCENT_LOG_INFO("nest 2"); +} + +//----------------------------------------------------------------------------- +void my_func_nest_1() +{ + ASCENT_MARK_FUNCTION(); + ASCENT_LOG_INFO("nest 1"); + my_func_nest_2(); +} + +//----------------------------------------------------------------------------- +void my_func_nest_0() +{ + ASCENT_MARK_FUNCTION(); + ASCENT_LOG_INFO("nest 0"); + my_func_nest_1(); +} + //----------------------------------------------------------------------------- void myfunc() { @@ -31,9 +55,10 @@ void myfunc() } //----------------------------------------------------------------------------- -TEST(ascent_smoke, ascent_about) +TEST(ascent_logging, basic_logging) { - ASCENT_LOG_OPEN("here_we_go.yaml") + + ASCENT_LOG_OPEN("tout_logging_log_1.yaml"); ASCENT_LOG_INFO("my info!"); ASCENT_LOG_WARN("my warning!"); ASCENT_LOG_ERROR("my error!"); @@ -44,8 +69,57 @@ TEST(ascent_smoke, ascent_about) ASCENT_MARK_END("blocky"); myfunc(); - ASCENT_MARK_BEGIN("blocky2"); + ASCENT_MARK_BEGIN("blocky"); myfunc(); - ASCENT_MARK_END("blocky2"); + ASCENT_MARK_END("blocky"); + + ASCENT_MARK_BEGIN("blocky"); + my_func_nest_0(); + ASCENT_MARK_END("blocky"); + ASCENT_LOG_CLOSE(); + + conduit::Node n; + n.load("tout_logging_log_1.yaml"); + n.print(); + } +//----------------------------------------------------------------------------- +TEST(ascent_logging, basic_logging_echo) +{ + + std::cout << "[echoed]" << std::endl; + ASCENT_LOG_OPEN("tout_logging_log_2.yaml"); + ascent::Logger::instance()->set_echo_threshold(0); + ASCENT_LOG_INFO("my info!"); + ASCENT_LOG_WARN("my warning!"); + ASCENT_LOG_ERROR("my error!"); + ASCENT_LOG_CLOSE(); + + std::cout << "[loaded]" << std::endl; + conduit::Node n; + n.load("tout_logging_log_2.yaml"); + n.print(); + EXPECT_EQ(n.number_of_children(),3); +} + +//----------------------------------------------------------------------------- +TEST(ascent_logging, basic_logging_threshold) +{ + + ASCENT_LOG_OPEN("tout_logging_log_3.yaml"); + ASCENT_LOG_INFO("my info!"); + ascent::Logger::instance()->set_log_threshold(ascent::Logger::LEGENDARY); + ASCENT_LOG_WARN("my warning!"); + ASCENT_LOG_ERROR("my error!"); + ASCENT_LOG_CLOSE(); + + std::cout << "[loaded]" << std::endl; + conduit::Node n; + n.load("tout_logging_log_3.yaml"); + n.print(); + EXPECT_EQ(n.number_of_children(),1); +} + + +