qmlimportscanner: Add logging to help with debugging performance

Add two new logging categories:
 qt.qml.import.scanner
 qt.qml.import.scanner.files

The first one logs how many files are scanned, which files are scanned
timestamps for operations done on each file, durations for the operations
that we expect to take longer.

The second category logs each qml file that is processed recursively
(so not only the input files). Because the output is quite verbose,
it's a separate category rather than being part of the first one.

This is useful to identify performance bottlenecks in projects, without
having to profile the executable.

Task-number: QTBUG-103187
Change-Id: I09506b488dda594b371d229e5fd535a534fe9515
Reviewed-by: Fabian Kosmale <fabian.kosmale@qt.io>
Reviewed-by: Ulf Hermann <ulf.hermann@qt.io>
Reviewed-by: Qt CI Bot <qt_ci_bot@qt-project.org>
(cherry picked from commit 0d826d745bd260b90a22e2d6cbba6af0d0de284c)

1 files changed, 40 insertions, 3 deletions

diff --git a/tools/qmlimportscanner/main.cpp b/tools/qmlimportscanner/main.cpp
index 3b051f7127..3944040d73 100644
--- a/tools/qmlimportscanner/main.cpp
+++ b/tools/qmlimportscanner/main.cpp
@@ -34,6 +34,8 @@
 #include <private/qqmljsresourcefilemapper_p.h>
 
 #include <QtCore/QCoreApplication>
+#include <QtCore/QDebug>
+#include <QtCore/QDateTime>
 #include <QtCore/QDir>
 #include <QtCore/QDirIterator>
 #include <QtCore/QFile>
@@ -47,12 +49,16 @@
 #include <QtCore/QJsonArray>
 #include <QtCore/QJsonDocument>
 #include <QtCore/QLibraryInfo>
+#include <QtCore/QLoggingCategory>
 
 #include <iostream>
 #include <algorithm>
 
 QT_USE_NAMESPACE
 
+Q_LOGGING_CATEGORY(lcImportScanner, "qt.qml.import.scanner");
+Q_LOGGING_CATEGORY(lcImportScannerFiles, "qt.qml.import.scanner.files");
+
 namespace {
 
 QStringList g_qmlImportPaths;
@@ -369,6 +375,9 @@ QVariantList findPathsForModuleImports(const QVariantList &imports)
 // Scan a single qml file for import statements
 QVariantList findQmlImportsInQmlCode(const QString &filePath, const QString &code)
 {
+    qCDebug(lcImportScannerFiles) << "Parsing code and finding imports in" << filePath
+                                  << "TS:" << QDateTime::currentMSecsSinceEpoch();
+
     QQmlJS::Engine engine;
     QQmlJS::Lexer lexer(&engine);
     lexer.setCode(code, /*line = */ 1);
@@ -467,6 +476,7 @@ QVariantList findQmlImportsInJavascriptFile(const QString &filePath)
 // Scan a single qml or js file for import statements
 QVariantList findQmlImportsInFile(const QString &filePath)
 {
+    const auto fileProcessTimeBegin = QDateTime::currentDateTime();
     QVariantList imports;
     if (filePath == QLatin1String("-")) {
         QFile f;
@@ -476,9 +486,25 @@ QVariantList findQmlImportsInFile(const QString &filePath)
         imports = findQmlImportsInQmlFile(filePath);
     } else if (filePath.endsWith(QLatin1String(".js"))) {
         imports = findQmlImportsInJavascriptFile(filePath);
+    } else {
+        qCDebug(lcImportScanner) << "Skipping file because it's not a .qml/.js file";
+        return imports;
     }
 
-    return findPathsForModuleImports(imports);
+    const auto pathsTimeBegin = QDateTime::currentDateTime();
+
+    qCDebug(lcImportScanner) << "Finding module paths for imported modules in" << filePath
+                             << "TS:" << pathsTimeBegin.toMSecsSinceEpoch();
+    QVariantList importPaths = findPathsForModuleImports(imports);
+
+    const auto pathsTimeEnd = QDateTime::currentDateTime();
+    const auto duration = pathsTimeBegin.msecsTo(pathsTimeEnd);
+    const auto fileProcessingDuration = fileProcessTimeBegin.msecsTo(pathsTimeEnd);
+    qCDebug(lcImportScanner) << "Found module paths:" << importPaths.count()
+                             << "TS:" << pathsTimeEnd.toMSecsSinceEpoch()
+                             << "Path resolution duration:" << duration << "msecs";
+    qCDebug(lcImportScanner) << "Scan duration:" << fileProcessingDuration << "msecs";
+    return importPaths;
 }
 
 // Merge two lists of imports, discard duplicates.
@@ -545,8 +571,12 @@ QVariantList findQmlImportsInDirectory(const QString &qmlDir)
         }
 
         for (const QFileInfo &x : entries)
-            if (x.isFile())
-                ret = mergeImports(ret, findQmlImportsInFile(x.absoluteFilePath()));
+            if (x.isFile()) {
+                const auto entryAbsolutePath = x.absoluteFilePath();
+                qCDebug(lcImportScanner) << "Scanning file" << entryAbsolutePath
+                                         << "TS:" << QDateTime::currentMSecsSinceEpoch();
+                ret = mergeImports(ret, findQmlImportsInFile(entryAbsolutePath));
+            }
      }
      return ret;
 }
@@ -558,14 +588,21 @@ QVariantList findQmlImportsRecursively(const QStringList &qmlDirs, const QString
 {
     QVariantList ret;
 
+    qCDebug(lcImportScanner) << "Scanning" << qmlDirs.count() << "root directories and"
+                             << scanFiles.count() << "files.";
+
     // Scan all app root qml directories for imports
     for (const QString &qmlDir : qmlDirs) {
+        qCDebug(lcImportScanner) << "Scanning root" << qmlDir
+                                 << "TS:" << QDateTime::currentMSecsSinceEpoch();
         QVariantList imports = findQmlImportsInDirectory(qmlDir);
         ret = mergeImports(ret, imports);
     }
 
     // Scan app qml files for imports
     for (const QString &file : scanFiles) {
+        qCDebug(lcImportScanner) << "Scanning file" << file
+                                 << "TS:" << QDateTime::currentMSecsSinceEpoch();
         QVariantList imports = findQmlImportsInFile(file);
         ret = mergeImports(ret, imports);
     }