mobile: add timer to measure startup.

Subsurface-mobile has a long startup time; in order to isolate the problem(s) a
timer is added to see where time is "lost".

The collected startup times are added to the clipboard together with the other
logs, allowing test users to report back.

All this is only enabled when compiling with -DENABLE_STARTUP_TIMING

Closes #1340

[Dirk Hohndel: collapsed multiple commits and minor white space cleanups, added
               missing QMutex variable]

Signed-off-by: Jan Iversen <jani@apache.org>
Signed-off-by: Dirk Hohndel <dirk@hohndel.org>

core/ssrf.h

@@ -12,6 +12,21 @@ extern "C" {
 #endif
 
 #ifdef __cplusplus
+
+#ifdef SUBSURFACE_MOBILE
+#ifdef ENABLE_STARTUP_TIMING
+// Declare generic function, will be seen only in CPP code
+// Use void parameters to avoid extra includes
+extern void log_stp(const char *ident, QString *buf);
+
+#define LOG_STP(x) log_stp(x, NULL)
+#define LOG_STP_CLIPBOARD(x) log_stp(NULL, x)
+#else
+#define LOG_STP(x)
+#define LOG_STP_CLIPBOARD(x)
+#endif // ENABLE_STARTUP_TIMING
+#endif // SUBSURFACE_MOBILE
+
 }
 #else
 

mobile-widgets/qmlmanager.cpp

@@ -32,6 +32,8 @@
 #include "qt-models/tankinfomodel.h"
 #include "core/downloadfromdcthread.h"
 
+#include "core/ssrf.h"
+
 QMLManager *QMLManager::m_instance = NULL;
 
 #define RED_FONT QLatin1Literal("<font color=\"red\">")
@@ -138,6 +140,7 @@ QMLManager::QMLManager() : m_locationServiceEnabled(false),
 	alreadySaving(false),
 	m_device_data(new DCDeviceData(this))
 {
+	LOG_STP("qmlmgr starting");
 	m_instance = this;
 	m_lastDevicePixelRatio = qApp->devicePixelRatio();
 	timer.start();
@@ -164,6 +167,7 @@ QMLManager::QMLManager() : m_locationServiceEnabled(false),
 				+ " at " + QDateTime::currentDateTime().toString());
 	}
 #endif
+	LOG_STP("qmlmgr log started");
 	set_error_cb(&showErrorFromC);
 	appendTextToLog("Starting " + getUserAgent());
 	appendTextToLog(QStringLiteral("built with libdivecomputer v%1").arg(dc_version(NULL)));
@@ -172,11 +176,13 @@ QMLManager::QMLManager() : m_locationServiceEnabled(false),
 	git_libgit2_version(&git_maj, &git_min, &git_rev);
 	appendTextToLog(QStringLiteral("built with libgit2 %1.%2.%3").arg(git_maj).arg(git_min).arg(git_rev));
 	setStartPageText(tr("Starting..."));
+	LOG_STP("qmlmgr start page");
 
 	// ensure that we start the BTDiscovery - this should be triggered by the export of the class
 	// to QML, but that doesn't seem to always work
 	BTDiscovery *btDiscovery = BTDiscovery::instance();
 	m_btEnabled = btDiscovery->btAvailable();
+	LOG_STP("qmlmgr bt available");
 	connect(&btDiscovery->localBtDevice, &QBluetoothLocalDevice::hostModeStateChanged,
 		this, &QMLManager::btHostModeChange);
 	setShowPin(false);
@@ -185,10 +191,13 @@ QMLManager::QMLManager() : m_locationServiceEnabled(false),
 	progress_callback = &progressCallback;
 	connect(locationProvider, SIGNAL(haveSourceChanged()), this, SLOT(hasLocationSourceChanged()));
 	setLocationServiceAvailable(locationProvider->hasLocationsSource());
+	LOG_STP("qmlmgr gps started");
 	set_git_update_cb(&gitProgressCB);
+	LOG_STP("qmlmgr git update");
 
 	// make sure we know if the current cloud repo has been successfully synced
 	syncLoadFromCloud();
+	LOG_STP("qmlmgr sync load cloud");
 }
 
 void QMLManager::applicationStateChanged(Qt::ApplicationState state)
@@ -352,6 +361,7 @@ void QMLManager::copyAppLogToClipboard()
 		QTextStream in(&f);
 		copyString += in.readAll();
 	}
+	LOG_STP_CLIPBOARD(&copyString);
 	copyString += "---------- finish ----------\n";
 
 	// and copy to clipboard

subsurface-mobile-helper.cpp

@@ -29,6 +29,8 @@
 
 #include "mobile-widgets/qml/kirigami/src/kirigamiplugin.h"
 
+#include "core/ssrf.h"
+
 QObject *qqWindowObject = NULL;
 
 void set_non_bt_addresses() {
@@ -51,6 +53,7 @@ void init_ui()
 
 void run_ui()
 {
+	LOG_STP("run_ui starting");
 	qmlRegisterType<QMLManager>("org.subsurfacedivelog.mobile", 1, 0, "QMLManager");
 	qmlRegisterType<QMLProfile>("org.subsurfacedivelog.mobile", 1, 0, "QMLProfile");
 
@@ -63,6 +66,7 @@ void run_ui()
 	qmlRegisterType<MapLocation>("org.subsurfacedivelog.mobile", 1, 0, "MapLocation");
 
 	QQmlApplicationEngine engine;
+	LOG_STP("run_ui qml engine started");
 	KirigamiPlugin::getInstance().registerTypes();
 #if defined(__APPLE__) && !defined(Q_OS_IOS)
 	// when running the QML UI on a Mac the deployment of the QML Components seems
@@ -79,11 +83,13 @@ void run_ui()
 #endif
 	engine.addImportPath("qrc://imports");
 	DiveListModel diveListModel;
+	LOG_STP("run_ui diveListModel started");
 	DiveListSortModel *sortModel = new DiveListSortModel(0);
 	sortModel->setSourceModel(&diveListModel);
 	sortModel->setDynamicSortFilter(true);
 	sortModel->setSortRole(DiveListModel::DiveDateRole);
 	sortModel->sort(0, Qt::DescendingOrder);
+	LOG_STP("run_ui diveListModel sorted");
 	GpsListModel gpsListModel;
 	QSortFilterProxyModel *gpsSortModel = new QSortFilterProxyModel(0);
 	gpsSortModel->setSourceModel(&gpsListModel);
@@ -95,11 +101,13 @@ void run_ui()
 	ctxt->setContextProperty("gpsModel", gpsSortModel);
 	ctxt->setContextProperty("vendorList", vendorList);
 	set_non_bt_addresses();
+	LOG_STP("run_ui set_non_bt_adresses");
 
 	ctxt->setContextProperty("connectionListModel", &connectionListModel);
 	ctxt->setContextProperty("logModel", MessageHandlerModel::self());
 
 	engine.load(QUrl(QStringLiteral("qrc:///qml/main.qml")));
+	LOG_STP("run_ui qml loaded");
 	qqWindowObject = engine.rootObjects().value(0);
 	if (!qqWindowObject) {
 		fprintf(stderr, "can't create window object\n");
@@ -112,8 +120,10 @@ void run_ui()
 	QScreen *screen = qml_window->screen();
 	QObject::connect(qml_window, &QQuickWindow::screenChanged, QMLManager::instance(), &QMLManager::screenChanged);
 	QMLManager *manager = QMLManager::instance();
+	LOG_STP("run_ui qmlmanager instance started");
 	// now that the log file is initialized...
 	show_computer_list();
+	LOG_STP("run_ui show_computer_list");
 
 	manager->setDevicePixelRatio(qml_window->devicePixelRatio(), qml_window->screen());
 	manager->dlSortModel = sortModel;
@@ -124,6 +134,7 @@ void run_ui()
 	qml_window->setWidth(800);
 #endif
 	qml_window->show();
+	LOG_STP("run_ui running exec");
 	qApp->exec();
 }
 

subsurface-mobile-main.cpp

@@ -19,14 +19,50 @@
 #include <QLocale>
 #include <git2.h>
 
+// Implementation of STP logging
+#include "core/ssrf.h"
+#ifdef ENABLE_STARTUP_TIMING
+#include <QElapsedTimer>
+#include <QMutex>
+#include <QMutexLocker>
+void log_stp(const char *ident, QString *buf)
+{
+	static bool firstCall = true;
+	static QElapsedTimer stpDuration;
+	static QString stpText;
+	static QMutex logMutex;
+
+	QMutexLocker l(&logMutex);
+
+	if (firstCall) {
+		firstCall = false;
+		stpDuration.start();
+	}
+	if (ident)
+		stpText += QString("STP ") \
+					.append(QString::number(stpDuration.elapsed())) \
+					.append(" ms, ") \
+					.append(ident) \
+					.append("\n");
+	if (buf) {
+		*buf += "---------- startup timer ----------\n";
+		*buf += stpText;
+	}
+}
+#endif // ENABLE_STARTUP_TIMING
+
+
 int main(int argc, char **argv)
 {
+	LOG_STP("main starting");
+
 	int i;
 	QGuiApplication::setAttribute(Qt::AA_EnableHighDpiScaling);
 	QLoggingCategory::setFilterRules(QStringLiteral("qt.bluetooth* = true"));
 
 	// Start application
 	new QApplication(argc, argv);
+	LOG_STP("main Qt started");
 
 	// and get comand line arguments
 	QStringList arguments = QCoreApplication::arguments();
@@ -41,6 +77,7 @@ int main(int argc, char **argv)
 		}
 	}
 	git_libgit2_init();
+	LOG_STP("main git loaded");
 	setup_system_prefs();
 	if (QLocale().measurementSystem() == QLocale::MetricSystem)
 		default_prefs.units = SI_units;
@@ -51,8 +88,11 @@ int main(int argc, char **argv)
 	fill_computer_list();
 
 	parse_xml_init();
+	LOG_STP("main xml parsed");
 	taglist_init_global();
+	LOG_STP("main taglist done");
 	init_ui();
+	LOG_STP("main init_ui done");
 	if (prefs.default_file_behavior == LOCAL_DEFAULT_FILE)
 		set_filename(prefs.default_filename);
 	else
@@ -66,6 +106,7 @@ int main(int argc, char **argv)
 
 	init_proxy();
 
+	LOG_STP("main call run_ui (continue in qmlmanager)");
 	if (!quit)
 		run_ui();
 	exit_ui();