Better system.part_log. [#CLICKHOUSE-3342]

dbms/src/Common/ErrorCodes.cpp

@@ -365,6 +365,7 @@ namespace ErrorCodes
     extern const int NO_COMMON_TYPE = 386;
     extern const int EXTERNAL_LOADABLE_ALREADY_EXISTS = 387;
     extern const int CANNOT_ASSIGN_OPTIMIZE = 388;
+    extern const int INSERT_WAS_DEDUPLICATED = 389;
 
     extern const int KEEPER_EXCEPTION = 999;
     extern const int POCO_EXCEPTION = 1000;

dbms/src/DataTypes/DataTypeEnum.h

@@ -58,7 +58,7 @@ private:
     void fillMaps();
 
 public:
-    DataTypeEnum(const Values & values_);
+    explicit DataTypeEnum(const Values & values_);
     DataTypeEnum(const DataTypeEnum & other);
 
     const Values & getValues() const { return values; }

dbms/src/Interpreters/PartLog.cpp

@@ -6,6 +6,7 @@
 #include <DataTypes/DataTypeDateTime.h>
 #include <DataTypes/DataTypeDate.h>
 #include <DataTypes/DataTypeString.h>
+#include <DataTypes/DataTypeEnum.h>
 #include <Storages/MergeTree/MergeTreeDataPart.h>
 #include <Storages/MergeTree/MergeTreeData.h>
 #include <Interpreters/PartLog.h>
@@ -16,21 +17,38 @@ namespace DB
 
 Block PartLogElement::createBlock()
 {
+    auto event_type_datatype = std::make_shared<DataTypeEnum8>(
+        DataTypeEnum8::Values{
+            {"NEW_PART",       static_cast<Int8>(NEW_PART)},
+            {"MERGE_PARTS",    static_cast<Int8>(MERGE_PARTS)},
+            {"DOWNLOAD_PART",  static_cast<Int8>(DOWNLOAD_PART)},
+            {"REMOVE_PART",    static_cast<Int8>(REMOVE_PART)}
+        }
+    );
+
     return
     {
-        {ColumnUInt8::create(),   std::make_shared<DataTypeUInt8>(),      "event_type"},
-
-        {ColumnUInt16::create(),  std::make_shared<DataTypeDate>(),       "event_date"},
-        {ColumnUInt32::create(),  std::make_shared<DataTypeDateTime>(),   "event_time"},
-
-        {ColumnUInt64::create(),  std::make_shared<DataTypeUInt64>(),     "size_in_bytes"},
-        {ColumnUInt64::create(),  std::make_shared<DataTypeUInt64>(),     "duration_ms"},
-
-        {ColumnString::create(),  std::make_shared<DataTypeString>(),     "database"},
-        {ColumnString::create(),  std::make_shared<DataTypeString>(),     "table"},
-        {ColumnString::create(),  std::make_shared<DataTypeString>(),     "part_name"},
-        {ColumnArray::create(ColumnString::create()),
-            std::make_shared<DataTypeArray>(std::make_shared<DataTypeString>()),    "merged_from"},
+        {ColumnInt8::create(),    std::move(event_type_datatype),       "event_type"},
+        {ColumnUInt16::create(),  std::make_shared<DataTypeDate>(),     "event_date"},
+        {ColumnUInt32::create(),  std::make_shared<DataTypeDateTime>(), "event_time"},
+        {ColumnUInt64::create(),  std::make_shared<DataTypeUInt64>(),   "duration_ms"},
+
+        {ColumnString::create(),  std::make_shared<DataTypeString>(),   "database"},
+        {ColumnString::create(),  std::make_shared<DataTypeString>(),   "table"},
+        {ColumnString::create(),  std::make_shared<DataTypeString>(),   "part_name"},
+
+        {ColumnUInt64::create(),  std::make_shared<DataTypeUInt64>(),   "rows"},
+        {ColumnUInt64::create(),  std::make_shared<DataTypeUInt64>(),   "size_in_bytes"}, // On disk
+
+        /// Merge-specific info
+        {ColumnArray::create(ColumnString::create()), std::make_shared<DataTypeArray>(std::make_shared<DataTypeString>()), "merged_from"},
+        {ColumnUInt64::create(),  std::make_shared<DataTypeUInt64>(),   "bytes_uncompressed"}, // Result bytes
+        {ColumnUInt64::create(),  std::make_shared<DataTypeUInt64>(),   "read_rows"},
+        {ColumnUInt64::create(),  std::make_shared<DataTypeUInt64>(),   "read_bytes"},
+
+        /// Is there an error during the execution or commit
+        {ColumnUInt16::create(),  std::make_shared<DataTypeUInt16>(),   "error"},
+        {ColumnString::create(),  std::make_shared<DataTypeString>(),   "exception"},
   };
 }
 
@@ -40,41 +58,71 @@ void PartLogElement::appendToBlock(Block & block) const
 
     size_t i = 0;
 
-    columns[i++]->insert(UInt64(event_type));
+    columns[i++]->insert(Int64(event_type));
     columns[i++]->insert(UInt64(DateLUT::instance().toDayNum(event_time)));
     columns[i++]->insert(UInt64(event_time));
-
-    columns[i++]->insert(UInt64(size_in_bytes));
     columns[i++]->insert(UInt64(duration_ms));
 
     columns[i++]->insert(database_name);
     columns[i++]->insert(table_name);
     columns[i++]->insert(part_name);
 
-    Array merged_from_array;
-    merged_from_array.reserve(merged_from.size());
-    for (const auto & name : merged_from)
-        merged_from_array.push_back(name);
+    columns[i++]->insert(UInt64(rows));
+    columns[i++]->insert(UInt64(bytes_compressed_on_disk));
+
+    Array source_part_names_array;
+    source_part_names_array.reserve(source_part_names.size());
+    for (const auto & name : source_part_names)
+        source_part_names_array.push_back(name);
+
+    columns[i++]->insert(source_part_names_array);
+
+    columns[i++]->insert(UInt64(bytes_uncompressed));
+    columns[i++]->insert(UInt64(rows_read));
+    columns[i++]->insert(UInt64(bytes_read_uncompressed));
 
-    columns[i++]->insert(merged_from_array);
+    columns[i++]->insert(UInt64(error));
+    columns[i++]->insert(exception);
 
     block.setColumns(std::move(columns));
 }
 
-void PartLog::addNewPart(const MergeTreeDataPart & part, double elapsed)
+
+bool PartLog::addNewPartToTheLog(Context & context, const MergeTreeDataPart & part, UInt64 elapsed_ns, const ExecutionStatus & execution_status)
 {
-    PartLogElement elem;
-    elem.event_time = time(nullptr);
+    PartLog * part_log = nullptr;
+
+    try
+    {
+        part_log = context.getPartLog(part.storage.getDatabaseName(), part.storage.getTableName());
+        if (!part_log)
+            return false;
+
+        PartLogElement elem;
 
-    elem.event_type = PartLogElement::NEW_PART;
-    elem.size_in_bytes = part.size_in_bytes;
-    elem.duration_ms = elapsed / 1000000;
+        elem.event_type = PartLogElement::NEW_PART;
+        elem.event_time = time(nullptr);
+        elem.duration_ms = elapsed_ns / 1000000;
 
-    elem.database_name = part.storage.getDatabaseName();
-    elem.table_name = part.storage.getTableName();
-    elem.part_name = part.name;
+        elem.database_name = part.storage.getDatabaseName();
+        elem.table_name = part.storage.getTableName();
+        elem.part_name = part.name;
+
+        elem.bytes_compressed_on_disk = part.size_in_bytes;
+        elem.rows = part.rows_count;
+
+        elem.error = static_cast<UInt16>(execution_status.code);
+        elem.exception = execution_status.message;
+
+        part_log->add(elem);
+    }
+    catch (...)
+    {
+        tryLogCurrentException(part_log ? part_log->log : &Logger::get("PartLog"), __PRETTY_FUNCTION__);
+        return false;
+    }
 
-    add(elem);
+    return true;
 }
 
 }

dbms/src/Interpreters/PartLog.h

@@ -18,15 +18,28 @@ struct PartLogElement
 
     Type event_type = NEW_PART;
 
-    time_t event_time{};
-
-    UInt64 size_in_bytes{};
-    UInt64 duration_ms{};
+    time_t event_time = 0;
+    UInt64 duration_ms = 0;
 
     String database_name;
     String table_name;
     String part_name;
-    Strings merged_from;
+
+    /// Size of the part
+    UInt64 rows = 0;
+
+    /// Size of files in filesystem
+    UInt64 bytes_compressed_on_disk = 0;
+
+    //// Make sense for Merges
+    Strings source_part_names;
+    UInt64 bytes_uncompressed = 0;
+    UInt64 rows_read = 0;
+    UInt64 bytes_read_uncompressed = 0;
+
+    /// Is the operation was successful?
+    UInt16 error = 0;
+    String exception;
 
     static std::string name() { return "PartLog"; }
 
@@ -44,7 +57,8 @@ class PartLog : public SystemLog<PartLogElement>
 
 public:
     /// Add a record about creation of new part.
-    void addNewPart(const MergeTreeDataPart & part, double elapsed);
+    static bool addNewPartToTheLog(Context & context, const MergeTreeDataPart & part, UInt64 elapsed_ns,
+                                   const ExecutionStatus & execution_status = {});
 };
 
 }

dbms/src/Interpreters/SystemLog.h

@@ -101,7 +101,7 @@ public:
             LOG_ERROR(log, "SystemLog queue is full");
     }
 
-private:
+protected:
     Context & context;
     const String database_name;
     const String table_name;

dbms/src/Storages/MergeTree/MergeTreeBlockOutputStream.cpp

@@ -18,8 +18,7 @@ void MergeTreeBlockOutputStream::write(const Block & block)
         MergeTreeData::MutableDataPartPtr part = storage.writer.writeTempPart(current_block);
         storage.data.renameTempPartAndAdd(part, &storage.increment);
 
-        if (auto part_log = storage.context.getPartLog(part->storage.getDatabaseName(), part->storage.getTableName()))
-            part_log->addNewPart(*part, watch.elapsed());
+        PartLog::addNewPartToTheLog(storage.context, *part, watch.elapsed());
 
         /// Initiate async merge - it will be done if it's good time for merge and if there are space in 'background_pool'.
         storage.merge_task_handle->wake();

dbms/src/Storages/MergeTree/MergeTreeData.cpp

@@ -47,6 +47,7 @@
 #include <typeinfo>
 #include <typeindex>
 #include <optional>
+#include <Interpreters/PartLog.h>
 
 
 namespace ProfileEvents
@@ -656,18 +657,43 @@ void MergeTreeData::rollbackDeletingParts(const MergeTreeData::DataPartsVector &
 
 void MergeTreeData::removePartsFinally(const MergeTreeData::DataPartsVector & parts)
 {
-    std::lock_guard<std::mutex> lock(data_parts_mutex);
+    {
+        std::lock_guard<std::mutex> lock(data_parts_mutex);
 
-    /// TODO: use data_parts iterators instead of pointers
-    for (auto & part : parts)
+        /// TODO: use data_parts iterators instead of pointers
+        for (auto & part : parts)
+        {
+            auto it = data_parts_by_name.find(part->info);
+            if (it == data_parts_by_name.end())
+                throw Exception("Deleting data part " + part->name + " is not exist", ErrorCodes::LOGICAL_ERROR);
+
+            (*it)->assertState({DataPartState::Deleting});
+
+            data_parts_indexes.erase(it);
+        }
+    }
+
+    /// Data parts is still alive (since DataPartsVector holds shared_ptrs) and contain useful metainformation for logging
+    /// NOTE: There is no need to log parts deletion somewhere else, all deleting parts pass through this function and pass away
+    if (auto part_log = context.getPartLog(database_name, table_name))
     {
-        auto it = data_parts_by_name.find(part->info);
-        if (it == data_parts_by_name.end())
-            throw Exception("Deleting data part " + part->name + " is not exist", ErrorCodes::LOGICAL_ERROR);
+        PartLogElement part_log_elem;
+
+        part_log_elem.event_type = PartLogElement::REMOVE_PART;
+        part_log_elem.event_time = time(nullptr);
+        part_log_elem.duration_ms = 0;
 
-        (*it)->assertState({DataPartState::Deleting});
+        part_log_elem.database_name = database_name;
+        part_log_elem.table_name = table_name;
 
-        data_parts_indexes.erase(it);
+        for (auto & part : parts)
+        {
+            part_log_elem.part_name = part->name;
+            part_log_elem.bytes_compressed_on_disk = part->size_in_bytes;
+            part_log_elem.rows = part->rows_count;
+
+            part_log->add(part_log_elem);
+        }
     }
 }
 

dbms/src/Storages/MergeTree/MergeTreeDataPart.h

@@ -130,7 +130,7 @@ struct MergeTreeDataPart
     String name;
     MergeTreePartInfo info;
 
-    /// A directory path (realative to storage's path) where part data is actually stored
+    /// A directory path (relative to storage's path) where part data is actually stored
     /// Examples: 'detached/tmp_fetch_<name>', 'tmp_<name>', '<name>'
     mutable String relative_path;
 

dbms/src/Storages/MergeTree/ReplicatedMergeTreeBlockOutputStream.cpp

@@ -20,6 +20,7 @@ namespace ErrorCodes
     extern const int NO_ZOOKEEPER;
     extern const int READONLY;
     extern const int UNKNOWN_STATUS_OF_INSERT;
+    extern const int INSERT_WAS_DEDUPLICATED;
 }
 
 
@@ -141,10 +142,21 @@ void ReplicatedMergeTreeBlockOutputStream::write(const Block & block)
             LOG_DEBUG(log, "Wrote block with " << block.rows() << " rows");
         }
 
-        commitPart(zookeeper, part, block_id);
 
-        if (auto part_log = storage.context.getPartLog(part->storage.getDatabaseName(), part->storage.getTableName()))
-            part_log->addNewPart(*part, watch.elapsed());
+
+        try
+        {
+            commitPart(zookeeper, part, block_id);
+
+            /// Set a special error code if the block is duplicate
+            int error = (deduplicate && last_block_is_duplicate) ? ErrorCodes::INSERT_WAS_DEDUPLICATED : 0;
+            PartLog::addNewPartToTheLog(storage.context, *part, watch.elapsed(), ExecutionStatus(error));
+        }
+        catch (...)
+        {
+            PartLog::addNewPartToTheLog(storage.context, *part, watch.elapsed(), ExecutionStatus::fromCurrentException(__PRETTY_FUNCTION__));
+            throw;
+        }
     }
 }
 
@@ -163,10 +175,16 @@ void ReplicatedMergeTreeBlockOutputStream::writeExistingPart(MergeTreeData::Muta
 
     Stopwatch watch;
 
-    commitPart(zookeeper, part, "");
-
-    if (auto part_log = storage.context.getPartLog(part->storage.getDatabaseName(), part->storage.getTableName()))
-        part_log->addNewPart(*part, watch.elapsed());
+    try
+    {
+        commitPart(zookeeper, part, "");
+        PartLog::addNewPartToTheLog(storage.context, *part, watch.elapsed());
+    }
+    catch (...)
+    {
+        PartLog::addNewPartToTheLog(storage.context, *part, watch.elapsed(), ExecutionStatus::fromCurrentException(__PRETTY_FUNCTION__));
+        throw;
+    }
 }
 
 

dbms/src/Storages/StorageMergeTree.cpp

@@ -330,45 +330,66 @@ bool StorageMergeTree::merge(
         merging_tagger.emplace(future_part.parts, MergeTreeDataMerger::estimateDiskSpaceForMerge(future_part.parts), *this);
     }
 
-    MergeList::EntryPtr merge_entry_ptr = context.getMergeList().insert(database_name, table_name, future_part.name, future_part.parts);
+    MergeList::EntryPtr merge_entry = context.getMergeList().insert(database_name, table_name, future_part.name, future_part.parts);
 
     /// Logging
     Stopwatch stopwatch;
+    MergeTreeData::MutableDataPartPtr new_part;
 
-    auto new_part = merger.mergePartsToTemporaryPart(
-        future_part, *merge_entry_ptr, aio_threshold, time(nullptr), merging_tagger->reserved_space.get(), deduplicate);
+    auto write_part_log = [&] (const ExecutionStatus & execution_status)
+    {
+        try
+        {
+            auto part_log = context.getPartLog(database_name, table_name);
+            if (!part_log)
+                return;
 
-    merger.renameMergedTemporaryPart(new_part, future_part.parts, nullptr);
+            PartLogElement part_log_elem;
 
-    if (auto part_log = context.getPartLog(database_name, table_name))
-    {
-        PartLogElement elem;
-        elem.event_time = time(nullptr);
+            part_log_elem.event_type = PartLogElement::MERGE_PARTS;
+            part_log_elem.event_time = time(nullptr);
+            part_log_elem.duration_ms = stopwatch.elapsed() / 1000000;
 
-        elem.merged_from.reserve(future_part.parts.size());
-        for (const auto & part : future_part.parts)
-            elem.merged_from.push_back(part->name);
-        elem.event_type = PartLogElement::MERGE_PARTS;
-        elem.size_in_bytes = new_part->size_in_bytes;
+            part_log_elem.database_name = database_name;
+            part_log_elem.table_name = table_name;
+            part_log_elem.part_name = future_part.name;
 
-        elem.database_name = new_part->storage.getDatabaseName();
-        elem.table_name = new_part->storage.getTableName();
-        elem.part_name = new_part->name;
+            if (new_part)
+                part_log_elem.bytes_compressed_on_disk = new_part->size_in_bytes;
 
-        elem.duration_ms = stopwatch.elapsed() / 1000000;
+            part_log_elem.source_part_names.reserve(future_part.parts.size());
+            for (const auto & source_part : future_part.parts)
+                part_log_elem.source_part_names.push_back(source_part->name);
 
-        part_log->add(elem);
+            part_log_elem.rows_read = (*merge_entry)->bytes_read_uncompressed;
+            part_log_elem.bytes_read_uncompressed = (*merge_entry)->bytes_read_uncompressed;
 
-        elem.duration_ms = 0;
-        elem.event_type = PartLogElement::REMOVE_PART;
-        elem.merged_from = Strings();
+            part_log_elem.rows = (*merge_entry)->rows_written;
+            part_log_elem.bytes_uncompressed = (*merge_entry)->bytes_written_uncompressed;
 
-        for (const auto & part : future_part.parts)
+            part_log_elem.error = static_cast<UInt16>(execution_status.code);
+            part_log_elem.exception = execution_status.message;
+
+            part_log->add(part_log_elem);
+        }
+        catch (...)
         {
-            elem.part_name = part->name;
-            elem.size_in_bytes = part->size_in_bytes;
-            part_log->add(elem);
+            tryLogCurrentException(log, __PRETTY_FUNCTION__);
         }
+    };
+
+    try
+    {
+        new_part = merger.mergePartsToTemporaryPart(future_part, *merge_entry, aio_threshold, time(nullptr),
+                                                    merging_tagger->reserved_space.get(), deduplicate);
+        merger.renameMergedTemporaryPart(new_part, future_part.parts, nullptr);
+
+        write_part_log({});
+    }
+    catch (...)
+    {
+        write_part_log(ExecutionStatus::fromCurrentException());
+        throw;
     }
 
     return true;

dbms/src/Storages/StorageReplicatedMergeTree.h

@@ -342,6 +342,11 @@ private:
 
     void executeDropRange(const LogEntry & entry);
 
+    /// Do the merge or recommend to make the fetch instead of the merge
+    void tryExecuteMerge(const LogEntry & entry, bool & do_fetch);
+
+    bool executeFetch(const LogEntry & entry);
+
     void executeClearColumnInPartition(const LogEntry & entry);
 
     /** Updates the queue.