# name : slow_extended.patch # introduced : 11 or before # maintainer : Oleg # #!!! notice !!! # Any small change to this file in the main branch # should be done or reviewed by the maintainer! --- a/include/mysql/plugin_audit.h.pp +++ b/include/mysql/plugin_audit.h.pp @@ -186,6 +186,16 @@ char *thd_security_context(void* thd, char *buffer, unsigned int length, unsigned int max_query_len); void thd_inc_row_count(void* thd); +void increment_thd_innodb_stats(void* thd, + unsigned long long trx_id, + long io_reads, + long long io_read, + long io_reads_wait_timer, + long lock_que_wait_timer, + long que_wait_timer, + long page_access); +unsigned long thd_log_slow_verbosity(const void* thd); +int thd_opt_slow_log(); int mysql_tmpfile(const char *prefix); int thd_killed(const void* thd); unsigned long thd_get_thread_id(const void* thd); --- a/include/mysql/plugin_auth.h.pp +++ b/include/mysql/plugin_auth.h.pp @@ -186,6 +186,16 @@ char *thd_security_context(void* thd, char *buffer, unsigned int length, unsigned int max_query_len); void thd_inc_row_count(void* thd); +void increment_thd_innodb_stats(void* thd, + unsigned long long trx_id, + long io_reads, + long long io_read, + long io_reads_wait_timer, + long lock_que_wait_timer, + long que_wait_timer, + long page_access); +unsigned long thd_log_slow_verbosity(const void* thd); +int thd_opt_slow_log(); int mysql_tmpfile(const char *prefix); int thd_killed(const void* thd); unsigned long thd_get_thread_id(const void* thd); --- a/include/mysql/plugin_ftparser.h.pp +++ b/include/mysql/plugin_ftparser.h.pp @@ -139,6 +139,16 @@ char *thd_security_context(void* thd, char *buffer, unsigned int length, unsigned int max_query_len); void thd_inc_row_count(void* thd); +void increment_thd_innodb_stats(void* thd, + unsigned long long trx_id, + long io_reads, + long long io_read, + long io_reads_wait_timer, + long lock_que_wait_timer, + long que_wait_timer, + long page_access); +unsigned long thd_log_slow_verbosity(const void* thd); +int thd_opt_slow_log(); int mysql_tmpfile(const char *prefix); int thd_killed(const void* thd); unsigned long thd_get_thread_id(const void* thd); --- a/include/mysql/plugin.h +++ b/include/mysql/plugin.h @@ -545,6 +545,17 @@ /* Increments the row counter, see THD::row_count */ void thd_inc_row_count(MYSQL_THD thd); +void increment_thd_innodb_stats(MYSQL_THD thd, + unsigned long long trx_id, + long io_reads, + long long io_read, + long io_reads_wait_timer, + long lock_que_wait_timer, + long que_wait_timer, + long page_access); +unsigned long thd_log_slow_verbosity(const MYSQL_THD thd); +int thd_opt_slow_log(); +#define EXTENDED_SLOWLOG /** Create a temporary file. --- /dev/null +++ b/patch_info/slow_extended.info @@ -0,0 +1,25 @@ +File=slow_extended.patch +Name=Extended statistics in slow.log (not InnoDB part) +Version=1.3 +Author=Percona +License=GPL +Comment= +Changelog +2008-11-26 +YK: Fix inefficient determination of trx, Make not to call useless gettimeofday when don't use slow log. Make log_slow_queries dynamic (bool). + +2008-11-07 +VT: Moved log_slow_rate_limit in SHOW VARIABLE into right place + +2008-11 +Arjen Lentz: Fixups (backward compatibility) by Arjen Lentz + +2010-07 +1) Fix overflow of query time and lock time (Bug 600360) (slow_extended_fix_overflow.patch merged) +2) Control global slow feature merged (control_global_slow.patch merged) +3) Microseconds in slow query log merged (microseconds_in_slow_query_log.patch merged) +4) Now use_global_long_query_time and use_global_log_slow_control are synonims. Add value "all" for use_global_log_slow_control (contol-global_slow-2.patch merged) +5) Fix innodb_stats on replication (Bug 600684) +6) Change variable types (system/command-line) +2011-01 +Patch profiling_slow.patch was merged --- a/scripts/mysqldumpslow.sh +++ b/scripts/mysqldumpslow.sh @@ -102,8 +102,8 @@ s/^#? Time: \d{6}\s+\d+:\d+:\d+.*\n//; my ($user,$host) = s/^#? User\@Host:\s+(\S+)\s+\@\s+(\S+).*\n// ? ($1,$2) : ('',''); - s/^# Query_time: ([0-9.]+)\s+Lock_time: ([0-9.]+)\s+Rows_sent: ([0-9.]+).*\n//; - my ($t, $l, $r) = ($1, $2, $3); + s/^# Query_time: (\d+(\.\d+)?) Lock_time: (\d+(\.\d+)?) Rows_sent: (\d+(\.\d+)?).*\n//; + my ($t, $l, $r) = ($1, $3, $5); $t -= $l unless $opt{l}; # remove fluff that mysqld writes to log when it (re)starts: --- a/sql/event_scheduler.cc +++ b/sql/event_scheduler.cc @@ -195,6 +195,7 @@ thd->client_capabilities|= CLIENT_MULTI_RESULTS; mysql_mutex_lock(&LOCK_thread_count); thd->thread_id= thd->variables.pseudo_thread_id= thread_id++; + thd->write_to_slow_log= true; mysql_mutex_unlock(&LOCK_thread_count); /* --- a/sql/filesort.cc +++ b/sql/filesort.cc @@ -193,6 +193,7 @@ { status_var_increment(thd->status_var.filesort_scan_count); } + thd->query_plan_flags|= QPLAN_FILESORT; #ifdef CAN_TRUST_RANGE if (select && select->quick && select->quick->records > 0L) { @@ -261,6 +262,7 @@ /* filesort cannot handle zero-length records during merge. */ DBUG_ASSERT(param.sort_length != 0); + thd->query_plan_flags|= QPLAN_FILESORT_DISK; if (table_sort.buffpek && table_sort.buffpek_len < maxbuffer) { my_free(table_sort.buffpek); @@ -1209,6 +1211,7 @@ DBUG_ENTER("merge_buffers"); status_var_increment(current_thd->status_var.filesort_merge_passes); + current_thd->query_plan_fsort_passes++; if (param->not_killable) { killed= ¬_killable; --- a/sql/log.cc +++ b/sql/log.cc @@ -715,11 +715,13 @@ */ bool Log_to_csv_event_handler:: - log_slow(THD *thd, time_t current_time, time_t query_start_arg, + log_slow(THD *thd, ulonglong current_utime, time_t query_start_arg, const char *user_host, uint user_host_len, ulonglong query_utime, ulonglong lock_utime, bool is_command, const char *sql_text, uint sql_text_len) { + time_t current_time= my_time_possible_from_micro(current_utime); + TABLE_LIST table_list; TABLE *table; bool result= TRUE; @@ -935,14 +937,14 @@ /** Wrapper around MYSQL_LOG::write() for slow log. */ bool Log_to_file_event_handler:: - log_slow(THD *thd, time_t current_time, time_t query_start_arg, + log_slow(THD *thd, ulonglong current_utime, time_t query_start_arg, const char *user_host, uint user_host_len, ulonglong query_utime, ulonglong lock_utime, bool is_command, const char *sql_text, uint sql_text_len) { Silence_log_table_errors error_handler; thd->push_internal_handler(&error_handler); - bool retval= mysql_slow_log.write(thd, current_time, query_start_arg, + bool retval= mysql_slow_log.write(thd, current_utime, query_start_arg, user_host, user_host_len, query_utime, lock_utime, is_command, sql_text, sql_text_len); @@ -1200,8 +1202,6 @@ if (*slow_log_handler_list) { - time_t current_time; - /* do not log slow queries from replication threads */ if (thd->slave_thread && !opt_log_slow_slave_statements) return 0; @@ -1216,16 +1216,29 @@ /* fill in user_host value: the format is "%s[%s] @ %s [%s]" */ user_host_len= (strxnmov(user_host_buff, MAX_USER_HOST_SIZE, sctx->priv_user ? sctx->priv_user : "", "[", - sctx->user ? sctx->user : "", "] @ ", + sctx->user ? sctx->user : (thd->slave_thread ? "SQL_SLAVE" : ""), "] @ ", sctx->host ? sctx->host : "", " [", sctx->ip ? sctx->ip : "", "]", NullS) - user_host_buff); - current_time= my_time_possible_from_micro(current_utime); if (thd->start_utime) { - query_utime= (current_utime - thd->start_utime); - lock_utime= (thd->utime_after_lock - thd->start_utime); + if(current_utime < thd->start_utime) + { + query_utime= 0; + } + else + { + query_utime= (current_utime - thd->start_utime); + } + if(thd->utime_after_lock < thd->start_utime) + { + lock_utime= 0; + } + else + { + lock_utime= (thd->utime_after_lock - thd->start_utime); + } } else { @@ -1240,7 +1253,7 @@ } for (current_handler= slow_log_handler_list; *current_handler ;) - error= (*current_handler++)->log_slow(thd, current_time, thd->start_time, + error= (*current_handler++)->log_slow(thd, current_utime, thd->start_time, user_host_buff, user_host_len, query_utime, lock_utime, is_command, query, query_length) || error; @@ -2656,12 +2669,13 @@ TRUE - error occured */ -bool MYSQL_QUERY_LOG::write(THD *thd, time_t current_time, +bool MYSQL_QUERY_LOG::write(THD *thd, ulonglong current_utime, time_t query_start_arg, const char *user_host, uint user_host_len, ulonglong query_utime, ulonglong lock_utime, bool is_command, const char *sql_text, uint sql_text_len) { + time_t current_time= my_time_possible_from_micro(current_utime); bool error= 0; DBUG_ENTER("MYSQL_QUERY_LOG::write"); @@ -2683,17 +2697,28 @@ if (!(specialflag & SPECIAL_SHORT_LOG_FORMAT)) { - if (current_time != last_time) + if (opt_slow_query_log_timestamp_always || current_time != last_time) { last_time= current_time; struct tm start; localtime_r(¤t_time, &start); - - buff_len= my_snprintf(buff, sizeof buff, - "# Time: %02d%02d%02d %2d:%02d:%02d\n", - start.tm_year % 100, start.tm_mon + 1, - start.tm_mday, start.tm_hour, - start.tm_min, start.tm_sec); + if(opt_slow_query_log_timestamp_precision & SLOG_MICROSECOND) + { + ulonglong microsecond = current_utime % (1000 * 1000); + buff_len= snprintf(buff, sizeof buff, + "# Time: %02d%02d%02d %2d:%02d:%02d.%010lld\n", + start.tm_year % 100, start.tm_mon + 1, + start.tm_mday, start.tm_hour, + start.tm_min, start.tm_sec,microsecond); + } + else + { + buff_len= my_snprintf(buff, sizeof buff, + "# Time: %02d%02d%02d %2d:%02d:%02d\n", + start.tm_year % 100, start.tm_mon + 1, + start.tm_mday, start.tm_hour, + start.tm_min, start.tm_sec); + } /* Note that my_b_write() assumes it knows the length for this */ if (my_b_write(&log_file, (uchar*) buff, buff_len)) @@ -2710,13 +2735,71 @@ /* For slow query log */ sprintf(query_time_buff, "%.6f", ulonglong2double(query_utime)/1000000.0); sprintf(lock_time_buff, "%.6f", ulonglong2double(lock_utime)/1000000.0); + DBUG_PRINT("info", ("Last_errno: %u", thd->last_errno)); if (my_b_printf(&log_file, - "# Query_time: %s Lock_time: %s" - " Rows_sent: %lu Rows_examined: %lu\n", + "# Thread_id: %lu Schema: %s Last_errno: %u Killed: %u\n" \ + "# Query_time: %s Lock_time: %s Rows_sent: %lu Rows_examined: %lu Rows_affected: %lu Rows_read: %lu\n" + "# Bytes_sent: %lu Tmp_tables: %lu Tmp_disk_tables: %lu Tmp_table_sizes: %lu\n", + (ulong) thd->thread_id, (thd->db ? thd->db : ""), + thd->last_errno, (uint) thd->killed, query_time_buff, lock_time_buff, (ulong) thd->sent_row_count, - (ulong) thd->examined_row_count) == (uint) -1) + (ulong) thd->examined_row_count, + ((long) thd->get_row_count_func() > 0 ) ? (ulong) thd->get_row_count_func() : 0, + (ulong) thd->sent_row_count, + (ulong) (thd->status_var.bytes_sent - thd->bytes_sent_old), + (ulong) thd->tmp_tables_used, + (ulong) thd->tmp_tables_disk_used, + (ulong) thd->tmp_tables_size) == (uint) -1) tmp_errno= errno; + +#if defined(ENABLED_PROFILING) + thd->profiling.print_current(&log_file); +#endif + if (thd->innodb_was_used) + { + char buf[20]; + snprintf(buf, 20, "%llX", thd->innodb_trx_id); + if (my_b_printf(&log_file, + "# InnoDB_trx_id: %s\n", buf) == (uint) -1) + tmp_errno=errno; + } + if ((thd->variables.log_slow_verbosity & (ULL(1) << SLOG_V_QUERY_PLAN)) && + my_b_printf(&log_file, + "# QC_Hit: %s Full_scan: %s Full_join: %s Tmp_table: %s Tmp_table_on_disk: %s\n" \ + "# Filesort: %s Filesort_on_disk: %s Merge_passes: %lu\n", + ((thd->query_plan_flags & QPLAN_QC) ? "Yes" : "No"), + ((thd->query_plan_flags & QPLAN_FULL_SCAN) ? "Yes" : "No"), + ((thd->query_plan_flags & QPLAN_FULL_JOIN) ? "Yes" : "No"), + ((thd->query_plan_flags & QPLAN_TMP_TABLE) ? "Yes" : "No"), + ((thd->query_plan_flags & QPLAN_TMP_DISK) ? "Yes" : "No"), + ((thd->query_plan_flags & QPLAN_FILESORT) ? "Yes" : "No"), + ((thd->query_plan_flags & QPLAN_FILESORT_DISK) ? "Yes" : "No"), + thd->query_plan_fsort_passes) == (uint) -1) + tmp_errno=errno; + if ((thd->variables.log_slow_verbosity & (ULL(1) << SLOG_V_INNODB)) && thd->innodb_was_used) + { + char buf[3][20]; + snprintf(buf[0], 20, "%.6f", thd->innodb_io_reads_wait_timer / 1000000.0); + snprintf(buf[1], 20, "%.6f", thd->innodb_lock_que_wait_timer / 1000000.0); + snprintf(buf[2], 20, "%.6f", thd->innodb_innodb_que_wait_timer / 1000000.0); + if (my_b_printf(&log_file, + "# InnoDB_IO_r_ops: %lu InnoDB_IO_r_bytes: %lu InnoDB_IO_r_wait: %s\n" \ + "# InnoDB_rec_lock_wait: %s InnoDB_queue_wait: %s\n" \ + "# InnoDB_pages_distinct: %lu\n", + (ulong) thd->innodb_io_reads, + (ulong) thd->innodb_io_read, + buf[0], buf[1], buf[2], + (ulong) thd->innodb_page_access) == (uint) -1) + tmp_errno=errno; + } + else + { + if ((thd->variables.log_slow_verbosity & (ULL(1) << SLOG_V_INNODB)) && + my_b_printf(&log_file,"# No InnoDB statistics available for this query\n") == (uint) -1) + tmp_errno=errno; + } + if (thd->db && strcmp(thd->db, db)) { // Database changed if (my_b_printf(&log_file,"use %s;\n",thd->db) == (uint) -1) --- a/sql/log.h +++ b/sql/log.h @@ -242,7 +242,7 @@ uint user_host_len, int thread_id, const char *command_type, uint command_type_len, const char *sql_text, uint sql_text_len); - bool write(THD *thd, time_t current_time, time_t query_start_arg, + bool write(THD *thd, ulonglong current_time, time_t query_start_arg, const char *user_host, uint user_host_len, ulonglong query_utime, ulonglong lock_utime, bool is_command, const char *sql_text, uint sql_text_len); @@ -517,7 +517,7 @@ virtual bool init()= 0; virtual void cleanup()= 0; - virtual bool log_slow(THD *thd, time_t current_time, + virtual bool log_slow(THD *thd, ulonglong current_time, time_t query_start_arg, const char *user_host, uint user_host_len, ulonglong query_utime, ulonglong lock_utime, bool is_command, @@ -546,7 +546,7 @@ virtual bool init(); virtual void cleanup(); - virtual bool log_slow(THD *thd, time_t current_time, + virtual bool log_slow(THD *thd, ulonglong current_utime, time_t query_start_arg, const char *user_host, uint user_host_len, ulonglong query_utime, ulonglong lock_utime, bool is_command, @@ -578,7 +578,7 @@ virtual bool init(); virtual void cleanup(); - virtual bool log_slow(THD *thd, time_t current_time, + virtual bool log_slow(THD *thd, ulonglong current_utime, time_t query_start_arg, const char *user_host, uint user_host_len, ulonglong query_utime, ulonglong lock_utime, bool is_command, --- a/sql/mysqld.cc +++ b/sql/mysqld.cc @@ -421,6 +421,11 @@ char* opt_secure_file_priv; my_bool opt_log_slow_admin_statements= 0; my_bool opt_log_slow_slave_statements= 0; +my_bool opt_log_slow_sp_statements= 0; +my_bool opt_slow_query_log_timestamp_always= 0; +ulonglong opt_slow_query_log_use_global_control= 0; +ulong opt_slow_query_log_timestamp_precision= 0; +ulong opt_slow_query_log_rate_type= 0; my_bool lower_case_file_system= 0; my_bool opt_large_pages= 0; my_bool opt_super_large_pages= 0; @@ -5892,14 +5897,10 @@ "Don't log extra information to update and slow-query logs.", &opt_short_log_format, &opt_short_log_format, 0, GET_BOOL, NO_ARG, 0, 0, 0, 0, 0, 0}, - {"log-slow-admin-statements", 0, - "Log slow OPTIMIZE, ANALYZE, ALTER and other administrative statements to " - "the slow log if it is open.", &opt_log_slow_admin_statements, - &opt_log_slow_admin_statements, 0, GET_BOOL, NO_ARG, 0, 0, 0, 0, 0, 0}, - {"log-slow-slave-statements", 0, + /*{"log-slow-slave-statements", 0, "Log slow statements executed by slave thread to the slow log if it is open.", &opt_log_slow_slave_statements, &opt_log_slow_slave_statements, - 0, GET_BOOL, NO_ARG, 0, 0, 0, 0, 0, 0}, + 0, GET_BOOL, NO_ARG, 0, 0, 0, 0, 0, 0},*/ {"log-slow-queries", OPT_SLOW_QUERY_LOG, "Log slow queries to a table or log file. Defaults logging to table " "mysql.slow_log or hostname-slow.log if --log-output=file is used. " @@ -7288,6 +7289,10 @@ C_MODE_END +/* defined in sys_vars.cc */ +extern void init_log_slow_verbosity(); +extern void init_slow_query_log_use_global_control(); + /** Get server options from the command line, and perform related server initializations. @@ -7437,6 +7442,8 @@ global_system_variables.long_query_time= (ulonglong) (global_system_variables.long_query_time_double * 1e6); + init_log_slow_verbosity(); + init_slow_query_log_use_global_control(); if (opt_short_log_format) opt_specialflag|= SPECIAL_SHORT_LOG_FORMAT; --- a/sql/mysqld.h +++ b/sql/mysqld.h @@ -116,6 +116,11 @@ extern char* opt_secure_backup_file_priv; extern size_t opt_secure_backup_file_priv_len; extern my_bool opt_log_slow_admin_statements, opt_log_slow_slave_statements; +extern my_bool opt_log_slow_sp_statements; +extern my_bool opt_slow_query_log_timestamp_always; +extern ulonglong opt_slow_query_log_use_global_control; +extern ulong opt_slow_query_log_timestamp_precision; +extern ulong opt_slow_query_log_rate_type; extern my_bool sp_automatic_privileges, opt_noacl; extern my_bool opt_old_style_user_limits, trust_function_creators; extern uint opt_crash_binlog_innodb; --- a/sql/slave.cc +++ b/sql/slave.cc @@ -2038,6 +2038,7 @@ + MAX_LOG_EVENT_HEADER; /* note, incr over the global not session var */ thd->slave_thread = 1; thd->enable_slow_log= opt_log_slow_slave_statements; + thd->write_to_slow_log= opt_log_slow_slave_statements; set_slave_thread_options(thd); thd->client_capabilities = CLIENT_LOCAL_FILES; mysql_mutex_lock(&LOCK_thread_count); --- a/sql/sp_head.cc +++ b/sql/sp_head.cc @@ -2164,7 +2164,7 @@ DBUG_PRINT("info",(" %.*s: eval args done", (int) m_name.length, m_name.str)); } - if (!(m_flags & LOG_SLOW_STATEMENTS) && thd->enable_slow_log) + if (!(m_flags & LOG_SLOW_STATEMENTS || opt_log_slow_sp_statements) && thd->enable_slow_log) { DBUG_PRINT("info", ("Disabling slow log for the execution")); save_enable_slow_log= true; --- a/sql/sql_cache.cc +++ b/sql/sql_cache.cc @@ -1780,6 +1780,7 @@ response, we can't handle it anyway. */ (void) trans_commit_stmt(thd); + thd->query_plan_flags|= QPLAN_QC; if (!thd->stmt_da->is_set()) thd->stmt_da->disable_status(); @@ -1790,6 +1791,7 @@ err_unlock: unlock(); err: + thd->query_plan_flags|= QPLAN_QC_NO; MYSQL_QUERY_CACHE_MISS(thd->query()); DBUG_RETURN(0); // Query was not cached } --- a/sql/sql_class.cc +++ b/sql/sql_class.cc @@ -616,6 +616,37 @@ thd->warning_info->inc_current_row_for_warning(); } +extern "C" +void increment_thd_innodb_stats(THD* thd, + unsigned long long trx_id, + long io_reads, + long long io_read, + long io_reads_wait_timer, + long lock_que_wait_timer, + long que_wait_timer, + long page_access) +{ + thd->innodb_was_used= TRUE; + thd->innodb_trx_id= trx_id; + thd->innodb_io_reads+= io_reads; + thd->innodb_io_read+= io_read; + thd->innodb_io_reads_wait_timer+= io_reads_wait_timer; + thd->innodb_lock_que_wait_timer+= lock_que_wait_timer; + thd->innodb_innodb_que_wait_timer+= que_wait_timer; + thd->innodb_page_access+= page_access; +} + +extern "C" +unsigned long thd_log_slow_verbosity(const THD *thd) +{ + return (unsigned long) thd->variables.log_slow_verbosity; +} + +extern "C" +int thd_opt_slow_log() +{ + return (int) opt_slow_log; +} /** Dumps a text description of a thread, its security context @@ -942,6 +973,8 @@ const char* msg, MYSQL_ERROR ** cond_hdl) { + last_errno= sql_errno; + if (!m_internal_handler) { *cond_hdl= NULL; @@ -1236,6 +1269,8 @@ /* Initialize the Debug Sync Facility. See debug_sync.cc. */ debug_sync_init_thread(this); #endif /* defined(ENABLED_DEBUG_SYNC) */ + + clear_slow_extended(); } @@ -3687,8 +3722,6 @@ backup->in_sub_stmt= in_sub_stmt; backup->enable_slow_log= enable_slow_log; backup->limit_found_rows= limit_found_rows; - backup->examined_row_count= examined_row_count; - backup->sent_row_count= sent_row_count; backup->cuted_fields= cuted_fields; backup->client_capabilities= client_capabilities; backup->savepoints= transaction.savepoints; @@ -3696,6 +3729,7 @@ first_successful_insert_id_in_prev_stmt; backup->first_successful_insert_id_in_cur_stmt= first_successful_insert_id_in_cur_stmt; + reset_sub_statement_state_slow_extended(backup); if ((!lex->requires_prelocking() || is_update_query(lex->sql_command)) && !is_current_stmt_binlog_format_row()) @@ -3711,13 +3745,74 @@ /* Disable result sets */ client_capabilities &= ~CLIENT_MULTI_RESULTS; in_sub_stmt|= new_state; - examined_row_count= 0; - sent_row_count= 0; cuted_fields= 0; transaction.savepoints= 0; first_successful_insert_id_in_cur_stmt= 0; } +void THD::clear_slow_extended() +{ + DBUG_ENTER("THD::clear_slow_extended"); + sent_row_count= 0; + examined_row_count= 0; + bytes_sent_old= status_var.bytes_sent; + tmp_tables_used= 0; + tmp_tables_disk_used= 0; + tmp_tables_size= 0; + innodb_was_used= FALSE; + innodb_trx_id= 0; + innodb_io_reads= 0; + innodb_io_read= 0; + innodb_io_reads_wait_timer= 0; + innodb_lock_que_wait_timer= 0; + innodb_innodb_que_wait_timer= 0; + innodb_page_access= 0; + query_plan_flags= QPLAN_NONE; + query_plan_fsort_passes= 0; + last_errno= 0; + DBUG_VOID_RETURN; +} + +void THD::reset_sub_statement_state_slow_extended(Sub_statement_state *backup) +{ + DBUG_ENTER("THD::reset_sub_statement_state_slow_extended"); + backup->sent_row_count= sent_row_count; + backup->examined_row_count= examined_row_count; + backup->tmp_tables_used= tmp_tables_used; + backup->tmp_tables_disk_used= tmp_tables_disk_used; + backup->tmp_tables_size= tmp_tables_size; + backup->innodb_was_used= innodb_was_used; + backup->innodb_io_reads= innodb_io_reads; + backup->innodb_io_read= innodb_io_read; + backup->innodb_io_reads_wait_timer= innodb_io_reads_wait_timer; + backup->innodb_lock_que_wait_timer= innodb_lock_que_wait_timer; + backup->innodb_innodb_que_wait_timer= innodb_innodb_que_wait_timer; + backup->innodb_page_access= innodb_page_access; + backup->query_plan_flags= query_plan_flags; + backup->query_plan_fsort_passes= query_plan_fsort_passes; + clear_slow_extended(); + DBUG_VOID_RETURN; +} + +void THD::restore_sub_statement_state_slow_extended(const Sub_statement_state *backup) +{ + DBUG_ENTER("THD::restore_sub_statement_state_slow_extended"); + sent_row_count= backup->sent_row_count; + examined_row_count+= backup->examined_row_count; + tmp_tables_used+= backup->tmp_tables_used; + tmp_tables_disk_used+= backup->tmp_tables_disk_used; + tmp_tables_size+= backup->tmp_tables_size; + innodb_was_used= (innodb_was_used || backup->innodb_was_used); + innodb_io_reads+= backup->innodb_io_reads; + innodb_io_read+= backup->innodb_io_read; + innodb_io_reads_wait_timer+= backup->innodb_io_reads_wait_timer; + innodb_lock_que_wait_timer+= backup->innodb_lock_que_wait_timer; + innodb_innodb_que_wait_timer+= backup->innodb_innodb_que_wait_timer; + innodb_page_access+= backup->innodb_page_access; + query_plan_flags|= backup->query_plan_flags; + query_plan_fsort_passes+= backup->query_plan_fsort_passes; + DBUG_VOID_RETURN; +} void THD::restore_sub_statement_state(Sub_statement_state *backup) { @@ -3758,7 +3853,6 @@ first_successful_insert_id_in_cur_stmt= backup->first_successful_insert_id_in_cur_stmt; limit_found_rows= backup->limit_found_rows; - sent_row_count= backup->sent_row_count; client_capabilities= backup->client_capabilities; /* If we've left sub-statement mode, reset the fatal error flag. @@ -3776,8 +3870,8 @@ The following is added to the old values as we are interested in the total complexity of the query */ - examined_row_count+= backup->examined_row_count; cuted_fields+= backup->cuted_fields; + restore_sub_statement_state_slow_extended(backup); DBUG_VOID_RETURN; } @@ -3802,7 +3896,7 @@ { mysql_mutex_lock(&LOCK_thd_data); set_query_inner(query_arg, query_length_arg, cs); - query_id= new_query_id; + do_set_query_id(new_query_id); mysql_mutex_unlock(&LOCK_thd_data); } @@ -3811,9 +3905,25 @@ void THD::set_query_id(query_id_t new_query_id) { mysql_mutex_lock(&LOCK_thd_data); - query_id= new_query_id; + do_set_query_id(new_query_id); mysql_mutex_unlock(&LOCK_thd_data); } +void THD::do_set_query_id(query_id_t new_query_id) +{ +#ifndef DBUG_OFF + if (variables.query_exec_id != 0 && + lex->sql_command != SQLCOM_SET_OPTION) + { + new_query_id= variables.query_exec_id; + } +#endif /* DBUG_OFF */ + query_id= new_query_id; + if (opt_slow_query_log_rate_type == SLOG_RT_QUERY) + { + const ulong& limit= variables.log_slow_rate_limit; + write_to_slow_log= limit == 0 || (query_id % limit) == 0; + } +} /** Assign a new value to thd->mysys_var. */ void THD::set_mysys_var(struct st_my_thread_var *new_mysys_var) --- a/sql/sql_class.h +++ b/sql/sql_class.h @@ -60,6 +60,36 @@ enum enum_duplicates { DUP_ERROR, DUP_REPLACE, DUP_UPDATE }; enum enum_delay_key_write { DELAY_KEY_WRITE_NONE, DELAY_KEY_WRITE_ON, DELAY_KEY_WRITE_ALL }; +enum enum_slow_query_log_use_global_control { + SLOG_UG_LOG_SLOW_FILTER, SLOG_UG_LOG_SLOW_RATE_LIMIT + , SLOG_UG_LOG_SLOW_VERBOSITY, SLOG_UG_LONG_QUERY_TIME + , SLOG_UG_MIN_EXAMINED_ROW_LIMIT, SLOG_UG_ALL +}; +enum enum_log_slow_verbosity { + SLOG_V_MICROTIME, SLOG_V_QUERY_PLAN, SLOG_V_INNODB, + SLOG_V_PROFILING, SLOG_V_PROFILING_USE_GETRUSAGE, + SLOG_V_MINIMAL, SLOG_V_STANDARD, SLOG_V_FULL +}; +enum enum_slow_query_log_timestamp_precision { + SLOG_SECOND, SLOG_MICROSECOND +}; +enum enum_slow_query_log_rate_type { + SLOG_RT_SESSION, SLOG_RT_QUERY +}; +#define QPLAN_NONE 0 +#define QPLAN_QC 1 << 0 +#define QPLAN_QC_NO 1 << 1 +#define QPLAN_FULL_SCAN 1 << 2 +#define QPLAN_FULL_JOIN 1 << 3 +#define QPLAN_TMP_TABLE 1 << 4 +#define QPLAN_TMP_DISK 1 << 5 +#define QPLAN_FILESORT 1 << 6 +#define QPLAN_FILESORT_DISK 1 << 7 +enum enum_log_slow_filter { + SLOG_F_QC_NO, SLOG_F_FULL_SCAN, SLOG_F_FULL_JOIN, + SLOG_F_TMP_TABLE, SLOG_F_TMP_DISK, SLOG_F_FILESORT, + SLOG_F_FILESORT_DISK +}; enum enum_slave_exec_mode { SLAVE_EXEC_MODE_STRICT, SLAVE_EXEC_MODE_IDEMPOTENT, SLAVE_EXEC_MODE_LAST_BIT}; @@ -508,6 +538,22 @@ my_bool sysdate_is_now; +#ifndef DBUG_OFF + ulonglong query_exec_time; + double query_exec_time_double; + ulong query_exec_id; +#endif + ulong log_slow_rate_limit; + ulonglong log_slow_filter; + ulonglong log_slow_verbosity; + + ulong innodb_io_reads; + ulonglong innodb_io_read; + ulong innodb_io_reads_wait_timer; + ulong innodb_lock_que_wait_timer; + ulong innodb_innodb_que_wait_timer; + ulong innodb_page_access; + double long_query_time_double; } SV; @@ -1140,6 +1186,24 @@ uint in_sub_stmt; bool enable_slow_log; bool last_insert_id_used; + + /*** Following variables used in slow_extended.patch ***/ + ulong tmp_tables_used; + ulong tmp_tables_disk_used; + ulonglong tmp_tables_size; + + bool innodb_was_used; + ulong innodb_io_reads; + ulonglong innodb_io_read; + ulong innodb_io_reads_wait_timer; + ulong innodb_lock_que_wait_timer; + ulong innodb_innodb_que_wait_timer; + ulong innodb_page_access; + + ulong query_plan_flags; + ulong query_plan_fsort_passes; + /*** The variables above used in slow_extended.patch ***/ + SAVEPOINT *savepoints; enum enum_check_fields count_cuted_fields; }; @@ -1588,6 +1652,71 @@ thr_lock_type update_lock_default; Delayed_insert *di; + /*** Following variables used in slow_extended.patch ***/ + /* + Variable write_to_slow_log: + 1) initialized in + * sql_connect.cc (log_slow_rate_limit support) + * slave.cc (log_slow_slave_statements support) + 2) The variable is initialized on the thread startup and remains + constant afterwards. This will change when + LP #712396 ("log_slow_slave_statements not work on replication + threads without RESTART") is implemented. + 3) An implementation of LP #688646 ("Make query sampling possible by query") should use it. + */ + bool write_to_slow_log; + /* + Variable bytes_send_old saves value of thd->status_var.bytes_sent + before query execution. + */ + ulonglong bytes_sent_old; + /* + Variables tmp_tables_*** collect statistics about usage of temporary tables + */ + ulong tmp_tables_used; + ulong tmp_tables_disk_used; + ulonglong tmp_tables_size; + /* + Variable innodb_was_used shows used or not InnoDB engine in current query. + */ + bool innodb_was_used; + /* + Following Variables innodb_*** (is |should be) different from + default values only if (innodb_was_used==TRUE) + */ + ulonglong innodb_trx_id; + ulong innodb_io_reads; + ulonglong innodb_io_read; + ulong innodb_io_reads_wait_timer; + ulong innodb_lock_que_wait_timer; + ulong innodb_innodb_que_wait_timer; + ulong innodb_page_access; + + /* + Variable query_plan_flags collects information about query plan entites + used on query execution. + */ + ulong query_plan_flags; + /* + Variable query_plan_fsort_passes collects information about file sort passes + acquired during query execution. + */ + ulong query_plan_fsort_passes; + /* + Query can generate several errors/warnings during execution + (see THD::handle_condition comment in sql_class.h) + Variable last_errno contains the last error/warning acquired during + query execution. + */ + uint last_errno; + /*** The variables above used in slow_extended.patch ***/ + + /*** Following methods used in slow_extended.patch ***/ + void clear_slow_extended(); + void reset_sub_statement_state_slow_extended(Sub_statement_state *backup); + void restore_sub_statement_state_slow_extended(const Sub_statement_state *backup); + /*** The methods above used in slow_extended.patch ***/ + /* <> 0 if we are inside of trigger or stored function. */ uint in_sub_stmt; @@ -2784,6 +2913,9 @@ void set_query_and_id(char *query_arg, uint32 query_length_arg, CHARSET_INFO *cs, query_id_t new_query_id); void set_query_id(query_id_t new_query_id); +private: + void do_set_query_id(query_id_t new_query_id); +public: void set_open_tables(TABLE *open_tables_arg) { mysql_mutex_lock(&LOCK_thd_data); --- a/sql/sql_connect.cc +++ b/sql/sql_connect.cc @@ -721,6 +721,14 @@ MYSQL_CONNECTION_START(thd->thread_id, &thd->security_ctx->priv_user[0], (char *) thd->security_ctx->host_or_ip); + /* + If rate limiting of slow log writes is enabled, decide whether to log this + new thread's queries or not. Uses extremely simple algorithm. :) + */ + const ulong& limit= thd->variables.log_slow_rate_limit; + thd->write_to_slow_log= opt_slow_query_log_rate_type == SLOG_RT_SESSION && + (limit == 0 || (thd->thread_id % limit) == 0); + prepare_new_connection_state(thd); return FALSE; } --- a/sql/sql_parse.cc +++ b/sql/sql_parse.cc @@ -114,6 +114,7 @@ static bool execute_sqlcom_select(THD *thd, TABLE_LIST *all_tables); static void sql_kill(THD *thd, ulong id, bool only_kill_query); +static inline ulonglong get_query_exec_time(THD *thd, ulonglong cur_utime); const char *any_db="*any*"; // Special symbol for check_access @@ -890,6 +891,7 @@ the slow log only if opt_log_slow_admin_statements is set. */ thd->enable_slow_log= TRUE; + thd->clear_slow_extended(); thd->lex->sql_command= SQLCOM_END; /* to avoid confusing VIEW detectors */ thd->set_time(); if (!thd->is_valid_time()) @@ -1440,6 +1442,60 @@ DBUG_RETURN(error); } +/** + Calculate execution time for the current query. + + For debug builds, check the session value of query_exec_time + and if it is not zero, return it instead of the actual execution time. + + SET queries are ignored so that statements changing query_exec_time are not + affected by themselves. + + @param thd thread handle + @param lex current relative time in microseconds + + @return time in microseconds from utime_after_lock +*/ + +static inline ulonglong get_query_exec_time(THD *thd, ulonglong cur_utime) +{ + ulonglong res; +#ifndef DBUG_OFF + if (thd->variables.query_exec_time != 0) + res= thd->lex->sql_command != SQLCOM_SET_OPTION ? + thd->variables.query_exec_time : 0; + else +#endif + + res= cur_utime - thd->utime_after_lock; + + if (res > thd->variables.long_query_time) + thd->server_status|= SERVER_QUERY_WAS_SLOW; + else + thd->server_status&= ~SERVER_QUERY_WAS_SLOW; + + return res; +} + + +static inline void copy_global_to_session(THD *thd, ulong flag, + const ulong *val) +{ + my_ptrdiff_t offset = ((char *)val - (char *)&global_system_variables); + if (opt_slow_query_log_use_global_control & (1ULL << flag)) + *(ulong *)((char *) &thd->variables + offset) = *val; +} + + +static inline void copy_global_to_session(THD *thd, ulong flag, + const ulonglong *val) +{ + my_ptrdiff_t offset = ((char *)val - (char *)&global_system_variables); + if (opt_slow_query_log_use_global_control & (1ULL << flag)) + *(ulonglong *)((char *) &thd->variables + offset) = *val; +} + + void log_slow_statement(THD *thd) { @@ -1453,13 +1509,47 @@ if (unlikely(thd->in_sub_stmt)) DBUG_VOID_RETURN; // Don't set time for sub stmt + /* Follow the slow log filter configuration. */ + if (thd->variables.log_slow_filter != 0 && + (!(thd->variables.log_slow_filter & thd->query_plan_flags) || + ((thd->variables.log_slow_filter & SLOG_F_QC_NO) && + (thd->query_plan_flags & QPLAN_QC)))) + DBUG_VOID_RETURN; + + ulonglong end_utime_of_query= thd->current_utime(); + ulonglong query_exec_time= get_query_exec_time(thd, end_utime_of_query); + + /* + Low long_query_time value most likely means user is debugging stuff and even + though some thread's queries are not supposed to be logged b/c of the rate + limit, if one of them takes long enough (>= 1 second) it will be sensible + to make an exception and write to slow log anyway. + */ + + system_variables const &g= global_system_variables; + copy_global_to_session(thd, SLOG_UG_LOG_SLOW_FILTER, + &g.log_slow_filter); + copy_global_to_session(thd, SLOG_UG_LOG_SLOW_RATE_LIMIT, + &g.log_slow_rate_limit); + copy_global_to_session(thd, SLOG_UG_LOG_SLOW_VERBOSITY, + &g.log_slow_verbosity); + copy_global_to_session(thd, SLOG_UG_LONG_QUERY_TIME, + &g.long_query_time); + copy_global_to_session(thd, SLOG_UG_MIN_EXAMINED_ROW_LIMIT, + &g.min_examined_row_limit); + + /* Do not log this thread's queries due to rate limiting. */ + if (!thd->write_to_slow_log && (thd->variables.long_query_time >= 1000000 + || (ulong) query_exec_time < 1000000)) + DBUG_VOID_RETURN; + + /* Do not log administrative statements unless the appropriate option is set. */ if (thd->enable_slow_log) { - ulonglong end_utime_of_query= thd->current_utime(); thd_proc_info(thd, "logging slow query"); if (((thd->server_status & SERVER_QUERY_WAS_SLOW) || @@ -5368,7 +5459,8 @@ thd->stmt_da->reset_diagnostics_area(); thd->warning_info->reset_for_next_command(); thd->rand_used= 0; - thd->sent_row_count= thd->examined_row_count= 0; + + thd->clear_slow_extended(); thd->reset_current_stmt_binlog_format_row(); thd->binlog_unsafe_warning_flags= 0; --- a/sql/sql_select.cc +++ b/sql/sql_select.cc @@ -6912,7 +6912,10 @@ { join->thd->server_status|=SERVER_QUERY_NO_INDEX_USED; if (statistics) + { status_var_increment(join->thd->status_var.select_scan_count); + join->thd->query_plan_flags|= QPLAN_FULL_SCAN; + } } } else @@ -6926,7 +6929,10 @@ { join->thd->server_status|=SERVER_QUERY_NO_INDEX_USED; if (statistics) + { status_var_increment(join->thd->status_var.select_full_join_count); + join->thd->query_plan_flags|= QPLAN_FULL_JOIN; + } } } if (!table->no_keyread) @@ -10274,6 +10280,7 @@ (ulong) rows_limit,test(group))); status_var_increment(thd->status_var.created_tmp_tables); + thd->query_plan_flags|= QPLAN_TMP_TABLE; if (use_temp_pool && !(test_flags & TEST_KEEP_TMP_TABLES)) temp_pool_slot = bitmap_lock_set_next(&temp_pool); @@ -11175,6 +11182,7 @@ goto err; } status_var_increment(table->in_use->status_var.created_tmp_disk_tables); + table->in_use->query_plan_flags|= QPLAN_TMP_DISK; share->db_record_offset= 1; DBUG_RETURN(0); err: @@ -11193,6 +11201,14 @@ save_proc_info=thd->proc_info; thd_proc_info(thd, "removing tmp table"); + thd->tmp_tables_used++; + if (entry->file) + { + thd->tmp_tables_size += entry->file->stats.data_file_length; + if (entry->file->ht->db_type != DB_TYPE_HEAP) + thd->tmp_tables_disk_used++; + } + // Release latches since this can take a long time ha_release_temporary_latches(thd); --- a/sql/sql_show.cc +++ b/sql/sql_show.cc @@ -1950,8 +1950,17 @@ table->field[4]->store(command_name[tmp->command].str, command_name[tmp->command].length, cs); /* MYSQL_TIME */ - table->field[5]->store((longlong)(tmp->start_time ? - now - tmp->start_time : 0), FALSE); + longlong value_in_time_column= 0; + if(tmp->start_time) + { + value_in_time_column = (now - tmp->start_time); + if(value_in_time_column > now) + { + value_in_time_column= 0; + } + } + table->field[5]->store(value_in_time_column, FALSE); + /* STATE */ if ((val= thread_state_info(tmp))) { --- a/sql/sys_vars.cc +++ b/sql/sys_vars.cc @@ -972,6 +972,36 @@ NO_MUTEX_GUARD, NOT_IN_BINLOG, ON_CHECK(0), ON_UPDATE(update_cached_long_query_time)); +#ifndef DBUG_OFF +static bool update_cached_query_exec_time(sys_var *self, THD *thd, + enum_var_type type) +{ + if (type == OPT_SESSION) + thd->variables.query_exec_time= + double2ulonglong(thd->variables.query_exec_time_double * 1e6); + else + global_system_variables.query_exec_time= + double2ulonglong(global_system_variables.query_exec_time_double * 1e6); + return false; +} + +static Sys_var_double Sys_query_exec_time( + "query_exec_time", + "Pretend queries take this many seconds. When 0 (the default) use the " + "actual execution time. Used only for debugging.", + SESSION_VAR(query_exec_time_double), + NO_CMD_LINE, VALID_RANGE(0, LONG_TIMEOUT), DEFAULT(0), + NO_MUTEX_GUARD, IN_BINLOG, ON_CHECK(0), + ON_UPDATE(update_cached_query_exec_time)); +static Sys_var_ulong sys_query_exec_id( + "query_exec_id", + "Pretend queries take this query id. When 0 (the default) use the" + "actual query id. Used only for debugging.", + SESSION_VAR(query_exec_id), + NO_CMD_LINE, VALID_RANGE(0, ULONG_MAX), DEFAULT(0), BLOCK_SIZE(1), + NO_MUTEX_GUARD, IN_BINLOG); +#endif + static bool fix_low_prio_updates(sys_var *self, THD *thd, enum_var_type type) { if (type == OPT_SESSION) @@ -2898,6 +2928,134 @@ DEFAULT(FALSE), NO_MUTEX_GUARD, NOT_IN_BINLOG, ON_CHECK(0), ON_UPDATE(fix_log_state)); +const char *log_slow_filter_name[]= { "qc_miss", "full_scan", "full_join", + "tmp_table", "tmp_table_on_disk", "filesort", "filesort_on_disk", 0}; +static Sys_var_set Sys_log_slow_filter( + "log_slow_filter", + "Log only the queries that followed certain execution plan. " + "Multiple flags allowed in a comma-separated string. " + "[qc_miss, full_scan, full_join, tmp_table, tmp_table_on_disk, " + "filesort, filesort_on_disk]", + SESSION_VAR(log_slow_filter), CMD_LINE(REQUIRED_ARG), + log_slow_filter_name, DEFAULT(0)); +static Sys_var_ulong sys_log_slow_rate_limit( + "log_slow_rate_limit","Rate limit statement writes to slow log to only those from every (1/log_slow_rate_limit) session.", + SESSION_VAR(log_slow_rate_limit), CMD_LINE(REQUIRED_ARG), + VALID_RANGE(1, ULONG_MAX), DEFAULT(1), BLOCK_SIZE(1)); +const char* log_slow_verbosity_name[] = { + "microtime", "query_plan", "innodb", + "profiling", "profling_use_getrusage", + "minimal", "standard", "full", 0 +}; +static ulonglong update_log_slow_verbosity_replace(ulonglong value, ulonglong what, ulonglong by) +{ + if((value & what) == what) + { + value = value & (~what); + value = value | by; + } + return value; +} +void update_log_slow_verbosity(ulonglong* value_ptr) +{ + ulonglong &value = *value_ptr; + ulonglong microtime= ULL(1) << SLOG_V_MICROTIME; + ulonglong query_plan= ULL(1) << SLOG_V_QUERY_PLAN; + ulonglong innodb= ULL(1) << SLOG_V_INNODB; + ulonglong minimal= ULL(1) << SLOG_V_MINIMAL; + ulonglong standard= ULL(1) << SLOG_V_STANDARD; + ulonglong full= ULL(1) << SLOG_V_FULL; + value= update_log_slow_verbosity_replace(value,minimal,microtime); + value= update_log_slow_verbosity_replace(value,standard,microtime | query_plan); + value= update_log_slow_verbosity_replace(value,full,microtime | query_plan | innodb); +} +static bool update_log_slow_verbosity_helper(sys_var */*self*/, THD *thd, + enum_var_type type) +{ + if(type == OPT_SESSION) + { + update_log_slow_verbosity(&(thd->variables.log_slow_verbosity)); + } + else + { + update_log_slow_verbosity(&(global_system_variables.log_slow_verbosity)); + } + return false; +} +void init_slow_query_log_use_global_control() +{ + update_log_slow_verbosity(&(global_system_variables.log_slow_verbosity)); +} +static Sys_var_set Sys_log_slow_verbosity( + "log_slow_verbosity", + "Choose how verbose the messages to your slow log will be. " + "Multiple flags allowed in a comma-separated string. [microtime, query_plan, innodb, profiling, profiling_use_getrusage]", + SESSION_VAR(log_slow_verbosity), CMD_LINE(REQUIRED_ARG), + log_slow_verbosity_name, DEFAULT(SLOG_V_MICROTIME), + NO_MUTEX_GUARD, NOT_IN_BINLOG, ON_CHECK(0), + ON_UPDATE(update_log_slow_verbosity_helper)); +static Sys_var_mybool Sys_log_slow_slave_statements( + "log_slow_slave_statements", + "Log queries replayed be the slave SQL thread", + GLOBAL_VAR(opt_log_slow_slave_statements), CMD_LINE(OPT_ARG), + DEFAULT(FALSE)); +static Sys_var_mybool Sys_log_slow_admin_statements( + "log_slow_admin_statements", + "Log slow OPTIMIZE, ANALYZE, ALTER and other administrative statements" + " to the slow log if it is open.", + GLOBAL_VAR(opt_log_slow_admin_statements), CMD_LINE(OPT_ARG), + DEFAULT(FALSE)); +static Sys_var_mybool Sys_log_slow_sp_statements( + "log_slow_sp_statements", + "Log slow statements executed by stored procedure to the slow log if it is open.", + GLOBAL_VAR(opt_log_slow_sp_statements), CMD_LINE(OPT_ARG), + DEFAULT(TRUE)); +static Sys_var_mybool Sys_slow_query_log_timestamp_always( + "slow_query_log_timestamp_always", + "Timestamp is printed for all records of the slow log even if they are same time.", + GLOBAL_VAR(opt_slow_query_log_timestamp_always), CMD_LINE(OPT_ARG), + DEFAULT(FALSE)); +const char *slow_query_log_use_global_control_name[]= { "log_slow_filter", "log_slow_rate_limit", "log_slow_verbosity", "long_query_time", "min_examined_row_limit", "all", 0}; +static bool update_slow_query_log_use_global_control(sys_var */*self*/, THD */*thd*/, + enum_var_type /*type*/) +{ + if(opt_slow_query_log_use_global_control & (ULL(1) << SLOG_UG_ALL)) + { + opt_slow_query_log_use_global_control= + SLOG_UG_LOG_SLOW_FILTER | SLOG_UG_LOG_SLOW_RATE_LIMIT | SLOG_UG_LOG_SLOW_VERBOSITY | + SLOG_UG_LONG_QUERY_TIME | SLOG_UG_MIN_EXAMINED_ROW_LIMIT; + } + return false; +} +void init_log_slow_verbosity() +{ + update_slow_query_log_use_global_control(0,0,OPT_GLOBAL); +} +static Sys_var_set Sys_slow_query_log_use_global_control( + "slow_query_log_use_global_control", + "Choose flags, wich always use the global variables. Multiple flags allowed in a comma-separated string. [none, log_slow_filter, log_slow_rate_limit, log_slow_verbosity, long_query_time, min_examined_row_limit, all]", + GLOBAL_VAR(opt_slow_query_log_use_global_control), CMD_LINE(REQUIRED_ARG), + slow_query_log_use_global_control_name, DEFAULT(0), + NO_MUTEX_GUARD, NOT_IN_BINLOG, ON_CHECK(0), + ON_UPDATE(update_slow_query_log_use_global_control)); +const char *slow_query_log_timestamp_precision_name[]= { "second", "microsecond", 0 }; +static Sys_var_enum Sys_slow_query_log_timestamp_precision( + "slow_query_log_timestamp_precision", + "Log slow statements executed by stored procedure to the slow log if it is open. [second, microsecond]", + GLOBAL_VAR(opt_slow_query_log_timestamp_precision), CMD_LINE(REQUIRED_ARG), + slow_query_log_timestamp_precision_name, DEFAULT(SLOG_SECOND)); + +const char* slow_query_log_rate_name[]= {"session", "query", 0}; +static Sys_var_enum Sys_slow_query_log_rate_type( + "log_slow_rate_type", + "Choose the log_slow_rate_limit behavior: session or query. " + "When you choose 'session' - every %log_slow_rate_limit connection " + "will be processed to slow query log. " + "When you choose 'query' - every %log_slow_rate_limit query " + "will be processed to slow query log. " + "[session, query]", + GLOBAL_VAR(opt_slow_query_log_rate_type), CMD_LINE(REQUIRED_ARG), + slow_query_log_rate_name, DEFAULT(SLOG_RT_SESSION)); /* Synonym of "slow_query_log" for consistency with SHOW VARIABLES output */ static Sys_var_mybool Sys_log_slow( "log_slow_queries", --- a/sql/sql_profile.cc +++ b/sql/sql_profile.cc @@ -243,7 +243,8 @@ { time_usecs= (double) my_getsystime() / 10.0; /* 1 sec was 1e7, now is 1e6 */ #ifdef HAVE_GETRUSAGE - getrusage(RUSAGE_SELF, &rusage); + if ((profile->get_profiling())->enabled_getrusage()) + getrusage(RUSAGE_SELF, &rusage); #elif defined(_WIN32) FILETIME ftDummy; // NOTE: Get{Process|Thread}Times has a granularity of the clock interval, @@ -251,6 +252,19 @@ // measurable by this function. GetProcessTimes(GetCurrentProcess(), &ftDummy, &ftDummy, &ftKernel, &ftUser); #endif + +#ifdef HAVE_CLOCK_GETTIME + struct timespec tp; + + if (!(clock_gettime(CLOCK_THREAD_CPUTIME_ID, &tp))) + { + cpu_time_usecs= tp.tv_sec*1000000000.0 + tp.tv_nsec; + } + else +#endif + { + cpu_time_usecs= 0; + } } @@ -366,7 +380,8 @@ finish_current_query(); } - enabled= ((thd->variables.option_bits & OPTION_PROFILING) != 0); + enabled= ((thd->variables.option_bits & OPTION_PROFILING) != 0) || + ((thd->variables.log_slow_verbosity & (ULL(1) << SLOG_V_PROFILING)) != 0); if (! enabled) DBUG_VOID_RETURN; @@ -404,7 +419,8 @@ status_change("ending", NULL, NULL, 0); if ((enabled) && /* ON at start? */ - ((thd->variables.option_bits & OPTION_PROFILING) != 0) && /* and ON at end? */ + (((thd->variables.option_bits & OPTION_PROFILING) != 0) || + ((thd->variables.log_slow_verbosity & (ULL(1) << SLOG_V_PROFILING)) != 0)) && /* and ON at end? */ (current->query_source != NULL) && (! current->entries.is_empty())) { @@ -505,6 +521,118 @@ DBUG_VOID_RETURN; } +bool PROFILING::enabled_getrusage() +{ + return ((thd->variables.log_slow_verbosity & (ULL(1) << SLOG_V_PROFILING_USE_GETRUSAGE)) != 0); +} + +/** + For a given profile entry specified by a name and 2 time measurements, + print its normalized name (i.e. with all spaces replaced with underscores) + along with its wall clock and CPU time. +*/ + +static void my_b_print_status(IO_CACHE *log_file, const char *status, + PROF_MEASUREMENT *start, PROF_MEASUREMENT *stop) +{ + DBUG_ENTER("my_b_print_status"); + DBUG_ASSERT(log_file != NULL && status != NULL); + char query_time_buff[22+7]; + const char *tmp; + + my_b_printf(log_file, "Profile_"); + for (tmp= status; *tmp; tmp++) + my_b_write_byte(log_file, *tmp == ' ' ? '_' : *tmp); + + snprintf(query_time_buff, sizeof(query_time_buff), "%.6f", + (stop->time_usecs - start->time_usecs) / (1000.0 * 1000)); + my_b_printf(log_file, ": %s ", query_time_buff); + + my_b_printf(log_file, "Profile_"); + for (tmp= status; *tmp; tmp++) + my_b_write_byte(log_file, *tmp == ' ' ? '_' : *tmp); + my_b_printf(log_file, "_cpu: "); + + snprintf(query_time_buff, sizeof(query_time_buff), "%.6f", + (stop->cpu_time_usecs - start->cpu_time_usecs) / + (1000.0 * 1000 * 1000)); + my_b_printf(log_file, "%s ", query_time_buff); + + DBUG_VOID_RETURN; +} + +/** + Print output for current query to file +*/ + +int PROFILING::print_current(IO_CACHE *log_file) +{ + DBUG_ENTER("PROFILING::print_current"); + ulonglong row_number= 0; + + QUERY_PROFILE *query; + /* Get current query */ + if (current == NULL) + { + DBUG_RETURN(0); + } + + query= current; + + my_b_printf(log_file, "# "); + + void *entry_iterator; + PROF_MEASUREMENT *entry= NULL, *previous= NULL, *first= NULL; + /* ...and for each query, go through all its state-change steps. */ + for (entry_iterator= query->entries.new_iterator(); + entry_iterator != NULL; + entry_iterator= query->entries.iterator_next(entry_iterator), + previous=entry, row_number++) + { + entry= query->entries.iterator_value(entry_iterator); + + /* Skip the first. We count spans of fence, not fence-posts. */ + if (previous == NULL) {first= entry; continue;} + + if (thd->lex->sql_command == SQLCOM_SHOW_PROFILE) + { + /* + We got here via a SHOW command. That means that we stored + information about the query we wish to show and that isn't + in a WHERE clause at a higher level to filter out rows we + wish to exclude. + + Because that functionality isn't available in the server yet, + we must filter here, at the wrong level. Once one can con- + struct where and having conditions at the SQL layer, then this + condition should be ripped out. + */ + if (thd->lex->profile_query_id == 0) /* 0 == show final query */ + { + if (query != last) + continue; + } + else + { + if (thd->lex->profile_query_id != query->profiling_query_id) + continue; + } + } + + my_b_print_status(log_file, previous->status, previous, entry); + } + + my_b_write_byte(log_file, '\n'); + if ((entry != NULL) && (first != NULL)) + { + my_b_printf(log_file, "# "); + my_b_print_status(log_file, "total", first, entry); + my_b_write_byte(log_file, '\n'); + } + + DBUG_RETURN(0); +} + /** Fill the information schema table, "query_profile", as defined in show.cc . There are two ways to get to this function: Selecting from the information @@ -600,6 +728,8 @@ #ifdef HAVE_GETRUSAGE + if (enabled_getrusage()) + { my_decimal cpu_utime_decimal, cpu_stime_decimal; double2my_decimal(E_DEC_FATAL_ERROR, @@ -687,6 +817,7 @@ table->field[14]->store((uint32)(entry->rusage.ru_nswap - previous->rusage.ru_nswap), true); table->field[14]->set_notnull(); + } #else /* TODO: Add swap info for non-BSD systems */ #endif --- a/sql/sql_profile.h +++ b/sql/sql_profile.h @@ -164,11 +164,15 @@ */ class PROF_MEASUREMENT { -private: - friend class QUERY_PROFILE; - friend class PROFILING; - QUERY_PROFILE *profile; + + char *allocated_status_memory; + + void set_label(const char *status_arg, const char *function_arg, + const char *file_arg, unsigned int line_arg); + void clean_up(); + +public: char *status; #ifdef HAVE_GETRUSAGE struct rusage rusage; @@ -181,12 +185,7 @@ unsigned int line; double time_usecs; - char *allocated_status_memory; - - void set_label(const char *status_arg, const char *function_arg, - const char *file_arg, unsigned int line_arg); - void clean_up(); - + double cpu_time_usecs; PROF_MEASUREMENT(); PROF_MEASUREMENT(QUERY_PROFILE *profile_arg, const char *status_arg); PROF_MEASUREMENT(QUERY_PROFILE *profile_arg, const char *status_arg, @@ -231,6 +230,11 @@ /* Show this profile. This is called by PROFILING. */ bool show(uint options); + +public: + + inline PROFILING * get_profiling() { return profiling; }; + }; @@ -276,9 +280,11 @@ /* SHOW PROFILES */ bool show_profiles(); + bool enabled_getrusage(); /* ... from INFORMATION_SCHEMA.PROFILING ... */ int fill_statistics_info(THD *thd, TABLE_LIST *tables, Item *cond); + int print_current(IO_CACHE *log_file); }; # endif /* HAVE_PROFILING */ --- /dev/null +++ b/mysql-test/include/log_grep.inc @@ -0,0 +1,41 @@ +--echo [log_grep.inc] file: $log_file pattern: $grep_pattern +perl; + $log_file= $ENV{'log_file'}; + $log_file_full_path= $ENV{'log_file_full_path'}; + $log_slow_rate_test= $ENV{'log_slow_rate_test'}; + open(FILE, "$log_file_full_path") + or die("Cannot open file $log_file_full_path: $!\n"); + + if ($log_slow_rate_test) { + $one= 0; + $two= 0; + $three= 0; + while() { + $one++ if(/'connection_one'/); + $two++ if(/'connection_two'/); + $three++ if(/'connection_three'/); + } + $sum= $one + $two + $three; + $zero= 0; + if ($one == 0) { + $zero++; + } + if ($two == 0) { + $zero++; + } + if ($three == 0) { + $zero++; + } + print "[log_grep.inc] sum: $sum\n"; + print "[log_grep.inc] zero: $zero\n"; + } + else { + $grep_pattern= $ENV{'grep_pattern'}; + $lines= 0; + while() { + $lines++ if (/$grep_pattern/); + } + print "[log_grep.inc] lines: $lines\n"; + } + close(FILE); +EOF --- /dev/null +++ b/mysql-test/include/log_start.inc @@ -0,0 +1,16 @@ +--disable_query_log +--let log_file_full_path = $MYSQLTEST_VARDIR/$log_file +SET @slow_query_log_old=@@slow_query_log; +SET @slow_query_log_file_old= @@slow_query_log_file; +SET GLOBAL slow_query_log=OFF; +perl; + $log_file_full_path= $ENV{'log_file_full_path'}; + unlink $log_file_full_path; + open(FILE, '>', $log_file_full_path) + or die "Cannot create log file $log_file_full_path, reason: $!"; + close(FILE); +EOF +--echo [log_start.inc] $log_file +EVAL SET GLOBAL slow_query_log_file="$log_file_full_path"; +SET GLOBAL slow_query_log=ON; +--enable_query_log --- /dev/null +++ b/mysql-test/include/log_stop.inc @@ -0,0 +1,7 @@ +--disable_query_log +FLUSH LOGS; +SET GLOBAL slow_query_log=OFF; +--echo [log_stop.inc] $log_file +SET GLOBAL slow_query_log_file= @slow_query_log_file_old; +SET GLOBAL slow_query_log= @slow_query_log_old; +--enable_query_log --- /dev/null +++ b/mysql-test/r/percona_bug643149.result @@ -0,0 +1,21 @@ +SET @old_slow_query_log_file=@@global.slow_query_log_file; +SET GLOBAL slow_query_log=on; +SET LOCAL log_slow_verbosity='profiling'; +SET LOCAL long_query_time=0; +SET GLOBAL slow_query_log_file='MYSQLTEST_VARDIR/percona_bug643149_slow.log';; +SELECT 1; +1 +1 +# User@Host: root[root] @ localhost [] +# Thread_id: X Schema: test Last_errno: X Killed: X +# Query_time: X.X Lock_time: X.X Rows_sent: X Rows_examined: X Rows_affected: X Rows_read: X +# Bytes_sent: X Tmp_tables: X Tmp_disk_tables: X Tmp_table_sizes: X +# Profile_starting: X.X Profile_starting_cpu: X.X Profile_Opening_tables: X.X Profile_Opening_tables_cpu: X.X Profile_query_end: X.X Profile_query_end_cpu: X.X Profile_closing_tables: X.X Profile_closing_tables_cpu: X.X Profile_freeing_items: X.X Profile_freeing_items_cpu: X.X Profile_logging_slow_query: X.X Profile_logging_slow_query_cpu: X.X +# Profile_total: X.X Profile_total_cpu: X.X +# User@Host: root[root] @ localhost [] +# Thread_id: X Schema: test Last_errno: X Killed: X +# Query_time: X.X Lock_time: X.X Rows_sent: X Rows_examined: X Rows_affected: X Rows_read: X +# Bytes_sent: X Tmp_tables: X Tmp_disk_tables: X Tmp_table_sizes: X +# Profile_starting: X.X Profile_starting_cpu: X.X Profile_checking_permissions: X.X Profile_checking_permissions_cpu: X.X Profile_Opening_tables: X.X Profile_Opening_tables_cpu: X.X Profile_init: X.X Profile_init_cpu: X.X Profile_optimizing: X.X Profile_optimizing_cpu: X.X Profile_executing: X.X Profile_executing_cpu: X.X Profile_end: X.X Profile_end_cpu: X.X Profile_query_end: X.X Profile_query_end_cpu: X.X Profile_closing_tables: X.X Profile_closing_tables_cpu: X.X Profile_freeing_items: X.X Profile_freeing_items_cpu: X.X Profile_logging_slow_query: X.X Profile_logging_slow_query_cpu: X.X +# Profile_total: X.X Profile_total_cpu: X.X +SET GLOBAL slow_query_log_file=@old_slow_query_log_file; --- /dev/null +++ b/mysql-test/r/percona_log_slow_filter-cl.result @@ -0,0 +1,6 @@ +SHOW VARIABLES LIKE 'log_slow_filter'; +Variable_name Value +log_slow_filter full_join +SHOW GLOBAL VARIABLES LIKE 'log_slow_filter'; +Variable_name Value +log_slow_filter full_join --- /dev/null +++ b/mysql-test/r/percona_log_slow_filter.result @@ -0,0 +1,16 @@ +CREATE TABLE t(id INT PRIMARY KEY); +INSERT INTO t VALUES(1); +INSERT INTO t VALUES(2); +INSERT INTO t VALUES(3); +SET long_query_time=1; +SET log_slow_filter=full_join; +[log_start.inc] percona.slow_extended.log_slow_filter +SET query_exec_time = 1.1; +SELECT * FROM t AS t1, t AS t2; +SET query_exec_time = default; +[log_stop.inc] percona.slow_extended.log_slow_filter +SET log_slow_filter=default; +SET long_query_time=default; +[log_grep.inc] file: percona.slow_extended.log_slow_filter pattern: Query_time +[log_grep.inc] lines: 1 +DROP TABLE t; --- /dev/null +++ b/mysql-test/r/percona_log_slow_slave_statements-cl.result @@ -0,0 +1,6 @@ +SHOW VARIABLES LIKE 'log_slow_slave_statements'; +Variable_name Value +log_slow_slave_statements ON +SHOW GLOBAL VARIABLES LIKE 'log_slow_slave_statements'; +Variable_name Value +log_slow_slave_statements ON --- /dev/null +++ b/mysql-test/r/percona_log_slow_slave_statements-innodb.result @@ -0,0 +1,19 @@ +include/master-slave.inc +[connection master] +DROP TABLE IF EXISTS t; +CREATE TABLE t(id INT,data CHAR(30)) ENGINE=InnoDB; +INSERT INTO t VALUES +(1,"aaaaabbbbbcccccdddddeeeeefffff"), +(2,"aaaaabbbbbcccccdddddeeeeefffff"), +(3,"aaaaabbbbbcccccdddddeeeeefffff"), +(4,"aaaaabbbbbcccccdddddeeeeefffff"), +(5,"aaaaabbbbbcccccdddddeeeeefffff"); +INSERT INTO t SELECT t2.id,t2.data from t as t1, t as t2; +INSERT INTO t SELECT t2.id,t2.data from t as t1, t as t2; +[log_start.inc] percona.slow_extended.log_slow_slave_statements-innodb +INSERT INTO t SELECT t.id,t.data from t; +[log_stop.inc] percona.slow_extended.log_slow_slave_statements-innodb +[log_grep.inc] file: percona.slow_extended.log_slow_slave_statements-innodb pattern: InnoDB_IO_r_ops +[log_grep.inc] lines: 1 +DROP TABLE t; +include/rpl_end.inc --- /dev/null +++ b/mysql-test/r/percona_log_slow_slave_statements.result @@ -0,0 +1,45 @@ +include/master-slave.inc +[connection master] +DROP TABLE IF EXISTS t; +CREATE TABLE t(id INT); +[log_start.inc] percona.slow_extended.log_slow_slave_statements +LINE 1 +LOG_SLOW_SLAVE_STATAMENTS is OFF +LOG_SLOW_SLAVE_STATEMENTS=ON +LOG_SLOW_SLAVE_STATAMENTS is ON +LINE 2 +include/restart_slave.inc +LOG_SLOW_SLAVE_STATAMENTS is ON +LINE 3 +LOG_SLOW_SLAVE_STATAMENTS is ON +LOG_SLOW_SLAVE_STATEMENTS=OFF +LOG_SLOW_SLAVE_STATAMENTS is OFF +LINE 4 +include/restart_slave.inc +LOG_SLOW_SLAVE_STATAMENTS is OFF +LINE 5 +LOG_SLOW_SLAVE_STATAMENTS is OFF +LOG_SLOW_SLAVE_STATEMENTS=ON +LOG_SLOW_SLAVE_STATAMENTS is ON +LINE 6 +include/restart_slave.inc +LOG_SLOW_SLAVE_STATAMENTS is ON +LINE 7 +[log_stop.inc] percona.slow_extended.log_slow_slave_statements +SET GLOBAL log_slow_slave_statements=default; +[log_grep.inc] file: percona.slow_extended.log_slow_slave_statements pattern: INSERT INTO t VALUES \(1\) +[log_grep.inc] lines: 0 +[log_grep.inc] file: percona.slow_extended.log_slow_slave_statements pattern: INSERT INTO t VALUES \(2\) +[log_grep.inc] lines: 0 +[log_grep.inc] file: percona.slow_extended.log_slow_slave_statements pattern: INSERT INTO t VALUES \(3\) +[log_grep.inc] lines: 1 +[log_grep.inc] file: percona.slow_extended.log_slow_slave_statements pattern: INSERT INTO t VALUES \(4\) +[log_grep.inc] lines: 0 +[log_grep.inc] file: percona.slow_extended.log_slow_slave_statements pattern: INSERT INTO t VALUES \(5\) +[log_grep.inc] lines: 0 +[log_grep.inc] file: percona.slow_extended.log_slow_slave_statements pattern: INSERT INTO t VALUES \(6\) +[log_grep.inc] lines: 0 +[log_grep.inc] file: percona.slow_extended.log_slow_slave_statements pattern: INSERT INTO t VALUES \(7\) +[log_grep.inc] lines: 1 +DROP TABLE t; +include/rpl_end.inc --- /dev/null +++ b/mysql-test/r/percona_log_slow_sp_statements-cl.result @@ -0,0 +1,6 @@ +SHOW VARIABLES LIKE 'log_slow_sp_statements'; +Variable_name Value +log_slow_sp_statements ON +SHOW GLOBAL VARIABLES LIKE 'log_slow_sp_statements'; +Variable_name Value +log_slow_sp_statements ON --- /dev/null +++ b/mysql-test/r/percona_log_slow_sp_statements.result @@ -0,0 +1,25 @@ +SET long_query_time=1; +SET GLOBAL log_slow_sp_statements=ON; +SET SESSION query_exec_time=0.1; +[log_start.inc] percona.slow_extended.log_slow_sp_statements +CREATE PROCEDURE test_f() +BEGIN +SET SESSION query_exec_time=1.1; SELECT 1; +SET SESSION query_exec_time=2.1; SELECT 1; +SET SESSION query_exec_time=3.1; SELECT 1; +SET SESSION query_exec_time=0.1; +END^ +CALL test_f(); +1 +1 +1 +1 +1 +1 +[log_stop.inc] percona.slow_extended.log_slow_sp_statements +SET SESSION query_exec_time=default; +SET GLOBAL log_slow_sp_statements=default; +SET long_query_time=default; +[log_grep.inc] file: percona.slow_extended.log_slow_sp_statements pattern: Query_time +[log_grep.inc] lines: 3 +DROP PROCEDURE test_f; --- /dev/null +++ b/mysql-test/r/percona_log_slow_verbosity-cl.result @@ -0,0 +1,6 @@ +SHOW VARIABLES LIKE 'log_slow_verbosity'; +Variable_name Value +log_slow_verbosity microtime,query_plan,innodb +SHOW GLOBAL VARIABLES LIKE 'log_slow_verbosity'; +Variable_name Value +log_slow_verbosity microtime,query_plan,innodb --- /dev/null +++ b/mysql-test/r/percona_log_slow_verbosity.result @@ -0,0 +1,16 @@ +SET SESSION long_query_time=1; +[log_start.inc] percona.slow_extended.log_slow_verbosity +SET SESSION query_exec_time=2.1; +SELECT 1; +1 +1 +SET SESSION log_slow_verbosity=innodb; +SELECT 1; +1 +1 +SET SESSION query_exec_time=default; +[log_stop.inc] percona.slow_extended.log_slow_verbosity +SET log_slow_verbosity=default; +SET long_query_time=default; +[log_grep.inc] file: percona.slow_extended.log_slow_verbosity pattern: No InnoDB statistics available for this query +[log_grep.inc] lines: 1 --- /dev/null +++ b/mysql-test/r/percona_long_query_time.result @@ -0,0 +1,33 @@ +SET long_query_time=2; +[log_start.inc] percona.slow_extended.long_query_time +SET SESSION query_exec_time=1.1; +SELECT 1; +1 +1 +SET SESSION query_exec_time=3.1; +SELECT 1; +1 +1 +SET SESSION query_exec_time=5.1; +SELECT 1; +1 +1 +SET long_query_time=4; +SET SESSION query_exec_time=1.1; +SELECT 1; +1 +1 +SET SESSION query_exec_time=3.1; +SELECT 1; +1 +1 +SET SESSION query_exec_time=5.1; +SELECT 1; +1 +1 +SET SESSION query_exec_time=default; +SET long_query_time=2; +[log_stop.inc] percona.slow_extended.long_query_time +SET long_query_time=default; +[log_grep.inc] file: percona.slow_extended.long_query_time pattern: Query_time +[log_grep.inc] lines: 3 --- /dev/null +++ b/mysql-test/r/percona_slow_query_log_timestamp_always-cl.result @@ -0,0 +1,6 @@ +SHOW VARIABLES LIKE 'slow_query_log_timestamp_always'; +Variable_name Value +slow_query_log_timestamp_always ON +SHOW GLOBAL VARIABLES LIKE 'slow_query_log_timestamp_always'; +Variable_name Value +slow_query_log_timestamp_always ON --- /dev/null +++ b/mysql-test/r/percona_slow_query_log_timestamp_always.result @@ -0,0 +1,41 @@ +SET long_query_time=2; +SET GLOBAL slow_query_log_timestamp_always=ON; +[log_start.inc] percona.slow_extended.slow_query_log_timestamp_always +SET SESSION query_exec_time=2.1; +SELECT 1; +1 +1 +SELECT 1; +1 +1 +SELECT 1; +1 +1 +SET GLOBAL slow_query_log_timestamp_always=OFF; +SET SESSION query_exec_time=2.1; +SELECT 1; +1 +1 +SELECT 1; +1 +1 +SELECT 1; +1 +1 +SET GLOBAL slow_query_log_timestamp_always=ON; +SET SESSION query_exec_time=2.1; +SELECT 1; +1 +1 +SELECT 1; +1 +1 +SELECT 1; +1 +1 +SET SESSION query_exec_time=default; +[log_stop.inc] percona.slow_extended.slow_query_log_timestamp_always +SET GLOBAL slow_query_log_timestamp_always=default; +SET long_query_time=default; +[log_grep.inc] file: percona.slow_extended.slow_query_log_timestamp_always pattern: # Time: [0-9]+[ ]+[0-9]+:[0-9]+:[0-9]+ +[log_grep.inc] lines: 6 --- /dev/null +++ b/mysql-test/r/percona_slow_query_log_timestamp_precision-cl.result @@ -0,0 +1,6 @@ +SHOW VARIABLES LIKE 'slow_query_log_timestamp_precision'; +Variable_name Value +slow_query_log_timestamp_precision microsecond +SHOW GLOBAL VARIABLES LIKE 'slow_query_log_timestamp_precision'; +Variable_name Value +slow_query_log_timestamp_precision microsecond --- /dev/null +++ b/mysql-test/r/percona_slow_query_log_timestamp_precision.result @@ -0,0 +1,18 @@ +SET long_query_time=2; +[log_start.inc] percona.slow_extended.slow_query_log_timestamp_precision +SET SESSION query_exec_time=2.1; +SELECT 1; +1 +1 +SET GLOBAL slow_query_log_timestamp_precision='microsecond'; +SELECT 1; +1 +1 +SET SESSION query_exec_time=default; +[log_stop.inc] percona.slow_extended.slow_query_log_timestamp_precision +SET GLOBAL slow_query_log_timestamp_precision=default; +SET long_query_time=default; +[log_grep.inc] file: percona.slow_extended.slow_query_log_timestamp_precision pattern: # Time: [0-9]+[ ]+[0-9]+:[0-9]+:[0-9]+.[0-9]+ +[log_grep.inc] lines: 1 +[log_grep.inc] file: percona.slow_extended.slow_query_log_timestamp_precision pattern: # Time: [0-9]+[ ]+[0-9]+:[0-9]+:[0-9]+ +[log_grep.inc] lines: 2 --- /dev/null +++ b/mysql-test/r/percona_slow_query_log_use_global_control.result @@ -0,0 +1,18 @@ +SET GLOBAL long_query_time=1; +[log_start.inc] percona.slow_extended.slow_query_log_use_global_control +SET SESSION query_exec_time=1.1; +SELECT 1; +1 +1 +SET GLOBAL log_slow_verbosity=innodb; +SET GLOBAL slow_query_log_use_global_control="log_slow_verbosity,long_query_time"; +SELECT 1; +1 +1 +SET SESSION query_exec_time=default; +[log_stop.inc] percona.slow_extended.slow_query_log_use_global_control +SET GLOBAL slow_query_log_use_global_control=default; +SET GLOBAL log_slow_verbosity=default; +SET GLOBAL long_query_time=default; +[log_grep.inc] file: percona.slow_extended.slow_query_log_use_global_control pattern: No InnoDB statistics available for this query +[log_grep.inc] lines: 1 --- /dev/null +++ b/mysql-test/t/percona_bug643149.test @@ -0,0 +1,49 @@ +# +# This test suffers from server +# Bug#38124 "general_log_file" variable silently unset when using expression +# In short: +# SET GLOBAL general_log_file = @ +# SET GLOBAL slow_query_log = @ +# cause that the value of these server system variables is set to default +# instead of the assigned values. There comes no error message or warning. +# If this bug is fixed please +# 1. try this test with "let $fixed_bug38124 = 0;" +# 2. remove all workarounds if 1. was successful. +--source include/have_profiling.inc +let $fixed_bug38124 = 0; + +SET @old_slow_query_log_file=@@global.slow_query_log_file; +SET GLOBAL slow_query_log=on; +SET LOCAL log_slow_verbosity='profiling'; +SET LOCAL long_query_time=0; + +let slogfile=$MYSQLTEST_VARDIR/percona_bug643149_slow.log; +--replace_result $MYSQLTEST_VARDIR MYSQLTEST_VARDIR +--eval SET GLOBAL slow_query_log_file='$slogfile'; + +SELECT 1; + +perl; + $slogfile= $ENV{'slogfile'}; + + open(FILE, "$slogfile") or + die("Unable to read slow query log file $slogfile: $!\n"); + while() { + next if (!/^#/); + next if (/^# Time:/); + s/[0-9]+/X/g; + print; + } + + close(FILE); +EOF + +SET GLOBAL slow_query_log_file=@old_slow_query_log_file; + +if(!$fixed_bug38124) +{ + --disable_query_log + let $my_var = `SELECT @old_slow_query_log_file`; + eval SET @@global.slow_query_log_file = '$my_var'; + --enable_query_log +} --- /dev/null +++ b/mysql-test/t/percona_log_slow_filter-cl-master.opt @@ -0,0 +1 @@ +--log_slow_filter=full_join --- /dev/null +++ b/mysql-test/t/percona_log_slow_filter-cl.test @@ -0,0 +1,2 @@ +SHOW VARIABLES LIKE 'log_slow_filter'; +SHOW GLOBAL VARIABLES LIKE 'log_slow_filter'; --- /dev/null +++ b/mysql-test/t/percona_log_slow_filter.test @@ -0,0 +1,26 @@ +--source include/have_debug.inc + +CREATE TABLE t(id INT PRIMARY KEY); +INSERT INTO t VALUES(1); +INSERT INTO t VALUES(2); +INSERT INTO t VALUES(3); + +SET long_query_time=1; +SET log_slow_filter=full_join; +--let log_file=percona.slow_extended.log_slow_filter +--source include/log_start.inc + +SET query_exec_time = 1.1; +--disable_result_log +SELECT * FROM t AS t1, t AS t2; +--enable_result_log +SET query_exec_time = default; + +--source include/log_stop.inc +SET log_slow_filter=default; +SET long_query_time=default; + +--let grep_pattern = Query_time +--source include/log_grep.inc + +DROP TABLE t; --- /dev/null +++ b/mysql-test/t/percona_log_slow_slave_statements-cl-master.opt @@ -0,0 +1 @@ +--log_slow_slave_statements \ No newline at end of file --- /dev/null +++ b/mysql-test/t/percona_log_slow_slave_statements-cl.test @@ -0,0 +1,3 @@ +SHOW VARIABLES LIKE 'log_slow_slave_statements'; +SHOW GLOBAL VARIABLES LIKE 'log_slow_slave_statements'; + --- /dev/null +++ b/mysql-test/t/percona_log_slow_slave_statements-innodb-slave.opt @@ -0,0 +1 @@ +--long_query_time=0 --log_slow_slave_statements --log_slow_verbosity=innodb \ No newline at end of file --- /dev/null +++ b/mysql-test/t/percona_log_slow_slave_statements-innodb.test @@ -0,0 +1,42 @@ +--source include/have_binlog_format_statement.inc +--source include/master-slave.inc +--source include/have_innodb.inc +--let log_file=percona.slow_extended.log_slow_slave_statements-innodb + +connection master; +-- disable_warnings +DROP TABLE IF EXISTS t; +-- enable_warnings + +CREATE TABLE t(id INT,data CHAR(30)) ENGINE=InnoDB; +INSERT INTO t VALUES +(1,"aaaaabbbbbcccccdddddeeeeefffff"), +(2,"aaaaabbbbbcccccdddddeeeeefffff"), +(3,"aaaaabbbbbcccccdddddeeeeefffff"), +(4,"aaaaabbbbbcccccdddddeeeeefffff"), +(5,"aaaaabbbbbcccccdddddeeeeefffff"); +INSERT INTO t SELECT t2.id,t2.data from t as t1, t as t2; +INSERT INTO t SELECT t2.id,t2.data from t as t1, t as t2; +sync_slave_with_master; + +connection slave; +--source include/log_start.inc + +connection master; +INSERT INTO t SELECT t.id,t.data from t; +sync_slave_with_master; + +connection slave; +--source include/log_stop.inc + +--enable_query_log +--enable_result_log + +--let grep_pattern = InnoDB_IO_r_ops +--source include/log_grep.inc + +connection master; +DROP TABLE t; +sync_slave_with_master; + +--source include/rpl_end.inc --- /dev/null +++ b/mysql-test/t/percona_log_slow_slave_statements-slave.opt @@ -0,0 +1 @@ +--long_query_time=0 \ No newline at end of file --- /dev/null +++ b/mysql-test/t/percona_log_slow_slave_statements.test @@ -0,0 +1,117 @@ +-- source include/have_binlog_format_statement.inc +-- source include/master-slave.inc +--let log_file=percona.slow_extended.log_slow_slave_statements +--let show=SELECT Variable_value FROM INFORMATION_SCHEMA.SESSION_VARIABLES WHERE Variable_name LIKE 'log_slow_slave_statements'; + +connection master; +-- disable_warnings +DROP TABLE IF EXISTS t; +-- enable_warnings + +CREATE TABLE t(id INT); +sync_slave_with_master; + +connection slave; +--source include/log_start.inc + +--disable_query_log +--disable_result_log + +--echo LINE 1 +connection master; +INSERT INTO t VALUES (1); +sync_slave_with_master; + +connection slave; +--let value=`$show` +--echo LOG_SLOW_SLAVE_STATAMENTS is $value +--echo LOG_SLOW_SLAVE_STATEMENTS=ON +SET GLOBAL log_slow_slave_statements=ON; +--let value=`$show` +--echo LOG_SLOW_SLAVE_STATAMENTS is $value + +--echo LINE 2 +connection master; +INSERT INTO t VALUES (2); +sync_slave_with_master; + +--source include/restart_slave_sql.inc + +connection slave; +--let value=`$show` +--echo LOG_SLOW_SLAVE_STATAMENTS is $value + +--echo LINE 3 +connection master; +INSERT INTO t VALUES (3); +sync_slave_with_master; + +connection slave; +--let value=`$show` +--echo LOG_SLOW_SLAVE_STATAMENTS is $value +--echo LOG_SLOW_SLAVE_STATEMENTS=OFF +SET GLOBAL log_slow_slave_statements=OFF; +--let value=`$show` +--echo LOG_SLOW_SLAVE_STATAMENTS is $value + +--echo LINE 4 +connection master; +INSERT INTO t VALUES (4); +sync_slave_with_master; + +--source include/restart_slave_sql.inc + +connection slave; +--let value=`$show` +--echo LOG_SLOW_SLAVE_STATAMENTS is $value + +--echo LINE 5 +connection master; +INSERT INTO t VALUES (5); +sync_slave_with_master; + +connection slave; +--let value=`$show` +--echo LOG_SLOW_SLAVE_STATAMENTS is $value +--echo LOG_SLOW_SLAVE_STATEMENTS=ON +SET GLOBAL log_slow_slave_statements=ON; +--let value=`$show` +--echo LOG_SLOW_SLAVE_STATAMENTS is $value + +--echo LINE 6 +connection master; +INSERT INTO t VALUES (6); +sync_slave_with_master; + +--source include/restart_slave_sql.inc + +connection slave; +--let value=`$show` +--echo LOG_SLOW_SLAVE_STATAMENTS is $value + +--echo LINE 7 +connection master; +INSERT INTO t VALUES (7); +sync_slave_with_master; + +--enable_query_log +--enable_result_log + +connection slave; +--source include/log_stop.inc +SET GLOBAL log_slow_slave_statements=default; + +connection slave; +--let i=1 +while($i < 8) +{ +--let grep_pattern= INSERT INTO t VALUES \($i\) +--source include/log_grep.inc + inc $i; +} + +connection master; +DROP TABLE t; +sync_slave_with_master; + +--source include/rpl_end.inc --- /dev/null +++ b/mysql-test/t/percona_log_slow_sp_statements-cl-master.opt @@ -0,0 +1 @@ +--log_slow_sp_statements --- /dev/null +++ b/mysql-test/t/percona_log_slow_sp_statements-cl.test @@ -0,0 +1,2 @@ +SHOW VARIABLES LIKE 'log_slow_sp_statements'; +SHOW GLOBAL VARIABLES LIKE 'log_slow_sp_statements'; --- /dev/null +++ b/mysql-test/t/percona_log_slow_sp_statements.test @@ -0,0 +1,29 @@ +--source include/have_debug.inc + +SET long_query_time=1; +SET GLOBAL log_slow_sp_statements=ON; +SET SESSION query_exec_time=0.1; +--let log_file=percona.slow_extended.log_slow_sp_statements +--source include/log_start.inc + +delimiter ^; +CREATE PROCEDURE test_f() +BEGIN + SET SESSION query_exec_time=1.1; SELECT 1; + SET SESSION query_exec_time=2.1; SELECT 1; + SET SESSION query_exec_time=3.1; SELECT 1; + SET SESSION query_exec_time=0.1; +END^ +delimiter ;^ + +CALL test_f(); + +--source include/log_stop.inc +SET SESSION query_exec_time=default; +SET GLOBAL log_slow_sp_statements=default; +SET long_query_time=default; + +--let grep_pattern = Query_time +--source include/log_grep.inc + +DROP PROCEDURE test_f; --- /dev/null +++ b/mysql-test/t/percona_log_slow_verbosity-cl-master.opt @@ -0,0 +1 @@ +--log_slow_verbosity="full" --- /dev/null +++ b/mysql-test/t/percona_log_slow_verbosity-cl.test @@ -0,0 +1,2 @@ +SHOW VARIABLES LIKE 'log_slow_verbosity'; +SHOW GLOBAL VARIABLES LIKE 'log_slow_verbosity'; --- /dev/null +++ b/mysql-test/t/percona_log_slow_verbosity.test @@ -0,0 +1,19 @@ +--source include/have_innodb.inc +--source include/have_debug.inc + +SET SESSION long_query_time=1; +--let log_file=percona.slow_extended.log_slow_verbosity +--source include/log_start.inc + +SET SESSION query_exec_time=2.1; +SELECT 1; +SET SESSION log_slow_verbosity=innodb; +SELECT 1; +SET SESSION query_exec_time=default; + +--source include/log_stop.inc +SET log_slow_verbosity=default; +SET long_query_time=default; + +--let grep_pattern = No InnoDB statistics available for this query +--source include/log_grep.inc --- /dev/null +++ b/mysql-test/t/percona_long_query_time.test @@ -0,0 +1,25 @@ +--source include/have_debug.inc + +SET long_query_time=2; +--let log_file=percona.slow_extended.long_query_time +--source include/log_start.inc + +SET SESSION query_exec_time=1.1; SELECT 1; +SET SESSION query_exec_time=3.1; SELECT 1; +SET SESSION query_exec_time=5.1; SELECT 1; + +SET long_query_time=4; + +SET SESSION query_exec_time=1.1; SELECT 1; +SET SESSION query_exec_time=3.1; SELECT 1; +SET SESSION query_exec_time=5.1; SELECT 1; + +SET SESSION query_exec_time=default; + +SET long_query_time=2; + +--source include/log_stop.inc +SET long_query_time=default; + +--let grep_pattern = Query_time +--source include/log_grep.inc --- /dev/null +++ b/mysql-test/t/percona_slow_query_log_timestamp_always-cl-master.opt @@ -0,0 +1 @@ +--slow_query_log_timestamp_always \ No newline at end of file --- /dev/null +++ b/mysql-test/t/percona_slow_query_log_timestamp_always-cl.test @@ -0,0 +1,2 @@ +SHOW VARIABLES LIKE 'slow_query_log_timestamp_always'; +SHOW GLOBAL VARIABLES LIKE 'slow_query_log_timestamp_always'; --- /dev/null +++ b/mysql-test/t/percona_slow_query_log_timestamp_always.test @@ -0,0 +1,34 @@ +--source include/have_debug.inc + +SET long_query_time=2; +SET GLOBAL slow_query_log_timestamp_always=ON; +--let log_file=percona.slow_extended.slow_query_log_timestamp_always +--source include/log_start.inc + +SET SESSION query_exec_time=2.1; +SELECT 1; +SELECT 1; +SELECT 1; + +SET GLOBAL slow_query_log_timestamp_always=OFF; + +SET SESSION query_exec_time=2.1; +SELECT 1; +SELECT 1; +SELECT 1; + +SET GLOBAL slow_query_log_timestamp_always=ON; + +SET SESSION query_exec_time=2.1; +SELECT 1; +SELECT 1; +SELECT 1; + +SET SESSION query_exec_time=default; + +--source include/log_stop.inc +SET GLOBAL slow_query_log_timestamp_always=default; +SET long_query_time=default; + +--let grep_pattern = # Time: [0-9]+[ ]+[0-9]+:[0-9]+:[0-9]+ +--source include/log_grep.inc --- /dev/null +++ b/mysql-test/t/percona_slow_query_log_timestamp_precision-cl-master.opt @@ -0,0 +1 @@ +--slow_query_log_timestamp_precision='microsecond' \ No newline at end of file --- /dev/null +++ b/mysql-test/t/percona_slow_query_log_timestamp_precision-cl.test @@ -0,0 +1,2 @@ +SHOW VARIABLES LIKE 'slow_query_log_timestamp_precision'; +SHOW GLOBAL VARIABLES LIKE 'slow_query_log_timestamp_precision'; --- /dev/null +++ b/mysql-test/t/percona_slow_query_log_timestamp_precision-master.opt @@ -0,0 +1 @@ +--slow_query_log_timestamp_always \ No newline at end of file --- /dev/null +++ b/mysql-test/t/percona_slow_query_log_timestamp_precision.test @@ -0,0 +1,25 @@ +--source include/have_debug.inc + +SET long_query_time=2; +--let log_file=percona.slow_extended.slow_query_log_timestamp_precision +--source include/log_start.inc + +SET SESSION query_exec_time=2.1; + +SELECT 1; + +SET GLOBAL slow_query_log_timestamp_precision='microsecond'; + +SELECT 1; + +SET SESSION query_exec_time=default; + +--source include/log_stop.inc +SET GLOBAL slow_query_log_timestamp_precision=default; +SET long_query_time=default; + +--let grep_pattern = # Time: [0-9]+[ ]+[0-9]+:[0-9]+:[0-9]+.[0-9]+ +--source include/log_grep.inc + +--let grep_pattern = # Time: [0-9]+[ ]+[0-9]+:[0-9]+:[0-9]+ +--source include/log_grep.inc --- /dev/null +++ b/mysql-test/t/percona_slow_query_log_use_global_control.test @@ -0,0 +1,28 @@ +--source include/have_debug.inc +--source include/have_innodb.inc + +SET GLOBAL long_query_time=1; + +--let log_file=percona.slow_extended.slow_query_log_use_global_control +--source include/log_start.inc + +SET SESSION query_exec_time=1.1; +SELECT 1; + +SET GLOBAL log_slow_verbosity=innodb; +SET GLOBAL slow_query_log_use_global_control="log_slow_verbosity,long_query_time"; + +SELECT 1; + +SET SESSION query_exec_time=default; + +--source include/log_stop.inc + + +SET GLOBAL slow_query_log_use_global_control=default; +SET GLOBAL log_slow_verbosity=default; +SET GLOBAL long_query_time=default; + +--let grep_pattern = No InnoDB statistics available for this query +--source include/log_grep.inc + --- /dev/null +++ b/mysql-test/r/percona_slow_query_log_use_global_control-cl.result @@ -0,0 +1,6 @@ +SHOW VARIABLES LIKE 'slow_query_log_use_global_control'; +Variable_name Value +slow_query_log_use_global_control log_slow_verbosity,long_query_time +SHOW GLOBAL VARIABLES LIKE 'slow_query_log_use_global_control'; +Variable_name Value +slow_query_log_use_global_control log_slow_verbosity,long_query_time --- /dev/null +++ b/mysql-test/t/percona_slow_query_log_use_global_control-cl-master.opt @@ -0,0 +1 @@ +--slow_query_log_use_global_control="log_slow_verbosity,long_query_time" --- /dev/null +++ b/mysql-test/t/percona_slow_query_log_use_global_control-cl.test @@ -0,0 +1,2 @@ +SHOW VARIABLES LIKE 'slow_query_log_use_global_control'; +SHOW GLOBAL VARIABLES LIKE 'slow_query_log_use_global_control'; --- /dev/null +++ b/mysql-test/r/percona_min_examined_row_limit.result @@ -0,0 +1,35 @@ +drop table if exists t; +create table t(id INT PRIMARY KEY); +insert into t values(1); +insert into t values(2); +insert into t values(3); +SET GLOBAL long_query_time=2; +SET GLOBAL slow_query_log_use_global_control='long_query_time,min_examined_row_limit'; +[log_start.inc] percona.slow_extended.min_examined_row_limit +SET SESSION query_exec_time=2.1; +SELECT 1; +1 +1 +SET GLOBAL min_examined_row_limit=5; +select * from t as t1, t as t2; +id id +1 1 +2 1 +3 1 +1 2 +2 2 +3 2 +1 3 +2 3 +3 3 +SELECT 1; +1 +1 +SET SESSION query_exec_time=default; +[log_stop.inc] percona.slow_extended.min_examined_row_limit +SET GLOBAL min_examined_row_limit=default; +SET GLOBAL slow_query_log_use_global_control=default; +SET GLOBAL long_query_time=default; +[log_grep.inc] file: percona.slow_extended.min_examined_row_limit pattern: Query_time +[log_grep.inc] lines: 1 +DROP TABLE t; --- /dev/null +++ b/mysql-test/t/percona_min_examined_row_limit.test @@ -0,0 +1,35 @@ +--source include/have_debug.inc + +--disable_warnings +drop table if exists t; +--enable_warnings + +create table t(id INT PRIMARY KEY); +insert into t values(1); +insert into t values(2); +insert into t values(3); + +SET GLOBAL long_query_time=2; +SET GLOBAL slow_query_log_use_global_control='long_query_time,min_examined_row_limit'; +--let log_file=percona.slow_extended.min_examined_row_limit +--source include/log_start.inc + +SET SESSION query_exec_time=2.1; +SELECT 1; + +SET GLOBAL min_examined_row_limit=5; + +select * from t as t1, t as t2; +SELECT 1; + +SET SESSION query_exec_time=default; + +--source include/log_stop.inc +SET GLOBAL min_examined_row_limit=default; +SET GLOBAL slow_query_log_use_global_control=default; +SET GLOBAL long_query_time=default; + +--let grep_pattern = Query_time +--source include/log_grep.inc + +DROP TABLE t; --- a/sql/log_event.cc +++ b/sql/log_event.cc @@ -2385,6 +2385,14 @@ start+= host.length; } } +#ifndef DBUG_OFF + if (thd && thd->variables.query_exec_time > 0) + { + *start++= Q_QUERY_EXEC_TIME; + int8store(start, thd->variables.query_exec_time); + start+= 8; + } +#endif /* NOTE: When adding new status vars, please don't forget to update the MAX_SIZE_LOG_EVENT_STATUS in log_event.h and update the function @@ -2871,6 +2879,17 @@ data_written= master_data_written= uint4korr(pos); pos+= 4; break; +#if !defined(DBUG_OFF) && !defined(MYSQL_CLIENT) + case Q_QUERY_EXEC_TIME: + { + THD *thd= current_thd; + CHECK_SPACE(pos, end, 8); + if (thd) + thd->variables.query_exec_time= uint8korr(pos); + pos+= 8; + break; + } +#endif case Q_INVOKER: { CHECK_SPACE(pos, end, 1); --- a/sql/log_event.h +++ b/sql/log_event.h @@ -343,6 +343,10 @@ #define Q_INVOKER 11 +#ifndef DBUG_OFF +#define Q_QUERY_EXEC_TIME 250 +#endif + /* Intvar event post-header */ /* Intvar event data */ --- /dev/null +++ b/mysql-test/suite/sys_vars/r/query_exec_time_basic.result @@ -0,0 +1,2 @@ +SET GLOBAL query_exec_time=default; +SET SESSION query_exec_time=default; --- /dev/null +++ b/mysql-test/suite/sys_vars/t/query_exec_time_basic.test @@ -0,0 +1,4 @@ +--source include/have_debug.inc + +SET GLOBAL query_exec_time=default; +SET SESSION query_exec_time=default; --- /dev/null +++ b/mysql-test/r/percona_log_slow_global_control_default.result @@ -0,0 +1 @@ +SET GLOBAL slow_query_log_use_global_control=default; --- /dev/null +++ b/mysql-test/t/percona_log_slow_global_control_default.test @@ -0,0 +1 @@ +SET GLOBAL slow_query_log_use_global_control=default; --- /dev/null +++ b/mysql-test/r/percona_slow_extended_log_error.result @@ -0,0 +1,10 @@ +SET long_query_time=0; +DROP TABLE IF EXISTS t1; +CREATE TABLE t(a INT); +[log_start.inc] percona.slow_extended.log_error +CREATE TABLE t(a INT); +ERROR 42S01: Table 't' already exists +[log_stop.inc] percona.slow_extended.log_error +[log_grep.inc] file: percona.slow_extended.log_error pattern: Last_errno: 1050 +[log_grep.inc] lines: 1 +DROP TABLE t; --- /dev/null +++ b/mysql-test/t/percona_slow_extended_log_error.test @@ -0,0 +1,15 @@ +--let log_file=percona.slow_extended.log_error +SET long_query_time=0; +--disable_warnings +DROP TABLE IF EXISTS t1; +--enable_warnings +CREATE TABLE t(a INT); +--source include/log_start.inc + +--error ER_TABLE_EXISTS_ERROR +CREATE TABLE t(a INT); + +--source include/log_stop.inc +--let grep_pattern = Last_errno: 1050 +--source include/log_grep.inc +DROP TABLE t; --- /dev/null +++ b/mysql-test/suite/sys_vars/t/log_slow_admin_statements_basic.test @@ -0,0 +1 @@ +SELECT @@global.log_slow_admin_statements; --- /dev/null +++ b/mysql-test/suite/sys_vars/r/log_slow_admin_statements_basic.result @@ -0,0 +1,3 @@ +SELECT @@global.log_slow_admin_statements; +@@global.log_slow_admin_statements +0 --- /dev/null +++ b/mysql-test/r/percona_log_slow_admin_statements.result @@ -0,0 +1,35 @@ +SHOW GLOBAL VARIABLES like 'log_slow_admin_statements'; +Variable_name Value +log_slow_admin_statements OFF +SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements'; +VARIABLE_NAME VARIABLE_VALUE +LOG_SLOW_ADMIN_STATEMENTS OFF +SET GLOBAL log_slow_admin_statements=true; +SHOW GLOBAL VARIABLES like 'log_slow_admin_statements'; +Variable_name Value +log_slow_admin_statements ON +SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements'; +VARIABLE_NAME VARIABLE_VALUE +LOG_SLOW_ADMIN_STATEMENTS ON +SET GLOBAL log_slow_admin_statements=false; +SHOW GLOBAL VARIABLES like 'log_slow_admin_statements'; +Variable_name Value +log_slow_admin_statements OFF +SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements'; +VARIABLE_NAME VARIABLE_VALUE +LOG_SLOW_ADMIN_STATEMENTS OFF +SET GLOBAL log_slow_admin_statements=foo; +ERROR 42000: Variable 'log_slow_admin_statements' can't be set to the value of 'foo' +SHOW GLOBAL VARIABLES like 'log_slow_admin_statements'; +Variable_name Value +log_slow_admin_statements OFF +SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements'; +VARIABLE_NAME VARIABLE_VALUE +LOG_SLOW_ADMIN_STATEMENTS OFF +SET GLOBAL log_slow_admin_statements=default; +SHOW GLOBAL VARIABLES like 'log_slow_admin_statements'; +Variable_name Value +log_slow_admin_statements OFF +SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements'; +VARIABLE_NAME VARIABLE_VALUE +LOG_SLOW_ADMIN_STATEMENTS OFF --- /dev/null +++ b/mysql-test/r/percona_log_slow_admin_statements-config_false.result @@ -0,0 +1,6 @@ +SHOW GLOBAL VARIABLES like 'log_slow_admin_statements'; +Variable_name Value +log_slow_admin_statements OFF +SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements'; +VARIABLE_NAME VARIABLE_VALUE +LOG_SLOW_ADMIN_STATEMENTS OFF --- /dev/null +++ b/mysql-test/r/percona_log_slow_admin_statements-config_foo.result @@ -0,0 +1,7 @@ +call mtr.add_suppression("option 'log_slow_admin_statements': boolean value 'foo' wasn't recognized. Set to OFF."); +SHOW GLOBAL VARIABLES like 'log_slow_admin_statements'; +Variable_name Value +log_slow_admin_statements OFF +SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements'; +VARIABLE_NAME VARIABLE_VALUE +LOG_SLOW_ADMIN_STATEMENTS OFF --- /dev/null +++ b/mysql-test/r/percona_log_slow_admin_statements-config_true.result @@ -0,0 +1,6 @@ +SHOW GLOBAL VARIABLES like 'log_slow_admin_statements'; +Variable_name Value +log_slow_admin_statements ON +SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements'; +VARIABLE_NAME VARIABLE_VALUE +LOG_SLOW_ADMIN_STATEMENTS ON --- /dev/null +++ b/mysql-test/r/percona_log_slow_admin_statements-config.result @@ -0,0 +1,6 @@ +SHOW GLOBAL VARIABLES like 'log_slow_admin_statements'; +Variable_name Value +log_slow_admin_statements ON +SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements'; +VARIABLE_NAME VARIABLE_VALUE +LOG_SLOW_ADMIN_STATEMENTS ON --- /dev/null +++ b/mysql-test/t/percona_log_slow_admin_statements-config_false.cnf @@ -0,0 +1,2 @@ +[mysqld.1] +log-slow-admin-statements=false --- /dev/null +++ b/mysql-test/t/percona_log_slow_admin_statements-config_foo.cnf @@ -0,0 +1,2 @@ +[mysqld.1] +log-slow-admin-statements=foo --- /dev/null +++ b/mysql-test/t/percona_log_slow_admin_statements-config_true.cnf @@ -0,0 +1,2 @@ +[mysqld.1] +log-slow-admin-statements=true --- /dev/null +++ b/mysql-test/t/percona_log_slow_admin_statements-config.cnf @@ -0,0 +1,2 @@ +[mysqld.1] +log-slow-admin-statements --- /dev/null +++ b/mysql-test/t/percona_log_slow_admin_statements.test @@ -0,0 +1,20 @@ +# default value +SHOW GLOBAL VARIABLES like 'log_slow_admin_statements'; +SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements'; +# set value to 'true' +SET GLOBAL log_slow_admin_statements=true; +SHOW GLOBAL VARIABLES like 'log_slow_admin_statements'; +SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements'; +# set value to 'false' +SET GLOBAL log_slow_admin_statements=false; +SHOW GLOBAL VARIABLES like 'log_slow_admin_statements'; +SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements'; +# set value to 'foo' +--error ER_WRONG_VALUE_FOR_VAR +SET GLOBAL log_slow_admin_statements=foo; +SHOW GLOBAL VARIABLES like 'log_slow_admin_statements'; +SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements'; +# set value to default +SET GLOBAL log_slow_admin_statements=default; +SHOW GLOBAL VARIABLES like 'log_slow_admin_statements'; +SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements'; --- /dev/null +++ b/mysql-test/t/percona_log_slow_admin_statements-config_false.test @@ -0,0 +1,2 @@ +SHOW GLOBAL VARIABLES like 'log_slow_admin_statements'; +SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements'; --- /dev/null +++ b/mysql-test/t/percona_log_slow_admin_statements-config_foo.test @@ -0,0 +1,3 @@ +call mtr.add_suppression("option 'log_slow_admin_statements': boolean value 'foo' wasn't recognized. Set to OFF."); +SHOW GLOBAL VARIABLES like 'log_slow_admin_statements'; +SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements'; --- /dev/null +++ b/mysql-test/t/percona_log_slow_admin_statements-config_true.test @@ -0,0 +1,2 @@ +SHOW GLOBAL VARIABLES like 'log_slow_admin_statements'; +SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements'; --- /dev/null +++ b/mysql-test/t/percona_log_slow_admin_statements-config.test @@ -0,0 +1,2 @@ +SHOW GLOBAL VARIABLES like 'log_slow_admin_statements'; +SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements'; --- a/mysql-test/r/mysqld--help-notwin.result +++ b/mysql-test/r/mysqld--help-notwin.result @@ -250,15 +250,38 @@ --log-slow-admin-statements Log slow OPTIMIZE, ANALYZE, ALTER and other administrative statements to the slow log if it is open. + --log-slow-filter=name + Log only the queries that followed certain execution + plan. Multiple flags allowed in a comma-separated string. + [qc_miss, full_scan, full_join, tmp_table, + tmp_table_on_disk, filesort, filesort_on_disk] --log-slow-queries[=name] Log slow queries to a table or log file. Defaults logging to table mysql.slow_log or hostname-slow.log if --log-output=file is used. Must be enabled to activate other slow log options. Deprecated option, use --slow-query-log/--slow-query-log-file instead. + --log-slow-rate-limit=# + Rate limit statement writes to slow log to only those + from every (1/log_slow_rate_limit) session. + --log-slow-rate-type=name + Choose the log_slow_rate_limit behavior: session or + query. When you choose 'session' - every + %log_slow_rate_limit connection will be processed to slow + query log. When you choose 'query' - every + %log_slow_rate_limit query will be processed to slow + query log. [session, query] --log-slow-slave-statements - Log slow statements executed by slave thread to the slow - log if it is open. + Log queries replayed be the slave SQL thread + --log-slow-sp-statements + Log slow statements executed by stored procedure to the + slow log if it is open. + (Defaults to on; use --skip-log-slow-sp-statements to disable.) + --log-slow-verbosity=name + Choose how verbose the messages to your slow log will be. + Multiple flags allowed in a comma-separated string. + [microtime, query_plan, innodb, profiling, + profiling_use_getrusage] --log-tc=name Path to transaction coordinator log (used for transactions that affect more than one storage engine, when binary log is disabled). @@ -660,6 +683,18 @@ Log slow queries to given log file. Defaults logging to hostname-slow.log. Must be enabled to activate other slow log options + --slow-query-log-timestamp-always + Timestamp is printed for all records of the slow log even + if they are same time. + --slow-query-log-timestamp-precision=name + Log slow statements executed by stored procedure to the + slow log if it is open. [second, microsecond] + --slow-query-log-use-global-control=name + Choose flags, wich always use the global variables. + Multiple flags allowed in a comma-separated string. + [none, log_slow_filter, log_slow_rate_limit, + log_slow_verbosity, long_query_time, + min_examined_row_limit, all] --socket=name Socket file to use for connection --sort-buffer-size=# Each thread that needs to do a sort allocates a buffer of @@ -817,7 +852,12 @@ log-short-format FALSE log-slave-updates FALSE log-slow-admin-statements FALSE +log-slow-filter +log-slow-rate-limit 1 +log-slow-rate-type session log-slow-slave-statements FALSE +log-slow-sp-statements TRUE +log-slow-verbosity log-tc tc.log log-tc-size 24576 log-warnings 1 @@ -933,6 +973,9 @@ slave-type-conversions slow-launch-time 2 slow-query-log FALSE +slow-query-log-timestamp-always FALSE +slow-query-log-timestamp-precision second +slow-query-log-use-global-control sort-buffer-size 2097152 sporadic-binlog-dump-fail FALSE sql-mode --- /dev/null +++ b/mysql-test/r/percona_slow_query_log_rate.result @@ -0,0 +1,78 @@ +SET GLOBAL long_query_time=1; +SET GLOBAL log_slow_rate_type='session'; +SET GLOBAL log_slow_rate_limit=3; +[log_start.inc] percona.slow_extended.log_slow_rate_limit +SET SESSION query_exec_time=1.1; +SET SESSION query_exec_id=1; +SELECT 'connection_one'; +connection_one +connection_one +SET SESSION query_exec_time=1.1; +SET SESSION query_exec_id=2; +SELECT 'connection_two'; +connection_two +connection_two +SET SESSION query_exec_time=1.1; +SET SESSION query_exec_id=3; +SELECT 'connection_three'; +connection_three +connection_three +SET SESSION query_exec_time=1.1; +SET SESSION query_exec_id=4; +SELECT 'connection_one'; +connection_one +connection_one +SET SESSION query_exec_time=1.1; +SET SESSION query_exec_id=5; +SELECT 'connection_two'; +connection_two +connection_two +SET SESSION query_exec_time=1.1; +SET SESSION query_exec_id=6; +SELECT 'connection_three'; +connection_three +connection_three +[log_stop.inc] percona.slow_extended.log_slow_rate_limit +[log_grep.inc] file: percona.slow_extended.log_slow_rate_limit pattern: +[log_grep.inc] sum: 2 +[log_grep.inc] zero: 2 +SET GLOBAL log_slow_rate_type='query'; +SET GLOBAL log_slow_rate_limit=2; +[log_start.inc] percona.slow_extended.log_slow_rate_limit +SET SESSION query_exec_time=1.1; +SET SESSION query_exec_id=1; +SELECT 'connection_one'; +connection_one +connection_one +SET SESSION query_exec_time=1.1; +SET SESSION query_exec_id=2; +SELECT 'connection_two'; +connection_two +connection_two +SET SESSION query_exec_time=1.1; +SET SESSION query_exec_id=3; +SELECT 'connection_three'; +connection_three +connection_three +SET SESSION query_exec_time=1.1; +SET SESSION query_exec_id=4; +SELECT 'connection_one'; +connection_one +connection_one +SET SESSION query_exec_time=1.1; +SET SESSION query_exec_id=5; +SELECT 'connection_two'; +connection_two +connection_two +SET SESSION query_exec_time=1.1; +SET SESSION query_exec_id=6; +SELECT 'connection_three'; +connection_three +connection_three +[log_stop.inc] percona.slow_extended.log_slow_rate_limit +[log_grep.inc] file: percona.slow_extended.log_slow_rate_limit pattern: +[log_grep.inc] sum: 3 +[log_grep.inc] zero: 0 +SET GLOBAL long_query_time=default; +SET GLOBAL log_slow_rate_type=default; +SET GLOBAL log_slow_rate_limit=default; --- /dev/null +++ b/mysql-test/t/percona_slow_query_log_rate.test @@ -0,0 +1,16 @@ +--source include/have_debug.inc +--let log_file=percona.slow_extended.log_slow_rate_limit + +SET GLOBAL long_query_time=1; + +SET GLOBAL log_slow_rate_type='session'; +SET GLOBAL log_slow_rate_limit=3; +--source include/percona_slow_query_log_rate.inc + +SET GLOBAL log_slow_rate_type='query'; +SET GLOBAL log_slow_rate_limit=2; +--source include/percona_slow_query_log_rate.inc + +SET GLOBAL long_query_time=default; +SET GLOBAL log_slow_rate_type=default; +SET GLOBAL log_slow_rate_limit=default; --- /dev/null +++ b/mysql-test/suite/sys_vars/t/log_slow_rate_limit_basic.test @@ -0,0 +1 @@ +SELECT @@global.log_slow_rate_limit; --- /dev/null +++ b/mysql-test/suite/sys_vars/r/log_slow_rate_limit_basic.result @@ -0,0 +1,3 @@ +SELECT @@global.log_slow_rate_limit; +@@global.log_slow_rate_limit +1 --- /dev/null +++ b/mysql-test/suite/sys_vars/t/log_slow_rate_type_basic.test @@ -0,0 +1 @@ +SELECT @@global.log_slow_rate_type; --- /dev/null +++ b/mysql-test/suite/sys_vars/r/log_slow_rate_type_basic.result @@ -0,0 +1,3 @@ +SELECT @@global.log_slow_rate_type; +@@global.log_slow_rate_type +session --- /dev/null +++ b/mysql-test/include/percona_slow_query_log_rate.inc @@ -0,0 +1,42 @@ +--let wait_condition=SELECT COUNT(*) = 1 FROM INFORMATION_SCHEMA.PROCESSLIST; +--connection default +--source include/log_start.inc + +--connect (connection_one,localhost,root,,) +--connect (connection_two,localhost,root,,) +--connect (connection_three,localhost,root,,) + +--let i=2 +--let k=1 + +while($i) +{ +--connection connection_one +SET SESSION query_exec_time=1.1; +eval SET SESSION query_exec_id=$k; +inc $k; +SELECT 'connection_one'; + +--connection connection_two +SET SESSION query_exec_time=1.1; +eval SET SESSION query_exec_id=$k; +inc $k; +SELECT 'connection_two'; + +--connection connection_three +SET SESSION query_exec_time=1.1; +eval SET SESSION query_exec_id=$k; +inc $k; +SELECT 'connection_three'; + +dec $i; +} + +--connection default +--disconnect connection_one +--disconnect connection_two +--disconnect connection_three +--source include/wait_condition.inc +--source include/log_stop.inc +--let log_slow_rate_test=1 +--source include/log_grep.inc --- /dev/null +++ b/mysql-test/suite/sys_vars/r/query_exec_id_basic.result @@ -0,0 +1,2 @@ +SET GLOBAL query_exec_id=default; +SET SESSION query_exec_id=default; --- /dev/null +++ b/mysql-test/suite/sys_vars/t/query_exec_id_basic.test @@ -0,0 +1,4 @@ +--source include/have_debug.inc + +SET GLOBAL query_exec_id=default; +SET SESSION query_exec_id=default;