Opensource internals

ClickHouse Buffers the Query Log and Flushes It Into a Real MergeTree Table

17 min read Jay Hubbert

system.query_log is not a special table: rows are appended to an in-memory queue by the query thread and a background thread every 7.5 seconds INSERTs them into an ordinary MergeTree table created lazily on the first flush.

TL;DR: system.query_log is a real MergeTree table in the system database. But nobody writes to it directly. The query thread pushes a QueryLogElement onto an in-memory queue; a background thread wakes up every 7.5 seconds, builds one Block from everything queued, and runs a full INSERT against the table through InterpreterInsertQuery. The table itself is created lazily, on the first flush.

There is a piece of every database that has an awkward requirement: it must record what the server did, and it must not slow the server down while doing it.

Postgres solves this with csvlog and pg_stat_statements — a side process that tails a file. MySQL solved it with the slow query log. Every solution involves either a separate process, a separate file format, or a background writer that has to be told when to flush.

ClickHouse’s solution is unusual, and it is worth understanding because it explains a lot of the observable behaviour of system.query_log:

  1. The log is a real MergeTree table. Not a view, not a file, not a ring buffer. system.query_log has parts, it gets merged, it can be OPTIMIZEd, it can be TTLed, and it can be read with the full power of the query engine.
  2. But the writes are asynchronous and buffered. A query that finishes does not write a row; it appends to a queue and returns.
  3. The table is created lazily, on the first flush, and rotated if the schema changes.

The queue

The heart of it is SystemLogQueue, a bounded, mutex-protected vector with a monotonically increasing index:

cpp 
// src/Common/SystemLogBase.h:185
    // Queue is bounded. But its size is quite large to not block in all normal cases.
    std::vector<LogElement> queue;

    // An always-incrementing index of the first message currently in the queue.
    // We use it to give a global sequential index to every message, so that we
    // can wait until a particular message is flushed. This is used to implement
    // synchronous log flushing for SYSTEM FLUSH LOGS.
    Index queue_front_index = 0;

    // Requested to flush logs up to this index, exclusive
    Index requested_flush_index = std::numeric_limits<Index>::min();
    // Flushed log up to this index, exclusive
    Index flushed_index = 0;

and then the two “prepare” indices, which track a separate concern — whether the table has been created:

cpp 
// src/Common/SystemLogBase.h:199
    // The same logic for the prepare tables: if requested_prepare_tables > prepared_tables we need to do prepare
    // except that initial prepared_tables is -1
    // it is due to the difference: when no logs have been written and we call flush logs
    // it becomes in the state: requested_flush_index = 0 and flushed_index = 0 -- we do not want to do anything
    // but if we need to prepare tables it becomes requested_prepare_tables = 0 and prepared_tables = -1
    // we trigger background thread and do prepare
    Index requested_prepare_tables = std::numeric_limits<Index>::min();
    Index prepared_tables = -1;

    size_t ignored_logs = 0;

This index-based protocol is the whole trick behind SYSTEM FLUSH LOGS. It is not “flush whatever is there right now” — it is “flush up to index N, and tell me when you have”. That is why SYSTEM FLUSH LOGS is synchronous and correct: a query that returns from SYSTEM FLUSH LOGS knows its rows are on disk.

Producing: add()

The producer side is a template that takes a callback, not a value:

cpp 
// src/Common/SystemLogBase.h:143
    // producer method: fill the element in place under a memory-tracker blocker, then enqueue it (moved).
    template <typename FillElement>
    requires std::is_invocable_r_v<void, FillElement, LogElement &>
    void add(FillElement && fill)
    {
        MemoryTrackerUntrackedAllocationsBlockerInThread untracked_allocations_blocker;
        MemoryTrackerBlockerInThread block_memory_tracker;
        LogElement element{};
        fill(element);
        push(std::move(element));
    }

Two things happen here that are easy to miss:

The element is filled in place, under a memory-tracker blocker. The QueryLogElement is a big struct — it holds the query text, the profile events map, the settings map, the exception stack trace. Building it on the stack and moving it into the queue means the allocation of the strings happens under the caller’s tracker, so a query that logs a 10 MB stack trace is charged for it. But the free happens later, on the flush thread, which cannot credit the original query’s tracker — hence the UntrackedAllocations blocker, which stops the flush thread’s frees from being charged to somebody else.

The static_assert in the class body guards the move:

cpp 
// src/Common/SystemLogBase.h:130
class SystemLogQueue
{
    /// `queue` reallocates while `mutex` is held. libc++ relocates with std::move_if_noexcept, so an element
    /// that can throw on move is deep-copied instead, and the critical section becomes O(queue size).
    static_assert(std::is_nothrow_move_constructible_v<LogElement>);

A throwing move would make std::vector’s reallocation copy every element, under the mutex, turning a push into an O(queue) operation.

The push

cpp 
// src/Common/SystemLogBase.cpp:101
template <typename LogElement>
void SystemLogQueue<LogElement>::push(LogElement && element)
{
    /// It is possible that the method will be called recursively.
    /// Better to drop these events to avoid complications.
    if (recursive_push_call)
        return;
    recursive_push_call = true;
    SCOPE_EXIT({ recursive_push_call = false; });

The recursion guard is worth a moment. Logging a message can itself log a message — a query that fails to log can fail to log that. The guard is a thread_local flag: if we are already inside a push, drop the event.

Then the two thresholds:

cpp 
// src/Common/SystemLogBase.cpp:118
    {
        std::unique_lock lock(mutex);

        if (is_shutdown)
            return;

        if (queue.size() == settings.buffer_size_rows_flush_threshold)
        {
            buffer_size_rows_flush_threshold_exceeded = true;

            // The queue more than half full, time to flush.
            // We only check for strict equality, because messages are added one
            // by one, under exclusive lock, so we will see each message count.
            // It is enough to only wake the flushing thread once, after the message
            // count increases past half available size.

            const auto last_log_index = queue_front_index + queue.size();
            notifyFlushUnlocked(last_log_index, /* should_prepare_tables_anyway */ false);
        }

        if (queue.size() >= settings.max_size_rows)
        {
            chassert(queue.size() == settings.max_size_rows);

            // Ignore all further entries until the queue is flushed.
            // To the next batch we add a log message about how much we have lost
            ++ignored_logs;
            return;
        }

        queue.push_back(std::move(element));
    }

The half-full threshold wakes the flush thread early. If the queue reaches buffer_size_rows_flush_threshold (by default half of max_size_rows), the push notifies the flush thread, which does not have to wait for its timer. This is what keeps the queue from filling up during a burst.

The hard limit drops events. If the queue is at max_size_rows, the event is dropped and ignored_logs is incremented. The count is reported at the next flush:

cpp 
// src/Common/SystemLogBase.cpp:283
    if (prev_ignored_logs)
        LOG_ERROR(log, "Queue had been full at {}, accepted {} logs, ignored {} logs.",
                    result.last_log_index - result.logs.size(),
                    result.logs.size(),
                    prev_ignored_logs);

So: the query log is lossy under extreme load, by design, and it tells you it was lossy. That is a better failure mode than blocking the query path.

The defaults

cpp 
// src/Common/SystemLogBase.h:263
    static consteval size_t getDefaultMaxSize() { return 1048576; }
    static consteval size_t getDefaultReservedSize() { return 8192; }
    static consteval size_t getDefaultFlushIntervalMilliseconds() { return 7500; }
    static consteval bool shouldNotifyFlushOnCrash() { return false; }
    static consteval bool shouldTurnOffLogger() { return false; }

1 048 576 rows is the hard cap. 8192 rows is the reserved capacity (the vector’s initial reservation, so that a normal flush does not reallocate). 7500 ms is the flush interval — the famous 7.5 seconds.

The threshold and the interval come from the config, per table, with a global system_tables. prefix:

cpp 
// src/Interpreters/SystemLogSettingsFromConfig.h:44
template <typename TSystemLog>
void readSystemLogQueueSettingsFromConfig(SystemLogQueueSettings & queue_settings, const Poco::Util::AbstractConfiguration & config, const std::string & config_prefix)
{
    queue_settings.flush_interval_milliseconds = getSystemTableOption<size_t>("flush_interval_milliseconds", config, config_prefix).value_or(TSystemLog::getDefaultFlushIntervalMilliseconds());

    queue_settings.max_size_rows = getSystemTableOption<size_t>("max_size_rows", config, config_prefix).value_or(TSystemLog::getDefaultMaxSize());
    if (queue_settings.max_size_rows < 1)
        throw Exception(ErrorCodes::BAD_ARGUMENTS, "max_size_rows for {} is {} should be 1 at least",
                        config_prefix,
                        queue_settings.max_size_rows);

    queue_settings.reserved_size_rows = getSystemTableOption<size_t>("reserved_size_rows", config, config_prefix).value_or(TSystemLog::getDefaultReservedSize());
    if (queue_settings.max_size_rows < queue_settings.reserved_size_rows)
    {
        throw Exception(ErrorCodes::BAD_ARGUMENTS,
                        "max_size_rows for {} is {} should be >= reserved_size_rows ({})",
                        config_prefix,
                        queue_settings.max_size_rows,
                        queue_settings.reserved_size_rows);
    }

    queue_settings.buffer_size_rows_flush_threshold = getSystemTableOption<size_t>("buffer_size_rows_flush_threshold", config, config_prefix).value_or(queue_settings.max_size_rows / 2);

So the defaults compose to: flush every 7.5 s, or earlier if the queue reaches 524 288 rows; drop events beyond 1 048 576.

The flush thread

One thread per log table, started at startup:

cpp 
// src/Common/SystemLogBase.cpp:333
template <typename LogElement>
void SystemLogBase<LogElement>::startup()
{
    std::lock_guard lock(thread_mutex);
    saving_thread = std::make_unique<ThreadFromGlobalPool>([this] { savingThreadFunction(); });
}

Its loop is short:

cpp 
// src/Interpreters/SystemLog.cpp:857
template <typename LogElement>
void SystemLog<LogElement>::savingThreadFunction()
{
    DB::setThreadName(ThreadName::SYSTEM_LOG_FLUSH);

    while (true)
    {
        try
        {
            auto result = queue->pop();

            if (result.is_shutdown)
            {
                LOG_TRACE(log, "Terminating");
                return;
            }

            if (!result.logs.empty())
            {
                flushImpl(result.logs, result.last_log_index);
            }
            else if (result.create_table_force)
            {
                prepareTable();
                queue->confirm(result.last_log_index);
            }
        }
        catch (...)
        {
            tryLogCurrentException(__PRETTY_FUNCTION__);
        }
    }
}

Note the catch (...): a failed flush must not kill the thread. The next iteration continues.

pop(): the timer

This is where the 7.5 seconds live:

cpp 
// src/Common/SystemLogBase.cpp:240
template <typename LogElement>
typename SystemLogQueue<LogElement>::PopResult SystemLogQueue<LogElement>::pop()
{
    [[maybe_unused]] MemoryTrackerUntrackedAllocationsBlockerInThread blocker;

    PopResult result;
    size_t prev_ignored_logs = 0;

    {
        std::unique_lock lock(mutex);

        flush_event.wait_for(lock, std::chrono::milliseconds(settings.flush_interval_milliseconds), [&] ()
        {
            return requested_flush_index > flushed_index || requested_prepare_tables > prepared_tables || is_shutdown;
        });

        if (is_shutdown)
            return PopResult{.is_shutdown = true};

        /// Allocate the next batch's buffer outside the lock so a large reallocation
        /// does not block producers, then hand it over with a cheap swap below.
        if (!queue.empty())
        {
            const auto next_capacity = std::max(settings.reserved_size_rows, queue.size());
            lock.unlock();
            result.logs.reserve(next_capacity);
            lock.lock();

            if (is_shutdown)
                return PopResult{.is_shutdown = true};
        }

        const auto queue_size = queue.size();
        queue_front_index += queue_size;
        prev_ignored_logs = ignored_logs;
        ignored_logs = 0;

        result.last_log_index = queue_front_index;
        if (!queue.empty())
            result.logs.swap(queue);
        result.create_table_force = requested_prepare_tables > prepared_tables;
    }

Four things to notice:

  1. wait_for with a predicate, not wait. The thread sleeps for up to flush_interval_milliseconds but wakes immediately when a flush is requested. That is how the half-full threshold produces an early flush.
  2. The batch is allocated outside the lock. result.logs.reserve(...) happens with the mutex released, then the buffer is handed over with a swap. The producers are not blocked by a 100 000-element reallocation.
  3. queue_front_index advances by the size of the batch, not by one. The index is therefore a logical sequence number: “the Nth log record ever produced”, regardless of batching. That is what makes SYSTEM FLUSH LOGS able to say “flush up to record 4 500 000”.
  4. swap, not clear. The queue vector and the batch vector trade places. The next batch gets a fresh, correctly-sized buffer, and the old one is freed when the batch goes out of scope.

The flush itself

flushImpl is where the rows become a Block and the Block becomes an INSERT:

cpp 
// src/Interpreters/SystemLog.cpp:892
template <typename LogElement>
void SystemLog<LogElement>::flushImpl(const std::vector<LogElement> & to_flush, uint64_t to_flush_end)
{
    auto component_guard = Coordination::setCurrentComponent("SystemLog::flushImpl");
    Stopwatch stopwatch;
    UInt64 prepare_table_time = 0;
    UInt64 prepare_insert_data_to_block = 0;
    UInt64 execute_insert_time = 0;
    UInt64 confirm_time = 0;
    size_t flush_size = to_flush.size();
    bool is_manual_flush = flush_policy->isManualFlush(to_flush_end);

    try
    {
        LOG_TRACE(log, "Flushing system log, {} entries to flush up to offset {}",
            to_flush.size(), to_flush_end);

        fiu_do_on(FailPoints::sleep_in_logs_flush,
        {
            sleepForSeconds(30);
        });

        /// We check for existence of the table and create it as needed at every
        /// flush. This is done to allow user to drop the table at any moment
        /// (new empty table will be created automatically). BTW, flush method
        /// is called from single thread.
        prepareTable();
        prepare_table_time = stopwatch.elapsedMilliseconds();
        stopwatch.restart();

        ColumnsWithTypeAndName log_element_columns;
        auto log_element_names_and_types = LogElement::getColumnsDescription();

        for (const auto & name_and_type : log_element_names_and_types.getAll())
            log_element_columns.emplace_back(name_and_type.type, name_and_type.name);

        Block block(std::move(log_element_columns));

        MutableColumns columns = block.mutateColumns();

        for (auto & column : columns)
            column->reserve(to_flush.size());

        for (const auto & elem : to_flush)
            elem.appendToBlock(columns);

        block.setColumns(std::move(columns));

Three things:

prepareTable() is called on every flush, not once at startup. The comment explains: “We check for existence of the table and create it as needed at every flush. This is done to allow user to drop the table at any moment (new empty table will be created automatically).” So DROP TABLE system.query_log does not disable logging; the next flush recreates it.

reserve(to_flush.size()) on every column — a single allocation per column for the whole batch, instead of growth-by-doubling.

appendToBlock is per-element, per-column serialisation. The element knows how to write itself into the columns.

And then the insert:

cpp 
// src/Interpreters/SystemLog.cpp:942
        /// We write to table indirectly, using InterpreterInsertQuery.
        /// This is needed to support DEFAULT-columns in table.

        auto insert = make_intrusive<ASTInsertQuery>();
        insert->table_id = table_id;

        /// Explicitly specify column names to avoid mismatch when the table
        /// has been altered (e.g. columns added) between prepareTable() and this INSERT.
        auto columns_ast = make_intrusive<ASTExpressionList>();
        for (const auto & name : block.getNames())
            columns_ast->children.emplace_back(make_intrusive<ASTIdentifier>(name));
        insert->columns = std::move(columns_ast);

        ASTPtr query_ptr = std::move(insert);

        // we need query context to do inserts to target table with MV containing subqueries or joins
        auto insert_context = Context::createCopy(context);
        insert_context->makeQueryContext();
        addSettingsForQuery(insert_context, IAST::QueryKind::Insert);

        InterpreterInsertQuery interpreter(
            query_ptr,
            insert_context,
            /* allow_materialized */ false,
            /* no_squash */ false,
            /* no_destination */ false,
            /* async_isnert */ false);
        BlockIO io = interpreter.execute();

        PushingPipelineExecutor executor(io.pipeline);

        executor.start();
        executor.push(block);
        executor.finish();

This is a full INSERT through the query interpreter. Not a direct write to the storage. The comment says why: “This is needed to support DEFAULT-columns in table.” Because the table is a real MergeTree with a real schema, the log’s rows go through the same machinery as any other insert — the same column defaults, the same materialized views, the same partitioning.

The cost of that decision is that every flush builds a query plan, opens the table, takes locks, and goes through the whole insert pipeline. The benefit is that the log table is indistinguishable from a user table: it can have materialized views attached to it, it can be read with the full query engine, it participates in replication if you configure it, and OPTIMIZE works on it.

Note also that the whole batch is a single INSERT — typically one MergeTree part per partition, written in one transaction. A million log rows land as one part.

And the failure handling: a failed flush is logged, the profile event SystemLogErrorOnFlush is incremented, and the batch is confirmed anyway:

cpp 
// src/Interpreters/SystemLog.cpp:981
    catch (...)
    {
        if (is_manual_flush)
            flush_policy->cancelManualFlush();
        ProfileEvents::increment(ProfileEvents::SystemLogErrorOnFlush);
        tryLogCurrentException(__PRETTY_FUNCTION__, fmt::format("Failed to flush system log {} with {} entries up to offset {}",
            table_id.getNameForLogs(), to_flush.size(), to_flush_end));
    }

    queue->confirm(to_flush_end);

The rows are lost, not retried. The log is best-effort by design.

The table is created lazily

The table does not exist until the first flush. The engine definition is assembled from the log element’s own description plus the config:

cpp 
// src/Interpreters/SystemLog.cpp:254
        log_settings.engine = "ENGINE = MergeTree";

        /// PARTITION expr is not necessary.
        String partition_by = getSystemTableOption<std::string>("partition_by", config, config_prefix).value_or(TSystemLog::getDefaultPartitionBy());
        if (!partition_by.empty())
            log_settings.engine += " PARTITION BY (" + partition_by + ")";

        /// TTL expr is not necessary.
        String ttl = getSystemTableOption<std::string>("ttl", config, config_prefix).value_or(TSystemLog::getDefaultTTL());
        if (!ttl.empty())
            log_settings.engine += " TTL " + ttl;

        /// ORDER BY expr is necessary.
        String order_by = getSystemTableOption<std::string>("order_by", config, config_prefix).value_or(TSystemLog::getDefaultOrderBy());
        log_settings.engine += " ORDER BY (" + order_by + ")";

with the defaults coming from the base class:

cpp 
// src/Common/SystemLogBase.h:258
    static const char * getDefaultPartitionBy() { return "toYYYYMM(event_date)"; }
    static const char * getDefaultOrderBy() { return "event_date, event_time"; }
    static const char * getDefaultTTL() { return ""; }

So the default system.query_log is:

sql 
CREATE TABLE system.query_log (
    ...
) ENGINE = MergeTree
  PARTITION BY (toYYYYMM(event_date))
  ORDER BY (event_date, event_time)

A monthly partition, ordered by time. That is a real table with real parts, and it gets merged in the background like any other.

prepareTable() also handles the case where the schema has changed between server versions — an Enum8 column gained a value, a column was added:

cpp 
// src/Interpreters/SystemLog.cpp:1014
template <typename LogElement>
void SystemLog<LogElement>::prepareTable()
{
    auto component_guard = Coordination::setCurrentComponent("SystemLog::prepareTable");
    String description = table_id.getNameForLogs();

    auto table = getStorage();
    if (table)
    {
        if (old_create_query.empty())
        {
            old_create_query = getCreateTableQueryClean(table_id, getContext())->formatWithSecretsOneLine();

and if the definition no longer matches, the old table is renamed to query_log_1, query_log_2, … and a fresh one is created. The docs call this “rotation”. It is how system.session_log handles a new interface enum value: the old table keeps its old enum, a new table is created with the new one, and your old data is still there under the rotated name.

SYSTEM FLUSH LOGS

Now the index protocol pays off. SYSTEM FLUSH LOGS needs to guarantee “when I return, the rows are on disk”. The implementation:

cpp 
// src/Interpreters/SystemLog.cpp:667
        for (auto * log : getAllLogs())
        {
            log->flushBufferToLog(std::chrono::system_clock::now());

            auto last_log_index = log->getLastLogIndex();
            logs_to_wait.push_back({log, last_log_index});
            if (should_prepare_tables_anyway)
                log->setManualFlushTargetIndex(last_log_index);
            log->notifyFlush(last_log_index, should_prepare_tables_anyway);
        }

then:

cpp 
// src/Interpreters/SystemLog.cpp:744
    /// We must wait for the async flushes to finish
    for (const auto & [log, index] : logs_to_wait)
    {
        if (!ignore_errors)
            log->flush(index, should_prepare_tables_anyway);

log->flush(index) is waitFlush, which blocks until the flush thread reports flushed_index >= index:

cpp 
// src/Common/SystemLogBase.cpp:202
    auto result = confirm_event.wait_for(
        lock,
        std::chrono::seconds(timeout_seconds),
        [&]
        {
            return (flushed_index >= expected_flushed_index && (!should_prepare_tables_anyway || prepared_tables >= expected_flushed_index))
                || is_shutdown;
        });

    if (!result)
    {
        throw Exception(ErrorCodes::TIMEOUT_EXCEEDED, "Timeout exceeded ({} s) while flushing system log '{}'.",
            toString(timeout_seconds), demangle(typeid(*this).name()));
    }

180 seconds of patience, then a TIMEOUT_EXCEEDED. The comment above it is a small piece of engineering honesty:

cpp 
// src/Common/SystemLogBase.cpp:188
    // Use an arbitrary timeout to avoid endless waiting. 60s proved to be
    // too fast for our parallel functional tests, probably because they
    // heavily load the disk.
    const int timeout_seconds = 180;

Note the “prepare tables” condition: SYSTEM FLUSH LOGS also waits for the table to exist, not just for the rows to be written. That is why SYSTEM FLUSH LOGS on a freshly started server creates the table.

The whole picture

text 
   query finishes
        |
        |  logQueryFinish(...) -> QueryLog::logQueryFinish
        v
   SystemLogBase::add(callback)
        |  element filled in place under a memory-tracker blocker
        v
   SystemLogQueue::push()
        |  under the mutex
        |  if size == half of max -> notify the flush thread
        |  if size == max      -> DROP the event, ++ignored_logs
        v
   [ queue: vector<QueryLogElement>, up to 1 048 576 rows ]
        |
        |  flush_event.wait_for(7.5 s)   <- the timer
        |  or woken by notifyFlush()
        v
   pop(): swap the queue out, advance queue_front_index
        |
        v
   flushImpl():
        |  prepareTable()      <- create the MergeTree table if missing
        |  build one Block from the whole batch
        |  InterpreterInsertQuery -> INSERT INTO system.query_log
        v
   [ a real MergeTree part ]
        |
        v
   merged, queried, TTLed, replicated -- like any other table

Trade-offs

What the “log is a real table” design buys you:

  • Full query power. system.query_log is a MergeTree table, so you can use system.query_log with PREWHERE, projections, skip indexes, FINAL, and every other MergeTree feature. A ring buffer or a CSV file gives you none of that.
  • The log is queryable while it is being written. The rows of the last 7.5 seconds are in memory, but everything before that is a normal part.
  • The log can be replicated, backed up, and shipped to a cluster with the same machinery as any other table.
  • Schema evolution is handled. A new enum value in a column means the old table is rotated and a new one created. Old data stays readable.
  • The write path is off the query’s critical path. The query thread only does a push_back under a mutex.

What it costs:

  • Up to 7.5 seconds of latency. A row appears in system.query_log up to 7.5 seconds after the query finished. This is the single most surprising thing about the query log, and it is why every monitoring script starts with SYSTEM FLUSH LOGS.
  • The log is lossy. When the queue is full, events are dropped and counted. Under a query storm, system.query_log will have holes. The LOG_ERROR about ignored logs is the only warning you get.
  • The flush is a full INSERT. Every 7.5 seconds, per log table, the server builds a query plan and runs an insert pipeline. With 30 log tables configured, that is 30 insert pipelines per 7.5 seconds. On a server with hundreds of log tables this is measurable.
  • The table can be dropped out from under the logger. The flush thread recreates it, but between the drop and the next flush, the log is silently going nowhere.
  • The Block is built in memory. A batch of a million log rows, each with a query string and a profile-events map, is a lot of RAM in one go. The max_size_rows bound is what keeps it finite.

Wrapping up

The one thing to remember: system.query_log is a real MergeTree table, but it is written by a background thread that batches rows in memory and flushes them every 7.5 seconds (or earlier, if the queue fills up). The query thread never touches the storage.

The part people get wrong: the log is not immediately visible. If you run a query and then immediately SELECT from system.query_log, the row may not be there. You need SYSTEM FLUSH LOGS first — or you need to wait 7.5 seconds.

What to go do about it: try it.

sql 
SELECT count() FROM system.query_log WHERE query LIKE '%flush%';

SYSTEM FLUSH LOGS query_log;

SELECT count() FROM system.query_log WHERE query LIKE '%flush%';

The second count is at least as large as the first — the SYSTEM FLUSH LOGS statement itself gets logged, and the flush is what makes it visible.

ClickhouseInternalsSystem tablesObservabilityPerformance