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.

SSRS Reporting Service URL commands

When you would like to access Report Server from your application or just link reports, you can use URL of Report Server for such a task. URL access to Reporting Services supports few useful commands you can handle visualisation your reports.

There are following sets of commands you can change look your Reporting Services.

Find more info here: https://bit.ly/2SYlgr0 .

Find few examples bellow.

Hide Toolbar with parameters.
http://dwh/Reportserver?/Blog/ReportSales7 - Interactive sorting&rc:Parameters=Collapsed
Collapsed toolbar
Picture 1 – Collapsed toolbar
Go to second page.
http://dwh/Reportserver?/Blog/ReportSales0 - Detail data&rc:Section=2
Report second page
Picture 2 – Report second page
List reports in directory.
http://dwh/Reportserver?/Blog/&rs:Command=GetChildren
List directory
Picture 3 – List directory
Get PDF format of report.
http://dwh/Reportserver?/Blog/ReportSales0 - Detail data&rs:Format=PDF
Export report
Picture 4 – Export report