From 983673266ea8161fc4662d7c653fdbcf4c114fbb Mon Sep 17 00:00:00 2001 From: mutouyun Date: Sun, 1 Jan 2023 16:26:55 +0800 Subject: [PATCH] upd: [imp] optimize log performance --- include/libimp/fmt_cpo.h | 4 +- include/libimp/log.h | 128 +++++++++++++++++++++++--------------- src/libimp/log.cpp | 32 ---------- test/imp/test_imp_log.cpp | 35 ++++++----- 4 files changed, 96 insertions(+), 103 deletions(-) diff --git a/include/libimp/fmt_cpo.h b/include/libimp/fmt_cpo.h index c3951b8..6352e81 100644 --- a/include/libimp/fmt_cpo.h +++ b/include/libimp/fmt_cpo.h @@ -39,9 +39,7 @@ public: bool append(std::string const &str) noexcept; }; -/** - * \brief Supports custom fmt_to methods for imp::fmt. - */ +/// \brief Supports custom fmt_to methods for imp::fmt. namespace detail { class fmt_to_t { diff --git a/include/libimp/log.h b/include/libimp/log.h index 73dc317..ac423f6 100644 --- a/include/libimp/log.h +++ b/include/libimp/log.h @@ -9,13 +9,15 @@ #include #include #include -#include +#include +#include #include "libimp/def.h" #include "libimp/detect_plat.h" #include "libimp/export.h" #include "libimp/enum_cast.h" #include "libimp/fmt.h" +#include "libimp/generic.h" LIBIMP_NAMESPACE_BEG_ namespace log { @@ -29,30 +31,69 @@ enum class level : std::int32_t { failed, }; +/// \struct template struct context +/// \brief Logging context. +/// \tparam ...T - a log records all parameter types passed +template struct context { log::level level; std::chrono::system_clock::time_point tp; char const *func; - std::string text; + std::tuple params; }; -LIBIMP_EXPORT std::string to_string(context &&) noexcept; -LIBIMP_EXPORT bool to_string(fmt_context &ctx, context &&) noexcept; - /// \brief Custom defined fmt_to method for imp::fmt -template -bool tag_invoke(decltype(::LIBIMP::fmt_to), fmt_context &ctx, context &&arg) noexcept { - return ::LIBIMP::log::to_string(ctx, std::move(arg)); +namespace detail { + +template +bool unfold_tuple_fmt_to(fmt_context &ctx, Tp const &tp, std::index_sequence, A &&...args) { + return fmt_to(ctx, std::forward(args)..., std::get(tp)...); } -} // namespace log +} // namespace detail -namespace detail_log { +template +bool context_to_string(fmt_context &f_ctx, context const &l_ctx) noexcept { + constexpr static char types[] = { + 'T', 'D', 'I', 'W', 'E', 'F', + }; + LIBIMP_TRY { + auto ms = std::chrono::time_point_cast(l_ctx.tp).time_since_epoch().count() % 1000; + return detail::unfold_tuple_fmt_to(f_ctx, l_ctx.params, std::index_sequence_for{}, + "[", types[enum_cast(l_ctx.level)], "]" + "[", l_ctx.tp, ".", spec("03")(ms), "]" + "[", l_ctx.func, "] "); + } LIBIMP_CATCH(...) { + return false; + } +} + +template +std::string context_to_string(context const &l_ctx) noexcept { + LIBIMP_TRY { + std::string log_txt; + fmt_context f_ctx(log_txt); + if (!context_to_string(f_ctx, l_ctx)) { + return {}; + } + f_ctx.finish(); + return log_txt; + } LIBIMP_CATCH(...) { + return {}; + } +} + +namespace detail { + +/// \brief Custom defined fmt_to method for imp::fmt +template +bool tag_invoke(decltype(::LIBIMP::fmt_to), fmt_context &f_ctx, context const &l_ctx) noexcept { + return ::LIBIMP::log::to_string(f_ctx, l_ctx); +} enum out_type : unsigned { out_none = 0x0, out_string = 0x1, - out_context = 0x2, }; template @@ -62,9 +103,6 @@ class has_fn_output { template ().output(log::level::trace, std::declval()))> static std::integral_constant check(U *u); - template ().output(std::declval()))> - static std::integral_constant check(U *u); - public: using type = decltype(check(static_cast(nullptr))); }; @@ -73,7 +111,7 @@ template constexpr out_type has_fn_output_v = has_fn_output::type::value; struct vtable_t { - void (*output)(void *, log::context &&); + void (*output)(void *, log::level, std::string &&); }; template @@ -81,27 +119,17 @@ class traits { template static auto make_fn_output() noexcept -> std::enable_if_t<(has_fn_output_v == out_none), decltype(vtable_t{}.output)> { - return [](void *, log::context &&) {}; + return [](void *, log::level, std::string &&) {}; } template static auto make_fn_output() noexcept -> std::enable_if_t<(has_fn_output_v == out_string), decltype(vtable_t{}.output)> { - return [](void *p, log::context &&ctx) { - auto lev = ctx.level; - auto str = to_string(std::move(ctx)); + return [](void *p, log::level lev, std::string &&str) { static_cast(p)->output(lev, std::move(str)); }; } - template - static auto make_fn_output() noexcept - -> std::enable_if_t<(has_fn_output_v == out_context), decltype(vtable_t{}.output)> { - return [](void *p, log::context &&ctx) { - static_cast(p)->output(std::move(ctx)); - }; - } - public: static auto make_vtable() noexcept { static vtable_t vt { make_fn_output() }; @@ -109,28 +137,35 @@ public: } }; -} // namespace detail_log +} // namespace detail -namespace log { - -class LIBIMP_EXPORT printer { +class printer { void *objp_ {nullptr}; - detail_log::vtable_t *vtable_ {nullptr}; + detail::vtable_t *vtable_ {nullptr}; public: printer() noexcept = default; template ::value>> + typename = is_not_match> printer(T &p) noexcept : objp_ (static_cast(&p)) - , vtable_(detail_log::traits::make_vtable()) {} + , vtable_(detail::traits::make_vtable()) {} - explicit operator bool() const noexcept; - void output(context) noexcept; + explicit operator bool() const noexcept { + return (objp_ != nullptr) && (vtable_ != nullptr); + } + + template + void output(context const &ctx) noexcept { + if (!*this) return; + LIBIMP_TRY { + vtable_->output(objp_, ctx.level, context_to_string(ctx)); + } LIBIMP_CATCH(...) {} + } }; +/// \class class LIBIMP_EXPORT std_t /// \brief Standard console output. class LIBIMP_EXPORT std_t { public: @@ -153,19 +188,10 @@ class grip { if (!printer_ || (enum_cast(l) < enum_cast(level_limit_))) { return *this; } - context ctx; - LIBIMP_TRY { - ctx = { - l, std::chrono::system_clock::now(), func_, - fmt(std::forward(args)...), - }; - } LIBIMP_CATCH(std::exception const &e) { - /// \remark [TBD] std::string constructor may throw an exception - ctx = { - level::failed, std::chrono::system_clock::now(), func_, e.what(), - }; - } - printer_.output(std::move(ctx)); + printer_.output(context { + l, std::chrono::system_clock::now(), func_, + std::forward_as_tuple(std::forward(args)...), + }); return *this; } @@ -186,4 +212,4 @@ public: } // namespace log LIBIMP_NAMESPACE_END_ -#define LIBIMP_LOG_(...) ::LIBIMP::log::grip log {__func__, __VA_ARGS__} \ No newline at end of file +#define LIBIMP_LOG_(...) ::LIBIMP::log::grip log(__func__,##__VA_ARGS__) \ No newline at end of file diff --git a/src/libimp/log.cpp b/src/libimp/log.cpp index 3b68705..de535bb 100644 --- a/src/libimp/log.cpp +++ b/src/libimp/log.cpp @@ -1,42 +1,10 @@ #include "libimp/log.h" -#include #include LIBIMP_NAMESPACE_BEG_ namespace log { -bool to_string(fmt_context &f_ctx, context &&l_ctx) noexcept { - constexpr static char types[] = { - 'T', 'D', 'I', 'W', 'E', 'F', - }; - LIBIMP_TRY { - auto ms = std::chrono::time_point_cast(l_ctx.tp).time_since_epoch().count() % 1000; - return fmt_to(f_ctx, "[", types[enum_cast(l_ctx.level)], "][", l_ctx.tp, ".", spec("03")(ms), "][", l_ctx.func, "] ", l_ctx.text); - } LIBIMP_CATCH(std::exception const &) { - return false; - } -} - -std::string to_string(context &&ctx) noexcept { - std::string log_txt; - fmt_context f_ctx(log_txt); - if (!to_string(f_ctx, std::move(ctx))) { - return {}; - } - f_ctx.finish(); - return log_txt; -} - -printer::operator bool() const noexcept { - return (objp_ != nullptr) && (vtable_ != nullptr); -} - -void printer::output(context ctx) noexcept { - if (!*this) return; - vtable_->output(objp_, std::move(ctx)); -} - std_t std_out; void std_t::output(log::level l, std::string &&s) noexcept { diff --git a/test/imp/test_imp_log.cpp b/test/imp/test_imp_log.cpp index c4852c0..631d661 100644 --- a/test/imp/test_imp_log.cpp +++ b/test/imp/test_imp_log.cpp @@ -1,23 +1,24 @@ #include +#include #include "gtest/gtest.h" #include "libimp/log.h" TEST(log, detail) { - EXPECT_EQ(imp::detail_log::has_fn_output_v, imp::detail_log::out_none); + EXPECT_EQ(imp::log::detail::has_fn_output_v, imp::log::detail::out_none); struct foo { int info(std::string); }; - EXPECT_EQ(imp::detail_log::has_fn_output_v, imp::detail_log::out_none); + EXPECT_EQ(imp::log::detail::has_fn_output_v, imp::log::detail::out_none); struct bar { int info(char const *); void output(imp::log::level, std::string &&); }; - EXPECT_EQ(imp::detail_log::has_fn_output_v, imp::detail_log::out_string); + EXPECT_EQ(imp::log::detail::has_fn_output_v, imp::log::detail::out_string); struct str { str(std::string const &); @@ -25,11 +26,11 @@ TEST(log, detail) { struct foo_bar { void output(imp::log::level, str); }; - EXPECT_EQ(imp::detail_log::has_fn_output_v, imp::detail_log::out_string); + EXPECT_EQ(imp::log::detail::has_fn_output_v, imp::log::detail::out_string); - auto vt_int = imp::detail_log::traits::make_vtable(); + auto vt_int = imp::log::detail::traits::make_vtable(); EXPECT_NE(vt_int, nullptr); - EXPECT_NO_THROW(vt_int->output(nullptr, imp::log::context{})); + EXPECT_NO_THROW(vt_int->output(nullptr, imp::log::level::error, "")); struct log { std::string what; @@ -37,13 +38,13 @@ TEST(log, detail) { if (l == imp::log::level::error) what += s + '\n'; } } ll; - auto vt_log = imp::detail_log::traits::make_vtable(); + auto vt_log = imp::log::detail::traits::make_vtable(); EXPECT_NE(vt_log, nullptr); - vt_log->output(&ll, imp::log::context{imp::log::level::info , std::chrono::system_clock::now(), __func__, "123"}); - vt_log->output(&ll, imp::log::context{imp::log::level::error, std::chrono::system_clock::now(), __func__, "321"}); - vt_log->output(&ll, imp::log::context{imp::log::level::info , std::chrono::system_clock::now(), __func__, "654"}); - vt_log->output(&ll, imp::log::context{imp::log::level::error, std::chrono::system_clock::now(), __func__, "456"}); + vt_log->output(&ll, imp::log::level::info, "123"); + vt_log->output(&ll, imp::log::level::info, "321"); + vt_log->output(&ll, imp::log::level::info, "654"); + vt_log->output(&ll, imp::log::level::info, "456"); std::cout << ll.what << "\n"; SUCCEED(); } @@ -60,15 +61,15 @@ TEST(log, log_printer) { } ll; imp::log::printer pt = ll; - pt.output({imp::log::level::info , std::chrono::system_clock::now(), __func__, "hello "}); - pt.output({imp::log::level::error, std::chrono::system_clock::now(), __func__, "failed: "}); - pt.output({imp::log::level::info , std::chrono::system_clock::now(), __func__, "log-pt"}); - pt.output({imp::log::level::error, std::chrono::system_clock::now(), __func__, "whatever"}); + pt.output(imp::log::context{imp::log::level::info , std::chrono::system_clock::now(), __func__, "hello "}); + pt.output(imp::log::context{imp::log::level::error, std::chrono::system_clock::now(), __func__, "failed: "}); + pt.output(imp::log::context{imp::log::level::info , std::chrono::system_clock::now(), __func__, "log-pt"}); + pt.output(imp::log::context{imp::log::level::error, std::chrono::system_clock::now(), __func__, "whatever"}); std::cout << ll.i << "\n"; std::cout << ll.e << "\n"; imp::log::printer ps = imp::log::std_out; - ps.output({imp::log::level::info, std::chrono::system_clock::now(), __func__, "hello world"}); + ps.output(imp::log::context{imp::log::level::info, std::chrono::system_clock::now(), __func__, "hello world"}); SUCCEED(); } @@ -82,4 +83,4 @@ TEST(log, gripper) { log.info("hello 2"); } SUCCEED(); -} \ No newline at end of file +}