Server Hang - 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

General SQL Server Forums

New to SQL Server Programming

Server Hang

Author

Topic

keat1963
Starting Member

5 Posts

Posted - 2007-02-06 : 08:15:53

Guys.
Quite a large log attached.

I had 5 servers hang all on the same day, all within about 5 mins of each other scattered across 4 corners of the UK. Our support team tell me that it has something to do with SQL Server, but cannot say what.
I can see looking at the error log of one of the servers, that there are about4 entries everyday since startup, and this continues right up until the night before the freeze.

At 22:00 the night before the freeze, a load of entries are written (Iv'e cut down the list to make it easier to read). then at around 4am the servers all froze.
Could someone take a sneaky peak at these logs and tell me in your own opinion what caused this to happen.

The first section, is what I believe to be normal

2006-11-28 20:52:53.68 server Copyright (C) 1988-2002 Microsoft Corporation.
2006-11-28 20:52:53.68 server All rights reserved.
2006-11-28 20:52:53.68 server Server Process ID is 952.
2006-11-28 20:52:53.68 server Logging SQL Server messages in file 'D:\Program Files\Microsoft SQL Server\MSSQL\log\ERRORLOG'.
2006-11-28 20:52:53.73 server SQL Server is starting at priority class 'normal'(1 CPU detected).
2006-11-28 20:52:54.75 server Working Set size set to 409600 kilobytes.
2006-11-28 20:52:54.90 server SQL Server configured for thread mode processing.
2006-11-28 20:52:54.90 server Processor affinity turned ON, processor mask 0x1
2006-11-28 20:52:54.92 server Using dynamic lock allocation. [2500] Lock Blocks, [5000] Lock Owner Blocks.
2006-11-28 20:52:55.20 server Attempting to initialize Distributed Transaction Coordinator.
2006-11-28 20:52:57.20 server Failed to obtain TransactionDispenserInterface: Result Code = 0x8004d01b
2006-11-28 20:52:57.53 spid3 Starting up database 'master'.
2006-11-28 20:52:59.31 spid3 Server name is 'SN047483'.
2006-11-28 20:52:59.31 server Using 'SSNETLIB.DLL' version '8.0.760'.
2006-11-28 20:52:59.31 spid5 Starting up database 'model'.
2006-11-28 20:52:59.50 spid8 Starting up database 'msdb'.
2006-11-28 20:52:59.50 spid9 Starting up database 'pubs'.
2006-11-28 20:52:59.53 spid10 Starting up database 'udb'.
2006-11-28 20:52:59.64 spid11 Starting up database 'vgold'.
2006-11-28 20:53:00.07 server SQL server listening on 155.202.58.53: 1433.
2006-11-28 20:53:00.07 server SQL server listening on 127.0.0.1: 1433.
2006-11-28 20:53:00.29 spid5 Clearing tempdb database.
2006-11-28 20:53:00.64 server SQL server listening on TCP, Shared Memory, Named Pipes.
2006-11-28 20:53:00.64 server SQL Server is ready for client connections
2006-11-28 20:53:00.71 spid9 Starting up database 'dbs'.
2006-11-28 20:53:01.01 spid8 Recovery is checkpointing database 'msdb' (4)
2006-11-28 20:53:01.50 spid5 Starting up database 'tempdb'.
2006-11-28 20:53:53.78 spid3 Recovery complete.
2006-11-28 20:53:53.78 spid3 SQL global counter collection task is created.
2006-11-28 20:53:54.32 spid59 Using 'xpsqlbot.dll' version '2000.80.194' to execute extended stored procedure 'xp_qv'.
2006-11-29 00:00:01.10 spid69 Using 'xpstar.dll' version '2000.80.760' to execute extended stored procedure 'xp_instance_regread'.
2006-11-29 02:00:01.54 spid69 Using 'xplog70.dll' version '2000.80.760' to execute extended stored procedure 'xp_cmdshell'.
2006-11-29 02:00:09.31 backup Database backed up: Database: master, creation date(time): 2006/11/28(20:52:57), pages dumped: 1907, first LSN: 159:245:1, last LSN: 159:247:1, number of dump devices: 1, device information: (FILE=1, TYPE=DISK: {'QMBACKDEVICE'}).
2006-11-29 02:00:11.46 backup Database backed up: Database: msdb, creation date(time): 2000/08/06(01:40:56), pages dumped: 1667, first LSN: 397:332:1, last LSN: 397:335:1, number of dump devices: 1, device information: (FILE=1, TYPE=DISK: {'QMBACKDEVICE'}).
2006-11-29 02:01:58.10 backup Database backed up: Database: dbs, creation date(time): 2004/10/05(08:00:04), pages dumped: 94467, first LSN: 114:53199:1, last LSN: 114:53203:1, number of dump devices: 1, device information: (FILE=1, TYPE=DISK: {'QMBACKDEVICE'}).
2006-11-29 02:01:58.20 backup Database log truncated: Database: dbs.
2006-11-29 10:51:33.43 spid62 Using 'odsole70.dll' version '2000.80.760' to execute extended stored procedure 'sp_OACreate'.
2006-11-30 02:00:04.34 backup Database backed up: Database: master, creation date(time): 2006/11/28(20:52:57), pages dumped: 1907, first LSN: 159:260:1, last LSN: 159:262:1, number of dump devices: 1, device information: (FILE=1, TYPE=DISK: {'QMBACKDEVICE'}).
2006-11-30 02:00:06.57 backup Database backed up: Database: msdb, creation date(time): 2000/08/06(01:40:56), pages dumped: 1667, first LSN: 398:26:1, last LSN: 398:29:1, number of dump devices: 1, device information: (FILE=1, TYPE=DISK: {'QMBACKDEVICE'}).
2006-11-30 02:01:53.84 backup Database backed up: Database: dbs, creation date(time): 2004/10/05(08:00:04), pages dumped: 94467, first LSN: 114:54895:1, last LSN: 114:54899:1, number of dump devices: 1, device information: (FILE=1, TYPE=DISK: {'QMBACKDEVICE'}).
2006-11-30 02:01:53.93 backup Database log truncated: Database: dbs.
2006-11-30 13:10:09.96 spid67 Error: 60002, Severity: 15, State: 1
2006-11-30 13:10:09.96 spid67 PBX login_id 5592 already exists in user id 379. Proc Name: um_user_insert.
2006-12-01 02:00:04.51 backup Database backed up: Database: master, creation date(time): 2006/11/28(20:52:57), pages dumped: 1907, first LSN: 159:275:1, last LSN: 159:277:1, number of dump devices: 1, device information: (FILE=1, TYPE=DISK: {'QMBACKDEVICE'}).
2006-12-01 02:00:06.76 backup Database backed up: Database: msdb, creation date(time): 2000/08/06(01:40:56), pages dumped: 1667, first LSN: 398:408:1, last LSN: 398:411:1, number of dump devices: 1, device information: (FILE=1, TYPE=DISK: {'QMBACKDEVICE'}).
2006-12-01 02:01:52.31 backup Database backed up: Database: dbs, creation date(time): 2004/10/05(08:00:04), pages dumped: 94515, first LSN: 114:55915:1, last LSN: 114:55923:1, number of dump devices: 1, device information: (FILE=1, TYPE=DISK: {'QMBACKDEVICE'}).
2006-12-01 02:01:52.39 backup Database log truncated: Database: dbs.

This second section then has around a good few hundred entries.

2006-12-01 22:00:01.98 spid67 Error: 60132, Severity: 15, State: 1
2006-12-01 22:00:01.98 spid67 Folder 7 is not assigned to user 11 Proc Name: ags_workflow_sess_count.
2006-12-01 22:00:02.04 spid67 Error: 60132, Severity: 15, State: 1
2006-12-01 22:00:02.04 spid67 Folder 7 is not assigned to user 11 Proc Name: ags_workflow_sess_count.
2006-12-01 22:18:02.57 spid66 Error: 60132, Severity: 15, State: 1
2006-12-01 22:18:02.57 spid66 Folder 7 is not assigned to user 63 Proc Name: ags_workflow_sess_count.
2006-12-01 22:43:37.42 spid67 Error: 60132, Severity: 15, State: 1
2006-12-01 22:43:37.42 spid67 Folder 7 is not assigned to user 493 Proc Name: ags_workflow_sess_count.
2006-12-01 22:43:37.43 spid67 Error: 60132, Severity: 15, State: 1
2006-12-01 22:43:37.43 spid67 Folder 7 is not assigned to user 493 Proc Name: ags_workflow_sess_count.
2006-12-01 22:44:37.51 spid58 Error: 60132, Severity: 15, State: 1
2006-12-01 22:44:37.51 spid58 Folder 7 is not assigned to user 613 Proc Name: ags_workflow_sess_count.
2006-12-01 22:46:07.00 spid67 Error: 60132, Severity: 15, State: 1
2006-12-01 22:46:07.00 spid67 Folder 7 is not assigned to user 660 Proc Name: ags_workflow_sess_count.
2006-12-01 23:00:20.65 spid58 Error: 60132, Severity: 15, State: 1
2006-12-01 23:00:20.65 spid58 Folder 7 is not assigned to user 949 Proc Name: ags_workflow_sess_count.
2006-12-01 23:00:20.67 spid58 Error: 60132, Severity: 15, State: 1
2006-12-01 23:00:20.67 spid58 Folder 7 is not assigned to user 973 Proc Name: ags_workflow_sess_count.
2006-12-01 23:02:33.07 spid66 Error: 60132, Severity: 15, State: 1
2006-12-01 23:02:33.07 spid66 Folder 7 is not assigned to user 1010 Proc Name: ags_workflow_sess_count.
2006-12-01 23:04:38.10 spid58 Error: 60132, Severity: 15, State: 1
2006-12-01 23:04:38.10 spid58 Folder 7 is not assigned to user 1247 Proc Name: ags_workflow_sess_count.
2006-12-01 23:04:38.12 spid58 Error: 60132, Severity: 15, State: 1
2006-12-01 23:04:38.12 spid58 Folder 7 is not assigned to user 1266 Proc Name: ags_workflow_sess_count.
2006-12-01 23:06:08.59 spid66 Error: 60132, Severity: 15, State: 1
2006-12-01 23:06:08.59 spid66 Folder 7 is not assigned to user 1659 Proc Name: ags_workflow_sess_count.
2006-12-01 23:06:08.59 spid66 Error: 60132, Severity: 15, State: 1
2006-12-01 23:06:08.59 spid66 Folder 7 is not assigned to user 1812 Proc Name: ags_workflow_sess_count.
2006-12-01 23:06:08.59 spid66 Error: 60132, Severity: 15, State: 1
2006-12-01 23:06:08.59 spid66 Folder 7 is not assigned to user 1812 Proc Name: ags_workflow_sess_count.
2006-12-01 23:06:08.60 spid66 Error: 60132, Severity: 15, State: 1
2006-12-01 23:06:08.60 spid66 Folder 7 is not assigned to user 1812 Proc Name: ags_workflow_sess_count.
2006-12-01 23:06:08.60 spid66 Error: 60132, Severity: 15, State: 1
2006-12-01 23:06:08.60 spid66 Folder 7 is not assigned to user 1812 Proc Name: ags_workflow_sess_count.
2006-12-01 23:06:08.62 spid66 Error: 60132, Severity: 15, State: 1
2006-12-01 23:06:08.62 spid66 Folder 7 is not assigned to user 1812 Proc Name: ags_workflow_sess_count.
2006-12-01 23:06:08.62 spid66 Error: 60132, Severity: 15, State: 1
2006-12-01 23:06:08.62 spid66 Folder 7 is not assigned to user 1812 Proc Name: ags_workflow_sess_count.
2006-12-01 23:06:08.62 spid66 Error: 60132, Severity: 15, State: 1
2006-12-01 23:06:08.62 spid66 Folder 7 is not assigned to user 1812 Proc Name: ags_workflow_sess_count.
2006-12-01 23:06:08.62 spid66 Error: 60132, Severity: 15, State: 1
2006-12-01 23:06:08.62 spid66 Folder 7 is not assigned to user 1812 Proc Name: ags_workflow_sess_count.
2006-12-01 23:06:08.64 spid66 Error: 60132, Severity: 15, State: 1
2006-12-01 23:06:08.64 spid66 Folder 7 is not assigned to user 1812 Proc Name: ags_workflow_sess_count.
2006-12-01 23:06:08.64 spid66 Error: 60132, Severity: 15, State: 1

This section shows from 4am onwards

2007-01-13 04:05:09.87 spid71 Error: 60132, Severity: 15, State: 1
2007-01-13 04:05:09.87 spid71 Folder 7 is not assigned to user 613 Proc Name: ags_workflow_sess_count.
2007-01-13 04:05:13.40 spid75 Error: 60132, Severity: 15, State: 1
2007-01-13 04:05:13.40 spid75 Folder 7 is not assigned to user 660 Proc Name: ags_workflow_sess_count.
2007-01-13 04:05:16.15 spid77 Error: 60132, Severity: 15, State: 1
2007-01-13 04:05:16.15 spid77 Folder 7 is not assigned to user 660 Proc Name: ags_workflow_sess_count.
2007-01-13 04:05:17.29 spid61 Error: 60132, Severity: 15, State: 1
2007-01-13 04:05:17.29 spid61 Folder 7 is not assigned to user 660 Proc Name: ags_workflow_sess_count.
2007-01-13 04:05:18.12 spid69 Error: 60132, Severity: 15, State: 1
2007-01-13 04:05:18.12 spid69 Folder 7 is not assigned to user 63 Proc Name: ags_workflow_sess_count.
2007-01-13 04:10:28.81 spid51 Unable to load OLE/DB initialization service.
2007-01-13 04:58:12.21 server Error: 17883, Severity: 1, State: 0
2007-01-13 04:58:12.21 server The Scheduler 0 appears to be hung. SPID 0, ECID 0, UMS Context 0x250A5C68.
2007-01-13 04:59:12.21 server Error: 17883, Severity: 1, State: 0
2007-01-13 04:59:12.21 server The Scheduler 0 appears to be hung. SPID 0, ECID 0, UMS Context 0x250A5C68.
2007-01-13 05:00:12.21 server Error: 17883, Severity: 1, State: 0
2007-01-13 05:00:12.21 server The Scheduler 0 appears to be hung. SPID 0, ECID 0, UMS Context 0x250A5C68.
2007-01-13 05:01:12.21 server Error: 17883, Severity: 1, State: 0
2007-01-13 05:01:12.21 server The Scheduler 0 appears to be hung. SPID 0, ECID 0, UMS Context 0x250A5C68.
2007-01-13 05:02:12.21 server Error: 17883, Severity: 1, State: 0
2007-01-13 05:02:12.21 server The Scheduler 0 appears to be hung. SPID 0, ECID 0, UMS Context 0x250A5C68.
2007-01-13 05:03:12.21 server Error: 17883, Severity: 1, State: 0

Kristen
Test

22859 Posts

Posted - 2007-02-06 : 10:36:23

"2007-01-13 04:05:09.87 spid71 Error: 60132, Severity: 15, State: 1
2007-01-13 04:05:09.87 spid71 Folder 7 is not assigned to user 613 Proc Name: ags_workflow_sess_count."

I reckon these are messages raised by your procedure: ags_workflow_sess_count

BoL says "Error messages with severity levels from 11 through 16 are generated by the user and can be corrected by the user"

I suggest you have a look at the code in "ags_workflow_sess_count" and see what it does

sp_helptext 'ags_workflow_sess_count'

should give you the source (in Query Analyser); search for "is not assigned to user" and see what it looks like.

In particular review whether the Procedure is calling some external 3rd parry code - which might be hitting a rock!

Kristen

keat1963
Starting Member

5 Posts

Posted - 2007-02-06 : 11:49:29

Any thoughts why this would affect 5 servers, all of which live 100 miles in opposite directions.

Kristen
Test

22859 Posts

Posted - 2007-02-06 : 15:47:18

If all the servers are using "ags_workflow_sess_count" and that uses some external / 3rd party object, then I can think of numerous reasons why they would all go AWOL at the same time ... license expired, Comms issue, some upgrade at the remote end, malicious "name no longer in payroll" routine ......

Kristen

keat1963
Starting Member

5 Posts

Posted - 2007-02-06 : 18:13:08

We have 6 sites all sitting 0n the same AD. The only server that didn't go AWOL was the one sitting at the same place as the customers AD.
My guess is the AD went AWOL and the other 5 servers fell over, but the customer is saying that nothing happened on the WAN or AD.
Our support guys are saying that the Windows Event logs and the SQL logs don't tell them enough. I think someone can't be bothered.

tkizer
Almighty SQL Goddess

38200 Posts

Posted - 2007-02-06 : 18:27:49

What is meant by the server hanging though? Did the servers crash? Was the CPU high? Did they blue screen? ...

Tara Kizer

keat1963
Starting Member

5 Posts

Posted - 2007-02-07 : 04:52:26

I'm not sure what happened to them, as they were in different parts of the country. The people who rebooted them will have just buttoned them (non techies).
I could ping all 5, but couldnt RDP on to them, couldn't PC-Anywhere on to them, Couldn't manage the services remotely, Even tried Sysinternals PS-Shutdown, but this wouldn't work.
My guess they went 100% CPU

Kristen
Test

22859 Posts

Posted - 2007-02-07 : 05:11:39

"will have just buttoned them ..."

Using their foreheads?!

keat1963
Starting Member

5 Posts

Posted - 2007-02-07 : 05:35:46

These things are in a suite, hanging off a KVM, Its far too technical when you have to explain how to switch between servers. "Press Shift twice", "Where is the Shift button".. You know the convesation.

tkizer
Almighty SQL Goddess

38200 Posts

Posted - 2007-02-07 : 11:29:31

Were you able to connect to them prior to them rebooting them via SQL Profiler, Enterprise Manager, Query Analyzer, and Performance Monitor?

It's practically impossible to help out if we don't know what the symptoms were. Hopefully you were at least able to connect to SQL Profiler and Performance Monitor to grab the longest running queries, the process that was using the most CPU, memory utilization, etc...

Tara Kizer

Subscribe to SQLTeam.com

SQLTeam.com Articles via RSS

SQLTeam.com Weblog via RSS

- Advertisement -

Resources