Re: [sqlite] Logging and timing queries

[Simon Slavin]

On 31 Jul 2014, at 1:41pm, Ketil Froyn  wrote:

> I find it would be
> very useful to log some or all queries sent to the database, ideally also
> with timing information on how long it took to gather and send the
> response, so that it can be determined what queries are received and how
> long each query actually takes.

This probably wouldn't get built into the standard SQLite library.  Bear in 
mind that of the literally billions of installations of SQLite, the vast 
majority are on smartphones, DVRs, set-top boxes, embedded controllers, or 
other small devices.  So adding code to SQLite is rarely done just for things 
which would be done only on 'normal' computers.

For the people who want it, it's easy to build a shell around the SQLite calls 
like this:

int pseudo_sqlite3_exec(commandString) {
log commandString
log start time
int theResult = sqlite3_exec(commandString)
log finish time
return theResult
}

Log to a text file, and write a utility to analyse the text file later.

SQLite does, however, include calls which can be used to monitor changes made 
to the database:




SQLite also includes a command specifically made for spotting badly-optimized 
combinations of commands and databases:



You can feed any statement to this and /instead of executing it/ SQLite will 
list the steps it would take to execute it.  So you can use it for testing 
without having to worry that your database will be changed.  If the query plan 
for a commonly used command includes scanning a long table (rather that using 
an index, which is shown differently) you think about and rephrasing it or 
creating a good index for it.

You can even execute EXPLAIN QUERY PLAN in the SQLite shell tool, which outputs 
the results neatly, and means you don't have to hack up your own software just 
for testing purposes.

Simon.
___
sqlite-users mailing list
sqlite-users@sqlite.org
http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users

Re: [sqlite] Logging and timing queries

[Dominique Pellé]

Ketil Froyn  wrote:

> Hi,
>
> In debugging and inspecting applications using sqlite, I find it would be
> very useful to log some or all queries sent to the database, ideally also
> with timing information on how long it took to gather and send the
> response, so that it can be determined what queries are received and how
> long each query actually takes. It's possible to do this at the application
> level, but I think it would be very useful to do this using sqlite itself.
> If detailed query logging could be enabled in the database with a pragma or
> by using a debug version of the libarry somehow, it would let users and
> developers get standardised details about what queries are run and how long
> they take, even temporarily on a live system.
>
> There's lots of situations where this could be useful, like switching on
> and off debugging on the fly in live/production systems to identify
> transient problems or bottlenecks, and debugging software using sqlite with
> a live dataset without necessarily having to recreate the working
> conditions in a controlled environment, and without recompiling, and
> without developing/enabling support for sql debugging in the application.
>
> I've used mysql-proxy in the past to debug mysql databases in this way, and
> it was very effective. But since there's no network connection involved in
> sqlite, this method can't be used to temporarily redirect the queries in
> the same way.
>
> Have I missed a way to do something like this in sqlite already, or would
> you regard this as a feature request?
>
> Thanks, Ketil

Hi Ketil

SQLite allows you to that.  See:

sqlite3_profile(...);
sqlite3_trace(...);

http://www.sqlite.org/c3ref/profile.html

You call sqlite3_profile(...) once to register a callback.
I use something like this:

sqlite3_profile(db, SqliteProfileCallback, db);

And for the callback, I use something like this:

static void SqliteProfileCallback(void* aDb, const char* aQueryStr,
sqlite3_uint64 aTimeInNs)
{
  sqlite3* db = static_cast(aDb);
  const char* dbName = sqlite3_db_filename(db, "main");

  // Statistics per DB connection.
  // See: http://www.sqlite.org/c3ref/db_status.html
  int cacheUsed[2]  = { 0, 0 };
  int schemaUsed[2] = { 0, 0 };
  int stmtUsed[2]   = { 0, 0 };
  int cacheHit[2]   = { 0, 0 };
  int cacheMiss[2]  = { 0, 0 };
  sqlite3_db_status(db, SQLITE_DBSTATUS_CACHE_USED,  &cacheUsed[0],
&cacheUsed[1],  0);
  sqlite3_db_status(db, SQLITE_DBSTATUS_SCHEMA_USED, &schemaUsed[0],
&schemaUsed[1], 0);
  sqlite3_db_status(db, SQLITE_DBSTATUS_STMT_USED,   &stmtUsed[0],
&stmtUsed[1],   0);
  sqlite3_db_status(db, SQLITE_DBSTATUS_CACHE_HIT,   &cacheHit[0],
&cacheHit[1],   0);
  sqlite3_db_status(db, SQLITE_DBSTATUS_CACHE_MISS,  &cacheMiss[0],
&cacheMiss[1],  0);

  fprintf(stderr, "SQLite profile: msec=[%llu] mem/high/lim=[%lld/%lld/%lld] "
 "schema=[%d] stmt=[%d] cache=[%d]
hit/miss=[%d/%d] db=[%s] sql=[%s]",
   aTimeInNs/100, // Time taken by the query
in milliseconds.

   sqlite3_memory_used(), // Global memory used by
SQLite now in bytes.
   sqlite3_memory_highwater(0),   // Global high water mark of
memory used by SQLite in bytes.
   sqlite3_soft_heap_limit64(-1), // Global current heap limit
in bytes (a hint only).

   schemaUsed[0], // Memory used by this
connection for the schema.
   stmtUsed[0],   // Memory used by this
connection for statements.
   cacheUsed[0],  // Memory used by this
connection for cache.

   cacheHit[0], cacheMiss[0], // SQLite cache hit/miss stats.
   dbName, aQueryStr);
}


That gives lots of useful information to find slow queries, memory
usage, etc.  But I'm curious whether there is anything else useful
that could be logged inside the profile or trace callback.

One thing that I would like, is to be able to call sqlite3_stmt_status(...)
to get information about the statement inside the callback. But
the sqlite3_stmt object is not available inside the callback
unfortunately and I don't see how to make it available, other
than changing SQLite source (which I have not tried). It would
have been nice it it was available somehow.

Regards
Dominique
___
sqlite-users mailing list
sqlite-users@sqlite.org
http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users

[sqlite] Logging and timing queries

[Ketil Froyn]

Hi,

In debugging and inspecting applications using sqlite, I find it would be
very useful to log some or all queries sent to the database, ideally also
with timing information on how long it took to gather and send the
response, so that it can be determined what queries are received and how
long each query actually takes. It's possible to do this at the application
level, but I think it would be very useful to do this using sqlite itself.
If detailed query logging could be enabled in the database with a pragma or
by using a debug version of the libarry somehow, it would let users and
developers get standardised details about what queries are run and how long
they take, even temporarily on a live system.

There's lots of situations where this could be useful, like switching on
and off debugging on the fly in live/production systems to identify
transient problems or bottlenecks, and debugging software using sqlite with
a live dataset without necessarily having to recreate the working
conditions in a controlled environment, and without recompiling, and
without developing/enabling support for sql debugging in the application.

I've used mysql-proxy in the past to debug mysql databases in this way, and
it was very effective. But since there's no network connection involved in
sqlite, this method can't be used to temporarily redirect the queries in
the same way.

Have I missed a way to do something like this in sqlite already, or would
you regard this as a feature request?

Thanks, Ketil
___
sqlite-users mailing list
sqlite-users@sqlite.org
http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users