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

[Oleg Tsarev]

Fixed bug #716210 - incorrect last_errno in slow-query-log

[Oleg Tsarev (tsarev)]

http://jenkins.percona.com/view/Percona%20Server%205.1/job/percona-server-5.1-param/133/

[Oleg Tsarev (tsarev)]

http://jenkins.percona.com/view/Percona%20Server%205.1/job/percona-server-5.1-param/138

[Laurynas Biveinis (laurynas-biveinis)]

LGTM provided that Jenkins result are clean

review: Approve

[Alexey Kopytov (akopytov)]

last_errno is not the only variable that has to be reset for admin commands after a failing statement. Most other counters from slow_extended are affected by the same problem.

Here's an test case:

create table t1(a int primary key);
insert into t1 values (1), (2), (3);
insert into t1 select * from t1 order by rand();

The last statement will fail ER_DUP_ENTRY, and the next admin command will have the same Last_errno, Rows_{sent,examined,affected,read}, Bytes_sent, Tmp_tables, Tmp_disk_tables and Tmp_table_sizes.

I'm fairly sure InnoDB stats have the same problem.

Some comments on the test case:

- with use_global_long_query_time=1 do you really need to create a separate connection?
- please replace 1050 with ER_TABLE_EXISTS_ERROR.

review: Needs Fixing

Unmerged revisions

282. By Oleg Tsarev on 2011-09-12

Fixed bug #716210 - incorrect last_errno in slow-query-log

281. By Oleg Tsarev on 2011-09-12

1) move tests from mysql-test/ to patches
2) remove install_tests script and call of script from Makefile

=== modified file 'patches/bug580324.patch'
--- patches/bug580324.patch	2011-08-09 13:35:34 +0000
+++ patches/bug580324.patch	2011-09-12 13:47:56 +0000
@@ -24,7 +24,7 @@
      int4store(key + key_length, thd->server_id);
 --- a/sql/sql_parse.cc
 +++ b/sql/sql_parse.cc
-@@ -1342,10 +1342,12 @@
+@@ -1343,10 +1343,12 @@
      break;
  #else
    {
@@ -39,7 +39,7 @@
  
      /* used as fields initializator */
      lex_start(thd);
-@@ -1357,26 +1359,22 @@
+@@ -1358,26 +1360,22 @@
      /*
        We have name + wildcard in packet, separated by endzero
      */
@@ -77,7 +77,7 @@
  
      if (is_schema_db(table_list.db, table_list.db_length))
      {
-@@ -1385,9 +1383,6 @@
+@@ -1386,9 +1384,6 @@
          table_list.schema_table= schema_table;
      }
  
 
=== modified file 'patches/response_time_distribution.patch'
--- patches/response_time_distribution.patch	2011-07-30 23:07:03 +0000
+++ patches/response_time_distribution.patch	2011-09-12 13:47:56 +0000
@@ -3119,7 +3119,7 @@
  
  /**
    @defgroup Runtime_Environment Runtime Environment
-@@ -1777,6 +1778,7 @@
+@@ -1778,6 +1779,7 @@
  
    ulonglong end_utime_of_query= thd->current_utime();
    ulonglong query_exec_time= get_query_exec_time(thd, end_utime_of_query);
@@ -3127,7 +3127,7 @@
  
    /*
      Low long_query_time value most likely means user is debugging stuff and even
-@@ -1947,6 +1949,7 @@
+@@ -1948,6 +1950,7 @@
    case SCH_CHARSETS:
    case SCH_ENGINES:
    case SCH_COLLATIONS:
@@ -3135,7 +3135,7 @@
    case SCH_COLLATION_CHARACTER_SET_APPLICABILITY:
    case SCH_USER_PRIVILEGES:
    case SCH_SCHEMA_PRIVILEGES:
-@@ -7306,6 +7309,12 @@
+@@ -7307,6 +7310,12 @@
      init_global_index_stats();
      pthread_mutex_unlock(&LOCK_global_index_stats);
    }
 
=== modified file 'patches/show_slave_status_nolock.patch'
--- patches/show_slave_status_nolock.patch	2011-09-06 08:23:51 +0000
+++ patches/show_slave_status_nolock.patch	2011-09-12 13:47:56 +0000
@@ -56,7 +56,7 @@
    sql_command_flags[SQLCOM_SHOW_CREATE_PROC]=  CF_STATUS_COMMAND;
    sql_command_flags[SQLCOM_SHOW_CREATE_FUNC]=  CF_STATUS_COMMAND;
    sql_command_flags[SQLCOM_SHOW_CREATE_TRIGGER]=  CF_STATUS_COMMAND;
-@@ -2589,12 +2590,16 @@
+@@ -2590,12 +2591,16 @@
      pthread_mutex_unlock(&LOCK_active_mi);
      break;
    }
@@ -74,7 +74,7 @@
      if (active_mi != NULL)
      {
        res = show_master_info(thd, active_mi);
-@@ -2605,7 +2610,10 @@
+@@ -2606,7 +2611,10 @@
                     WARN_NO_MASTER_INFO, ER(WARN_NO_MASTER_INFO));
        my_ok(thd);
      }
 
=== modified file 'patches/show_temp_51.patch'
--- patches/show_temp_51.patch	2011-09-06 08:23:51 +0000
+++ patches/show_temp_51.patch	2011-09-12 13:47:56 +0000
@@ -38,7 +38,7 @@
    sql_command_flags[SQLCOM_SHOW_TABLE_STATUS]= (CF_STATUS_COMMAND |
                                                  CF_SHOW_TABLE_COMMAND |
                                                  CF_REEXECUTION_FRAGILE);
-@@ -1875,6 +1878,8 @@
+@@ -1876,6 +1879,8 @@
  
    case SCH_TABLE_NAMES:
    case SCH_TABLES:
@@ -47,7 +47,7 @@
    case SCH_VIEWS:
    case SCH_TRIGGERS:
    case SCH_EVENTS:
-@@ -2374,6 +2379,7 @@
+@@ -2375,6 +2380,7 @@
    }
    case SQLCOM_SHOW_DATABASES:
    case SQLCOM_SHOW_TABLES:
@@ -55,7 +55,7 @@
    case SQLCOM_SHOW_TRIGGERS:
    case SQLCOM_SHOW_TABLE_STATUS:
    case SQLCOM_SHOW_OPEN_TABLES:
-@@ -5527,6 +5533,8 @@
+@@ -5528,6 +5534,8 @@
  
    case SCH_TABLE_NAMES:
    case SCH_TABLES:
 
=== modified file 'patches/slow_extended.patch'
--- patches/slow_extended.patch	2011-08-09 13:35:34 +0000
+++ patches/slow_extended.patch	2011-09-12 13:47:56 +0000
@@ -1388,7 +1388,15 @@
  
  const char *any_db="*any*";	// Special symbol for check_access
  
-@@ -1700,6 +1701,50 @@
+@@ -999,6 +1000,7 @@
+     the slow log only if opt_log_slow_admin_statements is set.
+   */
+   thd->enable_slow_log= TRUE;
++  thd->last_errno= 0;
+   thd->lex->sql_command= SQLCOM_END; /* to avoid confusing VIEW detectors */
+   thd->set_time();
+   if (!thd->is_valid_time())
+@@ -1700,6 +1702,50 @@
    DBUG_RETURN(error);
  }
  
@@ -1439,7 +1447,7 @@
  
  void log_slow_statement(THD *thd)
  {
-@@ -1713,17 +1758,51 @@
+@@ -1713,17 +1759,51 @@
    if (unlikely(thd->in_sub_stmt))
      DBUG_VOID_RETURN;                           // Don't set time for sub stmt
  
@@ -1494,7 +1502,7 @@
           ((thd->server_status &
             (SERVER_QUERY_NO_INDEX_USED | SERVER_QUERY_NO_GOOD_INDEX_USED)) &&
            opt_log_queries_not_using_indexes &&
-@@ -2099,6 +2178,9 @@
+@@ -2099,6 +2179,9 @@
      context.resolve_in_table_list_only(select_lex->
                                         table_list.first);
  
@@ -1504,7 +1512,7 @@
    /*
      Reset warning count for each query that uses tables
      A better approach would be to reset this for any commands
-@@ -5827,6 +5909,21 @@
+@@ -5827,6 +5910,21 @@
    thd->rand_used= 0;
    thd->sent_row_count= thd->examined_row_count= 0;
  
@@ -2575,3 +2583,44 @@
  /* Intvar event post-header */
  
  /* Intvar event data */
+--- /dev/null
++++ b/mysql-test/r/percona_log_slow_parse_error.result
+@@ -0,0 +1,11 @@
++SET GLOBAL long_query_time=0;
++SET GLOBAL use_global_long_query_time=1;
++SET GLOBAL log_slow_timestamp_every=1;
++DROP TABLE IF EXISTS t1;
++CREATE TABLE t1 (a INT);
++[log_start.inc] percona.slow_extended.error_on_quit
++CREATE TABLE t1 (a INT);
++ERROR 42S01: Table 't1' already exists
++[log_stop.inc] percona.slow_extended.error_on_quit
++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Last_errno: 1050
++[log_grep.inc] lines:   1
+--- /dev/null
++++ b/mysql-test/t/percona_log_slow_parse_error.test
+@@ -0,0 +1,24 @@
++--let log_file=percona.slow_extended.error_on_quit
++
++SET GLOBAL long_query_time=0;
++SET GLOBAL use_global_long_query_time=1;
++SET GLOBAL log_slow_timestamp_every=1;
++
++connect (conn1,localhost,root,,);
++connection conn1;
++--disable_warnings
++DROP TABLE IF EXISTS t1;
++--enable_warnings
++CREATE TABLE t1 (a INT);
++--source include/log_start.inc
++--error 1050
++CREATE TABLE t1 (a INT);
++disconnect conn1;
++connection default;
++--source include/log_stop.inc
++--let grep_pattern = Last_errno: 1050
++--source include/log_grep.inc
++SET GLOBAL long_query_time=default;
++SET GLOBAL use_global_long_query_time=default;
++SET GLOBAL log_slow_timestamp_every=default;
++DROP TABLE t1;
 
=== modified file 'patches/userstat.patch'
--- patches/userstat.patch	2011-09-06 08:23:51 +0000
+++ patches/userstat.patch	2011-09-12 13:47:56 +0000
@@ -1759,7 +1759,7 @@
    /*
      Commands which always take a long time are logged into
      the slow log only if opt_log_slow_admin_statements is set.
-@@ -1921,6 +1933,13 @@
+@@ -1922,6 +1934,13 @@
      thd->profiling.discard_current_query();
  #endif
      break;
@@ -1773,7 +1773,7 @@
    case SCH_OPEN_TABLES:
    case SCH_VARIABLES:
    case SCH_STATUS:
-@@ -2077,6 +2096,7 @@
+@@ -2078,6 +2097,7 @@
                         thd->security_ctx->priv_host)) &&
          check_global_access(thd, SUPER_ACL))
      {
@@ -1781,7 +1781,7 @@
        my_error(ER_SPECIFIC_ACCESS_DENIED_ERROR, MYF(0), "SUPER");
        DBUG_RETURN(TRUE);
      }
-@@ -5418,6 +5438,7 @@
+@@ -5419,6 +5439,7 @@
        if (!no_errors)
        {
          const char *db_name= db ? db : thd->db;
@@ -1789,7 +1789,7 @@
          my_error(ER_DBACCESS_DENIED_ERROR, MYF(0),
                   sctx->priv_user, sctx->priv_host, db_name);
        }
-@@ -5450,12 +5471,15 @@
+@@ -5451,12 +5472,15 @@
    {						// We can never grant this
      DBUG_PRINT("error",("No possible access"));
      if (!no_errors)
@@ -1805,7 +1805,7 @@
      DBUG_RETURN(TRUE);				/* purecov: tested */
    }
  
-@@ -5481,11 +5505,15 @@
+@@ -5482,11 +5506,15 @@
  
    DBUG_PRINT("error",("Access denied"));
    if (!no_errors)
@@ -1821,7 +1821,7 @@
    DBUG_RETURN(TRUE);				/* purecov: tested */
  }
  
-@@ -5514,6 +5542,7 @@
+@@ -5515,6 +5543,7 @@
  
      if (!thd->col_access && check_grant_db(thd, dst_db_name))
      {
@@ -1829,7 +1829,7 @@
        my_error(ER_DBACCESS_DENIED_ERROR, MYF(0),
                 thd->security_ctx->priv_user,
                 thd->security_ctx->priv_host,
-@@ -5595,9 +5624,12 @@
+@@ -5596,9 +5625,12 @@
          (want_access & ~(SELECT_ACL | EXTRA_ACL | FILE_ACL)))
      {
        if (!no_errors)
@@ -1842,7 +1842,7 @@
        return TRUE;
      }
      /*
-@@ -5760,6 +5792,7 @@
+@@ -5761,6 +5793,7 @@
    if ((thd->security_ctx->master_access & want_access))
      return 0;
    get_privilege_desc(command, sizeof(command), want_access);
@@ -1850,7 +1850,7 @@
    my_error(ER_SPECIFIC_ACCESS_DENIED_ERROR, MYF(0), command);
    return 1;
  #else
-@@ -6134,6 +6167,32 @@
+@@ -6135,6 +6168,32 @@
    lex_start(thd);
    mysql_reset_thd_for_next_command(thd);
  
@@ -1883,7 +1883,7 @@
    if (query_cache_send_result_to_client(thd, rawbuf, length) <= 0)
    {
      LEX *lex= thd->lex;
-@@ -6214,6 +6273,43 @@
+@@ -6215,6 +6274,43 @@
      *found_semicolon= NULL;
    }
  
@@ -1927,7 +1927,7 @@
    DBUG_VOID_RETURN;
  }
  
-@@ -7086,6 +7182,13 @@
+@@ -7087,6 +7183,13 @@
      if (flush_error_log())
        result=1;
    }
@@ -1941,7 +1941,7 @@
  #ifdef HAVE_QUERY_CACHE
    if (options & REFRESH_QUERY_CACHE_FREE)
    {
-@@ -7186,6 +7289,40 @@
+@@ -7187,6 +7290,40 @@
  #endif
   if (options & REFRESH_USER_RESOURCES)
     reset_mqh((LEX_USER *) NULL, 0);             /* purecov: inspected */