SSRS execution log expiration settings

Short description to change execution log expiration settings. SSRS execution log is good tool to monitor reports activity. When using it you can find that the data are not stored forever. The default time period for which the data are stored in Reporting Services database are 60 days. If you would like to change this setting, follow these steps.

Open SQL Management Studio and connect to Reporting Services by selecting Server type to Reporting Services and select your server name.

Connect to SSRS
Connect to SSRS

When connected to the server go to Object Inspector, obviously place on left side in Management Studio, go to Report Server name at the top and right click to get Popup menu.

Server properties
Picture 2 – Server properties

Go to Properties to get Server Properties window. Here you can see set of Reporting Services settings you can change from Management Studio. If you look at the first section, General, thee is URL address for report server (it is available in Reporting Services Configuration manager too). The name of instance is visible when you go to Reporting Services Manager at the top of the web interface. You can change it here.

But we would like to change Execution log settings so go to Logging section on the left menu.

SSRS general properties
Picture 3 – SSRS general properties

Here we can set the number of days the data will be stored in execution log. Or if to disable Report Execution logging at all.

SSRS execution log settings
Picture 4 -SSRS execution log settings

Reporting Services database log execution

Reporting Services execution log. You will find it in Reporting Services database. There stored data regarding Reports and Users activity in Reporting Services repository. You can use it for user access monitoring or when you register problems with Report performance.

Execution log data are stored in ExecutionLogStorage table or you can access it better using view Dbo.ExecutionLog, dbo.ExecutionLog2, dbo.ExecutionLog3 where this table is joined with Catalog table. Here are briefly few interesting attributes which could suit you.

  • Report data processing – information you need to get when resolving performance issues
    • TimeDataRetrieval
      • Time the data are retrieved from dataset in Milliseconds (SQL query, SQL procedure, etc.)
    • TimeProcessing
      • Time the data are processed in report (Expressions, Groups, Sorting etc.)
    • TimeRendering
      • Time the report spends with rendering (Pictures, rows, etc.)
    • TimeStart
      • Start of report processing
    • TimeEnd
      • End of report processing
  • Report data retrieval – good to know how many rows are taken from datasets to report
    • ByteCount
      • Size of rendered report in bytes
    • RowCount
      • Number of rows returned from datasets for report rendering
    • AdditionalInfo
      • Additional information regarding report rendering, processing (for example, rendering extension.)
  • Report states
    • Source – it could be useful when tuning report performance. For example, if report data are already taken from cache.
      • From which source was report generated
        • Live (preview report)
        • Cache – datasets are taken from execution cache
        • Snapshot – report is taken from snapshot
        • History
        • AdHoc – drilltrough actioin, report builder preview
        • Session – data are exported to cs vor excel format for example
        • Rdce – Rdce extension
    • ItemAction – to monitor source of action
      • Render, Sort, BookMarkNavigation, DocumentNavigation, GetDocumentMap, Findstring, Execute, RenderEdit
    • Status – here you can monitor wheater the report was generated sucesfully
      • Status of report processing – error code or rsSuccess
  • Catalog info
    • ItemPath
      • Report item with its path
    • Format
      • In which format was report generated
    • Parameters
      • Parameters set due to report execution – helpful when you would like to monitor which parameters caused performance issues or for nice solution to get last parameter value user set
    • UserName
      • User identifier

Let’s see stats f the Sales Report

 SELECT
 [ItemPath]
,[RequestType]
,[Format]
,[Parameters]
,[ItemAction]
,[TimeStart]
,[TimeEnd]
,[TimeDataRetrieval]
,[TimeProcessing]
,[TimeRendering]
,[Source]
,[Status]
,[ByteCount]
,[RowCount]
,[AdditionalInfo]
FROM [ReportServer].[dbo].[ExecutionLog3]
WHERE ItemPath ='/Blog/ReportSales0 - Detail data'
AND TimeStart='2019-07-28 16:28:12.630'
ORDER
BY TimeStart DESC.

You can see on picture bellow parameters the report was running and duration of report processing.

Report stats
Picture 1 – Report stats

Here you can see time in milliseconds the report spent on Time Processing and Time Rendering. Time Data Retrieval is 0 because the report was processed from cache as you can see in Source attribute.

Report starts
Picture 2 – Report starts

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.