4

I have a stored proc which is called every 2.5 seconds by a program, 24-7. This proc normally runs under the 10 milliseconds. A few times a day (3 -5 times) it takes around 42953 milliseconds to run (always between 42950 and 42959 milliseconds).

How can I find or profile the reason why it takes so long?

Update: Sql server version 2008 R2

Procedure:

select 
    [view_EventsToRaise].EventId,
    [view_EventsToRaise].EventStatus,
    [view_EventsToRaise].Tag,
    [view_EventsToRaise].SessieGebruikerId,
    Postbus.Persoon_Id_afz      as PersoonIdAfz,
    Postbus.Persoon_Id_adr      as PersoonIdAdr,
    Postbus.Persoon_Id_derde    as PersoonIdDerde,
    Postbus.Locatie_Id          as LocatieId,
    Postbus.Artikel_Id          as ArtikelId,
    Postbus.Onderwerp_Id        as OnderwerpId,
    Postbus.Bedrijf_Id_afz      as BedrijfIdAfz,
    Postbus.Bedrijf_Id_adr      as BedrijfIdAdr,
    Postbus.Bedrijf_Id_derde    as BedrijfIdDerde,
    Postbus.Document_Id         as DocumentId,      
    Postbus.Document            as Document,        
    DataKenmerk.Code            as PostbusDataCode,
    PostbusData.Inhoud          as PostbusDataInhoud,
    SimObj.Id                   as SimObjId,
    Eventsoort.Code             as Eventsoort
from 
    [view_EventsToRaise]
    left outer join Postbus
        left outer join PostbusData
            inner join DataKenmerk
            on PostbusData.DataKenmerk_id = DataKenmerk.id
        on PostbusData.Postbus_Id = Postbus.id
    on Postbus.Id = [view_EventsToRaise].PostbusId
    left outer join SimObjEvent                         
        inner join eventsoort
        on eventsoort.id = SimObjEvent.eventsoort_id
    on [view_EventsToRaise].SimObjEventId = SimObjEvent.Id
    left outer join SimObj
    on SimObj.Id = SimObjEvent.SimObj_Id
order by
    [view_EventsToRaise].Tijd,
    [view_EventsToRaise].EventId

Update 29-9-2014: When the above described situation occurs, looking to the profiler, the following got mine attention: When the RPC:Completed event is registered, the the starttime is the current system time at the log moment, but the endtime is a value in the future (current system time plus the duration, approx. 43 sec in the future).

How is the value of the endtime column determined? Is this a prediction?

  • 1
    Can you post the stored procedure up? We may be able to find the cause there. Also, if it is being hit every 2-3 seconds, the likelyhood is probably a lock on a table – twoleggedhorse Sep 19 '14 at 7:43
  • 1
    What version of SQL server? – twoleggedhorse Sep 19 '14 at 7:45
  • 1
    I have never seen joins written like that before! – Mark Sinkinson Sep 19 '14 at 12:18
  • Execution plan? You can pull latest deadlocks from system_health session. – Shawn Melton Sep 19 '14 at 14:11
5

This is probably caused by a blocking process. 3-5 times a day this is blocked by some update or other write that takes ~40 seconds. Your SELECT blocks until it can continue. If this is indeed the case, the problem can be identified using the Blocked Process Report Event. You will have to enable this event and set the threshold to ~35 seconds. See blocked process threshold Server Configuration Option. Obviously the event may fire for other queries too, but arguable those issues also needs to be addressed.

A simple workaround for blocking is using a row versioned isolation level. Read Understanding Row Versioning-Based Isolation Levels.

Otherwise, you will need to investigate this as a performance problem. Read How to analyse SQL Server performance.

  • I used this artikel for finding the problem. I configured the threshold at 35 sec and using the profiler I started a new trace (blank template) with only the Blocked process report. Unfortunately nothing was logged. Any other suggestions? – pexxxy Sep 23 '14 at 8:05

Your Answer

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

Not the answer you're looking for? Browse other questions tagged or ask your own question.