Discussion :

[stehga]

Bonjour


Je suis confronté à un pb de perfs sur une appli java qui travaille avec une base oracle 11g.

En gros, l'appli a deux grosses phases différentes, une première au cours de laquelle elle insère des données dans la BD et une seconde au cours de laquelle elle fait des select et des updates dans la base.

Cette 2eme phase s'avère extrèmement lente la 1ere fois qu'elle est effectuée alors que si on la relance une seconde, une 3eme fois, elle est trés rapide. On peut passer de plusieurs centaines de minutes à quelques minutes, voire moins d'une minute.

Je suis en train de chercher la cause de ce pb de "1ere fois" et ma question à l'adresse de pros sera de savoir ce qui pourrait faire une telle différence entre la 1ere fois et les suivantes, sachant que les ordres joués sont strictement les memes?

De plus, en regardant un peu sur internet comment chercher la cause de mon pb, j'ai trouvé plusieurs posts mentionnant la vue V$SQL. J'ai regardé son contenu dans ma base et j'ai vu que dans la colonne ELAPSED_TIME, un des ordres aurait pris plusieurs heures. Pouvez-vous me confirmer que cette colonne contient bien le temps effectif pour jouer l'odre en question?
Est-ce une bonne stratégie de se baser sur le contenu de cette vue pour enqueter sur mon pb?
Y a t-il d'autres outils oracle qui pourraient m'aider?

Et enfin, est-ce qu'un sous dimensionnement du schema (tables créées avec une taille de départ petite qui force oracle à redimensionner) à la base pourrait être lié à mon problème?

Merci pour votre aide.

[LBO72]

Une des raisons pourrait être :
- La première fois que tu lances ta requête, Oracle charge les données dans le cash et fait donc beaucoup d'accès disques, ce qui coute le plus cher.
- Les autres fois, l'optimiseur bénéficie du cash et de l'ancien plan d'exécution et du coup, le temps de réponse est plus rapide.

Pour en avoir le coeur net, lance ta requête la première fois et compte tes accès disques. La relancer une second fois et compter encore le nombre d'accès disques.

Ou alors, avant de la lancer les autres fois, vides le buffer cash pour repartir sur une situation identique.

LBO72.
Cdlt,

[Laurent_du_78]

C'est vrai que le chargement du cache se paye CASH

Ne pas oublier de calculer les stats après le chargement pour que les traitements qui suivent profitent de ce calcul.

[stehga]

Merci pour ces pistes.

Une question, surement débile : comment compter les accès disques et vider le buffer cacher?

Merci pour ces précisions

[metricx01]

pour vider le cache :

alter system flush buffer_cache;

pour les physical reads :

SQL>set autotrace traceonly
SQL>ton instruction d'update

mais il est mieux de tracer ce que fait votre application pour cela:
1> vider le cache
2> activer la trace
3> lancer votre appli
4> arrêter la trace et analyse les fichiers en sortie.

voire http://oracle.developpez.com/guide/tuning/tkprof/ pour plus de détails.

elapsed_time contient effectivement le temps pris par le curseur mais c'est en millisecondes.

[pachot]

J'ai regardé son contenu dans ma base et j'ai vu que dans la colonne ELAPSED_TIME, un des ordres aurait pris plusieurs heures.

Oui, mais c'est un temps cumulé. Il faut le diviser par EXECUTIONS pour avoir le temps moyen.

[Ahmed AANGOUR]

le mieux c'est de lancer un rapport AWR sur la période correspondant à la 2ème phase puis de comparer ce rapport pour les différents appels.

[stehga]

Re-bonjour,


J'ai sorti une trace avec tkprof en suivant les instructions ici : http://oracle.developpez.com/guide/tuning/tkprof/


et j'avoue avoir un peu de mal à interpréter le résultat...

Quelques questions :

- que signifie 'Misses in library cache during parse' ou 'Misses in library cache during execute' ? Ces valeurs sont quasiment toujours à 1, parfois 2 dans mon rapport.

- l'article mentionne que les valeurs cpu et elapsed doivent être proches, ce qui n'est pas mon cas pour un certain nombre d'ordres où elapsed est beaucoup plus grand que cpu. Qu'est-ce que va peut vouloir dire?

- Enfin à la fin du rapport, il y a un espèce de bilan qui indique apparemment le temps total : x elapsed seconds in trace file. Est-ce que ce temps correspond au temps effectif passé par oracle pour effectuer toutes les opérations? Si c'est le cas, ce temps est pour moi trés éloigné de ce que j'observe en réalité...

Merci de vos éclaircissements.

[Edit] Et aussi, qu'est-ce qu'un rapport AWR?

[pachot]

- que signifie 'Misses in library cache during parse' ou 'Misses in library cache during execute' ? Ces valeurs sont quasiment toujours à 1, parfois 2 dans mon rapport.

C'est le nombre de fois où la requête a du être reparsée. Dans le premier cas parce qu'elle n'est pas (ou plus) en shared pool, dans le deuxième cas parce qu'elle y est mais a été invalidée.

à comparer respectivement avec le nombre de parse et le nombre d'execute

l'article mentionne que les valeurs cpu et elapsed doivent être proches

La différence est le temps qui n'est pas du temps CPU: attentes d'apples systèmes (i/o, réseau) ou attente de vérrou,...
Je n'ai pas lu l'article, mais je ne cois pas pourquoi il faudrait que la majorité tu temps d'exécution de la requête soit de la CPU.

Il y a moyen d'avoir une trace étendue (event 10046 level 8) et tkprof te montrera exactement ce qui est fait pendant ce temps non-cpu

- Enfin à la fin du rapport, il y a un espèce de bilan qui indique apparemment le temps total : x elapsed seconds in trace file. Est-ce que ce temps correspond au temps effectif passé par oracle pour effectuer toutes les opérations? Si c'est le cas, ce temps est pour moi trés éloigné de ce que j'observe en réalité...

Je ne sait pas comment cette ligne est calculée et je ne pense pas qu'elle soit bien utile. Il vaudrait mieux regarder le total du temps elapsed (pour les requêtes non-récursives, parce que sinon, le même temps est compté plusieurs fois)

Cordialement,
Franck.

[stehga]

Re-bonjour,

Aprés analyse des traces, le problème vient du plan d'execution utilisé sur certaines requetes jouées trés souvent.

Lors du 1er lancement, un TABLE ACCESS FULL est fait systematiquement, alors que sur le lancement suivant, les premières fois, on a aussi un TABLE_ACCESS_FULL puis ensuite l'un des index sur la table est utilisé. Sans l'index, l'ordre passe en plusieurs secondes, avec index en plusieurs centièmes de secondes.

Donc ma nouvelle question : pourquoi le plan d'execution d'une meme requete change au cours du temps? Je sais que normalement ce sont les statistiques qui influencent le choix du plan d'execution, mais dans notre cas, elles n'ont pas changé entre les deux lancements. Y a-t-il d'autres paramètres qui pourraient expliquer ce comportement?

Merci