tkprof wait exprimé en quelle unité

**Débéa** · 09/02/2010, 15h15

Petite question sur tkprof pour en avoir le coeur net :

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

Code :

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

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

**pifor** · 09/02/2010, 17h40

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

**Débéa** · 10/02/2010, 09h29

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 :

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
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.

**pachot** · 10/02/2010, 18h14

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.

**Waldar** · 10/02/2010, 18h32

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

**Débéa** · 11/02/2010, 16h32

Comment expliquer un TOTAL WAITED de 127.81 secondes

Code :

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

1
2
3
Event waited ON                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message FROM client                 52888      100.71        127.81