Confirmação de transação do PostgreSQL por horas

11

Estou enfrentando um problema no qual tenho duas conexões de um usuário com o servidor PostgreSQL que estão em execução há cerca de 4 horas e que estão em um estado de confirmação há algum tempo (pelo menos 1 hora em que estou assistindo) . Essas conexões estão impedindo a execução de outras consultas, mas não são bloqueadas.

Aqui estão as duas conexões em questão.

postgres=# select * from pg_stat_activity where usename = 'xxxxx';
 datid | datname | procpid | usesysid | usename | current_query | waiting |          xact_start           |          query_start          |         backend_start         |  client_addr  | client_port
-------+---------+---------+----------+---------+---------------+---------+-------------------------------+-------------------------------+-------------------------------+---------------+-------------
 20394 | xxxxxx  |   17509 |    94858 | xxxxx   | COMMIT        | f       | 2014-01-30 05:51:11.311363-05 | 2014-01-30 05:51:12.042515-05 | 2014-01-30 05:51:11.294444-05 | xx.xx.xxx.xxx |       63531
 20394 | xxxxxx  |    9593 |    94858 | xxxxx   | COMMIT        | f       | 2014-01-30 06:45:17.032651-05 | 2014-01-30 06:45:17.694533-05 | 2014-01-30 06:45:16.992576-05 | xx.xx.xxx.xxx |       63605

O PID 9593 é o mais problemático que outros usuários ficam bloqueados por este. Tanto quanto o usuário está admitindo, ele truncou sua tabela e inseriu lotes de 1.000 confirmados após cada lote.

Atualmente, esse PID mostra os seguintes bloqueios:

postgres=# select * from pg_locks where pid = 9593;
   locktype    | database | relation | page | tuple | virtualxid | transactionid | classid | objid | objsubid | virtualtransaction | pid  |        mode         | granted
---------------+----------+----------+------+-------+------------+---------------+---------+-------+----------+--------------------+------+---------------------+---------
 relation      |    20394 | 29173472 |      |       |            |               |         |       |          | 261/0              | 9593 | AccessExclusiveLock | t
 relation      |    20394 | 27794470 |      |       |            |               |         |       |          | 261/0              | 9593 | RowExclusiveLock    | t
 relation      |    20394 | 27794470 |      |       |            |               |         |       |          | 261/0              | 9593 | ShareLock           | t
 relation      |    20394 | 27794470 |      |       |            |               |         |       |          | 261/0              | 9593 | AccessExclusiveLock | t
 virtualxid    |          |          |      |       | 261/503292 |               |         |       |          | 261/0              | 9593 | ExclusiveLock       | t
 transactionid |          |          |      |       |            |     503213304 |         |       |          | 261/0              | 9593 | ExclusiveLock       | t

Não consigo matar esse PID (nada acontece quando emito o comando kill). Não sei ao certo o que fazer para diagnosticar isso ainda mais e obviamente resolver isso.

Alguma entrada alguém?

Executando o PostgreSQL 8.4 no servidor Ubuntu Linux.

EDITAR:

Como encontrei outras conexões em um estado semelhante em que a confirmação estava interrompida, procurei mais e encontrei o seguinte nos logs do servidor:

Jan 30 02:29:45 server001 kernel: [3521062.240540] postgres      D 0000000000000000     0 23220   8154 0x00000004
Jan 30 02:29:45 server001 kernel: [3521062.240550]  ffff8800174c9d08 0000000000000082 ffff88041cd24728 0000000000015880
Jan 30 02:29:45 server001 kernel: [3521062.240559]  ffff8806c678b110 0000000000015880 0000000000015880 0000000000015880
Jan 30 02:29:45 server001 kernel: [3521062.240567]  0000000000015880 ffff8806c678b110 0000000000015880 0000000000015880
Jan 30 02:29:45 server001 kernel: [3521062.240575] Call Trace:
Jan 30 02:29:45 server001 kernel: [3521062.240582]  [<ffffffff810da010>] ? sync_page+0x0/0x50
Jan 30 02:29:45 server001 kernel: [3521062.240590]  [<ffffffff81528488>] io_schedule+0x28/0x40
Jan 30 02:29:45 server001 kernel: [3521062.240596]  [<ffffffff810da04d>] sync_page+0x3d/0x50
Jan 30 02:29:45 server001 kernel: [3521062.240603]  [<ffffffff815289a7>] __wait_on_bit+0x57/0x80
Jan 30 02:29:45 server001 kernel: [3521062.240610]  [<ffffffff810da1be>] wait_on_page_bit+0x6e/0x80
Jan 30 02:29:45 server001 kernel: [3521062.240618]  [<ffffffff81078540>] ? wake_bit_function+0x0/0x40
Jan 30 02:29:45 server001 kernel: [3521062.240627]  [<ffffffff810e4480>] ? pagevec_lookup_tag+0x20/0x30
Jan 30 02:29:45 server001 kernel: [3521062.240634]  [<ffffffff810da665>] wait_on_page_writeback_range+0xf5/0x190
Jan 30 02:29:45 server001 kernel: [3521062.240644]  [<ffffffff81053668>] ? try_to_wake_up+0x118/0x340
Jan 30 02:29:45 server001 kernel: [3521062.240651]  [<ffffffff810da727>] filemap_fdatawait+0x27/0x30
Jan 30 02:29:45 server001 kernel: [3521062.240659]  [<ffffffff811431b4>] vfs_fsync+0xa4/0xf0
Jan 30 02:29:45 server001 kernel: [3521062.240667]  [<ffffffff81143239>] do_fsync+0x39/0x60
Jan 30 02:29:45 server001 kernel: [3521062.240674]  [<ffffffff8114328b>] sys_fsync+0xb/0x10
Jan 30 02:29:45 server001 kernel: [3521062.240682]  [<ffffffff81012042>] system_call_fastpath+0x16/0x1b
ETL
fonte
Vi entradas semelhantes após alta carga de E / S. Ainda não tenho certeza se azar ou realmente alguma conexão.
frlan
2
Suspeito fortemente de uma falha no disco ou no subsistema de E / S no servidor.
Craig Ringer
@ CraigRinger - Eu acho que você está certo. O estranho é que, às 2 da manhã, recebi esses alertas no arquivo de log e, desde então, o dia inteiro não recebeu mais mensagens nos logs - no entanto, as conexões do banco de dados ainda estão suspensas, como se o PostgreSQL não se recuperasse dessas falhas. Vai fazer uma atualização do sistema operacional e tal hoje à noite (executando o kernel de 4 anos).
ETL
Verifique dmesgtambém o @ETL - procure erros de E / S, tempos limite, erros de HBA, etc. Faça um novo backup e verifique seus discos, subsistema de incursões etc.
Craig Ringer
Precisa haver outra mensagem logo acima do postgres D ... chamada trace printk, a que diria, por exemplo, bloqueio da CPU, processo travado por mais de 120 segundos, etc. Isso indicará mais claramente qual é o problema, embora o rastreamento seja já bastante claro - isso parece um fsync (2). Parece que o dispositivo subjacente está quebrado ou muito lento?
Josip Rodin

Respostas:

1

Desde então, atualizei para a versão 9.4 e um servidor totalmente novo, portanto não posso depurar isso ainda mais. Mas acredito que o problema estava em uma unidade. Encontrei um disco ruim que não foi relatado como ruim pela máquina.

ETL
fonte