diff --git a/src/realm/object-store/impl/collection_notifier.cpp b/src/realm/object-store/impl/collection_notifier.cpp index e20f6f9cd89..e0325b04fd7 100644 --- a/src/realm/object-store/impl/collection_notifier.cpp +++ b/src/realm/object-store/impl/collection_notifier.cpp @@ -305,8 +305,9 @@ void CollectionNotifier::prepare_handover() REALM_ASSERT(m_change.empty()); m_has_run = true; -#ifdef REALM_DEBUG util::CheckedLockGuard lock(m_callback_mutex); + m_run_time_point = std::chrono::steady_clock::now(); +#ifdef REALM_DEBUG for (auto& callback : m_callbacks) REALM_ASSERT(!callback.skip_next); #endif @@ -328,10 +329,59 @@ void CollectionNotifier::before_advance() }); } +static void log_changeset(util::Logger* logger, const CollectionChangeSet& changes, std::string_view description, + std::chrono::microseconds elapsed) +{ + if (!logger) { + return; + } + + logger->log(util::LogCategory::notification, util::Logger::Level::debug, + "Delivering notifications for %1 after %2 us", description, elapsed.count()); + if (!logger->would_log(util::Logger::Level::trace)) { + return; + } + if (changes.empty()) { + logger->log(util::LogCategory::notification, util::Logger::Level::trace, " No changes"); + } + else { + if (changes.collection_root_was_deleted) { + logger->log(util::LogCategory::notification, util::Logger::Level::trace, " collection deleted"); + } + else if (changes.collection_was_cleared) { + logger->log(util::LogCategory::notification, util::Logger::Level::trace, " collection cleared"); + } + else { + auto log = [logger](const char* change, const IndexSet& index_set) { + if (auto cnt = index_set.count()) { + std::ostringstream ostr; + bool first = true; + for (auto [a, b] : index_set) { + if (!first) + ostr << ','; + if (b > a + 1) { + ostr << '[' << a << ',' << b - 1 << ']'; + } + else { + ostr << a; + } + first = false; + } + logger->log(util::LogCategory::notification, util::Logger::Level::trace, " %1 %2: %3", cnt, + change, ostr.str().c_str()); + } + }; + log("deletions", changes.deletions); + log("insertions", changes.insertions); + log("modifications", changes.modifications); + } + } +} + void CollectionNotifier::after_advance() { using namespace std::chrono; - auto t1 = steady_clock::now(); + auto now = steady_clock::now(); for_each_callback([&](auto& lock, auto& callback) { if (callback.initial_delivered && callback.changes_to_deliver.empty()) { @@ -344,51 +394,9 @@ void CollectionNotifier::after_advance() // acquire a local reference to the callback so that removing the // callback from within it can't result in a dangling pointer auto cb = callback.fn; + auto elapsed = duration_cast(now - m_run_time_point); lock.unlock_unchecked(); - if (m_logger) { - m_logger->log(util::LogCategory::notification, util::Logger::Level::debug, - "Delivering notifications for %1 after %2 us", m_description, - duration_cast(t1 - m_run_time_point).count()); - if (m_logger->would_log(util::Logger::Level::trace)) { - if (changes.empty()) { - m_logger->log(util::LogCategory::notification, util::Logger::Level::trace, " No changes"); - } - else { - if (changes.collection_root_was_deleted) { - m_logger->log(util::LogCategory::notification, util::Logger::Level::trace, - " collection deleted"); - } - else if (changes.collection_was_cleared) { - m_logger->log(util::LogCategory::notification, util::Logger::Level::trace, - " collection cleared"); - } - else { - auto log = [this](const char* change, const IndexSet& index_set) { - if (auto cnt = index_set.count()) { - std::ostringstream ostr; - bool first = true; - for (auto [a, b] : index_set) { - if (!first) - ostr << ','; - if (b > a + 1) { - ostr << '[' << a << ',' << b - 1 << ']'; - } - else { - ostr << a; - } - first = false; - } - m_logger->log(util::LogCategory::notification, util::Logger::Level::trace, - " %1 %2: %3", cnt, change, ostr.str().c_str()); - } - }; - log("deletions", changes.deletions); - log("insertions", changes.insertions); - log("modifications", changes.modifications); - } - } - } - } + log_changeset(m_logger.get(), changes, m_description, elapsed); cb.after(changes); }); } @@ -527,3 +535,24 @@ void NotifierPackage::after_advance() for (auto& notifier : m_notifiers) notifier->after_advance(); } + +NotifierRunLogger::NotifierRunLogger(util::Logger* logger, std::string_view name, std::string_view description) + : m_logger(logger) + , m_name(name) + , m_description(description) +{ + if (logger && logger->would_log(util::Logger::Level::debug)) { + m_logger = logger; + m_start = std::chrono::steady_clock::now(); + } +} + +NotifierRunLogger::~NotifierRunLogger() +{ + using namespace std::chrono; + if (m_logger) { + auto now = steady_clock::now(); + m_logger->log(util::LogCategory::notification, util::Logger::Level::debug, "%1 %2 ran in %3 us", m_name, + m_description, duration_cast(now - m_start).count()); + } +} diff --git a/src/realm/object-store/impl/collection_notifier.hpp b/src/realm/object-store/impl/collection_notifier.hpp index a37d122b84a..a4c35402410 100644 --- a/src/realm/object-store/impl/collection_notifier.hpp +++ b/src/realm/object-store/impl/collection_notifier.hpp @@ -380,6 +380,18 @@ class NotifierPackage { RealmCoordinator* m_coordinator = nullptr; }; +class NotifierRunLogger { +public: + NotifierRunLogger(util::Logger* logger, std::string_view name, std::string_view description); + ~NotifierRunLogger(); + +private: + util::Logger* m_logger; + std::string_view m_name; + std::string_view m_description; + std::chrono::steady_clock::time_point m_start; +}; + } // namespace realm::_impl #endif /* REALM_BACKGROUND_COLLECTION_HPP */ diff --git a/src/realm/object-store/impl/list_notifier.cpp b/src/realm/object-store/impl/list_notifier.cpp index 511c9dc3dae..ebcfb797d77 100644 --- a/src/realm/object-store/impl/list_notifier.cpp +++ b/src/realm/object-store/impl/list_notifier.cpp @@ -33,7 +33,7 @@ ListNotifier::ListNotifier(std::shared_ptr realm, CollectionBase const& l , m_prev_size(list.size()) { attach(list); - if (m_logger) { + if (m_logger && m_logger->would_log(util::Logger::Level::debug)) { auto path = m_list->get_short_path(); auto prop_name = m_list->get_table()->get_column_name(path[0].get_col_key()); path[0] = PathElement(prop_name); @@ -94,16 +94,7 @@ bool ListNotifier::do_add_required_change_info(TransactionChangeInfo& info) void ListNotifier::run() { - using namespace std::chrono; - auto t1 = steady_clock::now(); - util::ScopeExit cleanup([&]() noexcept { - m_run_time_point = steady_clock::now(); - if (m_logger) { - m_logger->log(util::LogCategory::notification, util::Logger::Level::debug, - "ListNotifier %1 did run in %2 us", m_description, - duration_cast(m_run_time_point - t1).count()); - } - }); + NotifierRunLogger log(m_logger.get(), "ListNotifier", m_description); if (!m_list || !m_list->is_attached()) { // List was deleted, so report all of the rows being removed if this is diff --git a/src/realm/object-store/impl/object_notifier.cpp b/src/realm/object-store/impl/object_notifier.cpp index 86feba916d0..676680017d8 100644 --- a/src/realm/object-store/impl/object_notifier.cpp +++ b/src/realm/object-store/impl/object_notifier.cpp @@ -64,16 +64,7 @@ void ObjectNotifier::run() { if (!m_table || !m_info) return; - using namespace std::chrono; - auto t1 = steady_clock::now(); - util::ScopeExit cleanup([&]() noexcept { - m_run_time_point = steady_clock::now(); - if (m_logger) { - m_logger->log(util::LogCategory::notification, util::Logger::Level::debug, - "ObjectNotifier %1 did run in %2 us", m_description, - duration_cast(m_run_time_point - t1).count()); - } - }); + NotifierRunLogger log(m_logger.get(), "ObjectNotifier", m_description); auto it = m_info->tables.find(m_table->get_key()); if (it != m_info->tables.end() && it->second.deletions_contains(m_obj_key)) { diff --git a/src/realm/object-store/impl/results_notifier.cpp b/src/realm/object-store/impl/results_notifier.cpp index 6d7f9ef89df..b60029e58cd 100644 --- a/src/realm/object-store/impl/results_notifier.cpp +++ b/src/realm/object-store/impl/results_notifier.cpp @@ -65,12 +65,12 @@ ResultsNotifier::ResultsNotifier(Results& target) , m_target_is_in_table_order(target.is_in_table_order()) { if (m_logger) { - m_description = std::string("'") + std::string(m_query->get_table()->get_class_name()) + std::string("'"); + m_description = "'" + std::string(m_query->get_table()->get_class_name()) + "'"; if (m_query->has_conditions()) { m_description += " where \""; m_description += m_query->get_description_safe() + "\""; } - m_logger->log(util::LogCategory::notification, util::Logger::Level::debug, "Creating ResultsNotifier for ", + m_logger->log(util::LogCategory::notification, util::Logger::Level::debug, "Creating ResultsNotifier for %1", m_description); } reattach(); @@ -151,20 +151,10 @@ void ResultsNotifier::calculate_changes() void ResultsNotifier::run() { - using namespace std::chrono; + NotifierRunLogger log(m_logger.get(), "ResultsNotifier", m_description); REALM_ASSERT(m_info || !has_run()); - auto t1 = steady_clock::now(); - util::ScopeExit cleanup([&]() noexcept { - m_run_time_point = steady_clock::now(); - if (m_logger) { - m_logger->log(util::LogCategory::notification, util::Logger::Level::debug, - "ResultsNotifier %1 did run in %2 us", m_description, - duration_cast(m_run_time_point - t1).count()); - } - }); - // Table's been deleted, so report all objects as deleted if (!m_query->get_table()) { m_change = {}; @@ -278,7 +268,7 @@ ListResultsNotifier::ListResultsNotifier(Results& target) auto path = m_list->get_short_path(); auto prop_name = m_list->get_table()->get_column_name(path[0].get_col_key()); path[0] = PathElement(prop_name); - std::string sort_order; + std::string_view sort_order = ""; if (m_sort_order) { sort_order = *m_sort_order ? " sorted ascending" : " sorted descending"; } @@ -358,17 +348,6 @@ void ListResultsNotifier::calculate_changes() void ListResultsNotifier::run() { - using namespace std::chrono; - auto t1 = steady_clock::now(); - util::ScopeExit cleanup([&]() noexcept { - m_run_time_point = steady_clock::now(); - if (m_logger) { - m_logger->log(util::LogCategory::notification, util::Logger::Level::debug, - "ListResultsNotifier %1 did run in %2 us", m_description, - duration_cast(m_run_time_point - t1).count()); - } - }); - if (!m_list || !m_list->is_attached()) { // List was deleted, so report all of the rows being removed m_change = {}; @@ -379,10 +358,11 @@ void ListResultsNotifier::run() } if (!need_to_run()) { - cleanup.cancel(); return; } + NotifierRunLogger log(m_logger.get(), "ListResultsNotifier", m_description); + m_run_indices = std::vector(); if (m_distinct) m_list->distinct(*m_run_indices, m_sort_order);