#!/usr/bin/perl BEGIN { die "The PERCONA_TOOLKIT_BRANCH environment variable is not set.\n" unless $ENV{PERCONA_TOOLKIT_BRANCH} && -d $ENV{PERCONA_TOOLKIT_BRANCH}; unshift @INC, "$ENV{PERCONA_TOOLKIT_BRANCH}/lib"; }; use strict; use warnings FATAL => 'all'; use English qw(-no_match_vars); use Test::More; use SlowLogParser; use PerconaTest; my $p = new SlowLogParser; my $sample = "t/lib/samples/slowlogs"; # Check that we can parse MySQL 5.7+ slow log with dates in RFC3339 format. test_log_parser( parser => $p, file => "$sample/mysql5.7.log", result => [ { Lock_time => '0.000324', Query_time => '0.003464', Rows_examined => '2000', Rows_sent => '1000', Thread_id => '3', arg => 'SELECT * FROM db_facturacion.facturas LIMIT 0, 1000', bytes => 51, cmd => 'Query', host => 'localhost', ip => '127.0.0.1', pos_in_log => 0, timestamp => '1469038405', ts => '2016-07-20T18:13:25', user => 'root' }, { Lock_time => '0.000055', Query_time => '0.000241', Rows_examined => '0', Rows_sent => '0', Thread_id => '4', arg => 'SHOW INDEX FROM `db_facturacion`.`facturas`', bytes => 43, cmd => 'Query', host => 'localhost', ip => '127.0.0.1', pos_in_log => 608, timestamp => '1469038405', ts => '2016-07-20T18:13:25', user => 'root' } ], ); # Check that I can parse a slow log in the default slow log format. test_log_parser( parser => $p, file => "$sample/slow001.txt", result => [ { ts => '071015 21:43:52', user => 'root', host => 'localhost', ip => '', db => 'test', arg => 'select sleep(2) from n', Query_time => 2, Lock_time => 0, Rows_sent => 1, Rows_examined => 0, pos_in_log => 0, bytes => length('select sleep(2) from n'), cmd => 'Query', }, { ts => '071015 21:45:10', db => 'sakila', user => 'root', host => 'localhost', ip => '', arg => 'select sleep(2) from test.n', Query_time => 2, Lock_time => 0, Rows_sent => 1, Rows_examined => 0, pos_in_log => 359, bytes => length('select sleep(2) from test.n'), cmd => 'Query', }, ], ); # This one has complex SET insert_id=34484549,timestamp=1197996507; test_log_parser( parser => $p, file => "$sample/slow002.txt", result => [ { arg => 'BEGIN', ts => '071218 11:48:27', Filesort_on_disk => 'No', Merge_passes => '0', Full_scan => 'No', Full_join => 'No', Thread_id => '10', Tmp_table => 'No', QC_Hit => 'No', Rows_examined => '0', Filesort => 'No', Query_time => '0.000012', Tmp_table_on_disk => 'No', Rows_sent => '0', Lock_time => '0.000000', pos_in_log => 0, cmd => 'Query', user => '[SQL_SLAVE]', host => '', ip => '', bytes => 5, }, { db => 'db1', timestamp => 1197996507, arg => 'update db2.tuningdetail_21_265507 n inner join db1.gonzo a using(gonzo) set n.column1 = a.column1, n.word3 = a.word3', Filesort_on_disk => 'No', Merge_passes => '0', Full_scan => 'Yes', Full_join => 'No', Thread_id => '10', Tmp_table => 'No', QC_Hit => 'No', Rows_examined => '62951', Filesort => 'No', Query_time => '0.726052', Tmp_table_on_disk => 'No', Rows_sent => '0', Lock_time => '0.000091', pos_in_log => 338, cmd => 'Query', user => '[SQL_SLAVE]', host => '', ip => '', bytes => 129, }, { timestamp => 1197996507, arg => 'INSERT INTO db3.vendor11gonzo (makef, bizzle) VALUES (\'\', \'Exact\')', InnoDB_IO_r_bytes => '0', Merge_passes => '0', Full_join => 'No', InnoDB_pages_distinct => '24', Filesort => 'No', InnoDB_queue_wait => '0.000000', Rows_sent => '0', Lock_time => '0.000077', InnoDB_rec_lock_wait => '0.000000', Full_scan => 'No', Filesort_on_disk => 'No', Thread_id => '10', Tmp_table => 'No', QC_Hit => 'No', Rows_examined => '0', InnoDB_IO_r_ops => '0', Tmp_table_on_disk => 'No', Query_time => '0.000512', InnoDB_IO_r_wait => '0.000000', pos_in_log => 815, cmd => 'Query', user => '[SQL_SLAVE]', host => '', ip => '', bytes => 66, }, { arg => 'UPDATE db4.vab3concept1upload SET vab3concept1id = \'91848182522\' WHERE vab3concept1upload=\'6994465\'', InnoDB_IO_r_bytes => '0', Merge_passes => '0', Full_join => 'No', InnoDB_pages_distinct => '11', Filesort => 'No', InnoDB_queue_wait => '0.000000', Rows_sent => '0', Lock_time => '0.000028', InnoDB_rec_lock_wait => '0.000000', Full_scan => 'No', Filesort_on_disk => 'No', Thread_id => '10', Tmp_table => 'No', QC_Hit => 'No', Rows_examined => '0', InnoDB_IO_r_ops => '0', Tmp_table_on_disk => 'No', Query_time => '0.033384', InnoDB_IO_r_wait => '0.000000', pos_in_log => 1334, cmd => 'Query', user => '[SQL_SLAVE]', host => '', ip => '', bytes => 103, }, { insert_id => 34484549, timestamp => 1197996507, arg => 'INSERT INTO db1.conch (word3, vid83) VALUES (\'211\', \'18\')', InnoDB_IO_r_bytes => '0', Merge_passes => '0', Full_join => 'No', InnoDB_pages_distinct => '18', Filesort => 'No', InnoDB_queue_wait => '0.000000', Rows_sent => '0', Lock_time => '0.000027', InnoDB_rec_lock_wait => '0.000000', Full_scan => 'No', Filesort_on_disk => 'No', Thread_id => '10', Tmp_table => 'No', QC_Hit => 'No', Rows_examined => '0', InnoDB_IO_r_ops => '0', Tmp_table_on_disk => 'No', Query_time => '0.000530', InnoDB_IO_r_wait => '0.000000', pos_in_log => 1864, cmd => 'Query', user => '[SQL_SLAVE]', host => '', ip => '', bytes => 57, }, { arg => 'UPDATE foo.bar SET biz = \'91848182522\'', InnoDB_IO_r_bytes => '0', Merge_passes => '0', Full_join => 'No', InnoDB_pages_distinct => '18', Filesort => 'No', InnoDB_queue_wait => '0.000000', Rows_sent => '0', Lock_time => '0.000027', InnoDB_rec_lock_wait => '0.000000', Full_scan => 'No', Filesort_on_disk => 'No', Thread_id => '10', Tmp_table => 'No', QC_Hit => 'No', Rows_examined => '0', InnoDB_IO_r_ops => '0', Tmp_table_on_disk => 'No', Query_time => '0.000530', InnoDB_IO_r_wait => '0.000000', pos_in_log => 2393, cmd => 'Query', user => '[SQL_SLAVE]', host => '', ip => '', bytes => 41, }, { arg => 'UPDATE bizzle.bat SET boop=\'bop: 899\' WHERE fillze=\'899\'', timestamp => 1197996508, InnoDB_IO_r_bytes => '0', Merge_passes => '0', Full_join => 'No', InnoDB_pages_distinct => '18', Filesort => 'No', InnoDB_queue_wait => '0.000000', Rows_sent => '0', Lock_time => '0.000027', InnoDB_rec_lock_wait => '0.000000', Full_scan => 'No', Filesort_on_disk => 'No', Thread_id => '10', Tmp_table => 'No', QC_Hit => 'No', Rows_examined => '0', InnoDB_IO_r_ops => '0', Tmp_table_on_disk => 'No', Query_time => '0.000530', InnoDB_IO_r_wait => '0.000000', pos_in_log => 2861, cmd => 'Query', user => '[SQL_SLAVE]', host => '', ip => '', bytes => 60, }, { arg => 'UPDATE foo.bar SET biz = \'91848182522\'', InnoDB_IO_r_bytes => '0', Merge_passes => '0', Full_join => 'No', InnoDB_pages_distinct => '18', Filesort => 'No', InnoDB_queue_wait => '0.000000', Rows_sent => '0', Lock_time => '0.000027', InnoDB_rec_lock_wait => '0.000000', Full_scan => 'No', Filesort_on_disk => 'No', Thread_id => '10', Tmp_table => 'No', QC_Hit => 'No', Rows_examined => '0', InnoDB_IO_r_ops => '0', Tmp_table_on_disk => 'No', Query_time => '0.000530', InnoDB_IO_r_wait => '0.000000', pos_in_log => 3374, cmd => 'Query', user => '[SQL_SLAVE]', host => '', ip => '', bytes => 41, }, ], ); # Microsecond format. test_log_parser( parser => $p, file => "$sample/microslow001.txt", result => [ { ts => '071015 21:43:52', user => 'root', host => 'localhost', ip => '', arg => "SELECT id FROM users WHERE name='baouong'", Query_time => '0.000652', Lock_time => '0.000109', Rows_sent => 1, Rows_examined => 1, pos_in_log => 0, cmd => 'Query', bytes => 41, }, { ts => '071015 21:43:52', user => 'root', host => 'localhost', ip => '', arg => "INSERT IGNORE INTO articles (id, body,)VALUES(3558268,'sample text')", Query_time => '0.001943', Lock_time => '0.000145', Rows_sent => 0, Rows_examined => 0, pos_in_log => 183, cmd => 'Query', bytes => 68, }, ], ); # A log that starts with a blank line. test_log_parser( parser => $p, file => "$sample/slow003.txt", result => [ { Filesort_on_disk => 'No', Tmp_table_on_disk => 'No', Filesort => 'No', Full_join => 'No', Full_scan => 'No', Lock_time => '0.000000', Merge_passes => '0', QC_Hit => 'No', Query_time => '0.000012', Rows_examined => '0', Rows_sent => '0', Thread_id => '10', Tmp_table => 'No', arg => 'BEGIN', cmd => 'Query', host => '', ip => '', pos_in_log => '0', ts => '071218 11:48:27', user => '[SQL_SLAVE]', bytes => 5, }, ], ); test_log_parser( parser => $p, file => "$sample/slow004.txt", result => [ { Lock_time => '0', Query_time => '2', Rows_examined => '0', Rows_sent => '1', arg => 'select 12_13_foo from (select 12foo from 123_bar) as 123baz', cmd => 'Query', host => 'localhost', ip => '', pos_in_log => '0', ts => '071015 21:43:52', user => 'root', bytes => 59, }, ], ); # Check a slow log that has tabs in it. test_log_parser( parser => $p, file => "$sample/slow005.txt", result => [ { arg => "foo\nbar\n\t\t\t0 AS counter\nbaz", ts => '071218 11:48:27', Filesort_on_disk => 'No', Merge_passes => '0', Full_scan => 'No', Full_join => 'No', Thread_id => '10', Tmp_table => 'No', QC_Hit => 'No', Rows_examined => '0', Filesort => 'No', Query_time => '0.000012', Tmp_table_on_disk => 'No', Rows_sent => '0', Lock_time => '0.000000', pos_in_log => 0, cmd => 'Query', user => '[SQL_SLAVE]', host => '', ip => '', bytes => 27, }, ], ); # A bunch of case-sensitive and case-insensitive USE stuff. test_log_parser( parser => $p, file => "$sample/slow006.txt", result => [ { Filesort_on_disk => 'No', Tmp_table_on_disk => 'No', Filesort => 'No', Full_join => 'No', Full_scan => 'No', Lock_time => '0.000000', Merge_passes => '0', QC_Hit => 'No', Query_time => '0.000012', Rows_examined => '0', Rows_sent => '0', Schema => 'foo', Thread_id => '10', Tmp_table => 'No', arg => 'SELECT col FROM foo_tbl', cmd => 'Query', host => '', ip => '', pos_in_log => '0', ts => '071218 11:48:27', user => '[SQL_SLAVE]', bytes => 23, }, { Filesort_on_disk => 'No', Tmp_table_on_disk => 'No', Filesort => 'No', Full_join => 'No', Full_scan => 'No', Lock_time => '0.000000', Merge_passes => '0', QC_Hit => 'No', Query_time => '0.000012', Rows_examined => '0', Rows_sent => '0', Schema => 'foo', Thread_id => '10', Tmp_table => 'No', arg => 'SELECT col FROM foo_tbl', cmd => 'Query', host => '', ip => '', pos_in_log => '369', ts => '071218 11:48:57', user => '[SQL_SLAVE]', bytes => 23, }, { Filesort_on_disk => 'No', Tmp_table_on_disk => 'No', Filesort => 'No', Full_join => 'No', Full_scan => 'No', Lock_time => '0.000000', Merge_passes => '0', QC_Hit => 'No', Query_time => '0.000012', Rows_examined => '0', Rows_sent => '0', Thread_id => '20', Tmp_table => 'No', arg => 'SELECT col FROM bar_tbl', cmd => 'Query', db => 'bar', host => '', ip => '', pos_in_log => '737', ts => '071218 11:48:57', user => '[SQL_SLAVE]', bytes => 23, }, { Filesort_on_disk => 'No', Tmp_table_on_disk => 'No', Filesort => 'No', Full_join => 'No', Full_scan => 'No', Lock_time => '0.000000', Merge_passes => '0', QC_Hit => 'No', Query_time => '0.000012', Rows_examined => '0', Rows_sent => '0', Schema => 'bar', Thread_id => '10', Tmp_table => 'No', arg => 'SELECT col FROM bar_tbl', cmd => 'Query', host => '', ip => '', pos_in_log => '1101', ts => '071218 11:49:05', user => '[SQL_SLAVE]', bytes => 23, }, { Filesort_on_disk => 'No', Tmp_table_on_disk => 'No', Filesort => 'No', Full_join => 'No', Full_scan => 'No', Lock_time => '0.000000', Merge_passes => '0', QC_Hit => 'No', Query_time => '0.000012', Rows_examined => '0', Rows_sent => '0', Thread_id => '20', Tmp_table => 'No', arg => 'SELECT col FROM bar_tbl', cmd => 'Query', db => 'bar', host => '', ip => '', pos_in_log => '1469', ts => '071218 11:49:07', user => '[SQL_SLAVE]', bytes => 23, }, { Filesort_on_disk => 'No', Tmp_table_on_disk => 'No', Filesort => 'No', Full_join => 'No', Full_scan => 'No', Lock_time => '0.000000', Merge_passes => '0', QC_Hit => 'No', Query_time => '0.000012', Rows_examined => '0', Rows_sent => '0', Schema => 'foo', Thread_id => '30', Tmp_table => 'No', arg => 'SELECT col FROM foo_tbl', cmd => 'Query', host => '', ip => '', pos_in_log => '1833', ts => '071218 11:49:30', user => '[SQL_SLAVE]', bytes => 23, } ], ); # Schema test_log_parser( parser => $p, file => "$sample/slow007.txt", result => [ { Schema => 'food', arg => 'SELECT fruit FROM trees', ts => '071218 11:48:27', Filesort_on_disk => 'No', Merge_passes => '0', Full_scan => 'No', Full_join => 'No', Thread_id => '3', Tmp_table => 'No', QC_Hit => 'No', Rows_examined => '0', Filesort => 'No', Query_time => '0.000012', Tmp_table_on_disk => 'No', Rows_sent => '0', Lock_time => '0.000000', pos_in_log => 0, cmd => 'Query', user => '[SQL_SLAVE]', host => '', ip => '', bytes => 23, }, ], ); # Check for number of events to see that it doesn't just run forever # to the end of the file without returning between events. # Also check it parses commented event (admin cmd). test_log_parser( parser => $p, file => "$sample/slow008.txt", num_events => 3, result => [ { 'Schema' => 'db1', 'cmd' => 'Admin', 'ip' => '1.2.3.8', 'arg' => 'administrator command: Quit', 'Thread_id' => '5', 'host' => '1.2.3.8', 'Rows_examined' => '0', 'user' => 'meow', 'Query_time' => '0.000002', 'Lock_time' => '0.000000', 'Rows_sent' => '0', pos_in_log => 0, bytes => 27, }, { 'Schema' => 'db2', 'cmd' => 'Query', 'db' => 'db', 'ip' => '1.2.3.8', arg => 'SET NAMES utf8', 'Thread_id' => '6', 'host' => '1.2.3.8', 'Rows_examined' => '0', 'user' => 'meow', 'Query_time' => '0.000899', 'Lock_time' => '0.000000', 'Rows_sent' => '0', pos_in_log => 221, bytes => 14, }, { 'Schema' => 'db2', 'cmd' => 'Query', 'arg' => 'SELECT MIN(id),MAX(id) FROM tbl', 'ip' => '1.2.3.8', 'Thread_id' => '6', 'host' => '1.2.3.8', 'Rows_examined' => '0', 'user' => 'meow', 'Query_time' => '0.018799', 'Lock_time' => '0.009453', 'Rows_sent' => '0', pos_in_log => 435, bytes => 31, }, ], ); # Parse embedded meta-attributes test_log_parser( parser => $p, misc => { embed => qr/ -- .*/, capture => qr/(\w+): ([^,]+)/ }, file => "$sample/slow010.txt", result => [ { Lock_time => '0', Query_time => '2', Rows_examined => '0', Rows_sent => '1', arg => 'SELECT foo -- file: /user.php, line: 417, url: d217d035a34ac9e693b41d4c2&limit=500&offset=0', cmd => 'Query', host => 'localhost', ip => '', pos_in_log => '0', ts => '071015 21:43:52', user => 'root', file => '/user.php', line => '417', url => 'd217d035a34ac9e693b41d4c2&limit=500&offset=0', bytes => 91, }, ], ); $p = new SlowLogParser; # Parses commented event lines after uncommented meta-lines test_log_parser( parser => $p, file => "$sample/slow011.txt", result => [ { 'Schema' => 'db1', 'arg' => 'administrator command: Quit', 'ip' => '1.2.3.8', 'Thread_id' => '5', 'host' => '1.2.3.8', 'Rows_examined' => '0', 'user' => 'meow', 'Query_time' => '0.000002', 'Lock_time' => '0.000000', 'Rows_sent' => '0', pos_in_log => 0, cmd => 'Admin', bytes => 27, }, { 'Schema' => 'db2', 'db' => 'db', 'ip' => '1.2.3.8', arg => 'SET NAMES utf8', 'Thread_id' => '6', 'host' => '1.2.3.8', 'Rows_examined' => '0', 'user' => 'meow', 'Query_time' => '0.000899', 'Lock_time' => '0.000000', 'Rows_sent' => '0', pos_in_log => 221, cmd => 'Query', bytes => 14, }, { 'Schema' => 'db2', 'db' => 'db2', 'arg' => 'administrator command: Quit', 'ip' => '1.2.3.8', 'Thread_id' => '7', 'host' => '1.2.3.8', 'Rows_examined' => '0', 'user' => 'meow', 'Query_time' => '0.018799', 'Lock_time' => '0.009453', 'Rows_sent' => '0', pos_in_log => 435, cmd => 'Admin', bytes => 27, }, { 'Schema' => 'db2', 'db' => 'db', 'ip' => '1.2.3.8', arg => 'SET NAMES utf8', 'Thread_id' => '9', 'host' => '1.2.3.8', 'Rows_examined' => '0', 'user' => 'meow', 'Query_time' => '0.000899', 'Lock_time' => '0.000000', 'Rows_sent' => '0', pos_in_log => 663, cmd => 'Query', bytes => 14, } ], ); # events that might look like meta data test_log_parser( parser => $p, file => "$sample/slow012.txt", result => [ { 'Schema' => 'sab', 'arg' => 'SET autocommit=1', 'ip' => '10.1.250.19', 'Thread_id' => '39387', 'host' => '10.1.250.19', 'Rows_examined' => '0', 'user' => 'sabapp', 'Query_time' => '0.000018', 'Lock_time' => '0.000000', 'Rows_sent' => '0', pos_in_log => 0, cmd => 'Query', bytes => 16, }, { 'Schema' => 'sab', 'arg' => 'SET autocommit=1', 'ip' => '10.1.250.19', 'Thread_id' => '39387', 'host' => '10.1.250.19', 'Rows_examined' => '0', 'user' => 'sabapp', 'Query_time' => '0.000018', 'Lock_time' => '0.000000', 'Rows_sent' => '0', pos_in_log => 172, cmd => 'Query', bytes => 16, }, ], ); # A pathological test case to be sure a crash doesn't happen. Has a bunch of # "use" and "set" and administrator commands etc. test_log_parser( parser => $p, file => "$sample/slow013.txt", result => [ { 'Schema' => 'abc', 'cmd' => 'Query', 'arg' => 'SET autocommit=1', 'ip' => '10.1.250.19', 'Thread_id' => '39796', 'host' => '10.1.250.19', 'pos_in_log' => '0', 'Rows_examined' => '0', 'user' => 'foo_app', 'Query_time' => '0.000015', 'Rows_sent' => '0', 'Lock_time' => '0.000000', bytes => 16, }, { 'Schema' => 'test', 'db' => 'test', 'cmd' => 'Query', 'arg' => 'SHOW STATUS', 'ip' => '10.1.12.201', 'ts' => '081127 8:51:20', 'Thread_id' => '39947', 'host' => '10.1.12.201', 'pos_in_log' => '174', 'Rows_examined' => '226', 'Query_time' => '0.149435', 'user' => 'mytopuser', 'Rows_sent' => '226', 'Lock_time' => '0.000070', bytes => 11, }, { 'Schema' => 'test', 'cmd' => 'Admin', 'arg' => 'administrator command: Quit', 'ip' => '10.1.12.201', 'ts' => '081127 8:51:21', 'Thread_id' => '39947', 'host' => '10.1.12.201', 'pos_in_log' => '385', 'Rows_examined' => '0', 'Query_time' => '0.000005', 'user' => 'mytopuser', 'Rows_sent' => '0', 'Lock_time' => '0.000000', bytes => 27, }, { 'Schema' => 'abc', 'db' => 'abc', 'cmd' => 'Query', 'arg' => 'SET autocommit=0', 'ip' => '10.1.250.19', 'Thread_id' => '39796', 'host' => '10.1.250.19', 'pos_in_log' => '600', 'Rows_examined' => '0', 'user' => 'foo_app', 'Query_time' => '0.000067', 'Rows_sent' => '0', 'Lock_time' => '0.000000', bytes => 16, }, { 'Schema' => 'abc', 'cmd' => 'Query', 'arg' => 'commit', 'ip' => '10.1.250.19', 'Thread_id' => '39796', 'host' => '10.1.250.19', 'pos_in_log' => '782', 'Rows_examined' => '0', 'user' => 'foo_app', 'Query_time' => '0.000015', 'Rows_sent' => '0', 'Lock_time' => '0.000000', bytes => 6, } ], ); # events with a lot of headers test_log_parser( parser => $p, file => "$sample/slow014.txt", result => [ { ts => '071015 21:43:52', cmd => 'Query', user => 'root', host => 'localhost', ip => '', db => 'test', arg => 'select sleep(2) from n', Query_time => 2, Lock_time => 0, Rows_sent => 1, Rows_examined => 0, pos_in_log => 0, bytes => 22, }, { ts => '071015 21:43:52', cmd => 'Query', user => 'root', host => 'localhost', ip => '', db => 'test', arg => 'select sleep(2) from n', Query_time => 2, Lock_time => 0, Rows_sent => 1, Rows_examined => 0, pos_in_log => 1313, bytes => 22, }, ], ); # No error parsing truncated event with no newline test_log_parser( parser => $p, file => "$sample/slow015.txt", ); # Some more silly stuff with USE meta-data lines. test_log_parser( parser => $p, file => "$sample/slow016.txt", result => [ { user => 'root', cmd => 'Query', db => 'user_chos', host => 'localhost', ip => '127.0.0.1', Thread_id => 6997, Schema => 'user_chos', Query_time => '0.000020', Lock_time => '0.000000', Rows_sent => 0, Rows_examined => 0, Rows_affected => 0, Rows_read => 1, arg => 'USE `user_chos`', pos_in_log => 0, bytes => 15, }, { user => 'user_user', cmd => 'Query', db => 'user_sfn', host => 'my-server.myplace.net', ip => '192.168.100.1', Thread_id => 6996, Schema => 'user_sfn', Query_time => '0.000020', Lock_time => '0.000000', Rows_sent => 0, Rows_examined => 0, Rows_affected => 0, Rows_read => 0, arg => 'SELECT * FROM moderator', pos_in_log => 226, bytes => 23, }, ], ); # This is fixed in EventAggregator so that we can parse # Client: IP:port because an IP looks like a broken Query_time. # Check that issue 234 doesn't kill us (broken Query_time). #test_log_parser( # parser => $p, # file => "$sample/slow017.txt", # result => [ # { ts => '081116 15:07:11', # cmd => 'Query', # user => 'user', # host => 'host', # ip => '10.1.65.120', # db => 'mydb', # arg => 'SELECT * FROM mytbl', # Query_time => '18446744073708.796870', # Lock_time => '0.000036', # Rows_sent => 1, # Rows_examined => 127, # pos_in_log => 0, # bytes => 19, # }, # ], #}); # t/lib/samples/slow018.txt is a test for mk-query-digest. # Has some more combinations of meta-data and explicit query lines and # administrator commands. test_log_parser( parser => $p, file => "$sample/slow019.txt", result => [ { Lock_time => '0.000000', Query_time => '0.000002', Rows_examined => '3', Rows_sent => '5', Schema => 'db1', Thread_id => '5', arg => 'administrator command: Quit', cmd => 'Admin', host => '1.2.3.8', ip => '1.2.3.8', pos_in_log => '0', user => 'meow', bytes => 27, }, { Lock_time => '0.000000', Query_time => '0.000899', Rows_examined => '3', Rows_sent => '0', Schema => 'db2', Thread_id => '6', arg => 'SET NAMES utf8', cmd => 'Query', db => 'db', host => '1.2.3.8', ip => '1.2.3.8', pos_in_log => '221', user => 'meow', bytes => 14, }, { Lock_time => '0.009453', Query_time => '0.018799', Rows_examined => '2', Rows_sent => '9', Schema => 'db2', Thread_id => '7', arg => 'administrator command: Quit', cmd => 'Admin', db => 'db2', host => '1.2.3.8', ip => '1.2.3.8', pos_in_log => '435', user => 'meow', bytes => 27, } ], ); # Parse files that begin with Windows paths. It also has TWO lines of # meta-data. This is from MySQL 5.1 on Windows. test_log_parser( parser => $p, file => "$sample/slow031.txt", result => [ { Lock_time => '0.000000', Query_time => '0.453125', Rows_examined => '2160', Rows_sent => '2160', arg => 'SELECT * FROM cottages', cmd => 'Query', db => 'myplace', host => 'secure.myplace.co.uk', ip => '88.208.248.160', pos_in_log => '0', timestamp => '1233019414', ts => '090127 1:23:34', user => 'swuser', bytes => 22, }, ], ); # t/lib/samples/slow021.txt is for mk-query-digest. It has an entry without a Time. # t/lib/samples/slow022.txt has garbled Time entries. test_log_parser( parser => $p, file => "$sample/slow022.txt", result => [ { Filesort_on_disk => 'No', Tmp_table_on_disk => 'No', Filesort => 'No', Full_join => 'No', Full_scan => 'No', Lock_time => '0.000000', Merge_passes => '0', QC_Hit => 'No', Query_time => '0.000012', Rows_examined => '0', Rows_sent => '0', Schema => 'foo', Thread_id => '10', Tmp_table => 'No', arg => 'SELECT col FROM foo_tbl', cmd => 'Query', host => '', ip => '', pos_in_log => '0', user => '[SQL_SLAVE]', bytes => 23, }, { Filesort_on_disk => 'No', Tmp_table_on_disk => 'No', Filesort => 'No', Full_join => 'No', Full_scan => 'No', Lock_time => '0.000000', Merge_passes => '0', QC_Hit => 'No', Query_time => '0.000012', Rows_examined => '0', Rows_sent => '0', Schema => 'foo', Thread_id => '10', Tmp_table => 'No', arg => 'SELECT col FROM foo_tbl', cmd => 'Query', host => '', ip => '', pos_in_log => '369', user => '[SQL_SLAVE]', bytes => 23, }, { Filesort_on_disk => 'No', Tmp_table_on_disk => 'No', Filesort => 'No', Full_join => 'No', Full_scan => 'No', Lock_time => '0.000000', Merge_passes => '0', QC_Hit => 'No', Query_time => '0.000012', Rows_examined => '0', Rows_sent => '0', Thread_id => '20', Tmp_table => 'No', arg => 'SELECT col FROM bar_tbl', cmd => 'Query', db => 'bar', host => '', ip => '', pos_in_log => '737', user => '[SQL_SLAVE]', bytes => 23, }, { Filesort_on_disk => 'No', Tmp_table_on_disk => 'No', Filesort => 'No', Full_join => 'No', Full_scan => 'No', Lock_time => '0.000000', Merge_passes => '0', QC_Hit => 'No', Query_time => '0.000012', Rows_examined => '0', Rows_sent => '0', Schema => 'bar', Thread_id => '10', Tmp_table => 'No', arg => 'SELECT col FROM bar_tbl', cmd => 'Query', host => '', ip => '', pos_in_log => '1101', user => '[SQL_SLAVE]', bytes => 23, }, { Filesort_on_disk => 'No', Tmp_table_on_disk => 'No', Filesort => 'No', Full_join => 'No', Full_scan => 'No', Lock_time => '0.000000', Merge_passes => '0', QC_Hit => 'No', Query_time => '0.000012', Rows_examined => '0', Rows_sent => '0', Thread_id => '20', Tmp_table => 'No', arg => 'SELECT col FROM bar_tbl', cmd => 'Query', db => 'bar', host => '', ip => '', pos_in_log => '1469', user => '[SQL_SLAVE]', bytes => 23, }, { Filesort_on_disk => 'No', Tmp_table_on_disk => 'No', Filesort => 'No', Full_join => 'No', Full_scan => 'No', Lock_time => '0.000000', Merge_passes => '0', QC_Hit => 'No', Query_time => '0.000012', Rows_examined => '0', Rows_sent => '0', Schema => 'foo', Thread_id => '30', Tmp_table => 'No', arg => 'SELECT col FROM foo_tbl', cmd => 'Query', host => '', ip => '', pos_in_log => '1833', user => '[SQL_SLAVE]', bytes => 23, }, ], ); # t/lib/samples/slow025.txt has an empty Schema. test_log_parser( parser => $p, file => "$sample/slow025.txt", result => [ { Lock_time => '0.000066', Query_time => '17.737502', Rows_examined => '0', Rows_sent => '0', Schema => '', Thread_id => '12342', arg => 'SELECT missing_a_schema_above from crash_me', bytes => 43, cmd => 'Query', host => '10.1.12.30', ip => '10.1.12.30', pos_in_log => '0', ts => '081126 13:08:25', user => 'root' } ], ); # ############################################################################# # Test a callback chain. # ############################################################################# my $oktorun = 1; test_log_parser( parser => $p, file => "$sample/slow001.txt", oktorun => sub { $oktorun = $_[0]; }, result => [ { ts => '071015 21:43:52', user => 'root', host => 'localhost', ip => '', db => 'test', arg => 'select sleep(2) from n', Query_time => 2, Lock_time => 0, Rows_sent => 1, Rows_examined => 0, pos_in_log => 0, bytes => length('select sleep(2) from n'), cmd => 'Query', }, { ts => '071015 21:45:10', db => 'sakila', user => 'root', host => 'localhost', ip => '', arg => 'select sleep(2) from test.n', Query_time => 2, Lock_time => 0, Rows_sent => 1, Rows_examined => 0, pos_in_log => 359, bytes => length('select sleep(2) from test.n'), cmd => 'Query', }, ], ); is( $oktorun, 0, 'Sets oktorun' ); # ############################################################################# # Parse "Client: IP:port". # ############################################################################# test_log_parser( parser => $p, file => "$sample/slow036.txt", result => [ { Lock_time => '0.000000', Query_time => '0.000000', Rows_examined => '0', Rows_sent => '0', arg => 'select * from foo', bytes => length('select * from foo'), cmd => 'Query', pos_in_log => '0', ts => '071218 11:48:27', Client => '127.0.0.1:12345', } ], ); # ############################################################################# # Issue 1104: Schema isn't parsed right # ############################################################################# test_log_parser( parser => $p, file => "$sample/slow044.txt", result => [ { Lock_time => '0.000048', Query_time => '0.000173', Rows_examined => '18', Rows_sent => '18', arg => 'select /*this is only parsable by slowlog-to-outfile, not by mqd*/ foo', bytes => length('select /*this is only parsable by slowlog-to-outfile, not by mqd*/ foo'), cmd => 'Query', pos_in_log => '0', ts => '100525 10:22:00', Thread_id => '342', Last_errno => 1, Killed => 2, }, { Lock_time => '0.000048', Query_time => '0.000173', Rows_examined => '19', Rows_sent => '19', arg => 'select /*this is only parsable by slowlog-to-outfile, not by mqd*/ foo', bytes => length('select /*this is only parsable by slowlog-to-outfile, not by mqd*/ foo'), cmd => 'Query', pos_in_log => '253', Thread_id => '342', Last_errno => 3, Killed => 4, } ], ); # ############################################################################# # pt-query-digest fails to parse timestamp with no query # https://bugs.launchpad.net/percona-toolkit/+bug/1082599 # ############################################################################# test_log_parser( parser => $p, file => "$sample/slow056.txt", result => [ { Lock_time => '0.000000', Query_time => '0.000102', Rows_read => '0', Rows_affected => '0', Rows_examined => '0', Rows_sent => '0', arg => '/* No query */', bytes => '0', cmd => 'Query', pos_in_log => '0', ts => '121123 19:56:06', Thread_id => '558038', Last_errno => 0, Killed => 0, db => 'test_db', host => '127.0.0.1', Schema => 'test_db', ip => '127.0.0.1', timestamp => '1111111111', user => 'root', }, { ts => '121123 19:56:06', Killed => '0', Last_errno => '0', Lock_time => '0.000197', Query_time => '0.002515', Rows_affected => '1', Rows_examined => '1', Rows_read => '0', Rows_sent => '0', Schema => 'test_db', Thread_id => '558032', arg => 'update t set b = b + 30 where user_id=1', bytes => 39, cmd => 'Query', host => '127.0.0.1', ip => '127.0.0.1', pos_in_log => 596, timestamp => '2222222222', user => 'root', }, ], ); # ############################################################################# # pt-query-digest fails to parse Thread_id on 5.6 # https://bugs.launchpad.net/percona-toolkit/+bug/1299387 # ############################################################################# # first test with a Percona 5.5 slow log (includes an explicit Thread_id line) # (MySQL 5.5 doesn't include thread id) test_log_parser( parser => $p, file => "$sample/slow060.txt", result => [ { Thread_id => '1', # here's our item Bytes_sent => '64', Killed => '0', Last_errno => '0', Lock_time => '0.000000', Query_time => '10.000373', Rows_affected => '0', Rows_examined => '0', Rows_read => '0', Rows_sent => '1', arg => 'select sleep(10)', bytes => 16, cmd => 'Query', host => 'localhost', ip => '127.0.0.1', pos_in_log => 0, timestamp => '1405358212', ts => '140714 14:16:52', user => 'root' }, ], ); # now test with a Percona 5.6 slow log. Thread_id is now on the user@host line, and is called 'Id'. # (this is in line with MySQL 5.6) test_log_parser( parser => $p, file => "$sample/slow061.txt", result => [ { Thread_id => 1, # here's our item Bytes_sent => '64', Lock_time => '0.000000', Query_time => '11.013723', Rows_affected => '0', Rows_examined => '0', Rows_sent => '1', arg => 'select sleep(11)', bytes => 16, cmd => 'Query', host => 'localhost', ip => '127.0.0.1', pos_in_log => 0, timestamp => '1405360304', ts => '140714 14:51:44', user => 'root', }, ], ); # ############################################################################# # Done. # ############################################################################# my $output = ''; { local *STDERR; open STDERR, '>', \$output; $p->_d('Complete test coverage'); } like( $output, qr/Complete test coverage/, '_d() works' ); done_testing;