Quelle est la différence entre une validation lente dans une requête lente MySQL et une transaction lente dans binlog ?-tutoriel mysql-php.cn

Quelle est la différence entre une validation lente dans une requête lente MySQL et une transaction lente dans binlog ?

王林

Libérer： 2023-05-30 08:07:10

avant

1599 Les gens l'ont consulté

1. Source du problème

Les requêtes lentes et les transactions lentes binlog sont des méthodes couramment utilisées lors de l'analyse des problèmes de performances. Récemment, j'analysais une requête lente et j'ai découvert qu'elle contenait un grand nombre d'instructions de validation lentes, mais la correspondance n'a pas pu être complétée lors de l'analyse des transactions lentes du binlog. Par exemple, il peut y avoir 1 000 déclarations de validation au cours de cette période, mais il peut y avoir seulement 100 transactions lentes. C'est une trop grande différence, alors pourquoi ce phénomène se produit-il ?

2. Méthodes de jugement respectives

Les transactions lentes sont généralement les suivantes pour une transaction soumise par affichage (insertion) :
# 🎜 🎜#

GTID_LOG_EVENT et XID_EVENT sont l'heure à laquelle la commande "COMMIT" est lancée.
La première fois que vous lancez la commande "INSERT", c'est QUERY_EVENT.
MAP_EVENT/WRITE_ROWS_EVENT est l'heure à laquelle chaque commande «Insérer»

Nous obtenons donc généralement un temps de transaction lent en soustrayant l'heure de QUERY_EVENT de l'heure de XID_EVENT,

Bien sûr, s'il est automatiquement soumis, il ne peut pas être calculé ainsi , car chaque événement est le moment où la déclaration est initiée.

La possibilité d'une validation lente

Nous savons que l'endroit le plus probable pour une validation lente est le binlog flush Ou attendez l'ACK de l'esclave semi-synchrone, mais l'heure de XID EVENT dans le binlog n'inclut pas cette partie du temps, ce qui signifie que les enregistrements de validation dans la transaction lente du binlog et la requête lente ne sont pas dans le même temps période.

Brève description

Si nous prenons comme exemple la transaction suivante, donnez une brève description#🎜 🎜#

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)

Copier après la connexion

#🎜 🎜#
Donc la transaction lente Il n'y a presque pas de chevauchement entre le jugement et le jugement de commit lent dans une requête lente, cette situation est donc normale, comme cela sera prouvé ci-dessous.

3. Preuve

Bibliothèque principale : Le délai d'attente de semi-synchronisation est 999999999.

Depuis la bibliothèque : définissez sync_relay_log=1 et définissez le point d'arrêt sur la fonction MYSQL_BIN_LOG::flush_and_sync. Cette fonction est affectée par chaque événement écrit dans le journal de relais à partir de. la bibliothèque. L'impact de sync_relay_log=1 doit être déterminé par la fonction de placement.

De cette façon, attendre artificiellement au point d'arrêt allongera considérablement le temps de validation. Cela prouve également que la semi-synchronisation lente affectera la validation lente, comme suit : #🎜🎜 #

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)

Copier après la connexion

binlog transaction lente 22:20:54(T2) - 22:20:43(T1) = environ 11 secondes (nous avons ajouté 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= &#39;00320cc8-39f9-11ec-b5ba-000c2929706d:41&#39;/*!*/;
# 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/*!*/;

Copier après la connexion

Le commit dans la requête lente est lent 22:21:15(T4) - 22:20:54(T3) = 21 secondes

# 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;

Copier après la connexion