You are here: Home / Technologies / Databases / Drizzle Query logging

Drizzle Query logging

by

Currently Drizzle offers three (3) separate query logging plugins. These plugins offer an extensible means of gathering all or selected queries and provide the foundation for a query analyser tool. Additional filtering includes selecting queries by execution time, result size, rows processed and by any given regular expression via PCRE.

During this tutorial I’ll be stepping though the various logging_query parameters which log SQL in a CSV format.

Confirm Logging Plugins

You can view the current ACTIVE plugins in Drizzle with the following SQL.

drizzle> select version();
+--------------+
| version()    |
+--------------+
| 2009.07.1097 |
+--------------+

drizzle> select * from information_schema.plugins where plugin_name like 'logging%';
+-----------------+----------------+---------------+--------------------------------------+---------------------------------+----------------+
| PLUGIN_NAME     | PLUGIN_VERSION | PLUGIN_STATUS | PLUGIN_AUTHOR                        | PLUGIN_DESCRIPTION              | PLUGIN_LICENSE |
+-----------------+----------------+---------------+--------------------------------------+---------------------------------+----------------+
| logging_gearman | 0.1            | ACTIVE        | Mark Atwood  mark @fallenpegasus.com | Log queries to a Gearman server | GPL            |
| logging_query   | 0.2            | ACTIVE        | Mark Atwood  mark @fallenpegasus.com | Log queries to a CSV file       | GPL            |
| logging_syslog  | 0.2            | ACTIVE        | Mark Atwood  mark @fallenpegasus.com | Log to syslog                   | GPL            |
+-----------------+----------------+---------------+--------------------------------------+---------------------------------+----------------+
3 rows in set (0.01 sec)

Logging all queries

You can define the following configuration variables to enable query logging.

/etc/drizzle/drizzled.cnf
[drizzled]
logging_query_enable=true
logging_query_filename=/var/log/drizzle/general.csv

You can confirm the settings with the following SHOW VARIABLES.

drizzle> show global variables like 'logging_query%';
+---------------------------------------+------------------------------+
| Variable_name                         | Value                        |
+---------------------------------------+------------------------------+
| logging_query_enable                  | ON                           |
| logging_query_filename                | /var/log/drizzle/general.csv |
| logging_query_pcre                    |                              |
| logging_query_threshold_big_examined  | 0                            |
| logging_query_threshold_big_resultset | 0                            |
| logging_query_threshold_slow          | 0                            |
+---------------------------------------+------------------------------+

This command showing queries to be logged.

$ cat /var/log/drizzle/general.csv
1248214561824590,1,1,"","select @@version_comment limit 1","Query",1248214561824590,1240,1240,1,00,0
1248214582588346,1,3,"","show global variables like 'logging_query%'","Query",1248214582588346,1958,1706,6,62,0

Unfortunately the log does not yet provide a header. You need to turn the source code to get a better description of the columns.

      snprintf(msgbuf, MAX_MSG_LEN,
               "%"PRIu64",%"PRIu64",%"PRIu64","%.*s","%s","%.*s","
               "%"PRIu64",%"PRIu64",%"PRIu64",%"PRIu64",%"PRIu64
               "%"PRIu32",%"PRIu32"n",
               t_mark,
               session->thread_id,
               session->query_id,
               // dont need to quote the db name, always CSV safe
               dbl, dbs,
               // do need to quote the query
               quotify((unsigned char *)session->query,
                       session->query_length, qs, sizeof(qs)),
               // command_name is defined in drizzled/sql_parse.cc
               // dont need to quote the command name, always CSV safe
               (int)command_name[session->command].length,
               command_name[session->command].str,
               // counters are at end, to make it easier to add more
               (t_mark - session->connect_utime),
               (t_mark - session->start_utime),
               (t_mark - session->utime_after_lock),
               session->sent_row_count,
               session->examined_row_count,
               session->tmp_table,
               session->total_warn_count);

The important parts of this information include:

  • getmicrotime – 1248214561824590
  • Session Id – 1
  • Query Id – 1
  • Schema
  • The Query: “show global variables like ‘logging_query%'”
  • The Query type “Query”
  • Time session connected – 1248214582588346
  • The total execution time – 1958
  • The execution time after necessary locks – 1706
  • The number of rows returned – 6
  • The number of rows examined – 6
  • The number of temporary tables used – 2
  • The total warning count – 0

I also found what I believe is a formatting problem logged as Bug #402831.

You can enable logging dynamically.

drizzle> select now();
+---------------------+
| now()               |
+---------------------+
| 2009-07-22 02:14:31 |
+---------------------+
1 row in set (0 sec)

drizzle> set global logging_query_enable=true;
Query OK, 0 rows affected (0 sec)

drizzle> select curdate();
+------------+
| curdate()  |
+------------+
| 2009-07-22 |
+------------+
1 row in set (0 sec)

drizzle> set global logging_query_enable=false;
Query OK, 0 rows affected (0 sec)

drizzle> select now();
+---------------------+
| now()               |
+---------------------+
| 2009-07-22 02:14:54 |
+---------------------+
1 row in set (0 sec)

1248228876381645,4,3,"","set global logging_query_enable=true","Query",1248228876381645,761,761,0,00,0
1248228886866882,4,4,"","select curdate()","Query",1248228886866882,105,105,1,00,0

I was not able to alter the logging_query_filename dynamically. Need to confirm with the development team about this functionality for the future.

drizzle> set global logging_query_filename='/tmp/general.csv';
ERROR 1238 (HY000): Variable 'logging_query_filename' is a read only variable

Logging slow queries

If you just wanted to emulate the MySQL slow query log, with a long_query_time of 1 second, you could use the following.

/etc/drizzle/drizzled.cnf
[drizzled]
logging_query_enable=true
logging_query_filename=/var/log/drizzle/slow.csv
logging_query_threshold_slow=1000000

Drizzle supports the ability to set a threshold in microseconds.

NOTE: I wanted to demonstrate this using the popular MySQL SLEEP() function, only to find this is currently not available in Drizzle. This is an ideal example of a simple UDF that can be written and added to Drizzle. One day if I ever have the time.

Here is some sample output using queries > 1 second.

1248216457856195,1,43,"test","insert into numbers   select...","Query",1248216457856195,2160680,2160620,0,26214420,0
1248216462738678,1,45,"test","insert into numbers   select...","Query",1248216462738678,4530327,4530263,0,52428821,0
1248216472430813,1,47,"test","insert into numbers   select...","Query",1248216472430813,8990965,8990890,0,104857622,0
1248216473592812,1,48,"test","select @counter := count(*) from numbers","Query",1248216473592812,1152319,1152257,1,104857622,0

Logging by threshold

Drizzle Query Logging provides the ability to return results by 2 thresholds, the number of rows in the result, and the number of rows examined by the storage engine.

/etc/drizzle/drizzled.cnf
[drizzled]
logging_query_enable=true
logging_query_filename=/var/log/drizzle/slow.csv
logging_query_threshold_big_resultset=100

1248216631322097,1,5,"test","select * from numbers limit 100","Query",1248216631322097,281,217,100,1002,0
1248216642763174,1,6,"test","select * from numbers limit 101","Query",1248216642763174,268,215,101,1012,0

/etc/drizzle/drizzled.cnf
[drizzled]
logging_query_enable=true
logging_query_filename=/var/log/drizzle/slow.csv
logging_query_threshold_big_examined=1000

1248216785430588,1,6,"test","select * from numbers limit 1000","Query",1248216785430588,8055,7983,1000,10002,0
1248216800327928,1,7,"test","select count(*) from numbers","Query",1248216800327928,1041322,1041222,1,10485762,0

Logging by pattern

The final option is to return queries that match a given pattern via a PCRE expression.



/etc/drizzle/drizzled.cnf
[drizzled]
logging_query_enable=true
logging_query_filename=/var/log/drizzle/slow.csv
logging_query_pcre=now



drizzle> select now();
+---------------------+
| now()               |
+---------------------+
| 2009-07-22 03:24:32 |
+---------------------+
1 row in set (0 sec)

drizzle> select curdate();
+------------+
| curdate()  |
+------------+
| 2009-07-22 |
+------------+
1 row in set (0 sec)

drizzle> select "now";
+-----+
| now |
+-----+
| now |
+-----+
1 row in set (0 sec)

drizzle> select "know how";
+----------+
| know how |
+----------+
| know how |
+----------+
1 row in set (0 sec)



1248233072792211,3,2,"","select now()","Query",1248233072792211,154,154,1,00,0
1248233085807520,3,4,"","select "now"","Query",1248233085807520,92,92,1,00,0
1248233096659018,3,5,"","select "know how"","Query",1248233096659018,75,75,1,00,0



Another example using a pattern.


/etc/drizzle/drizzled.cnf
[drizzled]
logging_query_enable=true
logging_query_filename=/var/log/drizzle/slow.csv
logging_query_pcre="[0-9][0-9][0-9]"



drizzle> select 1;
+---+
| 1 |
+---+
| 1 |
+---+
1 row in set (0 sec)

drizzle> select 11;
+----+
| 11 |
+----+
| 11 |
+----+
1 row in set (0 sec)

drizzle> select 111;
+-----+
| 111 |
+-----+
| 111 |
+-----+
1 row in set (0 sec)

drizzle> select 1111;
+------+
| 1111 |
+------+
| 1111 |
+------+
1 row in set (0 sec)

drizzle> select 11+22;
+-------+
| 11+22 |
+-------+
|    33 |
+-------+
1 row in set (0 sec)



1248233336460373,3,4,"","select 111","Query",1248233336460373,79,79,1,00,0
1248233339300429,3,5,"","select 1111","Query",1248233339300429,82,82,1,00,0



Unfortunately it seems that this variable is also not configurable dynamically at this time.


drizzle> set global logging_query_pcre="now";
ERROR 1238 (HY000): Variable 'logging_query_pcre' is a read only variable



This is definitely an improvement over current MySQL logging.



Comments
    
	
  1. 
	
	
    2.