Temps réel supérieur au temps processeur

[roro56]

Bonjour,
j'ai une petite question concernant les temps réel et temps processeur.

J'ai une requete SQL (attaquant des tables SAS) qui tourne en 1h15 en temps REEL alors que le temps CPU est 12 minutes. Comment expliquer un tel décalage ?
Je précise que cette requête a été exécuté sur plusieurs jours et à chaque fois les temps constatés étaient les mêmes d'une journée à l'autre.

En vous remerciant d'avance,
cordialement,
Roro56

[bahraoui]

Bonjour,

Je crois que ce sujet a déjà été traité.
Le temps de lecture écriture fait parti des différents cause, les autres traitements qui tournent sur la machine(la machine alloue du temps pour chaque processus pour exécuter l'ensemble des traitements)...

Cordialement

[frfancha]

Envoyé par roro56

Bonjour,
j'ai une petite question concernant les temps réel et temps processeur.

J'ai une requete SQL (attaquant des tables SAS) qui tourne en 1h15 en temps REEL alors que le temps CPU est 12 minutes. Comment expliquer un tel décalage ?
Je précise que cette requête a été exécuté sur plusieurs jours et à chaque fois les temps constatés étaient les mêmes d'une journée à l'autre.

En vous remerciant d'avance,
cordialement,
Roro56

Sans doute parce que tes disques (comme les nôtres ;-) ) sont plus lents que les accès mémoires. Le temps des IO (entre autres) s'ajoute au temps processeur pour avoir le temps réel.

[roro56]

Merci frfancha,
Mais comment identifier la lenteur de nos disques ?
Pour info, le disque est un DELL PERC 5/i SCSI Disk Device de 103 gigas avec 81 gigas sur un serveur de Xeon de 2.33 Ghz avec 16 gigas de RAM.
Nos tables de sorties sont stockées sur le même disque que les tables en entrée (ce qui normalement limite les I/O).

Le traitement global prend quand même 11h15 en temps réel et 3h15 en temps processeur.

En vous remerciant d'avance,
Cordialement,
Roro56

[datametric]

(ce qui normalement limite les I/O)

Ah bon ?

[s_a_m]

tes disk sont de quel type SUN? NAS?

[xav2229]

Ajoute ces infos dans ton traitement et renvoie nous les résultats:

Code :

1
2
3
4
5
6
 
options fullstimer;
proc sql _method;
<code SQL>
;
quit;

X

[roro56]

Pour répondre a s_a_m, nos disques sont des SAN

Voici le résultat avec l'option fullstimer

Code :

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
150  options fullstimer;
151  PROC SQL _method;
152    CREATE TABLE test AS SELECT t1.*, t2.CD_TYPE_PRODUIT
153    FROM VR_NET AS t1 LEFT JOIN Pdt_Produit_CNP AS t2
154      ON t1.CD_PRD_Init=t2.CD_PRODUIT_CNP
155      WHERE t1.CD_PRD_Init IS NOT NULL;
 
NOTE: SQL execution methods chosen are:
 
      sqxcrta
          sqxjm
              sqxsort
                  sqxsrc( WORK.PDT_PRODUIT_CNP(alias = T2) )
              sqxsort
                  sqxsrc( WORK.VR_NET(alias = T1) )
NOTE: La TABLE WORK.TEST a été créée, avec 15660492 lignes et 135 col.
 
156  quit;
NOTE: La procédure SQL a utilisé (Durée totale du processus) :
      temps réel                   1:32:27.20
      temps processeur utilisateur 3:14.34
      temps processeur système     7:17.76
      Mémoire                            71819k

=> Pendant l'exécution de ce test, le serveur utilisait 3 % de CPU.

[s_a_m]

moi je dirai en partiie ,c'est du à tes disk. EEt oui il faut passer à la fibre optique

pour ta culture comparaison SAN et NAS.

[xav2229]

Peux tu faire les divers tests mentionnés ici

et nous renvoyer les resultats?

[roro56]

Voici les résultats :

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
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
NOTE: L'initialisation de SAS a utilisé :
      temps réel                   0.12 secondes
      temps processeur   0.12 secondes
 
NOTE: Remote signon to ADRESSE complete.
20   
21   rsubmit;
NOTE: Remote submit to ADRESSE commencing.
1    options compress=yes fullstimer;
2    
3    
4    %put CPUCOUNT = <%sysfunc(getoption(CPUCOUNT, keyword))>;
CPUCOUNT = <CPUCOUNT=8>
5    %put MEMSIZE  = <%sysfunc(getoption(MEMSIZE, keyword))>;
MEMSIZE  = <MEMSIZE=0>
6    %put SUMSIZE  = <%sysfunc(getoption(SUMSIZE, keyword))>;
SUMSIZE  = <SUMSIZE=0>
7    %put SORTSIZE = <%sysfunc(getoption(SORTSIZE, keyword))>;
SORTSIZE = <SORTSIZE=67108864>
8    
9    %let PSdatetime = %sysfunc(datetime());
10   /* Build table for gathering stats */
11   proc sql;
12      CREATE TABLE WORK.SAS_TASK
13      (PSdatetime num format = datetime22.3
14      ,STAT char(32)
15      ,MEASURE num
16      )
17      ;
NOTE: La table WORK.SAS_TASK a été créée, avec 0 lignes et 3 col.
18      INSERT INTO WORK.SAS_TASK
19      (PSdatetime, STAT)
20      VALUES(&PSdatetime, 'DATA')
21      VALUES(&PSdatetime, 'MD5')
22      VALUES(&PSdatetime, 'SORT')
23      VALUES(&PSdatetime, 'INDEX')
24      VALUES(&PSdatetime, 'SUMMARY')
25      ;
NOTE: 5 lignes ont été insérées dans WORK.SAS_TASK.
 
26   quit;
NOTE: La procédure SQL a utilisé (Durée totale du processus) :
      temps réel                   0.01 secondes
      temps processeur utilisateur 0.00 secondes
      temps processeur système     0.00 secondes
      Mémoire                            144k
 
 
27   
28   /* Premiere stat : on compte les IO afin de voir si le disque répond bien */
29   /* STAT : measuring IO in DATA step */
30   %let start = %sysfunc(datetime());
31   DATA WORK.BIG;
32      length LONG $ 8000;
33      do i = 1 TO 5*(10**5);
34         LONG = 'X';
35         aleas = time();
36         mod = mod(int(aleas)*100, 3);
37         output;
38      end;
39   run;
 
NOTE: La table WORK.BIG a 500000 observations et 4 variables.
NOTE: La compression de la table WORK.BIG a réduit la taille de 99.44 pourcent. 
      Compression de 1409 pages; la décompression nécessiterait 250001 pages.
NOTE: L'étape DATA a utilisé (Durée totale du processus) :
      temps réel                   7.45 secondes
      temps processeur utilisateur 7.40 secondes
      temps processeur système     0.03 secondes
      Mémoire                            176k
 
 
40   %let gap = %sysevalf(%sysfunc(datetime()) - &start);
41   %put gap = <&gap>;
gap = <7.4539999961853>
42   
43   proc sql;
44      UPDATE WORK.SAS_TASK
45      SET MEASURE = &gap
46      WHERE STAT = 'DATA'
47      ;
NOTE: 1 ligne a été mise à jour dans WORK.SAS_TASK.
 
48   quit;
NOTE: La procédure SQL a utilisé (Durée totale du processus) :
      temps réel                   0.00 secondes
      temps processeur utilisateur 0.00 secondes
      temps processeur système     0.00 secondes
      Mémoire                            314k
 
 
49   
50   
51   /* Ensuite un peu de calcul CPU, pas d'IO ici */
52   /* STAT : DATA : measuring CPU */
53   %let start = %sysfunc(datetime());
54   DATA _NULL_;
55      length LONG $ 64 BIG $ 16;
56      do i = 1 TO 20**6;
57         LONG = put(i, z32.) || reverse(put(i, z32.));
58         BIG = put(md5(LONG), hex16.);
59      end;
60   run;
 
NOTE: L'étape DATA a utilisé (Durée totale du processus) :
      temps réel                   3:08.58
      temps processeur utilisateur 3:08.54
      temps processeur système     0.00 secondes
      Mémoire                            193k
 
 
61   %let gap = %sysevalf(%sysfunc(datetime()) - &start);
62   %put gap = <&gap>;
gap = <188.584000110626>
63   
64   proc sql;
65      UPDATE WORK.SAS_TASK
66      SET MEASURE = &gap
67      WHERE STAT = 'MD5'
68      ;
NOTE: 1 ligne a été mise à jour dans WORK.SAS_TASK.
 
69   quit;
NOTE: La procédure SQL a utilisé (Durée totale du processus) :
      temps réel                   0.00 secondes
      temps processeur utilisateur 0.00 secondes
      temps processeur système     0.00 secondes
      Mémoire                            314k
 
 
70   
71   /* Puis encore de l'IO avec beaucoup de données manipulées */
72   /* STAT : measuring IO in SORT */
73   %let start = %sysfunc(datetime());
74   proc sort DATA=WORK.BIG;
75      BY mod aleas;
76   run;
 
NOTE:  500000 observations copiées de la TABLE WORK.BIG.
NOTE: La TABLE WORK.BIG a 500000 observations et 4 VARIABLES.
NOTE: La compression de la TABLE WORK.BIG a réduit la taille de 99.44 pourcent. 
      Compression de 1409 pages; la décompression nécessiterait 250001 pages.
NOTE: La procédure SORT a utilisé (Durée totale du processus) :
      temps réel                   29.18 secondes
      temps processeur utilisateur 24.03 secondes
      temps processeur système     14.61 secondes
      Mémoire                            66145k
 
 
77   %let gap = %sysevalf(%sysfunc(datetime()) - &start);
78   %put gap = <&gap>;
gap = <29.1879999637603>
79   
80   proc sql;
81      UPDATE WORK.SAS_TASK
82      SET MEASURE = &gap
83      WHERE STAT = 'SORT'
84      ;
NOTE: 1 ligne a été mise à jour dans WORK.SAS_TASK.
 
85   quit;
NOTE: La procédure SQL a utilisé (Durée totale du processus) :
      temps réel                   0.00 secondes
      temps processeur utilisateur 0.00 secondes
      temps processeur système     0.00 secondes
      Mémoire                            314k
 
 
86   
87   /* Encore de l'IO avec du CPU egalement */
88   /* STAT : measuring IO when creating INDEX */
89   %let start = %sysfunc(datetime());
90   proc datasets lib=WORK mt=DATA nolist;
91      MODIFY BIG;
92      INDEX CREATE mod;
NOTE: Un INDEX simple mod a été défini.
93   quit;
 
NOTE: MODIFY a réussi pour WORK.BIG.DATA.
NOTE: La procédure DATASETS a utilisé (Durée totale du processus) :
      temps réel                   0.42 secondes
      temps processeur utilisateur 0.36 secondes
      temps processeur système     0.04 secondes
      Mémoire                            70k
 
 
94   %let gap = %sysevalf(%sysfunc(datetime()) - &start);
95   %put gap = <&gap>;
gap = <0.43799996376037>
96   
97   proc sql;
98      UPDATE WORK.SAS_TASK
99      SET MEASURE = &gap
100     WHERE STAT = 'INDEX'
101     ;
NOTE: 1 ligne a été mise à jour dans WORK.SAS_TASK.
 
102  quit;
NOTE: La procédure SQL a utilisé (Durée totale du processus) :
      temps réel                   0.01 secondes
      temps processeur utilisateur 0.01 secondes
      temps processeur système     0.00 secondes
      Mémoire                            314k
 
 
103  
104  /* Puis enfin une tache d'agrégation */
105  
106  /* STAT : measuring multi-thread in SUMMARY */
107  %let start = %sysfunc(datetime());
108  proc summary DATA=WORK.BIG;
109     class mod;
110     var aleas;
111     output out=WORK.ZZ;
112  quit;
 
NOTE:  500000 observations copiées de la TABLE WORK.BIG.
NOTE: La TABLE WORK.ZZ a 20 observations et 5 VARIABLES.
NOTE: La compression de la TABLE WORK.ZZ a augmenté la taille de 100.00 pourcent. 
      Compression de 2 pages; une décompression nécessiterait  1 pages.
NOTE: La procédure SUMMARY a utilisé (Durée totale du processus) :
      temps réel                   0.40 secondes
      temps processeur utilisateur 0.34 secondes
      temps processeur système     0.07 secondes
      Mémoire                            8916k
 
 
113  %let gap = %sysevalf(%sysfunc(datetime()) - &start);
114  %put gap = <&gap>;
gap = <0.42200016975402>
115  
116  proc sql;
117     UPDATE WORK.SAS_TASK
118     SET MEASURE = &gap
119     WHERE STAT = 'SUMMARY';
NOTE: 1 ligne a été mise à jour dans WORK.SAS_TASK.
 
120  quit;
NOTE: La procédure SQL a utilisé (Durée totale du processus) :
      temps réel                   0.00 secondes
      temps processeur utilisateur 0.00 secondes
      temps processeur système     0.00 secondes
      Mémoire                            314k
 
 
121  
122  /*Au final : */
123  DATA _NULL_;
124     SET WORK.SAS_TASK;
125     put (_ALL_) (=);
126  run;
 
 
CPUCOUNT = <CPUCOUNT=8>
MEMSIZE  = <MEMSIZE=0>
SUMSIZE  = <SUMSIZE=0>
SORTSIZE = <SORTSIZE=67108864>
 
PSdatetime=08DEC2011:16:54:28.712 STAT=DATA MEASURE=7.4539999962
PSdatetime=08DEC2011:16:54:28.712 STAT=MD5 MEASURE=188.58400011
PSdatetime=08DEC2011:16:54:28.712 STAT=SORT MEASURE=29.187999964
PSdatetime=08DEC2011:16:54:28.712 STAT=INDEX MEASURE=0.4379999638
PSdatetime=08DEC2011:16:54:28.712 STAT=SUMMARY MEASURE=0.4220001698
NOTE:  5 observations copiées de la TABLE WORK.SAS_TASK.
NOTE: L'étape DATA a utilisé (Durée totale du processus) :
      temps réel                   0.01 secondes
      temps processeur utilisateur 0.00 secondes
      temps processeur système     0.00 secondes
      Mémoire                            152k

[xav2229]

il serait intéressant d'avoir la Log pour comparer le temps CPU/real

[roro56]

J'ai ajouté la log dans mon message précédent.

Merci d'avance

[xav2229]

J'ai regardé et dans ces étapes tu n'as pas de problèmes qui ressortent.
les temps sont meme bons!

Je pense que ta lenteur observée vient de la volumétrie de tes tables,
beaucoup de lignes et de colonnes: Ton résultat montre 15 millions de lignes + 135 cols

Ce qui consomme beaucoup se sont les tris:

Code :

1
2
3
4
              sqxsort
                  sqxsrc( WORK.PDT_PRODUIT_CNP(alias = T2) )
              sqxsort
                  sqxsrc( WORK.VR_NET(alias = T1) )

tu as combien de lignes dans PDT_PRODUIT_CNP / VR_NET ?

X

[roro56]

merci pour ta réponse Xav.
Pour ta question, la table produit contient 50 lignes pour 5 colonnes.

Je suis d'accord avec toi sur le fait que le nb de lignes et de colonnes de la table principale y est pour beaucoup. Mais ce qui m'intrigue plus c'est que le temps d'exécution de ce traitement sur le serveur est identique à celui que j'exécute en local sur mon PC (et pourtant mon PC est nettement moins "boosté", 2 CPU et 1 Go de RAM).
Le serveur devrait quand même être plus performant (sachant que c'était le seul process a tourné lors de ce test).

[xav2229]

La solution quand tu dois ajouter un libellé et que tu as 50 valeurs est de passer par un format.

Création du format:

Code :

1
2
3
4
5
6
7
8
9
10
11
12
13
 
proc sql;
   CREATE VIEW builformat AS
   SELECT t2.CD_PRODUIT_CNP AS START
         ,t2.CD_TYPE_PRODUIT AS LABEL
         ,'fmtProd' AS FMTNAME
         ,'C' AS TYPE
   FROM Pdt_Produit_CNP AS t2
   ;
quit;
 
proc format cntlin=builformat;
run;

Après tu auras le libellé directement:

Code :

1
2
 
put(CD_PRD_Init, $fmtProd.) =;

Xav

[roro56]

Je suis d'accord concernant l'ajout de libelle.
Par contre, la requête que je voulais posté initialement ne concernait pas l'ajout d'un libellé mais la restriction de données d'une table principale (15 millions de lignes) avec une table secondaire (70 000 lignes et 4 colonne).

voici le code :

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
20   proc sql _method;
21     CREATE TABLE Tmp AS
22     SELECT t1.*
23     FROM lib.principale AS t1 LEFT JOIN lib.annul AS t2
24       ON t1.ID_CONTRAT=t2.ID_CONTRAT AND
25          t1.DT_EFFET=t2.DT_EFFET AND
26          t1.DT_TRT<t2.DT_TRT
27     WHERE t2.ID_CONTRAT IS NULL;
 
NOTE: SQL execution methods chosen are:
 
      sqxcrta
          sqxfil
              sqxjm
                  sqxsort
                      sqxsrc( LIB.annul(alias = T2) )
                  sqxsort
                      sqxsrc( LIB.principale(alias = T1) )
NOTE: La compression de la TABLE TMP a réduit la taille de 53.92 pourcent.
      Compression de 611285 pages; la décompression nécessiterait 1326647 pages.
NOTE: La TABLE TMP a été créée, avec 15919742 lignes et 134 col.
 
28   quit;
NOTE: La procédure SQL a utilisé (Durée totale du processus) :
      temps réel                   1:36:38.21
      temps processeur utilisateur 6:19.53
      temps processeur système     7:33.62
      Mémoire                            71819k

Je précise que j'ai tenté le merge et les temps sont les mêmes (sur en local et sur le serveur).

[s_a_m]

essaies la méthode des tables de HACHAGE.
sinon pour ta requête SQL; as tu indexée tes colonnes de jointure?
il faut commencer peut être par lire la table secondaire ?

Code :

1
2
 
FROM lib.annul AS t1 LEFT JOIN lib.principale  AS t2

évites les select *.

après tu nous dis que le temps d'exécution sur le serveur est le même que sur ton SAS locale .
comment tu soumis ton code au serveur?
et quelle est la configuration de ton serveur?

[roro56]

Pour le haschtable, ça peut être rapidemant la galère.
Pour les index, oui pourquoi pas mais je voudrais d'abord comprendre pourquoi les temps sont identiques sur mon poste et sur le serveur.

La soumission sur serveur peut se faire de 2 manières différentes :
- en remote depuis mon poste
- ou alors directement sur le serveur

La config du serveur est la suivante :
Windows(R) Server 2003, Enterprise Edition
Version 5.2.3790 Service Pack 2 Build 3790
Total Physical Memory 16 382.99 MB
Available Physical Memory 14.83 GB
Total Virtual Memory 17.75 GB
Available Virtual Memory 16.57 GB
Page File Space 2.00 GB
8 processeurs de ce type :
Processor x86 Family 6 Model 15 Stepping 7 GenuineIntel ~2327 Mhz

[xav2229]

les différences de temps de traitements observées sont entre ces deux méthodes:

La soumission sur serveur peut se faire de 2 manières différentes :
- en remote depuis mon poste
- ou alors directement sur le serveur

?

X