Имеется типична ситуация:
- кем-то написанное приложение на 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) к приложению были совместимы, иначе можно получить падение.
ссылка на оригинал статьи https://habrahabr.ru/post/276711/
Добавить комментарий