Trace some timings.

4 files changed, 37 insertions, 11 deletions

diff --git a/common/clientapi.cpp b/common/clientapi.cpp
index a13456b..413abd3 100644
--- a/common/clientapi.cpp
+++ b/common/clientapi.cpp
@@ -22,6 +22,7 @@
 
 #include <QtConcurrent/QtConcurrentRun>
 #include <QTimer>
+#include <QTime>
 #include <QEventLoop>
 #include <QAbstractItemModel>
 #include <QDir>
@@ -162,13 +163,15 @@ KAsync::Job<void> Store::remove(const DomainType &domainObject)
 KAsync::Job<void> Store::shutdown(const QByteArray &identifier)
 {
     Trace() << "shutdown " << identifier;
-    return ResourceAccess::connectToServer(identifier).then<void, QSharedPointer<QLocalSocket>>([identifier](QSharedPointer<QLocalSocket> socket, KAsync::Future<void> &future) {
+    auto time = QSharedPointer<QTime>::create();
+    time->start();
+    return ResourceAccess::connectToServer(identifier).then<void, QSharedPointer<QLocalSocket>>([identifier, time](QSharedPointer<QLocalSocket> socket, KAsync::Future<void> &future) {
         //We can't currently reuse the socket
         socket->close();
         auto resourceAccess = QSharedPointer<Sink::ResourceAccess>::create(identifier);
         resourceAccess->open();
-        resourceAccess->sendCommand(Sink::Commands::ShutdownCommand).then<void>([&future, resourceAccess]() {
-            Trace() << "Shutdown complete";
+        resourceAccess->sendCommand(Sink::Commands::ShutdownCommand).then<void>([&future, resourceAccess, time]() {
+            Trace() << "Shutdown complete." << Log::TraceTime(time->elapsed());
             future.setFinished();
         }).exec();
     },
@@ -183,10 +186,12 @@ KAsync::Job<void> Store::shutdown(const QByteArray &identifier)
 KAsync::Job<void> Store::start(const QByteArray &identifier)
 {
     Trace() << "start " << identifier;
+    auto time = QSharedPointer<QTime>::create();
+    time->start();
     auto resourceAccess = QSharedPointer<Sink::ResourceAccess>::create(identifier);
     resourceAccess->open();
-    return resourceAccess->sendCommand(Sink::Commands::PingCommand).then<void>([resourceAccess]() {
-        Trace() << "Start complete";
+    return resourceAccess->sendCommand(Sink::Commands::PingCommand).then<void>([resourceAccess, time]() {
+        Trace() << "Start complete." << Log::TraceTime(time->elapsed());
     });
 }
 
@@ -303,15 +308,18 @@ KAsync::Job<void> Resources::inspect(const Inspection &inspectionCommand)
 {
     auto resource = inspectionCommand.resourceIdentifier;
 
+    auto time = QSharedPointer<QTime>::create();
+    time->start();
     Trace() << "Sending inspection " << resource;
     auto resourceAccess = QSharedPointer<Sink::ResourceAccess>::create(resource);
     resourceAccess->open();
     auto notifier = QSharedPointer<Sink::Notifier>::create(resourceAccess);
     auto id = QUuid::createUuid().toByteArray();
     return resourceAccess->sendInspectionCommand(id, ApplicationDomain::getTypeName<DomainType>(), inspectionCommand.entityIdentifier, inspectionCommand.property, inspectionCommand.expectedValue)
-        .template then<void>([resourceAccess, notifier, id](KAsync::Future<void> &future) {
-            notifier->registerHandler([&future, id](const Notification &notification) {
+        .template then<void>([resourceAccess, notifier, id, time](KAsync::Future<void> &future) {
+            notifier->registerHandler([&future, id, time](const Notification &notification) {
                 if (notification.id == id) {
+                    Trace() << "Inspection complete." << Log::TraceTime(time->elapsed());
                     if (notification.code) {
                         future.setError(-1, "Inspection returned an error: " + notification.message);
                     } else {
diff --git a/common/genericresource.cpp b/common/genericresource.cpp
index b49ca94..ffb323d 100644
--- a/common/genericresource.cpp
+++ b/common/genericresource.cpp
@@ -17,6 +17,7 @@
 
 #include <QUuid>
 #include <QDataStream>
+#include <QTime>
 
 static int sBatchSize = 100;
 
@@ -273,9 +274,12 @@ private slots:
         return KAsync::dowhile(
             [it]() { return it->hasNext(); },
             [it, this](KAsync::Future<void> &future) {
+                auto time = QSharedPointer<QTime>::create();
+                time->start();
+
                 auto queue = it->next();
-                processQueue(queue).then<void>([&future]() {
-                    Trace() << "Queue processed";
+                processQueue(queue).then<void>([&future, time]() {
+                    Trace() << "Queue processed." << Log::TraceTime(time->elapsed());
                     future.setFinished();
                 }).exec();
             }
diff --git a/common/log.h b/common/log.h
index 7d02634..bf133c4 100644
--- a/common/log.h
+++ b/common/log.h
@@ -55,6 +55,18 @@ QByteArrayList SINKCOMMON_EXPORT debugOutputFields();
 
 QDebug SINKCOMMON_EXPORT debugStream(DebugLevel debugLevel, int line, const char* file, const char* function, const char* debugArea = 0);
 
+struct SINKCOMMON_EXPORT TraceTime
+{
+    TraceTime(int i) : time(i){};
+    const int time;
+};
+
+inline QDebug SINKCOMMON_EXPORT operator<<(QDebug d, const TraceTime &time)
+{
+    d << time.time << "[ms]";
+    return d;
+}
+
 }
 }
 
diff --git a/common/resourceaccess.cpp b/common/resourceaccess.cpp
index 345622c..dd862c8 100644
--- a/common/resourceaccess.cpp
+++ b/common/resourceaccess.cpp
@@ -381,9 +381,11 @@ void ResourceAccess::open()
     if (d->openingSocket) {
         return;
     }
+    auto time = QSharedPointer<QTime>::create();
+    time->start();
     d->openingSocket = true;
-    d->initializeSocket().then<void>([this]() {
-        Trace() << "Socket is initialized";
+    d->initializeSocket().then<void>([this, time]() {
+        Trace() << "Socket is initialized." << Log::TraceTime(time->elapsed());
         d->openingSocket = false;
         QObject::connect(d->socket.data(), &QLocalSocket::disconnected,
                 this, &ResourceAccess::disconnected);