Как поймать чекпойнт - продолжение.

Спасибо всем, кто откликнулся. Были предложены следующие способы отлова чекпойнта. Все способы тестировались на SQL Server2008 R2 CTP3.

1. С помощью счетчика Perfomance Monitor SQLServer:Buffer Manager\Checkpoint pages/sec. Способ предложен Galliot on December 3, 2009 5:57 AM.

Среди счетчиков, которые SQL Server привносит в Perfomance Monitor, имеется счетчик Checkpoint pages/sec в категории SQLServer:Buffer Manager:

select * from sys.dm_os_performance_counters where counter_name like '%checkpoint%'

----

object_name counter_name instance_name cntr_value cntr_type

SQLServer:Buffer Manager Checkpoint pages/sec 3598 272696576

Скрипт 1

см. http://technet.microsoft.com/ru-ru/library/ms189628.aspx. Можно попробовать его использовать для отслеживания возникновении ситуации неявного чекпойнта. Наплодим кучу изменений, чтобы SQL Server осознал необходимость скинуть грязные страницы на диск и проверим показания счетчика.

if object_id('t', 'U') is not null drop table t

create table t(id int default 1)

select * from sys.dm_os_performance_counters where counter_name like '%checkpoint%'

set nocount on

declare @i int = 0

while @i < 1000 begin

 insert t values (default)

 delete t

 set @i += 1

end

select * from sys.dm_os_performance_counters where counter_name like '%checkpoint%'

Скрипт 2

 Рис.1

У меня вызывает опасение случай, когда чекпойнт вызывается явно, а грязных страниц в базе нет. Произойдет ли изменение значения показателя в этом случае?

select * from sys.dm_os_performance_counters where counter_name like '%checkpoint%'

checkpoint

select * from sys.dm_os_performance_counters where counter_name like '%checkpoint%'

checkpoint

select * from sys.dm_os_performance_counters where counter_name like '%checkpoint%'

checkpoint

checkpoint

select * from sys.dm_os_performance_counters where counter_name like '%checkpoint%'    

Скрипт 3

Рис.2

И мы видим, что нет - изменение показателя произошло только после первого явного вызова оператора CHECKPOINT. Откуда-то нашлись несчастные 5 страничек, которые SQL Server решил на всякий случай записать на диск. Потом совсем голяк на последующих 3-х вызовах. Он и не дергался понапрасну, хотя чекпойнт, вы видите, вызывался.

Однако, строго говоря, задача ставилась "как узнать, что произошел неявный чекпойнт?" Очевидно, что неявный чекпойнт произойдет только когда назрели достаточное кол-во страниц для записи, т.е. счетчик по-любому изменится. Данный способ ее решает. Спасибо Galliot.

 

2. С помощью флага трассировки 3502 и SQL Error Log. Способ предложен Dimsp on December 3, 2009 7:54 AM.

Иллюстрацию применения этого способа можно видеть в книге покойного Кена Хендерсона "The Guru's guide to SQL server stored procedures, XML, and HTML" (глава 22 "Undocumented Transact-SQL", стр.671). При включении флага трассировки 3502 информация о событии чекпойнт начинает выводиться в SQL Server Error Log. Для чтения Error Log'a воспользуемся недокументированной расширенной хранимой процедурой xp_readerrorlog. Информацию о ее использовании можно посмотреть, например, здесь - http://www.mssqltips.com/tip.asp?tip=1476. Она принимает следующие параметры:

· Value of error log file you want to read: 0 = current, 1 = Archive #1, 2 = Archive #2, etc...

· Log file type: 1 or 1 = error log, 2 = SQL Agent log

· Search string 1: String one you want to search for

· Search string 2: String two you want to search for to further refine the results

· Search from start time

· Search to end time

· Sort order for results: N'asc' = ascending, N'desc' = descending

Кроме того, нам понадобится всем знакомый с детства флаг 3604, направляющий информацию о выполнении команд трассировки в консоль (3605 - в Error Log).

 

dbcc traceon(3604)

Скрипт 4

Убеждаемся, что флаг 3502 в начальный момент выключен:

dbcc tracestatus(3502) --обо всех включенных - -1

---

TraceFlag Status Global Session

3502 0 0 0

Скрипт 5

и информация о чекпойнтах не отражается в Error Log'e:

checkpoint

exec xp_readerrorlog 0, 1, '', '', null, null, N'desc'

---

LogDate ProcessInfo Text

2009-12-04 12:12:34.450 spid52 DBCC TRACEON 3604, server process ID (SPID) 52. This is an informational message only; no user action is required.

2009-12-04 00:00:58.800 spid22s This instance of SQL Server has been using a process ID of 1752 since 18/11/2009 8:56:41 AM (local) 18/11/2009 5:56:41 AM (UTC). This is an informational message only; no user action is required.

2009-12-03 12:47:58.500 spid1s A significant part of sql server process memory has been paged out. This may result in a performance degradation. Duration: 57616 seconds. Working set (KB): 23384, committed (KB): 58960, memory utilization: 39%.

...

Скрипт 6

Включаем флаг 3502 и проверяем снова:

dbcc traceon(3502, -1)

checkpoint

Скрипт 7

exec xp_readerrorlog 0, 1, '', '', null, null, N'desc'

Скрипт 8

LogDate ProcessInfo Text

2009-12-04 12:33:19.290 spid52 Ckpt dbid 9 complete

2009-12-04 12:33:19.250 spid52 About to log Checkpoint end.

2009-12-04 12:33:19.250 spid52 Ckpt dbid 9 phase 1 ended (8)

2009-12-04 12:33:19.210 spid52 About to log Checkpoint begin.

2009-12-04 12:33:19.210 spid52 Ckpt dbid 9 started (8)

2009-12-04 12:33:11.880 spid52 DBCC TRACEON 3502, server process ID (SPID) 52. This is an informational message only; no user action is required.

2009-12-04 12:12:34.450 spid52 DBCC TRACEON 3604, server process ID (SPID) 52. This is an informational message only; no user action is required.

Теперь инициируем наступление неявного чекпойнта:

if object_id('t', 'U') is not null drop table t

create table t(id int default 1)

set nocount on

while 1 = 1 begin

 insert t values (default)

 delete t

end

Скрипт 9

Пусть покрутится секунд 5. Снова смотрим Error Log:

LogDate ProcessInfo Text

2009-12-04 12:37:52.630 spid11s Ckpt dbid 9 complete

2009-12-04 12:37:52.630 spid11s About to log Checkpoint end.

2009-12-04 12:37:52.620 spid11s Ckpt dbid 9 phase 1 ended (8)

2009-12-04 12:37:52.620 spid11s About to log Checkpoint begin.

2009-12-04 12:37:52.620 spid11s Ckpt dbid 9 started (8)

2009-12-04 12:37:52.220 spid11s Ckpt dbid 9 complete

2009-12-04 12:37:52.220 spid11s About to log Checkpoint end.

2009-12-04 12:37:52.140 spid11s Ckpt dbid 9 phase 1 ended (8)

2009-12-04 12:37:52.120 spid11s About to log Checkpoint begin.

2009-12-04 12:37:52.120 spid11s Ckpt dbid 9 started (8)

2009-12-04 12:33:19.290 spid52 Ckpt dbid 9 complete

2009-12-04 12:33:19.250 spid52 About to log Checkpoint end.

2009-12-04 12:33:19.250 spid52 Ckpt dbid 9 phase 1 ended (8)

2009-12-04 12:33:19.210 spid52 About to log Checkpoint begin.

2009-12-04 12:33:19.210 spid52 Ckpt dbid 9 started (8)

2009-12-04 12:33:11.880 spid52 DBCC TRACEON 3502, server process ID (SPID) 52. This is an informational message only; no user action is required.

2009-12-04 12:12:34.450 spid52 DBCC TRACEON 3604, server process ID (SPID) 52. This is an informational message only; no user action is required.

Скрипт 10

При включенном трейс-флаге 3502 в журнале ошибок отражается информация как о явных, так и неявных чекпойнтах. Спасибо Dimsp.

 

3. Добавлю до кучи способ мониторинга чекпойнтов с помощью расширенных событий.

Надысь я болел, сидел дома и от безысходности читал Books On-Line. Я понимаю, что вы меня сейчас покроете презрением. Как известно, настоящие программёры мануалов не читают, ибо они выше этого. Так я же говорю - болел L. Я читал раздел про расширенные события в 2008. Например, в посте http://blogs.technet.com/isv\_team/archive/2009/11/28/3296771.aspx мы решали задачу мониторинга логинов, заходящих на SQL Server в промежуток времени, при помощи оператора CREATE AUDIT. Расширенные события (XEvents) - приблизительно такая же хрень, только шире. И там прямо в качестве иллюстрации дается пример 1:1 на отлов чекпойнтов, т.е. событий checkpoint_begin и checkpoint_end. Чтобы не заниматься копи-пастом, я его слегка модифицирую. К примеру, зачем нам в кач-ве таргета asynchronous_bucketizer? Мы не собираемся агрегировать чекпойнты, а хотим просматривать каждое по отдельности. В файл журналировать не будем, чтобы не заморачиваться, пусть пока все остается в памяти, т.е. берем в кач-ве таргета ring_buffer. Единственно, я не нашел, как при создании сессии подпихнуть базу по имени, только по id. Ладно, смотрим id интересующей базы

select db_id('AdventureWorks2008R2')

и подставляем его в параметры сессии расширенных событий:

if exists(select 1 from sys.server_event_sessions where name = 'CaptureCheckpoint')

 drop event session CaptureCheckpoint on server

go

create event session CaptureCheckpoint on server

add event sqlserver.checkpoint_begin

(action (sqlserver.sql_text) where sqlserver.database_id = 5), --AdventureWorks

add event sqlserver.checkpoint_end

(action (sqlserver.sql_text) where sqlserver.database_id = 5)

add target package0.ring_buffer

(set max_memory = 4096)

with (max_dispatch_latency = 1 seconds)

Скрипт 11

alter event session CaptureCheckpoint on server state = start; --стартуем сессию

И проверяем

use AdventureWorks2008R2

явный чекпойнт

checkpoint

и неявный (см. Скрипт 9):

if object_id('t', 'U') is not null drop table t

create table t(id int default 1)

set nocount on

while 1 = 1 begin

 insert t values (default)

 delete t

end

Смотрим, что получилось.

select *

from sys.dm_xe_session_targets xest

join sys.dm_xe_sessions xes on xes.address = xest.event_session_address

where xest.target_name = 'ring_buffer' and xes.name = 'CaptureCheckpoint'

Скрипт 12

Лучше так для наглядности:

declare @x xml

select @x = cast(xest.target_data as xml)

from sys.dm_xe_session_targets xest

join sys.dm_xe_sessions xes on xes.address = xest.event_session_address

where xest.target_name = 'ring_buffer' and xes.name = 'CaptureCheckpoint'

select @x

Скрипт 13

Рис.3

Первые два события - это начало и конец явного чекпойнта. У них стоит в качестве sql_text - checkpoint. Все остальное - это посыпались неявные чекпойнты в цикле модификации таблицы. Легким упражнением на SQL XML превращаем журнал расширенных событий в более сжатый удобочитаемый формат:

select

x.value('@name[1]', 'varchar(100)') event,

x.value('@timestamp[1]', 'datetime') [time],

x.value('(data[@name="database_id"]/value)[1]', 'int') dbid,

x.value('(action[@name="sql_text"]/value)[1]', 'nvarchar(max)') sql

from @x.nodes('RingBufferTarget/event') t(x)

Скрипт 14

 

Рис.4

Это был третий способ отлова чекпойнтов. Спасибо BOL.

Итого. На данный момент в нашей интеллектуальной копилке 3 способа, позволяющих узнать о наступлении события чекпойнта: 1) Perfomance Monitor и в нем счетчик SQLServer:Buffer Manager\Checkpoint pages/sec; 2) Флаг 3502, включающий регистрацию чекпойнтов в SQL Error Log; 3) XEvents с событиями checkpoint_begin, checkpoint_end. По сравнению с 1) Способ 2 позволяет увидеть id базы, в которой случился чекпойнт, а Способ 3 дополнительно еще и различить ситуацию явного и неявного чекпойнта.

 

Алексей Шуленин