Show elapsed time during queries and show execute and plan time above query explain.

mainwindow.cpp

@@ -9,9 +9,61 @@
 #include <windows.h>
 #include "json/json.h"
 #include "explaintreemodelitem.h"
+#include <algorithm>
 
 //#include <thread>
 
+namespace {
+
+	// Supported range from microseconds to seconds
+	// min:sec to hours::min::sec
+	QString msfloatToHumanReadableString(float ms)
+	{
+		QString unit;
+		float val;
+		int deci = 3;
+		if (ms < 1.0f) {
+			val = ms * 1000.f;
+			//result = QString::asprintf("%0.3f", ms * 1000.0f);
+			unit = u8"μs";
+		}
+		else if (ms >= 1000.0) {
+			val = ms / 1000.0f;
+			unit = "s";
+			if (val >= 60.0) {
+				int secs = val;
+				int min = secs / 60.0;
+				secs -= min * 60;
+				if (min >= 60) {
+					int hour = min / 60;
+					min -= hour * 60;
+					return QString::asprintf("%d:%02d:%02d", hour, min, secs);
+				}
+				else {
+					return QString::asprintf("%02d:%02d", min, secs);
+				}
+			}
+		}
+		else {
+			val = ms;
+			unit = "ms";
+		}
+
+		if (val >= 1000.f) {
+			deci = 0;
+		}
+		else if (val >= 100.f) {
+			deci = 1;
+		}
+		else if (val >= 10.f) {
+			deci = 2;
+		}
+		QString result = QString::asprintf("%0.*f", deci, val);
+		return result + unit;
+	}
+
+}
+
 namespace pg = Pgsql;
 
 const char * test_query =
@@ -63,6 +115,9 @@ MainWindow::MainWindow(QWidget *parent)
 		{
 			QueueTask([this, details]() { receiveNotice(details); });
 		});
+
+	m_timeElapsedLabel = new QLabel(this);
+	statusBar()->addPermanentWidget(m_timeElapsedLabel);
 }
 
 MainWindow::~MainWindow()
@@ -111,6 +166,7 @@ void MainWindow::connectionStateChanged(ASyncDBConnection::State state)
 		status_str = tr("Query geannuleerd");
 		break;
 	}
+	addLog(status_str);
 	statusBar()->showMessage(status_str);
 }
 
@@ -122,12 +178,15 @@ void MainWindow::startConnect()
 
 void MainWindow::performQuery()
 {
+	addLog("Query clicked");
+
 	ui->ResultView->setModel(nullptr);
 	resultModel.reset();
 	ui->messagesEdit->clear();
 
 	QString command = ui->queryEdit->toPlainText();
 	std::string cmd = command.toUtf8().data();
+	startTimer();
 	m_dbConnection.send(cmd,
 		[this](std::shared_ptr<Pgsql::Result> res)
 		{
@@ -137,7 +196,9 @@ void MainWindow::performQuery()
 
 void MainWindow::query_ready(std::shared_ptr<Pgsql::Result> dbres)
 {
+	endTimer();
 	if (dbres) {
+		addLog("query_ready with result");
 		auto st = dbres->resultStatus();
 		if (st == PGRES_TUPLES_OK) {
 			resultModel.reset(new QueryResultModel(nullptr , dbres));
@@ -179,16 +240,20 @@ void MainWindow::query_ready(std::shared_ptr<Pgsql::Result> dbres)
 		}
 	}
 	else {
+		addLog("query_ready with NO result");
 		statusBar()->showMessage(tr("Query cancelled."));
 	}
 }
 
 void MainWindow::performExplain()
 {
-	ui->ResultView->setModel(nullptr);
-	resultModel.reset();
+	ui->explainTreeView->setModel(nullptr);
+	explainModel.reset();
 	ui->messagesEdit->clear();
 
+	addLog("Explain clicked");
+
+	startTimer();
 	QString command = "EXPLAIN (ANALYZE, VERBOSE, BUFFERS, FORMAT JSON) ";
 	command += ui->queryEdit->toPlainText();
 	std::string cmd = command.toUtf8().data();
@@ -217,7 +282,14 @@ void MainWindow::performExplain()
 
 void MainWindow::explain_ready(ExplainRoot::SPtr explain)
 {
+	endTimer();
 	if (explain) {
+		addLog("Explain ready");
+		QString times_str = QString("Execution time: %1, Planning time: %2")
+						.arg(
+					msfloatToHumanReadableString(explain->executionTime)
+					, msfloatToHumanReadableString(explain->planningTime));
+		ui->lblTimes->setText(times_str);
 		explainModel.reset(new QueryExplainModel(nullptr, explain));
 		ui->explainTreeView->setModel(explainModel.get());
 		ui->explainTreeView->expandAll();
@@ -231,6 +303,7 @@ void MainWindow::explain_ready(ExplainRoot::SPtr explain)
 		statusBar()->showMessage(tr("Explain ready."));
 	}
 	else {
+		addLog("Explain no result");
 		statusBar()->showMessage(tr("Explain failed."));
 	}
 }
@@ -259,3 +332,41 @@ void MainWindow::receiveNotice(Pgsql::ErrorDetails notice)
 		table->cellAt(3, 1).firstCursorPosition().insertText(QString::fromStdString(notice.messageDetail));
 	}
 }
+
+void MainWindow::addLog(QString s)
+{
+	QTextCursor text_cursor = QTextCursor(ui->edtLog->document());
+	text_cursor.movePosition(QTextCursor::End);
+	text_cursor.insertText(s + "\r\n");
+}
+
+void MainWindow::startTimer()
+{
+	m_startTime = std::chrono::steady_clock::now();
+	m_timer = std::make_unique<QTimer>(nullptr);
+	m_timer->setTimerType(Qt::CoarseTimer);
+	connect(m_timer.get(), SIGNAL(timeout()), this, SLOT(updateTimer()));
+	m_timer->start(18);
+}
+
+void MainWindow::updateTimer()
+{
+	auto nu = std::chrono::steady_clock::now();
+	std::chrono::duration<float, std::milli> diff = nu - m_startTime;
+	m_timeElapsedLabel->setText(msfloatToHumanReadableString(diff.count()));
+
+	if (m_timer) {
+		int interval = int(diff.count()) / 25;
+		interval = std::max(interval, 18);
+		interval = std::min(interval, 1000);
+		m_timer->start(interval);
+	}
+}
+
+void MainWindow::endTimer()
+{
+	if (m_timer) {
+		m_timer.reset();
+		updateTimer();
+	}
+}