T-SQL – Page 6 – Reporting Services

August 2, 2019March 21, 2020

Extended events query plan

I need to cover few scenarios connected to SQL statements or procedures and their Execution plans and IO statistics:

To monitor stored procedures performance running on server
To get execution plan from procedures not easily accessible from management studio
- Procedures called from service broker applications
- Huge nested level of SQL statement
Compare batches in testing labs

I decided to use Extended Events as lightweight solution for such a scenarios.

I found following tree evens very usefull to get requested data.

sqlserver.query_post_execution_showplan
- to get execution plan of running query
sqlserver.sql_statement_completed
- to get IO informations regarding executed query
sqlserver.sp_statement_completed
- to get IO informations regarding executed stored procedure¨

Bellow you can find simple script creating above mentioned events with resctriction to concreted session and database.

CREATE EVENT SESSION Test ON SERVER
ADD EVENT sqlserver.query_post_execution_showplan -- ,
                         (
                         ACTION (sqlserver.database_name,
                                 sqlserver.plan_handle,
                                 sqlserver.query_plan_hash,
                                 sqlserver.session_id,
                                 sqlserver.sql_text,
                                 sqlserver.username)
                            WHERE
                                         sqlserver.session_id=58
                                         AND sqlserver.database_id = 8
                          )
,
ADD EVENT sqlserver.sql_statement_completed -- ,
                         (
                         ACTION (sqlserver.database_name,
                                 sqlserver.plan_handle,
                                 sqlserver.query_plan_hash,
                                 sqlserver.session_id,
                                 sqlserver.sql_text,
                                 sqlserver.username)
                            WHERE
                                         sqlserver.session_id=58
                                         AND sqlserver.database_id = 8
                          ),
ADD EVENT sqlserver.sp_statement_completed -- ,
                    (
                    ACTION (sqlserver.database_name,
                            sqlserver.plan_handle,
                            sqlserver.query_plan_hash,
                            sqlserver.session_id,
                            sqlserver.sql_text,
                            sqlserver.username)
                    WHERE
                                     sqlserver.session_id=58
                                     AND sqlserver.database_id = 8
                     )
ADD TARGET package0.ring_buffer (SET max_memory = 4096  ) WITH (max_dispatch_latency = 1 seconds)

Let’s start the session.

ALTER EVENT SESSION Test ON SERVER STATE = START

Here is an example to get data from the session.

SELECT CAST(LocksAcquired.TargetXml AS XML) AS XMLData
  INTO #LogData
  FROM (SELECT CAST(t.target_data AS XML) AS TargetXml
          FROM sys.dm_xe_session_targets AS t
          JOIN sys.dm_xe_sessions AS s ON s.address= t.event_session_address
         WHERE s.name= 'Test'   ) AS LocksAcquired;
 SELECT T.XMLData.value('(action[@name="sql_text"])[1]','varchar(1000)' ) AS [SqlText],
        T.XMLData.value('(@timestamp)[1]',    'datetime' )                AS [OccurredDtTm],
        T.XMLData.value('(data[@name="message"])[1]','varchar(60)')       AS [Message]
        ,T.XMLData.value('(action[@name="username"])[1]','SYSNAME')       AS [UserName]
        ,T.XMLData.value('(action[@name="session_id"])[1]','INT')         AS [SessionID]
        ,T.XMLData.value('(action[@name="query_plan_hash"])[1]','DECIMAL(38,0)') AS [QueryPLanHash]
        ,T.XMLData.value('(action[@name="plan_handle"])[1]','VARBINARY(MAX)') AS [QueryPLanHandle]
        ,T.XMLData.value('(data[@name="cpu_time"])[1]','INT') AS [CPUTime] 
        ,T.XMLData.value('(data[@name="duration"])[1]','BIGINT')  AS [Duration]
        ,NULL [PhysicalReads]
        ,NULL                                 [LogicalReads]
        ,NULL                                 [Writes]
        ,NULL                                 [RowCount]
       ,T.XMLData.value('(data[@name="object_type"])[1]','SYSNAME') AS [ObjectType]
       ,T.XMLData.value('(data[@name="object_id"])[1]','INT') AS [ObjectID]
       ,U.XMLData.query('.')                                                    AS [XML]
       ,T.XMLData.value('(data[@name="estimated_rows"])[1]','BIGINT') AS [EstimatedRow]
      ,T.XMLData.value('(data[@name="estimated_cost"])[1]','BIGINT')  AS [EstimatedCost]
       , 'QueryPlan' AS [type]
         INTO #finalset
         FROM #LogData x 
  CROSS APPLY x.XMLData.nodes('/RingBufferTarget/event[@name="query_post_execution_showplan"]') AS T(XMLData)
  CROSS APPLY t.XMLData.nodes('data[@name="showplan_xml"]/value/*') AS U(XMLData);
    SELECT  T.XMLData.value('(action[@name="sql_text"])[1]','varchar(1000)') AS [SqlText],
            T.XMLData.value('(@timestamp)[1]',    'datetime')                AS [OccurredDtTm],
            T.XMLData.value('(data[@name="message"])[1]','varchar(60)')      AS [Message]
           ,T.XMLData.value('(action[@name="username"])[1]','SYSNAME')       AS [UserName]
           ,T.XMLData.value('(action[@name="session_id"])[1]','INT') AS [SessionID]
           ,T.XMLData.value('(action[@name="query_plan_hash"])[1]', 'DECIMAL(38,0)' ) AS [QueryPLanHash]
           ,T.XMLData.value('(action[@name="plan_handle"])[1]', 'VARBINARY(MAX)' )    AS [QueryPLanHandle]
           ,T.XMLData.value('(data[@name="cpu_time"])[1]', 'INT')                     AS [CPUTime]
           ,T.XMLData.value('(data[@name="duration"])[1]','BIGINT')                   AS [Duration]
           ,T.XMLData.value('(data[@name="physical_reads"])[1]','BIGINT')                [PhysicalReads]
           ,T.XMLData.value('(data[@name="logical_reads"])[1]','BIGINT')                 [LogicalReads]
           ,T.XMLData.value('(data[@name="writes"])[1]', 'BIGINT' )                      [Writes]
           ,T.XMLData.value('(data[@name="row_count"])[1]','BIGINT')                     [RowCount]
           ,T.XMLData.value('(data[@name="object_type"])[1]', 'SYSNAME' )              AS [ObjectType]
           ,T.XMLData.value('(data[@name="object_id"])[1]',  'INT' )                   AS [ObjectID]
                -- ,U.XMLData.query('.')                                                AS [XML]
            ,CAST (NULL AS XML) AS [XML]
            ,T.XMLData.value('(data[@name="estimated_rows"])[1]','BIGINT')              AS [EstimatedRow]
           ,T.XMLData.value('(data[@name="estimated_cost"])[1]','BIGINT')               AS [EstimatedCost]
           , 'IOSql' AS [type]
         INTO #finalsetII
         FROM #LogData x
        CROSS APPLY x.XMLData.nodes('/RingBufferTarget/event[@name="sql_statement_completed"]') AS T(XMLData)

SELECT  T.XMLData.value('(action[@name="sql_text"])[1]','varchar(1000)') AS [SqlText],
        T.XMLData.value('(@timestamp)[1]',    'datetime' )               AS [OccurredDtTm],
        T.XMLData.value('(data[@name="message"])[1]','varchar(60)' )     AS [Message]
        ,T.XMLData.value('(action[@name="username"])[1]', 'SYSNAME')     AS [UserName]
        ,T.XMLData.value('(action[@name="session_id"])[1]','INT' )       AS [SessionID]
        ,T.XMLData.value('(action[@name="query_plan_hash"])[1]','DECIMAL(38,0)') AS [QueryPLanHash]
        ,T.XMLData.value('(action[@name="plan_handle"])[1]','VARBINARY(MAX)' ) AS [QueryPLanHandle]
        ,T.XMLData.value('(data[@name="cpu_time"])[1]','INT') AS [CPUTime]
        ,T.XMLData.value('(data[@name="duration"])[1]','BIGINT') AS [Duration]
        ,T.XMLData.value('(data[@name="physical_reads"])[1]', 'BIGINT' ) [PhysicalReads]
        ,T.XMLData.value('(data[@name="logical_reads"])[1]', 'BIGINT' )  [LogicalReads]
       ,T.XMLData.value('(data[@name="writes"])[1]', 'BIGINT' )          [Writes]
       ,T.XMLData.value('(data[@name="row_count"])[1]', 'BIGINT' )       [RowCount]
         ,T.XMLData.value('(data[@name="object_type"])[1]','SYSNAME') AS [ObjectType]
       ,T.XMLData.value('(data[@name="object_id"])[1]', 'INT' ) AS [ObjectID]
            -- ,U.XMLData.query('.')                                                    AS [XML]
            , CAST(NULL AS XML) AS [XML]
        ,T.XMLData.value('(data[@name="estimated_rows"])[1]','BIGINT')AS [EstimatedRow]
         ,T.XMLData.value('(data[@name="estimated_cost"])[1]', 'BIGINT' ) AS [EstimatedCost]
       , 'IOProcedure' AS [type]
         INTO #finalsetIII
            FROM  #LogData x
            CROSS APPLY x.XMLData.nodes('/RingBufferTarget/event[@name="sp_statement_completed"]') AS T(XMLData)
            --CROSS APPLY t.XMLData.nodes('data[@name="showplan_xml"]/value/*') AS U(XMLData)
            ;
SELECT * FROM #finalset UNION ALL SELECT * FROM #finalsetII UNION ALL SELECT * FROM #finalsetIII

Do not forget to clear your session

IF EXISTS (SELECT * FROM sys.server_event_sessions WHERE name = 'Test')
BEGIN
DROP EVENT SESSION Test ON SERVER;
END

In next post I will publish SQL routines in which above mentioned script will be encapsulated.

May 26, 2019May 26, 2019

Extended Events – usage for logging

Since logging is fundamental functionality for many SQL applications, I still ask myself what the best approach is to make SQL log for your application. In lots of my solutions I got with SQL log table approach. But there could be other ways how to implement SQL logging mechanisms. I decided to use Extended Events functionality to implement such a solution. This is powerful feature of SQL server. There are many examples on internet web sites where you can find this functionality was implemented mainly for maintenance purposes or SQL server counters monitoring. But let’s try to find another usage for this feature.

Problem

Let’s develop error log solution for simple insert query. For our solution we will use extended events.

You can create extended events in SQL Management Studio -> Management->Extended Events section as you can see on picture bellow, in this post I will use T-SQL scripts.

In short:

Create testing database
Create log table
Create extended event session
Start extended event session
Simulate event which trigger log message
Get data from extended event
Put data into log table

At first, we prepare database with log table.

CREATE DATABASE LogTest
GO
USE LogTest
GO

IF OBJECT_ID('dbo.LogData') IS  NULL
CREATE TABLE dbo.LogData 
(sql_text NVARCHAR(1000),[log_datetime] DATETIME,[message] NVARCHAR(100))

The next step is to create extended event session. I named it LogTestSession. Since I would like to monitor error messages I will add object sqlserver.error_reported. It handles events connected to error messages triggered on the server. In Action section there are listed attributes we want to get from extended events. Where clause contains filters to our database (we get ID of our database) and then put it to this predicate (Because we would like to test it only on our database) Error number = 50000 means that we would like to check only user messages. As you can see there are many ways how to configure behaviour of extended events. There is not necessary to use filter and you can monitor all databases on the server and error messages. As target we use Ring buffer, it means that data will be written to memory. There is possibility to redirect extended event output to other destinations. I will not describe all possibilities in this post, more info can be found here: https://bit.ly/2JEVDcV.

The last attribute, I used in this solution is MAX_DISPATCH_LATENCY = { seconds SECONDS | INFINITE } and here is definition directly from Microsoft sites https://bit.ly/2HCIHSD. Specifies the amount of time that events will be buffered in memory before being dispatched to event session targets. By default, this value is set to 30 seconds.

Bellow is T-SQL batch for creating extended event session.

CREATE EVENT SESSION LogTestSession ON SERVER 
    ADD EVENT sqlserver.error_reported  -- ,
      (
      ACTION (sqlserver.sql_text, sqlserver.tsql_stack, sqlserver.database_id,sqlserver.username)
       WHERE sqlserver.database_id = 33  AND [error_number]=50000 /*Filter error no or db number*/
     )   
    ADD TARGET package0.ring_buffer    
        (SET max_memory = 4096 
    ) 
WITH (max_dispatch_latency = 1 seconds)

In next step we start extended events. Since that time, we can test our mechanism.

ALTER EVENT SESSION LogTestSession ON SERVER
STATE = START

Let’s raise user message.

DECLARE @Message VARCHAR(100) = 'Hello word message '+ CONVERT(VARCHAR(20),GETDATE(),20)
RAISERROR(  @Message,1,1);
SELECT CONVERT(VARCHAR(20),GETDATE(),20)

DECLARE @Message VARCHAR(100) = 'Log message '+ CONVERT(VARCHAR(20),GETDATE(),20)
RAISERROR(  @Message,1,1);
SELECT CONVERT(VARCHAR(20),GETDATE(),20)

Now we get data from extended events. There are few useful catalos in SQL server. In the script bellow we get data from tables containing user messages and stage them into temporary table like XML.

IF OBJECT_ID('tempdb.dbo.#LogData') IS NOT NULL
 DROP TABLE #LogData;

SELECT
       CAST(LocksAcquired.TargetXml AS XML)  AS XMLData
   INTO
       #LogData
   FROM
       (
       SELECT
               CAST(t.target_data AS XML)  AS TargetXml 
           FROM
                    sys.dm_xe_session_targets  AS t
               JOIN sys.dm_xe_sessions         AS s

                   ON s.address = t.event_session_address
           WHERE
            
               s.name        = 'LogTestSession'
       )
           AS LocksAcquired;

Now let’s parse our data to our LOG table. In next step we can create one procedure from these two queries. IT would fit better in scenarios of next posts.

 
INSERT INTO  dbo.LogData  	(sql_text ,[log_datetime] ,[message]  )
SELECT
     T.XMLData.value('(action[@name="sql_text"])[1]',
            'varchar(1000)'     )  AS [SqlText],
         T.XMLData.value('(@timestamp)[1]',
            'datetime'     )  AS [OccurredDtTm],
         T.XMLData.value('(data[@name="message"])[1]',
            'varchar(60)'     )  AS [Message]
    FROM
        #LogData
    CROSS APPLY XMLData.nodes('/RingBufferTarget/event[@name="error_reported"]')  AS T(XMLData);

Look to our log table and voila. Log messages are there.

SELECT * FROM dbo.LogData

Clean up our solution.

IF EXISTS (SELECT *
      FROM sys.server_event_sessions  
     WHERE name = 'LogTestSession')
BEGIN
    DROP EVENT SESSION LogTestSession
          ON SERVER;    
END

In this post I demonstrate how Extended Events could be used for logging purposes. Be aware that this approach does not come with real-time solution but with the asynchronous one. So, it cannot fit to every solution. On the other hand Extended Events are not in scope of transaction. Furthermore, here raise other questions which could be answered in other posts.

Handling error messages within transactions
What about extended events and their performance?
Ring buffer is still increasing, do we have solution to clean it up?
It could be interesting to compare this solution with classic approach within transaction scope
Whatever idea you get….

Stay tuned, stay strong

PS: if you would like to play, you can download the whole script here ext_events_log.

May 7, 2019May 24, 2019

Sorting direction in Sort operator

With my friend Mark, we recently discussed how the SQL server can deal with data retrieval, if the data are sorted by index in specified direction and query requests data in the opposite direction. As you can see below SQL server optimizer can deal with this request without the sort operator, which brings less costs in query execution. But it is very important that query meets with index design, otherwise sort operator occurs in query plan.

From samples bellow it is clear how it is important to pay attention to query with comparation to index design to avoid Sort operator

Let’s create a simple table with non-clustered index – ordered in ASC direction.

CREATE TABLE dbo.TestTable(id INT,sec_no INT)

CREATE NONCLUSTERED INDEX IX__TestTable__sec_No ON dbo.TestTable (sec_no ASC)

Let’s fill it with data.

INSERT INTO dbo.TestTable SELECT object_id,s.schema_id FROM sys.objects s

Now let’s look at execution plans of queries bellow. The first one ordered in ASC direction and the second one in DESC.

SELECT sec_no FROM dbo.TestTable ORDER BY sec_no ASC
SELECT sec_no FROM dbo.TestTable ORDER BY sec_no DESC

As you can see on both execution plans there are scans of non-clustered index and no sort operators.

If we look closer on Index Scan operators F4 we can see that optimizer used Scan Direction Forward on the first query execution plan and Backward in plan with DESC ordering.

Forward scan direction

Backward scan direction

Now if we remove non-clustered index we and run above mentioned queries we can see that Sort operator appears in our execution plans.

DROP INDEX IX__TestTable__sec_No ON dbo.TestTable

Execution plan - sort operator — *Picture 4 –* Execution plan – sort operator

Create non-clustered index again and change little bit its design. Now the data are ordered by ID column first.

CREATE  NONCLUSTERED INDEX IX__TestTable__sec_No ON dbo.TestTable (id,sec_no)

Now query optimizer uses index to retrieve data again but because index design does not correspond with our query (ordering of query does not fit to index), data has to be ordered in Sort operator. If we look by F4 on Index scan operator we can see that data are not returned in requested order – Ordered attribute is set to false.

We can get similar situation if we go back to our first example with right index design.

DROP INDEX IX__TestTable__sec_No ON dbo.TestTable
CREATE NONCLUSTERED INDEX IX__TestTable__sec_No ON dbo.TestTable(sec_no ASC)

But now we change our query little bit.

SELECT sec_no,id FROM dbo.TestTable ORDER BY sec_no ASC

From picture we can see that execution plan is similar like the one where we removed index. Here index exist on table but cannot be used to retrieve data because we changed our query the way index cannot be used and sort operator occurs again.

Lets create second table with index designed in right way as our first examples states. And compare both execution plans.

SELECT * INTO dbo.TestTableII FROM dbo.TestTable
CREATE NONCLUSTERED INDEX IX__TestTableII__sec_No ON dbo.TestTableII (sec_no)

*Picture 7 –* Execution plans comparation

From picture above, we can see that sort operator is a resource consuming operation from the perspective of query optimizer. In case you see it in the execution plan it is necessary to pay attention to it. If we want to avoid sorting in the execution plan, a suitable index design matching our query can help. However, this is not all yet. In the next posts I want to look at the Sort operator in more detail. And we will show that in some cases it also depends on the ordering direction of the index.