6

We have a physical SQL Server 2016 Enterprise SP2 with two instances and each instance contains one AG. Sometimes it happens that one AG goes to resolving (without failover), the cluster resource is automatically restarted after 500ms and then everything is back online. But I've not yet been able to find a cause.

When I'm checking the Errorlog, I see following entry:

Date 14/04/2019 23:35:37
SQL Server hosting availability group 'AG_PROD' did not receive a process event signal from the Windows Server Failover Cluster within the lease timeout period.

Date 14/04/2019 23:35:37
SQL Server hosting availability group 'AG_PROD' did not receive a process event signal from the Windows Server Failover Cluster within the lease timeout period.

Date 14/04/2019 23:35:14
SQL Server has encountered 1 occurrence(s) of I/O requests taking longer than > 15 seconds to complete on file [e:\sqlData\db.mdf] in database id 6. The OS file handle is 0x0000000000001128. The offset of the latest long I/O is: 0x00010de65c0000

Date 14/04/2019 23:33:10
BACKUP DATABASE WITH DIFFERENTIAL successfully processed 51459 pages in 61.045 > seconds (6.585 MB/sec).

As you see there is an IO-request that takes longer than 15 seconds, I would expect to find this in the *_SQLDIAG_*.xel file but no errors are found here.

When I check the cluster log I find following:

2019/04/14-23:35:09.430 INFO [NM] Received request from client address SQL1.
2019/04/14-23:35:09.444 INFO [NM] Received request from client address SQL1.
2019/04/14-23:35:09.459 INFO [RES] Network Name : Getting Read only private properties
2019/04/14-23:35:11.121 INFO [RES] Network Name: Agent: Sending request Netname/RecheckConfig to NN:a09ce798-e8d3-4446-9e0b-d0fe72278d37:Netbios
2019/04/14-23:35:14.121 INFO [API] s_ApiGetQuorumResource final status 0.
2019/04/14-23:35:14.122 INFO [API] s_ApiGetQuorumResource final status 0.
2019/04/14-23:35:14.201 INFO [API] s_ApiGetQuorumResource final status 0.
2019/04/14-23:35:14.201 INFO [API] s_ApiGetQuorumResource final status 0.
2019/04/14-23:35:14.202 INFO [API] s_ApiGetQuorumResource final status 0.
2019/04/14-23:35:14.202 INFO [API] s_ApiGetQuorumResource final status 0.
2019/04/14-23:35:14.282 INFO [API] s_ApiGetQuorumResource final status 0.
2019/04/14-23:35:14.283 INFO [API] s_ApiGetQuorumResource final status 0.
2019/04/14-23:35:16.121 INFO [RES] Network Name: Agent: Sending request Netname/RecheckConfig to NN:a09ce798-e8d3-4446-9e0b-d0fe72278d37:Netbios
2019/04/14-23:35:17.115 INFO [API] s_ApiGetQuorumResource final status 0.
2019/04/14-23:35:17.115 INFO [API] s_ApiGetQuorumResource final status 0.
2019/04/14-23:35:18.845 INFO [RES] Network Name : Dns: HealthCheck: SQL
2019/04/14-23:35:18.845 INFO [RES] Network Name : Dns: End of Slow Operation, state: Initialized/Reading, prevWorkState: Reading
2019/04/14-23:35:21.121 INFO [RES] Network Name: Agent: Sending request Netname/RecheckConfig to NN:a09ce798-e8d3-4446-9e0b-d0fe72278d37:Netbios
2019/04/14-23:35:21.184 INFO [API] s_ApiGetQuorumResource final status 0.
2019/04/14-23:35:21.184 INFO [API] s_ApiGetQuorumResource final status 0.
2019/04/14-23:35:26.121 INFO [RES] Network Name: Agent: Sending request Netname/RecheckConfig to NN:a09ce798-e8d3-4446-9e0b-d0fe72278d37:Netbios
2019/04/14-23:35:26.584 WARN [RES] SQL Server Availability Group: [hadrag] Failed to retrieve data column. Return code -1
2019/04/14-23:35:27.455 ERR [RES] SQL Server Availability Group: [hadrag] Failure detected, diagnostics heartbeat is lost
2019/04/14-23:35:27.455 ERR [RES] SQL Server Availability Group : [hadrag] Availability Group is not healthy with given HealthCheckTimeout and FailureConditionLevel
2019/04/14-23:35:27.455 ERR [RES] SQL Server Availability Group : [hadrag] Resource Alive result 0.
2019/04/14-23:35:27.455 ERR [RES] SQL Server Availability Group: [hadrag] Failure detected, diagnostics heartbeat is lost
2019/04/14-23:35:27.455 ERR [RES] SQL Server Availability Group : [hadrag] Availability Group is not healthy with given HealthCheckTimeout and FailureConditionLevel
2019/04/14-23:35:27.455 ERR
[RES] SQL Server Availability Group : [hadrag] Resource Alive result 0.
2019/04/14-23:35:27.455 WARN [RHS] Resource AG_PROD IsAlive has indicated failure.

So the HealthCheckTimeout was expired.

This is what is present at the system-eventlog at the time of the error:

14/04/2019 23:35:40 WARNING The IO operation at logical block address 0x8fd2b870 for Disk 1 (PDO name: \Device\MPIODisk1) was retried.

14/04/2019 23:35:27 ERROR Cluster resource 'AG_PROD' of type 'SQL Server Availability Group' in clustered role 'AG_PROD' failed.

Based on the failure policies for the resource and role, the cluster service may try to bring the resource online on this node or move the group to another node of the cluster and then restart it. Check the resource and group state using Failover Cluster Manager or the Get-ClusterResource Windows PowerShell cmdlet.

14/04/2019 23:32:05 INFO The WMI Performance Adapter service entered the running state.

This is what I found in the application-eventlog:

14/04/2019 23:35:37 INFO Always On: The local replica of availability group 'AG_HIX_PROD' is going offline because either the lease expired or lease renewal failed. This is an informational message only. No user action is required.

14/04/2019 23:35:37 ERROR The lease between availability group 'AG_HIX_PROD' and the Windows Server Failover Cluster has expired. A connectivity issue occurred between the instance of SQL Server and the Windows Server Failover Cluster. To determine whether the availability group is failing over correctly, check the corresponding availability group resource in the Windows Server Failover Cluster.

14/04/2019 23:35:37 ERROR SQL Server hosting availability group 'AG_HIX_PROD' did not receive a process event signal from the Windows Server Failover Cluster within the lease timeout period.

This is what I think happened: The cluster didn't get info back in time from sp_server_diagnostics => HealthCheckTimeout was reached.
As consequence the cluster service started to take the resource offline. Because the resource was being taken offline, we also got a lease-timeout.
So the machine didn't hung and caused a lease-timeout otherwise the other AG would also got a timeout.

I think sp_server_diagnostics is executed once per instance.
When I execute following query on each instance on the primary:

select spid,s.[status],host_name,s.program_name,host_process_id,
cmd,client_interface_name,original_login_name
from sys.sysprocesses p
inner join sys.dm_exec_sessions s on p.spid=s.session_id
where lastwaittype='SP_SERVER_DIAGNOSTICS_SLEEP'

I get two records, one with the command 'SYSTEM_HEALTH_MO' and host_process_id null and one with command 'EXECUTE' and a host_process_id. After tracking the host_process_id this was a RHS.exe process (so this was the cluster executing sp_server_diagnostics). The first record comes from a internal extended event, I think. You can find it by using following query:

select * from sys.dm_xe_sessions
where [name] =N'sp_server_diagnostics session'

Is my conclusion a correct one or did I make a mistake in my analysis?
An additional question: does each AG have his own lease or is it only one lease per instance?

  • Is your SQL server virtualized? – Alen Apr 16 at 15:12
  • @Alen: no this is a physical server. – Frederik Vanderhaegen Apr 17 at 6:25
  • You can try to increase the timeout in the cluster settings and look in the cluster log along with performance data for anything else. On a virtual instance i've seen this where the ESX host runs out of resources. – Alen Apr 17 at 14:22
  • 1
    Thanks - so the lease timeout is a red herring. The main issue seems to be not returning the result set either at all or fast enough... You'll need to look a the system eventlog, the ring buffer for the time period, and the sqldiag* XE files to see what the worker threads, cpu utilization, memory, QP health, etc., are all stating. The issue could still be either in side or outside SQL Server and there is a really good chance there isn't enough data hanging around to find out, but it's worth a look. – Sean Gallardy Apr 23 at 20:07
  • 1
    It means that something happened (unknown) where the result set wasn't returned in a timely manner. This could be anything, from high cpu, stalled scheduler, non-yielding scheduler, backup software freezing the vm, anti-cirus monopolizing cpu, memory pressure, I/O issues, etc. So there needs to be data to point in a direction, if there is none - dead in the water. If this happened once and never reoccurred, then I'm afraid there just isn't enough to go on. – Sean Gallardy Apr 24 at 10:59

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Browse other questions tagged or ask your own question.