feedc0de/qt-creator
1
0
Fork 0
forked from qt-creator/qt-creator
Code Pull Requests Activity

ClangCodeModel: Add some more timing debug information

Browse Source 
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>
This commit is contained in:
Cristian Adam
2022-03-04 19:42:46 +01:00
parent 047253b6a8
commit a1929bd9d7
1 changed files with 28 additions and 7 deletions
Download Patch File Download Diff File Expand all files Collapse all files

35
src/plugins/clangcodemodel/clangdclient.cpp
View File

@@ -997,9 +997,12 @@ public:
m_started = true; m_started = true;
m_finalized = false; m_finalized = false;
qCDebug(clangdLogTiming).noquote().nospace() << m_task << ": starting"; 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 " 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()); QTC_CHECK(!m_timer.isValid());
m_timer.start(); m_timer.start();
} }
@@ -1012,7 +1015,7 @@ public:
if (--m_subtasks > 0) // See startSubtask(). if (--m_subtasks > 0) // See startSubtask().
return; return;
qCDebug(clangdLogTiming).noquote().nospace() << m_task << ": subtask stopped at " 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()); QTC_CHECK(m_timer.isValid());
m_elapsedMs += m_timer.elapsed(); m_elapsedMs += m_timer.elapsed();
m_timer.invalidate(); m_timer.invalidate();
@@ -1020,9 +1023,12 @@ public:
stopTask(); stopTask();
} }
QElapsedTimer startTimer() const { return m_startTimer; }
private: private:
const QString m_task; const QString m_task;
QElapsedTimer m_timer; QElapsedTimer m_timer;
QElapsedTimer m_startTimer;
qint64 m_elapsedMs = 0; qint64 m_elapsedMs = 0;
int m_subtasks = 0; int m_subtasks = 0;
bool m_started = false; bool m_started = false;
@@ -1052,7 +1058,7 @@ public:
class ThreadedSubtaskTimer class ThreadedSubtaskTimer
{ {
public: 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"; qCDebug(clangdLogTiming).noquote().nospace() << m_task << ": starting thread";
m_timer.start(); m_timer.start();
@@ -1062,10 +1068,15 @@ public:
{ {
qCDebug(clangdLogTiming).noquote().nospace() << m_task << ": took " << m_timer.elapsed() qCDebug(clangdLogTiming).noquote().nospace() << m_task << ": took " << m_timer.elapsed()
<< " ms in dedicated thread"; << " ms in dedicated thread";
qCDebug(clangdLogTiming).noquote().nospace() << m_task << ": Start to end: "
<< m_taskTimer.startTimer().elapsed() << " ms";
} }
private: private:
const QString m_task; const QString m_task;
QElapsedTimer m_timer; QElapsedTimer m_timer;
const TaskTimer &m_taskTimer;
}; };
class MemoryTreeModel; class MemoryTreeModel;
@@ -1191,6 +1202,13 @@ public:
: LanguageClientCompletionAssistProcessor(client, snippetsGroup) : LanguageClientCompletionAssistProcessor(client, snippetsGroup)
, m_client(client) , m_client(client)
{ {
m_timer.start();
}
~ClangdCompletionAssistProcessor()
{
qCDebug(clangdLogTiming).noquote().nospace()
<< "ClangdCompletionAssistProcessor took: " << m_timer.elapsed() << " ms";
} }
private: private:
@@ -1208,6 +1226,7 @@ private:
const QList<LanguageServerProtocol::CompletionItem> &items) const override; const QList<LanguageServerProtocol::CompletionItem> &items) const override;
ClangdClient * const m_client; ClangdClient * const m_client;
QElapsedTimer m_timer;
}; };
QList<AssistProposalItemInterface *> QList<AssistProposalItemInterface *>
@@ -2653,9 +2672,10 @@ static void semanticHighlighter(QFutureInterface<HighlightingResult> &future,
const QList<ExpandedSemanticToken> &tokens, const QList<ExpandedSemanticToken> &tokens,
const QString &docContents, const AstNode &ast, const QString &docContents, const AstNode &ast,
const QPointer<TextDocument> &textDocument, 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()) { if (future.isCanceled()) {
future.reportFinished(); future.reportFinished();
return; return;
@@ -2921,9 +2941,10 @@ void ClangdClient::Private::handleSemanticTokens(TextDocument *doc,
const auto runner = [tokens, filePath = doc->filePath(), const auto runner = [tokens, filePath = doc->filePath(),
text = doc->document()->toPlainText(), ast, text = doc->document()->toPlainText(), ast,
doc = QPointer(doc), rev = doc->document()->revision(), doc = QPointer(doc), rev = doc->document()->revision(),
clangdVersion = q->versionNumber()] { clangdVersion = q->versionNumber(),
this] {
return Utils::runAsync(semanticHighlighter, filePath, tokens, text, ast, doc, rev, return Utils::runAsync(semanticHighlighter, filePath, tokens, text, ast, doc, rev,
clangdVersion); clangdVersion, highlightingTimer);
}; };
if (isTesting) { if (isTesting) {