慢查询日志中的大量时间 (MariaDB)

Question

当我运行慢速查询日志分析器时，我看到以秒为单位的大量请求。我尝试手动执行这些请求，它们执行得非常快（0.01 秒）。可能是什么问题呢？

mysql Ver 15.1 Distrib 10.1.9-MariaDB，对于 Linux (x86_64) 使用 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)

Answer 1

时钟倒流。你要放轻松——不要超过光速！

说真的，...在过去的 15 年里，我在 MySQL 的所有版本中定期看到这个。您看到的数字可能 -1 被视为 UNSIGNED 数字。

建议：将其视为零，继续前进。

好的，在这种情况下很难做到，因为您有一个摘要 (mysqldumpslow)。问题的根源在慢日志中的某个地方。如果它明天再次发生（在慢日志的不同部分），请使用 http://bugs.mysql.com 提交错误（假设那里还没有几个）。

Answer 2

如前所述，在 , a bug report was filed based on this question. The bug has now been fixed, the fix is available in 5.5 tree 中将与 MariaDB 的下一个版本一起发布：5.5.54、10.0.29、10.1.21、10.2.3。

慢查询日志中的大量时间 (MariaDB)

Huge time in slow query log (MariaDB)

mariadb

mysql-slow-query-log