From 23ebed25b79f4b6edf630546d7d9d571398a1640 Mon Sep 17 00:00:00 2001
From: Kitsune Ral <Kitsune-Ral@users.sf.net>
Date: Sun, 4 Nov 2018 19:55:20 +0900
Subject: Profiler logging fixes and improvements
---
lib/jobs/syncjob.cpp | 9 +++++----
lib/logging.h | 11 +++++++++++
lib/room.cpp | 30 ++++++++++++++++++------------
3 files changed, 34 insertions(+), 16 deletions(-)
diff --git a/lib/jobs/syncjob.cpp b/lib/jobs/syncjob.cpp
index 9cbac71b..6baf388e 100644
--- a/lib/jobs/syncjob.cpp
+++ b/lib/jobs/syncjob.cpp
@@ -109,11 +109,12 @@ BaseJob::Status SyncData::parseJson(const QJsonDocument &data)
totalEvents += r.state.size() + r.ephemeral.size() +
r.accountData.size() + r.timeline.size();
}
- totalRooms += roomData.size();
+ totalRooms += rs.size();
}
- qCDebug(PROFILER) << "*** SyncData::parseJson(): batch with"
- << totalRooms << "room(s),"
- << totalEvents << "event(s) in" << et;
+ if (totalRooms > 9 || et.nsecsElapsed() >= profilerMinNsecs())
+ qCDebug(PROFILER) << "*** SyncData::parseJson(): batch with"
+ << totalRooms << "room(s),"
+ << totalEvents << "event(s) in" << et;
return BaseJob::Success;
}
diff --git a/lib/logging.h b/lib/logging.h
index 8dbfdf30..6c93ca79 100644
--- a/lib/logging.h
+++ b/lib/logging.h
@@ -65,6 +65,17 @@ namespace QMatrixClient
{
return qdm(debug_object);
}
+
+ inline qint64 profilerMinNsecs()
+ {
+ return
+ #ifdef PROFILER_LOG_MIN_MS
+ PROFILER_LOG_MIN_MS
+ #else
+ 200
+ #endif
+ * 1000;
+ }
}
inline QDebug operator<< (QDebug debug_object, const QElapsedTimer& et)
diff --git a/lib/room.cpp b/lib/room.cpp
index aa1dfbf6..9cdacd91 100644
--- a/lib/room.cpp
+++ b/lib/room.cpp
@@ -416,7 +416,7 @@ void Room::Private::updateUnreadCount(rev_iter_t from, rev_iter_t to)
QElapsedTimer et; et.start();
const auto newUnreadMessages = count_if(from, to,
std::bind(&Room::Private::isEventNotable, this, _1));
- if (et.nsecsElapsed() > 10000)
+ if (et.nsecsElapsed() > profilerMinNsecs() / 10)
qCDebug(PROFILER) << "Counting gained unread messages took" << et;
if(newUnreadMessages > 0)
@@ -458,7 +458,7 @@ void Room::Private::promoteReadMarker(User* u, rev_iter_t newMarker, bool force)
QElapsedTimer et; et.start();
unreadMessages = count_if(eagerMarker, timeline.cend(),
std::bind(&Room::Private::isEventNotable, this, _1));
- if (et.nsecsElapsed() > 10000)
+ if (et.nsecsElapsed() > profilerMinNsecs() / 10)
qCDebug(PROFILER) << "Recounting unread messages took" << et;
// See https://github.com/QMatrixClient/libqmatrixclient/wiki/unread_count
@@ -1103,8 +1103,9 @@ void Room::updateData(SyncRoomData&& data)
emitNamesChanged |= processStateEvent(evt);
}
- qCDebug(PROFILER) << "*** Room::processStateEvents():"
- << data.state.size() << "event(s)," << et;
+ if (data.state.size() > 9 || et.nsecsElapsed() >= profilerMinNsecs())
+ qCDebug(PROFILER) << "*** Room::processStateEvents():"
+ << data.state.size() << "event(s)," << et;
}
if (!data.timeline.empty())
{
@@ -1112,8 +1113,9 @@ void Room::updateData(SyncRoomData&& data)
// State changes can arrive in a timeline event; so check those.
for (const auto& e: data.timeline)
emitNamesChanged |= processStateEvent(*e);
- qCDebug(PROFILER) << "*** Room::processStateEvents(timeline):"
- << data.timeline.size() << "event(s)," << et;
+ if (data.timeline.size() > 9 || et.nsecsElapsed() >= profilerMinNsecs())
+ qCDebug(PROFILER) << "*** Room::processStateEvents(timeline):"
+ << data.timeline.size() << "event(s)," << et;
}
if (emitNamesChanged)
emit namesChanged(this);
@@ -1123,7 +1125,8 @@ void Room::updateData(SyncRoomData&& data)
{
et.restart();
d->addNewMessageEvents(move(data.timeline));
- qCDebug(PROFILER) << "*** Room::addNewMessageEvents():" << et;
+ if (data.timeline.size() > 9 || et.nsecsElapsed() >= profilerMinNsecs())
+ qCDebug(PROFILER) << "*** Room::addNewMessageEvents():" << et;
}
for( auto&& ephemeralEvent: data.ephemeral )
processEphemeralEvent(move(ephemeralEvent));
@@ -1162,7 +1165,7 @@ QString Room::Private::sendEvent(RoomEventPtr&& event)
QString Room::Private::doSendEvent(const RoomEvent* pEvent)
{
auto txnId = pEvent->transactionId();
- // TODO: Enqueue the job rather than immediately trigger it
+ // TODO, #133: Enqueue the job rather than immediately trigger it.
auto call = connection->callApi<SendMessageJob>(BackgroundRequest,
id, pEvent->matrixType(), txnId, pEvent->contentJson());
Room::connect(call, &BaseJob::started, q,
@@ -1844,15 +1847,17 @@ void Room::processEphemeralEvent(EventPtr&& event)
if (memberJoinState(u) == JoinState::Join)
d->usersTyping.append(u);
}
- if (!evt->users().isEmpty())
+ if (evt->users().size() > 3 || et.nsecsElapsed() >= profilerMinNsecs())
qCDebug(PROFILER) << "*** Room::processEphemeralEvent(typing):"
<< evt->users().size() << "users," << et;
emit typingChanged();
}
if (auto* evt = eventCast<ReceiptEvent>(event))
{
+ int totalReceipts = 0;
for( const auto &p: qAsConst(evt->eventsWithReceipts()) )
{
+ totalReceipts += p.receipts.size();
{
if (p.receipts.size() == 1)
qCDebug(EPHEMERAL) << "Marking" << p.evtId
@@ -1891,10 +1896,11 @@ void Room::processEphemeralEvent(EventPtr&& event)
}
}
}
- if (!evt->eventsWithReceipts().isEmpty())
+ if (evt->eventsWithReceipts().size() > 3 || totalReceipts > 10 ||
+ et.nsecsElapsed() >= profilerMinNsecs())
qCDebug(PROFILER) << "*** Room::processEphemeralEvent(receipts):"
<< evt->eventsWithReceipts().size()
- << "events with receipts," << et;
+ << "event(s) with" << totalReceipts << "receipt(s)," << et;
}
}
@@ -2055,7 +2061,7 @@ QJsonObject Room::Private::toJson() const
result.insert(QStringLiteral("unread_notifications"), unreadNotifObj);
- if (et.elapsed() > 50)
+ if (et.elapsed() > 30)
qCDebug(PROFILER) << "Room::toJson() for" << displayname << "took" << et;
return result;
--
cgit v1.2.3