Reporting Services – Page 2 – SSRS, Reporting Services, SQL Server, Business Inteligence, Pentaho, T-SQL

July 3, 2020July 3, 2020

Insert exec

I was thinking about difference between INSERT and INSERT-EXEC statement from performance perspective since I saw lots of post announcing that you should avoid the second one mentioned (INSERT-EXEC). I decided to make few tests and look at this problematic from more angles to have better imagination about how these commands behave.

Testing scenarios:

Execution plan
IO stats and time stats
Extended events – statement completed event – row count
Transaction log behaviour
Transaction scope

Let’s create data structures for our tests:

First create tables for data insert

 CREATE TABLE dbo.InsertTable1 (id INT , [data] VARCHAR(255))

CREATE TABLE dbo.InsertTable2 (id INT , [data] VARCHAR(255))

Create two persistent temporary tables we will fill inside procedures we create:

CREATE TABLE dbo.TempTable1 (id INT , [data] VARCHAR(255))
CREATE TABLE dbo.TempTable2 (id INT, [data] VARCHAR(255))

Create objects we use to test:

The first one is stored procedure inserting data to InsertTable1 table – insert statement is part of stored procedure definition.

 CREATE PROCEDURE dbo.InsertData
   AS
INSERT INTO dbo.TempTable1
SELECT TOP 100000 a.object_id,REPLICATE('a',10 ) a
  FROM sys.objects a
  JOIN sys.objects b ON 1=1

 INSERT INTO dbo.TempTable2
 SELECT TOP 100000 a.object_id,REPLICATE('a',10 ) a
  FROM sys.objects a
  JOIN sys.objects b ON 1=1 

  INSERT INTO dbo.InsertTable1
  SELECT * FROM dbo.TempTable1
  UNION ALL
  SELECT * FROM dbo.TempTable2

The second one batch inserts data to InsertTable2 table – insert is realized by INSERT – EXEC statement.

EXEC ('INSERT INTO dbo.TempTable1 SELECT TOP 100000 a.object_id,REPLICATE('a',10 ) a 
FROM sys.objects a
JOIN sys.objects b ON 1=1

INSERT INTO dbo.TempTable2

SELECT TOP 100000  a.object_id,REPLICATE('a',10 ) a
FROM sys.objects a
JOIN sys.objects b ON 1=1

INSERT INTO dbo.InsertTable1
SELECT * FROM dbo.TempTable1
UNION ALL
SELECT * FROM dbo.TempTable2
')

Execute satements to fill the data:

exec  dbo.InsertData

INSERT EXEC ('…') /*put exec part above*/

Cleaning statements – call it before statements executions

TRUNCATE TABLE dbo.InsertTable1
TRUNCATE TABLE dbo.InsertTable2
TRUNCATE TABLE dbo.TempTable1
TRUNCATE TABLE dbo.TempTable2
DBCC FREEPROCCACHE
DBCC DROPCLEANBUFFERS
CHECKPOINT

Switch IO stats/processing time /actual execution plan in studio on. Or put following commands:

SET STATISTICS IO ON
SET SHOWPLAN_XML ON
SET STATISTICS TIME ON

Run following extended event with result to file.

CREATE EVENT SESSION GetRowsCount ON SERVER
ADD EVENT transaction_log 
( ACTION (sqlserver.sql_text, sqlserver.tsql_stack, sqlserver.database_id,sqlserver.username)
)
,
ADD EVENT sql_transaction 
( ACTION (sqlserver.sql_text, sqlserver.tsql_stack, sqlserver.database_id,sqlserver.username)
)
,
ADD EVENT sql_batch_completed 
( ACTION (sqlserver.sql_text, sqlserver.tsql_stack, sqlserver.database_id,sqlserver.username)
)
ADD TARGET package0.event_file(
SET filename='C:\outputfile\outputfile2.xel')
ALTER EVENT SESSION GetRowsCount ON SERVER STATE = START
ALTER EVENT SESSION GetRowsCount ON SERVER STATE = STOP

DROP EVENT SESSION GetRowsCount ON SERVER

Statement completed event – counters

Queries touched 400000 rows. 100000 for each from the two temptables and 200000 for final insert. But in case of insert we can see from batch completed event that query touched 600000 instead of 400000. Look at table below to check other counters.

SELECT CAST (EVENT_data AS XML),
       CAST (EVENT_data AS XML).value('(/event/data[@name="batch_text"])[1]','NVARCHAR(100)')     AS batch_text,
       CAST (EVENT_data AS XML).value('(/event/data[@name="duration"])[1]','NVARCHAR(100)')       AS duration,
       CAST (EVENT_data AS XML).value('(/event/data[@name="physical_reads"])[1]','NVARCHAR(100)') AS physical_reads,
       CAST (EVENT_data AS XML).value('(/event/data[@name="logical_reads"])[1]','NVARCHAR(100)') AS logical_reads,
     CASt
(EVENT_data AS
XML).value('(/event/data[@name="row_count"])[1]','NVARCHAR(100)')
AS row_count
FROM sys.fn_xe_file_target_read_file('C:\outputfile\outputfile1*.xel',
'C:\outputfile\outputfile1*.xem',
null,null) 
WHERE object_name = 'sql_batch_completed' ;

Counter	Insert	Insert – exec
Writes	1350	2194
Duration	9149345	11984022
Row count	400000	600000
Logical Reads	471973	962908
Physical Rads	662	1238

As you can see INSERT – EXEC statements consume more resources than normal insert on same set of data.

How it is possible than INSERT – EXEC generates additional 200000 row counts and finally touched 600000 rows and we made inserts with 400000 rows at total?

IO stats

Let’s check IO stats and execution plan to see the difference.

On picture above you can see that with INSERT-EXEC statement Worktable is created, means that insert-exec uses tempdb to store result- set before final insert. So, there we see that is an additional impact on tempdb and tempdb transaction log too.

Execution plan

The difference in execution plan is as follow. With INSERT – EXEC you get two statements. The one for the result-set of EXEC and the second one for inserting the data.

Transaction log

Another perspective is the transaction scope behaviour. Let’s get data from transaction_log event to temporary tables first.

SELECT     CAST (EVENT_data AS XML).value('(/event/data[@name="log_record_size"])[1]','INT') logsize,
CAST (EVENT_data AS XML).value('(/event/@timestamp)[1]','datetime2') timestamp,
CAST (EVENT_data AS XML).value('(/event/data[@name="transaction_start_time"])[1]','datetime2') date_time,
CAST (EVENT_data AS XML).value('(/event/data[@name="database_id"])[1]','INT')    database_id,
CAST (EVENT_data AS XML).value('(/event/data[@name="transaction_id"])[1]','INT')    transaction_id,
CAST (EVENT_data AS XML).value('(/event/action[@name="sql_text"])[1]','VARCHAR(1000)')    sql_text ,
CAST (EVENT_data AS XML).value('(/event/data[@name="operation"])[1]','VARCHAR(1000)')    operation
INTO #t1
FROM sys.fn_xe_file_target_read_file('C:\outputfile\outputfile1*.xel', 'C:\outputfile\outputfile1*.xem', null, null)
WHERE object_name = 'transaction_log' ;

SELECT CAST (EVENT_data AS XML).value('(/event/data[@name="log_record_size"])[1]','INT') logsize,
CAST (EVENT_data AS XML).value('(/event/@timestamp)[1]','datetime2') timestamp,
CAST (EVENT_data AS XML).value('(/event/data[@name="transaction_start_time"])[1]','datetime2') date_time,
CAST (EVENT_data AS XML).value('(/event/data[@name="database_id"])[1]','INT')    database_id,
CAST (EVENT_data AS XML).value('(/event/data[@name="transaction_id"])[1]','INT')    transaction_id,
CAST (EVENT_data AS XML).value('(/event/action[@name="sql_text"])[1]','VARCHAR(1000)')    sql_text ,
CAST (EVENT_data AS XML).value('(/event/data[@name="operation"])[1]','VARCHAR(1000)')    operation
INTO #t2
FROM sys.fn_xe_file_target_read_file('C:\outputfile\outputfile2*.xel', 'C:\outputfile\outputfile2*.xem', null, null)
WHERE object_name = 'transaction_log' 
;

Comparing following query outputs, we can see that insert-exec is scoped by one transaction against multiple individual transactions with normal insert.

SELECT COUNT(1) row_count,SUM(logsize) logsize,transaction_id,database_id FROM #t1 WHERE operation = '2LOP_INSERT_ROWS' GROUP BY transaction_id ,database_id

SELECT COUNT(1) row_count,SUM(logsize) logsize,transaction_id,database_id FROM #t2 WHERE operation = '2LOP_INSERT_ROWS' GROUP BY transaction_id, database_id

Transaction scope

In case of INSERT-EXEC statement it should rollback all insert statements inside of EXEC statement when error occurs, because INSERT – EXEC is scoped by one transaction. In case of individual transactions in stored procedure, each insert is taken like separate transaction, so rollbacked will be insert resulting with error. Let’s try:

Change type of inserting value to INT column in second insert.

INSERT INTO dbo.TempTable2
SELECT TOP 100000 REPLICATE('a',10 ) REPLICATE('a',10 ) a
FROM sys.objects a
JOIN sys.objects b ON 1=1

Run testing queries again. As you can see in case of INSERT-EXEC statement there are no rows inserted in tables since rollback appears.

Conclusion:

While INSERT-EXEC statement still takes place in some scenarios, you should be aware of mentioned circumstances.

NOTICE: I would like to check that transaction log of temporary database was filled with connection to the worktable created by INSERT-EXEC statement. But I cannot see any insert lop insert operation trough extended events in temporary database. I just see extent allocation

SELECT * FROM #t2 WHERE database_id = 2

If you have any idea whether worktables are logged and it is possible to trace them, please write a comment.

April 25, 2020April 25, 2020

CONTEXT_INFO to get from which procedure was trigger invoked

My colleague asked me once if there is a possibility to get info in trigger, from which stored procedure was trigger invoked. That time I didn’t have answer but now I had to resolve similar task and I found it very useful. We have a table which is getting data and their modifications from many places, since there are lots of mechanisms in the game. There is direct approach from applications, databases, SSIS packages etc. APP_NAME () function was not sufficient solution in my case since there were more ways to modify data from one application. My task was to log info regarding one concrete mechanism changing data in that table. I saw on internet few samples with CONTEXT_INFO solution and I found it very useful since the mechanism is implemented in database stored procedure. Solution was very easy then:
I put something similar to script bellow to stored procedure changing data on the table

DECLARE @context SYSNAME  = 'SOMEINFO'
DECLARE @contextBIN VARBINARY(128)  = CAST ( @context AS VARBINARY(128) )

In database trigger logging changes, I just put following code to get stored data in CONTEXT_INFO.

SELECT CAST (CONTEXT_INFO() AS SYSNAME) FROM inserted

SET CONTEXT_INFO establishes information with current session or connection, could be used for other scenarios, e. g. passing info between nested procedures, adding more details to batches called from applications, etc. See more info here: https://bit.ly/2Kzh1Pl.

Do you have another scenarios how to use CONTEXT_INFO ?

April 25, 2020April 25, 2020

Monitoring Deadlocks With Extended Events

With Extended events you can monitor and analyse occurence of deadlocks. Like traces there is a possibility to get information about deadlock occured in system. Lets have a look on it in detail in this post.

Lets create event session to monitor our deadlock.

CREATE EVENT SESSION DeadLockSession ON SERVER 
    ADD EVENT sqlserver.xml_deadlock_report  -- ,
      (
      ACTION (sqlserver.sql_text, sqlserver.tsql_stack, sqlserver.database_id,sqlserver.username)
       /*Filter error no or db number*/
     )   
    ADD TARGET package0.ring_buffer    
        (SET max_memory = 4096 
    ) 
WITH (max_dispatch_latency = 30 seconds)

Starting esssion:

ALTER EVENT SESSION  DeadLockSession ON SERVER
STATE = START

Now I create structures, two tables, and fill them with data. I will use it to raise a deadlock.

CREATE TABLE dbo.ConcurentTest (id INT IDENTITY(1,1))
ALTER TABLE dbo.ConcurentTest ADD col INT
CREATE TABLE dbo.ConcurentTest2 (id INT IDENTITY(1,1))
ALTER TABLE dbo.ConcurentTest2 ADD col INT
INSERT INTO dbo.ConcurentTest(col) SELECT 1 FROM sys.objects
INSERT INTO dbo.ConcurentTest2 (col) SELECT 1 FROM sys.objects

To create deadlock open two query windows in management studio and run queries (updates on tables) in bellow mentioned scripts in order specified in table bellow. We cause that queries will block each other to complete its operation because of U and X locks on our objects.

Query1

BEGIN TRAN
UPDATE dbo.ConcurentTest SET col=4 
WhERE id = 5
UPDATE dbo.ConcurentTest2 SET col=4 
WhERE id = 8
COMMIT

Query2

BEGIN TRAN
UPDATE dbo.ConcurentTest2 SET col=4 
WhERE id = 6
UPDATE dbo.ConcurentTest SET col=10
WhERE id = 7
COMMIT

Order to run queries.

Order	Script1	Script2
1	BEGIN TRAN UPDATE dbo.ConcurentTest SET col=4 WhERE id = 5
2		BEGIN TRAN UPDATE dbo.ConcurentTest2 SET col=4 WhERE id = 6
3	UPDATE dbo.ConcurentTest2 SET col=4 WhERE id = 8
4		UPDATE dbo.ConcurentTest SET col=10 WhERE id = 7

Now , in one of your query window you should see deadlock message. Query in this window was marked as deadlock victim and will not finish. Updates in the other query windows will be executed and data will be updated.

Now take a look on output from extended event xml_deadlock_report.

Put data to temporary table

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        = 'DeadLockSession'
       )
     LocksAcquired

Lets parse data.

SELECT p.XMLData.value('(inputbuf)[1]', 'varchar(1000)' ) AS [SqlText] ,
   p.XMLData.value('(@lockMode)[1]', 'varchar(1000)' ) AS [LockMode],
   p.XMLData.value('(@isolationlevel)[1]', 'varchar(1000)' ) AS [IsolationLevel],
   p.XMLData.value('(@spid)[1]', 'varchar(1000)' ) AS [SPID],
   p.XMLData.value('(@id)[1]', 'varchar(1000)' ) AS [processID]
  FROM #LogData tt
CROSS APPLY XMLData.nodes('/RingBufferTarget/event[@name="xml_deadlock_report"]') AS T(XMLData) 
CROSS APPLY T.XMLData.nodes('data/value/deadlock/process-list') AS i(XMLData) 
CROSS APPLY i.XMLData.nodes('process') AS p(XMLData) 

 SELECT	 p.XMLData.value('(@objectname)[1]', 'varchar(1000)' ) AS [OwnerObjectName] 
   ,p.XMLData.value('(owner-list/owner/@id)[1]', 'varchar(1000)' ) AS [OwnerProcessId] 
   ,p.XMLData.value('(waiter-list/waiter/@id)[1]', 'varchar(1000)' ) AS [WaiterProcessId] 
  FROM #LogData tt
CROSS APPLY XMLData.nodes('/RingBufferTarget/event[@name="xml_deadlock_report"]') AS T(XMLData) 
CROSS APPLY T.XMLData.nodes('data/value/deadlock/resource-list') AS i(XMLData) 
CROSS APPLY i.XMLData.nodes('ridlock') AS p(XMLData) 

 SELECT  i.XMLData.value('(victimProcess/@id)[1]', 'varchar(1000)' ) AS [VictimProcessId] 
 FROM #LogData tt
CROSS APPLY XMLData.nodes('/RingBufferTarget/event[@name="xml_deadlock_report"]') AS T(XMLData) 
CROSS APPLY T.XMLData.nodes('data/value/deadlock/victim-list') AS i(XMLData)

After running scipts above you should see which process was evaluated as deadlock victim, marked on picture bellow. You can get queries causing deadlocks with their SPIDSs. There are more interesting informations like deadlock type. In our case it was RID lock since we dont have any index on our structures and page the query touches.

As you can see extended events are very handful in deadlocks scenarios. Since I am still addicting to extended events deeper and deeper you can look forward to another posts with this topic.