What is the difference between slow commit in MySQL slow query and slow transaction in binlog?

1. Source of the problem

Slow query and binlog slow transactions are commonly used methods when analyzing performance problems. Recently, I was analyzing a slow query and found that it contained a large number of commit statements that were slow, but the matching could not be completed when analyzing the binlog slow transactions. For example, there may be 1,000 commit statements during this period, but there may be only 100 slow transactions. This is too big a difference, so why does this phenomenon occur?

2. Respective judgment methods

• Slow transactions usually are as follows for an explicitly submitted (insert) transaction:

• GTID_LOG_EVENT and XID_EVENT are the time when the command "COMMIT" is initiated.

• The first time the "INSERT" command is initiated is QUERY_EVENT.

• MAP_EVENT/WRITE_ROWS_EVENT is the time when each ‘Insert’ command is initiated.

So we usually get a slow transaction time by subtracting the time of QUERY_EVENT from the time of XID_EVENT, Of course, if it is automatically submitted, it cannot be calculated like this, because Each event is the time when the statement is initiated.

• Possibility of slow commit

We know that the most likely place for slow commit is flushing the binlog or waiting for semi-synchronized slave ACK. However, the time of XID EVENT in binlog does not include this part of time, which means that the commit records in binlog slow transactions and slow queries are not in the same time period.

• Brief explanation

If we take the following transaction as an example, give a brief explanation

begin;
insert into it values(10);
commit;        
-- insert语句执行      -> QUERY_EVENT时间(T1)  
-- insert语句执行完成,判定insert语句是否为慢查询(T2)          
-- commit语句执行      -> GTID_LOG_EVENT和XID_EVENT时间(T3)
   flush
   fsync
                  -----> 传输binlog (sync_binlog=1)
                  <----   等待ACK   (rpl_semi_sync_master_wait_point=AFTER_SYNC)
   commit
-- commit语句执行完成,判定commit语句是否为慢查询(T4)

• The criterion for judging whether the insert statement is slow is T2-T1 (-lock time)

• The criterion for judging whether the commit statement is slow is T4-T3

• The standard for determining slow transactions is T3-T1

There is almost no overlap between the determination of slow transactions and the determination of slow commit in slow queries, so this situation is normal, as follows to prove.

3. Proof

• Main database: The semi-synchronization timeout is 999999999.

• Slave library: Set sync_relay_log=1, and set the breakpoint on the MYSQL_BIN_LOG::flush_and_sync function. This function is affected by sync_relay_log=1 after each event is written to the relay log from the library. Affects the decision function that must be placed on the market.

In this way, waiting at the breakpoint will significantly lengthen the commit time. It also proves that the slow semi-synchronization will affect the slow commit, as follows:

begin;
select now();   -T1
insert into it values(10);
select sleep(10);
select now();   -T2
commit; (断点在从库生效卡主ack) -T3
select now();   -T4

结果
mysql> begin;
Query OK, 0 rows affected (0.00 sec)

mysql> select now();      -T1
+---------------------+
| now()               |
+---------------------+
| 2022-06-12 22:20:43 |
+---------------------+
1 row in set (0.00 sec)

mysql> insert into it values(10);
Query OK, 1 row affected (0.10 sec)

mysql> select sleep(10);

+-----------+
| sleep(10) |
+-----------+
|         0 |
+-----------+
1 row in set (10.01 sec)

mysql> select now();      -T2 AND T3
+---------------------+
| now()               |
+---------------------+
| 2022-06-12 22:20:54 |
+---------------------+
1 row in set (0.00 sec)

mysql> commit;         
Query OK, 0 rows affected (21.64 sec)

mysql> select now();    -T4
+---------------------+
| now()               |
+---------------------+
| 2022-06-12 22:21:15 |
+---------------------+
1 row in set (0.00 sec)

Let's analyze the slow query and binlog. The addition of sleep(10) prolongs the transaction commit time because the insert is too fast.

• binlog slow transaction 22:20:54(T2) - 22:20:43(T1) = about 11 seconds (we added sleep(10))

# at 12221
#220612 22:20:54 server id 613306  end_log_pos 12286 CRC32 0x3e019332   GTID    last_committed=40       sequence_number=41      rbr_only=yes
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
SET @@SESSION.GTID_NEXT= '00320cc8-39f9-11ec-b5ba-000c2929706d:41'/*!*/;
# at 12286
#220612 22:20:43 server id 613306  end_log_pos 12360 CRC32 0x8dcde193   Query   thread_id=43    exec_time=1     error_code=0
SET TIMESTAMP=1655043643/*!*/;
BEGIN
/*!*/;
# at 12360
#220612 22:20:43 server id 613306  end_log_pos 12409 CRC32 0x0db68582   Rows_query
# insert into it values(10)
# at 12409
#220612 22:20:43 server id 613306  end_log_pos 12456 CRC32 0x363a48c7   Table_map: `mysemi`.`it` mapped to number 124
# at 12456
#220612 22:20:43 server id 613306  end_log_pos 12496 CRC32 0xd44e43f3   Write_rows: table id 124 flags: STMT_END_F
### INSERT INTO `mysemi`.`it`
### SET
###   @1=10 /* INT meta=0 nullable=1 is_null=0 */
# at 12496
#220612 22:20:54 server id 613306  end_log_pos 12527 CRC32 0x4d8d2c64   Xid = 547
COMMIT/*!*/;

• The commit in slow query is slow 22:21:15(T4) - 22:20:54(T3) = 21 seconds

# Time: 2022-06-12T22:21:15.746223Z
# User@Host: root[root] @ localhost []  Id:    43
# Schema: mysemi  Last_errno: 0  Killed: 0
# Query_time: 21.641090  Lock_time: 0.000000  Rows_sent: 0  Rows_examined: 0  Rows_affected: 0
# Bytes_sent: 11
SET timestamp=1655043675;
commit;

It is obvious here that the slow commit of the slow query record is obviously not included in the slow transaction.

The above is the detailed content of What is the difference between slow commit in MySQL slow query and slow transaction in binlog?. For more information, please follow other related articles on the PHP Chinese website!