Timeout aléatoire durant appel via page web.

Bonjour,

Je rencontre actuellement un problème SQL.

Sur le serveur IIS, j'ai une page qui est appelé tout les matins pour un traitement. celui-ci ne fait pas de choses compliqués :

récupération données SQL
traitement sur les données
création de fichiers.

le tout prends 2 secondes (encore vérifié hier quand je l'appel manuellement).
Cette page est appelé par un outil de "job" que je ne gère pas (en gros je développe sous Visual Studio / Vb.net et une fois le projet fini, je peux avoir des traitements qui doivent être appelés le matin par exemple, et dans ce cas je fais une page dédié qui est appelé par une tâche par un serveur)

il m'arrive d'avoir de temps en temps le problème suivant :
Un timeout lors de l'excution de la page du côté SQL.
Code:

1 2 3 4 5 6 7 8 9 10 11 12 13 14 Expiration du Timeout. Le délai d'attente s'est écoulé avant la fin de l'opération ou le serveur ne répond pas. à System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseInAction) à System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock, Boolean asyncClose) à System.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady) à System.Data.SqlClient.SqlDataReader.TryConsumeMetaData() à System.Data.SqlClient.SqlDataReader.get_MetaData() à System.Data.SqlClient.SqlCommand.FinishExecuteReader(SqlDataReader ds, RunBehavior runBehavior, String resetOptionsString) à System.Data.SqlClient.SqlCommand.RunExecuteReaderTds(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, Boolean async, Int32 timeout, Task& task, Boolean asyncWrite, SqlDataReader ds) à System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method, TaskCompletionSource`1 completion, Int32 timeout, Task& task, Boolean asyncWrite) à System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method) à System.Data.SqlClient.SqlCommand.ExecuteReader(CommandBehavior behavior, String method) à System.Data.SqlClient.SqlCommand.ExecuteReader() ...
J'ai évoqué plusieurs fois qu'il ne s'agissait pas de mon code car ce dernier fonctionne et ce problème apparaît par moment. je suspecte un blocage de l'accès à la base par un processus.
Mais c'est à moi de trouver la source du problème.Si je l'execute non plus à 6h mais à par exemple à 9h, c'est à dire quand j'ai remarqué par mail l'erreur, le traitement se passe correctement.

Je dois donc déterminé la source du problème, savoir ce qui bloque via SQL et mon code vb, bref pas évident.

La seule chose que je vois possible c'est de lancé un traitement depuis mon poste pour interroger l'état de la base ? en continu ? ou le soir jusqu'à mon retour le matin.

Je ne vois pas comment faire, et un coup de main serait le bienvenu.
Merci d'avance.

Pouvez-vous poster le code SQL qui est lancer par ta page web ?
Poste également le code de ta page web.

Bonjour,

Vous pouvez capturer dans une trace SQL Profiler côté serveur ce qui se passe (cf. ce tutoriel, jusqu'au III inclus).
Il vous faudra sélectionner les éventements:

Errors and Warnings > Blocked process report
Stored procedures / RPC:Completed, SP:StmtCompleted (au cas où il y aurait de laborieux triggers)

Et les champs suivant autant de fois que c'est possible :

TextData
Duration
SPID
DatabaseID
ObjectType
CPU
Reads
Writes
Error
IndexID
Mode
ObjectID
RowCounts
StartTime

Ensuite il vous faudra filtrer sur le champ DatabaseID (SELECT DB_ID() dans le contexte de la base de données à étudier, ou SELECT * FROM sys.databases et vous regardez le champ database_id), et sur la colonne Duration avec une valeur de 1000 (c'est en millisecondes).

Avant de créer la trace côté serveur, veillez à positionner l'option d'instance blocked process threshold (s)
C'est la durée en secondes au dessus de laquelle un événement qui décrit une situation de blocage au format XML est levé par le moteur et capturable par SQL Profiler (entre autres outils).
Voici comment faire :

Code:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
EXEC sp_configure 'show advanced options', 1
GO
RECONFIGURE
GO
 
EXEC sp_configure 'blocked process threshold (s)', 5
GO
RECONFIGURE
GO
 
EXEC sp_configure 'show advanced options', 0
GO
RECONFIGURE
GO

A partir de là il vous suffit d'analyser le contenu du fichier de trace : ceci se fait à l'aide de la fonction système sys.fn_trace_gettable(). Vous aurez donc un quelque chose dans ce style :

Code:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
SELECT	StartTime
	, CAST(TextData AS nvarchar(max)) AS TextData 
	, Duration / 1000 AS Duration_ms -- les durées sont capturées en microsecondes 
	, CPU
	, Reads
	, Writes
	, Error
	, ObjectType
	, ObjectID
	, IndexID
	, Mode
	, RowCounts
	, EventClass
--INTO	dbo.trace_timeout -- si vous souhaitez charger le fichier dans une table
FROM	sys.fn_trace_gettable('', DEFAULT)

De là vous pouvez réaliser votre analyse en spécifiant une jointure avec la table suivante pour connaître l'événement :

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
DECLARE @events TABLE
(
	event_id tinyint
	, event_name sysname
)
 
INSERT @events VALUES (0, 'Reserved')
, (1, 'Reserved')
, (2, 'Reserved')
, (3, 'Reserved')
, (4, 'Reserved')
, (5, 'Reserved')
, (6, 'Reserved')
, (7, 'Reserved')
, (8, 'Reserved')
, (9, 'Reserved')
, (10, 'RPC:Completed')
, (11, 'RPC:Starting')
, (12, 'SQL:BatchCompleted')
, (13, 'SQL:BatchStarting')
, (14, 'Audit Login')
, (15, 'Audit Logout')
, (16, 'Attention')
, (17, 'ExistingConnection')
, (18, 'Audit Server Starts and Stops')
, (19, 'DTCTransaction')
, (20, 'Audit Login Failed')
, (21, 'EventLog')
, (22, 'ErrorLog')
, (23, 'Lock:Released')
, (24, 'Lock:Acquired')
, (25, 'Lock:Deadlock')
, (26, 'Lock:Cancel')
, (27, 'Lock:Timeout')
, (28, 'Degree of Parallelism Event (7.0 Insert)')
, (29, 'Reserved')
, (30, 'Reserved')
, (31, 'Reserved')
, (32, 'Reserved')
, (33, 'Exception')
, (34, 'SP:CacheMiss')
, (35, 'SP:CacheInsert')
, (36, 'SP:CacheRemove')
, (37, 'SP:Recompile')
, (38, 'SP:CacheHit')
, (39, 'Deprecated')
, (40, 'SQL:StmtStarting')
, (41, 'SQL:StmtCompleted')
, (42, 'SP:Starting')
, (43, 'SP:Completed')
, (44, 'SP:StmtStarting')
, (45, 'SP:StmtCompleted')
, (46, 'Object:Created')
, (47, 'Object:Deleted')
, (48, 'Reserved')
, (49, 'Reserved')
, (50, 'SQL Transaction')
, (51, 'Scan:Started')
, (52, 'Scan:Stopped')
, (53, 'CursorOpen')
, (54, 'TransactionLog')
, (55, 'Hash Warning')
, (56, 'Reserved')
, (57, 'Reserved')
, (58, 'Auto Stats')
, (59, 'Lock:Deadlock Chain')
, (60, 'Lock:Escalation')
, (61, 'OLE DB Errors')
, (62, 'Reserved')
, (63, 'Reserved')
, (64, 'Reserved')
, (65, 'Reserved')
, (66, 'Reserved')
, (67, 'Execution Warnings')
, (68, 'Showplan Text (Unencoded)')
, (69, 'Sort Warnings')
, (70, 'CursorPrepare')
, (71, 'Prepare SQL')
, (72, 'Exec Prepared SQL')
, (73, 'Unprepare SQL')
, (74, 'CursorExecute')
, (75, 'CursorRecompile')
, (76, 'CursorImplicitConversion')
, (77, 'CursorUnprepare')
, (78, 'CursorClose')
, (79, 'Missing Column Statistics')
, (80, 'Missing Join Predicate')
, (81, 'Server Memory Change')
, (82, 'User Configurable (0-9)')
, (83, 'User Configurable (0-9)')
, (84, 'User Configurable (0-9)')
, (85, 'User Configurable (0-9)')
, (86, 'User Configurable (0-9)')
, (87, 'User Configurable (0-9)')
, (88, 'User Configurable (0-9)')
, (89, 'User Configurable (0-9)')
, (90, 'User Configurable (0-9)')
, (91, 'User Configurable (0-9)')
, (92, 'Data File Auto Grow')
, (93, 'Log File Auto Grow')
, (94, 'Data File Auto Shrink')
, (95, 'Log File Auto Shrink')
, (96, 'Showplan Text')
, (97, 'Showplan All')
, (98, 'Showplan Statistics Profile')
, (99, 'Reserved')
, (100, 'RPC Output Parameter')
, (101, 'Reserved')
, (102, 'Audit Statement GDR Event')
, (103, 'Audit Object GDR Event')
, (104, 'Audit AddLogin Event')
, (105, 'Audit Login GDR Event')
, (106, 'Audit Login Change Property Event')
, (107, 'Audit Login Change Password Event')
, (108, 'Audit Add Login to Server Role Event')
, (109, 'Audit Add DB User Event')
, (110, 'Audit Add Member to DB Role Event')
, (111, 'Audit Add Role Event')
, (112, 'Audit App Role Change Password Event')
, (113, 'Audit Statement Permission Event')
, (114, 'Audit Schema Object Access Event')
, (115, 'Audit Backup/Restore Event')
, (116, 'Audit DBCC Event')
, (117, 'Audit Change Audit Event')
, (118, 'Audit Object Derived Permission Event')
, (119, 'OLEDB Call Event')
, (120, 'OLEDB QueryInterface Event')
, (121, 'OLEDB DataRead Event')
, (122, 'Showplan XML')
, (123, 'SQL:FullTextQuery')
, (124, 'Broker:Conversation')
, (125, 'Deprecation Announcement')
, (126, 'Deprecation Final Support')
, (127, 'Exchange Spill Event')
, (128, 'Audit Database Management Event')
, (129, 'Audit Database Object Management Event')
, (130, 'Audit Database Principal Management Event')
, (131, 'Audit Schema Object Management Event')
, (132, 'Audit Server Principal Impersonation Event')
, (133, 'Audit Database Principal Impersonation Event')
, (134, 'Audit Server Object Take Ownership Event')
, (135, 'Audit Database Object Take Ownership Event')
, (136, 'Broker:Conversation Group')
, (137, 'Blocked Process Report')
, (138, 'Broker:Connection')
, (139, 'Broker:Forwarded Message Sent')
, (140, 'Broker:Forwarded Message Dropped')
, (141, 'Broker:Message Classify')
, (142, 'Broker:Transmission')
, (143, 'Broker:Queue Disabled')
, (144, 'Reserved')
, (145, 'Reserved')
, (146, 'Showplan XML Statistics Profile')
, (148, 'Deadlock Graph')
, (149, 'Broker:Remote Message Acknowledgement')
, (150, 'Trace File Close')
, (151, 'Reserved')
, (152, 'Audit Change Database Owner')
, (153, 'Audit Schema Object Take Ownership Event')
, (154, 'Reserved')
, (155, 'FT:Crawl Started')
, (156, 'FT:Crawl Stopped')
, (157, 'FT:Crawl Aborted')
, (158, 'Audit Broker Conversation')
, (159, 'Audit Broker Login')
, (160, 'Broker:Message Undeliverable')
, (161, 'Broker:Corrupted Message')
, (162, 'User Error Message')
, (163, 'Broker:Activation')
, (164, 'Object:Altered')
, (165, 'Performance statistics')
, (166, 'SQL:StmtRecompile')
, (167, 'Database Mirroring State Change')
, (168, 'Showplan XML For Query Compile')
, (169, 'Showplan All For Query Compile')
, (170, 'Audit Server Scope GDR Event')
, (171, 'Audit Server Object GDR Event')
, (172, 'Audit Database Object GDR Event')
, (173, 'Audit Server Operation Event')
, (175, 'Audit Server Alter Trace Event')
, (176, 'Audit Server Object Management Event')
, (177, 'Audit Server Principal Management Event')
, (178, 'Audit Database Operation Event')
, (180, 'Audit Database Object Access Event')
, (181, 'TM: Begin Tran starting')
, (182, 'TM: Begin Tran completed')
, (183, 'TM: Promote Tran starting')
, (184, 'TM: Promote Tran completed')
, (185, 'TM: Commit Tran starting')
, (186, 'TM: Commit Tran completed')
, (187, 'TM: Rollback Tran starting')
, (188, 'TM: Rollback Tran completed')
, (189, 'Lock:Timeout (timeout > 0)')
, (190, 'Progress Report: Online Index Operation')
, (191, 'TM: Save Tran starting')
, (192, 'TM: Save Tran completed')
, (193, 'Background Job Error')
, (194, 'OLEDB Provider Information')
, (195, 'Mount Tape')
, (196, 'Assembly Load')
, (197, 'Reserved')
, (198, 'XQuery Static Type')
, (199, 'QN: subscription')
, (200, 'QN: parameter table')
, (201, 'QN: template')
, (202, 'QN: dynamics')

Cela a l'air peut-être fastidieux comme ça, mais si vous suivez bien les étapes, ça en vaut la chandelle ;)
Tout cela est d'ailleurs décrit dans le livre référencé dans ma signature (c'est moi qui ait écrit les chapitres sur la maintenance des performances ;))

Tu trouveras les timeout lorsque la colonne Error vaut 2 : c'est l'Abort .NET. Attention, le fait qu'il soit à 2 ET que la durée soit proche ou égale à la durée du timeout montre que c'en est très probablement un.
Si Error vaut 2 mais que la durée d'exécution n'a rien à voir avec un timeout, c'est que l'application l'a annulé en dehors de la condition de timeout (ce qui peut arriver sur annulation d'une opération dans l'UI par exemple).

Si tu as besoin d'un coup de main pour l'analyse, n'hésites pas.

@++ ;)

Bonjour,

Merci pour vos réponses,

Je vais regarder ce que je peux faire dès que l'occasion me sera donnée, ce qui n'est pas évident en ce moment ici. surement entre les midis quand je pourrais.

Il faut juste savoir que je n'ai pas accès au serveur SQL, que je n'accède uniquement à la partie Tables,Vue, procédure etc via l'interface de visual studio 2012, concepteur de requêtes.

Je verrais donc ce que je peux faire.
Plus d'infos prochainement.