Mysql Slave atascado en "Bloqueo del sistema"

8

Mi esclavo MySQL está pasando mucho tiempo adentro Slave_SQL_Running_State: System lock. Puedo ver que el sistema está actualmente vinculado a la escritura de E / S, y que está procesando el registro, aunque lentamente. Show processlistno muestra nada más que "Esperando a que el maestro envíe el evento" y "Bloqueo del sistema" cuando está en este estado.

Todas mis tablas (excepto las tablas del sistema) son InnoDB y el bloqueo externo está deshabilitado. ¿Qué está haciendo el esclavo en este estado?

Aquí hay información solicitada:

Primero, esta es la comunidad MySQL 5.6 en una instancia de Amazon EC2, con todo el almacenamiento en EBS.

mysql> show processlist;
+----+-------------+-----------+---------------+---------+--------+----------------------------------+------------------+
| Id | User        | Host      | db            | Command | Time   | State                            | Info             |
+----+-------------+-----------+---------------+---------+--------+----------------------------------+------------------+
|  1 | system user |           | NULL          | Connect |  26115 | Waiting for master to send event | NULL             |
|  2 | system user |           | NULL          | Connect | 402264 | System lock                      | NULL             |
| 14 | readonly    | localhost | theshadestore | Query   |      0 | init                             | show processlist |
+----+-------------+-----------+---------------+---------+--------+----------------------------------+------------------+
3 rows in set (0.00 sec)

mysql> show slave status\G
*************************** 1. row ***************************
               Slave_IO_State: Waiting for master to send event
                  Master_Host: 184.106.16.14
                  Master_User: replicant
                  Master_Port: 3306
                Connect_Retry: 60
              Master_Log_File: bin-log.000764
          Read_Master_Log_Pos: 505452667
               Relay_Log_File: relay-log.000197
                Relay_Log_Pos: 345413863
        Relay_Master_Log_File: bin-log.000746
             Slave_IO_Running: Yes
            Slave_SQL_Running: Yes
              Replicate_Do_DB: 
          Replicate_Ignore_DB: 
           Replicate_Do_Table: 
       Replicate_Ignore_Table: 
      Replicate_Wild_Do_Table: 
  Replicate_Wild_Ignore_Table: 
                   Last_Errno: 0
                   Last_Error: 
                 Skip_Counter: 0
          Exec_Master_Log_Pos: 345413702
              Relay_Log_Space: 19834085375
              Until_Condition: None
               Until_Log_File: 
                Until_Log_Pos: 0
           Master_SSL_Allowed: No
           Master_SSL_CA_File: 
           Master_SSL_CA_Path: 
              Master_SSL_Cert: 
            Master_SSL_Cipher: 
               Master_SSL_Key: 
        Seconds_Behind_Master: 402263
Master_SSL_Verify_Server_Cert: No
                Last_IO_Errno: 0
                Last_IO_Error: 
               Last_SQL_Errno: 0
               Last_SQL_Error: 
  Replicate_Ignore_Server_Ids: 
             Master_Server_Id: 307009
                  Master_UUID: b1bf9a19-dac0-11e2-8ffa-b8ca3a5bce90
             Master_Info_File: mysql.slave_master_info
                    SQL_Delay: 0
          SQL_Remaining_Delay: NULL
      Slave_SQL_Running_State: System lock
           Master_Retry_Count: 86400
                  Master_Bind: 
      Last_IO_Error_Timestamp: 
     Last_SQL_Error_Timestamp: 
               Master_SSL_Crl: 
           Master_SSL_Crlpath: 
           Retrieved_Gtid_Set: 
            Executed_Gtid_Set: 
                Auto_Position: 0
1 row in set (0.00 sec)
Greg
fuente
1
¿Algo pasa con tu almacenamiento? Si se trata de un disco local, ¿está recibiendo advertencias INTELIGENTES o posiblemente se encuentre en una matriz RAID degradada?
nedm
Proporcione algunas entradas relevantes de mysqld.logcuando la replicación se rompió por primera vez Y publique la siguiente salida de: mysql> SHOW SLAVE STATUS \ G; mysql> MOSTRAR LISTA DE PROCESOS COMPLETA;
alexus
Es un volumen EC2 EBS. No hay errores en dmesg.
Greg
1
tenga en cuenta que esto simplemente podría ser un error de 5.6, considere comparar con otra versión (por ejemplo, 5.5): forums.mysql.com/read.php?22,598354,598354
the-wabbit
1
Aquí está la definición de Estado de bloqueo del sistema. Parece que podría estar relacionado con que su sistema esté vinculado a la escritura de E / S. Bloqueo del sistema: el subproceso va a solicitar o está esperando un bloqueo del sistema interno o externo para la mesa. Para SHOW PROFILE, este estado significa que el subproceso solicita el bloqueo (no lo espera). a partir de: dev.mysql.com/doc/refman/5.6/en/general-thread-states.html
jbrahy

Respuestas:

2

Bases de datos que se ejecutan en almacenamiento distribuido facepalm . Yo compararía el sistema de archivos que se ejecuta sobre el sistema de almacenamiento EC2 EBS. Probablemente el método más simple es usar algo como s=$(date +%s); dd if=/dev/zero of=<database-dir> bs=1M count=512; e=$(date +%s); echo "scale=4; 512 / ( $e - $s )" | bc. Eso supone que tiene 512 MB de sobra. Ahora, el problema con esta evaluación comparativa es que (1) no tiene en cuenta los efectos de almacenamiento en caché y (2) la resolución no es muy buena. Pero si esta prueba es lenta, entonces el problema es definitivamente con EC2 EBS. Si la prueba es rápida o nominal, tenemos que cavar más y usar técnicas más sofisticadas.

El programa bonnie ++ es algo adecuado, pero no (AFAIK) vacía los búferes del sistema operativo entre la escritura y la lectura. Aún así, deberías tener una idea con algo así bonnie++ -u mysql -r 8 -s 16:512 -n 1 -b -d <mysql-data-directory>. Cuando hago esto en una máquina virtual que se ejecuta en almacenamiento local, obtengo:

Version  1.96       ------Sequential Output------ --Sequential Input- --Random-
Concurrency   1     -Per Chr- --Block-- -Rewrite- -Per Chr- --Block-- --Seeks--
Machine   Size:chnk K/sec %CP K/sec %CP K/sec %CP K/sec %CP K/sec %CP  /sec %CP
test        16M:512  1173  99 +++++ +++ +++++ +++  3187  99 +++++ +++ +++++ +++
Latency              1553us      23us     330us     750us     173us    6372us
Version  1.96       ------Sequential Create------ --------Random Create--------
test                -Create-- --Read--- -Delete-- -Create-- --Read--- -Delete--
              files  /sec %CP  /sec %CP  /sec %CP  /sec %CP  /sec %CP  /sec %CP
                  1  1850  20 +++++ +++ +++++ +++ +++++ +++ +++++ +++ +++++ +++
Latency             27428us      24us    1188us   30258us      36us    1107us

Esto es lo que obtengo cuando se ejecuta en una VM sobre NFS:

Version  1.96       ------Sequential Output------ --Sequential Input- --Random-
Concurrency   1     -Per Chr- --Block-- -Rewrite- -Per Chr- --Block-- --Seeks--
Machine   Size:chnk K/sec %CP K/sec %CP K/sec %CP K/sec %CP K/sec %CP  /sec %CP
test        16M:512  1273  98 +++++ +++ +++++ +++  3053  99 +++++ +++ +++++ +++
Latency              1372us      28us     380us     832us      19us    9473us
Version  1.96       ------Sequential Create------ --------Random Create--------
test                -Create-- --Read--- -Delete-- -Create-- --Read--- -Delete--
              files  /sec %CP  /sec %CP  /sec %CP  /sec %CP  /sec %CP  /sec %CP
                  1   754  11 +++++ +++   728   8   751  12 +++++ +++   791   8
Latency             12695us      47us    5306us    3710us      30us    3278us
Oteo
fuente
0

¿Es su instancia EC2 esclava de un tamaño similar al maestro en este caso?

Si se está ejecutando en una instancia más pequeña para ahorrar dinero, es posible que se encuentre con un cuello de botella allí. Los segundos de retraso son varios días. ¿La replicación estuvo fuera de línea durante mucho tiempo o creció con el tiempo durante algún tipo de pico de entrada de datos?

zaznet
fuente
El esclavo es definitivamente más lento. Me pregunto si hay una manera de saber en qué consulta está trabajando el esclavo, al igual que 'mostrar lista de procesos' en el maestro muestra qué consultas se están ejecutando.
Greg
1
Es una repetición de registro. Puede ver dónde están el esclavo y el maestro en la salida proporcionada anteriormente. Read_Master_Log_Pos: 505452667 Relay_Log_Pos: 345413863
zaznet