遅延耐久性、または自動テストの実行を11分から2.5分にスピードアップすることが判明した経緯





比較的最近、私は実際に就業時間を追跡するための無料のWebサービスとして開発されている新しい製品プロジェクトの支援を始めました。



テクノロジースタックは最初は小規模に選択され、 SQL Server 2014 Expressがデータストアとして使用されました。 私に与えられた最初のタスクの1つは、自動テストを高速化する可能性を調査することでした。



仕事に携わる前に、プロジェクトは長い間存在し、すでにかなりの量のテストを取得することができました(その時点で1300の自動テストをカウントしました)。 SSDを搭載したビルドマシンでは4〜5分テストが実行され、通常のHDDでは 11〜12分以上テストが実行されました。 SSDをチーム全体に提供することは可能ですが、特に近い将来、機能を拡張する予定であり、さらに多くのテストがあるため、これは問題の本質を解決しません。



すべてのテストがグループ化され、各グループが実行される前に、データベースから古いデータが消去されました。 以前は、データベースの再作成によってクリーニングが行われていましたが、このアプローチは実際には非常に遅かったです。 すべてのデータテーブルを単純にクリアし、 IDENTITY値をゼロにリセットして、後続の挿入が正しいテストデータを形成するようにした方がはるかに高速でした。 このアプローチのスクリプトは、私の出発点でした。



EXEC sys.sp_msforeachtable 'ALTER TABLE ? NOCHECK CONSTRAINT ALL' DELETE FROM [dbo].[Project] DBCC CHECKIDENT('[dbo].[Project]', RESEED, 0) DBCC CHECKIDENT('[dbo].[Project]', RESEED) DELETE FROM [dbo].[RecentWorkTask] ... EXEC sys.sp_msforeachtable 'ALTER TABLE ? WITH CHECK CHECK CONSTRAINT ALL'
      
      





私の目を引いた最初のことは、ベース上のすべての定数のシャットダウンと再包含でした。 この動作は削除操作を高速化することを目的としていましたが、実際にはサーバーのリソースを集中的に使用する操作であることが判明しました。 このアプローチの使用を放棄することにしました。



また、アイデアはすぐに動的SQLを使用してクエリを形成し、データを削除するように見えました。 たとえば、テーブルに外部キーがある場合、以前のようにDELETE操作を使用できます。そうでない場合は、 TRUNCATEコマンドを使用して最小限のログでデータを削除できます。



その結果、データの削除要求は次の形式を取りました。



 DECLARE @SQL NVARCHAR(MAX) = '' SELECT @SQL = ( SELECT CASE WHEN p.[object_id] IS NOT NULL THEN CASE WHEN f.referenced_object_id IS NULL THEN N'TRUNCATE TABLE ' ELSE N'DELETE FROM ' END + obj_name ELSE '' END + CHAR(13) + CHAR(10) + CASE WHEN has_identity > 0 THEN N'DBCC CHECKIDENT('''+ obj_name + N''', RESEED, 0) WITH NO_INFOMSGS' ELSE '' END + CHAR(13) + CHAR(10) FROM ( SELECT obj_name = QUOTENAME(s.name) + '.' + QUOTENAME(o.name) , o.[object_id] , has_identity = IdentityProperty(o.[object_id], 'LastValue') FROM sys.objects o JOIN sys.schemas s ON o.[schema_id] = s.[schema_id] WHERE o.is_ms_shipped = 0 AND o.[type] = 'U' ) t LEFT JOIN ( SELECT DISTINCT [object_id] FROM sys.partitions WHERE [rows] > 0 AND index_id IN (0, 1) ) p ON t.[object_id] = p.[object_id] LEFT JOIN ( SELECT DISTINCT referenced_object_id FROM sys.foreign_keys ) f ON f.referenced_object_id = t.[object_id] FOR XML PATH(''), TYPE).value('.', 'NVARCHAR(MAX)') PRINT @SQL --EXEC sys.sp_executesql @SQL
      
      





そして、私のマシンで最初に自動テストが11分間実行された場合:







その後、 ALTERステートメントを投げてリクエストを書き直した後、すべてのテストの実行が40秒速くなりました。







もちろん、私たちは喜んでタスクの解決済みステータスを静かに設定できますが、主な問題は残っています。







テスト中、ディスクの負荷は非常に高くなりました。 私はサーバーに何が期待されているかを見ることにしました。 これを行うには、最初にsys.dm_os_wait_statsを削除しました



 DBCC SQLPERF("sys.dm_os_wait_stats", CLEAR)
      
      





自動テストの実行を再開し、要求を満たした後:



 SELECT TOP(20) wait_type , wait_time = wait_time_ms / 1000. , wait_resource = (wait_time_ms - signal_wait_time_ms) / 1000. , wait_signal = signal_wait_time_ms / 1000. , waiting_tasks_count , percentage = 100.0 * wait_time_ms / SUM(wait_time_ms) OVER () , avg_wait = wait_time_ms / 1000. / waiting_tasks_count , avg_wait_resource = (wait_time_ms - signal_wait_time_ms) / 1000. / [waiting_tasks_count] , avg_wait_signal = signal_wait_time_ms / 1000.0 / waiting_tasks_count FROM sys.dm_os_wait_stats WHERE [waiting_tasks_count] > 0 AND max_wait_time_ms > 0 AND [wait_type] NOT IN ( N'BROKER_EVENTHANDLER', N'BROKER_RECEIVE_WAITFOR', N'BROKER_TASK_STOP', N'BROKER_TO_FLUSH', N'BROKER_TRANSMITTER', N'CHECKPOINT_QUEUE', N'CHKPT', N'CLR_AUTO_EVENT', N'CLR_MANUAL_EVENT', N'CLR_SEMAPHORE', N'DBMIRROR_DBM_EVENT', N'DBMIRROR_EVENTS_QUEUE', N'DBMIRROR_WORKER_QUEUE', N'DBMIRRORING_CMD', N'DIRTY_PAGE_POLL', N'DISPATCHER_QUEUE_SEMAPHORE', N'EXECSYNC', N'FSAGENT', N'FT_IFTS_SCHEDULER_IDLE_WAIT', N'FT_IFTSHC_MUTEX', N'HADR_CLUSAPI_CALL', N'HADR_FILESTREAM_IOMGR_IOCOMPLETION', N'HADR_LOGCAPTURE_WAIT', N'HADR_NOTIFICATION_DEQUEUE', N'HADR_TIMER_TASK', N'HADR_WORK_QUEUE', N'KSOURCE_WAKEUP', N'LAZYWRITER_SLEEP', N'LOGMGR_QUEUE', N'ONDEMAND_TASK_QUEUE', N'PWAIT_ALL_COMPONENTS_INITIALIZED', N'QDS_PERSIST_TASK_MAIN_LOOP_SLEEP', N'QDS_CLEANUP_STALE_QUERIES_TASK_MAIN_LOOP_SLEEP', N'REQUEST_FOR_DEADLOCK_SEARCH', N'RESOURCE_QUEUE', N'SERVER_IDLE_CHECK', N'SLEEP_BPOOL_FLUSH', N'SLEEP_DBSTARTUP', N'SLEEP_DCOMSTARTUP', N'SLEEP_MASTERDBREADY', N'SLEEP_MASTERMDREADY', N'SLEEP_MASTERUPGRADED', N'SLEEP_MSDBSTARTUP', N'SLEEP_SYSTEMTASK', N'SLEEP_TASK', N'SLEEP_TEMPDBSTARTUP', N'SNI_HTTP_ACCEPT', N'SP_SERVER_DIAGNOSTICS_SLEEP', N'SQLTRACE_BUFFER_FLUSH', N'SQLTRACE_INCREMENTAL_FLUSH_SLEEP', N'SQLTRACE_WAIT_ENTRIES', N'WAIT_FOR_RESULTS', N'WAITFOR', N'WAITFOR_TASKSHUTDOWN', N'WAIT_XTP_HOST_WAIT', N'WAIT_XTP_OFFLINE_CKPT_NEW_LOG', N'WAIT_XTP_CKPT_CLOSE', N'XE_DISPATCHER_JOIN', N'XE_DISPATCHER_WAIT', N'XE_TIMER_EVENT' ) ORDER BY [wait_time_ms] DESC
      
      





最大の遅延はWRITELOGで観察されます。



 wait_type wait_time waiting_tasks_count percentage ----------------------- ------------ -------------------- ----------- WRITELOG 546.798 60261 96.07 PAGEIOLATCH_EX 13.151 96 2.31 PAGELATCH_EX 5.768 46097 1.01 PAGEIOLATCH_UP 1.243 86 0.21 IO_COMPLETION 1.158 89 0.20 MEMORY_ALLOCATION_EXT 0.480 683353 0.08 LCK_M_SCH_S 0.200 34 0.03 ASYNC_NETWORK_IO 0.115 688 0.02 LCK_M_S 0.082 10 0.01 PAGEIOLATCH_SH 0.052 1 0.00 PAGELATCH_UP 0.037 6 0.00 SOS_SCHEDULER_YIELD 0.030 3598 0.00
      
      





Paul Randalによる「期待の百科事典」を開き、 MSDNを確認しながらWRITELOGを見つけます。



これは、ディスクへのログフラッシュを待機しているログ管理システムです。 一般に、I / Oサブシステムがログフラッシュボリュームに対応できないことを示していますが、非常に大容量のシステムでは、内部ログフラッシュの制限が原因である可能性があり、ワークロードを複数のデータベースに分割する必要がある場合がありますまたは、ログフラッシュを減らすためにトランザクションを少し長くします。 I / Oサブシステムであることを確認するには、DMV sys.dm_io_virtual_file_statsを使用してログファイルのI / Oレイテンシを調べ、平均WRITELOG時間と相関するかどうかを確認します。 WRITELOGの方が長い場合、内部競合が発生し、シャードする必要があります。 そうでない場合は、なぜ大量のトランザクションログを作成しているのか調査してください。



ログ管理サブシステムは、ログがディスクに書き込まれるのを待っています。 原則として、ディスクシステムはログボリューム全体のタイムリーな記録を提供できないことを意味しますが、高負荷のシステムでは、これはログ記録の一般的な制限が原因である可能性がありますディスクへのログエントリの数を減らすために長い。 原因がI / Oシステムにあることを確認するには、 DMV sys.dm_io_virtual_file_statsを使用してログファイルのI / O遅延を調べ、 WRITELOG遅延時間と一致するかどうかを確認します。 WRITELOGの持続時間が長い場合は、ディスクへの書き込みに関して内部競合が発生しているため、負荷を分担する必要があります。 そうでない場合は、なぜこのような大きなトランザクションログを作成するのかを調べてください。



それで、私はまだ何を見つける必要がありますか? はい、各自動テストは実行中にデータベースに何かを書き込みます。 WRITELOGの予想に関する問題の解決策として、データを行ではなく、より大きなチャンクに挿入することが可能です。 しかし、 SQL Server 2014では、 遅延オプションの基本レベルに新しいオプションが追加されました。つまり、トランザクションをコミットするときにデータをすぐにディスクにフラッシュしない機能です。



SQL Serverでデータはどのように変更されますか? 新しい行を挿入するとします。 SQL ServerStorage Engineを呼び出します。StorageEngineはBuffer Manager (メモリとディスク内のバッファーで動作します)を呼び出し、データを変更したいと言います。



その後、 バッファマネージャバッファプール (すべてのデータのメモリ内のキャッシュで、ページごとに情報を保存する-ページごとに8 KB)にアクセスし、メモリ内の必要なページを変更します。 これらのページが存在しない場合、ディスクからそれらをロードします。 メモリ内のページが変更された時点で、 SQL Serverはクエリが完了したとはまだ言えません。 そうしないと、変更の最後にデータがディスクに書き込まれることが保証されると、 ACIDの原則の1つであるDurabilityに違反します。



メモリ内のページを変更した後、 ストレージエンジンログマネージャーを呼び出し、 ログにデータを書き込みます。 しかし、彼はすぐにそれを行いませんが、サイズが60Kbで、ログを操作するときのパフォーマンスを最適化するために使用されるLog Bufferを使用します。 バッファからログファイルへのデータダンプは、次の場合に発生します。





データがログに保存されると、データが変更されたことが確認され、 SQL Serverはそのことをクライアントに通知します。



このロジックによれば、データがデータファイルに分類されないことがわかります。 SQL Serverは、非同期メカニズムを使用してデータファイルに書き込みます。 そのようなメカニズムは2つあります。



1)定期的に実行されるLazy WriterはSQL Serverに十分なメモリがあるかどうかを確認します 。 そうでない場合、ページはメモリから消去され、データファイルに書き込まれます。 そして、変更されたものはディスクにフラッシュされ、メモリから排出されます。



2) チェックポイント 、ダーティページを約1分間に1回スキャンし、ディスクにフラッシュしてメモリに残します。



たとえば、データが1行ずつ変更されるような小規模なトランザクションがシステムで大量に発生する状況を想定します。 各変更後、データはログバッファからトランザクションログに送られます。 すべての変更は同期的にログに反映され、他のトランザクションは順番に待機する必要があることに注意してください。



例を示しましょう:



 USE [master] GO SET NOCOUNT ON IF DB_ID('TT') IS NOT NULL BEGIN ALTER DATABASE TT SET SINGLE_USER WITH ROLLBACK IMMEDIATE DROP DATABASE TT END GO CREATE DATABASE TT GO ALTER DATABASE TT MODIFY FILE (NAME = N'TT', SIZE = 25MB, FILEGROWTH = 5MB) GO ALTER DATABASE TT MODIFY FILE (NAME = N'TT_log', SIZE = 25MB, FILEGROWTH = 5MB) GO USE TT GO CREATE TABLE dbo.tbl ( a INT IDENTITY PRIMARY KEY , b INT , c CHAR(2000) ) GO IF OBJECT_ID('tempdb.dbo.#temp') IS NOT NULL DROP TABLE #temp GO SELECT t.[file_id], t.num_of_writes, t.num_of_bytes_written INTO #temp FROM sys.dm_io_virtual_file_stats(DB_ID(), NULL) t DECLARE @WaitTime BIGINT , @WaitTasks BIGINT , @StartTime DATETIME = GETDATE() , @LogRecord BIGINT = ( SELECT COUNT_BIG(*) FROM sys.fn_dblog(NULL, NULL) ) SELECT @WaitTime = wait_time_ms , @WaitTasks = waiting_tasks_count FROM sys.dm_os_wait_stats WHERE [wait_type] = N'WRITELOG' DECLARE @i INT = 1 WHILE @i < 5000 BEGIN INSERT INTO dbo.tbl (b, c) VALUES (@i, 'text') SELECT @i += 1 END SELECT elapsed_seconds = DATEDIFF(MILLISECOND, @StartTime, GETDATE()) * 1. / 1000 , wait_time = (wait_time_ms - @WaitTime) / 1000. , waiting_tasks_count = waiting_tasks_count - @WaitTasks , log_record = ( SELECT COUNT_BIG(*) - @LogRecord FROM sys.fn_dblog(NULL, NULL) ) FROM sys.dm_os_wait_stats WHERE [wait_type] = N'WRITELOG' SELECT [file] = FILE_NAME(o.[file_id]) , num_of_writes = t.num_of_writes - o.num_of_writes , num_of_mb_written = (t.num_of_bytes_written - o.num_of_bytes_written) * 1. / 1024 / 1024 FROM #temp o CROSS APPLY sys.dm_io_virtual_file_stats(DB_ID(), NULL) t WHERE o.[file_id] = t.[file_id]
      
      





5,000行の挿入には約42.5秒かかりましたが、ログへの挿入中の遅延は42秒になりました。



 elapsed_seconds wait_time waiting_tasks_count log_record ---------------- ---------- -------------------- ----------- 42.54 42.13 5003 18748
      
      





物理的に、SQL Serverはログに5,000回アクセスし、合計20MBを記録しました。



 file num_of_writes num_of_mb_written ------- -------------- ------------------ TT 79 8.72 TT_log 5008 19.65
      
      





このような状況のために、 遅延耐久性が必要です。 オンにすると、 ログバッファがいっぱいになったときにのみログが記録されます。 データベース全体に対して遅延耐久性を有効にできます。



 ALTER DATABASE TT SET DELAYED_DURABILITY = FORCED GO
      
      





または個々のトランザクションの場合:



 ALTER DATABASE TT SET DELAYED_DURABILITY = ALLOWED GO BEGIN TRANSACTION t ... COMMIT TRANSACTION t WITH (DELAYED_DURABILITY = ON)
      
      





基本レベルでオンにして、スクリプトを再実行します。



期待は消え、リクエストは私のマシンで170ミリ秒間機能しました。



 elapsed_seconds wait_time waiting_tasks_count log_record ---------------- ---------- -------------------- ----------- 0.17 0.00 0 31958
      
      





ロギングがそれほど強力ではなかったという事実のため:



 file num_of_writes num_of_mb_written ------- -------------- ------------------ TT 46 9.15 TT_log 275 12.92
      
      





もちろん、軟膏にはハエがあります。 データが物理的にログファイルに記録される前であっても、クライアントには変更がコミットされたことがすでに通知されています。 障害が発生した場合、バッファのサイズに等しいデータが失われ、ベースを超える可能性があります。



私の場合、テストデータの安全性は必要ありませんでした。 自動テストが実行されたテストベースについては、 DELAYED_DURABILITYFORCED 設定すると、すべてのテストの次の実行が2.5分で機能しました。







また、ロギングに関連するすべての遅延がパフォーマンスへの影響を最小限に抑え始めました。



 wait_type wait_time waiting_tasks_count percentage -------------------- ----------- -------------------- ----------- PAGEIOLATCH_EX 16.031 61 43.27 WRITELOG 15.454 787 41.72 PAGEIOLATCH_UP 2.210 36 5.96 PAGEIOLATCH_SH 1.472 2 3.97 LCK_M_SCH_M 0.756 9 2.04 ASYNC_NETWORK_IO 0.464 735 1.25 PAGELATCH_UP 0.314 8 0.84 SOS_SCHEDULER_YIELD 0.154 2759 0.41 PAGELATCH_EX 0.154 44785 0.41 LCK_M_SCH_S 0.021 7 0.05 PAGELATCH_SH 0.011 378 0.02
      
      





遅延耐久性を要約するには:





更新2016-07-12:データ削除スクリプトがより機能的になりました
 DECLARE @SQL NVARCHAR(MAX) , @FK_TurnOff NVARCHAR(MAX) , @FK_TurnOn NVARCHAR(MAX) SELECT @SQL = ( SELECT CHAR(13) + CHAR(10) + IIF(p.[rows] > 0, IIF(t2.referenced_object_id IS NULL, N'TRUNCATE TABLE ', N'DELETE FROM ') + obj_name, '' ) + CHAR(13) + CHAR(10) + IIF(IdentityProperty(t.[object_id], 'LastValue') > 0, N'DBCC CHECKIDENT('''+ obj_name + N''', RESEED, 0) WITH NO_INFOMSGS', '' ) FROM ( SELECT obj_name = QUOTENAME(s.name) + '.' + QUOTENAME(o.name), o.[object_id] FROM sys.objects o JOIN sys.schemas s ON o.[schema_id] = s.[schema_id] WHERE o.is_ms_shipped = 0 AND o.[type] = 'U' AND o.name != N'__MigrationHistory' ) t JOIN sys.partitions p ON t.[object_id] = p.[object_id] AND p.index_id IN (0, 1) LEFT JOIN ( SELECT DISTINCT f.referenced_object_id FROM sys.foreign_keys f ) t2 ON t2.referenced_object_id = t.[object_id] FOR XML PATH(''), TYPE).value('.', 'NVARCHAR(MAX)') SELECT @FK_TurnOff = CAST(x.query('off/text()') AS NVARCHAR(MAX)) , @FK_TurnOn = CAST(x.query('on/text()') AS NVARCHAR(MAX)) FROM ( SELECT [off] = CHAR(10) + 'ALTER TABLE ' + obj + ' NOCHECK CONSTRAINT ' + fk , [on] = CHAR(10) + 'ALTER TABLE ' + obj + ' CHECK CONSTRAINT ' + fk FROM ( SELECT fk = QUOTENAME(f.name) , obj = QUOTENAME(SCHEMA_NAME(f.[schema_id])) + '.' + QUOTENAME(OBJECT_NAME(f.parent_object_id)) FROM sys.foreign_keys f WHERE f.delete_referential_action = 0 AND EXISTS( SELECT * FROM sys.partitions p WHERE p.[object_id] = f.parent_object_id AND p.[rows] > 0 AND p.index_id IN (0, 1) ) ) t FOR XML PATH(''), TYPE ) t(x) IF @SQL LIKE '%[az]%' BEGIN SET @SQL = ISNULL(@FK_TurnOff, '') + @SQL + ISNULL(@FK_TurnOn, '') PRINT @SQL --EXEC sys.sp_executesql @SQL END
      
      







この記事を英語圏の聴衆と共有したい場合:

遅延耐久性、または自動テストを11分から2.5分に短縮する方法のストーリー



All Articles