diff --git a/CHANGELOG.md b/CHANGELOG.md index c6411a408bb..32b0bb756d7 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -12,7 +12,8 @@ * Passing a double as argument for a Query on Decimal128 did not work ([#7386](https://github.com/realm/realm-core/issues/7386), since v14.0.0) * Opening file with file format 23 in read-only mode will crash ([#7388](https://github.com/realm/realm-core/issues/7388), since v14.0.0) * Querying a dictionary over a link would sometimes result in out-of-bounds memory reads ([PR #7382](https://github.com/realm/realm-core/pull/7382), since v14.0.0). -* Restore the pre-14.0.0 behavior of missing keys in dictionaries in queries ([PR #7391](https://github.com/realm/realm-core/pull/7391)) +* Restore the pre-14.0.0 behavior of missing keys in dictionaries in queries ([PR #7391](https://github.com/realm/realm-core/pull/7391)) +* Fix a ~10% performance regression for bulk insertion when using a log level which does not include debug/trace ([PR #7400](https://github.com/realm/realm-core/pull/7400), since v14.0.0) ### Breaking changes * None. diff --git a/src/realm/replication.cpp b/src/realm/replication.cpp index c6f76c0d315..35bd32d8b3a 100644 --- a/src/realm/replication.cpp +++ b/src/realm/replication.cpp @@ -17,7 +17,6 @@ **************************************************************************/ #include -#include #include #include @@ -25,6 +24,7 @@ using namespace realm; using namespace realm::util; +using LogLevel = util::Logger::Level; const char* Replication::history_type_name(int type) { @@ -66,12 +66,12 @@ Replication::version_type Replication::prepare_commit(version_type orig_version) void Replication::add_class(TableKey table_key, StringData name, Table::Type type) { - if (auto logger = get_logger()) { + if (auto logger = would_log(LogLevel::debug)) { if (type == Table::Type::Embedded) { - logger->log(LogCategory::object, util::Logger::Level::debug, "Add %1 class '%2'", type, name); + logger->log(LogCategory::object, LogLevel::debug, "Add %1 class '%2'", type, name); } else { - logger->log(LogCategory::object, util::Logger::Level::debug, "Add class '%1'", name); + logger->log(LogCategory::object, LogLevel::debug, "Add class '%1'", name); } } unselect_all(); @@ -81,10 +81,9 @@ void Replication::add_class(TableKey table_key, StringData name, Table::Type typ void Replication::add_class_with_primary_key(TableKey tk, StringData name, DataType pk_type, StringData pk_name, bool, Table::Type table_type) { - if (auto logger = get_logger()) { - logger->log(LogCategory::object, util::Logger::Level::debug, - "Add %1 class '%2' with primary key property '%3' of %4", table_type, - Group::table_name_to_class_name(name), pk_name, pk_type); + if (auto logger = would_log(LogLevel::debug)) { + logger->log(LogCategory::object, LogLevel::debug, "Add %1 class '%2' with primary key property '%3' of %4", + table_type, Group::table_name_to_class_name(name), pk_name, pk_type); } REALM_ASSERT(table_type != Table::Type::Embedded); unselect_all(); @@ -93,8 +92,8 @@ void Replication::add_class_with_primary_key(TableKey tk, StringData name, DataT void Replication::erase_class(TableKey tk, StringData table_name, size_t) { - if (auto logger = get_logger()) { - logger->log(LogCategory::object, util::Logger::Level::debug, "Remove class '%1'", + if (auto logger = would_log(LogLevel::debug)) { + logger->log(LogCategory::object, LogLevel::debug, "Remove class '%1'", Group::table_name_to_class_name(table_name)); } unselect_all(); @@ -105,7 +104,7 @@ void Replication::erase_class(TableKey tk, StringData table_name, size_t) void Replication::insert_column(const Table* t, ColKey col_key, DataType type, StringData col_name, Table* target_table) { - if (auto logger = get_logger()) { + if (auto logger = would_log(LogLevel::debug)) { const char* collection_type = ""; if (col_key.is_collection()) { if (col_key.is_list()) { @@ -119,12 +118,11 @@ void Replication::insert_column(const Table* t, ColKey col_key, DataType type, S } } if (target_table) { - logger->log(LogCategory::object, util::Logger::Level::debug, - "On class '%1': Add property '%2' %3linking '%4'", t->get_class_name(), col_name, - collection_type, target_table->get_class_name()); + logger->log(LogCategory::object, LogLevel::debug, "On class '%1': Add property '%2' %3linking '%4'", + t->get_class_name(), col_name, collection_type, target_table->get_class_name()); } else { - logger->log(LogCategory::object, util::Logger::Level::debug, "On class '%1': Add property '%2' %3of %4", + logger->log(LogCategory::object, LogLevel::debug, "On class '%1': Add property '%2' %3of %4", t->get_class_name(), col_name, collection_type, type); } } @@ -134,9 +132,9 @@ void Replication::insert_column(const Table* t, ColKey col_key, DataType type, S void Replication::erase_column(const Table* t, ColKey col_key) { - if (auto logger = get_logger()) { - logger->log(LogCategory::object, util::Logger::Level::debug, "On class '%1': Remove property '%2'", - t->get_class_name(), t->get_column_name(col_key)); + if (auto logger = would_log(LogLevel::debug)) { + logger->log(LogCategory::object, LogLevel::debug, "On class '%1': Remove property '%2'", t->get_class_name(), + t->get_column_name(col_key)); } select_table(t); // Throws m_encoder.erase_column(col_key); // Throws @@ -144,8 +142,8 @@ void Replication::erase_column(const Table* t, ColKey col_key) void Replication::create_object(const Table* t, GlobalKey id) { - if (auto logger = get_logger()) { - logger->log(LogCategory::object, util::Logger::Level::debug, "Create object '%1'", t->get_class_name()); + if (auto logger = would_log(LogLevel::debug)) { + logger->log(LogCategory::object, LogLevel::debug, "Create object '%1'", t->get_class_name()); } select_table(t); // Throws m_encoder.create_object(id.get_local_key(0)); // Throws @@ -153,8 +151,8 @@ void Replication::create_object(const Table* t, GlobalKey id) void Replication::create_object_with_primary_key(const Table* t, ObjKey key, Mixed pk) { - if (auto logger = get_logger()) { - logger->log(LogCategory::object, util::Logger::Level::debug, "Create object '%1' with primary key %2", + if (auto logger = would_log(LogLevel::debug)) { + logger->log(LogCategory::object, LogLevel::debug, "Create object '%1' with primary key %2", t->get_class_name(), pk); } select_table(t); // Throws @@ -163,18 +161,16 @@ void Replication::create_object_with_primary_key(const Table* t, ObjKey key, Mix void Replication::remove_object(const Table* t, ObjKey key) { - if (auto logger = get_logger()) { + if (auto logger = would_log(LogLevel::debug)) { if (t->is_embedded()) { - logger->log(LogCategory::object, util::Logger::Level::debug, "Remove embedded object '%1'", - t->get_class_name()); + logger->log(LogCategory::object, LogLevel::debug, "Remove embedded object '%1'", t->get_class_name()); } else if (t->get_primary_key_column()) { - logger->log(LogCategory::object, util::Logger::Level::debug, "Remove object '%1' with primary key %2", + logger->log(LogCategory::object, LogLevel::debug, "Remove object '%1' with primary key %2", t->get_class_name(), t->get_primary_key(key)); } else { - logger->log(LogCategory::object, util::Logger::Level::debug, "Remove object '%1'[%2]", - t->get_class_name(), key); + logger->log(LogCategory::object, LogLevel::debug, "Remove object '%1'[%2]", t->get_class_name(), key); } } select_table(t); // Throws @@ -186,23 +182,20 @@ inline void Replication::select_obj(ObjKey key) if (key == m_selected_obj) { return; } - if (auto logger = get_logger()) { - if (logger->would_log(util::Logger::Level::debug)) { - auto class_name = m_selected_table->get_class_name(); - if (m_selected_table->get_primary_key_column()) { - auto pk = m_selected_table->get_primary_key(key); - logger->log(LogCategory::object, util::Logger::Level::debug, - "Mutating object '%1' with primary key %2", class_name, pk); - } - else if (m_selected_table->is_embedded()) { - auto obj = m_selected_table->get_object(key); - logger->log(LogCategory::object, util::Logger::Level::debug, "Mutating object '%1' with path '%2'", - class_name, obj.get_id()); - } - else { - logger->log(LogCategory::object, util::Logger::Level::debug, "Mutating anonymous object '%1'[%2]", - class_name, key); - } + if (auto logger = would_log(LogLevel::debug)) { + auto class_name = m_selected_table->get_class_name(); + if (m_selected_table->get_primary_key_column()) { + auto pk = m_selected_table->get_primary_key(key); + logger->log(LogCategory::object, LogLevel::debug, "Mutating object '%1' with primary key %2", class_name, + pk); + } + else if (m_selected_table->is_embedded()) { + auto obj = m_selected_table->get_object(key); + logger->log(LogCategory::object, LogLevel::debug, "Mutating object '%1' with path '%2'", class_name, + obj.get_id()); + } + else { + logger->log(LogCategory::object, LogLevel::debug, "Mutating anonymous object '%1'[%2]", class_name, key); } } m_selected_obj = key; @@ -220,33 +213,29 @@ void Replication::do_set(const Table* t, ColKey col_key, ObjKey key, _impl::Inst void Replication::set(const Table* t, ColKey col_key, ObjKey key, Mixed value, _impl::Instruction variant) { do_set(t, col_key, key, variant); // Throws - if (auto logger = get_logger()) { - if (logger->would_log(util::Logger::Level::trace)) { - if (col_key.get_type() == col_type_Link && value.is_type(type_Link)) { - auto target_table = t->get_opposite_table(col_key); - if (target_table->is_embedded()) { - logger->log(LogCategory::object, util::Logger::Level::trace, - " Creating embedded object '%1' in '%2'", target_table->get_class_name(), - t->get_column_name(col_key)); - } - else if (target_table->get_primary_key_column()) { - auto link = value.get(); - auto pk = target_table->get_primary_key(link); - logger->log(LogCategory::object, util::Logger::Level::trace, - " Linking object '%1' with primary key %2 from '%3'", - target_table->get_class_name(), pk, t->get_column_name(col_key)); - } - else { - logger->log(LogCategory::object, util::Logger::Level::trace, - " Linking object '%1'[%2] from '%3'", target_table->get_class_name(), key, - t->get_column_name(col_key)); - } + if (auto logger = would_log(LogLevel::trace)) { + if (col_key.get_type() == col_type_Link && value.is_type(type_Link)) { + auto target_table = t->get_opposite_table(col_key); + if (target_table->is_embedded()) { + logger->log(LogCategory::object, LogLevel::trace, " Creating embedded object '%1' in '%2'", + target_table->get_class_name(), t->get_column_name(col_key)); + } + else if (target_table->get_primary_key_column()) { + auto link = value.get(); + auto pk = target_table->get_primary_key(link); + logger->log(LogCategory::object, LogLevel::trace, + " Linking object '%1' with primary key %2 from '%3'", target_table->get_class_name(), + pk, t->get_column_name(col_key)); } else { - logger->log(LogCategory::object, util::Logger::Level::trace, " Set '%1' to %2", - t->get_column_name(col_key), value.to_string(util::Logger::max_width_of_value)); + logger->log(LogCategory::object, LogLevel::trace, " Linking object '%1'[%2] from '%3'", + target_table->get_class_name(), key, t->get_column_name(col_key)); } } + else { + logger->log(LogCategory::object, LogLevel::trace, " Set '%1' to %2", t->get_column_name(col_key), + value.to_string(util::Logger::max_width_of_value)); + } } } @@ -255,8 +244,8 @@ void Replication::nullify_link(const Table* t, ColKey col_key, ObjKey key) select_table(t); // Throws select_obj(key); m_encoder.modify_object(col_key, key); // Throws - if (auto logger = get_logger()) { - logger->log(LogCategory::object, util::Logger::Level::trace, " Nullify '%1'", t->get_column_name(col_key)); + if (auto logger = would_log(LogLevel::trace)) { + logger->log(LogCategory::object, LogLevel::trace, " Nullify '%1'", t->get_column_name(col_key)); } } @@ -264,25 +253,26 @@ void Replication::add_int(const Table* t, ColKey col_key, ObjKey key, int_fast64 { do_set(t, col_key, key); // Throws if (auto logger = get_logger()) { - logger->log(LogCategory::object, util::Logger::Level::trace, " Adding %1 to '%2'", value, - t->get_column_name(col_key)); + logger->log(LogCategory::object, LogLevel::trace, " Adding %1 to '%2'", value, t->get_column_name(col_key)); } } Path Replication::get_prop_name(Path&& path) const { - Path ret(std::move(path)); - auto col_key = ret[0].get_col_key(); + auto col_key = path[0].get_col_key(); auto prop_name = m_selected_table->get_column_name(col_key); - ret[0] = PathElement(prop_name); - return ret; + path[0] = PathElement(prop_name); + return std::move(path); } void Replication::log_collection_operation(const char* operation, const CollectionBase& collection, Mixed value, Mixed index) const { - auto logger = get_logger(); + auto logger = would_log(LogLevel::trace); + if (REALM_LIKELY(!logger)) + return; + auto path = collection.get_short_path(); auto col_key = path[0].get_col_key(); auto prop_name = m_selected_table->get_column_name(col_key); @@ -294,55 +284,48 @@ void Replication::log_collection_operation(const char* operation, const Collecti if (Table::is_link_type(col_key.get_type()) && value.is_type(type_Link)) { auto target_table = m_selected_table->get_opposite_table(col_key); if (target_table->is_embedded()) { - logger->log(LogCategory::object, util::Logger::Level::trace, " %1 embedded object '%2' in %3%4 ", - operation, target_table->get_class_name(), path, position); + logger->log(LogCategory::object, LogLevel::trace, " %1 embedded object '%2' in %3%4 ", operation, + target_table->get_class_name(), path, position); } else if (target_table->get_primary_key_column()) { auto link = value.get(); auto pk = target_table->get_primary_key(link); - logger->log(LogCategory::object, util::Logger::Level::trace, - " %1 object '%2' with primary key %3 in %4%5", operation, target_table->get_class_name(), - pk, path, position); + logger->log(LogCategory::object, LogLevel::trace, " %1 object '%2' with primary key %3 in %4%5", + operation, target_table->get_class_name(), pk, path, position); } else { auto link = value.get(); - logger->log(LogCategory::object, util::Logger::Level::trace, " %1 object '%2'[%3] in %4%5", operation, + logger->log(LogCategory::object, LogLevel::trace, " %1 object '%2'[%3] in %4%5", operation, target_table->get_class_name(), link, path, position); } } else { - logger->log(LogCategory::object, util::Logger::Level::trace, " %1 %2 in %3%4", operation, + logger->log(LogCategory::object, LogLevel::trace, " %1 %2 in %3%4", operation, value.to_string(util::Logger::max_width_of_value), path, position); } } + void Replication::list_insert(const CollectionBase& list, size_t list_ndx, Mixed value, size_t) { select_collection(list); // Throws m_encoder.collection_insert(list.translate_index(list_ndx)); // Throws - if (auto logger = get_logger()) { - if (logger->would_log(util::Logger::Level::trace)) { - log_collection_operation("Insert", list, value, int64_t(list_ndx)); - } - } + log_collection_operation("Insert", list, value, int64_t(list_ndx)); } void Replication::list_set(const CollectionBase& list, size_t list_ndx, Mixed value) { select_collection(list); // Throws m_encoder.collection_set(list.translate_index(list_ndx)); // Throws - if (auto logger = get_logger()) { - if (logger->would_log(util::Logger::Level::trace)) { - log_collection_operation("Set", list, value, int64_t(list_ndx)); - } - } + log_collection_operation("Set", list, value, int64_t(list_ndx)); } void Replication::list_erase(const CollectionBase& list, size_t link_ndx) { select_collection(list); // Throws m_encoder.collection_erase(list.translate_index(link_ndx)); // Throws - if (auto logger = get_logger()) { - logger->log(LogCategory::object, util::Logger::Level::trace, " Erase '%1' at position %2", + if (auto logger = would_log(LogLevel::trace)) { + + logger->log(LogCategory::object, LogLevel::trace, " Erase '%1' at position %2", get_prop_name(list.get_short_path()), link_ndx); } } @@ -351,9 +334,9 @@ void Replication::list_move(const CollectionBase& list, size_t from_link_ndx, si { select_collection(list); // Throws m_encoder.collection_move(list.translate_index(from_link_ndx), list.translate_index(to_link_ndx)); // Throws - if (auto logger = get_logger()) { - logger->log(LogCategory::object, util::Logger::Level::trace, " Move %1 to %2 in '%3'", from_link_ndx, - to_link_ndx, get_prop_name(list.get_short_path())); + if (auto logger = would_log(LogLevel::trace)) { + logger->log(LogCategory::object, LogLevel::trace, " Move %1 to %2 in '%3'", from_link_ndx, to_link_ndx, + get_prop_name(list.get_short_path())); } } @@ -361,19 +344,15 @@ void Replication::set_insert(const CollectionBase& set, size_t set_ndx, Mixed va { select_collection(set); // Throws m_encoder.collection_insert(set_ndx); // Throws - if (auto logger = get_logger()) { - if (logger->would_log(util::Logger::Level::trace)) { - log_collection_operation("Insert", set, value, Mixed()); - } - } + log_collection_operation("Insert", set, value, Mixed()); } void Replication::set_erase(const CollectionBase& set, size_t set_ndx, Mixed value) { select_collection(set); // Throws m_encoder.collection_erase(set_ndx); // Throws - if (auto logger = get_logger()) { - logger->log(LogCategory::object, util::Logger::Level::trace, " Erase %1 from '%2'", value, + if (auto logger = would_log(LogLevel::trace)) { + logger->log(LogCategory::object, LogLevel::trace, " Erase %1 from '%2'", value, get_prop_name(set.get_short_path())); } } @@ -382,9 +361,8 @@ void Replication::set_clear(const CollectionBase& set) { select_collection(set); // Throws m_encoder.collection_clear(set.size()); // Throws - if (auto logger = get_logger()) { - logger->log(LogCategory::object, util::Logger::Level::trace, " Clear '%1'", - get_prop_name(set.get_short_path())); + if (auto logger = would_log(LogLevel::trace)) { + logger->log(LogCategory::object, LogLevel::trace, " Clear '%1'", get_prop_name(set.get_short_path())); } } @@ -411,11 +389,10 @@ void Replication::do_select_collection(const CollectionBase& list) void Replication::list_clear(const CollectionBase& list) { - select_collection(list); // Throws + select_collection(list); // Throws m_encoder.collection_clear(list.size()); // Throws - if (auto logger = get_logger()) { - logger->log(LogCategory::object, util::Logger::Level::trace, " Clear '%1'", - get_prop_name(list.get_short_path())); + if (auto logger = would_log(LogLevel::trace)) { + logger->log(LogCategory::object, LogLevel::trace, " Clear '%1'", get_prop_name(list.get_short_path())); } } @@ -423,8 +400,8 @@ void Replication::link_list_nullify(const Lst& list, size_t link_ndx) { select_collection(list); m_encoder.collection_erase(link_ndx); - if (auto logger = get_logger()) { - logger->log(LogCategory::object, util::Logger::Level::trace, " Nullify '%1' position %2", + if (auto logger = would_log(LogLevel::trace)) { + logger->log(LogCategory::object, LogLevel::trace, " Nullify '%1' position %2", m_selected_table->get_column_name(list.get_col_key()), link_ndx); } } @@ -433,30 +410,22 @@ void Replication::dictionary_insert(const CollectionBase& dict, size_t ndx, Mixe { select_collection(dict); m_encoder.collection_insert(ndx); - if (auto logger = get_logger()) { - if (logger->would_log(util::Logger::Level::trace)) { - log_collection_operation("Insert", dict, value, key); - } - } + log_collection_operation("Insert", dict, value, key); } void Replication::dictionary_set(const CollectionBase& dict, size_t ndx, Mixed key, Mixed value) { select_collection(dict); m_encoder.collection_set(ndx); - if (auto logger = get_logger()) { - if (logger->would_log(util::Logger::Level::trace)) { - log_collection_operation("Set", dict, value, key); - } - } + log_collection_operation("Set", dict, value, key); } void Replication::dictionary_erase(const CollectionBase& dict, size_t ndx, Mixed key) { select_collection(dict); m_encoder.collection_erase(ndx); - if (auto logger = get_logger()) { - logger->log(LogCategory::object, util::Logger::Level::trace, " Erase %1 from '%2'", key, + if (auto logger = would_log(LogLevel::trace)) { + logger->log(LogCategory::object, LogLevel::trace, " Erase %1 from '%2'", key, get_prop_name(dict.get_short_path())); } } @@ -465,8 +434,7 @@ void Replication::dictionary_clear(const CollectionBase& dict) { select_collection(dict); m_encoder.collection_clear(dict.size()); - if (auto logger = get_logger()) { - logger->log(LogCategory::object, util::Logger::Level::trace, " Clear '%1'", - get_prop_name(dict.get_short_path())); + if (auto logger = would_log(LogLevel::trace)) { + logger->log(LogCategory::object, LogLevel::trace, " Clear '%1'", get_prop_name(dict.get_short_path())); } } diff --git a/src/realm/replication.hpp b/src/realm/replication.hpp index 437d6654901..939f6731349 100644 --- a/src/realm/replication.hpp +++ b/src/realm/replication.hpp @@ -26,8 +26,9 @@ #include #include -#include #include +#include +#include #include #include @@ -438,6 +439,13 @@ class Replication { Mixed index) const; Path get_prop_name(Path&&) const; size_t transact_log_size(); + + util::Logger* would_log(util::Logger::Level level) const noexcept + { + if (m_logger && m_logger->would_log(level)) + return m_logger; + return nullptr; + } }; class Replication::Interrupted : public std::exception {