{"id":2022,"date":"2020-11-05T07:00:00","date_gmt":"2020-11-05T04:00:00","guid":{"rendered":"https:\/\/www.dataplatform.gr\/?p=2022"},"modified":"2024-10-16T13:07:20","modified_gmt":"2024-10-16T10:07:20","slug":"to-query-profiling-ginetai-lightweight","status":"publish","type":"post","link":"https:\/\/www.dataplatform.gr\/en\/to-query-profiling-ginetai-lightweight\/","title":{"rendered":"How do we find how much more it takes to complete the query and which is delayed (SQL Server Query Profiling)"},"content":{"rendered":"

Many times we will encounter queries that take too long to complete or never complete at all. To find out what exactly is at fault the most useful information is the actual execution plan<\/strong>.<\/p>\n\n\n\n

As the actual execution plan requires the completion of the query, with the live query statistics<\/strong> provide the ability for real-time information as you run the query. Information such as which query of the batch we are in, the number of records produced, execution time, CPU \u2013 I\/O usage, the progress of the query and finally in which execution plan operator<\/strong> we are here to complete the process.<\/p>\n\n\n\n

<\/p>\n\n\n\n

How can we monitor a specific query that we want to run<\/h2>\n\n\n\n

By writing the command before the query SET STATISTICS PROFILE ON<\/strong> when we run the batch in addition to the results we will be shown the actual execution plan<\/strong> per query<\/strong>.<\/p>\n\n\n\n

SET STATISTICS PROFILE ON\n\n\nselect top 10 * from pinakas;\ngo\n\ncreate nonclustered index ix_pin on pinakas (onoma);\ngo\n\ndelete from pinakas where tilefono like '%5%'\ngo\n\ndeclare \n@i int;\nset @i =1;\nwhile @i<100000\nbegin\ninsert into pinakas values ('stratos'+cast(@i as varchar),'20294012',null)\nset @i=@i+1\nend<\/pre>\n\n\n\n
\"\"<\/figure>\n\n\n\n
At the same time, this information about the progress of the query (which has the statistics profile activated) is recorded in the dynamic view sys.dm_exec_query_profiles<\/strong>. At the same time we can see the live execution plan<\/strong> in the sys.dm_exec_query_Statistics_xml<\/strong>.<\/p>\n\n\n\n
So by running it we see in which query <\/strong>and operator <\/strong>the batch is currently available. We also see it completion rate<\/strong>, the wait type and the live execution plan<\/strong> of.<\/p>\n\n\n\n
select d.name,qp.session_id,text,physical_operator_name,(row_count*100\/nullif(estimate_row_count,0)) as percent_complete,w.wait_type,w.wait_duration_ms,lp.query_plan as live_query_plan,p.query_plan,row_count,estimate_row_count,cpu_time_ms,logical_read_count,physical_read_count,write_page_count,qp.object_id,object_name(qp.object_id) as object_name,qp.index_id\n,i.name as index_name\nfrom sys.dm_exec_query_profiles qp\nleft join sys.dm_os_waiting_tasks w on w.session_id = qp.session_id\nleft join sys.databases d on d.database_id = qp.database_id\nleft join sys.indexes i on qp.object_id=i.object_id and qp.index_id = i.index_id\nouter apply sys.dm_exec_sql_text(qp.sql_handle) as t\nouter apply sys.dm_exec_query_plan(qp.plan_handle) as p\nouter apply sys.dm_exec_query_Statistics_xml(qp.plan_handle) as lp\nwhere text not like '%dm_exec_query_profiles%'\n<\/pre>\n\n\n\n
\"\"<\/figure>\n\n\n\n
How to enable Live Query Statistics<\/h2>\n\n\n\n
Beyond choosing to turn it on statistics profile<\/strong> if we are using SQL Server Management Studio 2016 and later, we have the option to enable both Live Query Statistics<\/strong>.<\/p>\n\n\n\n
Simple by selecting its button before executing the specific query Include Live Query Statistics<\/strong> (as shown in the image below).<\/p>\n\n\n\n
During the execution of the query we will see the query progress per batch and the progress of each query plan operator within it. <\/p>\n\n\n\n
\"\"<\/figure>\n\n\n\n
Also if we right click on Activity Monitor<\/strong> of Management Studio we will see the option Show Live Execution Plan<\/strong>  for which only queries the command is used SET STATISTICS PROFILE ON<\/strong>.<\/p>\n\n\n\n
\"\"<\/figure>\n\n\n\n
<\/p>\n\n\n\n
How do we enable these functions across the instance?<\/h2>\n\n\n\n
Its use profiling <\/strong>has always been a function with a large performance impact<\/strong> so we activate it for a certain period of time on selected bases.<\/p>\n\n\n\n
Since SQL Server 2016 (although officially it was from SQL Server 2014 SP2 using XEvent) introduced the lightweight query profiling<\/strong>. It is a lighter profiling that does not record CPU usage but collects all other information.<\/p>\n\n\n\n
Thanks to lightweight query profiling, we can have profiling enabled permanently on the entire instance.<\/p>\n\n\n\n
<\/p>\n\n\n\n
How to enable lightweight query profiling<\/h2>\n\n\n\n
To SQL Server 2016<\/strong> we can enable trace flag 7412 so that it is enabled on the entire instance.<\/p>\n\n\n\n
DBCC TRACEON (7412, -1);<\/pre>\n\n\n\n
Alternatively we can activate it if it is not at the instance level at the query only level with query hint<\/strong>.<\/p>\n\n\n\n
select * from pinakas option ( use hint ( 'QUERY_PLAN_PROFILE' ));<\/pre>\n\n\n\n
In order for it to work, XEvent must exist and has been created query_plan_profile<\/strong>.<\/p>\n\n\n\n
CREATE EVENT SESSION query_plan_profile\n    ON SERVER\n    ADD EVENT sqlserver.query_plan_profile\n    ( SET collect_database_name = ( 0 )\n     ACTION ( sqlserver.plan_handle, \n              sqlserver.query_hash_signed, \n              sqlserver.query_plan_hash_signed, \n              sqlserver.sql_text )\n              )\n    ADD TARGET package0.event_file\n    ( SET filename = N'c:\\xevents\\query_plan_profile' )\n    WITH ( MAX_MEMORY = 4096KB,\n           EVENT_RETENTION_MODE = ALLOW_SINGLE_EVENT_LOSS,\n           MAX_DISPATCH_LATENCY = 5 SECONDS,\n           MAX_EVENT_SIZE = 0KB,\n           MEMORY_PARTITION_MODE = NONE,\n           TRACK_CAUSALITY = OFF,\n           STARTUP_STATE = OFF );\nGO\n \nALTER EVENT SESSION query_plan_profile ON SERVER STATE = START;\nGO<\/pre>\n\n\n\n
<\/p>\n\n\n\n
What's changing in SQL Server 2019<\/h2>\n\n\n\n
From SQL Server 2019 on lightweight query profiling <\/strong>is enabled at the instance level by default (no trace flag needed).<\/p>\n\n\n\n
There is the command to enable or disable at database level.<\/p>\n\n\n\n
ALTER DATABASE SCOPED CONFIGURATION SET LIGHTWEIGHT_QUERY_PROFILING = ON\n<\/pre>\n\n\n\n
We also have the ability to find the last actual execution plan<\/strong> of the queries that are still blocked.<\/p>\n\n\n\n
To enable it we run at base level:<\/p>\n\n\n\n
ALTER DATABASE SCOPED CONFIGURATION SET LAST_QUERY_PLAN_STATS = ON;<\/pre>\n\n\n\n
To see the results simply having only the sql text:<\/p>\n\n\n\n
SELECT size_in_bytes,cacheobjtype,objtype,text,query_plan FROM sys.dm_exec_cached_plans AS cp\nCROSS APPLY sys.dm_exec_sql_text(plan_handle) AS st\nCROSS APPLY sys.dm_exec_query_plan_stats(plan_handle) AS qps\nWHERE st.text LIKE '%test%';  \nGO  <\/pre>\n\n\n\n
\"\"<\/figure>\n\n\n\n
Selecting the hyperlink in each one will open the graphic from the plan it had.<\/p>\n\n\n\n
\"\"<\/figure>\n\n\n\n
Also in SQL Server 2019 \/ SQL Server 2017 CU14 we have a new lightweight Extended Event (query_post_execution_plan_profile<\/em><\/strong>) which records the information of the actual execution plan. It is lightweight as it does not record wait types, heavy CPU and I\/O metrics.<\/p>\n\n\n\n
The script to create (I have set a threshold of 5 seconds and above):<\/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
To see the results with a single query that I painstakingly wrote to read the XML of the Extended Event:<\/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, TRY_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)') ='DB_test'\n--and A.value('(event\/data[@name=\"duration\"]\/value)[1]','bigint') \/ 1000000  >= 10 --sec\n\n<\/pre>\n\n\n\n
As we can see, it also brings us the shot that ran and by simply double-clicking on the hyperlink we will see its graphic.<\/p>\n\n\n\n
\"\"<\/figure>\n\n\n\n
\"\"<\/figure>\n\n\n\n
Sources:<\/h2>\n\n\n\n