From a1929bd9d7d29223a4523d727510fd90a7ff57b4 Mon Sep 17 00:00:00 2001
From: Cristian Adam <cristian.adam@qt.io>
Date: Fri, 4 Mar 2022 19:42:46 +0100
Subject: [PATCH] ClangCodeModel: Add some more timing debug information

By setting QT_LOGGING_RULES=qtc.clangcodemodel.clangd.timing=true I can get
values like:

qtc.clangcodemodel.clangd.timing: highlighting: Start to end: 2953 ms
qtc.clangcodemodel.clangd.timing: ClangdCompletionAssistProcessor took: 7343 ms

The first tells you how long Creator took to turn clangd's semantic tokens into
full highlighting info, and the second how long it took for Ctrl+Space.

Change-Id: I99bd04c2889bb7da98c04537eab06d6ed6117167
Reviewed-by: Christian Kandeler <christian.kandeler@qt.io>
---
 src/plugins/clangcodemodel/clangdclient.cpp | 35 ++++++++++++++++-----
 1 file changed, 28 insertions(+), 7 deletions(-)

diff --git a/src/plugins/clangcodemodel/clangdclient.cpp b/src/plugins/clangcodemodel/clangdclient.cpp
index 894f22aaa92..6d343c62a2a 100644
--- a/src/plugins/clangcodemodel/clangdclient.cpp
+++ b/src/plugins/clangcodemodel/clangdclient.cpp
@@ -997,9 +997,12 @@ public:
             m_started = true;
             m_finalized = false;
             qCDebug(clangdLogTiming).noquote().nospace() << m_task << ": starting";
+
+            // Used by ThreadedSubtaskTimer to mark the end of the whole highlighting operation
+            m_startTimer.restart();
         }
         qCDebug(clangdLogTiming).noquote().nospace() << m_task << ": subtask started at "
-                                                     << QDateTime::currentDateTime().toString();
+                                                     << QDateTime::currentDateTime().time().toString("hh:mm:ss.zzz");
         QTC_CHECK(!m_timer.isValid());
         m_timer.start();
     }
@@ -1012,7 +1015,7 @@ public:
         if (--m_subtasks > 0) // See startSubtask().
             return;
         qCDebug(clangdLogTiming).noquote().nospace() << m_task << ": subtask stopped at "
-                                                     << QDateTime::currentDateTime().toString();
+                                                     << QDateTime::currentDateTime().time().toString("hh:mm:ss.zzz");
         QTC_CHECK(m_timer.isValid());
         m_elapsedMs += m_timer.elapsed();
         m_timer.invalidate();
@@ -1020,9 +1023,12 @@ public:
             stopTask();
     }
 
+    QElapsedTimer startTimer() const { return m_startTimer; }
+
 private:
     const QString m_task;
     QElapsedTimer m_timer;
+    QElapsedTimer m_startTimer;
     qint64 m_elapsedMs = 0;
     int m_subtasks = 0;
     bool m_started = false;
@@ -1052,7 +1058,7 @@ public:
 class ThreadedSubtaskTimer
 {
 public:
-    ThreadedSubtaskTimer(const QString &task) : m_task(task)
+    ThreadedSubtaskTimer(const QString &task, const TaskTimer &taskTimer) : m_task(task), m_taskTimer(taskTimer)
     {
         qCDebug(clangdLogTiming).noquote().nospace() << m_task << ": starting thread";
         m_timer.start();
@@ -1062,10 +1068,15 @@ public:
     {
         qCDebug(clangdLogTiming).noquote().nospace() << m_task << ": took " << m_timer.elapsed()
                                                      << " ms in dedicated thread";
+
+        qCDebug(clangdLogTiming).noquote().nospace() << m_task << ": Start to end: "
+                                                     << m_taskTimer.startTimer().elapsed() << " ms";
     }
+
 private:
     const QString m_task;
     QElapsedTimer m_timer;
+    const TaskTimer &m_taskTimer;
 };
 
 class MemoryTreeModel;
@@ -1191,6 +1202,13 @@ public:
         : LanguageClientCompletionAssistProcessor(client, snippetsGroup)
         , m_client(client)
     {
+        m_timer.start();
+    }
+
+    ~ClangdCompletionAssistProcessor()
+    {
+        qCDebug(clangdLogTiming).noquote().nospace()
+            << "ClangdCompletionAssistProcessor took: " << m_timer.elapsed() << " ms";
     }
 
 private:
@@ -1208,6 +1226,7 @@ private:
         const QList<LanguageServerProtocol::CompletionItem> &items) const override;
 
     ClangdClient * const m_client;
+    QElapsedTimer m_timer;
 };
 
 QList<AssistProposalItemInterface *>
@@ -2653,9 +2672,10 @@ static void semanticHighlighter(QFutureInterface<HighlightingResult> &future,
                                 const QList<ExpandedSemanticToken> &tokens,
                                 const QString &docContents, const AstNode &ast,
                                 const QPointer<TextDocument> &textDocument,
-                                int docRevision, const QVersionNumber &clangdVersion)
+                                int docRevision, const QVersionNumber &clangdVersion,
+                                const TaskTimer &taskTimer)
 {
-    ThreadedSubtaskTimer t("highlighting");
+    ThreadedSubtaskTimer t("highlighting", taskTimer);
     if (future.isCanceled()) {
         future.reportFinished();
         return;
@@ -2921,9 +2941,10 @@ void ClangdClient::Private::handleSemanticTokens(TextDocument *doc,
         const auto runner = [tokens, filePath = doc->filePath(),
                              text = doc->document()->toPlainText(), ast,
                              doc = QPointer(doc), rev = doc->document()->revision(),
-                             clangdVersion = q->versionNumber()] {
+                             clangdVersion = q->versionNumber(),
+                             this] {
             return Utils::runAsync(semanticHighlighter, filePath, tokens, text, ast, doc, rev,
-                                   clangdVersion);
+                                   clangdVersion, highlightingTimer);
         };
 
         if (isTesting) {