Início / user-190872

Aldar's questions

Martin Hope
Aldar
Asked: 2021-07-30 08:27:21 +0800 CST
  • 0

um dos meus servidores PostgreSQL 11 estava lançando um erro estranho e se recusou a iniciar corretamente a replicação de streaming após um backup de base:

FATAL: encerrando o processo walreceiver devido ao comando do administrador

Tentei habilitar o maior detalhamento do log (Debug5), mas isso não forneceu mais informações sobre o motivo pelo qual ele continuava morrendo:

2021-07-29 15:33:30.862 UTC [39315] DEBUG:  postgres: PostmasterMain: initial environment dump:
2021-07-29 15:33:30.862 UTC [39315] DEBUG:  -----------------------------------------
2021-07-29 15:33:30.862 UTC [39315] DEBUG:      PG_OOM_ADJUST_FILE=/proc/self/oom_score_adj
2021-07-29 15:33:30.862 UTC [39315] DEBUG:      PG_GRANDPARENT_PID=39310
2021-07-29 15:33:30.862 UTC [39315] DEBUG:      PGLOCALEDIR=/usr/share/locale
2021-07-29 15:33:30.862 UTC [39315] DEBUG:      PGSYSCONFDIR=/etc/postgresql-common
2021-07-29 15:33:30.862 UTC [39315] DEBUG:      LANG=en_US.UTF-8
2021-07-29 15:33:30.862 UTC [39315] DEBUG:      PWD=/
2021-07-29 15:33:30.863 UTC [39315] DEBUG:      PGDATA=/var/lib/postgresql/11/replica
2021-07-29 15:33:30.863 UTC [39315] DEBUG:      LC_COLLATE=en_US.UTF-8
2021-07-29 15:33:30.863 UTC [39315] DEBUG:      LC_CTYPE=en_US.UTF-8
2021-07-29 15:33:30.863 UTC [39315] DEBUG:      LC_MESSAGES=en_US.UTF-8
2021-07-29 15:33:30.863 UTC [39315] DEBUG:      LC_MONETARY=C
2021-07-29 15:33:30.863 UTC [39315] DEBUG:      LC_NUMERIC=C
2021-07-29 15:33:30.863 UTC [39315] DEBUG:      LC_TIME=C
2021-07-29 15:33:30.863 UTC [39315] DEBUG:  -----------------------------------------
2021-07-29 15:33:30.867 UTC [39315] DEBUG:  registering background worker "logical replication launcher"
2021-07-29 15:33:30.868 UTC [39315] LOG:  listening on IPv6 address "::1", port 5433
2021-07-29 15:33:30.868 UTC [39315] LOG:  listening on IPv4 address "127.0.0.1", port 5433
2021-07-29 15:33:30.868 UTC [39315] LOG:  listening on IPv4 address "*snip*", port 5433
2021-07-29 15:33:30.868 UTC [39315] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5433"
2021-07-29 15:33:30.869 UTC [39315] DEBUG:  invoking IpcMemoryCreate(size=156459008)
2021-07-29 15:33:30.869 UTC [39315] DEBUG:  mmap(157286400) with MAP_HUGETLB failed, huge pages disabled: Cannot allocate memory
2021-07-29 15:33:30.885 UTC [39315] DEBUG:  SlruScanDirectory invoking callback on pg_notify/0000
2021-07-29 15:33:30.885 UTC [39315] DEBUG:  removing file "pg_notify/0000"
2021-07-29 15:33:30.885 UTC [39315] DEBUG:  dynamic shared memory system will support 588 segments
2021-07-29 15:33:30.885 UTC [39315] DEBUG:  created dynamic shared memory control segment 1597797971 (14128 bytes)
2021-07-29 15:33:30.887 UTC [39315] DEBUG:  max_safe_fds = 982, usable_fds = 1000, already_open = 8
2021-07-29 15:33:30.889 UTC [39316] LOG:  database system was shut down in recovery at 2021-07-29 15:31:23 UTC
2021-07-29 15:33:30.890 UTC [39316] DEBUG:  standby_mode = 'on'
2021-07-29 15:33:30.890 UTC [39316] DEBUG:  primary_conninfo = '*snip*'
2021-07-29 15:33:30.890 UTC [39316] DEBUG:  recovery_target_timeline = latest
2021-07-29 15:33:30.890 UTC [39316] LOG:  entering standby mode
2021-07-29 15:33:30.890 UTC [39316] LOG:  invalid resource manager ID 172 at 235/450000D0
2021-07-29 15:33:30.890 UTC [39316] DEBUG:  switched WAL source from archive to stream after failure
2021-07-29 15:33:30.891 UTC [39317] DEBUG:  find_in_dynamic_libpath: trying "/usr/lib/postgresql/11/lib/libpqwalreceiver"
2021-07-29 15:33:30.905 UTC [39317] DEBUG:  find_in_dynamic_libpath: trying "/usr/lib/postgresql/11/lib/libpqwalreceiver.so"
2021-07-29 15:33:30.918 UTC [39317] LOG:  started streaming WAL from primary at 235/45000000 on timeline 1
2021-07-29 15:33:30.920 UTC [39317] DEBUG:  sendtime 2021-07-29 15:33:30.917704+00 receipttime 2021-07-29 15:33:30.920718+00 replication apply delay (N/A) transfer latency 3 ms
2021-07-29 15:33:30.920 UTC [39317] DEBUG:  sending write 235/45020000 flush 0/0 apply 0/0
2021-07-29 15:33:30.921 UTC [39317] DEBUG:  sending write 235/45020000 flush 235/45020000 apply 0/0
2021-07-29 15:33:30.921 UTC [39316] LOG:  invalid resource manager ID 172 at 235/450000D0
2021-07-29 15:33:30.921 UTC [39317] FATAL:  terminating walreceiver process due to administrator command
2021-07-29 15:33:30.921 UTC [39317] DEBUG:  shmem_exit(1): 1 before_shmem_exit callbacks to make
2021-07-29 15:33:30.921 UTC [39317] DEBUG:  shmem_exit(1): 5 on_shmem_exit callbacks to make
2021-07-29 15:33:30.921 UTC [39317] DEBUG:  proc_exit(1): 2 callbacks to make
2021-07-29 15:33:30.921 UTC [39317] DEBUG:  exit(1)
2021-07-29 15:33:30.921 UTC [39316] DEBUG:  switched WAL source from stream to archive after failure

A única preocupação foram as mensagens de nível LOG como

LOG: ID do gerenciador de recursos inválido 172 em 235/450000D0

Descobriu-se, no entanto, que estas são apenas a maneira do Postgres de dizer "Chegou ao fim das estruturas WAL válidas" e as mensagens de nível de LOG podem ser ignoradas com segurança.

Eu tentei remover os logs WAL existentes (de datadir/pg_wal/), pensando que talvez uma corrupção de arquivo estivesse em jogo, o servidor ainda não iniciaria a replicação. A única solução foi fazer um backup de base completamente novo.

Minha pergunta - é terminating xyz process due to administrator commanduma mensagem padrão que o Postgres fornece quando um de seus processos morre de maneira não padrão?

Haveria mais opções de depuração em casos como este? Nem mesmo o mais alto detalhamento de log forneceu muita informação útil.

postgresql postgresql-11
Martin Hope
Aldar
Asked: 2019-09-14 04:27:39 +0800 CST
  • 1

Pela segunda vez, encontrei um problema em que nosso servidor MySQL (MariaDB v10.1) de repente lançou um erro - Não foi possível remover a tabela temporária: './database_name/#sql-4593_791', erro: 120.

Seguir os guids como https://mariadb.com/resources/blog/get-rid-of-orphaned-innodb-temporary-tables-the-right-way/ não funciona, ainda recebo um erro de que a tabela não é conhecido ( ERROR 1051 (42S02): Unknown table 'database_name.#mysql50#sql-4593_1e9')

O que torna este problema diferente de outras questões sobre a remoção de tabelas temporárias órfãs do InnoDB é que o servidor de banco de dados parece ter deletado o arquivo .frm, tanto do disco quanto da memória (a execução lsof | grep sql-4593_1e9mostra apenas o arquivo .ibd aberto)

Isso pode ser uma fonte do problema? Em caso afirmativo, existe alguma maneira de recriar o arquivo .frm de uma tabela praticamente inacessível de estrutura desconhecida?

A única menção que posso obter no próprio banco de dados é executando:

SELECT * FROM INFORMATION_SCHEMA.INNODB_SYS_TABLES WHERE NAME LIKE '%#sql%';

Que produz o seguinte:

+----------+-----------------------------+------+--------+---------+-------------+------------+---------------+
| TABLE_ID | NAME                        | FLAG | N_COLS | SPACE   | FILE_FORMAT | ROW_FORMAT | ZIP_PAGE_SIZE |
+----------+-----------------------------+------+--------+---------+-------------+------------+---------------+
|  1576128 | database_name/#sql-4593_1e9 |    1 |    118 | 1576114 | Antelope    | Compact    |             0 |
|  1576129 | database_name/#sql-4593_78d |    1 |    118 | 1576115 | Antelope    | Compact    |             0 |
|  1576130 | database_name/#sql-4593_791 |    1 |    118 | 1576116 | Antelope    | Compact    |             0 |
+----------+-----------------------------+------+--------+---------+-------------+------------+---------------+

Não me sinto à vontade para remover os arquivos de banco de dados do disco manualmente, pois não tenho certeza de que isso não levaria a problemas no futuro. Mesmo que as chances de colisão do ID do tablespace sejam próximas de zero.

innodb mariadb