Surprising behaviour of task scheduling.

[zjuwyz]

Description:

I encountered a task scheduling issue while using the concurrencpp library. The following is a test code snippet that demonstrates the problem:

#include "concurrencpp/concurrencpp.h"
#include <spdlog/spdlog.h>
namespace co = concurrencpp;
using namespace std;

shared_ptr<co::worker_thread_executor> wte;

co::result<void> sleeper()
{
    spdlog::info(">>> sleeper start");
    this_thread::sleep_for(1s);
    spdlog::info(">>> sleeper awake: enqueueing \">>> notify \"");
    co_await wte->submit([] { spdlog::info(">>> notify"); });
    this_thread::sleep_for(1s);
    spdlog::info(">>> sleeper return");
}

co::result<void> co_main()
{
    spdlog::info("co_main start");
    auto sleeper_task = wte->submit(sleeper);
    spdlog::info("co_main posted sleeper");
    this_thread::sleep_for(0.5s);
    spdlog::info("co_main ready: enqueueing \">>> scheduled\" ");
    co_await wte->submit([]{
       spdlog::info(">>> scheduled");
    });
    spdlog::info("co_main notified");
    co_await sleeper_task;
}

int main()
{
    co::runtime runtime;
    wte = runtime.make_worker_thread_executor();
    co_main().get();
}

The expected behavior is that the task submitted after 0.5s should be executed before the task submitted after 1s. However, the actual output suggests otherwise: (Some output logs are added inside concurrencpp lib for convenience)

[2023-09-11 21:35:22.066] [info] co_main start
enqueue
enqueue foreign
[2023-09-11 21:35:22.067] [info] co_main posted sleeper
task begin
[2023-09-11 21:35:22.067] [info] >>> sleeper start
[2023-09-11 21:35:22.567] [info] co_main ready: enqueueing ">>> scheduled"     // <-- first enqueued
enqueue
enqueue foreign
[2023-09-11 21:35:23.067] [info] >>> sleeper awake: enqueueing ">>> notify "
enqueue
enqueue local
task end
task begin
[2023-09-11 21:35:23.067] [info] >>> notify
[2023-09-11 21:35:24.067] [info] >>> sleeper return
task end
task begin
[2023-09-11 21:35:24.067] [info] >>> scheduled    // <-- but not first executed
[2023-09-11 21:35:24.067] [info] co_main notified
task end
Process finished with exit code 0

The issue is that the task submitted after 0.5s is actually executed after the task submitted after 1s, which contradicts my expectations.

This is caused by the private-public dual task queue inside worker_thread_executor. I would appreciate any insights on this design, rather than what is claimed in the docs:

worker thread executor - a single thread executor that maintains a single task queue. Suitable when applications want a dedicated thread that executes many related tasks.

[pefedotov]

Is it possible to exclude the influence of writing to the logs here? How does the logger behave when accessing functions from multiple threads?