Трэйсер запросов в tclsqlite

В новом релизе 3.6.21 появилась возможность полноценной трассировки запросов (раньше значения забинденных переменных не выводились). Тест у меня для этой функции давно написан, его и привожу.

Кстати, нюанс - функция трассировки имеет возможность отменить выполнение запроса, так что аудит запросов в эскулайт легко делается встроенными средствами. Замечу, что инструкции PRAGMA не выводятся.

$ ./test_trace.tcl
{DROP TABLE IF EXISTS events}
{CREATE TABLE events (id INTEGER PRIMARY KEY,value INTEGER)}
{SAVEPOINT _tcl_transaction}
{insert into events (value) values (0)}
{insert into events (value) values (1)}
{insert into events (value) values (2)}
{insert into events (value) values (3)}
{insert into events (value) values (4)}
{insert into events (value) values (5)}
{insert into events (value) values (6)}
{insert into events (value) values (7)}
{insert into events (value) values (8)}
{insert into events (value) values (9)}
{insert into events (value) values ('value')}
COMMIT
{CREATE INDEX events_value_idx ON events(value);}
{select value from events}

test_trace.tcl

#!/usr/bin/tclsh8.5 
package require sqlite3
sqlite3 db trace.db

proc trace {args} {
    puts "$args"
    return SQLITE_OK
}
db trace trace
db eval {PRAGMA legacy_file_format = off} 
db eval {DROP TABLE IF EXISTS events}
db eval {CREATE TABLE events (id INTEGER PRIMARY KEY,value INTEGER)}
db transaction {
    for {set i 0} {$i<10} {incr i} {
        set value [expr {$i % 500000}]
        db eval {insert into events (value) values ($value)}
    }
    set value value
    db eval {insert into events (value) values ($value)}
}
db eval {CREATE INDEX events_value_idx ON events(value);}
db onecolumn {select value from events}
db close

Что интересно, системные запросы тоже выводятся. Даже не знаю пока, баг это или фича, написал в рассылку эскулайта, посмотрим, что ответят. С одной стороны, полезно для отладки, с другой - придется как-то отделять введенные пользователем запросы от сгенерированных в "движке".

ANALYZE
{SELECT idx, stat FROM 'main'.sqlite_stat1}
{SELECT idx,sampleno,sample FROM 'main'.sqlite_stat2}
VACUUM
{ATTACH '' AS vacuum_db;}
{BEGIN EXCLUSIVE;}
{SELECT 'CREATE TABLE vacuum_db.' || substr(sql,14)   FROM sqlite_master WHERE type='table' 
AND name!='sqlite_sequence'   AND rootpage>0}
{CREATE TABLE vacuum_db.events (id INTEGER PRIMARY KEY,value INTEGER)}
{CREATE TABLE vacuum_db.sqlite_stat1(tbl,idx,stat)}
{CREATE TABLE vacuum_db.sqlite_stat2(tbl,idx,sampleno,sample)}
{SELECT 'CREATE INDEX vacuum_db.' || substr(sql,14)  FROM sqlite_master WHERE sql LIKE 
'CREATE INDEX %' }
{CREATE INDEX vacuum_db.events_value_idx ON events(value)}
{SELECT 'CREATE UNIQUE INDEX vacuum_db.' || substr(sql,21)   FROM sqlite_master WHERE sql 
LIKE 'CREATE UNIQUE INDEX %'}
{SELECT 'INSERT INTO vacuum_db.' || quote(name) || ' SELECT * FROM main.' || quote(name) || 
';'FROM main.sqlite_master WHERE type = 'table' AND name!='sqlite_sequence'   AND rootpage>0}
{INSERT INTO vacuum_db.'events' SELECT * FROM main.'events';}
{INSERT INTO vacuum_db.'sqlite_stat1' SELECT * FROM main.'sqlite_stat1';}
{INSERT INTO vacuum_db.'sqlite_stat2' SELECT * FROM main.'sqlite_stat2';}
{SELECT 'DELETE FROM vacuum_db.' || quote(name) || ';' FROM vacuum_db.sqlite_master WHERE 
name='sqlite_sequence' }
{SELECT 'INSERT INTO vacuum_db.' || quote(name) || ' SELECT * FROM main.' || quote(name) || 
';' FROM vacuum_db.sqlite_master WHERE name=='sqlite_sequence';}
{INSERT INTO vacuum_db.sqlite_master   SELECT type, name, tbl_name, rootpage, sql    FROM 
main.sqlite_master   WHERE type='view' OR type='trigger'      OR (type='table' AND rootpage=0)}

As you can see internal system queries are visualized too. It's may be useful for developers but very bad for users becouse it's impossible to log only user-applied queries.

The test script:

#!/usr/bin/tclsh8.5 
package require sqlite3
sqlite3 db trace.db

proc trace {args} {
    puts "$args"
    return SQLITE_OK
}
db trace trace
db eval {ANALYZE}
db eval {VACUUM}
db close

Upd.
In sqlite-users maillist Roger Binns answer by my question about universal mechanism for logging user queries:

> I want to build a universal extension for logging all user queries. I can write
> this with trace function but it's difficult or impossible to split system and
> user queries.

There are two ways that can be done. The first is to require your extension
and its API be used at which you can then filter and log as needed.

The way I would go about it is not using a SQLite extension, but instead
provide a shared library with logging functions. You can ensure the shared
library is loaded before SQLite (use LD_PRELOAD on Linux/Unix and something
similar on Windows) and hook the SQLite APIs. This requires no change to
the application.

For apswtrace I can output all SQL and bindings, rows returned, how long
each query took, most popular queries, queries that took the longest
(individually and ones that have the same text) etc. This doesn't require
any code changes in the Python application.

This unobtrusive mechanism also allows you to get more detailed. For
example you can track how often SQLite is busy (install a busy handler,
transparently call the user one if needed). You can even use it to fake
things. For example historically this mechanism has been used to fake the
current time, but you could fake busy results to help with testing. If you
also intercept read and write system calls you can even correspond I/O
activity to the queries that cause it. You can even capture stack
backtraces when tying them to SQL calls. There are so many possibilities.