Skip to content

Commit 7a389e6

Browse files
segoonsegoon
committed
feat logging: speed up module logging
commit_hash:c1b020643b82e3d622477c91c4b6ceba077b8195
1 parent e5c4f07 commit 7a389e6

File tree

24 files changed

+172
-76
lines changed

24 files changed

+172
-76
lines changed

‎core/src/logging/log_message_test.cpp

Lines changed: 47 additions & 15 deletions
Original file line numberDiff line numberDiff line change
@@ -94,6 +94,41 @@ TEST_F(LoggingTest, LogFormat) {
9494
<< "Path shortening for logs stopped working.";
9595
}
9696

97+
TEST_F(LoggingLtsvTest, LogFormatLtsv) {
98+
// Note: this is a golden test. The order and content of tags is stable, which
99+
// is an implementation detail, but it makes this test possible. If the order
100+
// or content of tags change, this test should be fixed to reflect the
101+
// changes.
102+
constexpr std::string_view kExpectedPattern = R"(timestamp:\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{6}\t)"
103+
R"(level:[A-Z]+\t)"
104+
R"(module:[-_\w\d ():./]+\t)"
105+
R"(task_id:[0-9A-F]+\t)"
106+
R"(thread_id:0x[0-9A-F]+\t)"
107+
R"(foo:bar\t)"
108+
R"(text:test\n)";
109+
LOG_CRITICAL() << "test" << logging::LogExtra{{"foo", "bar"}};
110+
logging::LogFlush();
111+
EXPECT_TRUE(utils::regex_match(GetStreamString(), utils::regex(kExpectedPattern))) << GetStreamString();
112+
}
113+
114+
TEST_F(LoggingRawTest, LogFormat) {
115+
// Note: this is a golden test. The order and content of tags is stable, which
116+
// is an implementation detail, but it makes this test possible. If the order
117+
// or content of tags change, this test should be fixed to reflect the
118+
// changes.
119+
constexpr std::string_view kExpectedPattern = R"(tskv\t)"
120+
R"(task_id=[0-9A-F]+\t)"
121+
R"(thread_id=0x[0-9A-F]+\t)"
122+
R"(foo=bar\t)"
123+
R"(text=test\n)";
124+
LOG_CRITICAL() << "test" << logging::LogExtra{{"foo", "bar"}};
125+
logging::LogFlush();
126+
EXPECT_TRUE(utils::regex_match(GetStreamString(), utils::regex(kExpectedPattern))) << GetStreamString();
127+
128+
EXPECT_THAT(GetStreamString(), testing::Not(testing::HasSubstr(" ( /")))
129+
<< "Path shortening for logs stopped working.";
130+
}
131+
97132
TEST_F(LoggingTest, MemLoggerLogFormat) {
98133
logging::impl::MemLogger mem_logger;
99134
mem_logger.ForwardTo(&*GetStreamLogger());
@@ -246,7 +281,8 @@ TEST_F(LoggingTest, ExternalModulePath) {
246281
logging::LogHelper a(
247282
logging::GetDefaultLogger(),
248283
logging::Level::kCritical,
249-
logging::Module{utils::impl::SourceLocation::Custom(__LINE__, kPath, __func__)}
284+
logging::LogClass::kLog,
285+
utils::impl::SourceLocation::Custom(__LINE__, kPath, __func__)
250286
);
251287
}
252288
logging::LogFlush();
@@ -261,7 +297,8 @@ TEST_F(LoggingTest, LogHelperNullptr) {
261297
logging::LogHelper(
262298
logging::LoggerPtr{},
263299
logging::Level::kCritical,
264-
logging::Module{utils::impl::SourceLocation::Custom(__LINE__, kPath, __func__)}
300+
logging::LogClass::kLog,
301+
utils::impl::SourceLocation::Custom(__LINE__, kPath, __func__)
265302
)
266303
.AsLvalue()
267304
<< "Test";
@@ -277,7 +314,8 @@ TEST_F(LoggingTest, LogHelperNullLogger) {
277314
logging::LogHelper(
278315
logging::GetNullLogger(),
279316
logging::Level::kCritical,
280-
logging::Module{utils::impl::SourceLocation::Custom(__LINE__, kPath, __func__)}
317+
logging::LogClass::kLog,
318+
utils::impl::SourceLocation::Custom(__LINE__, kPath, __func__)
281319
)
282320
.AsLvalue()
283321
<< "Test";
@@ -294,7 +332,8 @@ TEST_F(LoggingTest, PartialPrefixModulePath) {
294332
logging::LogHelper a(
295333
logging::GetDefaultLogger(),
296334
logging::Level::kCritical,
297-
logging::Module{utils::impl::SourceLocation::Custom(__LINE__, kPath, __func__)}
335+
logging::LogClass::kLog,
336+
utils::impl::SourceLocation::Custom(__LINE__, kPath, __func__)
298337
);
299338
}
300339
logging::LogFlush();
@@ -517,25 +556,18 @@ TEST_F(LoggingTest, Noexceptness) {
517556
static_assert(noexcept(logging::LogExtra::Stacktrace()));
518557

519558
if constexpr (noexcept(std::string_view{"some string"})) {
520-
EXPECT_TRUE(noexcept(logging::LogHelper(
521-
logging::GetNullLogger(), logging::Level::kCritical, logging::Module{utils::impl::SourceLocation::Current()}
522-
)));
559+
EXPECT_TRUE(noexcept(logging::LogHelper(logging::GetNullLogger(), logging::Level::kCritical)));
523560

524561
const auto logger_ptr = logging::MakeNullLogger();
525-
EXPECT_TRUE(noexcept(logging::LogHelper(
526-
logger_ptr, logging::Level::kCritical, logging::Module{utils::impl::SourceLocation::Current()}
527-
)));
562+
EXPECT_TRUE(noexcept(logging::LogHelper(logger_ptr, logging::Level::kCritical)));
528563

529-
EXPECT_TRUE(noexcept(logging::LogHelper(
530-
logging::LoggerPtr{}, logging::Level::kCritical, logging::Module{utils::impl::SourceLocation::Current()}
531-
)));
564+
EXPECT_TRUE(noexcept(logging::LogHelper(logging::LoggerPtr{}, logging::Level::kCritical)));
532565

533566
EXPECT_TRUE(noexcept(std::declval<const logging::impl::StaticLogEntry&>().ShouldNotLog(
534567
logging::GetDefaultLogger(), logging::Level::kInfo
535568
)));
536569

537-
// TODO: uncomment after https://st.yandex-team.ru/TAXICOMMON-9955
538-
// EXPECT_TRUE(noexcept(USERVER_IMPL_LOG_TO(logging::GetNullLogger(), logging::Level::kInfo)));
570+
EXPECT_TRUE(noexcept(USERVER_IMPL_LOG_TO(logging::GetNullLogger(), logging::Level::kInfo)));
539571

540572
EXPECT_TRUE(noexcept(std::declval<logging::LogHelper&>() << "Test"));
541573
EXPECT_TRUE(noexcept(std::declval<logging::LogHelper&>() << logging::LogExtra::Stacktrace()));

‎core/src/logging/logging_test.hpp

Lines changed: 5 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -126,4 +126,9 @@ class LoggingJsonTest : public LoggingTestBase {
126126
LoggingJsonTest() : LoggingTestBase(logging::Format::kJson) { SetDefaultLogger(GetStreamLogger()); }
127127
};
128128

129+
class LoggingRawTest : public LoggingTestBase {
130+
protected:
131+
LoggingRawTest() : LoggingTestBase(logging::Format::kRaw) { SetDefaultLogger(GetStreamLogger()); }
132+
};
133+
129134
USERVER_NAMESPACE_END

‎core/src/tracing/span.cpp

Lines changed: 1 addition & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -117,8 +117,7 @@ Span::Impl::~Impl() {
117117

118118
{
119119
const impl::DetachLocalSpansScope ignore_local_span;
120-
logging::LogHelper lh{
121-
logging::GetDefaultLogger(), log_level_, logging::Module{source_location_}, logging::LogClass::kTrace};
120+
logging::LogHelper lh{logging::GetDefaultLogger(), log_level_, logging::LogClass::kTrace, source_location_};
122121
std::move(*this).PutIntoLogger(lh.GetTagWriter());
123122
}
124123
}

‎core/src/tracing/span_opentracing.cpp

Lines changed: 1 addition & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -89,9 +89,7 @@ void Span::Impl::LogOpenTracing() const {
8989
auto logger = tracer_->GetOptionalLogger();
9090
if (logger) {
9191
const impl::DetachLocalSpansScope ignore_local_span;
92-
logging::LogHelper lh(
93-
*logger, log_level_, logging::Module(utils::impl::SourceLocation::Current()), logging::LogClass::kTrace
94-
);
92+
logging::LogHelper lh(*logger, log_level_, logging::LogClass::kTrace);
9593
DoLogOpenTracing(lh.GetTagWriter());
9694
}
9795
}

‎grpc/src/ugrpc/impl/grpc_native_logging.cpp

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -53,7 +53,7 @@ void LogFunction(::gpr_log_func_args* args) noexcept {
5353

5454
auto& logger = logging::GetDefaultLogger();
5555
const auto location = utils::impl::SourceLocation::Custom(args->line, args->file, "");
56-
logging::LogHelper(logger, lvl, logging::Module(location), logging::LogClass::kLog) << args->message;
56+
logging::LogHelper(logger, lvl, logging::LogClass::kLog, location) << args->message;
5757

5858
// We used to call LogFlush for kError logging level here,
5959
// but that might lead to a thread switch (there is a coroutine-aware

‎otlp/src/otlp/logs/logger.cpp

Lines changed: 16 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -8,6 +8,7 @@
88
#include <userver/logging/impl/tag_writer.hpp>
99
#include <userver/logging/logger.hpp>
1010
#include <userver/tracing/span.hpp>
11+
#include <userver/utils/algo.hpp>
1112
#include <userver/utils/assert.hpp>
1213
#include <userver/utils/encoding/hex.hpp>
1314
#include <userver/utils/overloaded.hpp>
@@ -29,12 +30,14 @@ const std::string kTimestampFormat = "%Y-%m-%dT%H:%M:%E*S";
2930
Formatter::Formatter(
3031
logging::Level level,
3132
logging::LogClass log_class,
33+
const utils::impl::SourceLocation& location,
3234
SinkType sink_type,
3335
logging::LoggerPtr default_logger,
3436
Logger& logger
3537
)
3638
: logger_(logger) {
3739
if (sink_type == SinkType::kOtlp || sink_type == SinkType::kBoth) {
40+
::opentelemetry::proto::common::v1::KeyValue* kv_module = nullptr;
3841
if (log_class == logging::LogClass::kLog) {
3942
auto& log_record = item_.otlp.emplace<::opentelemetry::proto::logs::v1::LogRecord>();
4043
log_record.set_severity_text(grpc::string{logging::ToUpperCaseString(level)});
@@ -43,14 +46,22 @@ Formatter::Formatter(
4346
std::chrono::duration_cast<std::chrono::nanoseconds>(std::chrono::system_clock::now().time_since_epoch()
4447
);
4548
log_record.set_time_unix_nano(nanoseconds.count());
49+
50+
kv_module = log_record.add_attributes();
4651
} else {
47-
item_.otlp.emplace<::opentelemetry::proto::trace::v1::Span>();
52+
auto& span = item_.otlp.emplace<::opentelemetry::proto::trace::v1::Span>();
53+
kv_module = span.add_attributes();
4854
}
55+
56+
kv_module->set_key("module");
57+
kv_module->mutable_value()->set_string_value(utils::StrCat<grpc::string>(
58+
location.GetFunctionName(), " ( ", location.GetFileName(), ":", location.GetLineString(), " )"
59+
));
4960
}
5061

5162
if (sink_type == SinkType::kDefault || sink_type == SinkType::kBoth) {
5263
if (default_logger) {
53-
item_.forwarded_formatter = default_logger->MakeFormatter(level, log_class);
64+
item_.forwarded_formatter = default_logger->MakeFormatter(level, log_class, location);
5465
}
5566
}
5667
}
@@ -190,9 +201,10 @@ void Logger::Log(logging::Level level, logging::impl::formatters::LoggerItemRef
190201
}
191202
}
192203

193-
logging::impl::formatters::BasePtr Logger::MakeFormatter(logging::Level level, logging::LogClass log_class) {
204+
logging::impl::formatters::BasePtr
205+
Logger::MakeFormatter(logging::Level level, logging::LogClass log_class, const utils::impl::SourceLocation& location) {
194206
auto sink = log_class == logging::LogClass::kLog ? config_.logs_sink : config_.tracing_sink;
195-
return std::make_unique<Formatter>(level, log_class, sink, default_logger_, *this);
207+
return std::make_unique<Formatter>(level, log_class, location, sink, default_logger_, *this);
196208
}
197209

198210
void Logger::SetAttributeValue(

‎otlp/src/otlp/logs/logger.hpp

Lines changed: 6 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -50,7 +50,7 @@ class Logger;
5050

5151
class Formatter final : public logging::impl::formatters::Base {
5252
public:
53-
Formatter(logging::Level level, logging::LogClass log_class, SinkType sink_type, logging::LoggerPtr default_logger, Logger&);
53+
Formatter(logging::Level level, logging::LogClass log_class, const utils::impl::SourceLocation& location, SinkType sink_type, logging::LoggerPtr default_logger, Logger&);
5454

5555
void AddTag(std::string_view key, const logging::LogExtra::Value& value) override;
5656
void AddTag(std::string_view key, std::string_view value) override;
@@ -73,7 +73,11 @@ class Logger final : public logging::impl::LoggerBase {
7373

7474
void Log(logging::Level level, logging::impl::formatters::LoggerItemRef item) override;
7575

76-
logging::impl::formatters::BasePtr MakeFormatter(logging::Level level, logging::LogClass log_class) override;
76+
logging::impl::formatters::BasePtr MakeFormatter(
77+
logging::Level level,
78+
logging::LogClass log_class,
79+
const utils::impl::SourceLocation& location
80+
) override;
7781

7882
void PrependCommonTags(logging::impl::TagWriter writer) const override;
7983

‎universal/include/userver/logging/impl/logger_base.hpp

Lines changed: 8 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -37,15 +37,20 @@ class LoggerBase {
3737
virtual void PrependCommonTags(impl::TagWriter writer) const;
3838

3939
virtual void Log(Level, formatters::LoggerItemRef item) = 0;
40-
virtual formatters::BasePtr MakeFormatter(Level level, LogClass log_class) = 0;
40+
41+
virtual formatters::BasePtr
42+
MakeFormatter(Level level, LogClass log_class, const utils::impl::SourceLocation& location) = 0;
4143

4244
virtual void Flush() {}
4345

4446
virtual void SetLevel(Level level);
47+
4548
Level GetLevel() const noexcept;
49+
4650
bool ShouldLog(Level level) const noexcept;
4751

4852
void SetFlushOn(Level level);
53+
4954
bool ShouldFlush(Level level) const;
5055

5156
virtual void ForwardTo(LoggerBase* logger_to);
@@ -71,7 +76,8 @@ class TextLogger : public LoggerBase {
7176

7277
Format GetFormat() const noexcept;
7378

74-
formatters::BasePtr MakeFormatter(Level level, LogClass log_class) override;
79+
formatters::BasePtr MakeFormatter(Level level, LogClass log_class, const utils::impl::SourceLocation& location)
80+
override;
7581

7682
private:
7783
const Format format_;

‎universal/include/userver/logging/impl/mem_logger.hpp

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -24,7 +24,8 @@ class MemLogger final : public LoggerBase {
2424

2525
void Log(Level, formatters::LoggerItemRef item) override;
2626

27-
formatters::BasePtr MakeFormatter(Level level, LogClass log_class) override;
27+
formatters::BasePtr MakeFormatter(Level level, LogClass log_class, const utils::impl::SourceLocation& location)
28+
override;
2829

2930
void ForwardTo(LoggerBase* logger_to) override;
3031

‎universal/include/userver/logging/log.hpp

Lines changed: 2 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -217,17 +217,8 @@ struct EntryStorage final {
217217
#endif
218218

219219
// NOLINTNEXTLINE(cppcoreguidelines-macro-usage)
220-
#define USERVER_IMPL_LOG_TO(logger, level) \
221-
USERVER_NAMESPACE::logging::LogHelper( \
222-
logger, \
223-
level, \
224-
[](const auto& location) -> const USERVER_NAMESPACE::logging::Module& { \
225-
static const USERVER_NAMESPACE::logging::Module module(location); \
226-
return module; \
227-
}(USERVER_NAMESPACE::utils::impl::SourceLocation::Current()), \
228-
USERVER_NAMESPACE::logging::LogClass::kLog \
229-
) \
230-
.AsLvalue()
220+
#define USERVER_IMPL_LOG_TO(logger, level) \
221+
USERVER_NAMESPACE::logging::LogHelper(logger, level, USERVER_NAMESPACE::logging::LogClass::kLog).AsLvalue()
231222

232223
// NOLINTNEXTLINE(cppcoreguidelines-macro-usage)
233224
#define USERVER_IMPL_DYNAMIC_DEBUG_ENTRY \

0 commit comments

Comments
 (0)