Pourquoi Postgres est-il inactif à 95%, sans E / S de fichier?

J'ai une pile TileMill / PostGIS fonctionnant sur une machine virtuelle Ubuntu 12.04 à 8 cœurs sur un cloud OpenStack. C'est une reconstruction d'un système très similaire qui fonctionnait bien sur du matériel très similaire (même cloud, mais matériel physique différent, je crois) la semaine dernière. J'ai essayé de reconstruire la pile exactement la même qu'elle était (en utilisant certains scripts que j'avais construits).

Tout fonctionne, mais la base de données exécute les requêtes avec une lenteur atroce, ce qui se manifeste finalement avec une génération de tuiles très lente. Un exemple de requête (comptez le nombre de pubs dans un rayon de chaque ville en Australie), qui prenait auparavant quelque chose comme 10-20 secondes prend maintenant plus de 10 minutes:

explain (analyze, buffers) update places set pubs = 
(select count(*) from planet_osm_point p where p.amenity = 'pub' and st_dwithin(p.way,places.way,scope)) +
(select count(*) from planet_osm_polygon p where p.amenity = 'pub' and st_dwithin(p.way,places.way,scope)) ;
 Update on places  (cost=0.00..948254806.93 rows=9037 width=160) (actual time=623321.558..623321.558 rows=0 loops=1)
   Buffers: shared hit=132126300
   ->  Seq Scan on places  (cost=0.00..948254806.93 rows=9037 width=160) (actual time=68.130..622931.130 rows=9037 loops=1)
         Buffers: shared hit=132107781
         SubPlan 1
           ->  Aggregate  (cost=12.95..12.96 rows=1 width=0) (actual time=0.187..0.188 rows=1 loops=9037)
                 Buffers: shared hit=158171
                 ->  Index Scan using planet_osm_point_index on planet_osm_point p  (cost=0.00..12.94 rows=1 width=0) (actual time=0.163..0.179 rows=0 loops=9037)
                       Index Cond: (way && st_expand(places.way, (places.scope)::double precision))
                       Filter: ((amenity = 'pub'::text) AND (places.way && st_expand(way, (places.scope)::double precision)) AND _st_dwithin(way, places.way, (places.scope)::double precision))
                       Buffers: shared hit=158171
         SubPlan 2
           ->  Aggregate  (cost=104917.24..104917.25 rows=1 width=0) (actual time=68.727..68.728 rows=1 loops=9037)
                 Buffers: shared hit=131949237
                 ->  Seq Scan on planet_osm_polygon p  (cost=0.00..104917.24 rows=1 width=0) (actual time=68.138..68.716 rows=0 loops=9037)
                       Filter: ((amenity = 'pub'::text) AND (way && st_expand(places.way, (places.scope)::double precision)) AND (places.way && st_expand(way, (places.scope)::double precision)) AND _st_dwithin(way, places.way, (places.scope)::double precision))
                       Buffers: shared hit=131949237
 Total runtime: 623321.801 ms

(J'inclus cette requête comme symptôme, pas directement le problème à résoudre. Cette requête particulière n'est exécutée qu'une fois par semaine environ.)

Le serveur dispose de 32 Go de RAM, et j'ai configuré Postgres comme suit (suivant les conseils trouvés sur le Web):

shared_buffers = 8GB
autovacuum = on
effective_cache_size = 8GB
work_mem = 128MB
maintenance_work_mem = 64MB
wal_buffers = 1MB
checkpoint_segments = 10

iostat ne montre rien en cours de lecture, un peu de données en cours d'écriture (aucune idée où ni pourquoi) et 95% de CPU inactif:

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
           5.40    0.00    0.00    0.11    0.00   94.49

Device:            tps    kB_read/s    kB_wrtn/s    kB_read    kB_wrtn
vda               0.20         0.00         0.80          0          8
vdb               2.30         0.00        17.58          0        176

Exemple de sortie de vmstat:

  procs -----------memory---------- ---swap-- -----io---- -system-- ----cpu----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa
...
 1  0      0 18329748 126108 12600436    0    0     0    18  148  140  5  0 95  0
 2  0      0 18329400 126124 12600436    0    0     0     9  173  228  5  0 95  0

En m'accrochant aux pailles, j'ai déplacé le répertoire de données Postgres de vda à vdb mais bien sûr, cela n'a fait aucune différence.

Je suis donc perdu. Pourquoi Postgres n'utilise-t-il que 5% du processeur disponible alors qu'il n'attend aucune E / S? Je serais ravi de toute suggestion pour une enquête plus approfondie, d'autres outils, des choses aléatoires à essayer.

Mise à jour

J'ai instantané le serveur et l'ai lancé sur une autre partie du même cloud (une zone de disponibilité différente). Les résultats étaient un peu étranges. vmstatsur ce serveur rapporte 12% d'utilisation du processeur (ce que je comprends maintenant comme la valeur attendue pour une seule requête Postgres sur une machine virtuelle à 8 cœurs) - bien que le temps d'exécution de la requête réelle soit pratiquement identique (630 secondes vs 623).

Je me rends compte maintenant que cette requête particulière n'est probablement pas un bon exemple pour cette raison: elle ne peut utiliser qu'un seul noyau, et c'est un update(alors que le rendu des tuiles est juste selects).

Je n'ai pas non plus remarqué dans le explainqui planet_osm_polygonn'utilise apparemment pas d'index. Cela pourrait bien être la cause, alors je vais poursuivre cela ensuite.

Update2

Le problème semble définitivement être que le ou les index planet_osm_polygon sont / ne sont pas utilisés. Il y en a deux (un créé par osm2pgsql, un créé par moi en suivant un guide aléatoire):

CREATE INDEX idx_planet_osm_polygon_tags
  ON planet_osm_polygon
  USING gist
  (tags);


CREATE INDEX planet_osm_polygon_pkey
  ON planet_osm_polygon
  USING btree
  (osm_id);

Les statistiques sur planet_osm_polygon et planet_osm_point sont assez révélatrices, je pense:

planet_osm_polygon:

Sequential Scans    194204  
Sequential Tuples Read  60981018608 
Index Scans 1574    
Index Tuples Fetched    0

planet_osm_point:

Sequential Scans    1142    
Sequential Tuples Read  12960604    
Index Scans 183454  
Index Tuples Fetched    43427685

Si j'ai bien lu, Postgres a fouillé le planet_osm_polygon 1574 fois, mais n'a jamais rien trouvé, donc a fait un nombre ridiculement élevé de recherches par force brute.

La nouvelle question: pourquoi?

Mystère résolu

Grâce à la réponse de Frederik Ramm , la réponse s'avère assez simple: il n'y avait pas d'index spatial, pour une raison quelconque. C'était insignifiant de les régénérer:

create index planet_osm_polygon_polygon on planet_osm_polygon using gist(way);
create index planet_osm_polygon_point on planet_osm_point using gist(way);

L'exécution de cette requête prend désormais 4,6 secondes. Les index spatiaux comptent! :)

L'exécution de votre sortie Explain Anlayze via expliqué.depesz.com met en évidence que l'essentiel de la lenteur provient de cette action:

Seq Scan on planet_osm_polygon p 

Cela a-t-il été indexé auparavant? Pouvez-vous l'indexer maintenant?

En recherchant cette zone à problème, j'ai également trouvé un Q&A connexe sur un site Open Street Map:

• Serveur de tuiles local - Rendu extrêmement lent

PostgreSQL ne peut utiliser qu'un seul cœur pour une requête donnée. Il atteint de bonnes performances parallèles avec de nombreuses requêtes simultanées, mais ne bénéficie pas d'un nombre important de cœurs pour les charges de travail de quelques requêtes très volumineuses. Donc, si vous n'exécutez qu'une seule requête, 5% n'est pas si surprenant, même si je m'attends à ce que ce soit 12% sur un système à 8 cœurs.

Le manque d'iowait suggère qu'il ne souffre probablement pas d'E / S disque.

Donc, il ne semble pas être goulot d'étranglement sur le processeur ou sur les E / S.

Est-il possible que la requête soit simplement bloquée pendant un certain temps par un verrou? Recherchez pg_stat_activityla requête et rejoignez-la pg_lockspour voir s'il existe des verrous non accordés. (Il existe des requêtes prédéfinies pour la surveillance du verrouillage Pg).

La prochaine chose à faire est d'exécuter des tests système de niveau inférieur. Exécutez pg_test_fsync, utilisez les tests de CPU et d'E / S de sysbench, etc.

Vous devez également collecter perf top -aun peu la sortie, voir ce qu'elle fait réellement.