Forums PostgreSQL.fr

7uc0

Membre

Investigation [suite] - Temps d'execution

[RE] bonjour,

Dans la continuité de mes investigations sur des comportements lents et / ou bloquants, j'observe des temps de réponses hyper longs  (plusieurs minutes) sur une requête suivante contre une table assez volumineuse (entre 50 et 60 M d'enregistrements au total) :

explain analyze select count(*) from snsrrecord where recorddate between '2011-09-21 00:00:00' and '2011-09-23 00:00:00';
                                                                           QUERY PLAN                                                                            
-----------------------------------------------------------------------------------------------------------------------------------------------------------------
 Aggregate  (cost=17.10..17.11 rows=1 width=0) (actual time=268580.842..268580.843 rows=1 loops=1)
   ->  Index Scan using idx_record_recorddate on snsrrecord  (cost=0.00..17.10 rows=1 width=0) (actual time=45.583..267006.647 rows=2389648 loops=1)
         Index Cond: ((recorddate >= '2011-09-21 00:00:00'::timestamp without time zone) AND (recorddate <= '2011-09-23 00:00:00'::timestamp without time zone))
 Total runtime: 268580.889 ms
(4 rows)

  count  
---------
 2387745

explain analyze select count(*) from snsrrecord where recorddate between '2011-09-22 00:00:00' and '2011-09-23 00:00:00';
                                                                           QUERY PLAN                                                                            
-----------------------------------------------------------------------------------------------------------------------------------------------------------------
 Aggregate  (cost=17.10..17.11 rows=1 width=0) (actual time=15314.732..15314.733 rows=1 loops=1)
   ->  Index Scan using idx_record_recorddate on snsrrecord  (cost=0.00..17.10 rows=1 width=0) (actual time=23.264..15218.793 rows=153268 loops=1)
         Index Cond: ((recorddate >= '2011-09-22 00:00:00'::timestamp without time zone) AND (recorddate <= '2011-09-23 00:00:00'::timestamp without time zone))
 Total runtime: 15314.781 ms

 count  
--------
 151326

La machine n'est pas "au taquet"

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND                                                                                                                                                                                                                      
 1541 postgres  20   0 50640  37m  35m D    1  3.7   0:28.32 postgres

J'aimerais trouver le moyen de réduire significativement ce temps, mais j'avoue ne pas savoir quel levier activer (réduire le nombre d'enregistrements ?)

E.

PG 8.4.7, ubuntu 9.10

Dernière modification par 7uc0 (22/09/2011 17:34:49)

Marc Cousin

Membre

Re : Investigation [suite] - Temps d'execution

Bon, il y a évidemment vider la table. Mais je présume que ça n'ira pas.

On pourrait déjà commencer par passer les stats sur les tables. Elles ne sont pas à jour du tout (il récupère 2 millions d'enregistrements là où il s'attend à en récupérer 1). Autovacuum est désactivé, pour qu'elles soient fausses à ce point ?

=> Exécuter ANALYZE snsrrecord pour commencer.

La requête sera longue de toutes façons, vu qu'il faut aller chercher 2 millions d'enregistrements, et que PostgreSQL doit (pour le moment, ça va peut-être changer en 9.2 vu comment c'est parti) aller vérifier dans la table que ces enregistrements sont visibles pour la transaction en cours, au lieu de pouvoir se contenter de parcourir l'index. Mais déjà, avec des stats à jour, il prendra le plan  le moins coûteux.

---

Marc.

Marc Cousin

Membre

Re : Investigation [suite] - Temps d'execution

Ah, un dernier point: la machine est "au taquet", niveau disque, je pense: faites plutôt un iostat -x -m 1 (si iostat n'est pas là, installez le package sysstat).

---

Marc.

7uc0

Membre

Re : Investigation [suite] - Temps d'execution

@Marc : FS Au taquet durant l'execution de la requete avant analyze, CPU au taquet durant analyze

L'analyse réduit considérablement le temps de requête, N'y a-t-il pas un démon similaire à l'autovacuum, chargé d'orchestrer les analyses sur une base ?

Merci en tout cas

7uc0

Membre

Re : Investigation [suite] - Temps d'execution

Le statut des traitements automatisés

select
    current_database(),
    schemaname || '.' || relname as table,
    to_char(last_vacuum,'DD-MM-YYYY HH24:mi') as lastvacuum,
    to_char(last_autovacuum,'DD-MM-YYYY HH24:mi') as lastautovacuum,
    to_char(last_analyze,'DD-MM-YYYY HH24:mi') as lastanalyze,
    to_char(last_autoanalyze,'DD-MM-YYYY HH24:mi') as lastautoanalyze
from
    pg_stat_user_tables
order by
    2

 current_database |            table             |    lastvacuum    |  lastautovacuum  |   lastanalyze    | lastautoanalyze  
------------------+------------------------------+------------------+------------------+------------------+------------------
 sensordb1        | public.databasechangelog     | 06-09-2011 08:00 |                  | 06-09-2011 08:00 | 
 sensordb1        | public.databasechangeloglock | 06-09-2011 08:00 |                  | 06-09-2011 08:00 | 
 sensordb1        | public.patchlevel            | 06-09-2011 08:00 |                  | 06-09-2011 08:00 | 
 sensordb1        | public.snsrbinding           | 06-09-2011 08:00 |                  | 06-09-2011 08:00 | 
 sensordb1        | public.snsrbroadcast         | 06-09-2011 08:00 |                  | 22-09-2011 18:09 | 20-09-2011 19:08
 sensordb1        | public.snsrcfgvar            | 06-09-2011 08:00 |                  | 06-09-2011 08:00 | 30-08-2011 15:01
 sensordb1        | public.snsrcmd               | 06-09-2011 08:00 |                  | 06-09-2011 08:00 | 
 sensordb1        | public.snsrcmd_args          | 06-09-2011 08:00 |                  | 06-09-2011 08:00 | 
 sensordb1        | public.snsrcomdqueue         | 06-09-2011 08:00 |                  | 06-09-2011 08:00 | 
 sensordb1        | public.snsrconsolidation     | 06-09-2011 08:00 |                  | 06-09-2011 08:00 | 
 sensordb1        | public.snsrcustomer          | 06-09-2011 08:00 |                  | 06-09-2011 08:00 | 
 sensordb1        | public.snsrdevice            | 06-09-2011 08:00 | 23-09-2011 01:00 | 22-09-2011 18:09 | 23-09-2011 00:46
 sensordb1        | public.snsrdevicecfg         | 06-09-2011 08:00 |                  | 06-09-2011 08:00 | 
 sensordb1        | public.snsrdevicetypeassoc   | 06-09-2011 08:00 |                  | 06-09-2011 08:00 | 
 sensordb1        | public.snsrexport            | 06-09-2011 08:00 |                  | 06-09-2011 08:00 | 22-09-2011 01:52
 sensordb1        | public.snsrfactorytest       | 06-09-2011 08:00 |                  | 06-09-2011 08:00 | 
 sensordb1        | public.snsrfactorytest_tests | 06-09-2011 08:00 |                  | 06-09-2011 08:00 | 19-09-2011 17:34
 sensordb1        | public.snsrmember            | 06-09-2011 08:00 |                  | 06-09-2011 08:00 | 
 sensordb1        | public.snsrmemberprofile     | 06-09-2011 08:00 |                  | 06-09-2011 08:00 | 
 sensordb1        | public.snsrmetric            | 06-09-2011 08:00 |                  | 06-09-2011 08:00 | 
 sensordb1        | public.snsrmetricvar         | 06-09-2011 08:00 |                  | 06-09-2011 08:00 | 
 sensordb1        | public.snsrmodeldef          | 06-09-2011 08:00 |                  | 06-09-2011 08:00 | 
 sensordb1        | public.snsrnode              | 06-09-2011 08:00 |                  | 06-09-2011 08:00 | 
 sensordb1        | public.snsroperation         | 06-09-2011 08:00 |                  | 06-09-2011 08:00 | 
 sensordb1        | public.snsrorganisation      | 06-09-2011 08:00 |                  | 06-09-2011 08:00 | 
 sensordb1        | public.snsrpackage           | 06-09-2011 08:00 |                  | 06-09-2011 08:00 | 
 sensordb1        | public.snsrpermassign        | 06-09-2011 08:00 |                  | 06-09-2011 08:00 | 
 sensordb1        | public.snsrpicture           | 06-09-2011 08:00 |                  | 06-09-2011 08:00 | 
 sensordb1        | public.snsrprobalert         | 06-09-2011 08:00 |                  | 06-09-2011 08:00 | 15-09-2011 09:48
 sensordb1        | public.snsrprobcond          | 06-09-2011 08:00 |                  | 06-09-2011 08:00 | 
 sensordb1        | public.snsrprobe             | 06-09-2011 08:00 |                  | 06-09-2011 08:00 | 
 sensordb1        | public.snsrprobecfg          | 06-09-2011 08:00 |                  | 06-09-2011 08:00 | 
 sensordb1        | public.snsrproduct           | 06-09-2011 08:00 |                  | 06-09-2011 08:00 | 
 sensordb1        | public.snsrprofile           | 06-09-2011 08:00 |                  | 06-09-2011 08:00 | 
 sensordb1        | public.snsrprop              | 06-09-2011 08:00 |                  | 06-09-2011 08:00 | 
 sensordb1        | public.snsrrecord            | 06-09-2011 08:07 | 20-09-2011 23:11 | 22-09-2011 17:52 | 18-09-2011 01:52
 sensordb1        | public.snsrrelease           | 06-09-2011 08:00 |                  | 06-09-2011 08:00 | 
 sensordb1        | public.snsrsite              | 06-09-2011 08:00 |                  | 06-09-2011 08:00 | 
 sensordb1        | public.snsrsiteway           | 06-09-2011 08:00 |                  | 06-09-2011 08:00 | 
 sensordb1        | public.snsrstatusvar         | 06-09-2011 08:00 |                  | 06-09-2011 08:00 | 
 sensordb1        | public.snsrsystem            | 06-09-2011 08:00 |                  | 06-09-2011 08:00 | 
 sensordb1        | public.snsrtargetmetric      | 06-09-2011 08:00 |                  | 06-09-2011 08:00 | 
 sensordb1        | public.snsrtypedef           | 06-09-2011 08:00 |                  | 06-09-2011 08:00 | 
 sensordb1        | public.snsrvariable          | 06-09-2011 08:00 |                  | 22-09-2011 18:09 | 
 sensordb1        | public.snsrvendor            | 06-09-2011 08:00 |                  | 06-09-2011 08:00 | 
 sensordb1        | public.snsrversion           | 06-09-2011 08:00 |                  | 06-09-2011 08:00 |

Marc Cousin

Membre

Re : Investigation [suite] - Temps d'execution

C'est autovacuum qui fait aussi le passage des stats. Suivant les paramètres autovacuum_analyze_threshold et autovacuum_analyze_scale_factor.

Malgré tout, il vaut mieux le faire au moins une fois manuellement de temps en temps. Même 1% de changement dans une table, quelquefois c'est très important pour un plan d'exécution. Et puis il y a quelques cas où les stats peuvent ne pas se retrouver à jour, malgré autovacuum.

=> Le plan a du basculer sur soit un bitmap index scan, soit sur un full scan, je présume ?

Sinon, pour aller encore plus vite sur cette requête, si la plupart du temps on fait des interrogations sur des données groupées dans le temps, on peut trier la table physiquement sur l'index idx_record_recorddate avec la commande cluster. C'est à refaire régulièrement, mais ça permet de réduire le nombre d'entrées sorties nécessaires pour récupérer des données dans une plage de dates.

---

Marc.

7uc0

Membre

Re : Investigation [suite] - Temps d'execution

Effectivementn, du Bitmap Heap et Bitmap Index (sans index, j'aurais eu droit à du Full / Seq  scan ?)

explain analyze select count(*) from snsrrecord where recorddate between '2011-09-22 00:00:00' and '2011-09-23 00:00:00';
                                                                              QUERY PLAN                                                                               
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Aggregate  (cost=486244.42..486244.43 rows=1 width=0) (actual time=111493.738..111493.739 rows=1 loops=1)
   ->  Bitmap Heap Scan on snsrrecord  (cost=8645.59..485492.17 rows=300897 width=0) (actual time=44681.949..110085.654 rows=2190730 loops=1)
         Recheck Cond: ((recorddate >= '2011-09-22 00:00:00'::timestamp without time zone) AND (recorddate <= '2011-09-23 00:00:00'::timestamp without time zone))
         ->  Bitmap Index Scan on idx_record_recorddate  (cost=0.00..8570.36 rows=300897 width=0) (actual time=44650.388..44650.388 rows=2221609 loops=1)
               Index Cond: ((recorddate >= '2011-09-22 00:00:00'::timestamp without time zone) AND (recorddate <= '2011-09-23 00:00:00'::timestamp without time zone))
 Total runtime: 111495.077 ms

Je rebondis sur un de tes posts précedents pour creuser :

"On pourrait déjà commencer par passer les stats sur les tables. Elles ne sont pas à jour du tout"

Que signifie le terme stats ? l'execution d'anlyze ? vacuum ? les deux ? pas du tout

Marc Cousin

Membre

Re : Investigation [suite] - Temps d'execution

Oui, sans index, ça aurait été full scan.

Les statistiques, c'est ce qui est produit par ANALYZE. Il y a des données comme la taille moyenne d'un enregistrement, le pourcentage de null dans une colonne, le nombre de valeurs distinctes, la répartition, la corrélation entre 2 valeurs consécutives… Ça permet à l'optimiseur de choisir un plan d'exécution intelligent.

Il y a aussi des statistiques d'exécution, mais cela n'a rien à voir (elles ne sont pas utilisées par l'optimiseur).

---

Marc.

7uc0

Membre

Re : Investigation [suite] - Temps d'execution

Thx

jhashe

Membre

Re : Investigation [suite] - Temps d'execution

Bonjour,

Je viens d'exécuter la requête d'analyse des statistiques ci-dessus sur ma propre BDD et je constate que les colonnes lastautovacuum et lastautoanalyze sont vides pour presque toutes les tables! Le paramètre autovaccuum est pourtant à "on" (toutes les options concernant ce paramètre ont les valeurs par défaut). Dois-je m'en inquiéter ?

Marc Cousin

Membre

Re : Investigation [suite] - Temps d'execution

C'est un peu louche. Sauf si la base ne bouge jamais.

Les autres paramètres autovacuum* dans le postgresql.conf, ils sont à quoi ?

---

Marc.

jhashe

Membre

Re : Investigation [suite] - Temps d'execution

Comme je le dis dans mon précédent post, ils sont tous à leur valeur par défaut; plus précisément, tous les paramètres concernant l'autovacuum sont "commentarisés" sauf autovacuum=on

Par ailleurs, parmi les processus actifs (au sens système), j'ai un processus "postgres: autovacuum launcher process" qui tourne.

Dernière modification par jhashe (26/09/2011 10:43:34)

Marc Cousin

Membre

Re : Investigation [suite] - Temps d'execution

Ok. Donc le paramétrage est celui par défaut, qui est la plupart du temps suffisant.

Ça n'est pas trop grave. Par contre, passez les stats sur toutes les tables qui n'en ont pas…

Le plus simple c'est de passer les stats sur toute la base. Il suffit de lancer 'ANALYZE' sans aucun paramètre. Voire 'VACUUM ANALYZE', il en profitera pour nettoyer la base.

---

Marc.