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

Имеется типична ситуация:

• кем-то написанное приложение на 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) к приложению были совместимы, иначе можно получить падение.