Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

it leaks #100

Open
Arniiiii opened this issue Sep 20, 2024 · 10 comments
Open

it leaks #100

Arniiiii opened this issue Sep 20, 2024 · 10 comments

Comments

@Arniiiii
Copy link

Arniiiii commented Sep 20, 2024

It has a memory leak.
I'm using updated (no) version of the lib with updated fmtlib. I believe it's fmtlog issue but I don't have time to investigate it
After logd or any like macro.

image

@Arniiiii
Copy link
Author

tests leak too.

UpdateCTestConfiguration  from :/home/paxu/data/code/experiments/fmtlog_cmake_fix/build/Clang_20.0.0gitfd7d7882_x86_64-pc-linux-gnu/Debug/DartConfiguration.tcl
UpdateCTestConfiguration  from :/home/paxu/data/code/experiments/fmtlog_cmake_fix/build/Clang_20.0.0gitfd7d7882_x86_64-pc-linux-gnu/Debug/DartConfiguration.tcl
Test project /home/paxu/data/code/experiments/fmtlog_cmake_fix/build/Clang_20.0.0gitfd7d7882_x86_64-pc-linux-gnu/Debug
Constructing a list of tests
Done constructing a list of tests
Updating test list for fixtures
Added 0 tests to meet fixture requirements
Checking test dependency graph...
Checking test dependency graph end
test 1
    Start 1: enc_dec_test

1: Test command: /home/paxu/code/experiments/fmtlog_cmake_fix/build/Clang_20.0.0gitfd7d7882_x86_64-pc-linux-gnu/Debug/test/enc_dec_test_Tests
1: Working Directory: /home/paxu/data/code/experiments/fmtlog_cmake_fix/build/Clang_20.0.0gitfd7d7882_x86_64-pc-linux-gnu/Debug/test
1: Test timeout computed to be: 10000000
1:
1: =================================================================
1: ==221008==ERROR: LeakSanitizer: detected memory leaks
1:
1: Direct leak of 79 byte(s) in 1 object(s) allocated from:
1:     #0 0x563c9483dd51 in operator new[](unsigned long) /var/tmp/portage/sys-libs/compiler-rt-sanitizers-20.0.0_pre20240917/work/compiler-rt/lib/asan/asan_new_delete.cpp:89:3
1:     #1 0x563c948da906 in fmt::v11::basic_string_view<char> fmtlogT<0>::unNameFormat<false, double, fmt::v11::detail::named_arg<char, int>, fmt::v11::detail::named_arg<char, char const (&) [4]>, fmt::v11::detail::named_arg<char, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char>>>, fmt::v11::detail::named_arg<char, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char>>>>(fmt::v11::basic_string_view<char>, unsigned int*, double const&, fmt::v11::detail::named_arg<char, int> const&, fmt::v11::detail::named_arg<char, char const (&) [4]> const&, fmt::v11::detail::named_arg<char, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char>>> const&, fmt::v11::detail::named_arg<char, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char>>> const&) /home/paxu/code/experiments/fmtlog_cmake_fix/include/fmtlog/fmtlog.h:620:41
1:     #2 0x563c9484ba78 in void test<char [59], double, fmt::v11::detail::named_arg<char, int>, fmt::v11::detail::named_arg<char, char const (&) [4]>, fmt::v11::detail::named_arg<char, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char>>>, fmt::v11::detail::named_arg<char, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char>>>>(char const (&) [59], double&&, fmt::v11::detail::named_arg<char, int>&&, fmt::v11::detail::named_arg<char, char const (&) [4]>&&, fmt::v11::detail::named_arg<char, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char>>>&&, fmt::v11::detail::named_arg<char, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char>>>&&) /home/paxu/code/experiments/fmtlog_cmake_fix/test/src/enc_dec_test.cc:59:25
1:     #3 0x563c94840b22 in main /home/paxu/code/experiments/fmtlog_cmake_fix/test/src/enc_dec_test.cc:96:3
1:     #4 0x7f7d0d82a44f in __libc_start_call_main /usr/src/debug/sys-libs/glibc-2.39-r6/glibc-2.39/csu/../sysdeps/nptl/libc_start_call_main.h:58:16
1:
1: SUMMARY: AddressSanitizer: 79 byte(s) leaked in 1 allocation(s).
1/3 Test #1: enc_dec_test .....................***Failed    0.05 sec
test 2
    Start 2: log_test

2: Test command: /home/paxu/code/experiments/fmtlog_cmake_fix/build/Clang_20.0.0gitfd7d7882_x86_64-pc-linux-gnu/Debug/test/log_test_Tests
2: Working Directory: /home/paxu/data/code/experiments/fmtlog_cmake_fix/build/Clang_20.0.0gitfd7d7882_x86_64-pc-linux-gnu/Debug/test
2: Test timeout computed to be: 10000000
2: 04:11:06.477170 log_test.cc:22   INF[221046] A string, pointer, number, and float: 'Hello World', 0x7ba3db6de020, 512, 3.14159
2: 04:11:06.477686 log_test.cc:27   INF[221046] void ptr: 0x7ba3db6de0b0, ptr: 7, sptr: 8, uptr: 6
2: 04:11:06.477689 log_test.cc:34   INF[221046] str: aaa, pstr: bbb, strarr: 111, pstrarr: 222, cstr: 111, pcstr: 222
2: 04:11:06.477694 log_test.cc:44   DBG[221046] Now debug msg is shown
2: 04:11:06.477798 log_test.cc:49   INF[main  ] log once: 0
2: 04:11:06.477803 log_test.cc:49   INF[main  ] log once: 1
2: 04:11:06.477805 log_test.cc:49   INF[main  ] log once: 2
2: 04:11:06.477807 log_test.cc:53   INF[main  ] Thread name changed
2: 2024-09-21 04:11:06.477856185 log_test.cc:58 INF[main] Header pattern is changed, full date time info is shown
2: 2024-09-21 04:11:06.477862890 log_test.cc:63 INF[main] This msg will be logged at an interval of at least 10 ns: 0.
2: 2024-09-21 04:11:06.477863477 log_test.cc:63 INF[main] This msg will be logged at an interval of at least 10 ns: 1.
2: 2024-09-21 04:11:06.477863571 log_test.cc:63 INF[main] This msg will be logged at an interval of at least 10 ns: 2.
2: 2024-09-21 04:11:06.477863639 log_test.cc:63 INF[main] This msg will be logged at an interval of at least 10 ns: 3.
2: 2024-09-21 04:11:06.477863717 log_test.cc:63 INF[main] This msg will be logged at an interval of at least 10 ns: 4.
2: 2024-09-21 04:11:06.477863785 log_test.cc:63 INF[main] This msg will be logged at an interval of at least 10 ns: 5.
2: 2024-09-21 04:11:06.477863855 log_test.cc:63 INF[main] This msg will be logged at an interval of at least 10 ns: 6.
2: 2024-09-21 04:11:06.477863924 log_test.cc:63 INF[main] This msg will be logged at an interval of at least 10 ns: 7.
2: 2024-09-21 04:11:06.477863987 log_test.cc:63 INF[main] This msg will be logged at an interval of at least 10 ns: 8.
2: 2024-09-21 04:11:06.477864043 log_test.cc:63 INF[main] This msg will be logged at an interval of at least 10 ns: 9.
2:
2: =================================================================
2: ==221046==ERROR: LeakSanitizer: detected memory leaks
2:
2: Direct leak of 1048960 byte(s) in 1 object(s) allocated from:
2:     #0 0x555cbf718056 in operator new(unsigned long, std::align_val_t) /var/tmp/portage/sys-libs/compiler-rt-sanitizers-20.0.0_pre20240917/work/compiler-rt/lib/asan/asan_new_delete.cpp:98:3
2:     #1 0x555cbf71c25d in fmtlogDetailT<0>::preallocate() /home/paxu/code/experiments/fmtlog_cmake_fix/include/fmtlog/fmtlog-inl.h:290:28
2:     #2 0x555cbf71c0b7 in fmtlogT<0>::preallocate() /home/paxu/code/experiments/fmtlog_cmake_fix/include/fmtlog/fmtlog-inl.h:541:31
2:     #3 0x555cbf7248da in fmtlogT<0>::allocMsg(unsigned int, bool) /home/paxu/code/experiments/fmtlog_cmake_fix/include/fmtlog/fmtlog-inl.h:527:32
2:     #4 0x555cbf7257e7 in void fmtlogT<0>::log<char (&) [12], void*, int, double>(unsigned int&, long, char const*, fmtlogT<0>::LogLevel, fmt::v11::basic_format_string<char, fmt::v11::type_identity<fmtlogdetail::UnrefPtr<std::remove_cv<std::remove_reference<char (&) [12]>::type>::type>::type>::type, fmt::v11::type_identity<fmtlogdetail::UnrefPtr<std::remove_cv<std::remove_reference<void*>::type>::type>::type>::type, fmt::v11::type_identity<fmtlogdetail::UnrefPtr<std::remove_cv<std::remove_reference<int>::type>::type>::type>::type, fmt::v11::type_identity<fmtlogdetail::UnrefPtr<std::remove_cv<std::remove_reference<double>::type>::type>::type>::type>, char (&) [12], void*&&, int&&, double&&) /home/paxu/code/experiments/fmtlog_cmake_fix/include/fmtlog/fmtlog.h:685:25
2:     #5 0x555cbf71aaef in main /home/paxu/code/experiments/fmtlog_cmake_fix/test/src/log_test.cc:21:3
2:     #6 0x7fa3dd02a44f in __libc_start_call_main /usr/src/debug/sys-libs/glibc-2.39-r6/glibc-2.39/csu/../sysdeps/nptl/libc_start_call_main.h:58:16
2:
2: SUMMARY: AddressSanitizer: 1048960 byte(s) leaked in 1 allocation(s).
2/3 Test #2: log_test .........................***Failed    0.07 sec
test 3
    Start 3: multithread_test

3: Test command: /home/paxu/code/experiments/fmtlog_cmake_fix/build/Clang_20.0.0gitfd7d7882_x86_64-pc-linux-gnu/Debug/test/multithread_test_Tests
3: Working Directory: /home/paxu/data/code/experiments/fmtlog_cmake_fix/build/Clang_20.0.0gitfd7d7882_x86_64-pc-linux-gnu/Debug/test
3: Test timeout computed to be: 10000000
3: total msg_cnt: 196570, cb_size: 13715460, throughput: 12.8 MB/second, 184057.2113596684 msg/sec
3/3 Test #3: multithread_test .................   Passed    1.10 sec

33% tests passed, 2 tests failed out of 3

Total Test time (real) =   1.22 sec

The following tests FAILED:
          1 - enc_dec_test (Failed)
          2 - log_test (Failed)
Errors while running CTest
Output from these tests are in: /home/paxu/data/code/experiments/fmtlog_cmake_fix/build/Clang_20.0.0gitfd7d7882_x86_64-pc-linux-gnu/Debug/Testing/Temporary/LastTest.log
Use "--rerun-failed --output-on-failure" to re-run the failed cases verbosely.

@Arniiiii
Copy link
Author

it fails with fmtlib 11.0.2 , 10.2.1 and 9.1.0 . It seems to be definitely fmtlog's problem.

@Arniiiii
Copy link
Author

Arniiiii commented Sep 21, 2024

It seems that in unNameFormat there's strange problem:

  1. Creating a char* unnamed_str at heap via std::unique_ptr
  2. Using it somehow to calc char* out
  3. Getting raw char* ptr via releasing from unique_ptr
  4. Return string_view(ptr, out - ptr)
  5. Leaked memory between out and end of ptr

So, at least here's two no-no:

  1. Returning std::string_view that expected to have own lifetime (but it's not, since it's std::string_view)
  2. pointer arithmetic

I'll try change the std::string_view to std::string.

@Arniiiii
Copy link
Author

Just fucking nice: one place fixed, got one test fixed and other tests leak in some other places. I'm loving it (no)

@Arniiiii
Copy link
Author

just... why ... why it's in C's char pointer and not it std::string or any like

@Arniiiii
Copy link
Author

Arniiiii commented Sep 21, 2024

Just amazing: solved another leak via converting a lot of dangling fmt::string_view to std::string...
And got another one...

Creating thread buffer in heap and then saving pointer in std::vector<type *> ...... clear does not work if the type don't have appropriate destructor...

@MengRao
Copy link
Owner

MengRao commented Sep 29, 2024

Memory management in fmtlog is a little bit tricky, which may trigger false alarm by sanitizers, so don't care too much about it.

@Arniiiii
Copy link
Author

Arniiiii commented Sep 29, 2024

Memory management in fmtlog is a little bit tricky, which may trigger false alarm by sanitizers, so don't care too much about it.

IDK , I solved them somehow, but now fmtlog requires fmtlog::poll() in any case. I believe it's because I've done something wrong with 3rd fix: there was a thread that wasn't destructed though it had state "ShouldBeDestroyed == true` or something like that

@GitSparTV
Copy link

Thinking leak sanitizer would not understand library logic and trigger a false positive is a bold statement.

Same leak on valgrind:

==504172== LEAK SUMMARY:
==504172==    definitely lost: 79 bytes in 1 blocks
==504172==    indirectly lost: 0 bytes in 0 blocks
==504172==      possibly lost: 0 bytes in 0 blocks
==504172==    still reachable: 153 bytes in 1 blocks
==504172==         suppressed: 0 bytes in 0 blocks

log_test:

==504307==    definitely lost: 1,048,960 bytes in 1 blocks
==504307==    indirectly lost: 0 bytes in 0 blocks
==504307==      possibly lost: 0 bytes in 0 blocks
==504307==    still reachable: 149 bytes in 1 blocks
==504307==         suppressed: 0 bytes in 0 blocks

Who want a 1MB leak in their app?

Anyway, here is my attempt to at least fix the leaks. I saw there was some logic to clean everything up, but it doesn't always work.

diff --git a/fmt b/fmt
--- a/fmt
+++ b/fmt
@@ -1 +1 @@
-Subproject commit e69e5f977d458f2650bb346dadf2ad30c5320281
+Subproject commit e69e5f977d458f2650bb346dadf2ad30c5320281-dirty
diff --git a/fmtlog-inl.h b/fmtlog-inl.h
index f02cab6..bc8dadd 100644
--- a/fmtlog-inl.h
+++ b/fmtlog-inl.h
@@ -103,10 +103,10 @@ public:
     setHeaderPattern("{HMSf} {s:<16} {l}[{t:<6}] ");
     logInfos.reserve(32);
     bgLogInfos.reserve(128);
-    bgLogInfos.emplace_back(nullptr, nullptr, fmtlog::DBG, fmt::string_view());
-    bgLogInfos.emplace_back(nullptr, nullptr, fmtlog::INF, fmt::string_view());
-    bgLogInfos.emplace_back(nullptr, nullptr, fmtlog::WRN, fmt::string_view());
-    bgLogInfos.emplace_back(nullptr, nullptr, fmtlog::ERR, fmt::string_view());
+    bgLogInfos.emplace_back(nullptr, nullptr, fmtlog::DBG, std::string{});
+    bgLogInfos.emplace_back(nullptr, nullptr, fmtlog::INF, std::string{});
+    bgLogInfos.emplace_back(nullptr, nullptr, fmtlog::WRN, std::string{});
+    bgLogInfos.emplace_back(nullptr, nullptr, fmtlog::ERR, std::string{});
     threadBuffers.reserve(8);
     bgThreadBuffers.reserve(8);
     memset(membuf.data(), 0, membuf.capacity());
@@ -119,7 +119,6 @@ public:
   }
 
   void setHeaderPattern(const char* pattern) {
-    if (shouldDeallocateHeader) delete[] headerPattern.data();
     using namespace fmt::literals;
     for (int i = 0; i < parttenArgSize; i++) {
       reorderIdx[i] = parttenArgSize - 1;
@@ -130,7 +129,6 @@ public:
       "l"_a = fmtlog::LogLevel(), "s"_a = "fmtlog.cc:123", "g"_a = "/home/raomeng/fmtlog/fmtlog.cc:123", "Ymd"_a = "",
       "HMS"_a = "", "HMSe"_a = "", "HMSf"_a = "", "HMSF"_a = "", "YmdHMS"_a = "", "YmdHMSe"_a = "", "YmdHMSf"_a = "",
       "YmdHMSF"_a = "");
-    shouldDeallocateHeader = headerPattern.data() != pattern;
 
     setArg<0>(fmt::string_view(weekdayName.s, 3));
     setArg<1>(fmt::string_view(monthName.s, 3));
@@ -177,7 +175,7 @@ public:
   struct StaticLogInfo
   {
     // Constructor
-    constexpr StaticLogInfo(fmtlog::FormatToFn fn, const char* loc, fmtlog::LogLevel level, fmt::string_view fmtString)
+    StaticLogInfo(fmtlog::FormatToFn fn, const char* loc, fmtlog::LogLevel level, std::string fmtString)
       : formatToFn(fn)
       , formatString(fmtString)
       , location(loc)
@@ -207,7 +205,7 @@ public:
     inline fmt::string_view getLocation() { return fmt::string_view(location, endPos); }
 
     fmtlog::FormatToFn formatToFn;
-    fmt::string_view formatString;
+    std::string formatString;
     const char* location;
     uint8_t basePos;
     uint8_t endPos;
@@ -217,8 +215,7 @@ public:
 
   static thread_local ThreadBufferDestroyer sbc;
   int64_t midnightNs;
-  fmt::string_view headerPattern;
-  bool shouldDeallocateHeader = false;
+  std::string headerPattern;
   FILE* outputFp = nullptr;
   bool manageFp = false;
   size_t fpos = 0; // file position of membuf, used only when manageFp == true
@@ -227,13 +224,13 @@ public:
   uint32_t flushBufSize = 8 * 1024;
   fmtlog::LogLevel flushLogLevel = fmtlog::OFF;
   std::mutex bufferMutex;
-  std::vector<fmtlog::ThreadBuffer*> threadBuffers;
+  std::vector<std::shared_ptr<fmtlog::ThreadBuffer>> threadBuffers;
   struct HeapNode
   {
-    HeapNode(fmtlog::ThreadBuffer* buffer)
-      : tb(buffer) {}
+    HeapNode(std::shared_ptr<fmtlog::ThreadBuffer> buffer)
+      : tb(std::move(buffer)) {}
 
-    fmtlog::ThreadBuffer* tb;
+    std::shared_ptr<fmtlog::ThreadBuffer> tb;
     const fmtlog::SPSCVarQueueOPT::MsgHeader* header = nullptr;
   };
   std::vector<HeapNode> bgThreadBuffers;
@@ -287,7 +284,7 @@ public:
 
   void preallocate() {
     if (fmtlog::threadBuffer) return;
-    fmtlog::threadBuffer = new fmtlog::ThreadBuffer();
+    fmtlog::threadBuffer = std::make_shared<fmtlog::ThreadBuffer>();
 #ifdef _WIN32
     uint32_t tid = static_cast<uint32_t>(::GetCurrentThreadId());
 #else
@@ -443,7 +440,6 @@ public:
       if (node.header) continue;
       node.header = node.tb->varq.front();
       if (!node.header && node.tb->shouldDeallocate) {
-        delete node.tb;
         node = bgThreadBuffers.back();
         bgThreadBuffers.pop_back();
         i--;
@@ -494,7 +490,7 @@ fmtlogDetailT<> fmtlogDetailWrapper<_>::impl;
 
 template<int _>
 void fmtlogT<_>::registerLogInfo(uint32_t& logId, FormatToFn fn, const char* location,
-                                 LogLevel level, fmt::string_view fmtString) noexcept {
+                                 LogLevel level, std::string fmtString) noexcept {
   auto& d = fmtlogDetailWrapper<>::impl;
   std::lock_guard<std::mutex> lock(d.logInfoMutex);
   if (logId) return;
diff --git a/fmtlog.h b/fmtlog.h
index 566b34f..0061ec4 100644
--- a/fmtlog.h
+++ b/fmtlog.h
@@ -38,7 +38,7 @@ SOFTWARE.
 #ifdef _WIN32
 #define FAST_THREAD_LOCAL thread_local
 #else
-#define FAST_THREAD_LOCAL __thread
+#define FAST_THREAD_LOCAL thread_local
 #endif
 
 // define FMTLOG_BLOCK=1 if log statment should be blocked when queue is full, instead of discarding the msg
@@ -378,7 +378,7 @@ public:
                                     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) noexcept;
+                              std::string fmtString) noexcept;
 
   static void vformat_to(MemoryBuffer& out, fmt::string_view fmt, fmt::format_args args);
 
@@ -391,7 +391,7 @@ public:
   TSCNS tscns;
 
   volatile LogLevel currentLogLevel;
-  static FAST_THREAD_LOCAL ThreadBuffer* threadBuffer;
+  static FAST_THREAD_LOCAL std::shared_ptr<ThreadBuffer> threadBuffer;
 
   template<typename Arg>
   static inline constexpr bool isNamedArg() {
@@ -609,19 +609,19 @@ public:
   }
 
   template<bool Reorder, typename... Args>
-  static fmt::string_view unNameFormat(fmt::string_view in, uint32_t* reorderIdx,
+  static std::string unNameFormat(fmt::string_view in, uint32_t* reorderIdx,
                                        const Args&... args) {
     constexpr size_t num_named_args = fmt::detail::count<isNamedArg<Args>()...>();
     if constexpr (num_named_args == 0) {
-      return in;
+      return std::string{in.data(), in.size()}; // :(
     }
     const char* begin = in.data();
     const char* p = begin;
-    std::unique_ptr<char[]> unnamed_str(new char[in.size() + 1 + num_named_args * 5]);
+    std::string unnamed_str(in.size() + 1 + num_named_args * 5, '\0');
     fmt::detail::named_arg_info<char> named_args[std::max(num_named_args, (size_t)1)];
     storeNamedArgs<0, 0>(named_args, args...);
 
-    char* out = (char*)unnamed_str.get();
+    char* out = unnamed_str.data();
     uint8_t arg_idx = 0;
     while (true) {
       auto c = *p++;
@@ -663,8 +663,10 @@ public:
       }
       begin = p;
     }
-    const char* ptr = unnamed_str.release();
-    return fmt::string_view(ptr, out - ptr);
+
+    unnamed_str.resize(out - unnamed_str.data());
+
+    return unnamed_str;
   }
 
 public:
@@ -723,7 +725,7 @@ public:
 using fmtlog = fmtlogT<>;
 
 template<int _>
-FAST_THREAD_LOCAL typename fmtlogT<_>::ThreadBuffer* fmtlogT<_>::threadBuffer;
+FAST_THREAD_LOCAL typename std::shared_ptr<typename fmtlogT<_>::ThreadBuffer> fmtlogT<_>::threadBuffer;
 
 template<int __ = 0>
 struct fmtlogWrapper

@GitSparTV
Copy link

And I don't know what to say about ThreadSanitizer: reported 10 warnings

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants