Merge lp:~dingqi-lxb/percona-server/5.5_log_queries_in_memory into lp:percona-server/5.5

[林晓斌]

patch for https://blueprints.launchpad.net/percona-server/+spec/log-queries-in-memory.

add a variable 'slowlog_in_memory_audit_max_memory' and global status 'slow_log_current_memory'

If the current_memory grows larger than max_memory, the eldest ones will be wash out.
Same action happens when max_mamory are set to a new value that is less than current_memory.

[Oleg Tsarev (tsarev)]

1. Please add patch name to the "patches/series" file
2. About innodb_trx_id. Please look to two following cases:
 * log_slow_verbosity doesn't set "innodb"
 * query doesn't use the InnoDB
In first case slow query log will has no information about InnoDB
In second case slow query will have line "# No InnoDB statistics available for this query\n"
In this two cases innodb_trx_id will be incorrect, and you can't use and setup it.

Please handle variable innodb_was_used correctly (at least for innodb_trx_id)

3. Following is very, very bad:
+ if (general_query)
+ {
....
+ }
+ else
+ {
+ this->general_query= "NULL";
+ this->general_query_len= 5;
+ }
You are break SQL semantic. For example query:
SELECT * FROM INSFORMATION_SCHEMA.I_S_SLOW_LOG WHERE QUERY IS NULL
or any join will not work correctly.
You are break SQL language semantic by string "NULL" instead of NULL

Same for Schema.

4. I_S_SLOW_LOG not very good name. Why SLOW_LOG bad?

5. Please add documentation to the doc/

6. Sleep in the test file - bad idea. Please replace this by debug variable query_exec_time.

7. Please add tests to sys_vars suite for the all added variables.

Please fix this, and I will review again.

review: Needs Fixing

[Oleg Tsarev (tsarev)]

8.
+ ulonglong utime_of_query= thd->current_utime() - thd->utime_after_lock;
+ if (utime_of_query <= thd->variables.long_query_time)
+ return;

Please look into the slow_extended.patch:

static inline ulonglong get_query_exec_time(THD *thd, ulonglong cur_utime)
...
thd->server_status|= SERVER_QUERY_WAS_SLOW;

Please better use this status variable, instead of calculate query execution time directly.

[林晓斌 (dingqi-lxb)]

Thank you. Oleg, I have some items to discuss.

2. About innodb_trx_id. Please look to two following cases
   In these two cases, the variable thd->innodb_trx_id is set to 0. It seems that I have to show it in the result table as 0, is there other result even use innodb_was_used ?

8.About calculating query execution time directly, it is because that I have to get the query_time, the status is not enough.

* Why plugin doesn't uninstall in test?
  You mean that it shows " Plugin is busy and will be uninstalled on shutdown" in result-file? It is the same with the demo for audit plugin "null_audit", the strategy decided by mysqld

[Oleg Tsarev (tsarev)]

On Mon, Dec 12, 2011 at 12:05 PM, 林晓斌 <email address hidden> wrote:
> Thank you. Oleg, I have some items to discuss.
>
> 2. About innodb_trx_id. Please look to two following cases
>   In these two cases, the variable thd->innodb_trx_id is set to 0.  It seems that I have to show it in the result table as 0, is there other result even use innodb_was_used ?

I think right decision is "NULL" value instead of 0.
>
> 8.About calculating query execution time directly, it is because that I have to get the query_time, the status is not enough.
>
> * Why plugin doesn't uninstall in test?
>  You mean that it shows " Plugin is busy and will be uninstalled on shutdown" in result-file? It is the same with the demo for audit plugin "null_audit", the strategy decided by mysqld

Ok

> --
> https://code.launchpad.net/~dingqi-lxb/percona-server/5.5_log_queries_in_memory/+merge/85251
> You are reviewing the proposed merge of lp:~dingqi-lxb/percona-server/5.5_log_queries_in_memory into lp:percona-server.

--
Oleg Tsarev, Software Engineer, Percona Inc.

[林晓斌 (dingqi-lxb)]

2. About innodb_trx_id. Generally, when the thd->innodb_trx_id is 0, the value of "INNODB_TRX_ID" should show NULL, so the thd->innodb_was_used will not be imported here.

7. Please add tests to sys_vars suite for the all added variables.
   The variable add in this plugin will not be seen in other test-case, it can only be seen the plugin is installed. So, is test-case in sys_vars suits necessary?

[Stewart Smith (stewart)]

On Wed, 21 Dec 2011 02:50:35 -0000, 林晓斌 <email address hidden> wrote:
> +There are two plugins in the feature. They can be installed by
> command ``"install plugin SLOWLOG_IN_MEMORY_AUDIT soname
> 'slowlog_in_memory.so'"`` and ``"install plugin SLOW_LOG soname
> 'slowlog_in_memory.so'"``, they work by keeping one list in memory.

I think we should be consistent in naming. SLOW_LOG instead of SLOWLOG
and slow_log instead of slowlog.
--
Stewart Smith

[Baron Schwartz (baron-xaprb)]

I'm sorry that I haven't noticed this discussion before, but I believe that it would be best to avoid a query time in milliseconds:

1. It should have microsecond resolution. Milliseconds is not enough.
2. It should be named EXEC_TIME and should be a floating-point value in seconds so the user does not have to convert the value to seconds.

[lp:~dingqi-lxb/percona-server/5.5_log_queries_in_memory]

199. By 林晓斌 on 2012-01-01

merge from trunk

200. By 林晓斌 on 2012-01-01

add slowlog_in_memory.patch

Unmerged revisions

200. By 林晓斌 on 2012-01-01

add slowlog_in_memory.patch

199. By 林晓斌 on 2012-01-01

merge from trunk

=== added file 'doc/source/diagnostics/slow_log_in_memory.rst'
--- doc/source/diagnostics/slow_log_in_memory.rst	1970-01-01 00:00:00 +0000
+++ doc/source/diagnostics/slow_log_in_memory.rst	2011-12-29 03:46:24 +0000
@@ -0,0 +1,74 @@
+.. _slow_log_in_memory:
+
+=================
+ Slow Log In Memory
+=================
+
+The feature is used to save slow queries in memory. This feature adds an ``INFORMATION_SCHEMA.SLOW_LOG`` table to show the latest queries, a variable to limit the max memory used, and status to show the status of memory used. 
+
+There are two plugins in the feature. They can be installed by command ``"install plugin SLOWLOG_IN_MEMORY_AUDIT soname 'slowlog_in_memory.so'"`` and ``"install plugin SLOW_LOG soname 'slowlog_in_memory.so'"``, they work by keeping one list in memory. 
+
+
+Other Information
+=================
+
+  * Author/Origin:
+     *Percona*; *Percona* added an ``INFORMATION_SCHEMA`` table and the :variable:`slowlog_in_memory_audit_max_memory` and the :status:`slow_log_current_memory`.
+
+System Variables
+================
+
+.. variable:: slowlog_in_memory_audit_max_memory
+
+     :cli: Yes
+     :conf: Yes
+     :scope: Global
+     :dyn: Yes
+     :vartype: ULONG
+     :default: 1M
+     :range: 0 - 1G
+
+The variable is used to limit the max-memory used for slow log. If a new slow query will make the `current_memory` bigger than this value, the most eldest items will be discarded, until there is enough memory for new item. When the value is decrease dynamically, it behaves the same.
+
+Status Variables
+================
+
+One new status variable was introduced by this feature.
+
+.. variable:: slow_log_current_memory
+
+     :vartype: ULONG
+     :scope: Global
+
+The variable showes the current memory used for the slow queries. It can never be bigger than the `slowlog_in_memory_audit_max_memory` variable.
+
+
+INFORMATION_SCHEMA Tables
+=========================
+
+.. table:: INFORMATION_SCHEMA.SLOW_LOG
+
+  :column EVENT_ID: A global increment id for every record in the table, can be used to identify every one.
+  :column TIMESTAMP: The timestamp when the query stop.
+  :column THREAD_ID: The thread_id of the query.
+  :column DB: The current database() of the query, may be NULL.
+  :column INNODB_TRX_ID: The Innodb_trx_id if InnoDB is used, may be NULL.
+  :column ERROR: The errno of the query, 0 means no error.
+  :column MS_QUERY_TIME: The query_exec_time of the query, in second.
+  :column QUERY: The query statement.
+
+This table holds the lastest slow queries.
+
+Example: ::
+
+  mysql> select * from information_schema.slow_log \G
+  *************************** 1. row ***************************
+       EVENT_ID: 1
+      TIMESTAMP: 1323753896
+      THREAD_ID: 2
+             DB: test
+  INNODB_TRX_ID: NULL
+          ERRNO: 0
+  MS_QUERY_TIME: 3001
+          QUERY: select sleep(3)
+

=== modified file 'patches/series'
--- patches/series	2011-12-16 09:37:26 +0000
+++ patches/series	2011-12-29 03:46:24 +0000
@@ -62,3 +62,4 @@
 bug45702.patch
 group_commit.patch
 warning_fixes.patch
+slowlog_in_memory.patch

=== added file 'patches/slow_extended.patch'
--- patches/slow_extended.patch	1970-01-01 00:00:00 +0000
+++ patches/slow_extended.patch	2011-12-29 03:46:24 +0000
@@ -0,0 +1,2772 @@
+# name       : slow_extended.patch
+# introduced : 11 or before
+# maintainer : Oleg
+#
+#!!! notice !!!
+# Any small change to this file in the main branch
+# should be done or reviewed by the maintainer!
+--- a/include/mysql/plugin_audit.h.pp
++++ b/include/mysql/plugin_audit.h.pp
+@@ -186,6 +186,16 @@
+ char *thd_security_context(void* thd, char *buffer, unsigned int length,
+                            unsigned int max_query_len);
+ void thd_inc_row_count(void* thd);
++void increment_thd_innodb_stats(void* thd,
++                    unsigned long long trx_id,
++                    long io_reads,
++                    long long io_read,
++                    long io_reads_wait_timer,
++                    long lock_que_wait_timer,
++                    long que_wait_timer,
++                    long page_access);
++unsigned long thd_log_slow_verbosity(const void* thd);
++int thd_opt_slow_log();
+ int mysql_tmpfile(const char *prefix);
+ int thd_killed(const void* thd);
+ unsigned long thd_get_thread_id(const void* thd);
+--- a/include/mysql/plugin_auth.h.pp
++++ b/include/mysql/plugin_auth.h.pp
+@@ -186,6 +186,16 @@
+ char *thd_security_context(void* thd, char *buffer, unsigned int length,
+                            unsigned int max_query_len);
+ void thd_inc_row_count(void* thd);
++void increment_thd_innodb_stats(void* thd,
++                    unsigned long long trx_id,
++                    long io_reads,
++                    long long io_read,
++                    long io_reads_wait_timer,
++                    long lock_que_wait_timer,
++                    long que_wait_timer,
++                    long page_access);
++unsigned long thd_log_slow_verbosity(const void* thd);
++int thd_opt_slow_log();
+ int mysql_tmpfile(const char *prefix);
+ int thd_killed(const void* thd);
+ unsigned long thd_get_thread_id(const void* thd);
+--- a/include/mysql/plugin_ftparser.h.pp
++++ b/include/mysql/plugin_ftparser.h.pp
+@@ -139,6 +139,16 @@
+ char *thd_security_context(void* thd, char *buffer, unsigned int length,
+                            unsigned int max_query_len);
+ void thd_inc_row_count(void* thd);
++void increment_thd_innodb_stats(void* thd,
++                    unsigned long long trx_id,
++                    long io_reads,
++                    long long io_read,
++                    long io_reads_wait_timer,
++                    long lock_que_wait_timer,
++                    long que_wait_timer,
++                    long page_access);
++unsigned long thd_log_slow_verbosity(const void* thd);
++int thd_opt_slow_log();
+ int mysql_tmpfile(const char *prefix);
+ int thd_killed(const void* thd);
+ unsigned long thd_get_thread_id(const void* thd);
+--- a/include/mysql/plugin.h
++++ b/include/mysql/plugin.h
+@@ -545,6 +545,17 @@
+ /* Increments the row counter, see THD::row_count */
+ void thd_inc_row_count(MYSQL_THD thd);
+ 
++void increment_thd_innodb_stats(MYSQL_THD thd,
++                    unsigned long long trx_id,
++                    long io_reads,
++                    long long io_read,
++                    long io_reads_wait_timer,
++                    long lock_que_wait_timer,
++                    long que_wait_timer,
++                    long page_access);
++unsigned long thd_log_slow_verbosity(const MYSQL_THD thd);
++int thd_opt_slow_log();
++#define EXTENDED_SLOWLOG
+ /**
+   Create a temporary file.
+ 
+--- /dev/null
++++ b/patch_info/slow_extended.info
+@@ -0,0 +1,25 @@
++File=slow_extended.patch
++Name=Extended statistics in slow.log (not InnoDB part)
++Version=1.3
++Author=Percona <[e-mail]>
++License=GPL
++Comment=
++Changelog
++2008-11-26
++YK: Fix inefficient determination of trx, Make not to call useless gettimeofday when don't use slow log. Make log_slow_queries dynamic (bool).
++
++2008-11-07
++VT: Moved log_slow_rate_limit in SHOW VARIABLE into right place
++
++2008-11
++Arjen Lentz: Fixups (backward compatibility) by Arjen Lentz <[e-mail]>
++
++2010-07
++1) Fix overflow of query time and lock time (Bug 600360) (slow_extended_fix_overflow.patch merged)
++2) Control global slow feature merged (control_global_slow.patch merged)
++3) Microseconds in slow query log merged (microseconds_in_slow_query_log.patch merged)
++4) Now use_global_long_query_time and use_global_log_slow_control are synonims. Add value "all" for use_global_log_slow_control (contol-global_slow-2.patch merged)
++5) Fix innodb_stats on replication (Bug 600684)
++6) Change variable types (system/command-line)
++2011-01
++Patch profiling_slow.patch was merged
+--- a/scripts/mysqldumpslow.sh
++++ b/scripts/mysqldumpslow.sh
+@@ -102,8 +102,8 @@
+     s/^#? Time: \d{6}\s+\d+:\d+:\d+.*\n//;
+     my ($user,$host) = s/^#? User\@Host:\s+(\S+)\s+\@\s+(\S+).*\n// ? ($1,$2) : ('','');
+ 
+-    s/^# Query_time: ([0-9.]+)\s+Lock_time: ([0-9.]+)\s+Rows_sent: ([0-9.]+).*\n//;
+-    my ($t, $l, $r) = ($1, $2, $3);
++    s/^# Query_time: (\d+(\.\d+)?)  Lock_time: (\d+(\.\d+)?)  Rows_sent: (\d+(\.\d+)?).*\n//;
++    my ($t, $l, $r) = ($1, $3, $5);
+     $t -= $l unless $opt{l};
+ 
+     # remove fluff that mysqld writes to log when it (re)starts:
+--- a/sql/event_scheduler.cc
++++ b/sql/event_scheduler.cc
+@@ -195,6 +195,7 @@
+   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);
+ 
+   /*
+--- a/sql/filesort.cc
++++ b/sql/filesort.cc
+@@ -193,6 +193,7 @@
+   {
+     status_var_increment(thd->status_var.filesort_scan_count);
+   }
++  thd->query_plan_flags|= QPLAN_FILESORT;
+ #ifdef CAN_TRUST_RANGE
+   if (select && select->quick && select->quick->records > 0L)
+   {
+@@ -261,6 +262,7 @@
+     /* filesort cannot handle zero-length records during merge. */
+     DBUG_ASSERT(param.sort_length != 0);
+ 
++    thd->query_plan_flags|= QPLAN_FILESORT_DISK;
+     if (table_sort.buffpek && table_sort.buffpek_len < maxbuffer)
+     {
+       my_free(table_sort.buffpek);
+@@ -1209,6 +1211,7 @@
+   DBUG_ENTER("merge_buffers");
+ 
+   status_var_increment(current_thd->status_var.filesort_merge_passes);
++  current_thd->query_plan_fsort_passes++;
+   if (param->not_killable)
+   {
+     killed= &not_killable;
+--- a/sql/log.cc
++++ b/sql/log.cc
+@@ -715,11 +715,13 @@
+ */
+ 
+ bool Log_to_csv_event_handler::
+-  log_slow(THD *thd, time_t current_time, time_t query_start_arg,
++  log_slow(THD *thd, ulonglong current_utime, time_t query_start_arg,
+            const char *user_host, uint user_host_len,
+            ulonglong query_utime, ulonglong lock_utime, bool is_command,
+            const char *sql_text, uint sql_text_len)
+ {
++  time_t current_time= my_time_possible_from_micro(current_utime);
++
+   TABLE_LIST table_list;
+   TABLE *table;
+   bool result= TRUE;
+@@ -935,14 +937,14 @@
+ /** Wrapper around MYSQL_LOG::write() for slow log. */
+ 
+ bool Log_to_file_event_handler::
+-  log_slow(THD *thd, time_t current_time, time_t query_start_arg,
++  log_slow(THD *thd, ulonglong current_utime, time_t query_start_arg,
+            const char *user_host, uint user_host_len,
+            ulonglong query_utime, ulonglong lock_utime, bool is_command,
+            const char *sql_text, uint sql_text_len)
+ {
+   Silence_log_table_errors error_handler;
+   thd->push_internal_handler(&error_handler);
+-  bool retval= mysql_slow_log.write(thd, current_time, query_start_arg,
++  bool retval= mysql_slow_log.write(thd, current_utime, query_start_arg,
+                                     user_host, user_host_len,
+                                     query_utime, lock_utime, is_command,
+                                     sql_text, sql_text_len);
+@@ -1200,8 +1202,6 @@
+ 
+   if (*slow_log_handler_list)
+   {
+-    time_t current_time;
+-
+     /* do not log slow queries from replication threads */
+     if (thd->slave_thread && !opt_log_slow_slave_statements)
+       return 0;
+@@ -1216,16 +1216,29 @@
+     /* fill in user_host value: the format is "%s[%s] @ %s [%s]" */
+     user_host_len= (strxnmov(user_host_buff, MAX_USER_HOST_SIZE,
+                              sctx->priv_user ? sctx->priv_user : "", "[",
+-                             sctx->user ? sctx->user : "", "] @ ",
++                             sctx->user ? sctx->user : (thd->slave_thread ? "SQL_SLAVE" : ""), "] @ ",
+                              sctx->host ? sctx->host : "", " [",
+                              sctx->ip ? sctx->ip : "", "]", NullS) -
+                     user_host_buff);
+ 
+-    current_time= my_time_possible_from_micro(current_utime);
+     if (thd->start_utime)
+     {
+-      query_utime= (current_utime - thd->start_utime);
+-      lock_utime=  (thd->utime_after_lock - thd->start_utime);
++      if(current_utime < thd->start_utime)
++      {
++        query_utime= 0;
++      }
++      else
++      {
++        query_utime= (current_utime - thd->start_utime);
++      }
++      if(thd->utime_after_lock < thd->start_utime)
++      {
++        lock_utime= 0;
++      }
++      else
++      {
++        lock_utime= (thd->utime_after_lock - thd->start_utime);
++      }
+     }
+     else
+     {
+@@ -1240,7 +1253,7 @@
+     }
+ 
+     for (current_handler= slow_log_handler_list; *current_handler ;)
+-      error= (*current_handler++)->log_slow(thd, current_time, thd->start_time,
++      error= (*current_handler++)->log_slow(thd, current_utime, thd->start_time,
+                                             user_host_buff, user_host_len,
+                                             query_utime, lock_utime, is_command,
+                                             query, query_length) || error;
+@@ -2656,12 +2669,13 @@
+     TRUE - error occured
+ */
+ 
+-bool MYSQL_QUERY_LOG::write(THD *thd, time_t current_time,
++bool MYSQL_QUERY_LOG::write(THD *thd, ulonglong current_utime,
+                             time_t query_start_arg, const char *user_host,
+                             uint user_host_len, ulonglong query_utime,
+                             ulonglong lock_utime, bool is_command,
+                             const char *sql_text, uint sql_text_len)
+ {
++  time_t current_time= my_time_possible_from_micro(current_utime);
+   bool error= 0;
+   DBUG_ENTER("MYSQL_QUERY_LOG::write");
+ 
+@@ -2683,17 +2697,28 @@
+ 
+     if (!(specialflag & SPECIAL_SHORT_LOG_FORMAT))
+     {
+-      if (current_time != last_time)
++      if (opt_slow_query_log_timestamp_always || current_time != last_time)
+       {
+         last_time= current_time;
+         struct tm start;
+         localtime_r(&current_time, &start);
+-
+-        buff_len= my_snprintf(buff, sizeof buff,
+-                              "# Time: %02d%02d%02d %2d:%02d:%02d\n",
+-                              start.tm_year % 100, start.tm_mon + 1,
+-                              start.tm_mday, start.tm_hour,
+-                              start.tm_min, start.tm_sec);
++	if(opt_slow_query_log_timestamp_precision & SLOG_MICROSECOND)
++	{
++	  ulonglong microsecond = current_utime % (1000 * 1000);
++	  buff_len= snprintf(buff, sizeof buff,
++	    "# Time: %02d%02d%02d %2d:%02d:%02d.%010lld\n",
++            start.tm_year % 100, start.tm_mon + 1,
++	    start.tm_mday, start.tm_hour,
++	    start.tm_min, start.tm_sec,microsecond);
++	}
++	else
++	{
++	  buff_len= my_snprintf(buff, sizeof buff,
++	    "# Time: %02d%02d%02d %2d:%02d:%02d\n",
++            start.tm_year % 100, start.tm_mon + 1,
++	    start.tm_mday, start.tm_hour,
++	    start.tm_min, start.tm_sec);
++	}
+ 
+         /* Note that my_b_write() assumes it knows the length for this */
+         if (my_b_write(&log_file, (uchar*) buff, buff_len))
+@@ -2710,13 +2735,71 @@
+     /* 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));
+     if (my_b_printf(&log_file,
+-                    "# Query_time: %s  Lock_time: %s"
+-                    " Rows_sent: %lu  Rows_examined: %lu\n",
++                    "# 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",
++                    (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) == (uint) -1)
++                    (ulong) thd->examined_row_count,
++                    ((long) thd->get_row_count_func() > 0 ) ? (ulong) thd->get_row_count_func() : 0,
++                    (ulong) thd->sent_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)
+       tmp_errno= errno;
++
++#if defined(ENABLED_PROFILING)
++    thd->profiling.print_current(&log_file);
++#endif
++    if (thd->innodb_was_used)
++    {
++      char buf[20];
++      snprintf(buf, 20, "%llX", thd->innodb_trx_id);
++      if (my_b_printf(&log_file,
++                    "# InnoDB_trx_id: %s\n", buf) == (uint) -1)
++        tmp_errno=errno;
++    }
++    if ((thd->variables.log_slow_verbosity & (ULL(1) << SLOG_V_QUERY_PLAN)) &&
++         my_b_printf(&log_file,
++                    "# QC_Hit: %s  Full_scan: %s  Full_join: %s  Tmp_table: %s  Tmp_table_on_disk: %s\n" \
++                    "# Filesort: %s  Filesort_on_disk: %s  Merge_passes: %lu\n",
++                    ((thd->query_plan_flags & QPLAN_QC) ? "Yes" : "No"),
++                    ((thd->query_plan_flags & QPLAN_FULL_SCAN) ? "Yes" : "No"),
++                    ((thd->query_plan_flags & QPLAN_FULL_JOIN) ? "Yes" : "No"),
++                    ((thd->query_plan_flags & QPLAN_TMP_TABLE) ? "Yes" : "No"),
++                    ((thd->query_plan_flags & QPLAN_TMP_DISK) ? "Yes" : "No"),
++                    ((thd->query_plan_flags & QPLAN_FILESORT) ? "Yes" : "No"),
++                    ((thd->query_plan_flags & QPLAN_FILESORT_DISK) ? "Yes" : "No"),
++                    thd->query_plan_fsort_passes) == (uint) -1)
++      tmp_errno=errno;
++    if ((thd->variables.log_slow_verbosity & (ULL(1) << SLOG_V_INNODB)) && thd->innodb_was_used)
++    {
++      char buf[3][20];
++      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);
++      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_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;
++    } 
++    else
++    {
++      if ((thd->variables.log_slow_verbosity & (ULL(1) << SLOG_V_INNODB)) &&
++          my_b_printf(&log_file,"# No InnoDB statistics available for this query\n") == (uint) -1)
++        tmp_errno=errno;
++    }
++
+     if (thd->db && strcmp(thd->db, db))
+     {						// Database changed
+       if (my_b_printf(&log_file,"use %s;\n",thd->db) == (uint) -1)
+--- a/sql/log.h
++++ b/sql/log.h
+@@ -242,7 +242,7 @@
+              uint user_host_len, int thread_id,
+              const char *command_type, uint command_type_len,
+              const char *sql_text, uint sql_text_len);
+-  bool write(THD *thd, time_t current_time, time_t query_start_arg,
++  bool write(THD *thd, ulonglong current_time, time_t query_start_arg,
+              const char *user_host, uint user_host_len,
+              ulonglong query_utime, ulonglong lock_utime, bool is_command,
+              const char *sql_text, uint sql_text_len);
+@@ -515,7 +515,7 @@
+   virtual bool init()= 0;
+   virtual void cleanup()= 0;
+ 
+-  virtual bool log_slow(THD *thd, time_t current_time,
++  virtual bool log_slow(THD *thd, ulonglong current_time,
+                         time_t query_start_arg, const char *user_host,
+                         uint user_host_len, ulonglong query_utime,
+                         ulonglong lock_utime, bool is_command,
+@@ -544,7 +544,7 @@
+   virtual bool init();
+   virtual void cleanup();
+ 
+-  virtual bool log_slow(THD *thd, time_t current_time,
++  virtual bool log_slow(THD *thd, ulonglong current_utime,
+                         time_t query_start_arg, const char *user_host,
+                         uint user_host_len, ulonglong query_utime,
+                         ulonglong lock_utime, bool is_command,
+@@ -576,7 +576,7 @@
+   virtual bool init();
+   virtual void cleanup();
+ 
+-  virtual bool log_slow(THD *thd, time_t current_time,
++  virtual bool log_slow(THD *thd, ulonglong current_utime,
+                         time_t query_start_arg, const char *user_host,
+                         uint user_host_len, ulonglong query_utime,
+                         ulonglong lock_utime, bool is_command,
+--- a/sql/mysqld.cc
++++ b/sql/mysqld.cc
+@@ -421,6 +421,10 @@
+ char* opt_secure_file_priv;
+ my_bool opt_log_slow_admin_statements= 0;
+ my_bool opt_log_slow_slave_statements= 0;
++my_bool opt_log_slow_sp_statements= 0;
++my_bool opt_slow_query_log_timestamp_always= 0;
++ulonglong opt_slow_query_log_use_global_control= 0;
++ulong opt_slow_query_log_timestamp_precision= 0;
+ my_bool lower_case_file_system= 0;
+ my_bool opt_large_pages= 0;
+ my_bool opt_super_large_pages= 0;
+@@ -5892,14 +5896,10 @@
+    "Don't log extra information to update and slow-query logs.",
+    &opt_short_log_format, &opt_short_log_format,
+    0, GET_BOOL, NO_ARG, 0, 0, 0, 0, 0, 0},
+-  {"log-slow-admin-statements", 0,
+-   "Log slow OPTIMIZE, ANALYZE, ALTER and other administrative statements to "
+-   "the slow log if it is open.", &opt_log_slow_admin_statements,
+-   &opt_log_slow_admin_statements, 0, GET_BOOL, NO_ARG, 0, 0, 0, 0, 0, 0},
+- {"log-slow-slave-statements", 0,
++ /*{"log-slow-slave-statements", 0,
+   "Log slow statements executed by slave thread to the slow log if it is open.",
+   &opt_log_slow_slave_statements, &opt_log_slow_slave_statements,
+-  0, GET_BOOL, NO_ARG, 0, 0, 0, 0, 0, 0},
++  0, GET_BOOL, NO_ARG, 0, 0, 0, 0, 0, 0},*/
+   {"log-slow-queries", OPT_SLOW_QUERY_LOG,
+    "Log slow queries to a table or log file. Defaults logging to table "
+    "mysql.slow_log or hostname-slow.log if --log-output=file is used. "
+@@ -7288,6 +7288,10 @@
+ 
+ C_MODE_END
+ 
++/* defined in sys_vars.cc */
++extern void init_log_slow_verbosity();
++extern void init_slow_query_log_use_global_control();
++
+ /**
+   Get server options from the command line,
+   and perform related server initializations.
+@@ -7437,6 +7441,8 @@
+   global_system_variables.long_query_time= (ulonglong)
+     (global_system_variables.long_query_time_double * 1e6);
+ 
++  init_log_slow_verbosity();
++  init_slow_query_log_use_global_control();
+   if (opt_short_log_format)
+     opt_specialflag|= SPECIAL_SHORT_LOG_FORMAT;
+ 
+--- a/sql/mysqld.h
++++ b/sql/mysqld.h
+@@ -116,6 +116,10 @@
+ extern char* opt_secure_backup_file_priv;
+ extern size_t opt_secure_backup_file_priv_len;
+ extern my_bool opt_log_slow_admin_statements, opt_log_slow_slave_statements;
++extern my_bool opt_log_slow_sp_statements;
++extern my_bool opt_slow_query_log_timestamp_always;
++extern ulonglong opt_slow_query_log_use_global_control;
++extern ulong opt_slow_query_log_timestamp_precision;
+ extern my_bool sp_automatic_privileges, opt_noacl;
+ extern my_bool opt_old_style_user_limits, trust_function_creators;
+ extern uint opt_crash_binlog_innodb;
+--- a/sql/slave.cc
++++ b/sql/slave.cc
+@@ -2038,6 +2038,7 @@
+     + MAX_LOG_EVENT_HEADER;  /* note, incr over the global not session var */
+   thd->slave_thread = 1;
+   thd->enable_slow_log= opt_log_slow_slave_statements;
++  thd->write_to_slow_log= opt_log_slow_slave_statements;
+   set_slave_thread_options(thd);
+   thd->client_capabilities = CLIENT_LOCAL_FILES;
+   mysql_mutex_lock(&LOCK_thread_count);
+--- a/sql/sp_head.cc
++++ b/sql/sp_head.cc
+@@ -2152,7 +2152,7 @@
+     DBUG_PRINT("info",(" %.*s: eval args done", (int) m_name.length, 
+                        m_name.str));
+   }
+-  if (!(m_flags & LOG_SLOW_STATEMENTS) && thd->enable_slow_log)
++  if (!(m_flags & LOG_SLOW_STATEMENTS || opt_log_slow_sp_statements) && thd->enable_slow_log)
+   {
+     DBUG_PRINT("info", ("Disabling slow log for the execution"));
+     save_enable_slow_log= true;
+--- a/sql/sql_cache.cc
++++ b/sql/sql_cache.cc
+@@ -1756,6 +1756,7 @@
+     response, we can't handle it anyway.
+   */
+   (void) trans_commit_stmt(thd);
++  thd->query_plan_flags|= QPLAN_QC;
+   if (!thd->stmt_da->is_set())
+     thd->stmt_da->disable_status();
+ 
+@@ -1766,6 +1767,7 @@
+ err_unlock:
+   unlock();
+ err:
++  thd->query_plan_flags|= QPLAN_QC_NO;
+   MYSQL_QUERY_CACHE_MISS(thd->query());
+   DBUG_RETURN(0);				// Query was not cached
+ }
+--- a/sql/sql_class.cc
++++ b/sql/sql_class.cc
+@@ -616,6 +616,37 @@
+   thd->warning_info->inc_current_row_for_warning();
+ }
+ 
++extern "C"
++void increment_thd_innodb_stats(THD* thd,
++                                unsigned long long trx_id,
++                                long io_reads,
++                                long long  io_read,
++                                long      io_reads_wait_timer,
++                                long      lock_que_wait_timer,
++                                long      que_wait_timer,
++                                long      page_access)
++{
++  thd->innodb_was_used=               TRUE;
++  thd->innodb_trx_id=                 trx_id;
++  thd->innodb_io_reads+=              io_reads;
++  thd->innodb_io_read+=               io_read;
++  thd->innodb_io_reads_wait_timer+=   io_reads_wait_timer;
++  thd->innodb_lock_que_wait_timer+=   lock_que_wait_timer;
++  thd->innodb_innodb_que_wait_timer+= que_wait_timer;
++  thd->innodb_page_access+=           page_access;
++}
++
++extern "C"
++unsigned long thd_log_slow_verbosity(const THD *thd)
++{
++  return (unsigned long) thd->variables.log_slow_verbosity;
++}
++
++extern "C"
++int thd_opt_slow_log()
++{
++  return (int) opt_slow_log;
++}
+ 
+ /**
+   Dumps a text description of a thread, its security context
+@@ -942,6 +973,8 @@
+                            const char* msg,
+                            MYSQL_ERROR ** cond_hdl)
+ {
++  last_errno= sql_errno;
++
+   if (!m_internal_handler)
+   {
+     *cond_hdl= NULL;
+@@ -1236,6 +1269,8 @@
+   /* Initialize the Debug Sync Facility. See debug_sync.cc. */
+   debug_sync_init_thread(this);
+ #endif /* defined(ENABLED_DEBUG_SYNC) */
++
++  clear_slow_extended();
+ }
+ 
+ 
+@@ -3682,8 +3717,6 @@
+   backup->in_sub_stmt=     in_sub_stmt;
+   backup->enable_slow_log= enable_slow_log;
+   backup->limit_found_rows= limit_found_rows;
+-  backup->examined_row_count= examined_row_count;
+-  backup->sent_row_count=   sent_row_count;
+   backup->cuted_fields=     cuted_fields;
+   backup->client_capabilities= client_capabilities;
+   backup->savepoints= transaction.savepoints;
+@@ -3691,6 +3724,7 @@
+     first_successful_insert_id_in_prev_stmt;
+   backup->first_successful_insert_id_in_cur_stmt= 
+     first_successful_insert_id_in_cur_stmt;
++  reset_sub_statement_state_slow_extended(backup);
+ 
+   if ((!lex->requires_prelocking() || is_update_query(lex->sql_command)) &&
+       !is_current_stmt_binlog_format_row())
+@@ -3706,13 +3740,74 @@
+   /* Disable result sets */
+   client_capabilities &= ~CLIENT_MULTI_RESULTS;
+   in_sub_stmt|= new_state;
+-  examined_row_count= 0;
+-  sent_row_count= 0;
+   cuted_fields= 0;
+   transaction.savepoints= 0;
+   first_successful_insert_id_in_cur_stmt= 0;
+ }
+ 
++void THD::clear_slow_extended()
++{
++  DBUG_ENTER("THD::clear_slow_extended");
++  sent_row_count=               0;
++  examined_row_count=           0;
++  bytes_sent_old=               status_var.bytes_sent;
++  tmp_tables_used=              0;
++  tmp_tables_disk_used=         0;
++  tmp_tables_size=              0;
++  innodb_was_used=              FALSE;
++  innodb_trx_id=                0;
++  innodb_io_reads=              0;
++  innodb_io_read=               0;
++  innodb_io_reads_wait_timer=   0;
++  innodb_lock_que_wait_timer=   0;
++  innodb_innodb_que_wait_timer= 0;
++  innodb_page_access=           0;
++  query_plan_flags=             QPLAN_NONE;
++  query_plan_fsort_passes=      0;
++  last_errno=                   0;
++  DBUG_VOID_RETURN;
++}
++
++void THD::reset_sub_statement_state_slow_extended(Sub_statement_state *backup)
++{
++  DBUG_ENTER("THD::reset_sub_statement_state_slow_extended");
++  backup->sent_row_count=               sent_row_count;
++  backup->examined_row_count=           examined_row_count;
++  backup->tmp_tables_used=              tmp_tables_used;
++  backup->tmp_tables_disk_used=         tmp_tables_disk_used;
++  backup->tmp_tables_size=              tmp_tables_size;
++  backup->innodb_was_used=              innodb_was_used;
++  backup->innodb_io_reads=              innodb_io_reads;
++  backup->innodb_io_read=               innodb_io_read;
++  backup->innodb_io_reads_wait_timer=   innodb_io_reads_wait_timer;
++  backup->innodb_lock_que_wait_timer=   innodb_lock_que_wait_timer;
++  backup->innodb_innodb_que_wait_timer= innodb_innodb_que_wait_timer;
++  backup->innodb_page_access=           innodb_page_access;
++  backup->query_plan_flags=             query_plan_flags;
++  backup->query_plan_fsort_passes=      query_plan_fsort_passes;
++  clear_slow_extended();
++  DBUG_VOID_RETURN;
++}
++
++void THD::restore_sub_statement_state_slow_extended(const Sub_statement_state *backup)
++{
++  DBUG_ENTER("THD::restore_sub_statement_state_slow_extended");
++  sent_row_count=                backup->sent_row_count;
++  examined_row_count+=           backup->examined_row_count;
++  tmp_tables_used+=              backup->tmp_tables_used;
++  tmp_tables_disk_used+=         backup->tmp_tables_disk_used;
++  tmp_tables_size+=              backup->tmp_tables_size;
++  innodb_was_used=               (innodb_was_used || backup->innodb_was_used);
++  innodb_io_reads+=              backup->innodb_io_reads;
++  innodb_io_read+=               backup->innodb_io_read;
++  innodb_io_reads_wait_timer+=   backup->innodb_io_reads_wait_timer;
++  innodb_lock_que_wait_timer+=   backup->innodb_lock_que_wait_timer;
++  innodb_innodb_que_wait_timer+= backup->innodb_innodb_que_wait_timer;
++  innodb_page_access+=           backup->innodb_page_access;
++  query_plan_flags|=             backup->query_plan_flags;
++  query_plan_fsort_passes+=      backup->query_plan_fsort_passes;
++  DBUG_VOID_RETURN;
++}
+ 
+ void THD::restore_sub_statement_state(Sub_statement_state *backup)
+ {
+@@ -3753,7 +3848,6 @@
+   first_successful_insert_id_in_cur_stmt= 
+     backup->first_successful_insert_id_in_cur_stmt;
+   limit_found_rows= backup->limit_found_rows;
+-  sent_row_count=   backup->sent_row_count;
+   client_capabilities= backup->client_capabilities;
+   /*
+     If we've left sub-statement mode, reset the fatal error flag.
+@@ -3771,8 +3865,8 @@
+     The following is added to the old values as we are interested in the
+     total complexity of the query
+   */
+-  examined_row_count+= backup->examined_row_count;
+   cuted_fields+=       backup->cuted_fields;
++  restore_sub_statement_state_slow_extended(backup);
+   DBUG_VOID_RETURN;
+ }
+ 
+--- a/sql/sql_class.h
++++ b/sql/sql_class.h
+@@ -60,6 +60,33 @@
+ enum enum_duplicates { DUP_ERROR, DUP_REPLACE, DUP_UPDATE };
+ enum enum_delay_key_write { DELAY_KEY_WRITE_NONE, DELAY_KEY_WRITE_ON,
+ 			    DELAY_KEY_WRITE_ALL };
++enum enum_slow_query_log_use_global_control {
++  SLOG_UG_LOG_SLOW_FILTER, SLOG_UG_LOG_SLOW_RATE_LIMIT
++  , SLOG_UG_LOG_SLOW_VERBOSITY, SLOG_UG_LONG_QUERY_TIME
++  , SLOG_UG_MIN_EXAMINED_ROW_LIMIT, SLOG_UG_ALL
++};
++enum enum_log_slow_verbosity { 
++  SLOG_V_MICROTIME, SLOG_V_QUERY_PLAN, SLOG_V_INNODB, 
++  SLOG_V_PROFILING, SLOG_V_PROFILING_USE_GETRUSAGE,
++  SLOG_V_MINIMAL, SLOG_V_STANDARD, SLOG_V_FULL
++};
++enum enum_slow_query_log_timestamp_precision {
++  SLOG_SECOND, SLOG_MICROSECOND
++};
++#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
++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,
++  SLOG_F_FILESORT_DISK
++};
+ enum enum_slave_exec_mode { SLAVE_EXEC_MODE_STRICT,
+                             SLAVE_EXEC_MODE_IDEMPOTENT,
+                             SLAVE_EXEC_MODE_LAST_BIT};
+@@ -508,6 +535,21 @@
+ 
+   my_bool sysdate_is_now;
+ 
++#ifndef DBUG_OFF
++  ulonglong query_exec_time;
++  double    query_exec_time_double;
++#endif
++  ulong log_slow_rate_limit;
++  ulonglong log_slow_filter;
++  ulonglong log_slow_verbosity;
++
++  ulong      innodb_io_reads;
++  ulonglong  innodb_io_read;
++  ulong      innodb_io_reads_wait_timer;
++  ulong      innodb_lock_que_wait_timer;
++  ulong      innodb_innodb_que_wait_timer;
++  ulong      innodb_page_access;
++
+   double long_query_time_double;
+ 
+ } SV;
+@@ -1140,6 +1182,24 @@
+   uint in_sub_stmt;
+   bool enable_slow_log;
+   bool last_insert_id_used;
++
++  /*** Following variables used in slow_extended.patch ***/
++  ulong      tmp_tables_used;
++  ulong      tmp_tables_disk_used;
++  ulonglong  tmp_tables_size;
++
++  bool       innodb_was_used;
++  ulong      innodb_io_reads;
++  ulonglong  innodb_io_read;
++  ulong      innodb_io_reads_wait_timer;
++  ulong      innodb_lock_que_wait_timer;
++  ulong      innodb_innodb_que_wait_timer;
++  ulong      innodb_page_access;
++
++  ulong      query_plan_flags;
++  ulong      query_plan_fsort_passes;
++  /*** The variables above used in slow_extended.patch ***/
++
+   SAVEPOINT *savepoints;
+   enum enum_check_fields count_cuted_fields;
+ };
+@@ -1588,6 +1648,71 @@
+   thr_lock_type update_lock_default;
+   Delayed_insert *di;
+ 
++  /*** 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.
++  */
++  ulonglong  bytes_sent_old;
++  /*
++    Variables tmp_tables_*** collect statistics about usage of temporary tables
++  */
++  ulong      tmp_tables_used;
++  ulong      tmp_tables_disk_used;
++  ulonglong  tmp_tables_size;
++  /*
++    Variable innodb_was_used shows used or not InnoDB engine in current query.
++  */
++  bool       innodb_was_used;
++  /*
++    Following Variables innodb_*** (is |should be) different from
++    default values only if (innodb_was_used==TRUE)
++  */
++  ulonglong  innodb_trx_id;
++  ulong      innodb_io_reads;
++  ulonglong  innodb_io_read;
++  ulong      innodb_io_reads_wait_timer;
++  ulong      innodb_lock_que_wait_timer;
++  ulong      innodb_innodb_que_wait_timer;
++  ulong      innodb_page_access;
++
++  /*
++    Variable query_plan_flags collects information about query plan entites
++    used on query execution.
++  */
++  ulong      query_plan_flags;
++  /*
++    Variable query_plan_fsort_passes collects information about file sort passes
++    acquired during query execution.
++  */
++  ulong      query_plan_fsort_passes;
++  /*
++    Query can generate several errors/warnings during execution
++    (see THD::handle_condition comment in sql_class.h)
++    Variable last_errno contains the last error/warning acquired during
++    query execution.
++  */
++  uint       last_errno;
++  /*** The variables above used in slow_extended.patch ***/
++
++  /*** Following methods used in slow_extended.patch ***/
++  void clear_slow_extended();
++  void reset_sub_statement_state_slow_extended(Sub_statement_state *backup);
++  void restore_sub_statement_state_slow_extended(const Sub_statement_state *backup);
++  /*** The methods above used in slow_extended.patch ***/
++
+   /* <> 0 if we are inside of trigger or stored function. */
+   uint in_sub_stmt;
+ 
+--- a/sql/sql_connect.cc
++++ b/sql/sql_connect.cc
+@@ -721,6 +721,15 @@
+   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. :) 
++    */ 
++    thd->write_to_slow_log= FALSE; 
++    if (thd->variables.log_slow_rate_limit <= 1 ||  
++        (thd->thread_id % thd->variables.log_slow_rate_limit) == 0) 
++         thd->write_to_slow_log= TRUE; 
++
+   prepare_new_connection_state(thd);
+   return FALSE;
+ }
+--- a/sql/sql_parse.cc
++++ b/sql/sql_parse.cc
+@@ -114,6 +114,7 @@
+ 
+ static bool execute_sqlcom_select(THD *thd, TABLE_LIST *all_tables);
+ static void sql_kill(THD *thd, ulong id, bool only_kill_query);
++static inline ulonglong get_query_exec_time(THD *thd, ulonglong cur_utime);
+ 
+ const char *any_db="*any*";	// Special symbol for check_access
+ 
+@@ -888,6 +889,7 @@
+     the slow log only if opt_log_slow_admin_statements is set.
+   */
+   thd->enable_slow_log= TRUE;
++  thd->clear_slow_extended();
+   thd->lex->sql_command= SQLCOM_END; /* to avoid confusing VIEW detectors */
+   thd->set_time();
+   if (!thd->is_valid_time())
+@@ -1430,6 +1432,60 @@
+   DBUG_RETURN(error);
+ }
+ 
++/**
++   Calculate execution time for the current query.
++
++   For debug builds, check the session value of query_exec_time
++   and if it is not zero, return it instead of the actual execution time.
++
++   SET queries are ignored so that statements changing query_exec_time are not
++   affected by themselves.
++
++   @param thd              thread handle
++   @param lex              current relative time in microseconds
++
++   @return                 time in microseconds from utime_after_lock
++*/
++
++static inline ulonglong get_query_exec_time(THD *thd, ulonglong cur_utime)
++{
++  ulonglong res;
++#ifndef DBUG_OFF
++  if (thd->variables.query_exec_time != 0)
++    res= thd->lex->sql_command != SQLCOM_SET_OPTION ?
++      thd->variables.query_exec_time : 0;
++  else
++#endif
++
++  res= cur_utime - thd->utime_after_lock;
++
++  if (res > thd->variables.long_query_time)
++    thd->server_status|= SERVER_QUERY_WAS_SLOW;
++  else
++    thd->server_status&= ~SERVER_QUERY_WAS_SLOW;
++
++  return res;
++}
++
++
++static inline void copy_global_to_session(THD *thd, ulong flag,
++                                          const ulong *val)
++{
++  my_ptrdiff_t offset = ((char *)val - (char *)&global_system_variables);
++  if (opt_slow_query_log_use_global_control & (1ULL << flag))
++    *(ulong *)((char *) &thd->variables + offset) = *val;
++}
++
++
++static inline void copy_global_to_session(THD *thd, ulong flag,
++                                          const ulonglong *val)
++{
++  my_ptrdiff_t offset = ((char *)val - (char *)&global_system_variables);
++  if (opt_slow_query_log_use_global_control & (1ULL << flag))
++    *(ulonglong *)((char *) &thd->variables + offset) = *val;
++}
++
++
+ 
+ void log_slow_statement(THD *thd)
+ {
+@@ -1443,13 +1499,48 @@
+   if (unlikely(thd->in_sub_stmt))
+     DBUG_VOID_RETURN;                           // Don't set time for sub stmt
+ 
++  /* 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->query_plan_flags & QPLAN_QC))))
++    DBUG_VOID_RETURN;
++
++  ulonglong end_utime_of_query= thd->current_utime();
++  ulonglong query_exec_time= get_query_exec_time(thd, end_utime_of_query);
++
++  /*
++    Low long_query_time value most likely means user is debugging stuff and even
++    though some thread's queries are not supposed to be logged b/c of the rate
++    limit, if one of them takes long enough (>= 1 second) it will be sensible
++    to make an exception and write to slow log anyway.
++  */
++
++  system_variables const &g= global_system_variables;
++  copy_global_to_session(thd, SLOG_UG_LOG_SLOW_FILTER,
++                         &g.log_slow_filter);
++  copy_global_to_session(thd, SLOG_UG_LOG_SLOW_RATE_LIMIT,
++                         &g.log_slow_rate_limit);
++  copy_global_to_session(thd, SLOG_UG_LOG_SLOW_VERBOSITY,
++                         &g.log_slow_verbosity);
++  copy_global_to_session(thd, SLOG_UG_LONG_QUERY_TIME,
++                         &g.long_query_time);
++  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 != TRUE
++      && (thd->variables.long_query_time >= 1000000
++          || (ulong) query_exec_time < 1000000))
++    DBUG_VOID_RETURN;
++
++
+   /*
+     Do not log administrative statements unless the appropriate option is
+     set.
+   */
+   if (thd->enable_slow_log)
+   {
+-    ulonglong end_utime_of_query= thd->current_utime();
+     thd_proc_info(thd, "logging slow query");
+ 
+     if (((thd->server_status & SERVER_QUERY_WAS_SLOW) ||
+@@ -5301,7 +5392,8 @@
+   thd->stmt_da->reset_diagnostics_area();
+   thd->warning_info->reset_for_next_command();
+   thd->rand_used= 0;
+-  thd->sent_row_count= thd->examined_row_count= 0;
++
++  thd->clear_slow_extended();
+ 
+   thd->reset_current_stmt_binlog_format_row();
+   thd->binlog_unsafe_warning_flags= 0;
+--- a/sql/sql_select.cc
++++ b/sql/sql_select.cc
+@@ -6902,7 +6902,10 @@
+ 	  {
+ 	    join->thd->server_status|=SERVER_QUERY_NO_INDEX_USED;
+ 	    if (statistics)
++            {
+ 	      status_var_increment(join->thd->status_var.select_scan_count);
++              join->thd->query_plan_flags|= QPLAN_FULL_SCAN;
++            }
+ 	  }
+ 	}
+ 	else
+@@ -6916,7 +6919,10 @@
+ 	  {
+ 	    join->thd->server_status|=SERVER_QUERY_NO_INDEX_USED;
+ 	    if (statistics)
++            {
+ 	      status_var_increment(join->thd->status_var.select_full_join_count);
++              join->thd->query_plan_flags|= QPLAN_FULL_JOIN;
++            }
+ 	  }
+ 	}
+ 	if (!table->no_keyread)
+@@ -10264,6 +10270,7 @@
+               (ulong) rows_limit,test(group)));
+ 
+   status_var_increment(thd->status_var.created_tmp_tables);
++  thd->query_plan_flags|= QPLAN_TMP_TABLE;
+ 
+   if (use_temp_pool && !(test_flags & TEST_KEEP_TMP_TABLES))
+     temp_pool_slot = bitmap_lock_set_next(&temp_pool);
+@@ -11162,6 +11169,7 @@
+     goto err;
+   }
+   status_var_increment(table->in_use->status_var.created_tmp_disk_tables);
++  table->in_use->query_plan_flags|= QPLAN_TMP_DISK;
+   share->db_record_offset= 1;
+   DBUG_RETURN(0);
+  err:
+@@ -11180,6 +11188,14 @@
+   save_proc_info=thd->proc_info;
+   thd_proc_info(thd, "removing tmp table");
+ 
++  thd->tmp_tables_used++;
++  if (entry->file)
++  {
++    thd->tmp_tables_size += entry->file->stats.data_file_length;
++    if (entry->file->ht->db_type != DB_TYPE_HEAP)
++      thd->tmp_tables_disk_used++;
++  }
++
+   // Release latches since this can take a long time
+   ha_release_temporary_latches(thd);
+ 
+--- a/sql/sql_show.cc
++++ b/sql/sql_show.cc
+@@ -1950,8 +1950,17 @@
+         table->field[4]->store(command_name[tmp->command].str,
+                                command_name[tmp->command].length, cs);
+       /* MYSQL_TIME */
+-      table->field[5]->store((longlong)(tmp->start_time ?
+-                                      now - tmp->start_time : 0), FALSE);
++      longlong value_in_time_column= 0;
++      if(tmp->start_time)
++      {
++        value_in_time_column = (now - tmp->start_time);
++        if(value_in_time_column > now)
++        {
++          value_in_time_column= 0;
++        }
++      }
++      table->field[5]->store(value_in_time_column, FALSE);
++
+       /* STATE */
+       if ((val= thread_state_info(tmp)))
+       {
+--- a/sql/sys_vars.cc
++++ b/sql/sys_vars.cc
+@@ -972,6 +972,29 @@
+        NO_MUTEX_GUARD, NOT_IN_BINLOG, ON_CHECK(0),
+        ON_UPDATE(update_cached_long_query_time));
+ 
++#ifndef DBUG_OFF
++static bool update_cached_query_exec_time(sys_var *self, THD *thd,
++                                          enum_var_type type)
++{
++  if (type == OPT_SESSION)
++    thd->variables.query_exec_time=
++      double2ulonglong(thd->variables.query_exec_time_double * 1e6);
++  else
++    global_system_variables.query_exec_time=
++      double2ulonglong(global_system_variables.query_exec_time_double * 1e6);
++  return false;
++}
++
++static Sys_var_double Sys_query_exec_time(
++       "query_exec_time",
++       "Pretend queries take this many seconds. When 0 (the default) use the "
++       "actual execution time. Used only for debugging.",
++       SESSION_VAR(query_exec_time_double),
++       NO_CMD_LINE, VALID_RANGE(0, LONG_TIMEOUT), DEFAULT(0),
++       NO_MUTEX_GUARD, IN_BINLOG, ON_CHECK(0),
++       ON_UPDATE(update_cached_query_exec_time));
++#endif
++
+ static bool fix_low_prio_updates(sys_var *self, THD *thd, enum_var_type type)
+ {
+   if (type == OPT_SESSION)
+@@ -2898,6 +2921,123 @@
+        DEFAULT(FALSE), NO_MUTEX_GUARD, NOT_IN_BINLOG, ON_CHECK(0),
+        ON_UPDATE(fix_log_state));
+ 
++const char *log_slow_filter_name[]= { "qc_miss", "full_scan", "full_join",
++                                      "tmp_table", "tmp_table_on_disk", "filesort", "filesort_on_disk", 0};
++static Sys_var_set Sys_log_slow_filter(
++       "log_slow_filter",
++       "Log only the queries that followed certain execution plan. "
++       "Multiple flags allowed in a comma-separated string. "
++       "[qc_miss, full_scan, full_join, tmp_table, tmp_table_on_disk, "
++       "filesort, filesort_on_disk]",
++       SESSION_VAR(log_slow_filter), CMD_LINE(REQUIRED_ARG),
++       log_slow_filter_name, DEFAULT(0));
++static Sys_var_ulong sys_log_slow_rate_limit(
++       "log_slow_rate_limit","Rate limit statement writes to slow log to only those from every (1/log_slow_rate_limit) session.",
++       SESSION_VAR(log_slow_rate_limit), CMD_LINE(REQUIRED_ARG),
++       VALID_RANGE(1, ULONG_MAX), DEFAULT(1), BLOCK_SIZE(1));
++const char* log_slow_verbosity_name[] = { 
++  "microtime", "query_plan", "innodb", 
++  "profiling", "profling_use_getrusage", 
++  "minimal", "standard", "full", 0
++};
++static ulonglong update_log_slow_verbosity_replace(ulonglong value, ulonglong what, ulonglong by)
++{
++  if((value & what) == what)
++  {
++    value = value & (~what);
++    value = value | by;
++  }
++  return value;
++}
++void update_log_slow_verbosity(ulonglong* value_ptr)
++{
++  ulonglong &value    = *value_ptr;
++  ulonglong microtime= ULL(1) << SLOG_V_MICROTIME;
++  ulonglong query_plan= ULL(1) << SLOG_V_QUERY_PLAN;
++  ulonglong innodb= ULL(1) << SLOG_V_INNODB;
++  ulonglong minimal= ULL(1) << SLOG_V_MINIMAL;
++  ulonglong standard= ULL(1) << SLOG_V_STANDARD;
++  ulonglong full= ULL(1) << SLOG_V_FULL;
++  value= update_log_slow_verbosity_replace(value,minimal,microtime);
++  value= update_log_slow_verbosity_replace(value,standard,microtime | query_plan);
++  value= update_log_slow_verbosity_replace(value,full,microtime | query_plan | innodb);
++}
++static bool update_log_slow_verbosity_helper(sys_var */*self*/, THD *thd,
++                                          enum_var_type type)
++{
++  if(type == OPT_SESSION)
++  {
++    update_log_slow_verbosity(&(thd->variables.log_slow_verbosity));
++  }
++  else
++  {
++    update_log_slow_verbosity(&(global_system_variables.log_slow_verbosity));
++  }
++  return false;
++}
++void init_slow_query_log_use_global_control()
++{
++  update_log_slow_verbosity(&(global_system_variables.log_slow_verbosity));
++}
++static Sys_var_set Sys_log_slow_verbosity(
++        "log_slow_verbosity",
++        "Choose how verbose the messages to your slow log will be. "
++        "Multiple flags allowed in a comma-separated string. [microtime, query_plan, innodb, profiling, profiling_use_getrusage]",
++        SESSION_VAR(log_slow_verbosity), CMD_LINE(REQUIRED_ARG),
++        log_slow_verbosity_name, DEFAULT(SLOG_V_MICROTIME),
++        NO_MUTEX_GUARD, NOT_IN_BINLOG, ON_CHECK(0),
++        ON_UPDATE(update_log_slow_verbosity_helper));
++static Sys_var_mybool Sys_log_slow_slave_statements(
++       "log_slow_slave_statements",
++       "Log queries replayed be the slave SQL thread",
++       GLOBAL_VAR(opt_log_slow_slave_statements), CMD_LINE(OPT_ARG),
++       DEFAULT(FALSE));
++static Sys_var_mybool Sys_log_slow_admin_statements(
++       "log_slow_admin_statements",
++       "Log slow OPTIMIZE, ANALYZE, ALTER and other administrative statements"
++       " to the slow log if it is open.",
++       GLOBAL_VAR(opt_log_slow_admin_statements), CMD_LINE(OPT_ARG),
++       DEFAULT(FALSE));
++static Sys_var_mybool Sys_log_slow_sp_statements(
++       "log_slow_sp_statements",
++       "Log slow statements executed by stored procedure to the slow log if it is open.",
++       GLOBAL_VAR(opt_log_slow_sp_statements), CMD_LINE(OPT_ARG),
++       DEFAULT(TRUE));
++static Sys_var_mybool Sys_slow_query_log_timestamp_always(
++       "slow_query_log_timestamp_always",
++       "Timestamp is printed for all records of the slow log even if they are same time.",
++       GLOBAL_VAR(opt_slow_query_log_timestamp_always), CMD_LINE(OPT_ARG),
++       DEFAULT(FALSE));
++const char *slow_query_log_use_global_control_name[]= { "log_slow_filter", "log_slow_rate_limit", "log_slow_verbosity", "long_query_time", "min_examined_row_limit", "all", 0};
++static bool update_slow_query_log_use_global_control(sys_var */*self*/, THD */*thd*/,
++                                               enum_var_type /*type*/)
++{
++  if(opt_slow_query_log_use_global_control & (ULL(1) << SLOG_UG_ALL))
++  {
++    opt_slow_query_log_use_global_control=
++      SLOG_UG_LOG_SLOW_FILTER | SLOG_UG_LOG_SLOW_RATE_LIMIT | SLOG_UG_LOG_SLOW_VERBOSITY |
++      SLOG_UG_LONG_QUERY_TIME | SLOG_UG_MIN_EXAMINED_ROW_LIMIT;
++  }
++  return false;
++}
++void init_log_slow_verbosity()
++{
++  update_slow_query_log_use_global_control(0,0,OPT_GLOBAL);
++}
++static Sys_var_set Sys_slow_query_log_use_global_control(
++       "slow_query_log_use_global_control",
++       "Choose flags, wich always use the global variables. Multiple flags allowed in a comma-separated string. [none, log_slow_filter, log_slow_rate_limit, log_slow_verbosity, long_query_time, min_examined_row_limit, all]",
++       GLOBAL_VAR(opt_slow_query_log_use_global_control), CMD_LINE(REQUIRED_ARG),
++       slow_query_log_use_global_control_name, DEFAULT(0),
++        NO_MUTEX_GUARD, NOT_IN_BINLOG, ON_CHECK(0),
++       ON_UPDATE(update_slow_query_log_use_global_control));
++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]",
++       GLOBAL_VAR(opt_slow_query_log_timestamp_precision), CMD_LINE(REQUIRED_ARG),
++       slow_query_log_timestamp_precision_name, DEFAULT(SLOG_SECOND));
++ 
+ /* Synonym of "slow_query_log" for consistency with SHOW VARIABLES output */
+ static Sys_var_mybool Sys_log_slow(
+        "log_slow_queries",
+--- a/sql/sql_profile.cc
++++ b/sql/sql_profile.cc
+@@ -243,7 +243,8 @@
+ {
+   time_usecs= (double) my_getsystime() / 10.0;  /* 1 sec was 1e7, now is 1e6 */
+ #ifdef HAVE_GETRUSAGE
+-  getrusage(RUSAGE_SELF, &rusage);
++  if ((profile->get_profiling())->enabled_getrusage())
++    getrusage(RUSAGE_SELF, &rusage);
+ #elif defined(_WIN32)
+   FILETIME ftDummy;
+   // NOTE: Get{Process|Thread}Times has a granularity of the clock interval,
+@@ -251,6 +252,19 @@
+   // measurable by this function.
+   GetProcessTimes(GetCurrentProcess(), &ftDummy, &ftDummy, &ftKernel, &ftUser);
+ #endif
++
++#ifdef HAVE_CLOCK_GETTIME
++  struct timespec tp;
++
++  if (!(clock_gettime(CLOCK_THREAD_CPUTIME_ID, &tp)))
++  {
++    cpu_time_usecs= tp.tv_sec*1000000000.0 + tp.tv_nsec;
++  }
++  else
++#endif
++  {
++    cpu_time_usecs= 0;
++  }
+ }
+ 
+ 
+@@ -366,7 +380,8 @@
+     finish_current_query();
+   }
+ 
+-  enabled= ((thd->variables.option_bits & OPTION_PROFILING) != 0);
++  enabled= ((thd->variables.option_bits & OPTION_PROFILING) != 0) ||
++            ((thd->variables.log_slow_verbosity & (ULL(1) << SLOG_V_PROFILING)) != 0);
+ 
+   if (! enabled) DBUG_VOID_RETURN;
+ 
+@@ -404,7 +419,8 @@
+     status_change("ending", NULL, NULL, 0);
+ 
+     if ((enabled) &&                                    /* ON at start? */
+-        ((thd->variables.option_bits & OPTION_PROFILING) != 0) &&   /* and ON at end? */
++        (((thd->variables.option_bits & OPTION_PROFILING) != 0) ||
++          ((thd->variables.log_slow_verbosity & (ULL(1) << SLOG_V_PROFILING)) != 0)) &&   /* and ON at end? */
+         (current->query_source != NULL) &&
+         (! current->entries.is_empty()))
+     {
+@@ -505,6 +521,118 @@
+   DBUG_VOID_RETURN;
+ }
+ 
++bool PROFILING::enabled_getrusage()
++{
++  return ((thd->variables.log_slow_verbosity & (ULL(1) << SLOG_V_PROFILING_USE_GETRUSAGE)) != 0);
++}
++
++/**
++   For a given profile entry specified by a name and 2 time measurements,
++   print its normalized name (i.e. with all spaces replaced with underscores)
++   along with its wall clock and CPU time.
++*/
++
++static void my_b_print_status(IO_CACHE *log_file, const char *status,
++                              PROF_MEASUREMENT *start, PROF_MEASUREMENT *stop)
++{
++  DBUG_ENTER("my_b_print_status");
++  DBUG_ASSERT(log_file != NULL && status != NULL);
++  char query_time_buff[22+7];
++  const char *tmp;
++
++  my_b_printf(log_file, "Profile_");
++  for (tmp= status; *tmp; tmp++)
++    my_b_write_byte(log_file, *tmp == ' ' ? '_' : *tmp);
++
++  snprintf(query_time_buff, sizeof(query_time_buff), "%.6f",
++           (stop->time_usecs - start->time_usecs) / (1000.0 * 1000));
++  my_b_printf(log_file, ": %s ", query_time_buff);
++
++  my_b_printf(log_file, "Profile_");
++  for (tmp= status; *tmp; tmp++)
++    my_b_write_byte(log_file, *tmp == ' ' ? '_' : *tmp);
++  my_b_printf(log_file, "_cpu: ");
++
++  snprintf(query_time_buff, sizeof(query_time_buff), "%.6f",
++           (stop->cpu_time_usecs - start->cpu_time_usecs) /
++           (1000.0 * 1000 * 1000));
++  my_b_printf(log_file, "%s ", query_time_buff);
++
++  DBUG_VOID_RETURN;
++}
++
++/**
++  Print output for current query to file 
++*/
++
++int PROFILING::print_current(IO_CACHE *log_file)
++{
++  DBUG_ENTER("PROFILING::print_current");
++  ulonglong row_number= 0;
++
++  QUERY_PROFILE *query;
++  /* Get current query */
++  if (current == NULL)
++  {
++    DBUG_RETURN(0);
++  }
++
++  query= current;
++
++  my_b_printf(log_file, "# ");
++
++    void *entry_iterator;
++    PROF_MEASUREMENT *entry= NULL, *previous= NULL, *first= NULL;
++    /* ...and for each query, go through all its state-change steps. */
++    for (entry_iterator= query->entries.new_iterator();
++         entry_iterator != NULL;
++         entry_iterator= query->entries.iterator_next(entry_iterator),
++         previous=entry, row_number++)
++    {
++      entry= query->entries.iterator_value(entry_iterator);
++
++      /* Skip the first.  We count spans of fence, not fence-posts. */
++      if (previous == NULL) {first= entry; continue;}
++
++      if (thd->lex->sql_command == SQLCOM_SHOW_PROFILE)
++      {
++        /*
++          We got here via a SHOW command.  That means that we stored
++          information about the query we wish to show and that isn't
++          in a WHERE clause at a higher level to filter out rows we
++          wish to exclude.
++
++          Because that functionality isn't available in the server yet,
++          we must filter here, at the wrong level.  Once one can con-
++          struct where and having conditions at the SQL layer, then this
++          condition should be ripped out.
++        */
++        if (thd->lex->profile_query_id == 0) /* 0 == show final query */
++        {
++          if (query != last)
++            continue;
++        }
++        else
++        {
++          if (thd->lex->profile_query_id != query->profiling_query_id)
++            continue;
++        }
++      }
++
++      my_b_print_status(log_file, previous->status, previous, entry);
++    }
++
++    my_b_write_byte(log_file, '\n');
++    if ((entry != NULL) && (first != NULL))
++    {
++      my_b_printf(log_file, "# ");
++      my_b_print_status(log_file, "total", first, entry);
++      my_b_write_byte(log_file, '\n');
++    }
++
++  DBUG_RETURN(0);
++}
++
+ /**
+   Fill the information schema table, "query_profile", as defined in show.cc .
+   There are two ways to get to this function:  Selecting from the information
+@@ -600,6 +728,8 @@
+ 
+ #ifdef HAVE_GETRUSAGE
+ 
++      if (enabled_getrusage())
++      {
+       my_decimal cpu_utime_decimal, cpu_stime_decimal;
+ 
+       double2my_decimal(E_DEC_FATAL_ERROR,
+@@ -687,6 +817,7 @@
+       table->field[14]->store((uint32)(entry->rusage.ru_nswap -
+                              previous->rusage.ru_nswap), true);
+       table->field[14]->set_notnull();
++      }
+ #else
+       /* TODO: Add swap info for non-BSD systems */
+ #endif
+--- a/sql/sql_profile.h
++++ b/sql/sql_profile.h
+@@ -164,11 +164,15 @@
+ */
+ class PROF_MEASUREMENT
+ {
+-private:
+-  friend class QUERY_PROFILE;
+-  friend class PROFILING;
+-
+   QUERY_PROFILE *profile;
++
++  char *allocated_status_memory;
++
++  void set_label(const char *status_arg, const char *function_arg, 
++                  const char *file_arg, unsigned int line_arg);
++  void clean_up();
++
++public:
+   char *status;
+ #ifdef HAVE_GETRUSAGE
+   struct rusage rusage;
+@@ -181,12 +185,7 @@
+   unsigned int line;
+ 
+   double time_usecs;
+-  char *allocated_status_memory;
+-
+-  void set_label(const char *status_arg, const char *function_arg, 
+-                  const char *file_arg, unsigned int line_arg);
+-  void clean_up();
+-  
++  double cpu_time_usecs;
+   PROF_MEASUREMENT();
+   PROF_MEASUREMENT(QUERY_PROFILE *profile_arg, const char *status_arg);
+   PROF_MEASUREMENT(QUERY_PROFILE *profile_arg, const char *status_arg,
+@@ -231,6 +230,11 @@
+ 
+   /* Show this profile.  This is called by PROFILING. */
+   bool show(uint options);
++
++public:
++
++  inline PROFILING * get_profiling() { return profiling; };
++
+ };
+ 
+ 
+@@ -276,9 +280,11 @@
+ 
+   /* SHOW PROFILES */
+   bool show_profiles();
++  bool enabled_getrusage();
+ 
+   /* ... from INFORMATION_SCHEMA.PROFILING ... */
+   int fill_statistics_info(THD *thd, TABLE_LIST *tables, Item *cond);
++  int print_current(IO_CACHE *log_file);
+ };
+ 
+ #  endif /* HAVE_PROFILING */
+--- /dev/null
++++ b/mysql-test/include/log_grep.inc
+@@ -0,0 +1,17 @@
++--disable_query_log
++--echo [log_grep.inc] file: $log_file pattern: $grep_pattern
++perl;
++  $log_file=           $ENV{'log_file'};
++  $log_file_full_path= $ENV{'log_file_full_path'};
++  $grep_pattern=       $ENV{'grep_pattern'};
++
++  open(FILE, "$log_file_full_path") 
++    or die("Cannot open file $log_file_full_path: $!\n");
++
++  $lines = 0;
++  while(<FILE>) {
++    $lines++ if (/$grep_pattern/);
++  }
++  close(FILE);
++  print "[log_grep.inc] lines:   $lines\n";
++EOF
+--- /dev/null
++++ b/mysql-test/include/log_start.inc
+@@ -0,0 +1,16 @@
++--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
+\ No newline at end of file
+--- /dev/null
++++ b/mysql-test/include/log_stop.inc
+@@ -0,0 +1,7 @@
++--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
+--- /dev/null
++++ b/mysql-test/r/percona_bug643149.result
+@@ -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  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;
+--- /dev/null
++++ b/mysql-test/r/percona_log_slow_filter-cl.result
+@@ -0,0 +1,6 @@
++SHOW VARIABLES LIKE 'log_slow_filter';
++Variable_name	Value
++log_slow_filter	full_join
++SHOW GLOBAL VARIABLES LIKE 'log_slow_filter';
++Variable_name	Value
++log_slow_filter	full_join
+--- /dev/null
++++ b/mysql-test/r/percona_log_slow_filter.result
+@@ -0,0 +1,15 @@
++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
+--- /dev/null
++++ b/mysql-test/r/percona_log_slow_slave_statements-cl.result
+@@ -0,0 +1,6 @@
++SHOW VARIABLES LIKE 'log_slow_slave_statements';
++Variable_name	Value
++log_slow_slave_statements	ON
++SHOW GLOBAL VARIABLES LIKE 'log_slow_slave_statements';
++Variable_name	Value
++log_slow_slave_statements	ON
+--- /dev/null
++++ b/mysql-test/r/percona_log_slow_slave_statements-innodb.result
+@@ -0,0 +1,18 @@
++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
++include/rpl_end.inc
+--- /dev/null
++++ b/mysql-test/r/percona_log_slow_slave_statements.result
+@@ -0,0 +1,44 @@
++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
++include/rpl_end.inc
+--- /dev/null
++++ b/mysql-test/r/percona_log_slow_sp_statements-cl.result
+@@ -0,0 +1,6 @@
++SHOW VARIABLES LIKE 'log_slow_sp_statements';
++Variable_name	Value
++log_slow_sp_statements	ON
++SHOW GLOBAL VARIABLES LIKE 'log_slow_sp_statements';
++Variable_name	Value
++log_slow_sp_statements	ON
+--- /dev/null
++++ b/mysql-test/r/percona_log_slow_sp_statements.result
+@@ -0,0 +1,24 @@
++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
+--- /dev/null
++++ b/mysql-test/r/percona_log_slow_verbosity-cl.result
+@@ -0,0 +1,6 @@
++SHOW VARIABLES LIKE 'log_slow_verbosity';
++Variable_name	Value
++log_slow_verbosity	microtime,query_plan,innodb
++SHOW GLOBAL VARIABLES LIKE 'log_slow_verbosity';
++Variable_name	Value
++log_slow_verbosity	microtime,query_plan,innodb
+--- /dev/null
++++ b/mysql-test/r/percona_log_slow_verbosity.result
+@@ -0,0 +1,16 @@
++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
+--- /dev/null
++++ b/mysql-test/r/percona_long_query_time.result
+@@ -0,0 +1,33 @@
++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
+--- /dev/null
++++ b/mysql-test/r/percona_slow_query_log_timestamp_always-cl.result
+@@ -0,0 +1,6 @@
++SHOW VARIABLES LIKE 'slow_query_log_timestamp_always';
++Variable_name	Value
++slow_query_log_timestamp_always	ON
++SHOW GLOBAL VARIABLES LIKE 'slow_query_log_timestamp_always';
++Variable_name	Value
++slow_query_log_timestamp_always	ON
+--- /dev/null
++++ b/mysql-test/r/percona_slow_query_log_timestamp_always.result
+@@ -0,0 +1,41 @@
++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
+--- /dev/null
++++ b/mysql-test/r/percona_slow_query_log_timestamp_precision-cl.result
+@@ -0,0 +1,6 @@
++SHOW VARIABLES LIKE 'slow_query_log_timestamp_precision';
++Variable_name	Value
++slow_query_log_timestamp_precision	microsecond
++SHOW GLOBAL VARIABLES LIKE 'slow_query_log_timestamp_precision';
++Variable_name	Value
++slow_query_log_timestamp_precision	microsecond
+--- /dev/null
++++ b/mysql-test/r/percona_slow_query_log_timestamp_precision.result
+@@ -0,0 +1,18 @@
++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
+--- /dev/null
++++ b/mysql-test/r/percona_slow_query_log_use_global_control.result
+@@ -0,0 +1,18 @@
++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
+--- /dev/null
++++ b/mysql-test/t/percona_bug643149.test
+@@ -0,0 +1,49 @@
++#
++# This test suffers from server
++# Bug#38124 "general_log_file" variable silently unset when using expression
++# In short:
++#    SET GLOBAL general_log_file = @<whatever>
++#    SET GLOBAL slow_query_log = @<whatever>
++# cause that the value of these server system variables is set to default
++# instead of the assigned values. There comes no error message or warning.
++# If this bug is fixed please
++# 1. try this test with "let $fixed_bug38124 = 0;"
++# 2. remove all workarounds if 1. was successful.
++--source include/have_profiling.inc
++let $fixed_bug38124 = 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;
++
++let slogfile=$MYSQLTEST_VARDIR/percona_bug643149_slow.log;
++--replace_result $MYSQLTEST_VARDIR MYSQLTEST_VARDIR
++--eval SET GLOBAL slow_query_log_file='$slogfile';
++
++SELECT 1;
++
++perl;
++  $slogfile= $ENV{'slogfile'};
++
++  open(FILE, "$slogfile") or
++    die("Unable to read slow query log file $slogfile: $!\n");
++  while(<FILE>) {
++    next if (!/^#/);
++    next if (/^# Time:/);
++    s/[0-9]+/X/g;
++    print;
++  }
++
++  close(FILE);
++EOF
++
++SET GLOBAL slow_query_log_file=@old_slow_query_log_file;
++
++if(!$fixed_bug38124)
++{
++  --disable_query_log
++  let $my_var = `SELECT @old_slow_query_log_file`;
++  eval SET @@global.slow_query_log_file = '$my_var';
++  --enable_query_log
++}
+--- /dev/null
++++ b/mysql-test/t/percona_log_slow_filter-cl-master.opt
+@@ -0,0 +1 @@
++--log_slow_filter=full_join
+--- /dev/null
++++ b/mysql-test/t/percona_log_slow_filter-cl.test
+@@ -0,0 +1,2 @@
++SHOW VARIABLES LIKE 'log_slow_filter';
++SHOW GLOBAL VARIABLES LIKE 'log_slow_filter';
+--- /dev/null
++++ b/mysql-test/t/percona_log_slow_filter.test
+@@ -0,0 +1,26 @@
++--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;
+--- /dev/null
++++ b/mysql-test/t/percona_log_slow_slave_statements-cl-master.opt
+@@ -0,0 +1 @@
++--log_slow_slave_statements
+\ No newline at end of file
+--- /dev/null
++++ b/mysql-test/t/percona_log_slow_slave_statements-cl.test
+@@ -0,0 +1,3 @@
++SHOW VARIABLES LIKE 'log_slow_slave_statements';
++SHOW GLOBAL VARIABLES LIKE 'log_slow_slave_statements';
++
+--- /dev/null
++++ b/mysql-test/t/percona_log_slow_slave_statements-innodb-slave.opt
+@@ -0,0 +1 @@
++--long_query_time=0 --log_slow_slave_statements --log_slow_verbosity=innodb
+\ No newline at end of file
+--- /dev/null
++++ b/mysql-test/t/percona_log_slow_slave_statements-innodb.test
+@@ -0,0 +1,42 @@
++--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
+--- /dev/null
++++ b/mysql-test/t/percona_log_slow_slave_statements-slave.opt
+@@ -0,0 +1 @@
++--long_query_time=0
+\ No newline at end of file
+--- /dev/null
++++ b/mysql-test/t/percona_log_slow_slave_statements.test
+@@ -0,0 +1,117 @@
++-- 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
+--- /dev/null
++++ b/mysql-test/t/percona_log_slow_sp_statements-cl-master.opt
+@@ -0,0 +1 @@
++--log_slow_sp_statements
+--- /dev/null
++++ b/mysql-test/t/percona_log_slow_sp_statements-cl.test
+@@ -0,0 +1,2 @@
++SHOW VARIABLES LIKE 'log_slow_sp_statements';
++SHOW GLOBAL VARIABLES LIKE 'log_slow_sp_statements';
+--- /dev/null
++++ b/mysql-test/t/percona_log_slow_sp_statements.test
+@@ -0,0 +1,29 @@
++--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;
+--- /dev/null
++++ b/mysql-test/t/percona_log_slow_verbosity-cl-master.opt
+@@ -0,0 +1 @@
++--log_slow_verbosity="full"
+--- /dev/null
++++ b/mysql-test/t/percona_log_slow_verbosity-cl.test
+@@ -0,0 +1,2 @@
++SHOW VARIABLES LIKE 'log_slow_verbosity';
++SHOW GLOBAL VARIABLES LIKE 'log_slow_verbosity';
+--- /dev/null
++++ b/mysql-test/t/percona_log_slow_verbosity.test
+@@ -0,0 +1,19 @@
++--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
+--- /dev/null
++++ b/mysql-test/t/percona_long_query_time.test
+@@ -0,0 +1,25 @@
++--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
+--- /dev/null
++++ b/mysql-test/t/percona_slow_query_log_timestamp_always-cl-master.opt
+@@ -0,0 +1 @@
++--slow_query_log_timestamp_always
+\ No newline at end of file
+--- /dev/null
++++ b/mysql-test/t/percona_slow_query_log_timestamp_always-cl.test
+@@ -0,0 +1,2 @@
++SHOW VARIABLES LIKE 'slow_query_log_timestamp_always';
++SHOW GLOBAL VARIABLES LIKE 'slow_query_log_timestamp_always';
+--- /dev/null
++++ b/mysql-test/t/percona_slow_query_log_timestamp_always.test
+@@ -0,0 +1,34 @@
++--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
+--- /dev/null
++++ b/mysql-test/t/percona_slow_query_log_timestamp_precision-cl-master.opt
+@@ -0,0 +1 @@
++--slow_query_log_timestamp_precision='microsecond'
+\ No newline at end of file
+--- /dev/null
++++ b/mysql-test/t/percona_slow_query_log_timestamp_precision-cl.test
+@@ -0,0 +1,2 @@
++SHOW VARIABLES LIKE 'slow_query_log_timestamp_precision';
++SHOW GLOBAL VARIABLES LIKE 'slow_query_log_timestamp_precision';
+--- /dev/null
++++ b/mysql-test/t/percona_slow_query_log_timestamp_precision-master.opt
+@@ -0,0 +1 @@
++--slow_query_log_timestamp_always
+\ No newline at end of file
+--- /dev/null
++++ b/mysql-test/t/percona_slow_query_log_timestamp_precision.test
+@@ -0,0 +1,25 @@
++--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
+--- /dev/null
++++ b/mysql-test/t/percona_slow_query_log_use_global_control.test
+@@ -0,0 +1,28 @@
++--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
++
+--- /dev/null
++++ b/mysql-test/r/percona_slow_query_log_use_global_control-cl.result
+@@ -0,0 +1,6 @@
++SHOW VARIABLES LIKE 'slow_query_log_use_global_control';
++Variable_name	Value
++slow_query_log_use_global_control	log_slow_verbosity,long_query_time
++SHOW GLOBAL VARIABLES LIKE 'slow_query_log_use_global_control';
++Variable_name	Value
++slow_query_log_use_global_control	log_slow_verbosity,long_query_time
+--- /dev/null
++++ b/mysql-test/t/percona_slow_query_log_use_global_control-cl-master.opt
+@@ -0,0 +1 @@
++--slow_query_log_use_global_control="log_slow_verbosity,long_query_time"
+--- /dev/null
++++ b/mysql-test/t/percona_slow_query_log_use_global_control-cl.test
+@@ -0,0 +1,2 @@
++SHOW VARIABLES LIKE 'slow_query_log_use_global_control';
++SHOW GLOBAL VARIABLES LIKE 'slow_query_log_use_global_control';
+--- /dev/null
++++ b/mysql-test/r/percona_min_examined_row_limit.result
+@@ -0,0 +1,34 @@
++drop table if exists t;
++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';
++[log_start.inc] percona.slow_extended.min_examined_row_limit
++SET SESSION query_exec_time=2.1;
++SELECT 1;
++1
++1
++SET GLOBAL min_examined_row_limit=5;
++select * from t as t1, t as t2;
++id	id
++1	1
++2	1
++3	1
++1	2
++2	2
++3	2
++1	3
++2	3
++3	3
++SELECT 1;
++1
++1
++SET SESSION query_exec_time=default;
++[log_stop.inc] percona.slow_extended.min_examined_row_limit
++SET GLOBAL min_examined_row_limit=default;
++SET GLOBAL slow_query_log_use_global_control=default;
++SET GLOBAL long_query_time=default;
++[log_grep.inc] file: percona.slow_extended.min_examined_row_limit pattern: Query_time
++[log_grep.inc] lines:   1
+--- /dev/null
++++ b/mysql-test/t/percona_min_examined_row_limit.test
+@@ -0,0 +1,35 @@
++--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;
+--- a/sql/log_event.cc
++++ b/sql/log_event.cc
+@@ -2385,6 +2385,14 @@
+       start+= host.length;
+     }
+   }
++#ifndef DBUG_OFF
++  if (thd && thd->variables.query_exec_time > 0)
++  {
++    *start++= Q_QUERY_EXEC_TIME;
++    int8store(start, thd->variables.query_exec_time);
++    start+= 8;
++  }
++#endif
+   /*
+     NOTE: When adding new status vars, please don't forget to update
+     the MAX_SIZE_LOG_EVENT_STATUS in log_event.h and update the function
+@@ -2871,6 +2879,17 @@
+       data_written= master_data_written= uint4korr(pos);
+       pos+= 4;
+       break;
++#if !defined(DBUG_OFF) && !defined(MYSQL_CLIENT)
++    case Q_QUERY_EXEC_TIME:
++    {
++      THD *thd= current_thd;
++      CHECK_SPACE(pos, end, 8);
++      if (thd)
++        thd->variables.query_exec_time= uint8korr(pos);
++      pos+= 8;
++      break;
++    }
++#endif
+     case Q_INVOKER:
+     {
+       CHECK_SPACE(pos, end, 1);
+--- a/sql/log_event.h
++++ b/sql/log_event.h
+@@ -342,6 +342,10 @@
+ 
+ #define Q_INVOKER 11
+ 
++#ifndef DBUG_OFF
++#define Q_QUERY_EXEC_TIME 250
++#endif
++
+ /* Intvar event post-header */
+ 
+ /* Intvar event data */
+--- /dev/null
++++ b/mysql-test/suite/sys_vars/r/query_exec_time_basic.result
+@@ -0,0 +1,2 @@
++SET GLOBAL query_exec_time=default;
++SET SESSION query_exec_time=default;
+--- /dev/null
++++ b/mysql-test/suite/sys_vars/t/query_exec_time_basic.test
+@@ -0,0 +1,4 @@
++--source include/have_debug.inc
++
++SET GLOBAL query_exec_time=default;
++SET SESSION query_exec_time=default;
+--- /dev/null
++++ b/mysql-test/r/percona_log_slow_global_control_default.result
+@@ -0,0 +1 @@
++SET GLOBAL slow_query_log_use_global_control=default;
+--- /dev/null
++++ b/mysql-test/t/percona_log_slow_global_control_default.test
+@@ -0,0 +1 @@
++SET GLOBAL slow_query_log_use_global_control=default;
+--- /dev/null
++++ b/mysql-test/r/percona_slow_extended_log_error.result
+@@ -0,0 +1,9 @@
++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
+--- /dev/null
++++ b/mysql-test/t/percona_slow_extended_log_error.test
+@@ -0,0 +1,15 @@
++--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;
+--- /dev/null
++++ b/mysql-test/suite/sys_vars/t/log_slow_admin_statements_basic.test
+@@ -0,0 +1 @@
++SELECT @@global.log_slow_admin_statements;
+--- /dev/null
++++ b/mysql-test/suite/sys_vars/r/log_slow_admin_statements_basic.result
+@@ -0,0 +1,3 @@
++SELECT @@global.log_slow_admin_statements;
++@@global.log_slow_admin_statements
++0
+--- /dev/null
++++ b/mysql-test/r/percona_log_slow_admin_statements.result
+@@ -0,0 +1,35 @@
++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
+--- /dev/null
++++ b/mysql-test/r/percona_log_slow_admin_statements-config_false.result
+@@ -0,0 +1,6 @@
++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
+--- /dev/null
++++ b/mysql-test/r/percona_log_slow_admin_statements-config_foo.result
+@@ -0,0 +1,7 @@
++call mtr.add_suppression("option 'log_slow_admin_statements': boolean value 'foo' wasn't recognized. Set to OFF.");
++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
+--- /dev/null
++++ b/mysql-test/r/percona_log_slow_admin_statements-config_true.result
+@@ -0,0 +1,6 @@
++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
+--- /dev/null
++++ b/mysql-test/r/percona_log_slow_admin_statements-config.result
+@@ -0,0 +1,6 @@
++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
+--- /dev/null
++++ b/mysql-test/t/percona_log_slow_admin_statements-config_false.cnf
+@@ -0,0 +1,2 @@
++[mysqld.1]
++log-slow-admin-statements=false
+--- /dev/null
++++ b/mysql-test/t/percona_log_slow_admin_statements-config_foo.cnf
+@@ -0,0 +1,2 @@
++[mysqld.1]
++log-slow-admin-statements=foo
+--- /dev/null
++++ b/mysql-test/t/percona_log_slow_admin_statements-config_true.cnf
+@@ -0,0 +1,2 @@
++[mysqld.1]
++log-slow-admin-statements=true
+--- /dev/null
++++ b/mysql-test/t/percona_log_slow_admin_statements-config.cnf
+@@ -0,0 +1,2 @@
++[mysqld.1]
++log-slow-admin-statements
+--- /dev/null
++++ b/mysql-test/t/percona_log_slow_admin_statements.test
+@@ -0,0 +1,20 @@
++# 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';
+--- /dev/null
++++ b/mysql-test/t/percona_log_slow_admin_statements-config_false.test
+@@ -0,0 +1,2 @@
++SHOW GLOBAL VARIABLES like 'log_slow_admin_statements';
++SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements';
+--- /dev/null
++++ b/mysql-test/t/percona_log_slow_admin_statements-config_foo.test
+@@ -0,0 +1,3 @@
++call mtr.add_suppression("option 'log_slow_admin_statements': boolean value 'foo' wasn't recognized. Set to OFF.");
++SHOW GLOBAL VARIABLES like 'log_slow_admin_statements';
++SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements';
+--- /dev/null
++++ b/mysql-test/t/percona_log_slow_admin_statements-config_true.test
+@@ -0,0 +1,2 @@
++SHOW GLOBAL VARIABLES like 'log_slow_admin_statements';
++SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements';
+--- /dev/null
++++ b/mysql-test/t/percona_log_slow_admin_statements-config.test
+@@ -0,0 +1,2 @@
++SHOW GLOBAL VARIABLES like 'log_slow_admin_statements';
++SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements';
+--- a/mysql-test/r/mysqld--help-notwin.result
++++ b/mysql-test/r/mysqld--help-notwin.result
+@@ -250,15 +250,31 @@
+  --log-slow-admin-statements 
+  Log slow OPTIMIZE, ANALYZE, ALTER and other
+  administrative statements to the slow log if it is open.
++ --log-slow-filter=name 
++ Log only the queries that followed certain execution
++ plan. Multiple flags allowed in a comma-separated string.
++ [qc_miss, full_scan, full_join, tmp_table,
++ tmp_table_on_disk, filesort, filesort_on_disk]
+  --log-slow-queries[=name] 
+  Log slow queries to a table or log file. Defaults logging
+  to table mysql.slow_log or hostname-slow.log if
+  --log-output=file is used. Must be enabled to activate
+  other slow log options. Deprecated option, use
+  --slow-query-log/--slow-query-log-file instead.
++ --log-slow-rate-limit=# 
++ Rate limit statement writes to slow log to only those
++ from every (1/log_slow_rate_limit) session.
+  --log-slow-slave-statements 
+- Log slow statements executed by slave thread to the slow
+- log if it is open.
++ Log queries replayed be the slave SQL thread
++ --log-slow-sp-statements 
++ Log slow statements executed by stored procedure to the
++ slow log if it is open.
++ (Defaults to on; use --skip-log-slow-sp-statements to disable.)
++ --log-slow-verbosity=name 
++ Choose how verbose the messages to your slow log will be.
++ Multiple flags allowed in a comma-separated string.
++ [microtime, query_plan, innodb, profiling,
++ profiling_use_getrusage]
+  --log-tc=name       Path to transaction coordinator log (used for
+  transactions that affect more than one storage engine,
+  when binary log is disabled).
+@@ -660,6 +676,18 @@
+  Log slow queries to given log file. Defaults logging to
+  hostname-slow.log. Must be enabled to activate other slow
+  log options
++ --slow-query-log-timestamp-always 
++ 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]
++ --slow-query-log-use-global-control=name 
++ Choose flags, wich always use the global variables.
++ Multiple flags allowed in a comma-separated string.
++ [none, log_slow_filter, log_slow_rate_limit,
++ log_slow_verbosity, long_query_time,
++ min_examined_row_limit, all]
+  --socket=name       Socket file to use for connection
+  --sort-buffer-size=# 
+  Each thread that needs to do a sort allocates a buffer of
+@@ -817,7 +845,11 @@
+ log-short-format FALSE
+ log-slave-updates FALSE
+ log-slow-admin-statements FALSE
++log-slow-filter 
++log-slow-rate-limit 1
+ log-slow-slave-statements FALSE
++log-slow-sp-statements TRUE
++log-slow-verbosity 
+ log-tc tc.log
+ log-tc-size 24576
+ log-warnings 1
+@@ -933,6 +965,9 @@
+ slave-type-conversions 
+ slow-launch-time 2
+ slow-query-log FALSE
++slow-query-log-timestamp-always FALSE
++slow-query-log-timestamp-precision second
++slow-query-log-use-global-control 
+ sort-buffer-size 2097152
+ sporadic-binlog-dump-fail FALSE
+ sql-mode 

=== removed file 'patches/slow_extended.patch'
--- patches/slow_extended.patch	2011-12-13 15:06:50 +0000
+++ patches/slow_extended.patch	1970-01-01 00:00:00 +0000
@@ -1,2772 +0,0 @@
-# name       : slow_extended.patch
-# introduced : 11 or before
-# maintainer : Oleg
-#
-#!!! notice !!!
-# Any small change to this file in the main branch
-# should be done or reviewed by the maintainer!
---- a/include/mysql/plugin_audit.h.pp
-+++ b/include/mysql/plugin_audit.h.pp
-@@ -186,6 +186,16 @@
- char *thd_security_context(void* thd, char *buffer, unsigned int length,
-                            unsigned int max_query_len);
- void thd_inc_row_count(void* thd);
-+void increment_thd_innodb_stats(void* thd,
-+                    unsigned long long trx_id,
-+                    long io_reads,
-+                    long long io_read,
-+                    long io_reads_wait_timer,
-+                    long lock_que_wait_timer,
-+                    long que_wait_timer,
-+                    long page_access);
-+unsigned long thd_log_slow_verbosity(const void* thd);
-+int thd_opt_slow_log();
- int mysql_tmpfile(const char *prefix);
- int thd_killed(const void* thd);
- unsigned long thd_get_thread_id(const void* thd);
---- a/include/mysql/plugin_auth.h.pp
-+++ b/include/mysql/plugin_auth.h.pp
-@@ -186,6 +186,16 @@
- char *thd_security_context(void* thd, char *buffer, unsigned int length,
-                            unsigned int max_query_len);
- void thd_inc_row_count(void* thd);
-+void increment_thd_innodb_stats(void* thd,
-+                    unsigned long long trx_id,
-+                    long io_reads,
-+                    long long io_read,
-+                    long io_reads_wait_timer,
-+                    long lock_que_wait_timer,
-+                    long que_wait_timer,
-+                    long page_access);
-+unsigned long thd_log_slow_verbosity(const void* thd);
-+int thd_opt_slow_log();
- int mysql_tmpfile(const char *prefix);
- int thd_killed(const void* thd);
- unsigned long thd_get_thread_id(const void* thd);
---- a/include/mysql/plugin_ftparser.h.pp
-+++ b/include/mysql/plugin_ftparser.h.pp
-@@ -139,6 +139,16 @@
- char *thd_security_context(void* thd, char *buffer, unsigned int length,
-                            unsigned int max_query_len);
- void thd_inc_row_count(void* thd);
-+void increment_thd_innodb_stats(void* thd,
-+                    unsigned long long trx_id,
-+                    long io_reads,
-+                    long long io_read,
-+                    long io_reads_wait_timer,
-+                    long lock_que_wait_timer,
-+                    long que_wait_timer,
-+                    long page_access);
-+unsigned long thd_log_slow_verbosity(const void* thd);
-+int thd_opt_slow_log();
- int mysql_tmpfile(const char *prefix);
- int thd_killed(const void* thd);
- unsigned long thd_get_thread_id(const void* thd);
---- a/include/mysql/plugin.h
-+++ b/include/mysql/plugin.h
-@@ -545,6 +545,17 @@
- /* Increments the row counter, see THD::row_count */
- void thd_inc_row_count(MYSQL_THD thd);
- 
-+void increment_thd_innodb_stats(MYSQL_THD thd,
-+                    unsigned long long trx_id,
-+                    long io_reads,
-+                    long long io_read,
-+                    long io_reads_wait_timer,
-+                    long lock_que_wait_timer,
-+                    long que_wait_timer,
-+                    long page_access);
-+unsigned long thd_log_slow_verbosity(const MYSQL_THD thd);
-+int thd_opt_slow_log();
-+#define EXTENDED_SLOWLOG
- /**
-   Create a temporary file.
- 
---- /dev/null
-+++ b/patch_info/slow_extended.info
-@@ -0,0 +1,25 @@
-+File=slow_extended.patch
-+Name=Extended statistics in slow.log (not InnoDB part)
-+Version=1.3
-+Author=Percona <[e-mail]>
-+License=GPL
-+Comment=
-+Changelog
-[phone]
-+YK: Fix inefficient determination of trx, Make not to call useless gettimeofday when don't use slow log. Make log_slow_queries dynamic (bool).
-+
-[phone]
-+VT: Moved log_slow_rate_limit in SHOW VARIABLE into right place
-+
-+2008-11
-+Arjen Lentz: Fixups (backward compatibility) by Arjen Lentz <[e-mail]>
-+
-+2010-07
-+1) Fix overflow of query time and lock time (Bug 600360) (slow_extended_fix_overflow.patch merged)
-+2) Control global slow feature merged (control_global_slow.patch merged)
-+3) Microseconds in slow query log merged (microseconds_in_slow_query_log.patch merged)
-+4) Now use_global_long_query_time and use_global_log_slow_control are synonims. Add value "all" for use_global_log_slow_control (contol-global_slow-2.patch merged)
-+5) Fix innodb_stats on replication (Bug 600684)
-+6) Change variable types (system/command-line)
-+2011-01
-+Patch profiling_slow.patch was merged
---- a/scripts/mysqldumpslow.sh
-+++ b/scripts/mysqldumpslow.sh
-@@ -102,8 +102,8 @@
-     s/^#? Time: \d{6}\s+\d+:\d+:\d+.*\n//;
-     my ($user,$host) = s/^#? User\@Host:\s+(\S+)\s+\@\s+(\S+).*\n// ? ($1,$2) : ('','');
- 
--    s/^# Query_time: ([0-9.]+)\s+Lock_time: ([0-9.]+)\s+Rows_sent: ([0-9.]+).*\n//;
--    my ($t, $l, $r) = ($1, $2, $3);
-+    s/^# Query_time: (\d+(\.\d+)?)  Lock_time: (\d+(\.\d+)?)  Rows_sent: (\d+(\.\d+)?).*\n//;
-+    my ($t, $l, $r) = ($1, $3, $5);
-     $t -= $l unless $opt{l};
- 
-     # remove fluff that mysqld writes to log when it (re)starts:
---- a/sql/event_scheduler.cc
-+++ b/sql/event_scheduler.cc
-@@ -195,6 +195,7 @@
-   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);
- 
-   /*
---- a/sql/filesort.cc
-+++ b/sql/filesort.cc
-@@ -193,6 +193,7 @@
-   {
-     status_var_increment(thd->status_var.filesort_scan_count);
-   }
-+  thd->query_plan_flags|= QPLAN_FILESORT;
- #ifdef CAN_TRUST_RANGE
-   if (select && select->quick && select->quick->records > 0L)
-   {
-@@ -261,6 +262,7 @@
-     /* filesort cannot handle zero-length records during merge. */
-     DBUG_ASSERT(param.sort_length != 0);
- 
-+    thd->query_plan_flags|= QPLAN_FILESORT_DISK;
-     if (table_sort.buffpek && table_sort.buffpek_len < maxbuffer)
-     {
-       my_free(table_sort.buffpek);
-@@ -1209,6 +1211,7 @@
-   DBUG_ENTER("merge_buffers");
- 
-   status_var_increment(current_thd->status_var.filesort_merge_passes);
-+  current_thd->query_plan_fsort_passes++;
-   if (param->not_killable)
-   {
-     killed= &not_killable;
---- a/sql/log.cc
-+++ b/sql/log.cc
-@@ -715,11 +715,13 @@
- */
- 
- bool Log_to_csv_event_handler::
--  log_slow(THD *thd, time_t current_time, time_t query_start_arg,
-+  log_slow(THD *thd, ulonglong current_utime, time_t query_start_arg,
-            const char *user_host, uint user_host_len,
-            ulonglong query_utime, ulonglong lock_utime, bool is_command,
-            const char *sql_text, uint sql_text_len)
- {
-+  time_t current_time= my_time_possible_from_micro(current_utime);
-+
-   TABLE_LIST table_list;
-   TABLE *table;
-   bool result= TRUE;
-@@ -935,14 +937,14 @@
- /** Wrapper around MYSQL_LOG::write() for slow log. */
- 
- bool Log_to_file_event_handler::
--  log_slow(THD *thd, time_t current_time, time_t query_start_arg,
-+  log_slow(THD *thd, ulonglong current_utime, time_t query_start_arg,
-            const char *user_host, uint user_host_len,
-            ulonglong query_utime, ulonglong lock_utime, bool is_command,
-            const char *sql_text, uint sql_text_len)
- {
-   Silence_log_table_errors error_handler;
-   thd->push_internal_handler(&error_handler);
--  bool retval= mysql_slow_log.write(thd, current_time, query_start_arg,
-+  bool retval= mysql_slow_log.write(thd, current_utime, query_start_arg,
-                                     user_host, user_host_len,
-                                     query_utime, lock_utime, is_command,
-                                     sql_text, sql_text_len);
-@@ -1200,8 +1202,6 @@
- 
-   if (*slow_log_handler_list)
-   {
--    time_t current_time;
--
-     /* do not log slow queries from replication threads */
-     if (thd->slave_thread && !opt_log_slow_slave_statements)
-       return 0;
-@@ -1216,16 +1216,29 @@
-     /* fill in user_host value: the format is "%s[%s] @ %s [%s]" */
-     user_host_len= (strxnmov(user_host_buff, MAX_USER_HOST_SIZE,
-                              sctx->priv_user ? sctx->priv_user : "", "[",
--                             sctx->user ? sctx->user : "", "] @ ",
-+                             sctx->user ? sctx->user : (thd->slave_thread ? "SQL_SLAVE" : ""), "] @ ",
-                              sctx->host ? sctx->host : "", " [",
-                              sctx->ip ? sctx->ip : "", "]", NullS) -
-                     user_host_buff);
- 
--    current_time= my_time_possible_from_micro(current_utime);
-     if (thd->start_utime)
-     {
--      query_utime= (current_utime - thd->start_utime);
--      lock_utime=  (thd->utime_after_lock - thd->start_utime);
-+      if(current_utime < thd->start_utime)
-+      {
-+        query_utime= 0;
-+      }
-+      else
-+      {
-+        query_utime= (current_utime - thd->start_utime);
-+      }
-+      if(thd->utime_after_lock < thd->start_utime)
-+      {
-+        lock_utime= 0;
-+      }
-+      else
-+      {
-+        lock_utime= (thd->utime_after_lock - thd->start_utime);
-+      }
-     }
-     else
-     {
-@@ -1240,7 +1253,7 @@
-     }
- 
-     for (current_handler= slow_log_handler_list; *current_handler ;)
--      error= (*current_handler++)->log_slow(thd, current_time, thd->start_time,
-+      error= (*current_handler++)->log_slow(thd, current_utime, thd->start_time,
-                                             user_host_buff, user_host_len,
-                                             query_utime, lock_utime, is_command,
-                                             query, query_length) || error;
-@@ -2656,12 +2669,13 @@
-     TRUE - error occured
- */
- 
--bool MYSQL_QUERY_LOG::write(THD *thd, time_t current_time,
-+bool MYSQL_QUERY_LOG::write(THD *thd, ulonglong current_utime,
-                             time_t query_start_arg, const char *user_host,
-                             uint user_host_len, ulonglong query_utime,
-                             ulonglong lock_utime, bool is_command,
-                             const char *sql_text, uint sql_text_len)
- {
-+  time_t current_time= my_time_possible_from_micro(current_utime);
-   bool error= 0;
-   DBUG_ENTER("MYSQL_QUERY_LOG::write");
- 
-@@ -2683,17 +2697,28 @@
- 
-     if (!(specialflag & SPECIAL_SHORT_LOG_FORMAT))
-     {
--      if (current_time != last_time)
-+      if (opt_slow_query_log_timestamp_always || current_time != last_time)
-       {
-         last_time= current_time;
-         struct tm start;
-         localtime_r(&current_time, &start);
--
--        buff_len= my_snprintf(buff, sizeof buff,
--                              "# Time: %02d%02d%02d %2d:%02d:%02d\n",
--                              start.tm_year % 100, start.tm_mon + 1,
--                              start.tm_mday, start.tm_hour,
--                              start.tm_min, start.tm_sec);
-+	if(opt_slow_query_log_timestamp_precision & SLOG_MICROSECOND)
-+	{
-+	  ulonglong microsecond = current_utime % (1000 * 1000);
-+	  buff_len= snprintf(buff, sizeof buff,
-+	    "# Time: %02d%02d%02d %2d:%02d:%02d.%010lld\n",
-+            start.tm_year % 100, start.tm_mon + 1,
-+	    start.tm_mday, start.tm_hour,
-+	    start.tm_min, start.tm_sec,microsecond);
-+	}
-+	else
-+	{
-+	  buff_len= my_snprintf(buff, sizeof buff,
-+	    "# Time: %02d%02d%02d %2d:%02d:%02d\n",
-+            start.tm_year % 100, start.tm_mon + 1,
-+	    start.tm_mday, start.tm_hour,
-+	    start.tm_min, start.tm_sec);
-+	}
- 
-         /* Note that my_b_write() assumes it knows the length for this */
-         if (my_b_write(&log_file, (uchar*) buff, buff_len))
-@@ -2710,13 +2735,71 @@
-     /* 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));
-     if (my_b_printf(&log_file,
--                    "# Query_time: %s  Lock_time: %s"
--                    " Rows_sent: %lu  Rows_examined: %lu\n",
-+                    "# 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",
-+                    (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) == (uint) -1)
-+                    (ulong) thd->examined_row_count,
-+                    ((long) thd->get_row_count_func() > 0 ) ? (ulong) thd->get_row_count_func() : 0,
-+                    (ulong) thd->sent_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)
-       tmp_errno= errno;
-+
-+#if defined(ENABLED_PROFILING)
-+    thd->profiling.print_current(&log_file);
-+#endif
-+    if (thd->innodb_was_used)
-+    {
-+      char buf[20];
-+      snprintf(buf, 20, "%llX", thd->innodb_trx_id);
-+      if (my_b_printf(&log_file,
-+                    "# InnoDB_trx_id: %s\n", buf) == (uint) -1)
-+        tmp_errno=errno;
-+    }
-+    if ((thd->variables.log_slow_verbosity & (ULL(1) << SLOG_V_QUERY_PLAN)) &&
-+         my_b_printf(&log_file,
-+                    "# QC_Hit: %s  Full_scan: %s  Full_join: %s  Tmp_table: %s  Tmp_table_on_disk: %s\n" \
-+                    "# Filesort: %s  Filesort_on_disk: %s  Merge_passes: %lu\n",
-+                    ((thd->query_plan_flags & QPLAN_QC) ? "Yes" : "No"),
-+                    ((thd->query_plan_flags & QPLAN_FULL_SCAN) ? "Yes" : "No"),
-+                    ((thd->query_plan_flags & QPLAN_FULL_JOIN) ? "Yes" : "No"),
-+                    ((thd->query_plan_flags & QPLAN_TMP_TABLE) ? "Yes" : "No"),
-+                    ((thd->query_plan_flags & QPLAN_TMP_DISK) ? "Yes" : "No"),
-+                    ((thd->query_plan_flags & QPLAN_FILESORT) ? "Yes" : "No"),
-+                    ((thd->query_plan_flags & QPLAN_FILESORT_DISK) ? "Yes" : "No"),
-+                    thd->query_plan_fsort_passes) == (uint) -1)
-+      tmp_errno=errno;
-+    if ((thd->variables.log_slow_verbosity & (ULL(1) << SLOG_V_INNODB)) && thd->innodb_was_used)
-+    {
-+      char buf[3][20];
-+      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);
-+      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_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;
-+    } 
-+    else
-+    {
-+      if ((thd->variables.log_slow_verbosity & (ULL(1) << SLOG_V_INNODB)) &&
-+          my_b_printf(&log_file,"# No InnoDB statistics available for this query\n") == (uint) -1)
-+        tmp_errno=errno;
-+    }
-+
-     if (thd->db && strcmp(thd->db, db))
-     {						// Database changed
-       if (my_b_printf(&log_file,"use %s;\n",thd->db) == (uint) -1)
---- a/sql/log.h
-+++ b/sql/log.h
-@@ -242,7 +242,7 @@
-              uint user_host_len, int thread_id,
-              const char *command_type, uint command_type_len,
-              const char *sql_text, uint sql_text_len);
--  bool write(THD *thd, time_t current_time, time_t query_start_arg,
-+  bool write(THD *thd, ulonglong current_time, time_t query_start_arg,
-              const char *user_host, uint user_host_len,
-              ulonglong query_utime, ulonglong lock_utime, bool is_command,
-              const char *sql_text, uint sql_text_len);
-@@ -515,7 +515,7 @@
-   virtual bool init()= 0;
-   virtual void cleanup()= 0;
- 
--  virtual bool log_slow(THD *thd, time_t current_time,
-+  virtual bool log_slow(THD *thd, ulonglong current_time,
-                         time_t query_start_arg, const char *user_host,
-                         uint user_host_len, ulonglong query_utime,
-                         ulonglong lock_utime, bool is_command,
-@@ -544,7 +544,7 @@
-   virtual bool init();
-   virtual void cleanup();
- 
--  virtual bool log_slow(THD *thd, time_t current_time,
-+  virtual bool log_slow(THD *thd, ulonglong current_utime,
-                         time_t query_start_arg, const char *user_host,
-                         uint user_host_len, ulonglong query_utime,
-                         ulonglong lock_utime, bool is_command,
-@@ -576,7 +576,7 @@
-   virtual bool init();
-   virtual void cleanup();
- 
--  virtual bool log_slow(THD *thd, time_t current_time,
-+  virtual bool log_slow(THD *thd, ulonglong current_utime,
-                         time_t query_start_arg, const char *user_host,
-                         uint user_host_len, ulonglong query_utime,
-                         ulonglong lock_utime, bool is_command,
---- a/sql/mysqld.cc
-+++ b/sql/mysqld.cc
-@@ -421,6 +421,10 @@
- char* opt_secure_file_priv;
- my_bool opt_log_slow_admin_statements= 0;
- my_bool opt_log_slow_slave_statements= 0;
-+my_bool opt_log_slow_sp_statements= 0;
-+my_bool opt_slow_query_log_timestamp_always= 0;
-+ulonglong opt_slow_query_log_use_global_control= 0;
-+ulong opt_slow_query_log_timestamp_precision= 0;
- my_bool lower_case_file_system= 0;
- my_bool opt_large_pages= 0;
- my_bool opt_super_large_pages= 0;
-@@ -5892,14 +5896,10 @@
-    "Don't log extra information to update and slow-query logs.",
-    &opt_short_log_format, &opt_short_log_format,
-    0, GET_BOOL, NO_ARG, 0, 0, 0, 0, 0, 0},
--  {"log-slow-admin-statements", 0,
--   "Log slow OPTIMIZE, ANALYZE, ALTER and other administrative statements to "
--   "the slow log if it is open.", &opt_log_slow_admin_statements,
--   &opt_log_slow_admin_statements, 0, GET_BOOL, NO_ARG, 0, 0, 0, 0, 0, 0},
-- {"log-slow-slave-statements", 0,
-+ /*{"log-slow-slave-statements", 0,
-   "Log slow statements executed by slave thread to the slow log if it is open.",
-   &opt_log_slow_slave_statements, &opt_log_slow_slave_statements,
--  0, GET_BOOL, NO_ARG, 0, 0, 0, 0, 0, 0},
-+  0, GET_BOOL, NO_ARG, 0, 0, 0, 0, 0, 0},*/
-   {"log-slow-queries", OPT_SLOW_QUERY_LOG,
-    "Log slow queries to a table or log file. Defaults logging to table "
-    "mysql.slow_log or hostname-slow.log if --log-output=file is used. "
-@@ -7288,6 +7288,10 @@
- 
- C_MODE_END
- 
-+/* defined in sys_vars.cc */
-+extern void init_log_slow_verbosity();
-+extern void init_slow_query_log_use_global_control();
-+
- /**
-   Get server options from the command line,
-   and perform related server initializations.
-@@ -7437,6 +7441,8 @@
-   global_system_variables.long_query_time= (ulonglong)
-     (global_system_variables.long_query_time_double * 1e6);
- 
-+  init_log_slow_verbosity();
-+  init_slow_query_log_use_global_control();
-   if (opt_short_log_format)
-     opt_specialflag|= SPECIAL_SHORT_LOG_FORMAT;
- 
---- a/sql/mysqld.h
-+++ b/sql/mysqld.h
-@@ -116,6 +116,10 @@
- extern char* opt_secure_backup_file_priv;
- extern size_t opt_secure_backup_file_priv_len;
- extern my_bool opt_log_slow_admin_statements, opt_log_slow_slave_statements;
-+extern my_bool opt_log_slow_sp_statements;
-+extern my_bool opt_slow_query_log_timestamp_always;
-+extern ulonglong opt_slow_query_log_use_global_control;
-+extern ulong opt_slow_query_log_timestamp_precision;
- extern my_bool sp_automatic_privileges, opt_noacl;
- extern my_bool opt_old_style_user_limits, trust_function_creators;
- extern uint opt_crash_binlog_innodb;
---- a/sql/slave.cc
-+++ b/sql/slave.cc
-@@ -2038,6 +2038,7 @@
-     + MAX_LOG_EVENT_HEADER;  /* note, incr over the global not session var */
-   thd->slave_thread = 1;
-   thd->enable_slow_log= opt_log_slow_slave_statements;
-+  thd->write_to_slow_log= opt_log_slow_slave_statements;
-   set_slave_thread_options(thd);
-   thd->client_capabilities = CLIENT_LOCAL_FILES;
-   mysql_mutex_lock(&LOCK_thread_count);
---- a/sql/sp_head.cc
-+++ b/sql/sp_head.cc
-@@ -2152,7 +2152,7 @@
-     DBUG_PRINT("info",(" %.*s: eval args done", (int) m_name.length, 
-                        m_name.str));
-   }
--  if (!(m_flags & LOG_SLOW_STATEMENTS) && thd->enable_slow_log)
-+  if (!(m_flags & LOG_SLOW_STATEMENTS || opt_log_slow_sp_statements) && thd->enable_slow_log)
-   {
-     DBUG_PRINT("info", ("Disabling slow log for the execution"));
-     save_enable_slow_log= true;
---- a/sql/sql_cache.cc
-+++ b/sql/sql_cache.cc
-@@ -1756,6 +1756,7 @@
-     response, we can't handle it anyway.
-   */
-   (void) trans_commit_stmt(thd);
-+  thd->query_plan_flags|= QPLAN_QC;
-   if (!thd->stmt_da->is_set())
-     thd->stmt_da->disable_status();
- 
-@@ -1766,6 +1767,7 @@
- err_unlock:
-   unlock();
- err:
-+  thd->query_plan_flags|= QPLAN_QC_NO;
-   MYSQL_QUERY_CACHE_MISS(thd->query());
-   DBUG_RETURN(0);				// Query was not cached
- }
---- a/sql/sql_class.cc
-+++ b/sql/sql_class.cc
-@@ -616,6 +616,37 @@
-   thd->warning_info->inc_current_row_for_warning();
- }
- 
-+extern "C"
-+void increment_thd_innodb_stats(THD* thd,
-+                                unsigned long long trx_id,
-+                                long io_reads,
-+                                long long  io_read,
-+                                long      io_reads_wait_timer,
-+                                long      lock_que_wait_timer,
-+                                long      que_wait_timer,
-+                                long      page_access)
-+{
-+  thd->innodb_was_used=               TRUE;
-+  thd->innodb_trx_id=                 trx_id;
-+  thd->innodb_io_reads+=              io_reads;
-+  thd->innodb_io_read+=               io_read;
-+  thd->innodb_io_reads_wait_timer+=   io_reads_wait_timer;
-+  thd->innodb_lock_que_wait_timer+=   lock_que_wait_timer;
-+  thd->innodb_innodb_que_wait_timer+= que_wait_timer;
-+  thd->innodb_page_access+=           page_access;
-+}
-+
-+extern "C"
-+unsigned long thd_log_slow_verbosity(const THD *thd)
-+{
-+  return (unsigned long) thd->variables.log_slow_verbosity;
-+}
-+
-+extern "C"
-+int thd_opt_slow_log()
-+{
-+  return (int) opt_slow_log;
-+}
- 
- /**
-   Dumps a text description of a thread, its security context
-@@ -942,6 +973,8 @@
-                            const char* msg,
-                            MYSQL_ERROR ** cond_hdl)
- {
-+  last_errno= sql_errno;
-+
-   if (!m_internal_handler)
-   {
-     *cond_hdl= NULL;
-@@ -1236,6 +1269,8 @@
-   /* Initialize the Debug Sync Facility. See debug_sync.cc. */
-   debug_sync_init_thread(this);
- #endif /* defined(ENABLED_DEBUG_SYNC) */
-+
-+  clear_slow_extended();
- }
- 
- 
-@@ -3682,8 +3717,6 @@
-   backup->in_sub_stmt=     in_sub_stmt;
-   backup->enable_slow_log= enable_slow_log;
-   backup->limit_found_rows= limit_found_rows;
--  backup->examined_row_count= examined_row_count;
--  backup->sent_row_count=   sent_row_count;
-   backup->cuted_fields=     cuted_fields;
-   backup->client_capabilities= client_capabilities;
-   backup->savepoints= transaction.savepoints;
-@@ -3691,6 +3724,7 @@
-     first_successful_insert_id_in_prev_stmt;
-   backup->first_successful_insert_id_in_cur_stmt= 
-     first_successful_insert_id_in_cur_stmt;
-+  reset_sub_statement_state_slow_extended(backup);
- 
-   if ((!lex->requires_prelocking() || is_update_query(lex->sql_command)) &&
-       !is_current_stmt_binlog_format_row())
-@@ -3706,13 +3740,74 @@
-   /* Disable result sets */
-   client_capabilities &= ~CLIENT_MULTI_RESULTS;
-   in_sub_stmt|= new_state;
--  examined_row_count= 0;
--  sent_row_count= 0;
-   cuted_fields= 0;
-   transaction.savepoints= 0;
-   first_successful_insert_id_in_cur_stmt= 0;
- }
- 
-+void THD::clear_slow_extended()
-+{
-+  DBUG_ENTER("THD::clear_slow_extended");
-+  sent_row_count=               0;
-+  examined_row_count=           0;
-+  bytes_sent_old=               status_var.bytes_sent;
-+  tmp_tables_used=              0;
-+  tmp_tables_disk_used=         0;
-+  tmp_tables_size=              0;
-+  innodb_was_used=              FALSE;
-+  innodb_trx_id=                0;
-+  innodb_io_reads=              0;
-+  innodb_io_read=               0;
-+  innodb_io_reads_wait_timer=   0;
-+  innodb_lock_que_wait_timer=   0;
-+  innodb_innodb_que_wait_timer= 0;
-+  innodb_page_access=           0;
-+  query_plan_flags=             QPLAN_NONE;
-+  query_plan_fsort_passes=      0;
-+  last_errno=                   0;
-+  DBUG_VOID_RETURN;
-+}
-+
-+void THD::reset_sub_statement_state_slow_extended(Sub_statement_state *backup)
-+{
-+  DBUG_ENTER("THD::reset_sub_statement_state_slow_extended");
-+  backup->sent_row_count=               sent_row_count;
-+  backup->examined_row_count=           examined_row_count;
-+  backup->tmp_tables_used=              tmp_tables_used;
-+  backup->tmp_tables_disk_used=         tmp_tables_disk_used;
-+  backup->tmp_tables_size=              tmp_tables_size;
-+  backup->innodb_was_used=              innodb_was_used;
-+  backup->innodb_io_reads=              innodb_io_reads;
-+  backup->innodb_io_read=               innodb_io_read;
-+  backup->innodb_io_reads_wait_timer=   innodb_io_reads_wait_timer;
-+  backup->innodb_lock_que_wait_timer=   innodb_lock_que_wait_timer;
-+  backup->innodb_innodb_que_wait_timer= innodb_innodb_que_wait_timer;
-+  backup->innodb_page_access=           innodb_page_access;
-+  backup->query_plan_flags=             query_plan_flags;
-+  backup->query_plan_fsort_passes=      query_plan_fsort_passes;
-+  clear_slow_extended();
-+  DBUG_VOID_RETURN;
-+}
-+
-+void THD::restore_sub_statement_state_slow_extended(const Sub_statement_state *backup)
-+{
-+  DBUG_ENTER("THD::restore_sub_statement_state_slow_extended");
-+  sent_row_count=                backup->sent_row_count;
-+  examined_row_count+=           backup->examined_row_count;
-+  tmp_tables_used+=              backup->tmp_tables_used;
-+  tmp_tables_disk_used+=         backup->tmp_tables_disk_used;
-+  tmp_tables_size+=              backup->tmp_tables_size;
-+  innodb_was_used=               (innodb_was_used || backup->innodb_was_used);
-+  innodb_io_reads+=              backup->innodb_io_reads;
-+  innodb_io_read+=               backup->innodb_io_read;
-+  innodb_io_reads_wait_timer+=   backup->innodb_io_reads_wait_timer;
-+  innodb_lock_que_wait_timer+=   backup->innodb_lock_que_wait_timer;
-+  innodb_innodb_que_wait_timer+= backup->innodb_innodb_que_wait_timer;
-+  innodb_page_access+=           backup->innodb_page_access;
-+  query_plan_flags|=             backup->query_plan_flags;
-+  query_plan_fsort_passes+=      backup->query_plan_fsort_passes;
-+  DBUG_VOID_RETURN;
-+}
- 
- void THD::restore_sub_statement_state(Sub_statement_state *backup)
- {
-@@ -3753,7 +3848,6 @@
-   first_successful_insert_id_in_cur_stmt= 
-     backup->first_successful_insert_id_in_cur_stmt;
-   limit_found_rows= backup->limit_found_rows;
--  sent_row_count=   backup->sent_row_count;
-   client_capabilities= backup->client_capabilities;
-   /*
-     If we've left sub-statement mode, reset the fatal error flag.
-@@ -3771,8 +3865,8 @@
-     The following is added to the old values as we are interested in the
-     total complexity of the query
-   */
--  examined_row_count+= backup->examined_row_count;
-   cuted_fields+=       backup->cuted_fields;
-+  restore_sub_statement_state_slow_extended(backup);
-   DBUG_VOID_RETURN;
- }
- 
---- a/sql/sql_class.h
-+++ b/sql/sql_class.h
-@@ -60,6 +60,33 @@
- enum enum_duplicates { DUP_ERROR, DUP_REPLACE, DUP_UPDATE };
- enum enum_delay_key_write { DELAY_KEY_WRITE_NONE, DELAY_KEY_WRITE_ON,
- 			    DELAY_KEY_WRITE_ALL };
-+enum enum_slow_query_log_use_global_control {
-+  SLOG_UG_LOG_SLOW_FILTER, SLOG_UG_LOG_SLOW_RATE_LIMIT
-+  , SLOG_UG_LOG_SLOW_VERBOSITY, SLOG_UG_LONG_QUERY_TIME
-+  , SLOG_UG_MIN_EXAMINED_ROW_LIMIT, SLOG_UG_ALL
-+};
-+enum enum_log_slow_verbosity { 
-+  SLOG_V_MICROTIME, SLOG_V_QUERY_PLAN, SLOG_V_INNODB, 
-+  SLOG_V_PROFILING, SLOG_V_PROFILING_USE_GETRUSAGE,
-+  SLOG_V_MINIMAL, SLOG_V_STANDARD, SLOG_V_FULL
-+};
-+enum enum_slow_query_log_timestamp_precision {
-+  SLOG_SECOND, SLOG_MICROSECOND
-+};
-+#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
-+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,
-+  SLOG_F_FILESORT_DISK
-+};
- enum enum_slave_exec_mode { SLAVE_EXEC_MODE_STRICT,
-                             SLAVE_EXEC_MODE_IDEMPOTENT,
-                             SLAVE_EXEC_MODE_LAST_BIT};
-@@ -508,6 +535,21 @@
- 
-   my_bool sysdate_is_now;
- 
-+#ifndef DBUG_OFF
-+  ulonglong query_exec_time;
-+  double    query_exec_time_double;
-+#endif
-+  ulong log_slow_rate_limit;
-+  ulonglong log_slow_filter;
-+  ulonglong log_slow_verbosity;
-+
-+  ulong      innodb_io_reads;
-+  ulonglong  innodb_io_read;
-+  ulong      innodb_io_reads_wait_timer;
-+  ulong      innodb_lock_que_wait_timer;
-+  ulong      innodb_innodb_que_wait_timer;
-+  ulong      innodb_page_access;
-+
-   double long_query_time_double;
- 
- } SV;
-@@ -1140,6 +1182,24 @@
-   uint in_sub_stmt;
-   bool enable_slow_log;
-   bool last_insert_id_used;
-+
-+  /*** Following variables used in slow_extended.patch ***/
-+  ulong      tmp_tables_used;
-+  ulong      tmp_tables_disk_used;
-+  ulonglong  tmp_tables_size;
-+
-+  bool       innodb_was_used;
-+  ulong      innodb_io_reads;
-+  ulonglong  innodb_io_read;
-+  ulong      innodb_io_reads_wait_timer;
-+  ulong      innodb_lock_que_wait_timer;
-+  ulong      innodb_innodb_que_wait_timer;
-+  ulong      innodb_page_access;
-+
-+  ulong      query_plan_flags;
-+  ulong      query_plan_fsort_passes;
-+  /*** The variables above used in slow_extended.patch ***/
-+
-   SAVEPOINT *savepoints;
-   enum enum_check_fields count_cuted_fields;
- };
-@@ -1588,6 +1648,71 @@
-   thr_lock_type update_lock_default;
-   Delayed_insert *di;
- 
-+  /*** 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.
-+  */
-+  ulonglong  bytes_sent_old;
-+  /*
-+    Variables tmp_tables_*** collect statistics about usage of temporary tables
-+  */
-+  ulong      tmp_tables_used;
-+  ulong      tmp_tables_disk_used;
-+  ulonglong  tmp_tables_size;
-+  /*
-+    Variable innodb_was_used shows used or not InnoDB engine in current query.
-+  */
-+  bool       innodb_was_used;
-+  /*
-+    Following Variables innodb_*** (is |should be) different from
-+    default values only if (innodb_was_used==TRUE)
-+  */
-+  ulonglong  innodb_trx_id;
-+  ulong      innodb_io_reads;
-+  ulonglong  innodb_io_read;
-+  ulong      innodb_io_reads_wait_timer;
-+  ulong      innodb_lock_que_wait_timer;
-+  ulong      innodb_innodb_que_wait_timer;
-+  ulong      innodb_page_access;
-+
-+  /*
-+    Variable query_plan_flags collects information about query plan entites
-+    used on query execution.
-+  */
-+  ulong      query_plan_flags;
-+  /*
-+    Variable query_plan_fsort_passes collects information about file sort passes
-+    acquired during query execution.
-+  */
-+  ulong      query_plan_fsort_passes;
-+  /*
-+    Query can generate several errors/warnings during execution
-+    (see THD::handle_condition comment in sql_class.h)
-+    Variable last_errno contains the last error/warning acquired during
-+    query execution.
-+  */
-+  uint       last_errno;
-+  /*** The variables above used in slow_extended.patch ***/
-+
-+  /*** Following methods used in slow_extended.patch ***/
-+  void clear_slow_extended();
-+  void reset_sub_statement_state_slow_extended(Sub_statement_state *backup);
-+  void restore_sub_statement_state_slow_extended(const Sub_statement_state *backup);
-+  /*** The methods above used in slow_extended.patch ***/
-+
-   /* <> 0 if we are inside of trigger or stored function. */
-   uint in_sub_stmt;
- 
---- a/sql/sql_connect.cc
-+++ b/sql/sql_connect.cc
-@@ -721,6 +721,15 @@
-   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. :) 
-+    */ 
-+    thd->write_to_slow_log= FALSE; 
-+    if (thd->variables.log_slow_rate_limit <= 1 ||  
-+        (thd->thread_id % thd->variables.log_slow_rate_limit) == 0) 
-+         thd->write_to_slow_log= TRUE; 
-+
-   prepare_new_connection_state(thd);
-   return FALSE;
- }
---- a/sql/sql_parse.cc
-+++ b/sql/sql_parse.cc
-@@ -114,6 +114,7 @@
- 
- static bool execute_sqlcom_select(THD *thd, TABLE_LIST *all_tables);
- static void sql_kill(THD *thd, ulong id, bool only_kill_query);
-+static inline ulonglong get_query_exec_time(THD *thd, ulonglong cur_utime);
- 
- const char *any_db="*any*";	// Special symbol for check_access
- 
-@@ -888,6 +889,7 @@
-     the slow log only if opt_log_slow_admin_statements is set.
-   */
-   thd->enable_slow_log= TRUE;
-+  thd->clear_slow_extended();
-   thd->lex->sql_command= SQLCOM_END; /* to avoid confusing VIEW detectors */
-   thd->set_time();
-   if (!thd->is_valid_time())
-@@ -1430,6 +1432,60 @@
-   DBUG_RETURN(error);
- }
- 
-+/**
-+   Calculate execution time for the current query.
-+
-+   For debug builds, check the session value of query_exec_time
-+   and if it is not zero, return it instead of the actual execution time.
-+
-+   SET queries are ignored so that statements changing query_exec_time are not
-+   affected by themselves.
-+
-+   @param thd              thread handle
-+   @param lex              current relative time in microseconds
-+
-+   @return                 time in microseconds from utime_after_lock
-+*/
-+
-+static inline ulonglong get_query_exec_time(THD *thd, ulonglong cur_utime)
-+{
-+  ulonglong res;
-+#ifndef DBUG_OFF
-+  if (thd->variables.query_exec_time != 0)
-+    res= thd->lex->sql_command != SQLCOM_SET_OPTION ?
-+      thd->variables.query_exec_time : 0;
-+  else
-+#endif
-+
-+  res= cur_utime - thd->utime_after_lock;
-+
-+  if (res > thd->variables.long_query_time)
-+    thd->server_status|= SERVER_QUERY_WAS_SLOW;
-+  else
-+    thd->server_status&= ~SERVER_QUERY_WAS_SLOW;
-+
-+  return res;
-+}
-+
-+
-+static inline void copy_global_to_session(THD *thd, ulong flag,
-+                                          const ulong *val)
-+{
-+  my_ptrdiff_t offset = ((char *)val - (char *)&global_system_variables);
-+  if (opt_slow_query_log_use_global_control & (1ULL << flag))
-+    *(ulong *)((char *) &thd->variables + offset) = *val;
-+}
-+
-+
-+static inline void copy_global_to_session(THD *thd, ulong flag,
-+                                          const ulonglong *val)
-+{
-+  my_ptrdiff_t offset = ((char *)val - (char *)&global_system_variables);
-+  if (opt_slow_query_log_use_global_control & (1ULL << flag))
-+    *(ulonglong *)((char *) &thd->variables + offset) = *val;
-+}
-+
-+
- 
- void log_slow_statement(THD *thd)
- {
-@@ -1443,13 +1499,48 @@
-   if (unlikely(thd->in_sub_stmt))
-     DBUG_VOID_RETURN;                           // Don't set time for sub stmt
- 
-+  /* 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->query_plan_flags & QPLAN_QC))))
-+    DBUG_VOID_RETURN;
-+
-+  ulonglong end_utime_of_query= thd->current_utime();
-+  ulonglong query_exec_time= get_query_exec_time(thd, end_utime_of_query);
-+
-+  /*
-+    Low long_query_time value most likely means user is debugging stuff and even
-+    though some thread's queries are not supposed to be logged b/c of the rate
-+    limit, if one of them takes long enough (>= 1 second) it will be sensible
-+    to make an exception and write to slow log anyway.
-+  */
-+
-+  system_variables const &g= global_system_variables;
-+  copy_global_to_session(thd, SLOG_UG_LOG_SLOW_FILTER,
-+                         &g.log_slow_filter);
-+  copy_global_to_session(thd, SLOG_UG_LOG_SLOW_RATE_LIMIT,
-+                         &g.log_slow_rate_limit);
-+  copy_global_to_session(thd, SLOG_UG_LOG_SLOW_VERBOSITY,
-+                         &g.log_slow_verbosity);
-+  copy_global_to_session(thd, SLOG_UG_LONG_QUERY_TIME,
-+                         &g.long_query_time);
-+  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 != TRUE
-+      && (thd->variables.long_query_time >= 1000000
-+          || (ulong) query_exec_time < 1000000))
-+    DBUG_VOID_RETURN;
-+
-+
-   /*
-     Do not log administrative statements unless the appropriate option is
-     set.
-   */
-   if (thd->enable_slow_log)
-   {
--    ulonglong end_utime_of_query= thd->current_utime();
-     thd_proc_info(thd, "logging slow query");
- 
-     if (((thd->server_status & SERVER_QUERY_WAS_SLOW) ||
-@@ -5301,7 +5392,8 @@
-   thd->stmt_da->reset_diagnostics_area();
-   thd->warning_info->reset_for_next_command();
-   thd->rand_used= 0;
--  thd->sent_row_count= thd->examined_row_count= 0;
-+
-+  thd->clear_slow_extended();
- 
-   thd->reset_current_stmt_binlog_format_row();
-   thd->binlog_unsafe_warning_flags= 0;
---- a/sql/sql_select.cc
-+++ b/sql/sql_select.cc
-@@ -6902,7 +6902,10 @@
- 	  {
- 	    join->thd->server_status|=SERVER_QUERY_NO_INDEX_USED;
- 	    if (statistics)
-+            {
- 	      status_var_increment(join->thd->status_var.select_scan_count);
-+              join->thd->query_plan_flags|= QPLAN_FULL_SCAN;
-+            }
- 	  }
- 	}
- 	else
-@@ -6916,7 +6919,10 @@
- 	  {
- 	    join->thd->server_status|=SERVER_QUERY_NO_INDEX_USED;
- 	    if (statistics)
-+            {
- 	      status_var_increment(join->thd->status_var.select_full_join_count);
-+              join->thd->query_plan_flags|= QPLAN_FULL_JOIN;
-+            }
- 	  }
- 	}
- 	if (!table->no_keyread)
-@@ -10264,6 +10270,7 @@
-               (ulong) rows_limit,test(group)));
- 
-   status_var_increment(thd->status_var.created_tmp_tables);
-+  thd->query_plan_flags|= QPLAN_TMP_TABLE;
- 
-   if (use_temp_pool && !(test_flags & TEST_KEEP_TMP_TABLES))
-     temp_pool_slot = bitmap_lock_set_next(&temp_pool);
-@@ -11162,6 +11169,7 @@
-     goto err;
-   }
-   status_var_increment(table->in_use->status_var.created_tmp_disk_tables);
-+  table->in_use->query_plan_flags|= QPLAN_TMP_DISK;
-   share->db_record_offset= 1;
-   DBUG_RETURN(0);
-  err:
-@@ -11180,6 +11188,14 @@
-   save_proc_info=thd->proc_info;
-   thd_proc_info(thd, "removing tmp table");
- 
-+  thd->tmp_tables_used++;
-+  if (entry->file)
-+  {
-+    thd->tmp_tables_size += entry->file->stats.data_file_length;
-+    if (entry->file->ht->db_type != DB_TYPE_HEAP)
-+      thd->tmp_tables_disk_used++;
-+  }
-+
-   // Release latches since this can take a long time
-   ha_release_temporary_latches(thd);
- 
---- a/sql/sql_show.cc
-+++ b/sql/sql_show.cc
-@@ -1950,8 +1950,17 @@
-         table->field[4]->store(command_name[tmp->command].str,
-                                command_name[tmp->command].length, cs);
-       /* MYSQL_TIME */
--      table->field[5]->store((longlong)(tmp->start_time ?
--                                      now - tmp->start_time : 0), FALSE);
-+      longlong value_in_time_column= 0;
-+      if(tmp->start_time)
-+      {
-+        value_in_time_column = (now - tmp->start_time);
-+        if(value_in_time_column > now)
-+        {
-+          value_in_time_column= 0;
-+        }
-+      }
-+      table->field[5]->store(value_in_time_column, FALSE);
-+
-       /* STATE */
-       if ((val= thread_state_info(tmp)))
-       {
---- a/sql/sys_vars.cc
-+++ b/sql/sys_vars.cc
-@@ -972,6 +972,29 @@
-        NO_MUTEX_GUARD, NOT_IN_BINLOG, ON_CHECK(0),
-        ON_UPDATE(update_cached_long_query_time));
- 
-+#ifndef DBUG_OFF
-+static bool update_cached_query_exec_time(sys_var *self, THD *thd,
-+                                          enum_var_type type)
-+{
-+  if (type == OPT_SESSION)
-+    thd->variables.query_exec_time=
-+      double2ulonglong(thd->variables.query_exec_time_double * 1e6);
-+  else
-+    global_system_variables.query_exec_time=
-+      double2ulonglong(global_system_variables.query_exec_time_double * 1e6);
-+  return false;
-+}
-+
-+static Sys_var_double Sys_query_exec_time(
-+       "query_exec_time",
-+       "Pretend queries take this many seconds. When 0 (the default) use the "
-+       "actual execution time. Used only for debugging.",
-+       SESSION_VAR(query_exec_time_double),
-+       NO_CMD_LINE, VALID_RANGE(0, LONG_TIMEOUT), DEFAULT(0),
-+       NO_MUTEX_GUARD, IN_BINLOG, ON_CHECK(0),
-+       ON_UPDATE(update_cached_query_exec_time));
-+#endif
-+
- static bool fix_low_prio_updates(sys_var *self, THD *thd, enum_var_type type)
- {
-   if (type == OPT_SESSION)
-@@ -2898,6 +2921,123 @@
-        DEFAULT(FALSE), NO_MUTEX_GUARD, NOT_IN_BINLOG, ON_CHECK(0),
-        ON_UPDATE(fix_log_state));
- 
-+const char *log_slow_filter_name[]= { "qc_miss", "full_scan", "full_join",
-+                                      "tmp_table", "tmp_table_on_disk", "filesort", "filesort_on_disk", 0};
-+static Sys_var_set Sys_log_slow_filter(
-+       "log_slow_filter",
-+       "Log only the queries that followed certain execution plan. "
-+       "Multiple flags allowed in a comma-separated string. "
-+       "[qc_miss, full_scan, full_join, tmp_table, tmp_table_on_disk, "
-+       "filesort, filesort_on_disk]",
-+       SESSION_VAR(log_slow_filter), CMD_LINE(REQUIRED_ARG),
-+       log_slow_filter_name, DEFAULT(0));
-+static Sys_var_ulong sys_log_slow_rate_limit(
-+       "log_slow_rate_limit","Rate limit statement writes to slow log to only those from every (1/log_slow_rate_limit) session.",
-+       SESSION_VAR(log_slow_rate_limit), CMD_LINE(REQUIRED_ARG),
-+       VALID_RANGE(1, ULONG_MAX), DEFAULT(1), BLOCK_SIZE(1));
-+const char* log_slow_verbosity_name[] = { 
-+  "microtime", "query_plan", "innodb", 
-+  "profiling", "profling_use_getrusage", 
-+  "minimal", "standard", "full", 0
-+};
-+static ulonglong update_log_slow_verbosity_replace(ulonglong value, ulonglong what, ulonglong by)
-+{
-+  if((value & what) == what)
-+  {
-+    value = value & (~what);
-+    value = value | by;
-+  }
-+  return value;
-+}
-+void update_log_slow_verbosity(ulonglong* value_ptr)
-+{
-+  ulonglong &value    = *value_ptr;
-+  ulonglong microtime= ULL(1) << SLOG_V_MICROTIME;
-+  ulonglong query_plan= ULL(1) << SLOG_V_QUERY_PLAN;
-+  ulonglong innodb= ULL(1) << SLOG_V_INNODB;
-+  ulonglong minimal= ULL(1) << SLOG_V_MINIMAL;
-+  ulonglong standard= ULL(1) << SLOG_V_STANDARD;
-+  ulonglong full= ULL(1) << SLOG_V_FULL;
-+  value= update_log_slow_verbosity_replace(value,minimal,microtime);
-+  value= update_log_slow_verbosity_replace(value,standard,microtime | query_plan);
-+  value= update_log_slow_verbosity_replace(value,full,microtime | query_plan | innodb);
-+}
-+static bool update_log_slow_verbosity_helper(sys_var */*self*/, THD *thd,
-+                                          enum_var_type type)
-+{
-+  if(type == OPT_SESSION)
-+  {
-+    update_log_slow_verbosity(&(thd->variables.log_slow_verbosity));
-+  }
-+  else
-+  {
-+    update_log_slow_verbosity(&(global_system_variables.log_slow_verbosity));
-+  }
-+  return false;
-+}
-+void init_slow_query_log_use_global_control()
-+{
-+  update_log_slow_verbosity(&(global_system_variables.log_slow_verbosity));
-+}
-+static Sys_var_set Sys_log_slow_verbosity(
-+        "log_slow_verbosity",
-+        "Choose how verbose the messages to your slow log will be. "
-+        "Multiple flags allowed in a comma-separated string. [microtime, query_plan, innodb, profiling, profiling_use_getrusage]",
-+        SESSION_VAR(log_slow_verbosity), CMD_LINE(REQUIRED_ARG),
-+        log_slow_verbosity_name, DEFAULT(SLOG_V_MICROTIME),
-+        NO_MUTEX_GUARD, NOT_IN_BINLOG, ON_CHECK(0),
-+        ON_UPDATE(update_log_slow_verbosity_helper));
-+static Sys_var_mybool Sys_log_slow_slave_statements(
-+       "log_slow_slave_statements",
-+       "Log queries replayed be the slave SQL thread",
-+       GLOBAL_VAR(opt_log_slow_slave_statements), CMD_LINE(OPT_ARG),
-+       DEFAULT(FALSE));
-+static Sys_var_mybool Sys_log_slow_admin_statements(
-+       "log_slow_admin_statements",
-+       "Log slow OPTIMIZE, ANALYZE, ALTER and other administrative statements"
-+       " to the slow log if it is open.",
-+       GLOBAL_VAR(opt_log_slow_admin_statements), CMD_LINE(OPT_ARG),
-+       DEFAULT(FALSE));
-+static Sys_var_mybool Sys_log_slow_sp_statements(
-+       "log_slow_sp_statements",
-+       "Log slow statements executed by stored procedure to the slow log if it is open.",
-+       GLOBAL_VAR(opt_log_slow_sp_statements), CMD_LINE(OPT_ARG),
-+       DEFAULT(TRUE));
-+static Sys_var_mybool Sys_slow_query_log_timestamp_always(
-+       "slow_query_log_timestamp_always",
-+       "Timestamp is printed for all records of the slow log even if they are same time.",
-+       GLOBAL_VAR(opt_slow_query_log_timestamp_always), CMD_LINE(OPT_ARG),
-+       DEFAULT(FALSE));
-+const char *slow_query_log_use_global_control_name[]= { "log_slow_filter", "log_slow_rate_limit", "log_slow_verbosity", "long_query_time", "min_examined_row_limit", "all", 0};
-+static bool update_slow_query_log_use_global_control(sys_var */*self*/, THD */*thd*/,
-+                                               enum_var_type /*type*/)
-+{
-+  if(opt_slow_query_log_use_global_control & (ULL(1) << SLOG_UG_ALL))
-+  {
-+    opt_slow_query_log_use_global_control=
-+      SLOG_UG_LOG_SLOW_FILTER | SLOG_UG_LOG_SLOW_RATE_LIMIT | SLOG_UG_LOG_SLOW_VERBOSITY |
-+      SLOG_UG_LONG_QUERY_TIME | SLOG_UG_MIN_EXAMINED_ROW_LIMIT;
-+  }
-+  return false;
-+}
-+void init_log_slow_verbosity()
-+{
-+  update_slow_query_log_use_global_control(0,0,OPT_GLOBAL);
-+}
-+static Sys_var_set Sys_slow_query_log_use_global_control(
-+       "slow_query_log_use_global_control",
-+       "Choose flags, wich always use the global variables. Multiple flags allowed in a comma-separated string. [none, log_slow_filter, log_slow_rate_limit, log_slow_verbosity, long_query_time, min_examined_row_limit, all]",
-+       GLOBAL_VAR(opt_slow_query_log_use_global_control), CMD_LINE(REQUIRED_ARG),
-+       slow_query_log_use_global_control_name, DEFAULT(0),
-+        NO_MUTEX_GUARD, NOT_IN_BINLOG, ON_CHECK(0),
-+       ON_UPDATE(update_slow_query_log_use_global_control));
-+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]",
-+       GLOBAL_VAR(opt_slow_query_log_timestamp_precision), CMD_LINE(REQUIRED_ARG),
-+       slow_query_log_timestamp_precision_name, DEFAULT(SLOG_SECOND));
-+ 
- /* Synonym of "slow_query_log" for consistency with SHOW VARIABLES output */
- static Sys_var_mybool Sys_log_slow(
-        "log_slow_queries",
---- a/sql/sql_profile.cc
-+++ b/sql/sql_profile.cc
-@@ -243,7 +243,8 @@
- {
-   time_usecs= (double) my_getsystime() / 10.0;  /* 1 sec was 1e7, now is 1e6 */
- #ifdef HAVE_GETRUSAGE
--  getrusage(RUSAGE_SELF, &rusage);
-+  if ((profile->get_profiling())->enabled_getrusage())
-+    getrusage(RUSAGE_SELF, &rusage);
- #elif defined(_WIN32)
-   FILETIME ftDummy;
-   // NOTE: Get{Process|Thread}Times has a granularity of the clock interval,
-@@ -251,6 +252,19 @@
-   // measurable by this function.
-   GetProcessTimes(GetCurrentProcess(), &ftDummy, &ftDummy, &ftKernel, &ftUser);
- #endif
-+
-+#ifdef HAVE_CLOCK_GETTIME
-+  struct timespec tp;
-+
-+  if (!(clock_gettime(CLOCK_THREAD_CPUTIME_ID, &tp)))
-+  {
-+    cpu_time_usecs= tp.tv_sec*1000000000.0 + tp.tv_nsec;
-+  }
-+  else
-+#endif
-+  {
-+    cpu_time_usecs= 0;
-+  }
- }
- 
- 
-@@ -366,7 +380,8 @@
-     finish_current_query();
-   }
- 
--  enabled= ((thd->variables.option_bits & OPTION_PROFILING) != 0);
-+  enabled= ((thd->variables.option_bits & OPTION_PROFILING) != 0) ||
-+            ((thd->variables.log_slow_verbosity & (ULL(1) << SLOG_V_PROFILING)) != 0);
- 
-   if (! enabled) DBUG_VOID_RETURN;
- 
-@@ -404,7 +419,8 @@
-     status_change("ending", NULL, NULL, 0);
- 
-     if ((enabled) &&                                    /* ON at start? */
--        ((thd->variables.option_bits & OPTION_PROFILING) != 0) &&   /* and ON at end? */
-+        (((thd->variables.option_bits & OPTION_PROFILING) != 0) ||
-+          ((thd->variables.log_slow_verbosity & (ULL(1) << SLOG_V_PROFILING)) != 0)) &&   /* and ON at end? */
-         (current->query_source != NULL) &&
-         (! current->entries.is_empty()))
-     {
-@@ -505,6 +521,118 @@
-   DBUG_VOID_RETURN;
- }
- 
-+bool PROFILING::enabled_getrusage()
-+{
-+  return ((thd->variables.log_slow_verbosity & (ULL(1) << SLOG_V_PROFILING_USE_GETRUSAGE)) != 0);
-+}
-+
-+/**
-+   For a given profile entry specified by a name and 2 time measurements,
-+   print its normalized name (i.e. with all spaces replaced with underscores)
-+   along with its wall clock and CPU time.
-+*/
-+
-+static void my_b_print_status(IO_CACHE *log_file, const char *status,
-+                              PROF_MEASUREMENT *start, PROF_MEASUREMENT *stop)
-+{
-+  DBUG_ENTER("my_b_print_status");
-+  DBUG_ASSERT(log_file != NULL && status != NULL);
-+  char query_time_buff[22+7];
-+  const char *tmp;
-+
-+  my_b_printf(log_file, "Profile_");
-+  for (tmp= status; *tmp; tmp++)
-+    my_b_write_byte(log_file, *tmp == ' ' ? '_' : *tmp);
-+
-+  snprintf(query_time_buff, sizeof(query_time_buff), "%.6f",
-+           (stop->time_usecs - start->time_usecs) / (1000.0 * 1000));
-+  my_b_printf(log_file, ": %s ", query_time_buff);
-+
-+  my_b_printf(log_file, "Profile_");
-+  for (tmp= status; *tmp; tmp++)
-+    my_b_write_byte(log_file, *tmp == ' ' ? '_' : *tmp);
-+  my_b_printf(log_file, "_cpu: ");
-+
-+  snprintf(query_time_buff, sizeof(query_time_buff), "%.6f",
-+           (stop->cpu_time_usecs - start->cpu_time_usecs) /
-+           (1000.0 * 1000 * 1000));
-+  my_b_printf(log_file, "%s ", query_time_buff);
-+
-+  DBUG_VOID_RETURN;
-+}
-+
-+/**
-+  Print output for current query to file 
-+*/
-+
-+int PROFILING::print_current(IO_CACHE *log_file)
-+{
-+  DBUG_ENTER("PROFILING::print_current");
-+  ulonglong row_number= 0;
-+
-+  QUERY_PROFILE *query;
-+  /* Get current query */
-+  if (current == NULL)
-+  {
-+    DBUG_RETURN(0);
-+  }
-+
-+  query= current;
-+
-+  my_b_printf(log_file, "# ");
-+
-+    void *entry_iterator;
-+    PROF_MEASUREMENT *entry= NULL, *previous= NULL, *first= NULL;
-+    /* ...and for each query, go through all its state-change steps. */
-+    for (entry_iterator= query->entries.new_iterator();
-+         entry_iterator != NULL;
-+         entry_iterator= query->entries.iterator_next(entry_iterator),
-+         previous=entry, row_number++)
-+    {
-+      entry= query->entries.iterator_value(entry_iterator);
-+
-+      /* Skip the first.  We count spans of fence, not fence-posts. */
-+      if (previous == NULL) {first= entry; continue;}
-+
-+      if (thd->lex->sql_command == SQLCOM_SHOW_PROFILE)
-+      {
-+        /*
-+          We got here via a SHOW command.  That means that we stored
-+          information about the query we wish to show and that isn't
-+          in a WHERE clause at a higher level to filter out rows we
-+          wish to exclude.
-+
-+          Because that functionality isn't available in the server yet,
-+          we must filter here, at the wrong level.  Once one can con-
-+          struct where and having conditions at the SQL layer, then this
-+          condition should be ripped out.
-+        */
-+        if (thd->lex->profile_query_id == 0) /* 0 == show final query */
-+        {
-+          if (query != last)
-+            continue;
-+        }
-+        else
-+        {
-+          if (thd->lex->profile_query_id != query->profiling_query_id)
-+            continue;
-+        }
-+      }
-+
-+      my_b_print_status(log_file, previous->status, previous, entry);
-+    }
-+
-+    my_b_write_byte(log_file, '\n');
-+    if ((entry != NULL) && (first != NULL))
-+    {
-+      my_b_printf(log_file, "# ");
-+      my_b_print_status(log_file, "total", first, entry);
-+      my_b_write_byte(log_file, '\n');
-+    }
-+
-+  DBUG_RETURN(0);
-+}
-+
- /**
-   Fill the information schema table, "query_profile", as defined in show.cc .
-   There are two ways to get to this function:  Selecting from the information
-@@ -600,6 +728,8 @@
- 
- #ifdef HAVE_GETRUSAGE
- 
-+      if (enabled_getrusage())
-+      {
-       my_decimal cpu_utime_decimal, cpu_stime_decimal;
- 
-       double2my_decimal(E_DEC_FATAL_ERROR,
-@@ -687,6 +817,7 @@
-       table->field[14]->store((uint32)(entry->rusage.ru_nswap -
-                              previous->rusage.ru_nswap), true);
-       table->field[14]->set_notnull();
-+      }
- #else
-       /* TODO: Add swap info for non-BSD systems */
- #endif
---- a/sql/sql_profile.h
-+++ b/sql/sql_profile.h
-@@ -164,11 +164,15 @@
- */
- class PROF_MEASUREMENT
- {
--private:
--  friend class QUERY_PROFILE;
--  friend class PROFILING;
--
-   QUERY_PROFILE *profile;
-+
-+  char *allocated_status_memory;
-+
-+  void set_label(const char *status_arg, const char *function_arg, 
-+                  const char *file_arg, unsigned int line_arg);
-+  void clean_up();
-+
-+public:
-   char *status;
- #ifdef HAVE_GETRUSAGE
-   struct rusage rusage;
-@@ -181,12 +185,7 @@
-   unsigned int line;
- 
-   double time_usecs;
--  char *allocated_status_memory;
--
--  void set_label(const char *status_arg, const char *function_arg, 
--                  const char *file_arg, unsigned int line_arg);
--  void clean_up();
--  
-+  double cpu_time_usecs;
-   PROF_MEASUREMENT();
-   PROF_MEASUREMENT(QUERY_PROFILE *profile_arg, const char *status_arg);
-   PROF_MEASUREMENT(QUERY_PROFILE *profile_arg, const char *status_arg,
-@@ -231,6 +230,11 @@
- 
-   /* Show this profile.  This is called by PROFILING. */
-   bool show(uint options);
-+
-+public:
-+
-+  inline PROFILING * get_profiling() { return profiling; };
-+
- };
- 
- 
-@@ -276,9 +280,11 @@
- 
-   /* SHOW PROFILES */
-   bool show_profiles();
-+  bool enabled_getrusage();
- 
-   /* ... from INFORMATION_SCHEMA.PROFILING ... */
-   int fill_statistics_info(THD *thd, TABLE_LIST *tables, Item *cond);
-+  int print_current(IO_CACHE *log_file);
- };
- 
- #  endif /* HAVE_PROFILING */
---- /dev/null
-+++ b/mysql-test/include/log_grep.inc
-@@ -0,0 +1,17 @@
-+--disable_query_log
-+--echo [log_grep.inc] file: $log_file pattern: $grep_pattern
-+perl;
-+  $log_file=           $ENV{'log_file'};
-+  $log_file_full_path= $ENV{'log_file_full_path'};
-+  $grep_pattern=       $ENV{'grep_pattern'};
-+
-+  open(FILE, "$log_file_full_path") 
-+    or die("Cannot open file $log_file_full_path: $!\n");
-+
-+  $lines = 0;
-+  while(<FILE>) {
-+    $lines++ if (/$grep_pattern/);
-+  }
-+  close(FILE);
-+  print "[log_grep.inc] lines:   $lines\n";
-+EOF
---- /dev/null
-+++ b/mysql-test/include/log_start.inc
-@@ -0,0 +1,16 @@
-+--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
-\ No newline at end of file
---- /dev/null
-+++ b/mysql-test/include/log_stop.inc
-@@ -0,0 +1,7 @@
-+--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
---- /dev/null
-+++ b/mysql-test/r/percona_bug643149.result
-@@ -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  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;
---- /dev/null
-+++ b/mysql-test/r/percona_log_slow_filter-cl.result
-@@ -0,0 +1,6 @@
-+SHOW VARIABLES LIKE 'log_slow_filter';
-+Variable_name	Value
-+log_slow_filter	full_join
-+SHOW GLOBAL VARIABLES LIKE 'log_slow_filter';
-+Variable_name	Value
-+log_slow_filter	full_join
---- /dev/null
-+++ b/mysql-test/r/percona_log_slow_filter.result
-@@ -0,0 +1,15 @@
-+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
---- /dev/null
-+++ b/mysql-test/r/percona_log_slow_slave_statements-cl.result
-@@ -0,0 +1,6 @@
-+SHOW VARIABLES LIKE 'log_slow_slave_statements';
-+Variable_name	Value
-+log_slow_slave_statements	ON
-+SHOW GLOBAL VARIABLES LIKE 'log_slow_slave_statements';
-+Variable_name	Value
-+log_slow_slave_statements	ON
---- /dev/null
-+++ b/mysql-test/r/percona_log_slow_slave_statements-innodb.result
-@@ -0,0 +1,18 @@
-+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
-+include/rpl_end.inc
---- /dev/null
-+++ b/mysql-test/r/percona_log_slow_slave_statements.result
-@@ -0,0 +1,44 @@
-+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
-+include/rpl_end.inc
---- /dev/null
-+++ b/mysql-test/r/percona_log_slow_sp_statements-cl.result
-@@ -0,0 +1,6 @@
-+SHOW VARIABLES LIKE 'log_slow_sp_statements';
-+Variable_name	Value
-+log_slow_sp_statements	ON
-+SHOW GLOBAL VARIABLES LIKE 'log_slow_sp_statements';
-+Variable_name	Value
-+log_slow_sp_statements	ON
---- /dev/null
-+++ b/mysql-test/r/percona_log_slow_sp_statements.result
-@@ -0,0 +1,24 @@
-+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
---- /dev/null
-+++ b/mysql-test/r/percona_log_slow_verbosity-cl.result
-@@ -0,0 +1,6 @@
-+SHOW VARIABLES LIKE 'log_slow_verbosity';
-+Variable_name	Value
-+log_slow_verbosity	microtime,query_plan,innodb
-+SHOW GLOBAL VARIABLES LIKE 'log_slow_verbosity';
-+Variable_name	Value
-+log_slow_verbosity	microtime,query_plan,innodb
---- /dev/null
-+++ b/mysql-test/r/percona_log_slow_verbosity.result
-@@ -0,0 +1,16 @@
-+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
---- /dev/null
-+++ b/mysql-test/r/percona_long_query_time.result
-@@ -0,0 +1,33 @@
-+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
---- /dev/null
-+++ b/mysql-test/r/percona_slow_query_log_timestamp_always-cl.result
-@@ -0,0 +1,6 @@
-+SHOW VARIABLES LIKE 'slow_query_log_timestamp_always';
-+Variable_name	Value
-+slow_query_log_timestamp_always	ON
-+SHOW GLOBAL VARIABLES LIKE 'slow_query_log_timestamp_always';
-+Variable_name	Value
-+slow_query_log_timestamp_always	ON
---- /dev/null
-+++ b/mysql-test/r/percona_slow_query_log_timestamp_always.result
-@@ -0,0 +1,41 @@
-+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
---- /dev/null
-+++ b/mysql-test/r/percona_slow_query_log_timestamp_precision-cl.result
-@@ -0,0 +1,6 @@
-+SHOW VARIABLES LIKE 'slow_query_log_timestamp_precision';
-+Variable_name	Value
-+slow_query_log_timestamp_precision	microsecond
-+SHOW GLOBAL VARIABLES LIKE 'slow_query_log_timestamp_precision';
-+Variable_name	Value
-+slow_query_log_timestamp_precision	microsecond
---- /dev/null
-+++ b/mysql-test/r/percona_slow_query_log_timestamp_precision.result
-@@ -0,0 +1,18 @@
-+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
---- /dev/null
-+++ b/mysql-test/r/percona_slow_query_log_use_global_control.result
-@@ -0,0 +1,18 @@
-+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
---- /dev/null
-+++ b/mysql-test/t/percona_bug643149.test
-@@ -0,0 +1,49 @@
-+#
-+# This test suffers from server
-+# Bug#38124 "general_log_file" variable silently unset when using expression
-+# In short:
-+#    SET GLOBAL general_log_file = @<whatever>
-+#    SET GLOBAL slow_query_log = @<whatever>
-+# cause that the value of these server system variables is set to default
-+# instead of the assigned values. There comes no error message or warning.
-+# If this bug is fixed please
-+# 1. try this test with "let $fixed_bug38124 = 0;"
-+# 2. remove all workarounds if 1. was successful.
-+--source include/have_profiling.inc
-+let $fixed_bug38124 = 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;
-+
-+let slogfile=$MYSQLTEST_VARDIR/percona_bug643149_slow.log;
-+--replace_result $MYSQLTEST_VARDIR MYSQLTEST_VARDIR
-+--eval SET GLOBAL slow_query_log_file='$slogfile';
-+
-+SELECT 1;
-+
-+perl;
-+  $slogfile= $ENV{'slogfile'};
-+
-+  open(FILE, "$slogfile") or
-+    die("Unable to read slow query log file $slogfile: $!\n");
-+  while(<FILE>) {
-+    next if (!/^#/);
-+    next if (/^# Time:/);
-+    s/[0-9]+/X/g;
-+    print;
-+  }
-+
-+  close(FILE);
-+EOF
-+
-+SET GLOBAL slow_query_log_file=@old_slow_query_log_file;
-+
-+if(!$fixed_bug38124)
-+{
-+  --disable_query_log
-+  let $my_var = `SELECT @old_slow_query_log_file`;
-+  eval SET @@global.slow_query_log_file = '$my_var';
-+  --enable_query_log
-+}
---- /dev/null
-+++ b/mysql-test/t/percona_log_slow_filter-cl-master.opt
-@@ -0,0 +1 @@
-+--log_slow_filter=full_join
---- /dev/null
-+++ b/mysql-test/t/percona_log_slow_filter-cl.test
-@@ -0,0 +1,2 @@
-+SHOW VARIABLES LIKE 'log_slow_filter';
-+SHOW GLOBAL VARIABLES LIKE 'log_slow_filter';
---- /dev/null
-+++ b/mysql-test/t/percona_log_slow_filter.test
-@@ -0,0 +1,26 @@
-+--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;
---- /dev/null
-+++ b/mysql-test/t/percona_log_slow_slave_statements-cl-master.opt
-@@ -0,0 +1 @@
-+--log_slow_slave_statements
-\ No newline at end of file
---- /dev/null
-+++ b/mysql-test/t/percona_log_slow_slave_statements-cl.test
-@@ -0,0 +1,3 @@
-+SHOW VARIABLES LIKE 'log_slow_slave_statements';
-+SHOW GLOBAL VARIABLES LIKE 'log_slow_slave_statements';
-+
---- /dev/null
-+++ b/mysql-test/t/percona_log_slow_slave_statements-innodb-slave.opt
-@@ -0,0 +1 @@
-+--long_query_time=0 --log_slow_slave_statements --log_slow_verbosity=innodb
-\ No newline at end of file
---- /dev/null
-+++ b/mysql-test/t/percona_log_slow_slave_statements-innodb.test
-@@ -0,0 +1,42 @@
-+--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
---- /dev/null
-+++ b/mysql-test/t/percona_log_slow_slave_statements-slave.opt
-@@ -0,0 +1 @@
-+--long_query_time=0
-\ No newline at end of file
---- /dev/null
-+++ b/mysql-test/t/percona_log_slow_slave_statements.test
-@@ -0,0 +1,117 @@
-+-- 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;