Compare commits

...

3 Commits

Author SHA1 Message Date
l0rinc
f2a0be1b9f
Merge 6f049e1230090baa64d1bf1a3d9c2064ee913e39 into cd8089c20baaaee329cbf7951195953a9f86d7cf 2025-03-16 17:15:28 +01:00
Lőrinc
6f049e1230 log,optimization: use original log string when no suspicious chars found
> build/src/bench/bench_bitcoin -filter='LogEscapeMessage.+' --min-time=10000

> C compiler ............................ AppleClang 16.0.0.16000026

|               ns/op |                op/s |    err% |     total | benchmark
|--------------------:|--------------------:|--------:|----------:|:----------
|              106.54 |        9,386,391.31 |    0.2% |     11.01 | `LogEscapeMessageNormal`
|              335.58 |        2,979,947.73 |    0.3% |     10.96 | `LogEscapeMessageSuspicious`
2025-02-24 15:24:41 +01:00
Lőrinc
a445c688ab bench: measure LogEscapeMessage in normal & suspicious cases
> build/src/bench/bench_bitcoin -filter='LogEscapeMessage.+' --min-time=10000

> C compiler ............................ AppleClang 16.0.0.16000026

|               ns/op |                op/s |    err% |     total | benchmark
|--------------------:|--------------------:|--------:|----------:|:----------
|              216.10 |        4,627,429.03 |    0.2% |     10.81 | `LogEscapeMessageNormal`
|              328.77 |        3,041,669.54 |    0.7% |     10.97 | `LogEscapeMessageSuspicious`
2025-02-24 15:19:04 +01:00
2 changed files with 55 additions and 7 deletions

View File

@ -9,6 +9,8 @@
#include <functional>
#include <vector>
using namespace std::literals;
// All but 2 of the benchmarks should have roughly similar performance:
//
// LogWithoutDebug should be ~3 orders of magnitude faster, as nothing is logged.
@ -57,8 +59,48 @@ static void LogWithoutWriteToFile(benchmark::Bench& bench)
});
}
namespace BCLog {
bool IsSuspicious(const char ch) noexcept;
std::string LogEscapeMessage(std::string_view str);
}
static void LogEscapeMessageNormal(benchmark::Bench& bench) {
const std::vector<std::string> normal_logs{
"UpdateTip: new best=000000000000000000003c4c32d94a9363241a84d42cbbc1ec9f5f12f84f4feb height=875371 version=0x20000004 log2_work=95.334853 tx=1133590694 date='2024-12-19T01:57:26Z' progress=0.993026 cache=8.3MiB(56574txo)"s,
"received: headers (162 bytes) peer=15"s,
"Config file arg: datadir=/Users/bitcoin/data"s,
"Verified block header at height 12345 hash: 你好 🔤"s
};
bench.batch(normal_logs.size()).run([&] {
for (const auto& msg : normal_logs) {
const auto& res{std::ranges::none_of(msg, BCLog::IsSuspicious) ? msg : BCLog::LogEscapeMessage(msg)};
ankerl::nanobench::doNotOptimizeAway(res);
}
});
}
static void LogEscapeMessageSuspicious(benchmark::Bench& bench) {
// Based on the test cases
const std::vector<std::string> suspicious_logs{
"Received strange message\0from peer=12"s,
"Got malformed packet\x01\x02\x03\x7F from peer=13"s,
"Peer=14 sent:\x0D\x0Econtent-length: 100\x0D\x0A"s,
"Validation failed on\x1B[31mERROR\x1B[0m block=123456"s
};
bench.batch(suspicious_logs.size()).run([&] {
for (const auto& msg : suspicious_logs) {
const auto& res{std::ranges::none_of(msg, BCLog::IsSuspicious) ? msg : BCLog::LogEscapeMessage(msg)};
ankerl::nanobench::doNotOptimizeAway(res);
}
});
}
BENCHMARK(LogWithDebug, benchmark::PriorityLevel::HIGH);
BENCHMARK(LogWithoutDebug, benchmark::PriorityLevel::HIGH);
BENCHMARK(LogWithThreadNames, benchmark::PriorityLevel::HIGH);
BENCHMARK(LogWithoutThreadNames, benchmark::PriorityLevel::HIGH);
BENCHMARK(LogWithoutWriteToFile, benchmark::PriorityLevel::HIGH);
BENCHMARK(LogEscapeMessageNormal, benchmark::PriorityLevel::LOW);
BENCHMARK(LogEscapeMessageSuspicious, benchmark::PriorityLevel::LOW);

View File

@ -315,6 +315,11 @@ std::string BCLog::Logger::LogTimestampStr(SystemClock::time_point now, std::chr
}
namespace BCLog {
bool IsSuspicious(const char ch) noexcept
{
const auto uch{static_cast<uint8_t>(ch)};
return (uch < ' ' && uch != '\n') || uch == '\x7f';
}
/** Belts and suspenders: make sure outgoing log messages don't contain
* potentially suspicious characters, such as terminal control codes.
*
@ -322,14 +327,15 @@ namespace BCLog {
* It escapes instead of removes them to still allow for troubleshooting
* issues where they accidentally end up in strings.
*/
std::string LogEscapeMessage(std::string_view str) {
std::string LogEscapeMessage(std::string_view str)
{
std::string ret;
for (char ch_in : str) {
uint8_t ch = (uint8_t)ch_in;
if ((ch >= 32 || ch == '\n') && ch != '\x7f') {
ret += ch_in;
} else {
ret.reserve(3 + str.size()); // Assume at least one suspicious character
for (auto ch : str) {
if (IsSuspicious(ch)) {
ret += strprintf("\\x%02x", ch);
} else {
ret += ch;
}
}
return ret;
@ -392,7 +398,7 @@ void BCLog::Logger::LogPrintStr(std::string_view str, std::string_view logging_f
void BCLog::Logger::LogPrintStr_(std::string_view str, std::string_view logging_function, std::string_view source_file, int source_line, BCLog::LogFlags category, BCLog::Level level)
{
std::string str_prefixed = LogEscapeMessage(str);
std::string str_prefixed{std::ranges::none_of(str, IsSuspicious) ? str : LogEscapeMessage(str)};
if (m_buffering) {
{