Имеется типична ситуация:
В такой ситуации хочется посмотреть что за запросы, их количество, время выполнения. Если в PostgreSQL есть pg_stat_statements и pgBadger, то для SQLite пришлось написать свой самокат. Самокат представляет из себя вызов sqlite3_profile для каждого соединения, запись полученной информации в журнал.
QSqlDriver предоставляет нам handle, откуда нам можно вытащить обработчик
Макросы
Сигнатура обработчика имеет вид
Параметры:
Исходники класса лога занимает < 200 строк
Бессмысленный и тупой пример
После открытия базы, устанавливаем обработчик
При помощи вспомогательной утилиты преобразуем лог в базу данных SQLite, для использования мощи SQL.
Запрос
Выдаст результат
Ожидаемый результат когда не используются транзакции. Среднее время операции вставки занимает 150 миллисекунд, время вставки всех записей 15 секунд. Чуточку интересней получается если раскомментировать транзакцию.
Весь код доступен на GitHub. При компиляции следите, чтобы версия SQLite используемая в Qt и линкуемая (нужно для sqlite3_profile) к приложению были совместимы, иначе можно получить падение.
- кем-то написанное приложение на 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) к приложению были совместимы, иначе можно получить падение.