Problemas ao decifrar um impasse em um log de status do innodb

16

Estamos acessando o MySQL a partir do conector Microsoft ADO.NET.

Ocasionalmente, vemos o seguinte impasse no nosso status innodb e não conseguimos identificar a causa do problema. Parece que a transação (2) está aguardando e mantendo o mesmo bloqueio?

------------------------
LATEST DETECTED DEADLOCK
------------------------
110606  5:35:09
*** (1) TRANSACTION:
TRANSACTION 0 45321452, ACTIVE 0 sec, OS thread id 3804 starting index read
mysql tables in use 1, locked 1
LOCK WAIT 2 lock struct(s), heap size 368, 1 row lock(s)
    MySQL thread id 84, query id 3265713 localhost 127.0.0.1 famdev Updating
    UPDATE people SET company_id = 1610, name = '<name>', password = '<hash>', temp_password = NULL, reset_password_hash = NULL, email = '<redacted>@yahoo.com', phone = NULL, mobile = '<phone>', iphone_device_id = 'android:<id>-<id>', iphone_device_time = '2011-06-06 05:35:09', last_checkin = '2011-06-06 05:24:42', location_lat = <lat>, location_long = -<lng>, gps_strength = 3296, picture_blob_id = 1190, authority = 1, active = 1, date_created = '2011-04-13 20:21:20', last_login = '2011-06-06 05:35:09', panic_mode = 0, battery_level = NULL, battery_state = NULL WHERE people_id = 3125
    *** (1) WAITING FOR THIS LOCK TO BE GRANTED:
    RECORD LOCKS space id 0 page no 11144 n bits 152 index `PRIMARY` of table `family`.`people` trx id 0 45321452 lock_mode X locks rec but not gap waiting
    Record lock, heap no 12 PHYSICAL RECORD: n_fields 25; compact format; info bits 0
    0: len 8; hex 8000000000000c35; asc        5;; 1: len 6; hex 000002b38ce6; asc       ;; 2: len 7; hex 00000002801f89; asc        ;; 3: len 8; hex 800000000000064a; asc        J;; 4: len 4; hex <data>; asc <name>;; 5: len 30; hex <data>; asc <data>;...(truncated); 6: SQL NULL; 7: SQL NULL; 8: len 16; hex <data>; asc <redacted>@yahoo.com;; 9: SQL NULL; 10: len 10; hex <data>; asc <phone>;; 11: len 30; hex <data>; asc android:<id>;...(truncated); 12: len 8; hex <data>; asc    J]  Z;; 13: len 8; hex <data>; asc    J]  Z;; 14: len 8; hex a39410acaa9b4340; asc       C@;; 15: len 8; hex <data>; asc     m S ;; 16: len 2; hex 8ce0; asc   ;; 17: len 8; hex 80000000000004a6; asc         ;; 18: len 4; hex 80000001; asc     ;; 19: len 1; hex 81; asc  ;; 20: len 8; hex <data>; asc    JR   ;; 21: len 8; hex <data>; asc    J]   ;; 22: len 1; hex 80; asc  ;; 23: SQL NULL; 24: SQL NULL;

    *** (2) TRANSACTION:
    TRANSACTION 0 45321448, ACTIVE 0 sec, OS thread id 3176 starting index read, thread declared inside InnoDB 500
    mysql tables in use 1, locked 1
    5 lock struct(s), heap size 1216, 2 row lock(s), undo log entries 1
    MySQL thread id 85, query id 3265714 localhost 127.0.0.1 famdev Updating
    UPDATE people SET company_id = 1610, name = '<name>', password = '<hash>', temp_password = NULL, reset_password_hash = NULL, email = '<redacted>@yahoo.com', phone = NULL, mobile = '<phone>', iphone_device_id = 'android:<id>-<id>-<id>-<id>', iphone_device_time = '2011-06-06 05:24:42', last_checkin = '2011-06-06 05:35:07', location_lat = <lat>, location_long = -<lng>, gps_strength = 3296, picture_blob_id = 1190, authority = 1, active = 1, date_created = '2011-04-13 20:21:20', last_login = '2011-06-06 05:35:09', panic_mode = 0, battery_level = NULL, battery_state = NULL WHERE people_id = 3125
    *** (2) HOLDS THE LOCK(S):
        RECORD LOCKS space id 0 page no 11144 n bits 152 index `PRIMARY` of table `family`.`people` trx id 0 45321448 lock mode S locks rec but not gap
        Record lock, heap no 12 PHYSICAL RECORD: n_fields 25; compact format; info bits 0
        0: len 8; hex 8000000000000c35; asc        5;; 1: len 6; hex 000002b38ce6; asc       ;; 2: len 7; hex 00000002801f89; asc        ;; 3: len 8; hex 800000000000064a; asc        J;; 4: len 4; hex <data>; asc <name>;; 5: len 30; hex <data>; asc <data>;...(truncated); 6: SQL NULL; 7: SQL NULL; 8: len 16; hex <data>; asc <redacted>@yahoo.com;; 9: SQL NULL; 10: len 10; hex <data>; asc <phone>;; 11: len 30; hex <data>; asc android:<id>;...(truncated); 12: len 8; hex <data>; asc    J]  Z;; 13: len 8; hex <data>; asc    J]  Z;; 14: len 8; hex a39410acaa9b4340; asc       C@;; 15: len 8; hex <data>; asc     m S ;; 16: len 2; hex 8ce0; asc   ;; 17: len 8; hex 80000000000004a6; asc         ;; 18: len 4; hex 80000001; asc     ;; 19: len 1; hex 81; asc  ;; 20: len 8; hex <data>; asc    JR   ;; 21: len 8; hex <data>; asc    J]   ;; 22: len 1; hex 80; asc  ;; 23: SQL NULL; 24: SQL NULL;

        *** (2) WAITING FOR THIS LOCK TO BE GRANTED:
        RECORD LOCKS space id 0 page no 11144 n bits 152 index `PRIMARY` of table `family`.`people` trx id 0 45321448 lock_mode X locks rec but not gap waiting
        Record lock, heap no 12 PHYSICAL RECORD: n_fields 25; compact format; info bits 0
        0: len 8; hex 8000000000000c35; asc        5;; 1: len 6; hex 000002b38ce6; asc       ;; 2: len 7; hex 00000002801f89; asc        ;; 3: len 8; hex 800000000000064a; asc        J;; 4: len 4; hex <data>; asc <name>;; 5: len 30; hex <data>; asc <data>;...(truncated); 6: SQL NULL; 7: SQL NULL; 8: len 16; hex <data>; asc <redacted>@yahoo.com;; 9: SQL NULL; 10: len 10; hex <data>; asc <phone>;; 11: len 30; hex <data>; asc android:<id>;...(truncated); 12: len 8; hex <data>; asc    J]  Z;; 13: len 8; hex <data>; asc    J]  Z;; 14: len 8; hex a39410acaa9b4340; asc       C@;; 15: len 8; hex <data>; asc     m S ;; 16: len 2; hex 8ce0; asc   ;; 17: len 8; hex 80000000000004a6; asc         ;; 18: len 4; hex 80000001; asc     ;; 19: len 1; hex 81; asc  ;; 20: len 8; hex <data>; asc    JR   ;; 21: len 8; hex <data>; asc    J]   ;; 22: len 1; hex 80; asc  ;; 23: SQL NULL; 24: SQL NULL;

        *** WE ROLL BACK TRANSACTION (1)

Lemos este artigo sobre o próximo bloqueio de teclas, mas parece que não se aplica a nós porque não estamos fazendo seleções para atualização.

Atualizar

Esta manhã, descobri uma assinatura de conflito um pouco diferente, que pode ser a causa raiz desse conflito. Tenho postado que impasse como uma questão separada para manter as coisas simples. Vou atualizar aqui se puder confirmar que a outra pergunta é a causa.

mysql innodb deadlock ado.net RedBlueThing
fonte
Atualizei minha resposta com mais largura de banda e taxa de transferência.
RolandoMySQLDBA 06/06
Eu atualizei a minha resposta com algo sobre autocommit
RolandoMySQLDBA
BTW Você recebe um +1 para esta pergunta porque esse tipo de pergunta deve manter os DBAs alerta.
RolandoMySQLDBA

Respostas:

6

Aqui está o que eu estou vendo

Eu vejo três perguntas, todas quase idênticas.

UPDATE people SET company_id = 1610, name = '<name>', password = '<hash>',
temp_password = NULL, reset_password_hash = NULL, email = '<redacted>@yahoo.com',
phone = NULL, mobile = '<phone>', iphone_device_id = 'android:<id>-<id>',
iphone_device_time = '2011-06-06 05:35:09', last_checkin = '2011-06-06 05:24:42',
location_lat = <lat>, location_long = -<lng>, gps_strength = 3296,
picture_blob_id = 1190,authority = 1, active = 1,
date_created = '2011-04-13 20:21:20',
last_login = '2011-06-06 05:35:09', panic_mode = 0, battery_level = NULL,
battery_state = NULL WHERE people_id = 3125;

As diferenças

TRANSAÇÃO 1

iphone_device_time = '2011-06-06 05:24:42', last_checkin = '2011-06-06 05:35:07'

TRANSAÇÃO 2

iphone_device_time = '2011-06-06 05:35:09', last_checkin = '2011-06-06 05:24:42'

Observe que os valores da coluna são invertidos. Normalmente, um conflito ocorre quando duas transações diferentes estão acessando dois bloqueios de duas tabelas com TX1 (Transação 1) obtendo a linha A e depois a linha B enquanto TX2 está obtendo a linha B e a linha A. Nesse caso, são TX1 e TX2 são acessando a mesma linha, mas alterando duas colunas diferentes (iphone_device_time, last_checkin).

Os valores não fazem nenhum sentido. Às 5:24:42, seu último check-in foi 5:35:07. Dez minutos e 27 segundos depois (5:35:07 - 05:24:42), os valores da coluna são revertidos.

A grande questão é: por que o TX1 é retido por quase 11 minutos ???

Esta não é realmente uma resposta. Isso é apenas largura de banda e todo o meu conteúdo. Espero que essas observações ajudem.

UPDATE 2011-06-06 09:57

Por favor, verifique este link referente a innodb_locks_unsafe_for_binlog : A razão pela qual sugiro ler isso é outra coisa que vi na sua tela INNODB STATUS. A frase lock_mode X (bloqueio exclusivo) e lock_mode S (bloqueio compartilhado) indica os dois bloqueios sendo impostos (ou tentando impor) na mesma linha. Pode haver alguma serialização interna em andamento para o bloqueio da próxima linha. O padrão é OFF. Depois de ler isso, considere habilitá-lo.

UPDATE 2011-06-06 10:03

Outro motivo para examinar essa linha de pensamento é o fato de que todas as transações estão atravessando a chave PRIMARY. Como o PRIMARY é um índice clusterizado no InnoDB, a chave PRIMARY e a própria linha estão juntas. Assim, atravessar uma linha ee a PRIMARY KEY são uma e a mesma. Portanto, qualquer bloqueio de índice na PRIMARY KEY também é um bloqueio de nível de linha.

UPDATE 2011-06-06 19:21

Verifique qual o valor de auocommit que você possui . Se a confirmação automática estiver desativada, posso ver dois (2) possíveis problemas

  1. atualizando a mesma linha duas vezes na mesma transação
  2. atualizando a mesma linha em duas transações diferentes

De fato, o SHOW ENGINE INNODB STATUS que você mostra na pergunta tem exatamente os dois cenários.

RolandoMySQLDBA
fonte
Obrigado pela sua contribuição. Percebemos isso também. Estou confuso por que alterações em duas colunas na mesma linha resultariam em um impasse.
RedBlueThing
Obrigado por suas atualizações. Acabei de verificar nossas configurações e a confirmação automática está ativada (ou seja, não alteramos o padrão).
RedBlueThing
@RedBlueThing Verifique o nível de isolamento da transação (a variável é tx_isolation dev.mysql.com/doc/refman/5.5/en/… ). Se você não definir isso, o padrão é REPEATABLE-READ. pode ser que um nível de isolamento de transação diferente possa ajudar com essa situação exclusiva.
RolandoMySQLDBA
Obrigado. Vou verificar isso e voltar para você. Obrigado novamente por sua persistência :)
RedBlueThing
Descobri um impasse diferente em nossos logs esta manhã, que poderia lançar alguma luz sobre esse problema. Eu postei isso como uma pergunta separada para simplificar as coisas. dba.stackexchange.com/questions/3223/…
RedBlueThing
1

A resposta de Rolando foi certamente útil para nos colocar no caminho da solução certa. No entanto, não ajustamos nossa configuração de confirmação automática , nossos níveis de isolamento ou o innodb_locks_unsafe_for_binlog configuração .

Acreditamos que o log de impasse que postamos nesta primeira pergunta é o resultado do impasse encontrado posteriormente e publicado aqui . Como resolvemos o problema com essas duas consultas, não vimos nenhum conflito desde então.

RedBlueThing
fonte
Embora não tenha encontrado a solução, fiquei feliz por poder ajudar !!!
RolandoMySQLDBA 23/06
Obrigado por considerar minhas sugestões e comentários aleatórios do MySQL (+1) !!!
RolandoMySQLDBA 30/06
@RolandoMySQLDBA Sem problemas;) Obrigado pela ajuda.
RedBlueThing