Commit c0484a30 authored by unknown's avatar unknown

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.
parent 51cd70da
...@@ -78,4 +78,4 @@ drop database mysqltest; ...@@ -78,4 +78,4 @@ drop database mysqltest;
prepare stmt4 from ' show full processlist '; prepare stmt4 from ' show full processlist ';
execute stmt4; execute stmt4;
Id User Host db Command Time State Info 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
...@@ -424,8 +424,6 @@ struct Query_cache_query_flags ...@@ -424,8 +424,6 @@ struct Query_cache_query_flags
#define query_cache_invalidate_by_MyISAM_filename_ref NULL #define query_cache_invalidate_by_MyISAM_filename_ref NULL
#endif /*HAVE_QUERY_CACHE*/ #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_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_alter_db(THD *thd, const char *db, HA_CREATE_INFO *create);
int mysql_rm_db(THD *thd,char *db,bool if_exists, bool silent); int mysql_rm_db(THD *thd,char *db,bool if_exists, bool silent);
...@@ -462,6 +460,7 @@ void mysql_execute_command(THD *thd); ...@@ -462,6 +460,7 @@ void mysql_execute_command(THD *thd);
bool do_command(THD *thd); bool do_command(THD *thd);
bool dispatch_command(enum enum_server_command command, THD *thd, bool dispatch_command(enum enum_server_command command, THD *thd,
char* packet, uint packet_length); char* packet, uint packet_length);
void log_slow_statement(THD *thd);
bool check_dup(const char *db, const char *name, TABLE_LIST *tables); bool check_dup(const char *db, const char *name, TABLE_LIST *tables);
bool table_cache_init(void); bool table_cache_init(void);
...@@ -899,6 +898,8 @@ extern ulong binlog_cache_size, max_binlog_cache_size, open_files_limit; ...@@ -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 max_binlog_size, max_relay_log_size;
extern ulong rpl_recovery_rank, thread_cache_size; extern ulong rpl_recovery_rank, thread_cache_size;
extern ulong com_stat[(uint) SQLCOM_END], com_other, back_log; 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 specialflag, current_pid;
extern ulong expire_logs_days, sync_binlog_period, sync_binlog_counter; extern ulong expire_logs_days, sync_binlog_period, sync_binlog_counter;
extern my_bool relay_log_purge, opt_innodb_safe_binlog; extern my_bool relay_log_purge, opt_innodb_safe_binlog;
......
...@@ -316,6 +316,8 @@ ulong slave_net_timeout, slave_trans_retries; ...@@ -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 thread_cache_size=0, binlog_cache_size=0, max_binlog_cache_size=0;
ulong query_cache_size=0; ulong query_cache_size=0;
ulong com_stat[(uint) SQLCOM_END], com_other; 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 bytes_sent, bytes_received, net_big_packet_count;
ulong refresh_version, flush_version; /* Increments on each reload */ ulong refresh_version, flush_version; /* Increments on each reload */
ulong query_id, long_query_count; ulong query_id, long_query_count;
...@@ -5474,6 +5476,11 @@ struct show_var_st status_vars[]= { ...@@ -5474,6 +5476,11 @@ struct show_var_st status_vars[]= {
{"Com_show_warnings", (char*) (com_stat+(uint) SQLCOM_SHOW_WARNS),SHOW_LONG}, {"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_start", (char*) (com_stat+(uint) SQLCOM_SLAVE_START),SHOW_LONG},
{"Com_slave_stop", (char*) (com_stat+(uint) SQLCOM_SLAVE_STOP),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_truncate", (char*) (com_stat+(uint) SQLCOM_TRUNCATE),SHOW_LONG},
{"Com_unlock_tables", (char*) (com_stat+(uint) SQLCOM_UNLOCK_TABLES),SHOW_LONG}, {"Com_unlock_tables", (char*) (com_stat+(uint) SQLCOM_UNLOCK_TABLES),SHOW_LONG},
{"Com_update", (char*) (com_stat+(uint) SQLCOM_UPDATE),SHOW_LONG}, {"Com_update", (char*) (com_stat+(uint) SQLCOM_UPDATE),SHOW_LONG},
......
...@@ -59,7 +59,6 @@ static void remove_escape(char *name); ...@@ -59,7 +59,6 @@ static void remove_escape(char *name);
static void refresh_status(void); static void refresh_status(void);
static bool append_file_to_dir(THD *thd, const char **filename_ptr, static bool append_file_to_dir(THD *thd, const char **filename_ptr,
const char *table_name); const char *table_name);
static void log_slow_query(THD *thd);
const char *any_db="*any*"; // Special symbol for check_access const char *any_db="*any*"; // Special symbol for check_access
...@@ -1515,7 +1514,7 @@ bool dispatch_command(enum enum_server_command command, THD *thd, ...@@ -1515,7 +1514,7 @@ bool dispatch_command(enum enum_server_command command, THD *thd,
#endif #endif
ulong length= (ulong)(packet_end-packet); ulong length= (ulong)(packet_end-packet);
log_slow_query(thd); log_slow_statement(thd);
/* Remove garbage at start of query */ /* Remove garbage at start of query */
while (my_isspace(thd->charset(), *packet) && length > 0) while (my_isspace(thd->charset(), *packet) && length > 0)
...@@ -1827,7 +1826,7 @@ bool dispatch_command(enum enum_server_command command, THD *thd, ...@@ -1827,7 +1826,7 @@ bool dispatch_command(enum enum_server_command command, THD *thd,
if (thd->is_fatal_error) if (thd->is_fatal_error)
send_error(thd,0); // End of memory ? send_error(thd,0); // End of memory ?
log_slow_query(thd); log_slow_statement(thd);
thd->proc_info="cleaning up"; thd->proc_info="cleaning up";
VOID(pthread_mutex_lock(&LOCK_thread_count)); // For process list VOID(pthread_mutex_lock(&LOCK_thread_count)); // For process list
...@@ -1843,7 +1842,7 @@ bool dispatch_command(enum enum_server_command command, THD *thd, ...@@ -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; time_t start_of_query=thd->start_time;
thd->end_time(); // Set start time thd->end_time(); // Set start time
...@@ -2193,6 +2192,8 @@ mysql_execute_command(THD *thd) ...@@ -2193,6 +2192,8 @@ mysql_execute_command(THD *thd)
DBUG_PRINT("info", ("DEALLOCATE PREPARE: %.*s\n", DBUG_PRINT("info", ("DEALLOCATE PREPARE: %.*s\n",
lex->prepared_stmt_name.length, lex->prepared_stmt_name.length,
lex->prepared_stmt_name.str)); 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))) if ((stmt= thd->stmt_map.find_by_name(&lex->prepared_stmt_name)))
{ {
thd->stmt_map.erase(stmt); thd->stmt_map.erase(stmt);
......
...@@ -820,7 +820,8 @@ static bool insert_params_from_vars_with_log(Prepared_statement *stmt, ...@@ -820,7 +820,8 @@ static bool insert_params_from_vars_with_log(Prepared_statement *stmt,
DBUG_ENTER("insert_params_from_vars"); DBUG_ENTER("insert_params_from_vars");
List_iterator<LEX_STRING> var_it(varnames); List_iterator<LEX_STRING> var_it(varnames);
String str; String buf;
const String *val;
uint32 length= 0; uint32 length= 0;
if (query->copy(stmt->query, stmt->query_length, default_charset_info)) if (query->copy(stmt->query, stmt->query_length, default_charset_info))
DBUG_RETURN(1); DBUG_RETURN(1);
...@@ -831,32 +832,35 @@ static bool insert_params_from_vars_with_log(Prepared_statement *stmt, ...@@ -831,32 +832,35 @@ static bool insert_params_from_vars_with_log(Prepared_statement *stmt,
varname= var_it++; varname= var_it++;
if (get_var_with_binlog(stmt->thd, *varname, &entry)) if (get_var_with_binlog(stmt->thd, *varname, &entry))
DBUG_RETURN(1); DBUG_RETURN(1);
DBUG_ASSERT(entry);
if (param->set_from_user_var(stmt->thd, entry)) if (param->set_from_user_var(stmt->thd, entry))
DBUG_RETURN(1); DBUG_RETURN(1);
/* Insert @'escaped-varname' instead of parameter in the query */ /* Insert @'escaped-varname' instead of parameter in the query */
char *buf, *ptr; if (entry)
str.length(0); {
if (str.reserve(entry->name.length*2+3)) char *begin, *ptr;
DBUG_RETURN(1); buf.length(0);
if (buf.reserve(entry->name.length*2+3))
DBUG_RETURN(1);
buf= str.c_ptr_quick(); begin= ptr= buf.c_ptr_quick();
ptr= buf; *ptr++= '@';
*ptr++= '@'; *ptr++= '\'';
*ptr++= '\''; ptr+= escape_string_for_mysql(&my_charset_utf8_general_ci,
ptr+= ptr, entry->name.str, entry->name.length);
escape_string_for_mysql(&my_charset_utf8_general_ci, *ptr++= '\'';
ptr, entry->name.str, entry->name.length); buf.length(ptr - begin);
*ptr++= '\''; val= &buf;
str.length(ptr - buf); }
else
val= &my_null_string;
if (param->convert_str_value(stmt->thd)) if (param->convert_str_value(stmt->thd))
DBUG_RETURN(1); /* out of memory */ 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); DBUG_RETURN(1);
length+= str.length()-1; length+= val->length()-1;
} }
DBUG_RETURN(0); DBUG_RETURN(0);
} }
...@@ -1558,6 +1562,13 @@ int mysql_stmt_prepare(THD *thd, char *packet, uint packet_length, ...@@ -1558,6 +1562,13 @@ int mysql_stmt_prepare(THD *thd, char *packet, uint packet_length,
DBUG_PRINT("prep_query", ("%s", packet)); 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) if (stmt == 0)
{ {
send_error(thd, ER_OUT_OF_RESOURCES); send_error(thd, ER_OUT_OF_RESOURCES);
...@@ -1596,7 +1607,7 @@ int mysql_stmt_prepare(THD *thd, char *packet, uint packet_length, ...@@ -1596,7 +1607,7 @@ int mysql_stmt_prepare(THD *thd, char *packet, uint packet_length,
DBUG_RETURN(1); 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; thd->current_arena= stmt;
mysql_init_query(thd, (uchar *) thd->query, thd->query_length); 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) ...@@ -1763,6 +1774,7 @@ void mysql_stmt_execute(THD *thd, char *packet, uint packet_length)
packet+= 9; /* stmt_id + 5 bytes of flags */ 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", if (!(stmt= find_prepared_statement(thd, stmt_id, "mysql_stmt_execute",
SEND_ERROR))) SEND_ERROR)))
DBUG_VOID_RETURN; DBUG_VOID_RETURN;
...@@ -1796,9 +1808,6 @@ void mysql_stmt_execute(THD *thd, char *packet, uint packet_length) ...@@ -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)) if (stmt->param_count && stmt->set_params_data(stmt, &expanded_query))
goto set_params_data_err; goto set_params_data_err;
#endif #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 thd->protocol= &thd->protocol_prep; // Switch to binary protocol
execute_stmt(thd, stmt, &expanded_query, TRUE); execute_stmt(thd, stmt, &expanded_query, TRUE);
thd->protocol= &thd->protocol_simple; // Use normal protocol thd->protocol= &thd->protocol_simple; // Use normal protocol
...@@ -1827,6 +1836,8 @@ void mysql_sql_stmt_execute(THD *thd, LEX_STRING *stmt_name) ...@@ -1827,6 +1836,8 @@ void mysql_sql_stmt_execute(THD *thd, LEX_STRING *stmt_name)
String expanded_query; String expanded_query;
DBUG_ENTER("mysql_sql_stmt_execute"); 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))) if (!(stmt= (Prepared_statement*)thd->stmt_map.find_by_name(stmt_name)))
{ {
my_error(ER_UNKNOWN_STMT_HANDLER, MYF(0), stmt_name->length, 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) ...@@ -1853,6 +1864,7 @@ void mysql_sql_stmt_execute(THD *thd, LEX_STRING *stmt_name)
my_error(ER_WRONG_ARGUMENTS, MYF(0), "EXECUTE"); my_error(ER_WRONG_ARGUMENTS, MYF(0), "EXECUTE");
send_error(thd); send_error(thd);
} }
thd->command= COM_EXECUTE; /* For nice messages in general log */
execute_stmt(thd, stmt, &expanded_query, FALSE); execute_stmt(thd, stmt, &expanded_query, FALSE);
DBUG_VOID_RETURN; DBUG_VOID_RETURN;
} }
...@@ -1887,6 +1899,7 @@ static void execute_stmt(THD *thd, Prepared_statement *stmt, ...@@ -1887,6 +1899,7 @@ static void execute_stmt(THD *thd, Prepared_statement *stmt,
my_error(ER_OUTOFMEMORY, 0, expanded_query->length()); my_error(ER_OUTOFMEMORY, 0, expanded_query->length());
DBUG_VOID_RETURN; 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 At first execution of prepared statement we will perform logical
transformations of the query tree (i.e. negations elimination). transformations of the query tree (i.e. negations elimination).
...@@ -1900,6 +1913,14 @@ static void execute_stmt(THD *thd, Prepared_statement *stmt, ...@@ -1900,6 +1913,14 @@ static void execute_stmt(THD *thd, Prepared_statement *stmt,
thd->lex->unit.cleanup(); thd->lex->unit.cleanup();
if (!(specialflag & SPECIAL_NO_PRIOR)) if (!(specialflag & SPECIAL_NO_PRIOR))
my_pthread_setprio(pthread_self(), WAIT_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 that were created during this execution of the PS. */
free_items(thd->free_list); free_items(thd->free_list);
...@@ -1941,6 +1962,7 @@ void mysql_stmt_reset(THD *thd, char *packet) ...@@ -1941,6 +1962,7 @@ void mysql_stmt_reset(THD *thd, char *packet)
DBUG_ENTER("mysql_stmt_reset"); DBUG_ENTER("mysql_stmt_reset");
statistic_increment(com_stmt_reset, &LOCK_status);
if (!(stmt= find_prepared_statement(thd, stmt_id, "mysql_stmt_reset", if (!(stmt= find_prepared_statement(thd, stmt_id, "mysql_stmt_reset",
SEND_ERROR))) SEND_ERROR)))
DBUG_VOID_RETURN; DBUG_VOID_RETURN;
...@@ -1973,6 +1995,7 @@ void mysql_stmt_free(THD *thd, char *packet) ...@@ -1973,6 +1995,7 @@ void mysql_stmt_free(THD *thd, char *packet)
DBUG_ENTER("mysql_stmt_free"); DBUG_ENTER("mysql_stmt_free");
statistic_increment(com_stmt_close, &LOCK_status);
if (!(stmt= find_prepared_statement(thd, stmt_id, "mysql_stmt_close", if (!(stmt= find_prepared_statement(thd, stmt_id, "mysql_stmt_close",
DONT_SEND_ERROR))) DONT_SEND_ERROR)))
DBUG_VOID_RETURN; DBUG_VOID_RETURN;
...@@ -2012,6 +2035,7 @@ void mysql_stmt_get_longdata(THD *thd, char *packet, ulong packet_length) ...@@ -2012,6 +2035,7 @@ void mysql_stmt_get_longdata(THD *thd, char *packet, ulong packet_length)
DBUG_ENTER("mysql_stmt_get_longdata"); DBUG_ENTER("mysql_stmt_get_longdata");
statistic_increment(com_stmt_send_long_data, &LOCK_status);
#ifndef EMBEDDED_LIBRARY #ifndef EMBEDDED_LIBRARY
/* Minimal size of long data packet is 6 bytes */ /* Minimal size of long data packet is 6 bytes */
if ((ulong) (packet_end - packet) < MYSQL_LONG_DATA_HEADER) if ((ulong) (packet_end - packet) < MYSQL_LONG_DATA_HEADER)
...@@ -2068,10 +2092,12 @@ Prepared_statement::Prepared_statement(THD *thd_arg) ...@@ -2068,10 +2092,12 @@ Prepared_statement::Prepared_statement(THD *thd_arg)
*last_error= '\0'; *last_error= '\0';
} }
void Prepared_statement::setup_set_params() void Prepared_statement::setup_set_params()
{ {
/* Setup binary logging */ /* 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; set_params_from_vars= insert_params_from_vars_with_log;
#ifndef EMBEDDED_LIBRARY #ifndef EMBEDDED_LIBRARY
...@@ -2091,6 +2117,7 @@ void Prepared_statement::setup_set_params() ...@@ -2091,6 +2117,7 @@ void Prepared_statement::setup_set_params()
} }
} }
Prepared_statement::~Prepared_statement() Prepared_statement::~Prepared_statement()
{ {
free_items(free_list); free_items(free_list);
......
Markdown is supported
0%
or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment