Hачну издалека. Счастливые обладатели SQL Server 2008 знают про атрибут filestream. Oн позволяет хранить varbinary(max) в файловой системе. Не в смысле файла БД, а когда под каждую такую ячейку заводится файл на диске. Проще стриминговый доступ плюс снимается ограничение на размер блоба в 2 гига. Многие до этого так и делали: контент хранили в файле, а в таблицу выносили атрибуты документа плюс линк на файл. В случае filestream оные файлы перестают быть посторонними по отношению к SQL Server. Они становится ему близкими и родными. SQL Server начинает их холить, лелеять, поддерживать над ними транзакционность, бэкап, полнотекст, репликацию, лог шиппинг, кластеризацию и все дела. Помните красивые слова WinFS, SQL Server File System и все такое? Filestream - это осколок Атлантиды. Но сейчас речь не об этом. В документации недостаточно явно отражен момент, что при операциях DELETE и непрямого UPDATE в файловой системе создается новый файл, между тем как файл со старым значением остается. Рано или поздно (чем больше гиг киношки, тем раньше), народ начинает искать, куда делось место на диске, находит и озабачивается вопросом, как бы старые версии того? Прибрать. Старые версии прибираются по чекпойнту. Скорее всего, по той же причине, почему на диск не скидываются по отдельности грязные записи после каждого изменения. Быстрее получается накопить их до кучи и записать разом, чем отвлекаться на каждую отдельно. Встала задача наглядно и красиво продемонстрировать данное поведение во время семинара. Вот смотрите - в базе наступает чекпойнт и старые файлы при этом автоматически удаляются. Кто подскажет, как отловить чекпойнт?
Спасибо всем, кто откликнулся. Были предложены следующие способы отлова чекпойнта. Все способы тестировались на SQL Server 2008 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
Открыть в полный размер' href="http://blogs.technet.com/blogfiles/isv_team/WindowsLiveWriter/902429db61ad_CBD3/image_2.png" target=_blank style=color:white;>Открыть в полный размер' href="http://blogs.technet.com/blogfiles/isv_team/WindowsLiveWriter/902429db61ad_CBD3/image_2.png" mce_href="http://blogs.technet.com/blogfiles/isv_team/WindowsLiveWriter/902429db61ad_CBD3/image_2.png">
Рис.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
Открыть в полный размер' href="http://blogs.technet.com/blogfiles/isv_team/WindowsLiveWriter/902429db61ad_CBD3/image_4.png" target=_blank style=color:white;>Открыть в полный размер' href="http://blogs.technet.com/blogfiles/isv_team/WindowsLiveWriter/902429db61ad_CBD3/image_4.png" mce_href="http://blogs.technet.com/blogfiles/isv_team/WindowsLiveWriter/902429db61ad_CBD3/image_4.png">
И мы видим, что нет - изменение показателя произошло только после первого явного вызова оператора 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
Открыть в полный размер' href="http://blogs.technet.com/blogfiles/isv_team/WindowsLiveWriter/902429db61ad_CBD3/image_6.png" target=_blank style=color:white;>Открыть в полный размер' href="http://blogs.technet.com/blogfiles/isv_team/WindowsLiveWriter/902429db61ad_CBD3/image_6.png" mce_href="http://blogs.technet.com/blogfiles/isv_team/WindowsLiveWriter/902429db61ad_CBD3/image_6.png">
Рис.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
Открыть в полный размер' href="http://blogs.technet.com/blogfiles/isv_team/WindowsLiveWriter/902429db61ad_CBD3/image_8.png" target=_blank style=color:white;>Открыть в полный размер' href="http://blogs.technet.com/blogfiles/isv_team/WindowsLiveWriter/902429db61ad_CBD3/image_8.png" mce_href="http://blogs.technet.com/blogfiles/isv_team/WindowsLiveWriter/902429db61ad_CBD3/image_8.png">
Рис.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 дополнительно еще и различить ситуацию явного и неявного чекпойнта.