From adbaaca2f50194fd504bf3ee768a0365d0abff65 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ra=C3=BAl=20Mar=C3=ADn?= Date: Thu, 6 Oct 2022 14:22:44 +0200 Subject: [PATCH] QOL log improvements (#41947) * Uniformize disk reservation logs * Remove log about destroying stuff that appears all the time * More tweaks on disk reservation logs * Reorder logs in hash join * Remove log that provides little information * Collapse part removal logs Co-authored-by: Sergei Trifonov --- src/Disks/DiskLocal.cpp | 14 ++++++-- .../ObjectStorages/DiskObjectStorage.cpp | 14 ++++++-- src/Disks/StoragePolicy.cpp | 7 ++-- src/Interpreters/Aggregator.cpp | 2 -- src/Interpreters/Cache/FileSegment.cpp | 1 - src/Interpreters/HashJoin.cpp | 3 +- src/Interpreters/HashJoin.h | 6 ++-- src/Storages/MergeTree/MergeTreeData.cpp | 33 +++++++++++++------ 8 files changed, 52 insertions(+), 28 deletions(-) diff --git a/src/Disks/DiskLocal.cpp b/src/Disks/DiskLocal.cpp index 750d08ef80c..afd6a1b7b58 100644 --- a/src/Disks/DiskLocal.cpp +++ b/src/Disks/DiskLocal.cpp @@ -230,19 +230,27 @@ std::optional DiskLocal::tryReserve(UInt64 bytes) if (bytes == 0) { - LOG_DEBUG(logger, "Reserving 0 bytes on disk {}", backQuote(name)); + LOG_TRACE(logger, "Reserved 0 bytes on local disk {}", backQuote(name)); ++reservation_count; return {unreserved_space}; } if (unreserved_space >= bytes) { - LOG_DEBUG(logger, "Reserving {} on disk {}, having unreserved {}.", - ReadableSize(bytes), backQuote(name), ReadableSize(unreserved_space)); + LOG_TRACE( + logger, + "Reserved {} on local disk {}, having unreserved {}.", + ReadableSize(bytes), + backQuote(name), + ReadableSize(unreserved_space)); ++reservation_count; reserved_bytes += bytes; return {unreserved_space - bytes}; } + else + { + LOG_TRACE(logger, "Could not reserve {} on local disk {}. Not enough unreserved space", ReadableSize(bytes), backQuote(name)); + } return {}; } diff --git a/src/Disks/ObjectStorages/DiskObjectStorage.cpp b/src/Disks/ObjectStorages/DiskObjectStorage.cpp index d58d462a8d5..fb13ed7eec8 100644 --- a/src/Disks/ObjectStorages/DiskObjectStorage.cpp +++ b/src/Disks/ObjectStorages/DiskObjectStorage.cpp @@ -459,19 +459,27 @@ std::optional DiskObjectStorage::tryReserve(UInt64 bytes) if (bytes == 0) { - LOG_TRACE(log, "Reserving 0 bytes on remote_fs disk {}", backQuote(name)); + LOG_TRACE(log, "Reserved 0 bytes on remote disk {}", backQuote(name)); ++reservation_count; return {unreserved_space}; } if (unreserved_space >= bytes) { - LOG_TRACE(log, "Reserving {} on disk {}, having unreserved {}.", - ReadableSize(bytes), backQuote(name), ReadableSize(unreserved_space)); + LOG_TRACE( + log, + "Reserved {} on remote disk {}, having unreserved {}.", + ReadableSize(bytes), + backQuote(name), + ReadableSize(unreserved_space)); ++reservation_count; reserved_bytes += bytes; return {unreserved_space - bytes}; } + else + { + LOG_TRACE(log, "Could not reserve {} on remote disk {}. Not enough unreserved space", ReadableSize(bytes), backQuote(name)); + } return {}; } diff --git a/src/Disks/StoragePolicy.cpp b/src/Disks/StoragePolicy.cpp index 3662a9732b3..10513c6beae 100644 --- a/src/Disks/StoragePolicy.cpp +++ b/src/Disks/StoragePolicy.cpp @@ -5,6 +5,7 @@ #include #include +#include #include #include @@ -212,17 +213,15 @@ UInt64 StoragePolicy::getMaxUnreservedFreeSpace() const ReservationPtr StoragePolicy::reserve(UInt64 bytes, size_t min_volume_index) const { - LOG_TRACE(log, "Reserving bytes {} from volume index {}, total volumes {}", bytes, min_volume_index, volumes.size()); for (size_t i = min_volume_index; i < volumes.size(); ++i) { const auto & volume = volumes[i]; auto reservation = volume->reserve(bytes); if (reservation) - { - LOG_TRACE(log, "Successfully reserved {} bytes on volume index {}", bytes, i); return reservation; - } } + LOG_TRACE(log, "Could not reserve {} from volume index {}, total volumes {}", ReadableSize(bytes), min_volume_index, volumes.size()); + return {}; } diff --git a/src/Interpreters/Aggregator.cpp b/src/Interpreters/Aggregator.cpp index 4399faac5d2..3d68351110d 100644 --- a/src/Interpreters/Aggregator.cpp +++ b/src/Interpreters/Aggregator.cpp @@ -3275,8 +3275,6 @@ void Aggregator::destroyAllAggregateStates(AggregatedDataVariants & result) cons if (result.empty()) return; - LOG_TRACE(log, "Destroying aggregate states"); - /// In what data structure is the data aggregated? if (result.type == AggregatedDataVariants::Type::without_key || params.overflow_row) destroyWithoutKey(result); diff --git a/src/Interpreters/Cache/FileSegment.cpp b/src/Interpreters/Cache/FileSegment.cpp index 708d60f56dc..cbfc5e50ae4 100644 --- a/src/Interpreters/Cache/FileSegment.cpp +++ b/src/Interpreters/Cache/FileSegment.cpp @@ -249,7 +249,6 @@ FileSegment::RemoteFileReaderPtr FileSegment::extractRemoteFileReader() return nullptr; } - LOG_TRACE(log, "Extracted reader from file segment"); return std::move(remote_file_reader); } diff --git a/src/Interpreters/HashJoin.cpp b/src/Interpreters/HashJoin.cpp index e559977be49..aa606ce1ec2 100644 --- a/src/Interpreters/HashJoin.cpp +++ b/src/Interpreters/HashJoin.cpp @@ -224,6 +224,7 @@ HashJoin::HashJoin(std::shared_ptr table_join_, const Block & right_s , right_sample_block(right_sample_block_) , log(&Poco::Logger::get("HashJoin")) { + LOG_DEBUG(log, "HashJoin. Datatype: {}, kind: {}, strictness: {}", data->type, kind, strictness); LOG_DEBUG(log, "Right sample block: {}", right_sample_block.dumpStructure()); if (isCrossOrComma(kind)) @@ -303,8 +304,6 @@ HashJoin::HashJoin(std::shared_ptr table_join_, const Block & right_s for (auto & maps : data->maps) dataMapInit(maps); - - LOG_DEBUG(log, "Join type: {}, kind: {}, strictness: {}", data->type, kind, strictness); } HashJoin::Type HashJoin::chooseMethod(JoinKind kind, const ColumnRawPtrs & key_columns, Sizes & key_sizes) diff --git a/src/Interpreters/HashJoin.h b/src/Interpreters/HashJoin.h index 33955333aa2..50544ae9039 100644 --- a/src/Interpreters/HashJoin.h +++ b/src/Interpreters/HashJoin.h @@ -360,15 +360,15 @@ private: friend class JoinSource; std::shared_ptr table_join; - JoinKind kind; - JoinStrictness strictness; + const JoinKind kind; + const JoinStrictness strictness; /// This join was created from StorageJoin and it is already filled. bool from_storage_join = false; bool any_take_last_row; /// Overwrite existing values when encountering the same key again std::optional asof_type; - ASOFJoinInequality asof_inequality; + const ASOFJoinInequality asof_inequality; /// Right table data. StorageJoin shares it between many Join objects. /// Flags that indicate that particular row already used in join. diff --git a/src/Storages/MergeTree/MergeTreeData.cpp b/src/Storages/MergeTree/MergeTreeData.cpp index f519fd75ecb..4a7d2b2dd63 100644 --- a/src/Storages/MergeTree/MergeTreeData.cpp +++ b/src/Storages/MergeTree/MergeTreeData.cpp @@ -91,6 +91,18 @@ #include #include +#include + +template <> +struct fmt::formatter : fmt::formatter +{ + template + auto format(const DB::DataPartPtr & part, FormatCtx & ctx) const + { + return fmt::formatter::format(part->name, ctx); + } +}; + namespace fs = std::filesystem; @@ -1905,6 +1917,7 @@ void MergeTreeData::clearPartsFromFilesystemImpl(const DataPartsVector & parts_t ThreadPool pool(num_threads); /// NOTE: Under heavy system load you may get "Cannot schedule a task" from ThreadPool. + LOG_DEBUG(log, "Removing {} parts from filesystem: {} (concurrently)", parts_to_remove.size(), fmt::join(parts_to_remove, ", ")); for (const DataPartPtr & part : parts_to_remove) { pool.scheduleOrThrowOnError([&, thread_group = CurrentThread::getGroup()] @@ -1912,7 +1925,6 @@ void MergeTreeData::clearPartsFromFilesystemImpl(const DataPartsVector & parts_t if (thread_group) CurrentThread::attachToIfDetached(thread_group); - LOG_DEBUG(log, "Removing part from filesystem {} (concurrently)", part->name); part->remove(); if (part_names_succeed) { @@ -1924,11 +1936,11 @@ void MergeTreeData::clearPartsFromFilesystemImpl(const DataPartsVector & parts_t pool.wait(); } - else + else if (!parts_to_remove.empty()) { + LOG_DEBUG(log, "Removing {} parts from filesystem: {}", parts_to_remove.size(), fmt::join(parts_to_remove, ", ")); for (const DataPartPtr & part : parts_to_remove) { - LOG_DEBUG(log, "Removing part from filesystem {}", part->name); part->remove(); if (part_names_succeed) part_names_succeed->insert(part->name); @@ -4911,15 +4923,13 @@ ReservationPtr MergeTreeData::tryReserveSpacePreferringTTLRules( DiskPtr selected_disk) const { expected_size = std::max(RESERVATION_MIN_ESTIMATION_SIZE, expected_size); - - LOG_TRACE(log, "Trying reserve {} bytes preffering TTL rules", expected_size); ReservationPtr reservation; auto move_ttl_entry = selectTTLDescriptionForTTLInfos(metadata_snapshot->getMoveTTLs(), ttl_infos.moves_ttl, time_of_move, true); if (move_ttl_entry) { - LOG_TRACE(log, "Got move TTL entry, will try to reserver destination for move"); + LOG_TRACE(log, "Trying to reserve {} to apply a TTL rule. Will try to reserve in the destination", ReadableSize(expected_size)); SpacePtr destination_ptr = getDestinationForMoveTTL(*move_ttl_entry); bool perform_ttl_move_on_insert = is_insert && destination_ptr && shouldPerformTTLMoveOnInsert(destination_ptr); @@ -4949,11 +4959,9 @@ ReservationPtr MergeTreeData::tryReserveSpacePreferringTTLRules( } else { - LOG_TRACE(log, "Reserving bytes on selected destination"); reservation = destination_ptr->reserve(expected_size); if (reservation) { - LOG_TRACE(log, "Reservation successful"); return reservation; } else @@ -4977,13 +4985,18 @@ ReservationPtr MergeTreeData::tryReserveSpacePreferringTTLRules( // Prefer selected_disk if (selected_disk) { - LOG_DEBUG(log, "Disk for reservation provided: {} (with type {})", selected_disk->getName(), toString(selected_disk->getDataSourceDescription().type)); + LOG_TRACE( + log, + "Trying to reserve {} on the selected disk: {} (with type {})", + ReadableSize(expected_size), + selected_disk->getName(), + toString(selected_disk->getDataSourceDescription().type)); reservation = selected_disk->reserve(expected_size); } if (!reservation) { - LOG_DEBUG(log, "No reservation, reserving using storage policy from min volume index {}", min_volume_index); + LOG_TRACE(log, "Trying to reserve {} using storage policy from min volume index {}", ReadableSize(expected_size), min_volume_index); reservation = getStoragePolicy()->reserve(expected_size, min_volume_index); }