Πώς βρίσκουμε πόσο ακόμα θέλει για να ολοκληρωθεί το query και που καθυστερεί (SQL Server Query Profiling)

Πώς βρίσκουμε πόσο ακόμα θέλει για να ολοκληρωθεί το query και που καθυστερεί (SQL Server Query Profiling)
Πώς βρίσκουμε πόσο ακόμα θέλει για να ολοκληρωθεί το query και που καθυστερεί (SQL Server Query Profiling)

Πολλές θα αντιμετωπίσουμε queries που αργούν πολύ να ολοκληρωθούν ή δεν ολοκληρώνονται ποτέ. Για να βρούμε τι ακριβώς φταίει η πιο χρήσιμη πληροφορία είναι το actual execution plan.

Καθώς το actual execution plan απαιτεί την ολοκλήρωση του query, με το live query statistics παρέχετε η δυνατότητα για real-time πληροφορίες καθώς εκτελείτε το query. Πληροφορίες όπως σε ποιο query του batch βρισκόμαστε, ο αριθμός εγγραφών που παρήχθησαν, χρόνος εκτέλεσης, χρήση CPU – I/O, η πρόοδος του query και τέλος σε ποιόν execution plan operator βρισκόμαστε για να ολοκληρωθεί η διεργασία.

Πως μπορούμε να παρακολουθήσουμε συγκεκριμένο query που θέλουμε να τρέξουμε

Γράφοντας πριν το query την εντολή SET STATISTICS PROFILE ON όταν εκτελέσουμε το batch εκτός από τα αποτελέσματα θα μας εμφανίζεται το actual execution plan ανά query.

SET STATISTICS PROFILE ON


select top 10 * from pinakas;
go

create nonclustered index ix_pin on pinakas (onoma);
go

delete from pinakas where tilefono like '%5%'
go

declare 
@i int;
set @i =1;
while @i<100000
begin
insert into pinakas values ('stratos'+cast(@i as varchar),'20294012',null)
set @i=@i+1
end
Πώς βρίσκουμε πόσο ακόμα θέλει για να ολοκληρωθεί το query και που καθυστερεί (SQL Server Query Profiling)

Παράλληλα η πληροφορία αυτή για την εξέλιξη του query (που έχει ενεργοποιημένο το statistics profile) καταγράφεται στο dynamic view sys.dm_exec_query_profiles. Παράλληλα μπορούμε να δούμε το live execution plan στο sys.dm_exec_query_Statistics_xml.

Οπότε με την εκτέλεση του βλέπουμε σε ποιο query και operator βρίσκεται αυτή την στιγμή το batch. Επίσης βλέπουμε το ποσοστό ολοκλήρωσης, το wait type και το live execution plan του.

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
,i.name as index_name
from sys.dm_exec_query_profiles qp
left join sys.dm_os_waiting_tasks w on w.session_id = qp.session_id
left join sys.databases d on d.database_id = qp.database_id
left join sys.indexes i on qp.object_id=i.object_id and qp.index_id = i.index_id
outer apply sys.dm_exec_sql_text(qp.sql_handle) as t
outer apply sys.dm_exec_query_plan(qp.plan_handle) as p
outer apply sys.dm_exec_query_Statistics_xml(qp.plan_handle) as lp
where text not like '%dm_exec_query_profiles%'
Πώς βρίσκουμε πόσο ακόμα θέλει για να ολοκληρωθεί το query και που καθυστερεί (SQL Server Query Profiling)

Πως ενεργοποιούμε τα Live Query Statistics

Πέρα από την επιλογή της ενεργοποίησης του statistics profile αν κάνουμε χρήση SQL Server Management Studio 2016 και έπειτα, έχουμε τη δυνατότητα να ενεργοποιήσουμε και τα Live Query Statistics.

Απλός επιλέγοντας πριν την εκτελεση του συγκεκριμένου query το κουμπί του Include Live Query Statistics (όπως φαίνεται στη κάτωθι εικόνα).

Κατα την εκτελεση του query θα δούμε το query progress άνα batch και το progress του κάθε query plan operator μέσα σε αυτό.

Πώς βρίσκουμε πόσο ακόμα θέλει για να ολοκληρωθεί το query και που καθυστερεί (SQL Server Query Profiling)

Επίσης αν κάνουμε δεξί κλικ στο Activity Monitor του Management Studio θα δούμε την επιλογή Show Live Execution Plan για όσα μόνο query γίνεται η χρήση της εντολής SET STATISTICS PROFILE ON.

Πώς βρίσκουμε πόσο ακόμα θέλει για να ολοκληρωθεί το query και που καθυστερεί (SQL Server Query Profiling)

Πώς ενεργοποιούμε τις λειτουργίες αυτές σε ολόκληρο το instance

Η χρήση του profiling ανέκαθεν ήταν μια λειτουργία με μεγάλο performance impact οπότε την ενεργοποιούμε για συγκεκριμένο χρονικό διάστημα σε επιλεγμένες βάσεις.

Από τον SQL Server 2016 (αν και επίσημα ήτανε από τον SQL Server 2014 SP2 με χρήση XEvent) παρουσιάστηκε το lightweight query profiling. Είναι ένα πιο ελαφρύ profiling που δεν καταγράφει το CPU usage αλλά συλλέγει όλες τις υπόλοιπες πληροφορίες.

Χάρις στο lightweight query profiling μπορούμε να έχουμε ενεργοποιημένο profiling μόνιμα σε ολόκληρο το instance.

Πως ενεργοποιείται το lightweight query profiling

Στον SQL Server 2016 μπορούμε να ενεργοποιήσουμε το trace flag 7412 ώστε να ενεργοποιηθεί σε ολόκληρο το instance.

DBCC TRACEON (7412, -1);

Εναλλακτικά μπορούμε να το ενεργοποιήσουμε αν δεν είναι σε επίπεδο instance σε επίπεδο query only με query hint.

select * from pinakas option ( use hint ( 'QUERY_PLAN_PROFILE' ));

Για να λειτουργήσει θα πρέπει να υπάρχει έχει δημιουργηθεί και το XEvent query_plan_profile.

CREATE EVENT SESSION query_plan_profile
    ON SERVER
    ADD EVENT sqlserver.query_plan_profile
    ( SET collect_database_name = ( 0 )
     ACTION ( sqlserver.plan_handle, 
              sqlserver.query_hash_signed, 
              sqlserver.query_plan_hash_signed, 
              sqlserver.sql_text )
              )
    ADD TARGET package0.event_file
    ( SET filename = N'c:\xevents\query_plan_profile' )
    WITH ( MAX_MEMORY = 4096KB,
           EVENT_RETENTION_MODE = ALLOW_SINGLE_EVENT_LOSS,
           MAX_DISPATCH_LATENCY = 5 SECONDS,
           MAX_EVENT_SIZE = 0KB,
           MEMORY_PARTITION_MODE = NONE,
           TRACK_CAUSALITY = OFF,
           STARTUP_STATE = OFF );
GO
 
ALTER EVENT SESSION query_plan_profile ON SERVER STATE = START;
GO

Τι αλλάζει στον SQL Server 2019

Από τον SQL Server 2019 το lightweight query profiling είναι ενεργοποιημένο στο επίπεδο instance by default (δεν χρειάζεται trace flag).

Υπάρχει η εντολή να ενεργοποιηθεί ή απενεργοποιηθεί σε database level.

ALTER DATABASE SCOPED CONFIGURATION SET LIGHTWEIGHT_QUERY_PROFILING = ON

Επίσης έχουμε τη δυνατότητα να βρούμε το τελευταίο actual execution plan από όσα queries είναι ακόμα κασαρισμένα.

Για να ενεργοποιηθεί τρέχουμε σε επίπεδο βάσης:

ALTER DATABASE SCOPED CONFIGURATION SET LAST_QUERY_PLAN_STATS = ON;

Για να δούμε τα αποτελέσματα έχοντας απλά μόνο το sql text:

SELECT size_in_bytes,cacheobjtype,objtype,text,query_plan FROM sys.dm_exec_cached_plans AS cp
CROSS APPLY sys.dm_exec_sql_text(plan_handle) AS st
CROSS APPLY sys.dm_exec_query_plan_stats(plan_handle) AS qps
WHERE st.text LIKE '%test%';  
GO  
Πώς βρίσκουμε πόσο ακόμα θέλει για να ολοκληρωθεί το query και που καθυστερεί (SQL Server Query Profiling)

Επιλέγοντας τον υπερσύνδεσμο στο καθένα θα μας ανοίξει το γραφικό από το πλάνο που είχε.

Πώς βρίσκουμε πόσο ακόμα θέλει για να ολοκληρωθεί το query και που καθυστερεί (SQL Server Query Profiling)

Επίσης στον SQL Server 2019 / SQL Server 2017 CU14 έχουμε ένα καινούργιο lightweight Extended Event (query_post_execution_plan_profile) που καταγράφει τις πληροφορίες του actual execution plan. Είναι lightweight καθώς δεν καταγράφει wait types, βαριά metrics CPU και I/O.

Το script για να δημιουργηθεί (έχω ορίσει threshold από 5 δευτερόλεπτα και πάνω):

CREATE EVENT SESSION [query_post_execution_plan_profile] ON SERVER 
ADD EVENT sqlserver.query_post_execution_plan_profile(SET collect_database_name=(0)
    ACTION(sqlserver.client_hostname,sqlserver.database_name,sqlserver.plan_handle,sqlserver.sql_text)
    WHERE ([package0].[greater_than_equal_uint64]([duration],(5000000))))
ADD TARGET package0.event_file(SET filename=N'c:\xevents\query_post_execution_plan_profile')
WITH (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)
GO

Για να δούμε τα αποτελέσματα με ένα single query που έγραψα με πολύ κόπο να διαβάζει το XML του Extended Event:

declare
@xel as varchar(max),
@xem as varchar(max),
@xm as XML

set @xel=(select 
SUBSTRING(cast(f.value as varchar(max)),1,len(cast(f.value as varchar(max)))-4)+'*.xel' as xel
from sys.server_event_session_fields f
inner join sys.server_event_sessions n on f.event_session_id = n.event_session_id
WHERE f.NAME = 'filename' 
and n.name like '%post%') --Set xevent Name

set @xem=(select 
SUBSTRING(cast(f.value as varchar(max)),1,len(cast(f.value as varchar(max)))-4)+'*.xem' as xem
from sys.server_event_session_fields f
inner join sys.server_event_sessions n on f.event_session_id = n.event_session_id
WHERE f.NAME = 'filename' 
and n.name like '%post%')  --Set xevent Name

;WITH XEvents AS
(
select  object_name, CAST(event_data AS XML) AS A FROM sys.fn_xe_file_target_read_file(
@xel
,@xem
, NULL, NULL) 
)

SELECT
A.value ('(/event/action[@name=''database_name'']/value)[1]', 'VARCHAR(MAX)') AS DB_Name,
DATEADD(HOUR,DATEDIFF(hour,  SYSUTCDATETIME(),SYSDATETIME() ),A.value ('(/event/@timestamp)[1]', 'DATETIME')) AS [Time],
A.value ('(event/data[@name="duration"]/value)[1]','bigint') / 1000000  AS [Duration_Seconds],
A.value ('(/event/action[@name=''sql_text'']/value)[1]', 'VARCHAR(MAX)') AS sql_text,
--A.value ('(/event/action[@name=''query_hash_signed'']/value)[1]', 'VARCHAR(MAX)') AS query_hash_signed,
--A.value ('(/event/action[@name=''query_plan_hash_signed'']/value)[1]', 'VARCHAR(MAX)') AS query_plan_hash_signed,
A.value ('(/event/action[@name=''client_hostname'']/value)[1]', 'VARCHAR(MAX)') AS client_hostname,
A.value('(event/data[@name="estimated_rows"]/value)[1]','bigint') AS row_count,
A.value('(/event/data[@name=''cpu_time'']/value)[1]','bigint') /1000000 AS cpu_seconds,
z.fragment.query('.') as showplan,
A.value ('(/event/action[@name=''plan_handle'']/value)[1]', 'VARCHAR(MAX)') AS plan_handle,
A  AS xml_report
from XEvents
CROSS APPLY A.nodes('/event/data[@name="showplan_xml"]/value/*') as z(fragment)
where  1=1
--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'
--and A.value ('(/event/action[@name=''database_name'']/value)[1]', 'VARCHAR(MAX)') ='DB_test'
--and A.value('(event/data[@name="duration"]/value)[1]','bigint') / 1000000  >= 10 --sec

Όπως βλέπουμε μας φέρνει και το πλάνο που έτρεξε και απλά κάνοντας διπλό κλικ στο υπερσύνδεσμο θα δούμε το γραφικό του.

Πώς βρίσκουμε πόσο ακόμα θέλει για να ολοκληρωθεί το query και που καθυστερεί (SQL Server Query Profiling)
Πώς βρίσκουμε πόσο ακόμα θέλει για να ολοκληρωθεί το query και που καθυστερεί (SQL Server Query Profiling)

Πηγές:

Μοιράσου το

Αφήστε μία απάντηση