Not output log when doing a libuv test

[WayneY]

I was doing a libuv test with quill, but when I added a line in a while loop, it can only output the first line, and blocked the whole program. Did I use the quill in a wrong way?

The test code is below, the 55th line

#include <thread>
#include <chrono>
#include <jemalloc/jemalloc.h>
#include "quill/Quill.h"
#include <uv.h>

static quill::Logger *logger = nullptr;

static int64_t count = 0;

static volatile int status = 0;

int main()
{
    quill::enable_console_colours();
    quill::start();

    logger = quill::get_logger();
    logger->set_log_level(quill::LogLevel::TraceL3);

    // enable a backtrace that will get flushed when we log CRITICAL
    logger->init_backtrace(2, quill::LogLevel::Critical);

    LOG_INFO(logger, "Welcome to Quill!");

    uv_loop_t *uv_loop = (uv_loop_t *)malloc(sizeof(uv_loop_t));
    uv_loop_init(uv_loop);

    uv_async_t *uv_async = (uv_async_t *)malloc(sizeof(uv_async_t));
    uv_async_init(uv_loop, uv_async, 
        [](uv_async_t *uv_handle)
        {
            LOG_INFO(logger, "count:{}", count);
            if (++count == 1000000)
            {
                // LOG_INFO(logger, "close async");
                status = 1; // stop
                while (status != 2) // stopped
                    uv_sleep(0);
                uv_close((uv_handle_t *)uv_handle, nullptr);
            }
        }
    );

    uv_thread_t *uv_thread = (uv_thread_t *)malloc(sizeof(uv_thread_t));
    uv_thread_create(
        uv_thread, 
        [](void *arg)
        {
            int c = 0;
            while (status == 0)
            {
                uv_async_send((uv_async_t *)arg);
                // std::cout << "c:" << ++c << "\n";
                LOG_INFO(logger, "after send, count:{}", ++c);        // <=======  Wrong with this  
            }
            status = 2;
        }, 
        uv_async
    );

    auto t1 = uv_hrtime();
    uv_run(uv_loop, UV_RUN_DEFAULT);
    auto t2 = uv_hrtime();
    uv_thread_join(uv_thread);
    LOG_INFO(logger, "spend:{}, count:{}, {}", (t2 - t1) / 1000, count, (t2 - t1) / 1000 / count);
    return 0;
}

[bl-ue]

@WayneY did you try getting it in the debugger? That might help visualize what's blocking.

[WayneY]

@WayneY did you try getting it in the debugger? That might help visualize what's blocking.

No, I havn't used a debugger. Which debugger should I use to generate a visualized report?

[bl-ue]

I was thinking of Visual Studio, where you could interactively step through each line, but you're probably on linux, no?

[WayneY]

Yes, I am on Linux.

If you would like you may compile and run that code above. It has no other dependences than libuv and I think it could reproduce this problem I met.

[odygrd]

if you change to if (++count == 10'000) it should work.
There is a spsc queue between the hot threads and the backend logging thread. Quill is designed in such way to keep the caller thread queue as empty as possible at all times so the queue doesn't re-allocate.
Therefore the backend worker thread is busy trying to empty the hot thread's queue and storing the objects locally, but then due to logging in a loop and so fast the backend worker has no time to log anything.

[odygrd]

thanks for reporting. While logging like this in a loop is a very unusual case, I understand it can happen. There is a fix for it in 37e2cf0 and your example should be running now.
Please open a new ticket if you have any other issues