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

Ensure flush callback gets called in move-assign operator #3232

Merged
merged 1 commit into from
Oct 30, 2024

Conversation

Oipo
Copy link
Contributor

@Oipo Oipo commented Oct 28, 2024

While this change makes the condition_variable more reliable, without the 100 ms loop results in spdlog-utests getting stuck sometimes. With the wait_for loop, the multithreaded flush test, which inserts 10240 messages of which most get overridden, continues to work.

@gabime
Copy link
Owner

gabime commented Oct 28, 2024

When using async with discard policy, slots get overrun using move assignments when the queue is full rather than destructed.. So, like I mentioned, the dtor won’t be called, and the loop may be stuck forever.

@Oipo
Copy link
Contributor Author

Oipo commented Oct 29, 2024

That's not how move assignment/constructors work.

To be able to move at all, one needs two objects: the moved-from and moved-to. The move assignment/constructor then (usually) moves variables between members, but doesn't change the fact that there are two objects and thus two destructor calls.

Please take a look at this godbolt example, which showcases how many destructor calls happen with move assignments.

Perhaps you're confusing moves with placement new? Placement new does indeed not call destructors, but as far as I can see, spdlog does not use placement new.

@gabime
Copy link
Owner

gabime commented Oct 30, 2024

I meant that the destruction of the items in the queue aren't called when overrun happens, so I guess this is the purpose of the swap in this PR - to call the callback of the overrun item in the destructor inside post_and_wait_for_flush()

Anyway, seems to get stuck. See the following example. After few runs it get stuck forever as one of the threads won't join:

#include <chrono>
#include "spdlog/spdlog.h"
#include "spdlog/async.h"
#include "spdlog/../../tests/test_sink.h"

int main(int, char *[]) {
    const size_t queue_size = 100;
    const int n_threads = 8;

    auto thread_pool = std::make_shared<spdlog::details::thread_pool>(queue_size, 1);
    auto test_sink = std::make_shared<spdlog::sinks::test_sink_mt>();
    test_sink->set_delay(std::chrono::milliseconds(2));
    test_sink->set_level(spdlog::level::trace);
    auto logger = std::make_shared<spdlog::async_logger>(
        "as", test_sink, thread_pool, spdlog::async_overflow_policy::overrun_oldest);
    logger->set_level(spdlog::level::trace);

    std::vector<std::thread> threads;
    std::atomic<int> started_threads(0);;
    std::atomic<int> done_threads(0);;
    for (int i = 0; i < n_threads; i++) {
        threads.emplace_back([&] {
            started_threads++;
            fmt::print("Thread {}/{} started\n", started_threads.load(), n_threads);
            for(int iter=0; iter < 10; iter++) {
                for (int j = 1; j < queue_size ; ++j) {
                    logger->info("Async message #{}", j);
                }
                logger->flush();
            }
            printf("Thread %d/%d done\n", ++done_threads, n_threads);
        });
    };
    // join the threads
    for (auto &t : threads) {
        t.join();
    }

    printf("Done all threads\n");
}

@Oipo
Copy link
Contributor Author

Oipo commented Oct 30, 2024

I meant that the destruction of the items in the queue aren't called when overrun happens, so I guess this is the purpose of the swap in this PR - to call the callback of the overrun item in the destructor inside post_and_wait_for_flush()

Ah gotcha. Yes, that is why the swap is needed.

Anyway, seems to get stuck. See the following example. After few runs it get stuck forever as one of the threads won't join:

I can reproduce the getting stuck locally. I also get the stuck behaviour on commit ee16895, the one before my changes were merged. I'm not surprised, as std::promise and std::future use some of the same mechanisms as my changes under the hood. It's good to see I didn't introduce any worse behaviour, other than the missed std::swap. Though still undesirable.

As for why, I'm not entirely sure. When running the thread sanitizer, I get data races on the cv being potentially destroyed before calling notify_all. Removing that call and forcing the 100 ms to always have to happen still results in hangs and thread sanitizer reporting data races. I'm not sure if they're false positive though as they happen in a completely different part of the code. It kind of seems like it's just a re-use of stack memory being reported here.

WARNING: ThreadSanitizer: data race (pid=26467)
  Write of size 8 at 0x7f3cac1ff288 by thread T6:
    #0 spdlog::details::log_msg::log_msg(std::chrono::time_point<std::chrono::_V2::system_clock, std::chrono::duration<long, std::ratio<1l, 1000000000l> > >, spdlog::source_loc, fmt::v10::basic_string_view<char>, spdlog::level::level_enum, fmt::v10::basic_string_view<char>) ../include/spdlog/details/log_msg-inl.h:29 (a.out+0x439f5b)
    #1 spdlog::details::log_msg::log_msg(spdlog::source_loc, fmt::v10::basic_string_view<char>, spdlog::level::level_enum, fmt::v10::basic_string_view<char>) ../include/spdlog/details/log_msg-inl.h:36 (a.out+0x439f5b)
    #2 void spdlog::logger::log_<int&>(spdlog::source_loc, spdlog::level::level_enum, fmt::v10::basic_string_view<char>, int&) ../include/spdlog/logger.h:331 (a.out+0x439f5b)
    #3 void spdlog::logger::log<int&>(spdlog::source_loc, spdlog::level::level_enum, fmt::v10::basic_format_string<char, fmt::v10::type_identity<int&>::type>, int&) ../include/spdlog/logger.h:80 (a.out+0x406fad)
    #4 void spdlog::logger::log<int&>(spdlog::level::level_enum, fmt::v10::basic_format_string<char, fmt::v10::type_identity<int&>::type>, int&) ../include/spdlog/logger.h:85 (a.out+0x406fad)
    #5 void spdlog::logger::info<int&>(fmt::v10::basic_format_string<char, fmt::v10::type_identity<int&>::type>, int&) ../include/spdlog/logger.h:140 (a.out+0x406fad)
    #6 operator() /home/oipo/Programming/spdlog/build/test.cpp:29 (a.out+0x406fad)
    #7 __invoke_impl<void, main(int, char**)::<lambda()> > /opt/gcc/14/include/c++/14.2.0/bits/invoke.h:61 (a.out+0x406fad)
    #8 __invoke<main(int, char**)::<lambda()> > /opt/gcc/14/include/c++/14.2.0/bits/invoke.h:96 (a.out+0x406fad)
    #9 _M_invoke<0> /opt/gcc/14/include/c++/14.2.0/bits/std_thread.h:301 (a.out+0x406fad)
    #10 operator() /opt/gcc/14/include/c++/14.2.0/bits/std_thread.h:308 (a.out+0x406fad)
    #11 _M_run /opt/gcc/14/include/c++/14.2.0/bits/std_thread.h:253 (a.out+0x406fad)
    #12 execute_native_thread_routine ../../../../../gcc-14.2.0/libstdc++-v3/src/c++11/thread.cc:104 (libstdc++.so.6+0xedda3)

  Previous atomic write of size 4 at 0x7f3cac1ff288 by thread T1:
    #0 std::atomic<spdlog::details::async_msg_flush>::store(spdlog::details::async_msg_flush, std::memory_order) /opt/gcc/14/include/c++/14.2.0/atomic:284 (a.out+0x4088b6)
    #1 spdlog::details::thread_pool::post_and_wait_for_flush(std::shared_ptr<spdlog::async_logger>&&, spdlog::async_overflow_policy)::{lambda(spdlog::details::async_msg_flush)#1}::operator()(spdlog::details::async_msg_flush) const ../include/spdlog/details/thread_pool-inl.h:72 (a.out+0x4088b6)
    #2 void std::__invoke_impl<void, spdlog::details::thread_pool::post_and_wait_for_flush(std::shared_ptr<spdlog::async_logger>&&, spdlog::async_overflow_policy)::{lambda(spdlog::details::async_msg_flush)#1}&, spdlog::details::async_msg_flush>(std::__invoke_other, spdlog::details::thread_pool::post_and_wait_for_flush(std::shared_ptr<spdlog::async_logger>&&, spdlog::async_overflow_policy)::{lambda(spdlog::details::async_msg_flush)#1}&, spdlog::details::async_msg_flush&&) /opt/gcc/14/include/c++/14.2.0/bits/invoke.h:61 (a.out+0x4088b6)
    #3 std::enable_if<is_invocable_r_v<void, spdlog::details::thread_pool::post_and_wait_for_flush(std::shared_ptr<spdlog::async_logger>&&, spdlog::async_overflow_policy)::{lambda(spdlog::details::async_msg_flush)#1}&, spdlog::details::async_msg_flush>, void>::type std::__invoke_r<void, spdlog::details::thread_pool::post_and_wait_for_flush(std::shared_ptr<spdlog::async_logger>&&, spdlog::async_overflow_policy)::{lambda(spdlog::details::async_msg_flush)#1}&, spdlog::details::async_msg_flush>(spdlog::details::thread_pool::post_and_wait_for_flush(std::shared_ptr<spdlog::async_logger>&&, spdlog::async_overflow_policy)::{lambda(spdlog::details::async_msg_flush)#1}&, spdlog::details::async_msg_flush&&) /opt/gcc/14/include/c++/14.2.0/bits/invoke.h:111 (a.out+0x4088b6)
    #4 std::_Function_handler<void (spdlog::details::async_msg_flush), spdlog::details::thread_pool::post_and_wait_for_flush(std::shared_ptr<spdlog::async_logger>&&, spdlog::async_overflow_policy)::{lambda(spdlog::details::async_msg_flush)#1}>::_M_invoke(std::_Any_data const&, spdlog::details::async_msg_flush&&) /opt/gcc/14/include/c++/14.2.0/bits/std_function.h:290 (a.out+0x4088b6)
    #5 std::function<void (spdlog::details::async_msg_flush)>::operator()(spdlog::details::async_msg_flush) const /opt/gcc/14/include/c++/14.2.0/bits/std_function.h:591 (a.out+0x43885f)
    #6 spdlog::details::thread_pool::process_next_msg_() ../include/spdlog/details/thread_pool-inl.h:128 (a.out+0x43885f)
    #7 spdlog::details::thread_pool::worker_loop_() ../include/spdlog/details/thread_pool-inl.h:109 (a.out+0x438ac7)
    #8 spdlog::details::thread_pool::thread_pool(unsigned long, unsigned long, std::function<void ()>, std::function<void ()>)::{lambda()#1}::operator()() const ../include/spdlog/details/thread_pool-inl.h:29 (a.out+0x438ac7)
    #9 void std::__invoke_impl<void, spdlog::details::thread_pool::thread_pool(unsigned long, unsigned long, std::function<void ()>, std::function<void ()>)::{lambda()#1}>(std::__invoke_other, spdlog::details::thread_pool::thread_pool(unsigned long, unsigned long, std::function<void ()>, std::function<void ()>)::{lambda()#1}&&) /opt/gcc/14/include/c++/14.2.0/bits/invoke.h:61 (a.out+0x438ac7)
    #10 std::__invoke_result<spdlog::details::thread_pool::thread_pool(unsigned long, unsigned long, std::function<void ()>, std::function<void ()>)::{lambda()#1}>::type std::__invoke<spdlog::details::thread_pool::thread_pool(unsigned long, unsigned long, std::function<void ()>, std::function<void ()>)::{lambda()#1}>(spdlog::details::thread_pool::thread_pool(unsigned long, unsigned long, std::function<void ()>, std::function<void ()>)::{lambda()#1}&&) /opt/gcc/14/include/c++/14.2.0/bits/invoke.h:96 (a.out+0x438ac7)
    #11 void std::thread::_Invoker<std::tuple<spdlog::details::thread_pool::thread_pool(unsigned long, unsigned long, std::function<void ()>, std::function<void ()>)::{lambda()#1}> >::_M_invoke<0ul>(std::_Index_tuple<0ul>) /opt/gcc/14/include/c++/14.2.0/bits/std_thread.h:301 (a.out+0x438ac7)
    #12 std::thread::_Invoker<std::tuple<spdlog::details::thread_pool::thread_pool(unsigned long, unsigned long, std::function<void ()>, std::function<void ()>)::{lambda()#1}> >::operator()() /opt/gcc/14/include/c++/14.2.0/bits/std_thread.h:308 (a.out+0x438ac7)
    #13 std::thread::_State_impl<std::thread::_Invoker<std::tuple<spdlog::details::thread_pool::thread_pool(unsigned long, unsigned long, std::function<void ()>, std::function<void ()>)::{lambda()#1}> > >::_M_run() /opt/gcc/14/include/c++/14.2.0/bits/std_thread.h:253 (a.out+0x438ac7)
    #14 execute_native_thread_routine ../../../../../gcc-14.2.0/libstdc++-v3/src/c++11/thread.cc:104 (libstdc++.so.6+0xedda3)

  Location is stack of thread T6.

  Thread T6 (tid=26474, running) created by main thread at:
    #0 pthread_create ../../../../gcc-14.2.0/libsanitizer/tsan/tsan_interceptors_posix.cpp:1022 (libtsan.so.2+0x5f4e6)
    #1 __gthread_create /home/oipo/Programming/gcc-build/x86_64-pc-linux-gnu/libstdc++-v3/include/x86_64-pc-linux-gnu/bits/gthr-default.h:676 (libstdc++.so.6+0xede78)
    #2 std::thread::_M_start_thread(std::unique_ptr<std::thread::_State, std::default_delete<std::thread::_State> >, void (*)()) ../../../../../gcc-14.2.0/libstdc++-v3/src/c++11/thread.cc:172 (libstdc++.so.6+0xede78)
    #3 __libc_start_call_main ../sysdeps/nptl/libc_start_call_main.h:58 (libc.so.6+0x29d8f) (BuildId: 490fef8403240c91833978d494d39e537409b92e)

  Thread T1 (tid=26469, running) created by main thread at:
    #0 pthread_create ../../../../gcc-14.2.0/libsanitizer/tsan/tsan_interceptors_posix.cpp:1022 (libtsan.so.2+0x5f4e6)
    #1 __gthread_create /home/oipo/Programming/gcc-build/x86_64-pc-linux-gnu/libstdc++-v3/include/x86_64-pc-linux-gnu/bits/gthr-default.h:676 (libstdc++.so.6+0xede78)
    #2 std::thread::_M_start_thread(std::unique_ptr<std::thread::_State, std::default_delete<std::thread::_State> >, void (*)()) ../../../../../gcc-14.2.0/libstdc++-v3/src/c++11/thread.cc:172 (libstdc++.so.6+0xede78)
    #3 std::thread& std::vector<std::thread, std::allocator<std::thread> >::emplace_back<spdlog::details::thread_pool::thread_pool(unsigned long, unsigned long, std::function<void ()>, std::function<void ()>)::{lambda()#1}>(spdlog::details::thread_pool::thread_pool(unsigned long, unsigned long, std::function<void ()>, std::function<void ()>)::{lambda()#1}&&) /opt/gcc/14/include/c++/14.2.0/bits/vector.tcc:123 (a.out+0x4215bc)
    #4 spdlog::details::thread_pool::thread_pool(unsigned long, unsigned long, std::function<void ()>, std::function<void ()>) ../include/spdlog/details/thread_pool-inl.h:27 (a.out+0x4215bc)
    #5 spdlog::details::thread_pool::thread_pool(unsigned long, unsigned long) ../include/spdlog/details/thread_pool-inl.h:42 (a.out+0x421840)
    #6 void std::_Construct<spdlog::details::thread_pool, unsigned long const&, int>(spdlog::details::thread_pool*, unsigned long const&, int&&) /opt/gcc/14/include/c++/14.2.0/bits/stl_construct.h:119 (a.out+0x421840)
    #7 void std::allocator_traits<std::allocator<void> >::construct<spdlog::details::thread_pool, unsigned long const&, int>(std::allocator<void>&, spdlog::details::thread_pool*, unsigned long const&, int&&) /opt/gcc/14/include/c++/14.2.0/bits/alloc_traits.h:657 (a.out+0x421840)
    #8 std::_Sp_counted_ptr_inplace<spdlog::details::thread_pool, std::allocator<void>, (__gnu_cxx::_Lock_policy)2>::_Sp_counted_ptr_inplace<unsigned long const&, int>(std::allocator<void>, unsigned long const&, int&&) /opt/gcc/14/include/c++/14.2.0/bits/shared_ptr_base.h:607 (a.out+0x421840)
    #9 std::__shared_count<(__gnu_cxx::_Lock_policy)2>::__shared_count<spdlog::details::thread_pool, std::allocator<void>, unsigned long const&, int>(spdlog::details::thread_pool*&, std::_Sp_alloc_shared_tag<std::allocator<void> >, unsigned long const&, int&&) /opt/gcc/14/include/c++/14.2.0/bits/shared_ptr_base.h:969 (a.out+0x421840)
    #10 std::__shared_ptr<spdlog::details::thread_pool, (__gnu_cxx::_Lock_policy)2>::__shared_ptr<std::allocator<void>, unsigned long const&, int>(std::_Sp_alloc_shared_tag<std::allocator<void> >, unsigned long const&, int&&) /opt/gcc/14/include/c++/14.2.0/bits/shared_ptr_base.h:1713 (a.out+0x421840)
    #11 std::shared_ptr<spdlog::details::thread_pool>::shared_ptr<std::allocator<void>, unsigned long const&, int>(std::_Sp_alloc_shared_tag<std::allocator<void> >, unsigned long const&, int&&) /opt/gcc/14/include/c++/14.2.0/bits/shared_ptr.h:463 (a.out+0x421840)
    #12 std::shared_ptr<std::enable_if<!std::is_array<spdlog::details::thread_pool>::value, spdlog::details::thread_pool>::type> std::make_shared<spdlog::details::thread_pool, unsigned long const&, int>(unsigned long const&, int&&) /opt/gcc/14/include/c++/14.2.0/bits/shared_ptr.h:1008 (a.out+0x421840)
    #13 main /home/oipo/Programming/spdlog/build/test.cpp:12 (a.out+0x403b2a)

SUMMARY: ThreadSanitizer: data race ../include/spdlog/details/log_msg-inl.h:29 in spdlog::details::log_msg::log_msg(std::chrono::time_point<std::chrono::_V2::system_clock, std::chrono::duration<long, std::ratio<1l, 1000000000l> > >, spdlog::source_loc, fmt::v10::basic_string_view<char>, spdlog::level::level_enum, fmt::v10::basic_string_view<char>)

I notice that async_msg and its parent classes do not have a virtual destructor. I don't think it needs one, but the behaviour of thread sanitizer changes if I do introduce it:

WARNING: ThreadSanitizer: data race (pid=27563)
  Write of size 8 at 0x7fa7303ff288 by thread T5:
    #0 fmt::v10::detail::buffer<char>::set(char*, unsigned long) ../include/spdlog/fmt/bundled/core.h:835 (a.out+0x43a351)
    #1 fmt::v10::basic_memory_buffer<char, 250ul, std::allocator<char> >::basic_memory_buffer(std::allocator<char> const&) ../include/spdlog/fmt/bundled/format.h:927 (a.out+0x43a351)
    #2 void spdlog::logger::log_<int&>(spdlog::source_loc, spdlog::level::level_enum, fmt::v10::basic_string_view<char>, int&) ../include/spdlog/logger.h:324 (a.out+0x43a351)
    #3 void spdlog::logger::log<int&>(spdlog::source_loc, spdlog::level::level_enum, fmt::v10::basic_format_string<char, fmt::v10::type_identity<int&>::type>, int&) ../include/spdlog/logger.h:80 (a.out+0x40706d)
    #4 void spdlog::logger::log<int&>(spdlog::level::level_enum, fmt::v10::basic_format_string<char, fmt::v10::type_identity<int&>::type>, int&) ../include/spdlog/logger.h:85 (a.out+0x40706d)
    #5 void spdlog::logger::info<int&>(fmt::v10::basic_format_string<char, fmt::v10::type_identity<int&>::type>, int&) ../include/spdlog/logger.h:140 (a.out+0x40706d)
    #6 operator() /home/oipo/Programming/spdlog/build/test.cpp:29 (a.out+0x40706d)
    #7 __invoke_impl<void, main(int, char**)::<lambda()> > /opt/gcc/14/include/c++/14.2.0/bits/invoke.h:61 (a.out+0x40706d)
    #8 __invoke<main(int, char**)::<lambda()> > /opt/gcc/14/include/c++/14.2.0/bits/invoke.h:96 (a.out+0x40706d)
    #9 _M_invoke<0> /opt/gcc/14/include/c++/14.2.0/bits/std_thread.h:301 (a.out+0x40706d)
    #10 operator() /opt/gcc/14/include/c++/14.2.0/bits/std_thread.h:308 (a.out+0x40706d)
    #11 _M_run /opt/gcc/14/include/c++/14.2.0/bits/std_thread.h:253 (a.out+0x40706d)
    #12 execute_native_thread_routine ../../../../../gcc-14.2.0/libstdc++-v3/src/c++11/thread.cc:104 (libstdc++.so.6+0xedda3)

  Previous atomic write of size 4 at 0x7fa7303ff288 by thread T3 (mutexes: write M0):
    #0 std::atomic<spdlog::details::async_msg_flush>::store(spdlog::details::async_msg_flush, std::memory_order) /opt/gcc/14/include/c++/14.2.0/atomic:284 (a.out+0x4089b6)
    #1 spdlog::details::thread_pool::post_and_wait_for_flush(std::shared_ptr<spdlog::async_logger>&&, spdlog::async_overflow_policy)::{lambda(spdlog::details::async_msg_flush)#1}::operator()(spdlog::details::async_msg_flush) const ../include/spdlog/details/thread_pool-inl.h:72 (a.out+0x4089b6)
    #2 void std::__invoke_impl<void, spdlog::details::thread_pool::post_and_wait_for_flush(std::shared_ptr<spdlog::async_logger>&&, spdlog::async_overflow_policy)::{lambda(spdlog::details::async_msg_flush)#1}&, spdlog::details::async_msg_flush>(std::__invoke_other, spdlog::details::thread_pool::post_and_wait_for_flush(std::shared_ptr<spdlog::async_logger>&&, spdlog::async_overflow_policy)::{lambda(spdlog::details::async_msg_flush)#1}&, spdlog::details::async_msg_flush&&) /opt/gcc/14/include/c++/14.2.0/bits/invoke.h:61 (a.out+0x4089b6)
    #3 std::enable_if<is_invocable_r_v<void, spdlog::details::thread_pool::post_and_wait_for_flush(std::shared_ptr<spdlog::async_logger>&&, spdlog::async_overflow_policy)::{lambda(spdlog::details::async_msg_flush)#1}&, spdlog::details::async_msg_flush>, void>::type std::__invoke_r<void, spdlog::details::thread_pool::post_and_wait_for_flush(std::shared_ptr<spdlog::async_logger>&&, spdlog::async_overflow_policy)::{lambda(spdlog::details::async_msg_flush)#1}&, spdlog::details::async_msg_flush>(spdlog::details::thread_pool::post_and_wait_for_flush(std::shared_ptr<spdlog::async_logger>&&, spdlog::async_overflow_policy)::{lambda(spdlog::details::async_msg_flush)#1}&, spdlog::details::async_msg_flush&&) /opt/gcc/14/include/c++/14.2.0/bits/invoke.h:111 (a.out+0x4089b6)
    #4 std::_Function_handler<void (spdlog::details::async_msg_flush), spdlog::details::thread_pool::post_and_wait_for_flush(std::shared_ptr<spdlog::async_logger>&&, spdlog::async_overflow_policy)::{lambda(spdlog::details::async_msg_flush)#1}>::_M_invoke(std::_Any_data const&, spdlog::details::async_msg_flush&&) /opt/gcc/14/include/c++/14.2.0/bits/std_function.h:290 (a.out+0x4089b6)
    #5 std::function<void (spdlog::details::async_msg_flush)>::operator()(spdlog::details::async_msg_flush) const /opt/gcc/14/include/c++/14.2.0/bits/std_function.h:591 (a.out+0x416b8e)
    #6 spdlog::details::async_msg::~async_msg() ../include/spdlog/details/thread_pool.h:37 (a.out+0x416b8e)
    #7 spdlog::details::thread_pool::post_and_wait_for_flush(std::shared_ptr<spdlog::async_logger>&&, spdlog::async_overflow_policy) ../include/spdlog/details/thread_pool-inl.h:71 (a.out+0x416b8e)
    #8 spdlog::async_logger::flush_() ../include/spdlog/async_logger-inl.h:56 (a.out+0x416fb9)
    #9 spdlog::logger::flush() ../include/spdlog/logger-inl.h:98 (a.out+0x4070af)
    #10 operator() /home/oipo/Programming/spdlog/build/test.cpp:31 (a.out+0x4070af)
    #11 __invoke_impl<void, main(int, char**)::<lambda()> > /opt/gcc/14/include/c++/14.2.0/bits/invoke.h:61 (a.out+0x4070af)
    #12 __invoke<main(int, char**)::<lambda()> > /opt/gcc/14/include/c++/14.2.0/bits/invoke.h:96 (a.out+0x4070af)
    #13 _M_invoke<0> /opt/gcc/14/include/c++/14.2.0/bits/std_thread.h:301 (a.out+0x4070af)
    #14 operator() /opt/gcc/14/include/c++/14.2.0/bits/std_thread.h:308 (a.out+0x4070af)
    #15 _M_run /opt/gcc/14/include/c++/14.2.0/bits/std_thread.h:253 (a.out+0x4070af)
    #16 execute_native_thread_routine ../../../../../gcc-14.2.0/libstdc++-v3/src/c++11/thread.cc:104 (libstdc++.so.6+0xedda3)

  Location is stack of thread T5.

  Mutex M0 (0x7fa7387ff2c0) created at:
    #0 pthread_mutex_lock ../../../../gcc-14.2.0/libsanitizer/tsan/tsan_interceptors_posix.cpp:1341 (libtsan.so.2+0x5e50e)
    #1 __gthread_mutex_lock /opt/gcc/14/include/c++/14.2.0/x86_64-pc-linux-gnu/bits/gthr-default.h:762 (a.out+0x416884)
    #2 std::mutex::lock() /opt/gcc/14/include/c++/14.2.0/bits/std_mutex.h:113 (a.out+0x416884)
    #3 std::unique_lock<std::mutex>::lock() /opt/gcc/14/include/c++/14.2.0/bits/unique_lock.h:147 (a.out+0x416884)
    #4 std::unique_lock<std::mutex>::unique_lock(std::mutex&) /opt/gcc/14/include/c++/14.2.0/bits/unique_lock.h:73 (a.out+0x416884)
    #5 spdlog::details::thread_pool::post_and_wait_for_flush(std::shared_ptr<spdlog::async_logger>&&, spdlog::async_overflow_policy) ../include/spdlog/details/thread_pool-inl.h:68 (a.out+0x416884)
    #6 spdlog::async_logger::flush_() ../include/spdlog/async_logger-inl.h:56 (a.out+0x416fb9)
    #7 spdlog::logger::flush() ../include/spdlog/logger-inl.h:98 (a.out+0x4070af)
    #8 operator() /home/oipo/Programming/spdlog/build/test.cpp:31 (a.out+0x4070af)
    #9 __invoke_impl<void, main(int, char**)::<lambda()> > /opt/gcc/14/include/c++/14.2.0/bits/invoke.h:61 (a.out+0x4070af)
    #10 __invoke<main(int, char**)::<lambda()> > /opt/gcc/14/include/c++/14.2.0/bits/invoke.h:96 (a.out+0x4070af)
    #11 _M_invoke<0> /opt/gcc/14/include/c++/14.2.0/bits/std_thread.h:301 (a.out+0x4070af)
    #12 operator() /opt/gcc/14/include/c++/14.2.0/bits/std_thread.h:308 (a.out+0x4070af)
    #13 _M_run /opt/gcc/14/include/c++/14.2.0/bits/std_thread.h:253 (a.out+0x4070af)
    #14 execute_native_thread_routine ../../../../../gcc-14.2.0/libstdc++-v3/src/c++11/thread.cc:104 (libstdc++.so.6+0xedda3)

  Thread T5 (tid=27569, running) created by main thread at:
    #0 pthread_create ../../../../gcc-14.2.0/libsanitizer/tsan/tsan_interceptors_posix.cpp:1022 (libtsan.so.2+0x5f4e6)
    #1 __gthread_create /home/oipo/Programming/gcc-build/x86_64-pc-linux-gnu/libstdc++-v3/include/x86_64-pc-linux-gnu/bits/gthr-default.h:676 (libstdc++.so.6+0xede78)
    #2 std::thread::_M_start_thread(std::unique_ptr<std::thread::_State, std::default_delete<std::thread::_State> >, void (*)()) ../../../../../gcc-14.2.0/libstdc++-v3/src/c++11/thread.cc:172 (libstdc++.so.6+0xede78)
    #3 __libc_start_call_main ../sysdeps/nptl/libc_start_call_main.h:58 (libc.so.6+0x29d8f) (BuildId: 490fef8403240c91833978d494d39e537409b92e)

  Thread T3 (tid=27567, running) created by main thread at:
    #0 pthread_create ../../../../gcc-14.2.0/libsanitizer/tsan/tsan_interceptors_posix.cpp:1022 (libtsan.so.2+0x5f4e6)
    #1 __gthread_create /home/oipo/Programming/gcc-build/x86_64-pc-linux-gnu/libstdc++-v3/include/x86_64-pc-linux-gnu/bits/gthr-default.h:676 (libstdc++.so.6+0xede78)
    #2 std::thread::_M_start_thread(std::unique_ptr<std::thread::_State, std::default_delete<std::thread::_State> >, void (*)()) ../../../../../gcc-14.2.0/libstdc++-v3/src/c++11/thread.cc:172 (libstdc++.so.6+0xede78)
    #3 __libc_start_call_main ../sysdeps/nptl/libc_start_call_main.h:58 (libc.so.6+0x29d8f) (BuildId: 490fef8403240c91833978d494d39e537409b92e)

SUMMARY: ThreadSanitizer: data race ../include/spdlog/fmt/bundled/core.h:835 in fmt::v10::detail::buffer<char>::set(char*, unsigned long)

@gabime gabime merged commit b6da594 into gabime:v1.x Oct 30, 2024
8 checks passed
@gabime
Copy link
Owner

gabime commented Oct 30, 2024

I merged since it get stuck even the previous commits.

I think I will change the flush behavior to be async again (as it was versions of spdlog prior to 1.14.0). This is getting too complicated and unstable.

Perhaps just wait for queue to be empty before and after sending the flush request. Most users are just interested in that anyway - that all items in the the queue got processed after flush returns

@Oipo
Copy link
Contributor Author

Oipo commented Oct 30, 2024

Yeah, I was thinking about proposing just removing the synchronous behaviour, but I don't know the use cases.

Another option is to provide message id's that can be polled by users. Just a monotonically increasing number that almost never wraps and the highest processed id can be requested from the logger or thread pool somehow,

gabime added a commit that referenced this pull request Nov 1, 2024
@gabime gabime mentioned this pull request Nov 1, 2024
gabime added a commit that referenced this pull request Nov 1, 2024
* Revert "Ensure flush callback gets called in move-assign operator (#3232)"

This reverts commit b6da594.

* Revert "Exchange promise for condition_variable when flushing (fixes #3221) (#3228)"

This reverts commit 16e0d2e.

* Revert PR #3049
@gabime
Copy link
Owner

gabime commented Nov 1, 2024

Reverted everything (#3235) to make flush fully async again.

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

Successfully merging this pull request may close these issues.

2 participants