Как поймать чекпойнт - продолжение.
Спасибо всем, кто откликнулся. Были предложены следующие способы отлова чекпойнта. Все способы тестировались на 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 дополнительно еще и различить ситуацию явного и неявного чекпойнта.
Алексей Шуленин