Skip to content

Commit

Permalink
Opt performance of async log (#2602)
Browse files Browse the repository at this point in the history 
* Opt performance of async log

* Fix ci
  • Loading branch information
@chenBright
chenBright authored May 27, 2024
1 parent f81af91 commit bdc141c
Show file tree
Hide file tree
Showing 2 changed files with 132 additions and 85 deletions.
174 changes: 109 additions & 65 deletions src/butil/logging.cc
View file
Original file line number Diff line number Diff line change
Expand Up @@ -428,12 +428,9 @@ void Log2File(const std::string& log) {
if (InitializeLogFileHandle()) {
#if defined(OS_WIN)
SetFilePointer(log_file, 0, 0, SEEK_END);
DWORD num_written;
WriteFile(log_file,
static_cast<const void*>(log.data()),
static_cast<DWORD>(log.size()),
&num_written,
NULL);
DWORD num_written;
WriteFile(log_file, static_cast<const void*>(log.data()),
static_cast<DWORD>(log.size()), &num_written, NULL);
#else
fwrite(log.data(), log.size(), 1, log_file);
fflush(log_file);
Expand All @@ -443,11 +440,41 @@ void Log2File(const std::string& log) {

} // namespace

#if defined(OS_LINUX) || defined(OS_MACOSX)
typedef timeval TimeVal;
#else
struct TimeVal {
time_t tv_sec;
};
#endif

TimeVal GetTimestamp() {
#if defined(OS_LINUX) || defined(OS_MACOSX)
timeval tv;
gettimeofday(&tv, NULL);
return tv;
#else
return { time(NULL) };
#endif
}

struct BAIDU_CACHELINE_ALIGNMENT LogInfo {
std::string file;
std::string func;
std::string content;
TimeVal timestamp{};
int severity{0};
int line{0};
// If `raw' is false, content has been a complete log.
// If raw is true, a complete log consists of all properties of LogInfo.
bool raw{false};
};

struct BAIDU_CACHELINE_ALIGNMENT LogRequest {
static LogRequest* const UNCONNECTED;

LogRequest* next{NULL};
std::string data;
LogInfo log_info;
};

LogRequest* const LogRequest::UNCONNECTED = (LogRequest*)(intptr_t)-1;
Expand All @@ -456,8 +483,8 @@ class AsyncLogger : public butil::SimpleThread {
public:
static AsyncLogger* GetInstance();

void Log(const std::string& log);
void Log(std::string&& log);
void Log(const LogInfo& log_info);
void Log(LogInfo&& log_info);
void StopAndJoin();

private:
Expand All @@ -484,7 +511,7 @@ friend struct DefaultSingletonTraits<AsyncLogger>;
bool IsLogComplete(LogRequest* old_head);

void DoLog(LogRequest* req);
void DoLog(const std::string& log);
void DoLog(const LogInfo& log_info);

butil::atomic<LogRequest*> _log_head;
butil::Mutex _mutex;
Expand Down Expand Up @@ -515,8 +542,26 @@ AsyncLogger::~AsyncLogger() {
StopAndJoin();
}

void AsyncLogger::Log(const std::string& log) {
if (log.empty()) {
std::string LogInfoToLogStr(int severity, butil::StringPiece file,
int line, butil::StringPiece func,
butil::StringPiece content) {
// There's a copy here to concatenate prefix and content. Since
// DefaultLogSink is hardly used right now, the copy is irrelevant.
// A LogSink focused on performance should also be able to handle
// non-continuous inputs which is a must to maximize performance.
std::ostringstream os;
PrintLog(os, severity, file.data(), line, func.data(), content);
os << '\n';
return os.str();
}

std::string LogInfo2LogStr(const LogInfo& log_info) {
return LogInfoToLogStr(log_info.severity, log_info.file, log_info.line,
log_info.func, log_info.content);
}

void AsyncLogger::Log(const LogInfo& log_info) {
if (log_info.content.empty()) {
return;
}

Expand All @@ -525,22 +570,22 @@ void AsyncLogger::Log(const std::string& log) {
FLAGS_max_async_log_queue_size;
if (is_full || _stop.load(butil::memory_order_relaxed)) {
// Async logger is full or stopped, fallback to sync log.
DoLog(log);
DoLog(log_info);
return;
}

auto log_req = butil::get_object<LogRequest>();
if (!log_req) {
// Async log failed, fallback to sync log.
DoLog(log);
DoLog(log_info);
return;
}
log_req->data = log;
log_req->log_info = log_info;
LogImpl(log_req);
}

void AsyncLogger::Log(std::string&& log) {
if (log.empty()) {
void AsyncLogger::Log(LogInfo&& log_info) {
if (log_info.content.empty()) {
return;
}

Expand All @@ -549,17 +594,17 @@ void AsyncLogger::Log(std::string&& log) {
FLAGS_max_async_log_queue_size;
if (is_full || _stop.load(butil::memory_order_relaxed)) {
// Async logger is full or stopped, fallback to sync log.
DoLog(log);
DoLog(log_info);
return;
}

auto log_req = butil::get_object<LogRequest>();
if (!log_req) {
// Async log failed, fallback to sync log.
DoLog(log);
DoLog(log_info);
return;
}
log_req->data = std::move(log);
log_req->log_info = std::move(log_info);
LogImpl(log_req);
}

Expand Down Expand Up @@ -632,7 +677,7 @@ void AsyncLogger::Run() {
void AsyncLogger::LogTask(LogRequest* req) {
do {
// req was logged, skip it.
if (req->next != NULL && req->data.empty()) {
if (req->next != NULL && req->log_info.content.empty()) {
LogRequest* const saved_req = req;
req = req->next;
butil::return_object(saved_req);
Expand All @@ -642,13 +687,13 @@ void AsyncLogger::LogTask(LogRequest* req) {
while (req->next != NULL) {
LogRequest* const saved_req = req;
req = req->next;
if (!saved_req->data.empty()) {
if (!saved_req->log_info.content.empty()) {
DoLog(saved_req);
}
// Release LogRequests until last request.
butil::return_object(saved_req);
}
if (!req->data.empty()) {
if (!req->log_info.content.empty()) {
DoLog(req);
}

Expand Down Expand Up @@ -700,13 +745,17 @@ bool AsyncLogger::IsLogComplete(LogRequest* old_head) {
}

void AsyncLogger::DoLog(LogRequest* req) {
DoLog(req->data);
req->data.clear();
DoLog(req->log_info);
req->log_info.content.clear();
}

void AsyncLogger::DoLog(const std::string& log) {
Log2File(log);
_log_request_count.fetch_sub(1);
void AsyncLogger::DoLog(const LogInfo& log_info) {
if (log_info.raw) {
Log2File(LogInfo2LogStr(log_info));
} else {
Log2File(log_info.content);
}
_log_request_count.fetch_sub(1, butil::memory_order_relaxed);
}

LoggingSettings::LoggingSettings()
Expand Down Expand Up @@ -778,16 +827,10 @@ static void PrintLogSeverity(std::ostream& os, int severity) {
}

void PrintLogPrefix(std::ostream& os, int severity,
const char* file, int line,
const char* func) {
butil::StringPiece file, int line,
butil::StringPiece func, TimeVal tv) {
PrintLogSeverity(os, severity);
#if defined(OS_LINUX) || defined(OS_MACOSX)
timeval tv;
gettimeofday(&tv, NULL);
time_t t = tv.tv_sec;
#else
time_t t = time(NULL);
#endif
struct tm local_tm = {0, 0, 0, 0, 0, 0, 0, 0, 0, 0, NULL};
#if _MSC_VER >= 1400
localtime_s(&local_tm, &t);
Expand Down Expand Up @@ -822,7 +865,7 @@ void PrintLogPrefix(std::ostream& os, int severity,
os << ' ' << hostname;
}
os << ' ' << file << ':' << line;
if (func && *func != '\0') {
if (!func.empty()) {
os << " " << func;
}
os << "] ";
Expand All @@ -832,12 +875,13 @@ void PrintLogPrefix(std::ostream& os, int severity,

void PrintLogPrefix(std::ostream& os, int severity,
const char* file, int line) {
PrintLogPrefix(os, severity, file, line, "");
PrintLogPrefix(os, severity, file, line, "", GetTimestamp());
}

static void PrintLogPrefixAsJSON(std::ostream& os, int severity,
const char* file, const char* func,
int line) {
butil::StringPiece file,
butil::StringPiece func,
int line, TimeVal tv) {
// severity
os << "\"L\":\"";
if (severity < 0) {
Expand All @@ -849,13 +893,7 @@ static void PrintLogPrefixAsJSON(std::ostream& os, int severity,
}
// time
os << "\",\"T\":\"";
#if defined(OS_LINUX)
timeval tv;
gettimeofday(&tv, NULL);
time_t t = tv.tv_sec;
#else
time_t t = time(NULL);
#endif
struct tm local_tm = {0, 0, 0, 0, 0, 0, 0, 0, 0, 0, NULL};
#if _MSC_VER >= 1400
localtime_s(&local_tm, &t);
Expand All @@ -871,7 +909,7 @@ static void PrintLogPrefixAsJSON(std::ostream& os, int severity,
<< std::setw(2) << local_tm.tm_hour << ':'
<< std::setw(2) << local_tm.tm_min << ':'
<< std::setw(2) << local_tm.tm_sec;
#if defined(OS_LINUX)
#if defined(OS_LINUX) || defined(OS_MACOSX)
os << '.' << std::setw(6) << tv.tv_usec;
#endif
os << "\",";
Expand All @@ -889,7 +927,7 @@ static void PrintLogPrefixAsJSON(std::ostream& os, int severity,
os << "\"host\":\"" << hostname << "\",";
}
os << "\"C\":\"" << file << ':' << line;
if (func && *func != '\0') {
if (!func.empty()) {
os << " " << func;
}
os << "\"";
Expand Down Expand Up @@ -922,11 +960,11 @@ inline void OutputLog(std::ostream& os, const butil::StringPiece& s) {
void PrintLog(std::ostream& os, int severity, const char* file, int line,
const char* func, const butil::StringPiece& content) {
if (!FLAGS_log_as_json) {
PrintLogPrefix(os, severity, file, line, func);
PrintLogPrefix(os, severity, file, line, func, GetTimestamp());
OutputLog(os, content);
} else {
os << '{';
PrintLogPrefixAsJSON(os, severity, file, func, line);
PrintLogPrefixAsJSON(os, severity, file, func, line, GetTimestamp());
bool pair_quote = false;
if (content.empty() || content[0] != '"') {
// not a json, add a 'M' field
Expand Down Expand Up @@ -1246,33 +1284,39 @@ class DefaultLogSink : public LogSink {
bool OnLogMessage(int severity, const char* file,
int line, const char* func,
const butil::StringPiece& content) override {
// There's a copy here to concatenate prefix and content. Since
// DefaultLogSink is hardly used right now, the copy is irrelevant.
// A LogSink focused on performance should also be able to handle
// non-continuous inputs which is a must to maximize performance.
std::ostringstream os;
PrintLog(os, severity, file, line, func, content);
os << '\n';
std::string log = os.str();

if ((logging_destination & LOG_TO_SYSTEM_DEBUG_LOG) != 0) {
fwrite(log.data(), log.size(), 1, stderr);
fflush(stderr);
} else if (severity >= kAlwaysPrintErrorLevel) {
std::string log;
if ((logging_destination & LOG_TO_SYSTEM_DEBUG_LOG) != 0 ||
severity >= kAlwaysPrintErrorLevel) {
log = LogInfoToLogStr(severity, file, line, func, content);
// When we're only outputting to a log file, above a certain log level, we
// should still output to stderr so that we can better detect and diagnose
// problems with unit tests, especially on the buildbots.
fwrite(log.data(), log.size(), 1, stderr);
fflush(stderr);
}

// write to log file
if ((logging_destination & LOG_TO_FILE) != 0) {
if ((FLAGS_crash_on_fatal_log && severity == BLOG_FATAL) ||
!FLAGS_async_log) {
if (log.empty()) {
log = LogInfoToLogStr(severity, file, line, func, content);
}
Log2File(log);
} else {
AsyncLogger::GetInstance()->Log(std::move(log));
LogInfo info;
if (log.empty()) {
info.severity = severity;
info.timestamp = GetTimestamp();
info.file = file;
info.func = func;
info.line = line;
info.content = content.as_string();
info.raw = true;
} else {
info.content = std::move(log);
info.raw = false;
}
AsyncLogger::GetInstance()->Log(std::move(info));
}
}
return true;
Expand Down
Loading

0 comments on commit bdc141c

Please sign in to comment.