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

Reference patch: facebook/mysql-5.6@9dec869

Reviewed By: hermanlee

Differential Revision: D6688159

fbshipit-source-id: b1f4b942b1d
  • Loading branch information
Aliaksei Sandryhaila authored and facebook-github-bot committed Dec 14, 2018
1 parent 663a7cb commit 09fdfb9
Show file tree
Hide file tree
Showing 11 changed files with 334 additions and 52 deletions.
69 changes: 69 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,72 @@ 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 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 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 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 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 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 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 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 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 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 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 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 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: 0 Rows_examined: 0 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: 8 Rows_examined: 8 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 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
36 changes: 36 additions & 0 deletions mysql-test/r/slow_log_extra_big.result
Original file line number Diff line number Diff line change
@@ -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
50 changes: 50 additions & 0 deletions mysql-test/t/slow_log_extra.test
Original file line number Diff line number Diff line change
@@ -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 = <FILE>;
foreach $line (@lines) {
if ($line =~ m/^# Query_time/) {
$line =~ m/(Rows_sent.*) Thread_id: .*( Errno.*) Start.*/;
print "$1$2\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_per_table --innodb_buffer_pool_size=20M --slow-query-log=1 --long-query-time=1 --log-slow-extra=1
72 changes: 72 additions & 0 deletions mysql-test/t/slow_log_extra_big.test
Original file line number Diff line number Diff line change
@@ -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 = <FILE>;
foreach $line (@lines) {
if ($line =~ m/^# Query_time/) {
$line =~ m/(Rows_sent.*) Thread_id.* (Errno.*) Start.*/;
print "$1 $2\n";
}
}
EOF

--exit

0 comments on commit 09fdfb9

Please sign in to comment.