diff --git a/src/elements/core.c b/src/elements/core.c index fe9bd349..d7fa2057 100644 --- a/src/elements/core.c +++ b/src/elements/core.c @@ -15416,6 +15416,9 @@ __dll_export #endif /* MDBX_BUILD_CONFIG */ , "MDBX_DEBUG=" STRINGIFY(MDBX_DEBUG) +#ifdef MDBX_LOGLEVEL_BUILD + " MDBX_LOGLEVEL_BUILD=" STRINGIFY(MDBX_LOGLEVEL_BUILD) +#endif /* MDBX_LOGLEVEL_BUILD */ " MDBX_WORDBITS=" STRINGIFY(MDBX_WORDBITS) " BYTE_ORDER=" #if __BYTE_ORDER__ == __ORDER_LITTLE_ENDIAN__ diff --git a/test/config.cc b/test/config.cc index 2bf5ee2e..deda27d9 100644 --- a/test/config.cc +++ b/test/config.cc @@ -314,7 +314,7 @@ const struct option_verb table_bits[] = { static void dump_verbs(const char *caption, size_t bits, const struct option_verb *verbs) { - log_info("%s: 0x%" PRIx64 " = ", caption, (uint64_t)bits); + log_verbose("%s: 0x%" PRIx64 " = ", caption, (uint64_t)bits); const char *comma = ""; while (verbs->mask && bits) { @@ -330,7 +330,7 @@ static void dump_verbs(const char *caption, size_t bits, } static void dump_duration(const char *caption, unsigned duration) { - log_info("%s: ", caption); + log_verbose("%s: ", caption); if (duration) { if (duration > 24 * 3600) logging::feed("%u_", duration / (24 * 3600)); @@ -347,84 +347,86 @@ void dump(const char *title) { logging::local_suffix indent(title); for (auto i = global::actors.begin(); i != global::actors.end(); ++i) { - log_info("#%u, testcase %s, space_id/table %u\n", i->actor_id, - testcase2str(i->testcase), i->space_id); + log_verbose("#%u, testcase %s, space_id/table %u\n", i->actor_id, + testcase2str(i->testcase), i->space_id); indent.push(); if (i->params.loglevel) { - log_info("log: level %u, %s\n", i->params.loglevel, - i->params.pathname_log.empty() ? "console" - : i->params.pathname_log.c_str()); + log_verbose("log: level %u, %s\n", i->params.loglevel, + i->params.pathname_log.empty() + ? "console" + : i->params.pathname_log.c_str()); } - log_info("database: %s, size %" PRIuPTR "[%" PRIiPTR "..%" PRIiPTR - ", %i %i, %i]\n", - i->params.pathname_db.c_str(), i->params.size_now, - i->params.size_lower, i->params.size_upper, - i->params.shrink_threshold, i->params.growth_step, - i->params.pagesize); + log_verbose("database: %s, size %" PRIuPTR "[%" PRIiPTR "..%" PRIiPTR + ", %i %i, %i]\n", + i->params.pathname_db.c_str(), i->params.size_now, + i->params.size_lower, i->params.size_upper, + i->params.shrink_threshold, i->params.growth_step, + i->params.pagesize); dump_verbs("mode", i->params.mode_flags, mode_bits); dump_verbs("table", i->params.table_flags, table_bits); if (i->params.test_nops) - log_info("iterations/records %u\n", i->params.test_nops); + log_verbose("iterations/records %u\n", i->params.test_nops); else dump_duration("duration", i->params.test_duration); if (i->params.nrepeat) - log_info("repeat %u\n", i->params.nrepeat); + log_verbose("repeat %u\n", i->params.nrepeat); else - log_info("repeat ETERNALLY\n"); + log_verbose("repeat ETERNALLY\n"); - log_info("threads %u\n", i->params.nthreads); + log_verbose("threads %u\n", i->params.nthreads); - log_info( + log_verbose( "keygen.params: case %s, width %u, mesh %u, rotate %u, offset %" PRIu64 ", split %u/%u\n", keygencase2str(i->params.keygen.keycase), i->params.keygen.width, i->params.keygen.mesh, i->params.keygen.rotate, i->params.keygen.offset, i->params.keygen.split, i->params.keygen.width - i->params.keygen.split); - log_info("keygen.seed: %u\n", i->params.keygen.seed); - log_info("key: minlen %u, maxlen %u\n", i->params.keylen_min, - i->params.keylen_max); - log_info("data: minlen %u, maxlen %u\n", i->params.datalen_min, - i->params.datalen_max); + log_verbose("keygen.seed: %u\n", i->params.keygen.seed); + log_verbose("key: minlen %u, maxlen %u\n", i->params.keylen_min, + i->params.keylen_max); + log_verbose("data: minlen %u, maxlen %u\n", i->params.datalen_min, + i->params.datalen_max); - log_info("batch: read %u, write %u\n", i->params.batch_read, - i->params.batch_write); + log_verbose("batch: read %u, write %u\n", i->params.batch_read, + i->params.batch_write); if (i->params.waitfor_nops) - log_info("wait: actor %u for %u ops\n", i->wait4id, - i->params.waitfor_nops); + log_verbose("wait: actor %u for %u ops\n", i->wait4id, + i->params.waitfor_nops); else if (i->params.delaystart) dump_duration("delay", i->params.delaystart); else - log_info("no-delay\n"); + log_verbose("no-delay\n"); if (i->params.inject_writefaultn) - log_info("inject-writefault on %u ops\n", i->params.inject_writefaultn); + log_verbose("inject-writefault on %u ops\n", + i->params.inject_writefaultn); else - log_info("no-inject-writefault\n"); + log_verbose("no-inject-writefault\n"); - log_info("limits: readers %u, tables %u\n", i->params.max_readers, - i->params.max_tables); + log_verbose("limits: readers %u, tables %u\n", i->params.max_readers, + i->params.max_tables); - log_info("drop table: %s\n", i->params.drop_table ? "Yes" : "No"); - log_info("ignore MDBX_MAP_FULL error: %s\n", - i->params.ignore_dbfull ? "Yes" : "No"); + log_verbose("drop table: %s\n", i->params.drop_table ? "Yes" : "No"); + log_verbose("ignore MDBX_MAP_FULL error: %s\n", + i->params.ignore_dbfull ? "Yes" : "No"); indent.pop(); } dump_duration("timeout", global::config::timeout_duration_seconds); - log_info("cleanup: before %s, after %s\n", - global::config::cleanup_before ? "Yes" : "No", - global::config::cleanup_after ? "Yes" : "No"); + log_verbose("cleanup: before %s, after %s\n", + global::config::cleanup_before ? "Yes" : "No", + global::config::cleanup_after ? "Yes" : "No"); - log_info("failfast: %s\n", global::config::failfast ? "Yes" : "No"); - log_info("progress indicator: %s\n", - global::config::progress_indicator ? "Yes" : "No"); + log_verbose("failfast: %s\n", global::config::failfast ? "Yes" : "No"); + log_verbose("progress indicator: %s\n", + global::config::progress_indicator ? "Yes" : "No"); } } /* namespace config */ diff --git a/test/log.cc b/test/log.cc index 4d7cb661..1f828300 100644 --- a/test/log.cc +++ b/test/log.cc @@ -20,7 +20,7 @@ void failure(const char *fmt, ...) { va_list ap; va_start(ap, fmt); fflushall(); - logging::output(logging::failure, fmt, ap); + logging::output_ap(logging::failure, fmt, ap); va_end(ap); fflushall(); exit(EXIT_FAILURE); @@ -37,17 +37,17 @@ void __noreturn failure_perror(const char *what, int errnum) { //----------------------------------------------------------------------------- -static void mdbx_logger(int loglevel, const char *function, int line, +static void mdbx_logger(int priority, const char *function, int line, const char *msg, va_list args) { if (!function) function = "unknown"; - if (loglevel == MDBX_LOG_FATAL) + if (priority == MDBX_LOG_FATAL) log_error("mdbx: fatal failure: %s, %d", function, line); if (logging::output( - logging::loglevel(loglevel), - strncmp(function, "mdbx_", 5) == 0 ? "%s: " : "mdbx: %s: ", function)) + logging::loglevel(priority), + strncmp(function, "mdbx_", 5) == 0 ? "%s: " : "mdbx %s: ", function)) logging::feed_ap(msg, args); } @@ -58,14 +58,15 @@ static std::string suffix; static loglevel level; static FILE *last; -void setlevel(loglevel _level) { +void setlevel(loglevel priority) { + level = priority; int rc = mdbx_setup_debug( - _level, MDBX_DBG_ASSERT | MDBX_DBG_JITTER | MDBX_DBG_DUMP, mdbx_logger); + priority, MDBX_DBG_ASSERT | MDBX_DBG_JITTER | MDBX_DBG_DUMP, mdbx_logger); log_trace("set mdbx debug-opts: 0x%02x", rc); } -void setup(loglevel _level, const std::string &_prefix) { - setlevel(_level); +void setup(loglevel priority, const std::string &_prefix) { + setlevel(priority); prefix = _prefix; } @@ -81,8 +82,8 @@ const char *level2str(const loglevel alevel) { return "trace"; case debug: return "debug"; - case info: - return "info"; + case verbose: + return "verbose"; case notice: return "notice"; case warning: @@ -95,24 +96,29 @@ const char *level2str(const loglevel alevel) { } bool output(const loglevel priority, const char *format, ...) { - if (priority > level) + if (lower(priority, level)) return false; va_list ap; va_start(ap, format); - output(priority, format, ap); + output_ap(priority, format, ap); va_end(ap); return true; } -bool output(const logging::loglevel priority, const char *format, va_list ap) { +bool output_ap(const logging::loglevel priority, const char *format, + va_list ap) { if (last) { putc('\n', last); fflush(last); + if (last == stderr) { + putc('\n', stdout); + fflush(stdout); + } last = nullptr; } - if (priority < level) + if (lower(priority, level)) return false; chrono::time now = chrono::now_realtime(); @@ -135,7 +141,7 @@ bool output(const logging::loglevel priority, const char *format, va_list ap) { va_list ones; memset(&ones, 0, sizeof(ones)) /* zap MSVC and other stupid compilers */; - if (priority >= error) + if (same_or_higher(priority, error)) va_copy(ones, ap); vfprintf(last, format, ap); @@ -162,14 +168,15 @@ bool output(const logging::loglevel priority, const char *format, va_list ap) { break; } - if (priority >= error) { + if (same_or_higher(priority, error)) { if (last != stderr) { fprintf(stderr, "[ %05u %-10s %.4s ] %s", osal_getpid(), prefix.c_str(), level2str(priority), suffix.c_str()); vfprintf(stderr, format, ones); - if (end != '\n') - putc('\n', stderr); - fflush(stderr); + if (end == '\n') + fflush(stderr); + else + last = stderr; } va_end(ones); } @@ -181,10 +188,18 @@ bool feed_ap(const char *format, va_list ap) { if (!last) return false; + if (last == stderr) { + va_list ones; + va_copy(ones, ap); + vfprintf(stdout, format, ones); + va_end(ones); + } vfprintf(last, format, ap); size_t len = strlen(format); if (len && format[len - 1] == '\n') { fflush(last); + if (last == stderr) + fflush(stdout); last = nullptr; } return true; @@ -229,70 +244,70 @@ local_suffix::~local_suffix() { suffix.erase(trim_pos); } } // namespace logging void log_extra(const char *msg, ...) { - if (logging::extra <= logging::level) { + if (logging::same_or_higher(logging::extra, logging::level)) { va_list ap; va_start(ap, msg); - logging::output(logging::extra, msg, ap); + logging::output_ap(logging::extra, msg, ap); va_end(ap); } else logging::last = nullptr; } void log_trace(const char *msg, ...) { - if (logging::trace <= logging::level) { + if (logging::same_or_higher(logging::trace, logging::level)) { va_list ap; va_start(ap, msg); - logging::output(logging::trace, msg, ap); + logging::output_ap(logging::trace, msg, ap); va_end(ap); } else logging::last = nullptr; } void log_debug(const char *msg, ...) { - if (logging::debug <= logging::level) { + if (logging::same_or_higher(logging::debug, logging::level)) { va_list ap; va_start(ap, msg); - logging::output(logging::debug, msg, ap); + logging::output_ap(logging::debug, msg, ap); va_end(ap); } else logging::last = nullptr; } -void log_info(const char *msg, ...) { - if (logging::info <= logging::level) { +void log_verbose(const char *msg, ...) { + if (logging::same_or_higher(logging::verbose, logging::level)) { va_list ap; va_start(ap, msg); - logging::output(logging::info, msg, ap); + logging::output_ap(logging::verbose, msg, ap); va_end(ap); } else logging::last = nullptr; } void log_notice(const char *msg, ...) { - if (logging::notice <= logging::level) { + if (logging::same_or_higher(logging::notice, logging::level)) { va_list ap; va_start(ap, msg); - logging::output(logging::notice, msg, ap); + logging::output_ap(logging::notice, msg, ap); va_end(ap); } else logging::last = nullptr; } void log_warning(const char *msg, ...) { - if (logging::warning <= logging::level) { + if (logging::same_or_higher(logging::warning, logging::level)) { va_list ap; va_start(ap, msg); - logging::output(logging::warning, msg, ap); + logging::output_ap(logging::warning, msg, ap); va_end(ap); } else logging::last = nullptr; } void log_error(const char *msg, ...) { - if (logging::error <= logging::level) { + if (logging::same_or_higher(logging::error, logging::level)) { va_list ap; va_start(ap, msg); - logging::output(logging::error, msg, ap); + logging::output_ap(logging::error, msg, ap); va_end(ap); } else logging::last = nullptr; @@ -303,7 +318,7 @@ void log_trouble(const char *where, const char *what, int errnum) { } bool log_enabled(const logging::loglevel priority) { - return (priority >= logging::level); + return logging::same_or_higher(priority, logging::level); } void log_flush(void) { fflushall(); } diff --git a/test/log.h b/test/log.h index 4df145eb..8bdf9aa5 100644 --- a/test/log.h +++ b/test/log.h @@ -27,19 +27,28 @@ enum loglevel { extra = MDBX_LOG_EXTRA, trace = MDBX_LOG_TRACE, debug = MDBX_LOG_DEBUG, - info = MDBX_LOG_VERBOSE, + verbose = MDBX_LOG_VERBOSE, notice = MDBX_LOG_NOTICE, warning = MDBX_LOG_WARN, error = MDBX_LOG_ERROR, failure = MDBX_LOG_FATAL }; -const char *level2str(const loglevel level); -void setup(loglevel level, const std::string &prefix); -void setup(const std::string &prefix); -void setlevel(loglevel level); +inline bool lower(loglevel left, loglevel right) { + static_assert(MDBX_LOG_EXTRA > MDBX_LOG_FATAL, "WTF?"); + return left > right; +} -bool output(const loglevel priority, const char *format, va_list ap); +inline bool same_or_higher(loglevel left, loglevel right) { + return left <= right; +} + +const char *level2str(const loglevel level); +void setup(loglevel priority, const std::string &prefix); +void setup(const std::string &prefix); +void setlevel(loglevel priority); + +bool output_ap(const loglevel priority, const char *format, va_list ap); bool __printf_args(2, 3) output(const loglevel priority, const char *format, ...); bool feed_ap(const char *format, va_list ap); @@ -67,7 +76,7 @@ public: void __printf_args(1, 2) log_extra(const char *msg, ...); void __printf_args(1, 2) log_trace(const char *msg, ...); void __printf_args(1, 2) log_debug(const char *msg, ...); -void __printf_args(1, 2) log_info(const char *msg, ...); +void __printf_args(1, 2) log_verbose(const char *msg, ...); void __printf_args(1, 2) log_notice(const char *msg, ...); void __printf_args(1, 2) log_warning(const char *msg, ...); void __printf_args(1, 2) log_error(const char *msg, ...); diff --git a/test/main.cc b/test/main.cc index 6b369ecd..6aa72754 100644 --- a/test/main.cc +++ b/test/main.cc @@ -26,7 +26,7 @@ void actor_params::set_defaults(const std::string &tmpdir) { pathname_log = ""; loglevel = #ifdef NDEBUG - logging::info; + logging::verbose; #elif defined(_WIN32) || defined(_WIN64) logging::debug; #else @@ -456,8 +456,8 @@ int main(int argc, char *const argv[]) { if (!actor) continue; - log_info("actor #%u, id %d, pid %u: %s\n", actor->actor_id, - actor->space_id, pid, status2str(status)); + log_verbose("actor #%u, id %d, pid %u: %s\n", actor->actor_id, + actor->space_id, pid, status2str(status)); if (status > as_running) { left -= 1; if (status != as_successful) { @@ -480,7 +480,7 @@ int main(int argc, char *const argv[]) { log_notice("RESULT: %s\n", failed ? "Failed" : "Successful"); if (global::config::cleanup_before) { if (failed) - log_info("skip cleanup"); + log_verbose("skip cleanup"); else cleanup(); } diff --git a/test/test.cc b/test/test.cc index 7db63d08..8ac8521c 100644 --- a/test/test.cc +++ b/test/test.cc @@ -265,8 +265,9 @@ void testcase::txn_inject_writefault(MDBX_txn *txn) { if (config.params.inject_writefaultn && txn) { if (config.params.inject_writefaultn <= nops_completed && (mdbx_txn_flags(txn) & MDBX_RDONLY) == 0) { - log_info("== txn_inject_writefault(): got %u nops or more, inject FAULT", - config.params.inject_writefaultn); + log_verbose( + "== txn_inject_writefault(): got %u nops or more, inject FAULT", + config.params.inject_writefaultn); log_flush(); #if defined(_WIN32) || defined(_WIN64) || defined(_WINDOWS) TerminateProcess(GetCurrentProcess(), 42); @@ -583,13 +584,13 @@ bool test_execute(const actor_config &config_const) { } if (config.params.nrepeat == 1) - log_info("test successed"); + log_verbose("test successed"); else { if (config.params.nrepeat) - log_info("test successed (iteration %zi of %zi)", iter, - size_t(config.params.nrepeat)); + log_verbose("test successed (iteration %zi of %zi)", iter, + size_t(config.params.nrepeat)); else - log_info("test successed (iteration %zi)", iter); + log_verbose("test successed (iteration %zi)", iter); config.params.keygen.seed += INT32_C(0xA4F4D37B); } diff --git a/test/ttl.cc b/test/ttl.cc index aad24467..e5631045 100644 --- a/test/ttl.cc +++ b/test/ttl.cc @@ -73,8 +73,8 @@ bool testcase_ttl::run() { const unsigned count_max = (config.params.batch_write > count_max_lower) ? config.params.batch_write : count_max_lower; - log_info("ttl: using `batch_read` value %u for window_max", window_max); - log_info("ttl: using `batch_write` value %u for count_max", count_max); + log_verbose("ttl: using `batch_read` value %u for window_max", window_max); + log_verbose("ttl: using `batch_write` value %u for count_max", count_max); uint64_t seed = prng64_map2_white(config.params.keygen.seed) + config.actor_id;