SQL Server AlwaysOn synchronous-commit 환경에서 동기화 레이턴시 트러블슈팅

SQL Server AlwaysOn synchronous-commit 환경에서 동기화 레이턴시 트러블슈팅 Version : SQL Server 

 

SQL Server AlwaysOn synchronous-commit(동기 커밋) 환경에서HADR_SYNC_COMMIT 대기 정보를 이용해서 레이턴시 상태를 확인할 수 있다.

HADR_SYNC_COMMIT대기는 SQL Server가 원격 복제본의 신호가 트랜잭션을 커밋하기를 기다리고 있음을 나타낸다.

트래잭션 커밋 대기 시간에 대한 자세한 정보는 아래 링크를 확인한다.Troubleshooting High HADR_SYNC_COMMIT wait type with Always On Availability Groups : https://blogs.msdn.microsoft.com/sql_server_team/troubleshooting-high-hadr_sync_commit-wait-type-with-always-on-availability-groups/SQL Server 2012 AlwaysOn – Part 12 – Performance Aspects and Performance Monitoring II : https://blogs.msdn.microsoft.com/saponsqlserver/2013/04/24/sql-server-2012-alwayson-part-12-performance-aspects-and-performance-monitoring-ii/ 

 

위 두 링크를 살펴보면 트랜잭션 지연은 다음 두 성능 카운터로 평가하는 것을 알 수 있다.

SQL Server:Database Replica –> Transaction DelaySQL Server:Database Replica –> Mirrored Write Transactions/sec 예를 들어 AG에서 노드 성능이 좋지 않아 "SQL Server:Database Replica –> Transaction Delay = 1000ms" 이고 "SQL Server:Database Replica –> Mirrored Write Transactions/sec = 50"이라고 가정하면 평균적으로 트랜잭션 지연시간은 1000ms/50= 20ms 이다.

 

동기 커밋에 대한 자세한 정보는 아래 링크를 확인한다.AlwaysON – HADRON Learning Series: – How does AlwaysON Process a Synchronous Commit Request : https://blogs.msdn.microsoft.com/psssql/2011/04/01/alwayson-hadron-learning-series-how-does-alwayson-process-a-synchronous-commit-request/Update adds AlwaysOn extended events and performance counters in SQL Server 2014 or 2016 : https://support.microsoft.com/en-us/help/3173156/update-adds-alwayson-extended-events-and-performance-counters-in-sql-s 

 

아래 그림은 동기 커밋 모드에서 로그 블록이 Replica 서버에 커밋 되는 각 단계마다 XEvent가 캡쳐 되는 흐름을 보여준다.

 

 

 위 그림에서 살펴보면 XEvent 추적이 캡처되면 로그 블록 이동의 각 단계에서 중요한 시점을 알 수 있으므로 트랜잭션 대기 시간의 정확한 위치를 알 수 있다. 일반적으로 지연은 세 부분으로 나누어진다.

Primary 서버에서 log harden 지속 시간 Log_flush_start(step 2) 및 Log_flush_complete(step 3)의 델타 시간은 동일하다.

Replica 서버에서 log harden 지속 시간 Log_flush_start(step 10) 및 Log_flush_complete(step 11)의 델타 시간은 동일하다.

네트워크 트래픽의 지속 시간 Primary : hadr_log_block_send_complete ->secondary:hadr_transport_receive_log_block_message (step 6-7)Secondary : hadr_lsn_send_complete->primary:hadr_receive_harden_lsn_message (step 12-13)

 

 아래 스크립트는XEvent를 사용하여 각 단계에 소요되는 시간을 캡처할 수 있다.

/* Note: this trace could generate very large amount of data very quickly, depends on the actual transaction rate. On a busy server it can grow several GB per minute, so do not run the script too long to avoid the impact to the production server. */  CREATE EVENT SESSION [AlwaysOn_Data_Movement_Tracing] ON SERVER ADD EVENT sqlserver.file_write_completed, ADD EVENT sqlserver.file_write_enqueued, ADD EVENT sqlserver.hadr_apply_log_block, ADD EVENT sqlserver.hadr_apply_vlfheader, ADD EVENT sqlserver.hadr_capture_compressed_log_cache, ADD EVENT sqlserver.hadr_capture_filestream_wait, ADD EVENT sqlserver.hadr_capture_log_block, ADD EVENT sqlserver.hadr_capture_vlfheader, ADD EVENT sqlserver.hadr_db_commit_mgr_harden, ADD EVENT sqlserver.hadr_db_commit_mgr_harden_still_waiting, ADD EVENT sqlserver.hadr_db_commit_mgr_update_harden, ADD EVENT sqlserver.hadr_filestream_processed_block, ADD EVENT sqlserver.hadr_log_block_compression, ADD EVENT sqlserver.hadr_log_block_decompression, ADD EVENT sqlserver.hadr_log_block_group_commit , ADD EVENT sqlserver.hadr_log_block_send_complete, ADD EVENT sqlserver.hadr_lsn_send_complete, ADD EVENT sqlserver.hadr_receive_harden_lsn_message, ADD EVENT sqlserver.hadr_send_harden_lsn_message, ADD EVENT sqlserver.hadr_transport_flow_control_action, ADD EVENT sqlserver.hadr_transport_receive_log_block_message, ADD EVENT sqlserver.log_block_pushed_to_logpool, ADD EVENT sqlserver.log_flush_complete , ADD EVENT sqlserver.log_flush_start, ADD EVENT sqlserver.recovery_unit_harden_log_timestamps ADD TARGET package0.event_file(SET filename=N'c:\mslog\AlwaysOn_Data_Movement_Tracing.xel',max_file_size=(500),max_rollover_files=(4)) WITH (MAX_MEMORY=4096 KB,EVENT_RETENTION_MODE=ALLOW_SINGLE_EVENT_LOSS,MAX_DISPATCH_LATENCY=30 SECONDS,MAX_EVENT_SIZE=0 KB,MEMORY_PARTITION_MODE=NONE,TRACK_CAUSALITY=OFF,STARTUP_STATE=ON)  GO

 아래 그림은 XEvent를 실행하여 캡처한 결과이다.[Primary]

 

 [Second synchronous replica]

 

 참고로 hadr_receive_harden_lsn_message의 log_block_id(14602889512)가 다른 ID(146028889488)와 동일하지 않는데, 그이유는 항상 다음의 harden log block의ID를 즉시 반환하기 때문이다. hadr_db_commit_mgr_update_harden xevent를 사용하여 XEvent를 상호연관 시킬 수 있다.

 

 

위의 XEvent 로그를 사용하여 캡처한 데이터를 사용하여 아래 표처럼 만들어서 트랜잭션 커밋의 상세한 지연시간을 확인할 수 있다. 이 리스트는 네트워크 및 log harden process의 시간 델타(latency)를 나열한 것이며 로그 블록의 압축이나 해제 등 다른 시간이 발생할 수도 있다.

	From	To	Lantency
Network: Primary->Secon	Primary: hadr_log_block_send_complete  2018-03-06 16:56:28.2174613	Secondary: hadr_transport_receive_log_block_message  2018-03-06 16:56:32.1241242	3.907 seconds
Network: Secondary->Primary	Secondary:hadr_lsn_send_complete 2018-03-06 16:56:32.7863432	Primary:hadr_receive_harden_lsn_message 2018-03-06 16:56:33.3732126	0.587 seconds
LogHarden(Primary)	log_flush_start 2018-03-06 16:56:28.2168580	log_flush_complete 2018-03-06 16:56:28.8785928	0.663 seconds
Log Harden(Secondary)	Log_flush_start 2018-03-06 16:56:32.1242499	Log_flush_complete 2018-03-06 16:56:32.7861231	0.663 seconds

 위에서 언급했든이 주로 발생하는 대기시간은 다음 세 부분에서 발생한다.복제본간의 네트워크 대기시간 : 3.907 + 0.857 = 4.494Primary Log harden : 0.663Secondary Log harden : 0.663 총 트랜잭션 지연시간을 얻기에는Primary 로그 플러시와 네트워크 전송이 동시에 발생하기 때문에 합산할 수 없어 쉽지 않다.

 

네트워크에서 4.494초가 발생하였고, Primary가 복제본으로부터 컨펌(hadr_receive_harden_lsn_message:2018-03-06 16:56:33.3732126)을 받고 완료한 시간을 (log_flush_complete : 2018-03-06 16 : 56 : 28.8785928) 시간을 계산할때 타임스탬프를 수동으로 계산할 필요가 없다.

 

XEvent는 두 개의 hadr_log_block_group_commit사이의 델타시간을 알 수 있기 때문이다. 아래 예시를 살펴보자.Primary: hadr_log_block_group_commit: 2018-03-06 16:56:28.2167393Primary: hadr_log_block_group_commit: 2018-03-06 16:56:33.3732847Total time to commit=delta of above two timestamps= 5.157 seconds 이 숫자는 네트워크 전송 시간과Secondary서버의 log harden을 더한것과 같다. 그 이유는Secondary 서버의log harden 가 네트워크를 사용할 수 있기를 기다려야하므 Primary와 마찬가지로 동시에 log harden를 할 수 없기 때문이다.

 

 

지금까지 AlwaysOn 동기-커밋 모드에서 복제본간 로그 블록 이동에 대해서 살펴보았다.

그런데 Primary 서버의 XEvent에서 "hadr_db_commit_mgr_harden_still_waiting"가 가끔 발생하는 것을 볼수 있는데 이 이벤트는 Primary 서버가 Secondary 복제본의 확인 메시지를 기다리고 있을때 2초 간격으로 발생(2초로 하드코딩 되어있음)한다. 2초 내에 Ack이 돌아오면 XEvent에 표시되지 않는다. 

 

[참고자료]https://blogs.msdn.microsoft.com/psssql/2018/04/05/troubleshooting-data-movement-latency-between-synchronous-commit-always-on-availability-groups/