From c0484a301f1dfdac6b63b25cf0e4697a2ad9d05c Mon Sep 17 00:00:00 2001 From: unknown Date: Fri, 17 Jun 2005 00:11:48 +0400 Subject: [PATCH] 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 | 2 +- sql/mysql_priv.h | 5 ++- sql/mysqld.cc | 7 ++++ sql/sql_parse.cc | 9 +++-- sql/sql_prepare.cc | 71 +++++++++++++++++++++++++----------- 5 files changed, 65 insertions(+), 29 deletions(-) diff --git a/mysql-test/r/ps_grant.result b/mysql-test/r/ps_grant.result index 0787f30c643..249fb2fe40f 100644 --- a/mysql-test/r/ps_grant.result +++ b/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 diff --git a/sql/mysql_priv.h b/sql/mysql_priv.h index e9e8b52270c..2bcaa1ecc2d 100644 --- a/sql/mysql_priv.h +++ b/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; diff --git a/sql/mysqld.cc b/sql/mysqld.cc index 951de53724f..ec05ea2b8ce 100644 --- a/sql/mysqld.cc +++ b/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}, diff --git a/sql/sql_parse.cc b/sql/sql_parse.cc index 4e714e70c5f..c107203b548 100644 --- a/sql/sql_parse.cc +++ b/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); diff --git a/sql/sql_prepare.cc b/sql/sql_prepare.cc index b57f88ac172..1f5bb04c802 100644 --- a/sql/sql_prepare.cc +++ b/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 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);