一则慢日志监控误报的问题分析
这是学习笔记的第 2195 篇文章
读完需要
速读仅需7分钟
之前因为各种原因，有些报警没有引起重视，最近放假马上排除了一些潜在的人为原因，发现数据库的慢日志报警有些奇怪，主要表现是慢日志报警不属实，收到报警的即时通信提醒后，隔一会去数据库里面去排查，发现慢日志的性能似乎没有那么差（我设置的一个阈值是60）。
排查过几次代码层面的逻辑，没有发现明显的问题，几次下来，问题依旧，这可激发了修正的念头，决定认真看看到底是什么原因。
后端使用的是基于ORM的模式，数据都存储在模型MySQL_slowlog_sql_history对应的表中。
代码层面是类似如下的逻辑：
MySQL_slowlog_sql_history.objects.filter(create_time__gt='2020-01-29 11:00:00',Query_time_pct_95__gt=60)
传入的时间是动态的，然后阈值取60秒，按照预期如果报警出来就肯定是有问题的。
为了进一步验证，我把阈值时间修改为600，竟然还是报出错误，执行7~8秒的慢查询照样会报出来。
我使用debug的方式得到了ORM解析得到的SQL:
SELECT...`mysql_slowlog_sql_history`.`create_time`, `mysql_slowlog_sql_history`.`memo`FROM `mysql_slowlog_sql_history`WHERE (`mysql_slowlog_sql_history`.`create_time` > '2020-01-29 11:00:00' AND `mysql_slowlog_sql_history`.`Query_time_pct_95` > '600') LIMIT 21;args=(u'2020-01-29 11:00:00', u'600')
看SQL没问题啊。
我自己在客户端执行，确实是好好的，只过滤出了600秒以上的结果。
select ip_addr,db_port from mysql_slowlog_sql_historywhere create_time>'2020-01-29 00:00:00' and Query_time_pct_95 > 600;
对着这个结果我开始反思，到底是什么原因呢？
我看着模型的字段定义开始有所悟，然后快速验证了一番。
为了方便说明，我创建了一个测试表test_dummy.
create table test_dummy(id int primary key auto_increment,Query_time_pct_95 varchar(100));初始化几条数据。
insert into test_dummy(Query_time_pct_95 ) values('8.83736'),('7.70056'),('5.09871'),('4.32582');+----+-------------------+| id | Query_time_pct_95 |+----+-------------------+| 1 | 8.83736 || 4 | 7.70056 || 7 | 5.09871 || 10 | 4.32582 |+----+-------------------+4 rows in set (0.00 sec
然后使用如下的两条语句来进行对比测试。
mysql> select *from test_dummy where Query_time_pct_95>600;Empty set (0.00 sec)
mysql> select *from test_dummy where Query_time_pct_95>'600';+----+-------------------+| id | Query_time_pct_95 |+----+-------------------+| 1 | 8.837364 || 2 | 7.700558 |+----+-------------------+2 rows in set (0.00 sec)
可以看到，使用了整型数值的时候，没有返回结果，而使用了字符类型的时候，匹配的结果是按照最左匹配的模式来进行过滤的，也就意味着在数据库层面对于浮点数的处理还是差别很大的。
所以这个问题的快速修复方式就是在数据库层面修改数据表的类型为float,而在精度损失方面这块的影响是可以忽略不计的。
再次验证，这个问题就没有再次出现。
7
近期热文
你可能也会对以下话题感兴趣。点击链接就可以查看。
8
转载热文
你可能也会对以下话题感兴趣，文章来源于转载，点击链接就可以查看。