tkprof wait exprimé en quelle unité

Version imprimable

Petite question sur tkprof pour en avoir le coeur net :

les waits sont exprimés en quelle unité ? 100 ième de seconde ?

Code:

1
2
3
4
5
6
7
Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message from client                 18612      151.39        161.78
  SQL*Net message to client                   18612        0.00          0.01
  SQL*Net more data to client                  1386        0.00          0.01
  direct path read                             1958        0.08          1.41

Merci par avance

09/02/2010, 17h40
pifor

Le temps est mesuré en secondes avec 10.2:
http://download.oracle.com/docs/cd/B...ace.htm#g22527

Alors j'y comprend plus rien. Voici un tkprof complet sur un SQL qui s'est exécute en 30 secondes et j'ai 127.81 en total waited à la fin.
D'ailleur je n'arrive pas à comprendre pourquoi elle s'exécute en 30 secondes. En principe il ne faut que 7 à 8 secondes !

Avez-vous une explication ?

Code:

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
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
 
TKPROF: Release 11.1.0.6.0 - Production on Wed Feb 10 08:53:56 2010
 
Copyright (c) 1982, 2007, Oracle.  All rights reserved.
 
Trace file: antp_ora_704562.trc
Sort options: default
 
********************************************************************************
count    = number of times OCI procedure was executed
cpu      = cpu time in seconds executing 
elapsed  = elapsed time in seconds executing
disk     = number of physical reads of buffers from disk
query    = number of buffers gotten for consistent read
current  = number of buffers gotten in current mode (usually for update)
rows     = number of rows processed by the fetch or execute call
--------------------------------------------------------------------------------
 
*** SESSION ID:(2161.2211) 2010-02-09 17:36:11.778
 
********************************************************************************
 
SQL ID : bm10wdd6g7qnt
Select sglnum , sgleta , sgllpa1 , naiacer.sgl_even."ROWID"  
from
 naiacer.sgl_even 
 
 
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        0      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch      177      0.00       0.06          0       1012          0       17652
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total      178      0.00       0.06          0       1012          0       17652
 
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 66  
 
Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                     178        0.00          0.00
  SQL*Net message from client                   178        0.00          0.07
  SQL*Net more data to client                   589        0.00          0.00
********************************************************************************
 
SQL ID : 9tyukgtj1hbpz
SELECT SGLLPA1 
from
 NAIACER.SGL_EVEN where ROWID = :1
 
 
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        0      0.00       0.00          0          0          0           0
Execute  17570      0.00       0.31          0          0          0           0
Fetch    17570      0.00       0.49          0      17570          0       17570
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total    35140      0.00       0.80          0      17570          0       17570
 
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 66  
 
Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                   17570        0.00          0.01
  SQL*Net message from client                 17570        0.04          3.07
 
 
 
********************************************************************************
 
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
 
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        0      0.00       0.00          0          0          0           0
Execute  17571      0.00       0.31          0          0          0           0
Fetch    17747      0.00       0.55          0      18582          0       35222
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total    35318      0.00       0.86          0      18582          0       35222
 
Misses in library cache during parse: 0
 
Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message from client                 52888      100.71        127.81
  SQL*Net message to client                   52888        0.00          0.04
  SQL*Net more data to client                   589        0.00          0.00
  direct path read                                4        0.00          0.00
 
 
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
 
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        0      0.00       0.00          0          0          0           0
Execute      0      0.00       0.00          0          0          0           0
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        0      0.00       0.00          0          0          0           0
 
Misses in library cache during parse: 0
 
    2  user  SQL statements in session.
    0  internal SQL statements in session.
    2  SQL statements in session.
********************************************************************************
Trace file: antp_ora_704562.trc
Trace file compatibility: 11.01.00
Sort options: default
 
       1  session in tracefile.
       2  user  SQL statements in trace file.
       0  internal SQL statements in trace file.
       2  SQL statements in trace file.
       2  unique SQL statements in trace file.
  141791  lines in trace file.
      31  elapsed seconds in trace file.

10/02/2010, 18h14
pachot

Bonjour,

Les 127.81 secondes, c'est: SQL*Net message FROM client
Il s'agit du temps où le serveur attends une requête de la part du client.
Donc ce n'est pas le temps d'exécution de la requête, mais au contraire le temps où tu est connecté sans rien faire. Du moins sans faire d'appel à oracle, le programme client tourne peut être.

Il y a 2 requêtes dans ton tkprof:
une exécutée 1 fois, avec 177 fetch et renvoit 17570 lignes (fetch size=100)
et une exécutée 17570 fois, donc probablement pour chaque ligne

Je pense que le pb vient du nombre d'aller-retours que tu fais vers la base.
Quel est l'interêt de cette deuxième requête ?

Cordialement,
Franck.
10/02/2010, 18h32
Waldar

Surtout que la seconde requête récupère une information déjà disponible dans la première !

Comment expliquer un TOTAL WAITED de 127.81 secondes
Code:

1 2 3 Event waited ON Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ SQL*Net message FROM client 52888 100.71 127.81
alors que le SQL ne dure que 31 secondes ?!!!

Code:

31 elapsed seconds IN trace file

C'est pour cela que je voulais être sûr qu'il s'agit bien de seconde !

Merci pour vos réponses

11/02/2010, 17h00
Waldar

Ce n'est PAS du temps lié à la requête.
11/02/2010, 17h03
Débéa

à quoi alors ?

à la session ?
11/02/2010, 17h40
Waldar

Je dirai entre le moment où vous avez activé votre trace, le moment où vous l'avez arrêté tout en retirant le temps de la requête.
15/02/2010, 12h32
Ahmed AANGOUR

le wait event SQL*Net message FROM client n'est pas à prendre en compte car il fait partie de la classe IDLE. Ce temps correspond juste au temps où t'as laissé ta fenêtre sqlplus ouverte jusqu'au moment où t'as désactivé la trace.

Peut-on voir le script que t'as exécuté ? Comme l'ont noté Franck et waldar tu dois surement boucler sur ta 1ère requête et effectuer plus de 17 000 fois un autre select sur la même table requêtée lors du premier select. Why ???