From 917a9f47b9014b5ee19bb97b07b83934955aaa98 Mon Sep 17 00:00:00 2001
From: Robert Schulze <robert@clickhouse.com>
Date: Mon, 4 Sep 2023 16:54:50 +0000
Subject: [PATCH] Query cache: Log caching of entries

---
 src/Interpreters/Cache/QueryCache.cpp | 19 ++++++++++---------
 src/Interpreters/Cache/QueryCache.h   |  3 +++
 2 files changed, 13 insertions(+), 9 deletions(-)

diff --git a/src/Interpreters/Cache/QueryCache.cpp b/src/Interpreters/Cache/QueryCache.cpp
index 5283e307f2d..972b6e4a3cb 100644
--- a/src/Interpreters/Cache/QueryCache.cpp
+++ b/src/Interpreters/Cache/QueryCache.cpp
@@ -7,7 +7,6 @@
 #include <Parsers/ASTSetQuery.h>
 #include <Parsers/IAST.h>
 #include <Parsers/formatAST.h>
-#include <Common/logger_useful.h>
 #include <Common/ProfileEvents.h>
 #include <Common/SipHash.h>
 #include <Common/TTLCachePolicy.h>
@@ -191,7 +190,7 @@ QueryCache::Writer::Writer(
     if (auto entry = cache.getWithKey(key); entry.has_value() && !IsStale()(entry->key))
     {
         skip_insert = true; /// Key already contained in cache and did not expire yet --> don't replace it
-        LOG_TRACE(&Poco::Logger::get("QueryCache"), "Skipped insert (non-stale entry found), query: {}", key.query_string);
+        LOG_TRACE(logger, "Skipped insert (non-stale entry found), query: {}", key.query_string);
     }
 }
 
@@ -263,14 +262,14 @@ void QueryCache::Writer::finalizeWrite()
 
     if (std::chrono::duration_cast<std::chrono::milliseconds>(std::chrono::system_clock::now() - query_start_time) < min_query_runtime)
     {
-        LOG_TRACE(&Poco::Logger::get("QueryCache"), "Skipped insert (query not expensive enough), query: {}", key.query_string);
+        LOG_TRACE(logger, "Skipped insert (query not expensive enough), query: {}", key.query_string);
         return;
     }
 
     if (auto entry = cache.getWithKey(key); entry.has_value() && !IsStale()(entry->key))
     {
         /// Same check as in ctor because a parallel Writer could have inserted the current key in the meantime
-        LOG_TRACE(&Poco::Logger::get("QueryCache"), "Skipped insert (non-stale entry found), query: {}", key.query_string);
+        LOG_TRACE(logger, "Skipped insert (non-stale entry found), query: {}", key.query_string);
         return;
     }
 
@@ -353,12 +352,14 @@ void QueryCache::Writer::finalizeWrite()
 
     if ((new_entry_size_in_bytes > max_entry_size_in_bytes) || (new_entry_size_in_rows > max_entry_size_in_rows))
     {
-        LOG_TRACE(&Poco::Logger::get("QueryCache"), "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.query_string);
+        LOG_TRACE(logger, "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.query_string);
         return;
     }
 
     cache.set(key, query_result);
 
+    LOG_TRACE(logger, "Stored result of query: {}", key.query_string);
+
     was_finalized = true;
 }
 
@@ -388,7 +389,7 @@ QueryCache::Reader::Reader(Cache & cache_, const Key & key, const std::lock_guar
 
     if (!entry.has_value())
     {
-        LOG_TRACE(&Poco::Logger::get("QueryCache"), "No entry found for query {}", key.query_string);
+        LOG_TRACE(logger, "No entry found for query {}", key.query_string);
         return;
     }
 
@@ -397,13 +398,13 @@ QueryCache::Reader::Reader(Cache & cache_, const Key & key, const std::lock_guar
 
     if (!entry_key.is_shared && entry_key.user_name != key.user_name)
     {
-        LOG_TRACE(&Poco::Logger::get("QueryCache"), "Inaccessible entry found for query {}", key.query_string);
+        LOG_TRACE(logger, "Inaccessible entry found for query {}", key.query_string);
         return;
     }
 
     if (IsStale()(entry_key))
     {
-        LOG_TRACE(&Poco::Logger::get("QueryCache"), "Stale entry found for query {}", key.query_string);
+        LOG_TRACE(logger, "Stale entry found for query {}", key.query_string);
         return;
     }
 
@@ -441,7 +442,7 @@ QueryCache::Reader::Reader(Cache & cache_, const Key & key, const std::lock_guar
         buildSourceFromChunks(entry_key.header, std::move(decompressed_chunks), entry_mapped->totals, entry_mapped->extremes);
     }
 
-    LOG_TRACE(&Poco::Logger::get("QueryCache"), "Entry found for query {}", key.query_string);
+    LOG_TRACE(logger, "Entry found for query {}", key.query_string);
 }
 
 bool QueryCache::Reader::hasCacheEntryForKey() const
diff --git a/src/Interpreters/Cache/QueryCache.h b/src/Interpreters/Cache/QueryCache.h
index 44099cfe61d..d3c98dbd97a 100644
--- a/src/Interpreters/Cache/QueryCache.h
+++ b/src/Interpreters/Cache/QueryCache.h
@@ -1,6 +1,7 @@
 #pragma once
 
 #include <Common/CacheBase.h>
+#include <Common/logger_useful.h>
 #include <Core/Block.h>
 #include <Parsers/IAST_fwd.h>
 #include <Processors/Sources/SourceFromChunks.h>
@@ -144,6 +145,7 @@ public:
         Cache::MappedPtr query_result TSA_GUARDED_BY(mutex) = std::make_shared<Entry>();
         std::atomic<bool> skip_insert = false;
         bool was_finalized = false;
+        Poco::Logger * logger = &Poco::Logger::get("QueryCache");
 
         Writer(Cache & cache_, const Key & key_,
             size_t max_entry_size_in_bytes_, size_t max_entry_size_in_rows_,
@@ -170,6 +172,7 @@ public:
         std::unique_ptr<SourceFromChunks> source_from_chunks;
         std::unique_ptr<SourceFromChunks> source_from_chunks_totals;
         std::unique_ptr<SourceFromChunks> source_from_chunks_extremes;
+        Poco::Logger * logger = &Poco::Logger::get("QueryCache");
         friend class QueryCache; /// for createReader()
     };