Overview

Στην δουλειά μας εδώ και πολλά χρόνια έχω αποδεχτεί ότι κάτι, σε κάποιον, θα συμβεί μέσα σε γιορτινές ημέρες. Έτσι και σήμερα για άλλου ξεκίνησα και αλλού βρέθηκα.

Η κλήση που δέχθηκα αφορούσε μια διαδικασία που διαρκούσε πολύ σε σχέση με το πρόσφατο παρελθόν, σύμφωνα πάντα με τον πελάτη, και λόγο της υψηλής κίνησης των ημερών δημιουργούσε προβλήματα στην ροή των εργασιών.

Αφού βρέθηκα στο χώρο του πελάτη διαπίστωσα με απλά queries χρησιμοποιώντας τις sys.dm_exec_sessions, sys.dm_exec_requests και sys.dm_exec_sql_text ότι αυτή η διαδικασία είναι μια stored procedure με πάνω από 2 χιλιάδες γραμμές κώδικα που κανείς δεν ήξερε τι κάνει σαν λογική και ο προμηθευτής της εφαρμογής αγνοούσε την ύπαρξη της.

Κλασσική περίπτωση βλάβης που έλεγε και ο αείμνηστος Τσάκωνας.

Φυσικά χρόνος για να κάνεις ανάλυση αυτής καθώς η παραγωγική διαδικασία καθυστερούσε και ήθελε άμεσα λύση δεν υπήρχε. Αυτό που έπρεπε να γίνει είναι να βρεθεί το σημείο ή τα σημεία εκείνα που δημιουργούσαν το μεγαλύτερο πρόβλημα.

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

Δεν υπάρχει κάτι μαγικό για να δοθεί απάντηση στο ερώτημα αυτό από την χρήση των παραπάνω αναγραφόμενων DMVs σε ένα απλό query.

Με το κώδικα της sp στην μια μεριά και με επαναλαμβανόμενες εκτελέσεις στο παρακάτω query/script βρέθηκαν οι αιτίες καθυστέρησης που με ένα index και κάποια update statistics σε κάποιους πίνακες η sp αυτή πλέον ολοκληρώνεται σε λιγότερο από 50 sec σε σχέση με τα 20 λεπτά που διαρκούσε και φυσικά ουδείς παραπονιέται.

The query/script

declare @spid int=0;
set     @spid = <put the session id here>;

select substring(   q.text, 
                        (r.statement_start_offset + 2)/2, 
                        case r.statement_end_offset 
                        when -1 then (datalength(q.text))
                        else ((r.statement_end_offset - r.statement_start_offset) + 2)/2 
                        end
                ) as current_executed_query, 
                r.session_id,
                r.start_time,
                r.status,
                r.command,
                db_name(r.database_id) as database_name,
                r.blocking_session_id,
                r.wait_type,
                r.wait_resource,
                r.wait_time,
                r.transaction_id
from    sys.dm_exec_requests  as r with(nolock)
cross apply sys.dm_exec_sql_text(r.sql_handle) as q
where r.session_id=@spid;

Αυτό το script δεν κάνει τίποτα περίεργο.

Είναι γνωστό οτιδήποτε τρέχει πάνω στον SQL Server instance μπορούμε να το δούμε μέσα από την sys.dm_exec_requests η οποία παρέχει το sql_handle field που στην ουσία δείχνει στο cached execution plan το οποίο μπορώ να διαβάσω με την sys.dm_exec_sql_text η οποία επιστρέφει το text field που έχει όλο το query την προκειμένη περίπτωση όλη την stored procedure πράγμα που δεν βοηθάει ιδιαίτερα.

Για αυτό χρησιμοποιούμε τα πεδία που η sys.dm_exec_requests δίνει και αυτά είναι τα statement_start_offset, statement_end_offset τα οποία σε κάθε εκτέλεση μου επιστρέφουν το offset του statement που εκτελείται τη στιγμή αυτή μέσα στην sp και με αυτά στο χέρι και ένα απλό substring μπορώ να διαβάσω εύκολα.

Πριν από αυτό για την ευκολία μας καλό θα είναι εντοπίζουμε ακριβώς το session στο οποίο εκτελείται η sp αυτή ώστε να έχουμε λιγότερα πράγματα να βλέπουμε.

//antonch