=== slowlog_1.diff === diff --git a/mysql-test/r/mysqld--help-notwin.result b/mysql-test/r/mysqld--help-notwin.result index 7a06037..2e76fa7 100644 --- a/mysql-test/r/mysqld--help-notwin.result +++ b/mysql-test/r/mysqld--help-notwin.result @@ -483,6 +483,7 @@ The following options may be given as the first argument: --log-slow-admin-statements Log slow OPTIMIZE, ANALYZE, ALTER and other administrative statements to the slow log if it is open. + --log-slow-extra Print more attributes to the slow query log --log-slow-slave-statements Log slow statements executed by slave thread to the slow log if it is open. @@ -1447,6 +1448,7 @@ log-raw FALSE log-short-format FALSE log-slave-updates FALSE log-slow-admin-statements FALSE +log-slow-extra FALSE log-slow-slave-statements FALSE log-statements-unsafe-for-binlog TRUE log-syslog FALSE diff --git a/mysql-test/r/slow_log.result b/mysql-test/r/slow_log.result new file mode 100644 index 0000000..edcd52e --- /dev/null +++ b/mysql-test/r/slow_log.result @@ -0,0 +1,4 @@ +set timestamp=10; +select unix_timestamp(), sleep(2); +unix_timestamp() sleep(2) +10 0 diff --git a/mysql-test/r/slow_log_extra.result b/mysql-test/r/slow_log_extra.result new file mode 100644 index 0000000..edcd52e --- /dev/null +++ b/mysql-test/r/slow_log_extra.result @@ -0,0 +1,4 @@ +set timestamp=10; +select unix_timestamp(), sleep(2); +unix_timestamp() sleep(2) +10 0 diff --git a/mysql-test/t/slow_log-master.opt b/mysql-test/t/slow_log-master.opt new file mode 100644 index 0000000..445da5d --- /dev/null +++ b/mysql-test/t/slow_log-master.opt @@ -0,0 +1 @@ +--slow-query-log=1 --long-query-time=1 diff --git a/mysql-test/t/slow_log.test b/mysql-test/t/slow_log.test new file mode 100644 index 0000000..e4c968e --- /dev/null +++ b/mysql-test/t/slow_log.test @@ -0,0 +1,7 @@ +set timestamp=10; +select unix_timestamp(), sleep(2); + +let $MYSQLD_DATADIR= `select @@datadir`; +--exec [ "1" -eq `grep "SET timestamp=10;" $MYSQLD_DATADIR/../mysqld-slow.log | wc -l` ] + +--exit diff --git a/mysql-test/t/slow_log_extra-master.opt b/mysql-test/t/slow_log_extra-master.opt new file mode 100644 index 0000000..08e4f3e --- /dev/null +++ b/mysql-test/t/slow_log_extra-master.opt @@ -0,0 +1 @@ +--slow-query-log=1 --long-query-time=1 --log-slow-extra=1 diff --git a/mysql-test/t/slow_log_extra.test b/mysql-test/t/slow_log_extra.test new file mode 100644 index 0000000..e4c968e --- /dev/null +++ b/mysql-test/t/slow_log_extra.test @@ -0,0 +1,7 @@ +set timestamp=10; +select unix_timestamp(), sleep(2); + +let $MYSQLD_DATADIR= `select @@datadir`; +--exec [ "1" -eq `grep "SET timestamp=10;" $MYSQLD_DATADIR/../mysqld-slow.log | wc -l` ] + +--exit diff --git a/sql/log.cc b/sql/log.cc index aa9ea93..008eea0 100644 --- a/sql/log.cc +++ b/sql/log.cc @@ -632,6 +632,7 @@ err: bool File_query_log::write_slow(THD *thd, ulonglong current_utime, + ulonglong query_start_utime, const char *user_host, size_t, ulonglong query_utime, ulonglong lock_utime, bool is_command, @@ -667,13 +668,60 @@ bool File_query_log::write_slow(THD *thd, ulonglong current_utime, /* For slow query log */ sprintf(query_time_buff, "%.6f", ulonglong2double(query_utime)/1000000.0); sprintf(lock_time_buff, "%.6f", ulonglong2double(lock_utime)/1000000.0); - if (my_b_printf(&log_file, - "# Query_time: %s Lock_time: %s" - " Rows_sent: %lu Rows_examined: %lu\n", - query_time_buff, lock_time_buff, - (ulong) thd->get_sent_row_count(), - (ulong) thd->get_examined_row_count()) == (uint) -1) - goto err; + if (!opt_log_slow_extra) { + if (my_b_printf(&log_file, + "# Query_time: %s Lock_time: %s" + " Rows_sent: %lu Rows_examined: %lu\n", + query_time_buff, lock_time_buff, + (ulong) thd->get_sent_row_count(), + (ulong) thd->get_examined_row_count()) == (uint) -1) + goto err; + } + else + { + char start_time_buff[iso8601_size], end_time_buff[iso8601_size]; + make_iso8601_timestamp(end_time_buff, current_utime, opt_log_timestamps); + if (query_start_utime) { + make_iso8601_timestamp(start_time_buff, query_start_utime, + opt_log_timestamps); + } + if (my_b_printf(&log_file, + "# Query_time: %s Lock_time: %s" + " Rows_sent: %lu Rows_examined: %lu" + " Thread_id: %lu Errno: %lu Killed: %lu" + " Bytes_received: %lu Bytes_sent: %lu" + " Read_first: %lu Read_last: %lu Read_key: %lu" + " Read_next: %lu Read_prev: %lu" + " Read_rnd: %lu Read_rnd_next: %lu" + " Sort_merge_passes: %lu Sort_range_count: %lu" + " Sort_rows: %lu Sort_scan_count: %lu" + " Created_tmp_disk_tables: %lu" + " Created_tmp_tables: %lu" + " Start: %s End: %s\n", + query_time_buff, lock_time_buff, + (ulong) thd->get_sent_row_count(), + (ulong) thd->get_examined_row_count(), + (ulong) thd->thread_id(), + (ulong) thd->get_protocol_classic()->get_net()->last_errno, + (ulong) thd->killed, + (ulong) thd->status_var.bytes_received, + (ulong) thd->status_var.bytes_sent, + (ulong) thd->status_var.ha_read_first_count, + (ulong) thd->status_var.ha_read_last_count, + (ulong) thd->status_var.ha_read_key_count, + (ulong) thd->status_var.ha_read_next_count, + (ulong) thd->status_var.ha_read_prev_count, + (ulong) thd->status_var.ha_read_rnd_count, + (ulong) thd->status_var.ha_read_rnd_next_count, + (ulong) thd->status_var.filesort_merge_passes, + (ulong) thd->status_var.filesort_range_count, + (ulong) thd->status_var.filesort_rows, + (ulong) thd->status_var.filesort_scan_count, + (ulong) thd->status_var.created_tmp_disk_tables, + (ulong) thd->status_var.created_tmp_tables, + start_time_buff, end_time_buff) == (uint) -1) + goto err; + } if (thd->db().str && strcmp(thd->db().str, db)) { // Database changed if (my_b_printf(&log_file,"use %s;\n",thd->db().str) == (uint) -1) @@ -700,12 +748,12 @@ bool File_query_log::write_slow(THD *thd, ulonglong current_utime, } /* - This info used to show up randomly, depending on whether the query - checked the query start time or not. now we always write current - timestamp to the slow log + The timestamp used to only be set when the query had checked the + start time. Now the slow log always logs the query start time. + This ensures logs can be used to replicate queries accurately. */ end= my_stpcpy(end, ",timestamp="); - end= int10_to_str((long) (current_utime / 1000000), end, 10); + end= int10_to_str((long) (query_start_utime / 1000000), end, 10); if (end != buff) { @@ -1094,7 +1142,7 @@ bool Log_to_csv_event_handler::activate_log(THD *thd, bool Log_to_file_event_handler::log_slow(THD *thd, ulonglong current_utime, - ulonglong, + ulonglong query_start_utime, const char *user_host, size_t user_host_len, ulonglong query_utime, @@ -1108,7 +1156,7 @@ bool Log_to_file_event_handler::log_slow(THD *thd, ulonglong current_utime, Silence_log_table_errors error_handler; thd->push_internal_handler(&error_handler); - bool retval= mysql_slow_log.write_slow(thd, current_utime, + bool retval= mysql_slow_log.write_slow(thd, current_utime, query_start_utime, user_host, user_host_len, query_utime, lock_utime, is_command, sql_text, sql_text_len); diff --git a/sql/log.h b/sql/log.h index db6af7b..56b5ace 100644 --- a/sql/log.h +++ b/sql/log.h @@ -224,6 +224,7 @@ class File_query_log @param thd THD of the query @param current_utime Current timestamp in micro seconds + @param query_start_arg Command start timestamp in micro seconds @param user_host The pointer to the string with user\@host info @param user_host_len Length of the user_host string. this is computed once and passed to all general log event handlers @@ -238,6 +239,7 @@ class File_query_log @return true if error, false otherwise. */ bool write_slow(THD *thd, ulonglong current_utime, + ulonglong query_start_arg, const char *user_host, size_t user_host_len, ulonglong query_utime, ulonglong lock_utime, bool is_command, const char *sql_text, size_t sql_text_len); diff --git a/sql/mysqld.cc b/sql/mysqld.cc index 30cb27a..a91432d 100644 --- a/sql/mysqld.cc +++ b/sql/mysqld.cc @@ -984,6 +984,7 @@ bool thread_cache_size_specified= false; bool host_cache_size_specified= false; bool table_definition_cache_specified= false; ulong locked_account_connection_count= 0; +bool opt_log_slow_extra= false; /** Limit of the total number of prepared statements in the server. @@ -7489,6 +7490,10 @@ struct my_option my_long_options[]= "The option will be removed in a future release.", 0, 0, 0, GET_BOOL, OPT_ARG, 0, 0, 0, 0, 0, 0}, + {"log_slow_extra", OPT_LOG_SLOW_EXTRA, + "Print more attributes to the slow query log", + &opt_log_slow_extra, &opt_log_slow_extra, 0, + GET_BOOL, NO_ARG, 0, 0, 0, 0, 0, 0}, {0, 0, 0, 0, 0, 0, GET_NO_ARG, NO_ARG, 0, 0, 0, 0, 0, 0} }; @@ -8542,6 +8547,8 @@ static int mysql_init_variables() #endif /* defined(ENABLED_DEBUG_SYNC) */ server_uuid[0]= 0; + opt_log_slow_extra= FALSE; + /* Character sets */ system_charset_info= &my_charset_utf8_general_ci; files_charset_info= &my_charset_utf8_general_ci; diff --git a/sql/mysqld.h b/sql/mysqld.h index 2951cd5..d673ab9 100644 --- a/sql/mysqld.h +++ b/sql/mysqld.h @@ -313,6 +313,8 @@ enum enum_binlog_error_action }; extern const char *binlog_error_action_list[]; +extern bool opt_log_slow_extra; + /* SHOW STATS var: Name of current timer */ extern const char *timer_in_use; /* Current timer stats */ diff --git a/sql/options_mysqld.h b/sql/options_mysqld.h index dee83f9..cb128a7 100644 --- a/sql/options_mysqld.h +++ b/sql/options_mysqld.h @@ -103,7 +103,8 @@ enum options_mysqld OPT_KEYRING_MIGRATION_SOCKET, OPT_KEYRING_MIGRATION_PORT, OPT_LOG_SLAVE_UPDATES, - OPT_SLAVE_PRESERVE_COMMIT_ORDER + OPT_SLAVE_PRESERVE_COMMIT_ORDER, + OPT_LOG_SLOW_EXTRA }; === slowlog_2.diff === diff --git a/mysql-test/r/slow_log_extra.result b/mysql-test/r/slow_log_extra.result index edcd52e..f668d5d 100644 --- a/mysql-test/r/slow_log_extra.result +++ b/mysql-test/r/slow_log_extra.result @@ -2,3 +2,69 @@ set timestamp=10; select unix_timestamp(), sleep(2); unix_timestamp() sleep(2) 10 0 +set global long_query_time=0; +drop table if exists islow; +drop table if exists mslow; +create table islow(i int) engine=innodb; +insert into islow values (1), (2), (3), (4), (5), (6), (7), (8); +create table mslow(i int) engine=myisam; +insert into mslow values (1), (2), (3), (4), (5), (6), (7), (8); +select * from islow; +i +1 +2 +3 +4 +5 +6 +7 +8 +select * from islow; +i +1 +2 +3 +4 +5 +6 +7 +8 +select * from mslow; +i +1 +2 +3 +4 +5 +6 +7 +8 +select * from mslow; +i +1 +2 +3 +4 +5 +6 +7 +8 +set global long_query_time=1; +drop table islow; +drop table mslow; +# +# This is a hack to check the log result. +# We strip off time related fields (non-deterministic) ana verify the rest are correct. +# +Rows_sent: 1 Rows_examined: 0 Thread_id: 8 Errno: 0 Killed: 0 Bytes_received: 0 Bytes_sent: 101 Read_first: 0 Read_last: 0 Read_key: 0 Read_next: 0 Read_prev: 0 Read_rnd: 0 Read_rnd_next: 0 Sort_merge_passes: 0 Sort_range_count: 0 Sort_rows: 0 Sort_scan_count: 0 Created_tmp_disk_tables: 0 Created_tmp_tables: 0 +Rows_sent: 0 Rows_examined: 0 Thread_id: 9 Errno: 0 Killed: 0 Bytes_received: 0 Bytes_sent: 11 Read_first: 0 Read_last: 0 Read_key: 4 Read_next: 0 Read_prev: 0 Read_rnd: 0 Read_rnd_next: 0 Sort_merge_passes: 0 Sort_range_count: 0 Sort_rows: 0 Sort_scan_count: 0 Created_tmp_disk_tables: 0 Created_tmp_tables: 0 +Rows_sent: 0 Rows_examined: 0 Thread_id: 9 Errno: 0 Killed: 0 Bytes_received: 0 Bytes_sent: 11 Read_first: 0 Read_last: 0 Read_key: 4 Read_next: 0 Read_prev: 0 Read_rnd: 0 Read_rnd_next: 0 Sort_merge_passes: 0 Sort_range_count: 0 Sort_rows: 0 Sort_scan_count: 0 Created_tmp_disk_tables: 0 Created_tmp_tables: 0 +Rows_sent: 0 Rows_examined: 0 Thread_id: 9 Errno: 0 Killed: 0 Bytes_received: 0 Bytes_sent: 11 Read_first: 0 Read_last: 0 Read_key: 18 Read_next: 0 Read_prev: 0 Read_rnd: 0 Read_rnd_next: 0 Sort_merge_passes: 0 Sort_range_count: 0 Sort_rows: 0 Sort_scan_count: 0 Created_tmp_disk_tables: 0 Created_tmp_tables: 0 +Rows_sent: 0 Rows_examined: 0 Thread_id: 9 Errno: 0 Killed: 0 Bytes_received: 0 Bytes_sent: 50 Read_first: 0 Read_last: 0 Read_key: 10 Read_next: 9 Read_prev: 0 Read_rnd: 0 Read_rnd_next: 0 Sort_merge_passes: 0 Sort_range_count: 0 Sort_rows: 0 Sort_scan_count: 0 Created_tmp_disk_tables: 0 Created_tmp_tables: 0 +Rows_sent: 0 Rows_examined: 0 Thread_id: 9 Errno: 0 Killed: 0 Bytes_received: 0 Bytes_sent: 11 Read_first: 0 Read_last: 0 Read_key: 11 Read_next: 1 Read_prev: 0 Read_rnd: 0 Read_rnd_next: 0 Sort_merge_passes: 0 Sort_range_count: 0 Sort_rows: 0 Sort_scan_count: 0 Created_tmp_disk_tables: 0 Created_tmp_tables: 0 +Rows_sent: 0 Rows_examined: 0 Thread_id: 9 Errno: 0 Killed: 0 Bytes_received: 0 Bytes_sent: 50 Read_first: 0 Read_last: 0 Read_key: 1 Read_next: 0 Read_prev: 0 Read_rnd: 0 Read_rnd_next: 0 Sort_merge_passes: 0 Sort_range_count: 0 Sort_rows: 0 Sort_scan_count: 0 Created_tmp_disk_tables: 0 Created_tmp_tables: 0 +Rows_sent: 8 Rows_examined: 8 Thread_id: 9 Errno: 0 Killed: 0 Bytes_received: 0 Bytes_sent: 106 Read_first: 1 Read_last: 0 Read_key: 1 Read_next: 0 Read_prev: 0 Read_rnd: 0 Read_rnd_next: 9 Sort_merge_passes: 0 Sort_range_count: 0 Sort_rows: 0 Sort_scan_count: 0 Created_tmp_disk_tables: 0 Created_tmp_tables: 0 +Rows_sent: 8 Rows_examined: 8 Thread_id: 9 Errno: 0 Killed: 0 Bytes_received: 0 Bytes_sent: 106 Read_first: 1 Read_last: 0 Read_key: 1 Read_next: 0 Read_prev: 0 Read_rnd: 0 Read_rnd_next: 9 Sort_merge_passes: 0 Sort_range_count: 0 Sort_rows: 0 Sort_scan_count: 0 Created_tmp_disk_tables: 0 Created_tmp_tables: 0 +Rows_sent: 8 Rows_examined: 8 Thread_id: 9 Errno: 0 Killed: 0 Bytes_received: 0 Bytes_sent: 106 Read_first: 0 Read_last: 0 Read_key: 0 Read_next: 0 Read_prev: 0 Read_rnd: 0 Read_rnd_next: 9 Sort_merge_passes: 0 Sort_range_count: 0 Sort_rows: 0 Sort_scan_count: 0 Created_tmp_disk_tables: 0 Created_tmp_tables: 0 +Rows_sent: 8 Rows_examined: 8 Thread_id: 9 Errno: 0 Killed: 0 Bytes_received: 0 Bytes_sent: 106 Read_first: 0 Read_last: 0 Read_key: 0 Read_next: 0 Read_prev: 0 Read_rnd: 0 Read_rnd_next: 9 Sort_merge_passes: 0 Sort_range_count: 0 Sort_rows: 0 Sort_scan_count: 0 Created_tmp_disk_tables: 0 Created_tmp_tables: 0 +Rows_sent: 0 Rows_examined: 8 Thread_id: 9 Errno: 0 Killed: 0 Bytes_received: 0 Bytes_sent: 0 Read_first: 0 Read_last: 0 Read_key: 0 Read_next: 0 Read_prev: 0 Read_rnd: 0 Read_rnd_next: 0 Sort_merge_passes: 0 Sort_range_count: 0 Sort_rows: 0 Sort_scan_count: 0 Created_tmp_disk_tables: 0 Created_tmp_tables: 0 diff --git a/mysql-test/r/slow_log_extra_big.result b/mysql-test/r/slow_log_extra_big.result new file mode 100644 index 0000000..c470ccd --- /dev/null +++ b/mysql-test/r/slow_log_extra_big.result @@ -0,0 +1,36 @@ +set @my_slow_logname = @@global.slow_query_log_file; +set global slow_query_log_file = "slow_log_extra_big-slow.log"; +set session long_query_time = 20; +set global long_query_time = 0; +select count(*) from big_table_slow; +count(*) +200 +select count(*) from big_table_slow; +count(*) +200 +select count(*) from big_table_slow where id>100 and id<200; +count(*) +49 +select * from big_table_slow where id=2; +id v t +2 v bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbba +select count(*) from big_table_slow where id >100; +count(*) +150 +select count(*) from big_table_slow where id < 100; +count(*) +49 +# Cleanup +set global slow_query_log_file = @my_slow_logname; +set global long_query_time=1; +drop table big_table_slow; +# +# This is a hack to check the log result. +# We strip off time related fields (non-deterministic) and verify the rest are correct. +# +Rows_sent: 1 Rows_examined: 0 Errno: 0 Killed: 0 Bytes_received: 0 Bytes_sent: 58 Read_first: 0 Read_last: 0 Read_key: 0 Read_next: 0 Read_prev: 0 Read_rnd: 0 Read_rnd_next: 0 Sort_merge_passes: 0 Sort_range_count: 0 Sort_rows: 0 Sort_scan_count: 0 Created_tmp_disk_tables: 0 Created_tmp_tables: 0 +Rows_sent: 1 Rows_examined: 0 Errno: 0 Killed: 0 Bytes_received: 0 Bytes_sent: 58 Read_first: 0 Read_last: 0 Read_key: 0 Read_next: 0 Read_prev: 0 Read_rnd: 0 Read_rnd_next: 0 Sort_merge_passes: 0 Sort_range_count: 0 Sort_rows: 0 Sort_scan_count: 0 Created_tmp_disk_tables: 0 Created_tmp_tables: 0 +Rows_sent: 1 Rows_examined: 49 Errno: 0 Killed: 0 Bytes_received: 0 Bytes_sent: 57 Read_first: 0 Read_last: 0 Read_key: 1 Read_next: 49 Read_prev: 0 Read_rnd: 0 Read_rnd_next: 0 Sort_merge_passes: 0 Sort_range_count: 0 Sort_rows: 0 Sort_scan_count: 0 Created_tmp_disk_tables: 0 Created_tmp_tables: 0 +Rows_sent: 1 Rows_examined: 1 Errno: 0 Killed: 0 Bytes_received: 0 Bytes_sent: 307 Read_first: 0 Read_last: 0 Read_key: 1 Read_next: 0 Read_prev: 0 Read_rnd: 0 Read_rnd_next: 0 Sort_merge_passes: 0 Sort_range_count: 0 Sort_rows: 0 Sort_scan_count: 0 Created_tmp_disk_tables: 0 Created_tmp_tables: 0 +Rows_sent: 1 Rows_examined: 150 Errno: 0 Killed: 0 Bytes_received: 0 Bytes_sent: 58 Read_first: 0 Read_last: 0 Read_key: 1 Read_next: 150 Read_prev: 0 Read_rnd: 0 Read_rnd_next: 0 Sort_merge_passes: 0 Sort_range_count: 0 Sort_rows: 0 Sort_scan_count: 0 Created_tmp_disk_tables: 0 Created_tmp_tables: 0 +Rows_sent: 1 Rows_examined: 49 Errno: 0 Killed: 0 Bytes_received: 0 Bytes_sent: 57 Read_first: 1 Read_last: 0 Read_key: 1 Read_next: 49 Read_prev: 0 Read_rnd: 0 Read_rnd_next: 0 Sort_merge_passes: 0 Sort_range_count: 0 Sort_rows: 0 Sort_scan_count: 0 Created_tmp_disk_tables: 0 Created_tmp_tables: 0 diff --git a/mysql-test/t/slow_log_extra.test b/mysql-test/t/slow_log_extra.test index e4c968e..2e0c62c 100644 --- a/mysql-test/t/slow_log_extra.test +++ b/mysql-test/t/slow_log_extra.test @@ -1,7 +1,57 @@ +# +# Test --log-slow-extra +# + set timestamp=10; select unix_timestamp(), sleep(2); let $MYSQLD_DATADIR= `select @@datadir`; --exec [ "1" -eq `grep "SET timestamp=10;" $MYSQLD_DATADIR/../mysqld-slow.log | wc -l` ] +# +# Confirm that per-query stats work. +# + +set global long_query_time=0; +connect (con,localhost,root,,); + +--disable_warnings +drop table if exists islow; +drop table if exists mslow; +--enable_warnings + +create table islow(i int) engine=innodb; +insert into islow values (1), (2), (3), (4), (5), (6), (7), (8); + +create table mslow(i int) engine=myisam; +insert into mslow values (1), (2), (3), (4), (5), (6), (7), (8); + +select * from islow; +select * from islow; + +select * from mslow; +select * from mslow; + +connection default; +set global long_query_time=1; +disconnect con; +drop table islow; +drop table mslow; + +--echo # +--echo # This is a hack to check the log result. +--echo # We strip off time related fields (non-deterministic) ana verify the rest are correct. +--echo # + +--perl +open FILE, "$ENV{'MYSQLTEST_VARDIR'}/mysqld.1/mysqld-slow.log" or die; +my @lines = ; +foreach $line (@lines) { + if ($line =~ m/^# Query_time/) { + $line =~ m/(Rows_sent.*) Start.*/; + print "$1\n"; + } +} +EOF + --exit diff --git a/mysql-test/t/slow_log_extra_big-master.opt b/mysql-test/t/slow_log_extra_big-master.opt new file mode 100644 index 0000000..92a5c86 --- /dev/null +++ b/mysql-test/t/slow_log_extra_big-master.opt @@ -0,0 +1 @@ +--innodb_file_per_table --innodb_buffer_pool_size=20M --slow-query-log=1 --long-query-time=1 --log-slow-extra=1 diff --git a/mysql-test/t/slow_log_extra_big.test b/mysql-test/t/slow_log_extra_big.test new file mode 100644 index 0000000..ab7b507 --- /dev/null +++ b/mysql-test/t/slow_log_extra_big.test @@ -0,0 +1,72 @@ +# +# Test --log-slow-extra +# + +--source include/count_sessions.inc + +set @my_slow_logname = @@global.slow_query_log_file; +set global slow_query_log_file = "slow_log_extra_big-slow.log"; + +# +# Confirm that per-query stats work. +# +set session long_query_time = 20; +--disable_warnings +--disable_query_log +drop table if exists big_table_slow; +create table big_table_slow (id int primary key auto_increment, v varchar(100), t text) engine=innodb key_block_size=8; + +let $x = 200; +while ($x) +{ +eval insert into big_table_slow values(2 * $x, lpad("v", $x mod 100, "b"), lpad("a", ($x * 100) mod 9000, "b")); +dec $x; +} + +--enable_query_log +--enable_warnings + +set global long_query_time = 0; + +connect (con,localhost,root,,); +select count(*) from big_table_slow; + +connect (con1,localhost,root,,); +select count(*) from big_table_slow; + +select count(*) from big_table_slow where id>100 and id<200; + +select * from big_table_slow where id=2; + +select count(*) from big_table_slow where id >100; + +select count(*) from big_table_slow where id < 100; + +--echo # Cleanup + +connection default; +set global slow_query_log_file = @my_slow_logname; + +set global long_query_time=1; +disconnect con1; +disconnect con; +--source include/wait_until_count_sessions.inc +drop table big_table_slow; + +--echo # +--echo # This is a hack to check the log result. +--echo # We strip off time related fields (non-deterministic) and verify the rest are correct. +--echo # + +--perl +open FILE, "$ENV{'MYSQLTEST_VARDIR'}/mysqld.1/data/slow_log_extra_big-slow.log" or die; +my @lines = ; +foreach $line (@lines) { + if ($line =~ m/^# Query_time/) { + $line =~ m/(Rows_sent.*) Thread_id.* (Errno.*) Start.*/; + print "$1 $2\n"; + } +} +EOF + +--exit diff --git a/sql/log.cc b/sql/log.cc index 2494992..741c6f0 100644 --- a/sql/log.cc +++ b/sql/log.cc @@ -636,7 +636,8 @@ bool File_query_log::write_slow(THD *thd, ulonglong current_utime, const char *user_host, size_t, ulonglong query_utime, ulonglong lock_utime, bool is_command, - const char *sql_text, size_t sql_text_len) + const char *sql_text, size_t sql_text_len, + struct System_status_var *query_start) { char buff[80], *end; char query_time_buff[22+7], lock_time_buff[22+7]; @@ -668,7 +669,7 @@ bool File_query_log::write_slow(THD *thd, ulonglong current_utime, /* For slow query log */ sprintf(query_time_buff, "%.6f", ulonglong2double(query_utime)/1000000.0); sprintf(lock_time_buff, "%.6f", ulonglong2double(lock_utime)/1000000.0); - if (!opt_log_slow_extra) { + if (!query_start) { if (my_b_printf(&log_file, "# Query_time: %s Lock_time: %s" " Rows_sent: %lu Rows_examined: %lu\n", @@ -704,21 +705,36 @@ bool File_query_log::write_slow(THD *thd, ulonglong current_utime, (ulong) thd->thread_id(), (ulong) thd->get_protocol_classic()->get_net()->last_errno, (ulong) thd->killed, - (ulong) thd->status_var.bytes_received, - (ulong) thd->status_var.bytes_sent, - (ulong) thd->status_var.ha_read_first_count, - (ulong) thd->status_var.ha_read_last_count, - (ulong) thd->status_var.ha_read_key_count, - (ulong) thd->status_var.ha_read_next_count, - (ulong) thd->status_var.ha_read_prev_count, - (ulong) thd->status_var.ha_read_rnd_count, - (ulong) thd->status_var.ha_read_rnd_next_count, - (ulong) thd->status_var.filesort_merge_passes, - (ulong) thd->status_var.filesort_range_count, - (ulong) thd->status_var.filesort_rows, - (ulong) thd->status_var.filesort_scan_count, - (ulong) thd->status_var.created_tmp_disk_tables, - (ulong) thd->status_var.created_tmp_tables, + (ulong) (thd->status_var.bytes_received - + query_start->bytes_received), + (ulong) (thd->status_var.bytes_sent - + query_start->bytes_sent), + (ulong) (thd->status_var.ha_read_first_count - + query_start->ha_read_first_count), + (ulong) (thd->status_var.ha_read_last_count - + query_start->ha_read_last_count), + (ulong) (thd->status_var.ha_read_key_count - + query_start->ha_read_key_count), + (ulong) (thd->status_var.ha_read_next_count - + query_start->ha_read_next_count), + (ulong) (thd->status_var.ha_read_prev_count - + query_start->ha_read_prev_count), + (ulong) (thd->status_var.ha_read_rnd_count - + query_start->ha_read_rnd_count), + (ulong) (thd->status_var.ha_read_rnd_next_count - + query_start->ha_read_rnd_next_count), + (ulong) (thd->status_var.filesort_merge_passes - + query_start->filesort_merge_passes), + (ulong) (thd->status_var.filesort_range_count - + query_start->filesort_range_count), + (ulong) (thd->status_var.filesort_rows - + query_start->filesort_rows), + (ulong) (thd->status_var.filesort_scan_count - + query_start->filesort_scan_count), + (ulong) (thd->status_var.created_tmp_disk_tables - + query_start->created_tmp_disk_tables), + (ulong) (thd->status_var.created_tmp_tables - + query_start->created_tmp_tables), start_time_buff, end_time_buff) == (uint) -1) goto err; } @@ -1143,15 +1159,17 @@ bool Log_to_csv_event_handler::activate_log(THD *thd, } -bool Log_to_file_event_handler::log_slow(THD *thd, ulonglong current_utime, - ulonglong query_start_utime, - const char *user_host, - size_t user_host_len, - ulonglong query_utime, - ulonglong lock_utime, - bool is_command, - const char *sql_text, - size_t sql_text_len) +bool Log_to_file_event_handler::log_slow( + THD *thd, ulonglong current_utime, + ulonglong query_start_utime, + const char *user_host, + size_t user_host_len, + ulonglong query_utime, + ulonglong lock_utime, + bool is_command, + const char *sql_text, + size_t sql_text_len, + struct System_status_var *query_start_status) { if (!mysql_slow_log.is_open()) return false; @@ -1161,7 +1179,8 @@ bool Log_to_file_event_handler::log_slow(THD *thd, ulonglong current_utime, bool retval= mysql_slow_log.write_slow(thd, current_utime, query_start_utime, user_host, user_host_len, query_utime, lock_utime, is_command, - sql_text, sql_text_len); + sql_text, sql_text_len, + query_start_status); thd->pop_internal_handler(); return retval; } @@ -1220,7 +1239,8 @@ void Query_logger::cleanup() bool Query_logger::slow_log_write(THD *thd, const char *query, - size_t query_length) + size_t query_length, + struct System_status_var *query_start_status) { DBUG_ASSERT(thd->enable_slow_log && opt_slow_log); @@ -1275,7 +1295,8 @@ bool Query_logger::slow_log_write(THD *thd, const char *query, thd->start_time.tv_usec, user_host_buff, user_host_len, query_utime, lock_utime, is_command, - query, query_length); + query, query_length, + query_start_status); } mysql_rwlock_unlock(&LOCK_logger); @@ -1573,7 +1594,7 @@ bool log_slow_applicable(THD *thd) } -void log_slow_do(THD *thd) +void log_slow_do(THD *thd, struct System_status_var* query_start_status) { THD_STAGE_INFO(thd, stage_logging_slow_query); thd->status_var.long_query_count++; @@ -1581,16 +1602,18 @@ void log_slow_do(THD *thd) if (thd->rewritten_query.length()) query_logger.slow_log_write(thd, thd->rewritten_query.c_ptr_safe(), - thd->rewritten_query.length()); + thd->rewritten_query.length(), + query_start_status); else - query_logger.slow_log_write(thd, thd->query().str, thd->query().length); + query_logger.slow_log_write(thd, thd->query().str, thd->query().length, + query_start_status); } -void log_slow_statement(THD *thd) +void log_slow_statement(THD *thd, struct System_status_var* query_start_status) { if (log_slow_applicable(thd)) - log_slow_do(thd); + log_slow_do(thd, query_start_status); } @@ -1611,7 +1634,8 @@ void Slow_log_throttle::new_window(ulonglong now) Slow_log_throttle::Slow_log_throttle(ulong *threshold, mysql_mutex_t *lock, ulong window_usecs, - bool (*logger)(THD *, const char *, size_t), + bool (*logger)(THD *, const char *, size_t, + struct System_status_var *), const char *msg) : Log_throttle(window_usecs, msg), total_exec_time(0), total_lock_time(0), rate(threshold), log_summary(logger), LOCK_log_throttle(lock) @@ -1659,7 +1683,7 @@ void Slow_log_throttle::print_summary(THD *thd, ulong suppressed, thd->set_security_context(&aggregate_sctx); mysql_mutex_unlock(&thd->LOCK_thd_data); - (*log_summary)(thd, buf, strlen(buf)); + (*log_summary)(thd, buf, strlen(buf), NULL); mysql_mutex_lock(&thd->LOCK_thd_data); thd->set_security_context(save_sctx); @@ -1791,9 +1815,11 @@ bool Error_log_throttle::flush() } -static bool slow_log_write(THD *thd, const char *query, size_t query_length) +static bool slow_log_write(THD *thd, const char *query, size_t query_length, + struct System_status_var *query_start_status) { - return opt_slow_log && query_logger.slow_log_write(thd, query, query_length); + return opt_slow_log && query_logger.slow_log_write(thd, query, query_length, + query_start_status); } diff --git a/sql/log.h b/sql/log.h index 56b5ace..b5a4cd8 100644 --- a/sql/log.h +++ b/sql/log.h @@ -242,7 +242,8 @@ class File_query_log ulonglong query_start_arg, const char *user_host, size_t user_host_len, ulonglong query_utime, ulonglong lock_utime, bool is_command, - const char *sql_text, size_t sql_text_len); + const char *sql_text, size_t sql_text_len, + struct System_status_var *query_start_status); private: /** Type of log file. */ @@ -313,7 +314,8 @@ public: ulonglong query_start_arg, const char *user_host, size_t user_host_len, ulonglong query_utime, ulonglong lock_utime, bool is_command, - const char *sql_text, size_t sql_text_len)= 0; + const char *sql_text, size_t sql_text_len, + struct System_status_var *query_start_status)= 0; /** Log command to the general log. @@ -360,7 +362,8 @@ public: ulonglong query_start_arg, const char *user_host, size_t user_host_len, ulonglong query_utime, ulonglong lock_utime, bool is_command, - const char *sql_text, size_t sql_text_len); + const char *sql_text, size_t sql_text_len, + struct System_status_var *query_start_status); /** @see Log_event_handler::log_general(). */ virtual bool log_general(THD *thd, ulonglong event_utime, const char *user_host, @@ -402,7 +405,8 @@ public: ulonglong query_start_arg, const char *user_host, size_t user_host_len, ulonglong query_utime, ulonglong lock_utime, bool is_command, - const char *sql_text, size_t sql_text_len); + const char *sql_text, size_t sql_text_len, + struct System_status_var *query_start_status); /** Wrapper around File_query_log::write_general() for general log. @@ -525,7 +529,8 @@ public: @return true if error, false otherwise. */ - bool slow_log_write(THD *thd, const char *query, size_t query_length); + bool slow_log_write(THD *thd, const char *query, size_t query_length, + struct System_status_var *query_start_status); /** Write printf style message to general query log. @@ -644,7 +649,7 @@ bool log_slow_applicable(THD *thd); @param thd thread handle */ -void log_slow_do(THD *thd); +void log_slow_do(THD *thd, struct System_status_var* query_start_status); /** Check whether we need to write the current statement to the slow query @@ -658,7 +663,7 @@ void log_slow_do(THD *thd); @param thd thread handle */ -void log_slow_statement(THD *thd); +void log_slow_statement(THD *thd, struct System_status_var* query_start_status); /** @class Log_throttle @@ -783,7 +788,7 @@ private: The routine we call to actually log a line (i.e. our summary). The signature miraculously coincides with slow_log_print(). */ - bool (*log_summary)(THD *, const char *, size_t); + bool (*log_summary)(THD *, const char *, size_t, struct System_status_var *); /** Slow_log_throttle is shared between THDs. @@ -812,7 +817,8 @@ public: @param msg use this template containing %lu as only non-literal */ Slow_log_throttle(ulong *threshold, mysql_mutex_t *lock, ulong window_usecs, - bool (*logger)(THD *, const char *, size_t), + bool (*logger)(THD *, const char *, size_t, + struct System_status_var *), const char *msg); /** diff --git a/sql/log_event.cc b/sql/log_event.cc index c4d1537..0fe373e 100644 --- a/sql/log_event.cc +++ b/sql/log_event.cc @@ -5403,6 +5403,14 @@ int Query_log_event::do_apply_event(Relay_log_info const *rli, if (thd->m_digest != NULL) thd->m_digest->reset(thd->m_token_array, max_digest_length); + struct System_status_var query_start_status; + struct System_status_var *query_start_status_ptr= NULL; + if (opt_log_slow_extra) + { + query_start_status_ptr= &query_start_status; + query_start_status= thd->status_var; + } + mysql_parse(thd, &parser_state); enum_sql_command command= thd->lex->sql_command; @@ -5452,7 +5460,7 @@ int Query_log_event::do_apply_event(Relay_log_info const *rli, } /* Finalize server status flags after executing a statement. */ thd->update_slow_query_status(); - log_slow_statement(thd); + log_slow_statement(thd, query_start_status_ptr); } thd->variables.option_bits&= ~OPTION_MASTER_SQL_ERROR; diff --git a/sql/sp_instr.cc b/sql/sp_instr.cc index d2c6953..6a8a7ce 100644 --- a/sql/sp_instr.cc +++ b/sql/sp_instr.cc @@ -965,7 +965,7 @@ bool sp_instr_stmt::execute(THD *thd, uint *nextp) */ if (!need_subst) rc= subst_spvars(thd, this, &m_query); - log_slow_do(thd); + log_slow_do(thd, NULL); } /* diff --git a/sql/sql_parse.cc b/sql/sql_parse.cc index b09fffd..b9b6c17 100644 --- a/sql/sql_parse.cc +++ b/sql/sql_parse.cc @@ -1471,6 +1471,15 @@ bool dispatch_command(THD *thd, const COM_DATA *com_data, DBUG_ENTER("dispatch_command"); DBUG_PRINT("info", ("command: %d", command)); + /* For per-query performance counters with log_slow_statement */ + struct System_status_var query_start_status; + struct System_status_var *query_start_status_ptr= NULL; + if (opt_log_slow_extra) + { + query_start_status_ptr= &query_start_status; + query_start_status= thd->status_var; + } + /* SHOW PROFILE instrumentation, begin */ #if defined(ENABLED_PROFILING) thd->profiling.start_new_query(); @@ -1787,7 +1796,12 @@ bool dispatch_command(THD *thd, const COM_DATA *com_data, size_t length= static_cast(packet_end - beginning_of_next_stmt); - log_slow_statement(thd); + log_slow_statement(thd, query_start_status_ptr); + if (query_start_status_ptr) + { + /* Reset for values at start of next statement */ + query_start_status= thd->status_var; + } /* Remove garbage at start of query */ while (length > 0 && my_isspace(thd->charset(), *beginning_of_next_stmt)) @@ -1944,6 +1958,7 @@ bool dispatch_command(THD *thd, const COM_DATA *com_data, break; } case COM_QUIT: + thd->set_sent_row_count(0); /* We don't calculate statistics for this command */ query_logger.general_log_print(thd, command, NullS); // Don't give 'abort' message @@ -2150,7 +2165,7 @@ done: mysql_audit_notify(thd, AUDIT_EVENT(MYSQL_AUDIT_COMMAND_END), command, command_name[command].str); - log_slow_statement(thd); + log_slow_statement(thd, query_start_status_ptr); THD_STAGE_INFO(thd, stage_cleaning_up); @@ -2889,7 +2904,8 @@ mysql_execute_command(THD *thd, bool first_level) memcpy(cross_db_query_log + prefix_len, thd->query().str, thd->query().length); cross_db_query_log[log_len] = 0; - query_logger.slow_log_write(thd, cross_db_query_log, log_len); + query_logger.slow_log_write(thd, cross_db_query_log, + log_len, &(thd->status_var)); my_free(cross_db_query_log); } if (ret == 2) /* For LOG_WARN */ diff --git a/unittest/gunit/log_throttle-t.cc b/unittest/gunit/log_throttle-t.cc index 5eddbe9..90cf62c 100644 --- a/unittest/gunit/log_throttle-t.cc +++ b/unittest/gunit/log_throttle-t.cc @@ -37,7 +37,8 @@ using my_testing::Server_initializer; int summary_count= 0; char last_query[10]; -static bool slow_logger(THD*, const char *query, size_t) +static bool slow_logger(THD*, const char *query, size_t, + struct system_status_var* system_status_var) { summary_count++; strcpy(last_query, query);