add async logger example

.github/workflows/example.yml

@@ -50,6 +50,12 @@ jobs:
     - uses: actions/checkout@v4
     - run: cd example/use-arena-with-brpc && ./build.sh
 
+  use-async-logger:
+    runs-on: ubuntu-latest
+    steps:
+    - uses: actions/checkout@v4
+    - run: cd example/use-async-logger && ./build.sh
+
   use-counter-with-bvar:
     runs-on: ubuntu-latest
     steps:

README.md

@@ -56,6 +56,7 @@ Babylon也支持使用[CMake](https://cmake.org)进行构建，并支持通过[f
 - [:executor](docs/executor.md)
 - [:future](docs/future.md)
 - [:logging](docs/logging/index.md)
+  - [Use async logger](example/use-async-logger)
 - [:reusable](docs/reusable/index.md)
 - [:serialization](docs/serialization.md)
 - [:time](docs/time.md)

example/use-async-logger/.bazelrc

@@ -0,0 +1,6 @@
+common --registry=https://bcr.bazel.build
+common --registry=https://baidu.github.io/babylon/registry
+common --registry=file:///home/oathdruid/src/babylon/registry
+common --registry=https://raw.githubusercontent.com/bazelboost/registry/main
+
+build --compilation_mode opt --copt=-O3 --cxxopt=-std=c++17

example/use-async-logger/.bazelversion

@@ -0,0 +1 @@
+7.2.1

example/use-async-logger/BUILD

@@ -0,0 +1,10 @@
+cc_binary(
+  name = 'example',
+  srcs = ['example.cpp'],
+  deps = [
+    '@babylon//:logging',
+    '@brpc',
+    '@spdlog',
+    '@tcmalloc//tcmalloc',
+  ],
+)

example/use-async-logger/MODULE.bazel

@@ -0,0 +1,5 @@
+bazel_dep(name = 'babylon', version = '1.3.0')
+bazel_dep(name = 'brpc', version = '1.10.0')
+bazel_dep(name = 'spdlog', version = '1.14.1')
+bazel_dep(name = 'tcmalloc', version = '0.0.0-20240411-5ed309d')
+single_version_override(module_name = 'protobuf', version = '3.19.6')

example/use-async-logger/README.md

@@ -0,0 +1,66 @@
+# Use concurrent counter optimize bvar
+
+## 示例构成
+
+- `:example`: 典型的异步日志初始化样例，同时进行简单的性能演示
+
+## 性能演示
+
+### 单线程低频
+
+- qps: 10000
+- concurrency: 1
+- file: /dev/null
+
+| AMD EPYC 7W83 64-Core Processor | latency               | cpu   |
+|---------------------------------|-----------------------|-------|
+| spdlog                          | [1419,1516,2070,5969] | 0.105 |
+| brpc                            | [1437,1555,2071,6130] | 0.124 |
+| babylon                         | [982,1002,1428,4017]  | 0.065 |
+
+### 单线程吞吐
+
+- concurrency: 1
+- file: /dev/null
+
+| AMD EPYC 7W83 64-Core Processor | max qps | latency             | cpu  |
+|---------------------------------|---------|---------------------|------|
+| spdlog                          | 2.07M   | [458,597,1074,1327] | 1.99 |
+| brpc                            | 0.53M   | [349,363,435,1614]  | 1.21 |
+| babylon                         | 1.58M   | [560,575,892,1401]  | 1.07 |
+
+spdlog和brpc都将全部或部分header格式化拆解到了异步线程执行，『单线程』极限吞吐场景可以通过分拆负载到消费线程提升综合吞吐，其中
+- brpc分拆更极限，可以取得最低的提交延迟，但是相对地消费线程负载过重，极限吞吐量相对较低
+- spdlog分拆相对均衡，可以更充分利用消费者提升单线程整体吞吐
+- babylon的格式化放在了生产端，但是整体使用了性能更好的实现，吞吐相比spdlog有小幅降低，但是单位日志的cpu开销显著节省
+
+### 多线程低频
+
+- qps: 70000
+- concurrency: 7
+- file: /dev/null
+
+| AMD EPYC 7W83 64-Core Processor | latency               | cpu   |
+|---------------------------------|-----------------------|-------|
+| spdlog                          | [1944,2290,4380,9876] | 0.732 |
+| brpc                            | [1706,1941,3582,7986] | 0.818 |
+| babylon                         | [1718,1791,2075,8011] | 0.538 |
+
+### 多线程吞吐
+
+- concurrency: 7
+- file: /dev/null
+
+| AMD EPYC 7W83 64-Core Processor | max qps | latency                     | cpu  |
+|---------------------------------|---------|-----------------------------|------|
+| spdlog                          | 1.41M   | [958,1206,4481,9771]        | 1.92 |
+| spdlog\*                        | 0.41M   | [23405,36043,111814,469699] | 2.63 |
+| brpc                            | 0.56M   | [311,329,436,820]           | 1.16 |
+| brpc\*                          | 0.67M   | [15066,21831,44584,71316]   | 5.56 |
+| babylon                         | 5.58M   | [1225,1268,1508,8881]       | 7.28 |
+
+**\*** 生产端最大速率运行
+spdlog和brpc都将全部或部分header格式化拆解到了异步线程执行，『多线程』极限吞吐相应受限
+- spdlog多线程吞吐低于单线程，主要由于前端竞争提升后反而限制了整体吞吐
+- brpc方案会更快达到消费者瓶颈，打满会降级到前端直接打印文件，但因为会显著增大竞争，对吞吐的提升有限
+- babylon消费端开销很低，即使生产端最大速率运行也可以支持不会产生退化，吞吐能力更高，单位日志cpu消耗也能够保持较低水平

example/use-async-logger/build.sh

@@ -0,0 +1,4 @@
+#!/bin/sh
+set -ex
+
+bazel build example

example/use-async-logger/example.cpp

@@ -0,0 +1,175 @@
+#include "babylon/logging/async_log_stream.h"
+#include "babylon/logging/rolling_file_object.h"
+
+#include "brpc/server.h"
+#include "gflags/gflags.h"
+
+#include "spdlog/async.h"
+#include "spdlog/sinks/basic_file_sink.h"
+#include "spdlog/spdlog.h"
+
+#include <filesystem>
+#include <thread>
+
+DEFINE_int32(dummy_port, 8000, "TCP Port of this dummy server");
+DEFINE_uint64(concurrency, 7, "Concurrent logging thread num");
+DEFINE_string(mode, "babylon", "");
+DEFINE_uint64(qps, 10000, "");
+DEFINE_uint64(batch, 1, "");
+DEFINE_bool(benchmark, true, "");
+DEFINE_uint64(payload, 50, "");
+
+namespace brpc {
+bool IsAskedToQuit();
+}
+
+void setup_babylon() {
+  static ::babylon::RollingFileObject rolling_object;
+  static ::babylon::NewDeletePageAllocator new_delete_allocator;
+  static ::babylon::CachedPageAllocator cached_allocator;
+  static ::babylon::BatchPageAllocator batch_allocator;
+  static ::babylon::AsyncFileAppender appender;
+
+  new_delete_allocator.set_page_size(256);
+  cached_allocator.set_upstream(new_delete_allocator);
+  cached_allocator.set_free_page_capacity(262144);
+  batch_allocator.set_upstream(cached_allocator);
+  batch_allocator.set_batch_size(64);
+
+  appender.set_page_allocator(batch_allocator);
+  appender.set_queue_capacity(262144);
+  appender.initialize();
+
+  rolling_object.set_directory("log");
+  rolling_object.set_file_pattern("name.%Y%m%d-%H%M%S");
+  if (FLAGS_benchmark) {
+    rolling_object.set_directory("/dev");
+    rolling_object.set_file_pattern("null");
+  }
+  rolling_object.scan_and_tracking_existing_files();
+
+  ::babylon::LoggerBuilder builder;
+  builder.set_log_stream_creator(
+      ::babylon::AsyncLogStream::creator(appender, rolling_object));
+  ::babylon::LoggerManager::instance().set_root_builder(::std::move(builder));
+  ::babylon::LoggerManager::instance().apply();
+
+  ::std::thread([&] {
+    while (true) {
+      rolling_object.delete_expire_files();
+      ::usleep(1000 * 1000);
+    }
+  }).detach();
+
+  struct S {
+    static size_t get_pending_size(void*) {
+      return appender.pending_size();
+    }
+    static size_t get_free_page_num(void*) {
+      return cached_allocator.free_page_num();
+    }
+    static ::bvar::Stat get_hit_summary(void*) {
+      auto summary = cached_allocator.cache_hit_summary();
+      return ::bvar::Stat {summary.sum, static_cast<ssize_t>(summary.num)};
+    }
+  };
+  static ::bvar::PassiveStatus<size_t> pending_size {"test-babylon-pending", S::get_pending_size, nullptr};
+  static ::bvar::PassiveStatus<size_t> free_page_num {"test-babylon-free", S::get_free_page_num, nullptr};
+  static ::bvar::PassiveStatus<::bvar::Stat> hit_summary {S::get_hit_summary, nullptr};
+  static ::bvar::Window<::bvar::PassiveStatus<::bvar::Stat>> hit_summary_win {"test-babylon-hit", &hit_summary, -1};
+}
+
+void setup_brpc() {
+  ::std::filesystem::create_directory("log");
+  ::logging::LoggingSettings settings;
+  settings.logging_dest = ::logging::LOG_TO_FILE;
+  settings.delete_old = ::logging::DELETE_OLD_LOG_FILE;
+  settings.log_file = "log/name.log";
+  if (FLAGS_benchmark) {
+    settings.log_file = "/dev/null";
+  }
+  ::logging::InitLogging(settings);
+}
+
+void setup_spdlog() {
+  ::spdlog::set_pattern("%l %Y-%m-%d %H:%M:%S.%f %t %s:%#] %v");
+  ::spdlog::init_thread_pool(262144, 1);
+  auto async_file = ::spdlog::basic_logger_mt<::spdlog::async_factory>("async_file_logger", FLAGS_benchmark ? "/dev/null" : "log/name.log");
+  ::spdlog::set_default_logger(async_file);
+}
+
+::std::string payload;
+
+void run_once_babylon(size_t round) {
+  BABYLON_LOG(INFO) << "round " << round << " payload " << payload;
+}
+
+void run_once_brpc(size_t round) {
+  LOG(INFO) << "round " << round << " payload " << payload;
+}
+
+void run_once_spdlog(size_t round) {
+  SPDLOG_INFO("round {} payload {}", round, payload);
+}
+
+void run_loop() {
+  ::bvar::LatencyRecorder latency {"test-" + FLAGS_mode};
+
+  int64_t expect_us = 1000.0 * 1000 / FLAGS_qps * FLAGS_batch * FLAGS_concurrency;
+
+  void (*run_once)(size_t);
+  if (FLAGS_mode == "babylon") {
+    run_once = run_once_babylon;
+  } else if  (FLAGS_mode == "brpc") {
+    run_once = run_once_brpc;
+  } else if  (FLAGS_mode == "spdlog") {
+    run_once = run_once_spdlog;
+  }
+  ::std::vector<::std::thread> threads;
+  for (size_t i = 0; i < FLAGS_concurrency; ++i) {
+    threads.emplace_back([&] {
+      size_t round = 0;
+      while (!::brpc::IsAskedToQuit()) {
+        auto round_begin = ::butil::cpuwide_time_ns();
+        for (size_t j = 0; j < FLAGS_batch; ++j) {
+          auto begin = ::butil::cpuwide_time_ns();
+          run_once(round);
+          auto end = ::butil::cpuwide_time_ns();
+          latency << (end - begin);
+        }
+        auto round_end = ::butil::cpuwide_time_ns();
+        auto use_us = (round_end - round_begin) / 1000;
+        if (use_us < expect_us) {
+          ::usleep(expect_us - use_us);
+        }
+        round++;
+      }
+    });
+  }
+
+  for (auto& thread : threads) {
+    thread.join();
+  }
+}
+
+int main(int argc, char* argv[]) {
+  ::gflags::ParseCommandLineFlags(&argc, &argv, true);
+
+  payload.resize(FLAGS_payload, 'x');
+
+  ::brpc::StartDummyServerAt(FLAGS_dummy_port);
+
+  ::std::filesystem::remove_all("log");
+  if (FLAGS_mode == "babylon") {
+    setup_babylon();
+    run_loop();
+  } else if (FLAGS_mode == "brpc") {
+    setup_brpc();
+    run_loop();
+  } else if (FLAGS_mode == "spdlog") {
+    setup_spdlog();
+    run_loop();
+  }
+
+  return 0;
+}