Πώς βρίσκουμε πόσο ακόμα θέλει για να ολοκληρωθεί το query και που καθυστερεί (SQL Server Query Profiling)
Πιστοποιήσεις:
- Πώς αυτοματοποιούμε τη διαδικασία ελέγχου ακεραιότητας των βάσεων δεδομένων σε SQL Server χωρίς την χρήση maintenance plan - 10 Μάιος 2024
- Πώς μπορούμε να συνδέσουμε Oracle Database με SQL Server με χρήση Oracle Gateway σε Windows - 5 Απρίλιος 2024
- Πώς μπορούμε να λαμβάνουμε email κάθε φορά που ξεπερνάει ένα όριο η μνήμη PGA σε βάση δεδομένων της Oracle - 1 Μάρτιος 2024
Πολλές θα αντιμετωπίσουμε 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 (που έχει ενεργοποιημένο το 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%'
Πως ενεργοποιούμε τα 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 μέσα σε αυτό.
Επίσης αν κάνουμε δεξί κλικ στο Activity Monitor του Management Studio θα δούμε την επιλογή Show Live Execution Plan για όσα μόνο query γίνεται η χρήση της εντολής SET STATISTICS PROFILE ON.
Πώς ενεργοποιούμε τις λειτουργίες αυτές σε ολόκληρο το 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
Επιλέγοντας τον υπερσύνδεσμο στο καθένα θα μας ανοίξει το γραφικό από το πλάνο που είχε.
Επίσης στον 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
Όπως βλέπουμε μας φέρνει και το πλάνο που έτρεξε και απλά κάνοντας διπλό κλικ στο υπερσύνδεσμο θα δούμε το γραφικό του.
