From 0a1b5a9e423aae9c8fa39ddc1fb7baceab3dcc99 Mon Sep 17 00:00:00 2001 From: staviq Date: Mon, 4 Sep 2023 02:22:26 +0200 Subject: [PATCH 01/11] LogTargetWrapper, LogStateWrapper --- common/log.h | 272 +++++++++++++++++++++++++++++++++++++++++++++++---- 1 file changed, 255 insertions(+), 17 deletions(-) diff --git a/common/log.h b/common/log.h index 0b9b01052b87c..2092223b2f49a 100644 --- a/common/log.h +++ b/common/log.h @@ -5,7 +5,10 @@ #include #include #include +#include +#include #include +#include #include #include @@ -47,6 +50,238 @@ // // -------------------------------- +class LogTargetWrapper +{ + private: + LogTargetWrapper( LogTargetWrapper& other ) = delete; + void operator=( const LogTargetWrapper& ) = delete; + + public: + LogTargetWrapper( FILE* handle ) + : _type(Type::Stream), + _opened(true), + _handle(handle) + {} + + LogTargetWrapper( const std::string && filename ) + : LogTargetWrapper(filename) + {} + LogTargetWrapper( const std::string & filename ) + : _filename(filename) + { + if(_filename.empty()) + { + _type = Type::Stream; + _handle = stderr; + _opened = true; + } + else + { + _type = Type::File; + } + } + + ~LogTargetWrapper() + { + if(_type == Type::File && _handle != nullptr) {std::fclose(_handle);} + } + + enum Type{ + Invalid, + File, + Stream + }; + + public: + operator FILE*() + { + // Assigning lambda result to a static variable guarantees one time thread-safe execution + // while completly removing the need for conditional if(initialized). + // + // This noticeably reduces performance overhead of LOG macro invocations. + // + // Initializing log file here, prevents creating a file before first LOG use, + // simplifying initial conditions and overrides from command line arguments. + // + // TODO: MSVC + // + static const auto dummy_init __attribute__((unused)) = [&](){ + std::lock_guard lock(_mutex); + if(!_opened && _type == Type::File) + { + auto result = std::fopen(_filename.c_str(), "w"); + if( result ) + { + _handle = result; + } + else + { + std::fprintf(stderr, "Failed to open logfile '%s' with error '%s'\n", _filename.c_str(), std::strerror(errno)); + std::fflush(stderr); + _handle = stderr; + } + _opened = true; + } + return _opened; + }(); + return _handle; + } + + void flush() + { + std::lock_guard lock(_mutex); + if(_opened && _type != Type::Invalid && _handle) + { + std::fflush(_handle); + } + } + + private: + std::mutex _mutex; + Type _type {Type::Invalid}; + std::string _filename; + bool _opened {false}; + std::atomic _handle {nullptr}; +}; + +class LogStateWrapper +{ + protected: + LogStateWrapper(){}; + + virtual ~LogStateWrapper() + { + flush_all_targets(); + for(auto t: _targets){delete t;} + } + + private: + LogStateWrapper( LogStateWrapper& other ) = delete; + void operator=( const LogStateWrapper& ) = delete; + + private: + static LogStateWrapper& instance() + { + static LogStateWrapper inst; + return inst; + } + + private: + std::mutex _mutex; + bool _enabled{true}; + bool _global_enabled{true}; + std::set _targets; + LogTargetWrapper _null_target {nullptr}; + LogTargetWrapper _stderr_target {stderr}; + std::atomic _current_target {&_null_target}; + std::atomic _current_tee_target {&_stderr_target}; + std::atomic _stored_target {&_null_target}; + std::atomic _stored_tee_target {&_null_target}; + + LogTargetWrapper* log_set_target_impl( const std::string && filename ) {return log_set_target_impl(filename);} + LogTargetWrapper* log_set_target_impl( const std::string & filename ) {return log_add_select_target(new LogTargetWrapper(filename));} + LogTargetWrapper* log_set_target_impl( FILE* handle ) {return log_add_select_target(new LogTargetWrapper(handle));} + LogTargetWrapper* log_set_target_impl( LogTargetWrapper * target ) + { + flush_all_targets(); + std::lock_guard lock(_mutex); + _current_target.store(target); + return target; + } + + LogTargetWrapper* log_set_tee_target_impl( const std::string && filename ) {return log_set_tee_target_impl(filename);} + LogTargetWrapper* log_set_tee_target_impl( const std::string & filename ) {return log_add_select_tee_target(new LogTargetWrapper(filename));} + LogTargetWrapper* log_set_tee_target_impl( FILE* handle ) {return log_add_select_tee_target(new LogTargetWrapper(handle));} + LogTargetWrapper* log_set_tee_target_impl( LogTargetWrapper * target ) + { + flush_all_targets(); + std::lock_guard lock(_mutex); + _current_tee_target.store(target); + return target; + } + + LogTargetWrapper* log_add_select_target(LogTargetWrapper* t) + { + flush_all_targets(); + std::lock_guard lock(_mutex); + _current_target.store(t); + _targets.insert(t); + return t; + } + + LogTargetWrapper* log_add_select_tee_target(LogTargetWrapper* t) + { + flush_all_targets(); + std::lock_guard lock(_mutex); + _current_tee_target.store(t); + _targets.insert(t); + return t; + } + + void flush_all_targets() + { + std::lock_guard lock(_mutex); + for(auto t: _targets){ t->flush(); } + } + + FILE* log_handler_impl() + { + return *_current_target; + } + + FILE* log_tee_handler_impl() + { + return *_current_tee_target; + } + + void log_global_disable() + { + { + std::lock_guard lock(_mutex); + _global_enabled = false; + } + log_disable_impl(); + } + + void log_disable_impl() + { + std::lock_guard lock(_mutex); + if(_enabled) + { + _stored_target.store (_current_target); + _stored_tee_target.store (_current_tee_target); + _current_target.store (&_null_target); + _current_tee_target.store (&_stderr_target); + _enabled = false; + } + } + + void log_enable_impl() + { + std::lock_guard lock(_mutex); + if(!_enabled && _global_enabled) + { + _current_target.store (_stored_target); + _current_tee_target.store (_stored_tee_target); + _enabled = true; + } + } + + public: + static LogTargetWrapper* log_set_target( const std::string && filename ) {return log_set_target(filename);} + static LogTargetWrapper* log_set_target( const std::string & filename ) {return instance().log_set_target_impl(filename);} + static LogTargetWrapper* log_set_target( FILE* handle ) {return instance().log_set_target_impl(handle);} + static LogTargetWrapper* log_set_target( LogTargetWrapper * target ) {return instance().log_set_target_impl(target);} + static LogTargetWrapper* log_set_tee_target( const std::string && filename ) {return log_set_tee_target(filename);} + static LogTargetWrapper* log_set_tee_target( const std::string & filename ) {return instance().log_set_tee_target_impl(filename);} + static LogTargetWrapper* log_set_tee_target( FILE* handle ) {return instance().log_set_tee_target_impl(handle);} + static LogTargetWrapper* log_set_tee_target( LogTargetWrapper * target ) {return instance().log_set_tee_target_impl(target);} + static FILE* log_handler() {return instance().log_handler_impl();} + static FILE* log_tee_handler() {return instance().log_tee_handler_impl();} + static void log_disable() {instance().log_disable_impl();} + static void log_enable() {instance().log_enable_impl();} +}; + // Specifies a log target. // default uses log_handler() with "llama.log" log file // this can be changed, by defining LOG_TARGET @@ -90,11 +325,11 @@ // } // #ifndef LOG_TARGET - #define LOG_TARGET log_handler() + #define LOG_TARGET LogStateWrapper::log_handler() #endif #ifndef LOG_TEE_TARGET - #define LOG_TEE_TARGET stderr + #define LOG_TEE_TARGET LogStateWrapper::log_tee_handler() #endif // Utility to obtain "pid" like unique process id and use it when creating log files. @@ -225,7 +460,7 @@ enum LogTriState // USE LOG() INSTEAD // #ifndef _MSC_VER - #define LOG_IMPL(str, ...) \ + #define LOG_IMPL(str, ...) \ { \ if (LOG_TARGET != nullptr) \ { \ @@ -234,7 +469,7 @@ enum LogTriState } \ } #else - #define LOG_IMPL(str, ...) \ + #define LOG_IMPL(str, ...) \ { \ if (LOG_TARGET != nullptr) \ { \ @@ -248,7 +483,7 @@ enum LogTriState // USE LOG_TEE() INSTEAD // #ifndef _MSC_VER - #define LOG_TEE_IMPL(str, ...) \ + #define LOG_TEE_IMPL(str, ...) \ { \ if (LOG_TARGET != nullptr) \ { \ @@ -262,7 +497,7 @@ enum LogTriState } \ } #else - #define LOG_TEE_IMPL(str, ...) \ + #define LOG_TEE_IMPL(str, ...) \ { \ if (LOG_TARGET != nullptr) \ { \ @@ -405,7 +640,8 @@ inline FILE *log_handler2_impl(bool change = false, LogTriState disable = LogTri // Disables logs entirely at runtime. // Makes LOG() and LOG_TEE() produce no output, // untill enabled back. -#define log_disable() log_disable_impl() +//#define log_disable() log_disable_impl() +#define log_disable() LogStateWrapper::log_disable() // INTERNAL, DO NOT USE inline FILE *log_disable_impl() @@ -414,7 +650,8 @@ inline FILE *log_disable_impl() } // Enables logs at runtime. -#define log_enable() log_enable_impl() +//#define log_enable() log_enable_impl() +#define log_enable() LogStateWrapper::log_enable() // INTERNAL, DO NOT USE inline FILE *log_enable_impl() @@ -423,7 +660,8 @@ inline FILE *log_enable_impl() } // Sets target fir logs, either by a file name or FILE* pointer (stdout, stderr, or any valid FILE*) -#define log_set_target(target) log_set_target_impl(target) +//#define log_set_target(target) log_set_target_impl(target) +#define log_set_target(target) LogStateWrapper::log_set_target(target) // INTERNAL, DO NOT USE inline FILE *log_set_target_impl(const std::string & filename) { return log_handler1_impl(true, LogTriStateSame, filename); } @@ -513,16 +751,16 @@ inline bool log_param_pair_parse(bool check_but_dont_parse, const std::string & inline void log_print_usage() { - fprintf(stdout, "log options:\n"); + printf("log options:\n"); /* format - fprintf(stdout, " -h, --help show this help message and exit\n");*/ + printf(" -h, --help show this help message and exit\n");*/ /* spacing - fprintf(stdout, "__-param----------------Description\n");*/ - fprintf(stdout, " --log-test Run simple logging test\n"); - fprintf(stdout, " --log-disable Disable trace logs\n"); - fprintf(stdout, " --log-enable Enable trace logs\n"); - fprintf(stdout, " --log-file Specify a log filename (without extension)\n"); - fprintf(stdout, " Log file will be tagged with unique ID and written as \"..log\"\n"); /* */ + printf("__-param----------------Description\n");*/ + printf(" --log-test Run simple logging test\n"); + printf(" --log-disable Disable trace logs\n"); + printf(" --log-enable Enable trace logs\n"); + printf(" --log-file Specify a log filename (without extension)\n"); + printf(" Log file will be tagged with unique ID and written as \"..log\"\n"); /* */ } #define log_dump_cmdline(argc, argv) log_dump_cmdline_impl(argc, argv) From de56a828308b6a845a0cd8d2bb229309e94c8c8f Mon Sep 17 00:00:00 2001 From: staviq Date: Fri, 8 Sep 2023 20:43:24 +0200 Subject: [PATCH 02/11] glob overrides, --log-disable restores def style --- common/log.h | 336 +++++++++++++++++++++++++++++++++------------------ 1 file changed, 219 insertions(+), 117 deletions(-) diff --git a/common/log.h b/common/log.h index 2092223b2f49a..df4c0bf2daa79 100644 --- a/common/log.h +++ b/common/log.h @@ -50,6 +50,8 @@ // // -------------------------------- +inline void log_test(); + class LogTargetWrapper { private: @@ -144,6 +146,15 @@ class LogTargetWrapper std::atomic _handle {nullptr}; }; +// Utility for synchronizing log configuration state +// since std::optional was introduced only in c++17 +enum LogTriState +{ + LogTriStateSame, + LogTriStateFalse, + LogTriStateTrue +}; + class LogStateWrapper { protected: @@ -151,7 +162,7 @@ class LogStateWrapper virtual ~LogStateWrapper() { - flush_all_targets(); + log_flush_all_targets(); for(auto t: _targets){delete t;} } @@ -168,24 +179,41 @@ class LogStateWrapper private: std::mutex _mutex; - bool _enabled{true}; - bool _global_enabled{true}; + std::atomic _enabled {true}; + std::atomic _global_override_enabled {LogTriState::LogTriStateSame}; std::set _targets; - LogTargetWrapper _null_target {nullptr}; - LogTargetWrapper _stderr_target {stderr}; - std::atomic _current_target {&_null_target}; - std::atomic _current_tee_target {&_stderr_target}; - std::atomic _stored_target {&_null_target}; - std::atomic _stored_tee_target {&_null_target}; + LogTargetWrapper _null_target {nullptr}; + LogTargetWrapper _stderr_target {stderr}; + std::atomic _global_override_target {LogTriState::LogTriStateSame}; + std::atomic _current_target {&_null_target}; + std::atomic _current_tee_target {&_stderr_target}; + std::atomic _stored_target {&_null_target}; + std::atomic _stored_tee_target {&_null_target}; LogTargetWrapper* log_set_target_impl( const std::string && filename ) {return log_set_target_impl(filename);} LogTargetWrapper* log_set_target_impl( const std::string & filename ) {return log_add_select_target(new LogTargetWrapper(filename));} LogTargetWrapper* log_set_target_impl( FILE* handle ) {return log_add_select_target(new LogTargetWrapper(handle));} LogTargetWrapper* log_set_target_impl( LogTargetWrapper * target ) { - flush_all_targets(); + log_flush_all_targets(); std::lock_guard lock(_mutex); - _current_target.store(target); + + if( _global_override_target == LogTriState::LogTriStateTrue ) + { + if(_enabled || _global_override_enabled == LogTriState::LogTriStateTrue) + return _current_target; + return _stored_target; + } + + if(_enabled || _global_override_enabled == LogTriState::LogTriStateTrue) + { + _current_target.store(target); + } + else + { + _stored_target.store(target); + } + return target; } @@ -194,31 +222,65 @@ class LogStateWrapper LogTargetWrapper* log_set_tee_target_impl( FILE* handle ) {return log_add_select_tee_target(new LogTargetWrapper(handle));} LogTargetWrapper* log_set_tee_target_impl( LogTargetWrapper * target ) { - flush_all_targets(); + log_flush_all_targets(); std::lock_guard lock(_mutex); - _current_tee_target.store(target); + + if(_enabled || _global_override_enabled == LogTriState::LogTriStateTrue) + { + _current_tee_target.store(target); + } + else + { + _stored_tee_target.store(target); + } + return target; } LogTargetWrapper* log_add_select_target(LogTargetWrapper* t) { - flush_all_targets(); + log_flush_all_targets(); std::lock_guard lock(_mutex); - _current_target.store(t); + + if( _global_override_target ) + { + if(_enabled || _global_override_enabled == LogTriState::LogTriStateTrue) + return _current_target; + return _stored_target; + } + + if(_enabled || _global_override_enabled == LogTriState::LogTriStateTrue) + { + _current_target.store(t); + } + else + { + _stored_target.store(t); + } _targets.insert(t); + return t; } LogTargetWrapper* log_add_select_tee_target(LogTargetWrapper* t) { - flush_all_targets(); + log_flush_all_targets(); std::lock_guard lock(_mutex); - _current_tee_target.store(t); + + if(_enabled || _global_override_enabled == LogTriState::LogTriStateTrue) + { + _current_tee_target.store(t); + } + else + { + _stored_tee_target.store(t); + } _targets.insert(t); + return t; } - void flush_all_targets() + void log_flush_all_targets() { std::lock_guard lock(_mutex); for(auto t: _targets){ t->flush(); } @@ -234,19 +296,22 @@ class LogStateWrapper return *_current_tee_target; } - void log_global_disable() + void log_disable_impl( bool threadsafe = true ) { + if( threadsafe ) { std::lock_guard lock(_mutex); - _global_enabled = false; + log_disable_impl_unsafe(); + } + else + { + log_disable_impl_unsafe(); } - log_disable_impl(); } - void log_disable_impl() + void log_disable_impl_unsafe() { - std::lock_guard lock(_mutex); - if(_enabled) + if(_enabled && _global_override_enabled != LogTriState::LogTriStateTrue) { _stored_target.store (_current_target); _stored_tee_target.store (_current_tee_target); @@ -256,10 +321,22 @@ class LogStateWrapper } } - void log_enable_impl() + void log_enable_impl( bool threadsafe = true ) { - std::lock_guard lock(_mutex); - if(!_enabled && _global_enabled) + if( threadsafe ) + { + std::lock_guard lock(_mutex); + log_enable_impl_unsafe(); + } + else + { + log_enable_impl_unsafe(); + } + } + + void log_enable_impl_unsafe() + { + if(!_enabled && _global_override_enabled != LogTriState::LogTriStateFalse) { _current_target.store (_stored_target); _current_tee_target.store (_stored_tee_target); @@ -267,6 +344,94 @@ class LogStateWrapper } } + bool log_param_single_parse_impl(const std::string & param) + { + if ( param == "--log-test") + { + log_test(); + return true; + } + + if ( param == "--log-disable") + { + { + std::lock_guard lock(_mutex); + log_disable_impl_unsafe(); + _global_override_enabled = LogTriState::LogTriStateFalse; + } + return true; + } + + if ( param == "--log-enable") + { + { + std::lock_guard lock(_mutex); + log_enable_impl_unsafe(); + _global_override_enabled = LogTriState::LogTriStateTrue; + } + return true; + } + + return false; + } + + bool log_param_pair_parse_impl(bool check_but_dont_parse, const std::string & param, const std::string & next = std::string()) + { + if ( param == "--log-file") + { + if (!check_but_dont_parse) + { + log_flush_all_targets(); + std::lock_guard lock(_mutex); + auto t = new LogTargetWrapper(log_filename_generator(next.empty() ? "unnamed" : next, "log")); + if(_enabled) + { + _current_target.store(t); + } + else + { + _stored_target.store(t); + } + _targets.insert(t); + _global_override_target = LogTriState::LogTriStateTrue; + return t; + } + + return true; + } + + return false; + } + + std::string log_filename_generator_impl(const std::string & basename, const std::string & extension) + { + std::stringstream buf; + + buf << basename; + buf << "."; + buf << log_get_pid(); + buf << "."; + buf << extension; + + return buf.str(); + } + + std::string log_get_pid_impl() + { + static std::string pid; + if (pid.empty()) + { + // std::this_thread::get_id() is the most portable way of obtaining a "process id" + // it's not the same as "pid" but is unique enough to solve multiple instances + // trying to write to the same log. + std::stringstream ss; + ss << std::this_thread::get_id(); + pid = ss.str(); + } + + return pid; + } + public: static LogTargetWrapper* log_set_target( const std::string && filename ) {return log_set_target(filename);} static LogTargetWrapper* log_set_target( const std::string & filename ) {return instance().log_set_target_impl(filename);} @@ -280,6 +445,12 @@ class LogStateWrapper static FILE* log_tee_handler() {return instance().log_tee_handler_impl();} static void log_disable() {instance().log_disable_impl();} static void log_enable() {instance().log_enable_impl();} + static bool log_param_single_parse(const std::string & param) {return instance().log_param_single_parse_impl(param);} + static bool log_param_pair_parse(bool check_but_dont_parse, const std::string & param, const std::string & next = std::string()) + {return instance().log_param_pair_parse_impl(check_but_dont_parse,param,next);} + static std::string log_filename_generator(const std::string & basename, const std::string & extension) + {return instance().log_filename_generator_impl(basename,extension);} + static std::string log_get_pid() {return instance().log_get_pid_impl();} }; // Specifies a log target. @@ -332,46 +503,15 @@ class LogStateWrapper #define LOG_TEE_TARGET LogStateWrapper::log_tee_handler() #endif -// Utility to obtain "pid" like unique process id and use it when creating log files. -inline std::string log_get_pid() -{ - static std::string pid; - if (pid.empty()) - { - // std::this_thread::get_id() is the most portable way of obtaining a "process id" - // it's not the same as "pid" but is unique enough to solve multiple instances - // trying to write to the same log. - std::stringstream ss; - ss << std::this_thread::get_id(); - pid = ss.str(); - } - - return pid; -} - // Utility function for generating log file names with unique id based on thread id. // invocation with log_filename_generator( "llama", "log" ) creates a string "llama..log" // where the number is a runtime id of the current thread. -#define log_filename_generator(log_file_basename, log_file_extension) log_filename_generator_impl(log_file_basename, log_file_extension) - -// INTERNAL, DO NOT USE -inline std::string log_filename_generator_impl(const std::string & log_file_basename, const std::string & log_file_extension) -{ - std::stringstream buf; - - buf << log_file_basename; - buf << "."; - buf << log_get_pid(); - buf << "."; - buf << log_file_extension; - - return buf.str(); -} +#define log_filename_generator(log_file_basename, log_file_extension) LogStateWrapper::log_filename_generator(log_file_basename, log_file_extension) -#ifndef LOG_DEFAULT_FILE_NAME - #define LOG_DEFAULT_FILE_NAME log_filename_generator("llama", "log") -#endif +// #ifndef LOG_DEFAULT_FILE_NAME +// #define LOG_DEFAULT_FILE_NAME log_filename_generator("llama", "log") +// #endif // Utility for turning #define values into string literals // so we can have a define for stderr and @@ -447,15 +587,6 @@ inline std::string log_filename_generator_impl(const std::string & log_file_base #define LOG_TEE_FLF_VAL ,"" #endif -// Utility for synchronizing log configuration state -// since std::optional was introduced only in c++17 -enum LogTriState -{ - LogTriStateSame, - LogTriStateFalse, - LogTriStateTrue -}; - // INTERNAL, DO NOT USE // USE LOG() INSTEAD // @@ -490,7 +621,7 @@ enum LogTriState fprintf(LOG_TARGET, LOG_TIMESTAMP_FMT LOG_FLF_FMT str "%s" LOG_TIMESTAMP_VAL LOG_FLF_VAL, __VA_ARGS__); \ fflush(LOG_TARGET); \ } \ - if (LOG_TARGET != nullptr && LOG_TARGET != stdout && LOG_TARGET != stderr && LOG_TEE_TARGET != nullptr) \ + if (LOG_TARGET != stdout && LOG_TARGET != stderr && LOG_TEE_TARGET != nullptr) \ { \ fprintf(LOG_TEE_TARGET, LOG_TEE_TIMESTAMP_FMT LOG_TEE_FLF_FMT str "%s" LOG_TEE_TIMESTAMP_VAL LOG_TEE_FLF_VAL, __VA_ARGS__); \ fflush(LOG_TEE_TARGET); \ @@ -504,7 +635,7 @@ enum LogTriState fprintf(LOG_TARGET, LOG_TIMESTAMP_FMT LOG_FLF_FMT str "%s" LOG_TIMESTAMP_VAL LOG_FLF_VAL "", ##__VA_ARGS__); \ fflush(LOG_TARGET); \ } \ - if (LOG_TARGET != nullptr && LOG_TARGET != stdout && LOG_TARGET != stderr && LOG_TEE_TARGET != nullptr) \ + if (LOG_TARGET != stdout && LOG_TARGET != stderr && LOG_TEE_TARGET != nullptr) \ { \ fprintf(LOG_TEE_TARGET, LOG_TEE_TIMESTAMP_FMT LOG_TEE_FLF_FMT str "%s" LOG_TEE_TIMESTAMP_VAL LOG_TEE_FLF_VAL "", ##__VA_ARGS__); \ fflush(LOG_TEE_TARGET); \ @@ -548,6 +679,7 @@ enum LogTriState #define LOG_TEELN(str, ...) LOG_TEE_IMPL("%s" str, "", __VA_ARGS__, "\n") #endif +/* // INTERNAL, DO NOT USE inline FILE *log_handler1_impl(bool change = false, LogTriState disable = LogTriStateSame, const std::string & filename = LOG_DEFAULT_FILE_NAME, FILE *target = nullptr) { @@ -636,42 +768,45 @@ inline FILE *log_handler2_impl(bool change = false, LogTriState disable = LogTri { return log_handler1_impl(change, disable, filename, target); } - +*/ // Disables logs entirely at runtime. // Makes LOG() and LOG_TEE() produce no output, // untill enabled back. //#define log_disable() log_disable_impl() #define log_disable() LogStateWrapper::log_disable() - +/* // INTERNAL, DO NOT USE inline FILE *log_disable_impl() { return log_handler1_impl(true, LogTriStateTrue); } - +*/ // Enables logs at runtime. //#define log_enable() log_enable_impl() #define log_enable() LogStateWrapper::log_enable() - +/* // INTERNAL, DO NOT USE inline FILE *log_enable_impl() { return log_handler1_impl(true, LogTriStateFalse); } - +*/ // Sets target fir logs, either by a file name or FILE* pointer (stdout, stderr, or any valid FILE*) //#define log_set_target(target) log_set_target_impl(target) #define log_set_target(target) LogStateWrapper::log_set_target(target) +/* // INTERNAL, DO NOT USE inline FILE *log_set_target_impl(const std::string & filename) { return log_handler1_impl(true, LogTriStateSame, filename); } inline FILE *log_set_target_impl(FILE *target) { return log_handler2_impl(true, LogTriStateSame, target); } // INTERNAL, DO NOT USE inline FILE *log_handler() { return log_handler1_impl(); } +*/ inline void log_test() { + auto log_default_logfile = log_set_target(log_filename_generator("llama","log")); log_disable(); LOG("01 Hello World to nobody, because logs are disabled!\n") log_enable(); @@ -680,11 +815,13 @@ inline void log_test() log_set_target(stderr); LOG("04 Hello World to stderr!\n") LOG_TEE("05 Hello World TEE with double printing to stderr prevented!\n") - log_set_target(LOG_DEFAULT_FILE_NAME); + //log_set_target(LOG_DEFAULT_FILE_NAME); + log_set_target(log_default_logfile); LOG("06 Hello World to default log file!\n") log_set_target(stdout); LOG("07 Hello World to stdout!\n") - log_set_target(LOG_DEFAULT_FILE_NAME); + //log_set_target(LOG_DEFAULT_FILE_NAME); + log_set_target(log_default_logfile); LOG("08 Hello World to default log file again!\n") log_disable(); LOG("09 Hello World _1_ into the void!\n") @@ -711,43 +848,8 @@ inline void log_test() #endif } -inline bool log_param_single_parse(const std::string & param) -{ - if ( param == "--log-test") - { - log_test(); - return true; - } - - if ( param == "--log-disable") - { - log_disable(); - return true; - } - - if ( param == "--log-enable") - { - log_enable(); - return true; - } - - return false; -} - -inline bool log_param_pair_parse(bool check_but_dont_parse, const std::string & param, const std::string & next = std::string()) -{ - if ( param == "--log-file") - { - if (!check_but_dont_parse) - { - log_set_target(log_filename_generator(next.empty() ? "unnamed" : next, "log")); - } - - return true; - } - - return false; -} +#define log_param_single_parse(param) LogStateWrapper::log_param_single_parse(param) +#define log_param_pair_parse(...) LogStateWrapper::log_param_pair_parse(__VA_ARGS__) inline void log_print_usage() { From eca94a06b45a60ffe7308ea91a5876e5b14df54a Mon Sep 17 00:00:00 2001 From: staviq Date: Tue, 12 Sep 2023 00:34:53 +0200 Subject: [PATCH 03/11] spinlock yield test 1 --- common/log.h | 26 ++++++++++++++++++-------- 1 file changed, 18 insertions(+), 8 deletions(-) diff --git a/common/log.h b/common/log.h index df4c0bf2daa79..f48a2956ea326 100644 --- a/common/log.h +++ b/common/log.h @@ -108,7 +108,8 @@ class LogTargetWrapper // TODO: MSVC // static const auto dummy_init __attribute__((unused)) = [&](){ - std::lock_guard lock(_mutex); + //std::lock_guard lock(_mutex); + while( _lock.test_and_set(std::memory_order_acquire) ){ std::this_thread::yield(); } if(!_opened && _type == Type::File) { auto result = std::fopen(_filename.c_str(), "w"); @@ -124,26 +125,30 @@ class LogTargetWrapper } _opened = true; } - return _opened; + _lock.clear(std::memory_order_release); + return _opened.load(); }(); return _handle; } void flush() { - std::lock_guard lock(_mutex); + //std::lock_guard lock(_mutex); + while( _lock.test_and_set(std::memory_order_acquire) ){ std::this_thread::yield(); } if(_opened && _type != Type::Invalid && _handle) { std::fflush(_handle); } + _lock.clear(std::memory_order_release); } private: - std::mutex _mutex; - Type _type {Type::Invalid}; + //std::mutex _mutex; + std::atomic_flag _lock = ATOMIC_FLAG_INIT; + Type _type {Type::Invalid}; std::string _filename; - bool _opened {false}; - std::atomic _handle {nullptr}; + std::atomic _opened {false}; + std::atomic _handle {nullptr}; }; // Utility for synchronizing log configuration state @@ -346,12 +351,13 @@ class LogStateWrapper bool log_param_single_parse_impl(const std::string & param) { +#ifdef LOG_WITH_TEST if ( param == "--log-test") { log_test(); return true; } - +#endif if ( param == "--log-disable") { { @@ -804,6 +810,7 @@ inline FILE *log_set_target_impl(FILE *target) { return log_handler2_impl(true, inline FILE *log_handler() { return log_handler1_impl(); } */ +#ifdef LOG_WITH_TEST inline void log_test() { auto log_default_logfile = log_set_target(log_filename_generator("llama","log")); @@ -847,6 +854,7 @@ inline void log_test() LOGLN("22 Hello msvc LOGLN with (%d)(%s) arguments\n", 1, "test") #endif } +#endif #define log_param_single_parse(param) LogStateWrapper::log_param_single_parse(param) #define log_param_pair_parse(...) LogStateWrapper::log_param_pair_parse(__VA_ARGS__) @@ -858,7 +866,9 @@ inline void log_print_usage() printf(" -h, --help show this help message and exit\n");*/ /* spacing printf("__-param----------------Description\n");*/ +#ifdef LOG_WITH_TEST printf(" --log-test Run simple logging test\n"); +#endif printf(" --log-disable Disable trace logs\n"); printf(" --log-enable Enable trace logs\n"); printf(" --log-file Specify a log filename (without extension)\n"); From 71c49a692a8b5f533bb6ab83c4d2ebada33f6a90 Mon Sep 17 00:00:00 2001 From: staviq Date: Sat, 16 Sep 2023 18:17:53 +0200 Subject: [PATCH 04/11] simplify tee funcs, LogTargetWrapper yield lock --- common/log.h | 116 +++++++++++++++------------------------------------ 1 file changed, 33 insertions(+), 83 deletions(-) diff --git a/common/log.h b/common/log.h index f48a2956ea326..412824024b643 100644 --- a/common/log.h +++ b/common/log.h @@ -50,7 +50,9 @@ // // -------------------------------- +#ifdef LOG_WITH_TEST inline void log_test(); +#endif class LogTargetWrapper { @@ -68,6 +70,7 @@ class LogTargetWrapper LogTargetWrapper( const std::string && filename ) : LogTargetWrapper(filename) {} + LogTargetWrapper( const std::string & filename ) : _filename(filename) { @@ -88,7 +91,7 @@ class LogTargetWrapper if(_type == Type::File && _handle != nullptr) {std::fclose(_handle);} } - enum Type{ + enum class Type{ Invalid, File, Stream @@ -97,20 +100,10 @@ class LogTargetWrapper public: operator FILE*() { - // Assigning lambda result to a static variable guarantees one time thread-safe execution - // while completly removing the need for conditional if(initialized). - // - // This noticeably reduces performance overhead of LOG macro invocations. - // - // Initializing log file here, prevents creating a file before first LOG use, - // simplifying initial conditions and overrides from command line arguments. - // - // TODO: MSVC - // - static const auto dummy_init __attribute__((unused)) = [&](){ - //std::lock_guard lock(_mutex); + if(!_opened) + { while( _lock.test_and_set(std::memory_order_acquire) ){ std::this_thread::yield(); } - if(!_opened && _type == Type::File) + if(!_opened && _type == Type::File) // check for opened again after acquiring a lock { auto result = std::fopen(_filename.c_str(), "w"); if( result ) @@ -126,14 +119,12 @@ class LogTargetWrapper _opened = true; } _lock.clear(std::memory_order_release); - return _opened.load(); - }(); + } return _handle; } void flush() { - //std::lock_guard lock(_mutex); while( _lock.test_and_set(std::memory_order_acquire) ){ std::this_thread::yield(); } if(_opened && _type != Type::Invalid && _handle) { @@ -143,7 +134,6 @@ class LogTargetWrapper } private: - //std::mutex _mutex; std::atomic_flag _lock = ATOMIC_FLAG_INIT; Type _type {Type::Invalid}; std::string _filename; @@ -153,11 +143,17 @@ class LogTargetWrapper // Utility for synchronizing log configuration state // since std::optional was introduced only in c++17 -enum LogTriState +enum class LogTriState { - LogTriStateSame, - LogTriStateFalse, - LogTriStateTrue + Same, + False, + True +}; + +enum class LogTargetChannel +{ + Logfile, + Screen }; class LogStateWrapper @@ -184,16 +180,15 @@ class LogStateWrapper private: std::mutex _mutex; + std::atomic_flag _lock = ATOMIC_FLAG_INIT; std::atomic _enabled {true}; - std::atomic _global_override_enabled {LogTriState::LogTriStateSame}; + std::atomic _global_override_enabled {LogTriState::Same}; std::set _targets; LogTargetWrapper _null_target {nullptr}; LogTargetWrapper _stderr_target {stderr}; - std::atomic _global_override_target {LogTriState::LogTriStateSame}; + std::atomic _global_override_target {LogTriState::Same}; std::atomic _current_target {&_null_target}; - std::atomic _current_tee_target {&_stderr_target}; std::atomic _stored_target {&_null_target}; - std::atomic _stored_tee_target {&_null_target}; LogTargetWrapper* log_set_target_impl( const std::string && filename ) {return log_set_target_impl(filename);} LogTargetWrapper* log_set_target_impl( const std::string & filename ) {return log_add_select_target(new LogTargetWrapper(filename));} @@ -203,14 +198,14 @@ class LogStateWrapper log_flush_all_targets(); std::lock_guard lock(_mutex); - if( _global_override_target == LogTriState::LogTriStateTrue ) + if( _global_override_target == LogTriState::True ) { - if(_enabled || _global_override_enabled == LogTriState::LogTriStateTrue) + if(_enabled || _global_override_enabled == LogTriState::True) return _current_target; return _stored_target; } - if(_enabled || _global_override_enabled == LogTriState::LogTriStateTrue) + if(_enabled || _global_override_enabled == LogTriState::True) { _current_target.store(target); } @@ -222,39 +217,19 @@ class LogStateWrapper return target; } - LogTargetWrapper* log_set_tee_target_impl( const std::string && filename ) {return log_set_tee_target_impl(filename);} - LogTargetWrapper* log_set_tee_target_impl( const std::string & filename ) {return log_add_select_tee_target(new LogTargetWrapper(filename));} - LogTargetWrapper* log_set_tee_target_impl( FILE* handle ) {return log_add_select_tee_target(new LogTargetWrapper(handle));} - LogTargetWrapper* log_set_tee_target_impl( LogTargetWrapper * target ) - { - log_flush_all_targets(); - std::lock_guard lock(_mutex); - - if(_enabled || _global_override_enabled == LogTriState::LogTriStateTrue) - { - _current_tee_target.store(target); - } - else - { - _stored_tee_target.store(target); - } - - return target; - } - LogTargetWrapper* log_add_select_target(LogTargetWrapper* t) { log_flush_all_targets(); std::lock_guard lock(_mutex); - if( _global_override_target ) + if( _global_override_target == LogTriState::True) { - if(_enabled || _global_override_enabled == LogTriState::LogTriStateTrue) + if(_enabled || _global_override_enabled == LogTriState::True) return _current_target; return _stored_target; } - if(_enabled || _global_override_enabled == LogTriState::LogTriStateTrue) + if(_enabled || _global_override_enabled == LogTriState::True) { _current_target.store(t); } @@ -267,24 +242,6 @@ class LogStateWrapper return t; } - LogTargetWrapper* log_add_select_tee_target(LogTargetWrapper* t) - { - log_flush_all_targets(); - std::lock_guard lock(_mutex); - - if(_enabled || _global_override_enabled == LogTriState::LogTriStateTrue) - { - _current_tee_target.store(t); - } - else - { - _stored_tee_target.store(t); - } - _targets.insert(t); - - return t; - } - void log_flush_all_targets() { std::lock_guard lock(_mutex); @@ -298,7 +255,7 @@ class LogStateWrapper FILE* log_tee_handler_impl() { - return *_current_tee_target; + return _stderr_target; } void log_disable_impl( bool threadsafe = true ) @@ -316,12 +273,10 @@ class LogStateWrapper void log_disable_impl_unsafe() { - if(_enabled && _global_override_enabled != LogTriState::LogTriStateTrue) + if(_enabled && _global_override_enabled != LogTriState::True) { _stored_target.store (_current_target); - _stored_tee_target.store (_current_tee_target); _current_target.store (&_null_target); - _current_tee_target.store (&_stderr_target); _enabled = false; } } @@ -341,10 +296,9 @@ class LogStateWrapper void log_enable_impl_unsafe() { - if(!_enabled && _global_override_enabled != LogTriState::LogTriStateFalse) + if(!_enabled && _global_override_enabled != LogTriState::False) { _current_target.store (_stored_target); - _current_tee_target.store (_stored_tee_target); _enabled = true; } } @@ -363,7 +317,7 @@ class LogStateWrapper { std::lock_guard lock(_mutex); log_disable_impl_unsafe(); - _global_override_enabled = LogTriState::LogTriStateFalse; + _global_override_enabled = LogTriState::False; } return true; } @@ -373,7 +327,7 @@ class LogStateWrapper { std::lock_guard lock(_mutex); log_enable_impl_unsafe(); - _global_override_enabled = LogTriState::LogTriStateTrue; + _global_override_enabled = LogTriState::True; } return true; } @@ -399,7 +353,7 @@ class LogStateWrapper _stored_target.store(t); } _targets.insert(t); - _global_override_target = LogTriState::LogTriStateTrue; + _global_override_target = LogTriState::True; return t; } @@ -443,10 +397,6 @@ class LogStateWrapper static LogTargetWrapper* log_set_target( const std::string & filename ) {return instance().log_set_target_impl(filename);} static LogTargetWrapper* log_set_target( FILE* handle ) {return instance().log_set_target_impl(handle);} static LogTargetWrapper* log_set_target( LogTargetWrapper * target ) {return instance().log_set_target_impl(target);} - static LogTargetWrapper* log_set_tee_target( const std::string && filename ) {return log_set_tee_target(filename);} - static LogTargetWrapper* log_set_tee_target( const std::string & filename ) {return instance().log_set_tee_target_impl(filename);} - static LogTargetWrapper* log_set_tee_target( FILE* handle ) {return instance().log_set_tee_target_impl(handle);} - static LogTargetWrapper* log_set_tee_target( LogTargetWrapper * target ) {return instance().log_set_tee_target_impl(target);} static FILE* log_handler() {return instance().log_handler_impl();} static FILE* log_tee_handler() {return instance().log_tee_handler_impl();} static void log_disable() {instance().log_disable_impl();} From 130f5fb1ed615427bcd9d2085a8d6cc5b4a22607 Mon Sep 17 00:00:00 2001 From: staviq Date: Sat, 16 Sep 2023 19:12:20 +0200 Subject: [PATCH 05/11] mv LogTargetWrapper private, simplify set_target --- common/log.h | 235 ++++++++++++++++++++++----------------------------- 1 file changed, 101 insertions(+), 134 deletions(-) diff --git a/common/log.h b/common/log.h index 412824024b643..774cb568cb020 100644 --- a/common/log.h +++ b/common/log.h @@ -54,93 +54,6 @@ inline void log_test(); #endif -class LogTargetWrapper -{ - private: - LogTargetWrapper( LogTargetWrapper& other ) = delete; - void operator=( const LogTargetWrapper& ) = delete; - - public: - LogTargetWrapper( FILE* handle ) - : _type(Type::Stream), - _opened(true), - _handle(handle) - {} - - LogTargetWrapper( const std::string && filename ) - : LogTargetWrapper(filename) - {} - - LogTargetWrapper( const std::string & filename ) - : _filename(filename) - { - if(_filename.empty()) - { - _type = Type::Stream; - _handle = stderr; - _opened = true; - } - else - { - _type = Type::File; - } - } - - ~LogTargetWrapper() - { - if(_type == Type::File && _handle != nullptr) {std::fclose(_handle);} - } - - enum class Type{ - Invalid, - File, - Stream - }; - - public: - operator FILE*() - { - if(!_opened) - { - while( _lock.test_and_set(std::memory_order_acquire) ){ std::this_thread::yield(); } - if(!_opened && _type == Type::File) // check for opened again after acquiring a lock - { - auto result = std::fopen(_filename.c_str(), "w"); - if( result ) - { - _handle = result; - } - else - { - std::fprintf(stderr, "Failed to open logfile '%s' with error '%s'\n", _filename.c_str(), std::strerror(errno)); - std::fflush(stderr); - _handle = stderr; - } - _opened = true; - } - _lock.clear(std::memory_order_release); - } - return _handle; - } - - void flush() - { - while( _lock.test_and_set(std::memory_order_acquire) ){ std::this_thread::yield(); } - if(_opened && _type != Type::Invalid && _handle) - { - std::fflush(_handle); - } - _lock.clear(std::memory_order_release); - } - - private: - std::atomic_flag _lock = ATOMIC_FLAG_INIT; - Type _type {Type::Invalid}; - std::string _filename; - std::atomic _opened {false}; - std::atomic _handle {nullptr}; -}; - // Utility for synchronizing log configuration state // since std::optional was introduced only in c++17 enum class LogTriState @@ -161,7 +74,7 @@ class LogStateWrapper protected: LogStateWrapper(){}; - virtual ~LogStateWrapper() + ~LogStateWrapper() { log_flush_all_targets(); for(auto t: _targets){delete t;} @@ -178,6 +91,95 @@ class LogStateWrapper return inst; } + class LogTargetWrapper + { + private: + LogTargetWrapper( LogTargetWrapper& other ) = delete; + void operator=( const LogTargetWrapper& ) = delete; + + public: + LogTargetWrapper( FILE* handle ) + : _type(Type::Stream), + _opened(true), + _handle(handle) + {} + + LogTargetWrapper( const std::string && filename ) + : LogTargetWrapper(filename) + {} + + LogTargetWrapper( const std::string & filename ) + : _filename(filename) + { + if(_filename.empty()) + { + _type = Type::Stream; + _handle = stderr; + _opened = true; + } + else + { + _type = Type::File; + } + } + + ~LogTargetWrapper() + { + if(_type == Type::File && _handle != nullptr) {std::fclose(_handle);} + } + + enum class Type{ + Invalid, + File, + Stream + }; + + public: + operator FILE*() + { + if(!_opened) + { + while( _lock.test_and_set(std::memory_order_acquire) ){ std::this_thread::yield(); } + if(!_opened && _type == Type::File) // check for opened again after acquiring a lock + { + auto result = std::fopen(_filename.c_str(), "w"); + if( result ) + { + _handle = result; + } + else + { + std::fprintf(stderr, "Failed to open logfile '%s' with error '%s'\n", _filename.c_str(), std::strerror(errno)); + std::fflush(stderr); + _handle = stderr; + } + _opened = true; + } + _lock.clear(std::memory_order_release); + } + return _handle; + } + + void flush() + { + while( _lock.test_and_set(std::memory_order_acquire) ){ std::this_thread::yield(); } + if(_opened && _type != Type::Invalid && _handle) + { + std::fflush(_handle); + } + _lock.clear(std::memory_order_release); + } + + private: + std::atomic_flag _lock = ATOMIC_FLAG_INIT; + Type _type {Type::Invalid}; + std::string _filename; + std::atomic _opened {false}; + std::atomic _handle {nullptr}; + + //friend class LogStateWrapper; + }; + private: std::mutex _mutex; std::atomic_flag _lock = ATOMIC_FLAG_INIT; @@ -191,53 +193,25 @@ class LogStateWrapper std::atomic _stored_target {&_null_target}; LogTargetWrapper* log_set_target_impl( const std::string && filename ) {return log_set_target_impl(filename);} - LogTargetWrapper* log_set_target_impl( const std::string & filename ) {return log_add_select_target(new LogTargetWrapper(filename));} - LogTargetWrapper* log_set_target_impl( FILE* handle ) {return log_add_select_target(new LogTargetWrapper(handle));} - LogTargetWrapper* log_set_target_impl( LogTargetWrapper * target ) - { - log_flush_all_targets(); - std::lock_guard lock(_mutex); + LogTargetWrapper* log_set_target_impl( const std::string & filename ) {return log_add_select_target(new LogTargetWrapper(filename), true);} + LogTargetWrapper* log_set_target_impl( FILE* handle ) {return log_add_select_target(new LogTargetWrapper(handle), true);} + LogTargetWrapper* log_set_target_impl( LogTargetWrapper * target ) {return log_add_select_target(target);} - if( _global_override_target == LogTriState::True ) - { - if(_enabled || _global_override_enabled == LogTriState::True) - return _current_target; - return _stored_target; - } - - if(_enabled || _global_override_enabled == LogTriState::True) - { - _current_target.store(target); - } - else - { - _stored_target.store(target); - } - - return target; - } - - LogTargetWrapper* log_add_select_target(LogTargetWrapper* t) + LogTargetWrapper* log_add_select_target(LogTargetWrapper* t, bool insert = false) { log_flush_all_targets(); std::lock_guard lock(_mutex); if( _global_override_target == LogTriState::True) { - if(_enabled || _global_override_enabled == LogTriState::True) - return _current_target; + if(_enabled || _global_override_enabled == LogTriState::True) return _current_target; return _stored_target; } - if(_enabled || _global_override_enabled == LogTriState::True) - { - _current_target.store(t); - } - else - { - _stored_target.store(t); - } - _targets.insert(t); + if(_enabled || _global_override_enabled == LogTriState::True) _current_target.store(t); + else _stored_target.store(t); + + if(insert) _targets.insert(t); return t; } @@ -248,15 +222,8 @@ class LogStateWrapper for(auto t: _targets){ t->flush(); } } - FILE* log_handler_impl() - { - return *_current_target; - } - - FILE* log_tee_handler_impl() - { - return _stderr_target; - } + FILE* log_handler_impl() { return *_current_target; } + FILE* log_tee_handler_impl() { return _stderr_target; } void log_disable_impl( bool threadsafe = true ) { From 9f630c6681dbd7debcdc340c32b84809179c7c6f Mon Sep 17 00:00:00 2001 From: staviq Date: Sat, 16 Sep 2023 20:37:38 +0200 Subject: [PATCH 06/11] formatting --- common/log.h | 84 +++++++++++++++++++++++++++------------------------- 1 file changed, 44 insertions(+), 40 deletions(-) diff --git a/common/log.h b/common/log.h index 774cb568cb020..bd5ac3a7c9ba9 100644 --- a/common/log.h +++ b/common/log.h @@ -77,15 +77,15 @@ class LogStateWrapper ~LogStateWrapper() { log_flush_all_targets(); - for(auto t: _targets){delete t;} + for(auto t : _targets){ delete t; } } private: - LogStateWrapper( LogStateWrapper& other ) = delete; - void operator=( const LogStateWrapper& ) = delete; + LogStateWrapper(LogStateWrapper & other) = delete; + void operator=(const LogStateWrapper &) = delete; private: - static LogStateWrapper& instance() + static LogStateWrapper & instance() { static LogStateWrapper inst; return inst; @@ -94,21 +94,21 @@ class LogStateWrapper class LogTargetWrapper { private: - LogTargetWrapper( LogTargetWrapper& other ) = delete; - void operator=( const LogTargetWrapper& ) = delete; + LogTargetWrapper(LogTargetWrapper & other) = delete; + void operator=(const LogTargetWrapper &) = delete; public: - LogTargetWrapper( FILE* handle ) + LogTargetWrapper(FILE* handle) : _type(Type::Stream), _opened(true), _handle(handle) {} - LogTargetWrapper( const std::string && filename ) + LogTargetWrapper(const std::string && filename) : LogTargetWrapper(filename) {} - LogTargetWrapper( const std::string & filename ) + LogTargetWrapper(const std::string & filename) : _filename(filename) { if(_filename.empty()) @@ -125,7 +125,7 @@ class LogStateWrapper ~LogTargetWrapper() { - if(_type == Type::File && _handle != nullptr) {std::fclose(_handle);} + if(_type == Type::File && _handle != nullptr) { std::fclose(_handle); } } enum class Type{ @@ -139,17 +139,21 @@ class LogStateWrapper { if(!_opened) { - while( _lock.test_and_set(std::memory_order_acquire) ){ std::this_thread::yield(); } + while(_lock.test_and_set(std::memory_order_acquire)){ std::this_thread::yield(); } if(!_opened && _type == Type::File) // check for opened again after acquiring a lock { auto result = std::fopen(_filename.c_str(), "w"); - if( result ) + if(result) { _handle = result; } else { - std::fprintf(stderr, "Failed to open logfile '%s' with error '%s'\n", _filename.c_str(), std::strerror(errno)); + std::fprintf( + stderr, + "Failed to open logfile '%s' with error '%s'\n", + _filename.c_str(), std::strerror(errno) + ); std::fflush(stderr); _handle = stderr; } @@ -162,7 +166,7 @@ class LogStateWrapper void flush() { - while( _lock.test_and_set(std::memory_order_acquire) ){ std::this_thread::yield(); } + while(_lock.test_and_set(std::memory_order_acquire)){ std::this_thread::yield(); } if(_opened && _type != Type::Invalid && _handle) { std::fflush(_handle); @@ -192,17 +196,17 @@ class LogStateWrapper std::atomic _current_target {&_null_target}; std::atomic _stored_target {&_null_target}; - LogTargetWrapper* log_set_target_impl( const std::string && filename ) {return log_set_target_impl(filename);} - LogTargetWrapper* log_set_target_impl( const std::string & filename ) {return log_add_select_target(new LogTargetWrapper(filename), true);} - LogTargetWrapper* log_set_target_impl( FILE* handle ) {return log_add_select_target(new LogTargetWrapper(handle), true);} - LogTargetWrapper* log_set_target_impl( LogTargetWrapper * target ) {return log_add_select_target(target);} + LogTargetWrapper* log_set_target_impl(const std::string && filename) { return log_set_target_impl(filename); } + LogTargetWrapper* log_set_target_impl(const std::string & filename) { return log_add_select_target(new LogTargetWrapper(filename), true); } + LogTargetWrapper* log_set_target_impl(FILE* handle) { return log_add_select_target(new LogTargetWrapper(handle), true); } + LogTargetWrapper* log_set_target_impl(LogTargetWrapper * target) { return log_add_select_target(target); } LogTargetWrapper* log_add_select_target(LogTargetWrapper* t, bool insert = false) { log_flush_all_targets(); std::lock_guard lock(_mutex); - if( _global_override_target == LogTriState::True) + if(_global_override_target == LogTriState::True) { if(_enabled || _global_override_enabled == LogTriState::True) return _current_target; return _stored_target; @@ -219,15 +223,15 @@ class LogStateWrapper void log_flush_all_targets() { std::lock_guard lock(_mutex); - for(auto t: _targets){ t->flush(); } + for(auto t : _targets){ t->flush(); } } FILE* log_handler_impl() { return *_current_target; } FILE* log_tee_handler_impl() { return _stderr_target; } - void log_disable_impl( bool threadsafe = true ) + void log_disable_impl(bool threadsafe = true) { - if( threadsafe ) + if(threadsafe) { std::lock_guard lock(_mutex); log_disable_impl_unsafe(); @@ -248,9 +252,9 @@ class LogStateWrapper } } - void log_enable_impl( bool threadsafe = true ) + void log_enable_impl(bool threadsafe = true) { - if( threadsafe ) + if(threadsafe) { std::lock_guard lock(_mutex); log_enable_impl_unsafe(); @@ -273,13 +277,13 @@ class LogStateWrapper bool log_param_single_parse_impl(const std::string & param) { #ifdef LOG_WITH_TEST - if ( param == "--log-test") + if (param == "--log-test") { log_test(); return true; } #endif - if ( param == "--log-disable") + if (param == "--log-disable") { { std::lock_guard lock(_mutex); @@ -289,7 +293,7 @@ class LogStateWrapper return true; } - if ( param == "--log-enable") + if (param == "--log-enable") { { std::lock_guard lock(_mutex); @@ -304,7 +308,7 @@ class LogStateWrapper bool log_param_pair_parse_impl(bool check_but_dont_parse, const std::string & param, const std::string & next = std::string()) { - if ( param == "--log-file") + if (param == "--log-file") { if (!check_but_dont_parse) { @@ -360,20 +364,20 @@ class LogStateWrapper } public: - static LogTargetWrapper* log_set_target( const std::string && filename ) {return log_set_target(filename);} - static LogTargetWrapper* log_set_target( const std::string & filename ) {return instance().log_set_target_impl(filename);} - static LogTargetWrapper* log_set_target( FILE* handle ) {return instance().log_set_target_impl(handle);} - static LogTargetWrapper* log_set_target( LogTargetWrapper * target ) {return instance().log_set_target_impl(target);} - static FILE* log_handler() {return instance().log_handler_impl();} - static FILE* log_tee_handler() {return instance().log_tee_handler_impl();} - static void log_disable() {instance().log_disable_impl();} - static void log_enable() {instance().log_enable_impl();} - static bool log_param_single_parse(const std::string & param) {return instance().log_param_single_parse_impl(param);} + static LogTargetWrapper* log_set_target(const std::string && filename) { return log_set_target(filename); } + static LogTargetWrapper* log_set_target(const std::string & filename) { return instance().log_set_target_impl(filename); } + static LogTargetWrapper* log_set_target(FILE* handle) { return instance().log_set_target_impl(handle); } + static LogTargetWrapper* log_set_target(LogTargetWrapper * target) { return instance().log_set_target_impl(target); } + static FILE* log_handler() { return instance().log_handler_impl(); } + static FILE* log_tee_handler() { return instance().log_tee_handler_impl(); } + static void log_disable() { instance().log_disable_impl(); } + static void log_enable() { instance().log_enable_impl(); } + static bool log_param_single_parse(const std::string & param) { return instance().log_param_single_parse_impl(param); } static bool log_param_pair_parse(bool check_but_dont_parse, const std::string & param, const std::string & next = std::string()) - {return instance().log_param_pair_parse_impl(check_but_dont_parse,param,next);} + { return instance().log_param_pair_parse_impl(check_but_dont_parse,param,next); } static std::string log_filename_generator(const std::string & basename, const std::string & extension) - {return instance().log_filename_generator_impl(basename,extension);} - static std::string log_get_pid() {return instance().log_get_pid_impl();} + { return instance().log_filename_generator_impl(basename,extension); } + static std::string log_get_pid() { return instance().log_get_pid_impl(); } }; // Specifies a log target. From 28cdd8c3b09235dbf11d97ca448e618266004a78 Mon Sep 17 00:00:00 2001 From: staviq Date: Sat, 16 Sep 2023 22:36:04 +0200 Subject: [PATCH 07/11] formatting --- common/common.cpp | 4 +- common/log.h | 222 +++++++++++++++++++++++++++++++--------------- 2 files changed, 154 insertions(+), 72 deletions(-) diff --git a/common/common.cpp b/common/common.cpp index 6d655fd5548c5..49e47cc9fc3b0 100644 --- a/common/common.cpp +++ b/common/common.cpp @@ -550,7 +550,7 @@ bool gpt_params_parse(int argc, char ** argv, gpt_params & params) { } else if ( log_param_single_parse( argv[i] ) ) { // Do nothing, log_param_single_parse automatically does it's thing // and returns if a match was found and parsed. - } else if ( log_param_pair_parse( /*check_but_dont_parse*/ true, argv[i] ) ) { + } else if ( log_param_pair_parse( /*parse*/ false, argv[i] ) ) { // We have a matching known parameter requiring an argument, // now we need to check if there is anything after this argv // and flag invalid_param or parse it. @@ -558,7 +558,7 @@ bool gpt_params_parse(int argc, char ** argv, gpt_params & params) { invalid_param = true; break; } - if( !log_param_pair_parse( /*check_but_dont_parse*/ false, argv[i-1], argv[i]) ) { + if( !log_param_pair_parse( /*parse*/ true, argv[i-1], argv[i]) ) { invalid_param = true; break; } diff --git a/common/log.h b/common/log.h index bd5ac3a7c9ba9..5ed67a6646713 100644 --- a/common/log.h +++ b/common/log.h @@ -98,7 +98,7 @@ class LogStateWrapper void operator=(const LogTargetWrapper &) = delete; public: - LogTargetWrapper(FILE* handle) + LogTargetWrapper(FILE * handle) : _type(Type::Stream), _opened(true), _handle(handle) @@ -135,7 +135,7 @@ class LogStateWrapper }; public: - operator FILE*() + operator FILE * () { if(!_opened) { @@ -196,12 +196,27 @@ class LogStateWrapper std::atomic _current_target {&_null_target}; std::atomic _stored_target {&_null_target}; - LogTargetWrapper* log_set_target_impl(const std::string && filename) { return log_set_target_impl(filename); } - LogTargetWrapper* log_set_target_impl(const std::string & filename) { return log_add_select_target(new LogTargetWrapper(filename), true); } - LogTargetWrapper* log_set_target_impl(FILE* handle) { return log_add_select_target(new LogTargetWrapper(handle), true); } - LogTargetWrapper* log_set_target_impl(LogTargetWrapper * target) { return log_add_select_target(target); } + LogTargetWrapper * log_set_target_impl(const std::string && filename) + { + return log_set_target_impl(filename); + } + + LogTargetWrapper * log_set_target_impl(const std::string & filename) + { + return log_add_select_target(new LogTargetWrapper(filename), true); + } + + LogTargetWrapper * log_set_target_impl(FILE * handle) + { + return log_add_select_target(new LogTargetWrapper(handle), true); + } + + LogTargetWrapper * log_set_target_impl(LogTargetWrapper * target) + { + return log_add_select_target(target); + } - LogTargetWrapper* log_add_select_target(LogTargetWrapper* t, bool insert = false) + LogTargetWrapper * log_add_select_target(LogTargetWrapper * t, bool insert = false) { log_flush_all_targets(); std::lock_guard lock(_mutex); @@ -226,8 +241,8 @@ class LogStateWrapper for(auto t : _targets){ t->flush(); } } - FILE* log_handler_impl() { return *_current_target; } - FILE* log_tee_handler_impl() { return _stderr_target; } + FILE * log_handler_impl() { return *_current_target; } + FILE * log_tee_handler_impl() { return _stderr_target; } void log_disable_impl(bool threadsafe = true) { @@ -306,11 +321,11 @@ class LogStateWrapper return false; } - bool log_param_pair_parse_impl(bool check_but_dont_parse, const std::string & param, const std::string & next = std::string()) + bool log_param_pair_parse_impl(bool parse, const std::string & param, const std::string & next = std::string()) { if (param == "--log-file") { - if (!check_but_dont_parse) + if (parse) { log_flush_all_targets(); std::lock_guard lock(_mutex); @@ -364,20 +379,65 @@ class LogStateWrapper } public: - static LogTargetWrapper* log_set_target(const std::string && filename) { return log_set_target(filename); } - static LogTargetWrapper* log_set_target(const std::string & filename) { return instance().log_set_target_impl(filename); } - static LogTargetWrapper* log_set_target(FILE* handle) { return instance().log_set_target_impl(handle); } - static LogTargetWrapper* log_set_target(LogTargetWrapper * target) { return instance().log_set_target_impl(target); } - static FILE* log_handler() { return instance().log_handler_impl(); } - static FILE* log_tee_handler() { return instance().log_tee_handler_impl(); } - static void log_disable() { instance().log_disable_impl(); } - static void log_enable() { instance().log_enable_impl(); } - static bool log_param_single_parse(const std::string & param) { return instance().log_param_single_parse_impl(param); } - static bool log_param_pair_parse(bool check_but_dont_parse, const std::string & param, const std::string & next = std::string()) - { return instance().log_param_pair_parse_impl(check_but_dont_parse,param,next); } - static std::string log_filename_generator(const std::string & basename, const std::string & extension) - { return instance().log_filename_generator_impl(basename,extension); } - static std::string log_get_pid() { return instance().log_get_pid_impl(); } + static LogTargetWrapper * log_set_target(const std::string &&filename) + { + return log_set_target(filename); + } + + static LogTargetWrapper * log_set_target(const std::string &filename) + { + return instance().log_set_target_impl(filename); + } + + static LogTargetWrapper * log_set_target(FILE * handle) + { + return instance().log_set_target_impl(handle); + } + + static LogTargetWrapper * log_set_target(LogTargetWrapper * target) + { + return instance().log_set_target_impl(target); + } + + static FILE * log_handler() + { + return instance().log_handler_impl(); + } + + static FILE * log_tee_handler() + { + return instance().log_tee_handler_impl(); + } + + static void log_disable() + { + instance().log_disable_impl(); + } + + static void log_enable() + { + instance().log_enable_impl(); + } + + static bool log_param_single_parse(const std::string ¶m) + { + return instance().log_param_single_parse_impl(param); + } + + static bool log_param_pair_parse(bool parse, const std::string & param, const std::string & next = "") + { + return instance().log_param_pair_parse_impl(parse, param, next); + } + + static std::string log_filename_generator(const std::string & basename, const std::string & extension) + { + return instance().log_filename_generator_impl(basename, extension); + } + + static std::string log_get_pid() + { + return instance().log_get_pid_impl(); + } }; // Specifies a log target. @@ -434,7 +494,8 @@ class LogStateWrapper // invocation with log_filename_generator( "llama", "log" ) creates a string "llama..log" // where the number is a runtime id of the current thread. -#define log_filename_generator(log_file_basename, log_file_extension) LogStateWrapper::log_filename_generator(log_file_basename, log_file_extension) +#define log_filename_generator(log_file_basename, log_file_extension) \ + LogStateWrapper::log_filename_generator(log_file_basename, log_file_extension) // #ifndef LOG_DEFAULT_FILE_NAME // #define LOG_DEFAULT_FILE_NAME log_filename_generator("llama", "log") @@ -448,6 +509,13 @@ class LogStateWrapper #define LOG_TEE_TARGET_STRING LOG_STRINGIZE(LOG_TEE_TARGET) +#define LOG_TIMESTAMP \ + ( \ + std::chrono::duration_cast>( \ + std::chrono::system_clock::now().time_since_epoch() \ + ) \ + ).count() + // Allows disabling timestamps. // in order to disable, define LOG_NO_TIMESTAMPS // like so: @@ -458,10 +526,10 @@ class LogStateWrapper #ifndef LOG_NO_TIMESTAMPS #ifndef _MSC_VER #define LOG_TIMESTAMP_FMT "[%" PRIu64 "] " - #define LOG_TIMESTAMP_VAL , (std::chrono::duration_cast>(std::chrono::system_clock::now().time_since_epoch())).count() + #define LOG_TIMESTAMP_VAL , LOG_TIMESTAMP #else #define LOG_TIMESTAMP_FMT "[%" PRIu64 "] " - #define LOG_TIMESTAMP_VAL , (std::chrono::duration_cast>(std::chrono::system_clock::now().time_since_epoch())).count() + #define LOG_TIMESTAMP_VAL , LOG_TIMESTAMP #endif #else #define LOG_TIMESTAMP_FMT "%s" @@ -471,10 +539,10 @@ class LogStateWrapper #ifdef LOG_TEE_TIMESTAMPS #ifndef _MSC_VER #define LOG_TEE_TIMESTAMP_FMT "[%" PRIu64 "] " - #define LOG_TEE_TIMESTAMP_VAL , (std::chrono::duration_cast>(std::chrono::system_clock::now().time_since_epoch())).count() + #define LOG_TEE_TIMESTAMP_VAL , LOG_TIMESTAMP #else #define LOG_TEE_TIMESTAMP_FMT "[%" PRIu64 "] " - #define LOG_TEE_TIMESTAMP_VAL , (std::chrono::duration_cast>(std::chrono::system_clock::now().time_since_epoch())).count() + #define LOG_TEE_TIMESTAMP_VAL , LOG_TIMESTAMP #endif #else #define LOG_TEE_TIMESTAMP_FMT "%s" @@ -517,23 +585,37 @@ class LogStateWrapper // INTERNAL, DO NOT USE // USE LOG() INSTEAD // + +#define LOG_FPRINTF_PARAMS_IMPL_GNU(str) \ + LOG_TIMESTAMP_FMT LOG_FLF_FMT str "%s" LOG_TIMESTAMP_VAL LOG_FLF_VAL + +#define LOG_FPRINTF_PARAMS_IMPL_MSVC(str) \ + LOG_TIMESTAMP_FMT LOG_FLF_FMT str "%s" LOG_TIMESTAMP_VAL LOG_FLF_VAL "" + +#define LOG_FPRINTF_PARAMS_TEE_IMPL_GNU(str) \ + LOG_TEE_TIMESTAMP_FMT LOG_TEE_FLF_FMT str "%s" LOG_TEE_TIMESTAMP_VAL LOG_TEE_FLF_VAL + +#define LOG_FPRINTF_PARAMS_TEE_IMPL_MSVC(str) \ + LOG_TEE_TIMESTAMP_FMT LOG_TEE_FLF_FMT str "%s" LOG_TEE_TIMESTAMP_VAL LOG_TEE_FLF_VAL "" + + #ifndef _MSC_VER - #define LOG_IMPL(str, ...) \ - { \ - if (LOG_TARGET != nullptr) \ - { \ - fprintf(LOG_TARGET, LOG_TIMESTAMP_FMT LOG_FLF_FMT str "%s" LOG_TIMESTAMP_VAL LOG_FLF_VAL, __VA_ARGS__); \ - fflush(LOG_TARGET); \ - } \ + #define LOG_IMPL(str, ...) \ + { \ + if (LOG_TARGET != nullptr) \ + { \ + fprintf(LOG_TARGET, LOG_FPRINTF_PARAMS_IMPL_GNU(str), __VA_ARGS__); \ + fflush(LOG_TARGET); \ + } \ } #else - #define LOG_IMPL(str, ...) \ - { \ - if (LOG_TARGET != nullptr) \ - { \ - fprintf(LOG_TARGET, LOG_TIMESTAMP_FMT LOG_FLF_FMT str "%s" LOG_TIMESTAMP_VAL LOG_FLF_VAL "", ##__VA_ARGS__); \ - fflush(LOG_TARGET); \ - } \ + #define LOG_IMPL(str, ...) \ + { \ + if (LOG_TARGET != nullptr) \ + { \ + fprintf(LOG_TARGET, LOG_FPRINTF_PARAMS_IMPL_MSVC(str), ##__VA_ARGS__); \ + fflush(LOG_TARGET); \ + } \ } #endif @@ -541,32 +623,32 @@ class LogStateWrapper // USE LOG_TEE() INSTEAD // #ifndef _MSC_VER - #define LOG_TEE_IMPL(str, ...) \ - { \ - if (LOG_TARGET != nullptr) \ - { \ - fprintf(LOG_TARGET, LOG_TIMESTAMP_FMT LOG_FLF_FMT str "%s" LOG_TIMESTAMP_VAL LOG_FLF_VAL, __VA_ARGS__); \ - fflush(LOG_TARGET); \ - } \ - if (LOG_TARGET != stdout && LOG_TARGET != stderr && LOG_TEE_TARGET != nullptr) \ - { \ - fprintf(LOG_TEE_TARGET, LOG_TEE_TIMESTAMP_FMT LOG_TEE_FLF_FMT str "%s" LOG_TEE_TIMESTAMP_VAL LOG_TEE_FLF_VAL, __VA_ARGS__); \ - fflush(LOG_TEE_TARGET); \ - } \ + #define LOG_TEE_IMPL(str, ...) \ + { \ + if (LOG_TARGET != nullptr) \ + { \ + fprintf(LOG_TARGET, LOG_FPRINTF_PARAMS_IMPL_GNU(str), __VA_ARGS__); \ + fflush(LOG_TARGET); \ + } \ + if (LOG_TARGET != stdout && LOG_TARGET != stderr && LOG_TEE_TARGET != nullptr) \ + { \ + fprintf(LOG_TEE_TARGET, LOG_FPRINTF_PARAMS_TEE_IMPL_GNU(str), __VA_ARGS__); \ + fflush(LOG_TEE_TARGET); \ + } \ } #else - #define LOG_TEE_IMPL(str, ...) \ - { \ - if (LOG_TARGET != nullptr) \ - { \ - fprintf(LOG_TARGET, LOG_TIMESTAMP_FMT LOG_FLF_FMT str "%s" LOG_TIMESTAMP_VAL LOG_FLF_VAL "", ##__VA_ARGS__); \ - fflush(LOG_TARGET); \ - } \ - if (LOG_TARGET != stdout && LOG_TARGET != stderr && LOG_TEE_TARGET != nullptr) \ - { \ - fprintf(LOG_TEE_TARGET, LOG_TEE_TIMESTAMP_FMT LOG_TEE_FLF_FMT str "%s" LOG_TEE_TIMESTAMP_VAL LOG_TEE_FLF_VAL "", ##__VA_ARGS__); \ - fflush(LOG_TEE_TARGET); \ - } \ + #define LOG_TEE_IMPL(str, ...) \ + { \ + if (LOG_TARGET != nullptr) \ + { \ + fprintf(LOG_TARGET, LOG_FPRINTF_PARAMS_IMPL_MSVC(str), ##__VA_ARGS__); \ + fflush(LOG_TARGET); \ + } \ + if (LOG_TARGET != stdout && LOG_TARGET != stderr && LOG_TEE_TARGET != nullptr) \ + { \ + fprintf(LOG_TEE_TARGET, LOG_FPRINTF_PARAMS_TEE_IMPL_MSVC(str), ##__VA_ARGS__); \ + fflush(LOG_TEE_TARGET); \ + } \ } #endif @@ -793,13 +875,13 @@ inline void log_print_usage() printf(" --log-disable Disable trace logs\n"); printf(" --log-enable Enable trace logs\n"); printf(" --log-file Specify a log filename (without extension)\n"); - printf(" Log file will be tagged with unique ID and written as \"..log\"\n"); /* */ + printf(" Log file will be tagged with unique ID and written as \"..log\"\n"); } #define log_dump_cmdline(argc, argv) log_dump_cmdline_impl(argc, argv) // INTERNAL, DO NOT USE -inline void log_dump_cmdline_impl(int argc, char **argv) +inline void log_dump_cmdline_impl(int argc, char ** argv) { std::stringstream buf; for (int i = 0; i < argc; ++i) From 06e5c1902ab24d0a8f8f76c2cce285e9fd72c9da Mon Sep 17 00:00:00 2001 From: staviq Date: Sun, 17 Sep 2023 14:45:25 +0200 Subject: [PATCH 08/11] formatting: break overly long LOG lines --- examples/main/main.cpp | 32 +++++++++++++++++++++------- examples/speculative/speculative.cpp | 26 ++++++++++++++++------ 2 files changed, 44 insertions(+), 14 deletions(-) diff --git a/examples/main/main.cpp b/examples/main/main.cpp index d78112260de08..44745c8dfbc51 100644 --- a/examples/main/main.cpp +++ b/examples/main/main.cpp @@ -298,8 +298,11 @@ int main(int argc, char ** argv) { } else if (n_matching_session_tokens >= embd_inp.size()) { LOG_TEE("%s: session file has exact match for prompt!\n", __func__); } else if (n_matching_session_tokens < (embd_inp.size() / 2)) { - LOG_TEE("%s: warning: session file has low similarity to prompt (%zu / %zu tokens); will mostly be reevaluated\n", - __func__, n_matching_session_tokens, embd_inp.size()); + LOG_TEE( + "%s: warning: session file has low similarity to prompt (%zu / %zu tokens);" + " will mostly be reevaluated\n", + __func__, n_matching_session_tokens, embd_inp.size() + ); } else { LOG_TEE("%s: session file matches %zu / %zu tokens of prompt\n", __func__, n_matching_session_tokens, embd_inp.size()); @@ -307,8 +310,10 @@ int main(int argc, char ** argv) { } LOGLN( - "recalculate the cached logits (check): embd_inp.empty() %s, n_matching_session_tokens %zu, embd_inp.size() %zu, session_tokens.size() %zu, embd_inp.size() %zu", - log_tostr(embd_inp.empty()), n_matching_session_tokens, embd_inp.size(), session_tokens.size(), embd_inp.size()); + "recalculate the cached logits (check): embd_inp.empty() %s, n_matching_session_tokens %zu," + " embd_inp.size() %zu, session_tokens.size() %zu, embd_inp.size() %zu", + log_tostr(embd_inp.empty()), n_matching_session_tokens, embd_inp.size(), session_tokens.size(), embd_inp.size() + ); // if we will use the cache for the full prompt without reaching the end of the cache, force // reevaluation of the last token token to recalculate the cached logits @@ -402,9 +407,17 @@ int main(int argc, char ** argv) { LOG_TEE("Input suffix: '%s'\n", params.input_suffix.c_str()); } } - LOG_TEE("sampling: repeat_last_n = %d, repeat_penalty = %f, presence_penalty = %f, frequency_penalty = %f, top_k = %d, tfs_z = %f, top_p = %f, typical_p = %f, temp = %f, mirostat = %d, mirostat_lr = %f, mirostat_ent = %f\n", - params.repeat_last_n, params.repeat_penalty, params.presence_penalty, params.frequency_penalty, params.top_k, params.tfs_z, params.top_p, params.typical_p, params.temp, params.mirostat, params.mirostat_eta, params.mirostat_tau); - LOG_TEE("generate: n_ctx = %d, n_batch = %d, n_predict = %d, n_keep = %d\n", n_ctx, params.n_batch, params.n_predict, params.n_keep); + LOG_TEE( + "sampling: repeat_last_n = %d, repeat_penalty = %f, presence_penalty = %f," + " frequency_penalty = %f, top_k = %d, tfs_z = %f, top_p = %f, typical_p = %f," + " temp = %f, mirostat = %d, mirostat_lr = %f, mirostat_ent = %f\n", + params.repeat_last_n, params.repeat_penalty, params.presence_penalty, + params.frequency_penalty, params.top_k, params.tfs_z, params.top_p, params.typical_p, + params.temp, params.mirostat, params.mirostat_eta, params.mirostat_tau + ); + LOG_TEE( + "generate: n_ctx = %d, n_batch = %d, n_predict = %d, n_keep = %d\n", + n_ctx, params.n_batch, params.n_predict, params.n_keep); LOG_TEE("\n\n"); struct llama_grammar * grammar = NULL; @@ -509,7 +522,10 @@ int main(int argc, char ** argv) { } const int n_left = n_past - params.n_keep; - LOG("context full, swapping: n_past = %d, n_left = %d, n_ctx = %d, n_keep = %d\n", n_past, n_left, n_ctx, params.n_keep); + LOG( + "context full, swapping: n_past = %d, n_left = %d, n_ctx = %d, n_keep = %d\n", + n_past, n_left, n_ctx, params.n_keep + ); // always keep the first token - BOS n_past = std::max(1, params.n_keep); diff --git a/examples/speculative/speculative.cpp b/examples/speculative/speculative.cpp index aa904183fa2d8..d7e222ffbac52 100644 --- a/examples/speculative/speculative.cpp +++ b/examples/speculative/speculative.cpp @@ -154,7 +154,10 @@ int main(int argc, char ** argv) { // check if the draft matches the target if (i_dft < (int) drafted.size() && id == drafted[i_dft]) { - LOG("the sampled target token matches the %dth drafted token (%d, '%s') - accepted\n", i_dft, id, token_str.c_str()); + LOG( + "the sampled target token matches the %dth drafted token (%d, '%s') - accepted\n", + i_dft, id, token_str.c_str() + ); ++n_accept; ++n_past_tgt; ++n_past_dft; @@ -166,8 +169,10 @@ int main(int argc, char ** argv) { // the drafted token was rejected or we are out of drafted tokens if (i_dft < (int) drafted.size()) { - LOG("the %dth drafted token (%d, '%s') does not match the sampled target token (%d, '%s') - rejected\n", - i_dft, drafted[i_dft], llama_token_to_piece(ctx_dft, drafted[i_dft]).c_str(), id, token_str.c_str()); + LOG( + "the %dth drafted token (%d, '%s') does not match the sampled target token (%d, '%s') - rejected\n", + i_dft, drafted[i_dft], llama_token_to_piece(ctx_dft, drafted[i_dft]).c_str(), id, token_str.c_str() + ); } else { LOG("out of drafted tokens\n"); } @@ -235,7 +240,10 @@ int main(int argc, char ** argv) { llama_sample_softmax(ctx_dft, &cur_p); for (int i = 0; i < 3; ++i) { - LOG(" - draft candidate %3d: %6d (%8.3f) '%s'\n", i, cur_p.data[i].id, cur_p.data[i].p, llama_token_to_piece(ctx_dft, cur_p.data[i].id).c_str()); + LOG( + " - draft candidate %3d: %6d (%8.3f) '%s'\n", + i, cur_p.data[i].id, cur_p.data[i].p, llama_token_to_piece(ctx_dft, cur_p.data[i].id).c_str() + ); } // TODO: better logic? @@ -276,8 +284,14 @@ int main(int argc, char ** argv) { LOG_TEE("\n\n"); - LOG_TEE("encoded %4d tokens in %8.3f seconds, speed: %8.3f t/s\n", n_input, (t_enc_end - t_enc_start) / 1e6f, inp.size() / ((t_enc_end - t_enc_start) / 1e6f)); - LOG_TEE("decoded %4d tokens in %8.3f seconds, speed: %8.3f t/s\n", n_predict, (t_dec_end - t_dec_start) / 1e6f, n_predict / ((t_dec_end - t_dec_start) / 1e6f)); + LOG_TEE( + "encoded %4d tokens in %8.3f seconds, speed: %8.3f t/s\n", + n_input, (t_enc_end - t_enc_start) / 1e6f, inp.size() / ((t_enc_end - t_enc_start) / 1e6f) + ); + LOG_TEE( + "decoded %4d tokens in %8.3f seconds, speed: %8.3f t/s\n", + n_predict, (t_dec_end - t_dec_start) / 1e6f, n_predict / ((t_dec_end - t_dec_start) / 1e6f) + ); // TODO: make sure these numbers are computed correctly LOG_TEE("\n"); From 5b4db36130e88f252d60d2673ba0cdbc5cfa0efd Mon Sep 17 00:00:00 2001 From: staviq Date: Sun, 17 Sep 2023 16:27:53 +0200 Subject: [PATCH 09/11] mv defs to log.cpp --- Makefile | 51 +++---- common/log.cpp | 331 +++++++++++++++++++++++++++++++++++++++++++ common/log.h | 376 ++++++------------------------------------------- 3 files changed, 404 insertions(+), 354 deletions(-) create mode 100644 common/log.cpp diff --git a/Makefile b/Makefile index 73a9fb17a3ebe..121f792f7a038 100644 --- a/Makefile +++ b/Makefile @@ -484,6 +484,9 @@ OBJS += ggml-alloc.o llama.o: llama.cpp ggml.h ggml-alloc.h ggml-cuda.h ggml-metal.h llama.h $(CXX) $(CXXFLAGS) -c $< -o $@ +log.o: common/log.cpp common/log.h + $(CXX) $(CXXFLAGS) -c $< -o $@ + common.o: common/common.cpp common/common.h build-info.h common/log.h $(CXX) $(CXXFLAGS) -c $< -o $@ @@ -503,13 +506,13 @@ clean: # Examples # -main: examples/main/main.cpp build-info.h ggml.o llama.o common.o console.o grammar-parser.o $(OBJS) +main: examples/main/main.cpp build-info.h ggml.o llama.o common.o log.o console.o grammar-parser.o $(OBJS) $(CXX) $(CXXFLAGS) $(filter-out %.h,$^) -o $@ $(LDFLAGS) @echo @echo '==== Run ./main -h for help. ====' @echo -simple: examples/simple/simple.cpp ggml.o llama.o common.o $(OBJS) +simple: examples/simple/simple.cpp ggml.o llama.o common.o log.o $(OBJS) $(CXX) $(CXXFLAGS) $(filter-out %.h,$^) -o $@ $(LDFLAGS) quantize: examples/quantize/quantize.cpp ggml.o llama.o $(OBJS) @@ -518,44 +521,44 @@ quantize: examples/quantize/quantize.cpp ggml.o llama.o $(O quantize-stats: examples/quantize-stats/quantize-stats.cpp ggml.o llama.o $(OBJS) $(CXX) $(CXXFLAGS) $(filter-out %.h,$^) -o $@ $(LDFLAGS) -perplexity: examples/perplexity/perplexity.cpp ggml.o llama.o common.o $(OBJS) +perplexity: examples/perplexity/perplexity.cpp ggml.o llama.o common.o log.o $(OBJS) $(CXX) $(CXXFLAGS) $(filter-out %.h,$^) -o $@ $(LDFLAGS) -embedding: examples/embedding/embedding.cpp ggml.o llama.o common.o $(OBJS) +embedding: examples/embedding/embedding.cpp ggml.o llama.o common.o log.o $(OBJS) $(CXX) $(CXXFLAGS) $(filter-out %.h,$^) -o $@ $(LDFLAGS) -save-load-state: examples/save-load-state/save-load-state.cpp ggml.o llama.o common.o $(OBJS) +save-load-state: examples/save-load-state/save-load-state.cpp ggml.o llama.o common.o log.o $(OBJS) $(CXX) $(CXXFLAGS) $(filter-out %.h,$^) -o $@ $(LDFLAGS) -server: examples/server/server.cpp examples/server/httplib.h examples/server/json.hpp examples/server/index.html.hpp examples/server/index.js.hpp examples/server/completion.js.hpp build-info.h ggml.o llama.o common.o grammar-parser.o $(OBJS) +server: examples/server/server.cpp examples/server/httplib.h examples/server/json.hpp examples/server/index.html.hpp examples/server/index.js.hpp examples/server/completion.js.hpp build-info.h ggml.o llama.o common.o log.o grammar-parser.o $(OBJS) $(CXX) $(CXXFLAGS) -Iexamples/server $(filter-out %.h,$(filter-out %.hpp,$^)) -o $@ $(LDFLAGS) $(LWINSOCK2) -$(LIB_PRE)embdinput$(DSO_EXT): examples/embd-input/embd-input.h examples/embd-input/embd-input-lib.cpp build-info.h ggml.o llama.o common.o $(OBJS) +$(LIB_PRE)embdinput$(DSO_EXT): examples/embd-input/embd-input.h examples/embd-input/embd-input-lib.cpp build-info.h ggml.o llama.o common.o log.o $(OBJS) $(CXX) --shared $(CXXFLAGS) $(filter-out %.h,$(filter-out %.hpp,$^)) -o $@ $(LDFLAGS) -embd-input-test: $(LIB_PRE)embdinput$(DSO_EXT) examples/embd-input/embd-input-test.cpp build-info.h ggml.o llama.o common.o $(OBJS) +embd-input-test: $(LIB_PRE)embdinput$(DSO_EXT) examples/embd-input/embd-input-test.cpp build-info.h ggml.o llama.o common.o log.o $(OBJS) $(CXX) $(CXXFLAGS) $(filter-out %$(DSO_EXT),$(filter-out %.h,$(filter-out %.hpp,$^))) -o $@ $(LDFLAGS) -L. -lembdinput gguf: examples/gguf/gguf.cpp ggml.o llama.o $(OBJS) $(CXX) $(CXXFLAGS) $(filter-out %.h,$^) -o $@ $(LDFLAGS) -train-text-from-scratch: examples/train-text-from-scratch/train-text-from-scratch.cpp ggml.o llama.o common.o $(OBJS) +train-text-from-scratch: examples/train-text-from-scratch/train-text-from-scratch.cpp ggml.o llama.o common.o log.o $(OBJS) $(CXX) $(TTFS_CXXFLAGS) $(filter-out %.h,$^) -o $@ $(LDFLAGS) convert-llama2c-to-ggml: examples/convert-llama2c-to-ggml/convert-llama2c-to-ggml.cpp ggml.o llama.o $(OBJS) $(CXX) $(CXXFLAGS) $(filter-out %.h,$^) -o $@ $(LDFLAGS) -llama-bench: examples/llama-bench/llama-bench.cpp build-info.h ggml.o llama.o common.o $(OBJS) +llama-bench: examples/llama-bench/llama-bench.cpp build-info.h ggml.o llama.o common.o log.o $(OBJS) $(CXX) $(CXXFLAGS) $(filter-out %.h,$^) -o $@ $(LDFLAGS) -baby-llama: examples/baby-llama/baby-llama.cpp ggml.o llama.o common.o $(OBJS) +baby-llama: examples/baby-llama/baby-llama.cpp ggml.o llama.o common.o log.o $(OBJS) $(CXX) $(CXXFLAGS) $(filter-out %.h,$^) -o $@ $(LDFLAGS) -beam-search: examples/beam-search/beam-search.cpp build-info.h ggml.o llama.o common.o $(OBJS) +beam-search: examples/beam-search/beam-search.cpp build-info.h ggml.o llama.o common.o log.o $(OBJS) $(CXX) $(CXXFLAGS) $(filter-out %.h,$^) -o $@ $(LDFLAGS) -speculative: examples/speculative/speculative.cpp build-info.h ggml.o llama.o common.o grammar-parser.o $(OBJS) +speculative: examples/speculative/speculative.cpp build-info.h ggml.o llama.o common.o log.o grammar-parser.o $(OBJS) $(CXX) $(CXXFLAGS) $(filter-out %.h,$^) -o $@ $(LDFLAGS) ifdef LLAMA_METAL @@ -584,37 +587,37 @@ benchmark-matmult: examples/benchmark/benchmark-matmult.cpp ggml.o $(OBJS) vdot: pocs/vdot/vdot.cpp ggml.o $(OBJS) $(CXX) $(CXXFLAGS) $^ -o $@ $(LDFLAGS) -tests/test-llama-grammar: tests/test-llama-grammar.cpp build-info.h ggml.o common.o grammar-parser.o $(OBJS) +tests/test-llama-grammar: tests/test-llama-grammar.cpp build-info.h ggml.o common.o log.o grammar-parser.o $(OBJS) $(CXX) $(CXXFLAGS) $(filter-out %.h,$^) -o $@ $(LDFLAGS) -tests/test-grammar-parser: tests/test-grammar-parser.cpp build-info.h ggml.o llama.o common.o grammar-parser.o $(OBJS) +tests/test-grammar-parser: tests/test-grammar-parser.cpp build-info.h ggml.o llama.o common.o log.o grammar-parser.o $(OBJS) $(CXX) $(CXXFLAGS) $(filter-out %.h,$^) -o $@ $(LDFLAGS) -tests/test-double-float: tests/test-double-float.cpp build-info.h ggml.o llama.o common.o $(OBJS) +tests/test-double-float: tests/test-double-float.cpp build-info.h ggml.o llama.o common.o log.o $(OBJS) $(CXX) $(CXXFLAGS) $(filter-out %.h,$^) -o $@ $(LDFLAGS) -tests/test-grad0: tests/test-grad0.cpp build-info.h ggml.o llama.o common.o $(OBJS) +tests/test-grad0: tests/test-grad0.cpp build-info.h ggml.o llama.o common.o log.o $(OBJS) $(CXX) $(CXXFLAGS) $(filter-out %.h,$^) -o $@ $(LDFLAGS) -tests/test-opt: tests/test-opt.cpp build-info.h ggml.o llama.o common.o $(OBJS) +tests/test-opt: tests/test-opt.cpp build-info.h ggml.o llama.o common.o log.o $(OBJS) $(CXX) $(CXXFLAGS) $(filter-out %.h,$^) -o $@ $(LDFLAGS) -tests/test-quantize-fns: tests/test-quantize-fns.cpp build-info.h ggml.o llama.o common.o $(OBJS) +tests/test-quantize-fns: tests/test-quantize-fns.cpp build-info.h ggml.o llama.o common.o log.o $(OBJS) $(CXX) $(CXXFLAGS) $(filter-out %.h,$^) -o $@ $(LDFLAGS) -tests/test-quantize-perf: tests/test-quantize-perf.cpp build-info.h ggml.o llama.o common.o $(OBJS) +tests/test-quantize-perf: tests/test-quantize-perf.cpp build-info.h ggml.o llama.o common.o log.o $(OBJS) $(CXX) $(CXXFLAGS) $(filter-out %.h,$^) -o $@ $(LDFLAGS) -tests/test-sampling: tests/test-sampling.cpp build-info.h ggml.o llama.o common.o $(OBJS) +tests/test-sampling: tests/test-sampling.cpp build-info.h ggml.o llama.o common.o log.o $(OBJS) $(CXX) $(CXXFLAGS) $(filter-out %.h,$^) -o $@ $(LDFLAGS) -tests/test-tokenizer-0-falcon: tests/test-tokenizer-0-falcon.cpp build-info.h ggml.o llama.o common.o $(OBJS) +tests/test-tokenizer-0-falcon: tests/test-tokenizer-0-falcon.cpp build-info.h ggml.o llama.o common.o log.o $(OBJS) $(CXX) $(CXXFLAGS) $(filter-out %.h,$^) -o $@ $(LDFLAGS) -tests/test-tokenizer-0-llama: tests/test-tokenizer-0-llama.cpp build-info.h ggml.o llama.o common.o $(OBJS) +tests/test-tokenizer-0-llama: tests/test-tokenizer-0-llama.cpp build-info.h ggml.o llama.o common.o log.o $(OBJS) $(CXX) $(CXXFLAGS) $(filter-out %.h,$^) -o $@ $(LDFLAGS) -tests/test-tokenizer-1-llama: tests/test-tokenizer-1-llama.cpp build-info.h ggml.o llama.o common.o $(OBJS) +tests/test-tokenizer-1-llama: tests/test-tokenizer-1-llama.cpp build-info.h ggml.o llama.o common.o log.o $(OBJS) $(CXX) $(CXXFLAGS) $(filter-out %.h,$^) -o $@ $(LDFLAGS) tests/test-c.o: tests/test-c.c llama.h diff --git a/common/log.cpp b/common/log.cpp new file mode 100644 index 0000000000000..f8ed4b0fc75d7 --- /dev/null +++ b/common/log.cpp @@ -0,0 +1,331 @@ +#include "log.h" + +LogStateWrapper::~LogStateWrapper() +{ + log_flush_all_targets_internal(); + for(auto t : _targets){ delete t; } +} + +LogStateWrapper & LogStateWrapper::instance() +{ + static LogStateWrapper inst; + return inst; +} + +LogStateWrapper::LogTargetWrapper::LogTargetWrapper(FILE * handle) +: _type(Type::Stream), + _opened(true), + _handle(handle) +{} + +LogStateWrapper::LogTargetWrapper::LogTargetWrapper(const std::string && filename) +: LogTargetWrapper(filename) +{} + +LogStateWrapper::LogTargetWrapper::LogTargetWrapper(const std::string & filename) +: _filename(filename) +{ + if(_filename.empty()) + { + _type = Type::Stream; + _handle = stderr; + _opened = true; + } + else + { + _type = Type::File; + } +} + +LogStateWrapper::LogTargetWrapper::~LogTargetWrapper() +{ + if(_type == Type::File && _handle != nullptr) { std::fclose(_handle); } +} + +LogStateWrapper::LogTargetWrapper::operator FILE * () +{ + if(!_opened) + { + while(_lock.test_and_set(std::memory_order_acquire)){ std::this_thread::yield(); } + if(!_opened && _type == Type::File) // check for opened again after acquiring a lock + { + auto result = std::fopen(_filename.c_str(), "w"); + if(result) + { + _handle = result; + } + else + { + std::fprintf( + stderr, + "Failed to open logfile '%s' with error '%s'\n", + _filename.c_str(), std::strerror(errno) + ); + std::fflush(stderr); + _handle = stderr; + } + _opened = true; + } + _lock.clear(std::memory_order_release); + } + return _handle; +} + +void LogStateWrapper::LogTargetWrapper::flush() +{ + while(_lock.test_and_set(std::memory_order_acquire)){ std::this_thread::yield(); } + if(_opened && _type != Type::Invalid && _handle) + { + std::fflush(_handle); + } + _lock.clear(std::memory_order_release); +} + +LogStateWrapper::LogTargetWrapper * LogStateWrapper::log_set_target_internal(const std::string && filename) +{ + return log_set_target_internal(filename); +} + +LogStateWrapper::LogTargetWrapper * LogStateWrapper::log_set_target_internal(const std::string & filename) +{ + return log_add_select_target_internal(new LogTargetWrapper(filename), true); +} + +LogStateWrapper::LogTargetWrapper * LogStateWrapper::log_set_target_internal(FILE * handle) +{ + return log_add_select_target_internal(new LogTargetWrapper(handle), true); +} + +LogStateWrapper::LogTargetWrapper * LogStateWrapper::log_set_target_internal(LogTargetWrapper * target) +{ + return log_add_select_target_internal(target); +} + +LogStateWrapper::LogTargetWrapper * LogStateWrapper::log_add_select_target_internal(LogTargetWrapper * t, bool insert) +{ + log_flush_all_targets_internal(); + std::lock_guard lock(_mutex); + + if(_global_override_target == LogTriState::True) + { + if(_enabled || _global_override_enabled == LogTriState::True) return _current_target; + return _stored_target; + } + + if(_enabled || _global_override_enabled == LogTriState::True) _current_target.store(t); + else _stored_target.store(t); + + if(insert) _targets.insert(t); + + return t; +} + +void LogStateWrapper::log_flush_all_targets_internal() +{ + std::lock_guard lock(_mutex); + for(auto t : _targets){ t->flush(); } +} + +FILE * LogStateWrapper::log_handler_internal() +{ + return *_current_target; +} + +FILE * LogStateWrapper::log_tee_handler_internal() +{ + return _stderr_target; +} + +void LogStateWrapper::log_disable_internal(bool threadsafe) +{ + if(threadsafe) + { + std::lock_guard lock(_mutex); + log_disable_internal_unsafe(); + } + else + { + log_disable_internal_unsafe(); + } +} + +void LogStateWrapper::log_disable_internal_unsafe() +{ + if(_enabled && _global_override_enabled != LogTriState::True) + { + _stored_target.store (_current_target); + _current_target.store (&_null_target); + _enabled = false; + } +} + +void LogStateWrapper::log_enable_internal(bool threadsafe) +{ + if(threadsafe) + { + std::lock_guard lock(_mutex); + log_enable_internal_unsafe(); + } + else + { + log_enable_internal_unsafe(); + } +} + +void LogStateWrapper::log_enable_internal_unsafe() +{ + if(!_enabled && _global_override_enabled != LogTriState::False) + { + _current_target.store (_stored_target); + _enabled = true; + } +} + +bool LogStateWrapper::log_param_single_parse_internal(const std::string & param) +{ +#ifdef LOG_WITH_TEST + if (param == "--log-test") + { + log_test(); + return true; + } +#endif + if (param == "--log-disable") + { + { + std::lock_guard lock(_mutex); + log_disable_internal_unsafe(); + _global_override_enabled = LogTriState::False; + } + return true; + } + + if (param == "--log-enable") + { + { + std::lock_guard lock(_mutex); + log_enable_internal_unsafe(); + _global_override_enabled = LogTriState::True; + } + return true; + } + + return false; +} + +bool LogStateWrapper::log_param_pair_parse_internal(bool parse, const std::string & param, const std::string & next) +{ + if (param == "--log-file") + { + if (parse) + { + log_flush_all_targets_internal(); + std::lock_guard lock(_mutex); + auto t = new LogTargetWrapper(log_filename_generator(next.empty() ? "unnamed" : next, "log")); + if(_enabled) + { + _current_target.store(t); + } + else + { + _stored_target.store(t); + } + _targets.insert(t); + _global_override_target = LogTriState::True; + return t; + } + + return true; + } + + return false; +} + +std::string LogStateWrapper::log_filename_generator_internal(const std::string & basename, const std::string & extension) +{ + std::stringstream buf; + + buf << basename; + buf << "."; + buf << log_get_pid_impl(); + buf << "."; + buf << extension; + + return buf.str(); +} + +std::string LogStateWrapper::log_get_pid_internal() +{ + static std::string pid; + if (pid.empty()) + { + // std::this_thread::get_id() is the most portable way of obtaining a "process id" + // it's not the same as "pid" but is unique enough to solve multiple instances + // trying to write to the same log. + std::stringstream ss; + ss << std::this_thread::get_id(); + pid = ss.str(); + } + + return pid; +} + +LogStateWrapper::LogTargetWrapper * LogStateWrapper::log_set_target_impl(const std::string && filename) +{ + return log_set_target_impl(filename); +} + +LogStateWrapper::LogTargetWrapper * LogStateWrapper::log_set_target_impl(const std::string & filename) +{ + return instance().log_set_target_internal(filename); +} + +LogStateWrapper::LogTargetWrapper * LogStateWrapper::log_set_target_impl(FILE * handle) +{ + return instance().log_set_target_internal(handle); +} + +LogStateWrapper::LogTargetWrapper * LogStateWrapper::log_set_target_impl(LogTargetWrapper * target) +{ + return instance().log_set_target_internal(target); +} + +FILE * LogStateWrapper::log_handler_impl() +{ + return instance().log_handler_internal(); +} + +FILE * LogStateWrapper::log_tee_handler_impl() +{ + return instance().log_tee_handler_internal(); +} + +void LogStateWrapper::log_disable_impl() +{ + instance().log_disable_internal(); +} + +void LogStateWrapper::log_enable_impl() +{ + instance().log_enable_internal(); +} + +bool LogStateWrapper::log_param_single_parse_impl(const std::string & param) +{ + return instance().log_param_single_parse_internal(param); +} + +bool LogStateWrapper::log_param_pair_parse_impl(bool parse, const std::string & param, const std::string & next) +{ + return instance().log_param_pair_parse_internal(parse, param, next); +} + +std::string LogStateWrapper::log_filename_generator_impl(const std::string & basename, const std::string & extension) +{ + return instance().log_filename_generator_internal(basename, extension); +} + +std::string LogStateWrapper::log_get_pid_impl() +{ + return instance().log_get_pid_internal(); +} diff --git a/common/log.h b/common/log.h index 5ed67a6646713..17cf1c4b40732 100644 --- a/common/log.h +++ b/common/log.h @@ -73,23 +73,14 @@ class LogStateWrapper { protected: LogStateWrapper(){}; - - ~LogStateWrapper() - { - log_flush_all_targets(); - for(auto t : _targets){ delete t; } - } + ~LogStateWrapper(); private: LogStateWrapper(LogStateWrapper & other) = delete; void operator=(const LogStateWrapper &) = delete; private: - static LogStateWrapper & instance() - { - static LogStateWrapper inst; - return inst; - } + static LogStateWrapper & instance(); class LogTargetWrapper { @@ -98,35 +89,10 @@ class LogStateWrapper void operator=(const LogTargetWrapper &) = delete; public: - LogTargetWrapper(FILE * handle) - : _type(Type::Stream), - _opened(true), - _handle(handle) - {} - - LogTargetWrapper(const std::string && filename) - : LogTargetWrapper(filename) - {} - - LogTargetWrapper(const std::string & filename) - : _filename(filename) - { - if(_filename.empty()) - { - _type = Type::Stream; - _handle = stderr; - _opened = true; - } - else - { - _type = Type::File; - } - } - - ~LogTargetWrapper() - { - if(_type == Type::File && _handle != nullptr) { std::fclose(_handle); } - } + LogTargetWrapper(FILE * handle); + LogTargetWrapper(const std::string && filename); + LogTargetWrapper(const std::string & filename); + ~LogTargetWrapper(); enum class Type{ Invalid, @@ -135,44 +101,8 @@ class LogStateWrapper }; public: - operator FILE * () - { - if(!_opened) - { - while(_lock.test_and_set(std::memory_order_acquire)){ std::this_thread::yield(); } - if(!_opened && _type == Type::File) // check for opened again after acquiring a lock - { - auto result = std::fopen(_filename.c_str(), "w"); - if(result) - { - _handle = result; - } - else - { - std::fprintf( - stderr, - "Failed to open logfile '%s' with error '%s'\n", - _filename.c_str(), std::strerror(errno) - ); - std::fflush(stderr); - _handle = stderr; - } - _opened = true; - } - _lock.clear(std::memory_order_release); - } - return _handle; - } - - void flush() - { - while(_lock.test_and_set(std::memory_order_acquire)){ std::this_thread::yield(); } - if(_opened && _type != Type::Invalid && _handle) - { - std::fflush(_handle); - } - _lock.clear(std::memory_order_release); - } + operator FILE * (); + void flush(); private: std::atomic_flag _lock = ATOMIC_FLAG_INIT; @@ -180,9 +110,7 @@ class LogStateWrapper std::string _filename; std::atomic _opened {false}; std::atomic _handle {nullptr}; - - //friend class LogStateWrapper; - }; + }; // class LogTargetWrapper private: std::mutex _mutex; @@ -196,249 +124,37 @@ class LogStateWrapper std::atomic _current_target {&_null_target}; std::atomic _stored_target {&_null_target}; - LogTargetWrapper * log_set_target_impl(const std::string && filename) - { - return log_set_target_impl(filename); - } - - LogTargetWrapper * log_set_target_impl(const std::string & filename) - { - return log_add_select_target(new LogTargetWrapper(filename), true); - } - - LogTargetWrapper * log_set_target_impl(FILE * handle) - { - return log_add_select_target(new LogTargetWrapper(handle), true); - } - - LogTargetWrapper * log_set_target_impl(LogTargetWrapper * target) - { - return log_add_select_target(target); - } - - LogTargetWrapper * log_add_select_target(LogTargetWrapper * t, bool insert = false) - { - log_flush_all_targets(); - std::lock_guard lock(_mutex); - - if(_global_override_target == LogTriState::True) - { - if(_enabled || _global_override_enabled == LogTriState::True) return _current_target; - return _stored_target; - } - - if(_enabled || _global_override_enabled == LogTriState::True) _current_target.store(t); - else _stored_target.store(t); - - if(insert) _targets.insert(t); - - return t; - } - - void log_flush_all_targets() - { - std::lock_guard lock(_mutex); - for(auto t : _targets){ t->flush(); } - } - - FILE * log_handler_impl() { return *_current_target; } - FILE * log_tee_handler_impl() { return _stderr_target; } - - void log_disable_impl(bool threadsafe = true) - { - if(threadsafe) - { - std::lock_guard lock(_mutex); - log_disable_impl_unsafe(); - } - else - { - log_disable_impl_unsafe(); - } - } - - void log_disable_impl_unsafe() - { - if(_enabled && _global_override_enabled != LogTriState::True) - { - _stored_target.store (_current_target); - _current_target.store (&_null_target); - _enabled = false; - } - } - - void log_enable_impl(bool threadsafe = true) - { - if(threadsafe) - { - std::lock_guard lock(_mutex); - log_enable_impl_unsafe(); - } - else - { - log_enable_impl_unsafe(); - } - } - - void log_enable_impl_unsafe() - { - if(!_enabled && _global_override_enabled != LogTriState::False) - { - _current_target.store (_stored_target); - _enabled = true; - } - } - - bool log_param_single_parse_impl(const std::string & param) - { -#ifdef LOG_WITH_TEST - if (param == "--log-test") - { - log_test(); - return true; - } -#endif - if (param == "--log-disable") - { - { - std::lock_guard lock(_mutex); - log_disable_impl_unsafe(); - _global_override_enabled = LogTriState::False; - } - return true; - } - - if (param == "--log-enable") - { - { - std::lock_guard lock(_mutex); - log_enable_impl_unsafe(); - _global_override_enabled = LogTriState::True; - } - return true; - } - - return false; - } - - bool log_param_pair_parse_impl(bool parse, const std::string & param, const std::string & next = std::string()) - { - if (param == "--log-file") - { - if (parse) - { - log_flush_all_targets(); - std::lock_guard lock(_mutex); - auto t = new LogTargetWrapper(log_filename_generator(next.empty() ? "unnamed" : next, "log")); - if(_enabled) - { - _current_target.store(t); - } - else - { - _stored_target.store(t); - } - _targets.insert(t); - _global_override_target = LogTriState::True; - return t; - } - - return true; - } - - return false; - } - - std::string log_filename_generator_impl(const std::string & basename, const std::string & extension) - { - std::stringstream buf; - - buf << basename; - buf << "."; - buf << log_get_pid(); - buf << "."; - buf << extension; - - return buf.str(); - } - - std::string log_get_pid_impl() - { - static std::string pid; - if (pid.empty()) - { - // std::this_thread::get_id() is the most portable way of obtaining a "process id" - // it's not the same as "pid" but is unique enough to solve multiple instances - // trying to write to the same log. - std::stringstream ss; - ss << std::this_thread::get_id(); - pid = ss.str(); - } - - return pid; - } + LogTargetWrapper * log_set_target_internal(const std::string && filename); + LogTargetWrapper * log_set_target_internal(const std::string & filename); + LogTargetWrapper * log_set_target_internal(FILE * handle); + LogTargetWrapper * log_set_target_internal(LogTargetWrapper * target); + LogTargetWrapper * log_add_select_target_internal(LogTargetWrapper * t, bool insert = false); + void log_flush_all_targets_internal(); + FILE * log_handler_internal(); + FILE * log_tee_handler_internal(); + void log_disable_internal(bool threadsafe = true); + void log_disable_internal_unsafe(); + void log_enable_internal(bool threadsafe = true); + void log_enable_internal_unsafe(); + bool log_param_single_parse_internal(const std::string & param); + bool log_param_pair_parse_internal(bool parse, const std::string & param, const std::string & next = ""); + std::string log_filename_generator_internal(const std::string & basename, const std::string & extension); + std::string log_get_pid_internal(); public: - static LogTargetWrapper * log_set_target(const std::string &&filename) - { - return log_set_target(filename); - } - - static LogTargetWrapper * log_set_target(const std::string &filename) - { - return instance().log_set_target_impl(filename); - } - - static LogTargetWrapper * log_set_target(FILE * handle) - { - return instance().log_set_target_impl(handle); - } - - static LogTargetWrapper * log_set_target(LogTargetWrapper * target) - { - return instance().log_set_target_impl(target); - } - - static FILE * log_handler() - { - return instance().log_handler_impl(); - } - - static FILE * log_tee_handler() - { - return instance().log_tee_handler_impl(); - } - - static void log_disable() - { - instance().log_disable_impl(); - } - - static void log_enable() - { - instance().log_enable_impl(); - } - - static bool log_param_single_parse(const std::string ¶m) - { - return instance().log_param_single_parse_impl(param); - } - - static bool log_param_pair_parse(bool parse, const std::string & param, const std::string & next = "") - { - return instance().log_param_pair_parse_impl(parse, param, next); - } - - static std::string log_filename_generator(const std::string & basename, const std::string & extension) - { - return instance().log_filename_generator_impl(basename, extension); - } - - static std::string log_get_pid() - { - return instance().log_get_pid_impl(); - } -}; + static LogTargetWrapper * log_set_target_impl(const std::string && filename); + static LogTargetWrapper * log_set_target_impl(const std::string & filename); + static LogTargetWrapper * log_set_target_impl(FILE * handle); + static LogTargetWrapper * log_set_target_impl(LogTargetWrapper * target); + static FILE * log_handler_impl(); + static FILE * log_tee_handler_impl(); + static void log_disable_impl(); + static void log_enable_impl(); + static bool log_param_single_parse_impl(const std::string & param); + static bool log_param_pair_parse_impl(bool parse, const std::string & param, const std::string & next = ""); + static std::string log_filename_generator_impl(const std::string & basename, const std::string & extension); + static std::string log_get_pid_impl(); +}; // class LogStateWrapper // Specifies a log target. // default uses log_handler() with "llama.log" log file @@ -483,11 +199,11 @@ class LogStateWrapper // } // #ifndef LOG_TARGET - #define LOG_TARGET LogStateWrapper::log_handler() + #define LOG_TARGET LogStateWrapper::log_handler_impl() #endif #ifndef LOG_TEE_TARGET - #define LOG_TEE_TARGET LogStateWrapper::log_tee_handler() + #define LOG_TEE_TARGET LogStateWrapper::log_tee_handler_impl() #endif // Utility function for generating log file names with unique id based on thread id. @@ -495,7 +211,7 @@ class LogStateWrapper // where the number is a runtime id of the current thread. #define log_filename_generator(log_file_basename, log_file_extension) \ - LogStateWrapper::log_filename_generator(log_file_basename, log_file_extension) + LogStateWrapper::log_filename_generator_impl(log_file_basename, log_file_extension) // #ifndef LOG_DEFAULT_FILE_NAME // #define LOG_DEFAULT_FILE_NAME log_filename_generator("llama", "log") @@ -782,7 +498,7 @@ inline FILE *log_handler2_impl(bool change = false, LogTriState disable = LogTri // Makes LOG() and LOG_TEE() produce no output, // untill enabled back. //#define log_disable() log_disable_impl() -#define log_disable() LogStateWrapper::log_disable() +#define log_disable() LogStateWrapper::log_disable_impl() /* // INTERNAL, DO NOT USE inline FILE *log_disable_impl() @@ -792,7 +508,7 @@ inline FILE *log_disable_impl() */ // Enables logs at runtime. //#define log_enable() log_enable_impl() -#define log_enable() LogStateWrapper::log_enable() +#define log_enable() LogStateWrapper::log_enable_impl() /* // INTERNAL, DO NOT USE inline FILE *log_enable_impl() @@ -802,7 +518,7 @@ inline FILE *log_enable_impl() */ // Sets target fir logs, either by a file name or FILE* pointer (stdout, stderr, or any valid FILE*) //#define log_set_target(target) log_set_target_impl(target) -#define log_set_target(target) LogStateWrapper::log_set_target(target) +#define log_set_target(target) LogStateWrapper::log_set_target_impl(target) /* // INTERNAL, DO NOT USE @@ -859,8 +575,8 @@ inline void log_test() } #endif -#define log_param_single_parse(param) LogStateWrapper::log_param_single_parse(param) -#define log_param_pair_parse(...) LogStateWrapper::log_param_pair_parse(__VA_ARGS__) +#define log_param_single_parse(param) LogStateWrapper::log_param_single_parse_impl(param) +#define log_param_pair_parse(...) LogStateWrapper::log_param_pair_parse_impl(__VA_ARGS__) inline void log_print_usage() { From 10ad994447b6b91d093bb4e613ed7576bd8368f0 Mon Sep 17 00:00:00 2001 From: staviq Date: Sun, 17 Sep 2023 16:32:11 +0200 Subject: [PATCH 10/11] fix cmake --- common/CMakeLists.txt | 2 ++ 1 file changed, 2 insertions(+) diff --git a/common/CMakeLists.txt b/common/CMakeLists.txt index dead56118bac8..f1cdaf9a5ae11 100644 --- a/common/CMakeLists.txt +++ b/common/CMakeLists.txt @@ -5,6 +5,8 @@ set(TARGET common) add_library(${TARGET} OBJECT common.h common.cpp + log.h + log.cpp console.h console.cpp grammar-parser.h From e283c202851c19044767906b081813746ab868ae Mon Sep 17 00:00:00 2001 From: staviq Date: Sun, 17 Sep 2023 16:59:37 +0200 Subject: [PATCH 11/11] mv handlers back to .h for inlining --- common/log.cpp | 26 -------------------------- common/log.h | 30 +++++++++++++++++++++++++----- 2 files changed, 25 insertions(+), 31 deletions(-) diff --git a/common/log.cpp b/common/log.cpp index f8ed4b0fc75d7..82dbf3fb8f710 100644 --- a/common/log.cpp +++ b/common/log.cpp @@ -6,12 +6,6 @@ LogStateWrapper::~LogStateWrapper() for(auto t : _targets){ delete t; } } -LogStateWrapper & LogStateWrapper::instance() -{ - static LogStateWrapper inst; - return inst; -} - LogStateWrapper::LogTargetWrapper::LogTargetWrapper(FILE * handle) : _type(Type::Stream), _opened(true), @@ -126,16 +120,6 @@ void LogStateWrapper::log_flush_all_targets_internal() for(auto t : _targets){ t->flush(); } } -FILE * LogStateWrapper::log_handler_internal() -{ - return *_current_target; -} - -FILE * LogStateWrapper::log_tee_handler_internal() -{ - return _stderr_target; -} - void LogStateWrapper::log_disable_internal(bool threadsafe) { if(threadsafe) @@ -290,16 +274,6 @@ LogStateWrapper::LogTargetWrapper * LogStateWrapper::log_set_target_impl(LogTarg return instance().log_set_target_internal(target); } -FILE * LogStateWrapper::log_handler_impl() -{ - return instance().log_handler_internal(); -} - -FILE * LogStateWrapper::log_tee_handler_impl() -{ - return instance().log_tee_handler_internal(); -} - void LogStateWrapper::log_disable_impl() { instance().log_disable_internal(); diff --git a/common/log.h b/common/log.h index 17cf1c4b40732..23270885845b5 100644 --- a/common/log.h +++ b/common/log.h @@ -80,7 +80,11 @@ class LogStateWrapper void operator=(const LogStateWrapper &) = delete; private: - static LogStateWrapper & instance(); + static LogStateWrapper & instance() + { + static LogStateWrapper inst; + return inst; + } class LogTargetWrapper { @@ -130,8 +134,6 @@ class LogStateWrapper LogTargetWrapper * log_set_target_internal(LogTargetWrapper * target); LogTargetWrapper * log_add_select_target_internal(LogTargetWrapper * t, bool insert = false); void log_flush_all_targets_internal(); - FILE * log_handler_internal(); - FILE * log_tee_handler_internal(); void log_disable_internal(bool threadsafe = true); void log_disable_internal_unsafe(); void log_enable_internal(bool threadsafe = true); @@ -141,19 +143,37 @@ class LogStateWrapper std::string log_filename_generator_internal(const std::string & basename, const std::string & extension); std::string log_get_pid_internal(); + FILE * log_handler_internal() + { + return *_current_target; + } + + FILE * log_tee_handler_internal() + { + return _stderr_target; + } + public: static LogTargetWrapper * log_set_target_impl(const std::string && filename); static LogTargetWrapper * log_set_target_impl(const std::string & filename); static LogTargetWrapper * log_set_target_impl(FILE * handle); static LogTargetWrapper * log_set_target_impl(LogTargetWrapper * target); - static FILE * log_handler_impl(); - static FILE * log_tee_handler_impl(); static void log_disable_impl(); static void log_enable_impl(); static bool log_param_single_parse_impl(const std::string & param); static bool log_param_pair_parse_impl(bool parse, const std::string & param, const std::string & next = ""); static std::string log_filename_generator_impl(const std::string & basename, const std::string & extension); static std::string log_get_pid_impl(); + + static FILE * log_handler_impl() + { + return instance().log_handler_internal(); + } + + static FILE * log_tee_handler_impl() + { + return instance().log_tee_handler_internal(); + } }; // class LogStateWrapper // Specifies a log target.