Results 1 to 11 of 11
  1. #1
    Join Date
    Jul 2011
    Posts
    22

    Question Unanswered: Need theories on cause of slow performance

    I'm having a hard time thinking of a way to start describing this issue. This issue is simply.... crazy.

    I'm working on an issue where our SQL server is responding at dramatically different speeds to the execution of a stored procedure. The stored procedure is executed from an ASP based web page. The web server (IIS 6) resides on a separate server than the SQL database (SQL 2008 R2). The stored procedure puts together a SQL Select statement, which includes joins across 13 tables, a WHERE EXISTS clause in addition to 6 LIKEs for filtering. The query is ran against 389k records, filtered down to as few as 4 records.

    At times the execution from the website takes only 3-5 seconds, which is great of course. Other times, which is frequent, and occurs during the day (when usage is high) or even late at night (when usage is low), the execution of the procedure can take 2 to 2.5 minutes. To be clear, it either takes a few seconds, or it takes at least 2 minutes, no middle ground here. When the issue is occurring from the website, it can be affecting a user for a few hours, before it suddenly goes away.

    We've ran Profiler against the stored procedure, and the difference in time is coming from the running of the SQL SELECT statement. During one of our tests we executed the command from the website, and when we found it was going to be running for the 2 minutes we executed the same exact stored procedure with the same parameters from the SQL server itself and from another Web server. Running the Stored Procedure from within Query Analyzer from those servers were completed in just a few seconds.

    Through all of our testing of running the stored procedure from within Query Analyzer, we have had some instances where the SP took 2-2.5 minutes to run.

    I'm just completely baffled as to why a stored procedure would vary so greatly in its running, especially when executed from different places at the same time.

  2. #2
    Join Date
    Aug 2004
    Location
    Dallas, Texas
    Posts
    831
    Blocks or Locking?

  3. #3
    Join Date
    Jul 2011
    Posts
    22
    We had considered Blocks and Locking, we aren't presented with any. Also the test where we ran the SP from two different servers while experiencing the issue, should exclude locks from being a factor, right? If a lock or block was causing the issue for the Web execution, than the other two servers should be encountering the same locks, since they were running the same stored procedure against the same data, with the same parameters.

  4. #4
    Join Date
    Jan 2003
    Location
    Massachusetts
    Posts
    5,800
    Provided Answers: 11
    When you get this problem again, query sys.dm_exec_requests for the wait_type (there is a description column the name of which escapes me, too). This should tell you more about what the problem is. It can range anywhere from blocking locks as corncrowe suggested to network I/O, which would be a symptom of the front end web server taking time stepping through the recordset.

    As a side note, when this happens in the profiler trace, is the reads column relatively static? Or does it shoot up along with the duration column?

  5. #5
    Join Date
    Jul 2011
    Posts
    22
    Thanks, I'll check the sys.dm_exec_requests. The recorded trace we conducted didn't capture the reads.

  6. #6
    Join Date
    Jan 2003
    Location
    Massachusetts
    Posts
    5,800
    Provided Answers: 11
    Having the reads on the trace is good, as that will point you toward whether this is a query plan issue, or an outside cause. If the reads are steady, the process is likely waiting on something else. If the reads are wildly different, the query plan is either changed, or otherwise not optimal for the parameters.

  7. #7
    Join Date
    Jul 2011
    Posts
    22
    I haven't been able to schedule a time to get a new trace to examine the Read counts, but I did get a look at the sys.dm_exec_requests table.

    It contained only my SELECT statement and a CHECKPOINT request.

    CheckPoint
    Start Time: 12/11/2011 8:11:24 AM
    Status: Background
    Wait type: Checkpoint Queue
    Wait Time: 16459
    cpu_time: 2722531
    total_elapsed_time: 2071232274
    Reads: 152
    Writes: 277196
    Logical Reads: 8181530

    The SP's Select
    Start Time: 6/1/2012 11:44:38 AM
    Status: Running
    blocking_session_id: 0
    wait_type: NULL
    wait_time: 0
    last_wait_type: SOS_SCHEDULER_YIELD
    cpu_time: 42360
    total_elapsed_time: 50843
    reads: 182
    writes: 85
    text_size: 2147483647

  8. #8
    Join Date
    Jan 2003
    Location
    Massachusetts
    Posts
    5,800
    Provided Answers: 11
    Is the second data sample from a run of the procedure during a minute long run? The process appears to not be waiting (wait_time = 0). Last_Wait_Type of SOS_Scheduler_Yield is a little more troubling, but only if it is a common occurrence. A one-off appearance by SOS_Scheduler_Yield once in a while is not a big deal. Repeated offenses can indicate larger problems.

  9. #9
    Join Date
    Jul 2011
    Posts
    22
    Yes, the data was grabbed while the issue was going on.

    I click a button on the Webpage, which is suppose to result in a set of data being filled into the page. If after I click refresh, the data isn't returned in 7 seconds, I know that it will take 2+ minutes to run. At about 7 seconds, I asked him to run the query. He do so shortly afterwards (10-30 seconds), and sent me the data.

    I found an article on MSDN where someone stated:

    "-- Check SQL Server Schedulers to see if they are waiting on CPU
    SELECT scheduler_id, current_tasks_count, runnable_tasks_count
    FROM sys.dm_os_schedulers
    WHERE scheduler_id < 255

    If you see the runnable tasks count above zero, that is cause for concern, and if you see it in double digits for any length of time, that is cause for extreme concern! "

    But if the SELECT wasn't waiting, that means it was running at the time of the Query. How frequently is sys.dm_exec_requests updated? Could it be waiting/not waiting/waiting/not waiting and I just happen to catch it on not waiting?

  10. #10
    Join Date
    Jan 2003
    Location
    Massachusetts
    Posts
    5,800
    Provided Answers: 11
    The Dynamic Management Views are not really tables, so they are not updated, per se. They are views of the system state, so they are real-time views.

    Ideally, you should run the query on sys.dm_exec_requests several times, so you can pick up on the trend of waiting (if any). This query may help a little more:

    Code:
    select s.host_name, s.login_name, r.wait_type, r.wait_type_desc, r.wait_time
    from sys.dm_exec_sessions s join
        sys.dm_exec_requests r on s.session_id = r.session_id
    You can use this to filter out the system processes (session_id < 50), and other applications.
    Last edited by MCrowley; 06-01-12 at 17:19. Reason: fixed [code ] tag

  11. #11
    Join Date
    Jul 2011
    Posts
    22
    ok, I'm planning on working with our hosting team to have them run the following script. =)

    Code:
    USE master
    DECLARE @iLP1 integer = 0
    
    CREATE TABLE #my_exec_requests (Timestamp datetime,session_id integer, start_time datetime, status nvarchar(30), command nvarchar(16), blocking_session_id integer, wait_type nvarchar(60),
    	wait_time integer, last_wait_type nvarchar(60), percent_complete real, cpu_time integer, total_elapsed_time integer, reads bigint, writes bigint, logical_reads bigint)
    
    WHILE 1 = 1
    BEGIN
    	WAITFOR DELAY '00:00:01'
    	SET @iLP1 = @iLP1 + 1
    	INSERT INTO #my_exec_requests 
    		SELECT GetDate() AS Timestamp,session_id,start_time,status,command,blocking_session_id,wait_type, wait_time,last_wait_type,percent_complete,cpu_time,total_elapsed_time,
    			reads,writes,logical_reads FROM sys.dm_exec_requests
    			WHERE Database_id = (SELECT database_id FROM sys.databases WHERE name = 'a2_Full_v22')
    	IF (@iLP1 = 10) BREAK
    END;
    SELECT * FROM #my_exec_requests
    DROP TABLE #my_exec_requests

Posting Permissions

  • You may not post new threads
  • You may not post replies
  • You may not post attachments
  • You may not edit your posts
  •