Search code examples
mariadbmysql-slow-query-log

Huge time in slow query log (MariaDB)


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)

Solution

  • 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.