Vous n'êtes pas identifié(e).
- Contributions : Récentes | Sans réponse
#26 22/04/2009 15:51:53
- gleu
- Administrateur
Re : Des requêtes lentes, plus de 10 minutes par requête!
Je ne sais pas si tu as vu les deux autres tests, celui à 200 et celui à 300 secondes. Autant je peux comprendre le premier, voire le deuxième test, autant les deux derniers semblent incohérents.
Guillaume.
Hors ligne
#27 22/04/2009 15:54:36
- gleu
- Administrateur
Re : Des requêtes lentes, plus de 10 minutes par requête!
Désolé pour les multiples messages. Je suis étonné que la désactivation du bitmapscan n'ait rien donné. Il serait possible d'avoir le EXPLAIN ANALYZE suite à un « SET enable_bitmapscan TO off ».
Guillaume.
Hors ligne
#28 22/04/2009 16:03:26
- solicel
- Membre
Re : Des requêtes lentes, plus de 10 minutes par requête!
En ce qui me concerne, cela me semble très 'raisonnable' comme temps de réponse : 55 secondes pour retourner 50 000 enregistrements, cela fait 1ms par enregistrement. Si ils sont réellement éparpillés sur le disque, on ne pourra pas faire beaucoup mieux. Enfin si, avec la 8.4, plein de disques le effective_io_concurrency mais on change un peu de budget là.
A part ça on voit aussi qu'il n'est plus dans les choux au niveau statistiques (un rapport 2 ça n'est pas si mal). Ça lui permet au moins de faire du bitmap_index_scan, ce qui me semble le plan raisonnable pour ce genre de requête.
On peut passer à l'étape d'après: voir ce que ça donne avec un plus gros cache (après le test demandé par gleu, qui peut permettre de gagner un peu aussi).
J'ai décidé de changer la machine de serveur avec une plus performante: 8 GO de ram, et un core2 duo.
Ceci veut dire que vais réinstaller le OS, et refaire tout a zéro, heureusement que j'ai une copie sauvegarde de chaque table. Ce qui serait intéressant ici est d'essayer d'optimiser tout:
- Quel OS choisir? Quel système de fichier? J'ai entendu que le Ubunutu 9.04 a le système de fichier ext4, on dit qu'il est 2 fois plus rapide que le ext3. Ou peut être garder simplement le vista?
- Quelle version de postgres? Vous avez parlé de 8.04, je n'ai pas de grandes informations sur ça.
- Ajouter un autre disque dur aidera plus? En fait cette machine dispose déjà d'un disque a 250 GO, peut être diviser chaque table sur les deux disque divisera le temps de recherche par 2?
Hors ligne
#29 22/04/2009 16:05:59
- solicel
- Membre
Re : Des requêtes lentes, plus de 10 minutes par requête!
Question complémentaire, il y a combien de lignes dans la table indexée ?
1 313 818 354 lignes.
Hors ligne
#30 22/04/2009 16:17:34
- gleu
- Administrateur
Re : Des requêtes lentes, plus de 10 minutes par requête!
Oubliez ma question sur la requête. Par contre, recréez l'index avec le text_pattern_ops, et refaites le EXPLAIN ANALYZE.
Concernant un nouveau serveur, ce sera certainement plus rapide grâce à la mémoire. Maintenant, pas sûr que cela résolve votre problème. En tout cas, oubliez vista si vous voulez des performances. Peu importe le linux que vous installez. Quant à PostgreSQL, utilisez la dernière version stable (8.3.7 aujourd'hui). Avoir plusieurs disques peut servir.
PS : il aurait été sympa de dire que vous aviez déjà fait des recherches et qu'il y avait déjà tout un tas d'infos sur http://www.developpez.net/forums/d70537 … ex-malgre/. Ça aurait évité qu'on ait à les chercher.
Guillaume.
Hors ligne
#31 22/04/2009 16:19:11
- solicel
- Membre
Re : Des requêtes lentes, plus de 10 minutes par requête!
Désolé pour les multiples messages. Je suis étonné que la désactivation du bitmapscan n'ait rien donné. Il serait possible d'avoir le EXPLAIN ANALYZE suite à un « SET enable_bitmapscan TO off ».
Vous avez raison, les premiers résultats sont avant la désactivation des bitmapscan, voici les nouveaux resultats:
explain analyze select * from fourgrams where lower(part2)='cheese' order by freq desc;
"Sort (cost=97967.05..98027.04 rows=23996 width=28) (actual time=53971.568..54016.015 rows=37135 loops=1)"
" Sort Key: freq"
" Sort Method: external merge Disk: 1568kB"
" -> Index Scan using part2_idx on fourgrams (cost=0.00..95685.78 rows=23996 width=28) (actual time=216.131..53750.682 rows=37135 loops=1)"
" Index Cond: (lower((part2)::text) = 'cheese'::text)"
"Total runtime: 54032.019 ms"
------------------------------------------------------------------------------------
explain analyze select * from fourgrams where lower(part3)='cheese' order by freq desc;
"Sort (cost=93373.59..93431.34 rows=23100 width=28) (actual time=158072.587..158119.490 rows=39521 loops=1)"
" Sort Key: freq"
" Sort Method: external merge Disk: 1680kB"
" -> Index Scan using part3_idx on fourgrams (cost=0.00..91184.85 rows=23100 width=28) (actual time=138.592..157876.670 rows=39521 loops=1)"
" Index Cond: (lower((part3)::text) = 'cheese'::text)"
"Total runtime: 158136.191 ms"
------------------------------------------------------------------------------------
explain analyze select * from fourgrams where lower(part4)='cheese' order by freq desc;
"Sort (cost=99253.41..99313.93 rows=24208 width=28) (actual time=194107.895..194171.071 rows=36617 loops=1)"
" Sort Key: freq"
" Sort Method: external merge Disk: 1576kB"
" -> Index Scan using part4_idx on fourgrams (cost=0.00..96951.68 rows=24208 width=28) (actual time=194.410..193886.645 rows=36617 loops=1)"
" Index Cond: (lower((part4)::text) = 'cheese'::text)"
"Total runtime: 194186.804 ms"Hors ligne
#32 22/04/2009 16:23:39
- solicel
- Membre
Re : Des requêtes lentes, plus de 10 minutes par requête!
Oubliez ma question sur la requête. Par contre, recréez l'index avec le text_pattern_ops, et refaites le EXPLAIN ANALYZE.
Concernant un nouveau serveur, ce sera certainement plus rapide grâce à la mémoire. Maintenant, pas sûr que cela résolve votre problème. En tout cas, oubliez vista si vous voulez des performances. Peu importe le linux que vous installez. Quant à PostgreSQL, utilisez la dernière version stable (8.3.7 aujourd'hui). Avoir plusieurs disques peut servir.
PS : il aurait été sympa de dire que vous aviez déjà fait des recherches et qu'il y avait déjà tout un tas d'infos sur http://www.developpez.net/forums/d70537 … ex-malgre/. Ça aurait évité qu'on ait à les chercher.
Je suis vraiment désolé de ne pas mentionner cela, c'est grâce a eux que j'ai eu l'idée de poster dans ce forum. Mais simplement j'ai cru que faire un résumé des tentatives que j'ai fait sera suffisant.
Mais vous avez raison.
Hors ligne
#33 22/04/2009 18:45:18
- Marc Cousin
- Membre
Re : Des requêtes lentes, plus de 10 minutes par requête!
Effectivement, les performances pour les deux requêtes en exemple sont vraiment basses. Ça laisse vraiment supposer un problème de performance disque. Parce que même sans aucun cache, ça devrait être plus rapide. En attendant que la nouvelle machine (qui est aussi un pc de bureau si je ne m'abuse à la description du matériel) ne soit prête, je serais intéressé par les executor_stats associées aux requêtes du message #31 (histoire de savoir combien de blocs postgresql va chercher sur le disque).
Marc.
Hors ligne
#34 22/04/2009 19:49:17
- solicel
- Membre
Re : Des requêtes lentes, plus de 10 minutes par requête!
Effectivement, les performances pour les deux requêtes en exemple sont vraiment basses. Ça laisse vraiment supposer un problème de performance disque. Parce que même sans aucun cache, ça devrait être plus rapide. En attendant que la nouvelle machine (qui est aussi un pc de bureau si je ne m'abuse à la description du matériel) ne soit prête, je serais intéressé par les executor_stats associées aux requêtes du message #31 (histoire de savoir combien de blocs postgresql va chercher sur le disque).
Voulez-vous dire log_executor_stats ?
Si c'est le cas un show log_executor_stats me donne le résultat off. Sinon quelle commande pour avoir ces statistiques?
Par la même occasion, les résultat du #31 sont après l'augmentation du shared buffer a 330 MO, le 1/3 de mon ram actuel.
Hors ligne
#35 22/04/2009 20:37:20
- Marc Cousin
- Membre
Re : Des requêtes lentes, plus de 10 minutes par requête!
pour obtenir les infos de l'executor (j'adore ce nom, ça fait méchant 
) dans une session psql :
dans psql:
* set client_min_messages to debug;
* set log_executor_stats to on;
* exécuter la requête (ou l'explain analyze, si on n'a pas trop envie de recevoir 50 000 enregistrements dans la figure).
Cela devrait afficher des traces de debug avec (entre autres) la quantité d'IO effectuée.
Marc.
Hors ligne
#36 23/04/2009 22:28:11
- solicel
- Membre
Re : Des requêtes lentes, plus de 10 minutes par requête!
Bonsoir c'est moi de nouveau,
Je suis désolé de ne rien avoir posté ce jour, mais la machine n'était pas libre.
Bref, je ne sais plus d'où commencer:
La création du nouveau indexe n'a rien (aprioris) ajouté, je m'en doute s'il a été crée correctement, je le refais ce soir et je vous poste les résultats demain.
Pour l'instant, voici ce que j'ai eu comme resultat pour cette colonne, qui est dans une seconde instance de la table, qui ne contient que ce nouveau index:
explain analyze select * from fourgrams where lower(part2)='milk' order by freq desc
--------
"Sort (cost=129241085.53..129241145.97 rows=24175 width=28) (actual time=1620489.771..1620561.163 rows=51203 loops=1)"
" Sort Key: freq"
" Sort Method: external merge Disk: 2064kB"
" -> Seq Scan on fourgrams (cost=100000000.00..129238786.44 rows=24175 width=28) (actual time=3855.122..1620049.389 rows=51203 loops=1)"
" Filter: (lower((part2)::text) = 'milk'::text)"
"Total runtime: 1620630.742 ms"
--------
LOG: EXECUTOR STATISTICS
DETAIL: ! system usage stats:
! 1620.631116 elapsed 1368.085500 user 121.723607 system sec
! [27074.340040 user 1046.909427 sys total]
! 152622608/4176 [805090120/211145544] filesystem blocks in/out
! 0/75 [27/48092] page faults/reclaims, 0 [0] swaps
! 0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
! 28256/351112 [1154487/6565795] voluntary/involuntary context switches
! buffer usage stats:
! Shared blocks: 9529349 read, 0 written, buffer hit rate = 0.00%
! Local blocks: 0 read, 0 written, buffer hit rate = 0.00%
! Direct blocks: 0 read, 0 written
Total query runtime: 1620691 ms.
6 rows retrieved.Cela ne me parait pas raisonnable, meme au niveau du seq_scan que j'ai désactivé et vérifié deux fois avant le lancement de la requete.
Pour ce quei concerne l'instance initiale de la table, voici quelques resultats:
explain analyze select * from fourgrams where lower(part1)='cheese' order by freq desc
-----------------------------
"Sort (cost=85715.66..85788.58 rows=29166 width=28) (actual time=395.897..432.396 rows=30220 loops=1)"
" Sort Key: freq"
" Sort Method: external merge Disk: 1272kB"
" -> Index Scan using part1_idx on fourgrams (cost=0.00..82901.71 rows=29166 width=28) (actual time=159.217..320.277 rows=30220 loops=1)"
" Index Cond: (lower((part1)::text) = 'cheese'::text)"
"Total runtime: 445.361 ms"
----------------------
LOG: EXECUTOR STATISTICS
DETAIL: ! system usage stats:
! 0.546619 elapsed 0.124008 user 0.036002 system sec
! [315.939745 user 91.889742 sys total]
! 6136/2544 [154765944/27320] filesystem blocks in/out
! 0/164 [3/9227] page faults/reclaims, 0 [0] swaps
! 0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
! 34/31 [695160/157752] voluntary/involuntary context switches
! buffer usage stats:
! Shared blocks: 315 read, 0 written, buffer hit rate = 1.87%
! Local blocks: 0 read, 0 written, buffer hit rate = 0.00%
! Direct blocks: 0 read, 0 written
Total query runtime: 563 ms.
6 rows retrieved.
------------------------------------------------------
explain analyze select * from fourgrams where lower(part2)='cheese' order by freq desc
----------
"Sort (cost=97967.05..98027.04 rows=23996 width=28) (actual time=54295.803..54334.025 rows=37135 loops=1)"
" Sort Key: freq"
" Sort Method: external merge Disk: 1568kB"
" -> Index Scan using part2_idx on fourgrams (cost=0.00..95685.78 rows=23996 width=28) (actual time=226.634..54170.885 rows=37135 loops=1)"
" Index Cond: (lower((part2)::text) = 'cheese'::text)"
"Total runtime: 54356.035 ms"
----------
LOG: EXECUTOR STATISTICS
DETAIL: ! system usage stats:
! 54.356459 elapsed 0.224014 user 0.444028 system sec
! [315.815737 user 91.853740 sys total]
! 92960/3168 [154759808/24768] filesystem blocks in/out
! 0/164 [3/9063] page faults/reclaims, 0 [0] swaps
! 0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
! 6333/12 [695122/157720] voluntary/involuntary context switches
! buffer usage stats:
! Shared blocks: 3919 read, 0 written, buffer hit rate = 0.00%
! Local blocks: 0 read, 0 written, buffer hit rate = 0.00%
! Direct blocks: 0 read, 0 written
Total query runtime: 54387 ms.
6 rows retrieved.
-------------------------------------------------------------------------------
explain analyze select * from fourgrams where lower(part3)='cheese' order by freq desc
----------
"Sort (cost=93373.59..93431.34 rows=23100 width=28) (actual time=137699.725..137748.542 rows=39521 loops=1)"
" Sort Key: freq"
" Sort Method: external merge Disk: 1680kB"
" -> Index Scan using part3_idx on fourgrams (cost=0.00..91184.85 rows=23100 width=28) (actual time=78.770..137514.032 rows=39521 loops=1)"
" Index Cond: (lower((part3)::text) = 'cheese'::text)"
"Total runtime: 137765.283 ms"
----------
LOG: EXECUTOR STATISTICS
DETAIL: ! system usage stats:
! 1691.255280 elapsed 1369.757605 user 124.775798 system sec
! [25706.250540 user 925.185820 sys total]
! 152638008/34464 [652467464/211141352] filesystem blocks in/out
! 0/81 [27/48016] page faults/reclaims, 0 [0] swaps
! 0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
! 28906/376734 [1126217/6214682] voluntary/involuntary context switches
! buffer usage stats:
! Shared blocks: 9527015 read, 0 written, buffer hit rate = 0.02%
! Local blocks: 0 read, 0 written, buffer hit rate = 0.00%
! Direct blocks: 0 read, 0 written
Total query runtime: 1691330 ms.
6 rows retrieved.A plus tard pour plus de resultats...
Dernière modification par solicel (24/04/2009 04:10:48)
Hors ligne
#37 23/04/2009 23:44:33
- gleu
- Administrateur
Re : Des requêtes lentes, plus de 10 minutes par requête!
Concernant le premier bloc de résultat, si part2 n'avait plus d'index, c'est assez logique. Il faut créer un index du même type que ce que j'ai marqué plus haut, mais pour chacune des colonnes.
Quant au deuxième bloc, il montre clairement qu'il y a beaucoup plus de lectures sur le disque, ce qui explique les lenteurs.
Guillaume.
Hors ligne
#38 24/04/2009 04:25:38
- solicel
- Membre
Re : Des requêtes lentes, plus de 10 minutes par requête!
Concernant le premier bloc de résultat, si part2 n'avait plus d'index, c'est assez logique. Il faut créer un index du même type que ce que j'ai marqué plus haut, mais pour chacune des colonnes.
Quant au deuxième bloc, il montre clairement qu'il y a beaucoup plus de lectures sur le disque, ce qui explique les lenteurs.
Je suis désolé pour cette erreur, j'ai permuté l'affichage de deux requêtes, maintenant le résultat est correct vous pouvez le reconsulter:
- Seule la requête sur la colonne part2 dans la table ou je n'ai que l'index que vous m'avez demandé de créer (avec le ops)
- les 3 requêtes sur les 3 colonnes une, deux et trois dans la tables là où il y a tous les anciens indexes
En tout cas je vais reconstruire les autres indexes pour la table comme vous l'avez indiqué.
Hors ligne
#39 24/04/2009 04:34:19
- solicel
- Membre
Re : Des requêtes lentes, plus de 10 minutes par requête!
J'ai une idée qui, bien qu'elle soit très naïve, elle peut résoudre le problème parfaitement:
puisque le secret de rapidité magique de la première colonne réside dans l'ordonnancement des lignes par rapport a celle-ci, je pense de créer autant de copies de la table que de colonnes qu'elle a, chacune de ces nouvelles copies est ordonné par rapport à une colonne, et ne contenant que l'indexe de cette colonne (dans notre cas 4 tables puisqu'on a 4 colonnes interrogables), cela devra fonctionner tous les indexes de manière similaire a celle de la première colonne.
Le seul problème pour moi ici est: comment ordonner une table relativement a une colonne déterminée?
Peut on ajouter une contrainte lors de la création du table, ou a partir d'une table existante?
Que pensez vous de cette idée?
Hors ligne
#40 24/04/2009 10:11:56
- Marc Cousin
- Membre
Re : Des requêtes lentes, plus de 10 minutes par requête!
L'idée est (assez) bonne, puisqu'elle permettrait effectivement de résoudre le problème, mais en quadruplant le nombre de tables. Ca pourrait se faire via des 'CLUSTER' à intervalle régulier sur les tables.
Pour revenir aux statistiques, les valeurs sont à peu près normales pour les parcours d'index (beaucoup de blocs lus quand même, et principalement en aléatoire vu le temps d'exécution). Par contre le hit ratio à 0, c'est très mauvais
=> A force j'ai un peu perdu le fil, mais je pense qu'on devrait vraiment commencer par augmenter le cache.
Marc.
Hors ligne
#41 24/04/2009 16:34:09
- solicel
- Membre
Re : Des requêtes lentes, plus de 10 minutes par requête!
Bonjour;
Merci pour vos réponses, revenons au résultats:
- initialement il y avait kernel.shmmax = 33 554 432, que j'ai multiplié par 10, pour avoir 333 MO
- j'ai mis cette valeur dans le /etc/sysctl.conf
- j'ai ajouté la ligne "deadline" dans le fichier /sys/block/sda/queue/sheduler,
et voici les resultats des requetes:
explain analyze select * from fourgrams where lower(part2)='cheese' order by freq desc
"Sort (cost=97958.94..98018.92 rows=23994 width=28) (actual time=55098.200..55142.929 rows=37135 loops=1)"
" Sort Key: freq"
" Sort Method: external merge Disk: 1568kB"
" -> Index Scan using part2_idx on fourgrams (cost=0.00..95677.83 rows=23994 width=28) (actual time=196.002..54971.364 rows=37135 loops=1)"
" Index Cond: (lower((part2)::text) = 'cheese'::text)"
"Total runtime: 55158.776 ms"
LOG: EXECUTOR STATISTICS
DETAIL: ! system usage stats:
! 55.229908 elapsed 0.208013 user 0.488030 system sec
! [23258.213547 user 731.029686 sys total]
! 92568/3160 [499206888/211090872] filesystem blocks in/out
! 0/244 [3/15086] page faults/reclaims, 0 [0] swaps
! 0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
! 6323/14 [1480440/5420876] voluntary/involuntary context switches
! buffer usage stats:
! Shared blocks: 3910 read, 0 written, buffer hit rate = 1.59%
! Local blocks: 0 read, 0 written, buffer hit rate = 0.00%
! Direct blocks: 0 read, 0 written
Total query runtime: 55257 ms.
6 rows retrieved.
--------------------------------------------------------------------------------------------
explain analyze select * from fourgrams where lower(part3)='cheese' order by freq desc
"Sort (cost=93369.58..93427.33 rows=23099 width=28) (actual time=159452.597..159497.776 rows=39521 loops=1)"
" Sort Key: freq"
" Sort Method: external merge Disk: 1680kB"
" -> Index Scan using part3_idx on fourgrams (cost=0.00..91180.91 rows=23099 width=28) (actual time=125.511..159257.109 rows=39521 loops=1)"
" Index Cond: (lower((part3)::text) = 'cheese'::text)"
"Total runtime: 159526.801 ms"
LOG: EXECUTOR STATISTICS
DETAIL: ! system usage stats:
! 159.527275 elapsed 0.424027 user 1.504094 system sec
! [23258.637574 user 732.533780 sys total]
! 338056/3384 [499544944/211094264] filesystem blocks in/out
! 0/164 [3/15250] page faults/reclaims, 0 [0] swaps
! 0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
! 21800/19 [1502244/5420898] voluntary/involuntary context switches
! buffer usage stats:
! Shared blocks: 16652 read, 0 written, buffer hit rate = 0.02%
! Local blocks: 0 read, 0 written, buffer hit rate = 0.00%
! Direct blocks: 0 read, 0 written
Total query runtime: 159578 ms.
6 rows retrieved.
------------------------------------------------------------------------------------------------------
explain analyze select * from fourgrams where lower(part4)='cheese' order by freq desc
"Sort (cost=99245.27..99305.78 rows=24206 width=28) (actual time=211044.823..211099.183 rows=36617 loops=1)"
" Sort Key: freq"
" Sort Method: external merge Disk: 1576kB"
" -> Index Scan using part4_idx on fourgrams (cost=0.00..96943.70 rows=24206 width=28) (actual time=178.206..210811.916 rows=36617 loops=1)"
" Index Cond: (lower((part4)::text) = 'cheese'::text)"
"Total runtime: 211116.443 ms"
LOG: EXECUTOR STATISTICS
DETAIL: ! system usage stats:
! 211.153733 elapsed 0.520032 user 2.316145 system sec
! [23259.157606 user 734.853925 sys total]
! 628608/3184 [500173600/211097464] filesystem blocks in/out
! 0/164 [3/15414] page faults/reclaims, 0 [0] swaps
! 0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
! 32611/9 [1534864/5420908] voluntary/involuntary context switches
! buffer usage stats:
! Shared blocks: 29282 read, 0 written, buffer hit rate = 0.00%
! Local blocks: 0 read, 0 written, buffer hit rate = 0.00%
! Direct blocks: 0 read, 0 written
Total query runtime: 211211 ms.
6 rows retrieved.Hors ligne
#42 24/04/2009 17:33:25
- Marc Cousin
- Membre
Re : Des requêtes lentes, plus de 10 minutes par requête!
+ l'ajout de la ligne deadline s'est fait comment ? (c'est un peu particulier) => que donne un cat sur ce fichier ?
+ la modification du sysctl n'a pas changé les paramètres de cache de postgresql, simplement reparamétré linux pour qu'il les accepte. Il faut augmenter le paramètre shared_buffers dans postgresql.conf pour cela
Marc.
Hors ligne
#43 24/04/2009 17:47:45
- solicel
- Membre
Re : Des requêtes lentes, plus de 10 minutes par requête!
+ l'ajout de la ligne deadline s'est fait comment ? (c'est un peu particulier) => que donne un cat sur ce fichier ?
+ la modification du sysctl n'a pas changé les paramètres de cache de postgresql, simplement reparamétré linux pour qu'il les accepte. Il faut augmenter le paramètre shared_buffers dans postgresql.conf pour cela
- pour la dealine j'ai utilisé sudo nano /sys/block/sda/queue/scheduler, maintenant je viens de vérifier que ce fichier contient exactement " noop anticipatory deadline [cfq]"
- la valeur de shared_buffers est de : shared_buffers = 330MB j'ai fait cela et redémarre postgres depuis 2 jours.
Hors ligne
#44 24/04/2009 19:35:47
- Marc Cousin
- Membre
Re : Des requêtes lentes, plus de 10 minutes par requête!
+ faut pas le faire avec nano, mais avec un echo (ce n'est pas un vrai fichier)
=> echo 'deadline' > /sys/block/sda/queue/scheduler
+ pour le shared buffers ok, donc on ne peut vraiment pas utiliser de cache avec cette requête ...
Marc.
Hors ligne
#45 24/04/2009 19:43:24
- Marc Cousin
- Membre
Re : Des requêtes lentes, plus de 10 minutes par requête!
Si on regarde, on est à environ 2 blocs par ms, ce qui est vraiment le signe de lecture de données aléatoires
Pour aller vraiment au bout de cette question, ça serait bien d'avoir des informations d'iostat pendant la requête :
> faire iostat -x -m 1 sda, le laisser tourner
> faire la requête
>arrêter l'iostat (avec Contrl+C)
L'iostat qu'on a pour le moment n'est pas bon, c'est la valeur moyenne depuis le démarrage du système
Marc.
Hors ligne
#46 26/04/2009 21:42:58
- solicel
- Membre
Re : Des requêtes lentes, plus de 10 minutes par requête!
Bonjour,
d'abord pour le echo 'deadline' ne marche pas, voila ce qui ce passe:
sudo echo 'deadline' > /sys/block/sda/queue/scheduler
bash: /sys/block/sda/queue/scheduler: Permission deniedvous voyez bien que j'utilise le sudo, et quand je tape le sudo nano voila le resultat:
sudo nano /sys/block/sda/queue/scheduler
GNU nano 2.0.7 File: /sys/block/sda/queue/scheduler
noop anticipatory deadline [cfq]Donc il me semble que la ligne existe déjà dans ce fichier.
Hors ligne
#47 26/04/2009 21:46:53
- solicel
- Membre
Re : Des requêtes lentes, plus de 10 minutes par requête!
Et pour le iostat, voici les resultats:
Requete:
explain analyze select * from fourgrams where lower(part2)='ham' order by freq desc
----
"Sort (cost=97958.94..98018.92 rows=23994 width=28) (actual time=28984.027..29001.872 rows=13579 loops=1)"
" Sort Key: freq"
" Sort Method: external merge Disk: 520kB"
" -> Index Scan using part2_idx on fourgrams (cost=0.00..95677.83 rows=23994 width=28) (actual time=134.097..28942.334 rows=13579 loops=1)"
" Index Cond: (lower((part2)::text) = 'ham'::text)"
"Total runtime: 29007.830 ms"
----
LOG: EXECUTOR STATISTICS
DETAIL: ! system usage stats:
! 29.008271 elapsed 0.084005 user 0.264016 system sec
! [23259.505628 user 735.897990 sys total]
! 46984/1040 [500349384/211102704] filesystem blocks in/out
! 1/163 [4/15743] page faults/reclaims, 0 [0] swaps
! 0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
! 3173/5 [1547136/5420943] voluntary/involuntary context switches
! buffer usage stats:
! Shared blocks: 2238 read, 0 written, buffer hit rate = 0.09%
! Local blocks: 0 read, 0 written, buffer hit rate = 0.00%
! Direct blocks: 0 read, 0 written
Total query runtime: 29031 ms.
6 rows retrieved.Hors ligne
#48 26/04/2009 21:48:56
- solicel
- Membre
Re : Des requêtes lentes, plus de 10 minutes par requête!
et l'historique de iostat:
Linux 2.6.24-23-generic (admin2-desktop) 26/04/09
avg-cpu: %user %nice %system %iowait %steal %idle
12.50 0.01 0.83 4.08 0.00 82.58
Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await svctm %util
sda 4.64 98.39 15.82 3.94 1.24 0.40 170.22 1.44 72.87 3.89 7.68
avg-cpu: %user %nice %system %iowait %steal %idle
1.01 0.00 0.00 0.00 0.00 98.99
Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await svctm %util
sda 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
avg-cpu: %user %nice %system %iowait %steal %idle
4.00 0.00 0.00 0.00 0.00 96.00
Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await svctm %util
sda 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
avg-cpu: %user %nice %system %iowait %steal %idle
7.92 0.00 0.99 0.00 0.00 91.09
Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await svctm %util
sda 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
avg-cpu: %user %nice %system %iowait %steal %idle
3.00 0.00 1.00 0.00 0.00 96.00
Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await svctm %util
sda 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
avg-cpu: %user %nice %system %iowait %steal %idle
4.00 0.00 0.00 0.00 0.00 96.00
Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await svctm %util
sda 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
avg-cpu: %user %nice %system %iowait %steal %idle
12.00 0.00 2.00 76.00 0.00 10.00
Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await svctm %util
sda 1.00 0.00 129.00 0.00 1.35 0.00 21.40 0.84 6.45 6.51 84.00
avg-cpu: %user %nice %system %iowait %steal %idle
5.05 0.00 2.02 92.93 0.00 0.00
Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await svctm %util
sda 0.00 0.00 119.00 0.00 0.76 0.00 13.11 1.00 8.44 8.40 100.00
avg-cpu: %user %nice %system %iowait %steal %idle
7.00 0.00 0.00 93.00 0.00 0.00
Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await svctm %util
sda 0.00 0.00 122.00 0.00 1.17 0.00 19.67 1.02 8.26 8.10 98.80
avg-cpu: %user %nice %system %iowait %steal %idle
5.00 0.00 2.00 93.00 0.00 0.00
Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await svctm %util
sda 0.00 20.00 102.00 3.00 0.70 0.09 15.31 1.22 11.73 9.41 98.80
avg-cpu: %user %nice %system %iowait %steal %idle
4.95 0.00 2.97 92.08 0.00 0.00
Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await svctm %util
sda 0.00 0.00 104.00 0.00 0.73 0.00 14.31 0.99 9.46 9.50 98.80
avg-cpu: %user %nice %system %iowait %steal %idle
5.05 0.00 1.01 93.94 0.00 0.00
Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await svctm %util
sda 0.00 0.00 115.00 0.00 0.80 0.00 14.19 1.00 8.59 8.70 100.00
avg-cpu: %user %nice %system %iowait %steal %idle
5.00 0.00 3.00 92.00 0.00 0.00
Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await svctm %util
sda 0.00 0.00 106.00 0.00 0.76 0.00 14.72 1.00 9.47 9.40 99.60
avg-cpu: %user %nice %system %iowait %steal %idle
6.00 0.00 0.00 94.00 0.00 0.00
Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await svctm %util
sda 0.00 0.00 124.00 0.00 0.85 0.00 14.00 1.00 8.10 8.06 100.00
avg-cpu: %user %nice %system %iowait %steal %idle
5.94 0.00 1.98 92.08 0.00 0.00
Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await svctm %util
sda 0.00 0.00 112.00 8.00 0.81 0.03 14.33 1.24 10.30 8.20 98.40
avg-cpu: %user %nice %system %iowait %steal %idle
6.06 0.00 2.02 91.92 0.00 0.00
Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await svctm %util
sda 1.00 19.00 103.00 5.00 1.02 0.09 21.04 1.33 12.37 9.07 98.00
avg-cpu: %user %nice %system %iowait %steal %idle
6.00 0.00 2.00 92.00 0.00 0.00
Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await svctm %util
sda 0.00 0.00 114.00 0.00 0.87 0.00 15.58 1.03 8.98 8.67 98.80
avg-cpu: %user %nice %system %iowait %steal %idle
6.00 0.00 0.00 94.00 0.00 0.00
Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await svctm %util
sda 0.00 0.00 126.00 0.00 0.85 0.00 13.78 1.00 8.00 7.94 100.00
avg-cpu: %user %nice %system %iowait %steal %idle
6.00 0.00 2.00 92.00 0.00 0.00
Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await svctm %util
sda 0.00 0.00 111.00 0.00 0.72 0.00 13.33 0.99 8.90 8.90 98.80
avg-cpu: %user %nice %system %iowait %steal %idle
6.00 0.00 1.00 93.00 0.00 0.00
Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await svctm %util
sda 0.00 0.00 122.00 0.00 0.84 0.00 14.16 1.00 8.16 8.16 99.60
avg-cpu: %user %nice %system %iowait %steal %idle
5.00 0.00 1.00 94.00 0.00 0.00
Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await svctm %util
sda 0.00 0.00 129.00 0.00 0.89 0.00 14.20 1.00 7.69 7.75 100.00
avg-cpu: %user %nice %system %iowait %steal %idle
6.00 0.00 2.00 92.00 0.00 0.00
Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await svctm %util
sda 0.00 18.00 103.00 3.00 0.70 0.08 15.09 1.17 11.09 9.32 98.80
avg-cpu: %user %nice %system %iowait %steal %idle
5.05 0.00 1.01 93.94 0.00 0.00
Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await svctm %util
sda 0.00 0.00 110.00 0.00 0.71 0.00 13.16 1.00 9.05 9.09 100.00
avg-cpu: %user %nice %system %iowait %steal %idle
6.93 0.00 0.99 92.08 0.00 0.00
Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await svctm %util
sda 0.00 0.00 126.00 0.00 1.08 0.00 17.52 0.99 7.90 7.87 99.20
avg-cpu: %user %nice %system %iowait %steal %idle
5.00 0.00 3.00 92.00 0.00 0.00
Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await svctm %util
sda 0.00 0.00 120.00 0.00 0.85 0.00 14.47 0.98 8.20 8.20 98.40
avg-cpu: %user %nice %system %iowait %steal %idle
6.93 0.00 1.98 91.09 0.00 0.00
Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await svctm %util
sda 0.00 0.00 100.00 0.00 0.64 0.00 13.12 1.00 9.88 9.92 99.20
avg-cpu: %user %nice %system %iowait %steal %idle
6.00 0.00 2.00 92.00 0.00 0.00
Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await svctm %util
sda 0.00 0.00 107.00 0.00 0.70 0.00 13.31 1.00 9.35 9.31 99.60
avg-cpu: %user %nice %system %iowait %steal %idle
6.00 0.00 1.00 93.00 0.00 0.00
Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await svctm %util
sda 0.00 18.00 95.00 3.00 0.62 0.08 14.61 1.25 12.82 10.16 99.60
avg-cpu: %user %nice %system %iowait %steal %idle
5.05 0.00 1.01 93.94 0.00 0.00
Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await svctm %util
sda 0.00 0.00 101.00 0.00 0.68 0.00 13.70 0.99 9.74 9.78 98.80
avg-cpu: %user %nice %system %iowait %steal %idle
5.94 0.00 2.97 91.09 0.00 0.00
Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await svctm %util
sda 0.00 0.00 104.00 0.00 0.68 0.00 13.46 0.99 9.54 9.54 99.20
avg-cpu: %user %nice %system %iowait %steal %idle
6.06 0.00 0.00 93.94 0.00 0.00
Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await svctm %util
sda 0.00 0.00 99.00 0.00 0.65 0.00 13.41 0.99 10.02 9.98 98.80
avg-cpu: %user %nice %system %iowait %steal %idle
6.93 0.00 0.99 92.08 0.00 0.00
Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await svctm %util
sda 0.00 0.00 105.00 0.00 0.69 0.00 13.41 0.99 9.45 9.45 99.20
avg-cpu: %user %nice %system %iowait %steal %idle
5.00 0.00 1.00 94.00 0.00 0.00
Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await svctm %util
sda 0.00 57.00 99.00 8.00 0.65 0.19 16.00 1.21 10.69 9.31 99.60
avg-cpu: %user %nice %system %iowait %steal %idle
6.00 0.00 0.00 94.00 0.00 0.00
Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await svctm %util
sda 0.00 0.00 73.00 2.00 0.49 0.07 15.36 1.25 17.49 13.33 100.00
avg-cpu: %user %nice %system %iowait %steal %idle
6.00 0.00 2.00 92.00 0.00 0.00
Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await svctm %util
sda 0.00 0.00 96.00 0.00 0.62 0.00 13.17 0.98 10.25 10.21 98.00
avg-cpu: %user %nice %system %iowait %steal %idle
13.00 0.00 3.00 11.00 0.00 73.00
Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await svctm %util
sda 0.00 0.00 15.00 0.00 0.10 0.00 13.33 0.12 8.53 8.27 12.40
avg-cpu: %user %nice %system %iowait %steal %idle
2.00 0.00 0.00 0.00 0.00 98.00
Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await svctm %util
sda 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
avg-cpu: %user %nice %system %iowait %steal %idle
13.00 0.00 14.00 0.00 0.00 73.00
Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await svctm %util
sda 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
avg-cpu: %user %nice %system %iowait %steal %idle
14.00 0.00 2.00 0.00 0.00 84.00
Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await svctm %util
sda 0.00 28.00 0.00 5.00 0.00 0.13 52.80 0.00 0.00 0.00 0.00
avg-cpu: %user %nice %system %iowait %steal %idle
20.00 0.00 3.00 0.00 0.00 77.00
Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await svctm %util
sda 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00Hors ligne
#49 26/04/2009 21:51:43
- solicel
- Membre
Re : Des requêtes lentes, plus de 10 minutes par requête!
Encore une fois pour la colonne 1:
Requête:
explain analyze select * from fourgrams where lower(part1)='ham' order by freq desc
--------
"Sort (cost=85706.94..85779.84 rows=29163 width=28) (actual time=300.397..315.992 rows=12068 loops=1)"
" Sort Key: freq"
" Sort Method: external merge Disk: 472kB"
" -> Index Scan using part1_idx on fourgrams (cost=0.00..82893.23 rows=29163 width=28) (actual time=131.684..263.224 rows=12068 loops=1)"
" Index Cond: (lower((part1)::text) = 'ham'::text)"
"Total runtime: 323.489 ms"
-------
LOG: EXECUTOR STATISTICS
DETAIL: ! system usage stats:
! 0.372393 elapsed 0.056003 user 0.000000 system sec
! [23259.561631 user 735.897990 sys total]
! 3136/944 [500352520/211103664] filesystem blocks in/out
! 0/199 [4/15942] page faults/reclaims, 0 [0] swaps
! 0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
! 28/15 [1547169/5420959] voluntary/involuntary context switches
! buffer usage stats:
! Shared blocks: 118 read, 0 written, buffer hit rate = 4.84%
! Local blocks: 0 read, 0 written, buffer hit rate = 0.00%
! Direct blocks: 0 read, 0 written
Total query runtime: 402 ms.
6 rows retrieved.et iostat:
Linux 2.6.24-23-generic (admin2-desktop) 26/04/09
avg-cpu: %user %nice %system %iowait %steal %idle
12.49 0.01 0.83 4.09 0.00 82.58
Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await svctm %util
sda 4.64 98.33 15.82 3.94 1.24 0.40 170.17 1.44 72.85 3.89 7.69
avg-cpu: %user %nice %system %iowait %steal %idle
4.00 0.00 0.00 0.00 0.00 96.00
Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await svctm %util
sda 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
avg-cpu: %user %nice %system %iowait %steal %idle
21.00 0.00 2.00 0.00 0.00 77.00
Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await svctm %util
sda 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
avg-cpu: %user %nice %system %iowait %steal %idle
19.00 0.00 1.00 0.00 0.00 80.00
Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await svctm %util
sda 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
avg-cpu: %user %nice %system %iowait %steal %idle
37.62 0.00 3.96 17.82 0.00 40.59
Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await svctm %util
sda 1.00 4.00 41.00 20.00 1.53 0.09 54.56 0.48 7.93 5.31 32.40
avg-cpu: %user %nice %system %iowait %steal %idle
11.11 0.00 0.00 0.00 0.00 88.89
Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await svctm %util
sda 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
avg-cpu: %user %nice %system %iowait %steal %idle
8.00 0.00 1.00 0.00 0.00 91.00
Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await svctm %util
sda 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
avg-cpu: %user %nice %system %iowait %steal %idle
1.98 0.00 0.99 0.00 0.00 97.03
Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await svctm %util
sda 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00Hors ligne
#50 26/04/2009 21:55:54
- solicel
- Membre
Re : Des requêtes lentes, plus de 10 minutes par requête!
Et une dernière fois pour la colonne la plus chiante, la 4 eme:
Requête:
explain analyze select * from fourgrams where lower(part4)='ham' order by freq desc
----------
"Sort (cost=99245.27..99305.78 rows=24206 width=28) (actual time=115311.557..115321.557 rows=11391 loops=1)"
" Sort Key: freq"
" Sort Method: external merge Disk: 448kB"
" -> Index Scan using part4_idx on fourgrams (cost=0.00..96943.70 rows=24206 width=28) (actual time=134.015..115255.306 rows=11391 loops=1)"
" Index Cond: (lower((part4)::text) = 'ham'::text)"
"Total runtime: 115326.717 ms"
-----------
LOG: EXECUTOR STATISTICS
DETAIL: ! system usage stats:
! 115.327146 elapsed 0.188012 user 1.064066 system sec
! [23259.749643 user 736.966057 sys total]
! 222920/896 [500575440/211104568] filesystem blocks in/out
! 0/199 [4/16141] page faults/reclaims, 0 [0] swaps
! 0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
! 14642/4 [1561816/5420965] voluntary/involuntary context switches
! buffer usage stats:
! Shared blocks: 10601 read, 0 written, buffer hit rate = 0.06%
! Local blocks: 0 read, 0 written, buffer hit rate = 0.00%
! Direct blocks: 0 read, 0 written
Total query runtime: 115355 ms.
6 rows retrieved.Hors ligne