Skip to Content

  In SQL server 2008 and later version, Microsoft introduces a new light weight trace tool called extended events. I found it is useful to identify expensive SQL statements in time using rpc_completed extended events. Unlike DMVs, this shows individual statement instead of cumulative data. and it is much useful to identify the source of the problem. I create a new T-SQL to generate rpc_completed extended event and an extracted T-SQL to view this data. Hope this can help others who want to identify expensive SQL statements. I give an exmaple below.

  There is one issue there. I still can’t get the correct plan_handle and extract the execution plan. Maybe someone can tell me how to do it.

PS: I recommend you to read raw file(.xel) directly. The information there is more complete.

— This script creates an extended event

IF EXISTS(SELECT * FROM sys.server_event_sessions WHERE name=’RPC_Expensive_Queries’)
    DROP EVENT SESSION [RPC_Expensive_Queries] ON SERVER;
GO

CREATE EVENT SESSION [RPC_Expensive_Queries] ON SERVER
    ADD EVENT sqlserver.rpc_completed(
         ACTION (sqlserver.database_id,
                 sqlserver.plan_handle,
                 sqlserver.session_id,
                 sqlserver.sql_text)
    WHERE cpu_time > 1000000000 /*total ms of CPU time, night 0, 000000000*/
       OR duration > 1000000000 /* night 0*/
       OR logical_reads > 100000000 /* eight 0 */
       OR physical_reads > 1000000 /* six 0 */
       OR writes > 100000 ) /*five 0 */
    ADD TARGET package0.ring_buffer(SET max_memory=2048),
    ADD TARGET package0.asynchronous_bucketizer(
        SET filtering_event_name=’sqlserver.rpc_completed’,
            source=’sqlserver.sql_text’),
    ADD TARGET package0.asynchronous_file_target
        (SET FILENAME = N’C:\Program Files\Microsoft SQL Server\MSSQL11.MSSQLSERVER\MSSQL\Log\RPC_Expensive_Queries.xel’,
        METADATAFILE = N’C:\Program Files\Microsoft SQL Server\MSSQL11.MSSQLSERVER\MSSQL\Log\RPC_Expensive_Queries.xem’)
WITH (MAX_MEMORY = 4096KB,
      EVENT_RETENTION_MODE = ALLOW_SINGLE_EVENT_LOSS,
      MAX_DISPATCH_LATENCY = 10 SECONDS,
      MAX_EVENT_SIZE = 0KB,
      MEMORY_PARTITION_MODE = NONE,
      TRACK_CAUSALITY = OFF,
      STARTUP_STATE = OFF)
GO

ALTER EVENT SESSION [RPC_Expensive_Queries] ON SERVER STATE = START
GO

— This script extracts xml information

SELECT

data.value (

  ‘(/event[@name=”rpc_completed”]/@timestamp)[1]’,

   ‘DATETIME’) AS [Time],

data.value (‘(/event/data[@name=”cpu_time”]/value)[1]’, ‘BIGINT’) AS [CPU (ms)],

data.value (‘(/event/data[@name=”duration”]/value)[1]’, ‘BIGINT’) AS [duration (ms)],

— CONVERT (FLOAT, data.value (

—  ‘(/event/data[@name=”cpu_time”]/value)[1]’, ‘BIGINT’)) / 1000000 AS [CPU (s)],

— CONVERT (FLOAT, data.value (

—  ‘(/event/data[@name=”duration”]/value)[1]’, ‘BIGINT’)) / 1000000 AS [Duration (s)],

        data.value(‘(/event/data[@name=”logical_reads”]/value)[1]’,’bigint’) LogicalReads,

        data.value(‘(/event/data[@name=”physical_reads”]/value)[1]’,’bigint’) PhysicalReads,

        data.value(‘(/event/data[@name=”writes”]/value)[1]’, ‘bigint’) as writes,

data.value (‘(/event/action[@name=”sql_text”]/value)[1]’,’VARCHAR(MAX)’) AS [SQL Text],

—        data.value (‘(/event/data[@name=”statement”]/value)[1]’,’VARCHAR(MAX)’) AS [Statement],

CAST(data.value(‘(event/action[@name=”plan_handle”]/value)[1]’, ‘varchar(max)’) AS XML) as plan_handle

FROM

(SELECT CONVERT (XML, event_data) AS data

FROM sys.fn_xe_file_target_read_file

  (‘C:\Program Files\Microsoft SQL Server\MSSQL11.MSSQLSERVER\MSSQL\Log\RPC_Expensive_Queries*.xel’,

  ‘C:\Program Files\Microsoft SQL Server\MSSQL11.MSSQLSERVER\MSSQL\Log\RPC_Expensive_Queries*.xem’, null, null)

) entries

ORDER BY [Time] DESC;

GO

— This is an expensive SQL statement I captured. Someone queries a mass data in table MSEG using SE16

— you can get xml format using

— SELECT CONVERT (XML, event_data) AS data

— FROM sys.fn_xe_file_target_read_file

—  (‘C:\Program Files\Microsoft SQL Server\MSSQL11.MSSQLSERVER\MSSQL\Log\RPC_Expensive_Queries*.xel’,

—  ‘C:\Program Files\Microsoft SQL Server\MSSQL11.MSSQLSERVER\MSSQL\Log\RPC_Expensive_Queries*.xem’, null, null)

<event name=”rpc_completed” package=”sqlserver” timestamp=”2013-12-13T03:42:20.284Z”>

  <data name=”cpu_time”>

    <value>614925000</value>

  </data>

  <data name=”duration”>

    <value>747622927</value>

  </data>

  <data name=”physical_reads”>

    <value>10545780</value>

  </data>

  <data name=”logical_reads”>

    <value>53445177</value>

  </data>

  <data name=”writes”>

    <value>0</value>

  </data>

  <data name=”result”>

    <value>0</value>

    <text>OK</text>

  </data>

  <data name=”row_count”>

    <value>4</value>

  </data>

  <data name=”connection_reset_option”>

    <value>0</value>

    <text>None</text>

  </data>

  <data name=”object_name”>

    <value>sp_prepexec</value>

  </data>

  <data name=”statement”>

    <value>declare @p1 int

set @p1=773450

exec sp_prepexec @p1 output,N’@P1 nvarchar(3),@P2 nvarchar(16)’,N’SELECT TOP 4000 “MANDT” AS c ,”MBLNR” AS c ,”MJAHR” AS c ,”ZEILE” AS c ,”LINE_ID” AS c ,”PARENT_ID” AS c ,”LINE_DEPTH” AS c ,”MAA_URZEI” AS c ,”BWART” AS c ,”XAUTO” AS c ,”MATNR” AS c ,”WERKS” AS c ,”LGORT” AS c ,”CHARG” AS c ,”INSMK” AS c ,”ZUSCH” AS c ,”ZUSTD” AS c ,”SOBKZ” AS c ,”LIFNR” AS c ,”KUNNR” AS c ,”KDAUF” AS c ,”KDPOS” AS c ,”KDEIN” AS c ,”PLPLA” AS c ,”SHKZG” AS c ,”WAERS” AS c ,”DMBTR” AS c ,”BNBTR” AS c ,”BUALT” AS c ,”SHKUM” AS c ,”DMBUM” AS c ,”BWTAR” AS c ,”MENGE” AS c ,”MEINS” AS c ,”ERFMG” AS c ,”ERFME” AS c ,”BPMNG” AS c ,”BPRME” AS c ,”EBELN” AS c ,”EBELP” AS c ,”LFBJA” AS c ,”LFBNR” AS c ,”LFPOS” AS c ,”SJAHR” AS c ,”SMBLN” AS c ,”SMBLP” AS c ,”ELIKZ” AS c ,”SGTXT” AS c ,”EQUNR” AS c ,”WEMPF” AS c ,”ABLAD” AS c ,”GSBER” AS c ,”KOKRS” AS c ,”PARGB” AS c ,”PARBU” AS c ,”KOSTL” AS c ,”PROJN” AS c ,”AUFNR” AS c ,”ANLN1″ AS c ,”ANLN2″ AS c ,”XSKST” AS c ,”XSAUF” AS c ,”XSPRO” AS c ,”XSERG” AS c,”GJAHR” AS c ,”XRUEM” AS c ,”XRUEJ” AS c ,”BUKRS” AS c ,”BELNR” AS c ,”BUZEI” AS c ,”BELUM” AS c ,”BUZUM” AS c ,”RSNUM” AS c ,”RSPOS” AS c ,”KZEAR” AS c ,”PBAMG” AS c ,”KZSTR” AS c ,”UMMAT” AS c ,”UMWRK” AS c ,”UMLGO” AS c ,”UMCHA” AS c ,”UMZST” AS c ,”UMZUS” AS c ,”UMBAR” AS c ,”UMSOK” AS c ,”KZBEW” AS c ,”KZVBR” AS c ,”KZZUG” AS c ,”WEUNB” AS c ,”PALAN” AS c ,”LGNUM” AS c ,”LGTYP” AS c ,”LGPLA” AS c ,”BESTQ” AS c ,”BWLVS” AS c ,”TBNUM” AS c ,”TBPOS” AS c ,”XBLVS” AS c ,”VSCHN” AS c ,”NSCHN” AS c ,”DYPLA” AS c ,”UBNUM” AS c ,”TBPRI” AS c ,”TANUM” AS c ,”WEANZ” AS c ,”GRUND” AS c ,”EVERS” AS c ,”EVERE” AS c ,”IMKEY” AS c ,”KSTRG” AS c ,”PAOBJNR” AS c ,”PRCTR” AS c ,”PS_PSP_PNR” AS c ,”NPLNR” AS c ,”AUFPL” AS c ,”APLZL” AS c ,”AUFPS” AS c ,”VPTNR” AS c ,”FIPOS” AS c ,”SAKTO” AS c ,”BSTMG” AS c ,”BSTME” AS c ,”XWSBR” AS c ,”EMLIF” AS c ,”EXBWR” AS c ,”VKWRT” AS c ,”AKTNR” AS c ,”ZEKKN” AS c ,”VFDAT” AS c ,”CUOBJ_CH” AS c ,”EXVKW” AS c ,”PPRCTR” AS c ,”RSART” AS c ,”GEBER” AS c ,”FISTL” AS c ,”MATBF” AS c ,”UMMAB” AS c ,”BUSTM” AS c ,”BUSTW” AS c ,”MENGU” AS c ,”WERTU” AS c ,”LBKUM” AS c ,”SALK3″ AS c ,”VPRSV” AS c ,”FKBER” AS c ,”DABRBZ” AS c ,”VKWRA” AS c ,”DABRZ” AS c ,”XBEAU” AS c ,”LSMNG” AS c ,”LSMEH” AS c ,”KZBWS” AS c ,”QINSPST” AS c ,”URZEI” AS c ,”J_1BEXBASE” AS c ,”MWSKZ” AS c ,”TXJCD” AS c ,”EMATN” AS c ,”J_1AGIRUPD” AS c ,”VKMWS” AS c ,”HSDAT” AS c ,”BERKZ” AS c ,”MAT_KDAUF” AS c ,”MAT_KDPOS” AS c ,”MAT_PSPNR” AS c ,”XWOFF” AS c ,”BEMOT” AS c ,”PRZNR” AS c ,”LLIEF” AS c ,”LSTAR” AS c ,”XOBEW” AS c ,”GRANT_NBR” AS c ,”ZUSTD_T156M” AS c ,”SPE_GTS_STOCK_TY” AS c ,”KBLNR” AS c ,”KBLPOS” AS c ,”XMACC” AS c ,”VGART_MKPF” AS c ,”BUDAT_MKPF” AS c ,”CPUDT_MKPF” AS c ,”CPUTM_MKPF” AS c ,”USNAM_MKPF” AS c ,”XBLNR_MKPF” AS c ,”TCODE2_MKPF” AS c ,”/BEV2/ED_KZ_VER” AS c ,”/BEV2/ED_USER” AS c ,”/BEV2/ED_AEDAT” AS c ,”/BEV2/ED_AETIM” AS c ,”OINAVNW” AS c ,”OICONDCOD” AS c ,”CONDI” AS c FROM “MSEG” WHERE “MANDT” = @P1 AND “XBLNR_MKPF” = @P2

/* R3:/1BCDWB/DBMSEG:1298 T:MSEG */

‘,N’218′,N’5585577476’

select @p1</value>

  </data>

  <data name=”data_stream”>

    <value />

  </data>

  <data name=”output_parameters”>

    <value />

  </data>

  <action name=”database_id” package=”sqlserver”>

    <value>5</value>

  </action>

  <action name=”plan_handle” package=”sqlserver”>

    <value>0000000000000000000000000000000000000000000000000000000000000000000000000000000000000000</value>

  </action>

  <action name=”session_id” package=”sqlserver”>

    <value>1262</value>

  </action>

  <action name=”sql_text” package=”sqlserver”>

    <value>(@P1 nvarchar(3),@P2 nvarchar(16))SELECT TOP 4000 “MANDT” AS c ,”MBLNR” AS c ,”MJAHR” AS c ,”ZEILE” AS c ,”LINE_ID” AS c ,”PARENT_ID” AS c ,”LINE_DEPTH” AS c ,”MAA_URZEI” AS c ,”BWART” AS c ,”XAUTO” AS c ,”MATNR” AS c ,”WERKS” AS c ,”LGORT” AS c ,”CHARG” AS c ,”INSMK” AS c ,”ZUSCH” AS c ,”ZUSTD” AS c ,”SOBKZ” AS c ,”LIFNR” AS c ,”KUNNR” AS c ,”KDAUF” AS c ,”KDPOS” AS c ,”KDEIN” AS c ,”PLPLA” AS c ,”SHKZG” AS c ,”WAERS” AS c ,”DMBTR” AS c ,”BNBTR” AS c ,”BUALT” AS c ,”SHKUM” AS c ,”DMBUM” AS c ,”BWTAR” AS c ,”MENGE” AS c ,”MEINS” AS c ,”ERFMG” AS c ,”ERFME” AS c ,”BPMNG” AS c ,”BPRME” AS c ,”EBELN” AS c ,”EBELP” AS c ,”LFBJA” AS c ,”LFBNR” AS c ,”LFPOS” AS c ,”SJAHR” AS c ,”SMBLN” AS c ,”SMBLP” AS c ,”ELIKZ” AS c ,”SGTXT” AS c ,”EQUNR” AS c ,”WEMPF” AS c ,”ABLAD” AS c ,”GSBER” AS c ,”KOKRS” AS c ,”PARGB” AS c ,”PARBU” AS c ,”KOSTL” AS c ,”PROJN” AS c ,”AUFNR” AS c ,”ANLN1″ AS c ,”ANLN2″ AS c ,”XSKST” AS c ,”XSAUF” AS c ,”XSPRO” AS c ,”XSERG” AS c ,”GJAHR” AS c ,”XRUEM” AS c ,”XRUEJ” AS c ,”BUKRS” AS c ,”BELNR” AS c ,”BUZEI” AS c ,”BELUM” AS c ,”BUZUM” AS c ,”RSNUM” AS c ,”RSPOS” AS c ,”KZEAR” AS c ,”PBAMG” AS c ,”KZSTR” AS c ,”UMMAT” AS c ,”UMWRK” AS c ,”UMLGO” AS c ,”UMCHA” AS c ,”UMZST” AS c ,”UMZUS” AS c ,”UMBAR” AS c ,”UMSOK” AS c ,”KZBEW” AS c ,”KZVBR” AS c ,”KZZUG” AS c ,”WEUNB” AS c ,”PALAN” AS c ,”LGNUM” AS c ,”LGTYP” AS c ,”LGPLA” AS c ,”BESTQ” AS c ,”BWLVS” AS c ,”TBNUM” AS c ,”TBPOS” AS c ,”XBLVS” AS c ,”VSCHN” AS c ,”NSCHN” AS c ,”DYPLA” AS c ,”UBNUM” AS c ,”TBPRI” AS c ,”TANUM” AS c ,”WEANZ” AS c ,”GRUND” AS c ,”EVERS” AS c ,”EVERE” AS c ,”IMKEY” AS c ,”KSTRG” AS c ,”PAOBJNR” AS c ,”PRCTR” AS c ,”PS_PSP_PNR” AS c ,”NPLNR” AS c ,”AUFPL” AS c ,”APLZL” AS c ,”AUFPS” AS c ,”VPTNR” AS c ,”FIPOS” AS c ,”SAKTO” AS c ,”BSTMG” AS c ,”BSTME” AS c ,”XWSBR” AS c ,”EMLIF” AS c ,”EXBWR” AS c ,”VKWRT” AS c ,”AKTNR” AS c ,”ZEKKN” AS c ,”VFDAT” AS c ,”CUOBJ_CH” AS c ,”EXVKW” AS c ,”PPRCTR” AS c ,”RSART” AS c ,”GEBER” AS c ,”FISTL” AS c ,”MATBF” AS c ,”UMMAB” AS c ,”BUSTM” AS c ,”BUSTW” AS c ,”MENGU” AS c ,”WERTU” AS c ,”LBKUM” AS c ,”SALK3″ AS c ,”VPRSV” AS c ,”FKBER” AS c ,”DABRBZ” AS c ,”VKWRA” AS c ,”DABRZ” AS c ,”XBEAU” AS c ,”LSMNG” AS c ,”LSMEH” AS c ,”KZBWS” AS c ,”QINSPST” AS c ,”URZEI” AS c ,”J_1BEXBASE” AS c ,”MWSKZ” AS c ,”TXJCD” AS c ,”EMATN” AS c ,”J_1AGIRUPD” AS c ,”VKMWS” AS c ,”HSDAT” AS c ,”BERKZ” AS c ,”MAT_KDAUF” AS c ,”MAT_KDPOS” AS c ,”MAT_PSPNR” AS c ,”XWOFF” AS c ,”BEMOT” AS c ,”PRZNR” AS c ,”LLIEF” AS c ,”LSTAR” AS c ,”XOBEW” AS c ,”GRANT_NBR” AS c ,”ZUSTD_T156M” AS c ,”SPE_GTS_STOCK_TY” AS c ,”KBLNR” AS c ,”KBLPOS” AS c ,”XMACC” AS c ,”VGART_MKPF” AS c ,”BUDAT_MKPF” AS c ,”CPUDT_MKPF” AS c ,”CPUTM_MKPF” AS c ,”USNAM_MKPF” AS c ,”XBLNR_MKPF” AS c ,”TCODE2_MKPF” AS c ,”/BEV2/ED_KZ_VER” AS c ,”/BEV2/ED_USER” AS c ,”/BEV2/ED_AEDAT” AS c ,”/BEV2/ED_AETIM” AS c ,”OINAVNW” AS c ,”OICONDCOD” AS c ,”CONDI” AS c FROM “MSEG” WHERE “MANDT” = @P1 AND “XBLNR_MKPF” = @P2

/* R3:/1BCDWB/DBMSEG:1298 T:MSEG */

</value>

  </action>

</event>

To report this post you need to login first.

3 Comments

You must be Logged on to comment or reply to a post.

  1. Leslie Moser

    Hello Dennis,

    We have also built in an expensive SQL Setatement history to transaction DBACockpit. Every 20 minutes, we capture and store the statements (and their plans) that are expensive by a few different categories: CPU, reads, calls, etc. You can even see the plan stored at the time of the expensive execution and compare it to the plan currently in cache.

    The screen is available in newer SAP NetWeaver releases and has been documented here:  http://scn.sap.com/docs/DOC-47393

    Best regards,

    Leslie

    ___________________________

    Leslie Moser
    Developer, Microsoft Platforms U.S.

    Netweaver Development Tools
    SAP Labs, LLC

    (0) 
      1. Leslie Moser

        Hello Dennis,

        OK, I see your point. There is always the chance that an expensive statement is not captured by our monitor. We take our snapshots every 20 minutes and rank the statements by what is in the cache at that very moment. So if a very expensive statement starts 2 minutes after Snapshot1 and finishes at 15 minutes after Snapshot1 plus the plan is then removed from the cache at minute 18, then the statement/plan won’t be captured by our scan of the cache at the next 20 minute Snapshot2 as it no longer exists in the cache.

        In regard to the second link you gave, we have processed just a a few customer messages where SAP on SQL Server customer systems did indeed have the bug documented in that Microsoft KB. You can always open an SAP customer incident to have us help you confirm your system does have that problem. Or, if you have a downtime scheduled soon you might just wish to apply the CU anyway and not spend time looking backward through the statistics. As of today, I’d recommend applying the latest (SQL Server 2012 SP1 CU7) if you’re going to apply a CU to your server.

        Thank you and best regards,

        Leslie

        (0) 

Leave a Reply