Merge pull request #49690 from kssenii/add-logging-for-try-reserve

Add some logging

src/Interpreters/Cache/FileCache.cpp

@@ -533,6 +533,11 @@ bool FileCache::tryReserve(FileSegment & file_segment, size_t size)
     assertInitialized();
     auto cache_lock = cache_guard.lock();
 
+    LOG_TEST(
+        log, "Trying to reserve space ({} bytes) for {}:{}, current usage {}/{}",
+        size, file_segment.key(), file_segment.offset(),
+        main_priority->getSize(cache_lock), main_priority->getSizeLimit());
+
     /// In case of per query cache limit (by default disabled), we add/remove entries from both
     /// (main_priority and query_priority) priority queues, but iterate entries in order of query_priority,
     /// while checking the limits in both.
@@ -545,7 +550,17 @@ bool FileCache::tryReserve(FileSegment & file_segment, size_t size)
 
         const bool query_limit_exceeded = query_priority->getSize(cache_lock) + size > query_priority->getSizeLimit();
         if (query_limit_exceeded && !query_context->recacheOnFileCacheQueryLimitExceeded())
+        {
+            LOG_TEST(log, "Query limit exceeded, space reservation failed, "
+                     "recache_on_query_limit_exceeded is disabled (while reserving for {}:{})",
+                     file_segment.key(), file_segment.offset());
             return false;
+        }
+
+        LOG_TEST(
+            log, "Using query limit, current usage: {}/{} (while reserving for {}:{})",
+            query_priority->getSize(cache_lock), query_priority->getSizeLimit(),
+            file_segment.key(), file_segment.offset());
     }
 
     size_t queue_size = main_priority->getElementsCount(cache_lock);
@@ -630,6 +645,10 @@ bool FileCache::tryReserve(FileSegment & file_segment, size_t size)
 
         if (is_query_priority_overflow())
             return false;
+
+        LOG_TEST(
+            log, "Query limits satisfied (while reserving for {}:{})",
+            file_segment.key(), file_segment.offset());
     }
 
     auto is_main_priority_overflow = [&]

src/Interpreters/Cache/FileSegment.cpp

@@ -753,7 +753,7 @@ bool FileSegment::assertCorrectnessUnlocked(const FileSegmentGuard::Lock &) cons
     }
     else
     {
-        if (download_state == State::DOWNLOADED)
+        if (download_state == State::DOWNLOADING)
         {
             chassert(!downloader_id.empty());
         }

src/Interpreters/Cache/LRUFileCachePriority.cpp

@@ -32,7 +32,8 @@ IFileCachePriority::Iterator LRUFileCachePriority::add(
         if (entry.size != 0 && entry.key == key && entry.offset == offset)
             throw Exception(
                 ErrorCodes::LOGICAL_ERROR,
-                "Attempt to add duplicate queue entry to queue. (Key: {}, offset: {}, size: {})",
+                "Attempt to add duplicate queue entry to queue. "
+                "(Key: {}, offset: {}, size: {})",
                 entry.key, entry.offset, entry.size);
     }
 #endif
@@ -46,14 +47,15 @@ IFileCachePriority::Iterator LRUFileCachePriority::add(
             key, offset, size, current_size, getSizeLimit());
     }
 
-    current_size += size;
-
     auto iter = queue.insert(queue.end(), Entry(key, offset, size, key_metadata));
+    current_size += size;
 
     CurrentMetrics::add(CurrentMetrics::FilesystemCacheSize, size);
     CurrentMetrics::add(CurrentMetrics::FilesystemCacheElements);
 
-    LOG_TEST(log, "Added entry into LRU queue, key: {}, offset: {}, size: {}", key, offset, size);
+    LOG_TEST(
+        log, "Added entry into LRU queue, key: {}, offset: {}, size: {}",
+        key, offset, size);
 
     return std::make_shared<LRUFileCacheIterator>(this, iter);
 }
@@ -81,13 +83,18 @@ LRUFileCachePriority::LRUQueueIterator LRUFileCachePriority::remove(LRUQueueIter
     CurrentMetrics::sub(CurrentMetrics::FilesystemCacheSize, it->size);
     CurrentMetrics::sub(CurrentMetrics::FilesystemCacheElements);
 
-    LOG_TEST(log, "Removed entry from LRU queue, key: {}, offset: {}", it->key, it->offset);
+    LOG_TEST(
+        log, "Removed entry from LRU queue, key: {}, offset: {}, size: {}",
+        it->key, it->offset, it->size);
+
     return queue.erase(it);
 }
 
 LRUFileCachePriority::LRUFileCacheIterator::LRUFileCacheIterator(
-    LRUFileCachePriority * cache_priority_, LRUFileCachePriority::LRUQueueIterator queue_iter_)
-    : cache_priority(cache_priority_), queue_iter(queue_iter_)
+    LRUFileCachePriority * cache_priority_,
+    LRUFileCachePriority::LRUQueueIterator queue_iter_)
+    : cache_priority(cache_priority_)
+    , queue_iter(queue_iter_)
 {
 }
 
@@ -113,7 +120,8 @@ void LRUFileCachePriority::iterate(IterateFunc && func, const CacheGuard::Lock &
         {
             throw Exception(
                 ErrorCodes::LOGICAL_ERROR,
-                "Mismatch of file segment size in file segment metadata and priority queue: {} != {} ({})",
+                "Mismatch of file segment size in file segment metadata "
+                "and priority queue: {} != {} ({})",
                 it->size, metadata->size(), metadata->file_segment->getInfoForLog());
         }
 
@@ -138,28 +146,26 @@ void LRUFileCachePriority::iterate(IterateFunc && func, const CacheGuard::Lock &
     }
 }
 
-LRUFileCachePriority::Iterator LRUFileCachePriority::LRUFileCacheIterator::remove(const CacheGuard::Lock &)
+LRUFileCachePriority::Iterator
+LRUFileCachePriority::LRUFileCacheIterator::remove(const CacheGuard::Lock &)
 {
-    return std::make_shared<LRUFileCacheIterator>(cache_priority, cache_priority->remove(queue_iter));
+    return std::make_shared<LRUFileCacheIterator>(
+        cache_priority, cache_priority->remove(queue_iter));
 }
 
 void LRUFileCachePriority::LRUFileCacheIterator::annul()
 {
-    cache_priority->current_size -= queue_iter->size;
-    queue_iter->size = 0;
+    updateSize(-queue_iter->size);
+    chassert(queue_iter->size == 0);
 }
 
 void LRUFileCachePriority::LRUFileCacheIterator::updateSize(int64_t size)
 {
     cache_priority->current_size += size;
-
-    if (size > 0)
-        CurrentMetrics::add(CurrentMetrics::FilesystemCacheSize, size);
-    else
-        CurrentMetrics::sub(CurrentMetrics::FilesystemCacheSize, size);
-
     queue_iter->size += size;
 
+    CurrentMetrics::add(CurrentMetrics::FilesystemCacheSize, size);
+
     chassert(cache_priority->current_size >= 0);
     chassert(queue_iter->size >= 0);
 }

src/Interpreters/Cache/Metadata.cpp

@@ -336,13 +336,18 @@ void LockedKey::removeAllReleasable()
 
 KeyMetadata::iterator LockedKey::removeFileSegment(size_t offset, const FileSegmentGuard::Lock & segment_lock)
 {
-    LOG_DEBUG(log, "Remove from cache. Key: {}, offset: {}", getKey(), offset);
-
     auto it = key_metadata->find(offset);
     if (it == key_metadata->end())
         throw Exception(ErrorCodes::LOGICAL_ERROR, "There is no offset {}", offset);
 
     auto file_segment = it->second->file_segment;
+
+    LOG_DEBUG(
+        log, "Remove from cache. Key: {}, offset: {}, size: {}",
+        getKey(), offset, file_segment->reserved_size);
+
+    chassert(file_segment->assertCorrectnessUnlocked(segment_lock));
+
     if (file_segment->queue_iterator)
         file_segment->queue_iterator->annul();