Re: Problème de select suivant un update

Bonjour,

Il y a quelques temps j'ai posté un mail sur un problème d'update mais
je me m'étais ensuite rendu compte d'une erreur dans nos tests.
Maintenant plus d'erreur, mais nous observons toujours un comportement
curieux -reproductible- d'une série d'update puis select sur une base
PG. Je suis preneur d'explication si vous en avez ...

Voilà : il s'agit d'une base PG 8.3.1 sur serveur linux RedHat 5.1 64
bit avec 4 Go de RAM.

On travaille sur une table de test contenant 5 millions de lignes. On
effectue un update portant sur environ 70000 lignes (avec utilisation
d'index). Lorsque on effectue ensuite un select portant sur les lignes
mises à jour (avec même condition donc on ne retournera aucune ligne)
le temps d'exécution de ce select est très long alors que on
s'attendrait à un retour immédiat.

Pourquoi ???

Ci-dessous les résultats des explain analyze update, select etc :

difmet=> \d test_update
Table « public.test_update »
Colonne | Type | Modificateurs
------------+-----------------------------+---------------
id | bigint | not null
state | integer | not null
state_date | timestamp without time zone | not null
priority | integer | not null
channel | character varying(30) | not null
clef | character varying(2048) | not null
data1 | character varying |
data2 | character varying |
data3 | character varying |
data4 | character varying |
Index :
« pk_test_update_id » PRIMARY KEY, btree (id)
« indx_test_update_channel » btree (state, channel
varchar_pattern_ops, clef varchar_pattern_ops, priority, state_date)
Contraintes de vérification :
« ck_test_update_id » CHECK (id > 0)
« ck_test_update_state » CHECK (state > 0)

difmet=>

difmet=> \timing
Chronométrage activé.

difmet=> \!date
mer mai 21 10:58:20 GMT 2008

difmet=> explain analyze update test_update set state = 3001 where
state
= 2101 and channel like 'FTP' and clef like
'ddbddbddbddbddbddbddbddbddbddbddbddbddbddbddb' ;

QUERY PLAN
--------------------------------------------------------------------------------------------
Index Scan using indx_test_update_channel on test_update
(cost=0.00..129127.15 rows=69744 width=572) (actual
time=22.140..327988.689 rows=71000 loops=1)
Index Cond: ((state = 2101) AND ((channel)::text ~=~ 'FTP'::text)
AND ((clef)::text ~=~
'ddbddbddbddbddbddbddbddbddbddbddbddbddbddbddb'::text))
Filter: (((channel)::text ~~ 'FTP'::text) AND ((clef)::text ~~
'ddbddbddbddbddbddbddbddbddbddbddbddbddbddbddb'::text))
Total runtime: 697914.820 ms
(4 lignes)

Temps : 698885,960 ms

difmet=> \!date
mer mai 21 11:09:59 GMT 2008

difmet=> explain analyse select id,priority,state_date from test_update
where state = 2101 and channel like 'FTP' and clef like
'ddbddbddbddbddbddbddbddbddbddbddbddbddbddbddb' LIMIT 10;

QUERY PLAN
----------------------------------------------------------------------------------------
Limit (cost=0.00..18.52 rows=10 width=20) (actual
time=258036.859..258036.859 rows=0 loops=1)
-> Index Scan using indx_test_update_channel on test_update
(cost=0.00..130964.52 rows=70734 width=20) (actual
time=258036.854..258036.854 rows=0 loops=1)
Index Cond: ((state = 2101) AND ((channel)::text ~=~
'FTP'::text) AND ((clef)::text ~=~
'ddbddbddbddbddbddbddbddbddbddbddbddbddbddbddb'::text))
Filter: (((channel)::text ~~ 'FTP'::text) AND ((clef)::text
~~
'ddbddbddbddbddbddbddbddbddbddbddbddbddbddbddb'::text))
Total runtime: 258036.916 ms
(5 lignes)

Temps : 262332,196 ms

difmet=> \!date
mer mai 21 11:14:22 GMT 2008

On voit bien que le select suivant l'update passe par l'index, que le
nombre de lignes concernées est 0, mais pourquoi le temps d'exécution de
ce select n'est-il pas quasi-nul ?

On a aussi fait le même test sur une version postgres 8.2, même
comportement.

Merci de votre aide, Valérie.

--

********************************************************************
* Les points de vue exprimes sont strictement personnels et *
* n'engagent pas la responsabilite de METEO-FRANCE. *
********************************************************************
* Valerie SCHNEIDER Tel : +33 (0)5 61 07 81 91 *
* METEO-FRANCE / DSI/DEV Fax : +33 (0)5 61 07 81 09 *
* 42, avenue G. Coriolis Email : Valerie(dot)Schneider(at)meteo(dot)fr *
* 31057 TOULOUSE Cedex 1 - FRANCE http://www.meteo.fr *
********************************************************************

On Tue, 03 Jun 2008 13:41:13 +0000
Valérie SCHNEIDER <valerie(dot)schneider(at)meteo(dot)fr> wrote:

> Bonjour,
>
> Il y a quelques temps j'ai posté un mail sur un problème d'update mais
> je me m'étais ensuite rendu compte d'une erreur dans nos tests.
> Maintenant plus d'erreur, mais nous observons toujours un comportement
> curieux -reproductible- d'une série d'update puis select sur une base
> PG. Je suis preneur d'explication si vous en avez ...
>
> Voilà : il s'agit d'une base PG 8.3.1 sur serveur linux RedHat 5.1 64
> bit avec 4 Go de RAM.
>
> On travaille sur une table de test contenant 5 millions de lignes. On
> effectue un update portant sur environ 70000 lignes (avec utilisation
> d'index). Lorsque on effectue ensuite un select portant sur les lignes
> mises à jour (avec même condition donc on ne retournera aucune ligne)
> le temps d'exécution de ce select est très long alors que on
> s'attendrait à un retour immédiat.
>
> Pourquoi ???
>
> Ci-dessous les résultats des explain analyze update, select etc :
>
> difmet=> \d test_update
> Table « public.test_update »
> Colonne | Type | Modificateurs
> ------------+-----------------------------+---------------
> id | bigint | not null
> state | integer | not null
> state_date | timestamp without time zone | not null
> priority | integer | not null
> channel | character varying(30) | not null
> clef | character varying(2048) | not null
> data1 | character varying |
> data2 | character varying |
> data3 | character varying |
> data4 | character varying |
> Index :
> « pk_test_update_id » PRIMARY KEY, btree (id)
> « indx_test_update_channel » btree (state, channel
> varchar_pattern_ops, clef varchar_pattern_ops, priority, state_date)
> Contraintes de vérification :
> « ck_test_update_id » CHECK (id > 0)
> « ck_test_update_state » CHECK (state > 0)
>
> difmet=>
>
> difmet=> \timing
> Chronométrage activé.
>
>
> difmet=> \!date
> mer mai 21 10:58:20 GMT 2008
>
>
> difmet=> explain analyze update test_update set state = 3001 where
> state
> = 2101 and channel like 'FTP' and clef like
> 'ddbddbddbddbddbddbddbddbddbddbddbddbddbddbddb' ;
>
> QUERY PLAN
> --------------------------------------------------------------------------------------------
> Index Scan using indx_test_update_channel on test_update
> (cost=0.00..129127.15 rows=69744 width=572) (actual
> time=22.140..327988.689 rows=71000 loops=1)
> Index Cond: ((state = 2101) AND ((channel)::text ~=~ 'FTP'::text)
> AND ((clef)::text ~=~
> 'ddbddbddbddbddbddbddbddbddbddbddbddbddbddbddb'::text))
> Filter: (((channel)::text ~~ 'FTP'::text) AND ((clef)::text ~~
> 'ddbddbddbddbddbddbddbddbddbddbddbddbddbddbddb'::text))
> Total runtime: 697914.820 ms
> (4 lignes)
>
> Temps : 698885,960 ms
>
>
> difmet=> \!date
> mer mai 21 11:09:59 GMT 2008
>
>
> difmet=> explain analyse select id,priority,state_date from test_update
> where state = 2101 and channel like 'FTP' and clef like
> 'ddbddbddbddbddbddbddbddbddbddbddbddbddbddbddb' LIMIT 10;
>
> QUERY PLAN
> ----------------------------------------------------------------------------------------
> Limit (cost=0.00..18.52 rows=10 width=20) (actual
> time=258036.859..258036.859 rows=0 loops=1)
> -> Index Scan using indx_test_update_channel on test_update
> (cost=0.00..130964.52 rows=70734 width=20) (actual
> time=258036.854..258036.854 rows=0 loops=1)
> Index Cond: ((state = 2101) AND ((channel)::text ~=~
> 'FTP'::text) AND ((clef)::text ~=~
> 'ddbddbddbddbddbddbddbddbddbddbddbddbddbddbddb'::text))
> Filter: (((channel)::text ~~ 'FTP'::text) AND ((clef)::text
> ~~
> 'ddbddbddbddbddbddbddbddbddbddbddbddbddbddbddb'::text))
> Total runtime: 258036.916 ms
> (5 lignes)
>
> Temps : 262332,196 ms
>
>
> difmet=> \!date
> mer mai 21 11:14:22 GMT 2008
>
>
> On voit bien que le select suivant l'update passe par l'index, que le
> nombre de lignes concernées est 0, mais pourquoi le temps d'exécution de
> ce select n'est-il pas quasi-nul ?
>
> On a aussi fait le même test sur une version postgres 8.2, même
> comportement.
>
> Merci de votre aide, Valérie.
>
> --

Valérie,

Essayez en faisant un VACUUM après mises à jour et avant select.
Si ça améliore les performances, lisez la doc sur vacuum.

AMHA, toutes les BD privilégient le conversationnel et les index sont mis à jour
avec un certain délai, ce qui n'est pas grâve à la vitesse de saisie manuelle.
Mais je ne pense pas que vos 70 000 mises à jour soient faites une par une ?

Amicalement,
--
Alain <eurlix(dot)alain(at)free(dot)fr>

Valérie SCHNEIDER a écrit :
> [...]
> On voit bien que le select suivant l'update passe par l'index, que le
> nombre de lignes concernées est 0, mais pourquoi le temps d'exécution de
> ce select n'est-il pas quasi-nul ?
>

Personnellement, ça ne me choque pas outre mesure, mais je n'ai
peut-être pas assez d'infos pour comprendre.

1. Avant mise à jour, quel temps met cette requête à s'exécuter ?
2. Quelle est la taille de la table et de l'index ? (taille physique,
pas le nombre de lignes)
3. Comment est construit l'index ? (à priori, je suppose qu'il utilise
trois colonnes (state, channel, clef)
4. Avez-vous essayé de lancer un ANALYZE entre l'UPDATE et le SELECT ?
Pourriez-vous le faire et nous indiquer ce que cela donne ?

Cordialement.

--
Guillaume.
http://www.postgresqlfr.org
http://dalibo.com

Le mardi 03 juin 2008 à 23:49 +0200, Guillaume Lelarge a écrit :
> Valérie SCHNEIDER a écrit :
> > [...]
> > On voit bien que le select suivant l'update passe par l'index, que le
> > nombre de lignes concernées est 0, mais pourquoi le temps d'exécution de
> > ce select n'est-il pas quasi-nul ?
> >
>
> Personnellement, ça ne me choque pas outre mesure, mais je n'ai
> peut-être pas assez d'infos pour comprendre.
Dans mon premier mail j'ai mis la description de la table et des index,
je les remets ci-dessous :
difmet=> \d test_update
Table « public.test_update »
Colonne | Type | Modificateurs
------------+-----------------------------+---------------
id | bigint | not null
state | integer | not null
state_date | timestamp without time zone | not null
priority | integer | not null
channel | character varying(30) | not null
clef | character varying(2048) | not null
data1 | character varying |
data2 | character varying |
data3 | character varying |
data4 | character varying |
Index :
« pk_test_update_id » PRIMARY KEY, btree (id)
« indx_test_update_channel » btree (state, channel
varchar_pattern_ops, clef varchar_pattern_ops, priority, state_date)
Contraintes de vérification :
« ck_test_update_id » CHECK (id > 0)
« ck_test_update_state » CHECK (state > 0)

difmet=>

La taille de la table sur disque est de 3 Go pour 5 millions de lignes
(en moyenne 700 octets par ligne).

L'update porte sur 70000 lignes et met un certain temps. Le problème
pour moi n'est pas là. Ce qui me dérange, c'est qu'ensuite, lorsque je
fais un accès select à la table sur ces mêmes lignes qui viennent d'être
mises à jour, avec les mêmes conditions, donc un select qui ramènera 0
ligne, et qui passe par l'index, cet accès devrait être immédiat, or il
met un temps catastrophique (de l'ordre de 300s) ! Si je relance le même
select (sur le même paquet de lignes), là le comportement sera celui
attendu : résultat quasi immédiat.
Le problème semble bien porter sur les lignes qui viennent d'être mises
à jour. Un select du même type (utilisant l'index) et portant sur un
autre paquet de lignes, sera rapide (<1s).

C'est réellement un pb pour nous. On est en train de mettre en place une
base à changement d'état, des tables journalières contenant 5 millions
de lignes, chacune sera mise à jour 2 fois dans la journée en moyenne,
donc 10 millions d'update par jour; en permanence une tâche recherchera
des lignes dans un état donné, donc ce que l'on teste reflétera ce que
l'on cherche à mettre en opérationnel.

Remarque : sur la même machine on a fait une base oracle (10g)
identique, et exécuté les mêmes instructions : le temps d'update est
comparable, le select qui suit est immédiat.
>
> 1. Avant mise à jour, quel temps met cette requête à s'exécuter ?
> 2. Quelle est la taille de la table et de l'index ? (taille physique,
> pas le nombre de lignes)
> 3. Comment est construit l'index ? (à priori, je suppose qu'il utilise
> trois colonnes (state, channel, clef)
> 4. Avez-vous essayé de lancer un ANALYZE entre l'UPDATE et le SELECT ?
> Pourriez-vous le faire et nous indiquer ce que cela donne ?

Autre test :
1. un select sur un paquet de lignes toujours en passant par index (on
fait toujours un explain analyze pour en être sûr) -> comportement
normal (réponse immédiate)
2. update sur ce même paquet de lignes -> un certain temps, supposé
normal (900 s)
3. analyse verbose de la table -> 21s
4. le select sur le même paquet de lignes (qui viennent d'être
modifiées) donc remonte 0 ligne -> 419 s !!!!
5. un second select sur le même paquet de lignes (donc remonte 0 ligne)
-> immédiat

Voir le détail des explain analyze de cette séquence dans le fichier
joint.

Merci, Valérie.

>
> Cordialement.
>
>
--

********************************************************************
* Les points de vue exprimes sont strictement personnels et *
* n'engagent pas la responsabilite de METEO-FRANCE. *
********************************************************************
* Valerie SCHNEIDER Tel : +33 (0)5 61 07 81 91 *
* METEO-FRANCE / DSI/DEV Fax : +33 (0)5 61 07 81 09 *
* 42, avenue G. Coriolis Email : Valerie(dot)Schneider(at)meteo(dot)fr *
* 31057 TOULOUSE Cedex 1 - FRANCE http://www.meteo.fr *
********************************************************************

Valérie SCHNEIDER a écrit :
> Le mardi 03 juin 2008 à 23:49 +0200, Guillaume Lelarge a écrit :
>> Valérie SCHNEIDER a écrit :
>>> [...]
> [...]
> La taille de la table sur disque est de 3 Go pour 5 millions de lignes
> (en moyenne 700 octets par ligne).
>
> L'update porte sur 70000 lignes et met un certain temps. Le problème
> pour moi n'est pas là.

On est d'accord là-dessus.

> Ce qui me dérange, c'est qu'ensuite, lorsque je
> fais un accès select à la table sur ces mêmes lignes qui viennent d'être
> mises à jour, avec les mêmes conditions, donc un select qui ramènera 0
> ligne, et qui passe par l'index, cet accès devrait être immédiat, or il
> met un temps catastrophique (de l'ordre de 300s) !

Ça peut-être dû au bgwriter qui s'exécute, ou au postmaster qui écrit
les tampons modifiés du cache pour récupérer de la place.

> Si je relance le même
> select (sur le même paquet de lignes), là le comportement sera celui
> attendu : résultat quasi immédiat.

Problème de cache à priori (voir mon explication plus détaillée ci-dessous).

> Le problème semble bien porter sur les lignes qui viennent d'être mises
> à jour. Un select du même type (utilisant l'index) et portant sur un
> autre paquet de lignes, sera rapide (<1s).
>

Cache trop petit ? (voir mon explication plus détaillée ci-dessous)

> C'est réellement un pb pour nous. On est en train de mettre en place une
> base à changement d'état, des tables journalières contenant 5 millions
> de lignes, chacune sera mise à jour 2 fois dans la journée en moyenne,
> donc 10 millions d'update par jour; en permanence une tâche recherchera
> des lignes dans un état donné, donc ce que l'on teste reflétera ce que
> l'on cherche à mettre en opérationnel.
>

CHECKPOINT peut être votre solution (voir mon explication plus détaillée
ci-dessous).

> Remarque : sur la même machine on a fait une base oracle (10g)
> identique, et exécuté les mêmes instructions : le temps d'update est
> comparable, le select qui suit est immédiat.

Cédric Villemain me dit qu'Oracle a un cache pour les résultats. J'en
profite donc pour ajouter ici un point qui a son importance : PostgreSQL
n'a pas de cache pour les résultats. Son cache est principalement un
cache disque (shared_buffers pour les fichiers de données, temp_buffer
pour les objets temporaires, wal_buffers pour les journaux de transaction).

>> 1. Avant mise à jour, quel temps met cette requête à s'exécuter ?
>> 2. Quelle est la taille de la table et de l'index ? (taille physique,
>> pas le nombre de lignes)
>> 3. Comment est construit l'index ? (à priori, je suppose qu'il utilise
>> trois colonnes (state, channel, clef)
>> 4. Avez-vous essayé de lancer un ANALYZE entre l'UPDATE et le SELECT ?
>> Pourriez-vous le faire et nous indiquer ce que cela donne ?
>
> Autre test :
> 1. un select sur un paquet de lignes toujours en passant par index (on
> fait toujours un explain analyze pour en être sûr) -> comportement
> normal (réponse immédiate)
> 2. update sur ce même paquet de lignes -> un certain temps, supposé
> normal (900 s)
> 3. analyse verbose de la table -> 21s
> 4. le select sur le même paquet de lignes (qui viennent d'être
> modifiées) donc remonte 0 ligne -> 419 s !!!!
> 5. un second select sur le même paquet de lignes (donc remonte 0 ligne)
> -> immédiat
>

Ce n'est pas un problème de l'optimiseur car vous avez mis à jour les
statistiques avec l'étape 3 (ça se voit dans le explain du fichier,
stats identiques pour le LIMIT comme pour le INDEX SCAN).

La différence de temps d'exécution entre les points 4 et 5 est
clairement un problème de cache PostgreSQL. Voici mon hypothèse :
* étape 1, le cache n'est pas rempli, le processus postgres lié à votre
client peut lire rapidement le disque ;
* étape 2, mise à jour des lignes, certaines des lignes sont écrites
sur disque mais pas toutes ;
* étape 3, analyze de la table, vu le nombre de lignes, ça impacte peu
le cache ;
* étape 4, le SELECT va vouloir charger une partie de la table et de
l'index dans le cache... malheureusement, il n'y a pas assez de
place... malheureusement encore, il doit écrire les pages disque
modifiées dans le tampon sur disque, d'où le temps monstrueux de
l'exécution.
* étape 5, le deuxième SELECT est rapide car le cache contient déjà la
majorité du contenu de la table et de l'index... et s'il a besoin de
plus, l'étape 4 a déjà écrit une bonne partie sur le disque.

Il y a deux moyens de vérifier mon hypothèse. La première est d'ajouter
une étape 3.5 qui exécute un CHECKPOINT... à ce moment-là, vous serez
certaine que le cache ne contient aucun tampon modifié et, du coup, le
SELECT de l'étape 4 devrait être plus rapide (toujours d'après mon
hypothèse). La seconde est d'utiliser vmstat pour vérifier si des
écritures disque ont bien lieu pendant le SELECT.

Si cela ne change rien, d'autres questions permettraient d'avancer :
* de quel quantité de mémoire dispose le serveur ?
* que vaut shared_buffers ? (s'il est possible d'avoir le fichier
postgresql.conf complet, ce serait préférable... vous pouvez me
l'envoyer directement si cela pose un problème qu'il devienne public)
* et quel est la taille de la table (3 Go à priori) et des index ?

Désolé pour toutes ces questions, mais c'est le seul moyen d'avancer :-/

--
Guillaume.
http://www.postgresqlfr.org
http://dalibo.com

Le Wednesday 04 June 2008, Guillaume Lelarge a écrit :
> Valérie SCHNEIDER a écrit :
> > Le mardi 03 juin 2008 à 23:49 +0200, Guillaume Lelarge a écrit :
> >> Valérie SCHNEIDER a écrit :
> >>> [...]
> >
> > [...]
> > La taille de la table sur disque est de 3 Go pour 5 millions de lignes
> > (en moyenne 700 octets par ligne).
> >
> > L'update porte sur 70000 lignes et met un certain temps. Le problème
> > pour moi n'est pas là.
>
> On est d'accord là-dessus.
>
> > Ce qui me dérange, c'est qu'ensuite, lorsque je
> > fais un accès select à la table sur ces mêmes lignes qui viennent d'être
> > mises à jour, avec les mêmes conditions, donc un select qui ramènera 0
> > ligne, et qui passe par l'index, cet accès devrait être immédiat, or il
> > met un temps catastrophique (de l'ordre de 300s) !
>
> Ça peut-être dû au bgwriter qui s'exécute, ou au postmaster qui écrit
> les tampons modifiés du cache pour récupérer de la place.
>
> > Si je relance le même
> > select (sur le même paquet de lignes), là le comportement sera celui
> > attendu : résultat quasi immédiat.
>
> Problème de cache à priori (voir mon explication plus détaillée
> ci-dessous).
>
> > Le problème semble bien porter sur les lignes qui viennent d'être mises
> > à jour. Un select du même type (utilisant l'index) et portant sur un
> > autre paquet de lignes, sera rapide (<1s).
>
> Cache trop petit ? (voir mon explication plus détaillée ci-dessous)
>
> > C'est réellement un pb pour nous. On est en train de mettre en place une
> > base à changement d'état, des tables journalières contenant 5 millions
> > de lignes, chacune sera mise à jour 2 fois dans la journée en moyenne,
> > donc 10 millions d'update par jour; en permanence une tâche recherchera
> > des lignes dans un état donné, donc ce que l'on teste reflétera ce que
> > l'on cherche à mettre en opérationnel.
>
> CHECKPOINT peut être votre solution (voir mon explication plus détaillée
> ci-dessous).
>
> > Remarque : sur la même machine on a fait une base oracle (10g)
> > identique, et exécuté les mêmes instructions : le temps d'update est
> > comparable, le select qui suit est immédiat.
>
> Cédric Villemain me dit qu'Oracle a un cache pour les résultats. J'en
> profite donc pour ajouter ici un point qui a son importance : PostgreSQL
> n'a pas de cache pour les résultats. Son cache est principalement un
> cache disque (shared_buffers pour les fichiers de données, temp_buffer
> pour les objets temporaires, wal_buffers pour les journaux de transaction).

ahem, je ne sais pas comment oracle gère son cache de résulats, mais il est
manifeste que pour Valérie (avec la conf d'oracle et de postgresql qui sont
propre à son install, et que nous ne connaissons pas) oracle donne de
meilleures perfs que postgresql.

>
> >> 1. Avant mise à jour, quel temps met cette requête à s'exécuter ?
> >> 2. Quelle est la taille de la table et de l'index ? (taille physique,
> >> pas le nombre de lignes)
> >> 3. Comment est construit l'index ? (à priori, je suppose qu'il utilise
> >> trois colonnes (state, channel, clef)
> >> 4. Avez-vous essayé de lancer un ANALYZE entre l'UPDATE et le SELECT ?
> >> Pourriez-vous le faire et nous indiquer ce que cela donne ?
> >
> > Autre test :
> > 1. un select sur un paquet de lignes toujours en passant par index (on
> > fait toujours un explain analyze pour en être sûr) -> comportement
> > normal (réponse immédiate)
> > 2. update sur ce même paquet de lignes -> un certain temps, supposé
> > normal (900 s)
> > 3. analyse verbose de la table -> 21s
> > 4. le select sur le même paquet de lignes (qui viennent d'être
> > modifiées) donc remonte 0 ligne -> 419 s !!!!
> > 5. un second select sur le même paquet de lignes (donc remonte 0 ligne)
> > -> immédiat
>
> Ce n'est pas un problème de l'optimiseur car vous avez mis à jour les
> statistiques avec l'étape 3 (ça se voit dans le explain du fichier,
> stats identiques pour le LIMIT comme pour le INDEX SCAN).

En fait, l'optimiseur ne rentre pas en ligne de compte pour comprendre
pourquoi le select apres update est bien long.

Cela n'empeche pas d'optimier index et tables.
1/ l'index obligeant à un filter n'est pas forcément optimum.
2/ les statistiques me semblent insuffisantes (avec un champs text un stat
target inférieur à 100 me semble tres optimiste)

>
> La différence de temps d'exécution entre les points 4 et 5 est
> clairement un problème de cache PostgreSQL. Voici mon hypothèse :
> * étape 1, le cache n'est pas rempli, le processus postgres lié à votre
> client peut lire rapidement le disque ;
> * étape 2, mise à jour des lignes, certaines des lignes sont écrites
> sur disque mais pas toutes ;
> * étape 3, analyze de la table, vu le nombre de lignes, ça impacte peu
> le cache ;
> * étape 4, le SELECT va vouloir charger une partie de la table et de
> l'index dans le cache... malheureusement, il n'y a pas assez de
> place... malheureusement encore, il doit écrire les pages disque
> modifiées dans le tampon sur disque, d'où le temps monstrueux de
> l'exécution.
> * étape 5, le deuxième SELECT est rapide car le cache contient déjà la
> majorité du contenu de la table et de l'index... et s'il a besoin de
> plus, l'étape 4 a déjà écrit une bonne partie sur le disque.
>
> Il y a deux moyens de vérifier mon hypothèse. La première est d'ajouter
> une étape 3.5 qui exécute un CHECKPOINT... à ce moment-là, vous serez
> certaine que le cache ne contient aucun tampon modifié et, du coup, le
> SELECT de l'étape 4 devrait être plus rapide (toujours d'après mon
> hypothèse). La seconde est d'utiliser vmstat pour vérifier si des
> écritures disque ont bien lieu pendant le SELECT.

iotop (ou une utilisation de libnotify) pourraient être utile pour déterminer
les processus créant de l'I/O (si vmstat confirme un acces io important).

>
> Si cela ne change rien, d'autres questions permettraient d'avancer :
> * de quel quantité de mémoire dispose le serveur ?
> * que vaut shared_buffers ? (s'il est possible d'avoir le fichier
> postgresql.conf complet, ce serait préférable... vous pouvez me
> l'envoyer directement si cela pose un problème qu'il devienne public)
> * et quel est la taille de la table (3 Go à priori) et des index ?
>
> Désolé pour toutes ces questions, mais c'est le seul moyen d'avancer :-/
>
>
> --
> Guillaume.
> http://www.postgresqlfr.org
> http://dalibo.com

--
Cédric Villemain
Administrateur de Base de Données
Cel: +33 (0)6 74 15 56 53
http://dalibo.com - http://dalibo.org

Bonsoir... enfin bonjour plutôt :)

Valérie SCHNEIDER a écrit :
> [...]
> Question: je suis très surpris du temps de sélection
> du cas (3) qui est très grand par rapport aux autres
> select, et pour ne récupérer aucune ligne (car un
> update précédent les a déplacées).
>

Pour être franc, moi aussi. Je viens de faire sept tests (et j'en
prépare un huitième qui s'exécutera pendant que je dormirais), tous ont
à peu de choses près la même durée d'exécution alors que le paramétrage
est bien différent. Je n'ai pas encore tout analysé car j'évite
d'utiliser ma machine pendant le test, mais il semble que j'avais raison
pour les écritures pendant le premier SELECT et l'absence d'écritures
pendant le second. Cependant, ma conclusion me paraît maintenant
suspecte. Je vais continuer à me pencher dessus car j'avoue que je ne
comprends pas du tout ce qu'il se passe (et ça m'ennuie beaucoup :) ).

> Remarque: dans ma description détaillée j'ai utilisé
> entre les requêtes les commandes:
> select * from pg_statio_all_tables
> where relname = 'test_update';
> décrite dans l'article sur PostgreSQL de Juin 2008
> dans Gnu Linux Magazine France, afin des voir l'utilisation
> des caches postgresql et les blocks lus sur le disque dur.
>

De mon côté, j'ai conservé les stats du bgwriter, j'espère en tirer
quelque chose demain.

Bonne nuit.

--
Guillaume.
http://www.postgresqlfr.org
http://dalibo.com

Guillaume Lelarge a écrit :
> Valérie SCHNEIDER a écrit :
>> [...]
>> Question: je suis très surpris du temps de sélection
>> du cas (3) qui est très grand par rapport aux autres
>> select, et pour ne récupérer aucune ligne (car un
>> update précédent les a déplacées).
>>
>
> Pour être franc, moi aussi. Je viens de faire sept tests (et j'en
> prépare un huitième qui s'exécutera pendant que je dormirais), tous ont
> à peu de choses près la même durée d'exécution alors que le paramétrage
> est bien différent. Je n'ai pas encore tout analysé car j'évite
> d'utiliser ma machine pendant le test, mais il semble que j'avais raison
> pour les écritures pendant le premier SELECT et l'absence d'écritures
> pendant le second. Cependant, ma conclusion me paraît maintenant
> suspecte. Je vais continuer à me pencher dessus car j'avoue que je ne
> comprends pas du tout ce qu'il se passe (et ça m'ennuie beaucoup :) ).
>

Je viens de faire un petit tableau sur les neuf tests que j'ai
finalement fait (les nombres sont des secondes) :

UPDATE ANALYZE CHECKPOINT SELECT SELECT
Test 1 992 292 0,02
Test 2 945 27,31 13,7 275,52 0,02
Test 3 942 33 22 724 2,14
Test 4 946 31 29 709 2,5
Test 5 924 47 21 644 0,3
Test 6 942 33 9,8 699 1,3
Test 7 953 33,8 9,99 683 1
Test 8 810 26 99 23 8
Test 9 869 32 9,7 375 45

Il est tout à fait étonnant que je multiplie par 3 le temps pour le
premier SELECT entre les tests 2 et 3 (la seule différence entre les
deux est la config où j'ai passé les checkpoint_segments de 3 à 30).

On remarque que le temps d'exécution de l'UPDATE ne varie presque pas,
sauf sur les tests 8 et 9 (particularité de ces tests, un
effective_cache_size passé de 128 Mo, valeur par défaut, à 1 Go)

Le test intéressant est le 8.

Différence de config entre test 7 et test 8 :
* passage de shared_buffers de 50 Mo à 1 Go
* passage de effective_cache_size de 128 Mo à 1 Go

Différence de config entre test 8 et test 9 :
* passage de shared_buffers de 1 Go à 50 Mo
* passage de effective_cache_size de 1 Go à 1,3 Go

Différence entre votre config et la mienne :
* passage de shared_buffers de 32 Mo à 1 Go
* passage de wal_buffers de 64 Ko à 1 Mo
* passage de checkpoint_segments de 3 à 30
* passage de checkpoint_timeout de 5min à 15 min
* passage de effective_cache de 128 Mo à 1 Go

(j'ai supprimé les différences inintéressantes du côté des perfs)

Je voulais rejouer le test 8 mais je viens de m'apercevoir, en
redémarrant, j'ai perdu la base :-/

Je dois la reconstruire, ça va prendre un peu de temps. À faire :
* de nouveau le test 8
* un test en modifiant la quantité de stats sur la table.

--
Guillaume.
http://www.postgresqlfr.org
http://dalibo.com

Guillaume Lelarge a écrit :
> [...]
> UPDATE ANALYZE CHECKPOINT SELECT SELECT
> Test 1 992 292 0,02
> Test 2 945 27,31 13,7 275,52 0,02
> Test 3 942 33 22 724 2,14
> Test 4 946 31 29 709 2,5
> Test 5 924 47 21 644 0,3
> Test 6 942 33 9,8 699 1,3
> Test 7 953 33,8 9,99 683 1
> Test 8 810 26 99 23 8
> Test 9 869 32 9,7 375 45
>

Désolé, j'aurais dû mettre des espaces et non pas des tabulations :

UPDATE ANALYZE CHECKPOINT SELECT SELECT
Test 1 992 292 0,02
Test 2 945 27,31 13,7 275,52 0,02
Test 3 942 33 22 724 2,14
Test 4 946 31 29 709 2,5
Test 5 924 47 21 644 0,3
Test 6 942 33 9,8 699 1,3
Test 7 953 33,8 9,99 683 1
Test 8 810 26 99 23 8
Test 9 869 32 9,7 375 45

--
Guillaume.
http://www.postgresqlfr.org
http://dalibo.com

Guillaume Lelarge wrote:
> Je viens de faire un petit tableau sur les neuf tests que j'ai
> finalement fait (les nombres sont des secondes) :
>
> UPDATE ANALYZE CHECKPOINT SELECT SELECT
> Test 1 992 292 0,02
> Test 2 945 27,31 13,7 275,52 0,02
> Test 3 942 33 22 724 2,14
> Test 4 946 31 29 709 2,5
> Test 5 924 47 21 644 0,3
> Test 6 942 33 9,8 699 1,3
> Test 7 953 33,8 9,99 683 1
> Test 8 810 26 99 23 8
> Test 9 869 32 9,7 375 45
>

> Il est tout à fait étonnant que je multiplie par 3 le temps pour le
> premier SELECT entre les tests 2 et 3 (la seule différence entre les
> deux est la config où j'ai passé les checkpoint_segments de 3 à 30).
>
> On remarque que le temps d'exécution de l'UPDATE ne varie presque
pas,
> sauf sur les tests 8 et 9 (particularité de ces tests, un
> effective_cache_size passé de 128 Mo, valeur par défaut, à 1 Go)
>
> Le test intéressant est le 8.
>
> Différence de config entre test 7 et test 8 :
> * passage de shared_buffers de 50 Mo à 1 Go
> * passage de effective_cache_size de 128 Mo à 1 Go
>
> Différence de config entre test 8 et test 9 :
> * passage de shared_buffers de 1 Go à 50 Mo
> * passage de effective_cache_size de 1 Go à 1,3 Go
>
>
> Différence entre votre config et la mienne :
> * passage de shared_buffers de 32 Mo à 1 Go
> * passage de wal_buffers de 64 Ko à 1 Mo
> * passage de checkpoint_segments de 3 à 30
> * passage de checkpoint_timeout de 5min à 15 min
> * passage de effective_cache de 128 Mo à 1 Go

Les gros paramètres ayant étés modifiés étant shared_buffers et
effective_cache_size, avec de telles valeurs il faut une
machine ayant au moins 3gigas de mémoire.

Je viens donc ce matin de faire deux tests sur un serveur
avec une base Postgresql , et les paramètres:

--- Parametres Postgresql:
--- shared_buffers = 1024MB
--- checkpoint_segments = 30
--- wal_buffers = 1024kB
--- autovacuum = off
--- effective_cache_size = 1024MB
---
--- Parametres Systeme Linux:
--- memoire: 4GB
---
---
--- Remarque: le file-systeme de la base de donnees est duplique par
--- drdb de linux-ha sur une seconde machine via un
--- lien 1giga prive.

Et j'obtiens en secondes:

UPDATE ANALYZE CHECKPOINT SELECT
test1: 1086 191 119 111
test2: 1310 223 136 701

Pour le test1, j'avais arrêté toute autre activite a la base
Postgresql.
Pour le test2, j'ai rétabli l'alimentation d'autres tables.

En surveillant l'activite du processus 'postgres: writer process',
et en utilisant une commande 'iostat -k 60 60' on voit qu'il y a
beaucoup d'activité d'écriture disque durant le select, et celui-ci
ne termine que vers la fin d'activité du bgwriter.

==================================================================

Remarque: j'ai fais le test suivant sur le PC
bureautique à coté , en pensant amméliorer les temps de selects
grace à une attente de 10 minutes avant le select:

--- Parametres Postgresql:
--- shared_buffers = 128MB
--- checkpoint_segments = 3
--- wal_buffers = 64kB
--- autovacuum = on
--- effective_cache_size = 128MB
---
--- Parametres Systeme Linux:
--- memoire: 1,8 gigas

1) UPDATE de 51872 lignes en 512 secondes
2) analyse verbose en 22 secondes
3) CHECKPOINT en 7 secondes
4) \!iostat -k 60 10
5) select 0 lignes, en 431 secondes

sur la machine, je n'ai pas d'autre activités en dehors de
mon test. On voit avec la commande 'iostat' que le processus
bgwriter de Postgresql ne travaille pas, et recommence son
travail lors du select.

J'aurais pensé, qu'il profita du temps libre (durant iostat)
pour mettre à jour les fichiers disque de la base.

Merci, Valérie.

>
--

********************************************************************
* Les points de vue exprimes sont strictement personnels et *
* n'engagent pas la responsabilite de METEO-FRANCE. *
********************************************************************
* Valerie SCHNEIDER Tel : +33 (0)5 61 07 81 91 *
* METEO-FRANCE / DSI/DEV Fax : +33 (0)5 61 07 81 09 *
* 42, avenue G. Coriolis Email : Valerie(dot)Schneider(at)meteo(dot)fr *
* 31057 TOULOUSE Cedex 1 - FRANCE http://www.meteo.fr *
********************************************************************

Bonjour,

> [...]
> Je viens donc ce matin de faire deux tests sur un serveur
> avec une base Postgresql , et les paramètres:
>
> --- Parametres Postgresql:
> --- shared_buffers = 1024MB
> --- checkpoint_segments = 30
> --- wal_buffers = 1024kB
> --- autovacuum = off
> --- effective_cache_size = 1024MB
> ---
> --- Parametres Systeme Linux:
> --- memoire: 4GB
> ---
> ---
> --- Remarque: le file-systeme de la base de donnees est duplique par
> --- drdb de linux-ha sur une seconde machine via un
> --- lien 1giga prive.
>
> Et j'obtiens en secondes:
>
> UPDATE ANALYZE CHECKPOINT SELECT
> test1: 1086 191 119 111
> test2: 1310 223 136 701
>
>
> Pour le test1, j'avais arrêté toute autre activite a la base
> Postgresql.
> Pour le test2, j'ai rétabli l'alimentation d'autres tables.
>
> En surveillant l'activite du processus 'postgres: writer process',
> et en utilisant une commande 'iostat -k 60 60' on voit qu'il y a
> beaucoup d'activité d'écriture disque durant le select, et celui-ci
> ne termine que vers la fin d'activité du bgwriter.
>

Mon hypothèse de départ était que le processus postgres attaché au
client faisait des écritures disques pendant le SELECT. Maintenant, que
ce soit ce processus ou le processus bgwriter, peu importe. Ce qui
m'étonne, c'est que je croyais que l'instruction CHECKPOINT (exécutée
explicitement) allait parcourir tout le cache pour tout écrire.
Apparemment, ce n'est pas le cas. Ceci dit, ça me donne une idée de tests.

> ==================================================================
>
> Remarque: j'ai fais le test suivant sur le PC
> bureautique à coté , en pensant amméliorer les temps de selects
> grace à une attente de 10 minutes avant le select:
>
> --- Parametres Postgresql:
> --- shared_buffers = 128MB
> --- checkpoint_segments = 3
> --- wal_buffers = 64kB
> --- autovacuum = on
> --- effective_cache_size = 128MB
> ---
> --- Parametres Systeme Linux:
> --- memoire: 1,8 gigas
>
> 1) UPDATE de 51872 lignes en 512 secondes
> 2) analyse verbose en 22 secondes
> 3) CHECKPOINT en 7 secondes
> 4) \!iostat -k 60 10
> 5) select 0 lignes, en 431 secondes
>
> sur la machine, je n'ai pas d'autre activités en dehors de
> mon test. On voit avec la commande 'iostat' que le processus
> bgwriter de Postgresql ne travaille pas, et recommence son
> travail lors du select.
>
> J'aurais pensé, qu'il profita du temps libre (durant iostat)
> pour mettre à jour les fichiers disque de la base.
>

bgwriter est un espèce de démon. Il se réveille dans certains cas :
* envoi d'un CHECKPOINT à partir d'un autre processus (arrêt du
serveur, création d'une base de données, commande CHECKPOINT)
* checkpoint_segments journaux de transactions créés sans un seul
CHECKPOINT
* dépassement du délai checkpoint_timeout sans CHECKPOINT.

De plus, bgwriter écrit au plus bgwriter_lru_maxpages tampons du cache
disque.

Bref, ça dépend principalement de votre paramètre checkpoint_timeout,
mais aussi de bgwriter_lru_maxpages.

PS : j'ai toujours des tests en cours.

--
Guillaume.
http://www.postgresqlfr.org
http://dalibo.com