From 0ca2916163406db10894789f3d2fa5c6e9e04576 Mon Sep 17 00:00:00 2001 From: kssenii Date: Mon, 19 Jun 2023 17:16:09 +0200 Subject: [PATCH 1/3] More metrics in cache --- src/Common/ProfileEvents.cpp | 13 +++ .../IO/CachedOnDiskReadBufferFromFile.cpp | 2 + .../Cached/CachedObjectStorage.cpp | 1 + src/Interpreters/Cache/FileCache.cpp | 35 ++++++-- src/Interpreters/Cache/FileCache.h | 2 +- src/Interpreters/Cache/FileSegment.cpp | 88 +++++++++++++------ src/Interpreters/Cache/FileSegment.h | 3 +- src/Interpreters/Cache/Metadata.cpp | 44 ++++++++-- src/Interpreters/Cache/Metadata.h | 1 + 9 files changed, 142 insertions(+), 47 deletions(-) diff --git a/src/Common/ProfileEvents.cpp b/src/Common/ProfileEvents.cpp index f66f7bc6465..1b535f06cb3 100644 --- a/src/Common/ProfileEvents.cpp +++ b/src/Common/ProfileEvents.cpp @@ -386,6 +386,19 @@ The server successfully detected this situation and will download merged part fr \ M(FilesystemCacheEvictedBytes, "Number of bytes evicted from filesystem cache") \ M(FilesystemCacheEvictedFileSegments, "Number of file segments evicted from filesystem cache") \ + M(FilesystemCacheLockKeyMilliseconds, "Lock cache key time") \ + M(FilesystemCacheLockMetadataMilliseconds, "Lock filesystem cache metadata time") \ + M(FilesystemCacheLockCacheMilliseconds, "Lock filesystem cache time") \ + M(FilesystemCacheReserveMilliseconds, "Filesystem cache space reservation time") \ + M(FilesystemCacheGetOrSetMilliseconds, "Filesystem cache getOrSet() time") \ + M(FilesystemCacheGetMilliseconds, "Filesystem cache get() time") \ + M(FileSegmentWaitMilliseconds, "Wait on DOWNLOADING state") \ + M(FileSegmentCompleteMilliseconds, "Duration of FileSegment::complete() in filesystem cache") \ + M(FileSegmentLockMilliseconds, "Lock file segment time") \ + M(FileSegmentWriteMilliseconds, "File segment write() time") \ + M(FileSegmentUseMilliseconds, "File segment use() time") \ + M(FileSegmentRemoveMilliseconds, "File segment remove() time") \ + M(FileSegmentHolderCompleteMilliseconds, "File segments holder complete() time") \ \ M(RemoteFSSeeks, "Total number of seeks for async buffer") \ M(RemoteFSPrefetches, "Number of prefetches made with asynchronous reading from remote filesystem") \ diff --git a/src/Disks/IO/CachedOnDiskReadBufferFromFile.cpp b/src/Disks/IO/CachedOnDiskReadBufferFromFile.cpp index 6317aba20e9..518a0e46b82 100644 --- a/src/Disks/IO/CachedOnDiskReadBufferFromFile.cpp +++ b/src/Disks/IO/CachedOnDiskReadBufferFromFile.cpp @@ -401,6 +401,8 @@ CachedOnDiskReadBufferFromFile::getImplementationBuffer(FileSegment & file_segme current_file_segment_counters.increment( ProfileEvents::FileSegmentWaitReadBufferMicroseconds, watch.elapsedMicroseconds()); + ProfileEvents::increment(ProfileEvents::FileSegmentWaitReadBufferMicroseconds); + [[maybe_unused]] auto download_current_segment = read_type == ReadType::REMOTE_FS_READ_AND_PUT_IN_CACHE; chassert(download_current_segment == file_segment.isDownloader()); diff --git a/src/Disks/ObjectStorages/Cached/CachedObjectStorage.cpp b/src/Disks/ObjectStorages/Cached/CachedObjectStorage.cpp index 3e73e45638b..b1cf8226895 100644 --- a/src/Disks/ObjectStorages/Cached/CachedObjectStorage.cpp +++ b/src/Disks/ObjectStorages/Cached/CachedObjectStorage.cpp @@ -138,6 +138,7 @@ void CachedObjectStorage::removeCacheIfExists(const std::string & path_key_for_c void CachedObjectStorage::removeObject(const StoredObject & object) { + removeCacheIfExists(object.remote_path); object_storage->removeObject(object); } diff --git a/src/Interpreters/Cache/FileCache.cpp b/src/Interpreters/Cache/FileCache.cpp index e6bc8b1f79b..128cf2b5ca8 100644 --- a/src/Interpreters/Cache/FileCache.cpp +++ b/src/Interpreters/Cache/FileCache.cpp @@ -11,6 +11,7 @@ #include #include #include +#include #include @@ -21,6 +22,10 @@ namespace ProfileEvents { extern const Event FilesystemCacheEvictedBytes; extern const Event FilesystemCacheEvictedFileSegments; + extern const Event FilesystemCacheLockCacheMilliseconds; + extern const Event FilesystemCacheReserveMilliseconds; + extern const Event FilesystemCacheGetOrSetMilliseconds; + extern const Event FilesystemCacheGetMilliseconds; } namespace @@ -129,6 +134,12 @@ void FileCache::initialize() cleanup_task->scheduleAfter(delayed_cleanup_interval_ms); } +CacheGuard::Lock FileCache::lockCache() const +{ + ProfileEventTimeIncrement watch(ProfileEvents::FilesystemCacheLockCacheMilliseconds); + return cache_guard.lock(); +} + FileSegments FileCache::getImpl(const LockedKey & locked_key, const FileSegment::Range & range) const { /// Given range = [left, right] and non-overlapping ordered set of file segments, @@ -414,6 +425,8 @@ FileSegmentsHolderPtr FileCache::set( FileSegmentsHolderPtr FileCache::getOrSet(const Key & key, size_t offset, size_t size, size_t file_size, const CreateFileSegmentSettings & settings) { + ProfileEventTimeIncrement watch(ProfileEvents::FilesystemCacheGetOrSetMilliseconds); + assertInitialized(); const auto aligned_offset = roundDownToMultiple(offset, boundary_alignment); @@ -448,6 +461,8 @@ FileCache::getOrSet(const Key & key, size_t offset, size_t size, size_t file_siz FileSegmentsHolderPtr FileCache::get(const Key & key, size_t offset, size_t size) { + ProfileEventTimeIncrement watch(ProfileEvents::FilesystemCacheGetMilliseconds); + assertInitialized(); auto locked_key = metadata.lockKeyMetadata(key, CacheMetadata::KeyNotFoundPolicy::RETURN_NULL); @@ -562,8 +577,10 @@ KeyMetadata::iterator FileCache::addFileSegment( bool FileCache::tryReserve(FileSegment & file_segment, const size_t size) { + ProfileEventTimeIncrement watch(ProfileEvents::FilesystemCacheReserveMilliseconds); + assertInitialized(); - auto cache_lock = cache_guard.lock(); + auto cache_lock = lockCache(); LOG_TEST( log, "Trying to reserve space ({} bytes) for {}:{}, current usage {}/{}", @@ -799,7 +816,7 @@ void FileCache::removeAllReleasable() /// `remove_persistent_files` defines whether non-evictable by some criteria files /// (they do not comply with the cache eviction policy) should also be removed. - auto lock = cache_guard.lock(); + auto lock = lockCache(); main_priority->iterate([&](LockedKey & locked_key, FileSegmentMetadataPtr segment_metadata) { @@ -822,7 +839,7 @@ void FileCache::removeAllReleasable() void FileCache::loadMetadata() { - auto lock = cache_guard.lock(); + auto lock = lockCache(); UInt64 offset = 0; size_t size = 0; @@ -1039,7 +1056,7 @@ FileSegmentsHolderPtr FileCache::dumpQueue() { file_segments.push_back(FileSegment::getSnapshot(segment_metadata->file_segment)); return PriorityIterationResult::CONTINUE; - }, cache_guard.lock()); + }, lockCache()); return std::make_unique(std::move(file_segments)); } @@ -1064,17 +1081,17 @@ std::vector FileCache::tryGetCachePaths(const Key & key) size_t FileCache::getUsedCacheSize() const { - return main_priority->getSize(cache_guard.lock()); + return main_priority->getSize(lockCache()); } size_t FileCache::getFileSegmentsNum() const { - return main_priority->getElementsCount(cache_guard.lock()); + return main_priority->getElementsCount(lockCache()); } void FileCache::assertCacheCorrectness() { - auto lock = cache_guard.lock(); + auto lock = lockCache(); main_priority->iterate([&](LockedKey &, FileSegmentMetadataPtr segment_metadata) { const auto & file_segment = *segment_metadata->file_segment; @@ -1100,7 +1117,7 @@ FileCache::QueryContextHolder::~QueryContextHolder() /// the query has been completed and the query_context is released. if (context && context.use_count() == 2) { - auto lock = cache->cache_guard.lock(); + auto lock = cache->lockCache(); cache->query_limit->removeQueryContext(query_id, lock); } } @@ -1111,7 +1128,7 @@ FileCache::QueryContextHolderPtr FileCache::getQueryContextHolder( if (!query_limit || settings.filesystem_cache_max_download_size == 0) return {}; - auto lock = cache_guard.lock(); + auto lock = lockCache(); auto context = query_limit->getOrSetQueryContext(query_id, settings, lock); return std::make_unique(query_id, this, std::move(context)); } diff --git a/src/Interpreters/Cache/FileCache.h b/src/Interpreters/Cache/FileCache.h index 71fc1722844..dc5dd67710c 100644 --- a/src/Interpreters/Cache/FileCache.h +++ b/src/Interpreters/Cache/FileCache.h @@ -125,7 +125,7 @@ public: using QueryContextHolderPtr = std::unique_ptr; QueryContextHolderPtr getQueryContextHolder(const String & query_id, const ReadSettings & settings); - CacheGuard::Lock lockCache() { return cache_guard.lock(); } + CacheGuard::Lock lockCache() const; private: using KeyAndOffset = FileCacheKeyAndOffset; diff --git a/src/Interpreters/Cache/FileSegment.cpp b/src/Interpreters/Cache/FileSegment.cpp index 7b82c58080c..ad838b9fbbe 100644 --- a/src/Interpreters/Cache/FileSegment.cpp +++ b/src/Interpreters/Cache/FileSegment.cpp @@ -9,11 +9,22 @@ #include #include #include +#include #include namespace fs = std::filesystem; +namespace ProfileEvents +{ + extern const Event FileSegmentWaitMilliseconds; + extern const Event FileSegmentCompleteMilliseconds; + extern const Event FileSegmentLockMilliseconds; + extern const Event FileSegmentWriteMilliseconds; + extern const Event FileSegmentUseMilliseconds; + extern const Event FileSegmentHolderCompleteMilliseconds; +} + namespace DB { @@ -83,9 +94,15 @@ FileSegment::FileSegment( } } +FileSegment::Range::Range(size_t left_, size_t right_) : left(left_), right(right_) +{ + if (left > right) + throw Exception(ErrorCodes::LOGICAL_ERROR, "Attempt to create incorrect range: [{}, {}]", left, right); +} + FileSegment::State FileSegment::state() const { - auto lock = segment_guard.lock(); + auto lock = lockFileSegment(); return download_state; } @@ -94,6 +111,12 @@ String FileSegment::getPathInLocalCache() const return getKeyMetadata()->getFileSegmentPath(*this); } +FileSegmentGuard::Lock FileSegment::lockFileSegment() const +{ + ProfileEventTimeIncrement watch(ProfileEvents::FileSegmentLockMilliseconds); + return segment_guard.lock(); +} + void FileSegment::setDownloadState(State state, const FileSegmentGuard::Lock & lock) { if (isCompleted(false) && state != State::DETACHED) @@ -110,19 +133,19 @@ void FileSegment::setDownloadState(State state, const FileSegmentGuard::Lock & l size_t FileSegment::getReservedSize() const { - auto lock = segment_guard.lock(); + auto lock = lockFileSegment(); return reserved_size; } FileSegment::Priority::Iterator FileSegment::getQueueIterator() const { - auto lock = segment_guard.lock(); + auto lock = lockFileSegment(); return queue_iterator; } void FileSegment::setQueueIterator(Priority::Iterator iterator) { - auto lock = segment_guard.lock(); + auto lock = lockFileSegment(); if (queue_iterator) throw Exception(ErrorCodes::LOGICAL_ERROR, "Queue iterator cannot be set twice"); queue_iterator = iterator; @@ -150,14 +173,14 @@ size_t FileSegment::getDownloadedSize(bool sync) const void FileSegment::setDownloadedSize(size_t delta) { - auto lock = segment_guard.lock(); + auto lock = lockFileSegment(); downloaded_size += delta; assert(downloaded_size == std::filesystem::file_size(getPathInLocalCache())); } bool FileSegment::isDownloaded() const { - auto lock = segment_guard.lock(); + auto lock = lockFileSegment(); return download_state == State::DOWNLOADED; } @@ -173,7 +196,7 @@ String FileSegment::getCallerId() String FileSegment::getDownloader() const { - auto lock = segment_guard.lock(); + auto lock = lockFileSegment(); return getDownloaderUnlocked(lock); } @@ -184,7 +207,7 @@ String FileSegment::getDownloaderUnlocked(const FileSegmentGuard::Lock &) const String FileSegment::getOrSetDownloader() { - auto lock = segment_guard.lock(); + auto lock = lockFileSegment(); assertNotDetachedUnlocked(lock); @@ -220,7 +243,7 @@ void FileSegment::resetDownloadingStateUnlocked(const FileSegmentGuard::Lock & l void FileSegment::resetDownloader() { - auto lock = segment_guard.lock(); + auto lock = lockFileSegment(); SCOPE_EXIT({ cv.notify_all(); }); @@ -255,7 +278,7 @@ void FileSegment::assertIsDownloaderUnlocked(const std::string & operation, cons bool FileSegment::isDownloader() const { - auto lock = segment_guard.lock(); + auto lock = lockFileSegment(); return isDownloaderUnlocked(lock); } @@ -266,14 +289,14 @@ bool FileSegment::isDownloaderUnlocked(const FileSegmentGuard::Lock & lock) cons FileSegment::RemoteFileReaderPtr FileSegment::getRemoteFileReader() { - auto lock = segment_guard.lock(); + auto lock = lockFileSegment(); assertIsDownloaderUnlocked("getRemoteFileReader", lock); return remote_file_reader; } void FileSegment::resetRemoteFileReader() { - auto lock = segment_guard.lock(); + auto lock = lockFileSegment(); assertIsDownloaderUnlocked("resetRemoteFileReader", lock); remote_file_reader.reset(); } @@ -287,7 +310,7 @@ FileSegment::RemoteFileReaderPtr FileSegment::extractRemoteFileReader() return std::move(remote_file_reader); } - auto segment_lock = segment_guard.lock(); + auto segment_lock = lockFileSegment(); assert(download_state != State::DETACHED); @@ -300,7 +323,7 @@ FileSegment::RemoteFileReaderPtr FileSegment::extractRemoteFileReader() void FileSegment::setRemoteFileReader(RemoteFileReaderPtr remote_file_reader_) { - auto lock = segment_guard.lock(); + auto lock = lockFileSegment(); assertIsDownloaderUnlocked("setRemoteFileReader", lock); if (remote_file_reader) @@ -311,13 +334,15 @@ void FileSegment::setRemoteFileReader(RemoteFileReaderPtr remote_file_reader_) void FileSegment::write(const char * from, size_t size, size_t offset) { + ProfileEventTimeIncrement watch(ProfileEvents::FileSegmentWriteMilliseconds); + if (!size) throw Exception(ErrorCodes::LOGICAL_ERROR, "Writing zero size is not allowed"); const auto file_segment_path = getPathInLocalCache(); { - auto lock = segment_guard.lock(); + auto lock = lockFileSegment(); assertIsDownloaderUnlocked("write", lock); assertNotDetachedUnlocked(lock); @@ -372,7 +397,7 @@ void FileSegment::write(const char * from, size_t size, size_t offset) } catch (ErrnoException & e) { - auto lock = segment_guard.lock(); + auto lock = lockFileSegment(); e.addMessage(fmt::format("{}, current cache state: {}", e.what(), getInfoForLogUnlocked(lock))); int code = e.getErrno(); @@ -392,7 +417,7 @@ void FileSegment::write(const char * from, size_t size, size_t offset) } catch (Exception & e) { - auto lock = segment_guard.lock(); + auto lock = lockFileSegment(); e.addMessage(fmt::format("{}, current cache state: {}", e.what(), getInfoForLogUnlocked(lock))); setDownloadFailedUnlocked(lock); throw; @@ -405,7 +430,7 @@ FileSegment::State FileSegment::wait(size_t offset) { OpenTelemetry::SpanHolder span{fmt::format("FileSegment::wait({})", key().toString())}; - auto lock = segment_guard.lock(); + auto lock = lockFileSegment(); if (downloader_id.empty() || offset < getCurrentWriteOffset(true)) return download_state; @@ -416,13 +441,14 @@ FileSegment::State FileSegment::wait(size_t offset) if (download_state == State::DOWNLOADING) { LOG_TEST(log, "{} waiting on: {}, current downloader: {}", getCallerId(), range().toString(), downloader_id); + ProfileEventTimeIncrement watch(ProfileEvents::FileSegmentWaitMilliseconds); chassert(!getDownloaderUnlocked(lock).empty()); chassert(!isDownloaderUnlocked(lock)); [[maybe_unused]] const auto ok = cv.wait_for(lock, std::chrono::seconds(60), [&, this]() { - return download_state != State::DOWNLOADING || offset < getCurrentWriteOffset(true); + return download_state != State::DOWNLOADING || offset < getCurrentWriteOffset(false); }); /// chassert(ok); } @@ -507,7 +533,7 @@ bool FileSegment::reserve(size_t size_to_reserve) reserved = cache->tryReserve(*this, size_to_reserve); if (!reserved) - setDownloadFailedUnlocked(segment_guard.lock()); + setDownloadFailedUnlocked(lockFileSegment()); return reserved; } @@ -549,7 +575,7 @@ void FileSegment::setDownloadFailedUnlocked(const FileSegmentGuard::Lock & lock) void FileSegment::completePartAndResetDownloader() { - auto lock = segment_guard.lock(); + auto lock = lockFileSegment(); SCOPE_EXIT({ cv.notify_all(); }); @@ -569,6 +595,8 @@ void FileSegment::completePartAndResetDownloader() void FileSegment::complete() { + ProfileEventTimeIncrement watch(ProfileEvents::FileSegmentCompleteMilliseconds); + if (isCompleted()) return; @@ -582,7 +610,7 @@ void FileSegment::complete() throw Exception(ErrorCodes::LOGICAL_ERROR, "Cannot complete file segment: {}", getInfoForLog()); } - auto segment_lock = segment_guard.lock(); + auto segment_lock = lockFileSegment(); if (isCompleted(false)) return; @@ -687,7 +715,7 @@ void FileSegment::complete() String FileSegment::getInfoForLog() const { - auto lock = segment_guard.lock(); + auto lock = lockFileSegment(); return getInfoForLogUnlocked(lock); } @@ -731,7 +759,7 @@ String FileSegment::stateToString(FileSegment::State state) bool FileSegment::assertCorrectness() const { - return assertCorrectnessUnlocked(segment_guard.lock()); + return assertCorrectnessUnlocked(lockFileSegment()); } bool FileSegment::assertCorrectnessUnlocked(const FileSegmentGuard::Lock &) const @@ -779,7 +807,7 @@ bool FileSegment::assertCorrectnessUnlocked(const FileSegmentGuard::Lock &) cons void FileSegment::assertNotDetached() const { - auto lock = segment_guard.lock(); + auto lock = lockFileSegment(); assertNotDetachedUnlocked(lock); } @@ -797,7 +825,7 @@ void FileSegment::assertNotDetachedUnlocked(const FileSegmentGuard::Lock & lock) FileSegmentPtr FileSegment::getSnapshot(const FileSegmentPtr & file_segment) { - auto lock = file_segment->segment_guard.lock(); + auto lock = file_segment->lockFileSegment(); auto snapshot = std::make_shared( file_segment->key(), @@ -816,7 +844,7 @@ FileSegmentPtr FileSegment::getSnapshot(const FileSegmentPtr & file_segment) bool FileSegment::isDetached() const { - auto lock = segment_guard.lock(); + auto lock = lockFileSegment(); return download_state == State::DETACHED; } @@ -832,7 +860,7 @@ bool FileSegment::isCompleted(bool sync) const if (is_completed_state()) return true; - auto lock = segment_guard.lock(); + auto lock = lockFileSegment(); return is_completed_state(); } @@ -858,6 +886,8 @@ void FileSegment::detach(const FileSegmentGuard::Lock & lock, const LockedKey &) void FileSegment::use() { + ProfileEventTimeIncrement watch(ProfileEvents::FileSegmentUseMilliseconds); + if (!cache) { chassert(isCompleted(true)); @@ -880,6 +910,8 @@ FileSegments::iterator FileSegmentsHolder::completeAndPopFrontImpl() FileSegmentsHolder::~FileSegmentsHolder() { + ProfileEventTimeIncrement watch(ProfileEvents::FileSegmentHolderCompleteMilliseconds); + if (!complete_on_dtor) return; diff --git a/src/Interpreters/Cache/FileSegment.h b/src/Interpreters/Cache/FileSegment.h index 5bf0a9cdcf3..681c0d719e4 100644 --- a/src/Interpreters/Cache/FileSegment.h +++ b/src/Interpreters/Cache/FileSegment.h @@ -130,7 +130,7 @@ public: size_t left; size_t right; - Range(size_t left_, size_t right_) : left(left_), right(right_) {} + Range(size_t left_, size_t right_); bool operator==(const Range & other) const { return left == other.left && right == other.right; } @@ -293,6 +293,7 @@ private: bool assertCorrectnessUnlocked(const FileSegmentGuard::Lock &) const; LockedKeyPtr lockKeyMetadata(bool assert_exists = true) const; + FileSegmentGuard::Lock lockFileSegment() const; Key file_key; Range segment_range; diff --git a/src/Interpreters/Cache/Metadata.cpp b/src/Interpreters/Cache/Metadata.cpp index c9a23d1c785..9ab304b598b 100644 --- a/src/Interpreters/Cache/Metadata.cpp +++ b/src/Interpreters/Cache/Metadata.cpp @@ -2,10 +2,17 @@ #include #include #include +#include #include namespace fs = std::filesystem; +namespace ProfileEvents +{ + extern const Event FilesystemCacheLockKeyMilliseconds; + extern const Event FilesystemCacheLockMetadataMilliseconds; +} + namespace DB { @@ -69,6 +76,8 @@ LockedKeyPtr KeyMetadata::lock() LockedKeyPtr KeyMetadata::tryLock() { + ProfileEventTimeIncrement watch(ProfileEvents::FilesystemCacheLockKeyMilliseconds); + auto locked = std::make_unique(shared_from_this()); if (key_state == KeyMetadata::KeyState::ACTIVE) return locked; @@ -156,6 +165,12 @@ String CacheMetadata::getPathForKey(const Key & key) const return fs::path(path) / key_str.substr(0, 3) / key_str; } +CacheMetadataGuard::Lock CacheMetadata::lockMetadata() const +{ + ProfileEventTimeIncrement watch(ProfileEvents::FilesystemCacheLockMetadataMilliseconds); + return guard.lock(); +} + LockedKeyPtr CacheMetadata::lockKeyMetadata( const FileCacheKey & key, KeyNotFoundPolicy key_not_found_policy, @@ -163,7 +178,7 @@ LockedKeyPtr CacheMetadata::lockKeyMetadata( { KeyMetadataPtr key_metadata; { - auto lock = guard.lock(); + auto lock = lockMetadata(); auto it = find(key); if (it == end()) @@ -182,9 +197,13 @@ LockedKeyPtr CacheMetadata::lockKeyMetadata( } { - auto locked_metadata = std::make_unique(key_metadata); - const auto key_state = locked_metadata->getKeyState(); + LockedKeyPtr locked_metadata; + { + ProfileEventTimeIncrement watch(ProfileEvents::FilesystemCacheLockKeyMilliseconds); + locked_metadata = std::make_unique(key_metadata); + } + const auto key_state = locked_metadata->getKeyState(); if (key_state == KeyMetadata::KeyState::ACTIVE) return locked_metadata; @@ -213,10 +232,15 @@ LockedKeyPtr CacheMetadata::lockKeyMetadata( void CacheMetadata::iterate(IterateCacheMetadataFunc && func) { - auto lock = guard.lock(); + auto lock = lockMetadata(); for (const auto & [key, key_metadata] : *this) { - auto locked_key = std::make_unique(key_metadata); + LockedKeyPtr locked_key; + { + ProfileEventTimeIncrement watch(ProfileEvents::FilesystemCacheLockKeyMilliseconds); + locked_key = std::make_unique(key_metadata); + } + const auto key_state = locked_key->getKeyState(); if (key_state == KeyMetadata::KeyState::ACTIVE) @@ -235,7 +259,7 @@ void CacheMetadata::iterate(IterateCacheMetadataFunc && func) void CacheMetadata::doCleanup() { - auto lock = guard.lock(); + auto lock = lockMetadata(); FileCacheKey cleanup_key; while (cleanup_queue->tryPop(cleanup_key)) @@ -244,9 +268,13 @@ void CacheMetadata::doCleanup() if (it == end()) continue; - auto locked_metadata = std::make_unique(it->second); - const auto key_state = locked_metadata->getKeyState(); + LockedKeyPtr locked_metadata; + { + ProfileEventTimeIncrement watch(ProfileEvents::FilesystemCacheLockKeyMilliseconds); + locked_metadata = std::make_unique(it->second); + } + const auto key_state = locked_metadata->getKeyState(); if (key_state == KeyMetadata::KeyState::ACTIVE) { /// Key was added back to cache after we submitted it to removal queue. diff --git a/src/Interpreters/Cache/Metadata.h b/src/Interpreters/Cache/Metadata.h index 3fd6176f201..bf79bafd659 100644 --- a/src/Interpreters/Cache/Metadata.h +++ b/src/Interpreters/Cache/Metadata.h @@ -110,6 +110,7 @@ public: void doCleanup(); private: + CacheMetadataGuard::Lock lockMetadata() const; const std::string path; /// Cache base path CacheMetadataGuard guard; const CleanupQueuePtr cleanup_queue; From ec86028fd88424c303a523f525e84e0566bdf3ad Mon Sep 17 00:00:00 2001 From: kssenii Date: Mon, 19 Jun 2023 17:44:28 +0200 Subject: [PATCH 2/3] Change to microseconds --- src/Common/ProfileEvents.cpp | 27 +++++++++---------- .../IO/CachedOnDiskReadBufferFromFile.cpp | 2 +- src/Interpreters/Cache/FileCache.cpp | 16 +++++------ src/Interpreters/Cache/FileSegment.cpp | 24 ++++++++--------- src/Interpreters/Cache/Metadata.cpp | 14 +++++----- src/Interpreters/Cache/Metadata.h | 2 +- 6 files changed, 42 insertions(+), 43 deletions(-) diff --git a/src/Common/ProfileEvents.cpp b/src/Common/ProfileEvents.cpp index 1b535f06cb3..dfa14548091 100644 --- a/src/Common/ProfileEvents.cpp +++ b/src/Common/ProfileEvents.cpp @@ -386,19 +386,19 @@ The server successfully detected this situation and will download merged part fr \ M(FilesystemCacheEvictedBytes, "Number of bytes evicted from filesystem cache") \ M(FilesystemCacheEvictedFileSegments, "Number of file segments evicted from filesystem cache") \ - M(FilesystemCacheLockKeyMilliseconds, "Lock cache key time") \ - M(FilesystemCacheLockMetadataMilliseconds, "Lock filesystem cache metadata time") \ - M(FilesystemCacheLockCacheMilliseconds, "Lock filesystem cache time") \ - M(FilesystemCacheReserveMilliseconds, "Filesystem cache space reservation time") \ - M(FilesystemCacheGetOrSetMilliseconds, "Filesystem cache getOrSet() time") \ - M(FilesystemCacheGetMilliseconds, "Filesystem cache get() time") \ - M(FileSegmentWaitMilliseconds, "Wait on DOWNLOADING state") \ - M(FileSegmentCompleteMilliseconds, "Duration of FileSegment::complete() in filesystem cache") \ - M(FileSegmentLockMilliseconds, "Lock file segment time") \ - M(FileSegmentWriteMilliseconds, "File segment write() time") \ - M(FileSegmentUseMilliseconds, "File segment use() time") \ - M(FileSegmentRemoveMilliseconds, "File segment remove() time") \ - M(FileSegmentHolderCompleteMilliseconds, "File segments holder complete() time") \ + M(FilesystemCacheLockKeyMicroseconds, "Lock cache key time") \ + M(FilesystemCacheLockMetadataMicroseconds, "Lock filesystem cache metadata time") \ + M(FilesystemCacheLockCacheMicroseconds, "Lock filesystem cache time") \ + M(FilesystemCacheReserveMicroseconds, "Filesystem cache space reservation time") \ + M(FilesystemCacheGetOrSetMicroseconds, "Filesystem cache getOrSet() time") \ + M(FilesystemCacheGetMicroseconds, "Filesystem cache get() time") \ + M(FileSegmentWaitMicroseconds, "Wait on DOWNLOADING state") \ + M(FileSegmentCompleteMicroseconds, "Duration of FileSegment::complete() in filesystem cache") \ + M(FileSegmentLockMicroseconds, "Lock file segment time") \ + M(FileSegmentWriteMicroseconds, "File segment write() time") \ + M(FileSegmentUseMicroseconds, "File segment use() time") \ + M(FileSegmentRemoveMicroseconds, "File segment remove() time") \ + M(FileSegmentHolderCompleteMicroseconds, "File segments holder complete() time") \ \ M(RemoteFSSeeks, "Total number of seeks for async buffer") \ M(RemoteFSPrefetches, "Number of prefetches made with asynchronous reading from remote filesystem") \ @@ -420,7 +420,6 @@ The server successfully detected this situation and will download merged part fr \ M(FileSegmentWaitReadBufferMicroseconds, "Metric per file segment. Time spend waiting for internal read buffer (includes cache waiting)") \ M(FileSegmentReadMicroseconds, "Metric per file segment. Time spend reading from file") \ - M(FileSegmentWriteMicroseconds, "Metric per file segment. Time spend writing cache") \ M(FileSegmentCacheWriteMicroseconds, "Metric per file segment. Time spend writing data to cache") \ M(FileSegmentPredownloadMicroseconds, "Metric per file segment. Time spent predownloading data to cache (predownloading - finishing file segment download (after someone who failed to do that) up to the point current thread was requested to do)") \ M(FileSegmentUsedBytes, "Metric per file segment. How many bytes were actually used from current file segment") \ diff --git a/src/Disks/IO/CachedOnDiskReadBufferFromFile.cpp b/src/Disks/IO/CachedOnDiskReadBufferFromFile.cpp index 518a0e46b82..64f8e553d35 100644 --- a/src/Disks/IO/CachedOnDiskReadBufferFromFile.cpp +++ b/src/Disks/IO/CachedOnDiskReadBufferFromFile.cpp @@ -401,7 +401,7 @@ CachedOnDiskReadBufferFromFile::getImplementationBuffer(FileSegment & file_segme current_file_segment_counters.increment( ProfileEvents::FileSegmentWaitReadBufferMicroseconds, watch.elapsedMicroseconds()); - ProfileEvents::increment(ProfileEvents::FileSegmentWaitReadBufferMicroseconds); + ProfileEvents::increment(ProfileEvents::FileSegmentWaitReadBufferMicroseconds, watch.elapsedMicroseconds()); [[maybe_unused]] auto download_current_segment = read_type == ReadType::REMOTE_FS_READ_AND_PUT_IN_CACHE; chassert(download_current_segment == file_segment.isDownloader()); diff --git a/src/Interpreters/Cache/FileCache.cpp b/src/Interpreters/Cache/FileCache.cpp index 128cf2b5ca8..ec9220af955 100644 --- a/src/Interpreters/Cache/FileCache.cpp +++ b/src/Interpreters/Cache/FileCache.cpp @@ -22,10 +22,10 @@ namespace ProfileEvents { extern const Event FilesystemCacheEvictedBytes; extern const Event FilesystemCacheEvictedFileSegments; - extern const Event FilesystemCacheLockCacheMilliseconds; - extern const Event FilesystemCacheReserveMilliseconds; - extern const Event FilesystemCacheGetOrSetMilliseconds; - extern const Event FilesystemCacheGetMilliseconds; + extern const Event FilesystemCacheLockCacheMicroseconds; + extern const Event FilesystemCacheReserveMicroseconds; + extern const Event FilesystemCacheGetOrSetMicroseconds; + extern const Event FilesystemCacheGetMicroseconds; } namespace @@ -136,7 +136,7 @@ void FileCache::initialize() CacheGuard::Lock FileCache::lockCache() const { - ProfileEventTimeIncrement watch(ProfileEvents::FilesystemCacheLockCacheMilliseconds); + ProfileEventTimeIncrement watch(ProfileEvents::FilesystemCacheLockCacheMicroseconds); return cache_guard.lock(); } @@ -425,7 +425,7 @@ FileSegmentsHolderPtr FileCache::set( FileSegmentsHolderPtr FileCache::getOrSet(const Key & key, size_t offset, size_t size, size_t file_size, const CreateFileSegmentSettings & settings) { - ProfileEventTimeIncrement watch(ProfileEvents::FilesystemCacheGetOrSetMilliseconds); + ProfileEventTimeIncrement watch(ProfileEvents::FilesystemCacheGetOrSetMicroseconds); assertInitialized(); @@ -461,7 +461,7 @@ FileCache::getOrSet(const Key & key, size_t offset, size_t size, size_t file_siz FileSegmentsHolderPtr FileCache::get(const Key & key, size_t offset, size_t size) { - ProfileEventTimeIncrement watch(ProfileEvents::FilesystemCacheGetMilliseconds); + ProfileEventTimeIncrement watch(ProfileEvents::FilesystemCacheGetMicroseconds); assertInitialized(); @@ -577,7 +577,7 @@ KeyMetadata::iterator FileCache::addFileSegment( bool FileCache::tryReserve(FileSegment & file_segment, const size_t size) { - ProfileEventTimeIncrement watch(ProfileEvents::FilesystemCacheReserveMilliseconds); + ProfileEventTimeIncrement watch(ProfileEvents::FilesystemCacheReserveMicroseconds); assertInitialized(); auto cache_lock = lockCache(); diff --git a/src/Interpreters/Cache/FileSegment.cpp b/src/Interpreters/Cache/FileSegment.cpp index ad838b9fbbe..95592fc7c12 100644 --- a/src/Interpreters/Cache/FileSegment.cpp +++ b/src/Interpreters/Cache/FileSegment.cpp @@ -17,12 +17,12 @@ namespace fs = std::filesystem; namespace ProfileEvents { - extern const Event FileSegmentWaitMilliseconds; - extern const Event FileSegmentCompleteMilliseconds; - extern const Event FileSegmentLockMilliseconds; - extern const Event FileSegmentWriteMilliseconds; - extern const Event FileSegmentUseMilliseconds; - extern const Event FileSegmentHolderCompleteMilliseconds; + extern const Event FileSegmentWaitMicroseconds; + extern const Event FileSegmentCompleteMicroseconds; + extern const Event FileSegmentLockMicroseconds; + extern const Event FileSegmentWriteMicroseconds; + extern const Event FileSegmentUseMicroseconds; + extern const Event FileSegmentHolderCompleteMicroseconds; } namespace DB @@ -113,7 +113,7 @@ String FileSegment::getPathInLocalCache() const FileSegmentGuard::Lock FileSegment::lockFileSegment() const { - ProfileEventTimeIncrement watch(ProfileEvents::FileSegmentLockMilliseconds); + ProfileEventTimeIncrement watch(ProfileEvents::FileSegmentLockMicroseconds); return segment_guard.lock(); } @@ -334,7 +334,7 @@ void FileSegment::setRemoteFileReader(RemoteFileReaderPtr remote_file_reader_) void FileSegment::write(const char * from, size_t size, size_t offset) { - ProfileEventTimeIncrement watch(ProfileEvents::FileSegmentWriteMilliseconds); + ProfileEventTimeIncrement watch(ProfileEvents::FileSegmentWriteMicroseconds); if (!size) throw Exception(ErrorCodes::LOGICAL_ERROR, "Writing zero size is not allowed"); @@ -441,7 +441,7 @@ FileSegment::State FileSegment::wait(size_t offset) if (download_state == State::DOWNLOADING) { LOG_TEST(log, "{} waiting on: {}, current downloader: {}", getCallerId(), range().toString(), downloader_id); - ProfileEventTimeIncrement watch(ProfileEvents::FileSegmentWaitMilliseconds); + ProfileEventTimeIncrement watch(ProfileEvents::FileSegmentWaitMicroseconds); chassert(!getDownloaderUnlocked(lock).empty()); chassert(!isDownloaderUnlocked(lock)); @@ -595,7 +595,7 @@ void FileSegment::completePartAndResetDownloader() void FileSegment::complete() { - ProfileEventTimeIncrement watch(ProfileEvents::FileSegmentCompleteMilliseconds); + ProfileEventTimeIncrement watch(ProfileEvents::FileSegmentCompleteMicroseconds); if (isCompleted()) return; @@ -886,7 +886,7 @@ void FileSegment::detach(const FileSegmentGuard::Lock & lock, const LockedKey &) void FileSegment::use() { - ProfileEventTimeIncrement watch(ProfileEvents::FileSegmentUseMilliseconds); + ProfileEventTimeIncrement watch(ProfileEvents::FileSegmentUseMicroseconds); if (!cache) { @@ -910,7 +910,7 @@ FileSegments::iterator FileSegmentsHolder::completeAndPopFrontImpl() FileSegmentsHolder::~FileSegmentsHolder() { - ProfileEventTimeIncrement watch(ProfileEvents::FileSegmentHolderCompleteMilliseconds); + ProfileEventTimeIncrement watch(ProfileEvents::FileSegmentHolderCompleteMicroseconds); if (!complete_on_dtor) return; diff --git a/src/Interpreters/Cache/Metadata.cpp b/src/Interpreters/Cache/Metadata.cpp index 9ab304b598b..20af931bbc2 100644 --- a/src/Interpreters/Cache/Metadata.cpp +++ b/src/Interpreters/Cache/Metadata.cpp @@ -9,8 +9,8 @@ namespace fs = std::filesystem; namespace ProfileEvents { - extern const Event FilesystemCacheLockKeyMilliseconds; - extern const Event FilesystemCacheLockMetadataMilliseconds; + extern const Event FilesystemCacheLockKeyMicroseconds; + extern const Event FilesystemCacheLockMetadataMicroseconds; } namespace DB @@ -76,7 +76,7 @@ LockedKeyPtr KeyMetadata::lock() LockedKeyPtr KeyMetadata::tryLock() { - ProfileEventTimeIncrement watch(ProfileEvents::FilesystemCacheLockKeyMilliseconds); + ProfileEventTimeIncrement watch(ProfileEvents::FilesystemCacheLockKeyMicroseconds); auto locked = std::make_unique(shared_from_this()); if (key_state == KeyMetadata::KeyState::ACTIVE) @@ -167,7 +167,7 @@ String CacheMetadata::getPathForKey(const Key & key) const CacheMetadataGuard::Lock CacheMetadata::lockMetadata() const { - ProfileEventTimeIncrement watch(ProfileEvents::FilesystemCacheLockMetadataMilliseconds); + ProfileEventTimeIncrement watch(ProfileEvents::FilesystemCacheLockMetadataMicroseconds); return guard.lock(); } @@ -199,7 +199,7 @@ LockedKeyPtr CacheMetadata::lockKeyMetadata( { LockedKeyPtr locked_metadata; { - ProfileEventTimeIncrement watch(ProfileEvents::FilesystemCacheLockKeyMilliseconds); + ProfileEventTimeIncrement watch(ProfileEvents::FilesystemCacheLockKeyMicroseconds); locked_metadata = std::make_unique(key_metadata); } @@ -237,7 +237,7 @@ void CacheMetadata::iterate(IterateCacheMetadataFunc && func) { LockedKeyPtr locked_key; { - ProfileEventTimeIncrement watch(ProfileEvents::FilesystemCacheLockKeyMilliseconds); + ProfileEventTimeIncrement watch(ProfileEvents::FilesystemCacheLockKeyMicroseconds); locked_key = std::make_unique(key_metadata); } @@ -270,7 +270,7 @@ void CacheMetadata::doCleanup() LockedKeyPtr locked_metadata; { - ProfileEventTimeIncrement watch(ProfileEvents::FilesystemCacheLockKeyMilliseconds); + ProfileEventTimeIncrement watch(ProfileEvents::FilesystemCacheLockKeyMicroseconds); locked_metadata = std::make_unique(it->second); } diff --git a/src/Interpreters/Cache/Metadata.h b/src/Interpreters/Cache/Metadata.h index bf79bafd659..6172808bcf5 100644 --- a/src/Interpreters/Cache/Metadata.h +++ b/src/Interpreters/Cache/Metadata.h @@ -112,7 +112,7 @@ public: private: CacheMetadataGuard::Lock lockMetadata() const; const std::string path; /// Cache base path - CacheMetadataGuard guard; + mutable CacheMetadataGuard guard; const CleanupQueuePtr cleanup_queue; Poco::Logger * log; }; From 7f9cd56f618a11ef2a22dd6241c1920cbe57587f Mon Sep 17 00:00:00 2001 From: kssenii Date: Mon, 19 Jun 2023 19:22:45 +0200 Subject: [PATCH 3/3] One more --- src/Common/ProfileEvents.cpp | 1 + src/Disks/IO/CachedOnDiskReadBufferFromFile.cpp | 6 ++++++ 2 files changed, 7 insertions(+) diff --git a/src/Common/ProfileEvents.cpp b/src/Common/ProfileEvents.cpp index dfa14548091..ffd7f8ca696 100644 --- a/src/Common/ProfileEvents.cpp +++ b/src/Common/ProfileEvents.cpp @@ -381,6 +381,7 @@ The server successfully detected this situation and will download merged part fr M(CachedReadBufferReadFromCacheBytes, "Bytes read from filesystem cache") \ M(CachedReadBufferCacheWriteBytes, "Bytes written from source (remote fs, etc) to filesystem cache") \ M(CachedReadBufferCacheWriteMicroseconds, "Time spent writing data into filesystem cache") \ + M(CachedReadBufferCreateBufferMicroseconds, "Prepare buffer time") \ M(CachedWriteBufferCacheWriteBytes, "Bytes written from source (remote fs, etc) to filesystem cache") \ M(CachedWriteBufferCacheWriteMicroseconds, "Time spent writing data into filesystem cache") \ \ diff --git a/src/Disks/IO/CachedOnDiskReadBufferFromFile.cpp b/src/Disks/IO/CachedOnDiskReadBufferFromFile.cpp index 64f8e553d35..20751731a27 100644 --- a/src/Disks/IO/CachedOnDiskReadBufferFromFile.cpp +++ b/src/Disks/IO/CachedOnDiskReadBufferFromFile.cpp @@ -8,6 +8,7 @@ #include #include #include +#include #include #include @@ -26,6 +27,7 @@ extern const Event CachedReadBufferCacheWriteMicroseconds; extern const Event CachedReadBufferReadFromSourceBytes; extern const Event CachedReadBufferReadFromCacheBytes; extern const Event CachedReadBufferCacheWriteBytes; +extern const Event CachedReadBufferCreateBufferMicroseconds; } namespace DB @@ -145,6 +147,8 @@ void CachedOnDiskReadBufferFromFile::initialize(size_t offset, size_t size) CachedOnDiskReadBufferFromFile::ImplementationBufferPtr CachedOnDiskReadBufferFromFile::getCacheReadBuffer(const FileSegment & file_segment) const { + ProfileEventTimeIncrement watch(ProfileEvents::CachedReadBufferCreateBufferMicroseconds); + /// Use is_persistent flag from in-memory state of the filesegment, /// because it is consistent with what is written on disk. auto path = file_segment.getPathInLocalCache(); @@ -167,6 +171,8 @@ CachedOnDiskReadBufferFromFile::getCacheReadBuffer(const FileSegment & file_segm CachedOnDiskReadBufferFromFile::ImplementationBufferPtr CachedOnDiskReadBufferFromFile::getRemoteReadBuffer(FileSegment & file_segment, ReadType read_type_) { + ProfileEventTimeIncrement watch(ProfileEvents::CachedReadBufferCreateBufferMicroseconds); + switch (read_type_) { case ReadType::REMOTE_FS_READ_AND_PUT_IN_CACHE: