Πώς συλλέγουμε to actual execution plan από τα queries με χρήση Extended Event και πως διαβάζουμε τα δεδομένα του
Πιστοποιήσεις:
- Πώς φτιάχνουμε Logon Trigger για να ελέγχουμε τους χρήστες που επιτρέπουμε να συνδεθούν σε Oracle Database - 13 Ιανουάριος 2025
- Πώς συλλέγουμε to actual execution plan από τα queries με χρήση Extended Event και πως διαβάζουμε τα δεδομένα του - 2 Δεκέμβριος 2024
- Πώς βρίσκουμε τι δικαιώματα έχει ένας χρήστης σε βάση δεδομένων της Oracle - 1 Νοέμβριος 2024
Σε παλαιότερο άρθρο είχαμε δει πως ενεργοποιούμε το Query Store για να παρακολουθήσουμε την απόδοση των queries και το πλάνο που έτρεξαν. Όμως όπως είχαμε πει το Query Store έχει αρκετό performance impact οπότε μπορεί να θέλουμε κάποιο lightweight profiling.Σε αυτό το άρθρο θα δούμε πως ενεργοποιούμε Extended Event που καταγράφει την πληροφορία αυτή.
Ονομάζετε query_post_execution_plan_profile και ενεργοποιείτε από τις εκδόσεις SQL Server 2019 / SQL Server 2017 CU14 και έπειτα.
Καταγράφει τις πληροφορίες του actual execution plan. Είναι lightweight καθώς δεν καταγράφει wait types, βαριά metrics CPU και I/O.
Για την δημιουργία του Extended Event
Δεν πρέπει να ξεχάσουμε να αλλάξουμε το path σε αυτό που θα θέλουμε να αποθηκεύονται τα δεδομένα.
Το μόνο που χρειάζεται να κάνουμε είναι να τρέξουμε το παρακάτω T-SQL command. Αφού δημιουργηθεί θα καταγράφει στο path που του έχουμε δηλώσει σε ένα αρχείο XML όσα queries είχανε διάρκεια πάνω από 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
alter event session query_post_execution_plan_profile on server state=start;
go
Ελέγχουμε στον Object Explorer ότι το Extended Event τρέχει (είναι πράσινο), αν δεν είναι πατάμε δεξί κλικ πάνω του και start session.
Πώς διαβάζουμε τα αποτελέσματα
Στο path που είχαμε ορίσει κατά την δημιουργία του XEvent δημιουργήθηκε ένα .xel και ένα .xem αρχείο. Μέσω του dynamic view sys.fn_xe_file_target_read_file με παραμέτρους αυτά τα αρχεία έχουμε ως αποτέλεσμα όλο το XML αρχείο με την πληροφορία.
Όμως επειδή δεν είναι πρακτικό να διαβάζεις με το μάτι ένα XML πρέπει κάπως να φιλτραριστεί το αρχείο σε μια πιο ευανάγνωστη μορφή.
Οπότε έκατσα και έφτιαξα ένα query που κάνει αυτή τη δουλειά.
Για αρχή μέσω του ονόματος που φτιάξαμε το Xevent βρίσκει το path που βρίσκεται δυναμικά και το ορίζει σαν παράμετρο στο query.
Έπειτα ορίζουμε το XML σαν ένα Common Table Expression. Κάνοντας το SELECT μπορούμε να φέρουμε την τιμή από την κάθε ιδιότητα που χρειαζόμαστε.
Στο where statement μπορούμε να φιλτράρουμε συγκεκριμένες βάσεις, την διάρκεια και το χρονικό διάστημα που εκτελέστηκε.
Σε αυτό το κομμάτι θέλει προσοχή, καθώς το default xml timestamp είναι σε UTC timezone οπότε για να βάζουμε την πραγματική ώρα που έχει ο server προσθέτουμε την διαφορά ώρας που έχει ο server με το UTC timezone (DATEADD(HOUR,DATEDIFF(hour, SYSUTCDATETIME(),SYSDATETIME() )).
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)') ='mig_db'
--and A.value('(event/data[@name="duration"]/value)[1]','bigint') / 1000000 >= 10 --sec
Το αποτέλεσμα
Το αποτέλεσμα του query μας έφερε για αυτό το χρονικό διάστημα, στη βάση που του ζητήσαμε, τα queries που τρέχανε πάνω από 5 δευτερόλεπτα, σε ποια βάση τρέξανε, για πόση ώρα, το sql text, από που τρέξανε, πόσες εγγραφές φέρανε και το execution plan που έτρεξαν.
Επιλέγοντας τον υπερσύνδεσμο στο καθένα θα μας ανοίξει το γραφικό από το execution plan που είχε.
