Merge lp:~tsarev/percona-server/5.5_fix_bug_688646 into lp:percona-server/5.5

[Oleg Tsarev]

http://jenkins.percona.com/view/Percona%20Server%205.5/job/percona-server-5.5-param/231/

Added implementation of #688646 (Made possible query sampling by query), tests and documentation for it.

[Laurynas Biveinis (laurynas-biveinis)]

The commit message does not have a detailed change description.

The MP seems to contain unrelated changes to clean up better after the slow query log tests, please split into a separate MP (with a bug #).

Why does log_grep.inc become aware of this feature?

Please rewrite if (CONDITION) foo= TRUE; else foo= FALSE; to foo= CONDITION;

The documentation and option description for help need a rewrite for clarity IMHO.

s/debussing/debugging

review: Needs Fixing

=== modified file 'doc/source/diagnostics/slow_extended_55.rst'
--- doc/source/diagnostics/slow_extended_55.rst	2011-10-07 23:38:41 +0000
+++ doc/source/diagnostics/slow_extended_55.rst	2012-01-29 07:52:23 +0000
@@ -67,6 +67,18 @@
 
 For example, to log only queries that perform a full table scan, set the value to ``full_scan``. To log only queries that use on-disk temporary storage for intermediate results, set the value to ``tmp_table_on_disk,filesort_on_disk``.
 
+.. variable:: log_slow_rate_type
+
+     :cli: Yes
+     :conf: Yes
+     :scope: Global
+     :dyn: Yes
+     :vartype: Enumerated
+     :default: ``session``
+     :range: ``session``, ``query``
+
+Specifies semantic of :variable:`log_slow_rate_limit` - ``session`` or ``query``.
+
 .. variable:: log_slow_rate_limit
 
      :cli: Yes
@@ -74,10 +86,26 @@
      :scope: Global, session
      :dyn: Yes
 
-Specifies that only a fraction of sessions should be logged. Logging is enabled for every nth session. By default, n is 1, so logging is enabled for every session. Rate limiting is disabled for the replication thread.
-
-Logging all queries might consume I/O bandwidth and cause the log file to grow large. This option lets you log full sessions, so you have complete records of sessions for later analysis; but you can rate-limit the number of sessions that are logged. For example, if you set the value to 100, then one percent of sessions will be logged in their entirety. Note that this feature will not work well if your application uses any type of connection pooling or persistent connections.
-
+Behavior of this variable depends from :variable:`log_slow_rate_type`.
+
+Specifies that only a fraction of ``session/query`` should be logged. Logging is enabled for every nth ``session/query``. By default, n is 1, so logging is enabled for every ``session/query``. Please note: when :variable:`log_slow_rate_type` is ``session`` rate limiting is disabled for the replication thread.
+
+Logging all queries might consume I/O bandwidth and cause the log file to grow large.
+ * When :variable:`log_slow_rate_type` is ``session``, this option lets you log full sessions, so you have complete records of sessions for later analysis; but you can rate-limit the number of sessions that are logged. Note that this feature will not work well if your application uses any type of connection pooling or persistent connections.
+ Note that you change :variable:`log_slow_rate_limit` in ``session`` mode, you should reconnect for get effect.
+
+ * When :variable:`log_slow_rate_type` is ``query``, this option lets you log just some queries for later analysis. For example, if you set the value to 100, then one percona of queryies will logged.
+
+Note that every query has global unique ``query_id`` and every connection can has it own (session) :variable:``log_slow_rate_limit`.
+Decision "log or no" calculated in following manner:
+
+ * if ``log_slow_rate_limit`` is 0 - log every query
+
+ * If ``log_slow_rate_limit`` > 0 - log query when (``query_id`` % ``log_slow_rate_limit``) is zero.
+
+This allows flexible setup logging behavior.
+
+For example, if you set the value to 100, then one percent of ``sessions/queries`` will be logged.
 
 .. variable:: log_slow_slave_statements
 

=== modified file 'patches/mysql-test.diff'
--- patches/mysql-test.diff	2012-01-10 11:28:15 +0000
+++ patches/mysql-test.diff	2012-01-29 07:52:23 +0000
@@ -749,12 +749,6 @@
 +@@global.log_slow_filter
 +
 --- /dev/null
-+++ b/mysql-test/suite/sys_vars/r/log_slow_rate_limit_basic.result
-@@ -0,0 +1,3 @@
-+SELECT @@global.log_slow_rate_limit;
-+@@global.log_slow_rate_limit
-+1
---- /dev/null
 +++ b/mysql-test/suite/sys_vars/r/log_slow_slave_statements_basic.result
 @@ -0,0 +1,3 @@
 +SELECT @@global.log_slow_slave_statements;
@@ -943,10 +937,6 @@
 @@ -0,0 +1 @@
 +SELECT @@global.log_slow_filter;
 --- /dev/null
-+++ b/mysql-test/suite/sys_vars/t/log_slow_rate_limit_basic.test
-@@ -0,0 +1 @@
-+SELECT @@global.log_slow_rate_limit;
---- /dev/null
 +++ b/mysql-test/suite/sys_vars/t/log_slow_slave_statements_basic.test
 @@ -0,0 +1 @@
 +SELECT @@global.log_slow_slave_statements;
@@ -1050,7 +1040,7 @@
 +SELECT Variable_name FROM INFORMATION_SCHEMA.SESSION_VARIABLES ORDER BY 1;
 --- /dev/null
 +++ b/mysql-test/r/percona_server_variables_debug.result
-@@ -0,0 +1,382 @@
+@@ -0,0 +1,384 @@
 +SELECT Variable_name FROM INFORMATION_SCHEMA.SESSION_VARIABLES ORDER BY 1;
 +Variable_name
 +AUTOCOMMIT
@@ -1252,6 +1242,7 @@
 +LOG_SLOW_FILTER
 +LOG_SLOW_QUERIES
 +LOG_SLOW_RATE_LIMIT
++LOG_SLOW_RATE_TYPE
 +LOG_SLOW_SLAVE_STATEMENTS
 +LOG_SLOW_SP_STATEMENTS
 +LOG_SLOW_VERBOSITY
@@ -1338,6 +1329,7 @@
 +QUERY_CACHE_STRIP_COMMENTS
 +QUERY_CACHE_TYPE
 +QUERY_CACHE_WLOCK_INVALIDATE
++QUERY_EXEC_ID
 +QUERY_EXEC_TIME
 +QUERY_PREALLOC_SIZE
 +QUERY_RESPONSE_TIME_RANGE_BASE
@@ -1435,7 +1427,7 @@
 +WARNING_COUNT
 --- /dev/null
 +++ b/mysql-test/r/percona_server_variables_release.result
-@@ -0,0 +1,377 @@
+@@ -0,0 +1,378 @@
 +SELECT Variable_name FROM INFORMATION_SCHEMA.SESSION_VARIABLES ORDER BY 1;
 +Variable_name
 +AUTOCOMMIT
@@ -1633,6 +1625,7 @@
 +LOG_SLOW_FILTER
 +LOG_SLOW_QUERIES
 +LOG_SLOW_RATE_LIMIT
++LOG_SLOW_RATE_TYPE
 +LOG_SLOW_SLAVE_STATEMENTS
 +LOG_SLOW_SP_STATEMENTS
 +LOG_SLOW_VERBOSITY

=== modified file 'patches/slow_extended.patch'
--- patches/slow_extended.patch	2011-12-27 15:32:16 +0000
+++ patches/slow_extended.patch	2012-01-29 07:52:23 +0000
@@ -411,7 +411,7 @@
                          ulonglong lock_utime, bool is_command,
 --- a/sql/mysqld.cc
 +++ b/sql/mysqld.cc
-@@ -421,6 +421,10 @@
+@@ -421,6 +421,11 @@
  char* opt_secure_file_priv;
  my_bool opt_log_slow_admin_statements= 0;
  my_bool opt_log_slow_slave_statements= 0;
@@ -419,10 +419,11 @@
 +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;
++ulong opt_slow_query_log_rate_type= 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 @@
+@@ -5892,14 +5897,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},
@@ -439,7 +440,7 @@
    {"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 @@
+@@ -7288,6 +7289,10 @@
  
  C_MODE_END
  
@@ -450,7 +451,7 @@
  /**
    Get server options from the command line,
    and perform related server initializations.
-@@ -7437,6 +7441,8 @@
+@@ -7437,6 +7442,8 @@
    global_system_variables.long_query_time= (ulonglong)
      (global_system_variables.long_query_time_double * 1e6);
  
@@ -461,7 +462,7 @@
  
 --- a/sql/mysqld.h
 +++ b/sql/mysqld.h
-@@ -116,6 +116,10 @@
+@@ -116,6 +116,11 @@
  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;
@@ -469,6 +470,7 @@
 +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 ulong opt_slow_query_log_rate_type;
  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;
@@ -681,9 +683,52 @@
    DBUG_VOID_RETURN;
  }
  
+@@ -3802,7 +3896,7 @@
+ {
+   mysql_mutex_lock(&LOCK_thd_data);
+   set_query_inner(query_arg, query_length_arg, cs);
+-  query_id= new_query_id;
++  do_set_query_id(new_query_id);
+   mysql_mutex_unlock(&LOCK_thd_data);
+ }
+ 
+@@ -3811,9 +3905,32 @@
+ void THD::set_query_id(query_id_t new_query_id)
+ {
+   mysql_mutex_lock(&LOCK_thd_data);
+-  query_id= new_query_id;
++  do_set_query_id(new_query_id);
+   mysql_mutex_unlock(&LOCK_thd_data);
+ }
++void THD::do_set_query_id(query_id_t new_query_id)
++{
++#ifndef DBUG_OFF
++  if (variables.query_exec_id != 0 &&
++      lex->sql_command != SQLCOM_SET_OPTION)
++  {
++    new_query_id= variables.query_exec_id;
++  }
++#endif /* DBUG_OFF */
++  query_id= new_query_id;
++  if (opt_slow_query_log_rate_type == SLOG_RT_QUERY)
++  {
++    if ((variables.log_slow_rate_limit == 0) ||
++        (query_id % variables.log_slow_rate_limit) == 0)
++    {
++      write_to_slow_log= TRUE;
++    }
++    else
++    {
++      write_to_slow_log= FALSE;
++    }
++  }
++}
+ 
+ /** Assign a new value to thd->mysys_var.  */
+ void THD::set_mysys_var(struct st_my_thread_var *new_mysys_var)
 --- a/sql/sql_class.h
 +++ b/sql/sql_class.h
-@@ -60,6 +60,33 @@
+@@ -60,6 +60,36 @@
  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 };
@@ -700,6 +745,9 @@
 +enum enum_slow_query_log_timestamp_precision {
 +  SLOG_SECOND, SLOG_MICROSECOND
 +};
++enum enum_slow_query_log_rate_type {
++  SLOG_RT_SESSION, SLOG_RT_QUERY
++};
 +#define QPLAN_NONE            0
 +#define QPLAN_QC              1 << 0
 +#define QPLAN_QC_NO           1 << 1
@@ -717,13 +765,14 @@
  enum enum_slave_exec_mode { SLAVE_EXEC_MODE_STRICT,
                              SLAVE_EXEC_MODE_IDEMPOTENT,
                              SLAVE_EXEC_MODE_LAST_BIT};
-@@ -506,6 +533,21 @@
+@@ -508,6 +538,22 @@
  
    my_bool sysdate_is_now;
  
 +#ifndef DBUG_OFF
 +  ulonglong query_exec_time;
 +  double    query_exec_time_double;
++  ulong     query_exec_id;
 +#endif
 +  ulong log_slow_rate_limit;
 +  ulonglong log_slow_filter;
@@ -739,7 +788,7 @@
    double long_query_time_double;
  
  } SV;
-@@ -1138,6 +1180,24 @@
+@@ -1140,6 +1186,24 @@
    uint in_sub_stmt;
    bool enable_slow_log;
    bool last_insert_id_used;
@@ -764,7 +813,7 @@
    SAVEPOINT *savepoints;
    enum enum_check_fields count_cuted_fields;
  };
-@@ -1586,6 +1646,71 @@
+@@ -1588,6 +1652,71 @@
    thr_lock_type update_lock_default;
    Delayed_insert *di;
  
@@ -836,20 +885,36 @@
    /* <> 0 if we are inside of trigger or stored function. */
    uint in_sub_stmt;
  
+@@ -2784,6 +2913,9 @@
+   void set_query_and_id(char *query_arg, uint32 query_length_arg,
+                         CHARSET_INFO *cs, query_id_t new_query_id);
+   void set_query_id(query_id_t new_query_id);
++private:
++  void do_set_query_id(query_id_t new_query_id);
++public:
+   void set_open_tables(TABLE *open_tables_arg)
+   {
+     mysql_mutex_lock(&LOCK_thd_data);
 --- a/sql/sql_connect.cc
 +++ b/sql/sql_connect.cc
-@@ -721,6 +721,15 @@
+@@ -721,6 +721,21 @@
    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; 
++      new thread's queries or not. Uses extremely simple algorithm. :)
++    */
++    if (opt_slow_query_log_rate_type == SLOG_RT_SESSION &&
++        (thd->variables.log_slow_rate_limit == 0 ||
++         (thd->thread_id % thd->variables.log_slow_rate_limit) == 0))
++    {
++      thd->write_to_slow_log= TRUE;
++    }
++    else
++    {
++      thd->write_to_slow_log= FALSE;
++    }
 +
    prepare_new_connection_state(thd);
    return FALSE;
@@ -1072,7 +1137,7 @@
        {
 --- a/sql/sys_vars.cc
 +++ b/sql/sys_vars.cc
-@@ -972,6 +972,29 @@
+@@ -972,6 +972,36 @@
         NO_MUTEX_GUARD, NOT_IN_BINLOG, ON_CHECK(0),
         ON_UPDATE(update_cached_long_query_time));
  
@@ -1097,12 +1162,19 @@
 +       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));
++static Sys_var_ulong sys_query_exec_id(
++       "query_exec_id",
++       "Pretend queries take this query id. When 0 (the default) use the"
++       "actual query id. Used only for debugging.",
++       SESSION_VAR(query_exec_id),
++       NO_CMD_LINE, VALID_RANGE(0, ULONG_MAX), DEFAULT(0), BLOCK_SIZE(1),
++       NO_MUTEX_GUARD, IN_BINLOG);
 +#endif
 +
  static bool fix_low_prio_updates(sys_var *self, THD *thd, enum_var_type type)
  {
    if (type == OPT_SESSION)
-@@ -2904,6 +2927,123 @@
+@@ -2898,6 +2928,134 @@
         DEFAULT(FALSE), NO_MUTEX_GUARD, NOT_IN_BINLOG, ON_CHECK(0),
         ON_UPDATE(fix_log_state));
  
@@ -1222,7 +1294,18 @@
 +       "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));
-+ 
++
++const char* slow_query_log_rate_name[]= {"session", "query", 0};
++static Sys_var_enum Sys_slow_query_log_rate_type(
++       "log_slow_rate_type",
++       "Choose the log_slow_rate_limit behavior: session or query. "
++       "When you choose 'session' - every %log_slow_rate_limit connection "
++       "will be processed to slow query log. "
++       "When you choose 'query' - every %log_slow_rate_limit query "
++       "will be processed to slow query log. "
++       "[session, query]",
++       GLOBAL_VAR(opt_slow_query_log_rate_type), CMD_LINE(REQUIRED_ARG),
++       slow_query_log_rate_name, DEFAULT(SLOG_RT_SESSION));
  /* Synonym of "slow_query_log" for consistency with SHOW VARIABLES output */
  static Sys_var_mybool Sys_log_slow(
         "log_slow_queries",
@@ -1476,23 +1559,47 @@
  #  endif /* HAVE_PROFILING */
 --- /dev/null
 +++ b/mysql-test/include/log_grep.inc
-@@ -0,0 +1,17 @@
-+--disable_query_log
+@@ -0,0 +1,41 @@
 +--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'};
-+
++  $log_slow_rate_test= $ENV{'log_slow_rate_test'};
 +  open(FILE, "$log_file_full_path") 
 +    or die("Cannot open file $log_file_full_path: $!\n");
 +
-+  $lines = 0;
-+  while(<FILE>) {
-+    $lines++ if (/$grep_pattern/);
++  if ($log_slow_rate_test) {
++    $one= 0;
++    $two= 0;
++    $three= 0;
++    while(<FILE>) {
++      $one++   if(/'connection_one'/);
++      $two++   if(/'connection_two'/);
++      $three++ if(/'connection_three'/);
++    }
++    $sum= $one + $two + $three;
++    $zero= 0;
++    if ($one == 0) {
++      $zero++;
++    }
++    if ($two == 0) {
++      $zero++;
++    }
++    if ($three == 0) {
++      $zero++;
++    }
++    print "[log_grep.inc] sum:  $sum\n";
++    print "[log_grep.inc] zero: $zero\n";
++  }
++  else {
++    $grep_pattern=       $ENV{'grep_pattern'};
++    $lines= 0;
++    while(<FILE>) {
++      $lines++ if (/$grep_pattern/);
++    }
++    print "[log_grep.inc] lines:   $lines\n";
 +  }
 +  close(FILE);
-+  print "[log_grep.inc] lines:   $lines\n";
 +EOF
 --- /dev/null
 +++ b/mysql-test/include/log_start.inc
@@ -1513,7 +1620,6 @@
 +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 @@
@@ -1559,7 +1665,7 @@
 +log_slow_filter	full_join
 --- /dev/null
 +++ b/mysql-test/r/percona_log_slow_filter.result
-@@ -0,0 +1,15 @@
+@@ -0,0 +1,16 @@
 +CREATE TABLE t(id INT PRIMARY KEY);
 +INSERT INTO t VALUES(1);
 +INSERT INTO t VALUES(2);
@@ -1575,6 +1681,7 @@
 +SET long_query_time=default;
 +[log_grep.inc] file: percona.slow_extended.log_slow_filter pattern: Query_time
 +[log_grep.inc] lines:   1
++DROP TABLE t;
 --- /dev/null
 +++ b/mysql-test/r/percona_log_slow_slave_statements-cl.result
 @@ -0,0 +1,6 @@
@@ -1586,7 +1693,7 @@
 +log_slow_slave_statements	ON
 --- /dev/null
 +++ b/mysql-test/r/percona_log_slow_slave_statements-innodb.result
-@@ -0,0 +1,18 @@
+@@ -0,0 +1,19 @@
 +include/master-slave.inc
 +[connection master]
 +DROP TABLE IF EXISTS t;
@@ -1604,10 +1711,11 @@
 +[log_stop.inc] percona.slow_extended.log_slow_slave_statements-innodb
 +[log_grep.inc] file: percona.slow_extended.log_slow_slave_statements-innodb pattern: InnoDB_IO_r_ops
 +[log_grep.inc] lines:   1
++DROP TABLE t;
 +include/rpl_end.inc
 --- /dev/null
 +++ b/mysql-test/r/percona_log_slow_slave_statements.result
-@@ -0,0 +1,44 @@
+@@ -0,0 +1,45 @@
 +include/master-slave.inc
 +[connection master]
 +DROP TABLE IF EXISTS t;
@@ -1651,6 +1759,7 @@
 +[log_grep.inc] lines:   0
 +[log_grep.inc] file: percona.slow_extended.log_slow_slave_statements pattern: INSERT INTO t VALUES \(7\)
 +[log_grep.inc] lines:   1
++DROP TABLE t;
 +include/rpl_end.inc
 --- /dev/null
 +++ b/mysql-test/r/percona_log_slow_sp_statements-cl.result
@@ -1663,7 +1772,7 @@
 +log_slow_sp_statements	ON
 --- /dev/null
 +++ b/mysql-test/r/percona_log_slow_sp_statements.result
-@@ -0,0 +1,24 @@
+@@ -0,0 +1,25 @@
 +SET long_query_time=1;
 +SET GLOBAL log_slow_sp_statements=ON;
 +SET SESSION query_exec_time=0.1;
@@ -1688,6 +1797,7 @@
 +SET long_query_time=default;
 +[log_grep.inc] file: percona.slow_extended.log_slow_sp_statements pattern: Query_time
 +[log_grep.inc] lines:   3
++DROP PROCEDURE test_f;
 --- /dev/null
 +++ b/mysql-test/r/percona_log_slow_verbosity-cl.result
 @@ -0,0 +1,6 @@
@@ -2373,7 +2483,7 @@
 +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 @@
+@@ -0,0 +1,35 @@
 +drop table if exists t;
 +create table t(id INT PRIMARY KEY);
 +insert into t values(1);
@@ -2408,6 +2518,7 @@
 +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
++DROP TABLE t;
 --- /dev/null
 +++ b/mysql-test/t/percona_min_examined_row_limit.test
 @@ -0,0 +1,35 @@
@@ -2516,7 +2627,7 @@
 +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 @@
+@@ -0,0 +1,10 @@
 +SET long_query_time=0;
 +DROP TABLE IF EXISTS t1;
 +CREATE TABLE t(a INT);
@@ -2526,6 +2637,7 @@
 +[log_stop.inc] percona.slow_extended.log_error
 +[log_grep.inc] file: percona.slow_extended.log_error pattern: Last_errno: 1050
 +[log_grep.inc] lines:   1
++DROP TABLE t;
 --- /dev/null
 +++ b/mysql-test/t/percona_slow_extended_log_error.test
 @@ -0,0 +1,15 @@
@@ -2695,7 +2807,7 @@
 +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 @@
+@@ -250,15 +250,38 @@
   --log-slow-admin-statements 
   Log slow OPTIMIZE, ANALYZE, ALTER and other
   administrative statements to the slow log if it is open.
@@ -2713,6 +2825,13 @@
 + --log-slow-rate-limit=# 
 + Rate limit statement writes to slow log to only those
 + from every (1/log_slow_rate_limit) session.
++ --log-slow-rate-type=name 
++ Choose the log_slow_rate_limit behavior: session or
++ query. When you choose 'session' - every
++ %log_slow_rate_limit connection will be processed to slow
++ query log. When you choose 'query' - every
++ %log_slow_rate_limit query will be processed to slow
++ query log. [session, query]
   --log-slow-slave-statements 
 - Log slow statements executed by slave thread to the slow
 - log if it is open.
@@ -2729,7 +2848,7 @@
   --log-tc=name       Path to transaction coordinator log (used for
   transactions that affect more than one storage engine,
   when binary log is disabled).
-@@ -662,6 +678,18 @@
+@@ -660,6 +683,18 @@
   Log slow queries to given log file. Defaults logging to
   hostname-slow.log. Must be enabled to activate other slow
   log options
@@ -2748,19 +2867,20 @@
   --socket=name       Socket file to use for connection
   --sort-buffer-size=# 
   Each thread that needs to do a sort allocates a buffer of
-@@ -819,7 +847,11 @@
+@@ -817,7 +852,12 @@
  log-short-format FALSE
  log-slave-updates FALSE
  log-slow-admin-statements FALSE
 +log-slow-filter 
 +log-slow-rate-limit 1
++log-slow-rate-type session
  log-slow-slave-statements FALSE
 +log-slow-sp-statements TRUE
 +log-slow-verbosity 
  log-tc tc.log
  log-tc-size 24576
  log-warnings 1
-@@ -936,6 +968,9 @@
+@@ -933,6 +973,9 @@
  slave-type-conversions 
  slow-launch-time 2
  slow-query-log FALSE
@@ -2770,3 +2890,180 @@
  sort-buffer-size 2097152
  sporadic-binlog-dump-fail FALSE
  sql-mode 
+--- /dev/null
++++ b/mysql-test/r/percona_slow_query_log_rate.result
+@@ -0,0 +1,78 @@
++SET GLOBAL long_query_time=1;
++SET GLOBAL log_slow_rate_type='session';
++SET GLOBAL log_slow_rate_limit=3;
++[log_start.inc] percona.slow_extended.log_slow_rate_limit
++SET SESSION query_exec_time=1.1;
++SET SESSION query_exec_id=1;
++SELECT 'connection_one';
++connection_one
++connection_one
++SET SESSION query_exec_time=1.1;
++SET SESSION query_exec_id=2;
++SELECT 'connection_two';
++connection_two
++connection_two
++SET SESSION query_exec_time=1.1;
++SET SESSION query_exec_id=3;
++SELECT 'connection_three';
++connection_three
++connection_three
++SET SESSION query_exec_time=1.1;
++SET SESSION query_exec_id=4;
++SELECT 'connection_one';
++connection_one
++connection_one
++SET SESSION query_exec_time=1.1;
++SET SESSION query_exec_id=5;
++SELECT 'connection_two';
++connection_two
++connection_two
++SET SESSION query_exec_time=1.1;
++SET SESSION query_exec_id=6;
++SELECT 'connection_three';
++connection_three
++connection_three
++[log_stop.inc] percona.slow_extended.log_slow_rate_limit
++[log_grep.inc] file: percona.slow_extended.log_slow_rate_limit pattern: 
++[log_grep.inc] sum:  2
++[log_grep.inc] zero: 2
++SET GLOBAL log_slow_rate_type='query';
++SET GLOBAL log_slow_rate_limit=2;
++[log_start.inc] percona.slow_extended.log_slow_rate_limit
++SET SESSION query_exec_time=1.1;
++SET SESSION query_exec_id=1;
++SELECT 'connection_one';
++connection_one
++connection_one
++SET SESSION query_exec_time=1.1;
++SET SESSION query_exec_id=2;
++SELECT 'connection_two';
++connection_two
++connection_two
++SET SESSION query_exec_time=1.1;
++SET SESSION query_exec_id=3;
++SELECT 'connection_three';
++connection_three
++connection_three
++SET SESSION query_exec_time=1.1;
++SET SESSION query_exec_id=4;
++SELECT 'connection_one';
++connection_one
++connection_one
++SET SESSION query_exec_time=1.1;
++SET SESSION query_exec_id=5;
++SELECT 'connection_two';
++connection_two
++connection_two
++SET SESSION query_exec_time=1.1;
++SET SESSION query_exec_id=6;
++SELECT 'connection_three';
++connection_three
++connection_three
++[log_stop.inc] percona.slow_extended.log_slow_rate_limit
++[log_grep.inc] file: percona.slow_extended.log_slow_rate_limit pattern: 
++[log_grep.inc] sum:  3
++[log_grep.inc] zero: 0
++SET GLOBAL long_query_time=default;
++SET GLOBAL log_slow_rate_type=default;
++SET GLOBAL log_slow_rate_limit=default;
+--- /dev/null
++++ b/mysql-test/t/percona_slow_query_log_rate.test
+@@ -0,0 +1,16 @@
++--source include/have_debug.inc
++--let log_file=percona.slow_extended.log_slow_rate_limit
++
++SET GLOBAL long_query_time=1;
++
++SET GLOBAL log_slow_rate_type='session';
++SET GLOBAL log_slow_rate_limit=3;
++--source include/percona_slow_query_log_rate.inc
++
++SET GLOBAL log_slow_rate_type='query';
++SET GLOBAL log_slow_rate_limit=2;
++--source include/percona_slow_query_log_rate.inc
++
++SET GLOBAL long_query_time=default;
++SET GLOBAL log_slow_rate_type=default;
++SET GLOBAL log_slow_rate_limit=default;
+--- /dev/null
++++ b/mysql-test/suite/sys_vars/t/log_slow_rate_limit_basic.test
+@@ -0,0 +1 @@
++SELECT @@global.log_slow_rate_limit;
+--- /dev/null
++++ b/mysql-test/suite/sys_vars/r/log_slow_rate_limit_basic.result
+@@ -0,0 +1,3 @@
++SELECT @@global.log_slow_rate_limit;
++@@global.log_slow_rate_limit
++1
+--- /dev/null
++++ b/mysql-test/suite/sys_vars/t/log_slow_rate_type_basic.test
+@@ -0,0 +1 @@
++SELECT @@global.log_slow_rate_type;
+--- /dev/null
++++ b/mysql-test/suite/sys_vars/r/log_slow_rate_type_basic.result
+@@ -0,0 +1,3 @@
++SELECT @@global.log_slow_rate_type;
++@@global.log_slow_rate_type
++session
+--- /dev/null
++++ b/mysql-test/include/percona_slow_query_log_rate.inc
+@@ -0,0 +1,42 @@
++--let wait_condition=SELECT COUNT(*) = 1 FROM INFORMATION_SCHEMA.PROCESSLIST;
++--connection default
++--source include/log_start.inc
++
++--connect (connection_one,localhost,root,,)
++--connect (connection_two,localhost,root,,)
++--connect (connection_three,localhost,root,,)
++
++--let i=2
++--let k=1
++
++while($i)
++{
++--connection connection_one
++SET SESSION query_exec_time=1.1;
++eval SET SESSION query_exec_id=$k;
++inc $k;
++SELECT 'connection_one';
++
++--connection connection_two
++SET SESSION query_exec_time=1.1;
++eval SET SESSION query_exec_id=$k;
++inc $k;
++SELECT 'connection_two';
++
++--connection connection_three
++SET SESSION query_exec_time=1.1;
++eval SET SESSION query_exec_id=$k;
++inc $k;
++SELECT 'connection_three';
++
++dec $i;
++}
++
++--connection default
++--disconnect connection_one
++--disconnect connection_two
++--disconnect connection_three
++--source include/wait_condition.inc
++--source include/log_stop.inc
++--let log_slow_rate_test=1
++--source include/log_grep.inc
+--- /dev/null
++++ b/mysql-test/suite/sys_vars/r/query_exec_id_basic.result
+@@ -0,0 +1,2 @@
++SET GLOBAL query_exec_id=default;
++SET SESSION query_exec_id=default;
+--- /dev/null
++++ b/mysql-test/suite/sys_vars/t/query_exec_id_basic.test
+@@ -0,0 +1,4 @@
++--source include/have_debug.inc
++
++SET GLOBAL query_exec_id=default;
++SET SESSION query_exec_id=default;