Profiling logs: added µs, less empty profiling log lines

Closes #177.

5 files changed, 33 insertions, 30 deletions

diff --git a/connection.cpp b/connection.cpp
index 9a5a5a4e..06da17e0 100644
--- a/connection.cpp
+++ b/connection.cpp
@@ -684,8 +684,7 @@ void Connection::saveState(const QUrl &toFile) const
 
     qCDebug(MAIN) << "Writing state to file" << outfile.fileName();
     outfile.write(data.data(), data.size());
-    qCDebug(PROFILER) << "*** Cached state for" << userId()
-                      << "saved in" << et.elapsed() << "ms";
+    qCDebug(PROFILER) << "*** Cached state for" << userId() << "saved in" << et;
 }
 
 void Connection::loadState(const QUrl &fromFile)
@@ -722,8 +721,7 @@ void Connection::loadState(const QUrl &fromFile)
     SyncData sync;
     sync.parseJson(jsonDoc);
     onSyncSuccess(std::move(sync));
-    qCDebug(PROFILER) << "*** Cached state for" << userId()
-                      << "loaded in" << et.elapsed() << "ms";
+    qCDebug(PROFILER) << "*** Cached state for" << userId() << "loaded in" << et;
 }
 
 QString Connection::stateCachePath() const
diff --git a/jobs/syncjob.cpp b/jobs/syncjob.cpp
index 7b066f4f..fd8bfc1a 100644
--- a/jobs/syncjob.cpp
+++ b/jobs/syncjob.cpp
@@ -83,7 +83,8 @@ BaseJob::Status SyncData::parseJson(const QJsonDocument &data)
             roomData.emplace_back(roomIt.key(), JoinState(i),
                                   roomIt.value().toObject());
     }
-    qCDebug(PROFILER) << "*** SyncData::parseJson():" << et.elapsed() << "ms";
+    qCDebug(PROFILER) << "*** SyncData::parseJson(): batch with"
+                      << rooms.size() << "room(s) in" << et;
     return BaseJob::Success;
 }
 
diff --git a/logging.h b/logging.h
index aaeceeac..ae7e0332 100644
--- a/logging.h
+++ b/logging.h
@@ -18,6 +18,7 @@
 
 #pragma once
 
+#include <QtCore/QElapsedTimer>
 #include <QtCore/QLoggingCategory>
 
 Q_DECLARE_LOGGING_CATEGORY(MAIN)
@@ -65,3 +66,13 @@ namespace QMatrixClient
         return qdm(debug_object);
     }
 }
+
+inline QDebug operator<< (QDebug debug_object, const QElapsedTimer& et)
+{
+    auto val = et.nsecsElapsed() / 1000;
+    if (val < 1000)
+        debug_object << val << u"µs";
+    else
+        debug_object << val / 1000 << "ms";
+    return debug_object;
+}
diff --git a/room.cpp b/room.cpp
index db36a713..20b19e93 100644
--- a/room.cpp
+++ b/room.cpp
@@ -876,7 +876,7 @@ void Room::updateData(SyncRoomData&& data)
         et.start();
         processStateEvents(data.state);
         qCDebug(PROFILER) << "*** Room::processStateEvents(state):"
-            << et.elapsed() << "ms," << data.state.size() << "events";
+                          << data.state.size() << "event(s)," << et;
     }
     if (!data.timeline.empty())
     {
@@ -884,30 +884,17 @@ void Room::updateData(SyncRoomData&& data)
         // State changes can arrive in a timeline event; so check those.
         processStateEvents(data.timeline);
         qCDebug(PROFILER) << "*** Room::processStateEvents(timeline):"
-            << et.elapsed() << "ms," << data.timeline.size() << "events";
+                          << data.timeline.size() << "event(s)," << et;
 
         et.restart();
         d->addNewMessageEvents(move(data.timeline));
-        qCDebug(PROFILER) << "*** Room::addNewMessageEvents():"
-                          << et.elapsed() << "ms";
-    }
-    if (!data.ephemeral.empty())
-    {
-        et.restart();
-        for( auto&& ephemeralEvent: data.ephemeral )
-            processEphemeralEvent(move(ephemeralEvent));
-        qCDebug(PROFILER) << "*** Room::processEphemeralEvents():"
-                          << et.elapsed() << "ms";
+        qCDebug(PROFILER) << "*** Room::addNewMessageEvents():" << et;
     }
+    for( auto&& ephemeralEvent: data.ephemeral )
+        processEphemeralEvent(move(ephemeralEvent));
 
-    if (!data.accountData.empty())
-    {
-        et.restart();
-        for (auto&& event: data.accountData)
-            processAccountDataEvent(move(event));
-        qCDebug(PROFILER) << "*** Room::processAccountData():"
-                          << et.elapsed() << "ms";
-    }
+    for (auto&& event: data.accountData)
+        processAccountDataEvent(move(event));
 
     if( data.highlightCount != d->highlightCount )
     {
@@ -1406,6 +1393,7 @@ void Room::processStateEvents(const RoomEvents& events)
 
 void Room::processEphemeralEvent(EventPtr event)
 {
+    QElapsedTimer et; et.start();
     switch (event->type())
     {
         case EventType::Typing: {
@@ -1417,6 +1405,9 @@ void Room::processEphemeralEvent(EventPtr event)
                 if (memberJoinState(u) == JoinState::Join)
                     d->usersTyping.append(u);
             }
+            if (!typingEvent->users().isEmpty())
+                qCDebug(PROFILER) << "*** Room::processEphemeralEvent(typing):"
+                    << typingEvent->users().size() << "users," << et;
             emit typingChanged();
             break;
         }
@@ -1459,13 +1450,17 @@ void Room::processEphemeralEvent(EventPtr event)
                     }
                 }
             }
+            if (!receiptEvent->eventsWithReceipts().isEmpty())
+                qCDebug(PROFILER) << "*** Room::processEphemeralEvent(receipts):"
+                    << receiptEvent->eventsWithReceipts().size()
+                    << "events with receipts," << et;
             if (receiptEvent->unreadMessages())
                 d->unreadMessages = true;
             break;
         }
         default:
             qCWarning(EPHEMERAL) << "Unexpected event type in 'ephemeral' batch:"
-                                 << event->type();
+                                 << event->jsonType();
     }
 }
 
diff --git a/user.cpp b/user.cpp
index 308b217c..54eaf38c 100644
--- a/user.cpp
+++ b/user.cpp
@@ -128,8 +128,7 @@ void User::Private::setNameForRoom(const Room* r, QString newName,
             mostUsedName = newName;
             otherNames.remove(newName);
             if (totalRooms > MIN_JOINED_ROOMS_TO_LOG)
-                qCDebug(PROFILER) << et.elapsed()
-                                  << "ms to switch the most used name";
+                qCDebug(PROFILER) << et << "to switch the most used name";
         }
         else
             otherNames.insert(newName, r);
@@ -186,8 +185,7 @@ void User::Private::setAvatarForRoom(const Room* r, const QUrl& newUrl,
                     avatarsToRooms.insert(nextMostUsed->url(), r1);
 
             if (totalRooms > MIN_JOINED_ROOMS_TO_LOG)
-                qCDebug(PROFILER) << et.elapsed()
-                                  << "ms to switch the most used avatar";
+                qCDebug(PROFILER) << et << "to switch the most used avatar";
         } else {
             otherAvatars.insert(newUrl, makeAvatar(newUrl));
             avatarsToRooms.insert(newUrl, r);