From 62de8a62240273ac678325eb30125c41d4c6bffd Mon Sep 17 00:00:00 2001 From: staviq Date: Wed, 23 Aug 2023 02:27:26 +0200 Subject: [PATCH 01/27] initial, base LOG macro --- Makefile | 2 +- common/log.h | 78 ++++++++++++++++++++++++++++++++++++++++++ examples/main/main.cpp | 19 ++++++++++ 3 files changed, 98 insertions(+), 1 deletion(-) create mode 100644 common/log.h diff --git a/Makefile b/Makefile index d31acc450b261..6bbd2fa78629a 100644 --- a/Makefile +++ b/Makefile @@ -351,7 +351,7 @@ 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 common/log.h console.o grammar-parser.o $(OBJS) $(CXX) $(CXXFLAGS) $(filter-out %.h,$^) -o $@ $(LDFLAGS) @echo @echo '==== Run ./main -h for help. ====' diff --git a/common/log.h b/common/log.h new file mode 100644 index 0000000000000..492f98ed819de --- /dev/null +++ b/common/log.h @@ -0,0 +1,78 @@ +#pragma once + +#include + +// Specifies a log target. +// default simply prints log to stderr +// this can be changed, by defining LOG_TARGET +// like so: +// +// #define LOG_TARGET (a valid FILE*) +// #include "log.h" +// +// The log target can also be redirected to a function +// like so: +// +// #define LOG_TARGET log_handler() +// #include "log.h" +// +// FILE* log_handler() +// { +// return stderr; +// } +// +// or: +// +// #define LOG_TARGET log_handler("somelog.log") +// #include "log.h" +// +// FILE* log_handler(char*filename) +// { +// (...) +// return fopen(...) +// } +// +#ifndef LOG_TARGET +#define LOG_TARGET stderr +#endif + +// Allows disabling timestamps. +// in order to disable, define LOG_NO_TIMESTAMPS +// like so: +// +// #define LOG_NO_TIMESTAMPS +// #include "log.h" +// +#ifndef LOG_NO_TIMESTAMPS +#define LOG_TIMESTAMP_FMT "[%lu]" +#define LOG_TIMESTAMP_VAL , (std::chrono::duration_cast>(std::chrono::system_clock::now().time_since_epoch())).count() +#else +#define LOG_TIMESTAMP_FMT +#define LOG_TIMESTAMP_VAL +#endif + +// Allows disabling file/line/function prefix +// in order to disable, define LOG_NO_FILE_LINE_FUNCTION +// like so: +// +// #define LOG_NO_FILE_LINE_FUNCTION +// #include "log.h" +// +#ifndef LOG_NO_FILE_LINE_FUNCTION +#define LOG_FLF_FMT "[%24s:%5d][%24s] " +#define LOG_FLF_VAL , __FILE__, __LINE__, __FUNCTION__ +#else +#define LOG_FLF_FMT +#define LOG_FLF_VAL +#endif + +#define _LOG(str, ...) \ + { \ + fprintf(LOG_TARGET, LOG_TIMESTAMP_FMT LOG_FLF_FMT str "%c" LOG_TIMESTAMP_VAL LOG_FLF_VAL, ##__VA_ARGS__); \ + fflush(LOG_TARGET); \ + } + +// This us a trick to bypass the silly +// "warning: ISO C++11 requires at least one argument for the "..." in a variadic macro" +// so we xan gave a single macro which can be called just like printf. +#define LOG(...) _LOG(__VA_ARGS__, '\n') \ No newline at end of file diff --git a/examples/main/main.cpp b/examples/main/main.cpp index 388e1f7d7fe02..31d3769858e4c 100644 --- a/examples/main/main.cpp +++ b/examples/main/main.cpp @@ -3,7 +3,11 @@ #define _GNU_SOURCE #endif +#define LOG_TARGET log_handler("asd") +//#define LOG_NO_TIMESTAMPS #include "common.h" + +#include "log.h" #include "console.h" #include "llama.h" #include "build-info.h" @@ -54,9 +58,24 @@ void sigint_handler(int signo) { } #endif +inline FILE *log_handler(std::string s) +{ + static bool initialized{false}; + + if (!initialized)[[unlikely]] + { + fprintf(stderr,"arg: %s", s.c_str()); + initialized=true; + } + + return stderr; +} + int main(int argc, char ** argv) { gpt_params params; + LOG("Hello World!") + if (gpt_params_parse(argc, argv, params) == false) { return 1; } From 727af3ea16f7567825e57f83f9be3d56f992b00f Mon Sep 17 00:00:00 2001 From: staviq Date: Wed, 23 Aug 2023 16:02:43 +0200 Subject: [PATCH 02/27] add *.log to .gitignore --- .gitignore | 1 + 1 file changed, 1 insertion(+) diff --git a/.gitignore b/.gitignore index a4df837a406a2..734b7a4f83b8c 100644 --- a/.gitignore +++ b/.gitignore @@ -3,6 +3,7 @@ *.so *.gguf *.bin +*.log .DS_Store .build/ .cache/ From d5156d33456c5cab1752c2c2c454f692bcb04d6e Mon Sep 17 00:00:00 2001 From: staviq Date: Wed, 23 Aug 2023 16:03:30 +0200 Subject: [PATCH 03/27] added basic log file handler --- common/log.h | 89 +++++++++++++++++++++++++++++++++++++----- examples/main/main.cpp | 15 +------ 2 files changed, 81 insertions(+), 23 deletions(-) diff --git a/common/log.h b/common/log.h index 492f98ed819de..7ea031d02c316 100644 --- a/common/log.h +++ b/common/log.h @@ -1,39 +1,57 @@ #pragma once +#ifndef _GNU_SOURCE +#define _GNU_SOURCE +#endif + #include +#include +#include // Specifies a log target. -// default simply prints log to stderr +// default uses log_handler() with "llama.log" log file // this can be changed, by defining LOG_TARGET // like so: // // #define LOG_TARGET (a valid FILE*) // #include "log.h" // -// The log target can also be redirected to a function +// or it can be simply redirected to stdout or stderr // like so: // -// #define LOG_TARGET log_handler() +// #define LOG_TARGET stderr // #include "log.h" // -// FILE* log_handler() +// The log target can also be redirected to a diffrent function +// like so: +// +// #define LOG_TARGET log_handler_diffrent() +// #include "log.h" +// +// FILE* log_handler_diffrent() // { // return stderr; // } // // or: // -// #define LOG_TARGET log_handler("somelog.log") +// #define LOG_TARGET log_handler_another_one("somelog.log") // #include "log.h" // -// FILE* log_handler(char*filename) +// FILE* log_handler_another_one(char*filename) // { +// static FILE* logfile = nullptr; +// (...) +// if( !logfile ) +// { +// fopen(...) +// } // (...) -// return fopen(...) +// return logfile // } // #ifndef LOG_TARGET -#define LOG_TARGET stderr +#define LOG_TARGET log_handler() #endif // Allows disabling timestamps. @@ -75,4 +93,57 @@ // This us a trick to bypass the silly // "warning: ISO C++11 requires at least one argument for the "..." in a variadic macro" // so we xan gave a single macro which can be called just like printf. -#define LOG(...) _LOG(__VA_ARGS__, '\n') \ No newline at end of file +#define LOG(...) _LOG(__VA_ARGS__, '\n') + +inline FILE *log_handler(std::string s = "llama.log") +{ + static std::atomic_bool _initialized{false}; + static std::atomic_bool _logfileopened{false}; + + static FILE* logfile = nullptr; + + if (_initialized)[[likely]] + { + // with fallback in case something went wrong + return logfile ? logfile : stderr; + } + else + { + // Mutex-less threadsafe synchronisation. + // we need to make sure not more than one invocation of this function + // attempts to open a file at once. + // compare_exchange_strong checks and updates a flag + // in a single atomic operation. + bool expected{false}; + if( _logfileopened.compare_exchange_strong(expected,true) ) + { + // If the flag was previously false, and we managed to turn it true + // ew are now responsible for opening the log file + logfile = fopen( s.c_str(), "wa" ); + + if( !logfile ) + { + // Verify whether the file was opened, otherwise fallback to stderr + logfile = stderr; + + fprintf(stderr, "Failed to open logfile '%s' with error '%s'\n", s.c_str(), std::strerror(errno)); + fflush(stderr); + } + + _initialized.store(true); + } + else + { + // We are not first to open the log file + // + // TODO: Better thread-safe option, possibly std::condition_variable + + return stderr; + } + + // with fallback in case something went wrong + return logfile ? logfile : stderr; + } + + return stderr; +} \ No newline at end of file diff --git a/examples/main/main.cpp b/examples/main/main.cpp index 31d3769858e4c..4d504cd784dfe 100644 --- a/examples/main/main.cpp +++ b/examples/main/main.cpp @@ -3,7 +3,7 @@ #define _GNU_SOURCE #endif -#define LOG_TARGET log_handler("asd") +//#define LOG_TARGET log_handler("asd") //#define LOG_NO_TIMESTAMPS #include "common.h" @@ -58,19 +58,6 @@ void sigint_handler(int signo) { } #endif -inline FILE *log_handler(std::string s) -{ - static bool initialized{false}; - - if (!initialized)[[unlikely]] - { - fprintf(stderr,"arg: %s", s.c_str()); - initialized=true; - } - - return stderr; -} - int main(int argc, char ** argv) { gpt_params params; From 356a166b19a154c492dab36fcef313eb0a4387bb Mon Sep 17 00:00:00 2001 From: staviq Date: Wed, 23 Aug 2023 16:06:46 +0200 Subject: [PATCH 04/27] reverted log auto endline to better mimic printf --- common/log.h | 4 ++-- examples/main/main.cpp | 3 ++- 2 files changed, 4 insertions(+), 3 deletions(-) diff --git a/common/log.h b/common/log.h index 7ea031d02c316..0e2e9cd474d1a 100644 --- a/common/log.h +++ b/common/log.h @@ -92,8 +92,8 @@ // This us a trick to bypass the silly // "warning: ISO C++11 requires at least one argument for the "..." in a variadic macro" -// so we xan gave a single macro which can be called just like printf. -#define LOG(...) _LOG(__VA_ARGS__, '\n') +// so we can gave a single macro which can be called just like printf. +#define LOG(...) _LOG(__VA_ARGS__, '\0') inline FILE *log_handler(std::string s = "llama.log") { diff --git a/examples/main/main.cpp b/examples/main/main.cpp index 4d504cd784dfe..aee4b280980fd 100644 --- a/examples/main/main.cpp +++ b/examples/main/main.cpp @@ -61,7 +61,8 @@ void sigint_handler(int signo) { int main(int argc, char ** argv) { gpt_params params; - LOG("Hello World!") + LOG("Hello World!\n") + LOG("Hello Again!\n") if (gpt_params_parse(argc, argv, params) == false) { return 1; From 71d05b9ae438e7d2c3f05212c3dcaf3a53606fa9 Mon Sep 17 00:00:00 2001 From: staviq Date: Wed, 23 Aug 2023 20:27:20 +0200 Subject: [PATCH 05/27] remove atomics and add dynamic log target --- common/log.h | 136 ++++++++++++++++++++++++++++++----------- examples/main/main.cpp | 11 +++- 2 files changed, 109 insertions(+), 38 deletions(-) diff --git a/common/log.h b/common/log.h index 0e2e9cd474d1a..cd7b43b4dd161 100644 --- a/common/log.h +++ b/common/log.h @@ -5,8 +5,9 @@ #endif #include -#include #include +#include +#include // Specifies a log target. // default uses log_handler() with "llama.log" log file @@ -84,66 +85,129 @@ #define LOG_FLF_VAL #endif -#define _LOG(str, ...) \ +#define _LOG(str, ...) \ { \ + /*fprintf(stderr, "DBG:" str, ##__VA_ARGS__);*/ \ fprintf(LOG_TARGET, LOG_TIMESTAMP_FMT LOG_FLF_FMT str "%c" LOG_TIMESTAMP_VAL LOG_FLF_VAL, ##__VA_ARGS__); \ - fflush(LOG_TARGET); \ + fflush(LOG_TARGET); /*fprintf(stderr, "DBGEND\n");*/ \ } -// This us a trick to bypass the silly +// This is a trick to bypass the silly // "warning: ISO C++11 requires at least one argument for the "..." in a variadic macro" // so we can gave a single macro which can be called just like printf. #define LOG(...) _LOG(__VA_ARGS__, '\0') -inline FILE *log_handler(std::string s = "llama.log") +inline std::string log_get_pid() { - static std::atomic_bool _initialized{false}; - static std::atomic_bool _logfileopened{false}; + static std::string pid; + if (pid.empty()) [[unlikely]] + { + // 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; +} + +#define LOG_DEFAULT_FILE_NAME std::string().append("llama.").append(log_get_pid()).append(".log") + +inline FILE *_log_handler1(bool change = false, std::string filename = LOG_DEFAULT_FILE_NAME, FILE *target = nullptr) +{ + // std::cerr << "\tFNM:" << filename << "TGT:" << (uint64_t)target << std::endl; + static bool _initialized{false}; + static std::string log_current_filename{filename}; + static FILE *log_current_target{target}; + static FILE *logfile = nullptr; + + if (change && log_current_filename.compare(filename) != 0) [[unlikely]] + { + // std::cerr << "\t\tFNM changed, deinit" << std::endl; + _initialized = false; + } - static FILE* logfile = nullptr; + if (change && log_current_target != target) [[unlikely]] + { + // std::cerr << "\t\tTGT changed, deinit" << std::endl; + _initialized = false; + } - if (_initialized)[[likely]] + // std::cerr << "\tINIT:" << (_initialized ? "true" : "false") << std::endl; + + if (_initialized) [[likely]] { - // with fallback in case something went wrong + // std::cerr << "\t\tIS Inited" << std::endl; + // with fallback in case something went wrong + // std::cerr << "\t\tEarly Done" << std::endl; return logfile ? logfile : stderr; } else { - // Mutex-less threadsafe synchronisation. - // we need to make sure not more than one invocation of this function - // attempts to open a file at once. - // compare_exchange_strong checks and updates a flag - // in a single atomic operation. - bool expected{false}; - if( _logfileopened.compare_exchange_strong(expected,true) ) + // std::cerr << "\t\tIS NOT Inited" << std::endl; + if (target != nullptr) { - // If the flag was previously false, and we managed to turn it true - // ew are now responsible for opening the log file - logfile = fopen( s.c_str(), "wa" ); - - if( !logfile ) + // std::cerr << "\t\t\tTGT not nullptr" << std::endl; + if (logfile != nullptr && logfile != stdout && logfile != stderr) { - // Verify whether the file was opened, otherwise fallback to stderr - logfile = stderr; - - fprintf(stderr, "Failed to open logfile '%s' with error '%s'\n", s.c_str(), std::strerror(errno)); - fflush(stderr); + // std::cerr << "\t\t\t\tF close" << std::endl; + fclose(logfile); } - _initialized.store(true); + log_current_filename = LOG_DEFAULT_FILE_NAME; + log_current_target = target; + + // std::cerr << "\t\t\tTGT set to new target" << std::endl; + logfile = target; } else { - // We are not first to open the log file - // - // TODO: Better thread-safe option, possibly std::condition_variable + // std::cerr << "\t\t\tTGT IS nullptr" << std::endl; + if (log_current_filename.compare(filename) != 0) [[likely]] + { + // std::cerr << "\t\t\t\tFNM changed" << std::endl; - return stderr; + if (logfile != nullptr && logfile != stdout && logfile != stderr) + { + // std::cerr << "\t\t\t\t\tF close 2" << std::endl; + fclose(logfile); + } + + // std::cerr << "\t\t\t\tF reopen" << std::endl; + logfile = nullptr; + logfile = fopen(filename.c_str(), "a"); + } + else + { + // std::cerr << "\t\t\t\tF open" << std::endl; + // logfile = fopen(filename.c_str(), "wa"); + logfile = fopen(filename.c_str(), "a"); + } } - // with fallback in case something went wrong - return logfile ? logfile : stderr; + if (!logfile) + { + // std::cerr << "\t\t\tF invalid" << std::endl; + // Verify whether the file was opened, otherwise fallback to stderr + logfile = stderr; + + fprintf(stderr, "Failed to open logfile '%s' with error '%s'\n", filename.c_str(), std::strerror(errno)); + fflush(stderr); + } + + _initialized = true; } - return stderr; -} \ No newline at end of file + // std::cerr << "\tDone" << std::endl; + return logfile ? logfile : stderr; +} +inline FILE *_log_handler2(bool change = false, FILE *target = nullptr, std::string filename = LOG_DEFAULT_FILE_NAME) +{ + return _log_handler1(change, filename, target); +} + +inline FILE *log_set_target(std::string filename) { return _log_handler1(true, filename); } +inline FILE *log_set_target(FILE *target) { return _log_handler2(true, target); } +inline FILE *log_handler() { return _log_handler1(); } \ No newline at end of file diff --git a/examples/main/main.cpp b/examples/main/main.cpp index aee4b280980fd..eaaa63f81740f 100644 --- a/examples/main/main.cpp +++ b/examples/main/main.cpp @@ -61,8 +61,15 @@ void sigint_handler(int signo) { int main(int argc, char ** argv) { gpt_params params; - LOG("Hello World!\n") - LOG("Hello Again!\n") + LOG("Hello World to default output!\n") + log_set_target(stderr); + LOG("Hello World to stderr!\n") + log_set_target(LOG_DEFAULT_FILE_NAME); + LOG("Hello World to default log file!\n") + log_set_target(stdout); + LOG("Hello World to stdout!\n") + log_set_target(LOG_DEFAULT_FILE_NAME); + LOG("Hello World to default log file again!\n") if (gpt_params_parse(argc, argv, params) == false) { return 1; From 47b9f2d36f75bbe0b26848a8d5cf28311b69dbd9 Mon Sep 17 00:00:00 2001 From: staviq Date: Thu, 24 Aug 2023 02:00:16 +0200 Subject: [PATCH 06/27] log_enable/disable, LOG_TEE, basic usage doc --- common/log.h | 197 +++++++++++++++++++++++++++++++++++------ examples/main/main.cpp | 27 ++++-- 2 files changed, 193 insertions(+), 31 deletions(-) diff --git a/common/log.h b/common/log.h index cd7b43b4dd161..0f18c7c03a55c 100644 --- a/common/log.h +++ b/common/log.h @@ -9,6 +9,41 @@ #include #include +// -------------------------------- +// +// Basic usage: +// +// -------- +// +// The LOG() and LOG_TEE() macros are ready to go by default +// they do not require any initialization. +// +// LOG() behaves exactly like printf, by default writing to a logfile. +// LOG_TEE() additionally, prints to the screen too ( mimics Unix tee command ). +// +// Default logfile is named +// "llama..log" +// Default LOG_TEE() secondary output target is +// stderr +// +// Logs can be dynamically disabled or enabled using functions: +// log_disable() +// and +// log_enable() +// +// A log target can be changed with: +// log_set_target( string ) +// creating and opening, or re-opening a file by string filename +// or +// log_set_target( FILE* ) +// allowing to point at stderr, stdout, or any valid FILE* file handler. +// +// -------- +// +// End of Basic usage. +// +// -------------------------------- + // Specifies a log target. // default uses log_handler() with "llama.log" log file // this can be changed, by defining LOG_TARGET @@ -55,6 +90,24 @@ #define LOG_TARGET log_handler() #endif +#ifndef LOG_TEE_TARGET +#define LOG_TEE_TARGET stderr +#endif + +#ifndef LOG_DEFAULT_FILE_NAME +// TODO: This should get a wrapper +// to let others have custom log names with automatic unique id +#define LOG_DEFAULT_FILE_NAME std::string().append("llama.").append(log_get_pid()).append(".log") +#endif + +// Utility for turning #define values into string literals +// so we can have a define for stderr and +// we can print "stderr" instead of literal stderr, etc. +#define _LOG_STRINGIZE(s) #s +#define LOG_STRINGIZE(s) _LOG_STRINGIZE(s) + +#define LOG_TEE_TARGET_STRING LOG_STRINGIZE(LOG_TEE_TARGET) + // Allows disabling timestamps. // in order to disable, define LOG_NO_TIMESTAMPS // like so: @@ -85,18 +138,66 @@ #define LOG_FLF_VAL #endif -#define _LOG(str, ...) \ - { \ - /*fprintf(stderr, "DBG:" str, ##__VA_ARGS__);*/ \ - fprintf(LOG_TARGET, LOG_TIMESTAMP_FMT LOG_FLF_FMT str "%c" LOG_TIMESTAMP_VAL LOG_FLF_VAL, ##__VA_ARGS__); \ - fflush(LOG_TARGET); /*fprintf(stderr, "DBGEND\n");*/ \ +// 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 +// +#define _LOG(str, ...) \ + { \ + /*fprintf(stderr, "DBG:" str, ##__VA_ARGS__);*/ \ + if (LOG_TARGET != nullptr) \ + { \ + fprintf(LOG_TARGET, LOG_TIMESTAMP_FMT LOG_FLF_FMT str "%c" LOG_TIMESTAMP_VAL LOG_FLF_VAL, ##__VA_ARGS__); \ + fflush(LOG_TARGET); /*fprintf(stderr, "DBGEND\n");*/ \ + } \ + } + +// INTERNAL, DO NOT USE +// USE LOG_TEE() INSTEAD +// +#define _LOG_TEE(str, ...) \ + { \ + /*fprintf(stderr, "DBG:" str, ##__VA_ARGS__);*/ \ + if (LOG_TARGET != nullptr) \ + { \ + fprintf(LOG_TARGET, LOG_TIMESTAMP_FMT LOG_FLF_FMT str "%c" LOG_TIMESTAMP_VAL LOG_FLF_VAL, ##__VA_ARGS__); \ + fflush(LOG_TARGET); /*fprintf(stderr, "DBGEND\n");*/ \ + } \ + if (LOG_TARGET != nullptr && LOG_TARGET != stdout && LOG_TARGET != stderr && LOG_TEE_TARGET != nullptr) \ + { \ + fprintf(LOG_TEE_TARGET, LOG_TIMESTAMP_FMT LOG_FLF_FMT str "%c" LOG_TIMESTAMP_VAL LOG_FLF_VAL, ##__VA_ARGS__); \ + fflush(LOG_TEE_TARGET); /*fprintf(stderr, "DBGEND\n");*/ \ + } \ } -// This is a trick to bypass the silly -// "warning: ISO C++11 requires at least one argument for the "..." in a variadic macro" -// so we can gave a single macro which can be called just like printf. +// The '\0' as a last argument, is a trick to bypass the silly +// "warning: ISO C++11 requires at least one argument for the "..." in a variadic macro" +// so we can have a single macro which can be called just like printf. + +// Main LOG macro. +// behaves like printf, and supports arguments the exact same way. +// #define LOG(...) _LOG(__VA_ARGS__, '\0') +// Main TEE macro. +// does the same as LOG +// and +// simultaneously writes stderr. +// +// Secondary target can be changed just like LOG_TARGET +// by defining LOG_TEE_TARGET +// +#define LOG_TEE(...) _LOG_TEE(__VA_ARGS__, '\0') + +// 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; @@ -113,36 +214,59 @@ inline std::string log_get_pid() return pid; } -#define LOG_DEFAULT_FILE_NAME std::string().append("llama.").append(log_get_pid()).append(".log") - -inline FILE *_log_handler1(bool change = false, std::string filename = LOG_DEFAULT_FILE_NAME, FILE *target = nullptr) +// INTERNAL, DO NOT USE +inline FILE *_log_handler1(bool change = false, LogTriState disable = LogTriStateSame, std::string filename = LOG_DEFAULT_FILE_NAME, FILE *target = nullptr) { // std::cerr << "\tFNM:" << filename << "TGT:" << (uint64_t)target << std::endl; static bool _initialized{false}; + static bool _disabled{(filename.empty() && target == nullptr)}; static std::string log_current_filename{filename}; static FILE *log_current_target{target}; static FILE *logfile = nullptr; - if (change && log_current_filename.compare(filename) != 0) [[unlikely]] + if (change) [[unlikely]] { - // std::cerr << "\t\tFNM changed, deinit" << std::endl; - _initialized = false; - } + if (disable == LogTriStateTrue) + { + // Disable primary target + _disabled = true; + } + // If previously disabled, only enable, and keep previous target + else if (disable == LogTriStateFalse) + { + _disabled = false; + } + // Otherwise, process the arguments + else + { + if (log_current_filename.compare(filename) != 0) + { + // std::cerr << "\t\tFNM changed, deinit" << std::endl; + _initialized = false; + } - if (change && log_current_target != target) [[unlikely]] - { - // std::cerr << "\t\tTGT changed, deinit" << std::endl; - _initialized = false; + if (log_current_target != target) + { + // std::cerr << "\t\tTGT changed, deinit" << std::endl; + _initialized = false; + } + } } - // std::cerr << "\tINIT:" << (_initialized ? "true" : "false") << std::endl; - if (_initialized) [[likely]] { // std::cerr << "\t\tIS Inited" << std::endl; // with fallback in case something went wrong // std::cerr << "\t\tEarly Done" << std::endl; - return logfile ? logfile : stderr; + if (_disabled) + { + // Log is disabled + return nullptr; + } + else + { + return logfile ? logfile : stderr; + } } else { @@ -197,17 +321,38 @@ inline FILE *_log_handler1(bool change = false, std::string filename = LOG_DEFAU fflush(stderr); } + // At this point we set init flag to true, and let the target fallback to stderr + // otherwise we would repeatedly fopen() which was already unsuccessful _initialized = true; } // std::cerr << "\tDone" << std::endl; return logfile ? logfile : stderr; } -inline FILE *_log_handler2(bool change = false, FILE *target = nullptr, std::string filename = LOG_DEFAULT_FILE_NAME) + +// INTERNAL, DO NOT USE +inline FILE *_log_handler2(bool change = false, LogTriState disable = LogTriStateSame, FILE *target = nullptr, std::string filename = LOG_DEFAULT_FILE_NAME) +{ + return _log_handler1(change, disable, filename, target); +} + +// Disables logs entirely at runtime. +// Makes LOG() and LOG_TEE() produce no output, +// untill enabled back. +inline FILE *log_disable() { - return _log_handler1(change, filename, target); + return _log_handler1(true, LogTriStateTrue); } -inline FILE *log_set_target(std::string filename) { return _log_handler1(true, filename); } -inline FILE *log_set_target(FILE *target) { return _log_handler2(true, target); } +// Enables logs at runtime. +inline FILE *log_enable() +{ + return _log_handler1(true, LogTriStateFalse); +} + +// Sets target fir logs, either by a file name or FILE* pointer (stdout, stderr, or any valid FILE*) +inline FILE *log_set_target(std::string filename) { return _log_handler1(true, LogTriStateSame, filename); } +inline FILE *log_set_target(FILE *target) { return _log_handler2(true, LogTriStateSame, target); } + +// INTERNAL, DO NOT USE inline FILE *log_handler() { return _log_handler1(); } \ No newline at end of file diff --git a/examples/main/main.cpp b/examples/main/main.cpp index eaaa63f81740f..ce48b30cacf39 100644 --- a/examples/main/main.cpp +++ b/examples/main/main.cpp @@ -61,15 +61,32 @@ void sigint_handler(int signo) { int main(int argc, char ** argv) { gpt_params params; - LOG("Hello World to default output!\n") + log_disable(); + LOG("01 Hello World to nobody, because logs are disabled!\n") + log_enable(); + LOG("02 Hello World to default output, which is \"%s\" ( Yaaay, arguments! )!\n", LOG_STRINGIZE(LOG_TARGET)) + LOG_TEE("03 Hello World to **both** default output and " LOG_TEE_TARGET_STRING "!\n") log_set_target(stderr); - LOG("Hello World to stderr!\n") + 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("Hello World to default log file!\n") + LOG("06 Hello World to default log file!\n") log_set_target(stdout); - LOG("Hello World to stdout!\n") + LOG("07 Hello World to stdout!\n") log_set_target(LOG_DEFAULT_FILE_NAME); - LOG("Hello World to default log file again!\n") + LOG("08 Hello World to default log file again!\n") + log_disable(); + LOG("09 Hello World _1_ into the void!\n") + log_enable(); + LOG("10 Hello World back from the void ( you should not see _1_ in the log or the output )!\n") + log_disable(); + log_set_target("llama.anotherlog.log"); + LOG("11 Hello World _2_ to nobody, new target was selected but logs are still disabled!\n") + log_enable(); + LOG("12 Hello World this time in a new file ( you should not see _2_ in the log or the output )?\n") + log_set_target("llama.yetanotherlog.log"); + LOG("13 Hello World this time in yet new file?\n") + if (gpt_params_parse(argc, argv, params) == false) { return 1; From f5080da474487e9532e4b332352c51afba97be78 Mon Sep 17 00:00:00 2001 From: staviq Date: Thu, 24 Aug 2023 19:47:18 +0200 Subject: [PATCH 07/27] update .gitignore --- .gitignore | 2 ++ 1 file changed, 2 insertions(+) diff --git a/.gitignore b/.gitignore index 734b7a4f83b8c..5483de6bacca5 100644 --- a/.gitignore +++ b/.gitignore @@ -3,6 +3,8 @@ *.so *.gguf *.bin +*.exe +*.dll *.log .DS_Store .build/ From 45f1a43d86d099566e01e07e8f967e6803351515 Mon Sep 17 00:00:00 2001 From: staviq Date: Thu, 24 Aug 2023 20:44:47 +0200 Subject: [PATCH 08/27] mv include to common, params, help msg --- Makefile | 4 +- common/common.cpp | 18 +++++ common/common.h | 2 + common/log.h | 150 ++++++++++++++++++++++++++++++++++------- examples/main/main.cpp | 34 ++-------- 5 files changed, 151 insertions(+), 57 deletions(-) diff --git a/Makefile b/Makefile index 6bbd2fa78629a..22ac4dbe511cd 100644 --- a/Makefile +++ b/Makefile @@ -332,7 +332,7 @@ 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 $@ -common.o: common/common.cpp common/common.h +common.o: common/common.cpp common/common.h common/log.h $(CXX) $(CXXFLAGS) -c $< -o $@ console.o: common/console.cpp common/console.h @@ -351,7 +351,7 @@ clean: # Examples # -main: examples/main/main.cpp build-info.h ggml.o llama.o common.o common/log.h console.o grammar-parser.o $(OBJS) +main: examples/main/main.cpp build-info.h ggml.o llama.o common.o console.o grammar-parser.o $(OBJS) $(CXX) $(CXXFLAGS) $(filter-out %.h,$^) -o $@ $(LDFLAGS) @echo @echo '==== Run ./main -h for help. ====' diff --git a/common/common.cpp b/common/common.cpp index 53002ba306b57..454a9aea457bb 100644 --- a/common/common.cpp +++ b/common/common.cpp @@ -462,6 +462,7 @@ bool gpt_params_parse(int argc, char ** argv, gpt_params & params) { } } else if (arg == "-h" || arg == "--help") { gpt_print_usage(argc, argv, default_params); + log_print_usage(); exit(0); } else if (arg == "--random-prompt") { params.random_prompt = true; @@ -501,6 +502,23 @@ bool gpt_params_parse(int argc, char ** argv, gpt_params & params) { std::istreambuf_iterator(), std::back_inserter(params.grammar) ); + // Parse args for logging parameters + } 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] ) ) { + // 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. + if (++i >= argc) { + invalid_param = true; + break; + } + if( !log_param_pair_parse( /*check_but_dont_parse*/ false, argv[i-1], argv[i]) ) { + invalid_param = true; + break; + } + // End of Parse args for logging parameters } else { fprintf(stderr, "error: unknown argument: %s\n", arg.c_str()); gpt_print_usage(argc, argv, default_params); diff --git a/common/common.h b/common/common.h index 17d271e6750e2..b3abc6ea2e359 100644 --- a/common/common.h +++ b/common/common.h @@ -4,6 +4,8 @@ #include "llama.h" +#include "log.h" + #include #include #include diff --git a/common/log.h b/common/log.h index 0f18c7c03a55c..4e4100468f227 100644 --- a/common/log.h +++ b/common/log.h @@ -1,13 +1,10 @@ #pragma once -#ifndef _GNU_SOURCE -#define _GNU_SOURCE -#endif - #include #include #include #include +#include // -------------------------------- // @@ -94,10 +91,37 @@ #define LOG_TEE_TARGET stderr #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()) [[unlikely]] + { + // 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(log_file_basename, log_file_extension) + +// INTERNAL, DO NOT USE +inline std::string _log_filename_generator(std::string log_file_basename, std::string log_file_extension) +{ + return std::string().append(log_file_basename).append(".").append(log_get_pid()).append(".").append(log_file_extension); +} + #ifndef LOG_DEFAULT_FILE_NAME -// TODO: This should get a wrapper -// to let others have custom log names with automatic unique id -#define LOG_DEFAULT_FILE_NAME std::string().append("llama.").append(log_get_pid()).append(".log") +#define LOG_DEFAULT_FILE_NAME LOG_FILENAME_GENERATOR("llama", "log") #endif // Utility for turning #define values into string literals @@ -197,23 +221,6 @@ enum LogTriState // #define LOG_TEE(...) _LOG_TEE(__VA_ARGS__, '\0') -// 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()) [[unlikely]] - { - // 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; -} - // INTERNAL, DO NOT USE inline FILE *_log_handler1(bool change = false, LogTriState disable = LogTriStateSame, std::string filename = LOG_DEFAULT_FILE_NAME, FILE *target = nullptr) { @@ -355,4 +362,97 @@ inline FILE *log_set_target(std::string filename) { return _log_handler1(true, L inline FILE *log_set_target(FILE *target) { return _log_handler2(true, LogTriStateSame, target); } // INTERNAL, DO NOT USE -inline FILE *log_handler() { return _log_handler1(); } \ No newline at end of file +inline FILE *log_handler() { return _log_handler1(); } + +inline void log_test() +{ + std::cerr << "LOGDBG: LOGTEST" << std::endl; + + log_disable(); + LOG("01 Hello World to nobody, because logs are disabled!\n") + log_enable(); + LOG("02 Hello World to default output, which is \"%s\" ( Yaaay, arguments! )!\n", LOG_STRINGIZE(LOG_TARGET)) + LOG_TEE("03 Hello World to **both** default output and " LOG_TEE_TARGET_STRING "!\n") + 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("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("08 Hello World to default log file again!\n") + log_disable(); + LOG("09 Hello World _1_ into the void!\n") + log_enable(); + LOG("10 Hello World back from the void ( you should not see _1_ in the log or the output )!\n") + log_disable(); + log_set_target("llama.anotherlog.log"); + LOG("11 Hello World _2_ to nobody, new target was selected but logs are still disabled!\n") + log_enable(); + LOG("12 Hello World this time in a new file ( you should not see _2_ in the log or the output )?\n") + log_set_target("llama.yetanotherlog.log"); + LOG("13 Hello World this time in yet new file?\n") + log_set_target(LOG_FILENAME_GENERATOR("llama_autonamed", "log")); + LOG("14 Hello World in log with generated filename!\n") + + //exit(0); +} + +inline bool log_param_single_parse(std::string param) +{ + std::cerr << "LOGDBG: single param: " << param << std::endl; + + if (std::string("--log-test").compare(param) == 0) + { + log_test(); + return true; + } + else if (std::string("--log-disable").compare(param) == 0) + { + log_disable(); + return true; + } + else if (std::string("--log-enable").compare(param) == 0) + { + log_enable(); + return true; + } + + std::cerr << "LOGDBG: single param NO MATCH " << param << std::endl; + + return false; +} + +inline bool log_param_pair_parse(bool check_but_dont_parse, std::string param, std::string next = std::string()) +{ + std::cerr << "LOGDBG: pair param: " << param << "/" << next << std::endl; + + if (std::string("--log-file").compare(param) == 0) + { + if( check_but_dont_parse ) + { + return true; + } + log_set_target(LOG_FILENAME_GENERATOR(next.empty() ? "unnamed" : next, "log")); + return true; + } + + std::cerr << "LOGDBG: pair param NO MATCH " << param << "/" << next << std::endl; + + return false; +} + +inline void log_print_usage() +{ + fprintf(stdout, "log options:\n"); + /* + fprintf(stdout, " -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"); /* */ +} diff --git a/examples/main/main.cpp b/examples/main/main.cpp index 3bcb551b4dd1b..8dcb481863232 100644 --- a/examples/main/main.cpp +++ b/examples/main/main.cpp @@ -3,11 +3,8 @@ #define _GNU_SOURCE #endif -//#define LOG_TARGET log_handler("asd") -//#define LOG_NO_TIMESTAMPS #include "common.h" -#include "log.h" #include "console.h" #include "llama.h" #include "build-info.h" @@ -59,34 +56,9 @@ void sigint_handler(int signo) { #endif int main(int argc, char ** argv) { - gpt_params params; - - log_disable(); - LOG("01 Hello World to nobody, because logs are disabled!\n") - log_enable(); - LOG("02 Hello World to default output, which is \"%s\" ( Yaaay, arguments! )!\n", LOG_STRINGIZE(LOG_TARGET)) - LOG_TEE("03 Hello World to **both** default output and " LOG_TEE_TARGET_STRING "!\n") - 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("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("08 Hello World to default log file again!\n") - log_disable(); - LOG("09 Hello World _1_ into the void!\n") - log_enable(); - LOG("10 Hello World back from the void ( you should not see _1_ in the log or the output )!\n") - log_disable(); - log_set_target("llama.anotherlog.log"); - LOG("11 Hello World _2_ to nobody, new target was selected but logs are still disabled!\n") - log_enable(); - LOG("12 Hello World this time in a new file ( you should not see _2_ in the log or the output )?\n") - log_set_target("llama.yetanotherlog.log"); - LOG("13 Hello World this time in yet new file?\n") + LOG("Log start - start of main()\n") + gpt_params params; if (gpt_params_parse(argc, argv, params) == false) { return 1; @@ -851,5 +823,7 @@ int main(int argc, char ** argv) { } llama_backend_free(); + LOG("Log end - end of main()\n") + return 0; } From 360b36c921a0b70cfe571ed03191adaad2edfd10 Mon Sep 17 00:00:00 2001 From: staviq Date: Fri, 25 Aug 2023 05:20:47 +0200 Subject: [PATCH 09/27] log tostring helpers, token vectors pretty prints --- common/log.h | 144 ++++++++++++++++++++++++++++++++++++++++++++------- 1 file changed, 126 insertions(+), 18 deletions(-) diff --git a/common/log.h b/common/log.h index 4e4100468f227..9e6b5c81c643c 100644 --- a/common/log.h +++ b/common/log.h @@ -5,6 +5,8 @@ #include #include #include +#include +#include // -------------------------------- // @@ -15,6 +17,9 @@ // The LOG() and LOG_TEE() macros are ready to go by default // they do not require any initialization. // +// LOGLN() and LOG_TEELN() are variants which automatically +// include \n character at the end of the log string. +// // LOG() behaves exactly like printf, by default writing to a logfile. // LOG_TEE() additionally, prints to the screen too ( mimics Unix tee command ). // @@ -147,6 +152,14 @@ inline std::string _log_filename_generator(std::string log_file_basename, std::s #define LOG_TIMESTAMP_VAL #endif +#ifdef LOG_TEE_TIMESTAMPS +#define LOG_TEE_TIMESTAMP_FMT "[%lu]" +#define LOG_TEE_TIMESTAMP_VAL , (std::chrono::duration_cast>(std::chrono::system_clock::now().time_since_epoch())).count() +#else +#define LOG_TEE_TIMESTAMP_FMT +#define LOG_TEE_TIMESTAMP_VAL +#endif + // Allows disabling file/line/function prefix // in order to disable, define LOG_NO_FILE_LINE_FUNCTION // like so: @@ -162,6 +175,14 @@ inline std::string _log_filename_generator(std::string log_file_basename, std::s #define LOG_FLF_VAL #endif +#ifdef LOG_TEE_FILE_LINE_FUNCTION +#define LOG_TEE_FLF_FMT "[%24s:%5d][%24s] " +#define LOG_TEE_FLF_VAL , __FILE__, __LINE__, __FUNCTION__ +#else +#define LOG_TEE_FLF_FMT +#define LOG_TEE_FLF_VAL +#endif + // Utility for synchronizing log configuration state // since std::optional was introduced only in c++17 enum LogTriState @@ -179,7 +200,7 @@ enum LogTriState /*fprintf(stderr, "DBG:" str, ##__VA_ARGS__);*/ \ if (LOG_TARGET != nullptr) \ { \ - fprintf(LOG_TARGET, LOG_TIMESTAMP_FMT LOG_FLF_FMT str "%c" LOG_TIMESTAMP_VAL LOG_FLF_VAL, ##__VA_ARGS__); \ + fprintf(LOG_TARGET, LOG_TIMESTAMP_FMT LOG_FLF_FMT str "%s" LOG_TIMESTAMP_VAL LOG_FLF_VAL, ##__VA_ARGS__); \ fflush(LOG_TARGET); /*fprintf(stderr, "DBGEND\n");*/ \ } \ } @@ -187,19 +208,19 @@ enum LogTriState // INTERNAL, DO NOT USE // USE LOG_TEE() INSTEAD // -#define _LOG_TEE(str, ...) \ - { \ - /*fprintf(stderr, "DBG:" str, ##__VA_ARGS__);*/ \ - if (LOG_TARGET != nullptr) \ - { \ - fprintf(LOG_TARGET, LOG_TIMESTAMP_FMT LOG_FLF_FMT str "%c" LOG_TIMESTAMP_VAL LOG_FLF_VAL, ##__VA_ARGS__); \ - fflush(LOG_TARGET); /*fprintf(stderr, "DBGEND\n");*/ \ - } \ - if (LOG_TARGET != nullptr && LOG_TARGET != stdout && LOG_TARGET != stderr && LOG_TEE_TARGET != nullptr) \ - { \ - fprintf(LOG_TEE_TARGET, LOG_TIMESTAMP_FMT LOG_FLF_FMT str "%c" LOG_TIMESTAMP_VAL LOG_FLF_VAL, ##__VA_ARGS__); \ - fflush(LOG_TEE_TARGET); /*fprintf(stderr, "DBGEND\n");*/ \ - } \ +#define _LOG_TEE(str, ...) \ + { \ + /*fprintf(stderr, "DBG:" str, ##__VA_ARGS__);*/ \ + 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); /*fprintf(stderr, "DBGEND\n");*/ \ + } \ + if (LOG_TARGET != nullptr && 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); /*fprintf(stderr, "DBGEND\n");*/ \ + } \ } // The '\0' as a last argument, is a trick to bypass the silly @@ -209,7 +230,7 @@ enum LogTriState // Main LOG macro. // behaves like printf, and supports arguments the exact same way. // -#define LOG(...) _LOG(__VA_ARGS__, '\0') +#define LOG(...) _LOG(__VA_ARGS__, "") // Main TEE macro. // does the same as LOG @@ -219,7 +240,11 @@ enum LogTriState // Secondary target can be changed just like LOG_TARGET // by defining LOG_TEE_TARGET // -#define LOG_TEE(...) _LOG_TEE(__VA_ARGS__, '\0') +#define LOG_TEE(...) _LOG_TEE(__VA_ARGS__, "") + +// LOG macro variants with auto endline. +#define LOGLN(...) _LOG(__VA_ARGS__, "\n") +#define LOG_TEELN(...) _LOG(__VA_ARGS__, "\n") // INTERNAL, DO NOT USE inline FILE *_log_handler1(bool change = false, LogTriState disable = LogTriStateSame, std::string filename = LOG_DEFAULT_FILE_NAME, FILE *target = nullptr) @@ -396,7 +421,7 @@ inline void log_test() log_set_target(LOG_FILENAME_GENERATOR("llama_autonamed", "log")); LOG("14 Hello World in log with generated filename!\n") - //exit(0); + // exit(0); } inline bool log_param_single_parse(std::string param) @@ -430,7 +455,7 @@ inline bool log_param_pair_parse(bool check_but_dont_parse, std::string param, s if (std::string("--log-file").compare(param) == 0) { - if( check_but_dont_parse ) + if (check_but_dont_parse) { return true; } @@ -456,3 +481,86 @@ inline void log_print_usage() 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"); /* */ } + +inline void log_dump_cmdline(int argc, char **argv) +{ + std::string buf; + for (int i = 0; i < argc; ++i) + { + if (std::string(argv[i]).find(' ') != std::string::npos) + { + buf.append(" \"").append(argv[i]).append("\""); + } + else + { + buf.append(" ").append(argv[i]); + } + } + LOGLN("Cmd:%s", buf.c_str()) +} + +#define LOG_TOSTR(var) _log_var_to_string(var).c_str() + +inline std::string _log_var_to_string(bool var) +{ + return var ? "true" : "false"; +} + +inline std::string _log_var_to_string(std::string var) +{ + return var; +} + +inline std::string _log_var_to_string(std::vector var) +{ + std::string buf; + buf.append("[ "); + bool first = true; + for (auto e : var) + { + if (first) + { + first = false; + } + else + { + buf.append(", "); + } + buf.append(std::to_string(e)); + } + buf.append(" ]"); + + return buf; +} + +#define LOG_TOKENS_TOSTR_PRETTY(tokens, ctx) \ + [&tokens, &ctx]() \ + { \ + std::string buf("[ "); \ + bool first = true; \ + for (const auto &token : tokens) \ + { \ + if (!first) \ + buf.append(", "); \ + else \ + first = false; \ + \ + auto detokenized = llama_token_to_str(ctx, token); \ + \ + detokenized.erase( \ + std::remove_if( \ + detokenized.begin(), \ + detokenized.end(), \ + [](const char c) { return !std::isprint(c); }), \ + detokenized.end()); \ + \ + buf \ + .append("'") \ + .append(detokenized) \ + .append("'") \ + .append(":") \ + .append(std::to_string(token)); \ + } \ + return buf.append(" ]"); \ + }() \ + .c_str() From 181e8a99029b4c12799e99d08b4717c6e2389908 Mon Sep 17 00:00:00 2001 From: staviq Date: Fri, 25 Aug 2023 05:22:23 +0200 Subject: [PATCH 10/27] main: replaced fprintf/LOG_TEE, some trace logging --- examples/main/main.cpp | 130 ++++++++++++++++++++++++----------------- 1 file changed, 77 insertions(+), 53 deletions(-) diff --git a/examples/main/main.cpp b/examples/main/main.cpp index 8dcb481863232..099907e2a2fbe 100644 --- a/examples/main/main.cpp +++ b/examples/main/main.cpp @@ -56,14 +56,20 @@ void sigint_handler(int signo) { #endif int main(int argc, char ** argv) { - LOG("Log start - start of main()\n") - gpt_params params; if (gpt_params_parse(argc, argv, params) == false) { return 1; } + log_set_target(LOG_FILENAME_GENERATOR("main", "log")); + LOG_TEE("Log start\n") + + log_dump_cmdline(argc,argv); + + // TODO: Dump params ? + //LOG("Params perplexity: %s\n", LOG_TOSTR(params.perplexity)) + // save choice to use color for later // (note for later: this is a slightly awkward choice) console::init(params.simple_io, params.use_color); @@ -86,34 +92,35 @@ int main(int argc, char ** argv) { } if (params.rope_freq_base != 10000.0) { - fprintf(stderr, "%s: warning: changing RoPE frequency base to %g (default 10000.0)\n", __func__, params.rope_freq_base); + LOG_TEE("%s: warning: changing RoPE frequency base to %g (default 10000.0)\n", __func__, params.rope_freq_base); } if (params.rope_freq_scale != 1.0) { - fprintf(stderr, "%s: warning: scaling RoPE frequency by %g (default 1.0)\n", __func__, params.rope_freq_scale); + LOG_TEE("%s: warning: scaling RoPE frequency by %g (default 1.0)\n", __func__, params.rope_freq_scale); } if (params.n_ctx > 2048) { // TODO: determine the actual max context of the model (e.g. 4096 for LLaMA v2) and use that instead of 2048 - fprintf(stderr, "%s: warning: base model only supports context sizes no greater than 2048 tokens (%d specified)\n", __func__, params.n_ctx); + LOG_TEE("%s: warning: base model only supports context sizes no greater than 2048 tokens (%d specified)\n", __func__, params.n_ctx); } else if (params.n_ctx < 8) { - fprintf(stderr, "%s: warning: minimum context size is 8, using minimum size.\n", __func__); + LOG_TEE("%s: warning: minimum context size is 8, using minimum size.\n", __func__); params.n_ctx = 8; } - fprintf(stderr, "%s: build = %d (%s)\n", __func__, BUILD_NUMBER, BUILD_COMMIT); + LOG_TEE("%s: build = %d (%s)\n", __func__, BUILD_NUMBER, BUILD_COMMIT); if (params.seed == LLAMA_DEFAULT_SEED) { params.seed = time(NULL); } - fprintf(stderr, "%s: seed = %u\n", __func__, params.seed); + LOG_TEE("%s: seed = %u\n", __func__, params.seed); std::mt19937 rng(params.seed); if (params.random_prompt) { params.prompt = gpt_random_prompt(rng); } + LOG("llama backend init\n") llama_backend_init(params.numa); llama_model * model; @@ -122,6 +129,7 @@ int main(int argc, char ** argv) { g_ctx = &ctx; // load the model and apply lora adapter, if any + LOG("load the model and apply lora adapter, if any\n") std::tie(model, ctx) = llama_init_from_gpt_params(params); if (params.cfg_scale > 1.f) { struct llama_context_params lparams = llama_context_params_from_gpt_params(params); @@ -129,14 +137,14 @@ int main(int argc, char ** argv) { } if (model == NULL) { - fprintf(stderr, "%s: error: unable to load model\n", __func__); + LOG_TEE("%s: error: unable to load model\n", __func__); return 1; } // print system information { - fprintf(stderr, "\n"); - fprintf(stderr, "system_info: n_threads = %d / %d | %s\n", + LOG_TEE("\n"); + LOG_TEE("system_info: n_threads = %d / %d | %s\n", params.n_threads, std::thread::hardware_concurrency(), llama_print_system_info()); } @@ -144,7 +152,7 @@ int main(int argc, char ** argv) { // uncomment the "used_mem" line in llama.cpp to see the results if (params.mem_test) { { - fprintf(stderr, "%s: testing memory usage for n_batch = %d, n_ctx = %d\n", __func__, params.n_batch, params.n_ctx); + LOG_TEE("%s: testing memory usage for n_batch = %d, n_ctx = %d\n", __func__, params.n_batch, params.n_ctx); const std::vector tmp(params.n_batch, llama_token_bos(ctx)); llama_eval(ctx, tmp.data(), tmp.size(), params.n_ctx, params.n_threads); @@ -170,7 +178,7 @@ int main(int argc, char ** argv) { std::vector session_tokens; if (!path_session.empty()) { - fprintf(stderr, "%s: attempting to load saved session from '%s'\n", __func__, path_session.c_str()); + LOG_TEE("%s: attempting to load saved session from '%s'\n", __func__, path_session.c_str()); // fopen to check for existing session FILE * fp = std::fopen(path_session.c_str(), "rb"); @@ -180,21 +188,22 @@ int main(int argc, char ** argv) { session_tokens.resize(params.n_ctx); size_t n_token_count_out = 0; if (!llama_load_session_file(ctx, path_session.c_str(), session_tokens.data(), session_tokens.capacity(), &n_token_count_out)) { - fprintf(stderr, "%s: error: failed to load session file '%s'\n", __func__, path_session.c_str()); + LOG_TEE("%s: error: failed to load session file '%s'\n", __func__, path_session.c_str()); return 1; } session_tokens.resize(n_token_count_out); llama_set_rng_seed(ctx, params.seed); - fprintf(stderr, "%s: loaded a session with prompt size of %d tokens\n", __func__, (int) session_tokens.size()); + LOG_TEE("%s: loaded a session with prompt size of %d tokens\n", __func__, (int) session_tokens.size()); } else { - fprintf(stderr, "%s: session file does not exist, will create\n", __func__); + LOG_TEE("%s: session file does not exist, will create\n", __func__); } } const bool is_spm = llama_vocab_type(ctx) == LLAMA_VOCAB_TYPE_SPM; // tokenize the prompt + LOG("Tokenize the prompt\n") std::vector embd_inp; if (params.interactive_first || params.instruct || !params.prompt.empty() || session_tokens.empty()) { embd_inp = ::llama_tokenize(ctx, params.prompt, is_spm); @@ -202,9 +211,14 @@ int main(int argc, char ** argv) { embd_inp = session_tokens; } + LOG("prompt: \"%s\"\n", LOG_TOSTR(params.prompt)) + //LOG("Prompt tokenized: %s\n", LOG_TOSTR(embd_inp)) + LOG("embd_inp tokenized: %s\n", LOG_TOKENS_TOSTR_PRETTY(embd_inp,ctx)) + // Should not run without any tokens if (embd_inp.empty()) { embd_inp.push_back(llama_token_bos(ctx)); + LOG("embd_inp was considered empty and bos was added: %s\n", LOG_TOKENS_TOSTR_PRETTY(embd_inp,ctx)) } // Tokenize negative prompt @@ -213,17 +227,24 @@ int main(int argc, char ** argv) { int original_prompt_len = 0; if (ctx_guidance) { params.cfg_negative_prompt.insert(0, 1, ' '); + LOG("cfg_negative_prompt: \"%s\"\n", LOG_TOSTR(params.cfg_negative_prompt)) guidance_inp = ::llama_tokenize(ctx_guidance, params.cfg_negative_prompt, is_spm); + LOG("guidance_inp tokenized: %s\n", LOG_TOKENS_TOSTR_PRETTY(guidance_inp,ctx_guidance)) std::vector original_inp = ::llama_tokenize(ctx, params.prompt, is_spm); + LOG("original_inp tokenized: %s\n", LOG_TOKENS_TOSTR_PRETTY(original_inp,ctx)) original_prompt_len = original_inp.size(); guidance_offset = (int)guidance_inp.size() - original_prompt_len; + LOG("original_prompt_len: %s", LOG_TOSTR(original_prompt_len)) + LOG("guidance_offset: %s", LOG_TOSTR(guidance_offset)) + } const int n_ctx = llama_n_ctx(ctx); + LOG("n_ctx: %d\n", n_ctx) if ((int) embd_inp.size() > n_ctx - 4) { - fprintf(stderr, "%s: error: prompt is too long (%d tokens, max %d)\n", __func__, (int) embd_inp.size(), n_ctx - 4); + LOG_TEE("%s: error: prompt is too long (%d tokens, max %d)\n", __func__, (int) embd_inp.size(), n_ctx - 4); return 1; } @@ -237,14 +258,14 @@ int main(int argc, char ** argv) { n_matching_session_tokens++; } if (params.prompt.empty() && n_matching_session_tokens == embd_inp.size()) { - fprintf(stderr, "%s: using full prompt from session file\n", __func__); + LOG_TEE("%s: using full prompt from session file\n", __func__); } else if (n_matching_session_tokens >= embd_inp.size()) { - fprintf(stderr, "%s: session file has exact match for prompt!\n", __func__); + LOG_TEE("%s: session file has exact match for prompt!\n", __func__); } else if (n_matching_session_tokens < (embd_inp.size() / 2)) { - fprintf(stderr, "%s: warning: session file has low similarity to prompt (%zu / %zu tokens); will mostly be reevaluated\n", + 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 { - fprintf(stderr, "%s: session file matches %zu / %zu tokens of prompt\n", + LOG_TEE("%s: session file matches %zu / %zu tokens of prompt\n", __func__, n_matching_session_tokens, embd_inp.size()); } } @@ -253,6 +274,9 @@ int main(int argc, char ** argv) { // reevaluation of the last token token to recalculate the cached logits if (!embd_inp.empty() && n_matching_session_tokens == embd_inp.size() && session_tokens.size() > embd_inp.size()) { + LOG( + "recalculate the cached logits: embd_inp.empty() %s, n_matching_session_tokens %lu, embd_inp.size() %lu, session_tokens.size() %lu, embd_inp.size() %lu, session_tokens.resize( %lu )", + LOG_TOSTR(embd_inp.empty()), n_matching_session_tokens, embd_inp.size(), session_tokens.size(), embd_inp.size(), embd_inp.size() - 1) session_tokens.resize(embd_inp.size() - 1); } @@ -277,30 +301,30 @@ int main(int argc, char ** argv) { } if (params.verbose_prompt) { - fprintf(stderr, "\n"); - fprintf(stderr, "%s: prompt: '%s'\n", __func__, params.prompt.c_str()); - fprintf(stderr, "%s: number of tokens in prompt = %zu\n", __func__, embd_inp.size()); + LOG_TEE("\n"); + LOG_TEE("%s: prompt: '%s'\n", __func__, params.prompt.c_str()); + LOG_TEE("%s: number of tokens in prompt = %zu\n", __func__, embd_inp.size()); for (int i = 0; i < (int) embd_inp.size(); i++) { - fprintf(stderr, "%6d -> '%s'\n", embd_inp[i], llama_token_to_str(ctx, embd_inp[i]).c_str()); + LOG_TEE("%6d -> '%s'\n", embd_inp[i], llama_token_to_str(ctx, embd_inp[i]).c_str()); } if (ctx_guidance) { - fprintf(stderr, "\n"); - fprintf(stderr, "%s: negative prompt: '%s'\n", __func__, params.cfg_negative_prompt.c_str()); - fprintf(stderr, "%s: number of tokens in negative prompt = %zu\n", __func__, guidance_inp.size()); + LOG_TEE("\n"); + LOG_TEE("%s: negative prompt: '%s'\n", __func__, params.cfg_negative_prompt.c_str()); + LOG_TEE("%s: number of tokens in negative prompt = %zu\n", __func__, guidance_inp.size()); for (int i = 0; i < (int) guidance_inp.size(); i++) { - fprintf(stderr, "%6d -> '%s'\n", guidance_inp[i], llama_token_to_str(ctx, guidance_inp[i]).c_str()); + LOG_TEE("%6d -> '%s'\n", guidance_inp[i], llama_token_to_str(ctx, guidance_inp[i]).c_str()); } } if (params.n_keep > 0) { - fprintf(stderr, "%s: static prompt based on n_keep: '", __func__); + LOG_TEE("%s: static prompt based on n_keep: '", __func__); for (int i = 0; i < params.n_keep; i++) { - fprintf(stderr, "%s", llama_token_to_str(ctx, embd_inp[i]).c_str()); + LOG_TEE("%s", llama_token_to_str(ctx, embd_inp[i]).c_str()); } - fprintf(stderr, "'\n"); + LOG_TEE("'\n"); } - fprintf(stderr, "\n"); + LOG_TEE("\n"); } if (params.interactive) { @@ -317,30 +341,30 @@ int main(int argc, char ** argv) { SetConsoleCtrlHandler(reinterpret_cast(console_ctrl_handler), true); #endif - fprintf(stderr, "%s: interactive mode on.\n", __func__); + LOG_TEE("%s: interactive mode on.\n", __func__); if (params.antiprompt.size()) { for (auto antiprompt : params.antiprompt) { - fprintf(stderr, "Reverse prompt: '%s'\n", antiprompt.c_str()); + LOG_TEE("Reverse prompt: '%s'\n", antiprompt.c_str()); } } if (params.input_prefix_bos) { - fprintf(stderr, "Input prefix with BOS\n"); + LOG_TEE("Input prefix with BOS\n"); } if (!params.input_prefix.empty()) { - fprintf(stderr, "Input prefix: '%s'\n", params.input_prefix.c_str()); + LOG_TEE("Input prefix: '%s'\n", params.input_prefix.c_str()); } if (!params.input_suffix.empty()) { - fprintf(stderr, "Input suffix: '%s'\n", params.input_suffix.c_str()); + LOG_TEE("Input suffix: '%s'\n", params.input_suffix.c_str()); } } - fprintf(stderr, "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", + 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); - fprintf(stderr, "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); - fprintf(stderr, "\n\n"); + 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"); grammar_parser::parse_state parsed_grammar; llama_grammar * grammar = NULL; @@ -350,14 +374,14 @@ int main(int argc, char ** argv) { if (parsed_grammar.rules.empty()) { return 1; } - fprintf(stderr, "%s: grammar:\n", __func__); + LOG_TEE("%s: grammar:\n", __func__); grammar_parser::print_grammar(stderr, parsed_grammar); - fprintf(stderr, "\n"); + LOG_TEE("\n"); { auto it = params.logit_bias.find(llama_token_eos(ctx)); if (it != params.logit_bias.end() && it->second == -INFINITY) { - fprintf(stderr, "%s: warning: EOS token is disabled, which will cause most grammars to fail\n", __func__); + LOG_TEE("%s: warning: EOS token is disabled, which will cause most grammars to fail\n", __func__); } } @@ -434,7 +458,7 @@ int main(int argc, char ** argv) { // - take half of the last (n_ctx - n_keep) tokens and recompute the logits in batches if (n_past + (int) embd.size() + std::max(0, guidance_offset) > n_ctx) { if (params.n_predict == -2) { - fprintf(stderr, "\n\n%s: context full, stopping generation\n", __func__); + LOG_TEE("\n\n%s: context full, stopping generation\n", __func__); break; } @@ -503,11 +527,11 @@ int main(int argc, char ** argv) { input_buf = embd_guidance.data(); input_size = embd_guidance.size(); - //fprintf(stderr, "\n---------------------\n"); + //LOG_TEE("\n---------------------\n"); //for (int i = 0; i < (int) embd_guidance.size(); i++) { - //fprintf(stderr, "%s", llama_token_to_str(ctx, embd_guidance[i])); + //LOG_TEE("%s", llama_token_to_str(ctx, embd_guidance[i])); //} - //fprintf(stderr, "\n---------------------\n"); + //LOG_TEE("\n---------------------\n"); } else { input_buf = embd.data(); input_size = embd.size(); @@ -516,7 +540,7 @@ int main(int argc, char ** argv) { for (int i = 0; i < input_size; i += params.n_batch) { int n_eval = std::min(input_size - i, params.n_batch); if (llama_eval(ctx_guidance, input_buf + i, n_eval, n_past_guidance, params.n_threads)) { - fprintf(stderr, "%s : failed to eval\n", __func__); + LOG_TEE("%s : failed to eval\n", __func__); return 1; } @@ -530,7 +554,7 @@ int main(int argc, char ** argv) { n_eval = params.n_batch; } if (llama_eval(ctx, &embd[i], n_eval, n_past, params.n_threads)) { - fprintf(stderr, "%s : failed to eval\n", __func__); + LOG_TEE("%s : failed to eval\n", __func__); return 1; } n_past += n_eval; @@ -796,7 +820,7 @@ int main(int argc, char ** argv) { // end of text token if (!embd.empty() && embd.back() == llama_token_eos(ctx) && !(params.instruct || params.interactive)) { - fprintf(stderr, " [end of text]\n"); + LOG_TEE(" [end of text]\n"); break; } @@ -809,7 +833,7 @@ int main(int argc, char ** argv) { } if (!path_session.empty() && params.prompt_cache_all && !params.prompt_cache_ro) { - fprintf(stderr, "\n%s: saving final output to session file '%s'\n", __func__, path_session.c_str()); + LOG_TEE("\n%s: saving final output to session file '%s'\n", __func__, path_session.c_str()); llama_save_session_file(ctx, path_session.c_str(), session_tokens.data(), session_tokens.size()); } @@ -823,7 +847,7 @@ int main(int argc, char ** argv) { } llama_backend_free(); - LOG("Log end - end of main()\n") + LOG_TEE("Log end\n") return 0; } From 4fdcede9ec83b69add37d5b4393444445e6a6c92 Mon Sep 17 00:00:00 2001 From: staviq Date: Fri, 25 Aug 2023 15:51:27 +0200 Subject: [PATCH 11/27] LOG_DISABLE_LOGS compile flag, wrapped f in macros --- Makefile | 5 +++ common/common.cpp | 4 ++ common/log.h | 85 +++++++++++++++++++++++++++++++----------- examples/main/main.cpp | 9 +++-- 4 files changed, 79 insertions(+), 24 deletions(-) diff --git a/Makefile b/Makefile index 22ac4dbe511cd..f5520e0e8c5ae 100644 --- a/Makefile +++ b/Makefile @@ -302,6 +302,11 @@ k_quants.o: k_quants.c k_quants.h $(CC) $(CFLAGS) -c $< -o $@ endif # LLAMA_NO_K_QUANTS +ifdef LLAMA_DISABLE_LOGS + CFLAGS += -DLOG_DISABLE_LOGS + CXXFLAGS += -DLOG_DISABLE_LOGS +endif # LLAMA_DISABLE_LOGS + # # Print build information # diff --git a/common/common.cpp b/common/common.cpp index 454a9aea457bb..d65cf7352ba95 100644 --- a/common/common.cpp +++ b/common/common.cpp @@ -462,7 +462,9 @@ bool gpt_params_parse(int argc, char ** argv, gpt_params & params) { } } else if (arg == "-h" || arg == "--help") { gpt_print_usage(argc, argv, default_params); +#ifndef LOG_DISABLE_LOGS log_print_usage(); +#endif // LOG_DISABLE_LOGS exit(0); } else if (arg == "--random-prompt") { params.random_prompt = true; @@ -502,6 +504,7 @@ bool gpt_params_parse(int argc, char ** argv, gpt_params & params) { std::istreambuf_iterator(), std::back_inserter(params.grammar) ); +#ifndef LOG_DISABLE_LOGS // Parse args for logging parameters } else if ( log_param_single_parse( argv[i] ) ) { // Do nothing, log_param_single_parse automatically does it's thing @@ -519,6 +522,7 @@ bool gpt_params_parse(int argc, char ** argv, gpt_params & params) { break; } // End of Parse args for logging parameters +#endif // LOG_DISABLE_LOGS } else { fprintf(stderr, "error: unknown argument: %s\n", arg.c_str()); gpt_print_usage(argc, argv, default_params); diff --git a/common/log.h b/common/log.h index 9e6b5c81c643c..b148474d9d9b5 100644 --- a/common/log.h +++ b/common/log.h @@ -371,20 +371,29 @@ inline FILE *_log_handler2(bool change = false, LogTriState disable = LogTriStat // Disables logs entirely at runtime. // Makes LOG() and LOG_TEE() produce no output, // untill enabled back. -inline FILE *log_disable() +#define LOG_DISABLE() _log_disable() + +// INTERNAL, DO NOT USE +inline FILE *_log_disable() { return _log_handler1(true, LogTriStateTrue); } // Enables logs at runtime. -inline FILE *log_enable() +#define LOG_ENABLE() _log_enable() + +// INTERNAL, DO NOT USE +inline FILE *_log_enable() { return _log_handler1(true, LogTriStateFalse); } // Sets target fir logs, either by a file name or FILE* pointer (stdout, stderr, or any valid FILE*) -inline FILE *log_set_target(std::string filename) { return _log_handler1(true, LogTriStateSame, filename); } -inline FILE *log_set_target(FILE *target) { return _log_handler2(true, LogTriStateSame, target); } +#define LOG_SET_TARGET(target) _log_set_target(target) + +// INTERNAL, DO NOT USE +inline FILE *_log_set_target(std::string filename) { return _log_handler1(true, LogTriStateSame, filename); } +inline FILE *_log_set_target(FILE *target) { return _log_handler2(true, LogTriStateSame, target); } // INTERNAL, DO NOT USE inline FILE *log_handler() { return _log_handler1(); } @@ -393,32 +402,32 @@ inline void log_test() { std::cerr << "LOGDBG: LOGTEST" << std::endl; - log_disable(); + LOG_DISABLE(); LOG("01 Hello World to nobody, because logs are disabled!\n") - log_enable(); + LOG_ENABLE(); LOG("02 Hello World to default output, which is \"%s\" ( Yaaay, arguments! )!\n", LOG_STRINGIZE(LOG_TARGET)) LOG_TEE("03 Hello World to **both** default output and " LOG_TEE_TARGET_STRING "!\n") - log_set_target(stderr); + 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("06 Hello World to default log file!\n") - log_set_target(stdout); + 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("08 Hello World to default log file again!\n") - log_disable(); + LOG_DISABLE(); LOG("09 Hello World _1_ into the void!\n") - log_enable(); + LOG_ENABLE(); LOG("10 Hello World back from the void ( you should not see _1_ in the log or the output )!\n") - log_disable(); - log_set_target("llama.anotherlog.log"); + LOG_DISABLE(); + LOG_SET_TARGET("llama.anotherlog.log"); LOG("11 Hello World _2_ to nobody, new target was selected but logs are still disabled!\n") - log_enable(); + LOG_ENABLE(); LOG("12 Hello World this time in a new file ( you should not see _2_ in the log or the output )?\n") - log_set_target("llama.yetanotherlog.log"); + LOG_SET_TARGET("llama.yetanotherlog.log"); LOG("13 Hello World this time in yet new file?\n") - log_set_target(LOG_FILENAME_GENERATOR("llama_autonamed", "log")); + LOG_SET_TARGET(LOG_FILENAME_GENERATOR("llama_autonamed", "log")); LOG("14 Hello World in log with generated filename!\n") // exit(0); @@ -435,12 +444,12 @@ inline bool log_param_single_parse(std::string param) } else if (std::string("--log-disable").compare(param) == 0) { - log_disable(); + LOG_DISABLE(); return true; } else if (std::string("--log-enable").compare(param) == 0) { - log_enable(); + LOG_ENABLE(); return true; } @@ -459,7 +468,7 @@ inline bool log_param_pair_parse(bool check_but_dont_parse, std::string param, s { return true; } - log_set_target(LOG_FILENAME_GENERATOR(next.empty() ? "unnamed" : next, "log")); + LOG_SET_TARGET(LOG_FILENAME_GENERATOR(next.empty() ? "unnamed" : next, "log")); return true; } @@ -482,7 +491,10 @@ inline void log_print_usage() fprintf(stdout, " Log file will be tagged with unique ID and written as \"..log\"\n"); /* */ } -inline void log_dump_cmdline(int argc, char **argv) +#define LOG_DUMP_CMDLINE( argc, argv ) _log_dump_cmdline(argc,argv) + +// INTERNAL, DO NOT USE +inline void _log_dump_cmdline(int argc, char **argv) { std::string buf; for (int i = 0; i < argc; ++i) @@ -564,3 +576,34 @@ inline std::string _log_var_to_string(std::vector var) return buf.append(" ]"); \ }() \ .c_str() + + +#ifdef LOG_DISABLE_LOGS + +#undef LOG +#define LOG(...) // dummy stub +#undef LOGLN +#define LOGLN(...) // dummy stub + +#undef LOG_TEE +#define LOG_TEE(...) fprintf(stderr, __VA_ARGS__); // convert to normal fprintf + +#undef LOG_TEELN +#define LOG_TEELN(...) fprintf(stderr, __VA_ARGS__); // convert to normal fprintf + +#undef LOG_DISABLE +#define LOG_DISABLE() // dummy stub + +#undef LOG_ENABLE +#define LOG_ENABLE() // dummy stub + +#undef LOG_ENABLE +#define LOG_ENABLE() // dummy stub + +#undef LOG_SET_TARGET +#define LOG_SET_TARGET(...) // dummy stub + +#undef LOG_DUMP_CMDLINE +#define LOG_DUMP_CMDLINE(...) // dummy stub + +#endif // LOG_DISABLE_LOGS diff --git a/examples/main/main.cpp b/examples/main/main.cpp index 099907e2a2fbe..08b1950c4454f 100644 --- a/examples/main/main.cpp +++ b/examples/main/main.cpp @@ -62,10 +62,11 @@ int main(int argc, char ** argv) { return 1; } - log_set_target(LOG_FILENAME_GENERATOR("main", "log")); +#ifndef LOG_DISABLE_LOGS + LOG_SET_TARGET(LOG_FILENAME_GENERATOR("main", "log")); LOG_TEE("Log start\n") - - log_dump_cmdline(argc,argv); + LOG_DUMP_CMDLINE(argc,argv); +#endif // LOG_DISABLE_LOGS // TODO: Dump params ? //LOG("Params perplexity: %s\n", LOG_TOSTR(params.perplexity)) @@ -847,7 +848,9 @@ int main(int argc, char ** argv) { } llama_backend_free(); +#ifndef LOG_DISABLE_LOGS LOG_TEE("Log end\n") +#endif // LOG_DISABLE_LOGS return 0; } From c8a1118308d7d3a568b4fb2638700028a4b77970 Mon Sep 17 00:00:00 2001 From: staviq Date: Fri, 25 Aug 2023 17:41:15 +0200 Subject: [PATCH 12/27] fix LOG_TEELN and configchecker --- common/log.h | 6 ++++-- examples/main/main.cpp | 1 - 2 files changed, 4 insertions(+), 3 deletions(-) diff --git a/common/log.h b/common/log.h index b148474d9d9b5..926a25e352e0f 100644 --- a/common/log.h +++ b/common/log.h @@ -244,7 +244,7 @@ enum LogTriState // LOG macro variants with auto endline. #define LOGLN(...) _LOG(__VA_ARGS__, "\n") -#define LOG_TEELN(...) _LOG(__VA_ARGS__, "\n") +#define LOG_TEELN(...) _LOG_TEE(__VA_ARGS__, "\n") // INTERNAL, DO NOT USE inline FILE *_log_handler1(bool change = false, LogTriState disable = LogTriStateSame, std::string filename = LOG_DEFAULT_FILE_NAME, FILE *target = nullptr) @@ -496,7 +496,9 @@ inline void log_print_usage() // INTERNAL, DO NOT USE inline void _log_dump_cmdline(int argc, char **argv) { - std::string buf; + // TODO: + // Windows doesn't seem to like this somehow + std::string buf{""}; for (int i = 0; i < argc; ++i) { if (std::string(argv[i]).find(' ') != std::string::npos) diff --git a/examples/main/main.cpp b/examples/main/main.cpp index 08b1950c4454f..e46b36c126c4c 100644 --- a/examples/main/main.cpp +++ b/examples/main/main.cpp @@ -238,7 +238,6 @@ int main(int argc, char ** argv) { guidance_offset = (int)guidance_inp.size() - original_prompt_len; LOG("original_prompt_len: %s", LOG_TOSTR(original_prompt_len)) LOG("guidance_offset: %s", LOG_TOSTR(guidance_offset)) - } const int n_ctx = llama_n_ctx(ctx); From 9bace227c51e214c109e19072ad495ef16618f43 Mon Sep 17 00:00:00 2001 From: staviq Date: Fri, 25 Aug 2023 18:24:55 +0200 Subject: [PATCH 13/27] stub LOG_DUMP_CMDLINE for WIN32 for now --- common/log.h | 12 +++++++++--- 1 file changed, 9 insertions(+), 3 deletions(-) diff --git a/common/log.h b/common/log.h index 926a25e352e0f..e3e45a5fc7d0f 100644 --- a/common/log.h +++ b/common/log.h @@ -491,14 +491,16 @@ inline void log_print_usage() fprintf(stdout, " Log file will be tagged with unique ID and written as \"..log\"\n"); /* */ } +#ifndef _WIN32 +// TODO: +// Windows doesn't seem to like this somehow + #define LOG_DUMP_CMDLINE( argc, argv ) _log_dump_cmdline(argc,argv) // INTERNAL, DO NOT USE inline void _log_dump_cmdline(int argc, char **argv) { - // TODO: - // Windows doesn't seem to like this somehow - std::string buf{""}; + std::string buf; for (int i = 0; i < argc; ++i) { if (std::string(argv[i]).find(' ') != std::string::npos) @@ -513,6 +515,10 @@ inline void _log_dump_cmdline(int argc, char **argv) LOGLN("Cmd:%s", buf.c_str()) } +#else +#define LOG_DUMP_CMDLINE(...) // dummy stub +#endif + #define LOG_TOSTR(var) _log_var_to_string(var).c_str() inline std::string _log_var_to_string(bool var) From 0b367255c1832316e3429872014e2408bbd79310 Mon Sep 17 00:00:00 2001 From: staviq Date: Sat, 26 Aug 2023 02:57:50 +0200 Subject: [PATCH 14/27] fix msvc --- common/log.h | 197 +++++++++++++++++++++++++---------------- examples/main/main.cpp | 6 ++ 2 files changed, 125 insertions(+), 78 deletions(-) diff --git a/common/log.h b/common/log.h index e3e45a5fc7d0f..46eda8d3358b3 100644 --- a/common/log.h +++ b/common/log.h @@ -89,18 +89,21 @@ // } // #ifndef LOG_TARGET -#define LOG_TARGET log_handler() +/**/ #define LOG_TARGET log_handler() #endif #ifndef LOG_TEE_TARGET -#define LOG_TEE_TARGET stderr +/**/ #define LOG_TEE_TARGET stderr #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()) [[unlikely]] + if (pid.empty()) +#ifndef _WIN32 + [[unlikely]] +#endif { // 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 @@ -126,7 +129,7 @@ inline std::string _log_filename_generator(std::string log_file_basename, std::s } #ifndef LOG_DEFAULT_FILE_NAME -#define LOG_DEFAULT_FILE_NAME LOG_FILENAME_GENERATOR("llama", "log") +/**/#define LOG_DEFAULT_FILE_NAME LOG_FILENAME_GENERATOR("llama", "log") #endif // Utility for turning #define values into string literals @@ -145,19 +148,29 @@ inline std::string _log_filename_generator(std::string log_file_basename, std::s // #include "log.h" // #ifndef LOG_NO_TIMESTAMPS -#define LOG_TIMESTAMP_FMT "[%lu]" -#define LOG_TIMESTAMP_VAL , (std::chrono::duration_cast>(std::chrono::system_clock::now().time_since_epoch())).count() +/**/#ifndef _WIN32 +/* */#define LOG_TIMESTAMP_FMT "[%lu]" +/* */#define LOG_TIMESTAMP_VAL , (std::chrono::duration_cast>(std::chrono::system_clock::now().time_since_epoch())).count() +/**/#else +/* */#define LOG_TIMESTAMP_FMT "[%llu]" +/* */#define LOG_TIMESTAMP_VAL , (std::chrono::duration_cast>(std::chrono::system_clock::now().time_since_epoch())).count() +/**/#endif #else -#define LOG_TIMESTAMP_FMT -#define LOG_TIMESTAMP_VAL +/**/#define LOG_TIMESTAMP_FMT +/**/#define LOG_TIMESTAMP_VAL #endif #ifdef LOG_TEE_TIMESTAMPS -#define LOG_TEE_TIMESTAMP_FMT "[%lu]" -#define LOG_TEE_TIMESTAMP_VAL , (std::chrono::duration_cast>(std::chrono::system_clock::now().time_since_epoch())).count() +/**/#ifndef _WIN32 +/* */#define LOG_TEE_TIMESTAMP_FMT "[%lu]" +/* */#define LOG_TEE_TIMESTAMP_VAL , (std::chrono::duration_cast>(std::chrono::system_clock::now().time_since_epoch())).count() +/**/#else +/* */#define LOG_TEE_TIMESTAMP_FMT "[%llu]" +/* */#define LOG_TEE_TIMESTAMP_VAL , (std::chrono::duration_cast>(std::chrono::system_clock::now().time_since_epoch())).count() +/**/#endif #else -#define LOG_TEE_TIMESTAMP_FMT -#define LOG_TEE_TIMESTAMP_VAL +/**/#define LOG_TEE_TIMESTAMP_FMT +/**/#define LOG_TEE_TIMESTAMP_VAL #endif // Allows disabling file/line/function prefix @@ -168,19 +181,29 @@ inline std::string _log_filename_generator(std::string log_file_basename, std::s // #include "log.h" // #ifndef LOG_NO_FILE_LINE_FUNCTION -#define LOG_FLF_FMT "[%24s:%5d][%24s] " -#define LOG_FLF_VAL , __FILE__, __LINE__, __FUNCTION__ +/**/#ifndef _WIN32 +/* */#define LOG_FLF_FMT "[%24s:%5d][%24s] " +/* */#define LOG_FLF_VAL , __FILE__, __LINE__, __FUNCTION__ +/**/#else +/* */#define LOG_FLF_FMT "[%24s:%5ld][%24s] " +/* */#define LOG_FLF_VAL , __FILE__, __LINE__, __FUNCTION__ +/**/#endif #else -#define LOG_FLF_FMT -#define LOG_FLF_VAL +/**/#define LOG_FLF_FMT +/**/#define LOG_FLF_VAL #endif #ifdef LOG_TEE_FILE_LINE_FUNCTION -#define LOG_TEE_FLF_FMT "[%24s:%5d][%24s] " -#define LOG_TEE_FLF_VAL , __FILE__, __LINE__, __FUNCTION__ +/**/#ifndef _WIN32 +/* */#define LOG_TEE_FLF_FMT "[%24s:%5d][%24s] " +/* */#define LOG_TEE_FLF_VAL , __FILE__, __LINE__, __FUNCTION__ +/**/#else +/* */#define LOG_TEE_FLF_FMT "[%24s:%5ld][%24s] " +/* */#define LOG_TEE_FLF_VAL , __FILE__, __LINE__, __FUNCTION__ +/**/#endif #else -#define LOG_TEE_FLF_FMT -#define LOG_TEE_FLF_VAL +/**/#define LOG_TEE_FLF_FMT +/**/#define LOG_TEE_FLF_VAL #endif // Utility for synchronizing log configuration state @@ -195,33 +218,58 @@ enum LogTriState // INTERNAL, DO NOT USE // USE LOG() INSTEAD // -#define _LOG(str, ...) \ +#ifndef _WIN32 +/**/#define _LOG(str, ...) \ { \ - /*fprintf(stderr, "DBG:" str, ##__VA_ARGS__);*/ \ 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); /*fprintf(stderr, "DBGEND\n");*/ \ + fflush(LOG_TARGET); \ } \ } +#else +/**/#define _LOG(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); \ + } \ + } +#endif // INTERNAL, DO NOT USE // USE LOG_TEE() INSTEAD // -#define _LOG_TEE(str, ...) \ +#ifndef _WIN32 +/**/#define _LOG_TEE(str, ...) \ { \ - /*fprintf(stderr, "DBG:" str, ##__VA_ARGS__);*/ \ 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); /*fprintf(stderr, "DBGEND\n");*/ \ + fflush(LOG_TARGET); \ } \ if (LOG_TARGET != nullptr && 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); /*fprintf(stderr, "DBGEND\n");*/ \ + fflush(LOG_TEE_TARGET); \ } \ } +#else +/**/#define _LOG_TEE(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 != nullptr && 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); \ + } \ + } +#endif // The '\0' as a last argument, is a trick to bypass the silly // "warning: ISO C++11 requires at least one argument for the "..." in a variadic macro" @@ -230,7 +278,11 @@ enum LogTriState // Main LOG macro. // behaves like printf, and supports arguments the exact same way. // -#define LOG(...) _LOG(__VA_ARGS__, "") +#ifndef _WIN32 +/**/#define LOG(...) _LOG(__VA_ARGS__, "") +#else +/**/#define LOG(str, ...) _LOG("%s" str, "", __VA_ARGS__, "") +#endif // Main TEE macro. // does the same as LOG @@ -240,23 +292,34 @@ enum LogTriState // Secondary target can be changed just like LOG_TARGET // by defining LOG_TEE_TARGET // -#define LOG_TEE(...) _LOG_TEE(__VA_ARGS__, "") +#ifndef _WIN32 +/**/#define LOG_TEE(...) _LOG_TEE(__VA_ARGS__, "") +#else +/**/#define LOG_TEE(str, ...) _LOG_TEE("%s" str, "", __VA_ARGS__, "") +#endif // LOG macro variants with auto endline. -#define LOGLN(...) _LOG(__VA_ARGS__, "\n") -#define LOG_TEELN(...) _LOG_TEE(__VA_ARGS__, "\n") +#ifndef _WIN32 +/**/#define LOGLN(...) _LOG(__VA_ARGS__, "\n") +/**/#define LOG_TEELN(...) _LOG_TEE(__VA_ARGS__, "\n") +#else +/**/#define LOGLN(str, ...) _LOG("%s" str, "", __VA_ARGS__, "\n") +/**/#define LOG_TEELN(str, ...) _LOG_TEE("%s" str, "", __VA_ARGS__, "\n") +#endif // INTERNAL, DO NOT USE inline FILE *_log_handler1(bool change = false, LogTriState disable = LogTriStateSame, std::string filename = LOG_DEFAULT_FILE_NAME, FILE *target = nullptr) { - // std::cerr << "\tFNM:" << filename << "TGT:" << (uint64_t)target << std::endl; static bool _initialized{false}; static bool _disabled{(filename.empty() && target == nullptr)}; static std::string log_current_filename{filename}; static FILE *log_current_target{target}; static FILE *logfile = nullptr; - if (change) [[unlikely]] + if (change) +#ifndef _WIN32 + [[unlikely]] +#endif { if (disable == LogTriStateTrue) { @@ -273,23 +336,21 @@ inline FILE *_log_handler1(bool change = false, LogTriState disable = LogTriStat { if (log_current_filename.compare(filename) != 0) { - // std::cerr << "\t\tFNM changed, deinit" << std::endl; _initialized = false; } if (log_current_target != target) { - // std::cerr << "\t\tTGT changed, deinit" << std::endl; _initialized = false; } } } - if (_initialized) [[likely]] + if (_initialized) +#ifndef _WIN32 + [[likely]] +#endif { - // std::cerr << "\t\tIS Inited" << std::endl; - // with fallback in case something went wrong - // std::cerr << "\t\tEarly Done" << std::endl; if (_disabled) { // Log is disabled @@ -297,55 +358,47 @@ inline FILE *_log_handler1(bool change = false, LogTriState disable = LogTriStat } else { + // with fallback in case something went wrong return logfile ? logfile : stderr; } } else { - // std::cerr << "\t\tIS NOT Inited" << std::endl; if (target != nullptr) { - // std::cerr << "\t\t\tTGT not nullptr" << std::endl; if (logfile != nullptr && logfile != stdout && logfile != stderr) { - // std::cerr << "\t\t\t\tF close" << std::endl; fclose(logfile); } log_current_filename = LOG_DEFAULT_FILE_NAME; log_current_target = target; - // std::cerr << "\t\t\tTGT set to new target" << std::endl; logfile = target; } else { - // std::cerr << "\t\t\tTGT IS nullptr" << std::endl; - if (log_current_filename.compare(filename) != 0) [[likely]] + if (log_current_filename.compare(filename) != 0) +#ifndef _WIN32 + [[likely]] +#endif { - // std::cerr << "\t\t\t\tFNM changed" << std::endl; - if (logfile != nullptr && logfile != stdout && logfile != stderr) { - // std::cerr << "\t\t\t\t\tF close 2" << std::endl; fclose(logfile); } - // std::cerr << "\t\t\t\tF reopen" << std::endl; logfile = nullptr; logfile = fopen(filename.c_str(), "a"); } else { - // std::cerr << "\t\t\t\tF open" << std::endl; - // logfile = fopen(filename.c_str(), "wa"); logfile = fopen(filename.c_str(), "a"); } } if (!logfile) { - // std::cerr << "\t\t\tF invalid" << std::endl; // Verify whether the file was opened, otherwise fallback to stderr logfile = stderr; @@ -358,7 +411,6 @@ inline FILE *_log_handler1(bool change = false, LogTriState disable = LogTriStat _initialized = true; } - // std::cerr << "\tDone" << std::endl; return logfile ? logfile : stderr; } @@ -400,8 +452,6 @@ inline FILE *log_handler() { return _log_handler1(); } inline void log_test() { - std::cerr << "LOGDBG: LOGTEST" << std::endl; - LOG_DISABLE(); LOG("01 Hello World to nobody, because logs are disabled!\n") LOG_ENABLE(); @@ -429,14 +479,20 @@ inline void log_test() LOG("13 Hello World this time in yet new file?\n") LOG_SET_TARGET(LOG_FILENAME_GENERATOR("llama_autonamed", "log")); LOG("14 Hello World in log with generated filename!\n") - - // exit(0); +#ifdef _WIN32 + LOG_TEE("15 Hello msvc TEE without arguments\n") + LOG_TEE("16 Hello msvc TEE with (%d)(%s) arguments\n", 1, "test") + LOG_TEELN("17 Hello msvc TEELN without arguments\n") + LOG_TEELN("18 Hello msvc TEELN with (%d)(%s) arguments\n", 1, "test") + LOG("19 Hello msvc LOG without arguments\n") + LOG("20 Hello msvc LOG with (%d)(%s) arguments\n", 1, "test") + LOGLN("21 Hello msvc LOGLN without arguments\n") + LOGLN("22 Hello msvc LOGLN with (%d)(%s) arguments\n", 1, "test") +#endif } inline bool log_param_single_parse(std::string param) { - std::cerr << "LOGDBG: single param: " << param << std::endl; - if (std::string("--log-test").compare(param) == 0) { log_test(); @@ -453,15 +509,11 @@ inline bool log_param_single_parse(std::string param) return true; } - std::cerr << "LOGDBG: single param NO MATCH " << param << std::endl; - return false; } inline bool log_param_pair_parse(bool check_but_dont_parse, std::string param, std::string next = std::string()) { - std::cerr << "LOGDBG: pair param: " << param << "/" << next << std::endl; - if (std::string("--log-file").compare(param) == 0) { if (check_but_dont_parse) @@ -472,17 +524,15 @@ inline bool log_param_pair_parse(bool check_but_dont_parse, std::string param, s return true; } - std::cerr << "LOGDBG: pair param NO MATCH " << param << "/" << next << std::endl; - return false; } inline void log_print_usage() { fprintf(stdout, "log options:\n"); - /* - fprintf(stdout, " -h, --help show this help message and exit\n"); - // spacing + /* format + fprintf(stdout, " -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"); @@ -491,11 +541,7 @@ inline void log_print_usage() fprintf(stdout, " Log file will be tagged with unique ID and written as \"..log\"\n"); /* */ } -#ifndef _WIN32 -// TODO: -// Windows doesn't seem to like this somehow - -#define LOG_DUMP_CMDLINE( argc, argv ) _log_dump_cmdline(argc,argv) +#define LOG_DUMP_CMDLINE(argc, argv) _log_dump_cmdline(argc, argv) // INTERNAL, DO NOT USE inline void _log_dump_cmdline(int argc, char **argv) @@ -515,10 +561,6 @@ inline void _log_dump_cmdline(int argc, char **argv) LOGLN("Cmd:%s", buf.c_str()) } -#else -#define LOG_DUMP_CMDLINE(...) // dummy stub -#endif - #define LOG_TOSTR(var) _log_var_to_string(var).c_str() inline std::string _log_var_to_string(bool var) @@ -585,7 +627,6 @@ inline std::string _log_var_to_string(std::vector var) }() \ .c_str() - #ifdef LOG_DISABLE_LOGS #undef LOG diff --git a/examples/main/main.cpp b/examples/main/main.cpp index e46b36c126c4c..2ba9fc1e15f91 100644 --- a/examples/main/main.cpp +++ b/examples/main/main.cpp @@ -274,9 +274,15 @@ int main(int argc, char ** argv) { // reevaluation of the last token token to recalculate the cached logits if (!embd_inp.empty() && n_matching_session_tokens == embd_inp.size() && session_tokens.size() > embd_inp.size()) { +#ifndef _WIN32 LOG( "recalculate the cached logits: embd_inp.empty() %s, n_matching_session_tokens %lu, embd_inp.size() %lu, session_tokens.size() %lu, embd_inp.size() %lu, session_tokens.resize( %lu )", LOG_TOSTR(embd_inp.empty()), n_matching_session_tokens, embd_inp.size(), session_tokens.size(), embd_inp.size(), embd_inp.size() - 1) +#else + LOG( + "recalculate the cached logits: embd_inp.empty() %s, n_matching_session_tokens %llu, embd_inp.size() %llu, session_tokens.size() %llu, embd_inp.size() %llu, session_tokens.resize( %llu )", + LOG_TOSTR(embd_inp.empty()), n_matching_session_tokens, embd_inp.size(), session_tokens.size(), embd_inp.size(), embd_inp.size() - 1) +#endif session_tokens.resize(embd_inp.size() - 1); } From e99f039c9ee91cb7905bf1214b51b8fdb130d470 Mon Sep 17 00:00:00 2001 From: staviq Date: Sat, 26 Aug 2023 17:52:25 +0200 Subject: [PATCH 15/27] cleanup main.cpp:273 --- examples/main/main.cpp | 16 +++++++--------- 1 file changed, 7 insertions(+), 9 deletions(-) diff --git a/examples/main/main.cpp b/examples/main/main.cpp index 2ba9fc1e15f91..243742f68d46d 100644 --- a/examples/main/main.cpp +++ b/examples/main/main.cpp @@ -270,19 +270,17 @@ 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()) + // 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 if (!embd_inp.empty() && n_matching_session_tokens == embd_inp.size() && session_tokens.size() > embd_inp.size()) { -#ifndef _WIN32 - LOG( - "recalculate the cached logits: embd_inp.empty() %s, n_matching_session_tokens %lu, embd_inp.size() %lu, session_tokens.size() %lu, embd_inp.size() %lu, session_tokens.resize( %lu )", - LOG_TOSTR(embd_inp.empty()), n_matching_session_tokens, embd_inp.size(), session_tokens.size(), embd_inp.size(), embd_inp.size() - 1) -#else - LOG( - "recalculate the cached logits: embd_inp.empty() %s, n_matching_session_tokens %llu, embd_inp.size() %llu, session_tokens.size() %llu, embd_inp.size() %llu, session_tokens.resize( %llu )", - LOG_TOSTR(embd_inp.empty()), n_matching_session_tokens, embd_inp.size(), session_tokens.size(), embd_inp.size(), embd_inp.size() - 1) -#endif + + LOGLN("recalculate the cached logits (do): session_tokens.resize( %zu )", embd_inp.size() - 1) + session_tokens.resize(embd_inp.size() - 1); } From 5cea86927544645ec255a6d74be9794400a7d5ab Mon Sep 17 00:00:00 2001 From: staviq Date: Sat, 26 Aug 2023 18:08:55 +0200 Subject: [PATCH 16/27] fix stray whitespace after master sync --- examples/main/main.cpp | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/examples/main/main.cpp b/examples/main/main.cpp index f582de5f05e41..fdc04573e237c 100644 --- a/examples/main/main.cpp +++ b/examples/main/main.cpp @@ -289,7 +289,7 @@ int main(int argc, char ** argv) { session_tokens.size() > embd_inp.size()) { LOGLN("recalculate the cached logits (do): session_tokens.resize( %zu )", embd_inp.size() - 1) - + session_tokens.resize(embd_inp.size() - 1); } From b97958a5115838bddc635551f42aee89a0937def Mon Sep 17 00:00:00 2001 From: Georgi Gerganov Date: Tue, 29 Aug 2023 13:46:43 +0300 Subject: [PATCH 17/27] log : fix compile warnings - do not use C++20 stuff - use PRIu64 to print uint64_t - avoid string copies by using const ref - fix ", ##__VA_ARGS__" warnings - compare strings with == and != --- Makefile | 2 +- common/log.h | 129 +++++++++++++++++++++++---------------------------- 2 files changed, 60 insertions(+), 71 deletions(-) diff --git a/Makefile b/Makefile index 5bbcde7e47511..506950bf22e48 100644 --- a/Makefile +++ b/Makefile @@ -327,7 +327,7 @@ k_quants.o: k_quants.c k_quants.h endif # LLAMA_NO_K_QUANTS ifdef LLAMA_DISABLE_LOGS - CFLAGS += -DLOG_DISABLE_LOGS + CFLAGS += -DLOG_DISABLE_LOGS CXXFLAGS += -DLOG_DISABLE_LOGS endif # LLAMA_DISABLE_LOGS diff --git a/common/log.h b/common/log.h index b5e1666e9e15e..43f1635823f74 100644 --- a/common/log.h +++ b/common/log.h @@ -7,6 +7,7 @@ #include #include #include +#include // -------------------------------- // @@ -89,11 +90,11 @@ // } // #ifndef LOG_TARGET -/**/ #define LOG_TARGET log_handler() +#define LOG_TARGET log_handler() #endif #ifndef LOG_TEE_TARGET -/**/ #define LOG_TEE_TARGET stderr +#define LOG_TEE_TARGET stderr #endif // Utility to obtain "pid" like unique process id and use it when creating log files. @@ -101,9 +102,6 @@ inline std::string log_get_pid() { static std::string pid; if (pid.empty()) -#ifndef _WIN32 - [[unlikely]] -#endif { // 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 @@ -123,7 +121,7 @@ inline std::string log_get_pid() #define LOG_FILENAME_GENERATOR(log_file_basename, log_file_extension) _log_filename_generator(log_file_basename, log_file_extension) // INTERNAL, DO NOT USE -inline std::string _log_filename_generator(std::string log_file_basename, std::string log_file_extension) +inline std::string _log_filename_generator(const std::string & log_file_basename, const std::string & log_file_extension) { return std::string().append(log_file_basename).append(".").append(log_get_pid()).append(".").append(log_file_extension); } @@ -149,10 +147,10 @@ inline std::string _log_filename_generator(std::string log_file_basename, std::s // #ifndef LOG_NO_TIMESTAMPS /**/#ifndef _WIN32 -/* */#define LOG_TIMESTAMP_FMT "[%lu]" +/* */#define LOG_TIMESTAMP_FMT "[%" PRIu64 "]" /* */#define LOG_TIMESTAMP_VAL , (std::chrono::duration_cast>(std::chrono::system_clock::now().time_since_epoch())).count() /**/#else -/* */#define LOG_TIMESTAMP_FMT "[%llu]" +/* */#define LOG_TIMESTAMP_FMT "[%" PRIu64 "]" /* */#define LOG_TIMESTAMP_VAL , (std::chrono::duration_cast>(std::chrono::system_clock::now().time_since_epoch())).count() /**/#endif #else @@ -162,10 +160,10 @@ inline std::string _log_filename_generator(std::string log_file_basename, std::s #ifdef LOG_TEE_TIMESTAMPS /**/#ifndef _WIN32 -/* */#define LOG_TEE_TIMESTAMP_FMT "[%lu]" +/* */#define LOG_TEE_TIMESTAMP_FMT "[%" PRIu64 "]" /* */#define LOG_TEE_TIMESTAMP_VAL , (std::chrono::duration_cast>(std::chrono::system_clock::now().time_since_epoch())).count() /**/#else -/* */#define LOG_TEE_TIMESTAMP_FMT "[%llu]" +/* */#define LOG_TEE_TIMESTAMP_FMT "[%" PRIu64 "]" /* */#define LOG_TEE_TIMESTAMP_VAL , (std::chrono::duration_cast>(std::chrono::system_clock::now().time_since_epoch())).count() /**/#endif #else @@ -219,22 +217,22 @@ enum LogTriState // USE LOG() INSTEAD // #ifndef _WIN32 -/**/#define _LOG(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(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); \ + } \ } #else -/**/#define _LOG(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(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); \ + } \ } #endif @@ -242,32 +240,32 @@ enum LogTriState // USE LOG_TEE() INSTEAD // #ifndef _WIN32 -/**/#define _LOG_TEE(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 != nullptr && 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(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 != nullptr && 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); \ + } \ } #else -/**/#define _LOG_TEE(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 != nullptr && 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(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 != nullptr && 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); \ + } \ } #endif @@ -308,7 +306,7 @@ enum LogTriState #endif // INTERNAL, DO NOT USE -inline FILE *_log_handler1(bool change = false, LogTriState disable = LogTriStateSame, std::string filename = LOG_DEFAULT_FILE_NAME, FILE *target = nullptr) +inline FILE *_log_handler1(bool change = false, LogTriState disable = LogTriStateSame, const std::string & filename = LOG_DEFAULT_FILE_NAME, FILE *target = nullptr) { static bool _initialized{false}; static bool _disabled{(filename.empty() && target == nullptr)}; @@ -317,9 +315,6 @@ inline FILE *_log_handler1(bool change = false, LogTriState disable = LogTriStat static FILE *logfile = nullptr; if (change) -#ifndef _WIN32 - [[unlikely]] -#endif { if (disable == LogTriStateTrue) { @@ -334,7 +329,7 @@ inline FILE *_log_handler1(bool change = false, LogTriState disable = LogTriStat // Otherwise, process the arguments else { - if (log_current_filename.compare(filename) != 0) + if (log_current_filename != filename) { _initialized = false; } @@ -347,16 +342,13 @@ inline FILE *_log_handler1(bool change = false, LogTriState disable = LogTriStat } if (_initialized) -#ifndef _WIN32 - [[likely]] -#endif { if (_disabled) { // Log is disabled return nullptr; } - else + else // NOLINT { // with fallback in case something went wrong return logfile ? logfile : stderr; @@ -378,10 +370,7 @@ inline FILE *_log_handler1(bool change = false, LogTriState disable = LogTriStat } else { - if (log_current_filename.compare(filename) != 0) -#ifndef _WIN32 - [[likely]] -#endif + if (log_current_filename != filename) { if (logfile != nullptr && logfile != stdout && logfile != stderr) { @@ -415,7 +404,7 @@ inline FILE *_log_handler1(bool change = false, LogTriState disable = LogTriStat } // INTERNAL, DO NOT USE -inline FILE *_log_handler2(bool change = false, LogTriState disable = LogTriStateSame, FILE *target = nullptr, std::string filename = LOG_DEFAULT_FILE_NAME) +inline FILE *_log_handler2(bool change = false, LogTriState disable = LogTriStateSame, FILE *target = nullptr, const std::string & filename = LOG_DEFAULT_FILE_NAME) { return _log_handler1(change, disable, filename, target); } @@ -444,7 +433,7 @@ inline FILE *_log_enable() #define LOG_SET_TARGET(target) _log_set_target(target) // INTERNAL, DO NOT USE -inline FILE *_log_set_target(std::string filename) { return _log_handler1(true, LogTriStateSame, filename); } +inline FILE *_log_set_target(const std::string & filename) { return _log_handler1(true, LogTriStateSame, filename); } inline FILE *_log_set_target(FILE *target) { return _log_handler2(true, LogTriStateSame, target); } // INTERNAL, DO NOT USE @@ -491,19 +480,19 @@ inline void log_test() #endif } -inline bool log_param_single_parse(std::string param) +inline bool log_param_single_parse(const std::string & param) { - if (std::string("--log-test").compare(param) == 0) + if (std::string("--log-test") == param) { log_test(); return true; } - else if (std::string("--log-disable").compare(param) == 0) + else if (std::string("--log-disable") == param) // NOLINT { LOG_DISABLE(); return true; } - else if (std::string("--log-enable").compare(param) == 0) + else if (std::string("--log-enable") == param) { LOG_ENABLE(); return true; @@ -512,9 +501,9 @@ inline bool log_param_single_parse(std::string param) return false; } -inline bool log_param_pair_parse(bool check_but_dont_parse, std::string param, std::string next = std::string()) +inline bool log_param_pair_parse(bool check_but_dont_parse, const std::string & param, const std::string & next = std::string()) { - if (std::string("--log-file").compare(param) == 0) + if (std::string("--log-file") == param) { if (check_but_dont_parse) { @@ -573,7 +562,7 @@ inline std::string _log_var_to_string(std::string var) return var; } -inline std::string _log_var_to_string(std::vector var) +inline std::string _log_var_to_string(const std::vector & var) { std::string buf; buf.append("[ "); From 6b4c65be83217f91da61a67a0542eeeb5b7ec8ab Mon Sep 17 00:00:00 2001 From: Georgi Gerganov Date: Tue, 29 Aug 2023 13:59:55 +0300 Subject: [PATCH 18/27] log : do not append to existing log + disable file line func by default --- common/common.h | 1 + common/log.h | 16 ++++++++-------- 2 files changed, 9 insertions(+), 8 deletions(-) diff --git a/common/common.h b/common/common.h index af8522c5b2cf2..5a379688ee529 100644 --- a/common/common.h +++ b/common/common.h @@ -4,6 +4,7 @@ #include "llama.h" +#define LOG_NO_FILE_LINE_FUNCTION #include "log.h" #include diff --git a/common/log.h b/common/log.h index 43f1635823f74..37cbd2101c4cb 100644 --- a/common/log.h +++ b/common/log.h @@ -90,11 +90,11 @@ // } // #ifndef LOG_TARGET -#define LOG_TARGET log_handler() + #define LOG_TARGET log_handler() #endif #ifndef LOG_TEE_TARGET -#define LOG_TEE_TARGET stderr + #define LOG_TEE_TARGET stderr #endif // Utility to obtain "pid" like unique process id and use it when creating log files. @@ -147,10 +147,10 @@ inline std::string _log_filename_generator(const std::string & log_file_basename // #ifndef LOG_NO_TIMESTAMPS /**/#ifndef _WIN32 -/* */#define LOG_TIMESTAMP_FMT "[%" PRIu64 "]" +/* */#define LOG_TIMESTAMP_FMT "[%" PRIu64 "] " /* */#define LOG_TIMESTAMP_VAL , (std::chrono::duration_cast>(std::chrono::system_clock::now().time_since_epoch())).count() /**/#else -/* */#define LOG_TIMESTAMP_FMT "[%" PRIu64 "]" +/* */#define LOG_TIMESTAMP_FMT "[%" PRIu64 "] " /* */#define LOG_TIMESTAMP_VAL , (std::chrono::duration_cast>(std::chrono::system_clock::now().time_since_epoch())).count() /**/#endif #else @@ -160,10 +160,10 @@ inline std::string _log_filename_generator(const std::string & log_file_basename #ifdef LOG_TEE_TIMESTAMPS /**/#ifndef _WIN32 -/* */#define LOG_TEE_TIMESTAMP_FMT "[%" PRIu64 "]" +/* */#define LOG_TEE_TIMESTAMP_FMT "[%" PRIu64 "] " /* */#define LOG_TEE_TIMESTAMP_VAL , (std::chrono::duration_cast>(std::chrono::system_clock::now().time_since_epoch())).count() /**/#else -/* */#define LOG_TEE_TIMESTAMP_FMT "[%" PRIu64 "]" +/* */#define LOG_TEE_TIMESTAMP_FMT "[%" PRIu64 "] " /* */#define LOG_TEE_TIMESTAMP_VAL , (std::chrono::duration_cast>(std::chrono::system_clock::now().time_since_epoch())).count() /**/#endif #else @@ -378,11 +378,11 @@ inline FILE *_log_handler1(bool change = false, LogTriState disable = LogTriStat } logfile = nullptr; - logfile = fopen(filename.c_str(), "a"); + logfile = fopen(filename.c_str(), "w"); } else { - logfile = fopen(filename.c_str(), "a"); + logfile = fopen(filename.c_str(), "w"); } } From 5c978f48a4223833c8faec8e4b91e41fb3c3194c Mon Sep 17 00:00:00 2001 From: Georgi Gerganov Date: Tue, 29 Aug 2023 14:21:14 +0300 Subject: [PATCH 19/27] log : try to fix Windows build --- common/log.h | 40 ++++++++++++++++++++-------------------- 1 file changed, 20 insertions(+), 20 deletions(-) diff --git a/common/log.h b/common/log.h index 37cbd2101c4cb..d0d5495afed95 100644 --- a/common/log.h +++ b/common/log.h @@ -226,13 +226,13 @@ enum LogTriState } \ } #else -/**/#define _LOG(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(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); \ + } \ } #endif @@ -254,18 +254,18 @@ enum LogTriState } \ } #else -/**/#define _LOG_TEE(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 != nullptr && 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(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 != nullptr && 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); \ + } \ } #endif @@ -584,7 +584,7 @@ inline std::string _log_var_to_string(const std::vector & var) return buf; } -#define LOG_TOKENS_TOSTR_PRETTY(tokens, ctx) \ +#define LOG_TOKENS_TOSTR_PRETTY(ctx, tokens) \ [&tokens, &ctx]() \ { \ std::string buf("[ "); \ From c72d344c1a0aa9c22cbdf40858a9fee581b157ad Mon Sep 17 00:00:00 2001 From: Georgi Gerganov Date: Tue, 29 Aug 2023 14:23:39 +0300 Subject: [PATCH 20/27] main : wip logs --- examples/main/main.cpp | 57 +++++++++++++++++++++--------------------- 1 file changed, 29 insertions(+), 28 deletions(-) diff --git a/examples/main/main.cpp b/examples/main/main.cpp index 3aa0f27aa2577..94958b0ea8f53 100644 --- a/examples/main/main.cpp +++ b/examples/main/main.cpp @@ -115,12 +115,12 @@ int main(int argc, char ** argv) { #ifndef LOG_DISABLE_LOGS LOG_SET_TARGET(LOG_FILENAME_GENERATOR("main", "log")); - LOG_TEE("Log start\n") + LOG_TEE("Log start\n"); LOG_DUMP_CMDLINE(argc,argv); #endif // LOG_DISABLE_LOGS // TODO: Dump params ? - //LOG("Params perplexity: %s\n", LOG_TOSTR(params.perplexity)) + //LOG("Params perplexity: %s\n", LOG_TOSTR(params.perplexity)); // save choice to use color for later // (note for later: this is a slightly awkward choice) @@ -172,7 +172,7 @@ int main(int argc, char ** argv) { params.prompt = gpt_random_prompt(rng); } - LOG("llama backend init\n") + LOG("%s: llama backend init\n", __func__); llama_backend_init(params.numa); llama_model * model; @@ -182,7 +182,7 @@ int main(int argc, char ** argv) { g_ctx = &ctx; // load the model and apply lora adapter, if any - LOG("load the model and apply lora adapter, if any\n") + LOG("%s: load the model and apply lora adapter, if any\n", __func__); std::tie(model, ctx) = llama_init_from_gpt_params(params); if (params.cfg_scale > 1.f) { struct llama_context_params lparams = llama_context_params_from_gpt_params(params); @@ -253,27 +253,26 @@ int main(int argc, char ** argv) { } } - // Add BOS if SPM tokenizer const bool add_bos = llama_vocab_type(ctx) == LLAMA_VOCAB_TYPE_SPM; + LOG("add_bos: %d\n", add_bos); - // tokenize the prompt - LOG("Tokenize the prompt\n") std::vector embd_inp; if (params.interactive_first || params.instruct || !params.prompt.empty() || session_tokens.empty()) { + LOG("tokenize the prompt\n"); embd_inp = ::llama_tokenize(ctx, params.prompt, add_bos); } else { + LOG("use session tokens\n"); embd_inp = session_tokens; } - LOG("prompt: \"%s\"\n", LOG_TOSTR(params.prompt)) - //LOG("Prompt tokenized: %s\n", LOG_TOSTR(embd_inp)) - LOG("embd_inp tokenized: %s\n", LOG_TOKENS_TOSTR_PRETTY(embd_inp,ctx)) + LOG("prompt: \"%s\"\n", LOG_TOSTR(params.prompt)); + LOG("tokens: %s\n", LOG_TOKENS_TOSTR_PRETTY(ctx, embd_inp)); // Should not run without any tokens if (embd_inp.empty()) { embd_inp.push_back(llama_token_bos(ctx)); - LOG("embd_inp was considered empty and bos was added: %s\n", LOG_TOKENS_TOSTR_PRETTY(embd_inp,ctx)) + LOG("embd_inp was considered empty and bos was added: %s\n", LOG_TOKENS_TOSTR_PRETTY(ctx, embd_inp)); } // Tokenize negative prompt @@ -281,22 +280,22 @@ int main(int argc, char ** argv) { int guidance_offset = 0; int original_prompt_len = 0; if (ctx_guidance) { - LOG("cfg_negative_prompt: \"%s\"\n", LOG_TOSTR(params.cfg_negative_prompt)) + LOG("cfg_negative_prompt: \"%s\"\n", LOG_TOSTR(params.cfg_negative_prompt)); guidance_inp = ::llama_tokenize(ctx_guidance, params.cfg_negative_prompt, add_bos); - LOG("guidance_inp tokenized: %s\n", LOG_TOKENS_TOSTR_PRETTY(guidance_inp,ctx_guidance)) + LOG("guidance_inp tokenized: %s\n", LOG_TOKENS_TOSTR_PRETTY(ctx_guidance, guidance_inp)); std::vector original_inp = ::llama_tokenize(ctx, params.prompt, add_bos); - LOG("original_inp tokenized: %s\n", LOG_TOKENS_TOSTR_PRETTY(original_inp,ctx)) + LOG("original_inp tokenized: %s\n", LOG_TOKENS_TOSTR_PRETTY(ctx, original_inp)); original_prompt_len = original_inp.size(); guidance_offset = (int)guidance_inp.size() - original_prompt_len; - LOG("original_prompt_len: %s", LOG_TOSTR(original_prompt_len)) - LOG("guidance_offset: %s", LOG_TOSTR(guidance_offset)) + LOG("original_prompt_len: %s", LOG_TOSTR(original_prompt_len)); + LOG("guidance_offset: %s", LOG_TOSTR(guidance_offset)); } const int n_ctx = llama_n_ctx(ctx); - LOG("n_ctx: %d\n", n_ctx) + LOG("n_ctx: %d\n", n_ctx); if ((int) embd_inp.size() > n_ctx - 4) { LOG_TEE("%s: error: prompt is too long (%d tokens, max %d)\n", __func__, (int) embd_inp.size(), n_ctx - 4); @@ -305,7 +304,7 @@ int main(int argc, char ** argv) { // debug message about similarity of saved session, if applicable size_t n_matching_session_tokens = 0; - if (session_tokens.size()) { + if (session_tokens.size() > 0) { for (llama_token id : session_tokens) { if (n_matching_session_tokens >= embd_inp.size() || id != embd_inp[n_matching_session_tokens]) { break; @@ -327,14 +326,12 @@ 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()) + 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 - if (!embd_inp.empty() && n_matching_session_tokens == embd_inp.size() && - session_tokens.size() > embd_inp.size()) { - - LOGLN("recalculate the cached logits (do): session_tokens.resize( %zu )", embd_inp.size() - 1) + if (!embd_inp.empty() && n_matching_session_tokens == embd_inp.size() && session_tokens.size() > embd_inp.size()) { + LOGLN("recalculate the cached logits (do): session_tokens.resize( %zu )", embd_inp.size() - 1); session_tokens.resize(embd_inp.size() - 1); } @@ -348,6 +345,9 @@ int main(int argc, char ** argv) { const auto inp_pfx = ::llama_tokenize(ctx, "\n\n### Instruction:\n\n", add_bos); const auto inp_sfx = ::llama_tokenize(ctx, "\n\n### Response:\n\n", false); + LOG("inp_pfx: %s\n", LOG_TOKENS_TOSTR_PRETTY(ctx, inp_pfx)); + LOG("inp_sfx: %s\n", LOG_TOKENS_TOSTR_PRETTY(ctx, inp_sfx)); + // in instruct mode, we inject a prefix and a suffix to each input by the user if (params.instruct) { params.interactive_first = true; @@ -403,7 +403,7 @@ int main(int argc, char ** argv) { LOG_TEE("%s: interactive mode on.\n", __func__); if (params.antiprompt.size()) { - for (auto antiprompt : params.antiprompt) { + for (const auto & antiprompt : params.antiprompt) { LOG_TEE("Reverse prompt: '%s'\n", antiprompt.c_str()); } } @@ -463,11 +463,11 @@ int main(int argc, char ** argv) { " - To return control without starting a new line, end your input with '/'.\n" " - If you want to submit another line, end your input with '\\'.\n"; } - fprintf(stderr, "== Running in interactive mode. ==\n" + LOG_TEE("== Running in interactive mode. ==\n"); #if defined (__unix__) || (defined (__APPLE__) && defined (__MACH__)) || defined (_WIN32) - " - Press Ctrl+C to interject at any time.\n" + LOG_TEE( " - Press Ctrl+C to interject at any time.\n"); #endif - "%s\n", control_message); + LOG_TEE( "%s\n", control_message); is_interacting = params.interactive_first; } @@ -492,8 +492,9 @@ int main(int argc, char ** argv) { std::vector embd; std::vector embd_guidance; - // do one empty run to warm up the model { + LOG("warming up the model with an empty run\n"); + const std::vector tmp = { llama_token_bos(ctx), }; llama_eval(ctx, tmp.data(), tmp.size(), 0, params.n_threads); llama_reset_timings(ctx); From ecdf113c69861c2b4694affecd158858dbe8cdf0 Mon Sep 17 00:00:00 2001 From: Georgi Gerganov Date: Tue, 29 Aug 2023 15:12:37 +0300 Subject: [PATCH 21/27] main : add trace log --- examples/chat.sh | 2 +- examples/main/main.cpp | 138 ++++++++++++++++++++++++++--------------- 2 files changed, 90 insertions(+), 50 deletions(-) diff --git a/examples/chat.sh b/examples/chat.sh index 9a928ef05431a..d567acecdff11 100755 --- a/examples/chat.sh +++ b/examples/chat.sh @@ -11,6 +11,6 @@ cd .. # # "--keep 48" is based on the contents of prompts/chat-with-bob.txt # -./main -m ./models/7B/ggml-model-q4_0.bin -c 512 -b 1024 -n 256 --keep 48 \ +./main -m ./models/llama-7b/ggml-model-q4_0.gguf -c 512 -b 1024 -n 256 --keep 48 \ --repeat_penalty 1.0 --color -i \ -r "User:" -f prompts/chat-with-bob.txt diff --git a/examples/main/main.cpp b/examples/main/main.cpp index 94958b0ea8f53..436eeb7178cf5 100644 --- a/examples/main/main.cpp +++ b/examples/main/main.cpp @@ -505,15 +505,17 @@ int main(int argc, char ** argv) { if (embd.size() > 0) { // Note: n_ctx - 4 here is to match the logic for commandline prompt handling via // --prompt or --file which uses the same value. - auto max_embd_size = n_ctx - 4; + int max_embd_size = n_ctx - 4; + // Ensure the input doesn't exceed the context size by truncating embd if necessary. - if ((int)embd.size() > max_embd_size) { - auto skipped_tokens = embd.size() - max_embd_size; + if ((int) embd.size() > max_embd_size) { + const int skipped_tokens = (int) embd.size() - max_embd_size; + embd.resize(max_embd_size); + console::set_display(console::error); - printf("<>", skipped_tokens, skipped_tokens != 1 ? "s" : ""); + printf("<>", skipped_tokens, skipped_tokens != 1 ? "s" : ""); console::set_display(console::reset); fflush(stdout); - embd.resize(max_embd_size); } // infinite text generation via context swapping @@ -522,28 +524,26 @@ int main(int argc, char ** argv) { // - take half of the last (n_ctx - n_keep) tokens and recompute the logits in batches if (n_past + (int) embd.size() + std::max(0, guidance_offset) > n_ctx) { if (params.n_predict == -2) { - LOG_TEE("\n\n%s: context full, stopping generation\n", __func__); + LOG_TEE("\n\n%s: context full and n_predict == -%d => stopping\n", __func__, params.n_predict); break; } 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); + // always keep the first token - BOS - n_past = std::max(1, params.n_keep); + n_past = std::max(1, params.n_keep); n_past_guidance = std::max(1, params.n_keep + guidance_offset); + LOG("after swap: n_past = %d, n_past_guidance = %d\n", n_past, n_past_guidance); + // insert n_left/2 tokens at the start of embd from last_n_tokens embd.insert(embd.begin(), last_n_tokens.begin() + n_ctx - n_left/2 - embd.size(), last_n_tokens.end() - embd.size()); - // stop saving session if we run out of context - path_session.clear(); + LOG("embd: %s\n", LOG_TOKENS_TOSTR_PRETTY(ctx, embd)); - //printf("\n---\n"); - //printf("resetting: '"); - //for (int i = 0; i < (int) embd.size(); i++) { - // printf("%s", llama_token_to_piece(ctx, embd[i])); - //} - //printf("'\n"); - //printf("\n---\n"); + LOG("clear session path\n"); + path_session.clear(); } // try to reuse a matching prefix from the loaded session instead of re-eval (via n_past) @@ -573,7 +573,7 @@ int main(int argc, char ** argv) { if (ctx_guidance) { int input_size = 0; - llama_token* input_buf = NULL; + llama_token * input_buf = NULL; if (n_past_guidance < (int) guidance_inp.size()) { // Guidance context should have the same data with these modifications: @@ -589,15 +589,12 @@ int main(int argc, char ** argv) { ); } - input_buf = embd_guidance.data(); + input_buf = embd_guidance.data(); input_size = embd_guidance.size(); - //LOG_TEE("\n---------------------\n"); - //for (int i = 0; i < (int) embd_guidance.size(); i++) { - //LOG_TEE("%s", llama_token_to_piece(ctx, embd_guidance[i])); - //} - //LOG_TEE("\n---------------------\n"); + + LOG("guidance context: %s\n", LOG_TOKENS_TOSTR_PRETTY(ctx, embd_guidance)); } else { - input_buf = embd.data(); + input_buf = embd.data(); input_size = embd.size(); } @@ -617,11 +614,17 @@ int main(int argc, char ** argv) { if (n_eval > params.n_batch) { n_eval = params.n_batch; } + + LOG("eval: %s\n", LOG_TOKENS_TOSTR_PRETTY(ctx, embd)); + if (llama_eval(ctx, &embd[i], n_eval, n_past, params.n_threads)) { LOG_TEE("%s : failed to eval\n", __func__); return 1; } + n_past += n_eval; + + LOG("n_past = %d\n", n_past); } if (embd.size() > 0 && !path_session.empty()) { @@ -634,7 +637,6 @@ int main(int argc, char ** argv) { embd_guidance.clear(); if ((int) embd_inp.size() <= n_consumed && !is_interacting) { - // out of user input, sample next token const float temp = params.temp; const int32_t top_k = params.top_k <= 0 ? llama_n_vocab(ctx) : params.top_k; const float top_p = params.top_p; @@ -653,6 +655,8 @@ int main(int argc, char ** argv) { if (!path_session.empty() && need_to_save_session && !params.prompt_cache_ro) { need_to_save_session = false; llama_save_session_file(ctx, path_session.c_str(), session_tokens.data(), session_tokens.size()); + + LOG("saved session to %s\n", path_session.c_str()); } llama_token id = 0; @@ -672,55 +676,68 @@ int main(int argc, char ** argv) { candidates.emplace_back(llama_token_data{token_id, logits[token_id], 0.0f}); } - llama_token_data_array candidates_p = { candidates.data(), candidates.size(), false }; + llama_token_data_array cur_p = { candidates.data(), candidates.size(), false }; if (ctx_guidance) { - llama_sample_classifier_free_guidance(ctx, &candidates_p, ctx_guidance, params.cfg_scale); + llama_sample_classifier_free_guidance(ctx, &cur_p, ctx_guidance, params.cfg_scale); } // Apply penalties float nl_logit = logits[llama_token_nl(ctx)]; auto last_n_repeat = std::min(std::min((int)last_n_tokens.size(), repeat_last_n), n_ctx); - llama_sample_repetition_penalty(ctx, &candidates_p, + llama_sample_repetition_penalty(ctx, &cur_p, last_n_tokens.data() + last_n_tokens.size() - last_n_repeat, last_n_repeat, repeat_penalty); - llama_sample_frequency_and_presence_penalties(ctx, &candidates_p, + llama_sample_frequency_and_presence_penalties(ctx, &cur_p, last_n_tokens.data() + last_n_tokens.size() - last_n_repeat, last_n_repeat, alpha_frequency, alpha_presence); if (!penalize_nl) { - for (size_t idx = 0; idx < candidates_p.size; idx++) { - if (candidates_p.data[idx].id == llama_token_nl(ctx)) { - candidates_p.data[idx].logit = nl_logit; + for (size_t idx = 0; idx < cur_p.size; idx++) { + if (cur_p.data[idx].id == llama_token_nl(ctx)) { + cur_p.data[idx].logit = nl_logit; break; } } } if (grammar != NULL) { - llama_sample_grammar(ctx, &candidates_p, grammar); + llama_sample_grammar(ctx, &cur_p, grammar); } if (temp <= 0) { // Greedy sampling - id = llama_sample_token_greedy(ctx, &candidates_p); + id = llama_sample_token_greedy(ctx, &cur_p); } else { if (mirostat == 1) { static float mirostat_mu = 2.0f * mirostat_tau; const int mirostat_m = 100; - llama_sample_temperature(ctx, &candidates_p, temp); - id = llama_sample_token_mirostat(ctx, &candidates_p, mirostat_tau, mirostat_eta, mirostat_m, &mirostat_mu); + llama_sample_temperature(ctx, &cur_p, temp); + id = llama_sample_token_mirostat(ctx, &cur_p, mirostat_tau, mirostat_eta, mirostat_m, &mirostat_mu); } else if (mirostat == 2) { static float mirostat_mu = 2.0f * mirostat_tau; - llama_sample_temperature(ctx, &candidates_p, temp); - id = llama_sample_token_mirostat_v2(ctx, &candidates_p, mirostat_tau, mirostat_eta, &mirostat_mu); + llama_sample_temperature(ctx, &cur_p, temp); + id = llama_sample_token_mirostat_v2(ctx, &cur_p, mirostat_tau, mirostat_eta, &mirostat_mu); } else { // Temperature sampling - llama_sample_top_k(ctx, &candidates_p, top_k, 1); - llama_sample_tail_free(ctx, &candidates_p, tfs_z, 1); - llama_sample_typical(ctx, &candidates_p, typical_p, 1); - llama_sample_top_p(ctx, &candidates_p, top_p, 1); - llama_sample_temperature(ctx, &candidates_p, temp); - id = llama_sample_token(ctx, &candidates_p); + llama_sample_top_k (ctx, &cur_p, top_k, 1); + llama_sample_tail_free (ctx, &cur_p, tfs_z, 1); + llama_sample_typical (ctx, &cur_p, typical_p, 1); + llama_sample_top_p (ctx, &cur_p, top_p, 1); + llama_sample_temperature(ctx, &cur_p, temp); + + { + const int n_top = 10; + LOG("top %d candidates:\n", n_top); + + for (int i = 0; i < n_top; i++) { + const llama_token id = cur_p.data[i].id; + LOG(" - %5d: '%12s' (%.3f)\n", id, llama_token_to_piece(ctx, id).c_str(), cur_p.data[i].p); + } + } + + id = llama_sample_token(ctx, &cur_p); + + LOG("sampled token: %5d: '%s'\n", id, llama_token_to_piece(ctx, id).c_str()); } } // printf("`%d`", candidates_p.size); @@ -731,9 +748,10 @@ int main(int argc, char ** argv) { last_n_tokens.erase(last_n_tokens.begin()); last_n_tokens.push_back(id); + + LOG("last: %s\n", LOG_TOKENS_TOSTR_PRETTY(ctx, last_n_tokens)); } - // add it to the context embd.push_back(id); // echo this to console @@ -741,8 +759,11 @@ int main(int argc, char ** argv) { // decrement remaining sampling budget --n_remain; + + LOG("n_remain: %d\n", n_remain); } else { // some user input remains from prompt or interaction, forward it to processing + LOG("embd_inp.size(): %d, n_consumed: %d\n", (int) embd_inp.size(), n_consumed); while ((int) embd_inp.size() > n_consumed) { embd.push_back(embd_inp[n_consumed]); last_n_tokens.erase(last_n_tokens.begin()); @@ -770,13 +791,12 @@ int main(int argc, char ** argv) { fflush(stdout); } // reset color to default if we there is no pending user input - if (input_echo && (int)embd_inp.size() == n_consumed) { + if (input_echo && (int) embd_inp.size() == n_consumed) { console::set_display(console::reset); } // if not currently processing queued inputs; if ((int) embd_inp.size() <= n_consumed) { - // check for reverse prompt if (params.antiprompt.size()) { std::string last_output; @@ -794,7 +814,7 @@ int main(int argc, char ** argv) { ? last_output.length() - static_cast(antiprompt.length() + extra_padding) : 0; - if (last_output.find(antiprompt.c_str(), search_start_pos) != std::string::npos) { + if (last_output.find(antiprompt, search_start_pos) != std::string::npos) { if (params.interactive) { is_interacting = true; console::set_display(console::user_input); @@ -804,10 +824,16 @@ int main(int argc, char ** argv) { break; } } + + if (is_antiprompt) { + LOG("found antiprompt: %s\n", last_output.c_str()); + } } // deal with end of text token in interactive mode if (last_n_tokens.back() == llama_token_eos(ctx)) { + LOG("found EOS token\n"); + if (params.interactive) { if (params.antiprompt.size() != 0) { // tokenize and inject first reverse prompt @@ -826,16 +852,20 @@ int main(int argc, char ** argv) { } if (n_past > 0 && is_interacting) { + LOG("waiting for user input\n"); + if (params.instruct) { printf("\n> "); } if (params.input_prefix_bos) { + LOG("adding input prefix BOS token\n"); embd_inp.push_back(llama_token_bos(ctx)); } std::string buffer; if (!params.input_prefix.empty()) { + LOG("appending input prefix: '%s'\n", params.input_prefix.c_str()); buffer += params.input_prefix; printf("%s", buffer.c_str()); } @@ -855,23 +885,30 @@ int main(int argc, char ** argv) { if (buffer.length() > 1) { // append input suffix if any if (!params.input_suffix.empty()) { + LOG("appending input suffix: '%s'\n", params.input_suffix.c_str()); buffer += params.input_suffix; printf("%s", params.input_suffix.c_str()); } + LOG("buffer: '%s'\n", buffer.c_str()); + const size_t original_size = embd_inp.size(); // instruct mode: insert instruction prefix if (params.instruct && !is_antiprompt) { + LOG("inserting instruction prefix\n"); n_consumed = embd_inp.size(); embd_inp.insert(embd_inp.end(), inp_pfx.begin(), inp_pfx.end()); } - auto line_inp = ::llama_tokenize(ctx, buffer, false); + const auto line_inp = ::llama_tokenize(ctx, buffer, false); + LOG("input tokens: %s\n", LOG_TOKENS_TOSTR_PRETTY(ctx, line_inp)); + embd_inp.insert(embd_inp.end(), line_inp.begin(), line_inp.end()); // instruct mode: insert response suffix if (params.instruct) { + LOG("inserting instruction suffix\n"); embd_inp.insert(embd_inp.end(), inp_sfx.begin(), inp_sfx.end()); } @@ -882,6 +919,9 @@ int main(int argc, char ** argv) { } n_remain -= line_inp.size(); + LOG("n_remain: %d\n", n_remain); + } else { + LOG("empty line, passing control back\n"); } input_echo = false; // do not echo this again From 3a10f5aa34243d2f54bc8c917cbb0425b9938eb6 Mon Sep 17 00:00:00 2001 From: staviq Date: Tue, 29 Aug 2023 17:29:37 +0200 Subject: [PATCH 22/27] review: macro f lowercase, str append to sstream --- common/log.h | 95 +++++++++++++++++++++++------------------- examples/main/main.cpp | 14 +++---- 2 files changed, 59 insertions(+), 50 deletions(-) diff --git a/common/log.h b/common/log.h index d0d5495afed95..9f45a1f37a7c9 100644 --- a/common/log.h +++ b/common/log.h @@ -115,19 +115,27 @@ inline std::string log_get_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" +// 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(log_file_basename, log_file_extension) +#define log_filename_generator(log_file_basename, log_file_extension) _log_filename_generator(log_file_basename, log_file_extension) // INTERNAL, DO NOT USE inline std::string _log_filename_generator(const std::string & log_file_basename, const std::string & log_file_extension) { - return std::string().append(log_file_basename).append(".").append(log_get_pid()).append(".").append(log_file_extension); + std::stringstream buf; + + buf << log_file_basename; + buf << "."; + buf << log_get_pid(); + buf << "."; + buf << log_file_extension; + + return buf.str(); } #ifndef LOG_DEFAULT_FILE_NAME -/**/#define LOG_DEFAULT_FILE_NAME LOG_FILENAME_GENERATOR("llama", "log") +/**/#define LOG_DEFAULT_FILE_NAME log_filename_generator("llama", "log") #endif // Utility for turning #define values into string literals @@ -412,7 +420,7 @@ inline FILE *_log_handler2(bool change = false, LogTriState disable = LogTriStat // Disables logs entirely at runtime. // Makes LOG() and LOG_TEE() produce no output, // untill enabled back. -#define LOG_DISABLE() _log_disable() +#define log_disable() _log_disable() // INTERNAL, DO NOT USE inline FILE *_log_disable() @@ -421,7 +429,7 @@ inline FILE *_log_disable() } // Enables logs at runtime. -#define LOG_ENABLE() _log_enable() +#define log_enable() _log_enable() // INTERNAL, DO NOT USE inline FILE *_log_enable() @@ -430,7 +438,7 @@ inline FILE *_log_enable() } // 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(target) +#define log_set_target(target) _log_set_target(target) // INTERNAL, DO NOT USE inline FILE *_log_set_target(const std::string & filename) { return _log_handler1(true, LogTriStateSame, filename); } @@ -441,32 +449,32 @@ inline FILE *log_handler() { return _log_handler1(); } inline void log_test() { - LOG_DISABLE(); + log_disable(); LOG("01 Hello World to nobody, because logs are disabled!\n") - LOG_ENABLE(); + log_enable(); LOG("02 Hello World to default output, which is \"%s\" ( Yaaay, arguments! )!\n", LOG_STRINGIZE(LOG_TARGET)) LOG_TEE("03 Hello World to **both** default output and " LOG_TEE_TARGET_STRING "!\n") - LOG_SET_TARGET(stderr); + 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("06 Hello World to default log file!\n") - LOG_SET_TARGET(stdout); + 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("08 Hello World to default log file again!\n") - LOG_DISABLE(); + log_disable(); LOG("09 Hello World _1_ into the void!\n") - LOG_ENABLE(); + log_enable(); LOG("10 Hello World back from the void ( you should not see _1_ in the log or the output )!\n") - LOG_DISABLE(); - LOG_SET_TARGET("llama.anotherlog.log"); + log_disable(); + log_set_target("llama.anotherlog.log"); LOG("11 Hello World _2_ to nobody, new target was selected but logs are still disabled!\n") - LOG_ENABLE(); + log_enable(); LOG("12 Hello World this time in a new file ( you should not see _2_ in the log or the output )?\n") - LOG_SET_TARGET("llama.yetanotherlog.log"); + log_set_target("llama.yetanotherlog.log"); LOG("13 Hello World this time in yet new file?\n") - LOG_SET_TARGET(LOG_FILENAME_GENERATOR("llama_autonamed", "log")); + log_set_target(log_filename_generator("llama_autonamed", "log")); LOG("14 Hello World in log with generated filename!\n") #ifdef _WIN32 LOG_TEE("15 Hello msvc TEE without arguments\n") @@ -489,12 +497,12 @@ inline bool log_param_single_parse(const std::string & param) } else if (std::string("--log-disable") == param) // NOLINT { - LOG_DISABLE(); + log_disable(); return true; } else if (std::string("--log-enable") == param) { - LOG_ENABLE(); + log_enable(); return true; } @@ -509,7 +517,7 @@ inline bool log_param_pair_parse(bool check_but_dont_parse, const std::string & { return true; } - LOG_SET_TARGET(LOG_FILENAME_GENERATOR(next.empty() ? "unnamed" : next, "log")); + log_set_target(log_filename_generator(next.empty() ? "unnamed" : next, "log")); return true; } @@ -530,27 +538,27 @@ inline void log_print_usage() fprintf(stdout, " Log file will be tagged with unique ID and written as \"..log\"\n"); /* */ } -#define LOG_DUMP_CMDLINE(argc, argv) _log_dump_cmdline(argc, argv) +#define log_dump_cmdline(argc, argv) _log_dump_cmdline(argc, argv) // INTERNAL, DO NOT USE inline void _log_dump_cmdline(int argc, char **argv) { - std::string buf; + std::stringstream buf; for (int i = 0; i < argc; ++i) { if (std::string(argv[i]).find(' ') != std::string::npos) { - buf.append(" \"").append(argv[i]).append("\""); + buf << " \"" << argv[i] <<"\""; } else { - buf.append(" ").append(argv[i]); + buf << " " << argv[i]; } } - LOGLN("Cmd:%s", buf.c_str()) + LOGLN("Cmd:%s", buf.str().c_str()) } -#define LOG_TOSTR(var) _log_var_to_string(var).c_str() +#define log_tostr(var) _log_var_to_string(var).c_str() inline std::string _log_var_to_string(bool var) { @@ -564,8 +572,8 @@ inline std::string _log_var_to_string(std::string var) inline std::string _log_var_to_string(const std::vector & var) { - std::string buf; - buf.append("[ "); + std::stringstream buf; + buf << "[ "; bool first = true; for (auto e : var) { @@ -575,24 +583,26 @@ inline std::string _log_var_to_string(const std::vector & var) } else { - buf.append(", "); + buf << ", "; } - buf.append(std::to_string(e)); + buf << std::to_string(e); } - buf.append(" ]"); + buf << " ]"; - return buf; + return buf.str(); } #define LOG_TOKENS_TOSTR_PRETTY(ctx, tokens) \ [&tokens, &ctx]() \ { \ - std::string buf("[ "); \ + std::stringstream buf; \ + buf << "[ "; \ + \ bool first = true; \ for (const auto &token : tokens) \ { \ if (!first) \ - buf.append(", "); \ + buf << ", "; \ else \ first = false; \ \ @@ -606,13 +616,12 @@ inline std::string _log_var_to_string(const std::vector & var) detokenized.end()); \ \ buf \ - .append("'") \ - .append(detokenized) \ - .append("'") \ - .append(":") \ - .append(std::to_string(token)); \ + << "'" << detokenized << "'" \ + << ":" << std::to_string(token); \ } \ - return buf.append(" ]"); \ + buf << " ]"; \ + \ + return buf.str(); \ }() \ .c_str() diff --git a/examples/main/main.cpp b/examples/main/main.cpp index 436eeb7178cf5..7117db4b091f1 100644 --- a/examples/main/main.cpp +++ b/examples/main/main.cpp @@ -114,9 +114,9 @@ int main(int argc, char ** argv) { } #ifndef LOG_DISABLE_LOGS - LOG_SET_TARGET(LOG_FILENAME_GENERATOR("main", "log")); + log_set_target(log_filename_generator("main", "log")); LOG_TEE("Log start\n"); - LOG_DUMP_CMDLINE(argc,argv); + log_dump_cmdline(argc,argv); #endif // LOG_DISABLE_LOGS // TODO: Dump params ? @@ -266,7 +266,7 @@ int main(int argc, char ** argv) { embd_inp = session_tokens; } - LOG("prompt: \"%s\"\n", LOG_TOSTR(params.prompt)); + LOG("prompt: \"%s\"\n", log_tostr(params.prompt)); LOG("tokens: %s\n", LOG_TOKENS_TOSTR_PRETTY(ctx, embd_inp)); // Should not run without any tokens @@ -280,7 +280,7 @@ int main(int argc, char ** argv) { int guidance_offset = 0; int original_prompt_len = 0; if (ctx_guidance) { - LOG("cfg_negative_prompt: \"%s\"\n", LOG_TOSTR(params.cfg_negative_prompt)); + LOG("cfg_negative_prompt: \"%s\"\n", log_tostr(params.cfg_negative_prompt)); guidance_inp = ::llama_tokenize(ctx_guidance, params.cfg_negative_prompt, add_bos); LOG("guidance_inp tokenized: %s\n", LOG_TOKENS_TOSTR_PRETTY(ctx_guidance, guidance_inp)); @@ -290,8 +290,8 @@ int main(int argc, char ** argv) { original_prompt_len = original_inp.size(); guidance_offset = (int)guidance_inp.size() - original_prompt_len; - LOG("original_prompt_len: %s", LOG_TOSTR(original_prompt_len)); - LOG("guidance_offset: %s", LOG_TOSTR(guidance_offset)); + LOG("original_prompt_len: %s", log_tostr(original_prompt_len)); + LOG("guidance_offset: %s", log_tostr(guidance_offset)); } const int n_ctx = llama_n_ctx(ctx); @@ -326,7 +326,7 @@ 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()); + 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 From ba5590f44bd981f143fdf63bcf9faebb4c42c11c Mon Sep 17 00:00:00 2001 From: staviq Date: Tue, 29 Aug 2023 17:44:54 +0200 Subject: [PATCH 23/27] review: simplify ifs and str comparisons --- common/log.h | 24 +++++++----------------- 1 file changed, 7 insertions(+), 17 deletions(-) diff --git a/common/log.h b/common/log.h index 9f45a1f37a7c9..b5cc47cfbbb63 100644 --- a/common/log.h +++ b/common/log.h @@ -337,12 +337,7 @@ inline FILE *_log_handler1(bool change = false, LogTriState disable = LogTriStat // Otherwise, process the arguments else { - if (log_current_filename != filename) - { - _initialized = false; - } - - if (log_current_target != target) + if (log_current_filename != filename || log_current_target != target) { _initialized = false; } @@ -384,14 +379,9 @@ inline FILE *_log_handler1(bool change = false, LogTriState disable = LogTriStat { fclose(logfile); } - - logfile = nullptr; - logfile = fopen(filename.c_str(), "w"); - } - else - { - logfile = fopen(filename.c_str(), "w"); } + + logfile = fopen(filename.c_str(), "w"); } if (!logfile) @@ -490,17 +480,17 @@ inline void log_test() inline bool log_param_single_parse(const std::string & param) { - if (std::string("--log-test") == param) + if ( param == "--log-test") { log_test(); return true; } - else if (std::string("--log-disable") == param) // NOLINT + else if ( param == "--log-disable") // NOLINT { log_disable(); return true; } - else if (std::string("--log-enable") == param) + else if ( param == "--log-enable") { log_enable(); return true; @@ -511,7 +501,7 @@ inline bool log_param_single_parse(const std::string & param) inline bool log_param_pair_parse(bool check_but_dont_parse, const std::string & param, const std::string & next = std::string()) { - if (std::string("--log-file") == param) + if ( param == "--log-file") { if (check_but_dont_parse) { From 3edee3fa932615f481ada3a73aac0d53973c2c33 Mon Sep 17 00:00:00 2001 From: staviq Date: Tue, 29 Aug 2023 19:20:16 +0200 Subject: [PATCH 24/27] fix MSVC, formatting, FMT/VAL placeholders --- common/log.h | 162 +++++++++++++++++++++++++-------------------------- 1 file changed, 81 insertions(+), 81 deletions(-) diff --git a/common/log.h b/common/log.h index b5cc47cfbbb63..2f21552ea1902 100644 --- a/common/log.h +++ b/common/log.h @@ -135,7 +135,7 @@ inline std::string _log_filename_generator(const std::string & log_file_basename } #ifndef LOG_DEFAULT_FILE_NAME -/**/#define LOG_DEFAULT_FILE_NAME log_filename_generator("llama", "log") + #define LOG_DEFAULT_FILE_NAME log_filename_generator("llama", "log") #endif // Utility for turning #define values into string literals @@ -154,29 +154,29 @@ inline std::string _log_filename_generator(const std::string & log_file_basename // #include "log.h" // #ifndef LOG_NO_TIMESTAMPS -/**/#ifndef _WIN32 -/* */#define LOG_TIMESTAMP_FMT "[%" PRIu64 "] " -/* */#define LOG_TIMESTAMP_VAL , (std::chrono::duration_cast>(std::chrono::system_clock::now().time_since_epoch())).count() -/**/#else -/* */#define LOG_TIMESTAMP_FMT "[%" PRIu64 "] " -/* */#define LOG_TIMESTAMP_VAL , (std::chrono::duration_cast>(std::chrono::system_clock::now().time_since_epoch())).count() -/**/#endif + #ifndef _WIN32 + #define LOG_TIMESTAMP_FMT "[%" PRIu64 "] " + #define LOG_TIMESTAMP_VAL , (std::chrono::duration_cast>(std::chrono::system_clock::now().time_since_epoch())).count() + #else + #define LOG_TIMESTAMP_FMT "[%" PRIu64 "] " + #define LOG_TIMESTAMP_VAL , (std::chrono::duration_cast>(std::chrono::system_clock::now().time_since_epoch())).count() + #endif #else -/**/#define LOG_TIMESTAMP_FMT -/**/#define LOG_TIMESTAMP_VAL + #define LOG_TIMESTAMP_FMT "%s" + #define LOG_TIMESTAMP_VAL ,"" #endif #ifdef LOG_TEE_TIMESTAMPS -/**/#ifndef _WIN32 -/* */#define LOG_TEE_TIMESTAMP_FMT "[%" PRIu64 "] " -/* */#define LOG_TEE_TIMESTAMP_VAL , (std::chrono::duration_cast>(std::chrono::system_clock::now().time_since_epoch())).count() -/**/#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() -/**/#endif + #ifndef _WIN32 + #define LOG_TEE_TIMESTAMP_FMT "[%" PRIu64 "] " + #define LOG_TEE_TIMESTAMP_VAL , (std::chrono::duration_cast>(std::chrono::system_clock::now().time_since_epoch())).count() + #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() + #endif #else -/**/#define LOG_TEE_TIMESTAMP_FMT -/**/#define LOG_TEE_TIMESTAMP_VAL + #define LOG_TEE_TIMESTAMP_FMT "%s" + #define LOG_TEE_TIMESTAMP_VAL ,"" #endif // Allows disabling file/line/function prefix @@ -187,29 +187,29 @@ inline std::string _log_filename_generator(const std::string & log_file_basename // #include "log.h" // #ifndef LOG_NO_FILE_LINE_FUNCTION -/**/#ifndef _WIN32 -/* */#define LOG_FLF_FMT "[%24s:%5d][%24s] " -/* */#define LOG_FLF_VAL , __FILE__, __LINE__, __FUNCTION__ -/**/#else -/* */#define LOG_FLF_FMT "[%24s:%5ld][%24s] " -/* */#define LOG_FLF_VAL , __FILE__, __LINE__, __FUNCTION__ -/**/#endif + #ifndef _WIN32 + #define LOG_FLF_FMT "[%24s:%5d][%24s] " + #define LOG_FLF_VAL , __FILE__, __LINE__, __FUNCTION__ + #else + #define LOG_FLF_FMT "[%24s:%5ld][%24s] " + #define LOG_FLF_VAL , __FILE__, __LINE__, __FUNCTION__ + #endif #else -/**/#define LOG_FLF_FMT -/**/#define LOG_FLF_VAL + #define LOG_FLF_FMT "%s" + #define LOG_FLF_VAL ,"" #endif #ifdef LOG_TEE_FILE_LINE_FUNCTION -/**/#ifndef _WIN32 -/* */#define LOG_TEE_FLF_FMT "[%24s:%5d][%24s] " -/* */#define LOG_TEE_FLF_VAL , __FILE__, __LINE__, __FUNCTION__ -/**/#else -/* */#define LOG_TEE_FLF_FMT "[%24s:%5ld][%24s] " -/* */#define LOG_TEE_FLF_VAL , __FILE__, __LINE__, __FUNCTION__ -/**/#endif + #ifndef _WIN32 + #define LOG_TEE_FLF_FMT "[%24s:%5d][%24s] " + #define LOG_TEE_FLF_VAL , __FILE__, __LINE__, __FUNCTION__ + #else + #define LOG_TEE_FLF_FMT "[%24s:%5ld][%24s] " + #define LOG_TEE_FLF_VAL , __FILE__, __LINE__, __FUNCTION__ + #endif #else -/**/#define LOG_TEE_FLF_FMT -/**/#define LOG_TEE_FLF_VAL + #define LOG_TEE_FLF_FMT "%s" + #define LOG_TEE_FLF_VAL ,"" #endif // Utility for synchronizing log configuration state @@ -225,7 +225,7 @@ enum LogTriState // USE LOG() INSTEAD // #ifndef _WIN32 -/**/#define _LOG(str, ...) \ + #define _LOG(str, ...) \ { \ if (LOG_TARGET != nullptr) \ { \ @@ -234,7 +234,7 @@ enum LogTriState } \ } #else -/**/#define _LOG(str, ...) \ + #define _LOG(str, ...) \ { \ if (LOG_TARGET != nullptr) \ { \ @@ -248,7 +248,7 @@ enum LogTriState // USE LOG_TEE() INSTEAD // #ifndef _WIN32 -/**/#define _LOG_TEE(str, ...) \ + #define _LOG_TEE(str, ...) \ { \ if (LOG_TARGET != nullptr) \ { \ @@ -262,7 +262,7 @@ enum LogTriState } \ } #else -/**/#define _LOG_TEE(str, ...) \ + #define _LOG_TEE(str, ...) \ { \ if (LOG_TARGET != nullptr) \ { \ @@ -285,9 +285,9 @@ enum LogTriState // behaves like printf, and supports arguments the exact same way. // #ifndef _WIN32 -/**/#define LOG(...) _LOG(__VA_ARGS__, "") + #define LOG(...) _LOG(__VA_ARGS__, "") #else -/**/#define LOG(str, ...) _LOG("%s" str, "", __VA_ARGS__, "") + #define LOG(str, ...) _LOG("%s" str, "", __VA_ARGS__, "") #endif // Main TEE macro. @@ -299,18 +299,18 @@ enum LogTriState // by defining LOG_TEE_TARGET // #ifndef _WIN32 -/**/#define LOG_TEE(...) _LOG_TEE(__VA_ARGS__, "") + #define LOG_TEE(...) _LOG_TEE(__VA_ARGS__, "") #else -/**/#define LOG_TEE(str, ...) _LOG_TEE("%s" str, "", __VA_ARGS__, "") + #define LOG_TEE(str, ...) _LOG_TEE("%s" str, "", __VA_ARGS__, "") #endif // LOG macro variants with auto endline. #ifndef _WIN32 -/**/#define LOGLN(...) _LOG(__VA_ARGS__, "\n") -/**/#define LOG_TEELN(...) _LOG_TEE(__VA_ARGS__, "\n") + #define LOGLN(...) _LOG(__VA_ARGS__, "\n") + #define LOG_TEELN(...) _LOG_TEE(__VA_ARGS__, "\n") #else -/**/#define LOGLN(str, ...) _LOG("%s" str, "", __VA_ARGS__, "\n") -/**/#define LOG_TEELN(str, ...) _LOG_TEE("%s" str, "", __VA_ARGS__, "\n") + #define LOGLN(str, ...) _LOG("%s" str, "", __VA_ARGS__, "\n") + #define LOG_TEELN(str, ...) _LOG_TEE("%s" str, "", __VA_ARGS__, "\n") #endif // INTERNAL, DO NOT USE @@ -380,7 +380,7 @@ inline FILE *_log_handler1(bool change = false, LogTriState disable = LogTriStat fclose(logfile); } } - + logfile = fopen(filename.c_str(), "w"); } @@ -582,37 +582,37 @@ inline std::string _log_var_to_string(const std::vector & var) return buf.str(); } -#define LOG_TOKENS_TOSTR_PRETTY(ctx, tokens) \ - [&tokens, &ctx]() \ - { \ - std::stringstream buf; \ - buf << "[ "; \ - \ - bool first = true; \ - for (const auto &token : tokens) \ - { \ - if (!first) \ - buf << ", "; \ - else \ - first = false; \ - \ - auto detokenized = llama_token_to_piece(ctx, token); \ - \ - detokenized.erase( \ - std::remove_if( \ - detokenized.begin(), \ - detokenized.end(), \ - [](const char c) { return !std::isprint(c); }), \ - detokenized.end()); \ - \ - buf \ - << "'" << detokenized << "'" \ - << ":" << std::to_string(token); \ - } \ - buf << " ]"; \ - \ - return buf.str(); \ - }() \ +#define LOG_TOKENS_TOSTR_PRETTY(ctx, tokens) \ + [&tokens, &ctx]() \ + { \ + std::stringstream buf; \ + buf << "[ "; \ + \ + bool first = true; \ + for (const auto &token : tokens) \ + { \ + if (!first) \ + buf << ", "; \ + else \ + first = false; \ + \ + auto detokenized = llama_token_to_piece(ctx, token); \ + \ + detokenized.erase( \ + std::remove_if( \ + detokenized.begin(), \ + detokenized.end(), \ + [](const unsigned char c) { return !std::isprint(c); }), \ + detokenized.end()); \ + \ + buf \ + << "'" << detokenized << "'" \ + << ":" << std::to_string(token); \ + } \ + buf << " ]"; \ + \ + return buf.str(); \ + }() \ .c_str() #ifdef LOG_DISABLE_LOGS From 6fa208e15727ffaa5ec3a6e3dffd48a2bf2926b7 Mon Sep 17 00:00:00 2001 From: staviq Date: Tue, 29 Aug 2023 22:13:03 +0200 Subject: [PATCH 25/27] review: if/else cleanup --- common/log.h | 27 ++++++++++++--------------- 1 file changed, 12 insertions(+), 15 deletions(-) diff --git a/common/log.h b/common/log.h index 2f21552ea1902..37b11fe688748 100644 --- a/common/log.h +++ b/common/log.h @@ -335,12 +335,9 @@ inline FILE *_log_handler1(bool change = false, LogTriState disable = LogTriStat _disabled = false; } // Otherwise, process the arguments - else + else if (log_current_filename != filename || log_current_target != target) { - if (log_current_filename != filename || log_current_target != target) - { - _initialized = false; - } + _initialized = false; } } @@ -351,11 +348,9 @@ inline FILE *_log_handler1(bool change = false, LogTriState disable = LogTriStat // Log is disabled return nullptr; } - else // NOLINT - { - // with fallback in case something went wrong - return logfile ? logfile : stderr; - } + + // with fallback in case something went wrong + return logfile ? logfile : stderr; } else { @@ -485,12 +480,14 @@ inline bool log_param_single_parse(const std::string & param) log_test(); return true; } - else if ( param == "--log-disable") // NOLINT + + if ( param == "--log-disable") { log_disable(); return true; } - else if ( param == "--log-enable") + + if ( param == "--log-enable") { log_enable(); return true; @@ -503,11 +500,11 @@ inline bool log_param_pair_parse(bool check_but_dont_parse, const std::string & { if ( param == "--log-file") { - if (check_but_dont_parse) + if (!check_but_dont_parse) { - return true; + log_set_target(log_filename_generator(next.empty() ? "unnamed" : next, "log")); } - log_set_target(log_filename_generator(next.empty() ? "unnamed" : next, "log")); + return true; } From f60f7d3640c04804e7aede4add1a729f5aa41f45 Mon Sep 17 00:00:00 2001 From: staviq Date: Tue, 29 Aug 2023 22:36:47 +0200 Subject: [PATCH 26/27] review: if/else cleanup (2) --- common/log.h | 54 ++++++++++++++++++++++++++-------------------------- 1 file changed, 27 insertions(+), 27 deletions(-) diff --git a/common/log.h b/common/log.h index 37b11fe688748..d19320727535e 100644 --- a/common/log.h +++ b/common/log.h @@ -352,47 +352,47 @@ inline FILE *_log_handler1(bool change = false, LogTriState disable = LogTriStat // with fallback in case something went wrong return logfile ? logfile : stderr; } + + // do the (re)initialization + if (target != nullptr) + { + if (logfile != nullptr && logfile != stdout && logfile != stderr) + { + fclose(logfile); + } + + log_current_filename = LOG_DEFAULT_FILE_NAME; + log_current_target = target; + + logfile = target; + } else { - if (target != nullptr) + if (log_current_filename != filename) { if (logfile != nullptr && logfile != stdout && logfile != stderr) { fclose(logfile); } - - log_current_filename = LOG_DEFAULT_FILE_NAME; - log_current_target = target; - - logfile = target; } - else - { - if (log_current_filename != filename) - { - if (logfile != nullptr && logfile != stdout && logfile != stderr) - { - fclose(logfile); - } - } - logfile = fopen(filename.c_str(), "w"); - } + logfile = fopen(filename.c_str(), "w"); + } - if (!logfile) - { - // Verify whether the file was opened, otherwise fallback to stderr - logfile = stderr; + if (!logfile) + { + // Verify whether the file was opened, otherwise fallback to stderr + logfile = stderr; - fprintf(stderr, "Failed to open logfile '%s' with error '%s'\n", filename.c_str(), std::strerror(errno)); - fflush(stderr); - } + fprintf(stderr, "Failed to open logfile '%s' with error '%s'\n", filename.c_str(), std::strerror(errno)); + fflush(stderr); - // At this point we set init flag to true, and let the target fallback to stderr + // At this point we let the init flag be to true below, and let the target fallback to stderr // otherwise we would repeatedly fopen() which was already unsuccessful - _initialized = true; } + _initialized = true; + return logfile ? logfile : stderr; } @@ -504,7 +504,7 @@ inline bool log_param_pair_parse(bool check_but_dont_parse, const std::string & { log_set_target(log_filename_generator(next.empty() ? "unnamed" : next, "log")); } - + return true; } From 89dc100653b0076200f88a6e78e0493f45f447ac Mon Sep 17 00:00:00 2001 From: staviq Date: Wed, 30 Aug 2023 00:05:48 +0200 Subject: [PATCH 27/27] replace _ prefix with _impl suffix --- common/log.h | 70 ++++++++++++++++++++++++++-------------------------- 1 file changed, 35 insertions(+), 35 deletions(-) diff --git a/common/log.h b/common/log.h index d19320727535e..c1364187d4cce 100644 --- a/common/log.h +++ b/common/log.h @@ -118,10 +118,10 @@ inline std::string log_get_pid() // 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(log_file_basename, log_file_extension) +#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(const std::string & log_file_basename, const std::string & log_file_extension) +inline std::string log_filename_generator_impl(const std::string & log_file_basename, const std::string & log_file_extension) { std::stringstream buf; @@ -141,8 +141,8 @@ inline std::string _log_filename_generator(const std::string & log_file_basename // Utility for turning #define values into string literals // so we can have a define for stderr and // we can print "stderr" instead of literal stderr, etc. -#define _LOG_STRINGIZE(s) #s -#define LOG_STRINGIZE(s) _LOG_STRINGIZE(s) +#define LOG_STRINGIZE1(s) #s +#define LOG_STRINGIZE(s) LOG_STRINGIZE1(s) #define LOG_TEE_TARGET_STRING LOG_STRINGIZE(LOG_TEE_TARGET) @@ -225,7 +225,7 @@ enum LogTriState // USE LOG() INSTEAD // #ifndef _WIN32 - #define _LOG(str, ...) \ + #define LOG_IMPL(str, ...) \ { \ if (LOG_TARGET != nullptr) \ { \ @@ -234,7 +234,7 @@ enum LogTriState } \ } #else - #define _LOG(str, ...) \ + #define LOG_IMPL(str, ...) \ { \ if (LOG_TARGET != nullptr) \ { \ @@ -248,7 +248,7 @@ enum LogTriState // USE LOG_TEE() INSTEAD // #ifndef _WIN32 - #define _LOG_TEE(str, ...) \ + #define LOG_TEE_IMPL(str, ...) \ { \ if (LOG_TARGET != nullptr) \ { \ @@ -262,7 +262,7 @@ enum LogTriState } \ } #else - #define _LOG_TEE(str, ...) \ + #define LOG_TEE_IMPL(str, ...) \ { \ if (LOG_TARGET != nullptr) \ { \ @@ -285,9 +285,9 @@ enum LogTriState // behaves like printf, and supports arguments the exact same way. // #ifndef _WIN32 - #define LOG(...) _LOG(__VA_ARGS__, "") + #define LOG(...) LOG_IMPL(__VA_ARGS__, "") #else - #define LOG(str, ...) _LOG("%s" str, "", __VA_ARGS__, "") + #define LOG(str, ...) LOG_IMPL("%s" str, "", __VA_ARGS__, "") #endif // Main TEE macro. @@ -299,22 +299,22 @@ enum LogTriState // by defining LOG_TEE_TARGET // #ifndef _WIN32 - #define LOG_TEE(...) _LOG_TEE(__VA_ARGS__, "") + #define LOG_TEE(...) LOG_TEE_IMPL(__VA_ARGS__, "") #else - #define LOG_TEE(str, ...) _LOG_TEE("%s" str, "", __VA_ARGS__, "") + #define LOG_TEE(str, ...) LOG_TEE_IMPL("%s" str, "", __VA_ARGS__, "") #endif // LOG macro variants with auto endline. #ifndef _WIN32 - #define LOGLN(...) _LOG(__VA_ARGS__, "\n") - #define LOG_TEELN(...) _LOG_TEE(__VA_ARGS__, "\n") + #define LOGLN(...) LOG_IMPL(__VA_ARGS__, "\n") + #define LOG_TEELN(...) LOG_TEE_IMPL(__VA_ARGS__, "\n") #else - #define LOGLN(str, ...) _LOG("%s" str, "", __VA_ARGS__, "\n") - #define LOG_TEELN(str, ...) _LOG_TEE("%s" str, "", __VA_ARGS__, "\n") + #define LOGLN(str, ...) LOG_IMPL("%s" str, "", __VA_ARGS__, "\n") + #define LOG_TEELN(str, ...) LOG_TEE_IMPL("%s" str, "", __VA_ARGS__, "\n") #endif // INTERNAL, DO NOT USE -inline FILE *_log_handler1(bool change = false, LogTriState disable = LogTriStateSame, const std::string & filename = LOG_DEFAULT_FILE_NAME, FILE *target = nullptr) +inline FILE *log_handler1_impl(bool change = false, LogTriState disable = LogTriStateSame, const std::string & filename = LOG_DEFAULT_FILE_NAME, FILE *target = nullptr) { static bool _initialized{false}; static bool _disabled{(filename.empty() && target == nullptr)}; @@ -397,40 +397,40 @@ inline FILE *_log_handler1(bool change = false, LogTriState disable = LogTriStat } // INTERNAL, DO NOT USE -inline FILE *_log_handler2(bool change = false, LogTriState disable = LogTriStateSame, FILE *target = nullptr, const std::string & filename = LOG_DEFAULT_FILE_NAME) +inline FILE *log_handler2_impl(bool change = false, LogTriState disable = LogTriStateSame, FILE *target = nullptr, const std::string & filename = LOG_DEFAULT_FILE_NAME) { - return _log_handler1(change, disable, filename, target); + 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() +#define log_disable() log_disable_impl() // INTERNAL, DO NOT USE -inline FILE *_log_disable() +inline FILE *log_disable_impl() { - return _log_handler1(true, LogTriStateTrue); + return log_handler1_impl(true, LogTriStateTrue); } // Enables logs at runtime. -#define log_enable() _log_enable() +#define log_enable() log_enable_impl() // INTERNAL, DO NOT USE -inline FILE *_log_enable() +inline FILE *log_enable_impl() { - return _log_handler1(true, LogTriStateFalse); + 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(target) +#define log_set_target(target) log_set_target_impl(target) // INTERNAL, DO NOT USE -inline FILE *_log_set_target(const std::string & filename) { return _log_handler1(true, LogTriStateSame, filename); } -inline FILE *_log_set_target(FILE *target) { return _log_handler2(true, LogTriStateSame, target); } +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(); } +inline FILE *log_handler() { return log_handler1_impl(); } inline void log_test() { @@ -525,10 +525,10 @@ inline void log_print_usage() fprintf(stdout, " Log file will be tagged with unique ID and written as \"..log\"\n"); /* */ } -#define log_dump_cmdline(argc, argv) _log_dump_cmdline(argc, argv) +#define log_dump_cmdline(argc, argv) log_dump_cmdline_impl(argc, argv) // INTERNAL, DO NOT USE -inline void _log_dump_cmdline(int argc, char **argv) +inline void log_dump_cmdline_impl(int argc, char **argv) { std::stringstream buf; for (int i = 0; i < argc; ++i) @@ -545,19 +545,19 @@ inline void _log_dump_cmdline(int argc, char **argv) LOGLN("Cmd:%s", buf.str().c_str()) } -#define log_tostr(var) _log_var_to_string(var).c_str() +#define log_tostr(var) log_var_to_string_impl(var).c_str() -inline std::string _log_var_to_string(bool var) +inline std::string log_var_to_string_impl(bool var) { return var ? "true" : "false"; } -inline std::string _log_var_to_string(std::string var) +inline std::string log_var_to_string_impl(std::string var) { return var; } -inline std::string _log_var_to_string(const std::vector & var) +inline std::string log_var_to_string_impl(const std::vector & var) { std::stringstream buf; buf << "[ ";