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

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

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

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

#pragma once

#include 

#include 

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 m_impl;
};
}

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

#include 
#include 

#include 
#include 
#include 
#include 
#include 
#include 

#include 

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

#include "Log.h"

typedef std::lock_guard 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(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();
        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.errorString();
        exit(1);
    }
}

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

#include 
#include 

#include 
#include 
#include 

#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;
}

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