optimize performance of easylog (#343)
This commit is contained in:
qicosmos
GitHub
parent
f1b9722210
commit
72b2ef8340
|
|
@ -19,7 +19,7 @@
|
|||
#include <filesystem>
|
||||
#include <fstream>
|
||||
#include <iostream>
|
||||
#include <mutex>
|
||||
#include <shared_mutex>
|
||||
#include <string>
|
||||
#include <string_view>
|
||||
|
||||
|
|
@ -32,12 +32,55 @@ struct QueueTraits : public moodycamel::ConcurrentQueueDefaultTraits {
|
|||
static const size_t BLOCK_SIZE = 256;
|
||||
};
|
||||
|
||||
constexpr char digits[10] = {'0', '1', '2', '3', '4', '5', '6', '7', '8', '9'};
|
||||
|
||||
template <size_t N, char c>
|
||||
inline void to_int(int num, char *p, int &size) {
|
||||
for (int i = 0; i < N; i++) {
|
||||
p[--size] = digits[num % 10];
|
||||
num = num / 10;
|
||||
}
|
||||
|
||||
if constexpr (N != 4)
|
||||
p[--size] = c;
|
||||
}
|
||||
|
||||
inline char *get_time_str(const auto &now) {
|
||||
static thread_local char buf[33];
|
||||
static thread_local std::chrono::seconds last_sec_{};
|
||||
|
||||
std::chrono::system_clock::duration d = now.time_since_epoch();
|
||||
std::chrono::seconds s = std::chrono::duration_cast<std::chrono::seconds>(d);
|
||||
auto mill_sec =
|
||||
std::chrono::duration_cast<std::chrono::milliseconds>(d - s).count();
|
||||
int size = 23;
|
||||
if (last_sec_ == s) {
|
||||
to_int<3, '.'>(mill_sec, buf, size);
|
||||
return buf;
|
||||
}
|
||||
|
||||
last_sec_ = s;
|
||||
auto tm = std::chrono::system_clock::to_time_t(now);
|
||||
auto gmt = localtime(&tm);
|
||||
|
||||
to_int<3, '.'>(mill_sec, buf, size);
|
||||
to_int<2, ':'>(gmt->tm_sec, buf, size);
|
||||
to_int<2, ':'>(gmt->tm_min, buf, size);
|
||||
to_int<2, ' '>(gmt->tm_hour, buf, size);
|
||||
|
||||
to_int<2, '-'>(gmt->tm_mday, buf, size);
|
||||
to_int<2, '-'>(gmt->tm_mon + 1, buf, size);
|
||||
to_int<4, ' '>(gmt->tm_year + 1900, buf, size);
|
||||
return buf;
|
||||
}
|
||||
|
||||
class appender {
|
||||
public:
|
||||
appender(const std::string &filename, bool async, bool enable_console,
|
||||
size_t max_file_size, size_t max_files, bool flush_every_time)
|
||||
: flush_every_time_(flush_every_time),
|
||||
enable_console_(enable_console),
|
||||
appender() = default;
|
||||
appender(const std::string &filename, bool async, size_t max_file_size,
|
||||
size_t max_files, bool flush_every_time)
|
||||
: has_init_(true),
|
||||
flush_every_time_(flush_every_time),
|
||||
max_file_size_(max_file_size) {
|
||||
filename_ = filename;
|
||||
max_files_ = (std::min)(max_files, static_cast<size_t>(1000));
|
||||
|
|
@ -56,7 +99,7 @@ class appender {
|
|||
}
|
||||
|
||||
if (queue_.size_approx() == 0) {
|
||||
std::unique_lock<std::mutex> lock(mtx_);
|
||||
std::unique_lock lock(que_mtx_);
|
||||
cnd_.wait(lock, [&]() {
|
||||
return queue_.size_approx() > 0 || stop_;
|
||||
});
|
||||
|
|
@ -74,45 +117,86 @@ class appender {
|
|||
}
|
||||
}
|
||||
|
||||
std::string_view get_tid_buf(unsigned int tid) {
|
||||
static thread_local char buf[24];
|
||||
static thread_local unsigned int last_tid;
|
||||
static thread_local size_t last_len;
|
||||
if (tid == last_tid) {
|
||||
return {buf, last_len};
|
||||
}
|
||||
|
||||
buf[0] = '[';
|
||||
auto [ptr, ec] = std::to_chars(buf + 1, buf + 21, tid);
|
||||
buf[22] = ']';
|
||||
buf[23] = ' ';
|
||||
last_len = ptr - buf;
|
||||
buf[last_len++] = ']';
|
||||
buf[last_len++] = ' ';
|
||||
return {buf, last_len};
|
||||
}
|
||||
|
||||
template <bool sync = false, bool enable_console = false>
|
||||
void write_record(record_t &record) {
|
||||
char buf[32];
|
||||
size_t len = get_time_str(buf, record.get_time_point());
|
||||
if constexpr (sync == true) {
|
||||
std::shared_lock guard(mtx_);
|
||||
if (max_files_ > 0 && file_size_ > max_file_size_ &&
|
||||
static_cast<size_t>(-1) != file_size_) {
|
||||
guard.unlock();
|
||||
std::lock_guard lock{mtx_};
|
||||
roll_log_files();
|
||||
}
|
||||
}
|
||||
|
||||
write_str({buf, len});
|
||||
write_str({" ", 1});
|
||||
write_str(severity_str(record.get_severity()));
|
||||
write_str({" ", 1});
|
||||
auto buf = get_time_str(record.get_time_point());
|
||||
|
||||
auto [ptr, ec] = std::to_chars(buf, buf + 32, record.get_tid());
|
||||
buf[23] = ' ';
|
||||
memcpy(buf + 24, severity_str(record.get_severity()).data(), 8);
|
||||
buf[32] = ' ';
|
||||
|
||||
write_str({"[", 1});
|
||||
write_str(std::string_view(buf, ptr - buf));
|
||||
write_str({"] ", 2});
|
||||
write_str(record.get_file_str());
|
||||
write_str(record.get_message());
|
||||
write_str({"\n", 1});
|
||||
if constexpr (enable_console) {
|
||||
add_color(record.get_severity());
|
||||
}
|
||||
|
||||
if (enable_console_) {
|
||||
write_str<enable_console>(std::string_view(buf, 33));
|
||||
|
||||
if constexpr (enable_console) {
|
||||
clean_color(record.get_severity());
|
||||
}
|
||||
|
||||
write_str<enable_console>(get_tid_buf(record.get_tid()));
|
||||
write_str<enable_console>(record.get_file_str());
|
||||
write_str<enable_console>(record.get_message());
|
||||
|
||||
if constexpr (enable_console) {
|
||||
std::cout << std::flush;
|
||||
}
|
||||
}
|
||||
|
||||
void add_color(Severity severity) {
|
||||
#if defined(_WIN32)
|
||||
#else
|
||||
if (severity == Severity::WARN)
|
||||
std::cout << "\x1B[93m";
|
||||
if (severity == Severity::ERROR)
|
||||
std::cout << "\x1B[91m";
|
||||
if (severity == Severity::CRITICAL)
|
||||
std::cout << "\x1B[97m\x1B[41m";
|
||||
#endif
|
||||
}
|
||||
|
||||
void clean_color(Severity severity) {
|
||||
#if defined(_WIN32)
|
||||
#else
|
||||
if (severity >= Severity::WARN)
|
||||
std::cout << "\x1B[0m\x1B[0K";
|
||||
#endif
|
||||
}
|
||||
|
||||
void write(record_t &&r) {
|
||||
queue_.enqueue(std::move(r));
|
||||
cnd_.notify_all();
|
||||
}
|
||||
|
||||
template <typename String>
|
||||
void write(const String &str) {
|
||||
std::lock_guard guard(mtx_);
|
||||
if (max_files_ > 0 && file_size_ > max_file_size_ &&
|
||||
static_cast<size_t>(-1) != file_size_) {
|
||||
roll_log_files();
|
||||
}
|
||||
|
||||
write_str(str);
|
||||
}
|
||||
|
||||
void flush() {
|
||||
std::lock_guard guard(mtx_);
|
||||
if (file_.is_open()) {
|
||||
|
|
@ -140,20 +224,6 @@ class appender {
|
|||
write_thd_.join();
|
||||
}
|
||||
|
||||
template <size_t N>
|
||||
size_t get_time_str(char (&buf)[N], const auto &now) {
|
||||
const auto nowAsTimeT = std::chrono::system_clock::to_time_t(now);
|
||||
const auto nowMs = std::chrono::duration_cast<std::chrono::milliseconds>(
|
||||
now.time_since_epoch())
|
||||
.count() %
|
||||
1000;
|
||||
|
||||
size_t endpos =
|
||||
std::strftime(buf, N, "%Y-%m-%d %H:%M:%S", std::localtime(&nowAsTimeT));
|
||||
snprintf(buf + endpos, N - endpos, ".%03d", (int)nowMs);
|
||||
return endpos + 4;
|
||||
}
|
||||
|
||||
private:
|
||||
void open_log_file() {
|
||||
std::string filename = build_filename();
|
||||
|
|
@ -214,22 +284,25 @@ class appender {
|
|||
is_first_write_ = false;
|
||||
}
|
||||
|
||||
template <bool enable_console>
|
||||
void write_str(std::string_view str) {
|
||||
if (file_.write(str.data(), str.size())) {
|
||||
if (flush_every_time_) {
|
||||
file_.flush();
|
||||
}
|
||||
if (has_init_) {
|
||||
if (file_.write(str.data(), str.size())) {
|
||||
if (flush_every_time_) {
|
||||
file_.flush();
|
||||
}
|
||||
|
||||
file_size_ += str.size();
|
||||
file_size_ += str.size();
|
||||
}
|
||||
}
|
||||
|
||||
if (enable_console_) {
|
||||
if constexpr (enable_console) {
|
||||
std::cout << str;
|
||||
}
|
||||
}
|
||||
|
||||
bool has_init_ = false;
|
||||
std::string filename_;
|
||||
bool enable_console_ = false;
|
||||
|
||||
bool flush_every_time_;
|
||||
size_t file_size_ = 0;
|
||||
|
|
@ -237,9 +310,11 @@ class appender {
|
|||
size_t max_files_ = 0;
|
||||
bool is_first_write_ = true;
|
||||
|
||||
std::mutex mtx_;
|
||||
std::shared_mutex mtx_;
|
||||
std::ofstream file_;
|
||||
|
||||
std::mutex que_mtx_;
|
||||
|
||||
moodycamel::ConcurrentQueue<record_t, QueueTraits> queue_;
|
||||
std::thread write_thd_;
|
||||
std::condition_variable cnd_;
|
||||
|
|
|
|||
|
|
@ -56,8 +56,8 @@ class logger {
|
|||
void init(Severity min_severity, bool async, bool enable_console,
|
||||
const std::string &filename, size_t max_file_size, size_t max_files,
|
||||
bool flush_every_time) {
|
||||
static appender appender(filename, async, enable_console, max_file_size,
|
||||
max_files, flush_every_time);
|
||||
static appender appender(filename, async, max_file_size, max_files,
|
||||
flush_every_time);
|
||||
async_ = async;
|
||||
appender_ = &appender;
|
||||
min_severity_ = min_severity;
|
||||
|
|
@ -73,49 +73,28 @@ class logger {
|
|||
void stop_async_log() { appender_->stop(); }
|
||||
|
||||
private:
|
||||
logger() = default;
|
||||
logger() {
|
||||
static appender appender{};
|
||||
appender_ = &appender;
|
||||
}
|
||||
|
||||
logger(const logger &) = default;
|
||||
|
||||
void append_record(record_t record) { appender_->write(std::move(record)); }
|
||||
|
||||
void append_format(const record_t &record) {
|
||||
char buf[32];
|
||||
size_t len = appender_->get_time_str(buf, record.get_time_point());
|
||||
|
||||
#ifdef YLT_ENABLE_PMR
|
||||
#if __has_include(<memory_resource>)
|
||||
char arr[1024];
|
||||
std::pmr::monotonic_buffer_resource resource(arr, 1024);
|
||||
std::pmr::string str{&resource};
|
||||
#endif
|
||||
#else
|
||||
std::string str;
|
||||
#endif
|
||||
str.append(buf, len).append(" ");
|
||||
str.append(severity_str(record.get_severity())).append(" ");
|
||||
|
||||
auto [ptr, ec] = std::to_chars(buf, buf + 32, record.get_tid());
|
||||
|
||||
str.append("[").append(std::string_view(buf, ptr - buf)).append("] ");
|
||||
str.append(record.get_file_str());
|
||||
str.append(record.get_message()).append("\n");
|
||||
|
||||
void append_format(record_t &record) {
|
||||
if (appender_) {
|
||||
appender_->write(str);
|
||||
}
|
||||
|
||||
if (enable_console_) {
|
||||
std::cout << str;
|
||||
std::cout << std::flush;
|
||||
}
|
||||
|
||||
for (auto &fn : appenders_) {
|
||||
fn(std::string_view(str));
|
||||
if (enable_console_) {
|
||||
appender_->write_record<true, true>(record);
|
||||
}
|
||||
else {
|
||||
appender_->write_record<true, false>(record);
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
Severity min_severity_;
|
||||
bool async_ = true;
|
||||
bool async_ = false;
|
||||
bool enable_console_ = true;
|
||||
appender *appender_ = nullptr;
|
||||
std::vector<std::function<void(std::string_view)>> appenders_;
|
||||
|
|
|
|||
|
|
@ -64,7 +64,6 @@ namespace easylog {
|
|||
|
||||
inline std::string_view severity_str(Severity severity) {
|
||||
switch (severity) {
|
||||
#if defined(NDEBUG) || defined(_WIN32)
|
||||
case Severity::TRACE:
|
||||
return "TRACE ";
|
||||
case Severity::DEBUG:
|
||||
|
|
@ -77,22 +76,8 @@ inline std::string_view severity_str(Severity severity) {
|
|||
return "ERROR ";
|
||||
case Severity::CRITICAL:
|
||||
return "CRITICAL";
|
||||
#else
|
||||
case Severity::TRACE:
|
||||
return "TRACE ";
|
||||
case Severity::DEBUG:
|
||||
return "DEBUG ";
|
||||
case Severity::INFO:
|
||||
return "INFO ";
|
||||
case Severity::WARN:
|
||||
return "\x1B[93mWARNING\x1B[0m\x1B[0K ";
|
||||
case Severity::ERROR:
|
||||
return "\x1B[91mERROR\x1B[0m\x1B[0K ";
|
||||
case Severity::CRITICAL:
|
||||
return "\x1B[97m\x1B[41mCRITICAL\x1B[0m\x1B[0K";
|
||||
#endif
|
||||
default:
|
||||
return "NONE";
|
||||
return "NONE ";
|
||||
}
|
||||
}
|
||||
|
||||
|
|
@ -102,14 +87,19 @@ class record_t {
|
|||
record_t(auto tm_point, Severity severity, std::string_view str)
|
||||
: tm_point_(tm_point),
|
||||
severity_(severity),
|
||||
tid_(get_tid_impl()),
|
||||
file_str_(str) {}
|
||||
tid_(_get_tid()),
|
||||
file_str_(str) {
|
||||
ss_.reserve(64);
|
||||
}
|
||||
record_t(record_t &&) = default;
|
||||
record_t &operator=(record_t &&) = default;
|
||||
|
||||
Severity get_severity() const { return severity_; }
|
||||
|
||||
const char *get_message() const { return ss_.data(); }
|
||||
const char *get_message() {
|
||||
ss_.push_back('\n');
|
||||
return ss_.data();
|
||||
}
|
||||
|
||||
std::string_view get_file_str() const { return file_str_; }
|
||||
|
||||
|
|
@ -175,6 +165,11 @@ class record_t {
|
|||
ss_.append(buf);
|
||||
}
|
||||
|
||||
unsigned int _get_tid() {
|
||||
static thread_local unsigned int tid = get_tid_impl();
|
||||
return tid;
|
||||
}
|
||||
|
||||
unsigned int get_tid_impl() {
|
||||
#ifdef _WIN32
|
||||
return std::hash<std::thread::id>{}(std::this_thread::get_id());
|
||||
|
|
|
|||
|
|
@ -1,9 +1,10 @@
|
|||
find_package(glog QUIET)
|
||||
find_package(spdlog QUIET)
|
||||
|
||||
if (UNIX)
|
||||
SET(CMAKE_CXX_FLAGS "${CMAKE_CXX_FLAGS} -pthread")
|
||||
endif()
|
||||
#include_directories(spdlog/include)
|
||||
# include_directories(spdlog/include)
|
||||
add_executable(easylog_benchmark
|
||||
main.cpp
|
||||
)
|
||||
|
|
@ -15,3 +16,9 @@ if (glog_FOUND)
|
|||
target_compile_definitions(easylog_benchmark PRIVATE HAVE_GLOG)
|
||||
target_link_libraries(easylog_benchmark PRIVATE glog::glog)
|
||||
endif ()
|
||||
|
||||
if (spdlog_FOUND)
|
||||
message(STATUS "spdlog_FOUND: ${spdlog_FOUND}")
|
||||
target_compile_definitions(easylog_benchmark PRIVATE HAVE_SPDLOG)
|
||||
target_link_libraries(easylog_benchmark PRIVATE spdlog::spdlog_header_only)
|
||||
endif ()
|
||||
|
|
|
|||
|
|
@ -14,12 +14,17 @@
|
|||
* limitations under the License.
|
||||
*/
|
||||
|
||||
#include <exception>
|
||||
#include <system_error>
|
||||
#ifdef HAVE_GLOG
|
||||
#include <glog/logging.h>
|
||||
#endif
|
||||
|
||||
// #include <spdlog/sinks/base_sink.h>
|
||||
// #include <spdlog/spdlog.h>
|
||||
#ifdef HAVE_SPDLOG
|
||||
#include <spdlog/sinks/base_sink.h>
|
||||
#include <spdlog/sinks/basic_file_sink.h>
|
||||
#include <spdlog/spdlog.h>
|
||||
#endif
|
||||
|
||||
#include <filesystem>
|
||||
|
||||
|
|
@ -67,36 +72,79 @@ void test_glog() {
|
|||
#endif
|
||||
}
|
||||
|
||||
void test_easylog() {
|
||||
std::filesystem::remove("long_name_of_easylog.txt");
|
||||
easylog::init_log(Severity::DEBUG, "long_name_of_easylog.txt", true, false,
|
||||
10 * 1024 * 1024, 1);
|
||||
void test_easylog(std::string filename, int count, bool async) {
|
||||
std::error_code ec;
|
||||
std::filesystem::remove(filename, ec);
|
||||
if (ec) {
|
||||
std::cout << ec.message() << "\n";
|
||||
}
|
||||
easylog::init_log(Severity::DEBUG, filename, async, false, -1);
|
||||
for (int i = 0; i < 10; i++) {
|
||||
ScopedTimer timer("easylog");
|
||||
for (int i = 0; i < 50000; i++)
|
||||
for (int i = 0; i < count; i++)
|
||||
ELOG(INFO) << "Hello logger: msg number " << i;
|
||||
}
|
||||
}
|
||||
|
||||
// void bench(int howmany, std::shared_ptr<spdlog::logger> log) {
|
||||
// spdlog::drop(log->name());
|
||||
#ifdef HAVE_SPDLOG
|
||||
void bench(int howmany, std::shared_ptr<spdlog::logger> log) {
|
||||
spdlog::drop(log->name());
|
||||
|
||||
// using std::chrono::duration;
|
||||
// using std::chrono::duration_cast;
|
||||
// using std::chrono::high_resolution_clock;
|
||||
using std::chrono::duration;
|
||||
using std::chrono::duration_cast;
|
||||
using std::chrono::high_resolution_clock;
|
||||
|
||||
// for (int i = 0; i < 10; i++) {
|
||||
// ScopedTimer timer("spdlog ");
|
||||
// for (auto i = 0; i < howmany; ++i) {
|
||||
// log->info("Hello logger: msg number {}", i);
|
||||
// }
|
||||
// }
|
||||
// }
|
||||
for (int i = 0; i < 10; i++) {
|
||||
ScopedTimer timer("spdlog ");
|
||||
for (auto i = 0; i < howmany; ++i) {
|
||||
SPDLOG_LOGGER_INFO(log, "Hello logger: msg number {}", i);
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
void bench_mt(int howmany, std::shared_ptr<spdlog::logger> log,
|
||||
size_t thread_count) {
|
||||
using std::chrono::duration;
|
||||
using std::chrono::duration_cast;
|
||||
using std::chrono::high_resolution_clock;
|
||||
spdlog::drop(log->name());
|
||||
|
||||
std::vector<std::thread> threads;
|
||||
threads.reserve(thread_count);
|
||||
{
|
||||
ScopedTimer timer("spdlog ");
|
||||
for (size_t t = 0; t < thread_count; ++t) {
|
||||
threads.emplace_back([&]() {
|
||||
for (int j = 0; j < howmany / static_cast<int>(thread_count); j++) {
|
||||
SPDLOG_LOGGER_INFO(log, "Hello logger: msg number {}", j);
|
||||
}
|
||||
});
|
||||
}
|
||||
|
||||
for (auto &t : threads) {
|
||||
t.join();
|
||||
};
|
||||
}
|
||||
}
|
||||
#endif
|
||||
|
||||
int main() {
|
||||
// auto basic_st = spdlog::basic_logger_st("basic_st", "basic_st.log", true);
|
||||
// bench(50000, std::move(basic_st));
|
||||
int count = 500000;
|
||||
#ifdef HAVE_SPDLOG
|
||||
spdlog::set_pattern("%Y-%m-%d %H:%M:%S.%e %l [%t] [%@] %v");
|
||||
|
||||
std::cout << "========test sync spdlog===========\n";
|
||||
auto basic_st = spdlog::basic_logger_st("basic_st", "basic_st.log", true);
|
||||
bench(count, std::move(basic_st));
|
||||
|
||||
std::cout << "========test async spdlog===========\n";
|
||||
auto basic_mt = spdlog::basic_logger_st("basic_mt", "basic_mt.log", true);
|
||||
bench_mt(count, std::move(basic_mt), 4);
|
||||
#endif
|
||||
|
||||
test_glog();
|
||||
test_easylog();
|
||||
std::cout << "========test sync easylog===========\n";
|
||||
test_easylog("easylog.txt", count, /*async =*/false);
|
||||
std::cout << "========test async easylog===========\n";
|
||||
test_easylog("async_easylog.txt", count, /*async =*/true);
|
||||
}
|
||||
|
|
|
|||
Loading…
Reference in New Issue