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.
No test case as there is no way to test slow log/general log in 
mysqltest.


mysql-test/r/ps_grant.result:
  Now execute is logged with tag 'Execute' (changed result file).
sql/mysql_priv.h:
  - remove obsolete macro.
  - add declarations for new status variables.
  - export function log_slow_statement, which now is used in sql_prepare.cc
sql/mysqld.cc:
  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/sql_parse.cc:
  - account DEALLOCATE prepare as a Com_stmt_close command (close of a
  prepared statement).
sql/sql_prepare.cc:
  - fix a bug in SQL syntax for 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.
  - account statistics for 
    mysql_stmt_{prepare,execute,close,reset,send_long_data} in
    Com_stmt_{prepare,execute,close,reset,send_long_data} correspondingly.
  - log slow statements into the slow 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 statement twice by 
    setting thd->enable_slow_log= FALSE.
  - 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 the statement twice.

mysql-test/r/ps_grant.result

@@ -78,4 +78,4 @@ drop database mysqltest;
 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

sql/mysql_priv.h

@@ -424,8 +424,6 @@ struct Query_cache_query_flags
 #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 @@ void mysql_execute_command(THD *thd);
 bool do_command(THD *thd);
 bool dispatch_command(enum enum_server_command command, THD *thd,
 		      char* packet, uint packet_length);
+void log_slow_statement(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 binlog_cache_size, max_binlog_cache_size, open_files_limit;
 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;

sql/mysqld.cc

@@ -316,6 +316,8 @@ ulong slave_net_timeout, slave_trans_retries;
 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;
@@ -5474,6 +5476,11 @@ struct show_var_st status_vars[]= {
   {"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},

sql/sql_parse.cc

@@ -59,7 +59,6 @@ static void remove_escape(char *name);
 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
 
@@ -1515,7 +1514,7 @@ bool dispatch_command(enum enum_server_command command, THD *thd,
 #endif
       ulong length= (ulong)(packet_end-packet);
 
-      log_slow_query(thd);
+      log_slow_statement(thd);
 
       /* Remove garbage at start of query */
       while (my_isspace(thd->charset(), *packet) && length > 0)
@@ -1827,7 +1826,7 @@ bool dispatch_command(enum enum_server_command command, THD *thd,
   if (thd->is_fatal_error)
     send_error(thd,0);				// End of memory ?
 
-  log_slow_query(thd);
+  log_slow_statement(thd);
 
   thd->proc_info="cleaning up";
   VOID(pthread_mutex_lock(&LOCK_thread_count)); // For process list
@@ -1843,7 +1842,7 @@ bool dispatch_command(enum enum_server_command command, THD *thd,
 }
 
 
-static void log_slow_query(THD *thd)
+void log_slow_statement(THD *thd)
 {
   time_t start_of_query=thd->start_time;
   thd->end_time();				// Set start time
@@ -2193,6 +2192,8 @@ mysql_execute_command(THD *thd)
     DBUG_PRINT("info", ("DEALLOCATE PREPARE: %.*s\n", 
                         lex->prepared_stmt_name.length,
                         lex->prepared_stmt_name.str));
+    /* We account deallocate in the same manner as mysql_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);

sql/sql_prepare.cc

@@ -820,7 +820,8 @@ static bool insert_params_from_vars_with_log(Prepared_statement *stmt,
   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 @@ static bool insert_params_from_vars_with_log(Prepared_statement *stmt,
     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 @@ int mysql_stmt_prepare(THD *thd, char *packet, uint packet_length,
 
   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 @@ int mysql_stmt_prepare(THD *thd, char *packet, uint packet_length,
     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 @@ void mysql_stmt_execute(THD *thd, char *packet, uint packet_length)
 
   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 @@ void mysql_stmt_execute(THD *thd, char *packet, uint packet_length)
   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 @@ void mysql_sql_stmt_execute(THD *thd, LEX_STRING *stmt_name)
   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 @@ void mysql_sql_stmt_execute(THD *thd, LEX_STRING *stmt_name)
     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 @@ static void execute_stmt(THD *thd, Prepared_statement *stmt,
     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 @@ static void execute_stmt(THD *thd, Prepared_statement *stmt,
   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_statement(thd);
+  /* Prevent from second logging in the end of dispatch_command */
+  thd->enable_slow_log= FALSE;
 
   /* Free Items that were created during this execution of the PS. */
   free_items(thd->free_list);
@@ -1941,6 +1962,7 @@ void mysql_stmt_reset(THD *thd, char *packet)
   
   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 @@ void mysql_stmt_free(THD *thd, char *packet)
 
   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 @@ void mysql_stmt_get_longdata(THD *thd, char *packet, ulong packet_length)
   
   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 @@ Prepared_statement::Prepared_statement(THD *thd_arg)
   *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
@@ -2091,6 +2117,7 @@ void Prepared_statement::setup_set_params()
   }
 }
 
+
 Prepared_statement::~Prepared_statement()
 {
   free_items(free_list);