Skip to content

Commit

Permalink
Port per query stats from 5.1 to 5.6
Browse files Browse the repository at this point in the history
Summary:
Make the log-slow-extra counters per query in the slow query log.

Tests ported from 5.1:
main.slow_log_extra
main.slow_log_extra_big

Test Plan: mysqltest.sh

Reviewers: steaphan

Reviewed By: steaphan

Differential Revision: https://reviews.facebook.net/D48345
Differential Revision: https://reviews.facebook.net/D52473
  • Loading branch information
Rongrong Zhong authored and jtolmer committed Jan 5, 2016
1 parent ee10602 commit 9dec869
Show file tree
Hide file tree
Showing 14 changed files with 342 additions and 51 deletions.
66 changes: 66 additions & 0 deletions mysql-test/r/slow_log_extra.result
Original file line number Diff line number Diff line change
Expand Up @@ -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: 2 Errno: 0 Killed: 0 Bytes_received: 0 Bytes_sent: 108 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: 3 Errno: 0 Killed: 0 Bytes_received: 0 Bytes_sent: 11 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: 3 Errno: 0 Killed: 0 Bytes_received: 0 Bytes_sent: 11 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: 3 Errno: 0 Killed: 0 Bytes_received: 0 Bytes_sent: 11 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: 3 Errno: 0 Killed: 0 Bytes_received: 0 Bytes_sent: 50 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: 3 Errno: 0 Killed: 0 Bytes_received: 0 Bytes_sent: 11 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: 3 Errno: 0 Killed: 0 Bytes_received: 0 Bytes_sent: 50 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: 8 Rows_examined: 8 Thread_id: 3 Errno: 0 Killed: 0 Bytes_received: 0 Bytes_sent: 113 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: 3 Errno: 0 Killed: 0 Bytes_received: 0 Bytes_sent: 113 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: 3 Errno: 0 Killed: 0 Bytes_received: 0 Bytes_sent: 113 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: 3 Errno: 0 Killed: 0 Bytes_received: 0 Bytes_sent: 113 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: 0 Thread_id: 3 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
37 changes: 37 additions & 0 deletions mysql-test/r/slow_log_extra_big.result
Original file line number Diff line number Diff line change
@@ -0,0 +1,37 @@
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(*)
20000
select count(*) from big_table_slow;
count(*)
20000
select count(*) from big_table_slow where id>1000 and id<2000;
count(*)
499
select * from big_table_slow where id=2;
id v t
2 v bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbba
select count(*) from big_table_slow where id >10000;
count(*)
15000
select count(*) from big_table_slow where id < 100000;
count(*)
20000
# Cleanup
SET GLOBAL innodb_file_format = "Barracuda";
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: 20000 Errno: 0 Killed: 0 Bytes_received: 0 Bytes_sent: 67 Read_first: 1 Read_last: 0 Read_key: 1 Read_next: 20000 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: 20000 Errno: 0 Killed: 0 Bytes_received: 0 Bytes_sent: 67 Read_first: 1 Read_last: 0 Read_key: 1 Read_next: 20000 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: 499 Errno: 0 Killed: 0 Bytes_received: 0 Bytes_sent: 65 Read_first: 0 Read_last: 0 Read_key: 1 Read_next: 499 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: 314 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: 15000 Errno: 0 Killed: 0 Bytes_received: 0 Bytes_sent: 67 Read_first: 0 Read_last: 0 Read_key: 1 Read_next: 15000 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: 20000 Errno: 0 Killed: 0 Bytes_received: 0 Bytes_sent: 67 Read_first: 1 Read_last: 0 Read_key: 1 Read_next: 20000 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
52 changes: 52 additions & 0 deletions mysql-test/t/slow_log_extra.test
Original file line number Diff line number Diff line change
@@ -1,7 +1,59 @@
#
# Test --log-slow-extra
#

--source include/have_innodb.inc

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 = <FILE>;
foreach $line (@lines) {
if ($line =~ m/^# Query_time/) {
$line =~ m/(Rows_sent.*) Start.*/;
print "$1\n";
}
}
EOF

--exit
1 change: 1 addition & 0 deletions mysql-test/t/slow_log_extra_big-master.opt
Original file line number Diff line number Diff line change
@@ -0,0 +1 @@
--innodb_file_format=Barracuda --innodb_file_per_table --innodb_buffer_pool_size=20M --slow-query-log=1 --long-query-time=1 --log-slow-extra=1
75 changes: 75 additions & 0 deletions mysql-test/t/slow_log_extra_big.test
Original file line number Diff line number Diff line change
@@ -0,0 +1,75 @@
#
# Test --log-slow-extra
#

-- source include/have_innodb.inc

--let $file_format_save = `SELECT @@innodb_file_format`
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(200), t text) engine=innodb key_block_size=8;

let $x = 20000;
while ($x)
{
eval insert into big_table_slow values(2 * $x, lpad("v", $x, "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>1000 and id<2000;

select * from big_table_slow where id=2;

select count(*) from big_table_slow where id >10000;

select count(*) from big_table_slow where id < 100000;

--echo # Cleanup

connection default;
eval SET GLOBAL innodb_file_format = \"$file_format_save\";
set global slow_query_log_file = @my_slow_logname;

set global long_query_time=1;
disconnect con1;
disconnect con;
let $count_sessions= 1;
--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 = <FILE>;
foreach $line (@lines) {
if ($line =~ m/^# Query_time/) {
$line =~ m/(Rows_sent.*) Thread_id.* (Errno.*) Start.*/;
print "$1 $2\n";
}
}
EOF

--exit
Loading

0 comments on commit 9dec869

Please sign in to comment.