Logging notification activity

src/realm/db.cpp

@@ -1494,7 +1494,7 @@ class DBLogger : public Logger {
 void DB::set_logger(const std::shared_ptr<util::Logger>& logger) noexcept
 {
     if (logger)
-        m_logger = std::make_unique<DBLogger>(logger, m_log_id);
+        m_logger = std::make_shared<DBLogger>(logger, m_log_id);
 }
 
 void DB::open(Replication& repl, const DBOptions options)

src/realm/db.hpp

@@ -503,7 +503,7 @@ class DB : public std::enable_shared_from_this<DB> {
     util::InterprocessCondVar m_pick_next_writer;
     std::function<void(int, int)> m_upgrade_callback;
     std::unique_ptr<AsyncCommitHelper> m_commit_helper;
-    std::unique_ptr<util::Logger> m_logger;
+    std::shared_ptr<util::Logger> m_logger;
     bool m_is_sync_agent = false;
     // Id for this DB to be used in logging. We will just use some bits from the pointer.
     // The path cannot be used as this would not allow us to distinguish between two DBs opening

src/realm/object-store/impl/collection_notifier.cpp

@@ -26,6 +26,7 @@
 #include <realm/dictionary.hpp>
 #include <realm/list.hpp>
 #include <realm/set.hpp>
+#include <realm/util/logger.hpp>
 
 using namespace realm;
 using namespace realm::_impl;
@@ -129,13 +130,22 @@ CollectionNotifier::CollectionNotifier(std::shared_ptr<Realm> realm)
     : m_realm(std::move(realm))
     , m_transaction(Realm::Internal::get_transaction_ref(*m_realm))
 {
+    if (auto logger = m_transaction->get_logger()) {
+        // We only have logging at debug and trace levels
+        if (logger->would_log(util::LogCategory::notification, util::Logger::Level::debug)) {
+            m_logger = logger;
+        }
+    }
 }
 
 CollectionNotifier::~CollectionNotifier()
 {
     // Need to do this explicitly to ensure m_realm is destroyed with the mutex
     // held to avoid potential double-deletion
     unregister();
+    if (m_logger) {
+        m_logger->log(util::LogCategory::notification, util::Logger::Level::debug, "Notifier %1 gone", m_description);
+    }
 }
 
 VersionID CollectionNotifier::version() const noexcept
@@ -320,6 +330,9 @@ void CollectionNotifier::before_advance()
 
 void CollectionNotifier::after_advance()
 {
+    using namespace std::chrono;
+    auto t1 = steady_clock::now();
+
     for_each_callback([&](auto& lock, auto& callback) {
         if (callback.initial_delivered && callback.changes_to_deliver.empty()) {
             return;
@@ -332,6 +345,50 @@ void CollectionNotifier::after_advance()
         // callback from within it can't result in a dangling pointer
         auto cb = callback.fn;
         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<microseconds>(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);
+                    }
+                }
+            }
+        }
         cb.after(changes);
     });
 }

src/realm/object-store/impl/collection_notifier.hpp

@@ -33,6 +33,11 @@
 #include <functional>
 #include <mutex>
 #include <unordered_set>
+#include <chrono>
+
+namespace realm::util {
+class Logger;
+}
 
 namespace realm::_impl {
 
@@ -211,6 +216,10 @@ class CollectionNotifier {
 
     void update_related_tables(Table const& table) REQUIRES(m_callback_mutex);
 
+    std::shared_ptr<util::Logger> m_logger;
+    std::string m_description;
+    std::chrono::steady_clock::time_point m_run_time_point;
+
     // The actual change, calculated in run() and delivered in prepare_handover()
     CollectionChangeBuilder m_change;
 

src/realm/object-store/impl/list_notifier.cpp

@@ -21,6 +21,7 @@
 #include <realm/object-store/list.hpp>
 
 #include <realm/transaction.hpp>
+#include <realm/util/scope_exit.hpp>
 
 using namespace realm;
 using namespace realm::_impl;
@@ -31,6 +32,15 @@ ListNotifier::ListNotifier(std::shared_ptr<Realm> realm, CollectionBase const& l
     , m_prev_size(list.size())
 {
     attach(list);
+    if (m_logger) {
+        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);
+
+        m_description = util::format("%1 %2%3", list.get_collection_type(), m_list->get_obj().get_id(), path);
+        m_logger->log(util::LogCategory::notification, util::Logger::Level::debug,
+                      "Creating CollectionNotifier for %1", m_description);
+    }
 }
 
 void ListNotifier::release_data() noexcept
@@ -80,6 +90,17 @@ 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<microseconds>(m_run_time_point - t1).count());
+        }
+    });
+
     if (!m_list || !m_list->is_attached()) {
         // List was deleted, so report all of the rows being removed if this is
         // the first run after that

src/realm/object-store/impl/object_notifier.cpp

@@ -19,6 +19,7 @@
 #include <realm/object-store/impl/object_notifier.hpp>
 
 #include <realm/object-store/shared_realm.hpp>
+#include <realm/util/scope_exit.hpp>
 
 using namespace realm;
 using namespace realm::_impl;
@@ -28,6 +29,11 @@ ObjectNotifier::ObjectNotifier(std::shared_ptr<Realm> realm, const Obj& obj)
     , m_table(obj.get_table())
     , m_obj_key(obj.get_key())
 {
+    if (m_logger) {
+        m_description = obj.get_id();
+        m_logger->log(util::LogCategory::notification, util::Logger::Level::debug, "Creating ObjectNotifier for %1",
+                      m_description);
+    }
 }
 
 void ObjectNotifier::reattach()
@@ -58,6 +64,16 @@ 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<microseconds>(m_run_time_point - t1).count());
+        }
+    });
 
     auto it = m_info->tables.find(m_table->get_key());
     if (it != m_info->tables.end() && it->second.deletions_contains(m_obj_key)) {

src/realm/object-store/impl/results_notifier.cpp

@@ -19,6 +19,7 @@
 #include <realm/object-store/impl/results_notifier.hpp>
 
 #include <realm/object-store/shared_realm.hpp>
+#include <realm/util/scope_exit.hpp>
 
 #include <numeric>
 
@@ -63,6 +64,15 @@ ResultsNotifier::ResultsNotifier(Results& target)
     , m_descriptor_ordering(target.get_descriptor_ordering())
     , 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("'");
+        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_description);
+    }
     reattach();
 }
 
@@ -141,8 +151,20 @@ void ResultsNotifier::calculate_changes()
 
 void ResultsNotifier::run()
 {
+    using namespace std::chrono;
+
     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<microseconds>(m_run_time_point - t1).count());
+        }
+    });
+
     // Table's been deleted, so report all objects as deleted
     if (!m_query->get_table()) {
         m_change = {};
@@ -252,6 +274,20 @@ ListResultsNotifier::ListResultsNotifier(Results& target)
         if (descr->get_type() == DescriptorType::Distinct)
             m_distinct = true;
     }
+    if (m_logger) {
+        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;
+        if (m_sort_order) {
+            sort_order = *m_sort_order ? " sorted ascending" : " sorted descending";
+        }
+
+        m_description =
+            util::format("%1 %2%3%4", m_list->get_collection_type(), m_list->get_obj().get_id(), path, sort_order);
+        m_logger->log(util::LogCategory::notification, util::Logger::Level::debug,
+                      "Creating ListResultsNotifier for %1", m_description);
+    }
 }
 
 void ListResultsNotifier::release_data() noexcept
@@ -322,6 +358,17 @@ 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<microseconds>(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 = {};
@@ -331,8 +378,10 @@ void ListResultsNotifier::run()
         return;
     }
 
-    if (!need_to_run())
+    if (!need_to_run()) {
+        cleanup.cancel();
         return;
+    }
 
     m_run_indices = std::vector<size_t>();
     if (m_distinct)

src/realm/query.cpp

@@ -1709,19 +1709,19 @@ std::string Query::validate() const
 
 std::string Query::get_description(util::serializer::SerialisationState& state) const
 {
-    if (m_view) {
-        throw SerializationError("Serialization of a query constrained by a view is not currently supported");
-    }
     std::string description;
     if (auto root = root_node()) {
         description = root->describe_expression(state);
     }
-    else {
+    if (m_view) {
+        description += util::format(" VIEW { %1 element(s) }", m_view->size());
+    }
+    if (description.length() == 0) {
         // An empty query returns all results and one way to indicate this
         // is to serialise TRUEPREDICATE which is functionally equivalent
         description = "TRUEPREDICATE";
     }
-    if (this->m_ordering) {
+    if (m_ordering) {
         description += " " + m_ordering->get_description(m_table);
     }
     return description;

src/realm/query.hpp

@@ -287,6 +287,10 @@ class Query final {
         return m_table;
     }
 
+    bool has_conditions() const
+    {
+        return m_groups.size() > 0 && m_groups[0].m_root_node;
+    }
     void get_outside_versions(TableVersions&) const;
 
     // True if matching rows are guaranteed to be returned in table order.
@@ -359,10 +363,6 @@ class Query final {
     size_t do_count(size_t limit = size_t(-1)) const;
     void delete_nodes() noexcept;
 
-    bool has_conditions() const
-    {
-        return m_groups.size() > 0 && m_groups[0].m_root_node;
-    }
     ParentNode* root_node() const
     {
         REALM_ASSERT(m_groups.size());

src/realm/transaction.hpp

@@ -164,9 +164,9 @@ class Transaction : public Group {
         return static_cast<bool>(m_oldest_version_not_persisted);
     }
 
-    util::Logger* get_logger() const noexcept
+    std::shared_ptr<util::Logger> get_logger() const noexcept
     {
-        return db->m_logger.get();
+        return db->m_logger;
     }
 
 private: