How to identify expensive SQL statements in SAP using extended events?

[former_member211576]

  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>