From 8383fa3547b362bc37908a5a98f649497d7d0ccf Mon Sep 17 00:00:00 2001
From: elsid <elsid.mail@gmail.com>
Date: Thu, 16 Feb 2023 23:38:47 +0100
Subject: [PATCH] Log time spent on document operations in editor

---
 apps/opencs/model/doc/operation.cpp | 41 ++++++++++++++++++++++++++++-
 apps/opencs/model/doc/operation.hpp |  8 ++++--
 2 files changed, 46 insertions(+), 3 deletions(-)

diff --git a/apps/opencs/model/doc/operation.cpp b/apps/opencs/model/doc/operation.cpp
index fe08c00231..4ba9f8ef84 100644
--- a/apps/opencs/model/doc/operation.cpp
+++ b/apps/opencs/model/doc/operation.cpp
@@ -6,12 +6,40 @@
 
 #include <QTimer>
 
+#include <components/debug/debuglog.hpp>
+
 #include <apps/opencs/model/doc/messages.hpp>
 
 #include "../world/universalid.hpp"
 
 #include "stage.hpp"
 
+namespace CSMDoc
+{
+    namespace
+    {
+        std::string_view operationToString(State value)
+        {
+            switch (value)
+            {
+                case State_Saving:
+                    return "Saving";
+                case State_Merging:
+                    return "Merging";
+                case State_Verifying:
+                    return "Verifying";
+                case State_Searching:
+                    return "Searching";
+                case State_Loading:
+                    return "Loading";
+                default:
+                    break;
+            }
+            return "Unknown";
+        }
+    }
+}
+
 void CSMDoc::Operation::prepareStages()
 {
     mCurrentStage = mStages.begin();
@@ -27,7 +55,7 @@ void CSMDoc::Operation::prepareStages()
     }
 }
 
-CSMDoc::Operation::Operation(int type, bool ordered, bool finalAlways)
+CSMDoc::Operation::Operation(State type, bool ordered, bool finalAlways)
     : mType(type)
     , mStages(std::vector<std::pair<Stage*, int>>())
     , mCurrentStage(mStages.begin())
@@ -61,6 +89,7 @@ void CSMDoc::Operation::run()
     }
 
     mPrepared = false;
+    mStart = std::chrono::steady_clock::now();
 
     mTimer->start(0);
 }
@@ -140,7 +169,17 @@ void CSMDoc::Operation::executeStage()
         emit reportMessage(*iter, mType);
 
     if (mCurrentStage == mStages.end())
+    {
+        if (mStart.has_value())
+        {
+            const auto duration = std::chrono::steady_clock::now() - *mStart;
+            Log(Debug::Verbose) << operationToString(mType) << " operation is completed in "
+                                << std::chrono::duration_cast<std::chrono::duration<double>>(duration).count() << 's';
+            mStart.reset();
+        }
+
         operationDone();
+    }
 }
 
 void CSMDoc::Operation::operationDone()
diff --git a/apps/opencs/model/doc/operation.hpp b/apps/opencs/model/doc/operation.hpp
index 86a28de3cb..f569ffa251 100644
--- a/apps/opencs/model/doc/operation.hpp
+++ b/apps/opencs/model/doc/operation.hpp
@@ -1,12 +1,15 @@
 #ifndef CSM_DOC_OPERATION_H
 #define CSM_DOC_OPERATION_H
 
+#include <chrono>
+#include <optional>
 #include <utility>
 #include <vector>
 
 #include <QObject>
 
 #include "messages.hpp"
+#include "state.hpp"
 
 class QTimer;
 
@@ -18,7 +21,7 @@ namespace CSMDoc
     {
         Q_OBJECT
 
-        int mType;
+        State mType;
         std::vector<std::pair<Stage*, int>> mStages; // stage, number of steps
         std::vector<std::pair<Stage*, int>>::iterator mCurrentStage;
         int mCurrentStep;
@@ -31,11 +34,12 @@ namespace CSMDoc
         QTimer* mTimer;
         bool mPrepared;
         Message::Severity mDefaultSeverity;
+        std::optional<std::chrono::steady_clock::time_point> mStart;
 
         void prepareStages();
 
     public:
-        Operation(int type, bool ordered, bool finalAlways = false);
+        Operation(State type, bool ordered, bool finalAlways = false);
         ///< \param ordered Stages must be executed in the given order.
         /// \param finalAlways Execute last stage even if an error occurred during earlier stages.