From c1c336a9064557bb987c30582bce84bab3f869bc Mon Sep 17 00:00:00 2001
From: Christian Mollekopf <chrigi_1@fastmail.fm>
Date: Wed, 10 Feb 2016 10:33:31 +0100
Subject: Gather more timings

---
 common/genericresource.cpp | 15 ++++++++++-----
 common/pipeline.cpp        | 12 +++++++++++-
 2 files changed, 21 insertions(+), 6 deletions(-)

diff --git a/common/genericresource.cpp b/common/genericresource.cpp
index c097893..2688df0 100644
--- a/common/genericresource.cpp
+++ b/common/genericresource.cpp
@@ -234,15 +234,17 @@ private slots:
     //Process all messages of this queue
     KAsync::Job<void> processQueue(MessageQueue *queue)
     {
+        auto time = QSharedPointer<QTime>::create();
         return KAsync::start<void>([this](){
             mPipeline->startTransaction();
         }).then(KAsync::dowhile(
             [queue]() { return !queue->isEmpty(); },
-            [this, queue](KAsync::Future<void> &future) {
-                queue->dequeueBatch(sBatchSize, [this](const QByteArray &data) {
-                        return KAsync::start<void>([this, data](KAsync::Future<void> &future) {
-                            processQueuedCommand(data).then<void, qint64>([&future, this](qint64 createdRevision) {
-                                Trace() << "Created revision " << createdRevision;
+            [this, queue, time](KAsync::Future<void> &future) {
+                queue->dequeueBatch(sBatchSize, [this, time](const QByteArray &data) {
+                        time->start();
+                        return KAsync::start<void>([this, data, time](KAsync::Future<void> &future) {
+                            processQueuedCommand(data).then<void, qint64>([&future, this, time](qint64 createdRevision) {
+                                Trace() << "Created revision " << createdRevision << ". Processing took: " << Log::TraceTime(time->elapsed());
                                 future.setFinished();
                             }).exec();
                         });
@@ -264,12 +266,15 @@ private slots:
 
     KAsync::Job<void> processPipeline()
     {
+        auto time = QSharedPointer<QTime>::create();
+        time->start();
         mPipeline->startTransaction();
         Trace() << "Cleaning up from " << mPipeline->cleanedUpRevision() + 1 << " to " << mLowerBoundRevision;
         for (qint64 revision = mPipeline->cleanedUpRevision() + 1; revision <= mLowerBoundRevision; revision++) {
             mPipeline->cleanupRevision(revision);
         }
         mPipeline->commit();
+        Trace() << "Cleanup done." << Log::TraceTime(time->elapsed());
 
         //Go through all message queues
         auto it = QSharedPointer<QListIterator<MessageQueue*> >::create(mCommandQueues);
diff --git a/common/pipeline.cpp b/common/pipeline.cpp
index 627550e..93d8236 100644
--- a/common/pipeline.cpp
+++ b/common/pipeline.cpp
@@ -25,6 +25,7 @@
 #include <QVector>
 #include <QUuid>
 #include <QDebug>
+#include <QTime>
 #include "entity_generated.h"
 #include "metadata_generated.h"
 #include "createentity_generated.h"
@@ -57,6 +58,8 @@ public:
     QHash<QString, DomainTypeAdaptorFactoryInterface::Ptr> adaptorFactory;
     bool revisionChanged;
     void storeNewRevision(qint64 newRevision, const flatbuffers::FlatBufferBuilder &fbb, const QByteArray &bufferType, const QByteArray &uid);
+    QTime transactionTime;
+    int transactionItemCount;
 };
 
 void Pipeline::Private::storeNewRevision(qint64 newRevision, const flatbuffers::FlatBufferBuilder &fbb, const QByteArray &bufferType, const QByteArray &uid)
@@ -103,6 +106,9 @@ void Pipeline::startTransaction()
     if (d->transaction) {
         return;
     }
+    Trace() << "Starting transaction.";
+    d->transactionTime.start();
+    d->transactionItemCount = 0;
     d->transaction = std::move(storage().createTransaction(Storage::ReadWrite));
 }
 
@@ -114,7 +120,8 @@ void Pipeline::commit()
     //     processor->finalize();
     // }
     const auto revision = Storage::maxRevision(d->transaction);
-    Trace() << "Committing " << revision;
+    const auto elapsed = d->transactionTime.elapsed();
+    Trace() << "Committing revision: " << revision << ":" << d->transactionItemCount << " items in: " << Log::TraceTime(elapsed) << " " << (double)elapsed/(double)qMax(d->transactionItemCount, 1) << "[ms/item]";
     if (d->transaction) {
         d->transaction.commit();
     }
@@ -138,6 +145,7 @@ Storage &Pipeline::storage() const
 KAsync::Job<qint64> Pipeline::newEntity(void const *command, size_t size)
 {
     Trace() << "Pipeline: New Entity";
+    d->transactionItemCount++;
 
     {
         flatbuffers::Verifier verifyer(reinterpret_cast<const uint8_t *>(command), size);
@@ -217,6 +225,7 @@ KAsync::Job<qint64> Pipeline::newEntity(void const *command, size_t size)
 KAsync::Job<qint64> Pipeline::modifiedEntity(void const *command, size_t size)
 {
     Trace() << "Pipeline: Modified Entity";
+    d->transactionItemCount++;
 
     const qint64 newRevision = Storage::maxRevision(d->transaction) + 1;
 
@@ -337,6 +346,7 @@ KAsync::Job<qint64> Pipeline::modifiedEntity(void const *command, size_t size)
 KAsync::Job<qint64> Pipeline::deletedEntity(void const *command, size_t size)
 {
     Trace() << "Pipeline: Deleted Entity";
+    d->transactionItemCount++;
 
     {
         flatbuffers::Verifier verifyer(reinterpret_cast<const uint8_t *>(command), size);
-- 
cgit v1.2.3