Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Logging notification activity #7072

Merged
merged 1 commit into from
Oct 24, 2023
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
2 changes: 1 addition & 1 deletion src/realm/db.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand Down
2 changes: 1 addition & 1 deletion src/realm/db.hpp
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
57 changes: 57 additions & 0 deletions src/realm/object-store/impl/collection_notifier.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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;
Expand All @@ -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);
});
}
Expand Down
9 changes: 9 additions & 0 deletions src/realm/object-store/impl/collection_notifier.hpp
Original file line number Diff line number Diff line change
Expand Up @@ -33,6 +33,11 @@
#include <functional>
#include <mutex>
#include <unordered_set>
#include <chrono>

namespace realm::util {
class Logger;
}

namespace realm::_impl {

Expand Down Expand Up @@ -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;

Expand Down
21 changes: 21 additions & 0 deletions src/realm/object-store/impl/list_notifier.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand All @@ -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
Expand Down Expand Up @@ -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
Expand Down
16 changes: 16 additions & 0 deletions src/realm/object-store/impl/object_notifier.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand All @@ -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()
Expand Down Expand Up @@ -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)) {
Expand Down
51 changes: 50 additions & 1 deletion src/realm/object-store/impl/results_notifier.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -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>

Expand Down Expand Up @@ -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();
}

Expand Down Expand Up @@ -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 = {};
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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 = {};
Expand All @@ -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)
Expand Down
10 changes: 5 additions & 5 deletions src/realm/query.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down
8 changes: 4 additions & 4 deletions src/realm/query.hpp
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand Down Expand Up @@ -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());
Expand Down
4 changes: 2 additions & 2 deletions src/realm/transaction.hpp
Original file line number Diff line number Diff line change
Expand Up @@ -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:
Expand Down
Loading