Page splits, extended events, index page allocation and all the fish

2 years ago I wrote about monitoring page splits with Extended Events. Only 2 bloggers explored Extended Events feature at that time, so my post was more of a learning than for any practical matter. Yet one question remained open: according to straightforward calculations, after 3 splits of the first page, next split should have occurred on another page - but trace with extended events clearly showed 4 splits of initial page.

Recently Pavel Nefyodov has drawn my attention to another curious fact: initially we had 1 page; after all those splits we had 10. But trace showed 10 splits, not 9. So where did additional split come from? And finally I've realized that there is another simple way to trace those splits - via transaction log. If we manually checkpoint the system before and perform insert in transaction afer - our transaction log will containg exactly the relevant data; and it'll remain this way all the time transaction stays open. We'll query transaction log using undocumented but widely known fn_dblog function.

OK, Let's see some code (mostly taken from my old post which in turn used page split demo from Kalen Delaney's blog). Initial configuration (including trace definition):

USE tempdb;
GO

CREATE TABLE split_page  
(id INT IDENTITY(0,2) PRIMARY KEY,
id2 bigint DEFAULT 0,
data1 VARCHAR(33) NULL,  
data2 VARCHAR(8000) NULL);
GO

INSERT INTO split_page DEFAULT VALUES;
GO 385

CREATE EVENT SESSION MonitorPageSplits ON SERVER
ADD EVENT sqlserver.page_split
(
   ACTION (sqlserver.database_id, sqlserver.sql_text)  
    WHERE sqlserver.database_id = 2
)
ADD TARGET package0.asynchronous_file_target
(
   SET  
       filename = N'c:\temp\MonitorPageSplits.etx',  
       metadatafile = N'c:\temp\MonitorPageSplits.mta'
);
GO

CHECKPOINT
GO



Short glance at our table's allocation inside data file:

DBCC IND(tempdb, split_page, -1);
GO

So we have 1 IAM page and 1 data page. Now the split itself and - remember, we should query transaction log before committing transaction if we don't want accidental checkpoint to ruine all our efforts.

ALTER EVENT SESSION MonitorPageSplits ON SERVER STATE = start;
GO

SET IDENTITY_INSERT split_page  ON;
GO
BEGIN TRAN

INSERT INTO split_page (id, id2, data1, data2)
      SELECT 111, 0, REPLICATE('a', 33), REPLICATE('b', 8000);
GO

SET IDENTITY_INSERT split_page  OFF;
GO

SELECT [Current LSN], Operation, Context, [Page ID], [Description]
FROM fn_dblog(NULL, NULL)

COMMIT
GO

ALTER EVENT SESSION MonitorPageSplits ON SERVER STATE = STOP;
GO
DROP EVENT SESSION MonitorPageSplits ON SERVER;
GO

SELECT  
   split.value('(/event/data[@name=''file_id'']/value)[1]','int') AS [file_id],
   split.value('(/event/data[@name=''page_id'']/value)[1]','int') AS [page_id],
   split.value('(/event[@name=''page_split'']/@timestamp)[1]','datetime') AS [event_time],
   split.value('(/event/action[@name=''sql_text'']/value)[1]','varchar(max)') AS [sql_text]
FROM
   (  
       SELECT CAST(event_data AS XML) AS split
       FROM sys.fn_xe_file_target_read_file('c:\temp\MonitorPageSplits*.etx', 'c:\temp\MonitorPageSplits*.mta', NULL, NULL)
   ) AS t
ORDER BY [event_time]


First let's take a look at our table now:

Transaction log contains more rows than we are interested in, so I cleaned irrelevant ones out from the table below and correlated transaction log with extended events trace. I also transformed hexadecimal page numbers from transaction log to decimal ones - like we see in extended events trace.

So we can see that indeed there have been 3 splits of the first page. From transaction log we see that first action was actually allocating of page 184 which is - look at the allocation table above - index page. According to transaction log this page is allocated - not splitted from any other page. Still extended events trace shows as if it has been splitted from the first data page of our table. Don't know whether this behavior can be considered as bug - probably not. Anyway - both unanswered question from my old post are resolved: first page indeed has been splitted 3 times and we had only 9 data page splits while 10th split belongs to index page allocation.

Have a nice week!