Merge lp:~tsarev/percona-server/5.1_fix_bug_716210 into lp:percona-server/5.1

[Oleg Tsarev]

Clean Jenkins result: http://jenkins.percona.com/view/Percona%20Server%205.1/job/percona-server-5.1-param/170

PLEASE NOTE: This MP fix JUST THE ON PROBLEM - inherit counters by administrative commands from previous queries.
Looks like, Rows_read counters incorrect - related to bug #721176

Test case is CORRECT, and check what now administrative commands work with clean counters.

      * "all statistics variables used in slow_extended.patch and thd->send_row_count and thd->examined_row_count" == SESV (Slow Extended Statistic Variables)

      * Added to class THD (sql/sql_class.h) following methods:
             1) clear_slow_extended - clear SESV
             2) reset_sub_statement_state_slow_extended(Sub_statement_state *backup) - backup SESV to backup area
             3) restore_sub_statement_state_slow_extended(Sub_statement_state *backup) - restore SESV from backup area

      * Added to class Sub_statement_state (sql/sql_class.h) required for correct backup variables

      * Added to class THD (sql/sql_class.h) comments near the SESV with explanations of purpose of variables

      * Added call of clear_slow_extended to THD::init() (required on THD class initialisation and change_user)

      * Fix admin command processing in LOGGER::slow_log_print (sql/loc.cc). Before fix SESV don't clean correctly (because if(!query_length) never was true).
        Explanation:
          1) query and query_length according to comment in sql_class.h always correlated - if query == NULL => query_length == 0, and if query != NULL => query_length != 0
          2) After "if (!query) { ... }" query_lenght always not 0
          3) if (!query_length) (code before my fix) always trye

      * Fixed accoring to code policy code formating in "increment_thd_innodb_stats" (sql/sql_class.cc)

      * Fixed THD::reset_for_next_command (sql/sql_parse.cc) - replace variables cleaning by clear_slow_extended call

      * Fixed bug #716210: add thd->clear_slow_extended() to dispatch_command()
        Explanation: before dispatch_command mysql doesn't call "reset_for_next_command" and SESV inherited from previous query

[Laurynas Biveinis (laurynas-biveinis)]

LGTM with the the first comment below replied to and the rest of the changes. As far as I'm concerned, if the adjusted patch will be different from the current one with the changes below and nothing else, a new MP is not necessary.

- Can the argument of
  THD::restore_sub_statement_state_slow_extended(Sub_statement_state
  *backup) and the method void
  THD::reset_sub_statement_state_slow_extended(Sub_statement_state
  *backup) be constified? Please do so if yes.

- Line 314: s/save/saves

- Line 330: s/innodb_was used show/innodb_was_used shows

- Line 362: s/Belowing/Following, or remove the line
  altogether (line 364 is almost duplicate)

review: Approve

=== modified file 'patches/slow_extended.patch'
--- patches/slow_extended.patch	2011-10-08 04:46:52 +0000
+++ patches/slow_extended.patch	2011-10-11 06:52:37 +0000
@@ -187,30 +187,16 @@
      else
      {
        query_utime= lock_utime= 0;
-@@ -1010,8 +1026,21 @@
-       query_length= command_name[thd->command].length;
+@@ -1011,7 +1027,7 @@
      }
  
-+    if (!query_length)
-+    {
-+      thd->sent_row_count= thd->examined_row_count= 0;
-+      thd->row_count= 0;
-+      thd->orig_row_count= 0;
-+      thd->bytes_sent_old= thd->status_var.bytes_sent;
-+      thd->tmp_tables_used= thd->tmp_tables_disk_used= 0;
-+      thd->tmp_tables_size= 0;
-+      thd->innodb_was_used= FALSE;
-+      thd->query_plan_flags= QPLAN_NONE;
-+      thd->query_plan_fsort_passes= 0;
-+    }
-+
      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;
-@@ -2282,12 +2311,13 @@
+@@ -2282,12 +2298,13 @@
      TRUE - error occured
  */
  
@@ -225,7 +211,7 @@
    bool error= 0;
    DBUG_ENTER("MYSQL_QUERY_LOG::write");
  
-@@ -2309,17 +2339,28 @@
+@@ -2309,17 +2326,28 @@
  
      if (!(specialflag & SPECIAL_SHORT_LOG_FORMAT))
      {
@@ -256,7 +242,7 @@
  
          /* Note that my_b_write() assumes it knows the length for this */
          if (my_b_write(&log_file, (uchar*) buff, buff_len))
-@@ -2337,12 +2378,64 @@
+@@ -2337,12 +2365,64 @@
      sprintf(query_time_buff, "%.6f", ulonglong2double(query_utime)/1000000.0);
      sprintf(lock_time_buff,  "%.6f", ulonglong2double(lock_utime)/1000000.0);
      if (my_b_printf(&log_file,
@@ -277,7 +263,7 @@
 +                    (ulong) thd->tmp_tables_used,
 +                    (ulong) thd->tmp_tables_disk_used,
 +                    (ulong) thd->tmp_tables_size) == (uint) -1)
-+      tmp_errno= errno;
+       tmp_errno= errno;
 +    if (thd->innodb_was_used)
 +    {
 +      char buf[20];
@@ -319,7 +305,7 @@
 +    {
 +      if ((thd->variables.log_slow_verbosity & SLOG_V_INNODB) &&
 +          my_b_printf(&log_file,"# No InnoDB statistics available for this query\n") == (uint) -1)
-       tmp_errno= errno;
++      tmp_errno= errno;
 +    }
      if (thd->db && strcmp(thd->db, db))
      {						// Database changed
@@ -1202,22 +1188,22 @@
  
 +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)
++                                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;
++  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"
@@ -1243,44 +1229,125 @@
    for (Internal_error_handler *error_handler= m_internal_handler;
         error_handler;
         error_handler= error_handler->m_prev_internal_handler)
-@@ -3196,6 +3229,12 @@
+@@ -881,6 +914,8 @@
+   /* Initialize the Debug Sync Facility. See debug_sync.cc. */
+   debug_sync_init_thread(this);
+ #endif /* defined(ENABLED_DEBUG_SYNC) */
++
++  clear_slow_extended();
+ }
+ 
+ 
+@@ -3187,8 +3222,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;
+@@ -3196,6 +3229,7 @@
      first_successful_insert_id_in_prev_stmt;
    backup->first_successful_insert_id_in_cur_stmt= 
      first_successful_insert_id_in_cur_stmt;
-+  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;
++  reset_sub_statement_state_slow_extended(backup);
  
    if ((!lex->requires_prelocking() || is_update_query(lex->sql_command)) &&
        !current_stmt_binlog_row_based)
-@@ -3215,6 +3254,14 @@
+@@ -3210,13 +3244,75 @@
+   /* 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;
-+  last_errno= 0;
-+  innodb_trx_id= 0;
-+  innodb_io_reads= 0;
-+  innodb_io_read= 0;
-+  innodb_io_reads_wait_timer= 0;
-+  innodb_lock_que_wait_timer= 0;
+ }
+ 
++void THD::clear_slow_extended()
++{
++  DBUG_ENTER("THD::clear_slow_extended");
++  sent_row_count=               0;
++  orig_row_count=               row_count;
++  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;
- }
- 
- 
-@@ -3277,6 +3324,12 @@
++  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)
+ {
+@@ -3257,7 +3353,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.
+@@ -3275,8 +3370,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;
+-  examined_row_count+= backup->examined_row_count;
    cuted_fields+=       backup->cuted_fields;
-+  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;
++  restore_sub_statement_state_slow_extended(backup);
    DBUG_VOID_RETURN;
  }
  
@@ -1308,11 +1375,17 @@
  };
  
  
-@@ -1000,6 +1015,14 @@
+@@ -1000,6 +1015,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;
@@ -1320,20 +1393,55 @@
 +  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;
  };
-@@ -1427,6 +1450,26 @@
+@@ -1427,6 +1460,77 @@
    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;
++  /*
++    Original row_count value at the start of query execution
++    (used by the slow_extended patch).
++  */
++  ulong      orig_row_count;
++  /*
++    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;
@@ -1342,26 +1450,34 @@
 +  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;
    /* TRUE when the current top has SQL_LOG_BIN ON */
-@@ -1772,6 +1815,11 @@
-     create_sort_index(); may differ from examined_row_count.
-   */
-   ulong      row_count;
-+  /*
-+    Original row_count value at the start of query execution
-+    (used by the slow_extended patch).
-+  */
-+  ulong      orig_row_count;
-   pthread_t  real_id;                           /* For debugging */
-   my_thread_id  thread_id;
-   uint	     tmp_table, global_read_lock;
 --- a/sql/sql_connect.cc
 +++ b/sql/sql_connect.cc
 @@ -1421,6 +1421,15 @@
@@ -1390,7 +1506,15 @@
  
  const char *any_db="*any*";	// Special symbol for check_access
  
-@@ -1702,6 +1703,50 @@
+@@ -1001,6 +1002,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())
+@@ -1702,6 +1704,50 @@
    DBUG_RETURN(error);
  }
  
@@ -1441,7 +1565,7 @@
  
  void log_slow_statement(THD *thd)
  {
-@@ -1715,17 +1760,51 @@
+@@ -1715,17 +1761,51 @@
    if (unlikely(thd->in_sub_stmt))
      DBUG_VOID_RETURN;                           // Don't set time for sub stmt
  
@@ -1496,38 +1620,16 @@
           ((thd->server_status &
             (SERVER_QUERY_NO_INDEX_USED | SERVER_QUERY_NO_GOOD_INDEX_USED)) &&
            opt_log_queries_not_using_indexes &&
-@@ -2101,6 +2180,9 @@
-     context.resolve_in_table_list_only(select_lex->
-                                        table_list.first);
- 
-+  /* Save the original row_count value for extended stats in slow query log */
-+  thd->orig_row_count= thd->row_count;
-+
-   /*
-     Reset warning count for each query that uses tables
-     A better approach would be to reset this for any commands
-@@ -5829,6 +5911,21 @@
+@@ -5827,7 +5907,8 @@
+   thd->main_da.reset_diagnostics_area();
+   thd->total_warn_count=0;			// Warnings for this query
    thd->rand_used= 0;
-   thd->sent_row_count= thd->examined_row_count= 0;
+-  thd->sent_row_count= thd->examined_row_count= 0;
++
++  thd->clear_slow_extended();
  
-+  thd->bytes_sent_old= thd->status_var.bytes_sent;
-+  thd->tmp_tables_used= thd->tmp_tables_disk_used= 0;
-+  thd->tmp_tables_size= 0;
-+  thd->innodb_was_used= FALSE;
-+  thd->innodb_trx_id= 0;
-+  thd->innodb_io_reads= 0;
-+  thd->innodb_io_read= 0;
-+  thd->innodb_io_reads_wait_timer= 0;
-+  thd->innodb_lock_que_wait_timer= 0;
-+  thd->innodb_innodb_que_wait_timer= 0;
-+  thd->innodb_page_access= 0;
-+  thd->query_plan_flags= QPLAN_NONE;
-+  thd->query_plan_fsort_passes= 0;
-+  thd->last_errno= 0;
-+
    /*
      Because we come here only for start of top-statements, binlog format is
-     constant inside a complex statement (using stored functions) etc.
 --- a/sql/sql_select.cc
 +++ b/sql/sql_select.cc
 @@ -6798,7 +6798,10 @@
@@ -2669,3 +2771,320 @@
 @@ -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_slow_extended_error_on_quit.test
+@@ -0,0 +1,87 @@
++################################################################################
++# Current test check following attributes:                                     #
++# 1) "Last_errno"                                                              #
++# 2) "Rows_{sent,examined|affected|read}                                       #
++# 3) Bytes_sent                                                                #
++# 4) Tmp_{tables|dist_tables|table_size}                                       #
++# 5) InnoDB statistic counters                                                 #
++# in Slow Query Log                                                            #
++# for administrative command "Quit"                                            #
++#                                                                              #
++# See Launchpad Bug #716210                                                    #
++################################################################################
++
++--source include/have_innodb.inc
++
++################################################################################
++--let log_file=percona.slow_extended.error_on_quit
++--let wait_condition=SELECT COUNT(*) = 1 FROM INFORMATION_SCHEMA.PROCESSLIST;
++################################################################################
++
++--disable_warnings
++DROP TABLE IF EXISTS t;
++--enable_warnings
++CREATE TABLE t(a INT) engine=InnoDB;
++INSERT INTO t VALUES(0),(1),(2),(3),(4);
++
++################################################################################
++--source include/log_start.inc
++
++--connect(additional,localhost,root,,)
++--connection additional
++
++  SET log_slow_verbosity=innodb;
++  SET long_query_time= 0;
++
++--disable_result_log
++--error ER_TABLE_EXISTS_ERROR
++  CREATE TABLE t(a INT) engine=InnoDB;
++--enable_result_log
++
++--connection default
++--echo # Disconnecting (passing to Slow Query Log "# administrative command: Quit")
++--disconnect additional
++--source include/wait_condition.inc
++--source include/log_stop.inc
++--source include/percona_slow_extended_error_on_quit.inc
++################################################################################
++--source include/log_start.inc
++
++--connect(additional,localhost,root,,)
++--connection additional
++
++  SET log_slow_verbosity=innodb;
++  SET long_query_time= 0;
++
++--disable_result_log
++  INSERT INTO t SELECT * FROM t ORDER BY RAND();
++--enable_result_log
++
++--connection default
++--echo # Disconnecting (passing to Slow Query Log "# administrative command: Quit")
++--disconnect additional
++--source include/wait_condition.inc
++--source include/log_stop.inc
++--source include/percona_slow_extended_error_on_quit.inc
++################################################################################
++--source include/log_start.inc
++
++--connect(additional,localhost,root,,)
++--connection additional
++
++  SET log_slow_verbosity=innodb;
++  SET long_query_time= 0;
++
++--disable_result_log
++  SELECT * FROM t;
++--enable_result_log
++
++--connection default
++--echo # Disconnecting (passing to Slow Query Log "# administrative command: Quit")
++--disconnect additional
++--source include/wait_condition.inc
++--source include/log_stop.inc
++--source include/percona_slow_extended_error_on_quit.inc
++################################################################################
++
++DROP TABLE t;
+--- /dev/null
++++ b/mysql-test/r/percona_slow_extended_error_on_quit.result
+@@ -0,0 +1,171 @@
++DROP TABLE IF EXISTS t;
++CREATE TABLE t(a INT) engine=InnoDB;
++INSERT INTO t VALUES(0),(1),(2),(3),(4);
++[log_start.inc] percona.slow_extended.error_on_quit
++SET log_slow_verbosity=innodb;
++SET long_query_time= 0;
++CREATE TABLE t(a INT) engine=InnoDB;
++# Disconnecting (passing to Slow Query Log "# administrative command: Quit")
++[log_stop.inc] percona.slow_extended.error_on_quit
++################################################################################
++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: CREATE
++[log_grep.inc] lines:   1
++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: INSERT
++[log_grep.inc] lines:   0
++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: SELECT
++[log_grep.inc] lines:   0
++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Quit
++[log_grep.inc] lines:   1
++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Last_errno: [^0]+
++[log_grep.inc] lines:   1
++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Last_errno: 0
++[log_grep.inc] lines:   2
++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_sent: [^0]+
++[log_grep.inc] lines:   0
++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_sent: 0
++[log_grep.inc] lines:   3
++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_examined: [^0]+
++[log_grep.inc] lines:   0
++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_examined: 0
++[log_grep.inc] lines:   3
++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_affected: [^0]+
++[log_grep.inc] lines:   0
++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_affected: 0
++[log_grep.inc] lines:   3
++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_read: [^0]+
++[log_grep.inc] lines:   3
++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_read: 0
++[log_grep.inc] lines:   0
++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Bytes_sent: [^0]+
++[log_grep.inc] lines:   2
++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Bytes_sent: 0
++[log_grep.inc] lines:   1
++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Tmp_tables: [^0]+
++[log_grep.inc] lines:   0
++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Tmp_tables: 0
++[log_grep.inc] lines:   3
++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Tmp_disk_tables: [^0]+
++[log_grep.inc] lines:   0
++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Tmp_disk_tables: 0
++[log_grep.inc] lines:   3
++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Tmp_table_sizes: [^0]+
++[log_grep.inc] lines:   0
++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Tmp_table_sizes: 0
++[log_grep.inc] lines:   3
++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: # No InnoDB statistics available for this query
++[log_grep.inc] lines:   3
++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: # InnoDB_trx_id: 
++[log_grep.inc] lines:   0
++################################################################################
++[log_start.inc] percona.slow_extended.error_on_quit
++SET log_slow_verbosity=innodb;
++SET long_query_time= 0;
++INSERT INTO t SELECT * FROM t ORDER BY RAND();
++# Disconnecting (passing to Slow Query Log "# administrative command: Quit")
++[log_stop.inc] percona.slow_extended.error_on_quit
++################################################################################
++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: CREATE
++[log_grep.inc] lines:   0
++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: INSERT
++[log_grep.inc] lines:   1
++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: SELECT
++[log_grep.inc] lines:   1
++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Quit
++[log_grep.inc] lines:   1
++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Last_errno: [^0]+
++[log_grep.inc] lines:   0
++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Last_errno: 0
++[log_grep.inc] lines:   3
++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_sent: [^0]+
++[log_grep.inc] lines:   0
++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_sent: 0
++[log_grep.inc] lines:   3
++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_examined: [^0]+
++[log_grep.inc] lines:   1
++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_examined: 0
++[log_grep.inc] lines:   2
++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_affected: [^0]+
++[log_grep.inc] lines:   2
++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_affected: 0
++[log_grep.inc] lines:   1
++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_read: [^0]+
++[log_grep.inc] lines:   3
++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_read: 0
++[log_grep.inc] lines:   0
++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Bytes_sent: [^0]+
++[log_grep.inc] lines:   2
++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Bytes_sent: 0
++[log_grep.inc] lines:   1
++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Tmp_tables: [^0]+
++[log_grep.inc] lines:   1
++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Tmp_tables: 0
++[log_grep.inc] lines:   2
++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Tmp_disk_tables: [^0]+
++[log_grep.inc] lines:   0
++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Tmp_disk_tables: 0
++[log_grep.inc] lines:   3
++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Tmp_table_sizes: [^0]+
++[log_grep.inc] lines:   1
++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Tmp_table_sizes: 0
++[log_grep.inc] lines:   2
++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: # No InnoDB statistics available for this query
++[log_grep.inc] lines:   2
++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: # InnoDB_trx_id: 
++[log_grep.inc] lines:   1
++################################################################################
++[log_start.inc] percona.slow_extended.error_on_quit
++SET log_slow_verbosity=innodb;
++SET long_query_time= 0;
++SELECT * FROM t;
++# Disconnecting (passing to Slow Query Log "# administrative command: Quit")
++[log_stop.inc] percona.slow_extended.error_on_quit
++################################################################################
++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: CREATE
++[log_grep.inc] lines:   0
++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: INSERT
++[log_grep.inc] lines:   0
++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: SELECT
++[log_grep.inc] lines:   1
++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Quit
++[log_grep.inc] lines:   1
++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Last_errno: [^0]+
++[log_grep.inc] lines:   0
++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Last_errno: 0
++[log_grep.inc] lines:   3
++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_sent: [^0]+
++[log_grep.inc] lines:   1
++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_sent: 0
++[log_grep.inc] lines:   2
++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_examined: [^0]+
++[log_grep.inc] lines:   1
++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_examined: 0
++[log_grep.inc] lines:   2
++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_affected: [^0]+
++[log_grep.inc] lines:   0
++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_affected: 0
++[log_grep.inc] lines:   3
++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_read: [^0]+
++[log_grep.inc] lines:   3
++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_read: 0
++[log_grep.inc] lines:   0
++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Bytes_sent: [^0]+
++[log_grep.inc] lines:   2
++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Bytes_sent: 0
++[log_grep.inc] lines:   1
++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Tmp_tables: [^0]+
++[log_grep.inc] lines:   0
++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Tmp_tables: 0
++[log_grep.inc] lines:   3
++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Tmp_disk_tables: [^0]+
++[log_grep.inc] lines:   0
++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Tmp_disk_tables: 0
++[log_grep.inc] lines:   3
++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Tmp_table_sizes: [^0]+
++[log_grep.inc] lines:   0
++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Tmp_table_sizes: 0
++[log_grep.inc] lines:   3
++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: # No InnoDB statistics available for this query
++[log_grep.inc] lines:   2
++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: # InnoDB_trx_id: 
++[log_grep.inc] lines:   1
++################################################################################
+--- /dev/null
++++ b/mysql-test/include/percona_slow_extended_error_on_quit.inc
+@@ -0,0 +1,50 @@
++--echo ################################################################################
++--let grep_pattern=CREATE
++--source include/log_grep.inc
++--let grep_pattern=INSERT
++--source include/log_grep.inc
++--let grep_pattern=SELECT
++--source include/log_grep.inc
++--let grep_pattern=Quit
++--source include/log_grep.inc
++--let grep_pattern=Last_errno: [^0]+
++--source include/log_grep.inc
++--let grep_pattern=Last_errno: 0
++--source include/log_grep.inc
++--let grep_pattern=Rows_sent: [^0]+
++--source include/log_grep.inc
++--let grep_pattern=Rows_sent: 0
++--source include/log_grep.inc
++--let grep_pattern=Rows_examined: [^0]+
++--source include/log_grep.inc
++--let grep_pattern=Rows_examined: 0
++--source include/log_grep.inc
++--let grep_pattern=Rows_affected: [^0]+
++--source include/log_grep.inc
++--let grep_pattern=Rows_affected: 0
++--source include/log_grep.inc
++--let grep_pattern=Rows_read: [^0]+
++--source include/log_grep.inc
++--let grep_pattern=Rows_read: 0
++--source include/log_grep.inc
++--let grep_pattern=Bytes_sent: [^0]+
++--source include/log_grep.inc
++--let grep_pattern=Bytes_sent: 0
++--source include/log_grep.inc
++--let grep_pattern=Tmp_tables: [^0]+
++--source include/log_grep.inc
++--let grep_pattern=Tmp_tables: 0
++--source include/log_grep.inc
++--let grep_pattern=Tmp_disk_tables: [^0]+
++--source include/log_grep.inc
++--let grep_pattern=Tmp_disk_tables: 0
++--source include/log_grep.inc
++--let grep_pattern=Tmp_table_sizes: [^0]+
++--source include/log_grep.inc
++--let grep_pattern=Tmp_table_sizes: 0
++--source include/log_grep.inc
++--let grep_pattern=# No InnoDB statistics available for this query
++--source include/log_grep.inc
++--let grep_pattern=# InnoDB_trx_id: 
++--source include/log_grep.inc
++--echo ################################################################################