Логгер производительности операций

[__Heaven__]

Привет, друзья!
Мне полюбилось измерять скорость дорогих операций и выводить их в QDebug. При таком подходе не нужно прибегать к помощи профайлера и можно достаточно быстро получить приблизительный результат оценки производительности.
В связи с этим появилась необходимость в создании класса, который будет запускать таймер в конструкторе и писать в QDebug информацию о времени своей жизни в деструкторе.
Также мне необходимо было, чтобы класс писал информационные сообщения в начале и конце жизни, о том, какую операцию он замерял и была возможность выводить через него другие отладочные сообщения. Важно ещё было учесть вложенность замеряемых функций, то есть, чтобы замерщик внутри замеряемой функции делал отступы при выводе в QDebug.
Ниже приведён код, который мне удалось реализовать. Спасибо Пантеру за помощь.

PerformanceLogger.h

Код

C++ (Qt)
#pragma once
 
#define PERFORMANCE_LOGGER(message)\
    PerformanceLogger performanceLogger(message);\
    Q_UNUSED(performanceLogger);
 
#include <QElapsedTimer>
#include <QString>
#include <QVariant>
 
class PerformanceLogger
{
    Q_DISABLE_COPY(PerformanceLogger)
public:
    explicit PerformanceLogger(const QString &message);
    ~PerformanceLogger();
 
    QString message() const;
    void setMessage(const QString &message);
 
    static QString spacer();
    static void setSpacer(const QString &spacer);
 
    static size_t instanceCount();
 
    static QString prefix();
    static void setPrefix(const QString &prefix);
 
    PerformanceLogger &operator << (const QString &logMessage);
 
    QString spaceWithPrefix() const;
 
private:
    QElapsedTimer timer_;
    QString message_;
 
    static size_t instanceCount_;
    static QString spacer_;
    static QString prefix_;
};
 
template<class T>
PerformanceLogger &operator << (PerformanceLogger &logger, const T &logMessage){
    return logger << QVariant(logMessage).toString();
}
 

PerformanceLogger.cpp

Код

C++ (Qt)
#include "PerformanceLogger.h"
#include <QtDebug>
 
size_t PerformanceLogger::instanceCount_ = 0;
QString PerformanceLogger::spacer_ = QStringLiteral("  ");
QString PerformanceLogger::prefix_ = QString();
 
PerformanceLogger::PerformanceLogger(const QString &message)
    : timer_{}
    , message_{message}
{
    ++instanceCount_;
 
    qDebug()<< qUtf8Printable(spaceWithPrefix() + message + "...");
    timer_.start();
}
 
PerformanceLogger::~PerformanceLogger()
{
    qDebug() << qUtf8Printable(spaceWithPrefix() + message_) << "done in" << timer_.elapsed() << "ms";
    --instanceCount_;
}
 
QString PerformanceLogger::message() const
{
    return message_;
}
 
void PerformanceLogger::setMessage(const QString &message)
{
    message_ = message;
}
 
QString PerformanceLogger::spacer()
{
    return spacer_;
}
 
void PerformanceLogger::setSpacer(const QString &spacer)
{
    spacer_ = spacer;
}
 
size_t PerformanceLogger::instanceCount()
{
    return instanceCount_;
}
 
QString PerformanceLogger::spaceWithPrefix() const
{
    QString result;
    for (size_t i = 0; i < instanceCount_ - 1; ++i){
        result += spacer_;
    }
    return result + prefix_;
}
 
QString PerformanceLogger::prefix()
{
    return prefix_;
}
 
void PerformanceLogger::setPrefix(const QString &prefix)
{
    prefix_ = prefix;
}
 
PerformanceLogger &PerformanceLogger::operator <<(const QString &logMessage)
{
    qDebug() << qUtf8Printable(spaceWithPrefix() + logMessage);
    return *this;
}
 

Пример использования

Код

C++ (Qt)
#include "PerformanceLogger.h"
 
void setupLogger(){
    PerformanceLogger::setSpacer("==");
    PerformanceLogger::setPrefix(">");
}
 
 
void subSubLongOperation(){
    PerformanceLogger performanceLogger("Calculating subSubLongOperation");
    performanceLogger << "Message inside subSubLongOperation";
    QElapsedTimer timer;
    timer.start();
    while(timer.elapsed() < 1000);
}
 
void subLongOperation(){
    PERFORMANCE_LOGGER("Calculating subLongOperation");
    subSubLongOperation();
    QElapsedTimer timer;
    timer.start();
    while(timer.elapsed() < 1000);
}
 
void longOperation(){
    PERFORMANCE_LOGGER("Calculating LongOperation");
    subLongOperation();
    QElapsedTimer timer;
    timer.start();
    while(timer.elapsed() < 1000);
}
 
int main()
{
    setupLogger();
    PERFORMANCE_LOGGER("Running main function");
    longOperation();
    return 0;
}
 

Вывод:

>Running main function...
==>Calculating LongOperation...
====>Calculating subLongOperation...
======>Calculating subSubLongOperation...
======>Message inside subSubLongOperation
======>Calculating subSubLongOperation done in 1000 ms
====>Calculating subLongOperation done in 2000 ms
==>Calculating LongOperation done in 3000 ms
>Running main function done in 3001 ms

Кому нравится - забирайте . Очень приветствуется конструктивная критика.

[ssoft]

Замечания на вскидку)

1. На сегодняшний день часто в ПО используются параллельные вычисления, где замеры времени выполнения операций также актуальны. К сожаление представленная реализация будет корректно работать только в последовательном коде.

2. Операция работы с текстом ооочень дорогие. Поэтому вместо цикла в spaceWithPrefix() лучше использовать QString::fill.

3. qDebug() внутри использует работу с QString и ряд других дорогих операций с QTextStream и QTextCodec , лучше использовать вывод в std::cout с явням преобразованием QString в QByteArray. А лучше сразу использовать QByteArray вместо QString.

4. В случае параллельного вывода, необходимо обеспечить отсутствие блокировок в самом методе логирования, чтобы он сам не являлся источником синхронизации между потоками выполнения, и как следствие неопределенным дополнительным временем выполнения операций.

[__Heaven__]

Спасибо за замечания.
1. Я пользуюсь только openmp и быть может, имею плохое представление о параллельных вычислениях. Сейчас я просто создаю логгер до начала параллельных вычислений и он удаляется после их окончания.

2. Да, наверное, так будет лучше, правда fill работает с QChar, а spacer_ является типом QString, пропадёт возможность писать более одного символа в качестве отступа (да и фиг с ним)

3. Вывод в std::cout использовать не стал по той причине, что я использую CuteLogger, который перехватывает данные и преобразует их в форматированный вывод.

4. Не совсем понял. А как обеспечивается отсутствие блокировок? Я вижу, будто их тут и так нет. Единственное, что в разных потоках может быть пересечение выводов.

[ssoft]

По п.4).

Сообщения необходимо выводить синхронно (иначе можно легко получить смесь из нескольких сообщений), поэтому при их выводе необходимо использовать механизм синхронизации.
Если все потоки будут вызывать метод логирования напрямую, то синхронизация вывода сообщений станет дополнительной синхронизацией между потоками.
Чтобы этого не происходило, обычно, формируют дополнительный поток, который осуществляет вывод сообщений. Тогда сообщения просто перенаправляются в очередь обработки этого дополнительного потока и синхронизация между рабочими потоками сводится к минимуму. А если еще используется lock-free очередь ... ).

[__Heaven__]

Я особо не запаривался на этот счёт, так как CuteLogger имеет MutexLockerы.
На самом деле не очень пока представляю, зачем нужно выводить что-то в потоке. Видимо, не сталкивался с такой задачей. lock-free не слышал пошёл читать

[Igors]

А если еще используется lock-free очередь ... ).

Да, заводное дело  

Конкретно при использовании omp можно просто использовать тамошние ф-ции/директивы которые уже заточены, напр

Код

C++ (Qt)
#pragma omp parallel 
for (int i = 0; i < data.size(); ++i) {
 double t = omp_get_wtime( );
 DoJob(data[i]);
 
#pragma omp single
 printf("thread %d done job %d in %.3f sec\n", omp_get_thread_num(), i, omp_get_wtime() - t);
}