From 89247b70e257e477611ea7247063b103e81cef32 Mon Sep 17 00:00:00 2001 From: zhao liwei Date: Wed, 8 Jul 2020 11:18:19 +0800 Subject: [PATCH] refactor: make simple logger decoupled from dsn_runtime (#530) --- include/dsn/tool-api/logging_provider.h | 5 +-- src/core/core/logging.cpp | 26 ++++++++++++- src/core/core/service_api_c.cpp | 51 ++++++++++++++++++++++++- src/core/tools/common/simple_logger.cpp | 49 ++++++------------------ 4 files changed, 87 insertions(+), 44 deletions(-) diff --git a/include/dsn/tool-api/logging_provider.h b/include/dsn/tool-api/logging_provider.h index f2a0a95f37..b203f64f1b 100644 --- a/include/dsn/tool-api/logging_provider.h +++ b/include/dsn/tool-api/logging_provider.h @@ -39,7 +39,6 @@ #include namespace dsn { - /*! @addtogroup tool-api-providers @{ @@ -87,6 +86,6 @@ class logging_provider static logging_provider *create_default_instance(); }; -/*@}*/ -// ----------------------- inline implementation --------------------------------------- +void set_log_prefixed_message_func(std::function func); +extern std::function log_prefixed_message_func; } // namespace dsn diff --git a/src/core/core/logging.cpp b/src/core/core/logging.cpp index 6a64b38085..a39d18d05d 100644 --- a/src/core/core/logging.cpp +++ b/src/core/core/logging.cpp @@ -39,13 +39,35 @@ DSN_DEFINE_string("core", DSN_DEFINE_bool("core", logging_flush_on_exit, true, "flush log when exit system"); +namespace dsn { +std::function log_prefixed_message_func = []() { + static thread_local std::string prefixed_message; + + static thread_local std::once_flag flag; + std::call_once(flag, [&]() { + prefixed_message.resize(23); + int tid = dsn::utils::get_current_tid(); + sprintf(const_cast(prefixed_message.c_str()), "unknown.io-thrd.%05d: ", tid); + }); + + return prefixed_message; +}; + +void set_log_prefixed_message_func(std::function func) +{ + log_prefixed_message_func = func; +} +} // namespace dsn + static void log_on_sys_exit(::dsn::sys_exit_type) { dsn::logging_provider *logger = dsn::logging_provider::instance(); logger->flush(); } -void dsn_log_init(const std::string &logging_factory_name, const std::string &dir_log) +void dsn_log_init(const std::string &logging_factory_name, + const std::string &dir_log, + std::function dsn_log_prefixed_message_func) { dsn_log_start_level = enum_from_string(FLAGS_logging_start_level, dsn_log_level_t::LOG_LEVEL_INVALID); @@ -92,6 +114,8 @@ void dsn_log_init(const std::string &logging_factory_name, const std::string &di dsn_log_set_start_level(start_level); return std::string("OK, current level is ") + enum_to_string(start_level); }); + + dsn::set_log_prefixed_message_func(dsn_log_prefixed_message_func); } DSN_API dsn_log_level_t dsn_log_get_start_level() { return dsn_log_start_level; } diff --git a/src/core/core/service_api_c.cpp b/src/core/core/service_api_c.cpp index 37fcb225be..4740c7c51f 100644 --- a/src/core/core/service_api_c.cpp +++ b/src/core/core/service_api_c.cpp @@ -32,6 +32,8 @@ #include #include #include +#include + #ifdef DSN_ENABLE_GPERF #include #endif @@ -275,7 +277,9 @@ tool_app *get_current_tool() { return dsn_all.tool.get(); } } // namespace tools } // namespace dsn -extern void dsn_log_init(const std::string &logging_factory_name, const std::string &dir_log); +extern void dsn_log_init(const std::string &logging_factory_name, + const std::string &dir_log, + std::function dsn_log_prefixed_message_func); extern void dsn_core_init(); inline void dsn_global_init() @@ -287,6 +291,49 @@ inline void dsn_global_init() dsn::service_engine::instance(); } +static std::string dsn_log_prefixed_message_func() +{ + std::string res; + res.resize(100); + char *prefixed_message = const_cast(res.c_str()); + + int tid = dsn::utils::get_current_tid(); + auto t = dsn::task::get_current_task_id(); + if (t) { + if (nullptr != dsn::task::get_current_worker2()) { + sprintf(prefixed_message, + "%6s.%7s%d.%016" PRIx64 ": ", + dsn::task::get_current_node_name(), + dsn::task::get_current_worker2()->pool_spec().name.c_str(), + dsn::task::get_current_worker2()->index(), + t); + } else { + sprintf(prefixed_message, + "%6s.%7s.%05d.%016" PRIx64 ": ", + dsn::task::get_current_node_name(), + "io-thrd", + tid, + t); + } + } else { + if (nullptr != dsn::task::get_current_worker2()) { + sprintf(prefixed_message, + "%6s.%7s%u: ", + dsn::task::get_current_node_name(), + dsn::task::get_current_worker2()->pool_spec().name.c_str(), + dsn::task::get_current_worker2()->index()); + } else { + sprintf(prefixed_message, + "%6s.%7s.%05d: ", + dsn::task::get_current_node_name(), + "io-thrd", + tid); + } + } + + return res; +} + bool run(const char *config_file, const char *config_arguments, bool sleep_after_init, @@ -386,7 +433,7 @@ bool run(const char *config_file, #endif // init logging - dsn_log_init(spec.logging_factory_name, spec.dir_log); + dsn_log_init(spec.logging_factory_name, spec.dir_log, dsn_log_prefixed_message_func); // prepare minimum necessary ::dsn::service_engine::instance().init_before_toollets(spec); diff --git a/src/core/tools/common/simple_logger.cpp b/src/core/tools/common/simple_logger.cpp index 9b1c77c0f3..20ff274a23 100644 --- a/src/core/tools/common/simple_logger.cpp +++ b/src/core/tools/common/simple_logger.cpp @@ -57,45 +57,18 @@ static void print_header(FILE *fp, dsn_log_level_t log_level) { static char s_level_char[] = "IDWEF"; - uint64_t ts = 0; - if (::dsn::tools::is_engine_ready()) - ts = dsn_now_ns(); - + uint64_t ts = dsn_now_ns(); char str[24]; - ::dsn::utils::time_ms_to_string(ts / 1000000, str); - - int tid = ::dsn::utils::get_current_tid(); - - fprintf(fp, "%c%s (%" PRIu64 " %04x) ", s_level_char[log_level], str, ts, tid); - - auto t = task::get_current_task_id(); - if (t) { - if (nullptr != task::get_current_worker2()) { - fprintf(fp, - "%6s.%7s%d.%016" PRIx64 ": ", - task::get_current_node_name(), - task::get_current_worker2()->pool_spec().name.c_str(), - task::get_current_worker2()->index(), - t); - } else { - fprintf(fp, - "%6s.%7s.%05d.%016" PRIx64 ": ", - task::get_current_node_name(), - "io-thrd", - tid, - t); - } - } else { - if (nullptr != task::get_current_worker2()) { - fprintf(fp, - "%6s.%7s%u: ", - task::get_current_node_name(), - task::get_current_worker2()->pool_spec().name.c_str(), - task::get_current_worker2()->index()); - } else { - fprintf(fp, "%6s.%7s.%05d: ", task::get_current_node_name(), "io-thrd", tid); - } - } + dsn::utils::time_ms_to_string(ts / 1000000, str); + + int tid = dsn::utils::get_current_tid(); + fprintf(fp, + "%c%s (%" PRIu64 " %04x) %s", + s_level_char[log_level], + str, + ts, + tid, + log_prefixed_message_func().c_str()); } screen_logger::screen_logger(bool short_header) : logging_provider("./")