Huge time in slow query log (MariaDB)

Question

When I run the slow query log analyzer, I see huge time of requests in seconds. I tried to execute these requests manually, they are executed very fast(0.01sec). What could be the problem?

mysql Ver 15.1 Distrib 10.1.9-MariaDB, for Linux (x86_64) using readline 5.1

CREATE DEFINER = 'root'@'192.168.1.101' EVENT `DEL_EXPIRED_BANS`
  ON SCHEDULE EVERY 10 MINUTE STARTS '2013-10-18 13:38:54'
  ON COMPLETION NOT PRESERVE
  ENABLE
  COMMENT ''  DO
BEGIN
update users set ban_type=0, ban_expire=null, ban_expire=null, ban_reason=null 
 where ban_type > 0 and ban_expire < CURRENT_TIMESTAMP();
 delete from `flash_client_log` where TIMESTAMPADD(DAY,4, `dttm` ) < CURRENT_TIMESTAMP() and `log_type`=1;
  delete from `flash_client_log` where TIMESTAMPADD(DAY,4, `dttm` ) < CURRENT_TIMESTAMP() and `log_type`=0;
END;

[root@xy1 GameServer]# mysqldumpslow -a -s t -t 15 /var/log/mysql_slow.log

Reading mysql slow query log from /var/log/mysql_slow.log
Count: 1344  Time=18446679593472.00s (24792337373626364s)  Lock=0.00s (0s)  Rows_sent=0.0 (0), Rows_examined=41408.5 (55653024), Rows_affected=0.0 (0), 2users@localhost
  update users set ban_type=0, ban_expire=null, ban_expire=null, ban_reason=null
  where ban_type > 0 and ban_expire < CURRENT_TIMESTAMP()

Count: 672  Time=18446679593471.92s (12396168686813130s)  Lock=0.15s (98s)  Rows_sent=0.0 (0), Rows_examined=33953.0 (22816416), Rows_affected=0.0 (0), root[root]@localhost
  delete from `flash_client_log` where TIMESTAMPADD(DAY,1, `dttm` ) < CURRENT_TIMESTAMP() and `log_type`=1

Count: 672  Time=18446679593471.92s (12396168686813128s)  Lock=0.15s (100s)  Rows_sent=0.0 (0), Rows_examined=33953.0 (22816416), Rows_affected=0.0 (0), root[root]@localhost
  delete from `flash_client_log` where TIMESTAMPADD(DAY,3, `dttm` ) < CURRENT_TIMESTAMP() and `log_type`=0

Count: 672  Time=18446679593471.91s (12396168686813120s)  Lock=0.09s (63s)  Rows_sent=0.0 (0), Rows_examined=14599.2 (9810684), Rows_affected=22.5 (15144), root[root]@192.168.1.101
  delete from `flash_client_log` where TIMESTAMPADD(DAY,4, `dttm` ) < CURRENT_TIMESTAMP() and `log_type`=1

Count: 672  Time=18446679593470.33s (12396168686812064s)  Lock=1.70s (1140s)  Rows_sent=0.0 (0), Rows_examined=28865.1 (19397320), Rows_affected=0.4 (237), root[root]@192.168.1.101
  delete from `flash_client_log` where TIMESTAMPADD(DAY,4, `dttm` ) < CURRENT_TIMESTAMP() and `log_type`=0

Count: 1  Time=18446679639052.95s (18446679639052s)  Lock=0.00s (0s)  Rows_sent=0.0 (0), Rows_examined=0.0 (0), Rows_affected=0.0 (0), billiards3d_net[billiards3d_net]@localhost
  delete from guests_log WHERE dttm < DATE_SUB(CURDATE(), INTERVAL 1 WEEK)

Apparently you have `log_queries_not_using_indexes=on`, and you hit a bug which affects queries meeting the criteria and executed via events. A bug report has been filed based on this question: https://jira.mariadb.org/browse/MDEV-11552 . The bug will be fixed in future versions of MariaDB. Meanwhile, if you aren't really in the process of analyzing queries not using indexes, you can set the variable `off` (if you do it in the config, you need to restart the server; if you do it at runtime, make sure it's a global value that you are changing, and restart `event_scheduler`). — elenst, Dec 12 '16 at 18:29

score 0 · Answer 1 · answered Dec 14 '16 at 03:40

The clock runeth backward. You need to take it easy -- do not exceed the speed of light!

Seriously, ... I have seen this periodically for the past 15 years, in all versions of MySQL. The number you are seeing is probably -1 being treated as a UNSIGNED number.

Recommendation: think of it as zero, and move on.

OK, that is hard to do in this case, since you have a summary (mysqldumpslow). The source of the problem is somewhere in the slowlog. If it happens again tomorrow (over a different part of the slowlog), file a bug with http://bugs.mysql.com (assuming there are not already several there).

score 0 · Accepted Answer · edited May 23 '17 at 11:46

0

As previously mentioned in the comment, a bug report was filed based on this question. The bug has now been fixed, the fix is available in 5.5 tree and will be released with the next releases of MariaDB: 5.5.54, 10.0.29, 10.1.21, 10.2.3.

edited May 23 '17 at 11:46

Community

1
1

answered Dec 23 '16 at 21:25

elenst

3,839
1
15
22

Huge time in slow query log (MariaDB)

2 Answers2