Merge lp:~daniel-nichter/drizzle/query-log-ts into lp:~drizzle-trunk/drizzle/development

[Daniel Nichter]

Just changes to query_log plugin, primarily: make first line of events "start_ts=VALUE" instead of a special bare "VALUE". This makes it possible to match/parse all attributes with one pattern because they are now all of the form ATTRIBUTE=VALUE. Documented meta-format of query log file.

=== modified file 'plugin/query_log/docs/index.rst'
--- plugin/query_log/docs/index.rst	2011-09-03 22:25:16 +0000
+++ plugin/query_log/docs/index.rst	2011-09-18 20:15:24 +0000
@@ -116,7 +116,7 @@
 * ``query_log_enabled``
 
    :Scope: Global
-   :Dynamic: No
+   :Dynamic: Yes
    :Option:
 
    If query logging is globally enabled or not.
@@ -126,7 +126,7 @@
 * ``query_log_file``
 
    :Scope: Global
-   :Dynamic: No
+   :Dynamic: Yes
    :Option: :option:`--query-log.file`
 
    Query log file.
@@ -136,7 +136,7 @@
 * ``query_log_file_enabled``
 
    :Scope: Global
-   :Dynamic: No
+   :Dynamic: Yes
    :Option: :option:`--query-log.file-enabled`
 
    If query logging to a file is enabled.
@@ -146,7 +146,7 @@
 * ``query_log_threshold_execution_time``
 
    :Scope: Global
-   :Dynamic: No
+   :Dynamic: Yes
    :Option: :option:`--query-log.threshold-execution-time`
 
    Threshold for logging slow queries.
@@ -156,7 +156,7 @@
 * ``query_log_threshold_lock_time``
 
    :Scope: Global
-   :Dynamic: No
+   :Dynamic: Yes
    :Option: :option:`--query-log.threshold-lock-time`
 
    Threshold for logging long locking queries.
@@ -166,7 +166,7 @@
 * ``query_log_threshold_rows_examined``
 
    :Scope: Global
-   :Dynamic: No
+   :Dynamic: Yes
    :Option: :option:`--query-log.threshold-rows-examined`
 
    Threshold for logging queries that examine too many rows.
@@ -176,7 +176,7 @@
 * ``query_log_threshold_rows_sent``
 
    :Scope: Global
-   :Dynamic: No
+   :Dynamic: Yes
    :Option: :option:`--query-log.threshold-rows-sent`
 
    Threshold for logging queries that return too many rows.
@@ -186,7 +186,7 @@
 * ``query_log_threshold_session_time``
 
    :Scope: Global
-   :Dynamic: No
+   :Dynamic: Yes
    :Option: :option:`--query-log.threshold-session-time`
 
    Threshold for logging queries that are active too long.
@@ -196,7 +196,7 @@
 * ``query_log_threshold_tmp_tables``
 
    :Scope: Global
-   :Dynamic: No
+   :Dynamic: Yes
    :Option: :option:`--query-log.threshold-tmp-tables`
 
    Threshold for logging queries that use too many temporary tables.
@@ -206,7 +206,7 @@
 * ``query_log_threshold_warnings``
 
    :Scope: Global
-   :Dynamic: No
+   :Dynamic: Yes
    :Option: :option:`--query-log.threshold-warnings`
 
    Threshold for logging queries that cause too many warnings.
@@ -214,7 +214,7 @@
 Examples
 --------
 
-Start Drizzle with the query plugin and log queries that take longer than 1 second to execute to the default log file:
+Start Drizzle with the query plugin and log queries that take longer than 1 second to execute to the default query log file:
 
 .. code-block:: none
 
@@ -257,20 +257,20 @@
 Log File
 ^^^^^^^^
 
-The log file destination is enabled when both ``query_log_enabled`` and ``query_log_file_enabled`` are true (``SHOW VARIABLES`` lists ``ON`` and ``OFF`` instead of ``TRUE`` and ``FASLE``).  When ``query_log_file_enabled`` is true, the ``query_log_file`` is open.  When ``query_log_file_enabled`` is set false, the log file is closed.  This is helpful if you want to rotate the log file.
+The query log file destination is enabled when both ``query_log_enabled`` and ``query_log_file_enabled`` are true (``SHOW VARIABLES`` lists ``ON`` and ``OFF`` instead of ``TRUE`` and ``FASLE``).  When ``query_log_file_enabled`` is true, the ``query_log_file`` is open.  When ``query_log_file_enabled`` is set false, the query log file is closed.  This is helpful if you want to rotate the query log file.
 
-The log file is a plain text, structured file that is readable by humans and easily parsable by tools.  It looks like:
+The query log file is a plain text, structured file that is readable by humans and easily parsable by tools.  It looks like:
 
 .. code-block:: none
 
-  # 2011-05-15T01:48:17.814985
+  # start_ts=2011-05-15T01:48:17.814985
   # session_id=1 query_id=6 rows_examined=0 rows_sent=0 tmp_tables=0 warnings=1
   # execution_time=0.000315 lock_time=0.000315 session_time=16.723020
   # error=true
   # schema=""
   set query_log_file_enabled=true;
   #
-  # 2011-05-15T01:48:21.526746
+  # start_ts=2011-05-15T01:48:21.526746
   # session_id=1 query_id=7 rows_examined=10 rows_sent=10 tmp_tables=0 warnings=0
   # execution_time=0.000979 lock_time=0.000562 session_time=20.435445
   # error=false
@@ -280,7 +280,31 @@
 
 Events are separated by a single ``#`` character.  This record separator can be used by programs like :program:`awk` and :program:`perl` to easily separate events in a log.
 
-The first line line of each event is a UTC/GMT timestamp with microsecond precision; the timezone cannot be changed.  The second line has attributes with integer values.  The third line has attributes with high-precision time values, always with six decimals places of precision.  The fourth line has attributes with boolean values, either ``true`` or ``false``.  The fifth line has attributes with string values, always double-quoted.  Remaining lines are the query which can contain multiple lines, blank lines, et.  The record separator marks the event of the event.
+The first line of each event has UTC/GMT timestamps with microsecond precision; the timezone cannot be changed.  The second line has attributes with integer values.  The third line has attributes with high-precision time values, always with six decimals places of precision.  The fourth line has attributes with boolean values, either ``true`` or ``false``.  The fifth line has attributes with string values, always double-quoted.  Remaining lines are the query which can contain multiple lines, blank lines, et.  The record separator marks the event of the event.
+
+As the example above demonstrates, the meta-format for each event in the query log is::
+
+  # attribute=value
+  query
+  #
+
+Parsing a query log file should be easy since the format is static, consistent, and follows
+these rules:
+
+  * Attribute-value pairs are on comment lines that begin with one ``#`` character followed
+    by a space.
+  * Comment lines have one or more attribute-value pairs.
+  * Attribute-value pairs are separated by one space.
+  * Attribute names are lowercase with only characters ``a`` to ``z`` and ``_`` (underscore).
+  * Attribute names with suffix ``_ts`` have microsecond UTC/GMT timestamp values.
+  * Attribute names with suffix ``_time`` have values with an amount of time in seconds with
+    microsecond precision.
+  * One or more comment line precedes the query.
+  * A query is always printed; there are no "admin commands" or special queries.
+  * Every query is terminated by one ``#`` character followed by a newline (``\n``),
+    even the last query in the log file.
+  * There are no blank lines between events.
+  * Only events with this format are printed; there are no special or "fluff" lines.
 
 Bugs and Limitations
 --------------------
@@ -316,7 +340,7 @@
 Version
 -------
 
-This documentation applies to **query_log 0.1**.
+This documentation applies to **query_log 1.0**.
 
 To see which version of the plugin a Drizzle server is running, execute:
 
@@ -327,6 +351,6 @@
 Changelog
 ---------
 
-v0.1
+v1.0
 ^^^^
 * First release.

=== modified file 'plugin/query_log/file.cc'
--- plugin/query_log/file.cc	2011-07-30 21:28:21 +0000
+++ plugin/query_log/file.cc	2011-09-18 20:15:24 +0000
@@ -37,7 +37,8 @@
 {
   if (_fh.is_open())
   {
-    _fh << "# " << event->ts << "\n"
+    _fh << "# start_ts=" << event->ts
+        << "\n"
         << "# session_id="     << event->session_id
         <<  " query_id="       << event->query_id
         <<  " rows_examined="  << event->rows_examined

=== modified file 'plugin/query_log/tests/check-query-log-attribute.pl'
--- plugin/query_log/tests/check-query-log-attribute.pl	2011-05-15 17:58:28 +0000
+++ plugin/query_log/tests/check-query-log-attribute.pl	2011-09-18 20:15:24 +0000
@@ -103,10 +103,7 @@
    my $lineno = 1;
    foreach my $line ( @event_lines ) { 
       next if $line =~ m/^$/;
-      if ( $lineno == 1 ) { # timestamp
-         push @props, 'ts', $line =~ m/^# (\S+)/;
-      }
-      elsif ( $lineno >= 2 && $lineno <= 4 ) { # ints, floats and bools
+      if ( $lineno <= 4 ) { # ts, ints, floats and bools
          push @props, $line =~ m/([a-z_]+)=(\S+)/g;
       }
       elsif ( $lineno == 5 ) { # strings

=== modified file 'plugin/query_log/tests/r/check_query_log_attribute.result'
--- plugin/query_log/tests/r/check_query_log_attribute.result	2011-05-15 17:58:28 +0000
+++ plugin/query_log/tests/r/check_query_log_attribute.result	2011-09-18 20:15:24 +0000
@@ -9,6 +9,6 @@
 schema=test
 session_id=1
 session_time=1.234567
+start_ts=1234-56-78T90:12:34.567890
 tmp_tables=5
-ts=1234-56-78T90:12:34.567890
 warnings=6

=== modified file 'plugin/query_log/tests/r/file.result'
--- plugin/query_log/tests/r/file.result	2011-08-03 16:10:06 +0000
+++ plugin/query_log/tests/r/file.result	2011-09-18 20:15:24 +0000
@@ -21,14 +21,14 @@
 SELECT @@query_log_enabled, @@query_log_file_enabled;
 @@query_log_enabled	@@query_log_file_enabled
 1	1
-# 0000-00-00T00:00:00.000000
+# start_ts=0-00-00T00:00:00.000000
 # session_id=0 query_id=0 rows_examined=0 rows_sent=0 tmp_tables=0 warnings=0
 # execution_time=0.000000 lock_time=0.000000 session_time=0.000000
 # error=false
 # schema="test"
 SET GLOBAL query_log_file_enabled=TRUE;
 #
-# 0000-00-00T00:00:00.000000
+# start_ts=0-00-00T00:00:00.000000
 # session_id=0 query_id=0 rows_examined=0 rows_sent=0 tmp_tables=0 warnings=0
 # execution_time=0.000000 lock_time=0.000000 session_time=0.000000
 # error=false
@@ -42,14 +42,14 @@
 SELECT 2;
 2
 2
-# 0000-00-00T00:00:00.000000
+# start_ts=0-00-00T00:00:00.000000
 # session_id=0 query_id=0 rows_examined=0 rows_sent=0 tmp_tables=0 warnings=0
 # execution_time=0.000000 lock_time=0.000000 session_time=0.000000
 # error=false
 # schema="test"
 SET GLOBAL query_log_file_enabled=TRUE;
 #
-# 0000-00-00T00:00:00.000000
+# start_ts=0-00-00T00:00:00.000000
 # session_id=0 query_id=0 rows_examined=0 rows_sent=0 tmp_tables=0 warnings=0
 # execution_time=0.000000 lock_time=0.000000 session_time=0.000000
 # error=false
@@ -71,14 +71,14 @@
 this is the second log file
 this is the second log file
 Log file exists
-# 0000-00-00T00:00:00.000000
+# start_ts=0-00-00T00:00:00.000000
 # session_id=0 query_id=0 rows_examined=0 rows_sent=0 tmp_tables=0 warnings=0
 # execution_time=0.000000 lock_time=0.000000 session_time=0.000000
 # error=false
 # schema="test"
 SET GLOBAL query_log_file_enabled=TRUE;
 #
-# 0000-00-00T00:00:00.000000
+# start_ts=0-00-00T00:00:00.000000
 # session_id=0 query_id=0 rows_examined=0 rows_sent=0 tmp_tables=0 warnings=0
 # execution_time=0.000000 lock_time=0.000000 session_time=0.000000
 # error=false
@@ -93,49 +93,49 @@
 SELECT 'this is the third log file';
 this is the third log file
 this is the third log file
-# 0000-00-00T00:00:00.000000
+# start_ts=0-00-00T00:00:00.000000
 # session_id=0 query_id=0 rows_examined=0 rows_sent=0 tmp_tables=0 warnings=0
 # execution_time=0.000000 lock_time=0.000000 session_time=0.000000
 # error=false
 # schema="third-log-file"
 SET GLOBAL query_log_file="third-log-file";
 #
-# 0000-00-00T00:00:00.000000
+# start_ts=0-00-00T00:00:00.000000
 # session_id=0 query_id=0 rows_examined=0 rows_sent=0 tmp_tables=0 warnings=0
 # execution_time=0.000000 lock_time=0.000000 session_time=0.000000
 # error=false
 # schema="third-log-file"
 SELECT @@query_log_enabled, @@query_log_file_enabled, @@query_log_file;
 #
-# 0000-00-00T00:00:00.000000
+# start_ts=0-00-00T00:00:00.000000
 # session_id=0 query_id=0 rows_examined=0 rows_sent=0 tmp_tables=0 warnings=0
 # execution_time=0.000000 lock_time=0.000000 session_time=0.000000
 # error=false
 # schema="third-log-file"
 SELECT 'this is the third log file';
 #
-# 0000-00-00T00:00:00.000000
+# start_ts=0-00-00T00:00:00.000000
 # session_id=0 query_id=0 rows_examined=0 rows_sent=0 tmp_tables=0 warnings=0
 # execution_time=0.000000 lock_time=0.000000 session_time=0.000000
 # error=false
 # schema="test"
 SET GLOBAL query_log_file_enabled=TRUE;
 #
-# 0000-00-00T00:00:00.000000
+# start_ts=0-00-00T00:00:00.000000
 # session_id=0 query_id=0 rows_examined=0 rows_sent=0 tmp_tables=0 warnings=0
 # execution_time=0.000000 lock_time=0.000000 session_time=0.000000
 # error=false
 # schema="test"
 SELECT @@query_log_enabled, @@query_log_file_enabled;
 #
-# 0000-00-00T00:00:00.000000
+# start_ts=0-00-00T00:00:00.000000
 # session_id=0 query_id=0 rows_examined=0 rows_sent=0 tmp_tables=0 warnings=0
 # execution_time=0.000000 lock_time=0.000000 session_time=0.000000
 # error=false
 # schema="test"
 SET GLOBAL query_log_file_enabled=TRUE;
 #
-# 0000-00-00T00:00:00.000000
+# start_ts=0-00-00T00:00:00.000000
 # session_id=0 query_id=0 rows_examined=0 rows_sent=0 tmp_tables=0 warnings=0
 # execution_time=0.000000 lock_time=0.000000 session_time=0.000000
 # error=false
@@ -144,7 +144,7 @@
 #
 SET GLOBAL query_log_file="DRIZZLETEST_VARDIR/query.log";
 Checking attributes and values of query SELECT DATE(NOW());
-ts value matches OK
+start_ts value matches OK
 Checking attributes and values of query SELECT DATE(NOW());
 execution_time value matches OK
 lock_time value matches OK

=== modified file 'plugin/query_log/tests/r/thresholds.result'
--- plugin/query_log/tests/r/thresholds.result	2011-08-03 16:10:06 +0000
+++ plugin/query_log/tests/r/thresholds.result	2011-09-18 20:15:24 +0000
@@ -26,7 +26,7 @@
 Checking attributes and values of query SELECT SLEEP(0.5);
 arg value equals SELECT SLEEP(0.5); OK
 
-# 0000-00-00T00:00:00.000000
+# start_ts=0-00-00T00:00:00.000000
 # session_id=0 query_id=0 rows_examined=0 rows_sent=0 tmp_tables=0 warnings=0
 # execution_time=0.000000 lock_time=0.000000 session_time=0.000000
 # error=false
@@ -45,7 +45,7 @@
 Checking attributes and values of query SELECT 'one';
 arg value equals SELECT 'one'; OK
 
-# 0000-00-00T00:00:00.000000
+# start_ts=0-00-00T00:00:00.000000
 # session_id=0 query_id=0 rows_examined=0 rows_sent=0 tmp_tables=0 warnings=0
 # execution_time=0.000000 lock_time=0.000000 session_time=0.000000
 # error=false

=== modified file 'plugin/query_log/tests/samples/sample-event.log'
--- plugin/query_log/tests/samples/sample-event.log	2011-05-15 17:58:28 +0000
+++ plugin/query_log/tests/samples/sample-event.log	2011-09-18 20:15:24 +0000
@@ -1,4 +1,4 @@
-# 1234-56-78T90:12:34.567890
+# start_ts=1234-56-78T90:12:34.567890
 # session_id=1 query_id=2 rows_examined=3 rows_sent=4 tmp_tables=5 warnings=6
 # execution_time=7.890123 lock_time=4.567890 session_time=1.234567
 # error=false

=== modified file 'plugin/query_log/tests/t/file.test'
--- plugin/query_log/tests/t/file.test	2011-08-03 16:10:06 +0000
+++ plugin/query_log/tests/t/file.test	2011-09-18 20:15:24 +0000
@@ -100,7 +100,7 @@
 # YYYY-MM-DDTHH:MM:SS.uuuuuu.  We just check that the start of the ts
 # matches today's date.
 let $today= `SELECT DATE(NOW())`;
---exec $TOP_SRCDIR/plugin/query_log/tests/check-query-log-attribute.pl $DRIZZLETEST_VARDIR/query.log ts matches "^$today"
+--exec $TOP_SRCDIR/plugin/query_log/tests/check-query-log-attribute.pl $DRIZZLETEST_VARDIR/query.log start_ts matches "^$today"
 
 # The 3rd line of an event should be microsecond times like 1.123456
 --exec $TOP_SRCDIR/plugin/query_log/tests/check-query-log-attribute.pl $DRIZZLETEST_VARDIR/query.log execution_time,lock_time,session_time matches '\d\.\d{6}','\d\.\d{6}','\d\.\d{6}'