Discussion :

[admunix21]

Bonjour,

Je suis en charge de tester les performances d'une application (qui vient d'être totalement ré-écrite) qui doit entrer en production le 25 février (135 000 utilisateurs devront s'y connecter obligatoirement à plusieurs reprises jusque fin mars).
Pour mes tests, j'utilise IBM Rational Performance et j'ai très vite pu constater les mauvais temps de réponses de l'application : à faible charge, ils dépassent déjà les 2 secondes pour 95% des utilisateurs (pour l'obtention d'une page).
Lors de mes investigations, j'ai remarqué qu' avec un seul utilisateur, n'effectuant q'une requête, j' obtiens des temps de réponse qui oscillent entre 100ms et 5s, voire 10s (à quelques minutes d'intervalle). Celà me parait plutôt bizarre.
Je n'ai aucune erreur.
L'analyse des rapports AWR ne m' a pas permis de mettre le doigt sur le problème.

Pour information voici l'environnement de tests:

Serveur web :
5 serveurs CentOS 5.4 derrière un altéon (qui a déjà été mis hors de cause)
apache 2 / php 5.1 / instantclient / utilisation de PDO_oci
Serveur de base de données :
un serveur AIX 5.3 mutualisé
une base de données (non mutualisée) oracle 10.2.0.3 UTF-8

Je ne dispose que de peu de temps pour établir un rapport de test.
Auriez-vous une idée des éléments vers lesquels je dois orienter mes recherches en priorité ?

Merci d'avance

[Rams7s]

Ben si le rapport AWR indique que la base à de bon temps de réponses, le problème ne vient pas d'elle.

Comme l'appli vient d'être ré-écrite, les développeurs ont du suivre les divers bonnes pratiques qui existent et instrumenté l'appli, mettre de quoi mesurer plus finement les temps de réponses des différentes parties de l'application. Il suffit d'activer ces différentes traces.

[admunix21]

Ben si le rapport AWR indique que la base à de bon temps de réponses, le problème ne vient pas d'elle.

Comme l'appli vient d'être ré-écrite, les développeurs ont du suivre les divers bonnes pratiques qui existent et instrumenté l'appli, mettre de quoi mesurer plus finement les temps de réponses des différentes parties de l'application. Il suffit d'activer ces différentes traces.

La question que je me pose : si un seul utilisateur peut-avoir autant d'écart dans les temps de réponse, l'application peut-elle en être reponsable ??? ou le réseau ?? ou la base ? c'est la première base en AL32UTF8 que nous avons, et, compte-tenu que nos serveurs web sont mutualisés en prod, je n'ai pas réadapter les paramètres apache/php en environnement de test, pour rester le plus près possible de la prod (13 bases de données et une seule en AL32UTF8).
Je ne suis pas non plus persuadée que les développeurs se préoccupent beaucoup de l'environnement sur lequel l'application devra être déployée en production

[Mohamed.Houri]

Pourquoi ne pas poster ici le rapport AWR

1. Load Profile
2. Instance Efficiency Percentages
3. Top 5 Timed Foreground Events

[Rams7s]

Quand je parlais des développeurs et des traces, il s'agissait de logs. Un truc type log4j, ou un mode debug qui va imprimer les temps d'appel des différentes fonctions. Exactement comme une trace dans oracle sur laquelle vous pouvez utiliser tkprof.

Dans le cas present, si la page met 4s à s'afficher, vous devez pouvoir savoir si elle met 3s95 à afficher le header, ou si c'est le corps de la page, ou bien l'affichage des différentes images, le temps du javascript, une requete en base... Si il n'y a rien qui ne vous permette de le faire, il va falloir instrumenter le code, être capable de mesurer les temps des réponses des différents appels. En plus, si le problème resurgit dans le futur vous pourrez isoler le coupable rapidement (mieux pour les 135 000 utilisateurs ).

Pour la base, vous pouvez effectivement utiliser AWR, regarder les temps des réponses des différents SQL, les waits et comparer avec avant le changement de base. Vous l'avez déjà fait, et en avez déduit que le problème ne venait pas de là.

Par contre c'est bien de ne pas vouloir taper exclusivement sur la base.

[admunix21]

Pourquoi ne pas poster ici le rapport AWR

1. Load Profile
2. Instance Efficiency Percentages
3. Top 5 Timed Foreground Events

Voici les infos suites à un test effectué aujourd'hui (temps de réponses collectés inacceptables) :
Load Profile
~~~~~~~~~~~~ Per Second Per Transaction
--------------- ---------------
Redo size: 1,818.15 35.05
Logical reads: 11,289.37 217.65
Block changes: 7.41 0.14
Physical reads: 0.06 0.00
Physical writes: 1.05 0.02
User calls: 1,735.86 33.47
Parses: 906.73 17.48
Hard parses: 0.64 0.01
Sorts: 380.94 7.34
Logons: 51.68 1.00
Executes: 858.41 16.55
Transactions: 51.87

% Blocks changed per Read: 0.07 Recursive Call %: 66.20
Rollback per transaction %: 99.59 Rows per Sort: 1.21

Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Buffer Nowait %: 100.00 Redo NoWait %: 99.99
Buffer Hit %: 100.00 In-memory Sort %: 100.00
Library Hit %: 99.91 Soft Parse %: 99.93
Execute to Parse %: -5.63 Latch Hit %: 99.75
Parse CPU to Parse Elapsd %: 28.47 % Non-Parse CPU: 96.97

Shared Pool Statistics Begin End
------ ------
Memory Usage %: 92.72 92.03
% SQL with executions>1: 96.26 72.91
% Memory for SQL w/exec>1: 96.88 72.34

Top 5 Timed Events Avg %Total
~~~~~~~~~~~~~~~~~~ wait Call
Event Waits Time (s) (ms) Time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
CPU time 1,011 90.7
SQL*Net more data from client 75,854 431 6 38.7 Network
SQL*Net more data to client 1,196,012 194 0 17.4 Network
os thread startup 359 13 36 1.2 Concurrenc
SQL*Net message to client 2,853,747 6 0 0.5 Network
-------------------------------------------------------------

[admunix21]

Quand je parlais des développeurs et des traces, il s'agissait de logs. Un truc type log4j, ou un mode debug qui va imprimer les temps d'appel des différentes fonctions. Exactement comme une trace dans oracle sur laquelle vous pouvez utiliser tkprof.

Dans le cas present, si la page met 4s à s'afficher, vous devez pouvoir savoir si elle met 3s95 à afficher le header, ou si c'est le corps de la page, ou bien l'affichage des différentes images, le temps du javascript, une requete en base... Si il n'y a rien qui ne vous permette de le faire, il va falloir instrumenter le code, être capable de mesurer les temps des réponses des différents appels. En plus, si le problème resurgit dans le futur vous pourrez isoler le coupable rapidement (mieux pour les 135 000 utilisateurs ).

Pour la base, vous pouvez effectivement utiliser AWR, regarder les temps des réponses des différents SQL, les waits et comparer avec avant le changement de base. Vous l'avez déjà fait, et en avez déduit que le problème ne venait pas de là.

Par contre c'est bien de ne pas vouloir taper exclusivement sur la base.

Je dispose de IBM page detailer. J'ai effectué quelques connexions comme un utilisateur lambda (en étant le seul utilisateur), et ai constaté, sur l'élément de page principal, après 5 connexions, une augmention du temps de réponses sur la page principale, passant de moins de 500ms à plus de 2s.
Je pourrai fournir le détail obtenu avec IBM Detailer demain sur quelques tests.

[Mohamed.Houri]

Code :

Sélectionner tout - Visualiser dans une fenêtre à part

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
 
Load Profile
~~~~~~~~~~~~     Per Second 	Per Transaction
--------------- ------------------------------
Redo size: 		1,818.15 	35.05
Logical reads: 	11,289.37 	217.65
Block changes: 	7.41 		0.14
Physical reads:     0.06 		0.00
Physical writes:    1.05 		0.02
User calls: 	       1,735.86 	33.47
Parses: 		906.73   	17.48
Hard parses:   	0.64 		0.01
Sorts: 		380.94 	7.34
Logons: 		51.68 	       1.00
Executes: 		858.41 	16.55
Transactions: 	51.87
 
% Blocks changed per Read: 0.07    Recursive Call %: 66.20
 Rollback per transaction %: 99.59 Rows per Sort: 1.21
 
Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Buffer Nowait %: 100.00    		Redo NoWait %: 99.99
Buffer Hit    %: 100.00 	  	  In-memory Sort %: 100.00
Library Hit %: 99.91 	   		Soft Parse %: 99.93
Execute to Parse %: -5.63  		Latch Hit %: 99.75
Parse CPU to Parse Elapsd %: 28.47  %Non-Parse CPU: 96.97
 
Shared Pool Statistics     Begin End 
------ -------------------------------
           Memory Usage %: 92.72 92.03
% SQL with executions>1  : 96.26 72.91
% Memory for SQL w/exec>1: 96.88 72.34
 
 
Top 5 Timed Events Avg %Total
~~~~~~~~~~~~~~~~~~ wait Call
Event 				             Waits         Time(s)     Avg(ms) %Time 	  Wait Class
------------------------------ ------------ ----------- ------   ------   ----------
CPU time 				                      1,011     90.7 
SQL*Net more data from client  75,854         431         6       38.7    Network
SQL*Net more data to client    1,196,012       194        0       17.4    Network
os thread startup              359             13         36      1.2     Concurrenc
SQL*Net message to client      2,853,747       6          0       0.5     Network
-------------------------------------------------------------------------------------

La première remarque importante que j’ai à vous faire est la suivante : comment pourriez-vous (et pourrions nous) correctement interpréter un rapport AWR sans tenir compte de la durée de ce rapport ? La deuxième remarque est que pour pouvoir être correctement interprété le rapport AWR doit être pris pendant la période où la performance n’était pas bonne.

Passons maintenant à l’analyse :

90% de votre temps (DB time que nous ne connaissons pas) a été passé dans la CPU. Avant d’aller vite en besogne et dire que vous avez un problème de CPU, il faudrait au moins que l’on sache quel est le nombre de CPU de votre machine et la durée de ce rapport AWR. Ceci dit, je ne pense pas du tout que vous avez un problème de CPU.

Je vous laisse aussi deviner comment j’ai su que votre base de données est du type DWH (et si ça ne l’est pas alors c’est une application OLTP pas très standard).

Vous avez une valeur négative du rapport Execute to Parse% (-5,63). Cette valeur négative est inhabituelle mais finalement elle nous signale peut-être simplement que vous faites 5,63% de parses de plus que d’exécutions. En étroite relation avec cela vous avez 1735 user calls qui se répartissent (grosso-modo) en 858 exécutions et 906 parses. Je me demande, dans un contexte DWH, où sont passés les fetches ? Seriez-vous en train de faire un seul gros fetch transférant un énorme volume de données entre le client et le serveur ?

En tout cas les deux ''wait events'' SQL*Net more data from client et SQL*Net more data to client tendent à suggérer la présence d'un transfert de données très important. Et, au vu des temps moyens d’exécution de ces deux ''events’’, il me semble que vous êtes servie par un disque rapide et que vote problème est plus lié à un souci avec le réseau ou avec la quantité de données à transférer qu’il ne l'est avec le disque. Peut-être qu’il faudrait revoir aussi le code pour pouvoir transférer efficacement (arraysize) les données.

Je trouve aussi qu'avoir 52 transactions (commit/rollback) par seconde est assez inhabituel pour une application DWH. Peut-être que c'est l'application cliente (webserver) qui fait des rollbacks après chaque fermeture de session même si cette session n'a fait que des selects.

D’autres détails sont nécessaires pour continuer l’interprétation

[Rams7s]

@Mohamed.Houri: Je vous trouve un peu dur. Vous demandez seulement certains éléments du rapport, vous les avez. Enfin, je trouve.

Ceci dit, Ligne 14 de la mise en page de M.Houri: 1 connection par transaction, et 51 connections par seconde?
Ca c'est rigolo, et pas très très efficace.

http://docs.oracle.com/cd/E11882_01/...htm#PFGRF94134
Le point 9 sera à faire, c'est un investissement pour l'avenir.
Et pour le moment, c'est le point 6 qui vous intéressera.

[admunix21]

@Mohamed.Houri: Je vous trouve un peu dur. Vous demandez seulement certains éléments du rapport, vous les avez. Enfin, je trouve.

Ceci dit, Ligne 14 de la mise en page de M.Houri: 1 connection par transaction, et 51 connections par seconde?
Ca c'est rigolo, et pas très très efficace.

http://docs.oracle.com/cd/E11882_01/...htm#PFGRF94134
Le point 9 sera à faire, c'est un investissement pour l'avenir.
Et pour le moment, c'est le point 6 qui vous intéressera.

Je tiens à vous remercier toi et à Mohamed.Houri.
Je vous fournirai des infos plus complètes demain, car, franchement, aujourd'hui je n'ai pas eu le temps de récupérer sur disque dur externe mes rapports ADDM et AWR correspondants à la plage des mes tests. J'avais un point écrit à faire sur mes premiers retours de tests et ce genre de chose me prend beaucoup de temps.
A noter que les infos que j'avais fourni à Mohamed correspondaient à une plage de tests durant laquelle j'avais obtenu des temps de réponses qui s'écartaient de ce qui a été défini comme acceptable par le projet. Il est vrai que je n'ai pas fourni beaucoup d'informations, mais je m' en étais tenue à ce qui était demandé (un peu bêtement peut-être ! mais bon)