Skip to content

Commit

Permalink
optimize latency and code size; upgrade fmtlib to 8.1.0
Browse files Browse the repository at this point in the history
  • Loading branch information
Rao Meng committed Jan 5, 2022
1 parent e2b4546 commit 1d92ad9
Show file tree
Hide file tree
Showing 4 changed files with 93 additions and 100 deletions.
2 changes: 1 addition & 1 deletion bench/spdlog
Submodule spdlog updated 113 files
2 changes: 1 addition & 1 deletion fmt
Submodule fmt updated 68 files
+2 −1 .github/workflows/linux.yml
+10 −5 CMakeLists.txt
+366 −8 ChangeLog.rst
+6 −6 README.rst
+29 −17 doc/api.rst
+3 −1 doc/basic-bootstrap/layout.html
+3 −0 doc/build.py
+15 −14 doc/syntax.rst
+2 −0 include/fmt/args.h
+962 −211 include/fmt/chrono.h
+23 −12 include/fmt/color.h
+14 −11 include/fmt/compile.h
+482 −261 include/fmt/core.h
+280 −263 include/fmt/format-inl.h
+582 −296 include/fmt/format.h
+30 −18 include/fmt/os.h
+31 −77 include/fmt/ostream.h
+12 −7 include/fmt/printf.h
+436 −111 include/fmt/ranges.h
+5 −5 include/fmt/xchar.h
+0 −1 src/fmt.cc
+46 −0 src/format.cc
+9 −8 src/os.cc
+1 −0 support/bazel/.bazelrc
+1 −0 support/bazel/.bazelversion
+29 −0 support/bazel/BUILD.bazel
+73 −0 support/bazel/README.md
+1 −0 support/bazel/WORKSPACE.bazel
+1 −1 support/manage.py
+201 −0 support/printable.py
+26 −29 test/CMakeLists.txt
+24 −11 test/args-test.cc
+279 −39 test/chrono-test.cc
+6 −0 test/color-test.cc
+169 −45 test/compile-error-test/CMakeLists.txt
+62 −0 test/compile-fp-test.cc
+18 −1 test/compile-test.cc
+99 −21 test/core-test.cc
+10 −9 test/enforce-checks-test.cc
+1 −2 test/find-package-test/main.cc
+0 −856 test/format
+7 −10 test/format-impl-test.cc
+223 −155 test/format-test.cc
+1 −1 test/fuzzing/CMakeLists.txt
+5 −3 test/fuzzing/build.sh
+6 −5 test/fuzzing/chrono-duration.cc
+32 −0 test/fuzzing/chrono-timepoint.cc
+5 −5 test/fuzzing/float.cc
+7 −5 test/fuzzing/fuzzer-common.h
+5 −3 test/fuzzing/named-arg.cc
+6 −5 test/fuzzing/one-arg.cc
+2 −1 test/fuzzing/two-args.cc
+3 −4 test/gtest-extra.cc
+7 −1 test/gtest-extra.h
+7 −0 test/gtest/CMakeLists.txt
+4 −0 test/header-only-test.cc
+23 −8 test/module-test.cc
+18 −0 test/noexception-test.cc
+22 −23 test/os-test.cc
+32 −13 test/ostream-test.cc
+0 −26 test/posix-mock-test.cc
+17 −0 test/ranges-odr-test.cc
+101 −2 test/ranges-test.cc
+0 −161 test/std-format-test.cc
+1 −0 test/test-main.cc
+1 −1 test/unicode-test.cc
+6 −2 test/util.h
+78 −3 test/xchar-test.cc
29 changes: 26 additions & 3 deletions fmtlog-inl.h
Original file line number Diff line number Diff line change
Expand Up @@ -227,7 +227,7 @@ class fmtlogDetailT
: tb(buffer) {}

fmtlog::ThreadBuffer* tb;
const fmtlog::SPSCVarQueueOPT<>::MsgHeader* header = nullptr;
const fmtlog::SPSCVarQueueOPT::MsgHeader* header = nullptr;
};
std::vector<HeapNode> bgThreadBuffers;
std::mutex logInfoMutex;
Expand Down Expand Up @@ -343,7 +343,7 @@ class fmtlogDetailT
if (thr.joinable()) thr.join();
}

void handleLog(fmt::string_view threadName, const fmtlog::SPSCVarQueueOPT<>::MsgHeader* header) {
void handleLog(fmt::string_view threadName, const fmtlog::SPSCVarQueueOPT::MsgHeader* header) {
setArgVal<6>(threadName);
StaticLogInfo& info = bgLogInfos[header->logId];
const char* data = (const char*)(header + 1);
Expand Down Expand Up @@ -375,7 +375,7 @@ class fmtlogDetailT
logLevel = (const char*)"DBG INF WRN ERR OFF" + (info.logLevel << 2);

size_t headerPos = membuf.size();
fmt::detail::vformat_to(membuf, headerPattern, fmt::basic_format_args(args.data(), parttenArgSize));
fmtlog::vformat_to(membuf, headerPattern, fmt::basic_format_args(args.data(), parttenArgSize));
size_t bodyPos = membuf.size();

if (info.formatToFn) {
Expand Down Expand Up @@ -492,6 +492,29 @@ void fmtlogT<_>::registerLogInfo(uint32_t& logId, FormatToFn fn, const char* loc
d.logInfos.emplace_back(fn, location, level, fmtString);
}

template<int _>
void fmtlogT<_>::vformat_to(fmtlog::MemoryBuffer& out, fmt::string_view fmt,
fmt::format_args args) {
fmt::detail::vformat_to(out, fmt, args);
}

template<int _>
size_t fmtlogT<_>::formatted_size(fmt::string_view fmt, fmt::format_args args) {
auto buf = fmt::detail::counting_buffer<>();
fmt::detail::vformat_to(buf, fmt, args);
return buf.count();
}

template<int _>
void fmtlogT<_>::vformat_to(char* out, fmt::string_view fmt, fmt::format_args args) {
fmt::vformat_to(out, fmt, args);
}

template<int _>
fmtlogT<_>::SPSCVarQueueOPT::MsgHeader* fmtlogT<_>::SPSCVarQueueOPT::allocMsg(uint32_t size) {
return alloc(size);
}

template<int _>
void fmtlogT<_>::preallocate() {
fmtlogDetailWrapper<>::impl.preallocate();
Expand Down
160 changes: 65 additions & 95 deletions fmtlog.h
Original file line number Diff line number Diff line change
Expand Up @@ -75,6 +75,7 @@ struct UnrefPtr<std::unique_ptr<Arg, D>> : std::true_type
template<typename Arg>
struct UnrefPtr<Arg*> : std::true_type
{ using type = Arg; };

}; // namespace fmtlogdetail

template<int __ = 0>
Expand All @@ -101,8 +102,8 @@ class fmtlogT
// Set the file for logging
static void setLogFile(const char* filename, bool truncate = false);

// Set an existing FILE* for logging, if manageFp is false fmtlog will not buffer log internally and will not close
// the FILE*
// Set an existing FILE* for logging, if manageFp is false fmtlog will not buffer log internally
// and will not close the FILE*
static void setLogFile(FILE* fp, bool manageFp = false);

// Collect log msgs from all threads and write to log file
Expand Down Expand Up @@ -130,7 +131,8 @@ class fmtlogT
// bodyPos: log body index in the msg
// logFilePos: log file position of this msg
typedef void (*LogCBFn)(int64_t ns, LogLevel level, fmt::string_view location, size_t basePos,
fmt::string_view threadName, fmt::string_view msg, size_t bodyPos, size_t logFilePos);
fmt::string_view threadName, fmt::string_view msg, size_t bodyPos,
size_t logFilePos);

// Set a callback function for all log msgs with a mininum log level
static void setLogCB(LogCBFn cb, LogLevel minCBLogLevel);
Expand Down Expand Up @@ -158,54 +160,30 @@ class fmtlogT
// Stop the polling thread
static void stopPollingThread();

private:
fmtlogT() { init(); }

void init() {
if (!inited) {
inited = true;
tscns.init();
currentLogLevel = INF;
}
}

template<int>
friend class fmtlogDetailT;
template<int>
friend struct fmtlogWrapper;
template<typename S, typename... Args>
friend void test(const S& format, Args&&...);

using Context = fmt::format_context;
using MemoryBuffer = fmt::basic_memory_buffer<char, 10000>;
typedef const char* (*FormatToFn)(fmt::string_view format, const char* data, MemoryBuffer& out, int& argIdx,
std::vector<fmt::basic_format_arg<Context>>& args);

static void registerLogInfo(uint32_t& logId, FormatToFn fn, const char* location, LogLevel level,
fmt::string_view fmtString);

// https://github.com/MengRao/SPSC_Queue
template<uint32_t Bytes = 1 << 20>
class SPSCVarQueueOPT
{
public:
struct MsgHeader
{
inline void push(uint32_t sz) { *(volatile uint32_t*)&size = sz + sizeof(MsgHeader); }

uint32_t size;
uint32_t logId;
};
static constexpr uint32_t BLK_CNT = Bytes / sizeof(MsgHeader);
static constexpr uint32_t BLK_CNT = (1 << 20) / sizeof(MsgHeader);

MsgHeader* allocMsg(uint32_t size);

MsgHeader* alloc(uint32_t size_) {
size = size_ + sizeof(MsgHeader);
MsgHeader* alloc(uint32_t size) {
size += sizeof(MsgHeader);
uint32_t blk_sz = (size + sizeof(MsgHeader) - 1) / sizeof(MsgHeader);
if (blk_sz >= free_write_cnt) {
uint32_t read_idx_cache = *(volatile uint32_t*)&read_idx;
if (read_idx_cache <= write_idx) {
free_write_cnt = BLK_CNT - write_idx;
if (blk_sz >= free_write_cnt && read_idx_cache != 0) { // wrap around
blk[0].size = 0;
std::atomic_thread_fence(std::memory_order_release);
blk[write_idx].size = 1;
write_idx = 0;
free_write_cnt = read_idx_cache;
Expand All @@ -218,28 +196,14 @@ class fmtlogT
return nullptr;
}
}
return &blk[write_idx];
}

void push() {
uint32_t blk_sz = (size + sizeof(MsgHeader) - 1) / sizeof(MsgHeader);
blk[write_idx + blk_sz].size = 0;
std::atomic_thread_fence(std::memory_order_release);
blk[write_idx].size = size;
MsgHeader* ret = &blk[write_idx];
write_idx += blk_sz;
free_write_cnt -= blk_sz;
blk[write_idx].size = 0;
return ret;
}

template<typename Writer>
bool tryPush(uint32_t size, Writer writer) {
MsgHeader* header = alloc(size);
if (!header) return false;
writer(header);
push();
return true;
}

const MsgHeader* front() {
inline const MsgHeader* front() {
uint32_t size = blk[read_idx].size;
if (size == 1) { // wrap around
read_idx = 0;
Expand All @@ -249,33 +213,22 @@ class fmtlogT
return &blk[read_idx];
}

void pop() {
inline void pop() {
uint32_t blk_sz = (blk[read_idx].size + sizeof(MsgHeader) - 1) / sizeof(MsgHeader);
*(volatile uint32_t*)&read_idx = read_idx + blk_sz;
}

template<typename Reader>
bool tryPop(Reader reader) {
MsgHeader* header = front();
if (!header) return false;
reader(header);
pop();
return true;
}

private:
alignas(64) MsgHeader blk[BLK_CNT] = {};

alignas(128) uint32_t write_idx = 0;
uint32_t write_idx = 0;
uint32_t free_write_cnt = BLK_CNT;
uint32_t size;

alignas(128) uint32_t read_idx = 0;
};

struct ThreadBuffer
{
SPSCVarQueueOPT<> varq;
SPSCVarQueueOPT varq;
bool shouldDeallocate = false;
char name[32];
size_t nameSize;
Expand All @@ -294,7 +247,8 @@ class fmtlogT
}
else {
#ifdef _WIN32
return calibrate(1000000 * 100); // wait more time as Windows' system time is in 100ns precision
return calibrate(1000000 *
100); // wait more time as Windows' system time is in 100ns precision
#else
return calibrate(1000000 * 10); //
#endif
Expand Down Expand Up @@ -355,18 +309,33 @@ class fmtlogT

void adjustOffset() { ns_offset = base_ns - (int64_t)(base_tsc * tsc_ghz_inv); }

alignas(64) double tsc_ghz_inv; // make sure tsc_ghz_inv and ns_offset are on the same cache line
alignas(64) double tsc_ghz_inv;
int64_t ns_offset;
int64_t base_tsc;
int64_t base_ns;
};

bool inited = false;
void init() {
tscns.init();
currentLogLevel = INF;
}

using Context = fmt::format_context;
using MemoryBuffer = fmt::basic_memory_buffer<char, 10000>;
typedef const char* (*FormatToFn)(fmt::string_view format, const char* data, MemoryBuffer& out,
int& argIdx, std::vector<fmt::basic_format_arg<Context>>& args);

static void registerLogInfo(uint32_t& logId, FormatToFn fn, const char* location, LogLevel level,
fmt::string_view fmtString);

static void vformat_to(MemoryBuffer& out, fmt::string_view fmt, fmt::format_args args);

static size_t formatted_size(fmt::string_view fmt, fmt::format_args args);

static void vformat_to(char* out, fmt::string_view fmt, fmt::format_args args);

public:
TSCNS tscns;

private:
volatile LogLevel currentLogLevel;
static FAST_THREAD_LOCAL ThreadBuffer* threadBuffer;

Expand Down Expand Up @@ -550,8 +519,8 @@ class fmtlogT
}

template<typename... Args>
static const char* formatTo(fmt::string_view format, const char* data, MemoryBuffer& out, int& argIdx,
std::vector<fmt::basic_format_arg<Context>>& args) {
static const char* formatTo(fmt::string_view format, const char* data, MemoryBuffer& out,
int& argIdx, std::vector<fmt::basic_format_arg<Context>>& args) {
constexpr size_t num_args = sizeof...(Args);
constexpr size_t num_dtors = fmt::detail::count<needCallDtor<Args>()...>();
const char* dtor_args[std::max(num_dtors, (size_t)1)];
Expand All @@ -564,7 +533,7 @@ class fmtlogT
else {
ret = decodeArgs<true, 0, 0, Args...>(data, args.data() + argIdx, dtor_args);
}
fmt::detail::vformat_to(out, format, fmt::basic_format_args(args.data() + argIdx, num_args));
vformat_to(out, format, fmt::basic_format_args(args.data() + argIdx, num_args));
destructArgs<0, Args...>(dtor_args);

return ret;
Expand Down Expand Up @@ -642,17 +611,17 @@ class fmtlogT
}
constexpr size_t num_cstring = fmt::detail::count<isCstring<Args>()...>();
size_t cstringSizes[std::max(num_cstring, (size_t)1)];
size_t allocSize = getArgSizes<0>(cstringSizes, args...) + 8;
size_t alloc_size = 8 + getArgSizes<0>(cstringSizes, args...);
if (threadBuffer == nullptr) preallocate();
do {
if (threadBuffer->varq.tryPush(allocSize, [&](typename SPSCVarQueueOPT<>::MsgHeader* header) {
header->logId = logId;
char* writePos = (char*)(header + 1);
*(int64_t*)writePos = tsc;
writePos += 8;
encodeArgs<0>(cstringSizes, writePos, std::forward<Args>(args)...);
}))
return;
auto header = threadBuffer->varq.allocMsg(alloc_size);
if (!header) continue;
header->logId = logId;
char* out = (char*)(header + 1);
*(int64_t*)out = tsc;
out += 8;
encodeArgs<0>(cstringSizes, out, std::forward<Args>(args)...);
header->push(alloc_size);
} while (FMTLOG_BLOCK);
}

Expand All @@ -663,20 +632,21 @@ class fmtlogT
fmt::detail::check_format_string<Args...>(format);
}
fmt::string_view sv(format);
size_t formatted_size = fmt::formatted_size(fmt::runtime(sv), args...);
size_t allocSize = formatted_size + 8 + 8;
auto&& fmt_args = fmt::make_format_args(args...);
size_t fmt_size = formatted_size(sv, fmt_args);
size_t alloc_size = 8 + 8 + fmt_size;
if (threadBuffer == nullptr) preallocate();
do {
if (threadBuffer->varq.tryPush(allocSize, [&](typename SPSCVarQueueOPT<>::MsgHeader* header) {
header->logId = (uint32_t)level;
char* writePos = (char*)(header + 1);
*(int64_t*)writePos = tscns.rdtsc();
writePos += 8;
*(const char**)writePos = location;
writePos += 8;
fmt::format_to(writePos, fmt::runtime(sv), args...);
}))
return;
auto header = threadBuffer->varq.allocMsg(alloc_size);
if (!header) continue;
header->logId = (uint32_t)level;
char* out = (char*)(header + 1);
*(int64_t*)out = tscns.rdtsc();
out += 8;
*(const char**)out = location;
out += 8;
vformat_to(out, sv, fmt_args);
header->push(alloc_size);
} while (FMTLOG_BLOCK);
}
};
Expand Down

0 comments on commit 1d92ad9

Please sign in to comment.