Πώς συλλέγουμε blocking queries μέσω Extended Event και πως διαβάζουμε τα δεδομένα του
Πιστοποιήσεις:
- Πώς μπορούμε να συνδέσουμε Oracle Database με SQL Server με χρήση Oracle Gateway σε Windows - 5 Απρίλιος 2024
- Πώς μπορούμε να λαμβάνουμε email κάθε φορά που ξεπερνάει ένα όριο η μνήμη PGA σε βάση δεδομένων της Oracle - 1 Μάρτιος 2024
- Πώς κάνουμε μαζικά detach / attach βάσεις δεδομένων στον SQL Server - 2 Φεβρουάριος 2024
Σε παλαιότερο άρθρο είχαμε δει πως δημιουργούμε Extended Event για να δούμε τα queries με μεγάλη διάρκεια. Σε αυτό το άρθρο θα φτιάξουμε Extended Event που καταγράφει τα blockings.
Το μόνο που χρειάζεται να κάνουμε είναι να το δημιουργήσουμε με ένα T-SQL command. Αφού δημιουργηθεί θα καταγράφει στο path που του έχουμε δηλώσει σε ένα αρχείο XML όσα queries είχανε διάρκεια πάνω από 1 δευτερόλεπτο.
Για την δημιουργία του Extended Event
Δεν πρέπει να ξεχάσουμε να αλλάξουμε το path σε αυτό που θα θέλουμε να αποθηκεύονται τα δεδομένα.
Έπειτα το εκτελούμε σε ένα απλό query window.
CREATE EVENT SESSION [BlockedProcessReport] ON SERVER ADD EVENT sqlserver.blocked_process_report ADD TARGET package0.event_file(SET filename=N'D:\Xevents\blockings.xel',max_file_size=(20),max_rollover_files=(50)) WITH (MAX_MEMORY=8192 KB,EVENT_RETENTION_MODE=ALLOW_SINGLE_EVENT_LOSS,MAX_DISPATCH_LATENCY=30 SECONDS,MAX_EVENT_SIZE=0 KB,MEMORY_PARTITION_MODE=NONE,TRACK_CAUSALITY=OFF,STARTUP_STATE=ON) GO alter event session BlockedProcessReport on server state=start; go
Για να λειτουργήσει όμως θα πρέπει να έχουμε αλλάξει την παράμετρο blocked process threshold που ορίζει τι διάρκειας blockings θα reportάρονται από alerts, profiler και extended events που αφορούν το blocking. Ορίζοντας την τιμή της ως 10 θα καταγράφει μόνο blockings που είχανε διάρκεια πάνω από 10 δευτερόλεπτα. Με την default τιμή που είναι το 0 δεν θα καταγράφει τίποτα. Δέχεται τιμές από 5 δευτερόλεπτα και πάνω.
Για εφαρμόσουμε αυτή την αλλαγή, τρέχουμε σε ένα query window στο instance τα παρακάτω:
EXEC sp_configure 'show advanced options', 1; RECONFIGURE WITH OVERRIDE; EXEC sp_configure 'blocked process threshold (s)', 10; RECONFIGURE WITH OVERRIDE;
Πως διαβάζουμε τα αποτελέσματα
Στο 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)
set @xel=(select
--n.name as XeventName,
SUBSTRING(cast(f.value as varchar(max)),1,len(cast(f.value as varchar(max)))-4)+'*.xel' as xel
--,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 '%BlockedProcessReport%') --Set xevent Name
set @xem=(select
--n.name as XeventName,
--SUBSTRING(cast(f.value as varchar(max)),1,len(cast(f.value as varchar(max)))-4)+'*.xel' as xel
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 '%BlockedProcessReport%') --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
d.name as DB_Name,
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/data[@name="object_id"]/value)[1]','bigint') AS Object_ID,
A.value ('(/event/data[@name="lock_mode"]/text)[1]', 'VARCHAR(MAX)') AS lock_mode,
A.value ('(/event/data[@name="blocked_process"]/value/blocked-process-report/blocked-process/process/inputbuf)[1]', 'VARCHAR(MAX)') AS BlockedQuery,
A.value ('(/event/data[@name="blocked_process"]/value/blocked-process-report/blocking-process/process/inputbuf)[1]', 'VARCHAR(MAX)') AS BlockingQuery,
A.value ('(/event/data[@name="blocked_process"]/value/blocked-process-report/blocking-process/process/executionStack/frame/@sqlhandle)[1]', 'VARCHAR(MAX)') AS sql_handle1,
sf1.text as full_text1,
qp1.query_plan as query_plan1,
A AS xml_report
--,A.value('(event/data[@name="cpu_time"]/value)[1]','bigint') /1000000 AS cpu_seconds
--,A.value('(event/data[@name="physical_reads"]/value)[1]','bigint') AS physical_reads
--,A.value('(event/data[@name="logical_reads"]/value)[1]','bigint') AS logical_reads
--,A.value('(event/data[@name="row_count"]/value)[1]','bigint') AS row_count
From XEvents x
inner join sys.databases d on x.A.value ('(/event/data[@name="database_id"]/value)[1]', 'VARCHAR(MAX)') =d.database_id
outer apply sys.dm_exec_sql_text (CONVERT(VARBINARY(MAX), x.A.value ('(/event/data[@name="blocked_process"]/value/blocked-process-report/blocking-process/process/executionStack/frame/@sqlhandle)[1]', 'varchar(max)'), 1)) as sf1
outer apply sys.dm_exec_query_plan((select top 1 plan_handle from sys.dm_exec_query_stats where sql_handle = CONVERT(VARBINARY(MAX), x.A.value ('(/event/data[@name="blocked_process"]/value/blocked-process-report/blocking-process/process/executionStack/frame/@sqlhandle)[1]', 'varchar(max)'), 1)order by last_execution_time desc))as qp1
where 1=1
and DATEADD(HOUR,DATEDIFF(hour, SYSUTCDATETIME(),SYSDATETIME() ),A.value ('(/event/@timestamp)[1]', 'DATETIME')) between '2020-05-01 10:45:00.000' and '2020-05-30 12:45:00.000'
and A.value ('(/event/action[@name=''database_name'']/value)[1]', 'VARCHAR(MAX)') ='DB_1'
Το αποτέλεσμα
Το αποτέλεσμα του query μας έφερε για αυτό το χρονικό διάστημα, στη βάση που του ζητήσαμε, τα queries που γινόντουσαν block, από ποιο query έγιναν blocked, σε ποιο object και τέλος με τι locking mode.
