Connection timeout problem - SQL Server Forums

Please start any new threads on our new site at https://forums.sqlteam.com. We've got lots of great SQL Server experts to answer whatever question you can come up with.

All Forums

SQL Server 2000 Forums

SQL Server Development (2000)

Connection timeout problem

Author

Topic

khycnar
Starting Member

6 Posts

Posted - 2008-02-28 : 07:18:42

Hi all,

We've got a pretty difficult problem to be solved on our production site. It happens very occasionally (and thus is hard to reproduce) that some of the database connections get timeouted. The query that is executed is as simple as: "select host from Hosts with (NOLOCK)". We have got two applications running exactly the same code (one is on Tomcat and the other is a standalone app) and both of them are affected. There is another application that runs a query that locks the Hosts table exclusively (I mean, it uses TABLOCK, HOLDLOCK hints) but anyway there're no deadlocks - we already tried to look for deadlocks by using both Profiler and setting both 1204 and 3605 traces on, but nothing has been detected.

We use the JTDS JDBC driver, additionally on Tomcat we have a DBCP connection pool (using the org.apache.commons.dbcp.BasicDataSource). The standalone application is single threaded so it uses a single Connection that is obtained from the DriverManager.

The exception stack traces we get are:


java.sql.SQLException: I/O Error: Connection timed out
        at net.sourceforge.jtds.jdbc.TdsCore.executeSQL(TdsCore.java:1052)
        at net.sourceforge.jtds.jdbc.JtdsStatement.executeSQLQuery(JtdsStatement.java:465)
        at net.sourceforge.jtds.jdbc.JtdsPreparedStatement.executeQuery(JtdsPreparedStatement.java:777)
        at org.apache.tomcat.dbcp.dbcp.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.java:92)
        at ptv.premierLeague.dao.HostJdbcDAO.getHostnames(HostJdbcDAO.java:54)
        at ptv.premierLeague.GeevsXmlProcessor.doPost(GeevsXmlProcessor.java:326)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:709)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:802)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:252)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:213)
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:178)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:126)
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:105)
        at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:541)
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:107)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:148)
        at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:869)
        at org.apache.coyote.http11.Http11BaseProtocol$Http11ConnectionHandler.processConnection(Http11BaseProtocol.java:664)
        at org.apache.tomcat.util.net.PoolTcpEndpoint.processSocket(PoolTcpEndpoint.java:527)
        at org.apache.tomcat.util.net.LeaderFollowerWorkerThread.runIt(LeaderFollowerWorkerThread.java:80)
        at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:684)
        at java.lang.Thread.run(Thread.java:595)
Caused by: java.net.SocketException: Connection timed out
        at java.net.SocketInputStream.socketRead0(Native Method)
        at java.net.SocketInputStream.read(SocketInputStream.java:129)
        at java.io.DataInputStream.readFully(DataInputStream.java:176)
        at java.io.DataInputStream.readFully(DataInputStream.java:152)
        at net.sourceforge.jtds.jdbc.SharedSocket.readPacket(SharedSocket.java:841)
        at net.sourceforge.jtds.jdbc.SharedSocket.getNetPacket(SharedSocket.java:722)
        at net.sourceforge.jtds.jdbc.ResponseStream.getPacket(ResponseStream.java:466)
        at net.sourceforge.jtds.jdbc.ResponseStream.read(ResponseStream.java:103)
        at net.sourceforge.jtds.jdbc.ResponseStream.peek(ResponseStream.java:88)
        at net.sourceforge.jtds.jdbc.TdsCore.wait(TdsCore.java:3928)
        at net.sourceforge.jtds.jdbc.TdsCore.executeSQL(TdsCore.java:1045)
        ... 22 more

and


Connection object is closed.
java.sql.SQLException: Invalid state, the Connection object is closed.
        at net.sourceforge.jtds.jdbc.ConnectionJDBC2.checkOpen(ConnectionJDBC2.java:1634)
        at net.sourceforge.jtds.jdbc.ConnectionJDBC2.setAutoCommit(ConnectionJDBC2.java:2139)
        at org.apache.tomcat.dbcp.dbcp.DelegatingConnection.setAutoCommit(DelegatingConnection.java:268)
        at org.apache.tomcat.dbcp.dbcp.PoolingDataSource$PoolGuardConnectionWrapper.setAutoCommit(PoolingDataSource.java:293)
        at ptv.premierLeague.PlFlipFactory.insertPlFlipFactoryMessage(PlFlipFactory.java:417)
        at ptv.premierLeague.PlFlipFactory.sendPlFlipFactoryMessage(PlFlipFactory.java:201)
        at ptv.premierLeague.GeevsXmlProcessor.doPost(GeevsXmlProcessor.java:344)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:709)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:802)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:252)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:213)
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:178)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:126)
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:105)
        at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:541)
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:107)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:148)
        at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:869)
        at org.apache.coyote.http11.Http11BaseProtocol$Http11ConnectionHandler.processConnection(Http11BaseProtocol.java:664)
        at org.apache.tomcat.util.net.PoolTcpEndpoint.processSocket(PoolTcpEndpoint.java:527)
        at org.apache.tomcat.util.net.LeaderFollowerWorkerThread.runIt(LeaderFollowerWorkerThread.java:80)
        at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:684)
        at java.lang.Thread.run(Thread.java:595)
25157228 [2008-02-27 13:59:23,976] [http-8080-Processor16] ERROR ptv.premierLeague.GeevsXmlProcessor  - Could not close the direct flip database connection
java.sql.SQLException: Already closed.
        at org.apache.tomcat.dbcp.dbcp.PoolableConnection.close(PoolableConnection.java:77)
        at org.apache.tomcat.dbcp.dbcp.PoolingDataSource$PoolGuardConnectionWrapper.close(PoolingDataSource.java:180)
        at ptv.premierLeague.GeevsXmlProcessor.doPost(GeevsXmlProcessor.java:385)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:709)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:802)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:252)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:213)
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:178)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:126)
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:105)
        at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:541)
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:107)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:148)
        at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:869)
        at org.apache.coyote.http11.Http11BaseProtocol$Http11ConnectionHandler.processConnection(Http11BaseProtocol.java:664)
        at org.apache.tomcat.util.net.PoolTcpEndpoint.processSocket(PoolTcpEndpoint.java:527)
        at org.apache.tomcat.util.net.LeaderFollowerWorkerThread.runIt(LeaderFollowerWorkerThread.java:80)
        at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:684)
        at java.lang.Thread.run(Thread.java:595)

The second exception occured while trying to set the autocommit flag on the connection back to true, but it seems like the connection has already been closed (by what?). Anyway to me it smells like a problem on the server side.

Thanx in advance for help or suggestions appreciated!

Krzysztof

RickD
Slow But Sure Yak Herding Master

3608 Posts

Posted - 2008-02-28 : 07:28:41

What do your SQL error logs tell you?

These can be found on your server and are named ErrorLog, Errorlog.1 etc

khycnar
Starting Member

6 Posts

Posted - 2008-02-28 : 09:15:03

2008-02-27 11:58:59.36 server Microsoft SQL Server 2000 - 8.00.760 (Intel X86)
Dec 17 2002 14:22:05
Copyright (c) 1988-2003 Microsoft Corporation
Standard Edition on Windows NT 5.2 (Build 3790: Service Pack 2)

2008-02-27 11:58:59.36 server Copyright (C) 1988-2002 Microsoft Corporation.
2008-02-27 11:58:59.36 server All rights reserved.
2008-02-27 11:58:59.36 server Server Process ID is 3436.
2008-02-27 11:58:59.36 server Logging SQL Server messages in file 'C:\Program Files\Microsoft SQL Server\MSSQL$FLIPINSTANCE\log\ERRORLOG'.
2008-02-27 11:58:59.36 server SQL Server is starting at priority class 'normal'(4 CPUs detected).
2008-02-27 11:58:59.46 server SQL Server configured for thread mode processing.
2008-02-27 11:58:59.46 server Using dynamic lock allocation. [2500] Lock Blocks, [5000] Lock Owner Blocks.
2008-02-27 11:58:59.52 server Attempting to initialize Distributed Transaction Coordinator.
2008-02-27 11:59:00.54 spid3 Starting up database 'master'.
2008-02-27 11:59:00.61 server Using 'SSNETLIB.DLL' version '8.0.766'.
2008-02-27 11:59:00.61 spid5 Starting up database 'model'.
2008-02-27 11:59:00.63 server SQL server listening on 172.16.7.81: 1433.
2008-02-27 11:59:00.63 spid3 Server name is 'PTVFELFLIPDB01\FLIPINSTANCE'.
2008-02-27 11:59:00.63 server SQL server listening on 127.0.0.1: 1433.
2008-02-27 11:59:00.63 spid8 Starting up database 'msdb'.
2008-02-27 11:59:00.63 spid9 Starting up database 'flip'.
2008-02-27 11:59:00.63 spid10 Starting up database 'flipmerge'.
2008-02-27 11:59:00.65 server SQL server listening on TCP, Named Pipes.
2008-02-27 11:59:00.65 server SQL Server is ready for client connections
2008-02-27 11:59:00.71 spid5 Clearing tempdb database.
2008-02-27 11:59:00.77 spid5 Starting up database 'tempdb'.
2008-02-27 11:59:00.79 spid3 Recovery complete.
2008-02-27 11:59:00.79 spid3 SQL global counter collection task is created.
2008-02-27 11:59:10.54 spid1 Warning: unable to allocate 'min server memory' of 2055MB.
2008-02-27 12:01:11.68 spid51 Starting up database 'flip'.
2008-02-27 12:01:11.68 spid51 Bypassing recovery for database 'flip' because it is marked IN LOAD.
2008-02-27 12:01:11.76 spid51 Starting up database 'flip'.
2008-02-27 12:01:11.76 spid51 Bypassing recovery for database 'flip' because it is marked IN LOAD.
2008-02-27 12:01:11.82 spid51 Recovery is checkpointing database 'flip' (5)
2008-02-27 12:01:11.87 spid51 Starting up database 'flip'.
2008-02-27 12:01:12.07 spid51 Using 'xpstar.dll' version '2000.80.760' to execute extended stored procedure 'xp_regread'.
2008-02-27 12:01:12.12 backup Database restored: Database: flip, creation date(time): 2007/07/09(14:36:20), first LSN: 274826:158:1, last LSN: 274826:175:1, number of dump devices: 1, device information: (FILE=1, TYPE=DISK: {'C:\Program Files\Telestream\FactoryArray\FactoryArrayDBMSqlServerShare\flip_172.16.7.82.dat'}).
2008-02-27 12:01:23.68 spid53 Error: 15457, Severity: 0, State: 1
2008-02-27 12:01:23.68 spid53 Configuration option 'show advanced options' changed from 1 to 1. Run the RECONFIGURE statement to install..
2008-02-27 12:01:23.83 spid53 Using 'xplog70.dll' version '2000.80.760' to execute extended stored procedure 'xp_msver'.
2008-02-27 12:04:16.50 backup Database backed up: Database: flip, creation date(time): 2007/07/09(14:36:20), pages dumped: 151115, first LSN: 274826:410:1, last LSN: 274826:421:1, number of dump devices: 1, device information: (FILE=1, TYPE=DISK: {'\\PTVFELFLIPDB02\FactoryArrayDBMSqlServerShare\flip_172.16.7.81.dat'}).
2008-02-27 12:08:03.86 spid55 Using 'odsole70.dll' version '2000.80.760' to execute extended stored procedure 'sp_OACreate'.
2008-02-27 12:24:49.50 spid4
Deadlock encountered .... Printing deadlock information
2008-02-27 12:24:49.50 spid4
2008-02-27 12:24:49.50 spid4 Wait-for graph
2008-02-27 12:24:49.50 spid4
2008-02-27 12:24:49.50 spid4 Node:1
2008-02-27 12:24:49.50 spid4 RID: 5:1:167:44 CleanCnt:1 Mode: X Flags: 0x2
2008-02-27 12:24:49.50 spid4 Grant List 2::
2008-02-27 12:24:49.50 spid4 Owner:0x19dab9c0 Mode: X Flg:0x0 Ref:1 Life:02000000 SPID:59 ECID:0
2008-02-27 12:24:49.50 spid4 SPID: 59 ECID: 0 Statement Type: CURSORDELETE Line #: 1
2008-02-27 12:24:49.50 spid4 Input Buf: RPC Event: sp_cursor;1
2008-02-27 12:24:49.50 spid4 Requested By:
2008-02-27 12:24:49.50 spid4 ResType:LockOwner Stype:'OR' Mode: S SPID:52 ECID:0 Ec:(0x19FB7538) Value:0x19db54c0 Cost:(0/0)
2008-02-27 12:24:49.50 spid4
2008-02-27 12:24:49.50 spid4 Node:2
2008-02-27 12:24:49.50 spid4 KEY: 5:149575571:2 (540195a89342) CleanCnt:1 Mode: S Flags: 0x0
2008-02-27 12:24:49.50 spid4 Grant List 0::
2008-02-27 12:24:49.50 spid4 Owner:0x19db5680 Mode: S Flg:0x0 Ref:1 Life:00000000 SPID:52 ECID:0
2008-02-27 12:24:49.50 spid4 SPID: 52 ECID: 0 Statement Type: SELECT Line #: 1
2008-02-27 12:24:49.50 spid4 Input Buf: RPC Event: sp_executesql;1
2008-02-27 12:24:49.50 spid4 Requested By:
2008-02-27 12:24:49.50 spid4 ResType:LockOwner Stype:'OR' Mode: X SPID:59 ECID:0 Ec:(0x19F6B530) Value:0x19db5840 Cost:(0/3C)
2008-02-27 12:24:49.50 spid4 Victim Resource Owner:
2008-02-27 12:24:49.50 spid4 ResType:LockOwner Stype:'OR' Mode: S SPID:52 ECID:0 Ec:(0x19FB7538) Value:0x19db54c0 Cost:(0/0)
2008-02-27 12:45:27.54 spid52 Error: 15457, Severity: 0, State: 1
2008-02-27 12:45:27.54 spid52 Configuration option 'show advanced options' changed from 1 to 1. Run the RECONFIGURE statement to install..
2008-02-27 12:46:22.48 spid51 Error: 15457, Severity: 0, State: 1
2008-02-27 12:46:22.48 spid51 Configuration option 'show advanced options' changed from 1 to 1. Run the RECONFIGURE statement to install..
2008-02-27 13:52:35.79 spid4
Deadlock encountered .... Printing deadlock information
2008-02-27 13:52:35.79 spid4
2008-02-27 13:52:35.79 spid4 Wait-for graph
2008-02-27 13:52:35.79 spid4
2008-02-27 13:52:35.79 spid4 Node:1
2008-02-27 13:52:35.79 spid4 KEY: 5:149575571:2 (d50154fb0084) CleanCnt:1 Mode: S Flags: 0x0
2008-02-27 13:52:35.79 spid4 Grant List 2::
2008-02-27 13:52:35.79 spid4 Owner:0x19dbf0c0 Mode: S Flg:0x0 Ref:1 Life:00000000 SPID:82 ECID:0
2008-02-27 13:52:35.79 spid4 SPID: 82 ECID: 0 Statement Type: SELECT Line #: 1
2008-02-27 13:52:35.79 spid4 Input Buf: RPC Event: sp_executesql;1
2008-02-27 13:52:35.79 spid4 Requested By:
2008-02-27 13:52:35.79 spid4 ResType:LockOwner Stype:'OR' Mode: X SPID:72 ECID:0 Ec:(0x1DC6D530) Value:0x19db4f60 Cost:(0/3C)
2008-02-27 13:52:35.79 spid4
2008-02-27 13:52:35.79 spid4 Node:2
2008-02-27 13:52:35.79 spid4 RID: 5:1:10093:23 CleanCnt:1 Mode: X Flags: 0x2
2008-02-27 13:52:35.79 spid4 Grant List 2::
2008-02-27 13:52:35.79 spid4 Owner:0x19db5220 Mode: X Flg:0x0 Ref:1 Life:02000000 SPID:72 ECID:0
2008-02-27 13:52:35.79 spid4 SPID: 72 ECID: 0 Statement Type: CURSORDELETE Line #: 1
2008-02-27 13:52:35.79 spid4 Input Buf: RPC Event: sp_cursor;1
2008-02-27 13:52:35.79 spid4 Requested By:
2008-02-27 13:52:35.79 spid4 ResType:LockOwner Stype:'OR' Mode: S SPID:82 ECID:0 Ec:(0x1FB97538) Value:0x19dab960 Cost:(0/0)
2008-02-27 13:52:35.79 spid4 Victim Resource Owner:
2008-02-27 13:52:35.79 spid4 ResType:LockOwner Stype:'OR' Mode: S SPID:82 ECID:0 Ec:(0x1FB97538) Value:0x19dab960 Cost:(0/0)
2008-02-27 14:00:14.57 spid51 Error: 15457, Severity: 0, State: 1
2008-02-27 14:00:14.57 spid51 Configuration option 'show advanced options' changed from 1 to 1. Run the RECONFIGURE statement to install..
2008-02-27 14:03:40.04 spid51 Error: 15457, Severity: 0, State: 1
2008-02-27 14:03:40.04 spid51 Configuration option 'show advanced options' changed from 1 to 1. Run the RECONFIGURE statement to install..
2008-02-27 14:07:51.76 spid51 Error: 15457, Severity: 0, State: 1
2008-02-27 14:07:51.76 spid51 Configuration option 'show advanced options' changed from 1 to 1. Run the RECONFIGURE statement to install..
2008-02-27 14:09:51.26 spid51 Error: 15457, Severity: 0, State: 1
2008-02-27 14:09:51.26 spid51 Configuration option 'show advanced options' changed from 1 to 1. Run the RECONFIGURE statement to install..
2008-02-27 14:12:22.81 spid57 Error: 15457, Severity: 0, State: 1
2008-02-27 14:12:22.81 spid57 Configuration option 'show advanced options' changed from 1 to 1. Run the RECONFIGURE statement to install..
2008-02-27 14:14:23.59 spid57 Error: 15457, Severity: 0, State: 1
2008-02-27 14:14:23.59 spid57 Configuration option 'min server memory (MB)' changed from 2055 to 2013. Run the RECONFIGURE statement to install..
2008-02-27 14:14:23.69 spid57 Error: 15457, Severity: 0, State: 1
2008-02-27 14:14:23.69 spid57 Configuration option 'max server memory (MB)' changed from 200 to 2050. Run the RECONFIGURE statement to install..
2008-02-27 14:14:28.30 spid1 Warning: unable to allocate 'min server memory' of 2013MB.
2008-02-27 14:14:28.52 spid3 SQL Server is terminating due to 'stop' request from Service Control Manager.

The deadlock info is rather unrelated to the problem we've got. It was caused by transaction accessing the Files table (we never touch this table) and it happend three times yesterday at different times of the day than our 5 timeout related problems.

2008-02-27 14:14:35.34 server Microsoft SQL Server 2000 - 8.00.760 (Intel X86)
Dec 17 2002 14:22:05
Copyright (c) 1988-2003 Microsoft Corporation
Standard Edition on Windows NT 5.2 (Build 3790: Service Pack 2)

2008-02-27 14:14:35.34 server Copyright (C) 1988-2002 Microsoft Corporation.
2008-02-27 14:14:35.34 server All rights reserved.
2008-02-27 14:14:35.34 server Server Process ID is 728.
2008-02-27 14:14:35.34 server Logging SQL Server messages in file 'C:\Program Files\Microsoft SQL Server\MSSQL$FLIPINSTANCE\log\ERRORLOG'.
2008-02-27 14:14:35.34 server SQL Server is starting at priority class 'normal'(4 CPUs detected).
2008-02-27 14:14:35.45 server SQL Server configured for thread mode processing.
2008-02-27 14:14:35.45 server Using dynamic lock allocation. [2500] Lock Blocks, [5000] Lock Owner Blocks.
2008-02-27 14:14:35.53 server Attempting to initialize Distributed Transaction Coordinator.
2008-02-27 14:14:36.77 spid3 Starting up database 'master'.
2008-02-27 14:14:36.89 server Using 'SSNETLIB.DLL' version '8.0.766'.
2008-02-27 14:14:36.89 spid5 Starting up database 'model'.
2008-02-27 14:14:36.91 spid3 Server name is 'PTVFELFLIPDB01\FLIPINSTANCE'.
2008-02-27 14:14:36.92 spid8 Starting up database 'msdb'.
2008-02-27 14:14:36.92 spid9 Starting up database 'flip'.
2008-02-27 14:14:36.92 spid10 Starting up database 'flipmerge'.
2008-02-27 14:14:37.05 server SQL server listening on 172.16.7.81: 1433.
2008-02-27 14:14:37.05 server SQL server listening on 127.0.0.1: 1433.
2008-02-27 14:14:37.05 spid5 Clearing tempdb database.
2008-02-27 14:14:37.19 spid5 Starting up database 'tempdb'.
2008-02-27 14:14:37.19 server SQL server listening on TCP, Shared Memory, Named Pipes.
2008-02-27 14:14:37.19 server SQL Server is ready for client connections
2008-02-27 14:14:37.22 spid3 Recovery complete.
2008-02-27 14:14:37.22 spid3 SQL global counter collection task is created.
2008-02-27 14:14:46.80 spid1 Warning: unable to allocate 'min server memory' of 2013MB.
2008-02-27 14:15:59.59 spid52 Using 'xpstar.dll' version '2000.80.760' to execute extended stored procedure 'sp_MSgetversion'.
2008-02-27 14:16:34.42 spid52 Error: 15457, Severity: 0, State: 1
2008-02-27 14:16:34.42 spid52 Configuration option 'show advanced options' changed from 1 to 1. Run the RECONFIGURE statement to install..
2008-02-27 14:16:34.77 spid52 Using 'xplog70.dll' version '2000.80.760' to execute extended stored procedure 'xp_msver'.
2008-02-27 14:16:54.42 spid51 Starting up database 'flip'.
2008-02-27 14:16:54.44 spid51 Bypassing recovery for database 'flip' because it is marked IN LOAD.
2008-02-27 14:16:54.53 spid51 Starting up database 'flip'.
2008-02-27 14:16:54.53 spid51 Bypassing recovery for database 'flip' because it is marked IN LOAD.
2008-02-27 14:16:54.63 spid51 Recovery is checkpointing database 'flip' (5)
2008-02-27 14:16:54.67 spid51 Starting up database 'flip'.
2008-02-27 14:16:54.86 backup Database restored: Database: flip, creation date(time): 2007/07/09(14:36:20), first LSN: 278124:264:1, last LSN: 278124:286:1, number of dump devices: 1, device information: (FILE=1, TYPE=DISK: {'C:\Program Files\Telestream\FactoryArray\FactoryArrayDBMSqlServerShare\flip_172.16.7.82.dat'}).
2008-02-27 14:17:33.99 spid56 Using 'odsole70.dll' version '2000.80.760' to execute extended stored procedure 'sp_OACreate'.
2008-02-27 14:17:37.31 spid56 Error: 15457, Severity: 0, State: 1
2008-02-27 14:17:37.31 spid56 Configuration option 'show advanced options' changed from 1 to 1. Run the RECONFIGURE statement to install..
2008-02-27 14:17:37.36 spid56 Error: 15457, Severity: 0, State: 1
2008-02-27 14:17:37.36 spid56 Configuration option 'max server memory (MB)' changed from 2050 to 2055. Run the RECONFIGURE statement to install..
2008-02-27 14:18:08.63 backup Database backed up: Database: flip, creation date(time): 2007/07/09(14:36:20), pages dumped: 157843, first LSN: 278124:486:1, last LSN: 278125:203:1, number of dump devices: 1, device information: (FILE=1, TYPE=DISK: {'\\PTVFELFLIPDB02\FactoryArrayDBMSqlServerShare\flip_172.16.7.81.dat'}).
2008-02-27 14:18:21.16 spid54 Error: 15457, Severity: 0, State: 1
2008-02-27 14:18:21.16 spid54 Configuration option 'show advanced options' changed from 1 to 1. Run the RECONFIGURE statement to install..
2008-02-27 14:18:21.21 spid54 Error: 15457, Severity: 0, State: 1
2008-02-27 14:18:21.21 spid54 Configuration option 'max server memory (MB)' changed from 2055 to 2055. Run the RECONFIGURE statement to install..
2008-02-27 14:20:25.03 spid55 Error: 15457, Severity: 0, State: 1
2008-02-27 14:20:25.03 spid55 Configuration option 'show advanced options' changed from 1 to 1. Run the RECONFIGURE statement to install..
2008-02-27 14:20:25.08 spid55 Error: 15457, Severity: 0, State: 1
2008-02-27 14:20:25.08 spid55 Configuration option 'max server memory (MB)' changed from 2055 to 2055. Run the RECONFIGURE statement to install..
2008-02-27 14:21:02.63 spid51 Error: 15457, Severity: 0, State: 1
2008-02-27 14:21:02.63 spid51 Configuration option 'show advanced options' changed from 1 to 1. Run the RECONFIGURE statement to install..
2008-02-27 14:21:02.67 spid51 Error: 15457, Severity: 0, State: 1
2008-02-27 14:21:02.67 spid51 Configuration option 'max server memory (MB)' changed from 2055 to 2055. Run the RECONFIGURE statement to install..
2008-02-27 14:22:19.84 spid52 Error: 15457, Severity: 0, State: 1
2008-02-27 14:22:19.84 spid52 Configuration option 'show advanced options' changed from 1 to 1. Run the RECONFIGURE statement to install..
2008-02-27 14:22:19.88 spid52 Error: 15457, Severity: 0, State: 1
2008-02-27 14:22:19.88 spid52 Configuration option 'max server memory (MB)' changed from 2055 to 2055. Run the RECONFIGURE statement to install..
2008-02-27 14:22:47.82 spid58 Error: 15457, Severity: 0, State: 1
2008-02-27 14:22:47.82 spid58 Configuration option 'show advanced options' changed from 1 to 1. Run the RECONFIGURE statement to install..
2008-02-27 14:23:25.68 spid52 Error: 15457, Severity: 0, State: 1
2008-02-27 14:23:25.68 spid52 Configuration option 'show advanced options' changed from 1 to 1. Run the RECONFIGURE statement to install..
2008-02-27 14:23:25.73 spid52 Error: 15457, Severity: 0, State: 1
2008-02-27 14:23:25.73 spid52 Configuration option 'max server memory (MB)' changed from 2055 to 50. Run the RECONFIGURE statement to install..
2008-02-27 14:23:46.20 spid58 Error: 15457, Severity: 0, State: 1
2008-02-27 14:23:46.20 spid58 Configuration option 'show advanced options' changed from 1 to 1. Run the RECONFIGURE statement to install..
2008-02-27 14:24:02.72 spid58 Error: 15457, Severity: 0, State: 1
2008-02-27 14:24:02.72 spid58 Configuration option 'max server memory (MB)' changed from 50 to 2050. Run the RECONFIGURE statement to install..
2008-02-27 14:24:30.07 spid52 Error: 15457, Severity: 0, State: 1
2008-02-27 14:24:30.07 spid52 Configuration option 'show advanced options' changed from 1 to 1. Run the RECONFIGURE statement to install..
2008-02-27 14:24:30.12 spid52 Error: 15457, Severity: 0, State: 1
2008-02-27 14:24:30.12 spid52 Configuration option 'max server memory (MB)' changed from 2050 to 2055. Run the RECONFIGURE statement to install..
2008-02-27 14:24:41.96 spid58 Error: 15457, Severity: 0, State: 1
2008-02-27 14:24:41.96 spid58 Configuration option 'show advanced options' changed from 1 to 1. Run the RECONFIGURE statement to install..
2008-02-27 14:26:07.45 spid3 SQL Server is terminating due to 'stop' request from Service Control Manager.

2008-02-27 14:26:16.86 server Microsoft SQL Server 2000 - 8.00.760 (Intel X86)
Dec 17 2002 14:22:05
Copyright (c) 1988-2003 Microsoft Corporation
Standard Edition on Windows NT 5.2 (Build 3790: Service Pack 2)

2008-02-27 14:26:16.86 server Copyright (C) 1988-2002 Microsoft Corporation.
2008-02-27 14:26:16.86 server All rights reserved.
2008-02-27 14:26:16.86 server Server Process ID is 656.
2008-02-27 14:26:16.86 server Logging SQL Server messages in file 'C:\Program Files\Microsoft SQL Server\MSSQL$FLIPINSTANCE\log\ERRORLOG'.
2008-02-27 14:26:16.86 server SQL Server is starting at priority class 'normal'(4 CPUs detected).
2008-02-27 14:26:16.94 server SQL Server configured for thread mode processing.
2008-02-27 14:26:16.94 server Using dynamic lock allocation. [2500] Lock Blocks, [5000] Lock Owner Blocks.
2008-02-27 14:26:17.02 server Attempting to initialize Distributed Transaction Coordinator.
2008-02-27 14:26:18.03 spid3 Starting up database 'master'.
2008-02-27 14:26:18.10 server Using 'SSNETLIB.DLL' version '8.0.766'.
2008-02-27 14:26:18.10 spid5 Starting up database 'model'.
2008-02-27 14:26:18.11 server SQL server listening on 172.16.7.81: 1433.
2008-02-27 14:26:18.11 server SQL server listening on 127.0.0.1: 1433.
2008-02-27 14:26:18.11 spid3 Server name is 'PTVFELFLIPDB01\FLIPINSTANCE'.
2008-02-27 14:26:18.11 spid8 Starting up database 'msdb'.
2008-02-27 14:26:18.11 spid9 Starting up database 'flip'.
2008-02-27 14:26:18.11 spid10 Starting up database 'flipmerge'.
2008-02-27 14:26:18.13 server SQL server listening on TCP, Shared Memory, Named Pipes.
2008-02-27 14:26:18.13 server SQL Server is ready for client connections
2008-02-27 14:26:18.17 spid9 0 transactions rolled back in database 'flip' (5).
2008-02-27 14:26:18.22 spid9 Recovery is checkpointing database 'flip' (5)
2008-02-27 14:26:18.24 spid5 Clearing tempdb database.
2008-02-27 14:26:18.30 spid5 Starting up database 'tempdb'.
2008-02-27 14:26:18.33 spid3 Recovery complete.
2008-02-27 14:26:18.33 spid3 SQL global counter collection task is created.
2008-02-27 14:26:28.09 spid1 Warning: unable to allocate 'min server memory' of 2013MB.
2008-02-27 14:27:36.62 spid3 SQL Server is terminating due to 'stop' request from Service Control Manager.

2008-02-27 14:26:16.86 server Microsoft SQL Server 2000 - 8.00.760 (Intel X86)
Dec 17 2002 14:22:05
Copyright (c) 1988-2003 Microsoft Corporation
Standard Edition on Windows NT 5.2 (Build 3790: Service Pack 2)

2008-02-27 14:26:16.86 server Copyright (C) 1988-2002 Microsoft Corporation.
2008-02-27 14:26:16.86 server All rights reserved.
2008-02-27 14:26:16.86 server Server Process ID is 656.
2008-02-27 14:26:16.86 server Logging SQL Server messages in file 'C:\Program Files\Microsoft SQL Server\MSSQL$FLIPINSTANCE\log\ERRORLOG'.
2008-02-27 14:26:16.86 server SQL Server is starting at priority class 'normal'(4 CPUs detected).
2008-02-27 14:26:16.94 server SQL Server configured for thread mode processing.
2008-02-27 14:26:16.94 server Using dynamic lock allocation. [2500] Lock Blocks, [5000] Lock Owner Blocks.
2008-02-27 14:26:17.02 server Attempting to initialize Distributed Transaction Coordinator.
2008-02-27 14:26:18.03 spid3 Starting up database 'master'.
2008-02-27 14:26:18.10 server Using 'SSNETLIB.DLL' version '8.0.766'.
2008-02-27 14:26:18.10 spid5 Starting up database 'model'.
2008-02-27 14:26:18.11 server SQL server listening on 172.16.7.81: 1433.
2008-02-27 14:26:18.11 server SQL server listening on 127.0.0.1: 1433.
2008-02-27 14:26:18.11 spid3 Server name is 'PTVFELFLIPDB01\FLIPINSTANCE'.
2008-02-27 14:26:18.11 spid8 Starting up database 'msdb'.
2008-02-27 14:26:18.11 spid9 Starting up database 'flip'.
2008-02-27 14:26:18.11 spid10 Starting up database 'flipmerge'.
2008-02-27 14:26:18.13 server SQL server listening on TCP, Shared Memory, Named Pipes.
2008-02-27 14:26:18.13 server SQL Server is ready for client connections
2008-02-27 14:26:18.17 spid9 0 transactions rolled back in database 'flip' (5).
2008-02-27 14:26:18.22 spid9 Recovery is checkpointing database 'flip' (5)
2008-02-27 14:26:18.24 spid5 Clearing tempdb database.
2008-02-27 14:26:18.30 spid5 Starting up database 'tempdb'.
2008-02-27 14:26:18.33 spid3 Recovery complete.
2008-02-27 14:26:18.33 spid3 SQL global counter collection task is created.
2008-02-27 14:26:28.09 spid1 Warning: unable to allocate 'min server memory' of 2013MB.
2008-02-27 14:27:36.62 spid3 SQL Server is terminating due to 'stop' request from Service Control Manager.

2008-02-27 14:27:55.85 server Microsoft SQL Server 2000 - 8.00.760 (Intel X86)
Dec 17 2002 14:22:05
Copyright (c) 1988-2003 Microsoft Corporation
Standard Edition on Windows NT 5.2 (Build 3790: Service Pack 2)

2008-02-27 14:27:55.85 server Copyright (C) 1988-2002 Microsoft Corporation.
2008-02-27 14:27:55.85 server All rights reserved.
2008-02-27 14:27:55.85 server Server Process ID is 1356.
2008-02-27 14:27:55.85 server Logging SQL Server messages in file 'C:\Program Files\Microsoft SQL Server\MSSQL$FLIPINSTANCE\log\ERRORLOG'.
2008-02-27 14:27:55.85 server SQL Server is starting at priority class 'normal'(4 CPUs detected).
2008-02-27 14:27:55.92 server SQL Server configured for thread mode processing.
2008-02-27 14:27:55.92 server Using dynamic lock allocation. [2500] Lock Blocks, [5000] Lock Owner Blocks.
2008-02-27 14:27:55.99 server Attempting to initialize Distributed Transaction Coordinator.
2008-02-27 14:27:58.00 spid3 Starting up database 'master'.
2008-02-27 14:27:58.08 server Using 'SSNETLIB.DLL' version '8.0.766'.
2008-02-27 14:27:58.08 spid5 Starting up database 'model'.
2008-02-27 14:27:58.10 server SQL server listening on 172.16.7.81: 1433.
2008-02-27 14:27:58.10 server SQL server listening on 127.0.0.1: 1433.
2008-02-27 14:27:58.10 spid3 Server name is 'PTVFELFLIPDB01\FLIPINSTANCE'.
2008-02-27 14:27:58.10 spid8 Starting up database 'msdb'.
2008-02-27 14:27:58.10 spid9 Starting up database 'flip'.
2008-02-27 14:27:58.10 spid10 Starting up database 'flipmerge'.
2008-02-27 14:27:58.11 server SQL server listening on TCP, Shared Memory, Named Pipes.
2008-02-27 14:27:58.11 server SQL Server is ready for client connections
2008-02-27 14:27:58.11 spid5 Clearing tempdb database.
2008-02-27 14:27:58.16 spid5 Starting up database 'tempdb'.
2008-02-27 14:27:58.19 spid3 Recovery complete.
2008-02-27 14:27:58.19 spid3 SQL global counter collection task is created.
2008-02-27 14:28:05.13 spid52 Using 'odsole70.dll' version '2000.80.760' to execute extended stored procedure 'sp_OACreate'.
2008-02-27 14:28:08.02 spid1 Warning: unable to allocate 'min server memory' of 2013MB.
2008-02-27 14:28:54.24 spid82 Using 'xpstar.dll' version '2000.80.760' to execute extended stored procedure 'sp_MSgetversion'.
2008-02-27 14:28:56.91 spid82 Error: 15457, Severity: 0, State: 1
2008-02-27 14:28:56.91 spid82 Configuration option 'show advanced options' changed from 1 to 1. Run the RECONFIGURE statement to install..
2008-02-27 14:28:57.00 spid82 Using 'xplog70.dll' version '2000.80.760' to execute extended stored procedure 'xp_msver'.
2008-02-27 14:29:17.63 backup Database backed up: Database: flip, creation date(time): 2007/07/09(14:36:20), pages dumped: 161092, first LSN: 278263:74:1, last LSN: 278332:897:1, number of dump devices: 1, device information: (FILE=1, TYPE=DISK: {'\\PTVFELFLIPDB02\FactoryArrayDBMSqlServerShare\flip_172.16.7.81.dat'}).
2008-02-27 14:34:26.20 spid82 Error: 15457, Severity: 0, State: 1
2008-02-27 14:34:26.20 spid82 Configuration option 'show advanced options' changed from 1 to 1. Run the RECONFIGURE statement to install..
2008-02-27 14:41:03.13 spid4
Deadlock encountered .... Printing deadlock information
2008-02-27 14:41:03.13 spid4
2008-02-27 14:41:03.13 spid4 Wait-for graph
2008-02-27 14:41:03.13 spid4
2008-02-27 14:41:03.13 spid4 Node:1
2008-02-27 14:41:03.13 spid4 RID: 5:1:167:38 CleanCnt:1 Mode: X Flags: 0x2
2008-02-27 14:41:03.13 spid4 Grant List 1::
2008-02-27 14:41:03.13 spid4 Owner:0x19db9b60 Mode: X Flg:0x0 Ref:1 Life:02000000 SPID:58 ECID:0
2008-02-27 14:41:03.13 spid4 SPID: 58 ECID: 0 Statement Type: CURSORDELETE Line #: 1
2008-02-27 14:41:03.13 spid4 Input Buf: RPC Event: sp_cursor;1
2008-02-27 14:41:03.13 spid4 Requested By:
2008-02-27 14:41:03.13 spid4 ResType:LockOwner Stype:'OR' Mode: S SPID:51 ECID:0 Ec:(0x19F63538) Value:0x19db9cc0 Cost:(0/0)
2008-02-27 14:41:03.13 spid4
2008-02-27 14:41:03.13 spid4 Node:2
2008-02-27 14:41:03.13 spid4 KEY: 5:149575571:2 (a401bbc7434d) CleanCnt:1 Mode: S Flags: 0x0
2008-02-27 14:41:03.13 spid4 Grant List 2::
2008-02-27 14:41:03.13 spid4 Owner:0x19db9980 Mode: S Flg:0x0 Ref:1 Life:00000000 SPID:51 ECID:0
2008-02-27 14:41:03.13 spid4 SPID: 51 ECID: 0 Statement Type: SELECT Line #: 1
2008-02-27 14:41:03.13 spid4 Input Buf: RPC Event: sp_executesql;1
2008-02-27 14:41:03.13 spid4 Requested By:
2008-02-27 14:41:03.13 spid4 ResType:LockOwner Stype:'OR' Mode: X SPID:58 ECID:0 Ec:(0x1A30B530) Value:0x19dba440 Cost:(0/3C)
2008-02-27 14:41:03.13 spid4 Victim Resource Owner:
2008-02-27 14:41:03.13 spid4 ResType:LockOwner Stype:'OR' Mode: S SPID:51 ECID:0 Ec:(0x19F63538) Value:0x19db9cc0 Cost:(0/0)
2008-02-27 15:34:54.26 spid89 Using 'xpsqlbot.dll' version '2000.80.760' to execute extended stored procedure 'xp_qv'.
2008-02-27 15:37:31.87 spid88 Error: 15457, Severity: 0, State: 1
2008-02-27 15:37:31.87 spid88 Configuration option 'show advanced options' changed from 1 to 1. Run the RECONFIGURE statement to install..
2008-02-27 15:56:33.16 spid92 Error: 15457, Severity: 0, State: 1
2008-02-27 15:56:33.16 spid92 Configuration option 'show advanced options' changed from 1 to 1. Run the RECONFIGURE statement to install..
2008-02-27 16:49:25.92 spid69 Error: 15457, Severity: 0, State: 1
2008-02-27 16:49:25.92 spid69 Configuration option 'show advanced options' changed from 1 to 1. Run the RECONFIGURE statement to install..
2008-02-27 16:49:25.97 spid69 Error: 15457, Severity: 0, State: 1
2008-02-27 16:49:25.97 spid69 Configuration option 'max server memory (MB)' changed from 2055 to 2055. Run the RECONFIGURE statement to install..
2008-02-27 18:07:57.88 spid53 Error: 15457, Severity: 0, State: 1
2008-02-27 18:07:57.88 spid53 Configuration option 'show advanced options' changed from 1 to 1. Run the RECONFIGURE statement to install..
2008-02-27 18:07:57.93 spid53 Error: 15457, Severity: 0, State: 1
2008-02-27 18:07:57.93 spid53 Configuration option 'max server memory (MB)' changed from 2055 to 2055. Run the RECONFIGURE statement to install..
2008-02-27 18:09:08.88 spid52 Error: 15457, Severity: 0, State: 1
2008-02-27 18:09:08.88 spid52 Configuration option 'show advanced options' changed from 1 to 1. Run the RECONFIGURE statement to install..
2008-02-27 18:09:08.93 spid52 Error: 15457, Severity: 0, State: 1
2008-02-27 18:09:08.93 spid52 Configuration option 'max server memory (MB)' changed from 2055 to 2055. Run the RECONFIGURE statement to install..
2008-02-28 09:21:46.88 spid68 Error: 15457, Severity: 0, State: 1
2008-02-28 09:21:46.88 spid68 Configuration option 'show advanced options' changed from 1 to 1. Run the RECONFIGURE statement to install..
2008-02-28 09:22:16.24 spid68 Error: 15457, Severity: 0, State: 1
2008-02-28 09:22:16.24 spid68 Configuration option 'min server memory (MB)' changed from 2013 to 68. Run the RECONFIGURE statement to install..
2008-02-28 09:22:16.33 spid68 Error: 15457, Severity: 0, State: 1
2008-02-28 09:22:16.33 spid68 Configuration option 'max server memory (MB)' changed from 2055 to 68. Run the RECONFIGURE statement to install..
2008-02-28 09:23:14.32 spid3 SQL Server is terminating due to 'stop' request from Service Control Manager.

RickD
Slow But Sure Yak Herding Master

3608 Posts

Posted - 2008-02-28 : 09:35:05

How much memory have you got in your server and why do you keep trying to change all the system settings?

khycnar
Starting Member

6 Posts

Posted - 2008-02-28 : 10:04:30

We've got 4GB on the box. We were changing this, because for a very strange reason the application we use (the third party one) has a capability of changing the values and it does on startup. Initially it was setting this to a very small value, but even after we blocked this bizzare functionality and set the value manually to about 2000 GB the problem still occurs.

khycnar
Starting Member

6 Posts

Posted - 2008-02-28 : 10:06:14

I mean... 2 GB of course :)

quote:
Originally posted by khycnar

We've got 4GB on the box. We were changing this, because for a very strange reason the application we use (the third party one) has a capability of changing the values and it does on startup. Initially it was setting this to a very small value, but even after we blocked this bizzare functionality and set the value manually to about 2 GB the problem still occurs.

RickD
Slow But Sure Yak Herding Master

3608 Posts

Posted - 2008-02-28 : 10:47:32

You shouldn't need to set it that high anyway, the part that concerns me is the:

2008-02-27 14:28:08.02 spid1 Warning: unable to allocate 'min server memory' of 2013MB.

Min server memory (as long as it a SQL Server dedicated box, can be set as low as you like. It still seems the application is trying to change these values according to your logs, I would guess that this is the crux of your problem. Do you have awe enabled (set to 1) in sp_configure?

khycnar
Starting Member

6 Posts

Posted - 2008-02-28 : 11:22:43

I've just decreased the min mem value and gonna run some tests now. The awe is not enabled.

Thanx for your suggestions! :)

K.

RickD
Slow But Sure Yak Herding Master

3608 Posts

Posted - 2008-02-28 : 11:25:24

It should be if you have 4GB.

khycnar
Starting Member

6 Posts

Posted - 2008-02-28 : 11:36:32

What do you mean by saying "It should"? Will the DB server break if it's not set, or it just won't be able to utilize all the memory available?