Log project load times, split by phase

Requested in #553 to compare Qt5 and Qt6 builds. QET already reports how
long the elements collection takes to load (ElementsCollectionWidget::
reload); this adds the equivalent for opening a project.

The phases are reported separately rather than as a single total. Reading
the XML and building the objects is mostly independent of the Qt version,
whereas refreshing the diagrams is graphics-scene work -- a single number
would mix the two and could suggest a Qt version makes no difference when
the part that changed is simply not where the time goes. Measured on the
example projects, XML parsing is 3-7% of the total and diagram
construction 77-83%, so the distinction matters in practice.

QETProject::openFile() reports the total with the parse/build split, and
readProjectXml() reports the build phases:

  Project content built in 1.391 seconds (elements collection 0.009,
    diagrams 1.153, terminal strips 0, refresh 0.196, database 0.033)
  Project "example.qet" (3399 KiB) opened in 1.505 seconds
    (xml parsing 0.11, content 1.395)

Logged with qInfo(), matching the existing collection timer, so it lands
in the normal log without a debug build.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
This commit is contained in:
ispyisail
2026-07-27 17:37:49 +12:00
parent e9a53dbec2
commit 9e070f9bce
+37 -1
View File
@@ -35,6 +35,7 @@
#include "qetxml.h"
#include "qetversion.h"
#include <QElapsedTimer>
#include <QHash>
#include <QTimer>
#include <QtConcurrentRun>
@@ -227,6 +228,9 @@ void QETProject::init()
*/
QETProject::ProjectState QETProject::openFile(QFile *file)
{
QElapsedTimer load_timer;
load_timer.start();
bool opened_here = file->isOpen() ? false : true;
if (!file->isOpen()
&& !file->open(QIODevice::ReadOnly
@@ -245,10 +249,19 @@ QETProject::ProjectState QETProject::openFile(QFile *file)
}
return XmlParsingFailed;
}
const qint64 xml_parse_ms = load_timer.elapsed();
//Build the project from the xml
readProjectXml(xml_project);
const qint64 total_ms = load_timer.elapsed();
qInfo().nospace().noquote()
<< "Project \"" << fi.fileName() << "\" ("
<< fi.size() / 1024 << " KiB) opened in "
<< total_ms / 1000.0 << " seconds (xml parsing "
<< xml_parse_ms / 1000.0 << ", content "
<< (total_ms - xml_parse_ms) / 1000.0 << ")";
if (!fi.isWritable()) {
setReadOnly(true);
}
@@ -1489,21 +1502,44 @@ void QETProject::readProjectXml(QDomDocument &xml_project)
//load the embedded titleblock templates
m_titleblocks_collection.fromXml(xml_project.documentElement());
/* Timings of the phases below are logged so the cost of opening a
* project can be attributed. Reading the XML and building the objects
* is mostly independent of the Qt version, while refreshing the
* diagrams is graphics-scene work -- keeping them apart is what makes
* the numbers comparable between builds.
*/
QElapsedTimer phase_timer;
phase_timer.start();
//Load the embedded elements collection
readElementsCollectionXml(xml_project);
const qint64 elements_ms = phase_timer.restart();
//Load the diagrams
readDiagramsXml(xml_project);
const qint64 diagrams_ms = phase_timer.restart();
//Load the terminal strip
readTerminalStripXml(xml_project);
const qint64 strips_ms = phase_timer.restart();
//Now that all are loaded we refresh content of the project.
refresh();
const qint64 refresh_ms = phase_timer.restart();
m_data_base.blockSignals(false);
m_data_base.updateDB();
const qint64 database_ms = phase_timer.elapsed();
qInfo().nospace()
<< "Project content built in "
<< (elements_ms + diagrams_ms + strips_ms
+ refresh_ms + database_ms) / 1000.0
<< " seconds (elements collection " << elements_ms / 1000.0
<< ", diagrams " << diagrams_ms / 1000.0
<< ", terminal strips " << strips_ms / 1000.0
<< ", refresh " << refresh_ms / 1000.0
<< ", database " << database_ms / 1000.0 << ")";
m_state = Ok;
}