The task in BackgroundProcessingPool is not run by fixed interval

[JaySon-Huang]

Bug Report

Please answer these questions before submitting your issue. Thanks!

1. Minimal reproduce step (Required)

Notice when testing #6899, also reported in #6816 (comment)

2. What did you expect to see? (Required)

The task which always returns false run with a fixed interval

3. What did you see instead (Required)

The task get executed frequently by different threads in BackgroundProcessingPool

4. What is your TiFlash version? (Required)

master

[JaySon-Huang]

It is because the task handle with min_time will be poped to multiple worker threads. Though the task with multi=false can prevent a task being run concurrently, it can not prevent those worker threads one by one run the task multiple times within an interval.

tiflash/dbms/src/Storages/BackgroundProcessingPool.cpp

Lines 173 to 190 in e1418dc

	Poco::Timestamp min_time;
	{
	std::unique_lock lock(tasks_mutex);
	if (!tasks.empty())
	{
	for (const auto & time_handle : tasks)
	{
	if (!time_handle.second->removed)
	{
	min_time = time_handle.first;
	task = time_handle.second;
	break;
	}
	}
	}
	}

[JaySon-Huang]

With a background pool with 10 threads, and one task expecting to run at 2 seconds intervals. It actually gets executed more than 35 times within 10 seconds.

click expand to see the unit test

TEST(BackgroundProcessingPoolTest, FixedInterval)
{
    BackgroundProcessingPool pool(10, "test");

    using Clock = std::chrono::system_clock;
    using TimePoint = std::chrono::time_point<Clock>;

    TimePoint last_update_timepoint = Clock::now();

    using namespace std::chrono_literals;
    const auto sleep_seconds = 10s;
    const Int64 expect_interval_ms = 2 * 1000;
    const auto num_expect_called = 5;

    Int64 num_actual_called = 0;
    Int64 min_diff_ms = std::numeric_limits<Int64>::max();
    auto task = pool.addTask(
        [&]() {
            num_actual_called += 1;
            auto diff_ms = std::chrono::duration_cast<std::chrono::milliseconds>(Clock::now() - last_update_timepoint).count();
            if (diff_ms < expect_interval_ms / 2)
            {
                LOG_ERROR(Logger::get(), "Unexpected frequent call, actual interval={}ms", diff_ms);
            }
            min_diff_ms = std::min(min_diff_ms, diff_ms);

            last_update_timepoint = Clock::now();
            return false; // expected to be run with a fixed interval
        },
        /*multi*/ false,
        expect_interval_ms);

    std::this_thread::sleep_for(sleep_seconds);

    pool.removeTask(task);

    LOG_INFO(Logger::get(), "actual being called for {} times", num_actual_called);
    ASSERT_TRUE(num_expect_called - 1 <= num_actual_called
                && num_actual_called <= num_expect_called + 1)
        << fmt::format("actual_called={} min_diff_ms={}", num_actual_called, min_diff_ms);
}

[----------] 1 test from BackgroundProcessingPoolTest
[ RUN      ] BackgroundProcessingPoolTest.FixedInterval
[2023/02/28 00:12:55.466 +08:00] [INFO] [BackgroundProcessingPool.cpp:90] ["Create BackgroundProcessingPool, prefix=test n_threads=10"] [thread_id=1]
[2023/02/28 00:12:55.591 +08:00] [ERROR] [gtest_bkg_pool.cpp:35] ["Unexpected frequent call, actual interval=124ms"] [thread_id=42]
[2023/02/28 00:12:57.640 +08:00] [ERROR] [gtest_bkg_pool.cpp:35] ["Unexpected frequent call, actual interval=39ms"] [thread_id=43]
[2023/02/28 00:12:57.731 +08:00] [ERROR] [gtest_bkg_pool.cpp:35] ["Unexpected frequent call, actual interval=90ms"] [thread_id=44]
[2023/02/28 00:12:58.039 +08:00] [ERROR] [gtest_bkg_pool.cpp:35] ["Unexpected frequent call, actual interval=308ms"] [thread_id=45]
[2023/02/28 00:12:58.120 +08:00] [ERROR] [gtest_bkg_pool.cpp:35] ["Unexpected frequent call, actual interval=80ms"] [thread_id=42]
[2023/02/28 00:12:58.304 +08:00] [ERROR] [gtest_bkg_pool.cpp:35] ["Unexpected frequent call, actual interval=183ms"] [thread_id=46]
[2023/02/28 00:12:58.360 +08:00] [ERROR] [gtest_bkg_pool.cpp:35] ["Unexpected frequent call, actual interval=56ms"] [thread_id=47]
[2023/02/28 00:12:58.440 +08:00] [ERROR] [gtest_bkg_pool.cpp:35] ["Unexpected frequent call, actual interval=79ms"] [thread_id=48]
[2023/02/28 00:12:58.533 +08:00] [ERROR] [gtest_bkg_pool.cpp:35] ["Unexpected frequent call, actual interval=92ms"] [thread_id=49]
[2023/02/28 00:12:58.576 +08:00] [ERROR] [gtest_bkg_pool.cpp:35] ["Unexpected frequent call, actual interval=42ms"] [thread_id=50]
[2023/02/28 00:13:00.000 +08:00] [ERROR] [gtest_bkg_pool.cpp:35] ["Unexpected frequent call, actual interval=154ms"] [thread_id=43]
[2023/02/28 00:13:00.050 +08:00] [ERROR] [gtest_bkg_pool.cpp:35] ["Unexpected frequent call, actual interval=49ms"] [thread_id=45]
[2023/02/28 00:13:00.263 +08:00] [ERROR] [gtest_bkg_pool.cpp:35] ["Unexpected frequent call, actual interval=213ms"] [thread_id=42]
[2023/02/28 00:13:00.346 +08:00] [ERROR] [gtest_bkg_pool.cpp:35] ["Unexpected frequent call, actual interval=82ms"] [thread_id=44]
[2023/02/28 00:13:00.767 +08:00] [ERROR] [gtest_bkg_pool.cpp:35] ["Unexpected frequent call, actual interval=421ms"] [thread_id=47]
[2023/02/28 00:13:00.770 +08:00] [ERROR] [gtest_bkg_pool.cpp:35] ["Unexpected frequent call, actual interval=2ms"] [thread_id=46]
[2023/02/28 00:13:00.808 +08:00] [ERROR] [gtest_bkg_pool.cpp:35] ["Unexpected frequent call, actual interval=37ms"] [thread_id=48]
[2023/02/28 00:13:01.297 +08:00] [ERROR] [gtest_bkg_pool.cpp:35] ["Unexpected frequent call, actual interval=489ms"] [thread_id=49]
[2023/02/28 00:13:01.358 +08:00] [ERROR] [gtest_bkg_pool.cpp:35] ["Unexpected frequent call, actual interval=60ms"] [thread_id=50]
[2023/02/28 00:13:02.124 +08:00] [ERROR] [gtest_bkg_pool.cpp:35] ["Unexpected frequent call, actual interval=765ms"] [thread_id=51]
[2023/02/28 00:13:02.285 +08:00] [ERROR] [gtest_bkg_pool.cpp:35] ["Unexpected frequent call, actual interval=160ms"] [thread_id=43]
[2023/02/28 00:13:02.578 +08:00] [ERROR] [gtest_bkg_pool.cpp:35] ["Unexpected frequent call, actual interval=292ms"] [thread_id=45]
[2023/02/28 00:13:02.585 +08:00] [ERROR] [gtest_bkg_pool.cpp:35] ["Unexpected frequent call, actual interval=6ms"] [thread_id=42]
[2023/02/28 00:13:02.991 +08:00] [ERROR] [gtest_bkg_pool.cpp:35] ["Unexpected frequent call, actual interval=405ms"] [thread_id=48]
[2023/02/28 00:13:03.083 +08:00] [ERROR] [gtest_bkg_pool.cpp:35] ["Unexpected frequent call, actual interval=91ms"] [thread_id=47]
[2023/02/28 00:13:03.297 +08:00] [ERROR] [gtest_bkg_pool.cpp:35] ["Unexpected frequent call, actual interval=213ms"] [thread_id=44]
[2023/02/28 00:13:03.336 +08:00] [ERROR] [gtest_bkg_pool.cpp:35] ["Unexpected frequent call, actual interval=38ms"] [thread_id=49]
[2023/02/28 00:13:03.364 +08:00] [ERROR] [gtest_bkg_pool.cpp:35] ["Unexpected frequent call, actual interval=27ms"] [thread_id=46]
[2023/02/28 00:13:03.785 +08:00] [ERROR] [gtest_bkg_pool.cpp:35] ["Unexpected frequent call, actual interval=421ms"] [thread_id=50]
[2023/02/28 00:13:04.386 +08:00] [ERROR] [gtest_bkg_pool.cpp:35] ["Unexpected frequent call, actual interval=600ms"] [thread_id=43]
[2023/02/28 00:13:04.973 +08:00] [ERROR] [gtest_bkg_pool.cpp:35] ["Unexpected frequent call, actual interval=587ms"] [thread_id=51]
[2023/02/28 00:13:05.130 +08:00] [ERROR] [gtest_bkg_pool.cpp:35] ["Unexpected frequent call, actual interval=156ms"] [thread_id=48]
[2023/02/28 00:13:05.268 +08:00] [ERROR] [gtest_bkg_pool.cpp:35] ["Unexpected frequent call, actual interval=137ms"] [thread_id=42]
[2023/02/28 00:13:05.366 +08:00] [ERROR] [gtest_bkg_pool.cpp:35] ["Unexpected frequent call, actual interval=96ms"] [thread_id=45]
[2023/02/28 00:13:05.466 +08:00] [INFO] [gtest_bkg_pool.cpp:49] ["actual being called for 36 times"] [thread_id=1]
/data1/jaysonhuang/tics-k/dbms/src/Storages/tests/gtest_bkg_pool.cpp:51: Failure
Value of: num_expect_called - 1 <= num_actual_called && num_actual_called <= num_expect_called + 1
  Actual: false
Expected: true
actual_called=36 min_diff_ms=2
[  FAILED  ] BackgroundProcessingPoolTest.FixedInterval (10002 ms)
[----------] 1 test from BackgroundProcessingPoolTest (10002 ms total)