Click here to monitor SSC
SQLServerCentral is supported by Red Gate Software Ltd.
 
Log in  ::  Register  ::  Not logged in
 
 
 
        
Home       Members    Calendar    Who's On


Add to briefcase ««123»»

SQL Server has encountered 1 occurrence of I/O Requests taking longer than 15 seconds Expand / Collapse
Author
Message
Posted Wednesday, March 26, 2014 6:32 PM


SSC-Enthusiastic

SSC-EnthusiasticSSC-EnthusiasticSSC-EnthusiasticSSC-EnthusiasticSSC-EnthusiasticSSC-EnthusiasticSSC-EnthusiasticSSC-Enthusiastic

Group: General Forum Members
Last Login: Thursday, October 9, 2014 3:22 PM
Points: 177, Visits: 522
sqlbuddy123 (3/26/2014)
tony28 (3/26/2014)
And Now I am seeing that I forgot System log, but time is after the problem, but maybe was problem with failoverclustering and it caused restart service,,, is it possible?


Good that you didn't have a SQL Server dump file. And basically SQL Error Log entries are logged in Application log too.

Are you using Clustering with Always ON or just Always ON ?

First find the exact stop time of the SQL services from the error log. Note that stop time and check a bunch of log entries before that time.

Looks like we can find some clue from the system log. The system log you posted is not enough. It's better to go back a little bit. Can you post all the system log entries on that day before the SQL Server failure ? You can attach it as a text file.

Also check the same on the SQL\Application log file too i.e all the events before the SQL Server stop time (on that day).

--
SQLBuddy


--
SQLBuddy


1. I am not sure, because it was set up by external company, I can just handle it. But I think with Failover Cluster
We have 3nodes. First two are in SQL Server Failover Cluster and then this group is with node 3 in AlwaysOn Availability Group. This is according to presentation what I have.



2.
Date 3/21/2014 6:08:41 PM
Log SQL Server (Archive #1 - 3/21/2014 6:08:00 PM)

Source spid198

Message
Configuration option 'Agent XPs' changed from 1 to 0. Run the RECONFIGURE statement to install.

Date 3/21/2014 6:08:39 PM
Log SQL Server Agent (Archive #2 - 3/21/2014 6:08:00 PM)
Message
[131] SQLSERVERAGENT service stopping due to a stop request from a user, process, or the OS...

3. There is nothing more,

Just sometimes shows this error

Volume Shadow Copy Service error: Unexpected error querying for the IVssWriterCallback interface. hr = 0x80070005, Access is denied.
. This is often caused by incorrect security settings in either the writer or requestor process.

Operation:
Gathering Writer Data

Context:
Writer Class Id: {e8132975-6f93-4464-a53e-1050253ae220}
Writer Name: System Writer
Writer Instance ID: {fe75e400-b924-45d3-81d3-bb0ee1096cb3}



and this

Log Name: Application
Source: MSSQLSERVER
Date: 21. 3. 2014 18:08:41
Event ID: 15457
Task Category: Server
Level: Information
Keywords: Classic
User: User
Computer: NameOfServer
Description:
Configuration option 'Agent XPs' changed from 1 to 0. Run the RECONFIGURE statement to install.
Event Xml:
<Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
<System>
<Provider Name="MSSQLSERVER" />
<EventID Qualifiers="16384">15457</EventID>
<Level>4</Level>
<Task>2</Task>
<Keywords>0x80000000000000</Keywords>
<TimeCreated SystemTime="2014-03-21T17:08:41.000000000Z" />
<EventRecordID>30331</EventRecordID>
<Channel>Application</Channel>
<Computer>NameOfServer</Computer>
<Security UserID="S-1-5-21-3074418465-2115644625-3052645785-1108" />
</System>
<EventData>
<Data>Agent XPs</Data>
<Data>1</Data>
<Data>0</Data>
<Binary>613C00000A0000000F0000004D00450053002D0048004100440052002D00560053005200560031000000050000006D007300640062000000</Binary>
</EventData>
</Event>

Log Name: Application
Source: SQLVDI
Date: 21. 3. 2014 18:08:31
Event ID: 1
Task Category: None
Level: Error
Keywords: Classic
User: N/A
Computer: NameOfServer
Description:
SQLVDI: Loc=SignalAbort. Desc=Client initiates abort. ErrorCode=(0). Process=3192. Thread=10908. Client. Instance=. VD=Global\TDPSQL-00000C78-0000_SQLVDIMemoryName_0.
Event Xml:
<Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
<System>
<Provider Name="SQLVDI" />
<EventID Qualifiers="0">1</EventID>
<Level>2</Level>
<Task>0</Task>
<Keywords>0x80000000000000</Keywords>
<TimeCreated SystemTime="2014-03-21T17:08:31.000000000Z" />
<EventRecordID>30330</EventRecordID>
<Channel>Application</Channel>
<Computer>NameOfServer</Computer>
<Security />
</System>
<EventData>
<Data>SignalAbort</Data>
<Data>Client initiates abort</Data>
<Data>0</Data>
<Data>
</Data>
<Data>3192</Data>
<Data>10908</Data>
<Data>Client</Data>
<Data>
</Data>
<Data>Global\TDPSQL-00000C78-0000_SQLVDIMemoryName_0</Data>
</EventData>
</Event>

Log Name: Application
Source: MSSQLSERVER
Date: 21. 3. 2014 18:07:43
Event ID: 833
Task Category: Server
Level: Information
Keywords: Classic
User: N/A
Computer: NameOfServer
Description:
SQL Server has encountered 1 occurrence(s) of I/O requests taking longer than 15 seconds to complete on file [G:\USERDB\MCS_MESDB_1.ldf] in database [MCS_MESDB] (8). The OS file handle is 0x0000000000000D08. The offset of the latest long I/O is: 0x000002e70cb000
Event Xml:
<Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
<System>
<Provider Name="MSSQLSERVER" />
<EventID Qualifiers="16384">833</EventID>
<Level>4</Level>
<Task>2</Task>
<Keywords>0x80000000000000</Keywords>
<TimeCreated SystemTime="2014-03-21T17:07:43.000000000Z" />
<EventRecordID>30329</EventRecordID>
<Channel>Application</Channel>
<Computer>NameOfServer</Computer>
<Security />
</System>
<EventData>
<Data>1</Data>
<Data>15</Data>
<Data>G:\USERDB\MCS_MESDB_1.ldf</Data>
<Data>MCS_MESDB</Data>
<Data>8</Data>
<Data>0000000000000D08</Data>
<Data>0x000002e70cb000</Data>
<Binary>410300000A0000000F0000004D00450053002D0048004100440052002D0056005300520056003100000000000000</Binary>
</EventData>
</Event>



Then I find in FDLAUNCHERRORLOG
2014-03-21 18:09:39.877 MSSQLFDLauncher service received control message.
2014-03-21 18:09:39.979 MSSQLFDLauncher service successfully launched FDHost.exe Process(process id = 9124).


then in ERRORLOG
2014-03-21 09:17:43.97 Server The Service Broker endpoint is in disabled or stopped state
then just Log was backed up, and last backup wasnt, but backup in 22:00 was ok .. it was first time, but you know we work 24/5 and it could be problem...

2014-03-21 18:07:43.41 spid8s SQL Server has encountered 1 occurrence(s) of I/O requests taking longer than 15 seconds to complete on file [G:\USERDB\MCS_MESDB_1.ldf] in database [MCS_MESDB] (8). The OS file handle is 0x0000000000000D08. The offset of the latest long I/O is: 0x000002e70cb000
2014-03-21 18:08:41.91 spid198 Configuration option 'Agent XPs' changed from 1 to 0. Run the RECONFIGURE statement to install.

.


  Post Attachments 
errorLogSystem.txt (2 views, 39.62 KB)
Post #1555234
Posted Wednesday, March 26, 2014 10:56 PM
Ten Centuries

Ten CenturiesTen CenturiesTen CenturiesTen CenturiesTen CenturiesTen CenturiesTen CenturiesTen Centuries

Group: General Forum Members
Last Login: Wednesday, October 15, 2014 7:59 PM
Points: 1,194, Visits: 2,222
This is what happened ..

SQL Server stopped with following error message :

Log Name: System
Source: Microsoft-Windows-FailoverClustering
Date: 21. 3. 2014 18:08:39
Event ID: 1069
Task Category: Resource Control Manager
Level: Error
Keywords:
User: SYSTEM
Computer: NameOfServer
Description:
Cluster resource 'SQL Server' of type 'SQL Server' in clustered role 'SQL Server (MSSQLSERVER)' 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.


SQL Server may stop unexpectedly due to different reasons :

Memory leaks from a process within the SQL Server memory space, such as from an extended stored procedure or from OLE automation.

Ending the sqlservr.exe process directly, such as from the Process tab on the Task Manager or with a program such as kill.exe from the Windows Resource Kit.

Some types of unhandled access violations.


Then SQL Server Agent got stopped ..

Date 3/21/2014 6:08:39 PM
Log SQL Server Agent (Archive #2 - 3/21/2014 6:08:00 PM)
Message
[131] SQLSERVERAGENT service stopping due to a stop request from a user, process, or the OS...


And later the message was ...

Log Name: System
Source: Service Control Manager
Date: 21. 3. 2014 18:09:37
Event ID: 7034
Task Category: None
Level: Error
Keywords: Classic
User: N/A
Computer: NameOfServer
Description:
The SQL Server (MSSQLSERVER) service terminated unexpectedly. It has done this 1 time(s).


This error message will be logged if SQL Server has been restarted by SQL Server Agent.

SQL Server Agent will only auto restart SQL Server if SQL Server stopped for some unexpected reason other than an explicit stop command from a user or application, and if the Auto restart SQL Server if it stops unexpectedly option is selected in SQL Server Agent properties. During the restart of SQL Server, SQL Server Agent will write this message to the application event log on the computer hosting SQL Server.

You need to check in SQL Server Agent properties in SSMS whether the following option has been enabled. Also check if SQL Server Agent has local admin rights on the box.

Auto restart SQL Server if it stops unexpectedly


--
SQLBuddy

Post #1555257
Posted Thursday, March 27, 2014 12:43 AM


SSC-Enthusiastic

SSC-EnthusiasticSSC-EnthusiasticSSC-EnthusiasticSSC-EnthusiasticSSC-EnthusiasticSSC-EnthusiasticSSC-EnthusiasticSSC-Enthusiastic

Group: General Forum Members
Last Login: Thursday, October 9, 2014 3:22 PM
Points: 177, Visits: 522
Thank you, good job, very helpful and thanks for experience. I know that this option is in SQL server, but i wouldn't remember in that time
So Service state is both on ... so now i understand ...
and what do you think that it can be cause?

and I found one log yet, i couldnt open before, i dont like metro on servers..
2014-03-21 18:08:39 - ? [131] SQLSERVERAGENT service stopping due to a stop request from a user, process, or the OS...
2014-03-21 18:08:41 - ! [240] 1 engine thread(s) failed to stop after 2 seconds of waiting
2014-03-21 18:08:41 - ! [311] Thread 'JobManager - CmdExec step' (ID 5240) is still running
2014-03-21 18:08:41 - ! [311] Thread 'JobInvocationEngine' (ID 5340) is still running
2014-03-21 18:08:41 - ! [311] Thread 'JobManager - CmdExec step' (ID 5712) is still running
2014-03-21 18:08:41 - ! [311] Thread 'JobManager - TSQL step' (ID 6716) is still running
2014-03-21 18:08:41 - ! [311] Thread 'JobManager - TSQL step' (ID 9092) is still running
2014-03-21 18:08:41 - ! [311] Thread 'JobManager - TSQL step' (ID 9844) is still running
2014-03-21 18:08:41 - ! [311] Thread 'JobManager - TSQL step' (ID 10668) is still running
2014-03-21 18:08:41 - ? [000] Configuration option 'Agent XPs' changed from 1 to 0. Run the RECONFIGURE statement to install. [SQLSTATE 01000] (Message 15457)
2014-03-21 18:08:41 - + [098] SQLServerAgent terminated (forcefully)
Post #1555283
Posted Thursday, March 27, 2014 8:33 AM
Ten Centuries

Ten CenturiesTen CenturiesTen CenturiesTen CenturiesTen CenturiesTen CenturiesTen CenturiesTen Centuries

Group: General Forum Members
Last Login: Wednesday, October 15, 2014 7:59 PM
Points: 1,194, Visits: 2,222
tony28 (3/27/2014)
Thank you, good job, very helpful and thanks for experience. I know that this option is in SQL server, but i wouldn't remember in that time
So Service state is both on ... so now i understand ...
and what do you think that it can be cause?

and I found one log yet, i couldnt open before, i dont like metro on servers..
2014-03-21 18:08:39 - ? [131] SQLSERVERAGENT service stopping due to a stop request from a user, process, or the OS...
2014-03-21 18:08:41 - ! [240] 1 engine thread(s) failed to stop after 2 seconds of waiting
2014-03-21 18:08:41 - ! [311] Thread 'JobManager - CmdExec step' (ID 5240) is still running
2014-03-21 18:08:41 - ! [311] Thread 'JobInvocationEngine' (ID 5340) is still running
2014-03-21 18:08:41 - ! [311] Thread 'JobManager - CmdExec step' (ID 5712) is still running
2014-03-21 18:08:41 - ! [311] Thread 'JobManager - TSQL step' (ID 6716) is still running
2014-03-21 18:08:41 - ! [311] Thread 'JobManager - TSQL step' (ID 9092) is still running
2014-03-21 18:08:41 - ! [311] Thread 'JobManager - TSQL step' (ID 9844) is still running
2014-03-21 18:08:41 - ! [311] Thread 'JobManager - TSQL step' (ID 10668) is still running
2014-03-21 18:08:41 - ? [000] Configuration option 'Agent XPs' changed from 1 to 0. Run the RECONFIGURE statement to install. [SQLSTATE 01000] (Message 15457)
2014-03-21 18:08:41 - + [098] SQLServerAgent terminated (forcefully)


You are welcome, Tony. You need to look for the log entries that have occured before 2014-03-21 18:08:39.

To find the reason for SQL Server failure, try to check the cluster log for errors. Check this for the cluster log ..

http://www.sqlserver-expert.com/2012/05/how-to-generate-clusterlog-for-windows.html

--
SQLBuddy
Post #1555458
Posted Thursday, March 27, 2014 3:13 PM


SSC-Enthusiastic

SSC-EnthusiasticSSC-EnthusiasticSSC-EnthusiasticSSC-EnthusiasticSSC-EnthusiasticSSC-EnthusiasticSSC-EnthusiasticSSC-Enthusiastic

Group: General Forum Members
Last Login: Thursday, October 9, 2014 3:22 PM
Points: 177, Visits: 522
Ok Now I will do log, after finish I will send..

do you think that is good this setting from your experience ? Auto restart SQL Server if it stops unexpectedly
I am thinking about this and maybe it is better that SQL server will be restart than frozen or something.

And please can you explain me something ?

SQL Server may stop unexpectedly due to different reasons :

Memory leaks from a process within the SQL Server memory space, such as from an extended stored procedure or from OLE automation.

and so is not missing the problem with Failover Clustering here ? Because you said 3 reasons, but from this log I see that problem was with Cluster.

Thank you.
Post #1555670
Posted Thursday, March 27, 2014 3:29 PM


SSC-Enthusiastic

SSC-EnthusiasticSSC-EnthusiasticSSC-EnthusiasticSSC-EnthusiasticSSC-EnthusiasticSSC-EnthusiasticSSC-EnthusiasticSSC-Enthusiastic

Group: General Forum Members
Last Login: Thursday, October 9, 2014 3:22 PM
Points: 177, Visits: 522
So I created Cluster log and last data are from 25.3
Post #1555678
Posted Thursday, March 27, 2014 3:42 PM


SSC-Enthusiastic

SSC-EnthusiasticSSC-EnthusiasticSSC-EnthusiasticSSC-EnthusiasticSSC-EnthusiasticSSC-EnthusiasticSSC-EnthusiasticSSC-Enthusiastic

Group: General Forum Members
Last Login: Thursday, October 9, 2014 3:22 PM
Points: 177, Visits: 522
I found something, but it looks like information about operation.


Log Name: Microsoft-Windows-FailoverClustering/Operational
Source: Microsoft-Windows-FailoverClustering
Date: 21. 3. 2014 18:09:40
Event ID: 1201
Task Category: Resource Control Manager
Level: Information
Keywords:
User: SYSTEM
Computer: NameOfServer
Description:
The Cluster service successfully brought the clustered service or application 'MES-SQL-CL' online.
Event Xml:
<Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
<System>
<Provider Name="Microsoft-Windows-FailoverClustering" Guid="{BAF908EA-3421-4CA9-9B84-6689B8C6F85F}" />
<EventID>1201</EventID>
<Version>0</Version>
<Level>4</Level>
<Task>3</Task>
<Opcode>0</Opcode>
<Keywords>0x4000000000000000</Keywords>
<TimeCreated SystemTime="2014-03-21T17:09:40.906587700Z" />
<EventRecordID>627</EventRecordID>
<Correlation />
<Execution ProcessID="2140" ThreadID="9552" />
<Channel>Microsoft-Windows-FailoverClustering/Operational</Channel>
<Computer> NameOfServer</Computer>
<Security UserID="S-1-5-18" />
</System>
<EventData>
<Data Name="ResourceGroup">MES-SQL-CL</Data>
</EventData>
</Event>

Log Name: Microsoft-Windows-FailoverClustering/Operational
Source: Microsoft-Windows-FailoverClustering
Date: 21. 3. 2014 18:09:41
Event ID: 1201
Task Category: Resource Control Manager
Level: Information
Keywords:
User: SYSTEM
Computer: NameOfServer
Description:
The Cluster service successfully brought the clustered service or application 'SQL Server (MSSQLSERVER)' online.
Event Xml:
<Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
<System>
<Provider Name="Microsoft-Windows-FailoverClustering" Guid="{BAF908EA-3421-4CA9-9B84-6689B8C6F85F}" />
<EventID>1201</EventID>
<Version>0</Version>
<Level>4</Level>
<Task>3</Task>
<Opcode>0</Opcode>
<Keywords>0x4000000000000000</Keywords>
<TimeCreated SystemTime="2014-03-21T17:09:41.270688400Z" />
<EventRecordID>628</EventRecordID>
<Correlation />
<Execution ProcessID="2140" ThreadID="8428" />
<Channel>Microsoft-Windows-FailoverClustering/Operational</Channel>
<Computer> NameOfServer</Computer>
<Security UserID="S-1-5-18" />
</System>
<EventData>
<Data Name="ResourceGroup">SQL Server (MSSQLSERVER)</Data>
</EventData>
</Event>
Post #1555681
Posted Thursday, March 27, 2014 3:51 PM


SSC-Enthusiastic

SSC-EnthusiasticSSC-EnthusiasticSSC-EnthusiasticSSC-EnthusiasticSSC-EnthusiasticSSC-EnthusiasticSSC-EnthusiasticSSC-Enthusiastic

Group: General Forum Members
Last Login: Thursday, October 9, 2014 3:22 PM
Points: 177, Visits: 522
So what do you think about that I will try function of Failover Clustering during weekend?
Post #1555684
Posted Thursday, March 27, 2014 5:03 PM
Ten Centuries

Ten CenturiesTen CenturiesTen CenturiesTen CenturiesTen CenturiesTen CenturiesTen CenturiesTen Centuries

Group: General Forum Members
Last Login: Wednesday, October 15, 2014 7:59 PM
Points: 1,194, Visits: 2,222
tony28 (3/27/2014)
Ok Now I will do log, after finish I will send..

do you think that is good this setting from your experience ? Auto restart SQL Server if it stops unexpectedly
I am thinking about this and maybe it is better that SQL server will be restart than frozen or something.



True. But it's good to document the setting so that you are aware of that and will help you with troubleshooting in the future.

http://technet.microsoft.com/en-us/magazine/gg313742.aspx

And please can you explain me something ?

SQL Server may stop unexpectedly due to different reasons :

Memory leaks from a process within the SQL Server memory space, such as from an extended stored procedure or from OLE automation.

and so is not missing the problem with Failover Clustering here ? Because you said 3 reasons, but from this log I see that problem was with Cluster.

Thank you.


I was mentioning about the possible reasons for that SQL server failure. And they are not the only reasons. Could be something else too ..

Check this for more info Memory Leaking

http://mssqlwiki.com/2012/12/04/sql-server-memory-leak/

Cluster Log could be helpful in finding the actual reason.

--
SQLBuddy
Post #1555694
Posted Thursday, March 27, 2014 5:04 PM
Ten Centuries

Ten CenturiesTen CenturiesTen CenturiesTen CenturiesTen CenturiesTen CenturiesTen CenturiesTen Centuries

Group: General Forum Members
Last Login: Wednesday, October 15, 2014 7:59 PM
Points: 1,194, Visits: 2,222
tony28 (3/27/2014)
I found something, but it looks like information about operation.


Log Name: Microsoft-Windows-FailoverClustering/Operational
Source: Microsoft-Windows-FailoverClustering
Date: 21. 3. 2014 18:09:40
Event ID: 1201
Task Category: Resource Control Manager
Level: Information
Keywords:
User: SYSTEM
Computer: NameOfServer
Description:
The Cluster service successfully brought the clustered service or application 'MES-SQL-CL' online.
Event Xml:
<Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
<System>
<Provider Name="Microsoft-Windows-FailoverClustering" Guid="{BAF908EA-3421-4CA9-9B84-6689B8C6F85F}" />
<EventID>1201</EventID>
<Version>0</Version>
<Level>4</Level>
<Task>3</Task>
<Opcode>0</Opcode>
<Keywords>0x4000000000000000</Keywords>
<TimeCreated SystemTime="2014-03-21T17:09:40.906587700Z" />
<EventRecordID>627</EventRecordID>
<Correlation />
<Execution ProcessID="2140" ThreadID="9552" />
<Channel>Microsoft-Windows-FailoverClustering/Operational</Channel>
<Computer> NameOfServer</Computer>
<Security UserID="S-1-5-18" />
</System>
<EventData>
<Data Name="ResourceGroup">MES-SQL-CL</Data>
</EventData>
</Event>

Log Name: Microsoft-Windows-FailoverClustering/Operational
Source: Microsoft-Windows-FailoverClustering
Date: 21. 3. 2014 18:09:41
Event ID: 1201
Task Category: Resource Control Manager
Level: Information
Keywords:
User: SYSTEM
Computer: NameOfServer
Description:
The Cluster service successfully brought the clustered service or application 'SQL Server (MSSQLSERVER)' online.
Event Xml:
<Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
<System>
<Provider Name="Microsoft-Windows-FailoverClustering" Guid="{BAF908EA-3421-4CA9-9B84-6689B8C6F85F}" />
<EventID>1201</EventID>
<Version>0</Version>
<Level>4</Level>
<Task>3</Task>
<Opcode>0</Opcode>
<Keywords>0x4000000000000000</Keywords>
<TimeCreated SystemTime="2014-03-21T17:09:41.270688400Z" />
<EventRecordID>628</EventRecordID>
<Correlation />
<Execution ProcessID="2140" ThreadID="8428" />
<Channel>Microsoft-Windows-FailoverClustering/Operational</Channel>
<Computer> NameOfServer</Computer>
<Security UserID="S-1-5-18" />
</System>
<EventData>
<Data Name="ResourceGroup">SQL Server (MSSQLSERVER)</Data>
</EventData>
</Event>


Could you attach the log file ?

--
SQLBuddy
Post #1555695
« Prev Topic | Next Topic »

Add to briefcase ««123»»

Permissions Expand / Collapse