Discussion :

[Kropernic]

Hello,

Je faisais un contrôle de routine en passant notamment par les journaux windows et je tombe sur un log venant d'une application que j'ai écrite et qui me dit ceci :

Timeout expired. The timeout period elapsed prior to completion of the operation or the server is not responding.

(daté du 01/06/2014 21:00:33)

Je pars donc en quête de l'explication de ce timeout.

Déjà, chose assez étrange, cela se produit chaque dimanche et jour férié. Perso, j'y vois plus qu'une coïncidence !

Mais je ne trouve rien dans les logs de sql server. De quel côté pourrais-je alors regarder ?

L'application en question en fait une application console .NET lancée via une tache planifiée tous les soirs à 21:00:00. Cette application se trouve sur la même machine que l'instance SQL. Ce n'est donc à priori pas un problème réseau (à moins la demande de connexion passe tout de même par le DNS pour revenir vers la même machine ? J'y connais rien en réseau ).

Cette histoire de dimanche et jours fériés me tracasse. On peut configurer une machine pour ne pas fonctionner certains jours ???

Je suis ouvert à toutes les suggestions !

[Kropernic]

Histoire de tenir informé ceux qui se creuserait éventuellement les méninges, je m'oriente sur la piste d'un backup fait par une société externe qui arrêterait p-e l'instance SQL.

L'horreur quoi !

[Kropernic]

Ce n'est pas le backup en cause. D'ailleurs, il n'y en a pas (pas de la machine mais je fais bien des backups des DB, soyez rassurés ^^).

Je viens de faire tourner la requête en lui passant la date de dimanche... C'est en fait une procédure stockée qui appelle une procédure stockée et cette dernière utilise la date du jour.

Je me disais qu'il y avait p-e un problème avec la 2e procédure quand on est un dimanche (ou un jour férié). Du coup, dans SSMS, j'ai pris le corps de la procédure, copier/coller dans une nouvelle fenêtre, déclarer une variable pour substituer le paramètre et je lui ai assigné la date du 01/06/2014.

Conclusion, résultat en 1 seconde. Bon après, vu que je copie le code, ce n'est pas le même plan qui est utilisé et il y a p-e un problème avec le plan de la procédure...

[dbaffaleuf]

Si version 2008+, utiliser le RING_BUFFER_CONNECTIVITY:

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
SELECT a.* FROM
(SELECT
x.value('(//Record/ConnectivityTraceRecord/RecordType)[1]', 'varchar(30)') AS [RecordType],
x.value('(//Record/ConnectivityTraceRecord/RecordSource)[1]', 'varchar(30)') AS [RecordSource],
x.value('(//Record/ConnectivityTraceRecord/Spid)[1]', 'int') AS [Spid],
x.value('(//Record/ConnectivityTraceRecord/OSError)[1]', 'int') AS [OSError],
x.value('(//Record/ConnectivityTraceRecord/SniConsumerError)[1]', 'int') AS [SniConsumerError],
x.value('(//Record/ConnectivityTraceRecord/State)[1]', 'int') AS [State],
x.value('(//Record/ConnectivityTraceRecord/RecordTime)[1]', 'nvarchar(30)') AS [RecordTime],
x.value('(//Record/ConnectivityTraceRecord/TdsBuffersInformation/TdsInputBufferError)[1]', 'int') AS [TdsInputBufferError],
x.value('(//Record/ConnectivityTraceRecord/TdsBuffersInformation/TdsOutputBufferError)[1]', 'int') AS [TdsOutputBufferError],
x.value('(//Record/ConnectivityTraceRecord/TdsBuffersInformation/TdsInputBufferBytes)[1]', 'int') AS [TdsInputBufferBytes],
x.value('(//Record/ConnectivityTraceRecord/LoginTimers/TotalLoginTimeInMilliseconds)[1]', 'int') AS [TotalLoginTimeInMilliseconds],
x.value('(//Record/ConnectivityTraceRecord/LoginTimers/LoginTaskEnqueuedInMilliseconds)[1]', 'int') AS [LoginTaskEnqueuedInMilliseconds],
x.value('(//Record/ConnectivityTraceRecord/LoginTimers/NetworkWritesInMilliseconds)[1]', 'int') AS [NetworkWritesInMilliseconds],
x.value('(//Record/ConnectivityTraceRecord/LoginTimers/NetworkReadsInMilliseconds)[1]', 'int') AS [NetworkReadsInMilliseconds],
x.value('(//Record/ConnectivityTraceRecord/LoginTimers/SslProcessingInMilliseconds)[1]', 'int') AS [SslProcessingInMilliseconds],
x.value('(//Record/ConnectivityTraceRecord/LoginTimers/SspiProcessingInMilliseconds)[1]', 'int') AS [SspiProcessingInMilliseconds],
x.value('(//Record/ConnectivityTraceRecord/LoginTimers/LoginTriggerAndResourceGovernorProcessingInMilliseconds)[1]', 'int') AS [LoginTriggerAndResourceGovernorProcessingInMilliseconds]
FROM (SELECT CAST (record as xml) FROM sys.dm_os_ring_buffers
WHERE ring_buffer_type = 'RING_BUFFER_CONNECTIVITY') AS R(x)) a
where a.RecordType = 'LoginTimers'
order by a.recordtime

[Kropernic]

Hello,

Je reviens sur le sujet. Ce problème était passé à la trappe pour cause d'autres problématiques plus urgentes à traiter.

Deux jour d'affilée (avant-hier et hier soir), vers 21:00:30, de nouveau le timeout expired. Le même que celui du message initial et à la même heure (c'est en fait l'heure à laquelle démarre la tache planifiée).

Je sais que le timeout standard est de 30 secondes lors de l'appel d'une procédure stockée depuis une application .NET. Le symptôme est bien identifiée. Ne reste plus qu'à en trouver la cause.

Je viens de faire tourner la requête proposée par dbaffaleuf mais je ne sais pas trop sur quoi je dois focaliser mon attention dans son résultat. Résultat que vous pouvez trouver dans le fichier en pièce jointe.

Je pourrais augmenter le timeout à plus de 30 secondes mais ce serait masqué le symptôme et non pas traiter la cause. Jusqu'ici, ce problème avait tendance à ne survenir que les dimanches et jours fériés (j'ignore totalement pourquoi). C'est la première fois que je constate qu'il a lieu durant la semaine.

J'espère que quelqu'un aura une idée pour m'aiguiller sur la bonne voie. J'ai épuisé toutes mes cartouches et ne sais plus où regarder.

[Invité]

Machine virtuelle ? VMWhare ? Sauvegarde niveau VM qui locke ponctuellement les fichiers de données ?

[dbaffaleuf]

Je viens de faire tourner la requête proposée par dbaffaleuf mais je ne sais pas trop sur quoi je dois focaliser mon attention dans son résultat. Résultat que vous pouvez trouver dans le fichier en pièce jointe.

Il y a eu des timeouts sur la période couverte par les résultats ?
(10/9/2014 13:36:17.105 => 10/10/2014 9:18:23.168)

Le temps de connexion le plus long est 66ms.

en PJ la sortie reformattée en xlsx : Book1.xlsx