bk commit into 4.1 tree (konstantin:1.2291) BUG#8367

[konstantin]

Below is the list of changes that have just been committed into a local
4.1 repository of kostja. When kostja does a push these changes will
be propagated to the main repository and, within 24 hours after the
push, to the public repository.
For information on how to access the public repository
see http://dev.mysql.com/doc/mysql/en/installing-source-tree.html

ChangeSet
  1.2291 05/06/11 00:16:02 konstantin@stripped +5 -0
  Fix Bug#9334 "PS API queries in log file" and 
  Bug#8367 "low log doesn't gives complete information about prepared 
  statements"
  Implement status variables for prepared statements commands (a port of
  the patch by Andrey Hristov).
  See details in comments to the changed files.

  sql/sql_prepare.cc
    1.146 05/06/11 00:15:57 konstantin@stripped +49 -22
    - fix a bug in SQL syntax in prepared statements + logging:
      if we use --log and EXECUTE stmt USING @no_such_variable;, the
      server crashed because the old code assumed that the variable 
      returned by get_var_with_binlog is never NULL.
    - accound statistics for 
      mysql_stmt_{prepare,execute,close,reset,send_long_data} in
      Com_stmt_{prepare,execute,close,reset,send_long_data} correspondingly.
    - log slow queries into the slow query log early, when thd->query
      points to a valid (with expanded placeholder values) query.
      The previous version was logging it in sql_parse, when thd->query
      is empty. Prevent the server from logging the query twice by 
      setting thd->slow_command= TRUE (slow commands are not logged in the
      slow query log).
    - now in case of EXECUTE stmt in SQL syntax for prepared statements the 
      general log gets two queries, e.g.
      Query    EXECUTE stmt USING @a, @b, @c
      Execute  INSERT INTO t1 VALUES (1, 2, 3)
      This makes the behavior consistent with PREPARE command, which
      also logs two queries.

  sql/sql_parse.cc
    1.441 05/06/11 00:15:56 konstantin@stripped +3 -2
    - account DEALLOCATE prepare as a Com_stmt_close command (close of a
    prepared statement).

  sql/mysqld.cc
    1.574 05/06/11 00:15:56 konstantin@stripped +7 -0
    Add status variables for prepared statements API: now we record
    mysql_stmt_close, mysql_stmt_reset, mysql_stmt_prepare, mysql_stmt_execute
    mysql_stmt_send_long_data, PREPARE, EXECUTE, DEALLOCATE.

  sql/mysql_priv.h
    1.351 05/06/11 00:15:56 konstantin@stripped +3 -2
    - remove obsolete macro.
    - add declarations for new status variables.
    - export function log_slow_query, which now is used in sql_prepare.cc

  mysql-test/r/ps_grant.result
    1.4 05/06/11 00:15:56 konstantin@stripped +1 -1
    Now execute is logged with tag 'Execute' (changed result file).

# This is a BitKeeper patch.  What follows are the unified diffs for the
# set of deltas contained in the patch.  The rest of the patch, the part
# that BitKeeper cares about, is below these diffs.
# User:	konstantin
# Host:	dragonfly.local
# Root:	/opt/local/work/mysql-4.1-9334-new

--- 1.350/sql/mysql_priv.h	2005-06-04 09:23:30 +04:00
+++ 1.351/sql/mysql_priv.h	2005-06-11 00:15:56 +04:00
@@ -424,8 +424,6 @@
 #define query_cache_invalidate_by_MyISAM_filename_ref NULL
 #endif /*HAVE_QUERY_CACHE*/
 
-#define prepare_execute(A) ((A)->command == COM_EXECUTE)
-
 int mysql_create_db(THD *thd, char *db, HA_CREATE_INFO *create, bool silent);
 int mysql_alter_db(THD *thd, const char *db, HA_CREATE_INFO *create);
 int mysql_rm_db(THD *thd,char *db,bool if_exists, bool silent);
@@ -462,6 +460,7 @@
 bool do_command(THD *thd);
 bool dispatch_command(enum enum_server_command command, THD *thd,
 		      char* packet, uint packet_length);
+void log_slow_query(THD *thd);
 bool check_dup(const char *db, const char *name, TABLE_LIST *tables);
 
 bool table_cache_init(void);
@@ -899,6 +898,8 @@
 extern ulong max_binlog_size, max_relay_log_size;
 extern ulong rpl_recovery_rank, thread_cache_size;
 extern ulong com_stat[(uint) SQLCOM_END], com_other, back_log;
+extern ulong com_stmt_prepare, com_stmt_execute, com_stmt_send_long_data;
+extern ulong com_stmt_reset, com_stmt_close;
 extern ulong specialflag, current_pid;
 extern ulong expire_logs_days, sync_binlog_period, sync_binlog_counter;
 extern my_bool relay_log_purge, opt_innodb_safe_binlog;

--- 1.573/sql/mysqld.cc	2005-06-04 00:45:57 +04:00
+++ 1.574/sql/mysqld.cc	2005-06-11 00:15:56 +04:00
@@ -315,6 +315,8 @@
 ulong thread_cache_size=0, binlog_cache_size=0, max_binlog_cache_size=0;
 ulong query_cache_size=0;
 ulong com_stat[(uint) SQLCOM_END], com_other;
+ulong com_stmt_prepare, com_stmt_execute, com_stmt_send_long_data;
+ulong com_stmt_close, com_stmt_reset;
 ulong bytes_sent, bytes_received, net_big_packet_count;
 ulong refresh_version, flush_version;	/* Increments on each reload */
 ulong query_id, long_query_count;
@@ -5462,6 +5464,11 @@
   {"Com_show_warnings",        (char*) (com_stat+(uint) SQLCOM_SHOW_WARNS),SHOW_LONG},
   {"Com_slave_start",	       (char*) (com_stat+(uint) SQLCOM_SLAVE_START),SHOW_LONG},
   {"Com_slave_stop",	       (char*) (com_stat+(uint) SQLCOM_SLAVE_STOP),SHOW_LONG},
+  {"Com_stmt_prepare",         (char*) &com_stmt_prepare, SHOW_LONG},
+  {"Com_stmt_execute",         (char*) &com_stmt_execute, SHOW_LONG},
+  {"Com_stmt_send_long_data",  (char*) &com_stmt_send_long_data, SHOW_LONG},
+  {"Com_stmt_reset",           (char*) &com_stmt_reset, SHOW_LONG},
+  {"Com_stmt_close",           (char*) &com_stmt_close, SHOW_LONG},
   {"Com_truncate",	       (char*) (com_stat+(uint) SQLCOM_TRUNCATE),SHOW_LONG},
   {"Com_unlock_tables",	       (char*) (com_stat+(uint) SQLCOM_UNLOCK_TABLES),SHOW_LONG},
   {"Com_update",	       (char*) (com_stat+(uint) SQLCOM_UPDATE),SHOW_LONG},

--- 1.440/sql/sql_parse.cc	2005-06-04 09:28:18 +04:00
+++ 1.441/sql/sql_parse.cc	2005-06-11 00:15:56 +04:00
@@ -59,7 +59,6 @@
 static void refresh_status(void);
 static bool append_file_to_dir(THD *thd, const char **filename_ptr,
 			       const char *table_name);
-static void log_slow_query(THD *thd);
 
 const char *any_db="*any*";	// Special symbol for check_access
 
@@ -1843,7 +1842,7 @@
 }
 
 
-static void log_slow_query(THD *thd)
+void log_slow_query(THD *thd)
 {
   time_t start_of_query=thd->start_time;
   thd->end_time();				// Set start time
@@ -2190,6 +2189,8 @@
     DBUG_PRINT("info", ("DEALLOCATE PREPARE: %.*s\n", 
                         lex->prepared_stmt_name.length,
                         lex->prepared_stmt_name.str));
+    /* We account deallocate the same as stmt_close */
+    statistic_increment(com_stmt_close, &LOCK_status);
     if ((stmt= thd->stmt_map.find_by_name(&lex->prepared_stmt_name)))
     {
       thd->stmt_map.erase(stmt);

--- 1.3/mysql-test/r/ps_grant.result	2005-05-12 19:49:28 +04:00
+++ 1.4/mysql-test/r/ps_grant.result	2005-06-11 00:15:56 +04:00
@@ -78,4 +78,4 @@
 prepare stmt4 from ' show full processlist ';
 execute stmt4;
 Id	User	Host	db	Command	Time	State	Info
-number	root	localhost	test	Query	time	NULL	show full processlist
+number	root	localhost	test	Execute	time	NULL	show full processlist

--- 1.145/sql/sql_prepare.cc	2005-03-23 09:36:42 +03:00
+++ 1.146/sql/sql_prepare.cc	2005-06-11 00:15:57 +04:00
@@ -820,7 +820,8 @@
   DBUG_ENTER("insert_params_from_vars");
 
   List_iterator<LEX_STRING> var_it(varnames);
-  String str;
+  String buf;
+  const String *val;
   uint32 length= 0;
   if (query->copy(stmt->query, stmt->query_length, default_charset_info))
     DBUG_RETURN(1);
@@ -831,32 +832,35 @@
     varname= var_it++;
     if (get_var_with_binlog(stmt->thd, *varname, &entry))
         DBUG_RETURN(1);
-    DBUG_ASSERT(entry);
 
     if (param->set_from_user_var(stmt->thd, entry))
       DBUG_RETURN(1);
     /* Insert @'escaped-varname' instead of parameter in the query */
-    char *buf, *ptr;
-    str.length(0);
-    if (str.reserve(entry->name.length*2+3))
-      DBUG_RETURN(1);
+    if (entry)
+    {
+      char *begin, *ptr;
+      buf.length(0);
+      if (buf.reserve(entry->name.length*2+3))
+        DBUG_RETURN(1);
 
-    buf= str.c_ptr_quick();
-    ptr= buf;
-    *ptr++= '@';
-    *ptr++= '\'';
-    ptr+=
-      escape_string_for_mysql(&my_charset_utf8_general_ci,
-                              ptr, entry->name.str, entry->name.length);
-    *ptr++= '\'';
-    str.length(ptr - buf);
+      begin= ptr= buf.c_ptr_quick();
+      *ptr++= '@';
+      *ptr++= '\'';
+      ptr+= escape_string_for_mysql(&my_charset_utf8_general_ci,
+                                    ptr, entry->name.str, entry->name.length);
+      *ptr++= '\'';
+      buf.length(ptr - begin);
+      val= &buf;
+    }
+    else
+      val= &my_null_string;
 
     if (param->convert_str_value(stmt->thd))
       DBUG_RETURN(1);                           /* out of memory */
 
-    if (query->replace(param->pos_in_query+length, 1, str))
+    if (query->replace(param->pos_in_query+length, 1, *val))
       DBUG_RETURN(1);
-    length+= str.length()-1;
+    length+= val->length()-1;
   }
   DBUG_RETURN(0);
 }
@@ -1558,6 +1562,13 @@
 
   DBUG_PRINT("prep_query", ("%s", packet));
 
+  /*
+    If this is an SQLCOM_PREPARE, we also increase Com_prepare_sql.
+    However, it seems handy if com_stmt_prepare is increased always,
+    no matter what kind of prepare is processed.
+  */
+  statistic_increment(com_stmt_prepare, &LOCK_status);
+
   if (stmt == 0)
   {
     send_error(thd, ER_OUT_OF_RESOURCES);
@@ -1596,7 +1607,7 @@
     DBUG_RETURN(1);
   }
 
-  mysql_log.write(thd, COM_PREPARE, "[%lu] %s", stmt->id, packet);
+  mysql_log.write(thd, thd->command, "[%lu] %s", stmt->id, packet);
 
   thd->current_arena= stmt;
   mysql_init_query(thd, (uchar *) thd->query, thd->query_length);
@@ -1763,6 +1774,7 @@
 
   packet+= 9;                               /* stmt_id + 5 bytes of flags */
 
+  statistic_increment(com_stmt_execute, &LOCK_status);
   if (!(stmt= find_prepared_statement(thd, stmt_id, "mysql_stmt_execute",
                                       SEND_ERROR)))
     DBUG_VOID_RETURN;
@@ -1796,9 +1808,6 @@
   if (stmt->param_count && stmt->set_params_data(stmt,
&expanded_query))
     goto set_params_data_err;
 #endif
-  mysql_log.write(thd, COM_EXECUTE, "[%lu] %s", stmt->id,
-                  expanded_query.length() ? expanded_query.c_ptr() :
-                                            stmt->query);
   thd->protocol= &thd->protocol_prep;           // Switch to binary protocol
   execute_stmt(thd, stmt, &expanded_query, TRUE);
   thd->protocol= &thd->protocol_simple;         // Use normal protocol
@@ -1827,6 +1836,8 @@
   String expanded_query;
   DBUG_ENTER("mysql_sql_stmt_execute");
 
+  /* See comment for statistics_increment in mysql_stmt_prepare */
+  statistic_increment(com_stmt_execute, &LOCK_status);
   if (!(stmt= (Prepared_statement*)thd->stmt_map.find_by_name(stmt_name)))
   {
     my_error(ER_UNKNOWN_STMT_HANDLER, MYF(0), stmt_name->length,
@@ -1853,6 +1864,7 @@
     my_error(ER_WRONG_ARGUMENTS, MYF(0), "EXECUTE");
     send_error(thd);
   }
+  thd->command= COM_EXECUTE; /* For nice messages in general log */
   execute_stmt(thd, stmt, &expanded_query, FALSE);
   DBUG_VOID_RETURN;
 }
@@ -1887,6 +1899,7 @@
     my_error(ER_OUTOFMEMORY, 0, expanded_query->length());
     DBUG_VOID_RETURN;
   }
+  mysql_log.write(thd, thd->command, "[%lu] %s", stmt->id, thd->query);
   /*
     At first execution of prepared statement we will perform logical
     transformations of the query tree (i.e. negations elimination).
@@ -1900,6 +1913,14 @@
   thd->lex->unit.cleanup();
   if (!(specialflag & SPECIAL_NO_PRIOR))
     my_pthread_setprio(pthread_self(), WAIT_PRIOR);
+  /*
+    'start_time' is set in dispatch_command, but THD::query will
+    be freed when we return from this function. So let's log the slow
+    query here.
+  */
+  log_slow_query(thd);
+  /* Prevent from second logging in the end of dispatch_command */
+  thd->slow_command= TRUE;
 
   /* Free Items that were created during this execution of the PS. */
   free_items(thd->free_list);
@@ -1941,6 +1962,7 @@
   
   DBUG_ENTER("mysql_stmt_reset");
 
+  statistic_increment(com_stmt_reset, &LOCK_status);
   if (!(stmt= find_prepared_statement(thd, stmt_id, "mysql_stmt_reset",
                                       SEND_ERROR)))
     DBUG_VOID_RETURN;
@@ -1973,6 +1995,7 @@
 
   DBUG_ENTER("mysql_stmt_free");
 
+  statistic_increment(com_stmt_close, &LOCK_status);
   if (!(stmt= find_prepared_statement(thd, stmt_id, "mysql_stmt_close",
                                       DONT_SEND_ERROR)))
     DBUG_VOID_RETURN;
@@ -2012,6 +2035,7 @@
   
   DBUG_ENTER("mysql_stmt_get_longdata");
 
+  statistic_increment(com_stmt_send_long_data, &LOCK_status);
 #ifndef EMBEDDED_LIBRARY
   /* Minimal size of long data packet is 6 bytes */
   if ((ulong) (packet_end - packet) < MYSQL_LONG_DATA_HEADER)
@@ -2068,10 +2092,12 @@
   *last_error= '\0';
 }
 
+
 void Prepared_statement::setup_set_params()
 {
   /* Setup binary logging */
-  if (mysql_bin_log.is_open() && is_update_query(lex->sql_command))
+  if (mysql_bin_log.is_open() && is_update_query(lex->sql_command) ||
+      mysql_log.is_open() || mysql_slow_log.is_open())
   {
     set_params_from_vars= insert_params_from_vars_with_log;
 #ifndef EMBEDDED_LIBRARY
@@ -2090,6 +2116,7 @@
 #endif
   }
 }
+
 
 Prepared_statement::~Prepared_statement()
 {