Πώς συλλέγουμε τα queries με μεγάλη διάρκεια μέσω Extended Event και πως διαβάζουμε τα δεδομένα του

• Σχετικά με
• τελευταίες δημοσιεύσεις

Stratos Matzouranis

Το ταξίδι άρχισε το 2008 όπου ξεκίνησα να εργάζομαι επίσημα στον τομέα της τεχνολογίας πληροφορικής (IT). Ξεκινώντας το πρώτο εξάμηνο της σχολής κατάλαβα μια ιδιαίτερη έλξη προς τις βάσεις δεδομένων και τους αυτοματισμούς.Έχω ασχοληθεί με βάσεις δεδομένων όπως Microsoft SQL Server / Oracle Database, ανάλυση δεδομένων και αυτοματισμούς με τη χρήση γραμμής εντολών (CLI), Visual Basic for Applications και Python. Μέσα από τα χρόνια εμπειρίας εξέλιξα αυτές τις δυνατότητες ώστε να μπορώ να κάνω τη ζωή μου πιο εύκολη. Για μένα ο σκοπός του κάθε IT guy αλλά και κάθε υπαλλήλου γραφείου είναι το να έχει τις γνώσεις ώστε μέσω εργαλείων να μπορεί να δουλεύει λίγο αλλά να παράγει πολύ. Μέσα από αυτό τον ιστότοπο του DataPlatform.gr προσπαθώ να προσφέρω γνώσεις και να προτείνω λύσεις σε καθημερινά προβλήματα.

Πιστοποιήσεις:

Τελευταίες δημοσιεύσεις από Stratos Matzouranis (Προβολή όλων)

• Πώς ενεργοποιούμε το Unified Auditing σε Oracle Database - 7 Οκτώβριος 2024
• Τι είναι η PostgreSQL και πως κάνουμε μία πλήρης εγκατάσταση - 2 Σεπτέμβριος 2024
• Πώς ρυθμίζουμε το replication του GoldenGate ώστε να διαβάζει από το Standby του Oracle Data Guard - 2 Αύγουστος 2024

Πολλές φορές θα χρειαστεί να βρούμε πόσα και ποια SQL queries εκτελέστηκαν για μία μεγάλη διάρκεια σε ένα χρονικό διάστημα στον SQL Server. Η πιο εύκολη λύση με το λιγότερο performance impact είναι η δημιουργία ενός Extended Event.

Το μόνο που χρειάζεται να κάνουμε είναι να το δημιουργήσουμε με ένα T-SQL command. Αφού δημιουργηθεί, θα καταγράφει στο path που του έχουμε δηλώσει σε ένα αρχείο XML όσα queries είχανε διάρκεια πάνω από ένα δευτερόλεπτο.

Για την δημιουργία του Extended Event

Δεν πρέπει να ξεχάσουμε να αλλάξουμε το path σε αυτό που θα θέλουμε να αποθηκεύονται τα δεδομένα.

Έπειτα το εκτελούμε σε ένα απλό query window:

CREATE EVENT SESSION [CaptureDuration] ON SERVER 
ADD EVENT sqlserver.rpc_completed(SET collect_statement=(1)
    ACTION(package0.collect_cpu_cycle_time,sqlos.cpu_id,sqlos.task_time,sqlserver.client_app_name,sqlserver.client_connection_id,sqlserver.client_hostname,sqlserver.database_id,sqlserver.database_name,sqlserver.nt_username,sqlserver.session_id,sqlserver.session_nt_username,sqlserver.session_server_principal_name,sqlserver.sql_text,sqlserver.transaction_id,sqlserver.tsql_stack,sqlserver.username)
    WHERE ([package0].[greater_than_equal_uint64]([duration],(10000000)))),
ADD EVENT sqlserver.sql_batch_completed(
    ACTION(package0.collect_cpu_cycle_time,sqlos.cpu_id,sqlos.task_time,sqlserver.client_app_name,sqlserver.client_connection_id,sqlserver.client_hostname,sqlserver.database_id,sqlserver.database_name,sqlserver.nt_username,sqlserver.session_id,sqlserver.session_nt_username,sqlserver.session_server_principal_name,sqlserver.sql_text,sqlserver.transaction_id,sqlserver.tsql_stack,sqlserver.username)
    WHERE ([package0].[greater_than_equal_uint64]([duration],(10000000)))),
ADD EVENT sqlserver.sql_statement_completed(SET collect_statement=(1)
    ACTION(package0.collect_cpu_cycle_time,sqlos.cpu_id,sqlos.task_time,sqlserver.client_app_name,sqlserver.client_connection_id,sqlserver.client_hostname,sqlserver.database_id,sqlserver.database_name,sqlserver.nt_username,sqlserver.session_id,sqlserver.session_nt_username,sqlserver.session_server_principal_name,sqlserver.sql_text,sqlserver.transaction_id,sqlserver.tsql_stack,sqlserver.username)
    WHERE ([package0].[greater_than_equal_int64]([duration],(10000000)))) 
ADD TARGET package0.event_file(SET filename=N'D:\Xevents\longqueries_file.xel',max_file_size=(20),max_rollover_files=(50))
WITH (MAX_MEMORY=4096 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 CaptureDuration on server state=start;
go

Πώς διαβάζουμε τα αποτελέσματα

Στο 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 που γίνεται με τις functions (DATEADD(HOUR,DATEDIFF(hour, SYSUTCDATETIME(),SYSDATETIME() )):

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

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 '%CaptureDuration%') --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 '%CaptureDuration%')  --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/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
A   AS xml_report
From XEvents
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)') ='DBATools'
and A.value('(event/data[@name="duration"]/value)[1]','bigint') / 1000000  >= 15 --sec

Το αποτέλεσμα

Το αποτέλεσμα του query μας έφερε για αυτό το χρονικό διάστημα στη βάση που του ζητήσαμε τα queries που τρέχανε και την διάρκεια τους:

Αντίστοιχα για να κρατήσουμε τα blockings, μπορούμε να ακολουθήσουμε τα βήματα που αναγράφονται σε αυτό το άρθρο.

Πηγές:

• Quickstart: Extended Events in SQL Server