SQLite Query Profiling for Qt Applications

There is a typical situation:

• written by someone on Qt;
• users complain that the program while working a lot of CPU;
• The profiler and strace indicate that the base is being raped.

In such a situation, I want to see what kind of requests, their number, and the execution time. If PostgreSQL has pg_stat_statements and pgBadger , then for SQLite I had to write my scooter. The scooter is a call to sqlite3_profile for each connection, recording the information received in the log.

Installing the sqlite3_profile handler

QSqlDriver provides us with a handle , from where we can pull out the sqlite3* handler. In Qt5, we have to do the following
')

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

Macros Q_DECLARE_* for registering type sqlite3* , which would then be pulled out of QVariant .

Handler

The handler signature is

 void profile(void* userData, const char* sql, sqlite3_uint64 time) 

Options:

• userData user data set in sqlite3_profile , in my case this is this ;
• sql query text in UTF-8;
• time query time in nanoseconds, but the current implementation ensures millisecond accuracy.

Log class sources take <200 lines

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

Usage example

Senseless and stupid example

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

After opening the database, set the handler Log::instance().setProfile(db.driver());
With the help of an auxiliary utility, we convert the log into a SQLite database, to use the power of SQL.

Request

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

Will give the result

CNT	Avg	TIME	QUERY
one	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 (?,?,?)

Expected result when no transactions are used. The average insertion time is 150 milliseconds, the insertion time for all records is 15 seconds. A little more interesting is obtained if you uncomment a transaction.

CNT	Avg	TIME	QUERY
one	0.0	0	BEGIN
one	129.0	129	COMMIT
one	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 (?,?,?)

All code is available on GitHub . When compiling, make sure that the version of SQLite used in Qt and linked (needed for sqlite3_profile) to the application are compatible, otherwise you can get a drop.