From f6259fbd65b144d7a7b163c7967f031465b30855 Mon Sep 17 00:00:00 2001 From: Robert Schulze Date: Sun, 29 Jan 2023 11:00:05 +0000 Subject: [PATCH 1/2] Query cache: Improve logging --- src/Interpreters/Cache/QueryCache.cpp | 17 +++++++++++++++-- 1 file changed, 15 insertions(+), 2 deletions(-) diff --git a/src/Interpreters/Cache/QueryCache.cpp b/src/Interpreters/Cache/QueryCache.cpp index 06fd0689993..4cf943a348a 100644 --- a/src/Interpreters/Cache/QueryCache.cpp +++ b/src/Interpreters/Cache/QueryCache.cpp @@ -186,7 +186,10 @@ QueryCache::Writer::Writer(std::mutex & mutex_, Cache & cache_, const Key & key_ , min_query_runtime(min_query_runtime_) { if (auto it = cache.find(key); it != cache.end() && !is_stale(it->first)) + { skip_insert = true; /// Key already contained in cache and did not expire yet --> don't replace it + LOG_TRACE(&Poco::Logger::get("QueryResultCache"), "Skipped insert (non-stale entry found), query: {}", key.queryStringFromAst()); + } } void QueryCache::Writer::buffer(Chunk && partial_query_result) @@ -205,6 +208,7 @@ void QueryCache::Writer::buffer(Chunk && partial_query_result) { chunks->clear(); /// eagerly free some space skip_insert = true; + LOG_TRACE(&Poco::Logger::get("QueryResultCache"), "Skipped insert (query result too big), new_entry_size_in_bytes: {} ({}), new_entry_size_in_rows: {} ({}), query: {}", new_entry_size_in_bytes, max_entry_size_in_bytes, new_entry_size_in_rows, max_entry_size_in_rows, key.queryStringFromAst()); } } @@ -214,12 +218,19 @@ void QueryCache::Writer::finalizeWrite() return; if (std::chrono::duration_cast(std::chrono::system_clock::now() - query_start_time) < min_query_runtime) + { + LOG_TRACE(&Poco::Logger::get("QueryResultCache"), "Skipped insert (query not expensive enough), query: {}", key.queryStringFromAst()); return; + } std::lock_guard lock(mutex); if (auto it = cache.find(key); it != cache.end() && !is_stale(it->first)) - return; /// same check as in ctor because a parallel Writer could have inserted the current key in the meantime + { + /// same check as in ctor because a parallel Writer could have inserted the current key in the meantime + LOG_TRACE(&Poco::Logger::get("QueryResultCache"), "Skipped insert (non-stale entry found), query: {}", key.queryStringFromAst()); + return; + } auto sufficient_space_in_cache = [this]() TSA_REQUIRES(mutex) { @@ -243,7 +254,9 @@ void QueryCache::Writer::finalizeWrite() } /// Insert or replace if enough space - if (sufficient_space_in_cache()) + if (!sufficient_space_in_cache()) + LOG_TRACE(&Poco::Logger::get("QueryResultCache"), "Skipped insert (insufficient cache space), query: {}", key.queryStringFromAst()); + else { cache_size_in_bytes += query_result.sizeInBytes(); if (auto it = cache.find(key); it != cache.end()) From 8a9493aeb9ecc978fbc2e92090447969315f7608 Mon Sep 17 00:00:00 2001 From: Robert Schulze Date: Wed, 1 Feb 2023 11:28:00 +0100 Subject: [PATCH 2/2] Update QueryCache.cpp --- src/Interpreters/Cache/QueryCache.cpp | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/Interpreters/Cache/QueryCache.cpp b/src/Interpreters/Cache/QueryCache.cpp index 4cf943a348a..0cdc2695f61 100644 --- a/src/Interpreters/Cache/QueryCache.cpp +++ b/src/Interpreters/Cache/QueryCache.cpp @@ -253,11 +253,11 @@ void QueryCache::Writer::finalizeWrite() LOG_TRACE(&Poco::Logger::get("QueryCache"), "Removed {} stale entries", removed_items); } - /// Insert or replace if enough space if (!sufficient_space_in_cache()) - LOG_TRACE(&Poco::Logger::get("QueryResultCache"), "Skipped insert (insufficient cache space), query: {}", key.queryStringFromAst()); + LOG_TRACE(&Poco::Logger::get("QueryResultCache"), "Skipped insert (cache has insufficient space), query: {}", key.queryStringFromAst()); else { + //// Insert or replace key cache_size_in_bytes += query_result.sizeInBytes(); if (auto it = cache.find(key); it != cache.end()) cache_size_in_bytes -= it->second.sizeInBytes(); // key replacement