mirror of
https://github.com/MariaDB/server.git
synced 2025-05-07 04:01:59 +03:00
cf2e7c770c
Logging slow stored procedures caused the slow log to write
very large lock times. The lock times was a result of a
negative number being cast to an unsigned integer.
The reason the lock time appeard negative was because
one of the measurements points was reset after execution
causing it to change order with the start time of the
statement.
This bug is related to bug 47905 which in turn was
introduced because of a joint fix for 12480,12481,12482 and 11587.
The fix is to only reset the start_time before any statement
execution in a SP while not resetting start_utime or
utime_after_lock which are used for measuring the
performance of the SP. Start_time is used to set the
timestamp on the replication event which controlls how
the slave interprets time functions like NOW().
114 lines
2.5 KiB
Plaintext
114 lines
2.5 KiB
Plaintext
SET @global_slow_query_log = @@global.slow_query_log;
|
|
SET @global_log_output = @@global.log_output;
|
|
SET @@session.long_query_time=1;
|
|
SET @@global.log_output = 'TABLE';
|
|
'----When slow_query_log = OFF----'
|
|
SET @@global.slow_query_log = OFF;
|
|
TRUNCATE mysql.slow_log;
|
|
SELECT sleep(2);
|
|
sleep(2)
|
|
0
|
|
SELECT count(*) FROM mysql.slow_log;
|
|
count(*)
|
|
0
|
|
'----When slow_query_log = ON-----'
|
|
SET @@global.slow_query_log = ON;
|
|
TRUNCATE mysql.slow_log;
|
|
SELECT sleep(2);
|
|
sleep(2)
|
|
0
|
|
SELECT count(*) > 0 FROM mysql.slow_log;
|
|
count(*) > 0
|
|
1
|
|
'Bug#47905 stored procedures not logged correctly to slow query log'
|
|
TRUNCATE mysql.slow_log;
|
|
CREATE PROCEDURE p_test()
|
|
BEGIN
|
|
select sleep(2);
|
|
select 1;
|
|
END//
|
|
CALL p_test();
|
|
sleep(2)
|
|
0
|
|
1
|
|
1
|
|
SELECT count(*) > 0 FROM mysql.slow_log;
|
|
count(*) > 0
|
|
1
|
|
DROP PROCEDURE p_test;
|
|
Bug53191 Lock_time in slow log is negative when logging stored routines
|
|
TRUNCATE mysql.slow_log;
|
|
CREATE TABLE t1 (c0 INT PRIMARY KEY AUTO_INCREMENT, c1 TIMESTAMP, c2 TIMESTAMP);
|
|
CREATE FUNCTION f_slow_now() RETURNS TIMESTAMP
|
|
BEGIN
|
|
DO SLEEP(2);
|
|
RETURN NOW();
|
|
END//
|
|
CREATE FUNCTION f_slow_current_time() RETURNS TIME
|
|
BEGIN
|
|
DO SLEEP(2);
|
|
RETURN CURRENT_TIME();
|
|
END
|
|
//
|
|
INSERT INTO t1 (c1,c2) VALUES (now(), f_slow_now())//
|
|
CREATE TRIGGER tf_before BEFORE INSERT ON t1
|
|
FOR EACH ROW BEGIN
|
|
SET new.c2 = f_slow_now();
|
|
END//
|
|
CREATE PROCEDURE p1()
|
|
BEGIN
|
|
INSERT INTO t1 (c1,c2) values (now(),now());
|
|
DO SLEEP(2);
|
|
INSERT INTO t1 (c1,c2) values (now(),now());
|
|
end//
|
|
INSERT INTO t1 (c1,c2) VALUES (now(), now());
|
|
CALL p1();
|
|
SELECT c1-c2 FROM t1;
|
|
c1-c2
|
|
0
|
|
0
|
|
0
|
|
0
|
|
*** There shouldn't less than 1 s difference between each row
|
|
SELECT t1.c1-self.c1 > 1 FROM t1, t1 as self WHERE t1.c0=self.c0+1 ORDER BY t1.c0;
|
|
t1.c1-self.c1 > 1
|
|
1
|
|
1
|
|
1
|
|
DROP TRIGGER tf_before;
|
|
DROP FUNCTION f_slow_now;
|
|
DROP FUNCTION f_slow_current_time;
|
|
DROP TABLE t1;
|
|
DROP TABLE IF EXISTS t1;
|
|
Warnings:
|
|
Note 1051 Unknown table 't1'
|
|
CREATE TABLE t1(c1 INT) ENGINE=MyISAM;
|
|
DROP PROCEDURE IF EXISTS p1;
|
|
CREATE PROCEDURE p1()
|
|
BEGIN
|
|
INSERT INTO t1 VALUES (1);
|
|
SELECT COUNT(*) FROM t1 WHERE c1= 1;
|
|
UPDATE t1 SET c1=c1*2;
|
|
END|
|
|
Connection 2
|
|
LOCK TABLE t1 WRITE;
|
|
Back to default connection
|
|
CALL p1();
|
|
Wait three seconds and unlock the table
|
|
UNLOCK TABLES;
|
|
COUNT(*)
|
|
1
|
|
Slow log:
|
|
**** 1 == we have slow log entries
|
|
SELECT count(*) > 0 FROM mysql.slow_log;
|
|
count(*) > 0
|
|
1
|
|
**** 0 == None of the entries have a lock time greater than 10 s
|
|
SELECT count(*) FROM mysql.slow_log WHERE lock_time > 10;
|
|
count(*)
|
|
0
|
|
DROP TABLE t1;
|
|
DROP PROCEDURE p1;
|
|
SET @@global.log_output = @global_log_output;
|
|
SET @global.slow_query_log = @global_slow_query_log;
|