Transaction Log

Firstly a brief introduction to the SQL Server Transaction Log and a process called write ahead logging.

It is this file (or sometimes files) that guarantees transactional consistency within SQL Server. A committed transaction will always write all transaction log records relating to that transaction to the physical log file before returning a committed notification to the client.

  • Transaction starts
  • DML operations occur and data starts being changed in the buffer pool
  • Transaction is committed
  • Transaction log records are written to disk
    • All as yet unwritten transaction log records in the log buffer are written to disk here and not just those relating to this transaction.
  • Commit success notification sent to the client
  • As some point thereafter, the checkpoint process copies the dirty data pages from the buffer pool to the physical data file(s).
    • The chronology described here could be different. The data pages could be written to disk prior to the transaction committing. SQL Server always guarantees however, that the log records will be written to disk prior to the data pages.
    • The occurrence of a checkpoint can be controlled by specifying the recovery interval at either the server or database level. Checkpoints can also be issued manually or internally by SQL Server.
    • All dirty pages are written to disk by the checkpoint process and not just those pertaining to a specific transaction.

Next, we will have some fun and investigate what happens when a log file is deleted.

If I create a database like so


CREATE DATABASE LogDeleteTest ON PRIMARY
(NAME = N'LogDeleteTest_Data', FILENAME = 'C:\SQL\LogDeleteTest_Data.mdf', SIZE = 10 MB,FILEGROWTH=10 MB, MAXSIZE = UNLIMITED)
LOG ON
(NAME = N'LogDeleteTest_Log', FILENAME = 'C:\SQL\LogDeleteTest_Log.ldf', SIZE = 10 MB,FILEGROWTH=10 MB, MAXSIZE = UNLIMITED);

Simply deleting the log file in windows explorer is not possible and gives this error

Log file delete error.JPG

If I take the database offline however, by issuing


ALTER DATABASE LogDeleteTest SET OFFLINE;

Then the delete works just fine. Bringing the database online


ALTER DATABASE LogDeleteTest SET ONLINE;

Then gives this: –

File activation failure. The physical file name “C:\SQL\LogDeleteTest_log.ldf” may be incorrect.
New log file ‘C:\SQL\LogDeleteTest_log.ldf’ was created.

The log file has been automatically created at C:\SQL\LogDeleteTest_log.ldf and the database is online and available.

However, we shut the database down cleanly prior to deleting the log file. This means a checkpoint occurred and all uncommitted transactions were rolled back and all committed were hardened to disk. This means the transaction log was rebuilt with no risk of data loss.

The fun happens when the database is not shut down cleanly prior to deleting the log file. Do this by performing an DDL or DML action to create a log record, stopping the SQL Server service on a test box and delete the log file as before. This then results in

Recovery pending

We then have to make use of emergency mode like so


USE master;
ALTER DATABASE LogDeleteTest SET SINGLE_USER;
ALTER DATABASE LogDeleteTest SET EMERGENCY;
DBCC CHECKDB (N'LogDeleteTest',REPAIR_ALLOW_DATA_LOSS) WITH ALL_ERRORMSGS;
ALTER DATABASE LogDeleteTest SET MULTI_USER;

This is in the output, the log file has been created and the database is online and available

File activation failure. The physical file name “C:\SQL\LogDeleteTest_Log.ldf” may be incorrect.
Warning: The log for database ‘LogDeleteTest’ has been rebuilt. Transactional consistency has been lost. The RESTORE chain was broken, and the server no longer has context on the previous log files, so you will need to know what they were. You should run DBCC CHECKDB to validate physical consistency. The database has been put in dbo-only mode. When you are ready to make the database available for use, you will need to reset database options and delete any extra log files.

If you consider what happened here, this is a really bad situation for the database to now be in. At the start while talking about write ahead logging, we described how SQL Server relies on the transaction log to roll back uncommitted transactions and roll forward committed transactions. This ensures data page updates for a transaction that was never committed are removed, and data page updates that were not previously performed for transactions that were committed are now done. Without the transaction log, this process has been completely omitted, meaning our database could now very well be in a transactionally inconsistent state where partially performed transactions are now within the database. At least your database is now up and available however if that was your primary goal.

Using emergency mode should be a last resort. You should always have a robust, documented disaster recovery solution in place to recover from such situations by other means with less exposure to data loss. If your last good log backup was 30 minutes before the log file was deleted however, you would have to make a judgement call. Either restore from backup and lose 30 minutes of data or use emergency mode and your last checkpoint could have only been 10 seconds before the log file was dropped. Maybe an option here would be to use both methods and then resolve manually by comparing the two. Always keep a copy of the files prior to taking any action, so you can revert to that if you make things worse.

 

SQL Server Extended Events

SQL Server extended events were introduced in SQL Server 2008 as a more flexible method for event monitoring to replace the more resource intensive SQL Server trace. Server side trace or SQL Profiler trace is still in the product as of SQL Server 2016, but is expected to be removed at some point.

Extended event sessions can be created via the SSMS GUI, or via T-SQL. Here is an example script of the latter to monitor for SQL batch start and stop events for a specific user: –

/*
Description: -

Create an extended events session to monitor batch start and stop for a specific username.

Query SQL Server actions via: -

SELECT [Action] = p.name + N'.' + o.name + N',',*
FROM sys.dm_xe_objects AS o
INNER JOIN sys.dm_xe_packages AS p ON o.package_guid = p.guid
WHERE o.object_type = N'action' AND
p.name = N'sqlserver'
ORDER BY [Action]

Change History: -
Who When Why
Andy Jones 04/11/2015 Created.
*/
IF EXISTS (SELECT 1 FROM sys.server_event_sessions WHERE name = N'Stored procedure execution')
 BEGIN;
 DROP EVENT SESSION [Stored procedure execution] ON SERVER;
 END;

CREATE EVENT SESSION [Stored procedure execution] ON SERVER

ADD EVENT sqlserver.sql_batch_starting (
 SET collect_batch_text = (1)
 ACTION(
 sqlserver.client_app_name,
 sqlserver.client_hostname,
 sqlserver.database_id,
 sqlserver.database_name,
 sqlserver.nt_username,
 sqlserver.plan_handle,
 sqlserver.server_instance_name,
 sqlserver.server_principal_name,
 sqlserver.server_principal_sid,
 sqlserver.session_id,
 sqlserver.session_nt_username,
 sqlserver.session_server_principal_name,
 sqlserver.sql_text,
 sqlserver.username
 )
 WHERE (username = (N'ajones'))
 ),

ADD EVENT sqlserver.sql_batch_completed (
 SET collect_batch_text = (1)
 ACTION(
 sqlserver.client_app_name,
 sqlserver.client_hostname,
 sqlserver.database_id,
 sqlserver.database_name,
 sqlserver.nt_username,
 sqlserver.plan_handle,
 sqlserver.server_instance_name,
 sqlserver.server_principal_name,
 sqlserver.server_principal_sid,
 sqlserver.session_id,
 sqlserver.session_nt_username,
 sqlserver.session_server_principal_name,
 sqlserver.sql_text,
 sqlserver.username
 )
 WHERE (username = (N'ajones'))
 )

ADD TARGET package0.ring_buffer(SET max_memory = (10240))

WITH (
 MAX_MEMORY = 4096 KB,
 EVENT_RETENTION_MODE = ALLOW_SINGLE_EVENT_LOSS,
 MAX_DISPATCH_LATENCY = 5 SECONDS,
 MAX_EVENT_SIZE = 0 KB,
 MEMORY_PARTITION_MODE = NONE,
 TRACK_CAUSALITY = ON,
 STARTUP_STATE = OFF
 );

IF NOT EXISTS (SELECT 1 FROM sys.dm_xe_sessions WHERE name = N'Stored procedure execution')
 BEGIN;
 ALTER EVENT SESSION [Stored procedure execution] ON SERVER STATE = START;
 END;

This example is writing the output to memory. Live session data can be viewed by SSMS | Management | Extended Events | Sessions | Stored procedure execution | Right Click | Watch Live Data. Alternatively, the session data can be written to a file and queried via T-SQL and XQuery. That method and other extended event options will be described in a future blog post.