Lesson Learned #253: Retry Logic for Execution Timeout Expired

[Jose_Manuel_Jurado]

Today, I worked on a case that our customer faced an execution command timeout "Msg -2, Level 11, State 0, Line 0 - Execution Timeout Expired. The timeout period elapsed prior to completion of the operation or the server is not responding"

As this business process is running over the night and they need to ensure that the execution will be completed, they asked if there is possible to implement an Execution Retry Logic. 

In the similar way that we have for Retry-Logic for Transient Failure We could implement a similar mechanism to retry the operation, the only thing that we need is to change the commandTimeout parameter, for example, in .NET. 

As you could see in the following C# code, 

        public int HighCPU(int index = 0, int nRows = 0, int iQueryTimeout = 30000, int iFactor = 5, Boolean bMultipleDBTest = false, String sdbNameToWork = "", String sServerName = "")
        {
            try
            {

                C.SqlConnection oConnSource = new C.SqlConnection();
                ClsRetryLogic oClsRetrySource = new ClsRetryLogic();

                if (oClsRetrySource.ConnectionRetryLogic(GetConnectionStringSource(true, TypeConn.AzureSQL, bMultipleDBTest, sdbNameToWork, sServerName, "HighCPU - " + index.ToString()), oConnSource, false, bMetric:true, sAdditionalInfo:"HighCPU"))
                {
                    TimeSpan ts;
                    Boolean bExecuted = false;
                    string elapsedTime;
                    string sQueryTextValue = "";
                    System.ConsoleColor iColorTmp;

                    Stopwatch stopWatchBulk = new Stopwatch();
                    Stopwatch stopWatchBulkItem = new Stopwatch();
                    ClsFunctionParameter oClsFunctionParameter = new ClsFunctionParameter();

                    stopWatchBulk.Start();

                    Random rnd = new Random();
                    iColorTmp = Console.ForegroundColor;
                    Console.ForegroundColor = ConsoleColor.Green;
                    Console.WriteLine("HighCPU..Started -- Thread: {0:00}", index);
                    Console.ForegroundColor = iColorTmp;

                    C.SqlCommand oCmdExecute = new C.SqlCommand("SELECT count(Id) FROM [MSxyzTest].[_x_y_z_MS_HighCPU] Where TextToSearch = @Name OPTION (MAXDOP 1)", oConnSource);
                    oCmdExecute.CommandTimeout = iQueryTimeout;
                    oCmdExecute.Parameters.Add("@Name", SqlDbType.NVarChar, 200);
                    oCmdExecute.Prepare();

                    stopWatchBulkItem.Start();
                    for (int tries = 1; tries <= nRows; tries++)
                    {
                        oCmdExecute.Parameters["@Name"].Value = "Example " + oClsFunctionParameter.FunctionType(TypeFunctionExecution.IntRandom, 1, 850338).ToString();
                        bExecuted = false;
                        for (int retries = 1; retries <= 3; retries++)
                        {
                            bExecuted = bExecuteQuery(oConnSource,oCmdExecute, "HighCPU - Thread: " + index.ToString().PadLeft(2, '0') + " <-> Execution Number " + tries.ToString().PadLeft(6, ' ') + " of " + nRows.ToString() + " - Attempt Number:" + retries.ToString() + " Query Timeout:" + oCmdExecute.CommandTimeout.ToString(), iType: 2);
                            if (bExecuted)
                            {
                                oCmdExecute.CommandTimeout = iQueryTimeout;
                                break;
                            }
                            else
                            {
                                oCmdExecute = new C.SqlCommand("SELECT count(Id) FROM [MSxyzTest].[_x_y_z_MS_HighCPU] Where TextToSearch = @Name OPTION (MAXDOP 1)", oConnSource);
                                oCmdExecute.CommandTimeout = iQueryTimeout + (retries * iFactor);
                                oCmdExecute.Parameters.Add("@Name", SqlDbType.NVarChar, 200);
                                oCmdExecute.Prepare();
                                oCmdExecute.Parameters["@Name"].Value = sQueryTextValue;
                            }
                        }
                        ts = stopWatchBulkItem.Elapsed;
                        iColorTmp = Console.ForegroundColor;
                        if (bExecuted)
                        {
                            Console.ForegroundColor = ConsoleColor.White;
                            Console.WriteLine("HighCPU - Thread: {0:00} <-> Execution Number {1,6} of {3} <->Time {2}", index, tries, String.Format("{0:00}:{1:00}:{2:00}.{3:00}", ts.Hours, ts.Minutes, ts.Seconds, ts.Milliseconds / 10), nRows);
                        }
                        else
                        {
                            Console.ForegroundColor = ConsoleColor.Yellow;
                            Console.WriteLine("HighCPU - Thread: {0:00} <-> Reach MaxRetries {1,6} of {3} <->Time {2}", index, tries, String.Format("{0:00}:{1:00}:{2:00}.{3:00}", ts.Hours, ts.Minutes, ts.Seconds, ts.Milliseconds / 10), nRows);
                        }
                        Console.ForegroundColor = iColorTmp;
                        stopWatchBulkItem.Restart();
                    }
                    iColorTmp = Console.ForegroundColor;
                    Console.ForegroundColor = ConsoleColor.Green;
                    Console.WriteLine("HighCPU..Completed.Thread:{0}", index);
                    ts = stopWatchBulk.Elapsed;
                    elapsedTime = String.Format("{0:00}:{1:00}:{2:00}.{3:00}", ts.Hours, ts.Minutes, ts.Seconds, ts.Milliseconds / 10);
                    Console.WriteLine("HighCPU. Completed on: Thread: {1:00} Time: {0}", elapsedTime, index);
                    Console.ForegroundColor = iColorTmp;
                    oConnSource.Close();
                }
                return 1;
            }
            catch (Exception e)
            {
                Console.WriteLine("HighCPU. Thread:{0:00} - Error: " + e.Message, index);
                return 0;
            }
        }

First, we have the definition of the TSQL command that I'm going to execute. We include in oCmdExecute.CommandTimeout the value of the timeout (iQueryTimeout) that could be defined in the function parameter.

C.SqlCommand oCmdExecute = new C.SqlCommand("SELECT count(Id) FROM [MSxyzTest].[_x_y_z_MS_HighCPU] Where TextToSearch = @Name OPTION (MAXDOP 1)", oConnSource);
oCmdExecute.CommandTimeout = iQueryTimeout;
oCmdExecute.Parameters.Add("@Name", SqlDbType.NVarChar, 200);
oCmdExecute.Prepare();

Once we have this, we are going to retry the operation, for example, 3 times. For every call, we are going to execute the TSQL command, and in case that the function call (bExecutedQuery) reported an execution timeout, we are going to change the command timeout using the formula (Number of retries*number of seconds to wait). 

Doing it, we are going to increase dynamically the command timeout until the process finished, of course, you could include a log to see later what happened and apply the actions needed.

                        oCmdExecute.Parameters["@Name"].Value = "Example " + oClsFunctionParameter.FunctionType(TypeFunctionExecution.IntRandom, 1, 850338).ToString();
                        bExecuted = false;
                        for (int retries = 1; retries <= 3; retries++)
                        {
                            bExecuted = bExecuteQuery(oConnSource,oCmdExecute, "HighCPU - Thread: " + index.ToString().PadLeft(2, '0') + " <-> Execution Number " + tries.ToString().PadLeft(6, ' ') + " of " + nRows.ToString() + " - Attempt Number:" + retries.ToString() + " Query Timeout:" + oCmdExecute.CommandTimeout.ToString(), iType: 2);
                            if (bExecuted)
                            {
                                oCmdExecute.CommandTimeout = iQueryTimeout;
                                break;
                            }
                            else
                            {
                                oCmdExecute = new C.SqlCommand("SELECT count(Id) FROM [MSxyzTest].[_x_y_z_MS_HighCPU] Where TextToSearch = @Name OPTION (MAXDOP 1)", oConnSource);
                                oCmdExecute.CommandTimeout = iQueryTimeout + (retries * iFactor);
                                oCmdExecute.Parameters.Add("@Name", SqlDbType.NVarChar, 200);
                                oCmdExecute.Prepare();
                                oCmdExecute.Parameters["@Name"].Value = sQueryTextValue;
                            }

Enjoy!