Shulou(Shulou.com)06/01 Report--

Address of the brief book:

Http://www.jianshu.com/p/2c25842d58d3

This case is the case of a friend. He also wrote it as follows:

Https://mp.weixin.qq.com/s/XSnFkuYzIlGWMaXIl-oPeQ

But after communicating with him, he is also prepared to change because there are some minor problems with the analysis.

1. Trigger condition binlog_gtid_simple_recovery=false. Version 5.7.6 or above. Gtid shuts down or Gtid turns on binlog with a large number of unopened Gtid. Second, this case review version: MySQL version 5.7.19. The fault is: a failure occurs about every half an hour, the whole Mysql pressure is huge, and many simple operations are correspondingly slow. Using tools such as iotop,top, it is found that a thread in Mysql has a large number of iThreads. Analysis method: using strace to find that there are a large number of binlog files read. Binlog_gtid_simple_recovery=false . Gtid was turned off and turned on halfway, but left behind a lot of binlog that did not open Gtid. The database was not restarted, but the binlog deletion was triggered by expire_logs_days. Third, fault analysis

In fact, this case is summarized in the seventh part of the previous article:

Gtid off, simple_recovery=flase5.7.6 above: this method must get the correct Gtid collection to restart Mysql without sweeping all the binlog. If you open GTID halfway to restart, you still need to scan multiple binlog because you need to find Gtid event. The purge binlog or expire_logs_days parameter setting does not trigger a full binlog scan. If you turn on GTID halfway and restart, you still need to scan multiple binlog because you need to find the Gtid event.

We know from the case that Gtid was opened midway, but left a lot of binlog that did not open Gtid. From the analysis of the sixth part of the source code bool MYSQL_BIN_LOG::init_gtid_sets () function, we know that deleting binlog will also trigger a forward lookup to get gtid_purged (Gtid_state.lost_gtids). When reading the first binlog, although the PREVIOUS GTID EVENT is obtained but there is no GTID EVENT, and simple_recovery=flase needs to continue to look for the next file until it finds the binlog that contains both PREVIOUS GTID EVENT and GTID EVENT, then obviously in this case the binlog generated when the Gtid is closed will all be scanned, and the cost will be huge if the quantity is large.

In the case, the binlog switch is triggered every half hour, because the trigger exceeds the expire_logs_days parameter setting and causes the binlog to be deleted, triggering a large number of binlog scans.

Obviously, with the previous foundation, this case is easy to analyze.

Fourth, case simulation

This case is very easy to simulate. I'm going to view it directly using strace. Because not every friend can easily use GDB debugging.

Use the test version community version 5.7.17:

+-+-+ | Log_name | File_size | +-+-+ | binlog.000027 | 198 | binlog.000028 | 198 | binlog.000029 | 198 | binlog.000030 | 198 | binlog.000031 | 198 | binlog.000032 | 198 | | binlog.000033 | 198 | binlog.000034 | 198 | binlog.000035 | binlog.000036 | 198 | binlog.000037 | binlog.000038 | 198 | binlog.000039 | 198 | binlog.000040 | binlog.000041 | 198 | binlog.000042 | binlog.000043 | 154 | +-| -+ mysql > show variables like'% gtid%' +-- +-+ | Variable_name | Value | +-- +-+ | binlog_gtid_simple_recovery | | OFF | | enforce_gtid_consistency | ON | | gtid_executed_compression_period | 1000 | | gtid_mode | OFF | | gtid_next | AUTOMATIC | | gtid_owned | | gtid_purged | session_track_gtids | | | OFF | +-- +-+ 8 rows in set (0.02 sec) mysql > show variables like'% expir%' | +-- +-+ | Variable_name | Value | +-+-+ | disconnect_on_expired_password | ON | | expire_logs_days | | 1 | +-- +-+ 2 rows in set (0.06 sec) |

Then I changed the system time and Mysql turned on Gtid.

[root@test1] # date-s' 2017-12-13 10:10:10'Wed Dec 13 10:10:10 CST 2017mysql > set global gtid_mode=1;Query OK, 0 rows affected (0.02 sec) mysql > set global gtid_mode=2;Query OK, 0 rows affected (0.02 sec) mysql > set global gtid_mode=3;Query OK, 0 rows affected (0.02 sec) mysql > show variables like'% gtid_mode%' +-+-+ | Variable_name | Value | +-+-+ | gtid_mode | ON | +-+-+ 1 row in set (0.02 sec)

To the next step we have reached the trigger standard, as long as manually trigger a flush binary logs, let binlog refresh will see. Of course, online is binlog full to do the switch.

At this time, we started to do strace and flush tables, and we observed that

Mysql > flush binary logs Query OK, 0 rows affected (0.30 sec) strace: [pid 6551] 10Query OK 171515.936738 read (62, "/ mysql/mysql5.7.17/binlog.000027"..., 528) = 528 [pid 6551] 1015,936834 stat ("/ mysql/mysql5.7.17/binlog.000027", {st_mode=S_IFREG | 0640, st_size=198,...}) = 0 [pid 6551] 101715.936925 lseek (3,0) SEEK_SET) = 0 [pid 6551] 10read (3, "/ mysql/mysql5.7.17/binlog.000043"..., 165) = 165[ pid 6551] 10read ("/ mysql", {st_mode=S_IFDIR | 0755, st_size=4096,...}) = 0 [pid 6551] 10read ("/ mysql/mysql5.7.17", {st_mode=S_IFDIR | 0755, st_size=4096) ) = 0 [pid 6551] 10 pid 1715. 937819 unlink ("/ mysql/mysql5.7.17/binlog.000027") = 0 [pid 6551] 10 mysql/mysql5.7.17/binlog.000027 17 stat ("/ mysql/mysql5.7.17/binlog.000028", {st_mode=S_IFREG | 0640, st_size=198,...}) = 0 [pid 6551] 101715.938119 lstat ("/ mysql", {st_mode=S_IFDIR | 0755, st_size=4096) .}) = 0 [pid 6551] 10mysql/mysql5.7.17 17st_size=4096 15.938228 lstat ("/ mysql/mysql5.7.17", {st_mode=S_IFDIR | 0755, st_size=4096,...}) = 0 [pid 6551] 10mysql/mysql5.7.17 1715,938314 unlink ("/ mysql/mysql5.7.17/binlog.000028") = 0. [pid 6551] 1017st_size=4096 15.954677 lstat ("/ mysql/mysql5.7.17", {st_mode=S_IFDIR | 0755, st_size=4096) ) = 0 [pid 6551] 10 pid 1715. 954756 unlink ("/ mysql/mysql5.7.17/binlog.000041") = 0 [pid 6551] 10 mysql/mysql5.7.17/binlog.000041 17 stat ("/ mysql/mysql5.7.17/binlog.000042", {st_mode=S_IFREG | 0640, st_size=198,...}) = 0 [pid 6551] 10 mysql/mysql5.7.17/binlog.000041 1715.955022 lstat ("/ mysql", {st_mode=S_IFDIR | 0755, st_size=4096) .}) = 0 [pid 6551] 10 mysql/mysql5.7.17 17 st_size=4096 15.955087 lstat ("/ mysql/mysql5.7.17", {st_mode=S_IFDIR | 0755, st_size=4096,...}) = 0 [pid 6551] 10 mysql/mysql5.7.17 17 st_size=4096 15.955159 unlink ("/ mysql/mysql5.7.17/binlog.000042") = 0

I have deleted some of the limited space here. We see that many read/lseek system calls are evidence of reading binlog.

So far, the simulation of the whole case has been completed.

V. Summary

It has been described earlier that binlog_gtid_simple_recovery above 5.7.6 should be set to true to avoid possible large binlog scans. Specific analysis can refer to section 7 and from the sixth part of the source code bool MYSQL_BIN_LOG::init_gtid_sets () function analysis.

Author Wechat:

Welcome to subscribe "Shulou Technology Information " to get latest news, interesting things and hot topics in the IT industry, and controls the hottest and latest Internet news, technology news and IT industry trends.