8 февраля 2016 в 10:01

Профилирование запросов к SQLite для Qt приложений

SQLite*, Qt*, C++*
Имеется типична ситуация:

  • кем-то написанное приложение на Qt;
  • пользователи жалуются, что программа во время работы жрем много CPU;
  • профилировщик и strace указывают на то, что происходит насилование базы.

В такой ситуации хочется посмотреть что за запросы, их количество, время выполнения. Если в PostgreSQL есть pg_stat_statements и pgBadger, то для SQLite пришлось написать свой самокат. Самокат представляет из себя вызов sqlite3_profile для каждого соединения, запись полученной информации в журнал.


Установка обработчика sqlite3_profile


QSqlDriver предоставляет нам handle, откуда нам можно вытащить обработчик sqlite3*. В Qt5 нам придется выполнить следующее

Q_DECLARE_OPAQUE_POINTER(sqlite3*);
Q_DECLARE_METATYPE(sqlite3*);

//....
QVariant v = driver->handle();
const QString tpName = v.typeName();

if (v.isValid() && (tpName == "sqlite3*"))
{
    sqlite3* handle = v.value<sqlite3*>();
    if (handle != nullptr)
    {
        sqlite3_profile(handle, profile, this);
    }
}

Макросы Q_DECLARE_* для регистрации типа sqlite3*, что бы потом вытащить из QVariant.

Обработчик


Сигнатура обработчика имеет вид

void profile(void* userData, const char* sql, sqlite3_uint64 time)

Параметры:

  • userData пользовательские данные установленные в sqlite3_profile, в моем случае это this;
  • sql текст запроса в UTF-8;
  • time время работы запроса в наносекундах, но текущая реализация обеспечивает точность до миллисекунд.

Исходники класса лога занимает < 200 строк


#pragma once

#include <memory>

#include <QtCore/QString>

class QSqlDriver;

namespace QSqliteProfiler
{

struct LogRecord
{
    quint64 timestamp;
    quint64 duration;
    QString query;
};

class Log
{
public:

    static Log& instance();

    void setProfile(QSqlDriver* driver);

    void setLogFile(const QString& file);
    void write(const LogRecord& record);

private:

    Log();
    ~Log();

private:

    struct LogImpl;
    std::unique_ptr<LogImpl> m_impl;
};
}

inline QDataStream & operator<< (QDataStream& stream, const QSqliteProfiler::LogRecord record)
{
    stream<<record.timestamp<<record.duration<<record.query;

}

inline QDataStream & operator>> (QDataStream& stream, QSqliteProfiler::LogRecord& record)
{
    stream>>record.timestamp>>record.duration>>record.query;
}




#include <mutex>
#include <sqlite3.h>

#include <QtCore/QFile>
#include <QtCore/QDebug>
#include <QtCore/QVariant>
#include <QtCore/QDateTime>
#include <QtCore/QMetaType>
#include <QtCore/QDataStream>

#include <QtSql/QSqlDriver>

Q_DECLARE_OPAQUE_POINTER(sqlite3*);
Q_DECLARE_METATYPE(sqlite3*);

#include "Log.h"

typedef std::lock_guard<std::mutex> LockGuard;

namespace
{

void profile(void* userData, const char* sql, sqlite3_uint64 time)
{
    using namespace QSqliteProfiler;

    const quint64 timestamp = QDateTime::currentMSecsSinceEpoch();
    LogRecord record{timestamp, time, sql};

    auto log = static_cast<Log*>(userData);
    log->write(record);
}

}

namespace QSqliteProfiler
{

Log& Log::instance()
{
    static Log log;
    return log;
}

struct Log::LogImpl
{
    ~LogImpl()
    {
        LockGuard lock(fileMutex);

        if(file.isOpen())
        {
            file.flush();
            file.close();
        }
    }

    QFile file;
    QDataStream stream;
    std::mutex fileMutex;
};

Log::Log() :
        m_impl(new LogImpl)
{

}

Log::~Log() = default;

void Log::setProfile(QSqlDriver* driver)
{
    QVariant v = driver->handle();
    const QString tpName = v.typeName();

    if (v.isValid() && (tpName == "sqlite3*"))
    {
        sqlite3* handle = v.value<sqlite3*>();
        if (handle != nullptr)
        {
            sqlite3_profile(handle, profile, this);
        }
    }
}

void Log::setLogFile(const QString& file)
{
    LockGuard lock(m_impl->fileMutex);

    if(m_impl->file.isOpen())
    {
        m_impl->file.close();
    }

    m_impl->file.setFileName(file);
    auto isOpen = m_impl->file.open(QIODevice::WriteOnly);
    if(isOpen)
    {
        m_impl->stream.setDevice(&m_impl->file);
    }
    else
    {
        qCritical()<<"Can not open file for writing, file"<<file;
        qDebug()<<m_impl->file.errorString();
        exit(1);
    }
}

void Log::write(const LogRecord& record)
{
    LockGuard lock(m_impl->fileMutex);
    if(m_impl->file.isOpen())
    {
        m_impl->stream<<record;
    }
}
}



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


Бессмысленный и тупой пример

#include <QtCore/QDebug>
#include <QtCore/QCoreApplication>

#include <QtSql/QSqlQuery>
#include <QtSql/QSqlDriver>
#include <QtSql/QSqlDatabase>

#include "Log.h"

int main(int argc, char *argv[])
{

    using namespace QSqliteProfiler;

    QCoreApplication app(argc, argv);
    Log::instance().setLogFile("sqlite.profile");

    QSqlDatabase db = QSqlDatabase::addDatabase("QSQLITE");
    db.setDatabaseName("db.sqlite");

    if (!db.open()) {
           qDebug()<<"Test data base not open";
           return 1;
    }

    Log::instance().setProfile(db.driver());

    QSqlQuery query;
    query.exec( "CREATE TABLE my_table ("
            "number integer PRIMARY KEY NOT NULL, "
            "address VARCHAR(255), "
            "age integer"
            ");");

    QString str;
    //db.transaction();
    for(int i = 0; i < 100; ++i)
    {
        QSqlQuery query1(db);
        query1.prepare("INSERT INTO my_table(number, address, age) VALUES (?, ?, ?)");
        query1.bindValue(0, i);
        query1.bindValue(1, "hello world str.");
        query1.bindValue(2, 37);
        query1.exec();
    }
    //db.commit();

    return 0;
}

После открытия базы, устанавливаем обработчик Log::instance().setProfile(db.driver());
При помощи вспомогательной утилиты преобразуем лог в базу данных SQLite, для использования мощи SQL.

Запрос

SELECT
  count(time) AS CNT, 
  avg(time)/1000000  AS AVG ,
  sum(time)/1000000 AS TIME,
  query 
FROM query
GROUP BY query

Выдаст результат

CNT AVG TIME QUERY
1 155.0 155 CREATE TABLE my_table (number integer PRIMARY KEY NOT NULL, address VARCHAR(255), age integer);
100 149.55 14955 INSERT INTO my_table(number, address, age) VALUES (?, ?, ?)

Ожидаемый результат когда не используются транзакции. Среднее время операции вставки занимает 150 миллисекунд, время вставки всех записей 15 секунд. Чуточку интересней получается если раскомментировать транзакцию.

CNT AVG TIME QUERY
1 0.0 0 BEGIN
1 129.0 129 COMMIT
1 132.0 132 CREATE TABLE my_table (number integer PRIMARY KEY NOT NULL, address VARCHAR(255), age integer);
100 0.02 2 INSERT INTO my_table(number, address, age) VALUES (?, ?, ?)

Весь код доступен на GitHub. При компиляции следите, чтобы версия SQLite используемая в Qt и линкуемая (нужно для sqlite3_profile) к приложению были совместимы, иначе можно получить падение.
Dmitry @RPG18
карма
31,2
рейтинг 0,3
C++/Golang
Похожие публикации
Самое читаемое Разработка

Комментарии (5)

  • +1
    Советую добавить чуть более подробное описание на GitHub и отправить проект в каталог inqlude.org
    • 0
      Обязательно дополню(если доберусь к себе домой) описание на GitHub. За inqlude спасибо, не знал.
  • 0
    Спасибо, полезная вещь, но есть пара вопросов:
    1. Извлечь указатель на sqlite3* из QVariant можно и через обычный static_cast, что, кстати, и рекомендуется в приведенной вами ссылке на документацию. Почему извлекаете именно через макросы Q_DECLARE_*?
    2. В связи с чем связано использование классов std::mutex и std::lock_quard, если существуют аналогичные в Qt QMutex и QMutexLocker? Если дело в накладных расходах, то, возможно, стоило бы использовать и std::ofstream вместо QFile.
    • 0
      1. Макросы связаны с тем, что использую метод value, который делает qvariant_cast. Метод data присутствует, но он помечен как «internal» и в документацию не попадает, поэтому использовал value.
      2. Ничем. Отдаю предпочтение стандартным типам, да и код там тривиальный.
  • 0
    Отличный хинт. Если опишите такое же для mysql и postgre я думаю многие скажут вам большое спасибо.

    Есть небольшой комментарий:
    Я не видел конкретной реализации функции которая вызывает «profile», но есть вероятность что в userData вам может прийти чужой указатель (например ваша библиотека/плагин одна/один из многих использующих sqlite с профилированием в приложении), и слепой static_cast может тут немного попортить нервы. Наверно я бы сделал profile статическим методом синглтона Log и добавил проверку на равенство userData. Есть подозрение что по userData реализовали разделение профилируемых запросов на стороне «клиента» (может быть я ошибаюсь не очень представляю схему по которой реализованы подключения в sqlite из одного процесса.). Просто неоднократно сталкивался с подобным дизайном в C API.

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