This commit is contained in:
staviq 2023-08-26 02:57:50 +02:00
parent 9bace227c5
commit 0b367255c1
2 changed files with 125 additions and 78 deletions

View file

@ -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::duration<std::uint64_t>>(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::duration<std::uint64_t>>(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::duration<std::uint64_t>>(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::duration<std::uint64_t>>(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::duration<std::uint64_t>>(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::duration<std::uint64_t>>(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,10 +541,6 @@ inline void log_print_usage()
fprintf(stdout, " Log file will be tagged with unique ID and written as \"<name>.<ID>.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
@ -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<int> var)
}() \
.c_str()
#ifdef LOG_DISABLE_LOGS
#undef LOG

View file

@ -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);
}