Lesson Learned #248: Working with sp_wait_for_database_copy_sync and SQL Auditing.

[Jose_Manuel_Jurado]

Based on this public documentation Auto-failover groups overview & best practices - Azure SQL Database | Microsoft Learn , we received several questions about how to identify if any data has been not synced between primary and secondary when we performed a force failover in Azure Transparent Failover Group. 

As you could see in this public documentation Auto-failover groups overview & best practices - Azure SQL Database | Microsoft Learn about sp_wait_for_database_copy_sync "sp_wait_for_database_copy_sync prevents data loss after geo-failover for specific transactions, but does not guarantee full synchronization for read access. The delay caused by a sp_wait_for_database_copy_sync procedure call can be significant and depends on the size of the not yet transmitted transaction log on the primary at the time of the call."

Our customer asked about several scenarios to understand this behaviour and also, verify if there is possible to identify the rows that have not been synced. For this, I developed a POC to test it:

• Created an environment using Transparent failover group using General Purpose with 2 vCores.
• Created a table called Example – CREATE TABLE Example (NAME varchar(100))
• I enabled SQL Auditing to know all the operations executed in the database. 
• The below C# code has two main functions: 
  • Inicia that explicitly creates a single transaction (insert) 1000 rows.
  • Inicia3 that runs the same operation but using an implicit transaction and with/without calling sys.sp_wait_for_database_copy_sync

 

Test #1: Using Inicia function with implicit transaction:

• After calling the commit method of the transaction and executing a failover with data loss manually, I  didn’t observe any data-loss.
• Before calling the commit method of the transaction and executing a failover with data loss manually, we observed that any data have been saved that it is expected.
• I observed in both tests all these commands executed in SQL Auditing Log.

 

Test #2: Using Inicia3 function without implicit transaction:

• I initiated a forced failover at the moment that we finished 398 inserts without calling sys.sp_wait_for_database_copy_sync and I observed the following scenario:
• New Primary with 337 rows
• New Secondary with 398 rows.
• After the databases were restarted and the synchronization phase completed we finally observed 337 rows in both databases. 
• I initiated a forced failover at the moment that we finished 398 inserts calling sys.sp_wait_for_database_copy_sync everytime and I observed the following scenario:
  
  • New Primary with 398 rows
  • New Secondary with 398 rows.
• I observed in both tests all these commands executed in SQL Auditing Log.

So, my lesson learned that using SQL Auditing Log will be an option to identify if any data has been lost.

C# Code

using System;
using System.Collections.Generic;
using System.Linq;
using System.Text;
using System.Threading.Tasks;

using System.Collections;
using System.Data;
using C = System.Data.SqlClient;
using System.Diagnostics;
using System.Threading;
using System.Configuration;

namespace DotNetExample
{
    class ClsGeo
    {
        private static string GetConnectionString(bool bPooling)
        {
            return ConfigurationManager.ConnectionStrings["OkGeo"].ToString() + (bPooling ? "yes" : "no");
        }

        public void Inicia(int nRows, bool bPooling, bool bInstanciaCadaVez = false)
        {
            try
            {
                Stopwatch stopWatch = new Stopwatch();
                stopWatch.Start();


                C.SqlConnection oConn = new C.SqlConnection();
                ClsRetryLogic oClsRetry = new ClsRetryLogic();
                if (oClsRetry.HazUnaConexionConReintentos(GetConnectionString(bPooling), oConn, bInstanciaCadaVez))
                {
                    C.SqlTransaction transaction;
                    transaction = oConn.BeginTransaction();
                    C.SqlCommand command = new C.SqlCommand("insert into Example (Name) values(@Name)", oConn, transaction);
                    command.CommandTimeout = 30;
                    command.Parameters.Add("@Name", SqlDbType.VarChar, 100);
                    command.Prepare();

                    for (int tries = 1; tries <= nRows; tries++)
                    {
                        Console.WriteLine("Attempt Nr.: " + tries.ToString());
                        command.Parameters["@Name"].Value = "Example " + (tries).ToString();
                        command.ExecuteNonQuery();
                        Console.WriteLine("ExecuteNonQuery Done.: " + tries.ToString());
                    }
                    transaction.Commit();
                    stopWatch.Stop();
                    // Obtenemos el tiempo pasado
                    TimeSpan ts = stopWatch.Elapsed;

                    // Formateamos y mostramos.
                    string elapsedTime = String.Format("{0:00}:{1:00}:{2:00}.{3:00}",
                        ts.Hours, ts.Minutes, ts.Seconds,
                        ts.Milliseconds / 10);
                    Console.WriteLine("Pooling:{0}. Time:{1}", bPooling ? "Pooling" : "Without Pooling", elapsedTime);
                    Console.ReadLine();
                }
            }
            catch (Exception e)
            {
                Console.WriteLine("ExecuteNonQuery Error.: ");
                Console.WriteLine("Ups!! " + e.Message);
                Console.ReadLine();
            }

        }


        public void Inicia3(int nRows, bool bPooling, bool bInstanciaCadaVez = false)
        {
            try
            {
                Stopwatch stopWatch = new Stopwatch();
                stopWatch.Start();
                
                C.SqlConnection oConn = new C.SqlConnection();
                ClsRetryLogic oClsRetry = new ClsRetryLogic();
                if (oClsRetry.HazUnaConexionConReintentos(GetConnectionString(bPooling), oConn, bInstanciaCadaVez))
                {
                    C.SqlCommand command = new C.SqlCommand("insert into Example (nAME) values(@Name)", oConn);
                    command.CommandTimeout = 30;
                    command.Parameters.Add("@Name", SqlDbType.VarChar, 100);
                    command.Prepare();

                    C.SqlCommand commandSyncData = new C.SqlCommand("EXEC sys.sp_wait_for_database_copy_sync _server = N'datasource', _database = N'failover-test'", oConn);
                    commandSyncData.CommandTimeout = 30;
                    
                    for (int tries = 1; tries <= nRows; tries++)
                    {
                        Console.WriteLine("Attempt Nr.: " + tries.ToString());
                        command.Parameters["@Name"].Value = "Example " + (tries).ToString();
                        command.ExecuteNonQuery();
                        Console.WriteLine("ExecuteNonQuery Done.: " + tries.ToString());
                        Console.WriteLine("ExecuteNonQuery Sync.: " );
                        commandSyncData.ExecuteNonQuery();
                        Console.WriteLine("ExecuteNonQuery Sync Done.: " );
                    }
                    stopWatch.Stop();
                    // Obtenemos el tiempo pasado
                    TimeSpan ts = stopWatch.Elapsed;

                    // Formateamos y mostramos.
                    string elapsedTime = String.Format("{0:00}:{1:00}:{2:00}.{3:00}",
                        ts.Hours, ts.Minutes, ts.Seconds,
                        ts.Milliseconds / 10);
                    Console.WriteLine("Pooling:{0}. Time:{1}", bPooling ? "Pooling" : "Without Pooling", elapsedTime);
                    Console.ReadLine();
                }
            }
            catch (Exception e)
            {
                Console.WriteLine("ExecuteNonQuery Error.: ");
                Console.WriteLine("Ups!! " + e.Message);
                Console.ReadLine();
            }

        }


    }
}

Enjoy!