Skip to content

Commit

Permalink
Fix a data race in collection notifier logging and extract some dupli…
Browse files Browse the repository at this point in the history 
…cated code

m_run_time_point was read on the target thread while being written on the
worker thread without any locking involved.
  • Loading branch information
@tgoyne
tgoyne committed Mar 4, 2024
1 parent 77fff53 commit f7263ed
Show file tree
Hide file tree
Showing 5 changed files with 96 additions and 93 deletions.
121 changes: 75 additions & 46 deletions src/realm/object-store/impl/collection_notifier.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand All @@ -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()) {
Expand All @@ -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<microseconds>(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<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);
}
}
}
}
log_changeset(m_logger.get(), changes, m_description, elapsed);
cb.after(changes);
});
}
Expand Down Expand Up @@ -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<microseconds>(now - m_start).count());
}
}
12 changes: 12 additions & 0 deletions src/realm/object-store/impl/collection_notifier.hpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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 */
13 changes: 2 additions & 11 deletions src/realm/object-store/impl/list_notifier.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -33,7 +33,7 @@ ListNotifier::ListNotifier(std::shared_ptr<Realm> 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);
Expand Down Expand Up @@ -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<microseconds>(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
Expand Down
11 changes: 1 addition & 10 deletions src/realm/object-store/impl/object_notifier.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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<microseconds>(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)) {
Expand Down
32 changes: 6 additions & 26 deletions src/realm/object-store/impl/results_notifier.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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();
Expand Down Expand Up @@ -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<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 @@ -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";
}
Expand Down Expand Up @@ -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<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 @@ -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<size_t>();
if (m_distinct)
m_list->distinct(*m_run_indices, m_sort_order);
Expand Down

0 comments on commit f7263ed

Please sign in to comment.