MySQL Bugs: #27492: Replication queries are not logged in slow query log

Bug #27492	Replication queries are not logged in slow query log
Submitted:	28 Mar 2007 9:05	Modified:	23 Oct 2008 15:19
Reporter:	Peter Zaitsev (Basic Quality Contributor)	Email Updates:
Status:	Duplicate	Impact on me:	None
Category:	MySQL Server: Replication	Severity:	S3 (Non-critical)
Version:	5.0.40-BK, 5.0.37	OS:	Any
Assigned to:	Assigned Account	CPU Architecture:	Any
Tags:	bfsm_2007_10_25, profiling, qc, replication

Description:
Replication queries are not being logged to slow query log even if they take more than specified amount of seconds. 

This hides some of the problems as queries on the slave may take longer than on master in case of different hardware due to locking or other means. 

How to repeat:
Run any long update query on the master.
I used:

mysql> insert into j select * from j;
Query OK, 14680064 rows affected (12.41 sec)
Records: 14680064  Duplicates: 0  Warnings: 0

I can clearly see it taking more than 2 seconds on the slave (my long_query_time) but it is not logged.

Thank you for a bug report. Verified with latest 5.0.40-BK:

openxs@suse:~/dbs/5.0/mysql-test> ./mysql-test-run.pl --mysqld=--log-slow-queries rpl_bug27492
Logging: ./mysql-test-run.pl --mysqld=--log-slow-queries rpl_bug27492
MySQL Version 5.0.40
Using ndbcluster when necessary, mysqld supports it
Skipping SSL, mysqld not compiled with SSL
mysql-test-run: WARNING: Could not find all required ndb binaries, all ndb tests
 will fail, use --skip-ndbcluster to skip testing it.
Using MTR_BUILD_THREAD      = 0
Using MASTER_MYPORT         = 9306
Using MASTER_MYPORT1        = 9307
Using SLAVE_MYPORT          = 9308
Using SLAVE_MYPORT1         = 9309
Using SLAVE_MYPORT2         = 9310
Using NDBCLUSTER_PORT       = 9310
Using IM_PORT               = 9312
Using IM_MYSQLD1_PORT       = 9313
Using IM_MYSQLD2_PORT       = 9314
Killing Possible Leftover Processes
mysql-test-run: WARNING: Found non pid file master-slow.log in /home/openxs/dbs/
5.0/mysql-test/var/run
mysql-test-run: WARNING: Found non pid file slave-slow.log in /home/openxs/dbs/5
.0/mysql-test/var/run
Removing Stale Files
Creating Directories
Installing Master Database
Installing Master Database
Installing Slave1 Database
=======================================================
Starting Tests in the 'main' suite

TEST                           RESULT         TIME (ms)
-------------------------------------------------------

rpl_bug27492                   [ fail ]

Errors are (from /home/openxs/dbs/5.0/mysql-test/var/log/mysqltest-time) :
/home/openxs/dbs/5.0/bin/mysqltest: Can't get stat of '/home/openxs/dbs/5.0/mysq
l-test/r/rpl_bug27492.result' (Errcode: 2)
(the last lines may be the most important ones)
Result from queries before failure can be found in r/rpl_bug27492.log

Aborting: rpl_bug27492 failed in default mode. To continue, re-run with '--force
'.
Stopping All Servers
openxs@suse:~/dbs/5.0/mysql-test> cat var/run/master-slow.log
/home/openxs/dbs/5.0/libexec/mysqld, Version: 5.0.40-log (Source distribution).
started with:
Tcp port: 9306  Unix socket: /home/openxs/dbs/5.0/mysql-test/var/tmp/master.sock

Time                 Id Command    Argument
# Time: 070404 11:29:55
# User@Host: root[root] @ localhost [127.0.0.1]
# Query_time: 20  Lock_time: 0  Rows_sent: 0  Rows_examined: 0
use test;
insert into t1 values(1, sleep(20));
openxs@suse:~/dbs/5.0/mysql-test> cat var/run/slave-slow.log
/home/openxs/dbs/5.0/libexec/mysqld, Version: 5.0.40-log (Source distribution).
started with:
Tcp port: 9308  Unix socket: /home/openxs/dbs/5.0/mysql-test/var/tmp/slave.sock
Time                 Id Command    Argument
openxs@suse:~/dbs/5.0/mysql-test> cat t/rpl_bug27492.test
source include/master-slave.inc;

connection master;
create table t1 (a int, b int);
insert into t1 values(1, sleep(20));
save_master_pos;

connection slave;
select * from t1;

Related to bug #5297

Duplicate of BUG#23000.

Correction: Duplicate of BUG#23300.