{"id":2995,"date":"2024-12-02T07:00:00","date_gmt":"2024-12-02T04:00:00","guid":{"rendered":"https:\/\/www.dataplatform.gr\/?p=2995"},"modified":"2024-12-01T22:35:39","modified_gmt":"2024-12-01T19:35:39","slug":"pos-syllegoyme-to-actual-execution-plan-apo-ta-queries-me-chrisi-extended-ev","status":"publish","type":"post","link":"https:\/\/www.dataplatform.gr\/en\/pos-syllegoyme-to-actual-execution-plan-apo-ta-queries-me-chrisi-extended-ev\/","title":{"rendered":"How do we collect the actual execution plan from queries using Extended Event and how do we read its data"},"content":{"rendered":"

In older article<\/a> we had seen how to activate it Query Store<\/strong> to monitor the performance of the queries and the plan they ran. However, as we said, the Query Store has a lot of performance impact, so we may want some lightweight profiling. In this article, we will see how to enable Extended Event that records this information.<\/p>\n\n\n\n

You name it query_post_execution_plan_profile<\/em><\/strong> and activate from the versions SQL Server 2019 \/ SQL Server 2017 CU14 <\/strong>and then.<\/p>\n\n\n\n

It records the actual execution plan information. It is lightweight as it does not record wait types, heavy CPU and I\/O metrics.<\/p>\n\n\n\n

To create the Extended Event<\/h4>\n\n\n\n

We must not forget to change the path to the one where we want the data to be stored.<\/p>\n\n\n\n

All we need to do is run the following T-SQL command. Once created, it will record all queries that lasted longer than 5 seconds in an XML file at the path we have declared.<\/p>\n\n\n\n

CREATE EVENT SESSION [query_post_execution_plan_profile] ON SERVER \nADD EVENT sqlserver.query_post_execution_plan_profile(SET collect_database_name=(0)\n    ACTION(sqlserver.client_hostname,sqlserver.database_name,sqlserver.plan_handle,sqlserver.sql_text)\n    WHERE ([package0].[greater_than_equal_uint64]([duration],(5000000))))\nADD TARGET package0.event_file(SET filename=N'c:\\xevents\\query_post_execution_plan_profile')\nWITH (MAX_MEMORY=4096 KB,EVENT_RETENTION_MODE=ALLOW_SINGLE_EVENT_LOSS,MAX_DISPATCH_LATENCY=5 SECONDS,MAX_EVENT_SIZE=0 KB,MEMORY_PARTITION_MODE=NONE,TRACK_CAUSALITY=OFF,STARTUP_STATE=ON)\nGO\n\nalter event session query_post_execution_plan_profile on server state=start;\ngo<\/pre>\n\n\n\n
We check in the Object Explorer that the Extended Event is running (it is green), if it is not, right-click on it and start session.<\/p>\n\n\n\n
\"\"<\/figure>\n\n\n\n
How we read the results<\/h4>\n\n\n\n
In the path we defined during its creation XEvent <\/strong>a .xel and a .xem file were created. Through the dynamic view sys.fn_xe_file_target_read_file<\/strong> with parameters these files we result in all the XML <\/strong>file with the information.<\/p>\n\n\n\n
But since it is impractical to read an XML by eye, the file must somehow be filtered into a more readable form.<\/p>\n\n\n\n
So I sat down and made a query that does this job.<\/p>\n\n\n\n
For starters, through the name we created, Xevent finds the path that is dynamically located and defines it as a parameter in the query.<\/p>\n\n\n\n
Then we define the XML as one Common Table Expression<\/strong>. By doing SELECT we can get the value from each property we need.<\/p>\n\n\n\n
In the where statement we can filter specific bases, the duration and the period of time it was executed.<\/p>\n\n\n\n
This part needs attention, as the default xml timestamp is in UTC timezone, so to put the actual time that the server has, we add the time difference that the server has with the UTC timezone (DATEADD(HOUR,DATEDIFF(hour, SYSUTCDATETIME(),SYSDATETIME() )<\/em>).<\/p>\n\n\n\n
declare\n@xel as varchar(max),\n@xem as varchar(max),\n@xm as XML\n\nset @xel=(select \nSUBSTRING(cast(f.value as varchar(max)),1,len(cast(f.value as varchar(max)))-4)+'*.xel' as xel\nfrom sys.server_event_session_fields f\ninner join sys.server_event_sessions n on f.event_session_id = n.event_session_id\nWHERE f.NAME = 'filename' \nand n.name like '%post%') --Set xevent Name\n\nset @xem=(select \nSUBSTRING(cast(f.value as varchar(max)),1,len(cast(f.value as varchar(max)))-4)+'*.xem' as xem\nfrom sys.server_event_session_fields f\ninner join sys.server_event_sessions n on f.event_session_id = n.event_session_id\nWHERE f.NAME = 'filename' \nand n.name like '%post%')  --Set xevent Name\n\n;WITH XEvents AS\n(\nselect  object_name, CAST(event_data AS XML) AS A FROM sys.fn_xe_file_target_read_file(\n@xel\n,@xem\n, NULL, NULL) \n)\n\nSELECT\nA.value ('(\/event\/action[@name=''database_name'']\/value)[1]', 'VARCHAR(MAX)') AS DB_Name,\nDATEADD(HOUR,DATEDIFF(hour,  SYSUTCDATETIME(),SYSDATETIME() ),A.value ('(\/event\/@timestamp)[1]', 'DATETIME')) AS [Time],\nA.value ('(event\/data[@name=\"duration\"]\/value)[1]','bigint') \/ 1000000  AS [Duration_Seconds],\nA.value ('(\/event\/action[@name=''sql_text'']\/value)[1]', 'VARCHAR(MAX)') AS sql_text,\n--A.value ('(\/event\/action[@name=''query_hash_signed'']\/value)[1]', 'VARCHAR(MAX)') AS query_hash_signed,\n--A.value ('(\/event\/action[@name=''query_plan_hash_signed'']\/value)[1]', 'VARCHAR(MAX)') AS query_plan_hash_signed,\nA.value ('(\/event\/action[@name=''client_hostname'']\/value)[1]', 'VARCHAR(MAX)') AS client_hostname,\nA.value('(event\/data[@name=\"estimated_rows\"]\/value)[1]','bigint') AS row_count,\nA.value('(\/event\/data[@name=''cpu_time'']\/value)[1]','bigint') \/1000000 AS cpu_seconds,\nz.fragment.query('.') as showplan,\nA.value ('(\/event\/action[@name=''plan_handle'']\/value)[1]', 'VARCHAR(MAX)') AS plan_handle,\nA  AS xml_report\nfrom XEvents\nCROSS APPLY A.nodes('\/event\/data[@name=\"showplan_xml\"]\/value\/*') as z(fragment)\nwhere  1=1\n--and DATEADD(HOUR,DATEDIFF(hour,  SYSUTCDATETIME(),SYSDATETIME() ),A.value ('(\/event\/@timestamp)[1]', 'DATETIME'))  between '2020-05-20 10:45:00.000' and '2020-05-22 12:45:00.000'\n--and A.value ('(\/event\/action[@name=''database_name'']\/value)[1]', 'VARCHAR(MAX)') ='mig_db'\n--and A.value('(event\/data[@name=\"duration\"]\/value)[1]','bigint') \/ 1000000  >= 10 --sec\n\n<\/pre>\n\n\n\n
The result<\/h3>\n\n\n\n
The result of the query brought us, for this period of time, in the database we asked for, the queries that ran for more than 5 seconds, in which database they ran, for how long, the sql text, where they ran from, how many records they fetched, and the execution plan they ran.<\/p>\n\n\n\n
\"\"<\/figure>\n\n\n\n
Selecting the hyperlink on each one will open the graphic from the execution plan it had.<\/p>\n\n\n\n
\"\"<\/figure>\n\n\n\n
Sources:<\/h2>\n\n\n\n