Skip to content

Commit 85be979

Browse files
committed
feat universal: optimize TSKV based formatters
Before: ``` Benchmark Time CPU Iterations ------------------------------------------------------------------- TskvFormatterConstructor 119 ns 118 ns 23614375 TskvFormatterAndTags 151 ns 151 ns 18966917 ``` With a single `fmt::format_to(char_ptr, ...)`: ``` ------------------------------------------------ Benchmark Time CPU Iterations ------------------------------------------------------------------- TskvFormatterConstructor 57.1 ns 57.1 ns 49465165 TskvFormatterAndTags 95.6 ns 95.6 ns 29809455 ``` With `Append`s: ``` ------------------------------------------------ Benchmark Time CPU Iterations ------------------------------------------------------------------- TskvFormatterConstructor 36.9 ns 36.9 ns 76092013 TskvFormatterAndTags 63.8 ns 63.8 ns 44395339 ``` `Tskv::Tskv` consumes 1.60% of overall CPU time on some services. This optimization reduces the time to about 0.5% Tests: протестировано CI commit_hash:ce42e415abe07c549118a8f6c71a347aa9466121
1 parent 9def123 commit 85be979

File tree

4 files changed

+68
-33
lines changed

4 files changed

+68
-33
lines changed

.mapping.json

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -5281,6 +5281,7 @@
52815281
"universal/src/logging/impl/formatters/struct.hpp":"taxi/uservices/userver/universal/src/logging/impl/formatters/struct.hpp",
52825282
"universal/src/logging/impl/formatters/tskv.cpp":"taxi/uservices/userver/universal/src/logging/impl/formatters/tskv.cpp",
52835283
"universal/src/logging/impl/formatters/tskv.hpp":"taxi/uservices/userver/universal/src/logging/impl/formatters/tskv.hpp",
5284+
"universal/src/logging/impl/formatters/tskv_benchmark.cpp":"taxi/uservices/userver/universal/src/logging/impl/formatters/tskv_benchmark.cpp",
52845285
"universal/src/logging/impl/log_extra_tskv_formatter.cpp":"taxi/uservices/userver/universal/src/logging/impl/log_extra_tskv_formatter.cpp",
52855286
"universal/src/logging/impl/logger_base.cpp":"taxi/uservices/userver/universal/src/logging/impl/logger_base.cpp",
52865287
"universal/src/logging/impl/mem_logger.cpp":"taxi/uservices/userver/universal/src/logging/impl/mem_logger.cpp",

universal/src/logging/impl/formatters/tskv.cpp

Lines changed: 36 additions & 32 deletions
Original file line numberDiff line numberDiff line change
@@ -1,7 +1,5 @@
11
#include <logging/impl/formatters/tskv.hpp>
22

3-
#include <iostream>
4-
53
#include <fmt/chrono.h>
64
#include <fmt/compile.h>
75
#include <fmt/format.h>
@@ -14,49 +12,55 @@
1412

1513
USERVER_NAMESPACE_BEGIN
1614

15+
namespace {
16+
17+
template <class... Args>
18+
char* Append(char* output, const Args&... args) {
19+
const auto append_impl = [&output](std::string_view data) noexcept {
20+
std::memcpy(output, data.data(), data.size());
21+
output += data.size();
22+
};
23+
(append_impl(args), ...);
24+
return output;
25+
};
26+
27+
} // namespace
28+
1729
namespace logging::impl::formatters {
1830

1931
Tskv::Tskv(Level level, Format format, const utils::impl::SourceLocation& location) : format_(format) {
2032
switch (format) {
2133
case Format::kTskv: {
22-
constexpr std::string_view kTemplate = "tskv\ttimestamp=0000-00-00T00:00:00.000000\tlevel=";
34+
constexpr std::string_view kTemplate = "tskv\ttimestamp=0000-00-00T00:00:00.000000\tlevel=\tmodule= ( : )";
2335
const auto now = std::chrono::system_clock::now();
2436
const auto level_string = logging::ToUpperCaseString(level);
25-
item_.log_line.resize(kTemplate.size() + level_string.size());
26-
fmt::format_to(
27-
item_.log_line.data(),
28-
FMT_COMPILE("tskv\ttimestamp={}.{:06}\tlevel={}"),
29-
GetCurrentLocalTimeString(now).ToStringView(),
30-
FractionalMicroseconds(now),
31-
level_string
32-
);
33-
fmt::format_to(
34-
std::back_inserter(item_.log_line),
35-
FMT_COMPILE("\tmodule={} ( {}:{} )"),
36-
location.GetFunctionName(),
37-
location.GetFileName(),
38-
location.GetLineString()
37+
item_.log_line.resize_and_overwrite(
38+
kTemplate.size() + level_string.size() + location.GetFunctionName().size() +
39+
location.GetFileName().size() + location.GetLineString().size(),
40+
[&](char* output, std::size_t size) {
41+
output = Append(output, "tskv\ttimestamp=", GetCurrentLocalTimeString(now).ToStringView(), ".");
42+
output = fmt::format_to(output, FMT_COMPILE("{:06}"), FractionalMicroseconds(now));
43+
output = Append(output, "\tlevel=", level_string, "\tmodule=", location.GetFunctionName());
44+
output = Append(output, " ( ", location.GetFileName(), ":", location.GetLineString(), " )");
45+
return size;
46+
}
3947
);
4048
return;
4149
}
4250
case Format::kLtsv: {
43-
constexpr std::string_view kTemplate = "timestamp:0000-00-00T00:00:00.000000\tlevel:";
51+
constexpr std::string_view kTemplate = "timestamp:0000-00-00T00:00:00.000000\tlevel:\tmodule: ( : )";
4452
const auto now = TimePoint::clock::now();
4553
const auto level_string = logging::ToUpperCaseString(level);
46-
item_.log_line.resize(kTemplate.size() + level_string.size());
47-
fmt::format_to(
48-
item_.log_line.data(),
49-
FMT_COMPILE("timestamp:{}.{:06}\tlevel:{}"),
50-
GetCurrentLocalTimeString(now).ToStringView(),
51-
FractionalMicroseconds(now),
52-
level_string
53-
);
54-
fmt::format_to(
55-
std::back_inserter(item_.log_line),
56-
FMT_COMPILE("\tmodule:{} ( {}:{} )"),
57-
location.GetFunctionName(),
58-
location.GetFileName(),
59-
location.GetLineString()
54+
item_.log_line.resize_and_overwrite(
55+
kTemplate.size() + level_string.size() + location.GetFunctionName().size() +
56+
location.GetFileName().size() + location.GetLineString().size(),
57+
[&](char* output, std::size_t size) {
58+
output = Append(output, "timestamp:", GetCurrentLocalTimeString(now).ToStringView(), ".");
59+
output = fmt::format_to(output, FMT_COMPILE("{:06}"), FractionalMicroseconds(now));
60+
output = Append(output, "\tlevel:", level_string, "\tmodule:", location.GetFunctionName());
61+
output = Append(output, " ( ", location.GetFileName(), ":", location.GetLineString(), " )");
62+
return size;
63+
}
6064
);
6165
return;
6266
}
Lines changed: 30 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,30 @@
1+
#include <benchmark/benchmark.h>
2+
3+
#include <logging/impl/formatters/tskv.hpp>
4+
5+
USERVER_NAMESPACE_BEGIN
6+
7+
void TskvFormatterConstructor(benchmark::State& state) {
8+
for ([[maybe_unused]] auto _ : state) {
9+
logging::impl::formatters::Tskv formatter(
10+
logging::Level::kDebug, logging::Format::kTskv, utils::impl::SourceLocation::Current()
11+
);
12+
benchmark::DoNotOptimize(&formatter);
13+
}
14+
}
15+
BENCHMARK(TskvFormatterConstructor);
16+
17+
void TskvFormatterAndTags(benchmark::State& state) {
18+
for ([[maybe_unused]] auto _ : state) {
19+
logging::impl::formatters::Tskv formatter(
20+
logging::Level::kDebug, logging::Format::kTskv, utils::impl::SourceLocation::Current()
21+
);
22+
formatter.AddTag("key1", std::string_view{"some_value"});
23+
formatter.AddTag("key2", std::string_view{"some value2"});
24+
formatter.AddTag("key 3", std::string_view{"some value2"});
25+
benchmark::DoNotOptimize(&formatter);
26+
}
27+
}
28+
BENCHMARK(TskvFormatterAndTags);
29+
30+
USERVER_NAMESPACE_END

universal/src/logging/log_helper_impl.cpp

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -33,7 +33,7 @@ void LogHelper::Impl::AddTag(std::string_view key, const LogExtra::Value& value)
3333
void LogHelper::Impl::AddTag(std::string_view key, std::string_view value) { formatter_->AddTag(key, value); }
3434

3535
void LogHelper::Impl::Finish() {
36-
formatter_->SetText(to_string(msg_));
36+
formatter_->SetText(std::string_view{msg_.data(), msg_.size()});
3737

3838
auto& log_item = formatter_->ExtractLoggerItem();
3939
logger_.Log(level_, log_item);

0 commit comments

Comments
 (0)