What statistics value corresponds to the ADO.net SqlCommand.CommandTimeout property?

user_7985128 0
Viewed 116

I am trying to understand this property, I have a function for running an sql query in ADO.net where I have set the SqlCommand.ConnectTimeout property to 500 seconds and the SqlCommand.CommandTimeout property to 1 second. Roughly the relevant portion looks like this.

        var conn = dbConn as SqlConnection;
        conn.ConnectTimeout = 500;
        conn.StatisticsEnabled = true;

        try
        {
            using (var command = new SqlCommand(query, conn))
            {
                command.CommandTimeout = 1;
                using (var adapter = new SqlDataAdapter(command))
                {
                    var rowsCount = adapter.Fill(startIdx, MaxRows, new DataTable[] { dtResult });
                    var stats = conn.RetrieveStatistics();
                    long commandExecutionTimeInMs = (long)stats["ExecutionTime"];
                    long commandNetworkServerTimeInMs = (long)stats["NetworkServerTime"];
                    Console.Writeline("Command statistics execution time: " + commandExecutionTimeInMs.ToString());
                    Console.Writeline("Command statistics network server time: " + commandNetworkServerTimeInMs.ToString());
                    conn.ResetStatistics();
                    conn.StatisticsEnabled = false;
                    return rowsCount;
                }
            }
        }
        catch (Exception ex)
        {
            var stats = conn.RetrieveStatistics();
            long commandExecutionTimeInMs = (long)stats["ExecutionTime"];
            long commandNetworkServerTimeInMs = (long)stats["NetworkServerTime"];
            Console.Writeline("Command statistics execution time: " + commandExecutionTimeInMs.ToString());
            Console.Writeline("Command statistics network server time: " + commandNetworkServerTimeInMs.ToString());
            conn.ResetStatistics();
            conn.StatisticsEnabled = false;
        }

With this, I am expecting any execution time above 1 second to timeout and throw an exception with this message: "Execution Timeout Expired. The timeout period elapsed prior to completion of the operation or the server is not responding.". However it is very inconsistent, my logs show me that execution time can go up to several seconds or even 10+ seconds without throwing anything sometimes. And NetworkServerTime is consistently in the 200 to 300ms range.

So what is the problem here? Am I misunderstanding how CommandTimeout works? Am I looking at the wrong statistics value? I am looking to set CommandTimeout to 1, and then when my query exceeds this time I can clearly see a statistic that logs the time as 1s or 1000ms in the catch block

Referring to this page nothing else seems to be relevant https://docs.microsoft.com/en-us/dotnet/framework/data/adonet/sql/provider-statistics-for-sql-server

ado.net sql-server c#
2 Answers

There are remarks and 2 notes in the docs.

Remark

!Note

The CommandTimeout property will be ignored by older APM (Asynchronous Programming Model) asynchronous method calls such as BeginExecuteReader. It will be honored by newer TAP (Task Asynchronous Programming) methods such as ExecuteReaderAsync.

!Note

This property is the cumulative time-out (for all network packets that are read during the invocation of a method) for all network reads during command execution or processing of the results. A time-out can still occur after the first row is returned, and does not include user processing time, only network read time.

For example, with a 30 second time out, if Read requires two network packets, then it has 30 seconds to read both network packets. If you call Read again, it will have another 30 seconds to read any data that it requires.
user_67487580

After looking into the documentation and discussions around the methods I was using I think I found the answer. It seems like this isn't a new issue for people using SqlDataAdapter. Quoting a Microsoft engineer here:

SqlCommand.CommandTimeout property affects only single operation of the command. So the timeout set will be the total time for all network reads during single execution such as SqlCommand.ExecuteReader or SqlDataReader.Read(), SqlDataReader.GetString(). The timeout is reset each time new operation is called.

SqlDataAdapter users public interface of the command, so it calls ExecuteReader once followed by calling several DataReader operations as needed to retrieve the data. So the total time is (one call for ExecuteReader + other operations on command) X CommandTimeout, depending on the parameters.

Reference: https://social.msdn.microsoft.com/Forums/en-US/de557eb1-aa0f-403d-89c6-199bb318a08f/sqldataadapterfill-does-not-time-out-when-it-should?forum=adodotnetdataproviders

SqlDataAdapter.Fill() method that I am using is probably doing multiple operations, hence why it easily exceeds the timeout in terms of execution time but doesn't actually trigger an exception.

user_79851280
Related