Slow SqlCommand performance with longer CommandText

Question

Does the length of the CommandText of an SqlCommand make a difference? I'm not talking about thousands of characters either. Here's what I have:

SqlCommand cmd = new SqlCommand();
cmd.Connection = conn;
cmd.CommandText = sql;

for (int i=0; i<1000; ++i)
{
    string name = i.ToString() + "Bob" + i.ToString();
    string email = i.ToString() + "Jim" + i.ToString();
    // etc...

    cmd.Parameters.Clear();
    cmd.Parameters.Add(new SqlParameter("@name", name));
    cmd.Parameters.Add(new SqlParameter("@country", country));

    DateTime cmdStart = DateTime.Now;
    cmd.ExecuteNonQuery();
    DateTime cmdEnd = DateTime.Now;
    TimeSpan len = cmdEnd - cmdStart;
}

If I use the following sql, the first iteration takes .5 seconds. The second takes 1.1 seconds. The third takes 3.3 seconds. And so on until it just throws for a timeout.

string sql =
    "INSERT INTO Test " +
    "           ([name] " +
    "           ,[email] " +
    "           ,[country] " +
    "           ,[comment] " +
    "           ,[date] " +
    "           ,[key_v0] " +
    "           ,[key_v1] " +
    "           ,[expires_v1] " +
    "           ,[expires_v2] " +
    "           ) " +
    "     VALUES " +
    "           (@name " +
    "           ,@email " +
    "           ,@country " +
    "           ,' ' " +
    "           ,@date " +
    "           ,@key_v0 " +
    "           ,@key_v1 " +
    "           ,@expires_v1 " +
    "           ,@expires_v2 " +
    "           )";

However, if I use the following sql, the entire loop is executed in under a second.

string sql =
    "INSERT INTO Test " +
    "([name] " +
    ",[email] " +
    ",[country] " +
    ",[comment] " +
    ",[date] " +
    ",[key_v0] " +
    ",[key_v1] " +
    ",[expires_v1] " +
    ",[expires_v2] " +
    ") " +
    "VALUES " +
    "(@name " +
    ",@email " +
    ",@country " +
    ",' ' " +
    ",@date " +
    ",@key_v0 " +
    ",@key_v1 " +
    ",@expires_v1 " +
    ",@expires_v2 " +
    ")";

The only difference is the whitespace. Removing the whitespace brought the total character count from 428 to 203. I have been unable to locate anything referencing the length of CommandText except references to 4k and 8k limits. I'm nowhere near that.

I have run both versions with the profiler running and it the duration is under 10ms for all calls. The delay seems to be happening from when the command is complete inside the SQL engine until ExecuteNonQuery returns.

I know that there are alternative ways to do this. I'm not asking about better ways to do this. I'm asking about the source of the slowdown.

UPDATE: As a test, I added spaces to the end of the query. As soon as I got above 400ish characters total, it slowed down. Interestingly, at 414 characters, the first 99 inserts are fast. At 415 characters, the first 9 inserts are fast. Since I am changing some of the strings based on the iteration number, this kinda makes sense. e.g. The 10th insert is a little longer than the 9th and the 100th insert is a little longer than the 99th.

While I kinda understand that longer inserts should take longer, I can't understand the clear division between fast and slow and the sheer magnitude of the difference. I also don't understand why the time taken increases.

UPDATE 2: (Additional information in response to Peter Oehlert's answer): The entire database is clean. There are no other tables and the test table is dropped and recreated for each run. There are no indexes, triggers or foreign keys. There is an 'id' column that is a primary key.

This is code pulled from a console app written specifically to troubleshoot this problem. It only includes the necessary code to repro this behavior.

(Aditional profiler information): When running the SQL profiler, there is a column called TextData that shows what the command and data are. An example is this:

exec sp_executesql N'INSERT INTO Test ([name] ,[email] ,[country] ,[comment] ,[date] ,[key_v0] ,[key_v1] ,[expires_v1] ,[expires_v2] ) VALUES (@name ,@email ,@country ,'' '' ,@date ,@key_v0 ,@key_v1 ,@expires_v1 ,@expires_v2 )                                                                                                                                                                                                                          ',N'@name nvarchar(4),@country nvarchar(2),@email nvarchar(3),@date datetime,@key_v0 nvarchar(4000),@key_v1 nvarchar(4000),@expires_v1 datetime,@expires_v2 datetime',@name=N'9Bob',@country=N'us',@email=N'Jim',@date='2009-08-28 15:35:36.5770000',@key_v0=N'',@key_v1=N'',@expires_v1='2009-08-28 15:35:36.5770000',@expires_v2='2009-08-28 15:35:36.5770000'

That line is 796 characters long and runs fast. Changing the name from '9Bob' to '10Bob' results in a slow insert. Neither 796, nor 797 seem like a significant numbers. Removing the exec sp_executesql portion means lengths of 777 and 778. They don't seem significant either.

I'm stumped.

Update: Posted trace here: http://www.jere.us/WierdInserts.trc

Answer 1

If 10Bob is much slower than both 9Bob and 99Bob, that would potentially point to an INDEX on Name where either the FILLFACTOR is set too high, or SQL Server is having to reindex the page when it hits the "1" in "10Bob".

So, that explains Bob, except that you say there is no index and whitespace also makes a difference...

768 bytes is an important boundary in MySQL for deciding whether a BLOB is stored inline or in a separate table. Perhaps the SQL query optimizer has a similar boundary?

That might explain a tiny performance difference, but doesn't explain the order of magnitude.

SQL Server uses 8k pages by default, so one might expect a tiny performance hit when the first INSERT comes along that requires a new page, but again, nothing to do with whitespace and doesn't explain the amount of delay here.