QmlDesigner: Add logging to NodeInstanceView

Change-Id: I95f9f2e089f2d66ba9cf27b631d2478d54b18085
Reviewed-by: Tim Jenssen <tim.jenssen@qt.io>

share/qtcreator/qml/qmlpuppet/interfaces/nodeinstanceserverinterface.h

@@ -78,6 +78,9 @@ public:
     virtual void token(const TokenCommand &command) = 0;
     virtual void removeSharedMemory(const RemoveSharedMemoryCommand &command) = 0;
 
+    virtual void benchmark(const QString &)
+    {}
+
     static void registerCommands();
 };
 

src/plugins/qmldesigner/designercore/instances/nodeinstanceserverproxy.cpp

@@ -73,6 +73,7 @@
 
 #include <QLocalServer>
 #include <QLocalSocket>
+#include <QLoggingCategory>
 #include <QProcess>
 #include <QCoreApplication>
 #include <QUuid>
@@ -84,6 +85,8 @@
 
 namespace QmlDesigner {
 
+static Q_LOGGING_CATEGORY(instanceViewBenchmark, "qtc.nodeinstances.init")
+
 void NodeInstanceServerProxy::showCannotConnectToPuppetWarningAndSwitchToEditMode()
 {
 #ifndef QMLDESIGNER_TEST
@@ -114,6 +117,9 @@ NodeInstanceServerProxy::NodeInstanceServerProxy(NodeInstanceView *nodeInstanceV
       m_runModus(runModus),
       m_synchronizeId(-1)
 {
+    if (instanceViewBenchmark().isInfoEnabled())
+        m_benchmarkTimer.start();
+
    QString socketToken(QUuid::createUuid().toString());
    m_localServer->listen(socketToken);
    m_localServer->setMaxPendingConnections(3);
@@ -147,6 +153,7 @@ NodeInstanceServerProxy::NodeInstanceServerProxy(NodeInstanceView *nodeInstanceV
    if (m_qmlPuppetEditorProcess->waitForStarted(waitConstant)) {
        connect(m_qmlPuppetEditorProcess.data(), static_cast<void (QProcess::*)(int, QProcess::ExitStatus)>(&QProcess::finished),
             m_qmlPuppetEditorProcess.data(), &QProcess::deleteLater);
+    qCInfo(instanceViewBenchmark) << "puppets started:" << m_benchmarkTimer.elapsed();
 
        if (runModus == NormalModus) {
            m_qmlPuppetPreviewProcess->waitForStarted(waitConstant / 2);
@@ -178,6 +185,7 @@ NodeInstanceServerProxy::NodeInstanceServerProxy(NodeInstanceView *nodeInstanceV
                    if (!m_localServer->hasPendingConnections())
                         connectedToPuppet = m_localServer->waitForNewConnection(waitConstant / 4);
 
+    qCInfo(instanceViewBenchmark) << "puppets connected:" << m_benchmarkTimer.elapsed();
                    if (connectedToPuppet) {
                        m_thirdSocket = m_localServer->nextPendingConnection();
                        connect(m_thirdSocket.data(), SIGNAL(readyRead()), this, SLOT(readThirdDataStream()));
@@ -272,6 +280,7 @@ void NodeInstanceServerProxy::dispatchCommand(const QVariant &command, PuppetStr
     static const int debugOutputCommandType = QMetaType::type("DebugOutputCommand");
     static const int puppetAliveCommandType = QMetaType::type("PuppetAliveCommand");
 
+    qCInfo(instanceViewBenchmark) << "dispatching command" << command.userType() << command.typeName();
     if (command.userType() ==  informationChangedCommandType) {
         nodeInstanceClient()->informationChanged(command.value<InformationChangedCommand>());
     } else if (command.userType() ==  valuesChangedCommandType) {
@@ -295,6 +304,7 @@ void NodeInstanceServerProxy::dispatchCommand(const QVariant &command, PuppetStr
         m_synchronizeId = synchronizeCommand.synchronizeId();
     }  else
         Q_ASSERT(false);
+     qCInfo(instanceViewBenchmark) << "dispatching command" << "done" << command.userType();
 }
 
 NodeInstanceClientInterface *NodeInstanceServerProxy::nodeInstanceClient() const
@@ -588,6 +598,7 @@ void NodeInstanceServerProxy::changeFileUrl(const ChangeFileUrlCommand &command)
 
 void NodeInstanceServerProxy::createScene(const CreateSceneCommand &command)
 {
+    qCInfo(instanceViewBenchmark) << Q_FUNC_INFO << m_benchmarkTimer.elapsed();
     writeCommand(QVariant::fromValue(command));
 }
 
@@ -656,4 +667,9 @@ void NodeInstanceServerProxy::removeSharedMemory(const RemoveSharedMemoryCommand
    writeCommand(QVariant::fromValue(command));
 }
 
+void NodeInstanceServerProxy::benchmark(const QString &message)
+{
+    qCInfo(instanceViewBenchmark) << message << m_benchmarkTimer.elapsed();
+}
+
 } // namespace QmlDesigner

src/plugins/qmldesigner/designercore/instances/nodeinstanceserverproxy.h

@@ -30,6 +30,7 @@
 #include <QPointer>
 #include <QProcess>
 #include <QFile>
+#include <QTime>
 #include <QTimer>
 
 QT_BEGIN_NAMESPACE
@@ -81,6 +82,7 @@ public:
     void changeNodeSource(const ChangeNodeSourceCommand &command);
     void token(const TokenCommand &command);
     void removeSharedMemory(const RemoveSharedMemoryCommand &command);
+    void benchmark(const QString &message) override;
 
 protected:
     void writeCommand(const QVariant &command);
@@ -125,6 +127,7 @@ private:
     quint32 m_thirdLastReadCommandCounter;
     RunModus m_runModus;
     int m_synchronizeId;
+    QTime m_benchmarkTimer;
 };
 
 } // namespace QmlDesigner

src/plugins/qmldesigner/designercore/instances/nodeinstanceview.cpp

@@ -1129,6 +1129,8 @@ void NodeInstanceView::pixmapChanged(const PixmapChangedCommand &command)
         }
     }
 
+    m_nodeInstanceServer->benchmark(Q_FUNC_INFO + QString::number(renderImageChangeSet.count()));
+
     if (!renderImageChangeSet.isEmpty())
         emitInstancesRenderImageChanged(renderImageChangeSet.toList().toVector());
 }
@@ -1158,6 +1160,8 @@ void NodeInstanceView::informationChanged(const InformationChangedCommand &comma
 
     QMultiHash<ModelNode, InformationName> informationChangeHash = informationChanged(command.informations());
 
+    m_nodeInstanceServer->benchmark(Q_FUNC_INFO + QString::number(informationChangeHash.count()));
+
     if (!informationChangeHash.isEmpty())
         emitInstanceInformationsChange(informationChangeHash);
 }
@@ -1222,6 +1226,8 @@ void NodeInstanceView::componentCompleted(const ComponentCompletedCommand &comma
             nodeVector.append(modelNodeForInternalId(instanceId));
     }
 
+    m_nodeInstanceServer->benchmark(Q_FUNC_INFO + QString::number(nodeVector.count()));
+
     if (!nodeVector.isEmpty())
         emitInstancesCompleted(nodeVector);
 }