Timeout lors de l'exécution d'une procédure stockée [Résolu]

[duffman]

Bonjour

Aujourd'hui lors d'un process en production, j'ai rencontre un probleme que nous n'avions jamais eu auparavant.

Un web service est appele pour metter a jour certaines donnees dans une bdd.

voila un pseudo code:

Code :

1
2
3
4
5
6
7
8
9
10
 
reader = execute(sp1)
 
while (reader.READ())
 
//get current row detail 
//CREATE parameters
execute(sp2, params)
 
end while

c'est donc assez basique.

Et donc voila le probleme, l'execution de sp2 (qui n'est rien d'autre qu'un simple update en SQL) a commence a renvoyer l'exception suivante:

System.Data.SqlClient.SqlException (0x80131904): Timeout expired. The timeout period elapsed prior to completion of the operation or the server is not responding.
at System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection)
at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning()
at System.Data.SqlClient.TdsParser.Run(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj)
at System.Data.SqlClient.SqlCommand.FinishExecuteReader(SqlDataReader ds, RunBehavior runBehavior, String resetOptionsString)
at System.Data.SqlClient.SqlCommand.RunExecuteReaderTds(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, Boolean async)
at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method, DbAsyncResult result)
at System.Data.SqlClient.SqlCommand.InternalExecuteNonQuery(DbAsyncResult result, String methodName, Boolean sendToPipe)
at System.Data.SqlClient.SqlCommand.ExecuteNonQuery()

Le probleme a ete reproduit systematiquement, pour la meme ligne de la table mise a jour, une bonne quinzaine de fois d'affile.

Apres avoir modifie le code vite fait pour "sauter" cette ligne, tout le reste de la table a ete mise a jour avec succes.

Ma question est la suivante:

Y'a-t-il quoique ce soit d'autre qu'un lock sur cette ligne qui pourrait causer ce probleme ?

Merci

Edit
Je precise un peu les environnements :

- SQL server 2008
- IIS 7
- Web service asp.net "classique" (pas WCF quoi)
- ADO.NET pour tout ce qui est connection/execution des commandes SQL
- .NET 4 pour le runtime

c'est a peu pres tout je crois

Ce message a peut-etre davantage sa place sur le forum SQL-server je ne sais pas...

[sofienems]

il nous faudra le code SQL de mise à jour . Je pense que le plantage est là .
regarde par la meme occasion s'il y a des trigger sur la table

[Bluedeep]

Bonjour

Tu peux toujours augmenter le CommandTimeOut dans l'objet commande.

Sinon, un truc m'interpelle quand même à la lecture de ton pseudo-code : pourquoi as tu un code qui apelle une prco stoc et en fonction du retour rapelle une autre proc stoc sur les données retournées ? il y a une raison précise pour que l'ensemble du traitement ne soit pas confié au SGBD et fasse des allez-retour de données vers le web service ?

En dehors de cela, la question relève plus de Sql Server que de C#.

Vous avez utilisé le Profiler pour voir les requêtes au sein des PS qui prennent du temps ?

[duffman]

Envoyé par sofienems

il nous faudra le code SQL de mise à jour . Je pense que le plantage est là .
regarde par la meme occasion s'il y a des trigger sur la table

le code SQL de mise a jour est simple comme bonjour:

Code :

1
2
3
4
5
6
7
8
9
10
11
12
procedure [dbo].[sp_UpdatePaymentDairyAfterUserDocUpdateForCredit]
@Diary_ID varchar(20)=NULL,
@Payee_Account_Location varchar(10)=NULL,
@Payee_Account_Number varchar(10)=NULL
AS
Begin
 
	UPDATE Payment_Diary SET  
    Payee_Account_Location = @Payee_Account_Location  ,
    Payee_Account_Number =@Payee_Account_Number
    WHERE ID=@Diary_ID
End

Je precise avant toute remarque concernant le nommage de la procedure que j'ai herite de ce projet en mode support uniquement, et que bah... y'a du boulot quoi

enfin bref, c'est donc un update ultra con.
Je reprecise ce qui s'est passe:
- cette procedure n'a a ma connaissance jamais plante auparavant.

- hier elle m'a sorti un timeout 15 fois d'affille sur la meme ligne (time out etait de 30 sec par defaut, pousse a 4 min, meme constat, j'ai le sentiment que j'aurais pu mettre 1h ca aurait ete pareil)

- Un restart du server SQL n'a pas resolu le probleme

- pas de trigger sur la table, ni d'index, et le champ ID n'est meme pas defini comme cle primaire (oui nous avons egalement herite de bases de donnees en ruine)

voila tout ca reunis je me dis que ca ne peut venir que d'un lock qui se serait glisse je ne sais encore comment, mais j'aimerais elimine toute autre possibilite.
Qu'en pensez-vous? cela peut-il venir d'autre chose que d'un rowlock ?

et au passage, un restart du server SQL n'est pas sense retirer tous les locks existants ?

Merci

[duffman]

Envoyé par Bluedeep

Bonjour

Tu peux toujours augmenter le CommandTimeOut dans l'objet commande.

Sinon, un truc m'interpelle quand même à la lecture de ton pseudo-code : pourquoi as tu un code qui apelle une prco stoc et en fonction du retour rapelle une autre proc stoc sur les données retournées ? il y a une raison précise pour que l'ensemble du traitement ne soit pas confié au SGBD et fasse des allez-retour de données vers le web service ?

En dehors de cela, la question relève plus de Sql Server que de C#.

Vous avez utilisé le Profiler pour voir les requêtes au sein des PS qui prennent du temps ?

La principale raison est que ca a ete code n'importe comment

Oui pour profiler et la requete qui plante coute cacahuete en resource comme le code peut le laisser penser.

[Waldar]

Envoyé par duffman

le champ ID n'est meme pas defini comme cle primaire (oui nous avons egalement herite de bases de donnees en ruine)

voila tout ca reunis je me dis que ca ne peut venir que d'un lock qui se serait glisse je ne sais encore comment, mais j'aimerais elimine toute autre possibilite.
Qu'en pensez-vous? cela peut-il venir d'autre chose que d'un rowlock ?

Combien y a-t-il de lignes dans votre table Payment_Diary ?

[duffman]

bonjour

la table contient 39000 lignes environ.

voila le code de la table en question:

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
 
 
/****** Object:  Table [dbo].[Payment_Diary]    Script Date: 02/03/2012 10:41:21 ******/
SET ANSI_NULLS ON
GO
 
SET QUOTED_IDENTIFIER ON
GO
 
SET ANSI_PADDING ON
GO
 
CREATE TABLE [dbo].[Payment_Diary](
	[ID] [int] IDENTITY(1,1) NOT NULL,
	[Amount] [money] NULL,
	[Document_ID] [int] NULL,
	[Document_Reference] [varchar](50) NULL,
	[Interchange_ID] [varchar](50) NULL,
	[Payee_Account_Location] [varchar](50) NULL,
	[Payee_Account_Name] [varchar](50) NULL,
	[Payee_Account_Number] [varchar](50) NULL,
	[Payer_Account_Location] [varchar](50) NULL,
	[Payer_Account_Name] [varchar](50) NULL,
	[Payer_Account_Number] [varchar](50) NULL,
	[Payer_UserId] [varchar](14) NULL,
	[Payment_Date] [datetime] NULL,
	[Status_Date] [datetime] NULL,
	[Status_Flag] [int] NULL,
	[Stamp] [datetime] NULL,
	[User_ID] [int] NULL,
	[EmployerID] [int] NULL,
	[SS_User_Document_ID] [int] NULL,
	[Channel_Code] [varchar](50) NULL,
	[Payer_Method_Flag] [char](10) NULL,
	[Credit_Interval] [int] NULL,
	[Payee_ABN] [varchar](14) NULL,
	[Payee_Name] [varchar](50) NULL,
	[Payee_Bank_Account_Flag] [char](1) NULL,
	[Product_ID] [int] NULL,
	[Product_Code] [varchar](50) NULL,
	[Debit_Interval] [int] NULL
) ON [PRIMARY]
 
GO
 
SET ANSI_PADDING OFF
GO

[Waldar]

Rajoutez une clef primaire sur la colonne ID, vous devriez noter une très nette amélioration !

[duffman]

Envoyé par Waldar

Rajoutez une clef primaire sur la colonne ID, vous devriez noter une très nette amélioration !

Merci pour cette suggestion, que l'on devrait pouvoir mettre en place.

Toutefois je cherche encore a comprendre ce qui a pu provoquer ce fameux timeout (de maniere consistante sur la meme ligne de la table).

J'ai vais essayer de mettre un lock sur une ligne dans notre env de test et de voir si je peux reproduire le meme message comme ca.
Toute piste est la bienvenue.

[duffman]

Bon je n'ai as l'explication mais d'apres diverses recherches, un probleme lie a un rowlock m'aurait renvoyer une erreur differente et MSDN ne mentionne pas le lock comme possible cause de l'erreur TimeOut expired.

Je vais mettre une cle primaire et un index, et prier.

Merci

[Bluedeep]

Envoyé par duffman

Bon je n'ai as l'explication mais d'apres diverses recherches, un probleme lie a un rowlock m'aurait renvoyer une erreur differente et MSDN ne mentionne pas le lock comme possible cause de l'erreur TimeOut expired.
Je vais mettre une cle primaire et un index, et prier.

Pour tester ce genre de truc, tu peux toujours utiliser dans ts PS de lecture (temporairement bien sur !!!!) la commande :

Code :

 SET TRANSACTION ISOLATION-LEVEL READ UNCOMMITTED

et voir si le problème persiste. Si il disparait, c'est que c'est un rowlock.

Contrairement à ce que tu dis, un timeout sur un rowlock est tout à fait habituel.

[duffman]

Desole de faire remonter ce vieux sujet mais je n'avais jamais trouve le fin mot de l'histoire.

Hier le probleme s'est produit de nouveau, sur la meme table mais une ligne et une requete differente.

On a pu observe les points suivants:

- la requete (un bete select avec une jointure basique) retourne un timeout apres 90 sec (uniquement lorsqu'appelle depuis le code C# )

- la meme requete (exactement la meme), executee depuis SQL studio retourne le resultat en 0:00 sec

- cette requete n'a jamais eu de probleme de performance auparavant. Ce n'est pas comme si elle etait passe de 85 sec pour s'executer a 90 sec, c'est passe de rien a time out du jour au lendemain.

La mise en place d'un index a resolu le probleme instantanement.

Alors je sais que les voies de SQL sont impenetrables et qu'un tas de trucs bizarre peuvent arriver, mais pour qu'une requete donne un timeout apres 1min30 dans un cas et renvoit le resultat instantanement dans l'autre, faut m'expliquer...

Ma theorie c'est que les query dans SQL Studio sont optimisees d'une maniere ou d'une autre, que les appels depuis ADO.NET ne le sont pas...

[Waldar]

Je n'avais pas fait attention à la première lecture mais vous avez un problème avec le typages de vos données.

Dans votre table :

ID int
Payee_Account_Location varchar(50)
Payee_Account_Number varchar(50)

Dans votre procédure stockée :

@Diary_ID varchar(20)
@Payee_Account_Location varchar(10)
@Payee_Account_Number varchar(10)

Il faut modifier cette dernière afin qu'elle utilise les mêmes types que dans la table, surtout sur la colonne ID sinon vous allez au devant des ennuis.
Pour les chaînes de caractères plus courtes c'est moins grave, un varchar(10) rentrera toujours dans un varchar(50), mais autant faire propre.

Quant à l'exécution de votre select, y a-t-il des variables concernées ?
Si vous pouvez reproduire le problème a volo, je vous conseille de lancer une trace avec le profiler afin de vérifier que la requête que vous pensez être la même soit réellement la même.

[duffman]

Merci Waldar

Effectivement, cette erreur ne doit pas aider la bdd a fonctionner correctement...

Lorsque le probleme est reapparu la semaine derniere, c'etait sur une autre procedure stockee, qui n'a pas de parametre ID. Nous avions utilise le profiler et la requete executee depuis le studio etait un copier coller de celle que le profiler loggait et affichait comme prenant 90 sec avec un timeout, donc c'est vraiment exactement le meme code qui fonctionne depuis le studio et pas depuis .NET.

Je pense toujours que le Studio possede un petit niveau d'optimisation ou qqch comme ca qui expliquerait ce comportement.

[SQLpro]

Effectivement oui, c'est souvent un problème de parameter sniffing. Lire l'article de mon confrère au nom imprononçable :
http://blog.developpez.com/sqlpro/p9...s-de-requetes/

A +

[duffman]

Merci pour ce super article, cette fois ci le post est resolu.