SQL Server 2012 Always On Setup with two nodes

Question

I have AlwaysOn setup with two data nodes and one witness. I faced an issue where my PRIMARY Server restarted abruptly.

Here're some issues I faced during this timeframe.

1. Due to abrupt restart of PRIMARY Replica the DB's gone into RECOVERY Mode.

2. The DB took around 1 hours time to recover.

3. During this RECOVERY Phase of PRIMARY Replica. The Secondary Server (Which is now PRIMARY due to FAILOVER) was facing timeouts and was observing slowness.

Looking at the logs I could see logs about roll forward and rollback that happened for the database. But at first place I am wondering what could be the reason my recovery of DB took longer?

Also, would like to get an input on if I add one more secondary node to this setup, will it help me efficiently?

Adding the Error Log :

2015-10-12 16:20:26.30 spid31s     The recovery LSN (6821:15912:1) was identified for the database with ID 12. This is an informational message only. No user action is required.
2015-10-12 16:23:56.81 spid44s     Recovery of database 'A' (11) is 0% complete (approximately 1168 seconds remain). Phase 1 of 3. This is an informational message only. No user action is required.
2015-10-12 16:23:57.28 spid44s     Recovery of database 'A' (11) is 0% complete (approximately 1091 seconds remain). Phase 1 of 3. This is an informational message only. No user action is required.
2015-10-12 16:23:57.28 spid44s     Recovery of database 'A' (11) is 0% complete (approximately 891 seconds remain). Phase 2 of 3. This is an informational message only. No user action is required.
2015-10-12 16:24:17.32 spid44s     Recovery of database 'A' (11) is 31% complete (approximately 44 seconds remain). Phase 2 of 3. This is an informational message only. No user action is required.
2015-10-12 16:24:50.53 spid6s      SQL Server has encountered 1 occurrence(s) of I/O requests taking longer than 15 seconds to complete on file [Z:\SQLData\A\A.mdf] in database [A] (11).  The OS file handle is 0x0000000000000B9.  The offset of the latest long I/O is: 0x0000041135800
2015-10-12 16:24:55.46 spid44s     Recovery of database 'A' (11) is 53% complete (approximately 51 seconds remain). Phase 2 of 3. This is an informational message only. No user action is required.
2015-10-12 16:25:15.50 spid44s     Recovery of database 'A' (11) is 85% complete (approximately 13 seconds remain). Phase 2 of 3. This is an informational message only. No user action is required.
2015-10-12 16:25:49.69 spid44s     3033 transactions rolled forward in database 'A' (11:0). This is an informational message only. No user action is required.
2015-10-12 16:25:50.15 spid44s     Recovery completed for database A (database ID 11) in 290 second(s) (analysis 480 ms, redo 87801 ms, undo 0 ms.) This is an informational message only. No user action is required.
2015-10-12 16:25:52.35 spid44s     CHECKDB for database 'A' finished without errors on 2012-10-27 22:19:16.470 (local time). This is an informational message only; no user action is required.
2015-10-12 16:42:57.67 spid24s     AlwaysOn Availability Groups connection with primary database established for secondary database 'A' on the availability replica with Replica ID: {}. This is an informational message only. No user action is required.
2015-10-12 16:42:57.67 spid24s     The recovery LSN (216726:2384:1) was identified for the database with ID 11. This is an informational message only. No user action is required.
2015-10-12 16:42:57.91 spid24s     AlwaysOn Availability Groups connection with primary database established for secondary database 'A' on the availability replica with Replica ID: {}. This is an informational message only. No user action is required.
2015-10-12 16:42:57.91 spid24s     The recovery LSN (216726:2384:1) was identified for the database with ID 11. This is an informational message only. No user action is required.
2015-10-12 16:42:58.53 spid24s     Error: 35278, Severity: 17, State: 1.
2015-10-12 16:42:58.53 spid24s     Availability database 'A', 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.
2015-10-12 16:42:58.53 spid29s     Nonqualified transactions are being rolled back in database A for an AlwaysOn Availability Groups state change. Estimated rollback completion: 100%. This is an informational message only. No user action is required.
2015-10-12 16:42:58.53 spid38s     AlwaysOn Availability Groups connection with primary database terminated for secondary database 'A' on the availability replica with Replica ID: {}. This is an informational message only. No user action is required.
2015-10-12 16:42:58.79 spid29s     Starting up database 'A'.
2015-10-12 16:49:45.32 spid29s     Recovery of database 'A' (11) is 0% complete (approximately 1168 seconds remain). Phase 1 of 3. This is an informational message only. No user action is required.
2015-10-12 16:49:45.78 spid29s     Recovery of database 'A' (11) is 0% complete (approximately 1091 seconds remain). Phase 1 of 3. This is an informational message only. No user action is required.
2015-10-12 16:49:45.78 spid29s     Recovery of database 'A' (11) is 0% complete (approximately 891 seconds remain). Phase 2 of 3. This is an informational message only. No user action is required.
2015-10-12 16:50:05.80 spid29s     Recovery of database 'A' (11) is 35% complete (approximately 37 seconds remain). Phase 2 of 3. This is an informational message only. No user action is required.
2015-10-12 16:50:25.82 spid29s     Recovery of database 'A' (11) is 68% complete (approximately 18 seconds remain). Phase 2 of 3. This is an informational message only. No user action is required.
2015-10-12 16:50:44.66 spid29s     AlwaysOn Availability Groups connection with primary database established for secondary database 'A' on the availability replica with Replica ID: {}. This is an informational message only. No user action is required.
2015-10-12 16:50:44.66 spid29s     The recovery LSN (216726:2386:1) was identified for the database with ID 11. This is an informational message only. No user action is required.
2015-10-12 16:50:44.66 spid29s     Error: 35286, Severity: 16, State: 1.
2015-10-12 16:50:44.66 spid29s     Using the recovery LSN (216726:2384:1) stored in the metadata for the database with ID 11. This is an informational message only. No user action is required.
2015-10-12 16:53:12.38 spid29s     Error: 35278, Severity: 17, State: 1.
2015-10-12 16:53:12.38 spid29s     Availability database 'A', 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.
2015-10-12 16:53:12.38 spid29s     Nonqualified transactions are being rolled back in database A for an AlwaysOn Availability Groups state change. Estimated rollback completion: 100%. This is an informational message only. No user action is required.
2015-10-12 16:53:12.40 spid31s     AlwaysOn Availability Groups connection with primary database terminated for secondary database 'A' on the availability replica with Replica ID: {}. This is an informational message only. No user action is required.
2015-10-12 16:53:14.45 spid29s     Starting up database 'A'.
2015-10-12 17:05:44.30 spid29s     Recovery of database 'A' (11) is 0% complete (approximately 1168 seconds remain). Phase 1 of 3. This is an informational message only. No user action is required.
2015-10-12 17:05:44.76 spid29s     Recovery of database 'A' (11) is 0% complete (approximately 1091 seconds remain). Phase 1 of 3. This is an informational message only. No user action is required.
2015-10-12 17:05:44.76 spid29s     Recovery of database 'A' (11) is 0% complete (approximately 891 seconds remain). Phase 2 of 3. This is an informational message only. No user action is required.
2015-10-12 17:06:04.88 spid29s     Recovery of database 'A' (11) is 31% complete (approximately 45 seconds remain). Phase 2 of 3. This is an informational message only. No user action is required.
2015-10-12 17:06:24.92 spid29s     Recovery of database 'A' (11) is 65% complete (approximately 21 seconds remain). Phase 2 of 3. This is an informational message only. No user action is required.
2015-10-12 17:06:45.55 spid29s     AlwaysOn Availability Groups connection with primary database established for secondary database 'A' on the availability replica with Replica ID: {}. This is an informational message only. No user action is required.
2015-10-12 17:06:45.55 spid29s     The recovery LSN (216726:19027:80) was identified for the database with ID 11. This is an informational message only. No user action is required.
2015-10-12 17:06:48.97 spid29s     3034 transactions rolled forward in database 'A' (11:0). This is an informational message only. No user action is required.
2015-10-12 17:06:49.04 spid29s     Recovery completed for database A (database ID 11) in 710 second(s) (analysis 470 ms, redo 60412 ms, undo 0 ms.) This is an informational message only. No user action is required.
2015-10-12 17:06:49.07 spid20s     AlwaysOn Availability Groups connection with primary database established for secondary database 'A' on the availability replica with Replica ID: {}. This is an informational message only. No user action is required.
2015-10-12 17:06:49.08 spid20s     The recovery LSN (216726:19027:80) was identified for the database with ID 11. This is an informational message only. No user action is required.

Answer 1

The problem is possibly within the error you are seeing: Error: 35278, When this happens you will probably observe that the database sits in a reverting state for a long period of time.

This can be caused by a number of reasons, normally a long running transaction.

The timeouts you were experiencing may have been caused by the traffic being sent between the replicas for the database to be recovered and come back however, are you certain that the timeouts where not being caused by some other issue?

I would be curious to know, what your backup strategy is on this database and when the last full backup had been run prior to this failover. I recently experienced this on a test environment where backups were not being run. A full backup and subsequent log backup allowed a failover to occur with out issue, the error was not present and the recovery time was very quick.