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 ?

[Kropernic]

Non, non et non ^^.

C'est un serveur avec ses propres disques à lui.

J'ai déjà parcouru les différents journaux d'évènement mais je n'ai à priori rien trouver de suspect (ou alors je l'ai vu sans savoir que c'est suspect ).

C'est du 2008R2 edition standard.

[Kropernic]

Et hier soir, toujours à 21h (comme tous les soirs), la tâche s'est déroulé sans aucun problème et donc sans aucun timeout...

[elsuket]

Bonjour,

Vous pouvez prendre une trace SQL Profiler un démarrer une session d’évènements étendus pour capturer toute requête dont la durée excède, disons 20 secondes, ce qui est déjà très long.
Vous trouverez des exemples presque tout faits pour votre problème à partir d'ici.
Pour les évènements étendus, c'est dans la page, pour SQL Profiler, il suffit de suivre le lien

Dites-nous ce que vous avez trouvé !

@++

[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

[Kropernic]

Salut à tous.

Sorry pour le déterrage de topic mais y avait de nouveau plus urgent à faire que ce problème-ci.

Le timeout est à nouveau survenu hier soir.

J'ai fait tourné la requête de dbaffaleuf mais je ne reçoit qu'une seule ligne alors que j'en avais 112 la dernière fois. Ca me semble bizarre... (mais vu que j'ai pas trop compris la requête, c'est p-e normal)

Sinon, je vais tenter le profiler comme suggéré par elsuket. J'ai déjà vu le profiler en formation avec sqlpro mais pas encore utiliser depuis.

C'est l'occasion de mettre cela en pratique. Par contre j'imagine que cela veut dire que je vais devoir attendre le timeout suivant pour avoir plus d'infos. Correct ??

[mikedavem]

Tu peux également utiliser les XE avec une cible de type pair_matching pour cela si jamais.

++

[Kropernic]

Hello,

Me voilà de retour de vacance.

Je lance la requête de dépouillement des événements étendus et j'obtiens mon résultat.

Je vais ensuite regarder quand j'ai eu mon dernier problème (en l’occurrence le 1e janvier) et, ôh désespoir, le n'ai rien le 1e janvier à 21h dans le résultat du dépouillement...

Si je comprends bien ce que cela implique, cela voudrait donc dire que le problème n'est pas que la requête prend trop de temps à s'exécuter mais que la connexion à la DB ne se fait carrément pas (en tout cas, la requête ne se lance même pas à priori).

Mon analyse est-elle correcte selon vous ???

Quel événement faudrait-il surveiller pour en avoir la confirmation ??

[Kropernic]

Hello,

Ce sujet ne passionne décidément pas les foules ^^.

Sinon, nouveau time-out ce dimanche. Je m'étais dit qu'il y avait p-e un maintenance sur les firewall le dimanche pile dans la timeframe que j'utilise et du coup, j'avais remplacé le nom du serveur par localhost dans la connectionstring de l'applicatif qui pose problème mais cela n'a apparemment servi à rien.

Ca aurait tendance à m'orienter vers une cause interne à mon serveur sur lequel se trouve la DB et cette fameuse tâche planifiée...

Si jamais quelqu'un avait une idée lumineuse, cela m'arrangerait car je sèche là

[mikedavem]

Yop,

Si le sujet est intéressant ... juste un manque de temps

Tu as déjà essayer d'effectuer un DBCC OPENTRAN sur ton serveur SQL après ton timeout histoire de voir que tu n'as pas une transaction restée ouverte après ton timeout ?

++

[Kropernic]

Hello,

Le timeout se produit lorsque la tâche planifiée se lance, cad à 21h et en général, le dimanche (ou les jours fériés).

Du coup, je ne suis pas présent pour faire un dbcc opentran...

Et le pire, c'est qu'on ne trouve absolument rien dans les logs... Je ne sais vraiment plus où chercher...

[SQLpro]

Enregistre le contenu de DBCC OPENTRAN WITH TABLERESULTS dans une table toutes les 20 secondes

le contenu est généralement le suivant :

Code :

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

1
2
3
4
5
6
7
8
9
10
 
DB_LOCK : VARCHAR(128)        OPENTRAN : VARCHAR(256)
----------------------------- ----------------------------------------------
OLDACT_SPID                   65
OLDACT_UID                    -1
OLDACT_NAME                   user_transaction
OLDACT_RECOVERYUNITID         0
OLDACT_LSN                    (63:252:2)
OLDACT_STARTTIME              janv 20 2015 11:44:09:007PM
OLDACT_SID                    0x0105000000000005150000005b65512235aa4c6b6999

A +

[Kropernic]

Hello,

Je viens de mettre en place un job pour enregistrer le résultat de dbcc opentran toutes les 20 secs sur la db concernée.

Rendez-vous au prochain plantage pour voir ce qu'il en ressort ^^.

[Kropernic]

Hello,

Le problème est à nouveau survenir hier soir.

Je viens d'aller voir dans la table qui stock le résultat des dbcc opentran et elle est vide...

J'ai également fait le dépouillement de l'évènement étendu suggéré par elsuket et la seule ligne qui pourrait coller d'un point de vu chronologique est celle-ci :

database_name	time_stamp	appname	hostname	username	query	CPU	duration	reads	writes
XXXXXXXX	2015-02-16 20:59:36.150	.Net SqlClient Data Provider	XXXXXXXXXX	XXXXXXX	Unable to retrieve SQL text	29500	29542336	38784771	71

Mais je ne peux en être sûr vu qu'il ne parvient à récupérer la requête.

Any idea ?

[Kropernic]

Rebelote hier soir.

Toujours rien d'autre dans le journal d'évènement qu'un "Timeout expired". Ca ne dit même pas si c'est la connexion ou la requête qui est en timeout...

En prime, dans la session d'évènement étendu, je n'ai pas de requête hier soir vers 21h.

Un truc que j'ignore toujours... Lorsque je lance une requête via une application .NET (en laissant le timeout par défaut (30 secondes)) et que cette requête met plus de 30 secondes à répondre, une exception est levée dans l'application mais que se passe-t-il côté sql server ?
Est-ce que :

1. La requête continue est les résultats sont renvoyés dans le vent
2. La requête "reçoit" une erreur et l'éventuelle transaction subit un rollback
3. La requête est annulée
4. Autre

Si c'est le cas 2 ou 3, la requête apparaît-elle alors dans les événements étendu ?

Je regarde également dans les logs SQL Server et là, je n'ai rien du tout hier soir à 21h. Même pas une connexion (mais j'ai l'impression que seule les échecs de connexion sont repris dans les logs).

Please HELP !