feedc0de/qt-creator
1
0
Fork 0
forked from qt-creator/qt-creator
Code Pull Requests Activity

Measure the time spent on starting and waiting for start

Browse Source 
Measure it on demand. The printout will appear when
QTC_MEASURE_PROCESS env variable is set. It may be easily
combined with QTC_USE_QPROCESS to compare the time spent
on freezing Creator when starting Creator or when loading
a big project, like Creator project.

In order to compare the measurement between
old implementation (using directly QProcess) and
new implementation (using process launcher) of QtcProcess
do the following (linux):

1. To measure the new implementation:
QTC_MEASURE_PROCESS= ./bin/qtcreator

2. To measure the old implementation:
QTC_USE_QPROCESS= QTC_MEASURE_PROCESS= ./bin/qtcreator

How to measure (two scenarios, A and B):

A. Launch Creator (don't load any project), wait a bit
   until all processes finished. Look for the last value
   in the 11th column ([A/M] Total Measurement, A means
   all measured functions, M means in main thread only).
   This value has the greatest influence on GUI freeze -
   the higher it is, the longer the GUI is frozen.
   Measure it with 1. (new) and 2. (old) implementation
   and share your results.

B. Launch Creator and load a Creator project.
   Wait until all processes finished (taskbar should be empty).
   Look for the last value in the 11th column.
   Measure it with 1. (new) and 2. (old) implementation
   and share your results.

C* (Additional one)
   If only you notice that launching a certain QtcProcess takes
   suspiciously too long, replay your scenario that triggers
   this process with 1. and 2. and share your results of
   the 11th column.

Change-Id: I549c0a9fd0b3d6223f3d27288130553d99ab768e
Reviewed-by: David Schulz <david.schulz@qt.io>
Reviewed-by: hjk <hjk@qt.io>
This commit is contained in:
Jarek Kobus
2021-08-19 23:04:39 +02:00
parent 37254cb92c
commit cc940d52be
1 changed files with 120 additions and 3 deletions
Download Patch File Download Diff File Expand all files Collapse all files

123
src/libs/utils/qtcprocess.cpp
View File

@@ -38,6 +38,7 @@
#include <QDebug>
#include <QDir>
#include <QLoggingCategory>
#include <QScopeGuard>
#include <QTextCodec>
#include <QThread>
#include <QTimer>
@@ -49,7 +50,9 @@
#endif
#include <algorithm>
#include <limits.h>
#include <atomic>
#include <functional>
#include <limits>
#include <memory>
#ifdef Q_OS_WIN
@@ -64,6 +67,120 @@ using namespace Utils::Internal;
namespace Utils {
namespace Internal {
class MeasureAndRun
{
public:
MeasureAndRun(const char *functionName)
: m_functionName(functionName)
, m_measureProcess(qEnvironmentVariableIsSet("QTC_MEASURE_PROCESS"))
{}
template <typename Function, typename... Args>
std::invoke_result_t<Function, Args...> measureAndRun(Function &&function, Args&&... args)
{
if (!m_measureProcess)
return std::invoke(std::forward<Function>(function), std::forward<Args>(args)...);
QElapsedTimer timer;
timer.start();
auto cleanup = qScopeGuard([this, &timer] {
const qint64 currentNsecs = timer.nsecsElapsed();
const bool isMainThread = QThread::currentThread() == qApp->thread();
const int hitThisAll = m_hitThisAll.fetch_add(1) + 1;
const int hitAllAll = m_hitAllAll.fetch_add(1) + 1;
const int hitThisMain = isMainThread
? m_hitThisMain.fetch_add(1) + 1
: m_hitThisMain.load();
const int hitAllMain = isMainThread
? m_hitAllMain.fetch_add(1) + 1
: m_hitAllMain.load();
const qint64 totalThisAll = toMs(m_totalThisAll.fetch_add(currentNsecs) + currentNsecs);
const qint64 totalAllAll = toMs(m_totalAllAll.fetch_add(currentNsecs) + currentNsecs);
const qint64 totalThisMain = toMs(isMainThread
? m_totalThisMain.fetch_add(currentNsecs) + currentNsecs
: m_totalThisMain.load());
const qint64 totalAllMain = toMs(isMainThread
? m_totalAllMain.fetch_add(currentNsecs) + currentNsecs
: m_totalAllMain.load());
printMeasurement(QLatin1String(m_functionName), hitThisAll, toMs(currentNsecs),
totalThisAll, hitAllAll, totalAllAll, isMainThread,
hitThisMain, totalThisMain, hitAllMain, totalAllMain);
});
return std::invoke(std::forward<Function>(function), std::forward<Args>(args)...);
}
private:
static void printHeader()
{
// [function/thread]: function:(T)his|(A)ll, thread:(M)ain|(A)ll
qDebug() << "+----------------+-------+---------+----------+-------+----------+---------+-------+----------+-------+----------+";
qDebug() << "| [Function/Thread] = [(T|A)/(M|A)], where: (T)his function, (A)ll functions / threads, (M)ain thread |";
qDebug() << "+----------------+-------+---------+----------+-------+----------+---------+-------+----------+-------+----------+";
qDebug() << "| 1 | 2 | 3 | 4 | 5 | 6 | 7 | 8 | 9 | 10 | 11 |";
qDebug() << "| | [T/A] | [T/A] | [T/A] | [A/A] | [A/A] | | [T/M] | [T/M] | [A/M] | [A/M] |";
qDebug() << "| Function | Hit | Current | Total | Hit | Total | Current | Hit | Total | Hit | Total |";
qDebug() << "| Name | Count | Measu- | Measu- | Count | Measu- | is Main | Count | Measu- | Count | Measu- |";
qDebug() << "| | | rement | rement | | rement | Thread | | rement | | rement |";
qDebug() << "+----------------+-------+---------+----------+-------+----------+---------+-------+----------+-------+----------+";
}
static void printMeasurement(const QString &functionName, int hitThisAll, int currentNsecs,
int totalThisAll, int hitAllAll, int totalAllAll, bool isMainThread,
int hitThisMain, int totalThisMain, int hitAllMain, int totalAllMain)
{
static const int repeatHeaderLineCount = 25;
if (s_lineCounter.fetch_add(1) % repeatHeaderLineCount == 0)
printHeader();
const QString &functionNameField = QString("%1").arg(functionName, 14);
const QString &hitThisAllField = formatField(hitThisAll, 5);
const QString &currentNsecsField = formatField(currentNsecs, 7, " ms");
const QString &totalThisAllField = formatField(totalThisAll, 8, " ms");
const QString &hitAllAllField = formatField(hitAllAll, 5);
const QString &totalAllAllField = formatField(totalAllAll, 8, " ms");
const QString &mainThreadField = isMainThread ? QString("%1").arg("yes", 7)
: QString("%1").arg("no", 7);
const QString &hitThisMainField = formatField(hitThisMain, 5);
const QString &totalThisMainField = formatField(totalThisMain, 8, " ms");
const QString &hitAllMainField = formatField(hitAllMain, 5);
const QString &totalAllMainField = formatField(totalAllMain, 8, " ms");
const QString &totalString = QString("| %1 | %2 | %3 | %4 | %5 | %6 | %7 | %8 | %9 | %10 | %11 |")
.arg(functionNameField, hitThisAllField, currentNsecsField,
totalThisAllField, hitAllAllField, totalAllAllField, mainThreadField,
hitThisMainField, totalThisMainField, hitAllMainField, totalAllMainField);
qDebug("%s", qPrintable(totalString));
}
static QString formatField(int number, int fieldWidth, const QString &suffix = QString())
{
return QString("%1%2").arg(number, fieldWidth - suffix.count()).arg(suffix);
}
static int toMs(quint64 nsesc) // nanoseconds to miliseconds
{
static const int halfMillion = 500000;
static const int million = 2 * halfMillion;
return int((nsesc + halfMillion) / million);
}
const bool m_measureProcess;
const char *m_functionName;
std::atomic_int m_hitThisAll = 0;
std::atomic_int m_hitThisMain = 0;
std::atomic_int64_t m_totalThisAll = 0;
std::atomic_int64_t m_totalThisMain = 0;
static std::atomic_int m_hitAllAll;
static std::atomic_int m_hitAllMain;
static std::atomic_int64_t m_totalAllAll;
static std::atomic_int64_t m_totalAllMain;
static std::atomic_int s_lineCounter;
};
std::atomic_int MeasureAndRun::m_hitAllAll = 0;
std::atomic_int MeasureAndRun::m_hitAllMain = 0;
std::atomic_int64_t MeasureAndRun::m_totalAllAll = 0;
std::atomic_int64_t MeasureAndRun::m_totalAllMain = 0;
std::atomic_int MeasureAndRun::s_lineCounter = 0;
static MeasureAndRun s_start = MeasureAndRun("start");
static MeasureAndRun s_waitForStarted = MeasureAndRun("waitForStarted");
enum { debug = 0 };
enum { syncDebug = 0 };
@@ -389,7 +506,7 @@ public:
{
const FilePath programFilePath = resolve(m_workingDirectory, FilePath::fromString(program));
if (programFilePath.exists() && programFilePath.isExecutableFile()) {
m_process->start(programFilePath.toString(), arguments, writeData);
s_start.measureAndRun(&ProcessInterface::start, m_process, program, arguments, writeData);
} else {
m_process->setErrorString(QLatin1String(
"The program \"%1\" does not exist or is not executable.").arg(program));
@@ -927,7 +1044,7 @@ qint64 QtcProcess::processId() const
bool QtcProcess::waitForStarted(int msecs)
{
return d->m_process->waitForStarted(msecs);
return s_waitForStarted.measureAndRun(&ProcessInterface::waitForStarted, d->m_process, msecs);
}
bool QtcProcess::waitForReadyRead(int msecs)