Merge lp:~laurynas-biveinis/percona-server/slow-log-fixes-5.5 into lp:percona-server/5.5

[Laurynas Biveinis]

Merge multiple slow query log fixes from 5.1.
http://jenkins.percona.com/job/percona-server-5.5-param/637/

[Stewart Smith (stewart)]

review: Approve

=== added file 'Percona-Server/mysql-test/include/log_cleanup.inc'
--- Percona-Server/mysql-test/include/log_cleanup.inc	1970-01-01 00:00:00 +0000
+++ Percona-Server/mysql-test/include/log_cleanup.inc	2013-01-21 06:27:51 +0000
@@ -0,0 +1,1 @@
+--remove_files_wildcard $MYSQLTEST_VARDIR *.slog
 
=== added file 'Percona-Server/mysql-test/include/log_start.inc'
--- Percona-Server/mysql-test/include/log_start.inc	1970-01-01 00:00:00 +0000
+++ Percona-Server/mysql-test/include/log_start.inc	2013-01-21 06:27:51 +0000
@@ -0,0 +1,11 @@
+--let slow_query_log_file_old=`SELECT Variable_value FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE Variable_name = 'slow_query_log_file';`
+--let slow_query_log_old=`SELECT Variable_value FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE Variable_name = 'slow_query_log';`
+--let log_output_old=`SELECT Variable_value FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE Variable_name = 'log_output';`
+--disable_query_log
+--let log_file_full_path = $MYSQLTEST_VARDIR/$log_file.slog
+SET GLOBAL slow_query_log=0;
+SET GLOBAL log_output=FILE;
+--echo [log_start.inc] $log_file
+EVAL SET GLOBAL slow_query_log_file="$log_file_full_path";
+SET GLOBAL slow_query_log=1;
+--enable_query_log
 
=== removed file 'Percona-Server/mysql-test/include/log_start.inc'
--- Percona-Server/mysql-test/include/log_start.inc	2012-04-18 23:25:38 +0000
+++ Percona-Server/mysql-test/include/log_start.inc	1970-01-01 00:00:00 +0000
@@ -1,16 +0,0 @@
---disable_query_log
---let log_file_full_path = $MYSQLTEST_VARDIR/$log_file
-SET @slow_query_log_old=@@slow_query_log;
-SET @slow_query_log_file_old= @@slow_query_log_file;
-SET GLOBAL slow_query_log=OFF;
-perl;
-  $log_file_full_path= $ENV{'log_file_full_path'};
-  unlink $log_file_full_path;
-  open(FILE, '>', $log_file_full_path)
-    or die "Cannot create log file $log_file_full_path, reason: $!";
-  close(FILE);
-EOF
---echo [log_start.inc] $log_file
-EVAL SET GLOBAL slow_query_log_file="$log_file_full_path";
-SET GLOBAL slow_query_log=ON;
---enable_query_log
 
=== added file 'Percona-Server/mysql-test/include/log_stop.inc'
--- Percona-Server/mysql-test/include/log_stop.inc	1970-01-01 00:00:00 +0000
+++ Percona-Server/mysql-test/include/log_stop.inc	2013-01-21 06:27:51 +0000
@@ -0,0 +1,7 @@
+--disable_query_log
+SET GLOBAL slow_query_log=0;
+--echo [log_stop.inc] $log_file
+EVAL SET GLOBAL log_output= $log_output_old;
+EVAL SET GLOBAL slow_query_log_file= "$slow_query_log_file_old";
+EVAL SET GLOBAL slow_query_log=      $slow_query_log_old;
+--enable_query_log
 
=== removed file 'Percona-Server/mysql-test/include/log_stop.inc'
--- Percona-Server/mysql-test/include/log_stop.inc	2012-04-18 23:25:38 +0000
+++ Percona-Server/mysql-test/include/log_stop.inc	1970-01-01 00:00:00 +0000
@@ -1,7 +0,0 @@
---disable_query_log
-FLUSH LOGS;
-SET GLOBAL slow_query_log=OFF;
---echo [log_stop.inc] $log_file
-SET GLOBAL slow_query_log_file= @slow_query_log_file_old;
-SET GLOBAL slow_query_log=      @slow_query_log_old;
---enable_query_log
 
=== removed file 'Percona-Server/mysql-test/include/percona_slow_extended_error_on_quit.inc'
--- Percona-Server/mysql-test/include/percona_slow_extended_error_on_quit.inc	2012-10-27 05:16:07 +0000
+++ Percona-Server/mysql-test/include/percona_slow_extended_error_on_quit.inc	1970-01-01 00:00:00 +0000
@@ -1,50 +0,0 @@
---echo ################################################################################
---let grep_pattern=CREATE
---source include/log_grep.inc
---let grep_pattern=INSERT
---source include/log_grep.inc
---let grep_pattern=SELECT
---source include/log_grep.inc
---let grep_pattern=Quit
---source include/log_grep.inc
---let grep_pattern=Last_errno: [^0]+
---source include/log_grep.inc
---let grep_pattern=Last_errno: 0
---source include/log_grep.inc
---let grep_pattern=Rows_sent: [^0]+
---source include/log_grep.inc
---let grep_pattern=Rows_sent: 0
---source include/log_grep.inc
---let grep_pattern=Rows_examined: [^0]+
---source include/log_grep.inc
---let grep_pattern=Rows_examined: 0
---source include/log_grep.inc
---let grep_pattern=Rows_affected: [^0]+
---source include/log_grep.inc
---let grep_pattern=Rows_affected: 0
---source include/log_grep.inc
---let grep_pattern=Rows_read: [^0]+
---source include/log_grep.inc
---let grep_pattern=Rows_read: 0
---source include/log_grep.inc
---let grep_pattern=Bytes_sent: [^0]+
---source include/log_grep.inc
---let grep_pattern=Bytes_sent: 0
---source include/log_grep.inc
---let grep_pattern=Tmp_tables: [^0]+
---source include/log_grep.inc
---let grep_pattern=Tmp_tables: 0
---source include/log_grep.inc
---let grep_pattern=Tmp_disk_tables: [^0]+
---source include/log_grep.inc
---let grep_pattern=Tmp_disk_tables: 0
---source include/log_grep.inc
---let grep_pattern=Tmp_table_sizes: [^0]+
---source include/log_grep.inc
---let grep_pattern=Tmp_table_sizes: 0
---source include/log_grep.inc
---let grep_pattern=# No InnoDB statistics available for this query
---source include/log_grep.inc
---let grep_pattern=# InnoDB_trx_id: 
---source include/log_grep.inc
---echo ################################################################################
 
=== added file 'Percona-Server/mysql-test/include/percona_slow_log_verbosity_grep.inc'
--- Percona-Server/mysql-test/include/percona_slow_log_verbosity_grep.inc	1970-01-01 00:00:00 +0000
+++ Percona-Server/mysql-test/include/percona_slow_log_verbosity_grep.inc	2013-01-21 06:27:51 +0000
@@ -0,0 +1,26 @@
+# Common extensions to the slow query log
+--let grep_pattern = ^# Thread_id: \d+  Schema: .+  Last_errno: \d+  Killed: \d+\$
+--source include/log_grep.inc
+--let grep_pattern = ^#.*Rows_affected: \d+  Rows_read: \d+\$
+--source include/log_grep.inc
+--let grep_pattern = ^# Bytes_sent: \d+.*\$
+--source include/log_grep.inc
+# InnoDB
+--let grep_pattern = ^# InnoDB_trx_id: \w+\$
+--source include/log_grep.inc
+# Query plan
+--let grep_pattern = ^# Bytes_sent: \d+  Tmp_tables: \d+  Tmp_disk_tables: \d+  Tmp_table_sizes: \d+\$
+--source include/log_grep.inc
+--let grep_pattern = ^# QC_Hit: (Yes|No)  Full_scan: (Yes|No)  Full_join: (Yes|No)  Tmp_table: (Yes|No)  Tmp_table_on_disk: (Yes|No)\$
+--source include/log_grep.inc
+--let grep_pattern = ^# Filesort: (Yes|No)  Filesort_on_disk: (Yes|No)  Merge_passes: \d+\$
+--source include/log_grep.inc
+# InnoDB
+--let grep_pattern = ^#   InnoDB_IO_r_ops: \d+  InnoDB_IO_r_bytes: \d+  InnoDB_IO_r_wait: \d*\.\d*\$
+--source include/log_grep.inc
+--let grep_pattern = ^#   InnoDB_rec_lock_wait: \d*\.\d*  InnoDB_queue_wait: \d*\.\d*\$
+--source include/log_grep.inc
+--let grep_pattern = ^#   InnoDB_pages_distinct: \d+\$
+--source include/log_grep.inc
+--let grep_pattern = ^# No InnoDB statistics available for this query\$
+--source include/log_grep.inc
 
=== modified file 'Percona-Server/mysql-test/include/percona_slow_query_log_rate.inc'
--- Percona-Server/mysql-test/include/percona_slow_query_log_rate.inc	2012-04-18 23:25:38 +0000
+++ Percona-Server/mysql-test/include/percona_slow_query_log_rate.inc	2013-01-21 06:27:51 +0000
@@ -1,31 +1,26 @@
---let wait_condition=SELECT COUNT(*) = 1 FROM INFORMATION_SCHEMA.PROCESSLIST;
 --connection default
---source include/log_start.inc
 
+--source include/count_sessions.inc
 --connect (connection_one,localhost,root,,)
 --connect (connection_two,localhost,root,,)
 --connect (connection_three,localhost,root,,)
 
+--source include/log_start.inc
+
 --let i=2
 --let k=1
 
 while($i)
 {
 --connection connection_one
-SET SESSION query_exec_time=1.1;
-eval SET SESSION query_exec_id=$k;
 inc $k;
 SELECT 'connection_one';
 
 --connection connection_two
-SET SESSION query_exec_time=1.1;
-eval SET SESSION query_exec_id=$k;
 inc $k;
 SELECT 'connection_two';
 
 --connection connection_three
-SET SESSION query_exec_time=1.1;
-eval SET SESSION query_exec_id=$k;
 inc $k;
 SELECT 'connection_three';
 
@@ -33,10 +28,10 @@
 }
 
 --connection default
+--source include/log_stop.inc
 --disconnect connection_one
 --disconnect connection_two
 --disconnect connection_three
---source include/wait_condition.inc
---source include/log_stop.inc
+--source include/wait_until_count_sessions.inc
 --let log_slow_rate_test=1
 --source include/log_grep.inc
 
=== modified file 'Percona-Server/mysql-test/r/mysqld--help-notwin.result'
--- Percona-Server/mysql-test/r/mysqld--help-notwin.result	2012-09-28 01:36:45 +0000
+++ Percona-Server/mysql-test/r/mysqld--help-notwin.result	2013-01-21 06:27:51 +0000
@@ -719,8 +719,8 @@
  Timestamp is printed for all records of the slow log even
  if they are same time.
  --slow-query-log-timestamp-precision=name 
- Log slow statements executed by stored procedure to the
- slow log if it is open. [second, microsecond]
+ Select the timestamp precision for use in the slow query
+ log.  [second, microsecond]
  --slow-query-log-use-global-control=name 
  Choose flags, wich always use the global variables.
  Multiple flags allowed in a comma-separated string.
 
=== added file 'Percona-Server/mysql-test/r/percona_bug643149.result'
--- Percona-Server/mysql-test/r/percona_bug643149.result	1970-01-01 00:00:00 +0000
+++ Percona-Server/mysql-test/r/percona_bug643149.result	2013-01-21 06:27:51 +0000
@@ -0,0 +1,21 @@
+SET @old_slow_query_log_file=@@global.slow_query_log_file;
+SET GLOBAL slow_query_log=on;
+SET LOCAL log_slow_verbosity='profiling';
+SET LOCAL long_query_time=0;
+SET GLOBAL slow_query_log_file='MYSQLTEST_VARDIR/percona_bug643149_slow.log';;
+SELECT 1;
+1
+1
+# User@Host: root[root] @ localhost []
+# Thread_id: X  Schema: test  Last_errno: X  Killed: X
+# Query_time: X.X  Lock_time: X.X  Rows_sent: X  Rows_examined: X  Rows_affected: X  Rows_read: X
+# Bytes_sent: X
+# Profile_starting: X.X Profile_starting_cpu: X.X Profile_Opening_tables: X.X Profile_Opening_tables_cpu: X.X Profile_query_end: X.X Profile_query_end_cpu: X.X Profile_closing_tables: X.X Profile_closing_tables_cpu: X.X Profile_freeing_items: X.X Profile_freeing_items_cpu: X.X Profile_logging_slow_query: X.X Profile_logging_slow_query_cpu: X.X 
+# Profile_total: X.X Profile_total_cpu: X.X 
+# User@Host: root[root] @ localhost []
+# Thread_id: X  Schema: test  Last_errno: X  Killed: X
+# Query_time: X.X  Lock_time: X.X  Rows_sent: X  Rows_examined: X  Rows_affected: X  Rows_read: X
+# Bytes_sent: X
+# Profile_starting: X.X Profile_starting_cpu: X.X Profile_checking_permissions: X.X Profile_checking_permissions_cpu: X.X Profile_Opening_tables: X.X Profile_Opening_tables_cpu: X.X Profile_init: X.X Profile_init_cpu: X.X Profile_optimizing: X.X Profile_optimizing_cpu: X.X Profile_executing: X.X Profile_executing_cpu: X.X Profile_end: X.X Profile_end_cpu: X.X Profile_query_end: X.X Profile_query_end_cpu: X.X Profile_closing_tables: X.X Profile_closing_tables_cpu: X.X Profile_freeing_items: X.X Profile_freeing_items_cpu: X.X Profile_logging_slow_query: X.X Profile_logging_slow_query_cpu: X.X 
+# Profile_total: X.X Profile_total_cpu: X.X 
+SET GLOBAL slow_query_log_file=@old_slow_query_log_file;
 
=== removed file 'Percona-Server/mysql-test/r/percona_bug643149.result'
--- Percona-Server/mysql-test/r/percona_bug643149.result	2012-04-18 23:25:38 +0000
+++ Percona-Server/mysql-test/r/percona_bug643149.result	1970-01-01 00:00:00 +0000
@@ -1,21 +0,0 @@
-SET @old_slow_query_log_file=@@global.slow_query_log_file;
-SET GLOBAL slow_query_log=on;
-SET LOCAL log_slow_verbosity='profiling';
-SET LOCAL long_query_time=0;
-SET GLOBAL slow_query_log_file='MYSQLTEST_VARDIR/percona_bug643149_slow.log';;
-SELECT 1;
-1
-1
-# User@Host: root[root] @ localhost []
-# Thread_id: X  Schema: test  Last_errno: X  Killed: X
-# Query_time: X.X  Lock_time: X.X  Rows_sent: X  Rows_examined: X  Rows_affected: X  Rows_read: X
-# Bytes_sent: X  Tmp_tables: X  Tmp_disk_tables: X  Tmp_table_sizes: X
-# Profile_starting: X.X Profile_starting_cpu: X.X Profile_Opening_tables: X.X Profile_Opening_tables_cpu: X.X Profile_query_end: X.X Profile_query_end_cpu: X.X Profile_closing_tables: X.X Profile_closing_tables_cpu: X.X Profile_freeing_items: X.X Profile_freeing_items_cpu: X.X Profile_logging_slow_query: X.X Profile_logging_slow_query_cpu: X.X 
-# Profile_total: X.X Profile_total_cpu: X.X 
-# User@Host: root[root] @ localhost []
-# Thread_id: X  Schema: test  Last_errno: X  Killed: X
-# Query_time: X.X  Lock_time: X.X  Rows_sent: X  Rows_examined: X  Rows_affected: X  Rows_read: X
-# Bytes_sent: X  Tmp_tables: X  Tmp_disk_tables: X  Tmp_table_sizes: X
-# Profile_starting: X.X Profile_starting_cpu: X.X Profile_checking_permissions: X.X Profile_checking_permissions_cpu: X.X Profile_Opening_tables: X.X Profile_Opening_tables_cpu: X.X Profile_init: X.X Profile_init_cpu: X.X Profile_optimizing: X.X Profile_optimizing_cpu: X.X Profile_executing: X.X Profile_executing_cpu: X.X Profile_end: X.X Profile_end_cpu: X.X Profile_query_end: X.X Profile_query_end_cpu: X.X Profile_closing_tables: X.X Profile_closing_tables_cpu: X.X Profile_freeing_items: X.X Profile_freeing_items_cpu: X.X Profile_logging_slow_query: X.X Profile_logging_slow_query_cpu: X.X 
-# Profile_total: X.X Profile_total_cpu: X.X 
-SET GLOBAL slow_query_log_file=@old_slow_query_log_file;
 
=== added file 'Percona-Server/mysql-test/r/percona_log_slow_admin_statements.result'
--- Percona-Server/mysql-test/r/percona_log_slow_admin_statements.result	1970-01-01 00:00:00 +0000
+++ Percona-Server/mysql-test/r/percona_log_slow_admin_statements.result	2013-01-21 06:27:51 +0000
@@ -0,0 +1,20 @@
+DROP TABLE IF EXISTS t1;
+CREATE TABLE t1 (a INT);
+SET SESSION min_examined_row_limit=0;
+SET SESSION long_query_time=0;
+SET GLOBAL log_slow_admin_statements=ON;
+[log_start.inc] percona_log_slow_admin_stmt_1
+ALTER TABLE t1 ADD INDEX a(a);
+[log_stop.inc] percona_log_slow_admin_stmt_1
+[log_grep.inc] file: percona_log_slow_admin_stmt_1 pattern: ALTER TABLE t1 ADD INDEX a\(a\);
+[log_grep.inc] lines:   1
+SET GLOBAL log_slow_admin_statements=OFF;
+[log_start.inc] percona_log_slow_admin_stmt_2
+ALTER TABLE t1 DROP INDEX a;
+[log_stop.inc] percona_log_slow_admin_stmt_2
+[log_grep.inc] file: percona_log_slow_admin_stmt_2 pattern: ALTER TABLE t1 DROP INDEX a;
+[log_grep.inc] lines:   0
+SET GLOBAL log_slow_admin_statements=default;
+SET SESSION long_query_time=default;
+SET SESSION min_examined_row_limit=default;
+DROP TABLE t1;
 
=== removed file 'Percona-Server/mysql-test/r/percona_log_slow_admin_statements.result'
--- Percona-Server/mysql-test/r/percona_log_slow_admin_statements.result	2012-04-18 23:25:38 +0000
+++ Percona-Server/mysql-test/r/percona_log_slow_admin_statements.result	1970-01-01 00:00:00 +0000
@@ -1,35 +0,0 @@
-SHOW GLOBAL VARIABLES like 'log_slow_admin_statements';
-Variable_name	Value
-log_slow_admin_statements	OFF
-SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements';
-VARIABLE_NAME	VARIABLE_VALUE
-LOG_SLOW_ADMIN_STATEMENTS	OFF
-SET GLOBAL log_slow_admin_statements=true;
-SHOW GLOBAL VARIABLES like 'log_slow_admin_statements';
-Variable_name	Value
-log_slow_admin_statements	ON
-SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements';
-VARIABLE_NAME	VARIABLE_VALUE
-LOG_SLOW_ADMIN_STATEMENTS	ON
-SET GLOBAL log_slow_admin_statements=false;
-SHOW GLOBAL VARIABLES like 'log_slow_admin_statements';
-Variable_name	Value
-log_slow_admin_statements	OFF
-SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements';
-VARIABLE_NAME	VARIABLE_VALUE
-LOG_SLOW_ADMIN_STATEMENTS	OFF
-SET GLOBAL log_slow_admin_statements=foo;
-ERROR 42000: Variable 'log_slow_admin_statements' can't be set to the value of 'foo'
-SHOW GLOBAL VARIABLES like 'log_slow_admin_statements';
-Variable_name	Value
-log_slow_admin_statements	OFF
-SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements';
-VARIABLE_NAME	VARIABLE_VALUE
-LOG_SLOW_ADMIN_STATEMENTS	OFF
-SET GLOBAL log_slow_admin_statements=default;
-SHOW GLOBAL VARIABLES like 'log_slow_admin_statements';
-Variable_name	Value
-log_slow_admin_statements	OFF
-SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements';
-VARIABLE_NAME	VARIABLE_VALUE
-LOG_SLOW_ADMIN_STATEMENTS	OFF
 
=== removed file 'Percona-Server/mysql-test/r/percona_log_slow_filter.result'
--- Percona-Server/mysql-test/r/percona_log_slow_filter.result	2012-04-18 23:25:38 +0000
+++ Percona-Server/mysql-test/r/percona_log_slow_filter.result	1970-01-01 00:00:00 +0000
@@ -1,16 +0,0 @@
-CREATE TABLE t(id INT PRIMARY KEY);
-INSERT INTO t VALUES(1);
-INSERT INTO t VALUES(2);
-INSERT INTO t VALUES(3);
-SET long_query_time=1;
-SET log_slow_filter=full_join;
-[log_start.inc] percona.slow_extended.log_slow_filter
-SET query_exec_time = 1.1;
-SELECT * FROM t AS t1, t AS t2;
-SET query_exec_time = default;
-[log_stop.inc] percona.slow_extended.log_slow_filter
-SET log_slow_filter=default;
-SET long_query_time=default;
-[log_grep.inc] file: percona.slow_extended.log_slow_filter pattern: Query_time
-[log_grep.inc] lines:   1
-DROP TABLE t;
 
=== added file 'Percona-Server/mysql-test/r/percona_log_slow_innodb.result'
--- Percona-Server/mysql-test/r/percona_log_slow_innodb.result	1970-01-01 00:00:00 +0000
+++ Percona-Server/mysql-test/r/percona_log_slow_innodb.result	2013-01-21 06:27:51 +0000
@@ -0,0 +1,42 @@
+DROP TABLE IF EXISTS t1, t2;
+CREATE TABLE t1(a INT) ENGINE=InnoDB;
+INSERT INTO t1 VALUE(1);
+CREATE TABLE t2(a INT) ENGINE=InnoDB;
+INSERT INTO t2 VALUE(1);
+SET SESSION min_examined_row_limit=0;
+SET SESSION long_query_time=0;
+SET @old_log_slow_verbosity := @@log_slow_verbosity;
+SET SESSION log_slow_verbosity='microtime,innodb';
+[log_start.inc] percona.slow_extended.innodb_0
+INSERT INTO t1 VALUES(2);
+INSERT INTO t2 VALUES(2);
+INSERT INTO t1 VALUES(3);
+SELECT 5;
+5
+5
+[log_stop.inc] percona.slow_extended.innodb_0
+LOCK TABLE t1 WRITE;
+[log_start.inc] percona.slow_extended.innodb_3
+LOCK TABLE t1 WRITE;
+SELECT SLEEP(5);
+SLEEP(5)
+0
+UNLOCK TABLES;
+[log_stop.inc] percona.slow_extended.innodb_3
+UNLOCK TABLES;
+BEGIN;
+SELECT * FROM t2 FOR UPDATE;
+a
+1
+2
+[log_start.inc] percona.slow_extended.innodb_4
+DELETE FROM t2 WHERE a=2;
+SELECT SLEEP(5);
+SLEEP(5)
+0
+COMMIT;
+[log_stop.inc] percona.slow_extended.innodb_4
+SET SESSION min_examined_row_limit=default;
+SET SESSION long_query_time=default;
+SET SESSION log_slow_verbosity=@old_log_slow_verbosity;
+DROP TABLE t1, t2;
 
=== added file 'Percona-Server/mysql-test/r/percona_log_slow_query_plan.result'
--- Percona-Server/mysql-test/r/percona_log_slow_query_plan.result	1970-01-01 00:00:00 +0000
+++ Percona-Server/mysql-test/r/percona_log_slow_query_plan.result	2013-01-21 06:27:51 +0000
@@ -0,0 +1,268 @@
+FLUSH STATUS;
+DROP TABLE IF EXISTS t1;
+CREATE TABLE t1(
+a INT NOT NULL AUTO_INCREMENT PRIMARY KEY,
+b INT) ENGINE=InnoDB;
+INSERT INTO t1 VALUES(NULL, 10), (NULL, 5);
+SET SESSION long_query_time=0;
+SET SESSION min_examined_row_limit=0;
+SET SESSION log_slow_verbosity='microtime,query_plan';
+EXPLAIN SELECT * FROM t1;
+id	select_type	table	type	possible_keys	key	key_len	ref	rows	Extra
+1	SIMPLE	t1	ALL	NULL	NULL	NULL	NULL	2	
+[log_start.inc] percona_slow_query_log.query_plan_0
+SELECT * FROM t1;
+a	b
+1	10
+2	5
+[log_stop.inc] percona_slow_query_log.query_plan_0
+[log_grep.inc] file: percona_slow_query_log.query_plan_0 pattern: ^# Filesort: No  Filesort_on_disk: No  Merge_passes: 0$
+[log_grep.inc] lines:   2
+EXPLAIN SELECT * FROM t1 ORDER BY b;
+id	select_type	table	type	possible_keys	key	key_len	ref	rows	Extra
+1	SIMPLE	t1	ALL	NULL	NULL	NULL	NULL	2	Using filesort
+[log_start.inc] percona_slow_query_log.query_plan_1
+SELECT * FROM t1 ORDER BY b;
+a	b
+2	5
+1	10
+[log_stop.inc] percona_slow_query_log.query_plan_1
+[log_grep.inc] file: percona_slow_query_log.query_plan_1 pattern: ^# Filesort: Yes  Filesort_on_disk: No  Merge_passes: 0$
+[log_grep.inc] lines:   1
+SET SESSION log_slow_filter='full_join,tmp_table,tmp_table_on_disk,filesort_on_disk';
+[log_start.inc] percona_slow_query_log.query_plan_1a
+SELECT * FROM t1 ORDER BY b;
+a	b
+2	5
+1	10
+[log_stop.inc] percona_slow_query_log.query_plan_1a
+[log_grep.inc] file: percona_slow_query_log.query_plan_1a pattern: ^# Filesort: Yes  Filesort_on_disk: No  Merge_passes: 0$
+[log_grep.inc] lines:   0
+SET SESSION log_slow_filter=default;
+SET SESSION sort_buffer_size=32804;
+CREATE TABLE t2 (a INT) ENGINE=InnoDB;
+INSERT INTO t2 VALUES (5), (16), (2), (17), (1);
+INSERT INTO t2 SELECT * FROM t2;
+INSERT INTO t2 SELECT * FROM t2;
+INSERT INTO t2 SELECT * FROM t2;
+INSERT INTO t2 SELECT * FROM t2;
+INSERT INTO t2 SELECT * FROM t2;
+INSERT INTO t2 SELECT * FROM t2;
+INSERT INTO t2 SELECT * FROM t2;
+INSERT INTO t2 SELECT * FROM t2;
+INSERT INTO t2 SELECT * FROM t2;
+SHOW SESSION STATUS LIKE 'Sort_merge_passes';
+Variable_name	Value
+Sort_merge_passes	0
+EXPLAIN SELECT * FROM t2 ORDER BY a;
+id	select_type	table	type	possible_keys	key	key_len	ref	rows	Extra
+1	SIMPLE	t2	ALL	NULL	NULL	NULL	NULL	ROWS	Using filesort
+[log_start.inc] percona_slow_query_log.query_plan_2
+SELECT * FROM t2 ORDER BY a;
+[log_stop.inc] percona_slow_query_log.query_plan_2
+[log_grep.inc] file: percona_slow_query_log.query_plan_2 pattern: ^# Filesort: Yes  Filesort_on_disk: Yes  Merge_passes: 1$
+[log_grep.inc] lines:   1
+SHOW SESSION STATUS LIKE 'Sort_merge_passes';
+Variable_name	Value
+Sort_merge_passes	1
+SET SESSION log_slow_filter='full_join,tmp_table,tmp_table_on_disk';
+[log_start.inc] percona_slow_query_log.query_plan_2a
+SELECT * FROM t2 ORDER BY a;
+[log_stop.inc] percona_slow_query_log.query_plan_2a
+[log_grep.inc] file: percona_slow_query_log.query_plan_2a pattern: ^# Filesort: Yes  Filesort_on_disk: Yes  Merge_passes: 1$
+[log_grep.inc] lines:   0
+SHOW SESSION STATUS LIKE 'Sort_merge_passes';
+Variable_name	Value
+Sort_merge_passes	2
+SET SESSION log_slow_filter=default;
+INSERT INTO t2 SELECT * FROM t2;
+INSERT INTO t2 SELECT * FROM t2;
+INSERT INTO t2 SELECT * FROM t2;
+INSERT INTO t2 SELECT * FROM t2;
+[log_start.inc] percona_slow_query_log.query_plan_3
+SELECT * FROM t2 ORDER BY a;
+[log_stop.inc] percona_slow_query_log.query_plan_3
+[log_grep.inc] file: percona_slow_query_log.query_plan_3 pattern: ^# Filesort: Yes  Filesort_on_disk: Yes  Merge_passes: 4$
+[log_grep.inc] lines:   1
+SHOW SESSION STATUS LIKE 'Sort_merge_passes';
+Variable_name	Value
+Sort_merge_passes	6
+SET SESSION sort_buffer_size=default;
+SHOW SESSION STATUS LIKE 'Select_scan';
+Variable_name	Value
+Select_scan	37
+[log_start.inc] percona_slow_query_log.query_plan_4
+SELECT * FROM t1 WHERE a=1;
+a	b
+1	10
+[log_stop.inc] percona_slow_query_log.query_plan_4
+[log_grep.inc] file: percona_slow_query_log.query_plan_4 pattern: ^#.*Full_scan: No.*$
+[log_grep.inc] lines:   2
+SHOW SESSION STATUS LIKE 'Select_scan';
+Variable_name	Value
+Select_scan	40
+[log_start.inc] percona_slow_query_log.query_plan_5
+SELECT COUNT(*) FROM t1;
+COUNT(*)
+2
+[log_stop.inc] percona_slow_query_log.query_plan_5
+[log_grep.inc] file: percona_slow_query_log.query_plan_5 pattern: ^#.*Full_scan: Yes.*$
+[log_grep.inc] lines:   1
+SHOW SESSION STATUS LIKE 'Select_scan';
+Variable_name	Value
+Select_scan	44
+SET SESSION log_slow_filter='full_join,tmp_table,tmp_table_on_disk,filesort,filesort_on_disk';
+[log_start.inc] percona_slow_query_log.query_plan_5a
+SELECT COUNT(*) FROM t1;
+COUNT(*)
+2
+[log_stop.inc] percona_slow_query_log.query_plan_5a
+[log_grep.inc] file: percona_slow_query_log.query_plan_5a pattern: ^#.*Full_scan: Yes.*$
+[log_grep.inc] lines:   0
+SHOW SESSION STATUS LIKE 'Select_scan';
+Variable_name	Value
+Select_scan	48
+SET SESSION log_slow_filter=default;
+CREATE TABLE t3(a INT NOT NULL AUTO_INCREMENT PRIMARY KEY) ENGINE=InnoDB;
+INSERT INTO t3 VALUES (1), (2), (3);
+SHOW SESSION STATUS LIKE 'Select_full_join';
+Variable_name	Value
+Select_full_join	0
+[log_start.inc] percona_slow_query_log.query_plan_6
+SELECT COUNT(*) FROM t1, t3 WHERE t1.a = t3.a;
+COUNT(*)
+2
+[log_stop.inc] percona_slow_query_log.query_plan_6
+[log_grep.inc] file: percona_slow_query_log.query_plan_6 pattern: ^#.*Full_join: No.*$
+[log_grep.inc] lines:   2
+SHOW SESSION STATUS LIKE 'Select_full_join';
+Variable_name	Value
+Select_full_join	0
+[log_start.inc] percona_slow_query_log.query_plan_7
+SELECT COUNT(*) FROM t1, t2 WHERE t1.b = t2.a;
+COUNT(*)
+8192
+[log_stop.inc] percona_slow_query_log.query_plan_7
+[log_grep.inc] file: percona_slow_query_log.query_plan_7 pattern: ^#.*Full_join: Yes.*$
+[log_grep.inc] lines:   1
+SHOW SESSION STATUS LIKE 'Select_full_join';
+Variable_name	Value
+Select_full_join	1
+SET SESSION log_slow_filter='tmp_table,tmp_table_on_disk,filesort,filesort_on_disk';
+[log_start.inc] percona_slow_query_log.query_plan_7a
+SELECT COUNT(*) FROM t1, t2 WHERE t1.b = t2.a;
+COUNT(*)
+8192
+[log_stop.inc] percona_slow_query_log.query_plan_7a
+[log_grep.inc] file: percona_slow_query_log.query_plan_7a pattern: ^#.*Full_join: Yes.*$
+[log_grep.inc] lines:   0
+SHOW SESSION STATUS LIKE 'Select_full_join';
+Variable_name	Value
+Select_full_join	2
+SET SESSION log_slow_filter=default;
+SHOW SESSION STATUS LIKE 'Created_tmp_tables';
+Variable_name	Value
+Created_tmp_tables	49
+SHOW SESSION STATUS LIKE 'Created_tmp_disk_tables';
+Variable_name	Value
+Created_tmp_disk_tables	0
+EXPLAIN SELECT COUNT(*) FROM t1;
+id	select_type	table	type	possible_keys	key	key_len	ref	rows	Extra
+1	SIMPLE	t1	index	NULL	PRIMARY	4	NULL	2	Using index
+[log_start.inc] percona_slow_query_log.query_plan_8
+SELECT COUNT(*) FROM t1;
+COUNT(*)
+2
+[log_stop.inc] percona_slow_query_log.query_plan_8
+[log_grep.inc] file: percona_slow_query_log.query_plan_8 pattern: ^#.*Tmp_tables: 0  Tmp_disk_tables: 0  Tmp_table_sizes: 0$
+[log_grep.inc] lines:   2
+[log_grep.inc] file: percona_slow_query_log.query_plan_8 pattern: ^#.*Tmp_table: No  Tmp_table_on_disk: No$
+[log_grep.inc] lines:   2
+SHOW SESSION STATUS LIKE 'Created_tmp_tables';
+Variable_name	Value
+Created_tmp_tables	52
+SHOW SESSION STATUS LIKE 'Created_tmp_disk_tables';
+Variable_name	Value
+Created_tmp_disk_tables	0
+EXPLAIN SELECT COUNT(*) FROM t1, t3 WHERE t1.a = t3.a GROUP BY t3.a;
+id	select_type	table	type	possible_keys	key	key_len	ref	rows	Extra
+1	SIMPLE	t1	index	PRIMARY	PRIMARY	4	NULL	2	Using index; Using temporary; Using filesort
+1	SIMPLE	t3	eq_ref	PRIMARY	PRIMARY	4	test.t1.a	1	Using index
+[log_start.inc] percona_slow_query_log.query_plan_9
+SELECT COUNT(*) FROM t1, t3 WHERE t1.a = t3.a GROUP BY t3.a;
+COUNT(*)
+1
+1
+[log_stop.inc] percona_slow_query_log.query_plan_9
+[log_grep.inc] file: percona_slow_query_log.query_plan_9 pattern: ^#.*Tmp_tables: 1  Tmp_disk_tables: 0  Tmp_table_sizes: [1-9][0-9]*$
+[log_grep.inc] lines:   1
+[log_grep.inc] file: percona_slow_query_log.query_plan_9 pattern: ^#.*Tmp_table: Yes  Tmp_table_on_disk: No$
+[log_grep.inc] lines:   1
+SHOW SESSION STATUS LIKE 'Created_tmp_tables';
+Variable_name	Value
+Created_tmp_tables	56
+SHOW SESSION STATUS LIKE 'Created_tmp_disk_tables';
+Variable_name	Value
+Created_tmp_disk_tables	0
+SET SESSION log_slow_filter='full_join,tmp_table_on_disk,filesort_on_disk';
+[log_start.inc] percona_slow_query_log.query_plan_9a
+SELECT COUNT(*) FROM t1, t3 WHERE t1.a = t3.a GROUP BY t3.a;
+COUNT(*)
+1
+1
+[log_stop.inc] percona_slow_query_log.query_plan_9a
+[log_grep.inc] file: percona_slow_query_log.query_plan_9a pattern: ^#.*Tmp_tables: 1  Tmp_disk_tables: 0  Tmp_table_sizes: [1-9][0-9]*$
+[log_grep.inc] lines:   0
+[log_grep.inc] file: percona_slow_query_log.query_plan_9a pattern: ^#.*Tmp_table: Yes  Tmp_table_on_disk: No$
+[log_grep.inc] lines:   0
+SHOW SESSION STATUS LIKE 'Created_tmp_tables';
+Variable_name	Value
+Created_tmp_tables	60
+SHOW SESSION STATUS LIKE 'Created_tmp_disk_tables';
+Variable_name	Value
+Created_tmp_disk_tables	0
+SET SESSION log_slow_filter=default;
+CREATE TABLE t4(a INT NOT NULL AUTO_INCREMENT PRIMARY KEY, b TEXT) ENGINE=InnoDB;
+INSERT INTO t4 VALUES (1, "aaa"), (2, "bbb"), (3, "ccc");
+EXPLAIN SELECT COUNT(*) FROM t1, t4 WHERE t1.a = t4.a GROUP BY t4.a;
+id	select_type	table	type	possible_keys	key	key_len	ref	rows	Extra
+1	SIMPLE	t1	index	PRIMARY	PRIMARY	4	NULL	2	Using index; Using temporary; Using filesort
+1	SIMPLE	t4	eq_ref	PRIMARY	PRIMARY	4	test.t1.a	1	Using index
+[log_start.inc] percona_slow_query_log.query_plan_10
+SELECT COUNT(*) FROM t1, t4 WHERE t1.a = t4.a GROUP BY t4.b;
+COUNT(*)
+1
+1
+[log_stop.inc] percona_slow_query_log.query_plan_10
+[log_grep.inc] file: percona_slow_query_log.query_plan_10 pattern: ^#.*Tmp_tables: 1  Tmp_disk_tables: 1  Tmp_table_sizes: [1-9][0-9]*$
+[log_grep.inc] lines:   1
+[log_grep.inc] file: percona_slow_query_log.query_plan_10 pattern: ^#.*Tmp_table: Yes  Tmp_table_on_disk: Yes$
+[log_grep.inc] lines:   1
+SHOW SESSION STATUS LIKE 'Created_tmp_tables';
+Variable_name	Value
+Created_tmp_tables	64
+SHOW SESSION STATUS LIKE 'Created_tmp_disk_tables';
+Variable_name	Value
+Created_tmp_disk_tables	1
+SET SESSION log_slow_filter='full_join,filesort_on_disk';
+[log_start.inc] percona_slow_query_log.query_plan_10a
+SELECT COUNT(*) FROM t1, t4 WHERE t1.a = t4.a GROUP BY t4.b;
+COUNT(*)
+1
+1
+[log_stop.inc] percona_slow_query_log.query_plan_10a
+[log_grep.inc] file: percona_slow_query_log.query_plan_10a pattern: ^#.*Tmp_tables: 1  Tmp_disk_tables: 1  Tmp_table_sizes: [1-9][0-9]*$
+[log_grep.inc] lines:   0
+[log_grep.inc] file: percona_slow_query_log.query_plan_10a pattern: ^#.*Tmp_table: Yes  Tmp_table_on_disk: Yes$
+[log_grep.inc] lines:   0
+SHOW SESSION STATUS LIKE 'Created_tmp_tables';
+Variable_name	Value
+Created_tmp_tables	68
+SHOW SESSION STATUS LIKE 'Created_tmp_disk_tables';
+Variable_name	Value
+Created_tmp_disk_tables	2
+SET SESSION log_slow_filter=default;
+SET SESSION long_query_time=default;
+SET SESSION min_examined_row_limit=default;
+SET SESSION log_slow_verbosity=default;
+DROP TABLE t1, t2, t3, t4;
 
=== added file 'Percona-Server/mysql-test/r/percona_log_slow_query_plan_qc.result'
--- Percona-Server/mysql-test/r/percona_log_slow_query_plan_qc.result	1970-01-01 00:00:00 +0000
+++ Percona-Server/mysql-test/r/percona_log_slow_query_plan_qc.result	2013-01-21 06:27:51 +0000
@@ -0,0 +1,46 @@
+FLUSH STATUS;
+SET SESSION min_examined_row_limit=0;
+DROP TABLE IF EXISTS t1;
+CREATE TABLE t1 (a INT) ENGINE=InnoDB;
+INSERT INTO t1 VALUE(5);
+SET SESSION query_cache_type=1;
+SET GLOBAL query_cache_size=1355776;
+SET SESSION long_query_time=0;
+SET SESSION log_slow_verbosity='microtime,query_plan';
+[log_start.inc] percona_slow_query_log.query_plan_qc_1
+SELECT * FROM t1;
+a
+5
+[log_stop.inc] percona_slow_query_log.query_plan_qc_1
+[log_grep.inc] file: percona_slow_query_log.query_plan_qc_1 pattern: ^# QC_Hit: No.*$
+[log_grep.inc] lines:   2
+SHOW STATUS LIKE 'Qcache_hits';
+Variable_name	Value
+Qcache_hits	0
+[log_start.inc] percona_slow_query_log.query_plan_qc_2
+SELECT * FROM t1;
+a
+5
+[log_stop.inc] percona_slow_query_log.query_plan_qc_2
+[log_grep.inc] file: percona_slow_query_log.query_plan_qc_2 pattern: ^# QC_Hit: Yes.*$
+[log_grep.inc] lines:   1
+SHOW STATUS LIKE 'Qcache_hits';
+Variable_name	Value
+Qcache_hits	1
+SET SESSION log_slow_filter='full_join,tmp_table,tmp_table_on_disk,filesort,filesort_on_disk';
+[log_start.inc] percona_slow_query_log.query_plan_qc_3
+SELECT * FROM t1 WHERE a > 5;
+a
+[log_stop.inc] percona_slow_query_log.query_plan_qc_3
+[log_grep.inc] file: percona_slow_query_log.query_plan_qc_3 pattern: ^# QC_Hit: No.*$
+[log_grep.inc] lines:   0
+SHOW STATUS LIKE 'Qcache_hits';
+Variable_name	Value
+Qcache_hits	1
+SET SESSION log_slow_filter=default;
+SET SESSION long_query_time=default;
+SET SESSION log_slow_verbosity=default;
+SET SESSION query_cache_type=default;
+SET GLOBAL query_cache_size=default;
+SET SESSION min_examined_row_limit=default;
+DROP TABLE t1;
 
=== added file 'Percona-Server/mysql-test/r/percona_log_slow_slave_statements-innodb.result'
--- Percona-Server/mysql-test/r/percona_log_slow_slave_statements-innodb.result	1970-01-01 00:00:00 +0000
+++ Percona-Server/mysql-test/r/percona_log_slow_slave_statements-innodb.result	2013-01-21 06:27:51 +0000
@@ -0,0 +1,28 @@
+include/master-slave.inc
+[connection master]
+SET SESSION min_examined_row_limit=0;
+DROP TABLE IF EXISTS t;
+CREATE TABLE t(id INT,data CHAR(30)) ENGINE=InnoDB;
+INSERT INTO t VALUES
+(1,"aaaaabbbbbcccccdddddeeeeefffff"),
+(2,"aaaaabbbbbcccccdddddeeeeefffff"),
+(3,"aaaaabbbbbcccccdddddeeeeefffff"),
+(4,"aaaaabbbbbcccccdddddeeeeefffff"),
+(5,"aaaaabbbbbcccccdddddeeeeefffff");
+INSERT INTO t SELECT t2.id,t2.data from t as t1, t as t2;
+INSERT INTO t SELECT t2.id,t2.data from t as t1, t as t2;
+SET GLOBAL long_query_time=0;
+SET GLOBAL log_slow_slave_statements=TRUE;
+SET GLOBAL log_slow_verbosity='innodb';
+include/restart_slave.inc
+[log_start.inc] percona.slow_extended.log_slow_slave_statements-innodb
+INSERT INTO t SELECT t.id,t.data from t;
+[log_stop.inc] percona.slow_extended.log_slow_slave_statements-innodb
+[log_grep.inc] file: percona.slow_extended.log_slow_slave_statements-innodb pattern: InnoDB_IO_r_ops
+[log_grep.inc] lines:   1
+DROP TABLE t;
+SET GLOBAL long_query_time=default;
+SET GLOBAL log_slow_slave_statements=default;
+SET GLOBAL log_slow_verbosity=default;
+SET SESSION min_examined_row_limit=default;
+include/rpl_end.inc
 
=== removed file 'Percona-Server/mysql-test/r/percona_log_slow_slave_statements-innodb.result'
--- Percona-Server/mysql-test/r/percona_log_slow_slave_statements-innodb.result	2012-04-18 23:25:38 +0000
+++ Percona-Server/mysql-test/r/percona_log_slow_slave_statements-innodb.result	1970-01-01 00:00:00 +0000
@@ -1,19 +0,0 @@
-include/master-slave.inc
-[connection master]
-DROP TABLE IF EXISTS t;
-CREATE TABLE t(id INT,data CHAR(30)) ENGINE=InnoDB;
-INSERT INTO t VALUES
-(1,"aaaaabbbbbcccccdddddeeeeefffff"),
-(2,"aaaaabbbbbcccccdddddeeeeefffff"),
-(3,"aaaaabbbbbcccccdddddeeeeefffff"),
-(4,"aaaaabbbbbcccccdddddeeeeefffff"),
-(5,"aaaaabbbbbcccccdddddeeeeefffff");
-INSERT INTO t SELECT t2.id,t2.data from t as t1, t as t2;
-INSERT INTO t SELECT t2.id,t2.data from t as t1, t as t2;
-[log_start.inc] percona.slow_extended.log_slow_slave_statements-innodb
-INSERT INTO t SELECT t.id,t.data from t;
-[log_stop.inc] percona.slow_extended.log_slow_slave_statements-innodb
-[log_grep.inc] file: percona.slow_extended.log_slow_slave_statements-innodb pattern: InnoDB_IO_r_ops
-[log_grep.inc] lines:   1
-DROP TABLE t;
-include/rpl_end.inc
 
=== added file 'Percona-Server/mysql-test/r/percona_log_slow_slave_statements.result'
--- Percona-Server/mysql-test/r/percona_log_slow_slave_statements.result	1970-01-01 00:00:00 +0000
+++ Percona-Server/mysql-test/r/percona_log_slow_slave_statements.result	2013-01-21 06:27:51 +0000
@@ -0,0 +1,30 @@
+include/master-slave.inc
+[connection master]
+DROP TABLE IF EXISTS t;
+CREATE TABLE t(id INT) ENGINE=InnoDB;
+SET GLOBAL min_examined_row_limit=0;
+SET GLOBAL long_query_time=0;
+SET GLOBAL log_slow_slave_statements=OFF;
+include/restart_slave.inc
+[log_start.inc] percona.slow_extended.log_slow_slave_statements
+INSERT INTO t VALUES (1);
+SET GLOBAL log_slow_slave_statements=ON;
+BEGIN;
+INSERT INTO t VALUES (2);
+COMMIT;
+SET GLOBAL log_slow_slave_statements=OFF;
+INSERT INTO t VALUES (3);
+[log_stop.inc] percona.slow_extended.log_slow_slave_statements
+[log_grep.inc] file: percona.slow_extended.log_slow_slave_statements pattern: INSERT INTO t VALUES \(1\)
+[log_grep.inc] lines:   0
+[log_grep.inc] file: percona.slow_extended.log_slow_slave_statements pattern: INSERT INTO t VALUES \(2\)
+[log_grep.inc] lines:   1
+[log_grep.inc] file: percona.slow_extended.log_slow_slave_statements pattern: INSERT INTO t VALUES \(3\)
+[log_grep.inc] lines:   0
+[log_grep.inc] file: percona.slow_extended.log_slow_slave_statements pattern: ^# User@Host: \[SQL_SLAVE\] @  \[\]
+[log_grep.inc] lines:   2
+DROP TABLE t;
+SET GLOBAL log_slow_slave_statements=default;
+SET GLOBAL long_query_time=default;
+SET GLOBAL min_examined_row_limit=default;
+include/rpl_end.inc
 
=== removed file 'Percona-Server/mysql-test/r/percona_log_slow_slave_statements.result'
--- Percona-Server/mysql-test/r/percona_log_slow_slave_statements.result	2012-04-18 23:25:38 +0000
+++ Percona-Server/mysql-test/r/percona_log_slow_slave_statements.result	1970-01-01 00:00:00 +0000
@@ -1,45 +0,0 @@
-include/master-slave.inc
-[connection master]
-DROP TABLE IF EXISTS t;
-CREATE TABLE t(id INT);
-[log_start.inc] percona.slow_extended.log_slow_slave_statements
-LINE 1
-LOG_SLOW_SLAVE_STATAMENTS is OFF
-LOG_SLOW_SLAVE_STATEMENTS=ON
-LOG_SLOW_SLAVE_STATAMENTS is ON
-LINE 2
-include/restart_slave.inc
-LOG_SLOW_SLAVE_STATAMENTS is ON
-LINE 3
-LOG_SLOW_SLAVE_STATAMENTS is ON
-LOG_SLOW_SLAVE_STATEMENTS=OFF
-LOG_SLOW_SLAVE_STATAMENTS is OFF
-LINE 4
-include/restart_slave.inc
-LOG_SLOW_SLAVE_STATAMENTS is OFF
-LINE 5
-LOG_SLOW_SLAVE_STATAMENTS is OFF
-LOG_SLOW_SLAVE_STATEMENTS=ON
-LOG_SLOW_SLAVE_STATAMENTS is ON
-LINE 6
-include/restart_slave.inc
-LOG_SLOW_SLAVE_STATAMENTS is ON
-LINE 7
-[log_stop.inc] percona.slow_extended.log_slow_slave_statements
-SET GLOBAL log_slow_slave_statements=default;
-[log_grep.inc] file: percona.slow_extended.log_slow_slave_statements pattern: INSERT INTO t VALUES \(1\)
-[log_grep.inc] lines:   0
-[log_grep.inc] file: percona.slow_extended.log_slow_slave_statements pattern: INSERT INTO t VALUES \(2\)
-[log_grep.inc] lines:   0
-[log_grep.inc] file: percona.slow_extended.log_slow_slave_statements pattern: INSERT INTO t VALUES \(3\)
-[log_grep.inc] lines:   1
-[log_grep.inc] file: percona.slow_extended.log_slow_slave_statements pattern: INSERT INTO t VALUES \(4\)
-[log_grep.inc] lines:   0
-[log_grep.inc] file: percona.slow_extended.log_slow_slave_statements pattern: INSERT INTO t VALUES \(5\)
-[log_grep.inc] lines:   0
-[log_grep.inc] file: percona.slow_extended.log_slow_slave_statements pattern: INSERT INTO t VALUES \(6\)
-[log_grep.inc] lines:   0
-[log_grep.inc] file: percona.slow_extended.log_slow_slave_statements pattern: INSERT INTO t VALUES \(7\)
-[log_grep.inc] lines:   1
-DROP TABLE t;
-include/rpl_end.inc
 
=== added file 'Percona-Server/mysql-test/r/percona_log_slow_sp_statements.result'
--- Percona-Server/mysql-test/r/percona_log_slow_sp_statements.result	1970-01-01 00:00:00 +0000
+++ Percona-Server/mysql-test/r/percona_log_slow_sp_statements.result	2013-01-21 06:27:51 +0000
@@ -0,0 +1,29 @@
+DROP PROCEDURE IF EXISTS test_f;
+SET SESSION min_examined_row_limit=0;
+SET SESSION long_query_time=0;
+SET SESSION query_cache_type=0;
+CREATE PROCEDURE test_f()
+BEGIN
+SELECT 1;
+END^
+SET GLOBAL log_slow_sp_statements=ON;
+[log_start.inc] percona.slow_extended.sp1
+CALL test_f();
+1
+1
+[log_stop.inc] percona.slow_extended.sp1
+[log_grep.inc] file: percona.slow_extended.sp1 pattern: SELECT 1;
+[log_grep.inc] lines:   1
+SET GLOBAL log_slow_sp_statements=OFF;
+[log_start.inc] percona.slow_extended.sp2
+CALL test_f();
+1
+1
+[log_stop.inc] percona.slow_extended.sp2
+[log_grep.inc] file: percona.slow_extended.sp2 pattern: SELECT 1;
+[log_grep.inc] lines:   0
+DROP PROCEDURE test_f;
+SET GLOBAL log_slow_sp_statements=default;
+SET SESSION long_query_time=default;
+SET SESSION min_examined_row_limit=default;
+SET SESSION query_cache_type=default;
 
=== removed file 'Percona-Server/mysql-test/r/percona_log_slow_sp_statements.result'
--- Percona-Server/mysql-test/r/percona_log_slow_sp_statements.result	2012-04-18 23:25:38 +0000
+++ Percona-Server/mysql-test/r/percona_log_slow_sp_statements.result	1970-01-01 00:00:00 +0000
@@ -1,25 +0,0 @@
-SET long_query_time=1;
-SET GLOBAL log_slow_sp_statements=ON;
-SET SESSION query_exec_time=0.1;
-[log_start.inc] percona.slow_extended.log_slow_sp_statements
-CREATE PROCEDURE test_f()
-BEGIN
-SET SESSION query_exec_time=1.1; SELECT 1;
-SET SESSION query_exec_time=2.1; SELECT 1;
-SET SESSION query_exec_time=3.1; SELECT 1;
-SET SESSION query_exec_time=0.1;
-END^
-CALL test_f();
-1
-1
-1
-1
-1
-1
-[log_stop.inc] percona.slow_extended.log_slow_sp_statements
-SET SESSION query_exec_time=default;
-SET GLOBAL log_slow_sp_statements=default;
-SET long_query_time=default;
-[log_grep.inc] file: percona.slow_extended.log_slow_sp_statements pattern: Query_time
-[log_grep.inc] lines:   3
-DROP PROCEDURE test_f;
 
=== added file 'Percona-Server/mysql-test/r/percona_log_slow_verbosity.result'
--- Percona-Server/mysql-test/r/percona_log_slow_verbosity.result	1970-01-01 00:00:00 +0000
+++ Percona-Server/mysql-test/r/percona_log_slow_verbosity.result	2013-01-21 06:27:51 +0000
@@ -0,0 +1,118 @@
+DROP TABLE IF EXISTS t1;
+CREATE TABLE t1(a INT) ENGINE=InnoDB;
+SET SESSION min_examined_row_limit=0;
+SET SESSION long_query_time=0;
+SET SESSION log_slow_verbosity='microtime,innodb,query_plan';
+[log_start.inc] percona.slow_extended.log_slow_verbosity_0
+INSERT INTO t1 VALUE(0);
+[log_stop.inc] percona.slow_extended.log_slow_verbosity_0
+log_slow_verbosity='microtime,innodb,query_plan':
+[log_grep.inc] file: percona.slow_extended.log_slow_verbosity_0 pattern: ^# Thread_id: \d+  Schema: .+  Last_errno: \d+  Killed: \d+$
+[log_grep.inc] lines:   2
+[log_grep.inc] file: percona.slow_extended.log_slow_verbosity_0 pattern: ^#.*Rows_affected: \d+  Rows_read: \d+$
+[log_grep.inc] lines:   2
+[log_grep.inc] file: percona.slow_extended.log_slow_verbosity_0 pattern: ^# Bytes_sent: \d+.*$
+[log_grep.inc] lines:   2
+[log_grep.inc] file: percona.slow_extended.log_slow_verbosity_0 pattern: ^# InnoDB_trx_id: \w+$
+[log_grep.inc] lines:   1
+[log_grep.inc] file: percona.slow_extended.log_slow_verbosity_0 pattern: ^# Bytes_sent: \d+  Tmp_tables: \d+  Tmp_disk_tables: \d+  Tmp_table_sizes: \d+$
+[log_grep.inc] lines:   2
+[log_grep.inc] file: percona.slow_extended.log_slow_verbosity_0 pattern: ^# QC_Hit: (Yes|No)  Full_scan: (Yes|No)  Full_join: (Yes|No)  Tmp_table: (Yes|No)  Tmp_table_on_disk: (Yes|No)$
+[log_grep.inc] lines:   2
+[log_grep.inc] file: percona.slow_extended.log_slow_verbosity_0 pattern: ^# Filesort: (Yes|No)  Filesort_on_disk: (Yes|No)  Merge_passes: \d+$
+[log_grep.inc] lines:   2
+[log_grep.inc] file: percona.slow_extended.log_slow_verbosity_0 pattern: ^#   InnoDB_IO_r_ops: \d+  InnoDB_IO_r_bytes: \d+  InnoDB_IO_r_wait: \d*\.\d*$
+[log_grep.inc] lines:   1
+[log_grep.inc] file: percona.slow_extended.log_slow_verbosity_0 pattern: ^#   InnoDB_rec_lock_wait: \d*\.\d*  InnoDB_queue_wait: \d*\.\d*$
+[log_grep.inc] lines:   1
+[log_grep.inc] file: percona.slow_extended.log_slow_verbosity_0 pattern: ^#   InnoDB_pages_distinct: \d+$
+[log_grep.inc] lines:   1
+[log_grep.inc] file: percona.slow_extended.log_slow_verbosity_0 pattern: ^# No InnoDB statistics available for this query$
+[log_grep.inc] lines:   1
+SET SESSION log_slow_verbosity='microtime,innodb,query_plan';
+[log_start.inc] percona.slow_extended.log_slow_verbosity_1
+SELECT 1;
+1
+1
+[log_stop.inc] percona.slow_extended.log_slow_verbosity_1
+log_slow_verbosity='microtime,innodb,query_plan':
+[log_grep.inc] file: percona.slow_extended.log_slow_verbosity_1 pattern: ^# Thread_id: \d+  Schema: .+  Last_errno: \d+  Killed: \d+$
+[log_grep.inc] lines:   2
+[log_grep.inc] file: percona.slow_extended.log_slow_verbosity_1 pattern: ^#.*Rows_affected: \d+  Rows_read: \d+$
+[log_grep.inc] lines:   2
+[log_grep.inc] file: percona.slow_extended.log_slow_verbosity_1 pattern: ^# Bytes_sent: \d+.*$
+[log_grep.inc] lines:   2
+[log_grep.inc] file: percona.slow_extended.log_slow_verbosity_1 pattern: ^# InnoDB_trx_id: \w+$
+[log_grep.inc] lines:   0
+[log_grep.inc] file: percona.slow_extended.log_slow_verbosity_1 pattern: ^# Bytes_sent: \d+  Tmp_tables: \d+  Tmp_disk_tables: \d+  Tmp_table_sizes: \d+$
+[log_grep.inc] lines:   2
+[log_grep.inc] file: percona.slow_extended.log_slow_verbosity_1 pattern: ^# QC_Hit: (Yes|No)  Full_scan: (Yes|No)  Full_join: (Yes|No)  Tmp_table: (Yes|No)  Tmp_table_on_disk: (Yes|No)$
+[log_grep.inc] lines:   2
+[log_grep.inc] file: percona.slow_extended.log_slow_verbosity_1 pattern: ^# Filesort: (Yes|No)  Filesort_on_disk: (Yes|No)  Merge_passes: \d+$
+[log_grep.inc] lines:   2
+[log_grep.inc] file: percona.slow_extended.log_slow_verbosity_1 pattern: ^#   InnoDB_IO_r_ops: \d+  InnoDB_IO_r_bytes: \d+  InnoDB_IO_r_wait: \d*\.\d*$
+[log_grep.inc] lines:   0
+[log_grep.inc] file: percona.slow_extended.log_slow_verbosity_1 pattern: ^#   InnoDB_rec_lock_wait: \d*\.\d*  InnoDB_queue_wait: \d*\.\d*$
+[log_grep.inc] lines:   0
+[log_grep.inc] file: percona.slow_extended.log_slow_verbosity_1 pattern: ^#   InnoDB_pages_distinct: \d+$
+[log_grep.inc] lines:   0
+[log_grep.inc] file: percona.slow_extended.log_slow_verbosity_1 pattern: ^# No InnoDB statistics available for this query$
+[log_grep.inc] lines:   2
+SET log_slow_verbosity='microtime';
+[log_start.inc] percona.slow_extended.log_slow_verbosity_2
+INSERT INTO t1 VALUE(1);
+[log_stop.inc] percona.slow_extended.log_slow_verbosity_2
+log_slow_verbosity='microtime':
+[log_grep.inc] file: percona.slow_extended.log_slow_verbosity_2 pattern: ^# Thread_id: \d+  Schema: .+  Last_errno: \d+  Killed: \d+$
+[log_grep.inc] lines:   2
+[log_grep.inc] file: percona.slow_extended.log_slow_verbosity_2 pattern: ^#.*Rows_affected: \d+  Rows_read: \d+$
+[log_grep.inc] lines:   2
+[log_grep.inc] file: percona.slow_extended.log_slow_verbosity_2 pattern: ^# Bytes_sent: \d+.*$
+[log_grep.inc] lines:   2
+[log_grep.inc] file: percona.slow_extended.log_slow_verbosity_2 pattern: ^# InnoDB_trx_id: \w+$
+[log_grep.inc] lines:   0
+[log_grep.inc] file: percona.slow_extended.log_slow_verbosity_2 pattern: ^# Bytes_sent: \d+  Tmp_tables: \d+  Tmp_disk_tables: \d+  Tmp_table_sizes: \d+$
+[log_grep.inc] lines:   0
+[log_grep.inc] file: percona.slow_extended.log_slow_verbosity_2 pattern: ^# QC_Hit: (Yes|No)  Full_scan: (Yes|No)  Full_join: (Yes|No)  Tmp_table: (Yes|No)  Tmp_table_on_disk: (Yes|No)$
+[log_grep.inc] lines:   0
+[log_grep.inc] file: percona.slow_extended.log_slow_verbosity_2 pattern: ^# Filesort: (Yes|No)  Filesort_on_disk: (Yes|No)  Merge_passes: \d+$
+[log_grep.inc] lines:   0
+[log_grep.inc] file: percona.slow_extended.log_slow_verbosity_2 pattern: ^#   InnoDB_IO_r_ops: \d+  InnoDB_IO_r_bytes: \d+  InnoDB_IO_r_wait: \d*\.\d*$
+[log_grep.inc] lines:   0
+[log_grep.inc] file: percona.slow_extended.log_slow_verbosity_2 pattern: ^#   InnoDB_rec_lock_wait: \d*\.\d*  InnoDB_queue_wait: \d*\.\d*$
+[log_grep.inc] lines:   0
+[log_grep.inc] file: percona.slow_extended.log_slow_verbosity_2 pattern: ^#   InnoDB_pages_distinct: \d+$
+[log_grep.inc] lines:   0
+[log_grep.inc] file: percona.slow_extended.log_slow_verbosity_2 pattern: ^# No InnoDB statistics available for this query$
+[log_grep.inc] lines:   0
+SET log_slow_verbosity='microtime,query_plan';
+[log_start.inc] percona.slow_extended.log_slow_verbosity_3
+INSERT INTO t1 VALUE(2);
+[log_stop.inc] percona.slow_extended.log_slow_verbosity_3
+log_slow_verbosity='query_plan':
+[log_grep.inc] file: percona.slow_extended.log_slow_verbosity_3 pattern: ^# Thread_id: \d+  Schema: .+  Last_errno: \d+  Killed: \d+$
+[log_grep.inc] lines:   2
+[log_grep.inc] file: percona.slow_extended.log_slow_verbosity_3 pattern: ^#.*Rows_affected: \d+  Rows_read: \d+$
+[log_grep.inc] lines:   2
+[log_grep.inc] file: percona.slow_extended.log_slow_verbosity_3 pattern: ^# Bytes_sent: \d+.*$
+[log_grep.inc] lines:   2
+[log_grep.inc] file: percona.slow_extended.log_slow_verbosity_3 pattern: ^# InnoDB_trx_id: \w+$
+[log_grep.inc] lines:   0
+[log_grep.inc] file: percona.slow_extended.log_slow_verbosity_3 pattern: ^# Bytes_sent: \d+  Tmp_tables: \d+  Tmp_disk_tables: \d+  Tmp_table_sizes: \d+$
+[log_grep.inc] lines:   2
+[log_grep.inc] file: percona.slow_extended.log_slow_verbosity_3 pattern: ^# QC_Hit: (Yes|No)  Full_scan: (Yes|No)  Full_join: (Yes|No)  Tmp_table: (Yes|No)  Tmp_table_on_disk: (Yes|No)$
+[log_grep.inc] lines:   2
+[log_grep.inc] file: percona.slow_extended.log_slow_verbosity_3 pattern: ^# Filesort: (Yes|No)  Filesort_on_disk: (Yes|No)  Merge_passes: \d+$
+[log_grep.inc] lines:   2
+[log_grep.inc] file: percona.slow_extended.log_slow_verbosity_3 pattern: ^#   InnoDB_IO_r_ops: \d+  InnoDB_IO_r_bytes: \d+  InnoDB_IO_r_wait: \d*\.\d*$
+[log_grep.inc] lines:   0
+[log_grep.inc] file: percona.slow_extended.log_slow_verbosity_3 pattern: ^#   InnoDB_rec_lock_wait: \d*\.\d*  InnoDB_queue_wait: \d*\.\d*$
+[log_grep.inc] lines:   0
+[log_grep.inc] file: percona.slow_extended.log_slow_verbosity_3 pattern: ^#   InnoDB_pages_distinct: \d+$
+[log_grep.inc] lines:   0
+[log_grep.inc] file: percona.slow_extended.log_slow_verbosity_3 pattern: ^# No InnoDB statistics available for this query$
+[log_grep.inc] lines:   0
+SET SESSION log_slow_verbosity=default;
+SET SESSION long_query_time=default;
+SET SESSION min_examined_row_limit=default;
+DROP TABLE t1;
 
=== removed file 'Percona-Server/mysql-test/r/percona_log_slow_verbosity.result'
--- Percona-Server/mysql-test/r/percona_log_slow_verbosity.result	2012-04-18 23:25:38 +0000
+++ Percona-Server/mysql-test/r/percona_log_slow_verbosity.result	1970-01-01 00:00:00 +0000
@@ -1,16 +0,0 @@
-SET SESSION long_query_time=1;
-[log_start.inc] percona.slow_extended.log_slow_verbosity
-SET SESSION query_exec_time=2.1;
-SELECT 1;
-1
-1
-SET SESSION log_slow_verbosity=innodb;
-SELECT 1;
-1
-1
-SET SESSION query_exec_time=default;
-[log_stop.inc] percona.slow_extended.log_slow_verbosity
-SET log_slow_verbosity=default;
-SET long_query_time=default;
-[log_grep.inc] file: percona.slow_extended.log_slow_verbosity pattern: No InnoDB statistics available for this query
-[log_grep.inc] lines:   1
 
=== added file 'Percona-Server/mysql-test/r/percona_long_query_time.result'
--- Percona-Server/mysql-test/r/percona_long_query_time.result	1970-01-01 00:00:00 +0000
+++ Percona-Server/mysql-test/r/percona_long_query_time.result	2013-01-21 06:27:51 +0000
@@ -0,0 +1,35 @@
+SET SESSION min_examined_row_limit=0;
+SET long_query_time=2;
+[log_start.inc] percona.slow_extended.long_query_time
+SET SESSION query_exec_time=1.1;
+SELECT 1;
+1
+1
+SET SESSION query_exec_time=3.1;
+SELECT 1;
+1
+1
+SET SESSION query_exec_time=5.1;
+SELECT 1;
+1
+1
+SET long_query_time=4;
+SET SESSION query_exec_time=1.1;
+SELECT 1;
+1
+1
+SET SESSION query_exec_time=3.1;
+SELECT 1;
+1
+1
+SET SESSION query_exec_time=5.1;
+SELECT 1;
+1
+1
+SET SESSION query_exec_time=default;
+SET long_query_time=2;
+[log_stop.inc] percona.slow_extended.long_query_time
+SET long_query_time=default;
+SET SESSION min_examined_row_limit=default;
+[log_grep.inc] file: percona.slow_extended.long_query_time pattern: Query_time
+[log_grep.inc] lines:   3
 
=== removed file 'Percona-Server/mysql-test/r/percona_long_query_time.result'
--- Percona-Server/mysql-test/r/percona_long_query_time.result	2012-04-18 23:25:38 +0000
+++ Percona-Server/mysql-test/r/percona_long_query_time.result	1970-01-01 00:00:00 +0000
@@ -1,33 +0,0 @@
-SET long_query_time=2;
-[log_start.inc] percona.slow_extended.long_query_time
-SET SESSION query_exec_time=1.1;
-SELECT 1;
-1
-1
-SET SESSION query_exec_time=3.1;
-SELECT 1;
-1
-1
-SET SESSION query_exec_time=5.1;
-SELECT 1;
-1
-1
-SET long_query_time=4;
-SET SESSION query_exec_time=1.1;
-SELECT 1;
-1
-1
-SET SESSION query_exec_time=3.1;
-SELECT 1;
-1
-1
-SET SESSION query_exec_time=5.1;
-SELECT 1;
-1
-1
-SET SESSION query_exec_time=default;
-SET long_query_time=2;
-[log_stop.inc] percona.slow_extended.long_query_time
-SET long_query_time=default;
-[log_grep.inc] file: percona.slow_extended.long_query_time pattern: Query_time
-[log_grep.inc] lines:   3
 
=== modified file 'Percona-Server/mysql-test/r/percona_min_examined_row_limit.result'
--- Percona-Server/mysql-test/r/percona_min_examined_row_limit.result	2012-04-18 23:25:38 +0000
+++ Percona-Server/mysql-test/r/percona_min_examined_row_limit.result	2013-01-21 06:27:51 +0000
@@ -11,7 +11,7 @@
 1
 1
 SET GLOBAL min_examined_row_limit=5;
-select * from t as t1, t as t2;
+SELECT * FROM t AS t1, t AS t2;
 id	id
 1	1
 2	1
 
=== modified file 'Percona-Server/mysql-test/r/percona_slow_extended_error_on_quit.result'
--- Percona-Server/mysql-test/r/percona_slow_extended_error_on_quit.result	2012-10-27 05:16:07 +0000
+++ Percona-Server/mysql-test/r/percona_slow_extended_error_on_quit.result	2013-01-21 06:27:51 +0000
@@ -1,172 +1,27 @@
 DROP TABLE IF EXISTS t;
-CREATE TABLE t(a INT) engine=InnoDB;
-INSERT INTO t VALUES(0),(1),(2),(3),(4);
-[log_start.inc] percona.slow_extended.error_on_quit
-SET log_slow_verbosity=innodb;
-SET long_query_time= 0;
-CREATE TABLE t(a INT) engine=InnoDB;
-# Disconnecting (passing to Slow Query Log "# administrative command: Quit")
-[log_stop.inc] percona.slow_extended.error_on_quit
-################################################################################
-[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: CREATE
-[log_grep.inc] lines:   1
-[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: INSERT
-[log_grep.inc] lines:   0
-[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: SELECT
-[log_grep.inc] lines:   0
-[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Quit
-[log_grep.inc] lines:   1
-[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Last_errno: [^0]+
-[log_grep.inc] lines:   1
-[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Last_errno: 0
-[log_grep.inc] lines:   2
-[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_sent: [^0]+
-[log_grep.inc] lines:   0
-[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_sent: 0
-[log_grep.inc] lines:   3
-[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_examined: [^0]+
-[log_grep.inc] lines:   0
-[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_examined: 0
-[log_grep.inc] lines:   3
-[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_affected: [^0]+
-[log_grep.inc] lines:   0
-[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_affected: 0
-[log_grep.inc] lines:   3
-[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_read: [^0]+
-[log_grep.inc] lines:   0
-[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_read: 0
-[log_grep.inc] lines:   3
-[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Bytes_sent: [^0]+
-[log_grep.inc] lines:   2
-[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Bytes_sent: 0
-[log_grep.inc] lines:   1
-[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Tmp_tables: [^0]+
-[log_grep.inc] lines:   0
-[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Tmp_tables: 0
-[log_grep.inc] lines:   3
-[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Tmp_disk_tables: [^0]+
-[log_grep.inc] lines:   0
-[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Tmp_disk_tables: 0
-[log_grep.inc] lines:   3
-[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Tmp_table_sizes: [^0]+
-[log_grep.inc] lines:   0
-[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Tmp_table_sizes: 0
-[log_grep.inc] lines:   3
-[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: # No InnoDB statistics available for this query
-[log_grep.inc] lines:   2
-[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: # InnoDB_trx_id: 
-[log_grep.inc] lines:   1
-################################################################################
-[log_start.inc] percona.slow_extended.error_on_quit
-SET log_slow_verbosity=innodb;
-SET long_query_time= 0;
-INSERT INTO t SELECT * FROM t ORDER BY RAND();
-# Disconnecting (passing to Slow Query Log "# administrative command: Quit")
-[log_stop.inc] percona.slow_extended.error_on_quit
-################################################################################
-[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: CREATE
-[log_grep.inc] lines:   0
-[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: INSERT
-[log_grep.inc] lines:   1
-[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: SELECT
-[log_grep.inc] lines:   1
-[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Quit
-[log_grep.inc] lines:   1
-[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Last_errno: [^0]+
-[log_grep.inc] lines:   0
-[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Last_errno: 0
-[log_grep.inc] lines:   3
-[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_sent: [^0]+
-[log_grep.inc] lines:   0
-[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_sent: 0
-[log_grep.inc] lines:   3
-[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_examined: [^0]+
-[log_grep.inc] lines:   1
-[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_examined: 0
-[log_grep.inc] lines:   2
-[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_affected: [^0]+
-[log_grep.inc] lines:   2
-[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_affected: 0
-[log_grep.inc] lines:   1
-[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_read: [^0]+
-[log_grep.inc] lines:   1
-[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_read: 0
-[log_grep.inc] lines:   2
-[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Bytes_sent: [^0]+
-[log_grep.inc] lines:   2
-[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Bytes_sent: 0
-[log_grep.inc] lines:   1
-[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Tmp_tables: [^0]+
-[log_grep.inc] lines:   1
-[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Tmp_tables: 0
-[log_grep.inc] lines:   2
-[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Tmp_disk_tables: [^0]+
-[log_grep.inc] lines:   0
-[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Tmp_disk_tables: 0
-[log_grep.inc] lines:   3
-[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Tmp_table_sizes: [^0]+
-[log_grep.inc] lines:   1
-[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Tmp_table_sizes: 0
-[log_grep.inc] lines:   2
-[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: # No InnoDB statistics available for this query
-[log_grep.inc] lines:   2
-[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: # InnoDB_trx_id: 
-[log_grep.inc] lines:   1
-################################################################################
-[log_start.inc] percona.slow_extended.error_on_quit
-SET log_slow_verbosity=innodb;
-SET long_query_time= 0;
+SET GLOBAL log_slow_admin_statements=ON;
+SET GLOBAL long_query_time=0;
+SET GLOBAL min_examined_row_limit=0;
+CREATE TABLE t(a INT) engine=InnoDB;
+[log_start.inc] percona.slow_extended.error_on_quit_1
+CREATE TABLE t(a INT) engine=InnoDB;
+ERROR 42S01: Table 't' already exists
+[log_stop.inc] percona.slow_extended.error_on_quit_1
+[log_grep.inc] file: percona.slow_extended.error_on_quit_1 pattern: Last_errno: [1-9]\d*\s
+[log_grep.inc] lines:   1
+[log_start.inc] percona.slow_extended.error_on_quit_2
+# Disconnecting (passing to Slow Query Log "# administrative command: Quit")
+[log_stop.inc] percona.slow_extended.error_on_quit_2
+[log_grep.inc] file: percona.slow_extended.error_on_quit_2 pattern: Last_errno: 0\s
+[log_grep.inc] lines:   2
+[log_start.inc] percona.slow_extended.error_on_quit_3
 SELECT * FROM t;
+a
 # Disconnecting (passing to Slow Query Log "# administrative command: Quit")
-[log_stop.inc] percona.slow_extended.error_on_quit
-################################################################################
-[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: CREATE
-[log_grep.inc] lines:   0
-[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: INSERT
-[log_grep.inc] lines:   0
-[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: SELECT
-[log_grep.inc] lines:   1
-[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Quit
-[log_grep.inc] lines:   1
-[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Last_errno: [^0]+
-[log_grep.inc] lines:   0
-[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Last_errno: 0
-[log_grep.inc] lines:   3
-[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_sent: [^0]+
-[log_grep.inc] lines:   1
-[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_sent: 0
-[log_grep.inc] lines:   2
-[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_examined: [^0]+
-[log_grep.inc] lines:   1
-[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_examined: 0
-[log_grep.inc] lines:   2
-[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_affected: [^0]+
-[log_grep.inc] lines:   0
-[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_affected: 0
-[log_grep.inc] lines:   3
-[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_read: [^0]+
-[log_grep.inc] lines:   1
-[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_read: 0
-[log_grep.inc] lines:   2
-[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Bytes_sent: [^0]+
-[log_grep.inc] lines:   2
-[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Bytes_sent: 0
-[log_grep.inc] lines:   1
-[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Tmp_tables: [^0]+
-[log_grep.inc] lines:   0
-[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Tmp_tables: 0
-[log_grep.inc] lines:   3
-[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Tmp_disk_tables: [^0]+
-[log_grep.inc] lines:   0
-[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Tmp_disk_tables: 0
-[log_grep.inc] lines:   3
-[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Tmp_table_sizes: [^0]+
-[log_grep.inc] lines:   0
-[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Tmp_table_sizes: 0
-[log_grep.inc] lines:   3
-[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: # No InnoDB statistics available for this query
-[log_grep.inc] lines:   2
-[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: # InnoDB_trx_id: 
-[log_grep.inc] lines:   1
-################################################################################
+[log_stop.inc] percona.slow_extended.error_on_quit_3
+[log_grep.inc] file: percona.slow_extended.error_on_quit_3 pattern: Last_errno: 0\s
+[log_grep.inc] lines:   3
 DROP TABLE t;
+SET GLOBAL log_slow_admin_statements=default;
+SET GLOBAL long_query_time=default;
+SET GLOBAL min_examined_row_limit=default;
 
=== added file 'Percona-Server/mysql-test/r/percona_slow_extended_log_error.result'
--- Percona-Server/mysql-test/r/percona_slow_extended_log_error.result	1970-01-01 00:00:00 +0000
+++ Percona-Server/mysql-test/r/percona_slow_extended_log_error.result	2013-01-21 06:27:51 +0000
@@ -0,0 +1,17 @@
+DROP TABLE IF EXISTS t1;
+SET SESSION min_examined_row_limit=0;
+SET long_query_time=0;
+[log_start.inc] percona.slow_extended.log_error_1
+CREATE TABLE t1(a INT);
+[log_stop.inc] percona.slow_extended.log_error_1
+[log_grep.inc] file: percona.slow_extended.log_error_1 pattern: ^.*Last_errno: 0 .*$
+[log_grep.inc] lines:   2
+[log_start.inc] percona.slow_extended.log_error_2
+CREATE TABLE t1(a INT);
+ERROR 42S01: Table 't1' already exists
+[log_stop.inc] percona.slow_extended.log_error_2
+[log_grep.inc] file: percona.slow_extended.log_error_2 pattern: ^.*Last_errno: 1050 .*$
+[log_grep.inc] lines:   1
+DROP TABLE t1;
+SET long_query_time=default;
+SET SESSION min_examined_row_limit=default;
 
=== removed file 'Percona-Server/mysql-test/r/percona_slow_extended_log_error.result'
--- Percona-Server/mysql-test/r/percona_slow_extended_log_error.result	2012-04-18 23:25:38 +0000
+++ Percona-Server/mysql-test/r/percona_slow_extended_log_error.result	1970-01-01 00:00:00 +0000
@@ -1,10 +0,0 @@
-SET long_query_time=0;
-DROP TABLE IF EXISTS t1;
-CREATE TABLE t(a INT);
-[log_start.inc] percona.slow_extended.log_error
-CREATE TABLE t(a INT);
-ERROR 42S01: Table 't' already exists
-[log_stop.inc] percona.slow_extended.log_error
-[log_grep.inc] file: percona.slow_extended.log_error pattern: Last_errno: 1050
-[log_grep.inc] lines:   1
-DROP TABLE t;
 
=== modified file 'Percona-Server/mysql-test/r/percona_slow_query_log_rate.result'
--- Percona-Server/mysql-test/r/percona_slow_query_log_rate.result	2012-04-18 23:25:38 +0000
+++ Percona-Server/mysql-test/r/percona_slow_query_log_rate.result	2013-01-21 06:27:51 +0000
@@ -1,78 +1,54 @@
-SET GLOBAL long_query_time=1;
+SET GLOBAL long_query_time=0;
 SET GLOBAL log_slow_rate_type='session';
 SET GLOBAL log_slow_rate_limit=3;
-[log_start.inc] percona.slow_extended.log_slow_rate_limit
-SET SESSION query_exec_time=1.1;
-SET SESSION query_exec_id=1;
-SELECT 'connection_one';
-connection_one
-connection_one
-SET SESSION query_exec_time=1.1;
-SET SESSION query_exec_id=2;
-SELECT 'connection_two';
-connection_two
-connection_two
-SET SESSION query_exec_time=1.1;
-SET SESSION query_exec_id=3;
-SELECT 'connection_three';
-connection_three
-connection_three
-SET SESSION query_exec_time=1.1;
-SET SESSION query_exec_id=4;
-SELECT 'connection_one';
-connection_one
-connection_one
-SET SESSION query_exec_time=1.1;
-SET SESSION query_exec_id=5;
-SELECT 'connection_two';
-connection_two
-connection_two
-SET SESSION query_exec_time=1.1;
-SET SESSION query_exec_id=6;
-SELECT 'connection_three';
-connection_three
-connection_three
-[log_stop.inc] percona.slow_extended.log_slow_rate_limit
-[log_grep.inc] file: percona.slow_extended.log_slow_rate_limit pattern: 
+[log_start.inc] percona.slow_extended.log_slow_rate_limit_1
+SELECT 'connection_one';
+connection_one
+connection_one
+SELECT 'connection_two';
+connection_two
+connection_two
+SELECT 'connection_three';
+connection_three
+connection_three
+SELECT 'connection_one';
+connection_one
+connection_one
+SELECT 'connection_two';
+connection_two
+connection_two
+SELECT 'connection_three';
+connection_three
+connection_three
+[log_stop.inc] percona.slow_extended.log_slow_rate_limit_1
+[log_grep.inc] file: percona.slow_extended.log_slow_rate_limit_1 pattern: 
 [log_grep.inc] sum:  2
 [log_grep.inc] zero: 2
 SET GLOBAL log_slow_rate_type='query';
 SET GLOBAL log_slow_rate_limit=2;
-[log_start.inc] percona.slow_extended.log_slow_rate_limit
-SET SESSION query_exec_time=1.1;
-SET SESSION query_exec_id=1;
-SELECT 'connection_one';
-connection_one
-connection_one
-SET SESSION query_exec_time=1.1;
-SET SESSION query_exec_id=2;
-SELECT 'connection_two';
-connection_two
-connection_two
-SET SESSION query_exec_time=1.1;
-SET SESSION query_exec_id=3;
-SELECT 'connection_three';
-connection_three
-connection_three
-SET SESSION query_exec_time=1.1;
-SET SESSION query_exec_id=4;
-SELECT 'connection_one';
-connection_one
-connection_one
-SET SESSION query_exec_time=1.1;
-SET SESSION query_exec_id=5;
-SELECT 'connection_two';
-connection_two
-connection_two
-SET SESSION query_exec_time=1.1;
-SET SESSION query_exec_id=6;
-SELECT 'connection_three';
-connection_three
-connection_three
-[log_stop.inc] percona.slow_extended.log_slow_rate_limit
-[log_grep.inc] file: percona.slow_extended.log_slow_rate_limit pattern: 
-[log_grep.inc] sum:  3
-[log_grep.inc] zero: 0
+[log_start.inc] percona.slow_extended.log_slow_rate_limit_2
+SELECT 'connection_one';
+connection_one
+connection_one
+SELECT 'connection_two';
+connection_two
+connection_two
+SELECT 'connection_three';
+connection_three
+connection_three
+SELECT 'connection_one';
+connection_one
+connection_one
+SELECT 'connection_two';
+connection_two
+connection_two
+SELECT 'connection_three';
+connection_three
+connection_three
+[log_stop.inc] percona.slow_extended.log_slow_rate_limit_2
+[log_grep.inc] file: percona.slow_extended.log_slow_rate_limit_2 pattern: 
+[log_grep.inc] sum:  0
+[log_grep.inc] zero: 3
 SET GLOBAL long_query_time=default;
 SET GLOBAL log_slow_rate_type=default;
 SET GLOBAL log_slow_rate_limit=default;
 
=== added file 'Percona-Server/mysql-test/r/percona_slow_query_log_timestamp_always.result'
--- Percona-Server/mysql-test/r/percona_slow_query_log_timestamp_always.result	1970-01-01 00:00:00 +0000
+++ Percona-Server/mysql-test/r/percona_slow_query_log_timestamp_always.result	2013-01-21 06:27:51 +0000
@@ -0,0 +1,16 @@
+SET SESSION min_examined_row_limit=0;
+SET SESSION long_query_time=0;
+SET GLOBAL slow_query_log_timestamp_always=TRUE;
+[log_start.inc] percona_slow_extended_query_log_1
+SELECT 1;
+1
+1
+SELECT 2;
+2
+2
+[log_stop.inc] percona_slow_extended_query_log_1
+[log_grep.inc] file: percona_slow_extended_query_log_1 pattern: ^# Time: \d{6} (\d| )\d:\d\d:\d\d$
+[log_grep.inc] lines:   3
+SET GLOBAL slow_query_log_timestamp_always=default;
+SET SESSION long_query_time=default;
+SET SESSION min_examined_row_limit=default;
 
=== removed file 'Percona-Server/mysql-test/r/percona_slow_query_log_timestamp_always.result'
--- Percona-Server/mysql-test/r/percona_slow_query_log_timestamp_always.result	2012-04-18 23:25:38 +0000
+++ Percona-Server/mysql-test/r/percona_slow_query_log_timestamp_always.result	1970-01-01 00:00:00 +0000
@@ -1,41 +0,0 @@
-SET long_query_time=2;
-SET GLOBAL slow_query_log_timestamp_always=ON;
-[log_start.inc] percona.slow_extended.slow_query_log_timestamp_always
-SET SESSION query_exec_time=2.1;
-SELECT 1;
-1
-1
-SELECT 1;
-1
-1
-SELECT 1;
-1
-1
-SET GLOBAL slow_query_log_timestamp_always=OFF;
-SET SESSION query_exec_time=2.1;
-SELECT 1;
-1
-1
-SELECT 1;
-1
-1
-SELECT 1;
-1
-1
-SET GLOBAL slow_query_log_timestamp_always=ON;
-SET SESSION query_exec_time=2.1;
-SELECT 1;
-1
-1
-SELECT 1;
-1
-1
-SELECT 1;
-1
-1
-SET SESSION query_exec_time=default;
-[log_stop.inc] percona.slow_extended.slow_query_log_timestamp_always
-SET GLOBAL slow_query_log_timestamp_always=default;
-SET long_query_time=default;
-[log_grep.inc] file: percona.slow_extended.slow_query_log_timestamp_always pattern: # Time: [0-9]+[ ]+[0-9]+:[0-9]+:[0-9]+
-[log_grep.inc] lines:   6
 
=== added file 'Percona-Server/mysql-test/r/percona_slow_query_log_timestamp_precision.result'
--- Percona-Server/mysql-test/r/percona_slow_query_log_timestamp_precision.result	1970-01-01 00:00:00 +0000
+++ Percona-Server/mysql-test/r/percona_slow_query_log_timestamp_precision.result	2013-01-21 06:27:51 +0000
@@ -0,0 +1,24 @@
+SET @old_slow_query_log_timestamp_always=@@slow_query_log_timestamp_always;
+SET SESSION min_examined_row_limit=0;
+SET long_query_time=0;
+SET GLOBAL slow_query_log_timestamp_always=TRUE;
+SET GLOBAL slow_query_log_timestamp_precision='microsecond';
+[log_start.inc] percona_slow_extended_1
+SELECT 1;
+1
+1
+[log_stop.inc] percona_slow_extended_1
+[log_grep.inc] file: percona_slow_extended_1 pattern: ^# Time: \d{6} (\d| )\d:\d\d:\d\d\.\d{6}$
+[log_grep.inc] lines:   2
+SET GLOBAL slow_query_log_timestamp_precision='second';
+[log_start.inc] percona_slow_extended_2
+SELECT 1;
+1
+1
+[log_stop.inc] percona_slow_extended_2
+[log_grep.inc] file: percona_slow_extended_2 pattern: ^# Time: \d{6} (\d| )\d:\d\d:\d\d$
+[log_grep.inc] lines:   2
+SET long_query_time=default;
+SET SESSION min_examined_row_limit=default;
+SET GLOBAL slow_query_log_timestamp_always=@old_slow_query_log_timestamp_always;
+SET GLOBAL slow_query_log_timestamp_precision=default;
 
=== removed file 'Percona-Server/mysql-test/r/percona_slow_query_log_timestamp_precision.result'
--- Percona-Server/mysql-test/r/percona_slow_query_log_timestamp_precision.result	2012-04-18 23:25:38 +0000
+++ Percona-Server/mysql-test/r/percona_slow_query_log_timestamp_precision.result	1970-01-01 00:00:00 +0000
@@ -1,18 +0,0 @@
-SET long_query_time=2;
-[log_start.inc] percona.slow_extended.slow_query_log_timestamp_precision
-SET SESSION query_exec_time=2.1;
-SELECT 1;
-1
-1
-SET GLOBAL slow_query_log_timestamp_precision='microsecond';
-SELECT 1;
-1
-1
-SET SESSION query_exec_time=default;
-[log_stop.inc] percona.slow_extended.slow_query_log_timestamp_precision
-SET GLOBAL slow_query_log_timestamp_precision=default;
-SET long_query_time=default;
-[log_grep.inc] file: percona.slow_extended.slow_query_log_timestamp_precision pattern: # Time: [0-9]+[ ]+[0-9]+:[0-9]+:[0-9]+.[0-9]+
-[log_grep.inc] lines:   1
-[log_grep.inc] file: percona.slow_extended.slow_query_log_timestamp_precision pattern: # Time: [0-9]+[ ]+[0-9]+:[0-9]+:[0-9]+
-[log_grep.inc] lines:   2
 
=== added file 'Percona-Server/mysql-test/r/percona_slow_query_log_use_global_control.result'
--- Percona-Server/mysql-test/r/percona_slow_query_log_use_global_control.result	1970-01-01 00:00:00 +0000
+++ Percona-Server/mysql-test/r/percona_slow_query_log_use_global_control.result	2013-01-21 06:27:51 +0000
@@ -0,0 +1,20 @@
+SET SESSION min_examined_row_limit=0;
+SET GLOBAL long_query_time=1;
+[log_start.inc] percona.slow_extended.slow_query_log_use_global_control
+SET SESSION query_exec_time=1.1;
+SELECT 1;
+1
+1
+SET GLOBAL log_slow_verbosity=innodb;
+SET GLOBAL slow_query_log_use_global_control="log_slow_verbosity,long_query_time";
+SELECT 1;
+1
+1
+SET SESSION query_exec_time=default;
+[log_stop.inc] percona.slow_extended.slow_query_log_use_global_control
+SET GLOBAL slow_query_log_use_global_control='';
+SET GLOBAL log_slow_verbosity='';
+SET GLOBAL long_query_time=default;
+SET SESSION min_examined_row_limit=default;
+[log_grep.inc] file: percona.slow_extended.slow_query_log_use_global_control pattern: No InnoDB statistics available for this query
+[log_grep.inc] lines:   1
 
=== removed file 'Percona-Server/mysql-test/r/percona_slow_query_log_use_global_control.result'
--- Percona-Server/mysql-test/r/percona_slow_query_log_use_global_control.result	2012-04-18 23:25:38 +0000
+++ Percona-Server/mysql-test/r/percona_slow_query_log_use_global_control.result	1970-01-01 00:00:00 +0000
@@ -1,18 +0,0 @@
-SET GLOBAL long_query_time=1;
-[log_start.inc] percona.slow_extended.slow_query_log_use_global_control
-SET SESSION query_exec_time=1.1;
-SELECT 1;
-1
-1
-SET GLOBAL log_slow_verbosity=innodb;
-SET GLOBAL slow_query_log_use_global_control="log_slow_verbosity,long_query_time";
-SELECT 1;
-1
-1
-SET SESSION query_exec_time=default;
-[log_stop.inc] percona.slow_extended.slow_query_log_use_global_control
-SET GLOBAL slow_query_log_use_global_control=default;
-SET GLOBAL log_slow_verbosity=default;
-SET GLOBAL long_query_time=default;
-[log_grep.inc] file: percona.slow_extended.slow_query_log_use_global_control pattern: No InnoDB statistics available for this query
-[log_grep.inc] lines:   1
 
=== modified file 'Percona-Server/mysql-test/t/disabled.def'
--- Percona-Server/mysql-test/t/disabled.def	2012-05-10 07:49:14 +0000
+++ Percona-Server/mysql-test/t/disabled.def	2013-01-21 06:27:51 +0000
@@ -15,3 +15,4 @@
 archive-big              : Bug#11817185 2011-03-10 Anitha Disabled since this leads to timeout on Solaris Sparc
 log_tables-big           : Bug#11756699 2010-11-15 mattiasj report already exists
 mysql_embedded           : Bug#12561297 2011-05-14 Anitha Dependent on PB2 changes - eventum#41836
+percona_slow_extended_error_on_quit : https://bugs.launchpad.net/percona-server/+bug/1098857 2013-01-12 laurynas
 
=== added file 'Percona-Server/mysql-test/t/percona_log_slow_admin_statements.test'
--- Percona-Server/mysql-test/t/percona_log_slow_admin_statements.test	1970-01-01 00:00:00 +0000
+++ Percona-Server/mysql-test/t/percona_log_slow_admin_statements.test	2013-01-21 06:27:51 +0000
@@ -0,0 +1,41 @@
+#
+# Test log_slow_slave_admin_statements
+#
+
+--disable_warnings
+DROP TABLE IF EXISTS t1;
+--enable_warnings
+
+CREATE TABLE t1 (a INT);
+
+SET SESSION min_examined_row_limit=0;
+SET SESSION long_query_time=0;
+
+#
+# Test enabled admin statement slow-logging
+#
+SET GLOBAL log_slow_admin_statements=ON;
+--let log_file=percona_log_slow_admin_stmt_1
+--source include/log_start.inc
+ALTER TABLE t1 ADD INDEX a(a);
+--source include/log_stop.inc
+--let grep_pattern=ALTER TABLE t1 ADD INDEX a\(a\);
+--source include/log_grep.inc
+
+#
+# Test disabled admin statement slow-logging
+#
+SET GLOBAL log_slow_admin_statements=OFF;
+--let log_file=percona_log_slow_admin_stmt_2
+--source include/log_start.inc
+ALTER TABLE t1 DROP INDEX a;
+--source include/log_stop.inc
+--let grep_pattern=ALTER TABLE t1 DROP INDEX a;
+--source include/log_grep.inc
+
+SET GLOBAL log_slow_admin_statements=default;
+SET SESSION long_query_time=default;
+SET SESSION min_examined_row_limit=default;
+
+DROP TABLE t1;
+--source include/log_cleanup.inc
 
=== removed file 'Percona-Server/mysql-test/t/percona_log_slow_admin_statements.test'
--- Percona-Server/mysql-test/t/percona_log_slow_admin_statements.test	2012-04-18 23:25:38 +0000
+++ Percona-Server/mysql-test/t/percona_log_slow_admin_statements.test	1970-01-01 00:00:00 +0000
@@ -1,20 +0,0 @@
-# default value
-SHOW GLOBAL VARIABLES like 'log_slow_admin_statements';
-SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements';
-# set value to 'true'
-SET GLOBAL log_slow_admin_statements=true;
-SHOW GLOBAL VARIABLES like 'log_slow_admin_statements';
-SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements';
-# set value to 'false'
-SET GLOBAL log_slow_admin_statements=false;
-SHOW GLOBAL VARIABLES like 'log_slow_admin_statements';
-SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements';
-# set value to 'foo'
---error ER_WRONG_VALUE_FOR_VAR
-SET GLOBAL log_slow_admin_statements=foo;
-SHOW GLOBAL VARIABLES like 'log_slow_admin_statements';
-SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements';
-# set value to default
-SET GLOBAL log_slow_admin_statements=default;
-SHOW GLOBAL VARIABLES like 'log_slow_admin_statements';
-SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements';
 
=== removed file 'Percona-Server/mysql-test/t/percona_log_slow_filter.test'
--- Percona-Server/mysql-test/t/percona_log_slow_filter.test	2012-04-18 23:25:38 +0000
+++ Percona-Server/mysql-test/t/percona_log_slow_filter.test	1970-01-01 00:00:00 +0000
@@ -1,26 +0,0 @@
---source include/have_debug.inc
-
-CREATE TABLE t(id INT PRIMARY KEY);
-INSERT INTO t VALUES(1);
-INSERT INTO t VALUES(2);
-INSERT INTO t VALUES(3);
-
-SET long_query_time=1;
-SET log_slow_filter=full_join;
---let log_file=percona.slow_extended.log_slow_filter
---source include/log_start.inc
-
-SET query_exec_time = 1.1;
---disable_result_log
-SELECT * FROM t AS t1, t AS t2;
---enable_result_log
-SET query_exec_time = default;
-
---source include/log_stop.inc
-SET log_slow_filter=default;
-SET long_query_time=default;
-
---let grep_pattern = Query_time
---source include/log_grep.inc
-
-DROP TABLE t;
 
=== added file 'Percona-Server/mysql-test/t/percona_log_slow_innodb.test'
--- Percona-Server/mysql-test/t/percona_log_slow_innodb.test	1970-01-01 00:00:00 +0000
+++ Percona-Server/mysql-test/t/percona_log_slow_innodb.test	2013-01-21 06:27:51 +0000
@@ -0,0 +1,82 @@
+#
+# Test that InnoDB stats for the extended slow query log are collected.
+# We do not parse the log to see that the values are reasonable.  That should be done after log to table is implemented.
+# We also do not test the stats that would require DEBUG_SYNC: InnoDB_queue_wait and InnoDB_rec_lock_wait.  The latter is
+# "tested" with SLEEP here, but this is not guaranteed to work.  The testcase is not unstable because of this as we don't
+# actually check the value.
+#
+--source include/have_innodb.inc
+
+--disable_warnings
+DROP TABLE IF EXISTS t1, t2;
+--enable_warnings
+
+let $MYSQLD_TMPDIR = `SELECT @@tmpdir`;
+let $MYSQLD_DATADIR = `SELECT @@datadir`;
+
+CREATE TABLE t1(a INT) ENGINE=InnoDB;
+INSERT INTO t1 VALUE(1);
+
+CREATE TABLE t2(a INT) ENGINE=InnoDB;
+INSERT INTO t2 VALUE(1);
+
+# Force cold buffer pool
+--source include/restart_mysqld.inc
+
+SET SESSION min_examined_row_limit=0;
+SET SESSION long_query_time=0;
+SET @old_log_slow_verbosity := @@log_slow_verbosity;
+SET SESSION log_slow_verbosity='microtime,innodb';
+
+--let log_file=percona.slow_extended.innodb_0
+--source include/log_start.inc
+INSERT INTO t1 VALUES(2);
+INSERT INTO t2 VALUES(2);
+INSERT INTO t1 VALUES(3); # Pages in the buffer pool already
+SELECT 5; # No InnoDB pages accessed
+--source include/log_stop.inc
+
+#
+# Table lock waits
+#
+
+LOCK TABLE t1 WRITE;
+--connect (con2,localhost,root,,test,,)
+--connection con2
+--let log_file=percona.slow_extended.innodb_3
+--source include/log_start.inc
+send LOCK TABLE t1 WRITE;
+--connection default
+# TODO: best-effort test for now. A bug if we check the actual lock time!
+SELECT SLEEP(5);
+UNLOCK TABLES;
+--connection con2
+reap;
+--source include/log_stop.inc
+UNLOCK TABLES;
+--connection default
+
+#
+# Row lock waits
+#
+BEGIN;
+SELECT * FROM t2 FOR UPDATE;
+--connection con2
+--let log_file=percona.slow_extended.innodb_4
+--source include/log_start.inc
+send DELETE FROM t2 WHERE a=2;
+--connection default
+SELECT SLEEP(5);
+COMMIT;
+--connection con2
+reap;
+--source include/log_stop.inc
+--disconnect con2
+--connection default
+
+SET SESSION min_examined_row_limit=default;
+SET SESSION long_query_time=default;
+SET SESSION log_slow_verbosity=@old_log_slow_verbosity;
+
+DROP TABLE t1, t2;
+--source include/log_cleanup.inc
 
=== added file 'Percona-Server/mysql-test/t/percona_log_slow_query_plan.test'
--- Percona-Server/mysql-test/t/percona_log_slow_query_plan.test	1970-01-01 00:00:00 +0000
+++ Percona-Server/mysql-test/t/percona_log_slow_query_plan.test	2013-01-21 06:27:51 +0000
@@ -0,0 +1,302 @@
+#
+# Test that various query plans are logged correctly in the slow query log.
+#
+--source include/have_innodb.inc
+
+FLUSH STATUS;
+
+--disable_warnings
+DROP TABLE IF EXISTS t1;
+--enable_warnings
+
+CREATE TABLE t1(
+       a INT NOT NULL AUTO_INCREMENT PRIMARY KEY,
+       b INT) ENGINE=InnoDB;
+
+INSERT INTO t1 VALUES(NULL, 10), (NULL, 5);
+
+SET SESSION long_query_time=0;
+SET SESSION min_examined_row_limit=0;
+SET SESSION log_slow_verbosity='microtime,query_plan';
+
+#
+# filesort, disk filesort, and filesort merge passes negative test
+#
+EXPLAIN SELECT * FROM t1;
+--let log_file=percona_slow_query_log.query_plan_0
+--source include/log_start.inc
+SELECT * FROM t1;
+--source include/log_stop.inc
+--let grep_pattern = ^# Filesort: No  Filesort_on_disk: No  Merge_passes: 0\$
+--source include/log_grep.inc
+
+#
+# filesort positive test, memory, zero merge passes
+#
+EXPLAIN SELECT * FROM t1 ORDER BY b;
+--let log_file=percona_slow_query_log.query_plan_1
+--source include/log_start.inc
+SELECT * FROM t1 ORDER BY b;
+--source include/log_stop.inc
+--let grep_pattern = ^# Filesort: Yes  Filesort_on_disk: No  Merge_passes: 0\$
+--source include/log_grep.inc
+
+#
+# Same as above but filtered away
+#
+SET SESSION log_slow_filter='full_join,tmp_table,tmp_table_on_disk,filesort_on_disk';
+--let log_file=percona_slow_query_log.query_plan_1a
+--source include/log_start.inc
+SELECT * FROM t1 ORDER BY b;
+--source include/log_stop.inc
+--let grep_pattern = ^# Filesort: Yes  Filesort_on_disk: No  Merge_passes: 0\$
+--source include/log_grep.inc
+SET SESSION log_slow_filter=default;
+
+#
+# filesort positive test, disk, one merge pass
+#
+SET SESSION sort_buffer_size=32804;
+CREATE TABLE t2 (a INT) ENGINE=InnoDB;
+INSERT INTO t2 VALUES (5), (16), (2), (17), (1);
+INSERT INTO t2 SELECT * FROM t2;
+INSERT INTO t2 SELECT * FROM t2;
+INSERT INTO t2 SELECT * FROM t2;
+INSERT INTO t2 SELECT * FROM t2;
+INSERT INTO t2 SELECT * FROM t2;
+INSERT INTO t2 SELECT * FROM t2;
+INSERT INTO t2 SELECT * FROM t2;
+INSERT INTO t2 SELECT * FROM t2;
+INSERT INTO t2 SELECT * FROM t2;
+
+SHOW SESSION STATUS LIKE 'Sort_merge_passes';
+--replace_column 9 ROWS
+EXPLAIN SELECT * FROM t2 ORDER BY a;
+
+--let log_file=percona_slow_query_log.query_plan_2
+--source include/log_start.inc
+--disable_result_log
+SELECT * FROM t2 ORDER BY a;
+--enable_result_log
+--source include/log_stop.inc
+--let grep_pattern = ^# Filesort: Yes  Filesort_on_disk: Yes  Merge_passes: 1\$
+--source include/log_grep.inc
+
+SHOW SESSION STATUS LIKE 'Sort_merge_passes';
+
+#
+# Same as above but filtered away
+#
+SET SESSION log_slow_filter='full_join,tmp_table,tmp_table_on_disk';
+--let log_file=percona_slow_query_log.query_plan_2a
+--source include/log_start.inc
+--disable_result_log
+SELECT * FROM t2 ORDER BY a;
+--enable_result_log
+--source include/log_stop.inc
+--let grep_pattern = ^# Filesort: Yes  Filesort_on_disk: Yes  Merge_passes: 1\$
+--source include/log_grep.inc
+
+SHOW SESSION STATUS LIKE 'Sort_merge_passes';
+
+SET SESSION log_slow_filter=default;
+
+#
+# Same as the above, with more than one merge pass
+#
+INSERT INTO t2 SELECT * FROM t2;
+INSERT INTO t2 SELECT * FROM t2;
+INSERT INTO t2 SELECT * FROM t2;
+INSERT INTO t2 SELECT * FROM t2;
+--let log_file=percona_slow_query_log.query_plan_3
+--source include/log_start.inc
+--disable_result_log
+SELECT * FROM t2 ORDER BY a;
+--enable_result_log
+--source include/log_stop.inc
+--let grep_pattern = ^# Filesort: Yes  Filesort_on_disk: Yes  Merge_passes: 4\$
+--source include/log_grep.inc
+
+SHOW SESSION STATUS LIKE 'Sort_merge_passes';
+
+SET SESSION sort_buffer_size=default;
+
+#
+# Full_scan, negative test
+#
+SHOW SESSION STATUS LIKE 'Select_scan';
+--let log_file=percona_slow_query_log.query_plan_4
+--source include/log_start.inc
+SELECT * FROM t1 WHERE a=1;
+--source include/log_stop.inc
+--let grep_pattern = ^#.*Full_scan: No.*\$
+--source include/log_grep.inc
+
+SHOW SESSION STATUS LIKE 'Select_scan';
+
+#
+# Full_scan, positive test
+#
+--let log_file=percona_slow_query_log.query_plan_5
+--source include/log_start.inc
+SELECT COUNT(*) FROM t1;
+--source include/log_stop.inc
+--let grep_pattern = ^#.*Full_scan: Yes.*\$
+--source include/log_grep.inc
+
+SHOW SESSION STATUS LIKE 'Select_scan';
+
+#
+# Same as above, but filtered away
+#
+SET SESSION log_slow_filter='full_join,tmp_table,tmp_table_on_disk,filesort,filesort_on_disk';
+--let log_file=percona_slow_query_log.query_plan_5a
+--source include/log_start.inc
+SELECT COUNT(*) FROM t1;
+--source include/log_stop.inc
+--let grep_pattern = ^#.*Full_scan: Yes.*\$
+--source include/log_grep.inc
+
+SHOW SESSION STATUS LIKE 'Select_scan';
+
+SET SESSION log_slow_filter=default;
+
+#
+# Full_join, negative test
+#
+CREATE TABLE t3(a INT NOT NULL AUTO_INCREMENT PRIMARY KEY) ENGINE=InnoDB;
+INSERT INTO t3 VALUES (1), (2), (3);
+
+SHOW SESSION STATUS LIKE 'Select_full_join';
+--let log_file=percona_slow_query_log.query_plan_6
+--source include/log_start.inc
+SELECT COUNT(*) FROM t1, t3 WHERE t1.a = t3.a;
+--source include/log_stop.inc
+--let grep_pattern = ^#.*Full_join: No.*\$
+--source include/log_grep.inc
+SHOW SESSION STATUS LIKE 'Select_full_join';
+
+#
+# Full_join, positive test
+#
+--let log_file=percona_slow_query_log.query_plan_7
+--source include/log_start.inc
+SELECT COUNT(*) FROM t1, t2 WHERE t1.b = t2.a;
+--source include/log_stop.inc
+--let grep_pattern = ^#.*Full_join: Yes.*\$
+--source include/log_grep.inc
+
+SHOW SESSION STATUS LIKE 'Select_full_join';
+
+#
+# Same as above, but filtered away
+#
+SET SESSION log_slow_filter='tmp_table,tmp_table_on_disk,filesort,filesort_on_disk';
+--let log_file=percona_slow_query_log.query_plan_7a
+--source include/log_start.inc
+SELECT COUNT(*) FROM t1, t2 WHERE t1.b = t2.a;
+--source include/log_stop.inc
+--let grep_pattern = ^#.*Full_join: Yes.*\$
+--source include/log_grep.inc
+
+SHOW SESSION STATUS LIKE 'Select_full_join';
+
+SET SESSION log_slow_filter=default;
+
+#
+# Tmp_table and Tmp_table_on_disk negative test
+#
+SHOW SESSION STATUS LIKE 'Created_tmp_tables';
+SHOW SESSION STATUS LIKE 'Created_tmp_disk_tables';
+EXPLAIN SELECT COUNT(*) FROM t1;
+--let log_file=percona_slow_query_log.query_plan_8
+--source include/log_start.inc
+SELECT COUNT(*) FROM t1;
+--source include/log_stop.inc
+--let grep_pattern = ^#.*Tmp_tables: 0  Tmp_disk_tables: 0  Tmp_table_sizes: 0\$
+--source include/log_grep.inc
+--let grep_pattern = ^#.*Tmp_table: No  Tmp_table_on_disk: No\$
+--source include/log_grep.inc
+
+#
+# Tmp_table positive, Tmp_table_on_disk negative test
+#
+SHOW SESSION STATUS LIKE 'Created_tmp_tables';
+SHOW SESSION STATUS LIKE 'Created_tmp_disk_tables';
+
+EXPLAIN SELECT COUNT(*) FROM t1, t3 WHERE t1.a = t3.a GROUP BY t3.a;
+--let log_file=percona_slow_query_log.query_plan_9
+--source include/log_start.inc
+SELECT COUNT(*) FROM t1, t3 WHERE t1.a = t3.a GROUP BY t3.a;
+--source include/log_stop.inc
+--let grep_pattern = ^#.*Tmp_tables: 1  Tmp_disk_tables: 0  Tmp_table_sizes: [1-9][0-9]*\$
+--source include/log_grep.inc
+--let grep_pattern = ^#.*Tmp_table: Yes  Tmp_table_on_disk: No\$
+--source include/log_grep.inc
+
+SHOW SESSION STATUS LIKE 'Created_tmp_tables';
+SHOW SESSION STATUS LIKE 'Created_tmp_disk_tables';
+
+#
+# Same as above but filtered away
+#
+SET SESSION log_slow_filter='full_join,tmp_table_on_disk,filesort_on_disk';
+
+--let log_file=percona_slow_query_log.query_plan_9a
+--source include/log_start.inc
+SELECT COUNT(*) FROM t1, t3 WHERE t1.a = t3.a GROUP BY t3.a;
+--source include/log_stop.inc
+--let grep_pattern = ^#.*Tmp_tables: 1  Tmp_disk_tables: 0  Tmp_table_sizes: [1-9][0-9]*\$
+--source include/log_grep.inc
+--let grep_pattern = ^#.*Tmp_table: Yes  Tmp_table_on_disk: No\$
+--source include/log_grep.inc
+
+SHOW SESSION STATUS LIKE 'Created_tmp_tables';
+SHOW SESSION STATUS LIKE 'Created_tmp_disk_tables';
+
+SET SESSION log_slow_filter=default;
+
+#
+# Tmp_table and Tmp_table_on_disk positive test
+#
+CREATE TABLE t4(a INT NOT NULL AUTO_INCREMENT PRIMARY KEY, b TEXT) ENGINE=InnoDB;
+INSERT INTO t4 VALUES (1, "aaa"), (2, "bbb"), (3, "ccc");
+
+EXPLAIN SELECT COUNT(*) FROM t1, t4 WHERE t1.a = t4.a GROUP BY t4.a;
+--let log_file=percona_slow_query_log.query_plan_10
+--source include/log_start.inc
+SELECT COUNT(*) FROM t1, t4 WHERE t1.a = t4.a GROUP BY t4.b;
+--source include/log_stop.inc
+--let grep_pattern = ^#.*Tmp_tables: 1  Tmp_disk_tables: 1  Tmp_table_sizes: [1-9][0-9]*\$
+--source include/log_grep.inc
+--let grep_pattern = ^#.*Tmp_table: Yes  Tmp_table_on_disk: Yes\$
+--source include/log_grep.inc
+
+SHOW SESSION STATUS LIKE 'Created_tmp_tables';
+SHOW SESSION STATUS LIKE 'Created_tmp_disk_tables';
+
+#
+# Same as above but filtered away
+#
+SET SESSION log_slow_filter='full_join,filesort_on_disk';
+
+--let log_file=percona_slow_query_log.query_plan_10a
+--source include/log_start.inc
+SELECT COUNT(*) FROM t1, t4 WHERE t1.a = t4.a GROUP BY t4.b;
+--source include/log_stop.inc
+--let grep_pattern = ^#.*Tmp_tables: 1  Tmp_disk_tables: 1  Tmp_table_sizes: [1-9][0-9]*\$
+--source include/log_grep.inc
+--let grep_pattern = ^#.*Tmp_table: Yes  Tmp_table_on_disk: Yes\$
+--source include/log_grep.inc
+
+SHOW SESSION STATUS LIKE 'Created_tmp_tables';
+SHOW SESSION STATUS LIKE 'Created_tmp_disk_tables';
+
+SET SESSION log_slow_filter=default;
+
+SET SESSION long_query_time=default;
+SET SESSION min_examined_row_limit=default;
+SET SESSION log_slow_verbosity=default;
+
+DROP TABLE t1, t2, t3, t4;
+--source include/log_cleanup.inc
 
=== added file 'Percona-Server/mysql-test/t/percona_log_slow_query_plan_qc.test'
--- Percona-Server/mysql-test/t/percona_log_slow_query_plan_qc.test	1970-01-01 00:00:00 +0000
+++ Percona-Server/mysql-test/t/percona_log_slow_query_plan_qc.test	2013-01-21 06:27:51 +0000
@@ -0,0 +1,71 @@
+#
+# Tests the query cache logging for the extended slow query log
+#
+--source include/have_innodb.inc
+--source include/have_query_cache.inc
+
+FLUSH STATUS;
+SET SESSION min_examined_row_limit=0;
+
+--disable_warnings
+DROP TABLE IF EXISTS t1;
+--enable_warnings
+
+CREATE TABLE t1 (a INT) ENGINE=InnoDB;
+
+INSERT INTO t1 VALUE(5);
+
+SET SESSION query_cache_type=1;
+SET GLOBAL query_cache_size=1355776;
+
+SET SESSION long_query_time=0;
+SET SESSION log_slow_verbosity='microtime,query_plan';
+
+#
+# Test uncached query
+#
+--let log_file = percona_slow_query_log.query_plan_qc_1
+--source include/log_start.inc
+SELECT * FROM t1;
+--source include/log_stop.inc
+--let grep_pattern = ^# QC_Hit: No.*\$
+--source include/log_grep.inc
+
+SHOW STATUS LIKE 'Qcache_hits';
+
+#
+# Test cached query
+#
+
+--let log_file = percona_slow_query_log.query_plan_qc_2
+--source include/log_start.inc
+SELECT * FROM t1;
+--source include/log_stop.inc
+--let grep_pattern = ^# QC_Hit: Yes.*\$
+--source include/log_grep.inc
+
+SHOW STATUS LIKE 'Qcache_hits';
+
+#
+# Test uncached query that is filtered away
+#
+SET SESSION log_slow_filter='full_join,tmp_table,tmp_table_on_disk,filesort,filesort_on_disk';
+--let log_file = percona_slow_query_log.query_plan_qc_3
+--source include/log_start.inc
+SELECT * FROM t1 WHERE a > 5;
+--source include/log_stop.inc
+--let grep_pattern = ^# QC_Hit: No.*\$
+--source include/log_grep.inc
+
+SHOW STATUS LIKE 'Qcache_hits';
+
+SET SESSION log_slow_filter=default;
+
+SET SESSION long_query_time=default;
+SET SESSION log_slow_verbosity=default;
+SET SESSION query_cache_type=default;
+SET GLOBAL query_cache_size=default;
+SET SESSION min_examined_row_limit=default;
+
+DROP TABLE t1;
+--source include/log_cleanup.inc
 
=== removed file 'Percona-Server/mysql-test/t/percona_log_slow_slave_statements-innodb-slave.opt'
--- Percona-Server/mysql-test/t/percona_log_slow_slave_statements-innodb-slave.opt	2012-04-18 23:25:38 +0000
+++ Percona-Server/mysql-test/t/percona_log_slow_slave_statements-innodb-slave.opt	1970-01-01 00:00:00 +0000
@@ -1,1 +0,0 @@
---long_query_time=0 --log_slow_slave_statements --log_slow_verbosity=innodb
 \ No newline at end of file
 
=== added file 'Percona-Server/mysql-test/t/percona_log_slow_slave_statements-innodb.test'
--- Percona-Server/mysql-test/t/percona_log_slow_slave_statements-innodb.test	1970-01-01 00:00:00 +0000
+++ Percona-Server/mysql-test/t/percona_log_slow_slave_statements-innodb.test	2013-01-21 06:27:51 +0000
@@ -0,0 +1,48 @@
+--source include/have_binlog_format_statement.inc
+--source include/master-slave.inc
+--source include/have_innodb.inc
+
+SET SESSION min_examined_row_limit=0;
+-- disable_warnings
+DROP TABLE IF EXISTS t;
+-- enable_warnings
+
+CREATE TABLE t(id INT,data CHAR(30)) ENGINE=InnoDB;
+INSERT INTO t VALUES
+(1,"aaaaabbbbbcccccdddddeeeeefffff"),
+(2,"aaaaabbbbbcccccdddddeeeeefffff"),
+(3,"aaaaabbbbbcccccdddddeeeeefffff"),
+(4,"aaaaabbbbbcccccdddddeeeeefffff"),
+(5,"aaaaabbbbbcccccdddddeeeeefffff");
+INSERT INTO t SELECT t2.id,t2.data from t as t1, t as t2;
+INSERT INTO t SELECT t2.id,t2.data from t as t1, t as t2;
+sync_slave_with_master;
+
+SET GLOBAL long_query_time=0;
+SET GLOBAL log_slow_slave_statements=TRUE;
+SET GLOBAL log_slow_verbosity='innodb';
+--source include/restart_slave_sql.inc
+
+--let log_file=percona.slow_extended.log_slow_slave_statements-innodb
+
+--source include/log_start.inc
+connection master;
+INSERT INTO t SELECT t.id,t.data from t;
+sync_slave_with_master;
+--source include/log_stop.inc
+
+--let grep_pattern =  InnoDB_IO_r_ops
+--source include/log_grep.inc
+
+connection master;
+DROP TABLE t;
+sync_slave_with_master;
+
+SET GLOBAL long_query_time=default;
+SET GLOBAL log_slow_slave_statements=default;
+SET GLOBAL log_slow_verbosity=default;
+SET SESSION min_examined_row_limit=default;
+
+--source include/rpl_end.inc
+
+--source include/log_cleanup.inc
 
=== removed file 'Percona-Server/mysql-test/t/percona_log_slow_slave_statements-innodb.test'
--- Percona-Server/mysql-test/t/percona_log_slow_slave_statements-innodb.test	2012-04-18 23:25:38 +0000
+++ Percona-Server/mysql-test/t/percona_log_slow_slave_statements-innodb.test	1970-01-01 00:00:00 +0000
@@ -1,42 +0,0 @@
---source include/have_binlog_format_statement.inc
---source include/master-slave.inc
---source include/have_innodb.inc
---let log_file=percona.slow_extended.log_slow_slave_statements-innodb
-
-connection master;
--- disable_warnings
-DROP TABLE IF EXISTS t;
--- enable_warnings
-
-CREATE TABLE t(id INT,data CHAR(30)) ENGINE=InnoDB;
-INSERT INTO t VALUES
-(1,"aaaaabbbbbcccccdddddeeeeefffff"),
-(2,"aaaaabbbbbcccccdddddeeeeefffff"),
-(3,"aaaaabbbbbcccccdddddeeeeefffff"),
-(4,"aaaaabbbbbcccccdddddeeeeefffff"),
-(5,"aaaaabbbbbcccccdddddeeeeefffff");
-INSERT INTO t SELECT t2.id,t2.data from t as t1, t as t2;
-INSERT INTO t SELECT t2.id,t2.data from t as t1, t as t2;
-sync_slave_with_master;
-
-connection slave;
---source include/log_start.inc
-
-connection master;
-INSERT INTO t SELECT t.id,t.data from t;
-sync_slave_with_master;
-
-connection slave;
---source include/log_stop.inc
-
---enable_query_log
---enable_result_log
-
---let grep_pattern =  InnoDB_IO_r_ops
---source include/log_grep.inc
-
-connection master;
-DROP TABLE t;
-sync_slave_with_master;
-
---source include/rpl_end.inc
 
=== removed file 'Percona-Server/mysql-test/t/percona_log_slow_slave_statements-slave.opt'
--- Percona-Server/mysql-test/t/percona_log_slow_slave_statements-slave.opt	2012-04-18 23:25:38 +0000
+++ Percona-Server/mysql-test/t/percona_log_slow_slave_statements-slave.opt	1970-01-01 00:00:00 +0000
@@ -1,1 +0,0 @@
---long_query_time=0
 \ No newline at end of file
 
=== added file 'Percona-Server/mysql-test/t/percona_log_slow_slave_statements.test'
--- Percona-Server/mysql-test/t/percona_log_slow_slave_statements.test	1970-01-01 00:00:00 +0000
+++ Percona-Server/mysql-test/t/percona_log_slow_slave_statements.test	2013-01-21 06:27:51 +0000
@@ -0,0 +1,68 @@
+#
+# Test log_slow_slave_statements
+#
+--source include/have_innodb.inc
+--source include/have_binlog_format_statement.inc
+--source include/master-slave.inc
+
+--disable_warnings
+DROP TABLE IF EXISTS t;
+--enable_warnings
+
+CREATE TABLE t(id INT) ENGINE=InnoDB;
+sync_slave_with_master;
+
+SET GLOBAL min_examined_row_limit=0;
+SET GLOBAL long_query_time=0;
+SET GLOBAL log_slow_slave_statements=OFF;
+--source include/restart_slave_sql.inc
+
+--let log_file=percona.slow_extended.log_slow_slave_statements
+--source include/log_start.inc
+
+#
+# A statement that should not be slow-logged
+#
+connection master;
+INSERT INTO t VALUES (1);
+sync_slave_with_master;
+
+#
+# A statement that should be slow-logged
+#
+SET GLOBAL log_slow_slave_statements=ON;
+connection master;
+# Explicit transaction to avoid slow-logging implicit BEGIN/COMMIT
+BEGIN;
+INSERT INTO t VALUES (2);
+COMMIT;
+sync_slave_with_master;
+
+#
+# A statement that should not be slow-logged
+#
+SET GLOBAL log_slow_slave_statements=OFF;
+connection master;
+INSERT INTO t VALUES (3);
+sync_slave_with_master;
+
+--source include/log_stop.inc
+
+--let grep_pattern= INSERT INTO t VALUES \(1\)
+--source include/log_grep.inc
+--let grep_pattern= INSERT INTO t VALUES \(2\)
+--source include/log_grep.inc
+--let grep_pattern= INSERT INTO t VALUES \(3\)
+--source include/log_grep.inc
+--let grep_pattern= ^# User@Host: \[SQL_SLAVE\] @  \[\]
+--source include/log_grep.inc
+
+connection master;
+DROP TABLE t;
+sync_slave_with_master;
+
+SET GLOBAL log_slow_slave_statements=default;
+SET GLOBAL long_query_time=default;
+SET GLOBAL min_examined_row_limit=default;
+--source include/rpl_end.inc
+--source include/log_cleanup.inc
 
=== removed file 'Percona-Server/mysql-test/t/percona_log_slow_slave_statements.test'
--- Percona-Server/mysql-test/t/percona_log_slow_slave_statements.test	2012-04-18 23:25:38 +0000
+++ Percona-Server/mysql-test/t/percona_log_slow_slave_statements.test	1970-01-01 00:00:00 +0000
@@ -1,117 +0,0 @@
--- source include/have_binlog_format_statement.inc
--- source include/master-slave.inc
---let log_file=percona.slow_extended.log_slow_slave_statements
---let show=SELECT Variable_value FROM INFORMATION_SCHEMA.SESSION_VARIABLES WHERE Variable_name LIKE 'log_slow_slave_statements';
-
-connection master;
--- disable_warnings
-DROP TABLE IF EXISTS t;
--- enable_warnings
-
-CREATE TABLE t(id INT);
-sync_slave_with_master;
-
-connection slave;
---source include/log_start.inc
-
---disable_query_log
---disable_result_log
-
---echo LINE 1
-connection master;
-INSERT INTO t VALUES (1);
-sync_slave_with_master;
-
-connection slave;
---let value=`$show`
---echo LOG_SLOW_SLAVE_STATAMENTS is $value
---echo LOG_SLOW_SLAVE_STATEMENTS=ON
-SET GLOBAL log_slow_slave_statements=ON;
---let value=`$show`
---echo LOG_SLOW_SLAVE_STATAMENTS is $value
-
---echo LINE 2
-connection master;
-INSERT INTO t VALUES (2);
-sync_slave_with_master;
-
---source include/restart_slave_sql.inc
-
-connection slave;
---let value=`$show`
---echo LOG_SLOW_SLAVE_STATAMENTS is $value
-
---echo LINE 3
-connection master;
-INSERT INTO t VALUES (3);
-sync_slave_with_master;
-
-connection slave;
---let value=`$show`
---echo LOG_SLOW_SLAVE_STATAMENTS is $value
---echo LOG_SLOW_SLAVE_STATEMENTS=OFF
-SET GLOBAL log_slow_slave_statements=OFF;
---let value=`$show`
---echo LOG_SLOW_SLAVE_STATAMENTS is $value
-
---echo LINE 4
-connection master;
-INSERT INTO t VALUES (4);
-sync_slave_with_master;
-
---source include/restart_slave_sql.inc
-
-connection slave;
---let value=`$show`
---echo LOG_SLOW_SLAVE_STATAMENTS is $value
-
---echo LINE 5
-connection master;
-INSERT INTO t VALUES (5);
-sync_slave_with_master;
-
-connection slave;
---let value=`$show`
---echo LOG_SLOW_SLAVE_STATAMENTS is $value
---echo LOG_SLOW_SLAVE_STATEMENTS=ON
-SET GLOBAL log_slow_slave_statements=ON;
---let value=`$show`
---echo LOG_SLOW_SLAVE_STATAMENTS is $value
-
---echo LINE 6
-connection master;
-INSERT INTO t VALUES (6);
-sync_slave_with_master;
-
---source include/restart_slave_sql.inc
-
-connection slave;
---let value=`$show`
---echo LOG_SLOW_SLAVE_STATAMENTS is $value
-
---echo LINE 7
-connection master;
-INSERT INTO t VALUES (7);
-sync_slave_with_master;
-
---enable_query_log
---enable_result_log
-
-connection slave;
---source include/log_stop.inc
-SET GLOBAL log_slow_slave_statements=default;
-
-connection slave;
---let i=1
-while($i < 8)
-{
---let grep_pattern= INSERT INTO t VALUES \($i\)
---source include/log_grep.inc
-  inc $i;
-}
-
-connection master;
-DROP TABLE t;
-sync_slave_with_master;
-
---source include/rpl_end.inc
 
=== added file 'Percona-Server/mysql-test/t/percona_log_slow_sp_statements.test'
--- Percona-Server/mysql-test/t/percona_log_slow_sp_statements.test	1970-01-01 00:00:00 +0000
+++ Percona-Server/mysql-test/t/percona_log_slow_sp_statements.test	2013-01-21 06:27:51 +0000
@@ -0,0 +1,41 @@
+#
+# Test slow-logging of statements in stored procedures
+#
+--disable_warnings
+DROP PROCEDURE IF EXISTS test_f;
+--enable_warnings
+
+SET SESSION min_examined_row_limit=0;
+SET SESSION long_query_time=0;
+SET SESSION query_cache_type=0;
+
+delimiter ^;
+CREATE PROCEDURE test_f()
+BEGIN
+   SELECT 1;
+END^
+delimiter ;^
+
+SET GLOBAL log_slow_sp_statements=ON;
+--let log_file=percona.slow_extended.sp1
+--source include/log_start.inc
+CALL test_f();
+--source include/log_stop.inc
+--let grep_pattern=SELECT 1;
+--source include/log_grep.inc
+
+SET GLOBAL log_slow_sp_statements=OFF;
+--let log_file=percona.slow_extended.sp2
+--source include/log_start.inc
+CALL test_f();
+--source include/log_stop.inc
+--let grep_pattern=SELECT 1;
+--source include/log_grep.inc
+
+DROP PROCEDURE test_f;
+
+SET GLOBAL log_slow_sp_statements=default;
+SET SESSION long_query_time=default;
+SET SESSION min_examined_row_limit=default;
+SET SESSION query_cache_type=default;
+--source include/log_cleanup.inc
 
=== removed file 'Percona-Server/mysql-test/t/percona_log_slow_sp_statements.test'
--- Percona-Server/mysql-test/t/percona_log_slow_sp_statements.test	2012-04-18 23:25:38 +0000
+++ Percona-Server/mysql-test/t/percona_log_slow_sp_statements.test	1970-01-01 00:00:00 +0000
@@ -1,29 +0,0 @@
---source include/have_debug.inc
-
-SET long_query_time=1;
-SET GLOBAL log_slow_sp_statements=ON;
-SET SESSION query_exec_time=0.1;
---let log_file=percona.slow_extended.log_slow_sp_statements
---source include/log_start.inc
-
-delimiter ^;
-CREATE PROCEDURE test_f()
-BEGIN
-  SET SESSION query_exec_time=1.1; SELECT 1;
-  SET SESSION query_exec_time=2.1; SELECT 1;
-  SET SESSION query_exec_time=3.1; SELECT 1;
-  SET SESSION query_exec_time=0.1;
-END^
-delimiter ;^	
-
-CALL test_f();
-
---source include/log_stop.inc
-SET SESSION query_exec_time=default;
-SET GLOBAL log_slow_sp_statements=default;
-SET long_query_time=default;
-
---let grep_pattern = Query_time
---source include/log_grep.inc
-
-DROP PROCEDURE test_f;
 
=== added file 'Percona-Server/mysql-test/t/percona_log_slow_verbosity.test'
--- Percona-Server/mysql-test/t/percona_log_slow_verbosity.test	1970-01-01 00:00:00 +0000
+++ Percona-Server/mysql-test/t/percona_log_slow_verbosity.test	2013-01-21 06:27:51 +0000
@@ -0,0 +1,75 @@
+#
+# Test the extended slow query log output format for various log_slow_verbosity values.
+#
+--source include/have_innodb.inc
+
+--disable_warnings
+DROP TABLE IF EXISTS t1;
+--enable_warnings
+
+CREATE TABLE t1(a INT) ENGINE=InnoDB;
+
+SET SESSION min_examined_row_limit=0;
+SET SESSION long_query_time=0;
+
+#
+# Test all enabled options with InnoDB-involving query
+#
+SET SESSION log_slow_verbosity='microtime,innodb,query_plan';
+--let log_file=percona.slow_extended.log_slow_verbosity_0
+
+--source include/log_start.inc
+INSERT INTO t1 VALUE(0);
+--source include/log_stop.inc
+
+--echo log_slow_verbosity='microtime,innodb,query_plan':
+--source include/percona_slow_log_verbosity_grep.inc
+
+#
+# Test for "No InnoDB statistics available" in output when InnoDB stats are requested
+# but the query does not involve InnoDB tables
+#
+
+SET SESSION log_slow_verbosity='microtime,innodb,query_plan'; 
+--let log_file=percona.slow_extended.log_slow_verbosity_1
+
+--source include/log_start.inc
+SELECT 1;
+--source include/log_stop.inc
+
+--echo log_slow_verbosity='microtime,innodb,query_plan':
+--source include/percona_slow_log_verbosity_grep.inc
+
+#
+# Test only 'microtime' in the output (bug 730173: InnoDB and query plan information
+# are logged when not enabled)
+#
+SET log_slow_verbosity='microtime';
+--let log_file=percona.slow_extended.log_slow_verbosity_2
+
+--source include/log_start.inc
+INSERT INTO t1 VALUE(1);
+--source include/log_stop.inc
+
+--echo log_slow_verbosity='microtime':
+--source include/percona_slow_log_verbosity_grep.inc
+
+#
+# Test 'query_plan'
+#
+SET log_slow_verbosity='microtime,query_plan';
+--let log_file=percona.slow_extended.log_slow_verbosity_3
+
+--source include/log_start.inc
+INSERT INTO t1 VALUE(2);
+--source include/log_stop.inc
+
+--echo log_slow_verbosity='query_plan':
+--source include/percona_slow_log_verbosity_grep.inc
+
+SET SESSION log_slow_verbosity=default;
+SET SESSION long_query_time=default;
+SET SESSION min_examined_row_limit=default;
+
+DROP TABLE t1;
+--source include/log_cleanup.inc
 
=== removed file 'Percona-Server/mysql-test/t/percona_log_slow_verbosity.test'
--- Percona-Server/mysql-test/t/percona_log_slow_verbosity.test	2012-04-18 23:25:38 +0000
+++ Percona-Server/mysql-test/t/percona_log_slow_verbosity.test	1970-01-01 00:00:00 +0000
@@ -1,19 +0,0 @@
---source include/have_innodb.inc
---source include/have_debug.inc
-
-SET SESSION long_query_time=1;
---let log_file=percona.slow_extended.log_slow_verbosity
---source include/log_start.inc
-
-SET SESSION query_exec_time=2.1;
-SELECT 1;
-SET SESSION log_slow_verbosity=innodb;
-SELECT 1;
-SET SESSION query_exec_time=default;
-
---source include/log_stop.inc
-SET log_slow_verbosity=default;
-SET long_query_time=default;
-
---let grep_pattern = No InnoDB statistics available for this query
---source include/log_grep.inc
 
=== added file 'Percona-Server/mysql-test/t/percona_long_query_time.test'
--- Percona-Server/mysql-test/t/percona_long_query_time.test	1970-01-01 00:00:00 +0000
+++ Percona-Server/mysql-test/t/percona_long_query_time.test	2013-01-21 06:27:51 +0000
@@ -0,0 +1,29 @@
+--source include/have_debug.inc
+
+SET SESSION min_examined_row_limit=0;
+SET long_query_time=2;
+--let log_file=percona.slow_extended.long_query_time
+--source include/log_start.inc
+
+SET SESSION query_exec_time=1.1; SELECT 1;
+SET SESSION query_exec_time=3.1; SELECT 1;
+SET SESSION query_exec_time=5.1; SELECT 1;
+
+SET long_query_time=4;
+
+SET SESSION query_exec_time=1.1; SELECT 1;
+SET SESSION query_exec_time=3.1; SELECT 1;
+SET SESSION query_exec_time=5.1; SELECT 1;
+
+SET SESSION query_exec_time=default;
+
+SET long_query_time=2;
+
+--source include/log_stop.inc
+SET long_query_time=default;
+SET SESSION min_examined_row_limit=default;
+
+--let grep_pattern = Query_time
+--source include/log_grep.inc
+
+--source include/log_cleanup.inc
 
=== removed file 'Percona-Server/mysql-test/t/percona_long_query_time.test'
--- Percona-Server/mysql-test/t/percona_long_query_time.test	2012-04-18 23:25:38 +0000
+++ Percona-Server/mysql-test/t/percona_long_query_time.test	1970-01-01 00:00:00 +0000
@@ -1,25 +0,0 @@
---source include/have_debug.inc
-
-SET long_query_time=2;
---let log_file=percona.slow_extended.long_query_time
---source include/log_start.inc
-
-SET SESSION query_exec_time=1.1; SELECT 1;
-SET SESSION query_exec_time=3.1; SELECT 1;
-SET SESSION query_exec_time=5.1; SELECT 1;
-
-SET long_query_time=4;
-
-SET SESSION query_exec_time=1.1; SELECT 1;
-SET SESSION query_exec_time=3.1; SELECT 1;
-SET SESSION query_exec_time=5.1; SELECT 1;
-
-SET SESSION query_exec_time=default;
-
-SET long_query_time=2;
-
---source include/log_stop.inc
-SET long_query_time=default;
-
---let grep_pattern = Query_time
---source include/log_grep.inc
 
=== added file 'Percona-Server/mysql-test/t/percona_min_examined_row_limit.test'
--- Percona-Server/mysql-test/t/percona_min_examined_row_limit.test	1970-01-01 00:00:00 +0000
+++ Percona-Server/mysql-test/t/percona_min_examined_row_limit.test	2013-01-21 06:27:51 +0000
@@ -0,0 +1,36 @@
+--source include/have_debug.inc
+
+--disable_warnings
+drop table if exists t;
+--enable_warnings
+
+create table t(id INT PRIMARY KEY);
+insert into t values(1);
+insert into t values(2);
+insert into t values(3);
+
+SET GLOBAL long_query_time=2;
+SET GLOBAL slow_query_log_use_global_control='long_query_time,min_examined_row_limit';
+--let log_file=percona.slow_extended.min_examined_row_limit
+--source include/log_start.inc
+
+SET SESSION query_exec_time=2.1;
+SELECT 1;
+
+SET GLOBAL min_examined_row_limit=5;
+
+SELECT * FROM t AS t1, t AS t2;
+SELECT 1;
+
+SET SESSION query_exec_time=default;
+
+--source include/log_stop.inc
+SET GLOBAL min_examined_row_limit=default;
+SET GLOBAL slow_query_log_use_global_control=default;
+SET GLOBAL long_query_time=default;
+
+--let grep_pattern = Query_time
+--source include/log_grep.inc
+
+DROP TABLE t;
+--source include/log_cleanup.inc
 
=== removed file 'Percona-Server/mysql-test/t/percona_min_examined_row_limit.test'
--- Percona-Server/mysql-test/t/percona_min_examined_row_limit.test	2012-04-18 23:25:38 +0000
+++ Percona-Server/mysql-test/t/percona_min_examined_row_limit.test	1970-01-01 00:00:00 +0000
@@ -1,35 +0,0 @@
---source include/have_debug.inc
-
---disable_warnings
-drop table if exists t;
---enable_warnings
-
-create table t(id INT PRIMARY KEY);
-insert into t values(1);
-insert into t values(2);
-insert into t values(3);
-
-SET GLOBAL long_query_time=2;
-SET GLOBAL slow_query_log_use_global_control='long_query_time,min_examined_row_limit';
---let log_file=percona.slow_extended.min_examined_row_limit
---source include/log_start.inc
-
-SET SESSION query_exec_time=2.1;
-SELECT 1;
-
-SET GLOBAL min_examined_row_limit=5;
-
-select * from t as t1, t as t2;
-SELECT 1;
-
-SET SESSION query_exec_time=default;
-
---source include/log_stop.inc
-SET GLOBAL min_examined_row_limit=default;
-SET GLOBAL slow_query_log_use_global_control=default;
-SET GLOBAL long_query_time=default;
-
---let grep_pattern = Query_time
---source include/log_grep.inc
-
-DROP TABLE t;
 
=== added file 'Percona-Server/mysql-test/t/percona_slow_extended_error_on_quit.test'
--- Percona-Server/mysql-test/t/percona_slow_extended_error_on_quit.test	1970-01-01 00:00:00 +0000
+++ Percona-Server/mysql-test/t/percona_slow_extended_error_on_quit.test	2013-01-21 06:27:51 +0000
@@ -0,0 +1,71 @@
+# Current test checks Last_errno for administrative command "Quit"
+# See Launchpad Bug #716210
+
+--source include/have_innodb.inc
+--source include/count_sessions.inc
+
+--disable_warnings
+DROP TABLE IF EXISTS t;
+--enable_warnings
+
+SET GLOBAL log_slow_admin_statements=ON;
+SET GLOBAL long_query_time=0;
+SET GLOBAL min_examined_row_limit=0;
+
+CREATE TABLE t(a INT) engine=InnoDB;
+
+--connect(additional,localhost,root,,)
+--connection additional
+
+#
+# 1st command in the log that sets Last_errno
+#
+--let log_file=percona.slow_extended.error_on_quit_1
+--source include/log_start.inc
+
+--error ER_TABLE_EXISTS_ERROR
+CREATE TABLE t(a INT) engine=InnoDB;
+--source include/log_stop.inc
+
+--let grep_pattern=Last_errno: [1-9]\d*\s
+--source include/log_grep.inc
+
+#
+# Subsequent Quit should not have Last_errno set
+#
+--let log_file=percona.slow_extended.error_on_quit_2
+--source include/log_start.inc
+--echo # Disconnecting (passing to Slow Query Log "# administrative command: Quit")
+--disconnect additional
+--connection default
+--source include/wait_until_count_sessions.inc
+--source include/log_stop.inc
+
+--let grep_pattern=Last_errno: 0\s
+--source include/log_grep.inc
+
+--connect(additional,localhost,root,,)
+--connection additional
+
+#
+# Negative case: both regular command and Quit with errno = 0
+#
+--let log_file=percona.slow_extended.error_on_quit_3
+--source include/log_start.inc
+
+SELECT * FROM t;
+
+--echo # Disconnecting (passing to Slow Query Log "# administrative command: Quit")
+--disconnect additional
+--connection default
+--source include/wait_until_count_sessions.inc
+--source include/log_stop.inc
+
+--let grep_pattern= Last_errno: 0\s
+--source include/log_grep.inc
+
+DROP TABLE t;
+SET GLOBAL log_slow_admin_statements=default;
+SET GLOBAL long_query_time=default;
+SET GLOBAL min_examined_row_limit=default;
+--source include/log_cleanup.inc
 
=== removed file 'Percona-Server/mysql-test/t/percona_slow_extended_error_on_quit.test'
--- Percona-Server/mysql-test/t/percona_slow_extended_error_on_quit.test	2012-10-27 05:16:07 +0000
+++ Percona-Server/mysql-test/t/percona_slow_extended_error_on_quit.test	1970-01-01 00:00:00 +0000
@@ -1,87 +0,0 @@
-################################################################################
-# Current test check following attributes:                                     #
-# 1) "Last_errno"                                                              #
-# 2) "Rows_{sent,examined|affected|read}                                       #
-# 3) Bytes_sent                                                                #
-# 4) Tmp_{tables|dist_tables|table_size}                                       #
-# 5) InnoDB statistic counters                                                 #
-# in Slow Query Log                                                            #
-# for administrative command "Quit"                                            #
-#                                                                              #
-# See Launchpad Bug #716210                                                    #
-################################################################################
-
---source include/have_innodb.inc
-
-################################################################################
---let log_file=percona.slow_extended.error_on_quit
---let wait_condition=SELECT COUNT(*) = 1 FROM INFORMATION_SCHEMA.PROCESSLIST;
-################################################################################
-
---disable_warnings
-DROP TABLE IF EXISTS t;
---enable_warnings
-CREATE TABLE t(a INT) engine=InnoDB;
-INSERT INTO t VALUES(0),(1),(2),(3),(4);
-
-################################################################################
---source include/log_start.inc
-
---connect(additional,localhost,root,,)
---connection additional
-
-  SET log_slow_verbosity=innodb;
-  SET long_query_time= 0;
-
---disable_result_log
---error ER_TABLE_EXISTS_ERROR
-  CREATE TABLE t(a INT) engine=InnoDB;
---enable_result_log
-
---connection default
---echo # Disconnecting (passing to Slow Query Log "# administrative command: Quit")
---disconnect additional
---source include/wait_condition.inc
---source include/log_stop.inc
---source include/percona_slow_extended_error_on_quit.inc
-################################################################################
---source include/log_start.inc
-
---connect(additional,localhost,root,,)
---connection additional
-
-  SET log_slow_verbosity=innodb;
-  SET long_query_time= 0;
-
---disable_result_log
-  INSERT INTO t SELECT * FROM t ORDER BY RAND();
---enable_result_log
-
---connection default
---echo # Disconnecting (passing to Slow Query Log "# administrative command: Quit")
---disconnect additional
---source include/wait_condition.inc
---source include/log_stop.inc
---source include/percona_slow_extended_error_on_quit.inc
-################################################################################
---source include/log_start.inc
-
---connect(additional,localhost,root,,)
---connection additional
-
-  SET log_slow_verbosity=innodb;
-  SET long_query_time= 0;
-
---disable_result_log
-  SELECT * FROM t;
---enable_result_log
-
---connection default
---echo # Disconnecting (passing to Slow Query Log "# administrative command: Quit")
---disconnect additional
---source include/wait_condition.inc
---source include/log_stop.inc
---source include/percona_slow_extended_error_on_quit.inc
-################################################################################
-
-DROP TABLE t;
 
=== added file 'Percona-Server/mysql-test/t/percona_slow_extended_log_error.test'
--- Percona-Server/mysql-test/t/percona_slow_extended_log_error.test	1970-01-01 00:00:00 +0000
+++ Percona-Server/mysql-test/t/percona_slow_extended_log_error.test	2013-01-21 06:27:51 +0000
@@ -0,0 +1,31 @@
+#
+# Test last_errno in extended slow query log
+# 
+
+--disable_warnings
+DROP TABLE IF EXISTS t1;
+--enable_warnings
+
+SET SESSION min_examined_row_limit=0;
+SET long_query_time=0;
+
+--let log_file=percona.slow_extended.log_error_1
+--source include/log_start.inc
+CREATE TABLE t1(a INT);
+--source include/log_stop.inc
+--let grep_pattern = ^.*Last_errno: 0 .*\$
+--source include/log_grep.inc
+
+--let log_file=percona.slow_extended.log_error_2
+--source include/log_start.inc
+--error ER_TABLE_EXISTS_ERROR
+CREATE TABLE t1(a INT);
+--source include/log_stop.inc
+--let grep_pattern = ^.*Last_errno: 1050 .*\$
+--source include/log_grep.inc
+
+DROP TABLE t1;
+
+SET long_query_time=default;
+SET SESSION min_examined_row_limit=default;
+--source include/log_cleanup.inc
 
=== removed file 'Percona-Server/mysql-test/t/percona_slow_extended_log_error.test'
--- Percona-Server/mysql-test/t/percona_slow_extended_log_error.test	2012-04-18 23:25:38 +0000
+++ Percona-Server/mysql-test/t/percona_slow_extended_log_error.test	1970-01-01 00:00:00 +0000
@@ -1,15 +0,0 @@
---let log_file=percona.slow_extended.log_error
-SET long_query_time=0;
---disable_warnings
-DROP TABLE IF EXISTS t1;
---enable_warnings
-CREATE TABLE t(a INT);
---source include/log_start.inc
-
---error ER_TABLE_EXISTS_ERROR
-CREATE TABLE t(a INT);
-
---source include/log_stop.inc
---let grep_pattern = Last_errno: 1050
---source include/log_grep.inc
-DROP TABLE t;
 
=== modified file 'Percona-Server/mysql-test/t/percona_slow_query_log_rate.test'
--- Percona-Server/mysql-test/t/percona_slow_query_log_rate.test	2012-04-18 23:25:38 +0000
+++ Percona-Server/mysql-test/t/percona_slow_query_log_rate.test	2013-01-21 06:27:51 +0000
@@ -1,16 +1,23 @@
---source include/have_debug.inc
---let log_file=percona.slow_extended.log_slow_rate_limit
+# Force deterministic session and query ids
+--source include/restart_mysqld.inc
 
-SET GLOBAL long_query_time=1;
+SET GLOBAL long_query_time=0;
 
 SET GLOBAL log_slow_rate_type='session';
 SET GLOBAL log_slow_rate_limit=3;
+--let log_file=percona.slow_extended.log_slow_rate_limit_1
 --source include/percona_slow_query_log_rate.inc
 
+# This is restart is necessary because of the variable possible number of session
+# disconnect checks at the end of the previous test
+--source include/restart_mysqld.inc
+
 SET GLOBAL log_slow_rate_type='query';
 SET GLOBAL log_slow_rate_limit=2;
+--let log_file=percona.slow_extended.log_slow_rate_limit_2
 --source include/percona_slow_query_log_rate.inc
 
 SET GLOBAL long_query_time=default;
 SET GLOBAL log_slow_rate_type=default;
 SET GLOBAL log_slow_rate_limit=default;
+--source include/log_cleanup.inc
 
=== added file 'Percona-Server/mysql-test/t/percona_slow_query_log_timestamp_always.test'
--- Percona-Server/mysql-test/t/percona_slow_query_log_timestamp_always.test	1970-01-01 00:00:00 +0000
+++ Percona-Server/mysql-test/t/percona_slow_query_log_timestamp_always.test	2013-01-21 06:27:51 +0000
@@ -0,0 +1,21 @@
+#
+# Test slow_query_log_timestamp_always variable.  It's missing tests for FALSE value that
+# the log entries with the same timestamp are indeed not timestamped, but this is
+# impossible to test in MTR without debug injections.
+#
+SET SESSION min_examined_row_limit=0;
+SET SESSION long_query_time=0;
+SET GLOBAL slow_query_log_timestamp_always=TRUE;
+
+--let log_file=percona_slow_extended_query_log_1
+--source include/log_start.inc
+SELECT 1;
+SELECT 2;
+--source include/log_stop.inc
+--let grep_pattern= ^# Time: \d{6} (\d| )\d:\d\d:\d\d\$
+--source include/log_grep.inc
+
+SET GLOBAL slow_query_log_timestamp_always=default;
+SET SESSION long_query_time=default;
+SET SESSION min_examined_row_limit=default;
+--source include/log_cleanup.inc
 
=== removed file 'Percona-Server/mysql-test/t/percona_slow_query_log_timestamp_always.test'
--- Percona-Server/mysql-test/t/percona_slow_query_log_timestamp_always.test	2012-04-18 23:25:38 +0000
+++ Percona-Server/mysql-test/t/percona_slow_query_log_timestamp_always.test	1970-01-01 00:00:00 +0000
@@ -1,34 +0,0 @@
---source include/have_debug.inc
-
-SET long_query_time=2;
-SET GLOBAL slow_query_log_timestamp_always=ON;
---let log_file=percona.slow_extended.slow_query_log_timestamp_always
---source include/log_start.inc
-
-SET SESSION query_exec_time=2.1;
-SELECT 1;
-SELECT 1;
-SELECT 1;
-
-SET GLOBAL slow_query_log_timestamp_always=OFF;
-
-SET SESSION query_exec_time=2.1;
-SELECT 1;
-SELECT 1;
-SELECT 1;
-
-SET GLOBAL slow_query_log_timestamp_always=ON;
-
-SET SESSION query_exec_time=2.1;
-SELECT 1;
-SELECT 1;
-SELECT 1;
-
-SET SESSION query_exec_time=default;
-
---source include/log_stop.inc
-SET GLOBAL slow_query_log_timestamp_always=default;
-SET long_query_time=default;
-
---let grep_pattern =  # Time: [0-9]+[ ]+[0-9]+:[0-9]+:[0-9]+
---source include/log_grep.inc
 
=== added file 'Percona-Server/mysql-test/t/percona_slow_query_log_timestamp_precision.test'
--- Percona-Server/mysql-test/t/percona_slow_query_log_timestamp_precision.test	1970-01-01 00:00:00 +0000
+++ Percona-Server/mysql-test/t/percona_slow_query_log_timestamp_precision.test	2013-01-21 06:27:51 +0000
@@ -0,0 +1,37 @@
+#
+# Test slow_query_log_timestamp_precision variable.
+#
+SET @old_slow_query_log_timestamp_always=@@slow_query_log_timestamp_always;
+SET SESSION min_examined_row_limit=0;
+SET long_query_time=0;
+SET GLOBAL slow_query_log_timestamp_always=TRUE;
+
+#
+# microsecond
+#
+SET GLOBAL slow_query_log_timestamp_precision='microsecond';
+
+--let log_file=percona_slow_extended_1
+--source include/log_start.inc
+SELECT 1;
+--source include/log_stop.inc
+--let grep_pattern= ^# Time: \d{6} (\d| )\d:\d\d:\d\d\.\d{6}\$
+--source include/log_grep.inc
+
+#
+# second
+#
+SET GLOBAL slow_query_log_timestamp_precision='second';
+
+--let log_file=percona_slow_extended_2
+--source include/log_start.inc
+SELECT 1;
+--source include/log_stop.inc
+--let grep_pattern= ^# Time: \d{6} (\d| )\d:\d\d:\d\d\$
+--source include/log_grep.inc
+
+SET long_query_time=default;
+SET SESSION min_examined_row_limit=default;
+SET GLOBAL slow_query_log_timestamp_always=@old_slow_query_log_timestamp_always;
+SET GLOBAL slow_query_log_timestamp_precision=default;
+--source include/log_cleanup.inc
 
=== removed file 'Percona-Server/mysql-test/t/percona_slow_query_log_timestamp_precision.test'
--- Percona-Server/mysql-test/t/percona_slow_query_log_timestamp_precision.test	2012-04-18 23:25:38 +0000
+++ Percona-Server/mysql-test/t/percona_slow_query_log_timestamp_precision.test	1970-01-01 00:00:00 +0000
@@ -1,25 +0,0 @@
---source include/have_debug.inc
-
-SET long_query_time=2;
---let log_file=percona.slow_extended.slow_query_log_timestamp_precision
---source include/log_start.inc
-
-SET SESSION query_exec_time=2.1;
-
-SELECT 1;
-
-SET GLOBAL slow_query_log_timestamp_precision='microsecond';
-
-SELECT 1;
-
-SET SESSION query_exec_time=default;
-
---source include/log_stop.inc
-SET GLOBAL slow_query_log_timestamp_precision=default;
-SET long_query_time=default;
-
---let grep_pattern = # Time: [0-9]+[ ]+[0-9]+:[0-9]+:[0-9]+.[0-9]+
---source include/log_grep.inc
-
---let grep_pattern =  # Time: [0-9]+[ ]+[0-9]+:[0-9]+:[0-9]+
---source include/log_grep.inc
 
=== added file 'Percona-Server/mysql-test/t/percona_slow_query_log_use_global_control.test'
--- Percona-Server/mysql-test/t/percona_slow_query_log_use_global_control.test	1970-01-01 00:00:00 +0000
+++ Percona-Server/mysql-test/t/percona_slow_query_log_use_global_control.test	2013-01-21 06:27:51 +0000
@@ -0,0 +1,31 @@
+--source include/have_debug.inc
+--source include/have_innodb.inc
+
+SET SESSION min_examined_row_limit=0;
+SET GLOBAL long_query_time=1;
+
+--let log_file=percona.slow_extended.slow_query_log_use_global_control
+--source include/log_start.inc
+
+SET SESSION query_exec_time=1.1;
+
+SELECT 1;
+
+SET GLOBAL log_slow_verbosity=innodb;
+SET GLOBAL slow_query_log_use_global_control="log_slow_verbosity,long_query_time";
+
+SELECT 1;
+
+SET SESSION query_exec_time=default;
+
+--source include/log_stop.inc
+
+SET GLOBAL slow_query_log_use_global_control='';
+SET GLOBAL log_slow_verbosity='';
+SET GLOBAL long_query_time=default;
+SET SESSION min_examined_row_limit=default;
+
+--let grep_pattern = No InnoDB statistics available for this query
+--source include/log_grep.inc
+
+--source include/log_cleanup.inc
 
=== removed file 'Percona-Server/mysql-test/t/percona_slow_query_log_use_global_control.test'
--- Percona-Server/mysql-test/t/percona_slow_query_log_use_global_control.test	2012-04-18 23:25:38 +0000
+++ Percona-Server/mysql-test/t/percona_slow_query_log_use_global_control.test	1970-01-01 00:00:00 +0000
@@ -1,28 +0,0 @@
---source include/have_debug.inc
---source include/have_innodb.inc
-
-SET GLOBAL long_query_time=1;
-
---let log_file=percona.slow_extended.slow_query_log_use_global_control
---source include/log_start.inc
-
-SET SESSION query_exec_time=1.1;
-SELECT 1;
-
-SET GLOBAL log_slow_verbosity=innodb;
-SET GLOBAL slow_query_log_use_global_control="log_slow_verbosity,long_query_time";
-
-SELECT 1;
-
-SET SESSION query_exec_time=default;
-
---source include/log_stop.inc
-
-
-SET GLOBAL slow_query_log_use_global_control=default;
-SET GLOBAL log_slow_verbosity=default;
-SET GLOBAL long_query_time=default;
-
---let grep_pattern = No InnoDB statistics available for this query
---source include/log_grep.inc
-
 
=== modified file 'Percona-Server/sql/event_scheduler.cc'
--- Percona-Server/sql/event_scheduler.cc	2012-09-17 13:08:32 +0000
+++ Percona-Server/sql/event_scheduler.cc	2013-01-21 06:27:51 +0000
@@ -195,7 +195,6 @@
   thd->client_capabilities|= CLIENT_MULTI_RESULTS;
   mysql_mutex_lock(&LOCK_thread_count);
   thd->thread_id= thd->variables.pseudo_thread_id= thread_id++;
-  thd->write_to_slow_log= true;
   mysql_mutex_unlock(&LOCK_thread_count);
 
   /*
 
=== modified file 'Percona-Server/sql/log.cc'
--- Percona-Server/sql/log.cc	2013-01-09 23:45:25 +0000
+++ Percona-Server/sql/log.cc	2013-01-21 06:27:51 +0000
@@ -1220,7 +1220,7 @@
 
   if (*slow_log_handler_list)
   {
-    /* do not log slow queries from replication threads */
+    /* do not log slow queries from replication threads, unless requested */
     if (thd->slave_thread && !opt_log_slow_slave_statements)
       return 0;
 
@@ -2709,6 +2709,9 @@
     char buff[80], *end;
     char query_time_buff[22+7], lock_time_buff[22+7];
     uint buff_len;
+    char sent_row_buff[21]; // max ulonglong val in dec is 20 digits
+    char examined_row_buff[21];
+    char affected_row_buff[21];
     end= buff;
 
     if (!(specialflag & SPECIAL_SHORT_LOG_FORMAT))
@@ -2722,7 +2725,7 @@
 	{
 	  ulonglong microsecond = current_utime % (1000 * 1000);
 	  buff_len= snprintf(buff, sizeof buff,
-	    "# Time: %02d%02d%02d %2d:%02d:%02d.%010lld\n",
+	    "# Time: %02d%02d%02d %2d:%02d:%02d.%06lld\n",
             start.tm_year % 100, start.tm_mon + 1,
 	    start.tm_mday, start.tm_hour,
 	    start.tm_min, start.tm_sec,microsecond);
@@ -2751,28 +2754,49 @@
     /* For slow query log */
     sprintf(query_time_buff, "%.6f", ulonglong2double(query_utime)/1000000.0);
     sprintf(lock_time_buff,  "%.6f", ulonglong2double(lock_utime)/1000000.0);
-    DBUG_PRINT("info", ("Last_errno: %u", thd->last_errno));
+    /* Here and below sprintf is used because my_b_printf does not support %llu
+    natively.  snprintf is not used as there is no way to overflow the buffer
+    for 64-bit integers and MySQL assumes it to be available on less systems
+    than sprintf.  */
+    sprintf(sent_row_buff, "%llu", (ulonglong)thd->sent_row_count);
+    sprintf(examined_row_buff, "%llu", (ulonglong)thd->examined_row_count);
+    sprintf(affected_row_buff, "%llu", (thd->get_row_count_func() > 0)
+            ? (ulonglong) thd->get_row_count_func() : 0);
     if (my_b_printf(&log_file,
-                    "# Thread_id: %lu  Schema: %s  Last_errno: %u  Killed: %u\n" \
-                    "# Query_time: %s  Lock_time: %s  Rows_sent: %lu  Rows_examined: %lu  Rows_affected: %lu  Rows_read: %lu\n"
-                    "# Bytes_sent: %lu  Tmp_tables: %lu  Tmp_disk_tables: %lu  Tmp_table_sizes: %lu\n",
+                    "# Thread_id: %lu  Schema: %s  Last_errno: %d  "
+                    "Killed: %u\n"
+                    "# Query_time: %s  Lock_time: %s  Rows_sent: %s  "
+                    "Rows_examined: %s  Rows_affected: %s  Rows_read: %s\n"
+                    "# Bytes_sent: %lu",
                     (ulong) thd->thread_id, (thd->db ? thd->db : ""),
                     thd->last_errno, (uint) thd->killed,
-                    query_time_buff, lock_time_buff,
-                    (ulong) thd->sent_row_count,
-                    (ulong) thd->examined_row_count,
-                    ((long) thd->get_row_count_func() > 0 ) ? (ulong) thd->get_row_count_func() : 0,
-                    (ulong) thd->examined_row_count,
-                    (ulong) (thd->status_var.bytes_sent - thd->bytes_sent_old),
-                    (ulong) thd->tmp_tables_used,
-                    (ulong) thd->tmp_tables_disk_used,
-                    (ulong) thd->tmp_tables_size) == (uint) -1)
+                    query_time_buff, lock_time_buff, sent_row_buff,
+                    examined_row_buff, affected_row_buff, examined_row_buff,
+                    (ulong) (thd->status_var.bytes_sent - thd->bytes_sent_old))
+        == (uint) -1)
       tmp_errno= errno;
 
+    if (thd->variables.log_slow_verbosity & (1ULL << SLOG_V_QUERY_PLAN))
+    {
+        char tmp_tables_size_buff[21];
+        sprintf(tmp_tables_size_buff, "%llu", thd->tmp_tables_size);
+        if (my_b_printf(&log_file,
+                        "  Tmp_tables: %lu  Tmp_disk_tables: %lu  "
+                        "Tmp_table_sizes: %s",
+                        thd->tmp_tables_used, thd->tmp_tables_disk_used,
+                        tmp_tables_size_buff) == (uint) -1)
+        {
+            tmp_errno= errno;
+        }
+    }
+    if (my_b_write(&log_file, (uchar*) "\n", 1))
+        tmp_errno= errno;
+
 #if defined(ENABLED_PROFILING)
     thd->profiling.print_current(&log_file);
 #endif
-    if (thd->innodb_was_used)
+    if ((thd->variables.log_slow_verbosity & (1ULL << SLOG_V_INNODB))
+        && thd->innodb_was_used)
     {
       char buf[20];
       snprintf(buf, 20, "%llX", thd->innodb_trx_id);
@@ -2796,18 +2820,20 @@
     if ((thd->variables.log_slow_verbosity & (ULL(1) << SLOG_V_INNODB)) && thd->innodb_was_used)
     {
       char buf[3][20];
+      char io_read_buff[21];
       snprintf(buf[0], 20, "%.6f", thd->innodb_io_reads_wait_timer / 1000000.0);
       snprintf(buf[1], 20, "%.6f", thd->innodb_lock_que_wait_timer / 1000000.0);
       snprintf(buf[2], 20, "%.6f", thd->innodb_innodb_que_wait_timer / 1000000.0);
+      sprintf(io_read_buff, "%llu", thd->innodb_io_read);
       if (my_b_printf(&log_file,
-                      "#   InnoDB_IO_r_ops: %lu  InnoDB_IO_r_bytes: %lu  InnoDB_IO_r_wait: %s\n" \
-                      "#   InnoDB_rec_lock_wait: %s  InnoDB_queue_wait: %s\n" \
+                      "#   InnoDB_IO_r_ops: %lu  InnoDB_IO_r_bytes: %s  "
+                      "InnoDB_IO_r_wait: %s\n"
+                      "#   InnoDB_rec_lock_wait: %s  InnoDB_queue_wait: %s\n"
                       "#   InnoDB_pages_distinct: %lu\n",
-                      (ulong) thd->innodb_io_reads,
-                      (ulong) thd->innodb_io_read,
-                      buf[0], buf[1], buf[2],
-                      (ulong) thd->innodb_page_access) == (uint) -1)
-        tmp_errno=errno;
+                      thd->innodb_io_reads, io_read_buff,
+                      buf[0], buf[1], buf[2], thd->innodb_page_access)
+          == (uint) -1)
+        tmp_errno= errno;
     } 
     else
     {
 
=== modified file 'Percona-Server/sql/log_event.cc'
--- Percona-Server/sql/log_event.cc	2013-01-09 23:46:01 +0000
+++ Percona-Server/sql/log_event.cc	2013-01-21 06:27:51 +0000
@@ -3511,7 +3511,7 @@
         thd->enable_slow_log is set to the value of
         opt_log_slow_admin_statements).
       */
-      thd->enable_slow_log= opt_log_slow_slave_statements;
+      thd->enable_slow_log= TRUE;
     }
     else
     {
 
=== modified file 'Percona-Server/sql/slave.cc'
--- Percona-Server/sql/slave.cc	2012-09-17 13:08:32 +0000
+++ Percona-Server/sql/slave.cc	2013-01-21 06:27:51 +0000
@@ -2086,8 +2086,7 @@
 */
   thd->variables.max_allowed_packet= slave_max_allowed_packet;
   thd->slave_thread = 1;
-  thd->enable_slow_log= opt_log_slow_slave_statements;
-  thd->write_to_slow_log= opt_log_slow_slave_statements;
+  thd->enable_slow_log= TRUE;
   set_slave_thread_options(thd);
   thd->client_capabilities = CLIENT_LOCAL_FILES;
   mysql_mutex_lock(&LOCK_thread_count);
 
=== modified file 'Percona-Server/sql/sql_class.cc'
--- Percona-Server/sql/sql_class.cc	2012-10-27 05:16:07 +0000
+++ Percona-Server/sql/sql_class.cc	2013-01-21 06:27:51 +0000
@@ -4112,11 +4112,6 @@
   }
 #endif /* DBUG_OFF */
   query_id= new_query_id;
-  if (opt_slow_query_log_rate_type == SLOG_RT_QUERY)
-  {
-    const ulong& limit= variables.log_slow_rate_limit;
-    write_to_slow_log= limit == 0 || (query_id % limit) == 0;
-  }
 }
 
 /** Assign a new value to thd->mysys_var.  */
 
=== modified file 'Percona-Server/sql/sql_class.h'
--- Percona-Server/sql/sql_class.h	2012-12-14 03:09:41 +0000
+++ Percona-Server/sql/sql_class.h	2013-01-21 06:27:51 +0000
@@ -80,14 +80,14 @@
   SLOG_RT_SESSION, SLOG_RT_QUERY
 };
 #define QPLAN_NONE            0
-#define QPLAN_QC              1 << 0
-#define QPLAN_QC_NO           1 << 1
-#define QPLAN_FULL_SCAN       1 << 2
-#define QPLAN_FULL_JOIN       1 << 3
-#define QPLAN_TMP_TABLE       1 << 4
-#define QPLAN_TMP_DISK        1 << 5
-#define QPLAN_FILESORT        1 << 6
-#define QPLAN_FILESORT_DISK   1 << 7
+#define QPLAN_QC_NO           (1 << 0)
+#define QPLAN_FULL_SCAN       (1 << 1)
+#define QPLAN_FULL_JOIN       (1 << 2)
+#define QPLAN_TMP_TABLE       (1 << 3)
+#define QPLAN_TMP_DISK        (1 << 4)
+#define QPLAN_FILESORT        (1 << 5)
+#define QPLAN_FILESORT_DISK   (1 << 6)
+#define QPLAN_QC              (1 << 7)
 enum enum_log_slow_filter {
   SLOG_F_QC_NO, SLOG_F_FULL_SCAN, SLOG_F_FULL_JOIN,
   SLOG_F_TMP_TABLE, SLOG_F_TMP_DISK, SLOG_F_FILESORT,
@@ -1670,18 +1670,6 @@
 
   /*** Following variables used in slow_extended.patch ***/
   /*
-    Variable write_to_slow_log:
-     1) initialized in
-       * sql_connect.cc (log_slow_rate_limit support)
-       * slave.cc       (log_slow_slave_statements support)
-     2) The variable is initialized on the thread startup and remains
-        constant afterwards.  This will change when 
-        LP #712396 ("log_slow_slave_statements not work on replication 
-        threads without RESTART") is implemented.
-     3) An implementation of LP #688646 ("Make query sampling possible by query") should use it.
-  */
-  bool       write_to_slow_log;
-  /*
     Variable bytes_send_old saves value of thd->status_var.bytes_sent
     before query execution.
   */
 
=== modified file 'Percona-Server/sql/sql_connect.cc'
--- Percona-Server/sql/sql_connect.cc	2013-01-09 23:45:25 +0000
+++ Percona-Server/sql/sql_connect.cc	2013-01-21 06:27:51 +0000
@@ -1417,14 +1417,6 @@
   MYSQL_CONNECTION_START(thd->thread_id, &thd->security_ctx->priv_user[0],
                          (char *) thd->security_ctx->host_or_ip);
 
-  /*
-    If rate limiting of slow log writes is enabled, decide whether to log this 
-    new thread's queries or not. Uses extremely simple algorithm. :)
-  */
-  const ulong& limit= thd->variables.log_slow_rate_limit;
-  thd->write_to_slow_log= opt_slow_query_log_rate_type == SLOG_RT_SESSION &&
-                          (limit == 0 || (thd->thread_id % limit) == 0);
-
   prepare_new_connection_state(thd);
   return FALSE;
 }
 
=== modified file 'Percona-Server/sql/sql_parse.cc'
--- Percona-Server/sql/sql_parse.cc	2013-01-09 23:45:25 +0000
+++ Percona-Server/sql/sql_parse.cc	2013-01-21 06:27:51 +0000
@@ -1535,7 +1535,7 @@
   /* Follow the slow log filter configuration. */
   if (thd->variables.log_slow_filter != 0 &&
       (!(thd->variables.log_slow_filter & thd->query_plan_flags) ||
-       ((thd->variables.log_slow_filter & SLOG_F_QC_NO) &&
+       ((thd->variables.log_slow_filter & (1UL << SLOG_F_QC_NO)) &&
         (thd->query_plan_flags & QPLAN_QC))))
     DBUG_VOID_RETURN;
 
@@ -1567,10 +1567,20 @@
   copy_global_to_session(thd, SLOG_UG_MIN_EXAMINED_ROW_LIMIT,
                          &g.min_examined_row_limit);
 
-  /* Do not log this thread's queries due to rate limiting. */
-  if (!thd->write_to_slow_log && (thd->variables.long_query_time >= 1000000
-                                  || (ulong) query_exec_time < 1000000))
-    DBUG_VOID_RETURN;
+  if (opt_slow_query_log_rate_type == SLOG_RT_QUERY
+      && thd->variables.log_slow_rate_limit
+      && thd->query_id % thd->variables.log_slow_rate_limit
+      && (thd->variables.long_query_time >= 1000000
+          || (ulong) query_exec_time < 1000000)) {
+    DBUG_VOID_RETURN;
+  }
+  if (opt_slow_query_log_rate_type == SLOG_RT_SESSION
+      && thd->variables.log_slow_rate_limit
+      && thd->thread_id % thd->variables.log_slow_rate_limit
+      && (thd->variables.long_query_time >= 1000000
+          || (ulong) query_exec_time < 1000000)) {
+    DBUG_VOID_RETURN;
+  }
 
 
   /*
 
=== modified file 'Percona-Server/sql/sys_vars.cc'
--- Percona-Server/sql/sys_vars.cc	2012-10-17 03:47:45 +0000
+++ Percona-Server/sql/sys_vars.cc	2013-01-21 06:27:51 +0000
@@ -3205,7 +3205,8 @@
 const char *slow_query_log_timestamp_precision_name[]= { "second", "microsecond", 0 };
 static Sys_var_enum Sys_slow_query_log_timestamp_precision(
        "slow_query_log_timestamp_precision",
-       "Log slow statements executed by stored procedure to the slow log if it is open. [second, microsecond]",
+       "Select the timestamp precision for use in the slow query log.  "
+       "[second, microsecond]",
        GLOBAL_VAR(opt_slow_query_log_timestamp_precision), CMD_LINE(REQUIRED_ARG),
        slow_query_log_timestamp_precision_name, DEFAULT(SLOG_SECOND));
 
 
=== modified file 'Percona-Server/storage/innobase/handler/ha_innodb.cc'
--- Percona-Server/storage/innobase/handler/ha_innodb.cc	2013-01-18 03:34:53 +0000
+++ Percona-Server/storage/innobase/handler/ha_innodb.cc	2013-01-21 06:27:51 +0000
@@ -1779,7 +1779,7 @@
 	trx->fake_changes = THDVAR(thd, fake_changes);
 
 #ifdef EXTENDED_SLOWLOG
-	if (thd_log_slow_verbosity(thd) & SLOG_V_INNODB) {
+	if (thd_log_slow_verbosity(thd) & (1ULL << SLOG_V_INNODB)) {
 		trx->take_stats = TRUE;
 	} else {
 		trx->take_stats = FALSE;