none
Getting error 1222: "Lock request time out period exceeded" even though LOCK_TIMEOUT is -1

    Question

  • I have a batch job that takes a couple of hours to run. During that time we are seeing a very large number of errors for 1222: "Lock request time out period exceeded" being logged as EXCEPTION by Service Broker event notifications. The LOCK_TIMEOUT is configured as -1, so I am not clear why this would be happening. Any suggestions would be appreciated. SQL Server 2012 SP1.

    Thanks,

    Ron Rice


    Ron Rice

    Tuesday, June 16, 2015 4:41 PM

Answers

  • One other note about event notification for exceptions: I know that at least one of the other types of message it captures is also bogus. It constantly records messages saying that temporary tables are not valid objects. For example, after executing sp_help I get a series of "errors" saying "Invalid object name '#spcnsttab'" and "Invalid object name '#spindtab'". That is clearly wrong. It seems like it is picking up some kind of low-level information that would not otherwise see the light of day because it is not really an error condition. I strongly suspect that is the case with these timeout messages as well.

    This I can explain. You can see this also when you run Profiler and capture the Error:Exception and Error:User Message events, as well as the BatchStarting/Completed and StmtStarting/Completed events.

    If you run this:

    CREATE PROCEDURE bad_sp
    PRINT 'Hoppla!'
    --CREATE TABLE #temp(a int NOT NULL)
    SELECT * FROM #temp
    go
    EXEC bad_sp

    You will see something like this:

    BatchStarting CREATE PROCEDURE ...
    StmtStarting CREATE PROCEDURE ...
    Error:Exception  Invalid Object Name '#temp'
    StmtCompleted CREATE PROCEDURE ...
    BatchCompleted CREATE PROCEDURE ...
    BatchStarting EXEC bad_sp
    StmtStartting EXEC bad_sp
    Error:Exception  Invalid Object Name
    StmtStarting Print 'Hoppla!'
    Error:Exception  Invalid Object Name '#temp'
    Error:UserMessage Invalid Object Name '#temp'
    BatchCompleted EXEC bad_sp

    That is, you get one exception event when the procedure is created, but the error is suppressed in the spirit of deferred name resolution.

    When you invoke the procedure, the procedure is compiled and put into cache, the exception occurs anew, but is again suppresed. Only first when the statement is reached you get both the Exception event and the User Message event.

    If you try this again, but uncomment the CREATE TABLE statement, you again get two Error:Exception events, but this time you don't get the third and the User Message event.

    So that is how it works. Pretty? Well, deferred name resolution is one of the biggest misfeatures in SQL Server in my opinion...


    Erland Sommarskog, SQL Server MVP, esquel@sommarskog.se
    Wednesday, June 24, 2015 9:33 PM
  • No, there is no other problem that I know of, except that it fills up our log table faster than we can delete the old data from it. This problem only occurs when the batch job is running, so there must be some connection between the two. I am going to guess that it is Service Broker itself, based on this: https://support.microsoft.com/en-us/kb/2837910. I will try installing SP2. :)

    Thanks for pointing me in the right direction on this.

    Ron


    Ron Rice

    Tuesday, June 16, 2015 7:43 PM

All replies

  • The lock request timeout says that some SQL Server query was trying to take lock on particular resource but was not able to take because it was already locked. You can try running this again or at different time what does batch job does actually ?

    Please mark this reply as answer if it solved your issue or vote as helpful if it helped so that other forum members can benefit from it

    My Technet Wiki Article

    MVP

    Tuesday, June 16, 2015 4:52 PM
    Moderator
  • LOCK_TIMEOUT is a session setting.  So there may be some other sessions (possibly background processes) using a different lock timeout. 

    What's the entire error message?  Are you seeing some sort of problem?

    David


    David http://blogs.msdn.com/b/dbrowne/

    Tuesday, June 16, 2015 5:11 PM
  • The job that is running when these occur does not set LOCK_TIMEOUT locally, to the best of my knowledge. This is the message (redacted) that is generated by Service Broker:
    <EVENT_INSTANCE>
      <EventType>EXCEPTION</EventType>
      <PostTime>2015-06-16T00:28:52.610</PostTime>
      <SPID>40</SPID>
      <TextData>Lock request time out period exceeded.</TextData>
      <DatabaseID>8</DatabaseID>
      <TransactionID />
      <NTUserName />
      <NTDomainName />
      <HostName />
      <ClientProcessID />
      <ApplicationName />
      <LoginName>sa</LoginName>
      <StartTime>2015-06-16T00:28:52.317</StartTime>
      <Severity>16</Severity>
      <ServerName>myserver</ServerName>
      <State>18</State>
      <Error>1222</Error>
      <DatabaseName>mydb</DatabaseName>
      <LoginSid>xxx</LoginSid>
      <RequestID>0</RequestID>
      <XactSequence>0</XactSequence>
      <EventSequence>12345</EventSequence>
      <IsSystem>1</IsSystem>
      <SessionLoginName />
      <GroupID>1</GroupID>
    </EVENT_INSTANCE>


    Ron Rice

    Tuesday, June 16, 2015 6:15 PM
  • <SPID>40</SPID>

    This means that this is occurring on a background system process.  Is there some problem other than seeing this error in the log?

    David


    David http://blogs.msdn.com/b/dbrowne/

    Tuesday, June 16, 2015 6:48 PM
  • No, there is no other problem that I know of, except that it fills up our log table faster than we can delete the old data from it. This problem only occurs when the batch job is running, so there must be some connection between the two. I am going to guess that it is Service Broker itself, based on this: https://support.microsoft.com/en-us/kb/2837910. I will try installing SP2. :)

    Thanks for pointing me in the right direction on this.

    Ron


    Ron Rice

    Tuesday, June 16, 2015 7:43 PM
  • <SPID>40</SPID>

    This means that this is occurring on a background system process. 

    It could be an activation procedure for a queue and which is blocked by this jb that r31416 is talking about.


    Erland Sommarskog, SQL Server MVP, esquel@sommarskog.se
    Tuesday, June 16, 2015 9:53 PM
  • Update on this: I did install SQL Server 2012 SP2 as suggested by the Microsoft Support article above. It did stop the timeout messages from being recorded in the SQL Server Log, as it said it would. However, it did not stop these messages from being recorded by an event notification for exception.

    The SPID's that get recorded with these messages are performing a command called "task manager". They are do not have a status of "background" but rather of "sleeping".

    I tried the "fan_in" option on the event notification, hoping that it might at least reduce the volume of these messages. No luck with that either.

    I am surprised no one else seems to have encountered this problem. It is occurring for us on six different servers. The volume is especially high during the time the batch job is running but there are also timeout messages recorded throughout the day. There is definitely no problem experienced by the processes that seem to generate or at least trigger these messages.

    I am afraid we may need to stop using event notifications for exceptions due to this problem, because it is filling up the table used to capture the messages at a faster rate than they can be deleted. Frustrating! :)


    Ron Rice

    Wednesday, June 24, 2015 2:52 PM
  • One other note about event notification for exceptions: I know that at least one of the other types of message it captures is also bogus. It constantly records messages saying that temporary tables are not valid objects. For example, after executing sp_help I get a series of "errors" saying "Invalid object name '#spcnsttab'" and "Invalid object name '#spindtab'". That is clearly wrong. It seems like it is picking up some kind of low-level information that would not otherwise see the light of day because it is not really an error condition. I strongly suspect that is the case with these timeout messages as well.

    Ron Rice

    Wednesday, June 24, 2015 4:08 PM
  • One other note about event notification for exceptions: I know that at least one of the other types of message it captures is also bogus. It constantly records messages saying that temporary tables are not valid objects. For example, after executing sp_help I get a series of "errors" saying "Invalid object name '#spcnsttab'" and "Invalid object name '#spindtab'". That is clearly wrong. It seems like it is picking up some kind of low-level information that would not otherwise see the light of day because it is not really an error condition. I strongly suspect that is the case with these timeout messages as well.

    This I can explain. You can see this also when you run Profiler and capture the Error:Exception and Error:User Message events, as well as the BatchStarting/Completed and StmtStarting/Completed events.

    If you run this:

    CREATE PROCEDURE bad_sp
    PRINT 'Hoppla!'
    --CREATE TABLE #temp(a int NOT NULL)
    SELECT * FROM #temp
    go
    EXEC bad_sp

    You will see something like this:

    BatchStarting CREATE PROCEDURE ...
    StmtStarting CREATE PROCEDURE ...
    Error:Exception  Invalid Object Name '#temp'
    StmtCompleted CREATE PROCEDURE ...
    BatchCompleted CREATE PROCEDURE ...
    BatchStarting EXEC bad_sp
    StmtStartting EXEC bad_sp
    Error:Exception  Invalid Object Name
    StmtStarting Print 'Hoppla!'
    Error:Exception  Invalid Object Name '#temp'
    Error:UserMessage Invalid Object Name '#temp'
    BatchCompleted EXEC bad_sp

    That is, you get one exception event when the procedure is created, but the error is suppressed in the spirit of deferred name resolution.

    When you invoke the procedure, the procedure is compiled and put into cache, the exception occurs anew, but is again suppresed. Only first when the statement is reached you get both the Exception event and the User Message event.

    If you try this again, but uncomment the CREATE TABLE statement, you again get two Error:Exception events, but this time you don't get the third and the User Message event.

    So that is how it works. Pretty? Well, deferred name resolution is one of the biggest misfeatures in SQL Server in my opinion...


    Erland Sommarskog, SQL Server MVP, esquel@sommarskog.se
    Wednesday, June 24, 2015 9:33 PM
  • Thank you for that explanation, Erland. I suspect something similar is occurring in the case of the timeout messages.

    Ron


    Ron Rice

    Thursday, June 25, 2015 12:57 PM
  • I think I may have solved this mystery, and I think it does in fact have to do with an exception that happens at a low level and is suppressed.

    I was looking at the sys.dm_os_performance_counters view the other day and noticed that the counter for SQLServer:Locks had very large numbers for "Lock Timeouts/sec". I experimented a little and found that the value of this counter is incremented every time there a process is *blocked*. It doesn't matter how short the time of the blocking is, the counter is always incremented.

    I am pretty sure that this is what we were seeing in the event notifications for exceptions: an "exception" for a lock timeout is logged every time a spid is blocked.

    This behavior reduces the usefulness of the lock timeout counter, since there is no way to distinguish timeouts that impact a user from those that don't.


    Ron Rice

    Wednesday, July 29, 2015 7:42 PM
  • Hi Ron,

    Please check below link, i hope it will help to you...

    last month i have faced same error and  followed the below to resolve the issue.

    http://www.sqlserver-query.com/sql-server-lock-request-time-out-period-exceeded-error/

    Thanks,

    Tirumala

    Thursday, July 30, 2015 7:34 AM
  • Hi Ron. 

    I'm facing this same problem right now with SQL Server 2012 SP3 so I was wondering if you founded some kind of solution. 

    I'm very interested in using Event Notifications in order to track exceptions in a lot of SQL Server intances and obviously, this issue prevents me of using it. 

    Thanks in advance. 

    Jorge

     

    Tuesday, August 08, 2017 11:14 AM