Профілювання запитів до 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 NOT NULL PRIMARY KEY, "
"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 NOT NULL PRIMARY KEY, 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 NOT NULL PRIMARY KEY, address VARCHAR(255), age integer); 100 0.02 2 INSERT INTO my_table(number, address, age) VALUES (?, ?, ?)
Весь код доступний на GitHub. При компіляції слідкуйте щоб версія SQLite використовувана в Qt і линкуемая(потрібно для sqlite3_profile) до додатка були сумісні, інакше можна отримати падіння.

Джерело: Хабрахабр

0 коментарів

Тільки зареєстровані та авторизовані користувачі можуть залишати коментарі.