Gathering Stored Procedure execution time in real time?

  • Is there a way to keep track in real time on how long a stored procedure is running for? So what I want to do is fire off a trace in a stored procedure if that stored procedure is running for over like 5 minutes. Is this possible? Appreciate the help.

  • If a stored procedure is a single query, then the basic answer is no. However, that doesn't mean that what the query accesses might not be able to create a condition that some kind of trace might be able to detect, although I don't know exactly how that could occur. However, if the proc is composed of multiple queries, and especially if each takes a significant fraction of the total execution time, then you could find a particular spot between queries to insert code to kick it off. The only other decent alternative would be the idea of having a DBA readily available to start a trace "on command", so to speak.

    Steve (aka sgmunson) 🙂 🙂 🙂
    Rent Servers for Income (picks and shovels strategy)

  • You could capture that amount of time that a stored procedure executes using Extended Events. "

    "I cant stress enough the importance of switching from a sequential files mindset to set-based thinking. After you make the switch, you can spend your time tuning and optimizing your queries instead of maintaining lengthy, poor-performing code."

    -- Itzik Ben-Gan 2001

  • Alan, your saying for the total time it took to execute and not in real time correct?

  • JP10 (6/11/2015)


    Alan, your saying for the total time it took to execute and not in real time correct?

    I don't know if I understand your question so I'm not sure if this will help or not. I don't know how I would turn this on if a stored proc was running for 5 minutes but you could just kick off an Extended Events session running and collect all the metrics for that proc until you turn the EE session off.

    Below is some sample code that will create a stored proc and executes it five times. I kick off an Extended Events session before it runs and turn it off after (you would just leave it running).

    USE tempdb

    GO

    SET NOCOUNT ON;

    -- (1) create a getnums function

    IF OBJECT_ID('dbo.GetNums') IS NOT NULL DROP FUNCTION dbo.GetNums;

    GO

    CREATE FUNCTION dbo.GetNums(@rows int)

    RETURNS TABLE WITH SCHEMABINDING AS RETURN

    WITH

    L1(N) AS (SELECT 1 FROM (VALUES (1),(1),(1),(1),(1),(1),(1),(1),(1)) t(N)),

    L3(N) AS (SELECT 1 FROM L1 a, L1 b, L1 c),

    Nums AS (SELECT N = ROW_NUMBER() OVER (ORDER BY (SELECT NULL)) FROM L3 a, L3 b, L3 c)

    SELECT TOP(@rows) N

    FROM Nums;

    GO

    -- (2) Create a sample proc

    IF OBJECT_ID('tempdb..someproc') IS NOT NULL DROP PROC someproc;

    GO

    CREATE PROC someproc AS SELECT x = newid() INTO #x10M FROM dbo.GetNums(10000000);

    GO

    -- (3) Create and start an EE session

    CREATE EVENT SESSION [queryperf] ON SERVER

    ADD EVENT sqlserver.sql_statement_completed

    ADD TARGET package0.event_file(SET filename=N'S:\sprocExes.xel',max_file_size=(20),max_rollover_files=(10))

    WITH

    (

    MAX_MEMORY=4096 KB, EVENT_RETENTION_MODE=ALLOW_MULTIPLE_EVENT_LOSS,

    MAX_DISPATCH_LATENCY=120 SECONDS, MAX_EVENT_SIZE=0 KB,

    MEMORY_PARTITION_MODE=NONE, TRACK_CAUSALITY=OFF, STARTUP_STATE=ON

    );

    -- (4) Start EE and kick of sproc test

    ALTER EVENT SESSION [queryperf] ON SERVER STATE = START;

    GO

    -- run it 20 times

    EXEC someproc

    GO 5

    -- (4) Drop the session

    DROP EVENT SESSION [queryperf] ON SERVER;

    The above code will create an Extended Events file that you can query as shown below. Timestamp would tell you when it ran, [duration(sec)] will tell you how long the function ran (in seconds).

    -- (5) Get results

    SELECT [duration(sec)],[cpu_time(sec)],q.physical_reads,q.logical_reads,q.writes,/*event_data_XML,*/statement,timestamp

    FROM

    (

    SELECT

    [duration(sec)]=e.event_data_XML.value('(//data[@name="duration"]/value/text())[1]','int')/1000000.,

    [cpu_time(sec)]=e.event_data_XML.value('(//data[@name="cpu_time"]/value/text())[1]','int')/1000000.,

    physical_reads=e.event_data_XML.value('(//data[@name="physical_reads"]/value/text())[1]','int'),

    logical_reads=e.event_data_XML.value('(//data[@name="logical_reads"]/value/text())[1]','int'),

    writes=e.event_data_XML.value('(//data[@name="writes"]/value/text())[1]','int'),

    statement=e.event_data_XML.value('(//data[@name="statement"]/value/text())[1]','nvarchar(50)'),

    TIMESTAMP=e.event_data_XML.value('(//@timestamp)[1]','datetime2(7)'), *

    FROM

    (

    SELECT CAST(event_data AS XML) AS event_data_XML

    FROM sys.fn_xe_file_target_read_file('S:\sprocExes*.xel', NULL, NULL, NULL)

    )e

    )q

    WHERE q.[statement] LIKE 'EXEC someproc%' --Filters out all the detritus that we're not interested in!

    ORDER BY q.[timestamp] ASC;

    "I cant stress enough the importance of switching from a sequential files mindset to set-based thinking. After you make the switch, you can spend your time tuning and optimizing your queries instead of maintaining lengthy, poor-performing code."

    -- Itzik Ben-Gan 2001

  • Yes, it is possible, but I have never done it. You'll need to use the built-in Dynamic Management Views (DMV), specifically sys.dm_exec_requests which gives you information about currently running requests. You can then follow the information in http://www.toadworld.com/platforms/sql-server/w/wiki/9827.running-traces-with-tsql.aspx to create and run a trace. You can even return the session_id from the DMV for use in filtering the trace.

    SELECT DATEDIFF(MINUTE, r.start_time, SYSDATETIME()) AS running_for,

    r.session_id,

    st.text

    FROM sys.dm_exec_requests AS r

    CROSS APPLY sys.dm_exec_sql_text(r.sql_handle) AS st

    WHERE r.database_id = DB_ID()

    AND st.text LIKE '%your_procedure_name%'

    Drew

    J. Drew Allen
    Business Intelligence Analyst
    Philadelphia, PA

Viewing 6 posts - 1 through 5 (of 5 total)

You must be logged in to reply to this topic. Login to reply