Infrastructure at your Service

David Barbarin

SQL Server: Forced failover with AlwaysOn & Availability Groups

During a workshop at one of my customer about the implementation of SQL Server AlwaysOn and availability groups, I had an interesting discussion. It was about asynchronous replication between 2 replicas and the effect of the forced failover operation with allowed data loss. Does SQL Server resynchronize availability databases if I loose some transactions during the failover process?

The quick answer is yes but probably the most interesting question is how SQL Server achieves resynchronization and this is exactly what we will see in this blog post.

Simulate a data loss is pretty easy if you have a SQL Server AlwaysOn architecture with availability groups and 2 replicas enrolled in an asynchronous replication. You can pause the replication on secondary and then perform a manual forced failover from the same server for instance. During this blog post I will use the undocumented function sys.fn_db_log() and some dynamic management views related to availability groups as well.

Let’s begin with my SQL Server architecture: One availability group with the adventureworks2012 database that hosts a table dbo.aag_test and 2 replicas SQL141 and SQL143 configured in asynchronous replication. SQL141 is the current primary.

 

Step 1: Create a replication issue by pausing the availability database on the secondary

After suspending the replication from the secondary, we insert an additional record in a table aag_test on the primary (SQL141) which will be not replicated to the secondary (SQL143). Notice that we are not aligned on both sides by viewing the content of the sys.fn_db_log() function on each transaction log.

 

:connect sql141
use AdventureWorks2012;
 
select * from dbo.aag_test;
 
select * from sys.fn_dblog(null, null);
go
 
 
:connect sql143
use AdventureWorks2012;
 
select * from dbo.aag_test;
 
select * from sys.fn_dblog(null, null);
go

Here is the content of the AdventureWorks2012 transaction log file on the primary:

00000104:00003a88:0001     LOP_MODIFY_ROW      LCX_BOOT_PAGE 0000:00000000    
00000104:00003a90:0001     LOP_MODIFY_ROW      LCX_SCHEMA_VERSION  0000:00000000
00000104:00003a90:0002     LOP_BEGIN_XACT      LCX_NULL     0000:000343da
00000104:00003a90:0003     LOP_BEGIN_XACT      LCX_NULL     0000:000343db
00000104:00003a90:0004     LOP_FORMAT_PAGE     LCX_HEAP     0000:000343db
00000104:00003a90:0005     LOP_MODIFY_ROW      LCX_PFS      0000:000343db
00000104:00003a90:0006     LOP_MODIFY_ROW      LCX_IAM      0000:000343db
00000104:00003a90:0007     LOP_HOBT_DELTA      LCX_NULL     0000:000343db
00000104:00003a90:0008     LOP_FORMAT_PAGE     LCX_HEAP     0000:000343db
00000104:00003a90:0009     LOP_COMMIT_XACT     LCX_NULL     0000:000343db
00000104:00003a90:000a     LOP_INSERT_ROWS     LCX_HEAP     0000:000343da
00000104:00003a90:000b     LOP_SET_FREE_SPACE  LCX_PFS      0000:00000000
00000104:00003a90:000c     LOP_COMMIT_XACT     LCX_NULL     0000:000343da

And this is the content of the same database transaction log file on the secondary:

00000104:00003a70:0018     LOP_INSERT_ROWS     LCX_HEAP     0000:000343d7
00000104:00003a70:0019     LOP_SET_FREE_SPACE  LCX_PFS      0000:00000000
00000104:00003a70:001a     LOP_COMMIT_XACT     LCX_NULL     0000:000343d7
00000104:00003a88:0001     LOP_MODIFY_ROW      LCX_BOOT_PAGE 0000:00000000

 

On the secondary, the last record in the transaction log file is identified by the LSN: 260:14984:1 (in decimal format). We notice additional records in the transaction log file on the primary after pausing the replication – we can identify among them LOP_INSERT_ROWS / LCX_HEAP records that correspond in fact to the insertion of additional records in the table aag_test.

We can also take a look at the DMV related to the availability groups by using this query:

SELECT
       ar.replica_server_name as ServerName,
       drs.synchronization_state_desc as SyncState,
       drs.last_hardened_lsn,
       drs.last_redone_lsn
FROM sys.dm_hadr_database_replica_states drs
       LEFT JOIN sys.availability_replicas ar
             ON drs.replica_id = ar.replica_id
ORDER BY ServerName

 

The query’s output below:

 

ServerName   SyncState           last_hardened_lsn   last_redone_lsn
SQL141       SYNCHRONIZED        260000001501600001  NULL
SQL143       NOT SYNCHRONIZING   260000001499200001  260000001498400001 (260:14984:1)

 

The column last_redone_lsn for the secondary (SQL143) represents the last log record that has been redone. The value (convert in decimal format) is the same previously found in the transaction log by using the sys.fn_db_log() function. The last_hardened_lsn value represents the last transaction blog hardened to the transaction log file. This value is usually greater than the last_redone_lsn value.

Step 2: SQL143 becomes the new primary – after restarting SQL141 and initiating a manuel forced failover with potential data loss

At this point we have some lost data that have not been replicated (LSN between 00000104:00003a88:0001 and 00000104:00003a90:000c).

00000104:00003a90:0001     LOP_MODIFY_ROW      LCX_SCHEMA_VERSION  0000:00000000
00000104:00003a90:0002     LOP_BEGIN_XACT      LCX_NULL     0000:000343da
00000104:00003a90:0003     LOP_BEGIN_XACT      LCX_NULL     0000:000343db
00000104:00003a90:0004     LOP_FORMAT_PAGE     LCX_HEAP     0000:000343db
00000104:00003a90:0005     LOP_MODIFY_ROW      LCX_PFS      0000:000343db
00000104:00003a90:0006     LOP_MODIFY_ROW      LCX_IAM      0000:000343db
00000104:00003a90:0007     LOP_HOBT_DELTA      LCX_NULL     0000:000343db
00000104:00003a90:0008     LOP_FORMAT_PAGE     LCX_HEAP     0000:000343db
00000104:00003a90:0009     LOP_COMMIT_XACT     LCX_NULL     0000:000343db
00000104:00003a90:000a     LOP_INSERT_ROWS     LCX_HEAP     0000:000343da
00000104:00003a90:000b     LOP_SET_FREE_SPACE  LCX_PFS      0000:00000000
00000104:00003a90:000c

The new status of each replica is as following:

ServerName   SyncState           last_hardened_lsn   last_redone_lsn
SQL141       NOT SYNCHRONIZING   0                   0
SQL143       NOT SYNCHRONIZING   260000001502400001  NULL

Some additional records are inserted to the transaction log but they are not related directly to the replicated data lost previously from the old primary SQL141.

Step 3: Replication from the new primary SQL143 is resumed

Here the new status of the replication of each replica:

ServerName   SyncState           last_hardened_lsn   last_redone_lsn
SQL141       NOT SYNCHRONIZING   260000001499200001  249000007658400001
SQL143       SYNCHRONIZED        26000001502400001  NULL

We can confirm now that we have lost the data remained in the send queue list on the old primary SQL141. The last hardened lsn is not the same between the initial situation and the new situation (260000001501600001 vs 260000001499200001). Remember that the hardened lsn (transaction log block) 260000001499200001 corresponds to the last hardened lsn on the old secondary SQL143 before the synchronization issue.

Step 4: Last step – resuming the database movement on the new secondary SQL141 in order to resynchronize the both replicas

At this point SQL Server has resynchronized perfectly the both replicas. Take a look at the output of the sys.fn_db_log() on each side. We retrieve effectively the same pattern on both sides.

Content of the transaction log on the new secondary SQL141:

00000104:00003a88:0001     LOP_MODIFY_ROW      LCX_BOOT_PAGE 0000:00000000
00000104:00003a90:0001     LOP_MODIFY_ROW      LCX_BOOT_PAGE 0000:00000000
00000104:00003a98:0001     LOP_COUNT_DELTA     LCX_CLUSTERED 0000:00000000
00000104:00003a98:0002     LOP_COUNT_DELTA     LCX_CLUSTERED 0000:00000000
00000104:00003a98:0003     LOP_COUNT_DELTA     LCX_CLUSTERED 0000:00000000
00000104:00003a98:0004     LOP_COUNT_DELTA     LCX_CLUSTERED 0000:00000000
00000104:00003a98:0005     LOP_BEGIN_CKPT      LCX_NULL     0000:00000000
00000104:00003aa0:0001     LOP_XACT_CKPT LCX_BOOT_PAGE_CKPT  0000:00000000
00000104:00003aa8:0001     LOP_END_CKPT LCX_NULL     0000:00000000

Content of the transaction log on the new primary SQL143:

00000104:00003a88:0001     LOP_MODIFY_ROW      LCX_BOOT_PAGE 0000:00000000
00000104:00003a90:0001     LOP_MODIFY_ROW      LCX_BOOT_PAGE 0000:00000000
00000104:00003a98:0001     LOP_COUNT_DELTA     LCX_CLUSTERED 0000:00000000
00000104:00003a98:0002     LOP_COUNT_DELTA     LCX_CLUSTERED 0000:00000000
00000104:00003a98:0003     LOP_COUNT_DELTA     LCX_CLUSTERED 0000:00000000
00000104:00003a98:0004     LOP_COUNT_DELTA     LCX_CLUSTERED 0000:00000000
00000104:00003a98:0005     LOP_BEGIN_CKPT      LCX_NULL     0000:00000000
00000104:00003aa0:0001     LOP_XACT_CKPT LCX_BOOT_PAGE_CKPT  0000:00000000
00000104:00003aa8:0001     LOP_END_CKPT LCX_NULL     0000:00000000

 

Compared to the first output in the transaction log of the old primary SQL141 we definitively lost the entries identified previously at the top of this article.

Wonderful but how SQL Server has achieved this process? The answer is in the SQL Server error log of the new secondary SQL141:

  • First, we notice the recovery LSN (transaction log block) identified by SQL Server for the AdventureWorks2012 database here (260:14992:1). The same value was founded previously by looking at the availability groups DMV and the column last_hardened_lsn. This is the starting point for the resynchronizing process
SQL141 error log
2014-10-07 22:40:57.120    spid17s      The recovery LSN (260:14992:1) was identified for the database with ID 5. This is an informational message only. No user action is required.

 

  • Then we resumed manually the replication and we retrieve the event in the error log.
2014-10-07 22:40:57.130    spid17s      AlwaysOn Availability Groups data movement for database ‘AdventureWorks2012′ has been suspended for the following reason: “failover from partner” (Source ID 1; Source string: ‘SUSPEND_FROM_PARTNER’). To resume data movement on the database, you will need to resume the database manually. For information about how to resume an availability database, see SQL Server Books On
 
 
2014-10-07 22:43:33.950    spid57 ALTER DB param option: RESUME
2014-10-07 22:43:33.950    spid57 AlwaysOn Availability Groups data movement for database ‘AdventureWorks2012′ has been resumed. This is an informational message only. No user action is required.
2014-10-07 22:43:33.960    spid17s      AlwaysOn Availability Groups connection with primary database established for secondary database ‘AdventureWorks2012′ on the availability replica ‘SQL143′ with Replica ID: {546df6b8-d07d-4aa4-afb6-5f543d5fae98}. This is an informational message only. No user action is required.

 

  • The new secondary automatically restarted to resynchronize with the current primary. The commit LSN here is probably in the transaction log block (14992) that is lower than the transaction log block related to the Hardened Lsn (15016).
2014-10-07 22:43:34.060    spid17s      Availability database ‘AdventureWorks2012′, which is in the secondary role, is being restarted to resynchronize with the current primary database. This is an informational message only. No user action is required.
2014-10-07 22:43:34.060    spid43s      Nonqualified transactions are being rolled back in database AdventureWorks2012 for an AlwaysOn Availability Groups state change. Estimated rollback completion: 100%. This is an informational message only. No user action is required.
2014-10-07 22:43:34.070    spid43s      State information for database ‘AdventureWorks2012′ – Hardended Lsn: ‘(260:15016:1)’   Commit LSN: ‘(260:14992:12)’   Commit Time: ‘Oct 7 2014 10:21PM’

 

  • And finally the most important information in this error log. SQL Server reverted to the transaction log block related to the recovery LSN (260:14992:1) and reinitialize to the last log record redone by the old secondary SQL143.

 

2014-10-07 22:43:34.810    spid43s      Using the recovery LSN (260:14992:1) stored in the metadata for the database with ID 5. This is an informational message only. No user action is required.
 

This is exactly the picture we have by looking at the last output of the sys.fn_db_log() function above that starting from the LSN 00000104:00003a90:0001 (260:14992:1 in decimal format) that corresponds to the begin of the transaction block to the LSN 00000104:00003aa8:0001 (104:15016:1 in decimal format).

As you can see SQL Server uses a sophisticated mechanism that allows to recover to a situation before data lost. You probably also notice that the key point of this revert process is the transaction log block and not the transaction itself.

Enjoy!

 

Leave a Reply


+ 6 = eight

David Barbarin
David Barbarin

Senior Consultant & Microsoft Technology Leader