From ef979feb8275d9c500a1087b1482e19fe040d1c8 Mon Sep 17 00:00:00 2001 From: Thomas Goyne Date: Thu, 29 Feb 2024 09:23:13 -0800 Subject: [PATCH] Avoid doing unneeded logger work in Replication Most of the replication log statements do some work including memory allocations which are then thrown away if the log level it too high, so always check the log level first. A few places don't actually benefit from this, but it's easier to consistently check the log level every time. --- CHANGELOG.md | 3 +- src/realm/replication.cpp | 228 ++++++++++++++++---------------------- src/realm/replication.hpp | 10 +- 3 files changed, 109 insertions(+), 132 deletions(-) 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 {