Please start any new threads on our new site at https://forums.sqlteam.com. We've got lots of great SQL Server experts to answer whatever question you can come up with.

 All Forums
 SQL Server 2008 Forums
 Other SQL Server 2008 Topics
 Column.Write Timeout when length changes

Author  Topic 

sTumpF
Starting Member

6 Posts
Posted - 2014-11-14 : 11:16:23
Hello I have an application which streams files in a database.
The application is written in c# and uses System.Data.SqlClient.SqlCommand to write the filedata in parts of 1024 bytes.
The query used for this is:

UPDATE [File] SET FileData.WRITE(@Bytes,@Index,@Length), FileDBImportProgress=@Progress WHERE FileId = @Id

Here is the code for the function:

private static bool WriteFileDataToDb(Guid fileid, string filename, System.IO.Stream stream, long length)
        {
            bool success = true;               
 
            using (System.Data.SqlClient.SqlConnection connection = new System.Data.SqlClient.SqlConnection(Config.ConnectionString))
            {
                SqlCommand command = null;
 
                try
                {                    
                    connection.Open();                    
 
                    command = connection.CreateCommand();
                    command.CommandTimeout = Config.SQLTimeout;
                    command.CommandText = "UPDATE [File] SET FileData.WRITE(@Bytes,@Index,@Length) WHERE FileId = @Id";
 
                    SqlParameter param_bytes = command.CreateParameter();
                    SqlParameter param_index = command.CreateParameter();
                    SqlParameter param_length = command.CreateParameter();
                    SqlParameter param_id = command.CreateParameter();
                    
                    param_bytes.DbType = DbType.Binary;
                    param_bytes.ParameterName = "@Bytes";
                    param_index.ParameterName = "@Index";
                    param_length.ParameterName = "@Length";
                    param_id.ParameterName = "@Id";                    
 
                    command.Parameters.Add(param_bytes);
                    command.Parameters.Add(param_index);
                    command.Parameters.Add(param_length);
                    command.Parameters.Add(param_id);
                    
                    int bufflength = 1024;
                    int index = 0;                    
                    byte[] buff = new byte[bufflength];
                                        
                    using (System.IO.BinaryReader br = new System.IO.BinaryReader(stream, Encoding.GetEncoding(Config.Encode)))
                    {
                        param_id.Value = fileid;
 
                        int offset = 0;
 
                        while ((buff = br.ReadBytes(buff.Length)).Length > 0)
                        {
                            offset = index * bufflength;
 
                            param_bytes.Value = buff;
                            param_index.Value = index * bufflength;
                            param_length.Value = buff.Length;
 
                            try
                            {                                
                                command.ExecuteNonQuery();                                
                            }                          
                            catch (Exception ex)
                            {
                                var msg = ex.Message;
                                var stack = ex.StackTrace;
                                success = false;
                                break;
                            }
                            index++;
                        }
                    }                    
                }
                catch (Exception ex)
                {                   
                    success = false;
                }
                finally
                {
                    if (command != null)
                        command.Dispose();
                    if (connection.State == ConnectionState.Open)
                        connection.Close();
                    if (connection != null)
                        connection.Dispose();
                }
            }
            return success;            
        }


Everything works fine just the last call of ExecuteNonQuery causes a timeout (when disable timeout the query tooks 2 minutes or longer).
The only thing that changes is that at the end the data to write is shorter than 1024 bytes.
When appending 0's, so the data has the length 1024, it works.
Here is the profile of the last write for a simple image with size of 87KB:

quote:

<Event id="10" name="RPC:Completed">
<Column id="11" name="LoginName">ThatsMyName</Column>
<Column id="15" name="EndTime">2014-11-14T16:56:02.417+01:00</Column>
<Column id="12" name="SPID">55</Column>
<Column id="16" name="Reads">30999954</Column>
<Column id="1" name="TextData">exec sp_executesql N'UPDATE [File] SET FileData.WRITE(@Bytes,@Index,@Length), FileDBImportProgress=@Progress WHERE FileId = @Id',N'@Bytes varbinary(532),@Index int,@Length int,@Id uniqueidentifier,@Progress int',@Bytes=0x5001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145007FFD9,@Index=88064,@Length=532,@Id='CE0A63DD-4BC9-4B89-8FCE-9ED10C82F551',@Progress=99</Column>
<Column id="9" name="ClientProcessID">4888</Column>
<Column id="13" name="Duration">124121443</Column>
<Column id="17" name="Writes">992494</Column>
<Column id="2" name="BinaryData">00000000080000001A00730070005F006500780065006300750074006500730071006C00FC00000082001A00E7206E00760061007200630068006100720028003100300036002900D400000055005000440041005400450020005B00460069006C0065005D0020005300450054002000460069006C00650044006100740061002E005700520049005400450028004000420079007400650073002C00400049006E006400650078002C0040004C0065006E0067007400680029002C002000460069006C0065004400420049006D0070006F0072007400500072006F00670072006500730073003D004000500072006F00670072006500730073002000570048004500520045002000460069006C0065004900640020003D002000400049006400C400000082001800E7206E00760061007200630068006100720028003700390029009E0000004000420079007400650073002000760061007200620069006E00610072007900280035003300320029002C00400049006E00640065007800200069006E0074002C0040004C0065006E00670074006800200069006E0074002C00400049006400200075006E0069007100750065006900640065006E007400690066006900650072002C004000500072006F0067007200650073007300200069006E0074004C02000080001C00A530760061007200620069006E00610072007900280035003300320029000C00400042007900740065007300140200005001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145001451450014514500145145007FFD92200000003000600381069006E0074000C00400049006E00640065007800005801002400000003000600381069006E0074000E0040004C0065006E00670074006800140200004200000048002000241075006E0069007100750065006900640065006E007400690066006900650072000600400049006400DD630ACEC94B894B8FCE9ED10C82F5512800000003000600381069006E00740012004000500072006F0067007200650073007300630000001400000003000600380469006E00740000000000</Column>
<Column id="6" name="NTUserName">ThatsMyName</Column>
<Column id="10" name="ApplicationName">.Net SqlClient Data Provider</Column>
<Column id="14" name="StartTime">2014-11-14T16:53:58.297+01:00</Column>
<Column id="18" name="CPU">25631</Column>
</Event>


Can this be a setting of the database?
Because when using a fresh database the problem does not occur, just in my working database which has lots of files (~3GB).
Both databases are created automatically, so there should be no difference.

The PK is FileId (uniqueidentifier) and is the only index.
The table has no trigger.

I'm working on this problem for days and really have no clue what could be causing this.

Does anyone have an idea?

Kind regards

sTumpF
Starting Member

6 Posts
Posted - 2014-11-17 : 06:23:56
Now i can reproduce the error in the new created database.
So the error occurs when at least some files are in the table.
The earliest error I could reproduce when ~1GB was streamed into the table.
Also I recognized that when the file is inserted I can stream it without problems again, the error occurs only the first time a file is streamed. The error then only occurs again for this file after a reboot.

I could make a sample to demonstrate the problem if it would be helpfull to reproduce the beahvior.
I still hope that there is someone who could help me with this, because I'm really clueless right now.
Go to Top of Page

tkizer
Almighty SQL Goddess

38200 Posts
Posted - 2014-11-17 : 12:38:22
Sounds like a concurrency issue. Since you can now reproduce it, check sp_lock on the session that is running the update to see what locks it is using. Also check what it is blocking (select * from master..sysprocesses where blocked <> 0).

Tara Kizer
SQL Server MVP since 2007
http://weblogs.sqlteam.com/tarad/
Go to Top of Page

sTumpF
Starting Member

6 Posts
Posted - 2014-11-18 : 07:26:49
Hello Tara,

thanks for the hint.
This is the result of sp_lock:

quote:


52 21 0 0 DB S GRANT
52 21 0 0 DB [PLANGUIDE] S GRANT
52 21 2121058592 0 TAB Sch-S GRANT
52 21 2105058535 0 TAB Sch-S GRANT
52 21 2105058535 0 TAB Sch-S GRANT
52 21 2105058535 0 TAB [UPDSTATS] X GRANT
52 21 0 0 MD 1(7d78a4e7:2:0) Sch-S GRANT
52 21 0 0 MD 2(7d78a4e7:2:0) Sch-S GRANT
52 21 0 0 MD 1(7d78a4e7:1:0) Sch-S GRANT
52 21 0 0 MD 1(7d78a4e7:1:0) Sch-S GRANT
53 21 0 0 DB S GRANT
54 21 0 0 DB S GRANT



I selected only the results of the corresponding Table (21).
Object 2121058592 is PK_File and 2105058535 is File.
select * from master..sysprocesses where blocked <> 0 returns nothing.
Go to Top of Page

sTumpF
Starting Member

6 Posts
Posted - 2014-11-18 : 09:07:52
Here is the script for the table:



USE [Your database here]
GO
 
/****** Object: Table [dbo].[File] Script Date: 11/11/2014 21:07:42 ******/
SET ANSI_NULLS ON
GO
 
SET QUOTED_IDENTIFIER ON
GO
 
SET ANSI_PADDING ON
GO
 
CREATE TABLE [dbo].[File](
[FileId] [uniqueidentifier] ROWGUIDCOL NOT NULL,
[FileName] [nvarchar](max) NULL,
[FileData] [varbinary](max) NULL,
[FileThumbnail] [varbinary](max) NULL,
[FileCreated] [datetime] NULL,
[FileLastEdit] [datetime] NULL,
[FileReadyForUse] [bit] NULL,
[FileType] [int] NULL,
[FileTags] [nvarchar](255) NULL,
[FileSize] [bigint] NULL,
[FileDuration] [float] NULL,
[FileSizeX] [int] NULL,
[FileSizeY] [int] NULL,
[FileError] [nvarchar](max) NULL,
[FileDBImportProgress] [int] NULL,
[FileConvertionProgress] [int] NULL,
CONSTRAINT [PK_File] PRIMARY KEY CLUSTERED
(
[FileId] ASC
)WITH (PAD_INDEX = OFF, STATISTICS_NORECOMPUTE = OFF, IGNORE_DUP_KEY = OFF, ALLOW_ROW_LOCKS = ON, ALLOW_PAGE_LOCKS = ON) ON [PRIMARY]
) ON [PRIMARY]
 
GO
 
SET ANSI_PADDING OFF
GO



The error is definitely on sql side.
I waited for the next timeout, copied query from SQL Server Profiler and ran the query from Sql Management Studio.
This time I used the recommended buffersize of 8040. (http://msdn.microsoft.com/en-us/library/ms177523%28v=sql.105%29.aspx)
It took 02:20 minutes for a simple Html file (1,83KB).
In the Server Profiler I get 1.566.049 Writes and 48.401.388 Reads, thats a lot of operations.
Go to Top of Page

sTumpF
Starting Member

6 Posts
Posted - 2014-11-18 : 09:58:04
Thanks to Tara I was able to find the reason for this behavior or at least a workaround to avoid it.
The root of this behavior seems to be a bug in the auto_update_statistics option (https://connect.microsoft.com/SQLServer/feedback/details/174619/update-statistics-holding-exclusive-lock-and-blocking).
After disabling the option for this table I could not reproduce the error.

Thank you very much.
Go to Top of Page

gbritton
Master Smack Fu Yak Hacker

2780 Posts
Posted - 2014-11-18 : 10:42:55
That's a Sql Server 2005 issue, I think. Are you running 2005 or 2008 as per the forum?
Go to Top of Page

sTumpF
Starting Member

6 Posts
Posted - 2014-11-18 : 11:07:52
It seems to be a problem on 2008 R2, too.
At least disabling the auto update statistics solved the problem.
I'm running on 2008 R2.
Go to Top of Page
   

Subscribe to SQLTeam.com

SQLTeam.com Articles via RSS

SQLTeam.com Weblog via RSS

- Advertisement -

Resources

Articles

Forums

Blogs

Contact Us

About the Site