Room: refactoring around logging (esp. profile logs)

1 files changed, 24 insertions, 24 deletions

diff --git a/lib/room.cpp b/lib/room.cpp
index a06a8d2a..54d63138 100644
--- a/lib/room.cpp
+++ b/lib/room.cpp
@@ -266,8 +266,8 @@ public:
             }
             if (events.size() > 9 || et.nsecsElapsed() >= profilerMinNsecs())
                 qCDebug(PROFILER)
-                    << "*** Room::Private::updateStateFrom():" << events.size()
-                    << "event(s)," << et;
+                    << "Updated" << q->objectName() << "room state from"
+                    << events.size() << "event(s) in" << et;
         }
         return changes;
     }
@@ -713,7 +713,8 @@ Room::Changes Room::Private::updateUnreadCount(const rev_iter_t& from,
         count_if(from, to,
                  std::bind(&Room::Private::isEventNotable, this, _1));
     if (et.nsecsElapsed() > profilerMinNsecs() / 10)
-        qCDebug(PROFILER) << "Counting gained unread messages took" << et;
+        qCDebug(PROFILER) << "Counting gained unread messages in"
+                          << q->objectName() << "took" << et;
 
     if (newUnreadMessages == 0)
         return NoChange;
@@ -745,7 +746,8 @@ Room::Changes Room::Private::recalculateUnreadCount(bool force)
         int(count_if(timeline.crbegin(), q->fullyReadMarker(),
                      [this](const auto& ti) { return isEventNotable(ti); }));
     if (et.nsecsElapsed() > profilerMinNsecs() / 10)
-        qCDebug(PROFILER) << "Recounting unread messages took" << et;
+        qCDebug(PROFILER) << "Recounting unread messages in" << q->objectName()
+                          << "took" << et;
 
     // See https://github.com/quotient-im/libQuotient/wiki/unread_count
     if (unreadMessages == 0)
@@ -1634,21 +1636,13 @@ void Room::updateData(SyncRoomData&& data, bool fromCache)
     setJoinState(data.joinState);
 
     Changes roomChanges = Change::NoChange;
-    QElapsedTimer et;
-    et.start();
     for (auto&& event : data.accountData)
         roomChanges |= processAccountDataEvent(move(event));
 
     roomChanges |= d->updateStateFrom(data.state);
+    // The order of calculation is important - don't merge these lines!
+    roomChanges |= d->addNewMessageEvents(move(data.timeline));
 
-    if (!data.timeline.empty()) {
-        et.restart();
-        roomChanges |= d->addNewMessageEvents(move(data.timeline));
-        if (data.timeline.size() > 9 || et.nsecsElapsed() >= profilerMinNsecs())
-            qCDebug(PROFILER)
-                << "*** Room::addNewMessageEvents():" << data.timeline.size()
-                << "event(s)," << et;
-    }
     if (roomChanges & TopicChange)
         emit topicChanged();
 
@@ -2403,6 +2397,8 @@ Room::Changes Room::Private::addNewMessageEvents(RoomEvents&& events)
     if (events.empty())
         return Change::NoChange;
 
+    QElapsedTimer et;
+    et.start();
     {
         // Pre-process redactions and edits so that events that get
         // redacted/replaced in the same batch landed in the timeline already
@@ -2539,6 +2535,9 @@ Room::Changes Room::Private::addNewMessageEvents(RoomEvents&& events)
     }
 
     Q_ASSERT(timeline.size() == timelineSize + totalInserted);
+    if (totalInserted > 9 || et.nsecsElapsed() >= profilerMinNsecs())
+        qCDebug(PROFILER) << "Added" << totalInserted << "new event(s) to"
+                          << q->objectName() << "in" << et;
     return roomChanges;
 }
 
@@ -2583,13 +2582,13 @@ void Room::Private::addHistoricalMessageEvents(RoomEvents&& events)
     updateUnreadCount(from, historyEdge());
     // When there are no unread messages and the read marker is within the
     // known timeline, unreadMessages == -1
-    // (see https://github.com/quotient-im/libQuotient/wiki/unread_count).
+    // (see https://github.com/quotient-im/libQuotient/wiki/Developer-notes#2-saving-unread-event-counts).
     Q_ASSERT(unreadMessages != 0 || q->fullyReadMarker() == historyEdge());
 
     Q_ASSERT(timeline.size() == timelineSize + insertedSize);
     if (insertedSize > 9 || et.nsecsElapsed() >= profilerMinNsecs())
-        qCDebug(PROFILER) << "*** Room::addHistoricalMessageEvents():"
-                          << insertedSize << "event(s)," << et;
+        qCDebug(PROFILER) << "Added" << insertedSize << "historical event(s) to"
+                          << q->objectName() << "in" << et;
 }
 
 Room::Changes Room::processStateEvent(const RoomEvent& e)
@@ -2813,8 +2812,9 @@ Room::Changes Room::processEphemeralEvent(EventPtr&& event)
                 d->usersTyping.append(user(userId));
 
         if (evt->users().size() > 3 || et.nsecsElapsed() >= profilerMinNsecs())
-            qCDebug(PROFILER) << "*** Room::processEphemeralEvent(typing):"
-                              << evt->users().size() << "users," << et;
+            qCDebug(PROFILER)
+                << "Processing typing events from" << evt->users().size()
+                << "user(s) in" << objectName() << "took" << et;
         emit typingChanged();
     }
     if (auto* evt = eventCast<ReceiptEvent>(event)) {
@@ -2848,10 +2848,9 @@ Room::Changes Room::processEphemeralEvent(EventPtr&& event)
         }
         if (eventsWithReceipts.size() > 3 || totalReceipts > 10
             || et.nsecsElapsed() >= profilerMinNsecs())
-            qCDebug(PROFILER)
-                << "*** Room::processEphemeralEvent(receipts):"
-                << eventsWithReceipts.size() << "event(s) with"
-                << totalReceipts << "receipt(s)," << et;
+            qCDebug(PROFILER) << "Processing" << totalReceipts
+                              << "receipt(s) on" << eventsWithReceipts.size()
+                              << "event(s) in" << objectName() << "took" << et;
     }
     return changes;
 }
@@ -3075,7 +3074,8 @@ QJsonObject Room::Private::toJson() const
     result.insert(QStringLiteral("unread_notifications"), unreadNotifObj);
 
     if (et.elapsed() > 30)
-        qCDebug(PROFILER) << "Room::toJson() for" << displayname << "took" << et;
+        qCDebug(PROFILER) << "Room::toJson() for" << q->objectName() << "took"
+                          << et;
 
     return result;
 }