0

SQL Server 2012 Enterprise in an AlwaysOn configuration. The Availability Group for this specific DB is synchronized and healthy.

I had to add a second transaction log file (logfile2) to the primary. The file did not replicate until I restarted the instance (was doing other maintenance). After the instance was restarted the transaction log appeared at the primary and secondary. 12 hours have passed since the instance was restarted and the log files show the same time/datestamp AND file size. Good so far ...

It appears however that transactions hitting logfile2 on the primary are not being synchronized to the secondary for over 20 minutes. In addition to the normal transaction log backup that runs every 2 hours, which includes a CHECKPOINT command, I had to install a SQL agent job that performs a CHECKPOINT on the DB every 15 minutes. The reasoning is that transactions going to logfile2 are languishing there and not getting applied to the database; so, I force the flush of the log files to the database, which then synchronizes to the secondary.

Can anyone shed some light on this behavior?
(Please hold your comments on having multiple log files. Unless you've walked a mile in my shoes ...)

5
  • While I won't mention the multiple log files in a negative light, can I ask why you have multiple? I think having that information may help us answer your question. Is there a chance that you can eliminate the second one? Was drive space the factor that caused there to be more than one log file? Just trying to gather some background information about your situation. – Kris Gruttemeyer May 17 '16 at 18:28
  • Please don't use windows timestamps to assume anything is going on. They lie, horrendously. How do you know it takes 20 minutes? What are you checking? In the first paragraph the databases are synchronized which means synchronous commit... yet files aren't showing up? How was this determined? If there was 20 minutes between data movement it wouldn't be synchronized but synchronizing. Big difference. Please add screenshots of the DMVs or AG Dashboard as the information given is contradictory. – Sean Gallardy - Retired User May 17 '16 at 18:46
  • The secondary is used for the reporting server to source. A data change in the application (registered on the primary DB) does not show up with that same change on the report 20 minutes later. I would expect that any data changed would synchronize close to instantaneous. When we had one log file changing there was no issue. Drive space was the factor for adding logfile2 – LookingforSQLAnswers May 17 '16 at 19:53
  • The secondary has its' read commited isolation level changed to snapshot, thus if the transaction is not fully completed (i.e. long running transaction, etc.) that change isn't going to show up. Period. The data will already be on the secondary, though. This is not a good test. You'll want to look into long running queries, etc., inserting/updating/deleting data. Again, it's not working as you're assuming it should. Please, again, provide screen shots, dmv output, etc. – Sean Gallardy - Retired User May 17 '16 at 23:06
  • FYI - running checkpoint commands does absolutely nothing for the movement of log blocks to the secondary. – Sean Gallardy - Retired User May 17 '16 at 23:07
4

Can anyone shed some light on this behavior?

The behavior you're describing is not working as described. The end result is the same but the inner workings are different than what you're thinking.

The Availability Group for this specific DB is synchronized and healthy.

I had to add a second transaction log file (logfile2) to the primary. The file did not replicate until I restarted the instance (was doing other maintenance). After the instance was restarted the transaction log appeared at the primary and secondary. 12 hours have passed since the instance was restarted and the log files show the same time/datestamp AND file size.

Restarting the instance didn't actually fix anything. If the databases were synchronized then the log blocks were hardened on the secondary. This doesn't mean there were redone yet, jus that they were hardened to disk.

By restarting the instance you've effectively forced redo to complete to a point and thus creating the second log file. If it is taking this much time to redo log blocks, there may be an issue with how much load the secondary could handle and this is one of the ways you'll see it manifest.

The last item that is indicative of this behavior is a blocked redo thread, which is most likely the cause.

It appears however that transactions hitting logfile2 on the primary are not being synchronized to the secondary for over 20 minutes.

Then the AG wouldn't be synchronized, it'd change to synchronizing. This is more likely what I descried above, where the log blocks were hardened and weren't yet redone (blocked redo thread).

Assuming the log blocks were sent, the AG is synchronized, and the redo thread was not blocked... this could be due to the transaction still being open. Until the transactions is committed (trancount = 0) your queries on the secondary won't see it as it isn't a yet committed transaction.

Assuming the transaction was committed (trancount = 0), the default isolation level of read committed is mapped to the snapshot isolation level on the secondary. This could also be due to isolation level changes and the query running.

In addition to the normal transaction log backup that runs every 2 hours, which includes a CHECKPOINT command, I had to install a SQL agent job that performs a CHECKPOINT on the DB every 15 minutes. The reasoning is that transactions going to logfile2 are languishing there and not getting applied to the database; so, I force the flush of the log files to the database, which then synchronizes to the secondary.

This is not how the process works. Checkpoint itself doesn't flush log records, they may need to be flushed from the log buffer because of WAL (Write Ahead Logging) enforcement for the data pages being flushed but it will do nothing to the log file. The setup done with the agent job and checkpoint is not helping one bit.

The unit of transport is a log block, not individual records. When log blocks end and are flushed to disk, if the database is part of AlwaysOn Availability Groups it is copied into (depending on version) another buffer and eventually sent through the transport when the secondary checks in. This is a gross over simplification but shows how it works.

What to do next?

  1. Checked for blocked redo threads on the secondary.
  2. Make sure the AG is synchronized and not synchronizing
  3. Make sure the transactions have @@TRANCOUNT = 0
  4. Make sure the secondary has enough disk IOPs to handle the load without growing the redo queue size

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.