Analysis and solution of a MySQL slow log monitoring false alarm problem

Previously, for various reasons, some alarms were not taken seriously. Recently, during the holiday, I immediately ruled out some potential human factors and found that the slow log alarm of the database was a bit strange. The main manifestation was that the slow log alarm was not true. After receiving the instant messaging reminder of the alarm, I went to the database to check after a while and found that the performance of the slow log did not seem to be that bad (I set a threshold of 60).

After checking the logic at the code level several times, no obvious problems were found. However, the problem persisted after several attempts. This inspired me to correct it and I decided to take a closer look at the cause.

The backend uses an ORM-based model, and the data is stored in the table corresponding to the model MySQL_slowlog_sql_history.

The code level has the following logic:

MySQL_slowlog_sql_history.objects.filter(create_time__gt='2020-01-29 11:00:00',Query_time_pct_95__gt=60)

The time passed in is dynamic, and the threshold is 60 seconds. As expected, if an alarm is triggered, there must be a problem.

For further verification, I changed the threshold time to 600, but an error was still reported, and slow queries that took 7 to 8 seconds to execute were still reported.

I used debug to get the SQL parsed by ORM:

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')

There is no problem looking at SQL.

I executed it on the client side and it worked fine, only the results that took more than 600 seconds were filtered out.

select ip_addr,db_port from mysql_slowlog_sql_history 
where create_time>'2020-01-29 00:00:00' and Query_time_pct_95 > 600;

Looking at this result, I began to reflect on what the reason was.

I looked at the model's field definitions and started to understand, and then I quickly verified it.

For the sake of illustration, I created a test table test_dummy.

create table test_dummy(id int primary key auto_increment,Query_time_pct_95 varchar(100));

Initialize some data.

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)

Then use the following two statements to perform a comparative test.

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)

It can be seen that when an integer value is used, no result is returned, but when a character type is used, the matching result is filtered according to the leftmost matching pattern, which means that the processing of floating-point numbers at the database level is still very different.

So the quick fix for this problem is to change the data table type to float at the database level, and the impact of this on precision loss is negligible.

After verifying again, the problem did not occur again.

The above is the detailed analysis and solution of a MySQL slow log monitoring false alarm problem. For more information about MySQL slow log monitoring false alarm, please pay attention to other related articles on 123WORDPRESS.COM!