Incompatibilidade enorme entre o tamanho do índice relatado e o número de buffers no plano de execução

10

O problema

Temos uma consulta como

SELECT COUNT(1) 
  FROM article
  JOIN reservation ON a_id = r_article_id 
 WHERE r_last_modified < now() - '8 weeks'::interval 
   AND r_group_id = 1 
   AND r_status = 'OPEN';

Como ocorre um tempo limite (após 10 minutos) com mais frequência, decidi investigar o problema.

A EXPLAIN (ANALYZE, BUFFERS)saída é assim:

 Aggregate  (cost=264775.48..264775.49 rows=1 width=0) (actual time=238960.290..238960.291 rows=1 loops=1)
   Buffers: shared hit=200483 read=64361 dirtied=666 written=8, temp read=3631 written=3617
   I/O Timings: read=169806.955 write=0.154
   ->  Hash Join  (cost=52413.67..264647.65 rows=51130 width=0) (actual time=1845.483..238957.588 rows=21644 loops=1)
         Hash Cond: (reservation.r_article_id = article.a_id)
         Buffers: shared hit=200483 read=64361 dirtied=666 written=8, temp read=3631 written=3617
         I/O Timings: read=169806.955 write=0.154
         ->  Index Scan using reservation_r_article_id_idx1 on reservation  (cost=0.42..205458.72 rows=51130 width=4) (actual time=34.035..237000.197 rows=21644 loops=1)
               Filter: ((r_group_id = 1) AND (r_status = 'OPEN') AND (r_last_modified < (now() - '56 days'::interval)))
               Rows Removed by Filter: 151549
               Buffers: shared hit=200193 read=48853 dirtied=450 written=8
               I/O Timings: read=168614.105 write=0.154
         ->  Hash  (cost=29662.22..29662.22 rows=1386722 width=4) (actual time=1749.392..1749.392 rows=1386814 loops=1)
               Buckets: 32768  Batches: 8  Memory Usage: 6109kB
               Buffers: shared hit=287 read=15508 dirtied=216, temp written=3551
               I/O Timings: read=1192.850
               ->  Seq Scan on article  (cost=0.00..29662.22 rows=1386722 width=4) (actual time=23.822..1439.310 rows=1386814 loops=1)
                     Buffers: shared hit=287 read=15508 dirtied=216
                     I/O Timings: read=1192.850
 Total runtime: 238961.812 ms

O nó do gargalo é obviamente a varredura do índice. Então, vamos ver a definição do índice:

CREATE INDEX reservation_r_article_id_idx1 
    ON reservation USING btree (r_article_id)
 WHERE (r_status <> ALL (ARRAY['FULFILLED', 'CLOSED', 'CANCELED']));

Tamanhos e números de linhas

O tamanho (relatado por \di+ou visitando o arquivo físico) é de 36 MB. Como as reservas geralmente passam apenas um tempo relativamente curto em todos os status não listados acima, há muitas atualizações acontecendo, então o índice é bastante inchado (cerca de 24 MB são desperdiçados aqui) - ainda assim, o tamanho é relativamente pequeno.

A reservationtabela tem cerca de 3,8 GB de tamanho, contendo cerca de 40 milhões de linhas. O número de reservas que ainda não foram fechadas é de cerca de 170.000 (o número exato é relatado no nó da varredura de índice acima).

Agora, a surpresa: os relatórios da varredura de índice buscam uma enorme quantidade de buffers (ou seja, 8 KB de páginas):

Buffers: shared hit=200193 read=48853 dirtied=450 written=8

Os números lidos no cache e no disco (ou no cache do SO) somam 1,9 GB!

Pior cenário

Por outro lado, o pior cenário, quando cada tupla fica em uma página diferente da tabela, seria responsável por visitar (21644 + 151549) + 4608 páginas (total de linhas buscadas na tabela mais o número da página de índice do físico Tamanho). Isso ainda está abaixo de 180.000 - muito abaixo dos quase 250.000 observados.

Interessante (e talvez importante) é que a velocidade de leitura do disco é de cerca de 2,2 MB / s, o que é bastante normal, eu acho.

E daí?

Alguém tem uma idéia de onde essa discrepância pode surgir?

Nota: Para ser claro, temos ideias sobre o que melhorar / alterar aqui, mas eu realmente gostaria de entender os números que obtive - é disso que se trata a questão.

Atualização: verificando o efeito do armazenamento em cache ou do microvacuum

Com base na resposta de jjanes , verifiquei o que acontece quando reexecuto exatamente a mesma consulta imediatamente. O número de buffers afetados não muda realmente. (Para fazer isso, simplifiquei a consulta ao mínimo necessário que ainda mostra o problema.) É o que vejo desde a primeira execução:

 Aggregate  (cost=240541.52..240541.53 rows=1 width=0) (actual time=97703.589..97703.590 rows=1 loops=1)
   Buffers: shared hit=413981 read=46977 dirtied=56
   I/O Timings: read=96807.444
   ->  Index Scan using reservation_r_article_id_idx1 on reservation  (cost=0.42..240380.54 rows=64392 width=0) (actual time=13.757..97698.461 rows=19236 loops=1)
         Filter: ((r_group_id = 1) AND (r_status = 'OPEN') AND (r_last_modified < (now() - '56 days'::interval)))
         Rows Removed by Filter: 232481
         Buffers: shared hit=413981 read=46977 dirtied=56
         I/O Timings: read=96807.444
 Total runtime: 97703.694 ms

e depois do segundo:

 Aggregate  (cost=240543.26..240543.27 rows=1 width=0) (actual time=388.123..388.124 rows=1 loops=1)
   Buffers: shared hit=460990
   ->  Index Scan using reservation_r_article_id_idx1 on reservation  (cost=0.42..240382.28 rows=64392 width=0) (actual time=0.032..385.900 rows=19236 loops=1)
         Filter: ((r_group_id = 1) AND (r_status = 'OPEN') AND (r_last_modified < (now() - '56 days'::interval)))
         Rows Removed by Filter: 232584
         Buffers: shared hit=460990
 Total runtime: 388.187 ms
postgresql index postgresql-9.3 execution-plan dezso
fonte
11
Provavelmente irrelevante, mas você precisa participar article? Parece que todas as colunas envolvidas são da reservationtabela e (assumindo) que existe um FK, o resultado deve ser o mesmo.
precisa saber é o seguinte
Essa é uma pergunta muito boa. E você está certo, não é necessário - esta é uma consulta usada no monitoramento por outra equipe. Ainda assim, pelo menos, olhar para o plano de consulta, tudo o resto é apenas decoração para que verificação de índice desagradável :)
Dezso
11
Deixe-me acrescentar que a remoção da junção não faz uma grande diferença - a verificação exagerada do índice permanece lá.
Dezso
Toast table access? Embora eu duvide que alguma das colunas que você mostra seja torrada. Se você tiver um clone ocioso do banco de dados para fins de teste, poderá executá pg_stat_reset()-lo e, em seguida, executar a consulta e, em seguida, procurar pg_statio_user_tablesonde ele atribui os blocos.
jjanes

Respostas:

4

Eu acho que a chave aqui é o monte de atualizações e o inchaço no índice.

O índice contém ponteiros para linhas na tabela que não estão mais 'ativas'. Estas são as versões antigas das linhas atualizadas. As versões antigas das linhas são mantidas por um tempo, para satisfazer as consultas com um instantâneo antigo, e são mantidas por mais algum tempo, porque ninguém deseja fazer o trabalho de removê-las com mais frequência do que o necessário.

Ao varrer o índice, ele deve visitar essas linhas e depois perceber que elas não estão mais visíveis, então as ignora. A explain (analyze,buffers)instrução não relata essa atividade explicitamente, exceto pela contagem dos buffers lidos / acessados ​​no processo de inspeção dessas linhas.

Há algum código de "microvacuum" para btrees, de modo que, quando a varredura retorna ao índice novamente, ele lembra que o ponteiro que ele perseguiu não estava mais ativo e o marca como morto no índice. Dessa forma, a próxima consulta semelhante executada não precisa persegui-la novamente. Portanto, se você executar exatamente a mesma consulta novamente, provavelmente verá que os acessos ao buffer caem mais perto do que você previu.

Você também pode VACUUMtabela com mais freqüência, que limpará as tuplas mortas da própria tabela, não apenas do índice parcial. Em geral, as tabelas com um índice parcial de alta rotatividade provavelmente se beneficiarão de um vácuo mais agressivo do que o nível padrão.

jjanes
fonte
Por favor, veja minha edição - para mim, parece cache, não microvacuum.
Dez15
Seus novos números são muito diferentes dos antigos (quase o dobro), portanto, é difícil interpretar o que eles significam sem ver também os novos números das linhas reais e linhas filtradas para a verificação do índice.
jjanes
Adicionado os planos completos como eles parecem hoje. O número do buffer afetado cresceu muito desde sexta-feira, assim como a linha conta.
Dezso
Você tem transações de longa duração por aí? Nesse caso, é possível que a varredura de índice ainda esteja rastreando as linhas que não são visíveis (o que causa os acertos extras do buffer), mas ainda não é possível microvacilá-las porque podem estar visíveis para outra pessoa com um histórico mais antigo. instantâneo.
jjanes
Não tenho nenhum - a transação típica leva menos de um segundo. Ocasionalmente alguns segundos, mas não mais.
Dezso